[tarantool-patches] [log 1/1] log: Fix logging large objects

[tarantool-patches] [log 1/1] log: Fix logging large objects

[Ilya Markov]

The bug was that logging we passed to function write
number of bytes which may be more than size of buffer.
This may happen because formatting log string we use vsnprintf which
returns number of bytes would be written to buffer, not the actual
number.

Fix this with limiting number of bytes passing to write function.

Close #3248
---
 src/say.c                    | 24 ++++++++++++++++++------
 test/app-tap/logger.test.lua |  9 +++++++--
 2 files changed, 25 insertions(+), 8 deletions(-)

diff --git a/src/say.c b/src/say.c
index b92514d..8a8d46a 100644
--- a/src/say.c
+++ b/src/say.c
@@ -842,6 +842,18 @@ say_format_syslog(struct log *log, char *buf, int len, int level, const char *fi
 enum { SAY_BUF_LEN_MAX = 16 * 1024 };
 static __thread char buf[SAY_BUF_LEN_MAX];
 
+/**
+ * Wrapper over write which ensures, that writes not more than buffer size.
+ */
+static ssize_t
+safe_write(int fd, const char *buf, int size)
+{
+	/* Writes at most SAY_BUF_LEN_MAX - 1
+	 * (1 byte was taken for 0 byte in vsnprintf).
+	 */
+	return write(fd, buf, MIN(size, SAY_BUF_LEN_MAX - 1));
+}
+
 static void
 say_default(int level, const char *filename, int line, const char *error,
 	    const char *format, ...)
@@ -852,7 +864,7 @@ say_default(int level, const char *filename, int line, const char *error,
 	int total = log_vsay(log_default, level, filename,
 			     line, error, format, ap);
 	if (level == S_FATAL && log_default->fd != STDERR_FILENO) {
-		ssize_t r = write(STDERR_FILENO, buf, total);
+		ssize_t r = safe_write(STDERR_FILENO, buf, total);
 		(void) r;                       /* silence gcc warning */
 	}
 
@@ -870,7 +882,7 @@ write_to_file(struct log *log, int total)
 	       log->type == SAY_LOGGER_PIPE ||
 	       log->type == SAY_LOGGER_STDERR);
 	assert(total >= 0);
-	ssize_t r = write(log->fd, buf, total);
+	ssize_t r = safe_write(log->fd, buf, total);
 	(void) r;                               /* silence gcc warning */
 }
 
@@ -882,7 +894,7 @@ write_to_syslog(struct log *log, int total)
 {
 	assert(log->type == SAY_LOGGER_SYSLOG);
 	assert(total >= 0);
-	if (log->fd < 0 || write(log->fd, buf, total) <= 0) {
+	if (log->fd < 0 || safe_write(log->fd, buf, total) <= 0) {
 		/*
 		 * Try to reconnect, if write to syslog has
 		 * failed. Syslog write can fail, if, for example,
@@ -899,7 +911,7 @@ write_to_syslog(struct log *log, int total)
 			 * it would block thread. Try to reconnect
 			 * on next vsay().
 			 */
-			ssize_t r = write(log->fd, buf, total);
+			ssize_t r = safe_write(log->fd, buf, total);
 			(void) r;               /* silence gcc warning */
 		}
 	}
@@ -1041,11 +1053,11 @@ log_vsay(struct log *log, int level, const char *filename, int line,
 	case SAY_LOGGER_SYSLOG:
 		write_to_syslog(log, total);
 		if (level == S_FATAL && log->fd != STDERR_FILENO)
-			(void) write(STDERR_FILENO, buf, total);
+			(void) safe_write(STDERR_FILENO, buf, total);
 		break;
 	case SAY_LOGGER_BOOT:
 	{
-		ssize_t r = write(STDERR_FILENO, buf, total);
+		ssize_t r = safe_write(STDERR_FILENO, buf, total);
 		(void) r;                       /* silence gcc warning */
 		break;
 	}
diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
index 72d13d3..85f6166 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(23)
+test:plan(24)
 
 --
 -- Check that Tarantool creates ADMIN session for #! script
@@ -91,6 +91,11 @@ local line = file:read()
 message = json.decode(line)
 test:is(message.message, "this is \"", "check message with escaped character")
 
+-- gh-3248 trash in log file with logging large objects
+log.info(string.rep('a', 32000))
+line = file:read()
+test:ok(line:len() < 20000, "big line truncated")
+
 log.info("json")
 local line = file:read()
 message = json.decode(line)
@@ -100,7 +105,7 @@ log.info("hello")
 line = file:read()
 test:ok(not line:match("{"), "log change format")
 s, e = pcall(log.log_format, "non_format")
-test:ok(not s)
+test:ok(not s, "bad format")
 file:close()
 
 log.log_format("json")
-- 
2.7.4

[tarantool-patches] Re: [log 1/1] log: Fix logging large objects

[Georgy Kirichenko]

[-- Attachment #1: Type: text/plain, Size: 4554 bytes --]

The patch itself looks Ok, but there is two tests failed on travis for the 
branch, please check it.
Also a branch url must be included just bellow `---'

On Wednesday, March 28, 2018 1:35:14 PM MSK Ilya Markov wrote:
> The bug was that logging we passed to function write
> number of bytes which may be more than size of buffer.
> This may happen because formatting log string we use vsnprintf which
> returns number of bytes would be written to buffer, not the actual
> number.
> 
> Fix this with limiting number of bytes passing to write function.
> 
> Close #3248
> ---
>  src/say.c                    | 24 ++++++++++++++++++------
>  test/app-tap/logger.test.lua |  9 +++++++--
>  2 files changed, 25 insertions(+), 8 deletions(-)
> 
> diff --git a/src/say.c b/src/say.c
> index b92514d..8a8d46a 100644
> --- a/src/say.c
> +++ b/src/say.c
> @@ -842,6 +842,18 @@ say_format_syslog(struct log *log, char *buf, int len,
> int level, const char *fi enum { SAY_BUF_LEN_MAX = 16 * 1024 };
>  static __thread char buf[SAY_BUF_LEN_MAX];
> 
> +/**
> + * Wrapper over write which ensures, that writes not more than buffer size.
> + */
> +static ssize_t
> +safe_write(int fd, const char *buf, int size)
> +{
> +	/* Writes at most SAY_BUF_LEN_MAX - 1
> +	 * (1 byte was taken for 0 byte in vsnprintf).
> +	 */
> +	return write(fd, buf, MIN(size, SAY_BUF_LEN_MAX - 1));
> +}
> +
>  static void
>  say_default(int level, const char *filename, int line, const char *error,
>  	    const char *format, ...)
> @@ -852,7 +864,7 @@ say_default(int level, const char *filename, int line,
> const char *error, int total = log_vsay(log_default, level, filename,
>  			     line, error, format, ap);
>  	if (level == S_FATAL && log_default->fd != STDERR_FILENO) {
> -		ssize_t r = write(STDERR_FILENO, buf, total);
> +		ssize_t r = safe_write(STDERR_FILENO, buf, total);
>  		(void) r;                       /* silence gcc warning */
>  	}
> 
> @@ -870,7 +882,7 @@ write_to_file(struct log *log, int total)
>  	       log->type == SAY_LOGGER_PIPE ||
>  	       log->type == SAY_LOGGER_STDERR);
>  	assert(total >= 0);
> -	ssize_t r = write(log->fd, buf, total);
> +	ssize_t r = safe_write(log->fd, buf, total);
>  	(void) r;                               /* silence gcc warning */
>  }
> 
> @@ -882,7 +894,7 @@ write_to_syslog(struct log *log, int total)
>  {
>  	assert(log->type == SAY_LOGGER_SYSLOG);
>  	assert(total >= 0);
> -	if (log->fd < 0 || write(log->fd, buf, total) <= 0) {
> +	if (log->fd < 0 || safe_write(log->fd, buf, total) <= 0) {
>  		/*
>  		 * Try to reconnect, if write to syslog has
>  		 * failed. Syslog write can fail, if, for example,
> @@ -899,7 +911,7 @@ write_to_syslog(struct log *log, int total)
>  			 * it would block thread. Try to reconnect
>  			 * on next vsay().
>  			 */
> -			ssize_t r = write(log->fd, buf, total);
> +			ssize_t r = safe_write(log->fd, buf, total);
>  			(void) r;               /* silence gcc warning */
>  		}
>  	}
> @@ -1041,11 +1053,11 @@ log_vsay(struct log *log, int level, const char
> *filename, int line, case SAY_LOGGER_SYSLOG:
>  		write_to_syslog(log, total);
>  		if (level == S_FATAL && log->fd != STDERR_FILENO)
> -			(void) write(STDERR_FILENO, buf, total);
> +			(void) safe_write(STDERR_FILENO, buf, total);
>  		break;
>  	case SAY_LOGGER_BOOT:
>  	{
> -		ssize_t r = write(STDERR_FILENO, buf, total);
> +		ssize_t r = safe_write(STDERR_FILENO, buf, total);
>  		(void) r;                       /* silence gcc warning */
>  		break;
>  	}
> diff --git a/test/app-tap/logger.test.lua b/test/app-tap/logger.test.lua
> index 72d13d3..85f6166 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(23)
> +test:plan(24)
> 
>  --
>  -- Check that Tarantool creates ADMIN session for #! script
> @@ -91,6 +91,11 @@ local line = file:read()
>  message = json.decode(line)
>  test:is(message.message, "this is \"", "check message with escaped
> character")
> 
> +-- gh-3248 trash in log file with logging large objects
> +log.info(string.rep('a', 32000))
> +line = file:read()
> +test:ok(line:len() < 20000, "big line truncated")
> +
>  log.info("json")
>  local line = file:read()
>  message = json.decode(line)
> @@ -100,7 +105,7 @@ log.info("hello")
>  line = file:read()
>  test:ok(not line:match("{"), "log change format")
>  s, e = pcall(log.log_format, "non_format")
> -test:ok(not s)
> +test:ok(not s, "bad format")
>  file:close()
> 
>  log.log_format("json")


[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 488 bytes --]