fix and refactor logging: drop 'with', simplify
With the recent fix of the junit report related issues, another issue arose: the 'with log.Origin' was changed to disallow __enter__ing an object twice to fix problems, now still code would fail because it tries to do 'with' on the same object twice. The only reason is to ensure that logging is associated with a given object. Instead of complicating even more, implement differently. Refactor logging to simplify use: drop the 'with Origin' style completely, and instead use the python stack to determine which objects are created by which, and which object to associate a log statement with. The new way: we rely on the convention that each class instance has a local 'self' referencing the object instance. If we need to find an origin as a new object's parent, or to associate a log message with, we traverse each stack frame, fetching the first local 'self' object that is a log.Origin class instance. How to use: Simply call log.log() anywhere, and it finds an Origin object to log for, from the stack. Alternatively call self.log() for any Origin() object to skip the lookup. Create classes as child class of log.Origin and make sure to call super().__init__(category, name). This constructor will magically find a parent Origin on the stack. When an exception happens, we first escalate the exception up through call scopes to where ever it is handled by log.log_exn(). This then finds an Origin object in the traceback's stack frames, no need to nest in 'with' scopes. Hence the 'with log.Origin' now "happens implicitly", we can write pure natural python code, no more hassles with scope ordering. Furthermore, any frame can place additional logging information in a frame by calling log.ctx(). This is automatically inserted in the ancestry associated with a log statement / exception. Change-Id: I5f9b53150f2bb6fa9d63ce27f0806f0ca6a45e90
This commit is contained in:
parent
0e57aadd28
commit
1a7a3f0e43
|
@ -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
|
||||
|
|
|
@ -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
|
||||
|
|
|
@ -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('<origin>', log.C_TST, 'from log.log()')
|
||||
log.dbg('<origin>', log.C_TST, 'from log.dbg(), not seen')
|
||||
log.log('from log.log()', _origin='<origin>', _category=log.C_TST)
|
||||
log.dbg('from log.dbg(), not seen', _origin='<origin>', _category=log.C_TST)
|
||||
log.set_level(log.C_TST, log.L_DBG)
|
||||
log.dbg('<origin>', log.C_TST, 'from log.dbg()')
|
||||
log.dbg('from log.dbg()', _origin='<origin>', _category=log.C_TST)
|
||||
log.set_level(log.C_TST, log.L_LOG)
|
||||
log.err('<origin>', log.C_TST, 'from log.err()')
|
||||
log.err('from log.err()', _origin='<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
|
||||
|
||||
|
|
|
@ -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',
|
||||
|
|
|
@ -78,7 +78,7 @@ want = {
|
|||
'modem': [ { 'times': 2 } ],
|
||||
}
|
||||
|
||||
origin = log.Origin('testowner')
|
||||
origin = log.Origin(None, 'testowner')
|
||||
|
||||
resources = pool.reserve(origin, want)
|
||||
|
||||
|
|
|
@ -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.
|
||||
|
|
|
@ -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))
|
||||
|
|
|
@ -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
|
||||
!
|
||||
|
|
|
@ -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):
|
||||
|
|
|
@ -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')
|
||||
|
|
|
@ -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
|
||||
|
||||
|
|
|
@ -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.
|
||||
|
|
|
@ -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):
|
||||
|
|
|
@ -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):
|
||||
|
|
|
@ -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
|
||||
|
||||
|
|
|
@ -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
|
||||
|
|
|
@ -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)))
|
||||
|
|
|
@ -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
|
||||
|
||||
|
|
|
@ -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)
|
||||
|
|
|
@ -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)
|
||||
|
|
|
@ -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):
|
||||
|
|
|
@ -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
|
||||
|
|
|
@ -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):
|
||||
|
|
|
@ -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:
|
||||
|
|
|
@ -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!'
|
||||
|
|
|
@ -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
|
||||
|
|
|
@ -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:
|
||||
|
|
Loading…
Reference in New Issue