KestrelHttpServer hangs when attacked with multiple requests, e.g. hit F5 multiple times in the browser

[poparta]

This is easy to reproduce with the samples - tested with MusicStore and HelloMVC on ubunto 14.04, Kestrel 1.0.0-alpha4 and latest libuv 1.0.0.x, compiled from sources.

[muojp]

I also noticed this issue, and easier repro here. I recently posted a Docker container which enables easy-to-play environment.

Here's the repro using this container.

note:

• first docker container runs with default "k web"
• second one runs with "k kestrel"

$ docker run -d -i -p 5000:5000 muojp/docker-hellovnext:latest
$ ab -n 3000 -c 50 http://localhost:5000/
... snip ...
Benchmarking localhost (be patient)
Completed 300 requests
Completed 600 requests
Completed 900 requests
Completed 1200 requests
Completed 1500 requests
Completed 1800 requests
Completed 2100 requests
Completed 2400 requests
Completed 2700 requests
Completed 3000 requests
Finished 3000 requests

... snip ...
Concurrency Level:      50
Time taken for tests:   1.020 seconds
Complete requests:      3000
Failed requests:        0
Requests per second:    2941.86 [#/sec] (mean)
... snip ...
$ docker rm -f goofy_einstein
$ docker run -d -i -p 5000:5000 muojp/docker-hellovnext:latest k kestrel
$ ab -n 3000 -c 50 http://localhost:5000/
... snip ...
Benchmarking localhost (be patient)
Completed 300 requests
... long wait ...
apr_socket_recv: Connection reset by peer (104)
Total of 421 requests completed
$ 

I'm not sure whether it's a Kestrel issue or Mono issue (or maybe combination issue). Could anybody tell me it reproduces on Windows host or not?

[malumar]

I have a similar problem on mono (Ubuntu 14.04 lts): docker with current microsoft/aspnet (MusicStore)

[davidfowl]

Does this still repro?

[muojp]

@davidfowl let me check against the latest build. I'll post the result in several hours.

[muojp]

@davidfowl

Quick test result: it reproduces

I performed the same test using

• KRE-Mono 1.0.0-rc1-10831
• Kestrel 1.0.0-* current from NuGet: 1.0.0-rc1-10848

actually, using this image: https://registry.hub.docker.com/u/muojp/hellovnext-docker/ .

And the result is: yes, it reproduces(k web works great on ab -n 3000 -c 50 but k kestrel hang up after first 300+ requests).

Test keep-alive-ed requests: work fine

To drill down problems, I switched keep-alive on like ab -k -n 50000 -c 50 and confirmed k web and k kestrel handle massive number of requests properly. So I suspect the problem resides in releasing old connections and establishing new ones. I once suspected TCP backlog setting in Linux Kernel, but it doesn't describe the behavior difference between k web and k kestrel.

Make Kestrel fail -> sleep well -> re-test: imply locks

I also tested this on fresh k kestrel instance:

$ ab -n 3000 -c 50 http://localhost:5000/ ; sleep 900 ; ab -k -n 3000 -c 50 http://localhost:5000/

which is intended to find out whether there are some resource lock issues inside Kestrel:

1. cause flood and make ab time out (as I previously tested)
2. take much rest, assuming enough time to exceed dead connections time out
3. perform keep-alived load test which should work (as I previously tested)

Result:

This is ApacheBench, Version 2.3 <$Revision: 1528965 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 300 requests
Completed 600 requests
apr_socket_recv: Connection reset by peer (104)
Total of 749 requests completed
This is ApacheBench, Version 2.3 <$Revision: 1528965 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
apr_socket_recv: Connection reset by peer (104)
Total of 21 requests completed

This result imply there are some infinite resource locking.

netstat after Kestrel fail: imply connection locks

I took a snapshot of netstat -an | grep 5000 on failed (already flooded w/ ab) Kestrel instance:

$ netstat -an | grep 5000
tcp6       0      0 :::5000                 :::*                    LISTEN

$ ab -n 3000 -c 50 http://localhost:5000/
This is ApacheBench, Version 2.3 <$Revision: 1528965 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
^C # <-- force quit after around 10 sec

Server Software:        
Server Hostname:        localhost
Server Port:            5000

Document Path:          /
Document Length:        0 bytes

Concurrency Level:      50
Time taken for tests:   9.670 seconds
Complete requests:      0
Failed requests:        0
Total transferred:      0 bytes
HTML transferred:       0 bytes

$ netstat -an | grep 5000
tcp        0      1 172.17.42.1:32883       172.17.2.154:5000       SYN_SENT   
tcp        0     83 172.17.42.1:32817       172.17.2.154:5000       FIN_WAIT1  
tcp        0      1 172.17.42.1:32878       172.17.2.154:5000       SYN_SENT   
tcp        0      1 172.17.42.1:32889       172.17.2.154:5000       SYN_SENT   
tcp        0      1 172.17.42.1:32891       172.17.2.154:5000       SYN_SENT   
tcp        0      1 172.17.42.1:32875       172.17.2.154:5000       SYN_SENT   
...snip...
tcp6       0      0 ::1:41295               ::1:5000                FIN_WAIT2  
tcp6      83      0 ::1:5000                ::1:41296               CLOSE_WAIT 
tcp6      83      0 ::1:5000                ::1:41298               CLOSE_WAIT 
tcp6       0      0 ::1:41300               ::1:5000                FIN_WAIT2  
tcp6      83      0 ::1:5000                ::1:41283               CLOSE_WAIT 
tcp6      83      0 ::1:5000                ::1:41306               CLOSE_WAIT 
tcp6      83      0 ::1:5000                ::1:41260               CLOSE_WAIT 
tcp6       0      0 ::1:41312               ::1:5000                FIN_WAIT2  
tcp6       0      0 ::1:41270               ::1:5000                FIN_WAIT2  
tcp6       0      0 ::1:41301               ::1:5000                FIN_WAIT2  
tcp6      83      0 ::1:5000                ::1:41276               CLOSE_WAIT 
tcp6       0      0 ::1:41307               ::1:5000                FIN_WAIT2  
...snip...

serial keep-alive-ed requests: OK

Since I tested multiple set of keep-alive request with Kestrel like below and all of them completed fine, I think clean socket shutdown procedure is OK.

$ for i in `seq 1 10` ; do ab -k -n 3000 -c 50 http://127.0.0.1:5000/ ; done

My guess

So I guess there are some resource leaking problems reside in Kestrel on non-clean socket shutdown situations or handling error of waiting list for frequent connections.

[Tragetaschen]

With #60:

Finished 3000 requests
[...]
Concurrency Level:      50
Time taken for tests:   2.627 seconds
Complete requests:      3000
Failed requests:        0
[...]
Requests per second:    1142.09 [#/sec] (mean)

Ending Kestrel after the run doesn't show any Finalizer warnings.

[muojp]

@Tragetaschen wow, great work! 😄 🐱

[poparta]

Indeed, great work! 👍