Python: Using the logging Module to Record Logs

Let's first look at a basic usage example

# -*- coding: utf-8 -*-

import logging
import sys

# 获取logger实例，如果参数为空则返回root logger
logger = logging.getLogger("AppName")

# 指定logger输出格式
formatter = logging.Formatter('%(asctime)s %(levelname)-8s: %(message)s')

# 文件日志
file_handler = logging.FileHandler("test.log")
file_handler.setFormatter(formatter)  # 可以通过setFormatter指定输出格式

# 控制台日志
console_handler = logging.StreamHandler(sys.stdout)
console_handler.formatter = formatter  # 也可以直接给formatter赋值

# 为logger添加的日志处理器
logger.addHandler(file_handler)
logger.addHandler(console_handler)

# 指定日志的最低输出级别，默认为WARN级别
logger.setLevel(logging.INFO)

# 输出不同级别的log
logger.debug('this is debug info')
logger.info('this is information')
logger.warn('this is warning message')
logger.error('this is error message')
logger.fatal('this is fatal message, it is same as logger.critical')
logger.critical('this is critical message')

# 2016-10-08 21:59:19,493 INFO    : this is information
# 2016-10-08 21:59:19,493 WARNING : this is warning message
# 2016-10-08 21:59:19,493 ERROR   : this is error message
# 2016-10-08 21:59:19,493 CRITICAL: this is fatal message, it is same as logger.critical
# 2016-10-08 21:59:19,493 CRITICAL: this is critical message

# 移除一些日志处理器
logger.removeHandler(file_handler)

Formatting log output

# 格式化输出
service_name = "Booking"
logger.error('%s service is down!' % service_name)  # 使用python自带的字符串格式化，不推荐
logger.error('%s service is down!', service_name)  # 使用logger的格式化，推荐
logger.error('%s service is %s!', service_name, 'down')  # 多参数格式化
logger.error('{} service is {}'.format(service_name, 'down')) # 使用format函数，推荐
 
# 2016-10-08 21:59:19,493 ERROR   : Booking service is down!

Recording exception information

When you use the logging module to record exception information, you don't need to pass in the exception object; just call logger.error() or logger.exception() directly and the current exception will be recorded.

# 记录异常信息
 
try:
    1 / 0
except:
    # 等同于error级别，但是会额外记录当前抛出的异常堆栈信息
    logger.exception('this is an exception message')
 
# 2016-10-08 21:59:19,493 ERROR   : this is an exception message
# Traceback (most recent call last):
#   File "D:/Git/py_labs/demo/use_logging.py", line 45, in 
#     1 / 0
# ZeroDivisionError: integer division or modulo by zero

Key points of logging configuration

GetLogger() method

This is the most basic entry point. The method's argument can be empty; the default logger name is root. If you always use a logger with the same name in the same program, you will actually get the same instance. Using this trick, you can call the same logger across modules to record logs.

You can also distinguish different modules of the same program by log name, as in this example.

logger = logging.getLogger("App.UI")
logger = logging.getLogger("App.Service")

Formatter log format

The Formatter object defines the structure and content of log information. Construction requires two arguments:

• One is the format template fmt, which by default includes the most basic level and message information
• One is the time format style datefmt, which defaults to 2003-07-08 16:49:45,896 (%Y-%m-%d %H:%M:%S)

Variables that can be used in fmt are listed in the table below.

• %(name)s Logger name
• %(levelno)s Numeric log level
• %(levelname)s Text log level
• %(pathname)s Full pathname of the module that called the logging output function; may be absent
• %(filename)s Filename of the module that called the logging output function
• %(module)s Name of the module that called the logging output function|
• %(funcName)s Name of the function that called the logging output function|
• %(lineno)d Line number of the statement that called the logging output function
• %(created)f Current time, represented as a UNIX-standard floating-point timestamp|
• %(relativeCreated)d Milliseconds since the Logger was created when the log information is output|
• %(asctime)s Current time as a string. The default format is "2003-07-08 16:49:45,896". The part after the comma is milliseconds
• %(thread)d Thread ID. May be absent
• %(threadName)s Thread name. May be absent
• %(process)d Process ID. May be absent
• %(message)s User-output message

SetLevel log level

Logging has the following levels: DEBUG, INFO, WARNING, ERROR, CRITICAL The default level is WARNING; the logging module will only output logs at the specified level and above. The advantage is that logs used for debug during project development don't need to be commented out one by one at product release; you only need to adjust the logger's level, which is very convenient.

Handler log handlers

The most commonly used are StreamHandler and FileHandler. Handlers are used to write logs to different outputs. Logging includes many handlers; ones you may use include the following

• StreamHandler instances send error messages to streams (file-like objects).
• FileHandler instances send error messages to disk files.
• RotatingFileHandler instances send error messages to disk files, with support for maximum log file sizes and log file rotation.
• TimedRotatingFileHandler instances send error messages to disk files, rotating the log file at certain timed intervals.
• SocketHandler instances send error messages to TCP/IP sockets.
• DatagramHandler instances send error messages to UDP sockets.
• SMTPHandler instances send error messages to a designated email address.

Configuration methods

There are roughly the following ways to configure logging.

• Complete configuration in code; see the example at the beginning, mainly done via the getLogger method.
• Simple configuration in code; there is an example below, mainly done via the basicConfig method.
• Via a configuration file; there is an example below, mainly via logging.config.fileConfig(filepath)

logging.basicConfig

basicConfig() provides a very convenient way for you to configure the logging module and start using it right away; see the example below. For the specific items you can configure, please consult the official documentation.

import logging
 
logging.basicConfig(filename='example.log',level=logging.DEBUG)
logging.debug('This message should go to the log file')
 
logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)
logging.debug('This message should appear on the console')
 
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')
logging.warning('is when this event was logged.')

Note: In fact, you can even configure nothing at all and use the defaults to write logs to the console. Replacing print statements this way will be a great help for future project maintenance.

Configuring logging via a file

If you want to manage logging via a configuration file, you can refer to this official documentation. This is a very common approach in log4net or log4j.

# logging.conf
[loggers]
keys=root

[logger_root]
level=DEBUG
handlers=consoleHandler
#,timedRotateFileHandler,errorTimedRotateFileHandler

#################################################
[handlers]
keys=consoleHandler,timedRotateFileHandler,errorTimedRotateFileHandler

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

[handler_timedRotateFileHandler]
class=handlers.TimedRotatingFileHandler
level=DEBUG
formatter=simpleFormatter
args=('debug.log', 'H')

[handler_errorTimedRotateFileHandler]
class=handlers.TimedRotatingFileHandler
level=WARN
formatter=simpleFormatter
args=('error.log', 'H')

#################################################
[formatters]
keys=simpleFormatter, multiLineFormatter

[formatter_simpleFormatter]
format= %(levelname)s %(threadName)s %(asctime)s:   %(message)s
datefmt=%H:%M:%S

[formatter_multiLineFormatter]
format= ------------------------- %(levelname)s -------------------------
 Time:      %(asctime)s
 Thread:    %(threadName)s
 File:      %(filename)s(line %(lineno)d)
 Message:
 %(message)s

datefmt=%Y-%m-%d %H:%M:%S

Assuming the above configuration file is placed in the same directory as the module, the call in code is as follows.

import os
filepath = os.path.join(os.path.dirname(__file__), 'logging.conf')
logging.config.fileConfig(filepath)
return logging.getLogger()

Pitfalls of duplicate log output

You may find that the logs you write are displayed multiple times. There can be many possible reasons, but they all boil down to just one: duplicate handlers are used in the logging.

Pitfall 1

import logging
 
logging.basicConfig(level=logging.DEBUG)
 
fmt = '%(levelname)s:%(message)s'
console_handler = logging.StreamHandler()
console_handler.setFormatter(logging.Formatter(fmt))
logging.getLogger().addHandler(console_handler)
 
logging.info('hello!')
 
# INFO:root:hello!
# INFO:hello!

The example above produces duplicate logs because when the basicConfig() method is called on line 3, the system creates a handler by default. If you then add another console handler, duplicate logs will appear.

Pitfall 2

import logging
 
def get_logger():
    fmt = '%(levelname)s:%(message)s'
    console_handler = logging.StreamHandler()
    console_handler.setFormatter(logging.Formatter(fmt))
    logger = logging.getLogger('App')
    logger.setLevel(logging.INFO)
    logger.addHandler(console_handler)
    return logger
 
def call_me():
    logger = get_logger()
    logger.info('hi')
 
call_me()
call_me()
 
# INFO:hi
# INFO:hi
# INFO:hi

In this example, hi was actually printed three times. What if you call call_me() once more? I'll tell you it will print 6 times. Why? Because every time you call the get_logger() method you add a new handler to it—you brought this on yourself. The proper approach is to configure the logger only once globally.

Pitfall 3

import logging
 
def get_logger():
    fmt = '%(levelname)s: %(message)s'
    console_handler = logging.StreamHandler()
    console_handler.setFormatter(logging.Formatter(fmt))
    logger = logging.getLogger('App')
    logger.setLevel(logging.INFO)
    logger.addHandler(console_handler)
    return logger
 
def foo():
    logging.basicConfig(format='[%(name)s]: %(message)s')
    logging.warn('some module use root logger')
 
def main():
    logger = get_logger()
    logger.info('App start.')
    foo()
    logger.info('App shutdown.')
 
main()
 
# INFO: App start.
# [root]: some module use root logger
# INFO: App shutdown.
# [App]: App shutdown.

Why was App shutdown printed twice at the end? That's why a lot of people on Stack Overflow ask how they should turn off the root logger—the root logger is such a damn pain. As long as you've used the root logger in the program, by default every log you print also counts as one for it. There's no particularly good solution for the example above. I suggest you find the person who used the root logger without thinking, beat them to death with a stick or fire them.

If you really want to disable the root logger, there are two non-solutions:

logging.getLogger().handlers = []  # 删除所有的handler
logging.getLogger().setLevel(logging.CRITICAL)  # 将它的级别设置到最高

Summary

Python's logging module, as part of the standard library, is fairly complete in functionality. Personally I find it easy to get started with, and it also supports advanced features such as filtering and file locking, which can meet the needs of most projects.

References

• Official documentation: https://docs.python.org/2.7/library/logging.html
• http://blog.csdn.net/balderfan/article/details/7644807
• http://python.jobbole.com/86887/