Python提供了功能强大且灵活的日志系统模块logging。根据业务需求可以根据自定义的日志事件等级做对应的处理。

基础模式

只是向控制台打印信息，我们可以直接调用日志记录方法：

等级 使用场景
DEBUG 详细信息，通常只有在诊断问题时才有意义
INFO 确认事情按预期工作
WARNING 表示发生了意想不到的事情，或者指示在不久的将来出现问题（例如，“磁盘空间不足”）。该软件仍在按预期工作
ERROR 由于更严重的问题，软件还没有能够执行一些功能
CRITICAL 一个严重的错误，表明程序本身可能无法继续运行

这些方法名代表日志等级严重程度。最低严重等级是debug,最严重等级是critical。

1
2
3
4
import logging

logging.warning('It is a warn message!')
logging.info('It is a info message!')

你将看到：

1
WARNING:root:It is a warn message!

logging.warning()方法的信息被打印了，但logging.info()方法信息没有被打印出来。

这是因为在logging模块默认等级是WARNING。低于这个等级的日志记录方法信息不会被跟踪。

logging.basicConfig

可以通过logging.basicConfig(**kwargs)对logging`进行配置。

1
2
3
4
5
6
7
import logging

logging.basicConfig(filename='example.log',level=logging.DEBUG)

logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

上面的代码会将日志信息写入到example.log 文件中，里面内容如下：

1
2
3
DEBUG:root:This message should go to the log file
INFO:root:So should this
WARNING:root:And this, too

我们通过basicConfig()方法指定了logging的等级为DEBUG，并且将信息写入example.log 文件中。

你多次调用上面的脚本，日志会向example.log 文件尾部添加。如果你希望每调用一次脚本，日志能覆盖原因文件内容，应该指定文件操作模式filemode。配置应该如下：

1
logging.basicConfig(filename='example.log', filemode='w', level=logging.DEBUG)

默认日志输出格式是:[levelname]:[name]:[message]。通过basicConfig我们可以指定日志输出格式。

1
2
3
4
5
import logging
logging.basicConfig(format='%(asctime)s :%(levelname)% : %(name)% : %(message)s', datefmt='%Y-%m/-%d %I:%M:%S %p',filename='example.log',level=logging.DEBUG)
logging.warning('is when this event was logged.')

#2017-12-14 11:41:42 AM：WARNING: root : is when this event was logged.

将日志记录时间也记录下来了。

记录变量数据

记录变量有三种写法%,$,{：

1
2
3
4
5
import logging

logging.warning('%s before you %s','look','leap!')
logging.warning('{0} before you {1}','look','leap!')
logging.warning('$a before you $b',a='look',b='leap!')

Python3.2以后才支持{和$写法。使用规则是str.format()和string.Template

高级模式

logging库使用模块方式提供四种组件用于定制日志系统：

  • loggers - 记录器，暴露给应用程序直接调用的接口。
  • handler - 处理器，将记录器日志发送给合适的目的地。
  • filter - 过滤器，提供更好的粒度设施来确定要输出的日志记录。
  • formatters - 格式化器，指定最终输出中日志记录的布局。

日志信息是在LogRecord实例的loggers,handlers,filters,formatters 之间传递的。

logger记录器是日志记录系统中执行开始单元。记录器是Logger类的实例化。通过logging.getLogger(name)获得。

Logging工作流

Logging工作流程图如下：

Logging flow

使用Logging模块的全局作用域中的getLogger函数获得Logger实例。使用Logger对象中的debug,info,error,warn,critical等方法记录日志信息。

当调用日志记录方法后：

  • 判断日志的等级是否大于Logger对象设置的等级，如果大于则继续执行，否则结束。
  • 产生日志。
  • 记录器连接的过滤器是否拒绝记录，如果yes则结束，否则继续。
  • 将日志传递给当前logger绑定的处理器，如果当前logger有处理器就交给处理器处理。
  • 当前logger是否允许将日志传播给父级，如果yes则查找父级logger,如果找到将日志传递给父级处理器处理。
  • 处理器接收到日志，先判断日志等级是否大于处理器设置的等级，如果大于则继续否则结束掉。
  • 处理器将可以处理的日志交给于自己绑定的过滤器，如果过滤器拒绝则结束。
  • 处理器的过滤器通过日志筛选，则日志最后按照处理器设定的打印格式输出到设定的目的地。

Loggers

Loggers实例是通过logging.getLogger(name)获得。它主要做三件事情：

  1. 向应用代码提供运行时记录日志信息的方法。
  2. 根据严重性或通过过滤器确定采取的日志消息。
  3. 将日志信息传递给感兴趣的处理器

logger对象的方法中分为两类：配置和发送信息。

configuration

  • Logger.setLevel()指定记录器处理日志的最低严重级别。
  • Logger.addHandler()和Logger.removeHandler给记录器添加或移除处理器。通过过滤的日志信息会交给处理器处理。处理器可以有多个，会依次执行处理日志信息。
  • [Logger.addFilter()]和[Logger.removeFilter()]添加或移除过滤器。通过记录器等级设置的日志信息会交给过滤器处理。过滤器可以有多个，会依次进行日志过滤。

以上方法不是必须设定的。

记录日志方法有：

  • Logger.debug(), Logger.info(), Logger.warning(), Logger.error(), Logger.critical()。创建日志记录信息，根据它们名称代码严重等级。它们接收变量赋值。
  • Logger.exception()创建一个类似Logger.error()错误信息。但是它只能用于exception处理方法中。
  • Logger.log(lvl,msg)接收整数参数（lvl ）作为信息等级。然后接收日志信息。一般用于记录大量日志信息。

日志记录方法等级：

Level Numeric value
CRITICAL 50
ERROR 40
WARING 30
INFO 20
DEBUG 10
NOTSET 0

getLogger()方法返回一个logger实例，如果不指定名称则默认时root。同一个名字调用多次getLogger()方法返回是同一个logger实例。

每个记录器有个名字，如果没有赋值默认是root。它们是.做为名字分隔符拥有上下级关系的空间结构。例如：一个记录器名字是scan,则它是scan.html,scan.css的父级。子级没有指定等级它会继承父级的等级。默认记录等级是(WARING)。

Logger名字可以是任意形式的，这个记录器的名字就是创建它这块应用区域在日志系统中的名字。

记录器的名字用于追踪包或模块的层级，并直观的显示日志记录发生的位置。

记录器会将信息传播给父级记录器的处理器进行处理。你可以将propagate 设为Flase关闭掉。

Handlers

Handler对象目的是将日志信息（基于日志严重等级）分配到指定的目的地。Logger可以添加0个或多个Handler，通过addHandler()方法。例子：

一个脚本，需要将应用所有的日志信息写入日志文件，并将所有严重等级大于higher的日志使用标准方式输出，最后将critical等级的日志信息用邮件发送给指定邮箱。则这个脚本需要创建三个handler。

handler处理器拥有下这些方法：

  • setLevel()处理器处理等级
  • setFormatter()处理器输出格式
  • addFilter()和removeFilter()添加或移除绑定的过滤器。

标准库已经包含了一些常用的处理类型(StreamHandler 和 FileHandler)

Formatters

Formatter对象负责配置日志消息的结构，顺序，内容。例子：

1
2
import logging
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

上面代码指定了日志最后输出信息格式是：当前时间-记录器名字-日志等级-日志信息。

formatter支持变量如下：

Format Description
%(asctime)s LogRecord创建时的可读时间
%(filename)s 文件名字
%(funcName)s 方法名
%(levelname)s 日志等级
%(levelno)s 日志等级数
%(lineno)d 记录调用发出的源行号
%(message)s 日志信息
%(module)s 模块名
%(name)s 记录器名字
%(pathname)s 发出日志记录调用的源文件的完整路径名（如果可用）。
%(process)d 进程ID（如果可用）
%(processName)s 进程名字

Configuring Logging

配置logging有三种方式：

  1. 通过在Python 代码创建 loggers,handlers,formatters，使用配合方法将它们联系起来。
  2. 通过logging配置文件，然后通过fileConfig()方法读取。
  3. 创建一个字典类型的配置项，传给dictConfig()方法。

在Python代码配置Logging规则：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
import logging

# 创建 logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# 创建标准输出和DEBUG等级
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# 创建规则
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# 将规则添加 进 ch 处理器
ch.setFormatter(formatter)

# logger 绑定处理器
logger.addHandler(ch)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

运行自个模块，在命令行会输出这些：

1
2
3
4
5
6
$ python simple_logging_module.py
2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message
2005-03-19 15:10:26,620 - simple_example - INFO - info message
2005-03-19 15:10:26,695 - simple_example - WARNING - warn message
2005-03-19 15:10:26,697 - simple_example - ERROR - error message
2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message

通过fileConfig()加载配置规则：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
import logging
import logging.config

logging.config.fileConfig('logging.conf')

# create logger
logger = logging.getLogger('simpleExample')

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

配置文件：

[loggers] # 定义loggers
keys=root,simpleExample

[handlers] # 定义handlers
keys=consoleHandler

[formatters] # 定义formatters
keys=simpleFormatter

[logger_root] # root logger
level=DEBUG
handlers=consoleHandler

[logger_simpleExample] # simpleExample logger
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler] # consoleHandler handler
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,) # 处理器参数

[formatter_simpleFormatter] # simpleFormatter formatter
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

它的输出和非文件配置几乎一样：

1
2
3
4
5
6
$ python simple_logging_config.py
2005-03-19 15:38:55,977 - simpleExample - DEBUG - debug message
2005-03-19 15:38:55,979 - simpleExample - INFO - info message
2005-03-19 15:38:56,054 - simpleExample - WARNING - warn message
2005-03-19 15:38:56,055 - simpleExample - ERROR - error message
2005-03-19 15:38:56,130 - simpleExample - CRITICAL - critical message

配置文件格式规则是configparser。
配置文件将配置项从python代码中抽离出来，更便于管理和修改。

fileConfig()有个默认参数disable_existing_loggers默认为True。它会导致在fileConfig()之前存在的loggers失效。将它设为False就可以了。

重复打印

在日志系统中因为我们代码写法不慎，经常会导致日志重复打印。

basicConfig()

basicConfig()方法时系统会默认创建一个handler，如果你再添加一个控制台handler时就会出现重复日志。

1
2
3
4
5
6
7
8
9
10
11
12
13
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!

handler

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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

每次调用get_logger()方法时都会给它加一个新的handler。则一天信息就会经过累加的处理器。全局只配置logger一次。

root

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
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.

为嘛最后的App shutdown打印了两次？
只要你在程序中使用过root logger，那么默认你打印的所有日志都算它一份。