Stop using Python’s print for your library

A short guide to getting starting with Python’s logging module.

Finally enough controls over the output. Image source.

We’ve all done this:

This is ridiculous!

Use Python’s logging module to clean up your logs.

All the code for the package can be found here.

Requirements

None — logging is built in. Note that we will be using python3.

A simple logging example

Let’s dive in with a simple logging example

The output will be:

This is for warnings  
This is for errors  
Again, this is for debugging  
Again, this is for info  
Again, this is for warnings  
Again, this is for errors

Notice that there is a StreamHandler called handlerPrint, and a logger called log.

Many different type of handlers exist as described here. They control where the output of the logs go.
You can create many different loggers with the getLogger(name) command — if the logger with the given name does not exist, it will be created.
Loggers can be assigned one or more handlers.

When do messages appear? Only if both the handler and the logger allow it. The possible logging levels are:

DEBUG  
INFO  
WARNING  
ERROR

The default level is WARNING.

Here we first turned the handler logging level to DEBUG, but the logger level is still the default WARNING.

Therefore, only the warning messages appear from the first part.

This is for warnings  
This is for errors

Next we turn on the logger to be DEBUG as well — now all messages will appear:

Again, this is for debugging  
Again, this is for info  
Again, this is for warnings  
Again, this is for errors

Configuration options =========================

Next we should dive into configuration options:

The output will be:

2020–07–03 11:22:05,323 | DEBUG | configuration.py | This is for debugging  
2020–07–03 11:22:05,323 | INFO | configuration.py | This is for info  
2020–07–03 11:22:05,323 | WARNING | configuration.py | This is for warnings  
2020–07–03 11:22:05,323 | ERROR | configuration.py | This is for errors

Fancy!

A complete list of formatting options is here.

Writing logs to files

A common use scenario is writing logs to a file. Simply add a new handler:

Notice the steps:

We created a new TimedRotatingFileHandler called handlerWrite. It writes to a log directory. Every hour, a new file will be created (when=”h” and interval=1). The new files will have an index number appended to them. A maximum of 24 files will exist — backupCount=23 plus the normal logs.log file. After this, logs will be overwritten.
Add the handler to the logger.
Set up the format for the handler. Here it is the same as for the print handler, but it can also be different.

Using the logging module in your library

Here are the official docs on configuring the logging module for your library.

But I’ll give you my unofficial take: the goals are two-fold:

Get global control over your module, letting you set the level for all your classes/methods.
Get local control over every class.

This is exactly what the division between handlers and loggers will let us do.

The scheme is:

Set up either one logger for your module, or if there are enough classes, one for each class. Put the names into the documentation.
Set up the formatter as desired, but just once for your entire module. Different output formats in the same module look terrible and are confusing.
If you want to collect all the logs from all the classes in a single file, also set up a single file that returns a configured TimedRotatingFileHandler(or whetever handler you like).
Remember that there are two controls for the logging level — the loggers and the handlers. The default level for both is WARNING.

The DEBUG level should only be relevant for you or other developers, but INFO may be interesting for everyone.

I therefore recommend to turn your loggers levels to INFO by default.

Let us create a module called mypackage with the following files:

mypackage/\_\_init\_\_.py  
mypackage/foo.py  
mypackage/bar.py  
mypackage/logging\_options.py  
test\_mypackage.py

Let’s look at the logging options first:

Here, we set up formatting and handlers for the entire module. In the foo.py and bar.py files, we use them as follows:

and almost identicalbar.py:

In the the test method test_mypackage.py, we can see how to selectively control output:

The output in the print stream is:

2020–07–03 12:42:34,401 | WARNING | foo.py | — — Starting do\_something — -

2020–07–03 12:42:34,402 | INFO | foo.py | Counting for 10 seconds

2020–07–03 12:42:34,402 | INFO | foo.py | count: 0

2020–07–03 12:42:34,402 | INFO | foo.py | count: 1

2020–07–03 12:42:34,402 | INFO | foo.py | count: 2

2020–07–03 12:42:34,402 | INFO | foo.py | count: 3

2020–07–03 12:42:34,402 | ERROR | foo.py | quitting early!

2020–07–03 12:42:34,402 | WARNING | foo.py | — — Finished do\_something — -

2020–07–03 12:42:34,403 | WARNING | foo.py | — — Starting do\_something — -

2020–07–03 12:42:34,403 | INFO | foo.py | Counting for 10 seconds

2020–07–03 12:42:34,403 | INFO | foo.py | count: 0

2020–07–03 12:42:34,403 | DEBUG | foo.py | cumulative count: 0

2020–07–03 12:42:34,403 | INFO | foo.py | count: 1

2020–07–03 12:42:34,403 | DEBUG | foo.py | cumulative count: 1

2020–07–03 12:42:34,403 | INFO | foo.py | count: 2

2020–07–03 12:42:34,403 | DEBUG | foo.py | cumulative count: 3

2020–07–03 12:42:34,404 | INFO | foo.py | count: 3

2020–07–03 12:42:34,404 | DEBUG | foo.py | cumulative count: 6

2020–07–03 12:42:34,404 | ERROR | foo.py | quitting early!

2020–07–03 12:42:34,404 | WARNING | foo.py | — — Finished do\_something — -

2020–07–03 12:42:34,404 | WARNING | bar.py | — — Starting do\_something — -

2020–07–03 12:42:34,405 | ERROR | bar.py | quitting early!

2020–07–03 12:42:34,405 | WARNING | bar.py | — — Finished do\_something — -

and in the log file:

2020–07–03 12:42:34,401 | WARNING | foo.py | — — Starting do\_something — -

2020–07–03 12:42:34,402 | INFO | foo.py | Counting for 10 seconds

2020–07–03 12:42:34,402 | INFO | foo.py | count: 0

2020–07–03 12:42:34,402 | INFO | foo.py | count: 1

2020–07–03 12:42:34,402 | INFO | foo.py | count: 2

2020–07–03 12:42:34,402 | INFO | foo.py | count: 3

2020–07–03 12:42:34,402 | ERROR | foo.py | quitting early!

2020–07–03 12:42:34,402 | WARNING | foo.py | — — Finished do\_something — -

2020–07–03 12:42:34,403 | WARNING | foo.py | — — Starting do\_something — -

2020–07–03 12:42:34,403 | INFO | foo.py | Counting for 10 seconds

2020–07–03 12:42:34,403 | INFO | foo.py | count: 0

2020–07–03 12:42:34,403 | DEBUG | foo.py | cumulative count: 0

2020–07–03 12:42:34,403 | INFO | foo.py | count: 1

2020–07–03 12:42:34,403 | DEBUG | foo.py | cumulative count: 1

2020–07–03 12:42:34,403 | INFO | foo.py | count: 2

2020–07–03 12:42:34,403 | DEBUG | foo.py | cumulative count: 3

2020–07–03 12:42:34,404 | INFO | foo.py | count: 3

2020–07–03 12:42:34,404 | DEBUG | foo.py | cumulative count: 6

2020–07–03 12:42:34,404 | ERROR | foo.py | quitting early!

2020–07–03 12:42:34,404 | WARNING | foo.py | — — Finished do\_something — -

2020–07–03 12:42:34,404 | WARNING | bar.py | — — Starting do\_something — -

2020–07–03 12:42:34,404 | INFO | bar.py | Counting for 5 seconds

2020–07–03 12:42:34,404 | INFO | bar.py | count: 0

2020–07–03 12:42:34,404 | INFO | bar.py | count: 1

2020–07–03 12:42:34,404 | INFO | bar.py | count: 2

2020–07–03 12:42:34,405 | ERROR | bar.py | quitting early!

2020–07–03 12:42:34,405 | WARNING | bar.py | — — Finished do\_something — -

We can therefore control output selectively for:

Different streams, such as printing and different file handlers.
Different classes / methods.
The entire module all at once.

Final thoughts

That does it for me, I’m tired of logging and blogging. All the code for the package can be found here.