Re: [Tarantool-patches] [PATCH v2 1/5] error: Add a Lua backtrace to error

[Vladislav Shpilevoy <v.shpilevoy@tarantool.org>]

Thanks for the patch!

Sorry, some of my comments may contain typos, because it is
very late and I can't continue polishing it today.

First of all there are some major issues with the
patch, which IMO should be clarified before it is pushed.

1) Why do we need the traceback in scope of 4398? It has
nothing to do with marshaling through IProto, nor with
custom error types.

2) What to do with stacked errors? Currently only the first
error in the stack gets a traceback, because luaT_pusherror() is
called only on the top error in the stack. Consider this test:

    box.cfg{}
    lua_code = [[function(tuple)
                    local json = require('json')
                    return json.encode(tuple)
                 end]]
    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'}}})

    function test_func() return pcall(s.insert, s, {1}) end
    box.error.cfg{traceback_enable = true}
    ok, err = test_func()


    tarantool> err:unpack()
    ---
    - traceback: "stack traceback:\n\t[C]: at 0x010014d1b0\n\t[C]: in function 'test_func'\n\t[string
        \"ok, err = test_func()\"]:1: in main chunk\n\t[C]: in function 'pcall'\n\tbuiltin/box/console.lua:382:
        in function 'eval'\n\tbuiltin/box/console.lua:676: in function 'repl'\n\tbuiltin/box/console.lua:725:
        in function <builtin/box/console.lua:713>"
    ... <snipped>

    tarantool> err.prev:unpack()
    ---
    - type: LuajitError
      message: '[string "return function(tuple)..."]:2: attempt to call global ''require''
        (a nil value)'
    ... <snipped>

The second error does not have a traceback at all.


See 10 comments below. Also I started a new branch with review
fixes to speed up the process. The branch is called

    lvasiliev/gh-4398-expose-error-module-4-review

You can find review fixes to this commit in the end of the
email and on this branch in a separate commit. Note, my branch
is rebased on master already. So some changes are related to
cleaning the mess after it.

On 10/04/2020 10:10, Leonid Vasiliev wrote:
> In accordance with https://github.com/tarantool/tarantool/issues/4398

1. We don't put links when issue is in the same repository.
We always use '#<number>' reference. This concerns this and all
next commits.

> Lua traceback has been added for box.error.
> Has been added a per server flag for turn on/off traceback adding
> and ability to force it at creation time.
> 
> @TarantoolBot document
> Title: error.traceback
> Was added:
> Per server flag for turn on/off adding a traceback to the errors.
> box.error.cfg({traceback_supplementation = true/false})

2. The option name is utterly overcomplicated. Just use

    traceback_enable

> Adding a traceback can be forced on creation.
> box.error.new({type = "CustomType", reason = "reason", traceback = true/false})

3. CustomType errors are not defined here, you can't use it in
the request description.

> Needed for #4398

4. Please, don't put issue references inside docbot requests. This
concerns this and all next commits.

> ---
>  src/box/lua/error.cc          | 33 ++++++++++++++++++++++++++++++++-
>  src/lib/core/diag.c           | 32 ++++++++++++++++++++++++++++++++
>  src/lib/core/diag.h           | 11 +++++++++++
>  src/lib/core/exception.cc     |  1 +
>  src/lua/error.c               | 10 ++++++++++
>  src/lua/error.lua             | 12 +++++++++++-
>  test/app/fiber.result         |  5 +++--
>  test/box/error.result         |  5 +++--
>  test/engine/func_index.result | 10 ++++++----
>  9 files changed, 109 insertions(+), 10 deletions(-)
> 
> diff --git a/src/box/lua/error.cc b/src/box/lua/error.cc
> index b2625bf..4432bc8 100644
> --- a/src/box/lua/error.cc
> +++ b/src/box/lua/error.cc> @@ -180,6 +193,20 @@ luaT_error_set(struct lua_State *L)
>  }
>  
>  static int
> +luaT_error_cfg(struct lua_State *L)
> +{
> +	if (lua_gettop(L) < 1 || !lua_istable(L, 1))
> +		return luaL_error(L, "Usage: box.error.cfg({}})");
> +
> +	lua_getfield(L, 1, "traceback_supplementation");
> +	if (lua_isnil(L, -1) == 0)

5. If something is not nil, it does not mean it is a boolean.
Better check lua_isboolean().

> +		error_set_traceback_supplementation(lua_toboolean(L, -1));
> +	lua_pop(L, 1);
> +
> +	return 0;
> +}
> diff --git a/src/lib/core/diag.c b/src/lib/core/diag.c
> index e143db1..1caa75e 100644
> --- a/src/lib/core/diag.c
> +++ b/src/lib/core/diag.c
> @@ -120,3 +127,28 @@ error_vformat_msg(struct error *e, const char *format, va_list ap)
>  	vsnprintf(e->errmsg, sizeof(e->errmsg), format, ap);
>  }
>  
> +void
> +error_set_lua_traceback(struct error *e, const char *lua_traceback)
> +{
> +	if (e == NULL)
> +		return;

6. It makes no sense to call this function on a NULL 'e'. This
should be an assertion. As well as it is not possible to 'reset'
the trace, so e->lua_traceback should be always NULL here.

7. Also I don't think it is a good idea to call traceback attribute
'lua_traceback'. Because we won't have separated 'lua_traceback'
and 'c_traceback'. Anyway there will be always only one. Probably
with C and Lua mixed (it is possible via space triggers to mix Lua
and C in layers).

> +
> +	if (lua_traceback == NULL) {
> +		free(e->lua_traceback);
> +		e->lua_traceback = NULL;
> +		return;
> +	}
> +
> +	size_t tb_len = strlen(lua_traceback);
> +	e->lua_traceback = realloc(e->lua_traceback, tb_len + 1);
> +	if (e->lua_traceback == NULL)
> +		return;
> +	strcpy(e->lua_traceback, lua_traceback);
> +	return;
> +}
> +
> +void
> +error_set_traceback_supplementation(bool traceback_mode)
> +{
> +	global_traceback_mode = traceback_mode;
> +}
> diff --git a/src/lua/error.lua b/src/lua/error.lua
> index bdc9c71..46d2866 100644
> --- a/src/lua/error.lua
> +++ b/src/lua/error.lua
> @@ -92,6 +94,14 @@ local function error_trace(err)
>      }
>  end
>  
> +local function error_traceback(err)
> +    local result = "Traceback is absent"

8. I don't think it is a good idea to add this to
every error object when there is no a trace. Just
leave it nil.

> +    if err.lua_traceback ~= ffi.nullptr then
> +        result = ffi.string(err.lua_traceback)
> +    end
> +    return result
> +end
> +
>  local function error_errno(err)
>      local e = err._saved_errno
>      if e == 0 then
> @@ -122,7 +132,6 @@ local function error_set_prev(err, prev)
>      if ok ~= 0 then
>          error("Cycles are not allowed")
>      end
> -

9. Please, avoid unnecessary diff.

>  end
>  
>  local error_fields = {
> diff --git a/test/engine/func_index.result b/test/engine/func_index.result
> index a827c92..28befca 100644
> --- a/test/engine/func_index.result
> +++ b/test/engine/func_index.result
> @@ -291,12 +292,13 @@ e = e.prev
>   | ...
>  e:unpack()
>   | ---
> - | - type: LuajitError
> - |   message: '[string "return function(tuple)                 local ..."]:1: attempt
> - |     to call global ''require'' (a nil value)'
> + | - traceback: Traceback is absent
>   |   trace:
>   |   - file: <filename>
>   |     line: <line>
> + |   type: LuajitError
> + |   message: '[string "return function(tuple)                 local ..."]:1: attempt
> + |     to call global ''require'' (a nil value)'
>   | ...
>  e = e.prev
>   | ---

10. Usually every commit should add tests on the feature it
introduces. You didn't add any single test. Why?

Consider my review fixes below and on a new branch in a
separate commit. It solves all the code-related problems,
but I still don't know what to do with the major issues
described in the beginning.

Branch is:

    lvasiliev/gh-4398-expose-error-module-4-review

====================
    Review fixes
    
    New commit message proposal:
    
    error: add a Lua traceback to error
    
    Lua backtrace can be enabled for all errors using a server-wide
    option, or on a per-error basis using box.error() and
    box.error.new() arguments.
    
    Needed for #4398
    
    @TarantoolBot document
    Title: Lua error.traceback
    
    Lua error objects now feature 'traceback' optional attribute.
    It contains Lua traceback. C part is not present here.
    
    Traceback collection is a relatively expensive operation, so it
    is disabled by default. In case you need to enable it, there are
    2 options:
    
    * Global option `traceback_enable` for `box.error.cfg` call:
    ```
        box.error.cfg({traceback_enable = true})
    ```
    
    * Per object option, in case you want traceback only for certain
    cases:
    ```
        box.error.new({
            code = 1000,
            reason = 'Reason',
            traceback = true/false
        })
    ```

diff --git a/src/box/lua/error.cc b/src/box/lua/error.cc
index 4432bc89b..a616e87a4 100644
--- a/src/box/lua/error.cc
+++ b/src/box/lua/error.cc
@@ -54,8 +54,8 @@ luaT_error_create(lua_State *L, int top_base)
 {
 	uint32_t code = 0;
 	const char *reason = NULL;
-	bool tb_parsed = false;
-	bool tb_mode = false;
+	bool is_traceback_enabled = false;
+	bool is_traceback_specified = false;
 	const char *file = "";
 	unsigned line = 0;
 	lua_Debug info;
@@ -91,10 +91,10 @@ luaT_error_create(lua_State *L, int top_base)
 		lua_pop(L, 1);
 		lua_getfield(L, top_base, "traceback");
 		if (lua_isboolean(L, -1)) {
-			tb_parsed = true;
-			tb_mode = lua_toboolean(L, -1);
+			is_traceback_enabled = lua_toboolean(L, -1);
+			is_traceback_specified = true;
 		}
-		lua_pop(L, -1);
+		lua_pop(L, 1);
 	} else {
 		return NULL;
 	}
@@ -112,9 +112,11 @@ raise:
 	}
 
 	struct error *err = box_error_new(file, line, code, "%s", reason);
-	if (tb_parsed)
-		err->traceback_mode = tb_mode;
-
+	/*
+	 * Explicit traceback option overrides the global setting.
+	 */
+	if (err != NULL && is_traceback_specified)
+		err->is_traceback_enabled = is_traceback_enabled;
 	return err;
 }
 
@@ -198,11 +200,9 @@ luaT_error_cfg(struct lua_State *L)
 	if (lua_gettop(L) < 1 || !lua_istable(L, 1))
 		return luaL_error(L, "Usage: box.error.cfg({}})");
 
-	lua_getfield(L, 1, "traceback_supplementation");
-	if (lua_isnil(L, -1) == 0)
-		error_set_traceback_supplementation(lua_toboolean(L, -1));
-	lua_pop(L, 1);
-
+	lua_getfield(L, 1, "traceback_enable");
+	if (lua_isboolean(L, -1))
+		error_is_traceback_enabled = lua_toboolean(L, -1);
 	return 0;
 }
 
diff --git a/src/lib/core/diag.c b/src/lib/core/diag.c
index 1caa75ee9..833454bac 100644
--- a/src/lib/core/diag.c
+++ b/src/lib/core/diag.c
@@ -31,10 +31,7 @@
 #include "diag.h"
 #include "fiber.h"
 
-/**
- * Global flag to add or not backtrace to errors.
- */
-static bool global_traceback_mode = false;
+bool error_is_traceback_enabled = false;
 
 int
 error_set_prev(struct error *e, struct error *prev)
@@ -102,8 +99,8 @@ error_create(struct error *e,
 	e->errmsg[0] = '\0';
 	e->cause = NULL;
 	e->effect = NULL;
-	e->lua_traceback = NULL;
-	e->traceback_mode = global_traceback_mode;
+	e->traceback = NULL;
+	e->is_traceback_enabled = error_is_traceback_enabled;
 }
 
 struct diag *
@@ -128,27 +125,14 @@ error_vformat_msg(struct error *e, const char *format, va_list ap)
 }
 
 void
-error_set_lua_traceback(struct error *e, const char *lua_traceback)
-{
-	if (e == NULL)
-		return;
-
-	if (lua_traceback == NULL) {
-		free(e->lua_traceback);
-		e->lua_traceback = NULL;
-		return;
-	}
-
-	size_t tb_len = strlen(lua_traceback);
-	e->lua_traceback = realloc(e->lua_traceback, tb_len + 1);
-	if (e->lua_traceback == NULL)
-		return;
-	strcpy(e->lua_traceback, lua_traceback);
-	return;
-}
-
-void
-error_set_traceback_supplementation(bool traceback_mode)
+error_set_traceback(struct error *e, const char *traceback)
 {
-	global_traceback_mode = traceback_mode;
+	assert(e->traceback == NULL);
+	e->traceback = strdup(traceback);
+	/*
+	 * Don't try to set it again. Traceback can be NULL in case of OOM, so
+	 * it is not a reliable source of information whether need to collect a
+	 * traceback.
+	 */
+	e->is_traceback_enabled = false;
 }
diff --git a/src/lib/core/diag.h b/src/lib/core/diag.h
index f38009c54..e918d3089 100644
--- a/src/lib/core/diag.h
+++ b/src/lib/core/diag.h
@@ -42,6 +42,13 @@
 extern "C" {
 #endif /* defined(__cplusplus) */
 
+/**
+ * Flag to turn on/off traceback automatic collection. Currently
+ * it works only for Lua. Stack is collected at the moment of
+ * error object push onto the stack.
+ */
+extern bool error_is_traceback_enabled;
+
 enum {
 	DIAG_ERRMSG_MAX = 512,
 	DIAG_FILENAME_MAX = 256
@@ -110,8 +117,19 @@ struct error {
 	 */
 	struct error *cause;
 	struct error *effect;
-	char *lua_traceback;
-	bool traceback_mode;
+	/**
+	 * Optional traceback. At the moment it can contain only
+	 * Lua traceback, and only when it is requested
+	 * explicitly.
+	 */
+	char *traceback;
+	/**
+	 * Flag whether a traceback should be collected when the
+	 * error object is exposed to a user next time. When the
+	 * tracing is disabled, or it is enabled but already
+	 * collected for this error object, it becomes false.
+	 */
+	bool is_traceback_enabled;
 };
 
 static inline void
@@ -174,6 +192,14 @@ error_unlink_effect(struct error *e)
 int
 error_set_prev(struct error *e, struct error *prev);
 
+/**
+ * Set traceback of @a e error object. It can be done only once.
+ * In case of OOM the traceback is kept NULL, and can't be
+ * collected again.
+ */
+void
+error_set_traceback(struct error *e, const char *traceback);
+
 NORETURN static inline void
 error_raise(struct error *e)
 {
@@ -199,15 +225,6 @@ error_format_msg(struct error *e, const char *format, ...);
 void
 error_vformat_msg(struct error *e, const char *format, va_list ap);
 
-void
-error_set_lua_traceback(struct error *e, const char *lua_traceback);
-
-/**
-* Sets the global flag to add or not backtrace to errors.
-*/
-void
-error_set_traceback_supplementation(bool traceback_mode);
-
 /**
  * Diagnostics Area - a container for errors
  */
diff --git a/src/lib/core/exception.cc b/src/lib/core/exception.cc
index 0e4b6ca8b..1717b76fb 100644
--- a/src/lib/core/exception.cc
+++ b/src/lib/core/exception.cc
@@ -42,7 +42,7 @@ extern "C" {
 static void
 exception_destroy(struct error *e)
 {
-	free(e->lua_traceback);
+	free(e->traceback);
 	delete (Exception *) e;
 }
 
diff --git a/src/lua/error.c b/src/lua/error.c
index cd6ab54b1..a21548ce6 100644
--- a/src/lua/error.c
+++ b/src/lua/error.c
@@ -86,12 +86,11 @@ luaT_pusherror(struct lua_State *L, struct error *e)
 	 */
 	error_ref(e);
 
-	if (e->lua_traceback == NULL && e->traceback_mode) {
+	if (e->traceback == NULL && e->is_traceback_enabled) {
 		int top = lua_gettop(L);
 		luaL_traceback(L, L, NULL, 0);
-		if (lua_isstring(L, -1)) {
-			error_set_lua_traceback(e, lua_tostring(L, -1));
-		}
+		if (lua_isstring(L, -1))
+			error_set_traceback(e, lua_tostring(L, -1));
 		lua_settop(L, top);
 	}
 
diff --git a/src/lua/error.lua b/src/lua/error.lua
index 46d28667f..535110588 100644
--- a/src/lua/error.lua
+++ b/src/lua/error.lua
@@ -26,8 +26,8 @@ struct error {
     char _errmsg[DIAG_ERRMSG_MAX];
     struct error *_cause;
     struct error *_effect;
-    char *lua_traceback;
-    bool traceback_mode;
+    char *traceback;
+    bool is_traceback_enabled;
 };
 
 char *
@@ -95,11 +95,7 @@ local function error_trace(err)
 end
 
 local function error_traceback(err)
-    local result = "Traceback is absent"
-    if err.lua_traceback ~= ffi.nullptr then
-        result = ffi.string(err.lua_traceback)
-    end
-    return result
+    return err.traceback ~= ffi.nullptr and ffi.string(err.traceback) or nil
 end
 
 local function error_errno(err)
@@ -132,6 +128,7 @@ local function error_set_prev(err, prev)
     if ok ~= 0 then
         error("Cycles are not allowed")
     end
+
 end
 
 local error_fields = {
diff --git a/test/app/fiber.result b/test/app/fiber.result
index fc6b3c92d..debfc6718 100644
--- a/test/app/fiber.result
+++ b/test/app/fiber.result
@@ -1038,13 +1038,12 @@ st;
 ...
 e:unpack();
 ---
-- traceback: Traceback is absent
+- type: ClientError
   code: 1
+  message: Illegal parameters, oh my
   trace:
   - file: '[string "function err() box.error(box.error.ILLEGAL_PA..."]'
     line: 1
-  type: ClientError
-  message: Illegal parameters, oh my
 ...
 flag = false;
 ---
diff --git a/test/box/error.result b/test/box/error.result
index 574bc481f..2502d88c4 100644
--- a/test/box/error.result
+++ b/test/box/error.result
@@ -34,13 +34,12 @@ e
  | ...
 e:unpack()
  | ---
- | - traceback: Traceback is absent
+ | - type: ClientError
  |   code: 1
+ |   message: Illegal parameters, bla bla
  |   trace:
  |   - file: '[C]'
  |     line: 4294967295
- |   type: ClientError
- |   message: Illegal parameters, bla bla
  | ...
 e.type
  | ---
@@ -832,3 +831,62 @@ assert(box.error.last() == e1)
  | ---
  | - true
  | ...
+
+--
+-- gh-4398: Lua traceback for errors.
+--
+function t1(traceback, throw)                                                   \
+    local opts = {code = 0, reason = 'Reason', traceback = traceback}           \
+    if throw then                                                               \
+        box.error(opts)                                                         \
+    else                                                                        \
+        return box.error.new(opts)                                              \
+    end                                                                         \
+end
+ | ---
+ | ...
+function t2(...) return t1(...), nil end
+ | ---
+ | ...
+function t3(...) return t2(...), nil end
+ | ---
+ | ...
+
+function check_trace(trace)                                                     \
+    local t1loc = trace:find('t1')                                              \
+    local t2loc = trace:find('t2')                                              \
+    local t3loc = trace:find('t3')                                              \
+    return t1loc < t2loc and t2loc < t3loc or {t1loc, t2loc, t3loc, trace}      \
+end
+ | ---
+ | ...
+
+check_trace(t3(true, false):unpack().traceback)
+ | ---
+ | - true
+ | ...
+
+box.error.cfg{traceback_enable = true}
+ | ---
+ | ...
+-- Explicit 'traceback = false' overrides the global setting.
+t3(false, false):unpack().traceback
+ | ---
+ | - null
+ | ...
+-- When explicit option is not specified, global setting works.
+check_trace(t3(nil, false):unpack().traceback)
+ | ---
+ | - true
+ | ...
+
+box.error.cfg{traceback_enable = false}
+ | ---
+ | ...
+_, e = pcall(t3, true, true)
+ | ---
+ | ...
+check_trace(e:unpack().traceback)
+ | ---
+ | - true
+ | ...
diff --git a/test/box/error.test.lua b/test/box/error.test.lua
index 41baed52d..6f1271630 100644
--- a/test/box/error.test.lua
+++ b/test/box/error.test.lua
@@ -229,3 +229,36 @@ box.error({code = 111, reason = "err"})
 box.error.last()
 box.error(e1)
 assert(box.error.last() == e1)
+
+--
+-- gh-4398: Lua traceback for errors.
+--
+function t1(traceback, throw)                                                   \
+    local opts = {code = 0, reason = 'Reason', traceback = traceback}           \
+    if throw then                                                               \
+        box.error(opts)                                                         \
+    else                                                                        \
+        return box.error.new(opts)                                              \
+    end                                                                         \
+end
+function t2(...) return t1(...), nil end
+function t3(...) return t2(...), nil end
+
+function check_trace(trace)                                                     \
+    local t1loc = trace:find('t1')                                              \
+    local t2loc = trace:find('t2')                                              \
+    local t3loc = trace:find('t3')                                              \
+    return t1loc < t2loc and t2loc < t3loc or {t1loc, t2loc, t3loc, trace}      \
+end
+
+check_trace(t3(true, false):unpack().traceback)
+
+box.error.cfg{traceback_enable = true}
+-- Explicit 'traceback = false' overrides the global setting.
+t3(false, false):unpack().traceback
+-- When explicit option is not specified, global setting works.
+check_trace(t3(nil, false):unpack().traceback)
+
+box.error.cfg{traceback_enable = false}
+_, e = pcall(t3, true, true)
+check_trace(e:unpack().traceback)
diff --git a/test/engine/func_index.result b/test/engine/func_index.result
index 28befca39..a827c929f 100644
--- a/test/engine/func_index.result
+++ b/test/engine/func_index.result
@@ -276,8 +276,7 @@ e = box.error.last()
  | ...
 e:unpack()
  | ---
- | - traceback: Traceback is absent
- |   code: 198
+ | - code: 198
  |   trace:
  |   - file: <filename>
  |     line: <line>
@@ -292,13 +291,12 @@ e = e.prev
  | ...
 e:unpack()
  | ---
- | - traceback: Traceback is absent
+ | - type: LuajitError
+ |   message: '[string "return function(tuple)                 local ..."]:1: attempt
+ |     to call global ''require'' (a nil value)'
  |   trace:
  |   - file: <filename>
  |     line: <line>
- |   type: LuajitError
- |   message: '[string "return function(tuple)                 local ..."]:1: attempt
- |     to call global ''require'' (a nil value)'
  | ...
 e = e.prev
  | ---