[PATCH] osmo-gsm-tester[master]: fix and refactor logging: drop 'with', simplify

This is merely a historical archive of years 2008-2021, before the migration to mailman3.

A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.

Neels Hofmeyr gerrit-no-reply at lists.osmocom.org
Mon Jun 12 12:05:11 UTC 2017


Review at  https://gerrit.osmocom.org/2886

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 string information in a local
variable called log_ctx. This is automatically inserted in the ancestry
associated with a log statement / exception.

Change-Id: I5f9b53150f2bb6fa9d63ce27f0806f0ca6a45e90
---
M src/osmo_gsm_tester/bts_osmotrx.py
M src/osmo_gsm_tester/bts_sysmo.py
M src/osmo_gsm_tester/config.py
M src/osmo_gsm_tester/event_loop.py
M src/osmo_gsm_tester/log.py
M src/osmo_gsm_tester/ofono_client.py
M src/osmo_gsm_tester/osmo_bsc.py
M src/osmo_gsm_tester/osmo_ctrl.py
M src/osmo_gsm_tester/osmo_hlr.py
M src/osmo_gsm_tester/osmo_mgcpgw.py
M src/osmo_gsm_tester/osmo_msc.py
M src/osmo_gsm_tester/osmo_nitb.py
M src/osmo_gsm_tester/pcap_recorder.py
M src/osmo_gsm_tester/process.py
M src/osmo_gsm_tester/resource.py
M src/osmo_gsm_tester/schema.py
M src/osmo_gsm_tester/suite.py
M src/osmo_gsm_tester/template.py
M src/osmo_gsm_tester/test.py
M src/osmo_gsm_tester/trial.py
20 files changed, 328 insertions(+), 381 deletions(-)


  git pull ssh://gerrit.osmocom.org:29418/osmo-gsm-tester refs/changes/86/2886/1

diff --git a/src/osmo_gsm_tester/bts_osmotrx.py b/src/osmo_gsm_tester/bts_osmotrx.py
index 0083512..7d12c85 100644
--- a/src/osmo_gsm_tester/bts_osmotrx.py
+++ b/src/osmo_gsm_tester/bts_osmotrx.py
@@ -36,10 +36,9 @@
     CONF_BTS_TRX = 'osmo-bts-trx.cfg'
 
     def __init__(self, suite_run, conf):
+        super().__init__(log.C_RUN, OsmoBtsTrx.BIN_BTS_TRX)
         self.suite_run = suite_run
         self.conf = conf
-        self.set_name(OsmoBtsTrx.BIN_BTS_TRX)
-        self.set_log_category(log.C_RUN)
         self.env = {}
 
     def remote_addr(self):
diff --git a/src/osmo_gsm_tester/bts_sysmo.py b/src/osmo_gsm_tester/bts_sysmo.py
index 5f2b3cb..a771ec4 100644
--- a/src/osmo_gsm_tester/bts_sysmo.py
+++ b/src/osmo_gsm_tester/bts_sysmo.py
@@ -35,52 +35,50 @@
     BTS_SYSMO_CFG = 'osmo-bts-sysmo.cfg'
 
     def __init__(self, suite_run, conf):
+        super().__init__(log.C_RUN, self.BTS_SYSMO_BIN)
         self.suite_run = suite_run
         self.conf = conf
-        self.set_name('osmo-bts-sysmo')
-        self.set_log_category(log.C_RUN)
         self.remote_env = {}
         self.remote_user = 'root'
 
     def start(self):
-        with self:
-            if self.bsc is None:
-                raise RuntimeError('BTS needs to be added to a BSC or NITB before it can be started')
-            self.log('Starting sysmoBTS to connect to', self.bsc)
-            self.run_dir = util.Dir(self.suite_run.trial.get_run_dir().new_dir(self.name()))
-            self.configure()
+        if self.bsc is None:
+            raise RuntimeError('BTS needs to be added to a BSC or NITB before it can be started')
+        log.log('Starting sysmoBTS to connect to', self.bsc)
+        self.run_dir = util.Dir(self.suite_run.trial.get_run_dir().new_dir(self.name()))
+        self.configure()
 
-            self.inst = util.Dir(os.path.abspath(self.suite_run.trial.get_inst(SysmoBts.BTS_SYSMO_BIN)))
-            lib = self.inst.child('lib')
-            if not os.path.isdir(lib):
-                self.raise_exn('No lib/ in', self.inst)
-            if not self.inst.isfile('bin', SysmoBts.BTS_SYSMO_BIN):
-                self.raise_exn('No osmo-bts-sysmo binary in', self.inst)
+        self.inst = util.Dir(os.path.abspath(self.suite_run.trial.get_inst(SysmoBts.BTS_SYSMO_BIN)))
+        lib = self.inst.child('lib')
+        if not os.path.isdir(lib):
+            raise log.Error('No lib/ in', self.inst)
+        if not self.inst.isfile('bin', SysmoBts.BTS_SYSMO_BIN):
+            raise log.Error('No osmo-bts-sysmo binary in', self.inst)
 
-            self.remote_dir = util.Dir(SysmoBts.REMOTE_DIR)
-            self.remote_inst = util.Dir(self.remote_dir.child(os.path.basename(str(self.inst))))
+        self.remote_dir = util.Dir(SysmoBts.REMOTE_DIR)
+        self.remote_inst = util.Dir(self.remote_dir.child(os.path.basename(str(self.inst))))
 
-            self.run_remote('rm-remote-dir', ('test', '!', '-d', SysmoBts.REMOTE_DIR, '||', 'rm', '-rf', SysmoBts.REMOTE_DIR))
-            self.run_remote('mk-remote-dir', ('mkdir', '-p', SysmoBts.REMOTE_DIR))
-            self.run_local('scp-inst-to-sysmobts',
-                ('scp', '-r', str(self.inst), '%s@%s:%s' % (self.remote_user, self.remote_addr(), str(self.remote_inst))))
+        self.run_remote('rm-remote-dir', ('test', '!', '-d', SysmoBts.REMOTE_DIR, '||', 'rm', '-rf', SysmoBts.REMOTE_DIR))
+        self.run_remote('mk-remote-dir', ('mkdir', '-p', SysmoBts.REMOTE_DIR))
+        self.run_local('scp-inst-to-sysmobts',
+            ('scp', '-r', str(self.inst), '%s@%s:%s' % (self.remote_user, self.remote_addr(), str(self.remote_inst))))
 
-            remote_run_dir = self.remote_dir.child(SysmoBts.BTS_SYSMO_BIN)
-            self.run_remote('mk-remote-run-dir', ('mkdir', '-p', remote_run_dir))
+        remote_run_dir = self.remote_dir.child(SysmoBts.BTS_SYSMO_BIN)
+        self.run_remote('mk-remote-run-dir', ('mkdir', '-p', remote_run_dir))
 
-            remote_config_file = self.remote_dir.child(SysmoBts.BTS_SYSMO_CFG)
-            self.run_local('scp-cfg-to-sysmobts',
-                ('scp', '-r', self.config_file, '%s@%s:%s' % (self.remote_user, self.remote_addr(), remote_config_file)))
+        remote_config_file = self.remote_dir.child(SysmoBts.BTS_SYSMO_CFG)
+        self.run_local('scp-cfg-to-sysmobts',
+            ('scp', '-r', self.config_file, '%s@%s:%s' % (self.remote_user, self.remote_addr(), remote_config_file)))
 
-            self.run_remote('reload-dsp-firmware', ('/bin/sh', '-c', '"cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0"'))
+        self.run_remote('reload-dsp-firmware', ('/bin/sh', '-c', '"cat /lib/firmware/sysmobts-v?.bit > /dev/fpgadl_par0 ; cat /lib/firmware/sysmobts-v?.out > /dev/dspdl_dm644x_0"'))
 
-            remote_lib = self.remote_inst.child('lib')
-            remote_binary = self.remote_inst.child('bin', 'osmo-bts-sysmo')
-            self.launch_remote('osmo-bts-sysmo',
-                ('LD_LIBRARY_PATH=%s' % remote_lib,
-                 remote_binary, '-c', remote_config_file, '-r', '1',
-                 '-i', self.bsc.addr()),
-                remote_cwd=remote_run_dir)
+        remote_lib = self.remote_inst.child('lib')
+        remote_binary = self.remote_inst.child('bin', 'osmo-bts-sysmo')
+        self.launch_remote('osmo-bts-sysmo',
+            ('LD_LIBRARY_PATH=%s' % remote_lib,
+             remote_binary, '-c', remote_config_file, '-r', '1',
+             '-i', self.bsc.addr()),
+            remote_cwd=remote_run_dir)
 
     def _process_remote(self, name, popen_args, remote_cwd=None):
         run_dir = self.run_dir.new_dir(name)
@@ -92,7 +90,8 @@
         proc.launch()
         proc.wait()
         if proc.result != 0:
-            proc.raise_exn('Exited in error')
+            log_ctx = proc
+            raise log.Error('Exited in error')
 
     def launch_remote(self, name, popen_args, remote_cwd=None):
         proc = self._process_remote(name, popen_args, remote_cwd)
@@ -105,7 +104,8 @@
         proc.launch()
         proc.wait()
         if proc.result != 0:
-            proc.raise_exn('Exited in error')
+            log_ctx = proc
+            raise log.Error('Exited in error')
 
     def remote_addr(self):
         return self.conf.get('addr')
diff --git a/src/osmo_gsm_tester/config.py b/src/osmo_gsm_tester/config.py
index 38d8e2f..1efd957 100644
--- a/src/osmo_gsm_tester/config.py
+++ b/src/osmo_gsm_tester/config.py
@@ -95,7 +95,7 @@
         real_l = os.path.realpath(l)
         p = os.path.realpath(os.path.join(real_l, basename))
         if os.path.isfile(p):
-            log.dbg(None, log.C_CNF, 'Found config file', basename, 'as', p, 'in', l, 'which is', real_l)
+            log.dbg('Found config file', basename, 'as', p, 'in', l, 'which is', real_l, _category=log.C_CNF)
             return (p, real_l)
     if not fail_if_missing:
         return None, None
@@ -122,7 +122,7 @@
     env_path = os.getenv(env_name)
     if env_path:
         real_env_path = os.path.realpath(env_path)
-        log.dbg(None, log.C_CNF, 'Found path', label, 'as', env_path, 'in', '$' + env_name, 'which is', real_env_path)
+        log.dbg('Found path', label, 'as', env_path, 'in', '$' + env_name, 'which is', real_env_path, _category=log.C_CNF)
         return real_env_path
 
     if PATHS is None:
@@ -132,15 +132,15 @@
         for key, path in sorted(PATHS.items()):
             if not path.startswith(os.pathsep):
                 PATHS[key] = os.path.realpath(os.path.join(found_in, path))
-                log.dbg(None, log.C_CNF, paths_file + ': relative path', path, 'is', PATHS[key])
+                log.dbg(paths_file + ': relative path', path, 'is', PATHS[key], _category=log.C_CNF)
     p = PATHS.get(label)
     if p is None and not allow_unset:
         raise RuntimeError('missing configuration in %s: %r' % (PATHS_CONF, label))
 
-    log.dbg(None, log.C_CNF, 'Found path', label, 'as', p)
+    log.dbg('Found path', label, 'as', p, _category=log.C_CNF)
     if p.startswith(PATHS_TEMPDIR_STR):
         p = os.path.join(get_tempdir(), p[len(PATHS_TEMPDIR_STR):])
-        log.dbg(None, log.C_CNF, 'Path', label, 'contained', PATHS_TEMPDIR_STR, 'and becomes', p)
+        log.dbg('Path', label, 'contained', PATHS_TEMPDIR_STR, 'and becomes', p, _category=log.C_CNF)
     return p
 
 def get_state_dir():
@@ -153,20 +153,20 @@
     return Dir(get_configured_path(PATH_SCENARIOS_DIR))
 
 def read(path, validation_schema=None, if_missing_return=False):
-    with log.Origin(path):
-        if not os.path.isfile(path) and if_missing_return is not False:
-            return if_missing_return
-        with open(path, 'r') as f:
-            config = yaml.safe_load(f)
-        config = _standardize(config)
-        if validation_schema:
-            schema.validate(config, validation_schema)
-        return config
+    log_ctx = path
+    if not os.path.isfile(path) and if_missing_return is not False:
+        return if_missing_return
+    with open(path, 'r') as f:
+        config = yaml.safe_load(f)
+    config = _standardize(config)
+    if validation_schema:
+        schema.validate(config, validation_schema)
+    return config
 
 def write(path, config):
-    with log.Origin(path):
-        with open(path, 'w') as f:
-            f.write(tostr(config))
+    log_ctx = path
+    with open(path, 'w') as f:
+        f.write(tostr(config))
 
 def tostr(config):
     return _tostr(_standardize(config))
@@ -191,8 +191,7 @@
 
 class Scenario(log.Origin, dict):
     def __init__(self, name, path):
-        self.set_name(name)
-        self.set_log_category(log.C_TST)
+        super().__init__(log.C_TST, name)
         self.path = path
 
 def get_scenario(name, validation_schema=None):
@@ -216,8 +215,8 @@
             if dest_val is None:
                 dest[key] = val
             else:
-                with log.Origin(key=key):
-                    add(dest_val, val)
+                log_ctx = 'key=%r' % key
+                add(dest_val, val)
         return
     if is_list(dest):
         if not is_list(src):
@@ -235,19 +234,19 @@
             raise ValueError('cannot combine dict with a value of type: %r' % type(src))
 
         for key, val in src.items():
+            log_ctx = 'key=%r' % key
             dest_val = dest.get(key)
             if dest_val is None:
                 dest[key] = val
             else:
-                with log.Origin(key=key):
-                    combine(dest_val, val)
+                combine(dest_val, val)
         return
     if is_list(dest):
         if not is_list(src):
             raise ValueError('cannot combine list with a value of type: %r' % type(src))
         for i in range(len(src)):
-            with log.Origin(idx=i):
-                combine(dest[i], src[i])
+            log_ctx = 'idx=%r' % i
+            combine(dest[i], src[i])
         return
     if dest == src:
         return
@@ -260,16 +259,16 @@
             raise ValueError('cannot combine dict with a value of type: %r' % type(src))
 
         for key, val in src.items():
+            log_ctx = 'key=%r' % key
             dest_val = dest.get(key)
-            with log.Origin(key=key):
-                dest[key] = overlay(dest_val, val)
+            dest[key] = overlay(dest_val, val)
         return dest
     if is_list(dest):
         if not is_list(src):
             raise ValueError('cannot combine list with a value of type: %r' % type(src))
         for i in range(len(src)):
-            with log.Origin(idx=i):
-                dest[i] = overlay(dest[i], src[i])
+            log_ctx = 'key=%r' % key
+            dest[i] = overlay(dest[i], src[i])
         return dest
     return src
 
diff --git a/src/osmo_gsm_tester/event_loop.py b/src/osmo_gsm_tester/event_loop.py
index c3c679b..fbf4bad 100644
--- a/src/osmo_gsm_tester/event_loop.py
+++ b/src/osmo_gsm_tester/event_loop.py
@@ -21,6 +21,8 @@
 # A test script can thus establish its context by doing:
 # from osmo_gsm_tester.test import *
 import time
+from . import log
+
 poll_funcs = []
 
 def register_poll_func(func):
@@ -38,7 +40,8 @@
 
 def wait_no_raise(log_obj, condition, condition_args, condition_kwargs, timeout, timestep):
     if not timeout or timeout < 0:
-        log_obj.raise_exn('wait() *must* time out at some point. timeout=%r' % timeout)
+        self = log_obj
+        raise log.Error('wait() *must* time out at some point.', timeout=timeout)
     if timestep < 0.1:
         timestep = 0.1
 
@@ -54,7 +57,8 @@
 
 def wait(log_obj, condition, *condition_args, timeout=300, timestep=1, **condition_kwargs):
     if not wait_no_raise(log_obj, condition, condition_args, condition_kwargs, timeout, timestep):
-        log_obj.raise_exn('Wait timeout')
+        log_ctx = log_obj
+        raise log.Error('Wait timeout')
 
 def sleep(log_obj, seconds):
     assert seconds > 0.
diff --git a/src/osmo_gsm_tester/log.py b/src/osmo_gsm_tester/log.py
index f098f2b..3ac8ccd 100644
--- a/src/osmo_gsm_tester/log.py
+++ b/src/osmo_gsm_tester/log.py
@@ -45,6 +45,37 @@
 C_BUS = 'bus'
 C_DEFAULT = '---'
 
+def dbg(*messages, _origin=None, _category=None, **named_items):
+    '''Log on debug level. See also log()'''
+    _log(messages, named_items, origin=_origin, category=_category, level=L_DBG)
+
+def log(*messages, _origin=None, _category=None, _level=L_LOG, **named_items):
+    '''Log a message. The origin, an Origin class instance, is normally
+    determined by stack magic, only pass _origin to override. The category is
+    taken from the origin. The log message is composed of all *messages and
+    **named_items, for example:
+      log('frobnicate:', thing, key=current_key, prop=erty)
+    '''
+    _log(messages, named_items, origin=_origin, category=_category, level=_level)
+
+def err(*messages, _origin=None, _category=None, **named_items):
+    '''Log on error level. See also log()'''
+    _log(messages, named_items, origin=_origin, category=_category, level=L_ERR)
+
+def _log(messages=[], named_items={}, origin=None, category=None, level=L_LOG, src=None):
+    if origin is None:
+        origin = Origin.find_on_stack()
+    if category is None and isinstance(origin, Origin):
+        category = origin._log_category
+    if src is None:
+        # two levels up
+        src = 2
+    if isinstance(src, int):
+        src = get_src_from_caller(src + 1)
+    for target in LogTarget.all_targets:
+        target.log(origin, category, level, src, messages, named_items)
+
+
 LONG_DATEFMT = '%Y-%m-%d_%H:%M:%S'
 DATEFMT = '%H:%M:%S'
 
@@ -52,7 +83,8 @@
 get_process_id = lambda: '%d-%d' % (os.getpid(), time.time())
 
 class Error(Exception):
-    pass
+    def __init__(self, *messages, **named_items):
+        super().__init__(compose_message(messages, named_items))
 
 class LogTarget:
     all_targets = []
@@ -153,7 +185,7 @@
 
     def log(self, origin, category, level, src, messages, named_items):
         if category and len(category) != 3:
-            self.log_write_func('WARNING: INVALID LOG SUBSYSTEM %r\n' % category)
+            self.log_write_func('WARNING: INVALID LOGGING CATEGORY %r\n' % category)
             self.log_write_func('origin=%r category=%r level=%r\n' % (origin, category, level));
 
         if not category:
@@ -172,14 +204,11 @@
         if self.do_log_origin:
             if origin is None:
                 name = '-'
-            elif isinstance(origin, Origins):
-                name = origin[-1]
-                if len(origin) > 1:
-                    deeper_origins = str(origin)
+            elif isinstance(origin, Origin):
+                name = origin.name()
+                deeper_origins = origin.ancestry_str()
             elif isinstance(origin, str):
                 name = origin or None
-            elif hasattr(origin, 'name'):
-                name = origin.name()
             if not name:
                 name = str(origin.__class__.__name__)
             log_pre.append(self.origin_fmt.format(name))
@@ -228,7 +257,7 @@
 
 def _log_all_targets(origin, category, level, src, messages, named_items=None):
     if origin is None:
-        origin = Origin._global_current_origin
+        origin = Origin.find_on_stack()
     if isinstance(src, int):
         src = get_src_from_caller(src + 1)
     for target in LogTarget.all_targets:
@@ -242,13 +271,15 @@
     caller = getframeinfo(stack()[levels_up][0])
     return '%s:%d' % (os.path.basename(caller.filename), caller.lineno)
 
-def get_src_from_tb(tb, levels_up=1):
-    ftb = traceback.extract_tb(tb)
+def get_src_from_exc_info(exc_info, levels_up=1):
+    ftb = traceback.extract_tb(exc_info[2])
     f,l,m,c = ftb[-levels_up]
     f = os.path.basename(f)
     return '%s:%s: %s' % (f, l, c)
 
 def get_line_for_src(src_path):
+    '''find a given source file on the stack and return the line number for
+    that file. (Used to indicate the position in a test script.)'''
     etype, exception, tb = sys.exc_info()
     if tb:
         ftb = traceback.extract_tb(tb)
@@ -265,28 +296,71 @@
 
 class Origin:
     '''
-    Base class for all classes that want to log,
-    and to add an origin string to a code path:
-    with log.Origin('my name'):
-        raise Problem()
-    This will log 'my name' as an origin for the Problem.
+    Base class for all classes that want to appear in the log.
+    It is a simple named marker to find in the stack frames.
+    This depends on the object instance named 'self' in each member class.
+
+    In addition, it provides a logging category and a globally unique ID for
+    each instance.
     '''
 
-    _global_current_origin = None
     _global_id = None
 
-    _log_category = None
-    _src = None
     _name = None
     _origin_id = None
-
+    _log_category = None
     _parent_origin = None
 
-    def __init__(self, *name_items, category=None, **detail_items):
-        self.set_log_category(category)
-        self.set_name(*name_items, **detail_items)
+    @staticmethod
+    def find_on_stack(except_obj=None, f=None):
+        if f is None:
+            f = sys._getframe(1)
+        log_ctx_obj = None
+        origin = None
+        while f is not None:
+            l = f.f_locals
 
-    def set_name(self, *name_items, **detail_items):
+            # if there is a log_ctx in the scope, add it, pointing to the next
+            # actual Origin class in the stack
+            log_ctx = l.get('log_ctx')
+            if log_ctx:
+                if isinstance(log_ctx, Origin):
+                    new_log_ctx_obj = log_ctx
+                else:
+                    new_log_ctx_obj = Origin(None, log_ctx, find_parent=False)
+                if log_ctx_obj is None:
+                    log_ctx_obj = new_log_ctx_obj
+                else:
+                    log_ctx_obj.highest_ancestor()._parent_origin = new_log_ctx_obj
+
+            obj = l.get('self')
+            if obj and isinstance(obj, Origin) and (except_obj is not obj):
+                origin = obj
+                break
+            f = f.f_back
+
+        if (origin is not None) and (log_ctx_obj is not None):
+            log_ctx_obj.highest_ancestor()._parent_origin = origin
+        if log_ctx_obj is not None:
+            return log_ctx_obj
+        # may return None
+        return origin
+
+    @staticmethod
+    def find_in_exc_info(exc_info):
+        tb = exc_info[2]
+        # get last tb ... I hope that's right
+        while tb.tb_next:
+            tb = tb.tb_next
+        return Origin.find_on_stack(f=tb.tb_frame)
+
+    def __init__(self, category, *name_items, find_parent=True, **detail_items):
+        self._set_log_category(category)
+        self._set_name(*name_items, **detail_items)
+        if find_parent:
+            self._parent_origin = Origin.find_on_stack(except_obj=self)
+
+    def _set_name(self, *name_items, **detail_items):
         if name_items:
             name = '-'.join([str(i) for i in name_items])
         elif not detail_items:
@@ -313,87 +387,43 @@
             self._origin_id = '%s-%s' % (self.name(), Origin._global_id)
         return self._origin_id
 
-    def set_log_category(self, category):
+    def _set_log_category(self, category):
         self._log_category = category
-
-    def _log(self, level, messages, named_items=None, src_levels_up=3, origins=None):
-        src = self._src or src_levels_up
-        origin = origins or self.gather_origins()
-        _log_all_targets(origin, self._log_category, level, src, messages, named_items)
-
-    def dbg(self, *messages, **named_items):
-        self._log(L_DBG, messages, named_items)
-
-    def log(self, *messages, **named_items):
-        self._log(L_LOG, messages, named_items)
-
-    def err(self, *messages, **named_items):
-        self._log(L_ERR, messages, named_items)
-
-    def trace(self, *messages, **named_items):
-        self._log(L_TRACEBACK, messages, named_items)
-
-    def log_exn(self, exc_info=None):
-        log_exn(self, self._log_category, exc_info)
-
-    def __enter__(self):
-        if not self.set_child_of(Origin._global_current_origin):
-            return self
-        Origin._global_current_origin = self
-        return self
-
-    def __exit__(self, *exc_info):
-        rc = None
-        if exc_info[0] is not None:
-            rc = exn_add_info(exc_info, self)
-        Origin._global_current_origin, self._parent_origin = self._parent_origin, None
-        return rc
-
-    def raise_exn(self, *messages, exn_class=Error, **named_items):
-        with self:
-            raise exn_class(compose_message(messages, named_items))
 
     def redirect_stdout(self):
         return contextlib.redirect_stdout(SafeRedirectStdout(self))
 
-    def gather_origins(self):
-        origins = Origins()
-        # this object shall always be seen as the immediate origin of the log message.
-        origins.add(self)
-        # now go through the parents of this object.
-        origin = self._parent_origin
-        # but if this object is "loose" and not set up with cascaded 'with' statements,
-        # take the last seen 'with' statement's object as next parent:
-        if origin is None and Origin._global_current_origin is not None:
-            origin = Origin._global_current_origin
-            # if this object is currently the _global_current_origin, we don't
-            # need to add it twice.
-            if origin is self:
-                origin = origin._parent_origin
-        # whichever we determined to be the parent above, go up through all its
-        # ancestors.
-        while origin is not None:
-            origins.add(origin)
+    def ancestry(self):
+        origins = []
+        n = 10
+        origin = self
+        while origin:
+            origins.insert(0, origin)
             origin = origin._parent_origin
+            n -= 1
+            if n < 0:
+                break
         return origins
 
-    def set_child_of(self, parent_origin):
-        # avoid loops
-        assert self._parent_origin is None
-        assert parent_origin is not self
-        self._parent_origin = parent_origin
-        return True
+    def ancestry_str(self):
+        return '↪'.join([o.name() for o in self.ancestry()])
 
-class LineInfo(Origin):
-    def __init__(self, src_file, *name_items, **detail_items):
-        self.src_file = src_file
-        self.set_name(*name_items, **detail_items)
+    def highest_ancestor(self):
+        if self._parent_origin:
+            return self._parent_origin.highest_ancestor()
+        return self
 
-    def name(self):
-        l = get_line_for_src(self.src_file)
-        if l is not None:
-            return '%s:%s' % (self._name, l)
-        return super().name()
+    def log(self, *messages, **named_items):
+        '''same as log.log() but passes this object to skip looking up an origin'''
+        log(*messages, _origin=self, **named_items)
+
+    def dbg(self, *messages, **named_items):
+        '''same as log.dbg() but passes this object to skip looking up an origin'''
+        dbg(*messages, _origin=self, **named_items)
+
+    def err(self, *messages, **named_items):
+        '''same as log.err() but passes this object to skip looking up an origin'''
+        err(*messages, _origin=self, **named_items)
 
 class SafeRedirectStdout:
     '''
@@ -407,7 +437,7 @@
     _log_line_buf = None
 
     def __init__(self, origin):
-        self._origin = origin
+        self.origin = origin
 
     def write(self, message):
         lines = message.splitlines()
@@ -419,93 +449,34 @@
         if not message.endswith('\n'):
             self._log_line_buf = lines[-1]
             lines = lines[:-1]
-        origins = self._origin.gather_origins()
         for line in lines:
-            self._origin._log(L_LOG, (line,), origins=origins)
+            _log(messages=(line,),
+                 origin=self.origin, level=L_LOG, src=3)
 
     def __getattr__(self, name):
         return sys.__stdout__.__getattribute__(name)
 
-
-def dbg(origin, category, *messages, **named_items):
-    _log_all_targets(origin, category, L_DBG, 2, messages, named_items)
-
-def log(origin, category, *messages, **named_items):
-    _log_all_targets(origin, category, L_LOG, 2, messages, named_items)
-
-def err(origin, category, *messages, **named_items):
-    _log_all_targets(origin, category, L_ERR, 2, messages, named_items)
-
-def trace(origin, category, exc_info):
-    _log_all_targets(origin, category, L_TRACEBACK, None,
-                     traceback.format_exception(*exc_info))
-
-def resolve_category(origin, category):
-    if category is not None:
-        return category
-    if not hasattr(origin, '_log_category'):
-        return None
-    return origin._log_category
-
-def exn_add_info(exc_info, origin, category=None):
-    etype, exception, tb = exc_info
-    if not hasattr(exception, 'origins'):
-        exception.origins = Origins()
-    if not hasattr(exception, 'category'):
-        # only remember the deepest category
-        exception.category = resolve_category(origin, category)
-    if not hasattr(exception, 'src'):
-        exception.src = get_src_from_tb(tb)
-    exception.origins.add(origin)
-    return False
-
-def log_exn(origin=None, category=None, exc_info=None):
-    if not (exc_info is not None and len(exc_info) == 3):
+def trace(exc_info=None, origin=None):
+    if exc_info is None:
         exc_info = sys.exc_info()
-        if not (exc_info is not None and len(exc_info) == 3):
-            raise RuntimeError('invalid call to log_exn() -- no valid exception info')
+    if origin is None:
+        origin = Origin.find_in_exc_info(exc_info)
+    _log(messages=traceback.format_exception(*exc_info),
+         origin=origin, level=L_TRACEBACK)
+
+def log_exn():
+    exc_info = sys.exc_info()
+    origin = Origin.find_in_exc_info(exc_info)
 
     etype, exception, tb = exc_info
-
-    # if there are origins recorded with the Exception, prefer that
-    if hasattr(exception, 'origins'):
-        origin = exception.origins
-
-    # if there is a category recorded with the Exception, prefer that
-    if hasattr(exception, 'category'):
-        category = exception.category
-
     if hasattr(exception, 'msg'):
         msg = exception.msg
     else:
         msg = str(exception)
 
-    if hasattr(exception, 'src'):
-        src = exception.src
-    else:
-        src = 2
-
-    trace(origin, category, exc_info)
-    _log_all_targets(origin, category, L_ERR, src,
-                     ('%s:' % str(etype.__name__), msg))
-
-
-class Origins(list):
-    def __init__(self, origin=None):
-        if origin is not None:
-            self.add(origin)
-
-    def add(self, origin):
-        if hasattr(origin, 'name'):
-            origin_str = origin.name()
-        else:
-            origin_str = repr(origin)
-        if origin_str is None:
-            raise RuntimeError('origin_str is None for %r' % origin)
-        self.insert(0, origin_str)
-
-    def __str__(self):
-        return '↪'.join(self)
+    trace(exc_info, origin=origin)
+    _log(messages=('%s:' % str(etype.__name__), msg),
+         origin=origin, level=L_ERR, src=get_src_from_exc_info(exc_info))
 
 
 def set_all_levels(level):
diff --git a/src/osmo_gsm_tester/ofono_client.py b/src/osmo_gsm_tester/ofono_client.py
index 83f3e0d..7a5682c 100644
--- a/src/osmo_gsm_tester/ofono_client.py
+++ b/src/osmo_gsm_tester/ofono_client.py
@@ -82,12 +82,14 @@
     Related: https://github.com/LEW21/pydbus/issues/56
     '''
 
+    modem_path = None
+    watch_props_subscription = None
+    _dbus_obj = None
+    interfaces = None
+
     def __init__(self, modem_path):
         self.modem_path = modem_path
-        self.set_name(self.modem_path)
-        self.set_log_category(log.C_BUS)
-        self.watch_props_subscription = None
-        self._dbus_obj = None
+        super().__init__(log.C_BUS, self.modem_path)
         self.interfaces = set()
 
         # A dict listing signal handlers to connect, e.g.
@@ -118,7 +120,7 @@
         try:
             return self.dbus_obj()[interface_name]
         except KeyError:
-            self.raise_exn('Modem interface is not available:', interface_name)
+            raise RuntimeError('Modem interface is not available:', interface_name)
 
     def signal(self, interface_name, signal):
         return getattr(self.interface(interface_name), signal)
@@ -253,8 +255,7 @@
     def __init__(self, conf):
         self.conf = conf
         self.path = conf.get('path')
-        self.set_name(self.path)
-        self.set_log_category(log.C_TST)
+        super().__init__(log.C_TST, self.path)
         self.sms_received_list = []
         self.dbus = ModemDbusInteraction(self.path)
         self.dbus.required_signals = {
@@ -312,8 +313,7 @@
     def imsi(self):
         imsi = self.conf.get('imsi')
         if not imsi:
-            with self:
-                raise RuntimeError('No IMSI')
+            raise RuntimeError('No IMSI')
         return imsi
 
     def ki(self):
diff --git a/src/osmo_gsm_tester/osmo_bsc.py b/src/osmo_gsm_tester/osmo_bsc.py
index 7753395..5447118 100644
--- a/src/osmo_gsm_tester/osmo_bsc.py
+++ b/src/osmo_gsm_tester/osmo_bsc.py
@@ -31,10 +31,9 @@
     bts = None
 
     def __init__(self, suite_run, msc, ip_address):
+        super().__init__(log.C_RUN, 'osmo-bsc_%s' % ip_address.get('addr'))
         self.suite_run = suite_run
         self.ip_address = ip_address
-        self.set_log_category(log.C_RUN)
-        self.set_name('osmo-bsc_%s' % ip_address.get('addr'))
         self.bts = []
         self.msc = msc
 
diff --git a/src/osmo_gsm_tester/osmo_ctrl.py b/src/osmo_gsm_tester/osmo_ctrl.py
index 0b717fa..b5a947f 100644
--- a/src/osmo_gsm_tester/osmo_ctrl.py
+++ b/src/osmo_gsm_tester/osmo_ctrl.py
@@ -29,8 +29,7 @@
 class OsmoCtrl(log.Origin):
 
     def __init__(self, host, port):
-        self.set_name('Ctrl', host=host, port=port)
-        self.set_log_category(log.C_BUS)
+        super().__init__(log.C_BUS, 'Ctrl', host=host, port=port)
         self.host = host
         self.port = port
         self.sck = None
@@ -79,12 +78,10 @@
         self._send(getmsg)
 
     def __enter__(self):
-        super().__enter__()
         self.connect()
         return self
 
     def __exit__(self, *exc_info):
         self.disconnect()
-        super().__exit__(*exc_info)
 
 # vim: expandtab tabstop=4 shiftwidth=4
diff --git a/src/osmo_gsm_tester/osmo_hlr.py b/src/osmo_gsm_tester/osmo_hlr.py
index 3492f06..14505db 100644
--- a/src/osmo_gsm_tester/osmo_hlr.py
+++ b/src/osmo_gsm_tester/osmo_hlr.py
@@ -32,10 +32,9 @@
     next_subscriber_id = 1
 
     def __init__(self, suite_run, ip_address):
+        super().__init__(log.C_RUN, 'osmo-hlr_%s' % ip_address.get('addr'))
         self.suite_run = suite_run
         self.ip_address = ip_address
-        self.set_log_category(log.C_RUN)
-        self.set_name('osmo-hlr_%s' % ip_address.get('addr'))
         self.bts = []
 
     def start(self):
@@ -47,16 +46,16 @@
 
         binary = inst.child('bin', 'osmo-hlr')
         if not os.path.isfile(binary):
-            self.raise_exn('Binary missing:', binary)
+            raise log.Error('Binary missing:', binary)
         lib = inst.child('lib')
         if not os.path.isdir(lib):
-            self.raise_exn('No lib/ in', inst)
+            raise log.Error('No lib/ in', inst)
 
         # bootstrap an empty hlr.db
         self.db_file = self.run_dir.new_file('hlr.db')
         sql_input = inst.child('share/doc/osmo-hlr/hlr.sql')
         if not os.path.isfile(sql_input):
-            self.raise_exn('hlr.sql missing:', sql_input)
+            raise log.Error('hlr.sql missing:', sql_input)
         self.run_local('create_hlr_db', ('/bin/sh', '-c', 'sqlite3 %r < %r' % (self.db_file, sql_input)))
 
         iface = util.ip_to_iface(self.addr())
@@ -96,13 +95,13 @@
         return not self.process.terminated()
 
     def run_local(self, name, popen_args):
-        with self:
-            run_dir = self.run_dir.new_dir(name)
-            proc = process.Process(name, run_dir, popen_args)
-            proc.launch()
-            proc.wait()
-            if proc.result != 0:
-                proc.raise_exn('Exited in error')
+        run_dir = self.run_dir.new_dir(name)
+        proc = process.Process(name, run_dir, popen_args)
+        proc.launch()
+        proc.wait()
+        if proc.result != 0:
+            log_ctx = proc
+            raise log.Error('Exited in error')
 
     def run_sql_file(self, name, sql_file):
         self.run_local(name, ('/bin/sh', '-c', 'sqlite3 %r < %r' % (self.db_file, sql_file)))
diff --git a/src/osmo_gsm_tester/osmo_mgcpgw.py b/src/osmo_gsm_tester/osmo_mgcpgw.py
index 3e722fb..b385274 100644
--- a/src/osmo_gsm_tester/osmo_mgcpgw.py
+++ b/src/osmo_gsm_tester/osmo_mgcpgw.py
@@ -30,10 +30,9 @@
     process = None
 
     def __init__(self, suite_run, ip_address, bts_ip):
+        super().__init__(log.C_RUN, 'osmo-mgcpgw_%s' % ip_address.get('addr'))
         self.suite_run = suite_run
         self.ip_address = ip_address
-        self.set_log_category(log.C_RUN)
-        self.set_name('osmo-mgcpgw_%s' % ip_address.get('addr'))
         # hack: so far mgcpgw needs one specific BTS IP.
         self.bts_ip = bts_ip
 
diff --git a/src/osmo_gsm_tester/osmo_msc.py b/src/osmo_gsm_tester/osmo_msc.py
index 2ef88df..829e20a 100644
--- a/src/osmo_gsm_tester/osmo_msc.py
+++ b/src/osmo_gsm_tester/osmo_msc.py
@@ -31,10 +31,9 @@
     hlr = None
 
     def __init__(self, suite_run, hlr, mgcpgw, ip_address):
+        super().__init__(log.C_RUN, 'osmo-msc_%s' % ip_address.get('addr'))
         self.suite_run = suite_run
         self.ip_address = ip_address
-        self.set_log_category(log.C_RUN)
-        self.set_name('osmo-msc_%s' % ip_address.get('addr'))
         self.hlr = hlr
         self.mgcpgw = mgcpgw
 
@@ -89,12 +88,11 @@
 
     def imsi_attached(self, *imsis):
         attached = self.imsi_list_attached()
-        self.dbg('attached:', attached)
+        log.dbg('attached:', attached)
         return all([(imsi in attached) for imsi in imsis])
 
     def imsi_list_attached(self):
-        with self:
-            return OsmoMscCtrl(self).subscriber_list_active()
+        return OsmoMscCtrl(self).subscriber_list_active()
 
     def running(self):
         return not self.process.terminated()
@@ -106,8 +104,7 @@
 
     def __init__(self, msc):
         self.msc = msc
-        self.set_name('CTRL(%s:%d)' % (self.msc.addr(), self.PORT))
-        self.set_child_of(msc)
+        super().__init__(log.C_BUS, 'CTRL(%s:%d)' % (self.msc.addr(), self.PORT))
 
     def ctrl(self):
         return osmo_ctrl.OsmoCtrl(self.msc.addr(), self.PORT)
diff --git a/src/osmo_gsm_tester/osmo_nitb.py b/src/osmo_gsm_tester/osmo_nitb.py
index b2ddfb7..535f73a 100644
--- a/src/osmo_gsm_tester/osmo_nitb.py
+++ b/src/osmo_gsm_tester/osmo_nitb.py
@@ -32,10 +32,9 @@
     bts = None
 
     def __init__(self, suite_run, ip_address):
+        super().__init__(log.C_RUN, 'osmo-nitb_%s' % ip_address.get('addr'))
         self.suite_run = suite_run
         self.ip_address = ip_address
-        self.set_log_category(log.C_RUN)
-        self.set_name('osmo-nitb_%s' % ip_address.get('addr'))
         self.bts = []
 
     def start(self):
@@ -96,8 +95,7 @@
             msisdn = self.suite_run.resources_pool.next_msisdn(modem)
         modem.set_msisdn(msisdn)
         self.log('Add subscriber', msisdn=msisdn, imsi=modem.imsi())
-        with self:
-            OsmoNitbCtrl(self).subscriber_add(modem.imsi(), msisdn, modem.ki())
+        OsmoNitbCtrl(self).subscriber_add(modem.imsi(), msisdn, modem.ki())
 
     def subscriber_attached(self, *modems):
         return self.imsi_attached(*[m.imsi() for m in modems])
@@ -108,8 +106,7 @@
         return all([(imsi in attached) for imsi in imsis])
 
     def imsi_list_attached(self):
-        with self:
-            return OsmoNitbCtrl(self).subscriber_list_active()
+        return OsmoNitbCtrl(self).subscriber_list_active()
 
     def running(self):
         return not self.process.terminated()
@@ -123,8 +120,7 @@
 
     def __init__(self, nitb):
         self.nitb = nitb
-        self.set_name('CTRL(%s:%d)' % (self.nitb.addr(), OsmoNitbCtrl.PORT))
-        self.set_child_of(nitb)
+        super().__init__(log.C_BUS, 'CTRL(%s:%d)' % (self.nitb.addr(), OsmoNitbCtrl.PORT))
 
     def ctrl(self):
         return osmo_ctrl.OsmoCtrl(self.nitb.addr(), OsmoNitbCtrl.PORT)
diff --git a/src/osmo_gsm_tester/pcap_recorder.py b/src/osmo_gsm_tester/pcap_recorder.py
index f3b1e6a..398ec6c 100644
--- a/src/osmo_gsm_tester/pcap_recorder.py
+++ b/src/osmo_gsm_tester/pcap_recorder.py
@@ -27,14 +27,13 @@
 class PcapRecorder(log.Origin):
 
     def __init__(self, suite_run, run_dir, iface=None, filters=''):
-        self.suite_run = suite_run
-        self.run_dir = run_dir
         self.iface = iface
         if not self.iface:
             self.iface = "any"
         self.filters = filters
-        self.set_log_category(log.C_RUN)
-        self.set_name('pcap-recorder_%s' % self.iface)
+        super().__init__(log.C_RUN, 'pcap-recorder_%s' % self.iface, filters=self.filters)
+        self.suite_run = suite_run
+        self.run_dir = run_dir
         self.start()
 
     def start(self):
diff --git a/src/osmo_gsm_tester/process.py b/src/osmo_gsm_tester/process.py
index e5d38f3..99e94ba 100644
--- a/src/osmo_gsm_tester/process.py
+++ b/src/osmo_gsm_tester/process.py
@@ -33,9 +33,8 @@
     killed = None
 
     def __init__(self, name, run_dir, popen_args, **popen_kwargs):
+        super().__init__(log.C_RUN, name)
         self.name_str = name
-        self.set_name(name)
-        self.set_log_category(log.C_RUN)
         self.run_dir = run_dir
         self.popen_args = popen_args
         self.popen_kwargs = popen_kwargs
@@ -62,23 +61,21 @@
         return f
 
     def launch(self):
-        with self:
+        log.dbg('cd %r; %s %s' % (
+                os.path.abspath(str(self.run_dir)),
+                ' '.join(['%s=%r'%(k,v) for k,v in self.popen_kwargs.get('env', {}).items()]),
+                ' '.join(self.popen_args)))
 
-            self.dbg('cd %r; %s %s' % (
-                    os.path.abspath(str(self.run_dir)),
-                    ' '.join(['%s=%r'%(k,v) for k,v in self.popen_kwargs.get('env', {}).items()]),
-                    ' '.join(self.popen_args)))
-
-            self.process_obj = subprocess.Popen(
-                self.popen_args,
-                stdout=self.make_output_log('stdout'),
-                stderr=self.make_output_log('stderr'),
-                stdin=subprocess.PIPE,
-                shell=False,
-                cwd=self.run_dir.path,
-                **self.popen_kwargs)
-            self.set_name(self.name_str, pid=self.process_obj.pid)
-            self.log('Launched')
+        self.process_obj = subprocess.Popen(
+            self.popen_args,
+            stdout=self.make_output_log('stdout'),
+            stderr=self.make_output_log('stderr'),
+            stdin=subprocess.PIPE,
+            shell=False,
+            cwd=self.run_dir.path,
+            **self.popen_kwargs)
+        self._set_name(self.name_str, pid=self.process_obj.pid)
+        self.log('Launched')
 
     def _poll_termination(self, time_to_wait_for_term=5):
         wait_step = 0.001
diff --git a/src/osmo_gsm_tester/resource.py b/src/osmo_gsm_tester/resource.py
index 7cc32bb..a67ce0f 100644
--- a/src/osmo_gsm_tester/resource.py
+++ b/src/osmo_gsm_tester/resource.py
@@ -83,7 +83,7 @@
     def __init__(self):
         self.config_path = config.get_config_file(RESOURCES_CONF)
         self.state_dir = config.get_state_dir()
-        self.set_name(conf=self.config_path, state=self.state_dir.path)
+        super().__init__(log.C_CNF, conf=self.config_path, state=self.state_dir.path)
         self.read_conf()
 
     def read_conf(self):
@@ -158,6 +158,7 @@
             return ReservedResources(self, origin, to_be_reserved)
 
     def free(self, origin, to_be_freed):
+        log_ctx = origin
         with self.state_dir.lock(origin.origin_id()):
             rrfile_path = self.state_dir.mk_parentdir(RESERVED_RESOURCES_FILE)
             reserved = Resources(config.read(rrfile_path, if_missing_return={}))
@@ -202,19 +203,19 @@
 
         with self.state_dir.lock(origin_id):
             msisdn_path = self.state_dir.child(LAST_USED_MSISDN_FILE)
-            with log.Origin(msisdn_path):
-                last_msisdn = '1000'
-                if os.path.exists(msisdn_path):
-                    if not os.path.isfile(msisdn_path):
-                        raise RuntimeError('path should be a file but is not: %r' % msisdn_path)
-                    with open(msisdn_path, 'r') as f:
-                        last_msisdn = f.read().strip()
-                    schema.msisdn(last_msisdn)
+            log_ctx = msisdn_path
+            last_msisdn = '1000'
+            if os.path.exists(msisdn_path):
+                if not os.path.isfile(msisdn_path):
+                    raise RuntimeError('path should be a file but is not: %r' % msisdn_path)
+                with open(msisdn_path, 'r') as f:
+                    last_msisdn = f.read().strip()
+                schema.msisdn(last_msisdn)
 
-                next_msisdn = util.msisdn_inc(last_msisdn)
-                with open(msisdn_path, 'w') as f:
-                    f.write(next_msisdn)
-                return next_msisdn
+            next_msisdn = util.msisdn_inc(last_msisdn)
+            with open(msisdn_path, 'w') as f:
+                f.write(next_msisdn)
+            return next_msisdn
 
 
 class NoResourceExn(Exception):
diff --git a/src/osmo_gsm_tester/schema.py b/src/osmo_gsm_tester/schema.py
index fb27f32..00facc4 100644
--- a/src/osmo_gsm_tester/schema.py
+++ b/src/osmo_gsm_tester/schema.py
@@ -124,9 +124,9 @@
                 validate_item(path, list_v, schema)
             return
 
-        with log.Origin(item=path):
-            type_validator = SCHEMA_TYPES.get(want_type)
-            type_validator(value)
+        log_ctx = path
+        type_validator = SCHEMA_TYPES.get(want_type)
+        type_validator(value)
 
     def nest(parent_path, config, schema):
         if parent_path:
diff --git a/src/osmo_gsm_tester/suite.py b/src/osmo_gsm_tester/suite.py
index 55f81b1..1157b6a 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
@@ -142,7 +138,7 @@
         self.fail_tb = tb_str
         self.err('%s: %s' % (self.fail_type, self.fail_message))
         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=%r' % conf_name
+        combination = copy.deepcopy(self.definition.conf.get(conf_name) or {})
+        self.dbg(definition_conf=combination)
+        for scenario in self.scenarios:
+            log_ctx = '{combining_scenarios=%r, %s}' % (conf_name, scenario.name())
+            c = scenario.get(conf_name)
+            self.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,17 +227,16 @@
 
     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()
         except BaseException as e:
@@ -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!'
diff --git a/src/osmo_gsm_tester/template.py b/src/osmo_gsm_tester/template.py
index 33ce2f6..4d8ed2a 100644
--- a/src/osmo_gsm_tester/template.py
+++ b/src/osmo_gsm_tester/template.py
@@ -26,7 +26,7 @@
 from .util import dict2obj
 
 _lookup = None
-_logger = log.Origin('no templates dir set')
+_logger = log.Origin(log.C_CNF, 'no templates dir set')
 
 def set_templates_dir(*templates_dirs):
     global _lookup
@@ -39,7 +39,7 @@
             raise RuntimeError('templates dir is not a dir: %r'
                                % os.path.abspath(d))
     _lookup = TemplateLookup(directories=templates_dirs)
-    _logger = log.Origin('Templates', category=log.C_CNF)
+    _logger = log.Origin(log.C_CNF, 'Templates')
 
 def render(name, values):
     '''feed values dict into template and return rendered result.
@@ -48,11 +48,11 @@
     if _lookup is None:
         set_templates_dir()
     tmpl_name = name + '.tmpl'
-    with log.Origin(tmpl_name):
-        template = _lookup.get_template(tmpl_name)
-        _logger.dbg('rendering', tmpl_name)
+    log_ctx = tmpl_name
+    template = _lookup.get_template(tmpl_name)
+    _logger.dbg('rendering', tmpl_name)
 
-        line_info_name = tmpl_name.replace('-', '_').replace('.', '_')
-        return template.render(**dict2obj(values))
+    line_info_name = tmpl_name.replace('-', '_').replace('.', '_')
+    return template.render(**dict2obj(values))
 
 # vim: expandtab tabstop=4 shiftwidth=4
diff --git a/src/osmo_gsm_tester/test.py b/src/osmo_gsm_tester/test.py
index 2958501..679ba96 100644
--- a/src/osmo_gsm_tester/test.py
+++ b/src/osmo_gsm_tester/test.py
@@ -24,9 +24,6 @@
 suite = None
 test = None
 resources = None
-log = None
-dbg = None
-err = None
 wait = None
 wait_no_raise = None
 sleep = None
@@ -40,9 +37,6 @@
     suite = suite_run
     test = _test
     resources = suite_run.reserved_resources
-    log = test.log
-    dbg = test.dbg
-    err = test.err
     wait = lambda *args, **kwargs: event_module.wait(suite_run, *args, **kwargs)
     wait_no_raise = lambda *args, **kwargs: event_module.wait_no_raise(suite_run, *args, **kwargs)
     sleep = lambda *args, **kwargs: event_module.sleep(suite_run, *args, **kwargs)
diff --git a/src/osmo_gsm_tester/trial.py b/src/osmo_gsm_tester/trial.py
index 741f3a7..d54e96c 100644
--- a/src/osmo_gsm_tester/trial.py
+++ b/src/osmo_gsm_tester/trial.py
@@ -57,8 +57,7 @@
 
     def __init__(self, trial_dir):
         self.path = os.path.abspath(trial_dir)
-        self.set_name(os.path.basename(self.path))
-        self.set_log_category(log.C_TST)
+        super().__init__(log.C_TST, os.path.basename(self.path))
         self.dir = util.Dir(self.path)
         self.inst_dir = util.Dir(self.dir.child('inst'))
         self.bin_tars = []
@@ -69,7 +68,8 @@
         return self.name()
 
     def __enter__(self):
-        # add a log target to log to the run dir
+        '''add a log target to log to the run dir, write taken marker, log a
+        starting separator.'''
         run_dir = self.get_run_dir()
         detailed_log = run_dir.new_child(FILE_LOG)
         self.log_targets = [
@@ -82,11 +82,10 @@
         log.large_separator(self.name(), sublevel=1)
         self.log('Detailed log at', detailed_log)
         self.take()
-        super().__enter__()
         return self
 
     def __exit__(self, *exc_info):
-        super().__exit__(*exc_info)
+        '''log a report, then remove log file targets for this trial'''
         self.log_report()
         for lt in self.log_targets:
             lt.remove()
@@ -195,6 +194,8 @@
                 except BaseException as e:
                     # when the program is aborted by a signal (like Ctrl-C), escalate to abort all.
                     self.err('TRIAL RUN ABORTED: %s' % type(e).__name__)
+                    # log the traceback before the trial's logging is ended
+                    log.log_exn()
                     raise
                 finally:
                     if suite_run.status != suite.SuiteRun.PASS:

-- 
To view, visit https://gerrit.osmocom.org/2886
To unsubscribe, visit https://gerrit.osmocom.org/settings

Gerrit-MessageType: newchange
Gerrit-Change-Id: I5f9b53150f2bb6fa9d63ce27f0806f0ca6a45e90
Gerrit-PatchSet: 1
Gerrit-Project: osmo-gsm-tester
Gerrit-Branch: master
Gerrit-Owner: Neels Hofmeyr <nhofmeyr at sysmocom.de>



More information about the gerrit-log mailing list