Implement per-test timeout guard

Timeout value can be specified by test in suite.conf:

config:
  suite:
    <suite_name>:
      <test_name>:
        timeout: 2 # 2 seconds timeout

Change-Id: I522f51f77f8be64ebfdb5d5e07ba92baf82d7706

doc/manuals/chapters/config.adoc

@@ -190,7 +190,18 @@ schema:
   a_suite_test_foo:
     one_test_parameter_for_test_foo: 'str'
     another_test_parameter_for_test_foo: ['bool_str']
+
+config:
+  suite:
+    <suite_name>:
+      some_suite_parameter: 3
+      a_suite_test_foo:
+        one_test_parameter_for_test_foo: 'hello'
+        timeout: 30 <1>
 ----
+<1> The per-test _timeout_ attribute is implicitly defined for all tests with
+type _duration_, and will trigger a timeout if test doesn't finish in time
+specified.
 
 [[scenarios_dir]]
 ==== 'scenarios_dir'

selftest/suite_test/suite_test.ok

@@ -15,6 +15,11 @@ cnf empty_dir: DBG: reading suite.conf
 cnf [PATH]/selftest/suite_test/suitedirA/empty_dir/suite.conf: ERR: FileNotFoundError: [Errno 2] No such file or directory: '[PATH]/selftest/suite_test/suitedirA/empty_dir/suite.conf'  [empty_dir↪[PATH]/selftest/suite_test/suitedirA/empty_dir/suite.conf]
 - valid suite dir
 cnf test_suite: DBG: reading suite.conf
+config:
+  suite:
+    test_suite:
+      test_timeout:
+        timeout: '1'
 resources:
   bts:
   - label: sysmoCell 5000
@@ -28,7 +33,7 @@ resources:
 
 - run hello world test
 tst test_suite: DBG: {combining='config'}
-tst {combining_scenarios='config'}: DBG: {definition_conf={}}  [test_suite↪{combining_scenarios='config'}]
+tst {combining_scenarios='config'}: DBG: {definition_conf={suite={test_suite={test_timeout={timeout='1'}}}}}  [test_suite↪{combining_scenarios='config'}]
 
 ---------------------------------------------------------------------
 trial test_suite
@@ -101,7 +106,7 @@ tst hello_world.py:[LINENR] Test passed (N.N sec)  [test_suite↪hello_world.py]
 ---------------------------------------------------------------------
 trial test_suite PASS
 ---------------------------------------------------------------------
-PASS: test_suite (pass: 1, skip: 6)
+PASS: test_suite (pass: 1, skip: 7)
     pass: hello_world.py (N.N sec)
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -109,6 +114,7 @@ PASS: test_suite (pass: 1, skip: 6)
     skip: test_fail.py
     skip: test_fail_raise.py
     skip: test_suite_params.py
+    skip: test_timeout.py
 
 - a test with an error
 
@@ -125,7 +131,7 @@ tst test_error.py:[LINENR]: Test FAILED (N.N sec)  [test_suite↪test_error.py:[
 ---------------------------------------------------------------------
 trial test_suite FAIL
 ---------------------------------------------------------------------
-FAIL: test_suite (fail: 1, skip: 6)
+FAIL: test_suite (fail: 1, skip: 7)
     skip: hello_world.py (N.N sec)
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -133,6 +139,7 @@ FAIL: test_suite (fail: 1, skip: 6)
     skip: test_fail.py
     skip: test_fail_raise.py
     skip: test_suite_params.py
+    skip: test_timeout.py
 
 - a test with a failure
 
@@ -149,7 +156,7 @@ tst test_fail.py:[LINENR]: Test FAILED (N.N sec)  [test_suite↪test_fail.py:[LI
 ---------------------------------------------------------------------
 trial test_suite FAIL
 ---------------------------------------------------------------------
-FAIL: test_suite (fail: 1, skip: 6)
+FAIL: test_suite (fail: 1, skip: 7)
     skip: hello_world.py (N.N sec)
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -157,6 +164,7 @@ FAIL: test_suite (fail: 1, skip: 6)
     FAIL: test_fail.py (N.N sec) EpicFail: This failure is expected
     skip: test_fail_raise.py
     skip: test_suite_params.py
+    skip: test_timeout.py
 
 - a test with a raised failure
 
@@ -172,7 +180,7 @@ tst test_fail_raise.py:[LINENR]: Test FAILED (N.N sec)  [test_suite↪test_fail_
 ---------------------------------------------------------------------
 trial test_suite FAIL
 ---------------------------------------------------------------------
-FAIL: test_suite (fail: 1, skip: 6)
+FAIL: test_suite (fail: 1, skip: 7)
     skip: hello_world.py (N.N sec)
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -180,9 +188,10 @@ FAIL: test_suite (fail: 1, skip: 6)
     skip: test_fail.py (N.N sec)
     FAIL: test_fail_raise.py (N.N sec) ExpectedFail: This failure is expected
     skip: test_suite_params.py
+    skip: test_timeout.py
 - test with half empty scenario
 tst test_suite: DBG: {combining='config'}  [suite.py:[LINENR]]
-tst {combining_scenarios='config'}: DBG: {definition_conf={}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
+tst {combining_scenarios='config'}: DBG: {definition_conf={suite={test_suite={test_timeout={timeout='1'}}}}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
 tst {combining_scenarios='config', scenario='foo'}: DBG: {conf={}, scenario='foo'}  [test_suite↪{combining_scenarios='config', scenario='foo'}]  [suite.py:[LINENR]]
 
 ---------------------------------------------------------------------
@@ -261,7 +270,7 @@ tst hello_world.py:[LINENR] Test passed (N.N sec)  [test_suite↪hello_world.py]
 ---------------------------------------------------------------------
 trial test_suite PASS
 ---------------------------------------------------------------------
-PASS: test_suite (pass: 1, skip: 6)
+PASS: test_suite (pass: 1, skip: 7)
     pass: hello_world.py (N.N sec)
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -269,9 +278,10 @@ PASS: test_suite (pass: 1, skip: 6)
     skip: test_fail.py
     skip: test_fail_raise.py
     skip: test_suite_params.py
+    skip: test_timeout.py
 - test with scenario
 tst test_suite: DBG: {combining='config'}  [suite.py:[LINENR]]
-tst {combining_scenarios='config'}: DBG: {definition_conf={}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
+tst {combining_scenarios='config'}: DBG: {definition_conf={suite={test_suite={test_timeout={timeout='1'}}}}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
 tst {combining_scenarios='config', scenario='foo'}: DBG: {conf={}, scenario='foo'}  [test_suite↪{combining_scenarios='config', scenario='foo'}]  [suite.py:[LINENR]]
 
 ---------------------------------------------------------------------
@@ -350,7 +360,7 @@ tst hello_world.py:[LINENR] Test passed (N.N sec)  [test_suite↪hello_world.py]
 ---------------------------------------------------------------------
 trial test_suite PASS
 ---------------------------------------------------------------------
-PASS: test_suite (pass: 1, skip: 6)
+PASS: test_suite (pass: 1, skip: 7)
     pass: hello_world.py (N.N sec)
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -358,9 +368,10 @@ PASS: test_suite (pass: 1, skip: 6)
     skip: test_fail.py
     skip: test_fail_raise.py
     skip: test_suite_params.py
+    skip: test_timeout.py
 - test with scenario and modifiers
 tst test_suite: DBG: {combining='config'}  [suite.py:[LINENR]]
-tst {combining_scenarios='config'}: DBG: {definition_conf={}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
+tst {combining_scenarios='config'}: DBG: {definition_conf={suite={test_suite={test_timeout={timeout='1'}}}}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
 tst {combining_scenarios='config', scenario='foo'}: DBG: {conf={}, scenario='foo'}  [test_suite↪{combining_scenarios='config', scenario='foo'}]  [suite.py:[LINENR]]
 tst test_suite: reserving resources in [PATH]/selftest/suite_test/test_work/state_dir ...  [suite.py:[LINENR]]
 tst test_suite: DBG: {combining='resources'}  [suite.py:[LINENR]]
@@ -485,7 +496,7 @@ tst hello_world.py:[LINENR] Test passed (N.N sec)  [test_suite↪hello_world.py]
 ---------------------------------------------------------------------
 trial test_suite PASS
 ---------------------------------------------------------------------
-PASS: test_suite (pass: 1, skip: 6)
+PASS: test_suite (pass: 1, skip: 7)
     pass: hello_world.py (N.N sec)
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -493,9 +504,10 @@ PASS: test_suite (pass: 1, skip: 6)
     skip: test_fail.py
     skip: test_fail_raise.py
     skip: test_suite_params.py
+    skip: test_timeout.py
 - test with suite-specific config
 tst test_suite: DBG: {combining='config'}  [suite.py:[LINENR]]
-tst {combining_scenarios='config'}: DBG: {definition_conf={}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
+tst {combining_scenarios='config'}: DBG: {definition_conf={suite={test_suite={test_timeout={timeout='1'}}}}}  [test_suite↪{combining_scenarios='config'}]  [suite.py:[LINENR]]
 tst {combining_scenarios='config', scenario='foo'}: DBG: {conf={suite={test_suite={some_suite_global_param='heyho', test_suite_params={one_bool_parameter='true', second_list_parameter=['23', '45']}}}}, scenario='foo'}  [test_suite↪{combining_scenarios='config', scenario='foo'}]  [suite.py:[LINENR]]
 tst test_suite: reserving resources in [PATH]/selftest/suite_test/test_work/state_dir ...  [suite.py:[LINENR]]
 tst test_suite: DBG: {combining='resources'}  [suite.py:[LINENR]]
@@ -614,13 +626,21 @@ trial test_suite test_suite_params.py
 tst test_suite_params.py:[LINENR]: starting test  [test_suite↪test_suite_params.py:[LINENR]]  [test_suite_params.py:[LINENR]]
 tst test_suite_params.py:[LINENR]: SPECIFIC SUITE CONFIG: {'some_suite_global_param': 'heyho',  [test_suite↪test_suite_params.py:[LINENR]]  [test_suite_params.py:[LINENR]]
 tst test_suite_params.py:[LINENR]:  'test_suite_params': {'one_bool_parameter': 'true',  [test_suite↪test_suite_params.py:[LINENR]]  [test_suite_params.py:[LINENR]]
-tst test_suite_params.py:[LINENR]:                        'second_list_parameter': ['23', '45']}}  [test_suite↪test_suite_params.py:[LINENR]]  [test_suite_params.py:[LINENR]]
+tst test_suite_params.py:[LINENR]:                        'second_list_parameter': ['23', '45']},  [test_suite↪test_suite_params.py:[LINENR]]  [test_suite_params.py:[LINENR]]
+tst test_suite_params.py:[LINENR]:  'test_timeout': {'timeout': '1'}}  [test_suite↪test_suite_params.py:[LINENR]]  [test_suite_params.py:[LINENR]]
 tst test_suite_params.py:[LINENR]: SPECIFIC TEST CONFIG: {'one_bool_parameter': 'true', 'second_list_parameter': ['23', '45']}  [test_suite↪test_suite_params.py:[LINENR]]  [test_suite_params.py:[LINENR]]
 tst test_suite_params.py:[LINENR] Test passed (N.N sec)  [test_suite↪test_suite_params.py]  [test.py:[LINENR]]
+
+----------------------------------------------
+trial test_suite test_timeout.py
+----------------------------------------------
+tst test_timeout.py:[LINENR]: starting test and waiting to receive Timeout after 1 seconds  [test_suite↪test_timeout.py:[LINENR]]  [test_timeout.py:[LINENR]]
+tst test_timeout.py:[LINENR]: ERR: Error: test_timeout.py:[LINENR] Test Timeout triggered: 1 seconds elapsed [test_suite↪test_timeout.py:[LINENR]↪test_timeout.py]  [test_suite↪test_timeout.py:[LINENR]]  [testenv.py:[LINENR]: raise log_module.Error('Test Timeout triggered: %d seconds elapsed' % self._test.elapsed_time())]
+tst test_timeout.py:[LINENR]: Test FAILED (N.N sec)  [test_suite↪test_timeout.py:[LINENR]]  [test.py:[LINENR]]
 ---------------------------------------------------------------------
-trial test_suite PASS
+trial test_suite FAIL
 ---------------------------------------------------------------------
-PASS: test_suite (pass: 1, skip: 6)
+FAIL: test_suite (fail: 1, pass: 1, skip: 6)
     skip: hello_world.py
     skip: mo_mt_sms.py
     skip: mo_sms.py
@@ -628,6 +648,7 @@ PASS: test_suite (pass: 1, skip: 6)
     skip: test_fail.py
     skip: test_fail_raise.py
     pass: test_suite_params.py (N.N sec)
+    FAIL: test_timeout.py (N.N sec) Error: test_timeout.py:[LINENR] Test Timeout triggered: 1 seconds elapsed [test_suite↪test_timeout.py:[LINENR]↪test_timeout.py]
 - test with template overlay
 cnf suiteC: DBG: reading suite.conf  [suite.py:[LINENR]]
 tst suiteC: DBG: {combining='config'}  [suite.py:[LINENR]]

selftest/suite_test/suite_test.py

@@ -102,7 +102,7 @@ sc['config'] = {'suite': {s.name(): { 'some_suite_global_param': 'heyho', 'test_
 s = suite.SuiteRun(trial, 'test_suite', s_def, [sc])
 s.reserve_resources()
 print(repr(s.reserved_resources))
-results = s.run_tests('test_suite_params.py')
+results = s.run_tests(['test_suite_params.py', 'test_timeout.py'])
 print(report.suite_to_text(s))
 
 print('- test with template overlay')

selftest/suite_test/suitedirA/test_suite/suite.conf

@@ -15,3 +15,9 @@ schema:
       one_bool_parameter: 'bool_str'
       second_list_parameter: ['uint']
 
+
+config:
+  suite:
+    test_suite:
+      test_timeout:
+        timeout: 1 # timeout in 1 second

selftest/suite_test/suitedirA/test_suite/test_timeout.py

@@ -0,0 +1,6 @@
+from osmo_gsm_tester.testenv import *
+
+timeout = int(tenv.config_test_specific()['timeout'])
+print('starting test and waiting to receive Timeout after %d seconds' % timeout)
+sleep(10)
+print('test failed, we expected timeout after %d seconds' % timeout)

src/osmo_gsm_tester/core/suite.py

@@ -44,6 +44,8 @@ class SuiteDefinition(log.Origin):
         self.suite_dir = suite_dir
         self.conf = None
         self._schema = None
+        self.test_basenames = []
+        self.load_test_basenames()
         self.read_conf()
 
     def read_conf(self):
@@ -54,13 +56,16 @@ class SuiteDefinition(log.Origin):
                                              SuiteDefinition.CONF_FILENAME))
         # Drop schema part since it's dynamically defining content, makes no sense to validate it.
         self._schema = self.conf.pop('schema', {})
+        # Add per-test 'timeout' attribute:
+        d = {t.rstrip('.py'):{'timeout': schema.DURATION} for t in self.test_basenames}
+        schema.combine(self._schema, d)
+        # Convert config file format to proper schema format and register it:
         sdef = schema.config_to_schema_def(self._schema, "%s." % self._suite_name)
         schema.register_config_schema('suite', sdef)
+        # Finally validate the file:
         schema.validate(self.conf, schema.get_all_schema())
-        self.load_test_basenames()
 
     def load_test_basenames(self):
-        self.test_basenames = []
         for basename in sorted(os.listdir(self.suite_dir)):
             if not basename.endswith('.py'):
                 continue

src/osmo_gsm_tester/core/test.py

@@ -35,12 +35,12 @@ class Test(log.Origin):
     PASS = 'pass'
     FAIL = 'FAIL'
 
-    def __init__(self, suite_run, test_basename, test_specific_config):
+    def __init__(self, suite_run, test_basename, config_test_specific):
         self.basename = test_basename
         super().__init__(log.C_TST, self.basename)
         self._run_dir = None
         self.suite_run = suite_run
-        self._config_test_specific = test_specific_config
+        self._config_test_specific = config_test_specific
         self.path = os.path.join(self.suite_run.definition.suite_dir, self.basename)
         self.status = Test.UNKNOWN
         self.start_timestamp = 0
@@ -49,6 +49,7 @@ class Test(log.Origin):
         self.fail_message = None
         self.log_targets = []
         self._report_stdout = None
+        self.timeout = int(config_test_specific['timeout']) if 'timeout' in config_test_specific else None
 
     def module_name(self):
         'Return test name without trailing .py'

src/osmo_gsm_tester/testenv.py

@@ -55,6 +55,8 @@ class TestEnv(log_module.Origin):
         self.test_import_modules_to_clean_up = []
         self.objects_to_clean_up = None
         MainLoop.register_poll_func(self.poll)
+        if self._test.timeout is not None: # aimed at firing once
+            MainLoop.register_poll_func(self.timeout_expired, timestep=self._test.timeout)
 
     def test(self):
         return self._test
@@ -120,6 +122,11 @@ class TestEnv(log_module.Origin):
             except Exception:
                 log_module.log_exn()
 
+    def timeout_expired(self):
+        # Avoid timeout being called several times:
+        MainLoop.unregister_poll_func(self.timeout_expired)
+        raise log_module.Error('Test Timeout triggered: %d seconds elapsed' % self._test.elapsed_time())
+
     def poll(self):
         for proc, respawn in self._processes:
             if proc.terminated():
@@ -139,6 +146,7 @@ class TestEnv(log_module.Origin):
         self.objects_cleanup()
         self.suite_run.reserved_resources.put_all()
         MainLoop.unregister_poll_func(self.poll)
+        MainLoop.unregister_poll_func(self.timeout_expired)
         self.test_import_modules_cleanup()
         self.set_overlay_template_dir(None)