Deprecate LogAdapter.set_statsd_prefix

Previously, the set_statsd_prefix method was used to mutate a logger's
StatsdClient tail prefix after a logger was instantiated. This pattern
had led to unexpected mutations (see Related-Change). The tail_prefix
can now be passed as an argument to get_logger(), and is then
forwarded to the StatsdClient constructor, for a more explicit
assignment pattern.

The set_statsd_prefix method is left in place for backwards
compatibility. A DeprecationWarning will be raised if it is used
to mutate the StatsdClient tail prefix.

Change-Id: I7692860e3b741e1bc10626e26bb7b27399c325ab
Related-Change: I0522b1953722ca96021a0002cf93432b973ce626

doc/source/admin/objectstorage-monitoring.rst

@@ -145,14 +145,6 @@ require accuracy (``sample_rate=1``) while others may not.
 Then the LogAdapter object returned by ``get_logger()``, usually stored
 in ``self.logger``, has these new methods:
 
--  ``set_statsd_prefix(self, prefix)`` Sets the client library stat
-   prefix value which gets prefixed to every meter. The default prefix
-   is the ``name`` of the logger such as ``object-server``,
-   ``container-auditor``, and so on. This is currently used to turn
-   ``proxy-server`` into one of ``proxy-server.Account``,
-   ``proxy-server.Container``, or ``proxy-server.Object`` as soon as the
-   Controller object is determined and instantiated for the request.
-
 -  ``update_stats(self, metric, amount, sample_rate=1)`` Increments
    the supplied meter by the given amount. This is used when you need
    to add or subtract more that one from a counter, like incrementing

swift/common/middleware/proxy_logging.py

@@ -133,8 +133,8 @@ class ProxyLoggingMiddleware(object):
                 access_log_conf[key] = value
         self.access_logger = logger or get_logger(
             access_log_conf,
-            log_route=conf.get('access_log_route', 'proxy-access'))
-        self.access_logger.set_statsd_prefix('proxy-server')
+            log_route=conf.get('access_log_route', 'proxy-access'),
+            statsd_tail_prefix='proxy-server')
         self.reveal_sensitive_prefix = int(
             conf.get('reveal_sensitive_prefix', 16))
         self.check_log_msg_template_validity()

swift/common/middleware/tempauth.py

@@ -209,13 +209,14 @@ class TempAuth(object):
     def __init__(self, app, conf):
         self.app = app
         self.conf = conf
-        self.logger = get_logger(conf, log_route='tempauth')
-        self.log_headers = config_true_value(conf.get('log_headers', 'f'))
         self.reseller_prefixes, self.account_rules = \
             config_read_reseller_options(conf, dict(require_group=''))
         self.reseller_prefix = self.reseller_prefixes[0]
-        self.logger.set_statsd_prefix('tempauth.%s' % (
-            self.reseller_prefix if self.reseller_prefix else 'NONE',))
+        statsd_tail_prefix = 'tempauth.%s' % (
+            self.reseller_prefix if self.reseller_prefix else 'NONE',)
+        self.logger = get_logger(conf, log_route='tempauth',
+                                 statsd_tail_prefix=statsd_tail_prefix)
+        self.log_headers = config_true_value(conf.get('log_headers', 'f'))
         self.auth_prefix = conf.get('auth_prefix', '/auth/')
         if not self.auth_prefix or not self.auth_prefix.strip('/'):
             self.logger.warning('Rewriting invalid auth prefix "%s" to '

swift/common/utils.py

@@ -1880,7 +1880,7 @@ class StatsdClient(object):
         self._host = host
         self._port = port
         self._base_prefix = base_prefix
-        self.set_prefix(tail_prefix)
+        self._set_prefix(tail_prefix)
         self._default_sample_rate = default_sample_rate
         self._sample_rate_factor = sample_rate_factor
         self.random = random
@@ -1921,16 +1921,45 @@ class StatsdClient(object):
         else:
             self._target = (host, port)
 
-    def set_prefix(self, new_prefix):
-        if new_prefix and self._base_prefix:
-            self._prefix = '.'.join([self._base_prefix, new_prefix, ''])
-        elif new_prefix:
-            self._prefix = new_prefix + '.'
+    def _set_prefix(self, tail_prefix):
+        """
+        Modifies the prefix that is added to metric names. The resulting prefix
+        is the concatenation of the component parts `base_prefix` and
+        `tail_prefix`. Only truthy components are included. Each included
+        component is followed by a period, e.g.::
+
+            <base_prefix>.<tail_prefix>.
+            <tail_prefix>.
+            <base_prefix>.
+            <the empty string>
+
+        Note: this method is expected to be called from the constructor only,
+        but exists to provide backwards compatible functionality for the
+        deprecated set_prefix() method.
+
+        :param tail_prefix: The new value of tail_prefix
+        """
+        if tail_prefix and self._base_prefix:
+            self._prefix = '.'.join([self._base_prefix, tail_prefix, ''])
+        elif tail_prefix:
+            self._prefix = tail_prefix + '.'
         elif self._base_prefix:
             self._prefix = self._base_prefix + '.'
         else:
             self._prefix = ''
 
+    def set_prefix(self, tail_prefix):
+        """
+        This method is deprecated; use the ``tail_prefix`` argument of the
+        constructor when instantiating the class instead.
+        """
+        warnings.warn(
+            'set_prefix() is deprecated; use the ``tail_prefix`` argument of '
+            'the constructor when instantiating the class instead.',
+            DeprecationWarning
+        )
+        self._set_prefix(tail_prefix)
+
     def _send(self, m_name, m_value, m_type, sample_rate):
         if sample_rate is None:
             sample_rate = self._default_sample_rate
@@ -2015,7 +2044,7 @@ def timing_stats(**dec_kwargs):
 class SwiftLoggerAdapter(logging.LoggerAdapter):
     """
     A logging.LoggerAdapter subclass that also passes through StatsD method
-    calls. Adds an optional metric_prefix to statsd metric names.
+    calls.
 
     Like logging.LoggerAdapter, you have to subclass this and override the
     process() method to accomplish anything useful.
@@ -2229,6 +2258,10 @@ class LogAdapter(logging.LoggerAdapter, object):
 
     def set_statsd_prefix(self, prefix):
         """
+        This method is deprecated. Callers should use the
+        ``statsd_tail_prefix`` argument of ``get_logger`` when instantiating a
+        logger.
+
         The StatsD client prefix defaults to the "name" of the logger.  This
         method may override that default with a specific value.  Currently used
         in the proxy-server to differentiate the Account, Container, and Object
@@ -2334,7 +2367,7 @@ class LogLevelFilter(object):
 
 
 def get_logger(conf, name=None, log_to_console=False, log_route=None,
-               fmt="%(server)s: %(message)s"):
+               fmt="%(server)s: %(message)s", statsd_tail_prefix=None):
     """
     Get the current system logger using config settings.
 
@@ -2365,6 +2398,8 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
                       is used as the name attribute of the
                       ``logging.LogAdapter`` that is returned.
     :param fmt: Override log format
+    :param statsd_tail_prefix: tail prefix to pass to statsd client; if None
+        then the tail prefix defaults to the value of ``name``.
     :return: an instance of ``LogAdapter``
     """
     # note: log_name is typically specified in conf (i.e. defined by
@@ -2443,8 +2478,10 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
             'log_statsd_default_sample_rate', 1))
         sample_rate_factor = float(conf.get(
             'log_statsd_sample_rate_factor', 1))
+        if statsd_tail_prefix is None:
+            statsd_tail_prefix = name
         statsd_client = StatsdClient(statsd_host, statsd_port, base_prefix,
-                                     name, default_sample_rate,
+                                     statsd_tail_prefix, default_sample_rate,
                                      sample_rate_factor, logger=logger)
         logger.statsd_client = statsd_client
     else:

swift/proxy/server.py

@@ -196,10 +196,10 @@ class Application(object):
         if conf is None:
             conf = {}
         if logger is None:
-            self.logger = get_logger(conf, log_route='proxy-server')
+            self.logger = get_logger(conf, log_route='proxy-server',
+                                     statsd_tail_prefix='proxy-server')
         else:
             self.logger = logger
-        self.logger.set_statsd_prefix('proxy-server')
         self._error_limiting = {}
 
         swift_dir = conf.get('swift_dir', '/etc/swift')

test/unit/common/middleware/test_proxy_logging.py

@@ -21,7 +21,7 @@ from logging.handlers import SysLogHandler
 import six
 from six.moves.urllib.parse import unquote
 
-from swift.common.utils import get_logger, split_path
+from swift.common.utils import get_logger, split_path, StatsdClient
 from swift.common.middleware import proxy_logging
 from swift.common.swob import Request, Response
 from swift.common import constraints
@@ -149,6 +149,26 @@ class TestProxyLogging(unittest.TestCase):
         self.assertEqual(got_metrics_values_and_kwargs,
                          exp_metrics_values_and_kwargs)
 
+    def test_logger_statsd_prefix(self):
+        app = proxy_logging.ProxyLoggingMiddleware(
+            FakeApp(), {'log_statsd_host': 'example.com'})
+        self.assertIsNotNone(app.access_logger.logger.statsd_client)
+        self.assertIsInstance(app.access_logger.logger.statsd_client,
+                              StatsdClient)
+        self.assertEqual('proxy-server.',
+                         app.access_logger.logger.statsd_client._prefix)
+
+        app = proxy_logging.ProxyLoggingMiddleware(
+            FakeApp(), {'log_statsd_metric_prefix': 'foo',  # set base prefix
+                        'access_log_name': 'bar',  # not used as tail prefix
+                        'log_name': 'baz',  # not used as tail prefix
+                        'log_statsd_host': 'example.com'})
+        self.assertIsNotNone(app.access_logger.logger.statsd_client)
+        self.assertIsInstance(app.access_logger.logger.statsd_client,
+                              StatsdClient)
+        self.assertEqual('foo.proxy-server.',
+                         app.access_logger.logger.statsd_client._prefix)
+
     def test_log_request_statsd_invalid_stats_types(self):
         app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
         app.access_logger = debug_logger()

test/unit/common/middleware/test_tempauth.py

@@ -24,7 +24,7 @@ from six.moves.urllib.parse import quote, urlparse
 from swift.common.middleware import tempauth as auth
 from swift.common.middleware.acl import format_acl
 from swift.common.swob import Request, Response
-from swift.common.utils import split_path
+from swift.common.utils import split_path, StatsdClient
 from test.unit import FakeMemcache
 
 NO_CONTENT_RESP = (('204 No Content', {}, ''),)   # mock server response
@@ -97,6 +97,34 @@ class TestAuth(unittest.TestCase):
         req.environ['swift.cache'] = FakeMemcache()
         return req
 
+    def test_statsd_prefix(self):
+        app = FakeApp()
+        ath = auth.filter_factory({'log_statsd_host': 'example.com'})(app)
+        self.assertIsNotNone(ath.logger.logger.statsd_client)
+        self.assertIsInstance(ath.logger.logger.statsd_client,
+                              StatsdClient)
+        self.assertEqual('tempauth.AUTH_.',
+                         ath.logger.logger.statsd_client._prefix)
+
+        ath = auth.filter_factory({'log_statsd_metric_prefix': 'foo',
+                                   'log_name': 'bar',
+                                   'log_statsd_host': 'example.com'})(app)
+        self.assertIsNotNone(ath.logger.logger.statsd_client)
+        self.assertIsInstance(ath.logger.logger.statsd_client,
+                              StatsdClient)
+        self.assertEqual('foo.tempauth.AUTH_.',
+                         ath.logger.logger.statsd_client._prefix)
+
+        ath = auth.filter_factory({'log_statsd_metric_prefix': 'foo',
+                                   'log_name': 'bar',
+                                   'log_statsd_host': 'example.com',
+                                   'reseller_prefix': 'TEST'})(app)
+        self.assertIsNotNone(ath.logger.logger.statsd_client)
+        self.assertIsInstance(ath.logger.logger.statsd_client,
+                              StatsdClient)
+        self.assertEqual('foo.tempauth.TEST_.',
+                         ath.logger.logger.statsd_client._prefix)
+
     def test_reseller_prefix_init(self):
         app = FakeApp()
         ath = auth.filter_factory({})(app)

test/unit/common/test_utils.py

@@ -5344,6 +5344,16 @@ class TestStatsdLogging(unittest.TestCase):
         self.assertEqual(logger.logger.statsd_client._prefix, 'some-name.')
         self.assertEqual(logger.logger.statsd_client._default_sample_rate, 1)
 
+        logger2 = utils.get_logger(
+            {'log_statsd_host': 'some.host.com'},
+            'other-name', log_route='some-route',
+            statsd_tail_prefix='some-name.more-specific')
+        self.assertEqual(logger.logger.statsd_client._prefix,
+                         'some-name.more-specific.')
+        self.assertEqual(logger2.logger.statsd_client._prefix,
+                         'some-name.more-specific.')
+
+        # note: set_statsd_prefix is deprecated
         logger2 = utils.get_logger({'log_statsd_host': 'some.host.com'},
                                    'other-name', log_route='some-route')
         logger.set_statsd_prefix('some-name.more-specific')
@@ -5356,15 +5366,23 @@ class TestStatsdLogging(unittest.TestCase):
         self.assertEqual(logger2.logger.statsd_client._prefix, '')
 
     def test_get_logger_statsd_client_non_defaults(self):
-        logger = utils.get_logger({
+        conf = {
             'log_statsd_host': 'another.host.com',
             'log_statsd_port': '9876',
             'log_statsd_default_sample_rate': '0.75',
             'log_statsd_sample_rate_factor': '0.81',
             'log_statsd_metric_prefix': 'tomato.sauce',
-        }, 'some-name', log_route='some-route')
+        }
+        logger = utils.get_logger(conf, 'some-name', log_route='some-route')
         self.assertEqual(logger.logger.statsd_client._prefix,
                          'tomato.sauce.some-name.')
+
+        logger = utils.get_logger(conf, 'other-name', log_route='some-route',
+                                  statsd_tail_prefix='some-name.more-specific')
+        self.assertEqual(logger.logger.statsd_client._prefix,
+                         'tomato.sauce.some-name.more-specific.')
+
+        # note: set_statsd_prefix is deprecated
         logger.set_statsd_prefix('some-name.more-specific')
         self.assertEqual(logger.logger.statsd_client._prefix,
                          'tomato.sauce.some-name.more-specific.')
@@ -5377,6 +5395,37 @@ class TestStatsdLogging(unittest.TestCase):
         self.assertEqual(logger.logger.statsd_client._sample_rate_factor,
                          0.81)
 
+    def test_statsd_set_prefix_deprecation(self):
+        conf = {'log_statsd_host': 'another.host.com'}
+
+        with warnings.catch_warnings(record=True) as cm:
+            warnings.resetwarnings()
+            warnings.simplefilter('always', DeprecationWarning)
+            logger = utils.get_logger(
+                conf, 'some-name', log_route='some-route')
+            logger.logger.statsd_client.set_prefix('some-name.more-specific')
+        msgs = [str(warning.message)
+                for warning in cm
+                if str(warning.message).startswith('set_prefix')]
+        self.assertEqual(
+            ['set_prefix() is deprecated; use the ``tail_prefix`` argument of '
+             'the constructor when instantiating the class instead.'],
+            msgs)
+
+        with warnings.catch_warnings(record=True) as cm:
+            warnings.resetwarnings()
+            warnings.simplefilter('always', DeprecationWarning)
+            logger = utils.get_logger(
+                conf, 'some-name', log_route='some-route')
+            logger.set_statsd_prefix('some-name.more-specific')
+        msgs = [str(warning.message)
+                for warning in cm
+                if str(warning.message).startswith('set_prefix')]
+        self.assertEqual(
+            ['set_prefix() is deprecated; use the ``tail_prefix`` argument of '
+             'the constructor when instantiating the class instead.'],
+            msgs)
+
     def test_ipv4_or_ipv6_hostname_defaults_to_ipv4(self):
         def stub_getaddrinfo_both_ipv4_and_ipv6(host, port, family, *rest):
             if family == socket.AF_INET:

test/unit/proxy/test_server.py

@@ -69,7 +69,7 @@ from swift.common.exceptions import ChunkReadTimeout, DiskFileNotExist, \
     APIVersionError, ChunkReadError
 from swift.common import utils, constraints, registry
 from swift.common.utils import hash_path, storage_directory, \
-    parse_content_type, parse_mime_headers, \
+    parse_content_type, parse_mime_headers, StatsdClient, \
     iter_multipart_mime_documents, public, mkdirs, NullLogger, md5
 from swift.common.wsgi import loadapp, ConfigString, SwiftHttpProtocol
 from swift.proxy.controllers import base as proxy_base
@@ -1336,11 +1336,25 @@ class TestProxyServer(unittest.TestCase):
                         path_parts.get('disallowed_sections'))
 
     def test_statsd_prefix(self):
-        app = proxy_server.Application({}, logger=debug_logger(),
+        app = proxy_server.Application({'log_statsd_host': 'example.com'},
                                        account_ring=FakeRing(),
                                        container_ring=FakeRing())
-        self.assertEqual([(('proxy-server',), {})],
-                         app.logger.log_dict['set_statsd_prefix'])
+        self.assertIsNotNone(app.logger.logger.statsd_client)
+        self.assertIsInstance(app.logger.logger.statsd_client,
+                              StatsdClient)
+        self.assertEqual('proxy-server.',
+                         app.logger.logger.statsd_client._prefix)
+
+        app = proxy_server.Application({'log_statsd_metric_prefix': 'foo',
+                                        'log_name': 'bar',
+                                        'log_statsd_host': 'example.com'},
+                                       account_ring=FakeRing(),
+                                       container_ring=FakeRing())
+        self.assertIsNotNone(app.logger.logger.statsd_client)
+        self.assertIsInstance(app.logger.logger.statsd_client,
+                              StatsdClient)
+        self.assertEqual('foo.proxy-server.',
+                         app.logger.logger.statsd_client._prefix)
 
 
 @patch_policies([
@@ -2147,7 +2161,7 @@ class TestProxyServerConfigLoading(unittest.TestCase):
         self.assertEqual('proxy-server', app.logger.name)
         self.assertEqual('swift', app.logger.server)
         mock_statsd.assert_called_once_with(
-            'example.com', 8125, '', 'swift', 1.0, 1.0,
+            'example.com', 8125, '', 'proxy-server', 1.0, 1.0,
             logger=app.logger.logger)
 
         conf_sections = """
@@ -2170,9 +2184,9 @@ class TestProxyServerConfigLoading(unittest.TestCase):
         self.assertEqual('proxy-server', app.logger.name)
         # server is defined by log_name option
         self.assertEqual('test-name', app.logger.server)
-        # statsd prefix is defined by log_name option
+        # statsd tail prefix is hard-wired 'proxy-server'
         mock_statsd.assert_called_once_with(
-            'example.com', 8125, '', 'test-name', 1.0, 1.0,
+            'example.com', 8125, '', 'proxy-server', 1.0, 1.0,
             logger=app.logger.logger)