0

Using: Frontend: Angular 14, API: .NET Core 5, c#, MVC IDS: .NET Core 5, c#, Razor as per ID standard

For my web app I have an instance of IdentityServer 4 running. This worked perfectly fine and without hick ups for about a year. Since recently when the app starts the login still works flawlessly and provides the token as per usual.

However, any API request thereafter return a 500 error, for about 1 minute or so, after which it works fine and without issue. Until the app is in 'rest' position (i.e. no active users) it starts of with the same error for the same amount of time.

I tried installing serilog to see if I can catch the error on the API side, to no avail. There are no errors in the logged serilog file. The only errors I can find are in the ASP.NET logs, which generally llok like the below;

fail: Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler[3]
      Exception occurred while processing message.
      System.InvalidOperationException: IDX20803: Unable to obtain configuration from: 'https://<ids_server_url>/.well-known/openid-configuration'.
       ---> System.IO.IOException: IDX20804: Unable to retrieve document from: 'https://<ids_server_url>/.well-known/openid-configuration'.
       ---> System.Net.Http.HttpRequestException: Only one usage of each socket address (protocol/network address/port) is normally permitted. (<ids_server_url>:443)
       ---> System.Net.Sockets.SocketException (10048): Only one usage of each socket address (protocol/network address/port) is normally permitted.
         at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)

Nor can I catch the error on the IDS side, as that also seems to be working fine.

Accessing the .well-known/openid-configuration directly (i.e. from browser) gives a direct and correct response.

Several posts on SO indicated to add the below;

IdentityModelEventSource.ShowPII = true; 
ServicePointManager.Expect100Continue = true;
ServicePointManager.SecurityProtocol = 
    SecurityProtocolType.Tls |
    SecurityProtocolType.Tls11 |
    SecurityProtocolType.Tls12;
    // | SecurityProtocolType.Tls13;

This didn't seem to do anything at all to improve the error.

Would anybody be able to point me in the directions of any other possibilities? Especially the fact that it is only about a minute at the startup of the app seems to be weird?

I thought it might be the startup of IDS instance, but given that the actual login window repsonds directly and without delay, it implies that the IDS instance is active and running?

Any ideas would be helpfull?


update: 19/02/2023

With the help of @Tore Nestenius I have been able to add some logging to the initial process but the behaviour remains erratic and only on the deployed instance. (Likely because of app_pool shutting down)

Last night according to logger, after 6 failed attempts there was a succesfull query of the openid-configuration

JwtBearerBackChannelListener
@@@@ SendASync: https://<ids_server_url>/.well-known/openid-configuration
@@@@ success: True
@@@@ completed: True
@@@@ loadtime: 132
@@@@ url: https://<ids_server_url>/.well-known/openid-configuration

But... The subsequent process fails (again)

fail: Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler[3]

What's more is that the initial call that the frontend makes is to a non-authorized endpoint (i.e. a public endpoint) there should not be a need for any token verification on that call?

If I query the backend on that endpoint directly from the browser it responds immediately, hence the backend appears to be working correctly? (i.e. api & database respond as expected when queried from the browser) yet in the API ASP logs it indicates a failed jwtHandler call? Weird...

mtholen
  • 1,631
  • 2
  • 15
  • 27

1 Answers1

1

Could it be a timing issue that, when you deploy your application that the client starts to request the discovery document before IdentityServer is up and running?

In AddOpenIDConnect and JwtBearer, you can define your own BackchannelHttpHandler, like this:

.AddJwtBearer(opt =>
{
    opt.BackchannelHttpHandler = new JwtBearerBackChannelListener();
    opt.BackchannelTimeout = TimeSpan.FromSeconds(60);         //default 60s
    ...
}

This handler is used when it needs to load and reload the discovery document.

A sample handler can look like this:

  public class JwtBearerBackChannelListener : DelegatingHandler
    {
        public JwtBearerBackChannelListener() : base(new HttpClientHandler())
        {
            Console.WriteLine();
        }

        protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            Console.WriteLine("JwtBearerBackChannelListener");
            Console.WriteLine("@@@@ SendASync: " + request.RequestUri);

            var sw = new Stopwatch();
            sw.Start();

            var result = base.SendAsync(request, cancellationToken);

            result.ContinueWith(t =>
            {
                sw.Stop();

                Console.WriteLine("@@@@ success: " + result.IsFaulted);
                Console.WriteLine("@@@@ loadtime: " + sw.ElapsedMilliseconds.ToString());
                Console.WriteLine("@@@@ url: " + request.RequestUri);

                Serilog.Log.Logger.ForContext("SourceContext", "JwtBearerBackChannelListener")
                                  .ForContext("url", request.RequestUri)
                                  .ForContext("loadtime", sw.ElapsedMilliseconds.ToString() + " ms")
                                  .ForContext("success", result.IsCompletedSuccessfully)
                                  .Information("Loading IdentityServer configuration");

            });

            return result;
        }
    }

This allows you to add more extensive logging and also even custom retry logic.

It is important that IdentityServer is up-and-running before the client/api starts.

enter image description here

One approach to solve this is to add a middleware that blocks incoming requests from being processed until IdentityServer is online, like this:

enter image description here

Sample code for a waiting middleware

namespace PaymentAPI.Middleware
{
    /// <summary>
    /// Extension method to register the middleware 
    /// </summary>
    public static class WaitForIdentityServerMiddlewareExtensions
    {
        public static IApplicationBuilder UseWaitForIdentityServer(this IApplicationBuilder builder, WaitForIdentityServerOptions options)
        {
            return builder.UseMiddleware<WaitForIdentityServerMiddleware>(options);
        }
    }

    public class WaitForIdentityServerOptions
    {
        public string Authority { get; set; }
    }


    /// <summary>
    /// ASP.NET Core middleware that will wait for IdentityServer to respond
    /// 
    /// It will return a 503 SERVICE UNAVAILABLE if IdentityServer is not responding 
    /// 
    /// This middleware is only in use until the first successfull response from IdentityServer.
    /// After that this module will not do anything.
    /// 
    /// It will add the following response headers to the resonse when we return a 503 error:
    /// 
    /// - x-reason: Waiting for IdentityServer
    /// - Cache-Control: no-store,no-cache,max-age=0
    /// - Retry-After: 5
    /// 
    /// The authority URL will be taken from the 
    /// 
    /// Written by Tore Nestenius to be used in the IdentityServer in production training class.
    /// https://www.tn-data.se
    /// 
    /// </summary>
    public class WaitForIdentityServerMiddleware
    {
        /// <summary>
        /// number of seconds between each attempt to contact IdentityServer
        /// </summary>
        private int secondsBetweenRetries = 2;

        /// <summary>
        /// How many seconds should we wait before we give up waiting?
        /// </summary>
        private int httpRequestTimeout = 3;

        /// <summary>
        /// True when we have been able to reach IdentityServer
        /// </summary>
        private bool _identityServerReady = false;

        private readonly RequestDelegate _next;
        private readonly string _discoveryUrl;
        private readonly SemaphoreSlim _refreshLock;
        private DateTimeOffset _syncAfter = DateTimeOffset.MinValue;
        private readonly DateTime _startTime;

        public WaitForIdentityServerMiddleware(RequestDelegate next, IConfiguration configuration, WaitForIdentityServerOptions options)
        {
            _next = next;
            _startTime = DateTime.UtcNow;
            _discoveryUrl = buildDiscoveryUrl(options.Authority);

            _refreshLock = new SemaphoreSlim(1);
        }


        public async Task InvokeAsync(HttpContext context)
        {
            //Has IdentityServer has succesfully responsed yet?
            if (_identityServerReady == false)
            {
                //Fail fast if we should wait a bit or if there is already a request is in progress
                if (_syncAfter > DateTimeOffset.UtcNow ||   
                    _refreshLock.CurrentCount == 0)
                {
                    //We are waiting to not overload IdentitytServer with to many requests
                    //Just terminate the request with a 503 Service Unavailable response
                    CreateServiceUnavailableResponse(context);
                    return;
                }

                //Make sure we only do one request at the time
                await _refreshLock.WaitAsync().ConfigureAwait(false);

                try
                {
                    //Still not answering?
                    if (_identityServerReady == false)
                    {
                        _identityServerReady = await TryToReachIdentityServer(context);
                    }
                }
                catch (Exception exc)
                {
                    Log.Logger.ForContext("SourceContext", "WaitForIdentityServerMiddleware")
                          .ForContext("DiscoveryUrl", _discoveryUrl)
                          .ForContext("Exception", exc.Message)
                          .ForContext("Path", context.Request.Path)
                          .Fatal("Exception while trying to reach IdentityServer");
                }
                finally
                {
                    _refreshLock.Release();
                    _syncAfter = DateTimeOffset.UtcNow.AddSeconds(secondsBetweenRetries);
                }
            }

            if (_identityServerReady)
            {
                // Call the next delegate/middleware in the pipeline
                await _next(context);
            }
            else
            {
                //As we did not succeeed, let's terminate return a 503 SERVICE UNAVAILABLE error back to the client
                CreateServiceUnavailableResponse(context);
                return;
            }
        }


        /// <summary>
        /// Create a service unavailable 503 error response 
        /// </summary>
        /// <param name="context"></param>
        private void CreateServiceUnavailableResponse(HttpContext context)
        {
            context.Response.Headers.Add("x-reason", "Waiting for IdentityServer");
            context.Response.Headers.Add("Retry-After", "5");                               //Add a retry again header, with 5 seconds
            context.Response.Headers.Add("Cache-Control", "no-store,no-cache,max-age=0");   //Don't cache this response
            context.Response.StatusCode = (int)HttpStatusCode.ServiceUnavailable;           //503 status code
        }


        /// <summary>
        /// Try to reach the IdentityServer discovery endpoint
        /// </summary>
        /// <returns>True if successfull</returns>
        private async Task<bool> TryToReachIdentityServer(HttpContext context)
        {
            var client = new HttpClient();
            client.Timeout = TimeSpan.FromSeconds(httpRequestTimeout);

            var response = await client.GetAsync(_discoveryUrl);

            //Should we log?
            if (response.IsSuccessStatusCode == false)
            {
                var secondsSinceStart = (int)DateTime.UtcNow.Subtract(_startTime).TotalSeconds;

                Log.Logger.ForContext("SourceContext", "WaitForIdentityServerMiddleware")
                                  .ForContext("DiscoveryUrl", _discoveryUrl)
                                  .ForContext("Path", context.Request.Path)
                                  .ForContext("Tried for over", secondsSinceStart.ToString() + " seconds")
                                  .Information("Failed to reach IdentityServer at startup");
            }

            return response.IsSuccessStatusCode;
        }


        /// <summary>
        /// Construct the discovery endpoint URL
        /// </summary>
        /// <param name="authority"></param>
        /// <returns></returns>
        private string buildDiscoveryUrl(string authority)
        {
            string Url = authority;

            if (!Url.EndsWith("/", StringComparison.Ordinal))
            {
                Url = Url + "/";
            }

            Url = Url + ".well-known/openid-configuration";

            return Url;
        }
    }
}

Then to use the handler:

//Make sure its placed before app.UseAuthentication();

//Wait for IdentityServer to startup
app.UseWaitForIdentityServer(new WaitForIdentityServerOptions() 
    { Authority = _configuration["openid:authority"] });
Tore Nestenius
  • 16,431
  • 5
  • 30
  • 40
  • Thanks for that, I will give that a try as well. I thought about the timing issue as well, but that seems awkward given the the actual login page is hosted by the ID server? (i.e. the standard login screen in ID). One would assume that if that page gets presented prior to navigation that ID server MUST be up an running as it would otherwise not be able to present the open-id config? And if I try to query the openid directly from browser it also directly responds. But thanks for the suggestion, I will give this a go! – mtholen Feb 18 '23 at 00:16
  • Otherwise it could be a DNS issue? – Tore Nestenius Feb 18 '23 at 11:34
  • I think the client downloads the discovery data before it redirect the user to IdentityServer and if it fails, I think the default is like 30-60 seconds until it tries again? I would add logging to get a better feeling for what is going on – Tore Nestenius Feb 18 '23 at 11:52
  • I have added yours above and try to see what's happening. From what I can gather now the problem appears when translating the initial openid-configuration response into the subsequent request, the jwks request. The translation between those should be done by the jwtbearerhandler which is where the error initiates. `fail: Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler[3]` Also trying to get a deeper understanding of the sequence of steps by more info from https://sandrino.dev/blog/aspnet-core-5-jwt-authorization – mtholen Feb 18 '23 at 11:56
  • By the way, in your code above, the `Console.WriteLine("@@@@ success: " + result.IsFaulted);` should be `Console.WriteLine("@@@@ success: " + (!result.IsFaulted));` as it otherwise logs `succes: True` when the `result.isFaulted=true` which would imply it failed as opposed to succeeded. :-) – mtholen Feb 18 '23 at 11:58
  • JwtBearer will when receiving the first token, call the discovery + JWKS endpoints on IdentityServer. see the added picture in my answer. – Tore Nestenius Feb 18 '23 at 12:25
  • How would one implement this waiting method as per the second picture that you have posted? Do you have a link or source information? – mtholen Feb 18 '23 at 14:20
  • I added a sample prototype I wrote earlier for one of my training classes to my answer. – Tore Nestenius Feb 18 '23 at 14:29
  • Great thanks, I'll give that a try tomorrow! Much appreciated – mtholen Feb 18 '23 at 14:34
  • Let us [continue this discussion in chat](https://chat.stackoverflow.com/rooms/251983/discussion-between-mtholen-and-tore-nestenius). – mtholen Feb 19 '23 at 00:04