Logs are lost if tests don't yield

[locker]

Consider the following test:

local t = require('luatest')
local g = t.group()

g.test_bad = function()
    t.log('foobar')
    t.assert(false)
end

It fails but it doesn't print any logs, no matter if it's run with capturing enabled or disabled:

$ bin/luatest test/bad_test.lua
Tarantool version is 3.4.0-entrypoint-227-gf1ccb2f142f6
started logging into a pipe, SIGHUP log rotation disabled
luatest | 2025-04-07 11:00:04.688 [26199] main/104/luatest/luatest.log runner.lua:306 I> Bootstrap finished: 1 test(s), 0 group(s)
F

Failed tests:
-------------

1) bad.test_bad
/home/vlad/src/tarantool/luatest/test/bad_test.lua:6: expected: a value evaluating to true, actual: false
stack traceback:
        /home/vlad/src/tarantool/luatest/test/bad_test.lua:6: in function 'bad.test_bad'
Captured stdout:
luatest | 2025-04-07 11:00:04.695 [26199] main/104/luatest/luatest.log runner.lua:312 I> Directory /tmp/t removed via cleanup procedure


Ran 1 tests in 0.010 seconds, 0 succeeded, 1 failed

Failed tests:

bad.test_bad
$ bin/luatest -c test/bad_test.lua
Tarantool version is 3.4.0-entrypoint-227-gf1ccb2f142f6
started logging into a pipe, SIGHUP log rotation disabled
luatest | 2025-04-07 11:00:11.079 [26211] main/104/luatest/luatest.log runner.lua:306 I> Bootstrap finished: 1 test(s), 0 group(s)
F

Failed tests:
-------------

1) bad.test_bad
/home/vlad/src/tarantool/luatest/test/bad_test.lua:6: expected: a value evaluating to true, actual: false
stack traceback:
        /home/vlad/src/tarantool/luatest/test/bad_test.lua:6: in function 'bad.test_bad'
Ran 1 tests in 0.010 seconds, 0 succeeded, 1 failed

Failed tests:

bad.test_bad

If the test sleeps, the logged message is captured but the assertion check isn't:

local t = require('luatest')
local g = t.group()

g.test_bad = function()
    t.log('foobar')
    require('fiber').sleep(0.1)
    t.assert(false)
end

Output:

$ bin/luatest test/bad_test.lua
Tarantool version is 3.4.0-entrypoint-227-gf1ccb2f142f6
started logging into a pipe, SIGHUP log rotation disabled
luatest | 2025-04-07 11:06:44.188 [26690] main/104/luatest/luatest.log runner.lua:306 I> Bootstrap finished: 1 test(s), 0 group(s)
F

Failed tests:
-------------

1) bad.test_bad
/home/vlad/src/tarantool/luatest/test/bad_test.lua:7: expected: a value evaluating to true, actual: false
stack traceback:
        /home/vlad/src/tarantool/luatest/test/bad_test.lua:7: in function 'bad.test_bad'
Captured stdout:
luatest | 2025-04-07 11:06:44.193 [26690] main/104/luatest/luatest.log runner.lua:312 I> Directory /tmp/t removed via cleanup procedure
luatest | 2025-04-07 11:06:44.193 [26690] main/104/luatest/luatest.log hooks.lua:244 I> Run hook before_each
luatest | 2025-04-07 11:06:44.193 [26690] main/104/luatest/luatest.log hooks.lua:259 I> Run hook before_test
luatest | 2025-04-07 11:06:44.193 [26690] main/104/luatest/luatest.log hooks.lua:289 I> Start test bad.test_bad
luatest | 2025-04-07 11:06:44.194 [26690] main/104/luatest/luatest.log bad_test.lua:5 I> foobar


Ran 1 tests in 0.112 seconds, 0 succeeded, 1 failed

Failed tests:

bad.test_bad

This happens because luatest processes logs printed by tests in a separate fiber, through a pipe. If the test doesn't yield, the fiber isn't scheduled. If there are too many logs, they may be lost because the pipe is limited in size and luatest uses the non-blocking mode when writing logs (see #417).

We could fix this by either processing logs in a separate process or by accumulating them in a local variable (or a file), as suggested by @Totktonada. Also, we probably need to flush logs after each test case.