OpenTelemetry в .NET: трассировка, которая помогает расследовать ошибки

Привет, Хабр! В прошлом материале про поиск причин сбоев мы разбирали структурированное логирование, BeginScope и классификацию событий на примере передачи актов в Единый реестр интернет-рекламы (ЕРИР). Продолжим тему.

Логи помогают узнать подробности события, но путь запроса через несколько сервисов по ним не соберешь. Особенно когда непонятно, куда ушло время: на проверку данных, на сохранение документа или на ожидание ответа внешней системы. Распределенная трассировка помогает это понять. Настроим ее через OpenTelemetry и разберем, какие операции создавать самому, что к ним добавлять и как проверить, что все работает.

За основу мы взяли демо-проект OrdTracingDemo: он содержит два ASP.NET Core приложения на .NET 10, OpenTelemetry Collector и Jaeger. Запросы можно отправлять через Swagger, а задержку и ошибку внешнего сервиса включать параметрами. 

Работать будем с передачей креативов, актов и статистики. Шлюз здесь учебный: к настоящему ЕРИР он не ходит, а маршруты в демо не совпадают с теми, что в WebAPI Медиаскаута. Дальше покажем настройку и ключевые решения на коротких примерах кода. Полную реализацию можно посмотреть и запустить из репозитория.

Почему невозможно обойтись только логами

Допустим, пользователь жалуется, что акт передается медленно. В журнале есть начало и конец операции:

12:30:01.100 Начата передача акта ACT-12345
12:30:03.020 Акт ACT-12345 передан шлюзу

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

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

Трассировка показывает порядок операций. Для передачи акта это проверка, сохранение, обращение к шлюзу и обновление состояния. У каждой операции есть начало и длительность, из которых видно, где приложение работало, а где просто ждало ответа.

Сообщение «не удалось передать акт» говорит только об общем результате. А трассировка при ошибках помогает: показывает, сохранился ли документ, ушёл ли HTTP-запрос и что ответил внешний сервис. 

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

Зачем здесь OpenTelemetry

В OpenTelemetry  есть инструменты для сбора трассировок, метрик и журналов. В демо-проекте включены только трассировки.

В .NET пользовательские операции описываются стандартными классами Activity и ActivitySource. OpenTelemetry подключается к источникам этих операций и экспортирует данные по протоколу OTLP. Jaeger принимает трассировки и предоставляет интерфейс для их просмотра.

Код приложения описывает, что происходит, а настройки экспорта определяют, куда уходит телеметрия. Сменить систему хранения можно без повторной разметки бизнес-операций. 

Как устроена трассировка в .NET

TraceId и SpanId

Вся трассировка объединена одним общим TraceId. Каждый span получает собственный SpanId, а ParentSpanId показывает, кто у него родитель. Скажем, входящий HTTP-запрос и вложенное сохранение документа имеют одинаковый TraceId, но разные SpanId. А у сохранения вдобавок проставлен родительский span.

За идентификаторами закреплены такие роли:

• TraceId открывает весь путь конкретного запроса;

• SpanId выделяет одну операцию;

• ParentSpanId связывает ее с родительской.

TraceId не заменяет идентификатор акта, ведь один акт может обрабатываться несколько раз и попадать в разные трассировки.

Activity и ActivitySource

В .NET span представлен объектом Activity, а ActivitySource создает объекты для пользовательских операций.

В демо-проекте общий источник основного API объявлен в OrdTelemetry.cs. Сервис обработки и репозиторий используют его для описания этапов, а OpenTelemetry подписывается на него при запуске приложения.

ActivitySource лишь создает операции. Записывать и экспортировать их будет настроенный сборщик, так что вызовы StartActivity без него не дадут трассировок в Jaeger. 

Как связываются два сервиса

Внутри приложения текущая операция доступна через Activity.Current. При обычной работе с async/await контекст сохраняется между продолжениями асинхронного метода.

Между сервисами по HTTP контекст передается по стандарту W3C Trace Context. В заголовке traceparent идут идентификатор трассировки, идентификатор вызывающего span’а и флаги трассировки. Принимающий сервис создает по ним связанный серверный span. В стандартном сценарии с ASP.NET Core и HttpClient заголовок вручную формировать не нужно.

Передача контекста и экспорт телеметрии — это разные процессы. Заголовок связывает запросы во время выполнения, а экспорт доставляет сведения об операциях в систему мониторинга. Сервис может корректно получить контекст и всё равно не появиться в Jaeger: достаточно ошибки в настройке экспорта. 

Состав traceparent:

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01

Настраиваем OpenTelemetry в ASP.NET Core

В демо-проекте два приложения. OrdDemo.Api принимает запросы на передачу креативов, актов и статистики. Erir.Mock.Api имитирует внешний шлюз: подтверждает прием данных, задерживает обработку или возвращает ошибку.

HTTP-запросы и телеметрия идут разными путями:

Обработка запроса:
Клиент → OrdDemo.Api → Erir.Mock.Api
 
Передача трассировок:
OrdDemo.Api   → Collector → Jaeger
Erir.Mock.Api → Collector → Jaeger

Collector в передаче актов не участвует. Каждое приложение само экспортирует свои span’ы, а общие идентификаторы позволяют собрать их в одну трассировку.

Подключаем сбор операций

Настройка лежит в Program.cs каждого приложения. В основном API она выглядит так:

builder.Services.AddOpenTelemetry()
    .ConfigureResource(resource => resource
        .AddService("mediascout-demo-api"))
    .WithTracing(tracing => tracing
        .AddAspNetCoreInstrumentation()
        .AddHttpClientInstrumentation()
        .AddSource(OrdTelemetry.SourceName)
        .AddOtlpExporter(options =>
        {
            options.Protocol = OtlpExportProtocol.HttpProtobuf;
            options.Endpoint = new Uri(endpoint);
        }));

Здесь:

• AddService задает имя приложения;

• AddAspNetCoreInstrumentation подключает сбор входящих HTTP-операций;

• AddHttpClientInstrumentation подключает сбор исходящих HTTP-вызовов;

• AddSource подписывает OpenTelemetry на пользовательские операции;

• AddOtlpExporter настраивает отправку трассировок.

У шлюза имя сервиса erir-gateway-mock. Исходящих HTTP-вызовов в нем нет, поэтому инструментация HttpClient ему не нужна.

Имя сервиса показывает, какое приложение выполнило операцию. Имя источника определяет, чьи пользовательские Activity собирать. В основном API источник называется Mediascout.Demo.Business, и его имя передается в AddSource. Если пропустить регистрацию или ошибиться в строке, автоматические HTTP-span’ы будут появляться, а пользовательские нет.

Настраиваем экспорт и адреса (docker compose)

В демо-проекте приложения передают трассировки в Collector по OTLP/HTTP. Полный адрес приемника задается через OTEL_EXPORTER_OTLP_TRACES_ENDPOINT и включает путь /v1/traces.

В Docker Compose используется:

http://otel-collector:4318/v1/traces

При локальном запуске приложения адрес по умолчанию другой:

http://localhost:4318/v1/traces

Здесь легко ошибиться: localhost внутри контейнера указывает на сам контейнер. К соседнему сервису в сети Compose обращаются по его имени.

По той же причине основной API ходит к шлюзу по адресу http://erir-mock-api:8080. Порт 5202 нужен, чтобы открыть шлюз с компьютера, а внутри контейнера приложение слушает 8080.

В otel-collector.yaml настроены приемник, экспортер и конвейер traces, который их связывает. Collector принимает OTLP/HTTP на порту 4318, а в Jaeger отправляет данные по OTLP/gRPC на jaeger:4317. Протокол и порт должны совпадать с настройкой принимающей стороны. Если поменять только номер порта, не меняя протокол, соединение не заработает.

Конфигурация Collector попадает в образ через Collector/Dockerfile, поэтому после ее изменения образ нужно пересобрать.

Проверяем весь путь

Из папки с docker-compose.yml запускаем:

docker compose up -d --build

После запуска доступны:

• основной Swagger — http://localhost:5201/swagger;

• Swagger учебного шлюза — http://localhost:5202/swagger;

• Jaeger — http://localhost:16686.

В основном Swagger отправим POST /api/invoices:

{
  "invoiceId": "ACT-12345",
  "contractId": "CONTRACT-1001",
  "amount": 125000,
  "slow": false,
  "fail": false
}

При успешной обработке API вернет 202 и traceId. По этому идентификатору открываем трассировку в Jaeger и проверяем, что в ней есть оба сервиса.

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

Если данных нет, проверяйте путь по порядку: приложение → Collector → Jaeger. Проверьте адрес экспортёра, настройки конвейера и ошибки в контейнерах. Если видны только HTTP-span’ы, проверьте AddSource.

Само наличие traceId в HTTP-ответе еще не подтверждает, что трассировка доставлена в Jaeger.

Добавляем span’ы в регистрацию актов, креативов и статистики

Автоматическая инструментация фиксирует HTTP-взаимодействие, но не говорит, на что уходит время внутри обработчика. Для этого в демо-проекте добавили пользовательские span’ы. 

Верхний span описывает бизнес-операцию: creative.register, invoice.register или statistics.submit. Внутри лежат отдельные этапы обработки.

Выбираем полезные границы

Span полезен, когда отвечает на конкретный вопрос: что выполнялось, сколько времени заняло и чем закончилось. Для передачи акта в демо-проекте мы выделили вот такие: 

• invoice.validate — имитация проверки данных;

• ord.document.persist — сохранение записи о документе;

• автоматически созданный HTTP-span — обращение к шлюзу;

• ord.operation.mark_submitted — обновление состояния после успешной отправки.

Span для каждого метода обычно не нужен. Копирование свойств или сборка небольшого DTO мало что дают расследованию, зато усложняют чтение трассировки. А название span’а должно отражать реальную работу. 

Явно определяем начало и конец span’а

Пользовательский span создается вызовом StartActivity. Чтобы увидеть границы, запишем сокращенный фрагмент OrdRegistrationService.SubmitAsync с явным блоком using. Команда, идентификатор операции и объект submission здесь уже подготовлены; обработка ошибок опущена:

using (var activity = OrdTelemetry.Source.StartActivity(
    "invoice.register",
    ActivityKind.Internal))
{
    // Span invoice.register уже начался.
 
    await ValidateAsync(command, cancellationToken);
 
    await repository.PersistAsync(
        operationId, command, cancellationToken);
 
    // HttpClient автоматически создаст дочерний HTTP-span.
    using var response = await client.PostAsJsonAsync(
        "/internal/submissions", submission, cancellationToken);
 
    response.EnsureSuccessStatusCode();
 
    await repository.MarkSubmittedAsync(
        operationId, cancellationToken);
 
} // Здесь завершается span invoice.register.

Span начинается с вызова StartActivity и заканчивается на выходе из блока using. Все, что выполняется внутри фигурных скобок, входит в его длительность, включая ожидание через await. Строка invoice.register — название операции в Jaeger, а ActivityKind.Internal отмечает внутреннюю операцию приложения.

В исходном OrdRegistrationService.cs используется короткая форма:

using var activity = OrdTelemetry.Source.StartActivity(
    operationName,
    ActivityKind.Internal);

Здесь Activity завершается при выходе из содержащего ее блока, то есть из метода SubmitAsync. Переменная operationName хранит название, выбранное по типу акта.

В асинхронном коде легко наступить на грабли: создать Activity, вернуть незавершённый Task и выйти из using. Span закроется раньше, чем работа, которую он измеряет. Поэтому нужные операции ожидаем внутри using. 

Сохраняем понятную вложенность

Когда SubmitAsync вызывает репозиторий, бизнес-span остается активным. В начале OrdRepository.PersistAsync создается span сохранения:

using var activity = OrdTelemetry.Source.StartActivity(
    "ord.document.persist");

// Имитируем обращение к хранилищу.
await Task.Delay(80, cancellationToken);

Он начинается при вызове StartActivity и завершается на выходе из PersistAsync, после записи данных в словарь. Родительский invoice.register в это время остается активным.

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

Родительский span описывает работу, в которую входят дочерние операции. А вот с независимой фоновой обработкой всё сложнее: она может продолжаться уже после того, как исходный HTTP-запрос завершился. Поэтому и границы span’а, и передачу контекста для неё нужно продумывать отдельно. 

Дополняем автоматическую инструментацию

В первом примере invoice.register измеряет всю бизнес-операцию, а автоматически созданный span HttpClient — один сетевой вызов внутри нее. Дополнительный StartActivity непосредственно вокруг того же HTTP-запроса обычно не нужен.

Отдельный span нужен там, где работы больше, чем один запрос: подготовка отправки, несколько попыток обращения, проверка результата. 

В успешном сценарии структура выглядит так:

POST /api/invoices

└── invoice.register

    ├── invoice.validate

    ├── ord.document.persist

    ├── POST

    │   └── POST /internal/submissions

    │       └── erir.mock.process

    └── ord.operation.mark_submitted

POST — клиентский span основного API; адрес запроса находится в атрибуте url.full. POST /internal/submissions — серверный span шлюза. Первый показывает длительность вызова со стороны основного API, второй — обработку на принимающей стороне.

Отправьте запрос с slow: true и fail: false. Шлюз увеличит искусственную задержку с 90 до 1800 мс. В трассировке вырастет длительность erir.mock.process, клиентского HTTP-span’а и родительской бизнес-операции.

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

Добавляем диагностические атрибуты и сведения об ошибках

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

Добавляем данные для поиска

Атрибут — пара «имя — значение», прикрепленная к конкретному span’у. В .NET он добавляется методом SetTag:

activity?.SetTag("app.ord.invoice.id", command.EntityId);

Эта строка не создает новый span и не меняет границы текущего, а только записывает идентификатор акта в существующую Activity.

Оператор ?. нужен потому, что StartActivity может вернуть null, например если источник не прослушивается. Обработке документа это мешать не должно.

В демо атрибуты добавляет метод EnrichWithOrdData из OrdActivityExtensions.cs. Он вызывается сразу после создания бизнес-span’а:

activity.EnrichWithOrdData(command);

Внутри метода предусмотрена проверка на null. Для регистрации акта он записывает такие данные:

Span: invoice.register
app.ord.entity.type = invoice
app.ord.invoice.id  = ACT-12345
app.ord.contract.id = CONTRACT-1001

Идентификаторы попадают в span ещё до проверки, сохранения и отправки. Так что сведения о документе никуда не денутся, даже если на одном из следующих этапов что-то упадёт. 

Название span’а при этом постоянное: invoice.register. Если добавить в него идентификатор акта, одинаковые операции станут выглядеть как разные, и группировать их будет труднее.

Выбираем место для атрибутов

В демо-проекте идентификаторы документов записываются на верхний бизнес-span. Он описывает всю обработку и служит удобной точкой для поиска.

Атрибуты родителя не копируются в дочерние span’ы автоматически. Если раскрыть ord.document.persist, идентификатора акта там не будет. Связь с документом можно установить через родительский invoice.register в той же трассировке.

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

Имена атрибутов должны совпадать. Если один участок записывает app.ord.invoice.id, а другой — actId, поиск одинаковых документов потребует разных условий. Общий метод EnrichWithOrdData помогает избежать таких расхождений.

Различаем результат и событие

После успешного ответа шлюза и обновления состояния документа OrdRegistrationService выполняет:

activity?.SetTag(
    "app.ord.submission.status",
    "accepted_by_gateway");
activity?.AddEvent(
    new ActivityEvent("submission.accepted"));

Атрибут показывает, чем закончилась передача: данные принял учебный шлюз. Событие отмечает, когда приложение зафиксировало результат, и несёт временную отметку. В демо оно появляется после того, как документ обновился в репозитории. Выходит, это момент фиксации в основном API, а не время приёма данных шлюзом. 

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

Сохраняем причину ошибки

Статус Error показывает, что операция не удалась, но для расследования нужны подробности. В OrdRegistrationService.SubmitAsync обработчик исключения выглядит так:

catch (Exception exception)
{
    activity?.SetTag(
        "error.type",
        exception.GetType().FullName);
    activity?.SetStatus(
        ActivityStatusCode.Error,
        "submission_failed");
    activity?.AddException(exception);
    throw;
}

У этих вызовов разные задачи:

• error.type группирует сбои по типу исключения;

• SetStatus отмечает неуспешный результат span’а;

• AddException сохраняет событие исключения с сообщением и стеком вызовов.

В примере используется Activity.AddException, доступный в .NET 10. Запись исключения не заменяет установку статуса: это отдельные действия, как описано в документации OpenTelemetry по обработке исключений.

Все вызовы выполняются, пока Activity ещё активна. Затем throw; передаёт исключение дальше с исходным стеком вызовов, а при выходе из метода Activity завершается.

Отдельно обработчик перехватывает отмену входящего запроса: её он пробрасывает дальше, не записывая ошибку. Так ведёт себя бизнес-span, а автоматические HTTP-span’ы обрабатывает их собственная инструментация.

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

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

Проверяем ошибочный сценарий

Повторим запрос на POST /api/invoices из раздела 3, изменив fail на true. Шлюз вернет 503, вызов EnsureSuccessStatusCode() выбросит HttpRequestException, а основной API ответит 502.

Скопируйте traceId из ответа и откройте трассировку в Jaeger.

Сохранение записи уже завершилось, но до обновления состояния выполнение не дошло. В учебном репозитории запись остается в состоянии created.

Раскройте invoice.register. У него должны быть идентификаторы документа, статус ошибки, атрибут error.type и событие исключения.

При fail: false и доступном шлюзе операция завершится успешно: появятся этап обновления состояния, атрибут accepted_by_gateway и событие submission.accepted. При этом код не устанавливает бизнес-span’у статус Ok явно: для успешного выполнения он остается Unset.

Причину сбоя нельзя определять только по ответу 502. В демо он возможен и при сетевой ошибке HttpClient, поэтому сопоставляйте сообщение исключения и клиентский HTTP-span.

Если входные данные некорректны, основной API может вернуть 400 до вызова бизнес-сервиса, например при неположительной сумме акта. Тогда invoice.register в трассировке не будет, и это ожидаемо: операция не начиналась.

Ограничиваем содержимое телеметрии

Для расследования обычно хватает типа документа, его идентификатора, связанных идентификаторов и результата операции. Полный JSON запроса в атрибутах раздувает объём данных и может содержать сведения, которым не место в системе мониторинга.

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

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

Что учитывать при переносе

Демо-проект показывает инструментацию обработки документа в двух сервисах. При переносе подхода в рабочее приложение есть два ограничения.

• Прием данных шлюзом не означает завершения регистрации. Ответ 202 в демо возвращается после HTTP-вызова шлюза и обновления записи в репозитории, а фоновой очереди за ним нет. В реальной интеграции окончательный результат может прийти позже. Тогда передачу контекста и создание span’ов для продолжения обработки придется организовывать отдельно.

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

Вместо вывода

Смысл демо в том, чтобы по конкретному запросу можно было ответить на три вопроса: где возникла задержка, какой вызов упал и что приложение успело сделать. Трассировка не убирает ошибки, но делает их объяснимыми — а это первый шаг к тому, чтобы их починить.

При добавлении инструментации полезно спросить себя: какое решение при расследовании поможет принять этот span или атрибут? Если ответ понятен, данные стоит собирать. Если нет, лишняя детализация, скорее всего, только усложнит чтение трассировки.

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