Lesson A12 – Logging

When debugging a program, you need to analyze the status of your program line by line (e.g. how far the program has been executed or the current values stored in certain variables). The pedestrian way to debugging is by writing print-statements that report the status of the code. These statements need to be commented out once the code is finished. The logging module automates this task, and lets you access status messages of different levels of criticality in the finished code. Logging can be useful in scientific applications, too , when you want to keep track of what the program did exactly. For example, if you setup a computer experiment (like a simulation), you want to document every single step of the setup procedure and parameters to ensure the reproducibility of the experiment.

Logging can be fairly complex. Consider this a rather advanced tutorial unit. Also have a look in the official logging how-to. Plenty of examples on formatting the output are found there as well.

import logging

Let’s declare a file “example.log” as the file where we want to store our logging information and modify some global options for the logger.

fname = 'io/example.log'
logging.basicConfig(
    filename=fname,
    filemode="w",
    format='%(asctime)s %(message)s',
    datefmt='%m/%d/%Y %I:%M:%S %p',
    level=logging.DEBUG,
    )

We call the function basicConfig from the logging module to configure the logging. The arguments we have passed here, have the following meaning:

filename declares the name of the file where we want to store our log data. If no such file exists, one will be created (see filemode).

filemode specifies the mode in which to open the log file. The value “w” means, create the file if it does not exist and overwrite it when it does. If you rather want to append to an existing file, use the default mode “a”.

format declares what exactly should be written (and how) to the log file, when we trigger the logging. The single elements starting with a % stand in for different possible parts. The string we used for example makes every log entry in the log file start with the current date and time (see datefmt) before the actual logging message is printed after a single space.

datefmt formats the date via the function time.strftime() from the time module. The logger uses this function internally. The single elements starting with a % stand in for different parts of the current date and time. The string we used translates for example into: “month/day/year hour/minute/second (am or pm)”.

The keyword level declares which level of logging is to be printed. There are five levels of logging ordered in decreasing severity:

1. CRITICAL

   • A serious error, indicating that the program itself may be unable to continue running.

2. ERROR

   • Due to a more serious problem, the software has not been able to perform some function.

3. WARNING

   • An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.

4. INFO

   • Confirmation that things are working as expected.

5. DEBUG

   • Detailed information, typically of interest only when diagnosing problems.

Declaring a level of debugging will also print all higher levels. We choose DEBUG, so all levels of logging will be printed to the file.

Now let’s see how to send something to the log file in the context of a little program.

import time

t0 = time.time()
name = 'Anon'

time.sleep(1)
# Do something or nothing

logging.debug('Debugs should go to the log file')
logging.info('So should Infos')
logging.warning('And warnings, too')

logging.error('Errors as well')
logging.critical('last but not least, this is critical')

logging.info('The order is chronological')

logging.info('Old style formatted Message:\n    This tutorial took %s %d seconds' % (name, (time.time() - t0)))
logging.info('New style formatted Message:\n    This tutorial took {} {:.2f} seconds'.format(name, (time.time() - t0)))
logging.info(f'f-string formatted Message:\n    This tutorial took {name} {time.time() - t0:.2f} seconds')

Lets look at the ouput file line by line

with open(fname) as f:
    for line in f:
        print(line, end="")

04/07/2020 05:26:56 PM Debugs should go to the log file
04/07/2020 05:26:56 PM So should Infos
04/07/2020 05:26:56 PM And warnings, too
04/07/2020 05:26:56 PM Errors as well
04/07/2020 05:26:56 PM last but not least, this is critical
04/07/2020 05:26:56 PM The order is chronological
04/07/2020 05:26:56 PM Old style formatted Message:
    This tutorial took Anon 1 seconds
04/07/2020 05:26:56 PM New style formatted Message:
    This tutorial took Anon 1.01 seconds
04/07/2020 05:26:56 PM f-string formatted Message:
    This tutorial took Anon 1.01 seconds

Info: The logging module uses the old %-string formatting to declare the format of printed variables as you saw above when we configured the logging. That is, we delcare the format with % and a letter where the letter represents a string format. After the string with placeholder, the variables follow in the same order in which they appear in the string. More information on the old printf-style string formatting here. You can still use the more convenient new style formatting in your own messages.

Examples

Below you will find some lines of pseudo code (code that is not actually executable) to further illustrate the use of the logging module. The examples come from the context of Molecular Dynamics simulations and deal with two important aspects of these computer experiments where logging can helpful:

• checking the simulation parameters provided by the user for consistency and irregularities before the simulation is started

• checking for errors and problems during the simulation

Checking simulation parameters for plausibility

# Load the parameters
timestep, lj_cutoff, pme_cutoff, boxsize = load_parameters()

parameter_warnings = 0  # warning counter

# Check whether the timestep is not larger than the usual upper limit
if timestep > 2 femtoseconds:
    logging.warning("Timestep unusually large")
    parameter_warnings += 1  # increase warning counter by 1


# Check whether the cutoff values are identical
if lj_cutoff != pme_cutoff:
    logging.error("Short range cutoff values don't match")
    parameter_warnings += 1  # increase warning counter by 1


# Check whether the cutoff values match the box size
if lj_cutoff > boxsize/2:
    logging.error("Cutoff larger than half the box size. Some interactions may be included multiple times.")
    parameter_warnings += 1  # increase warning counter by 1


# Report whether all parameters are fine
if parameter_warnings == 0:
    logging.info("All parameters are fine.")

Catching possible errors during the simulation

# Monitor the distances for atomic clashes

# Obtain the distances between atoms
distances = compute_distance(positions)
for d in distance:
    if d <= threshold:
    logging.error('Atoms are unusually close')


# Monitor the forces for numerical overflows

# Evaluate the forces
forces = compute_forces(positions, potential)
if any(np.isinf(forces)):
    logging.critical('Overflow in Forces')

# Monitor the temperature for a drift
# Temperature is not always, but often a conserved quantity in an MD simulation

drift = compute_temperature_drift(this_frame, previous_frame)
if drift > threshold:
    logging.warning('Temperature is Drifting')