From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: From: Serge Petrenko Message-Id: Content-Type: multipart/alternative; boundary="Apple-Mail=_B67C9668-D137-43EA-A796-3774154B8028" Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.8\)) Subject: Re: [tarantool-patches] Re: [PATCH v2] xrow: print corrupted rows on decoding error. Date: Thu, 4 Apr 2019 15:29:24 +0300 In-Reply-To: <20190404120637.x7s5bulkubcaqweh@esperanza> References: <20190401130906.31356-1-sergepetrenko@tarantool.org> <20190403091827.qh5rxxpsbrkl35bp@esperanza> <338F2586-287A-4521-A6EE-F9E738FF6701@tarantool.org> <20190404120637.x7s5bulkubcaqweh@esperanza> To: Vladimir Davydov Cc: Kirill Yukhin , tarantool-patches@freelists.org List-ID: --Apple-Mail=_B67C9668-D137-43EA-A796-3774154B8028 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 > 4 =D0=B0=D0=BF=D1=80. 2019 =D0=B3., =D0=B2 15:06, Vladimir Davydov = =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0=B0=D0=BB(=D0=B0= ): >=20 > On Thu, Apr 04, 2019 at 02:52:25PM +0300, Serge Petrenko wrote: >>=20 >> Hi! >>=20 >>> 3 =D0=B0=D0=BF=D1=80. 2019 =D0=B3., =D0=B2 12:18, Vladimir Davydov = =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0=B0=D0=BB(=D0=B0= ): >>>=20 >>> 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. >>>>=20 >>>> 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 >>>> ``` >>>>=20 >>>> Related to #4040 >>>> --- >>>> = https://github.com/tarantool/tarantool/tree/sp/xrow-decode-verbose-err >>>> https://github.com/tarantool/tarantool/issues/4040 >>>>=20 >>>> 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. >>>>=20 >>>> 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(-) >>>>=20 >>>> 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; >>>> } >>>>=20 >>>> +/** >>>> + * 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 =3D 3 * ((const char *)(_end) - (const char = *)(_start) + 1); \ >>>=20 >>> Nit: shouldn't +1 be outside the parentheses? >>=20 >> Yes, I guess I meant the interval to be inclusive. >> But since it is not, the =E2=80=98+1=E2=80=99 should be outside. >>=20 >>>=20 >>>> + char *_buf =3D (char *)malloc(_len); = \ >>>=20 >>> Nit: we don't usually prefix names with underscores, because this = may >>> conflict with libc internal macro definitions. >>=20 >> Ok. Do you want me to fix it? >=20 > Yes, please do and update the branch. Done, here=E2=80=99s 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 =3D 3 * ((const char *)(_end) - (const char = *)(_start) + 1); \ - char *_buf =3D (char *)malloc(_len); = \ - if (!_buf) { = \ + size_t len =3D 3 * ((const char *)(end) - (const char *)(start) = + 1); \ + char *buf =3D (char *)malloc(len); = \ + if (!buf) { = \ say_verbose("Got a corrupted row during decoding. " = \ "Not enough memory to dump row contents."); = \ break; = \ } = \ = \ - char *_pos =3D _buf; = \ - char *_buf_end =3D _buf + _len; = \ - for (const char *_cur =3D _start; _cur < _end; ++_cur) { = \ - _pos +=3D snprintf(_pos, _buf_end - _pos, "%02X ", = (unsigned char)*_cur); \ + char *pos =3D buf; = \ + char *buf_end =3D buf + len; = \ + for (const char *cur =3D start; cur < end; ++cur) { = \ + pos +=3D 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) =20 int= --Apple-Mail=_B67C9668-D137-43EA-A796-3774154B8028 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8

4 =D0=B0=D0=BF=D1=80. = 2019 =D0=B3., =D0=B2 15:06, Vladimir Davydov <vdavydov.dev@gmail.com> =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0= =B0=D0=BB(=D0=B0):

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

Hi!

3 =D0=B0=D0=BF=D1=80. 2019 =D0=B3., =D0=B2 12:18, Vladimir = Davydov <vdavydov.dev@gmail.com> =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0= =B0=D0=BB(=D0=B0):

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-verb= ose-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 =3D 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 =E2=80=98+1=E2=80=99 should be outside.


+ char *_buf =3D (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=E2=80=99s 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 =3D 3 * ((const = char *)(_end) - (const char *)(_start) + 1);        =   \
-       char *_buf = =3D (char *)malloc(_len);            =                     =               \
-       if (!_buf) {    =                     =                     =                     =     \
+     =   size_t len =3D 3 * ((const char *)(end) - (const char = *)(start) + 1);             \
+       char *buf =3D (char = *)malloc(len);                =                     =             \
+       if (!buf) {   =                     =                     =                     =       \
        =         say_verbose("Got a corrupted row during = decoding. "                 =     \
          =                   "Not = enough memory to dump row contents.");         =         \
      =           break;      =                     =                     =                   =   \
      =   }               =                     =                     =                     =     \
          =                     =                     =                     =                   \
-       char *_pos =3D _buf;  =                     =                     =                   =   \
-       char = *_buf_end =3D _buf + _len;           =                     =                   =   \
-       for (const = char *_cur =3D _start; _cur < _end; ++_cur) {      =                   =   \
-           =     _pos +=3D snprintf(_pos, _buf_end - _pos, "%02X ", = (unsigned char)*_cur); \
+     =   char *pos =3D buf;            =                     =                     =             \
+       char *buf_end =3D buf + = len;                  =                     =                 \
+       for (const char *cur =3D = start; cur < end; ++cur) {           =                   =   \
+           =     pos +=3D 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= --Apple-Mail=_B67C9668-D137-43EA-A796-3774154B8028--