Add propagate=False opt to basic_logger()

[taldcroft]

Description

This adds a keyword argument propagate=False to the logging.basic_logger() signature. The returned logger has propagate set to the input value.

Interface impacts

This changes the behavior of basic_logger, but in a way that is likely expected anyway. I checked all current uses of basic_logger in Ska and none of them would expect to propagate messages to a root or parent logger.

@javierggt - you should double-check astromon though.

Testing

Unit tests

• Mac

Independent check of unit tests by Jean

• Linux

Functional tests

From this branch in the git repo:

$ ipython
Python 3.10.8 | packaged by conda-forge | (main, Nov 22 2022, 08:27:35) [Clang 14.0.6 ]
Type 'copyright', 'credits' or 'license' for more information
IPython 8.8.0 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import annie
WARNING: AstropyDeprecationWarning: http://bugs.python.org/issue12166 is resolved. See docstring for alternatives. [chandra_aca.aca_image]
AstropyDeprecationWarning: http://bugs.python.org/issue12166 is resolved. See docstring for alternatives.

In [2]: import cheta

Previously the annie and cheta imports generated debug information from get_version() calls due to annie creating a root logger on import. This was because get_version() uses logging to catch debug information in an io.String() object, and all of those messages then get passed up to the parent where they get emitted regardless of the parent log level. (The annie root logger is at CRITICAL, but only the level of the handlers (NOTSET) is evaluated).

[taldcroft]

@javierggt - this PR is critical for ska3-prime.

xija_gui_fit also creates a root logger and ends up spewing all the debug info.

[javierggt]

I can confirm that using this branch, I do not get the log messages from ska_helpers.version.

I'm trying to understand what should be the behavior other than that. The PR does not say, and whenever we discuss logging, @taldcroft and I have different expectations.

For example, I would expect that the following code

import logging
logging.warning('Warning!')
import ska_helpers.logging
logger = ska_helpers.logging.basic_logger('test', level='CRITICAL', propagate=False, format='Aaargh! %(message)s')
logger.warning('this should not happen, dude!')

should give the following output:

WARNING:root:Warning!

but this is the actual output:

WARNING:root:Warning!
WARNING:test:this should not happen, dude!

[taldcroft]

@javierggt - good catch, this script now gives the expected output:

import logging
logging.basicConfig(level=logging.INFO)
logging.warning('Warning from root logger!')

import ska_helpers.logging
logger = ska_helpers.logging.basic_logger('test', level='CRITICAL', format='Aaargh! %(message)s')
logger.warning('WARNING dude!')
logger.critical('CRITICAL dude!')

Output:

WARNING:root:Warning from root logger!
Aaargh! CRITICAL dude!

[jeanconn]

As logging surprises us every day, what would make sense for ska_helpers tests for basic_logger? Just tossing it out there. Not a lien on this PR.

[taldcroft]

Good question @jeanconn but I've already spent too much time on this. Maybe another day.

[javierggt]

For the record, there is a pytest fixture to do exactly that (https://docs.pytest.org/en/7.1.x/how-to/logging.html)

So a test can be something like (from their docs):

def test_foo(caplog):
    logging.getLogger().info("boo %s", "arg")

    assert caplog.record_tuples == [("root", logging.INFO, "boo arg")]