Python 101: An Intro to logging

Posted by Mike on August 2nd, 2012 filed in Cross-Platform, Education, Python

Python provides a very powerful logging library in its standard library. A lot of programmers use print statements for debugging (myself included), but you can also use logging to do this. It’s actually cleaner to use logging as you won’t have to go through all your code to remove the print statements. In this tutorial we’ll cover the following topics:

  • Creating a simple logger
  • How to log from multiple modules
  • Log formatting
  • Log configuration

By the end of this tutorial, you should be able to confidently create your own logs for your applications. Let’s get started!

Creating a Simple Logger

Creating a log with the logging module is easy and straight-forward. It’s easiest to just look at a piece of code and then explain it, so here’s some code for you to read:

import logging
 
# add filemode="w" to overwrite
logging.basicConfig(filename="sample.log", level=logging.INFO)
 
logging.debug("This is a debug message")
logging.info("Informational message")
logging.error("An error has happened!")

As you might expect, to access the logging module you have to first import it. The easiest way to create a log is to use the logging module’s basicConfig function and pass it some keyword arguments. It accepts the following: filename, filemode, format, datefmt, level and stream. In our example, we pass it a file name and the logging level, which we set to INFO. There are five levels of logging (in ascending order): DEBUG, INFO, WARNING, ERROR and CRITICAL. By default, if you run this code multiple times, it will append to the log if it already exists. If you would rather have your logger overwrite the log, then pass in a filemode=”w” as mentioned in the comment in the code. Speaking of running the code, this is what you should get if you ran it once:


INFO:root:Informational message
ERROR:root:An error has happened!

Note that the debugging message isn’t in the output. That is because we set the level at INFO, so our logger will only log if it’s a INFO, WARNING, ERROR or CRITICAL message. The root part just means that this logging message is coming from the root logger or the main logger. We’ll look at how to change that so it’s more descriptive in the next section. If you don’t use basicConfig, then the logging module will output to the console / stdout.

The logging module can also log some exceptions to file or wherever you have it configured to log to. Here’s an example:

import logging
 
logging.basicConfig(filename="sample.log", level=logging.INFO)
log = logging.getLogger("ex")
 
try:
    raise RuntimeError
except Exception, err:
    log.exception("Error!")

This will log the entire traceback to file, which can be very handy when debugging.

How to log From Multiple Modules (and Formatting too!)

The more you code, the more often you end up creating a set of custom modules that work together. If you want them all to log to the same place, then you’ve come to the right place. We’ll look at the simple way and then show a more complex method that’s also more customizable. Here’s one easy way to do it:

import logging
import otherMod
 
#----------------------------------------------------------------------
def main():
    """
    The main entry point of the application
    """
    logging.basicConfig(filename="mySnake.log", level=logging.INFO)
    logging.info("Program started")
    result = otherMod.add(7, 8)
    logging.info("Done!")
 
if __name__ == "__main__":
    main()

Here we import logging and a module of our own creation (“otherMod”). Then we create our log file as before. The other module looks like this:

# otherMod.py
import logging
 
#----------------------------------------------------------------------
def add(x, y):
    """"""
    logging.info("added %s and %s to get %s" % (x, y, x+y))
    return x+y

If you run the main code, you should end up with a log that has the following contents:


INFO:root:Program started
INFO:root:added 7 and 8 to get 15
INFO:root:Done!

Do you see the problem with doing it this way? You can’t really tell very easily where the log messages are coming from. This will only get more confusing the more modules there are that write to this log. So we need to fix that. That brings us to the complex way of creating a logger. Let’s take a look at a different implementation:

import logging
import otherMod2
 
#----------------------------------------------------------------------
def main():
    """
    The main entry point of the application
    """
    logger = logging.getLogger("exampleApp")
    logger.setLevel(logging.INFO)
 
    # create the logging file handler
    fh = logging.FileHandler("new_snake.log")
 
    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    fh.setFormatter(formatter)
 
    # add handler to logger object
    logger.addHandler(fh)
 
    logger.info("Program started")
    result = otherMod2.add(7, 8)
    logger.info("Done!")
 
if __name__ == "__main__":
    main()

Here we create a logger instance named “exampleApp”. We set its logging level, create a logging file handler object and a logging Formatter object. The file handler has to set the formatter object as its formatter and then the file handler has to be added to the logger instance. The rest of the code in main is mostly the same. Just note that instead of “logging.info”, it’s “logger.info” or whatever you call your logger variable. Here’s the updated otherMod2 code:

# otherMod2.py
import logging
 
module_logger = logging.getLogger("exampleApp.otherMod2")
 
#----------------------------------------------------------------------
def add(x, y):
    """"""
    logger = logging.getLogger("exampleApp.otherMod2.add")
    logger.info("added %s and %s to get %s" % (x, y, x+y))
    return x+y

Note that here we have two loggers defined. We don’t do anything with the module_logger in this case, but we do use the other one. If you run the main script, you should see the following output in your file:


2012-08-02 15:37:40,592 - exampleApp - INFO - Program started
2012-08-02 15:37:40,592 - exampleApp.otherMod2.add - INFO - added 7 and 8 to get 15
2012-08-02 15:37:40,592 - exampleApp - INFO - Done!

You will notice that we no longer have any reference to root has been removed. Instead it uses our Formatter object which says that we should get a human readable time, the logger name, the logging level and then the message. These are actually known as LogRecord attributes. For a full list of LogRecord attributes, see the documentation as there are too many to list here.

Configuring Logs for Work and Pleasure

The logging module can be configured 3 different ways. You can configure it using methods (loggers, formatters, handlers) like we did earlier in this article; you can use a configuration file and pass it to fileConfig(); or you can create a dictionary of configuration information and pass it to the dictConfig() function. Let’s create a configuration file first and then we’ll look at how to execute it with Python. Here’s an example config file:

[loggers]
keys=root,exampleApp
 
[handlers]
keys=fileHandler, consoleHandler
 
[formatters]
keys=myFormatter
 
[logger_root]
level=CRITICAL
handlers=consoleHandler
 
[logger_exampleApp]
level=INFO
handlers=fileHandler
qualname=exampleApp
 
[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=myFormatter
args=(sys.stdout,)
 
[handler_fileHandler]
class=FileHandler
formatter=myFormatter
args=("config.log",)
 
[formatter_myFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

You’ll notice that we have two loggers specified: root and exampleApp. For whatever reason, “root” is required. If you don’t include it, Python will raise a ValueError from config.py’s _install_loggers function, which is a part of the logging module. If you set the root’s handler to fileHandler, then you’ll end up doubling the log output, so to keep that from happening, we send it to the console instead. Study this example closely. You’ll need a section for every key in the first three sections. Now let’s see how we load it in the code:

# log_with_config.py
import logging
import logging.config
import otherMod2
 
#----------------------------------------------------------------------
def main():
    """
    Based on http://docs.python.org/howto/logging.html#configuring-logging
    """
    logging.config.fileConfig('logging.conf')
    logger = logging.getLogger("exampleApp")
 
    logger.info("Program started")
    result = otherMod2.add(7, 8)
    logger.info("Done!")
 
if __name__ == "__main__":
    main()

As you can see, all you need to do is pass the config file path to logging.config.fileConfig. You’ll also notice that we don’t need all that setup code any more as that’s all in the config file. Also we can just import the otherMod2 module with no changes. Anyway, if you run the above, you should end up with the following in your log file:


2012-08-02 18:23:33,338 - exampleApp - INFO - Program started
2012-08-02 18:23:33,338 - exampleApp.otherMod2.add - INFO - added 7 and 8 to get 15
2012-08-02 18:23:33,338 - exampleApp - INFO - Done!

As you might have guessed, it’s very similar to the other example. Now we’ll move on to the other config method. The dictionary configuration method (dictConfig) wasn’t added until Python 2.7, so make sure you have that or better or you won’t be able to follow along. It’s not well documented how this works. In fact, the examples in the documentation show YAML for some reason. Anyway, here’s some working code for you to look over:

# log_with_config.py
import logging
import logging.config
import otherMod2
 
#----------------------------------------------------------------------
def main():
    """
    Based on http://docs.python.org/howto/logging.html#configuring-logging
    """
    dictLogConfig = {
        "version":1,
        "handlers":{
                    "fileHandler":{
                        "class":"logging.FileHandler",
                        "formatter":"myFormatter",
                        "filename":"config2.log"
                        }
                    },        
        "loggers":{
            "exampleApp":{
                "handlers":["fileHandler"],
                "level":"INFO",
                }
            },
 
        "formatters":{
            "myFormatter":{
                "format":"%(asctime)s - %(name)s - %(levelname)s - %(message)s"
                }
            }
        }
 
    logging.config.dictConfig(dictLogConfig)
 
    logger = logging.getLogger("exampleApp")
 
    logger.info("Program started")
    result = otherMod2.add(7, 8)
    logger.info("Done!")
 
if __name__ == "__main__":
    main()

If you run this code, you’ll end up with the same output as the previous method. Note that you don’t need the “root” logger when you use a dictionary configuration.

Wrapping Up

At this point you should know how to get started using loggers and how to configure them in several different ways. You should also have gained the knowledge of how to modify the output using the Formatter object. If you want to get really fancy with the output, I recommend that you check out some of the links below.

Additional reading

Source Code

Print Friendly

  • http://twitter.com/kevbradwick Kevin J Bradwick

    Perfect. I’ve been looking for an article like this for a while. Thank you.

  • http://twitter.com/chex0v Dmitriy Dmitrienko

    hate print for debug, love logging :)

  • driscollis

    Hey Dav1d! Thanks for the link. I hadn’t seen this one.

  • John Rambo

    The posted config file should read:
    [loggers]keys=root,exampleAppSomehow this key is not present on this page. Adding it back causes the script to run correctly. Either way, thank you for this rundown, I found  it extremely helpful :)

  • http://twitter.com/pjwarner Paul J Warner

    Just an FYI in the logging.conf file at the top there should be a header called [loggers] on line 1

    [loggers]
    keys=root,exampleApp

  • http://twitter.com/pjwarner Paul J Warner

    Beat me to it by 2 mins :)

  • Andreas Sikkema

    What about syslog? If an application sends its logs to syslog I can decide when the logfile rotates, where it gets written (locally, remote) and so on. Logging to a random location within a source tree or some other place in the filesystem makes me cry 😉

  • Pingback: Code! Code! Code!()

  • Alex Railean

    Is there a way to configure it such that different parts of the program log to different files?

    My system has 2 components, one if which creates a very verbose log that grows very fast (it needs to be that way), the other module is more modest in terms of output volume.

    I would like to separate them and use timestamps to make correlations when necessary.

    I understand that I could create distinct .py files in which the logging object is initialized with different settings – but I’d like to know if it can be avoided (to reduce the number of files in the directory).

  • Pingback: [Python] An Introduction to logging | Lonely Coder()

  • za

    Is this works at Python 2.7? I found this error when tried to run the code.

    Traceback (most recent call last): File “logging.py”, line 23, in main() File “logging.py”, line 17, in main logging.basicConfig(filename=”mySnake.log”, level=logging.INFO)AttributeError: ‘module’ object has no attribute ‘basicConfig’

  • driscollis

    I just tried it on Python 2.7 and it works for me.

  • SF

    Your file is called “logging.py”. Python thinks that basicConfig() comes from your file because “logging.py” is the name of the module you are importing and Python first searches the local directory for modules. I had the same problem. Just don’t name your file the same as the module you are importing.

    Here is the same problem on StackOverflow:
    http://stackoverflow.com/questions/4482587/module-object-has-no-attribute-basicconfig

  • jim

    this is a great article. yesterday I suddenly thought to myself why am i printing to the screen – this is stupid. got started with logging in a couple minutes with these examples!

  • driscollis

    Thanks! I’m glad you found it so helpful!

  • Pingback: Top 10 Articles of 2012 « The Black Velvet Room()

  • Pingback: Uso de Logs con Python y el Modulo Logging | El Blog de FoxCarlos()

  • Pingback: Mike Driscoll: wxPython: How to Redirect Python’s Logging Module to a TextCtrl | The Black Velvet Room()

  • Pingback: Live Streaming Κάλυψη Συνεδρείων()

  • Pingback: Python: How to Create Rotating Logs | Hello Linux()