Logging in Python

Setting up an application or a library to log is not just good practice; it is a key task of a responsible developer. It is as important as writing documentation or tests. Many people consider logging the runtime documentation, the same way developers read the documentation when interacting with the DevOps source code, and other developers will use the log traces when the application is running.

Hardcore logging advocates state that debuggers are extremely overused, and people should rely more on logging, using both info and trace logs to troubleshoot their code in development.

The idea is that if you are not able to troubleshoot your code with the highest level of verbosity in development, then you may have issues in production that you won’t be able to figure out the root issue of. In this part, we will cover how logging works and how to configure it to not fall into those kinds of issues.

Using logging

Logging is the best way to let the users of the running application know which state the process is in and how it is processing its work. It can also be used for auditing or troubleshooting client issues. There is nothing more frustrating than trying to figure out how your application behaved last week and having no information at all about what happened when it faced an issue.

You should also be careful about what information we log. Many companies will require users to never log information such as credit cards or any sensitive user data. While it is possible to conceal such data after it is logged, it is better to be mindful when we log it.

You might wonder what is wrong with just using print statements, but when you start to write large-scale applications or libraries, you realize that just using print does nothing to instrument an application. By using the logging module, you also get the following:

• Multithreading support: The logging module is designed to work in multithreaded environments. This is needed when using multiple threads as, otherwise, the data that you log will get interleaved, as can happen with print.
• Categorization through multiple levels of logging: When using print, there is no way to transmit the importance of the log trace being emitted. By using logging, we can choose the category that we want to log under to transmit its importance.
• Separation of concerns between instrumentation and configuration: There are two different users of the logging library: those who just emit and those who configure the logging stack. The logging library separates those nicely, allowing libraries and applications to just instrument their code with logs at different levels, and the final user to configure the logging stack at will.
• Flexibility and configurability: The logging stack is easily extensible and configurable. There are many types of handlers, and it is trivial to create new classes that extend its functionality. There is even a cookbook on how to extend the logging stack in the Standard Library documentation.

The main class you interact with when using the logging library is logger. It can be used to emit logs in any category. You usually create loggers objects by getting them through the logging.getLogger(<logger name>) factory method.

Once you have a logger object, you can call the different logging methods that match the different default categories in which you are able to log:

• debug: Fine-grained messages that are helpful for debugging and troubleshooting applications, usually enabled in development. As an example, a web server will log the input payload when receiving a request at this level.
• info: Coarse-grained informational messages that highlight the progress of an application. As an example, a web server will emit the requests being handled at this level without details of the data being received.
• warning: Messages that inform the user of a potentially harmful situation in the application or library. In our example of a web server, this will happen if you fail to decode an input JSON payload because it is corrupted. Note that while it might feel like an error and it might be for the whole system, if you own the frontend as well, the issue is not in the application handling the request; it is in the process sending it. Therefore, a warning might help notify the user of such an issue, but it is not an error. The error should be reported to the client as an error response, and the client should handle it as appropriate.
• error: Used for situations where an error has taken place but the application can continue to function properly. Logging an error usually means there is an action that needs to be carried out by a developer in the source code that logged it. Logging errors commonly happen when you capture an exception and have no way of handling it effectively. It is quite common to set up alerts in connection with errors to inform the DevOps or developer that an error situation took place. In our web server application, this might happen if you fail to encode a response or an exception is raised that was not expected when handling the request.
• fatal: Fatal logs indicate that there has been an error situation that compromises the current stability of the program, and, quite often, the process is restarted after a fatal message is logged. A fatal log means that the application needs an operator to take action urgently, compared to an error that a developer is expected to handle. A common situation is when the connection to a database is lost, or any other resource that is key for the application is no longer reachable.

Logger object

Loggers have a hierarchy of names split by a dot. For example, if you ask for a logger named my.logger, you are creating a logger that is a child of my, which is a child of the root logger. All top-level loggers “inherit” from the root logger.

You can get the root logger by calling getLogger without arguments or by logging directly with the logging module. A common practice is to use __name__ as the logger module. This makes your logging hierarchy follow your source code hierarchy. Unless you have a strong reason not to do that, use __name__ when developing libraries and applications.

Exercise 94 – using a logger object

The goal of this exercise is to create a logger object and use four different methods that allow us to log in the categories mentioned earlier in the Logging in Python section:

1. Import the logging module:

   import logging

2. Create a logger object:

We can now get a logger object through the getLogger factory method:

logger = logging.getLogger("logger_name")

This logger object will be the same everywhere, and you call it with the same name.

3. Log with different categories:

   logger.debug("Logging at debug")

   logger.info("Logging at info")

   logger.warning("Logging at warning")

   logger.error("Logging at error")

   logger.fatal("Logging at fatal")

The output is as follows:

Figure 6.28 – The output of running logging

By default, the logging stack will be configured to log records on level warning and above (error and critical), which explains why you only see those levels being printed to the console. You will see later how to configure the logging stack to include other levels, such as info. Use files or a different format to include further information.

4. Include information when logging:

   system = "moon"

   for number in range(3):

       logger.warning("%d errors reported in %s", number, system)

Usually, when you log, you don’t pass just a string but also some variable or information that helps us with the current state of the application:

Figure 6.29 – The output of running warning logs

Note

You use Python standard string interpolation, and you pass the remainder of the variables as attributes. %d is used to format numbers, while %s is used for strings. The string interpolation format also has syntax to customize the formatting of numbers or to use the repr of an object.

After this exercise, you now know how to use the different logger methods to log in different categories depending on the situation. This will allow you to properly group and handle your application messages.

Logging in warning, error, and fatal categories

You should be mindful when you log in the warning, error, and fatal categories. If there is something worse than an error, it is two errors. Logging an error is a way of informing the system of a situation that needs to be handled, and if you decide to log an error and raise an exception, you are basically duplicating the information. As a rule of thumb, following these two pieces of advice is key to an application or library that logs errors effectively:

• Never ignore an exception that transmits an error silently. If you handle an exception that notifies you of an error, log that error.
• Never raise and log an error. If you are raising an exception, the caller has the ability to decide whether it is truly an error situation, or whether they were expecting the issue to occur. They can then decide whether to log it following the previous rule, to handle it, or to re-raise it.

A good example of where the user might be tempted to log an error or warning is in the library of a database when a constraint is violated. From the library perspective, this might look like an error situation, but the user might be trying to insert it without checking whether the key was already in the table. The user can therefore just try to insert and ignore the exception, but if the library code logs a warning when such a situation happens, the warning or error will just spew the log files without a valid reason. Usually, a library will rarely log an error unless it has no way of transmitting the error through an exception.

When you are handling exceptions, it is quite common to log them and the information they come with. If you want to include the exception and trace back the full information, you can use the exc_info argument in any of the methods that we saw before:

try:
    int("nope")
except Exception:
    logging.error("Something bad happened", exc_info=True)

The output is as follows:

Figure 6.30 – Example output when logging an exception with exc_info

The error information now includes the message you passed in, but also the exception that was being handled with the traceback. This is common and so useful that there is a shortcut for it. You can call the exception method to achieve the same as using error with exc_info:

try:
    int("nope")
except Exception:
    logging.exception("Something bad happened")

The output is as follows:

Figure 6.31 – Example output when logging an exception with the exception method

Now, you will review two common bad practices with the logging module.

The first one is greedy string formatting. You might see some linters complain about formatting a string by the user rather than relying on the logging module’s string interpolation. This means that logging.info(“string template %s”, variable) is preferred over logging.info(“string template {}”.format(variable)). This is the case since if you perform the string interpolation with the format, you will be doing it no matter how we configure the logging stack. If the user who configures the application decides that they don’t need to print out the logs in the information level, you will have to perform interpolation when it wasn’t necessary:

# prefer
logging.info("string template %s", variable)
# to
logging.info("string template {}".format(variable))

Note

Linters are programs that detect code style violations, errors, and suggestions for the user.

The other, more important, bad practice is capturing and formatting exceptions when it’s not really needed. Often, you see developers capturing broad exceptions and formatting them manually as part of a log message. This is not only a boilerplate but also less explicit. Compare the following two approaches:

d = dict()
# Prefer
try:
    d["missing_key"] += 1
except Exception:
    logging.error("Something bad happened", exc_info=True)
# to
try:
    d["missing_key"] += 1
except Exception as e:
    logging.error("Something bad happened: %s", e)

The output is as follows:

Figure 6.32 – Example output difference of exc_info versus logging an exception string

The output in the second approach will only print the text of the exception, without further information. We don’t know whether it was a key error, nor where the issue appeared. If the exception was raised without a message, we would just get an empty message. Additionally, if logging an error, use an exception, and you won’t need to pass exc_info.

Configuring the logging stack

Another part of the logging library is the functions to configure it, but before diving into how to configure the logging stack, you should understand its different parts and the role they play.

You’ve already seen logger objects, which are used to define the logging messages that need to be generated. There are also the following classes, which take care of the process of processing and emitting a log:

• Log records: This is the object that is generated by the logger and contains all the information about the log, including the line where it was logged, the level, the template, and arguments, among others.
• Formatters: These take log records and transform them into strings that can be used by handlers that output to streams.
• Handlers: These are the ones that actually emit the records. They frequently use a formatter to transform records into strings. The Standard Library comes with multiple handlers to emit log records into stdout, stderr, files, sockets, and so on.
• Filters: Tools to fine-tune log record mechanisms. They can be added to both handlers and loggers.

If the functionality that is already provided by the Standard Library is not enough, you can always create your own kind of classes that customize how the logging process is performed.

Note

The logging library is truly flexible. If you are interested in doing so, read through the logging cookbook in the Python official documentation to see some examples at https://docs.python.org/3/howto/logging-cookbook.html.

Armed with this knowledge, there are multiple ways to configure all of the elements of the logging stack. You can do so by plugging together all the classes manually with code, passing dict via logging.config.dictConfig, or through an ini file with logging.config.iniConfig.

Exercise 95 – configuring the logging stack

In this exercise, you will learn how to configure the logging stack through multiple methods to output log messages to stdout.

You want to configure the logging stack to output logs to the console, which should look like this:

Figure 6.33 – Outputting logs to the console

Note

The background is white, which means the output went to stdout and not stderr, as in the previous examples. Make sure to restart the kernel or interpreter every time prior to configuring the logging stack.

You will see how you can configure it with code, with a dictionary, with basicConfig, and with a config file:

1. Open a new Jupyter notebook.
2. Start with configuring the code.

The first way to configure the stack is by manually creating all the objects and plugging them together:

import logging
import sys
root_logger = logging.getLogger()
handler = logging.StreamHandler(sys.stdout)
formatter = logging.Formatter("%(levelname)s: %(message)s")
handler.setFormatter(formatter)
root_logger.addHandler(handler)
root_logger.setLevel("INFO")
logging.info("Hello logging world")

The output will be as follows:

INFO: Hello logging world

In this code, you get a handle of the root logger in the third line by calling getLogger without any arguments. You then create a stream handler, which will output to sys.stdout (the console) and a formatter to configure how we want the logs to look. Finally, you just need to bind them together by setting the formatter in the handler and the handler in the logger. You set the level in the logger, though you could also configure it in the handler.

3. Restart the kernel on Jupyter and now use dictConfig to achieve the same configuration:

Exercise95.ipynb

import logging
from logging.config import dictConfig
dictConfig({
    "version": 1,
    "formatters": {
        "short":{
            "format": "%(levelname)s: %(message)s",
        }
    },
    "handlers": {
       "console": {
            "class": "logging.StreamHandler",
            "formatter": "short",
            "stream": "ext://sys.stdout",
      "level": "DEBUG",
      }
    },
    "loggers": {
        "": {
            "handlers": ["console"],
            "level": "INFO"
        }   
    }
})
logging.info("Hello logging world")

Note

If the previous link does not render, use https://nbviewer.jupyter.org/.

The output will be as follows:

INFO: Hello logging world

The dictionary configuring the logging stack is identical to the code in step 1. Many of the configuration parameters that are passed in as strings can also be passed as Python objects. For example, you can use sys.stdout instead of the string passed to the stream option, or logging.INFO rather than INFO.

Note

The code in step 3 is identical to the code in step 2; it just configures it in a declarative way through a dictionary.

4. Now, again, restart the kernel on Jupyter and use basicConfig as mentioned in the following code snippet:

   import sys

   import logging

   logging.basicConfig(

       level="INFO",

       format="%(levelname)s: %(message)s",

       stream=sys.stdout

   )

   logging.info("Hello there!")

The output will be as follows:

INFO: Hello there!

The logging stack comes with a utility function, basicConfig, which can be used to perform some basic configurations, such as the one we’re performing here, as mentioned in the code snippet that follows.

5. Another way to configure the logging stack is by using an ini file. We require an ini file, as follows:

   logging-config.ini

   [loggers]

   keys=root

   [handlers]

   keys=console_handler

   [formatters]

   keys=short

   [logger_root]

   level=INFO

   handlers=console_handler

   [handler_console_handler]

   class=StreamHandler

Note

If this code does not render, use https://nbviewer.jupyter.org/.

You can then load it with the following code:

import logging
from logging.config import fileConfig
fileConfig("logging-config.ini")
logging.info("Hello there!")

The output will be as follows:

INFO: Hello there!

All applications should configure the logging stack only once, ideally at startup. Some functions, such as basicConfig, will not run if the logging stack has already been configured.

You now know all of the different ways to configure an application’s logging stack. This is one of the key parts of creating an application.

In the next topic, you will learn about collections.