Modify log_name in internal clients' pipeline configs

Modify the 'log_name' option in the InternalClient wsgi config for the
following services: container-sharder, container-reconciler,
container-deleter, container-sync and object-expirer.

Previously the 'log_name' value for all internal client instances
sharing a single internal-client.conf file took the value configured
in the conf file, or would default to 'swift'. This resulted in no
distinction between logs from each internal client, and no association
with the service using a particular internal client.

With this change the 'log_name' value will typically be <log_route>-ic
where <log_route> is the service's conf file section name. For
example, 'container-sharder-ic'.

Note: any 'log_name' value configured in an internal client conf file
will now be ignored for these services unless the option key is
preceded by 'set'.

Note: by default, the logger's StatdsClient uses the log_name as its
tail_prefix when composing metrics' names. However, the proxy-logging
middleware overrides the tail_prefix with the hard-coded value
'proxy-server'. This change to log_name therefore does not change the
statsd metric names emitted by the internal client's proxy-logging.

This patch does not change the logging of the services themselves,
just their internal clients.

Change-Id: I844381fb9e1f3462043d27eb93e3fa188b206d05
Related-Change: Ida39ec7eb02a93cf4b2aa68fc07b7f0ae27b5439

etc/internal-client.conf-sample

@@ -2,7 +2,9 @@
 # swift_dir = /etc/swift
 # user = swift
 # You can specify default log routing here if you want:
-# log_name = swift
+# Note: the 'set' syntax is necessary to override the log_name that some
+# daemons specify when instantiating an internal client.
+# set log_name = swift
 # log_facility = LOG_LOCAL0
 # log_level = INFO
 # log_address = /dev/log

swift/cli/container_deleter.py

@@ -133,7 +133,7 @@ def mark_for_deletion(swift, account, container, marker, end_marker,
         return enqueue_deletes()
 
 
-def main():
+def main(args=None):
     parser = argparse.ArgumentParser(
         description=__doc__,
         formatter_class=argparse.RawTextHelpFormatter)
@@ -156,10 +156,11 @@ def main():
     parser.add_argument(
         '--timestamp', type=Timestamp, default=Timestamp.now(),
         help='delete all objects as of this time (default: now)')
-    args = parser.parse_args()
+    args = parser.parse_args(args)
 
     swift = InternalClient(
-        args.config, 'Swift Container Deleter', args.request_tries)
+        args.config, 'Swift Container Deleter', args.request_tries,
+        global_conf={'log_name': 'container-deleter-ic'})
     for deleted, marker in mark_for_deletion(
             swift, args.account, args.container,
             args.marker, args.end_marker, args.prefix, args.timestamp):

swift/common/utils.py

@@ -2387,11 +2387,18 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
         log_statsd_metric_prefix = (empty-string)
 
     :param conf: Configuration dict to read settings from
-    :param name: Name of the logger
+    :param name: This value is used to populate the ``server`` field in the log
+                 format, as the prefix for statsd messages, and as the default
+                 value for ``log_route``; defaults to the ``log_name`` value in
+                 ``conf``, if it exists, or to 'swift'.
     :param log_to_console: Add handler which writes to console on stderr
     :param log_route: Route for the logging, not emitted to the log, just used
-                      to separate logging configurations
+                      to separate logging configurations; defaults to the value
+                      of ``name`` or whatever ``name`` defaults to. This value
+                      is used as the name attribute of the
+                      ``logging.LogAdapter`` that is returned.
     :param fmt: Override log format
+    :return: an instance of ``LogAdapter``
     """
     if not conf:
         conf = {}

swift/container/reconciler.py

@@ -361,6 +361,7 @@ class ContainerReconciler(Daemon):
     """
     Move objects that are in the wrong storage policy.
     """
+    log_route = 'container-reconciler'
 
     def __init__(self, conf, logger=None, swift=None):
         self.conf = conf
@@ -372,13 +373,15 @@ class ContainerReconciler(Daemon):
         conf_path = conf.get('__file__') or \
             '/etc/swift/container-reconciler.conf'
         self.logger = logger or get_logger(
-            conf, log_route='container-reconciler')
+            conf, log_route=self.log_route)
         request_tries = int(conf.get('request_tries') or 3)
         self.swift = swift or InternalClient(
             conf_path,
             'Swift Container Reconciler',
             request_tries,
-            use_replication_network=True)
+            use_replication_network=True,
+            global_conf={'log_name': '%s-ic' % conf.get(
+                'log_name', self.log_route)})
         self.swift_dir = conf.get('swift_dir', '/etc/swift')
         self.stats = defaultdict(int)
         self.last_stat_time = time.time()

swift/container/sharder.py

@@ -665,9 +665,10 @@ DEFAULT_SHARDER_CONF = vars(ContainerSharderConf())
 
 class ContainerSharder(ContainerSharderConf, ContainerReplicator):
     """Shards containers."""
+    log_route = 'container-sharder'
 
     def __init__(self, conf, logger=None):
-        logger = logger or get_logger(conf, log_route='container-sharder')
+        logger = logger or get_logger(conf, log_route=self.log_route)
         ContainerReplicator.__init__(self, conf, logger=logger)
         ContainerSharderConf.__init__(self, conf)
         ContainerSharderConf.validate_conf(self)
@@ -716,7 +717,9 @@ class ContainerSharder(ContainerSharderConf, ContainerReplicator):
                 'Swift Container Sharder',
                 request_tries,
                 allow_modify_pipeline=False,
-                use_replication_network=True)
+                use_replication_network=True,
+                global_conf={'log_name': '%s-ic' % conf.get(
+                    'log_name', self.log_route)})
         except (OSError, IOError) as err:
             if err.errno != errno.ENOENT and \
                     not str(err).endswith(' not found'):

swift/container/sync.py

@@ -156,13 +156,14 @@ class ContainerSync(Daemon):
     :param container_ring: If None, the <swift_dir>/container.ring.gz will be
                            loaded. This is overridden by unit tests.
     """
+    log_route = 'container-sync'
 
     def __init__(self, conf, container_ring=None, logger=None):
         #: The dict of configuration values from the [container-sync] section
         #: of the container-server.conf.
         self.conf = conf
         #: Logger to use for container-sync log lines.
-        self.logger = logger or get_logger(conf, log_route='container-sync')
+        self.logger = logger or get_logger(conf, log_route=self.log_route)
         #: Path to the local device mount points.
         self.devices = conf.get('devices', '/srv/node')
         #: Indicates whether mount points should be verified as actual mount
@@ -241,7 +242,9 @@ class ContainerSync(Daemon):
         try:
             self.swift = InternalClient(
                 internal_client_conf, 'Swift Container Sync', request_tries,
-                use_replication_network=True)
+                use_replication_network=True,
+                global_conf={'log_name': '%s-ic' % conf.get(
+                    'log_name', self.log_route)})
         except (OSError, IOError) as err:
             if err.errno != errno.ENOENT and \
                     not str(err).endswith(' not found'):

swift/obj/expirer.py

@@ -73,10 +73,11 @@ class ObjectExpirer(Daemon):
 
     :param conf: The daemon configuration.
     """
+    log_route = 'object-expirer'
 
     def __init__(self, conf, logger=None, swift=None):
         self.conf = conf
-        self.logger = logger or get_logger(conf, log_route='object-expirer')
+        self.logger = logger or get_logger(conf, log_route=self.log_route)
         self.interval = float(conf.get('interval') or 300)
         self.tasks_per_second = float(conf.get('tasks_per_second', 50.0))
 
@@ -135,7 +136,9 @@ class ObjectExpirer(Daemon):
         request_tries = int(self.conf.get('request_tries') or 3)
         self.swift = swift or InternalClient(
             self.ic_conf_path, 'Swift Object Expirer', request_tries,
-            use_replication_network=True)
+            use_replication_network=True,
+            global_conf={'log_name': '%s-ic' % self.conf.get(
+                'log_name', self.log_route)})
 
         self.processes = int(self.conf.get('processes', 0))
         self.process = int(self.conf.get('process', 0))

test/unit/cli/test_container_deleter.py

@@ -276,3 +276,13 @@ class TestContainerDeleter(unittest.TestCase):
                     utils.Timestamp(ts)
                 )
             )
+
+    def test_init_internal_client_log_name(self):
+        with mock.patch(
+                'swift.cli.container_deleter.InternalClient') \
+                as mock_ic:
+            container_deleter.main(['a', 'c', '--request-tries', '2'])
+        mock_ic.assert_called_once_with(
+            '/etc/swift/internal-client.conf',
+            'Swift Container Deleter', 2,
+            global_conf={'log_name': 'container-deleter-ic'})

test/unit/common/test_internal_client.py

@@ -281,6 +281,103 @@ class TestInternalClient(unittest.TestCase):
                              object_ring_path)
             self.assertEqual(client.auto_create_account_prefix, '-')
 
+    @mock.patch('swift.common.utils.HASH_PATH_SUFFIX', new=b'endcap')
+    @with_tempdir
+    def test_load_from_config_with_global_conf(self, tempdir):
+        account_ring_path = os.path.join(tempdir, 'account.ring.gz')
+        write_fake_ring(account_ring_path)
+        container_ring_path = os.path.join(tempdir, 'container.ring.gz')
+        write_fake_ring(container_ring_path)
+        object_ring_path = os.path.join(tempdir, 'object.ring.gz')
+        write_fake_ring(object_ring_path)
+
+        # global_conf will override the 'x = y' syntax in conf file...
+        conf_path = os.path.join(tempdir, 'internal_client.conf')
+        conf_body = """
+        [DEFAULT]
+        swift_dir = %s
+        log_name = conf-file-log-name
+
+        [pipeline:main]
+        pipeline = catch_errors cache proxy-server
+
+        [app:proxy-server]
+        use = egg:swift#proxy
+        auto_create_account_prefix = -
+
+        [filter:cache]
+        use = egg:swift#memcache
+
+        [filter:catch_errors]
+        use = egg:swift#catch_errors
+        log_name = catch-errors-log-name
+        """ % tempdir
+        with open(conf_path, 'w') as f:
+            f.write(dedent(conf_body))
+        global_conf = {'log_name': 'global-conf-log-name'}
+        with patch_policies([StoragePolicy(0, 'legacy', True)]):
+            client = internal_client.InternalClient(
+                conf_path, 'test', 1, global_conf=global_conf)
+        self.assertEqual('global-conf-log-name', client.app.logger.server)
+
+        # ...but the 'set x = y' syntax in conf file DEFAULT section will
+        # override global_conf
+        conf_body = """
+        [DEFAULT]
+        swift_dir = %s
+        set log_name = conf-file-log-name
+
+        [pipeline:main]
+        pipeline = catch_errors cache proxy-server
+
+        [app:proxy-server]
+        use = egg:swift#proxy
+        auto_create_account_prefix = -
+
+        [filter:cache]
+        use = egg:swift#memcache
+
+        [filter:catch_errors]
+        use = egg:swift#catch_errors
+        log_name = catch-errors-log-name
+        """ % tempdir
+        with open(conf_path, 'w') as f:
+            f.write(dedent(conf_body))
+        global_conf = {'log_name': 'global-conf-log-name'}
+        with patch_policies([StoragePolicy(0, 'legacy', True)]):
+            client = internal_client.InternalClient(
+                conf_path, 'test', 1, global_conf=global_conf)
+        self.assertEqual('conf-file-log-name', client.app.logger.server)
+
+        # ...and the 'set x = y' syntax in conf file app section will override
+        # DEFAULT section and global_conf
+        conf_body = """
+        [DEFAULT]
+        swift_dir = %s
+        set log_name = conf-file-log-name
+
+        [pipeline:main]
+        pipeline = catch_errors cache proxy-server
+
+        [app:proxy-server]
+        use = egg:swift#proxy
+        auto_create_account_prefix = -
+
+        [filter:cache]
+        use = egg:swift#memcache
+
+        [filter:catch_errors]
+        use = egg:swift#catch_errors
+        set log_name = catch-errors-log-name
+        """ % tempdir
+        with open(conf_path, 'w') as f:
+            f.write(dedent(conf_body))
+        global_conf = {'log_name': 'global-conf-log-name'}
+        with patch_policies([StoragePolicy(0, 'legacy', True)]):
+            client = internal_client.InternalClient(
+                conf_path, 'test', 1, global_conf=global_conf)
+        self.assertEqual('catch-errors-log-name', client.app.logger.server)
+
     def test_init(self):
         conf_path = 'some_path'
         app = object()

test/unit/common/test_utils.py

@@ -1757,6 +1757,27 @@ class TestUtils(unittest.TestCase):
         self.assertEqual(sio.getvalue(),
                          'test1\ntest3\ntest4\ntest6\n')
 
+    def test_get_logger_name_and_route(self):
+        logger = utils.get_logger({}, name='name', log_route='route')
+        self.assertEqual('route', logger.name)
+        self.assertEqual('name', logger.server)
+        logger = utils.get_logger({'log_name': 'conf-name'}, name='name',
+                                  log_route='route')
+        self.assertEqual('route', logger.name)
+        self.assertEqual('name', logger.server)
+        logger = utils.get_logger({'log_name': 'conf-name'}, log_route='route')
+        self.assertEqual('route', logger.name)
+        self.assertEqual('conf-name', logger.server)
+        logger = utils.get_logger({'log_name': 'conf-name'})
+        self.assertEqual('conf-name', logger.name)
+        self.assertEqual('conf-name', logger.server)
+        logger = utils.get_logger({})
+        self.assertEqual('swift', logger.name)
+        self.assertEqual('swift', logger.server)
+        logger = utils.get_logger({}, log_route='route')
+        self.assertEqual('route', logger.name)
+        self.assertEqual('swift', logger.server)
+
     @with_tempdir
     def test_get_logger_sysloghandler_plumbing(self, tempdir):
         orig_sysloghandler = utils.ThreadSafeSysLogHandler
@@ -5509,11 +5530,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')
         logger.set_statsd_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.')
         logger.set_statsd_prefix('')
         self.assertEqual(logger.logger.statsd_client._prefix, '')
+        self.assertEqual(logger2.logger.statsd_client._prefix, '')
 
     def test_get_logger_statsd_client_non_defaults(self):
         logger = utils.get_logger({

test/unit/container/test_reconciler.py

@@ -896,6 +896,22 @@ class TestReconciler(unittest.TestCase):
         self.assertRaises(ValueError, reconciler.ContainerReconciler,
                           conf, self.logger, self.swift)
 
+    def test_init_internal_client_log_name(self):
+        def _do_test_init_ic_log_name(conf, exp_internal_client_log_name):
+            with mock.patch(
+                    'swift.container.reconciler.InternalClient') \
+                    as mock_ic:
+                reconciler.ContainerReconciler(conf)
+            mock_ic.assert_called_once_with(
+                '/etc/swift/container-reconciler.conf',
+                'Swift Container Reconciler', 3,
+                global_conf={'log_name': exp_internal_client_log_name},
+                use_replication_network=True)
+
+        _do_test_init_ic_log_name({}, 'container-reconciler-ic')
+        _do_test_init_ic_log_name({'log_name': 'my-container-reconciler'},
+                                  'my-container-reconciler-ic')
+
     def _mock_listing(self, objects):
         self.swift.parse(objects)
         self.fake_swift = self.reconciler.swift.app

test/unit/container/test_sharder.py

@@ -187,7 +187,8 @@ class TestSharder(BaseTestSharder):
         mock_ic.assert_called_once_with(
             '/etc/swift/internal-client.conf', 'Swift Container Sharder', 3,
             allow_modify_pipeline=False,
-            use_replication_network=True)
+            use_replication_network=True,
+            global_conf={'log_name': 'container-sharder-ic'})
 
         # non-default shard_container_threshold influences other defaults
         conf = {'shard_container_threshold': 20000000}
@@ -201,7 +202,8 @@ class TestSharder(BaseTestSharder):
         mock_ic.assert_called_once_with(
             '/etc/swift/internal-client.conf', 'Swift Container Sharder', 3,
             allow_modify_pipeline=False,
-            use_replication_network=True)
+            use_replication_network=True,
+            global_conf={'log_name': 'container-sharder-ic'})
 
         # non-default values
         conf = {
@@ -262,7 +264,8 @@ class TestSharder(BaseTestSharder):
         mock_ic.assert_called_once_with(
             '/etc/swift/my-sharder-ic.conf', 'Swift Container Sharder', 2,
             allow_modify_pipeline=False,
-            use_replication_network=True)
+            use_replication_network=True,
+            global_conf={'log_name': 'container-sharder-ic'})
         self.assertEqual(self.logger.get_lines_for_level('warning'), [
             'Option auto_create_account_prefix is deprecated. '
             'Configure auto_create_account_prefix under the '
@@ -385,6 +388,27 @@ class TestSharder(BaseTestSharder):
                     ContainerSharder({})
         self.assertIn('kaboom', str(cm.exception))
 
+    def test_init_internal_client_log_name(self):
+        def _do_test_init_ic_log_name(conf, exp_internal_client_log_name):
+            with mock.patch(
+                    'swift.container.sharder.internal_client.InternalClient') \
+                    as mock_ic:
+                with mock.patch('swift.common.db_replicator.ring.Ring') \
+                        as mock_ring:
+                    mock_ring.return_value = mock.MagicMock()
+                    mock_ring.return_value.replica_count = 3
+                    ContainerSharder(conf)
+            mock_ic.assert_called_once_with(
+                '/etc/swift/internal-client.conf',
+                'Swift Container Sharder', 3,
+                allow_modify_pipeline=False,
+                global_conf={'log_name': exp_internal_client_log_name},
+                use_replication_network=True)
+
+        _do_test_init_ic_log_name({}, 'container-sharder-ic')
+        _do_test_init_ic_log_name({'log_name': 'container-sharder-6021'},
+                                  'container-sharder-6021-ic')
+
     def _assert_stats(self, expected, sharder, category):
         # assertEqual doesn't work with a defaultdict
         stats = sharder.stats['sharding'][category]

test/unit/container/test_sync.py

@@ -20,7 +20,7 @@ from textwrap import dedent
 
 import mock
 import errno
-from swift.common.utils import Timestamp
+from swift.common.utils import Timestamp, readconf
 from test.debug_logger import debug_logger
 from swift.container import sync
 from swift.common.db import DatabaseConnectionError
@@ -154,9 +154,29 @@ class TestContainerSync(unittest.TestCase):
         sample_conf_filename = os.path.join(
             os.path.dirname(test.__file__),
             '../etc/internal-client.conf-sample')
-        with open(sample_conf_filename) as sample_conf_file:
-            sample_conf = sample_conf_file.read()
-        self.assertEqual(contents, sample_conf)
+        actual_conf = readconf(ConfigString(contents))
+        expected_conf = readconf(sample_conf_filename)
+        actual_conf.pop('__file__')
+        expected_conf.pop('__file__')
+        self.assertEqual(expected_conf, actual_conf)
+
+    def test_init_internal_client_log_name(self):
+        def _do_test_init_ic_log_name(conf, exp_internal_client_log_name):
+            with mock.patch(
+                    'swift.container.sync.InternalClient') \
+                    as mock_ic:
+                sync.ContainerSync(conf, container_ring='dummy object')
+            mock_ic.assert_called_once_with(
+                'conf-path',
+                'Swift Container Sync', 3,
+                global_conf={'log_name': exp_internal_client_log_name},
+                use_replication_network=True)
+
+        _do_test_init_ic_log_name({'internal_client_conf_path': 'conf-path'},
+                                  'container-sync-ic')
+        _do_test_init_ic_log_name({'internal_client_conf_path': 'conf-path',
+                                   'log_name': 'my-container-sync'},
+                                  'my-container-sync-ic')
 
     def test_run_forever(self):
         # This runs runs_forever with fakes to succeed for two loops, the first

test/unit/obj/test_expirer.py

@@ -168,6 +168,22 @@ class TestObjectExpirer(TestCase):
         ])
         self.assertEqual(x.expiring_objects_account, '-expiring_objects')
 
+    def test_init_internal_client_log_name(self):
+        def _do_test_init_ic_log_name(conf, exp_internal_client_log_name):
+            with mock.patch(
+                    'swift.obj.expirer.InternalClient') \
+                    as mock_ic:
+                expirer.ObjectExpirer(conf)
+            mock_ic.assert_called_once_with(
+                '/etc/swift/object-expirer.conf',
+                'Swift Object Expirer', 3,
+                global_conf={'log_name': exp_internal_client_log_name},
+                use_replication_network=True)
+
+        _do_test_init_ic_log_name({}, 'object-expirer-ic')
+        _do_test_init_ic_log_name({'log_name': 'my-object-expirer'},
+                                  'my-object-expirer-ic')
+
     def test_get_process_values_from_kwargs(self):
         x = expirer.ObjectExpirer({})
         vals = {

test/unit/proxy/test_server.py

@@ -2110,6 +2110,55 @@ class TestProxyServerConfigLoading(unittest.TestCase):
         app = self._write_conf_and_load_app(conf_sections)
         self._check_policy_options(app, exp_options, {})
 
+    def test_log_name(self):
+        # defaults...
+        conf_sections = """
+        [DEFAULT]
+        log_statsd_host = example.com
+        swift_dir = %s
+
+        [pipeline:main]
+        pipeline = proxy-server
+
+        [app:proxy-server]
+        use = egg:swift#proxy
+        """ % self.tempdir
+        conf_path = self._write_conf(dedent(conf_sections))
+
+        with mock.patch('swift.common.utils.StatsdClient') as mock_statsd:
+            app = loadapp(conf_path, allow_modify_pipeline=False)
+        # logger name is hard-wired 'proxy-server'
+        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,
+            logger=app.logger.logger)
+
+        conf_sections = """
+        [DEFAULT]
+        log_name = test-name
+        log_statsd_host = example.com
+        swift_dir = %s
+
+        [pipeline:main]
+        pipeline = proxy-server
+
+        [app:proxy-server]
+        use = egg:swift#proxy
+        """ % self.tempdir
+        conf_path = self._write_conf(dedent(conf_sections))
+
+        with mock.patch('swift.common.utils.StatsdClient') as mock_statsd:
+            app = loadapp(conf_path, allow_modify_pipeline=False)
+        # logger name is hard-wired 'proxy-server'
+        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
+        mock_statsd.assert_called_once_with(
+            'example.com', 8125, '', 'test-name', 1.0, 1.0,
+            logger=app.logger.logger)
+
 
 class TestProxyServerConfigStringLoading(TestProxyServerConfigLoading):
     # The proxy may be loaded from a conf string rather than a conf file, for