Author cagney
Recipients Birne94, Connor.Wolf, Giovanni.Bajo, Winterflower, bobbyi, cagney, dan.oreilly, davin, emptysquare, forest_atq, gregory.p.smith, ionelmc, jcea, lesha, neologix, nirai, nirs, ochedru, pitrou, sbt, sdaoden, tshepang, vinay.sajip, vstinner
Date 2019-04-04.17:35:45
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1554399346.05.0.115658735961.issue6721@roundup.psfhosted.org>
In-reply-to
Content
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))
History
Date User Action Args
2019-04-04 17:35:46cagneysetrecipients: + 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:46cagneysetmessageid: <1554399346.05.0.115658735961.issue6721@roundup.psfhosted.org>
2019-04-04 17:35:46cagneylinkissue6721 messages
2019-04-04 17:35:45cagneycreate