From f88efdb4df37577c687f68b2cc3712465955c20e Mon Sep 17 00:00:00 2001 From: Shreeya Deshpande Date: Tue, 1 Oct 2024 16:14:09 -0400 Subject: [PATCH] Remove PrefixLoggerAdapter and SwiftLoggerAdapter 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 --- doc/source/admin_guide.rst | 12 +- swift/cli/relinker.py | 28 ++- swift/common/utils/__init__.py | 4 +- swift/common/utils/logs.py | 97 +++------ swift/obj/auditor.py | 11 +- swift/obj/reconstructor.py | 22 +- swift/obj/replicator.py | 24 ++- test/debug_logger.py | 7 +- test/probe/test_reconstructor_rebuild.py | 6 +- test/unit/common/test_daemon.py | 2 +- test/unit/common/test_internal_client.py | 8 +- test/unit/common/test_statsd_client.py | 36 ++++ test/unit/common/utils/test_logs.py | 246 +++++++++++++++++++---- test/unit/obj/test_auditor.py | 17 +- 14 files changed, 357 insertions(+), 163 deletions(-) diff --git a/doc/source/admin_guide.rst b/doc/source/admin_guide.rst index c87d7edffa..dab57e64ec 100644 --- a/doc/source/admin_guide.rst +++ b/doc/source/admin_guide.rst @@ -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: diff --git a/swift/cli/relinker.py b/swift/cli/relinker.py index ec02e47901..e47334091f 100644 --- a/swift/cli/relinker.py +++ b/swift/cli/relinker.py @@ -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'), diff --git a/swift/common/utils/__init__.py b/swift/common/utils/__init__.py index 2cd5dde281..8f1e070c4e 100644 --- a/swift/common/utils/__init__.py +++ b/swift/common/utils/__init__.py @@ -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, diff --git a/swift/common/utils/logs.py b/swift/common/utils/logs.py index fb5bb5e092..0b1c938850 100644 --- a/swift/common/utils/logs.py +++ b/swift/common/utils/logs.py @@ -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.""" diff --git a/swift/obj/auditor.py b/swift/obj/auditor.py index a1ddefbe99..ab753c4f16 100644 --- a/swift/obj/auditor.py +++ b/swift/obj/auditor.py @@ -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) diff --git a/swift/obj/reconstructor.py b/swift/obj/reconstructor.py index 6e8dc0679b..95406387ad 100644 --- a/swift/obj/reconstructor.py +++ b/swift/obj/reconstructor.py @@ -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.""" diff --git a/swift/obj/replicator.py b/swift/obj/replicator.py index 29e397257e..07e2815f66 100644 --- a/swift/obj/replicator.py +++ b/swift/obj/replicator.py @@ -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): """ diff --git a/test/debug_logger.py b/test/debug_logger.py index fbf782131c..43f47064c7 100644 --- a/test/debug_logger.py +++ b/test/debug_logger.py @@ -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: diff --git a/test/probe/test_reconstructor_rebuild.py b/test/probe/test_reconstructor_rebuild.py index 4fc546f72a..a5e14ea398 100644 --- a/test/probe/test_reconstructor_rebuild.py +++ b/test/probe/test_reconstructor_rebuild.py @@ -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')) diff --git a/test/unit/common/test_daemon.py b/test/unit/common/test_daemon.py index ac65e279db..37085d292f 100644 --- a/test/unit/common/test_daemon.py +++ b/test/unit/common/test_daemon.py @@ -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({}) diff --git a/test/unit/common/test_internal_client.py b/test/unit/common/test_internal_client.py index f5580f0ed8..774edc6d86 100644 --- a/test/unit/common/test_internal_client.py +++ b/test/unit/common/test_internal_client.py @@ -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), diff --git a/test/unit/common/test_statsd_client.py b/test/unit/common/test_statsd_client.py index 73ea86d41f..457a455960 100644 --- a/test/unit/common/test_statsd_client.py +++ b/test/unit/common/test_statsd_client.py @@ -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)) diff --git a/test/unit/common/utils/test_logs.py b/test/unit/common/utils/test_logs.py index 48f844d0e3..032559934f 100644 --- a/test/unit/common/utils/test_logs.py +++ b/test/unit/common/utils/test_logs.py @@ -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: diff --git a/test/unit/obj/test_auditor.py b/test/unit/obj/test_auditor.py index aa9783c28b..69b1afd7e5 100644 --- a/test/unit/obj/test_auditor.py +++ b/test/unit/obj/test_auditor.py @@ -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):