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.log 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.log 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.log 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.

Advanced Example

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

https://docs.python.org/3/_images/logging_flow.png

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().