Pull to refresh

Работаем с долгими API в ASP.NET Core правильно или тонкости переезда на новую платформу

Reading time 9 min
Views 19K
Microsoft очень постарался, создавая новую платформу для веб-разработки. Новый ASP.NET Core похож на старенький ASP.NET MVC только, быть может, самой MVC-архитектурой. Ушли сложности и привычные вещи из старой платформы, появился встроенный DI и легковесные view-компоненты, HTTP модули и хэндлеры уступили место middleware и т.д. Вкупе с кроссплатформенностью и хорошей производительностью всё это делает платформу очень привлекательной для выбора. В этой статье я расскажу, как мне удалось решить специфическую задачу логирования длительных запросов к сторонним API для повышения удобства анализа инцидентов.

Вместо вступления...


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

Формулировка задачи


Начну с того, что компания, где я работаю, занимается разработкой высоконагруженных сайтов. Приложения, над которыми на текущий момент мне удалось потрудиться, по своей большей части, являются неким прикрытым авторизацией интерфейсом доступа к внутренним АПИ заказчика. Логики там немного и она распределена примерно в равных пропорциях между frontend'ом и backend'ом. Большинство ключевой бизнес-логики лежит именно в этих АПИ, а сайты, видимые конечному клиенту, являются их консьюмерами.

Иногда получается так, что сторонние по отношению к сайту API отвечают на запросы пользователя весьма продолжительное время. Иногда это временный эффект, иногда постоянный. Так как приложения по природе своей — высоконагруженные, нельзя допустить, чтобы запросы пользователя находились в подвисшем состоянии долгое время, иначе это может грозить нам постоянно увеличивающимся количеством открытых сокетов, быстро пополняющуюся очередь не отвеченных запросов на сервере, а ещё — большим количеством клиентов, волнующихся и переживающих, почему их любимый сайт открывается так долго. С API мы ничего сделать не можем. И в связи с этим с очень давних времен у нас на балансировщике было введено ограничение на длительность выполнения запроса, равное 5 секундам. Это в первую очередь накладывает ограничения на архитектуру приложения, так как подразумевает ещё больше асинхронного взаимодействия, вследствие чего решает вышеописанную проблему. Сам сайт открывается быстро, а уже на открытой странице крутятся индикаторы загрузки, которые в конце концов выдадут какой-то результат пользователю. Будет это тем, что пользователь ожидает увидеть, или же ошибкой уже не играет большого значения, и это будет уже совсем другой историей…

Совсем другая история
hqdefault

Внимательный читатель заметит: но если ограничение стоит на все запросы, то оно ведь распространяется и на 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), значит должен быть какой-то другой способ это сделать.

image

Поковырявшись в исходниках 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-контейнере.

HttpContextPreserver

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 одновременных тасков, тест прошел успешно.

image

Кстати, благодаря архитектуре ASP.NET Core такие тесты можно писать легко и непринужденно. Нужно всего лишь запустить полноценный сервер внутри теста и обратиться к нему через настоящий сокет:

Инициализация сервера по URL
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 к этому стремится, и когда-нибудь (пусть может и не скоро) у них должно это получиться.

Ссылка на github
Tags:
Hubs:
+4
Comments 48
Comments Comments 48

Articles