Logging

As you probably noticed almost no package, e.g. numpy has print functions. Most packages use so called logging. Logging enables you to turn on/off printing depending on the logging mode. It is a standard python built-in, so I suggest you make use of it

Setting up your logging

A standard practice is to set the logger in the matpy.__init__ using Python’s built-in logging module.

 1from __future__ import (absolute_import, print_function, division)
 2import logging
 3from .log_util import VERBOSE
 4from .log_util import modify_logger
 5
 6# Setup the logger
 7logger = logging.getLogger("matpy")
 8modify_logger(logger)
 9
10'''The different levels are
11
12 0: logging.NOTSET
1310: logging.DEBUG
1415: logging.VERBOSE
1520: logging.INFO
1630: logging.WARNING
1740: logging.ERROR
1850: logging.CRITICAL
19
20'''
21
22logger.setLevel(logging.VERBOSE)
23
24
25'''The following line is simply used to make it possible to 
26
27.. code-block::
28    
29    from matpy import MatrixMultiplication
30    
31instead of 
32
33.. code-block::
34    
35    from matpy.matrixmultiplication import MatrixMultiplication
36    
37which is still a valid statement.
38
39Note the  "#NOQA" after the statement? This is used to note make an additional
40automatic documentation entry.
41
42'''
43from .matrixmultiplication import MatrixMultiplication  # NOQA

The outline is as follows:

  1. Retrieve the module’s logger

  2. Use how it outputs stuff using the matpy.log_util.modify_logger()

  3. Set logging level

All necessary code for modifying the logging is located in the matpy.log_util. The code is shown below and not all too complicated, but it is ‘long’. Do not get intimidated and continue below!

  1#!/usr/bin/env python
  2
  3"""
  4
  5This module includes a custom logger to make it easier to identify errors and
  6debug etc.
  7
  8The module adds both another level to the logger and the corresponding
  9formatter. If you want to remove or add any logging level make sure to edit
 10both the CustomLogger and the CustomFormatter to accommodate your changes!
 11
 12:author:
 13    Lucas Sawade (lsawade@princeton.edu, 2019)
 14
 15:license:
 16    GNU Lesser General Public License, Version 3
 17    (http://www.gnu.org/copyleft/lgpl.html)
 18"""
 19import logging
 20
 21from logging import getLoggerClass
 22from logging import NOTSET
 23
 24VERBOSE = 15
 25
 26
 27def addLoggingLevel(levelName, levelNum, methodName=None):
 28    """
 29    Comprehensively adds a new logging level to the `logging` module and the
 30    currently configured logging class.
 31
 32    `levelName` becomes an attribute of the `logging` module with the value
 33    `levelNum`. `methodName` becomes a convenience method for both `logging`
 34    itself and the class returned by `logging.getLoggerClass()` (usually just
 35    `logging.Logger`). If `methodName` is not specified, `levelName.lower()` is
 36    used.
 37
 38    To avoid accidental clobberings of existing attributes, this method will
 39    raise an `AttributeError` if the level name is already an attribute of the
 40    `logging` module or if the method name is already present
 41
 42    .. rubric:: Example
 43
 44    .. code-block:: python
 45
 46        addLoggingLevel('TRACE', logging.DEBUG - 5)
 47        logging.getLogger(__name__).setLevel("TRACE")
 48        logging.getLogger(__name__).trace('that worked')
 49        logging.trace('so did this')
 50        logging.TRACE
 51        5
 52
 53    Taken from StackOverflow because the code was beautifully simple.
 54    Author: Mad Physicist (Mar 4, 2016)
 55
 56    """
 57    if not methodName:
 58        methodName = levelName.lower()
 59
 60    if hasattr(logging, levelName):
 61        raise AttributeError(
 62            '{} already defined in logging module'.format(levelName))
 63    if hasattr(logging, methodName):
 64        raise AttributeError(
 65            '{} already defined in logging module'.format(methodName))
 66    if hasattr(logging.getLoggerClass(), methodName):
 67        raise AttributeError(
 68            '{} already defined in logger class'.format(methodName))
 69
 70    # This method was inspired by the answers to Stack Overflow post
 71    # http://stackoverflow.com/q/2183233/2988730, especially
 72    # http://stackoverflow.com/a/13638084/2988730
 73    def logForLevel(self, message, *args, **kwargs):
 74        if self.isEnabledFor(levelNum):
 75            self._log(levelNum, message, args, **kwargs)
 76
 77    def logToRoot(message, *args, **kwargs):
 78        logging.log(levelNum, message, *args, **kwargs)
 79
 80    logging.addLevelName(levelNum, levelName)
 81    setattr(logging, levelName, levelNum)
 82    setattr(logging.getLoggerClass(), methodName, logForLevel)
 83    setattr(logging, methodName, logToRoot)
 84
 85
 86class CustomLogger(getLoggerClass()):
 87    """
 88    This class is just created ot add the VERBOSE level. More
 89    level could be added to this class to accommodate other levels.
 90
 91    The variable VERBOSE is given at the top of the module. That way it can be
 92    changed for all depending function
 93
 94    The class makes it possible to add extra levels to the classic logger
 95    The line `addLoggingLevel("VERBOSE", VERBOSE)` in the initalization is
 96    an example on how to add a level using the `addLoggingLevel` function
 97    located in this module.
 98
 99    Don't forget to edit the `CustomFormatter` to accommodate for your
100    introduced levels if you are using the `CustomFormatter`.
101    An example is given in the class under `# EXTRA LEVELS` for the
102    `VERBOSE` level.
103
104    """
105
106    def __init__(self, name, level=NOTSET):
107        super().__init__(name, level)
108
109        addLoggingLevel("VERBOSE", VERBOSE)
110
111
112class CustomFormatter(logging.Formatter):
113    """
114    Logging Formatter to add colors and count warning / errors
115
116    This class organizes the customization of the logging output.
117    The formatter as of now outputs the logs in the following manner in
118    order of Loglevel:
119
120    .. rubric:: Example Output
121
122    .. code-block:: python
123
124        [2020-04-03 14:17:18] -- matpy.matrixmultiplication ----- [INFO]: Initializing matrices...
125        [2020-04-03 14:17:18] -- matpy.matrixmultiplication ---- [ERROR]: Test Error Level (matrixmultiplication.py:60)
126        [2020-04-03 14:17:18] -- matpy.matrixmultiplication - [CRITICAL]: Test Critical Level (matrixmultiplication.py:61)
127        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]: Test Verbose Level
128        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]: A:
129        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [1 2]
130        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [3 4]
131        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]: B:
132        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [2 3 5]
133        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [4 5 6]
134        [2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [WARNING]: Matrix size exceeds 4 elements.
135
136    These outputs are colored in the actual output but the formatting is just
137    as shown above. VERBOSE is an extra added LogLevel formatting. More can be
138    added below the comment `EXTRA LEVELS` in the same way the VERBOSE is added.
139
140    The variable VERBOSE is given at the top of the module. That way it can be
141    changed for all depending function
142
143    """
144
145    # Setting up the different ANSI color escape sequences for color terminals:
146    # Codes are 3/4-bit codes from here:
147    # https://en.wikipedia.org/wiki/ANSI_escape_code
148    # For 8-colors: use "\x1b[38;5;<n>m" where <n> is the number of the color.
149    grey = "\x1b[38;21m"
150    green = "\x1b[38;5;64m"
151    light_grey = "\x1b[38;5;240m"
152    dark_blue = "\x1b[38;5;25m"
153    light_blue = "\x1b[38;5;69m"
154    yellow = "\x1b[33;21m"
155    red = "\x1b[31;21m"
156    dark_red = "\x1b[38;5;97m"
157    bold_red = "\x1b[31;1m"
158    reset = "\x1b[0m"
159
160    # Formats The spaces accommodate the different length of the words and
161    # amount of detail wanted in the message:
162    time_fmt = light_grey + "[%(asctime)s]" + reset
163    name_fmt = "-- %(name)s -"
164    pre_fmt = time_fmt + " " + name_fmt
165
166    debug_fmt = "--- [" + light_blue + "%(levelname)s" + reset + "]:" \
167        + light_blue + " %(message)s (%(filename)s:%(lineno)d)" + reset
168    info_fmt = "---- [%(levelname)s]: %(message)s"
169    warning_fmt = "- [" + yellow + "%(levelname)s" + reset + "]:" \
170                 + yellow + " %(message)s" + reset
171    error_fmt = "--- [" + red + "%(levelname)s" + reset + "]:" \
172        + red + " %(message)s (%(filename)s:%(lineno)d)" + reset
173    critical_fmt = " [" + bold_red + "%(levelname)s" + reset + "]:" \
174        + bold_red + " %(message)s (%(filename)s:%(lineno)d)" + reset
175
176    # Create format dictionary
177    FORMATS = {
178        logging.DEBUG: pre_fmt + debug_fmt,
179        logging.INFO: pre_fmt + info_fmt,
180        logging.WARNING: pre_fmt + warning_fmt,
181        logging.ERROR: pre_fmt + error_fmt,
182        logging.CRITICAL: pre_fmt + critical_fmt
183    }
184
185    # EXTRA LEVELS
186    # Verbose
187    addLoggingLevel('VERBOSE', VERBOSE)
188    verbose_fmt = "- [%(levelname)s]: %(message)s"
189    FORMATS[logging.VERBOSE] = pre_fmt + verbose_fmt  # add to format dictionary
190
191    # Initialize with a default logging.Formatter
192    def __init__(self):
193        super().__init__(fmt="-- %(name)s ---- [%(levelname)s]: %(message)s",
194                         datefmt=None, style='%')
195
196    def format(self, record):
197
198        # Use the logging.LEVEL to get the right formatting
199        log_fmt = self.FORMATS.get(record.levelno)
200
201        # Create new formatter with modified timestamp formatting.
202        formatter = logging.Formatter(log_fmt, "%Y-%m-%d %H:%M:%S")
203
204        # Return
205        return formatter.format(record)
206
207
208def modify_logger(logger):
209
210    # Make sure only this module prints the logger information.
211    logger.propagate = 0
212
213    # Add formatter
214    ch = logging.StreamHandler()
215    ch.setFormatter(CustomFormatter())
216    logger.addHandler(ch)
217
218    return logger

There are 3-4 important things here. The first one is the matpy.log_util.CustomLogger. The matpy.log_util.CustomLogger simply takes logging.Logger and adds another Logging (see below) level by using the function matpy.log_util.addLoggingLevel(). That’s all the functions are doing. Of course there are some details in matpy.log_util.addLoggingLevel(), but those are simply there to handle the adding if the matpy.log_util.CustomLogger is called multiple times so that the Logging level is not overwritten. The most important part (why I started writing the logging docs) is the matpy.log_util.CustomFormatter. The matpy.log_util.CustomFormatter is a basic class containing some info that specifies the nature of the logged print statements, i.e., colors and whether a certain statement should be print depending on the logging levels etc. It’s basic string formatting that depends on the level of the statements.

There are a number 6 different logging levels:

    1. Not-set

    1. Debug

    1. Info

    1. Warning

    1. Error

    1. Critical

In general, the lower the debug level the larger the number of messages. Meaning, if the level is set to 50, only Critical messages will be printed, but if the level is set to 20, Critical, Error, Warning, and Info messages will be printed.

We can in theory create a different format for any of those message-levels. When debugging for examples this can be a huge advantage, because you can assign a different color to the debugging messages and find the correct lines faster.

The logging level of any package can be set by any script from anywhere by retrieving the logger and setting the level:

import logging

# Retrieve logger
logger = logging.getLogger("matpy")

# Set level
logger.setLevel(logging.INFO)

For this package, we put set the level to VERBOSE, so that all messages are printed. Except the DEBUG message. An example output:

[2020-04-03 14:17:18] -- matpy.matrixmultiplication ----- [INFO]: Initializing matrices...
[2020-04-03 14:17:18] -- matpy.matrixmultiplication ---- [ERROR]: Test Error Level (matrixmultiplication.py:60)
[2020-04-03 14:17:18] -- matpy.matrixmultiplication - [CRITICAL]: Test Critical Level (matrixmultiplication.py:61)
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]: Test Verbose Level
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]: A:
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [1 2]
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [3 4]
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]: B:
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [2 3 5]
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [VERBOSE]:     [4 5 6]
[2020-04-03 14:17:18] -- matpy.matrixmultiplication -- [WARNING]: Matrix size exceeds 4 elements.

Then, just as in matpy.matrixmultiplication.matmul(), the logger can print statements much like the normal print function.

# Setup Logger at the top of your module
import logging
from .log_util import modify_logger

logger = logging.getLogger(__name__)
modify_logger(logger)

logger.debug("Test Debug")
logger.error("Test Error")
logger.critical("Test Critical")
logger.info("Test info")
logger.warning("Test Warning")

The last important this is modify logger. I wish it wasn’t so but it also has to be run to apply the matpy.log_util.CustomFormatter because the intrinsic logging facility has its one format. Just to explain it see the code below.

def modify_logger(logger):

    # Make sure only this module prints the logger information.
    logger.propagate = 0

    # Add formatter
    ch = logging.StreamHandler()
    ch.setFormatter(CustomFormatter())
    logger.addHandler(ch)

    return logger

The propagate module sets only that the logging statements are not propagated to a parent module, so that this is the only module to print the messages. The loggingStreamHandler handles how stuff is output, in our case we want it to be output in a specific format, so we set our matpy.log_util.CustomFormatter. The formatter is optional but convenient. instead of the matpy.log_util.CustomFormatter, a “simple”

# Customformatter
FORMAT = "%(name)s - %(levelname)s: %(message)s"
formatter = logging.Formatter(FORMAT)
ch.setFormatter(formatter)

would have worked as well, but let me elaborate the benefits (beauty) of a truly custom formatter.

So, now you are all set for logging! Feel free to modify the logging!