4 апр. 2019 г., в 15:06, Vladimir Davydov <vdavydov.dev@gmail.com> написал(а):

On Thu, Apr 04, 2019 at 02:52:25PM +0300, Serge Petrenko wrote:

Hi!

3 апр. 2019 г., в 12:18, Vladimir Davydov <vdavydov.dev@gmail.com> написал(а):

On Mon, Apr 01, 2019 at 04:09:06PM +0300, Serge Petrenko wrote:
Add row hex printing to log on verbose level. This would be useful
during investigation of errors related to invalid msgpack packet
arrival.

Here's some example output:
```
2019-04-01 16:04:51.629 [31304] iproto V> Corrupted row is: 3D A5 41 55 99 18 A8 08 C2 40 2B BA 50 12 F6 C6 0B 27 66 1C
2019-04-01 16:04:51.629 [31304] iproto xrow.c:133 E> ER_INVALID_MSGPACK: Invalid MsgPack - packet header
```

Related to #4040
---
https://github.com/tarantool/tarantool/tree/sp/xrow-decode-verbose-err
https://github.com/tarantool/tarantool/issues/4040

Changes in v2:
- make xrow_on_decode_err a macro instead of a
  function to preserve line where error occurs.
- add a test case.
- always allocate buffer for hex dump with malloc
- add logging on all errors related to invalid
  msgpack and missing request field.

src/box/xrow.c            | 116 ++++++++++++++++++++++++++------------
test/box/net.box.result   |  34 +++++++++++
test/box/net.box.test.lua |  16 ++++++
3 files changed, 131 insertions(+), 35 deletions(-)

diff --git a/src/box/xrow.c b/src/box/xrow.c
index 73d9e739b..fdd15bef3 100644
--- a/src/box/xrow.c
+++ b/src/box/xrow.c
@@ -88,15 +88,49 @@ mp_decode_vclock(const char **data, struct vclock *vclock)
return 0;
}

+/**
+ * Set diagnostics with an error and log the corrupted row
+ * which caused the error.
+ * Optionally, 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.
+ */
+#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); \

Nit: shouldn't +1 be outside the parentheses?

Yes, I guess I meant the interval to be inclusive.
But since it is not, the ‘+1’ should be outside.


+ char *_buf = (char *)malloc(_len); \

Nit: we don't usually prefix names with underscores, because this may
conflict with libc internal macro definitions.

Ok. Do you want me to fix it?

Yes, please do and update the branch.

Done, here’s the diff.

diff --git a/src/box/xrow.c b/src/box/xrow.c
index fdd15bef3..6aebe5c50 100644
--- a/src/box/xrow.c
+++ b/src/box/xrow.c
@@ -97,28 +97,28 @@ mp_decode_vclock(const char **data, struct vclock *vclock)
  * @param what - exception to set.
  * @param desc_str - error description string.
  */
-#define xrow_on_decode_err(_start, _end, _what, _desc_str) do {                                \
-       diag_set(ClientError, _what, _desc_str);                                        \
+#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) {                                                                    \
+       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); \
+       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);                                      \
+       say_verbose("Corrupted row is: %s", buf);                                       \
                                                                                        \
-       free(_buf);                                                                     \
+       free(buf);                                                                      \
 } while (0)
 
 int