423 lines
15 KiB
Markdown
423 lines
15 KiB
Markdown
# Logging
|
||
|
||
glog defines a series of macros that simplify many common logging tasks. You can
|
||
log messages by [severity level](#severity-levels), [control logging](flags.md)
|
||
behavior from the command line, log based on
|
||
[conditionals](#conditional-occasional-logging), abort the program when
|
||
[expected conditions](#runtime-checks) are not met, introduce your [own logging
|
||
levels](#verbose-logging), [customize the prefix](#format-customization)
|
||
attached to log messages, and more.
|
||
|
||
|
||
## Severity Levels
|
||
|
||
You can specify one of the following severity levels (in increasing order of
|
||
severity):
|
||
|
||
1. `INFO`,
|
||
2. `WARNING`,
|
||
3. `ERROR`, and
|
||
4. `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](#debugging-support)
|
||
(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](https://learn.microsoft.com/en-us/windows/win32/api/fileapi/nf-fileapi-gettemppatha)
|
||
API function to retrieve the directory for temporary files with a
|
||
fallback to
|
||
|
||
1. `C:\TMP\`
|
||
2. `C:\TEMP\`
|
||
|
||
(in the order given.)
|
||
|
||
**non-Windows**
|
||
|
||
: The directory is determined by referencing the environment variables
|
||
|
||
1. `TMPDIR`
|
||
2. `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 |
|
||
|
||
!!! example "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
|
||
|
||
``` cpp
|
||
google::InstallPrefixFormatter(&MyPrefixFormatter);
|
||
```
|
||
|
||
function to pass a pointer to the corresponding `MyPrefixFormatter` callback
|
||
during initialization. `InstallPrefixFormatter` takes a second optional argument
|
||
of type `#!cpp void*` that allows supplying user data to the callback.
|
||
|
||
!!! example "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 `#!cpp nullptr`.
|
||
|
||
``` cpp
|
||
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:
|
||
|
||
``` cpp
|
||
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.
|
||
|
||
``` cpp
|
||
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 `#!cpp google::COUNTER` identifies the recurring repetition.
|
||
|
||
You can combine conditional and occasional logging with the following
|
||
macro.
|
||
|
||
``` cpp
|
||
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:
|
||
|
||
``` cpp
|
||
LOG_FIRST_N(INFO, 20) << "Got the " << google::COUNTER << "th cookie";
|
||
```
|
||
|
||
Outputs log messages for the first 20 times it is executed. The `#!cpp
|
||
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:
|
||
|
||
``` cpp
|
||
LOG_EVERY_T(INFO, 0.01) << "Got a cookie";
|
||
```
|
||
|
||
Or every 2.35s:
|
||
|
||
``` cpp
|
||
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 `#!bash --v` command line option controls which verbose messages are logged:
|
||
|
||
``` cpp
|
||
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 `#!bash --v==1`, `#!cpp VLOG(1)` will log, but `#!cpp
|
||
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
|
||
`#!bash --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
|
||
`#!cpp 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:
|
||
|
||
``` bash
|
||
--vmodule=mapreduce=2,file=1,gfs*=3 --v=0
|
||
```
|
||
|
||
Specifying these options will specifically:
|
||
|
||
1. Print `#!cpp VLOG(2)` and lower messages from mapreduce.{h,cc}
|
||
2. Print `#!cpp VLOG(1)` and lower messages from file.{h,cc}
|
||
3. Print `#!cpp VLOG(3)` and lower messages from files prefixed with "gfs"
|
||
4. Print `#!cpp 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](flags.md) for more information.
|
||
|
||
There's also `#!cpp VLOG_IS_ON(n)` "verbose level" condition macro. This macro
|
||
returns `#!cpp true` when the `--v` is equal to or greater than `n`. The macro can be
|
||
used as follows:
|
||
|
||
``` cpp
|
||
if (VLOG_IS_ON(2)) {
|
||
// do some logging preparation and logging
|
||
// that can’t be accomplished with just VLOG(2) << ...;
|
||
}
|
||
```
|
||
|
||
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.
|
||
|
||
``` cpp
|
||
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;
|
||
```
|
||
|
||
|
||
!!! info "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.
|
||
|
||
``` cpp
|
||
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.
|
||
|
||
``` cpp
|
||
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:
|
||
|
||
``` cpp
|
||
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
|
||
`#!cpp operator<<(ostream, ...)` defined.
|
||
|
||
You may append to the error message like so:
|
||
|
||
``` cpp
|
||
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:
|
||
|
||
``` cpp
|
||
CHECK_EQ(string("abc")[1], ’b’);
|
||
```
|
||
|
||
The compiler reports an error if one of the arguments is a pointer and the other
|
||
is `#!cpp nullptr`. To work around this, simply `#!cpp static_cast` `#!cpp
|
||
nullptr` to the type of the desired pointer.
|
||
|
||
``` cpp
|
||
CHECK_EQ(some_ptr, static_cast<SomeType*>(nullptr));
|
||
```
|
||
|
||
Better yet, use the `CHECK_NOTNULL` macro:
|
||
|
||
``` cpp
|
||
CHECK_NOTNULL(some_ptr);
|
||
some_ptr->DoSomething();
|
||
```
|
||
|
||
Since this macro returns the given pointer, this is very useful in
|
||
constructor initializer lists.
|
||
|
||
``` cpp
|
||
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 (`#!cpp 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 `#!cpp nullptr` pointers to this macro.
|
||
They treat `#!cpp nullptr` and any non-`#!cpp nullptr` string as not equal. Two
|
||
`#!cpp nullptr`s are equal.
|
||
|
||
!!! note
|
||
Both arguments may be temporary objects which are destructed at the
|
||
end of the current *full expression*, such as
|
||
|
||
``` cpp
|
||
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](https://github.com/google/glog/blob/0.7.x/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.
|
||
|
||
``` cpp
|
||
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.
|