Логирование

Назначение

В YDB осуществляется структурированное логирование происходящих событий.
Структурированность подразумевает, что в логе (журнале работы) текстовое описание событий отделено от параметров этих событий, а сами значения параметров хранятся и обрабатываются независимо друг от друга. Например, если произошла ошибка чтения файла, то её описание — это текст вида "Ошибка чтения файла", а параметры — это путь к файлу, код системной ошибки, текстовое описание системной ошибки и т.п.

Разделение описания событий и их параметров впоследствии может быть использовано для эффективного поиска сообщений, сбора статистики, оптимизированного хранения журнала и прочих задач.

Базовые средства записи сообщений в лог

В большинстве случаев при записи сообщений в лог выполняются следующие условия:

1. Исходный код содержится в некотором файле .cpp (логирование из заголовочных файлов поддерживается, но рассматривается далее).
2. В одном файле .cpp все сообщения пишутся от имени одного и того же компонента. Поэтому в начале файла (но после всех директив #include) должен быть определён макрос YDB_LOG_THIS_FILE_COMPONENT, который задаёт код компонента для всего файла.

Пример:

#define YDB_LOG_THIS_FILE_COMPONENT NKikimrServices::STATESTORAGE

#undef YDB_LOG_THIS_FILE_COMPONENT

3. Логирование происходит в ходе работы актора, и для работы с контекстом (в частности, отправки сообщений актору логирования) доступна переменная NActors::TlsActivationContext.

Далее в этом файле .cpp для логирования сообщений могут использоваться следующие макросы:

В аргументах вызова перечисленных макросов указываются следующие параметры:

• message — текстовое сообщение;
• ...values... — опциональные параметры. Каждый параметр указывается в виде пары {name, value}, где name — текстовая строка с названием параметра, а value — значение параметра.

Примеры записи сообщений в журнал:

1. Сообщение без параметров:

YDB_LOG_INFO("Module started");

2. Сообщение с параметрами:

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});

Расширенные средства записи сообщений в лог

Ядро логирования

Наиболее низкоуровневым средством для записи сообщений в журнал является макрос YDB_LOG_CTX_COMP. Он проверяет необходимость логирования (согласно настройкам), формирует текстовое сообщение, прикрепляет к нему опциональные параметры и затем отправляет всю эту информацию актору логирования. Далее, актор логирования обрабатывает полученное сообщение согласно своим текущим настройкам (например, записывает в файл или syslog).

Полный синтаксис макроса логирования выглядит следующим образом:

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

В аргументах вызова макроса указываются следующие параметры:

• ctx — контекст исполнения актора (необходим для отправки сообщения актору логирования);
• prio — уровень логирования сообщения (соответствует уровням логирования);
• comp — идентификатор компонента;
• message — текстовое сообщение;
• ...values... — опциональные параметры. Каждый параметр указывается в виде пары {name, value}, где name — текстовая строка с названием параметра, а value — значение параметра.

В примерах ниже EXAMPLE_COMP_CODE обозначает код компонента логирования. В рабочем коде вместо него укажите существующий компонент, например 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});

Макрос YDB_LOG_CTX_COMP подразумевает динамическое определение уровня сообщения и его передачу в виде аргумента. По аналогии с базовыми средствами логирования, существует ряд макросов, которые не требуют передачи уровня сообщения в виде аргумента.

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

На основе макроса YDB_LOG_CTX_COMP работает множество других макросов, рассматриваемых далее. Их названия строятся по следующей схеме:

1. Имя макроса всегда начинается с YDB_LOG.
2. Если макрос не требует указания уровня сообщения, то к имени макроса через символ подчеркивания добавляется название уровня сообщения.
3. Если макрос требует указания контекста исполнения, то к имени макроса добавляется _CTX.
4. Если макрос требует указания компонента, то к имени макроса добавляется _COMP.

Использование стандартного контекста исполнения

В большинстве случаев для передачи сообщений актору логирования используется контекст исполнения, доступный через глобальную переменную NActors::TlsActivationContext. Для того, чтобы исходные тексты не были визуально перегружены обращениями к этой глобальной переменной, введён дополнительный макрос YDB_LOG_COMP, который всегда использует NActors::TlsActivationContext и не требует указания параметра CTX.

Пример:

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

В этом примере используется стандартный контекст исполнения, а логирование происходит от имени компонента с кодом EXAMPLE_COMP_CODE.

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

Использование компонента по умолчанию

Используется тот же механизм, что и в базовых средствах логирования:

1. В начале файла (но после всех директив #include) должен быть определён макрос YDB_LOG_THIS_FILE_COMPONENT. Он задаёт код компонента для всего файла.

#undef YDB_LOG_THIS_FILE_COMPONENT

2. Далее в файле должны использоваться макросы логирования, не требующие указания кода компонента. Они аналогичны уже рассмотренным ранее, но их имя не содержит в себе строку _COMP.

Пример:

#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});

Логирование в заголовочных файлах

Если в заголовочном файле необходимо логирование, то следует использовать макросы, требующие явного указания кода компонента:

1. YDB_LOG_CTX_COMP — требует явного указания уровня сообщения, контекста исполнения и кода компонента.
2. YDB_LOG_XXXX_CTX_COMP — не требует указания уровня сообщения.
3. YDB_LOG_COMP — использует стандартный контекст исполнения.
4. YDB_LOG_XXXX_COMP — использует стандартный контекст исполнения и не требует указания уровня сообщения.

Построение сообщений

Переиспользуемые наборы прикрепляемых параметров

Если один и тот же набор параметров прикрепляется к различным сообщениям, то во избежание дублирования кода можно заранее создать этот набор параметров, а затем его переиспользовать при логировании различных событий. Для этого предназначен макрос YDB_LOG_CREATE_MESSAGE. В качестве аргументов он принимает набор параметров (в виде пар {name, value}), а в качестве результата возвращает объект, который впоследствии может быть использован при отправке сообщений в журнал.

#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
}

Результат вызова макроса YDB_LOG_CREATE_MESSAGE является экземпляром класса TStructuredMessage. Этот экземпляр хранит набор входящих в него параметров, их имена, типы и значения. Экземпляры класса TStructuredMessage можно хранить в локальных и глобальных переменных, копировать, передавать и т.д.

Поддерживаются операции по изменению ранее созданного набора параметров:

1. Добавление и обновление.

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

2. Удаление параметров.

context.RemoveValue("socket");

Вложенные наборы параметров

Возможно создание вложенных наборов прикрепляемых параметров. Для этого при логировании сообщения (или создании другого набора параметров) в паре {name, value} в качестве значения должен быть указан ранее созданный набор значений (т.е. экземпляр класса TStructuredMessage). Тогда в итоговое сообщение (или создаваемый набор значений) будут автоматически добавлены все параметры из набора value, но к именам этих параметров будет добавлен префикс, указанный в name, с разделителем ..

#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;
    }
    ...
}

Контексты логирования

Формирование и переиспользование наборов прикрепляемых параметров неудобно в следующих случаях:

1. Эти наборы нужно указывать при логировании большого количества сообщений.
2. Эти наборы нужно передавать во все вызываемые функции, чтобы там указывать при логировании сообщений.

Можно упростить исходный код, если использовать контекст логирования — набор параметров, которые будут автоматически прикрепляться ко всем сообщениям, отправляемым в журнал в данном потоке исполнения. Для этого нужно вызвать макрос YDB_LOG_CREATE_CONTEXT и передать ему пары {name, value} (так же, как при отправке сообщений в журнал или создании переиспользуемых наборов), а также ранее созданные объекты TStructuredMessage. Добавление перечисленных в YDB_LOG_CREATE_CONTEXT параметров происходит при логировании в блоке кода, где вызван этот макрос, а также во вложенных блоках кода и всех вызываемых функциях.

#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",     // К сообщению будут прикреплены параметры sourceFilePath и errorCode
            {"errorCode", errorCode});
        return;
    }
    ...
    YDB_LOG_NOTICE("MyFunction succeeded");    // К сообщению будет прикреплён параметр sourceFilePath
}

Контексты логирования организованы в виде стека. Если контекст логирования настроен, то он хранится в верхушке стека. У каждого потока исполнения свой стек контекстов логирования.

При вызове YDB_LOG_CREATE_CONTEXT происходят действия:

1. Создаётся новый набор параметров (как и при вызове YDB_LOG_CREATE_MESSAGE), содержащий все параметры из уже существующего контекста, а также параметры, непосредственно указанные в макросе YDB_LOG_CREATE_CONTEXT.
2. Новый набор параметров помещается на верхушку стека и, таким образом, становится текущим контекстом логирования в данном потоке исполнения.
3. При записи сообщения в журнал (вызове макроса YDB_LOG_CTX_COMP или т.п.) к сообщению автоматически прикрепляются параметры из верхушки стека контекстов логирования, а поверх этого набора записываются параметры, указанные в макросе логирования.
4. Верхушка стека будет автоматически удалена при выходе из текущего блока, и таким образом произойдёт возврат к предыдущему настроенному контексту.

Чтобы добавить параметры в текущий контекст или обновить их значения, необходимо использовать макрос YDB_LOG_UPDATE_CONTEXT:

YDB_LOG_UPDATE_CONTEXT({"requestId", requestId});

В макросе YDB_LOG_UPDATE_CONTEXT может быть указано сразу несколько параметров и их значений. Если указанные параметры уже существуют в контексте, то их значения будут обновлены. Если указанные параметры отсутствуют в контексте, то их значения будут добавлены в контекст.

Чтобы удалить параметры из текущего контекста, необходимо передать их имена в YDB_LOG_REMOVE_CONTEXT:

YDB_LOG_REMOVE_CONTEXT("requestId");

Макросы YDB_LOG_UPDATE_CONTEXT и YDB_LOG_REMOVE_CONTEXT могут вызываться сколько угодно раз. Они изменяют только текущий контекст (то есть верхушку стека контекстов), но не создают новых контекстов и никак не затрагивают другие контексты, расположенные ниже по стеку контекстов.

Рекомендации по наполнению логов

Безопасность

Запрещается записывать в лог пароли, токены доступа, ключи шифрования, строки подключения и персональные данные. Если значение необходимо для диагностики, то перед передачей в макрос необходимо удалить чувствительную часть, замаскировать её или заменить необратимым хешем.

Стиль кодирования

Рекомендуется следующий стиль кодирования при использовании макросов логирования:

1. Вся обязательная информация (контекст исполнения, код компонента, уровень сообщения и текст сообщения) располагается на одной строке.
2. Каждая пара {name, value} располагается на отдельной строке.

Пример записи сообщения с несколькими параметрами:

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

Стиль текстовых сообщений

Рекомендуется следующий стиль написания текстов сообщений:

1. Текст является осмысленным (и желательно корректным) предложением на английском языке, говорящим о некотором событии внутри системы, при этом:

   • текст начинается с заглавной буквы;
   • если текст представляет собой отдельное предложение, то точка в конце сообщения не ставится;
   • если текст состоит из нескольких предложений, то они разделяются точками, но после последнего предложения точка не ставится.

2. Текст может содержать имена классов и функций. Если актор логирует факт получения некоторого сообщения, то хорошей практикой является логирование с текстом Handle <имя класса-события>.

3. Сообщения являются фиксированным текстом без динамически формируемых фрагментов.

4. Вся динамическая информация, известная только на момент исполнения, должна помещаться в виде прикрепляемых параметров.

Для согласования текстов сообщений и названий параметров существует простое эмпирическое правило:

Если взять текст сообщения и к нему добавить значения параметров в виде (name=value, name=value, ... ), то должно получиться осмысленное, законченное, однозначное и понятное человеку текстовое сообщение.

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

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

Общие рекомендации по именованию отдельных параметров

Стиль именования отдельных параметров строится на двух базовых принципах:

1. В контексте конкретного сообщения значение параметра должно интерпретироваться просто и однозначно.

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. Семантически близкие параметры должны иметь одинаковые названия, поскольку различное именование одних и тех же понятий затрудняет поиск записей в логах. Например, нежелательно в одних сообщениях идентификатор транзакции обозначить как txId, а в других — как transactionId.

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. Названия параметров пишутся в camelCase.

Частные рекомендации по именованию отдельных параметров

Далее перечисляются рекомендации, направленные на выполнение двух указанных выше принципов:

1. Нежелательно в качестве названий параметров использовать отдельные общеупотребимые слова (id, item, value, path, child, parent, min, max, и т.п.) — это осложняет поиск записей в логах. Например, слово id обозначает идентификатор, но при этом совершенно непонятно, к какой сущности он относится, хотя в контексте конкретного сообщения смысл этого параметра может быть предельно ясен.

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. Названия параметров должны состоять из нескольких слов, причём главным должно быть последнее слово, а каждое предшествующее должно уточнять смысл последующего. Например:

• actorId — идентификатор актора;
• operationId — идентификатор операции;
• operationName — название операции;
• operationSessionId — идентификатор сессии, в рамках которой выполняется операция.

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

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

3. Правила обозначения отдельных сущностей и коллекций:

• отдельное упоминание имени сущности в единственном числе предполагает, что значение параметра содержит описание этой сущности. Например, table — это описание таблицы (однако, в данном случае лучше добавлять суффикс, то есть tableId явно указывает, что параметр содержит идентификатор таблицы, tableName — название таблицы, tableDesc — описание таблицы и т.д.);
• отдельное упоминание имени сущности во множественном числе предполагает, что значение параметра содержит описание коллекции сущностей. Например,
  tables — это описание нескольких таблиц (но не их количество);
• отдельное упоминание имени сущности во множественном числе с добавлением Count предполагает, что значение параметра содержит количество элементов в коллекции. Например, tablesCount — количество таблиц;
• нежелательно для обозначения количества элементов в коллекции к названию параметра вместо Count добавлять Size. Например, по названию параметра totalFilesSize — непонятно, речь идёт о количестве файлов или их суммарном размере.

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

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

4. Если в названии параметра используется общепринятая в YDB аббревиатура или термин, то её следует писать в том регистре, в котором принято. Примеры названия таких параметров:

• VDiskId — идентификатор VDisk (пишется не как vdiskId);
• PDiskId — идентификатор PDisk (пишется не как pdiskId);
• и т.д.

5. Допустимо использовать популярные сокращения (idx вместо index, msg вместо message, tx вместо transaction и т.д.).

6. Если параметр содержит числовую величину, то желательно к названию параметра добавлять суффикс:

• Id, если число является идентификатором (но не как ID);
• название единиц измерения (например, для объёмов памяти — Byte, KByte, MByte, для времени — Ms, Sec, Min, для указания процентных долей чего-либо — Percent и так далее). Если используется нестандартная единица измерения, то желательно использовать предлог In (например, bufferSizeInBlocks);

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

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

7. Если числовое значение параметра человеку удобнее анализировать не в десятичном виде, то лучше это значение указывать как символьную строку и дополнять общепринятыми символами (например, у шестнадцатеричного представления должен быть префикс 0x, а у двоичного — префикс '0b' и т.д.). Хорошей практикой является дополнение названия параметра суффиксом Hex или т.п.

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. Если параметр содержит текстовую информацию, то желательно к названию параметра добавлять суффикс, позволяющий легче интерпретировать значение параметра (например, Name, Desc, Json, Base64 и т.п.).
9. Для именования параметров можно применять правила именования локальных переменных (например, для логических признаков следует в начало названия параметра добавлять is, has или т. п.).

Общепринятые названия параметров

Существуют общепринятые названия параметров, которые желательно использовать.

Методология обогащения логов контекстной информацией

Предлагается следующая методология для обогащения событий, которые пишет в журнал конкретный актор.

Шаг 1. В акторе должна быть реализована функция, которая формирует текущий контекст логирования в виде набора параметров, прикрепляемых к логируемым сообщениям.

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

Шаг 2. Настройка контекста в "точках входа". У каждого актора есть небольшой набор функций, которые могут быть вызваны ядром акторной системы. Сюда входят:

1. Функция Bootstrap.
2. Функции обработки сообщений (ищутся по макросу STATEFN или т.п.).
3. Прочие виртуальные функции, которые переопределяет актор (они легко ищутся по ключевому слову override).

Далее в первой строке каждой такой функции с помощью макроса YDB_LOG_CREATE_CONTEXT должен настраиваться контекст логирования.

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