openstack/swift
Code Issues Proposed changes

Remove PrefixLoggerAdapter and SwiftLoggerAdapter

Browse Source 
In order to modernize swift's statsd configuration we're working to
separate it from logging. This change is a pre-requisite for the
Related-Change in order to simplfy the stdlib base logger instance
wrapping in a single extended SwiftLogAdapter (previously LogAdapter)
which supports all the features swift's servers/daemons need
from our logger instance interface.

Related-Change-Id: I44694b92264066ca427bb96456d6f944e09b31c0

Change-Id: I8988c0add6bb4a65cc8be38f0bf527f141aac48a
This commit is contained in:
Shreeya Deshpande 2024-10-01 16:14:09 -04:00
parent 288677695d
commit f88efdb4df
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):