logger_problems

logger 的一些问题

logging 基础知识

​ 在需要调试复杂情况的时候，我们都会使用 logging 而不是 print，一般来说配置日志文件有两种方式，全局的 logger 或者局部的 logger，全局的 logger 可以这样配置：

1
2
3
4
5
6
7
8
9
10
import logging

# level 用语过滤 INFO 严重级别以下的信息，默认值是 warning
logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

logging.debug('debug msg')
logging.info("info msg")
logging.warning('warning msg')
logging.error('error msg')
logging.error('critical msg')

实际上这种方法虽然没有显示配置 logger，但是其实是默认配置了 logger.root

​ logger 的配置方式一般为：

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

logger = logging.getLogger('my_logger')
logger.setLevel(logging.DEBUG)  # 设置logger级别

# 创建handler
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# 创建formatter并添加到handler
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
logger.addHandler(ch)
logger.debug('This is a debug message from my_logger')
  • logging 可决定输出到什么地方，以及输出格式。有许多的重要性别级可供选择，debug、info、warning、error 以及 critical。通过赋予 logger 或者 handler 不同的级别，你就可以只输出错误消息到特定的记录文件中，或者在调试时只记录调试信息
  • 创建 logger 的过程中，getLogger 函数返回的 logger 只与日志名称有关，输入相同的名称会返回同一个实例（如果是全局的 logging，那么 logger 的名字就是 root）
  • FileHandler 配置的参数和 logging.basicConfig 对应，他们可以配置几乎完全相同的参数，例如输出格式，输出等级（配置输出格式使用 setFormatter 方法）
    • logger 可配置的参数只有 level，其他的参数全部是属于 Handeler 配置
  • 同一个 logger 可以加入多个 Handler，同一个Handler 也可以给多个 logger（这一点和 Java 相同）

logging msg 输出格式中可以配置的参数有：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
'%(name)s'          # Logger的名字
'%(levelno)s'       # 数字形式的日志级别
'%(levelname)s'     # 文本形式的日志级别（如 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'）
'%(pathname)s'      # 完整路径名，可能包括文件名
'%(filename)s'      # 文件名（从pathname中提取）
'%(module)s'        # 模块名（从filename中提取，不带扩展名）
'%(lineno)d'        # 代码行号
'%(funcName)s'      # 函数或方法名
'%(created)f'       # 当前时间（自纪元以来的秒数，浮点数）
'%(asctime)s'       # 字符串形式的时间，格式可以由你指定，默认为 '%Y-%m-%d %H:%M:%S,%f'
'%(msecs)d'         # 毫秒部分
'%(thread)d'        # 线程ID
'%(threadName)s'    # 线程名称
'%(process)d'       # 进程ID
'%(message)s'       # 用户记录的消息

暗箱操作导致多重日志

​ logging 的暗箱操作：logger 在没有 handler 的情况下，其本身是不具备输出消息能力的。但是为什么上面全局 logger 的例子中 logging.warning(msg) 能够在不配置 handler 的情况下，输出日志呢？这其实是 logging 模块的保护机制，对于 warning 和 error 级别的消息，如果消息的日志等级大于 logger 的日志等级，且 logger 没有配置任何的 handler，则会调用 logging 模块内置的 streamHandler 来输出信息

坑爹的 logging.warning

​ 当我们开心地调用 logging.warning 时，我们以为只是输出了一条日志，实际上可能给 logging.root 偷偷配置了 streamHandler

1
2
3
logging.warnign('learn logging') 
print(logging.root.handlers) 
# [<StreamHandler <stderr> (NOTSET)>]

​ 如果单纯的以为就多了个 streamHandler 就错了。他会引起多重日志的问题。为什么使用 pytorch 1.10 突然出现了多重日志？追根溯源，是因为 pytorch 1.10 的 DistributedDataParallel 模块在 forward 过程中调用了 logging.info ，进而 logging.root 多出了一个 streamHandler，如果这个调用发生在 logging.getLogger 之后，就会导致多重日志的发生

  • 为了避免多重日志的发生，我们最好配置输出的 formatter，让 logger 输出的日志自带 logger 名，这样就知道每条日志信息是哪一个 logger 产生，就很好调试了

万恶的logging.root

​ 众所可能不周知， logging 库为了简化配置 logger 的流程，允许我们通过派生“子实例”来获取日志格式和父实例一样的 logger。所有通过 logging.getLogger 方法创建的实例，都拥有共同的祖先：logging.root

1
2
3
4
5
6
7
8
9
10
11
>>> logger = logging.getLogger('roommate') 
>>> logger = logger.getChild('roommate') 
>>> logger = logger.getChild('roommate') 
>>> logger = logger.getChild('roommate') 
>>> while logger.parent: 
>>>     print(logger.parent.name) 
>>>     logger = logger.parent 
roommate.roommate.roommate 
roommate.roommate 
roommate 
root

​ 子实例会继承父实例的属性，但是我们前面提到了 logger 的可配置参数只有 level，这个东西继承并不会带来多重日志的问题，但是 logger 还有通过 propagate 属性继承（严格来说这不算继承） Handler 的机制，当 propagate 为 True 时，子实例会向上搜索并调用父实例的 Handler 从而触发多重打印。我们只需要另 propagate 为 False，能走出万恶的继承循环了

​ 我们举一个错误的代码例子：

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


format_str = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
logging.basicConfig(level=logging.DEBUG, format=format_str)
logging.error("error msg from root logger")


child_logger = logging.getLogger("child")
# 为子记录器配置一个自己的处理器（这将导致双重日志）
ch_child = logging.StreamHandler()
ch_child.setLevel(logging.DEBUG)
formatter = logging.Formatter(format_str)
ch_child.setFormatter(formatter)

child_logger.addHandler(ch_child)
child_logger.error("error msg from child logger")

# >>>
# 2024-12-27 14:55:20,288 - root - ERROR - error msg from root logger
# 2024-12-27 14:55:20,288 - child - ERROR - error msg from child logger
# 2024-12-27 14:55:20,288 - child - ERROR - error msg from child logger

​ 这样的错误代码在同一个文件内可能哈哈还会因为两种使用方式不同而发现，但如果是导入包的时候出现了这个问题那 debug 的难度是要上天了

​ 代码的修改也很简单，将 child_logger 的 propagate 属性设置成 False 就行了：

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


format_str = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
logging.basicConfig(level=logging.DEBUG, format=format_str)
logging.error("error msg from root logger")


child_logger = logging.getLogger("child")
child_logger.propagate = False  # Set propagate=False for child logger
ch_child = logging.StreamHandler()
ch_child.setLevel(logging.DEBUG)
formatter = logging.Formatter(format_str)
ch_child.setFormatter(formatter)

child_logger.addHandler(ch_child)
child_logger.error("error msg from child logger")

# >>>
# 2024-12-27 15:05:59,857 - root - ERROR - error msg from root logger
# 2024-12-27 15:05:59,861 - child - ERROR - error msg from child logger

loguru：更简单的日志写法

​ loguru 是一个 Python 的记录日志的第三方库，旨在简化和改进应用程序的日志记录过程。loguru 试图通过提供有用的功能来解决标准库 logging 中的一些痛点，例如更简单的 API、自动处理日志文件的轮转、压缩等（但是这个库发现记录信息有点慢了）

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
from loguru import logger

# 移除默认的控制台处理器
logger.remove()
# 添加一个新的处理器，将日志写入 'log.txt' 文件中
# level='DEBUG' 设置最低日志级别为 DEBUG
logger.add("log.txt", level="DEBUG")

# 记录一些不同级别的日志消息
logger.debug("debug msg")
logger.info("info msg")
logger.warning("warning msg")
logger.error("error msg")
# >>>
# 2024-12-27 15:20:29.546 | DEBUG    | __main__:<module>:33 - debug msg
# 2024-12-27 15:20:29.546 | INFO     | __main__:<module>:34 - info msg
# 2024-12-27 15:20:29.546 | WARNING  | __main__:<module>:35 - warning msg
# 2024-12-27 15:20:29.546 | ERROR    | __main__:<module>:36 - error msg