Merge "relinker: Add start/end logs to parallel_process"

swift/cli/relinker.py

@@ -15,12 +15,14 @@
 
 
 import argparse
+import datetime
 import errno
 import fcntl
 import json
 import logging
 import os
 import time
+
 from swift.common.storage_policy import POLICIES
 from swift.common.utils import replace_partition_in_path, config_true_value, \
     audit_location_generator, get_logger, readconf, drop_privileges, \
@@ -520,11 +522,19 @@ def parallel_process(do_cleanup, conf, logger=None, device_list=None):
         workers = len(device_list)
     else:
         workers = min(workers, len(device_list))
-    if workers == 0 or len(device_list) in (0, 1):
-        return Relinker(
-            conf, logger, device_list, do_cleanup=do_cleanup).run()
 
     start = time.time()
+    logger.info('Starting relinker (cleanup=%s) using %d workers: %s' %
+                (do_cleanup, workers,
+                 time.strftime('%X %x %Z', time.gmtime(start))))
+    if workers == 0 or len(device_list) in (0, 1):
+        ret = Relinker(
+            conf, logger, device_list, do_cleanup=do_cleanup).run()
+        logger.info('Finished relinker (cleanup=%s): %s (%s elapsed)' %
+                    (do_cleanup, time.strftime('%X %x %Z', time.gmtime()),
+                     datetime.timedelta(seconds=time.time() - start)))
+        return ret
+
     children = {}
     for worker_devs in distribute_evenly(device_list, workers):
         pid = os.fork()
@@ -573,6 +583,9 @@ def parallel_process(do_cleanup, conf, logger=None, device_list=None):
 
     for msg in final_messages:
         logger.warning(msg)
+    logger.info('Finished relinker (cleanup=%s): %s (%s elapsed)' %
+                (do_cleanup, time.strftime('%X %x %Z', time.gmtime()),
+                 datetime.timedelta(seconds=time.time() - start)))
     return final_status
 
 

test/unit/cli/test_relinker.py

@@ -215,6 +215,13 @@ class TestRelinker(unittest.TestCase):
                 'Expected log line to end with %r; got %r'
                 % (msg, warning_lines[0]))
             self.assertFalse(warning_lines[1:])
+            info_lines = self.logger.get_lines_for_level('info')
+            self.assertEqual(2, len(info_lines))
+            self.assertIn('Starting relinker (cleanup=True) using 5 workers:',
+                          info_lines[0])
+            self.assertIn('Finished relinker (cleanup=True):',
+                          info_lines[1])
+            print(info_lines)
             self.logger.clear()
 
         os.mkdir(os.path.join(self.devices, 'sda2'))
@@ -1133,13 +1140,18 @@ class TestRelinker(unittest.TestCase):
                 '--partition', str(self.part + 1),
             ]))
         self.assertFalse(os.path.isdir(self.expected_dir))
+        info_lines = self.logger.get_lines_for_level('info')
+        self.assertEqual(4, len(info_lines))
+        self.assertIn('Starting relinker (cleanup=False) using 1 workers:',
+                      info_lines[0])
         self.assertEqual(
             ['Processing files for policy platinum under %s (cleanup=False)'
              % os.path.join(self.devices, 'sda1'),
              '0 hash dirs processed (cleanup=False) (0 files, 0 linked, '
-             '0 removed, 0 errors)'],
-            self.logger.get_lines_for_level('info')
+             '0 removed, 0 errors)'], info_lines[1:3]
         )
+        self.assertIn('Finished relinker (cleanup=False):',
+                      info_lines[3])
 
         # restrict to one partition with a test object
         self.logger.clear()
@@ -1157,14 +1169,19 @@ class TestRelinker(unittest.TestCase):
         stat_old = os.stat(os.path.join(self.objdir, self.object_fname))
         stat_new = os.stat(self.expected_file)
         self.assertEqual(stat_old.st_ino, stat_new.st_ino)
+        info_lines = self.logger.get_lines_for_level('info')
+        self.assertEqual(5, len(info_lines))
+        self.assertIn('Starting relinker (cleanup=False) using 1 workers:',
+                      info_lines[0])
         self.assertEqual(
             ['Processing files for policy platinum under %s (cleanup=False)'
              % os.path.join(self.devices, 'sda1'),
              'Step: relink Device: sda1 Policy: platinum Partitions: 1/3',
              '1 hash dirs processed (cleanup=False) (1 files, 1 linked, '
-             '0 removed, 0 errors)'],
-            self.logger.get_lines_for_level('info')
+             '0 removed, 0 errors)'], info_lines[1:4]
         )
+        self.assertIn('Finished relinker (cleanup=False):',
+                      info_lines[4])
 
         # restrict to two partitions with test objects
         self.logger.clear()
@@ -1191,15 +1208,20 @@ class TestRelinker(unittest.TestCase):
         stat_old = os.stat(other_objs[1][1])
         stat_new = os.stat(expected_file)
         self.assertEqual(stat_old.st_ino, stat_new.st_ino)
+        info_lines = self.logger.get_lines_for_level('info')
+        self.assertEqual(6, len(info_lines))
+        self.assertIn('Starting relinker (cleanup=False) using 1 workers:',
+                      info_lines[0])
         self.assertEqual(
             ['Processing files for policy platinum under %s (cleanup=False)'
              % os.path.join(self.devices, 'sda1'),
              'Step: relink Device: sda1 Policy: platinum Partitions: 2/3',
              'Step: relink Device: sda1 Policy: platinum Partitions: 3/3',
              '2 hash dirs processed (cleanup=False) (2 files, 2 linked, '
-             '0 removed, 0 errors)'],
-            self.logger.get_lines_for_level('info')
+             '0 removed, 0 errors)'], info_lines[1:5]
         )
+        self.assertIn('Finished relinker (cleanup=False):',
+                      info_lines[5])
 
     @patch_policies(
         [StoragePolicy(0, name='gold', is_default=True),
@@ -1247,12 +1269,18 @@ class TestRelinker(unittest.TestCase):
                 '--device', self.existing_device,
             ]))
         self.assertFalse(os.path.isdir(self.expected_dir))
+        info_lines = self.logger.get_lines_for_level('info')
+        self.assertEqual(4, len(info_lines))
+        self.assertIn('Starting relinker (cleanup=False) using 1 workers:',
+                      info_lines[0])
         self.assertEqual(
             ['Processing files for policy platinum under %s/%s (cleanup=False)'
              % (self.devices, self.existing_device),
              '0 hash dirs processed (cleanup=False) (0 files, 0 linked, '
-             '0 removed, 0 errors)'],
-            self.logger.get_lines_for_level('info'))
+             '0 removed, 0 errors)'], info_lines[1:3]
+        )
+        self.assertIn('Finished relinker (cleanup=False):',
+                      info_lines[3])
 
         # policy with object
         self.logger.clear()
@@ -1271,13 +1299,19 @@ class TestRelinker(unittest.TestCase):
         stat_old = os.stat(os.path.join(self.objdir, self.object_fname))
         stat_new = os.stat(self.expected_file)
         self.assertEqual(stat_old.st_ino, stat_new.st_ino)
+        info_lines = self.logger.get_lines_for_level('info')
+        self.assertEqual(5, len(info_lines))
+        self.assertIn('Starting relinker (cleanup=False) using 1 workers:',
+                      info_lines[0])
         self.assertEqual(
             ['Processing files for policy gold under %s/%s (cleanup=False)'
              % (self.devices, self.existing_device),
              'Step: relink Device: sda1 Policy: gold Partitions: 1/1',
              '1 hash dirs processed (cleanup=False) (1 files, 1 linked, '
-             '0 removed, 0 errors)'],
-            self.logger.get_lines_for_level('info'))
+             '0 removed, 0 errors)'], info_lines[1:4]
+        )
+        self.assertIn('Finished relinker (cleanup=False):',
+                      info_lines[4])
 
         # policy name works, too
         self.logger.clear()
@@ -1296,12 +1330,18 @@ class TestRelinker(unittest.TestCase):
         stat_old = os.stat(os.path.join(self.objdir, self.object_fname))
         stat_new = os.stat(self.expected_file)
         self.assertEqual(stat_old.st_ino, stat_new.st_ino)
+        info_lines = self.logger.get_lines_for_level('info')
+        self.assertEqual(4, len(info_lines))
+        self.assertIn('Starting relinker (cleanup=False) using 1 workers:',
+                      info_lines[0])
         self.assertEqual(
             ['Processing files for policy gold under %s/%s (cleanup=False)'
              % (self.devices, self.existing_device),
              '0 hash dirs processed (cleanup=False) '
-             '(0 files, 0 linked, 0 removed, 0 errors)'],
-            self.logger.get_lines_for_level('info'))
+             '(0 files, 0 linked, 0 removed, 0 errors)'], info_lines[1:3]
+        )
+        self.assertIn('Finished relinker (cleanup=False):',
+                      info_lines[3])
 
     @patch_policies(
         [StoragePolicy(0, name='gold', is_default=True),