logging: add more documentation
authorAdam Simpkins <simpkins@fb.com>
Wed, 13 Dec 2017 00:30:13 +0000 (16:30 -0800)
committerFacebook Github Bot <facebook-github-bot@users.noreply.github.com>
Wed, 13 Dec 2017 00:36:35 +0000 (16:36 -0800)
Summary: Add several new documents describing the behavior of the folly logging library.

Reviewed By: yfeldblum

Differential Revision: D6525997

fbshipit-source-id: 8ba2ff99c70c7566987b3da321526a16755e72bf

folly/experimental/logging/docs/Comparisons.md [new file with mode: 0644]
folly/experimental/logging/docs/Config.md
folly/experimental/logging/docs/LogCategories.md [new file with mode: 0644]
folly/experimental/logging/docs/LogHandlers.md [new file with mode: 0644]
folly/experimental/logging/docs/LogLevels.md [new file with mode: 0644]
folly/experimental/logging/docs/Overview.md [new file with mode: 0644]
folly/experimental/logging/docs/Usage.md [new file with mode: 0644]

diff --git a/folly/experimental/logging/docs/Comparisons.md b/folly/experimental/logging/docs/Comparisons.md
new file mode 100644 (file)
index 0000000..6e3eeab
--- /dev/null
@@ -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.
index 1816f3ad5c92aa85a7effad039d485f5351dac35..ddab897f7d648cee70c5ae1378456244ddb90e3d 100644 (file)
@@ -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 (file)
index 0000000..bd4d24c
--- /dev/null
@@ -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 (file)
index 0000000..d64d4d2
--- /dev/null
@@ -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<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.
diff --git a/folly/experimental/logging/docs/LogLevels.md b/folly/experimental/logging/docs/LogLevels.md
new file mode 100644 (file)
index 0000000..6fb8aaf
--- /dev/null
@@ -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 (file)
index 0000000..b0bce78
--- /dev/null
@@ -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<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).
diff --git a/folly/experimental/logging/docs/Usage.md b/folly/experimental/logging/docs/Usage.md
new file mode 100644 (file)
index 0000000..0f365a9
--- /dev/null
@@ -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<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.