Rework server log handling

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
 

CMakeLists.txt

@@ -1,4 +1,4 @@
-cmake_minimum_required(VERSION 2.8 FATAL_ERROR)
+cmake_minimum_required(VERSION 3.5 FATAL_ERROR)
 
 project(luatest NONE)
 

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/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/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,46 +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'}, 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)

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)