From f8a1c10baa4827a116c1cc6bd54b7b94bb7af395 Mon Sep 17 00:00:00 2001 From: Oleg Chaplashkin Date: Tue, 19 Dec 2023 18:16:07 +0400 Subject: [PATCH] Add logging to unified file We present a new functionality for logging. > How it worked before Having written a simple test with two servers (bob and frank) we would like to see the output of each of them and also what is going on in the test itself. For example: g.test_with_bob_and_frank = function() g.bob:exec(function() require('log').info('Hi, Frank!') end) g.frank:exec(function() require('log').info('Hi, Bob!') end) require('log').info('Hi, Bob and Frank!') end In order to see their greetings, we had to look over each server log file: $ cat /tmp/t/${BOB_VARDIR}/bob.log ... 2023-12-19 18:34:26.305 [84739] main/109/main I> Hi, Frank! $ cat /tmp/t/${FRANK_VARDIR}/frank.log ... 2023-12-19 18:34:26.306 [84752] main/109/main I> Hi, Bob! And there was no way to see the "Hi, Bob and Frank!" log message at all. > How it works now Now, if we provide the `-l, --log` parameter with the file path, we will see the following contents in the specified log file: $ ./bin/luatest -c -v -l run.log && cat run.log ... bob | 2023-12-19 18:39:40.858 [85021] main/109/main I> Hi, Frank! frank | 2023-12-19 18:39:40.859 [85034] main/109/main I> Hi, Bob! luatest | 2023-12-19 18:39:40.860 [85034] main/109/main I> Hi, Bob and Frank! > What's under the hood The solution is based on the existing OutputBeautifier module logic: it can already read data from standard output streams (stdout/stderr) and print it to luatest stdout. When we run luatest (this is Tarantool process), we read stderr stream and hijack it. All logs of this process will be written to stderr and intercepted by the OutputBeautifier fiber. The fiber processes them and writes to our specified file for all logs and then to the luatest stdout stream. To save the log file for each server separately (this can be useful for research) we use the standard `tee` command. In the case of the server, we configure logging as follows: ' | tee ${TARANTOOL_WORKDIR}/${TARANTOOL_ALIAS}.log' While the server is running, all logs will be redirected to the `tee` command. So it will be written to the server log file and stdout stream. Then all data from stdout will be intercepted by the OutputBeautifier fiber that will write it to the specified log file. > What's new in administration New options: `-l, --log PATH` - set the path to the unified log file. `--runner-log-prefix NAME` - set the log prefix for luatest runner, 'luatest' by default. Improved options: `-v` - increase output verbosity (as it was before) and set `INFO` log level for luatest runner. `-vv` - increase log verbosity to `VERBOSE` level for luatest runnner. `-vvv` - increase log verbosity to `DEBUG` level for luatest runnner. Closes #324 --- CHANGELOG.md | 4 +++ luatest/output_beautifier.lua | 33 +++++++++++++++--- luatest/runner.lua | 63 ++++++++++++++++++++++++++++++++++- luatest/server.lua | 19 ++++++++++- luatest/server_instance.lua | 46 ++++++++++++++++++++++--- 5 files changed, 154 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c7158896..6da39513 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 d847bbb9..b9cf587d 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 e4ce6b1a..ce8baf69 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 86860a64..55068715 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 8de20d55..865fcf4b 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