Logger¶
CoSApp defines its own logger handler on top of Python logging package. The reason behind the definition of customized handlers is to invert the logging logic for fine debugging. Meaning, instead of having log message built by CoSApp objects at all times and then filter by the logging system depending on the log level, for debug level, the log handler will request CoSApp objects to provide more information. This allows to reduce the execution overhead of producing debug messages when it is not required.
First, the log message flow will be described (the figures below are reproduced from Logger flow).
As seen in the flow graph below, when the code is calling the logger to emit a message, first the logger
test if the message should be considered depending on its level. Then if it does, a LogRecord
object
is instantiated and logger filters are applied on it. And only then, is the record pass to the handlers.
Finally the flow is looping over the logger hierarchy.
For each handler, specific debug level and filters can be defined. So the record is again tested against those selection criteria. And if those criteria are respected the record is emitted on the proper support.
To extend the logging Python system, the easiest method is to create filters and handlers. Both can then be added to loggers - in particular to the root logger to catch all messages.
The other need is to get the active CoSApp context to let the handler know that it can request additional information.
This is done by passing the CoSApp object as extra attribute of a LogRecord
(see log_context()
).
Thanks to the context manager log_context()
, you can in CoSApp code activate
for a method execution the context. For example, in cosapp.core.module.Module.call_setup_run()
:
To use it, the CoSApp class needs to inherit from LoggerContext
(this is the case of
Module
and therefore of Driver
and System
).
Then the convention used is to pass a string with the calling method. When entering and exiting the context manager,
the method log_debug_message
of the context object will be called (if the log level is DEBUG
or lower).
As a consequence to provide more information, that method needs to be overridden in the CoSApp object to be meaningful.
For example, in System
.
log_debug_message()
,
no additional information is displayed for call_setup_run
and call_clean_run
. But for run_once
or run_driver
,
the inputs are displayed at the entering of the log context and the outputs at its exit.
Note
As log_debug_message
is called by the handler, additional information should be logged directly on it. So the handler
is an argument of log_debug_message
. And logging a message can be done using the helper log()
.
A drawback of the current approach is that log_debug_message
will be called by all handlers.
The other advantage to pass the context to the handler allows to pass it to the filters. This is used by TimeFilter
and ContextFilter
. The first one needs the context to see if its time is valid when the second
filters the context itself.
Note
As the context is only propagated when the log level is lower or equal to DEBUG
, those two filters
are accepting any log message of higher level than DEBUG
.
To clarify the above description, two sequence diagrams are shown next. The first one displays what happen when the log level is
greater than DEBUG
(e.g. INFO
).
At the entering and exiting log_context()
,
the log message carrying the context will never reach the handler. Therefore additional
information won’t be requested.
Then the case of a System simulation with FULL_DEBUG
is presented.