dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.36k stars 9.99k forks source link

The thrown exception's message is completely useless... #44895

Closed mobycorp closed 1 year ago

mobycorp commented 1 year ago

Is there an existing issue for this?

Describe the bug

When an ASP.NET/gRPC application is first starting, it configures its http or https endpoints. If something is not configured correctly the application throws an error which is completely useless! The offending error is:

System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProvider.GetService(Type serviceType, ServiceProviderEngineScope serviceProviderEngineScope)
   at Microsoft.Extensions.DependencyInjection.ServiceProvider.GetService(Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetService[T](IServiceProvider provider)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.WaitForShutdownAsync(IHost host, CancellationToken token)
   at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.WaitForShutdown(IHost host)
   at Program.<Main>$(String[] args) in D:\Development\Moby\Dev\MobyFileTransferServices\MobyFileTransferServices\Program.cs:line 206.

I have found that if any of the following occurs, this exception is thrown:

  1. If the port is incorrect
  2. If the TLS certificate is not found
  3. If the TLS certificate's password is not correct
  4. and there are others that I will add to this list when I can remember what they are

The internal code (either ASP.NET or gRPC - I am posting this in both forums) knows why it is throwing the exception so why not just say why the exception is being thrown! The Object name: 'IServiceProvider' message is a true red herring and completely useless. As I have come to have more experience on getting this to work, I grow more agitated in the lack of quality of that message. Look, getting SSL to work is hard enough to begin with. Help your developer community by throwing a better, more specific error!!!

For completeness' sage, I am including my Kestrel configuration. appsettings:

    "Kestrel": {
        "EndpointDefaults": {
            "Protocols": "Http2",
            "SslProtocols": [ "Tls12" ]
        },
        "Endpoints": {
            "Https1": {
                "Certificate": {
                    "Password": "123456",
                    "Path": "localhost.pfx"
                },
                "Url": "https://*:30054"
            }
        }
    }

program.cs:

    // Add services to the container.
    _ = builder.Services.AddGrpc (grpcServiceOptions => {
        logger?.Debug ("Configuring presence intercepter...");
        grpcServiceOptions.Interceptors.Add<PresenceInterceptor> ();
        _ = grpcServiceOptions.EnableDetailedErrors = true;
    });

There is nothing special about this configuration. It's very simple. Please provide better messages as to why this initialization fails!!!

Regards, Steve Miller

Expected Behavior

Provide an explanatory message that describes the ACTUAL reason the exception is being thrown!!!

Steps To Reproduce

No response

Exceptions (if any)

No response

.NET Version

7.0.100-rc.2.22477.23 but I'm actually using .NET 6

Anything else?

NOTE: I have downloaded both the gRPC and ASP.NET repositories and can't even find the string "Cannot access a disposed object" in the code... I have no idea where this message is being thrown from...

davidfowl commented 1 year ago

The Object name: 'IServiceProvider' message is a true red herring and completely useless.

I'm not sure that's true. At least, based on the information provided I don't see another explanation for the error as yet. Can you share the entire application or share more of the logic in Program.cs? It's possible something is being disposed prematurely during shutdown causing this problem.

davidfowl commented 1 year ago

PS: Turning on verbose logging is another way to get more information about what might be happening.

mobycorp commented 1 year ago

Hi David,

Thanks for your input!! Looking at your credentials, you are exactly the right person I need to talk to!!! :-)

  1. I have logging set to Trace so I am getting the most verbose output.
  2. As I said, this one error is triggered by multiple causes that I listed (missing cert, invalid cert, missing password, password mismatch, incorrect port, and incorrect protocol i.e. https vs http).
  3. All of these things trigger this one error, so the message text returned by this error is bogus. As for sharing code, this happens on app startup so the Kestrel config and the tiny delegate for AddGrpc call. With that said, I am trying to setup some other callbacks that I think are triggered when certificate validation is occurring, but so far I'm not getting those breakpoints to hit.

Here is the additional code I added to program.cs:

    _ = builder.Services.AddAuthentication (CertificateAuthenticationDefaults.AuthenticationScheme)
        .AddCertificate (certificateAuthenticationOptions => {
            certificateAuthenticationOptions.AllowedCertificateTypes = CertificateTypes.All;
            certificateAuthenticationOptions.Events = new CertificateAuthenticationEvents {
                OnAuthenticationFailed = certificateAuthenticationFailedContext => {

                    certificateAuthenticationFailedContext.NoResult ();

                    certificateAuthenticationFailedContext.Response.StatusCode = 403;
                    certificateAuthenticationFailedContext.Response.ContentType = "text/plain";
                    certificateAuthenticationFailedContext.Response.WriteAsync (certificateAuthenticationFailedContext.Exception.ToString ()).Wait ();

                    return Task.CompletedTask;
                },
                OnCertificateValidated = certificateValidatedContext => {

                    var claims = new[] {
                        new Claim (ClaimTypes.Name, certificateValidatedContext.ClientCertificate.Subject, ClaimValueTypes.String, certificateValidatedContext.Options.ClaimsIssuer)
                    };

                    certificateValidatedContext.Principal = new ClaimsPrincipal (new ClaimsIdentity (claims, certificateValidatedContext.Scheme.Name));

                    Console.WriteLine ($"Client certificate thumbprint: {certificateValidatedContext.ClientCertificate.Thumbprint}");
                    Console.WriteLine ($"Client certificate subject: {certificateValidatedContext.ClientCertificate.Subject}");

                    certificateValidatedContext.Success ();

                    return Task.CompletedTask;
                },
                OnChallenge = certificateChallengeContext => {

                    return Task.CompletedTask;
                }
            };
        });

    ServicePointManager.ServerCertificateValidationCallback =
        delegate (object sender, X509Certificate? certificate, X509Chain? chain, SslPolicyErrors sslPolicyErrors) {
            return true;
        };

This is some code I copied from a text, "Microservices Communication in .NET Using gRPC".

I think that somewhere in the ASP.NET code the error manifests itself and it is being caught in another try block and it loses the context of the original message... That is my observation anyway...

Thoughts? Steve

davidfowl commented 1 year ago

Can you show the try catch? It looks like the exception is coming from WaitForShutdown but I'd like to better understand the code flow that causes this to happen.

mobycorp commented 1 year ago

The try/catch is not in my code… it’s in your code somewhere. I downloaded the aspnet and gRPC repos and did a string search for exception names and message text and couldn’t find it so I am only speculating, but it’s not in my code. I have overloaded every delegate and callback in my program.cs file as well as setting a specific break in the exceptions window for the exceptions and the code does not stop anywhere during startup.

On Sat, Nov 5, 2022 at 11:20 AM David Fowler @.***> wrote:

Can you show the try catch? It looks like the exception is coming from WaitForShutdown but I'd like to better understand the code flow that causes this to happen.

— Reply to this email directly, view it on GitHub https://github.com/dotnet/aspnetcore/issues/44895#issuecomment-1304605146, or unsubscribe https://github.com/notifications/unsubscribe-auth/AOPRYYO63JN4RSLTCF7RJNTWG2QNTANCNFSM6AAAAAARX5U7CA . You are receiving this because you authored the thread.Message ID: @.***>

davidfowl commented 1 year ago

Can you reproduce this at will? You should be able to debug the original exception (turning on first chance exceptions in the debugger) and figure out where things are falling apart. All I'm looking for are repro steps so I can debug this myself 😅

mobycorp commented 1 year ago

Yes, I can. (I do it more than I wish!! ;-) ) I will try to gin up a repo and upload it to github. I will get to that later today! Thanks so much for your help...

ghost commented 1 year ago

Hi @mobycorp. We have added the "Needs: Author Feedback" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

ghost commented 1 year ago

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. If it is closed, feel free to comment when you are able to provide the additional information and we will re-investigate.

See our Issue Management Policies for more information.

mobycorp commented 1 year ago

@davidfowl - I was going to come back and update this after my list of issues regarding this error after some of them manifest themselves... I am once again listing this as a gRPC issue (but it may be a purely Kestrel issue).

I was installing an update of one of my services on an Ubuntu box and found this one again. When I use systemctl to stop a service, it does not always close the port that the app was using. If you try to start an app on a port that is locked, you will get this error. Again, the error displayed has NOTHING to do with the actual error!! I have run across at least three instances of this error being propagated and only found them by painstaking debugging. Seeing the ACTUAL cause would have saved me at least three days of development!!!

ghost commented 1 year ago

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. If it is closed, feel free to comment when you are able to provide the additional information and we will re-investigate.

See our Issue Management Policies for more information.

mobycorp commented 1 year ago

@davidfowl What is it you want me to do? There is no way I can debug this code as it is in your dlls. It happens with too much frequency. As I have said, there are at least three conditions that cause an error and your try/catch blocks are throwing the error that is thrown by internal code and, thus, the actual error never percolates to the top of the stack. I am looking to you to find where this blasted 'IServiceProvider' exception is thrown and figure out the root cause. I am getting tired of seeing this error over and over and over again.

mobycorp commented 1 year ago

@davidfowl - Ok, you said a key phrase that I probably missed earlier... I just now setup a first chance exception handler and it does throw some good information:

warn: Microsoft.AspNetCore.Server.Kestrel[0]
      Overriding address(es) 'https://localhost:5001/, http://localhost:5000/'. Binding to endpoints defined via IConfiguration and/or UseKestrel() instead.
FirstChanceException event raised in MobyMessageServices: Only one usage of each socket address (protocol/network address/port) is normally permitted.
FirstChanceException event raised in MobyMessageServices: Only one usage of each socket address (protocol/network address/port) is normally permitted.
FirstChanceException event raised in MobyMessageServices: Only one usage of each socket address (protocol/network address/port) is normally permitted.
FirstChanceException event raised in MobyMessageServices: Only one usage of each socket address (protocol/network address/port) is normally permitted.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Failed to bind to address https://[::]:40102: address already in use.
FirstChanceException event raised in MobyMessageServices: Cannot access a disposed object.
Object name: 'IServiceProvider'.
FirstChanceException event raised in MobyMessageServices: Cannot access a disposed object.
Object name: 'IServiceProvider'.

And, so you can see this 'IServiceProvider' error is a complete red herring and lends nothing to troubleshooting. I have indicated there are several conditions that will trip this error such as the issue you are seeing here: that a https port is locked by another process. I have found this can happen when a previous process does not shut down properly. With all that said, I feel that masking the error in the first place is the actual problem. How does a silent startup that only shows 'IServiceProvider' help anything? Also, I am guessing that the fact that the same set of errors being repeated is due to some retry logic in kestrel???

For what it's worth: I have upgraded my solution to .NET 7. This is a gRPC service. Even though you won't be able to run this code, if you can see what I am doing wrong (or accept the fact that I am correct in my assertion the error is being masked and not at all helpful to a debugging session...)

IConfiguration configuration;

NLog.ILogger? logger = null;

X509Certificate2? _certificate;

try {
    #region Configure the application's builders.

    // Set an app-wide unhandled exception handler.
    AppDomain.CurrentDomain.UnhandledException += AppUnhandledException;

    // Establish a First Chance Exception handler.
#pragma warning disable CS8622 // Nullability of reference types in type of parameter doesn't match the target delegate (possibly because of nullability attributes).
    AppDomain.CurrentDomain.FirstChanceException +=
       (object source, FirstChanceExceptionEventArgs e) => Console.WriteLine ("FirstChanceException event raised in {0}: {1}",
               AppDomain.CurrentDomain.FriendlyName, e.Exception.Message);
#pragma warning restore CS8622 // Nullability of reference types in type of parameter doesn't match the target delegate (possibly because of nullability attributes).

    var webApplicationOptions = new WebApplicationOptions {
        Args = args,
        ContentRootPath = WindowsServiceHelpers.IsWindowsService ()
            ? AppContext.BaseDirectory
            : default
    };

    var builder = WebApplication.CreateBuilder (webApplicationOptions);
    var webHostBuilder = builder.WebHost;

    // What environment are we running?  It could be either Development
    // or Production.  This is used to get the correct configuration from
    // the appsettings.Development.json or appsettings.Production.json
    // files.
    var environment = builder.Environment.EnvironmentName;

    #endregion

    #region Configure Logging

    // Configure logging.
#pragma warning disable ASP0011 // Suggest using builder.Logging over Host.ConfigureLogging or WebHost.ConfigureLogging
    _ = webHostBuilder.ConfigureLogging (options => {

        var archiveFileName = string.Empty;
        var fileName = string.Empty;

        // We need to programmatically set the log file folder location
        // based on the operating system.
        if (RuntimeInformation.IsOSPlatform (OSPlatform.Windows)) {
            archiveFileName = @"C:\Users\Public\Documents\Moby\Logs\MobyMessageServices.{#}.log";
            fileName = @"C:\Users\Public\Documents\Moby\Logs\MobyMessageServices.log";
        } else if (RuntimeInformation.IsOSPlatform (OSPlatform.OSX) || RuntimeInformation.IsOSPlatform (OSPlatform.Linux)) {
            archiveFileName = "/opt/moby/logs/MobyMessageServices.{#}.log";
            fileName = "/opt/moby/logs/MobyMessageServices.log";
        }

        var config = new NLog.Config.LoggingConfiguration ();
        var fileTarget = new NLog.Targets.FileTarget {
            ArchiveDateFormat = "yyyyMMdd",
            ArchiveEvery = NLog.Targets.FileArchivePeriod.Day,
            ArchiveFileName = archiveFileName,
            ArchiveNumbering = NLog.Targets.ArchiveNumberingMode.Date,
            FileName = fileName,
            Layout = "${longdate} ${level:uppercase=true:padding=-8} ${message}",
            Name = "file"
        };

        config.AddRule (LogLevel.Debug, LogLevel.Fatal, fileTarget, "*");

        _ = options.AddNLog ();

        // Get the logger.
        LogManager.Configuration = config;

        logger = NLogBuilder.ConfigureNLog (LogManager.Configuration).GetCurrentClassLogger () as NLog.ILogger ?? throw new NullReferenceException (nameof (logger));

        // Set the global logger for static classes.
        HttpHelpers.Logger = logger;
        ApplicationControl.Logger = logger;

        // Log the App Start preamble in the log file.
        ApplicationControl.LogAppStart ("Message");
    });
#pragma warning restore ASP0011 // Suggest using builder.Logging over Host.ConfigureLogging or WebHost.ConfigureLogging

    #endregion

    #region Configure Database

    logger?.Debug ($"Current Directory: {AppContext.BaseDirectory}");

#pragma warning disable ASP0013 // Suggest switching from using Configure methods to WebApplicationBuilder.Configuration
    _ = webHostBuilder.ConfigureAppConfiguration (iConfigurationBuilder =>
        configuration = iConfigurationBuilder
            .SetBasePath (AppContext.BaseDirectory)
            .AddJsonFile ($"appsettings.json", optional: true, reloadOnChange: false)
            .Build ());
#pragma warning restore ASP0013 // Suggest switching from using Configure methods to WebApplicationBuilder.Configuration

    var logisticsConfigurationVersion = builder.Configuration.GetValue<string> ("AppSettings:LogisticsConfigurationVersion");

    logger?.Debug ("Creating database");
    logger?.Debug ($"Logistics Configuration Version: {logisticsConfigurationVersion}");

    Guard.IsNotNullOrEmpty (logisticsConfigurationVersion);

    MobyDatabaseService.CreateDatabase (
        LogisticsDatabaseConstants.DatabaseName,
        logisticsConfigurationVersion);

    logger?.Debug ("Database created");

    #endregion

    #region Configure Service Host Containers

    // Configure the app to run as a Windows Service (Windows only).
    _ = builder.Host.UseWindowsService (windowsServiceLifetimeOptions =>
            windowsServiceLifetimeOptions.ServiceName = "Moby Message Services");

    // Configure the app to run as a linux daemon.
    _ = builder.Host.UseSystemd ();

    #endregion

    #region Configure gRPC

    _ = builder.WebHost.ConfigureKestrel (kestrelServiceOptions => {

        _certificate = new X509Certificate2 (
            fileName: "C:\\Users\\Public\\Documents\\Moby\\Logistics\\moby-client.pfx",
            password: cert_password);

        Guard.IsNotNull (_certificate);

        kestrelServiceOptions.ConfigureHttpsDefaults (httpsConnectionAdapterOptions => {

            httpsConnectionAdapterOptions.ClientCertificateMode = ClientCertificateMode.RequireCertificate;
            httpsConnectionAdapterOptions.ClientCertificateValidation = ValidateClientCertificate;
            httpsConnectionAdapterOptions.ServerCertificate = _certificate;
        });
    });

    _ = builder.Services.AddTransient<X509CertificateServices> ();

    _ = builder.Services.AddAuthentication (CertificateAuthenticationDefaults.AuthenticationScheme)
        .AddCertificate (options => {

            options.AllowedCertificateTypes = CertificateTypes.All;
            options.RevocationFlag = X509RevocationFlag.ExcludeRoot;
            options.RevocationMode = X509RevocationMode.NoCheck;

            options.Events = new CertificateAuthenticationEvents {

                OnCertificateValidated = context => {

                    var validationService = context.HttpContext.RequestServices.GetService<X509CertificateServices> ();

                    if (validationService == null) {
                        context.Fail ("validation service not found");
                    } else {
                        if (validationService.ValidateCertificate (context.ClientCertificate)) {
                            context.Success ();
                        } else {
                            context.Fail ("invalid cert");
                        }
                    }

                    return Task.CompletedTask;
                },
                OnAuthenticationFailed = context => {

                    context.Fail ("invalid cert");

                    return Task.CompletedTask;
                }
            };
        });

    _ = builder.Services.AddAuthorization ();

    // Add services to the container.
    _ = builder.Services.AddGrpc (grpcServiceOptions => {

        logger?.Debug ("Configuring presence intercepter...");

        grpcServiceOptions.Interceptors.Add<PresenceInterceptor> ();

        _ = grpcServiceOptions.EnableDetailedErrors = true;
    });

    #endregion

    #region Add items to the injection container

    logger?.Debug ("Adding support services to the injection container...");

    // Add Moby-specific components as singletons.
    _ = builder.Services.AddSingleton<IMobyServiceConfigurationManager, MobyServiceConfigurationManager> ();
    _ = builder.Services.AddSingleton<IMobyMessageService, MobyMessageService> ();

    #endregion

    #region Set the configuration; build the app object.

    // Get the application builder so we can add services to the mix...
    var app = builder.Build ();

    #endregion

    #region Initalize configuration manager and microservices

    logger?.Debug ("Initializing support services...");

    // Add services to the container.
    var configurationManager = app.Services.GetService<IMobyServiceConfigurationManager> ();

    if (configurationManager == null) {
        logger?.Debug ("Moby configuration cannot be determined... shutting down...");

        Environment.Exit (-1);
    }

    MobyDatabaseService.LogisticsConfigurationVersion = configurationManager.LogisticsConfigurationVersion;

    #endregion

    #region Start the application

    _ = app.UseRouting ();

    _ = app.UseAuthentication ();
    _ = app.UseAuthorization ();

    // Configure the HTTP request pipeline.
    _ = app.MapGrpcService<MobyMessageService> ();
    _ = app.MapGet ("/", () =>
        "Communication with gRPC endpoints must be made through a gRPC client. To learn how to create a client, visit: https://go.microsoft.com/fwlink/?linkid=2086909");

    logger?.Debug ("Moby Message Services configured and ready to run!");

    // Let 'er rip!
    _ = app.RunAsync ();

    logger?.Debug ("Moby Message Services running!");

    // We're going down! Down, down, down, down, down!
    app.WaitForShutdown ();

    #endregion
} catch (Exception ex) {
    logger?.Error (string.Format (ExceptionResources.ExceptionMessageFormat, ex));
}

void AppUnhandledException (object sender, UnhandledExceptionEventArgs e) =>
    logger?.Error (string.Format (ExceptionResources.ExceptionMessageFormat, e.ExceptionObject));

bool ValidateClientCertificate (X509Certificate2 x509Certificate2, X509Chain? x509Chain, SslPolicyErrors sslPolicyErrors) {

    Guard.IsNotNull (_certificate);

    if (sslPolicyErrors != SslPolicyErrors.None) return false;

    if (!x509Certificate2.Issuer.Contains ("CN=localhost")) return false;
    if (!x509Certificate2.Subject.Contains ("CN=localhost")) return false;
    if (!x509Certificate2.Thumbprint.ToUpper ().Equals (_certificate.Thumbprint)) return false;

    return true;
};

I am doing the kestrel configuration in my appsettings.json file:

{
    "AllowedHosts": "*",
    "Kestrel": {
        "EndpointDefaults": {
            "ClientCertificateMode": "RequireCertificate",
            "Protocols": "Http2",
            "SslProtocols": [ "Tls12" ]
        },
        "Endpoints": {
            "HttpsGrpc": {
                "Certificate": {
                    "Password": "password goes here...",
                    "Path": "C:\\Users\\Public\\Documents\\Moby\\Logistics\\moby-client.pfx"
                },
                "Protocols": "Http2",
                "Url": "https://*:40102"
            }
        }
    },
    "Logging": {
        "LogLevel": {
            "Default": "Trace",
            "Grpc": "Trace",
            "Microsoft.AspNetCore": "Trace"
        }
    }
}

How can I test that the port I am wanting to use is locked by another process. Kestrel is obviously doing this.

I am a single developer working on a project that should have 10 developers. I doing the full stack so this week I may be in one of my 7 gRPC services or in my MAUI app. I have a bunch of submitted a bunch of issues to both teams so it is hard for me to track all of the feedback I am getting from MS... flimsy excuse, yes, but it is also my reality!! ;-)

ghost commented 1 year ago

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. If it is closed, feel free to comment when you are able to provide the additional information and we will re-investigate.

See our Issue Management Policies for more information.

ghost commented 1 year ago

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. If it is closed, feel free to comment when you are able to provide the additional information and we will re-investigate.

See our Issue Management Policies for more information.

ghost commented 1 year ago

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. If it is closed, feel free to comment when you are able to provide the additional information and we will re-investigate.

See our Issue Management Policies for more information.