diff --git a/selftest/config_test.ok b/selftest/config_test.ok index 40a5dcb8..80b5a065 100644 --- a/selftest/config_test.ok +++ b/selftest/config_test.ok @@ -54,42 +54,42 @@ Validation: Error --- -: ERR: ValueError: config item not known: 'a_dict[]' Validation: Error - unknown band: ---- (item='bts[].trx[].band'): ERR: ValueError: Unknown GSM band: 'what' +--- bts[].trx[].band: ERR: ValueError: Unknown GSM band: 'what' Validation: Error - invalid v4 addrs: ---- (item='addr[]'): ERR: ValueError: Invalid IPv4 address: '1.2.3' +--- addr[]: ERR: ValueError: Invalid IPv4 address: '1.2.3' Validation: Error ---- (item='addr[]'): ERR: ValueError: Invalid IPv4 address: '1.2.3 .4' +--- addr[]: ERR: ValueError: Invalid IPv4 address: '1.2.3 .4' Validation: Error ---- (item='addr[]'): ERR: ValueError: Invalid IPv4 address: '91.2.3' +--- addr[]: ERR: ValueError: Invalid IPv4 address: '91.2.3' Validation: Error ---- (item='addr[]'): ERR: ValueError: Invalid IPv4 address: 'go away' +--- addr[]: ERR: ValueError: Invalid IPv4 address: 'go away' Validation: Error ---- (item='addr[]'): ERR: ValueError: Invalid IPv4 address: '' +--- addr[]: ERR: ValueError: Invalid IPv4 address: '' Validation: Error ---- (item='addr[]'): ERR: ValueError: Invalid IPv4 address: None +--- addr[]: ERR: ValueError: Invalid IPv4 address: None Validation: Error - invalid hw addrs: ---- (item='hwaddr[]'): ERR: ValueError: Invalid hardware address: '1.2.3' +--- hwaddr[]: ERR: ValueError: Invalid hardware address: '1.2.3' Validation: Error ---- (item='hwaddr[]'): ERR: ValueError: Invalid hardware address: '0b:0c:0d:0e:0f:0g' +--- hwaddr[]: ERR: ValueError: Invalid hardware address: '0b:0c:0d:0e:0f:0g' Validation: Error ---- (item='hwaddr[]'): ERR: ValueError: Invalid hardware address: '0b:0c:0d:0e : 0f:0f' +--- hwaddr[]: ERR: ValueError: Invalid hardware address: '0b:0c:0d:0e : 0f:0f' Validation: Error ---- (item='hwaddr[]'): ERR: ValueError: Invalid hardware address: 'go away' +--- hwaddr[]: ERR: ValueError: Invalid hardware address: 'go away' Validation: Error ---- (item='hwaddr[]'): ERR: ValueError: Invalid hardware address: '' +--- hwaddr[]: ERR: ValueError: Invalid hardware address: '' Validation: Error ---- (item='hwaddr[]'): ERR: ValueError: Invalid hardware address: None +--- hwaddr[]: ERR: ValueError: Invalid hardware address: None Validation: Error - invalid imsis: ---- (item='imsi[]'): ERR: ValueError: Invalid IMSI: '99999999x9' +--- imsi[]: ERR: ValueError: Invalid IMSI: '99999999x9' Validation: Error ---- (item='imsi[]'): ERR: ValueError: Invalid IMSI: '123 456 789 123' +--- imsi[]: ERR: ValueError: Invalid IMSI: '123 456 789 123' Validation: Error ---- (item='imsi[]'): ERR: ValueError: Invalid IMSI: 'go away' +--- imsi[]: ERR: ValueError: Invalid IMSI: 'go away' Validation: Error ---- (item='imsi[]'): ERR: ValueError: Invalid IMSI: '' +--- imsi[]: ERR: ValueError: Invalid IMSI: '' Validation: Error ---- (item='imsi[]'): ERR: ValueError: Invalid IMSI: None +--- imsi[]: ERR: ValueError: Invalid IMSI: None Validation: Error diff --git a/selftest/log_test.ok b/selftest/log_test.ok index 7ed94a00..17198b77 100644 --- a/selftest/log_test.ok +++ b/selftest/log_test.ok @@ -32,10 +32,9 @@ but no time format 01:02:03 --- LogTest: hello log, no category nor name set [log_test.py:110] 01:02:03 --- LogTest: DBG: debug message, no category nor name set [log_test.py:113] - Testing logging of Exceptions, tracing origins -Not throwing an exception in 'with:' works. nested print just prints -01:02:03 tst level3: nested log() [level1↪level2↪level3] [log_test.py:145] -01:02:03 tst level2: nested l2 log() from within l3 scope [level1↪level2] [log_test.py:146] -01:02:03 tst level3: ERR: ValueError: bork [level1↪level2↪level3] [log_test.py:147: raise ValueError('bork')] -- Enter the same Origin context twice +01:02:03 tst level3: nested log() [level1↪level2↪level3] [log_test.py:135] +01:02:03 tst level2: nested l2 log() from within l3 scope [level1↪level2] [log_test.py:136] +01:02:03 tst level3: ERR: ValueError: bork [level1↪level2↪level3] [log_test.py:137: raise ValueError('bork')] +- Disallow origin loops disallowed successfully diff --git a/selftest/log_test.py b/selftest/log_test.py index 7670c8ea..9136906e 100755 --- a/selftest/log_test.py +++ b/selftest/log_test.py @@ -32,20 +32,20 @@ log.style_change(time=True, time_fmt=fake_time) log.set_all_levels(None) print('- Testing global log functions') -log.log('', log.C_TST, 'from log.log()') -log.dbg('', log.C_TST, 'from log.dbg(), not seen') +log.log('from log.log()', _origin='', _category=log.C_TST) +log.dbg('from log.dbg(), not seen', _origin='', _category=log.C_TST) log.set_level(log.C_TST, log.L_DBG) -log.dbg('', log.C_TST, 'from log.dbg()') +log.dbg('from log.dbg()', _origin='', _category=log.C_TST) log.set_level(log.C_TST, log.L_LOG) -log.err('', log.C_TST, 'from log.err()') +log.err('from log.err()', _origin='', _category=log.C_TST) print('- Testing log.Origin functions') class LogTest(log.Origin): - pass + def __init__(self, *name_items, **detail_items): + super().__init__(log.C_TST, *name_items, **detail_items) + +t = LogTest('some', 'name', some="detail") -t = LogTest() -t.set_log_category(log.C_TST) -t.set_name('some', 'name', some="detail") t.log("hello log") t.err("hello err") @@ -86,10 +86,10 @@ t.dbg("add src") log.style_change(origin=True) t.dbg("add origin") +# some space to keep source line numbers identical to previous code + print('- Testing origin_width') -t = LogTest() -t.set_log_category(log.C_TST) -t.set_name('shortname') +t = LogTest('shortname') log.style(origin_width=23, time_fmt=fake_time) t.log("origin str set to 23 chars") t.set_name('very long name', some='details', and_some=(3, 'things', 'in a tuple')) @@ -97,16 +97,16 @@ t.log("long origin str") t.dbg("long origin str dbg") t.err("long origin str err") + print('- Testing log.Origin with omitted info') t = LogTest() -t.set_log_category(log.C_TST) t.log("hello log, name implicit from class name") -t = LogTest() -t.set_name('explicit_name') +t = LogTest('explicit_name') +t._set_log_category(None) t.log("hello log, no category set") - t = LogTest() +t._set_log_category(None) t.log("hello log, no category nor name set") t.dbg("hello log, no category nor name set, not seen") log.set_level(log.C_DEFAULT, log.L_DBG) @@ -117,47 +117,37 @@ log.style(time_fmt=fake_time, origin_width=0) class Thing(log.Origin): def __init__(self, some_path): - self.set_log_category(log.C_TST) - self.set_name(some_path) + super().__init__(log.C_TST, some_path) def say(self, msg): print(msg) -#log.style_change(trace=True) + def l1(self): + level2 = Thing('level2') + level2.l2() -with Thing('print_redirected'): - print("Not throwing an exception in 'with:' works.") + def l2(self): + level3 = Thing('level3') + level3.l3(self) -def l1(): - level1 = Thing('level1') - with level1: - l2() - -def l2(): - level2 = Thing('level2') - with level2: - l3(level2) - -def l3(level2): - level3 = Thing('level3') - with level3: + def l3(self, level2): print('nested print just prints') - level3.log('nested log()') + self.log('nested log()') level2.log('nested l2 log() from within l3 scope') raise ValueError('bork') try: - l1() + level1 = Thing('level1') + level1.l1() except Exception: log.log_exn() -print('- Enter the same Origin context twice') +print('- Disallow origin loops') try: t = Thing('foo') - with t: - with t: - raise RuntimeError('this should not be reached') -except AssertionError: + t._set_parent(t) + raise RuntimeError('this should not be reached') +except log.OriginLoopError: print('disallowed successfully') pass diff --git a/selftest/resource_test.ok b/selftest/resource_test.ok index cdc3519d..d366cf9a 100644 --- a/selftest/resource_test.ok +++ b/selftest/resource_test.ok @@ -13,8 +13,8 @@ cnf -: DBG: Found config file paths.conf as [PATH]/selftest/conf/paths.conf in . cnf -: DBG: [PATH]/selftest/conf/paths.conf: relative path ./test_work/state_dir is [PATH]/selftest/conf/test_work/state_dir cnf -: DBG: [PATH]/selftest/conf/paths.conf: relative path ./suite_test is [PATH]/selftest/conf/suite_test cnf -: DBG: Found path state_dir as [PATH]/selftest/conf/test_work/state_dir -cnf -: DBG: Found config file resources.conf as [PATH]/selftest/conf/resources.conf in ./conf which is [PATH]/selftest/conf -cnf -: DBG: Found path state_dir as [PATH]/selftest/conf/test_work/state_dir +cnf ResourcesPool: DBG: Found config file resources.conf as [PATH]/selftest/conf/resources.conf in ./conf which is [PATH]/selftest/conf +cnf ResourcesPool: DBG: Found path state_dir as [PATH]/selftest/conf/test_work/state_dir *** all resources: {'arfcn': [{'_hash': 'e620569450f8259b3f0212ec19c285dd07df063c', 'arfcn': '512', diff --git a/selftest/resource_test.py b/selftest/resource_test.py index c78485ea..a0ec4901 100755 --- a/selftest/resource_test.py +++ b/selftest/resource_test.py @@ -78,7 +78,7 @@ want = { 'modem': [ { 'times': 2 } ], } -origin = log.Origin('testowner') +origin = log.Origin(None, 'testowner') resources = pool.reserve(origin, want) diff --git a/selftest/suite_test.ok b/selftest/suite_test.ok index 54c950a8..28084744 100644 --- a/selftest/suite_test.ok +++ b/selftest/suite_test.ok @@ -7,7 +7,7 @@ cnf -: DBG: Found path suites_dir as [PATH]/selftest/suite_test - no suite.conf cnf -: DBG: Found path suites_dir as [PATH]/selftest/suite_test cnf empty_dir: DBG: reading suite.conf ---- [PATH]/selftest/suite_test/empty_dir/suite.conf: ERR: FileNotFoundError: [Errno 2] No such file or directory: '[PATH]/selftest/suite_test/empty_dir/suite.conf' +cnf [PATH]/selftest/suite_test/empty_dir/suite.conf: ERR: FileNotFoundError: [Errno 2] No such file or directory: '[PATH]/selftest/suite_test/empty_dir/suite.conf' [empty_dir↪[PATH]/selftest/suite_test/empty_dir/suite.conf] - valid suite dir cnf -: DBG: Found path suites_dir as [PATH]/selftest/suite_test cnf test_suite: DBG: reading suite.conf @@ -22,15 +22,15 @@ resources: - times: '2' - run hello world test -cnf -: DBG: Found config file resources.conf as [PATH]/selftest/suite_test/resources.conf in ./suite_test which is [PATH]/selftest/suite_test -cnf -: DBG: Found path state_dir as [PATH]/selftest/suite_test/test_work/state_dir +cnf ResourcesPool: DBG: Found config file resources.conf as [PATH]/selftest/suite_test/resources.conf in ./suite_test which is [PATH]/selftest/suite_test +cnf ResourcesPool: DBG: Found path state_dir as [PATH]/selftest/suite_test/test_work/state_dir --------------------------------------------------------------------- trial test_suite --------------------------------------------------------------------- tst test_suite: reserving resources in [PATH]/selftest/suite_test/test_work/state_dir ... tst test_suite: DBG: {combining='resources'} -tst test_suite: DBG: {definition_conf={bts=[{'times': '1'}], ip_address=[{'times': '1'}], modem=[{'times': '2'}]}} [test_suite↪(combining_scenarios='resources')↪test_suite] +tst {combining_scenarios='resources'}: DBG: {definition_conf={bts=[{'times': '1'}], ip_address=[{'times': '1'}], modem=[{'times': '2'}]}} [test_suite↪{combining_scenarios='resources'}] tst test_suite: Reserving 1 x bts (candidates: 3) tst test_suite: DBG: Picked - _hash: 07d9c8aaa940b674efcbbabdd69f58a6ce4e94f9 addr: 10.42.42.114 @@ -83,7 +83,7 @@ trial test_suite trial test_suite test_error.py ---------------------------------------------- tst test_error.py:[LINENR]: I am 'test_suite' / 'test_error.py:[LINENR]' [test_suite↪test_error.py:[LINENR]] [test_error.py:[LINENR]] -tst test_error.py:[LINENR]: ERR: AssertionError: test_error.py:[LINENR]: assert False [test_error.py:[LINENR]] [test_suite↪test_error.py:[LINENR]] [suite.py:[LINENR]] +tst test_error.py:[LINENR]: ERR: AssertionError: test_error.py:[LINENR]: assert False [test_suite↪test_error.py:[LINENR]] [test_error.py:[LINENR]: assert False] tst test_error.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_error.py:[LINENR]] [suite.py:[LINENR]] --------------------------------------------------------------------- trial test_suite FAIL @@ -92,7 +92,7 @@ FAIL: test_suite (fail: 1, skip: 5) skip: hello_world.py (N.N sec) skip: mo_mt_sms.py skip: mo_sms.py - FAIL: test_error.py (N.N sec) AssertionError: test_error.py:[LINENR]: assert False [test_error.py:[LINENR]] + FAIL: test_error.py (N.N sec) AssertionError: test_error.py:[LINENR]: assert False skip: test_fail.py skip: test_fail_raise.py @@ -106,7 +106,7 @@ trial test_suite trial test_suite test_fail.py ---------------------------------------------- tst test_fail.py:[LINENR]: I am 'test_suite' / 'test_fail.py:[LINENR]' [test_suite↪test_fail.py:[LINENR]] [test_fail.py:[LINENR]] -tst test_fail.py:[LINENR]: ERR: EpicFail: This failure is expected [test_suite↪test_fail.py:[LINENR]] [suite.py:[LINENR]] +tst test_fail.py:[LINENR]: ERR: EpicFail: This failure is expected [test_suite↪test_fail.py:[LINENR]] [test_fail.py:[LINENR]] tst test_fail.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_fail.py:[LINENR]] [suite.py:[LINENR]] --------------------------------------------------------------------- trial test_suite FAIL @@ -128,7 +128,7 @@ trial test_suite ---------------------------------------------- trial test_suite test_fail_raise.py ---------------------------------------------- -tst test_fail_raise.py:[LINENR]: ERR: ExpectedFail: This failure is expected [test_fail_raise.py:[LINENR]] [test_suite↪test_fail_raise.py:[LINENR]] [suite.py:[LINENR]] +tst test_fail_raise.py:[LINENR]: ERR: ExpectedFail: This failure is expected [test_suite↪test_fail_raise.py:[LINENR]] [test_fail_raise.py:[LINENR]: raise ExpectedFail('This failure is expected')] tst test_fail_raise.py:[LINENR]: Test FAILED (N.N sec) [test_suite↪test_fail_raise.py:[LINENR]] [suite.py:[LINENR]] --------------------------------------------------------------------- trial test_suite FAIL @@ -139,6 +139,6 @@ FAIL: test_suite (fail: 1, skip: 5) skip: mo_sms.py skip: test_error.py (N.N sec) skip: test_fail.py (N.N sec) - FAIL: test_fail_raise.py (N.N sec) ExpectedFail: This failure is expected [test_fail_raise.py:[LINENR]] + FAIL: test_fail_raise.py (N.N sec) ExpectedFail: This failure is expected - graceful exit. diff --git a/selftest/suite_test.py b/selftest/suite_test.py index 2a92f477..86c4c25d 100755 --- a/selftest/suite_test.py +++ b/selftest/suite_test.py @@ -20,7 +20,7 @@ assert(isinstance(s_def, suite.SuiteDefinition)) print(config.tostr(s_def.conf)) print('- run hello world test') -trial = log.Origin('trial') +trial = log.Origin(log.C_TST, 'trial') s = suite.SuiteRun(trial, 'test_suite', s_def) results = s.run_tests('hello_world.py') print(report.suite_to_text(s)) diff --git a/selftest/template_test.ok b/selftest/template_test.ok index d031c966..1267dac6 100644 --- a/selftest/template_test.ok +++ b/selftest/template_test.ok @@ -1,5 +1,5 @@ - Testing: fill a config file with values -cnf Templates: DBG: rendering osmo-nitb.cfg.tmpl [osmo-nitb.cfg.tmpl↪Templates] +cnf Templates: DBG: rendering osmo-nitb.cfg.tmpl ! Configuration rendered by osmo-gsm-tester password foo ! diff --git a/src/osmo_gsm_tester/bts_osmotrx.py b/src/osmo_gsm_tester/bts_osmotrx.py index 00835123..7d12c853 100644 --- a/src/osmo_gsm_tester/bts_osmotrx.py +++ b/src/osmo_gsm_tester/bts_osmotrx.py @@ -36,10 +36,9 @@ class OsmoBtsTrx(log.Origin): 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 5f2b3cbc..30fff0e8 100644 --- a/src/osmo_gsm_tester/bts_sysmo.py +++ b/src/osmo_gsm_tester/bts_sysmo.py @@ -35,52 +35,50 @@ class SysmoBts(log.Origin): 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 @@ class SysmoBts(log.Origin): 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 @@ class SysmoBts(log.Origin): 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 38d8e2f4..20ae83e1 100644 --- a/src/osmo_gsm_tester/config.py +++ b/src/osmo_gsm_tester/config.py @@ -95,7 +95,7 @@ def _get_config_file(basename, fail_if_missing=True): 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 @@ def get_configured_path(label, allow_unset=False): 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 @@ def get_configured_path(label, allow_unset=False): 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 @@ def get_scenarios_dir(): 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 @@ def get_defaults(for_kind): 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 @@ def add(dest, src): if dest_val is None: dest[key] = val else: - with log.Origin(key=key): - add(dest_val, val) + log.ctx(key=key) + add(dest_val, val) return if is_list(dest): if not is_list(src): @@ -235,19 +234,19 @@ def combine(dest, src): raise ValueError('cannot combine dict with a value of type: %r' % type(src)) for key, val in src.items(): + log.ctx(key=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=i) + combine(dest[i], src[i]) return if dest == src: return @@ -260,16 +259,16 @@ def overlay(dest, src): raise ValueError('cannot combine dict with a value of type: %r' % type(src)) for key, val in src.items(): + log.ctx(key=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=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 c3c679be..6f64ef9e 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 poll(): 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_no_raise(log_obj, condition, condition_args, condition_kwargs, timeout, 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 f098f2b8..c4a66295 100644 --- a/src/osmo_gsm_tester/log.py +++ b/src/osmo_gsm_tester/log.py @@ -45,6 +45,41 @@ C_CNF = 'cnf' C_BUS = 'bus' C_DEFAULT = '---' +LOG_CTX_VAR = '_log_ctx_' + +def dbg(*messages, _origin=None, _category=None, _src=None, **named_items): + '''Log on debug level. See also log()''' + _log(messages, named_items, origin=_origin, category=_category, level=L_DBG, src=_src) + +def log(*messages, _origin=None, _category=None, _level=L_LOG, _src=None, **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. _src is normally an integer indicating how many + levels up the stack sits the interesting source file to log about, can also + be a string. 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, src=_src) + +def err(*messages, _origin=None, _category=None, _src=None, **named_items): + '''Log on error level. See also log()''' + _log(messages, named_items, origin=_origin, category=_category, level=L_ERR, src=_src) + +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 +87,8 @@ DATEFMT = '%H:%M:%S' 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 +189,7 @@ class LogTarget: 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 +208,13 @@ class LogTarget: 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() + # only log ancestry when there is more than one + if origin._parent is not None: + 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 +263,7 @@ def level_str(level): 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 +277,17 @@ def get_src_from_caller(levels_up=1): 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=None, levels_up=1): + if exc_info is None: + exc_info = sys.exc_info() + 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) @@ -262,31 +301,112 @@ def get_line_for_src(src_path): return caller.lineno return None +def ctx(*name_items, **detail_items): + '''Store log context in the current frame. This string will appear as + origin information for exceptions thrown within the calling scope.''' + if not name_items and not detail_items: + ctx_obj(None) + if not detail_items and len(name_items) == 1 and isinstance(name_items[0], Origin): + ctx_obj(name_items[0]) + else: + ctx_obj(compose_message(name_items, detail_items)) + +def ctx_obj(origin_or_str): + f = sys._getframe(2) + if origin_or_str is None: + f.f_locals.pop(LOG_CTX_VAR, None) + else: + f.f_locals[LOG_CTX_VAR] = origin_or_str + +class OriginLoopError(Error): + pass 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. + + Each child class *must* call super().__init__(category, name), to allow + noting its parent origins. ''' - _global_current_origin = None _global_id = None - _log_category = None - _src = None _name = None _origin_id = None + _log_category = None + _parent = None - _parent_origin = None + @staticmethod + def find_on_stack(except_obj=None, f=None): + if f is None: + f = sys._getframe(2) + log_ctx_obj = None + origin = None + while f is not None: + l = f.f_locals - def __init__(self, *name_items, category=None, **detail_items): - self.set_log_category(category) + # 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_VAR) + 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()._set_parent(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()._set_parent(origin) + p = log_ctx_obj + while p: + p._set_log_category(origin._log_category) + p = p._parent + 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._set_parent(Origin.find_on_stack(except_obj=self)) + + def _set_parent(self, parent): + # make sure to avoid loops + p = parent + while p: + if p is self: + raise OriginLoopError('Origin parent loop') + p = p._parent + self._parent = parent def set_name(self, *name_items, **detail_items): + '''Change the origin's name for log output; rather use the constructor. + This function can be used to change the name in case naming info + becomes available only after class creation (like a pid)''' if name_items: name = '-'.join([str(i) for i in name_items]) elif not detail_items: @@ -313,87 +433,43 @@ class Origin: 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) - origin = origin._parent_origin + def ancestry(self): + origins = [] + n = 10 + origin = self + while origin: + origins.insert(0, origin) + origin = origin._parent + 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: + return self._parent.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, _src=3, **named_items): + '''same as log.log() but passes this object to skip looking up an origin''' + log(*messages, _origin=self, _src=_src, **named_items) + + def dbg(self, *messages, _src=3, **named_items): + '''same as log.dbg() but passes this object to skip looking up an origin''' + dbg(*messages, _origin=self, _src=_src, **named_items) + + def err(self, *messages, _src=3, **named_items): + '''same as log.err() but passes this object to skip looking up an origin''' + err(*messages, _origin=self, _src=_src, **named_items) class SafeRedirectStdout: ''' @@ -407,7 +483,7 @@ class SafeRedirectStdout: _log_line_buf = None def __init__(self, origin): - self._origin = origin + self.origin = origin def write(self, message): lines = message.splitlines() @@ -419,93 +495,34 @@ class SafeRedirectStdout: 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=2) 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 fc9bba4c..67659e1c 100644 --- a/src/osmo_gsm_tester/ofono_client.py +++ b/src/osmo_gsm_tester/ofono_client.py @@ -139,12 +139,14 @@ class ModemDbusInteraction(log.Origin): 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. @@ -175,7 +177,7 @@ class ModemDbusInteraction(log.Origin): try: return self.dbus_obj()[interface_name] except KeyError: - self.raise_exn('Modem interface is not available:', interface_name) + raise log.Error('Modem interface is not available:', interface_name) def signal(self, interface_name, signal): return getattr(self.interface(interface_name), signal) @@ -310,8 +312,7 @@ class Modem(log.Origin): 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.register_attempts = 0 @@ -371,8 +372,7 @@ class Modem(log.Origin): def imsi(self): imsi = self.conf.get('imsi') if not imsi: - with self: - raise RuntimeError('No IMSI') + raise log.Error('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 77533950..5447118a 100644 --- a/src/osmo_gsm_tester/osmo_bsc.py +++ b/src/osmo_gsm_tester/osmo_bsc.py @@ -31,10 +31,9 @@ class OsmoBsc(log.Origin): 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 0b717faa..b5a947f4 100644 --- a/src/osmo_gsm_tester/osmo_ctrl.py +++ b/src/osmo_gsm_tester/osmo_ctrl.py @@ -29,8 +29,7 @@ class CtrlInterfaceExn(Exception): 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 @@ class OsmoCtrl(log.Origin): 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 3492f065..110faa5c 100644 --- a/src/osmo_gsm_tester/osmo_hlr.py +++ b/src/osmo_gsm_tester/osmo_hlr.py @@ -32,10 +32,9 @@ class OsmoHlr(log.Origin): 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 @@ class OsmoHlr(log.Origin): 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 @@ class OsmoHlr(log.Origin): 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 3e722fbf..b3852749 100644 --- a/src/osmo_gsm_tester/osmo_mgcpgw.py +++ b/src/osmo_gsm_tester/osmo_mgcpgw.py @@ -30,10 +30,9 @@ class OsmoMgcpgw(log.Origin): 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 3a822f19..443b254c 100644 --- a/src/osmo_gsm_tester/osmo_msc.py +++ b/src/osmo_gsm_tester/osmo_msc.py @@ -32,10 +32,9 @@ class OsmoMsc(log.Origin): config = 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 @@ -100,12 +99,11 @@ class OsmoMsc(log.Origin): 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() @@ -117,8 +115,7 @@ class OsmoMscCtrl(log.Origin): 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 b4bf2475..3104842f 100644 --- a/src/osmo_gsm_tester/osmo_nitb.py +++ b/src/osmo_gsm_tester/osmo_nitb.py @@ -32,10 +32,9 @@ class OsmoNitb(log.Origin): 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): @@ -106,8 +105,7 @@ class OsmoNitb(log.Origin): 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]) @@ -118,8 +116,7 @@ class OsmoNitb(log.Origin): 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() @@ -133,8 +130,7 @@ class OsmoNitbCtrl(log.Origin): 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 f3b1e6a3..398ec6ce 100644 --- a/src/osmo_gsm_tester/pcap_recorder.py +++ b/src/osmo_gsm_tester/pcap_recorder.py @@ -27,14 +27,13 @@ from . import log, util, config, template, process, osmo_ctrl 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 e5d38f34..d24bf3dc 100644 --- a/src/osmo_gsm_tester/process.py +++ b/src/osmo_gsm_tester/process.py @@ -33,9 +33,8 @@ class Process(log.Origin): 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 @@ class Process(log.Origin): 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 7cc32bb1..dbfc4e0c 100644 --- a/src/osmo_gsm_tester/resource.py +++ b/src/osmo_gsm_tester/resource.py @@ -83,7 +83,7 @@ class ResourcesPool(log.Origin): 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 @@ class ResourcesPool(log.Origin): 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 @@ class ResourcesPool(log.Origin): 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 fb27f321..d652aa76 100644 --- a/src/osmo_gsm_tester/schema.py +++ b/src/osmo_gsm_tester/schema.py @@ -124,9 +124,9 @@ def validate(config, schema): 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 55f81b16..eeaf7df4 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!' diff --git a/src/osmo_gsm_tester/template.py b/src/osmo_gsm_tester/template.py index 33ce2f65..0ddfc842 100644 --- a/src/osmo_gsm_tester/template.py +++ b/src/osmo_gsm_tester/template.py @@ -26,7 +26,7 @@ from . import log 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 @@ def set_templates_dir(*templates_dirs): 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 @@ def render(name, values): 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/trial.py b/src/osmo_gsm_tester/trial.py index 741f3a7d..d54e96cd 100644 --- a/src/osmo_gsm_tester/trial.py +++ b/src/osmo_gsm_tester/trial.py @@ -57,8 +57,7 @@ class Trial(log.Origin): 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 @@ class Trial(log.Origin): 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 @@ class Trial(log.Origin): 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 @@ class Trial(log.Origin): 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: