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

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

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

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

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

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

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

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

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

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

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

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

Install-Package Serilog.Sinks.Logzio 

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

LoggerConfiguration loggerConfig = new LoggerConfiguration(); loggerConfig.WriteTo.Logzio(secrets.LogzioToken, 10, TimeSpan.FromSeconds(10), null, LogEventLevel.Debug); 

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

Интерфейсы

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

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

Корелляция в 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-запрос отправляет событие SomethingDoneMessage со значением «done». Контракт такого сообщения можно описать так:

namespace MbMessages {     public interface ISomethingDoneMessageV1     {         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:MbMessages:ISomethingDoneMessageV1"   ],   "message": {     "value": "done"   } } 

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

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

namespace MbMessages {     public interface ISomethingDoneMessageV1 : CorrelatedBy<Guid>     {         string Value { get; }     } } 

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

internal class SomethingDoneMessageV1 : ISomethingDoneMessageV1 {     internal SomethingDoneMessageV1(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:MbMessages:ISomethingDoneMessageV1"   ],   "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