运维开发：Python 中少用 print，让 logging 成为习惯

日志记录的重要性

日志记录的流程框架

日志记录的相关用法

总的来说 logging 模块相比 print 有这么几个优点：

可以在 logging 模块中设置日志等级，在不同的版本（如开发环境、生产环境）上通过设置不同的输出等级来记录对应的日志，非常灵活。

print 的输出信息都会输出到标准输出流中，而 logging 模块就更加灵活，可以设置输出到任意位置，如写入文件、写入远程服务器等。

logging 模块具有灵活的配置和格式化功能，如配置输出当前模块信息、运行时间等，相比 print 的字符串格式化更加方便易用。

下面我们初步来了解下 logging 模块的基本用法，先用一个实例来感受一下：

import logging

logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

logger = logging.getLogger(__name__)

logger.info('This is a log info')

logger.debug('Debugging')

logger.warning('Warning exists')

logger.info('Finish')

2018-06-03 13:42:43,526 - __main__ - INFO - This is a log info

2018-06-03 13:42:43,526 - __main__ - WARNING - Warning exists

2018-06-03 13:42:43,526 - __main__ - INFO - Finish

可以看到输出结果一共有三条日志信息，每条日志都是对应了指定的格式化内容，另外我们发现 DEBUG 的信息是没有输出的，这是因为我们在全局配置的时候设置了输出为 INFO 级别，所以 DEBUG 级别的信息就被过滤掉了。

这时如果我们将输出的日志级别设置为 DEBUG，就可以看到 DEBUG 级别的日志输出了：

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

输出结果：

2018-06-03 13:49:22,770 - __main__ - INFO - This is a log info

2018-06-03 13:49:22,770 - __main__ - DEBUG - Debugging

2018-06-03 13:49:22,770 - __main__ - WARNING - Warning exists

2018-06-03 13:49:22,770 - __main__ - INFO - Finish

由此可见，相比 print 来说，通过刚才的代码，我们既可以输出时间、模块名称，又可以输出不同级别的日志信息作区分并加以过滤，是不是灵活多了？

当然这只是 logging 模块的一小部分功能，接下来我们首先来全面了解一下 basicConfig 的参数都有哪些：

下面我们再用一个实例来感受一下：

import logging

logging.basicConfig(level=logging.DEBUG,

filename='output.log',

datefmt='%Y/%m/%d %H:%M:%S',

format='%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(module)s - %(message)s')

logger = logging.getLogger(__name__)

logger.info('This is a log info')

logger.debug('Debugging')

logger.warning('Warning exists')

logger.info('Finish')

这里我们指定了输出文件的名称为 output.log，另外指定了日期的输出格式，其中年月日的格式变成了 %Y/%m/%d，另外输出的 format 格式增加了 lineno、module 这两个信息，运行之后便会生成一个 output.log 的文件，内容如下：

2018/06/03 14:43:26 - __main__ - INFO - 9 - demo3 - This is a log info

2018/06/03 14:43:26 - __main__ - DEBUG - 10 - demo3 - Debugging

2018/06/03 14:43:26 - __main__ - WARNING - 11 - demo3 - Warning exists

2018/06/03 14:43:26 - __main__ - INFO - 12 - demo3 - Finish

可以看到日志便会输出到文件中，同时输出了行号、模块名称等信息。

以上我们通过 basicConfig 来进行了一些全局的配置，我们同样可以使用 Formatter、Handler 进行更灵活的处理，下面我们来了解一下。

Level

首先我们来了解一下输出日志的等级信息，logging 模块共提供了如下等级，每个等级其实都对应了一个数值，列表如下：

这里最高的等级是 CRITICAL 和 FATAL，两个对应的数值都是 50，另外对于 WARNING 还提供了简写形式 WARN，两个对应的数值都是 30。

我们设置了输出 level，系统便只会输出 level 数值大于或等于该 level 的的日志结果，例如我们设置了输出日志 level 为 INFO，那么输出级别大于等于 INFO 的日志，如 WARNING、ERROR 等，DEBUG 和 NOSET 级别的不会输出。

import logging

logger = logging.getLogger(__name__)

logger.setLevel(level=logging.WARN)

# Log

logger.debug('Debugging')

logger.critical('Critical Something')

logger.error('Error Occurred')

logger.warning('Warning exists')

logger.info('Finished')

这里我们设置了输出级别为 WARN，然后对应输出了五种不同级别的日志信息，运行结果如下：

Critical Something

Error Occurred

Warning exists

可以看到只有 CRITICAL、ERROR、WARNING 信息输出了，DEBUG、INFO 信息没有输出。

Handler

下面我们先来了解一下 Handler 的用法，看下面的实例：

import logging

logger = logging.getLogger(__name__)

logger.setLevel(level=logging.INFO)

handler = logging.FileHandler('output.log')

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

handler.setFormatter(formatter)

logger.addHandler(handler)

logger.info('This is a log info')

logger.debug('Debugging')

logger.warning('Warning exists')

logger.info('Finish')

这里我们没有再使用 basicConfig 全局配置，而是先声明了一个 Logger 对象，然后指定了其对应的 Handler 为 FileHandler 对象，然后 Handler 对象还单独指定了 Formatter 对象单独配置输出格式，最后给 Logger 对象添加对应的 Handler 即可，最后可以发现日志就会被输出到 output.log 中，内容如下：

2018-06-03 14:53:36,467 - __main__ - INFO - This is a log info

2018-06-03 14:53:36,468 - __main__ - WARNING - Warning exists

2018-06-03 14:53:36,468 - __main__ - INFO - Finish

另外我们还可以使用其他的 Handler 进行日志的输出，logging 模块提供的 Handler 有：

StreamHandler：

logging.StreamHandler；日志输出到流，可以是 sys.stderr，sys.stdout 或者文件。

FileHandler：

logging.FileHandler；日志输出到文件。

BaseRotatingHandler：

logging.handlers.BaseRotatingHandler；基本的日志回滚方式。

RotatingHandler：

logging.handlers.RotatingHandler；日志回滚方式，支持日志文件最大数量和日志文件回滚。

TimeRotatingHandler：

logging.handlers.TimeRotatingHandler；日志回滚方式，在一定时间区域内回滚日志文件。

SocketHandler：

logging.handlers.SocketHandler；远程输出日志到TCP/IP sockets。

DatagramHandler：

logging.handlers.DatagramHandler；远程输出日志到UDP sockets。

SMTPHandler：

logging.handlers.SMTPHandler；远程输出日志到邮件地址。

SysLogHandler：

logging.handlers.SysLogHandler；日志输出到syslog。

NTEventLogHandler：

logging.handlers.NTEventLogHandler；远程输出日志到Windows NT/2000/XP的事件日志。

MemoryHandler：

logging.handlers.MemoryHandler；日志输出到内存中的指定buffer。

HTTPHandler：

logging.handlers.HTTPHandler；通过”GET”或者”POST”远程输出到HTTP服务器。

下面我们使用三个 Handler 来实现日志同时输出到控制台、文件、HTTP 服务器：

import logging

from logging.handlers import HTTPHandler

import sys

logger = logging.getLogger(__name__)

logger.setLevel(level=logging.DEBUG)

# StreamHandler

stream_handler = logging.StreamHandler(sys.stdout)

stream_handler.setLevel(level=logging.DEBUG)

logger.addHandler(stream_handler)

# FileHandler

file_handler = logging.FileHandler('output.log')

file_handler.setLevel(level=logging.INFO)

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

file_handler.setFormatter(formatter)

logger.addHandler(file_handler)

# HTTPHandler

http_handler = HTTPHandler(host='localhost:8001', url='log', method='POST')

logger.addHandler(http_handler)

# Log

logger.info('This is a log info')

logger.debug('Debugging')

logger.warning('Warning exists')

logger.info('Finish')

运行之前我们需要先启动 HTTP Server，并运行在 8001 端口，其中 log 接口是用来接收日志的接口。

运行之后控制台输出会输出如下内容：

This is a log info

Debugging

Warning exists

Finish

output.log 文件会写入如下内容：

2018-06-03 15:13:44,895 - __main__ - INFO - This is a log info

2018-06-03 15:13:44,947 - __main__ - WARNING - Warning exists

2018-06-03 15:13:44,949 - __main__ - INFO - Finish

HTTP Server 会收到控制台输出的信息。

这样一来，我们就通过设置多个 Handler 来控制了日志的多目标输出。

另外值得注意的是，在这里 StreamHandler 对象我们没有设置 Formatter，因此控制台只输出了日志的内容，而没有包含时间、模块等信息，而 FileHandler 我们通过 setFormatter() 方法设置了一个 Formatter 对象，因此输出的内容便是格式化后的日志信息。

另外每个 Handler 还可以设置 level 信息，最终输出结果的 level 信息会取 Logger 对象的 level 和 Handler 对象的 level 的交集。

Formatter

在进行日志格式化输出的时候，我们可以不借助于 basicConfig 来全局配置格式化输出内容，可以借助于 Formatter 来完成，下面我们再来单独看下 Formatter 的用法：

import logging

logger = logging.getLogger(__name__)

logger.setLevel(level=logging.WARN)

formatter = logging.Formatter(fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s', datefmt='%Y/%m/%d %H:%M:%S')

handler = logging.StreamHandler()

handler.setFormatter(formatter)

logger.addHandler(handler)

# Log

logger.debug('Debugging')

logger.critical('Critical Something')

logger.error('Error Occurred')

logger.warning('Warning exists')

logger.info('Finished')

在这里我们指定了一个 Formatter，并传入了 fmt 和 datefmt 参数，这样就指定了日志结果的输出格式和时间格式，然后 handler 通过 setFormatter() 方法设置此 Formatter 对象即可，输出结果如下：

2018/06/03 15:47:15 - __main__ - CRITICAL - Critical Something

2018/06/03 15:47:15 - __main__ - ERROR - Error Occurred

2018/06/03 15:47:15 - __main__ - WARNING - Warning exists

这样我们可以每个 Handler 单独配置输出的格式，非常灵活。

捕获Traceback

如果遇到错误，我们更希望报错时出现的详细 Traceback 信息，便于调试，利用 logging 模块我们可以非常方便地实现这个记录，我们用一个实例来感受一下：

import logging

logger = logging.getLogger(__name__)

logger.setLevel(level=logging.DEBUG)

# Formatter

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

# FileHandler

file_handler = logging.FileHandler('result.log')

file_handler.setFormatter(formatter)

logger.addHandler(file_handler)

# StreamHandler

stream_handler = logging.StreamHandler()

stream_handler.setFormatter(formatter)

logger.addHandler(stream_handler)

# Log

logger.info('Start')

logger.warning('Something maybe fail.')

try:

result = 10 / 0

except Exception:

logger.error('Faild to get result', exc_info=True)

logger.info('Finished')

这里我们在 error() 方法中添加了一个参数，将 exc_info 设置为了 True，这样我们就可以输出执行过程中的信息了，即完整的 Traceback 信息。

运行结果如下：

2018-06-03 16:00:15,382 - __main__ - INFO - Start print log

2018-06-03 16:00:15,382 - __main__ - DEBUG - Do something

2018-06-03 16:00:15,382 - __main__ - WARNING - Something maybe fail.

2018-06-03 16:00:15,382 - __main__ - ERROR - Faild to get result

Traceback (most recent call last):

File "/private/var/books/aicodes/loggingtest/demo8.py", line 23, in

result = 10 / 0

ZeroDivisionError: division by zero

2018-06-03 16:00:15,383 - __main__ - INFO - Finished

可以看到这样我们就非常方便地记录下来了报错的信息，一旦出现了错误，我们也能非常方便地排查。

配置共享

在写项目的时候，我们肯定会将许多配置放置在许多模块下面，这时如果我们每个文件都来配置 logging 配置那就太繁琐了，logging 模块提供了父子模块共享配置的机制，会根据 Logger 的名称来自动加载父模块的配置。

例如我们这里首先定义一个 main.py 文件：

import logging

import core

logger = logging.getLogger('main')

logger.setLevel(level=logging.DEBUG)

# Handler

handler = logging.FileHandler('result.log')

handler.setLevel(logging.INFO)

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

handler.setFormatter(formatter)

logger.addHandler(handler)

logger.info('Main Info')

logger.debug('Main Debug')

logger.error('Main Error')

core.run()

这里我们配置了日志的输出格式和文件路径，同时定义了 Logger 的名称为 main，然后引入了另外一个模块 core，最后调用了 core 的 run() 方法。

接下来我们定义 core.py，内容如下：

import logging

logger = logging.getLogger('main.core')

def run():

logger.info('Core Info')

logger.debug('Core Debug')

logger.error('Core Error')

这里我们定义了 Logger 的名称为 main.core，注意这里开头是 main，即刚才我们在 main.py 里面的 Logger 的名称，这样 core.py 里面的 Logger 就会复用 main.py 里面的 Logger 配置，而不用再去配置一次了。

运行之后会生成一个 result.log 文件，内容如下：

2018-06-03 16:55:56,259 - main - INFO - Main Info

2018-06-03 16:55:56,259 - main - ERROR - Main Error

2018-06-03 16:55:56,259 - main.core - INFO - Core Info

2018-06-03 16:55:56,259 - main.core - ERROR - Core Error

可以看到父子模块都使用了同样的输出配置。

如此一来，我们只要在入口文件里面定义好 logging 模块的输出配置，子模块只需要在定义 Logger 对象时名称使用父模块的名称开头即可共享配置，非常方便。

文件配置

在开发过程中，将配置在代码里面写死并不是一个好的习惯，更好的做法是将配置写在配置文件里面，我们可以将配置写入到配置文件，然后运行时读取配置文件里面的配置，这样是更方便管理和维护的，下面我们以一个实例来说明一下，首先我们定义一个 yaml 配置文件：

version: 1

formatters:

brief:

format: "%(asctime)s - %(message)s"

simple:

format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"

handlers:

console:

class : logging.StreamHandler

formatter: brief

level : INFO

stream : ext://sys.stdout

file:

class : logging.FileHandler

formatter: simple

level: DEBUG

filename: debug.log

error:

class: logging.handlers.RotatingFileHandler

level: ERROR

formatter: simple

filename: error.log

maxBytes: 10485760

backupCount: 20

encoding: utf8

loggers:

main.core:

level: DEBUG

handlers: [console, file, error]

root:

level: DEBUG

handlers: [console]

这里我们定义了 formatters、handlers、loggers、root 等模块，实际上对应的就是各个 Formatter、Handler、Logger 的配置，参数和它们的构造方法都是相同的。

接下来我们定义一个主入口文件，main.py，内容如下：

import logging

import core

import yaml

import logging.config

import os

def setup_logging(default_path='config.yaml', default_level=logging.INFO):

path = default_path

with open(path, 'r', encoding='utf-8') as f:

config = yaml.load(f)

else:

logging.basicConfig(level=default_level)

def log():

logging.debug('Start')

logging.info('Exec')

logging.info('Finished')

if __name__ == '__main__':

yaml_path = 'config.yaml'

setup_logging(yaml_path)

log()

core.run()

这里我们定义了一个 setup_logging() 方法，里面读取了 yaml 文件的配置，然后通过 dictConfig() 方法将配置项传给了 logging 模块进行全局初始化。

另外这个模块还引入了另外一个模块 core，所以我们定义 core.py 如下：

import logging

logger = logging.getLogger('main.core')

def run():

logger.info('Core Info')

logger.debug('Core Debug')

logger.error('Core Error')

这个文件的内容和上文是没有什么变化的。

观察配置文件，主入口文件 main.py 实际上对应的是 root 一项配置，它指定了 handlers 是 console，即只输出到控制台。另外在 loggers 一项配置里面，我们定义了 main.core 模块，handlers 是 console、file、error 三项，即输出到控制台、输出到普通文件和回滚文件。

这样运行之后，我们便可以看到所有的运行结果输出到了控制台：

2018-06-03 17:07:12,727 - Exec

2018-06-03 17:07:12,727 - Finished

2018-06-03 17:07:12,727 - Core Info

2018-06-03 17:07:12,727 - Core Info

2018-06-03 17:07:12,728 - Core Error

2018-06-03 17:07:12,728 - Core Error

在 debug.log 文件中则包含了 core.py 的运行结果：

2018-06-03 17:07:12,727 - main.core - INFO - Core Info

2018-06-03 17:07:12,727 - main.core - DEBUG - Core Debug

2018-06-03 17:07:12,728 - main.core - ERROR - Core Error

可以看到，通过配置文件，我们可以非常灵活地定义 Handler、Formatter、Logger 等配置，同时也显得非常直观，也非常容易维护，在实际项目中，推荐使用此种方式进行配置。

以上便是 logging 模块的基本使用方法，有了它，我们可以方便地进行日志管理和维护，会给我们的工作带来极大的方便。

日志记录使用常见误区

在日志输出的时候经常我们会用到字符串拼接的形式，很多情况下我们可能会使用字符串的 format() 来构造一个字符串，但这其实并不是一个好的方法，因为还有更好的方法，下面我们对比两个例子：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# bad

logging.debug('Hello , !'.format('World', 'Congratulations'))

# good

logging.debug('Hello %s, %s!', 'World', 'Congratulations')

这里有两种打印 Log 的方法，第一种使用了字符串的 format() 的方法进行构造，传给 logging 的只用到了第一个参数，实际上 logging 模块提供了字符串格式化的方法，我们只需要在第一个参数写上要打印输出的模板，占位符用 %s、%d 等表示即可，然后在后续参数添加对应的值就可以了，推荐使用这种方法。

运行结果如下：

2018-06-03 22:27:51,220 - root - DEBUG - Hello World, Congratulations!

2018-06-03 22:27:51,220 - root - DEBUG - Hello World, Congratulations!

另外在进行异常处理的时候，通常我们会直接将异常进行字符串格式化，但其实可以直接指定一个参数将 traceback 打印出来，示例如下：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

try:

result = 5 / 0

except Exception as e:

# bad

logging.error('Error: %s', e)

# good

logging.error('Error', exc_info=True)

# good

logging.exception('Error')

如果我们直接使用字符串格式化的方法将错误输出的话，是不会包含 Traceback 信息的，但如果我们加上 exc_info 参数或者直接使用 exception() 方法打印的话，那就会输出 Traceback 信息了。

运行结果如下：

2018-06-03 22:24:31,927 - root - ERROR - Error: division by zero

2018-06-03 22:24:31,927 - root - ERROR - Error

Traceback (most recent call last):

File "/private/var/books/aicodes/loggingtest/demo9.py", line 6, in

result = 5 / 0

ZeroDivisionError: division by zero

2018-06-03 22:24:31,928 - root - ERROR - Error

Traceback (most recent call last):

File "/private/var/books/aicodes/loggingtest/demo9.py", line 6, in

result = 5 / 0

ZeroDivisionError: division by zero

以上便是整个对 logging 模块的介绍。嗯，是时候抛弃 print 了，开始体验下 logging 的便利吧！

干货分享