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

[Georgy Kirichenko <georgy@tarantool.org>]

[-- 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 --]