Basic usage of python logging module

Basic usage of python logging module#

Paola Petrelli, CLEX CMS

Most people use print statements to debug their code, uncommenting them when they need them and commenting them again when they have finished.
Python has some proper debugging modules like pdb or you might be using an IDE with debug functionality like pycharm .
Look here for a list: https://wiki.python.org/moin/PythonDebuggingTools ).
While these tools are certainly good, in this blog I will show you how to use the logging module. This module, used in a basic mode, is as easy as printing statements but will give you a lot more control on your code and the ability to eventually add more advanced features.
As well as demostrating some simple usage of logging, I will touch on other simple but useful debugging tools: the functions type() and dir() and the try/except control flow.
logging is part of the python distribution so you do not need to install or load anything else, simply import the module.

NB I am using python3.5 there might be difference if you are using a different version. Also jupyter can send your logging output to the terminal rather then the cell and generally interacts with logging in its own way. While you might be able to fix this after reading the blog, using python would make reproducing this easier.

import logging

Now we are ready to start!

Printing out messages and logging levels#

logging.warning('This is a warning message this should be printed on your console')
logging.info('This is an info message the code will not print this unless you change its operating level')

All we have to do is to call one of the logging printing method, we used warning and info.
Let’s have a look at the message we printed.
The first part indicates the logging level, in this case WARNING.
The second part root is telling us that we are using the root logger i.e. the default logger, in fact we haven’t set up anything up to now, but just started using logging. Finally there is the message.
The logging.info command didn’t produce any output. Logging has 5 different levels. From the lowest:

DEBUG
INFO
WARNING
ERROR
CRITICAL

Logging will only show the messages which are of level >= of the set level, the default level is warning so our info message is not getting printed.
Let’s change the level.

logging.basicConfig(level=logging.INFO)  # Note the logging levels are defined in the logging attributes, not by a string!
logging.warning('This is a warning message this should be printed on your console, its level is above the set level')
logging.info('This is an info message it should be printed now!')
logging.debug('This is a debug message which will not be shown, its level is below the set level')

Oops nothing happened, the level is still set to warning. Let’s pretend we researched this, there could various situations when this happens. In my brief experience, it is usually because: This function does nothing if the root logger has already handlers configured.
The root logger is set up so you can get logging to work straight on as we did. Loggers are the logging objects we are dealing with. Like all other python variables, they have some attributes and some methods. So when we use logging.info() for example we are calling the method info() of our root logger. A logging handler takes a log message and send it to an output, this could the console (default) or a file, an e-mail or more complex outputs.
This might seems complicated but now that we know there is already a logger defined, we know we need to disable it somehow.
We can use two approaches:

disable the root logger handlers and start afresh
setup our own logger object pointing at the root logger

Let’s start with disabling the root logger handlers first and then we’ll see how to set our own logger.

# Remove all handlers associated with the root logger object.
for handler in logging.root.handlers[:]:
    logging.root.removeHandler(handler)
logging.basicConfig(level=logging.INFO) 
logging.warning('This is a warning message this should be printed on your console, its level is above the set level')
logging.info('This is an info message it should be printed now!')
logging.debug('This is a debug message which will not be shown, its level is below the set level')

WARNING:root:This is a warning message this should be printed on your console, its level is above the set level
INFO:root:This is an info message it should be printed now!

Setting up a logger#

# Note: this works because we configured the root logger before.
# if you are starting from scratch uncomment the lines below
#import logging
#for handler in logging.root.handlers[:]:
#    logging.root.removeHandler(handler)
#logging.basicConfig(level=logging.INFO)

mylog = logging.getLogger('mylogger')
mylog.setLevel(logging.INFO)
mylog.warning('This is a warning message this should be printed on your console, its level is above the set level')
mylog.info('This is an info message it should be printed now!')
mylog.debug('This is a debug message which will not be shown, its level is below the set level')

WARNING:mylogger:This is a warning message this should be printed on your console, its level is above the set level
INFO:mylogger:This is an info message it should be printed now!

We created a new logger and save it to a variable using getLogger().
Then we use setLevel() to change the level to INFO and the messages are showing as expected.
If we want to run the code in debug mode we can now change only the logging level instead of commenting/uncommenting print statements.

mylog.warning('I now have two loggers working!')
logging.warning('I can still use the root logger')
root_logger = logging.getLogger()
root_logger.warning('This is still the root logger, I have just saved it to a different variable')

WARNING:mylogger:I now have two loggers working!
WARNING:root:I can still use the root logger
WARNING:root:This is still the root logger, I have just saved it to a different variable

The root logger it’s still working, we can use one of the other.
We can also saved the root logger to a variable by using the get_logger() function without any arguments.

This is a good start but let’s see how we can actually print out something a bit more useful.
Personally when I’m trying to debug something there are 3 things which I usually print: the variable value, its type and the methods and attributes. Remember, in python any variable is an object and can have more or less complex methods (functions) and attributes.

mylog.warning('This script is totally useless')
var1 = 1
var2 = 0
mylog.debug('Input values are %d %d', var1, var2)
mylog.info('Starting complex calculation')
result = var1 + var2
mylog.info('Calculation completed, result is %d', result)

WARNING:mylogger:This script is totally useless
INFO:mylogger:Starting complex calculation
INFO:mylogger:Calculation completed, result is 1

This looks more like a script, first of all we are starting using the levels as appropriate.
INFO is used to define the steps our script is going through and show us the result of our calculation.
WARNING is telling the user something which is potentially an issue but not an error.
DEBUG is ready to show us the values of the variables we used, should something go wrong.
Please note that I am using %d as a number placeholder.
Let’s now generate an error.

mylog.warning('This script is totally useless')
var1 = 1
var2 = '0'
mylog.debug('Input values are %d %d', var1, var2)
mylog.info('Starting complex calculation')
result = var1 + var2
mylog.info('Calculation completed, result is %d', result)

WARNING:mylogger:This script is totally useless
INFO:mylogger:Starting complex calculation

---------------------------------------------------------------------------
TypeError                                 Traceback (most recent call last)
<ipython-input-8-f0ab03a4fc0a> in <module>()
      4 mylog.debug('Input values are %d %d', var1, var2)
      5 mylog.info('Starting complex calculation')
----> 6 result = var1 + var2
      7 mylog.info('Calculation completed, result is %d', result)

TypeError: unsupported operand type(s) for +: 'int' and 'str'

Instead of 0 we passed the equivalent string so we get an error. Let’s switch to debug level.

mylog.setLevel(logging.DEBUG)
mylog.warning('This script is totally useless')
var1 = 1
var2 = '0'
mylog.debug('Input values are %d %d', var1, var2)
mylog.info('Starting complex calculation')
result = var1 + var2
mylog.info('Calculation completed, result is %d', result)

WARNING:mylogger:This script is totally useless
--- Logging error ---
Traceback (most recent call last):
  File "/Users/paolap/anaconda/lib/python3.5/logging/__init__.py", line 980, in emit
    msg = self.format(record)
  File "/Users/paolap/anaconda/lib/python3.5/logging/__init__.py", line 830, in format
    return fmt.format(record)
  File "/Users/paolap/anaconda/lib/python3.5/logging/__init__.py", line 567, in format
    record.message = record.getMessage()
  File "/Users/paolap/anaconda/lib/python3.5/logging/__init__.py", line 330, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not str
Call stack:
  File "/Users/paolap/anaconda/lib/python3.5/runpy.py", line 184, in _run_module_as_main
    "__main__", mod_spec)
  File "/Users/paolap/anaconda/lib/python3.5/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/traitlets/config/application.py", line 596, in launch_instance
    app.start()
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelapp.py", line 442, in start
    ioloop.IOLoop.instance().start()
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/ioloop.py", line 162, in start
    super(ZMQIOLoop, self).start()
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/tornado/ioloop.py", line 883, in start
    handler_func(fd_obj, events)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/tornado/stack_context.py", line 275, in null_wrapper
    return fn(*args, **kwargs)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelbase.py", line 276, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelbase.py", line 228, in dispatch_shell
    handler(stream, idents, msg)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/kernelbase.py", line 391, in execute_request
    user_expressions, allow_stdin)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/ipykernel/ipkernel.py", line 199, in do_execute
    shell.run_cell(code, store_history=store_history, silent=silent)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/IPython/core/interactiveshell.py", line 2723, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/IPython/core/interactiveshell.py", line 2825, in run_ast_nodes
    if self.run_code(code, result):
  File "/Users/paolap/anaconda/lib/python3.5/site-packages/IPython/core/interactiveshell.py", line 2885, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-c5109423231f>", line 5, in <module>
    mylog.debug('Input values are %d %d', var1, var2)
Message: 'Input values are %d %d'
Arguments: (1, '0')
INFO:mylogger:Starting complex calculation

---------------------------------------------------------------------------
TypeError                                 Traceback (most recent call last)
<ipython-input-9-c5109423231f> in <module>()
      5 mylog.debug('Input values are %d %d', var1, var2)
      6 mylog.info('Starting complex calculation')
----> 7 result = var1 + var2
      8 mylog.info('Calculation completed, result is %d', result)

TypeError: unsupported operand type(s) for +: 'int' and 'str'

Funnily enough, now we have two separate error messages:

The debug statement uses %d as place holder which fails when passed a string, we can use %s instead which is a string place holder and works with basically everything. You will notice that this error didn’t stop the code from going on. This is a useful feature!
The second error message tells us we have a type error, we can improve our debug message to catch this better.

mylog.warning('This script is totally useless')
var1 = 1
var2 = '0'
mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))
mylog.info('Starting complex calculation')
result = var1 + var2
mylog.info('Calculation completed, result is %s', result)

WARNING:mylogger:This script is totally useless
DEBUG:mylogger:Input values are 1 0, their respective types are <class 'int'> and <class 'str'>
INFO:mylogger:Starting complex calculation

---------------------------------------------------------------------------
TypeError                                 Traceback (most recent call last)
<ipython-input-10-f50982a73b33> in <module>()
      4 mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))
      5 mylog.info('Starting complex calculation')
----> 6 result = var1 + var2
      7 mylog.info('Calculation completed, result is %s', result)

TypeError: unsupported operand type(s) for +: 'int' and 'str'

This is better except in good programming, the programmer is expected to handle errors rather than letting the code to crash. An easy way to do this is the the try: except: statements.

Let’s also see what the ERROR level does. We can safely ignore CRITICAL that’s reserved for an error which can have catastrophic consequences and it’s probably not useful to us.

Let’s get back to a lower level of logging and run the script again.

mylog.setLevel(logging.INFO)
mylog.warning('This script is totally useless')
var1 = 1
var2 = '0'
mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))
mylog.info('Starting complex calculation')
try:
    result = var1 + var2
except: 
    mylog.error('There is an issue adding %s and %s', var1, var2)
mylog.warning('I am still going on!')
# Last statement still print fine because we haven't deleted result
mylog.info('Calculation completed, result is %s', result)

WARNING:mylogger:This script is totally useless
INFO:mylogger:Starting complex calculation
ERROR:mylogger:There is an issue adding 1 and 0
WARNING:mylogger:I am still going on!
INFO:mylogger:Calculation completed, result is 1

We tried to do 1 + ‘0’ which failed so the code moved on executing the except statement rather then stopping and throwing out an error.
While often we want our code to stop when failing, there are situations where we can remedy the error. try/except help us handling those cases. For example if you want to open a file and you are not sure if exists already you could try to open the file, if that fails you can use except to create first and then open the file.
The other common case is to simply use try/except as we did to choose an error message to print out and then exit the code by adding sys.exit() at the end or going on depending on how critical the error is.
Note that because we are using try/except we cannot see the standard error message anymore, since this could be useful let’s see how we can get both.

mylog.warning('This script is totally useless')
var1 = 1
var2 = '0'
mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))
mylog.info('Starting complex calculation')
try:
    result = var1 + var2
except: 
    mylog.error('There some issue with adding %s and %s', var1, var2, exc_info=True)
    mylog.exception('There is some issue adding %s and %s', var1, var2)
mylog.warning('I am still going on!')
mylog.info('Calculation completed, result is %d', result)

WARNING:mylogger:This script is totally useless
INFO:mylogger:Starting complex calculation
ERROR:mylogger:There some issue with adding 1 and 0
Traceback (most recent call last):
  File "<ipython-input-12-bbad2226f873>", line 7, in <module>
    result = var1 + var2
TypeError: unsupported operand type(s) for +: 'int' and 'str'
ERROR:mylogger:There is some issue adding 1 and 0
Traceback (most recent call last):
  File "<ipython-input-12-bbad2226f873>", line 7, in <module>
    result = var1 + var2
TypeError: unsupported operand type(s) for +: 'int' and 'str'
WARNING:mylogger:I am still going on!
INFO:mylogger:Calculation completed, result is 1

By adding exc_info=True to the logger.error() we can get also the traceback error again. Please note that you can achieve exactly the same using logger.exception().

This is a fairly straightforward error, sometimes when you have variables going from one function to another and using modules you are not familiar with, you might end up with mysterious objects that don’t work as you expect. Or simply, you might want to understand better the objects’ properties. This is where the function dir() comes handy.
Let’s look at a simple example.

a = {'key1': 1, 'key2': 2}
print( dir(a)[-10:-5])
print('pop is %s', type(a.pop))
print('keys is %s', type(a.keys))  
# There's a new way to print formatted string introduced in python3.6, which accept any expression in {} embedded in the string
# then evaluates the expression before printing.
# It doesn't work yet in notebooks, but it will if you run directly with python.
# print(f"pop is {type(a.pop)}")
# print(f"the sum of {var1} and {var2} is {var1 + var2}")

['copy', 'fromkeys', 'get', 'items', 'keys']
pop is %s <class 'builtin_function_or_method'>
keys is %s <class 'builtin_function_or_method'>

We defined a dictionary and used dir() to list all its properties, some are attributes and some are methods. type() will tell us that. Please note dir() returns a list and we printed only a subset to avoid a long listing. In fact lots of the debugging information might be better off sent to a file, this will allow us to keep a record we can check later and to separate it from the usual print statements, or better, INFO and WARNING level statements. We’ll have a look at how to do this in the second part.

Sending messages to different ouputs#

Remember the handlers at the start of the blog? We will have a quick look at how to use them to send different levels of messages to different output channels.

To make testing easier we will write the logger setup as a function that takes the logger level as input.

We defined the file_handler simply by giving it a filename, there are other options we could set at the same time, but that’s the only one we need.
We set the file_handler level to DEBUG and add a formatter to add before the message:
time | logger_name | log level
NB I added a ‘w’ to the file handler definition so it will create a new file each time.
Finally we add it to the logger and add a debug message to test it.
Let’s call the function using INFO as input level. Remember this is setting the level for the logger not the file_handler.

IMPORTANT
Because we are disabling all the existing handlers after importing the module we need to set up a level for the root logger!
You can use the basicConfig command only once in a session, if you try to run it twice it won’t do anything.

%%script python3
# I am using this to run this as a separate script so we start with a clean enviroment!
import logging
# remember to uncomment these lines if you have want to set your own root logger
#for handler in logging.root.handlers[:]:
#    logging.root.removeHandler(handler)
# We disabled the existing handlers after import logging so we can configure the root logger as we want
# We set the level to root logger level to WARNING
logging.basicConfig(level=logging.WARNING)

def log_setup(name, level, fname):
    '''This function will setup a logger with the name and level you pass as input'''
    # start a logger
    logger = logging.getLogger(name)
    # set a formatter to manage the output format of our handler
    formatter = logging.Formatter('%(asctime)s | %(name)s |  %(levelname)s: %(message)s')
    # set the level passed as input, has to be logging.LEVEL not a string
    # until we do so mylog doesn't have a level and inherits the root logger level:WARNING
    logger.setLevel(level)

    # add a handler to send INFO level messages to console

    # add a handler to send DEBUG level messages to file
    # all you need is a file name I added the 'w' so each time a new file will be created
    # without it the messagges will be appended to the same file
    file_handler = logging.FileHandler(fname,'w')
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(formatter)
    logger.addHandler(file_handler)

    # return the logger object
    return logger

# call function to setup the logger to the lowest level (DEBUG) so we can see all the messages!
mylog = log_setup('clever_logger', logging.INFO, 'mycode_debug.log')
# add some debug messages
mylog.info('This function is a logging demo')
var1 = 1
var2 = '0'
mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))
mylog.info('Code ends here!')

INFO:clever_logger:This function is a logging demo
INFO:clever_logger:Code ends here!

!cat mycode_debug.log

2018-10-05 12:16:29,093 | clever_logger |  INFO: This function is a logging demo
2018-10-05 12:16:29,093 | clever_logger |  INFO: Code ends here!

The output shows that the INFO message was printed out both in the file and on the console. There’s no trace of the debug message in the file even if the file_handler level was set to DEBUG!!
Let’s try to run it again but passing DEBUG as level.
I’m running the same script directly from the command line.

# the console output
!python demo_log.py > out.txt
!cat out.txt

INFO:clever_logger:This function is a logging demo
DEBUG:clever_logger:Input values are 1 0, their respective types are <class 'int'> and <class 'str'>
INFO:clever_logger:Code ends here!

# the file output
!cat mycode_debug.log

2018-10-05 12:16:37,998 | clever_logger |  INFO: This function is a logging demo
2018-10-05 12:16:37,998 | clever_logger |  DEBUG: Input values are 1 0, their respective types are <class 'int'> and <class 'str'>
2018-10-05 12:16:37,998 | clever_logger |  INFO: Code ends here!

Ok now we can see the debug message!
We couldn’t before because the logger level was setting the lowest possible level to INFO so even if we set the file level to DEBUG this was bumped up to INFO.
Luckily this can be easily fixed by setting the logger level to DEBUG, so now our file handler works as expected! The problem is that the debug messages are also showing on the console, if we want to set different levels we need to define stream handler.

%%script python3
# I am using this to run this as a separate script so we start with a clean enviroment!

import logging
#for handler in logging.root.handlers[:]:
#    logging.root.removeHandler(handler)
# We disabled the existing handlers after import logging so we can configure the root logger as we want
# We set the level to root logger level to WARNING
#logging.basicConfig(level=logging.WARNING)


def log_setup(name, level):
    '''This function will setup a logger with the name and level you pass as input'''
    # start a logger
    logger = logging.getLogger(name)
    # set a formatter to manage the output format of our handler
    formatter = logging.Formatter('%(asctime)s | %(name)s |  %(levelname)s: %(message)s')
    # set the level passed as input, has to be logging.LEVEL not a string
    # until we do so mylog doesn't have a level and inherits the root logger level:WARNING
    logger.setLevel(level)
    
    # add a handler to send INFO level messages to console
    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    logger.addHandler(console_handler)    
    
    # add a handler to send DEBUG level messages to file 
    # all you need is a file name I added the 'w' so each time a new file will be created
    # without it the messagges will be appended to the same file
    file_handler = logging.FileHandler('mycode_debug.log','w') 
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(formatter)
    logger.addHandler(file_handler)
    
    # return the logger object
    return logger

# call function to setup the logger to the lowest level (DEBUG) so we can see all the messages!
mylog = log_setup('clever_logger', logging.DEBUG)
# add some debug messages
mylog.info('This function is a logging demo')
var1 = 1
var2 = '0'
mylog.debug('Input values are %s %s, their respective types are %s and %s', var1, var2, type(var1), type(var2))
mylog.info('Code ends here!')

This function is a logging demo
Code ends here!

!cat mycode_debug.log

2018-10-05 12:16:48,654 | clever_logger |  INFO: This function is a logging demo
2018-10-05 12:16:48,654 | clever_logger |  DEBUG: Input values are 1 0, their respective types are <class 'int'> and <class 'str'>
2018-10-05 12:16:48,654 | clever_logger |  INFO: Code ends here!

Now we are going to get all the message at level INFO or above printed on the console and the same plus the DEBUG messages saved on the file!
NB Because now we set up a stream handler I’m ignoring completely the root logger and I commented the basicConfig command.
If you try the same in the previous version you will, or better might since it depends on the starting logging config, find that nothing gets printed on the console. This is because our logger wouldn’t have any stream handler to inherit from.

I hope you’ll find this helpful, once you understand the different loggers levels and how they interacts, this can be a very helpful module.
While we started the demo using the root logger is probably a good practice to setup your own logger and use that in your code.
You can use as a starting point the log_setup function we used in the last example.
Keep also in mind that the root logger will be used by some of the modules you might be loading so changing its configuration level will affect them too. Once you are a bit more experienced you could use this if you want to get more information out of them or redirect their log output to a file.

Basic usage of python logging module

Contents

Basic usage of python logging module#

Printing out messages and logging levels#

Setting up a logger#

Sending messages to different ouputs#