diff --git a/swift/cli/relinker.py b/swift/cli/relinker.py index 948011f4bd..566ab60362 100644 --- a/swift/cli/relinker.py +++ b/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 diff --git a/test/unit/cli/test_relinker.py b/test/unit/cli/test_relinker.py index 9f389036b8..2545cd5ebf 100644 --- a/test/unit/cli/test_relinker.py +++ b/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),