Python logging模块在信号处理函数中导致死锁的原因与解决方案

现象：

在生产中心执行大规模拷机任务时，同时下发300个任务。一段时间后，发现任务调度停止，检查后台日志发现输出停滞在特定时间点。

分析：

1、首先确认相关进程依然存在，并未处于dead状态。

2、使用strace -p命令跟踪进程，发现进程阻塞在futex系统调用上，推测问题出在锁操作环节。

3、通过gdb attach到进程ID，并使用py-bt查看堆栈信息。结果显示调用链为：sig_handler（信号处理函数）-> auroralogger（自定义日志函数）-> logging（Python标准logging模块）-> threading.acquire（获取锁）。gdb的backtrace信息验证了上述猜想，即发生了死锁。

4、Python的logging模块本身不太可能存在死锁bug，问题更可能出在使用方式上。查阅Python官方文档中关于Thread Safety的部分，其简短说明直接解释了该问题，内容如下：

The logging module is intended to be thread-safe without any special work needing to be done by its clients. It achieves this though using threading locks; there is one lock to serialize access to the module's shared data, and each handler also creates a lock to serialize access to its underlying I/O.

If you are implementing asynchronous signal handlers using the signal module, you may not be able to use logging from within such handlers. This is because lock implementations in the threading module are not always re-entrant, and so cannot be invoked from such signal handlers.

文档第一部分指出，logging模块旨在实现线程安全，无需客户端额外处理。它通过threading锁机制对共享数据加锁来实现这一目标，每个handler也会创建独立的锁来序列化底层I/O操作。

文档第二部分特别强调，在使用signal模块实现异步信号处理函数时，可能无法在信号处理函数内部使用logging模块。这是因为threading模块中的锁实现并非总是可重入的（re-entrant），因此不能从信号处理函数中调用。

这解释了前文遇到的死锁问题：因为在信号处理函数中调用了不可重入的logging模块，导致了锁无法释放。

线程安全和可重入：

从上述logging模块的行为来看，线程安全和可重入并非等价概念。那么这两个概念之间有何联系和区别？

1、可重入函数：从字面理解，该函数可以被重复调用。即使被多个线程乱序执行甚至交错执行，也能保证输出结果与单独执行一次时一致。也就是说，函数的输出仅取决于输入。

线程安全函数：该函数可以被多个线程调用，并保证不会引用到错误或不一致的数据。线程安全函数的输出不仅依赖于输入，还可能依赖于调用时的执行顺序。

2、可重入函数与线程安全函数的最大差异在于：是否具备异步信号安全性。可重入函数可以在异步信号处理函数中安全调用，而线程安全函数并不保证能在异步信号处理函数中安全调用。

前文遇到的logging模块即属于非异步信号安全的情况。在主线程中，log函数调用threading.lock获取了锁，此时产生了一个异步信号，程序跳转到信号处理函数。若信号处理函数恰好再次调用log函数，由于前一个log函数尚未释放锁，最终形成死锁。

1、可重入函数必然是线程安全函数和异步信号安全函数；但线程安全函数不一定是可重入函数。

总结：

在异步信号处理函数中，应尽量保持功能简单，且严禁调用不可重入的函数。

Python的logging模块是线程安全的，但它是不可重入的。

补充：Python—logging模块使用教程

简单用法

日志等级

控制台输出日志

import logging
logging.warning('Watch out!')  
logging.info('I told you so') 

将日志保存到文件并且设置时间和输出格式

import logging
# 保存文件为example.log，记录等级为DEBUG，即只记录DENBUG及以上的日志
# 输出格式为 2019-19-06 18:47:06 - WARNING - And this, too
logging.basicConfig(
  filename='example.log',
  filemode='w',
  level=logging.DEBUG,
  format='%(asctime)s - %(levelname)s - %(message)s',
  datefmt='%Y-%d-%d %H:%M:%S'
)
logging.debug('This message should go to the log file')
logging.info('So shoul this')
logging.warning('And this, too')

参数解释

filename日志文件路径

filemode记录日志文件的模式，w为每次启动程序都创建一个全新的文件记录, a表示追加到文件末尾, 默认为a

level记录日志的等级

format日志输出的格式

datefmt日志输出时间的格式

使用配置文件配置日志

[loggers]
# 配置日志对象名, 默认为root
keys=root, poj
[handlers]
# 日志配置名对象名
keys=writeFileHandlers
[formatters]
# 日志输出格式对象名
keys=writeFileFormatters
[logger_root]
level=DEBUG
handlers=writeFileHandlers
[logger_poj]
level=DEBUG
handlers=writeFileHandlers
qualname=writeFileFormatters
propagate=0
[logger_leetcode]
level=DEBUG
handlers=writeFileHandlers
qualname=writeFileFormatters
propagate=0
[handler_writeFileHandlers]
# 设置writeFileHandlers对象的配置
class=FileHandler
level=DEBUG
formatter=writeFileFormatters
# 记录在文件中，以追加的形式
args=("demo.log", "a")
[formatter_writeFileFormatters]
设置writeFileHandlers对象的输出配置
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=%Y-%d-%m %H:%M:%S

使用配置文件

import logging.config
# 加载配置文件
logging.config.fileConfig('logging.conf')
# 获取日志对象名为poj的
logger = logging.getLogger("poj")
logger.debug('This message should go to the log file')
logger.info('So shoul this')
logger.warning('And this, too')

以上为个人经验，希望能给大家一个参考，也希望大家多多支持本站。如有错误或未考虑完全的地方，望不吝赐教。