Fix logging yet again

ocrd/ocrd/cli/log.py

@@ -4,11 +4,10 @@
 import click
 from ocrd_utils import initLogging, getLogger, getLevelName
 
-initLogging()
-
 class LogCtx():
 
     def __init__(self, name):
+        initLogging()
         self.logger = getLogger(name)
 
     def log(self, lvl, *args, **kwargs):

ocrd/ocrd/decorators/__init__.py

@@ -15,7 +15,7 @@
 from ..resolver import Resolver
 from ..processor.base import run_processor
 
-from .loglevel_option import loglevel_option, ocrd_loglevel
+from .loglevel_option import ocrd_loglevel
 from .parameter_option import parameter_option, parameter_override_option
 from .ocrd_cli_options import ocrd_cli_options
 

ocrd_utils/ocrd_utils/__init__.py

@@ -117,11 +117,13 @@
     membername)
 
 from .logging import (
-    logging,
-    getLogger,
+    disableLogging,
     getLevelName,
+    getLogger,
     initLogging,
-    setOverrideLogLevel)
+    logging,
+    setOverrideLogLevel,
+    )
 
 from .os import (
     abspath,

ocrd_utils/ocrd_utils/logging.py

@@ -22,13 +22,15 @@
 from .constants import LOG_FORMAT, LOG_TIMEFMT
 
 __all__ = [
-    'logging',
-    'getLogger',
+    'disableLogging',
     'getLevelName',
+    'getLogger',
     'initLogging',
-    'setOverrideLogLevel'
+    'logging',
+    'setOverrideLogLevel',
 ]
 
+_initialized_flag = False
 _overrideLogLevel = None
 
 _ocrdLevel2pythonLevel = {
@@ -69,14 +71,16 @@ def setOverrideLogLevel(lvl, silent=False):
         lvl (string): Log level name.
         silent (boolean): Whether to log the override call
     """
+    global _initialized_flag # pylint: disable=global-statement
+    global _overrideLogLevel # pylint: disable=global-statement
     if lvl is None:
         return
+    root_logger = logging.getLogger('')
     if not silent:
-        logging.info('Overriding log level globally to %s', lvl)
+        root_logger.info('Overriding log level globally to %s', lvl)
     lvl = getLevelName(lvl)
-    global _overrideLogLevel # pylint: disable=global-statement
     _overrideLogLevel = lvl
-    logging.getLogger('').setLevel(lvl)
+    root_logger.setLevel(lvl)
     for loggerName in logging.Logger.manager.loggerDict:
         logger = logging.Logger.manager.loggerDict[loggerName]
         if isinstance(logger, logging.PlaceHolder):
@@ -88,23 +92,25 @@ def getLogger(*args, **kwargs):
     Wrapper around ``logging.getLogger`` that respects `overrideLogLevel <#setOverrideLogLevel>`_.
     """
     logger = logging.getLogger(*args, **kwargs)
-    if _overrideLogLevel is not None:
+    if _overrideLogLevel:
         logger.setLevel(logging.NOTSET)
+    with open('/tmp/debug.log', 'a') as f:
+        f.write('getLogger(%s) level=%s\n' % (args[0], logger.level))
     return logger
 
 # Default logging config
 
-def initLogging():
+def initLogging(reinit=False):
     """
     Reset root logger, read logging configuration if exists, otherwise use basicConfig
     """
+    global _initialized_flag
+    if _initialized_flag and not reinit:
+        raise Exception("initLogging called multiple times")
 
     for handler in logging.root.handlers[:]:
         logging.root.removeHandler(handler)
 
-    global _overrideLogLevel # pylint: disable=global-statement
-    _overrideLogLevel = None
-
     CONFIG_PATHS = [
         os.path.curdir,
         os.path.join(os.path.expanduser('~')),
@@ -113,6 +119,7 @@ def initLogging():
     for p in CONFIG_PATHS:
         config_file = os.path.join(p, 'ocrd_logging.conf')
         if os.path.exists(config_file):
+            logging.info("Picked up logging config at %s" % config_file)
             logging.config.fileConfig(config_file)
             return
 
@@ -128,6 +135,17 @@ def initLogging():
     # To cut back on the `Self-intersection at or near point` INFO messages
     logging.getLogger('shapely.geos').setLevel(logging.ERROR)
 
+    if _overrideLogLevel:
+        setOverrideLogLevel(_overrideLogLevel)
+
+    _initialized_flag = True
+
+def disableLogging():
+    global _initialized_flag # pylint: disable=global-statement
+    _initialized_flag = False
+    global _overrideLogLevel # pylint: disable=global-statement
+    _overrideLogLevel = None
+    logging.basicConfig(level=logging.CRITICAL)
 
 # Initializing stream handlers at module level
 # would cause message output in all runtime contexts,
@@ -138,4 +156,4 @@ def initLogging():
 # Also, we even have to block log output for libraries
 # (like matplotlib/tensorflow) which set up logging
 # themselves already:
-logging.basicConfig(level=logging.CRITICAL)
+disableLogging()

tests/cli/test_log.py

@@ -1,13 +1,12 @@
 import click
-from click.testing import CliRunner
 from ocrd.cli import log_cli
 from os import environ as ENV
 
 # pylint: disable=import-error, no-name-in-module
 from tests.base import CapturingTestCase as TestCase, main, assets, copy_of_directory
 
 from ocrd.decorators import ocrd_loglevel
-from ocrd_utils import initLogging
+from ocrd_utils import initLogging, setOverrideLogLevel, logging, disableLogging
 
 @click.group()
 @ocrd_loglevel
@@ -17,46 +16,47 @@ def mock_ocrd_cli(log_level):
 
 class TestLogCli(TestCase):
 
-    def setUp(self):
-        self.runner = CliRunner(mix_stderr=False)
-        initLogging()
+    # def setUp(self):
+    #     initLogging()
+    #     setOverrideLogLevel('DEBUG')
 
-    def test_loglevel(self):
-        _, _, err = self.invoke_cli(mock_ocrd_cli, ['log', 'debug', 'foo'])
-        self.assertNotIn(' DEBUG root - foo', err)
-        _, _, err = self.invoke_cli(mock_ocrd_cli, ['-l', 'DEBUG', 'log', 'debug', 'foo'])
-        self.assertIn(' DEBUG root - foo', err)
+    def _get_log_output(self, *args):
+        disableLogging()
+        _, _, err = self.invoke_cli(mock_ocrd_cli, args)
+        return err
 
     def tearDown(self):
         if 'OCRD_TOOL_NAME' in ENV:
             del(ENV['OCRD_TOOL_NAME'])
 
+    def test_loglevel(self):
+        assert ' DEBUG root - foo' not in self._get_log_output('log', 'debug', 'foo')
+        assert ' DEBUG root - foo' in self._get_log_output('-l', 'DEBUG', 'log', 'debug', 'foo')
+
     def test_log_basic(self):
-        exit_code, out, err = self.invoke_cli(log_cli, ['info', 'foo bar'])
-        self.assertIn('INFO root - foo bar', err)
+        assert 'INFO root - foo bar' in self._get_log_output('log', 'info', 'foo bar')
 
     def test_log_name_param(self):
-        exit_code, out, err = self.invoke_cli(log_cli, ['--name', 'boo.far', 'info', 'foo bar'])
-        self.assertIn('INFO boo.far - foo bar', err)
+        assert 'INFO boo.far - foo bar' in self._get_log_output('log', '--name', 'boo.far', 'info', 'foo bar')
 
     def test_log_name_envvar(self):
         ENV['OCRD_TOOL_NAME'] = 'boo.far'
-        exit_code, out, err  = self.invoke_cli(log_cli, ['info', 'foo bar'])
-        self.assertIn('INFO boo.far - foo bar', err)
+        assert 'INFO boo.far - foo bar' in self._get_log_output('log', 'info', 'foo bar')
 
     def test_log_name_levels(self):
         ENV['OCRD_TOOL_NAME'] = 'ocrd.foo'
-        self.assertIn('DEBUG ocrd.foo - foo', self.invoke_cli(mock_ocrd_cli, ['-l', 'DEBUG', 'log', 'debug', 'foo'])[2])
-        self.assertIn('DEBUG ocrd.foo - foo', self.invoke_cli(log_cli, ['trace', 'foo'])[2])
-        self.assertIn('INFO ocrd.foo - foo', self.invoke_cli(log_cli, ['info', 'foo'])[2])
-        self.assertIn('WARNING ocrd.foo - foo', self.invoke_cli(log_cli, ['warning', 'foo'])[2])
-        self.assertIn('ERROR ocrd.foo - foo', self.invoke_cli(log_cli, ['error', 'foo'])[2])
-        self.assertIn('CRITICAL ocrd.foo - foo', self.invoke_cli(log_cli, ['critical', 'foo'])[2])
+        assert 'DEBUG ocrd.foo - foo' in self._get_log_output('-l', 'DEBUG', 'log', 'debug', 'foo')
+        assert 'DEBUG ocrd.foo - foo' in self._get_log_output('-l', 'DEBUG', 'log', 'trace', 'foo')
+        assert 'INFO ocrd.foo - foo' in  self._get_log_output('log', 'info', 'foo')
+        assert 'WARNING ocrd.foo - foo' in  self._get_log_output('log', 'warning', 'foo')
+        assert 'ERROR ocrd.foo - foo' in  self._get_log_output('log', 'error', 'foo')
+        assert 'CRITICAL ocrd.foo - foo' in  self._get_log_output('log', 'critical', 'foo')
 
     def test_log_error(self):
-        code, out, err  = self.invoke_cli(log_cli, ['-n', 'foo',  'info', 'foo bar', 'foo bar'])
-        print('code=%s out=%s err=%s' % (code, out, err))
-        assert 'Logging error' not in err
+        assert 'Logging error' not in self._get_log_output('log', '-n', 'foo',  'info', 'foo bar', 'foo bar')
+
+    def test_log_override(self):
+        assert 'DEBUG' not in self._get_log_output('-l', 'INFO', 'log', 'debug', 'foo')
 
 
 if __name__ == '__main__':

tests/test_logging.py

@@ -10,6 +10,7 @@
     pushd_popd,
     getLevelName,
     setOverrideLogLevel,
+    disableLogging,
     initLogging,
     getLogger,
     LOG_FORMAT,
@@ -22,7 +23,7 @@
 class TestLogging(TestCase):
 
     def setUp(self):
-        initLogging()
+        disableLogging()
 
     def test_setOverrideLogLevel(self):
         rootLogger = logging.getLogger('')
@@ -175,9 +176,9 @@ def test_tmpConfigfile(self):
                         ''')
                 # this will call logging.config.fileConfig with disable_existing_loggers=True,
                 # so the defaults from the import-time initLogging should be invalided
-                initLogging()
+                initLogging(True)
                 # ensure log level is set from temporary config file
                 self.assertEqual(logging.getLogger('').getEffectiveLevel(), logging.ERROR)
 
 if __name__ == '__main__':
-    main()
+    main(__file__)