{ "cells": [ { "cell_type": "markdown", "metadata": {}, "source": [ "# Lesson A12 – Logging" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "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." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Logging can be fairly complex. Consider this a rather advanced tutorial unit. Also have a look in the official logging\n", "[how-to](https://docs.python.org/3/howto/logging.html). Plenty of\n", "examples on formatting the output are found there as well." ] }, { "cell_type": "code", "execution_count": 1, "metadata": {}, "outputs": [], "source": [ "import logging" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "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." ] }, { "cell_type": "code", "execution_count": 2, "metadata": {}, "outputs": [], "source": [ "fname = 'io/example.log'\n", "logging.basicConfig(\n", " filename=fname,\n", " filemode=\"w\",\n", " format='%(asctime)s %(message)s',\n", " datefmt='%m/%d/%Y %I:%M:%S %p',\n", " level=logging.DEBUG,\n", " )" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "We call the function `basicConfig` from the logging module to configure\n", "the logging. The arguments we have passed here, have the following meaning:" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "`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`).\n", "\n", "`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\".\n", "\n", "`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.\n", "\n", "`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)\".\n", "\n", "The keyword `level` declares which level of logging is to be printed. There are five levels of logging ordered in decreasing severity:\n", "\n", "1. CRITICAL\n", " - A serious error, indicating that the program itself may be unable to continue running.\n", "2. ERROR\n", " - Due to a more serious problem, the software has not been able to perform some function.\n", "3. WARNING\n", " - 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.\n", "4. INFO \n", " - Confirmation that things are working as expected.\n", "5. DEBUG\n", " - Detailed information, typically of interest only when diagnosing problems.\n", " \n", "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." ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Now let's see how to send something to the log file in the context of a\n", "little program." ] }, { "cell_type": "code", "execution_count": 3, "metadata": {}, "outputs": [], "source": [ "import time\n", "\n", "t0 = time.time()\n", "name = 'Anon'\n", "\n", "time.sleep(1)\n", "# Do something or nothing\n", "\n", "logging.debug('Debugs should go to the log file')\n", "logging.info('So should Infos')\n", "logging.warning('And warnings, too')\n", "\n", "logging.error('Errors as well')\n", "logging.critical('last but not least, this is critical')\n", "\n", "logging.info('The order is chronological')\n", "\n", "logging.info('Old style formatted Message:\\n This tutorial took %s %d seconds' % (name, (time.time() - t0)))\n", "logging.info('New style formatted Message:\\n This tutorial took {} {:.2f} seconds'.format(name, (time.time() - t0)))\n", "logging.info(f'f-string formatted Message:\\n This tutorial took {name} {time.time() - t0:.2f} seconds')" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "Lets look at the ouput file line by line" ] }, { "cell_type": "code", "execution_count": 4, "metadata": {}, "outputs": [ { "name": "stdout", "output_type": "stream", "text": [ "04/07/2020 05:26:56 PM Debugs should go to the log file\n", "04/07/2020 05:26:56 PM So should Infos\n", "04/07/2020 05:26:56 PM And warnings, too\n", "04/07/2020 05:26:56 PM Errors as well\n", "04/07/2020 05:26:56 PM last but not least, this is critical\n", "04/07/2020 05:26:56 PM The order is chronological\n", "04/07/2020 05:26:56 PM Old style formatted Message:\n", " This tutorial took Anon 1 seconds\n", "04/07/2020 05:26:56 PM New style formatted Message:\n", " This tutorial took Anon 1.01 seconds\n", "04/07/2020 05:26:56 PM f-string formatted Message:\n", " This tutorial took Anon 1.01 seconds\n" ] } ], "source": [ "with open(fname) as f:\n", " for line in f:\n", " print(line, end=\"\")" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "
\n", "\n", "**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](https://docs.python.org/3.8/library/stdtypes.html#string-formatting). You can still use the more convenient new style formatting in your own messages.\n", "\n", "
" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "## Examples\n", "\n", "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:\n", "\n", " - checking the simulation parameters provided by the user for consistency and irregularities before the simulation is started\n", " - checking for errors and problems during the simulation" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Checking simulation parameters for plausibility" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "```python\n", "# Load the parameters\n", "timestep, lj_cutoff, pme_cutoff, boxsize = load_parameters() \n", "\n", "parameter_warnings = 0 # warning counter\n", "\n", "# Check whether the timestep is not larger than the usual upper limit\n", "if timestep > 2 femtoseconds:\n", " logging.warning(\"Timestep unusually large\")\n", " parameter_warnings += 1 # increase warning counter by 1\n", " \n", "\n", "# Check whether the cutoff values are identical\n", "if lj_cutoff != pme_cutoff:\n", " logging.error(\"Short range cutoff values don't match\")\n", " parameter_warnings += 1 # increase warning counter by 1\n", " \n", "\n", "# Check whether the cutoff values match the box size\n", "if lj_cutoff > boxsize/2:\n", " logging.error(\"Cutoff larger than half the box size. Some interactions may be included multiple times.\")\n", " parameter_warnings += 1 # increase warning counter by 1\n", "\n", " \n", "# Report whether all parameters are fine\n", "if parameter_warnings == 0:\n", " logging.info(\"All parameters are fine.\")\n", "```" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "### Catching possible errors during the simulation" ] }, { "cell_type": "markdown", "metadata": {}, "source": [ "```python\n", "# Monitor the distances for atomic clashes \n", "\n", "# Obtain the distances between atoms\n", "distances = compute_distance(positions)\n", "for d in distance:\n", " if d <= threshold:\n", " logging.error('Atoms are unusually close')\n", "\n", "\n", "# Monitor the forces for numerical overflows \n", " \n", "# Evaluate the forces\n", "forces = compute_forces(positions, potential)\n", "if any(np.isinf(forces)):\n", " logging.critical('Overflow in Forces')\n", " \n", "# Monitor the temperature for a drift\n", "# Temperature is not always, but often a conserved quantity in an MD simulation\n", "\n", "drift = compute_temperature_drift(this_frame, previous_frame)\n", "if drift > threshold:\n", " logging.warning('Temperature is Drifting')\n", "```" ] } ], "metadata": { "kernelspec": { "display_name": "Python 3", "language": "python", "name": "python3" }, "language_info": { "codemirror_mode": { "name": "ipython", "version": 3 }, "file_extension": ".py", "mimetype": "text/x-python", "name": "python", "nbconvert_exporter": "python", "pygments_lexer": "ipython3", "version": "3.6.10" }, "toc": { "base_numbering": 1, "nav_menu": {}, "number_sections": true, "sideBar": true, "skip_h1_title": false, "title_cell": "Table of Contents", "title_sidebar": "Contents", "toc_cell": false, "toc_position": {}, "toc_section_display": true, "toc_window_display": false } }, "nbformat": 4, "nbformat_minor": 2 }