Don't log stack traces for localhost bind failures. by Tratcher · Pull Request #1238 · aspnet/KestrelHttpServer

Tratcher · 2016-11-28T23:31:52Z

#1001
We're getting almost daily hits on this issue. A non-fatal error is being displayed like a fatal error and it distracts users from their real problems. Azure may or may not ever change their implementation.
@muratg @halter73

I also recommend we backport this to 1.0.x and 1.1.x.

Before:

dbug: Microsoft.AspNetCore.Hosting.Internal.WebHost[3]
      Hosting starting
warn: Microsoft.AspNetCore.Server.Kestrel[0]
      Unable to bind to http://localhost:19786 on the IPv6 loopback interface.
System.AggregateException: One or more errors occurred. ---> Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvException: Error -4089 EAFNOSUPPORT address family not supported
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.tcp_bind(UvTcpHandle handle, SockAddr& addr, Int32 flags) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\Libuv.cs:line 202
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvTcpHandle.Bind(ServerAddress address) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvTcpHandle.cs:line 48
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.TcpListenerPrimary.CreateListenSocket() in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\TcpListenerPrimary.cs:line 39
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Listener.<StartAsync>b__8_0(Object state) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Listener.cs:line 39
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.ListenerPrimary.<StartAsync>d__12.MoveNext() in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\ListenerPrimary.cs:line 54
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.KestrelEngine.CreateServer(ServerAddress address) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\KestrelEngine.cs:line 118
   at Microsoft.AspNetCore.Server.Kestrel.KestrelServer.Start[TContext](IHttpApplication`1 application) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\KestrelServer.cs:line 168
---> (Inner Exception #0) Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvException: Error -4089 EAFNOSUPPORT address family not supported
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.Libuv.tcp_bind(UvTcpHandle handle, SockAddr& addr, Int32 flags) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\Libuv.cs:line 202
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvTcpHandle.Bind(ServerAddress address) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Networking\UvTcpHandle.cs:line 48
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.TcpListenerPrimary.CreateListenSocket() in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\TcpListenerPrimary.cs:line 39
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Listener.<StartAsync>b__8_0(Object state) in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\Listener.cs:line 39
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.ListenerPrimary.<StartAsync>d__12.MoveNext() in C:\git\Universe\KestrelHttpServer\src\Microsoft.AspNetCore.Server.Kestrel\Internal\Http\ListenerPrimary.cs:line 54<---

dbug: Microsoft.AspNetCore.Hosting.Internal.WebHost[4]
      Hosting started
Hosting environment: Production
Content root path: D:\home\site\wwwroot\
Now listening on: http://localhost:19786
Application started. Press Ctrl+C to shut down.

After:

dbug: Microsoft.AspNetCore.Hosting.Internal.WebHost[3]
      Hosting starting
info: Microsoft.AspNetCore.Server.Kestrel[0]
      Unable to bind to http://localhost:20266 on the IPv6 loopback interface.
dbug: Microsoft.AspNetCore.Hosting.Internal.WebHost[4]
      Hosting started
Hosting environment: Production
Content root path: D:\home\site\wwwroot\
Now listening on: http://localhost:20266
Application started. Press Ctrl+C to shut down.

We could add an additional log for real fatal errors on line 185.

cesarblum · 2016-11-28T23:39:30Z

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

                            else
                            {
-                                _logger.LogWarning(0, ex, $"Unable to bind to {parsedAddress.ToString()} on the IPv4 loopback interface.");
+                                _logger.LogInformation(0, $"Unable to bind to {parsedAddress.ToString()} on the IPv4 loopback interface.");


I think this should still be a warning - just don't pass the exception to the log call.

Warnings should be actionable, this isn't. I'm tempted to downgrade it to debug.

This warning could very well be actionable if you're not running in a shared hosting environment.

How does shared hosting make the error any different? It's fatal or it isn't.
Yes we know Azure has one specific issue, but overall we've decided that only failing on one protocol isn't fatal.

Because if you have full control over the host, you could see why binding to either IPv4 or IPv6 failed and then fix it. Typically it's some OS-level configuration, no?

You could also change "localhost" to "127.0.01" or "[::1]" in UseUrls() if you expect to only bind to one interface.

Depends on the error. What errors have you seen that we may be hiding here?

The -4089 EAFNOSUPPORT error.

halter73 · 2016-11-28T23:44:14Z

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

                            }
                            else
                            {
-                                _logger.LogWarning(0, ex, $"Unable to bind to {parsedAddress.ToString()} on the IPv6 loopback interface.");


What if the error isn't -4089 EAFNOSUPPORT? Should we special case just that error code and log the exception otherwise? If it is something else, it would be good to know.

I could include the error code. We don't need the stack trace regardless.

Yeah I was thinking about that too. We know it's a benign error specifically on Azure, but it's still a potentially legit error in other environments.

I think the scariest part of the log message is the stack trace. How about logging the exception message only?

And UvException.Message. That would leave out the stack trace. Sometimes libuv uses different error codes on different platforms, so having the message could be useful.

Looks like the StatusCode is in the Message, no need to duplicate.

Unable to bind to http://localhost:27574 on the IPv6 loopback interface. (Error -4089 EAFNOSUPPORT address family not supported)

halter73 · 2016-11-29T00:02:23Z

LGTM after it's changed back to a warning. If there was an easy way to force an EAFNOSUPPORT error, I would ask for a test, but I think that's more complicated than it's worth.

cesarblum · 2016-11-29T00:21:15Z

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

                        catch (AggregateException ex) when (ex.InnerException is UvException)
                        {
-                            if ((ex.InnerException as UvException).StatusCode == Constants.EADDRINUSE)
+                            var uvEx = (UvException)ex.InnerException;


cesarblum · 2016-11-29T00:22:03Z

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

                            {
-                                _logger.LogWarning(0, ex, $"Unable to bind to {parsedAddress.ToString()} on the IPv4 loopback interface.");
-                                exceptions.Add(ex.InnerException);
+                                _logger.LogInformation(0, $"Unable to bind to {parsedAddress.ToString()} on the IPv4 loopback interface. ({uvEx.Message})");


Change to ...interface: ({uvEx.Message}) (i.e. colon instead of period)

cesarblum · 2016-11-29T00:22:10Z

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

                            {
-                                _logger.LogWarning(0, ex, $"Unable to bind to {parsedAddress.ToString()} on the IPv6 loopback interface.");
-                                exceptions.Add(ex.InnerException);
+                                _logger.LogInformation(0, $"Unable to bind to {parsedAddress.ToString()} on the IPv6 loopback interface. ({uvEx.Message})");


Change to ...interface: ({uvEx.Message}) (i.e. colon instead of period)

cesarblum · 2016-11-29T00:22:15Z

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

                        catch (AggregateException ex) when (ex.InnerException is UvException)
                        {
-                            if ((ex.InnerException as UvException).StatusCode == Constants.EADDRINUSE)
+                            var uvEx = (UvException)ex.InnerException;


1.1.x)

1.0.x)

Tratcher added this to the 1.2.0 milestone Nov 28, 2016

Tratcher self-assigned this Nov 28, 2016

dnfclas added the cla-already-signed label Nov 28, 2016

cesarblum suggested changes Nov 28, 2016

View reviewed changes

halter73 reviewed Nov 28, 2016

View reviewed changes

cesarblum suggested changes Nov 29, 2016

View reviewed changes

Tratcher force-pushed the tratcher/localhostwarn branch from 6c9e55c to a82270e Compare November 29, 2016 00:33

#1001 don't log stack traces for localhost bind failures.

53e5c3d

Tratcher force-pushed the tratcher/localhostwarn branch from a82270e to 53e5c3d Compare November 29, 2016 00:36

Tratcher merged commit 53e5c3d into dev Nov 29, 2016

Tratcher deleted the tratcher/localhostwarn branch November 29, 2016 00:36

Tratcher mentioned this pull request Nov 29, 2016

Patch Azure IPv6 stack trace log #1239

Closed

muratg modified the milestones: 1.2.0, 2.0.0 Jan 12, 2017

This was referenced Apr 7, 2017

Don't log stack traces for localhost bind failures (port fix to 1.0.x) #1628

Closed

[1.1.2] Don't log stack traces for localhost bind failures (port fix to 1.1.x) #1629

Closed

natemcmaster pushed a commit that referenced this pull request Apr 13, 2017

Don't log stack traces for localhost bind failures (#1238, backported to

a1ce476

1.1.x)

natemcmaster mentioned this pull request Apr 13, 2017

[1.1.2] Don't log stack traces for localhost bind failures #1677

Merged

natemcmaster pushed a commit that referenced this pull request Apr 13, 2017

Don't log stack traces for localhost bind failures (#1238, backported to

26c0728

1.0.x)

natemcmaster mentioned this pull request Apr 13, 2017

[1.0.4] Don't log stack traces for localhost bind failures #1679

Merged

halter73 mentioned this pull request Jun 30, 2017

On Azure deployment, getting "Unable to bind to http://localhost:9410 on the IPv6 loopback interface." #1001

Closed

Conversation

Tratcher commented Nov 28, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

halter73 commented Nov 29, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants