path: root/src/osmo_gsm_tester/log.py
AgeCommit message (Collapse)AuthorFilesLines
2020-04-11Create core directory to contain most of code not in object classes used by ↵Pau Espin Pedrol1-604/+0
tests Change-Id: I9aec6c55ccd71894182057d36e0025b69925d314
2020-02-24Add test log to junit outputPau Espin Pedrol1-0/+3
Change-Id: Ieb5566a41ecf3a9512db579eb37e8d8ed5325057
2018-02-13log: Use sys._getframe() to avoid stat(2) callsHolger Hans Peter Freyther1-2/+4
The Osmo MS driver is launching many many processes and I would like to use the logging framework for the code as well. Unfortunately the inspect/traceback code will use a linecache which will execute stat(2) on one or more python files. Related: OS#2927 Change-Id: I8f6bacadcf74d3aa25db1e1f41644f64aa19cf92
2017-07-03Add microsecond accuracy to log timestampsPau Espin Pedrol1-3/+4
This is useful while debugging and trying to check events across other outputs such as pcap files, process logs, etc. Change-Id: I43bb5c6e9977189251802bc2b078c52eb046bab8
2017-06-13fix and refactor logging: drop 'with', simplifyNeels Hofmeyr1-171/+188
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
2017-06-09refactor: fix error handling; fix log.Origin; only one trialNeels Hofmeyr1-11/+15
A bit of refactoring to fix logging and error reporting, and simplify the code. This transmogrifies some of the things committed in 0ffb41440661631fa1d520c152be4cf8ebd4c46b "Add JUnit XML reports; refactor test reporting", which did not fully match the code structuring ideas used in osmo-gsm-tester. Also solve some problems present from the start of the code base. Though this is a bit of a code bomb, it would take a lot of time to separate this into smaller bits: these changes are closely related and resulted incrementally from testing error handling and logging details. I hope it's ok. Things changed / problems fixed: Allow only a single trial to be run per cmdline invocation: unbloat trial and suite invocation in osmo-gsm-tester.py. There is a SuiteDefinition, intended to be immutable, and a mutable SuiteRun. SuiteDefinition had a list of tests, which was modified by the SuiteRun to record test results. Instead, have only the test basenames in the SuiteDefinition and create a new set of Test() instances for each SuiteRun, to ensure that no state leaks between separate suite runs. State leaking across runs can be seen in http://jenkins.osmocom.org/jenkins/view/osmo-gsm-tester/job/osmo-gsm-tester_run/453/ where an earlier sms test for sysmo succeeds, but its state gets overwritten by the later sms test for trx that fails. The end result is that both tests failed, although the first run was successful. Fix a problem with Origin: log.Origin allowed to be __enter__ed more than once, skipping the second entry. The problem there is that we'd still __exit__ twice or more, popping the Origin off the stack even though it should still remain. We could count __enter__ recurrences, but instead, completely disallow entering a second time. A code path should have one 'with' statement per object, at pivotal points like run_suites or run_tests. Individual utility functions should not do 'with' on a central object. The structure needed is, in pseudo code: try: with trial: try: with suite_run: try: with test: test_actions() The 'with' needs to be inside the 'try', so that the exception can be handled in __exit__ before it reaches the exception logging. To clarify this, like test exceptions caught in Test.run(), also move suite exception handling from Trial into SuiteRun.run_tests(). There are 'with self' in Test.run() and SuiteRun.run_tests(), which are well placed, because these are pivotal points in the main code path. Log output: clearly separate logging of distinct suites and test scripts, by adding more large_separator() calls at the start of each test. Place these separator calls in more logical places. Add separator size and spacing args. Log output: print tracebacks only once, for the test script where they happen. Have less state that duplicates other state: drop SuiteRun.test_failed_ctr and suite.test_skipped_ctr, instead add SuiteRun.count_test_results(). For test failure reporting, store the traceback text in a separate member var. In the text report, apply above changes and unclutter to achieve a brief and easy to read result overview: print less filler characters, drop the starting times, drop the tracebacks. This can be found in the individual test logs. Because the tracebacks are no longer in the text report, the suite_test.py can just print the reports and expect that output instead of asserting individual contents. In the text report, print duration in precision of .1 seconds. Add origin information and a traceback text to the junit XML result to give more context when browsing the result XML. For 'AssertionError', add the source line of where the assertion hit. Drop the explicit Failure exception. We don't need one specific exception to mark a failure, instead any arbitrary exception is treated as a failure. Use the exception's class name as fail_type. Though my original idea was to use raising exceptions as the only way to cause a test failure, I'm keeping the set_fail() function as an alternative way, because it allows test specific cleanup and may come in handy later. To have both ways integrate seamlessly, shift some result setting into 'finally' clauses and make sure higher levels (suite, trial) count the contained items' stati. Minor tweak: write the 'pass' and 'skip' reports in lower case so that the 'FAIL' stands out. Minor tweak: pass the return code that the program exit should return further outward, so that the exit(1) call does not cause a SystemExit exception to be logged. The aims of this patch are: - Logs are readable so that it is clear which logging belongs to which test and suite. - The logging origins are correct (vs. parents gone missing as previously) - A single test error does not cause following tests or suites to be skipped. - An exception "above" Exception, i.e. SystemExit and the like, *does* immediately abort all tests and suites, and the results for tests that were not run are reported as "unknown" (rather than skipped on purpose): - Raising a SystemExit aborts all. - Hitting ctrl-c aborts all. - The resulting summary in the log is brief and readable. Change-Id: Ibf0846d457cab26f54c25e6906a8bb304724e2d8
2017-06-07fix problem in origin ancestry: don't add self twiceNeels Hofmeyr1-0/+10
Also add various comments to illustrate what is going on during origin resolution. In the regression tests' expectations, some duplicate entries in the origins are removed, and hence no list of deeper origin ancestry is printed anymore. Change-Id: I42c3b8635b54c31c27699140e200c1f75a6ada29
2017-06-06cosmetic: whitespace in log.pyNeels Hofmeyr1-3/+2
Change-Id: I356725ba7d874d3d41afb5e4c89dac188c8d7dcc
2017-06-03Re-License under GPLv3-or-later instead of AGPLv3-or-laterHarald Welte1-3/+3
The "Affero" nature makes sense for the Osmocom network components like BSC, SGSN, etc. as they are typically operated to provide a network service. For testing, this doesn't make so much sense as it is difficult to imagine people creating a business out of offering to run test cases on an end-to-end Osmocom GSM network. So let's drop the 'Affero' here. All code is so far developed by sysmocom staff, so as Managing Director of sysmocom I can effect such a license change unilaterally. Change-Id: I8959c2d605854ffdc21cb29c0fe0e715685c4c05
2017-05-29log.Origin: return self on __enter__Neels Hofmeyr1-1/+2
Allows using 'with some_origin() as foo:' constructs. Not used actively, but is sometimes useful during debugging sessions. Change-Id: I7a6463ee39761775305dd2272c24f248552db4ad
2017-05-28log: change 'log_all_origins' from bool to a list of levels to apply toNeels Hofmeyr1-6/+7
The idea is to see the full origin list for log level ERR, while the rest of the logging can be kept less verbose. Change-Id: I0277782652548fa321f767da79b207d70678fad1
2017-05-08log.py: add a log target option to omit the list of deeper originsNeels Hofmeyr1-3/+6
Change-Id: I8a0a508ee4aeffe940be906de0e431740653a08c
2017-05-08run dir: write detailed log fileNeels Hofmeyr1-0/+3
For each run on a trial, create a log target that logs to a file in the run dir. Set all levels to DBG in that log target. Related: OS#2206 Change-Id: Ie7279aeaf32950f85d4145abdc917024003d1d99
2017-05-08log: make 32 the default origin_width.Neels Hofmeyr1-2/+2
Change-Id: I1159395251332f3b1af3b3a322e7191559105faa
2017-05-08log.py: add FileLogTargetNeels Hofmeyr1-0/+25
Will be used in a subsequent commit. Change-Id: Id3dfdeea236eb8ade5e6c80e64d5c3ce4de96b81
2017-05-08log.py: LogTarget: return self for chaining modifiersNeels Hofmeyr1-0/+4
For example this allows tgt = LogTarget(foo).set_all_levels(bar).style_change(baz) Change-Id: If168cc06f644bde6183f3bc51e394c7705386b3e
2017-05-08log.py: tweak LogTarget list, require explicit LogTargetNeels Hofmeyr1-25/+22
Rename log_sink to log_write_func to make it more clear. Remember the list of log targets as static member LogTarget.all_targets. Make each LogTarget instance register with the list of targets implicitly. No longer create a default log target, rather create one explicitly in osmo-gsm-tester.py. Change-Id: I5844485eaed536cb34b44bfe23dc635fe1982dcd
2017-04-27fix 'make check'Neels Hofmeyr1-3/+11
Apply various fixes that arose from test case code rot. These tests will now be used to verify patches submitted to gerrit, so they need to be up to par. Change-Id: I5277be0c434226d9d02e038f0bc72fd2557350c1 Related: OS#2215
2017-04-13fix octphy, fix conf, improve loggingYour Name1-0/+12
Clearly separate the kinds of BTS hardware the GSM tester knows ('type') from the NITB's bts/type config item ('osmobsc_bts_type' -- not 'osmonitb_...' to stay in tune with future developments: it is the libbsc that needs this). For BTS hardware kinds, use the full name of the binary for osmo driven models: osmo-bts-sysmo, osmo-bts-trx, osmo-bts-octphy. Change-Id: I1aa9b48e74013a93f9db1a34730f17717fb3b36c
2017-04-10trying to get sysmobts to work and various detailsNeels Hofmeyr1-3/+4
I know that these commit messages aren't very good, but the code is not stable yet, so I'm not bothering with details. Change-Id: I2d5e5f4a5407725d71093cbd71ef97b271eb8197
2017-04-09make prematurely exited processes fail the testNeels Hofmeyr1-7/+19
Change-Id: I54394c40718b44378df597e32003742059052869
2017-04-08core implementationNeels Hofmeyr1-33/+129
code bomb implementing the bulk of the osmo-gsm-tester Change-Id: I53610becbf643ed51b90cfd9debc6992fe211ec9
2017-03-28initial import0.1Neels Hofmeyr1-0/+405
The original osmo-gsm-tester was an internal development at sysmocom, mostly by D. Laszlo Sitzer <dlsitzer@sysmocom.de>, of which this public osmo-gsm-tester is a refactoring / rewrite. This imports an early state of the refactoring and is not functional yet. Bits from the earlier osmo-gsm-tester will be added as needed. The earlier commit history is not imported.