grid.promise: add tests for promise cached information

slapos/grid/promise/__init__.py

@@ -94,7 +94,6 @@ class PromiseProcess(Process):
     self._periodicity = None
     self.cache_folder = os.path.join(self.partition_folder,
                                      PROMISE_CACHE_FOLDER_NAME)
-    mkdir_p(self.cache_folder)
     self.cache_file = os.path.join(self.cache_folder, self.getPromiseTitle())
     # XXX - remove old files used to store promise timestamp and periodicity
     self._cleanupDeprecated()
@@ -111,12 +110,6 @@ class PromiseProcess(Process):
     if os.path.exists(periodicity_file) and os.path.isfile(periodicity_file):
       os.unlink(periodicity_file)
 
-  def getNextPromiseTime(self, periodicity):
-    """
-      Return the next promise execution timestamp from now
-    """
-    return time.time() + (periodicity * 60.0)
-
   def getPromiseTitle(self):
     return os.path.splitext(self.name)[0]
 
@@ -171,6 +164,7 @@ class PromiseProcess(Process):
       promise_started = False
       if self.uid and self.gid:
         dropPrivileges(self.uid, self.gid, logger=self.logger)
+      mkdir_p(self.cache_folder)
       if self.wrap_promise:
         promise_instance = WrapPromise(self.argument_dict)
       else:
@@ -338,6 +332,7 @@ class PromiseLauncher(object):
 
     self.queue_result = MQueue()
     self.bang_called = False
+    self._skipped_amount = 0
 
     self.promise_output_dir = os.path.join(
       self.partition_folder,
@@ -464,10 +459,12 @@ class PromiseLauncher(object):
             or not self.check_anomaly and not promise_cache_dict.get('is_tested'):
           # promise is skipped, send empty result
           self._writePromiseResult(PromiseQueueResult())
+          self._skipped_amount += 1
           return
       if not self.force and (promise_cache_dict is not None and not
           self.isPeriodicityMatch(promise_cache_dict.get('next_run_after'))):
         # we won't start the promise process, just get the latest result
+        self._skipped_amount += 1
         result = self._loadPromiseResult(promise_process.getPromiseTitle())
         if result is not None:
           if result.item.hasFailed():
@@ -624,6 +621,8 @@ class PromiseLauncher(object):
           failed_promise_name = promise_name
 
     self._updateFolderOwner(self.promise_output_dir)
-
+    if self._skipped_amount > 0:
+      self.logger.info("%s promises didn't need to be checked." % \
+        self._skipped_amount)
     if failed_promise_name:
       raise PromiseError("Promise %r failed." % failed_promise_name)

slapos/tests/test_promise.py

@@ -36,7 +36,8 @@ import logging
 from datetime import datetime, timedelta
 import six
 from six.moves import queue
-from slapos.grid.promise import interface, PromiseLauncher, PromiseProcess, PromiseError
+from slapos.grid.promise import (interface, PromiseLauncher, PromiseProcess,
+                                 PromiseError, PROMISE_CACHE_FOLDER_NAME)
 from slapos.grid.promise.generic import (GenericPromise, TestResult, AnomalyResult,
                                          PromiseQueueResult, PROMISE_STATE_FOLDER_NAME,
                                          PROMISE_RESULT_FOLDER_NAME,
@@ -93,7 +94,7 @@ class TestSlapOSPromiseMixin(unittest.TestCase):
 
     self.launcher = PromiseLauncher(
       config=parameter_dict,
-      logger=logging.getLogger('slapos.test.promise'),
+      #logger=logging.getLogger('slapos.test.promise'),
       dry_run=dry_run
     )
     if save_method:
@@ -1213,6 +1214,102 @@ exit 1
     # no result returned by the promise
     self.assertTrue(self.called)
 
+  def test_promise_cache(self):
+    promise_name = 'my_promise.py'
+    promise_file = os.path.join(self.plugin_dir, promise_name)
+    self.configureLauncher(timeout=1, enable_anomaly=True)
+    self.generatePromiseScript(promise_name, success=True, periodicity=0.01,
+      with_anomaly=True, is_tested=False)
+
+    # run promise, no failure
+    self.launcher.run()
+    cache_folder = os.path.join(self.partition_dir, PROMISE_CACHE_FOLDER_NAME)
+    cache_file = os.path.join(cache_folder, 'my_promise')
+    self.assertTrue(os.path.exists(cache_folder))
+    self.assertTrue(os.path.exists(cache_file))
+    file_stat = os.stat(promise_file)
+    with open(cache_file) as f:
+      cache_dict = json.load(f)
+    timestamp = cache_dict.pop('timestamp')
+    info_dict = {
+      u'is_tested': False,
+      u'is_anomaly_detected': True,
+      u'periodicity': 0.01,
+      u'next_run_after' : (timestamp + 0.01 * 60.0),
+      u'module_file': u'%s' % promise_file,
+      u'module_file_mtime': file_stat.st_mtime,
+    }
+    # next run is in future
+    self.assertTrue(info_dict['next_run_after'] > time.time())
+    self.assertEqual(info_dict, cache_dict)
+
+  def test_promise_cache_expire_with_periodicity(self):
+    self.called = False
+    def test_method(result):
+      self.called = True
+
+    promise_name = 'my_promise.py'
+    promise_file = os.path.join(self.plugin_dir, promise_name)
+    self.configureLauncher(save_method=test_method, timeout=1, enable_anomaly=True)
+    self.generatePromiseScript(promise_name, success=True, periodicity=0.01,
+      with_anomaly=True, is_tested=False)
+
+    # run promise, no failure
+    self.launcher.run()
+    cache_folder = os.path.join(self.partition_dir, PROMISE_CACHE_FOLDER_NAME)
+    cache_file = os.path.join(cache_folder, 'my_promise')
+    self.assertTrue(os.path.exists(cache_folder))
+    self.assertTrue(os.path.exists(cache_file))
+    file_stat = os.stat(promise_file)
+    with open(cache_file) as f:
+      cache_dict = json.load(f)
+    timestamp = cache_dict.pop('timestamp')
+    info_dict = {
+      u'is_tested': False,
+      u'is_anomaly_detected': True,
+      u'periodicity': 0.01,
+      u'next_run_after' : (timestamp + 0.01 * 60.0),
+      u'module_file': u'%s' % promise_file,
+      u'module_file_mtime': file_stat.st_mtime,
+    }
+    self.assertEqual(info_dict, cache_dict)
+    self.assertTrue(self.called)
+    next_run_after = cache_dict['next_run_after']
+
+    # periodicity not match
+    self.called = False
+    self.configureLauncher(save_method=test_method, timeout=1, enable_anomaly=True)
+    self.launcher.run()
+    self.assertFalse(self.called)
+    with open(cache_file) as f:
+      cache_dict = json.load(f)
+    # no change!
+    current_timestamp = cache_dict.pop('timestamp')
+    self.assertEqual(current_timestamp, timestamp)
+    self.assertEqual(info_dict, cache_dict)
+
+    time.sleep(1)
+    # periodicity match
+    self.configureLauncher(save_method=test_method, timeout=1, enable_anomaly=True)
+    self.launcher.run()
+
+    # cached was updated
+    with open(cache_file) as f:
+      cache_dict = json.load(f)
+    new_timestamp = cache_dict.pop('timestamp')
+    info_dict = {
+      u'is_tested': False,
+      u'is_anomaly_detected': True,
+      u'periodicity': 0.01,
+      u'next_run_after' : (new_timestamp + 0.01 * 60.0),
+      u'module_file': u'%s' % promise_file,
+      u'module_file_mtime': file_stat.st_mtime,
+    }
+    self.assertTrue(new_timestamp > timestamp)
+    # next run is in future
+    self.assertTrue(cache_dict['next_run_after'] > next_run_after)
+    self.assertEqual(info_dict, cache_dict)
+
 class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
 
   def initialisePromise(self, promise_content="", success=True, timeout=60):

[Jérome Perrin]

@alain.takoudjou was this intentional ? After !73 (merged) tests were silent and I noticed that recently they are logging again, for exemple:

test_promise_cache (slapos.tests.test_promise.TestSlapOSPromiseLauncher) ... 2019-03-19 11:26:56,905 - slapos.grid.promise - INFO - Checking promise my_promise.py...
ok
test_promise_cache_expire_with_periodicity (slapos.tests.test_promise.TestSlapOSPromiseLauncher) ... 2019-03-19 11:26:57,018 - slapos.grid.promise - INFO - Checking promise my_promise.py...
2019-03-19 11:26:57,122 - slapos.grid.promise - INFO - 1 promises didn't need to be checked.
2019-03-19 11:26:58,129 - slapos.grid.promise - INFO - Checking promise my_promise.py...
ok

I guess this was the reason. Can we set logger again so that log is not output on console ?

[Alain Takoudjou]

Yes, I commented because there was no logging in console (of webrunner) and I wanted to see what was happening to debug something.

I guess this was the reason. Can we set logger again so that log is not output on console ?

I'm ok to set logger again. I'll do a commit so.

[Jérome Perrin]

Thanks, yes let's make it silent by default.

BTW, slapos.core test suite more or less work with pytest now and pytest is very clever with logging, it capture logging and show the logs related to failing tests. Next time you can also try this, in my experience, it's nice ( but some tests seem to fail only on pytest )

[Jérome Perrin]

3343cbea thanks :)