Ease your pain with logging

My initial thought of using the logging mechanism is “why bother to create this because it will take up space in the system where the software gonna run, and why need it when python has an excellent error pointing mechanism”. But realized that I was wrong because it will ease your life later when you get a massage “it’s not working properly” or “program was broken” from your co-developer, testers or end users. Because proper logging mechanism can help you to find two things,

• What type of problem occurred
• What was the cause

With that in mind let’s look at what logging is and how it can be done in python using the logging package.

What is logging?

In simple terms, logging is keeping records. That records can be errors, states, or just pieces of information. That record can be about either the operating system or the program. Normally those records are messages, but they can be error traces or both. Massage is a very wide term because that massage can either tell about the action performed or exceptional details and much other valuable information. Typically log entries can be divided into

• Just information
• Warnings
• Errors

Why logging is important?

Logging is significant when you diagnose a bug or error. Here I mean a bug, where the program is working but does not give the expected outcome. Errors mean where the program breaks. In situations where you have to find out why the program breaks. The debugging process will be so easy if there is a way to see what inputs provide and what happened when the transformation or manipulation of given inputs. In these scenarios, logs will come handy. Because it will reduce the time needed to reproduce the inputs or combination of parameters or use cases that break the system or make it malfunction. Especially programs which tend to do a lot of transformation on input data, and systems that use to do critical missions.

Logging in python

Python has a package “logging” to ease the logging task. There are five types of logging in the logging package which is categorized based on the level or severity.

• INFO
• DEBUG
• WARNING
• ERROR
• CRITICAL

In default logging package only records above WARNING level messages. Of course, it can configure as the user need. Logging can be done two ways in the logging package, either the user can print massage in the terminal or can write those messages into a separate file.

Basic logging

The easiest way is to print the massage into the terminal, I say that because it can be done without any configuration,

The output will be like this in the terminal but note there is no INFO in the output because by default logging tracks only WARNING and above.

WARNING:root:this is a warning!

With little change to the configuration, we can log into a separate file. To reconfigure the logging can use the basicConfig() function. In the following code block uses a filename parameter to pass the name of the log file and note that change the level of tracking into DEBUG which now track all level above DEBUG and itself.

Calling the baseConfig() needs to do before any logging function (logging.debug, logging.error). Otherwise whichever logging function executes first will call basicConfig() with default values. basicConfig() is one-time execution until the session kills and restarts. After the first execution, it will do the append operation. By default, filemode parameter is set as append mode (‘a’) which appends log messages into an existing log file if the specified file does not exist then it will create a log file.

log into separate file

Advance logging

So far we saw a very simple program which consists single module, what about programs has multiple modules. This is two ways, either the program has multiple modules but has only one execution point meaning that only one place to initiate or use the functions or classes from another module, or it is possible that other modules also use separately like the python package, user can call functions or classes from any module into their programs. Approaches to these two situations are different indeed.

If there is only one place or script that can use all other modules it will be like this,

output .log file look like this,

logging into separate file with single root (only one execution point)

As you can see this has a single root, but you calling functions from a different module. This even works with a package-like file structure shown below,

package like file structure

If you want to add logging capability into the python package you create it will different how you use the configuration. In that case, more advanced concept call loggers can use to achieve this.

The first one is explicitly creating loggers, handlers and formatting of logging. This needs to be done on top of the python file. The second way is neater than the first one which is to use a python dictionary to configure the logging and pass it using dictConfig(). Third is the most elegant way of doing this which is using a .config file to create all configurations and use it with fileConfig(). Using loggers will allow us to create logging configurations that are different in the different modules of the package. Remember when using loggers you need to specify how you want to handle log entries either in a terminal or a separate file. Handlers are exists to create those handling of how log entries to output. There are mainly two handlers which are StreamHandler and FileHandler there are also other handler classes but these two are widely used ones.

If we want to create logging to the above package structure let’s see how we can do it by using the first method,

Let’s talk about some background details about the below example, it has two modules and each module has a single file. I’m writing the main program as a user of this module outside of its root folder. Files in each module are like this,

The main program of user programs like this,

With this configuration, you will get your output as this in your terminal,

call this to do something
call this to do something
main is calling do_something from module_y
main is calling do_something from module_y

Two write your log entries into a separate file what you should use is FileHandler. Like this,

Note: I am calling __name__ in to getLogger() function. It’s also possible for users to give custom names for the logger.

I’m not going to explain how to use a dictionary to do the configuration with a full example instead of I’ll show how to create the configuration dictionary.

When using dictConfig() there are a few rules to define a dictionary for your logging configurations. Let’s go through them one by one,

1. There are fixed values users should provide to configure the dictionary, I listed some of them here because most of the time you only use a few of them, these are more common than others. These act as keys in a dictionary you provide to dictConfig(). dictConfig will be looking for these. Most of them only accept dictionaries as correspondent values but there are few accept lists and there are few accept Boolean values. Note that some of them are compulsory to have and some are optional. version, handlers, loggers, root, disable_existing_loggers.
2. When giving values to dictionary keys, if those values need to match the data type those keys accept and when giving dictionaries those dictionaries need to follow the keys that are defined for giving values into those dictionaries. For example, when giving values to handles it must be a dictionary and that dictionary also has a predefined set of keys such as class, level etc. The user must include those keys without providing random keys to define the dictionary.
3. Users can provide multiple objects to some of the fields in the configuration dictionary. Such as fields like handlers this is not very useful if you are not define this dictionary with multiple ways to output log entries, for example, you only log warnings to the user in terminal error and debug messages are only put in a separate file, this can easily achieve by providing multiple handlers.
4. disable_existing_loggers is very important to set false if need to log entries from different modules. By default it is set to true, meaning it only logs massages from your running root.

Now let’s see the same example with the use of a separate file. First, let’s see how we can use the .json file to store configuration and use it in different modules with different settings.

This is how our configuration JSON looks like,

This is what our modules and user main.py look like when using .json to load configuration,

Note: error log into our .log file but other than the error messages did not print in the terminal. This behavior happens because of level hierarchy in the logging library, will see this in more detail later.

Terminal results,

call this to do something
this is a random error message from lib_x.
call this to do something
this is a random error message

.log file after execution,

.log file

We can use a .config file as well,

Here is what our .config file looks like,

The only change for the above example is,

Remember when using .config need to specify a formatter to format your log entries because it doesn’t have a default format. Will discuss formatting later with more details. Also, users can create different log configurations for different modules rather than one master configuration file, in the system which files structure will look like this,

config file for each module

Each module has its logging configuration which will enable a lot of flexibility when need to maintain different logging mechanisms based on module functionality.

Understand logging levels

Understanding the levels in the logging library is essential when you use log messages from multiple modules because we need to configure loggers when you config them to a certain level of tracking it will normally track the log entries from the specified level to all the higher levels of the program. So if you config logger into the wrong level you didn’t get the desired result.

The level of severity is increasing downwards in this figure and higher levels (top to bottom order) can see all the levels below them, meaning when you set a certain logging level it will track all the other levels below that specified level. For example, DEBUG will track all the other levels.

levels of logging

Let’s look at an example we used before,

Here we define the root logging level as DEBUG so it will track all the levels of log entries. But instead of DEBUG you set ERROR then the logger will track only ERROR and CRITICAL level log entries. Even if you added INFO or DEBUG log entries logger will ignore them.

Formatting log massages

So far we only use default formatting of log massage, just printing string. But we can change that behavior to log more valuable information with string formatting. Users can add variable values, date and time of log entered and module name or file name, error trace etc.

Note: error trace can be added using .error() function stack_info parameter.

This can do in every way of configuring logging we discussed so far with basicConfig(), dictConfig() and fileConfig. But the way you do it is different. Let’s jump into action,

First see how basicConfig() do it,

We can specify custom formats for basic configuration functions using format parameters like in this example,

Output in the terminal will look like this,

2023-02-27 13:28:54,503 DEBUG: start execution
2023-02-27 13:28:54,503 INFO: main is calling do_something from module_x
2023-02-27 13:28:54,503 INFO: main is calling do_something from module_y
2023-02-27 13:28:54,503 DEBUG: end execution
2023-02-27 13:28:54,503 ERROR: this is a random error message

This is also the same if you use a .log file instead of terminal output.

Finally, let’s see how dictionary configuration can be modified to add custom formatting to log messages.

Here I used the same example as in using dictionary configuration using a .json file. Only changes were done to the configuration file where I added the formatters section.

Here is what it looks like when messages are logged,

This log file has lot of information in it’s log entries such as there is the date and time the log created, level of the log tracking and it tells us where it came from which file and line number and even what were the function or method. this is how we can log massages can format to get more valuable information from and about the program.

One final thought, when you logging information don’t log things that may put you and your user put in risk such as usernames, passwords, emails …

Author

Credits for this article must go to the following author for contributing their time, effort, and knowledge to the Technoid Community.

Author: Ashen Hewarathna

See also

• Logging documentation: https://docs.python.org/3/contents.html