Merge pull request #1080 from OCR-D/revise-logging

Refactor logging

Makefile

@@ -5,7 +5,7 @@ PYTHON ?= python
 PIP ?= pip
 LOG_LEVEL = INFO
 PYTHONIOENCODING=utf8
-TESTDIR = tests
+TESTDIR = $(CURDIR)/tests
 PYTEST_ARGS = --continue-on-collection-errors
 
 SPHINX_APIDOC =
@@ -198,15 +198,9 @@ assets: repo/assets
 test: assets
 	$(PYTHON) \
 		-m pytest $(PYTEST_ARGS) --durations=10\
-		--ignore=$(TESTDIR)/test_logging.py \
-		--ignore=$(TESTDIR)/test_logging_conf.py \
 		--ignore-glob="$(TESTDIR)/**/*bench*.py" \
 		$(TESTDIR)
-	#$(MAKE) test-logging
-
-test-logging:
-	HOME=$(CURDIR)/ocrd_utils $(PYTHON) -m pytest --continue-on-collection-errors -k TestLogging $(TESTDIR)
-	HOME=$(CURDIR) $(PYTHON) -m pytest --continue-on-collection-errors -k TestLogging $(TESTDIR)
+	cd ocrd_utils ; $(PYTHON) -m pytest --continue-on-collection-errors -k TestLogging $(TESTDIR)
 
 benchmark:
 	$(PYTHON) -m pytest $(TESTDIR)/model/test_ocrd_mets_bench.py

ocrd/ocrd/cli/log.py

@@ -21,14 +21,17 @@ def log(self, lvl, *args, **kwargs):
 pass_log = click.make_pass_decorator(LogCtx)
 
 @click.group("log")
-@click.option('-n', '--name', envvar='OCRD_TOOL_NAME', default='', metavar='LOGGER_NAME', help='Name of the logger', show_default=True)
+@click.option('-n', '--name', envvar='OCRD_TOOL_NAME', default='ocrd', metavar='LOGGER_NAME', help='Name of the logger', show_default=True)
 @click.pass_context
 def log_cli(ctx, name, *args, **kwargs):
     """
     Logging
+
+    Logger name will be ocrd.OCRD_TOOL_NAME where OCRD_TOOL_NAME is normally
+    (when using bashlib) the name of the processor.
     """
     initLogging()
-    ctx.obj = LogCtx(name)
+    ctx.obj = LogCtx('ocrd.' + name)
 
 def _bind_log_command(lvl):
     @click.argument('msgs', nargs=-1)

ocrd/ocrd/decorators/loglevel_option.py

@@ -4,6 +4,8 @@
 __all__ = ['ocrd_loglevel']
 
 def _setOverrideLogLevel(ctx, param, value):    # pylint: disable=unused-argument
+    if value is None:   # Explicitly test for None because logging.DEBUG == 0
+        return
     setOverrideLogLevel(value)
     return value
 

ocrd/ocrd/mets_server.py

@@ -19,11 +19,6 @@
 from ocrd_models import OcrdMets, OcrdFile, ClientSideOcrdFile, OcrdAgent, ClientSideOcrdAgent
 from ocrd_utils import initLogging, getLogger, deprecated_alias
 
-#
-# XXX HACKS TODO
-#
-initLogging()
-
 #
 # Models
 #

ocrd_utils/ocrd_logging.conf

@@ -53,6 +53,29 @@ handlers=consoleHandler
 #handlers=fileHandler
 #qualname=ocrd.workspace
 
+# ocrd loggers
+[logger_ocrd_ocrd]
+level=ERROR
+handlers=consoleHandler
+qualname=ocrd
+
+[logger_ocrd_ocrd_models]
+level=INFO
+handlers=consoleHandler
+qualname=ocrd_models
+[logger_ocrd_ocrd_utils]
+level=INFO
+handlers=consoleHandler
+qualname=ocrd_utils
+[logger_ocrd_ocrd_network]
+level=INFO
+handlers=consoleHandler
+qualname=ocrd_network
+[logger_ocrd_ocrd_exif]
+level=INFO
+handlers=consoleHandler
+qualname=ocrd_exif
+
 
 #
 # logger tensorflow
@@ -62,7 +85,6 @@ level=ERROR
 handlers=consoleHandler
 qualname=tensorflow
 
-
 #
 # logger shapely.geos
 #

ocrd_utils/ocrd_utils/__init__.py

@@ -166,7 +166,6 @@
     getLevelName,
     getLogger,
     initLogging,
-    logging,
     setOverrideLogLevel,
     )
 

ocrd_utils/ocrd_utils/logging.py

@@ -10,15 +10,29 @@
 - $PWD/ocrd_logging.py
 
 These files will be executed in the context of ocrd/ocrd_logging.py, with `logging` global set.
+
+Changes as of 2023-08-20:
+
+    - Try to be less intrusive with OCR-D specific logging conventions to
+      make it easier and less surprising to define logging behavior when
+      using OCR-D/core as a library
+    - Change setOverrideLogLevel to only override the log level of the ``ocrd``
+      logger and its descendants
+    - initLogging will set exactly one handler, for the root logger or for the
+      ``ocrd`` logger.
+    - Child loggers should propagate to the ancestor logging (default
+      behavior of the logging library - no more PropagationShyLogger)
+    - disableLogging only removes any handlers from the ``ocrd`` logger
 """
 # pylint: disable=no-member
 
 from __future__ import absolute_import
+
 from traceback import format_stack
 
 import logging
 import logging.config
-import os
+from pathlib import Path
 import sys
 
 from .constants import LOG_FORMAT, LOG_TIMEFMT
@@ -32,8 +46,22 @@
     'setOverrideLogLevel',
 ]
 
+LOGGING_DEFAULTS = {
+    'ocrd': logging.INFO,
+    'ocrd_models': logging.INFO,
+    'ocrd_utils': logging.INFO,
+    'ocrd_network': logging.INFO,
+    'ocrd_exif': logging.INFO,
+    # 'ocrd.resolver': logging.INFO,
+    # 'ocrd.resolver.download_to_directory': logging.INFO,
+    # 'ocrd.resolver.add_files_to_mets': logging.INFO,
+    # To cut back on the `Self-intersection at or near point` INFO messages
+    'shapely.geos': logging.ERROR,
+    'tensorflow': logging.ERROR,
+    'PIL': logging.INFO,
+}
+
 _initialized_flag = False
-_overrideLogLevel = None
 
 _ocrdLevel2pythonLevel = {
     'TRACE': 'DEBUG',
@@ -54,128 +82,119 @@ def tf_disable_interactive_logs():
         # Nothing should be handled here if TF is not available
         pass
 
-
-class PropagationShyLogger(logging.Logger):
-
-    def addHandler(self, hdlr):
-        super().addHandler(hdlr)
-        self.propagate = not self.handlers
-
-    def removeHandler(self, hdlr):
-        super().removeHandler(hdlr)
-        self.propagate = not self.handlers
-
-logging.setLoggerClass(PropagationShyLogger)
-logging.getLogger().propagate = False
-
 def getLevelName(lvl):
     """
     Get (string) python logging level for (string) spec-defined log level name.
     """
     lvl = _ocrdLevel2pythonLevel.get(lvl, lvl)
     return logging.getLevelName(lvl)
 
-def setOverrideLogLevel(lvl, silent=False):
+def getLogger(*args, **kwargs):
     """
-    Override all logger filter levels to include lvl and above.
-
+    Wrapper around ``logging.getLogger`` that alls :py:func:`initLogging` if
+    that wasn't explicitly called before.
+    """
+    if not _initialized_flag:
+        initLogging()
+    logger = logging.getLogger(*args, **kwargs)
+    return logger
 
-    - Set root logger level
-    - iterates all existing loggers and sets their log level to ``NOTSET``.
+def setOverrideLogLevel(lvl, silent=True):
+    """
+    Override the output log level of the handlers attached to the ``ocrd`` logger.
 
     Args:
         lvl (string): Log level name.
         silent (boolean): Whether to log the override call
     """
-    if lvl is None:
-        return
-    root_logger = logging.getLogger('')
-    if not silent:
-        root_logger.info('Overriding log level globally to %s', lvl)
-    lvl = getLevelName(lvl)
-    global _overrideLogLevel # pylint: disable=global-statement
-    _overrideLogLevel = lvl
-    for loggerName in logging.Logger.manager.loggerDict:
-        logger = logging.Logger.manager.loggerDict[loggerName]
-        if isinstance(logger, logging.PlaceHolder):
-            continue
-        logger.setLevel(logging.NOTSET)
-    root_logger.setLevel(lvl)
-
-def getLogger(*args, **kwargs):
-    """
-    Wrapper around ``logging.getLogger`` that respects `overrideLogLevel <#setOverrideLogLevel>`_.
-    """
     if not _initialized_flag:
         initLogging()
-        logging.getLogger('').critical('getLogger was called before initLogging. Source of the call:')
-        for line in [x for x in format_stack(limit=2)[0].split('\n') if x]:
-            logging.getLogger('').critical(line)
-    name = args[0]
-    logger = logging.getLogger(*args, **kwargs)
-    if _overrideLogLevel and name:
-        logger.setLevel(logging.NOTSET)
-    return logger
+    ocrd_logger = logging.getLogger('ocrd')
+
+    if lvl is None:
+        if not silent:
+            ocrd_logger.info('Reset log level override')
+        ocrd_logger.setLevel(logging.NOTSET)
+    else:
+        if not silent:
+            ocrd_logger.info('Overriding ocrd log level to %s', lvl)
+        ocrd_logger.setLevel(lvl)
 
-def initLogging():
+def initLogging(builtin_only=False, force_reinit=False):
     """
-    Reset root logger, read logging configuration if exists, otherwise use basicConfig
+    Reset ``ocrd`` logger, read logging configuration if exists, otherwise use basicConfig
+
+    initLogging is to be called by OCR-D/core once, i.e.
+        -  for the ``ocrd`` CLI
+        -  for the processor wrapper methods
+
+    Other processes that use OCR-D/core as a library can, but do not have to, use this functionality.
+
+    Keyword Args:
+        - builtin_only (bool, False): Whether to search for logging configuration
+                                      on-disk (``False``) or only use the
+                                      hard-coded config (``True``). For testing
+        - force_reinit (bool, False): Whether to ignore the module-level
+                                      ``_initialized_flag``. For testing only.
     """
-    global _initialized_flag # pylint: disable=global-statement
-    if _initialized_flag:
-        logging.getLogger('').critical('initLogging was called multiple times. Source of latest call:')
-        for line in [x for x in format_stack(limit=2)[0].split('\n') if x]:
-            logging.getLogger('').critical(line)
+    global _initialized_flag
+    if _initialized_flag and not force_reinit:
+        return
+    # disableLogging()
 
+    # https://docs.python.org/3/library/logging.html#logging.disable
+    # If logging.disable(logging.NOTSET) is called, it effectively removes this
+    # overriding level, so that logging output again depends on the effective
+    # levels of individual loggers.
     logging.disable(logging.NOTSET)
-    for handler in logging.root.handlers[:]:
-        logging.root.removeHandler(handler)
-
-    CONFIG_PATHS = [
-        os.path.curdir,
-        os.path.join(os.path.expanduser('~')),
-        '/etc',
-    ]
-    config_file = next((f for f \
-            in [os.path.join(p, 'ocrd_logging.conf') for p in CONFIG_PATHS] \
-            if os.path.exists(f)),
-            None)
+
+    # remove all handlers for the ocrd logger
+    for handler in logging.getLogger('ocrd').handlers[:]:
+        logging.getLogger('ocrd').removeHandler(handler)
+
+    config_file = None
+    if not builtin_only:
+        CONFIG_PATHS = [
+            Path.cwd(),
+            Path.home(),
+            Path('/etc'),
+        ]
+        config_file = next((f for f \
+                in [p / 'ocrd_logging.conf' for p in CONFIG_PATHS] \
+                if f.exists()),
+                None)
     if config_file:
         logging.config.fileConfig(config_file)
-        logging.getLogger('ocrd.logging').debug("Picked up logging config at %s" % config_file)
+        logging.getLogger('ocrd.logging').debug("Picked up logging config at %s", config_file)
     else:
         # Default logging config
-        logging.basicConfig(level=logging.INFO, format=LOG_FORMAT, datefmt=LOG_TIMEFMT, stream=sys.stderr)
-        logging.getLogger('').setLevel(logging.INFO)
-        #  logging.getLogger('ocrd.resolver').setLevel(logging.INFO)
-        #  logging.getLogger('ocrd.resolver.download_to_directory').setLevel(logging.INFO)
-        #  logging.getLogger('ocrd.resolver.add_files_to_mets').setLevel(logging.INFO)
-        logging.getLogger('PIL').setLevel(logging.INFO)
-        # To cut back on the `Self-intersection at or near point` INFO messages
-        logging.getLogger('shapely.geos').setLevel(logging.ERROR)
-        logging.getLogger('tensorflow').setLevel(logging.ERROR)
-
-    if _overrideLogLevel:
-        # for existing loggers that won't have getLogger do this
-        # (because they were instantiated through logging.getLogger
-        #  instead of ours, or come from logging.config.fileConfig),
-        # unset log levels so the global override can apply:
-        for loggerName in logging.Logger.manager.loggerDict:
-            logger = logging.Logger.manager.loggerDict[loggerName]
-            if isinstance(logger, logging.PlaceHolder):
-                continue
-            logger.setLevel(logging.NOTSET)
-        logging.getLogger('').setLevel(_overrideLogLevel)
+        ocrd_handler = logging.StreamHandler(stream=sys.stderr)
+        ocrd_handler.setFormatter(logging.Formatter(fmt=LOG_FORMAT, datefmt=LOG_TIMEFMT))
+        ocrd_handler.setLevel(logging.DEBUG)
+        logging.getLogger('ocrd').addHandler(ocrd_handler)
+        for logger_name, logger_level in LOGGING_DEFAULTS.items():
+            logging.getLogger(logger_name).setLevel(logger_level)
 
     _initialized_flag = True
 
-def disableLogging():
+def disableLogging(silent=True):
+    """
+    Disables all logging of the ``ocrd`` logger and descendants
+
+    Keyword Args:
+        silent (bool, True): Whether to log the call to disableLogging
+    """
     global _initialized_flag # pylint: disable=global-statement
+    if _initialized_flag and not silent:
+        logging.getLogger('ocrd.logging').debug("Disabling logging")
     _initialized_flag = False
-    global _overrideLogLevel # pylint: disable=global-statement
-    _overrideLogLevel = None
-    logging.basicConfig(level=logging.CRITICAL)
-    logging.disable(logging.ERROR)
+    # logging.basicConfig(level=logging.CRITICAL)
+    # logging.disable(logging.ERROR)
+    # remove all handlers for the ocrd logger
+    for handler in logging.getLogger('ocrd').handlers[:]:
+        logging.getLogger('ocrd').removeHandler(handler)
+    for logger_name in LOGGING_DEFAULTS:
+        logging.getLogger(logger_name).setLevel(logging.NOTSET)
 
 # Initializing stream handlers at module level
 # would cause message output in all runtime contexts,