4

i am using glog for logging purpose when i use :

LOG(INFO) << "something";

it works as expected but when i use multiple logs like below it will not log until the program is stopped .when programm stops it will log everything as expected.

LOG(INFO) <<"111111111111111";
LOG(INFO) <<"222222222222222";
LOG(INFO) <<"333333333333333";
LOG(INFO) <<"444444444444444";

But what is confusing here is when i use LOG(WARNING) multiple times it works perfectly , i.e, it will log everything even when the program is running unlike the previous case when everything was logged when program stopped.

LOG(WARNING) <<"111111111111111";
LOG(WARNING) <<"222222222222222";
LOG(WARNING) <<"333333333333333";
LOG(WARNING) <<"444444444444444";

**any help on this behavior is greatly appreciated **

kshitij singh
  • 363
  • 2
  • 10
  • 19
  • The INFO stream probably needs to be flushed. Have you tried something like `LOG(INFO).flush()`? – muXXmit2X Feb 23 '16 at 08:13
  • @muXXmit2X yes i tried it but the problem is same , it will write everything to the log file after i stop program execution . i am using it in proxygen library – kshitij singh Feb 23 '16 at 08:19
  • Does this also happen when you are logging to stderr instead of a log file? – muXXmit2X Feb 23 '16 at 08:27
  • @muXXmit2X No,it logs everything to console perfectly just with the log file this problem is there – kshitij singh Feb 23 '16 at 08:36
  • @muXXmit2X i found somewhere to use google::LogMessage::Flush() but wheni use it this error comes up: `cannot call member function ‘void google::LogMessage::Flush()’ without object google::LogMessage::Flush();` – kshitij singh Feb 23 '16 at 08:40
  • Possible duplicate of [Is there a "built in way" to log everything with glog up to the program crash?](http://stackoverflow.com/questions/6574150/is-there-a-built-in-way-to-log-everything-with-glog-up-to-the-program-crash) – villintehaspam Feb 23 '16 at 13:44

3 Answers3

9

This is because of glog buffering INFO logs by default. Buffering is controlled by the flag FLAG_logbuflevel whose default value is 0 which is to say that all severity <= this value will be buffered.

The accepted answer works since google::FlushLogFiles(min_severity) force flushes all logs >= min_severity but it may not be feasible to define our custom macro in a production codebase. So, the simplest solution to prevent buffering of INFO logs is to set FLAG_logbuflevel to -1

The other answer raises an interesting idea that LogMessage::~LogMessage() has a call to Flush() and hence an explicit flush as suggested in the accepted answer is not needed. This isn't correct as the call to Flush() in the dtor is conditional. Here is the call stack-

LogMessage::~LogMessage()
|__LogMessage::Flush()
   |__(LogMessage::*send_method_)() == LogMessage::SendToLog()
       |__LogDestination::LogToAllLogfiles()
          |__LogDestination::MaybeLogToLogfile()
             |__Logger::Write(should_flush = log_severity > FLAGS_logbuflevel )

As you can see in the last frame of the call stack, the actual Write to the log destination(file) takes in a boolean should_flush which is dependent on the flag FLAGS_logbuflevel I spoke about earlier.

Hence, by default, the actual flushing of data to disk doesn't take place even though there is a Flush call in the dtor of LogMessage

Community
  • 1
  • 1
Pavan Manjunath
  • 27,404
  • 12
  • 99
  • 125
7

The Problem is fairly simple. glog by default uses one log file for each severity to prevent two streams opening the same file. If you open the same file in c++ by different streams one of those (the first one to open the file) gets prioritized to write to the file. The other one can only start writing to that file, when the first stream was closed.

You either have to declare different log files for each severity or to have all log messages in one file you could simply write your own little logging library.

It seems that especially the INFO stream needs to be flushed using google::FlushLogFiles(google::INFO). To do that after each info you want to log I would define myself a macro to call the flush function like so:

#define log(severity, msg) LOG(severity) << msg; google::FlushLogFiles(google::severity);

This ensures that the stream will be flushed and all your messages will appear in the log file

muXXmit2X
  • 2,745
  • 3
  • 17
  • 34
0

Although the above answer was accepted and probably helped to solve the problem, I am not sure it is the right way and even the right explanation to the problem.

If you check glog's code, you will find:

#define LOG(severity) COMPACT_GOOGLE_LOG_ ## severity.stream()

So in the original question, LOG(INFO) will be defined as something like 

#define COMPACT_GOOGLE_LOG_INFO google::LogMessage(__FILE__, __LINE__, google::GLOG_INFO).stream()

which will create a temporary stream object, and the logging content will be written to that stream object. After that, the destructor of LogMessage LogMessage::~LogMessage() will be called. Inside that destructor, Flush() will actually be called to flush the logging content to I/O device.

That is to say, for each LOG(INFO) statement, a temporary stream object will be created and destroyed, and Flush() will be called before it is destroyed. So IMHO, no additional calls to google::LogMessage::Flush() or even google::FlushLogFiles(google::INFO) should be necessary.

muXXmit2X
  • 2,745
  • 3
  • 17
  • 34
rsm
  • 103
  • 1
  • 6
  • This is *not* right. The presence of `Flush` in the destructor does not guarantee actual flushing of data since it is conditional on the flag `FLAG_logbuflevel`. See my answer – Pavan Manjunath Apr 14 '20 at 17:05