Logging integration: make the logger a library citizen, and use it

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
 =====================

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.

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
 -----------

pcapkit/dumpkit/common.py

@@ -24,17 +24,23 @@
 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
 
     from dictdumper.dumper import Dumper as ABCDumper
     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.
 

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}')

pcapkit/foundation/engines/pcap.py

@@ -13,13 +13,18 @@
 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']
 
 if TYPE_CHECKING:
     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