From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: From: Serge Petrenko Subject: [PATCH] xrow: improve corrupted header logging on an error Date: Fri, 5 Apr 2019 19:09:17 +0300 Message-Id: <20190405160918.17305-1-sergepetrenko@tarantool.org> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit To: vdavydov.dev@gmail.com Cc: tarantool-patches@freelists.org, kostja@tarantool.org, Serge Petrenko List-ID: Improve row printing to log. Since say only has 16k buffer, there is no point in printing the whole packet, which can have arbitrary length, in one go. So, print the header row by row, 16 bytes in a row, and format output to match `xxd` output: ``` [001] 2019-04-05 18:22:46.679 [11859] iproto V> Got a corrupted row: [001] 2019-04-05 18:22:46.679 [11859] iproto V> 00000000: A3 02 D6 5A E4 D9 E7 68 A1 53 8D 53 60 5F 20 3F [001] 2019-04-05 18:22:46.679 [11859] iproto V> 00000010: D8 E2 D6 E2 A3 02 D6 5A E4 D9 E7 68 A1 53 8D 53 ``` Now we can get rid of malloc, and use a preallocated tt_static_buf instead. Also, replace a big macro with a small macro and a helper function. Followup to f645119f7732b67ed50b48b1b9d7c8b683953931 --- https://github.com/tarantool/tarantool/tree/sp/print-bad-row-followup src/box/xrow.c | 55 +++++++++++++++++++-------------------- test/box/net.box.result | 30 +++++++++++++++++---- test/box/net.box.test.lua | 13 ++++++--- 3 files changed, 62 insertions(+), 36 deletions(-) diff --git a/src/box/xrow.c b/src/box/xrow.c index 6aebe5c50..aaed84e38 100644 --- a/src/box/xrow.c +++ b/src/box/xrow.c @@ -89,37 +89,36 @@ mp_decode_vclock(const char **data, struct vclock *vclock) } /** - * Set diagnostics with an error and log the corrupted row - * which caused the error. - * Optionally, if log_level is 'verbose' or greater, + * If log_level is 'verbose' or greater, * dump the corrupted row contents in hex to the log. * - * @param what - exception to set. - * @param desc_str - error description string. + * The format is similar to the xxd utility. */ -#define xrow_on_decode_err(start, end, what, desc_str) do { \ - diag_set(ClientError, what, desc_str); \ - \ - if (!say_log_level_is_enabled(S_VERBOSE)) \ - break; \ - \ - size_t len = 3 * ((const char *)(end) - (const char *)(start) + 1); \ - char *buf = (char *)malloc(len); \ - if (!buf) { \ - say_verbose("Got a corrupted row during decoding. " \ - "Not enough memory to dump row contents."); \ - break; \ - } \ - \ - char *pos = buf; \ - char *buf_end = buf + len; \ - for (const char *cur = start; cur < end; ++cur) { \ - pos += snprintf(pos, buf_end - pos, "%02X ", (unsigned char)*cur); \ - } \ - say_verbose("Corrupted row is: %s", buf); \ - \ - free(buf); \ -} while (0) +void dump_row_hex(const char *start, const char *end) { + if (!say_log_level_is_enabled(S_VERBOSE)) + return; + + char *buf = tt_static_buf(); + const char *buf_end = buf + TT_STATIC_BUF_LEN; + + say_verbose("Got a corrupted row:"); + for (const char *cur = start; cur < end;) { + char *pos = buf; + pos += snprintf(pos, buf_end - pos, "%08lX: ", cur - start); + for (size_t i = 0; i < 16; ++i) { + pos += snprintf(pos, buf_end - pos, "%02X ", (unsigned char)*cur++); + if (cur >= end || pos == buf_end) + break; + } + *pos = '\0'; + say_verbose("%s", buf); + } +} + +#define xrow_on_decode_err(start, end, what, desc_str) do {\ + diag_set(ClientError, what, desc_str);\ + dump_row_hex(start, end);\ +} while (0); int xrow_header_decode(struct xrow_header *header, const char **pos, diff --git a/test/box/net.box.result b/test/box/net.box.result index a9f1b8f3f..f71699818 100644 --- a/test/box/net.box.result +++ b/test/box/net.box.result @@ -3541,21 +3541,41 @@ sock = socket.tcp_connect(LISTEN.host, LISTEN.service) -- we need to have a packet with correctly encoded length, -- so that it bypasses iproto length check, but cannot be -- decoded in xrow_header_decode --- 0x14 = 20, sha1 digest is 20 bytes long -data = string.fromhex('14'..require('digest').sha1_hex('asdf')) +-- 0x3C = 60, sha1 digest is 20 bytes long +data = string.fromhex('3C'..string.rep(require('digest').sha1_hex('bcde'), 3)) --- ... sock:write(data) --- -- 21 +- 61 ... sock:close() --- - true ... -test_run:grep_log('default', 'Corrupted row is: .*') +test_run:grep_log('default', 'Got a corrupted row.*') +--- +- 'Got a corrupted row:' +... +test_run:grep_log('default', '00000000:.*') +--- +- '00000000: A3 02 D6 5A E4 D9 E7 68 A1 53 8D 53 60 5F 20 3F ' +... +test_run:grep_log('default', '00000010:.*') +--- +- '00000010: D8 E2 D6 E2 A3 02 D6 5A E4 D9 E7 68 A1 53 8D 53 ' +... +test_run:grep_log('default', '00000020:.*') +--- +- '00000020: 60 5F 20 3F D8 E2 D6 E2 A3 02 D6 5A E4 D9 E7 68 ' +... +test_run:grep_log('default', '00000030:.*') --- -- 'Corrupted row is: 3D A5 41 55 99 18 A8 08 C2 40 2B BA 50 12 F6 C6 0B 27 66 1C ' +- '00000030: A1 53 8D 53 60 5F 20 3F D8 E2 D6 E2 ' +... +test_run:grep_log('default', '00000040:.*') +--- +- null ... box.cfg{log_level=log_level} --- diff --git a/test/box/net.box.test.lua b/test/box/net.box.test.lua index e2f8f90ba..beb33c24f 100644 --- a/test/box/net.box.test.lua +++ b/test/box/net.box.test.lua @@ -1445,9 +1445,16 @@ sock = socket.tcp_connect(LISTEN.host, LISTEN.service) -- we need to have a packet with correctly encoded length, -- so that it bypasses iproto length check, but cannot be -- decoded in xrow_header_decode --- 0x14 = 20, sha1 digest is 20 bytes long -data = string.fromhex('14'..require('digest').sha1_hex('asdf')) +-- 0x3C = 60, sha1 digest is 20 bytes long +data = string.fromhex('3C'..string.rep(require('digest').sha1_hex('bcde'), 3)) sock:write(data) sock:close() -test_run:grep_log('default', 'Corrupted row is: .*') + +test_run:grep_log('default', 'Got a corrupted row.*') +test_run:grep_log('default', '00000000:.*') +test_run:grep_log('default', '00000010:.*') +test_run:grep_log('default', '00000020:.*') +test_run:grep_log('default', '00000030:.*') +test_run:grep_log('default', '00000040:.*') + box.cfg{log_level=log_level} -- 2.20.1 (Apple Git-117)