对一名开发者来说最糟糕的情况，莫过于要弄清楚一个不熟悉的应用为何不工作。有时候，你甚至不知道系统运行，是否跟原始设计一致。
在线运行的应用就是黑盒子，需要被跟踪监控。最简单也最重要的方式就是记录日志。记录日志允许我们在开发软件的同时，让程序在系统运行时发出信息，这些信息对于我们和系统管理员来说都是有用的。
就像为将来的程序员写代码文档一样，我们应该让新软件产生足够的日志供系统的开发者和管理员使用。日志是关于应用运行状态的系统文件的关键部分。给软件加日志产生句时，要向给未来维护系统的开发者和管理员写文档一样。
一些纯粹主义者认为一个受过训练的开发者使用日志和测试的时候几乎不需要交互调试器。如果我们不能用详细的日志解释开发过程中的应用，那么当代码在线上运行的时候，解释它们会变得更困难。
这篇文章介绍了 Python 的 logging 模块，包括它的设计以及针对更多复杂案例的适用方法。这篇文章不是写给开发者的文档，它更像是一个指导手册，来说明 Python 的 logging 模板是如何搭建的，并且激发感兴趣的人深入研究。
为什么使用 logging 模块？
也许会有开发者会问，为什么不是简单的 print 语句呢？ Logging 模块有很多优势，包括：
- 多线程支持
- 通过不同级别的日志分类
- 灵活性和可配置性
- 将如何记录日志与记录什么内容分离
最后一点，将我们记录内容从记录方式中真正分离，保证了软件不同部分的合作。举个例子，它允许一个框架或库的开发者增加日志并且让系统管理员或负责运行配置的人员决定稍后应该记录什么。
Logging 模块中有什么
Logging 模块完美地将它的每个部分的职责分离（遵循 Apache Log4j API 的方法）。让我们看看一个日志线是如何通过这个模块的代码，并且研究下它的不同部分。
记录器（Logger）
记录器是开发者经常交互的对象。那些主要的 API 说明了我们想要记录的内容。
举个记录器的例子，我们可以分类请求发出一条信息，而不用担心它们是如何从哪里被发出的。
比如，当我们写下 logger.info(“Stock was sold at %s”, price) 我们在头脑中就有如下模块：
我们需要一条线。假设有些代码在记录器中运行，让这条线出现在控制台或文件中。但是在内部实际发生了什么呢？
日志记录
日志记录是 logging 模块用来满足所有需求信息的包。它们包含了需要记录日志的地方、变化的字符串、参数、请求的信息队列等信息。
它们都是被记录的对象。每次我们调用记录器时，都会生成这些对象。但这些对象是如何序列化到流中的呢？通过处理器！
处理器
处理器将日志记录发送给其他输出终端，他们获取日志记录并用相关函数中处理它们。
比如，一个文件处理器将会获取一条日志记录，并且把它添加到文件中。
标准的 logging 模块已经具备了多种内置的处理器，例如：
多种文件处理器（TimeRotated, SizeRotated, Watched），可以写入文件中
- StreamHandler 输出目标流比如 stdout 或 stderr
- SMTPHandler 通过 email 发送日志记录
- SocketHandler 将日志文件发送到流套接字
- SyslogHandler、NTEventHandler、HTTPHandler及MemoryHandler等
目前我们有个类似于真实情况的模型：
大部分的处理器都在处理字符串(SMTPHandler和FileHandler等)。或许你想知道这些结构化的日志记录是如何转变为易于序列化的字节的。
格式器
格式器负责将丰富的元数据日志记录转换为字符串，如果什么都没有提供，将会有个默认的格式器。
一般的格式器类由 logging 库提供，采用模板和风格作为输入。然后占位符可以在一个 LogRecord 对象中声明所有属性。
比如：’%(asctime)s %(levelname)s %(name)s: %(message)s’ 将会生成日志类似于 2017-07-19 15:31:13,942 INFO parent.child: Hello EuroPython.
请注意：属性信息是通过提供的参数对日志的原始模板进行插值的结果。（比如，对于 logger.info(“Hello %s”, “Laszlo”) 这条信息将会是 “Hello Laszlo”）
所有默认的属性都可以在日志文档中找到。
好了，现在我们了解了格式器，我们的模型又发生了变化：
过滤器
我们日志工具的最后一个对象就是过滤器。
过滤器允许对应该发送的日志记录进行细粒度控制。多种过滤器能同时应用在记录器和处理器中。对于一条发送的日志来说，所有的过滤器都应该通过这条记录。
用户可以声明他们自己的过滤器作为对象，使用 filter 方法获取日志记录作为输入，反馈 True / False 作为输出。
出于这种考虑，以下是当前的日志工作流：
记录器层级
此时，你可能会对大量复杂的内容和巧妙隐藏的模块配置印象深刻，但是还有更需要考虑的：记录器分层。
我们可以通过 logging.getLogger() 创建一个记录器。这条字符向 getLogger 传递了一个参数，这个参数可以通过使用圆点分隔元素来定义一个层级。
举个例子，logging.getLogger(“parent.child”) 将会创建一个 “child” 的记录器，它的父级记录器叫做 “parent.” 记录器是被 logging 模块管理的全局对象，所以我们可以方便地在项目中的任何地方检索他们。
记录器的例子通常也被认为是渠道。层级允许开发者去定义渠道和他们的层级。
在日志记录被传递到所有记录器内的处理器时，父级处理器将会进行递归处理，直到我们到达*的记录器（被定义为一个空字符串），或者有一个记录器设置了 propagate = False。我们可通过更新的图中看出：
请注意父级记录器没有被调用，只有它的处理器被调用。这意味着过滤器和其他在记录器类中的代码不会在父级中被执行。当我们在记录器中增加过滤器时，这通常是个陷阱。
工作流小结
我们已经阐明过职责的划分以及我们是如何微调日志过滤。然而还是有两个其他的属性我们没有提及：
- 记录器可以是残缺的，从而不允许任何记录从这被发出。
- 一个有效的层级可以同时在记录器和处理器中被设置。
举个例子，当一个记录器被设置为 INFO 的等级，只有 INFO 等级及以上的才会被传递，同样的规则适用于处理器。
基于以上所有的考虑，最后的日志记录的流程图看起来像这样：
如何使用日志记录模块
现在我们已经了解了 logging 模块的部分及设计，是时候去了解一个开发者是如何与它交互的了。以下是一个代码例子：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
|
import logging
def sample_function(secret_parameter):
logger = logging.getLogger(__name__) # __name__=projectA.moduleB
logger.debug("Going to perform magic with '%s'", secret_parameter)
...
try:
result = do_magic(secret_parameter)
except IndexError:
logger.exception("OMG it happened again, someone please tell Laszlo")
except:
logger.info("Unexpected exception", exc_info=True)
raise
else:
logger.info("Magic with '%s' resulted in '%s'", secret_parameter, result, stack_info=True)
|
它用模块 __name__ 创建了一个日志记录器。它会基于项目结构创建渠道和等级，正如 Pyhon 模块用圆点连接一样。
记录器变量引用记录器的 “module” ，用 “projectA” 作为父级， “root” 作为父级的父级。
在第五行，我们看到如何执行调用去发送日志。我们可以用 debug 、 info 、error 或 critical 这些方法之一在合适的等级上去记录日志。
当记录一条信息时，除了模板参数，我们可以通过特殊的含义传递密码参数，最有意思的是 exc_info 和 stack_info。它们将会分别增加关于当前异常和栈帧的信息。为了方便起见，在记录器对象中有一个方法异常，正如这个错误调用 exc_info=True 。
这些是如何使用记录器模块的基础，但是有些通常被认为是不良操作的做法同样值得说明。
过度格式化字符串
应该尽量避免使用 loggger.info(“string template {}”.format(argument)) ，可能的话尽量使用 logger.info(“string template %s”, argument)。 这是个更好的实践，因为只有当日志被发送时，字符串才会发生真正改变。当我们记录的层级在 INFO 之上时，不这么做会导致浪费周期，因为这个改变仍然会发生。
捕捉和格式化异常
通常，我们想记录在抓取模块异常的日志信息，如果这样写会很直观：
|
1
2
3
4
|
try:
...
except Exception as error:
logger.info("Something bad happened: %s", error)
|
但是这样的代码会给我们显示类似于 Something bad happened: “secret_key.” 的日志行，这并不是很有用。如果我们使用 exc_info 作为事先说明，那么它将会如下显示：
|
1
2
3
4
|
try:
...
except Exception:
logger.info("Something bad happened", exc_info=True)
|
|
1
2
3
4
5
6
7
|
Something bad happened
Traceback (most recent call last):
File "sample_project.py", line 10, in code
inner_code()
File "sample_project.py", line 6, in inner_code
x = data["secret_key"]
KeyError: 'secret_key'
|
这不仅仅会包含异常的准确资源，同时也会包含它的类型。
设置记录器
装备我们的软件很简单，我们需要设置日志栈，并且制定这些记录是如何被发出的。
以下是设置日志栈的多种方法
基础设置
这是至今最简单的设置日志记录的方法。使用 logging.basicConfig(level=”INFO”) 搭建一个基础的 StreamHandler ，这样就会记录在 INFO 上的任何东西，并且到控制台以上的级别。以下是编写基础设置的一些参数：
| 参数 | 说明 | 举例 |
| filename | 指定创建的文件处理器，使用特定的文件名，而不是流处理器 | /var/logs/logs.txt |
| format | 为处理器使用特定格式的字符串 | “‘%(asctime)s %(message)s'” |
| datefmt | 使用特定的日期/时间格式 | “%H:%M:%S” |
| level | 为根记录器等级设置特定等级 | “INFO” |
在设置简单的脚本上，这是简单又使用的方法。
请注意， basicConfig 仅仅在运行的一开始可以这么调用。如果你已经设置了你的根记录器，调用 basicConfig 将不会奏效。
字典设置
所有元素的设置以及如何连接它们可以作为字典来说明。这个字典应当由不同的部分组成，包括记录器、处理器、格式化以及一些基本的通用参数。
例子如下：
|
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
28
29
|
config = {
'disable_existing_loggers': False,
'version': 1,
'formatters': {
'short': {
'format': '%(asctime)s %(levelname)s %(name)s: %(message)s'
},
},
'handlers': {
'console': {
'level': 'INFO',
'formatter': 'short',
'class': 'logging.StreamHandler',
},
},
'loggers': {
'': {
'handlers': ['console'],
'level': 'ERROR',
},
'plugins': {
'handlers': ['console'],
'level': 'INFO',
'propagate': False
}
},
}
import logging.config
logging.config.dictConfig(config)
|
当被引用时， dictConfig 将会禁用所有运行的记录器，除非 disable_existing_loggers 被设置为 false。这通常是需要的，因为很多模块声明了一个全球记录器，它在 dictConfig 被调用之前被导入的时候将会实例化。
你可以查看 schema that can be used for the dictConfig method（链接）。通常，这些设置将会存储在一个 YAML 文件中，并且从那里设置。很多开发者会倾向于使用这种方式而不是使用 fileConfig（链接）,因为它为定制化提供了更好的支持。
拓展 logging
幸亏设计了这种方式，拓展 logging 模块很容易。让我们来看些例子：
logging JSON | 记录 JSON
只要我们想要记录，我们可以通过创建一种自定义格式化来记录 JSON ，它会将日志记录转化为 JSON 编码的字符串。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
|
import logging
import logging.config
import json
ATTR_TO_JSON = ['created', 'filename', 'funcName', 'levelname', 'lineno', 'module', 'msecs', 'msg', 'name', 'pathname', 'process', 'processName', 'relativeCreated', 'thread', 'threadName']
class JsonFormatter:
def format(self, record):
obj = {attr: getattr(record, attr)
for attr in ATTR_TO_JSON}
return json.dumps(obj, indent=4)
handler = logging.StreamHandler()
handler.formatter = JsonFormatter()
logger = logging.getLogger(__name__)
logger.addHandler(handler)
logger.error("Hello")
|
添加更多上下文
在格式化中，我们可以指定任何日志记录的属性。
我们可以通过多种方式增加属性，在这个例子中，我们用过滤器来丰富日志记录。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
|
import logging
import logging.config
GLOBAL_STUFF = 1
class ContextFilter(logging.Filter):
def filter(self, record):
global GLOBAL_STUFF
GLOBAL_STUFF += 1
record.global_data = GLOBAL_STUFF
return True
handler = logging.StreamHandler()
handler.formatter = logging.Formatter("%(global_data)s %(message)s")
handler.addFilter(ContextFilter())
logger = logging.getLogger(__name__)
logger.addHandler(handler)
logger.error("Hi1")
logger.error("Hi2")
|
这样有效地在所有日志记录中增加了一个属性，它可以通过记录器。格式化会在日志行中包含这个属性。
请注意这会在你的应用中影响所有的日志记录，包含你可能用到以及你发送日志的库和其他的框架。它可以用来记录类似于在所有日志行里的一个独立请求 ID ，去追踪请求或者去添加额外的上下文信息。
从 Python 3.2 开始，你可以使用 setLogRecordFactory 去获得所有日志的创建记录和增加额外的信息。这个 extra attribute 和 LoggerAdapter class 或许同样是有趣的。
缓冲日志
有时候当错误发生时，我们想要排除日志故障。创建一个缓冲的处理器，来记录当错误发生时的最新故障信息是一种可行的办法。下面的代码是个非人为策划的例子：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
|
import logging
import logging.handlers
class SmartBufferHandler(logging.handlers.MemoryHandler):
def __init__(self, num_buffered, *args, **kwargs):
kwargs["capacity"] = num_buffered + 2 # +2 one for current, one for prepop
super().__init__(*args, **kwargs)
def emit(self, record):
if len(self.buffer) == self.capacity - 1:
self.buffer.pop(0)
super().emit(record)
handler = SmartBufferHandler(num_buffered=2, target=logging.StreamHandler(), flushLevel=logging.ERROR)
logger = logging.getLogger(__name__)
logger.setLevel("DEBUG")
logger.addHandler(handler)
logger.error("Hello1")
logger.debug("Hello2") # This line won't be logged
logger.debug("Hello3")
logger.debug("Hello4")
logger.error("Hello5") # As error will flush the buffered logs, the two last debugs will be logged
|