test-run expects test output on stdout and not on stderr

[ligurio]

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

[Totktonada]

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.