Generic host/kestrel known cases proper error handling

[maxcherednik]

Summary

I would like to provide a better operations experience and reduce the maintenance burden.

What we have right now:

public class Program
    {
        public static async Task<int> Main(string[] args)
        {
            await CreateHostBuilder(args).Build().RunAsync();

            return 0;
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder => { webBuilder.UseStartup<Startup>(); });
    }

If someone from the ops team, happened to install our application on a server where there is something already running on port 443, then they will receive and ugly stack trace with critical log level:

crit: Microsoft.AspNetCore.Server.Kestrel[0]
      Unable to start Kestrel.
      System.IO.IOException: Failed to bind to address https://127.0.0.1:5001: address already in use.
       ---> Microsoft.AspNetCore.Connections.AddressInUseException: Only one usage of each socket address (protocol/network address/port) is normally permitted.
       ---> System.Net.Sockets.SocketException (10048): Only one usage of each socket address (protocol/network address/port) is normally permitted.
         at System.Net.Sockets.Socket.UpdateStatusAfterSocketErrorAndThrowException(SocketError error, String callerName)
         at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress)
         at System.Net.Sockets.Socket.Bind(EndPoint localEP)
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketConnectionListener.<Bind>g__BindSocket|13_0(<>c__DisplayClass13_0& )
         --- End of inner exception stack trace ---
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketConnectionListener.<Bind>g__BindSocket|13_0(<>c__DisplayClass13_0& )
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketConnectionListener.Bind()
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.SocketTransportFactory.BindAsync(EndPoint endpoint, CancellationToken cancellationToken)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TransportManager.BindAsync(EndPoint endPoint, ConnectionDelegate connectionDelegate, EndpointConfig endpointConfig)
         at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServerImpl.<>c__DisplayClass29_0`1.<<StartAsync>g__OnBind|0>d.MoveNext()
      --- End of stack trace from previous location ---
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.BindEndpointAsync(ListenOptions endpoint, AddressBindContext context)
         --- End of inner exception stack trace ---
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.BindEndpointAsync(ListenOptions endpoint, AddressBindContext context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.LocalhostListenOptions.BindAsync(AddressBindContext context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.AddressesStrategy.BindAsync(AddressBindContext context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.AddressBinder.BindAsync(IEnumerable`1 listenOptions, AddressBindContext context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServerImpl.BindAsync(CancellationToken cancellationToken)
         at Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServerImpl.StartAsync[TContext](IHttpApplication`1 application, CancellationToken cancellationToken)

In this stack trace there is only one line of useful information, the rest is just noise, which is not need for an ops person.
Would not it be better to log something like this:

It seems that there is another application running on port (port number here)

My general judgment around stack traces in the log file is pretty simple: you see a stack trace - it a bug!

@Tratcher says here that failing to bind is fatal. Yes it is for the kestrel, but it is a known case.

The case is just a misconfiguration of the environment where an ops person picked either the wrong port or picked the wrong machine to install the application. If we look at this problem from such perspective, it does not deserve a huge noisy stack trace in the log file.

There is another use case of misconfiguration which happens to us like every day.
An ops person installs the application with https and somehow forgets/misconfigures the certificates. Again, there is no need to scary an ops person with an ugly stack trace. Taking into account the fact that not all the ops guys are equally experienced, they often just come back to the developers and ask: what does this stack trace mean?

Work around example

This is what I have to do now.

public class Program
    {
        public static async Task<int> Main(string[] args)
        {

            var host = CreateHostBuilder(args).Build();
            
            try
            {
                await host.RunAsync();
            }
            //catch(AnotherException e) // related to a fact that the application was configured to run with https, but administrator forgot/misconfigured ssl certificates  
            //{
                // var logger = host.Services.GetRequiredService<ILogger<Program>>();
                //
                // logger.LogError("The application was configured to run with https, but no certificates found...");
                //     
                // return -100; // return known error code
            //}
            catch (IOException e) when (e.InnerException is AddressInUseException)
            {
                var logger = host.Services.GetRequiredService<ILogger<Program>>();
                
                // it would be cool to speak in a human language without any stack traces
                logger.LogError("It seems that there is another application running on port (80)");
                
                return -1; // return known error code 
            }

            return 0;
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder => { webBuilder.UseStartup<Startup>(); });
    }

Obviously there are multiple things wrong here:

• I am catching exceptions which are not officially described on the generic host level
• By default it is still printing the stack trace from here:

  aspnetcore/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs

  Line 208 in c925f99

  catch (Exception ex)

• I have to disable the logging from the kestrel, which is probably fine as long as you rethrow the exception.

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information",
      "Microsoft.AspNetCore.Server.Kestrel": "None"
    }
  },
  "AllowedHosts": "*"
}

• The logger is not available anymore, cause everything is disposed already.

Design proposition

It is difficult to propose something specific, cause I don't have the full picture.

Requirements:

• Possibility to control the exit code to be non-zero.
• Possibility to control the message written to the log file

Old references

#948
#2001

[BrennanConroy]

Triage: We should consider special casing this specific exception and only logging the message for "address in use".

We've moved this issue to the Backlog milestone. This means that it is not going to be worked on for the coming release. We will reassess the backlog following the current release and consider this item at that time. To learn more about our issue management process and to have better expectation regarding different types of issues you can read our Triage Process.

[BerserkerDotNet]

Hi, @BrennanConroy, I've sent a PR to special case AddressInUseException.

@maxcherednik, in my PR I address the issue of the stack trace being logged, but it will still throw an unhandled exception that you would need to handle by yourself.

If you're interested in simplifying the code you have for catching the exception, you can write an extension method to the IHost and handle your case there.

[davidfowl]

Thanks