Rework server log handling

Instead of configuring Tarantool test servers to write logs both to
stdout and a file using the tee command, let's write all logs to stderr
only and make the output beautifier work as tee. This fixes two issues
at once:
 - Using `grep_log()` for a server started using the `cluster` helper.
 - Using `grep_log()` for a stopped server.

Note that after this change we don't store all stderr output in
the output beautifier anymore. It was used for detecting crashes
at exit. Now, we use `grep_log()` to search for segmeration faults
and memory leaks.

Closes #389
Closes #397

Author: locker

CHANGELOG.md

@@ -24,6 +24,9 @@
   (gh-396).
 - Remove pretty-printing of `luatest.log` arguments.
 - Add `cluster` helper as a tool for managing a Tarantool cluster (gh-368).
+- Fix `Server:grep_log()` to work with a server instance started using
+  the `cluster` helper (gh-389).
+- Fix `Server:grep_log()` to work with a stopped server instance (gh-397).
 
 ## 1.0.1
 

luatest/output_beautifier.lua

@@ -1,5 +1,6 @@
 local checks = require('checks')
 local fiber = require('fiber')
+local fio = require('fio')
 local fun = require('fun')
 
 local Class = require('luatest.class')
@@ -57,11 +58,13 @@ end
 --- Build OutputBeautifier object.
 -- @param object
 -- @string object.prefix String to prefix each output line with.
+-- @string[opt] object.file Path to the file to append all output too.
 -- @string[opt] object.color Color name for prefix.
 -- @string[opt] object.color_code Color code for prefix.
 -- @return input object.
 function OutputBeautifier:new(object)
-    checks('table', {prefix = 'string', color = '?string', color_code = '?string'})
+    checks('table', {prefix = 'string', file = '?string',
+                     color = '?string', color_code = '?string'})
     return self:from(object)
 end
 
@@ -70,7 +73,6 @@ function OutputBeautifier.mt:initialize()
         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.stderr = ''
 end
 
 -- Replace standard output descriptors with pipes.
@@ -87,7 +89,7 @@ function OutputBeautifier.mt:enable(options)
     end
     self.fibers = {}
     for i, pipe in pairs(self.pipes) do
-        self.fibers[i] = fiber.new(self.run, self, pipe[0], i)
+        self.fibers[i] = fiber.new(self.run, self, pipe[0])
     end
     self.fibers.pid_tracker = options and options.track_pid and fiber.new(function()
         Process = Process or require('luatest.process')
@@ -99,6 +101,10 @@ function OutputBeautifier.mt:enable(options)
             fiber.sleep(self.class.PID_TRACKER_INTERVAL)
         end
     end)
+    if self.file then
+        self.fh = fio.open(self.file, {'O_CREAT', 'O_WRONLY', 'O_APPEND'},
+                           tonumber('640', 8))
+    end
 end
 
 -- Stop fibers.
@@ -111,6 +117,10 @@ function OutputBeautifier.mt:disable()
         end
     end
     self.fibers = nil
+    if self.fh then
+        self.fh:close()
+    end
+    self.fh = nil
 end
 
 -- Process all available data from fd using synchronization with monitor.
@@ -139,22 +149,21 @@ 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)
+function OutputBeautifier.mt:run(fd)
     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)
-            if pipe == 'stderr' then
-                self.stderr = self.stderr .. raw_lines
-            end
-            local lines = raw_lines:split('\n')
+            local lines = table.concat(chunks):split('\n')
             if lines[#lines] == '' then
                 table.remove(lines)
             end
             for _, line in pairs(lines) do
+                if self.fh ~= nil then
+                    self.fh:write(table.concat({prefix, line, '\n'}))
+                end
                 if log_file ~= nil then
                     -- Redirect all output to the log file if unified logging
                     -- is enabled.

luatest/process.lua

@@ -36,16 +36,21 @@ function Process:start(path, args, env, options)
         chdir = '?string',
         ignore_gc = '?boolean',
         output_prefix = '?string',
+        output_file = '?string',
     })
     args = args and table.copy(args) or {}
     env = env or {}
     options = options or {}
 
     table.insert(args, 1, path)
 
-    local output_beautifier = options.output_prefix and OutputBeautifier:new({
-        prefix = options.output_prefix,
-    })
+    local output_beautifier
+    if options.output_prefix or options.output_file then
+        output_beautifier = OutputBeautifier:new({
+            prefix = options.output_prefix,
+            file = options.output_file,
+        })
+    end
 
     local env_list = fun.iter(env):map(function(k, v) return k .. '=' .. v end):totable()
     local pid = ffi.C.fork()

luatest/server.lua

@@ -327,9 +327,7 @@ 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
+    self.log_file = fio.pathjoin(self.workdir, self.alias .. '.log')
 end
 
 -- Create a table with env variables based on the constructor params.
@@ -341,7 +339,6 @@ end
 --   * `TARANTOOL_ALIAS`
 --   * `TARANTOOL_HTTP_PORT`
 --   * `TARANTOOL_BOX_CFG`
---   * `TARANTOOL_UNIFIED_LOG_ENABLED`
 --
 -- @return table
 function Server:build_env()
@@ -354,9 +351,6 @@ 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
 
@@ -442,6 +436,7 @@ function Server:start(opts)
     self.process = Process:start(command, args, env, {
         chdir = self.chdir,
         output_prefix = self.alias,
+        output_file = self.log_file,
     })
 
     local wait_until_ready
@@ -573,14 +568,16 @@ function Server:stop()
         end
         local workdir = fio.basename(self.workdir)
         local pid = self.process.pid
-        local stderr = self.process.output_beautifier.stderr
-        if stderr:find('Segmentation fault') then
-            error(('Segmentation fault during process termination (alias: %s, workdir: %s, pid: %d)\n%s')
-                :format(self.alias, workdir, pid, stderr))
-        end
-        if stderr:find('LeakSanitizer') then
-            error(('Memory leak during process execution (alias: %s, workdir: %s, pid: %s)\n%s')
-                :format(self.alias, workdir, pid, stderr))
+        -- Check the log file for crash and memory leak reports.
+        if fio.path.exists(self.log_file) then
+            if self:grep_log('Segmentation fault$', math.huge) then
+                error(('Segmentation fault during process termination (alias: %s, workdir: %s, pid: %d)')
+                    :format(self.alias, workdir, pid))
+            end
+            if self:grep_log('LeakSanitizer: detected memory leaks$', math.huge) then
+                error(('Memory leak during process execution (alias: %s, workdir: %s, pid: %s)')
+                    :format(self.alias, workdir, pid))
+            end
         end
         log.info('Process of server %q (pid: %d) killed', self.alias, self.process.pid)
         self.process = nil
@@ -869,7 +866,6 @@ end
 --
 
 --- Search a string pattern in the server's log file.
--- If the server has crashed, `opts.filename` is required.
 --
 -- @string pattern String pattern to search in the server's log file.
 -- @number[opt] bytes_num Number of bytes to read from the server's log file.
@@ -878,21 +874,12 @@ end
 --   pattern is found, which means that the server was restarted.
 --   Defaults to `true`.
 -- @string[opt] opts.filename Path to the server's log file.
---   Defaults to `box.cfg.log`.
+--   Defaults to `<workdir>/<alias>.log`.
 -- @return string|nil
 function Server:grep_log(pattern, bytes_num, opts)
     local options = opts or {}
     local reset = options.reset or true
-
-    -- `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 filename = options.filename or self.log_file
     local file = fio.open(filename, {'O_RDONLY', 'O_NONBLOCK'})
 
     log.info('Trying to grep %q in server\'s log file %s', pattern, filename)

luatest/server_instance.lua

@@ -1,55 +1,12 @@
-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 = log_cfg()
     }
 end
 

test/server_instance.lua

@@ -5,11 +5,10 @@ local json = require('json')
 local workdir = os.getenv('TARANTOOL_WORKDIR')
 local listen = os.getenv('TARANTOOL_LISTEN')
 local http_port = os.getenv('TARANTOOL_HTTP_PORT')
-local log = os.getenv('TARANTOOL_LOG')
 
 local httpd = require('http.server').new('0.0.0.0', http_port)
 
-box.cfg({work_dir = workdir, log = log})
+box.cfg({work_dir = workdir})
 box.schema.user.grant('guest', 'super', nil, nil, {if_not_exists = true})
 box.cfg({listen = listen})
 

test/server_test.lua

@@ -22,7 +22,6 @@ local server = Server:new({
         LUA_PATH = root .. '/?.lua;' ..
             root .. '/?/init.lua;' ..
             root .. '/.rocks/share/tarantool/?.lua',
-        TARANTOOL_LOG = fio.pathjoin(datadir, 'server_test.log'),
         custom_env = 'test_value',
     },
     http_port = 8182,