Fix infinite recursion during logging when syslog is down

Change-Id: Ia9ecffc88ce43616977e141498e5ee404f2c29c4

swift/common/utils.py

@@ -1233,11 +1233,37 @@ class NullLogger(object):
 
 class LoggerFileObject(object):
 
+    # Note: this is greenthread-local storage
+    _cls_thread_local = threading.local()
+
     def __init__(self, logger, log_type='STDOUT'):
         self.logger = logger
         self.log_type = log_type
 
     def write(self, value):
+        # We can get into a nasty situation when logs are going to syslog
+        # and syslog dies.
+        #
+        # It's something like this:
+        #
+        # (A) someone logs something
+        #
+        # (B) there's an exception in sending to /dev/log since syslog is
+        #     not working
+        #
+        # (C) logging takes that exception and writes it to stderr (see
+        #     logging.Handler.handleError)
+        #
+        # (D) stderr was replaced with a LoggerFileObject at process start,
+        #     so the LoggerFileObject takes the provided string and tells
+        #     its logger to log it (to syslog, naturally).
+        #
+        # Then, steps B through D repeat until we run out of stack.
+        if getattr(self._cls_thread_local, 'already_called_write', False):
+            return
+
+        self._cls_thread_local.already_called_write = True
+        try:
             value = value.strip()
             if value:
                 if 'Connection reset by peer' in value:
@@ -1246,11 +1272,20 @@ class LoggerFileObject(object):
                 else:
                     self.logger.error(_('%(type)s: %(value)s'),
                                       {'type': self.log_type, 'value': value})
+        finally:
+            self._cls_thread_local.already_called_write = False
 
     def writelines(self, values):
+        if getattr(self._cls_thread_local, 'already_called_writelines', False):
+            return
+
+        self._cls_thread_local.already_called_writelines = True
+        try:
             self.logger.error(_('%(type)s: %(value)s'),
                               {'type': self.log_type,
                                'value': '#012'.join(values)})
+        finally:
+            self._cls_thread_local.already_called_writelines = False
 
     def close(self):
         pass

test/unit/common/test_utils.py

@@ -1264,6 +1264,48 @@ class TestUtils(unittest.TestCase):
             self.assertRaises(IOError, lfo.readline, 1024)
             lfo.tell()
 
+    def test_LoggerFileObject_recursion(self):
+        crashy_calls = [0]
+
+        class CrashyLogger(logging.Handler):
+            def emit(self, record):
+                crashy_calls[0] += 1
+                try:
+                    # Pretend to be trying to send to syslog, but syslogd is
+                    # dead. We need the raise here to set sys.exc_info.
+                    raise socket.error(errno.ENOTCONN, "This is an ex-syslog")
+                except socket.error:
+                    self.handleError(record)
+
+        logger = logging.getLogger()
+        logger.addHandler(CrashyLogger())
+
+        # Set up some real file descriptors for stdio. If you run
+        # nosetests with "-s", you already have real files there, but
+        # otherwise they're StringIO objects.
+        #
+        # In any case, since capture_stdio() closes sys.stdin and friends,
+        # we'd want to set up some sacrificial files so as to not goof up
+        # the testrunner.
+        new_stdin = open(os.devnull, 'r+b')
+        new_stdout = open(os.devnull, 'w+b')
+        new_stderr = open(os.devnull, 'w+b')
+
+        with contextlib.closing(new_stdin), contextlib.closing(new_stdout), \
+                contextlib.closing(new_stderr):
+            # logging.raiseExceptions is set to False in test/__init__.py, but
+            # is True in Swift daemons, and the error doesn't manifest without
+            # it.
+            with mock.patch('sys.stdin', new_stdin), \
+                    mock.patch('sys.stdout', new_stdout), \
+                    mock.patch('sys.stderr', new_stderr), \
+                    mock.patch.object(logging, 'raiseExceptions', True):
+                # Note: since stdio is hooked up to /dev/null in here, using
+                # pdb is basically impossible. Sorry about that.
+                utils.capture_stdio(logger)
+                logger.info("I like ham")
+                self.assertTrue(crashy_calls[0], 1)
+
     def test_parse_options(self):
         # Get a file that is definitely on disk
         with NamedTemporaryFile() as f: