From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 9D269297D2 for ; Wed, 28 Mar 2018 06:35:28 -0400 (EDT) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing.freelists.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 6NjVpUiNEJdk for ; Wed, 28 Mar 2018 06:35:28 -0400 (EDT) Received: from smtp61.i.mail.ru (smtp61.i.mail.ru [217.69.128.41]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTPS id EA7DE23585 for ; Wed, 28 Mar 2018 06:35:27 -0400 (EDT) From: Ilya Markov Subject: [tarantool-patches] [log 1/1] log: Fix logging large objects Date: Wed, 28 Mar 2018 13:35:14 +0300 Message-Id: <5644fb6343e31f6e136071bb5659f893ac176400.1522233290.git.imarkov@tarantool.org> Sender: tarantool-patches-bounce@freelists.org Errors-to: tarantool-patches-bounce@freelists.org Reply-To: tarantool-patches@freelists.org List-help: List-unsubscribe: List-software: Ecartis version 1.0.0 List-Id: tarantool-patches List-subscribe: List-owner: List-post: List-archive: To: georgy@tarantool.org Cc: tarantool-patches@freelists.org 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