Logging¶
Logging is one of the first useful means that help investigating on test executions. That’s the reason why a particular attention is paid to providing efficient logging facilities.
For the purpose, the scenario framework makes use and extends the standard logging library.
Log levels¶
As the system logging module proposes it, log levels are defined by int values.
The ERROR, WARNING, INFO and DEBUG log levels are mostly to be considered.
ERROR, WARNING and INFO log records are always displayed. DEBUG log records may be displayed or not, depending on the context (see main logger and class loggers below).
Log levels are displayed within the log lines (usually after the date/time). They are also commonly emphased with colors in the console, in order to facilitate hot analyses.
Date / time¶
When analyzing test logs, the timing question is usually essential.
Log date/time is displayed by default at the beginning of the log lines,
with a ISO8601 pattern: YYYY-MM-DDTHH:MM:SS.mmmuuu+HH:MM.
It may disabled through the scenario.log_date_time configuration value.
Main logger¶
The scenario framework defines a main logger.
It uses a regular logging.Logger instance with 'scenario' for name [1].
It is accessible through the scenario.logging variable.
Debugging is enabled by default with this main logger.
def step010(self):
self.STEP("Logging with the main logger")
if self.ACTION("Log messages of different log levels with the main logger."):
scenario.logging.error("This is an error!!!")
scenario.logging.warning("This is a warning!")
scenario.logging.info("This is information.")
scenario.logging.debug("This is debug.")
STEP#1: Logging with the main logger (demo/loggingdemo.py:22:LoggingScenario.step010)
------------------------------------------------
ACTION: Log messages of different log levels with the main logger.
ERROR This is an error!!!
WARNING This is a warning!
INFO This is information.
DEBUG This is debug.
Implementation details
The main logger carries the logging.Handler instances.
It ownes up to two handlers:
A first one for the console output, always set.
A second one, optional, for file logging when applicable (see file logging).
Class loggers¶
Class loggers make it possible to classify sets of log lines with a given subject: the log class. The log class is displayed within the log lines, between square brackets, and furthermore makes it possible to enable or disable debug log lines for it.
A Logger instance may be created directly.
_logger = scenario.Logger("My logger")
But a common pattern is to inherit from Logger,
either directly (see test libraries) or through an intermediate class.
A couple of scenario classes inherit from the Logger class,
among others:
class LoggingScenario(scenario.Scenario):
def __init__(self):
scenario.Scenario.__init__(self)
Todo
Example needed for inheriting scenario.Step.
A scenario.Scenario instance is a class logger with the path of the Python script defining it as its log class.
A scenario.Step instance takes the fully qualified name of the class or method defining it for log class.
Debugging is enabled by default for such user-defined scenario and step instances:
class LoggingScenario(scenario.Scenario):
def step020(self):
self.STEP("Logging with the scenario instance")
if self.ACTION("Log messages of different log levels with the scenario itself."):
self.error("This is an error!!!")
self.warning("This is a warning!")
self.info("This is information.")
self.debug("This is debug.")
STEP#2: Logging with the scenario instance (demo/loggingdemo.py:31:LoggingScenario.step020)
------------------------------------------------
ACTION: Log messages of different log levels with the scenario itself.
ERROR [demo/loggingdemo.py] This is an error!!!
WARNING [demo/loggingdemo.py] This is a warning!
INFO [demo/loggingdemo.py] This is information.
DEBUG [demo/loggingdemo.py] This is debug.
Otherwise, debugging is disabled by default for class loggers.
class LoggingScenario(scenario.Scenario):
def __init__(self):
scenario.Scenario.__init__(self)
self.class_logger = MyLogger()
def step030(self):
self.STEP("Logging with a class logger")
if self.ACTION("Log messages of different log levels with the class logger instance."):
self.class_logger.error("This is an error!!!")
self.class_logger.warning("This is a warning!")
self.class_logger.info("This is information.")
self.class_logger.debug("This is debug.")
STEP#3: Logging with a class logger (demo/loggingdemo.py:40:LoggingScenario.step030)
------------------------------------------------
ACTION: Log messages of different log levels with the class logger instance.
ERROR [My logger] This is an error!!!
WARNING [My logger] This is a warning!
INFO [My logger] This is information.
Class logger debugging can be activated on-demand, either 1) programmatically, …:
if self.ACTION("Activate debugging for the class logger instance."):
self.class_logger.enabledebug(True)
if self.ACTION("Log a debug message again with the class logger instance."):
self.class_logger.debug("This is debug again.")
ACTION: Activate debugging for the class logger instance.
ACTION: Log a debug message again with the class logger instance.
DEBUG [My logger] This is debug again.
… 2) through the --debug-class command line option, …:
$ ./bin/run-test.py --debug-class "My logger" ./demo/loggingdemo.py
… or 3) through the scenario.debug_classes configuration value.
—
Acces to logging.Logger instances
Colors¶
The scenario framework manages colorization in the console, which facilitates hot analyses of the log flow.
Log colors may be disabled through the scenario.log_color configuration value.
Log level colorization¶
The basic usage of log colorization is to highlight log levels:
ERROR: colored in red,
WARNING: colored in yellow,
INFO: colored in white,
DEBUG: colored in grey.
These default colors may be overriden with the scenario.log_%(level)_color configuration values.
The log message also takes the color of its log level by default.
Class logger colorization¶
Log colors may also be applied for every log line of a given log class, which is particularly useful when different class loggers generate interleaved log lines:
self.class_logger.setlogcolor(scenario.Console.Color.LIGHTBLUE36)
Indentation¶
Log indentation also contributes in facilitating log analyses.
The scenario framework provides several indentation mechanisms.
Scenario stack indentation¶
When sub-scenarios are executed, lines of ‘|’ characters highlight the nestings of scenario executions.
Example of output from the commutativeadditions.py sample test.
SCENARIO 'demo/commutativeadditions.py'
------------------------------------------------
STEP#1: Both positive members (demo/commutativeadditions.py:16:CommutativeAdditions.step010)
------------------------------------------------
ACTION: Launch the CommutativeAddition scenario with 4 and 5 for inputs.
| SCENARIO 'demo/commutativeaddition.py'
| ------------------------------------------------
|
| STEP#1: Initial conditions (demo/commutativeaddition.py:18:CommutativeAddition.step000)
| ------------------------------------------------
| ACTION: Let a = 4, and b = 5
| EVIDENCE: -> a = 4
| EVIDENCE: -> b = 5
|
| STEP#2: a + b (demo/commutativeaddition.py:25:CommutativeAddition.step010)
| ------------------------------------------------
| ACTION: Compute (a + b) and store the result as result1.
| EVIDENCE: -> result1 = 9
|
| STEP#3: b + a (demo/commutativeaddition.py:32:CommutativeAddition.step020)
| ------------------------------------------------
| ACTION: Compute (b + a) and store the result as result2.
| EVIDENCE: -> result2 = 9
|
| STEP#4: Check (demo/commutativeaddition.py:39:CommutativeAddition.step030)
| ------------------------------------------------
| ACTION: Compare result1 and result2.
| RESULT: result1 and result2 are the same.
| EVIDENCE: -> 9 == 9
|
| END OF 'demo/commutativeaddition.py'
STEP#2: Positive and negative members (demo/commutativeadditions.py:23:CommutativeAdditions.step020)
------------------------------------------------
ACTION: Launch the CommutativeAddition scenario with -1 and 3 for inputs.
| SCENARIO 'demo/commutativeaddition.py'
| ------------------------------------------------
|
| STEP#1: Initial conditions (demo/commutativeaddition.py:18:CommutativeAddition.step000)
| ------------------------------------------------
| ACTION: Let a = -1, and b = 3
| EVIDENCE: -> a = -1
| EVIDENCE: -> b = 3
|
| STEP#2: a + b (demo/commutativeaddition.py:25:CommutativeAddition.step010)
| ------------------------------------------------
| ACTION: Compute (a + b) and store the result as result1.
| EVIDENCE: -> result1 = 2
|
(Output truncated…)
If a sub-scenario executes another sub-scenario, the ‘|’ indentation is doubled, and so on.
Class logger indentation¶
Additional indentation may be useful when the test makes verifications in a recursive way.
It may be set using the following methods:
When these calls are made on a class logger, the logging lines of this class logger are indented the way below.
def step110(self):
self.STEP("Class logger indentation")
if self.ACTION("Log something with the class logger."):
self.class_logger.info("Hello")
try:
for _ in range(3):
if self.ACTION("Push indentation to the class logger."):
self.class_logger.pushindentation()
if self.ACTION("Log something with the class logger."):
self.class_logger.info("Hello")
if self.ACTION("Pop indentation from the class logger."):
self.class_logger.popindentation()
if self.ACTION("Log something with the class logger."):
self.class_logger.info("Hello")
finally:
if self.ACTION("Reset the class logger indentation."):
self.class_logger.resetindentation()
if self.ACTION("Log something with the class logger."):
self.class_logger.info("Hello")
STEP#4: Class logger indentation (demo/loggingdemo.py:55:LoggingScenario.step110)
------------------------------------------------
ACTION: Log something with the class logger.
INFO [My logger] Hello
ACTION: Push indentation to the class logger.
ACTION: Log something with the class logger.
INFO [My logger] Hello
ACTION: Push indentation to the class logger.
ACTION: Log something with the class logger.
INFO [My logger] Hello
ACTION: Push indentation to the class logger.
ACTION: Log something with the class logger.
INFO [My logger] Hello
ACTION: Pop indentation from the class logger.
ACTION: Log something with the class logger.
INFO [My logger] Hello
ACTION: Reset the class logger indentation.
ACTION: Log something with the class logger.
INFO [My logger] Hello
Additional indentation pattern
The Logger.pushindentation() and Logger.popindentation() methods
have a indentation parameter that lets you change the 4-space default pattern by what you need.
When removing indentation, the indentation pattern passed on must be the same as the one added in regards.
self.class_logger.pushindentation("1> ")
self.class_logger.pushindentation("2> ")
self.class_logger.pushindentation("3> ")
self.class_logger.popindentation("3> ")
self.class_logger.popindentation("2> ")
self.class_logger.popindentation("1> ")
Main logger indentation¶
When Logger.pushindentation(), Logger.popindentation()
and Logger.resetindentation() calls are made on the main logger,
it takes effect on every log lines:
main logger and class logger loggings (from DEBUG to ERROR log levels),
but also actions, expected results and evidence texts.
def step120(self):
self.STEP("Main logger indentation")
if self.ACTION("Log something with the main logger."):
scenario.logging.info("Hello")
try:
for _ in range(3):
if self.ACTION("Push indentation to the main logger."):
scenario.logging.pushindentation()
if self.ACTION("Log something with the main logger."):
scenario.logging.info("Hello")
if self.ACTION("Pop indentation from the main logger."):
scenario.logging.popindentation()
if self.ACTION("Log something with the main logger."):
scenario.logging.info("Hello")
finally:
if self.ACTION("Reset the main logger indentation."):
scenario.logging.resetindentation()
if self.ACTION("Log something with the main logger."):
scenario.logging.info("Hello")
STEP#5: Main logger indentation (demo/loggingdemo.py:76:LoggingScenario.step120)
------------------------------------------------
ACTION: Log something with the main logger.
INFO Hello
ACTION: Push indentation to the main logger.
ACTION: Log something with the main logger.
INFO Hello
ACTION: Push indentation to the main logger.
ACTION: Log something with the main logger.
INFO Hello
ACTION: Push indentation to the main logger.
ACTION: Log something with the main logger.
INFO Hello
ACTION: Pop indentation from the main logger.
ACTION: Log something with the main logger.
INFO Hello
ACTION: Reset the main logger indentation.
ACTION: Log something with the main logger.
INFO Hello
Scenario stack v/s user identation
Even though main logger indentation applies to every log lines, it does not break the scenario stack indentation presentation: the ‘|’ characters remain aligned, the main logger indentation applies after.
Debugging¶
Depending on the logger configuration, debug lines may be discarded. By the way, formatting the whole logging message prior to discarding is a waste of time. Depending on the amount of debugging information generated along the code, this can slow down the tests in a sensible way.
Such useless formatting processing can be saved by:
Formatting & positional arguments¶
When logging a debug line, one can write:
self.debug("Hello I'm %s." % name) # Option 1: `%` operator.
self.debug(f"Hello I'm {name}") # Option 2: f-string.
self.debug("Hello I'm %s.", name) # Option 3. positional arguments.
The second option is preferrable to the first one in as much as as it is easier to maintain (main point for f-strings), and f-strings are around 10% more efficient.
Still, with f-strings, the resulting string is computed before it is passed to the Logger.debug() method,
and possibly discarded after being computed.
That’s the reason why, the third option is even more efficient for debug logging: a useless message will be discarded before the formatting arguments are applied to it.
Delayed strings¶
Even when passing format arguments as positionals, some of them may take a while being computed by themselves.
That’s the reason why the scenario.debug package gathers a couple of functions and classes that enable delaying more string computations:
Function |
Class |
Description |
Example |
|---|---|---|---|
Abstract class that defines a string which computation may be delayed. You may inherit from this base class for specific needs. |
|||
Describes a delayed string that should be built with format and arguments. The string can be prepared step by step, thanks to the The application of the arguments is delayed on time when needed. |
_str = scenario.debug.FmtAndArgs("Hello, I'm %s", name)
if profession:
_str.push(" and I'm a %s", profession)
_str.push(".")
self.debug(_str)
|
||
Computes a repr-like string, but ensures a not-too-long string, possibly focused on certain parts, such computation being delayed as for the others. |
self.debug(
"%s in %s",
scenario.debug.saferepr(searched),
scenario.debug.saferepr(longtext, focus=searched),
)
|
||
Delays the dump computation for JSON data. |
self.debug(
"JSON data: %s", scenario.debug.jsondump(data, indent=2),
extra=self.longtext(max_lines=10),
)
Tip
|
||
Delays the execution of a string builder callback. Possibly set with a lambda, this function makes it possible to delay quite everything. |
self.debug(
"Very special data: %s",
scenario.debug.callback(lambda x, y, z: ..., arg1, arg2, arg3),
)
|
Long texts¶
The scenario logging feature provides a way to log long texts on several lines.
To do so, set the extra parameter using the Logger.longtext() method when logging some text:
self.debug(scenario.jsondump(_json_data, indent=2),
extra=self.longtext(max_lines=10))
This feature has primarily been designed for debugging, but it works with the
Logger.info(),
Logger.warning() and
Logger.error()
methods as well.
The max_lines parameter may be set to None in order to display the full text.
File logging¶
The scenario logging feature provides the ability to save the test log output into a file.
To do so, set the scenario.log_file configuration value,
either with the –-config-value command line option, or within a configuration file.
The command line example below disables the output in the console, but saves it into the ‘doc/data/commutativeaddition.log’ file (from the main directory of the scenario library):
$ mkdir -p ./doc/data
$ ./bin/run-test.py \
--config-value "scenario.log_console" "0" \
--config-value "scenario.log_file" "./doc/data/commutativeaddition.log" \
./demo/commutativeaddition.py
$ cat ./doc/data/commutativeaddition.log
SCENARIO 'demo/commutativeaddition.py'
------------------------------------------------
STEP#1: Initial conditions (demo/commutativeaddition.py:18:CommutativeAddition.step000)
------------------------------------------------
ACTION: Let a = 1, and b = 3
EVIDENCE: -> a = 1
EVIDENCE: -> b = 3
STEP#2: a + b (demo/commutativeaddition.py:25:CommutativeAddition.step010)
------------------------------------------------
ACTION: Compute (a + b) and store the result as result1.
EVIDENCE: -> result1 = 4
STEP#3: b + a (demo/commutativeaddition.py:32:CommutativeAddition.step020)
------------------------------------------------
ACTION: Compute (b + a) and store the result as result2.
EVIDENCE: -> result2 = 4
STEP#4: Check (demo/commutativeaddition.py:39:CommutativeAddition.step030)
------------------------------------------------
ACTION: Compare result1 and result2.
RESULT: result1 and result2 are the same.
EVIDENCE: -> 4 == 4
END OF 'demo/commutativeaddition.py'
------------------------------------------------
Status: SUCCESS
Number of STEPs: 4/4
Number of ACTIONs: 4/4
Number of RESULTs: 1/1
Time: HH:MM:SS.mmmmmm
Tip
The scenario.log_file configuration value may also be set programmatically
through the ConfigDatabase.set() method,
as illustrated in the launcher script extension section.
Extra flags¶
The LogExtraData define a set of flags that can be set to specialize the behaviour of each Logger.
For instance, the ScenarioRunner and ScenarioStack classes
disable the LogExtraData.ACTION_RESULT_MARGIN flag,
so that their related log lines remain aligned on the left whatever the current action / expected result context is.
Please, refer the following links for details on extra flags:
Warning
Setting extra flags on class loggers, or even worse on the main logger, may lead to unpredictable behaviours.
Nevertheless, this advanced feature is provided as is. To be used with parsimony.