From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtp57.i.mail.ru (smtp57.i.mail.ru [217.69.128.37]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id D0A084696C3 for ; Tue, 21 Apr 2020 19:23:39 +0300 (MSK) Date: Tue, 21 Apr 2020 19:23:34 +0300 From: Alexander Turenko Message-ID: <20200421162334.7aaulmlqs5mvxpwl@tkn_work_nb> References: <20200324085243.29337-1-arkholga@tarantool.org> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline In-Reply-To: <20200324085243.29337-1-arkholga@tarantool.org> Subject: Re: [Tarantool-patches] [PATCH] say: fix syslog format List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Olga Arkhangelskaia Cc: tarantool-patches@dev.tarantool.org LGTM. Made minor changes and pushed to master, 2.4 and 2.3. CCed Kirill. See more below. WBR, Alexander Turenko. ---- I wondered why a log format is attempted to change at all after setting up syslog logger. Found that 'log' option is parsed at first box.cfg{}, but then 'log_format' is applied. This change disables it: diff --git a/src/lib/core/say.c b/src/lib/core/say.c index 5d572e1ab..fa3529194 100644 --- a/src/lib/core/say.c +++ b/src/lib/core/say.c @@ -694,7 +694,8 @@ say_logger_init(const char *init_str, int level, int nonblock, say_set_log_level(level); log_background = background; log_pid = log_default->pid; - say_set_log_format(say_format_by_name(format)); + if (log_default->type != SAY_LOGGER_SYSLOG) + say_set_log_format(say_format_by_name(format)); if (background) { fflush(stderr); It allows the test to pass, but it does not fix the whole problem. Messages that are generated during box.cfg{} have right format, but if we'll call log.info(<...>) -- those ones will have 'plain' format. NB: We should add log.info() case to the test. There is one more place, where log_format is set during first box.cfg{}: diff --git a/src/box/lua/load_cfg.lua b/src/box/lua/load_cfg.lua index 5d818addf..daf2385c1 100644 --- a/src/box/lua/load_cfg.lua +++ b/src/box/lua/load_cfg.lua @@ -574,7 +574,11 @@ local function load_cfg(cfg) __call = locked(reload_cfg), }) private.cfg_load() + -- XXX: Give an error if log_format and log are set both? for key, fun in pairs(dynamic_cfg) do + if key == 'log_format' and cfg.log ~= nil then + goto continue + end local val = cfg[key] if val ~= nil then if not dynamic_cfg_skip_at_load[key] then @@ -587,6 +591,7 @@ local function load_cfg(cfg) log.info("set '%s' configuration option to %s", key, json.encode(val)) end end + ::continue:: end if not box.cfg.read_only and not box.cfg.replication then box.schema.upgrade{auto = true} After this the problem is gone. Those exclusions looks fragile, so I would stick with your approach for now: put the skip condition back to say_set_log_format(). IMHO, it is consequence of the way syslog is implemented now: it requires specific format, but there is no such `enum say_format` value. `log` option may configure actual format, but then default log_format is set (and should be ignored underneath). This looks as the tech debt. Now, changes I made to the patch: I verify all arrived log messages instead of the first one. It requires to make the syslog entry pattern less restrictive, because 'saving snapshot' message comes from 'snapshot' fiber, not the main one). I added the log.info() case into your test and also verified that log.log_format('plain') does not change syslog format to 'plain'. Minor style fixes. The full diff is below: diff --git a/test/box-tap/gh-4785-syslog.test.lua b/test/box-tap/gh-4785-syslog.test.lua index ba43c1566..3d750b9ed 100755 --- a/test/box-tap/gh-4785-syslog.test.lua +++ b/test/box-tap/gh-4785-syslog.test.lua @@ -5,38 +5,64 @@ local log = require('log') local fio = require('fio') local tap = require('tap') -local test = tap.test("Tarantool 4785") -test:plan(1) - -local identity = 'tarantool' -local path = fio.pathjoin(fio.cwd(), 'log_unix_socket_test.sock') +-- A unix socket to read log entries from it. +local path = fio.pathjoin(fio.cwd(), 'syslog.sock') local unix_socket = socket('AF_UNIX', 'SOCK_DGRAM', 0) +os.remove(path) unix_socket:bind('unix/', path) +local identity = 'tarantool' box.cfg{ - log = string.format("syslog:server=unix:%s,identity=%s", path, identity) + log = ('syslog:server=unix:%s,identity=%s'):format(path, identity), } -local entry = unix_socket:recv(100) --- Check syslog format: IDENTITY[PID]: CORD/FID/FILE FACILITY> +-- Syslog format: +-- +-- IDENTITY[PID]: CORD/FID/FILE FACILITY> local patterns = { - PRI = '<%d+>', - TIMESTAMP = '%u%l%l ?%d?%d %d%d:%d%d:%d%d', - IDENTITY = identity, - PID = '%[%d+%]', - CORD = 'main', - FID = '%d+', - FILE = '.+%.lua', - FACILITY = '%u' + '<%d+>', -- PRI + '%u%l%l ?%d?%d %d%d:%d%d:%d%d', -- TIMESTAMP + identity, -- IDENTITY + '%[%d+%]', -- PID + '[%l%d]+', -- CORD + '%d+', -- FID + '[%l%d-_.]+', -- FILE + '%u', -- FACILITY } +local pattern = ('%s%s %s%s: %s/%s/%s %s>'):format(unpack(patterns)) + +local test = tap.test('gh-4785-syslog') +test:plan(4) -local pattern = string.format('%s%s %s%s: %s/%s/%s %s>', - patterns.PRI, patterns.TIMESTAMP, - patterns.IDENTITY, patterns.PID, patterns.CORD, - patterns.FID, patterns.FILE, patterns.FACILITY) -test:like(entry, pattern, 'syslog format') +-- Verify all log entries we have after box.cfg(). +local ok = true +local logs = {} +while true do + local entry = unix_socket:recv(100) + if entry == nil then break end + ok = ok and entry:match(pattern) + table.insert(logs, entry) +end +test:ok(ok, 'box.cfg() log entries are in syslog format', {logs = logs}) +-- Verify a log entry written by log.info(). +log.info('hello') +local entry = unix_socket:recv(100) +test:like(entry, pattern, 'log.info() log entry is in syslog format', + {logs = {entry}}) + +-- log.log_format('plain') is silently ignored. +local ok = pcall(log.log_format, 'plain') +test:ok(ok, "log.log_format('plain') is ignored with syslog") + +-- Verify log format again after log.log_format(). +log.info('world') +local entry = unix_socket:recv(100) +test:like(entry, pattern, 'log.info() log entry after log_format', + {logs = {entry}}) + +-- Drop unix socket file. unix_socket:close() os.remove(path) -os.exit(test:check() and 0 or 1) +os.exit(test:check() and 0 or 1)