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

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

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

В тази статия ще вземем просто уеб API приложение и ще организираме логване, което ще

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

• да имате единна точка на вход с удобен анализ, така че инструментът за логване да може да се използва дори от Поддръжката, която получава въпроси като "в приложението ми е изскочила грешка с такъв-то идентификатор на заявка".

Първо, трябва да се определим с доставчика на логване в приложението ни. Основното изискване за съвременното логване е структурността, т.е. трябва да работим не с плоски текстови съобщения, а с обекти. С такива логове лесно можем да изградим представления на съобщенията ни от различни ъгли и да провеждаме анализ.

За нашето приложение ще използваме пакета Serilog, който има отлична поддръжка за структурно логване и богата система от добавки. Ще пропусна основните стъпки за настройка (можете да намерите много статии по темата) и ще предположа, че

• 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);

След като стартираме приложението, ще можем да наблюдаваме нашите съобщения не само в конзолата, но и в Кибана.

Интерфейси

В приложението от тип услуга можем да откроим два основни интерфейса за взаимодействие с външния свят, които да наречем вертикален и horizontal. Вертикалният интерфейс е уеб-API, през което идват повиквания от клиентското приложение. Хоризонталният е брокер на съобщения, който се използва за обмен на данни с други вътрешни услуги.

Нека разгледаме стъпките за внедряване на корелация на всеки от тези интерфейси.

Корелация в HTTP заявките

За да получаваме колкото е възможно повече информация, е необходимо да генерираме идентификатор на корелацията колкото се може по-близо до началото на активността, т.е. на шлюза или директно на клиента (мобилен или уеб). Поскольку днес имаме работа с бекенд приложение, просто ще обозначим изискването за задължителен заглавието „X-Correlation-ID“ за всички заявки към уеб-API.

Добавяме пакета 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-филтър:

публичен запечатан клас ApiRequestFilter : ActionFilterAttribute
{
    публичен ApiRequestFilter(IApiRequestTracker apiRequestTracker, ICorrelationContextAccessor correlationContextAccessor)
    {
        _correlationContextAccessor = correlationContextAccessor ?? throw new ArgumentNullException(nameof(correlationContextAccessor));
    }
    
    частен readonly ICorrelationContextAccessor _correlationContextAccessor;
    
    публичен 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();
    }
    
    публичен override async Task OnResultExecutionAsync(ResultExecutingContext context, ResultExecutionDelegate next)
    {
        await next.Invoke();
    }
}

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

[Route("[controller]")]
[ApiController]
[ServiceFilter(typeof(ApiRequestFilter))]
публичен клас CarsController : ControllerBase
{

}

В резултат контролерът ще издава 400 Bad Request на всички заявки без заглавка със съответния идентификатор.

След като започнахме да получаваме идентификатор от клиента, трябва да го добавим в контекста на логването, ще създадем обгръщаща прослойка за целта:

публичен клас CorrelationIdContextLogger
{
    публичен CorrelationIdContextLogger(RequestDelegate next)
    {
        _next = next ?? throw new ArgumentNullException(nameof(next));
    }
    
    readonly RequestDelegate _next;
    
    публичен async Task InvokeAsync(HttpContext httpContext, ILogger 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, затова стойността ще добавяме с простo разширение към него.

публичен static IDisposable BeginScopeWith(this ILogger logger, params (string key, object value)[] keys)
{
    return logger.BeginScope(keys.ToDictionary(x => x.key, x => x.value));
}

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

публичен клас Startup
{
    публичен void Configure(IApplicationBuilder application)
    {
        application.UseMiddleware();
    }
}

Сега всички активности, произтичащи от заявките към нашето уеб API, съдържат корелационен идентификатор, по който лесно могат да бъдат свързани.

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

Следващата стъпка е да настроим предаването и получаването на корелационния идентификатор чрез брокер на съобщения. В нашия пример ще използваме RabbitMQ, а за клиент ще вземем фреймворка MassTransit. Отново, ще пропуснем началната конфигурация за работа с MassTransit и ще преминем направо към настройките за логване.

За начало можем да активираме логовете на самия MassTransit, за тази цел добавяме в приложението ни пакета MassTransit.SerilogIntegration

Install-Package MassTransit.SerilogIntegration

Сега след добавянето на логера в настройките на MassTransit ще можем да виждаме логовете на фреймворка.

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

Нека нашето приложение да изпраща събитие SomethingDoneMessage със стойност „done“ в отговор на POST заявка. Контрактът на такова съобщение може да бъде описан така:

namespace MbMessages
{
    public interface ISomethingDoneMessageV1
    {
        string Value { get; }
    }
}

Съобщенията на MassTransit всъщност представляват плик, в който са вложени съобщенията на брокера. Пликът изглежда приблизително така:

{
  "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
    {
        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; }
}

Когато разгледаме обновеното съобщение, ще видим, че идентификаторът на корелацията е станал не само част от нашето съобщение, но и част от конверта — този идентификатор сега ще се използва и във всички логове на MassTransit, което ще улесни разбирането на проблемите на ниво брокер на съобщения.

{
  "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, който поставя контекста на съобщението в потокобезопасен стек. Serilog чете контекста от стека и добавя тези допълнителни свойства в нашите логове.

Install-Package Serilog.Enrichers.MassTransitMessage

В MassTransit добавяме филтър

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

А в конфигурацията на Serilog добавяме енричер

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

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

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

Така получената система за логване в .Net приложения позволява без особени проблеми да корелираме логовете от абсолютно различни микросервизи — дори и тези, които работят чрез брокер на съобщения. А с помощта на Elasticsearch можем бързо и удобно да извършваме анализ на логовете, като изградим в Kibana необходимите ни табла за управление (примерът е показан на изображението към публикацията).

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

Можете да разгледате изходния код на получената система в проекта: github.com/a-postx/YA.ServiceTemplate

Източник: habr.com