openstack/swift
Code Issues Proposed changes

Merge "Remove PrefixLoggerAdapter and SwiftLoggerAdapter"

Browse Source
This commit is contained in:
Zuul 2024-11-14 12:51:08 +00:00 committed by Gerrit Code Review
commit 71696d3a83
14 changed files with 357 additions and 163 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
doc/source/admin_guide.rst
View File

@ -1064,8 +1064,8 @@ Custom Log Handlers
Swift supports setting up custom log handlers for services by specifying a
comma-separated list of functions to invoke when logging is setup. It does so
via the ``log_custom_handlers`` configuration option. Logger hooks invoked are
passed the same arguments as Swift's get_logger function (as well as the
getLogger and LogAdapter object):
passed the same arguments as Swift's ``get_logger`` function, as well as the
``logging.Logger`` and ``SwiftLogAdapter`` objects:
============== ===============================================
Name Description
@ -1079,6 +1079,14 @@ logger The logging.getLogger object
adapted_logger The LogAdapter object
============== ===============================================
.. note::
The instance of ``SwiftLogAdapter`` that wraps the ``logging.Logger``
object may be replaced with cloned instances during runtime, for example to
use a different log prefix with the same ``logging.Logger``. Custom log
handlers should therefore not modify any attributes of the
``SwiftLogAdapter`` instance other than those that will be copied if it is
cloned.
A basic example that sets up a custom logger might look like the
following:

28
swift/cli/relinker.py
View File

@ -30,9 +30,10 @@ from swift.common.exceptions import LockTimeout
from swift.common.storage_policy import POLICIES
from swift.common.utils import replace_partition_in_path, config_true_value, \
audit_location_generator, get_logger, readconf, drop_privileges, \
RateLimitedIterator, PrefixLoggerAdapter, distribute_evenly, \
RateLimitedIterator, distribute_evenly, \
non_negative_float, non_negative_int, config_auto_int_value, \
dump_recon_cache, get_partition_from_path, get_hub
from swift.common.utils.logs import SwiftLogAdapter, get_prefixed_logger
from swift.obj import diskfile
from swift.common.recon import RECON_RELINKER_FILE, DEFAULT_RECON_CACHE_PATH
@ -658,8 +659,17 @@ def _reset_recon(recon_cache, logger):
dump_recon_cache(device_progress_recon, recon_cache, logger)
def parallel_process(do_cleanup, conf, logger=None, device_list=None):
logger = logger or logging.getLogger()
def parallel_process(do_cleanup, conf, logger, device_list=None):
"""
Fork Relinker workers based on config and wait for them to finish.
:param do_cleanup: boolean, if workers should perform cleanup step
:param conf: dict, config options
:param logger: SwiftLogAdapter instance
:kwarg device_list: list of strings, optionally limit to specific devices
:returns: int, exit code; zero on success
"""
# initialise recon dump for collection
# Lets start by always deleting last run's stats
@ -689,11 +699,10 @@ def parallel_process(do_cleanup, conf, logger=None, device_list=None):
for worker_devs in distribute_evenly(device_list, workers):
pid = os.fork()
if pid == 0:
dev_logger = PrefixLoggerAdapter(logger, {})
dev_logger.set_prefix('[pid=%s, devs=%s] ' % (
logger = get_prefixed_logger(logger, '[pid=%s, devs=%s] ' % (
os.getpid(), ','.join(worker_devs)))
os._exit(Relinker(
conf, dev_logger, worker_devs, do_cleanup=do_cleanup).run())
conf, logger, worker_devs, do_cleanup=do_cleanup).run())
else:
children[pid] = worker_devs
@ -796,16 +805,17 @@ def main(args=None):
drop_privileges(user)
logger = get_logger(conf)
else:
conf = {'log_level': 'DEBUG' if args.debug else 'INFO'}
level = 'DEBUG' if args.debug else 'INFO'
conf = {'log_level': level}
if args.user:
# Drop privs before creating log file
drop_privileges(args.user)
conf['user'] = args.user
logging.basicConfig(
format='%(message)s',
level=logging.DEBUG if args.debug else logging.INFO,
level=getattr(logging, level),
filename=args.logfile)
logger = logging.getLogger()
logger = SwiftLogAdapter(logging.getLogger(), server='relinker')
conf.update({
'swift_dir': args.swift_dir or conf.get('swift_dir', '/etc/swift'),

4
swift/common/utils/__init__.py
View File

@ -88,13 +88,11 @@ from swift.common.utils.logs import ( # noqa
SysLogHandler, # t.u.helpers.setup_servers monkey patch is sketch
logging_monkey_patch,
get_logger,
PrefixLoggerAdapter,
get_prefixed_logger,
LogLevelFilter,
NullLogger,
capture_stdio,
SwiftLogFormatter,
SwiftLoggerAdapter,
LogAdapter,
LoggerFileObject,
PipeMutex,
NoopMutex,

97
swift/common/utils/logs.py
View File

@ -243,17 +243,24 @@ class ThreadSafeSysLogHandler(SysLogHandler):
# double inheritance to support property with setter
class LogAdapter(logging.LoggerAdapter, object):
class SwiftLogAdapter(logging.LoggerAdapter, object):
"""
A Logger like object which performs some reformatting on calls to
:meth:`exception`. Can be used to store a threadlocal transaction id and
client ip.
A LogAdapter that modifies the adapted ``Logger`` instance
in the following ways:
* Performs some reformatting on calls to :meth:`exception`.
* Provides threadlocal txn_id and client_ip attributes.
* Adds the txn_id, client_ip and server attributes to the ``extras`` dict
when a message is processed.
* Adds the given prefix to the start of each log message.
* Provides a notice method for logging at NOTICE level.
"""
_cls_thread_local = threading.local()
def __init__(self, logger, server):
def __init__(self, logger, server, prefix=''):
logging.LoggerAdapter.__init__(self, logger, {})
self.prefix = prefix
self.server = server
self.warn = self.warning
@ -262,6 +269,7 @@ class LogAdapter(logging.LoggerAdapter, object):
# - https://github.com/python/cpython/commit/1bbd482
# - https://github.com/python/cpython/commit/0b6a118
# - https://github.com/python/cpython/commit/ce9e625
def _log(self, level, msg, args, exc_info=None, extra=None,
stack_info=False):
"""
@ -323,6 +331,7 @@ class LogAdapter(logging.LoggerAdapter, object):
"""
kwargs['extra'] = {'server': self.server, 'txn_id': self.txn_id,
'client_ip': self.client_ip}
msg = '%s%s' % (self.prefix, msg)
return msg, kwargs
def notice(self, msg, *args, **kwargs):
@ -335,6 +344,9 @@ class LogAdapter(logging.LoggerAdapter, object):
self.log(NOTICE, msg, *args, **kwargs)
def _exception(self, msg, *args, **kwargs):
msg = '%s%s' % (self.prefix, msg)
# We up-call to exception() where stdlib uses error() so we can get
# some of the traceback suppression from LogAdapter, below
logging.LoggerAdapter.exception(self, msg, *args, **kwargs)
def exception(self, msg, *args, **kwargs):
@ -414,6 +426,7 @@ class LogAdapter(logging.LoggerAdapter, object):
if getattr(self.logger, 'statsd_client'):
func = getattr(self.logger.statsd_client, statsd_func_name)
return func(*a, **kw)
return wrapped
update_stats = statsd_delegate('update_stats')
@ -556,73 +569,6 @@ class LoggerFileObject(object):
return self
class SwiftLoggerAdapter(logging.LoggerAdapter):
"""
A logging.LoggerAdapter subclass that also passes through StatsD method
calls.
Like logging.LoggerAdapter, you have to subclass this and override the
process() method to accomplish anything useful.
"""
@property
def name(self):
# py3 does this for us already; add it for py2
return self.logger.name
def update_stats(self, *a, **kw):
return self.logger.update_stats(*a, **kw)
def increment(self, *a, **kw):
return self.logger.increment(*a, **kw)
def decrement(self, *a, **kw):
return self.logger.decrement(*a, **kw)
def timing(self, *a, **kw):
return self.logger.timing(*a, **kw)
def timing_since(self, *a, **kw):
return self.logger.timing_since(*a, **kw)
def transfer_rate(self, *a, **kw):
return self.logger.transfer_rate(*a, **kw)
@property
def thread_locals(self):
return self.logger.thread_locals
@thread_locals.setter
def thread_locals(self, thread_locals):
self.logger.thread_locals = thread_locals
def exception(self, msg, *a, **kw):
# We up-call to exception() where stdlib uses error() so we can get
# some of the traceback suppression from LogAdapter, below
self.logger.exception(msg, *a, **kw)
class PrefixLoggerAdapter(SwiftLoggerAdapter):
"""
Adds an optional prefix to all its log messages. When the prefix has not
been set, messages are unchanged.
"""
def set_prefix(self, prefix):
self.extra['prefix'] = prefix
def exception(self, msg, *a, **kw):
if 'prefix' in self.extra:
msg = self.extra['prefix'] + msg
super(PrefixLoggerAdapter, self).exception(msg, *a, **kw)
def process(self, msg, kwargs):
msg, kwargs = super(PrefixLoggerAdapter, self).process(msg, kwargs)
if 'prefix' in self.extra:
msg = self.extra['prefix'] + msg
return (msg, kwargs)
class LogLevelFilter(object):
"""
Drop messages for the logger based on level.
@ -747,7 +693,7 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
logger.statsd_client = statsd_client.get_statsd_client(
conf, statsd_tail_prefix, logger)
adapted_logger = LogAdapter(logger, name)
adapted_logger = SwiftLogAdapter(logger, name)
other_handlers = conf.get('log_custom_handlers', None)
if other_handlers:
log_custom_handlers = [s.strip() for s in other_handlers.split(',')
@ -768,6 +714,11 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
return adapted_logger
def get_prefixed_logger(swift_logger, prefix):
return SwiftLogAdapter(
swift_logger.logger, swift_logger.server, prefix=prefix)
class NullLogger(object):
"""A no-op logger for eventlet wsgi."""

11
swift/obj/auditor.py
View File

@ -32,8 +32,8 @@ from swift.common.storage_policy import POLICIES
from swift.common.utils import (
config_auto_int_value, dump_recon_cache, get_logger, list_from_csv,
listdir, load_pkg_resource, parse_prefixed_conf, EventletRateLimiter,
readconf, round_robin_iter, unlink_paths_older_than, PrefixLoggerAdapter,
parse_options)
readconf, round_robin_iter, unlink_paths_older_than, parse_options,
get_prefixed_logger)
from swift.common.recon import RECON_OBJECT_FILE, DEFAULT_RECON_CACHE_PATH
@ -489,13 +489,16 @@ class WatcherWrapper(object):
Simple and gets the job done. Note that we aren't doing anything
to isolate ourselves from hangs or file descriptor leaks
in the plugins.
:param logger: an instance of ``SwiftLogAdapter``.
"""
def __init__(self, watcher_class, watcher_name, conf, logger):
self.watcher_name = watcher_name
self.watcher_in_error = False
self.logger = PrefixLoggerAdapter(logger, {})
self.logger.set_prefix('[audit-watcher %s] ' % watcher_name)
self.logger = get_prefixed_logger(
logger, '[audit-watcher %s] ' % watcher_name)
try:
self.watcher = watcher_class(conf, self.logger)

22
swift/obj/reconstructor.py
View File

@ -30,11 +30,11 @@ from eventlet.support.greenlets import GreenletExit
from swift.common.utils import (
whataremyips, unlink_older_than, compute_eta, get_logger,
dump_recon_cache, mkdirs, config_true_value,
dump_recon_cache, mkdirs, config_true_value, parse_options,
GreenAsyncPile, Timestamp, remove_file, node_to_string,
load_recon_cache, parse_override_options, distribute_evenly,
PrefixLoggerAdapter, remove_directory, config_request_node_count_value,
non_negative_int, parse_options)
remove_directory, config_request_node_count_value,
non_negative_int, get_prefixed_logger)
from swift.common.header_key_dict import HeaderKeyDict
from swift.common.bufferedhttp import http_connect
from swift.common.daemon import Daemon, run_daemon
@ -158,11 +158,11 @@ class ObjectReconstructor(Daemon):
def __init__(self, conf, logger=None):
"""
:param conf: configuration object obtained from ConfigParser
:param logger: logging object
:param logger: an instance of ``SwiftLogAdapter``.
"""
self.conf = conf
self.logger = PrefixLoggerAdapter(
logger or get_logger(conf, log_route='object-reconstructor'), {})
self.logger = \
logger or get_logger(conf, log_route='object-reconstructor')
self.devices_dir = conf.get('devices', '/srv/node')
self.mount_check = config_true_value(conf.get('mount_check', 'true'))
self.swift_dir = conf.get('swift_dir', '/etc/swift')
@ -792,10 +792,12 @@ class ObjectReconstructor(Daemon):
(time.time() - self.start))
def _emplace_log_prefix(self, worker_index):
self.logger.set_prefix("[worker %d/%d pid=%s] " % (
worker_index + 1, # use 1-based indexing for more readable logs
self.reconstructor_workers,
os.getpid()))
self.logger = get_prefixed_logger(
self.logger, "[worker %d/%d pid=%s] " % (
worker_index + 1,
# use 1-based indexing for more readable logs
self.reconstructor_workers,
os.getpid()))
def kill_coros(self):
"""Utility function that kills all coroutines currently running."""

24
swift/obj/replicator.py
View File

@ -32,11 +32,11 @@ from eventlet.green import subprocess
from swift.common.constraints import check_drive
from swift.common.ring.utils import is_local_device
from swift.common.utils import whataremyips, unlink_older_than, \
compute_eta, get_logger, dump_recon_cache, \
compute_eta, get_logger, dump_recon_cache, parse_options, \
rsync_module_interpolation, mkdirs, config_true_value, \
config_auto_int_value, storage_directory, \
load_recon_cache, PrefixLoggerAdapter, parse_override_options, \
distribute_evenly, listdir, node_to_string, parse_options, EUCLEAN
config_auto_int_value, storage_directory, load_recon_cache, EUCLEAN, \
parse_override_options, distribute_evenly, listdir, node_to_string, \
get_prefixed_logger
from swift.common.bufferedhttp import http_connect
from swift.common.daemon import Daemon, run_daemon
from swift.common.http import HTTP_OK, HTTP_INSUFFICIENT_STORAGE
@ -127,11 +127,11 @@ class ObjectReplicator(Daemon):
def __init__(self, conf, logger=None):
"""
:param conf: configuration object obtained from ConfigParser
:param logger: logging object
:param logger: an instance of ``SwiftLogAdapter``.
"""
self.conf = conf
self.logger = PrefixLoggerAdapter(
logger or get_logger(conf, log_route='object-replicator'), {})
self.logger = \
logger or get_logger(conf, log_route='object-replicator')
self.devices_dir = conf.get('devices', '/srv/node')
self.mount_check = config_true_value(conf.get('mount_check', 'true'))
self.swift_dir = conf.get('swift_dir', '/etc/swift')
@ -215,10 +215,12 @@ class ObjectReplicator(Daemon):
return sum(self.stats_for_dev.values(), Stats())
def _emplace_log_prefix(self, worker_index):
self.logger.set_prefix("[worker %d/%d pid=%d] " % (
worker_index + 1, # use 1-based indexing for more readable logs
self.replicator_workers,
os.getpid()))
self.logger = get_prefixed_logger(
self.logger, "[worker %d/%d pid=%d] " % (
worker_index + 1,
# use 1-based indexing for more readable logs
self.replicator_workers,
os.getpid()))
def _child_process_reaper(self):
"""

7
test/debug_logger.py
View File

@ -258,7 +258,7 @@ class DebugLogger(FakeLogger):
self.records[record.levelname].append(formatted)
class DebugLogAdapter(utils.LogAdapter):
class DebugLogAdapter(utils.logs.SwiftLogAdapter):
def __init__(self, *args, **kwargs):
super(DebugLogAdapter, self).__init__(*args, **kwargs)
self.txn_id = None
@ -290,7 +290,7 @@ class ForwardingLogHandler(logging.NullHandler):
return self.handler_fn(record)
class CaptureLogAdapter(utils.LogAdapter, CaptureLog):
class CaptureLogAdapter(utils.logs.SwiftLogAdapter, CaptureLog):
"""
A LogAdapter that is capable of capturing logs for inspection via accessor
methods.
@ -325,7 +325,8 @@ def capture_logger(conf, *args, **kwargs):
accessor methods (e.g. get_lines_for_level) directly on the logger
instance.
"""
with mock.patch('swift.common.utils.logs.LogAdapter', CaptureLogAdapter):
with mock.patch('swift.common.utils.logs.SwiftLogAdapter',
CaptureLogAdapter):
log_adapter = utils.logs.get_logger(conf, *args, **kwargs)
log_adapter.start_capture()
try:

6
test/probe/test_reconstructor_rebuild.py
View File

@ -426,7 +426,7 @@ class TestReconstructorRebuild(ECProbeTest):
reconstructor = self.run_custom_daemon(
ObjectReconstructor, 'object-reconstructor', conf_index,
{'quarantine_age': '0'})
logger = reconstructor.logger.logger
logger = reconstructor.logger
error_lines.append(logger.get_lines_for_level('error'))
warning_lines.append(logger.get_lines_for_level('warning'))
@ -463,7 +463,7 @@ class TestReconstructorRebuild(ECProbeTest):
reconstructor = self.run_custom_daemon(
ObjectReconstructor, 'object-reconstructor', conf_index,
{'quarantine_age': '0', 'quarantine_threshold': '1'})
logger = reconstructor.logger.logger
logger = reconstructor.logger
error_lines.append(logger.get_lines_for_level('error'))
warning_lines.append(logger.get_lines_for_level('warning'))
@ -516,7 +516,7 @@ class TestReconstructorRebuild(ECProbeTest):
reconstructor = self.run_custom_daemon(
ObjectReconstructor, 'object-reconstructor', conf_index,
{'quarantine_age': '0', 'quarantine_threshold': '1'})
logger = reconstructor.logger.logger
logger = reconstructor.logger
error_lines.append(logger.get_lines_for_level('error'))
warning_lines.append(logger.get_lines_for_level('warning'))

2
test/unit/common/test_daemon.py
View File

@ -59,7 +59,7 @@ class TestDaemon(unittest.TestCase):
def test_create(self):
d = daemon.Daemon({})
self.assertEqual(d.conf, {})
self.assertIsInstance(d.logger, utils.LogAdapter)
self.assertIsInstance(d.logger, utils.logs.SwiftLogAdapter)
def test_stubs(self):
d = daemon.Daemon({})

8
test/unit/common/test_internal_client.py
View File

@ -25,8 +25,7 @@ from textwrap import dedent
import six
from six.moves import range, zip_longest
from six.moves.urllib.parse import quote, parse_qsl
from swift.common import exceptions, internal_client, request_helpers, swob, \
utils
from swift.common import exceptions, internal_client, request_helpers, swob
from swift.common.header_key_dict import HeaderKeyDict
from swift.common.storage_policy import StoragePolicy
from swift.common.middleware.proxy_logging import ProxyLoggingMiddleware
@ -528,8 +527,7 @@ class TestInternalClient(unittest.TestCase):
self.request_tries = 1
self.use_replication_network = False
fake_logger = debug_logger()
logger = utils.LogAdapter(fake_logger, 'test-server')
logger = debug_logger()
# Make sure there's no transaction ID set -- other tests may have
# polluted the logger
logger.txn_id = None
@ -538,7 +536,7 @@ class TestInternalClient(unittest.TestCase):
client.make_request('GET', '/', {}, (200,))
logger.debug('After request')
self.assertEqual([(args[0], kwargs['extra'].get('txn_id'))
for args, kwargs in fake_logger.log_dict['debug']], [
for args, kwargs in logger.log_dict['debug']], [
('Before request', None),
('Inside of request', 'foo'),
('After request', None),

36
test/unit/common/test_statsd_client.py
View File

@ -819,3 +819,39 @@ class TestModuleFunctions(unittest.TestCase):
self.assertEqual(self.logger, client.logger)
warn_lines = self.logger.get_lines_for_level('warning')
self.assertEqual([], warn_lines)
class TestSwiftLogAdapterDelegation(unittest.TestCase):
def setUp(self):
self.logger = utils.get_logger({'log_statsd_host': 'some.host.com'},
'some-name', log_route='some-route')
self.mock_socket = MockUdpSocket()
self.logger.logger.statsd_client._open_socket = \
lambda *_: self.mock_socket
self.address = ('some.host.com', 8125)
def test_setup(self):
self.logger.increment('foo')
self.assertEqual(self.mock_socket.sent,
[(b'some-name.foo:1|c', self.address)])
def test_get_prefix_logger(self):
prefixed_logger = utils.get_prefixed_logger(self.logger, 'my-prefix')
prefixed_logger.increment('bar')
self.assertEqual(self.mock_socket.sent,
[(b'some-name.bar:1|c', self.address)])
def test_adapted_logger(self):
adapted_logger = utils.logs.SwiftLogAdapter(
self.logger.logger, 'my-adapter')
adapted_logger.increment('buz')
self.assertEqual(self.mock_socket.sent,
[(b'some-name.buz:1|c', self.address)])
def test_wrapped_adapter(self):
wrapped_adapter = utils.logs.SwiftLogAdapter(
self.logger, 'wrapped-adapter')
with self.assertRaises(AttributeError) as ctx:
wrapped_adapter.increment('baz')
self.assertIn("has no attribute 'statsd_client'", str(ctx.exception))

246
test/unit/common/utils/test_logs.py
View File

@ -47,7 +47,8 @@ else:
from swift.common import utils
from swift.common.swob import Request, Response
from swift.common.utils.logs import SwiftLogFormatter
from swift.common.utils.logs import SwiftLogFormatter, SwiftLogAdapter, \
get_prefixed_logger
def reset_loggers():
@ -434,6 +435,38 @@ class TestUtilsLogs(unittest.TestCase):
}, 'server', log_route='server')
self.assertEqual(errno.EPERM, cm.exception.errno)
def test_get_logger_custom_log_handlers(self):
def custom_log_handler(conf, name, log_to_console, log_route, fmt,
logger, adapted_logger):
adapted_logger.server = adapted_logger.server.upper()
sio = StringIO()
logger = logging.getLogger('my_logger_name')
handler = logging.StreamHandler(sio)
logger.addHandler(handler)
formatter = logging.Formatter('%(levelname)s: %(server)s %(message)s')
handler.setFormatter(formatter)
# sanity check...
conf = {}
adapted_logger = utils.get_logger(
conf, 'my_server', log_route='my_logger_name')
adapted_logger.warning('test')
self.assertEqual(sio.getvalue(),
'WARNING: my_server test\n')
# custom log handler...
sio = StringIO()
handler.stream = sio
patch_target = 'test.unit.common.utils.custom_log_handler'
conf = {'log_custom_handlers': patch_target}
with mock.patch(patch_target, custom_log_handler, create=True):
adapted_logger = utils.get_logger(
conf, 'my_server', log_route='my_logger_name')
adapted_logger.warning('test')
self.assertEqual(sio.getvalue(),
'WARNING: MY_SERVER test\n')
@reset_logger_state
def test_clean_logger_exception(self):
# setup stream logging
@ -695,14 +728,13 @@ class TestUtilsLogs(unittest.TestCase):
logger.logger.removeHandler(handler)
@reset_logger_state
def test_prefixlogger(self):
def test_get_prefixed_logger(self):
# setup stream logging
sio = StringIO()
base_logger = utils.get_logger(None)
handler = logging.StreamHandler(sio)
base_logger.logger.addHandler(handler)
logger = utils.PrefixLoggerAdapter(base_logger, {})
logger.set_prefix('some prefix: ')
logger = get_prefixed_logger(base_logger, 'some prefix: ')
def strip_value(sio):
sio.seek(0)
@ -745,16 +777,54 @@ class TestUtilsLogs(unittest.TestCase):
base_logger.logger.removeHandler(handler)
@reset_logger_state
def test_nested_prefixlogger(self):
def test_get_prefixed_logger_non_string_values(self):
# setup stream logging
sio = StringIO()
base_logger = utils.get_logger(None)
handler = logging.StreamHandler(sio)
base_logger.logger.addHandler(handler)
inner_logger = utils.PrefixLoggerAdapter(base_logger, {})
inner_logger.set_prefix('one: ')
outer_logger = utils.PrefixLoggerAdapter(inner_logger, {})
outer_logger.set_prefix('two: ')
logger = get_prefixed_logger(base_logger, 'some prefix: ')
exc = Exception('blah')
def strip_value(sio):
sio.seek(0)
v = sio.getvalue()
sio.truncate(0)
return v
try:
logger = get_prefixed_logger(logger, 'abc')
self.assertEqual('abc', logger.prefix)
logger.info('test')
self.assertEqual(strip_value(sio), 'abctest\n')
logger.info(exc)
self.assertEqual(strip_value(sio), 'abcblah\n')
logger = get_prefixed_logger(logger, '')
self.assertEqual('', logger.prefix)
logger.info('test')
self.assertEqual(strip_value(sio), 'test\n')
logger.info(exc)
self.assertEqual(strip_value(sio), 'blah\n')
logger = get_prefixed_logger(logger, 0)
self.assertEqual(0, logger.prefix)
logger.info('test')
self.assertEqual(strip_value(sio), '0test\n')
logger.info(exc)
self.assertEqual(strip_value(sio), '0blah\n')
finally:
logger.logger.removeHandler(handler)
@reset_logger_state
def test_get_prefixed_logger_replaces_prefix(self):
# setup stream logging
sio = StringIO()
base_logger = utils.get_logger(None)
handler = logging.StreamHandler(sio)
base_logger.logger.addHandler(handler)
logger1 = get_prefixed_logger(base_logger, 'one: ')
logger2 = get_prefixed_logger(logger1, 'two: ')
def strip_value(sio):
sio.seek(0)
@ -763,17 +833,54 @@ class TestUtilsLogs(unittest.TestCase):
return v
try:
# establish base case
self.assertEqual(strip_value(sio), '')
inner_logger.info('test')
base_logger.info('test')
self.assertEqual(strip_value(sio), 'test\n')
self.assertEqual(strip_value(sio), '')
logger1.info('test')
self.assertEqual(strip_value(sio), 'one: test\n')
outer_logger.info('test')
self.assertEqual(strip_value(sio), 'one: two: test\n')
self.assertEqual(strip_value(sio), '')
logger2.info('test')
self.assertEqual(strip_value(sio), 'two: test\n')
finally:
base_logger.logger.removeHandler(handler)
def test_get_prefixed_logger_isolation(self):
# verify that the new instance's attributes are copied by value
# from the old (except prefix), but the thread_locals are still shared
adapted_logger = utils.get_logger(None, name='server')
adapted_logger.thread_locals = ('id', 'ip')
adapted_logger = get_prefixed_logger(adapted_logger, 'foo')
self.assertEqual(adapted_logger.server, 'server')
self.assertEqual(adapted_logger.thread_locals, ('id', 'ip'))
self.assertEqual(adapted_logger.prefix, 'foo')
cloned_adapted_logger = get_prefixed_logger(
adapted_logger, 'boo')
self.assertEqual(cloned_adapted_logger.server, 'server')
self.assertEqual(cloned_adapted_logger.thread_locals, ('id', 'ip'))
self.assertEqual(cloned_adapted_logger.txn_id, 'id')
self.assertEqual(cloned_adapted_logger.client_ip, 'ip')
self.assertEqual(adapted_logger.thread_locals, ('id', 'ip'))
self.assertEqual(cloned_adapted_logger.prefix, 'boo')
self.assertEqual(adapted_logger.prefix, 'foo')
self.assertIs(adapted_logger.logger, cloned_adapted_logger.logger)
cloned_adapted_logger = get_prefixed_logger(
adapted_logger, adapted_logger.prefix + 'bar')
adapted_logger.server = 'waiter'
self.assertEqual(adapted_logger.server, 'waiter')
self.assertEqual(cloned_adapted_logger.server, 'server')
self.assertEqual(adapted_logger.prefix, 'foo')
self.assertEqual(cloned_adapted_logger.prefix, 'foobar')
adapted_logger.thread_locals = ('x', 'y')
self.assertEqual(adapted_logger.thread_locals, ('x', 'y'))
self.assertEqual(cloned_adapted_logger.thread_locals, ('x', 'y'))
self.assertIs(adapted_logger.logger, cloned_adapted_logger.logger)
@reset_logger_state
def test_capture_stdio(self):
# stubs
@ -1002,46 +1109,113 @@ class TestUtilsLogs(unittest.TestCase):
'md5', '54LT'))
class TestSwiftLoggerAdapter(unittest.TestCase):
class TestSwiftLogAdapter(unittest.TestCase):
def setUp(self):
self.core_logger = logging.getLogger('test')
self.core_logger.setLevel(logging.INFO)
self.sio = StringIO()
self.handler = logging.StreamHandler(self.sio)
self.core_logger.addHandler(self.handler)
def tearDown(self):
self.core_logger.removeHandler(self.handler)
def read_sio(self):
self.sio.seek(0)
v = self.sio.getvalue()
self.sio.truncate(0)
return v
def test_init(self):
adapter = SwiftLogAdapter(self.core_logger, 'my-server')
self.assertIs(self.core_logger, adapter.logger)
self.assertEqual('my-server', adapter.server)
self.assertEqual('', adapter.prefix)
adapter.info('hello')
self.assertEqual('hello\n', self.read_sio())
def test_init_with_prefix(self):
adapter = SwiftLogAdapter(self.core_logger, 'my-server', 'my-prefix: ')
self.assertIs(self.core_logger, adapter.logger)
self.assertEqual('my-server', adapter.server)
self.assertEqual('my-prefix: ', adapter.prefix)
adapter.info('hello')
self.assertEqual('my-prefix: hello\n', self.read_sio())
def test_formatter_extras(self):
formatter = logging.Formatter(
'%(levelname)s: %(server)s %(message)s %(txn_id)s %(client_ip)s')
self.handler.setFormatter(formatter)
adapter = SwiftLogAdapter(self.core_logger, 'my-server')
adapter.txn_id = 'my-txn-id'
adapter.client_ip = '1.2.3.4'
adapter.info('hello')
self.assertEqual('INFO: my-server hello my-txn-id 1.2.3.4\n',
self.read_sio())
@reset_logger_state
def test_thread_locals(self):
logger = utils.get_logger({}, 'foo')
adapter1 = utils.SwiftLoggerAdapter(logger, {})
adapter2 = utils.SwiftLoggerAdapter(logger, {})
adapter1 = SwiftLogAdapter(self.core_logger, 'foo')
adapter2 = SwiftLogAdapter(self.core_logger, 'foo')
locals1 = ('tx_123', '1.2.3.4')
adapter1.thread_locals = locals1
self.assertEqual(adapter1.thread_locals, locals1)
self.assertEqual(adapter2.thread_locals, locals1)
self.assertEqual(logger.thread_locals, locals1)
locals2 = ('tx_456', '1.2.3.456')
logger.thread_locals = locals2
adapter2.thread_locals = locals2
self.assertEqual(adapter1.thread_locals, locals2)
self.assertEqual(adapter2.thread_locals, locals2)
self.assertEqual(logger.thread_locals, locals2)
logger.thread_locals = (None, None)
adapter1.thread_locals = (None, None)
self.assertEqual(adapter1.thread_locals, (None, None))
self.assertEqual(adapter2.thread_locals, (None, None))
adapter1.txn_id = '5678'
self.assertEqual('5678', adapter1.txn_id)
self.assertEqual('5678', adapter2.txn_id)
self.assertIsNone(adapter1.client_ip)
self.assertIsNone(adapter2.client_ip)
self.assertEqual(('5678', None), adapter1.thread_locals)
self.assertEqual(('5678', None), adapter2.thread_locals)
adapter1.client_ip = '5.6.7.8'
self.assertEqual('5678', adapter1.txn_id)
self.assertEqual('5678', adapter2.txn_id)
self.assertEqual('5.6.7.8', adapter1.client_ip)
self.assertEqual('5.6.7.8', adapter2.client_ip)
self.assertEqual(('5678', '5.6.7.8'), adapter1.thread_locals)
self.assertEqual(('5678', '5.6.7.8'), adapter2.thread_locals)
@reset_logger_state
def test_thread_locals_more(self):
logger = utils.get_logger(None)
def test_thread_locals_stacked_adapter(self):
adapter1 = SwiftLogAdapter(self.core_logger, 'foo')
# adapter2 is stacked on adapter1
adapter2 = SwiftLogAdapter(adapter1, 'foo')
self.assertIs(adapter1, adapter2.logger)
# test the setter
logger.thread_locals = ('id', 'ip')
self.assertEqual(logger.thread_locals, ('id', 'ip'))
adapter1.thread_locals = ('id', 'ip')
self.assertEqual(adapter1.thread_locals, ('id', 'ip'))
self.assertEqual(adapter2.thread_locals, ('id', 'ip'))
# reset
logger.thread_locals = (None, None)
self.assertEqual(logger.thread_locals, (None, None))
logger.txn_id = '1234'
logger.client_ip = '1.2.3.4'
self.assertEqual(logger.thread_locals, ('1234', '1.2.3.4'))
logger.txn_id = '5678'
logger.client_ip = '5.6.7.8'
self.assertEqual(logger.thread_locals, ('5678', '5.6.7.8'))
adapter1.thread_locals = (None, None)
self.assertEqual(adapter1.thread_locals, (None, None))
self.assertEqual(adapter2.thread_locals, (None, None))
adapter1.txn_id = '1234'
adapter1.client_ip = '1.2.3.4'
self.assertEqual(adapter1.thread_locals, ('1234', '1.2.3.4'))
self.assertEqual(adapter2.thread_locals, ('1234', '1.2.3.4'))
adapter2.txn_id = '5678'
adapter2.client_ip = '5.6.7.8'
self.assertEqual(adapter1.thread_locals, ('5678', '5.6.7.8'))
self.assertEqual(adapter2.thread_locals, ('5678', '5.6.7.8'))
def test_exception(self):
# verify that the adapter routes exception calls to utils.LogAdapter
# verify that the adapter routes exception calls to SwiftLogAdapter
# for special case handling
logger = utils.get_logger({})
adapter = utils.SwiftLoggerAdapter(logger, {})
adapter = SwiftLogAdapter(self.core_logger, 'foo')
try:
raise OSError(errno.ECONNREFUSED, 'oserror')
except OSError:

17
test/unit/obj/test_auditor.py
View File

@ -41,7 +41,8 @@ from swift.obj.diskfile import (
get_auditor_status, HASH_FILE, HASH_INVALIDATIONS_FILE)
from swift.common.exceptions import ClientException
from swift.common.utils import (
mkdirs, normalize_timestamp, Timestamp, readconf, md5, PrefixLoggerAdapter)
mkdirs, normalize_timestamp, Timestamp, readconf, md5)
from swift.common.utils.logs import SwiftLogAdapter
from swift.common.storage_policy import (
ECStoragePolicy, StoragePolicy, POLICIES, EC_POLICY)
@ -1696,8 +1697,13 @@ class TestAuditWatchers(TestAuditorBase):
self.assertEqual(len(calls), 6)
self.assertEqual(calls[0], ["__init__", conf, mock.ANY])
self.assertIsInstance(calls[0][2], PrefixLoggerAdapter)
self.assertIs(calls[0][2].logger, self.logger)
watcher_logger = calls[0][2]
self.assertIsInstance(calls[0][2], SwiftLogAdapter)
self.assertIs(calls[0][2].logger, self.logger.logger)
self.assertEqual(watcher_logger.server, my_auditor.logger.server)
self.assertEqual('', my_auditor.logger.prefix) # sanity check
self.assertEqual('[audit-watcher test_watcher1] ',
watcher_logger.prefix)
self.assertEqual(calls[1], ["start", "ZBF"])
@ -1731,10 +1737,15 @@ class TestAuditWatchers(TestAuditorBase):
self.assertEqual(calls[5], ["end"])
# check that watcher has not mutated the prefix of the auditor logger
my_auditor.logger.debug('the auditor has no logger prefix')
log_lines = self.logger.get_lines_for_level('debug')
self.assertIn(
"[audit-watcher test_watcher1] getting started",
log_lines)
self.assertIn(
"the auditor has no logger prefix",
log_lines)
def test_builtin_watchers(self):