Skip to content

core: increase error logging verbosity from C#11716

Merged
locker merged 2 commits intotarantool:masterfrom
nshy:error-log-verbosity-c
Aug 11, 2025
Merged

core: increase error logging verbosity from C#11716
locker merged 2 commits intotarantool:masterfrom
nshy:error-log-verbosity-c

Conversation

@nshy
Copy link
Contributor

@nshy nshy commented Jul 25, 2025

When compat option box_error_serialize_verbose is set to new then tostring of Lua box error object prints error with increased verbosity. This affects logging error from Lua. Unfortunately it does not affect logging box error from C.

Let's move tostring logic to C code so we align logging from Lua and C.

Note that:

  • error is logged from C verbosly unconditionally (box_error_serialize_verbose is not taken into account)
  • details that printed before ':' are removed (error code for ClientError for example)

While at it we did next changes in tostring():

  • frames are printed from effect to cause
  • prefix Caused by: is added for cause frames

Note that say_logger_free() it patched so that logger can be reinitialized in unit/fiber.cc test.

Closes #10116
Follow-up #9105

@nshy nshy requested a review from a team as a code owner July 25, 2025 13:21
@nshy nshy requested a review from locker July 25, 2025 13:33
@coveralls
Copy link

coveralls commented Jul 25, 2025

Coverage Status

coverage: 87.602% (+0.01%) from 87.59%
when pulling 01f8489 on nshy:error-log-verbosity-c
into 634d063
on tarantool:master
.

@locker locker assigned nshy and unassigned locker Jul 25, 2025
@nshy nshy force-pushed the error-log-verbosity-c branch 2 times, most recently from 78ea954 to 41289f1 Compare July 30, 2025 07:54
@nshy nshy requested a review from Totktonada as a code owner July 30, 2025 07:54
@nshy nshy force-pushed the error-log-verbosity-c branch from 41289f1 to c61ba20 Compare July 30, 2025 08:19
@nshy nshy assigned locker and unassigned nshy Jul 30, 2025
@nshy nshy added the full-ci Enables all tests for a pull request label Jul 30, 2025
@locker
Copy link
Member

locker commented Jul 30, 2025

@nshy ASAN workflows fail. PTAL.

@locker locker assigned nshy and unassigned locker Jul 30, 2025
@nshy
Copy link
Contributor Author

nshy commented Jul 30, 2025

@nshy ASAN workflows fail. PTAL.

Fixed.

diff
diff --git a/src/lua/error.lua b/src/lua/error.lua
index 5adf83c5e8..130943751d 100644
--- a/src/lua/error.lua
+++ b/src/lua/error.lua
@@ -269,6 +269,7 @@ local function error_to_string(err)
     end
 
     local ibuf = buffer.internal.cord_ibuf_take()
+    ibuf:reserve(ibuf:capacity())
     local len = ffi.C.error_to_string(err, ibuf.wpos, ibuf:capacity())
     if len + 1 > ibuf:capacity() then
         ibuf:reserve(len + 1)
diff --git a/test/unit/error.c b/test/unit/error.c
index 44a90f6a1c..e597873144 100644
--- a/test/unit/error.c
+++ b/test/unit/error.c
@@ -672,15 +672,18 @@ test_logging(void)
 
 	/* Some of basic errors. */
 	e = BuildTimedOut("filename", 303);
+	error_ref(e);
 	error_log(e);
 	fail_unless(fgets(buf, size, f) != NULL);
 	ok(strstr(buf,
 		  "E> timed out "
 		  "{\"type\":\"TimedOut\",\"errno\":110,"
 		  "\"trace\":[{\"file\":\"filename\",\"line\":303}]}") != NULL);
+	error_unref(e);
 
 	/* ClientError plus payload plus some escaping. */
 	e = BuildClientError("\"filename\"", 707, ER_READONLY);
+	error_ref(e);
 	/* Check json escaping payload name and data. */
 	error_set_str(e, "\"f1\"", "\"p1\"");
 	error_log(e);
@@ -692,13 +695,15 @@ test_logging(void)
 		  "\"\\\"f1\\\"\":\"\\\"p1\\\"\","
 		  "\"trace\":[{\"file\":\"\\\"filename\\\"\",\"line\":707}]}"
 		  ) != NULL);
+	error_unref(e);
 
 	/* CustomError plus some unusual branches. */
 	/* 1. Check json escaping custom type. */
 	/* 2. Check no trace. */
 	/* 3. Check zero code. */
 	e = BuildCustomError("", 505, "\"typo\"", 0);
-	e->errmsg = "some message";
+	error_ref(e);
+	strcpy(e->errmsg_buf, "some message");
 	/* 4. Check errno. */
 	e->saved_errno = 11;
 	error_log(e);
@@ -707,14 +712,16 @@ test_logging(void)
 		  "E> some message "
 		  "{\"type\":\"\\\"typo\\\"\",\"errno\":11,"
 		  "\"trace\":[{}]}") != NULL);
+	error_unref(e);
 
 	/* Check stacked error. */
 	struct error *e1 = BuildCustomError("", 101, "level_1", 0);
-	e1->errmsg = "message 1";
+	error_ref(e1);
+	strcpy(e1->errmsg_buf, "message 1");
 	struct error *e2 = BuildCustomError("", 202, "level_2", 0);
-	e2->errmsg = "message 2";
+	strcpy(e2->errmsg_buf, "message 2");
 	struct error *e3 = BuildCustomError("", 303, "level_3", 0);
-	e3->errmsg = "message 3";
+	strcpy(e3->errmsg_buf, "message 3");
 	error_set_prev(e1, e2);
 	error_set_prev(e2, e3);
 	error_log(e2);
@@ -728,6 +735,7 @@ test_logging(void)
 		  "Caused by: message 3 "
 		  "{\"type\":\"level_3\","
 		  "\"trace\":[{}]}") != 0);
+	error_unref(e1);
 
 	fclose(f);
 	say_logger_free();

@nshy nshy removed the full-ci Enables all tests for a pull request label Jul 30, 2025
@nshy nshy force-pushed the error-log-verbosity-c branch from c61ba20 to e4a346d Compare July 30, 2025 14:29
@nshy nshy assigned locker and Totktonada and unassigned nshy Jul 30, 2025
@Totktonada
Copy link
Contributor

Sorry, reassigned by a mistake.

@locker locker removed their assignment Aug 1, 2025
@nshy nshy assigned nshy and unassigned Totktonada Aug 6, 2025
It will give cleaner diagnostic for user. Currently they have
'LuajitError: ' prefix and 'fatal error, exiting the event loop' suffix.

Also we are going to print error trace in technical format on panic.
It would clutter diagnostic even more.

Part of tarantool#10116

NO_CHANGELOG=minor changes
NO_DOC=minor changes
@nshy nshy force-pushed the error-log-verbosity-c branch from e4a346d to cfe1400 Compare August 11, 2025 13:16
@nshy nshy assigned Totktonada and unassigned nshy Aug 11, 2025
@Totktonada Totktonada removed their assignment Aug 11, 2025
When compat option `box_error_serialize_verbose` is set to `new` then
`tostring` of Lua box error object prints error with increased
verbosity. This affects logging error from Lua. Unfortunately it does
not affect logging box error from C.

Let's move `tostring` logic to C code so we can align logging from Lua and
C.

Note that:

- error is logged from C verbosly unconditionally
  (`box_error_serialize_verbose` is not taken into account)
- details that printed before ':' are removed (error code for
  `ClientError` for example)

While at it we did next changes in `tostring()`:

- frames are printed from effect to cause
- prefix `Caused by: ` is added for cause frames

Note that `say_logger_free()` it patched so that logger can be
reinitialized in `unit/fiber.cc` test.

Closes tarantool#10116
Follow-up tarantool#9105

NO_DOC=minor change
@nshy nshy force-pushed the error-log-verbosity-c branch from cfe1400 to 01f8489 Compare August 11, 2025 13:51
@nshy nshy added the full-ci Enables all tests for a pull request label Aug 11, 2025
@locker locker merged commit 2120de9 into tarantool:master Aug 11, 2025
58 of 59 checks passed
@nshy nshy deleted the error-log-verbosity-c branch August 11, 2025 15:51
Buristan added a commit to Buristan/tarantool that referenced this pull request Aug 18, 2025
This patch is a follow-up to the commit
2120de9 ("core: increase error logging
verbosity from C"). The test
`test_increased_error_string_conversion_verbosity` extended in this
commit assumes that the repository is cloned in the directory
"tarantool", so the path to the test file ends like the following:
| ..l/test/box-luatest/error_subsystem_improvements_test.lua

In the case when the last letter in the directory name is different, the
test fails. This patch changes strict comparison of strings to pattern
matching to accept any character in the directory name.

Follows-up tarantool#11716

NO_DOC=test
NO_CHANGELOG=test
Buristan added a commit to Buristan/tarantool that referenced this pull request Aug 18, 2025
This patch is a follow-up to the commit
2120de9 ("core: increase error logging
verbosity from C"). The test
`test_increased_error_string_conversion_verbosity` extended in this
commit assumes that the repository is cloned in the directory
"tarantool", so the path to the test file ends like the following:
| ...l/test/box-luatest/error_subsystem_improvements_test.lua

In the case when the last letter in the directory name is different, the
test fails. This patch chomps the last character in the directory name
to avoid failures.

Follows-up tarantool#11716

NO_DOC=test
NO_CHANGELOG=test
Buristan added a commit that referenced this pull request Aug 18, 2025
This patch is a follow-up to the commit
2120de9 ("core: increase error logging
verbosity from C"). The test
`test_increased_error_string_conversion_verbosity` extended in this
commit assumes that the repository is cloned in the directory
"tarantool", so the path to the test file ends like the following:
| ...l/test/box-luatest/error_subsystem_improvements_test.lua

In the case when the last letter in the directory name is different, the
test fails. This patch chomps the last character in the directory name
to avoid failures.

Follows-up #11716

NO_DOC=test
NO_CHANGELOG=test
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

full-ci Enables all tests for a pull request

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Increase verbosity for logging errors from C

6 participants