From 8e59dfbee2a67f84a1fd1d5cc1679ec514255fdc Mon Sep 17 00:00:00 2001
From: Tim Burke <tim.burke@gmail.com>
Date: Wed, 19 Apr 2017 00:28:50 +0000
Subject: [PATCH] Log remote_merges during DB replication

Change-Id: I1850f09bab16401479b5a0cc521f67a32ea9c9f5
---
 swift/common/db_replicator.py          |  4 +-
 test/unit/common/test_db_replicator.py | 57 ++++++++++++++++++++++++--
 2 files changed, 55 insertions(+), 6 deletions(-)

diff --git a/swift/common/db_replicator.py b/swift/common/db_replicator.py
index 30c6a35c12..4afa7c095a 100644
--- a/swift/common/db_replicator.py
+++ b/swift/common/db_replicator.py
@@ -229,9 +229,9 @@ class Replicator(Daemon):
              'replication_last': now},
             self.rcache, self.logger)
         self.logger.info(' '.join(['%s:%s' % item for item in
-                         self.stats.items() if item[0] in
+                         sorted(self.stats.items()) if item[0] in
                          ('no_change', 'hashmatch', 'rsync', 'diff', 'ts_repl',
-                          'empty', 'diff_capped')]))
+                          'empty', 'diff_capped', 'remote_merge')]))
 
     def _add_failure_stats(self, failure_devs_info):
         for node, dev in failure_devs_info:
diff --git a/test/unit/common/test_db_replicator.py b/test/unit/common/test_db_replicator.py
index 50f83c2d70..20fd01fb60 100644
--- a/test/unit/common/test_db_replicator.py
+++ b/test/unit/common/test_db_replicator.py
@@ -584,12 +584,61 @@ class TestDBReplicator(unittest.TestCase):
         self.assertFalse(
             replicator._usync_db(0, FakeBroker(), fake_http, '12345', '67890'))
 
-    def test_stats(self):
-        # I'm not sure how to test that this logs the right thing,
-        # but we can at least make sure it gets covered.
-        replicator = TestReplicator({})
+    @mock.patch('swift.common.db_replicator.dump_recon_cache')
+    @mock.patch('swift.common.db_replicator.time.time', return_value=1234.5678)
+    def test_stats(self, mock_time, mock_recon_cache):
+        logger = unit.debug_logger('test-replicator')
+        replicator = TestReplicator({}, logger=logger)
         replicator._zero_stats()
+        self.assertEqual(replicator.stats['start'], mock_time.return_value)
         replicator._report_stats()
+        self.assertEqual(logger.get_lines_for_level('info'), [
+            'Attempted to replicate 0 dbs in 0.00000 seconds (0.00000/s)',
+            'Removed 0 dbs',
+            '0 successes, 0 failures',
+            'diff:0 diff_capped:0 empty:0 hashmatch:0 no_change:0 '
+            'remote_merge:0 rsync:0 ts_repl:0',
+        ])
+        self.assertEqual(1, len(mock_recon_cache.mock_calls))
+        self.assertEqual(mock_recon_cache.mock_calls[0][1][0], {
+            'replication_time': 0.0,
+            'replication_last': mock_time.return_value,
+            'replication_stats': replicator.stats,
+        })
+
+        mock_recon_cache.reset_mock()
+        logger.clear()
+        replicator.stats.update({
+            'attempted': 30,
+            'success': 25,
+            'remove': 9,
+            'failure': 1,
+
+            'diff': 5,
+            'diff_capped': 4,
+            'empty': 7,
+            'hashmatch': 8,
+            'no_change': 6,
+            'remote_merge': 2,
+            'rsync': 3,
+            'ts_repl': 10,
+        })
+        mock_time.return_value += 246.813576
+        replicator._report_stats()
+        self.maxDiff = None
+        self.assertEqual(logger.get_lines_for_level('info'), [
+            'Attempted to replicate 30 dbs in 246.81358 seconds (0.12155/s)',
+            'Removed 9 dbs',
+            '25 successes, 1 failures',
+            'diff:5 diff_capped:4 empty:7 hashmatch:8 no_change:6 '
+            'remote_merge:2 rsync:3 ts_repl:10',
+        ])
+        self.assertEqual(1, len(mock_recon_cache.mock_calls))
+        self.assertEqual(mock_recon_cache.mock_calls[0][1][0], {
+            'replication_time': 246.813576,
+            'replication_last': mock_time.return_value,
+            'replication_stats': replicator.stats,
+        })
 
     def test_replicate_object(self):
         db_replicator.ring = FakeRingWithNodes()