Add logging to unified file

[ochaplashkin]

❤️ We present a new functionality for logging ❤️

How it worked before

Having written a simple test with two servers (bob and frank) we would like to see the output of each of them and also what is going on in the test itself. For example:

g.test_with_bob_and_frank = function()
    g.bob:exec(function()
        require('log').info('Hi, Frank!')
    end)
    g.frank:exec(function()
        require('log').info('Hi, Bob!')
    end)
    require('log').info('Hi, Bob and Frank!')
end

In order to see their greetings, we had to look over each server log file:

$ cat /tmp/t/${BOB_VARDIR}/bob.log
...
2023-12-19 18:34:26.305 [84739] main/109/main I> Hi, Frank!

$ cat /tmp/t/${FRANK_VARDIR}/frank.log
...
2023-12-19 18:34:26.306 [84752] main/109/main I> Hi, Bob!

And there was no way to see the "Hi, Bob and Frank!" log message.

How it works now

Now, if we provide the -l, --log parameter with the file path, we will see the following contents in the specified log file:

$ ./bin/luatest -c -v -l run.log <test> && cat run.log
...
bob | 2023-12-19 18:39:40.858 [85021] main/109/main I> Hi, Frank!
frank | 2023-12-19 18:39:40.859 [85034] main/109/main I> Hi, Bob!
luatest | 2023-12-19 18:39:40.860 [85034] main/109/main I> Hi, Bob and Frank!

What's under the hood

Data flow diagram

The solution is based on the existing OutputBeautifier module logic: it can already read data from standard output streams (stdout/stderr) and print it to luatest stdout.

When we run luatest (this is Tarantool process), we read stderr stream and hijack it. All logs of this process will be written to stderr and intercepted by the OutputBeautifier fiber. The fiber processes them and writes to our specified file for all logs and then to the luatest stdout stream.

To save the log file for each server separately (this can be useful for research) we use the standard tee command.

In the case of the server, we configure logging as follows:

' | tee ${TARANTOOL_WORKDIR}/${TARANTOOL_ALIAS}.log'

While the server is running, all logs will be redirected to the tee command. So it will be written to the server log file and stdout stream. Then all data from stdout will be intercepted by the OutputBeautifier fiber that will write it to the specified log file.

What's new in administration

New options:

-l, --log PATH - set the path to the unified log file.
--runner-log-prefix NAME - set the log prefix for luatest runner,
'luatest' by default.

Improved options:

-v - increase output verbosity (as it was before) and set INFO log
level for luatest runner.
-vv - increase log verbosity to VERBOSE level for luatest runnner.
-vvv - increase log verbosity to DEBUG level for luatest runnner.

A few words about backward compatibility (< 2.5.1)

Logging cannot be initialized without configuring the box engine on a version less than 2.5.1. Otherwise, this causes the attempt to call field 'cfg' (a nil value) error, so there are the following limitations:

1. There is no luatest.log file (but logs are still available in stdout and in the run.log file);
2. All logs from luatest are non-formatted and look like:

luatest | My log message

Closes #324

[ochaplashkin]

I tested this patch and saw that one test needed to be changed:

diff --git a/test/box-luatest/gh_7904_export_box_schema_version_to_public_api_test.lua b/test/box-luatest/gh_7904_export_box_schema_version_to_public_api_test.lua
index 18af7968f..9953e2b28 100644
--- a/test/box-luatest/gh_7904_export_box_schema_version_to_public_api_test.lua
+++ b/test/box-luatest/gh_7904_export_box_schema_version_to_public_api_test.lua
@@ -23,7 +23,7 @@ g.test_box_internal_schema_version_deprecation = function(cg)
     local deprecation_warning =
         'box.internal.schema_version will be removed, please use box.info.schema_version instead'
     t.assert_is_not(cg.server:grep_log(deprecation_warning, 256), nil)
-    local log_file = g.server:exec(function() return box.cfg.log end)
+    local log_file = g.server:exec(function() return rawget(_G, 'box_cfg_log_file') or box.cfg.log end)
     fio.truncate(log_file)
     cg.server:exec(function()
         box.internal.schema_version()

[ylobankov]

LGTM