Logger names are not intuitive

[llucax]

What's needed?

We sometimes want to configure some loggers differently (for example to print debug messages), but it is not easy at all to figure out which logger should be configured when some high-level module is composed of other private modules that the user is never supposed to import directly, and __name__ is used as logger name, which maps to the fully qualified module name.

For example, the timeseries module have these debug log messages:

src/frequenz/sdk/timeseries/_grid_frequency.py:        _logger.debug("Sent request for grid frequency: %s", self._source_component)
src/frequenz/sdk/timeseries/_moving_window.py:            _logger.debug("Returning value at index %s ", key)
src/frequenz/sdk/timeseries/_moving_window.py:                _logger.debug("Received new sample: %s", sample)
src/frequenz/sdk/timeseries/_periodic_feature_extractor.py:        _logger.debug("Initializing PeriodicFeatureExtractor!")

If someone configures the logger frequenz.sdk.timeseries to print debug logs, they won't actually see any logs. In these cases, the users have basically no reliable way to know which loggers they should configure.

Proposed solution

Option 1

Use always the high-level module name as logger name. We could use a convention, for example, to have a _logger.py module that instantiates and exposes the global logger for that high-level module, and then all the internal sub-modules will just import that logger.

To follow the example, we would have a src/frequenz/sdk/timeseries/_logger.py module like:

import logging

logger = logging.getLogger(__name__[:__name__.rindex('.')])

And then in, for example, src/frequenz/sdk/timeseries/_moving_window.py:

from ._logger import logger

# ...
            _logger.debug("Returning value at index %s ", key)

Option 2

Add some utility function to the SDK (or probably better core) to get the logger ignoring the private modules, like logger = get_public_logger(__name__):

import logging

def get_public_logger(module_name):
    parts = module_name.split('.')
    public_parts = []
    for part in parts:
        if part.startswith('_'):
            break
        public_parts.append(part)
    return logging.getLogger('.'.join(public_parts))

[llucax]

I think option 1 doesn't make much sense, it is just I came up with that one before coming up with option 2, so I left it, but I think we should go with option 2.

[llucax]

OK, created:

• https://github.com/frequenz-floss/frequenz-core-python/pull/23

This issue should be solved when this is released and the SDK starts using it, so marking as blocked for now.

[llucax]

We figured that if we go for option 2 we still have an issue with having big modules, as enabling logging for one module might end up being too verbose, as it will enable logging for a lot of stuff.

One way to cope with this would be to add the function/class name to the logger name, so we are still following the public interface naming but we get much more fine-grained loggers.

So, get_public_logger() can have an optional second parameter to get the symbol name:

For example, in src/frequenz/sdk/timeseries/_periodic_feature_extractor.py we would do something like:

class PeriodicFeatureExtractor:
    def __init__(self, ...) -> None:
        self._logger = get_public_logger(__name__, self)
        self._logger.debug("Initializing PeriodicFeatureExtractor!")

This will give us a logger named: frequenz.sdk.timeseries.PeriodicFeatureExtractor.

The only problem with this approach is we can still end up with logger names that are not publicly available, as not every class or function in a private module gets exported, but it might take out some of the weirdness in logger names.

[llucax]

Thinking a bit more about this, since loggers are hierarchical, actually having logger names that are more nested than the public interface is not such a big deal. For example, if we enable logging for frequenz.sdk.timeseries, then we'll get the logs for all internal modules too, effectively being the same as using get_public_logger(), with the advantage of, once you already saw a weird nested logger name, you can still configure it either to disable it (to reduce noise) or to only enable the nested logger with a weird name.

Given the simplicity of just using _logger = logging.getLogger(__name__) I think we should live it like it is, it is much more work to get and store a logger on each class/function, just to have less cryptic logger names.

[llucax]

Closing as invalid because of the above comment.