search

http4s / blaze

Blazing fast NIO microframework and Http Parser
Apache License 2.0
351 stars 63 forks source link

http4s blaze client with connection pool is closing connection after processing a large response #641

Open vmanpuria opened 4 years ago

vmanpuria commented 4 years ago

Issue: http4s blaze client with connection pool is closing connection after processing a large response of 129KB.

This log line indicates that the connection was shutdown due to idle timeout instead of being recycled:

2020-08-07 22:16:16.791 - [ERROR] - from org.http4s.blazecore.IdleTimeoutStage-? in astra-compute-1 Shutting down idle timeout stage. stageShutdown. stackTrace=java.base/java.lang.Thread.getStackTrace(Thread.java:1607)

Full logs: https://gist.github.com/vmanpuria/cc0329b22f34a572df7e3a51064f2dd1

vmanpuria commented 4 years ago

tcpdump logs

TCP dump logs show that at 22:16:16.792914 and 22:16:16.810912, the two connections were respectively shutdown instead of being recycled.

Client IP: 10.0.3.27 Server IP: 10.0.2.52

tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 262144 bytes
22:16:06.357521 IP 10.0.3.27.36634 > 10.0.2.52.8080: Flags [F.], seq 3000846910, ack 3039530385, win 55, options [nop,nop,TS val 596607360 ecr 1296945316], length 0
22:16:14.939152 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [S], seq 84235099, win 26883, options [mss 8961,sackOK,TS val 596615941 ecr 0,nop,wscale 9], length 0
22:16:14.939741 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [S.], seq 1162392249, ack 84235100, win 8949, options [mss 8961,sackOK,TS val 1300020929 ecr 596615941,nop,wscale 0], length 0
22:16:14.939765 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 1, win 53, options [nop,nop,TS val 596615942 ecr 1300020929], length 0
22:16:14.964611 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [P.], seq 1:822, ack 1, win 53, options [nop,nop,TS val 596615967 ecr 1300020929], length 821: HTTP: GET /v2/profiles/user/@me?fields=guid%2Cidentifiers HTTP/1.1
22:16:14.965176 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [.], ack 822, win 9852, options [nop,nop,TS val 1300020954 ecr 596615967], length 0
22:16:14.965359 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 1:271, ack 822, win 9852, options [nop,nop,TS val 1300020955 ecr 596615967], length 270: HTTP: HTTP/1.1 200 OK
22:16:14.965373 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 271, win 55, options [nop,nop,TS val 596615967 ecr 1300020955], length 0
22:16:16.716024 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [P.], seq 822:2096, ack 271, win 55, options [nop,nop,TS val 596617718 ecr 1300020955], length 1274: HTTP: GET /api/affiliate/v1/items/search?countryCode=US&lang=en&fieldSets=items&merchants=269a179b-bbba-46ed-91ca-f7129757c9c1&merchantTiers=1&merchantTiers=2&merchantTiers=3&providers=walmart_grocery&branchCode=2280&filters=inStock&sortBy=popularity&orderBy=DESC&sourceTypes=product&siteId=us-inbox&pageId=inbox-grocery&imageSize=100x100&limit=1&offset=0 HTTP/1.1
22:16:16.717137 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 271:18169, ack 2096, win 12740, options [nop,nop,TS val 1300022706 ecr 596617718], length 17898: HTTP: HTTP/1.1 200 OK
22:16:16.717163 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 18169, win 125, options [nop,nop,TS val 596617719 ecr 1300022706], length 0
22:16:16.717167 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [.], seq 18169:27118, ack 2096, win 12740, options [nop,nop,TS val 1300022706 ecr 596617718], length 8949: HTTP
22:16:16.717173 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 27118, win 160, options [nop,nop,TS val 596617719 ecr 1300022706], length 0
22:16:16.717182 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [S], seq 1040721867, win 26883, options [mss 8961,sackOK,TS val 596617719 ecr 0,nop,wscale 9], length 0
22:16:16.717736 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [S.], seq 4161101274, ack 1040721868, win 8949, options [mss 8961,sackOK,TS val 1300022707 ecr 596617719,nop,wscale 0], length 0
22:16:16.717737 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 27118:36067, ack 2096, win 12740, options [nop,nop,TS val 1300022707 ecr 596617719], length 8949: HTTP
22:16:16.717751 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [.], ack 1, win 53, options [nop,nop,TS val 596617720 ecr 1300022707], length 0
22:16:16.717754 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 36067, win 181, options [nop,nop,TS val 596617720 ecr 1300022707], length 0
22:16:16.717754 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 36067:53965, ack 2096, win 12740, options [nop,nop,TS val 1300022707 ecr 596617719], length 17898: HTTP
22:16:16.717761 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 53965, win 156, options [nop,nop,TS val 596617720 ecr 1300022707], length 0
22:16:16.717766 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 53965:71863, ack 2096, win 12740, options [nop,nop,TS val 1300022707 ecr 596617719], length 17898: HTTP
22:16:16.717772 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 71863, win 132, options [nop,nop,TS val 596617720 ecr 1300022707], length 0
22:16:16.717775 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 71863:89761, ack 2096, win 12740, options [nop,nop,TS val 1300022707 ecr 596617719], length 17898: HTTP
22:16:16.717782 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 89761, win 107, options [nop,nop,TS val 596617720 ecr 1300022707], length 0
22:16:16.717785 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 89761:107659, ack 2096, win 12740, options [nop,nop,TS val 1300022707 ecr 596617719], length 17898: HTTP
22:16:16.718319 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 107659:125557, ack 2096, win 12740, options [nop,nop,TS val 1300022708 ecr 596617720], length 17898: HTTP
22:16:16.718329 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 125557:129874, ack 2096, win 12740, options [nop,nop,TS val 1300022708 ecr 596617720], length 4317: HTTP
22:16:16.719947 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [P.], seq 1:1811, ack 1, win 53, options [nop,nop,TS val 596617722 ecr 1300022707], length 1810: HTTP: GET /api/affiliate/v1/items/search?countryCode=US&lang=en&fieldSets=items&merchants=269a179b-bbba-46ed-91ca-f7129757c9c1&merchantTiers=1&merchantTiers=2&merchantTiers=3&advancedSearch=1&filters=inStock&branchCode=2280&providers=walmart_grocery&keyword=%28%22Cucumber%2C%201%20Each%22%20%22Coca-Cola%20Soda%2C%20Cherry%20Vanilla%2C%2012%20Fl%20Oz%2C%2012%20Count%22%20%22Great%20Value%20Garlic%20Texas%20Toast%2C%2011.25%20oz%2C%208%20Count%22%20%22Nathan%27s%20Famous%20Skinless%20Beef%20Franks%2C%2014%20oz%22%20%22Red%20Bell%20Pepper%2C%201%20each%22%20%22Great%20Value%202%25%20Reduced-Fat%20Milk%2C%201%20Gallon%2C%20128%20Fl.%20Oz.%22%20%22Great%20Value%20Large%20White%20Grade%20AA%20Eggs%2C%2018%20Count%22%20%22Honeycrisp%20Apples%2C%203%20lb%20bag%22%29&sortBy=popularity&orderBy=DESC&sourceTypes=product&siteId=us-inbox&pageId=inbox-grocery&imageSize=100x100&limit=1&offset=0 HTTP/1.1
22:16:16.720507 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [.], ack 1811, win 10860, options [nop,nop,TS val 1300022710 ecr 596617722], length 0
22:16:16.720946 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 1:17899, ack 1811, win 10860, options [nop,nop,TS val 1300022710 ecr 596617722], length 17898: HTTP: HTTP/1.1 200 OK
22:16:16.720962 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [.], ack 17899, win 123, options [nop,nop,TS val 596617723 ecr 1300022710], length 0
22:16:16.720966 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [.], seq 17899:26848, ack 1811, win 10860, options [nop,nop,TS val 1300022710 ecr 596617722], length 8949: HTTP
22:16:16.720972 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [.], ack 26848, win 158, options [nop,nop,TS val 596617723 ecr 1300022710], length 0
22:16:16.721518 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 26848:35797, ack 1811, win 10860, options [nop,nop,TS val 1300022711 ecr 596617723], length 8949: HTTP
22:16:16.721530 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [.], ack 35797, win 181, options [nop,nop,TS val 596617724 ecr 1300022711], length 0
22:16:16.721534 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 35797:53695, ack 1811, win 10860, options [nop,nop,TS val 1300022711 ecr 596617723], length 17898: HTTP
22:16:16.721544 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 53695:71593, ack 1811, win 10860, options [nop,nop,TS val 1300022711 ecr 596617723], length 17898: HTTP
22:16:16.721552 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 71593:89491, ack 1811, win 10860, options [nop,nop,TS val 1300022711 ecr 596617723], length 17898: HTTP
22:16:16.721559 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 89491:107389, ack 1811, win 10860, options [nop,nop,TS val 1300022711 ecr 596617723], length 17898: HTTP
22:16:16.722088 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 107389:125287, ack 1811, win 10860, options [nop,nop,TS val 1300022711 ecr 596617724], length 17898: HTTP
22:16:16.728271 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [P.], seq 125557:129874, ack 2096, win 12740, options [nop,nop,TS val 1300022718 ecr 596617720], length 4317: HTTP
22:16:16.742520 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [.], ack 125287, win 57, options [nop,nop,TS val 596617745 ecr 1300022711], length 0
22:16:16.742529 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 129874, win 49, options [nop,nop,TS val 596617745 ecr 1300022707,nop,nop,sack 1 {125557:129874}], length 0
22:16:16.743082 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [P.], seq 125287:129604, ack 1811, win 10860, options [nop,nop,TS val 1300022732 ecr 596617745], length 4317: HTTP
22:16:16.749118 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 129874, win 98, options [nop,nop,TS val 596617751 ecr 1300022707], length 0
22:16:16.750662 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [.], ack 129604, win 98, options [nop,nop,TS val 596617753 ecr 1300022732], length 0
22:16:16.792914 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [F.], seq 1811, ack 129604, win 193, options [nop,nop,TS val 596617795 ecr 1300022732], length 0
22:16:16.793480 IP 10.0.2.52.8080 > 10.0.3.27.41424: Flags [F.], seq 129604, ack 1812, win 10860, options [nop,nop,TS val 1300022783 ecr 596617795], length 0
22:16:16.793506 IP 10.0.3.27.41424 > 10.0.2.52.8080: Flags [.], ack 129605, win 193, options [nop,nop,TS val 596617796 ecr 1300022783], length 0
22:16:16.810912 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [F.], seq 2096, ack 129874, win 195, options [nop,nop,TS val 596617813 ecr 1300022707], length 0
22:16:16.811491 IP 10.0.2.52.8080 > 10.0.3.27.41384: Flags [F.], seq 129874, ack 2097, win 12740, options [nop,nop,TS val 1300022801 ecr 596617813], length 0
22:16:16.811501 IP 10.0.3.27.41384 > 10.0.2.52.8080: Flags [.], ack 129875, win 195, options [nop,nop,TS val 596617814 ecr 1300022801], length 0
^C
52 packets captured
54 packets received by filter
0 packets dropped by kernel
[ouser@ip-10-0-3-27 ~]$
vmanpuria commented 4 years ago

Forum discussion

Hi Folks - I am new to http4s. We have noticed that with a large payload (over 6k bytes), https connections are being shutdown. After I adding logs, examined tcpdump and browsed the code, the issue seems to be in the http4s. After connection reset, instead of calling isReusable, a call is made to shutdown the connection. Therefore, it could be a bug with idle timeout or with the http client. I am using an Http Blaze client with connection pool. The http protocol version is 1.1. With smaller payloads (like 3kb payloads), the https connection stays alive and is re-usable for the next https call. With larger payloads and with chunk transfers, the connection is being shutdown by http4s client.

Christopher Davenport @ChristopherDavenport 16:37 @vmanpuria That seems like perhaps an idle timeout bug. If you could create an issue with the logs on highest level when it occurs we can try to figure out what's killing the connection.