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
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
_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 @@
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 @@
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 @@
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!'