Логирование в микросервисной среде .Net на практике

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

В .Net Core 3 добавилась отличная возможность передачи контекста корреляции в HTTP-заголовках, поэтому если ваши приложения используют прямые HTTP-вызовы для межсервисного взаимодействия, то вы можете воспользоваться этой коробочной функцональностью. Однако, если архитектура вашего бекенда подразумевает взаимодействие через брокера сообщений (RabbitMQ, Kafka и т.п.), то вам по-прежнему необходимо озаботиться темой передачи корелляционного контекста через эти сообщения самостоятельно.

В этой статье мы возьмём простое веб-апи приложение и организуем логирование, которое будет

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

• иметь единую точку входа с удобным анализом, чтобы инструментом логирования смогла пользоваться даже Поддержка, к которой летят вопросы вроде «у меня тут в приложении выскочила ошибка с таким-то айдишником запроса»

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

Для нашего приложения мы воспользуемся пакетом Serilog (Серилог), который имеет отличную поддержку структурного логирования и богатую систему дополнений. Я опущу базовые этапы его настройки (вы можете найти большое количество статей на эту тему) и сделаю допущение о том, что

• Серилог уже сконфигурирован и является логером по-умолчанию у вашего поставщика внедрения зависимостей

• в его конфигурации включено обогащение сообщений свойствами контекста (Enrich.FromLogContext)

Следующим шагом необходимо выбрать в какую систему централизованного сбора логов посылать сообщения из Serilog. Пожалуй, самый распространённый на сегодня вариант из открытого ПО это стек ELK (Elasticsearch, Logstash и Kibana), его и возьмём. Для этого воспользуемся предложением от Logz.IO — после регистрации на бесплатном тарифе в наших руках оказывается вся мощь поискового движка Lucene.

Нам остаётся добавить в наш проект пакет Serilog.Sinks.Logz.Io

Install-Package Serilog.Sinks.Logz.Io

И добавить соответствующий энричер в конфигурацию нашего логера, скормив ему токен доступа

LoggerConfiguration loggerConfig = new LoggerConfiguration();
loggerConfig.WriteTo.LogzIo(secrets.LogzioToken, null,
                    new LogzioOptions
                    {
                        DataCenterSubDomain = "listener-eu",
                        UseHttps = false,
                        RestrictedToMinimumLevel = LogEventLevel.Debug,
                        Period = TimeSpan.FromSeconds(10),
                        BatchPostingLimit = 10
                    });

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

Интерфейсы

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

Рассмотрим этапы внедрения корелляционности на каждом из этих интерфейсов.

Корелляция в HTTP-запросах

Чтобы получать как можно больше информации нам необходимо генерировать идентификатор корелляции как можно ближе к началу активности, т.е. на шлюзе или прямо на клиенте (мобильном или веб). Поскольку мы сегодня имеем дело с бекендным приложением, то просто обозначим на нём требование обязательного заголовка «X-Correlation-ID» во всех запросах к веб-апи.

Добавляем пакет CorrelationID, функция которого заключается в заборе значения из необходимого нам заголовка

Install-Package CorrelationID

Добавим его в конвейер обработки запроса

public class Startup
{
    public void Configure(IApplicationBuilder application)
    {
        application
	    .UseCorrelationId(new CorrelationIdOptions
        {
            Header = "X-Correlation-ID",
            IncludeInResponse = false,
            UpdateTraceIdentifier = false,
            UseGuidForCorrelationId = false
        });
    }
}

Теперь с его помощью сделаем простой action-фильтр:

public sealed class ApiRequestFilter : ActionFilterAttribute
{
    public ApiRequestFilter(IApiRequestTracker apiRequestTracker, ICorrelationContextAccessor correlationContextAccessor)
    {
        _correlationContextAccessor = correlationContextAccessor ?? throw new ArgumentNullException(nameof(correlationContextAccessor));
    }
    
    private readonly ICorrelationContextAccessor _correlationContextAccessor;
    
    public override async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
    {
        if (!Guid.TryParse(_correlationContextAccessor.CorrelationContext.CorrelationId, out Guid correlationId))
        {
            context.Result = new BadRequestResult();
            return;
        }
    
        await next.Invoke();
    }
    
    public override async Task OnResultExecutionAsync(ResultExecutingContext context, ResultExecutionDelegate next)
    {
        await next.Invoke();
    }
}

И добавим его в контроллер

[Route("[controller]")]
[ApiController]
[ServiceFilter(typeof(ApiRequestFilter))]
public class CarsController : ControllerBase
{

}

В результате контроллер станет выводить 400 Bad request на все запросы без заголовка с соответствующим идентификатором.

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

public class CorrelationIdContextLogger
{
    public CorrelationIdContextLogger(RequestDelegate next)
    {
        _next = next ?? throw new ArgumentNullException(nameof(next));
    }
    
    readonly RequestDelegate _next;
    
    public async Task InvokeAsync(HttpContext httpContext, ILogger<CorrelationIdContextLogger> logger, ICorrelationContextAccessor correlationContextAccessor)
    {
        if (Guid.TryParse(correlationContextAccessor.CorrelationContext.CorrelationId, out Guid correlationId))
        {
            using (logger.BeginScopeWith(("CorrelationId", correlationId)))
            {
                await _next(context);
            }
        }
        else
        {
            await _next(context);
        }
    }
}

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

public static IDisposable BeginScopeWith(this ILogger logger, params (string key, object value)[] keys)
{
    return logger.BeginScope(keys.ToDictionary(x => x.key, x => x.value));
}

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

public class Startup
{
    public void Configure(IApplicationBuilder application)
    {
        application.UseMiddleware<CorrelationIdContextLogger>();
    }
}

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

Корелляция в сообщениях брокера

Следующим шагом нам необходимо наладить передачу и приём корелляционного идентификатора через брокер сообщений. В нашем примере мы будем использовать RabbitMQ, а в качестве клиента возьмём фреймворк MassTransit (МассТранзит). Опять же, опустим первоначальную настройку работы с МассТранзита и перейдём сразу к настройке логирования.

Для начала мы можем включить логи самого МассТранзита, для этого добавим в наше приложение пакет MassTransit.SerilogIntegration

Install-Package MassTransit.SerilogIntegration

Теперь после добавления логера в настройки MassTransit мы сможем видеть логи фреймворка.

services
    .AddSingleton(provider =>
        {
            return Bus.Factory.CreateUsingRabbitMq(cfg =>
            {
                cfg.UseSerilog();
            });
        });

Пусть наше приложение в качестве реакции на POST-запрос отправляет событие SomethingHappened со значением «Hello». Контракт такого сообщения можно описать так:

namespace MbEvents
{
    public interface ISomethingHappenedV1
    {
        string Value { get; }
    }
}

Сообщения МассТранзита по сути являются конвертом, в который вложены сообщения брокера. Выглядит конверт примерно так:

{
  "messageId": "59020000-5dba-0015-10b8-08d77ec28593",
  "requestId": "59020000-5dba-0015-5674-08d77ec28592",
  "conversationId": "59020000-5dba-0015-bca8-08d77ec28594",
  "destinationAddress": "rabbitmq://bear.rmq.cloudamqp.com/aelzlsta/ya.servicetemplate.receiveendpoint",
  "headers": {},
  "messageType": [
    "urn:message:MbEvents:ISomethingHappenedV1"
  ],
  "message": {
    "value": "Hello"
  }
}

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

Добавим к контракту сообщения интерфейс CorrelatedBy:

namespace MbEvents
{
    public interface ISomethingHappenedV1 : CorrelatedBy<Guid>
    {
        string Value { get; }
    }
}

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

internal class SomethingHappenedV1 : ISomethingHappenedV1
{
    internal SomethingHappenedV1(Guid correlationId, string value)
    {
        CorrelationId = correlationId;
        Value = value;
    }
    
    public Guid CorrelationId { get; private set; }
    public string Value { get; private set; }
}

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

{
  "messageId": "59020000-5dba-0015-10b8-08d77ec28593",
  "requestId": "59020000-5dba-0015-5674-08d77ec28592",
  "conversationId": "59020000-5dba-0015-bca8-08d77ec28594",
  "correlationId": "c7ff562a-b639-415b-9add-c9e524a727cc",
  "destinationAddress": "rabbitmq://bear.rmq.cloudamqp.com/aelzlsta/ya.servicetemplate.receiveendpoint",
  "headers": {},
  "messageType": [
    "urn:message:MbEvents:ISomethingHappenedV1"
  ],
  "message": {
    "correlationId": "c7ff562a-b639-415b-9add-c9e524a727cc",
    "value": "Hello"
  }
}

Нам осталось настроить логирование этих служебных свойств сообщения, для этого добавим в проект пакет Serilog.Enrichers.MassTransitMessage. Пакет добавляет фильтр в конвейер обработки сообщений MassTransit, который складывает контекст сообщения в потокобезопасный стек. Серилог читает контекст из стека и добавляет в наши объекты логов эти дополнительные свойства.

Install-Package Serilog.Enrichers.MassTransitMessage

В МассТранзите вставляем фильтр

services
    .AddSingleton(provider =>
        {
            return Bus.Factory.CreateUsingRabbitMq(cfg =>
            {
                cfg.UseSerilog();
                cfg.UseSerilogMessagePropertiesEnricher();
            });
        });

А в конфигурации Серилога добавляем энричер

Log.Logger = new LoggerConfiguration()
    .Enrich.FromMassTransitMessage()
    .CreateLogger();

Поскольку приложение, которое получает сообщение из очереди RabbitMQ, имеет доступ ко всем свойствам конверта MassTransit, мы можем использовать полученный идентификатор корелляционности внутри приложения-потребителя, а также передавать его дальше по всей цепочке вызовов.

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

Итак, полученная система логирования в .Net приложениях позволяет нам без особых проблем скореллировать логи из абсолютно разных микросервисов — даже тех, что работают через брокера сообщений. А с помощью Elasticsearch мы можем быстро и удобно проводить анализ логов, построив в Кибане необходимые нам дашборды (пример приведён на картинке к посту).

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

Поразбираться в исходном коде получившейся системы вы можете в проекте: github.com/a-postx/YA.ServiceTemplate