openstack/swift
Code Issues Proposed changes

s3api: fix statsd prefix mutation

Browse Source 
The 'log_route' argument of utils.get_logger() determines which global
Logger instance is wrapped by the returned LogAdapter. Most middlewares
(s3api being the exception) explicity set 'log_route' to equal the
middleware 'brief' name e.g. 'bulk', 'tempauth' etc. However, the
s3api middleware sets 'log_route' to be the config 'log_name', if that
key is found in config.

When a proxy pipeline is instantiated via wsgi.run_wsgi(), all
middlewares and the proxy app are passed a default conf with
'"log_name": "proxy-server"'. As a result, the s3api middleware calls
get_logger() with log_route='proxy-server' and its LogAdapter
therefore shares the same Logger instance used by proxy-server app
(and any other middleware that similarly fails to explicitly
differentiate 'log_route)'.

Each Logger instance has a StatsdClient instance bound to it by
get_logger(). The Related-Change added statsd metrics to the s3api
middleware and sets 's3api' as the 'statsd_tail_prefix' when calling
get_logger(). This had the unintended effect of replacing the shared
Logger instance's StatsdClient with one that has prefix 's3api', such
that stats emitted by the proxy app (e.g. memcache shard range
hit/miss stats) would be erroneously prefixed with 's3api'.

This patch modifies the s3api middleware logger instantiation to
explictly set log_route='s3api', so that the s3api middleware
LogAdapter now wraps a unique global Logger instance, with a unique
StatsdClient instance bound to it.

The 'server' attribute of the middleware's LogAdapter, which may be
included in log lines by the "%(server)s" format element, is not
affected by this change. Its value is derived from the config
'log_name' or the 'name' argument passed to get_logger().

Change-Id: Ia89485bae8f92f4f3d9f5375cab8ff08f70a11a7
Related-Change: I4976b3ee24e4ec498c66359f391813261d42c495
This commit is contained in:
Alistair Coles 2023-07-18 15:00:25 +01:00
parent 7cc8a01729
commit bdbe8ce9f8
3 changed files with 105 additions and 4 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
swift/common/middleware/s3api/s3api.py
View File

@ -293,8 +293,7 @@ class S3ApiMiddleware(object):
wsgi_conf.get('ratelimit_as_client_error', False))
self.logger = get_logger(
wsgi_conf, log_route=wsgi_conf.get('log_name', 's3api'),
statsd_tail_prefix='s3api')
wsgi_conf, log_route='s3api', statsd_tail_prefix='s3api')
self.check_pipeline(wsgi_conf)
def is_s3_cors_preflight(self, env):

20
test/unit/common/middleware/s3api/test_s3api.py
View File

@ -32,7 +32,7 @@ from swift.common.middleware.s3api.utils import Config
from swift.common.middleware.keystoneauth import KeystoneAuth
from swift.common import swob, registry
from swift.common.swob import Request
from swift.common.utils import md5
from swift.common.utils import md5, get_logger
from keystonemiddleware.auth_token import AuthProtocol
from keystoneauth1.access import AccessInfoV2
@ -214,6 +214,24 @@ class TestS3ApiMiddleware(S3ApiTestCase):
loader.assert_called_with(loadwsgi.APP, 'proxy-conf-file')
pipeline.assert_called_with(context)
def test_init_logger(self):
proxy_logger = get_logger({}, log_route='proxy-server').logger
s3api = S3ApiMiddleware(None, {})
self.assertEqual('s3api', s3api.logger.name)
self.assertEqual('s3api', s3api.logger.logger.name)
self.assertIsNot(s3api.logger.logger, proxy_logger)
self.assertEqual('swift', s3api.logger.server)
self.assertIsNone(s3api.logger.logger.statsd_client)
s3api = S3ApiMiddleware(None, {'log_name': 'proxy-server',
'log_statsd_host': '1.2.3.4'})
self.assertEqual('s3api', s3api.logger.name)
self.assertEqual('s3api', s3api.logger.logger.name)
self.assertIsNot(s3api.logger.logger, proxy_logger)
self.assertEqual('proxy-server', s3api.logger.server)
self.assertEqual('s3api.', s3api.logger.logger.statsd_client._prefix)
def test_non_s3_request_passthrough(self):
req = Request.blank('/something')
status, headers, body = self.call_s3api(req)

86
test/unit/common/test_utils.py
View File

@ -73,7 +73,8 @@ from swift.common.exceptions import Timeout, MessageTimeout, \
ConnectionTimeout, LockTimeout, ReplicationLockTimeout, \
MimeInvalid
from swift.common import utils
from swift.common.utils import set_swift_dir, md5, ShardRangeList
from swift.common.utils import set_swift_dir, md5, ShardRangeList, \
SwiftLogFormatter
from swift.common.container_sync_realms import ContainerSyncRealms
from swift.common.header_key_dict import HeaderKeyDict
from swift.common.storage_policy import POLICIES, reload_storage_policies
@ -989,25 +990,108 @@ class TestUtils(unittest.TestCase):
'test1\ntest3\ntest4\ntest6\n')
def test_get_logger_name_and_route(self):
@contextlib.contextmanager
def add_log_handler(logger):
# install a handler to capture log messages formatted as per swift
sio = StringIO()
handler = logging.StreamHandler(sio)
handler.setFormatter(SwiftLogFormatter(
fmt="%(server)s: %(message)s", max_line_length=20)
)
logger.logger.addHandler(handler)
yield sio
logger.logger.removeHandler(handler)
logger = utils.get_logger({}, name='name', log_route='route')
# log_route becomes the LogAdapter.name and logging.Logger.name
self.assertEqual('route', logger.name)
self.assertEqual('route', logger.logger.name)
# name becomes the LogAdapter.server!
self.assertEqual('name', logger.server)
# LogAdapter.server is used when formatting a log message
with add_log_handler(logger) as sio:
logger.info('testing')
self.assertEqual('name: testing\n', sio.getvalue())
logger = utils.get_logger({'log_name': 'conf-name'}, name='name',
log_route='route')
self.assertEqual('route', logger.name)
self.assertEqual('name', logger.server)
with add_log_handler(logger) as sio:
logger.info('testing')
self.assertEqual('name: testing\n', sio.getvalue())
logger = utils.get_logger({'log_name': 'conf-name'}, log_route='route')
self.assertEqual('route', logger.name)
self.assertEqual('conf-name', logger.server)
with add_log_handler(logger) as sio:
logger.info('testing')
self.assertEqual('conf-name: testing\n', sio.getvalue())
logger = utils.get_logger({'log_name': 'conf-name'})
self.assertEqual('conf-name', logger.name)
self.assertEqual('conf-name', logger.server)
with add_log_handler(logger) as sio:
logger.info('testing')
self.assertEqual('conf-name: testing\n', sio.getvalue())
logger = utils.get_logger({})
self.assertEqual('swift', logger.name)
self.assertEqual('swift', logger.server)
with add_log_handler(logger) as sio:
logger.info('testing')
self.assertEqual('swift: testing\n', sio.getvalue())
logger = utils.get_logger({}, log_route='route')
self.assertEqual('route', logger.name)
self.assertEqual('swift', logger.server)
with add_log_handler(logger) as sio:
logger.info('testing')
self.assertEqual('swift: testing\n', sio.getvalue())
# same log_route, different names...
logger1 = utils.get_logger({'log_statsd_host': '1.2.3.4'},
name='name1', log_route='route')
logger2 = utils.get_logger({'log_statsd_host': '1.2.3.5'},
name='name2', log_route='route')
self.assertEqual('route', logger1.name)
self.assertEqual('route', logger1.logger.name)
self.assertEqual('name1', logger1.server)
# oh dear, the statsd client on the common logging.Logger instance got
# mutated when logger2 was created
self.assertEqual('name2.', logger1.logger.statsd_client._prefix)
self.assertEqual('route', logger2.name)
self.assertEqual('route', logger2.logger.name)
self.assertEqual('name2', logger2.server)
self.assertEqual('name2.', logger2.logger.statsd_client._prefix)
self.assertIs(logger2.logger, logger1.logger)
with add_log_handler(logger1) as sio:
logger1.info('testing')
self.assertEqual('name1: testing\n', sio.getvalue())
with add_log_handler(logger2) as sio:
logger2.info('testing')
self.assertEqual('name2: testing\n', sio.getvalue())
# different log_route, different names...
logger1 = utils.get_logger({'log_statsd_host': '1.2.3.4'},
name='name1', log_route='route1')
logger2 = utils.get_logger({'log_statsd_host': '1.2.3.5'},
name='name2', log_route='route2')
self.assertEqual('route1', logger1.name)
self.assertEqual('route1', logger1.logger.name)
self.assertEqual('name1', logger1.server)
self.assertEqual('name1.', logger1.logger.statsd_client._prefix)
self.assertEqual('route2', logger2.name)
self.assertEqual('route2', logger2.logger.name)
self.assertEqual('name2', logger2.server)
self.assertEqual('name2.', logger2.logger.statsd_client._prefix)
self.assertIsNot(logger2.logger, logger1.logger)
with add_log_handler(logger1) as sio:
logger1.info('testing')
self.assertEqual('name1: testing\n', sio.getvalue())
with add_log_handler(logger2) as sio:
logger2.info('testing')
self.assertEqual('name2: testing\n', sio.getvalue())
@with_tempdir
def test_get_logger_sysloghandler_plumbing(self, tempdir):