Debug

There are numerous debug features built in to hutch-python.

Live Session Logging

The first place to go when something has already gone wrong is to the log files. These are stored in a logs directory in the same location as the conf.yml file, and sorted by date and session start time.

These contain every log message from the session in the order they were called. Each module can choose when to make calls to logger.debug to generate log messages, but we also log every single input line, output line, and exception that was raised in the interactive session. Note that the input and output lines are not available to the logger until the entire command has executed, so the log messages immediately preceding an input log are those that were created by calling that statement.

The logging configuration is specified by the logging.yaml file and is set up by the log_setup module. If not in debug mode, only log levels INFO and above will make it to the terminal. The files are configured to rotate and roll over into a second file once they get too large.

Default Log Filtering Rules

The following filtering rules are applied to the console logs:

• Loggers and ophyd object logging adapters that send many messages in a short period of time will stop being logged. This can be configured using the logs.filter object.

• Calls to warnings.warn will be redirected to the logging module stream at “WARNING” level, and duplicate messages will be dropped to “DEBUG” level for the console. This is similar to how warnings behave normally outside of IPython sessions, but this way we also get a record of them in the normal log file.

• Subscription callback exceptions from ophyd objects will be demoted from “ERROR” level to “DEBUG” level to prevent spam while preserving error logs.

• All log messages from ophyd objects at “INFO” level will also be demoted to “DEBUG” level to prevent spam.

PCDS-wide Logging

A special Python logger for PCDS-wide logging is pre-configured within hutch-python. This special logger is named 'pcds-logging', and hooks in with our managed logstash, ElasticSearch and Grafana stack.

To explore the data, access Grafana here.

To record information, first get the logger itself:

import logging
pcds_logger = logging.getLogger('pcds-logging')

Log messages above the configured level (by default logging.DEBUG) will be transmitted to the centralized log server to be recorded and indexed.

One example use case is when an important event that would be useful to see trended over time:

pcds_logger.info('I dropped the sample')

Or for exception statistics, perhaps. The following will include a full stack trace along with module and line information automatically:

try:

1/0

except ZeroDivisionError:

pcds_logger.exception(‘This specific thing went wrong’)

It is not necessary to include information about the host that is running Python, module versions, or thread/process names as these are automatically included.

Debug Mode and Logging Tools

You can start in debug mode by passing the --debug option to hutch-python. Debug mode changes the logging configuration to print log messages of level DEBUG and above to the screen. If that’s a bit much, or if you change your mind during a session, we have a logs namespace with all of the relevant logging configuration tooling.

• logs.log_objects

  Used to configure DEBUG level logging for specific devices.

• logs.log_objects_off

  Used to reset previous calls to log_objects.

• logs.get_log_directory

  Returns the current configured log path.

• logs.get_session_logfiles

  Returns a list of all the logfiles generated by this session.

• logs.get_console_level_name

  Returns the name of the console’s log level, e.g. “INFO”

• logs.set_console_level

  Change the log level of the console logging handler.

• logs.debug_mode:

  A shortcut for setting the console level between “INFO” and “DEBUG”.

• logs.debug_context:

  Context manager for enabling debug mode for a block of code.

• logs.filter:

  Get the ophyd object filter that’s on the console handler. This contains a whitelist for allowing spammy loggers and a blacklist for hiding non-spammy loggers.

• logs.file_filter:

  The same as above, but for the file handler.

logs.debug_mode(True)     # Turn on debug mode
logs.debug_mode(False)    # Turn off debug mode
print(logs.debug_mode())  # Check debug mode

# Turn on debug mode for the duration of a code block
with logs.debug_context():
    buggy_function(arg)

Automated Test Logging

If you’re running the automated test suite, each test run is stored in a module-level logs folder. This can be useful for diagnosing why the tests are failing.