This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.
neels gerrit-no-reply at lists.osmocom.orgneels has submitted this change. ( https://gerrit.osmocom.org/c/osmo-gsm-tester/+/21513 )
Change subject: do not redirect_stdout in test scripts
......................................................................
do not redirect_stdout in test scripts
In a test, I called print() on a multi-line string and saw the log
showing each line 0.2 seconds apart. redirect.stdout seems to be pretty
inefficient.
Instead, put a print() function into the testenv, to directly call log()
on the strings passed to print().
The initial idea for redirect_stdout was that we could print() in any
deeper functions called from a test script. But we have no such nested
print() anywhere, only in test scripts themselves.
As a result of this, a multi-line print() in test scripts now no longer
puts the log prefix (timestamp, test name...) and suffix (backtrace /
source position) to each single line, but prints the multiline block
between a single log prefix and suffix -- exactly like the log()
function does everywhere else.
I actually briefly implemented adding the log prefix to each separate
line everywhere, but decided that it is not a good idea: in some places
we log config file snippets and other lists, and prepending the log
prefix to each line makes pasting such a snippet from (say) a jenkins
log super cumbersome. And the log prefix (backtrace) attached on each
separate line makes multiline blocks very noisy, unreadable.
Change-Id: I0972c66b9165bd7f2b0b387e0335172849199193
---
M selftest/suite_test/suite_test.ok
M src/osmo_gsm_tester/core/log.py
M src/osmo_gsm_tester/core/test.py
M src/osmo_gsm_tester/testenv.py
4 files changed, 24 insertions(+), 55 deletions(-)
Approvals:
pespin: Looks good to me, approved
diff --git a/selftest/suite_test/suite_test.ok b/selftest/suite_test/suite_test.ok
index caf5a5b..3790e1a 100644
--- a/selftest/suite_test/suite_test.ok
+++ b/selftest/suite_test/suite_test.ok
@@ -161,9 +161,9 @@
----------------------------------------------
tst hello_world.py:[LINENR]: hello world [test_suite↪hello_world.py:[LINENR]]
tst hello_world.py:[LINENR]: I am 'test_suite' / 'hello_world.py' [test_suite↪hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: one [test_suite↪hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: two [test_suite↪hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: three [test_suite↪hello_world.py:[LINENR]]
+tst hello_world.py:[LINENR]: one
+two
+three [test_suite↪hello_world.py:[LINENR]]
tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py]
---------------------------------------------------------------------
trial test_suite PASS
@@ -390,9 +390,9 @@
----------------------------------------------
tst hello_world.py:[LINENR]: hello world [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
tst hello_world.py:[LINENR]: I am 'test_suite' / 'hello_world.py' [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: one [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: two [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: three [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
+tst hello_world.py:[LINENR]: one
+two
+three [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py] [test.py:[LINENR]]
---------------------------------------------------------------------
trial test_suite PASS
@@ -545,9 +545,9 @@
----------------------------------------------
tst hello_world.py:[LINENR]: hello world [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
tst hello_world.py:[LINENR]: I am 'test_suite' / 'hello_world.py' [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: one [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: two [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: three [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
+tst hello_world.py:[LINENR]: one
+two
+three [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py] [test.py:[LINENR]]
---------------------------------------------------------------------
trial test_suite PASS
@@ -746,9 +746,9 @@
----------------------------------------------
tst hello_world.py:[LINENR]: hello world [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
tst hello_world.py:[LINENR]: I am 'test_suite' / 'hello_world.py' [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: one [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: two [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
-tst hello_world.py:[LINENR]: three [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
+tst hello_world.py:[LINENR]: one
+two
+three [test_suite↪hello_world.py:[LINENR]] [hello_world.py:[LINENR]]
tst hello_world.py:[LINENR] Test passed (N.N sec) [test_suite↪hello_world.py] [test.py:[LINENR]]
---------------------------------------------------------------------
trial test_suite PASS
@@ -946,10 +946,10 @@
trial test_suite test_suite_params.py
----------------------------------------------
tst test_suite_params.py:[LINENR]: starting test [test_suite↪test_suite_params.py:[LINENR]] [test_suite_params.py:[LINENR]]
-tst test_suite_params.py:[LINENR]: SPECIFIC SUITE CONFIG: {'some_suite_global_param': 'heyho', [test_suite↪test_suite_params.py:[LINENR]] [test_suite_params.py:[LINENR]]
-tst test_suite_params.py:[LINENR]: 'test_suite_params': {'one_bool_parameter': 'true', [test_suite↪test_suite_params.py:[LINENR]] [test_suite_params.py:[LINENR]]
-tst test_suite_params.py:[LINENR]: 'second_list_parameter': ['23', '45']}, [test_suite↪test_suite_params.py:[LINENR]] [test_suite_params.py:[LINENR]]
-tst test_suite_params.py:[LINENR]: 'test_timeout': {'timeout': '1'}} [test_suite↪test_suite_params.py:[LINENR]] [test_suite_params.py:[LINENR]]
+tst test_suite_params.py:[LINENR]: SPECIFIC SUITE CONFIG: {'some_suite_global_param': 'heyho',
+ 'test_suite_params': {'one_bool_parameter': 'true',
+ 'second_list_parameter': ['23', '45']},
+ 'test_timeout': {'timeout': '1'}} [test_suite↪test_suite_params.py:[LINENR]] [test_suite_params.py:[LINENR]]
tst test_suite_params.py:[LINENR]: SPECIFIC TEST CONFIG: {'one_bool_parameter': 'true', 'second_list_parameter': ['23', '45']} [test_suite↪test_suite_params.py:[LINENR]] [test_suite_params.py:[LINENR]]
tst test_suite_params.py:[LINENR] Test passed (N.N sec) [test_suite↪test_suite_params.py] [test.py:[LINENR]]
diff --git a/src/osmo_gsm_tester/core/log.py b/src/osmo_gsm_tester/core/log.py
index 2b8db62..7a13bdd 100644
--- a/src/osmo_gsm_tester/core/log.py
+++ b/src/osmo_gsm_tester/core/log.py
@@ -21,7 +21,6 @@
import sys
import time
import traceback
-import contextlib
import atexit
from datetime import datetime # we need this for strftime as the one from time doesn't carry microsecond info
from inspect import getframeinfo, stack
@@ -466,9 +465,6 @@
def _set_log_category(self, category):
self._log_category = category
- def redirect_stdout(self):
- return contextlib.redirect_stdout(SafeRedirectStdout(self))
-
def ancestry(self):
origins = []
n = 10
@@ -501,37 +497,6 @@
'''same as log.err() but passes this object to skip looking up an origin'''
err(*messages, _origin=self, _src=_src, **named_items)
-class SafeRedirectStdout:
- '''
- To be able to use 'print' in test scripts, this is used to redirect stdout
- to a test class' log() function. However, it turns out doing that breaks
- python debugger sessions -- it uses extended features of stdout, and will
- fail dismally if it finds this wrapper in sys.stdout. Luckily, overriding
- __getattr__() to return the original sys.__stdout__ attributes for anything
- else than write() makes the debugger session work nicely again!
- '''
- _log_line_buf = None
-
- def __init__(self, origin):
- self.origin = origin
-
- def write(self, message):
- lines = message.splitlines()
- if not lines:
- return
- if self._log_line_buf:
- lines[0] = self._log_line_buf + lines[0]
- self._log_line_buf = None
- if not message.endswith('\n'):
- self._log_line_buf = lines[-1]
- lines = lines[:-1]
- for line in lines:
- _log(messages=(line,),
- origin=self.origin, level=L_LOG, src=2)
-
- def __getattr__(self, name):
- return sys.__stdout__.__getattribute__(name)
-
def trace(exc_info=None, origin=None):
if exc_info is None:
exc_info = sys.exc_info()
diff --git a/src/osmo_gsm_tester/core/test.py b/src/osmo_gsm_tester/core/test.py
index 896eb4c..cf910ea 100644
--- a/src/osmo_gsm_tester/core/test.py
+++ b/src/osmo_gsm_tester/core/test.py
@@ -71,9 +71,8 @@
self.status = Test.UNKNOWN
self.start_timestamp = time.time()
testenv_obj = testenv.setup(self.suite_run, self)
- with self.redirect_stdout():
- util.run_python_file('%s.%s' % (self.suite_run.definition.name(), self.basename),
- self.path)
+ 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:
diff --git a/src/osmo_gsm_tester/testenv.py b/src/osmo_gsm_tester/testenv.py
index ebc8f91..b3db84f 100644
--- a/src/osmo_gsm_tester/testenv.py
+++ b/src/osmo_gsm_tester/testenv.py
@@ -43,6 +43,7 @@
Sms = None
process = None
tenv = None
+print = None
class Timeout(Exception):
pass
@@ -351,12 +352,15 @@
self.log('using BVCI', bvci)
return bvci
+ def print(self, *messages, **named_items):
+ log_module.log(*messages, _origin=self.test(), _src=3, **named_items)
+
def setup(suite_run, _test):
from .core.event_loop import MainLoop
from .obj.sms import Sms as Sms_class
- global test, log, dbg, err, wait, wait_no_raise, sleep, poll, prompt, Sms, process, tenv
+ global test, log, dbg, err, wait, wait_no_raise, sleep, poll, prompt, Sms, process, tenv, print
test = _test
log = test.log
@@ -370,6 +374,7 @@
Sms = Sms_class
process = process_module
prompt = tenv.prompt
+ print = tenv.print
return tenv
# vim: expandtab tabstop=4 shiftwidth=4
--
To view, visit https://gerrit.osmocom.org/c/osmo-gsm-tester/+/21513
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings
Gerrit-Project: osmo-gsm-tester
Gerrit-Branch: master
Gerrit-Change-Id: I0972c66b9165bd7f2b0b387e0335172849199193
Gerrit-Change-Number: 21513
Gerrit-PatchSet: 4
Gerrit-Owner: neels <nhofmeyr at sysmocom.de>
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: pespin <pespin at sysmocom.de>
Gerrit-MessageType: merged
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20201210/21aff3d9/attachment.htm>