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
changes/10/27010/4
Vadim Yanitskiy 10 months ago
parent 27961906ad
commit eff0880f3b
  1. 8
      tests/logging/logging_test.c
  2. 2
      tests/logging/logging_test_stream.err
  3. BIN
      tests/logging/logging_test_wqueue.err

@ -130,5 +130,13 @@ int main(int argc, char **argv)
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;
}

@ -7,3 +7,5 @@ DLGLOBAL You should see this on DLGLOBAL (c)
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)

Loading…
Cancel
Save