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