|
| 1 | +Debug |
| 2 | +===== |
| 3 | + |
| 4 | +There are numerous debug features built in to ``hutch-python``. |
| 5 | + |
| 6 | +Live Session Logging |
| 7 | +-------------------- |
| 8 | + |
| 9 | +The first place to go when something has already gone wrong is to the log |
| 10 | +files. These are stored in a ``logs`` directory in the same location as the |
| 11 | +``conf.yml`` file, and sorted by date and session start time. |
| 12 | + |
| 13 | +These contain every log message from the session in the order they were called. |
| 14 | +Each module can choose when to make calls to ``logger.debug`` to generate |
| 15 | +log messages, but we also log every single input line, output line, and |
| 16 | +exception that was raised in the interactive session. Note that the input and |
| 17 | +output lines are not available to the logger until the entire command has |
| 18 | +executed, so the log messages immediately preceding an input log are those |
| 19 | +that were created by calling that statement. |
| 20 | + |
| 21 | +The logging configuration is specified by the ``logging.yaml`` file and is |
| 22 | +set up by the :py:mod:`log_setup` module. If not in debug mode, only log levels |
| 23 | +``INFO`` and above will make it to the terminal. The files are configured to |
| 24 | +rotate and roll over into a second file once they get too large. |
| 25 | + |
| 26 | + |
| 27 | +Default Log Filtering Rules |
| 28 | +--------------------------- |
| 29 | +The following filtering rules are applied to the console logs: |
| 30 | + |
| 31 | +- Loggers and ophyd object logging adapters that send many messages in a short |
| 32 | + period of time will stop being logged. This can be configured using the |
| 33 | + ``logs.filter`` object. |
| 34 | +- Calls to ``warnings.warn`` will be redirected to the ``logging`` module |
| 35 | + stream at "WARNING" level, and duplicate messages will be dropped to "DEBUG" |
| 36 | + level for the console. This is similar to how warnings behave normally |
| 37 | + outside of IPython sessions, but this way we also get a record of them in |
| 38 | + the normal log file. |
| 39 | +- Subscription callback exceptions from ophyd objects will be demoted from |
| 40 | + "ERROR" level to "DEBUG" level to prevent spam while preserving error |
| 41 | + logs. |
| 42 | +- All log messages from ophyd objects at "INFO" level will also be demoted to |
| 43 | + "DEBUG" level to prevent spam. |
| 44 | + |
| 45 | + |
| 46 | +PCDS-wide Logging |
| 47 | +----------------- |
| 48 | + |
| 49 | +A special Python logger for PCDS-wide logging is pre-configured within |
| 50 | +``hutch-python``. This special logger is named ``'pcds-logging'``, and hooks |
| 51 | +in with our managed logstash, ElasticSearch and Grafana stack. |
| 52 | + |
| 53 | +To explore the data, access Grafana `here |
| 54 | +<https://pswww.slac.stanford.edu/ctl/grafana/explore>`_. |
| 55 | + |
| 56 | +To record information, first get the logger itself: |
| 57 | + |
| 58 | +.. code-block:: python |
| 59 | +
|
| 60 | + import logging |
| 61 | + pcds_logger = logging.getLogger('pcds-logging') |
| 62 | +
|
| 63 | +
|
| 64 | +Log messages above the configured level (by default ``logging.DEBUG``) will be |
| 65 | +transmitted to the centralized log server to be recorded and indexed. |
| 66 | + |
| 67 | +One example use case is when an important event that would be useful to see |
| 68 | +trended over time: |
| 69 | + |
| 70 | +.. code-block:: python |
| 71 | +
|
| 72 | + pcds_logger.info('I dropped the sample') |
| 73 | +
|
| 74 | +
|
| 75 | +Or for exception statistics, perhaps. The following will include a full stack |
| 76 | +trace along with module and line information automatically: |
| 77 | + |
| 78 | + |
| 79 | + try: |
| 80 | + 1/0 |
| 81 | + except ZeroDivisionError: |
| 82 | + pcds_logger.exception('This specific thing went wrong') |
| 83 | + |
| 84 | + |
| 85 | +It is not necessary to include information about the host that is running |
| 86 | +Python, module versions, or thread/process names as these are automatically |
| 87 | +included. |
| 88 | + |
| 89 | + |
| 90 | +Debug Mode and Logging Tools |
| 91 | +---------------------------- |
| 92 | + |
| 93 | +You can start in debug mode by passing the ``--debug`` option to |
| 94 | +``hutch-python``. Debug mode changes the logging configuration to print |
| 95 | +log messages of level ``DEBUG`` and above to the screen. If that's a bit much, |
| 96 | +or if you change your mind during a session, we have a ``logs`` namespace |
| 97 | +with all of the relevant logging configuration tooling. |
| 98 | + |
| 99 | +- `logs.log_objects <hutch_python.log_setup.log_objects>` |
| 100 | + Used to configure ``DEBUG`` level logging for specific devices. |
| 101 | +- `logs.log_objects_off <hutch_python.log_setup.log_objects_off>` |
| 102 | + Used to reset previous calls to ``log_objects``. |
| 103 | +- `logs.get_log_directory <hutch_python.log_setup.get_log_directory>` |
| 104 | + Returns the current configured log path. |
| 105 | +- `logs.get_session_logfiles <hutch_python.log_setup.get_session_logfiles>` |
| 106 | + Returns a list of all the logfiles generated by this session. |
| 107 | +- `logs.get_console_level_name <hutch_python.log_setup.get_console_level_name>` |
| 108 | + Returns the name of the console's log level, e.g. "INFO" |
| 109 | +- `logs.set_console_level <hutch_python.log_setup.set_console_level>` |
| 110 | + Change the log level of the console logging handler. |
| 111 | +- `logs.debug_mode <hutch_python.log_setup.debug_mode>`: |
| 112 | + A shortcut for setting the console level between "INFO" and "DEBUG". |
| 113 | +- `logs.debug_context <hutch_python.log_setup.debug_context>`: |
| 114 | + Context manager for enabling debug mode for a block of code. |
| 115 | +- `logs.filter <hutch_python.log_setup.ObjectFilter>`: |
| 116 | + Get the ophyd object filter that's on the console handler. |
| 117 | + This contains a whitelist for allowing spammy loggers and a blacklist |
| 118 | + for hiding non-spammy loggers. |
| 119 | +- `logs.file_filter <hutch_python.log_setup.ObjectFilter>`: |
| 120 | + The same as above, but for the file handler. |
| 121 | + |
| 122 | + |
| 123 | +.. code-block:: python |
| 124 | +
|
| 125 | + logs.debug_mode(True) # Turn on debug mode |
| 126 | + logs.debug_mode(False) # Turn off debug mode |
| 127 | + print(logs.debug_mode()) # Check debug mode |
| 128 | +
|
| 129 | + # Turn on debug mode for the duration of a code block |
| 130 | + with logs.debug_context(): |
| 131 | + buggy_function(arg) |
| 132 | +
|
| 133 | +
|
| 134 | +Automated Test Logging |
| 135 | +---------------------- |
| 136 | + |
| 137 | +If you're running the automated test suite, each test run is stored in a |
| 138 | +module-level ``logs`` folder. This can be useful for diagnosing why the tests |
| 139 | +are failing. |
0 commit comments