Aspnetcore: dotnet core 2 app returning 502.3 error

[zhongj2]

Description

Occasionally, we are observing our dotnet core 2 application returning 502.3 errors.

The application is been served via IIS and we verified that the application process is indeed running and listening to a port. That exact port number is also been set in by environment variable ASPNETCORE_PORT for that process.

When attempting to telnet to the process on that port number, we are seeing Connect failed error.

Reproduce

Intermittent, unable to consistently reproduce.

Environment

Windows Server 2012
IIS 8
Dotnet Core 2

[buddyspike]

A bit more context to this issue:

• We run Kestral behind IIS with (aspnetcore module)
• When we start experiencing these 502s, the Kestral process is running and netstat proves that the process is listening on the designated port.
• The port Kestral is listening on is also correctly set in ASPNETCORE_PORT variable for w3wp process managed by IIS.
• The symptoms of our issue look quite similar to the ones described here https://github.com/aspnet/KestrelHttpServer/issues/1304. The only difference is we are running Kestral on Windows behind IIS.

[DaniilSokolyuk]

We have the same problem in the same environment, error in ~1% of all requests
Nginx with next upstream on errors saves us

[muratg]

This could happen for many different reasons -- it's hard to get an exact reason why you may be hitting this without a lot more details.

@shirhatti -- could you write down a summary somewhere with a list of possible issues where we can forward people to?

[halter73]

@DaniilSokolyuk Do you have nginx in front of IIS or are you seeing 502.3s directly from Kestrel?

[buddyspike]

@halter73 No nginx in our case. 502.3 is from IIS. Kestral is not responding at all (i.e. If we try to telnet via telnet localhost <kestral port registered with iis>, it times out).

[halter73]

@buddyspike Kestrel should reject direct requests unless you include the MS-ASPNETCORE-TOKEN header with the correct paring token. That said, you should get a 400 not a timeout.

So telnet times out even attempting to establish a connection? If so, you should collect a memory dump and see if there are any obvious deadlocks or pass it along to us.

[buddyspike]

@muratg Thanks. Happy provide further information you need to narrow it down. I have looked at a process dump taken when host is in this state. There were a few ConnectionAbortedExceptions in !dumpheap -stat output. In addition to that, we also enabled Trace and we can see certain messages like below (details are omitted for brevity) in the log just before process becomes useless.

SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481P\" started."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481Q\" started."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481P\" received FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481P\" disconnecting."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481P\" sending FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481P\" stopped."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481Q\" received FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481Q\" disconnecting."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481Q\" sending FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481Q\" stopped."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481R\" started."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481R\" received FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481R\" disconnecting."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481R\" sending FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481R\" stopped."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481S\" started."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481S\" received FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481S\" disconnecting."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481S\" sending FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481S\" stopped."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481T\" started."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481T\" received FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481T\" disconnecting."
SOURCE=Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv;   EVENT_MESSAGE="Connection id \"0HLC8377K481T\" sending FIN."
SOURCE=Microsoft.AspNetCore.Server.Kestrel;   EVENT_MESSAGE="Connection id \"0HLC8377K481T\" stopped."

[buddyspike]

@halter73 Thanks. Yes telnet fails to connect.

We do have a memory dump, however, getting it across to you could take a bit of effort due to our environment ;-). Will look for the deadlocks in the meantime.

[halter73]

@buddyspike what version of Kestrel?

[buddyspike]

@halter73 2.0.1

[buddyspike]

@halter73 !locks -v says 32 critical sections scanned but none of them are in locked state.
Then ran !syncblk and it does not report any locks either.

[DaniilSokolyuk]

@halter73 yeah, we have nginx in front of IIS, with Windows Server 2012, IIS 8, asp net windows hosting 2.0.5 , netcoreapp2.0 runtime
We do not see any errors in asp logger, errors are only in iis logs

[buddyspike]

@halter73 What's the best way to privately share the memory dump?

[halter73]

You can email a download link to the address listed in my github profile.

[effyteva]

Is anyone still investigating this? We seem to suffer from that same issue as well.

[Tratcher]

@effyteva do you have any data to add to the investigation?

[effyteva]

Yes @Tratcher,
After ~2 weeks of ongoing issues, I believe we figured it out.
We have quite a complex application, which on some cases combine nested DisplayTemplates/EditorTemplates/Partial Views and Asynchronous operations (on the Razor files).
Due to the fact the ViewEngine doesn't support async all the way (See this issue: https://github.com/aspnet/Mvc/issues/7416), templates are rendered using a synchronous operation.
Nest those templates with Asynchronous operations on the razor files, and we got ourselves a .NET tasks
deadlock.

For now, we temporarily resolved this issue by switching to an external TaskFactory, instead of using the simpler "await" command.

[npestana]

We suffer from this issue as well.
We have a complex application like @effyteva and we are doing the same thing, but we haven't tested if TaskFactory would solve our problem.
The strange thing is, this does not happen to us without IIS Integration, only on our dev environment.

[effyteva]

@npestana
My solution for now is a custom build of the ViewFeatures DLL, which supports Async all the way (EditorForAsync, DisplayForAsync etc), it works great.
If you want to give it a try, I attached the local NuGet package we created for it.

Local NuGet.zip

[aspnet-hello]

We periodically close 'discussion' issues that have not been updated in a long period of time.

We apologize if this causes any inconvenience. We ask that if you are still encountering an issue, please log a new issue with updated information and we will investigate.