laforge submitted this change.

View Change

Approvals: Jenkins Builder: Verified laforge: Looks good to me, approved
tests/logging: also test printing the filename information

This commit demonstrates a bug introduced in [1], which can be
observed when the logging is configured to print the filename
*after* the logging message (LOG_FILENAME_POS_HEADER_END):

logging print file 1 last
^^^^

In this mode, the code in _output_buf() overwrites the '\n' sybmol
contained in the logging message itself by shifting the 'offset'
backwards, and appends the nipped '\n' after the filename info.

The problem is that the 'len' variable is not updated in this case,
so the resulting length includes +1 character - '\0', which gets
printed at the end of every logging line.

Interestingly enough, this problem affects only the wqueue mode.

Change-Id: I54bf5e5c036efb1908232fe3d8e8e2989715fbb3
Related: [1] I393907b3c9e0cc1145e102328adad0a83ee13a9f
---
M tests/logging/logging_test.c
M tests/logging/logging_test_stream.err
M tests/logging/logging_test_wqueue.err
3 files changed, 10 insertions(+), 0 deletions(-)

diff --git a/tests/logging/logging_test.c b/tests/logging/logging_test.c
index 12a7374..3548b1d 100644
--- a/tests/logging/logging_test.c
+++ b/tests/logging/logging_test.c
@@ -130,5 +130,13 @@
log_set_category_filter(stderr_target, DLGLOBAL, 1, LOGL_DEBUG);
DEBUGP(DLGLOBAL, "You should see this (DLGLOBAL on DEBUG)\n");

+ /* Test printing of the filename */
+ log_set_print_filename2(stderr_target, LOG_FILENAME_BASENAME);
+
+ log_set_print_filename_pos(stderr_target, LOG_FILENAME_POS_HEADER_END);
+ DEBUGP(DLGLOBAL, "A message with source info printed first\n");
+ log_set_print_filename_pos(stderr_target, LOG_FILENAME_POS_LINE_END);
+ DEBUGP(DLGLOBAL, "A message with source info printed last\n");
+
return 0;
}
diff --git a/tests/logging/logging_test_stream.err b/tests/logging/logging_test_stream.err
index 17b3cad..01ab878 100644
--- a/tests/logging/logging_test_stream.err
+++ b/tests/logging/logging_test_stream.err
@@ -7,3 +7,5 @@
DLGLOBAL You should see this on DLGLOBAL (d)
DLGLOBAL You should see this on DLGLOBAL (e)
DLGLOBAL You should see this (DLGLOBAL on DEBUG)
+DLGLOBAL logging_test.c:137 A message with source info printed first
+DLGLOBAL A message with source info printed last (logging_test.c:139)
diff --git a/tests/logging/logging_test_wqueue.err b/tests/logging/logging_test_wqueue.err
index 17b3cad..3e2008b 100644
--- a/tests/logging/logging_test_wqueue.err
+++ b/tests/logging/logging_test_wqueue.err
Binary files differ

To view, visit change 27010. To unsubscribe, or for help writing mail filters, visit settings.

Gerrit-Project: libosmocore
Gerrit-Branch: master
Gerrit-Change-Id: I54bf5e5c036efb1908232fe3d8e8e2989715fbb3
Gerrit-Change-Number: 27010
Gerrit-PatchSet: 4
Gerrit-Owner: fixeria <vyanitskiy@sysmocom.de>
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: laforge <laforge@osmocom.org>
Gerrit-Reviewer: neels <nhofmeyr@sysmocom.de>
Gerrit-MessageType: merged