CLI log-level ignored if config file is present

[bertsky]

It seems we were not thorough enough in #599: Currently --log-level has no effect when some ~/ocrd_logging.conf is present.

IIUC this is because ocrd_utils.logging.initLogging comes after setOverrideLoglevel (so all its logger setLevels get wiped out and only global _overrideLogLevel survives), but logging.config.fileConfig of course does not honour ocrd_utils.logging.getLogger's _overrideLogLevel.

[M3ssman]

I'm totally aware of stuff like this is hard to catch, but I really like to see a test-fixture setup for this situation that can be integrated into test_logging.py even as a sort of regression test and, as first step, to reproduce the mentioned behavior.

[kba]

It seems we were not thorough enough in #599: Currently --log-level has no effect when some ~/ocrd_logging.conf is present.

How can I reproduce this?

cp $OCRD/ocrd_utils/ocrd_logging.conf .
ocrd -l DEBUG log debug yay

does log the debug message.

ocrd -l ERROR log error foo

does NOT log, as is expected.

I'm trying to make sure that #628 fixes the issue. probably unrelated (#590)

[bertsky]

How can I reproduce this?

cp $OCRD/ocrd_utils/ocrd_logging.conf .
ocrd -l DEBUG log debug yay

does log the debug message.

ocrd -l ERROR log error foo

Not sure about ocrd log, but a real processor should show the pattern.

[kba]

I've tried with ocrd-dummy:

cp ocrd_utils/ocrd_logging.conf .
ocrd-dummy -l ERROR -I FOO -O BAR

logs nothing as expected

ocrd-dummy -l TRACE -I FOO -O BAR
17:44:08.253 DEBUG ocrd.resolver.workspace_from_url - Deriving dst_dir /home/kba/build/github.com/OCR-D/monorepo/ocrd_all/core from /home/kba/build/github.com/OCR-D/monorepo/ocrd_all/core/mets.xml
17:44:08.255 DEBUG ocrd.resolver.workspace_from_url - workspace_from_url
...

I tried it with olahd-client as well, same result. What am I doing wrong here?

[bertsky]

It's sufficient to have any loggers in your config besides the root logger. For example,

[logger_ocrd]
level=INFO
handlers=consoleHandler
qualname=ocrd

already prevents ocrd-dummy output, as well as ocrd -l DEBUG log -n ocrd.test debug naye

[M3ssman]

@bertsky Yep, this works since qualname corresponds to the hierarchical channel name of the loggers, i.e. ocrdwill match any logger starting with ocrd. as in ocrd.cli, ocrd.cli.workspace and so forth and also ocrd.dummy.

[bertsky]

@M3ssman sufficient to see the bug of not honouring the CLI override!

[M3ssman]

Actually, the logging module by itself behaves as expected even if the config file is present:

def test_config_file_present_set_loglevel(logging_conf, capsys):
    """Ensure logLevel can be changed if config file present"""

    # arrange
    os.chdir(logging_conf)
    initLogging()
    test_logger = getLogger('')

    # act and assert
    assert test_logger.level == 20
    test_logger.debug("debug output")
    log_debug_output = capsys.readouterr().out
    assert not log_debug_output
    test_logger.info("some info")
    log_info_output = capsys.readouterr().out
    assert log_info_output

    setOverrideLogLevel('ERROR', silent=True)
    test_logger.info("info outout")
    log_info_output = capsys.readouterr().out
    assert not log_info_output
    test_logger.error("some errs")
    log_error_output = capsys.readouterr().out
    assert log_error_output

    assert test_logger.level != 20
    assert test_logger.level == 40

What is the transformation from _ocrdLevel2pythonLevel good for? It confuses me somehow with mapping TRACEto DEBUG ...

[kba]

Maybe I'm just really slow today but I still cannot reproduce this

[loggers]
keys=root

[handler_consoleHandler]
class=StreamHandler
formatter=defaultFormatter
args=(sys.stdout,)

[handlers]
keys=consoleHandler

[formatters]
keys=defaultFormatter

[formatter_defaultFormatter]
format=%(asctime)s.%(msecs)03d %(levelname)s %(name)s - %(message)s
datefmt=%H:%M:%S

[logger_root]
level=INFO
handlers=consoleHandler

[logger_ocrd]
level=ERROR
handlers=consoleHandler
qualname=ocrd

ocrd -l DEBUG log -n ocrd.test debug naye
12:09:37.873 DEBUG ocrd.test - naye

ocrd-dummy -l DEBUG -I FOO -O BAR                                                                                                                                        
12:10:15.102 DEBUG ocrd.resolver.workspace_from_url - Deriving dst_dir /home/kba/build/github.com/OCR-D/monorepo/ocrd_all/core from /home/kba/build/github.com/OCR-D/monorepo
/ocrd_all/core/mets.xml      

😕

[kba]

What is the transformation from _ocrdLevel2pythonLevel good for? It confuses me somehow with mapping TRACEto DEBUG ...

The logging spec was initially based on log4j conventions IIRC, hence the additional TRACE which should be below DEBUG. Not easy to get rid of some details like that because we don't want to break people's scripts.

[bertsky]

@M3ssman

Actually, the logging module by itself behaves as expected even if the config file is present:

Your test is not realistic though. On the CLI, the decorator for --log-level kicks in before initLogging – see above.

@kba

[loggers]
keys=root

Your are missing keys=root,ocrd to arm that additional logger!

[M3ssman]

@bertsky Sounds like tests/test_decorators.py is the place where this test should reside

[bertsky]

Sounds like tests/test_decorators.py is the place where this test should reside

Yes, there's a test_loglevel_override already, but it needs to be run in the presence of a logging config in the FS, too. Better both ways...