[2574] improved loadzone report text, including progress in %, speed and ETC.

src/bin/loadzone/loadzone.py.in

@@ -25,6 +25,7 @@ from isc.datasrc import *
 import isc.util.process
 import isc.log
 from isc.log_messages.loadzone_messages import *
+from datetime import timedelta
 
 isc.util.process.rename()
 
@@ -113,6 +114,8 @@ class LoadZoneRunner:
         self._log_severity = 'INFO'
         self._log_debuglevel = 0
         self._report_interval = LOAD_INTERVAL_DEFAULT
+        self._start_time = None
+        self._get_time = time.time
 
         self._config_log()
 
@@ -200,16 +203,37 @@ class LoadZoneRunner:
         logger.info(LOADZONE_SQLITE3_USING_DEFAULT_CONFIG, default_db_file)
         return '{"database_file": "' + default_db_file + '"}'
 
-    def _report_progress(self, loaded_rrs):
+    def _report_progress(self, loaded_rrs, progress, dump=True):
         '''Dump the current progress report to stdout.
 
         This is essentially private, but defined as "protected" for tests.
+        Normally dump is True, but tests will set it False to get the
+        text to be reported.  Tests may also fake self._get_time (which
+        is set to time.time() by default) and self._start_time for control
+        time related conditions.
 
         '''
-        elapsed = time.time() - self.__start_time
-        sys.stdout.write("\r" + (80 * " "))
-        sys.stdout.write("\r%d RRs loaded in %.2f seconds" %
-                         (loaded_rrs, elapsed))
+        elapsed = self._get_time() - self._start_time
+        speed = int(loaded_rrs / elapsed) if elapsed > 0 else 0
+        etc = None            # calculate estimated time of completion
+        if progress != ZoneLoader.PROGRESS_UNKNOWN:
+            etc = (1 - progress) * (elapsed / progress)
+
+        # Build report text
+        report_txt = '\r%d RRs' % loaded_rrs
+        if progress != ZoneLoader.PROGRESS_UNKNOWN:
+            report_txt += ' (%.1f%%)' % (progress * 100)
+        report_txt += ' in %s, %d RRs/sec' % \
+            (str(timedelta(seconds=int(elapsed))), speed)
+        if etc is not None:
+            report_txt += ', %s ETC' % str(timedelta(seconds=int(etc)))
+
+        # Dump or return the report text.
+        if dump:
+            sys.stdout.write("\r" + (80 * " "))
+            sys.stdout.write(report_txt)
+        else:
+            return report_txt
 
     def _do_load(self):
         '''Main part of the load logic.
@@ -230,7 +254,7 @@ class LoadZoneRunner:
                             self._zone_class)
             loader = ZoneLoader(datasrc_client, self._zone_name,
                                 self._zone_file)
-            self.__start_time = time.time()
+            self._start_time = time.time()
             if self._report_interval > 0:
                 limit = self._report_interval
             else:
@@ -241,7 +265,8 @@ class LoadZoneRunner:
                    not loader.load_incremental(limit)):
                 self._loaded_rrs += self._report_interval
                 if self._report_interval > 0:
-                    self._report_progress(self._loaded_rrs)
+                    self._report_progress(self._loaded_rrs,
+                                          loader.get_progress())
             if self.__interrupted:
                 raise LoadFailure('loading interrupted by signal')
 
@@ -275,7 +300,7 @@ class LoadZoneRunner:
             self._set_signal_handlers()
             self._parse_args()
             self._do_load()
-            total_elapsed_txt = "%.2f" % (time.time() - self.__start_time)
+            total_elapsed_txt = "%.2f" % (time.time() - self._start_time)
             logger.info(LOADZONE_DONE, self._loaded_rrs, self._zone_name,
                         self._zone_class, total_elapsed_txt)
             return 0

src/bin/loadzone/tests/loadzone_test.py

@@ -142,7 +142,7 @@ class TestLoadZoneRunner(unittest.TestCase):
         self.__runner._datasrc_config = DATASRC_CONFIG
         self.__runner._report_interval = 1
         self.__reports = []
-        self.__runner._report_progress = lambda x: self.__reports.append(x)
+        self.__runner._report_progress = lambda x, _: self.__reports.append(x)
 
     def __check_zone_soa(self, soa_txt, zone_name=TEST_ZONE_NAME):
         """Check that the given SOA RR exists and matches the expected string
@@ -195,6 +195,35 @@ class TestLoadZoneRunner(unittest.TestCase):
         self.__check_zone_soa(NEW_SOA_TXT)   # but load is completed
         self.assertEqual(3, self.__runner._loaded_rrs)
 
+    def test_report_progress(self):
+        '''Check the output format of report_progress.
+
+        For some simple scenario and minor corner cases.  We tweak the
+        start and current times so the test results will be predicatble.
+
+        '''
+        # 10 RRs in 10 sec, which is 25% of the entire zone.  it'll take
+        # 30 sec more
+        self.__runner._start_time = 10
+        self.__runner._get_time = lambda: 20
+        self.assertEqual('\r10 RRs (25.0%) in 0:00:10, 1 RRs/sec, ' +
+                         '0:00:30 ETC',
+                         self.__runner._report_progress(10, 0.25, False))
+
+        # start time == current time.  unlikely to happen in practice, but
+        # it shouldn't cause disruption.
+        self.__runner._get_time = lambda: 10
+        self.assertEqual('\r10 RRs (25.0%) in 0:00:00, 0 RRs/sec, ' +
+                         '0:00:00 ETC',
+                         self.__runner._report_progress(10, 0.25, False))
+
+        # progress is unknown
+        self.__runner._get_time = lambda: 20
+        unknown_progress = isc.datasrc.ZoneLoader.PROGRESS_UNKNOWN
+        self.assertEqual('\r10 RRs in 0:00:10, 1 RRs/sec',
+                         self.__runner._report_progress(10, unknown_progress,
+                                                        False))
+
     def test_create_and_load(self):
         '''successful case to loading contents to a new zone (created).'''
         self.__common_load_setup()
@@ -279,7 +308,8 @@ class TestLoadZoneRunner(unittest.TestCase):
     def test_load_interrupted(self):
         '''Load attempt fails due to signal interruption'''
         self.__common_load_setup()
-        self.__runner._report_progress = lambda x: self.__interrupt_progress(x)
+        self.__runner._report_progress = \
+            lambda x, _: self.__interrupt_progress(x)
         # The interrupting _report_progress() will terminate the loading
         # in the middle.  the number of reports is smaller, and the zone
         # won't be changed.
@@ -294,7 +324,8 @@ class TestLoadZoneRunner(unittest.TestCase):
 
         '''
         self.__common_load_setup()
-        self.__runner._report_progress = lambda x: self.__interrupt_progress(x)
+        self.__runner._report_progress = \
+            lambda x, _: self.__interrupt_progress(x)
         self.__runner._zone_name = Name('example.com')
         self.__runner._zone_file = ALT_NEW_ZONE_TXT_FILE
         self.__check_zone_soa(None, zone_name=Name('example.com'))