Print luatest logs to stdout when unified log is disabled

If unified logging is enabled, logs written by the runner are written
both to its own log file and to the unified log file. This is consistent
with how logs written by test processes are handled. However, if unified
logging is disabled, then runner logs are written only to its log file
while test process logs are also written to stdout and captured if
capturing is enabled. Let's write runner logs to stdout in this case as
well because they can be useful for debugging.

While we are at it, let's get rid of using `tee` for logging: we can
redirect all logs to the output beautifier directly and instruct the
latter to write them to a file.

No changelog because the feature was added by commit f8a1c10
("Add logging to unified file"), which hasn't been released yet.

Author: locker

luatest/log.lua

@@ -1,10 +1,69 @@
+local checks = require('checks')
+local fio = require('fio')
 local tarantool_log = require('log')
 
+local OutputBeautifier = require('luatest.output_beautifier')
 local utils = require('luatest.utils')
 
 -- Utils for logging
 local log = {}
 local default_level = 'info'
+local is_initialized = false
+
+function log.initialize(options)
+    checks({
+        vardir = 'string',
+        log_file = '?string',
+        log_prefix = '?string',
+    })
+    if is_initialized then
+        return
+    end
+
+    local vardir = options.vardir
+    local luatest_log_prefix = options.log_prefix or 'luatest'
+    local luatest_log_file = fio.pathjoin(vardir, luatest_log_prefix .. '.log')
+    local unified_log_file = options.log_file
+
+    fio.mktree(vardir)
+
+    if unified_log_file then
+        -- Save the file descriptor as a global variable to use it in
+        -- the `output_beautifier` module.
+        local fh = fio.open(unified_log_file, {'O_CREAT', 'O_WRONLY', 'O_TRUNC'},
+                            tonumber('640', 8))
+        rawset(_G, 'log_file', {fh = fh})
+    end
+
+    local output_beautifier = OutputBeautifier:new({
+        file = luatest_log_file,
+        prefix = luatest_log_prefix,
+    })
+    output_beautifier:enable()
+
+    -- Redirect all logs to the pipe created by OutputBeautifier.
+    local log_cfg = string.format('/dev/fd/%d', output_beautifier.pipes.stdout[1])
+
+    -- 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> ...
+        require('log').cfg{log = log_cfg}
+    end
+
+    is_initialized = true
+end
 
 local function _log(level, msg, ...)
     if utils.version_current_ge_than(2, 5, 1) then

luatest/runner.lua

@@ -17,7 +17,6 @@ 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')
 
@@ -58,47 +57,11 @@ 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)
-
-        fio.mktree(Server.vardir)
-        log_cfg = fio.pathjoin(Server.vardir, log_cfg)
-
-        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', 'O_TRUNC'},
-                                tonumber('640', 8))
-            rawset(_G, 'log_file', {fh = fh})
-
-            local output_beautifier = OutputBeautifier:new({prefix = log_prefix})
-            output_beautifier:enable()
-
-            -- `tee` copy logs to file and also to standard output, but we need
-            -- process all captured data through the OutputBeatifier object.
-            -- So we redirect stdout to the pipe created by OutputBeautifier.
-            log_cfg = string.format("| tee %s > /dev/fd/%d",
-                                    log_cfg, output_beautifier.pipes.stdout[1])
-        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> ...
-            require('log').cfg{log = log_cfg}
-        end
+        log.initialize({
+            vardir = Server.vardir,
+            log_file = options.log_file,
+            log_prefix = options.log_prefix,
+        })
 
         if options.help then
             print(Runner.USAGE)

test/capture_test.lua

@@ -5,6 +5,9 @@ local g = t.group()
 local Capture = require('luatest.capture')
 local capture = Capture:new()
 
+-- Disable luatest logging to avoid capturing it.
+require('log').cfg{level = 'error'}
+
 g.setup = function() capture:enable() end
 g.teardown = function()
     capture:flush()

test/capturing_test.lua

@@ -5,6 +5,9 @@ local helper = require('test.helpers.general')
 local Capture = require('luatest.capture')
 local capture = Capture:new()
 
+-- Disable luatest logging to avoid capturing it.
+require('log').cfg{level = 'error'}
+
 g.setup = function() capture:enable() end
 g.teardown = function()
     capture:flush()