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..8ad17e16c0 --- /dev/null +++ b/docs/source/pcapkit/utilities/logging.rst @@ -0,0 +1,200 @@ +============== +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)`` -- 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:: + + 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..08d6d2c230 100644 --- a/pcapkit/foundation/engines/dpkt.py +++ b/pcapkit/foundation/engines/dpkt.py @@ -15,6 +15,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 get_logger from pcapkit.utilities.warnings import AttributeWarning, DPKTWarning, warn __all__ = ['DPKT'] @@ -30,6 +31,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. @@ -114,11 +119,13 @@ def run(self) -> 'None': 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 + ) 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..89e0506c8d 100644 --- a/pcapkit/foundation/engines/pyshark.py +++ b/pcapkit/foundation/engines/pyshark.py @@ -15,6 +15,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 get_logger from pcapkit.utilities.warnings import AttributeWarning, warn __all__ = ['PyShark'] @@ -25,6 +26,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 +108,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", @@ -112,9 +118,10 @@ def run(self) -> 'None': 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 + ) # 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..a69fc22d41 100644 --- a/pcapkit/foundation/engines/scapy.py +++ b/pcapkit/foundation/engines/scapy.py @@ -14,6 +14,7 @@ from pcapkit.foundation.engines.engine import EngineBase as Engine from pcapkit.utilities.exceptions import stacklevel +from pcapkit.utilities.logging import get_logger from pcapkit.utilities.warnings import AttributeWarning, warn __all__ = ['Scapy'] @@ -25,6 +26,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. @@ -101,9 +106,10 @@ def run(self) -> 'None': 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 + ) # 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..fecf3b2f2e 100644 --- a/pcapkit/foundation/extraction.py +++ b/pcapkit/foundation/extraction.py @@ -37,7 +37,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 get_logger from pcapkit.utilities.warnings import (EngineWarning, ExtractionWarning, FormatWarning, RegistryWarning, warn) @@ -70,6 +70,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 +430,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 +456,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 +489,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 +620,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 +633,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 +745,14 @@ def __init__(self, if isinstance(verbose, bool): self._flag_v = verbose if verbose: + # 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 - ) # pylint: disable=logging-fstring-interpolation + ) 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,12 @@ def __init__(self, self.__output__[fmt] = (output, ext) # update mapping upon import dumper = make_dumper(output) + # 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') # 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 +932,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 +949,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..a0da7f3789 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): @@ -799,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): @@ -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..685c8d5730 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,11 @@ 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) + # 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 def dump(self, packet: '_PT') -> 'None': @@ -323,6 +332,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..15db274b50 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,274 @@ # 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 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. + + 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 + + +# 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) -else: - logger.setLevel(logging.INFO) -handler.setFormatter(formatter) -logger.addHandler(handler) + if handler not in logger.handlers: + 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..4f0c747de4 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,391 @@ 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('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, 6) + + # 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_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 + + stdout = io.StringIO() + with contextlib.redirect_stdout(stdout): + 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), 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('in.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()