Tracing & logging

As cotainr is a tools that wraps other tools, e.g. Singularity and Conda, quite a lot of text messages are passed around. In particular, we handle:

• Printed information from cotainr.

• Logging information from cotainr.

• Messages sent to stdout by subprocess, e.g. Singularity or Conda.

• Messages sent to stderr by subprocess, e.g. Singularity or Conda.

All of these have to be filtered, annotated, routed, and displayed on the console and/or written to files.

The cotainr tracing & logging setup handles all of this in a consistent way.

Cotainr logging

Logging in cotainr is handled using the Python standard library logging module. We use the standard convention of creating loggers on a per-module basis, i.e. all modules in cotainr include a logger = logging.getLogger(__name__) line following any imports. Logging is then done using the module logger, e.g. logger.info("Some logged message.").

The cotainr library does not define any logging handlers. This is left for the user of the library. When using the cotainr CLI, though, a set of handlers is defined as outlined in the description of the Cotainr CLI tracing.

Cotainr CLI tracing

When using the cotainr CLI, quite a lot of messages from cotainr and subprocesses needs to filtered, annotated, routed, and displayed on the console and/or written to files to provide the most useful information to the user. This process of providing the most useful information to the user, we refer to as “tracing.” Tracing in cotainr is done using three separate abstractions:

• Forwarding of stdout/stdout from subprocesses

• Processing of log messages

• Adding a console spinner

Forwarding of stdout/stdout from subprocesses

When external programs, e.g. Singularity or Conda, are called in separate subproceses, their output on stdout / stderr is captured and forwarded in real time to the main process. It may then either be directly piped to the main process stdout / stderr or further processed using the setup described in Processing of log messages.

The real time forwarding of stdout / stderr is implemented by the cotainr.util.stream_subprocess() function which is used when running the subprocesses.

Processing of log messages

The Python logging machinery is used for advanced processing of all text messages to be displayed on the console and, optionally, written to a file.

This setup is primarily implemented by two classes cotainr.tracing.LogDispatcher and cotainr.tracing.LogSettings. Each subprocess is linked to a LogDispatcher instance which sets up the logging machinery based on the supplied LogSettings, any filters, and a map_log_level_func function, to:

• Determine the correct log level for loggers and handlers based on verbosity (as described in Cotainr tracing log levels).

• Specify the logging message format based on verbosity.

• Setup StreamHandlers for stdout / stderr.

• Setup FileHandlers for stdout / stderr, if requested.

• Apply any filters to modify and/or remove log messages.

• Add colored console output based on log level, as implemented in cotainr.tracing.ColoredOutputFormatter, if requested.

The LogDispatcher then defines methods log_to_stdout() and log_to_stderr() which may be used with subprocesses to log to stdout / stderr, respectively, at a message log level determined by the provided map_log_level_func function.

In order to take advantage of this machinery, CLI subcommands must:

• Implement the –verbose and –quiet arguments and map them to the verbosity level as described in Cotainr tracing log levels.

• Implement the –log-to-file argument and map it to a log_file_path.

• Implement the –no-color argument.

• Instantiate a LogSettings object and pass it onto any cotainr functionality that may spawn subprocesses.

An example of a subcommand implementing this is cotainr.cli.Build.

Futhermore, cotainr functionality that spawn subprocesses, e.g. cotainr.container.SingularitySandbox or cotainr.pack.CondaInstall must:

• Implement a map_log_level_func function, that (attempts to) infers the correct logging level for a given message.

• Instantiate their own LogDispatcher, which should be passed to cotainr.util.stream_subprocess() when spawning subprocesses.

An example of this is given in cotainr.pack.CondaInstall which implements the static method cotainr.pack.CondaInstall._map_log_level() and instantiates a LogDispatcher in its constructor.

Similarly to the setup done by LogDispatcher for subprocesses, the cotainr.cli.CotainrCLI sets up the cotainr root logger for the main process based on the subcommand LogSettings. This is implemented in the cotainr.cli.CotainrCLI._setup_cotainr_cli_logging() method.

Cotainr tracing log levels

Within cotainr, we map the subcommand –verbose / –quiet flags to a verbosity level, one of the standard Python logging levels (independently for cotainr and LogDispatcher`s), and `--verbose / –quiet levels for subprocesses, e.g. Singularity or Conda. Specifically the mapping is as shown in the below table:

cotainr verbose	cotainr verbosity	cotainr log level	LogDispatcher log level	Singularity verbose	Conda verbose
-q	-1	CRITICAL	CRITICAL	-s	-q
<None>	0	INFO	WARNING	-q	-q
-v	1	INFO	INFO	<None>	<None>
-vv	2	DEBUG	INFO	<None>	-v
-vvv	3	DEBUG	DEBUG	-v	-vv
-vvvv	4	DEBUG	DEBUG	-v	-vvv

The subcommand –verbose / –quiet flags are mapped to a verbosity level as part of the parsing of the CLI arguments, e.g. as in cotainr.CLI.build.add_arguments. Based on the verbosity level,

• the cotainr log level (as used for filtering messages in loggers and handlers) is set in the cotainr.cli.CotainrCLI._setup_cotainr_cli_logging() method.

• the LogDispatcher log level (as used for filtering messages in loggers and handlers) is set as part of its construction, i.e. in cotainr.tracing.LogDispatcher._determine_log_level() method.

• the Singularity –verbose / –quiet flags are injected into Singularity subprocess commands using the cotainr.container.SingularitySandbox._add_verbosity_arg() method.

• the Conda -v / -q flags are appended to Conda subprocess commands using the cotainr.pack.CondaInstall._conda_verbosity_arg() method.

Note the this means that logged messages may be filtered by both the subprocess command (e.g. singularity), the logger used to log the message, and the handler used to emit the message to the console and/or a file.

Adding a console spinner

For a given block of code, a spinner may be added to any console output to stdout / stderr from that code by running it in a cotainr.tracing.ConsoleSpinner context.

The spinner is implemented in the cotainr.tracing.MessageSpinner class which manages a separate thread updating the spinner for each individual message. Within the ConsoleSpinner context, the spinning message is updated by monkey patching sys.stdout.write()/std.stderr.write() with cotainr.tracing.StreamWriteProxy wrappers that make sure to update the spinning message whenever something is written to sys.stdout/sys.stderr.