Relinker: Add partition progress to relinker log

Turns out the relinker's relink and cleanup command can take a while so
it would be nice to have progress added to the log file.

This patch adds an info level log line to the relinker log once a
partition is completed. It looks something like:

  Device: sda1 Step: cleanup Partitions: 1/2

So from a glance we can see what device, what step and the progress. In
the above snippet it's just finished the first of 2 partitions.

Change-Id: I364b37ca77a5b6d6125a1f133efa255340316949

swift/cli/relinker.py

@@ -136,7 +136,7 @@ def partitions_filter(states, part_power, next_part_power,
 
 
 # Save states when a partition is done
-def hook_post_partition(states, step, policy, diskfile_manager,
+def hook_post_partition(logger, states, step, policy, diskfile_manager,
                         partition_path):
     datadir_path, part = os.path.split(os.path.abspath(partition_path))
     device_path, datadir_name = os.path.split(datadir_path)
@@ -207,6 +207,9 @@ def hook_post_partition(states, step, policy, diskfile_manager,
         json.dump(states, f)
         os.fsync(f.fileno())
     os.rename(state_tmp_file, state_file)
+    num_parts_done = sum(1 for part in states["state"].values() if part)
+    logger.info("Device: %s Step: %s Partitions: %d/%d" % (
+        device, step, num_parts_done, len(states["state"])))
 
 
 def hashes_filter(next_part_power, suff_path, hashes):
@@ -275,8 +278,9 @@ def relink(conf, logger, device):
         relink_hook_post_device = partial(hook_post_device, locks)
         relink_partition_filter = partial(partitions_filter,
                                           states, part_power, next_part_power)
-        relink_hook_post_partition = partial(
-            hook_post_partition, states, STEP_RELINK, policy, diskfile_mgr)
+        relink_hook_post_partition = partial(hook_post_partition, logger,
+                                             states, STEP_RELINK, policy,
+                                             diskfile_mgr)
         relink_hashes_filter = partial(hashes_filter, next_part_power)
 
         locations = audit_location_generator(
@@ -343,8 +347,9 @@ def cleanup(conf, logger, device):
         cleanup_hook_post_device = partial(hook_post_device, locks)
         cleanup_partition_filter = partial(partitions_filter,
                                            states, part_power, next_part_power)
-        cleanup_hook_post_partition = partial(
-            hook_post_partition, states, STEP_CLEANUP, policy, diskfile_mgr)
+        cleanup_hook_post_partition = partial(hook_post_partition, logger,
+                                              states, STEP_CLEANUP, policy,
+                                              diskfile_mgr)
         cleanup_hashes_filter = partial(hashes_filter, next_part_power)
 
         locations = audit_location_generator(

test/unit/cli/test_relinker.py

@@ -794,9 +794,12 @@ class TestRelinker(unittest.TestCase):
                               'mount_check': False}, self.logger)[pol]
 
         # Ack partition 96
-        relinker.hook_post_partition(states, relinker.STEP_RELINK, pol, mgr,
+        relinker.hook_post_partition(self.logger, states,
+                                     relinker.STEP_RELINK, pol, mgr,
                                      os.path.join(datadir_path, '96'))
         self.assertEqual(states["state"], {'96': True, '227': False})
+        self.assertIn("Device: sda1 Step: relink Partitions: 1/2",
+                      self.logger.get_lines_for_level("info"))
         with open(state_file, 'rt') as f:
             self.assertEqual(json.load(f), {
                 "part_power": PART_POWER,
@@ -810,8 +813,11 @@ class TestRelinker(unittest.TestCase):
         self.assertEqual(states["state"], {'96': True, '227': False})
 
         # Ack partition 227
-        relinker.hook_post_partition(states, relinker.STEP_RELINK, pol, mgr,
-                                     os.path.join(datadir_path, '227'))
+        relinker.hook_post_partition(
+            self.logger, states, relinker.STEP_RELINK, pol,
+            mgr, os.path.join(datadir_path, '227'))
+        self.assertIn("Device: sda1 Step: relink Partitions: 2/2",
+                      self.logger.get_lines_for_level("info"))
         self.assertEqual(states["state"], {'96': True, '227': True})
         with open(state_file, 'rt') as f:
             self.assertEqual(json.load(f), {
@@ -852,8 +858,11 @@ class TestRelinker(unittest.TestCase):
                          call_partition_filter(PART_POWER + 1, PART_POWER + 1,
                                                ['96', '227', '312']))
         # Ack partition 227
-        relinker.hook_post_partition(states, relinker.STEP_CLEANUP, pol, mgr,
-                                     os.path.join(datadir_path, '227'))
+        relinker.hook_post_partition(
+            self.logger, states, relinker.STEP_CLEANUP, pol, mgr,
+            os.path.join(datadir_path, '227'))
+        self.assertIn("Device: sda1 Step: cleanup Partitions: 1/2",
+                      self.logger.get_lines_for_level("info"))
         self.assertEqual(states["state"],
                          {'96': False, '227': True})
         with open(state_file, 'rt') as f:
@@ -871,8 +880,11 @@ class TestRelinker(unittest.TestCase):
                          {'96': False, '227': True})
 
         # Ack partition 96
-        relinker.hook_post_partition(states, relinker.STEP_CLEANUP, pol, mgr,
+        relinker.hook_post_partition(self.logger, states,
+                                     relinker.STEP_CLEANUP, pol, mgr,
                                      os.path.join(datadir_path, '96'))
+        self.assertIn("Device: sda1 Step: cleanup Partitions: 2/2",
+                      self.logger.get_lines_for_level("info"))
         self.assertEqual(states["state"],
                          {'96': True, '227': True})
         with open(state_file, 'rt') as f: