From 1a7a3f0e4318bccbd3ed177d5b07fa3618d06868 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Sat, 10 Jun 2017 01:18:27 +0200 Subject: fix and refactor logging: drop 'with', simplify With the recent fix of the junit report related issues, another issue arose: the 'with log.Origin' was changed to disallow __enter__ing an object twice to fix problems, now still code would fail because it tries to do 'with' on the same object twice. The only reason is to ensure that logging is associated with a given object. Instead of complicating even more, implement differently. Refactor logging to simplify use: drop the 'with Origin' style completely, and instead use the python stack to determine which objects are created by which, and which object to associate a log statement with. The new way: we rely on the convention that each class instance has a local 'self' referencing the object instance. If we need to find an origin as a new object's parent, or to associate a log message with, we traverse each stack frame, fetching the first local 'self' object that is a log.Origin class instance. How to use: Simply call log.log() anywhere, and it finds an Origin object to log for, from the stack. Alternatively call self.log() for any Origin() object to skip the lookup. Create classes as child class of log.Origin and make sure to call super().__init__(category, name). This constructor will magically find a parent Origin on the stack. When an exception happens, we first escalate the exception up through call scopes to where ever it is handled by log.log_exn(). This then finds an Origin object in the traceback's stack frames, no need to nest in 'with' scopes. Hence the 'with log.Origin' now "happens implicitly", we can write pure natural python code, no more hassles with scope ordering. Furthermore, any frame can place additional logging information in a frame by calling log.ctx(). This is automatically inserted in the ancestry associated with a log statement / exception. Change-Id: I5f9b53150f2bb6fa9d63ce27f0806f0ca6a45e90 --- src/osmo_gsm_tester/suite.py | 91 +++++++++++++++++++++----------------------- 1 file changed, 43 insertions(+), 48 deletions(-) (limited to 'src/osmo_gsm_tester/suite.py') diff --git a/src/osmo_gsm_tester/suite.py b/src/osmo_gsm_tester/suite.py index 55f81b1..eeaf7df 100644 --- a/src/osmo_gsm_tester/suite.py +++ b/src/osmo_gsm_tester/suite.py @@ -49,9 +49,8 @@ class SuiteDefinition(log.Origin): def __init__(self, suite_dir): - self.set_log_category(log.C_CNF) self.suite_dir = suite_dir - self.set_name(os.path.basename(self.suite_dir)) + super().__init__(log.C_CNF, os.path.basename(self.suite_dir)) self.read_conf() def read_conf(self): @@ -78,12 +77,10 @@ class Test(log.Origin): FAIL = 'FAIL' def __init__(self, suite_run, test_basename): - self.suite_run = suite_run self.basename = test_basename + super().__init__(log.C_TST, self.basename) + self.suite_run = suite_run self.path = os.path.join(self.suite_run.definition.suite_dir, self.basename) - super().__init__(self.path) - self.set_name(self.basename) - self.set_log_category(log.C_TST) self.status = Test.UNKNOWN self.start_timestamp = 0 self.duration = 0 @@ -92,16 +89,15 @@ class Test(log.Origin): def run(self): try: - with self: - log.large_separator(self.suite_run.trial.name(), self.suite_run.name(), self.name(), sublevel=3) - self.status = Test.UNKNOWN - self.start_timestamp = time.time() - test.setup(self.suite_run, self, ofono_client, sys.modules[__name__], event_loop) - with self.redirect_stdout(): - util.run_python_file('%s.%s' % (self.suite_run.definition.name(), self.basename), - self.path) - if self.status == Test.UNKNOWN: - self.set_pass() + log.large_separator(self.suite_run.trial.name(), self.suite_run.name(), self.name(), sublevel=3) + self.status = Test.UNKNOWN + self.start_timestamp = time.time() + test.setup(self.suite_run, self, ofono_client, sys.modules[__name__], event_loop) + with self.redirect_stdout(): + util.run_python_file('%s.%s' % (self.suite_run.definition.name(), self.basename), + self.path) + if self.status == Test.UNKNOWN: + self.set_pass() except Exception as e: if hasattr(e, 'msg'): msg = e.msg @@ -110,14 +106,14 @@ class Test(log.Origin): if isinstance(e, AssertionError): # AssertionError lacks further information on what was # asserted. Find the line where the code asserted: - msg += log.get_src_from_tb(sys.exc_info()[2]) + msg += log.get_src_from_exc_info(sys.exc_info()) # add source file information to failure report if hasattr(e, 'origins'): msg += ' [%s]' % e.origins tb_str = traceback.format_exc() if isinstance(e, resource.NoResourceExn): tb_str += self.suite_run.resource_status_str() - self.set_fail(type(e).__name__, msg, tb_str) + self.set_fail(type(e).__name__, msg, tb_str, log.get_src_from_exc_info()) except BaseException as e: # when the program is aborted by a signal (like Ctrl-C), escalate to abort all. self.err('TEST RUN ABORTED: %s' % type(e).__name__) @@ -129,7 +125,7 @@ class Test(log.Origin): return '%s:%s' % (self._name, l) return super().name() - def set_fail(self, fail_type, fail_message, tb_str=None): + def set_fail(self, fail_type, fail_message, tb_str=None, src=4): self.status = Test.FAIL self.duration = time.time() - self.start_timestamp self.fail_type = fail_type @@ -140,9 +136,9 @@ class Test(log.Origin): tb_str = ''.join(traceback.format_stack()[:-1]) self.fail_tb = tb_str - self.err('%s: %s' % (self.fail_type, self.fail_message)) + self.err('%s: %s' % (self.fail_type, self.fail_message), _src=src) if self.fail_tb: - self.trace(self.fail_tb) + self.log(self.fail_tb, _level=log.L_TRACEBACK) self.log('Test FAILED (%.1f sec)' % self.duration) def set_pass(self): @@ -171,11 +167,10 @@ class SuiteRun(log.Origin): _processes = None def __init__(self, trial, suite_scenario_str, suite_definition, scenarios=[]): + super().__init__(log.C_TST, suite_scenario_str) self.trial = trial self.definition = suite_definition self.scenarios = scenarios - self.set_name(suite_scenario_str) - self.set_log_category(log.C_TST) self.resources_pool = resource.ResourcesPool() self.status = SuiteRun.UNKNOWN self.load_tests() @@ -201,18 +196,18 @@ class SuiteRun(log.Origin): self.status = SuiteRun.UNKNOWN def combined(self, conf_name): - self.dbg(combining=conf_name) - with log.Origin(combining_scenarios=conf_name): - combination = copy.deepcopy(self.definition.conf.get(conf_name) or {}) - self.dbg(definition_conf=combination) - for scenario in self.scenarios: - with scenario: - c = scenario.get(conf_name) - self.dbg(scenario=scenario.name(), conf=c) - if c is None: - continue - config.combine(combination, c) - return combination + log.dbg(combining=conf_name) + log.ctx(combining_scenarios=conf_name) + combination = copy.deepcopy(self.definition.conf.get(conf_name) or {}) + log.dbg(definition_conf=combination) + for scenario in self.scenarios: + log.ctx(combining_scenarios=conf_name, scenario=scenario.name()) + c = scenario.get(conf_name) + log.dbg(scenario=scenario.name(), conf=c) + if c is None: + continue + config.combine(combination, c) + return combination def resource_requirements(self): if self._resource_requirements is None: @@ -232,19 +227,18 @@ class SuiteRun(log.Origin): def run_tests(self, names=None): try: - with self: - log.large_separator(self.trial.name(), self.name(), sublevel=2) - self.mark_start() - event_loop.register_poll_func(self.poll) - if not self.reserved_resources: - self.reserve_resources() - for test in self.tests: - if names and not test.name() in names: - test.set_skip() - continue - test.run() + log.large_separator(self.trial.name(), self.name(), sublevel=2) + self.mark_start() + event_loop.register_poll_func(self.poll) + if not self.reserved_resources: + self.reserve_resources() + for test in self.tests: + if names and not test.name() in names: + test.set_skip() + continue + test.run() except Exception: - self.log_exn() + log.log_exn() except BaseException as e: # when the program is aborted by a signal (like Ctrl-C), escalate to abort all. self.err('SUITE RUN ABORTED: %s' % type(e).__name__) @@ -355,7 +349,8 @@ class SuiteRun(log.Origin): if process.terminated(): process.log_stdout_tail() process.log_stderr_tail() - process.raise_exn('Process ended prematurely') + log.ctx(process) + raise log.Error('Process ended prematurely') def prompt(self, *msgs, **msg_details): 'ask for user interaction. Do not use in tests that should run automatically!' -- cgit v1.2.3