Python solves a problem encountered in the use of logging function

Phenomena:

The production center copied 300 tasks under the task, and found that the task was no longer scheduled after 1 array of time. Looking at the background log, it was found that the log output stopped at a certain point in time.

Analysis:

1. First, confirm that the process exists and there is no dead.

2, and then use strace p to see the process under 1, found that the process stuck in futex call above, should be in the lock operation above the problem.

3. Use gdb attach to process ID, and use py-bt to check the stack under 1. It is found that the information of the stack is roughly: sig_handler (a certain signal processing function)- > auroralogger (custom logging function)- > logging (logging module of python)- > threading. acquire (get lock). From the bt information of gdb, the above conjecture is basically verified, and deadlock should appear.

4. The logging module of Python itself will definitely not have deadlock. The possible problem with this bug is our usage. Looking at doc of logging module in python, we found that there is a chapter with one Thread Safety. The content is very simple, but it also explains the problem I encountered under one. The content is as follows:

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.

Part 1 says that logging is thread safe, and the common data is locked through lock of threading.

Part 2 specifically mentioned that the logging module cannot be used in asynchronous signal processing functions, because the lock mechanism of threading does not support reentry.

This explains the deadlock problem I encountered above, because I called the non-reentrant logging module in the signal processing function.

Thread-safe and reentrant:

From the above logging module, we can see that thread safety and reentrancy are not equivalent, so what is the connection and difference between these two concepts?

1. Reentrant function: Literally, this function can be called repeatedly, and the out-of-order execution or even interleaving execution of the function by multiple threads can ensure that the output of the function and the output of the function being executed once alone are 1. That is to say, the output of the function only depends on the input.

Thread-safe functions: Functions can be called by multiple threads and are guaranteed not to refer to incorrect or dirty data. Thread-safe function output depends not only on the input but also on the order in which it is called.

2. One of the biggest differences between reentrant functions and thread-safe functions is whether they are asynchronous signal-safe. Reentrant functions can be safely called in asynchronous signal handlers, while thread-safe functions are not guaranteed to be safely called in asynchronous signal handlers.

The loggin module we encountered above is non-asynchronous signal safe, In the main thread, we are using log function and log function calls threading. lock to obtain the lock. At this time, an asynchronous signal generator jumps to the signal processing function, and the signal processing function just calls log function, because the first called log function has not released the lock, and finally a deadlock is formed.

1. Reentrant functions must be thread-safe functions and asynchronous signal-safe functions, while thread-safe functions are not reentrant functions.

Summary:

Asynchronous signal processing function 1 must be as simple as possible and can not call non-reentrant functions.

The Python loggin module is thread safe but non-reentrant.

Supplement: Python-logging Module Use Tutorial

Simple usage

Log level

级别	何时使用
DEBUG	细节信息，仅当诊断问题时适用。
INFO	确认程序按预期运行
WARNING	表明有已经或即将发生的意外（例如：磁盘空间不足）。程序仍按预期进行
ERROR	由于严重的问题，程序的某些功能已经不能正常执行
CRITICAL	严重的错误，表明程序已不能继续执行

Console output log

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

Save the log to a file and set the time and output format

import logging
#  Save the file as example.log The record level is DEBUG That is, only records DENBUG Log and above 
#  The output format is  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')

Parameter interpretation

filename Log file path

filemode Record log file mode, w for each start-up program to create a new file record, a means append to the end of the file, the default is a

level Log level

format Format of log output

datefmt Format of log output time

Configuring Log with Profile

[loggers]
#  Configuration Log Object Name ,  Default to root
keys=root, poj
[handlers]
#  Log configuration name object name 
keys=writeFileHandlers
[formatters]
#  Log Output Format Object Name 
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]
#  Settings writeFileHandlers Configuration of object 
class=FileHandler
level=DEBUG
formatter=writeFileFormatters
#  Record in a file as an append 
args=("demo.log", "a")
[formatter_writeFileFormatters]
 Settings writeFileHandlers Output configuration of object 
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=%Y-%d-%m %H:%M:%S

Using configuration files

import logging.config
#  Load configuration file 
logging.config.fileConfig('logging.conf')
#  Gets the log object named poj Adj. 
logger = logging.getLogger("poj")
logger.debug('This message should go to the log file')
logger.info('So shoul this')
logger.warning('And this, too')