[Tarantool-patches] [PATCH v7 00/11] lua/log: add an ability to setup logger without box.cfg{}

[Tarantool-patches] [PATCH v7 00/11] lua/log: add an ability to setup logger without box.cfg{}

[Cyrill Gorcunov]

In the series we add an ability to configure logger early
without calling box.cfg{}. The syntax is the same as
in box.cfg{} call.

There was an idea to implement something similar via triggers but
I think this will require a way more efforts and code redesign,
so at first lets stick to simplier solution.

v2 by Oleg:
 - hide box_api symbols from users
 - initialize logger via log.cfg() call to look similar to box.cfg
v3 by Oleg:
 - add parametesr verification
 - allow to reconfig via log.cfg() call
v4 by Oleg:
 - lua style fixes
 - extent test (I didn't find a way to test wrong params verification
   inside tap test, so I did it manually. Still we might extent the
   test on top of the series).
v5..v6:
 - left for internal use
v7 by Oleg and Leonid:
 - add bidirectional sync between log and box settings
 - symbolic names for levels
 - test extension
 - reduce ffi usage

branch gorcunov/gh-689-logger-7
issue https://github.com/tarantool/tarantool/issues/689

Cyrill Gorcunov (11):
  core/say: do not reconfig early set up logger
  core/say: use say_logger_initialized in say_logger_free
  lua/log: declare say_logger_init and say_logger_initialized
  lua/log: put string constants to map
  lua/log: do not allow to set json for boot logger
  lua/log: declare log as separate variable
  lua/log: use log module settings inside box.cfg
  lua/log: allow to configure logging without a box
  test: use direct log module
  log/lua: allow to specify logging level as a string
  lua/log: use log_cfg instead of ffi's instances

 src/box/lua/load_cfg.lua     |  26 +++-
 src/lib/core/say.c           |  15 +-
 src/lib/core/say.h           |   4 +
 src/lua/log.lua              | 272 ++++++++++++++++++++++++++++++++---
 test/app-tap/logger.test.lua |  86 ++++++++++-
 5 files changed, 370 insertions(+), 33 deletions(-)

-- 
2.26.2

[Tarantool-patches] [PATCH v7 01/11] core/say: do not reconfig early set up logger

[Cyrill Gorcunov]

We gonna support logger configuration on its own
without requirement to call `box.cfg{}`. Thus lets
say_logger_init() to skip processing if we already
did.

Note it is preparatory for next patches. Currently
the init called once.

Part-of #689

Reviewed-by: Oleg Babin <olegrok@tarantool.org>
Reviewed-by: Leonid Vasiliev <lvasiliev@tarantool.org>
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lib/core/say.c | 13 +++++++++++++
 src/lib/core/say.h |  4 ++++
 2 files changed, 17 insertions(+)

diff --git a/src/lib/core/say.c b/src/lib/core/say.c
index e22089aac..d8f59fb9b 100644
--- a/src/lib/core/say.c
+++ b/src/lib/core/say.c
@@ -684,10 +684,23 @@ log_create(struct log *log, const char *init_str, int nonblock)
 	return 0;
 }
 
+bool
+say_logger_initialized(void)
+{
+	return log_default == &log_std;
+}
+
 void
 say_logger_init(const char *init_str, int level, int nonblock,
 		const char *format, int background)
 {
+	/*
+	 * The logger may be early configured
+	 * by hands without configuing the whole box.
+	 */
+	if (say_logger_initialized())
+		return;
+
 	if (log_create(&log_std, init_str, nonblock) < 0)
 		goto fail;
 
diff --git a/src/lib/core/say.h b/src/lib/core/say.h
index c50d7bbf4..857145465 100644
--- a/src/lib/core/say.h
+++ b/src/lib/core/say.h
@@ -274,6 +274,10 @@ say_logger_init(const char *init_str,
 		const char *log_format,
 		int background);
 
+/** Test if logger is initialized. */
+bool
+say_logger_initialized(void);
+
 /** Free default logger */
 void
 say_logger_free();
-- 
2.26.2

[Tarantool-patches] [PATCH v7 02/11] core/say: use say_logger_initialized in say_logger_free

[Cyrill Gorcunov]

To eliminate opencoded comparision.

Reviewed-by: Leonid Vasiliev <lvasiliev@tarantool.org>
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lib/core/say.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/lib/core/say.c b/src/lib/core/say.c
index d8f59fb9b..791011e6f 100644
--- a/src/lib/core/say.c
+++ b/src/lib/core/say.c
@@ -749,7 +749,7 @@ say_logger_init(const char *init_str, int level, int nonblock,
 void
 say_logger_free()
 {
-	if (log_default == &log_std)
+	if (say_logger_initialized())
 		log_destroy(&log_std);
 }
 
-- 
2.26.2

[Tarantool-patches] [PATCH v7 03/11] lua/log: declare say_logger_init and say_logger_initialized

[Cyrill Gorcunov]

We gonna use it to provide a way to initialize
logger subsystem early.

Part-of #689

Reviewed-by: Oleg Babin <olegrok@tarantool.org>
Reviewed-by: Leonid Vasiliev <lvasiliev@tarantool.org>
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lua/log.lua | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/src/lua/log.lua b/src/lua/log.lua
index 312c14d5e..23529b30e 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -22,6 +22,12 @@ ffi.cdef[[
     void
     say_set_log_format(enum say_format format);
 
+    extern void
+    say_logger_init(const char *init_str, int level, int nonblock,
+                    const char *format, int background);
+
+    extern bool
+    say_logger_initialized(void);
 
     extern sayfunc_t _say;
     extern struct ev_loop;
-- 
2.26.2

[Tarantool-patches] [PATCH v7 04/11] lua/log: put string constants to map

[Cyrill Gorcunov]

This allows us to reuse them instead of copying
opencoded constants. They are highly bound to
ones compiled into the C code.

Part-of #689

Reviewed-by: Oleg Babin <olegrok@tarantool.org>
Reviewed-by: Leonid Vasiliev <lvasiliev@tarantool.org>
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lua/log.lua | 35 +++++++++++++++++++++++++++++------
 1 file changed, 29 insertions(+), 6 deletions(-)

diff --git a/src/lua/log.lua b/src/lua/log.lua
index 23529b30e..94d8ca46c 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -81,6 +81,26 @@ local special_fields = {
     "error_msg"
 }
 
+-- Map format number to string.
+local fmt_num2str = {
+    [ffi.C.SF_PLAIN]    = "plain",
+    [ffi.C.SF_JSON]     = "json",
+}
+
+-- Map format string to number.
+local fmt_str2num = {
+    ["plain"]           = ffi.C.SF_PLAIN,
+    ["json"]            = ffi.C.SF_JSON,
+}
+
+local function fmt_list()
+    local keyset = {}
+    for k in pairs(fmt_str2num) do
+        keyset[#keyset + 1] = k
+    end
+    return table.concat(keyset, ',')
+end
+
 local function say(level, fmt, ...)
     if ffi.C.log_level < level then
         -- don't waste cycles on debug.getinfo()
@@ -102,7 +122,7 @@ local function say(level, fmt, ...)
         fmt = json.encode(fmt)
         if ffi.C.log_format == ffi.C.SF_JSON then
             -- indicate that message is already encoded in JSON
-            format = "json"
+            format = fmt_num2str[ffi.C.SF_JSON]
         end
     elseif type_fmt ~= 'string' then
         fmt = tostring(fmt)
@@ -133,16 +153,19 @@ local function log_level(level)
     return ffi.C.say_set_log_level(level)
 end
 
-local function log_format(format_name)
-    if format_name == "json" then
+local function log_format(name)
+    if not fmt_str2num[name] then
+        local m = "log_format: expected %s"
+        error(m:format(fmt_list()))
+    end
+
+    if fmt_str2num[name] == ffi.C.SF_JSON then
         if ffi.C.log_type() == ffi.C.SAY_LOGGER_SYSLOG then
             error("log_format: 'json' can't be used with syslog logger")
         end
         ffi.C.say_set_log_format(ffi.C.SF_JSON)
-    elseif format_name == "plain" then
-        ffi.C.say_set_log_format(ffi.C.SF_PLAIN)
     else
-        error("log_format: expected 'json' or 'plain'")
+        ffi.C.say_set_log_format(ffi.C.SF_PLAIN)
     end
 end
 
-- 
2.26.2

[Tarantool-patches] [PATCH v7 05/11] lua/log: do not allow to set json for boot logger

[Cyrill Gorcunov]

For some reason we've missed that say_set_log_format
doesn't support json format not only for syslog but
for boottime logging as well.

Part-of #689

Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lua/log.lua              | 7 +++++--
 test/app-tap/logger.test.lua | 5 +++--
 2 files changed, 8 insertions(+), 4 deletions(-)

diff --git a/src/lua/log.lua b/src/lua/log.lua
index 94d8ca46c..d5a99076d 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -160,8 +160,11 @@ local function log_format(name)
     end
 
     if fmt_str2num[name] == ffi.C.SF_JSON then
-        if ffi.C.log_type() == ffi.C.SAY_LOGGER_SYSLOG then
-            error("log_format: 'json' can't be used with syslog logger")
+        if ffi.C.log_type() == ffi.C.SAY_LOGGER_SYSLOG or
+            ffi.C.log_type() == ffi.C.SAY_LOGGER_BOOT then
+            local m = "log_format: %s can't be used with " ..
+                    "syslog or boot-time logger"
+            error(m:format(fmt_num2str[ffi.C.SF_JSON]))
         end
         ffi.C.say_set_log_format(ffi.C.SF_JSON)
     else
diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
index 492d5ea0b..676c860d3 100755
--- a/test/app-tap/logger.test.lua
+++ b/test/app-tap/logger.test.lua
@@ -1,12 +1,13 @@
 #!/usr/bin/env tarantool
 
 local test = require('tap').test('log')
-test:plan(24)
+test:plan(25)
 
 -- gh-3946: Assertion failure when using log_format() before box.cfg()
 local log = require('log')
-log.log_format('json')
 log.log_format('plain')
+_,err = pcall(log, {log_format = 'json'})
+test:ok(err ~= nil)
 
 --
 -- Check that Tarantool creates ADMIN session for #! script
-- 
2.26.2

[Tarantool-patches] [PATCH v7 06/11] lua/log: declare log as separate variable

[Cyrill Gorcunov]

We gonna hide some internal symbols in sake
of communication with box module, thus lets
make it clear.

Part-of #689

Reviewed-by: Oleg Babin <olegrok@tarantool.org>
Reviewed-by: Leonid Vasiliev <lvasiliev@tarantool.org>
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lua/log.lua | 26 +++++++++++++++-----------
 1 file changed, 15 insertions(+), 11 deletions(-)

diff --git a/src/lua/log.lua b/src/lua/log.lua
index d5a99076d..746e0d82f 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -187,16 +187,20 @@ local compat_v16 = {
     end;
 }
 
-return setmetatable({
-    warn = say_closure(S_WARN);
-    info = say_closure(S_INFO);
-    verbose = say_closure(S_VERBOSE);
-    debug = say_closure(S_DEBUG);
-    error = say_closure(S_ERROR);
-    rotate = log_rotate;
-    pid = log_pid;
-    level = log_level;
-    log_format = log_format;
-}, {
+local log = {
+    warn = say_closure(S_WARN),
+    info = say_closure(S_INFO),
+    verbose = say_closure(S_VERBOSE),
+    debug = say_closure(S_DEBUG),
+    error = say_closure(S_ERROR),
+    rotate = log_rotate,
+    pid = log_pid,
+    level = log_level,
+    log_format = log_format,
+}
+
+setmetatable(log, {
     __index = compat_v16;
 })
+
+return log
-- 
2.26.2

[Tarantool-patches] [PATCH v7 07/11] lua/log: use log module settings inside box.cfg

[Cyrill Gorcunov]

Currently box module carries configuration settings in box.cfg
variable which is created dinamically on demand.

The default values are kept in default_cfg variable. Since we're
going to make the log module to work on its own, we need it to
provide default settings to the box.cfg interface.

For this sake we export log:box_api table which the main box
module use when needed.

Part-of #689

Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/box/lua/load_cfg.lua | 26 ++++++++++++++----
 src/lua/log.lua          | 59 +++++++++++++++++++++++++++++++++++++++-
 2 files changed, 78 insertions(+), 7 deletions(-)

diff --git a/src/box/lua/load_cfg.lua b/src/box/lua/load_cfg.lua
index 5d818addf..7612deb90 100644
--- a/src/box/lua/load_cfg.lua
+++ b/src/box/lua/load_cfg.lua
@@ -59,10 +59,6 @@ local default_cfg = {
     vinyl_range_size          = nil, -- set automatically
     vinyl_page_size           = 8 * 1024,
     vinyl_bloom_fpr           = 0.05,
-    log                 = nil,
-    log_nonblock        = nil,
-    log_level           = 5,
-    log_format          = "plain",
     io_collect_interval = nil,
     readahead           = 16320,
     snap_io_rate_limit  = nil, -- no limit
@@ -233,8 +229,8 @@ end
 local dynamic_cfg = {
     listen                  = private.cfg_set_listen,
     replication             = private.cfg_set_replication,
-    log_level               = private.cfg_set_log_level,
-    log_format              = private.cfg_set_log_format,
+    log_level               = log.box_api.set_log_level,
+    log_format              = log.box_api.set_log_format,
     io_collect_interval     = private.cfg_set_io_collect_interval,
     readahead               = private.cfg_set_readahead,
     too_long_threshold      = private.cfg_set_too_long_threshold,
@@ -470,6 +466,21 @@ local function apply_default_cfg(cfg, default_cfg)
     end
 end
 
+-- Fetch default settings from modules.
+local function modules_apply_default_cfg(cfg)
+    log.box_api.on_apply_default_cfg(cfg)
+end
+
+-- Propagate settings to modules.
+local function modules_load_cfg(cfg)
+    log.box_api.on_load_cfg(cfg)
+end
+
+-- Propagate settings to modules.
+local function modules_reload_cfg(cfg)
+    log.box_api.on_reload_cfg(cfg)
+end
+
 -- Return true if two configurations are equivalent.
 local function compare_cfg(cfg1, cfg2)
     if type(cfg1) ~= type(cfg2) then
@@ -517,6 +528,7 @@ local function reload_cfg(oldcfg, cfg)
                 json.encode(val))
         end
     end
+    modules_reload_cfg(cfg)
     if type(box.on_reload_configuration) == 'function' then
         box.on_reload_configuration()
     end
@@ -554,6 +566,7 @@ local function load_cfg(cfg)
     cfg = upgrade_cfg(cfg, translate_cfg)
     cfg = prepare_cfg(cfg, default_cfg, template_cfg, modify_cfg)
     apply_default_cfg(cfg, default_cfg);
+    modules_apply_default_cfg(cfg)
     -- Save new box.cfg
     box.cfg = cfg
     if not pcall(private.cfg_check)  then
@@ -573,6 +586,7 @@ local function load_cfg(cfg)
             end,
             __call = locked(reload_cfg),
         })
+    modules_load_cfg(box.cfg)
     private.cfg_load()
     for key, fun in pairs(dynamic_cfg) do
         local val = cfg[key]
diff --git a/src/lua/log.lua b/src/lua/log.lua
index 746e0d82f..33e98fd84 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -101,6 +101,24 @@ local function fmt_list()
     return table.concat(keyset, ',')
 end
 
+-- Default options. The keys are part of
+-- user API, so change with caution.
+local log_cfg = {
+    log             = nil,
+    nonblock        = nil,
+    level           = S_INFO,
+    format          = fmt_num2str[ffi.C.SF_PLAIN],
+}
+
+-- Name mapping from box to log module.
+-- Make sure all required fields are covered!
+local log2box_keys = {
+    ['log']         = 'log',
+    ['nonblock']    = 'log_nonblock',
+    ['level']       = 'log_level',
+    ['format']      = 'log_format',
+}
+
 local function say(level, fmt, ...)
     if ffi.C.log_level < level then
         -- don't waste cycles on debug.getinfo()
@@ -150,7 +168,8 @@ local function log_rotate()
 end
 
 local function log_level(level)
-    return ffi.C.say_set_log_level(level)
+    ffi.C.say_set_log_level(level)
+    rawset(log_cfg, 'level', level)
 end
 
 local function log_format(name)
@@ -170,12 +189,31 @@ local function log_format(name)
     else
         ffi.C.say_set_log_format(ffi.C.SF_PLAIN)
     end
+    rawset(log_cfg, 'format', name)
 end
 
 local function log_pid()
     return tonumber(ffi.C.log_pid)
 end
 
+-- Apply defaut config to the box module
+local function box_on_apply_default_cfg(box_cfg)
+    for k, v in pairs(log2box_keys) do
+        if box_cfg[v] == nil then
+            box_cfg[v] = log_cfg[k]
+        end
+    end
+end
+
+-- Update own values from box interface.
+local function box_on_load_cfg(box_cfg)
+    for k, v in pairs(log2box_keys) do
+        if box_cfg[v] ~= log_cfg[k] then
+            log_cfg[k] = box_cfg[v]
+        end
+    end
+end
+
 local compat_warning_said = false
 local compat_v16 = {
     logger_pid = function()
@@ -197,9 +235,28 @@ local log = {
     pid = log_pid,
     level = log_level,
     log_format = log_format,
+
+    -- Internal API to box module, not for users,
+    -- names can be changed.
+    box_api = {
+        set_log_level = function()
+            log_level(box.cfg.log_level)
+        end,
+        set_log_format = function()
+            log_format(box.cfg.log_format)
+        end,
+        on_load_cfg = box_on_load_cfg,
+        on_reload_cfg = box_on_load_cfg,
+        on_apply_default_cfg = box_on_apply_default_cfg,
+    },
 }
 
 setmetatable(log, {
+    __serialize = function(self)
+        local res = table.copy(self)
+        res.box_api = nil
+        return setmetatable(res, {})
+    end,
     __index = compat_v16;
 })
 
-- 
2.26.2

[Tarantool-patches] [PATCH v7 08/11] lua/log: allow to configure logging without a box

[Cyrill Gorcunov]

We bring in an ability to configure logger early without
calling box.cfg{}. For this sake log.cfg({}) becomes a
callable table. One can provide arguments of the looger
which later will be propagated back to box.cfg table on
demand.

Another notable change is that the settings in log module
become defaults value, thus if one configured log before
the box then new settings get propagated to box's default
logging settings (previously they are silently reset to
defaults).

Fixes #689

@TarantoolBot documnent
Title: Module log

To configure log module eary without initializing box module
at all call the `log.cfg({})` method, where the following
arguments are acceptable:

 - `log` to specify file, pipe or syslog (same as
   `box.cfg{log}` option); the default value is nil
   and stderr is used;

 - `level` to specify logging level (1-7); the default
   value is 5;

 - `format` to specify output encoding ('plain' or 'json');
   the default value is 'plain';

 - `nonblock` to open logging output in nonblocking mode
   (`true` or `false`); the default value is `false`.

Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lua/log.lua | 105 +++++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 104 insertions(+), 1 deletion(-)

diff --git a/src/lua/log.lua b/src/lua/log.lua
index 33e98fd84..dfdc326fe 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -119,6 +119,27 @@ local log2box_keys = {
     ['format']      = 'log_format',
 }
 
+local box_module_cfg = nil
+
+-- Reflect changes in box.cfg (if
+-- box.cfg been initialized).
+local function update_box_cfg(k)
+    if box_module_cfg ~= nil then
+        local update = function(k, v)
+            if box_module_cfg[v] ~= log_cfg[k] then
+                box_module_cfg[v] = log_cfg[k]
+            end
+        end
+        if k ~= nil then
+            update(k, log2box_keys[k])
+        else
+            for k, v in pairs(log2box_keys) do
+                update(k, v)
+            end
+        end
+    end
+end
+
 local function say(level, fmt, ...)
     if ffi.C.log_level < level then
         -- don't waste cycles on debug.getinfo()
@@ -170,6 +191,7 @@ end
 local function log_level(level)
     ffi.C.say_set_log_level(level)
     rawset(log_cfg, 'level', level)
+    update_box_cfg('level')
 end
 
 local function log_format(name)
@@ -190,6 +212,7 @@ local function log_format(name)
         ffi.C.say_set_log_format(ffi.C.SF_PLAIN)
     end
     rawset(log_cfg, 'format', name)
+    update_box_cfg('format')
 end
 
 local function log_pid()
@@ -208,10 +231,87 @@ end
 -- Update own values from box interface.
 local function box_on_load_cfg(box_cfg)
     for k, v in pairs(log2box_keys) do
-        if box_cfg[v] ~= log_cfg[k] then
+        if box_cfg[v] ~= nil and box_cfg[v] ~= log_cfg[k] then
             log_cfg[k] = box_cfg[v]
         end
     end
+    -- Remember the backreference to box
+    -- module config table.
+    box_module_cfg = box_cfg
+end
+
+local params_once = {
+    'log',
+    'log_nonblock',
+}
+
+-- Setup dynamic parameters.
+local function dynamic_cfg(cfg)
+    for _, k in pairs(params_once) do
+        if cfg[k] ~= nil and cfg[k] ~= log_cfg[k] then
+            local m = "log: '%s' can't be set dynamically"
+            error(m:format(k))
+        end
+    end
+
+    if cfg.level ~= nil then
+        log_level(cfg.level)
+    end
+
+    if cfg.format ~= nil then
+        log_format(cfg.format)
+    end
+
+    -- The log_x helpers above update box
+    -- settings on their own, so no need
+    -- for more update_box_cfg calls.
+end
+
+-- Load or reload configuration via log.cfg({}) call.
+local function load_cfg(oldcfg, cfg)
+    cfg = cfg or {}
+
+    if cfg.format ~= nil then
+        if fmt_str2num[cfg.format] == nil then
+            local m = "log: 'format' must be %s"
+            error(m:format(fmt_list()))
+        end
+    end
+
+    if cfg.level ~= nil then
+        if type(cfg.level) ~= 'number' then
+            error("log: 'level' option must be a number")
+        end
+    end
+
+    if cfg.nonblock ~= nil then
+        if type(cfg.nonblock) ~= 'boolean' then
+            error("log: 'nonblock' option must be 'true' or 'false'")
+        end
+    end
+
+    if ffi.C.say_logger_initialized() == true then
+        return dynamic_cfg(cfg)
+    end
+
+    cfg.level = cfg.level or log_cfg.level
+    cfg.format = cfg.format or log_cfg.format
+    cfg.nonblock = cfg.nonblock or (log_cfg.nonblock or false)
+
+    -- We never allow confgure the logger in background
+    -- mode since we don't know how the box will be configured
+    -- later.
+    ffi.C.say_logger_init(cfg.log, cfg.level,
+                          cfg.nonblock, cfg.format, 0)
+
+    -- Update log_cfg vars to show them in module
+    -- configuration output.
+    rawset(log_cfg, 'log', cfg.log)
+    rawset(log_cfg, 'level', cfg.level)
+    rawset(log_cfg, 'nonblock', cfg.nonblock)
+    rawset(log_cfg, 'format', cfg.format)
+
+    update_box_cfg()
 end
 
 local compat_warning_said = false
@@ -235,6 +335,9 @@ local log = {
     pid = log_pid,
     level = log_level,
     log_format = log_format,
+    cfg = setmetatable(log_cfg, {
+        __call = load_cfg,
+    }),
 
     -- Internal API to box module, not for users,
     -- names can be changed.
-- 
2.26.2

[Tarantool-patches] [PATCH v7 09/11] test: use direct log module

[Cyrill Gorcunov]

To test if we can setup logging module before the box.cfg{}.

Part-of #689

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

diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
index 676c860d3..c6f207908 100755
--- a/test/app-tap/logger.test.lua
+++ b/test/app-tap/logger.test.lua
@@ -1,7 +1,7 @@
 #!/usr/bin/env tarantool
 
 local test = require('tap').test('log')
-test:plan(25)
+test:plan(34)
 
 -- gh-3946: Assertion failure when using log_format() before box.cfg()
 local log = require('log')
@@ -10,16 +10,66 @@ _,err = pcall(log, {log_format = 'json'})
 test:ok(err ~= nil)
 
 --
--- Check that Tarantool creates ADMIN session for #! script
+-- gh-689: Operate with logger via log module without calling box.cfg{}
 --
+local json = require('json')
 local filename = "1.log"
+
+-- Test json output
+log.cfg({log=filename, format='json', level=5})
+local m = "info message"
+
+local file = io.open(filename)
+while file:read() do
+end
+
+log.info(m)
+local line = file:read()
+local message = json.decode(line)
+file:close()
+
+test:is(type(message), 'table', "(log) json valid in log.info")
+test:is(message.level, "INFO", "(log) check type info")
+test:is(message.message, m, "(log) check message content")
+
+-- Test runtime change to plain format
+log.log_format('plain')
+local file = io.open(filename)
+while file:read() do
+end
+log.info(m)
+local line = file:read()
+file:close()
+test:is(line:sub(-m:len()), m, m)
+
+-- Test wrong arguments
+_, err = pcall(log.cfg, {format = 'unknown'})
+test:ok(err ~= nil)
+
+-- Test that changes in log module are propagated
+-- back to the box module correctly
+box.cfg{
+    log=filename,
+    log_format='json',
+    log_level=6,
+    memtx_memory=107374182,
+}
+test:is(box.cfg.log_format, 'json', 'box in json format')
+test:is(box.cfg.log_level, 6, 'box level 6')
+log.cfg({format='plain', level=5})
+test:is(box.cfg.log_format, 'plain', 'box sees plain format')
+test:is(box.cfg.log_level, 5, 'box sees level change')
+
+--
+-- Check that Tarantool creates ADMIN session for #! script
+--
 local message = "Hello, World!"
 box.cfg{
     log=filename,
+    log_format='plain',
     memtx_memory=107374182,
 }
 local fio = require('fio')
-local json = require('json')
 local fiber = require('fiber')
 local file = io.open(filename)
 while file:read() do
-- 
2.26.2

[Tarantool-patches] [PATCH v7 10/11] log/lua: allow to specify logging level as a string

[Cyrill Gorcunov]

Allow to specify logging level as a string in log.cfg() call.

@TarantoolBot document
Title: Module log

The `log.cfg({level='string'})` accepts not only number but
symbolic repreentation of loglevels such as: `fatal`, `syserror`,
`error`, `crit`, `warn`, `info`, `verbose` and `debug`.

Part-of #689

Suggested-by: Oleg Babin <olegrok@tarantool.org>
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lua/log.lua              | 36 ++++++++++++++++++++++++++++++++++--
 test/app-tap/logger.test.lua | 29 ++++++++++++++++++++++++++++-
 2 files changed, 62 insertions(+), 3 deletions(-)

diff --git a/src/lua/log.lua b/src/lua/log.lua
index dfdc326fe..3376932ff 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -140,6 +140,26 @@ local function update_box_cfg(k)
     end
 end
 
+-- Logging levels symbolic representation.
+local log_level_keys = {
+    ['fatal']       = ffi.C.S_FATAL,
+    ['syserror']    = ffi.C.S_SYSERROR,
+    ['error']       = ffi.C.S_ERROR,
+    ['crit']        = ffi.C.S_CRIT,
+    ['warn']        = ffi.C.S_WARN,
+    ['info']        = ffi.C.S_INFO,
+    ['verbose']     = ffi.C.S_VERBOSE,
+    ['debug']       = ffi.C.S_DEBUG,
+}
+
+local function log_level_list()
+    local keyset = {}
+    for k in pairs(log_level_keys) do
+        keyset[#keyset + 1] = k
+    end
+    return table.concat(keyset, ',')
+end
+
 local function say(level, fmt, ...)
     if ffi.C.log_level < level then
         -- don't waste cycles on debug.getinfo()
@@ -279,8 +299,20 @@ local function load_cfg(oldcfg, cfg)
     end
 
     if cfg.level ~= nil then
-        if type(cfg.level) ~= 'number' then
-            error("log: 'level' option must be a number")
+        if type(cfg.level) == 'number' then
+            if cfg.level < ffi.C.S_FATAL or
+                cfg.level > ffi.C.S_DEBUG then
+                local m = "log: 'level' must be in range [%d;%d]"
+                error(m:format(ffi.C.S_FATAL, ffi.C.S_DEBUG))
+            end
+        elseif type(cfg.level) == 'string' then
+            if log_level_keys[cfg.level] == nil then
+                local m = "log: 'level' must be one of [%s]"
+                error(m:format(log_level_list()))
+            end
+            cfg.level = log_level_keys[cfg.level]
+        else
+            error("log: 'level' must be a number or string")
         end
     end
 
diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
index c6f207908..557c31f1a 100755
--- a/test/app-tap/logger.test.lua
+++ b/test/app-tap/logger.test.lua
@@ -1,7 +1,7 @@
 #!/usr/bin/env tarantool
 
 local test = require('tap').test('log')
-test:plan(34)
+test:plan(44)
 
 -- gh-3946: Assertion failure when using log_format() before box.cfg()
 local log = require('log')
@@ -60,6 +60,33 @@ log.cfg({format='plain', level=5})
 test:is(box.cfg.log_format, 'plain', 'box sees plain format')
 test:is(box.cfg.log_level, 5, 'box sees level change')
 
+-- Test symbolic names for loglevels
+log.cfg({level='fatal'})
+test:ok(log.cfg.level == 0 and box.cfg.log_level == 0, 'both sees fatal')
+log.cfg({level='syserror'})
+test:ok(log.cfg.level == 1 and box.cfg.log_level == 1, 'both sees fatal')
+log.cfg({level='error'})
+test:ok(log.cfg.level == 2 and box.cfg.log_level == 2, 'both sees fatal')
+log.cfg({level='crit'})
+test:ok(log.cfg.level == 3 and box.cfg.log_level == 3, 'both sees fatal')
+log.cfg({level='warn'})
+test:ok(log.cfg.level == 4 and box.cfg.log_level == 4, 'both sees fatal')
+log.cfg({level='info'})
+test:ok(log.cfg.level == 5 and box.cfg.log_level == 5, 'both sees fatal')
+log.cfg({level='verbose'})
+test:ok(log.cfg.level == 6 and box.cfg.log_level == 6, 'both sees fatal')
+log.cfg({level='debug'})
+test:ok(log.cfg.level == 7 and box.cfg.log_level == 7, 'both sees fatal')
+
+_,err = pcall(log, {level = -1})
+test:ok(err ~= nil, 'level = -1 error')
+
+_,err = pcall(log, {level = 'unknown'})
+test:ok(err ~= nil, "level = 'unknown' error")
+
+-- restore to info for next tests
+log.cfg({level='info'})
+
 --
 -- Check that Tarantool creates ADMIN session for #! script
 --
-- 
2.26.2

[Tarantool-patches] [PATCH v7 11/11] lua/log: use log_cfg instead of ffi's instances

[Cyrill Gorcunov]

To reduce number of ffi calls.

Part-of #689

Suggested-by: Leonid Vasiliev <lvasiliev@tarantool.org>
Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
---
 src/lua/log.lua | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/lua/log.lua b/src/lua/log.lua
index 3376932ff..7ca206989 100644
--- a/src/lua/log.lua
+++ b/src/lua/log.lua
@@ -161,7 +161,7 @@ local function log_level_list()
 end
 
 local function say(level, fmt, ...)
-    if ffi.C.log_level < level then
+    if log_cfg.level < level then
         -- don't waste cycles on debug.getinfo()
         return
     end
@@ -179,7 +179,7 @@ local function say(level, fmt, ...)
             fmt[field] = nil
         end
         fmt = json.encode(fmt)
-        if ffi.C.log_format == ffi.C.SF_JSON then
+        if log_cfg.format == fmt_num2str[ffi.C.SF_JSON] then
             -- indicate that message is already encoded in JSON
             format = fmt_num2str[ffi.C.SF_JSON]
         end
-- 
2.26.2

Re: [Tarantool-patches] [PATCH v7 02/11] core/say: use say_logger_initialized in say_logger_free

[Oleg Babin]

LGTM

On 02/06/2020 01:24, Cyrill Gorcunov wrote:
> To eliminate opencoded comparision.
> 
> Reviewed-by: Leonid Vasiliev <lvasiliev@tarantool.org>
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
>   src/lib/core/say.c | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/src/lib/core/say.c b/src/lib/core/say.c
> index d8f59fb9b..791011e6f 100644
> --- a/src/lib/core/say.c
> +++ b/src/lib/core/say.c
> @@ -749,7 +749,7 @@ say_logger_init(const char *init_str, int level, int nonblock,
>   void
>   say_logger_free()
>   {
> -	if (log_default == &log_std)
> +	if (say_logger_initialized())
>   		log_destroy(&log_std);
>   }
>   
> 

Re: [Tarantool-patches] [PATCH v7 05/11] lua/log: do not allow to set json for boot logger

[Oleg Babin]

Hi. Thanks for your patch see one comment.

On 02/06/2020 01:25, Cyrill Gorcunov wrote:
> pcall(log, {log_format = 'json'})

It seems to be incorrect.

```
tarantool> pcall(log, {log_format = 'json'})
---
- false
- attempt to call a table value
...
```

And it should be
```
tarantool> pcall(log.log_format, 'json')
---
- false
- 'builtin/log.lua:228: log_format: json can''t be used with syslog or 
boot-time logger'
...
```

Also please check error message. Smth like:
```
err:find('log_format: json can\'t be used with syslog or boot%-time 
logger') ~= nil
```

Re: [Tarantool-patches] [PATCH v7 07/11] lua/log: use log module settings inside box.cfg

[Oleg Babin]

Hi! Thanks for your patch.

I've found a strange case:
```
tarantool> log.cfg({log = '1.txt'})
---
...

tarantool> log.cfg({log = '2.txt'}) -- error - OK
---
- error: 'builtin/log.lua:273: log: ''log'' can''t be set dynamically'
...

tarantool> box.cfg{log = '2.txt'} -- no error (why?)
---
...

tarantool> log.error('test')
---
...
```

log.cfg and box.cfg shows:
```
tarantool> log.cfg.log
---
- 2.txt
...

tarantool> box.cfg.log
---
- 2.txt
...
```

But actually "1.txt" is my log file.
Also I suggest to cover such situation with a test :)

On 02/06/2020 01:25, Cyrill Gorcunov wrote:
> Currently box module carries configuration settings in box.cfg
> variable which is created dinamically on demand.
> 
> The default values are kept in default_cfg variable. Since we're
> going to make the log module to work on its own, we need it to
> provide default settings to the box.cfg interface.
> 
> For this sake we export log:box_api table which the main box
> module use when needed.
> 
> Part-of #689
> 
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
>   src/box/lua/load_cfg.lua | 26 ++++++++++++++----
>   src/lua/log.lua          | 59 +++++++++++++++++++++++++++++++++++++++-
>   2 files changed, 78 insertions(+), 7 deletions(-)
> 
> diff --git a/src/box/lua/load_cfg.lua b/src/box/lua/load_cfg.lua
> index 5d818addf..7612deb90 100644
> --- a/src/box/lua/load_cfg.lua
> +++ b/src/box/lua/load_cfg.lua
> @@ -59,10 +59,6 @@ local default_cfg = {
>       vinyl_range_size          = nil, -- set automatically
>       vinyl_page_size           = 8 * 1024,
>       vinyl_bloom_fpr           = 0.05,
> -    log                 = nil,
> -    log_nonblock        = nil,
> -    log_level           = 5,
> -    log_format          = "plain",
>       io_collect_interval = nil,
>       readahead           = 16320,
>       snap_io_rate_limit  = nil, -- no limit
> @@ -233,8 +229,8 @@ end
>   local dynamic_cfg = {
>       listen                  = private.cfg_set_listen,
>       replication             = private.cfg_set_replication,
> -    log_level               = private.cfg_set_log_level,
> -    log_format              = private.cfg_set_log_format,
> +    log_level               = log.box_api.set_log_level,
> +    log_format              = log.box_api.set_log_format,
>       io_collect_interval     = private.cfg_set_io_collect_interval,
>       readahead               = private.cfg_set_readahead,
>       too_long_threshold      = private.cfg_set_too_long_threshold,
> @@ -470,6 +466,21 @@ local function apply_default_cfg(cfg, default_cfg)
>       end
>   end
>   
> +-- Fetch default settings from modules.
> +local function modules_apply_default_cfg(cfg)
> +    log.box_api.on_apply_default_cfg(cfg)
> +end
> +
> +-- Propagate settings to modules.
> +local function modules_load_cfg(cfg)
> +    log.box_api.on_load_cfg(cfg)
> +end
> +
> +-- Propagate settings to modules.
> +local function modules_reload_cfg(cfg)
> +    log.box_api.on_reload_cfg(cfg)
> +end
> +
>   -- Return true if two configurations are equivalent.
>   local function compare_cfg(cfg1, cfg2)
>       if type(cfg1) ~= type(cfg2) then
> @@ -517,6 +528,7 @@ local function reload_cfg(oldcfg, cfg)
>                   json.encode(val))
>           end
>       end
> +    modules_reload_cfg(cfg)
>       if type(box.on_reload_configuration) == 'function' then
>           box.on_reload_configuration()
>       end
> @@ -554,6 +566,7 @@ local function load_cfg(cfg)
>       cfg = upgrade_cfg(cfg, translate_cfg)
>       cfg = prepare_cfg(cfg, default_cfg, template_cfg, modify_cfg)
>       apply_default_cfg(cfg, default_cfg);
> +    modules_apply_default_cfg(cfg)
>       -- Save new box.cfg
>       box.cfg = cfg
>       if not pcall(private.cfg_check)  then
> @@ -573,6 +586,7 @@ local function load_cfg(cfg)
>               end,
>               __call = locked(reload_cfg),
>           })
> +    modules_load_cfg(box.cfg)
>       private.cfg_load()
>       for key, fun in pairs(dynamic_cfg) do
>           local val = cfg[key]
> diff --git a/src/lua/log.lua b/src/lua/log.lua
> index 746e0d82f..33e98fd84 100644
> --- a/src/lua/log.lua
> +++ b/src/lua/log.lua
> @@ -101,6 +101,24 @@ local function fmt_list()
>       return table.concat(keyset, ',')
>   end
>   
> +-- Default options. The keys are part of
> +-- user API, so change with caution.
> +local log_cfg = {
> +    log             = nil,
> +    nonblock        = nil,
> +    level           = S_INFO,
> +    format          = fmt_num2str[ffi.C.SF_PLAIN],
> +}
> +
> +-- Name mapping from box to log module.
> +-- Make sure all required fields are covered!
> +local log2box_keys = {
> +    ['log']         = 'log',
> +    ['nonblock']    = 'log_nonblock',
> +    ['level']       = 'log_level',
> +    ['format']      = 'log_format',
> +}
> +
>   local function say(level, fmt, ...)
>       if ffi.C.log_level < level then
>           -- don't waste cycles on debug.getinfo()
> @@ -150,7 +168,8 @@ local function log_rotate()
>   end
>   
>   local function log_level(level)
> -    return ffi.C.say_set_log_level(level)
> +    ffi.C.say_set_log_level(level)
> +    rawset(log_cfg, 'level', level)
>   end
>   
>   local function log_format(name)
> @@ -170,12 +189,31 @@ local function log_format(name)
>       else
>           ffi.C.say_set_log_format(ffi.C.SF_PLAIN)
>       end
> +    rawset(log_cfg, 'format', name)
>   end
>   
>   local function log_pid()
>       return tonumber(ffi.C.log_pid)
>   end
>   
> +-- Apply defaut config to the box module
> +local function box_on_apply_default_cfg(box_cfg)
> +    for k, v in pairs(log2box_keys) do
> +        if box_cfg[v] == nil then
> +            box_cfg[v] = log_cfg[k]
> +        end
> +    end
> +end
> +
> +-- Update own values from box interface.
> +local function box_on_load_cfg(box_cfg)
> +    for k, v in pairs(log2box_keys) do
> +        if box_cfg[v] ~= log_cfg[k] then
> +            log_cfg[k] = box_cfg[v]
> +        end
> +    end
> +end
> +
>   local compat_warning_said = false
>   local compat_v16 = {
>       logger_pid = function()
> @@ -197,9 +235,28 @@ local log = {
>       pid = log_pid,
>       level = log_level,
>       log_format = log_format,
> +
> +    -- Internal API to box module, not for users,
> +    -- names can be changed.
> +    box_api = {
> +        set_log_level = function()
> +            log_level(box.cfg.log_level)
> +        end,
> +        set_log_format = function()
> +            log_format(box.cfg.log_format)
> +        end,
> +        on_load_cfg = box_on_load_cfg,
> +        on_reload_cfg = box_on_load_cfg,
> +        on_apply_default_cfg = box_on_apply_default_cfg,
> +    },
>   }
>   
>   setmetatable(log, {
> +    __serialize = function(self)
> +        local res = table.copy(self)
> +        res.box_api = nil
> +        return setmetatable(res, {})
> +    end,
>       __index = compat_v16;
>   })
>   
> 

Re: [Tarantool-patches] [PATCH v7 08/11] lua/log: allow to configure logging without a box

[Oleg Babin]

Hi! Thanks for your patch. Looks OK. But still I think about 
inconsistency I noticed in previous message (to 7th patch). May be I was 
wrong and some validation is missed here.

On 02/06/2020 01:25, Cyrill Gorcunov wrote:
> We bring in an ability to configure logger early without
> calling box.cfg{}. For this sake log.cfg({}) becomes a
> callable table. One can provide arguments of the looger
> which later will be propagated back to box.cfg table on
> demand.
> 
> Another notable change is that the settings in log module
> become defaults value, thus if one configured log before
> the box then new settings get propagated to box's default
> logging settings (previously they are silently reset to
> defaults).
> 
> Fixes #689
> 
> @TarantoolBot documnent
> Title: Module log
> 
> To configure log module eary without initializing box module
> at all call the `log.cfg({})` method, where the following
> arguments are acceptable:
> 
>   - `log` to specify file, pipe or syslog (same as
>     `box.cfg{log}` option); the default value is nil
>     and stderr is used;
> 
>   - `level` to specify logging level (1-7); the default
>     value is 5;
> 
>   - `format` to specify output encoding ('plain' or 'json');
>     the default value is 'plain';
> 
>   - `nonblock` to open logging output in nonblocking mode
>     (`true` or `false`); the default value is `false`.
> 
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
>   src/lua/log.lua | 105 +++++++++++++++++++++++++++++++++++++++++++++++-
>   1 file changed, 104 insertions(+), 1 deletion(-)
> 
> diff --git a/src/lua/log.lua b/src/lua/log.lua
> index 33e98fd84..dfdc326fe 100644
> --- a/src/lua/log.lua
> +++ b/src/lua/log.lua
> @@ -119,6 +119,27 @@ local log2box_keys = {
>       ['format']      = 'log_format',
>   }
>   
> +local box_module_cfg = nil
> +
> +-- Reflect changes in box.cfg (if
> +-- box.cfg been initialized).
> +local function update_box_cfg(k)
> +    if box_module_cfg ~= nil then
> +        local update = function(k, v)
> +            if box_module_cfg[v] ~= log_cfg[k] then
> +                box_module_cfg[v] = log_cfg[k]
> +            end
> +        end
> +        if k ~= nil then
> +            update(k, log2box_keys[k])
> +        else
> +            for k, v in pairs(log2box_keys) do
> +                update(k, v)
> +            end
> +        end
> +    end
> +end
> +
>   local function say(level, fmt, ...)
>       if ffi.C.log_level < level then
>           -- don't waste cycles on debug.getinfo()
> @@ -170,6 +191,7 @@ end
>   local function log_level(level)
>       ffi.C.say_set_log_level(level)
>       rawset(log_cfg, 'level', level)
> +    update_box_cfg('level')
>   end
>   
>   local function log_format(name)
> @@ -190,6 +212,7 @@ local function log_format(name)
>           ffi.C.say_set_log_format(ffi.C.SF_PLAIN)
>       end
>       rawset(log_cfg, 'format', name)
> +    update_box_cfg('format')
>   end
>   
>   local function log_pid()
> @@ -208,10 +231,87 @@ end
>   -- Update own values from box interface.
>   local function box_on_load_cfg(box_cfg)
>       for k, v in pairs(log2box_keys) do
> -        if box_cfg[v] ~= log_cfg[k] then
> +        if box_cfg[v] ~= nil and box_cfg[v] ~= log_cfg[k] then
>               log_cfg[k] = box_cfg[v]
>           end
>       end
> +    -- Remember the backreference to box
> +    -- module config table.
> +    box_module_cfg = box_cfg
> +end
> +
> +local params_once = {
> +    'log',
> +    'log_nonblock',
> +}
> +
> +-- Setup dynamic parameters.
> +local function dynamic_cfg(cfg)
> +    for _, k in pairs(params_once) do
> +        if cfg[k] ~= nil and cfg[k] ~= log_cfg[k] then
> +            local m = "log: '%s' can't be set dynamically"
> +            error(m:format(k))
> +        end
> +    end
> +
> +    if cfg.level ~= nil then
> +        log_level(cfg.level)
> +    end
> +
> +    if cfg.format ~= nil then
> +        log_format(cfg.format)
> +    end
> +
> +    -- The log_x helpers above update box
> +    -- settings on their own, so no need
> +    -- for more update_box_cfg calls.
> +end
> +
> +-- Load or reload configuration via log.cfg({}) call.
> +local function load_cfg(oldcfg, cfg)
> +    cfg = cfg or {}
> +
> +    if cfg.format ~= nil then
> +        if fmt_str2num[cfg.format] == nil then
> +            local m = "log: 'format' must be %s"
> +            error(m:format(fmt_list()))
> +        end
> +    end
> +
> +    if cfg.level ~= nil then
> +        if type(cfg.level) ~= 'number' then
> +            error("log: 'level' option must be a number")
> +        end
> +    end
> +
> +    if cfg.nonblock ~= nil then
> +        if type(cfg.nonblock) ~= 'boolean' then
> +            error("log: 'nonblock' option must be 'true' or 'false'")
> +        end
> +    end
> +
> +    if ffi.C.say_logger_initialized() == true then
> +        return dynamic_cfg(cfg)
> +    end
> +
> +    cfg.level = cfg.level or log_cfg.level
> +    cfg.format = cfg.format or log_cfg.format
> +    cfg.nonblock = cfg.nonblock or (log_cfg.nonblock or false)
> +
> +    -- We never allow confgure the logger in background
> +    -- mode since we don't know how the box will be configured
> +    -- later.
> +    ffi.C.say_logger_init(cfg.log, cfg.level,
> +                          cfg.nonblock, cfg.format, 0)
> +
> +    -- Update log_cfg vars to show them in module
> +    -- configuration output.
> +    rawset(log_cfg, 'log', cfg.log)
> +    rawset(log_cfg, 'level', cfg.level)
> +    rawset(log_cfg, 'nonblock', cfg.nonblock)
> +    rawset(log_cfg, 'format', cfg.format)
> +
> +    update_box_cfg()
>   end
>   
>   local compat_warning_said = false
> @@ -235,6 +335,9 @@ local log = {
>       pid = log_pid,
>       level = log_level,
>       log_format = log_format,
> +    cfg = setmetatable(log_cfg, {
> +        __call = load_cfg,
> +    }),
>   
>       -- Internal API to box module, not for users,
>       -- names can be changed.
> 

Re: [Tarantool-patches] [PATCH v7 09/11] test: use direct log module

[Oleg Babin]

Hi! Thanks for your patch. See comments below.

On 02/06/2020 01:25, Cyrill Gorcunov wrote:
> To test if we can setup logging module before the box.cfg{}.
> 
> Part-of #689
> 
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
>   test/app-tap/logger.test.lua | 56 ++++++++++++++++++++++++++++++++++--
>   1 file changed, 53 insertions(+), 3 deletions(-)
> 
> diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
> index 676c860d3..c6f207908 100755
> --- a/test/app-tap/logger.test.lua
> +++ b/test/app-tap/logger.test.lua
> @@ -1,7 +1,7 @@
>   #!/usr/bin/env tarantool
>   
>   local test = require('tap').test('log')
> -test:plan(25)
> +test:plan(34)
>   
>   -- gh-3946: Assertion failure when using log_format() before box.cfg()
>   local log = require('log')
> @@ -10,16 +10,66 @@ _,err = pcall(log, {log_format = 'json'})
>   test:ok(err ~= nil)
>   
>   --
> --- Check that Tarantool creates ADMIN session for #! script
> +-- gh-689: Operate with logger via log module without calling box.cfg{}
>   --
> +local json = require('json')
>   local filename = "1.log"
> +
> +-- Test json output
> +log.cfg({log=filename, format='json', level=5})
> +local m = "info message"
> +
> +local file = io.open(filename)
> +while file:read() do
> +end
> +
> +log.info(m)
> +local line = file:read()
> +local message = json.decode(line)
> +file:close()
> +
> +test:is(type(message), 'table', "(log) json valid in log.info")
> +test:is(message.level, "INFO", "(log) check type info")
> +test:is(message.message, m, "(log) check message content")
> +
> +-- Test runtime change to plain format
> +log.log_format('plain')
> +local file = io.open(filename)
> +while file:read() do
> +end
> +log.info(m)
> +local line = file:read()
> +file:close()
> +test:is(line:sub(-m:len()), m, m)

I think it could be checked as `test:ok(line:endswith(m))`.

> +
> +-- Test wrong arguments
> +_, err = pcall(log.cfg, {format = 'unknown'})
> +test:ok(err ~= nil)

I suggest to check the text of error messages.

> +
> +-- Test that changes in log module are propagated
> +-- back to the box module correctly

I think that here we should try to change static log parameters via 
box.cfg and check that it's impossible.

> +box.cfg{
> +    log=filename,
> +    log_format='json',
> +    log_level=6,
> +    memtx_memory=107374182,
> +}
> +test:is(box.cfg.log_format, 'json', 'box in json format')
> +test:is(box.cfg.log_level, 6, 'box level 6')
> +log.cfg({format='plain', level=5})
> +test:is(box.cfg.log_format, 'plain', 'box sees plain format')
> +test:is(box.cfg.log_level, 5, 'box sees level change' > +
> +--
> +-- Check that Tarantool creates ADMIN session for #! script
> +--
>   local message = "Hello, World!"
>   box.cfg{
>       log=filename,
> +    log_format='plain',
>       memtx_memory=107374182,
>   }
>   local fio = require('fio')
> -local json = require('json')
>   local fiber = require('fiber')
>   local file = io.open(filename)
>   while file:read() do
> 

Re: [Tarantool-patches] [PATCH v7 10/11] log/lua: allow to specify logging level as a string

[Oleg Babin]

Hi! Thanks for your patch it's amazing. See several comments below.

On 02/06/2020 01:25, Cyrill Gorcunov wrote:
> Allow to specify logging level as a string in log.cfg() call.
> 
> @TarantoolBot document
> Title: Module log
> 
> The `log.cfg({level='string'})` accepts not only number but
> symbolic repreentation of loglevels such as: `fatal`, `syserror`,
> `error`, `crit`, `warn`, `info`, `verbose` and `debug`.
> 
> Part-of #689

You've closed this issue in previous message. Seems it could be 
follow-up or may be even "Closes #1054" 
(https://github.com/tarantool/tarantool/issues/1054)

> 
> Suggested-by: Oleg Babin <olegrok@tarantool.org>
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
>   src/lua/log.lua              | 36 ++++++++++++++++++++++++++++++++++--
>   test/app-tap/logger.test.lua | 29 ++++++++++++++++++++++++++++-
>   2 files changed, 62 insertions(+), 3 deletions(-)
> 
> diff --git a/src/lua/log.lua b/src/lua/log.lua
> index dfdc326fe..3376932ff 100644
> --- a/src/lua/log.lua
> +++ b/src/lua/log.lua
> @@ -140,6 +140,26 @@ local function update_box_cfg(k)
>       end
>   end
>   
> +-- Logging levels symbolic representation.
> +local log_level_keys = {
> +    ['fatal']       = ffi.C.S_FATAL,
> +    ['syserror']    = ffi.C.S_SYSERROR,
> +    ['error']       = ffi.C.S_ERROR,
> +    ['crit']        = ffi.C.S_CRIT,
> +    ['warn']        = ffi.C.S_WARN,
> +    ['info']        = ffi.C.S_INFO,
> +    ['verbose']     = ffi.C.S_VERBOSE,
> +    ['debug']       = ffi.C.S_DEBUG,
> +}
> +
> +local function log_level_list()
> +    local keyset = {}
> +    for k in pairs(log_level_keys) do
> +        keyset[#keyset + 1] = k
> +    end
> +    return table.concat(keyset, ',')
> +end
> +
>   local function say(level, fmt, ...)
>       if ffi.C.log_level < level then
>           -- don't waste cycles on debug.getinfo()
> @@ -279,8 +299,20 @@ local function load_cfg(oldcfg, cfg)
>       end
>   
>       if cfg.level ~= nil then
> -        if type(cfg.level) ~= 'number' then
> -            error("log: 'level' option must be a number")
> +        if type(cfg.level) == 'number' then
> +            if cfg.level < ffi.C.S_FATAL or
> +                cfg.level > ffi.C.S_DEBUG then
> +                local m = "log: 'level' must be in range [%d;%d]"
> +                error(m:format(ffi.C.S_FATAL, ffi.C.S_DEBUG))
> +            end
> +        elseif type(cfg.level) == 'string' then
> +            if log_level_keys[cfg.level] == nil then
> +                local m = "log: 'level' must be one of [%s]"
> +                error(m:format(log_level_list()))
> +            end
> +            cfg.level = log_level_keys[cfg.level]
> +        else
> +            error("log: 'level' must be a number or string")
>           end
>       end
>   
> diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
> index c6f207908..557c31f1a 100755
> --- a/test/app-tap/logger.test.lua
> +++ b/test/app-tap/logger.test.lua
> @@ -1,7 +1,7 @@
>   #!/usr/bin/env tarantool
>   
>   local test = require('tap').test('log')
> -test:plan(34)
> +test:plan(44)
>   
>   -- gh-3946: Assertion failure when using log_format() before box.cfg()
>   local log = require('log')
> @@ -60,6 +60,33 @@ log.cfg({format='plain', level=5})
>   test:is(box.cfg.log_format, 'plain', 'box sees plain format')
>   test:is(box.cfg.log_level, 5, 'box sees level change')
>   
> +-- Test symbolic names for loglevels
> +log.cfg({level='fatal'})
> +test:ok(log.cfg.level == 0 and box.cfg.log_level == 0, 'both sees fatal')
> +log.cfg({level='syserror'})
> +test:ok(log.cfg.level == 1 and box.cfg.log_level == 1, 'both sees fatal')
> +log.cfg({level='error'})
> +test:ok(log.cfg.level == 2 and box.cfg.log_level == 2, 'both sees fatal')
> +log.cfg({level='crit'})
> +test:ok(log.cfg.level == 3 and box.cfg.log_level == 3, 'both sees fatal')
> +log.cfg({level='warn'})
> +test:ok(log.cfg.level == 4 and box.cfg.log_level == 4, 'both sees fatal')
> +log.cfg({level='info'})
> +test:ok(log.cfg.level == 5 and box.cfg.log_level == 5, 'both sees fatal')
> +log.cfg({level='verbose'})
> +test:ok(log.cfg.level == 6 and box.cfg.log_level == 6, 'both sees fatal')
> +log.cfg({level='debug'})
> +test:ok(log.cfg.level == 7 and box.cfg.log_level == 7, 'both sees fatal')
> +
> +_,err = pcall(log, {level = -1})
> +test:ok(err ~= nil, 'level = -1 error')
> +
> +_,err = pcall(log, {level = 'unknown'})
> +test:ok(err ~= nil, "level = 'unknown' error")
> +

Please check error messages text here.

> +-- restore to info for next tests
> +log.cfg({level='info'})
> +
>   --
>   -- Check that Tarantool creates ADMIN session for #! script
>   --
> 

Re: [Tarantool-patches] [PATCH v7 11/11] lua/log: use log_cfg instead of ffi's instances

[Oleg Babin]

Hi! Thanks for your patch. LGTM.

On 02/06/2020 01:25, Cyrill Gorcunov wrote:
> To reduce number of ffi calls.
> 
> Part-of #689
> 
> Suggested-by: Leonid Vasiliev <lvasiliev@tarantool.org>
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
>   src/lua/log.lua | 4 ++--
>   1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/src/lua/log.lua b/src/lua/log.lua
> index 3376932ff..7ca206989 100644
> --- a/src/lua/log.lua
> +++ b/src/lua/log.lua
> @@ -161,7 +161,7 @@ local function log_level_list()
>   end
>   
>   local function say(level, fmt, ...)
> -    if ffi.C.log_level < level then
> +    if log_cfg.level < level then
>           -- don't waste cycles on debug.getinfo()
>           return
>       end
> @@ -179,7 +179,7 @@ local function say(level, fmt, ...)
>               fmt[field] = nil
>           end
>           fmt = json.encode(fmt)
> -        if ffi.C.log_format == ffi.C.SF_JSON then
> +        if log_cfg.format == fmt_num2str[ffi.C.SF_JSON] then
>               -- indicate that message is already encoded in JSON
>               format = fmt_num2str[ffi.C.SF_JSON]
>           end
> 

Re: [Tarantool-patches] [PATCH v7 10/11] log/lua: allow to specify logging level as a string

[Oleg Babin]

Also. I've found that it's not allowed to set log level as string via 
box API:

```

tarantool> box.cfg{log_level = 'info'}
---
- error: 'Incorrect value for option ''log_level'': should be of type 
number'
...

```

But it could be easily fixed here: 
https://github.com/tarantool/tarantool/blob/master/src/box/lua/load_cfg.lua#L129

On 02/06/2020 01:25, Cyrill Gorcunov wrote:
> Allow to specify logging level as a string in log.cfg() call.
> 
> @TarantoolBot document
> Title: Module log
> 
> The `log.cfg({level='string'})` accepts not only number but
> symbolic repreentation of loglevels such as: `fatal`, `syserror`,
> `error`, `crit`, `warn`, `info`, `verbose` and `debug`.
> 
> Part-of #689
> 
> Suggested-by: Oleg Babin <olegrok@tarantool.org>
> Signed-off-by: Cyrill Gorcunov <gorcunov@gmail.com>
> ---
>   src/lua/log.lua              | 36 ++++++++++++++++++++++++++++++++++--
>   test/app-tap/logger.test.lua | 29 ++++++++++++++++++++++++++++-
>   2 files changed, 62 insertions(+), 3 deletions(-)
> 
> diff --git a/src/lua/log.lua b/src/lua/log.lua
> index dfdc326fe..3376932ff 100644
> --- a/src/lua/log.lua
> +++ b/src/lua/log.lua
> @@ -140,6 +140,26 @@ local function update_box_cfg(k)
>       end
>   end
>   
> +-- Logging levels symbolic representation.
> +local log_level_keys = {
> +    ['fatal']       = ffi.C.S_FATAL,
> +    ['syserror']    = ffi.C.S_SYSERROR,
> +    ['error']       = ffi.C.S_ERROR,
> +    ['crit']        = ffi.C.S_CRIT,
> +    ['warn']        = ffi.C.S_WARN,
> +    ['info']        = ffi.C.S_INFO,
> +    ['verbose']     = ffi.C.S_VERBOSE,
> +    ['debug']       = ffi.C.S_DEBUG,
> +}
> +
> +local function log_level_list()
> +    local keyset = {}
> +    for k in pairs(log_level_keys) do
> +        keyset[#keyset + 1] = k
> +    end
> +    return table.concat(keyset, ',')
> +end
> +
>   local function say(level, fmt, ...)
>       if ffi.C.log_level < level then
>           -- don't waste cycles on debug.getinfo()
> @@ -279,8 +299,20 @@ local function load_cfg(oldcfg, cfg)
>       end
>   
>       if cfg.level ~= nil then
> -        if type(cfg.level) ~= 'number' then
> -            error("log: 'level' option must be a number")
> +        if type(cfg.level) == 'number' then
> +            if cfg.level < ffi.C.S_FATAL or
> +                cfg.level > ffi.C.S_DEBUG then
> +                local m = "log: 'level' must be in range [%d;%d]"
> +                error(m:format(ffi.C.S_FATAL, ffi.C.S_DEBUG))
> +            end
> +        elseif type(cfg.level) == 'string' then
> +            if log_level_keys[cfg.level] == nil then
> +                local m = "log: 'level' must be one of [%s]"
> +                error(m:format(log_level_list()))
> +            end
> +            cfg.level = log_level_keys[cfg.level]
> +        else
> +            error("log: 'level' must be a number or string")
>           end
>       end
>   
> diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
> index c6f207908..557c31f1a 100755
> --- a/test/app-tap/logger.test.lua
> +++ b/test/app-tap/logger.test.lua
> @@ -1,7 +1,7 @@
>   #!/usr/bin/env tarantool
>   
>   local test = require('tap').test('log')
> -test:plan(34)
> +test:plan(44)
>   
>   -- gh-3946: Assertion failure when using log_format() before box.cfg()
>   local log = require('log')
> @@ -60,6 +60,33 @@ log.cfg({format='plain', level=5})
>   test:is(box.cfg.log_format, 'plain', 'box sees plain format')
>   test:is(box.cfg.log_level, 5, 'box sees level change')
>   
> +-- Test symbolic names for loglevels
> +log.cfg({level='fatal'})
> +test:ok(log.cfg.level == 0 and box.cfg.log_level == 0, 'both sees fatal')
> +log.cfg({level='syserror'})
> +test:ok(log.cfg.level == 1 and box.cfg.log_level == 1, 'both sees fatal')
> +log.cfg({level='error'})
> +test:ok(log.cfg.level == 2 and box.cfg.log_level == 2, 'both sees fatal')
> +log.cfg({level='crit'})
> +test:ok(log.cfg.level == 3 and box.cfg.log_level == 3, 'both sees fatal')
> +log.cfg({level='warn'})
> +test:ok(log.cfg.level == 4 and box.cfg.log_level == 4, 'both sees fatal')
> +log.cfg({level='info'})
> +test:ok(log.cfg.level == 5 and box.cfg.log_level == 5, 'both sees fatal')
> +log.cfg({level='verbose'})
> +test:ok(log.cfg.level == 6 and box.cfg.log_level == 6, 'both sees fatal')
> +log.cfg({level='debug'})
> +test:ok(log.cfg.level == 7 and box.cfg.log_level == 7, 'both sees fatal')
> +
> +_,err = pcall(log, {level = -1})
> +test:ok(err ~= nil, 'level = -1 error')
> +
> +_,err = pcall(log, {level = 'unknown'})
> +test:ok(err ~= nil, "level = 'unknown' error")
> +
> +-- restore to info for next tests
> +log.cfg({level='info'})
> +
>   --
>   -- Check that Tarantool creates ADMIN session for #! script
>   --
> 

Re: [Tarantool-patches] [PATCH v7 10/11] log/lua: allow to specify logging level as a string

[Cyrill Gorcunov]

On Tue, Jun 02, 2020 at 11:05:57AM +0300, Oleg Babin wrote:
> Also. I've found that it's not allowed to set log level as string via box
> API:
> 
> ```
> 
> tarantool> box.cfg{log_level = 'info'}
> ---
> - error: 'Incorrect value for option ''log_level'': should be of type
> number'
> ...
> 
> ```
> 
> But it could be easily fixed here: https://github.com/tarantool/tarantool/blob/master/src/box/lua/load_cfg.lua#L129

Yeah, I left it on intent. Didn't want to change box.cfg api.
Currently the keywords are parsed in log module solely so I'll
have to provide some way to make similar inside load_cfg code,
and I tried to escape it.

You know, the base idea is to configure logging via log module
solely and maybe deprecate it from box.cfg.

Anyway even if I fix it I'll do it on top of the series.

Re: [Tarantool-patches] [PATCH v7 09/11] test: use direct log module

[Cyrill Gorcunov]

On Tue, Jun 02, 2020 at 10:52:17AM +0300, Oleg Babin wrote:
> Hi! Thanks for your patch. See comments below.
> 

Thanks for comments, will address!

Re: [Tarantool-patches] [PATCH v7 07/11] lua/log: use log module settings inside box.cfg

[Cyrill Gorcunov]

On Tue, Jun 02, 2020 at 10:51:28AM +0300, Oleg Babin wrote:
> Hi! Thanks for your patch.
> 
> I've found a strange case:
> ```
> tarantool> log.cfg({log = '1.txt'})
> ---
> ...
> 
> tarantool> log.cfg({log = '2.txt'}) -- error - OK
> ---
> - error: 'builtin/log.lua:273: log: ''log'' can''t be set dynamically'
> ...
> 
> tarantool> box.cfg{log = '2.txt'} -- no error (why?)
> ---
> ...
> 
> tarantool> log.error('test')
> ---
> ...
> ```
> 
> log.cfg and box.cfg shows:
> ```
> tarantool> log.cfg.log
> ---
> - 2.txt
> ...
> 
> tarantool> box.cfg.log
> ---
> - 2.txt
> ...
> ```
> 
> But actually "1.txt" is my log file.
> Also I suggest to cover such situation with a test :)

Good catch! Yes, I need to revisit this moment. Thanks!!!

Re: [Tarantool-patches] [PATCH v7 05/11] lua/log: do not allow to set json for boot logger

[Cyrill Gorcunov]

On Tue, Jun 02, 2020 at 10:51:21AM +0300, Oleg Babin wrote:
> Hi. Thanks for your patch see one comment.

Thanks for comments! Will revisit.

Re: [Tarantool-patches] [PATCH v7 05/11] lua/log: do not allow to set json for boot logger

[Kirill Yukhin]

Hello,

On 02 июн 01:25, Cyrill Gorcunov wrote:
> For some reason we've missed that say_set_log_format
> doesn't support json format not only for syslog but
> for boottime logging as well.
> 
> Part-of #689

I've checked first 5 patches into master.

--
Regards, Kirill Yukhin