From bbcf51f0b172d2b41c95fa3eb5c60c07bac9e669 Mon Sep 17 00:00:00 2001 From: Jarry Shaw Date: Mon, 14 Sep 2026 21:28:00 -0400 Subject: [PATCH 1/4] logging: make the logger a library citizen, and use it pcapkit configured logging at import: a single flat logger named 'pcapkit', with a StreamHandler on stderr attached and the level forced from PCAPKIT_DEVMODE. Importing the library therefore hijacked the consumer's logging, and undoing it meant reaching into logger.handlers. There was also no way to change verbosity at runtime, since the environment variable is read once. Now a NullHandler and no level at import, so verbosity is inherited from the application, with the old stderr handler kept for PCAPKIT_DEVMODE as the opt-in path. Alongside the existing logger object: get_logger() for per-module children, configure() to set level, handler, stream, format or propagation at runtime and per logger name, reset() to return to library-neutral, and ensure_output() for the verbose= path. Seventeen modules take getLogger(__name__), so a consumer can silence pcapkit.foundation.registry while keeping pcapkit.foundation.extraction. The library was also nearly silent where it mattered and noisy where it did not. 38 info calls become debug - 34 of them registry bookkeeping, 4 extractor configuration - leaving exactly one info in the package, the pcapkit-vendor CLI progress line. Four print calls that were clearly meant to be logging, each self-documenting with a logging-fstring-interpolation suppression, become logger.debug with lazy % args. And 31 new debug calls cover what was undiagnosable: extractor lifecycle, engine selection and fallback, reassembly and trace-flow entry points. Nothing was added to per-frame or per-field loops. Behaviour changes a consumer could notice, all documented in a compatibility note on the new docs page: no stderr handler at import (restore with configure(logging.INFO, stream=sys.stderr)); registry messages invisible even at INFO; handler is no longer logger.handlers[0]; and verbose=True logs at debug, so ensure_output() attaches a stderr handler only when nothing up the chain would receive the record - otherwise Extractor(verbose=True) would have gone silent. warnings.py keeps its behaviour: the double-emit and the global simplefilter mutation are filed as #363 and #364 and want their own change. --- docs/source/pcapkit/utilities/index.rst | 40 +- docs/source/pcapkit/utilities/logging.rst | 199 ++++++++++ docs/source/pep.rst | 46 ++- pcapkit/dumpkit/common.py | 8 +- pcapkit/foundation/engines/dpkt.py | 15 +- pcapkit/foundation/engines/pcap.py | 8 + pcapkit/foundation/engines/pcapng.py | 6 + pcapkit/foundation/engines/pyshark.py | 15 +- pcapkit/foundation/engines/scapy.py | 14 +- pcapkit/foundation/extraction.py | 42 ++- pcapkit/foundation/reassembly/reassembly.py | 13 + pcapkit/foundation/registry/foundation.py | 26 +- pcapkit/foundation/registry/protocols.py | 54 +-- pcapkit/foundation/traceflow/tcp.py | 10 + pcapkit/foundation/traceflow/traceflow.py | 13 +- pcapkit/protocols/transport/transport.py | 7 +- pcapkit/utilities/__init__.py | 5 +- pcapkit/utilities/decorators.py | 7 +- pcapkit/utilities/exceptions.py | 7 +- pcapkit/utilities/logging.py | 306 ++++++++++++++- pcapkit/utilities/warnings.py | 7 +- pcapkit/vendor/__main__.py | 7 +- tests/utilities/test_logging.py | 395 +++++++++++++++++++- 23 files changed, 1133 insertions(+), 117 deletions(-) create mode 100644 docs/source/pcapkit/utilities/logging.rst diff --git a/docs/source/pcapkit/utilities/index.rst b/docs/source/pcapkit/utilities/index.rst index 897d83aa50..9a15ab3ae4 100644 --- a/docs/source/pcapkit/utilities/index.rst +++ b/docs/source/pcapkit/utilities/index.rst @@ -16,45 +16,7 @@ several user-refined exceptions and warnings. functools exceptions warnings - -Logging System -============== - -.. module:: pcapkit.utilities.logging - -:mod:`pcapkit.utilities.logging` contains naïve integration -of the Python logging system, i.e. a :class:`logging.Logger` -instance as :data:`~pcapkit.utilities.logging.logger`. - -.. autodata:: pcapkit.utilities.logging.logger - :no-value: - -Environment Variables ---------------------- - -.. autodata:: pcapkit.utilities.logging.DEVMODE - :no-value: - - .. seealso:: - - This variable can be configured through the environment variable - :envvar:`PCAPKIT_DEVMODE`. - -.. autodata:: pcapkit.utilities.logging.VERBOSE - :no-value: - - .. seealso:: - - This variable can be configured through the environment variable - :envvar:`PCAPKIT_VERBOSE`. - -.. autodata:: pcapkit.utilities.logging.SPHINX_TYPE_CHECKING - :no-value: - - .. seealso:: - - This variable can be configured through the environment variable - :envvar:`PCAPKIT_SPHINX`. + logging Version Compatibility ===================== diff --git a/docs/source/pcapkit/utilities/logging.rst b/docs/source/pcapkit/utilities/logging.rst new file mode 100644 index 0000000000..7b213b20c3 --- /dev/null +++ b/docs/source/pcapkit/utilities/logging.rst @@ -0,0 +1,199 @@ +============== +Logging System +============== + +.. module:: pcapkit.utilities.logging + +:mod:`pcapkit.utilities.logging` integrates :mod:`pcapkit` with the standard +:mod:`logging` system. It owns the package-wide logger hierarchy rooted at +:data:`~pcapkit.utilities.logging.logger` and the configuration API through +which an application decides what, if anything, :mod:`pcapkit` emits. + +.. autodata:: pcapkit.utilities.logging.logger + :no-value: + +The Logger Hierarchy +==================== + +``pcapkit`` is the root. Every module inside the package logs through its own +child logger, named after the module and obtained from +:func:`~pcapkit.utilities.logging.get_logger`, so a record carries the name of +the code that emitted it and any subtree can be addressed on its own: + +.. code-block:: python + + import logging + + # quieten the registry's bookkeeping, keep everything else + logging.getLogger('pcapkit.foundation.registry').setLevel(logging.WARNING) + + # or follow just the extraction path + logging.getLogger('pcapkit.foundation.extraction').setLevel(logging.DEBUG) + +The names in use are the module paths themselves, e.g. +``pcapkit.foundation.extraction``, ``pcapkit.foundation.registry.protocols``, +``pcapkit.foundation.engines.pcap``, ``pcapkit.foundation.reassembly.reassembly``, +``pcapkit.foundation.traceflow.tcp``, ``pcapkit.utilities.warnings``. + +.. autofunction:: pcapkit.utilities.logging.get_logger + +.. autodata:: pcapkit.utilities.logging.ROOT_LOGGER_NAME + +What ``DEBUG`` Will Tell You +============================ + +At :data:`logging.DEBUG` the library explains what it did with a file, without +descending to per-field parsing: which input was opened, which engine was +requested and which was actually used (including a fallback when an optional +dependency is missing), the file format identified from the magic number, the +output format and dumper, whether reassembly and flow tracing were enabled and +with which flags, how many frames were read, and when cleanup ran. Reassembly +reports datagram counts on flush and flow tracing reports flows opening and +closing. + +.. note:: + + Nothing is logged from inside per-frame or per-field parsing loops, so + enabling :data:`~logging.DEBUG` does not turn a capture with a million + packets into a million records. Registration bookkeeping across + :mod:`pcapkit.foundation.registry` is also at :data:`~logging.DEBUG` rather + than :data:`~logging.INFO`, since a library announcing its own registry + entries is not news to its consumer. + +Configuring the Output +====================== + +Importing :mod:`pcapkit` configures **no** logging output: the only handler +attached to :data:`~pcapkit.utilities.logging.logger` is a +:class:`logging.NullHandler`, and no level is set. This is the behaviour +recommended for libraries -- the application keeps control of its own logging, +and :mod:`pcapkit`'s records simply propagate into whatever it has configured, +typically via :func:`logging.basicConfig` or :mod:`logging.config`. + +For an application that would rather let :mod:`pcapkit` set up its own output, +:func:`~pcapkit.utilities.logging.configure` does so at runtime: + +.. code-block:: python + + import logging + import sys + + from pcapkit.utilities.logging import configure, reset + + # everything pcapkit does, on stderr + configure(logging.DEBUG, stream=sys.stderr) + + # to a file, with a format of your own + configure(logging.INFO, handler=logging.FileHandler('pcapkit.log'), + fmt='%(asctime)s %(name)s %(levelname)s %(message)s') + + # loud in general, quiet about the registry + configure(logging.DEBUG, stream=sys.stderr) + configure(logging.WARNING, name='pcapkit.foundation.registry') + + # and back to the pristine, library-neutral state + reset() + +.. autofunction:: pcapkit.utilities.logging.configure + +.. autofunction:: pcapkit.utilities.logging.reset + +.. autofunction:: pcapkit.utilities.logging.ensure_output + +Formatting +---------- + +.. autodata:: pcapkit.utilities.logging.DEFAULT_FORMAT + +.. autodata:: pcapkit.utilities.logging.DEFAULT_DATE_FORMAT + +.. autodata:: pcapkit.utilities.logging.formatter + :no-value: + +.. autodata:: pcapkit.utilities.logging.handler + :no-value: + +Environment Variables +===================== + +.. autodata:: pcapkit.utilities.logging.DEVMODE + :no-value: + + .. seealso:: + + This variable can be configured through the environment variable + :envvar:`PCAPKIT_DEVMODE`. + +.. autodata:: pcapkit.utilities.logging.VERBOSE + :no-value: + + .. seealso:: + + This variable can be configured through the environment variable + :envvar:`PCAPKIT_VERBOSE`. + +.. autodata:: pcapkit.utilities.logging.SPHINX_TYPE_CHECKING + :no-value: + + .. seealso:: + + This variable can be configured through the environment variable + :envvar:`PCAPKIT_SPHINX`. + +.. _logging-compatibility: + +Compatibility Note +================== + +.. warning:: + + :mod:`pcapkit` used to attach a :class:`logging.StreamHandler` on + :obj:`sys.stderr` and force the level to :data:`logging.INFO` (or + :data:`logging.DEBUG` under :envvar:`PCAPKIT_DEVMODE`) **at import time**. + That is no longer done, because it hijacked the logging configuration of + every application that imported :mod:`pcapkit`. + + Two consequences are visible to existing code: + + 1. **Messages that used to appear on stderr no longer do.** In particular the + ``registered ...`` bookkeeping is now at :data:`logging.DEBUG` rather than + :data:`logging.INFO`. Restore the old output in one line: + + .. code-block:: python + + import logging, sys + from pcapkit.utilities.logging import configure + configure(logging.INFO, stream=sys.stderr) + + Equivalently, re-attach the module's own handler, which is still built and + still carries the historical format: + + .. code-block:: python + + from pcapkit.utilities.logging import handler, logger + logger.setLevel(logging.INFO) + logger.addHandler(handler) + + 2. **The handler is no longer at** ``logger.handlers[0]``. Code that reached + into that list to remove or reconfigure the handler should call + :func:`~pcapkit.utilities.logging.reset` or + :func:`~pcapkit.utilities.logging.configure` instead. + + Unaffected: :data:`~pcapkit.utilities.logging.logger` remains public, + importable from both :mod:`pcapkit.utilities.logging` and + :mod:`pcapkit.utilities`, and named ``pcapkit``; + :envvar:`PCAPKIT_DEVMODE` still produces the stderr handler at + :data:`logging.DEBUG`; and ``Extractor(verbose=True)`` still prints a line per + frame, now through :data:`logging.DEBUG` with a destination guaranteed by + :func:`~pcapkit.utilities.logging.ensure_output` when the application has + configured none. + +.. 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. diff --git a/docs/source/pep.rst b/docs/source/pep.rst index 576082ae45..661a686ac2 100644 --- a/docs/source/pep.rst +++ b/docs/source/pep.rst @@ -63,9 +63,49 @@ specific file. Logging Integration ------------------- -As PyPCAPKit now has the :data:`pcapkit.utilities.logging.logger` in place, I'm -expecting to fully extend its functionality in the entire module. Ideas and -contributions are welcomed to integrate the logging system into PyPCAPKit. +.. note:: + + Largely **done**. :mod:`pcapkit.utilities.logging` is no longer a single flat + logger with a hard-wired handler. It now provides: + + - a **logger hierarchy** rooted at ``pcapkit``, with every module logging + through its own child obtained from + :func:`~pcapkit.utilities.logging.get_logger`, so that a subtree such as + ``pcapkit.foundation.registry`` can be silenced independently of + ``pcapkit.foundation.extraction``; + - **library-safe defaults** -- importing :mod:`pcapkit` attaches only a + :class:`logging.NullHandler` and sets no level, leaving the destination and + verbosity to the application. :envvar:`PCAPKIT_DEVMODE` still bootstraps the + historical :obj:`sys.stderr` handler at :data:`logging.DEBUG`; + - a **runtime configuration API** -- + :func:`~pcapkit.utilities.logging.configure`, + :func:`~pcapkit.utilities.logging.reset` and + :func:`~pcapkit.utilities.logging.ensure_output` -- rather than a single + environment variable read once at import; + - **levels chosen deliberately**. Registration bookkeeping across + :mod:`pcapkit.foundation.registry` moved from ``info`` to ``debug``, since + a library announcing its own registry entries is not news to its consumer; + and the four :func:`print` calls that were marked + ``# pylint: disable=logging-fstring-interpolation`` are now real logger + calls; + - **``debug`` coverage of the extraction path** -- extractor construction, + engine selection and fallback, frame counts, cleanup, reassembly and + flow-tracing setup -- so that ``DEBUG`` explains what PyPCAPKit did with a + file without descending into per-field parsing. + + See :doc:`pcapkit/utilities/logging` for the configuration recipes, including + the one-line restore of the pre-existing :obj:`sys.stderr` output. + + What remains wanted is the two items called out there as deliberately out of + scope: :func:`pcapkit.utilities.warnings.warn` still double-reports every + warning through both :mod:`logging` and :mod:`warnings`, and + :class:`~pcapkit.utilities.warnings.BaseWarning` still mutates the global + warning filters with :func:`warnings.simplefilter`. + +Originally: as PyPCAPKit now has the :data:`pcapkit.utilities.logging.logger` in +place, I'm expecting to fully extend its functionality in the entire module. +Ideas and contributions are welcomed to integrate the logging system into +PyPCAPKit. New Engines ----------- diff --git a/pcapkit/dumpkit/common.py b/pcapkit/dumpkit/common.py index 02b62ad5c1..c86c62ba97 100644 --- a/pcapkit/dumpkit/common.py +++ b/pcapkit/dumpkit/common.py @@ -24,10 +24,11 @@ from pcapkit.corekit.infoclass import Info from pcapkit.corekit.multidict import MultiDict, OrderedMultiDict from pcapkit.protocols.schema.schema import Schema -from pcapkit.utilities.logging import logger +from pcapkit.utilities.logging import get_logger __all__ = ['make_dumper'] + if TYPE_CHECKING: from typing import Any, DefaultDict, Optional, TextIO, Type @@ -35,6 +36,11 @@ from typing_extensions import Literal +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + + class DumperBase(dictdumper.dumper.Dumper): """Base :class:`~dictdumper.dumper.Dumper` object. diff --git a/pcapkit/foundation/engines/dpkt.py b/pcapkit/foundation/engines/dpkt.py index 0d9f91930b..5af66dbcbd 100644 --- a/pcapkit/foundation/engines/dpkt.py +++ b/pcapkit/foundation/engines/dpkt.py @@ -10,11 +10,13 @@ .. _DPKT: https://dpkt.readthedocs.io """ +import logging from typing import TYPE_CHECKING, cast from pcapkit.const.reg.linktype import LinkType as Enum_LinkType from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.utilities.exceptions import FormatError, stacklevel +from pcapkit.utilities.logging import ensure_output, get_logger from pcapkit.utilities.warnings import AttributeWarning, DPKTWarning, warn __all__ = ['DPKT'] @@ -30,6 +32,10 @@ Reader = Union[PCAPReader, PCAPNGReader] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + class DPKT(Engine['DPKTPacket']): """DPKT engine support. @@ -112,13 +118,16 @@ def run(self) -> 'None': # setup verbose handler if ext._flag_v: from pcapkit.toolkit.dpkt import packet2chain # isort:skip - ext._vfunc = lambda e, f: print( - f'Frame {e._frnum:>3d}: {packet2chain(f)}' # pylint: disable=protected-access - ) # pylint: disable=logging-fstring-interpolation + ensure_output(logging.DEBUG) + ext._vfunc = lambda e, f: logger.debug( + 'Frame %3d: %s', e._frnum, packet2chain(f) # pylint: disable=protected-access + ) if ext.magic_number in PCAP.MAGIC_NUMBER: + logger.debug('dpkt: reading %s as PCAP', ext._ifnm) reader = dpkt.pcap.Reader(ext._ifile) elif ext.magic_number in PCAPNG.MAGIC_NUMBER: + logger.debug('dpkt: reading %s as PCAP-NG', ext._ifnm) reader = dpkt.pcapng.Reader(ext._ifile) else: raise FormatError(f'unsupported file format: {ext.magic_number!r}') diff --git a/pcapkit/foundation/engines/pcap.py b/pcapkit/foundation/engines/pcap.py index 159d52bdbe..ea878588fe 100644 --- a/pcapkit/foundation/engines/pcap.py +++ b/pcapkit/foundation/engines/pcap.py @@ -13,6 +13,7 @@ from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.protocols.misc.pcap.frame import Frame from pcapkit.protocols.misc.pcap.header import Header +from pcapkit.utilities.logging import get_logger __all__ = ['PCAP'] @@ -20,6 +21,10 @@ from pcapkit.const.reg.linktype import LinkType as Enum_LinkType from pcapkit.corekit.version import VersionInfo +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + class PCAP(Engine[Frame]): """PCAP file extraction support. @@ -110,6 +115,9 @@ def run(self) -> 'None': self._dlink = self._gbhdr.protocol self._nnsec = self._gbhdr.nanosecond + logger.debug('PCAP global header: version %s, link layer %s, nanosecond %s', + self._vinfo, self._dlink.name, self._nnsec) + if ext._flag_q: return diff --git a/pcapkit/foundation/engines/pcapng.py b/pcapkit/foundation/engines/pcapng.py index 67aba8d19a..6ac20f93c4 100644 --- a/pcapkit/foundation/engines/pcapng.py +++ b/pcapkit/foundation/engines/pcapng.py @@ -15,10 +15,15 @@ from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.protocols.misc.pcapng import PCAPNG as P_PCAPNG from pcapkit.utilities.exceptions import FormatError, stacklevel +from pcapkit.utilities.logging import get_logger from pcapkit.utilities.warnings import DeprecatedFormatWarning, warn __all__ = ['PCAPNG'] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + if TYPE_CHECKING: from typing import Optional @@ -151,6 +156,7 @@ def run(self) -> 'None': self._ctx_list.append(self._ctx) shb._ctx = self._ctx + logger.debug('PCAP-NG section %d header read', len(self._ctx_list)) self._write_file(shb.info, name=f'Section Header {len(self._ctx_list)}') def read_frame(self) -> 'P_PCAPNG': diff --git a/pcapkit/foundation/engines/pyshark.py b/pcapkit/foundation/engines/pyshark.py index b9f591eece..9b88e0d0a2 100644 --- a/pcapkit/foundation/engines/pyshark.py +++ b/pcapkit/foundation/engines/pyshark.py @@ -10,11 +10,13 @@ .. _PyShark: https://kiminewt.github.io/pyshark """ +import logging from typing import TYPE_CHECKING, cast from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.foundation.reassembly import ReassemblyManager from pcapkit.utilities.exceptions import stacklevel +from pcapkit.utilities.logging import ensure_output, get_logger from pcapkit.utilities.warnings import AttributeWarning, warn __all__ = ['PyShark'] @@ -25,6 +27,10 @@ from pcapkit.foundation.extraction import Extractor +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + class PyShark(Engine['PySharkPacket']): """PyShark engine support. @@ -103,6 +109,7 @@ def run(self) -> 'None': if ext._flag_r and (ext._ipv4 or ext._ipv6 or ext._tcp): ext._flag_r = False + logger.debug('pyshark: reassembly unsupported, disabling it') ext._reasm = ReassemblyManager(ipv4=None, ipv6=None, tcp=None) warn("'Extractor(engine=pyshark)' object does not support reassembly; " f"so 'ipv4={ext._ipv4}', 'ipv6={ext._ipv6}' and 'tcp={ext._tcp}' will be ignored", @@ -110,11 +117,13 @@ def run(self) -> 'None': # setup verbose handler if ext._flag_v: - ext._vfunc = lambda e, f: print( - f'Frame {e._frnum:>3d}: {f.frame_info.protocols}' # pylint: disable=protected-access - ) # pylint: disable=logging-fstring-interpolation + ensure_output(logging.DEBUG) + ext._vfunc = lambda e, f: logger.debug( + 'Frame %3d: %s', e._frnum, f.frame_info.protocols # pylint: disable=protected-access + ) # extract & analyse file + logger.debug('pyshark: opening %s', ext._ifnm) self._extmp = self._expkg.FileCapture(ext._ifnm, keep_packets=False) def read_frame(self) -> 'PySharkPacket': diff --git a/pcapkit/foundation/engines/scapy.py b/pcapkit/foundation/engines/scapy.py index 70c177102f..c771640552 100644 --- a/pcapkit/foundation/engines/scapy.py +++ b/pcapkit/foundation/engines/scapy.py @@ -10,10 +10,12 @@ .. _Scapy: https://scapy.net """ +import logging from typing import TYPE_CHECKING, cast from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.utilities.exceptions import stacklevel +from pcapkit.utilities.logging import ensure_output, get_logger from pcapkit.utilities.warnings import AttributeWarning, warn __all__ = ['Scapy'] @@ -25,6 +27,10 @@ from pcapkit.foundation.extraction import Extractor +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + class Scapy(Engine['ScapyPacket']): """Scapy engine support. @@ -99,11 +105,13 @@ def run(self) -> 'None': # setup verbose handler if ext._flag_v: from pcapkit.toolkit.scapy import packet2chain # isort:skip - ext._vfunc = lambda e, f: print( - f'Frame {e._frnum:>3d}: {packet2chain(f)}' # pylint: disable=protected-access - ) # pylint: disable=logging-fstring-interpolation + ensure_output(logging.DEBUG) + ext._vfunc = lambda e, f: logger.debug( + 'Frame %3d: %s', e._frnum, packet2chain(f) # pylint: disable=protected-access + ) # extract & analyse file + logger.debug('scapy: sniffing %s', ext._ifnm) self._extmp = iter(self._expkg.sniff(offline=ext._ifnm)) def read_frame(self) -> 'ScapyPacket': diff --git a/pcapkit/foundation/extraction.py b/pcapkit/foundation/extraction.py index 676fe200dc..14ef14e7d6 100644 --- a/pcapkit/foundation/extraction.py +++ b/pcapkit/foundation/extraction.py @@ -16,6 +16,7 @@ import collections import importlib import io +import logging import os import sys from typing import TYPE_CHECKING, Generic, TypeVar, cast @@ -37,7 +38,7 @@ from pcapkit.foundation.traceflow.traceflow import TraceFlow from pcapkit.utilities.exceptions import (CallableError, FileNotFound, FormatError, IterableError, RegistryError, UnsupportedCall, stacklevel) -from pcapkit.utilities.logging import logger +from pcapkit.utilities.logging import ensure_output, get_logger from pcapkit.utilities.warnings import (EngineWarning, ExtractionWarning, FormatWarning, RegistryWarning, warn) @@ -70,6 +71,10 @@ __all__ = ['Extractor'] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + _P = TypeVar('_P') @@ -426,12 +431,15 @@ def run(self) -> 'None': # pylint: disable=inconsistent-return-statements :rtype: None """ + logger.debug('requested extraction engine: %s', self._exnam) + if self._exnam in self.__engine__: # check if engine is supported eng = self.__engine__[self._exnam] if isinstance(eng, ModuleDescriptor): eng = eng.klass if self.import_test(eng.module, name=eng.name) is not None: # type: ignore[arg-type] + logger.debug('using engine %s (%s)', eng.name, eng.module) self._exeng = eng(self) self._exeng.run() @@ -449,8 +457,10 @@ def run(self) -> 'None': # pylint: disable=inconsistent-return-statements self._exnam = 'default' # using default/pcapkit engine if self._magic in PCAP_Engine.MAGIC_NUMBER: + logger.debug('magic number %r identifies a PCAP file', self._magic) self._exeng = cast('Engine[_P]', PCAP_Engine(self)) elif self._magic in PCAPNG_Engine.MAGIC_NUMBER: + logger.debug('magic number %r identifies a PCAP-NG file', self._magic) self._exeng = cast('Engine[_P]', PCAPNG_Engine(self)) else: raise FormatError(f'unknown file format: {self._magic!r}') @@ -480,6 +490,7 @@ def import_test(engine: 'str', *, name: 'Optional[str]' = None) -> 'Optional[Mod module = importlib.import_module(engine) except ImportError: module = None + logger.debug('engine module %r is not importable', engine) warn(f"extraction engine '{name or engine}' not available; " 'using default engine instead', EngineWarning, stacklevel=stacklevel()) return module @@ -610,6 +621,7 @@ def record_frames(self) -> 'None': """ if self._flag_a: + logger.debug('reading frames from %s', self._ifnm) while True: try: self._exeng.read_frame() @@ -622,9 +634,11 @@ def record_frames(self) -> 'None': # quit when EOF break except KeyboardInterrupt: + logger.debug('interrupted after %d frame(s)', self._frnum) self._cleanup() raise + logger.debug('read %d frame(s) from %s', self._frnum, self._ifnm) self._cleanup() ########################################################################## @@ -732,9 +746,13 @@ def __init__(self, if isinstance(verbose, bool): self._flag_v = verbose if verbose: - self._vfunc = lambda e, f: print( - f'Frame {e._frnum:>3d}: {f.protochain}' # pylint: disable=protected-access - ) # pylint: disable=logging-fstring-interpolation + # ``verbose=True`` is an explicit request to see the frames, so + # make sure the records have a destination even in an + # application that never configured logging at all + ensure_output(logging.DEBUG) + self._vfunc = lambda e, f: logger.debug( + 'Frame %3d: %s', e._frnum, f.protochain # pylint: disable=protected-access + ) else: self._vfunc = lambda e, f: None else: @@ -757,7 +775,7 @@ def __init__(self, reasm_obj_ipv4 = reasm_obj_ipv6 = reasm_obj_tcp = None if self._ipv4: - logger.info('IPv4 reassembly enabled') + logger.debug('IPv4 reassembly enabled') reasm_cls_ipv4 = self.__reassembly__['ipv4'] if isinstance(reasm_cls_ipv4, ModuleDescriptor): @@ -765,7 +783,7 @@ def __init__(self, self.__reassembly__['ipv4'] = reasm_cls_ipv4 # update mapping upon import reasm_obj_ipv4 = cast('IPv4_Reassembly', reasm_cls_ipv4(strict=reasm_strict, store=reasm_store)) if self._ipv6: - logger.info('IPv6 reassembly enabled') + logger.debug('IPv6 reassembly enabled') reasm_cls_ipv6 = self.__reassembly__['ipv6'] if isinstance(reasm_cls_ipv6, ModuleDescriptor): @@ -773,7 +791,7 @@ def __init__(self, self.__reassembly__['ipv6'] = reasm_cls_ipv6 # update mapping upon import reasm_obj_ipv6 = cast('IPv6_Reassembly', reasm_cls_ipv6(strict=reasm_strict, store=reasm_store)) if self._tcp: - logger.info('TCP reassembly enabled') + logger.debug('TCP reassembly enabled') reasm_cls_tcp = self.__reassembly__['tcp'] if isinstance(reasm_cls_tcp, ModuleDescriptor): @@ -796,7 +814,7 @@ def __init__(self, trace_format = None if self._tcp: - logger.info('TCP flow tracing enabled') + logger.debug('TCP flow tracing enabled') trace_cls_tcp = self.__traceflow__['tcp'] if isinstance(trace_cls_tcp, ModuleDescriptor): @@ -810,11 +828,14 @@ def __init__(self, ) if self._flag_s: + logger.debug('opening input file %s', ifnm) self._ifile = open(ifnm, 'rb') # input file # pylint: disable=unspecified-encoding,consider-using-with else: + logger.debug('reading from the pre-opened stream %r', fin) self._ifile = cast('BufferedReader', fin) if not self._ifile.seekable(): + logger.debug('input stream is not seekable, wrapping it in SeekableReader') self._ifile = SeekableReader(self._ifile, buffer_size, buffer_save, buffer_path, stream_closing=not self._flag_s) @@ -828,7 +849,10 @@ def __init__(self, self.__output__[fmt] = (output, ext) # update mapping upon import dumper = make_dumper(output) + logger.debug('dumping %s output to %s via %s', fmt, ofnm, dumper.__name__) self._ofile = dumper if self._flag_f else dumper(ofnm) # output file + else: + logger.debug('file output disabled') # NOTE: we use peek() to read the magic number, as the file pointer # will not be moved after reading; however, the returned bytes object @@ -906,6 +930,7 @@ def __enter__(self) -> 'Extractor': def __exit__(self, exc_type: 'Type[BaseException] | None', exc_value: 'BaseException | None', traceback: 'TracebackType | None') -> 'None': # pylint: disable=unused-argument """Close the input file when exits.""" + logger.debug('closing %s on context exit after %d frame(s)', self._ifnm, self._frnum) self._ifile.close() self._exeng.close() @@ -922,6 +947,7 @@ def _cleanup(self) -> 'None': """ # pylint: disable=attribute-defined-outside-init + logger.debug('cleaning up after %d frame(s) from %s', self._frnum, self._ifnm) self._flag_e = True if isinstance(self._ifile, SeekableReader): self._ifile.close() diff --git a/pcapkit/foundation/reassembly/reassembly.py b/pcapkit/foundation/reassembly/reassembly.py index 9549885e41..92bad08a53 100644 --- a/pcapkit/foundation/reassembly/reassembly.py +++ b/pcapkit/foundation/reassembly/reassembly.py @@ -17,6 +17,7 @@ from pcapkit.protocols import __proto__ as protocol_registry from pcapkit.protocols.misc.raw import Raw from pcapkit.utilities.exceptions import UnsupportedCall +from pcapkit.utilities.logging import get_logger if TYPE_CHECKING: from typing import Any, Callable, Optional, Type @@ -30,6 +31,10 @@ __all__ = ['Reassembly'] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + # packet _PT = TypeVar('_PT', bound='Info') # datagram @@ -217,6 +222,8 @@ def fetch(self) -> 'tuple[_DT, ...]': if (cached := self.__cached__.get('fetch')) is not None: return cached + logger.debug('%s: flushing %d outstanding buffer(s)', self.name, len(self._buffer)) + temp_dtgram = [] # type: list[_DT] for (bufid, buffer) in self._buffer.items(): temp_dtgram.extend( @@ -225,6 +232,8 @@ def fetch(self) -> 'tuple[_DT, ...]': temp_dtgram.extend(self._dtgram) ret = tuple(temp_dtgram) + logger.debug('%s: fetched %d datagram(s)', self.name, len(ret)) + self.__cached__['fetch'] = ret return ret @@ -253,6 +262,7 @@ def run(self, packets: 'list[_PT]') -> 'None': packets: list of packet dicts to be reassembled """ + logger.debug('%s: reassembling %d packet(s)', self.name, len(packets)) for packet in packets: self.reassembly(packet) @@ -320,6 +330,9 @@ def __init__(self, *, strict: 'bool' = True, store: 'bool' = True) -> 'None': #: to store reassembled datagrams. self._dtgram = [] # type: list[_DT] + logger.debug('%s reassembly initialised (strict=%s, store=%s)', + self.name, strict, store) + def __call__(self, packet: '_PT') -> 'None': """Call packet reassembly. diff --git a/pcapkit/foundation/registry/foundation.py b/pcapkit/foundation/registry/foundation.py index 0c3755adde..2de4fd9db7 100644 --- a/pcapkit/foundation/registry/foundation.py +++ b/pcapkit/foundation/registry/foundation.py @@ -16,7 +16,7 @@ from pcapkit.foundation.reassembly.tcp import TCP as TCP_Reassembly from pcapkit.foundation.traceflow import TraceFlow from pcapkit.foundation.traceflow.tcp import TCP as TCP_TraceFlow -from pcapkit.utilities.logging import logger +from pcapkit.utilities.logging import get_logger if TYPE_CHECKING: from typing import Type @@ -41,6 +41,10 @@ 'register_extractor_reassembly', 'register_extractor_traceflow', ] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + NULL = '(null)' ############################################################################### @@ -77,7 +81,7 @@ def register_extractor_engine(name: 'str', module: 'ModuleDescriptor[Engine] | T module = cast('ModuleDescriptor[Engine]', ModuleDescriptor(module, class_)) Extractor.register_engine(name, module) - logger.info('registered extractor engine: %s', name) + logger.debug('registered extractor engine: %s', name) ############################################################################### @@ -120,7 +124,7 @@ def register_dumper(format: 'str', module: 'ModuleDescriptor[Dumper] | Type[Dump Extractor.register_dumper(format, module, ext) TraceFlow.register_dumper(format, module, ext) - logger.info('registered output format: %s', format) + logger.debug('registered output format: %s', format) @overload @@ -153,7 +157,7 @@ def register_extractor_dumper(format: 'str', module: 'ModuleDescriptor[Dumper] | module = cast('ModuleDescriptor[Dumper]', ModuleDescriptor(module, class_)) Extractor.register_dumper(format, module, ext) - logger.info('registered extractor output dumper: %s', format) + logger.debug('registered extractor output dumper: %s', format) @overload @@ -186,7 +190,7 @@ def register_traceflow_dumper(format: 'str', module: 'ModuleDescriptor[Dumper] | module = cast('ModuleDescriptor[Dumper]', ModuleDescriptor(module, class_)) TraceFlow.register_dumper(format, module, ext) - logger.info('registered traceflow output: %s', format) + logger.debug('registered traceflow output: %s', format) ############################################################################### @@ -207,7 +211,7 @@ def register_reassembly_ipv4_callback(callback: 'Reasm_CallbackFn') -> 'None': """ IPv4_Reassembly.register(callback) - logger.info('registered IPv4 reassembly callback: %r', callback) + logger.debug('registered IPv4 reassembly callback: %r', callback) # NOTE: pcapkit.foundation.reassembly.ipv6.IPv6.__callback_fn__ @@ -223,7 +227,7 @@ def register_reassembly_ipv6_callback(callback: 'Reasm_CallbackFn') -> 'None': """ IPv6_Reassembly.register(callback) - logger.info('registered IPv6 reassembly callback: %r', callback) + logger.debug('registered IPv6 reassembly callback: %r', callback) # NOTE: pcapkit.foundation.reassembly.tcp.TCP.__callback_fn__ @@ -239,7 +243,7 @@ def register_reassembly_tcp_callback(callback: 'Reasm_CallbackFn') -> 'None': """ TCP_Reassembly.register(callback) - logger.info('registered TCP reassembly callback: %r', callback) + logger.debug('registered TCP reassembly callback: %r', callback) # NOTE: pcapkit.foundation.traceflow.tcp.TCP.__callback_fn__ @@ -255,7 +259,7 @@ def register_traceflow_tcp_callback(callback: 'Trace_CallbackFn') -> 'None': """ TCP_TraceFlow.register_callback(callback) - logger.info('registered TCP flow tracing callback: %r', callback) + logger.debug('registered TCP flow tracing callback: %r', callback) ############################################################################### @@ -292,7 +296,7 @@ def register_extractor_reassembly(protocol: 'str', module: 'str | ModuleDescript module = cast('ModuleDescriptor[Reassembly]', ModuleDescriptor(module, class_)) Extractor.register_reassembly(protocol, module) - logger.info('registered extractor reassembly: %s', protocol) + logger.debug('registered extractor reassembly: %s', protocol) @overload @@ -324,4 +328,4 @@ def register_extractor_traceflow(protocol: 'str', module: 'str | ModuleDescripto module = cast('ModuleDescriptor[TraceFlow]', ModuleDescriptor(module, class_)) Extractor.register_traceflow(protocol, module) - logger.info('registered extractor flow tracing: %s', protocol) + logger.debug('registered extractor flow tracing: %s', protocol) diff --git a/pcapkit/foundation/registry/protocols.py b/pcapkit/foundation/registry/protocols.py index 691d8b5917..1fa60d790e 100644 --- a/pcapkit/foundation/registry/protocols.py +++ b/pcapkit/foundation/registry/protocols.py @@ -46,7 +46,7 @@ from pcapkit.protocols.transport.tcp import TCP from pcapkit.protocols.transport.udp import UDP from pcapkit.utilities.exceptions import RegistryError -from pcapkit.utilities.logging import logger +from pcapkit.utilities.logging import get_logger if TYPE_CHECKING: from typing import Optional, Type @@ -125,6 +125,10 @@ 'register_pcapng_record', ] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + NULL = '(null)' @@ -144,7 +148,7 @@ def register_protocol(protocol: 'Type[Protocol]') -> 'None': raise RegistryError(f'protocol must be a Protocol subclass, not {protocol!r}') protocol_registry[protocol.__name__.upper()] = protocol - logger.info('registered protocol: %s', protocol.__name__) + logger.debug('registered protocol: %s', protocol.__name__) ############################################################################### @@ -188,7 +192,7 @@ def register_linktype(code: 'LinkType', module: 'str | ModuleDescriptor[Protocol Frame.register(code, module) PCAPNG.register(code, module) - logger.info('registered linktype protocol: %s', code.name) + logger.debug('registered linktype protocol: %s', code.name) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): @@ -225,7 +229,7 @@ def register_pcap(code: 'LinkType', module: 'str | ModuleDescriptor[Protocol] | module = cast('ModuleDescriptor[Protocol]', ModuleDescriptor(module, class_)) Frame.register(code, module) - logger.info('registered PCAP linktype protocol: %s', code.name) + logger.debug('registered PCAP linktype protocol: %s', code.name) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): @@ -262,7 +266,7 @@ def register_pcapng(code: 'LinkType', module: 'str | ModuleDescriptor[Protocol] module = cast('ModuleDescriptor[Protocol]', ModuleDescriptor(module, class_)) PCAPNG.register(code, module) - logger.info('registered PCAP-NG linktype protocol: %s', code.name) + logger.debug('registered PCAP-NG linktype protocol: %s', code.name) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): @@ -304,7 +308,7 @@ def register_ethertype(code: 'EtherType', module: 'str | ModuleDescriptor[Protoc module = cast('ModuleDescriptor[Protocol]', ModuleDescriptor(module, class_)) Link.register(code, module) - logger.info('registered ethertype protocol: %s', code.name) + logger.debug('registered ethertype protocol: %s', code.name) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): @@ -346,7 +350,7 @@ def register_transtype(code: 'TransType', module: 'str | ModuleDescriptor[Protoc module = cast('ModuleDescriptor[Protocol]', ModuleDescriptor(module, class_)) Internet.register(code, module) - logger.info('registered transtype protocol: %s', code.name) + logger.debug('registered transtype protocol: %s', code.name) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): @@ -376,7 +380,7 @@ def register_ipv4_option(code: 'IPv4_OptionNumber', meth: 'str | tuple[IPv4_Opti IPv4.register_option(code, meth) if schema is not None: Schema_IPv4_Option.register(code, schema) - logger.info('registered IPv4 option parser: %s', code.name) + logger.debug('registered IPv4 option parser: %s', code.name) # NOTE: pcapkit.protocols.internet.hip.HIP @@ -401,7 +405,7 @@ def register_hip_parameter(code: 'HIP_Parameter', meth: 'str | tuple[HIP_Paramet HIP.register_parameter(code, meth) if schema is not None: Schema_HIP_Parameter.register(code, schema) - logger.info('registered HIP parameter parser: %s', code.name) + logger.debug('registered HIP parameter parser: %s', code.name) # NOTE: pcapkit.protocols.internet.hopopt.HOPOPT.__option__ @@ -426,7 +430,7 @@ def register_hopopt_option(code: 'IPv6_Option', meth: 'str | tuple[HOPOPT_Option HOPOPT.register_option(code, meth) if schema is not None: Schema_HOPOPT_Option.register(code, schema) - logger.info('registered HOPOPT option parser: %s', code.name) + logger.debug('registered HOPOPT option parser: %s', code.name) # NOTE: pcapkit.protocols.internet.ipv6_opts.IPv6_Opts.__option__ @@ -451,7 +455,7 @@ def register_ipv6_opts_option(code: 'IPv6_Option', meth: 'str | tuple[IPv6_Opts_ IPv6_Opts.register_option(code, meth) if schema is not None: Schema_IPv6_Opts_Option.register(code, schema) - logger.info('registered IPv6-Opts option parser: %s', code.name) + logger.debug('registered IPv6-Opts option parser: %s', code.name) # NOTE: pcapkit.protocols.internet.ipv6_route.IPv6_Route.__routing__ @@ -476,7 +480,7 @@ def register_ipv6_route_routing(code: 'IPv6_Routing', meth: 'str | tuple[IPv6_Ro IPv6_Route.register_routing(code, meth) if schema is not None: Schema_IPv6_Route_RoutingType.register(code, schema) - logger.info('registered IPv6-Route routing data parser: %s', code.name) + logger.debug('registered IPv6-Route routing data parser: %s', code.name) # NOTE: pcapkit.protocols.internet.mh.MH.__message__ @@ -501,7 +505,7 @@ def register_mh_message(code: 'MH_Packet', meth: 'str | tuple[MH_PacketParser, M MH.register_message(code, meth) if schema is not None: Schema_MH_Packet.register(code, schema) - logger.info('registered MH message type parser: %s', code.name) + logger.debug('registered MH message type parser: %s', code.name) # NOTE: pcapkit.protocols.internet.mh.MH.__option__ @@ -526,7 +530,7 @@ def register_mh_option(code: 'MH_Option', meth: 'str | tuple[MH_OptionParser, MH MH.register_option(code, meth) if schema is not None: Schema_MH_Option.register(code, schema) - logger.info('registered MH option parser: %s', code.name) + logger.debug('registered MH option parser: %s', code.name) # NOTE: pcapkit.protocols.internet.mh.MH.__extension__ @@ -551,7 +555,7 @@ def register_mh_extension(code: 'MH_CGAExtension', meth: 'str | tuple[MH_Extensi MH.register_extension(code, meth) if schema is not None: Schema_MH_CGAExtension.register(code, schema) - logger.info('registered MH CGA extension: %s', code.name) + logger.debug('registered MH CGA extension: %s', code.name) ############################################################################### @@ -623,7 +627,7 @@ def register_apptype(code: 'int | Enum_AppType', module: 'str | ModuleDescriptor continue cls.register(code, module) - logger.info('registered %s port: %s', test.name, code) + logger.debug('registered %s port: %s', test.name, code) _reg = True if not _reg: @@ -666,7 +670,7 @@ def register_tcp(code: 'int | Enum_AppType', module: 'str | ModuleDescriptor[Pro module = cast('ModuleDescriptor[Protocol]', ModuleDescriptor(module, class_)) TCP.register(code, module) - logger.info('registered TCP port: %s', code) + logger.debug('registered TCP port: %s', code) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): @@ -696,7 +700,7 @@ def register_tcp_option(code: 'TCP_Option', meth: 'str | tuple[TCP_OptionParser, TCP.register_option(code, meth) if schema is not None: Schema_TCP_Option.register(code, schema) - logger.info('registered TCP option parser: %s', code.name) + logger.debug('registered TCP option parser: %s', code.name) # NOTE: pcapkit.protocols.transport.tcp.TCP.__mp_option__ @@ -721,7 +725,7 @@ def register_tcp_mp_option(code: 'TCP_MPTCPOption', meth: 'str | tuple[TCP_MPOpt TCP.register_mp_option(code, meth) if schema is not None: Schema_TCP_MPTCP.register(code, schema) - logger.info('registered MPTCP option parser: %s', code.name) + logger.debug('registered MPTCP option parser: %s', code.name) @overload @@ -755,7 +759,7 @@ def register_udp(code: 'int | Enum_AppType', module: 'str | ModuleDescriptor[Pro module = cast('ModuleDescriptor[Protocol]', ModuleDescriptor(module, class_)) UDP.register(code, module) - logger.info('registered UDP port: %s', code) + logger.debug('registered UDP port: %s', code) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): @@ -834,7 +838,7 @@ def register_http_frame(code: 'HTTP_Frame', meth: 'str | tuple[HTTP_FrameParser, HTTPv2.register_frame(code, meth) if schema is not None: Schema_HTTP_FrameType.register(code, schema) - logger.info('registered HTTP/2 frame parser: %s', code.name) + logger.debug('registered HTTP/2 frame parser: %s', code.name) ############################################################################### @@ -864,7 +868,7 @@ def register_pcapng_block(code: 'PCAPNG_BlockType', meth: 'str | tuple[PCAPNG_Bl PCAPNG.register_block(code, meth) if schema is not None: Schema_PCAPNG_BlockType.register(code, schema) - logger.info('registered PCAP-NG block parser: %s', code.name) + logger.debug('registered PCAP-NG block parser: %s', code.name) # NOTE: pcapkit.protocols.misc.pcapng.PCAPNG.__option__ @@ -889,7 +893,7 @@ def register_pcapng_option(code: 'PCAPNG_OptionType', meth: 'str | tuple[PCAPNG_ PCAPNG.register_option(code, meth) if schema is not None: Schema_PCAPNG_Option.register(code, schema) - logger.info('registered PCAP-NG option parser: %s', code.name) + logger.debug('registered PCAP-NG option parser: %s', code.name) # NOTE: pcapkit.protocols.misc.pcapng.PCAPNG.__record__ @@ -915,7 +919,7 @@ def register_pcapng_record(code: 'PCAPNG_RecordType', meth: 'str | tuple[PCAPNG_ PCAPNG.register_record(code, meth) if schema is not None: Schema_PCAPNG_NameResolutionRecord.register(code, schema) - logger.info('registered PCAP-NG name resolution record parser: %s', code.name) + logger.debug('registered PCAP-NG name resolution record parser: %s', code.name) # NOTE: pcapkit.protocols.misc.pcapng.PCAPNG.__secrets__ @@ -940,4 +944,4 @@ def register_pcapng_secrets(code: 'PCAPNG_SecretsType', meth: 'str | tuple[PCAPN PCAPNG.register_secrets(code, meth) if schema is not None: Schema_PCAPNG_DSBSecrets.register(code, schema) - logger.info('registered PCAP-NG decryption secrets parser: %s', code.name) + logger.debug('registered PCAP-NG decryption secrets parser: %s', code.name) diff --git a/pcapkit/foundation/traceflow/tcp.py b/pcapkit/foundation/traceflow/tcp.py index fdcab34b7c..75a96cde2d 100644 --- a/pcapkit/foundation/traceflow/tcp.py +++ b/pcapkit/foundation/traceflow/tcp.py @@ -14,6 +14,7 @@ from pcapkit.foundation.traceflow.data.tcp import _AT, Buffer, BufferID, Index, Packet from pcapkit.foundation.traceflow.traceflow import TraceFlowBase as TraceFlow from pcapkit.protocols.transport.tcp import TCP as TCP_Protocol +from pcapkit.utilities.logging import get_logger __all__ = ['TCP'] @@ -21,6 +22,10 @@ from dictdumper.dumper import Dumper from typing_extensions import Literal +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + class TCP(TraceFlow[BufferID, Buffer, Index, Packet[_AT]], Generic[_AT]): """Trace TCP flows. @@ -108,6 +113,7 @@ def trace(self, packet: 'Packet[_AT]', *, output: 'bool' = False) -> 'Dumper | s label = f'{packet.src}_{packet.srcport}-{packet.dst}_{packet.dstport}-{packet.timestamp}' else: label = f'{packet.src}_{packet.srcport}-{packet.dst}_{packet.dstport}-{packet.timestamp}'.replace(':', '.') + logger.debug('new TCP flow %s', label) self._buffer[BUFID] = Buffer( fpout=self._foutio(fname=f'{self._fproot}/{label}{self._fdpext or ""}', protocol=packet.protocol, byteorder=self._endian, nanosecond=self._nnsecd), @@ -125,6 +131,7 @@ def trace(self, packet: 'Packet[_AT]', *, output: 'bool' = False) -> 'Dumper | s buf = self._buffer.pop(BUFID) # fpout, label = buf['fpout'], buf['label'] + logger.debug('TCP flow %s closed after %d frame(s)', label, len(buf.index)) index = Index( fpout=f'{self._fproot}/{label}{self._fdpext}' if self._fdpext is not None else None, index=tuple(buf.index), @@ -155,5 +162,8 @@ def submit(self) -> 'tuple[Index, ...]': ret.extend(self._stream) ret_submit = tuple(ret) + logger.debug('submitted %d TCP flow(s), %d still open', + len(ret_submit), len(self._buffer)) + self.__cached__['submit'] = ret_submit return ret_submit diff --git a/pcapkit/foundation/traceflow/traceflow.py b/pcapkit/foundation/traceflow/traceflow.py index 29dda80491..5106796eb5 100644 --- a/pcapkit/foundation/traceflow/traceflow.py +++ b/pcapkit/foundation/traceflow/traceflow.py @@ -23,10 +23,15 @@ from pcapkit.protocols import __proto__ as protocol_registry from pcapkit.protocols.misc.raw import Raw from pcapkit.utilities.exceptions import FileExists, RegistryError, stacklevel +from pcapkit.utilities.logging import get_logger from pcapkit.utilities.warnings import FileWarning, FormatWarning, RegistryWarning, warn __all__ = ['TraceFlow'] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + if TYPE_CHECKING: from typing import Any, Callable, DefaultDict, Optional, Type @@ -232,7 +237,10 @@ def make_fout(cls, fout: 'str' = './tmp', fmt: 'str' = 'pcap') -> 'tuple[Type[Du warn(error.strerror, FileWarning, stacklevel=stacklevel()) else: raise FileExists(*error.args).with_traceback(error.__traceback__) - return make_dumper(output), ext + + dumper = make_dumper(output) + logger.debug('flow tracing output root %s, format %s via %s', fout, fmt, dumper.__name__) + return dumper, ext @abc.abstractmethod def dump(self, packet: '_PT') -> 'None': @@ -323,6 +331,9 @@ def __init__(self, fout: 'Optional[str]', format: 'Optional[str]', # pylint: di #: Optional[str]: Output file extension. self._fdpext = ext + logger.debug('%s flow tracing initialised (root=%s, format=%s, byteorder=%s, ' + 'nanosecond=%s)', self.name, fout, format, byteorder, nanosecond) + def __call__(self, packet: '_PT') -> 'None': """Dump frame to output files. diff --git a/pcapkit/protocols/transport/transport.py b/pcapkit/protocols/transport/transport.py index 9faca552e3..ec0629a9a2 100644 --- a/pcapkit/protocols/transport/transport.py +++ b/pcapkit/protocols/transport/transport.py @@ -19,7 +19,7 @@ from pcapkit.protocols.protocol import _PT, _ST from pcapkit.protocols.protocol import ProtocolBase as Protocol from pcapkit.utilities.exceptions import StructError, UnsupportedCall, stacklevel -from pcapkit.utilities.logging import DEVMODE, logger +from pcapkit.utilities.logging import DEVMODE, get_logger from pcapkit.utilities.warnings import RegistryWarning, warn if TYPE_CHECKING: @@ -30,6 +30,11 @@ __all__ = ['Transport'] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + + class Transport(Protocol[_PT, _ST], Generic[_PT, _ST]): # pylint: disable=abstract-method """Abstract base class for transport layer protocol family.""" diff --git a/pcapkit/utilities/__init__.py b/pcapkit/utilities/__init__.py index 9cdd996a03..2086907841 100644 --- a/pcapkit/utilities/__init__.py +++ b/pcapkit/utilities/__init__.py @@ -14,7 +14,8 @@ """ from pcapkit.utilities.decorators import beholder, prepare, seekset from pcapkit.utilities.exceptions import stacklevel -from pcapkit.utilities.logging import logger +from pcapkit.utilities.logging import configure, ensure_output, get_logger, logger, reset from pcapkit.utilities.warnings import warn -__all__ = ['logger', 'warn', 'stacklevel'] +__all__ = ['logger', 'get_logger', 'configure', 'reset', 'ensure_output', + 'warn', 'stacklevel'] diff --git a/pcapkit/utilities/decorators.py b/pcapkit/utilities/decorators.py index ddc5e33086..62a6f9d23d 100644 --- a/pcapkit/utilities/decorators.py +++ b/pcapkit/utilities/decorators.py @@ -18,7 +18,7 @@ from typing import TYPE_CHECKING, cast from pcapkit.utilities.exceptions import StructError, stacklevel -from pcapkit.utilities.logging import DEVMODE, VERBOSE, logger +from pcapkit.utilities.logging import DEVMODE, VERBOSE, get_logger if TYPE_CHECKING: from typing import IO, Any, Callable, Optional, Type, TypeVar @@ -36,6 +36,11 @@ __all__ = ['seekset', 'beholder', 'prepare'] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + + def seekset(func: 'Callable[Concatenate[Protocol, P], R_seekset]') -> 'Callable[P, R_seekset]': """Read file from start then set back to original. diff --git a/pcapkit/utilities/exceptions.py b/pcapkit/utilities/exceptions.py index b358f490bc..27dcac5fbe 100644 --- a/pcapkit/utilities/exceptions.py +++ b/pcapkit/utilities/exceptions.py @@ -22,7 +22,7 @@ from typing import TYPE_CHECKING from pcapkit.utilities.compat import ModuleNotFoundError # pylint: disable=redefined-builtin -from pcapkit.utilities.logging import DEVMODE, VERBOSE, logger +from pcapkit.utilities.logging import DEVMODE, VERBOSE, get_logger if TYPE_CHECKING: from typing import Any @@ -52,6 +52,11 @@ ] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + + def stacklevel() -> 'int': """Fetch current stack level. diff --git a/pcapkit/utilities/logging.py b/pcapkit/utilities/logging.py index 867aab72bd..465c526fc7 100644 --- a/pcapkit/utilities/logging.py +++ b/pcapkit/utilities/logging.py @@ -4,16 +4,51 @@ .. module:: pcapkit.utilities.logging -:mod:`pcapkit.utilities.logging` contains naïve integration -of the Python logging system, i.e. a :class:`logging.Logger` -instance as :data:`~pcapkit.utilities.logging.logger`. +:mod:`pcapkit.utilities.logging` integrates :mod:`pcapkit` with the standard +:mod:`logging` system. It owns the package-wide logger hierarchy rooted at +:data:`~pcapkit.utilities.logging.logger` (the logger named ``pcapkit``), and +the :func:`~pcapkit.utilities.logging.configure` and +:func:`~pcapkit.utilities.logging.reset` pair through which an application +decides what, if anything, :mod:`pcapkit` emits. + +:mod:`pcapkit` is a library, so importing it configures **no** logging output: +the only handler attached to :data:`logger` is a :class:`logging.NullHandler`, +and no level is set, which leaves both the destination and the verbosity to the +embedding application. Every module logs through its own child logger, obtained +via :func:`get_logger` with ``__name__``, so that a single subtree may be +silenced or amplified independently:: + + import logging + logging.getLogger('pcapkit.foundation.registry').setLevel(logging.WARNING) + +For applications that do not configure :mod:`logging` themselves, +:func:`configure` attaches a handler of :mod:`pcapkit`'s own:: + + import sys + from pcapkit.utilities.logging import configure + configure('DEBUG', stream=sys.stderr) + +and :func:`reset` puts everything back the way importing :mod:`pcapkit` left it. + +.. seealso:: + + :envvar:`PCAPKIT_DEVMODE` still bootstraps the historical :obj:`sys.stderr` + handler at :data:`logging.DEBUG`, so a development session needs no explicit + :func:`configure` call. """ import logging import os import sys +from typing import TYPE_CHECKING -__all__ = ['logger'] +if TYPE_CHECKING: + from typing import IO, Optional, Union + +__all__ = [ + 'logger', 'get_logger', 'configure', 'reset', 'ensure_output', + 'ROOT_LOGGER_NAME', 'DEFAULT_FORMAT', 'DEFAULT_DATE_FORMAT', +] ############################################################################### # Dev Mode @@ -41,15 +76,262 @@ # Logger Setup ############################################################################### -#: logging.Logger: :class:`~logging.Logger` instance named after ``pcapkit``. -logger = logging.getLogger('pcapkit') +#: str: Name of the logger at the root of :mod:`pcapkit`'s hierarchy. +ROOT_LOGGER_NAME = 'pcapkit' + +#: str: Default :class:`logging.Formatter` format string. +DEFAULT_FORMAT = '[%(levelname)s] %(asctime)s - %(message)s' +#: str: Default :class:`logging.Formatter` date format string. +DEFAULT_DATE_FORMAT = '%m/%d/%Y %I:%M:%S %p' -formatter = logging.Formatter(fmt='[%(levelname)s] %(asctime)s - %(message)s', - datefmt='%m/%d/%Y %I:%M:%S %p') +#: logging.Logger: :class:`~logging.Logger` instance named after ``pcapkit``, +#: at the root of the package's logger hierarchy. Per-module loggers are its +#: children, so configuring this one configures all of :mod:`pcapkit`. +logger = logging.getLogger(ROOT_LOGGER_NAME) + +#: logging.Formatter: Default formatter, used by any handler that +#: :func:`configure` creates and by the :envvar:`PCAPKIT_DEVMODE` bootstrap. +formatter = logging.Formatter(fmt=DEFAULT_FORMAT, datefmt=DEFAULT_DATE_FORMAT) + +#: logging.StreamHandler: The historical :obj:`sys.stderr` handler. It is only +#: *attached* under :envvar:`PCAPKIT_DEVMODE`; it is constructed unconditionally +#: so that ``logger.addHandler(handler)`` remains a one-line way back to the +#: pre-1.4 default output. handler = logging.StreamHandler(sys.stderr) +handler.setFormatter(formatter) + + +def get_logger(name: 'Optional[str]' = None) -> 'logging.Logger': + """Retrieve a logger inside :mod:`pcapkit`'s hierarchy. + + This is the accessor every module in :mod:`pcapkit` uses, as + ``logger = get_logger(__name__)``, so that records carry the emitting + module's name and an application can address one subtree at a time. + + Args: + name: Dotted logger name, normally the caller's :data:`__name__`. + :data:`None` or ``'pcapkit'`` yields the root :data:`logger`. + A name outside the ``pcapkit`` hierarchy -- notably ``'__main__'``, + which is what :data:`__name__` reports for a module run as a + script -- is placed *under* the root rather than beside it, since a + sibling of ``pcapkit`` would escape every :mod:`pcapkit`-level + configuration. + + Returns: + The requested logger. + + """ + if not name or name == ROOT_LOGGER_NAME: + return logger + if name.startswith(f'{ROOT_LOGGER_NAME}.'): + return logging.getLogger(name) + return logger.getChild(name) + + +def _detach(target: 'logging.Logger') -> 'None': + """Remove every handler attached to ``target``. + + Handlers are detached but deliberately never closed: a handler reached here + was either built from a stream the caller still owns, or handed to + :func:`configure` ready-made, and closing someone else's file or socket on + their behalf is not this module's business. Whoever created a handler closes + it. + + Args: + target: Logger to strip. + + """ + for entry in list(target.handlers): + target.removeHandler(entry) + + +def _has_output(target: 'logging.Logger') -> 'bool': + """Whether a record from ``target`` would reach a real handler. + + Walks the ancestry the way :meth:`logging.Logger.callHandlers` does, + stopping where propagation stops, and ignores + :class:`~logging.NullHandler` since its whole purpose is to swallow records. + + Args: + target: Logger to inspect. + + Returns: + :data:`True` if some handler would receive the record. + + """ + current = target # type: Optional[logging.Logger] + while current is not None: + for entry in current.handlers: + if not isinstance(entry, logging.NullHandler): + return True + if not current.propagate: + break + current = current.parent + return False + + +def ensure_output(level: 'Union[int, str]' = logging.DEBUG, *, + stream: 'Optional[IO[str]]' = None) -> 'bool': + """Guarantee that :mod:`pcapkit`'s records have somewhere to go. + + This exists for the features a caller switches on precisely *because* they + want to see the output -- ``Extractor(verbose=True)`` above all -- where + staying silent because the application never configured :mod:`logging` would + be a bug rather than good library manners. + + An application that has configured its own handlers has already answered the + question, so nothing is changed in that case. + + Args: + level: Level to configure if, and only if, a handler has to be added. + stream: Where to write, defaulting to :obj:`sys.stderr`. + + Returns: + :data:`True` if a handler was added, :data:`False` if output was already + going somewhere and the existing configuration was left alone. + + """ + if _has_output(logger): + return False + configure(level, stream=stream or sys.stderr, replace=False) + return True + + +def reset(name: 'Optional[str]' = None) -> 'logging.Logger': + """Restore a :mod:`pcapkit` logger to its pristine, library-neutral state. + + That is: no handlers other than the :class:`logging.NullHandler` on the + root, no level of its own (:data:`logging.NOTSET`, so the level is inherited + from the application's configuration), and propagation enabled. + + Args: + name: Logger to reset, as accepted by :func:`get_logger`. Defaults to + the root :data:`logger`, which also resets nothing else -- children + keep any level explicitly set on them. + + Returns: + The logger that was reset. + + Note: + This discards the :envvar:`PCAPKIT_DEVMODE` bootstrap along with + everything else. To reinstate it, call + ``configure(logging.DEBUG, stream=sys.stderr)``. + + """ + target = get_logger(name) + + _detach(target) + target.setLevel(logging.NOTSET) + target.propagate = True + + if target is logger: + # the null handler is what keeps a library quiet rather than noisy: + # without it, ``logging`` prints its own "no handlers could be found" + # complaint the first time an unconfigured application triggers a record + target.addHandler(logging.NullHandler()) + return target + + +def configure(level: 'Optional[Union[int, str]]' = None, *, + name: 'Optional[str]' = None, + stream: 'Optional[IO[str]]' = None, + handler: 'Optional[logging.Handler]' = None, # pylint: disable=redefined-outer-name + fmt: 'Optional[str]' = None, + datefmt: 'Optional[str]' = None, + propagate: 'Optional[bool]' = None, + replace: 'bool' = True) -> 'logging.Logger': + """Configure :mod:`pcapkit`'s logging at runtime. + + Every argument is optional and only the ones supplied take effect, so this + is usable both as a one-shot setup call and as a targeted adjustment. + + Args: + level: Level for the logger, as either a :obj:`str` name (``'DEBUG'``) + or an :obj:`int` (:data:`logging.DEBUG`). Left untouched when + :data:`None`, which for a freshly imported :mod:`pcapkit` means the + level is inherited from the application. + name: Logger to configure, as accepted by :func:`get_logger`. Defaults + to the root :data:`logger`; pass e.g. + ``'pcapkit.foundation.registry'`` to configure one subtree. + stream: Writable text stream to log to, e.g. :obj:`sys.stderr`. A + :class:`logging.StreamHandler` is created for it and given a + :class:`logging.Formatter` built from ``fmt`` and ``datefmt``. + handler: An already-built handler to attach instead, for anything a + plain stream cannot express -- a + :class:`~logging.handlers.RotatingFileHandler`, a queue handler, a + test double. Mutually exclusive with ``stream``. Its formatter is + only replaced if ``fmt`` or ``datefmt`` is given. + fmt: Format string for the handler this call creates. Defaults to + :data:`DEFAULT_FORMAT`. + datefmt: Date format string for the handler this call creates. Defaults + to :data:`DEFAULT_DATE_FORMAT`. + propagate: Whether records should reach ancestor loggers. Setting this + to :data:`False` on the root :data:`logger` keeps :mod:`pcapkit`'s + records out of the application's own handlers. + replace: Whether to detach the logger's existing handlers first, so that + repeated calls replace rather than accumulate output. Pass + :data:`False` to add a second destination. Unlike :func:`reset`, + this only touches handlers -- the level and propagation are left + alone unless the corresponding arguments are given. + + Returns: + The logger that was configured, for chaining or inspection. + + Raises: + ValueError: If both ``stream`` and ``handler`` are given, since which + one is meant to receive ``fmt`` would be ambiguous. + + Example: + Restore the pre-1.4 default of :obj:`sys.stderr` at + :data:`logging.INFO`:: + + configure(logging.INFO, stream=sys.stderr) + + Send everything to a file, but keep the registry's bookkeeping out:: + + configure(logging.DEBUG, handler=logging.FileHandler('pcapkit.log')) + configure(logging.INFO, name='pcapkit.foundation.registry') + + """ + if stream is not None and handler is not None: + raise ValueError("configure() accepts 'stream' or 'handler', not both") + + target = get_logger(name) + + if replace: + _detach(target) + if target is logger: + target.addHandler(logging.NullHandler()) + + if stream is None and handler is None and (fmt is not None or datefmt is not None): + # a format was asked for, so output was clearly intended; honouring it + # beats silently discarding the only argument the caller passed + stream = sys.stderr + + if stream is not None: + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter(fmt=fmt or DEFAULT_FORMAT, + datefmt=datefmt or DEFAULT_DATE_FORMAT)) + elif handler is not None and (fmt is not None or datefmt is not None): + handler.setFormatter(logging.Formatter(fmt=fmt or DEFAULT_FORMAT, + datefmt=datefmt or DEFAULT_DATE_FORMAT)) + + if handler is not None: + target.addHandler(handler) + if level is not None: + target.setLevel(level) + if propagate is not None: + target.propagate = propagate + return target + + +# Re-running this module (which the test suite does, to exercise import-time +# behaviour) must not stack a second handler onto the process-wide ``pcapkit`` +# logger, so start from a known-clean state rather than adding to whatever is +# already there. +reset() + if DEVMODE: + # development mode keeps the historical behaviour: everything, on stderr logger.setLevel(logging.DEBUG) -else: - logger.setLevel(logging.INFO) -handler.setFormatter(formatter) -logger.addHandler(handler) + logger.addHandler(handler) diff --git a/pcapkit/utilities/warnings.py b/pcapkit/utilities/warnings.py index 34bf18739b..e713e14bab 100644 --- a/pcapkit/utilities/warnings.py +++ b/pcapkit/utilities/warnings.py @@ -11,7 +11,7 @@ from typing import TYPE_CHECKING from pcapkit.utilities.exceptions import stacklevel as stacklevel_calculator -from pcapkit.utilities.logging import DEVMODE, VERBOSE, logger +from pcapkit.utilities.logging import DEVMODE, VERBOSE, get_logger if TYPE_CHECKING: from typing import Any, Optional, Type, Union @@ -36,6 +36,11 @@ ] +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + + def warn(message: 'Union[str, Warning]', category: 'Type[Warning]', stacklevel: 'Optional[int]' = None) -> 'None': """Wrapper function of :func:`warnings.warn`. diff --git a/pcapkit/vendor/__main__.py b/pcapkit/vendor/__main__.py index 0bf045bcd6..b7c5645d5d 100644 --- a/pcapkit/vendor/__main__.py +++ b/pcapkit/vendor/__main__.py @@ -18,7 +18,7 @@ from pcapkit import __version__ from pcapkit import vendor as vendor_module -from pcapkit.utilities.logging import VERBOSE, logger +from pcapkit.utilities.logging import VERBOSE, get_logger from pcapkit.utilities.warnings import InvalidVendorWarning, VendorRuntimeWarning, warn if TYPE_CHECKING: @@ -28,6 +28,11 @@ from pcapkit.vendor.default import Vendor +#: logging.Logger: Module-level logger, a child of the package-wide +#: :data:`pcapkit.utilities.logging.logger`. +logger = get_logger(__name__) + + def get_parser() -> 'ArgumentParser': """CLI argument parser.""" parser = argparse.ArgumentParser(prog='pcapkit-vendor', diff --git a/tests/utilities/test_logging.py b/tests/utilities/test_logging.py index 2e81eb5ae2..88ac5099b0 100644 --- a/tests/utilities/test_logging.py +++ b/tests/utilities/test_logging.py @@ -1,12 +1,38 @@ from __future__ import annotations +import importlib.util +import io +import logging import os import unittest from tests._support import load_module, purge_modules +RUNTIME_DEPS = ('tbtrim', 'aenum', 'chardet', 'dictdumper') +HAS_RUNTIME = all(importlib.util.find_spec(name) is not None for name in RUNTIME_DEPS) + +#: Name of the logger at the root of the package hierarchy. +ROOT = 'pcapkit' + + +def pristine() -> None: + """Return the process-wide ``pcapkit`` logger to its library-neutral state. + + The :mod:`logging` registry is global and outlives any module purge, so a + test that attaches a handler would otherwise leak it into every later test + in the run. + """ + root = logging.getLogger(ROOT) + for handler in list(root.handlers): + root.removeHandler(handler) + root.setLevel(logging.NOTSET) + root.propagate = True + root.addHandler(logging.NullHandler()) + + +class LoggingEnvironmentTests(unittest.TestCase): + """The environment-variable flags, which are read at import time.""" -class LoggingTests(unittest.TestCase): def setUp(self) -> None: purge_modules(['pcapkit']) self._saved = {key: os.environ.get(key) for key in ('PCAPKIT_DEVMODE', 'PCAPKIT_VERBOSE', 'PCAPKIT_SPHINX')} @@ -18,6 +44,7 @@ def tearDown(self) -> None: else: os.environ[key] = value purge_modules(['pcapkit']) + pristine() def test_boolean_environment_flags_are_parsed(self) -> None: os.environ['PCAPKIT_DEVMODE'] = 'yes' @@ -48,6 +75,372 @@ def test_utilities_package_re_exports_common_helpers(self) -> None: self.assertTrue(callable(package.warn)) self.assertTrue(callable(package.stacklevel)) + def test_utilities_package_re_exports_the_configuration_api(self) -> None: + package = load_module('pcapkit.utilities', 'pcapkit/utilities/__init__.py') + + for name in ('configure', 'reset', 'get_logger', 'ensure_output'): + with self.subTest(name=name): + self.assertIn(name, package.__all__) + self.assertTrue(callable(getattr(package, name))) + + +class LoggingImportTimeTests(unittest.TestCase): + """Importing a library must not configure the application's logging.""" + + def setUp(self) -> None: + purge_modules(['pcapkit']) + self._saved = os.environ.get('PCAPKIT_DEVMODE') + os.environ.pop('PCAPKIT_DEVMODE', None) + pristine() + + def tearDown(self) -> None: + if self._saved is None: + os.environ.pop('PCAPKIT_DEVMODE', None) + else: + os.environ['PCAPKIT_DEVMODE'] = self._saved + purge_modules(['pcapkit']) + pristine() + + def test_fresh_import_attaches_only_a_null_handler(self) -> None: + load_module('pcapkit.utilities.logging', 'pcapkit/utilities/logging.py') + root = logging.getLogger(ROOT) + + self.assertEqual(len(root.handlers), 1) + self.assertIsInstance(root.handlers[0], logging.NullHandler) + + def test_fresh_import_sets_no_level_and_leaves_propagation_on(self) -> None: + load_module('pcapkit.utilities.logging', 'pcapkit/utilities/logging.py') + root = logging.getLogger(ROOT) + + # NOTSET means the level is inherited from the application's own + # configuration rather than dictated by the library + self.assertEqual(root.level, logging.NOTSET) + self.assertTrue(root.propagate) + + def test_fresh_import_does_not_write_to_stderr(self) -> None: + logging_module = load_module('pcapkit.utilities.logging', 'pcapkit/utilities/logging.py') + + # the module keeps a stderr handler around for the devmode bootstrap and + # as a one-line restore path, but must not have attached it + self.assertNotIn(logging_module.handler, logging.getLogger(ROOT).handlers) + + def test_devmode_bootstraps_the_historical_stderr_handler(self) -> None: + os.environ['PCAPKIT_DEVMODE'] = '1' + + logging_module = load_module('pcapkit.utilities.logging', 'pcapkit/utilities/logging.py') + root = logging.getLogger(ROOT) + + self.assertTrue(logging_module.DEVMODE) + self.assertEqual(root.level, logging.DEBUG) + self.assertIn(logging_module.handler, root.handlers) + + def test_re_executing_the_module_does_not_stack_handlers(self) -> None: + for _ in range(3): + load_module('pcapkit.utilities.logging', 'pcapkit/utilities/logging.py') + + self.assertEqual(len(logging.getLogger(ROOT).handlers), 1) + + +class LoggerHierarchyTests(unittest.TestCase): + """Per-module loggers, so a consumer can address one subtree at a time.""" + + def setUp(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def tearDown(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def test_get_logger_maps_module_names_onto_the_hierarchy(self) -> None: + from pcapkit.utilities.logging import get_logger, logger + + self.assertIs(get_logger(None), logger) + self.assertIs(get_logger(ROOT), logger) + self.assertEqual(get_logger('pcapkit.foundation.extraction').name, + 'pcapkit.foundation.extraction') + + def test_get_logger_keeps_foreign_names_inside_the_hierarchy(self) -> None: + from pcapkit.utilities.logging import get_logger + + # ``python -m pcapkit.vendor`` reports ``__name__ == '__main__'``; a + # logger by that bare name would be a sibling of ``pcapkit`` and so + # unreachable from any pcapkit-level configuration + self.assertEqual(get_logger('__main__').name, 'pcapkit.__main__') + self.assertEqual(get_logger('somewhere.else').name, 'pcapkit.somewhere.else') + + def test_public_root_logger_is_still_importable_and_named_pcapkit(self) -> None: + from pcapkit.utilities.logging import logger + + self.assertIs(logger, logging.getLogger(ROOT)) + self.assertEqual(logger.name, ROOT) + + @unittest.skipUnless(HAS_RUNTIME, 'runtime dependencies not installed') + def test_modules_log_through_their_own_child_logger(self) -> None: + cases = { + 'pcapkit.foundation.extraction': 'pcapkit.foundation.extraction', + 'pcapkit.foundation.registry.protocols': 'pcapkit.foundation.registry.protocols', + 'pcapkit.foundation.registry.foundation': 'pcapkit.foundation.registry.foundation', + 'pcapkit.foundation.reassembly.reassembly': 'pcapkit.foundation.reassembly.reassembly', + 'pcapkit.foundation.traceflow.traceflow': 'pcapkit.foundation.traceflow.traceflow', + 'pcapkit.foundation.traceflow.tcp': 'pcapkit.foundation.traceflow.tcp', + 'pcapkit.foundation.engines.pcap': 'pcapkit.foundation.engines.pcap', + 'pcapkit.foundation.engines.pcapng': 'pcapkit.foundation.engines.pcapng', + 'pcapkit.utilities.exceptions': 'pcapkit.utilities.exceptions', + 'pcapkit.utilities.warnings': 'pcapkit.utilities.warnings', + 'pcapkit.utilities.decorators': 'pcapkit.utilities.decorators', + 'pcapkit.dumpkit.common': 'pcapkit.dumpkit.common', + } + for module_name, expected in cases.items(): + with self.subTest(module=module_name): + module = importlib.import_module(module_name) + self.assertEqual(module.logger.name, expected) + + +class LoggingConfigureTests(unittest.TestCase): + """The public configuration API, at runtime rather than at import.""" + + def setUp(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def tearDown(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def test_configure_sets_level_and_attaches_a_stream_handler(self) -> None: + from pcapkit.utilities.logging import configure, logger + + stream = io.StringIO() + self.assertIs(configure(logging.DEBUG, stream=stream), logger) + + self.assertEqual(logger.level, logging.DEBUG) + logger.debug('configured at runtime') + self.assertIn('configured at runtime', stream.getvalue()) + + def test_configure_accepts_a_level_name(self) -> None: + from pcapkit.utilities.logging import configure, logger + + configure('WARNING') + self.assertEqual(logger.level, logging.WARNING) + + def test_configure_honours_a_custom_format(self) -> None: + from pcapkit.utilities.logging import configure, logger + + stream = io.StringIO() + configure(logging.INFO, stream=stream, fmt='%(levelname)s|%(name)s|%(message)s') + + logger.info('formatted') + self.assertEqual(stream.getvalue().strip(), 'INFO|pcapkit|formatted') + + def test_configure_replaces_handlers_by_default(self) -> None: + from pcapkit.utilities.logging import configure, logger + + first, second = io.StringIO(), io.StringIO() + configure(logging.INFO, stream=first) + configure(logging.INFO, stream=second) + + logger.info('only the second') + self.assertEqual(first.getvalue(), '') + self.assertIn('only the second', second.getvalue()) + + def test_configure_can_add_a_second_destination(self) -> None: + from pcapkit.utilities.logging import configure, logger + + first, second = io.StringIO(), io.StringIO() + configure(logging.INFO, stream=first) + configure(stream=second, replace=False) + + logger.info('both of them') + self.assertIn('both of them', first.getvalue()) + self.assertIn('both of them', second.getvalue()) + + def test_configure_accepts_a_ready_made_handler(self) -> None: + from pcapkit.utilities.logging import configure, logger + + stream = io.StringIO() + handler = logging.StreamHandler(stream) + configure(logging.INFO, handler=handler) + + self.assertIn(handler, logger.handlers) + logger.info('via handler') + self.assertIn('via handler', stream.getvalue()) + + def test_configure_rejects_both_stream_and_handler(self) -> None: + from pcapkit.utilities.logging import configure + + with self.assertRaises(ValueError): + configure(stream=io.StringIO(), handler=logging.NullHandler()) + + def test_configure_can_target_a_single_subtree(self) -> None: + from pcapkit.utilities.logging import configure, logger + + stream = io.StringIO() + configure(logging.DEBUG, stream=stream) + configure(logging.WARNING, name='pcapkit.foundation.registry') + + logging.getLogger('pcapkit.foundation.registry.protocols').debug('bookkeeping') + logging.getLogger('pcapkit.foundation.extraction').debug('worth seeing') + + self.assertNotIn('bookkeeping', stream.getvalue()) + self.assertIn('worth seeing', stream.getvalue()) + self.assertEqual(logger.level, logging.DEBUG) + + def test_configure_can_stop_propagation(self) -> None: + from pcapkit.utilities.logging import configure, logger + + configure(propagate=False) + self.assertFalse(logger.propagate) + + def test_reset_restores_the_library_neutral_state(self) -> None: + from pcapkit.utilities.logging import configure, logger, reset + + configure(logging.DEBUG, stream=io.StringIO(), propagate=False) + self.assertIs(reset(), logger) + + self.assertEqual(logger.level, logging.NOTSET) + self.assertTrue(logger.propagate) + self.assertEqual(len(logger.handlers), 1) + self.assertIsInstance(logger.handlers[0], logging.NullHandler) + + def test_one_line_restore_of_the_historical_stderr_output(self) -> None: + from pcapkit.utilities.logging import DEFAULT_FORMAT, configure, logger + + stream = io.StringIO() + configure(logging.INFO, stream=stream, fmt=DEFAULT_FORMAT) + + logger.info('as it used to be') + self.assertIn('[INFO]', stream.getvalue()) + self.assertIn('as it used to be', stream.getvalue()) + + def test_ensure_output_adds_a_handler_only_when_there_is_none(self) -> None: + from pcapkit.utilities.logging import configure, ensure_output, logger + + # stop propagation first: the ancestry walk would otherwise find the + # handlers the test runner itself attaches to the root logger, which is + # the correct answer but not the one under test here + configure(propagate=False) + + stream = io.StringIO() + self.assertTrue(ensure_output(logging.DEBUG, stream=stream)) + logger.debug('nowhere else to go') + self.assertIn('nowhere else to go', stream.getvalue()) + + # once the application has configured its own output, leave it alone + chosen = io.StringIO() + configure(logging.DEBUG, stream=chosen, propagate=False) + self.assertFalse(ensure_output(logging.DEBUG, stream=io.StringIO())) + logger.debug('to the chosen stream') + self.assertIn('to the chosen stream', chosen.getvalue()) + + def test_ensure_output_respects_an_application_that_configured_the_root(self) -> None: + from pcapkit.utilities.logging import ensure_output, logger + + # an application whose handlers live on the root logger has already + # decided where records go, even though ``pcapkit`` itself has none + root = logging.getLogger() + stream = io.StringIO() + handler = logging.StreamHandler(stream) + root.addHandler(handler) + try: + self.assertFalse(ensure_output(logging.DEBUG)) + self.assertEqual([entry for entry in logger.handlers + if not isinstance(entry, logging.NullHandler)], []) + finally: + root.removeHandler(handler) + + +@unittest.skipUnless(HAS_RUNTIME, 'runtime dependencies not installed') +class RegistryLogLevelTests(unittest.TestCase): + """Registration bookkeeping is the library's own business, so ``debug``.""" + + def setUp(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def tearDown(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def test_registry_bookkeeping_is_logged_at_debug_not_info(self) -> None: + from pcapkit.foundation.reassembly.ipv4 import IPv4 + from pcapkit.foundation.registry.foundation import register_reassembly_ipv4_callback + + def callback(datagrams: list) -> None: + """Throwaway callback.""" + + saved = list(IPv4.__callback_fn__) + try: + with self.assertLogs('pcapkit.foundation.registry.foundation', + level=logging.DEBUG) as caught: + register_reassembly_ipv4_callback(callback) + finally: + IPv4.__callback_fn__[:] = saved + + self.assertEqual(len(caught.records), 1) + record = caught.records[0] + self.assertEqual(record.levelno, logging.DEBUG) + self.assertIn('registered IPv4 reassembly callback', record.getMessage()) + + def test_no_registry_module_still_logs_at_info(self) -> None: + import pcapkit.foundation.registry.foundation # noqa: F401 + import pcapkit.foundation.registry.protocols # noqa: F401 + + root = os.path.dirname(os.path.dirname(os.path.abspath( + pcapkit.foundation.registry.protocols.__file__))) + for name in ('registry/protocols.py', 'registry/foundation.py'): + with self.subTest(module=name): + with open(os.path.join(root, name), encoding='utf-8') as file: + source = file.read() + self.assertNotIn('logger.info(', source) + self.assertIn('logger.debug(', source) + + +@unittest.skipUnless(HAS_RUNTIME, 'runtime dependencies not installed') +class ExtractorLoggingTests(unittest.TestCase): + """The debug trail should explain what pcapkit did with a file.""" + + def setUp(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def tearDown(self) -> None: + purge_modules(['pcapkit']) + pristine() + + def test_extraction_emits_a_debug_trail(self) -> None: + from pcapkit.foundation.extraction import Extractor + from tests._support import sample_path + + with self.assertLogs('pcapkit', level=logging.DEBUG) as caught: + extractor = Extractor(fin=sample_path('arp.pcap'), nofile=True, store=False) + + messages = [record.getMessage() for record in caught.records] + self.assertTrue(any('opening input file' in message for message in messages), messages) + self.assertTrue(any('extraction engine' in message for message in messages), messages) + self.assertTrue(any('reading frames from' in message for message in messages), messages) + self.assertTrue(any('frame(s) from' in message for message in messages), messages) + self.assertEqual(extractor.length, 2) + + # nothing on the parsing path should be shouting at info or above + self.assertEqual([record.getMessage() for record in caught.records + if record.levelno >= logging.INFO and 'EOF' not in record.getMessage()], + []) + + def test_verbose_extraction_still_reaches_a_destination(self) -> None: + from pcapkit.foundation.extraction import Extractor + from tests._support import sample_path + + # ``verbose=True`` asks to see the frames; removing the import-time + # stderr handler must not turn that into silence + with self.assertLogs('pcapkit', level=logging.DEBUG) as caught: + Extractor(fin=sample_path('arp.pcap'), nofile=True, store=False, verbose=True) + + frames = [record.getMessage() for record in caught.records + if record.getMessage().startswith('Frame ')] + self.assertEqual(len(frames), 2) + self.assertTrue(frames[0].startswith('Frame 1: '), frames) + if __name__ == '__main__': unittest.main() From 6a7fe07820a4c022b09259a20d4eb81091acf522 Mon Sep 17 00:00:00 2001 From: Jarry Shaw Date: Mon, 14 Sep 2026 21:46:36 -0400 Subject: [PATCH 2/4] logging: keep verbose frame output on stdout, not on the logger Converting the four verbose= handlers to logger.debug moved user-facing output onto the logger, which changed both its stream and its visibility: the CLI's -v frame chains went from stdout to stderr and only appeared if the consumer had configured a handler. tests/integration/test_cli_subprocess.py caught it. Those chains are a feature of the tool, not diagnostics, so they stay on print. That also removes the need for ensure_output() on the library path -- it existed only to stop verbose=True falling silent once the import-time handler was gone. The helper itself stays public and tested, since it is a reasonable thing for a consumer to call. Every genuine debug call added by this branch is untouched; only the four verbose handlers revert. Docs note and test updated to state the rule: verbose= is stdout, logging is diagnostics. Also converted register_sctp's logger.info to debug, which the branch had missed because SCTP landed on main after it was written -- the branch's own "no info on the registry path" test now passes. Full suite: 529 passed, 4 skipped, 303 subtests passed. --- docs/source/pcapkit/utilities/logging.rst | 9 ++++--- pcapkit/foundation/engines/dpkt.py | 7 +++-- pcapkit/foundation/engines/pyshark.py | 7 +++-- pcapkit/foundation/engines/scapy.py | 7 +++-- pcapkit/foundation/extraction.py | 15 ++++++----- pcapkit/foundation/registry/protocols.py | 2 +- tests/utilities/test_logging.py | 31 ++++++++++++++++++----- 7 files changed, 48 insertions(+), 30 deletions(-) diff --git a/docs/source/pcapkit/utilities/logging.rst b/docs/source/pcapkit/utilities/logging.rst index 7b213b20c3..8ad17e16c0 100644 --- a/docs/source/pcapkit/utilities/logging.rst +++ b/docs/source/pcapkit/utilities/logging.rst @@ -183,10 +183,11 @@ Compatibility Note importable from both :mod:`pcapkit.utilities.logging` and :mod:`pcapkit.utilities`, and named ``pcapkit``; :envvar:`PCAPKIT_DEVMODE` still produces the stderr handler at - :data:`logging.DEBUG`; and ``Extractor(verbose=True)`` still prints a line per - frame, now through :data:`logging.DEBUG` with a destination guaranteed by - :func:`~pcapkit.utilities.logging.ensure_output` when the application has - configured none. + :data:`logging.DEBUG`; and ``Extractor(verbose=True)`` -- like the CLI's + ``-v`` -- still prints a line per frame to :data:`sys.stdout`. That output is + a feature of the tool rather than diagnostics, so it deliberately stays on + :func:`print`: routing it through :mod:`logging` would have moved it to + another stream and made it invisible until the consumer configured a handler. .. note:: diff --git a/pcapkit/foundation/engines/dpkt.py b/pcapkit/foundation/engines/dpkt.py index 5af66dbcbd..a7f433c444 100644 --- a/pcapkit/foundation/engines/dpkt.py +++ b/pcapkit/foundation/engines/dpkt.py @@ -16,7 +16,7 @@ from pcapkit.const.reg.linktype import LinkType as Enum_LinkType from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.utilities.exceptions import FormatError, stacklevel -from pcapkit.utilities.logging import ensure_output, get_logger +from pcapkit.utilities.logging import get_logger from pcapkit.utilities.warnings import AttributeWarning, DPKTWarning, warn __all__ = ['DPKT'] @@ -118,9 +118,8 @@ def run(self) -> 'None': # setup verbose handler if ext._flag_v: from pcapkit.toolkit.dpkt import packet2chain # isort:skip - ensure_output(logging.DEBUG) - ext._vfunc = lambda e, f: logger.debug( - 'Frame %3d: %s', e._frnum, packet2chain(f) # pylint: disable=protected-access + ext._vfunc = lambda e, f: print( + f'Frame {e._frnum:>3d}: {packet2chain(f)}' # pylint: disable=protected-access ) if ext.magic_number in PCAP.MAGIC_NUMBER: diff --git a/pcapkit/foundation/engines/pyshark.py b/pcapkit/foundation/engines/pyshark.py index 9b88e0d0a2..4163932e6b 100644 --- a/pcapkit/foundation/engines/pyshark.py +++ b/pcapkit/foundation/engines/pyshark.py @@ -16,7 +16,7 @@ from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.foundation.reassembly import ReassemblyManager from pcapkit.utilities.exceptions import stacklevel -from pcapkit.utilities.logging import ensure_output, get_logger +from pcapkit.utilities.logging import get_logger from pcapkit.utilities.warnings import AttributeWarning, warn __all__ = ['PyShark'] @@ -117,9 +117,8 @@ def run(self) -> 'None': # setup verbose handler if ext._flag_v: - ensure_output(logging.DEBUG) - ext._vfunc = lambda e, f: logger.debug( - 'Frame %3d: %s', e._frnum, f.frame_info.protocols # pylint: disable=protected-access + ext._vfunc = lambda e, f: print( + f'Frame {e._frnum:>3d}: {f.frame_info.protocols}' # pylint: disable=protected-access ) # extract & analyse file diff --git a/pcapkit/foundation/engines/scapy.py b/pcapkit/foundation/engines/scapy.py index c771640552..e8999f3bcc 100644 --- a/pcapkit/foundation/engines/scapy.py +++ b/pcapkit/foundation/engines/scapy.py @@ -15,7 +15,7 @@ from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.utilities.exceptions import stacklevel -from pcapkit.utilities.logging import ensure_output, get_logger +from pcapkit.utilities.logging import get_logger from pcapkit.utilities.warnings import AttributeWarning, warn __all__ = ['Scapy'] @@ -105,9 +105,8 @@ def run(self) -> 'None': # setup verbose handler if ext._flag_v: from pcapkit.toolkit.scapy import packet2chain # isort:skip - ensure_output(logging.DEBUG) - ext._vfunc = lambda e, f: logger.debug( - 'Frame %3d: %s', e._frnum, packet2chain(f) # pylint: disable=protected-access + ext._vfunc = lambda e, f: print( + f'Frame {e._frnum:>3d}: {packet2chain(f)}' # pylint: disable=protected-access ) # extract & analyse file diff --git a/pcapkit/foundation/extraction.py b/pcapkit/foundation/extraction.py index 14ef14e7d6..c4e40e4903 100644 --- a/pcapkit/foundation/extraction.py +++ b/pcapkit/foundation/extraction.py @@ -38,7 +38,7 @@ from pcapkit.foundation.traceflow.traceflow import TraceFlow from pcapkit.utilities.exceptions import (CallableError, FileNotFound, FormatError, IterableError, RegistryError, UnsupportedCall, stacklevel) -from pcapkit.utilities.logging import ensure_output, get_logger +from pcapkit.utilities.logging import get_logger from pcapkit.utilities.warnings import (EngineWarning, ExtractionWarning, FormatWarning, RegistryWarning, warn) @@ -746,12 +746,13 @@ def __init__(self, if isinstance(verbose, bool): self._flag_v = verbose if verbose: - # ``verbose=True`` is an explicit request to see the frames, so - # make sure the records have a destination even in an - # application that never configured logging at all - ensure_output(logging.DEBUG) - self._vfunc = lambda e, f: logger.debug( - 'Frame %3d: %s', e._frnum, f.protochain # pylint: disable=protected-access + # NOTE: ``verbose=True`` and the CLI's ``-v`` are a request for + # user-facing output on stdout, not diagnostics -- the frame + # chains are a feature of the tool, so they stay on ``print`` + # rather than becoming log records a consumer has to configure + # a handler to see (and on a different stream at that). + self._vfunc = lambda e, f: print( + f'Frame {e._frnum:>3d}: {f.protochain}' # pylint: disable=protected-access ) else: self._vfunc = lambda e, f: None diff --git a/pcapkit/foundation/registry/protocols.py b/pcapkit/foundation/registry/protocols.py index 1fa60d790e..a0da7f3789 100644 --- a/pcapkit/foundation/registry/protocols.py +++ b/pcapkit/foundation/registry/protocols.py @@ -803,7 +803,7 @@ def register_sctp(code: 'int | SCTP_PayloadProtocolIdentifier', module: 'str | M module = cast('ModuleDescriptor[Protocol]', ModuleDescriptor(module, class_)) SCTP.register(code, module) - logger.info('registered SCTP payload protocol identifier: %s', code) + logger.debug('registered SCTP payload protocol identifier: %s', code) # register protocol to protocol registry if isinstance(module, ModuleDescriptor): diff --git a/tests/utilities/test_logging.py b/tests/utilities/test_logging.py index 88ac5099b0..0612e0b9bb 100644 --- a/tests/utilities/test_logging.py +++ b/tests/utilities/test_logging.py @@ -427,20 +427,39 @@ def test_extraction_emits_a_debug_trail(self) -> None: if record.levelno >= logging.INFO and 'EOF' not in record.getMessage()], []) - def test_verbose_extraction_still_reaches_a_destination(self) -> None: + def test_verbose_extraction_prints_frames_to_stdout(self) -> None: + """``verbose=True`` is user-facing output, not a log record. + + The frame chains are a feature of the tool and of the CLI's ``-v``, so + they go to stdout via :func:`print` and are readable without the + consumer configuring a logging handler. Removing the import-time stderr + handler must not turn that into silence, and moving it onto the logger + would have changed both the stream and the visibility. + + """ + import contextlib + import io + from pcapkit.foundation.extraction import Extractor from tests._support import sample_path - # ``verbose=True`` asks to see the frames; removing the import-time - # stderr handler must not turn that into silence - with self.assertLogs('pcapkit', level=logging.DEBUG) as caught: + stdout = io.StringIO() + with contextlib.redirect_stdout(stdout): Extractor(fin=sample_path('arp.pcap'), nofile=True, store=False, verbose=True) - frames = [record.getMessage() for record in caught.records - if record.getMessage().startswith('Frame ')] + frames = [line for line in stdout.getvalue().splitlines() + if line.startswith('Frame ')] self.assertEqual(len(frames), 2) self.assertTrue(frames[0].startswith('Frame 1: '), frames) + # and it stays off the logger, so a consumer at DEBUG is not spammed + # with per-frame records + with self.assertLogs('pcapkit', level=logging.DEBUG) as caught: + with contextlib.redirect_stdout(io.StringIO()): + Extractor(fin=sample_path('arp.pcap'), nofile=True, store=False, verbose=True) + self.assertEqual([record.getMessage() for record in caught.records + if record.getMessage().startswith('Frame ')], []) + if __name__ == '__main__': unittest.main() From b1a1d0ceed9a04e52e40a923df42915cd249ab5a Mon Sep 17 00:00:00 2001 From: Jarry Shaw Date: Mon, 14 Sep 2026 22:23:43 -0400 Subject: [PATCH 3/4] tests: keep the logging tests on a committed capture The new verbose and debug-trail tests read arp.pcap, which the generators build rather than the repository carrying, so the unit-test workflow - which deliberately runs without generated fixtures - failed on every Python version with FileNotFoundError. Same trap as the reassembly case in #376. Switched to in.pcap, one of the six committed captures, and corrected the expected frame count from 2 to 6. Both tests belong in the unit tier: they assert logging behaviour, not capture contents, so any real capture will do. Verified by running the CI selection with only the committed captures present: 417 passed, 219 subtests passed. --- tests/utilities/test_logging.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/tests/utilities/test_logging.py b/tests/utilities/test_logging.py index 0612e0b9bb..4f0c747de4 100644 --- a/tests/utilities/test_logging.py +++ b/tests/utilities/test_logging.py @@ -413,14 +413,14 @@ def test_extraction_emits_a_debug_trail(self) -> None: from tests._support import sample_path with self.assertLogs('pcapkit', level=logging.DEBUG) as caught: - extractor = Extractor(fin=sample_path('arp.pcap'), nofile=True, store=False) + extractor = Extractor(fin=sample_path('in.pcap'), nofile=True, store=False) messages = [record.getMessage() for record in caught.records] self.assertTrue(any('opening input file' in message for message in messages), messages) self.assertTrue(any('extraction engine' in message for message in messages), messages) self.assertTrue(any('reading frames from' in message for message in messages), messages) self.assertTrue(any('frame(s) from' in message for message in messages), messages) - self.assertEqual(extractor.length, 2) + self.assertEqual(extractor.length, 6) # nothing on the parsing path should be shouting at info or above self.assertEqual([record.getMessage() for record in caught.records @@ -445,18 +445,18 @@ def test_verbose_extraction_prints_frames_to_stdout(self) -> None: stdout = io.StringIO() with contextlib.redirect_stdout(stdout): - Extractor(fin=sample_path('arp.pcap'), nofile=True, store=False, verbose=True) + Extractor(fin=sample_path('in.pcap'), nofile=True, store=False, verbose=True) frames = [line for line in stdout.getvalue().splitlines() if line.startswith('Frame ')] - self.assertEqual(len(frames), 2) + self.assertEqual(len(frames), 6) self.assertTrue(frames[0].startswith('Frame 1: '), frames) # and it stays off the logger, so a consumer at DEBUG is not spammed # with per-frame records with self.assertLogs('pcapkit', level=logging.DEBUG) as caught: with contextlib.redirect_stdout(io.StringIO()): - Extractor(fin=sample_path('arp.pcap'), nofile=True, store=False, verbose=True) + Extractor(fin=sample_path('in.pcap'), nofile=True, store=False, verbose=True) self.assertEqual([record.getMessage() for record in caught.records if record.getMessage().startswith('Frame ')], []) From 61fecb45021cb3ffb15ea0e8b321a688b2ded960 Mon Sep 17 00:00:00 2001 From: Jarry Shaw Date: Mon, 14 Sep 2026 22:42:22 -0400 Subject: [PATCH 4/4] logging: do not disturb configuration the application already made Import called reset(), which detached whatever handlers the host application had attached to the pcapkit logger and forced NOTSET and propagate back on. That contradicts the point of the change: a library should inherit the application's configuration, not overwrite it because it was imported second. Import now only guarantees the logger has a handler, and the devmode branch checks membership before attaching, so re-execution still cannot stack handlers - which is what reset() was there for. Verified: an application that configures a handler, INFO and propagate=False before importing pcapkit keeps all three, and two reloads leave one handler. Also from review: - dropped `import logging` from four modules where reverting the verbose handlers to print left it unused (AST-verified, not just grepped: the name survives only in docstrings). - extraction and traceflow logged dumper.__name__, which make_dumper() always names 'DictDumper' whatever the format. They log the wrapped output class now. dictdumper exposes `kind` rather than `name`, but it is an instance property and both sites log before instantiation - and its value duplicates the `fmt` already on the same line, so the class name is what adds anything. - ensure_output's docstring no longer cites verbose= as its motivation, since that path deliberately stays on print, and notes nothing in pcapkit calls it. Full suite 529 passed, 4 skipped, 303 subtests; CI selection without generated captures 417 passed. --- pcapkit/foundation/engines/dpkt.py | 1 - pcapkit/foundation/engines/pyshark.py | 1 - pcapkit/foundation/engines/scapy.py | 1 - pcapkit/foundation/extraction.py | 5 ++-- pcapkit/foundation/traceflow/traceflow.py | 3 ++- pcapkit/utilities/logging.py | 32 ++++++++++++++++------- 6 files changed, 27 insertions(+), 16 deletions(-) diff --git a/pcapkit/foundation/engines/dpkt.py b/pcapkit/foundation/engines/dpkt.py index a7f433c444..08d6d2c230 100644 --- a/pcapkit/foundation/engines/dpkt.py +++ b/pcapkit/foundation/engines/dpkt.py @@ -10,7 +10,6 @@ .. _DPKT: https://dpkt.readthedocs.io """ -import logging from typing import TYPE_CHECKING, cast from pcapkit.const.reg.linktype import LinkType as Enum_LinkType diff --git a/pcapkit/foundation/engines/pyshark.py b/pcapkit/foundation/engines/pyshark.py index 4163932e6b..89e0506c8d 100644 --- a/pcapkit/foundation/engines/pyshark.py +++ b/pcapkit/foundation/engines/pyshark.py @@ -10,7 +10,6 @@ .. _PyShark: https://kiminewt.github.io/pyshark """ -import logging from typing import TYPE_CHECKING, cast from pcapkit.foundation.engines.engine import EngineBase as Engine diff --git a/pcapkit/foundation/engines/scapy.py b/pcapkit/foundation/engines/scapy.py index e8999f3bcc..a69fc22d41 100644 --- a/pcapkit/foundation/engines/scapy.py +++ b/pcapkit/foundation/engines/scapy.py @@ -10,7 +10,6 @@ .. _Scapy: https://scapy.net """ -import logging from typing import TYPE_CHECKING, cast from pcapkit.foundation.engines.engine import EngineBase as Engine diff --git a/pcapkit/foundation/extraction.py b/pcapkit/foundation/extraction.py index c4e40e4903..fecf3b2f2e 100644 --- a/pcapkit/foundation/extraction.py +++ b/pcapkit/foundation/extraction.py @@ -16,7 +16,6 @@ import collections import importlib import io -import logging import os import sys from typing import TYPE_CHECKING, Generic, TypeVar, cast @@ -850,7 +849,9 @@ def __init__(self, self.__output__[fmt] = (output, ext) # update mapping upon import dumper = make_dumper(output) - logger.debug('dumping %s output to %s via %s', fmt, ofnm, dumper.__name__) + # NOTE: make_dumper() names every subclass it builds 'DictDumper', so the + # useful name is the output class it wraps. + logger.debug('dumping %s output to %s via %s', fmt, ofnm, output.__name__) self._ofile = dumper if self._flag_f else dumper(ofnm) # output file else: logger.debug('file output disabled') diff --git a/pcapkit/foundation/traceflow/traceflow.py b/pcapkit/foundation/traceflow/traceflow.py index 5106796eb5..685c8d5730 100644 --- a/pcapkit/foundation/traceflow/traceflow.py +++ b/pcapkit/foundation/traceflow/traceflow.py @@ -239,7 +239,8 @@ def make_fout(cls, fout: 'str' = './tmp', fmt: 'str' = 'pcap') -> 'tuple[Type[Du raise FileExists(*error.args).with_traceback(error.__traceback__) dumper = make_dumper(output) - logger.debug('flow tracing output root %s, format %s via %s', fout, fmt, dumper.__name__) + # NOTE: as above -- make_dumper()'s subclass is always called 'DictDumper'. + logger.debug('flow tracing output root %s, format %s via %s', fout, fmt, output.__name__) return dumper, ext @abc.abstractmethod diff --git a/pcapkit/utilities/logging.py b/pcapkit/utilities/logging.py index 465c526fc7..15db274b50 100644 --- a/pcapkit/utilities/logging.py +++ b/pcapkit/utilities/logging.py @@ -174,10 +174,15 @@ def ensure_output(level: 'Union[int, str]' = logging.DEBUG, *, stream: 'Optional[IO[str]]' = None) -> 'bool': """Guarantee that :mod:`pcapkit`'s records have somewhere to go. - This exists for the features a caller switches on precisely *because* they - want to see the output -- ``Extractor(verbose=True)`` above all -- where - staying silent because the application never configured :mod:`logging` would - be a bug rather than good library manners. + This is for a caller that has switched something on precisely *because* it + wants to see the output, and for which staying silent merely because the + application never configured :mod:`logging` would be unhelpful. + + Note that ``Extractor(verbose=True)`` and the CLI's ``-v`` do **not** go + through here: their frame chains are user-facing output and are written to + :data:`sys.stdout` with :func:`print`, so they are visible with no logging + configuration at all. Nothing in :mod:`pcapkit` calls this function itself; + it exists for consumers. An application that has configured its own handlers has already answered the question, so nothing is changed in that case. @@ -325,13 +330,20 @@ def configure(level: 'Optional[Union[int, str]]' = None, *, return target -# Re-running this module (which the test suite does, to exercise import-time -# behaviour) must not stack a second handler onto the process-wide ``pcapkit`` -# logger, so start from a known-clean state rather than adding to whatever is -# already there. -reset() +# NOTE: Import must not disturb configuration the application has already +# made -- that is the whole point of the NullHandler convention -- so this only +# guarantees the logger has *a* handler, and leaves level and propagation +# alone. Calling reset() here instead would detach a host application's +# handlers merely because it imported pcapkit after configuring logging. +# +# The membership tests also make re-execution idempotent, which the test suite +# relies on when it exercises import-time behaviour: neither the NullHandler +# nor the devmode stderr handler can be stacked twice. +if not logger.handlers: + logger.addHandler(logging.NullHandler()) if DEVMODE: # development mode keeps the historical behaviour: everything, on stderr logger.setLevel(logging.DEBUG) - logger.addHandler(handler) + if handler not in logger.handlers: + logger.addHandler(handler)