Python Exceptions Best Practices
2019-03-25
What is Apache Kafka?
2019-05-08
Show all

Logging in Python Tutorial

Adding logging to your Python program is as easy as this:

import logging

With the logging module imported, you can use something called a “logger” to log messages that you want to see. By default, there are 5 standard levels indicating the severity of events. Each has a corresponding method that can be used to log events at that level of severity. The defined levels, in order of increasing severity, are the following:

  • DEBUG
  • INFO
  • WARNING
  • ERROR
  • CRITICAL

The logging module provides you with a default logger that allows you to get started without needing to do much configuration. The corresponding methods for each level can be called as shown in the following example:

import logging

logging.debug('This is a debug message')
logging.info('This is an info message')
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

Basic Configurations

You can use the basicConfig(**kwargs) method to configure the logging:

  • level: The root logger will be set to the specified severity level.
  • filename: This specifies the file.
  • filemode: If filename is given, the file is opened in this mode. The default is a, which means append.
  • format: This is the format of the log message.

You can customize the root logger even further by using more parameters for basicConfig(), which can be found here.

Here’s an example:

import logging

logging.basicConfig(level=logging.DEBUG)
logging.debug('This will get logged')

For logging to a file rather than the console, filename and filemode can be used, and you can decide the format of the message using format. The following example shows the usage of all three:

import logging

logging.basicConfig(filename='app.log', filemode='w', format='%(name)s - %(levelname)s - %(message)s')
logging.warning('This will get logged to a file')

Calling basicConfig() to configure the root logger works only if the root logger has not been configured before. Basically, this function can only be called once.

debug()info()warning()error(), and critical() also call basicConfig() without arguments automatically if it has not been called before. This means that after the first time one of the above functions is called, you can no longer configure the root logger because they would have called the basicConfig() function internally.

The default setting in basicConfig() is to set the logger to write to the console in the following format:

ERROR:root:This is an error message

Formatting the Output

While you can pass any variable that can be represented as a string from your program as a message to your logs, there are some basic elements that are already a part of the LogRecordand can be easily added to the output format. If you want to log the process ID along with the level and message, you can do something like this:

import logging

logging.basicConfig(format='%(process)d-%(levelname)s-%(message)s')
logging.warning('This is a Warning')

The entire list of available attributes can be found here.

Here’s another example where you can add the date and time info:

import logging

logging.basicConfig(format='%(asctime)s - %(message)s', level=logging.INFO)
logging.info('Admin logged in')

%(asctime)s adds the time of creation of the LogRecord. The format can be changed using the datefmt attribute, which uses the same formatting language as the formatting functions in the datetime module, such as time.strftime():

import logging

logging.basicConfig(format='%(asctime)s - %(message)s', datefmt='%d-%b-%y %H:%M:%S')
logging.warning('Admin logged out')

Logging Variable Data

import logging

name = 'John'

logging.error('%s raised an error', name)

Capturing Stack Traces

The logging module also allows you to capture the full stack traces in an application. Exception information can be captured if the exc_info parameter is passed as True, and the logging functions are called like this:

import logging

a = 5
b = 0

try:
  c = a / b
except Exception as e:
  logging.error("Exception occurred", exc_info=True)

Here’s a quick tip: if you’re logging from an exception handler, use the logging.exception()method, which logs a message with level ERROR and adds exception information to the message. To put it more simply, calling logging.exception() is like calling logging.error(exc_info=True). But since this method always dumps exception information, it should only be called from an exception handler. Take a look at this example:

import logging

a = 5
b = 0
try:
  c = a / b
except Exception as e:
  logging.exception("Exception occurred")
>>> import logging
>>> logging.basicConfig()
>>> logger = logging.getLogger(__name__)
>>>
>>> logger.critical('logging is easier than I was expecting')
CRITICAL:__main__:logging is easier than I was expecting

getLogger provided us with a logger instance. We then gave it the event ‘logging is easier than I was expecting’ with a level of critical.

loggingLevels

 the info and debug didn’t print a message. By default, the logger will only print warningerror, or critical messages. You can customize this behavior, and even modify it at runtime to activate more verbose logging dynamically.

1
2
3
4
5
6
7
8
>>> # should show up; info is a higher level than debug
>>> logger.setLevel(logging.DEBUG)
>>> logger.info(1)
INFO:root:1
>>>
>>> # shouldn't show up; info is a lower level than warning
... logger.setLevel(logging.WARNING)
>>> logger.info(2)

Adding Context

A generic log message provides just about as little information as no log message. Imagine if you had to go through your logs and you saw removed from cart. This makes it difficult to answer questions such as: When was the item removed? Who removed it? What did they remove?

It’s best to add structured data to your logs instead of string-ifying an object to enrich it. Without structured data, it’s difficult to decipher the log stream in the future. The best way to deal with this is to push important metadata to the extra object. Using this, you’ll be able to enrich your messages in the stream.

1
2
3
4
5
6
>>> import logging
>>> logFormatter = '%(asctime)s - %(user)s - %(levelname)s - %(message)s'
>>> logging.basicConfig(format=logFormatter, level=logging.DEBUG)
>>> logger = logging.getLogger(__name__)
>>> logger.info('purchase completed', extra={'user': 'Sid Panjwani'})
2018-06-19 17:44:10,276 - Sid Panjwani - INFO - purchase completed

Performance

Logging introduces overhead that needs to be balanced with the performance requirements of the software you write. While the overhead is generally negligible, bad practices and mistakes can lead to unfortunate situations.

Here are a few helpful tips:

Wrap Expensive Calls in a Level Check

The Python Logging Documentation recommends that expensive calls be wrapped in a level check to delay evaluation.

1
2
if logger.isEnabledFor(logging.INFO):
    logger.debug('%s', expensive_func())

Now, expensive_func will only be called if the logging level is greater than or equal to INFO.

Avoid Logging in the Hot Path

The hot path is code that is critical for performance, so it is executed often. It’s best to avoid logging here because it can become an IO bottleneck, unless it’s necessary because the data to log is not available outside the hot path.

Storing & Accessing These Logs

Now that you’ve learned to write these (beautiful) logs, you’ve got to determine what to do with them. By default, logs are written to the standard output device (probably your terminal window), but Python’s logging module provides a rich set of options to customize the output handling. Logging to standard output is encouraged, and platforms such as Heroku, Amazon Elastic Beanstalk, and Docker build on this standard by capturing the standard output and redirecting to other logging facilities at a platform level.

Logging To A File

The logging module makes it easy to write your logs to a local file using a “handler” for long-term retention.

1
2
3
4
5
6
7
8
>>> import logging
>>> logger = logging.getLogger(__name__)
>>>
>>> handler = logging.FileHandler('myLogs.log')
>>> handler.setLevel(logging.INFO)
>>>
>>> logger.addHandler(handler)
>>> logger.info('You can find this written in myLogs.log')

If you’ve been following along (which you should be), you’ll notice that your log won’t show up in your file because it is level info. Make sure to use setLevel to change that.

Rotating Logs

The Python logging module makes it easy to log in a different file after an interval of time or after the log file reaches a certain size. This becomes useful if you automatically want to get rid of older logs, or if you’re going to search through your logs by date since you won’t have to search through a huge file to find a set of logs that are already grouped.

To create a handler that makes a new log file every day and automatically deletes logs more than five days old, you can use a TimedRotatingFileHandler. Here’s an example:

1
2
3
4
5
6
logger = logging.getLogger('Rotating Log by Day')

# writes to pathToLog
# creates a new file every day because `when="d"` and `interval=1`
# automatically deletes logs more than 5 days old because `backupCount=5`
handler = TimedRotatingFileHandler(pathToLog, when="d", interval=1,  backupCount=5)

The Drawbacks

It’s important to understand where logs fit in when it comes to observing your application. I recommend readers take a look at the 3 pillars of observabilityprinciple, in that logs should be one of a few tools you reach for when observing your application. Logs are a component of your observability stack, but metrics and tracing are equally so.

Logging can become expensive, especially at scale. Metrics can be used to aggregate data and answer questions about your customers without having to keep a trace of every action, while tracing enables you to see the path of your request throughout your platform.

Logging from Modules

Modules, that is, libraries intended to be used by other programs, should only emit log messages as a best practice. They should never configure how log messages are handled. That is the responsibility of the application that imports and uses the modules. The only responsibility modules have is to make it easy for the application to route their log messages. For this reason, it is a convention for each module to simply use a logger named like the module itself. This makes it easy for the application to route different modules differently, while also keeping log code in the module simple. The module just needs two lines to set up logging, and then use the named logger:

import logging log = logging.getLogger(__name__) 
def do_something():    
log.debug(“Doing something!”)

That is all there is to it. In Python, __name__ contains the full name of the current module, so this will simply work in any module.

If you want to set the logging level from a command-line option such as:

--log=INFO

and you have the value of the parameter passed for --log in some variable loglevel, you can use:

getattr(logging, loglevel.upper())

to get the value which you’ll pass to basicConfig() via the level argument. You may want to error check any user input value, perhaps as in the following example:

# assuming loglevel is bound to the string value obtained from the
# command line argument. Convert to upper case to allow the user to
# specify --log=DEBUG or --log=debug
numeric_level = getattr(logging, loglevel.upper(), None)
if not isinstance(numeric_level, int):
    raise ValueError('Invalid log level: %s' % loglevel)
logging.basicConfig(level=numeric_level, ...)

Logging from multiple modules

If your program consists of multiple modules, here’s an example of how you could organize logging in it:

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(filename='myapp.log', level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()
# mylib.py
import logging

def do_something():
    logging.info('Doing something')

If you run myapp.py, you should see this in myapp.log:

INFO:root:Started
INFO:root:Doing something
INFO:root:Finished

which is hopefully what you were expecting to see. You can generalize this to multiple modules, using the pattern in mylib.py. Note that for this simple usage pattern, you won’t know, by looking in the log file, where in your application your messages came from, apart from looking at the event description. If you want to track the location of your messages, you’ll need to refer to the documentation beyond the tutorial level – see Advanced Logging Tutorial.

Write logging records everywhere with proper level

With flexibility of the logging module, you can write logging record everywhere with proper level and configure them later. What is the proper level to use, you may ask. Here I share my experience.

In most cases, you don’t want to read too much details in the log file. Therefore, debug level is only enabled when you are debugging. I use debug level only for detail debugging information, especially when the data is big or the frequency is high, such as records of algorithm internal state changes in a for-loop.

def complex_algorithm(items):
    for i, item in enumerate(items):
        # do some complex algorithm computation
        logger.debug('%s iteration, item=%s', i, item)

I use info level for routines, for example, handling requests or server state changed.

def handle_request(request):
    logger.info('Handling request %s', request)
    # handle request here
    result = 'result'
    logger.info('Return result: %s', result)

def start_service():
    logger.info('Starting service at port %s ...', port)
    service.start()
    logger.info('Service is started')

I use warning when it is important, but not an error, for example, when a user attempts to login with wrong password or connection is slow.

def authenticate(user_name, password, ip_address):
    if user_name != USER_NAME and password != PASSWORD:
        logger.warn('Login attempt to %s from IP %s', user_name, ip_address)
        return False
    # do authentication here

I use error level when something is wrong, for example, an exception is thrown, IO operation failure or connectivity issue.

def get_user_by_id(user_id):
    user = db.read_user(user_id)
    if user is None:
        logger.error('Cannot find user with user_id=%s', user_id)
        return user
    return user

I seldom use critical, you can use it when something really bad happen, for example, out of memory, disk is full or a nuclear meltdown (Hope that will not happen :S).

Useful Links:

https://docs.python.org/3/howto/logging.html#basic-logging-tutorial

https://python.readthedocs.io/en/latest/library/logging.html

https://docs.python.org/3/howto/logging-cookbook.html

https://realpython.com/python-logging/

https://timber.io/blog/the-pythonic-guide-to-logging/#logging-info-hello-world-to-logging-

https://www.loggly.com/ultimate-guide/python-logging-basics/

https://fangpenlin.com/posts/2012/08/26/good-logging-practice-in-python/

https://www.toptal.com/python/in-depth-python-logging

https://stackoverflow.com/questions/7507825/where-is-a-complete-example-of-logging-config-dictconfig/7507842

https://tutorialedge.net/python/python-logging-best-practices/

https://www.techatbloomberg.com/blog/guide-logging-python/

https://simpletutorials.com/c/1457/Python+3+Logging+using+DictConfig

https://opensource.com/article/17/9/python-logging

https://www.programcreek.com/python/example/105588/logging.config.dictConfig





Amir Masoud Sefidian
Amir Masoud Sefidian
Data Scientist, Machine Learning Engineer, Researcher, Software Developer

Comments are closed.