test-run expects test output on stdout and not on stderr
ligurio opened this issue · 1 comments
Steps to reproduce:
- create a test, that write to stdout, and run it using test-run
- test-run successfully read test output for this test
- create test, that write to stderr, and run it using test-run
- test-run will report "No output during 10 seconds. Will abort after 120 seconds without output." because no output on stdout
Expected result
test-run listen stderr too
Actual result
test-run does not listen stderr, stdout only.
Observation
In Tarantool print()
write to stdout and log.info()
(and other methods of module log
) write to stderr:
[0] ~/sources/MRG/tarantool$ tarantool -e "print('stdout string')" 2> stderr 1> stdout
[0] ~/sources/MRG/tarantool$ cat stderr
[0] ~/sources/MRG/tarantool$ cat stdout
stdout string
[0] ~/sources/MRG/tarantool$ tarantool -e "require('log').info('stderr string')" 2> stderr 1> stdout
[0] ~/sources/MRG/tarantool$ cat stdout
[0] ~/sources/MRG/tarantool$ cat stderr
stderr string
Log output
Let's demonstrate it:
[1] ~/sources/MRG/tarantool$ cat test/box-luatest/stderr_test.lua
local t = require('luatest')
local g = t.group('test-run')
local log = require('log')
g.test_example_1 = function()
for i = 1, 25 do
os.execute("sleep 1")
log.info("one more second")
end
end
[1] ~/sources/MRG/tarantool$ luatest -c test/box-luatest/stderr_test.lua
Tarantool version is 2.11.0-rc2-0-g2ae0c94a2
Running with --shuffle group:4769
one more second
one more second
one more second
one more second
one more second
.
<snipped>
Ran 1 tests in 25.011 seconds, 1 succeeded, 0 failed
[0] ~/sources/MRG/tarantool$ ./test/test-run.py --debug --verbose --no-output-timeout=15 box-luatest/stderr_test.lua
<snipped>
======================================================================================
WORKR TEST PARAMS RESULT
---------------------------------------------------------------------------------
No output during 10 seconds. Will abort after 15 seconds without output. List of workers not reporting the status:
- 001_box-luatest [box-luatest/stderr_test.lua, None] at /tmp/t/001_box-luatest/stderr.result:0
No output during 20 seconds. Will abort after 15 seconds without output. List of workers not reporting the status:
- 001_box-luatest [box-luatest/stderr_test.lua, None] at /tmp/t/001_box-luatest/stderr.result:0
Test hung! Result content mismatch:
[File does not exist: box-luatest/stderr.result]
[Main process] No output from workers. It seems that we hang. Send SIGKILL to workers; exiting...
---------------------------------------------------------------------------------
Top 10 tests by occupied memory (RSS, Mb):
* 19.8 box-luatest/stderr_test.lua
(Tests quicker than 0.1 seconds may be missed.)
---------------------------------------------------------------------------------
Top 10 longest tests (seconds):
---------------------------------------------------------------------------------
* undone: 1
Expected result
test-run listen stderr too
I would ask a clarification here. Am I understand right that your idea is to track stderr to postpone the --no-output-timeout
watchdog? Is it the sole reason to catch stderr or there are other supposed ones?
I'm asking, because --no-output-timeout
shouldn't normally be reached -- it likely reveals some problem in test-run itself. (I have added some details about timeout handling into #382.)
And this timeout is quite large by default -- two minutes.
BTW, as I see from the implementation (luatest_server.py
), test-run reads a mixed stdout+stderr stream from luatest. So it doesn't differentiate stdout and stderr here.
There is a buffering problem in this place. A test may write something, but test-run doesn't report it. luatest_server.py
is likely the same here as app_server.py
, see #119.
I had attempts to solve it, but no luck. One idea I didn't try with test-run is to disable stdout buffering in the child.