ocrd_utils.initLogging: also add handler to root logger

src/ocrd_utils/logging.py

@@ -48,13 +48,8 @@
     'setOverrideLogLevel',
 ]
 
-# These are the loggers we add handlers to
-ROOT_OCRD_LOGGERS = [
-    'ocrd',
-    'ocrd_network'
-]
-
 LOGGING_DEFAULTS = {
+    '': logging.WARNING,
     'ocrd': logging.INFO,
     'ocrd_network': logging.INFO,
     # 'ocrd.resolver': logging.INFO,
@@ -115,18 +110,15 @@ def setOverrideLogLevel(lvl, silent=not config.OCRD_LOGGING_DEBUG):
         lvl (string): Log level name.
         silent (boolean): Whether to log the override call
     """
-    if not _initialized_flag:
-        initLogging(silent=silent)
-    ocrd_logger = logging.getLogger('ocrd')
-
-    if lvl is None:
-        if not silent:
-            print('[LOGGING] Reset log level override', file=sys.stderr)
-        ocrd_logger.setLevel(logging.NOTSET)
-    else:
-        if not silent:
-            print(f'[LOGGING] Overriding ocrd log level to {lvl}', file=sys.stderr)
-        ocrd_logger.setLevel(lvl)
+    if lvl is not None:
+        lvl = getLevelName(lvl)
+        if not _initialized_flag:
+            initLogging(silent=silent)
+        # affect all configured loggers
+        for logger_name in logging.root.manager.loggerDict:
+            if not silent:
+                print(f'[LOGGING] Overriding {logger_name} log level to {lvl}', file=sys.stderr)
+            logging.getLogger(logger_name).setLevel(lvl)
 
 def get_logging_config_files():
     """
@@ -160,20 +152,11 @@ def initLogging(builtin_only=False, force_reinit=False, silent=not config.OCRD_L
         - silent (bool, True): Whether to log logging behavior by printing to stderr
     """
     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)
-
-    # remove all handlers for the ocrd root loggers
-    for logger_name in ROOT_OCRD_LOGGERS:
-        for handler in logging.getLogger(logger_name).handlers[:]:
-            logging.getLogger(logger_name).removeHandler(handler)
+    if _initialized_flag:
+        if force_reinit:
+            disableLogging(silent=silent)
+        else:
+            return
 
     config_file = None
     if not builtin_only:
@@ -192,8 +175,8 @@ def initLogging(builtin_only=False, force_reinit=False, silent=not config.OCRD_L
         ocrd_handler = logging.StreamHandler(stream=sys.stderr)
         ocrd_handler.setFormatter(logging.Formatter(fmt=LOG_FORMAT, datefmt=LOG_TIMEFMT))
         ocrd_handler.setLevel(logging.DEBUG)
-        for logger_name in ROOT_OCRD_LOGGERS:
-            logging.getLogger(logger_name).addHandler(ocrd_handler)
+        root_logger = logging.getLogger('')
+        root_logger.addHandler(ocrd_handler)
         for logger_name, logger_level in LOGGING_DEFAULTS.items():
             logging.getLogger(logger_name).setLevel(logger_level)
     _initialized_flag = True
@@ -209,24 +192,16 @@ def disableLogging(silent=not config.OCRD_LOGGING_DEBUG):
     if _initialized_flag and not silent:
         print("[LOGGING] Disabling logging", file=sys.stderr)
     _initialized_flag = False
-    # logging.basicConfig(level=logging.CRITICAL)
-    # logging.disable(logging.ERROR)
-    # remove all handlers for the 'ocrd.' and root logger
-    for logger_name in ROOT_OCRD_LOGGERS + ['']:
-        for handler in logging.getLogger(logger_name).handlers[:]:
-            logging.getLogger(logger_name).removeHandler(handler)
-    for logger_name in LOGGING_DEFAULTS:
-        logging.getLogger(logger_name).setLevel(logging.NOTSET)
+    # remove all handlers we might have added (via initLogging on builtin or file config)
+    for logger_name in logging.root.manager.loggerDict:
+        if not silent:
+            print(f'[LOGGING] Resetting {logger_name} log level and handlers')
+        logger = logging.getLogger(logger_name)
+        logger.setLevel(logging.NOTSET)
+        for handler in logger.handlers[:]:
+            logger.removeHandler(handler)
+    for handler in logging.root.handlers[:]:
+        logging.root.removeHandler(handler)
     # Python default log level is WARNING
     logging.root.setLevel(logging.WARNING)
 
-# Initializing stream handlers at module level
-# would cause message output in all runtime contexts,
-# including those which are already run for std output
-# (--dump-json, --version, ocrd-tool, bashlib etc).
-# So this needs to be an opt-in from the CLIs/decorators:
-#initLogging()
-# Also, we even have to block log output for libraries
-# (like matplotlib/tensorflow) which set up logging
-# themselves already:
-disableLogging()

src/ocrd_utils/ocrd_logging.conf

@@ -34,7 +34,7 @@ keys=defaultFormatter,detailedFormatter
 # default logger "root" using consoleHandler
 #
 [logger_root]
-level=INFO
+level=WARNING
 handlers=consoleHandler,fileHandler
 
 
@@ -56,30 +56,30 @@ handlers=consoleHandler,fileHandler
 # ocrd loggers
 [logger_ocrd]
 level=INFO
-handlers=consoleHandler,fileHandler
+handlers=
 qualname=ocrd
-propagate=0
 
 [logger_ocrd_network]
 level=INFO
-handlers=consoleHandler,processingServerHandler
+#handlers=consoleHandler,processingServerHandler
+handlers=processingServerHandler
 qualname=ocrd_network
-propagate=0
+#propagate=0
 
 #
 # logger tensorflow
 #
 [logger_ocrd_tensorflow]
 level=ERROR
-handlers=consoleHandler
+handlers=
 qualname=tensorflow
 
 #
 # logger shapely.geos
 #
 [logger_ocrd_shapely_geos]
 level=ERROR
-handlers=consoleHandler
+handlers=
 qualname=shapely.geos
 
 
@@ -88,42 +88,40 @@ qualname=shapely.geos
 #
 [logger_ocrd_PIL]
 level=INFO
-handlers=consoleHandler
+handlers=
 qualname=PIL
 
 #
 # paramiko loggers
 #
 [logger_paramiko]
 level=INFO
-handlers=consoleHandler
+handlers=
 qualname=paramiko
-propagate=0
 
 [logger_paramiko_transport]
 level=INFO
-handlers=consoleHandler
+handlers=
 qualname=paramiko.transport
-propagate=0
 
 #
 # uvicorn loggers
 #
 [logger_uvicorn]
 level=INFO
-handlers=consoleHandler
+handlers=
 qualname=uvicorn
 [logger_uvicorn_access]
 level=WARN
-handlers=consoleHandler
+handlers=
 qualname=uvicorn.access
 [logger_uvicorn_error]
 level=INFO
-handlers=consoleHandler
+handlers=
 qualname=uvicorn.error
 [logger_multipart]
 level=INFO
-handlers=consoleHandler
+handlers=
 qualname=multipart
 
 

tests/base.py

@@ -26,8 +26,6 @@ class TestCase(VanillaTestCase):
 
     def setUp(self):
         chdir(dirname(realpath(__file__)) + '/..')
-        disableLogging()
-        initLogging(builtin_only=True)
 
 class CapturingTestCase(TestCase):
     """

tests/cli/test_log.py

@@ -6,8 +6,8 @@
 from tests.base import CapturingTestCase as TestCase, main, assets, copy_of_directory
 
 from ocrd.decorators import ocrd_loglevel
-from ocrd_utils import setOverrideLogLevel, logging, disableLogging
-import logging as python_logging
+from ocrd_utils import disableLogging, initLogging
+import logging
 
 @click.group()
 @ocrd_loglevel
@@ -18,14 +18,19 @@ def mock_ocrd_cli(log_level):
 class TestLogCli(TestCase):
 
     def _get_log_output(self, *args):
-        disableLogging()
         code, out, err = self.invoke_cli(mock_ocrd_cli, args)
         print({'code': code, 'out': out, 'err': err})
         return err
 
+    def setUp(self):
+        super().setUp()
+        initLogging()
+
     def tearDown(self):
         if 'OCRD_TOOL_NAME' in ENV:
             del(ENV['OCRD_TOOL_NAME'])
+        super().tearDown()
+        disableLogging()
 
     def test_loglevel(self):
         assert 'DEBUG ocrd.log_cli - foo' not in self._get_log_output('log', 'debug', 'foo')

tests/processor/test_processor.py

@@ -17,21 +17,21 @@
 
 class TestProcessor(TestCase):
 
+    def run(self, result=None):
+        with copy_of_directory(assets.path_to('SBB0000F29300010000/data')) as workdir:
+            with pushd_popd(workdir):
+                self.resolver = Resolver()
+                self.workspace = self.resolver.workspace_from_url('mets.xml')
+                super().run(result=result)
+
     def setUp(self):
         super().setUp()
-        # make sure we get an isolated temporary copy of the testdata each time
-        # as long as we are not using pytest but unittest, we need to manage contexts
-        # (enterContext is only supported starting with py311)
-        with ExitStack() as stack:
-            self.resolver = Resolver()
-            self.workdir = stack.enter_context(copy_of_directory(assets.path_to('SBB0000F29300010000/data')))
-            stack.enter_context(pushd_popd(self.workdir))
-            self.workspace = self.resolver.workspace_from_url('mets.xml')
-            self.addCleanup(stack.pop_all().close)
+        initLogging()
 
     def tearDown(self):
         super().tearDown()
         config.reset_defaults()
+        disableLogging()
 
     def test_incomplete_processor(self):
         proc = IncompleteProcessor(None)
@@ -251,6 +251,7 @@ class ZipTestProcessor(Processor): pass
 
 def test_run_output_metsserver(start_mets_server):
     mets_server_url, ws = start_mets_server
+    assert len(ws.mets.find_all_files(fileGrp="OCR-D-OUT")) == 0
     run_processor(DummyProcessorWithOutput, workspace=ws,
                   input_file_grp="OCR-D-IMG",
                   output_file_grp="OCR-D-OUT",
@@ -269,7 +270,7 @@ def test_run_output_metsserver(start_mets_server):
                       output_file_grp="OCR-D-OUT",
                       mets_server_url=mets_server_url)
     assert "already exists" in str(exc.value)
-
+    config.reset_defaults()
 
 if __name__ == "__main__":
     main(__file__)

tests/test_decorators.py

@@ -41,22 +41,20 @@ def cli_dummy_processor(*args, **kwargs):
 
 class TestDecorators(TestCase):
 
-    def setUp(self):
-        super().setUp()
-        disableLogging()
-
     def tearDown(self):
         super().tearDown()
         config.reset_defaults()
+        disableLogging()
 
     def test_minimal(self):
-        exit_code, out, err = self.invoke_cli(cli_with_ocrd_cli_options, ['-l', 'DEBUG'])
-        print(out, err)
-        assert not exit_code
+        initLogging()
+        code, out, err = self.invoke_cli(cli_with_ocrd_cli_options, ['-l', 'DEBUG'])
+        assert not code, (out, err)
 
     def test_loglevel_invalid(self):
-        code, _, err = self.invoke_cli(cli_with_ocrd_loglevel, ['--log-level', 'foo'])
-        assert code
+        initLogging()
+        code, out, err = self.invoke_cli(cli_with_ocrd_loglevel, ['--log-level', 'foo'])
+        assert code, (out, err)
         import click
         if int(click.__version__[0]) < 8:
             assert 'invalid choice: foo' in err
@@ -67,7 +65,6 @@ def test_loglevel_override(self):
         if get_logging_config_files():
             pytest.skip(f"ocrd_logging.conf found at {get_logging_config_files()}, skipping logging test")
         import logging
-        disableLogging()
         assert logging.getLogger('').getEffectiveLevel() == logging.WARNING
         assert logging.getLogger('ocrd').getEffectiveLevel() == logging.WARNING
         initLogging()

tests/test_logging.py

@@ -26,16 +26,22 @@ class TestLogging(TestCase):
     def setUp(self):
         pass # do not chdir
 
+    def tearDown(self):
+        super().tearDown()
+        disableLogging()
+
     def test_loglevel_inheritance(self):
         initLogging(builtin_only=True)
         ocrd_logger = logging.getLogger('ocrd')
         assert ocrd_logger.getEffectiveLevel() == logging.INFO
         some_logger = getLogger('ocrd.foo')
+        assert some_logger.level == logging.NOTSET
         assert some_logger.getEffectiveLevel() == logging.INFO
         setOverrideLogLevel('ERROR')
         assert ocrd_logger.getEffectiveLevel() == logging.ERROR
         assert some_logger.getEffectiveLevel() == logging.ERROR
         another_logger = getLogger('ocrd.bar')
+        assert another_logger.level == logging.NOTSET
         assert another_logger.getEffectiveLevel() == logging.ERROR
 
     def test_getLevelName(self):