Современные запросы к Web-сервисам представляют собой сложные вещи. Сервис, к которому вы обращаетесь, может сам вызывать другие сервисы, те - третьи и т. д. Все эти запросы могут идти параллельно. Конечно, система логирования хранит информацию со всех участвовавших в запросе сервисов, но с учётом того, что часы на разных сервисах могут быть рассинхронизированы, восстановить полную картину можут быть непросто. А если добавить сюда посылку и обработку сообщений через различные очереди (Azure EventHub, RabbitMQ, ...), то картина становится ещё более запутанной.
Здесь я попытаюсь создать такую систему, которая могла бы очень быстро строить для меня диаграмму последовательности событий (sequence diagram), происходящих во время моего запроса.
Итак, начнём.
Анализируемая система
Давайте начнём с построения той системы, прохождение запросов через которую я хочу анализировать. Полный код можно скачать с GitHub.
Моя система будет состоять из нескольких сервисов (Service1, Service2, Service3, ExternalService):
Сервисы ServiceN представляют собой участников моей системы, находящихся под моим контролем. Они выполняют некоторую работу, заносят в лог записи и делают запросы к другим сервисам. Для нас сейчас не важно, что именно делают сервисы. Вот типичный пример метода одного из контроллеров:
[HttpGet]
public async Task<IEnumerable<WeatherForecast>> Get()
{
_logger.LogInformation("Get weather forecast");
Enumerable.Range(1, 4).ToList()
.ForEach(_ => _logger.LogInformation("Some random message"));
await Task.WhenAll(Enumerable.Range(1, 3).Select(_ => _service2Client.Get()));
await _service3Client.Get();
return Enumerable.Range(1, 5).Select(index => new WeatherForecast
{
Date = DateTime.Now.AddDays(index),
TemperatureC = Random.Shared.Next(-20, 55),
Summary = Summaries[Random.Shared.Next(Summaries.Length)]
})
.ToArray();
}Но кроме моих сервисов, существуют и внешние сервисы. Проще говоря, это те сервисы, которые ничего не пишут в нашу систему логирования. Это может быть всё, что угодно: почта, базы данных, авторизация, webhook'и клиентов, ... Их у меня представляет сервис ExternalService.
Теперь наша система готова. Давайте приступим к её настройке.
Настройка системы
Во-первых, мы хотим собирать все наши логи в одном месте. Я для этого буду использовать Seq, но только потому, что его очень легко поднять в Docker. Вот соответствующий Docker Compose файл:
version: "3"
services:
seq:
image: datalust/seq
container_name: seq
environment:
- ACCEPT_EULA=Y
ports:
- "5341:5341"
- "9090:80"Теперь по адресу http://localhost:9090 у меня есть доступ к UI Seq, а настроить запись логов в него можно с помощью Serilog:
Log.Logger = new LoggerConfiguration()
.MinimumLevel.Override("Microsoft", LogEventLevel.Error)
.MinimumLevel.Override("System", LogEventLevel.Error)
.Enrich.FromLogContext()
.WriteTo.Console(new CompactJsonFormatter())
.WriteTo.Seq("http://localhost:5341")
.CreateLogger();Но к системе логирования у меня есть ещё одно требование. Она должна давать доступ к сохранённым в ней событиям через API. В данном случае, Seq предоставляет NuGet-пакет Seq.Api. Этого мне вполне достаточно.
Теперь нам нужно добавить в логи некоторую информацию, которую потом можно будет использовать для построения диаграммы последовательности запроса. Для этого я создам ASP.NET Core middleware и добавлю его в конвейер обработки запроса. Вот его основной код:
public async Task Invoke(HttpContext context)
{
GetCorrelationId(context);
GetInitialsService(context);
GetPreviousService(context);
GetPreviousClock(context);
using (LogContext.PushProperty(Names.CurrentServiceName, ServiceNameProvider.ServiceName))
using (LogContext.PushProperty(Names.CorrelationIdHeaderName, _correlationIdProvider.GetCorrelationId()))
using (LogContext.PushProperty(Names.InitialServiceHeaderName, _initialServiceProvider.GetInitialService()))
using (LogContext.PushProperty(Names.PreviousServiceHeaderName, _previousServiceProvider.GetPreviousService()))
using (LogContext.PushProperty(Names.RequestClockHeaderName, _requestClockProvider.GetPreviousServiceClock()))
{
await _next(context);
}
}Что мы здесь видим? Мы добавляем во все записи логов следующую информацию:
Имя текущего сервиса. Здесь нет никакой магии. Это может быть просто имя сборки или всё, что вам угодно.
Correlation id. Надеюсь, его подробно представлять не нужно. Он связывает все записи, относящиеся к одному внешнему запросу.
Имя сервиса, получившего внешний запрос. Т. е. это фактически точка, с которой произошёл вход запроса в нашу систему. Эта информация добавлена для удобства и в построение диаграммы последовательности использоваться не будет.
Имя предыдущего сервиса в цепочке запросов. Может быть полезно знать, от кого конкретно нам пришёл запрос.
Некоторая отметка времени, которая не зависит от конкретных часов различных сервисов. О ней речь будет идти далее.
В начале обработки запроса мы должны получить значения всех этих величин из пришедшего к нам запроса. Именно этим и занимаются методы GetNNN в начале кода Invoke. Давайте рассмотрим для примера GetCorrelationId. Остальные методы реализованы аналогично.
private void GetCorrelationId(HttpContext context)
{
if (context.Request.Headers.ContainsKey(Names.CorrelationIdHeaderName)
&& context.Request.Headers[Names.CorrelationIdHeaderName].Any())
{
_correlationIdProvider.SetCorrelationId(context.Request.Headers[Names.CorrelationIdHeaderName][0]);
}
else
{
_correlationIdProvider.SetCorrelationId(Guid.NewGuid().ToString("N"));
}
}Сами провайдеры всех этих значений тоже по большей части устроены однотипно. Они хранят значения на протяжении всего запроса в поле типа AsyncLocal<T>:
public class CorrelationIdProvider
{
private static readonly AsyncLocal<string> Value = new();
public string GetCorrelationId()
{
var value = Value.Value;
if (string.IsNullOrWhiteSpace(value))
{
value = Guid.NewGuid().ToString("N");
SetCorrelationId(value);
}
return value;
}
public void SetCorrelationId(string value)
{
if (string.IsNullOrWhiteSpace(value))
throw new ArgumentException("Value cannot be null or whitespace.", nameof(value));
Value.Value = value;
}
}Но из этой простоты есть одно исключение. А именно - монотонные часы. Вот и пришло время поговорить о них.
Монотонная последовательность вызовов
В принципе все записи лога снабжены отметками времени. Что мешает мне отсортировать их по этим отметкам и рассматривать такую последовательность записей? Несколько вещей.
Во-первых, как я уже говорил, часы на различных сервисах могут быть рассинхронизированы. Даже небольшое вроде бы отличие в несколько десятков миллисекунд может привести к тому, что записи в логах окажутся перемешанными.
Но даже если бы часы были синхронизированы идеально, это не решило бы нашу проблему до конца. Представьте себе, что мой сервис в процессе обработки запроса вызывает несколько раз одну и ту же конечную точку (endpoint) другого сервиса, но каждый раз с несколько иными параметрами. Причём для экономии времени это делается параллельно. Записи таких вызовов практически неизбежно перемешаются между собой.
Что же нам делать? Нам нужны некоторые волшебные монотонные часы, которые шли бы для всех одинаково, или монотонно увеличивающаяся последовательность чисел. Её можно было бы использовать так. Когда в мою систему приходит внешний запрос, я устанавливаю эти часы в 0. Когда мне нужно сделать вызов другого сервиса, я увеличиваю на единичку значение часов и передаю это значение другому сервису. Он получает его, делает свои вызовы, каждый раз увеличивая значение часов, а в конце возвращает мне последнее значение. И с этим значением я продолжаю работать дальше.
У такой схемы есть ряд недостатков. Во-первых, внешние (не мои) системы никак не обновляют моих часов. Но это не особо страшно. Хуже то, что сейчас я не могу делать параллельных вызовов. Мне нужно дождаться окончания очередного вызова, чтобы получить обновлённое значение часов.
Чтобы избавиться от этой проблемы, я использовал несколько иную схему. Я использую значение часов, пришедшее от предыдущего сервиса, как префикс к значению часов в моём сервисе. Суффиксом же является монотонно увеличивающаяся на каждом вызове другого сервиса последовательность чисел. Вот как это реализовано:
public class RequestClockProvider
{
private class ClockHolder
{
public string PreviousServiceClock { get; init; }
public int CurrentClock { get; set; }
}
private static readonly AsyncLocal<ClockHolder> Clock = new();
public void SetPreviousServiceClock(string? value)
{
Clock.Value = new ClockHolder
{
PreviousServiceClock = value ?? string.Empty
};
}
public string GetPreviousServiceClock() => Clock.Value?.PreviousServiceClock ?? string.Empty;
public string GetNextCurrentServiceClock()
{
lock (this)
{
var clock = Clock.Value!;
return $"{clock.PreviousServiceClock}.{clock.CurrentClock++}";
}
}
}Метод SetPreviousServiceClock используется моим middleware для инициализации часов для данного запроса. Метод же GetNextCurrentServiceClock используется при каждой отправке запроса другому сервису.
Так, если мой сервис получил запрос, в котором эти часы были установлены в 2, то он будет делать запросы со значениями часов 2.0, 2.1, 2.2, ... А сервис, получивший запрос со значением 2.1, будет генерировать свои запросы со значениями 2.1.0, 2.1.1, 2.1.2, ...
Имея эти значения для каждой из записей лога, я легко могу сгруппировать их и упорядочить. А записи внутри каждой такой группы можно безопасно сортировать по стандартной отметке времени, поскольку они относятся к обработке одного запроса одним сервисом, т. е. все они использовали значения одних и тех же физических часов.
Одно замечание. Вероятно можно было бы сказать, что я тут реализую часы Лэмпорта. Скорее всего так и есть, но я не рискну претендовать на это. Наверняка есть более эффективные алгоритмы, решающие ту же задачу. На практике, несомненно, нужно применять именно их. Но для простоты и понимания мне достаточно и моей реализации.
Отправка запросов
Итак, мы получили из пришедшего к нам запроса содержащуюся в нём требуемую нам информацию. Теперь мы должны передавать её дальше с каждым нашим собственным запросом. Как это сделать? Для простоты я буду использовать обычные HttpClient. Вот мой клиент для одного из сервисов:
public interface IService2Client
{
Task Get();
}
public class Service2Client : IService2Client
{
private readonly HttpClient _client;
public Service2Client(HttpClient client)
{
_client = client ?? throw new ArgumentNullException(nameof(client));
}
public async Task Get()
{
_ = await _client.GetAsync("http://localhost:5106/weatherforecast");
}
}Я зарегистрирую его в контейнере зависимостей так:
builder.Services.AddHttpClientWithHeaders<IService2Client, Service2Client>();Здесь метод AddHttpClientWithHeaders имеет вид:
public static IHttpClientBuilder AddHttpClientWithHeaders<TInterface, TClass>(this IServiceCollection services)
where TInterface : class
where TClass : class, TInterface
{
return services.AddHttpClient<TInterface, TClass>()
.AddHttpMessageHandler<RequestHandler>();
}Как видите, я просто добавляю свой обработчик сообщений. Вот как он выглядит:
protected override Task<HttpResponseMessage> SendAsync(
HttpRequestMessage request,
CancellationToken cancellationToken)
{
var requestClockValue = _requestClockProvider.GetNextCurrentServiceClock();
request.Headers.Add(Names.CorrelationIdHeaderName, _correlationIdProvider.GetCorrelationId());
request.Headers.Add(Names.InitialServiceHeaderName, _initialServiceProvider.GetInitialService());
request.Headers.Add(Names.PreviousServiceHeaderName, ServiceNameProvider.ServiceName);
request.Headers.Add(Names.RequestClockHeaderName, requestClockValue);
using (LogContext.PushProperty(Names.RequestBoundaryForName, requestClockValue))
using (LogContext.PushProperty(Names.RequestURLName, $"{request.Method} {request.RequestUri}"))
{
_logger.LogInformation("Sending request...");
return base.SendAsync(request, cancellationToken);
}
}Во-первых, я добавляю к запросу несколько заголовков, значения которых вам уже знакомы. Именно здесь происходит передача значений в следующий запрос.
Во-вторых, я создаю дополнительную запись в логе с двумя специальными полями. Одно из них - адрес запроса, нужно исключительно для информационных целей. Я буду показывать на диаграмме последовательности этот адрес. Второе же (RequestBoundaryFor) будет использоваться мной для того, чтобы знать, куда вставлять записи лога, относящиеся к вызываемому сервису. Мы коснёмся этого позже, когда будем рассматривать создание самой диаграммы последовательности запроса.
Запуск системы
Теперь пришло время выполнить какой-нибудь запрос. Сперва я с помощью Docker Compose запущу Seq:
> docker compose -f "docker-compose.yml" up -dПотом я запущу все мои сервисы. Для этого я создам конфигурацию запуска в Visual Studio:
Осталось выполнить запрос к одному из сервисов (например, http://localhost:5222/weatherforecast).
После этого в Seq у нас появятся логи, относящиеся к этому запросу:
Мне потребуется получить из них correlation id.
Давайте теперь посмотрим, как можно построить из этих записей диаграмму последовательности запроса.
Построение диаграммы последовательности запроса
В Интернет существует бесплатный сервис www.websequencediagrams.com. Он имеет свой язык описания диаграммы последовательности. Именно на этом языке мы и будем описывать наш запрос. Этим будет заниматься приложение EventsReader.
Но для начала нам нужно получить записи лога из Seq. Для этого используется NuGet-пакет Seq.Api:
using EventsReader;
using Seq.Api;
var connection = new SeqConnection("http://localhost:9090");
var result = connection.Events.EnumerateAsync(
filter: "CorrelationId = '4395cd986c9e4b548404a2aa2aca6016'",
render: true,
count: int.MaxValue);
var logs = new ServicesRequestLogs();
await foreach (var evt in result)
{
logs.Add(evt);
}
logs.PrintSequenceDiagram();В классе ServicesRequestLogs мы сперва разбиваем все записи по значению наших монотонных часов:
public void Add(EventEntity evt)
{
var clock = evt.GetPropertyValue(Names.RequestClockHeaderName);
if(clock == null) return;
var singleServiceLogs = GetSingleServiceLogs(clock, evt);
singleServiceLogs.Add(evt);
}
private SingleServiceRequestLogs GetSingleServiceLogs(string clock, EventEntity evt)
{
if (_logRecords.ContainsKey(clock))
{
return _logRecords[clock];
}
var serviceName = evt.GetPropertyValue(Names.CurrentServiceName)!;
var serviceAlias = GetServiceAlias(serviceName);
var logs = new SingleServiceRequestLogs
{
ServiceName = serviceName,
ServiceAlias = serviceAlias,
Clock = clock
};
_logRecords.Add(clock, logs);
return logs;
}
private string GetServiceAlias(string serviceName)
{
if(_serviceAliases.ContainsKey(serviceName))
return _serviceAliases[serviceName];
var serviceAlias = $"s{_serviceAliases.Count}";
_serviceAliases[serviceName] = serviceAlias;
return serviceAlias;
}Все записи, у которых это значение одинаково, относятся к одной обработке запроса одним сервисом. Все они хранятся в простом классе:
public class SingleServiceRequestLogs
{
public string ServiceName { get; set; }
public string ServiceAlias { get; set; }
public string Clock { get; set; }
public List<EventEntity> LogEntities { get; } = new List<EventEntity>();
public void Add(EventEntity evt)
{
LogEntities.Add(evt);
}
}Теперь осталось построить описание диаграммы последовательности:
public void PrintSequenceDiagram()
{
Console.WriteLine();
PrintParticipants();
PrintServiceLogs("");
}Метод PrintParticipants описывает всех участников обработки запроса. Поскольку имена сервисов могут содержать символы, которые неприемлемы для websequencediagrams, то мы используем псевдонимы (alias) для них:
private void PrintParticipants()
{
Console.WriteLine("participant \"User\" as User");
foreach (var record in _serviceAliases)
{
Console.WriteLine($"participant \"{record.Key}\" as {record.Value}");
}
}Метод PrintServiceLogs печатает последовательность обработки запроса в одном сервисе. Для этого ему передаётся значение монотонных часов:
private void PrintServiceLogs(string clock)
{
var logs = _logRecords[clock];
if (clock == string.Empty)
{
Console.WriteLine($"User->{logs.ServiceAlias}: ");
Console.WriteLine($"activate {logs.ServiceAlias}");
}
foreach (var entity in logs.LogEntities.OrderBy(e => DateTime.Parse(e.Timestamp, null, System.Globalization.DateTimeStyles.RoundtripKind)))
{
var boundaryClock = entity.GetPropertyValue(Names.RequestBoundaryForName);
if (boundaryClock == null)
{
Console.WriteLine($"note right of {logs.ServiceAlias}: {entity.RenderedMessage}");
}
else
{
if (_logRecords.TryGetValue(boundaryClock, out var anotherLogs))
{
Console.WriteLine($"{logs.ServiceAlias}->{anotherLogs.ServiceAlias}: {entity.GetPropertyValue(Names.RequestURLName)}");
Console.WriteLine($"activate {anotherLogs.ServiceAlias}");
PrintServiceLogs(boundaryClock);
Console.WriteLine($"{anotherLogs.ServiceAlias}->{logs.ServiceAlias}: ");
Console.WriteLine($"deactivate {anotherLogs.ServiceAlias}");
}
else
{
// Call to external system
Console.WriteLine($"{logs.ServiceAlias}->External: {entity.GetPropertyValue(Names.RequestURLName)}");
Console.WriteLine($"activate External");
Console.WriteLine($"External->{logs.ServiceAlias}: ");
Console.WriteLine($"deactivate External");
}
}
}
if (clock == string.Empty)
{
Console.WriteLine($"{logs.ServiceAlias}->User: ");
Console.WriteLine($"deactivate {logs.ServiceAlias}");
}
}Здесь мы сперва получаем все записи лога с данным значением часов (переменная logs). Далее, в начале и в конце метода мы добавляем код для самого внешнего запроса, призванный сделать нашу диаграмму более красивой. Ничего важного в нём нет:
if (clock == string.Empty) ...Вся основная работа происходит в цикле. Как видите, мы сортируем записи лога по отметке времени. Здесь это делать безопасно, поскольку они относятся только к одной обработке запроса одним сервисом. Т. е. все они получены от одних и тех же физических часов:
foreach (var entity in logs.LogEntities.OrderBy(e => DateTime.Parse(e.Timestamp, null, System.Globalization.DateTimeStyles.RoundtripKind))) ...Затем мы проверяем, не является ли текущая запись в лог служебной записью, которая означает начало запроса к другому сервису. Как уже говорилось, это определяется по наличию поля RequestBoundaryFor. Если этого поля нет, то запись является обычной записью. Поэтому мы выводим её текст в виде сноски (note):
Console.WriteLine($"note right of {logs.ServiceAlias}: {entity.RenderedMessage}");Если же это наша служебная запись, то возможны два варианта. Во-первых, может начинаться запрос к другому сервису нашей системы. Тогда в логах должна быть информация об этом запросе. Именно её мы и извлекаем и добавляем на диаграмму:
Console.WriteLine($"{logs.ServiceAlias}->{anotherLogs.ServiceAlias}: {entity.GetPropertyValue(Names.RequestURLName)}");
Console.WriteLine($"activate {anotherLogs.ServiceAlias}");
PrintServiceLogs(boundaryClock);
Console.WriteLine($"{anotherLogs.ServiceAlias}->{logs.ServiceAlias}: ");
Console.WriteLine($"deactivate {anotherLogs.ServiceAlias}");Во-вторых, это может быть запрос к внешнему сервису. Тогда у нас в логах не будет никаких записей о его работе:
Console.WriteLine($"{logs.ServiceAlias}->External: {entity.GetPropertyValue(Names.RequestURLName)}");
Console.WriteLine($"activate External");
Console.WriteLine($"External->{logs.ServiceAlias}: ");
Console.WriteLine($"deactivate External");Вот и всё. Теперь можно вставить в соответствующее место Program.cs наш correlation id и запустить программу. Она выдаст нам описание, которое можно вставить в www.websequencediagrams.com:
Улучшения
Наша система построения диаграммы последовательности запроса готова. В заключение можно сказать пару слов о её дальнейшем совершенствовании.
Во-первых, я здесь ничего не сказал о сообщениях, посылаемых через очереди сообщений (RabbitMQ, Azure EventHub, ...). Обычно они позволяют передавать метаданные вместе с сообщениями, так что там тоже возможно передавать наши данные (correlation id, значение монотонных часов, ...). Поддержка очередей сообщений является естественным расширением нашего подхода.
Во-вторых, возможности www.websequencediagrams.com (по крайней мере в бесплатной версии) не очень велики. Мне бы, например, хотелось бы как-то визуально разделять различные типы записей в лог (Info, Warning, Error, ...). Возможно следует применить другой, более мощный инструмент для визуализации диаграмм последовательностей.
В-третьих, некоторые запросы осуществляются по принципу "отправил и забыл", т. е. их окончания никто не дожидается. Представлением таких запросов также нужно заняться.
Заключение
Вот и подошла к концу эта статья. Надеюсь, что она будет вам полезна и поможет разобраться, что же происходит в сложной системе. Удачи!
doriane
выглядит как велосипед, а чем распределенная трассировка плоха ? там можно смотреть граф запросов