Logging¶

glog defines a series of macros that simplify many common logging tasks. You can log messages by severity level, control logging behavior from the command line, log based on conditionals, abort the program when expected conditions are not met, introduce your own logging levels, customize the prefix attached to log messages, and more.

Severity Levels¶

You can specify one of the following severity levels (in increasing order of severity):

INFO,
WARNING,
ERROR, and
FATAL.

Logging a FATAL message terminates the program (after the message is logged).

Note

Messages of a given severity are logged not only to corresponding severity logfile but also to other logfiles of lower severity. For instance, a message of severity FATAL will be logged to logfiles of severity FATAL, ERROR, WARNING, and INFO.

The DFATAL severity logs a FATAL error in debug mode (i.e., there is no NDEBUG macro defined), but avoids halting the program in production by automatically reducing the severity to ERROR.

Log Files¶

Unless otherwise specified, glog uses the format

<tmp>/<program name>.<hostname>.<user name>.log.<severity level>.<date>-<time>.<pid>

for log filenames written to a directory designated as <tmp> and determined according to the following rules.

Windows

glog uses the GetTempPathA API function to retrieve the directory for temporary files with a fallback to

C:\TMP\
C:\TEMP\

(in the order given.)

non-Windows

The directory is determined by referencing the environment variables

TMPDIR
TMP

if set with a fallback to /tmp/.

The default path to a log file on Linux, for instance, could be

/tmp/hello_world.example.com.hamaji.log.INFO.20080709-222411.10474

By default, glog echos ERROR and FATAL messages to standard error in addition to log files.

Log Line Prefix Format¶

Log lines have this form:

Lyyyymmdd hh:mm:ss.uuuuuu threadid file:line] msg...

where the fields are defined as follows:

Placeholder	Meaning
`L`	A single character, representing the log level (e.g., `I` for `INFO`)
`yyyy`	The year
`mm`	The month (zero padded; i.e., May is `05`)
`dd`	The day (zero padded)
`hh:mm:ss.uuuuuu`	Time in hours, minutes and fractional seconds
`threadid`	The space-padded thread ID
`file`	The file name
`line`	The line number
`msg`	The user-supplied message

Default log line prefix format

I1103 11:57:31.739339 24395 google.cc:2341] Command line: ./some_prog
I1103 11:57:31.739403 24395 google.cc:2342] Process id 24395

Note

Although microseconds are useful for comparing events on a single machine, clocks on different machines may not be well synchronized. Hence, use with caution when comparing the low bits of timestamps from different machines.

Format Customization¶

The predefined log line prefix can be replaced using a user-provided callback that formats the corresponding output.

For each log entry, the callback will be invoked with a reference to a google::LogMessage instance containing the severity, filename, line number, thread ID, and time of the event. It will also be given a reference to the output stream, whose contents will be prepended to the actual message in the final log line.

To enable the use of a prefix formatter, use the

google::InstallPrefixFormatter(&MyPrefixFormatter);

function to pass a pointer to the corresponding MyPrefixFormatter callback during initialization. InstallPrefixFormatter takes a second optional argument of type void* that allows supplying user data to the callback.

Custom prefix formatter

The following function outputs a prefix that matches glog's default format. The third parameter data can be used to access user-supplied data which unless specified defaults to nullptr.

void MyPrefixFormatter(std::ostream& s, const google::LogMessage& m, void* /*data*/) {
   s << google::GetLogSeverityName(m.severity())[0]
   << setw(4) << 1900 + m.time().year()
   << setw(2) << 1 + m.time().month()
   << setw(2) << m.time().day()
   << ' '
   << setw(2) << m.time().hour() << ':'
   << setw(2) << m.time().min()  << ':'
   << setw(2) << m.time().sec() << "."
   << setw(6) << m.time().usec()
   << ' '
   << setfill(' ') << setw(5)
   << m.thread_id() << setfill('0')
   << ' '
   << m.basename() << ':' << m.line() << "]";
}

Conditional / Occasional Logging¶

Sometimes, you may only want to log a message under certain conditions. You can use the following macros to perform conditional logging:

LOG_IF(INFO, num_cookies > 10) << "Got lots of cookies";

The "Got lots of cookies" message is logged only when the variable num_cookies exceeds 10. If a line of code is executed many times, it may be useful to only log a message at certain intervals. This kind of logging is most useful for informational messages.

LOG_EVERY_N(INFO, 10) << "Got the " << google::COUNTER << "th cookie";

The above line outputs a log messages on the 1st, 11th, 21st, ... times it is executed.

Note

The placeholder google::COUNTER identifies the recurring repetition.

You can combine conditional and occasional logging with the following macro.

LOG_IF_EVERY_N(INFO, (size > 1024), 10) << "Got the " << google::COUNTER
                                        << "th big cookie";

Instead of outputting a message every nth time, you can also limit the output to the first n occurrences:

LOG_FIRST_N(INFO, 20) << "Got the " << google::COUNTER << "th cookie";

Outputs log messages for the first 20 times it is executed. The google::COUNTER identifier indicates which repetition is happening.

Other times, it is desired to only log a message periodically based on a time. For instance, to log a message every 10ms:

LOG_EVERY_T(INFO, 0.01) << "Got a cookie";

Or every 2.35s:

LOG_EVERY_T(INFO, 2.35) << "Got a cookie";

Verbose Logging¶

When you are chasing difficult bugs, thorough log messages are very useful. However, you may want to ignore too verbose messages in usual development. For such verbose logging, glog provides the VLOG macro, which allows you to define your own numeric logging levels.

The --v command line option controls which verbose messages are logged:

VLOG(1) << "I’m printed when you run the program with --v=1 or higher";
VLOG(2) << "I’m printed when you run the program with --v=2 or higher";

With VLOG, the lower the verbose level, the more likely messages are to be logged. For example, if --v==1, VLOG(1) will log, but VLOG(2) will not log.

Warning

The VLOG behavior is opposite of the severity level logging, where INFO, ERROR, etc. are defined in increasing order and thus --minloglevel of 1 will only log WARNING and above.

Though you can specify any integers for both VLOG macro and --v flag, the common values for them are small positive integers. For example, if you write VLOG(0), you should specify --v=-1 or lower to silence it. This is less useful since we may not want verbose logs by default in most cases. The VLOG macros always log at the INFO log level (when they log at all).

Verbose logging can be controlled from the command line on a per-module basis:

--vmodule=mapreduce=2,file=1,gfs*=3 --v=0

Specifying these options will specifically:

Print VLOG(2) and lower messages from mapreduce.{h,cc}
Print VLOG(1) and lower messages from file.{h,cc}
Print VLOG(3) and lower messages from files prefixed with "gfs"
Print VLOG(0) and lower messages from elsewhere

The wildcarding functionality 3. supports both * (matches 0 or more characters) and ? (matches any single character) wildcards. Please also refer to command line flags for more information.

There's also VLOG_IS_ON(n) "verbose level" condition macro. This macro returns true when the --v is equal to or greater than n. The macro can be used as follows:

if (VLOG_IS_ON(2)) {
    // (1)
}

Here we can perform some logging preparation and logging that can’t be accomplished with just VLOG(2) << "message ...";

Verbose level condition macros VLOG_IF, VLOG_EVERY_N and VLOG_IF_EVERY_N behave analogous to LOG_IF, LOG_EVERY_N, LOG_IF_EVERY_N, but accept a numeric verbosity level as opposed to a severity level.

VLOG_IF(1, (size > 1024))
   << "I’m printed when size is more than 1024 and when you run the "
      "program with --v=1 or more";
VLOG_EVERY_N(1, 10)
   << "I’m printed every 10th occurrence, and when you run the program "
      "with --v=1 or more. Present occurrence is " << google::COUNTER;
VLOG_IF_EVERY_N(1, (size > 1024), 10)
   << "I’m printed on every 10th occurrence of case when size is more "
      " than 1024, when you run the program with --v=1 or more. ";
      "Present occurrence is " << google::COUNTER;

Performance

The conditional logging macros provided by glog (e.g., CHECK, LOG_IF, VLOG, etc.) are carefully implemented and don't execute the right hand side expressions when the conditions are false. So, the following check may not sacrifice the performance of your application.

CHECK(obj.ok) << obj.CreatePrettyFormattedStringButVerySlow();

Debugging Support¶

Special debug mode logging macros only have an effect in debug mode and are compiled away to nothing for non-debug mode compiles. Use these macros to avoid slowing down your production application due to excessive logging.

DLOG(INFO) << "Found cookies";
DLOG_IF(INFO, num_cookies > 10) << "Got lots of cookies";
DLOG_EVERY_N(INFO, 10) << "Got the " << google::COUNTER << "th cookie";
DLOG_FIRST_N(INFO, 10) << "Got the " << google::COUNTER << "th cookie";
DLOG_EVERY_T(INFO, 0.01) << "Got a cookie";

Runtime Checks¶

It is a good practice to check expected conditions in your program frequently to detect errors as early as possible. The CHECK macro provides the ability to abort the application when a condition is not met, similar to the assert macro defined in the standard C library.

CHECK aborts the application if a condition is not true. Unlike assert, it is not controlled by NDEBUG, so the check will be executed regardless of compilation mode. Therefore, fp->Write(x) in the following example is always executed:

CHECK(fp->Write(x) == 4) << "Write failed!";

There are various helper macros for equality/inequality checks -CHECK_EQ, CHECK_NE, CHECK_LE, CHECK_LT, CHECK_GE, and CHECK_GT. They compare two values, and log a FATAL message including the two values when the result is not as expected. The values must have operator<<(ostream, ...) defined.

You may append to the error message like so:

CHECK_NE(1, 2) << ": The world must be ending!";

We are very careful to ensure that each argument is evaluated exactly once, and that anything which is legal to pass as a function argument is legal here. In particular, the arguments may be temporary expressions which will end up being destroyed at the end of the apparent statement, for example:

CHECK_EQ(string("abc")[1], ’b’);

The compiler reports an error if one of the arguments is a pointer and the other is nullptr. To work around this, simply static_cast nullptr to the type of the desired pointer.

CHECK_EQ(some_ptr, static_cast<SomeType*>(nullptr));

Better yet, use the CHECK_NOTNULL macro:

CHECK_NOTNULL(some_ptr);
some_ptr->DoSomething();

Since this macro returns the given pointer, this is very useful in constructor initializer lists.

struct S {
    S(Something* ptr) : ptr_(CHECK_NOTNULL(ptr)) {}
    Something* ptr_;
};

Warning

Due to the argument forwarding, CHECK_NOTNULL cannot be used to simultaneously stream an additional custom message. To provide a custom message, one can use the macro CHECK_EQ prior to the failing check.

If you are comparing C strings (char *), a handy set of macros performs both case sensitive and insensitive comparisons - CHECK_STREQ, CHECK_STRNE, CHECK_STRCASEEQ, and CHECK_STRCASENE. The CHECK_*CASE* macro variants are case-insensitive. You can safely pass nullptr pointers to this macro. They treat nullptr and any non-nullptr string as not equal. Two nullptrs are equal.

Note

Both arguments may be temporary objects which are destructed at the end of the current full expression, such as

CHECK_STREQ(Foo().c_str(), Bar().c_str());

where Foo and Bar return std::string.

The CHECK_DOUBLE_EQ macro checks the equality of two floating point values, accepting a small error margin. CHECK_NEAR accepts a third floating point argument, which specifies the acceptable error margin.

Raw Logging¶

The header file <glog/raw_logging.h> can be used for thread-safe logging, which does not allocate any memory or acquire any locks. Therefore, the macros defined in this header file can be used by low-level memory allocation and synchronization code. Please check src/glog/raw_logging.h for detail.

Google Style `perror()`¶

PLOG() and PLOG_IF() and PCHECK() behave exactly like their LOG* and CHECK equivalents with the addition that they append a description of the current state of errno to their output lines. E.g.

PCHECK(write(1, nullptr, 2) >= 0) << "Write nullptr failed";

This check fails with the following error message.

F0825 185142 test.cc:22] Check failed: write(1, nullptr, 2) >= 0 Write nullptr failed: Bad address [14]

Syslog¶

SYSLOG, SYSLOG_IF, and SYSLOG_EVERY_N macros are available. These log to syslog in addition to the normal logs. Be aware that logging to syslog can drastically impact performance, especially if syslog is configured for remote logging! Make sure you understand the implications of outputting to syslog before you use these macros. In general, it's wise to use these macros sparingly.

Logging¶

Severity Levels¶

Log Files¶

Log Line Prefix Format¶

Format Customization¶

Conditional / Occasional Logging¶

Verbose Logging¶

Debugging Support¶

Runtime Checks¶

Raw Logging¶

Google Style perror()¶

Syslog¶

Google Style `perror()`¶