From 3b493f35678a574a06dfbece61a2deda1bcc73ad Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Tue, 1 Dec 2020 03:51:27 +0100 Subject: 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 --- selftest/suite_test/suite_test.ok | 32 ++++++++++++++++---------------- 1 file changed, 16 insertions(+), 16 deletions(-) (limited to 'selftest') 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 @@ 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]] -- cgit v1.2.3