python 中的 logging 详解_python logging

1. Abstract

写 python 代码难免会用到 logging 日志，用它记录程序运行状态及过程极为方便，起码看起来比 print() 高大上多了。使用 logging 也比较简单，下面是官方文档给出的一个简单例子：

import logging
logging.warning('Watch out!')  # will print a message to the console
logging.info('I told you so')  # will not print anything
1
2
3

控制台输出：

对于这个输出的解释：WARNING 是日志信息等级，root 是日志记录器(Logger)的名字，后面是记录信息。

对于一些基础的知识，这里就不多说了。我之前也一直在用 logging 查看及记录实验信息，代码基本是从博客抄来的，比较基础的用法：

def set_logger():
	logging.basicConfig(
		filename=path.join(config.save_path, 'train.log'),
		filemode='w',
		format='%(asctime)s | %(levelname)s:  %(message)s',
		datefmt='%Y-%m-%d %H:%M:%S',
		level=logging.INFO,
		encoding='UTF-8'
	)
	console = logging.StreamHandler()
	console.setLevel(logging.INFO)
	console.setFormatter(logging.Formatter('%(asctime)s | %(levelname)s:  %(message)s'))
	logging.getLogger().addHandler(console)
1
2
3
4
5
6
7
8
9
10
11
12
13

运行程序前，先执行一下这个函数，就可以将 logging.info(message) 输出到控制台以及日志文件中。然而，关于这段代码，我只知道：前半部分的 logging.basicConfig(...) 是配置日志文件的路径和信息格式，后半部分是配置输出到 console 的信息格式，其他就一无所知了，比如：什么是 logging.StreamHandler()？它为什么将信息输出到控制台？logging.getLogger().addHandler(console) 到底做了什么？

想解答这些问题，探索 logging 更丰富的用法，于是我去查看了官方文档教程，在这里对这次学习进行记录整理。本文不追究文档的细节，对基础的知识也默认已知，主要目的是建立对 logging 整体架构和工作方式的认识。

2. logging 模块结构

logging 模块内容还是比较多的，光 logging/__init__.py 就两千多行代码，另加 logging/config.py 和 logging/handlers.py，所以我只抽出教程中提到的一些内容，展示出来，先看一下类结构图吧：

图1：logging 模块内的类结构

大概长这个样子，位于第一层的主要有四个类：LogRecord、Filter、Filterer 和 Formatter。然后 Filterer 有两个子类 Handler 和 Logger。。。下面我把类之间的联系图展示出来：

图2：类图+日志流程图

本来打算只画一个类似 UML 类图的东西，结果发现这玩意儿也没啥好画的，而且关于 UML 的知识也忘干净了。看了教程中的信息传递流程图，发现虽然它逻辑很清晰，但不能和具体的代码对应起来，于是突发奇想，干脆把 UML 图和流程图整合起来算了，于是就读了源代码，画成了上面的这张图，教程的流程图在下面。

一图胜千言，我现在只对上图的符号做一些解释：红色属于 Filterer 部分，蓝色属于 Logger 部分，橙色属于 Handler 部分，紫色属于 Formatter 部分；箭头上的文字代表其上传输的信息，箭头旁边带颜色背景的方块代表各类的方法；菱形代表判断，矩形代表函数动作，虚线框起来的是整个函数内容。

图3：官方教程中的日志流程图

要想真正了解 logging 的工作机制，结合这两张图去看看源代码，一定会有不小的收获。

除了图中所画的类图外，logging 模块还有一些其他内容，如管理 logger 树形结构所用的类：Manager、PlaceHolder 等；可直接调用的函数：

• looging.debug(...)、looging.info(...)；
• looging.getLogger(...)；
• looging.basicConfig(...)

后面会讲它们背后的运作机制。

3. Logger 的层次结构和命名规则

仅仅了解上面的结构图是不够的，至少现在还不明白为什么一个 logging.basicConfig(...) 函数配置文件后，就可以用 logging.info(...) 输出日志到文件？logging.getLogger() 到底得到了什么？为什么它 add 一个 logging.StreamHandler() 之后就能用 logging.info(...) 输出日志到控制台？等等。。。

3.1 RootLogger

从图中看，大概可以知道：日志信息是由 Logger 的实例发出的， 结合上面的 WARNING:root:Watch out! 以及 RootLogger，猜想系统有一个默认的名为 root 的 Logger 对象，当我们调用 logging.info(...) 时，系统就会调用这个对象的方法进行日志输出。的确，我发现了这行代码：

root = RootLogger(WARNING)  # RootLogger 是 Logger 的子类
1

这个 Logger 的子类并没有添加什么东西，仅仅是给起了个默认的名字 “root”：

Logger.__init__(self, "root", level)
1

名为 “root” 的 Logger 对象默认 Level 是 WARNING，这就是刚才的例子中，只输出 WARNING 信息而没有 INFO 信息的原因。看一看源代码，具体了解一下：

def info(msg, *args, **kwargs):
	"""
	Log a message with severity 'INFO' on the root logger. If the logger has
	no handlers, call basicConfig() to add a console handler with a pre-defined
	format.
	"""
	if len(root.handlers) == 0:
		basicConfig()
	root.info(msg, *args, **kwargs)
1
2
3
4
5
6
7
8
9

调用 logging.info(...) 时，它首先会检查 root 有没有配置好(即有没有 handlers)，没有的话，就执行 basicConfig() 进行默认配置，关于默认配置，稍后会说。然后，调用 root 的 info(...) 函数，接下来一切按上面的流程图走。

接下来，就可以回答问题：logging.getLogger() 到底得到了什么？

def getLogger(name=None):
	"""
	Return a logger with the specified name, creating it if necessary.
	If no name is specified, return the root logger.
	"""
	if not name or isinstance(name, str) and name == root.name:
		return root
	return Logger.manager.getLogger(name)
1
2
3
4
5
6
7
8

这个函数中，首先检查参数 name 是不是没有提供，或者提供的是不是 root.name，如果是，则返回 root 日志对象，否则返回 Logger.manager.getLogger(name) (这一句先不管)。那么，得到 root 后，在我之前使用的代码里 logging.getLogger().addHandler(console) 就是 root.addHandler(console)，给 root 日志对象添加了一个目的地是控制台的 StreamHandler 对象，所以在使用函数 logging.info(...) 时，才会输出到控制台。

3.2 层次结构和命名规则

图中还有一个陌生的地方：callHandlers(...) 中的循环。

图4：Logger 中的信息层级传播

这可不是 “Pass Record to Handlers of the Current Logger” 的循环，外面还有一层循环呢！看看 callHandlers(...) 的内部代码片段：

c = self
while c:
	for hdlr in c.handlers:  # 把信息 record 发送给其 self.handlers
		if record.levelno >= hdlr.level:
			hdlr.handle(record)
	if not c.propagate:  # 是否允许传播
		c = None    # break out
	else:
		c = c.parent  # 转向其父 logger
1
2
3
4
5
6
7
8
9

logger 对象在把信息 record 发送给其 self.handlers 后(for hdlr in c.handlers)，会检查是否允许传播(self.propagate)，如果不允许，则结束 while 循环，停止传播，否则，其父 logger(self.parent) 也向其包含的 handlers 发送 record。注意：传播过程中并不考虑父 logger 的 Level 和 Filters，而是直接将 record 发送给父 logger 的 handlers。

嗯！这个还是没见过的。那什么是父 logger？怎么组织的？这个牵扯到两方面：Logger 对象的层次结构和命名规则，以及工厂机制。

3.2.1 层次结构和命名规则

Logger 层级命名规则

很简单，和 Python 包的命名规则是一样的。

3.2.2 Logger 的工厂机制

工厂模式

这是官方文档 “#记录器对象” 一节的第一段话。妥妥的工厂模式，如果是 Java 语言，Logger 类肯定会被声明为一个 private class，使外部无法访问到该类，进而无法直接实例化 Logger，只能通过公有函数 public Logger getLogger(String name) 获取 Logger 对象。但在 Python 中没有这样的公私有管理方案，你可以通过 Logger(name) 直接实例化记录器，但官方不建议这么做，他们安排了工厂模式，以方便管理层次化的日志记录器。关于 Logger 类的大致内容，已经在类图中展示，下面让我们看一看函数 logging.getLogger(name) 干了什么，上面已经展示了该函数的代码，知道它默认返回 root 记录器，但其他情况呢？返回 Logger.manager.getLogger(name)，不过这里的 Logger.manager 是什么？我在 class Logger(Filterer) 里找了半天没找到，后来发现它在外面：

Logger.root = root
Logger.manager = Manager(Logger.root)
1
2

这两句就在 root = RootLogger(WARNING) 的下面，在创建了 root 对象之后，立马给 Logger 类定了这两个属性，根据 Manager 的构造器：

def __init__(self, rootnode):
	"""
	Initialize the manager with the root node of the logger hierarchy.
	"""
	self.root = rootnode
	self.disable = 0
	self.emittedNoHandlerWarning = False
	self.loggerDict = {}
	self.loggerClass = None
	self.logRecordFactory = None
1
2
3
4
5
6
7
8
9
10

可知，Logger.manager 是持有了一个管理器，这个管理器的 rootnode 就是 root 对象。下一步，看一看 manager.getLogger(name)：

def getLogger(self, name):
	"""
	Get a logger with the specified name (channel name), creating it
	if it doesn't yet exist. This name is a dot-separated hierarchical
	name, such as "a", "a.b", "a.b.c" or similar.

	If a PlaceHolder existed for the specified name [i.e. the logger
	didn't exist but a child of it did], replace it with the created
	logger and fix up the parent/child references which pointed to the
	placeholder to now point to the logger.
	"""
	rv = None
	if not isinstance(name, str):
		raise TypeError('A logger name must be a string')
	_acquireLock()
	try:
		if name in self.loggerDict:
			rv = self.loggerDict[name]
			if isinstance(rv, PlaceHolder):
				ph = rv
				rv = (self.loggerClass or _loggerClass)(name)
				rv.manager = self
				self.loggerDict[name] = rv
				self._fixupChildren(ph, rv)
				self._fixupParents(rv)
		else:
			rv = (self.loggerClass or _loggerClass)(name)
			rv.manager = self
			self.loggerDict[name] = rv
			self._fixupParents(rv)
	finally:
		_releaseLock()
	return rv
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
30
31
32
33

manager 对象管理一个 loggerDict，如果字典中包含 name，则返回对应的 Logger 对象，否则创建一个新的 Logger(name) 对象，加入字典，并返回该对象。这符合上面说的工厂模式 “多次使用相同的名字调用 getLogger() 会一直返回相同的 Logger 对象的引用”。其他的：

self._fixupChildren(ph, rv)
self._fixupParents(rv)
1
2

估计就是管理树形层次结构的，我们不深入研究了。

4. Logger 和 Handler 的过滤机制：Level 和 Filter

在流程图中，我们可以看到，无论是蓝色的 Logger 部分，还是橙色的 Handler 部分，都有 Level 和 Filter 这两个过滤机制，先 Level 后 Filter。我们现在只知道日志分 DEBUG、INFO、WARNING、ERORR、CRITICAL 五个等级，logger 对象会根据自身的 self.level 来决定是否输出某个等级的日志：

def info(self, msg, *args, **kwargs):
	"""
	Log 'msg % args' with severity 'INFO'.
	To pass exception information, use the keyword argument exc_info with
	a true value, e.g.
	logger.info("Houston, we have a %s", "interesting problem", exc_info=1)
	"""
	if self.isEnabledFor(INFO):
		self._log(INFO, msg, args, **kwargs)
1
2
3
4
5
6
7
8
9

Level 过滤机制比较简单，都是发送日志之前先检查一下 Level 值大小是否符合要求，不符合就直接终止当前消息了。而 Filter 的过滤机制来源于 Filterer 类，较为复杂一点，这也是 Logger 和 Handler 都继承自 Filterer 的原因。现在还不了解的主要是 Filter，先看一看：

def filter(self, record):  # in logger.handle(record) 函数
	"""
	Determine if a record is loggable by consulting all the filters.

	The default is to allow the record to be logged; any filter can veto
	this and the record is then dropped. Returns a zero value if a record
	is to be dropped, else non-zero.

	.. versionchanged:: 3.2

	Allow filters to be just callables.
	"""
	rv = True
	for f in self.filters:
		if hasattr(f, 'filter'):
			result = f.filter(record)
		else:
			result = f(record)  # assume callable - will raise if not
		if not result:
			rv = False
			break
	return rv
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22

对其持有的 self.filters 执行 f.filter(record) 或 f(record)，返回一个 bool 值，下一步看看这两个函数干了什么。

class Filter(object):
	def __init__(self, name=''):
		"""
		Initialize with the name of the logger which, together with its
		children, will have its events allowed through the filter. If no
		name is specified, allow every event.
		使用记录器的名称进行初始化，记录器及其子记录器将允许其事件通过过滤器。
		如果未指定名称，则允许每个事件。
		"""
		self.name = name
		self.nlen = len(name)

	def filter(self, record):
		"""
		Determine if the specified record is to be logged.

		Returns True if the record should be logged, or False otherwise.
		If deemed appropriate, the record may be modified in-place.
		"""
		if self.nlen == 0:
			return True
		elif self.name == record.name:
			return True
		elif record.name.find(self.name, 0, self.nlen) != 0:  # self.name 不是 record.name 的开头？
			return False
		return (record.name[self.nlen] == ".")
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

查看代码，发现 record.name 就是 self.makeRecord(self.name, ...) 时的 self.name，即，创建 record 的 logger 的 name，这样的话，我们可以得出过滤规则：

• 过滤器的名字为空字符串时，允许任何 record 通过；
• 过滤器的名字不是空字符串时，如果 record.name 和过滤器名字相同，则可通过；
• 如果 record.name 以过滤器名字开头，并紧跟 . 则可通过；

感觉第三条的意思就是 record.name 以 "self.name". 开头，即，创建 record 的 logger 是 “过滤器名字的子记录器”。这符合树形结构的记录器向上传播机制。再看一看过滤器的名字是怎么来的！发现 Logger 和各种 XXHandler 内的父类初始化语句都是 Filterer.__init__(self)，而 Filterer 的初始化默认是：

def __init__(self):
	"""
	Initialize the list of filters to be an empty list.
	"""
	self.filters = []
1
2
3
4
5

空的，即，没有过滤器。哈哈哈！如果我们不手动设置，实际上是没有过滤器的！先不管了，以后用到了再说吧，官方教程也没写怎么用这个东西。

5. emit：格式化与输出流

经历上述一系列的向上传播和过滤之后，handlers 确定可以发送 record 到目的地了，就会调用 emit(record) 函数：

def emit(self, record):
	try:
		msg = self.format(record)
		stream = self.stream
		# issue 35046: merged two stream.writes into one.
		stream.write(msg + self.terminator)
		self.flush()
	except RecursionError:  # See issue 36272
		raise
	except Exception:
		self.handleError(record)
1
2
3
4
5
6
7
8
9
10
11

即，先格式化日志信息，再将信息写入目的流。关于这一块就没什么好说的了，主要关注一些格式化名词，如

"%(asctime)s | %(levelname)s: %(message)s"

中括号内的一些关键名词代表的信息，它们记录在 record 中，由 format 函数进行解析替换。更多关键名词请查看 LogRecord attributes。

6. 配置 basicConfig，logging.config.fileConfig…；

上面基本把流程图的内容讲完了，下面该讲一讲配置方面的内容了。有三种方法配置 logging：

1. 通过 Python 代码手动创建 loggers、handlers 和 formatters；
2. 创建一个 config 文件，并用 fileConfig() 函数加载配置信息；
3. 创建一个包含配置信息的 dictionary，并传递给 dictConfig() 函数。

2, 3 有点相似，如果是从 json 或 yaml 文件中读取字典形式的配置信息，那么 2, 3 基本上就是一样的；不同之处就在于，3 可以用 Python 代码创建 dictionary，但一般还是读取文件。

6.1 basicConfig(...) 配置函数

我所使用的 set_logger 就是 Python 代码配置，先看一看 basicConfig 函数，它主要配置 root，因为它是所有 logger 的父 logger，在默认参数 logger,propagate=True 的情况下，root 要记录所有日志信息，所以它很重要。这个最基本的配置函数代码：

def basicConfig(**kwargs):
	"""
	Do basic configuration for the logging system.

	This function does nothing if the root logger already has handlers
	configured, unless the keyword argument *force* is set to ``True``.
	It is a convenience method intended for use by simple scripts
	to do one-shot configuration of the logging package.

	The default behaviour is to create a StreamHandler which writes to
	sys.stderr, set a formatter using the BASIC_FORMAT format string, and
	add the handler to the root logger.

	A number of optional keyword arguments may be specified, which can alter
	the default behaviour.

	filename  Specifies that a FileHandler be created, using the specified
			  filename, rather than a StreamHandler.
	filemode  Specifies the mode to open the file, if filename is specified
			  (if filemode is unspecified, it defaults to 'a').
	format    Use the specified format string for the handler.
	datefmt   Use the specified date/time format.
	style     If a format string is specified, use this to specify the
			  type of format string (possible values '%', '{', '$', for
			  %-formatting, :meth:`str.format` and :class:`string.Template`
			  - defaults to '%').
	level     Set the root logger level to the specified level.
	stream    Use the specified stream to initialize the StreamHandler. Note
			  that this argument is incompatible with 'filename' - if both
			  are present, 'stream' is ignored.
	handlers  If specified, this should be an iterable of already created
			  handlers, which will be added to the root handler. Any handler
			  in the list which does not have a formatter assigned will be
			  assigned the formatter created in this function.
	force     If this keyword  is specified as true, any existing handlers
			  attached to the root logger are removed and closed, before
			  carrying out the configuration as specified by the other
			  arguments.
	encoding  If specified together with a filename, this encoding is passed to
			  the created FileHandler, causing it to be used when the file is
			  opened.
	errors    If specified together with a filename, this value is passed to the
			  created FileHandler, causing it to be used when the file is
			  opened in text mode. If not specified, the default value is
			  `backslashreplace`.

	Note that you could specify a stream created using open(filename, mode)
	rather than passing the filename and mode in. However, it should be
	remembered that StreamHandler does not close its stream (since it may be
	using sys.stdout or sys.stderr), whereas FileHandler closes its stream
	when the handler is closed.

	.. versionchanged:: 3.2
	   Added the ``style`` parameter.

	.. versionchanged:: 3.3
	   Added the ``handlers`` parameter. A ``ValueError`` is now thrown for
	   incompatible arguments (e.g. ``handlers`` specified together with
	   ``filename``/``filemode``, or ``filename``/``filemode`` specified
	   together with ``stream``, or ``handlers`` specified together with
	   ``stream``.

	.. versionchanged:: 3.8
	   Added the ``force`` parameter.

	.. versionchanged:: 3.9
	   Added the ``encoding`` and ``errors`` parameters.
	"""
	# Add thread safety in case someone mistakenly calls
	# basicConfig() from multiple threads
	_acquireLock()
	try:
		force = kwargs.pop('force', False)
		encoding = kwargs.pop('encoding', None)
		errors = kwargs.pop('errors', 'backslashreplace')
		if force:
			for h in root.handlers[:]:
				root.removeHandler(h)
				h.close()
		if len(root.handlers) == 0:
			handlers = kwargs.pop("handlers", None)
			if handlers is None:
				if "stream" in kwargs and "filename" in kwargs:
					raise ValueError("'stream' and 'filename' should not be "
									 "specified together")
			else:  # 有了 'handlers'，就不能提供 filename 或 stream 了，看来 set_logger 中 console 额外另加是对的
				if "stream" in kwargs or "filename" in kwargs:
					raise ValueError("'stream' or 'filename' should not be "
									 "specified together with 'handlers'")
			if handlers is None:  # 空的时候，才会创建 fileHandler;
				filename = kwargs.pop("filename", None)
				mode = kwargs.pop("filemode", 'a')
				if filename:
					if 'b' in mode:
						errors = None
					h = FileHandler(filename, mode,
									encoding=encoding, errors=errors)
				else:  # 没有 filename 就创建默认的 StreamHandler
					stream = kwargs.pop("stream", None)
					h = StreamHandler(stream)
				handlers = [h]
			dfs = kwargs.pop("datefmt", None)
			style = kwargs.pop("style", '%')
			if style not in _STYLES:
				raise ValueError('Style must be one of: %s' % ','.join(
					_STYLES.keys()))
			fs = kwargs.pop("format", _STYLES[style][1])
			fmt = Formatter(fs, dfs, style)
			for h in handlers:
				if h.formatter is None:
					h.setFormatter(fmt)
				root.addHandler(h)
			level = kwargs.pop("level", None)
			if level is not None:
				root.setLevel(level)
			if kwargs:
				keys = ', '.join(kwargs.keys())
				raise ValueError('Unrecognised argument(s): %s' % keys)
	finally:
		_releaseLock()
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
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120

看起来比较复杂，我还是用流程图把它表示出来吧：

图5：basicConfig

需要注意的几点：

• logging.info(msg) 等函数实际上是在调用 root.info(msg)，但在这之前，若root.handlers 为空，则会执行 basicConfig()；
• 调用 basicConfig(...) 时，若root.handlers 不为空，则函数不会执行任何动作，除非参数 force=True，这样会清空 root.handlers ；所以，如果不设置 force=False，那么该函数就是一次性的（只运行一次）；
• root 是 logging 包内置好的 logger，这个函数主要是给 root 配置 handlers、level 等信息；在配置 handlers 时， 有两种方式：(1) 直接提供配置好的 handlers；(2) 提供文件名或 Stream 流；它们互斥；
• (1) 像 set_logger() 中的 console = logging.StreamHandler() ... 一样，创建、配置 handler，就可以以参数的形式传递给 basicConfig 函数；但是，提供了 handlers，就不能再提供 filename 或 stream 了；
• (2) basicConfig 函数是可以直接接收 filename 或 stream 参数的，但二选一，不能同时提供，而且只能提供一个；然后该函数会根据 filename 或 stream 创建 handler；注意只有一个，这就是为什么在提供了 filename 之后，又在函数外创建添加 console = logging.StreamHandler() ...，而不是一起放在函数参数表内；
• 在经历了 (1) 或 (2) 之后，函数就会根据参数所提供的 formatter 信息给还未配置 formatter 的 handlers 配置 formatter；如果已经配置了，则会跳过。

这么来看，其实像下面这段代码一样配置 logging，或许更能让人明白咋回事：

def use_basic_onfig():
	console_handler = logging.StreamHandler()
	console_handler.setLevel(logging.INFO)  # handler 的 Level
	console_handler.setFormatter(logging.Formatter('%(asctime)s |c %(levelname)s:  %(message)s'))  # c
	file_handler = logging.FileHandler(
		filename=path.join('./results', 'train.log'),
		mode='w',
		encoding='UTF-8'
	)
	file_handler.setLevel(logging.WARNING)
	file_handler.setFormatter(logging.Formatter('%(asctime)s |f %(levelname)s:  %(message)s'))  # f

	logging.basicConfig(
		format='%(asctime)s | %(levelname)s:  %(message)s',  # 这是给哪些没安排 formatter 的 handler 准备的
		datefmt='%Y-%m-%d %H:%M:%S',
		level=logging.INFO,  # root logger 的 Level
		handlers=[console_handler, file_handler]
	)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18

当然，也可以通过 logger = logging.getLogger(name) 创建所需的 logger，然后的配置就是 setLevel、addHandler() 之类的配置函数。下面是官方教程给出的示例：

import logging
# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

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

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

6.2 通过文件配置：logging.config.fileConfig(...)

先摆上官方给出的例子：

import logging
import logging.config

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

# create logger; 这里确切说应该是取出 logger 吧，我觉得上面的函数已经创建了
logger = logging.getLogger('simpleExample')

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')
1
2
3
4
5
6
7
8
9
10
11
12
13
14

加载配置文件很简单，主要看一看 logging.conf 文件的内容：

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

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

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

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
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

从大致内容上来看，这和上面的例子是一样的。下面我们仔细看看到底是怎么配置的：

• 首先是头三行，是 [loggers], [handlers], [formatters]，后面跟着 keys=...，这可以理解为编程语言变量声明，总共四个对象：root, simpleExample, consoleHandler, simpleFormatter；
• 然后就是这四个对象的配置内容，以 [对象类型_对象名] 开头，基本就是属性键值对的配置方式。

有两个需要注意的地方：

1. propagate=0 在 Python 里是 bool 类型，而这里是 0，大概是 False 的意思吧，猜想设置为 1 就是 True；
2. args=(sys.stdout,)，从 Stream 的构造函数 def __init__(self, stream=None): 中可以看到，它只有一个参数，args=(sys.stdout,) 很可能就是传递参数的。

果不其然，因为配置文件中两个 logger 都设置为 level=DEBUG，所以所有信息都能输出的，但实际得到的是：

2023-11-21 23:05:32,712 - simpleExample - DEBUG - debug message
2023-11-21 23:05:32,712 - simpleExample - INFO - info message
2023-11-21 23:05:32,712 - simpleExample - WARNING - warn message
2023-11-21 23:05:32,712 - simpleExample - ERROR - error message
2023-11-21 23:05:32,712 - simpleExample - CRITICAL - critical message
1
2
3
4
5

只有 simpleExample 的信息输出了，root 没有，即并没有向父 logger 传递。如果设置 propagate=1，则输出为：

2023-11-21 23:08:57,691 - simpleExample - DEBUG - debug message
2023-11-21 23:08:57,691 - simpleExample - DEBUG - debug message
2023-11-21 23:08:57,691 - simpleExample - INFO - info message
2023-11-21 23:08:57,691 - simpleExample - INFO - info message
2023-11-21 23:08:57,691 - simpleExample - WARNING - warn message
2023-11-21 23:08:57,691 - simpleExample - WARNING - warn message
2023-11-21 23:08:57,691 - simpleExample - ERROR - error message
2023-11-21 23:08:57,691 - simpleExample - ERROR - error message
2023-11-21 23:08:57,692 - simpleExample - CRITICAL - critical message
2023-11-21 23:08:57,692 - simpleExample - CRITICAL - critical message
1
2
3
4
5
6
7
8
9
10

双倍的输出。(⊙o⊙)？全部是 simpleExample，看来 %(name)s 指的是产生这条 record 的 logger.name，也许它本身就存于 record 中。

学以致用，那我现在用这种 logging.config.fileConfig 的方式创建我之前 set_logger 使用的配置：

[loggers]
keys=root

[handlers]
keys=fileHandler,consoleHandler

[formatters]
keys=fileFormatter,consoleFormatter

[logger_root]
level=DEBUG
handlers=fileHandler,consoleHandler

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=fileFormatter
args=('./results/train.log', 'w', 'UTF-8')

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

[formatter_fileFormatter]
format=%(asctime)s |f %(levelname)s:  %(message)s

[formatter_consoleFormatter]
format=%(asctime)s |c %(levelname)s:  %(message)s
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
30

得到了想要的效果：控制台有消息，文件中也有同样的消息(除了 ‘f’ 和 ‘c’)。args=('./results/train.log', 'w', 'UTF-8') 也证实了其参数传递的作用。只是还不知 mode='w' 这样的键值传递方式咋弄，试了字典式，不管用。

6.3 logging.config.dictConfig(...)

官方建议使用 YAML 格式的文件提供 dict：

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:
	simpleExample:
		level: DEBUG
		handlers: [console]
		propagate: no
root:
	level: DEBUG
	handlers: [console]
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18

不过没有提供示例，那就自己试试：

with open('./configs/logging.yaml') as yaml_file:
	config_dict = yaml.load(yaml_file, Loader=yaml.FullLoader)
cfg.dictConfig(config_dict)
1
2
3

学以致用，那我现在用这种 logging.config.dictConfig 的方式创建我之前 set_logger 使用的配置：

version: 1
formatters:
	fileFormatter:
		format: '%(asctime)s f %(name)s - %(levelname)s - %(message)s'
	consoleFormatter:
		format: '%(asctime)s c %(name)s - %(levelname)s - %(message)s'
handlers:
	fileHandler:
		class: logging.FileHandler
		level: DEBUG
		formatter: fileFormatter
		filename: ./results/train.log
		mode: w
		encoding: UTF-8
	consoleHandler:
		class: logging.StreamHandler
		level: DEBUG
		formatter: consoleFormatter
		stream: ext://sys.stdout
loggers:
	root:
		level: DEBUG
		handlers: [fileHandler, consoleHandler]
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

得到了想要的效果：控制台有消息，文件中也有同样的消息(除了 ‘f’ 和 ‘c’)。与 fileConfig 不同的是，FileHandler 的参数不再是 args=(‘./results/train.log’, ‘w’, ‘UTF-8’)，而是直接使用与 class: logging.FileHandler 同级的键值对传递参数。这比 fileConfig 好使多了。但是，比较奇怪的是：这些参数虽然都是字符串类型的，但不能写引号，写的话会出错，而 format: '%(asctime)s f %(name)s - %(levelname)s - %(message)s' 是带引号的，可能它并不是传给 Formatter 类的参数。也许是咱对 YAML 文件了解不够。但它看起来真的好简洁，尤其相比一下 Python 代码中的字典，下面是 GPT3.5 给出的例子：

# 定义日志配置字典
log_config = {
	'version': 1,
	'handlers': {
		'file_handler': {
			'class': 'logging.FileHandler',
			'filename': 'app.log',
			'level': 'DEBUG',
			'formatter': 'my_formatter'
		},
	},
	'formatters': {
		'my_formatter': {
			'format': '%(asctime)s - %(levelname)s - %(message)s'
		}
	},
	'root': {
		'level': 'DEBUG',
		'handlers': ['file_handler']
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

立见高下。

7. 多模块下 logging 的使用

多模块情况下使用 logging，我窃以为官方所建议的 logging.getLogger(__name__) 作用如下：

• loggers 的树形结构与模块结构完全一致，每个模块使用自己的 logger 记录日志，并向上层逐渐传播，直到 root logger。如此一来，结果就是：每个模块有自己的日志，root logger 记录全局，对于中间的包，如果它的 __init__.py 中有 logger 的话，会记录自身的日志以及其下层的 logger 日志；
• 那如果包的 __init__.py 中没有 logger 呢？这就要看一看 PlaceHolder 了，它只是一个占位符，其下层的 loggers 会直接跳过它(可能会跳过多个)，直接以更上级的 logger 为 parent，直到 root logger。【这个可以通过查看 logging.Manager 中的 _fixupParents(self, alogger) 和 _fixupChildren(self, ph, alogger) 两个函数得知树形结构的管理模式】

这对大型项目来说确实有用，当程序足够大时，要记录的日志太多，每个模块有自己的日志是很有必要的。你可以想象：当你想查看数据库的读取日志时，如果去 root logger 密密麻麻的各种记录中寻找你想要的日志，该是何等的痛苦。

不过对于科研人员来说，大多数情况下程序结构很简单，就好比我习惯的程序结构：

• configure.py：配置一些参数，比如 learning_rate、batch_size、num_epoch 等等；
• dataset.py：读取并处理数据，以模型最终所需要的数据格式为模型提供数据；
• utils.py：放一些工具类函数；
• models.py：模型构建；
• traintest.py：融合数据和模型，编写训练、测试和模型选择与保存等操作；
• main.py：运行程序；

满共 6 个模块，还有仨是及其简单的，主要记录的就是 dataset.py、models.py 和 traintest.py 三个模块而已，即使只使用 root 一个 logger，也无伤大雅。所以，我扯这一大篇的博文，其实没啥卵用！

不过既然都到这一步了，我还是以一个 toy example 结束此文吧：Python logging 日志的模块化使用示例。