Client connection is closed after each request

[arisewanggithub]

Hi there,

We have an Asp.net 5 app which is in Azure AKS behind AppGateway. I find that our service container always has a lot of connections in TIME_WAIT state to the local 80 port. These connections are from AppGateway to our service.
Based on my test, after each request to our service, our service will close the connection. So though the AppGateway has only limited instances, based on the traffic, there can be a huge amount of local sockets in TIME_WAIT state as the connections are not kept alive and reused. When the traffic is low, this is not a big issue. But when the traffic is high, it can consume up all the available ports quickly.
I wonder why asp.net core (.net 5) has this behavior. Can it be changed?

[Tratcher]

ASP.NET Core uses keep-alive connections by default. The app or gateway would have to be opting out of keep-alives by one of these mechanisms:

• The gateway using HTTP/1.0 instead of 1.1 or 2.0
• The gateway sending Connection: close
• The app sending Connection: close on responses
• The client sending large request bodies and the app not consuming them. The server will try to drain them but only to a point.
• Short lived WebSockets

[arisewanggithub]

The above request was sent from my local browser to my local service in local dev environment. It's not from app gateway. I got a new log after enabled connection logging. BTW, locally I'm using .net core 3.1 now, not .net 5.
dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
Hosting starting
dbug: Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer[2]
Failed to locate the development https certificate at '(null)'.
warn: Microsoft.AspNetCore.Server.Kestrel[0]
Overriding address(es) 'http://localhost:52727/'. Binding to endpoints defined in UseKestrel() instead.
info: Microsoft.Hosting.Lifetime[0]
Now listening on: http://0.0.0.0:52727
info: Microsoft.Hosting.Lifetime[0]
Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
Hosting environment: Development
dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
Hosting started
dbug: Microsoft.AspNetCore.Server.Kestrel[39]
Connection id "0HM61HH86TCH3" accepted.
dbug: Microsoft.AspNetCore.Server.Kestrel[1]
Connection id "0HM61HH86TCH3" started.
dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
ReadAsync[589] 47 45 54 20 2F 68 65 61 6C 74 68 20 48 54 54 50 2F 31 2E 31 0D 0A 48 6F 73 74 3A 20 6C 6F 63 61 6C 68 6F 73 74 3A 35 32 37 32 37 0D 0A 43 6F 6E 6E 65 63 74 69 6F 6E 3A 20 6B 65 65 70 2D 61 6C 69 76 65 0D 0A 43 61 63 68 65 2D 43 6F 6E 74 72 6F 6C 3A 20 6D 61 78 2D 61 67 65 3D 30 0D 0A 55 70 67 72 61 64 65 2D 49 6E 73 65 63 75 72 65 2D 52 65 71 75 65 73 74 73 3A 20 31 0D 0A 55 73 65 72 2D 41 67 65 6E 74 3A 20 4D 6F 7A 69 6C 6C 61 2F 35 2E 30 20 28 57 69 6E 64 6F 77 73 20 4E 54 20 31 30 2E 30 3B 20 57 69 6E 36 34 3B 20 78 36 34 29 20 41 70 70 6C 65 57 65 62 4B 69 74 2F 35 33 37 2E 33 36 20 28 4B 48 54 4D 4C 2C 20 6C 69 6B 65 20 47 65 63 6B 6F 29 20 43 68 72 6F 6D 65 2F 38 38 2E 30 2E 34 33 32 34 2E 39 36 20 53 61 66 61 72 69 2F 35 33 37 2E 33 36 20 45 64 67 2F 38 38 2E 30 2E 37 30 35 2E 35 30 0D 0A 41 63 63 65 70 74 3A 20 74 65 78 74 2F 68 74 6D 6C 2C 61 70 70 6C 69 63 61 74 69 6F 6E 2F 78 68 74 6D 6C 2B 78 6D 6C 2C 61 70 70 6C 69 63 61 74 69 6F 6E 2F 78 6D 6C 3B 71 3D 30 2E 39 2C 69 6D 61 67 65 2F 77 65 62 70 2C 69 6D 61 67 65 2F 61 70 6E 67 2C 2A 2F 2A 3B 71 3D 30 2E 38 2C 61 70 70 6C 69 63 61 74 69 6F 6E 2F 73 69 67 6E 65 64 2D 65 78 63 68 61 6E 67 65 3B 76 3D 62 33 3B 71 3D 30 2E 39 0D 0A 53 65 63 2D 46 65 74 63 68 2D 53 69 74 65 3A 20 6E 6F 6E 65 0D 0A 53 65 63 2D 46 65 74 63 68 2D 4D 6F 64 65 3A 20 6E 61 76 69 67 61 74 65 0D 0A 53 65 63 2D 46 65 74 63 68 2D 55 73 65 72 3A 20 3F 31 0D 0A 53 65 63 2D 46 65 74 63 68 2D 44 65 73 74 3A 20 64 6F 63 75 6D 65 6E 74 0D 0A 41 63 63 65 70 74 2D 45 6E 63 6F 64 69 6E 67 3A 20 67 7A 69 70 2C 20 64 65 66 6C 61 74 65 2C 20 62 72 0D 0A 41 63 63 65 70 74 2D 4C 61 6E 67 75 61 67 65 3A 20 65 6E 2D 55 53 2C 65 6E 3B 71 3D 30 2E 39 2C 7A 68 2D 43 4E 3B 71 3D 30 2E 38 2C 7A 68 3B 71 3D 30 2E 37 0D 0A 0D 0A
GET /health HTTP/1.1\x0D\x0AHost: localhost:52727\x0D\x0AConnection: keep-alive\x0D\x0ACache-Control: max-age=0\x0D\x0AUpgrade-Insecure-Requests: 1\x0D\x0AUser-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.96 Safari/537.36 Edg/88.0.705.50\x0D\x0AAccept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9\x0D\x0ASec-Fetch-Site: none\x0D\x0ASec-Fetch-Mode: navigate\x0D\x0ASec-Fetch-User: ?1\x0D\x0ASec-Fetch-Dest: document\x0D\x0AAccept-Encoding: gzip, deflate, br\x0D\x0AAccept-Language: en-US,en;q=0.9,zh-CN;q=0.8,zh;q=0.7\x0D\x0A\x0D\x0A
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Request starting HTTP/1.1 GET http://localhost:52727/health
dbug: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[0]
Wildcard detected, all requests with hosts will be allowed.
dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
1 candidate(s) found for the request path '/health'
dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
Request matched endpoint 'Health checks'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Executing endpoint 'Health checks'
dbug: Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService[100]
Running health checks
dbug: Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService[101]
Health check processing completed after 5.6675ms with combined status Healthy
dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
WriteAsync[364] 48 54 54 50 2F 31 2E 31 20 32 30 30 20 4F 4B 0D 0A 43 6F 6E 6E 65 63 74 69 6F 6E 3A 20 63 6C 6F 73 65 0D 0A 44 61 74 65 3A 20 4D 6F 6E 2C 20 32 35 20 4A 61 6E 20 32 30 32 31 20 32 33 3A 35 32 3A 34 35 20 47 4D 54 0D 0A 43 6F 6E 74 65 6E 74 2D 54 79 70 65 3A 20 74 65 78 74 2F 70 6C 61 69 6E 0D 0A 53 65 72 76 65 72 3A 20 4B 65 73 74 72 65 6C 0D 0A 43 61 63 68 65 2D 43 6F 6E 74 72 6F 6C 3A 20 6E 6F 2D 73 74 6F 72 65 2C 20 6E 6F 2D 63 61 63 68 65 0D 0A 50 72 61 67 6D 61 3A 20 6E 6F 2D 63 61 63 68 65 0D 0A 54 72 61 6E 73 66 65 72 2D 45 6E 63 6F 64 69 6E 67 3A 20 63 68 75 6E 6B 65 64 0D 0A 45 78 70 69 72 65 73 3A 20 54 68 75 2C 20 30 31 20 4A 61 6E 20 31 39 37 30 20 30 30 3A 30 30 3A 30 30 20 47 4D 54 0D 0A 46 44 2D 52 65 67 69 6F 6E 3A 20 4C 6F 63 61 6C 0D 0A 46 44 2D 45 6E 76 69 72 6F 6E 6D 65 6E 74 3A 20 44 65 76 65 6C 6F 70 6D 65 6E 74 0D 0A 46 44 2D 4D 61 63 68 69 6E 65 4E 61 6D 65 3A 20 41 52 49 53 45 53 55 52 46 41 43 45 42 4F 4F 0D 0A 58 2D 43 6F 6E 74 65 6E 74 2D 54 79 70 65 2D 4F 70 74 69 6F 6E 73 3A 20 6E 6F 73 6E 69 66 66 0D 0A 0D 0A 37 0D 0A 48 65 61 6C 74 68 79 0D 0A
HTTP/1.1 200 OK\x0D\x0AConnection: close\x0D\x0ADate: Mon, 25 Jan 2021 23:52:45 GMT\x0D\x0AContent-Type: text/plain\x0D\x0AServer: Kestrel\x0D\x0ACache-Control: no-store, no-cache\x0D\x0APragma: no-cache\x0D\x0ATransfer-Encoding: chunked\x0D\x0AExpires: Thu, 01 Jan 1970 00:00:00 GMT\x0D\x0AFD-Region: Local\x0D\x0AFD-Environment: Development\x0D\x0AX-Content-Type-Options: nosniff\x0D\x0A\x0D\x0A7\x0D\x0AHealthy\x0D\x0A
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Executed endpoint 'Health checks'
dbug: Microsoft.AspNetCore.Server.Kestrel.Core.Internal.LoggingConnectionMiddleware[0]
WriteAsync[5] 30 0D 0A 0D 0A
0\x0D\x0A\x0D\x0A
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Request finished in 866.1248ms 200 text/plain
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[6]
Connection id "0HM61HH86TCH3" received FIN.
dbug: Microsoft.AspNetCore.Server.Kestrel[10]
Connection id "0HM61HH86TCH3" disconnecting.
dbug: Microsoft.AspNetCore.Server.Kestrel[2]
Connection id "0HM61HH86TCH3" stopped.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
Connection id "0HM61HH86TCH3" sending FIN because: "The Socket transport's send loop completed gracefully."

[Tratcher]

Oh, there is an explicit Connection: close response header in there. It's not obvious if that's added by the app or server, but judging by all the other no-cache headers being added by the app it seems likely.

I am curious why your request has a Connection: keep-alive header though, that's a non-standard header that should not be needed for HTTP/1.1 requests. You said this request was just coming from a normal chrome browser? You're not customizing the request at all?

[arisewanggithub]

yes, that's correct. The request just comes from my local chrome. The keep-alive is also added by Chrome. In Edge, it will add the same host header. Our service response can't be cached. So no cache makes sense. But no cache doesn't mean the connection should be dropped.
And I just used tcpdump to get the real requests of health check requests from app gateway. I can see it's our service that is sending the first FIN. Please check the attachment. Our service uses port 80.

[Tratcher]

Our service response can't be cached. So no cache makes sense. But no cache doesn't mean the connection should be dropped.

I understand, but that's the first place I would check to make sure that same code is not the one adding the Connection: close header.

Kestrel will add Connection: close in some circumstances like those I mentioned above, but not for a standard browser request.

[arisewanggithub]

Yes, you are correct. I've found a middleware in our app that sets this connection: close header. After removing this header, it works both locally and in Azure. When we have this header, the behavior is a little different local vs azure though. On my local machine (.net core 3.1 and windows), kestrel doesn't disconnect. Browser receives this header and then sends the FIN flag to disconnect. That' why you saw this in my first log. In Azure (.net 5 and Linux), kestrel sends FIN to disconnect first when it sees this header. And that's what we saw in the tcpdump snapshot. I don't know why the difference. But this header seems to be the culprit. Thanks a lot for the help!