From 7503fb71b1d3523fb16fcff60b74c245e9574831 Mon Sep 17 00:00:00 2001 From: Konstantin Baierer Date: Wed, 18 Oct 2023 12:46:33 +0200 Subject: [PATCH 1/6] ocrd_logging.conf: attach fileHandlers --- ocrd_utils/ocrd_logging.conf | 14 ++++---------- 1 file changed, 4 insertions(+), 10 deletions(-) diff --git a/ocrd_utils/ocrd_logging.conf b/ocrd_utils/ocrd_logging.conf index 7340ed9d3..8cf1a0fe4 100644 --- a/ocrd_utils/ocrd_logging.conf +++ b/ocrd_utils/ocrd_logging.conf @@ -11,7 +11,7 @@ # each logger requires a corresponding configuration section below # [loggers] -keys=root,ocrd,ocrd_network,ocrd_models,ocrd_tensorflow,ocrd_shapely_geos,ocrd_PIL,uvicorn,uvicorn_access,uvicorn_error +keys=root,ocrd,ocrd_network,ocrd_tensorflow,ocrd_shapely_geos,ocrd_PIL,uvicorn,uvicorn_access,uvicorn_error # # mandatory handlers section @@ -35,7 +35,7 @@ keys=defaultFormatter,detailedFormatter # [logger_root] level=INFO -handlers=consoleHandler +handlers=consoleHandler,fileHandler # @@ -55,15 +55,9 @@ handlers=consoleHandler # ocrd loggers [logger_ocrd] -level=ERROR -handlers=consoleHandler -qualname=ocrd -propagate=0 - -[logger_ocrd_models] level=INFO -handlers=consoleHandler -qualname=ocrd_models +handlers=consoleHandler,fileHandler +qualname=ocrd propagate=0 [logger_ocrd_network] From 00915b69e270728419bb2de7324171a8394fb50a Mon Sep 17 00:00:00 2001 From: Konstantin Baierer Date: Wed, 18 Oct 2023 13:07:02 +0200 Subject: [PATCH 2/6] logging tests: run decorator test with logging conf file --- Makefile | 2 +- tests/base.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/Makefile b/Makefile index 30771ef84..f0ff387b2 100644 --- a/Makefile +++ b/Makefile @@ -200,7 +200,7 @@ test: assets -m pytest $(PYTEST_ARGS) --durations=10\ --ignore-glob="$(TESTDIR)/**/*bench*.py" \ $(TESTDIR) - cd ocrd_utils ; $(PYTHON) -m pytest --continue-on-collection-errors -k TestLogging $(TESTDIR) + cd ocrd_utils ; $(PYTHON) -m pytest --continue-on-collection-errors -k TestLogging -k TestDecorators $(TESTDIR) benchmark: $(PYTHON) -m pytest $(TESTDIR)/model/test_ocrd_mets_bench.py diff --git a/tests/base.py b/tests/base.py index 70f66a599..53f393e08 100644 --- a/tests/base.py +++ b/tests/base.py @@ -27,7 +27,7 @@ class TestCase(VanillaTestCase): def setUp(self): chdir(dirname(realpath(__file__)) + '/..') disableLogging() - initLogging() + initLogging(builtin_only=True) class CapturingTestCase(TestCase): """ From ed33ac69b4fd3c6ffd7033245ab2ff37f6d80b16 Mon Sep 17 00:00:00 2001 From: Konstantin Baierer Date: Wed, 18 Oct 2023 13:08:08 +0200 Subject: [PATCH 3/6] logging config: set log level to DEBUG, use defaultFormatter for fileHandler --- ocrd_utils/ocrd_logging.conf | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/ocrd_utils/ocrd_logging.conf b/ocrd_utils/ocrd_logging.conf index 8cf1a0fe4..84cd41cb5 100644 --- a/ocrd_utils/ocrd_logging.conf +++ b/ocrd_utils/ocrd_logging.conf @@ -34,7 +34,7 @@ keys=defaultFormatter,detailedFormatter # default logger "root" using consoleHandler # [logger_root] -level=INFO +level=DEBUG handlers=consoleHandler,fileHandler @@ -55,7 +55,7 @@ handlers=consoleHandler,fileHandler # ocrd loggers [logger_ocrd] -level=INFO +level=DEBUG handlers=consoleHandler,fileHandler qualname=ocrd propagate=0 @@ -123,7 +123,7 @@ args=(sys.stderr,) # [handler_fileHandler] class=FileHandler -formatter=detailedFormatter +formatter=defaultFormatter args=('ocrd.log','a+') [handler_processingServerHandler] From d1995a3c862f6e44e508621be2476b9a7f62d704 Mon Sep 17 00:00:00 2001 From: Konstantin Baierer Date: Tue, 19 Sep 2023 16:44:32 +0200 Subject: [PATCH 4/6] With OCRD_LOGGING_DEBUG=1, print debug info on logging itself to STDERR Also warn if multiple config files are found --- ocrd_utils/ocrd_utils/config.py | 6 ++++++ ocrd_utils/ocrd_utils/logging.py | 33 +++++++++++++++++++------------- tests/test_logging_conf.py | 2 +- 3 files changed, 27 insertions(+), 14 deletions(-) diff --git a/ocrd_utils/ocrd_utils/config.py b/ocrd_utils/ocrd_utils/config.py index b6f8b8daa..7b4538223 100644 --- a/ocrd_utils/ocrd_utils/config.py +++ b/ocrd_utils/ocrd_utils/config.py @@ -184,3 +184,9 @@ def _ocrd_download_timeout_parser(val): config.add("XDG_CONFIG_HOME", description="Directory to look for `./ocrd-resources/*` (i.e. `ocrd resmgr` data location)", default=(True, lambda: Path(config.HOME, '.config'))) + +config.add("OCRD_LOGGING_DEBUG", + description="Print information about the logging setup to STDERR", + default=(True, False), + validator=lambda val: isinstance(val, bool) or val in ('true', 'false', '0', '1'), + parser=lambda val: val in ('true', '1')) diff --git a/ocrd_utils/ocrd_utils/logging.py b/ocrd_utils/ocrd_utils/logging.py index 038b6a6c5..03fa9a5c5 100644 --- a/ocrd_utils/ocrd_utils/logging.py +++ b/ocrd_utils/ocrd_utils/logging.py @@ -36,6 +36,8 @@ import sys from .constants import LOG_FORMAT, LOG_TIMEFMT +from .config import config + __all__ = [ 'disableLogging', @@ -104,7 +106,7 @@ def getLogger(*args, **kwargs): logger = logging.getLogger(*args, **kwargs) return logger -def setOverrideLogLevel(lvl, silent=True): +def setOverrideLogLevel(lvl, silent=not config.OCRD_LOGGING_DEBUG): """ Override the output log level of the handlers attached to the ``ocrd`` logger. @@ -113,19 +115,19 @@ def setOverrideLogLevel(lvl, silent=True): silent (boolean): Whether to log the override call """ if not _initialized_flag: - initLogging() + initLogging(silent=silent) ocrd_logger = logging.getLogger('ocrd') if lvl is None: if not silent: - ocrd_logger.info('Reset log level override') + print('[LOGGING] Reset log level override', file=sys.stderr) ocrd_logger.setLevel(logging.NOTSET) else: if not silent: - ocrd_logger.info('Overriding ocrd log level to %s', lvl) + print(f'[LOGGING] Overriding ocrd log level to {lvl}', file=sys.stderr) ocrd_logger.setLevel(lvl) -def initLogging(builtin_only=False, force_reinit=False): +def initLogging(builtin_only=False, force_reinit=False, silent=not config.OCRD_LOGGING_DEBUG): """ Reset ``ocrd`` logger, read logging configuration if exists, otherwise use basicConfig @@ -141,6 +143,7 @@ def initLogging(builtin_only=False, force_reinit=False): hard-coded config (``True``). For testing - force_reinit (bool, False): Whether to ignore the module-level ``_initialized_flag``. For testing only. + - silent (bool, True): Whether to log logging behavior by printing to stderr """ global _initialized_flag if _initialized_flag and not force_reinit: @@ -165,14 +168,19 @@ def initLogging(builtin_only=False, force_reinit=False): Path.home(), Path('/etc'), ] - config_file = next((f for f \ + config_file = [f for f \ in [p / 'ocrd_logging.conf' for p in CONFIG_PATHS] \ - if f.exists()), - None) + if f.exists()] if config_file: + if len(config_file) > 1 and not silent: + print(f"[LOGGING] Multiple logging configuration files found at {config_file}, using first one", file=sys.stderr) + config_file = config_file[0] + if not silent: + print(f"[LOGGING] Picked up logging config at {config_file}", file=sys.stderr) logging.config.fileConfig(config_file) - logging.getLogger('ocrd.logging').debug("Picked up logging config at %s", config_file) else: + if not silent: + print("[LOGGING] Initializing logging with built-in defaults", file=sys.stderr) # Default logging config ocrd_handler = logging.StreamHandler(stream=sys.stderr) ocrd_handler.setFormatter(logging.Formatter(fmt=LOG_FORMAT, datefmt=LOG_TIMEFMT)) @@ -181,19 +189,18 @@ def initLogging(builtin_only=False, force_reinit=False): logging.getLogger(logger_name).addHandler(ocrd_handler) for logger_name, logger_level in LOGGING_DEFAULTS.items(): logging.getLogger(logger_name).setLevel(logger_level) - _initialized_flag = True -def disableLogging(silent=True): +def disableLogging(silent=not config.OCRD_LOGGING_DEBUG): """ Disables all logging of the ``ocrd`` logger and descendants Keyword Args: - silent (bool, True): Whether to log the call to disableLogging + - silent (bool, True): Whether to log logging behavior by printing to stderr """ global _initialized_flag # pylint: disable=global-statement if _initialized_flag and not silent: - logging.getLogger('ocrd.logging').debug("Disabling logging") + print("[LOGGING] Disabling logging", file=sys.stderr) _initialized_flag = False # logging.basicConfig(level=logging.CRITICAL) # logging.disable(logging.ERROR) diff --git a/tests/test_logging_conf.py b/tests/test_logging_conf.py index 311eec327..1bfe742b7 100644 --- a/tests/test_logging_conf.py +++ b/tests/test_logging_conf.py @@ -18,7 +18,7 @@ from tests.base import main -sys.path.append(os.path.dirname(os.path.realpath(__file__)) + '/../ocrd') +# sys.path.append(os.path.dirname(os.path.realpath(__file__)) + '/../ocrd') TEST_ROOT = pathlib.Path(os.path.dirname(os.path.abspath(__file__))).parent def resetLogging(): From c7063ec21bef41dc1eb618844b46f14e88709d6f Mon Sep 17 00:00:00 2001 From: Konstantin Baierer Date: Wed, 18 Oct 2023 13:57:13 +0200 Subject: [PATCH 5/6] add OCRD_LOGGING_DEBUG to ocrd --help --- ocrd/ocrd/cli/__init__.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/ocrd/ocrd/cli/__init__.py b/ocrd/ocrd/cli/__init__.py index 52e6397b5..97cff1db7 100644 --- a/ocrd/ocrd/cli/__init__.py +++ b/ocrd/ocrd/cli/__init__.py @@ -52,6 +52,8 @@ {config.describe('OCRD_NETWORK_SOCKETS_ROOT_DIR')} \b {config.describe('OCRD_NETWORK_LOGS_ROOT_DIR')} +\b +{config.describe('OCRD_LOGGING_DEBUG')} """ def command_with_replaced_help(*replacements): From e2b0b632238d8e9376eb76c9b482c13f57f34f52 Mon Sep 17 00:00:00 2001 From: Konstantin Baierer Date: Wed, 18 Oct 2023 14:48:54 +0200 Subject: [PATCH 6/6] logging multipart messages only INFO and up --- ocrd_utils/ocrd_logging.conf | 6 +++++- ocrd_utils/ocrd_utils/logging.py | 3 ++- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/ocrd_utils/ocrd_logging.conf b/ocrd_utils/ocrd_logging.conf index 84cd41cb5..3595d64cc 100644 --- a/ocrd_utils/ocrd_logging.conf +++ b/ocrd_utils/ocrd_logging.conf @@ -11,7 +11,7 @@ # each logger requires a corresponding configuration section below # [loggers] -keys=root,ocrd,ocrd_network,ocrd_tensorflow,ocrd_shapely_geos,ocrd_PIL,uvicorn,uvicorn_access,uvicorn_error +keys=root,ocrd,ocrd_network,ocrd_tensorflow,ocrd_shapely_geos,ocrd_PIL,uvicorn,uvicorn_access,uvicorn_error,multipart # # mandatory handlers section @@ -106,6 +106,10 @@ qualname=uvicorn.access level=DEBUG handlers=consoleHandler qualname=uvicorn.error +[logger_multipart] +level=INFO +handlers=consoleHandler +qualname=multipart diff --git a/ocrd_utils/ocrd_utils/logging.py b/ocrd_utils/ocrd_utils/logging.py index 03fa9a5c5..109802f52 100644 --- a/ocrd_utils/ocrd_utils/logging.py +++ b/ocrd_utils/ocrd_utils/logging.py @@ -67,7 +67,8 @@ 'paramiko.transport': logging.INFO, 'uvicorn.access': logging.DEBUG, 'uvicorn.error': logging.DEBUG, - 'uvicorn': logging.INFO + 'uvicorn': logging.INFO, + 'multipart': logging.INFO, } _initialized_flag = False