Microsoft очень постарался, создавая новую платформу для веб-разработки. Новый ASP.NET Core похож на старенький ASP.NET MVC только, быть может, самой MVC-архитектурой. Ушли сложности и привычные вещи из старой платформы, появился встроенный DI и легковесные view-компоненты, HTTP модули и хэндлеры уступили место middleware и т.д. Вкупе с кроссплатформенностью и хорошей производительностью всё это делает платформу очень привлекательной для выбора. В этой статье я расскажу, как мне удалось решить специфическую задачу логирования длительных запросов к сторонним API для повышения удобства анализа инцидентов.
Вместо вступления...
В дипломах и диссертациях где-то в начале обычно должна формулироваться проблема. Но то, что я опишу ниже, скорее даже не проблема, а стремление сделать приложение юзабельнее и окружающий мир немножечко прекраснее. Это один из тех моментов в моей жизни, где я спрашиваю себя, а можно ли сделать лучше? А после этого пытаюсь найти способы это сделать. Иногда у меня это получается, иногда я понимаю, что сделать лучше либо невозможно, либо на это стоит затратить столько усилий, что это в конечном итоге потеряет всякий смысл. В конце концов, это не перевернет мир и не решит проблему бедности на планете не то, на что стоит тратить свои силы и время. Но так или иначе, я получаю из этого какой-то опыт, который не может не пригодиться в будущем. В этой статье я опишу то, что мне кажется, у меня получилось сделать лучше.
Формулировка задачи
Начну с того, что компания, где я работаю, занимается разработкой высоконагруженных сайтов. Приложения, над которыми на текущий момент мне удалось потрудиться, по своей большей части, являются неким прикрытым авторизацией интерфейсом доступа к внутренним АПИ заказчика. Логики там немного и она распределена примерно в равных пропорциях между frontend'ом и backend'ом. Большинство ключевой бизнес-логики лежит именно в этих АПИ, а сайты, видимые конечному клиенту, являются их консьюмерами.
Иногда получается так, что сторонние по отношению к сайту API отвечают на запросы пользователя весьма продолжительное время. Иногда это временный эффект, иногда постоянный. Так как приложения по природе своей — высоконагруженные, нельзя допустить, чтобы запросы пользователя находились в подвисшем состоянии долгое время, иначе это может грозить нам постоянно увеличивающимся количеством открытых сокетов, быстро пополняющуюся очередь не отвеченных запросов на сервере, а ещё — большим количеством клиентов, волнующихся и переживающих, почему их любимый сайт открывается так долго. С API мы ничего сделать не можем. И в связи с этим с очень давних времен у нас на балансировщике было введено ограничение на длительность выполнения запроса, равное 5 секундам. Это в первую очередь накладывает ограничения на архитектуру приложения, так как подразумевает ещё больше асинхронного взаимодействия, вследствие чего решает вышеописанную проблему. Сам сайт открывается быстро, а уже на открытой странице крутятся индикаторы загрузки, которые в конце концов выдадут какой-то результат пользователю. Будет это тем, что пользователь ожидает увидеть, или же ошибкой уже не играет большого значения, и это будет уже совсем другой историей…
Внимательный читатель заметит: но если ограничение стоит на все запросы, то оно ведь распространяется и на AJAX-запросы тоже. Все правильно. Я вообще не знаю способа отличить AJAX-запрос от обычного перехода на страницу, 100% работающего во всех случаях. Поэтому долгие AJAX-запросы реализуются по следующему принципу: с клиента мы делаем запрос на сервер, сервер создает Task и ассоциирует с ним определенный GUID, затем возвращает этот GUID клиенту, а клиент получает результат по данному GUID, когда он придет на сервер от API. На этом этапе мы почти подобрались к сути моей надуманной проблемы задачи.
Все запросы и ответы к этим API мы должны логировать и хранить для разбора полетов, а из логов мы должны получать максимум полезной информации: вызванный action/controller, IP, URI, логин пользователя и т.д. и т.п. Когда же я в первый раз с помощью NLog'а залогировал свой запрос/ответ в моем ASP.NET Core приложении, то в принципе я не удивился, увидев в ElasticSearch что-то вроде:
2017-09-23 23:15:53.4287|0|AspNetCoreApp.Services.LongRespondingService|TRACE|/| DoJob method is starting (AspNetCoreApp.Services.LongRespondingService.DoJob:0)| url:http:///
В то же время в конфигурации NLog все выглядело достаточно правильно и в качестве layout было установлено следующее:
${longdate}|${event-properties:item=EventId.Id}|${logger}|${uppercase:${level}}|${aspnet-mvc-controller}/${aspnet-mvc-action}| ${message} (${callsite}:${callsite-linenumber})| url:${aspnet-request-url}
Проблема здесь в том, что ответ от API приходит уже после окончания выполнения запроса клиентом (ему то возвращается всего лишь GUID). Вот тут то я и начал думать о возможных способах решения этой проблемы…
Возможные решения проблемы
Конечно, любую проблему можно устранить несколькими способами. Причем забить на нее — тоже один из приёмов, которым иногда не стоит пренебрегать. Но поговорим всеж-таки о реальных способах решения и их последствиях.
Передавать ID задачи в метод обращения к API
Наверное, это первое, что только может прийти в голову. Мы генерируем GUID, логируем этот GUID еще до выхода из action'а и передаем его в сервис работы с API.
Проблемы этого подхода — очевидны. Мы должны передавать этот ID в абсолютно все методы обращения к сторонним API. При этом, если мы захотим переиспользовать данный кусочек где-то еще, где такая функциональность не требуется, то нам это очень сильно будет мешать.
Ситуация усугубляется, если перед отдачей данных клиенту, мы хотим их каким-то образом обработать, упростить или агрегировать. Это относится к бизнес-логике и ее следует вынести в отдельный кусочек. Получается, что этот кусочек, который должен оставаться максимально независимым, будет тоже работать с этим идентификатором! Так дела не делаются, поэтому рассмотрим другие способы.
Сохранить ID задачи в CallContext
Если мы подумаем, какие средства нам предоставляет фрэймворк для этих целей, то первым делом вспомним про CallContext с его LogicalSetData/LogicalGetData. Используя эти методы, можно сохранить ID задачи в CallContext'e, а .NET (лучше сказать, .NET 4.5) сам позаботится о том, чтобы новые потоки автоматически получили доступ к этим же данным. Внутри фрэймворка это реализуется с помощью паттерна, чем-то напоминающего Memento, который должны использовать все методы запуска нового потока/задачи:
// Перед запуском задачи делаем snapshot текущего состояния
var ec = ExecutionContext.Capture();
...
// Разворачиваем сохраненный snapshot в новом потоке
ExecutionContext.Run(ec, obj =>
{
// snapshot на этом этапе уже развернут, поэтому здесь вызывается уже пользовательский код
}, state);
Теперь когда мы знаем, как сохранить ID, а затем получить его в нашей task'е, мы можем в каждое наше логируемое сообщение, включить этот идентификатор. Можно сделать это непосредственно при вызове метода логирования. Или, чтобы не засорять слой доступа к данным, можно использовать возможности вашего логгера. В NLog, например, есть Layout Renderers.
Также в крайнем случае можно написать свой логгер. В ASP.NET Core всё логирование осуществляется с помощью специальных интерфейсов, расположенных в пространстве имен Microsoft.Extensions.Logging, которые внедряются в класс посредством DI. Поэтому нам достаточно реализовать два интерфейса: ILogger и ILoggerProvider. Думаю, такой вариант может оказаться полезным, если ваш логгер не поддерживает расширения.
А чтобы все получилось так, как надо, рекомендую ознакомиться со статьей Stephen'а Cleary. В ней нет привязки к .NET Core (в 2013 году его просто-напросто еще не было), но что-то полезное для себя там точно можно подчеркнуть.
Недостаток данного подхода в том, что в лог будут попадать сообщения с идентификатором и чтобы получить полную картину нужно будет искать HTTP-запрос с этим же ID. Про производительность я промолчу, так как, даже если и будет какая-та просадка, то по сравнению с другими вещами это будет казаться несоизмеримо малым значением.
А что, если подумать, почему это не работает?
Как я уже говорил, в лог к нам сыпятся сообщения вида:
2017-09-23 23:15:53.4287|0|AspNetCoreApp.Services.LongRespondingService|TRACE|/| DoJob method is starting (AspNetCoreApp.Services.LongRespondingService.DoJob:0)| url:http:///
Т.е. все, что связано с IHttpContext просто зануляется. Оно вроде как и понятно: выполнение запроса то закончилось, поэтому NLog и не может получить данные, т.е. ссылки на HttpContext просто уже нет.
Наконец-то, я решил посмотреть, а как собственно NLog получает ссылку на HttpContext вне контроллера. Так как с SynchronizationContext'ом и HttpContext.Current в .NET Core было покончено (да, это снова Stephen Cleary), значит должен быть какой-то другой способ это сделать.
Поковырявшись в исходниках NLog, я нашел некий IHttpContextAccessor. Жажда понять, что все таки здесь происходит, заставила меня снова залезть в GitHub и посмотреть, что же представляет из себя эта магическая штука с одним свойством. Оказалось, что это просто абстракция над AsyncLocal, который по сути является новой версией LogicalCallContext (те самые методы LogicalSetData / LogicalGetData). Кстати, для .NET Framework'а так было не всегда.
После этого я задал себе вопрос: а почему собственно тогда это не работает? Мы запускаем Task стандартным способом, никакого неуправляемого кода тут нет… Запустив дебаггер, чтобы посмотреть, что происходит с HttpContext в момент вызова метода логирования, я увидел, что HttpContext есть, но свойства в нем все обнулены за исключением Request.Scheme, которое в момент вызова равно «http». Вот и получается, что в логе у меня вместо урла — странное "http:///".
Итак, получается, что в целях повышения производительности ASP.NET Core где-то внутри себя обнуляет HttpContext'ы и переиспользует их. Видимо, такие тонкости вкупе и позволяют достичь значительного преимущества по сравнению со стареньким ASP.NET MVC.
Что же я мог с этим сделать? Да просто сохранить текущее состояние HttpContext'а! Я написал простой сервис с единственным методом CloneCurrentContext, который я зарегистрировал в DI-контейнере.
public class HttpContextPreserver : IHttpContextPreserver
{
private readonly IHttpContextAccessor _httpContextAccessor;
ILogger _logger;
public HttpContextPreserver(IHttpContextAccessor httpContextAccessor, ILogger<HttpContextPreserver> logger)
{
_httpContextAccessor = httpContextAccessor;
_logger = logger;
}
public void CloneCurrentContext()
{
var httpContext = _httpContextAccessor.HttpContext;
var feature = httpContext.Features.Get<IHttpRequestFeature>();
feature = new HttpRequestFeature()
{
Scheme = feature.Scheme,
Body = feature.Body,
Headers = new HeaderDictionary(feature.Headers.ToDictionary(kvp => kvp.Key, kvp => kvp.Value)),
Method = feature.Method,
Path = feature.Path,
PathBase = feature.PathBase,
Protocol = feature.Protocol,
QueryString = feature.QueryString,
RawTarget = feature.RawTarget
};
var itemsFeature = httpContext.Features.Get<IItemsFeature>();
itemsFeature = new ItemsFeature()
{
Items = itemsFeature?.Items.ToDictionary(kvp => kvp.Key, kvp => kvp.Value)
};
var routingFeature = httpContext.Features.Get<IRoutingFeature>();
routingFeature = new RoutingFeature()
{
RouteData = routingFeature.RouteData
};
var connectionFeature = httpContext.Features.Get<IHttpConnectionFeature>();
connectionFeature = new HttpConnectionFeature()
{
ConnectionId = connectionFeature?.ConnectionId,
LocalIpAddress = connectionFeature?.LocalIpAddress,
RemoteIpAddress = connectionFeature?.RemoteIpAddress,
};
var collection = new FeatureCollection();
collection.Set(feature);
collection.Set(itemsFeature);
collection.Set(connectionFeature);
collection.Set(routingFeature);
var newContext = new DefaultHttpContext(collection);
_httpContextAccessor.HttpContext = newContext;
}
}
public interface IHttpContextPreserver
{
void CloneCurrentContext();
}
Я не использовал deep cloner, так как это добавило бы тяжелую рефлексию в проект. А нужно это мне всего в одном единственном месте. Поэтому я просто создаю новый HttpContext на базе существующего и копирую в него только то, что будет полезно увидеть в логе при анализе инцидентов (action|controller, url, ip и т.п.). Копируется не вся информация.
Теперь запустив приложение, я увидел примерно следующие счастливые строчки:
2017-10-08 20:29:25.3015|0|AspNetCoreApp.Services.LongRespondingService|TRACE|Home/Test| DoJob method is starting (AspNetCoreApp.Services.LongRespondingService.DoJob:0)| url:http://localhost/Test/1
2017-10-08 20:29:34.3322|0|AspNetCoreApp.Services.LongRespondingService|TRACE|Home/Test| DoJob method is ending (AspNetCoreApp.Services.LongRespondingService+<DoJob>d__3.MoveNext:0)| url:http://localhost/Test/1
А это означало для меня маленькую победу, которой я и делюсь здесь с вами. Кто что об этом думает?
Чтобы удостовериться, что я ничего себе не надумал ложного, я написал маленький функционально-нагрузочный тест, который можно найти в моем репозитории на github'е вместе с сервисом. При запуске 5000 одновременных тасков, тест прошел успешно.
Кстати, благодаря архитектуре ASP.NET Core такие тесты можно писать легко и непринужденно. Нужно всего лишь запустить полноценный сервер внутри теста и обратиться к нему через настоящий сокет:
protected TestFixture(bool fixHttpContext, string solutionRelativeTargetProjectParentDir)
{
var startupAssembly = typeof(TStartup).Assembly;
var contentRoot = GetProjectPath(solutionRelativeTargetProjectParentDir, startupAssembly);
Console.WriteLine($"Content root: {contentRoot}");
var builder = new WebHostBuilder()
.UseKestrel()
.UseContentRoot(contentRoot)
.ConfigureServices(InitializeServices)
.UseEnvironment(fixHttpContext ? "Good" : "Bad")
.UseStartup(typeof(TStartup))
.UseUrls(BaseAddress);
_host = builder.Build();
_host.Start();
}
Еще один довод к использованию ASP.NET Core в своих проектах.
Итоги
Мне очень понравился ASP.NET Core во всех аспектах его реализации. В нем заложена большая гибкость и одновременно лёгкость всей платформы. За счет абстракций для абсолютно всей функциональности можно делать любые вещи и настраивать всю платформу под себя, свою команду и свои методы разработки. Кроссплатформенность пока не доведена до совершенства, но Microsoft к этому стремится, и когда-нибудь (пусть может и не скоро) у них должно это получиться.
Автор: Александр Гилевич
