diff --git a/CHANGELOG.md b/CHANGELOG.md index c715889..6da3951 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ # Changelog +## Unreleased + +- Add logging to unified file (gh-324). + ## 1.0.1 - Fixed incorrect Unix domain socket path length check (gh-341). diff --git a/luatest/output_beautifier.lua b/luatest/output_beautifier.lua index d847bbb..b9cf587 100644 --- a/luatest/output_beautifier.lua +++ b/luatest/output_beautifier.lua @@ -59,9 +59,10 @@ end -- @string object.prefix String to prefix each output line with. -- @string[opt] object.color Color name for prefix. -- @string[opt] object.color_code Color code for prefix. +-- @boolean[opt] object.runner Mark OutputBeautifier object is created for runner process. -- @return input object. function OutputBeautifier:new(object) - checks('table', {prefix = 'string', color = '?string', color_code = '?string'}) + checks('table', {prefix = 'string', color = '?string', color_code = '?string', runner = '?boolean'}) return self:from(object) end @@ -69,19 +70,30 @@ function OutputBeautifier.mt:initialize() self.color_code = self.color_code or 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.pipes = {stderr = ffi_io.create_pipe()} + if not self.runner then + self.pipes.stdout = ffi_io.create_pipe() + end self.stderr = '' + self.enable_capture = nil end -- Replace standard output descriptors with pipes. +-- Stdout descriptor of the runner process will not be replaced +-- because it is used for displaying all captured data from other processes. function OutputBeautifier.mt:hijack_output() - ffi_io.dup2_io(self.pipes.stdout[1], io.stdout) + if not self.runner then + ffi_io.dup2_io(self.pipes.stdout[1], io.stdout) + end ffi_io.dup2_io(self.pipes.stderr[1], io.stderr) end -- Start fibers that reads from pipes and prints formatted output. -- Pass `track_pid` option to automatically stop forwarder once process is finished. function OutputBeautifier.mt:enable(options) + if options and options.enable_capture ~= nil then + self.enable_capture = options.enable_capture == false + end if self.fibers then return end @@ -140,8 +152,10 @@ 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) - local prefix = self.color_code .. self.prefix .. ' | ' + 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) @@ -154,7 +168,16 @@ function OutputBeautifier.mt:run(fd, pipe) end for _, line in pairs(lines) do line_color_code = self:color_for_line(line) or line_color_code - io.stdout:write(table.concat({prefix, line_color_code, line, self.class.RESET_TERM, '\n'})) + if not self.runner or self.enable_capture then + io.stdout:write( + table.concat( + {colored_prefix, line_color_code, line, self.class.RESET_TERM,'\n'} + ) + ) + end + if log_file ~= nil then + log_file.fh:write(table.concat({prefix, line, '\n'})) + end fiber.yield() end end) diff --git a/luatest/runner.lua b/luatest/runner.lua index e4ce6b1..ce8baf6 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -4,6 +4,7 @@ local clock = require('clock') local fio = require('fio') +local log = require('log') local assertions = require('luatest.assertions') local capturing = require('luatest.capturing') @@ -16,6 +17,7 @@ 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') @@ -56,6 +58,50 @@ 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) + + 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, runner = true}) + output_beautifier:enable({enable_capture = options.enable_capture}) + output_beautifier:hijack_output() + + -- `tee` copy logs to file and also to standard output, but we need + -- process all captured data through the OutputBeatifier object. + -- Data will be redirected back to stderr of the current process. + -- `/dev/fd/2` is a symlink to `/proc/self/fd`, where `/proc/self` is + -- a symlink to `/proc/`. So `/dev/fd/2` is equal to `/proc//fd/2` + -- and it means "stderr of the current process". + log_cfg = string.format("| tee %s > /dev/fd/2", log_cfg) + 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> ... + log.cfg{ + log = log_cfg, + level = options.log_level or 5, + } + end + if options.help then print(Runner.USAGE) return 0 @@ -85,12 +131,17 @@ Positional arguments: Options: -h, --help: Print this help --version: Print version information - -v, --verbose: Increase verbosity + -v, --verbose: Increase output verbosity for luatest runnner + -vv, Increase log verbosity to VERBOSE level for luatest runnner + -vvv, Increase log verbosity to DEBUG level for luatest runnner -q, --quiet: Set verbosity to minimum -c Disable capture -b Print full backtrace (don't remove luatest frames) -e, --error: Stop on first error -f, --failure: Stop on first failure or error + -l, --log PATH: Path to the unified log file + --runner-log-prefix NAME: + Log prefix for luatest runner, 'luatest' by default --shuffle VALUE: Set execution order: - group[:seed] - shuffle tests within group - all[:seed] - shuffle all tests @@ -135,6 +186,12 @@ function Runner.parse_cmd_line(args) result.version = true elseif arg == '--verbose' or arg == '-v' then result.verbosity = GenericOutput.VERBOSITY.VERBOSE + elseif arg == '-vv' then + result.verbosity = GenericOutput.VERBOSITY.VERBOSE + result.log_level = 6 -- verbose + elseif arg == '-vvv' then + result.verbosity = GenericOutput.VERBOSITY.VERBOSE + result.log_level = 7 -- debug elseif arg == '--quiet' or arg == '-q' then result.verbosity = GenericOutput.VERBOSITY.QUIET elseif arg == '--fail-fast' or arg == '-f' then @@ -145,6 +202,10 @@ function Runner.parse_cmd_line(args) if seed then result.seed = tonumber(seed) or error('Invalid seed value') end + elseif arg == '-l' or arg == '--log' then + result.log_file = tostring(next_arg()) or error('Invalid log file path') + elseif arg == '--runner-log-prefix' then + result.log_prefix = tostring(next_arg()) elseif arg == '--seed' then result.seed = tonumber(next_arg()) or error('Invalid seed value') elseif arg == '--output' or arg == '-o' then diff --git a/luatest/server.lua b/luatest/server.lua index 86860a6..5506871 100644 --- a/luatest/server.lua +++ b/luatest/server.lua @@ -212,6 +212,10 @@ 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 end -- Create a table with env variables based on the constructor params. @@ -223,6 +227,7 @@ end -- * `TARANTOOL_ALIAS` -- * `TARANTOOL_HTTP_PORT` -- * `TARANTOOL_BOX_CFG` +-- * `TARANTOOL_UNIFIED_LOG_ENABLED` -- -- @return table function Server:build_env() @@ -235,6 +240,9 @@ 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 @@ -743,7 +751,16 @@ end function Server:grep_log(pattern, bytes_num, opts) local options = opts or {} local reset = options.reset or true - local filename = options.filename or self:exec(function() return box.cfg.log end) + + -- `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 file = fio.open(filename, {'O_RDONLY', 'O_NONBLOCK'}) local function fail(msg) diff --git a/luatest/server_instance.lua b/luatest/server_instance.lua index 8de20d5..865fcf4 100644 --- a/luatest/server_instance.lua +++ b/luatest/server_instance.lua @@ -1,17 +1,55 @@ 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 = fio.pathjoin( - os.getenv('TARANTOOL_WORKDIR'), - os.getenv('TARANTOOL_ALIAS') .. '.log' - ), + log = log_cfg() } end