Log parsing on full data (#1276)

* measurement_flow_process_duration is set in any case. Supplying a timeout of None will lead to no timeout

* Log parsing is now done on full data

* Introduced simpler handling of post processing steps; Improved cleaning routine of runner private attributes; Small Bugfixes

* Test fix

* Fixed SCI parsing and added multi test

* Added test file

* Changed all function names to _XXX to indicate that they should not be used externally

* Adapted test_functions to use new runner function names and _post_process mechanism

* Test-fix

Author: ArneTR

lib/notes.py

@@ -1,4 +1,4 @@
-from re import fullmatch
+import re
 
 from lib.db import DB
 
@@ -22,26 +22,21 @@ def save_to_db(self, run_id):
                     """,
                        params=(run_id, note['detail_name'], note['note'], int(note['timestamp']))
                        )
+    def parse_and_add_notes(self, detail_name, data):
+        for match in re.findall(r'^(\d{16}) (.+)$', data, re.MULTILINE):
+            self.__notes.append({'note': match[1], 'detail_name': detail_name, 'timestamp': match[0]})
 
-    def parse_note(self, line):
-        if match := fullmatch(r'^(\d{16}) (.+)', line):
-            return int(match[1]), match[2]
-        return None
-
-    def add_note(self, note):
-        self.__notes.append(note)
+    def add_note(self, note, detail_name, timestamp):
+        self.__notes.append({'note': note , 'detail_name': detail_name, 'timestamp': timestamp})
 
 if __name__ == '__main__':
     import argparse
-    import time
 
     parser = argparse.ArgumentParser()
     parser.add_argument('run_id', help='Please supply a run_id to attribute the measurements to')
 
     args = parser.parse_args()  # script will exit if arguments not present
 
     notes = Notes()
-    notes.add_note({'note': 'This is my note',
-                 'timestamp': int(time.time_ns() / 1000),
-                 'detail_name': 'Arnes_ Container'})
+    notes.parse_and_add_notes('my container', '1234567890123456 My note')
     notes.save_to_db(args.run_id)

lib/scenario_runner.py

@@ -0,0 +1,29 @@
+---
+name: Test Stress
+author: Dan Mateas
+description: test
+
+sci:
+  R_d: Cool run
+
+services:
+  test-container:
+    type: container
+    image: gcb_stress
+    build:
+      context: ../stress-application
+
+flow:
+  - name: Stress
+    container: test-container
+    commands:
+      - type: console
+        shell: sh
+        command: stress-ng -c 1 -t 1 -q; echo GMT_SCI_R=500
+        log-stdout: True
+        read-sci-stdout: True
+      - type: console
+        shell: sh
+        command: stress-ng -c 1 -t 1 -q; echo GMT_SCI_R=600
+        log-stdout: True
+        read-sci-stdout: True

tests/data/usage_scenarios/stress_sci_multi.yml

@@ -410,3 +410,17 @@ def test_sci_run():
     assert len(data) == 1
     assert 50 < data[0]['value'] < 150
     assert data[0]['unit'] == 'ugCO2e/Cool run'
+
+def test_sci_multi_steps_run():
+    runner = ScenarioRunner(uri=GMT_ROOT_DIR, uri_type='folder', filename='tests/data/usage_scenarios/stress_sci_multi.yml', skip_system_checks=True, dev_cache_build=True, dev_no_sleeps=True, dev_no_metrics=False, dev_no_phase_stats=False)
+
+    out = io.StringIO()
+    err = io.StringIO()
+    with redirect_stdout(out), redirect_stderr(err):
+        run_id = runner.run()
+
+    data = DB().fetch_all("SELECT value, unit FROM phase_stats WHERE phase = %s AND run_id = %s AND metric = 'software_carbon_intensity_global' ", params=('004_[RUNTIME]', run_id), fetch_mode='dict')
+
+    assert len(data) == 1
+    assert 8 < data[0]['value'] < 20
+    assert data[0]['unit'] == 'ugCO2e/Cool run'

tests/lib/test_phase_stats.py

@@ -13,23 +13,23 @@
 ]
 
 
-@pytest.mark.parametrize("run_id,note,detail,timestamp", invalid_test_data)
-def test_invalid_timestamp(run_id, note, detail, timestamp):
+@pytest.mark.parametrize("run_id,note,detail_name,timestamp", invalid_test_data)
+def test_invalid_timestamp(run_id, note, detail_name, timestamp):
     with pytest.raises(ValueError) as err:
         notes = Notes()
-        notes.add_note({"note": note,"detail_name": detail,"timestamp": timestamp,})
+        notes.add_note(note, detail_name, timestamp)
         notes.save_to_db(run_id)
     expected_exception = "invalid literal for int"
     assert expected_exception in str(err.value), \
         Tests.assertion_info(f"Exception: {expected_exception}", str(err.value))
 
-@pytest.mark.parametrize("run_id,note,detail,timestamp", valid_test_data)
+@pytest.mark.parametrize("run_id,note,detail_name,timestamp", valid_test_data)
 @patch('lib.db.DB.query')
-def test_valid_timestamp(mock_query, run_id, note, detail, timestamp):
+def test_valid_timestamp(mock_query, run_id, note, detail_name, timestamp):
     mock_query.return_value = None  # Replace with the desired return value
 
     notes = Notes()
-    notes.add_note({"note": note, "detail_name": detail, "timestamp": timestamp})
+    notes.add_note(note, detail_name, timestamp)
     notes.save_to_db(run_id)
 
     mock_query.assert_called_once()

tests/lib/test_save_notes.py

@@ -277,79 +277,70 @@ def run_until(self, step):
             raise RuntimeError("run_until must be used within the context")
 
         try:
-            self.__runner.start_measurement()
-            self.__runner.clear_caches()
-            self.__runner.check_system('start')
-            self.__runner.initialize_folder(self.__runner._tmp_folder)
-            self.__runner.checkout_repository()
-            self.__runner.load_yml_file()
-            self.__runner.initial_parse()
-            self.__runner.register_machine_id()
-            self.__runner.import_metric_providers()
+            self.__runner._start_measurement()
+            self.__runner._clear_caches()
+            self.__runner._check_system('start')
+            self.__runner._initialize_folder(self.__runner._tmp_folder)
+            self.__runner._checkout_repository()
+            self.__runner._load_yml_file()
+            self.__runner._initial_parse()
+            self.__runner._register_machine_id()
+            self.__runner._import_metric_providers()
             if step == 'import_metric_providers':
                 return
-            self.__runner.populate_image_names()
-            self.__runner.prepare_docker()
-            self.__runner.check_running_containers()
-            self.__runner.remove_docker_images()
-            self.__runner.download_dependencies()
-            self.__runner.initialize_run()
+            self.__runner._populate_image_names()
+            self.__runner._prepare_docker()
+            self.__runner._check_running_containers()
+            self.__runner._remove_docker_images()
+            self.__runner._download_dependencies()
+            self.__runner._initialize_run()
 
-            self.__runner.start_metric_providers(allow_other=True, allow_container=False)
-            self.__runner.custom_sleep(self.__runner._measurement_pre_test_sleep)
+            self.__runner._start_metric_providers(allow_other=True, allow_container=False)
+            self.__runner._custom_sleep(self.__runner._measurement_pre_test_sleep)
 
-            self.__runner.start_phase('[BASELINE]')
-            self.__runner.custom_sleep(self.__runner._measurement_baseline_duration)
-            self.__runner.end_phase('[BASELINE]')
+            self.__runner._start_phase('[BASELINE]')
+            self.__runner._custom_sleep(self.__runner._measurement_baseline_duration)
+            self.__runner._end_phase('[BASELINE]')
 
-            self.__runner.start_phase('[INSTALLATION]')
-            self.__runner.build_docker_images()
-            self.__runner.end_phase('[INSTALLATION]')
+            self.__runner._start_phase('[INSTALLATION]')
+            self.__runner._build_docker_images()
+            self.__runner._end_phase('[INSTALLATION]')
 
-            self.__runner.save_image_and_volume_sizes()
+            self.__runner._save_image_and_volume_sizes()
 
-            self.__runner.start_phase('[BOOT]')
-            self.__runner.setup_networks()
+            self.__runner._start_phase('[BOOT]')
+            self.__runner._setup_networks()
             if step == 'setup_networks':
                 return
-            self.__runner.setup_services()
+            self.__runner._setup_services()
             if step == 'setup_services':
                 return
-            self.__runner.end_phase('[BOOT]')
-
-            self.__runner.add_containers_to_metric_providers()
-            self.__runner.start_metric_providers(allow_container=True, allow_other=False)
-
-            self.__runner.start_phase('[IDLE]')
-            self.__runner.custom_sleep(self.__runner._measurement_idle_duration)
-            self.__runner.end_phase('[IDLE]')
-
-            self.__runner.start_phase('[RUNTIME]')
-            self.__runner.run_flows() # can trigger debug breakpoints;
-            self.__runner.end_phase('[RUNTIME]')
-
-            self.__runner.start_phase('[REMOVE]')
-            self.__runner.custom_sleep(1)
-            self.__runner.end_phase('[REMOVE]')
-
-            self.__runner.end_measurement()
-            self.__runner.check_process_returncodes()
-            self.__runner.identify_invalid_run()
-            self.__runner.custom_sleep(self.__runner._measurement_post_test_sleep)
-            self.__runner.update_start_and_end_times()
-            self.__runner.store_phases()
-            self.__runner.read_container_logs()
-            self.__runner.stop_metric_providers()
-            self.__runner.read_and_cleanup_processes()
-            self.__runner.save_notes_runner()
-            self.__runner.save_stdout_logs()
-
-            if self.__runner._dev_no_phase_stats is False:
-                from tools.phase_stats import build_and_store_phase_stats # pylint: disable=import-outside-toplevel
-                build_and_store_phase_stats(self.__runner._run_id, self.__runner._sci)
+            self.__runner._end_phase('[BOOT]')
+
+            self.__runner._add_containers_to_metric_providers()
+            self.__runner._start_metric_providers(allow_container=True, allow_other=False)
+
+            self.__runner._start_phase('[IDLE]')
+            self.__runner._custom_sleep(self.__runner._measurement_idle_duration)
+            self.__runner._end_phase('[IDLE]')
+
+            self.__runner._start_phase('[RUNTIME]')
+            self.__runner._run_flows() # can trigger debug breakpoints;
+            self.__runner._end_phase('[RUNTIME]')
+
+            self.__runner._start_phase('[REMOVE]')
+            self.__runner._custom_sleep(1)
+            self.__runner._end_phase('[REMOVE]')
+
+            self.__runner._end_measurement()
+            self.__runner._check_process_returncodes()
+            self.__runner._check_system('end')
+            self.__runner._custom_sleep(self.__runner._measurement_post_test_sleep)
+            self.__runner._identify_invalid_run()
+            self.__runner._post_process(0)
 
         except BaseException as exc:
-            self.__runner.add_to_log(exc.__class__.__name__, str(exc))
+            self.__runner._add_to_log(exc.__class__.__name__, str(exc))
             raise exc
 
     def __exit__(self, exc_type, exc_value, traceback):

tests/test_functions.py

@@ -329,7 +329,7 @@ def test_check_system(skip_system_checks, config_file, expectation):
 
     try:
         with expectation:
-            runner.check_system()
+            runner._check_system('start')
     finally:
         GlobalConfig().override_config(config_location=f"{os.path.dirname(os.path.realpath(__file__))}/test-config.yml") # reset, just in case. although done by fixture
 

tests/test_runner.py

@@ -13,9 +13,9 @@ def test_includes(self):
         name = 'test_' + utils.randomword(12)
 
         runner = ScenarioRunner(name=name, uri=GMT_DIR, uri_type='folder', filename=test_root_file)
-        runner.checkout_repository() # We need to do this to setup the file paths correctly
+        runner._checkout_repository() # We need to do this to setup the file paths correctly
 
-        runner.load_yml_file()
+        runner._load_yml_file()
         result_obj = {'name': 'Import Test',
                     'services': {'test-container':
                                     {'type': 'container'}},
@@ -28,9 +28,9 @@ def test_(self):
         name = 'test_' + utils.randomword(12)
 
         runner = ScenarioRunner(name=name, uri=GMT_DIR, uri_type='folder', filename=test_root_file)
-        runner.checkout_repository() # We need to do this to setup the file paths correctly
+        runner._checkout_repository() # We need to do this to setup the file paths correctly
 
-        runner.load_yml_file()
+        runner._load_yml_file()
         result_obj = {'name': 'my sample flow',
                       'author': 'Arne Tarara',
                       'description': 'test',
@@ -50,5 +50,5 @@ def test_invalid_path(self):
         name = 'test_' + utils.randomword(12)
         test_root_file = 'tests/data/usage_scenarios/import_error.yml'
         runner = ScenarioRunner(name=name, uri=GMT_DIR, uri_type='folder', filename=test_root_file)
-        runner.checkout_repository() # We need to do this to setup the file paths correctly
-        self.assertRaises(ValueError, runner.load_yml_file)
+        runner._checkout_repository() # We need to do this to setup the file paths correctly
+        self.assertRaises(ValueError, runner._load_yml_file)