Don't monkey patch logging on import

Previously swift.common.utils monkey patched logging.thread,
logging.threading, and logging._lock upon import with eventlet
threading modules, but that is no longer reasonable or necessary.

With py3, the existing logging._lock is not patched by eventlet,
unless the logging module is reloaded. The existing lock is not
tracked by the gc so would not be found by eventlet's
green_existing_locks().

Instead we group all monkey patching into utils function and apply
patching consistently across daemons and WSGI servers.

Co-Authored-By: Clay Gerrard <clay.gerrard@gmail.com>
Co-Authored-By: Alistair Coles <alistairncoles@gmail.com>
Closes-Bug: #1380815
Change-Id: I6f35ad41414898fb7dc5da422f524eb52ff2940f

6 files changed, 108 insertions, 19 deletions

diff --git a/swift/common/daemon.py b/swift/common/daemon.py
index 773ca9424..300710e98 100644
--- a/swift/common/daemon.py
+++ b/swift/common/daemon.py
@@ -20,8 +20,8 @@ import time
 import signal
 from re import sub
 
+import eventlet
 import eventlet.debug
-from eventlet.hubs import use_hub
 
 from swift.common import utils
 
@@ -281,7 +281,9 @@ def run_daemon(klass, conf_file, section_name='', once=False, **kwargs):
         # and results in an exit code of 1.
         sys.exit(e)
 
-    use_hub(utils.get_hub())
+    # patch eventlet/logging early
+    utils.monkey_patch()
+    eventlet.hubs.use_hub(utils.get_hub())
 
     # once on command line (i.e. daemonize=false) will over-ride config
     once = once or not utils.config_true_value(conf.get('daemonize', 'true'))
diff --git a/swift/common/utils/__init__.py b/swift/common/utils/__init__.py
index 16dc58807..cdaa0b807 100644
--- a/swift/common/utils/__init__.py
+++ b/swift/common/utils/__init__.py
@@ -119,16 +119,10 @@ from swift.common.utils.timestamp import (  # noqa
     normalize_delete_at_timestamp,
 )
 
-# logging doesn't import patched as cleanly as one would like
 from logging.handlers import SysLogHandler
 import logging
-logging.thread = eventlet.green.thread
-logging.threading = eventlet.green.threading
-logging._lock = logging.threading.RLock()
-# setup notice level logging
+
 NOTICE = 25
-logging.addLevelName(NOTICE, 'NOTICE')
-SysLogHandler.priority_map['NOTICE'] = 'notice'
 
 # Used by hash_path to offer a bit more security when generating hashes for
 # paths. It simply appends this value to all paths; guessing the hash a path
@@ -442,6 +436,17 @@ def config_read_prefixed_options(conf, prefix_name, defaults):
     return params
 
 
+def logging_monkey_patch():
+    # explicitly patch the logging lock
+    logging._lock = logging.threading.RLock()
+    # setup notice level logging
+    logging.addLevelName(NOTICE, 'NOTICE')
+    SysLogHandler.priority_map['NOTICE'] = 'notice'
+    # Trying to log threads while monkey-patched can lead to deadlocks; see
+    # https://bugs.launchpad.net/swift/+bug/1895739
+    logging.logThreads = 0
+
+
 def eventlet_monkey_patch():
     """
     Install the appropriate Eventlet monkey patches.
@@ -452,9 +457,14 @@ def eventlet_monkey_patch():
     #         if thread is monkey-patched.
     eventlet.patcher.monkey_patch(all=False, socket=True, select=True,
                                   thread=True)
-    # Trying to log threads while monkey-patched can lead to deadlocks; see
-    # https://bugs.launchpad.net/swift/+bug/1895739
-    logging.logThreads = 0
+
+
+def monkey_patch():
+    """
+    Apply all swift monkey patching consistently in one place.
+    """
+    eventlet_monkey_patch()
+    logging_monkey_patch()
 
 
 def validate_configuration():
diff --git a/swift/common/wsgi.py b/swift/common/wsgi.py
index 7c39a89e2..99dc4c203 100644
--- a/swift/common/wsgi.py
+++ b/swift/common/wsgi.py
@@ -838,7 +838,7 @@ def run_wsgi(conf_path, app_section, *args, **kwargs):
             return 1
 
     # patch event before loadapp
-    utils.eventlet_monkey_patch()
+    utils.monkey_patch()
 
     # Ensure the configuration and application can be loaded before proceeding.
     global_conf = {'log_name': log_name}
diff --git a/test/unit/common/test_daemon.py b/test/unit/common/test_daemon.py
index 94c7917bc..de8145299 100644
--- a/test/unit/common/test_daemon.py
+++ b/test/unit/common/test_daemon.py
@@ -148,9 +148,12 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
         ])
 
     def test_run_daemon(self):
+        logging.logThreads = 1  # reset to default
         sample_conf = "[my-daemon]\nuser = %s\n" % getuser()
         with tmpfile(sample_conf) as conf_file, \
-                mock.patch('swift.common.daemon.use_hub') as mock_use_hub:
+                mock.patch('swift.common.utils.eventlet') as _utils_evt, \
+                mock.patch('eventlet.hubs.use_hub') as mock_use_hub, \
+                mock.patch('eventlet.debug') as _debug_evt:
             with mock.patch.dict('os.environ', {'TZ': ''}), \
                     mock.patch('time.tzset') as mock_tzset:
                 daemon.run_daemon(MyDaemon, conf_file)
@@ -160,6 +163,12 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
                 self.assertEqual(mock_use_hub.mock_calls,
                                  [mock.call(utils.get_hub())])
             daemon.run_daemon(MyDaemon, conf_file, once=True)
+            _utils_evt.patcher.monkey_patch.assert_called_with(all=False,
+                                                               socket=True,
+                                                               select=True,
+                                                               thread=True)
+            self.assertEqual(0, logging.logThreads)  # fixed in monkey_patch
+            _debug_evt.hub_exceptions.assert_called_with(False)
             self.assertEqual(MyDaemon.once_called, True)
 
             # test raise in daemon code
@@ -196,7 +205,9 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
 
             sample_conf = "[my-daemon]\nuser = %s\n" % getuser()
             with tmpfile(sample_conf) as conf_file, \
-                    mock.patch('swift.common.daemon.use_hub'):
+                    mock.patch('swift.common.utils.eventlet'), \
+                    mock.patch('eventlet.hubs.use_hub'), \
+                    mock.patch('eventlet.debug'):
                 daemon.run_daemon(MyDaemon, conf_file)
                 self.assertFalse(MyDaemon.once_called)
                 self.assertTrue(MyDaemon.forever_called)
@@ -222,7 +233,9 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
         contents = dedent(conf_body)
         with open(conf_path, 'w') as f:
             f.write(contents)
-        with mock.patch('swift.common.daemon.use_hub'):
+        with mock.patch('swift.common.utils.eventlet'), \
+                mock.patch('eventlet.hubs.use_hub'), \
+                mock.patch('eventlet.debug'):
             d = daemon.run_daemon(MyDaemon, conf_path)
         # my-daemon section takes priority (!?)
         self.assertEqual('2', d.conf['client_timeout'])
@@ -241,7 +254,9 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
         contents = dedent(conf_body)
         with open(conf_path, 'w') as f:
             f.write(contents)
-        with mock.patch('swift.common.daemon.use_hub'):
+        with mock.patch('swift.common.utils.eventlet'), \
+                mock.patch('eventlet.hubs.use_hub'), \
+                mock.patch('eventlet.debug'):
             app_config = lambda: daemon.run_daemon(MyDaemon, tempdir)
             self.assertDuplicateOption(app_config, 'client_timeout', '1')
 
@@ -266,7 +281,9 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
             path = os.path.join(tempdir, filename + '.conf')
             with open(path, 'wt') as fd:
                 fd.write(dedent(conf_body))
-        with mock.patch('swift.common.daemon.use_hub'):
+        with mock.patch('swift.common.utils.eventlet'), \
+                mock.patch('eventlet.hubs.use_hub'), \
+                mock.patch('eventlet.debug'):
             d = daemon.run_daemon(MyDaemon, tempdir)
         # my-daemon section takes priority (!?)
         self.assertEqual('2', d.conf['client_timeout'])
@@ -289,7 +306,9 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
             path = os.path.join(tempdir, filename + '.conf')
             with open(path, 'wt') as fd:
                 fd.write(dedent(conf_body))
-        with mock.patch('swift.common.daemon.use_hub'):
+        with mock.patch('swift.common.utils.eventlet'), \
+                mock.patch('eventlet.hubs.use_hub'), \
+                mock.patch('eventlet.debug'):
             app_config = lambda: daemon.run_daemon(MyDaemon, tempdir)
             self.assertDuplicateOption(app_config, 'client_timeout', '4')
 
@@ -314,6 +333,7 @@ class TestRunDaemon(unittest.TestCase, ConfigAssertMixin):
             yield
 
     def test_fork_workers(self):
+        utils.logging_monkey_patch()  # needed to log at notice
         d = MyWorkerDaemon({'workers': 3})
         strategy = daemon.DaemonStrategy(d, d.logger)
         with self.mock_os():
diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py
index e477ee85d..560b3359c 100644
--- a/test/unit/common/test_utils.py
+++ b/test/unit/common/test_utils.py
@@ -210,6 +210,61 @@ class TestUtils(unittest.TestCase):
             self.md5_digest = '0d6dc3c588ae71a04ce9a6beebbbba06'
             self.fips_enabled = True
 
+    def test_monkey_patch(self):
+        def take_and_release(lock):
+            try:
+                lock.acquire()
+            finally:
+                lock.release()
+
+        def do_test():
+            res = 0
+            try:
+                # this module imports eventlet original threading, so re-import
+                # locally...
+                import threading
+                import traceback
+                logging_lock_before = logging._lock
+                my_lock_before = threading.RLock()
+                self.assertIsInstance(logging_lock_before,
+                                      type(my_lock_before))
+
+                utils.monkey_patch()
+
+                logging_lock_after = logging._lock
+                my_lock_after = threading.RLock()
+                self.assertIsInstance(logging_lock_after,
+                                      type(my_lock_after))
+
+                self.assertTrue(logging_lock_after.acquire())
+                thread = threading.Thread(target=take_and_release,
+                                          args=(logging_lock_after,))
+                thread.start()
+                self.assertTrue(thread.isAlive())
+                # we should timeout while the thread is still blocking on lock
+                eventlet.sleep()
+                thread.join(timeout=0.1)
+                self.assertTrue(thread.isAlive())
+
+                logging._lock.release()
+                thread.join(timeout=0.1)
+                self.assertFalse(thread.isAlive())
+            except AssertionError:
+                traceback.print_exc()
+                res = 1
+            finally:
+                os._exit(res)
+
+        pid = os.fork()
+        if pid == 0:
+            # run the test in an isolated environment to avoid monkey patching
+            # in this one
+            do_test()
+        else:
+            child_pid, errcode = os.waitpid(pid, 0)
+            self.assertEqual(0, os.WEXITSTATUS(errcode),
+                             'Forked do_test failed')
+
     def test_get_zero_indexed_base_string(self):
         self.assertEqual(utils.get_zero_indexed_base_string('something', 0),
                          'something')
diff --git a/test/unit/common/test_wsgi.py b/test/unit/common/test_wsgi.py
index 39349ffa3..3c66d07f3 100644
--- a/test/unit/common/test_wsgi.py
+++ b/test/unit/common/test_wsgi.py
@@ -989,6 +989,7 @@ class TestWSGI(unittest.TestCase, ConfigAssertMixin):
         def _loadapp(uri, name=None, **kwargs):
             calls['_loadapp'] += 1
 
+        logging.logThreads = 1  # reset to default
         with mock.patch.object(wsgi, '_initrp', _initrp), \
                 mock.patch.object(wsgi, 'get_socket'), \
                 mock.patch.object(wsgi, 'drop_privileges') as _d_privs, \
@@ -1009,6 +1010,7 @@ class TestWSGI(unittest.TestCase, ConfigAssertMixin):
         # just clean_up_deemon_hygene()
         self.assertEqual([], _d_privs.mock_calls)
         self.assertEqual([mock.call()], _c_hyg.mock_calls)
+        self.assertEqual(0, logging.logThreads)  # fixed in our monkey_patch
 
     @mock.patch('swift.common.wsgi.run_server')
     @mock.patch('swift.common.wsgi.WorkersStrategy')