Show log of tests #308

alyapunov · 2023-05-24T11:03:30Z

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 · 2023-08-30T12:59:50Z

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

We got the log from the test at 3 levels in stdout;
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

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

We also got the log from the test at 3 levels in stdout;
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 · 2023-09-06T14:29:13Z

@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 · 2023-09-06T16:08:08Z

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 · 2023-09-07T03:58:21Z

A couple of thoughts in addition.

Actually log_level = 7 is used very seldom just because it generates tons of useless information about, for example, addressed of created tuples etc.
It seems that in case of problems we could set log level right in the test (box.cfg{log_level=6}).
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 · 2023-09-07T12:44:49Z

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 · 2023-09-07T13:20:16Z

We see three related tasks:

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);
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);
--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.

Now luatest will always clear the server vardir (`/tmp/t` by default) before running tests. You should be specify a new `--not-clean` parameter to disable this deletion. Also luatest does not delete the server workdir in the Server:drop(). Part of tarantool#308

Now luatest will always clear the server vardir (`/tmp/t` by default) before running tests. You should be specify a new `--no-clean` parameter to disable this deletion. Also luatest does not delete the server workdir in the Server:drop(). Part of tarantool#308

Now, luatest does not delete the server's working directory in the drop() function. Instead of this, it deletes the whole var dir (default: /tmp/t) before running tests. So all server artifacts from all tests are saved after the run and can be analyzed. However, you can disable this deletion by specifying the new `--no-clean` option. Part of tarantool#308

Now, luatest does not delete the server's working directory in the drop() function. Instead of this, it deletes the whole var dir (default: /tmp/t) before running tests. So all server artifacts from all tests are saved after the run and can be analyzed. However, you can disable this deletion by specifying the new `--no-clean` option. Part of #308

The `--no-clean` option was added after the luatest update [1]. Test-run uses luatest but independently performs the preparation (creation and cleaning of directories). Therefore this option was added to avoid incompatibility between the two tools. [1] tarantool/luatest@18859f6 Part of tarantool/luatest#308

By default, test-run captures the stderr stream and redirects its to the log file: $ cat /tmp/t/001_foo-luatest/foo_test.log: [001] Some error log [001] My warning log ... Use the new option `--show-capture` (abbr. `-c`) to redirect stderr to stdout. Use it instead of the deprecated `--verbose` option. The `--verbose` option will be ignored and output: Argument ['--verbose'] is deprecated and is ignored. Close tarantool/luatest#308

We synchronize the options of two tools: test-run and luatest. When luatest runs separate tarantool instance it duplicates the streams thereby we can see logs(warning, error, etc) and prints. We have added a context manager to create the same behavior with luatest. Close tarantool/luatest#308

ylobankov · 2024-04-15T20:20:53Z

Finally, it should be fixed by #345.

ylobankov assigned ochaplashkin Jun 29, 2023

ylobankov added the feature A new functionality label Jun 29, 2023

ochaplashkin mentioned this issue Sep 12, 2023

Not delete the server's working directory in Server:drop() #327

Merged

ochaplashkin mentioned this issue Sep 18, 2023

Redirect luatest stderr to stdout with new option tarantool/test-run#410

Draft

ylobankov closed this as completed Apr 15, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Show log of tests #308

Show log of tests #308

alyapunov commented May 24, 2023

ochaplashkin commented Aug 30, 2023 •

edited

Loading

ochaplashkin commented Sep 6, 2023 •

edited

Loading

locker commented Sep 6, 2023 •

edited

Loading

alyapunov commented Sep 7, 2023

locker commented Sep 7, 2023

ochaplashkin commented Sep 7, 2023 •

edited

Loading

ylobankov commented Apr 15, 2024

Show log of tests #308

Show log of tests #308

Comments

alyapunov commented May 24, 2023

ochaplashkin commented Aug 30, 2023 • edited Loading

Description of current behavior (with more details)

luatest: run the test that will be passed

luatest: run the test that will be failed

test-run: run the test that will be passed

test-run: run the test that will be failed

ochaplashkin commented Sep 6, 2023 • edited Loading

locker commented Sep 6, 2023 • edited Loading

alyapunov commented Sep 7, 2023

locker commented Sep 7, 2023

ochaplashkin commented Sep 7, 2023 • edited Loading

ylobankov commented Apr 15, 2024

ochaplashkin commented Aug 30, 2023 •

edited

Loading

luatest: run the test that will be `passed`

luatest: run the test that will be `failed`

test-run: run the test that will be `passed`

test-run: run the test that will be `failed`

ochaplashkin commented Sep 6, 2023 •

edited

Loading

locker commented Sep 6, 2023 •

edited

Loading

ochaplashkin commented Sep 7, 2023 •

edited

Loading