From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <vdavydov.dev@gmail.com>
Date: Mon, 18 Mar 2019 20:58:29 +0300
From: Vladimir Davydov <vdavydov.dev@gmail.com>
Subject: Re: [PATCH] xrow: print corrupted rows on decoding error.
Message-ID: <20190318175829.rxdmzizp67wwfdkq@esperanza>
References: <20190315160238.37882-1-sergepetrenko@tarantool.org>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20190315160238.37882-1-sergepetrenko@tarantool.org>
To: Serge Petrenko <sergepetrenko@tarantool.org>
Cc: tarantool-patches@freelists.org
List-ID: <tarantool-patches.dev.tarantool.org>

On Fri, Mar 15, 2019 at 07:02:38PM +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.
> 
> Related to #4040
> ---
> https://github.com/tarantool/tarantool/tree/sp/xrow-decode-verbose-err
> 
> 
>  src/box/xrow.c | 27 +++++++++++++++++++++++++++
>  1 file changed, 27 insertions(+)
> 
> diff --git a/src/box/xrow.c b/src/box/xrow.c
> index bddae1d5b..8a5254902 100644
> --- a/src/box/xrow.c
> +++ b/src/box/xrow.c
> @@ -88,14 +88,29 @@ mp_decode_vclock(const char **data, struct vclock *vclock)
>  	return 0;
>  }
>  
> +static inline void
> +say_dump_row_hex(const char *start, const char *end)
> +{
> +	char *buf = (char *)malloc(3 * (end - start) + 1);

Theoretically, malloc() may fail. You'd better check it and print
a warning in this case. Anyway, do we really need to use malloc()
here at all? Won't tt_static_buf be enough for typical cases.

> +	char *pos = buf;
> +	for (const char *cur = start; cur < end; ++cur) {
> +		pos += sprintf(pos, "%02hhX ", *cur);
> +	}
> +	*pos = 0;
> +	say_verbose("Corrupted row is: %s", buf);

say_verbose() will turn into no-op, but you allocate a buffer and format
the message anyway. Please fix that by using say_log_level_is_enabled()
before doing anything.

> +	free(buf);
> +}
> +
>  int
>  xrow_header_decode(struct xrow_header *header, const char **pos,
>  		   const char *end, bool end_is_exact)
>  {
>  	memset(header, 0, sizeof(struct xrow_header));
>  	const char *tmp = *pos;
> +	const char * const start = *pos;
>  	if (mp_check(&tmp, end) != 0) {
>  error:
> +		say_dump_row_hex(start, end);
>  		diag_set(ClientError, ER_INVALID_MSGPACK, "packet header");
>  		return -1;
>  	}
> @@ -163,6 +178,7 @@ error:
>  	if (*pos < end && header->type != IPROTO_NOP) {
>  		const char *body = *pos;
>  		if (mp_check(pos, end)) {
> +			say_dump_row_hex(start, end);
>  			diag_set(ClientError, ER_INVALID_MSGPACK, "packet body");
>  			return -1;
>  		}
> @@ -171,6 +187,7 @@ error:
>  		header->body[0].iov_len = *pos - body;
>  	}
>  	if (end_is_exact && *pos < end) {
> +		say_dump_row_hex(start,end);
>  		diag_set(ClientError, ER_INVALID_MSGPACK, "packet body");

It would be better to add a helper function that would set diag and
print a corrupted row so that we don't miss it in case we add another
point of failure. Dunno, may be it's even worth adding a new exception
class with logging built in.