diff --git a/docs/source/pcapkit/utilities/exceptions.rst b/docs/source/pcapkit/utilities/exceptions.rst index bc56ae0a8d..859d9471e1 100644 --- a/docs/source/pcapkit/utilities/exceptions.rst +++ b/docs/source/pcapkit/utilities/exceptions.rst @@ -3,15 +3,47 @@ User Defined Exceptions .. module:: pcapkit.utilities.exceptions -:mod:`pcapkit.exceptions` refined built-in exceptions. -Make it possible to show only user error stack infomation [*]_, +:mod:`pcapkit.utilities.exceptions` refined built-in exceptions. +Make it possible to show only user error stack information [*]_, when exception raised on user's operation. +Loud and Quiet Errors +--------------------- + +Raising a :class:`~pcapkit.utilities.exceptions.BaseError` is, by default, a +**loud** act: the error is logged once at :data:`logging.CRITICAL` on the +:data:`~pcapkit.utilities.logging.logger` logger, and outside development mode +:data:`sys.tracebacklimit` is set to ``0``, which suppresses the traceback frames +entirely so the user sees the exception line rather than a walk through +:mod:`pcapkit`'s internals. + +``quiet=True`` marks an error that :mod:`pcapkit` raises as **internal control +flow** and expects to catch itself -- the +:exc:`~pcapkit.utilities.exceptions.MissingKeyError` behind +:meth:`MultiDict.get ` is the archetype. +Such an error emits nothing on any channel and touches no process-global state. +It is still an ordinary exception carrying its message, so ``except`` clauses and +:func:`repr` are unaffected. + +.. attention:: + + Up to and including v1.4.1, ``quiet=True`` meant "log at ``ERROR`` instead of + ``CRITICAL``" rather than "do not log", and :data:`sys.tracebacklimit` was set + on both paths. A single ``MultiDict.get()`` miss therefore produced an + ``ERROR`` record -- one per frame when parsing a capture containing + unfragmented IPv6 with reassembly enabled -- and truncated the tracebacks of + unrelated exceptions for the remainder of the process. A consumer who was + watching for those ``ERROR`` records will no longer see them; they never + corresponded to a fault. Anything that genuinely wants to observe internal + lookup misses should catch the exception rather than read the log. + .. autoexception:: pcapkit.utilities.exceptions.BaseError :no-members: :show-inheritance: - :param quiet: If :data:`True`, suppress exception message. + :param quiet: If :data:`True`, the error is neither logged nor allowed to + alter :data:`sys.tracebacklimit`; it is raised silently, as internal + control flow. :param \*args: Arbitrary positional arguments. :param \*\*kwargs: Arbitrary keyword arguments. diff --git a/docs/source/pcapkit/utilities/logging.rst b/docs/source/pcapkit/utilities/logging.rst index 8ad17e16c0..a237034a7a 100644 --- a/docs/source/pcapkit/utilities/logging.rst +++ b/docs/source/pcapkit/utilities/logging.rst @@ -191,10 +191,9 @@ Compatibility Note .. note:: - Two related issues are deliberately left alone for now: - :func:`pcapkit.utilities.warnings.warn` reports every warning twice, once - through :mod:`logging` and once through :mod:`warnings`; and - :class:`~pcapkit.utilities.warnings.BaseWarning` calls - :func:`warnings.simplefilter` outside development mode, which mutates the - process-wide warning filters. Both change observable behaviour well beyond - logging and belong in their own change. + The warning channel is documented separately, in + :doc:`warnings`. In short: + :func:`pcapkit.utilities.warnings.warn` reports each warning exactly once per + channel -- one :data:`logging.WARNING` record and one :func:`warnings.warn` + -- and constructing a warning no longer mutates the process-wide warning + filters, so suppression is the application's to configure. diff --git a/docs/source/pcapkit/utilities/warnings.rst b/docs/source/pcapkit/utilities/warnings.rst index f7ef8d6575..7d2b6ef114 100644 --- a/docs/source/pcapkit/utilities/warnings.rst +++ b/docs/source/pcapkit/utilities/warnings.rst @@ -3,14 +3,88 @@ User Defined Warnings .. module:: pcapkit.utilities.warnings -:mod:`pcapkit.warnings` refined built-in warnings. +:mod:`pcapkit.utilities.warnings` refined built-in warnings. + +How a Warning Is Reported +------------------------- + +Every warning :mod:`pcapkit` reports goes through +:func:`~pcapkit.utilities.warnings.warn`, which reports it **exactly once on each +of two channels**: + +1. the :data:`~pcapkit.utilities.logging.logger` logger, at + :data:`logging.WARNING` level, unconditionally -- so a consumer watching the + ``pcapkit`` logger sees every complaint whatever the warning filters say; +2. the standard :mod:`warnings` machinery, via :func:`warnings.warn`, subject to + the filters -- so :func:`warnings.filterwarnings`, + :func:`warnings.catch_warnings`, :mod:`pytest`'s ``filterwarnings``, + :option:`-W` and :envvar:`PYTHONWARNINGS` govern :mod:`pcapkit` warnings + exactly as they govern any other library's (with one wrinkle in naming a + category on the command line, noted below). + +The counts are the same in development mode as outside it: +:envvar:`PCAPKIT_DEVMODE` and :envvar:`PCAPKIT_VERBOSE` change how much detail +the log record carries, never how many records there are. Constructing a warning +class is not an act of reporting one -- it emits nothing and has no side effects. + +Silencing pcapkit Warnings +-------------------------- + +Filter them like any other library's, at the level of granularity you want -- +:class:`~pcapkit.utilities.warnings.BaseWarning` for all of them, or a single +category:: + + import warnings + + from pcapkit.utilities.warnings import BaseWarning, SchemaWarning + + warnings.filterwarnings('ignore', category=BaseWarning) # all of them + warnings.filterwarnings('error', category=SchemaWarning) # or turn one into an error + +From the command line, name one of the standard categories these are mixed with. +:exc:`UserWarning` covers all of them, and :exc:`RuntimeWarning`, +:exc:`ImportWarning`, :exc:`ResourceWarning` and :exc:`DeprecationWarning` each +select a family:: + + python -W ignore::UserWarning ... # every pcapkit warning, and everyone else's + python -W error::RuntimeWarning ... # the RuntimeWarning family, as errors + +.. note:: + + :option:`-W` and :envvar:`PYTHONWARNINGS` cannot name a :mod:`pcapkit` + category directly: ``-W ignore::pcapkit.utilities.warnings.BaseWarning`` is + rejected with ``Invalid -W option ignored: invalid module name``. CPython + imports the category while parsing the option, and that happens before + :mod:`site` has added ``site-packages`` to :data:`sys.path`, so no installed + package's own category can be named there -- this is not specific to + :mod:`pcapkit`. Use a standard category on the command line, or install a + precise filter in code as above. + +All of that governs the :mod:`warnings` channel. The ``pcapkit`` logger is +configured separately, through the :mod:`logging` module:: + + import logging + + logging.getLogger('pcapkit').setLevel(logging.ERROR) # drop WARNING records + +.. attention:: + + Up to and including v1.4.1, :class:`~pcapkit.utilities.warnings.BaseWarning` + installed an ``ignore`` filter for its own class as a side effect of being + constructed, so :mod:`pcapkit` warnings were invisible on the :mod:`warnings` + channel by default and a caller could not re-enable them. They are now + delivered, which means a consumer who was relying on that silence will start + seeing them; the first snippet above restores the old quiet. Since the filter + was installed at the *front* of the process-global :data:`warnings.filters`, + it also overrode the host application's own configuration for those + categories and made unrelated warnings re-fire, so it is not something that + can be kept. .. autoexception:: pcapkit.utilities.warnings.BaseWarning :no-members: :show-inheritance: :param \*args: Arbitrary positional arguments. - :param \*\*kwargs: Arbitrary keyword arguments. :exc:`ImportWarning` Category ----------------------------- diff --git a/pcapkit/utilities/exceptions.py b/pcapkit/utilities/exceptions.py index 27dcac5fbe..d6d2f38a12 100644 --- a/pcapkit/utilities/exceptions.py +++ b/pcapkit/utilities/exceptions.py @@ -86,16 +86,27 @@ def stacklevel() -> 'int': class BaseError(Exception): """Base error class of all kinds. - Important: - - * Turn off system-default traceback function by set :data:`sys.tracebacklimit` to ``0``. - * But bugs appear in Python 3.6, so we have to set :data:`sys.tracebacklimit` to ``None``. - - .. note:: + A loud error -- the default -- is reported once, at + :data:`logging.CRITICAL` level, on the + :data:`~pcapkit.utilities.logging.logger` logger. Outside development mode it + also sets :data:`sys.tracebacklimit` to ``0``, which suppresses the traceback + frames entirely, so a user sees the exception line rather than a walk through + :mod:`pcapkit`'s internals. + + A **quiet** error (``quiet=True``) is one :mod:`pcapkit` raises as internal + control flow and expects to catch itself, such as the + :exc:`~pcapkit.utilities.exceptions.MissingKeyError` behind + :meth:`MultiDict.get `. It is + therefore silent and free of side effects: nothing is logged, and + :data:`sys.tracebacklimit` is left alone. It is still a perfectly ordinary + exception, carrying its message for whoever catches it. - This note is deprecated since Python fixed the problem above. + Important: - * In Python 2.7, :func:`trace.print_stack(limit)` dose not support negative limit. + * :data:`sys.tracebacklimit` is process-global, so it is only set for a + loud error -- a quiet one used as control flow must not truncate the + tracebacks of unrelated exceptions for the rest of the process. + * In Python 2.7, :func:`trace.print_stack(limit)` does not support negative limit. See Also: :func:`pcapkit.utilities.exceptions.stacklevel` @@ -103,22 +114,15 @@ class BaseError(Exception): """ def __init__(self, *args: 'Any', quiet: 'bool' = False, **kwargs: 'Any') -> 'None': - # log error + # log error -- a quiet error emits nothing and mutates nothing if not quiet: if DEVMODE: logger.critical('%s: %s', type(self).__name__, str(self), exc_info=self if VERBOSE else False, stack_info=VERBOSE, stacklevel=-stacklevel()) else: - logger.critical("%s: %s", type(self).__name__, str(self)) - - # logger.error('%s: %s', type(self).__name__, str(self), exc_info=self, - # stack_info=True, stacklevel=-stacklevel()) - else: - logger.error('%s: %s', type(self).__name__, str(self)) - - if not DEVMODE: - sys.tracebacklimit = 0 + logger.critical('%s: %s', type(self).__name__, str(self)) + sys.tracebacklimit = 0 super().__init__(*args, **kwargs) diff --git a/pcapkit/utilities/warnings.py b/pcapkit/utilities/warnings.py index e713e14bab..0477e9635b 100644 --- a/pcapkit/utilities/warnings.py +++ b/pcapkit/utilities/warnings.py @@ -4,17 +4,62 @@ .. module:: pcapkit.utilities.warnings -:mod:`pcapkit.warnings` refined built-in warnings. +:mod:`pcapkit.utilities.warnings` refined built-in warnings. + +Every warning :mod:`pcapkit` reports goes through :func:`warn`, which reports it +**exactly once on each of two channels**: + +1. the :data:`~pcapkit.utilities.logging.logger` logger, at + :data:`logging.WARNING` level, unconditionally -- so a consumer watching the + ``pcapkit`` logger sees every complaint whatever the warning filters say; +2. the standard :mod:`warnings` machinery, via :func:`warnings.warn`, subject to + the filters -- so :func:`warnings.filterwarnings`, + :func:`warnings.catch_warnings`, :mod:`pytest`'s ``filterwarnings``, + :option:`-W` and :envvar:`PYTHONWARNINGS` govern :mod:`pcapkit` warnings + exactly as they govern any other library's (see below for the one wrinkle in + naming a category on the command line). + +The counts are the same in development mode as outside it; +:data:`~pcapkit.utilities.logging.DEVMODE` and +:data:`~pcapkit.utilities.logging.VERBOSE` change how much detail the log record +carries, never how many records there are. Constructing a warning class is not +an act of reporting one, and has no side effects at all. + +To silence :mod:`pcapkit` warnings, filter them like any other category:: + + import warnings + + from pcapkit.utilities.warnings import BaseWarning + + warnings.filterwarnings('ignore', category=BaseWarning) + +From the command line, name one of the standard categories these are mixed with +-- :exc:`UserWarning` covers all of them, and :exc:`RuntimeWarning`, +:exc:`ImportWarning`, :exc:`ResourceWarning` and :exc:`DeprecationWarning` each +select a family:: + + python -W ignore::UserWarning ... + +:option:`-W` and :envvar:`PYTHONWARNINGS` cannot name a :mod:`pcapkit` category +directly -- ``-W ignore::pcapkit.utilities.warnings.BaseWarning`` is rejected +with ``Invalid -W option ignored: invalid module name``. CPython imports the +category while parsing the option, which happens before :mod:`site` has added +``site-packages`` to :data:`sys.path`, so no installed package's own category can +be named there; this is not specific to :mod:`pcapkit`. + +Note that all of the above governs the :mod:`warnings` channel only. The +``pcapkit`` logger is configured separately, e.g. with +``logging.getLogger('pcapkit').setLevel(logging.ERROR)``. """ import warnings from typing import TYPE_CHECKING from pcapkit.utilities.exceptions import stacklevel as stacklevel_calculator -from pcapkit.utilities.logging import DEVMODE, VERBOSE, get_logger +from pcapkit.utilities.logging import VERBOSE, get_logger if TYPE_CHECKING: - from typing import Any, Optional, Type, Union + from typing import Optional, Type, Union __all__ = [ 'warn', @@ -45,11 +90,23 @@ def warn(message: 'Union[str, Warning]', category: 'Type[Warning]', stacklevel: 'Optional[int]' = None) -> 'None': """Wrapper function of :func:`warnings.warn`. + The warning is reported once on the :data:`~pcapkit.utilities.logging.logger` + logger, then once through :func:`warnings.warn`. The logger call does not + consult :data:`warnings.filters`, so a log-based consumer sees the complaint + even when the application has filtered the category out; the + :func:`warnings.warn` call is filtered normally, so the application keeps + full control of that channel -- including turning the warning into an error + with :option:`-W error <-W>`. + Args: message: Warning message. category: Warning category. stacklevel: Warning stack level. + See Also: + :mod:`pcapkit.utilities.warnings` for the emission model in full, and for + how to silence either channel. + """ if stacklevel is None: stacklevel = stacklevel_calculator() @@ -65,21 +122,26 @@ def warn(message: 'Union[str, Warning]', category: 'Type[Warning]', class BaseWarning(UserWarning): - """Base warning class of all kinds.""" - - def __init__(self, *args: 'Any', **kwargs: 'Any') -> 'None': # pylint: disable=useless-super-delegation - # log warning - if DEVMODE: - if VERBOSE: - logger.warning(str(self), exc_info=self, stack_info=True, - stacklevel=stacklevel_calculator()) - else: - logger.warning(str(self)) - else: - warnings.simplefilter('ignore', type(self)) - - # warnings.simplefilter('default') - super().__init__(*args, **kwargs) + """Base warning class of all kinds. + + Constructing one of these is deliberately free of side effects: it emits + nothing and mutates no process-global state. Reporting a warning is the job + of :func:`warn`, which is called once per complaint; a warning object may be + built without ever being reported, and the two must not be confused. + + Note: + Up to and including v1.4.1, this constructor called + ``warnings.simplefilter('ignore', type(self))`` outside development + mode, which inserted an entry at the front of the process-global + :data:`warnings.filters` -- overriding whatever the host application, + :option:`-W` or the test runner had configured, and invalidating every + module's ``__warningregistry__`` so that unrelated warnings re-fired. + It also logged the warning a second time under + :data:`~pcapkit.utilities.logging.DEVMODE`. Both are gone; filtering is + the application's business, and is done through the standard + :mod:`warnings` machinery. + + """ ############################################################################## diff --git a/tests/utilities/_harness.py b/tests/utilities/_harness.py new file mode 100644 index 0000000000..a382117e85 --- /dev/null +++ b/tests/utilities/_harness.py @@ -0,0 +1,102 @@ +"""Shared scaffolding for the warning/exception emission regressions. + +Two things the tests in this directory need and the stdlib does not offer in a +form that fits: + +* :func:`capture` -- collect every record a :class:`logging.Logger` emits, at any + level, without also printing it. :mod:`unittest.TestCase.assertNoLogs` would do + half of this but only exists on Python 3.10+, and this project declares support + from 3.6. +* :func:`bootstrap` -- (re)load the :mod:`pcapkit` core modules with + :envvar:`PCAPKIT_DEVMODE` forced on or off. The flag is read once, at import + time, so a test that cares about it has to control the environment *before* the + import rather than patch a module global afterwards. + +It is deliberately not named ``test_*``, so :program:`pytest` imports it only +when a test asks for it. + +""" +from __future__ import annotations + +import contextlib +import logging +import os +import sys +from typing import TYPE_CHECKING + +from tests._support import bootstrap_core_modules, purge_modules + +if TYPE_CHECKING: + from typing import Iterator + +__all__ = ['Recorder', 'capture', 'bootstrap'] + + +class Recorder(logging.Handler): + """A handler that keeps the records instead of formatting them.""" + + def __init__(self) -> None: + super().__init__(level=logging.NOTSET) + self.records = [] # type: list[logging.LogRecord] + + def emit(self, record: 'logging.LogRecord') -> None: + self.records.append(record) + + @property + def messages(self) -> 'list[tuple[str, str]]': + """Every captured record so far, as ``(levelname, message)`` pairs.""" + return [(record.levelname, record.getMessage()) for record in self.records] + + +@contextlib.contextmanager +def capture(logger: 'logging.Logger') -> 'Iterator[Recorder]': + """Take ``logger`` over for the duration of the block. + + :mod:`pcapkit.utilities.logging` attaches a :class:`logging.StreamHandler` to + :data:`sys.stderr` at import time, so a test that merely *adds* a handler + both counts records and prints them. This swaps the handler list out, drops + the level to :data:`~logging.DEBUG` so that nothing is filtered out before it + can be counted, turns off propagation, and restores all three afterwards. + + Capturing at :data:`~logging.DEBUG` is deliberate: an assertion that a quiet + error logs *nothing* must be able to see a record that has been demoted to + ``DEBUG``, that being one of the things it might plausibly be changed to. + + """ + recorder = Recorder() + handlers, level, propagate = logger.handlers, logger.level, logger.propagate + logger.handlers = [recorder] + logger.setLevel(logging.DEBUG) + logger.propagate = False + try: + yield recorder + finally: + logger.handlers = handlers + logger.setLevel(level) + logger.propagate = propagate + + +def bootstrap(devmode: 'bool') -> 'dict[str, object]': + """Reload the :mod:`pcapkit` core modules with ``PCAPKIT_DEVMODE`` forced. + + Returns the mapping :func:`tests._support.bootstrap_core_modules` returns, + plus the freshly loaded ``logging`` module under the key ``'logging'``. + + The caller is responsible for restoring :data:`os.environ`; the test cases + here do it in ``tearDown``. + + """ + os.environ['PCAPKIT_DEVMODE'] = '1' if devmode else '0' + purge_modules(['pcapkit']) + modules = dict(bootstrap_core_modules()) + modules['logging'] = sys.modules['pcapkit.utilities.logging'] + + # Guard against the test passing for the wrong reason: several of these + # regressions only reproduce with development mode off, so a silently + # ignored environment variable would turn a real assertion into a no-op. + if getattr(modules['logging'], 'DEVMODE') is not devmode: + raise AssertionError( + 'PCAPKIT_DEVMODE did not take effect: expected DEVMODE=%r, got %r' + % (devmode, getattr(modules['logging'], 'DEVMODE')) + ) + return modules diff --git a/tests/utilities/_unrelated_warning.py b/tests/utilities/_unrelated_warning.py new file mode 100644 index 0000000000..81d512a155 --- /dev/null +++ b/tests/utilities/_unrelated_warning.py @@ -0,0 +1,33 @@ +"""A stand-in for third-party code that has never heard of :mod:`pcapkit`. + +The module exists to give the :mod:`tests.utilities.test_warning_filters` +regression a *control arm*: it owns its own warning category and does not import +:mod:`pcapkit`, so anything observed about its warnings is attributable to +whatever ran in between rather than to the observation itself. + +It is deliberately not named ``test_*``, so :program:`pytest` imports it only +when a test asks for it. + +""" +from __future__ import annotations + +import warnings + + +class UnrelatedWarning(UserWarning): + """A category :mod:`pcapkit` knows nothing about.""" + + +def emit() -> None: + """Warn once, at the default ``stacklevel``. + + The default ``stacklevel`` of 1 is load-bearing. It makes the + ``__warningregistry__`` consulted by the ``default`` action *this* module's, + keyed on *this* line, so repeated calls de-duplicate however far apart their + call sites are. Passing ``stacklevel=2`` would key the registry on each + caller's line instead, and identical calls from two different lines would + then both be shown -- which looks exactly like the re-firing this test is + trying to detect. + + """ + warnings.warn('unrelated third-party complaint', UnrelatedWarning) diff --git a/tests/utilities/test_exceptions_warnings.py b/tests/utilities/test_exceptions_warnings.py index 7793b322b2..f5ea6cd2fb 100644 --- a/tests/utilities/test_exceptions_warnings.py +++ b/tests/utilities/test_exceptions_warnings.py @@ -25,10 +25,14 @@ def test_struct_error_records_eof_flag(self) -> None: self.assertEqual(str(error), 'truncated') def test_base_error_limits_traceback_in_non_dev_mode(self) -> None: + # Only a *loud* error does this: `sys.tracebacklimit` is process-global, + # and a quiet error is internal control flow that must not truncate + # unrelated tracebacks. See tests/utilities/test_quiet_exceptions.py. original = getattr(sys, 'tracebacklimit', None) try: with mock.patch.object(self.exceptions, 'DEVMODE', False): - self.exceptions.BaseError('boom', quiet=True) + with mock.patch.object(self.exceptions.logger, 'critical'): + self.exceptions.BaseError('boom') self.assertEqual(sys.tracebacklimit, 0) finally: if original is None: @@ -46,15 +50,20 @@ def test_base_error_devmode_logs_with_verbose_metadata(self) -> None: critical.assert_called_once() self.assertTrue(critical.call_args.kwargs['stack_info']) - def test_warn_suppresses_base_warning_categories_outside_dev_mode(self) -> None: - with mock.patch.object(self.warnings, 'DEVMODE', False): + def test_warn_delivers_base_warning_categories_to_the_caller(self) -> None: + # pcapkit no longer installs an `ignore` filter of its own, so a caller + # who asks to see the warning sees it. Whether it is displayed, raised or + # dropped is now entirely the application's decision -- see + # tests/utilities/test_warning_filters.py for that contract in full. + with mock.patch.object(self.warnings.logger, 'warning'): with pywarnings.catch_warnings(record=True) as records: pywarnings.simplefilter('always') self.warnings.warn('careful', self.warnings.FormatWarning, stacklevel=1) - self.assertEqual(records, []) + self.assertEqual(len(records), 1) + self.assertIs(records[0].category, self.warnings.FormatWarning) - def test_warn_default_stacklevel_and_base_warning_devmode_logging(self) -> None: + def test_warn_passes_the_calculated_stacklevel_to_the_logger(self) -> None: with mock.patch.object(self.warnings, 'stacklevel_calculator', return_value=3): with mock.patch.object(self.warnings.logger, 'warning') as logger_warning: with pywarnings.catch_warnings(record=True) as records: @@ -62,21 +71,21 @@ def test_warn_default_stacklevel_and_base_warning_devmode_logging(self) -> None: self.warnings.warn('careful', UserWarning) self.assertEqual(len(records), 1) + logger_warning.assert_called_once() self.assertEqual(logger_warning.call_args.kwargs['stacklevel'], 3) - with mock.patch.object(self.warnings, 'DEVMODE', True): - with mock.patch.object(self.warnings, 'VERBOSE', True): - with mock.patch.object(self.warnings.logger, 'warning') as logger_warning: - warning = self.warnings.BaseWarning('dev warning') - self.assertIsInstance(warning, self.warnings.BaseWarning) - logger_warning.assert_called_once() - self.assertTrue(logger_warning.call_args.kwargs['stack_info']) + def test_constructing_a_base_warning_reports_nothing(self) -> None: + # Constructing a warning is not reporting one: the constructor logs + # nothing and installs no filter. See + # tests/utilities/test_warning_emission.py for the devmode arm. + with mock.patch.object(self.warnings.logger, 'warning') as logger_warning: + filters = pywarnings.filters[:] + warning = self.warnings.BaseWarning('dev warning') - with mock.patch.object(self.warnings, 'DEVMODE', True): - with mock.patch.object(self.warnings, 'VERBOSE', False): - with mock.patch.object(self.warnings.logger, 'warning') as logger_warning: - self.warnings.BaseWarning('dev warning') - logger_warning.assert_called_once_with('dev warning') + self.assertIsInstance(warning, self.warnings.BaseWarning) + self.assertEqual(str(warning), 'dev warning') + logger_warning.assert_not_called() + self.assertEqual(pywarnings.filters, filters) if __name__ == '__main__': diff --git a/tests/utilities/test_quiet_exceptions.py b/tests/utilities/test_quiet_exceptions.py new file mode 100644 index 0000000000..e72ae6d70e --- /dev/null +++ b/tests/utilities/test_quiet_exceptions.py @@ -0,0 +1,148 @@ +"""Regression tests for GH-362 -- ``quiet=True`` must mean *emit nothing*. + +``BaseError.__init__`` used to treat ``quiet`` as "log at ``ERROR`` instead of +``CRITICAL``", so every absent-key lookup through +:meth:`MultiDict.get ` -- which raises +:exc:`~pcapkit.utilities.exceptions.MissingKeyError` with ``quiet=True`` and +catches it immediately -- put an ``ERROR`` record on :data:`sys.stderr`. Parsing a +capture with unfragmented IPv6 and reassembly enabled produced one such record +per frame, for what the calling code itself documents as the ordinary case. + +The same constructor also set :data:`sys.tracebacklimit` to ``0`` on both +branches, so an absent-key ``.get()`` truncated the tracebacks of entirely +unrelated exceptions for the rest of the process. ``quiet=True`` now means no log +record on any channel and no process-global side effect; a loud error is +unchanged. + +""" +from __future__ import annotations + +import os +import sys +import traceback +import unittest + +from tests._support import purge_modules +from tests.utilities._harness import bootstrap, capture + + +def _unrelated_failure() -> 'int': + """Format an unrelated exception and count the traceback's lines. + + The :mod:`traceback` module honours :data:`sys.tracebacklimit`, so this is + what a logging handler using ``exc_info=True``, or a framework's error page, + would show for an exception that has nothing to do with :mod:`pcapkit`. + + """ + def inner() -> None: + raise ValueError('an exception that has nothing to do with pcapkit') + + def middle() -> None: + inner() + + try: + middle() + except ValueError: + return len(traceback.format_exc().splitlines()) + raise AssertionError('unreachable') # pragma: no cover + + +class QuietExceptionTests(unittest.TestCase): + def setUp(self) -> None: + self._saved_devmode = os.environ.get('PCAPKIT_DEVMODE') + self._saved_tracebacklimit = getattr(sys, 'tracebacklimit', None) + # The defect, and the traceback truncation, only reproduce outside + # development mode. + modules = bootstrap(devmode=False) + self.exceptions = modules['exceptions'] + self.multidict = modules['multidict'] + self.logger = modules['logging'].logger + + def tearDown(self) -> None: + if self._saved_tracebacklimit is None: + if hasattr(sys, 'tracebacklimit'): + del sys.tracebacklimit + else: + sys.tracebacklimit = self._saved_tracebacklimit + if self._saved_devmode is None: + os.environ.pop('PCAPKIT_DEVMODE', None) + else: + os.environ['PCAPKIT_DEVMODE'] = self._saved_devmode + purge_modules(['pcapkit']) + + def test_quiet_error_logs_nothing(self) -> None: + with capture(self.logger) as recorder: + error = self.exceptions.BaseError('boom', quiet=True) + + self.assertEqual(recorder.messages, []) + self.assertEqual(str(error), 'boom') + + def test_quiet_error_with_keyword_state_logs_nothing(self) -> None: + """A ``quiet`` subclass that carries extra state is still silent.""" + with capture(self.logger) as recorder: + error = self.exceptions.StructError('truncated', eof=True, quiet=True) + + self.assertEqual(recorder.messages, []) + self.assertTrue(error.eof) + self.assertEqual(str(error), 'truncated') + + def test_loud_error_still_logs_exactly_once_at_critical(self) -> None: + with capture(self.logger) as recorder: + self.exceptions.BaseError('boom') + + self.assertEqual(recorder.messages, [('CRITICAL', 'BaseError: boom')]) + + def test_absent_key_lookup_logs_nothing(self) -> None: + """``.get()`` on an absent key is control flow, not an error.""" + for name in ('MultiDict', 'OrderedMultiDict'): + with self.subTest(mapping=name): + mapping = getattr(self.multidict, name)() + + with capture(self.logger) as recorder: + missing = mapping.get('absent') + defaulted = mapping.get('absent', 'fallback') + + self.assertEqual(recorder.messages, []) + self.assertIsNone(missing) + self.assertEqual(defaulted, 'fallback') + + def test_absent_key_subscript_still_raises(self) -> None: + """Silencing the log must not silence the exception.""" + for name in ('MultiDict', 'OrderedMultiDict'): + with self.subTest(mapping=name): + mapping = getattr(self.multidict, name)() + + with capture(self.logger) as recorder: + with self.assertRaises(self.exceptions.MissingKeyError): + mapping['absent'] + with self.assertRaises(KeyError): + mapping['absent'] + + self.assertEqual(recorder.messages, []) + + def test_quiet_error_leaves_tracebacklimit_alone(self) -> None: + if hasattr(sys, 'tracebacklimit'): + del sys.tracebacklimit + before = _unrelated_failure() + + with capture(self.logger): + self.multidict.OrderedMultiDict().get('absent') + self.exceptions.BaseError('boom', quiet=True) + + self.assertFalse(hasattr(sys, 'tracebacklimit')) + self.assertEqual(_unrelated_failure(), before) + self.assertGreater(before, 1) + + def test_loud_error_still_limits_the_traceback(self) -> None: + """The feature a loud error provides is unchanged.""" + if hasattr(sys, 'tracebacklimit'): + del sys.tracebacklimit + + with capture(self.logger): + self.exceptions.BaseError('boom') + + self.assertEqual(sys.tracebacklimit, 0) + + +if __name__ == '__main__': + unittest.main() diff --git a/tests/utilities/test_warning_emission.py b/tests/utilities/test_warning_emission.py new file mode 100644 index 0000000000..119fb33eab --- /dev/null +++ b/tests/utilities/test_warning_emission.py @@ -0,0 +1,135 @@ +"""Regression tests for GH-363 -- one :func:`~pcapkit.utilities.warnings.warn` +call must produce exactly one record on each channel. + +The emission model, which these tests pin: + +* exactly **one** :mod:`logging` record, on the ``pcapkit`` logger, at + ``WARNING`` level, whatever the warning filters say; +* exactly **one** :mod:`warnings`-module emission, subject to the filters; +* **the same counts in development mode and out of it** -- + :envvar:`PCAPKIT_DEVMODE` and :envvar:`PCAPKIT_VERBOSE` change how much detail + the log record carries, never how many records there are; +* constructing a warning category is **not** an emission, and reports nothing. + +Before the fix the counts were: 1 outside development mode (the +:mod:`warnings` emission was swallowed by the filter the constructor installed -- +see GH-364) and 3 in development mode (two log records, from ``warn()`` and again +from ``BaseWarning.__init__``, plus the :mod:`warnings` emission). + +""" +from __future__ import annotations + +import os +import unittest +import warnings as pywarnings +from unittest import mock + +from tests._support import purge_modules +from tests.utilities._harness import bootstrap, capture + + +class WarningEmissionTests(unittest.TestCase): + def setUp(self) -> None: + self._saved_devmode = os.environ.get('PCAPKIT_DEVMODE') + + def tearDown(self) -> None: + if self._saved_devmode is None: + os.environ.pop('PCAPKIT_DEVMODE', None) + else: + os.environ['PCAPKIT_DEVMODE'] = self._saved_devmode + purge_modules(['pcapkit']) + + def emissions(self, devmode: 'bool', verbose: 'bool' = False, + category: 'type | None' = None) -> 'tuple[list, list]': + """Report one warning and return ``(log records, warnings emissions)``.""" + modules = bootstrap(devmode=devmode) + warnings_module = modules['warnings'] + logger = modules['logging'].logger + if category is None: + category = warnings_module.SchemaWarning + + with mock.patch.object(warnings_module, 'VERBOSE', verbose): + with capture(logger) as recorder: + with pywarnings.catch_warnings(record=True) as records: + pywarnings.resetwarnings() + pywarnings.simplefilter('always') + warnings_module.warn('a complaint', category, stacklevel=1) + return recorder.records, list(records) + + def test_one_record_per_channel_outside_devmode(self) -> None: + records, emissions = self.emissions(devmode=False) + + self.assertEqual(len(records), 1) + self.assertEqual(records[0].levelname, 'WARNING') + self.assertEqual(records[0].getMessage(), 'a complaint') + + self.assertEqual(len(emissions), 1) + self.assertEqual(str(emissions[0].message), 'a complaint') + + def test_one_record_per_channel_in_devmode(self) -> None: + records, emissions = self.emissions(devmode=True) + + self.assertEqual(len(records), 1) + self.assertEqual(records[0].levelname, 'WARNING') + self.assertEqual(records[0].getMessage(), 'a complaint') + + self.assertEqual(len(emissions), 1) + self.assertEqual(str(emissions[0].message), 'a complaint') + + def test_counts_do_not_depend_on_devmode_or_verbose(self) -> None: + for devmode in (False, True): + for verbose in (False, True): + with self.subTest(devmode=devmode, verbose=verbose): + records, emissions = self.emissions(devmode=devmode, verbose=verbose) + self.assertEqual(len(records), 1) + self.assertEqual(len(emissions), 1) + + def test_a_non_pcapkit_category_is_reported_the_same_way(self) -> None: + """The counts must not depend on the category being a ``BaseWarning``. + + A ``BaseWarning`` used to be reported a different number of times from a + plain :exc:`UserWarning`, because only the former ran the constructor that + logged and filtered. + + """ + for devmode in (False, True): + with self.subTest(devmode=devmode): + records, emissions = self.emissions(devmode=devmode, category=UserWarning) + self.assertEqual(len(records), 1) + self.assertEqual(len(emissions), 1) + + def test_constructing_a_warning_reports_nothing(self) -> None: + """Building a warning object is not reporting a warning.""" + for devmode in (False, True): + with self.subTest(devmode=devmode): + modules = bootstrap(devmode=devmode) + warnings_module = modules['warnings'] + + with capture(modules['logging'].logger) as recorder: + with pywarnings.catch_warnings(record=True) as records: + pywarnings.resetwarnings() + pywarnings.simplefilter('always') + warning = warnings_module.SchemaWarning('just constructing the object') + + self.assertIsInstance(warning, warnings_module.BaseWarning) + self.assertEqual(str(warning), 'just constructing the object') + self.assertEqual(recorder.messages, []) + self.assertEqual(list(records), []) + + def test_the_log_record_is_emitted_even_when_the_category_is_filtered_out(self) -> None: + """The two channels are independent: filtering one does not mute the other.""" + modules = bootstrap(devmode=False) + warnings_module = modules['warnings'] + + with capture(modules['logging'].logger) as recorder: + with pywarnings.catch_warnings(record=True) as records: + pywarnings.resetwarnings() + pywarnings.simplefilter('ignore') + warnings_module.warn('a complaint', warnings_module.SchemaWarning, stacklevel=1) + + self.assertEqual(len(recorder.records), 1) + self.assertEqual(list(records), []) + + +if __name__ == '__main__': + unittest.main() diff --git a/tests/utilities/test_warning_filters.py b/tests/utilities/test_warning_filters.py new file mode 100644 index 0000000000..efcd5fb510 --- /dev/null +++ b/tests/utilities/test_warning_filters.py @@ -0,0 +1,216 @@ +"""Regression tests for GH-364 -- constructing a pcapkit warning must not touch +the process-global :data:`warnings.filters`. + +``BaseWarning.__init__`` used to call ``warnings.simplefilter('ignore', +type(self))`` outside development mode. That inserted an entry at index 0 of the +filter list -- *ahead* of everything the interpreter, :option:`-W` and the host +application had put there -- and never removed it. Two consequences reached code +that has nothing to do with :mod:`pcapkit`: + +1. the application's own configuration for the category was overridden, so + ``-W error`` and a programmatic :func:`warnings.simplefilter` were both + defeated; +2. :func:`warnings.simplefilter` calls ``warnings._filters_mutated()``, which + invalidates every module's ``__warningregistry__``, so an unrelated + once-per-location warning was reported a second time. + +Every test here forces ``PCAPKIT_DEVMODE=0``, because the defect only reproduced +outside development mode -- in development mode the constructor logged instead of +filtering, and these assertions would pass against the unfixed code. + +""" +from __future__ import annotations + +import os +import unittest +import warnings as pywarnings + +from tests._support import purge_modules +from tests.utilities import _unrelated_warning +from tests.utilities._harness import bootstrap, capture + +#: Every warning category the module exports, by name. +CATEGORY_NAMES = [ + 'BaseWarning', + 'FormatWarning', 'EngineWarning', 'InvalidVendorWarning', + 'FileWarning', 'LayerWarning', 'ProtocolWarning', 'AttributeWarning', + 'DevModeWarning', 'VendorRequestWarning', 'VendorRuntimeWarning', + 'UnknownFieldWarning', 'RegistryWarning', 'SchemaWarning', 'InfoWarning', + 'SeekWarning', 'ExtractionWarning', + 'DPKTWarning', 'ScapyWarning', 'PySharkWarning', 'EmojiWarning', + 'VendorWarning', + 'DeprecatedFormatWarning', +] + + +class WarningFilterTests(unittest.TestCase): + def setUp(self) -> None: + self._saved_devmode = os.environ.get('PCAPKIT_DEVMODE') + modules = bootstrap(devmode=False) + self.warnings = modules['warnings'] + self.logger = modules['logging'].logger + + def tearDown(self) -> None: + if self._saved_devmode is None: + os.environ.pop('PCAPKIT_DEVMODE', None) + else: + os.environ['PCAPKIT_DEVMODE'] = self._saved_devmode + purge_modules(['pcapkit']) + + def categories(self) -> 'list[type]': + return [getattr(self.warnings, name) for name in CATEGORY_NAMES] + + def test_constructing_a_warning_leaves_the_global_filters_identical(self) -> None: + """Construct every category and require the filter list to be unchanged.""" + with pywarnings.catch_warnings(): + # A stand-in for the configuration an application, a test runner or + # `-W` would have installed: `error` for the unrelated category, + # `ignore` for a category pcapkit does use. + pywarnings.resetwarnings() + pywarnings.simplefilter('always') + pywarnings.filterwarnings('error', category=_unrelated_warning.UnrelatedWarning) + pywarnings.filterwarnings('ignore', category=DeprecationWarning) + snapshot = pywarnings.filters[:] + + for category in self.categories(): + category('just constructing the object') + + self.assertEqual(pywarnings.filters, snapshot) + # Called out separately: index 0 is the slot `simplefilter` used to + # take over, and the one that decides which action wins. + self.assertEqual(pywarnings.filters[0], snapshot[0]) + self.assertEqual(len(pywarnings.filters), len(snapshot)) + + def test_warn_leaves_the_global_filters_identical(self) -> None: + """The same, going through :func:`warn` rather than the constructor.""" + with capture(self.logger): + with pywarnings.catch_warnings(record=True): + pywarnings.resetwarnings() + pywarnings.simplefilter('always') + snapshot = pywarnings.filters[:] + + self.warnings.warn('a complaint', self.warnings.SchemaWarning, stacklevel=1) + + self.assertEqual(pywarnings.filters, snapshot) + + def test_application_filter_configuration_is_honoured(self) -> None: + """``simplefilter('error')`` must turn a pcapkit warning into an error. + + This is the programmatic equivalent of ``python -W error``, which the + index-0 override used to defeat. + + """ + with capture(self.logger): + with pywarnings.catch_warnings(): + pywarnings.resetwarnings() + pywarnings.simplefilter('error') + + with self.assertRaises(self.warnings.SchemaWarning): + self.warnings.warn('a complaint', self.warnings.SchemaWarning, stacklevel=1) + + def test_application_can_still_silence_pcapkit_warnings(self) -> None: + """The suppression pcapkit used to impose must remain available to the caller.""" + with capture(self.logger): + with pywarnings.catch_warnings(record=True) as records: + pywarnings.resetwarnings() + pywarnings.simplefilter('always') + pywarnings.filterwarnings('ignore', category=self.warnings.BaseWarning) + + self.warnings.warn('a complaint', self.warnings.SchemaWarning, stacklevel=1) + + self.assertEqual([record.message for record in records], []) + + def test_a_standard_base_category_filter_reaches_pcapkit_warnings(self) -> None: + """``-W ignore::UserWarning`` and friends must reach pcapkit's categories. + + This is the command-line escape hatch the documentation offers, since + :option:`-W` cannot name a pcapkit category directly -- CPython resolves + the category before :mod:`site` puts ``site-packages`` on + :data:`sys.path`. Filtering on the standard category each pcapkit warning + is mixed with is what works, so the mixin has to keep working. + + """ + cases = [ + (UserWarning, self.warnings.SchemaWarning), + (RuntimeWarning, self.warnings.SchemaWarning), + (ImportWarning, self.warnings.FormatWarning), + (ResourceWarning, self.warnings.DPKTWarning), + (DeprecationWarning, self.warnings.DeprecatedFormatWarning), + ] + for standard, pcapkit_category in cases: + with self.subTest(standard=standard.__name__, + category=pcapkit_category.__name__): + self.assertTrue(issubclass(pcapkit_category, standard)) + + with capture(self.logger): + with pywarnings.catch_warnings(): + pywarnings.resetwarnings() + pywarnings.simplefilter('always') + pywarnings.filterwarnings('error', category=standard) + + with self.assertRaises(pcapkit_category): + self.warnings.warn('a complaint', pcapkit_category, stacklevel=1) + + def test_unrelated_category_configuration_survives(self) -> None: + """A filter for a category pcapkit has never heard of keeps working.""" + with capture(self.logger): + with pywarnings.catch_warnings(): + pywarnings.resetwarnings() + pywarnings.simplefilter('always') + pywarnings.filterwarnings('error', category=_unrelated_warning.UnrelatedWarning) + + for category in self.categories(): + category('just constructing the object') + self.warnings.warn('a complaint', self.warnings.SchemaWarning, stacklevel=1) + + with self.assertRaises(_unrelated_warning.UnrelatedWarning): + _unrelated_warning.emit() + + def refire_probe(self, middle: 'object') -> 'tuple[int, int]': + """Count an unrelated module's warnings before and after ``middle`` runs. + + Emits the unrelated warning twice under the ``default`` action, so the + second one is de-duplicated, then runs ``middle``, then emits a third + time. Returns ``(count after two, count after three)``; equal values mean + de-duplication survived whatever ``middle`` did. + + """ + with pywarnings.catch_warnings(record=True) as records: + pywarnings.resetwarnings() + pywarnings.simplefilter('default') + + _unrelated_warning.emit() + _unrelated_warning.emit() + deduplicated = len([record for record in records + if record.category is _unrelated_warning.UnrelatedWarning]) + + middle() # type: ignore[operator] + + _unrelated_warning.emit() + afterwards = len([record for record in records + if record.category is _unrelated_warning.UnrelatedWarning]) + return deduplicated, afterwards + + def test_unrelated_warnings_do_not_refire(self) -> None: + """An unrelated de-duplicated warning must not be reported again. + + The control arm establishes that the probe can tell the two apart: a + plain :func:`warnings.warn` in the middle does not disturb the registry, + so if the pcapkit arm shows a re-fire it is pcapkit's doing. + + """ + control = self.refire_probe(lambda: pywarnings.warn('control', DeprecationWarning)) + self.assertEqual(control, (1, 1), 'control arm re-fired; the probe cannot ' + 'attribute a re-fire to pcapkit') + + with capture(self.logger): + constructed = self.refire_probe(lambda: self.warnings.SchemaWarning('probe')) + reported = self.refire_probe( + lambda: self.warnings.warn('probe', self.warnings.SchemaWarning, stacklevel=1)) + + self.assertEqual(constructed, (1, 1)) + self.assertEqual(reported, (1, 1)) + + +if __name__ == '__main__': + unittest.main()