Best practices for Python exceptions

2019-03-25

What is Apache Kafka?

2019-05-08

Complete guide on Logging in Python

The Logging Module

The logging module in Python is a ready-to-use and powerful module that is designed to meet the needs of beginners as well as enterprise teams. It is used by most of the third-party Python libraries, so you can integrate your log messages with the ones from those libraries to produce a homogeneous log for your application. 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 many configurations. 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 LogRecord and 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 the 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")

mport 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.

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

# 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)

Classes and Functions

So far, we have seen the default logger named root, which is used by the logging module whenever its functions are called directly like this: logging.debug(). You can (and should) define your own logger by creating an object of the Logger class, especially if your application has multiple modules. Let’s have a look at some of the classes and functions in the module.

The most commonly used classes defined in the logging module are the following:

Logger: This is the class whose objects will be used in the application code directly to call the functions.
LogRecord: Loggers automatically create LogRecord objects that have all the information related to the event being logged, like the name of the logger, the function, the line number, the message, and more.
Handler: Handlers send the LogRecord to the required output destination, like the console or a file. Handler is a base for subclasses like StreamHandler, FileHandler, SMTPHandler, HTTPHandler, and more. These subclasses send the logging outputs to corresponding destinations, like sys.stdout or a disk file.
Formatter: This is where you specify the format of the output by specifying a string format that lists out the attributes that the output should contain.

Out of these, we mostly deal with the objects of the Logger class, which are instantiated using the module-level function logging.getLogger(name). Multiple calls to getLogger() with the same name will return a reference to the same Logger object, which saves us from passing the logger objects to every part where it’s needed. Here’s an example:

import logging

logger = logging.getLogger('example_logger')
logger.warning('This is a warning')

This is a warning

This creates a custom logger named example_logger, but unlike the root logger, the name of a custom logger is not part of the default output format and has to be added to the configuration. Configuring it to a format to show the name of the logger would give an output like this:

WARNING:example_logger:This is a warning

Again, unlike the root logger, a custom logger can’t be configured using basicConfig(). You have to configure it using Handlers and Formatters:

“It is recommended that we use module-level loggers by passing __name__ as the name parameter to getLogger() to create a logger object as the name of the logger itself would tell us from where the events are being logged. __name__ is a special built-in variable in Python which evaluates to the name of the current module.” (Source)

Using Handlers

Handlers come into the picture when you want to configure your own loggers and send the logs to multiple places when they are generated. Handlers send the log messages to configured destinations like the standard output stream or a file or over HTTP or to your email via SMTP.

A logger that you create can have more than one handler, which means you can set it up to be saved to a log file and also send it over email.

Like loggers, you can also set the severity level in handlers. This is useful if you want to set multiple handlers for the same logger but want different severity levels for each of them. For example, you may want logs with level WARNING and above to be logged to the console, but everything with level ERROR and above should also be saved to a file. Here’s a program that does that:

# logging_example.py

import logging

# Create a custom logger
logger = logging.getLogger(__name__)

# Create handlers
c_handler = logging.StreamHandler()
f_handler = logging.FileHandler('file.log')
c_handler.setLevel(logging.WARNING)
f_handler.setLevel(logging.ERROR)

# Create formatters and add it to handlers
c_format = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
f_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
c_handler.setFormatter(c_format)
f_handler.setFormatter(f_format)

# Add handlers to the logger
logger.addHandler(c_handler)
logger.addHandler(f_handler)

logger.warning('This is a warning')
logger.error('This is an error')

__main__ - WARNING - This is a warning
__main__ - ERROR - This is an error

Here, logger.warning() is creating a LogRecord that holds all the information of the event and passes it to all the Handlers that it has: c_handler and f_handler. c_handler is a StreamHandler with level WARNING and takes the info from the LogRecord to generate an output in the format specified and print it to the console. f_handler is a FileHandler with level ERROR, and it ignores this LogRecord as its level is WARNING.

When logger.error() is called, c_handler behaves exactly as before, and f_handler gets a LogRecord at the level of ERROR, so it proceeds to generate an output just like c_handler, but instead of printing it to console, it writes it to the specified file in this format:

2018-08-03 16:12:21,723 - __main__ - ERROR - This is an error

The name of the logger corresponding to the __name__ variable is logged as __main__, which is the name Python assigns to the module where execution starts. If this file is imported by some other module, then the __name__ variable would correspond to its name logging_example. Here’s how it would look:

# run.py

import logging_example

logging_example - WARNING - This is a warning
logging_example - ERROR - This is an error

Other Configuration Methods

You can configure logging as shown above using the module and class functions or by creating a config file or a dictionary and loading it using fileConfig() or dictConfig() respectively. These are useful in case you want to change your logging configuration in a running application.

Here’s an example file configuration:

[loggers]
keys=root,sampleLogger

[handlers]
keys=consoleHandler

[formatters]
keys=sampleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_sampleLogger]
level=DEBUG
handlers=consoleHandler
qualname=sampleLogger
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=sampleFormatter
args=(sys.stdout,)

[formatter_sampleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

In the above file, there are two loggers, one handler, and one formatter. After their names are defined, they are configured by adding the words logger, handler, and formatter before their names are separated by an underscore.

To load this config file, you have to use fileConfig():

import logging
import logging.config

logging.config.fileConfig(fname='file.conf', disable_existing_loggers=False)

# Get the logger specified in the file
logger = logging.getLogger(__name__)

logger.debug('This is a debug message')

2018-07-13 13:57:45,467 - __main__ - DEBUG - This is a debug message

The path of the config file is passed as a parameter to the fileConfig() method, and the disable_existing_loggers parameter is used to keep or disable the loggers that are present when the function is called. It defaults to True if not mentioned.

Here’s the same configuration in a YAML format for the dictionary approach:

version: 1
formatters:
  simple:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: simple
    stream: ext://sys.stdout
loggers:
  sampleLogger:
    level: DEBUG
    handlers: [console]
    propagate: no
root:
  level: DEBUG
  handlers: [console]

Here’s an example that shows how to load config from a yaml file:

import logging
import logging.config
import yaml

with open('config.yaml', 'r') as f:
    config = yaml.safe_load(f.read())
    logging.config.dictConfig(config)

logger = logging.getLogger(__name__)

logger.debug('This is a debug message')

2018-07-13 14:05:03,766 - __main__ - DEBUG - This is a debug message

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 stringifying 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.

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.

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.

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:

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 observability principle, 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 a 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 the proper level

With the flexibility of the logging module, you can write logging records everywhere at the 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 many details in the log file. Therefore, debug level is only enabled when you are debugging. I use debug level only for detailed 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 changes.

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 a warning when it is important, but not an error, for example, when a user attempts to login with a wrong password or the 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 the 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 happens, for example, out of memory, the disk is full, or a nuclear meltdown.