Re: [Tarantool-patches] [PATCH] say: fix syslog format

[Alexander Turenko <alexander.turenko@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: <PRI><TIMESTAMP> IDENTITY[PID]: CORD/FID/FILE FACILITY>
+-- Syslog format:
+--
+-- <PRI><TIMESTAMP> 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)