[tarantool-patches] [PATCH v3 6/6] iproto: support stacked diagnostics for errors

[Kirill Shcherbatov <kshcherbatov@tarantool.org>]

Introduced a new iproto message key IPROTO_ERROR_V2 to support
errors stacked diagnostics. This key extends iproto protocol
messages to have the following structure:
{
	// backward compatibility
	IPROTO_ERROR: "the most recent error message",
	// modern error message
        IPROTO_ERROR_V2: {
		{
			// the most recent error object
			"code": error_code_number,
			"reason": error_reason_string,
			"file": file_name_string,
			"line": line_number,
		},
		...
		{
			// the oldest (reason) error object
		},
	}
}

Such messages are decoded with updated netbox client and applier.
The legacy format with IPROTO_ERROR is kept to provide backward
compatibility in distributed environment.

Closes #1148
---
 src/box/iproto_constants.h |   1 +
 src/box/xrow.c             | 126 ++++++++++++++++++++++++++++++++-----
 src/box/lua/net_box.lua    |  24 ++++++-
 test/box-py/iproto.result  |   6 +-
 test/box-py/iproto.test.py |   6 +-
 test/box/misc.result       |  82 ++++++++++++++++++++++++
 test/box/misc.test.lua     |  27 ++++++++
 7 files changed, 248 insertions(+), 24 deletions(-)

diff --git a/src/box/iproto_constants.h b/src/box/iproto_constants.h
index 724cce535..c190895c5 100644
--- a/src/box/iproto_constants.h
+++ b/src/box/iproto_constants.h
@@ -120,6 +120,7 @@ enum iproto_key {
 	 * }
 	 */
 	IPROTO_SQL_INFO = 0x42,
+	IPROTO_ERROR_V2 = 0x43,
 	IPROTO_KEY_MAX
 };
 
diff --git a/src/box/xrow.c b/src/box/xrow.c
index e1e0a62be..42b9f4f99 100644
--- a/src/box/xrow.c
+++ b/src/box/xrow.c
@@ -41,6 +41,7 @@
 #include "tt_static.h"
 #include "error.h"
 #include "vclock.h"
+#include "mpstream.h"
 #include "scramble.h"
 #include "iproto_constants.h"
 #include "mpstream.h"
@@ -479,12 +480,34 @@ mpstream_error_handler(void *error_ctx)
 	*(bool *)error_ctx = true;
 }
 
+#define IPROTO_ERROR_V2_CODE   "code"
+#define IPROTO_ERROR_V2_REASON "reason"
+#define IPROTO_ERROR_V2_FILE   "file"
+#define IPROTO_ERROR_V2_LINE   "line"
+
 static void
 mpstream_iproto_encode_error(struct mpstream *stream, const struct error *error)
 {
 	mpstream_encode_map(stream, 2);
 	mpstream_encode_uint(stream, IPROTO_ERROR);
 	mpstream_encode_str(stream, error->errmsg);
+
+	mpstream_encode_uint(stream, IPROTO_ERROR_V2);
+	uint32_t stack_sz = 0;
+	for (const struct error *it = error; it != NULL; it = it->prev)
+		stack_sz++;
+	mpstream_encode_array(stream, stack_sz);
+	for (const struct error *it = error; it != NULL; it = it->prev) {
+		mpstream_encode_map(stream, 4);
+		mpstream_encode_str(stream, IPROTO_ERROR_V2_CODE);
+		mpstream_encode_uint(stream, box_error_code(it));
+		mpstream_encode_str(stream, IPROTO_ERROR_V2_REASON);
+		mpstream_encode_str(stream, it->errmsg);
+		mpstream_encode_str(stream, IPROTO_ERROR_V2_FILE);
+		mpstream_encode_str(stream, it->file);
+		mpstream_encode_str(stream, IPROTO_ERROR_V2_LINE);
+		mpstream_encode_uint(stream, it->line);
+	}
 }
 
 int
@@ -1056,44 +1079,117 @@ xrow_encode_auth(struct xrow_header *packet, const char *salt, size_t salt_len,
 	return 0;
 }
 
+static int
+iproto_decode_error(const char **pos, uint32_t errcode, enum iproto_key *key)
+{
+	char reason[DIAG_ERRMSG_MAX] = {0};
+	char filename[DIAG_FILENAME_MAX] = {0};
+
+	*key = (enum iproto_key)mp_decode_uint(pos);
+	if (*key == IPROTO_ERROR && mp_typeof(**pos) == MP_STR) {
+		/* Legacy IPROTO_ERROR error. */
+		uint32_t len;
+		const char *str = mp_decode_str(pos, &len);
+		snprintf(reason, sizeof(reason), "%.*s", len, str);
+		box_error_set(__FILE__, __LINE__, errcode, NULL, reason);
+		return 0;
+	} else if (*key != IPROTO_ERROR_V2 || mp_typeof(**pos) != MP_ARRAY) {
+		/* Corrupted frame. */
+		return -1;
+	}
+
+	assert(*key == IPROTO_ERROR_V2 && mp_typeof(**pos) == MP_ARRAY);
+	struct error *prev = NULL;
+	uint32_t stack_sz = mp_decode_array(pos);
+	for (uint32_t stack_idx = 0; stack_idx < stack_sz; stack_idx++) {
+		filename[0] = reason[0] = 0;
+		uint32_t code = errcode, line = 0;
+		if (mp_typeof(**pos) != MP_MAP)
+			return -1;
+		uint32_t map_sz = mp_decode_map(pos);
+		for (uint32_t key_idx = 0; key_idx < map_sz; key_idx++) {
+			uint32_t len;
+			const char *str = mp_decode_str(pos, &len);
+			if (len == strlen(IPROTO_ERROR_V2_CODE) &&
+			    memcmp(str, IPROTO_ERROR_V2_CODE, len) == 0) {
+				if (mp_typeof(**pos) != MP_UINT)
+					return -1;
+				code = mp_decode_uint(pos);
+			} else if (len == strlen(IPROTO_ERROR_V2_REASON) &&
+				memcmp(str, IPROTO_ERROR_V2_REASON, len) == 0) {
+				if (mp_typeof(**pos) != MP_STR)
+					return -1;
+				uint32_t len;
+				const char *str = mp_decode_str(pos, &len);
+				snprintf(reason, sizeof(reason), "%.*s",
+					 len, str);
+			} else if (len == strlen(IPROTO_ERROR_V2_FILE) &&
+				   memcmp(str, IPROTO_ERROR_V2_FILE,
+					  len) == 0) {
+				if (mp_typeof(**pos) != MP_STR)
+					return -1;
+				uint32_t len;
+				const char *str = mp_decode_str(pos, &len);
+				snprintf(filename, sizeof(filename), "%.*s",
+					 len, str);
+			} else if (len == strlen(IPROTO_ERROR_V2_LINE) &&
+				   memcmp(str, IPROTO_ERROR_V2_LINE,
+					  len) == 0) {
+				if (mp_typeof(**pos) != MP_UINT)
+					return -1;
+				line = mp_decode_uint(pos);
+			} else {
+				return -1;
+			}
+		}
+		box_error_set(filename[0] == 0 ? __FILE__ : filename,
+			      line == 0 ? __LINE__ : line, code, prev, reason);
+		prev = diag_last_error(diag_get());
+	}
+	return 0;
+}
+
 void
 xrow_decode_error(struct xrow_header *row)
 {
 	uint32_t code = row->type & (IPROTO_TYPE_ERROR - 1);
-
-	char error[DIAG_ERRMSG_MAX] = { 0 };
-	const char *pos;
-	uint32_t map_size;
-
 	if (row->bodycnt == 0)
 		goto error;
-	pos = (char *) row->body[0].iov_base;
+	const char *pos = (char *) row->body[0].iov_base;
 	if (mp_check(&pos, pos + row->body[0].iov_len))
 		goto error;
 
 	pos = (char *) row->body[0].iov_base;
 	if (mp_typeof(*pos) != MP_MAP)
 		goto error;
-	map_size = mp_decode_map(&pos);
+	bool is_error_set = false;
+	uint32_t map_size = mp_decode_map(&pos);
 	for (uint32_t i = 0; i < map_size; i++) {
 		if (mp_typeof(*pos) != MP_UINT) {
 			mp_next(&pos); /* key */
 			mp_next(&pos); /* value */
 			continue;
 		}
-		uint8_t key = mp_decode_uint(&pos);
-		if (key != IPROTO_ERROR || mp_typeof(*pos) != MP_STR) {
+		enum iproto_key key;
+		if (iproto_decode_error(&pos, code, &key) != 0) {
 			mp_next(&pos); /* value */
 			continue;
 		}
-
-		uint32_t len;
-		const char *str = mp_decode_str(&pos, &len);
-		snprintf(error, sizeof(error), "%.*s", len, str);
+		/*
+		 * New tnt instances send both legacy
+		 * IPROTO_ERROR and IPROTO_ERROR_V2 error
+		 * messages. Prefer an error message is
+		 * constructed with IPROTO_ERROR_V2 payload.
+		 */
+		is_error_set = true;
+		if (key == IPROTO_ERROR_V2)
+			return;
+		assert(key == IPROTO_ERROR);
 	}
-
+	if (is_error_set)
+		return;
 error:
-	box_error_set(__FILE__, __LINE__, code, NULL, error);
+	box_error_set(__FILE__, __LINE__, code, NULL, NULL);
 }
 
 void
diff --git a/src/box/lua/net_box.lua b/src/box/lua/net_box.lua
index 31a8c16b7..3d70d59b5 100644
--- a/src/box/lua/net_box.lua
+++ b/src/box/lua/net_box.lua
@@ -47,6 +47,7 @@ local IPROTO_ERROR_KEY     = 0x31
 local IPROTO_GREETING_SIZE = 128
 local IPROTO_CHUNK_KEY     = 128
 local IPROTO_OK_KEY        = 0
+local IPROTO_ERROR_V2_KEY  = 0x43
 
 -- select errors from box.error
 local E_UNKNOWN              = box.error.UNKNOWN
@@ -273,8 +274,20 @@ local function create_transport(host, port, user, password, callback,
     --
     function request_index:result()
         if self.errno then
-            return nil, box.error.new({code = self.errno,
-                                       reason = self.response})
+            if type(self.response) == 'table' then
+                local prev = nil
+                for i = #self.response,1,-1 do
+                    local error = self.response[i]
+                    prev = box.error.new({code = error.code,
+                                          reason = error.reason,
+                                          file = error.file, line = error.line,
+                                          prev = prev})
+                end
+                return nil, prev
+            else
+                return nil, box.error.new({code = self.errno,
+                                           reason = self.response})
+            end
         elseif not self.id then
             return self.response
         elseif not worker_fiber then
@@ -555,7 +568,12 @@ local function create_transport(host, port, user, password, callback,
             body, body_end_check = decode(body_rpos)
             assert(body_end == body_end_check, "invalid xrow length")
             request.errno = band(status, IPROTO_ERRNO_MASK)
-            request.response = body[IPROTO_ERROR_KEY]
+            if body[IPROTO_ERROR_V2_KEY] ~= nil then
+                request.response = body[IPROTO_ERROR_V2_KEY]
+                assert(type(request.response) == 'table')
+            else
+                request.response = body[IPROTO_ERROR_KEY]
+            end
             request.cond:broadcast()
             return
         end
diff --git a/test/box-py/iproto.result b/test/box-py/iproto.result
index 900e6e24f..04e2e220c 100644
--- a/test/box-py/iproto.result
+++ b/test/box-py/iproto.result
@@ -169,9 +169,9 @@ box.schema.user.revoke('guest', 'read,write,execute', 'universe')
 # Test bugs gh-272, gh-1654 if the packet was incorrect, respond with
 # an error code and do not close connection
 
-sync=0, {49: 'Invalid MsgPack - packet header'}
-sync=1234, {49: "Missing mandatory field 'space id' in request"}
-sync=5678, {49: "Read access to space '_user' is denied for user 'guest'"}
+sync=0, Invalid MsgPack - packet header
+sync=1234, Missing mandatory field 'space id' in request
+sync=5678, Read access to space '_user' is denied for user 'guest'
 space = box.schema.space.create('test_index_base', { id = 568 })
 ---
 ...
diff --git a/test/box-py/iproto.test.py b/test/box-py/iproto.test.py
index 77637d8ed..cdd1a71c5 100644
--- a/test/box-py/iproto.test.py
+++ b/test/box-py/iproto.test.py
@@ -355,15 +355,15 @@ s = c._socket
 header = { "hello": "world"}
 body = { "bug": 272 }
 resp = test_request(header, body)
-print 'sync=%d, %s' % (resp['header'][IPROTO_SYNC], resp['body'])
+print 'sync=%d, %s' % (resp['header'][IPROTO_SYNC], resp['body'].get(IPROTO_ERROR))
 header = { IPROTO_CODE : REQUEST_TYPE_SELECT }
 header[IPROTO_SYNC] = 1234
 resp = test_request(header, body)
-print 'sync=%d, %s' % (resp['header'][IPROTO_SYNC], resp['body'])
+print 'sync=%d, %s' % (resp['header'][IPROTO_SYNC], resp['body'].get(IPROTO_ERROR))
 header[IPROTO_SYNC] = 5678
 body = { IPROTO_SPACE_ID: 304, IPROTO_KEY: [], IPROTO_LIMIT: 1 }
 resp = test_request(header, body)
-print 'sync=%d, %s' % (resp['header'][IPROTO_SYNC], resp['body'])
+print 'sync=%d, %s' % (resp['header'][IPROTO_SYNC], resp['body'].get(IPROTO_ERROR))
 c.close()
 
 
diff --git a/test/box/misc.result b/test/box/misc.result
index 8429bf191..5fcbed1e5 100644
--- a/test/box/misc.result
+++ b/test/box/misc.result
@@ -1398,3 +1398,85 @@ collectgarbage()
 ---
 - 0
 ...
+-- test stacked diagnostics with netbox
+test_run:cmd("push filter \"file: .*\" to \"file: <filename>\"")
+---
+- true
+...
+test_run:cmd("setopt delimiter ';'")
+---
+- true
+...
+lua_code = [[function(tuple)
+                local json = require('json')
+                return json.encode(tuple)
+             end]]
+test_run:cmd("setopt delimiter ''");
+---
+...
+box.schema.func.create('runtimeerror', {body = lua_code, is_deterministic = true, is_sandboxed = true})
+---
+...
+s = box.schema.space.create('withdata')
+---
+...
+pk = s:create_index('pk')
+---
+...
+idx = s:create_index('idx', {func = box.func.runtimeerror.id, parts = {{1, 'string'}}})
+---
+...
+box.schema.user.grant('guest', 'read,write,execute', 'universe')
+---
+...
+net = require('net.box')
+---
+...
+c = net.connect(os.getenv("LISTEN"))
+---
+...
+c.space.withdata:insert({1})
+---
+- error: 'Failed to build a key for functional index ''idx'' of space ''withdata'':
+    can''t evaluate function'
+...
+e = box.error.last()
+---
+...
+e:unpack()
+---
+- code: 198
+  trace:
+  - file: <filename>
+    line: 68
+  type: ClientError
+  prev: '[string "return function(tuple)                 local ..."]:1: attempt to
+    call global ''require'' (a nil value)'
+  message: 'Failed to build a key for functional index ''idx'' of space ''withdata'':
+    can''t evaluate function'
+  refs: 3
+...
+e.prev:unpack()
+---
+- code: 32
+  trace:
+  - file: <filename>
+    line: 1010
+  type: ClientError
+  message: '[string "return function(tuple)                 local ..."]:1: attempt
+    to call global ''require'' (a nil value)'
+  refs: 4
+...
+box.schema.user.revoke('guest', 'read,write,execute', 'universe')
+---
+...
+s:drop()
+---
+...
+box.func.runtimeerror:drop()
+---
+...
+test_run:cmd("clear filter")
+---
+- true
+...
diff --git a/test/box/misc.test.lua b/test/box/misc.test.lua
index f4444b470..195ed2882 100644
--- a/test/box/misc.test.lua
+++ b/test/box/misc.test.lua
@@ -405,3 +405,30 @@ collectgarbage()
 e1.refs == 1
 e1 = nil
 collectgarbage()
+
+-- test stacked diagnostics with netbox
+test_run:cmd("push filter \"file: .*\" to \"file: <filename>\"")
+test_run:cmd("setopt delimiter ';'")
+lua_code = [[function(tuple)
+                local json = require('json')
+                return json.encode(tuple)
+             end]]
+test_run:cmd("setopt delimiter ''");
+box.schema.func.create('runtimeerror', {body = lua_code, is_deterministic = true, is_sandboxed = true})
+s = box.schema.space.create('withdata')
+pk = s:create_index('pk')
+idx = s:create_index('idx', {func = box.func.runtimeerror.id, parts = {{1, 'string'}}})
+
+box.schema.user.grant('guest', 'read,write,execute', 'universe')
+net = require('net.box')
+c = net.connect(os.getenv("LISTEN"))
+c.space.withdata:insert({1})
+
+e = box.error.last()
+e:unpack()
+e.prev:unpack()
+
+box.schema.user.revoke('guest', 'read,write,execute', 'universe')
+s:drop()
+box.func.runtimeerror:drop()
+test_run:cmd("clear filter")
-- 
2.22.1