<jupyter_start><jupyter_text>Logging(back to the overview [offline](../Main.ipynb),[online](https://nbviewer.jupyter.org/github/QCoDeS/Qcodes/tree/master/docs/examples/Main.ipynb))[read on nbviewer](https://nbviewer.jupyter.org/github/QCoDeS/Qcodes/tree/master/docs/examples/logging/logging_example.ipynb)  TL;DR * There is a QCoDeS logging module: `qcodes.utils.logger` * Call `logger.start_all_logging` at the start of every script/session to make sure all log messages get stored to the `.qcodes/logs` folder in your home directory. * For debugging purposes you can log messages of an individual instrument (and see the VISA dialog). * You can obtain all logging messages in a `pandas.DataFrame` for further analysis.  Contents- [Introduction](Introduction)- [Set up logging in QCoDeS](Set-up-logging-in-QCoDeS)  - [QCoDeS default handlers](QCoDeS-default-handlers)  - [IPython command history](IPython-command-history)- [Temporarily elevating the logging level](Temporarily-elevating-the-logging-level)- [Filtering log messages by instrument](Filtering-log-messages-by-instrument)- [Capturing Pandas.DataFrame](Capturing-Pandas.DataFrame)  IntroductionPython offers an excellent logging framework that is widely used in QCoDeS. As a user you might be interested in reading the log messages that are generated by QCoDeS for debugging and also profiling purposes.All log records(=messages+meta data) are created using a python `logging.logger` object. In QCoDeS there is a logger for every module with the same name as the module itself, i.e. you can use `logging.getLogger('qcodes.instrument.base')` for getting the logger of the QCoDeS `Instrument`. From the dots in the names of the loggers a hierarchy is define, at the top of which is the so called *root logger* that catches all messages.The log records created in a logger are processed by the *handlers* that have been attached to this specific *logger*.The handlers can for example be used to output the log messages into different locations, like the console or a log file.Every logger, handler and log record has an associated level. The default levels are: `CRITICAL` `ERROR`, `WARNING`, `INFO`, `DEBUG`. The levels determine how messages are passed: A logger passes only records that exceeds its minimal passing level to its handlers and the handlers in turn only output those messages that exceed their minimal passing level.For a more detailed description of Python logging refer to the [official manual](https://docs.python.org/3.6/library/logging.htmlmodule-logging) (This is all well summed up [in this chart](https://docs.python.org/3.6/howto/logging.htmllogging-flow))  Instrument communication loggersNot all the used loggers in QCoDeS follow the previously presented rule of naming the logger after the module. For instruments there are the following loggers: - **qcodes.instrument.base.com**:   This logger logs all the communication of the `Instrument` and its descendants with the actual physical instruments e.g. the messages generated by the `write` and `query` calls. - **qcodes.instrument.base.com.visa**:  This is a sublogger that logs all the communication related messages of the `VisaInstrument` and its descendants.  Set up logging in QCoDeSAt the beginning of every experiment script file you should include the following lines:<jupyter_code>from qcodes.logger import start_all_logging
start_all_logging()<jupyter_output>Logging hadn't been started.
Activating auto-logging. Current session state plus future input saved.
Filename       : C:\Users\jenielse\.qcodes\logs\command_history.log
Mode           : append
Output logging : True
Raw input log  : False
Timestamping   : True
State          : active<jupyter_text>The call to `start_all_logging` does two things:1. Create handlers to output logging messages from the root logger to the console and to a log file.2. Enable logging of the ipython commands into a separate log file.  QCoDeS default handlersThe effect of the console handler can be seen in the two printed lines with a red background below the previous code cell. Every line corresponds to a log record. The fields of the records are separated by `¦` and have the following meaning: 0. time stamp 1. logger name, here the module name 2. record log level 3. name of the function that created the log message 4. line at which the message has been issued 5. actual log messageThe same format is used for the file handler. By default QCoDeS logs to the file `/.qcodes/logs/qcodes.log`. To avoid endlessly long files, the files roll over at midnight and get the date appended to their name where `qcodes.log` without date always gives you the log messages of the same day.To configure the levels you want to log/handle, you need to edit the `qcodesrc.json` file in you home directory. The default values are:```    "logger":{        "console_level": "WARNING",        "file_level": "INFO",        "logger_levels":{            "pyvisa": "INFO"        }```While `console_level` and `file_level` describe the levels of the two default handlers described previously, `logger_levels` is a dictionary that can be used to limit the messages passed on by module level loggers. This means with these defaults, the pyvisa module will not log messages on a `DEBUG` level. Therefore setting the `console_level` to `DEBUG` will not show the pyvisa debug messages (you certainly don't want to see them as they log every single character that is passed to an instrument with an individual message). On the other hand setting the console level to warning will still suppress pyvisa info messages.   IPython command historyThe output above that follows these logging messages comes from IPython. It tells us that all issued IPython commands will be logged to a file. The file lives in the same log directory as the python logs and is called `command_history.log`. It will not roll over.To change the command history logging directory you will need to call `start_command_history_logger` with the new path as an argument.  Temporarily elevating the logging levelSometimes you might wish to catch e.g. all debug messages for a few lines of code. You can do this simply by:<jupyter_code>import logging
import qcodes.logger as logger
log = logging.getLogger('example_logger')

log.debug('This message will not be visible as the logging level is set to `DEBUG`')

with logger.console_level(logging.DEBUG):
    log.debug('This message is visible as the logging level is temporarily elevated to `DEBUG`')
    
log.debug('The level is back to what it used to be')<jupyter_output>2019-08-20 11:52:36,583 ¦ example_logger ¦ DEBUG ¦ <ipython-input-2-c7e8205cb86b> ¦ <module> ¦ 8 ¦ This message is visible as the logging level is temporarily elevated to `DEBUG`<jupyter_text>For other handlers than the console handler you can do the same thing using the `handler_level` context manager.  Filtering log messages by instrumentA very common use case for logging in qcodes is to analyze the communication with a VISA instrument. For this purpose the logger module provides a context manager to filter the logging messages by instrument.Generally one could of course simply attach a handler to the logger of `qcodes.instrument_drivers.Vendor.Type` but this would not show the messages that are generated by the visa communication in `qcodes.instrument.visa`. Additionally with the approach implemented here one can not only filter messages for a given type of instrument but also of a specific instance.To demonstrate this consider the following mock up of the AMI430 Magnet controller that consists of individual visa instruments for each axis, here with the names `x`, `y` and `z`:<jupyter_code>from qcodes.instrument.ip_to_visa import AMI430_VISA
from qcodes.instrument_drivers.american_magnetics.AMI430 import AMI430_3D, AMI430Warning

import qcodes.instrument.sims as sims

visalib = sims.__file__.replace('__init__.py', 'AMI430.yaml@sim')

mag_x = AMI430_VISA('x', address='GPIB::1::INSTR', visalib=visalib,
                        terminator='\n', port=1)
mag_y = AMI430_VISA('y', address='GPIB::2::INSTR', visalib=visalib,
                        terminator='\n', port=1)
mag_z = AMI430_VISA('z', address='GPIB::3::INSTR', visalib=visalib,
                        terminator='\n', port=1)

import numpy as np
field_limit = [
    lambda x, y, z: x == 0 and y == 0 and z < 3,
    lambda x, y, z: np.linalg.norm([x, y, z]) < 2
]

driver = AMI430_3D("AMI430-3D", mag_x, mag_y, mag_z, field_limit)<jupyter_output>Connected to: QCoDeS AMI430_simulation (serial:1337, firmware:0.0.01) in 0.24s
Connected to: QCoDeS AMI430_simulation (serial:1337, firmware:0.0.01) in 0.02s
Connected to: QCoDeS AMI430_simulation (serial:1337, firmware:0.0.01) in 0.02s<jupyter_text>In the above messages you can see the prefix `[()]`. To analyze the visa communication one can use `filter_instrument`:<jupyter_code>driver.cartesian((0, 0, 0))
with logger.console_level('DEBUG'):
    with logger.filter_instrument(mag_x):
        driver.cartesian((0, 0, 1))<jupyter_output>2019-08-20 11:52:37,041 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 228 ¦ [x(AMI430_VISA)] Querying: STATE?
2019-08-20 11:52:37,041 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 230 ¦ [x(AMI430_VISA)] Response: 2
2019-08-20 11:52:37,041 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 228 ¦ [x(AMI430_VISA)] Querying: FIELD:MAG?
2019-08-20 11:52:37,061 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 230 ¦ [x(AMI430_VISA)] Response: 0.0
2019-08-20 11:52:37,076 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 228 ¦ [x(AMI430_VISA)] Querying: FIELD:MAG?
2019-08-20 11:52:37,082 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 230 ¦ [x(AMI430_VISA)] Response: 0.0<jupyter_text>The output on the console shows as expected only messages from the `x` instrument. For multiple instruments pass a sequence of instruments to `filter_instrument`:<jupyter_code>driver.cartesian((0, 0, 0))
with logger.console_level('DEBUG'):
    with logger.filter_instrument((mag_x, mag_y)):
        driver.cartesian((0, 0, 1))<jupyter_output>2019-08-20 11:52:37,158 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 228 ¦ [x(AMI430_VISA)] Querying: STATE?
2019-08-20 11:52:37,158 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 230 ¦ [x(AMI430_VISA)] Response: 2
2019-08-20 11:52:37,158 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 228 ¦ [y(AMI430_VISA)] Querying: STATE?
2019-08-20 11:52:37,175 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 230 ¦ [y(AMI430_VISA)] Response: 2
2019-08-20 11:52:37,175 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 228 ¦ [x(AMI430_VISA)] Querying: FIELD:MAG?
2019-08-20 11:52:37,175 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 230 ¦ [x(AMI430_VISA)] Response: 0.0
2019-08-20 11:52:37,175 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 228 ¦ [y(AMI430_VISA)] Querying: FIELD:MAG?
2019-08-20 11:52:37,175 ¦ qcodes.instrument.base.com.visa ¦ DEBUG ¦ visa ¦ ask_raw ¦ 230 ¦ [y(AMI430_VISA)] Response: 0.0
2019-08-[...]<jupyter_text>Capturing Pandas.DataFrameTo process the logs, especially with the timestamps the [pandas module](https://pandas.pydata.org/) is highly suited. With `logger.log_to_dataframe` or `logger.logfile_to_dataframe` you can convert a log(file) to a pandas `DataFrame`. See this ([online](https://nbviewer.jupyter.org/github/QCoDeS/Qcodes/tree/master/docs/examples/logging/logfile_parsing.ipynb), [offline](logfile_parsing.ipynb)) notebook for an example.You can also use a context manager to capture the logs directly into a `DataFrame`<jupyter_code>from qcodes.logger.log_analysis import capture_dataframe
with logger.console_level(logging.WARN):
    driver.cartesian((0, 0, 0))
    with capture_dataframe(level='DEBUG') as (handler, get_dataframe):
        driver.cartesian((0, 0, 1))
        df = get_dataframe()
        driver.cartesian((0, 0, 2))
        df2 = get_dataframe() # this is the cummulative log
df
df2<jupyter_output><empty_output><jupyter_text>You can of course combine the context managers like this:<jupyter_code>with logger.console_level(logging.WARN):
    driver.cartesian((0, 0, 0))
    with capture_dataframe(level='DEBUG') as (handler, get_dataframe):
        with logger.filter_instrument(mag_x, handler=handler):
            driver.cartesian((0, 0, 1))
            df = get_dataframe()
df<jupyter_output><empty_output>
{'fraction_non_alphanumeric': 0.09262820512820513, 'fraction_numerical': 0.03958333333333333, 'mean_word_length': 4.727856815052776, 'pattern_counts': {'":': 5, '<': 28, '<?xml version=': 0, '>': 26, 'https://': 6, 'lorem ipsum': 0, 'www.': 0, 'xml': 0}, 'pii_count': 0, 'substrings_counts': 0, 'word_list_counts': {'cursed_substrings.json': 0, 'profanity_word_list.json': 0, 'sexual_word_list.json': 0, 'zh_pornsignals.json': 0}}
{'chain_length': '7', 'dir': 'jupyter-structured-clean-dedup', 'id': '144923', 'license': 'MIT', 'n_tokens_mistral': 4198, 'n_tokens_neox': 3816, 'n_words': 1507, 'path': 'docs/examples/logging/logging_example.ipynb', 'repo_name': 'pjramsey37/Qcodes', 'size': '12480'}