Контекст потока в логировании C++: thread-local context в logme

Хороший лог должен отвечать не только на вопрос «что произошло», но и давать контекст: с каким запросом, соединением, клиентом или фоновой задачей связано сообщение.

Пока программа небольшая, нужные данные легко добавить прямо в текст:

LogmeI(
  "Request %s: loading profile for user %d"
  , requestId
  , userId
);

Проблема начинается глубже в стеке вызовов. requestId нужен обработчику запроса, затем сервису, затем репозиторию, HTTP-клиенту и библиотечному коду. Самим этим функциям идентификатор запроса зачастую вообще не нужен — он передаётся только для того, чтобы через несколько уровней снова попасть в лог.

Так появляются лишние параметры:

void HandleRequest(
  const char* requestId
  , int userId
);

void LoadProfile(
  const char* requestId
  , int userId
);

void ReadFromDatabase(
  const char* requestId
  , int userId
);

Чем больше диагностических данных, тем хуже становится ситуация. Кроме request_id может понадобиться connection_id, tenant, подсистема, канал вывода или специальный режим форматирования.

Для этого в logme существует контекст потока в логировании — thread-local logging context. Нужный контекст можно установить один раз на границе операции, после чего код глубже в стеке продолжает использовать обычные LogmeI(), LogmeW() и другие вызовы logme.

Что можно связать с текущим потоком

В logme нет единственного большого объекта LoggingContext. Вместо него используются несколько независимых механизмов.

Канал для текущего потока задаётся через:

LogmeThreadChannel(channel);

Подсистема:

LogmeThreadSubsystem(subsystem);

Структурированные поля:

LogmeThreadFields(fields);

Временные параметры вывода:

LogmeThreadOverride(override);

Есть также LogmeThreadName(...), позволяющий дать потоку понятное имя. Это близкая по назначению возможность, хотя внутри logme имя потока хранится другим способом и не является частью того же thread_local объекта.

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

Пример: request_id задаётся один раз

Предположим, сервер получил запрос. В точке входа уже известны канал, подсистема и идентификатор запроса.

Logme::ID WebChannel{ "web" };
Logme::SID BillingSubsystem = Logme::SID::Build("billing");

static void LoadProfile(int userId)
{
  LogmeI("Loading profile for user %d", userId);
}

static void CheckBilling()
{
  LogmeI("Checking billing state");
}

void HandleRequest(
  int userId
  , const char* requestId
)
{
  Logme::ThreadFields fields;

  fields.Set("request_id", requestId);
  fields.Set("user_id", std::to_string(userId));

  {
    LogmeThreadChannel(WebChannel);
    LogmeThreadSubsystem(BillingSubsystem);
    LogmeThreadFields(fields);

    LogmeI("Request started");

    LoadProfile(userId);
    CheckBilling();

    LogmeI("Request completed");
  }
}

LoadProfile() ничего не знает о requestId. CheckBilling() ничего не знает о канале web. Ни одна из этих функций не получает BillingSubsystem через аргументы.

И это правильно: эти данные нужны не для выполнения самих функций, а для описания контекста, в котором они выполняются.

Всё, что находится внутри scope с установленным thread-local context, может использовать этот контекст при логировании.

Канал текущего потока

LogmeThreadChannel(...) задаёт канал по умолчанию для сообщений текущего потока, если канал не указан непосредственно в вызове.

Это особенно удобно для общего или библиотечного кода.

Например:

static void ProcessProtocol()
{
  LogmeI("Protocol initialized");
  LogmeW("Peer response is delayed");
}

Функция не обязана знать, используется она сейчас клиентом, сервером или тестовым инструментом.

Вызывающая сторона может определить это сама:

{
  LogmeThreadChannel(ClientChannel);
  ProcessProtocol();
}

В другом месте тот же код может выполняться уже в другом канале:

{
  LogmeThreadChannel(ServerChannel);
  ProcessProtocol();
}

Именно такой сценарий демонстрирует поставляемый с logme пример ThreadContext: worker создаёт свой канал и устанавливает его для потока, после чего библиотечная функция пишет обычные сообщения без явного знания о маршрутизации.

Это удобнее, чем заставлять каждую функцию принимать ChannelPtr или ID только потому, что где-то внутри неё есть одна строка лога.

Подсистема тоже может быть частью контекста

LogmeThreadSubsystem(...) решает похожую задачу для subsystem.

Например, канал может описывать общий поток журналов приложения, а subsystem — конкретную функциональную область:

{
  LogmeThreadChannel(WebChannel);
  LogmeThreadSubsystem(BillingSubsystem);

  ProcessPayment();
}

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

Это особенно полезно потому, что subsystem в logme — не просто декоративная подпись. Уровни логирования могут настраиваться отдельно для подсистем, поэтому thread-local subsystem участвует и в фильтрации сообщений.

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

Thread fields и structured logging

Для обработки запросов, соединений и фоновых jobs, пожалуй, наиболее интересен LogmeThreadFields(...).

ThreadFields позволяет связать с текущим потоком набор пар имя = значение:

Logme::ThreadFields fields;

fields.Set("request_id", "req-84721");
fields.Set("tenant", "customer-a");
fields.Set("operation", "load-profile");

После этого набор можно установить на время выполнения операции:

{
  LogmeThreadFields(fields);
  LogmeI("Profile loading started");

  LoadProfile();

  LogmeI("Profile loading completed");
}

При использовании structured output эти значения становятся отдельными полями записи.

Например, JSON может выглядеть примерно так:

{
  "level": "INFO",
  "request_id": "req-84721",
  "tenant": "customer-a",
  "operation": "load-profile",
  "message": "Profile loading started"
}

Это принципиально лучше, чем строить текст:

request_id=req-84721 tenant=customer-a operation=load-profile Profile loading started

В первом случае система сбора логов получает настоящие поля. По request_id можно искать все записи запроса, по tenant — события конкретного клиента, по operation — определённый тип работы.

Текст сообщения при этом остаётся текстом сообщения.

Текущая реализация logme добавляет thread fields в JSON и XML output. В обычном OUTPUT_TEXT эти поля автоматически к строке не приписываются. Это намеренное разделение: ThreadFields — прежде всего механизм structured logging, а не скрытая конкатенация дополнительного текста.

Не обязательно менять весь набор сразу

Для длительно живущего контекста logme позволяет устанавливать отдельные поля непосредственно через Logger.

Например:

Logme::Instance->SetThreadField(
  "request_id"
  , requestId
);

Logme::Instance->SetThreadField(
  "tenant"
  , tenant
);

Поле можно получить через GetThreadField(), удалить через RemoveThreadField(), а весь набор текущего потока очистить с помощью:

Logme::Instance->ClearThreadFields();

Такой вариант может быть удобен в worker loop:

void Worker()
{
  for (;;)
  {
    Job job = GetNextJob();

    Logme::Instance->SetThreadField(
      "job_id"
      , job.Id.c_str()
    );

    ProcessJob(job);

    Logme::Instance->ClearThreadFields();
  }
}

Но здесь появляется очевидный риск: поток продолжает жить после завершения ProcessJob(). Если забыть очистить поле, следующий job унаследует job_id предыдущего.

Поэтому там, где время жизни контекста соответствует обычному C++ scope, лучше использовать RAII-вариант.

Контекст автоматически восстанавливается

LogmeThreadChannel, LogmeThreadSubsystem, LogmeThreadFields и LogmeThreadOverride построены вокруг небольших RAII-классов logme.

При входе в scope сохраняется предыдущее состояние, устанавливается новое, а при уничтожении объекта старое состояние возвращается.

Поэтому вложенный контекст выглядит естественно:

{
  LogmeThreadSubsystem(NetworkSubsystem);

  LogmeI("Connection started");

  {
    LogmeThreadSubsystem(TlsSubsystem);

    LogmeI("TLS handshake started");
    PerformHandshake();
  }

  LogmeI("Connection established");
}

После выхода из внутреннего блока снова действует NetworkSubsystem.

Это работает и при досрочном return, и при C++ exception: восстановление выполняется деструктором.

По сравнению с ручной последовательностью «установить — выполнить — вернуть назад» такой подход заметно труднее случайно сломать.

У LogmeThreadFields(...) есть важная особенность. Новый ThreadFields временно заменяет текущий набор полей, а после выхода предыдущий набор восстанавливается. Автоматического объединения внешнего и внутреннего наборов здесь нет.

Если нужно просто изменить одно поле существующего контекста, для этого лучше подходит SetThreadField().

Thread override без передачи по всему стеку

Контекст текущего потока может содержать и Override.

Например:

Logme::Override override;
override.Remove.Method = true;

{
  LogmeThreadOverride(override);

  ProcessRequest();
}

Теперь вложенное логирование использует этот override без необходимости передавать его через каждый вызов.

Такой подход также используется в официальном примере ThreadContext из исходников logme: worker назначает thread channel и thread override, а затем вызывает функцию библиотеки, которая логирует обычным способом и ничего не знает об этих настройках.

Здесь хорошо виден сам принцип: решение о диагностическом контексте принимается на границе операции, а не размазывается по всей реализации операции.

А зачем тогда ThreadName

Числовой ID потока удобен машине, но обычно плохо читается человеком. Поэтому logme позволяет назначать потоку понятное имя:

LogmeThreadName(
  channel
  , "network-worker-3"
);

Для долгоживущих worker threads это может сильно улучшить читаемость журнала. Вместо набора похожих числовых thread ID становятся видны scheduler, network-worker-3, db-maintenance и другие понятные роли.

Но thread name и request_id решают разные задачи.

Имя отвечает на вопрос:

Какой поток выполнял код?

request_id или job_id отвечает на другой:

Какую конкретную операцию этот поток выполнял?

Один worker за время жизни может обработать тысячи задач, поэтому использовать имя потока вместо идентификатора операции не стоит.

Что происходит при переходе в другой поток

Здесь особенно важно слово thread-local.

Контекст принадлежит текущему потоку. Если работа началась в одном thread, а затем продолжилась в другом, нельзя рассчитывать, что thread-local context автоматически переместится вместе с задачей.

Это особенно важно для thread pool, очередей задач и сложных asynchronous pipelines.

Например, обработчик получил request_id, поставил работу в очередь, а выполнять её позже будет свободный worker. В worker необходимо установить соответствующий контекст уже для этого этапа выполнения.

То есть thread-local context хорошо избавляет от передачи диагностических данных вдоль обычного стека вызовов одного потока, но не является универсальным механизмом propagation между потоками.

Это полезное разделение. logme не пытается незаметно угадать, какая задача в другом потоке является продолжением текущей.

Что стоит помещать в logging context

Thread fields не должны превращаться во вторую копию объекта Request.

В контексте хорошо работают значения, которые помогают связывать множество записей одной операции: request_id, connection_id, job_id, tenant, иногда user_id или название текущей операции.

А данные, относящиеся только к одному событию, лучше оставить непосредственно в сообщении.

Например, request_id относится ко всему запросу:

fields.Set(
  "request_id"
  , requestId
);

а HTTP status появляется только в конце:

LogmeI(
  "Request completed, status=%d"
  , status
);

Так контекст остаётся небольшим и предсказуемым, а сами сообщения сохраняют полезную конкретику.

Когда контекст потока особенно полезен

Наиболее естественно он работает там, где в приложении есть хорошо определённая граница выполнения.

Сервер начал обработку запроса:

{
  LogmeThreadChannel(WebChannel);
  LogmeThreadFields(requestFields);

  HandleRequest();
}

Worker получил новую задачу:

{
  LogmeThreadSubsystem(WorkerSubsystem);
  LogmeThreadFields(jobFields);

  ProcessJob();
}

Или библиотечный код вызывается в контексте конкретного соединения:

{
  LogmeThreadChannel(ConnectionChannel);

  ProtocolLibrary();
}

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

Он просто пишет сообщения.

Контекст логирования не должен менять архитектуру приложения

Это, пожалуй, главная причина использовать thread-local logging context.

Если значение является частью бизнес-логики функции, его, конечно, нужно передавать обычным способом. Нельзя прятать необходимые данные в logging context только ради того, чтобы убрать параметр из сигнатуры.

Но request_id, выбранный logging channel или временный override часто вообще не являются входными данными функции. Они нужны исключительно для диагностики.

Передавать такие значения через десятки уровней API означает заставлять архитектуру приложения обслуживать инфраструктуру журналирования.

Контекст потока позволяет этого избежать.

На границе запроса, job или worker-а мы один раз устанавливаем необходимые channel, subsystem и structured fields. После этого внутренний код остаётся обычным кодом, а его сообщения всё равно получают правильный диагностический контекст.

Именно для этого в logme существует контекст потока в логировании: не чтобы спрятать данные приложения, а чтобы не протаскивать через всё приложение данные, которые нужны только логам.