diff --git a/CHANGELOG.md b/CHANGELOG.md index ba0e75d..1518dd9 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/CMakeLists.txt b/CMakeLists.txt index 5173907..6728768 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/luatest/log.lua b/luatest/log.lua index c6741ac..115b09a 100644 --- a/luatest/log.lua +++ b/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 diff --git a/luatest/output_beautifier.lua b/luatest/output_beautifier.lua index 7a83891..9bd8523 100644 --- a/luatest/output_beautifier.lua +++ b/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. diff --git a/luatest/process.lua b/luatest/process.lua index 89622cd..5b9d932 100644 --- a/luatest/process.lua +++ b/luatest/process.lua @@ -36,6 +36,7 @@ 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 {} @@ -43,9 +44,13 @@ function Process:start(path, args, env, options) 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() diff --git a/luatest/runner.lua b/luatest/runner.lua index d17f932..82c50ff 100644 --- a/luatest/runner.lua +++ b/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) diff --git a/luatest/server.lua b/luatest/server.lua index 34917de..96b1e40 100644 --- a/luatest/server.lua +++ b/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 `/.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) diff --git a/luatest/server_instance.lua b/luatest/server_instance.lua index 865fcf4..12c191a 100644 --- a/luatest/server_instance.lua +++ b/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 = } - -- ]]}) - -- - -- 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 diff --git a/test/capture_test.lua b/test/capture_test.lua index e205a08..2b20ff5 100644 --- a/test/capture_test.lua +++ b/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('luatest.log').info = function() end + g.setup = function() capture:enable() end g.teardown = function() capture:flush() diff --git a/test/capturing_test.lua b/test/capturing_test.lua index c62cc0c..43ab0f7 100644 --- a/test/capturing_test.lua +++ b/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('luatest.log').info = function() end + g.setup = function() capture:enable() end g.teardown = function() capture:flush() diff --git a/test/server_instance.lua b/test/server_instance.lua index 35ee87a..10aadd4 100755 --- a/test/server_instance.lua +++ b/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}) diff --git a/test/server_test.lua b/test/server_test.lua index 5b06115..0285db9 100644 --- a/test/server_test.lua +++ b/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,