fix for drifting risk of slow jobs

socorro/cron/crontabber.py

@@ -670,6 +670,7 @@ def _run_one(self, job_class, config, force=False):
         info = self.database.get(app_name)
 
         last_success = None
+        now = utc_now()
         try:
             for last_success in self._run_job(job_class, config, info):
                 _debug('successfully ran %r on %s', job_class, last_success)
@@ -685,7 +686,7 @@ def _run_one(self, job_class, config, force=False):
             _debug('error when running %r on %s',
                    job_class, last_success, exc_info=True)
         finally:
-            self._log_run(job_class, seconds, time_, last_success,
+            self._log_run(job_class, seconds, time_, last_success, now,
                           exc_type, exc_value, exc_tb)
 
     def check_dependencies(self, class_):
@@ -733,11 +734,10 @@ def _run_job(self, class_, config, info):
         instance = class_(config, info)
         return instance.main()
 
-    def _log_run(self, class_, seconds, time_, last_success,
+    def _log_run(self, class_, seconds, time_, last_success, now,
                  exc_type, exc_value, exc_tb):
         assert inspect.isclass(class_)
         app_name = class_.app_name
-        now = utc_now()
         info = self.database.get(app_name, {})
         if 'first_run' not in info:
             info['first_run'] = now

socorro/unittest/cron/test_crontabber.py

@@ -185,6 +185,32 @@ def fmt(d):
                                             if 'Ran BasicJob' in x])
             self.assertEqual(count_infos_after_second, count_infos + 1)
 
+    def test_slow_run_job(self):
+        config_manager, json_file = self._setup_config_manager(
+          'socorro.unittest.cron.test_crontabber.SlowJob|1h'
+        )
+
+        with config_manager.context() as config:
+            tab = crontabber.CronTabber(config)
+            time_before = utc_now()
+            tab.run_all()
+            time_after = utc_now()
+            time_taken = (time_after - time_before).seconds
+            #time_taken = (time_after - time_before).microseconds / 1000.0 / 1000.0
+            #print time_taken
+            self.assertEqual(round(time_taken), 1.0)
+
+            # check that this was written to the JSON file
+            # and that the next_run is going to be 1 day from now
+            assert os.path.isfile(json_file)
+            structure = json.load(open(json_file))
+            information = structure['slow-job']
+            self.assertEqual(information['error_count'], 0)
+            self.assertEqual(information['last_error'], {})
+            self.assertTrue(information['next_run'].startswith(
+                             (time_before + datetime.timedelta(hours=1))
+                              .strftime('%Y-%m-%d %H:%M:%S')))
+
     def test_run_job_by_class_path(self):
         config_manager, json_file = self._setup_config_manager(
           'socorro.unittest.cron.test_crontabber.BasicJob|30m'
@@ -1060,6 +1086,15 @@ class BarJob(_Job):
     depends_on = 'foo'
 
 
+class SlowJob(_Job):
+    # an app that takes a whole second to run
+    app_name = 'slow-job'
+
+    def run(self):
+        from time import sleep
+        sleep(1)
+        super(SlowJob, self).run()
+
 class TroubleJob(_Job):
     app_name = 'trouble'