utils.log module

Logging framework

This module creates the cfme logger, for use throughout the project. This logger only captures log messages explicitly sent to it, not logs emitted by other components (such as selenium). To capture those, consider using the pytest-capturelog plugin.

Example Usage

from utils.log import logger

logger.debug('debug log message')
logger.info('info log message')
logger.warning('warning log message')
logger.error('error log message')
logger.critical('critical log message')

The above will result in the following output in cfme_tests/logs/cfme.log:

1970-01-01 00:00:00,000 [D] debug log message (filename.py:3)
1970-01-01 00:00:00,000 [I] info log message (filename.py:4)
1970-01-01 00:00:00,000 [W] warning log message (filename.py:5)
1970-01-01 00:00:00,000 [E] error log message (filename.py:6)
1970-01-01 00:00:00,000 [C] fatal log message (filename.py:7)

Additionally, if log_error_to_console is True (see below), the following will be written to stderr:

[E] error (filename.py:6)
[C] fatal (filename.py:7)

Log Message Source

We have added a custom log record attribute that can be used in log messages: %(source)s This attribute is included in the default ‘cfme’ logger configuration.

This attribute will be generated by default and include the filename and line number from where the log message was emitted. It will attempt to convert file paths to be relative to cfme_tests, but use the absolute file path if a relative path can’t be determined.

When writting generic logging facilities, it is sometimes helpful to override those source locations to make the resultant log message more useful. To do so, pass the extra source_file (str) and source_lineno (int) to the log emission:

logger.info('info log message', extra={'source_file': 'somefilename.py', 'source_lineno': 7})

If source_lineno is None and source_file is included, the line number will be omitted. This is useful in cases where the line number can’t be determined or isn’t necessary.

Configuration

# in env.yaml
logging:
    # Can be one of DEBUG, INFO, WARNING, ERROR, CRITICAL
    level: INFO
    # Maximum logfile size, in bytes, before starting a new logfile
    # Set to 0 to disable log rotation
    max_logfile_size: 0
    # Maximimum backup copies to make of rotated log files (e.g. cfme.log.1, cfme.log.2, ...)
    # Set to 0 to keep no backups
    max_logfile_backups: 0
    # If True, messages of level ERROR and CRITICAL are also written to stderr
    errors_to_console: False
    # Default file format
    file_format: "%(asctime)-15s [%(levelname).1s] %(message)s (%(source)s)"
    # Default format to console if errors_to_console is True
    stream_format: "[%(levelname)s] %(message)s (%(source)s)"

Additionally, individual logger configurations can be overridden by defining nested configuration values using the logger name as the configuration key. Note that the name of the logger objects exposed by this module don’t obviously line up with their key in cfme_data. The ‘name’ attribute of loggers can be inspected to get this value:

>>> utils.log.logger.name
'cfme'
>>> utils.log.perflog.logger.name
'perf'

Here’s an example of those names being used in env.local.yaml to configure loggers individually:

logging:
    cfme:
        # set the cfme log level to debug
        level: DEBUG
    perf:
        # make the perflog a little more "to the point"
        file_format: "%(message)s"

Notes:

  • The cfme and perf loggers are guaranteed to exist when using this module.
  • The name of a logger is used to generate its filename, and will usually not have the word “log” in it.
    • perflog‘s logger name is perf for this reason, resulting in log/perf.log instead of log/perflog.log.
    • Similarly, logger‘s’ name is cfme, to prevent having log/logger.log.

Warning

Creating a logger with the same name as one of the default configuration keys, e.g. create_logger('level') will cause a rift in space-time (or a ValueError).

Do not attempt.

Message Format

year-month-day hour:minute:second,millisecond [Level] message text (file:linenumber)

[Level]:

One letter in square brackets, where [I] corresponds to INFO, [D] corresponds to DEBUG, and so on.

(file:linenumber):

The relative location from which this log message was emitted. Paths outside

Members

class utils.log.ArtifactorLoggerAdapter(logger, extra)[source]

Bases: logging.LoggerAdapter

Logger Adapter that hands messages off to the artifactor before logging

art_log(level_name, message, kwargs)[source]
artifactor[source]
critical(msg, *args, **kwargs)[source]
debug(msg, *args, **kwargs)[source]
error(msg, *args, **kwargs)[source]
exception(msg, *args, **kwargs)[source]
info(msg, *args, **kwargs)[source]
log(lvl, msg, *args, **kwargs)[source]
process(msg, kwargs)[source]
slaveid[source]
trace(msg, *args, **kwargs)[source]
warning(msg, *args, **kwargs)[source]
class utils.log.NamedLoggerAdapter(logger, extra)[source]

Bases: utils.log.TraceLoggerAdapter

An adapter that injects a name into log messages

process(message, kwargs)[source]
class utils.log.Perflog(perflog_name='perf')[source]

Bases: object

Performance logger, useful for timing arbitrary events by name

Logged events will be written to log/perf.log by default, unless a different log file name is passed to the Perflog initializer.

Usage:

from utils.log import perflog
perflog.start('event_name')
# do stuff
seconds_taken = perflog.stop('event_name')
# seconds_taken is also written to perf.log for later analysis
start(event_name)[source]

Start tracking the named event

Will reset the start time if the event is already being tracked

stop(event_name)[source]

Stop tracking the named event

Returns:A float value of the time passed since start was last called, in seconds, or None if start was never called.
tracking_events = {}
class utils.log.SyslogMsecFormatter(fmt=None, datefmt=None)[source]

Bases: logging.Formatter

A custom Formatter for the syslogger which changes the log timestamps to have millisecond resolution for compatibility with splunk.

static converter()

timestamp[, tz] -> tz’s local time from POSIX timestamp.

formatTime(record, datefmt=None)[source]
class utils.log.TraceLogger(name, level=0)[source]

Bases: logging.Logger

A trace-loglevel-aware Logger

trace(msg, *args, **kwargs)[source]

Log ‘msg % args’ with severity ‘TRACE’.

class utils.log.TraceLoggerAdapter(logger, extra)[source]

Bases: logging.LoggerAdapter

A trace-loglevel-aware LoggerAdapter

trace(msg, *args, **kwargs)[source]

Delegate a trace call to the underlying logger, after adding contextual information from this adapter instance.

utils.log.create_logger(logger_name, filename=None, max_file_size=None, max_backups=None)[source]

Creates and returns the named logger

If the logger already exists, it will be destroyed and recreated with the current config in env.yaml

utils.log.create_sublogger(logger_sub_name, logger_name='cfme')[source]
utils.log.format_marker(mstring, mark='-')[source]

Creates a marker in log files using a string and leader mark.

This function uses the constant MARKER_LEN to determine the length of the marker, and then centers the message string between padding made up of leader_mark characters.

Parameters:
  • mstring – The message string to be placed in the marker.
  • leader_mark – The marker character to use for leading and trailing.

Returns: The formatted marker string.

Note: If the message string is too long to fit one character of leader/trailer and
a space, then the message is returned as is.
class utils.log.logger_wrap(*args, **kwargs)[source]

Bases: object

Sets up the logger by default, used as a decorator in utils.appliance

If the logger doesn’t exist, sets up a sensible alternative

utils.log.nth_frame_info(n)[source]

Inspect the stack to determine the filename and lineno of the code running at the “n”th frame

Parameters:n – Number of the stack frame to inspect

Raises IndexError if the stack doesn’t contain the nth frame (the caller should know this)

Returns a frameinfo namedtuple as described in inspect