[tarantool-patches] [PATCH v2 0/2] logger non inf error

[tarantool-patches] [PATCH v2 0/2] logger non inf error

[Olga Arkhangelskaia]

Fix non-informative error messages in logger and added some
tests to keep logger safe for usage. 

Olga Arkhangelskaia (2):
  Fixed non-informative error messages for log conf.
  box-tap: test to check logger invalid config.

 src/box/box.cc            | 66 ++++++++++++++++++++++++++++++-----------------
 src/say.c                 |  5 ++--
 test/box-tap/cfg.test.lua |  7 +++--
 3 files changed, 50 insertions(+), 28 deletions(-)

-- 
https://github.com/tarantool/tarantool/issues/3553
https://github.com/tarantool/tarantool/tree/OKriw/gh-3553-non-inf-error

v1:
https://www.freelists.org/post/tarantool-patches/PATCH-01-Fixed-noninformative-error-messages-for-log-conf

Changes in v2:
- added tests
- changed the way of checks, now all checks is left in box
- added re-usage of some checks 

2.14.3 (Apple Git-98)

[tarantool-patches] [PATCH v2 1/2] Fixed non-informative error messages for log conf.

[Olga Arkhangelskaia]

In case of bad or erroneous options for log configurations
errors had ambiguous or absent messages. In some cases it lead to
app crashes.

Closes #3553
---
 src/box/box.cc            | 66 ++++++++++++++++++++++++++++++-----------------
 src/say.c                 |  5 ++--
 test/box-tap/cfg.test.lua |  2 +-
 3 files changed, 46 insertions(+), 27 deletions(-)

diff --git a/src/box/box.cc b/src/box/box.cc
index 62fd05468..dc607c1ae 100644
--- a/src/box/box.cc
+++ b/src/box/box.cc
@@ -351,17 +351,41 @@ apply_initial_join_row(struct xstream *stream, struct xrow_header *row)
 
 /* {{{ configuration bindings */
 
+static enum say_format
+box_check_log_format(const char *log_format)
+{
+	enum say_format format = say_format_by_name(log_format);
+	if (format == say_format_MAX)
+		tnt_raise(ClientError, ER_CFG, "log_format",
+			 "expected 'plain' or 'json'");
+	return format;
+}
+
 static void
-box_check_say()
+box_check_format_compatibility(enum say_format format, enum say_logger_type type)
 {
-	const char *log = cfg_gets("log");
-	if (log == NULL)
-		return;
-	enum say_logger_type type;
-	if (say_parse_logger_type(&log, &type) < 0) {
+	if (type == SAY_LOGGER_SYSLOG && format == SF_JSON) {
+		tnt_raise(ClientError, ER_CFG, "log_format",
+			  "'json' can't be used with syslog logger");
+	}
+}
+
+static enum say_logger_type
+box_check_logger_type(const char **log)
+{
+	enum say_logger_type type = SAY_LOGGER_STDERR;
+	if (*log != NULL && say_parse_logger_type(log, &type) < 0) {
 		tnt_raise(ClientError, ER_CFG, "log",
 			  diag_last_error(diag_get())->errmsg);
 	}
+	return type;
+}
+
+static void
+box_check_say()
+{
+	const char *log = cfg_gets("log");
+	enum say_logger_type type = box_check_logger_type(&log);
 
 	if (type == SAY_LOGGER_SYSLOG) {
 		struct say_syslog_opts opts;
@@ -377,27 +401,18 @@ box_check_say()
 	}
 
 	const char *log_format = cfg_gets("log_format");
-	enum say_format format = say_format_by_name(log_format);
-	if (format == say_format_MAX)
-		diag_set(ClientError, ER_CFG, "log_format",
-			 "expected 'plain' or 'json'");
-	if (type == SAY_LOGGER_SYSLOG && format == SF_JSON) {
-		tnt_raise(ClientError, ER_ILLEGAL_PARAMS, "log, log_format");
-	}
+	enum say_format format = box_check_log_format(log_format);
+	box_check_format_compatibility(format, type);
+
 	int log_nonblock = cfg_getb("log_nonblock");
 	if (log_nonblock == 1 && type == SAY_LOGGER_FILE) {
-		tnt_raise(ClientError, ER_ILLEGAL_PARAMS, "log, log_nonblock");
+		tnt_raise(ClientError, ER_CFG, "log_nonblock",
+			  "true' can't be used with file logger type");
+	}
+	if (log_nonblock == 1 && type == SAY_LOGGER_STDERR) {
+		tnt_raise(ClientError, ER_CFG, "log_nonblock",
+			  "'true' can't be used with stderr logger type");
 	}
-}
-
-static enum say_format
-box_check_log_format(const char *log_format)
-{
-	enum say_format format = say_format_by_name(log_format);
-	if (format == say_format_MAX)
-		tnt_raise(ClientError, ER_CFG, "log_format",
-			  "expected 'plain' or 'json'");
-	return format;
 }
 
 static void
@@ -745,7 +760,10 @@ box_set_log_level(void)
 void
 box_set_log_format(void)
 {
+	const char *log = cfg_gets("log");
 	enum say_format format = box_check_log_format(cfg_gets("log_format"));
+	static enum say_logger_type type = box_check_logger_type(&log);
+	box_check_format_compatibility(format, type);
 	say_set_log_format(format);
 }
 
diff --git a/src/say.c b/src/say.c
index ac221dd19..01a0d150d 100644
--- a/src/say.c
+++ b/src/say.c
@@ -541,7 +541,6 @@ log_create(struct log *log, const char *init_str, int nonblock)
 	if (init_str != NULL) {
 		enum say_logger_type type;
 		if (say_parse_logger_type(&init_str, &type)) {
-			diag_set(IllegalParams, logger_syntax_reminder);
 			return -1;
 		}
 		int rc;
@@ -989,8 +988,10 @@ say_parse_logger_type(const char **str, enum say_logger_type *type)
 		*type = SAY_LOGGER_SYSLOG;
 	else if (strchr(*str, ':') == NULL)
 		*type = SAY_LOGGER_FILE;
-	else
+	else {
+		diag_set(IllegalParams, logger_syntax_reminder);
 		return -1;
+	}
 	return 0;
 }
 
diff --git a/test/box-tap/cfg.test.lua b/test/box-tap/cfg.test.lua
index ffafdbe42..ea6f4d646 100755
--- a/test/box-tap/cfg.test.lua
+++ b/test/box-tap/cfg.test.lua
@@ -51,7 +51,7 @@ invalid('vinyl_bloom_fpr', 1.1)
 
 local function invalid_combinations(name, val)
     local status, result = pcall(box.cfg, val)
-    test:ok(not status and result:match('Illegal'), 'invalid '..name)
+    test:ok(not status and result:match('Incorrect'), 'incompatible values'..name)
 end
 
 invalid_combinations("log, log_nonblock", {log = "1.log", log_nonblock = true})
-- 
2.14.3 (Apple Git-98)

[tarantool-patches] [PATCH v2 2/2] box-tap: test to check logger invalid config.

[Olga Arkhangelskaia]

Added test to check that logger doesn't except invalid
configuration.

In scope of gh-3553
---
 test/box-tap/cfg.test.lua | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/test/box-tap/cfg.test.lua b/test/box-tap/cfg.test.lua
index ea6f4d646..2d77c9f3e 100755
--- a/test/box-tap/cfg.test.lua
+++ b/test/box-tap/cfg.test.lua
@@ -6,7 +6,7 @@ local socket = require('socket')
 local fio = require('fio')
 local uuid = require('uuid')
 local msgpack = require('msgpack')
-test:plan(95)
+test:plan(98)
 
 --------------------------------------------------------------------------------
 -- Invalid values
@@ -39,6 +39,8 @@ invalid('listen', '//!')
 invalid('log', ':')
 invalid('log', 'syslog:xxx=')
 invalid('log_level', 'unknown')
+invalid('log_format', "xxx")
+invalid('log', ":test:")
 invalid('vinyl_memory', -1)
 invalid('vinyl_read_threads', 0)
 invalid('vinyl_write_threads', 1)
@@ -56,6 +58,7 @@ end
 
 invalid_combinations("log, log_nonblock", {log = "1.log", log_nonblock = true})
 invalid_combinations("log, log_format", {log = "syslog:identity=tarantool", log_format = 'json'})
+invalid_combinations("log, log_nonblock", {log_nonblock = true})
 
 test:is(type(box.cfg), 'function', 'box is not started')
 
-- 
2.14.3 (Apple Git-98)

Re: [tarantool-patches] [PATCH v2 1/2] Fixed non-informative error messages for log conf.

[Vladimir Davydov]

On Wed, Aug 01, 2018 at 02:07:09PM +0300, Olga Arkhangelskaia wrote:
> In case of bad or erroneous options for log configurations
> errors had ambiguous or absent messages. In some cases it lead to
> app crashes.
> 
> Closes #3553
> ---
>  src/box/box.cc            | 66 ++++++++++++++++++++++++++++++-----------------
>  src/say.c                 |  5 ++--
>  test/box-tap/cfg.test.lua |  2 +-
>  3 files changed, 46 insertions(+), 27 deletions(-)

We don't submit tests separately. Please squash patch 2 in this patch.

> 
> diff --git a/src/box/box.cc b/src/box/box.cc
> index 62fd05468..dc607c1ae 100644
> --- a/src/box/box.cc
> +++ b/src/box/box.cc
> @@ -351,17 +351,41 @@ apply_initial_join_row(struct xstream *stream, struct xrow_header *row)
>  
>  /* {{{ configuration bindings */
>  
> +static enum say_format
> +box_check_log_format(const char *log_format)
> +{
> +	enum say_format format = say_format_by_name(log_format);
> +	if (format == say_format_MAX)
> +		tnt_raise(ClientError, ER_CFG, "log_format",
> +			 "expected 'plain' or 'json'");
> +	return format;
> +}
> +
>  static void
> -box_check_say()
> +box_check_format_compatibility(enum say_format format, enum say_logger_type type)

Bad name: what 'format'? tuple format, space format?

>  {
> -	const char *log = cfg_gets("log");
> -	if (log == NULL)
> -		return;
> -	enum say_logger_type type;
> -	if (say_parse_logger_type(&log, &type) < 0) {
> +	if (type == SAY_LOGGER_SYSLOG && format == SF_JSON) {
> +		tnt_raise(ClientError, ER_CFG, "log_format",
> +			  "'json' can't be used with syslog logger");
> +	}
> +}
> +
> +static enum say_logger_type
> +box_check_logger_type(const char **log)

I don't like this function. Its semantics is quite different from other
cfg-related helpers: it modifies the input argument. I don't think
that you really need it. See my comment to box_set_log_format() below.

> +{
> +	enum say_logger_type type = SAY_LOGGER_STDERR;
> +	if (*log != NULL && say_parse_logger_type(log, &type) < 0) {
>  		tnt_raise(ClientError, ER_CFG, "log",
>  			  diag_last_error(diag_get())->errmsg);
>  	}
> +	return type;
> +}
> +
> +static void
> +box_check_say()
> +{
> +	const char *log = cfg_gets("log");
> +	enum say_logger_type type = box_check_logger_type(&log);
>  
>  	if (type == SAY_LOGGER_SYSLOG) {
>  		struct say_syslog_opts opts;
> @@ -377,27 +401,18 @@ box_check_say()
>  	}
>  
>  	const char *log_format = cfg_gets("log_format");
> -	enum say_format format = say_format_by_name(log_format);
> -	if (format == say_format_MAX)
> -		diag_set(ClientError, ER_CFG, "log_format",
> -			 "expected 'plain' or 'json'");
> -	if (type == SAY_LOGGER_SYSLOG && format == SF_JSON) {
> -		tnt_raise(ClientError, ER_ILLEGAL_PARAMS, "log, log_format");
> -	}
> +	enum say_format format = box_check_log_format(log_format);
> +	box_check_format_compatibility(format, type);
> +
>  	int log_nonblock = cfg_getb("log_nonblock");
>  	if (log_nonblock == 1 && type == SAY_LOGGER_FILE) {
> -		tnt_raise(ClientError, ER_ILLEGAL_PARAMS, "log, log_nonblock");
> +		tnt_raise(ClientError, ER_CFG, "log_nonblock",
> +			  "true' can't be used with file logger type");

A single quite (') before "true" is missing.

> +	}
> +	if (log_nonblock == 1 && type == SAY_LOGGER_STDERR) {
> +		tnt_raise(ClientError, ER_CFG, "log_nonblock",
> +			  "'true' can't be used with stderr logger type");

"'true' can't be used with stderr logger type" sounds strange...

Besides, I don't think it's worth differentiating between stderr and
file logger in this case. Why not rewrite it like below?

	if (log_nonblock && (type == SAY_LOGGER_STDERR ||
			     type == SAY_LOGGER_FILE)) {
		tnt_raise(ClientError, ER_CFG, "log_nonblock",
			  "the option is incompatible with file/stderr logger")

>  	}
> -}
> -
> -static enum say_format
> -box_check_log_format(const char *log_format)
> -{
> -	enum say_format format = say_format_by_name(log_format);
> -	if (format == say_format_MAX)
> -		tnt_raise(ClientError, ER_CFG, "log_format",
> -			  "expected 'plain' or 'json'");
> -	return format;
>  }
>  
>  static void
> @@ -745,7 +760,10 @@ box_set_log_level(void)
>  void
>  box_set_log_format(void)
>  {
> +	const char *log = cfg_gets("log");
>  	enum say_format format = box_check_log_format(cfg_gets("log_format"));
> +	static enum say_logger_type type = box_check_logger_type(&log);

When we chatted, we agreed that using box_check_say() for checking
logger format in box_set_log_format() may be not good, because the user
can overwrite box.cfg.log so that cfg_gets() would return NULL even
though the logger type can be in fact set to syslog. Actually, that was
the only reason not to use box_check_say() here.

However, you still call cfg_gets("log") here, which is no better than
simply calling box_check_say(), just costs us more code. I thought you'd
inquire the configured logger type from say.c. Please either do that or
call box_check_say().

If you choose to get the logger type from say.c, you don't need
box_check_logger_type() and box_check_format_compatibility().
The former can be inlined in box_check_say() as it used to be.
The latter can be inlined in box_check_format() - you just need
to add 'type' parameter to that function.

> +	box_check_format_compatibility(format, type);
>  	say_set_log_format(format);

say_set_log_format() has a log of code that becomes dead after
this patch. Please remove it. That function should simply call
log_set_format() on log_default and update log_format variable.

>  }
>  
> diff --git a/src/say.c b/src/say.c
> index ac221dd19..01a0d150d 100644
> --- a/src/say.c
> +++ b/src/say.c
> @@ -541,7 +541,6 @@ log_create(struct log *log, const char *init_str, int nonblock)
>  	if (init_str != NULL) {
>  		enum say_logger_type type;
>  		if (say_parse_logger_type(&init_str, &type)) {
> -			diag_set(IllegalParams, logger_syntax_reminder);
>  			return -1;
>  		}
>  		int rc;
> @@ -989,8 +988,10 @@ say_parse_logger_type(const char **str, enum say_logger_type *type)
>  		*type = SAY_LOGGER_SYSLOG;
>  	else if (strchr(*str, ':') == NULL)
>  		*type = SAY_LOGGER_FILE;
> -	else
> +	else {
> +		diag_set(IllegalParams, logger_syntax_reminder);
>  		return -1;
> +	}
>  	return 0;
>  }
>  
> diff --git a/test/box-tap/cfg.test.lua b/test/box-tap/cfg.test.lua
> index ffafdbe42..ea6f4d646 100755
> --- a/test/box-tap/cfg.test.lua
> +++ b/test/box-tap/cfg.test.lua
> @@ -51,7 +51,7 @@ invalid('vinyl_bloom_fpr', 1.1)
>  
>  local function invalid_combinations(name, val)
>      local status, result = pcall(box.cfg, val)
> -    test:ok(not status and result:match('Illegal'), 'invalid '..name)
> +    test:ok(not status and result:match('Incorrect'), 'incompatible values'..name)

I see why you need to change 'Illegal' to 'Incorrect', but
why change 'invalid ' to 'incompatible values'? Please don't:
'invalid log_format' looks better than 'incompatible valueslog_format'
(yeah, the space is missing).

Re: [tarantool-patches] [PATCH v2 2/2] box-tap: test to check logger invalid config.

[Vladimir Davydov]

On Wed, Aug 01, 2018 at 02:07:10PM +0300, Olga Arkhangelskaia wrote:
> Added test to check that logger doesn't except invalid
> configuration.
> 
> In scope of gh-3553
> ---
>  test/box-tap/cfg.test.lua | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)

We don't submit tests separately. Please squash this patch in patch 1.

You also changed the way box.cfg{log_format=...} works when called
after initial configuration: now it returns an error if the format is
incompatible with the logger type. Please add a test case for this, too.

> 
> diff --git a/test/box-tap/cfg.test.lua b/test/box-tap/cfg.test.lua
> index ea6f4d646..2d77c9f3e 100755
> --- a/test/box-tap/cfg.test.lua
> +++ b/test/box-tap/cfg.test.lua
> @@ -6,7 +6,7 @@ local socket = require('socket')
>  local fio = require('fio')
>  local uuid = require('uuid')
>  local msgpack = require('msgpack')
> -test:plan(95)
> +test:plan(98)
>  
>  --------------------------------------------------------------------------------
>  -- Invalid values
> @@ -39,6 +39,8 @@ invalid('listen', '//!')
>  invalid('log', ':')
>  invalid('log', 'syslog:xxx=')
>  invalid('log_level', 'unknown')
> +invalid('log_format', "xxx")
> +invalid('log', ":test:")
>  invalid('vinyl_memory', -1)
>  invalid('vinyl_read_threads', 0)
>  invalid('vinyl_write_threads', 1)
> @@ -56,6 +58,7 @@ end
>  
>  invalid_combinations("log, log_nonblock", {log = "1.log", log_nonblock = true})
>  invalid_combinations("log, log_format", {log = "syslog:identity=tarantool", log_format = 'json'})
> +invalid_combinations("log, log_nonblock", {log_nonblock = true})
>  
>  test:is(type(box.cfg), 'function', 'box is not started')