Message339458
Below is a backtrace from the deadlock.
It happens because the logging code is trying to acquire two per-logger locks; and in an order different to the random order used by the fork() handler.
The code in question has a custom class DebugHandler(logging.Handler). The default logging.Handler.handle() method grabs its lock and calls .emit() vis:
if rv:
self.acquire()
try:
self.emit(record)
finally:
self.release()
the custom .emit() then sends the record to a sub-logger stream vis:
def emit(self, record):
for stream_handler in self.stream_handlers:
stream_handler.emit(record)
if _DEBUG_STREAM:
_DEBUG_STREAM.emit(record)
and one of these emit() functions calls flush() which tries to acquire a further lock.
Thread 0x00007f976b7fe700 (most recent call first):
File "/usr/lib64/python3.7/logging/__init__.py", line 854 in acquire
File "/usr/lib64/python3.7/logging/__init__.py", line 1015 in flush
def flush(self):
"""
Flushes the stream.
"""
self.acquire() <----
try:
if self.stream and hasattr(self.stream, "flush"):
self.stream.flush()
finally:
self.release()
File "/usr/lib64/python3.7/logging/__init__.py", line 1038 in emit
self.flush() <----
File "/home/build/libreswan-web/master/testing/utils/fab/logutil.py", line 163 in emit
def emit(self, record):
for stream_handler in self.stream_handlers:
stream_handler.emit(record) <---
if _DEBUG_STREAM:
_DEBUG_STREAM.emit(record)
File "/usr/lib64/python3.7/logging/__init__.py", line 905 in handle
def handle(self, record):
"""
Conditionally emit the specified logging record.
Emission depends on filters which may have been added to the handler.
Wrap the actual emission of the record with acquisition/release of
the I/O thread lock. Returns whether the filter passed the record for
emission.
"""
rv = self.filter(record)
if rv:
self.acquire()
try:
self.emit(record) <---
finally:
self.release()
return rv
File "/usr/lib64/python3.7/logging/__init__.py", line 1591 in callHandlers
hdlr.handle(record)
File "/usr/lib64/python3.7/logging/__init__.py", line 1529 in handle
self.callHandlers(record)
File "/usr/lib64/python3.7/logging/__init__.py", line 1519 in _log
self.handle(record)
File "/usr/lib64/python3.7/logging/__init__.py", line 1449 in log
self._log(level, msg, args, **kwargs)
File "/usr/lib64/python3.7/logging/__init__.py", line 1768 in log
self.logger.log(level, msg, *args, **kwargs)
File "/usr/lib64/python3.7/logging/__init__.py", line 1724 in debug
self.log(DEBUG, msg, *args, **kwargs)
File "/home/build/libreswan-web/master/testing/utils/fab/shell.py", line 110 in write
self.logger.debug(self.message, ascii(text)) |
|
Date |
User |
Action |
Args |
2019-04-04 17:35:46 | cagney | set | recipients:
+ cagney, gregory.p.smith, vinay.sajip, jcea, nirs, pitrou, vstinner, nirai, forest_atq, ionelmc, bobbyi, neologix, Giovanni.Bajo, sdaoden, tshepang, sbt, lesha, emptysquare, dan.oreilly, davin, Connor.Wolf, Winterflower, Birne94, ochedru |
2019-04-04 17:35:46 | cagney | set | messageid: <1554399346.05.0.115658735961.issue6721@roundup.psfhosted.org> |
2019-04-04 17:35:46 | cagney | link | issue6721 messages |
2019-04-04 17:35:45 | cagney | create | |
|