Httpx 5 second delay #3019
-
Hi all, Httpx version: I'm still on httpx 24.1 because I had to downgrade because of #2929 Expectation:I expect my http calls not to get delayed by a constant 5 seconds. Actual:My http calls are delayed with a constant 5 seconds, plus I get DNS related logs from dockerd. Long storyI noticed in my system logs weird docker dns issues: Click to see logsDec 15 22:53:44 my-hostname dockerd[1601]: time="2023-12-15T22:53:44.285539223+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;gameboy2023.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:53713->192.168.50.1:53: i/o timeout" Dec 15 22:53:44 my-hostname dockerd[1601]: time="2023-12-15T22:53:44.296076826+01:00" level=error msg="[resolver] failed to query DNS server: 1.1.1.1:53, query: ;ht.my-site-ommitted.nl.\tIN\t A" error="read udp 172.28.0.105:43077->1.1.1.1:53: i/o timeout" Dec 15 22:53:44 my-hostname dockerd[1601]: time="2023-12-15T22:53:44.296120525+01:00" level=error msg="[resolver] failed to query DNS server: 1.1.1.1:53, query: ;ht.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.105:60254->1.1.1.1:53: i/o timeout" Dec 15 22:53:44 my-hostname dockerd[1601]: time="2023-12-15T22:53:44.305453453+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;theultimatenerdconf.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:49108->192.168.50.1:53: i/o timeout" Dec 15 22:53:48 my-hostname dockerd[1601]: time="2023-12-15T22:53:48.364826590+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;zongaatonder.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:48923->192.168.50.1:53: i/o timeout" Dec 15 22:53:48 my-hostname dockerd[1601]: time="2023-12-15T22:53:48.366090453+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;top10movies.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:56201->192.168.50.1:53: i/o timeout" Dec 15 22:53:52 my-hostname dockerd[1601]: time="2023-12-15T22:53:52.496770882+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;gameboy2023.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:49707->192.168.50.1:53: i/o timeout" Dec 15 22:53:52 my-hostname dockerd[1601]: time="2023-12-15T22:53:52.508179669+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;ergotherapie2.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:51178->192.168.50.1:53: i/o timeout" Dec 15 22:53:56 my-hostname dockerd[1601]: time="2023-12-15T22:53:56.515096544+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;theultimatenerdconf.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:33374->192.168.50.1:53: i/o timeout" Dec 15 22:53:56 my-hostname dockerd[1601]: time="2023-12-15T22:53:56.590845767+01:00" level=error msg="[resolver] failed to query DNS server: 192.168.50.1:53, query: ;zongaatonder.my-site-ommitted.nl.\tIN\t AAAA" error="read udp 172.28.0.3:60863->192.168.50.1:53: i/o timeout" It always used to happen when I was doing health probes on about a 100 websites asynchronous as the same moment. I discovered this issue 2 weeks ago, but today got the time to dig into this. I suspected it was httpx, but I had no proof other than running into long timeouts for http calls to sites that were supposed to be fast. I also ran I then changed up my implementation to retrieve all my site urls (there are a little over 100 in db) and make it so I can swap With aiohttp my problem disappears and I get normal response times. All 106 response times are below 1.2 seconds, with the lowest being 0.07. With httpx about 64 out of 106 come with the 5.xx seconds (out of 106 calls only 1 fails, so no TimeoutException) AND system logs appear. Now I think those logs are trying to tell that the dns query wasn't read, hence the So my bug is about what is httpx doing with regards to DNS? What could lead to the issues I'm describing. This is an excerpt of my code (based on Sanic): async def get_all_site_urls(conn):
async with conn.cursor(aiomysql.DictCursor) as cur:
await cur.execute("SELECT site_url FROM site_config")
site_configs = await cur.fetchall()
return [x["site_url"] for x in site_configs]
@app.get("/all_sites_health/<client_type>", name="get all sites health")
async def get_all_sites_health(request, client_type: str):
site_urls = await get_all_site_urls(request.ctx.conn)
# TODO set better timeouts on teh http clients, use defaults for now
if client_type == "aiohttp":
http_client_cls = aiohttp.ClientSession
# timeout 5 seconds per conn/read/write/pool
else:
http_client_cls = httpx.AsyncClient
# timeout 300 seconds by default
async with http_client_cls() as http_client:
tasks = []
for url in site_urls:
task = asyncio.create_task(perform_get_probe(http_client, url))
tasks.append(task)
results = await asyncio.gather(*tasks)
return response.json({"res": results})
async def perform_get_probe(http_client, site_url: str):
start = perf_counter()
try:
res = await http_client.get(site_url)
try:
healthy = res.status_code == 200 # httpx
except AttributeError:
healthy = res.status == 200 # aiohttp
except (httpx.RequestError, aiohttp.ClientError):
healthy = False
duration = perf_counter() - start
return site_url, healthy, duration |
Beta Was this translation helpful? Give feedback.
Replies: 2 comments 1 reply
-
Click for httpx response{ "res": [ [ "https://site-ommitted.com", true, 0.08230855100555345 ], [ "https://site-ommitted.com", true, 0.07588783901883289 ], [ "https://site-ommitted.com", true, 0.07920174198807217 ], [ "https://site-ommitted.com", true, 0.08778418099973351 ], [ "https://site-ommitted.com", true, 0.13690642398432828 ], [ "https://site-ommitted.com", true, 0.0974578780005686 ], [ "https://site-ommitted.com", true, 0.1448600110015832 ], [ "https://site-ommitted.com", true, 0.15822116000344977 ], [ "https://site-ommitted.com", true, 0.1573515950003639 ], [ "https://site-ommitted.com", true, 0.16777641998487525 ], [ "https://site-ommitted.com", true, 0.16832476400304586 ], [ "https://site-ommitted.com", true, 0.1795747959986329 ], [ "https://site-ommitted.com", true, 0.1785589350038208 ], [ "https://site-ommitted.com", true, 0.19023008301155642 ], [ "https://site-ommitted.com", true, 0.18832918899715878 ], [ "https://site-ommitted.com", true, 0.2125282810011413 ], [ "https://site-ommitted.com", true, 0.19909359401208349 ], [ "https://site-ommitted.com", true, 0.20931722500245087 ], [ "https://site-ommitted.com", true, 1.219315297988942 ], [ "https://site-ommitted.com", true, 1.2234200469974894 ], [ "https://site-ommitted.com", true, 1.24114932899829 ], [ "https://site-ommitted.com", true, 0.2432923009910155 ], [ "https://site-ommitted.com", true, 0.2539872580091469 ], [ "https://site-ommitted.com", true, 0.31527304399060085 ], [ "https://site-ommitted.com", true, 0.2718045760120731 ], [ "https://site-ommitted.com", true, 0.3257563969818875 ], [ "https://site-ommitted.com", true, 0.28546475601615384 ], [ "https://site-ommitted.com", true, 0.284011529001873 ], [ "https://site-ommitted.com", true, 1.3038933030038606 ], [ "https://site-ommitted.com", true, 0.36453612201148644 ], [ "https://site-ommitted.com", true, 0.4020084560033865 ], [ "https://site-ommitted.com", true, 0.4172002209816128 ], [ "https://site-ommitted.com", true, 0.4273250449914485 ], [ "https://site-ommitted.com", true, 0.43114954300108366 ], [ "https://site-ommitted.com", true, 0.4371286270034034 ], [ "https://site-ommitted.com", true, 0.46435234099044465 ], [ "https://site-ommitted.com", true, 0.44388942001387477 ], [ "https://site-ommitted.com", true, 0.46024485101224855 ], [ "https://site-ommitted.com", true, 0.46921792899956927 ], [ "https://site-ommitted.com", true, 0.48012528000981547 ], [ "https://site-ommitted.com", true, 0.4805364279891364 ], [ "https://site-ommitted.com", true, 0.48555712099187076 ], [ "https://site-ommitted.com", true, 0.48918977499124594 ], [ "https://site-ommitted.com", true, 0.49903287598863244 ], [ "https://site-ommitted.com", true, 0.5458768660027999 ], [ "https://site-ommitted.com", true, 0.5098859680001624 ], [ "https://site-ommitted.com", true, 0.5109355980239343 ], [ "https://site-ommitted.com", true, 0.5168635240115691 ], [ "https://site-ommitted.com", true, 0.5176010129798669 ], [ "https://site-ommitted.com", true, 0.5284237960004248 ], [ "https://site-ommitted.com", true, 0.5369556059886236 ], [ "https://site-ommitted.com", true, 0.5392905979824718 ], [ "https://site-ommitted.com", true, 0.5409694989793934 ], [ "https://site-ommitted.com", true, 0.5938889000099152 ], [ "https://site-ommitted.com", true, 0.5487178530020174 ], [ "https://site-ommitted.com", true, 0.5569975399994291 ], [ "https://site-ommitted.com", true, 0.569307719997596 ], [ "https://site-ommitted.com", true, 0.6323446340102237 ], [ "https://site-ommitted.com", true, 0.5885791959881317 ], [ "https://site-ommitted.com", true, 0.6336101880006026 ], [ "https://site-ommitted.com", true, 0.6516960989974905 ], [ "https://site-ommitted.com", true, 0.6504951339738909 ], [ "https://site-ommitted.com", true, 0.6610094860079698 ], [ "https://site-ommitted.com", true, 0.662951950012939 ], [ "https://site-ommitted.com", true, 0.6707514619920403 ], [ "https://site-ommitted.com", true, 0.6830367119982839 ], [ "https://site-ommitted.com", true, 0.6874035130022094 ], [ "https://site-ommitted.com", true, 0.6945644340012223 ], [ "https://site-ommitted.com", true, 0.6967934390122537 ], [ "https://site-ommitted.com", true, 0.9381926939822733 ], [ "https://site-ommitted.com", true, 0.7298675710044336 ], [ "https://site-ommitted.com", true, 0.7229369939886965 ], [ "https://site-ommitted.com", true, 1.018343289004406 ], [ "https://site-ommitted.com", true, 1.0151123339892365 ], [ "https://site-ommitted.com", true, 1.7825855640112422 ], [ "https://site-ommitted.com", true, 4.783693912992021 ], [ "https://site-ommitted.com", true, 4.798365044000093 ], [ "https://site-ommitted.com", true, 4.801851213007467 ], [ "https://site-ommitted.com", true, 4.810604446014622 ], [ "https://site-ommitted.com", true, 4.82105564000085 ], [ "https://site-ommitted.com", true, 4.825917247973848 ], [ "https://site-ommitted.com", true, 4.890641294012312 ], [ "https://site-ommitted.com", true, 4.89644876300008 ], [ "https://site-ommitted.com", true, 4.923877081018873 ], [ "https://site-ommitted.com", true, 4.937262438994367 ], [ "https://site-ommitted.com", true, 4.93350724800257 ], [ "https://site-ommitted.com", true, 4.935869189997902 ], [ "https://site-ommitted.com", true, 4.955896254017716 ], [ "https://site-ommitted.com", true, 4.943970352993347 ], [ "https://site-ommitted.com", true, 4.964652997994563 ], [ "https://site-ommitted.com", true, 4.9569486629916355 ], [ "https://site-ommitted.com", true, 4.962951977009652 ], [ "https://site-ommitted.com", true, 4.9769580680003855 ], [ "https://site-ommitted.com", true, 4.983465526980581 ], [ "https://site-ommitted.com", true, 5.040740039985394 ], [ "https://site-ommitted.com", true, 6.0204855680058245 ], [ "https://site-ommitted.com", true, 6.019802807975793 ], [ "https://site-ommitted.com", true, 6.026205580012174 ], [ "https://site-ommitted.com", true, 6.024835749994963 ], [ "https://site-ommitted.com", true, 5.078686130000278 ], [ "https://site-ommitted.com", true, 5.102339288016083 ], [ "https://site-ommitted.com", true, 5.053123448014958 ], [ "https://site-ommitted.com", true, 5.122248945001047 ], [ "https://site-ommitted.com", true, 5.1151541029976215 ], [ "https://site-ommitted.com", true, 5.126930127997184 ], [ "http://localhost:8084", false, 5.062833144009346 ] ] } Click for aiohttp response{ "res": [ [ "https://site-ommitted.com", true, 0.10253822198137641 ], [ "https://site-ommitted.com", true, 0.09174630098277703 ], [ "https://site-ommitted.com", true, 0.07379615301033482 ], [ "https://site-ommitted.com", true, 0.31039385200710967 ], [ "https://site-ommitted.com", true, 0.31313316099112853 ], [ "https://site-ommitted.com", true, 0.10617338499287143 ], [ "https://site-ommitted.com", true, 0.08843065000837669 ], [ "https://site-ommitted.com", true, 0.1050302789954003 ], [ "https://site-ommitted.com", true, 0.31665156700182706 ], [ "https://site-ommitted.com", true, 0.10555135199683718 ], [ "https://site-ommitted.com", true, 0.3197533159982413 ], [ "https://site-ommitted.com", true, 0.306745720008621 ], [ "https://site-ommitted.com", true, 0.10509419598383829 ], [ "https://site-ommitted.com", true, 0.3189662880031392 ], [ "https://site-ommitted.com", true, 0.3252686019986868 ], [ "https://site-ommitted.com", true, 0.13012582398368977 ], [ "https://site-ommitted.com", true, 0.10957723300089128 ], [ "https://site-ommitted.com", true, 0.3214663139951881 ], [ "https://site-ommitted.com", true, 0.3211135150049813 ], [ "https://site-ommitted.com", true, 0.1291689920180943 ], [ "https://site-ommitted.com", true, 0.12866547700832598 ], [ "https://site-ommitted.com", true, 0.3206150189798791 ], [ "https://site-ommitted.com", true, 0.12812287401175126 ], [ "https://site-ommitted.com", true, 0.12768924600095488 ], [ "https://site-ommitted.com", true, 0.3284434480010532 ], [ "https://site-ommitted.com", true, 0.33157822501379997 ], [ "https://site-ommitted.com", true, 0.32728885201504454 ], [ "https://site-ommitted.com", true, 0.3320439310045913 ], [ "https://site-ommitted.com", true, 0.8184483369986992 ], [ "https://site-ommitted.com", true, 0.422472520993324 ], [ "https://site-ommitted.com", true, 0.37804489699192345 ], [ "https://site-ommitted.com", true, 0.35501788900000975 ], [ "https://site-ommitted.com", true, 0.4234831799985841 ], [ "https://site-ommitted.com", true, 0.4135655249992851 ], [ "https://site-ommitted.com", true, 0.3805674120085314 ], [ "https://site-ommitted.com", true, 0.42257619701558724 ], [ "https://site-ommitted.com", true, 0.42621472899918444 ], [ "https://site-ommitted.com", true, 0.4240108939993661 ], [ "https://site-ommitted.com", true, 0.41092154299258254 ], [ "https://site-ommitted.com", true, 0.4118240769894328 ], [ "https://site-ommitted.com", true, 0.4147492900083307 ], [ "https://site-ommitted.com", true, 0.42225384700577706 ], [ "https://site-ommitted.com", true, 0.3986967859964352 ], [ "https://site-ommitted.com", true, 0.7259267379995435 ], [ "https://site-ommitted.com", true, 0.6459036190062761 ], [ "https://site-ommitted.com", true, 0.6457853929896373 ], [ "https://site-ommitted.com", true, 0.39251336801680736 ], [ "https://site-ommitted.com", true, 0.4002886489906814 ], [ "https://site-ommitted.com", true, 0.39904994500102475 ], [ "https://site-ommitted.com", true, 0.6445776690088678 ], [ "https://site-ommitted.com", true, 0.36002087098313496 ], [ "https://site-ommitted.com", true, 1.3985193470143713 ], [ "https://site-ommitted.com", true, 0.41321903400239535 ], [ "https://site-ommitted.com", true, 0.724239637987921 ], [ "https://site-ommitted.com", true, 0.3950124940020032 ], [ "https://site-ommitted.com", true, 0.6438538600050379 ], [ "https://site-ommitted.com", true, 0.7239115580159705 ], [ "https://site-ommitted.com", true, 0.40497850999236107 ], [ "https://site-ommitted.com", true, 0.3535978620056994 ], [ "https://site-ommitted.com", true, 0.3917347509996034 ], [ "https://site-ommitted.com", true, 0.6727138049900532 ], [ "https://site-ommitted.com", true, 0.3512298920250032 ], [ "https://site-ommitted.com", true, 0.3954355019959621 ], [ "https://site-ommitted.com", true, 0.38985216701985337 ], [ "https://site-ommitted.com", true, 0.7052611209801398 ], [ "https://site-ommitted.com", true, 0.9474295140244067 ], [ "https://site-ommitted.com", true, 0.3925839159928728 ], [ "https://site-ommitted.com", true, 0.3891920360038057 ], [ "https://site-ommitted.com", true, 0.6407597020152025 ], [ "https://site-ommitted.com", true, 1.9193670130043756 ], [ "https://site-ommitted.com", true, 0.640633136004908 ], [ "https://site-ommitted.com", true, 0.7206984230142552 ], [ "https://site-ommitted.com", true, 0.3731395319919102 ], [ "https://site-ommitted.com", true, 0.3885772840003483 ], [ "https://site-ommitted.com", true, 0.7201866990071721 ], [ "https://site-ommitted.com", true, 0.6398218899848871 ], [ "https://site-ommitted.com", true, 0.3868115170043893 ], [ "https://site-ommitted.com", true, 1.9118139570055064 ], [ "https://site-ommitted.com", true, 0.9452606590057258 ], [ "https://site-ommitted.com", true, 1.927783183986321 ], [ "https://site-ommitted.com", true, 2.17318323199288 ], [ "https://site-ommitted.com", true, 2.1803380199999083 ], [ "https://site-ommitted.com", true, 0.4069704999856185 ], [ "https://site-ommitted.com", true, 0.3872905330208596 ], [ "https://site-ommitted.com", true, 2.1860569800192025 ], [ "https://site-ommitted.com", true, 0.4541739910200704 ], [ "https://site-ommitted.com", true, 1.120478537020972 ], [ "https://site-ommitted.com", true, 1.1170351680193562 ], [ "https://site-ommitted.com", true, 1.1123927060107235 ], [ "https://site-ommitted.com", true, 0.4546947250200901 ], [ "https://site-ommitted.com", true, 0.4541311629873235 ], [ "https://site-ommitted.com", true, 0.4548404809902422 ], [ "https://site-ommitted.com", true, 1.122179516009055 ], [ "https://site-ommitted.com", true, 1.1491414670017548 ], [ "https://site-ommitted.com", true, 1.1383227679762058 ], [ "https://site-ommitted.com", true, 1.1422526410024147 ], [ "https://site-ommitted.com", true, 1.1457494779897388 ], [ "https://site-ommitted.com", true, 1.1514888770179823 ], [ "https://site-ommitted.com", true, 1.1441824349749368 ], [ "https://site-ommitted.com", true, 1.136703625001246 ], [ "https://site-ommitted.com", true, 1.1618297819804866 ], [ "https://site-ommitted.com", true, 1.196622949995799 ], [ "https://site-ommitted.com", true, 1.1396636480058078 ], [ "https://site-ommitted.com", true, 1.160594688000856 ], [ "https://site-ommitted.com", true, 1.1944751440023538 ], [ "http://localhost:8084", false, 0.11373258900130168 ] ] } Note: all the way at the bottom for both responses you see I called localhost, that is the only call that failed. In the aiohttp I see expected response times. In the httpx response I see a lot of response times at 5 seconds in combination with the docker dns logs. For privacy reasons I ommitted al site urls, but they are all unique. In this case it concerns wildcard subdomain if that is helpful information. |
Beta Was this translation helpful? Give feedback.
-
Resolved in
So, You can see that our backends just use regular connect calls that ought to end up with fairly standard
You might want to try comparing the The difference is likely to be due to what If you're able to start with just a little more digging and comparison then I'd probably suggest we could escalate this into an "Support DNS caching" ticket in the |
Beta Was this translation helpful? Give feedback.
Resolved in
httpx
0.26.So,
httpx
isn't doing anything unusual with DNS lookups.You can see that our backends just use regular connect calls that ought to end up with fairly standard
getaddrinfo()
lookups...You migh…