When an user, use logging, to try to display an object that uses some threading locks, there could be a race condition and the logging module will deadlock. So, any thread that will try to use logging, will then be stuck forever.
Please see the following test case that is a simplification of a case that I have encountered. I'm able to reproduce the issue on python 3.4.3, and python 2.7.9. But, based on the code, I think that all versions are affected.
Basically, I try to log a variable that is like a property or the __unicode__ function of an object. But this value will not be calculated before entering the "logging.warning" code but in the "self.format" of the logging handler. This self.format is called under the umbrella of the big lock of "logging".
So, if function to get my variable value involve taking another lock and then performing a logging call. There is great chances that another thread also took the variable lock between the time that I took the logging lock and before it take the variable lock.
So, the first thread will wait for the variable lock but will have the logging lock.
But the other thread will have the variable lock but will wait the logging lock.
Traceback of the current situation:
# ThreadID: 140410437482240
File: "/usr/lib/python2.7/threading.py", line 783, in __bootstrap
self.__bootstrap_inner()
File: "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
self.run()
File: "/usr/lib/python2.7/threading.py", line 763, in run
self.__target(*self.__args, **self.__kwargs)
File: "testcase-bug-python-deadlock-logging.py", line 37, in second_thread
my_db.log_pid()
File: "testcase-bug-python-deadlock-logging.py", line 24, in log_pid
logging.warning(u"my_db pid is: %s", u"1234")
File: "/usr/lib/python2.7/logging/__init__.py", line 1604, in warning
root.warning(msg, *args, **kwargs)
File: "/usr/lib/python2.7/logging/__init__.py", line 1164, in warning
self._log(WARNING, msg, args, **kwargs)
File: "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
self.handle(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
self.callHandlers(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
hdlr.handle(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 747, in handle
self.acquire()
File: "/usr/lib/python2.7/logging/__init__.py", line 698, in acquire
self.lock.acquire()
File: "/usr/lib/python2.7/threading.py", line 173, in acquire
rc = self.__block.acquire(blocking)
# ThreadID: 140410445874944
File: "/usr/lib/python2.7/threading.py", line 783, in __bootstrap
self.__bootstrap_inner()
File: "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
self.run()
File: "/usr/lib/python2.7/threading.py", line 763, in run
self.__target(*self.__args, **self.__kwargs)
File: "testcase-bug-python-deadlock-logging.py", line 31, in first_thread
logging.warning(u"My slow pid is: %s", my_db)
File: "/usr/lib/python2.7/logging/__init__.py", line 1604, in warning
root.warning(msg, *args, **kwargs)
File: "/usr/lib/python2.7/logging/__init__.py", line 1164, in warning
self._log(WARNING, msg, args, **kwargs)
File: "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
self.handle(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
self.callHandlers(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
hdlr.handle(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 749, in handle
self.emit(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 851, in emit
msg = self.format(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 724, in format
return fmt.format(record)
File: "/usr/lib/python2.7/logging/__init__.py", line 464, in format
record.message = record.getMessage()
File: "/usr/lib/python2.7/logging/__init__.py", line 328, in getMessage
msg = msg % self.args
File: "testcase-bug-python-deadlock-logging.py", line 17, in __unicode__
with db_lock:
File: "/usr/lib/python2.7/threading.py", line 173, in acquire
rc = self.__block.acquire(blocking) |