Привет, Хабр! На связи Андрей Алексеенко, техлид оператора рекламных данных (ОРД) «МедиаСкаут». В предыдущем посте мы начали рассказывать о том, как своевременно передаем информацию в единый реестр интернет-рекламы (ЕРИР) — показали настройку гарантированной доставки данных внешним сервисам. Сегодня предлагаю пойти дальше и обсудить, что мы сделали, чтобы вовремя находить, локализовать и устранять проблему, если по какой-то причине (а их множество, и потому разбирать нет смысла) доставка все же не случилась.
Речь о наблюдаемости за системой, которая держится на трех принципах: логирование, трассировка, метрики. В материале разберем механизм контекста структурированного логирования и посмотрим на примерах, как использовать EventId в .NET Core для классификации событий в логах, чтобы быстро понимать, где и что сломалось. Итак, поехали!
Структурированное логирование — must have при многомиллионных запросах
Очень часто в своей практике я встречал строки кода подобного плана:
logger.LogInformation("Процесс запущен"); logger.LogInformation("Обработка данных"); logger.LogInformation("Процесс завершен");
И в лог-файл в этом случае записывалось примерно следующее — не связанные между собой текстовые сообщения:
2026-04-15 10:00:01 | INFO | Процесс запущен 2026-04-15 10:00:02 | INFO | Обрабатываем данные 2026-04-15 10:00:03 | ERROR | Ошибка отправки запроса в ЕРИР
По сути, ничего плохого в этом нет, но вот анализировать такие записи довольно сложно, особенно когда у вас многомиллионные запросы:
поиск по тексту медленный и неточный;
нет связи между сообщениями;
автоматизация разбора кастомных сообщений становится очень сложной задачей;
трудно, а порой и невозможно подсчитать статистику (например, число ошибок в день, месяц).
В таких случаях спасает структурированное логирование — запись логов в формате данных (обычно JSON), а не текста. Каждое сообщение содержит пары «ключ — значение»:
{ "EventId": 201, "http.request.method": "POST", "invoice.id": "ACT-12345", "MessageTemplate": "Запрос отправлен" }
Да, запись в лог становится громоздкой, прочитать ее сложнее, зато появляются значительные преимущества:
автоматическая агрегация данных (подсчет событий, группировка по статусам);
обогащение логов контекстом (значениями переменных);
самое важное — данные можно импортировать в специальные системы для анализа логов. Мы, например, используем ELK (Elasticsearch, Logstash, Kibana), поэтому в материале я буду делать отсылки к этой системе;
быстрый поиск и фильтрация по полям — этот пункт достоин отдельного обсуждения ниже.
Раньше, чтобы найти нужное в логах, использовали grep. Например, команда grep -E "ERROR|WARNING" webapi_log_01_04_2026.log показывала все ошибки и предупреждения. Или открывали файл в Notepad++ и искали вручную. Но даже такой подход уже удобнее, чем ничего: можно отфильтровать конкретные события. Например, команда grep -r '"EventId": 202' /path/to/logs/.log найдет все записи с событием 202 сразу во всех логах в папке.
Однако все начинает играть красками, если использовать такой инструмент, как Kibana:
На картинке показано, как можно отфильтровать логи по полю EventId. А на скриншоте ниже видно список запросов, где у пользователей были ошибки, — сразу понятно, в UI проблема или в Web API:
Благодаря этому мы можем оперативно подсказать пользователям, что у них ошибка в запросе. А сколько времени уйдет на анализ текстового лога, чтобы собрать подобную аналитику? Думаю, разница очевидна.
Как работает контекст логирования: передаем данные между слоями и ищем по цепочке событий
Важная часть структурированного лога — контекст логирования. Его задача «прикрепить» дополнительные данные (например, ID акта, параметры запроса, тип операции) ко всем записям в лог внутри определенного блока кода. Эти данные автоматически добавляются к каждому сообщению, пока контекст активен.
Посмотрим на примере — фрагменте кода из запроса, который мы отправили в ЕРИР:
partial void PrepareRequest(HttpClient client, HttpRequestMessage request, string url) { var logFields = new Dictionary<string, object> { ["http.request.method"] = request.Method, ["http.request.url"] = url, ["http.request.path"] = request.RequestUri.LocalPath }; if (request.Method == HttpMethod.Post || request.Method == HttpMethod.Put) { if (request.Content != null) { logFields.Add(LogFields.HttpRequestBody, request.Content.ReadAsStringAsync().GetAwaiter().GetResult()); } } httpRequestScope = logger.BeginScope(logFields); stopwatch = new Stopwatch(); stopwatch.Start(); }
Перед отправкой в контекст логирования добавили параметры запроса, «прикрепили» следующее:
var logFields = new Dictionary<string, object> { ["http.request.method"] = request.Method, ["http.request.url"] = url, ["http.request.path"] = request.RequestUri!.LocalPath }; … _httpRequestScope = _logger.BeginScope(logFields);
Основной инструмент — метод BeginScope() у ILogger<T>, он возвращает объект IDisposable. Пока этот объект не удален Dispose(), все логи внутри блока получают данные из контекста. Таким образом мы получаем средство для передачи любых значений в лог между самыми разными вызовами. Более того, можем создавать новый контекст, и если у предыдущего не был вызван Dispose(), в лог будут попадать данные из обоих контекстов.
Но важно понимать и учитывать, что увеличение данных в контексте может привести к увеличению потребления памяти в момент пиковых нагрузок на систему. Поэтому рекомендую добавлять в контекст логирования только простые типы данных, что гарантирует минимальное потребление памяти.
Но не всегда есть возможность писать в лог минимум информации. Например, у себя в логах мы сохраняем весь трафик с ЕРИР (для нас и наших клиентов очень важно фиксировать, что и когда мы отправили и какой ответ получили на случай возникновения вопросов между нами, клиентом и ЕРИР) — это довольно-таки большой объем. И тут контекст логирования прекрасно справляется, данные в памяти долго не задерживаются, уборщик мусора действует на отлично. Вот пример метрик по памяти в момент нагрузки на систему, примерно 300 rps:
К сожалению, не могу сказать точно, сколько именно из общего объема заняло логирование, но что можно сказать однозначно: контекст не мешает, а избавляет от множества рутинных задач.
Преимущества
Я бы выделил три основных преимущества:
автоматическое добавление полей, благодаря которому не нужно вручную передавать ID между методами;
если открыть новый контекст внутри существующего, поля объединяются;
есть ограничение по области, поэтому, когда контекст закрывается (Dispose()), новые поля уже не добавляются.
Вот как это работает на примере все того же запроса в ЕРИР:
1. Создаем словарь с данными контекста:
var logFields = new Dictionary<string, object> { ["InvoiceID"] = "INV-789", ["UserID"] = "U-456" };
2. Запускаем контекст с помощью BeginScope():
using (_logger.BeginScope(logFields)) { // Весь код внутри этого блока будет логироваться с полями из logFields _logger.LogInformation("Начало обработки акта"); // ... какой‑то код ... _logger.LogWarning("Обнаружено предупреждение: не заполнены параметры"); // ... еще код ... _logger.LogError("Ошибка: не удалось отправить акт в ЕРИР"); }
3. Смотрим, что происходит внутри блока using.
Каждый вызов _logger (например, LogInformation, LogError) автоматически включает поля из logFields. Так мы получаем записи в лог-файл:
[ { "Timestamp": "2026-03-15T10:05:01", "Level": "INFO", "Message": "Начало обработки акта", "InvoiceID": "INV-789", "UserID": "U-456", "Environment": "Development" }, { "Timestamp": "2026-06-15T10:05:10", "Level": "WARNING", "Message": "Обнаружено предупреждение: не заполнены параметры ", "InvoiceID": "INV-789", "UserID": "U-456", "Environment": "Development" }, { "Timestamp": "2026-03-15T10:05:25", "Level": "ERROR", "Message": " Ошибка: не удалось отправить акт в ЕРИР ", "InvoiceID": "INV-789", "UserID": "U-456", "Environment": "Development" } ]
4. Завершаем контекст. Когда выполнение выходит из блока using, контекст автоматически закрывается (вызывается Dispose()). Все последующие логи уже не будут содержать InvoiuceID, UserID и так далее.
Что нам дал контекст логирования:
Быстрое понимание сути проблемы. В логе сразу видны все важные параметры (кто, что, где).
Упрощенная фильтрация. Можно искать все ошибки для конкретного акта (InvoiceID: "INV-789") или пользователя.
Меньше ручного труда. Не нужно передавать ID через десятки методов — контекст делает это автоматически.
Гибкость. Легко добавлять новые поля без изменения логики приложения.
Аналитика. В системах типа Kibana можно строить дашборды по полям из контекста (например, «количество ошибок по типам запросов»).
На этом можно было бы поставить точку, но, как и везде, не обходится без подводных камней.
Подводные камни
Вот с чем можно столкнуться по ходу работы:
1. Контекст может потеряться между асинхронными операциями или сброситься при переключении потоков (например, после await). Пример:
using (_logger.BeginScope("RequestId: {RequestId}", requestId)) { await SomeAsyncOperation().ConfigureAwait(false); // Контекст сбросится _logger.LogInformation("Это сообщение потеряет RequestId"); }
Основная причина: отказ от восстановления предыдущего контекста синхронизации после await, так что лучше избегать ConfigureAwait(false) в коде логирования.
2. В некоторых средах (например, консольных приложениях) SynchronizationContext отсутствует или сбрасывается, что нарушает цепочку распространения контекста.
3. BeginScope работает корректно в асинхронном коде благодаря механизму AsyncLocal<T>, но довольно легко можно создать ситуацию, при которой контекст логирования не будет использоваться. Рассмотрим простой пример, как работает механизм сохранения контекста логирования:
при вызове BeginScope создается новая область логирования;
контекст сохраняется в AsyncLocal<T>;
при выполнении await ExecutionContext захватывает и сохраняет этот контекст;
после await контекст восстанавливается автоматически.
Пример корректной работы:
using (_logger.BeginScope("RequestId: {RequestId}", requestId)) { await SomeAsyncOperation(); // Контекст сохранится _logger.LogInformation("Сообщение с RequestId"); // RequestId будет в логе }
Однако если использовать Task.Run(…) для запуска потоков, контекст логирования потеряется. Task.Run запускает код в потоке из пула потоков (ThreadPool), что приводит к следующим проблемам:
поток пула имеет свой ExecutionContext, который не содержит сохраненного контекста логирования;
Task.Run не захватывает текущий ExecutionContext по умолчанию;
контекст AsyncLocal<T> привязан к логическому потоку выполнения, а не к физическому потоку.
Пример потери контекста:
using (_logger.BeginScope("RequestId: {RequestId}", "123")) { await Task.Run(() => { _logger.LogInformation("Это сообщение НЕ получит RequestId!"); // Контекст потерян }); }
Самый простой вариант, как этого избежать, это явно передавать ILogger внутрь Run и создавать контекст внутри метода:
var currentLogger = _logger; await Task.Run(() => { using (currentLogger.BeginScope("RequestId: {RequestId}", "123")) { currentLogger.LogInformation("Теперь RequestId доступен"); } });
Еще вместо Task.Run(…) можно использовать ValueTask, но все же лучше избегать подобных ситуаций и использовать именно асинхронные версии функций.
Не забывайте очищать контекст логирования, так как при большом rps можно быстро получить утечку памяти.
Используйте библиотеки с поддержкой асинхронного контекста, например NLog или Serilog.
Старайтесь выделять время для проверки записи данных в лог еще на этапе разработки, потому что на проде уже будет поздно.
Классифицируем события в .NET Core с помощью EventId для быстрой навигации по инцидентам
EventId — это числовой идентификатор, который присваивается определенному типу события (записи в логе) в приложении. Он служит своего рода меткой, позволяющей быстро классифицировать, фильтровать и анализировать записи в логах.
Вернемся к простой форме логов.
2026-04-15 10:00:01 | INFO | Процесс запущен 2026-04-15 10:00:02 | INFO | Обрабатываем данные 2026-04-15 10:00:03 | ERROR | Ошибка отправки запроса в ЕРИР
Здесь нет классификатора событий. Чтобы найти ошибки отправки запросов в ЕРИР, нужно выполнить поиск по фрагменту текста, что долго и не очень точно (могут попасться похожие фразы).
EventId же помогает назначить уникальный номер каждому событию.
{ "Timestamp": "2026-04-15T10:05:22", "Level": "ERROR", "EventId": 500, "Message": "Не удалось отправить запрос в ЕРИР" }
Так для поиска достаточно отфильтровать логи по EventId = 500.
Чтобы использовать EventId в .NET Core:
1. Определяем идентификаторы. Создаем статический класс для хранения всех EventId (кому как удобнее, но на мой взгляд такие идентификаторы должны храниться в одном месте, чтобы избежать дублирования и накладок):
public static class ErirEventIds { public static readonly EventId ReqeustSendingSuccess = new EventId(1001, "Запрос успешно отправлен в ЕРИР"); public static readonly EventId ReqeustSendingFailed = new EventId(1002, "Не удалось отправить запрос в ЕРИР"); }
2. Записываем логи с EventId. Используем перегрузку метода логирования, которая принимает EventId:
_logger.LogInformation(ErirEventIds.ReqeustSendingSuccess, “”);
Когда логи содержат EventId, их легко находить и анализировать в системах типа Kibana, Grafana или даже в Excel. Так из набора текстов они превращаются в структурированные данные, что помогает:
быстрее находить проблемы;
строить дашборды и графики;
автоматизировать мониторинг;
улучшить читаемость для всей команды.
Структурированное логирование на практике
Для закрепления материала перейдем к практической части. Я подготовил небольшой проект на GitHub на основе стандартного шаблона по WEBAPI.
Для настройки в конфигурационном файле appsettings.Development.json в свойстве path укажите, куда записывать лог. Теперь можно переходить к логированию.
В проект добавлен пакет mediatr для взаимодействия с бизнес-логикой приложения:
В строке 23 создается контекст логирования и в него добавлен ключ path, далее мы делаем вызов через mediatr к нашему запросу. Обратите внимание, что в контроллере нет записи в лог — только подготовленный контекст.
Выполняем логирование в обработчике запроса — и теперь посмотрим, что у нас записалось в лог-файл:
Теперь посмотрим на две строки (я отформатировал их для удобства чтения), по EventId вы легко найдете нашу запись. Обратите внимание на то, как отработал контекст логирования: в контроллере мы присвоили значение, записали его в обработчике запроса mediatr, а данные из контекста контроллера записались в обработчике запроса! При том что контроллер ничего не знает об обработчике — ровно, как и обработчик о контроллере
Благодаря этому можно добавлять свои ключи для отслеживания нужных данных и построения цепочек прохождения — от момента, когда клиент нажимает кнопку «Отправить», до записи в СУБД. Поэтому при работе с каждым актом мы всегда добавляем идентификатор в контекст логирования еще на старте редактирования. Все, что будет писаться в лог, будет содержать его идентификатор. Так мы легко можем найти все, что происходило именно с этим актом.
Итоги
Вот что мы получили после внедрения структурированных логов:
можем полноценно делать аналитику: строить графики и дашборды, настроить оповещения;
быстро находим локализацию проблемы через поиск по EventId и фильтрацию по контекстным полям;
стандартизировали имена полей во всей инфраструктуре с помощью EventId;
обогащаем контекст тем, что передаем данные между модулями без ручного кодирования.
А еще asp.net core добавил два важных поля — TraceId и SpanId. Это ниточки, которые позволяют собрать всю цепочку записей в одну последовательность. А мы получаем в руки мощный инструмент фиксации событий в нашем приложении: настраивая фильтры в Kibana по EventId и дополнительным полям, легко можем находить сбои в системе, раскручивая цепочки вызовов, приведшие нас в проблемную точку.
В следующей части подробнее поговорим как раз о трассировке и как она связывается с логами. Не переключайтесь!