From 47aff724bb0d21e5985b8b5ccbdf5a5621e63134 Mon Sep 17 00:00:00 2001
From: Samuel Merritt <sam@swiftstack.com>
Date: Wed, 30 May 2018 14:35:21 -0700
Subject: [PATCH] Log updater stats once per pass, not per policy

The object updater emits a log line saying "Object update sweep
completed on <disk> in <time>: <lots-of-stats>" after finishing each
storage policy's async pendings. That's not right; an update sweep is
completed on a device when you've looked at all the async pendings on
the device.

This commit moves the "sweep completed" message so it's once per
device, not per policy.

Change-Id: Ibb5f02a18ac431da230afe30c556a756f60d1680
---
 swift/obj/updater.py          | 38 +++++++++++++--------------
 test/unit/obj/test_updater.py | 49 +++++++++++++++++++++++++++++++++++
 2 files changed, 68 insertions(+), 19 deletions(-)

diff --git a/swift/obj/updater.py b/swift/obj/updater.py
index febb754ce9..8db17b98d4 100644
--- a/swift/obj/updater.py
+++ b/swift/obj/updater.py
@@ -278,25 +278,25 @@ class ObjectUpdater(Daemon):
                     os.rmdir(prefix_path)
                 except OSError:
                     pass
-            self.logger.timing_since('timing', start_time)
-            sweep_totals = self.stats.since(start_stats)
-            self.logger.info(
-                ('Object update sweep completed on %(device)s '
-                 'in %(elapsed).02fs seconds:, '
-                 '%(successes)d successes, %(failures)d failures, '
-                 '%(quarantines)d quarantines, '
-                 '%(unlinks)d unlinks, %(errors)d errors, '
-                 '%(redirects)d redirects '
-                 '(pid: %(pid)d)'),
-                {'device': device,
-                 'elapsed': time.time() - start_time,
-                 'pid': my_pid,
-                 'successes': sweep_totals.successes,
-                 'failures': sweep_totals.failures,
-                 'quarantines': sweep_totals.quarantines,
-                 'unlinks': sweep_totals.unlinks,
-                 'errors': sweep_totals.errors,
-                 'redirects': sweep_totals.redirects})
+        self.logger.timing_since('timing', start_time)
+        sweep_totals = self.stats.since(start_stats)
+        self.logger.info(
+            ('Object update sweep completed on %(device)s '
+             'in %(elapsed).02fs seconds:, '
+             '%(successes)d successes, %(failures)d failures, '
+             '%(quarantines)d quarantines, '
+             '%(unlinks)d unlinks, %(errors)d errors, '
+             '%(redirects)d redirects '
+             '(pid: %(pid)d)'),
+            {'device': device,
+             'elapsed': time.time() - start_time,
+             'pid': my_pid,
+             'successes': sweep_totals.successes,
+             'failures': sweep_totals.failures,
+             'quarantines': sweep_totals.quarantines,
+             'unlinks': sweep_totals.unlinks,
+             'errors': sweep_totals.errors,
+             'redirects': sweep_totals.redirects})
 
     def process_object_update(self, update_path, device, policy):
         """
diff --git a/test/unit/obj/test_updater.py b/test/unit/obj/test_updater.py
index ae51153b8e..98146f1214 100644
--- a/test/unit/obj/test_updater.py
+++ b/test/unit/obj/test_updater.py
@@ -321,6 +321,55 @@ class TestObjectUpdater(unittest.TestCase):
             info_lines[3])
         self.assertIn(self.sda1, info_lines[3])
 
+    def test_sweep_logs_multiple_policies(self):
+        for policy in _mocked_policies:
+            asyncdir = os.path.join(self.sda1, get_async_dir(policy.idx))
+            prefix_dir = os.path.join(asyncdir, 'abc')
+            mkpath(prefix_dir)
+
+            for o, t in [('abc', 123), ('def', 234), ('ghi', 345)]:
+                ohash = hash_path('account', 'container%d' % policy.idx, o)
+                o_path = os.path.join(prefix_dir, ohash + '-' +
+                                      normalize_timestamp(t))
+                write_pickle({}, o_path)
+
+        class MockObjectUpdater(object_updater.ObjectUpdater):
+            def process_object_update(self, update_path, device, policy):
+                os.unlink(update_path)
+                self.stats.successes += 1
+                self.stats.unlinks += 1
+
+        logger = FakeLogger()
+        ou = MockObjectUpdater({
+            'devices': self.devices_dir,
+            'mount_check': 'false',
+            'swift_dir': self.testdir,
+            'interval': '1',
+            'concurrency': '1',
+            'report_interval': '10.0',
+            'node_timeout': '5'}, logger=logger)
+
+        now = [time()]
+
+        def mock_time():
+            rv = now[0]
+            now[0] += 0.01
+            return rv
+
+        with mock.patch('swift.obj.updater.time',
+                        mock.MagicMock(time=mock_time)):
+            ou.object_sweep(self.sda1)
+
+        completion_lines = [l for l in logger.get_lines_for_level('info')
+                            if "sweep complete" in l]
+
+        self.assertEqual(len(completion_lines), 1)
+        self.assertIn("sweep complete", completion_lines[0])
+        self.assertIn(
+            "6 successes, 0 failures, 0 quarantines, 6 unlinks, 0 errors, "
+            "0 redirects",
+            completion_lines[0])
+
     @mock.patch.object(object_updater, 'check_drive')
     def test_run_once_with_disk_unmounted(self, mock_check_drive):
         mock_check_drive.return_value = False