From 80093cc51132c2cdaa2e7a607d822b8c397b75c6 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Wed, 2 Apr 2025 18:50:56 +0300 Subject: [PATCH 1/4] cmake: bump min version to 3.5 Compatibility with CMake < 3.5 has been removed from CMake. --- CMakeLists.txt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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) From 8ee10312e1975608b98539d036ddb8f624742741 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Wed, 2 Apr 2025 14:40:04 +0300 Subject: [PATCH 2/4] Truncate unified log file at startup Otherwise we can get mixed logs in the unified log file after running luatest a few times. No changelog because the feature was added by commit f8a1c10baa482 ("Add logging to unified file"), which hasn't been released yet. --- luatest/runner.lua | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/luatest/runner.lua b/luatest/runner.lua index d17f932..616ede7 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -69,7 +69,8 @@ function Runner.run(args, options) -- 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)) + 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}) From be2c0c4aca2bd27a41f46d780af5fe02ef0e6bdb Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 1 Apr 2025 16:41:33 +0300 Subject: [PATCH 3/4] 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 --- CHANGELOG.md | 3 +++ luatest/output_beautifier.lua | 27 ++++++++++++++-------- luatest/process.lua | 11 ++++++--- luatest/server.lua | 41 ++++++++++++--------------------- luatest/server_instance.lua | 43 ----------------------------------- test/server_instance.lua | 3 +-- test/server_test.lua | 1 - 7 files changed, 44 insertions(+), 85 deletions(-) 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/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/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/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, From c1d532453c25860fb08c8c6377396f44580dff5b Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Thu, 3 Apr 2025 16:00:25 +0300 Subject: [PATCH 4/4] 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 f8a1c10baa482 ("Add logging to unified file"), which hasn't been released yet. --- luatest/log.lua | 59 +++++++++++++++++++++++++++++++++++++++++ luatest/runner.lua | 47 ++++---------------------------- test/capture_test.lua | 3 +++ test/capturing_test.lua | 3 +++ 4 files changed, 70 insertions(+), 42 deletions(-) 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/runner.lua b/luatest/runner.lua index 616ede7..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,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) 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()