Print the real testcase duration

TestCase offers a new public method to calculate and print the duration.
It also adds the related unit tests and adapts run_tests.py.

Change-Id: Ib6a7e637dafacb9027146199aeb033c2dcb986c6
Signed-off-by: Cédric Ollivier <cedric.ollivier@orange.com>

3 files changed, 53 insertions, 12 deletions

diff --git a/functest/ci/run_tests.py b/functest/ci/run_tests.py
index d13612603..d9f3fe42d 100755
--- a/functest/ci/run_tests.py
+++ b/functest/ci/run_tests.py
@@ -9,7 +9,6 @@
 #
 
 import argparse
-import datetime
 import enum
 import importlib
 import logging
@@ -121,8 +120,8 @@ def get_run_dict(testname):
 
 
 def run_test(test, tier_name, testcases=None):
+    duration = "XX:XX"
     result_str = "PASS"
-    start = datetime.datetime.now()
     test_name = test.get_name()
     logger.info("\n")  # blank line
     print_separator("=")
@@ -146,7 +145,6 @@ def run_test(test, tier_name, testcases=None):
             cls = getattr(module, run_dict['class'])
             test_dict = ft_utils.get_dict_by_test(test_name)
             test_case = cls(**test_dict)
-
             try:
                 kwargs = run_dict['args']
                 result = test_case.run(**kwargs)
@@ -155,7 +153,8 @@ def run_test(test, tier_name, testcases=None):
             if result == testcase.TestCase.EX_OK:
                 if GlobalVariables.REPORT_FLAG:
                     test_case.push_to_db()
-                result = test_case.check_result()
+                result = test_case.is_successful()
+            duration = test_case.get_duration()
         except ImportError:
             logger.exception("Cannot import module {}".format(
                 run_dict['module']))
@@ -168,12 +167,9 @@ def run_test(test, tier_name, testcases=None):
     if test.needs_clean() and GlobalVariables.CLEAN_FLAG:
         cleanup()
 
-    end = datetime.datetime.now()
-    duration = (end - start).seconds
-    duration_str = ("%02d:%02d" % divmod(duration, 60))
-    logger.info("Test execution time: %s" % duration_str)
+    logger.info("Test execution time: %s", duration)
 
-    if result != 0:
+    if result != testcase.TestCase.EX_OK:
         logger.error("The test case '%s' failed. " % test_name)
         GlobalVariables.OVERALL_RESULT = Result.EX_ERROR
         result_str = "FAIL"
@@ -181,12 +177,12 @@ def run_test(test, tier_name, testcases=None):
         if test.is_blocking():
             if not testcases or testcases == "all":
                 # if it is a single test we don't print the whole results table
-                update_test_info(test_name, result_str, duration_str)
+                update_test_info(test_name, result_str, duration)
                 generate_report.main(GlobalVariables.EXECUTED_TEST_CASES)
             raise BlockingTestFailed("The test case {} failed and is blocking"
                                      .format(test.get_name()))
 
-    update_test_info(test_name, result_str, duration_str)
+    update_test_info(test_name, result_str, duration)
 
 
 def run_tier(tier):
diff --git a/functest/core/testcase.py b/functest/core/testcase.py
index 217f07e51..fd8928494 100644
--- a/functest/core/testcase.py
+++ b/functest/core/testcase.py
@@ -43,6 +43,24 @@ class TestCase(object):
         self.start_time = ""
         self.stop_time = ""
 
+    def get_duration(self):
+        """Return the duration of the test case.
+
+        Returns:
+            duration if start_time and stop_time are set
+            "XX:XX" otherwise.
+        """
+        try:
+            assert self.start_time
+            assert self.stop_time
+            if self.stop_time < self.start_time:
+                return "XX:XX"
+            return "{0[0]:02.0f}:{0[1]:02.0f}".format(divmod(
+                self.stop_time - self.start_time, 60))
+        except Exception:
+            self.__logger.error("Please run test before getting the duration")
+            return "XX:XX"
+
     def check_result(self):
         """Interpret the result of the test case.
 
diff --git a/functest/tests/unit/core/test_testcase.py b/functest/tests/unit/core/test_testcase.py
index cc8446d80..37948ee18 100644
--- a/functest/tests/unit/core/test_testcase.py
+++ b/functest/tests/unit/core/test_testcase.py
@@ -22,7 +22,7 @@ __author__ = "Cedric Ollivier <cedric.ollivier@orange.com>"
 class TestCaseTesting(unittest.TestCase):
 
     """The class testing TestCase."""
-    # pylint: disable=missing-docstring
+    # pylint: disable=missing-docstring,too-many-public-methods
 
     logging.disable(logging.CRITICAL)
 
@@ -162,6 +162,33 @@ class TestCaseTesting(unittest.TestCase):
         self.assertEqual(self.test.check_result(),
                          testcase.TestCase.EX_TESTCASE_FAILED)
 
+    def test_get_duration_start_ko(self):
+        self.test.start_time = None
+        self.assertEqual(self.test.get_duration(), "XX:XX")
+        self.test.start_time = 0
+        self.assertEqual(self.test.get_duration(), "XX:XX")
+
+    def test_get_duration_end_ko(self):
+        self.test.stop_time = None
+        self.assertEqual(self.test.get_duration(), "XX:XX")
+        self.test.stop_time = 0
+        self.assertEqual(self.test.get_duration(), "XX:XX")
+
+    def test_get_invalid_duration(self):
+        self.test.start_time = 2
+        self.test.stop_time = 1
+        self.assertEqual(self.test.get_duration(), "XX:XX")
+
+    def test_get_zero_duration(self):
+        self.test.start_time = 2
+        self.test.stop_time = 2
+        self.assertEqual(self.test.get_duration(), "00:00")
+
+    def test_get_duration(self):
+        self.test.start_time = 1
+        self.test.stop_time = 180
+        self.assertEqual(self.test.get_duration(), "02:59")
+
 
 if __name__ == "__main__":
     unittest.main(verbosity=2)