From 84b995f275c42795b2193a92eaef0329f68a1f20 Mon Sep 17 00:00:00 2001 From: Chetan Mishra Date: Sun, 9 Apr 2017 10:02:12 -0400 Subject: [PATCH] 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 Co-Authored-By: Alistair Coles Closes-Bug: #1380815 Change-Id: I6f35ad41414898fb7dc5da422f524eb52ff2940f --- swift/common/daemon.py | 6 ++-- swift/common/utils/__init__.py | 30 ++++++++++++------ swift/common/wsgi.py | 2 +- test/unit/common/test_daemon.py | 32 +++++++++++++++---- test/unit/common/test_utils.py | 55 +++++++++++++++++++++++++++++++++ test/unit/common/test_wsgi.py | 2 ++ 6 files changed, 108 insertions(+), 19 deletions(-) diff --git a/swift/common/daemon.py b/swift/common/daemon.py index 773ca9424d..300710e982 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 16dc58807a..cdaa0b8072 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 7c39a89e25..99dc4c203d 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 94c7917bcd..de81452990 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 e477ee85d4..560b3359cc 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 39349ffa3f..3c66d07f3e 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')