[master] Merge branch 'trac2574'

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()
 
@@ -87,7 +88,6 @@ class LoadZoneRunner:
     '''
     def __init__(self, command_args):
         self.__command_args = command_args
-        self.__loaded_rrs = 0
         self.__interrupted = False # will be set to True on receiving signal
 
         # system-wide log configuration.  We need to configure logging this
@@ -103,8 +103,9 @@ class LoadZoneRunner:
                                           [{"output": "stderr",
                                             "destination": "console"}]}]}
 
-        # These are essentially private, and defined as "protected" for the
+        # These are essentially private, but defined as "protected" for the
         # convenience of tests inspecting them
+        self._loaded_rrs = 0
         self._zone_class = None
         self._zone_name = None
         self._zone_file = None
@@ -113,6 +114,10 @@ class LoadZoneRunner:
         self._log_severity = 'INFO'
         self._log_debuglevel = 0
         self._report_interval = LOAD_INTERVAL_DEFAULT
+        self._start_time = None
+        # This one will be used in (rare) cases where we want to allow tests to
+        # fake time.time()
+        self._get_time = time.time
 
         self._config_log()
 
@@ -200,16 +205,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 +256,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:
@@ -239,17 +265,20 @@ class LoadZoneRunner:
                 limit = LOAD_INTERVAL_DEFAULT
             while (not self.__interrupted and
                    not loader.load_incremental(limit)):
-                self.__loaded_rrs += self._report_interval
+                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')
 
             # On successful completion, add final '\n' to the progress
             # report output (on failure don't bother to make it prettier).
             if (self._report_interval > 0 and
-                self.__loaded_rrs >= self._report_interval):
+                self._loaded_rrs >= self._report_interval):
                 sys.stdout.write('\n')
+            # record the final count of the loaded RRs for logging
+            self._loaded_rrs = loader.get_rr_count()
         except Exception as ex:
             # release any remaining lock held in the loader
             loader = None
@@ -273,8 +302,8 @@ class LoadZoneRunner:
             self._set_signal_handlers()
             self._parse_args()
             self._do_load()
-            total_elapsed_txt = "%.2f" % (time.time() - self.__start_time)
-            logger.info(LOADZONE_DONE, self.__loaded_rrs, self._zone_name,
+            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
         except BadArgument as ex:

src/bin/loadzone/loadzone_messages.mes

@@ -27,16 +27,11 @@ LOADZONE_ZONE_CREATED), but the loading operation has subsequently
 failed.  The newly created zone has been removed from the data source,
 so that the data source will go back to the original state.
 
-% LOADZONE_DONE Loaded (at least) %1 RRs into zone %2/%3 in %4 seconds
+% LOADZONE_DONE Loaded %1 RRs into zone %2/%3 in %4 seconds
 b10-loadzone has successfully loaded the specified zone.  If there was
 an old version of the zone in the data source, it is now deleted.
-It also prints (a lower bound of) the number of RRs that have been loaded
-and the time spent for the loading.  Due to a limitation of the
-current implementation of the underlying library however, it cannot show the
-exact number of the loaded RRs; it's counted for every N-th RR where N
-is the value of the -i command line option.  So, for smaller zones that
-don't even contain N RRs, the reported value will be 0.  This will be
-improved in a future version.
+It also prints the number of RRs that have been loaded
+and the time spent for the loading.
 
 % LOADZONE_LOAD_ERROR Failed to load zone %1/%2: %3
 Loading a zone by b10-loadzone fails for some reason in the middle of

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
@@ -175,6 +175,7 @@ class TestLoadZoneRunner(unittest.TestCase):
         # be 3 RRs
         self.assertEqual([1, 2, 3], self.__reports)
         self.__check_zone_soa(NEW_SOA_TXT)
+        self.assertEqual(3, self.__runner._loaded_rrs)
 
     def test_load_update_skipped_report(self):
         '''successful loading, with reports for every 2 RRs'''
@@ -182,6 +183,8 @@ class TestLoadZoneRunner(unittest.TestCase):
         self.__runner._report_interval = 2
         self.__runner._do_load()
         self.assertEqual([2], self.__reports)
+        # total RRs should still be set the actual value
+        self.assertEqual(3, self.__runner._loaded_rrs)
 
     def test_load_update_no_report(self):
         '''successful loading, without progress reports'''
@@ -190,6 +193,36 @@ class TestLoadZoneRunner(unittest.TestCase):
         self.__runner._do_load()
         self.assertEqual([], self.__reports) # no report
         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).'''
@@ -275,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.
@@ -290,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'))