From 7fb9d9fd95490f2a5fbdd0d7bb8a44e5b95f2c48 Mon Sep 17 00:00:00 2001 From: Adam Simpkins Date: Tue, 12 Dec 2017 16:30:13 -0800 Subject: [PATCH] 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 --- .../experimental/logging/docs/Comparisons.md | 56 +++++++ folly/experimental/logging/docs/Config.md | 12 +- .../logging/docs/LogCategories.md | 78 +++++++++ .../experimental/logging/docs/LogHandlers.md | 148 ++++++++++++++++++ folly/experimental/logging/docs/LogLevels.md | 55 +++++++ folly/experimental/logging/docs/Overview.md | 99 ++++++++++++ folly/experimental/logging/docs/Usage.md | 117 ++++++++++++++ 7 files changed, 562 insertions(+), 3 deletions(-) create mode 100644 folly/experimental/logging/docs/Comparisons.md create mode 100644 folly/experimental/logging/docs/LogCategories.md create mode 100644 folly/experimental/logging/docs/LogHandlers.md create mode 100644 folly/experimental/logging/docs/LogLevels.md create mode 100644 folly/experimental/logging/docs/Overview.md create mode 100644 folly/experimental/logging/docs/Usage.md diff --git a/folly/experimental/logging/docs/Comparisons.md b/folly/experimental/logging/docs/Comparisons.md new file mode 100644 index 00000000..6e3eeab1 --- /dev/null +++ b/folly/experimental/logging/docs/Comparisons.md @@ -0,0 +1,56 @@ +# 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. diff --git a/folly/experimental/logging/docs/Config.md b/folly/experimental/logging/docs/Config.md index 1816f3ad..ddab897f 100644 --- a/folly/experimental/logging/docs/Config.md +++ b/folly/experimental/logging/docs/Config.md @@ -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 diff --git a/folly/experimental/logging/docs/LogCategories.md b/folly/experimental/logging/docs/LogCategories.md new file mode 100644 index 00000000..bd4d24c3 --- /dev/null +++ b/folly/experimental/logging/docs/LogCategories.md @@ -0,0 +1,78 @@ +# 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. diff --git a/folly/experimental/logging/docs/LogHandlers.md b/folly/experimental/logging/docs/LogHandlers.md new file mode 100644 index 00000000..d64d4d20 --- /dev/null +++ b/folly/experimental/logging/docs/LogHandlers.md @@ -0,0 +1,148 @@ +# 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()); + +``` + +## 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. diff --git a/folly/experimental/logging/docs/LogLevels.md b/folly/experimental/logging/docs/LogLevels.md new file mode 100644 index 00000000..6fb8aaf9 --- /dev/null +++ b/folly/experimental/logging/docs/LogLevels.md @@ -0,0 +1,55 @@ +# 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. diff --git a/folly/experimental/logging/docs/Overview.md b/folly/experimental/logging/docs/Overview.md new file mode 100644 index 00000000..b0bce781 --- /dev/null +++ b/folly/experimental/logging/docs/Overview.md @@ -0,0 +1,99 @@ +# 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()`, 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). diff --git a/folly/experimental/logging/docs/Usage.md b/folly/experimental/logging/docs/Usage.md new file mode 100644 index 00000000..0f365a9c --- /dev/null +++ b/folly/experimental/logging/docs/Usage.md @@ -0,0 +1,117 @@ +# 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()` 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. -- 2.34.1