Debugging and Logging

Changed in version 1.6.0: Bluesky’s use of Python’s logging framework has been completely reworked to follow Python’s documented best practices for libraries.

Bluesky uses Python’s logging framework, which enables sophisticated log management. For common simple cases, including viewing logs in the terminal or writing them to a file, the next section illustrates streamlined, copy/paste-able examples. Users who are familiar with that framework or who need to route logs to multiple destinations may wish to skip ahead to Bluesky’s Logging-Related API.

Useful Snippets

Log warnings

This is the recommended standard setup.

from bluesky import config_bluesky_logging
config_bluesky_logging()

It will display 'bluesky' log records of WARNING level or higher in the terminal (standard out) with a format tailored to bluesky.

Maximum verbosity

If the RunEngine is “hanging,” running slowly, or repeatedly encountering an error, it is useful to know exactly where in the plan the problem is occurring. To follow the RunEngine’s progress through the plan, crank up the verbosity of the logging.

This will display each message from the plan just before the RunEngine processes it, giving a clear indication of when plan execution is stuck.

from bluesky import config_bluesky_logging
config_bluesky_logging(level='DEBUG')

Log to a file

This will direct all log messages to a file instead of the terminal (standard out).

from bluesky import config_bluesky_logging
config_bluesky_logging(file='/tmp/bluesky.log', level='DEBUG')

Important

We strongly recommend setting levels on handlers not on loggers. In previous versions of bluesky, we recommended adjusting the level on the logger, as in RE.log.setLevel('DEBUG'). We now recommended that you avoid setting levels on loggers because it would affect all handlers downstream, potentially inhibiting some other part of the program from collecting the records it wants to collect.

Bluesky’s Logging-Related API

Logger Names

Here are the primary loggers used by bluesky.

• 'bluesky' — the logger to which all bluesky log records propagate

• 'bluesky.emit_document' — A log record is emitted whenever a Document is emitted. The log record does not contain the full content of the Document.

• 'bluesky.RE' — Records from a RunEngine. INFO-level notes state changes. DEBUG-level notes when each message from a plan is about to be processed and when a status object has completed.

• 'bluesky.RE.msg — A log record is emitted when each Msg is about to be processed.

• 'bluesky.RE.state — A log record is emitted when the RunEngine’s state changes.

There are also some module-level loggers for specific features.

Formatter

class bluesky.log.LogFormatter(fmt='%(color)s[%(levelname)1.1s %(asctime)s %(module)s:%(lineno)d]%(end_color)s %(message)s', datefmt='%y%m%d %H:%M:%S', style='%', color=True, colors={10: 4, 20: 2, 30: 3, 40: 1})

Log formatter for bluesky records.

Adapted from the log formatter used in Tornado. Key features of this formatter are:

• Color support when logging to a terminal that supports it.

• Timestamps on every log line.

• Includes extra record attributes (old_state, new_state, msg_command, doc_name, doc_uid) when present.

Global Handler

Following Python’s recommendation, bluesky does not install any handlers at import time, but it provides a function to set up a basic useful configuration in one line, similar to Python’s logging.basicConfig() but with some additional options—and scoped to the 'bluesky' logger with bluesky’s bluesky.log.LogFormatter. It streamlines common use cases without interfering with more sophisticated use cases.

We recommend that facilities using bluesky leave this function for users and configure any standardized, facility-managed logging handlers separately, as described in the next section.

bluesky.log.config_bluesky_logging(file=<_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>, datefmt='%H:%M:%S', color=True, level='WARNING')

Set a new handler on the logging.getLogger('bluesky') logger.

If this is called more than once, the handler from the previous invocation is removed (if still present) and replaced.

Parameters

fileobject with write method or filename string

Default is sys.stdout.

datefmtstring

Date format. Default is '%H:%M:%S'.

colorboolean

Use ANSI color codes. True by default.

levelstr or int

Python logging level, given as string or corresponding integer. Default is ‘WARNING’.

Returns

handlerlogging.Handler

The handler, which has already been added to the ‘bluesky’ logger.

Examples

Log to a file.

>>> config_bluesky_logging(file='/tmp/what_is_happening.txt')

Include the date along with the time. (The log messages will always include microseconds, which are configured separately, not as part of ‘datefmt’.)

>>> config_bluesky_logging(datefmt="%Y-%m-%d %H:%M:%S")

Turn off ANSI color codes.

>>> config_bluesky_logging(color=False)

Increase verbosity: show level INFO or higher.

>>> config_bluesky_logging(level='INFO')

bluesky.log.get_handler()

Return the handler configured by the most recent call to config_bluesky_logging().

If config_bluesky_logging() has not yet been called, this returns None.

Advanced Example

The flow of log event information in loggers and handlers is illustrated in the following diagram:

For further reference, see the Python 3 logging howto: https://docs.python.org/3/howto/logging.html#logging-flow

As an illustrative example, we will set up two handlers using the Python logging framework directly, ignoring bluesky’s convenience function.

Suppose we set up a handler aimed at a file:

import logging
file_handler = logging.FileHandler('bluesky.log')

And another aimed at Logstash:

import logstash  # requires python-logstash package
logstash_handler = logstash.TCPLogstashHandler(<host>, <port>, version=1)

We can attach the handlers to the bluesky logger, to which all log records created by bluesky propagate:

logger = logging.getLogger('bluesky')
logger.addHandler(logstash_handler)
logger.addHandler(file_filter)

We can set the verbosity of each handler. Suppose want maximum verbosity in the file but only medium verbosity in logstash.

logstash_handler.setLevel('INFO')
file_handler.setLevel('DEBUG')

Finally, ensure that “effective level” of logger is at least as verbose as the most verbose handler—in this case, 'DEBUG'. By default, at import, its level is not set

In [1]: logging.getLevelName(logger.level)

In [2]: 'NOTSET'

and so it inherits the level of Python’s default “handler of last resort,” logging.lastResort, which is 'WARNING'.

In [3]: logging.getLevelName(logger.getEffectiveLevel())

In [4]: 'WARNING'

In this case we should set it to 'DEBUG', to match the most verbose level of the handler we have added.

logger.setLevel('DEBUG')

This makes DEBUG-level records available to all handlers. Our logstash handler, set to 'INFO', will filter out DEBUG-level records.

To globally disable the generation of any log records at or below a certain verbosity, which may be helpful for optimizing performance, Python provides logging.disable().