Add logging to unified file

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 at all.

> 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

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.

Closes #324

Author: Oleg Chaplashkin

CHANGELOG.md

@@ -1,5 +1,9 @@
 # Changelog
 
+## Unreleased
+
+- Add logging to unified file (gh-324).
+
 ## 1.0.1
 
 - Fixed incorrect Unix domain socket path length check (gh-341).

luatest/output_beautifier.lua

@@ -59,29 +59,41 @@ end
 -- @string object.prefix String to prefix each output line with.
 -- @string[opt] object.color Color name for prefix.
 -- @string[opt] object.color_code Color code for prefix.
+-- @boolean[opt] object.runner Mark OutputBeautifier object is created for runner process.
 -- @return input object.
 function OutputBeautifier:new(object)
-    checks('table', {prefix = 'string', color = '?string', color_code = '?string'})
+    checks('table', {prefix = 'string', color = '?string', color_code = '?string', runner = '?boolean'})
     return self:from(object)
 end
 
 function OutputBeautifier.mt:initialize()
     self.color_code = self.color_code or
         self.class.COLOR_BY_NAME[self.color] or
         OutputBeautifier:next_color_code()
-    self.pipes = {stdout = ffi_io.create_pipe(), stderr = ffi_io.create_pipe()}
+    self.pipes = {stderr = ffi_io.create_pipe()}
+    if not self.runner then
+        self.pipes.stdout = ffi_io.create_pipe()
+    end
     self.stderr = ''
+    self.enable_capture = nil
 end
 
 -- Replace standard output descriptors with pipes.
+-- Stdout descriptor of the runner process will not be replaced
+-- because it is used for displaying all captured data from other processes.
 function OutputBeautifier.mt:hijack_output()
-    ffi_io.dup2_io(self.pipes.stdout[1], io.stdout)
+    if not self.runner then
+        ffi_io.dup2_io(self.pipes.stdout[1], io.stdout)
+    end
     ffi_io.dup2_io(self.pipes.stderr[1], io.stderr)
 end
 
 -- Start fibers that reads from pipes and prints formatted output.
 -- Pass `track_pid` option to automatically stop forwarder once process is finished.
 function OutputBeautifier.mt:enable(options)
+    if options and options.enable_capture ~= nil then
+        self.enable_capture = options.enable_capture == false
+    end
     if self.fibers then
         return
     end
@@ -140,8 +152,10 @@ end
 -- Every line with log level mark (` X> `) changes the color for all the following
 -- lines until the next one with the mark.
 function OutputBeautifier.mt:run(fd, pipe)
-    local prefix = self.color_code .. self.prefix .. ' | '
+    local prefix = self.prefix .. ' | '
+    local colored_prefix = self.color_code .. prefix
     local line_color_code = self.class.RESET_TERM
+    local log_file = rawget(_G, 'log_file')
     while fiber.testcancel() or true do
         self:process_fd_output(fd, function(chunks)
             local raw_lines = table.concat(chunks)
@@ -154,7 +168,16 @@ function OutputBeautifier.mt:run(fd, pipe)
             end
             for _, line in pairs(lines) do
                 line_color_code = self:color_for_line(line) or line_color_code
-                io.stdout:write(table.concat({prefix, line_color_code, line, self.class.RESET_TERM, '\n'}))
+                if not self.runner or self.enable_capture then
+                    io.stdout:write(
+                        table.concat(
+                            {colored_prefix, line_color_code, line, self.class.RESET_TERM,'\n'}
+                        )
+                    )
+                end
+                if log_file ~= nil then
+                    log_file.fh:write(table.concat({prefix, line, '\n'}))
+                end
                 fiber.yield()
             end
         end)

luatest/runner.lua

@@ -4,6 +4,7 @@
 
 local clock = require('clock')
 local fio = require('fio')
+local log = require('log')
 
 local assertions = require('luatest.assertions')
 local capturing = require('luatest.capturing')
@@ -16,6 +17,7 @@ local Server = require('luatest.server')
 local sorted_pairs = require('luatest.sorted_pairs')
 local TestInstance = require('luatest.test_instance')
 local utils = require('luatest.utils')
+local OutputBeautifier = require('luatest.output_beautifier')
 
 local ROCK_VERSION = require('luatest.VERSION')
 
@@ -56,6 +58,50 @@ function Runner.run(args, options)
         end
         options = utils.merge(options.luatest.configure(), Runner.parse_cmd_line(args), options)
 
+        local log_prefix = options.log_prefix or 'luatest'
+        local log_cfg = string.format("%s.log", log_prefix)
+
+        if options.log_file then
+            -- Save the file descriptor as a global variable to use it
+            -- in the `output_beautifier` module: this module is connected to the
+            -- the `server` module. We cannot link the `server` module to the `runner`
+            -- module to explicitly give this parameter.
+            local fh = fio.open(options.log_file, {'O_CREAT', 'O_WRONLY'}, tonumber('640', 8))
+            rawset(_G, 'log_file', {fh = fh})
+
+            local output_beautifier = OutputBeautifier:new({prefix = log_prefix, runner = true})
+            output_beautifier:enable({enable_capture = options.enable_capture})
+            output_beautifier:hijack_output()
+
+            -- `tee` copy logs to file and also to standard output, but we need
+            -- process all captured data through the OutputBeatifier object.
+            -- Data will be redirected back to stderr of the current process.
+            -- `/dev/fd/2` is a symlink to `/proc/self/fd`, where `/proc/self` is
+            -- a symlink to `/proc/<PID>`. So `/dev/fd/2` is equal to `/proc/<PID>/fd/2`
+            -- and it means "stderr of the current process".
+            log_cfg = string.format("| tee %s > /dev/fd/2", log_cfg)
+        end
+        -- Logging cannot be initialized without configuring the `box` engine
+        -- on a version less than 2.5.1 (see more details at [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
+        --
+        -- [1]: https://github.com/tarantool/tarantool/issues/689
+        if utils.version_current_ge_than(2, 5, 1) then
+            -- Initialize logging for luatest runner.
+            -- The log format will be as follows:
+            --     YYYY-MM-DD HH:MM:SS.ZZZ [ID] main/.../luatest I> ...
+            log.cfg{
+                log = log_cfg,
+                level = options.log_level or 5,
+            }
+        end
+
         if options.help then
             print(Runner.USAGE)
             return 0
@@ -85,12 +131,17 @@ Positional arguments:
 Options:
   -h, --help:             Print this help
   --version:              Print version information
-  -v, --verbose:          Increase verbosity
+  -v, --verbose:          Increase output verbosity for luatest runnner
+  -vv,                    Increase log verbosity to VERBOSE level for luatest runnner
+  -vvv,                   Increase log verbosity to DEBUG level for luatest runnner
   -q, --quiet:            Set verbosity to minimum
   -c                      Disable capture
   -b                      Print full backtrace (don't remove luatest frames)
   -e, --error:            Stop on first error
   -f, --failure:          Stop on first failure or error
+  -l, --log PATH:         Path to the unified log file
+  --runner-log-prefix NAME:
+                          Log prefix for luatest runner, 'luatest' by default
   --shuffle VALUE:        Set execution order:
                             - group[:seed] - shuffle tests within group
                             - all[:seed] - shuffle all tests
@@ -135,6 +186,12 @@ function Runner.parse_cmd_line(args)
             result.version = true
         elseif arg == '--verbose' or arg == '-v' then
             result.verbosity = GenericOutput.VERBOSITY.VERBOSE
+        elseif arg == '-vv' then
+            result.verbosity = GenericOutput.VERBOSITY.VERBOSE
+            result.log_level = 6 -- verbose
+        elseif arg == '-vvv' then
+            result.verbosity = GenericOutput.VERBOSITY.VERBOSE
+            result.log_level = 7 -- debug
         elseif arg == '--quiet' or arg == '-q' then
             result.verbosity = GenericOutput.VERBOSITY.QUIET
         elseif arg == '--fail-fast' or arg == '-f' then
@@ -145,6 +202,10 @@ function Runner.parse_cmd_line(args)
             if seed then
                 result.seed = tonumber(seed) or error('Invalid seed value')
             end
+        elseif arg == '-l' or arg == '--log' then
+            result.log_file = tostring(next_arg()) or error('Invalid log file path')
+        elseif arg == '--runner-log-prefix' then
+            result.log_prefix = tostring(next_arg())
         elseif arg == '--seed' then
             result.seed = tonumber(next_arg()) or error('Invalid seed value')
         elseif arg == '--output' or arg == '-o' then

luatest/server.lua

@@ -212,6 +212,10 @@ function Server:initialize()
 
     local prefix = fio.pathjoin(Server.vardir, 'artifacts', self.rs_id or '')
     self.artifacts = fio.pathjoin(prefix, self.id)
+
+    if rawget(_G, 'log_file') ~= nil then
+        self.unified_log_enabled = true
+    end
 end
 
 -- Create a table with env variables based on the constructor params.
@@ -223,6 +227,7 @@ end
 --   * `TARANTOOL_ALIAS`
 --   * `TARANTOOL_HTTP_PORT`
 --   * `TARANTOOL_BOX_CFG`
+--   * `TARANTOOL_UNIFIED_LOG_ENABLED`
 --
 -- @return table
 function Server:build_env()
@@ -235,6 +240,9 @@ function Server:build_env()
     if self.box_cfg ~= nil then
         res.TARANTOOL_BOX_CFG = json.encode(self.box_cfg)
     end
+    if self.unified_log_enabled then
+        res.TARANTOOL_UNIFIED_LOG_ENABLED = tostring(self.unified_log_enabled)
+    end
     return res
 end
 
@@ -743,7 +751,16 @@ end
 function Server:grep_log(pattern, bytes_num, opts)
     local options = opts or {}
     local reset = options.reset or true
-    local filename = options.filename or self:exec(function() return box.cfg.log end)
+
+    -- `box.cfg.log` can contain not only the path to the log file.
+    -- When unified logging mode is on, `box.cfg.log` is as follows:
+    --
+    --     | tee ${TARANTOOL_WORKDIR}/${TARANTOOL_ALIAS}.log
+    --
+    -- Therefore, we set `_G.box_cfg_log_file` in server_instance.lua which
+    -- contains the log file path: ${TARANTOOL_WORKDIR}/${TARANTOOL_ALIAS}.log.
+    local filename = options.filename or self:exec(function()
+        return rawget(_G, 'box_cfg_log_file') or box.cfg.log end)
     local file = fio.open(filename, {'O_RDONLY', 'O_NONBLOCK'})
 
     local function fail(msg)

luatest/server_instance.lua

@@ -1,17 +1,55 @@
 local fio = require('fio')
 local fun = require('fun')
 local json = require('json')
+local log = require('log')
 
 local TIMEOUT_INFINITY = 500 * 365 * 86400
 
+local function log_cfg()
+    -- `log.cfg{}` is available since 2.5.1 version only. See more
+    -- details at https://github.com/tarantool/tarantool/issues/689.
+    if log.cfg ~= nil then
+        -- Logging may be initialized before `box.cfg{}` call:
+        --
+        --     server:new({
+        --         env = {['TARANTOOL_RUN_BEFORE_BOX_CFG'] = [[
+        --             require('log').cfg{ log = <custom_log_file> }
+        --         ]]})
+        --
+        -- This causes the `Can't set option 'log' dynamically` error,
+        -- so we need to return the old log file path.
+        if log.cfg.log ~= nil then
+            return log.cfg.log
+        end
+    end
+    local log_file = fio.pathjoin(
+        os.getenv('TARANTOOL_WORKDIR'),
+        os.getenv('TARANTOOL_ALIAS') .. '.log'
+    )
+    -- When `box.cfg.log` is called, we may get a string like
+    --
+    --     | tee ${TARANTOOL_WORKDIR}/${TARANTOOL_ALIAS}.log
+    --
+    -- Some tests or functions (e.g. Server:grep_log) may request the
+    -- log file path, so we save it to a global variable. Thus it can
+    -- be obtained by `rawget(_G, 'box_cfg_log_file')`.
+    rawset(_G, 'box_cfg_log_file', log_file)
+
+    local unified_log_enabled = os.getenv('TARANTOOL_UNIFIED_LOG_ENABLED')
+    if unified_log_enabled then
+        -- Redirect the data stream to two sources at once:
+        -- to the standard stream (stdout) and to the file
+        -- ${TARANTOOL_WORKDIR}/${TARANTOOL_ALIAS}.log.
+        return string.format('| tee %s', log_file)
+    end
+    return log_file
+end
+
 local function default_cfg()
     return {
         work_dir = os.getenv('TARANTOOL_WORKDIR'),
         listen = os.getenv('TARANTOOL_LISTEN'),
-        log = fio.pathjoin(
-            os.getenv('TARANTOOL_WORKDIR'),
-            os.getenv('TARANTOOL_ALIAS') .. '.log'
-        ),
+        log = log_cfg()
     }
 end