openstack/swift
Code Issues Proposed changes

Fix logger test coupling

Browse Source 
Two tests fail if test/unit/common/test_daemon.py is excluded
from the test set:

test.unit.common.test_utils.TestUtils.test_swift_log_formatter
test.unit.common.test_utils.TestStatsdLoggingDelegation.test_thread_locals

They fail because they assert that logger.txn_id is None,
when previous tests cause txn_id to be set. This coupling is masked
when test_daemon.py is included because it reloads the common/utils
module, and is executed just before test.unit.common.test_utils.

The coupling can be observed by running, for example:

nosetests ./test/unit/common/middleware/test_except.py ./test/unit/common/test_utils.py
or
nosetests ./test/unit/proxy ./test/unit/common/test_utils.py

The failing tests should reset logger thread_locals before making
assertions. test_utils.reset_loggers() attempts this but is broken
because it sets thread_local on the wrong object.

Changes in this patch:
 - fix reset_loggers() to reset the LogAdapter thread local state
 - add a reset_logger_state decorator to call reset_loggers
   before and after a decorated method
 - use the decorator for increased isolation of tests that previously
   called reset_loggers only on exit

Change-Id: If9aa781a2dd1929a47ef69322ec8c53263d47660
This commit is contained in:
Alistair Coles 2015-02-11 17:49:41 +00:00
parent b54532ca05
commit f5ab30574e
1 changed files with 35 additions and 19 deletions

54
test/unit/common/test_utils.py

@ -21,6 +21,7 @@ import ctypes
import errno
import eventlet
import eventlet.event
import functools
import grp
import logging
import os
@ -144,14 +145,28 @@ class MockSys(object):
def reset_loggers():
if hasattr(utils.get_logger, 'handler4logger'):
for logger, handler in utils.get_logger.handler4logger.items():
logger.thread_locals = (None, None)
logger.removeHandler(handler)
delattr(utils.get_logger, 'handler4logger')
if hasattr(utils.get_logger, 'console_handler4logger'):
for logger, h in utils.get_logger.console_handler4logger.items():
logger.thread_locals = (None, None)
logger.removeHandler(h)
delattr(utils.get_logger, 'console_handler4logger')
# Reset the LogAdapter class thread local state. Use get_logger() here
# to fetch a LogAdapter instance because the items from
# get_logger.handler4logger above are the underlying logger instances,
# not the LogAdapter.
utils.get_logger(None).thread_locals = (None, None)
def reset_logger_state(f):
@functools.wraps(f)
def wrapper(self, *args, **kwargs):
reset_loggers()
try:
return f(self, *args, **kwargs)
finally:
reset_loggers()
return wrapper
class TestTimestamp(unittest.TestCase):
@ -1241,6 +1256,7 @@ class TestUtils(unittest.TestCase):
finally:
utils.SysLogHandler = orig_sysloghandler
@reset_logger_state
def test_clean_logger_exception(self):
# setup stream logging
sio = StringIO()
@ -1330,8 +1346,8 @@ class TestUtils(unittest.TestCase):
finally:
logger.logger.removeHandler(handler)
reset_loggers()
@reset_logger_state
def test_swift_log_formatter_max_line_length(self):
# setup stream logging
sio = StringIO()
@ -1385,8 +1401,8 @@ class TestUtils(unittest.TestCase):
self.assertEqual(strip_value(sio), '1234567890abcde\n')
finally:
logger.logger.removeHandler(handler)
reset_loggers()
@reset_logger_state
def test_swift_log_formatter(self):
# setup stream logging
sio = StringIO()
@ -1449,7 +1465,6 @@ class TestUtils(unittest.TestCase):
self.assertEquals(strip_value(sio), 'test 1.2.3.4 test 12345\n')
finally:
logger.logger.removeHandler(handler)
reset_loggers()
def test_storage_directory(self):
self.assertEquals(utils.storage_directory('objects', '1', 'ABCDEF'),
@ -1697,6 +1712,7 @@ log_name = %(yarr)s'''
for func in required_func_calls:
self.assert_(utils.os.called_funcs[func])
@reset_logger_state
def test_capture_stdio(self):
# stubs
logger = utils.get_logger(None, 'dummy')
@ -1744,13 +1760,12 @@ log_name = %(yarr)s'''
utils.LoggerFileObject))
self.assertFalse(isinstance(utils.sys.stderr,
utils.LoggerFileObject))
reset_loggers()
finally:
utils.sys = _orig_sys
utils.os = _orig_os
@reset_logger_state
def test_get_logger_console(self):
reset_loggers()
logger = utils.get_logger(None)
console_handlers = [h for h in logger.logger.handlers if
isinstance(h, logging.StreamHandler)]
@ -1768,7 +1783,6 @@ log_name = %(yarr)s'''
self.assertEquals(len(console_handlers), 1)
new_handler = console_handlers[0]
self.assertNotEquals(new_handler, old_handler)
reset_loggers()
def verify_under_pseudo_time(
self, func, target_runtime_ms=1, *args, **kwargs):
@ -3666,19 +3680,21 @@ class TestStatsdLoggingDelegation(unittest.TestCase):
self.assertEquals('\xef\xbf\xbd\xef\xbf\xbd\xec\xbc\x9d\xef\xbf\xbd',
utils.get_valid_utf8_str(invalid_utf8_str))
@reset_logger_state
def test_thread_locals(self):
logger = utils.get_logger(None)
orig_thread_locals = logger.thread_locals
try:
self.assertEquals(logger.thread_locals, (None, None))
logger.txn_id = '1234'
logger.client_ip = '1.2.3.4'
self.assertEquals(logger.thread_locals, ('1234', '1.2.3.4'))
logger.txn_id = '5678'
logger.client_ip = '5.6.7.8'
self.assertEquals(logger.thread_locals, ('5678', '5.6.7.8'))
finally:
logger.thread_locals = orig_thread_locals
# test the setter
logger.thread_locals = ('id', 'ip')
self.assertEquals(logger.thread_locals, ('id', 'ip'))
# reset
logger.thread_locals = (None, None)
self.assertEquals(logger.thread_locals, (None, None))
logger.txn_id = '1234'
logger.client_ip = '1.2.3.4'
self.assertEquals(logger.thread_locals, ('1234', '1.2.3.4'))
logger.txn_id = '5678'
logger.client_ip = '5.6.7.8'
self.assertEquals(logger.thread_locals, ('5678', '5.6.7.8'))
def test_no_fdatasync(self):
called = []