Repository: ocr-d/core
Issue: logging: avoid duplicate messages

Despite our epic efforts in #460 and #462, we now do have the unfortunate situation that log messsages are sometimes received as duplicates.

Example to reproduce:
1. configure a logger with handler for `processor`
2. program a processor sending to `processor.MyProc`
3. watch messages coming in twice, because `processor.MyProc` has no handler (so `getLogger` keeps `propagate=True`) and `processor` has a handler but _also_ has the default `propagate=True` (which no `getLogger` was asked to disable) so root's handler gets it as well

Proposed solution: Invert the logic and set `propagate=False` in the _root_ logger in `initLogging`, but then set `propagate=True` in `getLogger` iff the requested logger has not been equipped with handlers qua config.

Changed files:
ocrd_utils/ocrd_utils/logging.py, tests/test_logging.py

diff --git a/ocrd_utils/ocrd_utils/logging.py b/ocrd_utils/ocrd_utils/logging.py
index 9c8b5d06..e3364f73 100644
--- a/ocrd_utils/ocrd_utils/logging.py
+++ b/ocrd_utils/ocrd_utils/logging.py
@@ -37,6 +37,19 @@ _ocrdLevel2pythonLevel = {
     'FATAL': 'ERROR',
 }
 
+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 (numerical) python logging level for (string) spec-defined log level name.
@@ -75,9 +88,6 @@ def getLogger(*args, **kwargs):
     logger = logging.getLogger(*args, **kwargs)
     if _overrideLogLevel is not None:
         logger.setLevel(logging.NOTSET)
-    if logger.handlers:
-        # avoid duplicating messages
-        logger.propagate = False
     return logger
 
 # Default logging config
diff --git a/tests/test_logging.py b/tests/test_logging.py
index 5033c346..fb2e364d 100644
--- a/tests/test_logging.py
+++ b/tests/test_logging.py
@@ -43,6 +43,42 @@ class TestLogging(TestCase):
         self.assertEqual(getLevelName('FATAL'), logging.ERROR)
         self.assertEqual(getLevelName('OFF'), logging.CRITICAL)
 
+    def test_logging_really_non_duplicate(self):
+        child_logger = getLogger('a.b')
+        print(child_logger)
+        parent_logger = getLogger('a')
+        root_logger = getLogger('')
+        self.assertFalse(root_logger.propagate, 'root logger should not propagate')
+        self.assertTrue(parent_logger.propagate, 'parent has no handler => do propagate')
+        self.assertTrue(child_logger.propagate, 'child no handler => do propagate')
+
+        root_capture = FIFOIO(256)
+        root_handler = logging.StreamHandler(root_capture)
+        root_handler.setFormatter(logging.Formatter(fmt=LOG_FORMAT, datefmt=LOG_DATEFMT))
+        root_logger.addHandler(root_handler)
+
+        parent_capture = FIFOIO(256)
+        parent_handler = logging.StreamHandler(parent_capture)
+        parent_handler.setFormatter(logging.Formatter(fmt=LOG_FORMAT, datefmt=LOG_DATEFMT))
+        parent_logger.addHandler(parent_handler)
+
+        # parent_logger = getLogger('a')
+        # self.assertFalse(parent_logger.propagate, 'parent has handler now => do not propagate')
+
+        self.assertTrue(child_logger.propagate, 'child has still no handler => do propagate')
+
+        child_logger.error('test')
+
+        root_str = root_capture.getvalue()
+        parent_str = parent_capture.getvalue()
+
+        self.assertEqual(root_str.count('\\n'), 0)
+        self.assertEqual(parent_str.count('\\n'), 1)
+
+        # root_logger.removeHandler(root_handler) # remove stream handler so we actually see the output
+        # root_logger.info('root_str=%s', root_str)
+        # root_logger.info('parent_str=%s', parent_str)
+
     def test_logging_non_duplicate(self):
         """
         Verify that child loggers don't propagate a log message they handle