Логирование в Azure с Application Insights и Serilog / forpes.ru

06.09.2023 07:00

dimka44 0 461 Источник

Введение

В этой статье я рассмотрю, как в .NET приложении можно эффективно использовать Application Insights и Serilog, а также как можно воспользоваться специфичным функционалом Azure для логирования. Вместе эти два прекрасных инструмента дают очень богатые и гибкие возможности по логированию для любого приложения. В статье будут показаны разнообразные варианты настройки этих инструментов и приведены примеры кода для разных сценариев логирования.

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

Serilog реализует «структурное логирование», которое сохраняет сообщения и данные в формате, удобном для поиска и анализа, используя так называемые «sinks» для записи логов в различные хранилища. С помощью Serilog можно одновременно сохранять логи в Application Insights, локальные файлы и любые другие хранилища. Эти sinks можно очень тонко настраивать, а также включать и выключать в ходе работы приложения.

Конфигурирование Application Insights

Я не буду погружаться в детали базовой настройки Application Insights, поскольку есть много хороших и подробных руководств, включая материалы на сайте Microsoft. Сфокусируюсь только на самых значимых моментах.

Прежде всего, нужно найти раздел, посвященный Application Insights, на портале Azure. Его первая страница должна выглядеть примерно так:

Важная для нас информация - это Connection String, мы будем ее использовать для конфигурирования доступа к Application Insights в коде приложения. Если нажать на ссылку 'JSON view' справа на странице, она покажет всю информацию, связанную с данным экземпляром Application Insights.

Скопируйте Connection String - ее нужно будет использовать для настройки приложения. Один из вариантов - это поместить ее в переменную окружения APPLICATIONINSIGHTS_CONNECTION_STRING, или же в любой из источников конфигурации .NET приложения (конфигурационные файлы appSettings.json, и т.п.) В этом случае она должна быть сохранена с ключом "ApplicationInsights:ConnectionString".

Обратите внимание, что Instrumentation Key использовать не нужно. Он уже включен в Connection String, и, кроме того, в документации Microsoft указано, что в будущем для настройки приложения он будет неприменим. Так же нужно учитывать, что Application Insights Connection String является секретом, и эта информация не должна попасть в общий доступ или быть сохранена в систему контроля версий.

Доступ к логам Application Insights

Опять же, работа с логами и метриками, сохраненными в Application Insights выходит за рамки этой статьи. В целом, доступ к Application Insights можно получить через портал Azure, открыв любой из ваших ресурсов App Service, Azure Function, или же сам Application Insights.

На первой странице Application Insights указана общая статистика - ошибки, запросы, и т.д. В разделе 'Monitoring - Logs' можно с помощью мощного языка запросов делать выборки по всем данным, сохраненным в Application Insights.

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

Вся информация, отправляемая приложениями в Application Insights, становится доступна с определенной задержкой, которая зависит от используемого Telemetry Channel. Кроме того, Azure позволяет получить доступ к логам приложения буквально в режиме реального времени, о чем мы тоже поговорим, хотя эта возможность доступна только приложениям, работающим в Azure.

Использование Azure Log Stream

Azure Log Stream позволяет видеть логи приложения практически в режиме реального времени, как только они записаны на Azure filesystem или в Azure blob. Однако этот функционал предназначен больше для отладки и диагностики, а не для постоянного использования, и будет выключен автоматически через 12 часов после включения.

При правильной конфигурации в приложении, его логи можно видеть в режиме реального времени на странице Log Stream внутри ресурса Application Insights. Например:

Это может быть очень полезным для отладки и диагностики.

Подготовка проекта

Добавление nuget пакетов, любимая часть любого туториала :)

Начнем писать код. Особо нетерпеливые могут сразу заглянуть в репозиторий проекта-примера:

Пакеты для использования Application Insights:

Microsoft.ApplicationInsights.AspNetCore - SDK и Auto Collectors для приложений ASP.NET Core
Microsoft.ApplicationInsights.WorkerService - SDK и Auto Collectors для консольных и Worker Service приложений
Microsoft.ApplicationInsights - базовый SDK; Auto Collectors должны быть установлены или реализованы отдельно
Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel - реализует более надежные механизмы доставки телеметрии
Microsoft.Extensions.Logging.ApplicationInsights - логирование в Application Insights

Страница Application Insights на GitHub содержит подробную информацию о том, в каких случаях нужно использовать каждый пакет. Хорошей практикой будет использование последней версии каждого пакета.

О telemetry channels

Базовый SDK Application Insight использует реализацию telemetry channel, которая сохраняет все сообщения и метрики в памяти приложения. Эта реализация больше подходит для приложений с коротким циклом выполнения, и она не гарантирует полную доставку телеметрии в Application Insights в случае сетевых сбоев или преждевременного завершения приложения. По умолчанию доставка происходит либо каждые 30 секунд, либо при накоплении 500 сообщений в буфере в памяти.

Пакет Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel реализует дополнительные механизмы обеспечения доставки: повтор отправки при сетевых сбоях и сохранение сообщений на диске. Эта реализация больше подходит для приложений с долгим циклом выполнения - таких как всевозможные сервисы и веб-приложения. Также она дает большую (с конфигурацией по умолчанию) задержку при отправке данных в Application Insights.

Все реализации класса TelemetryChannel имеют метод Flush, который должен постараться отправить все накопленные данные. Базовая реализация этого метода синхронная (блокирующая): метод завершится только после отправки всех данных.

Серверный telemetry channel реализует этот метод асинхронно: выполнение будет немедленно передано дальше, и нет гарантированного способа удостовериться, что отправка всех данных завершена. Microsoft советует реализовать "достаточную задержку" после вызова этого метода перед тем, как позволить приложению завершиться. Однако какая-то часть телеметрии все равно может быть потеряна в данном случае из-за общей непредсказуемости этапа завершения работы приложения.

Пакеты, необходимые для Serilog:

Serilog - базовый пакет
Serilog.AspNetCore - поддержка ASP.NET Core
Serilog.Exceptions - улучшенное логирование исключений
Serilog.Extensions.Logging - провайдер Serilog для Microsoft.Extensions.Logging
Serilog.Extensions.Logging.ApplicationInsights - упрощает настройку Application Insights для Serilog
Serilog.Sinks.ApplicationInsights - реализует Serilog "sink" для отправки логов в Application Insights
Serilog.Expressions - расширенные возможности настройки с использованием конфигурационных файлов (своеобразный "мини-язык" для настройки фильтрации и форматирования, идеален для конфигурирования Serilog с помощью json- и xml-файлов)
Serilog.Settings.Configuration - шаблон файла appSettings.json для конфигурирования Serilog
Serilog.Extensions.Hosting - позволяет "забутстрапить" Serilog: дает возможность подключить Serilog на этапе старта приложения, до того, как все сервисы будут сконфигурированы

"Обогащение" (enrichment) логов дополнительными данными:

Serilog.Enrichers.CorrelationId - поддержка correlation id
Serilog.Enrichers.Sensitive - автоматическая маскировка данных

Дополнительные "sinks" для записи логов:

Serilog.Sinks.Async
Serilog.Sinks.Console
Serilog.Sinks.File

Для Serilog реализовано много других пакетов, которые могут быть полезны для реализации разнообразного функционала и требований.

Дополнительные пакеты

Microsoft.Azure.AppConfiguration.AspNetCore - использование Azure App Configuration (для приложений, размещенных в Azure)
Microsoft.Extensions.Logging.AzureAppServices - лог-провайдер для Azure (для приложений, размещенных в Azure)
Microsoft.AspNetCore.HeaderPropagation - настройка "header propagation" для веб-запросов

Настройка Application Insights и Serilog в .NET проекте

После подключения всех нужных пакетов нужно правильно настроить Application Insights, Serilog, и другие компоненты Azure.

Говоря в общем, нужно настроить сервисы Application Insights, сконфигурировать «синки» Serilog для записи логов, и выполнить дополнительную настройку тех функций, которыми мы хотим расширить возможности логирования в нашем приложении.

Прежде всего, подготовка сервисов приложения. Connection String для Application Insights должна находиться в правильном месте — или в переменной окружения, или в файлах конфигурации с ключом «ApplicationInsights:ConnectionString». Если наше приложение будет размещено в Azure, нужно также подключить конфигурационные сервисы Azure.

Эта часть кода выглядит очень просто:

builder.Services.AddApplicationInsightsTelemetry();
builder.Services.AddAzureAppConfiguration();

Здесь мы подключаем сервисы сбора телеметрии Application Insights, а также создаем экземпляр класса TelemetryConfiguration, который инициализируется с нашей Application Insights Connection String. Этот экземпляр регистрируется в DI контейнере как IOptions<TelemetryConfiguration>, и к нему можно получить доступ через IServiceProvider.

Теперь пора настраивать логирование. Самое удобное место - это методы расширения IHostBuilder: IHostBuilder.ConfigureLogging и IHostBuilder.UseSerilog, которые можно вызвать сразу вслед за предыдущим кодом.

Метод ConfigureLogging использует ILoggingBuilder для настройки логирования. Например:

builder.Host.ConfigureLogging(logging => {
    logging.ClearProviders();
    logging.AddAzureWebAppDiagnostics();
});

Давайте рассмотрим этот код. Вызов метода ClearProviders не является обязательным, однако он сбрасывает все стандартные провайдеры логирования - такие как консольный и отладочный. Они могут быть полезны при локальной отладке, но в production режиме они явно будут лишними. В целом, все, что мы хотим использовать для логирования, стоит указывать и настраивать явно.

Вызов метода AddAzureWebAppDiagnostics регистрирует необходимую инфраструктуру для использования Azure Log Stream.

Теперь начнем настраивать Serilog. Лучше всего использовать метод расширения UseSerilog:

builder.Host.UseSerilog(setupLoggerAction, writeToProviders: false);

Перед тем, как углубиться в метод setupLoggerAction, важный комментарий о параметре writeToProviders. Его значение по умолчанию — false, и его лучше оставить таким. Serilog использует «синки» для физической записи всех отправленных ему сообщений, и каждый из этих «синков» стоит настраивать явно и отдельно либо в коде, либо в конфигурационных файлах (или других источниках, вроде переменных окружения). Если параметр writeToProviders будет установлен в true, это приведет к тому, что все данные будут записаны не только в «синки», но и во все лог‑провайдеры, известные текущему DI контейнеру, даже если для них нет соответствующего «синка» Serilog. И хотя это может быть желательным поведением в определенных сценариях, это также часто приводит к дублированию сообщений в логах, если соответствующий «синк» был настроен. При этом причина возникновения этих дубликатов часто оказывается неочевидной для разработчиков. Поэтому использовать этот режим может иметь смысл только в том случае, если нет явной настройки ни одного из «синков» Serilog, и мы действительно хотим, чтобы все логирование выполнялось через Serilog «неявно». Вместе с тем явная настройка «синков» дает многочисленные преимущества, такие как раздельная детализация и форматирование логов при записи в разные физические хранилища.

Теперь перейдем к детальному рассмотрению кода настройки Serilog:

private static void SetupLoggerConfiguration(HostBuilderContext context, IServiceProvider provider, LoggerConfiguration loggerConfiguration) {
    var options = provider.GetRequiredService<IOptions<LogConfigOptions>>().Value;
    // LogConfigOptions is a home-brew configuration class for high-level logging setup

    loggerConfiguration
        .Enrich.FromLogContext()
        .Enrich.WithCorrelationIdHeader("x-correlation-id")
        .Enrich.WithExceptionDetails();

    if (options.HttpRequestLogging) {
        // this line is required 'as is' in order to enable HTTP request logging;
        // see more here: https://github.com/serilog/serilog-aspnetcore#request-logging
        loggerConfiguration.MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning);
    }
    
    var readerOptions = new ConfigurationReaderOptions {
        SectionName = options.ConfigurationSectionName
    };
    loggerConfiguration
        .ReadFrom.Configuration(context.Configuration, readerOptions)
        .ReadFrom.Services(provider);
    
    // Configure Application Insights sink
    var telemetryConfiguration = provider.GetService<IOptions<TelemetryConfiguration>>();
    if (!string.IsNullOrEmpty(telemetryConfiguration?.Value.ConnectionString)) {
        // We have a valid Application Insights setup
        loggerConfiguration
            .WriteTo
            .ApplicationInsights(telemetryConfiguration.Value, TelemetryConverter.Traces);
    }
    
    // Configure Azure log stream sink
    if (options.LogToAzureFileSystem && !context.HostingEnvironment.IsDevelopment()) {
        loggerConfiguration
            .WriteTo
            .Async(x => x.File(
                $@"D:\home\LogFiles\Application\{context.HostingEnvironment.ApplicationName}.txt",
                shared: true,
                flushToDiskInterval: TimeSpan.FromSeconds(1)
            ));
    }
}

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

Serilog enrichers - "обогащение" логов

Serilog реализует своеобразную и интересную концепцию «обогащения» логов данными из любых источников, которые могут быть необходимы. Эти данные не надо указывать в явном виде при записи логов, что очень удобно в тех случаях, когда они недоступны или не нужны в том месте, где мы создаем сами логи. В нашем коде есть три вызова loggerConfiguration.Enrich. Например, метод WithCorrelationIdHeader добавит correlation id текущего принятого веб-запроса (для веб-приложения) ко всем сообщениям, которые будут отправлены в Serilog. Correlation id позволяет связать многочисленные записи в логах в единую операцию как в случае с монолитом, так и при распределенных микро-сервисах.

Метод WithExceptionDetails позволит автоматически «обогатить» логирование любого исключения без написания дополнительного кода. Еще один полезный «обогатитель» реализован в классе Serilog.Enrichers.Sensitive — его метод WithSensitiveDataMasking подключает автоматическое маскирование потенциально секретной информации в логах.

Вики Serilog дает хорошее описание механизма «обогащения» логов, и ниже я приведу пример собственной реализации такого "обогащения" логов.

Настройка Serilog в коде и с помощью конфигурационных файлов

var readerOptions = new ConfigurationReaderOptions {
    SectionName = options.ConfigurationSectionName
};
loggerConfiguration.ReadFrom.Configuration(context.Configuration, readerOptions);

Этот код читает настройки Serilog из всех известных приложению источников конфигурации, используя указанное имя секции. И хотя Serilog можно полностью настроить через файлы конфигурации (пример дан в проекте), настройка через код более желательна во многих случаях.

loggerConfiguration.ReadFrom.Services(provider);

Этот метод использует текущее наполнение DI контейнера, и последовательно применяет все регистрации следующих зависимостей: ILoggerSettings, IDestructuringPolicy, ILogEventEnricher, ILogEventFilter, и ILogEventSink.

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

Моя личная рекомендация такова: настройка Serilog для локального окружения для разработки вполне может быть сделана через конфигурационный файл (в частности, appSettings.Development.json) — например, для записи детальных логов в локальные файлы, тогда как настройка для production должна делаться в коде с минимальным общим управлением через конфигурацию приложения. Produciton код как бы «отлит в бронзе» — максимально стабилен и статичен в плане изменений.

Настройка "синка" для Application Insights

Рассмотрим этот код:

var telemetryConfiguration = provider.GetService<IOptions<TelemetryConfiguration>>();
if (!string.IsNullOrEmpty(telemetryConfiguration?.Value.ConnectionString)) {
    // We have a valid Application Insights setup
    loggerConfiguration
        .WriteTo
        .ApplicationInsights(telemetryConfiguration.Value, TelemetryConverter.Traces);
}

Вызов метода builder.Services.AddApplicationInsightsTelemetry() создал и зарегистрировал в DI контейнере экземпляр класса TelemetryConfiguration, чем мы здесь и пользуемся. Сначала для проверки, что у нас есть рабочая конфигурация Application Insights, а затем для инициализации самого «синка».

Второй параметр при инициализации «синка» — это конвертер телеметрии. Serilog предоставляет два таких конветера: TelemetryConverter.Traces и TelemetryConverter.Events. Конвертер определяет, в каком виде Application Insights будет хранить переданные данные. И хотя разные конвертеры формируют сообщение по‑разному, все данные сохраняются в Application Insights. При логировании исключений выбор конвертера не имеет значения, потому что в этом случае всегда используется специальный конвертер, предназначенный именно для исключений.

TelemetryConverter.Traces по умолчанию передает сообщения так:

сообщение сохраняется в Application Insights как 'trace'
отформатированный текст сообщения помещается в поле 'message',
уровень сообщения помещается в поле 'severityLevel',
время сообщения помещается в поле 'timestamp',
шаблон сообщения помещается в объект 'customDimensions',
параметры сообщения помещается в объект 'customDimensions'.

TelemetryConverter.Events по умолчанию передает сообщения так:

сообщение сохраняется в Application Insights как 'event'
шаблон сообщение сохраняется как event name,
уровень сообщения помещается в поле 'severityLevel',
время сообщения помещается в поле 'timestamp',
отформатированный текст сообщения помещается в объект 'customDimensions',
параметры сообщения помещается в объект 'customDimensions'.

Исключения передаются как:

стандартный объект типа 'exception' в Application Insights,
уровень сообщения помещается в поле 'severityLevel',
время сообщения помещается в поле 'timestamp',
параметры сообщения помещается в объект 'customDimensions'.

Говоря в общем, TelemetryConverter.Traces формирует более легкое для чтения и анализа представление сообщений, но, как обычно, все зависит от конкретных требований и предпочтений.

При настройке «синка» есть третий необязательный параметр: 'LogEventLevel restrictedToMinimumLevel', по умолчанию равный LogEventLevel.Verbose. Он позволяет фильтровать те сообщения, которые будут физически записываться в данный «синк». Обратите внимание, что этот параметр отличается от того, какой уровень логирования включен глобально. Например, Serilog может быть настроен на уровень Debug глобально, но «синк» инициализирован с уровнем Warning. В результате, в Application Insights будут отправляться сообщения только с уровнем Warning или выше.

Есть также и четвертый необязательный параметр: 'LoggingLevelSwitch levelSwitch', по умолчанию равный null. С его помощью можно динамически контролировать уровень записываемых в «синк» сообщений.

Настройка "синка" для Azure Log Stream

Теперь обратим внимание сюда:

(options.LogToAzureFileSystem && !context.HostingEnvironment.IsDevelopment()) {
    loggerConfiguration
        .WriteTo
        .Async(x => x.File(
            $@"D:\home\LogFiles\Application\{context.HostingEnvironment.ApplicationName}.txt",
            shared: true,
            flushToDiskInterval: TimeSpan.FromSeconds(1)
        ));
}

Поскольку Azure Log Stream в большей степени является инструментом диагностики и отладки, его обычно не нужно держать включенным. Кроме того, в локальном окружении он может не работать, поскольку использует фиксированное расположение файлов: папку 'D:\home\LogFiles\Application'. Если Azure Log Stream включен, он будет пересылать в консоль Azure те файлы, которые будут записываться в эту папку.

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

Обратите внимание, что многие другие «синки» Serilog либо уже реализуют асинхронную запись сообщений, как «синк» Application Insights, либо не нуждаются в ней, подобно консольному «синку».

В настройке этого «синка» два параметра имеют особое значение применительно к сценарию Azure Log Stream: 'shared' и 'flushToDiskInterval'. Параметр 'shared' всегда должен быть установлен в true, а параметр 'flushToDiskInterval' нужно устанавливать в относительно небольшое значение, чтобы логи становились доступны максимально быстро в консоли Azure Log Stream.

У файлового «синка» есть много других параметров, которые можно не изменять. Но все же давайте посмотрим, как их можно лучше приспособить для Azure Log Stream:

fileSizeLimitBytes — определяет максимальный размер лог‑файла, по умолчанию равен null, что означает отсутствие ограничения по размеру. Файловое хранилище, доступное Azure Log Stream, имеет относительно небольшую квоту на размер, поэтому стоит установить этот параметр в небольшое значение, не более 1–4 МБ.
rollOnFileSizeLimit — логический параметр, позволяющий включить «перекат» лог‑файлов: создать копию лог‑файла с другим именем при достижении лимита на размер перед тем, как будет создан новый файл для записи логов. По умолчанию равен 'false'. Для нашего сценария этот параметр можно не изменять, однако для лучшего понимания его особенностей приведу еще два параметра, которыми можно дополнительно повлиять на «перекат» лог файлов.
retainedFileCountLimit — количество сохраняемых лог‑файлов при включенном «перекате». Значение по умолчанию — 31, что слишком много с учетом квоты на размер. Лучше всего сделать это значение маленьким, не более 3.
retainedFileTimeLimit — значение TimeSpan, определяющее как долго может храниться лог‑файл. Файл будет удален либо по достижении максимального числа сохраняемый файлов, либо по истечении указанного времени. Значение по умолчанию — сохранять вечно. Для сценария Azure Log Stream это значение должно быть небольшим, лучше не превышающим 24 часа.

Файловый «синк» также может быть дополнительно настроен с помощью параметров 'restrictedToMinimumLevel' и 'levelSwitch', аналогично «синку» Application Insights.

Использование Serilog в коде

Serilog определяет необобщенный интерфейс, ILogger, который регистрируется в DI контейнере при регистрации Serilog. В приложении, использующем Serilog, лучше использовать именно этот интерфейс для всех операций логирования (вместо стандартного обобщенного ILogger). Кроме того, есть глобальный статический объект Serilog.Log, который реализует точно такие же методы, как и ILogger.

Дальнейшие шаги

Итак, к этому моменту наше приложение полностью настроено для использования Application Insights и Serilog, и мы можем использовать Serilog для отправки сообщений в Application Insights, а также в любые другие хранилища, если мы их сконфигурировали.

Дальше мы рассмотрим, как еще можно улучшить логирование в приложении, например логирование HTTP запросов и логирование распределенных операций.

Логирование HTTP запросов

Serilog позволяет реализовать логирование HTTP запросов в более чистом и полезном виде:

Стандартное логирование запросов в ASP.NET Core сильно захламлено, поскольку для каждого входящего запроса записывается несколько сообщений. Реализованное нами (Serilog) middleware объединяет все эти сообщения в одно, в котором сохраняются метод, путь, код ответа и длительность выполнения запроса.

Чтобы включить этот функционал, нужно добавить две строки кода. Одну из них мы уже добавили:

loggerConfiguration.MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning);

А вот и вторая:

app.UseSerilogRequestLogging(); // app is an IApplicationBuilder

Этот метод регистрирует middleware для логирования запросов, и поэтому его нужно вызвать перед регистрацией других middleware и обработчиков, таких как MVC. В противном случае запросы, обрабатываемые ими, не будут логироваться. В метод UseSerilogRequestLogging можно передать параметр - функцию настройки:

var logOptions = app.ApplicationServices.GetRequiredService<IOptions<LogConfigOptions>>().Value;
// LogConfigOptions is a home-brew configuration class for high-level logging setup

if (logOptions.HttpRequestLogging) {
    app.UseSerilogRequestLogging(options => {
        options.GetLevel = (_, _, _) => logOptions.HttpRequestLogLevel;
    
        options.EnrichDiagnosticContext = (diagnosticContext, httpContext) => {
            foreach (var filler in httpContext.RequestServices.GetServices<IDiagnosticContextItem>()) {
                var data = filler.GetData(httpContext);
                if (data is not null) {
                    diagnosticContext.Set(filler.Key, data, destructureObjects: true);
                }
            }
        };
    });
    
    app.UseMiddleware<RequestBodyLoggingMiddleware>();
}

Опять же, рассмотрим этот код подробно. Эта функция принимает параметр типа RequestLoggingOptions для более тонкой настройки логирования запросов. Поле 'GetLevel' определяет функцию с тремя параметрами и возвращающую LogEventLevel:

экземпляр HttpContext для текущего запроса,
длительность выполнения запроса в миллисекундах,
исключение, если оно произошло.

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

Другое поле, EnrichDiagnosticContext, тоже является функцией, которая позволяет добавлять дополнительные данные к логу текущего запроса. Эта функция принимает два параметра: экземпляр HttpContext для текущего запроса и экземпляр типа IDiagnosticContext. Этот интерфейс реализует два метода - Set и SetException - для добавления дополнительных данных к логу. Метод Set принимает три параметра: имя логируемого параметра, его значение и необязательный параметр destructureObjects, который позволяет включить структурное логирование для переданного значения. Значение по умолчанию для этого параметра - false, но если мы добавляем сложные объекты (классы и т.п.), то лучше установить его в true: тогда логи будут более читаемыми и полезными.

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

Логирование тела запроса

В вышеприведенном фрагменте кода мы настроили Serilog для логирования входящих HTTP запросов в удобном для анализа виде. Однако Serilog не будет логировать ряд важных параметров запросов, к примеру, тело и заголовки, что может быть нужно для отладки и/или исходя из требований к приложению.

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

public sealed class RequestBodyLoggingMiddleware {
    private readonly RequestDelegate next;
    
    public RequestBodyLoggingMiddleware(RequestDelegate next) {
        this.next = next;
    }
    
    public async Task InvokeAsync(HttpContext context, IOptions<LogConfigOptions> logOptions) {
        if (logOptions.Value.HttpRequestLogging && (context.Request.Method == HttpMethod.Post.Method
            || context.Request.Method == HttpMethod.Put.Method || context.Request.Method == HttpMethod.Patch.Method)) {
            string body = await TryGetRequestData(context.Request);
            if (!string.IsNullOrEmpty(body)) {
                var bodyLogger = context.RequestServices.GetRequiredService<RequestBodyDiagnosticItem>();
                bodyLogger.ProvideRequestBody(body);
            }
        }
    
        await next(context);
    }
    
    private static async ValueTask<string> TryGetRequestData(HttpRequest request) {
        if (request.ContentLength.GetValueOrDefault() == 0) {
            return "";
        }
    
        if (request.HasFormContentType) {
            return ReadFormData(request.Form);
        }
    
        return await ReadBodyAsync(request);
    }
    
    private static async ValueTask<string> ReadBodyAsync(HttpRequest request) {
        if (!request.Body.CanSeek) {
            request.EnableBuffering();
        }
    
        using var streamReader = new StreamReader(request.Body, leaveOpen: true);
        string body = await streamReader.ReadToEndAsync();
        request.Body.Position = 0;
        return body;
    }
    
    private static string ReadFormData(IFormCollection form) { ... }
}

Этот код, в целом, говорит сам за себя. Тем не менее, укажу на основные важные моменты. Ряд HTTP методов, вроде GET, не содержат (или не должны содержать) тело запроса. К таким методам относятся TRACE, OPTIONS и HEAD. Некоторые реализации позволяют передавать и принимать тело с DELETE запросами, однако такое поведение является нежелательным, поэтому метод DELETE тоже не должен содержать тела запроса. Другие же методы - PUT, POST и PATCH - часто содержат тело запроса, которое мы и будем логировать.

Приведенная реализация пытается извлечь данные либо из тела запроса, либо из переданной формы. При чтении потока (stream) тела запроса нужно включить буферирование, чтобы после чтения можно было вернуть позицию потока в начало - иначе тело станет недоступно. Разбор данных формы здесь пропущен для краткости - этот код есть в репозитории проекта-примера (см. ссылку в конце статьи).

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

Давайте рассмотрим реализацию еще одного класса, RequestBodyDiagnosticItem, и его использование. Этот класс реализует уже упомянутый интерфейс IDiagnosticContextItem, и его нужно зарегистрировать в DI контейнере:

public sealed class RequestBodyDiagnosticItem : IDiagnosticContextItem {
    private string requestBody = "";

    public void ProvideRequestBody(string body) {
        requestBody = body;
    }
    
    public string Key => "Body";
    public object GetData(HttpContext context) => requestBody;
}

// And its registration:
services
    .AddScoped<RequestBodyDiagnosticItem>()
    .AddTransient<IDiagnosticContextItem>(provider => provider.GetRequiredService<RequestBodyDiagnosticItem>());

Аналогичным образом можно добавить другие дополнительные данные к логам HTTP запросов. Например, клиентский IP адрес и заголовки запроса.

public sealed class RequestIpDiagnosticItem : IDiagnosticContextItem{
	public object GetData(HttpContext context) => context.Request.HttpContext.Connection.RemoteIpAddress ?? IPAddress.None;
	public string Key => "IP address";
}

public class RequestHeadersDiagnosticItem : IDiagnosticContextItem {
	public object GetData(HttpContext context) => context.Request.Headers.ToArray();
	public string Key => "Headers";
}

// And their registration:
services
    .AddTransient<IDiagnosticContextItem, RequestHeadersDiagnosticItem>()
    .AddTransient<IDiagnosticContextItem, RequestIpDiagnosticItem>();

Обратите внимание, что эти два класса регистрируются как 'transient', то есть, DI контейнер не сохраняет их экземпляры. Эти классы не хранят состояние, а только лишь реализуют поведение, в отличие от RequestBodyDiagnosticItem, который должен хранить состояние на протяжение времени выполнения запроса.

Давайте посмотрим, как такие логи будут выглядеть в Application Insights:

Тело запроса помещается в объект customDimensions, в который также помещаются данные, отправленные самим Serilog, как и все другие дополнительные данные, логирование которых мы реализовали выше - 'Headers' и 'IP address'. У этого запроса не было тела, поэтому оно отсутствует на скриншоте.

Если мы развернем заголовки, то увидим их значения:

Обратите внимание на заголовок 'apikey' - он относится к тем данным, которые нельзя логировать. В реальном приложении нужно реализовать маскирование логируемых данных.

Итак, теперь мы можем логировать HTTP запросы достаточно полно.

"Обогащение" (enriching) логов дополнительными данными

У Serilog есть интересная концепция «обогащения» логов, которую они описывают как «логируемые сообщения могут быть обогащены данными с помощью разных подходов». Мы уже воспользовались некоторыми стандартными способами «обогащения»:

loggerConfiguration
    .Enrich.FromLogContext()
    .Enrich.WithCorrelationIdHeader(HeaderKeyNames.CorrelationId)
    .Enrich.WithExceptionDetails();

«Обогащение» с помощью 'log context' позволяет динамически добавлять дополнительные данные к логам и исключать их. Такие объекты реализуют интерфейс IDisposable, и с помощью метода Dispose их можно исключить из всех последующих сообщений по мере необходимости.

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

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

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

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

public sealed class UserIdEnricher : ILogEventEnricher {
    private const string UserIdPropertyName = "UserId";
    
    private readonly IHttpContextAccessor contextAccessor;
    
    public UserIdEnricher(IHttpContextAccessor contextAccessor) {
        this.contextAccessor = contextAccessor;
    }
    
    void ILogEventEnricher.Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) {
        if (contextAccessor.HttpContext == null) {
            return;
        }
    
        int? userId = ... // logic to extract the id; the id may as well be a string or a GUID
    
        if (userId.HasValue) {
            var property = new LogEventProperty(UserIdPropertyName, new ScalarValue(userId));
            logEvent.AddOrUpdateProperty(property);
        }
    }
}

Этот класс реализует стандартный интерфейс Serilog — ILogEventEnricher. Его метод Enrich будет вызван Serilog для «обогащения» логируемых сообщений теми данными, которые мы извлечен из токена (или другого источника), который доступен через текущий HttpContext. Достаточно правильно зарегистрировать этот класс:

loggerConfiguration.Enrich.With<UserIdEnricher>(); // loggerConfiguration is a Serilog.LoggerConfiguration instance

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

loggerConfiguration.ReadFrom.Services(provider);

И просто зарегистрировать наш класс в DI контейнере:

services.AddScoped<ILogEventEnricher, UserIdEnricher>();

Метод ReadFrom.Services воспользуется всеми зарегистрированными реализациями ILogEventEnricher. Никакого дополнительного кода не нужно, чтобы наш «обогатитель» заработал и стал добавлять информацию о текущем пользователе ко всем логам.

Итак, что может дать концепция «обогащения» логов и как ее можно применять? Первое, что стоит упомянуть, — это то, что ни бизнес‑код, ни код приложения не предназначены для того, чтобы производить логи, у этого кода совсем другая задача. Чем меньше кода, относящегося к логированию, примешано к бизнес‑коду и коду приложения, тем более чистым, менее связанным и более сопряженным (low coupling, high cohesion — эти термины плохо переводятся адекватно) будет наш код. Многие из тех, кто работают с enterprise‑приложениями, привыкли к коду, щедро «сдобренному» операторами логирования и другими «посторонними» вставками. И хотя «что и как» логировать и «что и когда» не логировать является предметом частых дебатов и зависит от конкретных сценариев и требований, написание чистого и легко поддерживаемого кода всегда желательно.

«Обогащение», реализованное Serilog, — это способ абстрагировать и изолировать сбор дополнительных данных для логирования и их запись в логи. С его помощью можно писать более чистый и более тестируемый код. Часто какие‑то данные недоступны в том месте кода, где нужно записать логи, и эти данные при «обычном подходе» придется как‑то регистрировать, а потом передавать через дополнительную зависимость или через некий «провайдер», который может их предоставить. Противоположный сценарий тоже не редок: некие данные, доступные сейчас, должны оказаться в логах, которые будут записаны где-то дальше. Давайте рассмотрим вариант решения этой проблемы.

public sealed class CustomLogEnricher : ILogEventEnricher {
    private readonly Dictionary<string, List<string>> properties = new();
    
    public CustomLogEnricher With(string property, string value) {
        if (string.IsNullOrWhiteSpace(value)) {
            return this;
        }
    
        if (properties.TryGetValue(property, out var values)) {
            values.Add(value);
        } else {
            properties.Add(property, new() { value });
        }
    
        return this;
    }
    
    void ILogEventEnricher.Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) {
        foreach (var item in properties) {
            LogEventPropertyValue value = item.Value.Count == 1
                ? new ScalarValue(item.Value[0])
                : new SequenceValue(item.Value.Select(x => new ScalarValue(x)));
            logEvent.AddOrUpdateProperty(new LogEventProperty(item.Key, value));
        }
    }
}

// Its registration:
services
    .AddScoped<CustomLogEnricher>()
    .AddTransient<ILogEventEnricher>(provider => provider.GetRequiredService<CustomLogEnricher>());

Это достаточно общий вариант «обогащения» логов. Экземпляр этого класса может быть внешней зависимостью, и с помощью его метода With можно передать данные, которые мы хотим логировать со всеми последующими записями в лог. Опять же — эта реализация дана для демонстрации концепции и возможностей «обогащения», реальные сценарии могут потребовать более комплексного подхода. С определенной точки зрения, это упрощенный вариант LogContextEnricher, доступного «из коробки» со стандартным набором «обогатителей» Serilog, и который предоставляет ряд дополнительных возможностей, например исключения данных из дальнейшего логирования.

Также стоит упомянуть, что только те данные, которые были накоплены в «обогатителях» к моменту записи сообщения в лог, будут записаны вместе с сообщением. Кроме того, можно реализовать дополнительную логику внутри метода Enrich для фильтрации или форматирования данных в зависимости от параметров текущего LogEvent, например, его уровня или наличия исключения. Эта логика может опираться на любые доступные внешние зависимости.

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

Поддержка логирования для распределенных сервисов

Распределенные сервисы и распределенные логи встречаются часто. Одна из основных задач для этого сценария — обеспечить единый уникальный идентификатор операции на протяжении всей цепочки вызова распределенных сервисов, которые с нашей точки зрения являются одной целостной операцией. Для REST API и HTTP запросов для этой цели обычно используется «correlation id», который передается в заголовках запроса для всех операций, и его значение поддерживается на протяжении всей цепочки вызовов.

Давайте посмотрим, как это реализовать и использовать для записи логов в Application Insights с помощью Serilog.

При настройке логирования мы использовали "обогащение" для correlation id:

loggerConfiguration.Enrich.WithCorrelationIdHeader("x-correlation-id");

Его задача очень проста: прочитать значение указанного заголовка и использовать при записи логов. По умолчанию будет использован заголовок с именем 'x-correlation-id'. Однако нужен ряд дополнительных шагов, чтобы этот заголовок с тем же самым значением был передан всем исходящим запросам. ASP.NET Core реализует механизм 'header propagation', которым мы и воспользуемся.

Этот код подключает все необходимые сервисы для header propagation:

services.AddHeaderPropagation(x => {
    x.Headers.Add("x-correlation-id");
    x.Headers.Add("traceparent");
});

Если мы используем HttpClientFactory для исходящих запросов, то ее тоже нужно настроить для поддержки header propagation:

services.AddHttpClient("name-of-http-client").AddHeaderPropagation();

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

Концепция operation id в Application Insights

Во всех записях в Application Insights присутствует поле 'operation_Id' которое служит именно этой цели - связать воедино все записи, относящиеся к одной логической операции. Есть несколько способов передать operation id в Application Insights, и мы рассмотрим, как это можно реализовать в приложении ASP.NET Core.

Один из стандартов, принятых консорциумом W3C, является 'Trace Context', который служит для поддержки распределенных операций, и Application Insights полностью поддерживает его. Нам достаточно создать заголовок 'traceparent' с правильным значением и отправить его вместе с запросом - Application Insights прочитает его, извлечет значение operation id и добавит ко всем записанным сообщениям. И поскольку мы уже настроили header propagation для передачи этого заголовка, он будет отправлен со всеми исходящими запросами, и будет точно так же использован дальше.

Стандарт продолжает изменяться, и сейчас он имеет 'Level 3'. Давайте кратко рассмотрим, как сформировать правильное значение. Оно состоит из четырех частей, разделенных дефисом ('-'):

version,
trace id,
parent id,
флаги.

На настоящий момент поле version всегда должно быть "00". Поле 'trace id' хранит нужный нам operation id, и должно состоять из 32 шестнадцатеричных знаков на нижнем регистре. Поле 'parent id' должно состоять из 16 шестнадцатеричных знаков на нижнем регистре. Стандарт описывает это поле как "идентификатор запроса, известный вызывающей стороне". Для наших целей, однако, это поле можно изначально сгенерировать случайным образом.

Поле флагов определяет два флага: FLAG_SAMPLED = 1 и FLAG_RANDOM = 2. Поскольку обычно мы будем генерировать случайное значение, нам нужно будет устанавливать FLAG_RANDOM. Другой флаг, FLAG_SAMPLED, может использоваться вызывающей стороной чтобы указать, что она записала данные трассировки у себя. Этот флаг можно спокойно игнорировать, поскольку он никак не влияет на обработку этого значения в Application Insights.

Ниже приведена простая реализация генератора значений для заголовка traceparent.

public sealed class TraceContext {
    private const string Version = "00";
    
    private const int FlagSampled = 1;
    private const int FlagRandom = 2;
    
    private const int ParentIdLength = 16;
    private const int CorrelationIdLength = 32;
    
    private static readonly Random Rnd = new();
    
    private string? traceParentValue;
    
    public TraceContext() {
        var bytes = new byte[8];
        Rnd.NextBytes(bytes);
        ParentId = string.Concat(bytes.Select(b => b.ToString("x2")));
        CorrelationId = Guid.NewGuid().ToString("N");
    }
    
    public TraceContext(string parentId, string correlationId) {
        if (parentId.Length != ParentIdLength || !IsHexadecimal(parentId)) {
            throw new ArgumentException("Must contain a 16 hexadecimal lowercase characters string", nameof(parentId));
        }
    
        if (correlationId.Length != CorrelationIdLength || !IsHexadecimal(correlationId)) {
            throw new ArgumentException("Must contain a 32 hexadecimal lowercase characters string", nameof(correlationId));
        }
    
        ParentId = parentId;
        CorrelationId = correlationId;
    }
    
    public bool Sampled { get; set; } = false;
    public string ParentId { get; }
    public string CorrelationId { get; }

    public override string ToString() {
        if (traceParentValue is null) {
            var sb = new StringBuilder(Version, 55)
                .Append("-")
                .Append(CorrelationId)
                .Append("-")
                .Append(ParentId)
                .Append("-")
                .Append((FlagRandom | (Sampled ? FlagSampled : 0)).ToString("x2"));
    
            traceParentValue = sb.ToString();
        }
    
        return traceParentValue;
    }
    
    private static bool IsHexadecimal(ReadOnlySpan<char> span) {
        foreach (char c in span) {
            if (c is (< '0' or > '9') and (< 'a' or > 'f')) {
                return false;
            }
        }
    
        return true;
    }
}

Итак, если мы сгенерируем заголовок traceparent и передадим его с первым запросом в нашей операции, Application Insights автоматически использует его, и он будет передан дальше со всеми исходящими запросами благодаря реализованному нами коду, образуя уникальную логическую операцию в наших логах.

Наш код можно в этом случае несколько упростить, и вместо имени заголовка 'x-correlation-id' указать 'traceparent', если всем сервисам этого будет достаточно:

loggerConfiguration.Enrich.WithCorrelationIdHeader("traceparent");

Заключение

К этому моменту наше приложение полностью настроено для поддержки комплексных сценариев логирования с помощью Serilog и использует Application Insights в качестве основного хранилища логов. При необходимости мы можем дополнить логи полной информацией о входящих HTTP запросах, «обогатить» логи дополнительной информацией, поддержать сценарий с распределенными сервисами и воспользоваться Azure Log Stream для немедленного доступа к логируемой информации.

Для реального приложения необходимо реализовать дополнительный функционал — например, маскирование секретной и чувствительной информации в логах (помните записанный API key?). Однако обзор этой и других тем потребует другого большого материала. Могу лишь указать на реализацию SensitiveDataEnricher: «обогащение» логов способно не только добавлять данные, но и манипулировать текущим содержимым LogEvent. Конечно, для этого есть и другие возможности, например, явная фильтрация заголовков.

Спасибо за чтение, я надеюсь, оно было полезным!

Ссылки на использованные ресурсы

Общая информация о логировании в .NET - https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging

Обзор Application Insights - https://learn.microsoft.com/en-us/azure/azure-monitor/app/app-insights-overview

О Telemetry channels в Application Insights - https://learn.microsoft.com/en-us/azure/azure-monitor/app/telemetry-channels

О Azure log streams:

Serilog:

Общая информация о внедрении зависимостей в .NET - https://learn.microsoft.com/en-us/dotnet/core/extensions/dependency-injection

О trace context - https://w3c.github.io/trace-context/#traceparent-header-field-values

Логирование в Azure с Application Insights и Serilog +3