From 95efd3f9035ec4141e1b182516f040a59a3e5aa6 Mon Sep 17 00:00:00 2001
From: Samuel Merritt <sam@swiftstack.com>
Date: Wed, 23 Mar 2016 13:51:47 -0700
Subject: [PATCH] Fix infinite recursion during logging when syslog is down

Change-Id: Ia9ecffc88ce43616977e141498e5ee404f2c29c4
---
 swift/common/utils.py          | 57 +++++++++++++++++++++++++++-------
 test/unit/common/test_utils.py | 42 +++++++++++++++++++++++++
 2 files changed, 88 insertions(+), 11 deletions(-)

diff --git a/swift/common/utils.py b/swift/common/utils.py
index fcfe86a8dd..68c6025f29 100644
--- a/swift/common/utils.py
+++ b/swift/common/utils.py
@@ -1233,24 +1233,59 @@ 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):
-        value = value.strip()
-        if value:
-            if 'Connection reset by peer' in value:
-                self.logger.error(
-                    _('%s: Connection reset by peer'), self.log_type)
-            else:
-                self.logger.error(_('%(type)s: %(value)s'),
-                                  {'type': self.log_type, 'value': 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:
+                    self.logger.error(
+                        _('%s: Connection reset by peer'), self.log_type)
+                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):
-        self.logger.error(_('%(type)s: %(value)s'),
-                          {'type': self.log_type,
-                           'value': '#012'.join(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
diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py
index 409990ad4a..c2a9e93cc3 100644
--- a/test/unit/common/test_utils.py
+++ b/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: