Quartz 4

37. Logging Basics

9 min read

Note: I usually am using Jupyter Notebooks to store all the codes I am using for this Python Playlist, but for this lesson I’m going to use a .py file because otherwise I would have had to reset the Jupyter kernel every time I changed the default level of the logger.

Let’s start Logging in Python by calling on logging the corresponding methods for the log level that we want to use:

import logging
 
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

Here we have five different logging statements at five different logging levels. If we run this code, we’ll see only messages referred to warning, error and critical level:

WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

The reason is that the default log level of Python’s logger is warning, meaning that anything below warning in severity is ignored. So, even that we’ve made calls on debug and info level, the logger checks to see if each of those levels is at or above its current log level and then decide if its’ going to process the log message or not. This is one of the greatest advantages versus just using print() function, that is you can easily toggle the level of messages that your app is going to give out. Furthermore you don’t need to worry about adding and then removing or just commenting a bunch of print() statements in your codebase, and you can just instead add different level log statements and modify you logging level at runtime.

Let’s see how to modify this log level of this default logger:

import logging
 
logging.basicConfig(level=logging.INFO)
 
logging.debug("This is a debug message")
logging.info("This is an info message")
logging.warning("This is a warning message")
logging.error("This is an error message")
logging.critical("This is a critical message")

Output:

INFO:root:This is an info message
WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

Let’s talk about these levels:

  • debug: this is typically detailed information that most users likely shouldn’t see such as API responses, important variable values, or anything you think would be useful to help you track down potential bugs in your program by tracing your program’s execution.
  • info: this is typically the level most people set their debuggers to because this level should show program information that users are more likely interested in. These messages should also show normal program flow and success.
  • warning: these are typically problems that your program can adjust to. Things that the user likely should take some action to avoid in the future. Some examples are deprecation messages.
  • error: these are typically exceptions or other errors the program encounters at runtime These are likely going to be followed by raising some exception, but not always.
  • critical: these are rarely seen and they are fatal exceptions or system level issues. There’s a bit of a blur between what constitutes an error and what constitutes a critical.

Let’s analyze better this line logging.basicConfig(level=logging.INFO). INFO is uppercase because it’s a constant. Let’s take a look at it in the IPython shell:

>>> logging.DEBUG
10
>>> logging.INFO
20
>>> logging.WARNING
30
>>> logging.ERROR
40
>>> logging.CRITICAL
50

This means that the piece of code we are analyzing can be replaced with logging.basicConfig(level=20). Alternatively, there’s another way to do the same, that is just use the uppercase version of the level you want to use between quotes: logging.basicConfig(level="INFO").

It’s possible to see the corresponding integer value to each logging level with:

>>> logging._nameToLevel
{'CRITICAL': 50,
 'FATAL': 50,
 'ERROR': 40,
 'WARN': 30,
 'WARNING': 30,
 'INFO': 20,
 'DEBUG': 10,
 'NOTSET': 0}

This provides a handy dictionary which Python uses to lookup the corresponding value.

Formatting

Let’s make the logger messages more interesting by customizing its behaviour. Firstly, let’s give a name to the logger:

import logging
 
logger = logging.getLogger(name="myapp")
 
logger.debug("This is a debug message")
logger.info("This is an info message")
logger.warning("This is a warning message")
logger.error("This is an error message")
logger.critical("This is a critical message")

Output:

This is a warning message
This is an error message
This is a critical message

Note that

  • we lost both the debug and info level messages. The reason is that we haven’t actually set a log level for our logger and, since we’re also not setting on Python’s default logger, it now falls back to its original default of only logging messages that are warning and higher. To solve this we’ll use .set_Level() method. Let’s fix it:
logger = logging.getLogger(name="myapp")
logger.setLevel(logging.INFO)
  • we lost the message formatting we had previously. Let’s add some information to our log messages by creating our own formatter with Formatter() method, where fmt indicates the format of the message and style is necessary because Python needs to know what type of string replacement it needs to use to format the log message:
formatter = logging.Formatter(
    fmt="[{levelname} {name} {asctime}] {message}",
)

Now, we need to make a new Handler, that is an object that actually emit the log messages themselves. In this case we’ll use the default one. Then we’ll set the formatter and then we’ll add this handler object to the logger:

handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger.addHandler(handler)

Output:

[INFO myapp 2024-11-01 22:07:20,616] This is an info message
[WARNING myapp 2024-11-01 22:07:20,616] This is a warning message
[ERROR myapp 2024-11-01 22:07:20,616] This is an error message
[CRITICAL myapp 2024-11-01 22:07:20,616] This is a critical message

We can customize logger messages even more by specifying the date format in the formatter:

formatter = logging.Formatter(
    fmt="[{levelname} {name} {asctime}] {message}",
    datefmt="%H:%M:%S",
    style="{",
)

Here’s the output, which is more clean:

[INFO myapp 14:49:27] This is an info message
[WARNING myapp 14:49:27] This is a warning message
[ERROR myapp 14:49:27] This is an error message
[CRITICAL myapp 14:49:27] This is a critical message

Now the log messages look great, but all these log messages are cluttering up standard output, meaning that logging messages are being printed to the console (which is standard output) along with other important output the program might have. This can make it hard to see what’s relevant, as too many log messages can fill up the screen and make it difficult to read the actual results of the program. We can easily remedy by switching from logging everything to standard out by default to standard error by default. To make this, let’s import sys and let’s modify the handler object:

import logging
import sys
 
logger = logging.getLogger(name="myapp")
logger.setLevel(logging.INFO)
 
formatter = logging.Formatter(
    fmt="[{levelname} {name} {asctime}] {message}",
    datefmt="%H:%M:%S",
    style="{",
)
 
handler = logging.StreamHandler(stream=sys.stderr)
handler.setFormatter(formatter)
logger.addHandler(handler)
 
logger.debug("This is a debug message")
logger.info("This is an info message")
logger.warning("This is a warning message")
logger.error("This is an error message")
logger.critical("This is a critical message")

Output:

[INFO myapp 16:07:30] This is an info message
[WARNING myapp 16:07:30] This is a warning message
[ERROR myapp 16:07:30] This is an error message
[CRITICAL myapp 16:07:30] This is a critical message

Note that this output is not different from the one above. However, since we’re on Linux, we can do some things to test this out. Firstly, let’s add two print statements:

print("I'm here first!")
 
logger.debug("This is a debug message")
logger.info("This is an info message")
logger.warning("This is a warning message")
logger.error("This is an error message")
logger.critical("This is a critical message")
 
print("I'm here last!")

Now, since print() by default is going to go to standard out, we’ll redirect:

  • 1 (or standard out) to a file called stdout.log
  • 2 (or standard error) to a file called stderr.log and 2

To do so, we’ll hit in the terminal:

python 37.\ Logging\ Basics.py 1> stdout.log 2> stderr.log

This command creates two new files, one containing only print statements output and the other only logs messages:

This way you can keep things like standard out clean for things that use your app for automation, but you can still use standard error to present information to the console that looks like it’s mixed in with everything else. However, we don’t have to stop there because one of the great advantages of using logging is to be able to log to files. To log a file we’ll create file_handler object and we’ll use the same formatter object we used before:

file_handler = logging.FileHandler("myapp.log")
file_handler.setFormatter(formatter)

Furthermore we can also set different log level for file handler and then we’ll add this file handler to the logger (because we can have multiple handlers per logger):

file_handler.setLevel(logging.DEBUG)
logger.addHandler(file_handler)

So, when we call, for example, logger.warning("This is a warning message"), the logger is passing this log message not only to the StreamHandler, but also to FileHandler. However, this isn’t going to work yet because, even though the FileHandler is set to DEBUG, our main logger is still set to INFO; so when we call logger.debug("..."), the logger itself is never going to pass that along even though our underlying handler is at a lower level. In order to fix this, we’re going to set our logger to the lowest level that we want any of our handlers at (logger.setLevel(logging.DEBUG)) and our handlers need to have specific levels for each other. So, what we’ll do is to set a new level for our original handler object setting it to INFO and this way, when we call logger.debug("This is a debug message"), it’s going to pass. that debug message along to both our handlers:

  • our StreamHandler (that is handler) will not do anything with it because it’s set to INFO;
  • our FileHandler (that is file_handler) is going to take that and log it out because it is set to DEBUG.

Let’s rewrite the full corrected code:

import logging
import sys
 
logger = logging.getLogger(name="myapp")
logger.setLevel(logging.INFO)
 
formatter = logging.Formatter(
    fmt="[{levelname} {name} {asctime}] {message}",
    datefmt="%H:%M:%S",
    style="{",
)
 
handler = logging.StreamHandler(stream=sys.stderr)
handler.setFormatter(formatter)
handler.setLevel(logging.INFO)
logger.addHandler(handler)
 
file_handler = logging.FileHandler("myapp.log")
file_handler.setFormatter(formatter)
file_handler.setLevel(logging.DEBUG)
logger.addHandler(file_handler)
 
print("I'm here first!")
 
logger.debug("This is a debug message")
logger.info("This is an info message")
logger.warning("This is a warning message")
logger.error("This is an error message")
logger.critical("This is a critical message")
 
print("I'm here last!")

Then let’s run again:

python 37.\ Logging\ Basics.py 1> stdout.log 2> stderr.log

The console will look exactly the same as before:

I'm here first!
[INFO myapp 17:15:23] This is an info message
[WARNING myapp 17:15:23] This is a warning message
[ERROR myapp 17:15:23] This is an error message
[CRITICAL myapp 17:15:23] This is a critical message
I'm here last!

However, the file myapp.log will contain not only the log messages we have in our console, but also the debug level message:

This also shows the separation between our standard out printed messages and our log messages.

Graph View