Harmonize loggers

[kba]

This is a colophon to #1080

• changing the logger names - all OCR-D/core logging except for ocrd_network now are derived from the ocrd logger
• making the logger names in ocrd_network explicit
• removing the custom logging code in ocrd_network and porting the defaults to the config file and ocrd_utils.logging resp.
• simplifying the naming in the logging configuration file and removing now unrequired logger configs

Unfortunately, there is a heisenbug for (ironically) test_log_error in tests/cli/test_log.py. Error goes away when replacing the StreamHandler of consoleHandler with a FileHandler in the logging configuration - which isn't even used in that test. I tried git bisecting through the changes, but it only appears in the commit 660b468. If anybody (@M3ssman perhaps?) has an idea, pls let me know.

[M3ssman]

@kba Sorry, can't reproduce.
Checked out latest commit (8f05b0d7) in a fresh Python3.8 venv on Ubuntu 20.04, I've got exactly the same 6 Failures listed on the Github Action for Python 3.8 actually:

FAILED tests/test_logging.py::TestLogging::test_loglevel_inheritance
FAILED tests/test_logging.py::TestLogging::test_tmpConfigfile
FAILED tests/test_logging_conf.py::test_configured_dateformat
FAILED tests/test_logging_conf.py::test_configured_tensorflow_logger_present
FAILED tests/test_logging_conf.py::test_configured_shapely_logger_present
FAILED tests/processor/test_processor.py::TestProcessor::test_zip_input_files_require_first 

But I didn't recognize anything related to the logging handling ...

[MehmedGIT]

@kba, I cannot reproduce the bug as well. Getting the same errors above. Could you share the logging configuration file you are using?

[kba]

The last commit was just a frantic try to fix before the weekend, I'll force-push that out of the PR. The relevant error message is for commit 660b468 (https://app.circleci.com/pipelines/github/OCR-D/core/2010/workflows/d45d734f-7a79-46ed-9c60-acb69d9e8881/jobs/8208)

[kba]

And it's a heisenbug because it only happens when the full test suite is run, running the logging test in isolation doesn't raise the error.

[M3ssman]

Well if it always happens if full suite is run, it shall be reproducible and therefore can't be considered to be a Heisenbug 🙂

I do faintly remember similar phenomenons once upon a time when there were serious attempts made to re-write the whole testing suites with pytest only 🧐

Tried to update to 660b4680, first run make test which yields FAILED tests/cli/test_log.py::TestLogCli::test_log_error - assert 'Logging error' not in '16:54:12.45...uments: ()\n' , like @kba already said. Strange, if I run just pytest -k test_log , then I get some more failures (3 failed, 13 passed, 2 skipped, 439 deselected in 1.76s) :

FAILED tests/test_logging.py::TestLogging::test_loglevel_inheritance - assert 10 == 20
FAILED tests/test_logging.py::TestLogging::test_tmpConfigfile - AssertionError: 10 != 40
FAILED tests/cli/test_log.py::TestLogCli::test_log_error - assert 'Logging error' not in '16:55:51.13...uments: ()\n'

Something like this shouldn't happen of course. Obviously there must some strange dependencies be hidden, concerning tests doing changes to the environment or alike. A quick look into disableLogging tells there is this global thing _initialized_flag inside, which will be turned each time a test/script/module does something just like loading the logging module.

Probably one should investigate further the top of the failure message:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/__init__.py", line 1088, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/bin/pytest", line 8, in <module>
    sys.exit(console_main())

...
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/lib/python3.8/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/lib/python3.8/site-packages/ocrd/cli/log.py", line 47, in _log_wrapper
    ctx.log(lvl.upper(), msg)
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/lib/python3.8/site-packages/ocrd/cli/log.py", line 19, in log
    logger.log(getLevelName(lvl), *args, **kwargs)
Message: 'foo bar foo bar'
Arguments: ()

Why is this closed?
Probably by some other test?

[kba]

Well if it always happens if full suite is run, it shall be reproducible and therefore can't be considered to be a Heisenbug 🙂

Heisenbug in the sense that there is some weird entanglement/mysterious action at a distance with the other tests ;)

I do faintly remember similar phenomenons once upon a time when there were serious attempts made to re-write the whole testing suites with pytest only 🧐

Tried to update to 660b4680, first run make test which yields FAILED tests/cli/test_log.py::TestLogCli::test_log_error - assert 'Logging error' not in '16:54:12.45...uments: ()\n' , like @kba already said. Strange, if I run just pytest -k test_log , then I get some more failures (3 failed, 13 passed, 2 skipped, 439 deselected in 1.76s) :

FAILED tests/test_logging.py::TestLogging::test_loglevel_inheritance - assert 10 == 20
FAILED tests/test_logging.py::TestLogging::test_tmpConfigfile - AssertionError: 10 != 40
FAILED tests/cli/test_log.py::TestLogCli::test_log_error - assert 'Logging error' not in '16:55:51.13...uments: ()\n'

Something like this shouldn't happen of course. Obviously there must some strange dependencies be hidden, concerning tests doing changes to the environment or alike. A quick look into disableLogging tells there is this global thing _initialized_flag inside, which will be turned each time a test/script/module does something just like loading the logging module.

The module is only loaded once, that is not the issue here.

Probably one should investigate further the top of the failure message:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/__init__.py", line 1088, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/bin/pytest", line 8, in <module>
    sys.exit(console_main())

...
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/lib/python3.8/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/lib/python3.8/site-packages/ocrd/cli/log.py", line 47, in _log_wrapper
    ctx.log(lvl.upper(), msg)
  File "/home/hartwig/Projekte/github-ocr-d-core/venv/lib/python3.8/site-packages/ocrd/cli/log.py", line 19, in log
    logger.log(getLevelName(lvl), *args, **kwargs)
Message: 'foo bar foo bar'
Arguments: ()

Why is this closed? Probably by some other test?

Yes, but I don't know why or at what point.

I suspect this has to do with the logging handlers. They are added to the root handler, e.g.

log_capture_string = FIFOIO(256)                   
ch = logging.StreamHandler(log_capture_string)     
ch.setFormatter(logging.Formatter(LOG_FORMAT))     
getLogger('ocrd.process.profile').setLevel('DEBUG')
getLogger('ocrd.process.profile').addHandler(ch)   

but not removed.

And in the initLogging we do now only set a ConsoleHandler for the ocrd logger, not the root logger.

But honestly, I am stumped right now, this is just very confusing behavior. I'll investigate the root handler idea further tomorrow...

[kba]

OK, I gave up (for now) and reduced the changes to just aligning logging in ocrd_network and the rest of the software and renaming loggers to simplify configuration.

I've kept the work-in-progress in https://github.com/OCR-D/core/tree/harmnize-loggers-WIP to be revisited once the more pressing issues are out of the way. The problems are based around pytest capturing stdout/stderr, click capturing stdout/stderr, pytest adding log handlers to the root logger, us adding log handlers, streams being closed and reopened at various places and the order of tests...