Commit 7fb9d9fd authored by Adam Simpkins's avatar Adam Simpkins Committed by Facebook Github Bot

logging: add more documentation

Summary: Add several new documents describing the behavior of the folly logging library.

Reviewed By: yfeldblum

Differential Revision: D6525997

fbshipit-source-id: 8ba2ff99c70c7566987b3da321526a16755e72bf
parent a674aa6c
# Comparing `folly::logging` to other log libraries
This document attempts to briefly describe the differences between the folly
logging library and other C++ logging libraries. This is not necessarily
comprehensive, and may become out of date as libraries change.
## [Google Logging (glog)](https://github.com/google/glog)
The folly logging library is similar to glog in many ways.
Like folly logging, glog also provides very cheap debug log messages with its
`VLOG` macro. (However, the glog `LOG` macro is not lazy, and always evaluates
its arguments, even if the log message is disabled.)
The primary difference between folly logging and glog is that folly offers more
flexibility in turning debug messages on or off. The `VLOG()` macros can be
enabled or disabled on per-file basis through a `--vmodule` command line flag
on non-Windows platforms. This flag does support regular expressions to match
groups of files, but the expression only applies to the last component of the
file name. This makes it more difficult to control logging for specific
libraries and subcomponents of a project.
Other advantages of folly logging over glog:
* Logging I/O can be performed in a separate thread. glog performs all logging
I/O in the thread that generated the log message. This can block processing
while waiting for logging I/O to complete.
* Unprintable characters in multi-line log messages are escaped by default.
This helps avoid problematic or dangerous terminal escape sequences from
appearing in log messages.
* Better support for multi-line log messages. Folly logging adds a log message
header after each internal new line in log messages.
* Full functionality on Windows. The `VLOG()` macro from `glog` has somewhat
diminished functionality on Windows, since it cannot be controlled on a
per-module basis.
Advantages of glog over folly logging over glog:
* Smaller generated code size. Due to automatically picking a log category
name, folly logging's `XLOG()` macros currently result in slightly larger
generated code compared to `VLOG()`.
## Log4j Clones
There are a number of Log4j-like libraries for C++ (log4cxx, log4cpp,
log4cplus).
Conceptually folly logging behaves similarly to most of these libraries. Much
of folly logging's hierarchical log category behavior was modeled after log4j
functionality, like these libraries.
The main difference between folly logging and most of these libraries is
low overhead for disabled log messages. The folly logging code ensures that
disabled log messages boil down to a single conditional level check. Most of
the other C++ log4j clones always evaluate log message arguments, and some also
perform more complex hierarchical log level checks at log time.
......@@ -93,7 +93,9 @@ special character like a comma or semicolon use the JSON format instead.
The log category configurations are a comma-separated list. Each element in
this list has the form
NAME=LEVEL:HANDLER1:HANDLER2
```
NAME=LEVEL:HANDLER1:HANDLER2
```
The log category name and '=' sign can be omitted, in which case the setting
applies to the root log category. The root log category can also be
......@@ -114,7 +116,9 @@ for this category to be cleared instead.
Each log handler configuration section takes the form
NAME=TYPE:OPTION1=VALUE1,OPTION2=VALUE2
```
NAME=TYPE:OPTION1=VALUE1,OPTION2=VALUE2
```
NAME specifies the log handler name, and TYPE specifies the log handler
type. A comma separated list of name=value options may follow the log
......@@ -124,7 +128,9 @@ LogHandlerFactory for the specified handler type.
The log handler type may be omitted to update the settings of an existing log
handler object:
NAME:OPTION1=VALUE1
```
NAME:OPTION1=VALUE1
```
A log handler with this name must already exist. Options specified in the
configuration will be updated with their new values, and any option names not
......
# Log Categories
Each log message is logged to a specific log category.
Log categories have a level setting that controls what log messages should be
enabled for this category, as well as a list of log handlers that control what
should be done with enabled log messages.
# Log Category Hierarchy
Log categories are arranged in a hierarchy. Each log category except for the
root has a parent category, and they may have zero or more children categories.
The log category hierarchy is determined by category names: the `.`
character acts as a separator in category names. For example, the category
`spacesim` is the parent of the category `spacesim.ships`. The root category
can be referred to either as `.` or as the empty string.
One recommended option for choosing log category names is to follow the source
code directory structure. For example, a partial view of the log category
hierarchy for a space simulator project might look something like:
```
. --- spacesim --- ships --- corvette -- cpp
\ \ \- h
| \- cruiser -- cpp
| \- h
|
\- actors --- player -- cpp
\ \- h
\- ai --- enemy -- cpp
\- h
```
The `XLOG()` macro automatically selects the log category to use based on the
source file path.
# Log Level Propagation
Log level settings automatically propagates downward from a particular log
category to its children.
If the log verbosity is increased on a particular log category (by lowering the
minimum enabled log level) , all of its children also inherit that increased
log verbosity by default. For instance, setting the log level to `INFO` on
`spacesim.ships` will automatically enable `INFO` and higher log messages on
the `spacesim.ships` category as well as children categories such as
`spacesim.ships.corvette`, `spacesim.ships.fighter`, etc. This makes it easily
possible to control the log verbosity of entire sections of the code base at
once.
Log level propagation can be disabled on specific categories by turning off the
`inherit` setting for that category. For instance, disabling the `inherit`
setting on the `spacesim.ships.cruiser` category will prevent it form
inheriting increased log level verbosity from its parent `spacesim.ships`
category (or indirectly inheriting settings from `spacesim` or the root
category). This makes it possible to turn down the verbosity for specific
categories even if when a larger category they belong to does have a higher
verbosity setting.
# Log Message Propagation
Logged messages propagate upwards through the log category hierarchy.
For instance, a message logged to `spacesim.ships.corvette.cpp` will first be
sent to any `LogHandler` objects configured on `spacesim.ship.corvette.cpp`,
then to the handlers for `spacesim.ships.corvette`, then `spacesim.ships`, then
to `spacesim`, and finally to the handlers for the root log category.
Due to this behavior, if you install a `LogHandler` on the root log category it
will automatically receive all messages logged to any category. Installing
`LogHandler` objects on sub-categories allows you to perform handling only for
specific category messages. `LogHandler` objects receive the full `LogMessage`
object, and can perform further filtering based on the log level or other
message properties if desired.
The [Log Handler](LogHandlers.md) documentation provides additional details
about log handler behavior.
# Log Handlers
The `LogHandler` class defines the interface for classes that wish to be
notified of log messages.
`LogHandler` objects can be attached to specific log categories to be notified
about log messages sent to that category or any of its children categories.
Attaching a `LogHandler` to the root category will cause it to be notified
about every enabled log message.
# Built-in Log Handlers
The logging library currently provides a few basic built-in `LogHandler`
implementations.
## `stream` Handler Type
In the [configuration settings](Config.md), you can use the `stream` type to
define a log handler that will write to `stdout` or `stderr`. The `stream`
property of the log handler specifies which stream to write to. For example,
the following defines a handler named `myhandler` that writes to stderr
```
myhandler=stream:stream=stderr
```
## `file` Handler Type
A `file` handler type is also provided that appends log messages to a file on
disk. The `path` option controls which file to write to. For example:
```
myhandler=file:path=/var/log/my.log
```
However, note that the `file` handler is currently not registered by default by
`folly::initLogging()`. This log handler allows appending to arbitrary files
based on the configuration settings. You should only enable this handler type
if you trust the source of your configuration string. (For instance, this
handler is potentially unsafe if your program runs with elevated privileges but
users with lower privilege levels can write to your configuration file.)
The following code snippet can be used to explicitly enable this log handler
type. It can be called before `initLogging()` to support the `file` handler
type in the configuration string passed to `initLogging()`.
```
folly::LoggerDB::get()->registerHandlerFactory(
std::make_unique<folly::FileHandlerFactory>());
```
## Handler Options
The built-in handler types also accept several options to control their
behavior. These include:
### `async`
The `async` option controls whether log messages should be written
asynchronously in a separate thread (when `async` is true) or immediately in
the thread that generated the log messages (when `async` is false).
This mainly affects the behavior when log messages are being generated faster
than they can be written to the output file or stream:
* Using `async=true` will ensure that your program never blocks waiting to
write the messages. Instead, the handler will start dropping log messages
when this occurs. When it is able to catch up it will emit a message
indicating how many messages were dropped.
* Using `async=false` will ensure that no log messages are dropped, at the
expense of blocking your program's normal processing until the log messages
can be written.
One additional consideration is that `async=false` will ensure that all log
messages have been flushed if your program crashes. With `async=true` it is
possible to lose some recent messages on program crash. For instance, if one
thread logs a message and then dereferences a null pointer, `async=false` will
ensure that the log message has been flushed before the thread can proceed to
dereference the null pointer. However with `async=true` the logging I/O thread
may not have flushed the log message by the time the thread that generated the
message crashes.
With `async=true`, the `max_buffer_size` option controls how much log data may
buffered in memory before dropping new log messages. This option specifies the
maximum number of bytes of unflushed log data to keep. New log messages that
would trigger this limit to be exceeded will be discarded. (Log messages are
either entirely kept or discarded; partial messages are never kept.)
### `formatter`
The `formatter` parameter controls how log messages should be formatted.
Currently the only built-in log formatter is `glog`, which formats log messages
similarly to [glog](https://github.com/google/glog). Additional formatters may
be added in the future, and it is also possible to implement your own
`LogFormatter` class.
# Default Handler Configuration
By default `initLogging()` creates a single log handler named `default`.
This log handler is installed on the root log category, and logs all messages
to stderr using a message format similar to that used by
[glog](https://github.com/google/glog).
This `default` log handler has the `async` option disabled by default. This
means that `initLogging()` will not spawn a separate logging I/O thread by
default. However, log messages may delay normal program processing if they are
being generated faster than they can be written to stderr.
High performance programs that want to avoid performance hiccups caused by
logging may wish to enable the `async` option on the default log handler.
This can easily be changed with the logging configuration string. For
instance, the following string sets the root category's log level to `WARN` and
enables the `async` option on the default log handler:
```
WARN; default:async=true
```
# Custom Log Handlers
It is possible to define your own custom `LogHandler` class should you choose
to. The `LogHandlerFactory` API enables you to create your own custom
`LogHandler` types from configuration settings parsed by `parseLogConfig()`.
You can use `LoggerDB::get()->registerHandlerFactory()` to register your own
custom log handler type.
## `StandardLogHandler`
The `StandardLogHandler` class is an implementation of `LogHandler` that
splits log message processing into two steps: formatting the message to a
string, and then writing that string somewhere.
It uses a `LogFormatter` class to perform the message formatting, and a
`LogWriter` class to write the formatted message.
You can provide only a custom `LogFormatter` or `LogWriter` implementation if
you want to customize one of these two steps without providing a full
`LogHandler` implementation of your own.
The `StandardLogHandlerFactory` class can then be used to implement your own
custom `LogHandlerFactory` that creates a `StandardLogHandler` with your custom
log formatter or writer type.
# Log Levels
The available log levels are defined in `logging/LogLevel.h`
### `FATAL`
A message logged with the `FATAL` log level will abort your program. `FATAL`
log messages cannot be disabled. If you have no log handlers configured when a
`FATAL` message is logged it will be printed to stderr, to ensure that your
program does not abort silently.
### `DFATAL`
The `DFATAL` log level is similar to `FATAL`, but only aborts your program in
debug builds (if the `NDEBUG` preprocessor macro was not defined at build
time).
### `CRITICAL`
`CRITICAL` is intended for important error messages. It falls in between `ERR`
and `FATAL`.
### `ERR`
`ERR` is intended for error messages. This category is named `ERR` rather than
`ERROR` due to the fact that common Windows header files `#define ERROR` as a
preprocessor macro.
### `WARN`, aka `WARNING`
`WARN` is intended for warning messages. `WARNING` is accepted as an alternate
name for `WARN`.
### `INFO`
`INFO` is intended for informational messages.
### `DBG0` through `DBG9`
There are 10 numbered debug message categories, `DBG0`, `DBG1`, `DBG2`, ...,
`DBG9`.
Note that `DBG0` is a more important log level than `DBG9`. The number next to
the debug level can be thought of as its verbosity: the higher the debug level
the more verbose it is. Setting a log category's level to `DBG5` will enable
log messages with levels `DBG0` through `DBG5` (as well as higher levels such
as `INFO` and above), while messages at level `DBG6` through `DBG9` will be
disabled.
### `DEBUG`
The `DEBUG` category falls below `DBG9`.
Setting a log category's level to `DEBUG` will automatically enable all
numbered `DBG` levels.
# The Folly Logging Library
`folly::logging` is a logging library for C++.
It allows configurable logging of text-based messages, and pays special
attention to supporting debug logging.
It has two primary goals:
1. Very cheap debug log statements
2. Configurable, hierarchical log categories
Together these two features make it possible to leave lots of debug log
statements present in production code with little overhead, and to then easily
turn on debug messages for specific parts of the code base at runtime when
troubleshooting.
# Usage
The [Usage](Usage.md) document provides a overview of how to use the logging
library. The [Log Categories](LogCategories.md) document describes the basic
behavior of log categories.
# Features
## Very cheap debug log statements
Folly logging statements normally boil down to a single conditional `if` check
when the log message is disabled. The arguments to be logged are evaluated
lazily, and are never evaluated if the log message is disabled.
This makes it possible to leave debug log statements present even in fairly hot
code paths with minimal performance impact.
## Hierarchical log categories
Folly logging uses a hierarchical log category model, similar to the one
popularized by [Apache Log4j](https://logging.apache.org/log4j/)
See the [Log Categories](LogCategories.md) document for a more complete
description of how log categories work.
This model makes it easy to control the logging levels for specific portions of
the code. Specific category settings can be changed to enable log messages in
specific files or specific sections of the code, and settings on higher level
categories can be adjusted to easily enable or disable log messages for larger
sections of the code.
This also makes it easy for teams to run their programs with elevated log
levels for code they maintain, while turning down potentially noisy messages
from libraries they depend on.
## Automatically chosen log category names
Picking good log category names and consistently using them throughout the code
base can sometimes be a challenge with log4j-style logging libraries. Folly
logging provides an `XLOG()` macro that automatically picks a log category name
based on the current filename, eliminating the need for programmers to worry
about log category names in most cases.
The `XLOG()` macro chooses a log category name based on the source file path,
with directory separators replaced by `.`. This allows log categories to
re-use the directory hierarchy decisions that have already been made.
## Asynchronous I/O
Folly logging provide log handlers that perform I/O asynchronously in a
separate thread, to avoid slowing down your main program threads if log
messages are being generated faster than they can be written to the output file
or stream. These asynchronous log writers will drop messages rather than
slowing down your main processing threads if log messages are being generated
faster than they can be consumed.
Performing I/O directly in the thread that generated the log message can often
be problematic, particularly if an unexpected event or configuration change
suddenly makes your code log more messages than normal.
This behavior is easily configurable, so that you can choose the best trade-off
for your program (possibly dropping some messages vs possibly blocking threads
on logging I/O).
## Support for folly::format()
The `XLOGF()` and `FB_LOGF()` macros format their arguments using
`folly::format()`. This allows log statements to use the powerful Python-like
format syntax supported by
[`folly::format()`](https://github.com/facebook/folly/blob/master/folly/docs/Format.md)
Additionally he `XLOG()` and `FB_LOG()` macros concatenate any log arguments
using `folly::to<string>()`, and also accept arguments via iostream-style `<<`
syntax.
## Safe handling of unprintable characters
The folly logging framework automatically escapes unprintable characters in log
messages by default. This helps avoid security vulnerabilities such as
[CVE-2013-1862](https://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2013-1862)
and
[CVE-2009-4496](https://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2009-4496).
# Usage
Logging messages with the folly logging library is done with one of a handful
of log macros. Macros are used to allow lazily evaluating the log arguments:
if the log message is disabled the log message expression will not be executed.
# Logging Macros
## `XLOG()`
In most cases, if you want to log a message you will use the `XLOG()` macro:
```
XLOG(INFO) << "hello world!";
```
This macro is defined in `folly/logging/xlog.h`
## `FB_LOG()`
The `XLOG()` macro automatically chooses the log category based on the current
file name. However, if you want to log to an explicit log category, you can
use `FB_LOG()`. It behaves like `XLOG()`, except that it requires a
`folly::Logger` as is first argument to specify the log category:
```
folly::Logger eventLogger("eden.events");
FB_LOG(eventLogger, INFO) << "something happened";
```
`FB_LOG()` is defined in `folly/logging/Logger.h`
## Macro Arguments
The `XLOG()` macro takes a log level as its first argument. See the
[Log Levels](LogLevels.md) document for a list of available log levels.
If you supply additional arguments they will be converted to strings using
`folly::to<std::string>()` and concatenated together as part of the log
message. For example:
```
XLOG(INFO, "the number is ", 2 + 2);
```
will result in the message "the number is 4".
If desired, you can specify both function argument style and `ostream` style
streaming log arguments together:
```
XLOG(INFO, "the number is ") << 2 + 2);
```
The `FB_LOG()` macro accepts requires a `Logger` object as its first argument,
and all subsequent arguments behave the same as the arguments to `XLOG()`.
## Python-style string formatting
The `XLOGF()` and `FB_LOGF()` macros allow log messages to be formatted using
format strings similar to python's
[str.format()](https://docs.python.org/3/library/string.html#formatspec)
mechanism.
```
XLOGF(DBG1, "cannot engage {} thruster: {}", thruster.name(), err.what());
```
This uses [`folly::format()`](https://github.com/facebook/folly/blob/master/folly/docs/Format.md)
to perform the formatting internally.
## `printf`-style string formatting
To help existing projects convert from older logging APIs, `XLOGC()` and
`FB_LOGC()` macros exist to support C-style `printf()` format strings.
You must include `folly/logging/printf.h` to access these macros.
```
XLOGC(DBG1, "failed to engage thruster %d: %s", thruster.number(), err.what());
```
# Log Category Selection
The `XLOG()` macro automatically selects a log category to log to based on the
current source file name. Directory separators in the path are replaced with
`.` characters to compute the log category name.
For instance, in a source file named `src/tiefighter/thruster.cpp` the default
`XLOG()` category will be `src.tiefighter.thruster.cpp`
Inside `.cpp` files the default `XLOG()` category name can be overridden using
the `XLOG_SET_CATEGORY_NAME()` macro. `XLOG_SET_CATEGORY_NAME()` can be
specified at top-level scope in the `.cpp` file to specify an alternate
category name for all `XLOG()` statements in this file.
`XLOG_SET_CATEGORY_NAME()` should not be used in header files, since it would
end up affecting all `.cpp` files that include that header.
# Configuration
The logging library provides several APIs for configuring log categories and
handlers. While you can programmatically configure `LogCategory` and
`LogHandler` objects via their public APIs, there are also APIs to configure
the logging library via configuration strings.
`folly::parseLogConfig()` can parse a configuration string in to a `LogConfig`
object. The configuration string syntax is documented in
[Config.md](Config.md).
You can then apply a `LogConfig` object to the main `LoggerDB` singleton by
using `LoggerDB::get()->updateConfig()` to incrementally update the current
configuration, or by using `LoggerDB::get()->resetConfig()` to replace all
existing settings with the new configuration.
The `folly::initLogging()` function provides a convenient API for initially
configuring the logging library from a configuration string that was obtained
from a command line flag or configuration file.
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment