docs/logging.md
The new log system adds capability to produce structured logs in the Relaxed Extended JSON 2.0.0 format. The new API requires names to be given to variables, forming field names for the variables in structured JSON logs. Named variables are called attributes in the log system.
Log lines are composed primarily of a message (msg) and attributes (attr fields).
As you write log messages, keep the following in mind: A big thing that makes JSON and BSON useful as data formats is the ability to provide rich field names.
What makes logv2 machine readable is that we write an intact Extended BSON format.
But, what makes these lines human readable is that the msg provides a simple,
clear context for interpreting well-formed field names and values in the attr
subdocument.
For maximum readability, a log message additionally has the least amount of repetition possible, and shares attribute names with other related log lines.
The msg field predicates a reader's interpretation of the log line. It should
be crafted with care and attention.
msg strings containing fmt-style
{expr} braces. These are legacy artifacts and should be rephrased
according to these guidelines.The attr subdocument includes important metrics/statistics about the logged
event for the purposes of debugging or performance analysis. These variables
should be named very well, as though intended for a very human-readable portion
of the codebase (like config variable declaration, abstract class definitions,
etc.)
For attr field names, do the following:
The bar for understanding should be:
Exception: Do not add a unit suffix when logging a Duration type. The system automatically adds this unit.
To describe the execution time of an operation using our preferred method:
Specify an attr name of “duration” and provide a value using the Milliseconds
Duration type. The log system will automatically append "Millis" to the
attribute name.
Alternatively, specify an attr name of “durationMillis” and provide the
number of milliseconds as an integer type.
Importantly: downstream analysis tools will rely on this convention, as a replacement for the "[0-9]+ms$" format of prior logs.
When logging the below information, do so with these specific terms:
Example 1:
LOGV2(1041, "Transition to PRIMARY complete");
JSON Output:
{ ... , "id": 1041, "msg": "Transition to PRIMARY complete", "attr": {} }
Example 2:
LOGV2(1042, "Slow query", "duration"_attr = getDurationMillis());
JSON Output:
{ ..., "id": 1042, "msg": "Slow query", "attr": { "durationMillis": 1000 } }
For adding STL containers as dynamic attributes, see RollbackImpl::_summarizeRollback
For sharing a string between a log line and a status see this section of InitialSyncer::_lastOplogEntryFetcherCallbackForStopTimestamp
The log system is made available with the following header:
#include "mongo/logv2/log.h"
The macro MONGO_LOGV2_DEFAULT_COMPONENT is expanded by all logging macros.
This configuration macro must expand at their point of use to a LogComponent
expression, which is implicitly attached to the emitted message. It is
conventionally defined near the top of a .cpp file after headers are included,
and before any logging macros are invoked. Example:
#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kDefault
Logging is performed using function style macros:
LOGV2(ID,
message-string,
"name0"_attr = var0,
...,
"nameN"_attr = varN);
The ID is a signed 32bit integer in the same number space as the error code
numbers. It is used to uniquely identify a log statement. If changing existing
code, using a new ID is strongly advised to avoid any parsing ambiguity. When
selecting ID during work on JIRA ticket SERVER-ABCDE you can use the JIRA
ticket number to avoid ID collisions with other engineers by taking ID from the
range ABCDE00 - ABCDE99.
Attributes are created with the _attr user-defined literal. The intermediate
object that gets instantiated provides the assignment operator = for
assigning a value to the attribute.
The message string must be a compile time constant. This is to avoid dynamic attribute names in the log output and to be able to add compile time verification of log statements in the future. If the string needs to be shared with anything else (like constructing a Status object) you can use this pattern:
static constexpr char str[] = "the string";
No attributes.
LOGV2(1000, "Logging event, no replacement fields is OK");
Some attributes.
LOGV2(1002,
"Replication state change",
"from"_attr = getOldState(),
"to"_attr = getNewState());
To override the default component, a separate logging API can be used that
takes a LogOptions structure:
LOGV2_OPTIONS(options, message-string, attr0, ...);
LogOptions can be constructed with a LogComponent to avoid verbosity in the
log statement.
LOGV2_OPTIONS(1003, {LogComponent::kCommand}, "To the command component");
LOGV2 is the logging macro for the default informational (0) severity. To log
to different severities there are separate logging macros to be used, they all
take paramaters like LOGV2:
LOGV2_WARNINGLOGV2_ERRORLOGV2_FATALLOGV2_FATAL_NOTRACELOGV2_FATAL_CONTINUEThere is also variations that take LogOptions if needed:
LOGV2_WARNING_OPTIONSLOGV2_ERROR_OPTIONSLOGV2_FATAL_OPTIONSFatal level log statements using LOGV2_FATAL perform fassert after logging,
using the provided ID as assert id. LOGV2_FATAL_NOTRACE perform
fassertNoTrace and LOGV2_FATAL_CONTINUE does not fassert allowing for
continued execution. LOGV2_FATAL_CONTINUE is meant to be used when a fatal
error has occurred but a different way of halting execution is desired such as
std::terminate or fassertFailedWithStatus.
LOGV2_FATAL_OPTIONS performs fassert by default like LOGV2_FATAL but this
can be changed by setting the FatalMode on the LogOptions.
Debug-level logging is slightly different where an additional parameter (as integer) required to indicate the desired debug level:
LOGV2_DEBUG(ID, debug-level, message-string, attr0, ...);
LOGV2_DEBUG_OPTIONS(
ID,
debug-level,
options,
message-string,
attr0, ...);
LOGV2_PROD_ONLY logs like a default LOGV2 log in production, but debug-1 log
in internal testing. It accepts the same arguments as LOGV2. This log level is
for log lines that may be spammy in testing but are more rare in production. As
such, they may be useful in investigations. This level also preserves backwards
compatibility for logs that are no longer as useful as when they were introduced.
To determine whether to log, this macro uses the LogSeverity::ProdOnly()
level, which returns level LogSeverity::Debug(1) when in a testing environment
and LogSeverity::Log() otherwise. Whether the server is in a testing
environment is determined using the enableTestCommands server parameter.
It is preferred to use other macros over this one as it introduces a difference
between testing and production. There is also the LOGV2_PROD_ONLY_OPTIONS
variation that takes LogOptions.
Status status = ...;
int remainingAttempts = ...;
LOGV2_ERROR(1004,
"Initial sync failed.",
"reason"_attr = status,
"remainingAttempts"_attr = remainingAttempts);
Log tags are replacing the Tee from the old log system as the way to indicate
that the log should also be written to a RamLog (accessible with the getLog
command).
Tags are added to a log statement with the options API similarly to how
non-default components are specified by constructing a LogOptions.
Multiple tags can be attached to a log statement using the bitwise or operator
|.
LOGV2_WARNING_OPTIONS(
1005,
{LogTag::kStartupWarnings},
"XFS filesystem is recommended with WiredTiger");
Sometimes there is a need to add attributes depending on runtime conditionals.
To support this there is the DynamicAttributes class that has an add method
to add named attributes one by one. This class is meant to be used when you
have this specific requirement and is not the general logging API.
When finished, it is logged using the regular logging API but the
DynamicAttributes instance is passed as the first attribute parameter. Mixing
_attr literals with the DynamicAttributes is not supported.
When using the DynamicAttributes you need to be careful about parameter
lifetimes. The DynamicAttributes binds attributes by reference and the
reference must be valid when passing the DynamicAttributes to the log
statement.
DynamicAttributes attrs;
attrs.add("str", "StringData value"_sd);
if (condition) {
// getExtraInfo() returns a reference that is valid until the LOGV2
// call below. Be careful of functions returning by value.
attrs.add("extra", getExtraInfo());
}
LOGV2(1030, "Dynamic attributes", attrs);
Many basic types have built in support:
char is logged as integerlong double is prohibitedstd::stringStringDataconst char*BSONObjBSONArrayBSONElementBSONObjBuilder::append overload availableboost::optional<T> of any loggable type TTo make a user-defined type loggable it needs a serialization member function that the log system can bind to.
The system binds and uses serialization functions by looking for functions in the following priority order:
void x.serialize(BSONObjBuilder*) const (member)BSONObj x.toBSON() const (member)BSONArray x.toBSONArray() const (member)toBSON(x) (non-member)toStringForLogging(x) (non-member)x.serialize(&fmtMemoryBuffer) (member)x.toString() (member)toString(x) (non-member)Enums cannot have member functions, but they will still try to bind to the
toStringForLogging(e) or toString(e) non-members. If neither is available,
the enum value will be logged as its underlying integral type.
In order to offer structured serialization and output, a type would need to supply a structured serialization function. Otherwise, if only stringification is provided, the output will be an escaped string.
The toStringForLogging non-member is an ADL customization hook used to
override toString for very rare cases where toString is inappropriate for
logging perhaps because it's needed for other non-logging formatting. Usually a
toString (member or nonmember) is a sufficient customization point and should
be preferred as a canonical stringification of the object.
NOTE: No operator<< overload is used even if available
class UserDefinedType {
public:
void serialize(BSONObjBuilder* builder) const {
builder->append("str"_sd, _str);
builder->append("int"_sd, _int);
}
private:
std::string _str;
int32_t _int;
};
STL containers and data structures that have STL like interfaces are loggable as long as they contain loggable elements (built-in, user-defined or other containers).
Sequential containers like std::vector, std::deque and std::list are
loggable and the elements get formatted as JSON array in structured output.
Associative containers such as std::map and stdx::unordered_map loggable
with the requirement that they key is of a string type. The structured format
is a JSON object where the field names are the key.
Ranges is loggable via helpers to indicate what type of range it is
seqLog(begin, end)mapLog(begin, end)seqLog indicates that it is a sequential range where the iterators point to loggable value directly.
mapLog indicates that it is a range coming from an associative container where the iterators point to a key-value pair.
Logging a sequence:
std::array<int, 20> arrayOfInts = ...;
LOGV2(1010,
"Log container directly",
"values"_attr = arrayOfInts);
LOGV2(1011,
"Log iterator range",
"values"_attr = seqLog(arrayOfInts.begin(), arrayOfInts.end());
LOGV2(1012,
"Log first five elements",
"values"_attr = seqLog(arrayOfInts.data(), arrayOfInts.data() + 5);
Logging a map-like container:
StringMap<BSONObj> bsonMap = ...;
LOGV2(1013,
"Log map directly",
"values"_attr = bsonMap);
LOGV2(1014,
"Log map iterator range",
"values"_attr = mapLog(bsonMap.begin(), bsonMap.end());
uint64_tLogging of containers uses BSONObj as an internal representation and
uint64_t is not a supported type with BSONObjBuilder::append(). As a user
you can use boost::transform_iterator to cast the uint64_t to a supported
type.
std::vector<uint64_t> vec = ...;
// If we know casting to signed is safe
auto asSigned = [](uint64_t i) { return static_cast<int64_t>(i); };
LOGV2(2000,
"As signed array",
"values"_attr = seqLog(
boost::make_transform_iterator(vec.begin(), asSigned),
boost::make_transform_iterator(vec.end(), asSigned)));
// Otherwise we can log as any of these types instead of using asSigned
auto asDecimal128 = [](uint64_t i) { return Decimal128(i); };
auto asString = [](uint64_t i) { return std::to_string(i); };
Duration types have special formatting to match existing practices in the server code base. Their resulting format depends on the context they are logged.
When durations are formatted as JSON or BSON a unit suffix is added to the attribute name when building the field name. The value will be count of the duration as a number.
When logging containers with durations there is no attribute per duration instance that can have the suffix added. In this case durations are instead formatted as a BSON object.
"duration" attribute
C++ expression:
"duration"_attr = Milliseconds(10)
JSON format:
"durationMillis": 10
Container of Duration objects
C++ expression:
"samples"_attr = std::vector<Nanoseconds>{Nanoseconds(200),
Nanoseconds(400)}
JSON format:
"samples": [{"durationNanos": 200}, {"durationNanos": 400}]
The style guide contains recommendations for attribute naming in certain cases.
To make abstraction of attribute naming possible a logAttrs function can be
implemented as a friend function in a class with the following signature:
class AnyUserType {
public:
friend auto logAttrs(const AnyUserType& instance) {
return "name"_attr=instance;
}
BSONObj toBSON() const; // Type needs to be loggable
};
const AnyUserType& t = ...;
LOGV2(2001, "Log of user type", logAttr(t));
In some cases a loggable type might be composed as a hierarchy in the C++ type
system which would lead to a very verbose structured log output as every level
in the hierarcy needs a name when outputted as JSON. The attribute naming
abstraction system can also be used to collapse such hierarchies. Instead of
making a type loggable it can instead return one or more attributes from its
members by using multipleAttrs in logAttrs functions.
multipleAttrs(...) accepts attributes or instances of types with logAttrs
functions implemented.
class NotALoggableType {
std::string name;
BSONObj data;
friend auto logAttrs(const NotALoggableType& instance) {
return logv2::multipleAttrs("name"_attr=instance.name,
"data"_attr=instance.data);
}
};
NotALoggableType t = ...;
// These two log statements are equivalent:
LOGV2(2002, "Statement", logAttrs(t));
LOGV2(2002, "Statement", "name"_attr=t.name, "data"_attr=t.data);
To avoid lifetime issues (log attributes bind their values by reference) it is
recommended to not create attributes when using multipleAttrs unless
attributes are created for members directly. If logAttrs or ""_attr= is
used inside a logAttrs function on the return of a function returning by
value it will result in a dangling reference. The following example illustrates
the problem:
class SomeSubType {
public:
BSONObj toBSON() const {...};
friend auto logAttrs(const SomeSubType& sub) {
return "subAttr"_attr=sub;
}
};
class SomeType {
public:
const std::string& name() const { return name_; }
SomeSubType sub() const { return sub_; } // Returning by value!
friend auto logAttrs(const SomeType& type) {
// logAttrs(type.sub()) below will contain a dangling reference!
return logv2::multipleAttrs("name"_attr=type.name(),
logAttrs(type.sub()));
}
private:
SomeSubType sub_;
std::string name_;
};
The better implementation would be to let the log system control the
lifetime by passing the instance to multipleAttrs without creating the
attribute. The log system will detect that it is not an attribute and will
attempt to create attributes by calling logAttrs:
friend auto logAttrs(const SomeType& type) {
return logv2::multipleAttrs("name"_attr=type.name(), type.sub());
}
Code that emits a high severity log statement may also need to emit a uassert
after the log. There is the UserAssertAfterLog logging option that allows you
to re-use the log statement to do the formatting required for the uassert.
The assertion id can be either the logging ID by passing UserAssertAfterLog
with no arguments or the assertion id can set by constructing
UserAssertAfterLog with an ErrorCodes::Error.
The assertion reason string will be a plain text log and can be provided with additional attribute arguments.
LOGV2_ERROR_OPTIONS(1050000,
{UserAssertAfterLog()},
"Assertion after log");
Would emit a uassert after performing the log that is equivalent to:
uasserted(1050000, "Assertion after log");
Using a named error code:
LOGV2_ERROR_OPTIONS(
1050,
{UserAssertAfterLog(ErrorCodes::DataCorruptionDetected)},
"Data corruption detected",
"recordId"_attr=RecordId(123456));
Would emit a uassert after performing the log that is equivalent to:
uasserted(ErrorCodes::DataCorruptionDetected,
"Data corruption detected for RecordId(123456)");
To make it easier to use the log system for tracing in local development, there is a special API that does not use IDs or attribute names:
logd(format-string, value0, ..., valueN);
It formats the string using libfmt similarly to what
fmt::format(format-string, value0, ..., valueN) would produce but using the
regular log system type support on how types are made loggable. The formatted
string is logged as the msg field in the JSON output, with no attr
subobject.
When using logd the log will emitted with standard severity and the default
component.
A difference from regular logging, logd is allowed to be used in header files
by including logv2/log_debug.h.
Unstructured logging is not allowed to be used in code committed to master, there is a lint check to validate this. It is however allowed to be used in Evergreen patch builds.
UserDefinedType t; // Defined in previous example
logd("this is a debug log, value 1: {} and value 2: {}", 1, t);
Rate limiting logs is useful to reduce the impact of logging on database throughput. At high rate and concurrency, logging can be expensive and reduce performance. Attention should be paid specifically to logs that can occur on every operation, whether they fail or succeed.
The rate limiting feature is implemented by SeveritySuppressor (see
src/mongo/logv2/log_severity_suppressor.h). It works by changing the severity level of logs
dynamically: within a configurable time interval, only the first log is emitted at the "normal"
severity; subsequent logs within that interval are emitted at a "quiet" severity (typically a debug
level). This ensures logs are not always written unless the logging level is increased for the
component.
SeveritySuppressor is typically used with StaticImmortal for static storage. The interval can
be configured with a server parameter when constructing SeveritySuppressor.
static StaticImmortal<logv2::SeveritySuppressor> logSuppressor{
gSlowNetworkLogRate.loadRelaxed(), logv2::LogSeverity::Info(), logv2::LogSeverity::Debug(2)};
LOGV2_DEBUG(6983000,
(*logSuppressor)(),
"Slow network response send time",
"elapsed"_attr = bob.obj());
In this example, the first log within each gSlowNetworkLogRate-second window is emitted at Info level; subsequent logs within that window are emitted at Debug(2), which requires increasing the component's log level to be visible.
For per-key rate limiting (e.g., one log per key per interval), use KeyedSeveritySuppressor
instead.
Produces structured logs of the Relaxed Extended JSON 2.0.0 format. Below is an example of a log statement in C++ and a pretty-printed JSON output:
C++ statement:
BSONObjBuilder builder;
builder.append("first"_sd, 1);
builder.append("second"_sd, "str");
std::vector<int> vec = {1, 2, 3};
LOGV2_ERROR(1020,
"Example",
"bson"_attr = builder.obj(),
"vector"_attr = vec,
"optional"_attr = boost::none);
Output:
{
"t": {
"$date": "2020-01-06T19:10:54.246Z"
},
"s": "E",
"c": "NETWORK",
"ctx": "conn1",
"id": 23453,
"msg": "Example",
"attr": {
"bson": {
"first": 1,
"second": "str"
},
"vector": [1, 2, 3],
"optional": null
}
}