Fix steps time measurement

Substeps execution time is not stored with the right time of step execution

Issue-ID: TEST-292
Signed-off-by: Michal Jagiello <michal.jagiello@t-mobile.pl>
Change-Id: I58e2aecb1f3cfb1a2bf78a438fc3d508ecf83cc1

5 files changed, 68 insertions, 4 deletions

diff --git a/src/onaptests/steps/base.py b/src/onaptests/steps/base.py
index 9e1c991..aa2be6a 100644
--- a/src/onaptests/steps/base.py
+++ b/src/onaptests/steps/base.py
@@ -40,6 +40,7 @@ class BaseStep(ABC):
         self._cleanup: bool = cleanup
         self._parent: "BaseStep" = None
         self._reports_collection: ReportsCollection = None
+        self._start_time: float = None
 
     def add_step(self, step: "BaseStep") -> None:
         """Add substep.
@@ -122,7 +123,6 @@ class BaseStep(ABC):
     def store_state(cls, fun):
         def wrapper(self, *args, **kwargs):
             try:
-                start_time: float = time.time()
                 ret = fun(self, *args, **kwargs)
                 execution_status: ReportStepStatus = ReportStepStatus.PASS
                 return ret
@@ -130,24 +130,29 @@ class BaseStep(ABC):
                 execution_status: ReportStepStatus = ReportStepStatus.FAIL
                 raise
             finally:
+                if not self._start_time:
+                    self._logger.error("No execution start time saved for %s step. Fix it by call `super.execute()` "
+                                       "in step class `execute()` method definition")
+                    self._start_time = time.time()
                 self.reports_collection.put(
                     Report(
                         step_description=f"[{self.component}] {self.name}: {self.description}",
                         step_execution_status=execution_status,
-                        step_execution_duration=time.time() - start_time
+                        step_execution_duration=time.time() - self._start_time
                     )
                 )
         return wrapper
 
     def execute(self) -> None:
-        """Step's action.
+        """Step's action execution.
 
         Run all substeps action before it's own action.
-        Override this method and remember to call `super().action()` before.
+        Override this method and remember to call `super().execute()` before.
 
         """
         for step in self._steps:
             step.execute()
+        self._start_time = time.time()
 
     def cleanup(self) -> None:
         """Step's cleanup.
diff --git a/src/onaptests/steps/cloud/customer_create.py b/src/onaptests/steps/cloud/customer_create.py
index b99fdb1..6c78d55 100644
--- a/src/onaptests/steps/cloud/customer_create.py
+++ b/src/onaptests/steps/cloud/customer_create.py
@@ -24,4 +24,5 @@ class CustomerCreateStep(BaseStep):
         Use settings values:
          - GLOBAL_CUSTOMER_ID.
         """
+        super().execute()
         Customer.create(settings.GLOBAL_CUSTOMER_ID, settings.GLOBAL_CUSTOMER_ID, "INFRA")
diff --git a/src/onaptests/steps/onboard/pnf.py b/src/onaptests/steps/onboard/pnf.py
index 12f2561..547e0c0 100644
--- a/src/onaptests/steps/onboard/pnf.py
+++ b/src/onaptests/steps/onboard/pnf.py
@@ -46,6 +46,7 @@ class PnfOnboardStep(BaseStep):
          - PNF_ARTIFACT_FILE_PATH
 
         """
+        super().execute()
         vendor: Vendor = Vendor(name=settings.VENDOR_NAME)
         pnf: Pnf = Pnf(name=settings.PNF_NAME, vendor=vendor)
         pnf.create()
diff --git a/src/onaptests/steps/simulator/pnf/pnf_instantiate.py b/src/onaptests/steps/simulator/pnf/pnf_instantiate.py
index 5fb664d..d9d2620 100644
--- a/src/onaptests/steps/simulator/pnf/pnf_instantiate.py
+++ b/src/onaptests/steps/simulator/pnf/pnf_instantiate.py
@@ -18,6 +18,7 @@ class PNFInstanceStep(BaseStep):
     @BaseStep.store_state
     def execute(self) -> None:
         """Run PNF simulator containers."""
+        super().execute()
         utils.build_image()
         utils.bootstrap_simulator()
         utils.run_container()
diff --git a/tests/test_store_state.py b/tests/test_store_state.py
index f5fcc62..8b3a728 100644
--- a/tests/test_store_state.py
+++ b/tests/test_store_state.py
@@ -1,3 +1,5 @@
+from time import sleep
+
 import pytest
 
 from onaptests.steps.base import BaseStep
@@ -35,6 +37,37 @@ class TestFailStep(BaseStep):
         return "Test"
 
 
+class TestOneSecStep(BaseStep):
+
+    @BaseStep.store_state
+    def execute(self):
+        super().execute()
+        sleep(1)
+
+    @property
+    def description(self):
+        return "One second test step"
+
+    @property
+    def component(self) -> str:
+        return "Test"
+
+
+class TestStepNoSuperExecute(BaseStep):
+
+    @BaseStep.store_state
+    def execute(self):
+        sleep(1)
+
+    @property
+    def description(self):
+        return "One second test step - no super execute call"
+
+    @property
+    def component(self) -> str:
+        return "Test"
+
+
 def test_store_state():
     ts = TestStep()
     ts.execute()
@@ -56,3 +89,26 @@ def test_store_state():
     assert rep_s.step_description == "[Test] TestStep: Test pass step"
     assert rep_s.step_execution_status.value == "PASS"
     assert rep_s.step_execution_duration != 0
+
+
+def test_store_state_time_measurement():
+
+    ts = TestOneSecStep()
+    ts.execute()
+    assert len(ts.reports_collection.report) == 1
+    rep = ts.reports_collection.report[0]
+    assert rep.step_execution_duration > 1
+
+    ts = TestOneSecStep()
+    ts.add_step(TestOneSecStep())
+    ts.execute()
+    assert len(ts.reports_collection.report) == 2
+    rep_one, rep_two = ts.reports_collection.report
+    assert rep_one.step_execution_duration > 1 and rep_one.step_execution_duration < 2
+    assert rep_two.step_execution_duration > 1 and rep_two.step_execution_duration < 2
+
+    ts = TestStepNoSuperExecute()
+    ts.execute()
+    assert len(ts.reports_collection.report) == 1
+    rep = ts.reports_collection.report[0]
+    assert rep.step_execution_duration < 1