From 1a7a3f0e4318bccbd3ed177d5b07fa3618d06868 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Sat, 10 Jun 2017 01:18:27 +0200 Subject: fix and refactor logging: drop 'with', simplify With the recent fix of the junit report related issues, another issue arose: the 'with log.Origin' was changed to disallow __enter__ing an object twice to fix problems, now still code would fail because it tries to do 'with' on the same object twice. The only reason is to ensure that logging is associated with a given object. Instead of complicating even more, implement differently. Refactor logging to simplify use: drop the 'with Origin' style completely, and instead use the python stack to determine which objects are created by which, and which object to associate a log statement with. The new way: we rely on the convention that each class instance has a local 'self' referencing the object instance. If we need to find an origin as a new object's parent, or to associate a log message with, we traverse each stack frame, fetching the first local 'self' object that is a log.Origin class instance. How to use: Simply call log.log() anywhere, and it finds an Origin object to log for, from the stack. Alternatively call self.log() for any Origin() object to skip the lookup. Create classes as child class of log.Origin and make sure to call super().__init__(category, name). This constructor will magically find a parent Origin on the stack. When an exception happens, we first escalate the exception up through call scopes to where ever it is handled by log.log_exn(). This then finds an Origin object in the traceback's stack frames, no need to nest in 'with' scopes. Hence the 'with log.Origin' now "happens implicitly", we can write pure natural python code, no more hassles with scope ordering. Furthermore, any frame can place additional logging information in a frame by calling log.ctx(). This is automatically inserted in the ancestry associated with a log statement / exception. Change-Id: I5f9b53150f2bb6fa9d63ce27f0806f0ca6a45e90 --- selftest/config_test.ok | 36 ++++++++++++------------ selftest/log_test.ok | 9 +++--- selftest/log_test.py | 70 ++++++++++++++++++++--------------------------- selftest/resource_test.ok | 4 +-- selftest/resource_test.py | 2 +- selftest/suite_test.ok | 18 ++++++------ selftest/suite_test.py | 2 +- selftest/template_test.ok | 2 +- 8 files changed, 66 insertions(+), 77 deletions(-) (limited to 'selftest') diff --git a/selftest/config_test.ok b/selftest/config_test.ok index 40a5dcb..80b5a06 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 7ed94a0..17198b7 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 7670c8e..9136906 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) - -with Thing('print_redirected'): - print("Not throwing an exception in 'with:' works.") + def l1(self): + level2 = Thing('level2') + level2.l2() -def l1(): - level1 = Thing('level1') - with level1: - l2() - -def l2(): - level2 = Thing('level2') - with level2: - l3(level2) + def l2(self): + level3 = Thing('level3') + level3.l3(self) -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 cdc3519..d366cf9 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 c78485e..a0ec490 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 54c950a..2808474 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 2a92f47..86c4c25 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 d031c96..1267dac 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 ! -- cgit v1.2.3