[New-bugs-announce] [issue25668] Deadlock in logging caused by a possible race condition with "format"

[Florent Viard]

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 <report at bugs.python.org>
<http://bugs.python.org/issue25668>
_______________________________________