Python 解决logging功能使用过程中遇到的一个问题

现象：

生产中心进行拷机任务下了300个任务，过了一阵时间后发现任务不再被调度起来，查看后台日志发现日志输出停在某个时间点。

分析：

1、首先确认进程存在并没有dead。

2、然后用strace –p看了一下进程，发现进程卡在futex调用上面，应该是在锁操作上面出问题了。

3、用gdb attach进程ID，用py-bt查看一下堆栈，发现堆栈的信息大致为：sig_handler(某个信号处理函数)->auroralogger(自定义的日志函数)->logging(python的logging模块)->threading.acquire(获取锁)。从gdb的bt信息基本验证了上面的猜想，应该是出现了死锁。

4、Python的logging模块本身肯定不会有死锁的这种bug有可能出问题的就是我们的使用方式，看python中logging模块的doc，发现有一个有一个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的lock对公用的数据进行了加锁。

第二部分特意提到了在异步的信号处理函数中不能使用logging模块，因为threading的lock机制是不支持重入的。

这样就解释了上面我遇到的死锁问题，因为我在信号处理函数中调用了不可以重入的logging模块。

线程安全和可重入：

从上面的logging模块来看线程安全和可重入不是等价的，那么这两个概念之间有什么联系、区别呢？

1、可重入函数：从字面意思来理解就是这个函数可以重复调用，函数被多个线程乱序执行甚至交错执行都能保证函数的输出和函数单独被执行一次的输出一致。也就是说函数的输出只决定于输入。

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

2、可重入函数和线程安全函数之间有一个最大的差异是：是否是异步信号安全。可重入函数在异步信号处理函数中可以被安全调用，而线程安全函数不保证可以在异步信号处理函数中被安全调用。

上面我们遇到的loggin模块就是非异步信号安全的，在主线程中我们正在使用log函数而log函数调用了threading.lock来获取到了锁，此时一个异步信号产生程序跳转到信号处理函数中，信号处理函数又正好调用了log函数，因为前一个被调用的log函数还未释放锁，最后就形成了一个死锁。

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

总结：

异步信号处理函数中一定要尽可能的功能简单并且不能调用不可重入的函数。

Python loggin模块是线程安全但是是不可重入的。

补充：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')

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