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
This commit is contained in:
Neels Hofmeyr
parent
112da03e98
commit
3b493f3567
|
|
@ -161,9 +161,9 @@ trial test_suite hello_world.py
|
|||
----------------------------------------------
|
||||
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 @@ trial test_suite hello_world.py
|
|||
----------------------------------------------
|
||||
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 @@ trial test_suite hello_world.py
|
|||
----------------------------------------------
|
||||
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 @@ trial test_suite hello_world.py
|
|||
----------------------------------------------
|
||||
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
|
|||
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]]
|
||||
|
||||
|
|
|
|||
|
|
@ -21,7 +21,6 @@ import os
|
|||
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 @@ class Origin:
|
|||
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 @@ class Origin:
|
|||
'''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()
|
||||
|
|
|
|||
|
|
@ -71,9 +71,8 @@ class Test(log.Origin):
|
|||
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:
|
||||
|
|
|
|||
|
|
@ -43,6 +43,7 @@ prompt = None
|
|||
Sms = None
|
||||
process = None
|
||||
tenv = None
|
||||
print = None
|
||||
|
||||
class Timeout(Exception):
|
||||
pass
|
||||
|
|
@ -351,12 +352,15 @@ class TestEnv(log_module.Origin):
|
|||
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 @@ def setup(suite_run, _test):
|
|||
Sms = Sms_class
|
||||
process = process_module
|
||||
prompt = tenv.prompt
|
||||
print = tenv.print
|
||||
return tenv
|
||||
|
||||
# vim: expandtab tabstop=4 shiftwidth=4
|
||||
|
|
|
|||
Loading…
Reference in New Issue