slapgrid.promise: Fix again get promise result, count execution instead of check time

slapos/grid/promise/__init__.py

@@ -221,7 +221,7 @@ class GenericPromise(object):
       if match is not None:
         if not only_failure or (only_failure and match.groups()[1] == 'ERROR'):
           result_list.append({
-            'date': match.groups()[0],
+            'date': datetime.strptime(match.groups()[0], '%Y-%m-%d %H:%M:%S'),
             'status': match.groups()[1],
             'message': (match.groups()[2] + line_part).strip(),
           })
@@ -232,13 +232,26 @@ class GenericPromise(object):
 
     return result_list
 
-  def getLastPromiseResultList(self, latest_minute=1, only_failure=False):
+  def __checkLogDateInNewPromise(self, log_date, previous_date):
+    if previous_date is None:
+      return True
+
+    diff = previous_date - log_date
+    if diff.seconds >= self.getConfig('promise-timeout'):
+      # The promise run in max 20 seconds so this was not in the same process
+      return True
+    return False
+
+  def getLastPromiseResultList(self, latest_minute=0, result_count=1,
+      only_failure=False):
     """
       Return the latest log result of the promise starting from the most recent
 
       @param last_minute: the number of minutes in the past. If last_minute is
-        1, it will return the log of the latest minute execution.
+        1, it will return the log of the latest minute execution. 0 => disabled
       @param only_failure: only return the lines which contain failures.
+      @param result_count: maximum number of promise result to check, will not
+        exceed the `latest_minute`
       @return Return a dict of logs. The format is
         [{"date": "DATE", "status": "STATUS", "message": MESSAGE}, ]
     """
@@ -254,10 +267,14 @@ class GenericPromise(object):
       return []
 
     regex = self.__getLogRegex()
-    date = datetime.now() - timedelta(minutes=latest_minute)
-    date_string = date.strftime('%Y-%m-%d %H:%M:%S')
+    max_date_string = ""
+    if latest_minute > 0:
+      date = datetime.now() - timedelta(minutes=latest_minute)
+      max_date_string = date.strftime('%Y-%m-%d %H:%M:%S')
 
     line_list = []
+    previous_date = None
+    promise_count = 0
     with open(self.__log_file, 'r') as f:
       offset = 0
       f.seek(0, 2)
@@ -276,36 +293,46 @@ class GenericPromise(object):
           if line != "":
             result = regex.match(line)
             if result is not None:
-              if result.groups()[0] <= date_string:
+              if max_date_string and result.groups()[0] <= max_date_string:
+                break
+              log_date = datetime.strptime(result.groups()[0], '%Y-%m-%d %H:%M:%S')
+              if self.__checkLogDateInNewPromise(log_date, previous_date):
+                promise_count += 1
+                previous_date = log_date
+              if promise_count > result_count:
                 break
               if not only_failure or \
                   (only_failure and result.groups()[1] == 'ERROR'):
                 line_list.append({
-                  'date': result.groups()[0],
+                  'date': log_date,
                   'status': result.groups()[1],
                   'message': (result.groups()[2] + line_part).strip(),
                 })
             else:
-              line_part += '\n' + line
+              line_part = '\n' + line + line_part
               line = ""
               continue
             line = line_part = ""
     return line_list
 
-  def defaultTest(self, latest_minute=2, failure_amount=1, is_anomaly=False):
+  def defaultTest(self, result_count=1, failure_amount=1, latest_minute=0,
+      is_anomaly=False):
     """
       Test if the latest messages contain `failure_amount` failures.
 
+      @param result_count: maximum number of promise result to check, will not
+        exceed the `latest_minute`
       @param latest_minute: test the result from now to the latest X minutes in
         the past.
       @param failure_amount: fail is this amount of failure is found in result
       @param is_anomaly: Say if the result is an AnomalyResult of TestResult
     """
 
-    problem = False
+    problem = True
     message = ""
     module = TestResult if not is_anomaly else AnomalyResult
     latest_result_list = self.getLastPromiseResultList(
+      result_count=result_count,
       latest_minute=latest_minute,
       only_failure=False
     )
@@ -321,7 +348,6 @@ class GenericPromise(object):
     while i < result_size and failure_found < failure_amount:
       if latest_result_list[i]['status'] == 'ERROR':
         failure_found += 1
-        problem = True
       i += 1
 
     if failure_found != failure_amount:
@@ -754,6 +780,7 @@ class PromiseLauncher(object):
       'log-folder': self.log_folder,
       'partition-folder': self.partition_folder,
       'debug': self.debug,
+      'promise-timeout': self.promise_timeout,
       'slapgrid-mode': self.slapgrid_mode,
       'check-anomaly': self.check_anomaly,
       'master-url': self.master_url,

slapos/tests/promise.py

@@ -684,7 +684,7 @@ exit 0
 
 class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
 
-  def initialisePromise(self, promise_content="", success=True):
+  def initialisePromise(self, promise_content="", success=True, timeout=60):
     self.promise_name = 'my_promise.py'
     self.promise_path = os.path.join(self.plugin_dir, self.promise_name)
     self.configureLauncher()
@@ -694,6 +694,7 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
     self.promise_config = {
       'log-folder': self.log_dir,
       'partition-folder': self.partition_dir,
+      'promise-timeout': timeout,
       'debug': False,
       'slapgrid-mode': False,
       'check-anomaly': True,
@@ -795,15 +796,15 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
     date = datetime.now()
     promise.sense()
     # get all messages during the latest minute
-    latest_message_list = promise.getLastPromiseResultList(latest_minute=1)
-    date_string = date.strftime('%Y-%m-%d %H:%M:%S')
+    latest_message_list = promise.getLastPromiseResultList(result_count=1)
+    date = datetime.strptime(date.strftime('%Y-%m-%d %H:%M:%S'), '%Y-%m-%d %H:%M:%S')
     self.assertEquals(len(latest_message_list), 2)
     self.assertEquals(
       latest_message_list[0],
-      {'date': date_string, 'status': 'INFO', 'message': 'success'})
+      {'date': date, 'status': 'INFO', 'message': 'success'})
     self.assertEquals(
       latest_message_list[1],
-      {'date': date_string, 'status': 'INFO', 'message': 'Promise is running...'})
+      {'date': date, 'status': 'INFO', 'message': 'Promise is running...'})
 
   def test_promise_resultfromlog_error(self):
     promise_content = 'self.logger.error("Promise is running...\\nmessage in new line")'
@@ -815,15 +816,15 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
     date = datetime.now()
     promise.sense()
     # get all messages during the latest minute
-    latest_message_list = promise.getLastPromiseResultList(latest_minute=1)
-    date_string = date.strftime('%Y-%m-%d %H:%M:%S')
+    latest_message_list = promise.getLastPromiseResultList(result_count=1)
+    date = datetime.strptime(date.strftime('%Y-%m-%d %H:%M:%S'), '%Y-%m-%d %H:%M:%S')
     self.assertEquals(len(latest_message_list), 2)
     self.assertEquals(
       latest_message_list[0],
-      {'date': date_string, 'status': 'INFO', 'message': 'success'})
+      {'date': date, 'status': 'INFO', 'message': 'success'})
     self.assertEquals(
       latest_message_list[1],
-      {'date': date_string, 'status': 'ERROR',
+      {'date': date, 'status': 'ERROR',
        'message': 'Promise is running...\nmessage in new line'})
 
   def test_promise_resultfromlog_no_logfolder(self):
@@ -840,17 +841,17 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
     self.assertEquals(promise.getLogFile(), None)
 
     # get all messages during the latest minute
-    latest_message_list = promise.getLastPromiseResultList(latest_minute=1)
-    date_string = date.strftime('%Y-%m-%d %H:%M:%S')
+    latest_message_list = promise.getLastPromiseResultList(result_count=1)
+    date = datetime.strptime(date.strftime('%Y-%m-%d %H:%M:%S'), '%Y-%m-%d %H:%M:%S')
     self.assertEquals(len(latest_message_list), 2)
     self.assertEquals(
       latest_message_list[0],
-      {'date': date_string, 'status': 'INFO', 'message': 'success'})
+      {'date': date, 'status': 'INFO', 'message': 'success'})
     self.assertEquals(
       latest_message_list[1],
-      {'date': date_string, 'status': 'INFO', 'message': 'Promise is running...'})
+      {'date': date, 'status': 'INFO', 'message': 'Promise is running...'})
 
-  def test_promise_resultfromlog_older_log(self):
+  def test_promise_resultfromlog_latest_minutes(self):
     self.initialisePromise()
     promise_module = self.launcher._loadPromiseModule(self.promise_name)
     reload(promise_module)
@@ -865,19 +866,22 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
         line = "%s - INFO - Promise result %s\n" % (date_string, i)
         f.write(line)
 
-    #promise.sense()
-    latest_message_list = promise.getLastPromiseResultList(latest_minute=10)
-    start_date_string = start_date.strftime('%Y-%m-%d %H:%M:%S')
+    latest_message_list = promise.getLastPromiseResultList(
+      latest_minute=10,
+      result_count=100
+    )
+    start_date = datetime.strptime(start_date.strftime('%Y-%m-%d %H:%M:%S'), '%Y-%m-%d %H:%M:%S')
     end_date_string = (start_date - timedelta(minutes=9)).strftime('%Y-%m-%d %H:%M:%S')
+    end_date = datetime.strptime(end_date_string, '%Y-%m-%d %H:%M:%S')
     self.assertEquals(len(latest_message_list), 10)
     self.assertEquals(
       latest_message_list[0],
-      {'date': start_date_string, 'status': 'INFO', 'message': 'Promise result 49'})
+      {'date': start_date, 'status': 'INFO', 'message': 'Promise result 49'})
     self.assertEquals(
       latest_message_list[-1],
-      {'date': end_date_string, 'status': 'INFO', 'message': 'Promise result 40'})
+      {'date': end_date, 'status': 'INFO', 'message': 'Promise result 40'})
 
-  def test_promise_resultfromlog_older_log_more(self):
+  def test_promise_resultfromlog_latest_minutes_multilog(self):
     self.initialisePromise()
     promise_module = self.launcher._loadPromiseModule(self.promise_name)
     reload(promise_module)
@@ -896,19 +900,96 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
     with open(promise.getLogFile(), 'w') as f:
       f.write('\n'.join(line_list))
 
-    #promise.sense()
-    latest_message_list = promise.getLastPromiseResultList(latest_minute=10)
+    latest_message_list = promise.getLastPromiseResultList(
+      latest_minute=10,
+      result_count=100
+    )
 
-    start_date_string = start_date.strftime('%Y-%m-%d %H:%M:%S')
+    start_date = datetime.strptime(start_date.strftime('%Y-%m-%d %H:%M:%S'), '%Y-%m-%d %H:%M:%S')
     end_date_string = (start_date - timedelta(seconds=30*19)).strftime('%Y-%m-%d %H:%M:%S')
+    end_date = datetime.strptime(end_date_string, '%Y-%m-%d %H:%M:%S')
     # there is 2 result line per minutes
     self.assertEquals(len(latest_message_list), 20)
     self.assertEquals(
       latest_message_list[0],
-      {'date': start_date_string, 'status': 'INFO', 'message': 'Promise result 0'})
+      {'date': start_date, 'status': 'INFO', 'message': 'Promise result 0'})
+    self.assertEquals(
+      latest_message_list[-1],
+      {'date': end_date, 'status': 'INFO', 'message': 'Promise result 19'})
+
+  def test_promise_resultfromlog_result_count(self):
+    self.initialisePromise()
+    promise_module = self.launcher._loadPromiseModule(self.promise_name)
+    reload(promise_module)
+    promise = promise_module.RunPromise(self.promise_config)
+
+    # write some random logs
+    start_date = datetime.now()
+    date = start_date
+    line_list = []
+    for i in range(0, 50):
+      date_string = date.strftime('%Y-%m-%d %H:%M:%S')
+      line_list.append("%s - INFO - Promise result %s" % (date_string, i))
+      date = date - timedelta(seconds=30)
+
+    line_list.reverse()
+    with open(promise.getLogFile(), 'w') as f:
+      f.write('\n'.join(line_list))
+
+    # result_count = 2 will return 2 log
+    # max execution time is 1 min and log is writen every 30 seconds
+    latest_message_list = promise.getLastPromiseResultList(result_count=1)
+
+    start_date = datetime.strptime(start_date.strftime('%Y-%m-%d %H:%M:%S'), '%Y-%m-%d %H:%M:%S')
+    end_date_string = (start_date - timedelta(seconds=30)).strftime('%Y-%m-%d %H:%M:%S')
+    end_date = datetime.strptime(end_date_string, '%Y-%m-%d %H:%M:%S')
+    # there is 2 result line per minutes
+    self.assertEquals(len(latest_message_list), 2)
+    self.assertEquals(
+      latest_message_list[0],
+      {'date': start_date, 'status': 'INFO', 'message': 'Promise result 0'})
+    self.assertEquals(
+      latest_message_list[-1],
+      {'date': end_date, 'status': 'INFO', 'message': 'Promise result 1'})
+
+  def test_promise_resultfromlog_result_count_many(self):
+    self.initialisePromise()
+    promise_module = self.launcher._loadPromiseModule(self.promise_name)
+    reload(promise_module)
+    promise = promise_module.RunPromise(self.promise_config)
+
+    # write some random logs
+    start_date = datetime.now()
+    date = start_date
+    line_list = []
+    for i in range(0, 50):
+      date_string = date.strftime('%Y-%m-%d %H:%M:%S')
+      line_list.append("%s - INFO - Promise result %s" % (date_string, i))
+      date = date - timedelta(seconds=30)
+
+    line_list.reverse()
+    with open(promise.getLogFile(), 'w') as f:
+      f.write('\n'.join(line_list))
+
+    # result_count = 2 will return 4 log
+    # max execution time is 1 min and log is writen every 30 seconds
+    latest_message_list = promise.getLastPromiseResultList(result_count=2)
+
+    start_date = datetime.strptime(start_date.strftime('%Y-%m-%d %H:%M:%S'), '%Y-%m-%d %H:%M:%S')
+    end_date_string = (start_date - timedelta(seconds=30*3)).strftime('%Y-%m-%d %H:%M:%S')
+    end_date = datetime.strptime(end_date_string, '%Y-%m-%d %H:%M:%S')
+    # there is 2 result line per minutes
+    self.assertEquals(len(latest_message_list), 4)
+    self.assertEquals(
+      latest_message_list[0],
+      {'date': start_date, 'status': 'INFO', 'message': 'Promise result 0'})
     self.assertEquals(
       latest_message_list[-1],
-      {'date': end_date_string, 'status': 'INFO', 'message': 'Promise result 19'})
+      {'date': end_date, 'status': 'INFO', 'message': 'Promise result 3'})
+
+    latest_message_list = promise.getLastPromiseResultList(result_count=100)
+    # all results
+    self.assertEquals(len(latest_message_list), 50)
 
   def test_promise_defaulttest(self):
     promise_content = 'self.logger.info("Promise is running...\\nmessage in new line")'
@@ -919,7 +1000,7 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
 
     promise.sense()
 
-    result = promise.defaultTest(latest_minute=1, failure_amount=1)
+    result = promise.defaultTest(result_count=1, failure_amount=1)
     self.assertTrue(isinstance(result, TestResult))
     self.assertEquals(result.message, 'success')
     self.assertEquals(result.hasFailed(), False)
@@ -932,13 +1013,13 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
 
     promise.sense()
 
-    result = promise.defaultTest(latest_minute=1, failure_amount=1)
+    result = promise.defaultTest(result_count=1, failure_amount=1)
     self.assertTrue(isinstance(result, TestResult))
     self.assertEquals(result.message, 'failed')
     self.assertEquals(result.hasFailed(), True)
 
   def test_promise_defaulttest_error_if_two_fail(self):
-    self.initialisePromise(success=False)
+    self.initialisePromise(success=False, timeout=0.5)
     promise_module = self.launcher._loadPromiseModule(self.promise_name)
     reload(promise_module)
     promise = promise_module.RunPromise(self.promise_config)
@@ -946,19 +1027,21 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
     promise.sense()
 
     # fail if 2 errors found
-    result = promise.defaultTest(latest_minute=1, failure_amount=2)
+    result = promise.defaultTest(result_count=2, failure_amount=2)
     self.assertTrue(isinstance(result, TestResult))
     self.assertEquals(result.message, 'failed')
     self.assertEquals(result.hasFailed(), False)
 
+    time.sleep(0.6)
     promise.sense()
-    result = promise.defaultTest(latest_minute=1, failure_amount=2)
+    result = promise.defaultTest(result_count=2, failure_amount=2)
     self.assertEquals(result.message, 'failed')
     self.assertEquals(result.hasFailed(), True)
 
     # will continue to fail
+    time.sleep(0.6)
     promise.sense()
-    result = promise.defaultTest(latest_minute=1, failure_amount=2)
+    result = promise.defaultTest(result_count=2, failure_amount=2)
     self.assertEquals(result.message, 'failed')
     self.assertEquals(result.hasFailed(), True)
 
@@ -971,7 +1054,7 @@ class TestSlapOSGenericPromise(TestSlapOSPromiseMixin):
 
     promise.sense()
 
-    result = promise.defaultTest(latest_minute=1, failure_amount=1, is_anomaly=True)
+    result = promise.defaultTest(result_count=1, failure_amount=1, is_anomaly=True)
     self.assertTrue(isinstance(result, AnomalyResult))
     self.assertEquals(result.message, 'success')
     self.assertEquals(result.hasFailed(), False)