Logging

Purpose

YDB uses structured logging for events that occur in the system. Structured logging means that in the log (operation journal), the textual description of events is separated from the parameters of those events, and the parameter values themselves are stored and processed independently of each other. For example, if a file read error occurs, its description is text like "Unable to read file", while the parameters are the file path, system error code, textual description of the system error, and so on.

Separating event descriptions from their parameters can subsequently be used for efficient message search, statistics collection, optimized log storage, and other tasks.

Basic tools for writing messages to the log

In most cases, the following conditions are met when writing messages to the log:

1. The source code is contained in some .cpp file (logging from header files is supported but discussed further).
2. In one .cpp file, all messages are written on behalf of the same component. Therefore, at the beginning of the file (but after all #include directives), the YDB_LOG_THIS_FILE_COMPONENT macro must be defined, which sets the component code for the entire file.

Example:

#define YDB_LOG_THIS_FILE_COMPONENT NKikimrServices::STATESTORAGE

#undef YDB_LOG_THIS_FILE_COMPONENT

3. Logging occurs during the operation of an actor, and the NActors::TlsActivationContext variable is available for working with the context (in particular, for sending messages to the logging actor).

Further in this .cpp file, the following macros can be used for logging messages:

The following parameters are specified in the arguments of the listed macros:

• message — text message;
• ...values... — optional parameters. Each parameter is specified as a {name, value} pair, where name is a text string with the parameter name, and value is the parameter value.

Examples of writing messages to the log:

1. Message without parameters:

YDB_LOG_INFO("Module started");

2. Message with parameters:

YDB_LOG_ERROR("Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

YDB_LOG(prio, message, ...values...);

auto prio = NActors::NLog::PRI_ERROR;
...
YDB_LOG(prio, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

Extended tools for writing messages to the log

Logging core

The lowest-level tool for writing messages to the log is the YDB_LOG_CTX_COMP macro. It checks the need for logging (according to settings), forms the text message, attaches optional parameters to it, and then sends all this information to the logging actor. Next, the logging actor processes the received message according to its current settings (for example, writes it to a file or syslog).

The full syntax of the logging macro is as follows:

YDB_LOG_CTX_COMP(ctx, prio, comp, message, ...values...)

The following parameters are specified in the macro call arguments:

• ctx — actor execution context (needed to send the message to the logging actor);
• prio — message logging level (corresponds to logging levels);
• comp — component identifier;
• message — text message;
• ...values... — optional parameters. Each parameter is specified as a {name, value} pair, where name is a text string with the parameter name, and value is the parameter value.

In the examples below, EXAMPLE_COMP_CODE denotes the logging component code. In real code, specify an existing component instead, for example NKikimrServices::STATESTORAGE.

YDB_LOG_CTX_COMP(ctx, PRI_INFO, EXAMPLE_COMP_CODE, "Module started");

YDB_LOG_CTX_COMP(ctx, PRI_ERROR, EXAMPLE_COMP_CODE, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

The YDB_LOG_CTX_COMP macro implies dynamic determination of the message level and passing it as an argument. By analogy with basic logging tools, there are a number of macros that do not require passing the message level as an argument.

YDB_LOG_ERROR_CTX_COMP(ctx, EXAMPLE_COMP_CODE, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

Many other macros discussed below are based on the YDB_LOG_CTX_COMP macro. Their names are constructed according to the following scheme:

1. The macro name always starts with YDB_LOG.
2. If the macro does not require specifying the message level, then the message level name is added to the macro name with an underscore character.
3. If the macro requires specifying the execution context, then _CTX is added to the macro name.
4. If the macro requires specifying the component, then _COMP is added to the macro name.

Using the standard execution context

In most cases, the execution context available through the global variable NActors::TlsActivationContext is used to send messages to the logging actor. To avoid visually overloading the source code with references to this global variable, an additional YDB_LOG_COMP macro has been introduced, which always uses NActors::TlsActivationContext and does not require specifying the CTX parameter.

Example:

YDB_LOG_COMP(PRI_ERROR, EXAMPLE_COMP_CODE, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

In this example, the standard execution context is used, and logging occurs on behalf of the component with code EXAMPLE_COMP_CODE.

YDB_LOG_ERROR_COMP(EXAMPLE_COMP_CODE, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

Using the default component

The same mechanism is used as in basic logging tools:

1. At the beginning of the file (but after all #include directives), the YDB_LOG_THIS_FILE_COMPONENT macro must be defined. It sets the component code for the entire file.

#undef YDB_LOG_THIS_FILE_COMPONENT

2. Further in the file, logging macros that do not require specifying the component code should be used. They are similar to those already discussed, but their name does not contain the _COMP string.

Example:

#define YDB_LOG_THIS_FILE_COMPONENT EXAMPLE_COMP_CODE
...
YDB_LOG_CTX(ctx, PRI_ERROR, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

#define YDB_LOG_THIS_FILE_COMPONENT EXAMPLE_COMP_CODE
...
YDB_LOG_ERROR_CTX(ctx, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

Logging in header files

If logging is needed in a header file, macros that require explicit specification of the component code should be used:

1. YDB_LOG_CTX_COMP — requires explicit specification of the message level, execution context, and component code.
2. YDB_LOG_XXXX_CTX_COMP — does not require specifying the message level.
3. YDB_LOG_COMP — uses the standard execution context.
4. YDB_LOG_XXXX_COMP — uses the standard execution context and does not require specifying the message level.

Constructing messages

Reusable sets of attached parameters

If the same set of parameters is attached to different messages, then to avoid code duplication, you can create this parameter set in advance and then reuse it when logging various events. The YDB_LOG_CREATE_MESSAGE macro is intended for this purpose. It accepts a set of parameters (as {name, value} pairs) as arguments and returns an object that can subsequently be used when sending messages to the log.

#define YDB_LOG_THIS_FILE_COMPONENT EXAMPLE_COMP_CODE
...
void MyFunction(const std::string& filename) {
    ...
    // Create message parameters
    auto context = YDB_LOG_CREATE_MESSAGE(
        {"sourceFilePath", filename});
    ...
    if (err != 0) {
        YDB_LOG_ERROR("MyFunction failed",
            context,                            // Use message parameters
            {"errorCode", err});
        return;
    }
    ...
    YDB_LOG_NOTICE("MyFunction succeeded",
        context);                               // Use message parameters
}

The result of calling the YDB_LOG_CREATE_MESSAGE macro is an instance of the TStructuredMessage class. This instance stores the set of parameters included in it, their names, types, and values. Instances of the TStructuredMessage class can be stored in local and global variables, copied, passed, and so on.

Operations for modifying a previously created parameter set are supported:

1. Adding and updating.

YDB_LOG_UPDATE_MESSAGE(context,
    {"socket", socketNum});

2. Removing parameters.

context.RemoveValue("socket");

Nested parameter sets

It is possible to create nested sets of attached parameters. To do this, when logging a message (or creating another parameter set), a previously created value set (i.e., an instance of the TStructuredMessage class) must be specified as the value in the {name, value} pair. Then all parameters from the value set will be automatically added to the resulting message (or the created value set), but with the prefix specified in name added to the parameter names, with . as the separator.

#define YDB_LOG_THIS_FILE_COMPONENT EXAMPLE_COMP_CODE
...
void MyFunction() {
    // Create message parameters
    auto context = YDB_LOG_CREATE_MESSAGE(
        {"operationName", "read"},
        {"sourceFilePath", filename});
    ...
    if (err != 0) {
        YDB_LOG_ERROR("MyFunction failed",
            {"details", context},                            // Use message parameters
            {"errorCode", err});
        return;
    }
    ...
}

Logging contexts

Forming and reusing sets of attached parameters is inconvenient in the following cases:

1. These sets need to be specified when logging a large number of messages.
2. These sets need to be passed to all called functions so that they can be specified there when logging messages.

You can simplify the source code by using a logging context — a set of parameters that will be automatically attached to all messages sent to the log in the given execution thread. To do this, call the YDB_LOG_CREATE_CONTEXT macro and pass it {name, value} pairs (the same way as when sending messages to the log or creating reusable sets), as well as previously created TStructuredMessage objects. The parameters listed in YDB_LOG_CREATE_CONTEXT are added during logging in the code block where this macro is called, as well as in nested code blocks and all called functions.

#define YDB_LOG_THIS_FILE_COMPONENT EXAMPLE_COMP_CODE
...
void MyFunction() {
    YDB_LOG_CREATE_CONTEXT(
        {"sourceFilePath", filename});
    ...
    if (errorCode != 0) {
        YDB_LOG_ERROR("MyFunction failed",     // The sourceFilePath and errorCode parameters will be attached to the message
            {"errorCode", errorCode});
        return;
    }
    ...
    YDB_LOG_NOTICE("MyFunction succeeded");    // The sourceFilePath parameter will be attached to the message
}

Logging contexts are organized as a stack. If a logging context is configured, it is stored at the top of the stack. Each execution thread has its own stack of logging contexts.

When YDB_LOG_CREATE_CONTEXT is called, the following actions occur:

1. A new parameter set is created (as when calling YDB_LOG_CREATE_MESSAGE), containing all parameters from the existing context, as well as parameters directly specified in the YDB_LOG_CREATE_CONTEXT macro.
2. The new parameter set is placed on the top of the stack and thus becomes the current logging context in the given execution thread.
3. When writing a message to the log (calling the YDB_LOG_CTX_COMP macro or similar), parameters from the top of the logging context stack are automatically attached to the message, and the parameters specified in the logging macro are written on top of this set.
4. The top of the stack will be automatically removed when exiting the current block, thus returning to the previously configured context.

To add parameters to the current context or update their values, use the YDB_LOG_UPDATE_CONTEXT macro:

YDB_LOG_UPDATE_CONTEXT({"requestId", requestId});

Multiple parameters and their values can be specified in the YDB_LOG_UPDATE_CONTEXT macro. If the specified parameters already exist in the context, their values will be updated. If the specified parameters are absent from the context, their values will be added to the context.

To remove parameters from the current context, pass their names to YDB_LOG_REMOVE_CONTEXT:

YDB_LOG_REMOVE_CONTEXT("requestId");

The YDB_LOG_UPDATE_CONTEXT and YDB_LOG_REMOVE_CONTEXT macros can be called any number of times. They modify only the current context (that is, the top of the context stack), but do not create new contexts and do not affect other contexts located lower in the context stack.

Recommendations for log content

Security

It is forbidden to write passwords, access tokens, encryption keys, connection strings, and personal data to the log. If a value is needed for diagnostics, the sensitive part must be removed, masked, or replaced with an irreversible hash before passing it to the macro.

Coding style

The following coding style is recommended when using logging macros:

1. All mandatory information (execution context, component code, message level, and message text) is placed on one line.
2. Each {name, value} pair is placed on a separate line.

Example of writing a message with multiple parameters:

    YDB_LOG_DEBUG("Handle TEvNodeWardenNotifyConfigMismatch",
        {"clusterStateGeneration", ClusterStateGeneration},
        {"msgGeneration", msgGeneration},
        {"clusterStateGuid", ClusterStateGuid},
        {"msgGuid", msgGuid});

Text message style

The following style for writing message texts is recommended:

1. The text is a meaningful (and preferably correct) sentence in English that speaks about some event inside the system, with the following requirements:

   • the text starts with a capital letter;
   • if the text is a separate sentence, no period is placed at the end of the message;
   • if the text consists of several sentences, they are separated by periods, but no period is placed after the last sentence.

2. The text may contain class and function names. If an actor logs the fact of receiving some message, a good practice is to log with the text Handle <event class name>.

3. Messages are fixed text without dynamically formed fragments.

4. All dynamic information known only at runtime should be placed as attached parameters.

To align message texts and parameter names, there is a simple empirical rule:

If you take the message text and add the parameter values to it in the form (name=value, name=value, ... ), you should get a meaningful, complete, unambiguous, and human-understandable text message.

YDB_LOG_ERROR_CTX(ctx, "Unable to open file",
    {"sourceFilePath", filename},
    {"errorCode", err});

Unable to open file (errorCode = ..., sourceFilePath = ...)

General recommendations for naming individual parameters

The style of naming individual parameters is based on two basic principles:

1. In the context of a specific message, the parameter value should be interpreted simply and unambiguously.

YDB_LOG_ERROR("Response timeout elapsed",
    {"nodeHostName", hostName},
    {"requestNum", requestNum},
    {"waitAtPosixTime", startTime},
    {"timeoutMs", timeout});

YDB_LOG_ERROR("Response timeout elapsed",
    {"node", hostName},
    {"request", requestNum},
    {"wait", startTime},
    {"timeout", timeout});

2. Semantically similar parameters should have the same names, since different naming of the same concepts makes it difficult to search for log entries. For example, it is undesirable to denote a transaction identifier as txId in some messages and as transactionId in others.

YDB_LOG_INFO("Started transaction",
    {"txId", transactionId});
...
YDB_LOG_INFO("Transaction modifies table",
    {"queryId", queryId},
    {"txId", transactionId});
...
YDB_LOG_INFO("Query commits transaction",
    {"queryId", queryId},
    {"txId", transactionId});
...

YDB_LOG_INFO("Started transaction",
    {"id", transactionId});
...
YDB_LOG_INFO("Transaction modifies table",
    {"id", queryId},
    {"transactionId", transactionId});
...
YDB_LOG_INFO("Query commits transaction",
    {"id", queryId},
    {"txId", transactionId});
...

3. Parameter names are written in camelCase.

Specific recommendations for naming individual parameters

The following recommendations are aimed at fulfilling the two principles mentioned above:

1. It is undesirable to use individual common words (id, item, value, path, child, parent, min, max, etc.) as parameter names — this complicates searching log entries. For example, the word id denotes an identifier, but it is completely unclear which entity it refers to, although in the context of a specific message, the meaning of this parameter may be perfectly clear.

YDB_LOG_INFO("Started transaction",
    {"txId", ...});
...
YDB_LOG_INFO("Received query",
    {"queryId", ...});
...
YDB_LOG_INFO("Sent request to actor",
    {"actorId", ...});

YDB_LOG_INFO("Started transaction",
    {"id", ...});
...
YDB_LOG_INFO("Received query",
    {"id", ...});
...
YDB_LOG_INFO("Sent request to actor",
    {"id", ...});

2. Parameter names should consist of several words, with the last word being the main one, and each preceding word clarifying the meaning of the following one. For example:

• actorId — actor identifier;
• operationId — operation identifier;
• operationName — operation name;
• operationSessionId — identifier of the session within which the operation is performed.

YDB_LOG_INFO("Copy data to another shard",
    {"srcShardId", ...},
    {"dstShardId", ...});

YDB_LOG_INFO("Copy data to another shard",
    {"srcId", ...},
    {"dstShard", ...});

3. Rules for denoting individual entities and collections:

• a separate mention of an entity name in the singular implies that the parameter value contains a description of that entity. For example, table is a description of a table (however, in this case, it is better to add a suffix, that is, tableId clearly indicates that the parameter contains a table identifier, tableName — a table name, tableDesc — a table description, etc.);
• a separate mention of an entity name in the plural implies that the parameter value contains a description of a collection of entities. For example, tables is a description of several tables (but not their count);
• a separate mention of an entity name in the plural with the addition of Count implies that the parameter value contains the number of elements in the collection. For example, tablesCount — the number of tables;
• it is undesirable to add Size instead of Count to the parameter name to denote the number of elements in a collection. For example, the parameter name totalFilesSize makes it unclear whether we are talking about the number of files or their total size.

YDB_LOG_INFO("Backup volumes progress",
    {"currentVolumeNum", ...},
    {"volumesCount", ...},
    {"volumesSizeBytes", ...});

YDB_LOG_INFO("Backup volumes progress",
    {"currentVolume", ...},
    {"volumes", ...});

4. If a commonly accepted abbreviation or term in YDB is used in a parameter name, it should be written in the case in which it is conventionally used. Examples of such parameter names:

• VDiskId — VDisk identifier (written not as vdiskId);
• PDiskId — PDisk identifier (written not as pdiskId);
• etc.

5. Popular abbreviations are allowed (idx instead of index, msg instead of message, tx instead of transaction, etc.).

6. If a parameter contains a numeric value, it is desirable to add a suffix to the parameter name:

• Id, if the number is an identifier (but not as ID);
• the name of the units of measurement (for example, for memory volumes — Byte, KByte, MByte, for time — Ms, Sec, Min, for indicating percentage fractions of something — Percent, and so on). If a non-standard unit of measurement is used, it is desirable to use the preposition In (for example, bufferSizeInBlocks);

YDB_LOG_INFO("Table dump progress",
    {"tableId", ...},
    {"dumpedRecordsCount", ...},
    {"dumpedSizeBytes", ...},
    {"totalSizeBytes", ...});

YDB_LOG_INFO("Table dump progress",
    {"table", ...},
    {"dumpedRecords", ...},
    {"dumpedSize", ...},
    {"totalSize", ...});

7. If a numeric parameter value is more convenient for a person to analyze not in decimal form, it is better to specify this value as a character string and supplement it with commonly accepted characters (for example, a hexadecimal representation should have the prefix 0x, and a binary one should have the prefix 0b, etc.). A good practice is to supplement the parameter name with the suffix Hex or similar.

unsigned flags;
...
YDB_LOG_INFO("Invalid access rights to file",
    {"filename", ...},
    {"aclFlags", flags},
    {"aclFlagsOct", ToOct(flags)});         // Make flags as "0XXXXX" string

unsigned flags;
...
YDB_LOG_INFO("Invalid access rights to file",
    {"filename", ...},
    {"aclFlags", flags});

8. If a parameter contains textual information, it is desirable to add a suffix to the parameter name that makes it easier to interpret the parameter value (for example, Name, Desc, Json, Base64, etc.).
9. Local variable naming rules can be applied to parameter names (for example, for boolean flags, add is, has, or similar to the beginning of the parameter name).

Commonly accepted parameter names

There are commonly accepted parameter names that are desirable to use.

Methodology for enriching logs with contextual information

The following methodology is proposed for enriching events that a specific actor writes to the log.

Step 1. The actor should implement a function that forms the current logging context as a set of parameters attached to logged messages.

TStructuredMessage GetLogContext() const {
    return YDB_LOG_CREATE_MESSAGE(
        {"actorClassName", "TFileReader"},
        {"selfId", SelfId()},
        {"sourceFilePath", filename});
}

Step 2. Setting up the context at "entry points". Each actor has a small set of functions that can be called by the actor system core. These include:

1. The Bootstrap function.
2. Message processing functions (found by the STATEFN macro or similar).
3. Other virtual functions that the actor overrides (they are easily found by the override keyword).

Then, in the first line of each such function, the logging context should be configured using the YDB_LOG_CREATE_CONTEXT macro.

STATEFN(StateWork) {
    YDB_LOG_CREATE_CONTEXT(GetLogContext());
    switch (ev->GetTypeRewrite()) {
        ...
    }
}