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

    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
    Поделиться публикацией
    AdBlock похитил этот баннер, но баннеры не зубы — отрастут

    Подробнее
    Реклама
    Комментарии 48
    • +1
      SynchronizationContext'ом и HttpContext.Current в .NET Core

      System.Threading.SynchronizationContext в .NET Core никуда не делся и нормально поддерживается всей инфраструктурой TPL, включая async/await. Вот ASP.NET Core, да, свой контекст синхронизации больше не выставляет. Но он этого и на полном фреймворке не делает.

      • –1
        System.Threading.SynchronizationContext в .NET Core никуда не делся и нормально поддерживается всей инфраструктурой TPL, включая async/await.

        Хорошее замечание.


        Но он этого и на полном фреймворке не делает.

        Не делает. Сайт из примера крутится на полном фреймворке (Target Framework у него — .NET Framework 4.6.2).

      • 0
        Если мы подумаем, какие средства нам предоставляет фрэймворк для этих целей, то первым делом вспомним про CallContext с его LogicalSetData/LogicalGetData. [...] Внутри фрэймворка это реализуется с помощью паттерна, чем-то напоминающего Memento, который должны использовать все методы запуска нового потока/задачи

        Подождите, так надо обычному коду на .net core это писать, или нет? Я как-то привык думать (на основании той самой статьи Клири), что этот контекст двигается с нами автоматически.

        • –1

          Немного вас не понял. ExecutionContext двигается с нами, да. Но чтобы какую-то инфу двигать, нужно же вызывать как раз методы LogicalSetData/LogicalGetData.

          • 0

            Я вот про это:


            var ec = ExecutionContext.Capture();
            ...
            
            ExecutionContext.Run(ec, obj =>
            {
            ...
            }, state);

            Это в .net core нужно, чтобы ExecutionContext двигался?

            • 0

              Нет-нет, конечно. Это я показал как это внутри .NET реализовано. Т.е. это то, чем там оборачиваются наши вызовы Task.Run и т.п.

              • 0

                А, хорошо, а то я уже успел напугаться, что что-то важное отломали (из лучших побуждений, конечно же).

              • –1

                Из-за этой штуки в Akka.NET нет по-настоящему нативной поддержки тасков к акторам. Сохранение лишнего хлама в контексте приводит к серьёзным тормозам.

                • 0

                  Оу-воу, а можно с этого места поподробнее? Интересно и "нет нативной поддержки" (а то я там помню и асинки внутри таска, и PipeTo), и что именно с тормозами — они возникают из самого факта наличия ExecutionContext или из того, сколько конкретный программист туда данных положит?

                  • 0

                    Асинки внутри таска там сделаны костылями через остановку актора и/или стэш сообщений. Само ядро обработки очередей сообщений про асинхронность ничего не знает. Тормоза возникали из самого факта обращений к контексту, в который пытались запихнуть ActorContext. Единственный способом обойти эти ограничения и сделать так, чтобы не тормозило — отказаться от thread-local переменных, но они слишком много где используются.

                    • 0

                      Звучит печально, чего уж.

          • 0
            Вы не думали на тему использования инструментов типа Quartz.NET? И сохранять не HttpContext, ведь это абсолютно нелогично, так как задача у вас выполняется не в контексте запроса, значит копировать/сохранять/эмулировать его — будет большой обман, а тупо персистить информацию о полученном запросе, только то, что нужно, при создании задачи?
            • 0

              Quartz.NET — это планировщик задач, так? Тогда у меня получится то же самое, что и способ с сохранением ID из статьи, только здесь еще и добавляется внешний инструмент. Планировщики задач это нужная штука при больших задачах, требующих последовательности/консистентности. А при таких маленьких задачах, как получение данных о пользователе, я считаю, это лишнее. Насчет нелогичности — спорный момент. Запрос к АПИ начинается во время запроса пользователя к сайту. Здесь же выигрыш в том, что в логе мы видим сразу всю инфу, а не ковыряем разные источники в ее поисках.

              • 0
                Абсолютно ни одной предпосылки для того, чтобы момент можно было даже с огромным натягом назвать «спорным». Клиент сделал запрос к серверу, получил ответ. Всё что происходит до получение ответа — это обработка запроса. Клиент получил некий ID, и через некоторое время сделал ещё один запрос с этим ID, это уже другой запрос, другой контекст. Если вам так важно в логе видеть URL запроса, с которого была инициирована задача, привяжите её к ID, но эмулировать контекст запроса, которого ни по каким понятиям нет, это антипаттерн, введение в заблуждение и костыль, который здесь ничего не решает, только создаёт проблемы. Выигрыша никакого, вы просто смастерили костыль, который будет вводить людей в заблуждение. Так мне это видится :)
                • 0
                  Я вот тоже ни разу не понял зачем такой геморой, когда легко выделяется некоторый менеджер задач, в интерфейсе которого будет генерация задачи, получение её состояния, и вероятно её остановки и удаление из очереди. Так можно даже реализовать ограничение на одновременную обработку задач…
                  • 0

                    Значит, вы считаете, что лучше логировать информацию о запросе отдельно, логировать запрос/ответ от АПИ, а потом это всё сопоставлять вручную по идентификатору при инцидентах. Понятно :)

                  • 0
                    Насчёт кварца, вы зря пытаетесь оперировать величиной задач. У задачи есть контекст, который перситится, куда вы можете сохранить и ID и URL и всё остальное, выполнение задач отлично журналируется и управляются планировщиком, также можно масштабировать при необходимости, есть отдельный UI, в котором вы можете смотреть чего там сейчас происходит, чего отвалилось и почему. Огромная задача или нет, не имеет значения.
                  • 0
                    Советую ещё на Hangfire посмотреть — тоже весьма годный планировщик. К слову, есть порт под .NET Core. Имеет реализации хранилищ под разные СУБД, позволяет запускать таски на нескольких серверах, хранит всю историю, позволяет запускать и перезапускать таски вручную, из коробки имеет дашборд и интегрирован с DI. Единственный минус — синхронный API. Так что для вызова асинхронных методов — GetAwaiter().GetResult()
                    • Еще один минус — минимальный крон для задачи у Hangfire 1 минута. +- он раз в 15 секунд свое хранилище опрашивает.
                      • 0
                        он раз в 15 секунд свое хранилище опрашивает

                        Судя по документации, минимальный интервал — 1 секунда
                        • Это да, можно частоту опроса настроить вместо дефолтных 15 секунд в 1 секунду но минимальный крон один фиг 1 минута.
                  • 0
                    Извиняюсь за глупый вопрос, но важен мне для дальнейшего понимания (а хочется понять что такое CallContext, ExecutionContext, не пользовал, и что решает AKKA.NET, но застреваю раньше). Вы пишите: «Наверное, это первое, что только может прийти в голову. Мы генерируем GUID, логируем этот GUID еще до выхода из action'а и передаем его в сервис работы с API.»

                    Мне первое что пришло в голову — генерировать ГУИД еще на клиенте и передовать его со всеми запросами в хттп хеадере. В таком случае его и возвращать не надо. Умер запрос (пусть по таймауту, пусть по коду «ждите»), следующий запрос в цикле уже с тем же гуидом. Вопрос всего лишь в обертке js ajax методов. Почему это не работает?
                    • 0

                      Извиняюсь за поздний ответ. Увидел ваш комментарий только сейчас. Генерирование ID на клиенте в JS — дело не очень благодарное, ведь нужно гарантировать его уникальность — клиентов то у нас много. Во-вторых, клиентский JavaScript (я сейчас не про node.js) не предназначен для такого. Возможно, есть какие-то библиотечки для специфических задач, которые могут составлять GUID-подобные ID'шники, но я никогда не встречал такого (и не встречал тех, кто бы мог их использовать). В-третьих, разница между тем, что описываю я в статье, и тем, что описываете вы, всего лишь в том, что вы предлагаете генерировать ID на клиенте. Все остальное — ajax обертки и код "ждите" — остается ровным счетом таким же. Сервер также должен понимать эти ID и искать их в своем хранилище ответов, и логика их обработки никуда не исчезнет. А в таком случае стоит ли игра свеч?

                      • 0
                        Спасибо за ответ.
                        Все остальное — ajax обертки и код "ждите" — остается ровным счетом таким же
                        Если это о клиентской части то разве в вашем решении клиент не просто держит соединение? В моем решении — крутит запросы циклом, пока получает «ответ ждите» (возможно с подсказкой сколько секунд).

                        Что касается ID — ну можно сгенерировать на стороннем сервере предварительно (а можно и сотню и закешировать). Задержка? Да, но это доля секунды, а вообще разговор же идет значительно медленном основном запросе (десятки секунд).

                        В общем раз вы говорите что разница между решениям не большая, просто в вашем надо разобраться с внутренностями ASP.CORE а в моем нет — меня такой уровень понимания устроит. Случайному читателю порекомендую не разбираться, не то чтобы asp.core не заслуживает изучения, задача просто в статье решается не прямым способом (прямым — это correlation-token по месту создания запроса, т.е на клиенте). Но конечно каждый выбирает по себе. Слабая сторона: я так никогда и не узнаю что-такое CallContext, и ExecutionContext, а может это что-то важное…
                        • 0
                          Если это о клиентской части то разве в вашем решении клиент не просто держит соединение

                          Нет, конечно. В статье я как раз описываю, что так делать не получается в нашей инфраструктуре. Ограничение на запрос — 5 секунд.


                          В моем решении — крутит запросы циклом, пока получает «ответ ждите» (возможно с подсказкой сколько секунд).

                          У меня также и зацикливается запрос. И в качестве ответа "ждите" сначала приходит id, а потом код 204. Я совсем не эту задачу решаю в моей статье. Перечитайте еще раз. Решается задача логирования детальной информации о запросе пользователя, а не задача обработки запроса.

                          • 0
                            Извините, не понял сразу. Спасибо за терпение.

                            Это было из разряда не укладывается в голове: не понятно зачем «логгировать детали запроса», если запрос повторяется? Я выбрал гипотезу «ну значит не повторяется».
                            Перечитал. Теперь понял что вы стартуете таск с колбеком и когда колбек возвращатся все нормально работает, но в логах нет всей нужной информации (конекст занулен). Поэтому… вы восстанавливаете контекст, чтобы LoggerProvider имел что залогить.

                            Тогда суть критики меняется: то что называется «данные для разбора полетов» — это аудит, бизнес логика, а не трейсинг. Для аудита не надо использовать LoggerProvider. Если бы у вас была возможность отослать аудит сообщение из колбека явно, у вас бы не было всей этой сомнительной мороки с восстановлением контекста. Надежность, утечки, скорость, GC? Вы бы в колбек передали нужные строчки и оттуда их и залоггили бы. Не обижайтесь, вы продемонстрировали серый трюк, на фоне неправильной архитектуры. Хотя приобретенным знаниям по глубинам ASP.CORE я завидую.

                            • 0
                              вы восстанавливаете контекст, чтобы LoggerProvider имел что залогить.

                              Контекст не восстанавливается при вызове колбека (я говорю только про свой код сейчас). Контекст сохраняется до вызова метода АПИ. Дальше за меня всю работу делает AsyncLocal (т.е. .NET).


                              Надежность, утечки, скорость, GC?

                              Надежность я проверил на "функционально-нагрузочном" тесте. Все отработало как часы. Исходники теста на гитхабе. Утечек памяти не будет так как это управляемый код (я понимаю, что можно назвать утечкой, когда создаются очень много объектов, с которыми потом мучается GC, но это не мой кейс). Та дельта скорости, которой я жертвую, "бесконечно" мала по сравнению со временем выполнения запроса. GC тоже много лишней работы не проделает, так как те новые пять-десять объектов создаются только при вызове АПИ, а с учетом .NET графа в GC объектов для обработки становится еще меньше.


                              Вы бы в колбек передали нужные строчки и оттуда их и залоггили бы

                              Не понимаю вас. Про какие строчки идет речь? Можете пояснить на более живом примере, используя async-await?

                              • 0
                                Извиняюсь за скороспелые выводы, но так работают мозги. Должна быть «рабочая гипотеза».

                                Теперь понял, вы просто нашли как NLOGу подсунуть частично клонутый HttpContext. Это выглядит в разы безопасней чем представлялось. Но на вопрос кто что об этом думает, отвечаю так же. Я думаю: «аудит логгить надо явно». Понимаю что готовое решение убедительней моего мнения (основанного на требованиях к гибкости решения — если регулярно используется — нужно будет регулярно улучшать).

                                Под «собрать строчки»я имел ввиду просто передать колбеку параметры со значениями нужными вам в логе ${aspnet-mvc-controller}/${aspnet-mvc-action} и т.п. В колбеке был бы явный вызов logger.Log в нужный вам таргет со всем этим добром.

                                А можно спросить еще, NLog уже умеет через appsettigns.json конфигурироваться?
                                • 0
                                  Под «собрать строчки»я имел ввиду просто передать колбеку параметры со значениями нужными вам в логе ${aspnet-mvc-controller}/${aspnet-mvc-action}

                                  А вот теперь мой любимый вопрос… А что если вы должны будете переиспользовать этот же самый сервис или провайдер данных (с колбеком) в приложении совсем никак не связанном с MVC архитектурой? Не будет там action'ов, контроллеров и т.п. Насколько теперь кажется хорошей идея вынести параметры action-controller в метод интерфейса данного сервиса?


                                  NLog уже умеет через appsettigns.json конфигурироваться?

                                  Пока еще нет: https://github.com/NLog/NLog/issues/1588. Ребята очень заняты и трудятся над новым релизом :)

                                  • 0
                                    Не понял дважды. Во первых у явного аудита — явный формат, и будет в сообщении поле «место вызова» — его не может не быть. Туда и положите контроллер с акшином. А не при МВЦ другой идентификатор места вызова.
                                    Во-вторых колбек почему-то в «провайдер данных» уложили…
                                    Давайте не сводить меня с ума и колбек вне провайдера оставим.

                                    var controllerText = «myController»;
                                    return Task.Factory.StartNew(
                                    {
                                    // API call
                                    }
                                    ).ContinueWith(()=>{ logger.Log(«bla,bla» + controllerText )});

                                    • 0
                                      Давайте не сводить меня с ума

                                      Вы предлагаете вам не отвечать?)


                                      Во-вторых колбек почему-то в «провайдер данных» уложили…

                                      Это не я, а компилятор так разбивает метод, помеченный как async. Давайте все-таки уйдем с абстрактного понятия колбэк и перейдем на общепринятые async-await. Так мне будет легче вас понять.


                                      поле «место вызова»… Туда и положите контроллер с акшином. А не при МВЦ другой идентификатор места вызова

                                      Можно придумывать таких "мега-универсальных" полей тысячи и потом долго вспоминать, что там для чего, а потом еще дольше объяснять новым членам по команде, что куда нужно пихать и в каких случаях.


                                      ContinueWith(()=>{ logger.Log(«bla,bla» + controllerText )});

                                      Я еще раз хочу заметить, что основной моей целью было залогировать запрос-ответ от АПИ. Если вы вместо "bla,bla" как раз и имеете в виду запрос-ответ, то было бы здорово услышать от вас подробное объяснение, как именно вы хотите их вытаскивать вне провайдера, т.е. внутри frontend-приложения (с учетом моей просьбы про async выше).

                    • 0
                      Спасибо за ответы. Поскольку я фрилансер, мне сильно не хватает информации «как это у других» (точнее я вижу как у других — и сильно огорчаюсь — а получить разъяснения — вот
                      этого не получается совсем).

                      Вот более детальный код:

                          public class DefaultController : Controller
                          {
                              public IActionResult Index()
                              {
                                  var queryString = this.HttpContext.Request.GetDisplayUrl();
                                  Task.Factory.StartNew(
                                          () =>  System.Threading.Thread.Sleep(4000)
                                      ).ContinueWith(
                                          (notused) => Console.WriteLine($"API finishing: {queryString}")
                                  );
                                  Console.WriteLine("HTTP finishing");
                                  return Content(Guid.NewGuid().ToString()); 
                              }
                          }


                      Не понятно почему async await становится особенным условием — это же наш контроллер, если необходимо то ставим, если не обязательно — то не ставим. Я опущу просто потому что здесь не обязательно.

                      Ответ трейсера содержит
                      info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
                      Request finished in 99.6118ms 200 text/plain; charset=utf-8
                      API finishing: localhost:50527/Default

                      вот есть информация о реквесте на коллбеке. что я упускаю?
                      • 0

                        Подождите, вы меня не понимаете почему-то. Где у вас логируется запрос/ответ от АПИ. Т.е. сейчас вы логируете только query string, controller и action. А где полный текст HTTP запроса и ответа (или хотя бы его тело)? Мне не нужен код, расскажите просто принцип, как и где вы будете отлавливать эту информацию и куда сохранять для будущего логирования. Т.е. задача — сопоставить данные, которые вы сейчас залогировали, с запросом к АПИ (пусть для простоты это будет REST интерфейс)

                      • 0
                        Я не понимаю потому что вижу кучу противоречий и мечусь между ними.

                        ${longdate}|${event-properties:item=EventId.Id}|${logger}|${uppercase:${level}}|${aspnet-mvc-controller}/${aspnet-mvc-action}| ${message} (${callsite}:${callsite-linenumber})| url:${aspnet-request-url}

                        т.е.

                        2017-10-08 20:29:34.3322|0|AspNetCoreApp.Services.LongRespondingService|TRACE|Home/Test| DoJob method is ending (AspNetCoreApp.Services.LongRespondingService+d__3.MoveNext:0)| url:http://localhost/Test/1

                        А теперь возник httpresponce.body… Где в вашем решении боди?
                        А потом мне надо будет понять что такое «сопоставить данные» залогировать httpresponce.body вместе с сообщением finishing…? Так в body лежит GUID, я его и так явно залогировать могу… Для нужд аудита — достаточно. Залогировать что-то что вернет API вместе — ну какие проблемы? А что это в вашем примере? Да не важно переношу операцию логгинга прямо за операцией вызова (и удаляю «явный коллбек т.е. continueWith») — все будет работать. Любые поля из реквеста. А респонс — ну не знаю, что там нужно то тоже можно. Но я в вашем NLOG шаблоне не вижу нчи
                        • 0
                          Наверное надо задать промежуточный вопрос: «а как вы сопоставляете данные, которые мы залогировали (displayUrl), с запросом к АПИ »? Из конфигурации форматера не видно. А если где и скзалаи, то у меня блокируются мозги уже потому что в форматере то и не видно, а сопоставлять вы ставите задачу именно им сформированное сообщение.

                          • 0

                            У меня запрос-ответ логируется через основное сообщение (в конфигурации за это отвечает ${message}), которое я отправляю в логгер. Запрос-ответ я с легкостью могу получить в самом методе провайдера данных, так как именно из него я отправляю запрос к АПИ. Именно оттуда я их и логирую вместе с данными из HttpContext'а. А вот как вы планируете получать данную информацию вне провайдера данных в "колбэке" можно только догадываться. Должно быть, в момент исполнения делегата в ContinueWith вы должны получить недавно исполненный запрос (а может и несколько запросов) и всю сопутствующую ему информацию из какого-то хранилища...

                            • 0
                              Чуть чуть повторюсь. Вот ваш результат, вы им довольны.

                              2017-10-08 20:29:34.3322|0|AspNetCoreApp.Services.LongRespondingService|TRACE|Home/Test| DoJob method is ending (AspNetCoreApp.Services.LongRespondingService+d__3.MoveNext:0)| url:http://localhost/Test/1

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

                              Видимо вы не возвражаете, но начинаете говорить о том что надо «сопоставить сообщения из контроллера с сообщениями из провайдера».
                              Я могу предположить что под «сопоставить» вы хотите иметь законную возможность «каждую сессию — в отдельный файл (и сообщение MVC Controllerа и провайдера)» — это логично, но по скольку у вас у самого такого решения нет — то я зависаю.
                              Другое предоположение вы хотите иметь чтобы все сообщения одной сессии были залогены с каким-то общим correlation token'ом по которому можно их отобрать. Опять же у вас самого такого решения нет, опять зависаю.

                              Как бы я сам решал?

                              public class DefaultController : Controller
                                  {
                                      public IActionResult Index(Reqest request)
                                      {
                                          Guid correlationToken = Guid.NewGuid().ToString();
                                          logger.Log($"API starting {correlationToken}, {request}");
                                          var queryString = this.HttpContext.Request.GetDisplayUrl();
                                          Task.Factory.StartNew(
                                                  () =>  {
                                                                dataProvider.AuditOnResult = (msg)=>{
                                                                                             logger.Log($"API finishing: {correlationToken}, {msg}")
                                                                                    };
                                                                dataProvider.Start(request);
                                                                logger.Log($"API finishing: {correlationToken}, {queryString}")
                                                             }
                                          );
                                           logger.Log("HTTP session finishing {correlationToken}");
                                          return Content(correlationToken); 
                                      }
                                  }


                              • 0

                                Решение есть. Я вам его рассказал.


                                У вас ошибка в вашем коде. Код будет работать пока к серверу обращается всего один клиент (и то не всегда). Никто не гарантирует, что таска будет выполняться в экслюзивном режиме. Если начнут выполняться одновременно две таски, то неизвестно какой делегат в вашем свойстве AuditOnResult останется жить, а какой затрется другим. Я даже знаю, какое будет ваше следующее решение — создавать dataProvider создается каждый раз новый при очередном запросе. Я не буду даже упомянать про GC и производительность (хотя вы кстати говорили об этом в вашем комментарии выше). Подумайте хотя бы, что будет, если вам нужно будет сделать некоторое преобразование данных в слое бизнес-логики. dataProvider будет вызываться из другого сервиса, а не из контроллера, как сейчас. Вам придется прокидывать ваш AuditOnResult глубже и глубже и делать это для каждого сервиса.

                                • 0
                                  Вступление: это не ошибка конечно dataProvider в моем коде — transient.
                                  А если сервис удаленный то и решение будет другим (без передачи делегата), а именно каждое аудит сообщение будет логится с нашим corellation tokenом (в нашем случае пойдет и тот самый GUID ожидания), по нему впоследствии всё и свяжем. Я не вижу тут никакой проблемы.

                                  Но пусть будет сервис не удаленный, а работающий в нашем процессе, «доступный из контейнера».
                                  Не просто не вижу проблемы в «придется прокидывать ваш AuditOnResult глубже и глубже» — а считаю возможность прокидывать (конечно не AuditOnResult, а контейнер созданный для конретной сессии с которого можно получить AuditOnResult) важнейшим признаком архитектуры здорового человека. Прокидывать не через interface кончено (т.е. уродовать API не будет) а через реализации.
                                  Получив AuditOnResult инициированный correlationTokenом я буду логить весь аудит из сервиса вместе с correlationTokenом даже не зная значения correlationToken — поскольку в сервисе получаю лишь обертку созданную для конкретной сессии.

                                  Но вернемся еще назад, я не понял как же вы связываете

                                  2017-10-08 20:29:34.3322|0|AspNetCoreApp.Services.LongRespondingService|TRACE|Home/Test| DoJob method is ending (AspNetCoreApp.Services.LongRespondingService+d__3.MoveNext:0)| url:http://localhost/Test/1

                                  с сообщениями из providerа. В этом вашем примерном сообщении нет ничго что может связать. Нет GUIDа. А возможности конфигурации NLOG не позволяют кидать все сообщения и контролера и провайдера «в файл per session». Или нет?

                                  Больше у меня вопросов не будет.
                                  • 0

                                    Роман, это и есть сообщение из провайдера: DoJob method is ending


                                    Посмотрите уже, наконец, код на гитхабе: https://github.com/Dobby007/aspnetcore-longtask/blob/master/AspNetCoreApp/Services/LongRespondingService.cs


                                    Да и в сообщении же явно видно откуда оно логируется: AspNetCoreApp.Services.LongRespondingService+d__3.MoveNext


                                    Вы, мне кажется, совсем не поняли, о чем идет речь в статье.


                                    Прокидывать не через interface кончено (т.е. уродовать API не будет) а через реализации.

                                    Т.е. вы считаете нормальным, когда сервисы у вас зависят от конкретных реализаций других сервисов, а не их интерфейсов. Ну ок… После этого я считаю, что следующий выпад в мою сторону вообще комментировать не нужно:


                                    считаю возможность прокидывать… контейнер созданный для конретной сессии… важнейшим признаком архитектуры здорового человека

                                    Откровенно говоря, я даже и не понял, про какой контейнер вы говорите

                        • 0
                          «Здоровый человек» — это мем (легкие курильщика), я не хотел вас напрячь, приношу извинения.

                          Как не странно мне вас убеждать что вы «не связали», но это именно так. По крайней мере для нужд разбора полетов «урл» недостаточно, нужна связь со всем запросом пользователя, по этому я и бился как рыба об лед: где тут связь с конкретным запросом, где тут коррелайшн токен. Use case разбора полетов: «клиент на запросе поймал ошибку — автоматом выслал коррелайшн токен своего запроса, бекофис сформировал тикет со всеми сообщениями из логов (всех логов, всех сервисов включая удаленные) для этого запроса (отобрав по коррелайшн токену)». В вашей архитектуре такого нет и легко реализовать не получится (где гибкость?). Моя оценка: не только архитектурное решение несовершенно, но и если это считается «а мы связали» — задача аудита понята не правильно.

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

                          Под контейнером я имел ввиду DI контейнер. DI контейнер не обязан быть глобальным и а может быть per session, и может вполне передаваться по стеку. Он не становится при этом service locator'ом поскольку service locator, по крайней мере тот который ругают, это глабальная переменная, тут же это просто «DI конейнер передаваемый по стеку». Это вообще абсолютно нормально — DI контейнер это «еще один сервис» — что тут такого где в архитектуре где «всё сервис». Ничто не мешает передававть IServiceCollection (DI контейнер) ИЛИ ЕГО ВРАПЕР в controller через constructor injection и уже из него запрашивать нужные сервисы, сервис выдающий сервисы.

                          Ни одна реализация сервиса при этом не будет зависить от других реализаций, но будут зависеть от контейенра.

                          Пример

                          public interface IContainer{
                            IAuditService GetAuditService();
                            IMyService GetMyService();
                          }
                          
                          // можно и дженерик, строго говоря нет причин иметь универсальных дженерик контейнеры  вроде
                          //public interface IContainer<T>{
                          //  T GetService();
                          //}
                          
                          public class Container: IContainer{
                            public Container(Guid correlationToken){
                            }
                            public IAuditService GetAuditService(){ 
                              return new AuditService(correlationToken)
                            }
                            public IMyService GetMyService(){ 
                              return new MyService(GetAuditService()); // DI как он есть
                            }
                          }
                          
                          public interface IAuditService {
                           void Log(string message);
                          }
                          
                          public class AuditService: IAuditService {
                            Guid correlationToken;
                            public void AuditService(Guid correlationToken) =>  this.correlationToken=correlationToken;
                            public void Log(string message)=> Console.WriteLine($" {correlationToken} "+ message);
                          
                          }
                          
                          public class MyService: IMyService{
                              IAuditService auditService 
                              MyService(IContainer container){
                                 this.auditService =container.GetAuditService();
                                auditService.Log("bla bla"); // будет залогено вместе с correlation token
                              }
                          }
                          


                          По ассемблям/слоям: 1) IMyService, IAuditService 2) IContainer (ссылается на 1) 3) MyService, AuditService (ссылается на 1 и 2) 4) Container (ссылается на 1 2 3) — контейнер должен знать всех. При этом ASP.CORE проект линкуется только с 1) 2) 4) но не с три (не с реализациями сервисов).

                          Я чувствую что это плохо оформленно а плохо оформленное злит. Значит закончу тоже извинением.
                          • 0
                            В вашей архитектуре такого нет и легко реализовать не получится (гибкость?). Моя оценка: не только архитектурное решение несовершенно

                            Не делайте поспешных выводов. Можно просто поместить этот ваш correlation token в HttpContext.Items и логировать его вместе с url с помощью специального layout renderer'а. Или можно логин пользователя туда добавлять. Собственно говоря, можно сделать, что угодно, было бы желание делать и понять.


                            DI контейнер не обязан быть глобальным и а может быть per session

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


                            Кроме того, вам придется изобрести велосипед механизм для добавления ваших сервисов в режиме "per session", поскольку ASP.NET Core такого режима не поддерживает.

                          • 0

                            [Комментарий удален, ответил выше]

                            • 0
                              Кроме того, вам придется изобрести велосипед механизм для добавления ваших сервисов в режиме «per session», поскольку ASP.NET Core такого режима не поддерживает.


                              А его не надо поддерживать в ASP.NET, точка входа — на например вызов action контроллера. Тут создал контейнер и далее «пропихиваешь его внутрь», через конструкторы сервисов. Тут нет никакого велосипеда чистое и ясное «функциональное» программирование если хотите. Вроде node'ы.
                              • 0

                                Предлагаю закончить данную дискуссию. Ваш аргумент, что мое решение не гибкое я опроверг. Ваше решение я комментировать не буду по понятным причинам.

                                • –1
                                  Можно просто поместить этот ваш correlation token в HttpContext.Items
                                  — соглашусь.
                                  В этом случае вам придется выдавать тот же самый идентификатор сессии,
                                  — не соглашусь. correlation token может задаваться хоть в броузере, и потом передваться по всем серверам. не
                                  придется выдавать тот же самый
                                  — а цель такая использовать тот же самый по всему жизненному циклу запроса на всех серверах.

                                  да, он часть интерфейса систем и может портить бизнес api используемый между системами (хотя не всегда, например в запросе от токена может передаваться через хидер, когда логика — через запрос). однако когда аудит — это действительно требование (а не нужда девелопера — трейсинга), он становится частью спецификации а значит вполне заслуживает упоминания в межсетевых интерфейсах.

                                  вообще correlation token не мой books.google.lt/books?id=qqB7nrrna_sC&pg=PA165&lpg=PA165&dq=correlation+token+pattern&source=bl&ots=57keILj-x3&sig=kjU_rPtc_ouh6u5WVGkgBmkqGCM&hl=en&sa=X&ved=0ahUKEwiNv-_085HYAhVIJ1AKHRrICmoQ6AEIPDAD#v=onepage&q=correlation%20token%20pattern&f=false
                                  • 0

                                    Даже в начале главы книги, которую вы привели в качестве примера, говорится, что correlation token используется в асинхронных методах общения клиента и сервера (в очередях). Протокол HTTP — синхронный. Здесь не нужно сопоставлять запрос и ответ между браузером и сервером. Собственно, там так и написано прямым текстом только про старый RPI:


                                    image

                                    • –1
                                      Большое спасибо за вопроас! Здесь асинхронность в том что сообщения в логах просматриваются независимо не синхронно к процессу запроса (у вас человеком, но вообще это может и должно быть автоматизированно «собери мне все сообщения с этим токеном»). There is no confusion about which call produced given result — ключевое. У вас была confusion (и по хорошему остается пока недобавили GUID в HttpContext.Items). Вы ее решили забавным трюком, хотя по простому это решается тем что каждое сообщение в лог добавляется с correlation token'ом (который надо передавать конечно, между службами, между удаленными явно, между теми что получаются из DI — не явно вводя IoC container per request — там в IoC container е и будет жить метод лога который логит все время вставляя correlation token).

                                Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.