Merge lp:~lifeless/zconfig/bug-481512 into lp:~fdrake/zconfig/trunk

[Robert Collins]

This is an alternative fix for the signal handling race condition.

It:
 - sets a flag atomically, by binding a name to True.
 - does a flush of the stream
 - changes the reopen and close orders to prevent self.stream being a closed file.

[Curtis Hovey (sinzui)]

Hi Robert.

I think the code and safe and okay to land. Before you do land, Review the comment in line 51+. I think line 55 is from an earlier edit and it does not make sense.

review: Approve (code)

Unmerged revisions

503. By Robert Collins on 2012-09-04

Flush, hopefully safely.

502. By Robert Collins on 2012-09-04

Another approach for dealing with race conditions in reopen when used from signal handlers.

=== modified file 'ZConfig/components/logger/loghandler.py'
--- ZConfig/components/logger/loghandler.py	2012-02-11 06:04:50 +0000
+++ ZConfig/components/logger/loghandler.py	2012-09-04 05:45:23 +0000
@@ -69,27 +69,52 @@
         self.baseFilename = filename
         self.mode = mode
         self._wr = weakref.ref(self, _remove_from_reopenable)
+        self._reopen = False
         _reopenable_handlers.append(self._wr)
 
     def close(self):
-        self.stream.close()
-        # This can raise a KeyError if the handler has already been
-        # removed, but a later error can be raised if
-        # StreamHandler.close() isn't called.  This seems the best
-        # compromise.  :-(
-        try:
-            StreamHandler.close(self)
-        except KeyError:
-            pass
-        _remove_from_reopenable(self._wr)
-
-    def reopen(self):
-        self.acquire()
-        try:
+        try:
+            _remove_from_reopenable(self._wr)
+        finally:
             self.stream.close()
+            # This can raise a KeyError if the handler has already been
+            # removed, but a later error can be raised if
+            # StreamHandler.close() isn't called.  This seems the best
+            # compromise.  :-(
+            try:
+                StreamHandler.close(self)
+            except KeyError:
+                pass
+
+    def acquire(self):
+        super(FileHandler, self).acquire()
+        if self._reopen:
+            # Ensure that self.stream is never assigned-but-closed.
+            old_stream = self.stream
             self.stream = open(self.baseFilename, self.mode)
-        finally:
-            self.release()
+            self._reopen = False
+            old_stream.close()
+
+    def reopen(self):
+        # Note: this may be called from a signal handler, so it cannot:
+        # - take non reentrant locks
+        #   which includes locks written in python that are built on
+        #   non-reentrant C primitives
+        # make any assumptions about state.
+        # -> we set a flag, which is a simple assignment, and that is inspected
+        # by acquire.
+        # Any in-progress log message (that already holds the lock) will log to
+        # the stream that was open when it started.
+        # The next log message will cause an actual re-open to occur.
+        # This means that there is an unknown, and unknownable duration between
+        # reopen() being called, and the reopen happening.
+        # If two signals are received in short order, its possible that the
+        # reset in acquire will be overwritten, but the absence of a
+        # compare-exchange, and the inability to use Python based locks in a
+        # signal handler makes this intractable.
+        # See http://bugs.python.org/issue13697 for more information.
+        self._reopen = True
+        self.stream.flush()
 
 
 class Win32FileHandler(FileHandler):

=== modified file 'ZConfig/components/logger/tests/test_logger.py'
--- ZConfig/components/logger/tests/test_logger.py	2012-02-11 20:34:47 +0000
+++ ZConfig/components/logger/tests/test_logger.py	2012-09-04 05:45:23 +0000
@@ -628,23 +628,6 @@
                 logger.removeHandler(handler)
                 handler.close()
 
-    def test_filehandler_reopen_thread_safety(self):
-        # The reopen method needs to do locking to avoid a race condition
-        # with emit calls. For simplicity we replace the "acquire" and
-        # "release" methods with dummies that record calls to them.
-
-        fn = self.mktemp()
-        h = self.handler_factory(fn)
-
-        calls = []
-        h.acquire = lambda: calls.append("acquire")
-        h.release = lambda: calls.append("release")
-
-        h.reopen()
-        h.close()
-
-        self.assertEqual(calls, ["acquire", "release"])
-
 
 def test_logger_convenience_function_and_ommiting_name_to_get_root_logger():
     """