Skip to content

Replace use of Python root logger with module-scope loggers

Daniel Tang requested to merge feature/local_scope_logger into gstreamer_python_upgrade

Summary

This MR makes progress towards addressing Issue #10 by configuring our python modules to use loggers scoped and named locally to on a per-file basis.

We use the convenience functions defined in the spiir.logging module found here: https://git.ligo.org/spiir-group/spiir/-/blob/main/src/spiir/logging.py

This should prevent unintended logs from other packages such as matplotlib appearing in our output logging file(originally named "finalsink_debug_log").

In particular, this is relevant for !130 (and possibly !89 (merged)) as they save matplotlib figures as .png files as a visual debug tool.

Context

Currently, postcoh_finalsink.py edits the logging level configuration for all Python logging, and then passes its log messages to that root logger (via use of the logging module object directly). This has the unintended consequence of setting the logging level configuration for all imported modules (such as matplotlib), not just postcoh_finalsink.py.

For example, when a matplotlib plotting function is called, sometimes huge amounts of debug output is logged by matplotlib. Given the legacy implementation of logging in postcoh_finalsink.py, all of this text gets routed into postcoh_finalsink's debug log file output (finalsink_debug_log), polluting the logs with irrelevant lines and making it very difficult to read.

Additional Context

As discussed during internal review, the following comment is worth highlighting.

Click to expand

We definitely should not setup the loggers inside each module of our Python library.

The logging messages that a user wants to receive should be configured by the user themselves (i.e. when they run a script or start an application), either in their entry-point script or with a configuration file. What setup_logger is essentially doing is adding a console handler and file handler to the various library loggers.

To configure output file logs and levels inside the module of your library itself would pre-configure the logs for every user, and that would be bad practice.

See this as an example: https://docs.python-guide.org/writing/logging/#logging-in-a-library

It references a "NullHandler()", but I haven't personally run into a scenario where it's necessary.

See here for more details on NullHandlers below: https://docs.python.org/3/howto/logging.html#library-config

Note: It is strongly advised that you do not log to the root logger in your library. Instead, use a logger with a unique and easily identifiable name, such as the name for your library’s top-level package or module. Logging to the root logger will make it difficult or impossible for the application developer to configure the logging verbosity or handlers of your library as they wish.

The above was exactly what SPIIR was doing before. Sending logs to logging directly is equivalent to using the root logger.

Note: It is strongly advised that you do not add any handlers other than NullHandler to your library’s loggers. This is because the configuration of handlers is the prerogative of the application developer who uses your library. The application developer knows their target audience and what handlers are most appropriate for their application: if you add handlers ‘under the hood’, you might well interfere with their ability to carry out unit tests and deliver logs which suit their requirements.

Merge Strategy

We have made this a separate merge request to be followed immediately after !130 - primarily to keep this as a distinct MR that will hopefully simplify external LIGO review. If a different merge strategy is recommended to expedite review, please feel free to change how commits are merged.

Edited by Daniel Tang

Merge request reports