New submission from Florent Viard: 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) ---------- components: Library (Lib) files: testcase-bug-python-deadlock-logging.py messages: 254896 nosy: fviard priority: normal severity: normal status: open title: Deadlock in logging caused by a possible race condition with "format" type: crash versions: Python 2.7, Python 3.2, Python 3.3, Python 3.4, Python 3.5, Python 3.6 Added file: http://bugs.python.org/file41077/testcase-bug-python-deadlock-logging.py _______________________________________ Python tracker <rep...@bugs.python.org> <http://bugs.python.org/issue25668> _______________________________________ _______________________________________________ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
