[issue6721] Locks in the standard library should be sanitized on fork

[cagney]

cagney <andrew.cagney at gmail.com> added the comment:

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))

----------

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue6721>
_______________________________________