[PATCH] xrow: improve corrupted header logging on an error

[PATCH] xrow: improve corrupted header logging on an error

[Serge Petrenko]

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)

Re: [PATCH] xrow: improve corrupted header logging on an error

[Vladimir Davydov]

On Fri, Apr 05, 2019 at 07:09:17PM +0300, Serge Petrenko wrote:
> 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.

Looks awesome, thanks! Pushed to master, 2.1, and 1.10.

It's a shame we didn't think about multiline output ourselves until
Kostja suggested it :(