Restore the stream format after writing the log prefix

[meyerj]

Resolves #695:

when i use glog with Eigen3 matrix, i found that every value in Eigen3 matrix is pad with '0'.

We had the same issue in the past, and I applied this patch in a fork in early 2020 already.

I do not remember why exactly I had to update MungeLine() in src/googletest.h. The new implementation tries to find the prefix at any position of the line, not only at the beginning of a word, and preserves whitespace. It may have been because of the log lines with multiple spaces for formatted number output in logging_unittest.err, which were munged into one by the previous implementation and hence the comparison failed.

[sergiud]

Thanks for the PR. Unfortunately, the changes break the tests.

[coveralls]

Coverage increased (+3.7%) to 76.64% when pulling d002d3d on meyerj:fix/save-stream-state-when-writing-the-log-prefix into 9cf0eb7 on google:master.

[meyerj]

Thanks for the PR. Unfortunately, the changes break the tests.

That should be fixed by https://github.com/google/glog/pull/731/commits/https://github.com/google/glog/pull/731/commits/18b3fa34bc74293007684c1b85ab19cfcc39237d. The patch was originally based on v0.3.5, and I did not test it anymore after having cherry-picked and adapted it for the latest master version.

Because the log prefix now contains the year and is 4 bytes longer, the termination condition begin_of_logging_prefix + 9 == line.size() in MungeLine() is not necessarily true anymore for log lines that are shorter than 9 characters, like " vlog -1". The operator should have been >=.

But I don't know what the issue is now with some of the debug builds, and I cannot reproduce that locally on Ubuntu Focal 20.04 with GCC 9.3.0.

[sergiud]

The failing debug builds are static library versions of glog that also enable custom prefix (WITH_CUSTOM_PREFIX=ON). You may also need a recent version of GTest.

You can check the Setup Dependencies and Configure steps for packages and CMake arguments being used and possibly the Build GTest step.

[meyerj]

The failing debug builds are static library versions of glog that also enable custom prefix (WITH_CUSTOM_PREFIX=ON). You may also need a recent version of GTest.

That was the right hint. I was not aware of this new feature. The logging_custom_prefix_unittest.cc uses the same logging_unittest.err file and hence also requires the additional LOG(INFO) statement from logging_unittest.cc to have a chance to succeed.

But even then the test case still fails, because the custom PrefixAttacher() does not set setfill('0'), which is now only applied in the custom_prefix_callback == NULL case with my proposed patch.

The log line that triggers the failure:

E20211029  1:27:44. 14269 957576 logging_custom_prefix_unittest.cc:1194] Message 2

gdb debugging output:

*** Check failure stack trace: ***
    @     0x55555558bc0c  google::LogMessage::Fail()
    @     0x55555558bb55  google::LogMessage::SendToLog()
    @     0x55555558b446  google::LogMessage::Flush()
    @     0x55555558ef9e  google::LogMessageFatal::~LogMessageFatal()
    @     0x55555556fc7f  google::MungeLine()
    @     0x555555570353  google::Munge()
    @     0x555555570c9e  google::MungeAndDiffTestStderr()
    @     0x5555555724ca  main
    @     0x7ffff7b710b3  __libc_start_main
    @     0x55555556ec9e  _start

Thread 1 "logging_custom_" received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007ffff7b6f859 in __GI_abort () at abort.c:79
#2  0x000055555559482d in google::DumpStackTraceAndExit () at /home/johannes/src/glog/src/utilities.cc:178
#3  0x000055555558bc0c in google::LogMessage::Fail () at /home/johannes/src/glog/src/logging.cc:1885
#4  0x000055555558bb55 in google::LogMessage::SendToLog (this=0x7fffffffc5a0) at /home/johannes/src/glog/src/logging.cc:1860
#5  0x000055555558b446 in google::LogMessage::Flush (this=0x7fffffffc5a0) at /home/johannes/src/glog/src/logging.cc:1720
#6  0x000055555558ef9e in google::LogMessageFatal::~LogMessageFatal (this=0x7fffffffc5a0, __in_chrg=<optimized out>) at /home/johannes/src/glog/src/logging.cc:2463
#7  0x000055555556fc7f in google::MungeLine (line="I20211029  1:48: 9.238988 969378 logging_custom_prefix_unittest.cc:286] foo bar 10 3.4\n") at /home/johannes/src/glog/src/googletest.h:451
#8  0x0000555555570353 in google::Munge (filename="/tmp/captured.err") at /home/johannes/src/glog/src/googletest.h:478
#9  0x0000555555570c9e in google::MungeAndDiffTestStderr (golden_filename="/home/johannes/src/glog/src/logging_custom_prefix_unittest.err") at /home/johannes/src/glog/src/googletest.h:512
#10 0x00005555555724ca in main (argc=1, argv=0x7fffffffde48) at /home/johannes/src/glog/src/logging_custom_prefix_unittest.cc:262
(gdb) frame 7
#7  0x000055555556fc7f in google::MungeLine (line="I20211029  1:48: 9.238988 969378 logging_custom_prefix_unittest.cc:286] foo bar 10 3.4\n") at /home/johannes/src/glog/src/googletest.h:451
451	    CHECK_EQ(']', tmp[tmp.size() - 1]);
(gdb) info locals
_result = 0x5555555d6d10
tmp = "969378"
before = ""
logcode_date = "I20211029"
time = "1:48:"
thread_lineinfo = "9.238988"
begin_of_logging_prefix = 0
iss = <incomplete type>
index = 42
rest = ""

The failure case is only triggered if the most significant digit of any of the minutes, seconds or fractional second parts is zero.

Which solution do you prefer?

1. Also save the state and set the fill character to 0 if a custom_prefix_callback is set in LogMessage::Init(), basically outside the if statement, for backwards compatibility?

2. Update the PrefixAttacher() in logging_custom_prefix_unittest.cc, but keep the behavior in LogMessage::Init() as in 35f1727? So any other custom implementation would have to set the fill character for timestamps itself, and also take care of saving and restoring the stream state.

3. Relax the checks in MungeLine() such that a log line with spaces instead of 0 characters is accepted?

[sergiud]

Option 1 sounds reasonable. I would avoid option 3.

[meyerj]

Option 1 sounds reasonable. I would avoid option 3.

Applied in d002d3d.

[sergiud]

Thanks!