Show log of tests

[alyapunov]

Now log sometimes seems not to work at all, and even it works, it must be saved when tests are completed.

pg.test_abort_readers_of_insertion = function(cg)
    t.tarantool.skip_if_not_debug()
    require('log').error('XXXXX 1') -- I don't see this message anywhere
    cg.server:exec(function(idx)
        require('log').info('XXXXX 2') -- I see this only while the test runs, the log file disappears then.
        require('fiber').sleep(10)

Sometimes logs are the only thing that helps to understand what's going on. So we should always write them and don't clean them after the test is finished. Perhaps we should clean the log right before the test is run.

[ochaplashkin]

Description of current behavior (with more details)

[!NOTE]
Luatest version: 0.5.7-44-g2d51155

Test source code:

g.test_foo = function()
    log.error('[ERROR] log')
    log.warn('[WARNING] log')
    log.info('[INFO] log')
    log.verbose('[VERBOSE] log')
    log.debug('[DEBUG] log')
    g.server:exec(function()
        log.error('[ERROR] server log')
        log.warn('[WARNING] server log')
        log.info('[INFO] server log')
        log.verbose('[VERBOSE] server log')
        log.debug('[DEBUG] server log')
    end)
end

Let's launch this test in different ways.

luatest: run the test that will be passed

$ ./bin/luatest -c -v ./test/log_test.lua 
Tarantool version is 2.11.1-0-g96877bd35
Started on Thu Aug 31 14:14:00 2023
    log.test_foo ... 
[ERROR] log
[WARNING] log
[INFO] log
    log.test_foo ... (0.002s) Ok
=========================================================
Ran 1 tests in 0.002 seconds, 1 succeeded, 0 failed

[!IMPORTANT]

1. We got the log from the test at 3 levels in stdout;
2. We don't see server logs anywhere (g.server).

luatest: run the test that will be failed

We just added t.assert(false) at the end of test:

test source code

```js g.test_foo = function() log.error('[ERROR] log') log.warn('[WARNING] log') log.info('[INFO] log') log.verbose('[VERBOSE] log') log.debug('[DEBUG] log') g.server:exec(function() log.error('[ERROR] server log') log.warn('[WARNING] server log') log.info('[INFO] server log') log.verbose('[VERBOSE] server log') log.debug('[DEBUG] server log') end) t.assert(false) <-- new line end ```

$ ./bin/luatest -c -v ./test/log_test.lua 
Tarantool version is 2.11.1-0-g96877bd35
Started on Thu Aug 31 14:32:13 2023
    log.test_log ... 
[ERROR] log
[WARNING] log
[INFO] log
    log.test_log ... (0.010s) fail
///test/log_test.lua:23: expected: a value evaluating to true, actual: false
=========================================================

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

1) log.test_log
///test/log_test.lua:23: expected: a value evaluating to true, actual: false
stack traceback:
    ...
    [C]: in function 'xpcall'
artifacts:
    server -> /tmp/t/artifacts/server-Ti0bhD2XgTQT
Ran 1 tests in 0.010 seconds, 0 succeeded, 1 failed

=========================================================
Failed tests:

log.test_log

Now we have artifacts of the server, we can look at the specified directory:

$ tree -L 1 /tmp/t/artifacts/server-Ti0bhD2XgTQT
/tmp/t/artifacts/server-Ti0bhD2XgTQT
├── 00000000000000000000.snap
├── 00000000000000000000.xlog
└── server.log
$
$
$ cat /tmp/t/artifacts/server-Ti0bhD2XgTQT/server.log
main I> entering the event loop
main/109/main/home.pc.workspace.vk.luatest...test.log_test log_test.lua:16 E> [ERROR] server log
main/109/main/...test.log_test log_test.lua:17 W> [WARNING] server log
...test.log_test I> [INFO] server log

[!IMPORTANT]

1. We also got the log from the test at 3 levels in stdout;
2. We can look at the server logs.

test-run: run the test that will be passed

$ ./test-run.py engine-luatest/log_test.lua
Started ./test-run.py engine-luatest/log_test.lua
Running in parallel with 12 workers
...
WORKR TEST                                            PARAMS          RESULT
---------------------------------------------------------------------------------
[001] engine-luatest/log_test.lua                                     [ pass ]
...
Statistics:
* pass: 1

[!IMPORTANT] We don't see any logs and there are no server artifacts (because the test is marked successful).

test-run: run the test that will be failed

...
WORKR TEST                                            PARAMS          RESULT
---------------------------------------------------------------------------------
[001] engine-luatest/log_test.lua                                     [ fail ]
[001] Test failed! Output from reject file /tmp/t/rejects/engine-luatest/log.reject:
[001] Tarantool version is 3.0.0-alpha1-176-ga5d7f3429
[001] TAP version 13
[001] 1..1
[001] # Started on Thu Aug 31 14:48:30 2023
[001] # Starting group: engine-luatest.log
[001] not ok 1  engine-luatest.log.test_haha
[001] #   ...tarantool/test/engine-luatest/log_test.lua:23: expected: a value evaluating to true, actual: false
[001] #   stack traceback:
[001] #     ...tarantool/test/engine-luatest/log_test.lua:23: in function 'engine-luatest.log.test_haha'
[001] #     ...
[001] #     [C]: in function 'xpcall'
[001] #   artifacts:
[001] #   server -> /tmp/t/001_engine-luatest/artifacts/server-YNv6RdoVwOFT
[001] # Ran 1 tests in 0.010 seconds, 0 succeeded, 1 failed
[001] 
[001] [test-run server "luatest_server"] Last 15 lines of the log file /tmp/t/001_engine-luatest/log_test.log:
[001] [ERROR] log
[001] [WARNING] log
[001] [INFO] log

Server artifacts:

$ cat /tmp/t/001_engine-luatest/artifacts/server-YNv6RdoVwOFT/server.log
...
main I> entering the event loop
main/109/main/test.engine-luatest.log_test log_test.lua:16 E> [ERROR] server log
main/109/main/test.engine-luatest.log_test log_test.lua:17 W> [WARNING] server log
main/109/main/test.engine-luatest.log_test I> [INFO] server log

Test logs:

$ cat /tmp/t/001_engine-luatest/log_test.log
[ERROR] log
[WARNING] log
[INFO] log

[!IMPORTANT] We can see all the logs (test and server).

[ochaplashkin]

@ylobankov suggested adding a parameter for luatest --debug (-d). This is to set log_level = 7 for the luatest runner.

Example:

$ ./bin/luatest -c -v ./test/log_test.lua
Tarantool version is 2.11.1-0-g96877bd35
Started on Wed Sep  6 18:23:32 2023
    log.test_log ... 
[ERROR] log
[WARNING] log
[INFO] log
    log.test_log ... (0.003s) Ok
=========================================================
Ran 1 tests in 0.004 seconds, 1 succeeded, 0 failed

Is there too little information about the test? Just add the --debug flag:

$ ./bin/luatest -c -v --debug ./test/log_test.lua
pc@workstation:~/workspace/vk/luatest$ ./bin/luatest -c -v --debug ./test/log_test.lua
Tarantool version is 2.11.1-0-g96877bd35
2023-09-06 18:23:17.556 [222330] main/103/luatest D> log.cfg({log=nil, level=7, nonblock=nil, format=plain})
2023-09-06 18:23:17.556 [222330] main/103/luatest I> Tarantool 2.11.1-0-g96877bd35 Linux-x86_64-RelWithDebInfo
2023-09-06 18:23:17.556 [222330] main/103/luatest I> log level 7
2023-09-06 18:23:17.556 [222330] main/103/luatest D> cbus_endpoint_create: locking &cbus.mutex
...
Started on Wed Sep  6 18:23:17 2023
    log.test_log ... 
2023-09-06 18:23:17.686 [222330] main/103/luatest/..test.log_test log_test.lua:14 E> [ERROR] log
2023-09-06 18:23:17.686 [222330] main/103/luatest/..test.log_test log_test.lua:15 W> [WARNING] log
2023-09-06 18:23:17.686 [222330] main/103/luatest/..test.log_test I> [INFO] log
2023-09-06 18:23:17.686 [222330] main/103/luatest/..test.log_test V> [VERBOSE] log
2023-09-06 18:23:17.686 [222330] main/103/luatest/..test.log_test D> [DEBUG] log
    log.test_log ... (0.004s) Ok
=========================================================
Ran 1 tests in 0.004 seconds, 1 succeeded, 0 failed
2023-09-06 18:23:17.698 [222330] main D> cpipe_flush_cb: locking &endpoint->mutex
...

@alyapunov what do you think about this param?

IMHO: I like working with logs because one of the tasks of the luatest is to transparently show the state of testing (and internal logic). Now it's all hidden and not visible.

I would like to see something like this:

$ ./bin/luatest --log-level VERBOSE ...
or
$ ./bin/luatest --log-level 6 ...

[locker]

I don't need the log levels and I don't see how they would help me. What I'd like to have to debug test is a single log file that would contain messages from all test servers and the main test process. It'd be nice if t.assert helpers logged into this file as well.

To illustrate what I mean, suppose we have the following test case:

g.test_foo = function(cg)
    t.log('message 1')
    cg.server1:exec(function()
        t.log('message 2')
        t.assert_equals(box.info.status, 'running')
    end)
    t.log('message 3')
    cg.server2:exec(function()
        t.log('message 4')
        t.assert_equals(box.info.status, 'running')
    end)
end

Then I imagine the log would contain something like this upon running the test case:

# time                  file:line      origin   message
2023-09-06 19:04:34.742 my_test.lua:30 luatest: begin g.test_foo
2023-09-06 19:04:34.742 my_test.lua:31 luatest: message 1
2023-09-06 19:04:34.743 my_test.lua:33 server1: message 2
2023-09-06 19:04:34.743 my_test.lua:34 server1: assert_equals(box.info.status, 'running')
2023-09-06 19:04:34.744 my_test.lua:36 luatest: message 3
2023-09-06 19:04:34.744 my_test.lua:38 server2: message 4
2023-09-06 19:04:34.745 my_test.lua:39 server2: assert_equals(box.info.status, 'running')
2023-09-06 19:04:34.746 my_test.lua:41 luatest: done g.test_foo

Note this log file has nothing to do with Tarantool log.

[alyapunov]

A couple of thoughts in addition.

1. Actually log_level = 7 is used very seldom just because it generates tons of useless information about, for example, addressed of created tuples etc.
2. It seems that in case of problems we could set log level right in the test (box.cfg{log_level=6}).
3. The most interesting part is usually happens inside of serverX:exec call.

This issue is about improving of convenience of writing new tests. We can make mistakes in test and want to find out them, and tarantool itself can do unexpected thing and we want to figure out when and what. I think that t.log would be useful and deserves its own issue. But I think that the original issue about saving logs in case of failure including cases of crash or unexpected exit is still actual.

[locker]

Maybe write logs from all instances including the test process to a single file using the Tarantool syslog logger and always save this file? It'd be easier to analyze if one could see the linear history of events from all servers and the test. And if log from a single instance was required, one could easily filter it out by prefix.

[ochaplashkin]

We see three related tasks:

1. developer does not see XXXX 1 and XXXX 2 logs from the test (see issue description, it will be as fix of test-run not luatest);
2. the concept of a single logfile (from @locker) + t.log() + luatest should log high-level actions (start/end group, before_all/after_all, assert(...), etc);
3. --debug (or any other name) parameter of luatest: log low-level actions (create server, wait for condition, etc).

@alyapunov, @locker I suggest solving the first problem and creating separate tasks for the rest.

[ylobankov]

Finally, it should be fixed by https://github.com/tarantool/luatest/pull/345.