TST: Slightly changed logging behaviour, step_id and run_id added

progress_view.py can be sorted by execution_id
tooltip text-code implemented (not completly finished)

Tst/confignator/confignator/config.py

@@ -72,7 +72,7 @@ fmt += '%(thread)s\t'
 fmt += '%(threadName)s\t'
 
 logging_format = fmt
-logging_level_file = logging.DEBUG
+logging_level_file = logging.INFO
 logging_level_console = logging.WARNING
 module_logger = logging.getLogger(__name__)
 module_logger.setLevel(logging.DEBUG)

Tst/testing_library/testlib/analyse_command_log.py

@@ -80,18 +80,29 @@ def get_steps_and_commands(filename):
     :rtype: list of dict
     """
     steps = []
+    steps_start = []
+    steps_end = []
 
-    def new_step_template():
+    def new_step_template_start():
         return {'step': None, 'version': '', 'tcs': [], 'date': ''}
 
-    new_step = new_step_template()
+    def new_step_template_end():
+        return {'step': None, 'timestamp': '', 'step_id': ''}
+
+    new_step = new_step_template_start()
+    run_count = 1
 
     with open(filename, 'r') as fileobject:
         for line in fileobject:
+            #if report.key_word_found(line, report.cmd_test_start_keyword):
+                # Get general infos about the whole test, append to every step of this run
+                #general_step_info = report.parse_step_from_json_string(line, report.cmd_test_start_keyword)
+                #general_step_info['run_count'] = str(run_count)
+                #run_count += 1
             if report.key_word_found(line, report.cmd_step_keyword):
                 if new_step['step'] is not None:
-                    steps.append(new_step)
-                new_step = new_step_template()
+                    steps_start.append(new_step)
+                new_step = new_step_template_start()
                 # get date of the step execution
                 new_step['exec_date'] = testing_logger.extract_date(line)
                 # get the information about the step
@@ -100,6 +111,13 @@ def get_steps_and_commands(filename):
                     new_step['step'] = step_start_info['step']
                     new_step['start_timestamp'] = step_start_info['timestamp']
                     new_step['version'] = step_start_info['version']
+                    new_step['descr'] = step_start_info['descr']
+                    new_step['run_id'] = step_start_info['run_id']
+                    new_step['step_id'] = step_start_info['step_id']
+                #try:
+                #    new_step['general_run_info'] = general_step_info
+                #except:
+                #    new_step['general_run_info'] = None
             if tcid.key_word_found(line):
                 new_tc_id = tcid.TcId()
                 new_tc_id.parse_tc_id_from_json_string(line=line)
@@ -109,16 +127,29 @@ def get_steps_and_commands(filename):
             if report.key_word_found(line, report.cmd_step_keyword_done):
                 step_end_info = report.parse_step_from_json_string(line, report.cmd_step_keyword_done)
                 if step_end_info is not None:
-                    if new_step['step'] == step_end_info['step']:
-                        new_step['end_timestamp'] = step_end_info['timestamp']
-                    else:
-                        print('get_steps_and_commands: the step number in the step-end string is different than the'
-                              'step number of the last step-start string.')
+                    new_step_end = new_step_template_end()
+                    new_step_end['step'] = step_end_info['step']
+                    new_step_end['timestamp'] = step_end_info['timestamp']
+                    new_step_end['step_id'] = step_end_info['step_id']
+                    steps_end.append(new_step_end)
+                    #if new_step['step'] == step_end_info['step']:
+                    #    new_step['end_timestamp'] = step_end_info['timestamp']
+                    #else:
+                    #    print('get_steps_and_commands: the step number in the step-end string is different than the'
+                    #          'step number of the last step-start string.')
         if new_step['step'] is not None:
-            steps.append(new_step)
+            steps_start.append(new_step)
         fileobject.close()
 
-    return steps
+    if len(steps_end) > len(steps_start):
+        print('More steps ended than started, something went wrong')
+
+    for start_info in steps_start:
+        for end_info in steps_end:
+            if start_info['step_id'] == start_info['step_id']:
+                start_info['end_timestamp'] = end_info['timestamp']
+
+    return steps_start
 
 
 if __name__ == '__main__':

Tst/testing_library/testlib/analyse_verification_log.py

@@ -15,16 +15,23 @@ def get_verification_steps(filename):
              end timestamp (CUC) of the verification and the result of the verification for this step
     :rtype: list of dict
     """
+
     vrc_start = []
     vrc_end = []
+    id_codes = {}
     with open(filename, 'r') as fileobject:
         for line in fileobject:
             if report.key_word_found(line, report.vrc_step_keyword):
                 new_dict = report.parse_step_from_json_string(line, report.vrc_step_keyword)
                 new_dict['exec_date'] = testing_logger.extract_date(line)
+                #new_dict['id_code'] = line.split('\t')[2]
+                #id_codes[line.split('\t')[2]] = int(line.split('\t')[2])
                 vrc_start.append(new_dict)
             if report.key_word_found(line, report.vrc_step_keyword_done):
-                vrc_end.append(report.parse_step_from_json_string(line, report.vrc_step_keyword_done))
+                new_dict = report.parse_step_from_json_string(line, report.vrc_step_keyword_done)
+                #new_dict['id_code'] = line.split('\t')[2]
+                #id_codes[line.split('\t')[2]] = int(line.split('\t')[2])
+                vrc_end.append(new_dict)
         fileobject.close()
 
     # print('\nfound {} steps:'.format(len(vrc_start)))
@@ -33,6 +40,9 @@ def get_verification_steps(filename):
     #
     # for item in vrc_start:
     #     print('Verification end for Step {} @ {}'.format(item['step'], item['timestamp']))
+    #exec_count = 1
+    if len(vrc_end) > len(vrc_start):
+        print('There are more steps finished than started, something went wrong')
 
     vrc_steps = []
     for item in vrc_start:
@@ -41,8 +51,12 @@ def get_verification_steps(filename):
         new_vrc_step['start_timestamp'] = item['timestamp']
         new_vrc_step['exec_date'] = item['exec_date']
         new_vrc_step['version'] = item['version']
+        new_vrc_step['descr'] = item['descr']
+        new_vrc_step['run_id'] = item['run_id']
+        new_vrc_step['step_id'] = item['step_id']
         for element in vrc_end:
-            if element['step'] == item['step']:
+            if element['step_id'] == item['step_id']:
+                #new_vrc_step['run_count'] = id_run_count[element['id_code']]
                 new_vrc_step['end_timestamp'] = element['timestamp']
                 new_vrc_step['result'] = element['result']
         vrc_steps.append(new_vrc_step)

Tst/testing_library/testlib/report.py

@@ -3,7 +3,7 @@
 Report - writing log entries
 ============================
 """
-import datetime
+from datetime import datetime
 import logging
 import collections
 import json
@@ -13,15 +13,23 @@ import confignator
 sys.path.append(confignator.get_option('paths', 'ccs'))
 import ccs_function_lib as cfl
 
-# create a logger
+# create logger
 logger = logging.getLogger(__name__)
+#now = datetime.now()  # current date and time
+#code = now.strftime("%Y%m%d%H%M%S")
+#extra = {'id_code': code}
+#logger = logging.LoggerAdapter(logger, extra)
+
+import datetime
 
+cmd_test_start_keyword = '#START TEST'
 cmd_step_keyword = '#COMMAND STEP'
 cmd_step_exception_keyword = 'EXCEPTION IN STEP'
 cmd_step_keyword_done = '#STEP DONE'  # ATTENTION! The _done keyword must not contain the start keyword
+vrc_test_start_keyword = '#START VERIFICATION'
 vrc_step_keyword = '#VERIFICATION FOR STEP'
 vrc_step_exception_keyword = 'EXCEPTION IN STEP'
-vrc_step_keyword_done = '#VERIFICATION DONE'  # ATTENTION! The _done keyword must not contain the start keyword
+vrc_step_keyword_done = '#VERIFICATION STEP DONE'  # ATTENTION! The _done keyword must not contain the start keyword
 
 
 def key_word_found(line, key_word):
@@ -40,7 +48,7 @@ def key_word_found(line, key_word):
     return found
 
 
-def encode_to_json_string(step_number, timestamp, step_version=None, step_result=None):
+def encode_to_json_string(step_number, timestamp, step_version=None, step_result=None, descr=None, run_id=None, step_id=None):
     """
     Make a JSON string out of the step number and timestamp
     :param step_number: number of the step
@@ -54,9 +62,21 @@ def encode_to_json_string(step_number, timestamp, step_version=None, step_result
         od['version'] = step_version
     if step_result is not None:
         od['result'] = step_result
+    if descr is not None:
+        od['descr'] = descr
+    if run_id is not None:
+        od['run_id'] = run_id
+    if step_id is not None:
+        od['step_id'] = step_id
     json_string = json.dumps(od)
     return json_string
 
+def make_json_string(*args, **kwargs):
+    od = {}
+    for key, value in kwargs.items():
+        od[str(key)] = value
+    json_string = json.dumps(od)
+    return json_string
 
 def parse_step_from_json_string(line, key_word):
     """
@@ -85,7 +105,7 @@ def parse_step_from_json_string(line, key_word):
             logger.error('parse_tc_id_from_json_string: parsing of the TC JSON string failed!')
 
 
-def command_step_begin(step_param, script_version, pool_name, step_start_cuc):
+def command_step_begin(step_param, script_version, pool_name, step_start_cuc, run_id, step_id):
     """
     Builds a string and writes it into the logging file. A keyword is set to enable a machine read out of the log file.
     All information of the step is written in a JSON string.
@@ -95,48 +115,57 @@ def command_step_begin(step_param, script_version, pool_name, step_start_cuc):
     :param step_start_cuc:
     :return:
     """
+    #print(step_param)
     logger.info('{} {} {}'.format(cmd_step_keyword,
                                   step_param['step_no'],
                                   encode_to_json_string(step_number=step_param['step_no'],
                                                         timestamp=step_start_cuc,
-                                                        step_version=script_version)))
-    logger.info(step_param['msg'])
+                                                        step_version=script_version,
+                                                        run_id=run_id,
+                                                        step_id=step_id,
+                                                        descr=step_param['descr'])))
+    logger.info(step_param['descr'])
     if 'comment' in step_param:
         if len(step_param['comment']) > 0:
             logger.info('Comment: {}'.format(step_param['comment']))
 
 
-def command_step_exception(step_param):
-    logger.warning('{} {}'.format(cmd_step_exception_keyword,
-                                  step_param['step_no']))
+def command_step_exception(step_param, step_id=None):
+    logger.warning('{} {} {}'.format(cmd_step_exception_keyword,
+                                  step_param['step_no'], make_json_string(step_id=step_id)))
 
 
-def command_step_end(step_param, step_end_cuc):
-    logger.info('{} {}\n'.format(cmd_step_keyword_done, encode_to_json_string(step_param['step_no'], step_end_cuc)))
+def command_step_end(step_param, step_end_cuc, step_id):
+    logger.info('{} {}\n'.format(cmd_step_keyword_done, encode_to_json_string(step_param['step_no'], step_end_cuc, step_id=step_id)))
 
 
-def verification_step_begin(step_param, script_version, pool_name, step_start_cuc):
+def verification_step_begin(step_param, script_version, pool_name, step_start_cuc, run_id, step_id):
+
     logger.info('{} {} {}'.format(vrc_step_keyword,
                                   step_param['step_no'],
                                   encode_to_json_string(step_number=step_param['step_no'],
                                                         timestamp=step_start_cuc,
-                                                        step_version=script_version)))
-    logger.info(step_param['msg'])
+                                                        step_version=script_version,
+                                                        run_id=run_id,
+                                                        step_id=step_id,
+                                                        descr=step_param['descr'])))
+    logger.info(step_param['descr'])
     if 'comment' in step_param:
         if len(step_param['comment']) > 0:
             logger.info('Comment: {}'.format(step_param['comment']))
 
 
-def verification_step_exception(step_param):
-    logger.warning('{} {}'.format(vrc_step_exception_keyword,
-                                  step_param['step_no']))
+def verification_step_exception(step_param, step_id=None):
+    logger.warning('{} {} {}'.format(vrc_step_exception_keyword,
+                                  step_param['step_no'], make_json_string(step_id=step_id)))
 
 
-def verification_step_end(step_param, step_result, step_end_cuc):
+def verification_step_end(step_param, step_result, step_end_cuc, step_id):
     logger.info('{} {} {}'.format(vrc_step_keyword_done,
                                   step_param['step_no'],
                                   encode_to_json_string(step_number=step_param['step_no'],
                                                         timestamp=step_end_cuc,
+                                                        step_id=step_id,
                                                         step_result=step_result)))
     if step_result is True:
         logger.info('Verification for step {} was passed successful. +++ OK +++\n'.format(step_param['step_no']))
@@ -154,12 +183,12 @@ class StepSummary:
     def had_exception(self):
         self.has_exception = True
 # --------------------------------------------
-
+# Command log output
 
 def write_log_step_header(step_param, pool_name, step_start_cuc):
     logger.info('STEP {} (starting from {})'
              .format(step_param['step_no'], step_start_cuc))
-    logger.info(step_param['msg'])
+    logger.info(step_param['descr'])
     if 'comment' in step_param:
         if len(step_param['comment']) > 0:
             logger.info('Comment: {}'.format(step_param['comment']))
@@ -171,13 +200,20 @@ def write_log_step_footer(step_param, step_result):
     else:
         logger.warning('Step {} failed.'.format(step_param['step_no']))
 
-
-def write_log_test_header(test, pool_name):
+def write_log_test_header(test, pool_name=None):
     logger.info('-------------------------------------------------------------------------------')
-    logger.info('Running test {}\n\t\t\t\t\tversion {}\n\t\t\t\t\tpoolname = {}\n\t\t\t\t\tCUC-timestamp of test '
-             'start = {}\n\t\t\t\t\tlocal time = {}'
-             .format(test.id, test.version, pool_name, cfl.get_last_pckt_time(pool_name=pool_name, string=False),
-                     datetime.datetime.now().isoformat()))
+    #logger.info('#Start Test: {}\n\t\t\t\t\tversion {}\n\t\t\t\t\tpoolname = {}\n\t\t\t\t\tCUC-timestamp of test '
+    #         'start = {}\n\t\t\t\t\tlocal time = {}'
+    #         .format(test.id, test.version, pool_name, cfl.get_last_pckt_time(pool_name=pool_name, string=False),
+    #                 datetime.datetime.now().isoformat()))
+    date_time = datetime.datetime.now().isoformat()
+    logger.info('{} {}'.format(cmd_test_start_keyword, make_json_string(test_name=test.id,
+    #                                                    version=test.version,
+                                                        pool_name=pool_name,
+                                                        cuc_start_time=cfl.get_last_pckt_time(pool_name=pool_name, string=False),
+                                                        local_start_time=date_time,
+                                                        run_id=test.run_id)))
+
     logger.info('#Description: {} \n'.format(test.description))
     if test.comment:
         logger.info('Comment: {}'.format(test.comment))
@@ -270,3 +306,4 @@ def write_postcondition_outcome(result):
         logger.info('Postconditions are fulfilled.\n')
     else:
         logger.warning('Postconditions are NOT fulfilled.\n')
+

Tst/testing_library/testlib/testing_logger.py

@@ -7,6 +7,7 @@ import logging.config
 import os
 import datetime
 import confignator
+#from datetime import datetime
 
 from . import tools
 
@@ -73,7 +74,12 @@ def extract_date(line):
 
 
 def my_formatter():
-    return logging.Formatter(fmt='%(levelname)s\t%(asctime)s\tlogger: %(name)s:\t%(message)s')
+    #return logging.Formatter(fmt='%(levelname)s\t%(asctime)s\t%(id_code)s\t%(name)s:\t%(message)s')
+    return logging.Formatter(fmt='%(levelname)s\t%(asctime)s\t%(name)s:\t%(message)s')
+
+#def my_formatter_vrc():
+#    return logging.Formatter(fmt='%(levelname)s\t%(asctime)s\t%(id_code)s\t%(name)s:\t%(message)s')
+    #return logging.Formatter(fmt='%(levelname)s\t%(asctime)s\t%(name)s:\t%(message)s')
 
 
 def cmd_log_handler(file_name):

Tst/tst/generator_templates/co_class.py

@@ -15,6 +15,7 @@ class ${testSpecClassName}:
         self.integrity = True
         self.exceptions = []
         self.do_verification = do_verification
+        self.run_id = False
 
         # some tests are depended on other tests, thus information is stored on class level
         # insert class variables here

Tst/tst/generator_templates/co_footer.py

@@ -15,6 +15,8 @@
         """
         testing_logger.cmd_log_handler(__name__)
 
+        self.run_id = False
+        self.check_run_and_step_id(pool_name=pool_name)
         # log the header of this test
         report.write_log_test_header(test=self, pool_name=pool_name)
 
@@ -56,6 +58,8 @@
         # save the packet pool
         self.save_pool_in_file(pool_name=pool_name, save_pool=save_pool)
 
+        self.run_id = False
+
         # log the summary of this test
         self.successful_steps = report.write_log_test_footer(test=self)
 
@@ -70,3 +74,9 @@
         if save_pool is True:
             pool_file = tools.get_path_for_testing_logs() + self.id + '.tmpool'
             cfl.savepool(filename=pool_file, pool_name=pool_name)
+
+    def check_run_and_step_id(self, pool_name=None):
+        now = datetime.now()  # current date and time
+        if not self.run_id and pool_name:
+            self.run_id = now.strftime("%Y%m%d%H%M%S")
+        return now.strftime("%Y%m%d%H%M%S%f")
\ No newline at end of file

Tst/tst/generator_templates/co_header.py

@@ -5,6 +5,7 @@ import os
 import time
 import importlib
 import threading
+from datetime import datetime
 import confignator
 ccs_path = confignator.get_option('paths', 'ccs')
 sys.path.append(ccs_path)

Tst/tst/generator_templates/co_post_condition.py

     # VERIFY EVERY STEP ------------------------------------------------------------------------------------------------
-    def step_verification(self, pool_name, step_start_cuc, param, summary, tc_id, ver_file, ver_class, ver_func):
+    def step_verification(self, pool_name, step_start_cuc, param, summary, tc_id, ver_file, ver_class, ver_func, step_id):
         """
         This functions does the verification for every step
         :param pool_name: str
@@ -25,7 +25,7 @@
                 ver_instance_call = getattr(ver_file, ver_class)
                 instance = ver_instance_call()
                 ver_func_call = getattr(instance, ver_func)
-                success = ver_func_call(pool_name, start_cuc=step_start_cuc, tc_id=tc_id)
+                success = ver_func_call(pool_name, start_cuc=step_start_cuc, tc_id=tc_id, run_id=self.run_id, step_id=step_id)
                 summary.result = success
             except:
                 logger.exception('Exception in the Verification for Step {}'.format(param['step_no']))
@@ -44,7 +44,7 @@
         :return: True if all conditions were successfull.
         :rtype: bool
         """
-        # testing_logger.cmd_log_handler(__name__)
+        testing_logger.cmd_log_handler(__name__)
         success = False
         logger.info('establishing postconditions started')
 

Tst/tst/generator_templates/co_post_condition_entry.py

@@ -13,3 +13,13 @@ print('Hello, I am the whole post-condition')
 #reset = tc.reset_all_housekeepings(pool_name=pool_name)
 success = True
 
+
+
+#####-Save-#####
+
+
+
+#####-Save-#####
+
+
+

Tst/tst/generator_templates/co_pre_condition.py

@@ -7,7 +7,7 @@
         :return: bool
             True if the preconditions are fulfilled
         """
-        #testing_logger.cmd_log_handler(__name__)
+        testing_logger.cmd_log_handler(__name__)
         success = False
         logger.info('establishing preconditions started')
 
@@ -32,10 +32,11 @@
         :return: tc_id:
         """
         testing_logger.cmd_log_handler(__name__)
+        step_id = self.check_run_and_step_id(pool_name=pool_name)
         step_start_cuc = cfl.get_last_pckt_time(pool_name=pool_name, string=False)
         report.command_step_begin(step_param=param, script_version=self.version(), pool_name=pool_name,
-                                  step_start_cuc=step_start_cuc)
+                                  step_start_cuc=step_start_cuc, run_id=self.run_id, step_id=step_id)
 
         summary = report.StepSummary(step_number=param['step_no'])
         tc_id = None
-        return step_start_cuc, summary, tc_id
+        return step_start_cuc, summary, tc_id, step_id

Tst/tst/generator_templates/co_pre_condition_entry.py

@@ -17,3 +17,13 @@ success = True
 
 
 
+#####-Save-#####
+
+
+
+
+
+#####-Save-#####
+
+
+

Tst/tst/generator_templates/co_step.py

@@ -2,10 +2,10 @@
     def step_${testStepNumber}(self, pool_name):
         param = {
             'step_no': '$testStepNumber',
-            'msg': '$testStepDescription',
+            'descr': '$testStepDescription',
             'comment': '$testStepComment'
         }
-        step_start_cuc, summary, tc_id = self.begin_steps(pool_name=pool_name, param=param)
+        step_start_cuc, summary, tc_id, step_id = self.begin_steps(pool_name=pool_name, param=param)
 
         try:
             ########---The defined step starts here---########
@@ -14,16 +14,16 @@
 
             ########---The defined step ends here---########
         except Exception as e:
-            report.command_step_exception(step_param=param)
+            report.command_step_exception(step_param=param, step_id=step_id)
             logger.exception('Exception in the try block of the step')
             summary.result = False
             summary.had_exception()
         finally:
             step_end_cuc = cfl.get_last_pckt_time(pool_name=pool_name, string=False)
-            report.command_step_end(step_param=param, step_end_cuc=step_end_cuc)
+            report.command_step_end(step_param=param, step_end_cuc=step_end_cuc, step_id=step_id)
 
         summary =self.step_verification(pool_name=pool_name, step_start_cuc=step_start_cuc, param=param, tc_id=tc_id,
                                         summary=summary, ver_file=${testSpecFileName}_verification,
-                                        ver_class="${testSpecClassName}Verification", ver_func="step_${testStepNumber}")
+                                        ver_class="${testSpecClassName}Verification", ver_func="step_${testStepNumber}", step_id=step_id)
 
         return summary

Tst/tst/generator_templates/run_header.py

@@ -10,6 +10,7 @@ print('current working directory: {}'.format(os.getcwd()))
 import confignator
 ccs_path = confignator.get_option('paths', 'ccs')
 sys.path.append(ccs_path)
+import ccs_function_lib as cfl
 cfl.add_tst_import_paths()
 from testlib import tools
 from testlib import report
@@ -18,7 +19,7 @@ from testlib import tc
 from testlib import precond
 from testlib import testing_logger
 from testlib import sim
-logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
+logging.basicConfig(stream=sys.stdout, level=logging.INFO)
 import ${testSpecFileName}_command
 import ${testSpecFileName}_verification
 

Tst/tst/generator_templates/ver_class.py

@@ -12,6 +12,7 @@ class ${testSpecClassName}Verification:
         self.precond_ok = False
         self.integrity = True
         self.exceptions = []
+        self.run_id = False
 
         # some tests are depended on other tests, thus information is stored on class level
         # insert class variables here
@@ -39,9 +40,22 @@ class ${testSpecClassName}Verification:
 
         # ------- analyze command log -> get step start CUC timestamps, TCid and step end CUC timestamps -------
         # ToDo
+        self.run_id = False
         steps = analyse_command_log.get_steps(filename=command_log_file)
         tcs = analyse_command_log.get_sent_tcs(filename=command_log_file)
         # ------- loop over the verification steps, show progress -------
         # ToDo
         # ------- show final result -------
         # ToDo
+
+    def vrc_step_begin(self, pool_name, param, run_id, step_id):
+        if run_id:
+            self.run_id = run_id
+        else:
+            if not self.run_id:
+                now = datetime.now()  # current date and time
+                self.run_id = now.strftime("%Y%m%d%H%M%S")
+
+        step_start_cuc = cfl.get_last_pckt_time(pool_name=pool_name, string=False)
+        report.verification_step_begin(step_param=param, script_version=self.version(), pool_name=pool_name,
+                                       step_start_cuc=step_start_cuc, run_id=self.run_id, step_id=step_id)

Tst/tst/generator_templates/ver_header.py

@@ -12,6 +12,7 @@ sys.path.append(confignator.get_option('tst-paths', 'testing_library'))
 
 import ccs_function_lib as cfl
 
+from datetime import datetime
 from testlib import report
 from testlib import analyse_command_log
 from testlib import testing_logger

Tst/tst/generator_templates/ver_step.py

     # STEP $testStepNumber --------------------------------------------------------------------------------------------------------
-    def step_$testStepNumber(self, pool_name, start_cuc=None, tc_id=None):
+    def step_$testStepNumber(self, pool_name, start_cuc=None, tc_id=None, run_id=None, step_id=None):
         testing_logger.ver_log_handler(__name__)
         param = {
             'step_no': '$testStepNumber',
-            'msg': '$testStepDescription',
+            'descr': '$testStepDescription',
             'comment': '$testStepComment'
         }
-        step_start_cuc = cfl.get_last_pckt_time(pool_name=pool_name, string=False)
-        report.verification_step_begin(step_param=param, script_version=self.version(), pool_name=pool_name, step_start_cuc=step_start_cuc)
-        # if online: use provided timestamp when the step started, use provided TcId
-        if start_cuc is not None:
-            pass
-        # if offline: read the command log file and extract the starting timestamp and TcId
-        else:
-            pass
+        self.vrc_step_begin(pool_name=pool_name, param=param, run_id=run_id, step_id=step_id)
 
         result = True
         try:
             $testStepVerificationCode
         except Exception as e:
-            report.verification_step_exception(step_param=param)
+            report.verification_step_exception(step_param=param, step_id=step_id)
             logger.exception('Exception in the try block of the step')
             result = False
         finally:
             step_end_cuc = cfl.get_last_pckt_time(pool_name=pool_name, string=False)
-            report.verification_step_end(step_param=param, step_result=result, step_end_cuc=step_end_cuc)
+            report.verification_step_end(step_param=param, step_result=result, step_end_cuc=step_end_cuc, step_id=step_id)
         return result