[Tarantool-patches] [PATCH v2 0/3] log: allow json formatter in boottime logger

[Tarantool-patches] [PATCH v2 0/3] log: allow json formatter in boottime logger

[Cyrill Gorcunov]

For some reason we've disabled usage of json formatter in early
logging since the commit 098324556. Lets allow it back.

v2:
 - add early verification of options for cases like
   box.cfg{log="syslog:", log_format="json"}
 - extend test

branch gorcunov/gh-5121-logger-boot-json-2
issue https://github.com/tarantool/tarantool/issues/5121

Cyrill Gorcunov (3):
  core/say: allow to use json in boot logger
  lua/log: allow to use json formatter early
  test: app-tap/logger -- test json in boottime logger

 src/box/lua/load_cfg.lua     |  6 ++---
 src/lib/core/say.c           |  7 ++----
 src/lua/log.lua              | 43 +++++++++++++++++++++++++++---------
 test/app-tap/logger.test.lua | 19 ++++++++++++----
 4 files changed, 53 insertions(+), 22 deletions(-)

-- 
2.26.2

[Tarantool-patches] [PATCH 1/3] core/say: allow to use json in boot logger

[Cyrill Gorcunov]

For some reason in commit 098324556 we've disabled
to use json format in boot time logger. There is
no reason to do so.

Only syslog output format is predefined and must not
be changed, in turn json format is just a decoration
over output stream so we can use it whenever requested.

Part-of #5121

Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lib/core/say.c | 7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/src/lib/core/say.c b/src/lib/core/say.c
index 791011e6f..b903cb03f 100644
--- a/src/lib/core/say.c
+++ b/src/lib/core/say.c
@@ -206,17 +206,14 @@ say_set_log_format(enum say_format format)
 {
 	log_format_func_t format_func;
 	/*
-	 * 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;
-	if (unchangeable)
+	if (log_default->type == SAY_LOGGER_SYSLOG)
 		return;
+
 	switch (format) {
 	case SF_JSON:
 		format_func = say_format_json;
-- 
2.26.2

[Tarantool-patches] [PATCH 2/3] lua/log: allow to use json formatter early

[Cyrill Gorcunov]

There is no reason to not allow for json formatter
on early logging stage.

We add verification that

	box.cfg{log="syslog:", log_format="json"}
or
	require('log').cfg{log="syslog:", format="json"}

is triggering error since syslog output requires
predefined structure and can't use json.

Fixes #5121

Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/box/lua/load_cfg.lua |  6 +++---
 src/lua/log.lua          | 43 ++++++++++++++++++++++++++++++----------
 2 files changed, 36 insertions(+), 13 deletions(-)

diff --git a/src/box/lua/load_cfg.lua b/src/box/lua/load_cfg.lua
index f2f2df6f8..549c14cf3 100644
--- a/src/box/lua/load_cfg.lua
+++ b/src/box/lua/load_cfg.lua
@@ -459,13 +459,13 @@ local function prepare_cfg(cfg, default_cfg, template_cfg,
                             module_cfg[k], modify_cfg[k], readable_name)
         elseif template_cfg[k] == 'module' then
             local old_value = module_cfg[k].cfg_get(k, v)
-            module_cfg_backup[k] = old_value
+            module_cfg_backup[k] = old_value or box.NULL
 
-            local ok, msg = module_cfg[k].cfg_set(k, v)
+            local ok, msg = module_cfg[k].cfg_set(cfg, k, v)
             if not ok then
                 -- restore back the old values for modules
                 for module_k, module_v in pairs(module_cfg_backup) do
-                    module_cfg[module_k].cfg_set(module_k, module_v)
+                    module_cfg[module_k].cfg_set(nil, module_k, module_v)
                 end
                 box.error(box.error.CFG, readable_name, msg)
             end
diff --git a/src/lua/log.lua b/src/lua/log.lua
index bed690526..44414bbd7 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -194,7 +194,7 @@ local function verify_static(k, v)
 end
 
 -- Test if format is valid.
-local function verify_format(key, name)
+local function verify_format(key, name, init_str)
     assert(log_cfg[key] ~= nil)
 
     if not fmt_str2num[name] then
@@ -202,11 +202,20 @@ local function verify_format(key, name)
         return false, m:format(fmt_list())
     end
 
+    local log_type = ffi.C.log_type()
+
+    -- When comes from log.cfg{} or box.cfg{}
+    -- initial call we might be asked to setup
+    -- syslog with json which is not allowed.
+    if init_str ~= nil then
+        if string.sub(init_str, 1, 7) == "syslog:" then
+            log_type = ffi.C.SAY_LOGGER_SYSLOG
+        end
+    end
+
     if fmt_str2num[name] == ffi.C.SF_JSON then
-        if ffi.C.log_type() == ffi.C.SAY_LOGGER_SYSLOG or
-            ffi.C.log_type() == ffi.C.SAY_LOGGER_BOOT then
-            local m = "%s can't be used with " ..
-            "syslog or boot-time logger"
+        if log_type == ffi.C.SAY_LOGGER_SYSLOG then
+            local m = "%s can't be used with syslog logger"
             return false, m:format(fmt_num2str[ffi.C.SF_JSON])
         end
     end
@@ -239,11 +248,11 @@ local verify_ops = {
 }
 
 -- Verify a value for the particular key.
-local function verify_option(k, v)
+local function verify_option(k, v, ...)
     assert(k ~= nil)
 
     if verify_ops[k] ~= nil then
-        return verify_ops[k](k, v)
+        return verify_ops[k](k, v, ...)
     end
 
     return true
@@ -372,10 +381,24 @@ local function box_api_cfg_get(key)
 end
 
 -- Set value to log from box.cfg{}.
-local function box_api_cfg_set(key, value)
+local function box_api_cfg_set(cfg, key, value)
     local log_key = box2log_keys[key]
+    local aux_data
+
+    -- a special case where we need to restore
+    -- nil value from previous setup attempt.
+    if value == box.NULL then
+        log_cfg[log_key] = nil
+        return true
+    end
+
+    -- 'format' option requires auxilary data
+    -- for verification sake.
+    if cfg ~= nil and log_key == 'format' then
+        aux_data = cfg['log']
+    end
 
-    local ok, msg = verify_option(log_key, value)
+    local ok, msg = verify_option(log_key, value, aux_data)
     if not ok then
         return false, msg
     end
@@ -450,7 +473,7 @@ local function load_cfg(oldcfg, cfg)
     end
 
     if cfg.format ~= nil then
-        local ok, msg = verify_option('format', cfg.format)
+        local ok, msg = verify_option('format', cfg.format, cfg.log)
         if not ok then
             local m = "log.cfg: \'%s\' %s"
             error(m:format('format', msg))
-- 
2.26.2

[Tarantool-patches] [PATCH 3/3] test: app-tap/logger -- test json in boottime logger

[Cyrill Gorcunov]

Make sure we're allowed to setup json formatter before
box.cfg() call, ie that named boot-time logger.

Part-of #5121

Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 test/app-tap/logger.test.lua | 19 +++++++++++++++----
 1 file changed, 15 insertions(+), 4 deletions(-)

diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
index ae4a3b99a..a448ba87a 100755
--- a/test/app-tap/logger.test.lua
+++ b/test/app-tap/logger.test.lua
@@ -1,13 +1,24 @@
 #!/usr/bin/env tarantool
 
 local test = require('tap').test('log')
-test:plan(62)
+test:plan(64)
 
--- gh-3946: Assertion failure when using log_format() before box.cfg()
+--
+-- gh-5121: Allow to use 'json' output before box.cfg()
+--
 local log = require('log')
-log.log_format('plain')
 _, err = pcall(log.log_format, 'json')
-test:ok(err:find("json can\'t be used") ~= nil)
+test:ok(err == nil)
+
+-- We're not allowed to use json with syslog though.
+_, err = pcall(log.cfg, {log='syslog:', format='json'})
+test:ok(tostring(err):find("can\'t be used with syslog logger") ~= nil)
+
+_, err = pcall(box.cfg, {log='syslog:', log_format='json'})
+test:ok(tostring(err):find("can\'t be used with syslog logger") ~= nil)
+
+-- switch back to plain to next tests
+log.log_format('plain')
 
 --
 -- gh-689: various settings change from box.cfg/log.cfg interfaces
-- 
2.26.2

Re: [Tarantool-patches] [PATCH 2/3] lua/log: allow to use json formatter early

[Oleg Babin]

Hi! Thanks for your patch see my four comments below.

On 30/06/2020 19:02, Cyrill Gorcunov wrote:
> There is no reason to not allow for json formatter
> on early logging stage.
>
> We add verification that
>
> 	box.cfg{log="syslog:", log_format="json"}
> or
> 	require('log').cfg{log="syslog:", format="json"}
>
> is triggering error since syslog output requires
> predefined structure and can't use json.
>
> Fixes #5121
>
> Signed-off-by: Cyrill Gorcunov<gorcunov@gmail.com>
> ---

May be it's not directly related to the patch but:

```

tarantool> log.cfg{log = ' syslog:identity=test', format = 'json'}
IllegalParams: expecting a file name or a prefix, such as '|', 'pipe:', 
'syslog:'
failed to initialize logging subsystem

```

It should be a simple error but not panic. I've just add a space in log 
parameter.

At the same time:

```

tarantool> box.cfg{log = ' syslog:'}
---
- error: 'Incorrect value for option ''log'': expecting a file name or a 
prefix, such
     as ''|'', ''pipe:'', ''syslog:'''
...

```

>   src/box/lua/load_cfg.lua |  6 +++---
>   src/lua/log.lua          | 43 ++++++++++++++++++++++++++++++----------
>   2 files changed, 36 insertions(+), 13 deletions(-)
>
> diff --git a/src/box/lua/load_cfg.lua b/src/box/lua/load_cfg.lua
> index f2f2df6f8..549c14cf3 100644
> --- a/src/box/lua/load_cfg.lua
> +++ b/src/box/lua/load_cfg.lua
> @@ -459,13 +459,13 @@ local function prepare_cfg(cfg, default_cfg, template_cfg,
>                               module_cfg[k], modify_cfg[k], readable_name)
>           elseif template_cfg[k] == 'module' then
>               local old_value = module_cfg[k].cfg_get(k, v)
> -            module_cfg_backup[k] = old_value
> +            module_cfg_backup[k] = old_value or box.NULL
>   

Could you please clarify this change? I see below you check "value == 
box.NULL" but if value is simple nil then such condition is true.

```

tarantool> box.NULL == nil
---
- true
...

tarantool> box.NULL == box.NULL
---
- true
...

```

Why is simple "nil" not enough?

> -            local ok, msg = module_cfg[k].cfg_set(k, v)
> +            local ok, msg = module_cfg[k].cfg_set(cfg, k, v)
>               if not ok then
>                   -- restore back the old values for modules
>                   for module_k, module_v in pairs(module_cfg_backup) do
> -                    module_cfg[module_k].cfg_set(module_k, module_v)
> +                    module_cfg[module_k].cfg_set(nil, module_k, module_v)
>                   end
>                   box.error(box.error.CFG, readable_name, msg)
>               end
> diff --git a/src/lua/log.lua b/src/lua/log.lua
> index bed690526..44414bbd7 100644
> --- a/src/lua/log.lua
> +++ b/src/lua/log.lua
> @@ -194,7 +194,7 @@ local function verify_static(k, v)
>   end
>   
>   -- Test if format is valid.
> -local function verify_format(key, name)
> +local function verify_format(key, name, init_str)
>       assert(log_cfg[key] ~= nil)
>   
>       if not fmt_str2num[name] then
> @@ -202,11 +202,20 @@ local function verify_format(key, name)
>           return false, m:format(fmt_list())
>       end
>   
> +    local log_type = ffi.C.log_type()
> +
> +    -- When comes from log.cfg{} or box.cfg{}
> +    -- initial call we might be asked to setup
> +    -- syslog with json which is not allowed.
> +    if init_str ~= nil then
> +        if string.sub(init_str, 1, 7) == "syslog:" then
> +            log_type = ffi.C.SAY_LOGGER_SYSLOG
> +        end
> +    end
> +

I believe that string.startswith(str, 'syslog:') is better here than 
string.sub(...).

>       if fmt_str2num[name] == ffi.C.SF_JSON then
> -        if ffi.C.log_type() == ffi.C.SAY_LOGGER_SYSLOG or
> -            ffi.C.log_type() == ffi.C.SAY_LOGGER_BOOT then
> -            local m = "%s can't be used with " ..
> -            "syslog or boot-time logger"
> +        if log_type == ffi.C.SAY_LOGGER_SYSLOG then
> +            local m = "%s can't be used with syslog logger"
>               return false, m:format(fmt_num2str[ffi.C.SF_JSON])
>           end
>       end
> @@ -239,11 +248,11 @@ local verify_ops = {
>   }
>   
>   -- Verify a value for the particular key.
> -local function verify_option(k, v)
> +local function verify_option(k, v, ...)
>       assert(k ~= nil)
>   
>       if verify_ops[k] ~= nil then
> -        return verify_ops[k](k, v)
> +        return verify_ops[k](k, v, ...)
>       end
>   
>       return true
> @@ -372,10 +381,24 @@ local function box_api_cfg_get(key)
>   end
>   
>   -- Set value to log from box.cfg{}.
> -local function box_api_cfg_set(key, value)
> +local function box_api_cfg_set(cfg, key, value)
>       local log_key = box2log_keys[key]
> +    local aux_data
> +
> +    -- a special case where we need to restore
> +    -- nil value from previous setup attempt.
> +    if value == box.NULL then
> +        log_cfg[log_key] = nil
> +        return true
> +    end
> +
> +    -- 'format' option requires auxilary data
> +    -- for verification sake.
> +    if cfg ~= nil and log_key == 'format' then
> +        aux_data = cfg['log']
> +    end
>   

May be it's better to pass the whole "cfg" not single parameter to 
verify_ functions. I think it's more extendable.

Feel free to disagree with me, but I think that verify_format should 
extract "log" from configuration and consider them - it should not be 
done on top level.

> -    local ok, msg = verify_option(log_key, value)
> +    local ok, msg = verify_option(log_key, value, aux_data)
>       if not ok then
>           return false, msg
>       end
> @@ -450,7 +473,7 @@ local function load_cfg(oldcfg, cfg)
>       end
>   
>       if cfg.format ~= nil then
> -        local ok, msg = verify_option('format', cfg.format)
> +        local ok, msg = verify_option('format', cfg.format, cfg.log)
>           if not ok then
>               local m = "log.cfg: \'%s\' %s"
>               error(m:format('format', msg))

Re: [Tarantool-patches] [PATCH 2/3] lua/log: allow to use json formatter early

[Cyrill Gorcunov]

On Wed, Jul 01, 2020 at 01:01:43PM +0300, Oleg Babin wrote:
> 
> tarantool> log.cfg{log = ' syslog:identity=test', format = 'json'}
> IllegalParams: expecting a file name or a prefix, such as '|', 'pipe:',
> 'syslog:'
> failed to initialize logging subsystem
> 
> ```

File a bug please. Lets be clear -- our config parsing code is
far from being user friendly, hopefully we will make it more
convenient with time. I'm pretty sure that using lua language
for parsing config params was wrong from the very beginning
(especially when we start to allow config procedure via
modules and to sync data between box config and module config
we've to provide some internal "api", this is utter crap but
imposible to fix without remake of the whole config engine.
I expect we will do so eventually).

> 
> It should be a simple error but not panic. I've just add a space in log
> parameter.
> 
> At the same time:
> 
> ```
> 
> tarantool> box.cfg{log = ' syslog:'}
> ---
> - error: 'Incorrect value for option ''log'': expecting a file name or a
> prefix, such
>     as ''|'', ''pipe:'', ''syslog:'''
> ...
> 
> ```

Yup.

> > @@ -459,13 +459,13 @@ local function prepare_cfg(cfg, default_cfg, template_cfg,
> >                               module_cfg[k], modify_cfg[k], readable_name)
> >           elseif template_cfg[k] == 'module' then
> >               local old_value = module_cfg[k].cfg_get(k, v)
> > -            module_cfg_backup[k] = old_value
> > +            module_cfg_backup[k] = old_value or box.NULL
> 
> Could you please clarify this change? I see below you check "value ==
> box.NULL" but if value is simple nil then such condition is true.
> 
> ```

The key moment is that Lua treats box.NULL in a special way.

tarantool> a={log=box.NULL}
---
...

tarantool> a
---
- log: null
...

tarantool> a={log=nil}
---
...

tarantool> a
---
- []
...


IOW, when you set up some key to nil it gets vanished.
But when configuration fails I need to restore log=nil
if it were so (because setting cfg entries doesn't go
in one pass but instead one by one). Thus imagine we
set up log="syslog:" and made some mistake in format
key, I need to walk over backed up values and setup
them back.

> 
> tarantool> box.NULL == nil
> ---
> - true
> ...
> 
> tarantool> box.NULL == box.NULL
> ---
> - true
> ...
> 
> ```
> 
> Why is simple "nil" not enough?
> 
> > -            local ok, msg = module_cfg[k].cfg_set(k, v)
> > +            local ok, msg = module_cfg[k].cfg_set(cfg, k, v)
> >               if not ok then
> >                   -- restore back the old values for modules
> >                   for module_k, module_v in pairs(module_cfg_backup) do
> > -                    module_cfg[module_k].cfg_set(module_k, module_v)
> > +                    module_cfg[module_k].cfg_set(nil, module_k, module_v)
> >                   end
> >                   box.error(box.error.CFG, readable_name, msg)
...
> >               end
> > +    local log_type = ffi.C.log_type()
> > +
> > +    -- When comes from log.cfg{} or box.cfg{}
> > +    -- initial call we might be asked to setup
> > +    -- syslog with json which is not allowed.
> > +    if init_str ~= nil then
> > +        if string.sub(init_str, 1, 7) == "syslog:" then
> > +            log_type = ffi.C.SAY_LOGGER_SYSLOG
> > +        end
> > +    end
> > +
> 
> I believe that string.startswith(str, 'syslog:') is better here than
> string.sub(...).

Indeed, thanks! I didn't know about this helper. Will update.

> > +
> > +    -- 'format' option requires auxilary data
> > +    -- for verification sake.
> > +    if cfg ~= nil and log_key == 'format' then
> > +        aux_data = cfg['log']
> > +    end
> 
> May be it's better to pass the whole "cfg" not single parameter to verify_
> functions. I think it's more extendable.
> 
> Feel free to disagree with me, but I think that verify_format should extract
> "log" from configuration and consider them - it should not be done on top
> level.

Sounds reasonable, I'll take a look, thanks!

Re: [Tarantool-patches] [PATCH 2/3] lua/log: allow to use json formatter early

[Oleg Babin]

Hi! Thanks for your answers.

On 02/07/2020 10:27, Cyrill Gorcunov wrote:
> On Wed, Jul 01, 2020 at 01:01:43PM +0300, Oleg Babin wrote:
>> tarantool> log.cfg{log = ' syslog:identity=test', format = 'json'}
>> IllegalParams: expecting a file name or a prefix, such as '|', 'pipe:',
>> 'syslog:'
>> failed to initialize logging subsystem
>>
>> ```
> File a bug please. Lets be clear -- our config parsing code is
> far from being user friendly, hopefully we will make it more
> convenient with time. I'm pretty sure that using lua language
> for parsing config params was wrong from the very beginning
> (especially when we start to allow config procedure via
> modules and to sync data between box config and module config
> we've to provide some internal "api", this is utter crap but
> imposible to fix without remake of the whole config engine.
> I expect we will do so eventually).
https://github.com/tarantool/tarantool/issues/5130
>> It should be a simple error but not panic. I've just add a space in log
>> parameter.
>>
>> At the same time:
>>
>> ```
>>
>> tarantool> box.cfg{log = ' syslog:'}
>> ---
>> - error: 'Incorrect value for option ''log'': expecting a file name or a
>> prefix, such
>>      as ''|'', ''pipe:'', ''syslog:'''
>> ...
>>
>> ```
> Yup.
>
>>> @@ -459,13 +459,13 @@ local function prepare_cfg(cfg, default_cfg, template_cfg,
>>>                                module_cfg[k], modify_cfg[k], readable_name)
>>>            elseif template_cfg[k] == 'module' then
>>>                local old_value = module_cfg[k].cfg_get(k, v)
>>> -            module_cfg_backup[k] = old_value
>>> +            module_cfg_backup[k] = old_value or box.NULL
>> Could you please clarify this change? I see below you check "value ==
>> box.NULL" but if value is simple nil then such condition is true.
>>
>> ```
> The key moment is that Lua treats box.NULL in a special way.
>
> tarantool> a={log=box.NULL}
> ---
> ...
>
> tarantool> a
> ---
> - log: null
> ...
>
> tarantool> a={log=nil}
> ---
> ...
>
> tarantool> a
> ---
> - []
> ...
>
>
> IOW, when you set up some key to nil it gets vanished.
> But when configuration fails I need to restore log=nil
> if it were so (because setting cfg entries doesn't go
> in one pass but instead one by one). Thus imagine we
> set up log="syslog:" and made some mistake in format
> key, I need to walk over backed up values and setup
> them back.
Thanks for the explanation.

[Tarantool-patches] [PATCH 3/3] test: app-tap/logger -- test json in boottime logger

[Cyrill Gorcunov]

Make sure we're allowed to setup json formatter before
box.cfg() call, ie that named boot-time logger.

Part-of #5121

Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 test/app-tap/logger.test.lua | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
index ae4a3b99a..41276c3d0 100755
--- a/test/app-tap/logger.test.lua
+++ b/test/app-tap/logger.test.lua
@@ -3,11 +3,13 @@
 local test = require('tap').test('log')
 test:plan(62)
 
--- gh-3946: Assertion failure when using log_format() before box.cfg()
+--
+-- gh-5121: Allow to use 'json' output before box.cfg()
+--
 local log = require('log')
-log.log_format('plain')
 _, err = pcall(log.log_format, 'json')
-test:ok(err:find("json can\'t be used") ~= nil)
+test:ok(err == nil)
+log.log_format('plain')
 
 --
 -- gh-689: various settings change from box.cfg/log.cfg interfaces
-- 
2.26.2