Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

At random intervals the application fails to set RouteValues #41924

Closed
1 task done
okolvik-avento opened this issue May 30, 2022 · 44 comments
Closed
1 task done

At random intervals the application fails to set RouteValues #41924

okolvik-avento opened this issue May 30, 2022 · 44 comments
Assignees
@davidfowl
Labels
area-mvc Includes: MVC, Actions and Controllers, Localization, CORS, most templates External This is an issue in a component not contained in this repository. It is open for tracking purposes. feature-routing ✔️ Resolution: Fixed The bug or enhancement requested in this issue has been checked-in!
Milestone
.NET 7 Planning

Comments

@okolvik-avento
Copy link

okolvik-avento commented May 30, 2022 •
edited by David-Engel
Loading

Is there an existing issue for this?

  • I have searched the existing issues

Describe the bug

At random intervals (6-24 hours) the application fails to set RouteValues, which raises an exception.
Parallel or subsequent requests completes successfully, it only happens once in a blue moon.

Technical details:
.NET 6.0.5
Windows Server 2019, IIS 10
YARP (Reverse Proxy) 1.1.0
Application Insights 2.20.0

The bug happened with Ocelot as well as YARP, so i don't think either of them is the reason.

System.NullReferenceException: Object reference not set to an instance of an object.
   at Microsoft.AspNetCore.Http.DefaultHttpRequest.set_RouteValues(RouteValueDictionary value)
   at Microsoft.AspNetCore.Routing.Matching.DfaMatcher.MatchAsync(HttpContext httpContext)
   at Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync()

appsettings.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Warning"
    }
  },
  "Serilog": {
    "Using": [ "Serilog.Sinks.File", "Serilog.Sinks.ApplicationInsights" ],
    "MinimumLevel": "Warning",
    "WriteTo": [
      {
        "Name": "Async",
        "Args": {
          "configure": [
            {
              "Name": "File",
              "Args": {
                "path": "Logs/serilog.txt",
                "rollingInterval": "Day",
                "rollOnFileSizeLimit": true,
                "retainedFileCountLimit": 20,
                "fileSizeLimitBytes": 104857600
              }
            }
          ]
        }
      },
      {
        "Name": "ApplicationInsights",
        "Args": {
          "InstrumentationKey": "xxx",
          "restrictedToMinimumLevel": "Information",
          "telemetryConverter": "Serilog.Sinks.ApplicationInsights.Sinks.ApplicationInsights.TelemetryConverters.TraceTelemetryConverter, Serilog.Sinks.ApplicationInsights"
        }
      }
    ],
    "Enrich": [ "FromLogContext", "WithMachineName", "WithThreadId" ]
  },
  "AllowedHosts": "*",
  "ConnectionStrings": {
    "CmsAdmin": "Data Source=xxx;User ID=xxx;Password=xxx;Initial Catalog=xxx;MultipleActiveResultSets=True"
  },
  "InternalIPWhiteList": [
    "10.0.0.0/8",
    "172.16.0.0/12",
    "192.168.0.0/16",
    "::1",
    "127.0.0.1"
  ],
  "ApplicationInsights": {
    "ConnectionString": "xxx",
    "DeveloperMode": false,
    "EnableRequestTrackingTelemetryModule": true,
    "EnableAdaptiveSampling": true,
    "EnableActiveTelemetryConfigurationSetup": true
  },
  "ReverseProxy": {
    "Routes": {
      "route1": {
        "ClusterId": "cluster1",
        "AuthorizationPolicy": "default",
        "Match": {
          "Path": "{**catch-all}"
        },
        "AllowAnonymous": false
      }
    },
    "Clusters": {
      "cluster1": {
        "Destinations": {
          "destination1": {
            "Address": "http://192.168.197.13"
          },
          "destination2": {
            "Address": "http://192.168.197.14"
          }
        }
      }
    },
    "LoadBalancingPolicy": "PowerOfTwoChoices"
  }
}

Startup.cs

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using xx.Api.Gateway.Services;
using xx.Api.Handlers;
using Microsoft.AspNetCore.Authentication;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.HttpOverrides;
using Microsoft.AspNetCore.HttpsPolicy;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Hosting.Internal;
using Microsoft.Extensions.Logging;
using Serilog;
using Yarp.ReverseProxy.Transforms;

namespace xx.Api.Gateway
{
    public class Startup
    {
        public Startup(IConfiguration configuration, IWebHostEnvironment env)
        {
            Configuration = configuration;
            _env = env;
        }

        public IConfiguration Configuration { get; }

        private readonly IWebHostEnvironment _env;

        // This method gets called by the runtime. Use this method to add services to the container.
        public void ConfigureServices(IServiceCollection services)
        {
            services.AddCors();
            services.AddOptions();
            services.AddMemoryCache();
            services.AddHttpContextAccessor();
            
            // configure basic authentication 
            services.AddAuthentication("BasicAuthentication")
                .AddScheme<AuthenticationSchemeOptions, BasicAuthenticationHandler>("BasicAuthentication", null);

            // configure DI for application services
            services.AddScoped<IAccountService, AccountService>();
            services.AddApplicationInsightsTelemetry();
            services.AddSingleton<IPService>();

            var proxyBuilder = services.AddReverseProxy();
            // Initialize the reverse proxy from the "ReverseProxy" section of configuration
            proxyBuilder.LoadFromConfig(Configuration.GetSection("ReverseProxy"));
            proxyBuilder.AddTransforms(builderContext =>
            {
                // Conditionally add a transform for routes that require auth.
                if (!string.IsNullOrEmpty(builderContext.Route.AuthorizationPolicy))
                {
                    builderContext.AddRequestTransform(transformContext =>
                    {
                        var user = transformContext.HttpContext.User;
                        var version = user.Claims.FirstOrDefault(x => x.Type.Equals("ApiVersion"))?.Value;
                        var hostname = user.Claims.FirstOrDefault(x => x.Type.Equals("ApiHostname"))?.Value;
                        var urlVersion = user.Claims.FirstOrDefault(x => x.Type.Equals("ApiUrlVersion"))?.Value;

                        var environment = _env.EnvironmentName == "Production" ? "" : "-development";
                        if (!string.IsNullOrEmpty(version) && !string.IsNullOrEmpty(hostname) && !string.IsNullOrEmpty(urlVersion))
                        {
                            transformContext.ProxyRequest.Headers.Remove("X-Api-Version");
                            transformContext.ProxyRequest.Headers.Remove("X-Api-Hostname");
                            transformContext.ProxyRequest.Headers.Add("X-Api-Version", version);
                            transformContext.ProxyRequest.Headers.Add("X-Api-Hostname", hostname);
                            transformContext.Path = string.Format("/v{0}{1}{2}", urlVersion, environment, transformContext.Path);
                        }

                        return default;
                    });
                }
            });
        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            // global cors policy
            app.UseCors(x => x
                .AllowAnyOrigin()
                .AllowAnyMethod()
                .AllowAnyHeader());

            //app.UseHttpsRedirection();

            app.UseAuthentication();         
            app.UseRouting();
            app.UseAuthorization();
            app.UseEndpoints(endpoints =>
            {
                endpoints.MapReverseProxy();
            });

        }
    }
}

BasicAuthenticationHandler:

using System;
using System.Net.Http.Headers;
using System.Security.Claims;
using System.Text;
using System.Text.Encodings.Web;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Authentication;
using Microsoft.Extensions.Options;
using xx.Api.Gateway.Entities;
using xx.Api.Gateway.Services;
using Microsoft.AspNetCore.HttpOverrides;
using Microsoft.Extensions.Logging;
using Microsoft.ApplicationInsights;

namespace xx.Api.Handlers
{
    public class BasicAuthenticationHandler : AuthenticationHandler<AuthenticationSchemeOptions>
    {
        private readonly IAccountService _userService;
        private readonly IPService _ipService;
        private readonly TelemetryClient _telemetry;

        public BasicAuthenticationHandler(
            IOptionsMonitor<AuthenticationSchemeOptions> options,
            ILoggerFactory logger,
            UrlEncoder encoder,
            ISystemClock clock,
            IAccountService userService,
            IPService ipService,
            TelemetryClient telemetry)
            : base(options, logger, encoder, clock)
        {
            _userService = userService;
            _ipService = ipService;
            _telemetry = telemetry;
        }

        protected override async Task<AuthenticateResult> HandleAuthenticateAsync()
        {
            var remoteIp = Request.HttpContext.Connection.RemoteIpAddress;
            Logger.LogInformation(remoteIp != null ? "Remote ip is: " + remoteIp.ToString() : "Remote ip is null");

            if (Request.Headers.ContainsKey("Authorization"))
            {
                Logger.LogDebug("Logging in with autorization");
                return await AuthenticateWithAuthorization();
            }
            
            if(remoteIp != null && _ipService.IsIPWhiteListed(remoteIp))
            {
                Logger.LogDebug("Logging in with hostname");
                return await AuthenticateWithApiHost();
            }

            return AuthenticateResult.Fail("Unknown authentication method.");
        }

        private async Task<AuthenticateResult> AuthenticateWithApiHost()
        {
            Account account = null;
            try
            {
                string apiHost;

                if(Request.Headers.ContainsKey("X-Api-Hostname"))
                {
                    apiHost = Request.Headers["X-Api-Hostname"];
                    Logger.LogInformation("X-Api-Hostname " + apiHost);
                }
                else
                {
                    var hosts = Request.Host.Host.Split(".");
                    if (hosts.Length < 3)
                    {
                        return AuthenticateResult.Fail("No hostname");
                    }

                    apiHost = hosts[0];
                    Logger.LogInformation("Parsed hostname " + apiHost);
                }

                account = await _userService.AuthenticateHost(apiHost);
            }
            catch(Exception ex)
            {
                _telemetry.TrackException(ex);
                return AuthenticateResult.Fail("Invalid hostname");
            }

            if (account == null)
                return AuthenticateResult.Fail("Invalid hostname");

            return CreateTicket(account);
        }

        protected async Task<AuthenticateResult> AuthenticateWithAuthorization()
        {
            Account account = null;
            try
            {
                var authHeader = AuthenticationHeaderValue.Parse(Request.Headers["Authorization"]);
                var credentialBytes = Convert.FromBase64String(authHeader.Parameter);
                var credentials = Encoding.UTF8.GetString(credentialBytes).Split(new[] { ':' }, 2);
                var username = credentials[0];
                var password = credentials[1];
                if(Request.Headers.ContainsKey("X-Api-Verify-Token"))
                {
                    account = await _userService.AuthenticateAccessToken(username, password);
                }
                else
                {
                    account = await _userService.Authenticate(username, password);
                }
                
            }
            catch(Exception ex)
            {
                _telemetry.TrackException(ex);
                return AuthenticateResult.Fail("Invalid Authorization Header");
            }

            if (account == null)
                return AuthenticateResult.Fail("Invalid Username or Password");

            return CreateTicket(account);
        }

        protected AuthenticateResult CreateTicket(Account account)
        {
            Version apiVersion = new Version(1,0);
            int urlVersion = 2;
            if(Request.Headers.ContainsKey("X-Api-Version"))
            {
                Version v;
                if(Version.TryParse(Request.Headers["X-Api-Version"].ToString(), out v))
                {
                    urlVersion = v.Major > 1 ? v.Major : 2;
                    apiVersion = v;
                }
            }
            Logger.LogInformation(string.Format("Api hostname: {0}, Api version: {1}, Url version: {2}", account.ApiHost, apiVersion, urlVersion));

            var name = string.IsNullOrEmpty(account.Username) ? account.ApiHost : account.Username;

            var claims = new[] {
                new Claim(ClaimTypes.NameIdentifier, account.Id.ToString()),
                new Claim(ClaimTypes.Name, name),
                new Claim("ApiHostname", account.ApiHost),
                new Claim("ApiUrlVersion", urlVersion.ToString()),
                new Claim("ApiVersion", apiVersion.ToString())
            };
            var identity = new ClaimsIdentity(claims, Scheme.Name);
            var principal = new ClaimsPrincipal(identity);
            var ticket = new AuthenticationTicket(principal, Scheme.Name);

            return AuthenticateResult.Success(ticket);
        }
    }
}

Expected Behavior

No exception

Steps To Reproduce

Sadly i can't reproduce it, since i don't know what's actually wrong.

Exceptions (if any)

System.NullReferenceException: Object reference not set to an instance of an object.
at Microsoft.AspNetCore.Http.DefaultHttpRequest.set_RouteValues(RouteValueDictionary value)
at Microsoft.AspNetCore.Routing.Matching.DfaMatcher.MatchAsync(HttpContext httpContext)
at Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.Invoke(HttpContext httpContext)
at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync()

.NET Version

6.0.5

Anything else?

.NET 6.0.5
Windows Server 2019, IIS 10
YARP (Reverse Proxy) 1.1.0
Application Insights 2.20.0
@MihaZupan MihaZupan mentioned this issue May 30, 2022
Closed
@javiercn javiercn added area-mvc Includes: MVC, Actions and Controllers, Localization, CORS, most templates feature-routing investigate labels May 30, 2022
@javiercn
Copy link
Member

@okolvik-avento thanks for contacting us.

Could you put the code in a minimal repro project instead? It is super hard to make sense on an issue with so much code.

@javiercn
Copy link
Member

@Tratcher My understanding is that DefaultHttpRequest.RouteValues is failing (somehow). Do you know what can be the case for that?

@javiercn javiercn added this to the .NET 7 Planning milestone May 30, 2022
@ghost
Copy link

ghost commented May 30, 2022

Thanks for contacting us.
We're moving this issue to the .NET 7 Planning milestone for future evaluation / consideration. Because it's not immediately obvious that this is a bug in our framework, we would like to keep this around to collect more feedback, which can later help us determine the impact of it. We will re-evaluate this issue, during our next planning meeting(s).
If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues.
To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

@okolvik-avento
Copy link
Author

@javiercn The project itself is already quite small, so i can send you an invite to a repo without secrets.

@okolvik-avento
Copy link
Author

@javiercn I should note that i have yet to get the error in local development with IIS Express. I've only ever seen it on IIS.

@okolvik-avento
Copy link
Author

okolvik-avento commented May 30, 2022 •
edited
Loading

@javiercn Just noticed that i had not set the application pool to "No Managed Code", maybe that is the issue? I will see if it fixes the problem

Update:
It did not fix the issue

@davidfowl
Copy link
Member

Issues like these are always hard to track down. Does it repro if you remove application insights (I assume you're using it)?

@okolvik-avento
Copy link
Author

@davidfowl Yeah i use Application Insights. I've removed service.AddApplicationInsightsTelemetry() now and removed all traces of the telemetry client. Lets see how it goes

@okolvik-avento
Copy link
Author

okolvik-avento commented May 31, 2022 •
edited
Loading

@davidfowl No errors after i removed it. So it seems Application Insights is the issue here. I think this is related #1524

@davidfowl
Copy link
Member

Hmmm, I expected this but the callstack does look different. I would be great a capture a process dump when this happens...

@okolvik-avento
Copy link
Author

@davidfowl What's the best way to do that?

@okolvik-avento
Copy link
Author

okolvik-avento commented May 31, 2022 •
edited
Loading

@davidfowl Here is the .net callstack:
I have a minidump also if you have a place i can send it
At least i hope it's the right exception and not just a similar one

Microsoft.AspNetCore.Http.DefaultHttpRequest.set_RouteValues(Microsoft.AspNetCore.Routing.RouteValueDictionary)+97 
Microsoft.AspNetCore.Routing.Matching.DfaMatcher.MatchAsync()+810 
Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.Invoke()+a4 
Microsoft.AspNetCore.Authentication.AuthenticationMiddleware+d__6.MoveNext()+6a6 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Authentication.AuthenticationMiddleware+d__6, Microsoft.AspNetCore.Authentication]].MoveNext(System.Threading.Thread)+cd 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Microsoft.AspNetCore.Authentication.AuthenticationService+d__14.MoveNext()+59d 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Microsoft.AspNetCore.Authentication.AuthenticationService+d__14, Microsoft.AspNetCore.Authentication.Core]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Microsoft.AspNetCore.Authentication.AuthenticationHandler`1+d__48[[System.__Canon, System.Private.CoreLib]].MoveNext()+307 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Microsoft.AspNetCore.Authentication.AuthenticationHandler`1+d__48[[System.__Canon, System.Private.CoreLib]], Microsoft.AspNetCore.Authentication]].MoveNext(System.Threading.Thread)+119 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Handlers.BasicAuthenticationHandler+d__3.MoveNext()+411 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Handlers.BasicAuthenticationHandler+d__3, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Handlers.BasicAuthenticationHandler+d__4.MoveNext()+431 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Handlers.BasicAuthenticationHandler+d__4, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Gateway.Services.AccountService+d__5.MoveNext()+207 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Gateway.Services.AccountService+d__5, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Gateway.Services.AccountService+d__7.MoveNext()+3e3 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Gateway.Services.AccountService+d__7, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, System.Private.CoreLib]].SetExistingTaskResult(System.Threading.Tasks.Task`1, System.__Canon)+a3 
Dapper.SqlMapper+d__34`1[[System.__Canon, System.Private.CoreLib]].MoveNext()+c98 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Dapper.SqlMapper+d__34`1[[System.__Canon, System.Private.CoreLib]], Dapper]].MoveNext(System.Threading.Thread)+119 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task.FinishSlow(Boolean)+27 
System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)+13d 
System.Threading.Tasks.ThreadPoolTaskScheduler.TryExecuteTaskInline(System.Threading.Tasks.Task, Boolean)+8c 
System.Threading.Tasks.TaskContinuation.InlineIfPossibleOrElseQueue(System.Threading.Tasks.Task, Boolean)+a3 
System.Threading.Tasks.ContinueWithTaskContinuation.Run(System.Threading.Tasks.Task, Boolean)+e8 
System.Threading.Tasks.Task.RunContinuations(System.Object)+36c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
System.Threading.Tasks.UnwrapPromise`1[[System.__Canon, System.Private.CoreLib]].TrySetFromTask(System.Threading.Tasks.Task, Boolean)+c5 
System.Threading.Tasks.UnwrapPromise`1[[System.__Canon, System.Private.CoreLib]].ProcessInnerTask(System.Threading.Tasks.Task)+2a 
System.Threading.Tasks.Task.RunContinuations(System.Object)+352 
System.Threading.Tasks.Task.FinishSlow(Boolean)+27 
System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)+13d 
System.Threading.ThreadPoolWorkQueue.Dispatch()+1fa 
System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()+1f2 
[[DebuggerU2MCatchHandlerFrame]]

Another similar one:

[[HelperMethodFrame]] 
System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()+20 
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(System.Threading.Tasks.Task)+5c 
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)+4a 
Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1+d__2[[System.__Canon, System.Private.CoreLib]].MoveNext()+1cf 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Boolean, System.Private.CoreLib],[Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1+d__2[[System.__Canon, System.Private.CoreLib]], Microsoft.AspNetCore.Server.IIS]].MoveNext(System.Threading.Thread)+119 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task.FinishSlow(Boolean)+3d 
System.Threading.Tasks.Task.TrySetException(System.Object)+83 
System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib]].SetException(System.Exception, System.Threading.Tasks.Task`1 ByRef)+52 
System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetException(System.Exception)+13 
Microsoft.AspNetCore.Authentication.AuthenticationMiddleware+d__6.MoveNext()+83d 
[[FaultingExceptionFrame]] 
Microsoft.AspNetCore.Http.DefaultHttpRequest.set_RouteValues(Microsoft.AspNetCore.Routing.RouteValueDictionary)+97 
Microsoft.AspNetCore.Routing.Matching.DfaMatcher.MatchAsync()+810 
Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.Invoke()+a4 
Microsoft.AspNetCore.Authentication.AuthenticationMiddleware+d__6.MoveNext()+6a6 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Authentication.AuthenticationMiddleware+d__6, Microsoft.AspNetCore.Authentication]].MoveNext(System.Threading.Thread)+cd 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Microsoft.AspNetCore.Authentication.AuthenticationService+d__14.MoveNext()+59d 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Microsoft.AspNetCore.Authentication.AuthenticationService+d__14, Microsoft.AspNetCore.Authentication.Core]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Microsoft.AspNetCore.Authentication.AuthenticationHandler`1+d__48[[System.__Canon, System.Private.CoreLib]].MoveNext()+307 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Microsoft.AspNetCore.Authentication.AuthenticationHandler`1+d__48[[System.__Canon, System.Private.CoreLib]], Microsoft.AspNetCore.Authentication]].MoveNext(System.Threading.Thread)+119 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Handlers.BasicAuthenticationHandler+d__3.MoveNext()+411 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Handlers.BasicAuthenticationHandler+d__3, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Handlers.BasicAuthenticationHandler+d__4.MoveNext()+431 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Handlers.BasicAuthenticationHandler+d__4, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Gateway.Services.AccountService+d__5.MoveNext()+207 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Gateway.Services.AccountService+d__5, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
Atom.Api.Gateway.Services.AccountService+d__7.MoveNext()+3e3 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Atom.Api.Gateway.Services.AccountService+d__7, Atom.Api.Gateway]].MoveNext(System.Threading.Thread)+f4 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, System.Private.CoreLib]].SetExistingTaskResult(System.Threading.Tasks.Task`1, System.__Canon)+a3 
Dapper.SqlMapper+d__34`1[[System.__Canon, System.Private.CoreLib]].MoveNext()+c98 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+77 
System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Dapper.SqlMapper+d__34`1[[System.__Canon, System.Private.CoreLib]], Dapper]].MoveNext(System.Threading.Thread)+119 
System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+f4 
System.Threading.Tasks.Task.RunContinuations(System.Object)+7c 
System.Threading.Tasks.Task.FinishSlow(Boolean)+27 
System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)+13d 
System.Threading.Tasks.ThreadPoolTaskScheduler.TryExecuteTaskInline(System.Threading.Tasks.Task, Boolean)+8c 
System.Threading.Tasks.TaskContinuation.InlineIfPossibleOrElseQueue(System.Threading.Tasks.Task, Boolean)+a3 
System.Threading.Tasks.ContinueWithTaskContinuation.Run(System.Threading.Tasks.Task, Boolean)+e8 
System.Threading.Tasks.Task.RunContinuations(System.Object)+36c 
System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+81 
System.Threading.Tasks.UnwrapPromise`1[[System.__Canon, System.Private.CoreLib]].TrySetFromTask(System.Threading.Tasks.Task, Boolean)+c5 
System.Threading.Tasks.UnwrapPromise`1[[System.__Canon, System.Private.CoreLib]].ProcessInnerTask(System.Threading.Tasks.Task)+2a 
System.Threading.Tasks.Task.RunContinuations(System.Object)+352 
System.Threading.Tasks.Task.FinishSlow(Boolean)+27 
System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)+13d 
System.Threading.ThreadPoolWorkQueue.Dispatch()+1fa 
System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()+1f2 
[[DebuggerU2MCatchHandlerFrame]]

@okolvik-avento
Copy link
Author

@davidfowl And one for get_Cookies

Microsoft.AspNetCore.Http.DefaultHttpRequest.get_Cookies()+8f 
Microsoft.ApplicationInsights.AspNetCore.TelemetryInitializers.WebSessionTelemetryInitializer.UpdateRequestTelemetryFromPlatformContext(Microsoft.ApplicationInsights.DataContracts.RequestTelemetry, Microsoft.AspNetCore.Http.HttpContext)+3c 
Microsoft.ApplicationInsights.AspNetCore.TelemetryInitializers.WebSessionTelemetryInitializer.OnInitializeTelemetry(Microsoft.AspNetCore.Http.HttpContext, Microsoft.ApplicationInsights.DataContracts.RequestTelemetry, Microsoft.ApplicationInsights.Channel.ITelemetry)+c4 
Microsoft.ApplicationInsights.AspNetCore.TelemetryInitializers.TelemetryInitializerBase.Initialize(Microsoft.ApplicationInsights.Channel.ITelemetry)+fa 
Microsoft.ApplicationInsights.TelemetryClient.Initialize(Microsoft.ApplicationInsights.Channel.ITelemetry)+2f9 
Microsoft.ApplicationInsights.TelemetryClient.Track(Microsoft.ApplicationInsights.Channel.ITelemetry)+35 
Microsoft.ApplicationInsights.DependencyCollector.Implementation.SqlClientDiagnostics.SqlClientDiagnosticSourceListener.AfterExecuteHelper(System.Collections.Generic.KeyValuePair`2, Microsoft.ApplicationInsights.Common.PropertyFetcher, Microsoft.ApplicationInsights.Common.PropertyFetcher, Microsoft.ApplicationInsights.Common.PropertyFetcher)+18b 
Microsoft.ApplicationInsights.DependencyCollector.Implementation.SqlClientDiagnostics.SqlClientDiagnosticSourceListener.System.IObserver>.OnNext(System.Collections.Generic.KeyValuePair`2)+48f 
System.Diagnostics.DiagnosticListener.Write(System.String, System.Object)+45 
System.Data.SqlClient.SqlClientDiagnosticListenerExtensions.WriteCommandAfter(System.Diagnostics.DiagnosticListener, System.Guid, System.Data.SqlClient.SqlCommand, System.String)+1fc 
System.Data.SqlClient.SqlCommand+<>c__DisplayClass130_0.b__2(System.Threading.Tasks.Task`1)+2fc 
System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+4b 
System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)+b6 
System.Threading.ThreadPoolWorkQueue.Dispatch()+1fa 
System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()+1f2

@davidfowl
Copy link
Member

This stack is the app insights ones that I would expect to fail.

@okolvik-avento
Copy link
Author

This stack is the app insights ones that I would expect to fail.

Ok, i'll keep monitoring the exceptions. Tell me if you want a minidump

@davidfowl
Copy link
Member

Did you capture one?

@okolvik-avento
Copy link
Author

Did you capture one?

Yeah i'm running the debug diagnostic tool on the application pool

@okolvik-avento
Copy link
Author

Note that the set_RouteValues one also only happens with AI activated

@okolvik-avento
Copy link
Author

okolvik-avento commented May 31, 2022 •
edited
Loading

@davidfowl https://avento365-my.sharepoint.com/:f:/g/personal/ole_kolvik_avento_no/EnPB1kXz48RJjju2c45gqQwB-gpS6lyIKiYu3JsaG7v5_A?e=HeWMXw

1 for get_Cookies and 1 for set_RouteValues.
I can see that Application Insights is running in another thread on the set_RouteValues one, it might access HttpContext causing the issue?

Btw, the pdb for Application Insights isn't on the microsoft symbol servers or on the nuget ones. Had to grab it manually.

@okolvik-avento
Copy link
Author

I do have full userdumps as well, but i'm not sharing them publicly

@okolvik-avento
Copy link
Author

None of these errors happen on Debug builds, could it be something wrong with optimization for Release builds?

@okolvik-avento
Copy link
Author

okolvik-avento commented Jun 1, 2022 •
edited
Loading

Also here is a load test with JMeter on Debug vs Release build
The Debug build runs much faster and does not error. The Release build errors out and stops processing requests/sending data to application insights, i didn't run the release build test long this time, but the pattern is repeated in other tests i've done.

Debug:

PS C:\Users\ole.kolvik\Downloads\apache-jmeter-5.4.3\bin> .\jmeter.bat -n -t .\gateway-dev.test
Creating summariser <summary>
Created the tree successfully using .\gateway-dev.test
Starting standalone test @ Wed Jun 01 16:35:14 CEST 2022 (1654094114429)
Waiting for possible Shutdown/StopTestNow/HeapDump/ThreadDump message on port 4445
summary +    674 in 00:00:15 =   44.7/s Avg:    20 Min:    12 Max:   166 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary +   1446 in 00:00:30 =   48.1/s Avg:    15 Min:    11 Max:    39 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   2120 in 00:00:45 =   47.0/s Avg:    17 Min:    11 Max:   166 Err:     0 (0.00%)
summary +   1421 in 00:00:30 =   47.4/s Avg:    17 Min:    11 Max:   197 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   3541 in 00:01:15 =   47.2/s Avg:    17 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1437 in 00:00:30 =   47.9/s Avg:    16 Min:    11 Max:    62 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   4978 in 00:01:45 =   47.4/s Avg:    17 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1439 in 00:00:30 =   47.9/s Avg:    16 Min:    11 Max:    63 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   6417 in 00:02:15 =   47.5/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1443 in 00:00:30 =   48.1/s Avg:    15 Min:    11 Max:    45 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   7860 in 00:02:45 =   47.6/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1436 in 00:00:30 =   47.9/s Avg:    16 Min:    12 Max:    53 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   9296 in 00:03:15 =   47.7/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1427 in 00:00:30 =   47.5/s Avg:    16 Min:    11 Max:   155 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  10723 in 00:03:45 =   47.6/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1433 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:    79 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  12156 in 00:04:15 =   47.7/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1444 in 00:00:30 =   48.1/s Avg:    15 Min:    11 Max:    54 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  13600 in 00:04:45 =   47.7/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1438 in 00:00:30 =   47.9/s Avg:    16 Min:    11 Max:    95 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  15038 in 00:05:15 =   47.7/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1435 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:    73 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  16473 in 00:05:45 =   47.7/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1438 in 00:00:30 =   48.0/s Avg:    15 Min:    11 Max:   106 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  17911 in 00:06:15 =   47.8/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1443 in 00:00:30 =   48.1/s Avg:    15 Min:    11 Max:    37 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  19354 in 00:06:45 =   47.8/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1426 in 00:00:30 =   47.5/s Avg:    16 Min:    11 Max:    98 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  20780 in 00:07:15 =   47.8/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1444 in 00:00:30 =   48.1/s Avg:    15 Min:    11 Max:    41 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  22224 in 00:07:45 =   47.8/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1427 in 00:00:30 =   47.6/s Avg:    17 Min:    11 Max:    88 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  23651 in 00:08:15 =   47.8/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1437 in 00:00:30 =   47.9/s Avg:    15 Min:    11 Max:    85 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  25088 in 00:08:45 =   47.8/s Avg:    16 Min:    11 Max:   197 Err:     0 (0.00%)
summary +   1371 in 00:00:30 =   45.7/s Avg:    21 Min:    11 Max:   764 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  26459 in 00:09:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1422 in 00:00:30 =   47.4/s Avg:    17 Min:    11 Max:   159 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  27881 in 00:09:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1428 in 00:00:30 =   47.6/s Avg:    16 Min:    12 Max:    65 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  29309 in 00:10:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1437 in 00:00:30 =   47.9/s Avg:    15 Min:    11 Max:    43 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  30746 in 00:10:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1438 in 00:00:30 =   47.9/s Avg:    16 Min:    11 Max:    62 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  32184 in 00:11:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1438 in 00:00:30 =   47.9/s Avg:    15 Min:    11 Max:    43 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  33622 in 00:11:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1441 in 00:00:30 =   48.1/s Avg:    15 Min:    11 Max:    55 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  35063 in 00:12:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1434 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:    89 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  36497 in 00:12:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1435 in 00:00:30 =   47.8/s Avg:    17 Min:    11 Max:    91 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  37932 in 00:13:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1385 in 00:00:30 =   46.2/s Avg:    21 Min:    11 Max:   552 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  39317 in 00:13:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1435 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:   107 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  40752 in 00:14:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1435 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:   143 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  42187 in 00:14:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1432 in 00:00:30 =   47.7/s Avg:    16 Min:    11 Max:    62 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  43619 in 00:15:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1439 in 00:00:30 =   48.0/s Avg:    16 Min:    11 Max:   100 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  45058 in 00:15:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1418 in 00:00:30 =   47.3/s Avg:    18 Min:    11 Max:   185 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  46476 in 00:16:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1443 in 00:00:30 =   48.1/s Avg:    15 Min:    11 Max:    44 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  47919 in 00:16:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1431 in 00:00:30 =   47.5/s Avg:    17 Min:    11 Max:    90 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  49350 in 00:17:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1438 in 00:00:30 =   48.0/s Avg:    15 Min:    11 Max:   164 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  50788 in 00:17:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1433 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:   113 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  52221 in 00:18:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1435 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:    69 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  53656 in 00:18:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1424 in 00:00:30 =   47.4/s Avg:    17 Min:    11 Max:   117 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  55080 in 00:19:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1437 in 00:00:30 =   48.0/s Avg:    15 Min:    11 Max:   114 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  56517 in 00:19:45 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
summary +   1435 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:    79 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =  57952 in 00:20:15 =   47.7/s Avg:    16 Min:    11 Max:   764 Err:     0 (0.00%)
Terminate batch job (Y/N)? y
PS C:\Users\ole.kolvik\Downloads\apache-jmeter-5.4.3\bin> .\jmeter.bat -n -t .\gateway-dev.test

Release:

PS C:\Users\ole.kolvik\Downloads\apache-jmeter-5.4.3\bin> .\jmeter.bat -n -t .\gateway-dev.test
Creating summariser <summary>
Created the tree successfully using .\gateway-dev.test
Starting standalone test @ Wed Jun 01 17:07:24 CEST 2022 (1654096044228)
Waiting for possible Shutdown/StopTestNow/HeapDump/ThreadDump message on port 4445
summary +     13 in 00:00:08 =    1.7/s Avg:  1499 Min:    27 Max:  4455 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary +   1075 in 00:00:28 =   38.8/s Avg:    66 Min:    11 Max:  4554 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   1088 in 00:00:35 =   30.7/s Avg:    83 Min:    11 Max:  4554 Err:     0 (0.00%)
summary +   1435 in 00:00:30 =   47.8/s Avg:    16 Min:    11 Max:    85 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   2523 in 00:01:06 =   38.5/s Avg:    45 Min:    11 Max:  4554 Err:     0 (0.00%)
summary +   1241 in 00:02:00 =   10.3/s Avg:   470 Min:    11 Max: 50059 Err:     2 (0.16%) Active: 6 Started: 6 Finished: 0
summary =   3764 in 00:03:05 =   20.3/s Avg:   185 Min:    11 Max: 50059 Err:     2 (0.05%)
summary +   1444 in 00:00:30 =   48.2/s Avg:    15 Min:    11 Max:    37 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   5208 in 00:03:35 =   24.2/s Avg:   138 Min:    11 Max: 50059 Err:     2 (0.04%)
summary +   1441 in 00:00:30 =   48.0/s Avg:    15 Min:    11 Max:    55 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   6649 in 00:04:05 =   27.1/s Avg:   111 Min:    11 Max: 50059 Err:     2 (0.03%)
summary +   1440 in 00:00:30 =   48.0/s Avg:    15 Min:    11 Max:    63 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   8089 in 00:04:35 =   29.4/s Avg:    94 Min:    11 Max: 50059 Err:     2 (0.02%)
Terminate batch job (Y/N)? y
PS C:\Users\ole.kolvik\Downloads\apache-jmeter-5.4.3\bin>

@okolvik-avento
Copy link
Author

Release without services.AddApplicationInsightsTelemetry();

PS C:\Users\ole.kolvik\Downloads\apache-jmeter-5.4.3\bin> .\jmeter.bat -n -t .\gateway-dev.test
Creating summariser <summary>
Created the tree successfully using .\gateway-dev.test
Starting standalone test @ Wed Jun 01 17:50:55 CEST 2022 (1654098655542)
Waiting for possible Shutdown/StopTestNow/HeapDump/ThreadDump message on port 4445
summary +    180 in 00:00:04 =   42.5/s Avg:    15 Min:    11 Max:    68 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary +   1417 in 00:00:30 =   47.3/s Avg:    17 Min:    11 Max:    99 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   1597 in 00:00:34 =   46.7/s Avg:    17 Min:    11 Max:    99 Err:     0 (0.00%)
summary +   1432 in 00:00:30 =   47.6/s Avg:    16 Min:    11 Max:   110 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   3029 in 00:01:04 =   47.1/s Avg:    16 Min:    11 Max:   110 Err:     0 (0.00%)
summary +   1419 in 00:00:30 =   47.4/s Avg:    17 Min:    11 Max:    78 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   4448 in 00:01:34 =   47.2/s Avg:    17 Min:    11 Max:   110 Err:     0 (0.00%)
summary +   1408 in 00:00:30 =   46.9/s Avg:    17 Min:    11 Max:   628 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   5856 in 00:02:04 =   47.1/s Avg:    17 Min:    11 Max:   628 Err:     0 (0.00%)
summary +   1427 in 00:00:30 =   47.6/s Avg:    17 Min:    11 Max:   128 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   7283 in 00:02:34 =   47.2/s Avg:    17 Min:    11 Max:   628 Err:     0 (0.00%)
summary +   1438 in 00:00:30 =   47.9/s Avg:    15 Min:    10 Max:   208 Err:     0 (0.00%) Active: 6 Started: 6 Finished: 0
summary =   8721 in 00:03:04 =   47.3/s Avg:    16 Min:    10 Max:   628 Err:     0 (0.00%)
Terminate batch job (Y/N)? y
PS C:\Users\ole.kolvik\Downloads\apache-jmeter-5.4.3\bin>

@davidfowl
Copy link
Member

@okolvik-avento can you get me access to the dump. My email is david.fowler at microsoft

@okolvik-avento
Copy link
Author

@davidfowl sent you an invite to a onedrive folder

@davidfowl
Copy link
Member

davidfowl commented Jun 3, 2022 •
edited
Loading

My current theory is that there's concurrent access to the HttpContext causing this corruption. I will admit that I haven't yet figured out why its concurrent access to the HttpContext this early.

This method is returning null

aspnetcore/src/Extensions/Features/src/FeatureReferences.cs

Line 93 in b3c9396

public TFeature? Fetch<TFeature, TState>(

@okolvik-avento
Copy link
Author

@davidfowl i suspect it's the BasicAuthenticationHandler. It seems to be accessing a lot of headers in various async functions. That might be it? I'll try moving every header in the initial authentication function

@Tratcher
Copy link
Member

Tratcher commented Jun 3, 2022

BasicAuthenticationHandler looks fine. Async functions are ok so long as you await them so the flow stays linear.

@davidfowl
Copy link
Member

I see why it happens now. It's because the basic auth middleware calls into the telemetry client. That's why it fails at routing. I'm going to see if we can improve these issues but one short term fix would be to remove the telemetry initializer that read the http context.

@okolvik-avento
Copy link
Author

okolvik-avento commented Jun 4, 2022 •
edited
Loading

@davidfowl in the updated code that the dumps are from, there is no telemetry in BasicAuth (remember i removed everything about the telemetry client #41924 (comment)). I changed everything to use Logger.LogError where Logger is Microsoft.Extensions.Logging.ILoggerFactory which is the standard logger in AuthenticationHandler.

Unless i'm misunderstanding you that is.

@davidfowl
Copy link
Member

Are you saying it still happens when you remove application insights?

@davidfowl
Copy link
Member

Thanks to these dumps I can visually see the race condition 😄:

hang

When the exception happens for cookies, there's an async Task continuation that is running and writing to app insights (where the null ref happens). Concurrently the auth middleware is currently running. Where are your SQL queries? In the user service?

@okolvik-avento
Copy link
Author

@davidfowl No, that's not what i mean. It only happens when i have services.AddApplicationInsightsTelemetry(), even when i don't actually use the telemetry client anywhere.

This goes for both the get_Cookies and set_RouteValues

I'm sending you an invite to the repo with the code that created the dumps.

@davidfowl
Copy link
Member

Got it, yea it seems like something is making SQL queries on another thread that is running concurrently with the request causing the race.

@davidfowl
Copy link
Member

davidfowl commented Jun 4, 2022 •
edited
Loading

I didn't even realize the problem was right in front of my eyes. @okolvik-avento Thanks for the dumps, the issue in the in SqlCommand implementation here

When you run an async sql command, even when you await it properly, the implementation fires the diagnostics listener callback after running the user's continuation. This allows the telemetry initializers in app insights to run concurrently with the request, causing this chaos.

This isn't an app insights issue (this time 😄), it turns out.

cc @ajcvickers @roji

@davidfowl davidfowl mentioned this issue Jun 4, 2022
Closed
@okolvik-avento
Copy link
Author

@davidfowl I'm replacing System.Data.SqlClient with Microsoft.Data.SqlClient for more testing.
I don't see SqlClient in the stack trace for set_RouteValues (the original exception)

@okolvik-avento
Copy link
Author

okolvik-avento commented Jun 4, 2022 •
edited
Loading

First thing i see is a huge performance increase. While tests with System.Data.SqlClient had 20ms responsetime with max up to 100ms, i now see sub 5ms responsetimes with max up to 20ms

@davidfowl davidfowl mentioned this issue Jun 4, 2022
Open
@okolvik-avento
Copy link
Author

@davidfowl Sadly i'm still seeing the get_Cookies exception

@davidfowl
Copy link
Member

Yes, the problematic code exists in both implementations 😄, see dotnet/SqlClient#1634

@ajcvickers
Copy link
Member

@David-Engel owns SqlClient.

@davidfowl
Copy link
Member

PR open here dotnet/SqlClient#1637

@davidfowl davidfowl added External This is an issue in a component not contained in this repository. It is open for tracking purposes. ✔️ Resolution: Fixed The bug or enhancement requested in this issue has been checked-in! and removed investigate labels Jun 7, 2022
@davidfowl davidfowl self-assigned this Jun 7, 2022
@davidfowl
Copy link
Member

This is fixed!

@okolvik-avento
Copy link
Author

Thank you for the quick response @davidfowl!

@davidfowl
Copy link
Member

Thanks for the great debugging and dumps @okolvik-avento !

@davidfowl davidfowl mentioned this issue Jun 8, 2022
Closed
1 task
@ghost ghost locked as resolved and limited conversation to collaborators Jul 8, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@davidfowl davidfowl

Labels
area-mvc Includes: MVC, Actions and Controllers, Localization, CORS, most templates External This is an issue in a component not contained in this repository. It is open for tracking purposes. feature-routing ✔️ Resolution: Fixed The bug or enhancement requested in this issue has been checked-in!
Projects
None yet
Milestone
.NET 7 Planning
Development

No branches or pull requests
5 participants
@davidfowl @ajcvickers @Tratcher @javiercn @okolvik-avento