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

[Igor Munkin <imun@tarantool.org>]

Olya,

Thanks for the patch! I left a couple nits below, please consider them.

Furthemore, I see there is still test/box-tap/gh-4785-syslog.result
in the diff. Please remove it.

On 15.04.20, Olga Arkhangelskaia wrote:
> Hi Igor!
> 
> Thanks for the review!
> 
> I have fixed the patch according to what we have discussed.
> 
> Please, see diff below
> 
> 14.04.2020 15:52, Igor Munkin пишет:
> > Olya,
> >
> > Thanks for the patch! I left several comments below, please consider
> > them.
> >
> > On 24.03.20, Olga Arkhangelskaia wrote:
> >> While refactoring of say module in commit 2.0.4-837-g5db765a76
> > AFAICS, we mention commits the following way:
> > | * b5b4809cf2e6d48230eb9e4301eac188b080e0f4 ('replication: update
> > | replica gc state on subscribe');
> >
> >> format of syslog was broken.
> >>
> >> Closes #4785
> >> ---
> >>   src/lib/core/say.c                   |  6 +++++-
> >>   test/box-tap/gh-4785-syslog.result   |  1 +
> >>   test/box-tap/gh-4785-syslog.test.lua | 22 ++++++++++++++++++++++
> >>   3 files changed, 28 insertions(+), 1 deletion(-)
> >>   create mode 100644 test/box-tap/gh-4785-syslog.result
> >>   create mode 100755 test/box-tap/gh-4785-syslog.test.lua
> >>
> >> diff --git a/src/lib/core/say.c b/src/lib/core/say.c
> >> index dd05285a6..d03e687b5 100644
> >> --- a/src/lib/core/say.c
> >> +++ b/src/lib/core/say.c
> >> @@ -199,7 +199,11 @@ void
> >>   say_set_log_format(enum say_format format)
> >>   {
> >>   	log_format_func_t format_func;
> >> -
> >> +	bool allowed_to_change = log_default->type == SAY_LOGGER_STDERR ||
> >> +			         log_default->type == SAY_LOGGER_PIPE ||
> >> +				 log_default->type == SAY_LOGGER_FILE;
> > Considering the values in SAY_LOGGER_* enum only two types are not
> > allowed to be changed: SAY_LOGGER_SYSLOG (since syslog format is fixed)
> > and SAY_LOGGER_BOOT (and I have no idea why). Thereby it would be great
> > to mention unchangable logger types with the corresponding reasons.
> > Also, considering the reasons the inverted condition looks more
> > convenient.
> >
> >> +	if (!allowed_to_change)
> >> +		return;
> >>   	switch (format) {
> >>   	case SF_JSON:
> >>   		assert(log_default->type != SAY_LOGGER_SYSLOG);
> > This assertion never raises after the patch, so can be dropped.
> >
> >> diff --git a/test/box-tap/gh-4785-syslog.result b/test/box-tap/gh-4785-syslog.result
> >> new file mode 100644
> >> index 000000000..bf3df9e6e
> >> --- /dev/null
> >> +++ b/test/box-tap/gh-4785-syslog.result
> >> @@ -0,0 +1 @@
> >> +<>TIMESTAMP tarantool[PID]: main//gh.test.lua C> Tarantool
> >> diff --git a/test/box-tap/gh-4785-syslog.test.lua b/test/box-tap/gh-4785-syslog.test.lua
> >> new file mode 100755
> >> index 000000000..586a2eb1a
> >> --- /dev/null
> >> +++ b/test/box-tap/gh-4785-syslog.test.lua
> > Since you created a diff-based test it has to be moved to box directory
> > otherwise you can leave it here and transform it to a TAP-based one.
> > I propose to go the latter way.
> >
> >> @@ -0,0 +1,22 @@
> >> +#!/usr/bin/env tarantool
> >> +test_run = require('test_run').new()
> > Seems like you don't need 'test_run' object here.
> >
> >> +
> >> +local socket = require('socket')
> >> +local log = require('log')
> >> +local fio = require('fio')
> >> +
> >> +path = fio.pathjoin(fio.cwd(), 'log_unix_socket_test.sock')
> >> +unix_socket = socket('AF_UNIX', 'SOCK_DGRAM', 0)
> >> +unix_socket:bind('unix/', path)
> >> +
> >> +opt = string.format("syslog:server=unix:%s,identity=tarantool", path)
> >> +local buf = ''
> >> +box.cfg{log = opt}
> >> +buf = buf .. unix_socket:recv(100)
> >> +str = string.format(buf)
> >> +-- Check syslog format: TIMESTAMP IDENTATION[PID]
> >> +--<>TIMESTAMP tarantool[PID]: main//gh.test.lua C> Tarantool
> >> +print(((((str:gsub("%d", "")):gsub("%p%p--%w+", "")):gsub("%w+  ::", "TIMESTAMP")):gsub("]", "PID]")))
> > You can just use test:like here to check the received log entry. Also
> > <buf> and <opt> variables are excess and parentheses can be omitted.
> > Furthermore, syslog entry is a well documented format[1], so you can
> > match it against an RFC pattern. I reimplemented the test the following
> > way (the diff is below):
> >
> > ================================================================================
> >
> > diff --git a/test/box-tap/gh-4785-syslog.result
> > b/test/box-tap/gh-4785-syslog.result
> > deleted file mode 100644
> > index bf3df9e6e..000000000
> > --- a/test/box-tap/gh-4785-syslog.result
> > +++ /dev/null
> > @@ -1 +0,0 @@
> > -<>TIMESTAMP tarantool[PID]: main//gh.test.lua C> Tarantool
> > diff --git a/test/box-tap/gh-4785-syslog.test.lua b/test/box-tap/gh-4785-syslog.test.lua
> > index 586a2eb1a..bdf8d5d88 100755
> > --- a/test/box-tap/gh-4785-syslog.test.lua
> > +++ b/test/box-tap/gh-4785-syslog.test.lua
> > @@ -1,22 +1,39 @@
> >   #!/usr/bin/env tarantool
> > -test_run = require('test_run').new()
> > -
> >   local socket = require('socket')
> >   local log = require('log')
> >   local fio = require('fio')
> > +local tap = require('tap')
> > +
> > +local test = tap.test("Tarantool 4785")
> > +test:plan(1)
> >   
> > -path = fio.pathjoin(fio.cwd(), 'log_unix_socket_test.sock')
> > -unix_socket = socket('AF_UNIX', 'SOCK_DGRAM', 0)
> > +local identity = 'tarantool'
> > +local path = fio.pathjoin(fio.cwd(), 'log_unix_socket_test.sock')
> > +local unix_socket = socket('AF_UNIX', 'SOCK_DGRAM', 0)
> >   unix_socket:bind('unix/', path)
> >
> > -opt = string.format("syslog:server=unix:%s,identity=tarantool", path)
> > -local buf = ''
> > -box.cfg{log = opt}
> > -buf = buf .. unix_socket:recv(100)
> > -str = string.format(buf)
> > --- Check syslog format: TIMESTAMP IDENTATION[PID]
> > ---<>TIMESTAMP tarantool[PID]: main//gh.test.lua C> Tarantool
> > -print(((((str:gsub("%d", "")):gsub("%p%p--%w+", "")):gsub("%w+  ::", "TIMESTAMP")):gsub("]", "PID]")))
> > +box.cfg{
> > +  log = string.format("syslog:server=unix:%s,identity=%s", path, identity)
> > +}
> > +
> > +local entry = unix_socket:recv(100)
> > +-- Check 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'
> > +}
> > +
> > +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')
> >   unix_socket:close()
> >   os.remove(path)
> > -os.exit(0)
> > +os.exit(test:check() and 0 or 1)
> >
> > ================================================================================
> >
> >> +unix_socket:close()
> >> +os.remove(path)
> >> +os.exit(0)
> >> -- 
> >> 2.20.1 (Apple Git-117)
> >>
> > [1]: https://tools.ietf.org/html/rfc3164#section-4.1
> 
>   While refactoring of say module in commit
>    7 5db765a76ab7270b350960a2dd6d89dcd3bdc032 (say: fix non-informative 
> error
>    8 messages for log cfg) format of syslog was broken.
> 
> 
>   30 +`....../* For syslog, default or boot log type the log format can
>   31 +`...... * not be changed.
>   32 +`...... */

At first, there is still no a word regarding the reasons why formats for
these logger types are unchanged.

Furthermore, Sasha mentioned[1] about the comment style we use in our
code, so I just cite him:

| We use two styles of comments (for one-line and multi-line comments):
|
|  | /* Hello. */
|
|  | /*
|  |  * Hello,
|  |  * world.
|  |  */
|
| Changed the comment to follow the latter style.
|
| If you're curious, Linus about comments style (strong language, you have
| been warned): https://lkml.org/lkml/2016/7/8/625

I propose to change the comment the following way:

================================================================================

diff --git a/src/lib/core/say.c b/src/lib/core/say.c
index 776321283..924ec8e77 100644
--- a/src/lib/core/say.c
+++ b/src/lib/core/say.c
@@ -199,8 +199,14 @@ void
 say_set_log_format(enum say_format format)
 {
        log_format_func_t format_func;
-       /* For syslog, default or boot log type the log format can
-        * not be changed.
+
+       /*
+        * When logger type is SAY_LOGGER_BOOT it simply prints
+        * every message to stdout intact and can't be formatted.
+        * SAY_LOGGER_SYSLOG type uses the well-documented and
+        * *recommended* format described in the RFC below:
+        * https://tools.ietf.org/html/rfc3164#section-4.1
+        * Thereby format can't be changed for this type either.
         */
        bool unchangeable =  log_default->type == SAY_LOGGER_BOOT ||
                             log_default->type == SAY_LOGGER_SYSLOG;

================================================================================

>   33 +`......bool unchangeable =  log_default->type == SAY_LOGGER_BOOT ||
>   34 +`......`.......`.......     log_default->type == SAY_LOGGER_SYSLOG;

Typo: space is doubled after the assignment sign.

>   35 +`......if (unchangeable)
>   36 +`......`.......return;
>   37  `......switch (format) {
>   38  `......case SF_JSON:
>   39 -`......`.......assert(log_default->type != SAY_LOGGER_SYSLOG);
>   40  `......`.......format_func = say_format_json;
>   41 `......`.......break;
>   42  `......case SF_PLAIN:
> >

[1]: https://lists.tarantool.org/pipermail/tarantool-patches/2020-February/014230.html

-- 
Best regards,
IM