[S] cURL DNS lookups really slow with some sites + resolvers

[Havin_it]

Hi,

This might be a bug report but I wanted to get insight here before I go that route, in case "the problem is me".

I have been having an issue using Composer for a PHP project with 'update' commands complaining of curl encountering a timeout. I tried using curl directly to request the same file and saw the same issue: a delay of >10s during DNS resolution phase. It is almost always about that long although on rare occasions (less than 1/20) it can be almost immediate.

Here it is with debugging cranked up:

Code: Select all

$ curl -vvvv https://packages.drupal.org/8/packages.json
12:48:49.768182 [0-x] * [MULTI] [INIT] added to multi, mid=1, running=1, total=2
12:48:49.768226 [0-x] * [MULTI] [INIT] multi_wait(fds=1, timeout=0) tinternal=0
12:48:49.768288 [0-x] * [MULTI] [INIT] -> [SETUP]
12:48:49.768344 [0-x] * [MULTI] [SETUP] -> [CONNECT]
12:48:49.768378 [0-x] * [READ] client_reset, clear readers
12:48:49.768447 [0-0] * [MULTI] [CONNECT] [CPOOL] added connection 0. The cache now contains 1 members
12:48:49.768613 [0-0] * [DNS] asyn-ares: servers=192.168.2.30:53,192.168.2.1:53
12:48:49.768667 [0-0] * [DNS] asyn-ares: fire off getaddrinfo for A+AAAA
12:48:49.768886 [0-0] * [DNS] asyn-ares: fire off query for HTTPSRR: packages.drupal.org
12:48:49.768975 [0-0] * [MULTI] [CONNECT] -> [RESOLVING]
12:48:49.769031 [0-0] * [TIMER] [ASYNC_NAME] set for 1999000ns
12:48:49.769068 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
12:48:49.769116 [0-0] * [TIMER] [ASYNC_NAME] expires in 1998915ns
12:48:49.769158 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 2000ms
12:48:49.769207 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=2, timeout=1000) tinternal=2000
12:48:49.772218 [0-0] * [DNS] Curl_resolv_check() -> 0, missing
12:48:49.772246 [0-0] * [TIMER] [ASYNC_NAME] set for 1996000ns
12:48:49.772330 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
12:48:49.772380 [0-0] * [TIMER] [ASYNC_NAME] expires in 1995865ns
12:48:49.772420 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 1997ms
12:48:49.772469 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=2, timeout=1000) tinternal=1997
12:48:49.772722 [0-0] * [DNS] Curl_resolv_check() -> 0, missing
12:48:49.772781 [0-0] * [TIMER] [ASYNC_NAME] set for 1996000ns
12:48:49.772819 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
12:48:49.772872 [0-0] * [TIMER] [ASYNC_NAME] expires in 1995908ns
12:48:49.772914 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 1997ms
12:48:49.772964 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=2, timeout=1000) tinternal=1997
12:48:49.784644 [0-0] * [DNS] Curl_resolv_check() -> 0, missing
12:48:49.784671 [0-0] * [TIMER] [ASYNC_NAME] set for 1984000ns
12:48:49.784726 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
12:48:49.784787 [0-0] * [TIMER] [ASYNC_NAME] expires in 1983885ns
12:48:49.784835 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 1985ms
12:48:49.784892 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=2, timeout=1000) tinternal=1985
12:48:50.786100 [0-0] * [DNS] Curl_resolv_check() -> 0, missing
12:48:50.786138 [0-0] * [TIMER] [ASYNC_NAME] set for 982000ns
12:48:50.786215 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
12:48:50.786302 [0-0] * [TIMER] [ASYNC_NAME] expires in 981835ns
12:48:50.786341 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 983ms
12:48:50.786388 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=2, timeout=983) tinternal=983
12:48:51.770573 [0-0] * [DNS] ares: addrinfo done, query status=0, overall status=0, pending=1, addr=found
12:48:51.770721 [0-0] * [DNS] Curl_resolv_check() -> 0, missing
12:48:51.770768 [0-0] * [TIMER] [ASYNC_NAME] set for 1999000ns
12:48:51.770809 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=5 IN, fd=4 IN], timeouts=1
12:48:51.770870 [0-0] * [TIMER] [ASYNC_NAME] expires in 1998897ns
12:48:51.770921 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 2000ms
12:48:51.770984 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=3, timeout=1000) tinternal=2000
12:48:51.771527 [0-0] * [MULTI] [RESOLVING] Curl_multi_will_close fd=4
12:48:51.771595 [0-0] * [DNS] Curl_resolv_check() -> 0, missing

[...SNIP repetitions...]

12:49:12.548488 [0-0] * [TIMER] [ASYNC_NAME] set for 55000ns
12:49:12.548542 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
12:49:12.548587 [0-0] * [TIMER] [ASYNC_NAME] expires in 54901ns
12:49:12.548655 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 55ms
12:49:12.548697 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=2, timeout=55) tinternal=55
12:49:12.603942 [0-0] * [DNS] Curl_resolv_check() -> 0, missing
12:49:12.603970 [0-0] * [TIMER] [ASYNC_NAME] set for 0ns
12:49:12.603997 [0-0] * [MULTI] [RESOLVING] multi_wait pollset[fd=4 IN], timeouts=1
12:49:12.604094 [0-0] * [TIMER] [ASYNC_NAME] expires in -124ns
12:49:12.604158 [0-0] * [TIMER] [ASYNC_NAME] gives multi timeout in 0ms
12:49:12.604204 [0-0] * [MULTI] [RESOLVING] multi_wait(fds=2, timeout=0) tinternal=0
12:49:12.604251 [0-0] * [DNS] ares: httpsrr done, status=12, pending=0, dnsres=not found
12:49:12.604329 [0-0] * [DNS] is_resolved() result=0, dns=found
12:49:12.604367 [0-0] * Host packages.drupal.org:443 was resolved.
12:49:12.604406 [0-0] * IPv6: (none)
12:49:12.604431 [0-0] * IPv4: 146.75.74.217
12:49:12.604480 [0-0] * [DNS] Curl_resolv_check() -> 0, found

The two local DNS servers in the output are:
192.168.2.30: dnsmasq serving DNS+DHCP for local hosts
192.168.2.1: Fritz!Box router/modem

The dnsmasq server delegates to the router, and the router to my ISP's resolvers. Both are adequately responsive for all other requests, including wget requests for the same URL. Both have the issue, as I confirmed by disabling the dnsmasq box in resolv.conf leaving only the router listed.

I have read that curl attempting IPv6 lookups where IPv6 support on the network is incomplete can be an issue, but doing curl -4 makes no difference.

Both Gentoo machines on this LAN have the same issue, running net-misc/curl-8.17.0-r1. A RasPi on the same network, running curl-8.14, has no problem.

The delay does not occur when forcing curl to use an upstream resolver, e.g. curl --dns-servers 8.8.8.8 or one of my ISP's, so part of the problem seems to be with config/limitations of the local resolvers.

USE flags are as follows.

Code: Select all

[ebuild   R    ] net-misc/curl-8.17.0-r1::gentoo  USE="adns alt-svc ftp hsts http2 http3 httpsrr imap openssl pop3 psl quic samba smtp ssl tftp websockets -brotli -debug -ech -gnutls -gopher -idn -kerberos -ldap -mbedtls -rtmp -rustls -sasl-scram -ssh -static-libs -telnet -test -verify-sig -zstd" ABI_X86="(64) -32 (-x32)" CURL_QUIC="openssl -ngtcp2" CURL_SSL="openssl -gnutls -mbedtls -rustls"

TIA

[Havin_it]

To add: After experimentation I can eliminate this lookup delay by unsetting USE=adns

Code: Select all

 + + adns              : Add support for asynchronous DNS resolution

I am not sure how big of a sacrifice that is by itself, but it also nobbles these dependent flags

Code: Select all

 + + http3             : Enable HTTP/3 support
 + + httpsrr           : Enable HTTPS Resource Record support
 + + quic              : Enable support for QUIC (RFC 9000); a UDP-based protocol intended to replace TCP

I hope there is a better resolution because although I don't think I have any need of QUIC at present, it seems to be heavily promoted and may become important to have in the mid-term.

[pingtoo]

what if you disable USE flag 'httpsrr' and keep adns, see if that help? And/or further disable USE flag 'http3' for now until you need it.

[Havin_it]

Hi pingtoo,

I have just tried this, and the results are more curious still. On the first invocation of the curl command there is a ~2s delay; when re-run quickly afterwards, no delay. The initial delay recurs after a short break (maybe ~1min).

If I use --dns-servers 192.168.2.1 [the router], the same request fails entirely:

Code: Select all

curl: (6) Could not resolve host: packages.drupal.org (Timeout while contacting DNS servers)

Note on flags: http3 depends on httpsrr, and http3 and quic are co-dependent, so the only options are to disable just those three, or those and adns.

[pingtoo]

Hi pingtoo,

I have just tried this, and the results are more curious still. On the first invocation of the curl command there is a ~2s delay; when re-run quickly afterwards, no delay. The initial delay recurs after a short break (maybe ~1min).

If I use --dns-servers 192.168.2.1 [the router], the same request fails entirely:

Code: Select all

curl: (6) Could not resolve host: packages.drupal.org (Timeout while contacting DNS servers)

Note on flags: http3 depends on httpsrr, and http3 and quic are co-dependent, so the only options are to disable just those three, or those and adns.

Thanks for testing. Let me explain why I think disable httpsrr might help,

when curl enable with adns, it mean it is using c-ares library, which is async dns resolver library. the c-ares have support for HTTPS Resource Record (Type 65) is modern DNS standard (RFC 9460) the benefit use it is because it make the dns server return query with one answer instead multiple round trips, however this require DNS server support. in the case of dnsmasq does not have build in support for httpsrr but it does know how to forward it as is to upstream.

from your trace log it seems to spending time waiting for reply from upstream on the httpsrr record. So when you turn it off, I assume curl just posting normal A+AAAA DNS request, so the dnsmasq initially take time to get the A record, however subsequently because build in support it will cache the A record, therefor your second query will become much faster.

[Havin_it]

Thanks for the background on httpsrr and dnsmasq. I am just trying to map it to what I've observed in the different build states.

With +adns +httpsrr:
DNS = dnsmasq: >10s delay (usually)
DNS = router: ditto
DNS = ISP server: No delay

With +adns -httpsrr:
DNS = dnsmasq: ~2s delay; next time no delay
DNS = router: ~2s delay; next time fail to resolve (code 6)*
DNS = ISP server: No delay

With -adns -httpsrr:
No delay with any DNS

*This was on my 2nd rebuild with this config. The first time, as mentioned in last comment, it always gave that fail-result. This time, it's the slow ~2s on first attempt, then fail. Unsure why this would change. Maybe difference in commands I did against other resolver prior to that.

At some times I will need to use the router as primary resolver, so the hard-fail behaviour with +adns -httpsrr is probably a worse situation.

Let me know if traces for any other builds/resolvers would be useful.

[pingtoo]

primarily your operation is for Composer for PHP. I don't know if there is any option you can configured to influence the actual curl call.

I think you may want to keep curl as feature rich as much as possible.

You can consider add new/extra dns server entry eith in your local resolver file. or modify dnsmasq with new dns server entry. And set it to your ISP directly. (or any public available DNS servers)

For example the a-res (adns) if it use all three dns server simultaneously and if your ISP return first (which you observation indicate that) you should be just fine.

When you configure curl without adns, you are rely on libc implementation. which usually is a sequence call to each nameserver listed in resolver file. and there will be delay in between a failed nameserver to next available one. so most likely is not preferred. Note standard libc resolver implementation will not try next nameserver if the active nameserver return NXDOMAIN

[Havin_it]

Although my use-case currently was composer, I don't like the idea too much of a solution that's unique to it, as lots of things could be using curl/libcurl on a busy machine (2 machines between server and laptop) and this problem would affect them all.

Certainly it's better to retain all features if possible. I guess, from combination of the results above, this may be viable if I simply bypass all use of the router as a DNS server (unless dnsmasq also gives its own problems).

I will start by making the rPi use the ISP resolvers in its resolv.conf, and give them out as well as its own address in its DHCP server config, and see if that gets OK results in all cases.

[Hu]

These results look to me like the +adns and +httpsrr cases cause curl to send some query that the router mishandles. That in turn suggests that curl is not the guilty party, but may be provoking problems from the upstream handler. What do you see if you take a network capture of the good versus bad queries?

The raspberry pi being unaffected may be because its older curl has not yet learned how to send the troublesome query.

[Havin_it]

@Hu you just made me realise I injected some ambiguity above. To clear up, there are two RPis in the equation:

1. The Pi1B+ running dnsmasq. This runs piCorePlayer distro.
2. A Pi5B (the one mentioned in OP) that I used to test an older curl (and yes, checked ldd and it does not use c-ares).

[There are others hanging around but let's not complicate things further ]

Also to add, I have now managed to get the "error 6" failure with +adns +httpsrr / DNS=router, so it is not unique to +adns -httpsrr. It is intermittent in this mode though. I'm thinking the router's responsiveness is quite variable (unless it is the upstream resolvers).

Can you clarify "network capture"? I have tcpdump installed, if it's that, but have only used it under verbatim instruction, and that long ago.

[Hu]

Yes, tcpdump is the easiest way to capture the data, albeit not the easiest way to read the data once captured. As a first level inquiry, I would want to see whether the resolver responds to the initial queries, versus it discards them and curl eventually sends a different query that the resolver processes successfully. If it is answering the initial query, does it do so promptly?

[pingtoo]

Although my use-case currently was composer, I don't like the idea too much of a solution that's unique to it, as lots of things could be using curl/libcurl on a busy machine (2 machines between server and laptop) and this problem would affect them all.

Certainly it's better to retain all features if possible. I guess, from combination of the results above, this may be viable if I simply bypass all use of the router as a DNS server (unless dnsmasq also gives its own problems).

I will start by making the rPi use the ISP resolvers in its resolv.conf, and give them out as well as its own address in its DHCP server config, and see if that gets OK results in all cases.

I am not 100% sure, but when you setup a DNS server (or DNS proxy, like dnsmasq) usually have nothing to do with your content in /etc/resolv.conf. Those DNS server/proxy usually have its own configuration setup to select upstream DNS server.

What I call DNS proxy is not the same as HTTP proxy. The more correct term is DNS cache server. but to me it is like a proxy in between my query to the real DNS server.

if your ISP does have lock down on outgoing DNS port (53, 853, or possible 5353) or you have network wise firewall setup to protect outgoing traffic. You can leave out the router as dns server. because usually you only have limited option you can control how to configure your router DNS resolution setting. you want your ISP router perform only route/NAT duty, not additional DNS caching.

if don't have limitation on network for outgoing DNS traffic then I suggest you configure your DHCP always give out DNS server record with your internal DNS proxy. and ont the proxy you make it search those public DNS cache server like 8.8.8.8 or 1.1.1.1. You can also consider some other that provide filter function too.

[Havin_it]

Although my use-case currently was composer, I don't like the idea too much of a solution that's unique to it, as lots of things could be using curl/libcurl on a busy machine (2 machines between server and laptop) and this problem would affect them all.

Certainly it's better to retain all features if possible. I guess, from combination of the results above, this may be viable if I simply bypass all use of the router as a DNS server (unless dnsmasq also gives its own problems).

I will start by making the rPi use the ISP resolvers in its resolv.conf, and give them out as well as its own address in its DHCP server config, and see if that gets OK results in all cases.

I am not 100% sure, but when you setup a DNS server (or DNS proxy, like dnsmasq) usually have nothing to do with your content in /etc/resolv.conf. Those DNS server/proxy usually have its own configuration setup to select upstream DNS server.

What I call DNS proxy is not the same as HTTP proxy. The more correct term is DNS cache server. but to me it is like a proxy in between my query to the real DNS server.

if your ISP does have lock down on outgoing DNS port (53, 853, or possible 5353) or you have network wise firewall setup to protect outgoing traffic. You can leave out the router as dns server. because usually you only have limited option you can control how to configure your router DNS resolution setting. you want your ISP router perform only route/NAT duty, not additional DNS caching.

if don't have limitation on network for outgoing DNS traffic then I suggest you configure your DHCP always give out DNS server record with your internal DNS proxy. and ont the proxy you make it search those public DNS cache server like 8.8.8.8 or 1.1.1.1. You can also consider some other that provide filter function too.

No outbound filtering of :53, at least I can query from e.g. 8.8.8.8 (Google) as well as from the ISP resolvers just fine from any host inside.

dnsmasq by default uses its host system's /etc/hosts and /etc/resolv.conf to answer DNS queries. On that machine, only the router IP is in resolv.conf but I intend to try changing that to the ISP resolvers. Separately, as a DHCP server, dnsmasq can hand out any dns-server config to its clients; I would change those likewise, from "[dnsmasq IP], [router IP]" to "[dnsmasq IP], [ISP #1], [ISP #2]".

With +adns +httpsrr / ISP's resolver, the curl response is immediate, so I think the main problem is in the router's delegation of the query, because when I specify only the router as resolver in same build, it always has the ~10s delay.

[Havin_it]

Yes, tcpdump is the easiest way to capture the data, albeit not the easiest way to read the data once captured. As a first level inquiry, I would want to see whether the resolver responds to the initial queries, versus it discards them and curl eventually sends a different query that the resolver processes successfully. If it is answering the initial query, does it do so promptly?

Can any of that be determined from the curl -vvvv output as posted in OP? I'm up for whatever but I may not have more serious time for this for a day or two.

[grknight]

If you mean to use dnsmasq as a same-system resolver, I would recommend setting nameservers in new file like /etc/resolv.dnsmasq.
Then, set resolv-file=/etc/resolv.dnsmasq in /etc/dnsmasq.conf
Finally, set /etc/resolv.conf to the localhost (127.0.0.1) as the sole nameserver.

I don't see that dnsmasq would exclude itself from queries and may take extra processing to continue to the next nameserver. Hence the above suggestion.

[pingtoo]

Havin_it,

I wonder could it be that IPv6 query slow you down.

Can you try curl -4 -vvvv ... in the worst configuration, i.e. router and dnserver only setting. just to settle which type DNS query is causing issue.

[grknight]

Havin_it,

I wonder could it be that IPv6 query slow you down.

Can you try curl -4 -vvvv ... in the worst configuration, i.e. router and dnserver only setting. just to settle which type DNS query is causing issue.

On this note, if you only have IPv4, then putting filter=AAAA into /etc/dnsmasq.conf can also help using a dnsmasq server.

[Havin_it]

If you mean to use dnsmasq as a same-system resolver, I would recommend setting nameservers in new file like /etc/resolv.dnsmasq.
Then, set resolv-file=/etc/resolv.dnsmasq in /etc/dnsmasq.conf
Finally, set /etc/resolv.conf to the localhost (127.0.0.1) as the sole nameserver.

I don't see that dnsmasq would exclude itself from queries and may take extra processing to continue to the next nameserver. Hence the above suggestion.

Running dnsmasq for the LAN is that Rpi's only duty apart from local media-server (Lyrion) so its own external DNS needs as a client are minimal to nil. Even otherwise, I would say that it's simpler to keep the nameserver config in its /etc/resolv.conf where it can be used for its own external lookups as well as by dnsmasq for delegation. (I might also add the ISP IPs as nameservers to be provided in local DHCP by dnsmasq, but if dnsmasq delegates to them anyway then it's not really necessary; it's more belt-n-braces in case the Rpi has an outage.)

[Havin_it]

I went ahead and updated the dnsmasq instance so it now recurses to the ISP resolvers instead of the router, and gives out only itself (not the router) as resolver to DHCP clients.

This has basically eliminated delays of any annoying length in curl- or glibc-based queries across all hosts on the LAN. So, it seems the whole problem was the router sucking at recursing c-ares' requests properly.

I just got that router (from my ISP) last summer, and unfortunately it is a black box so I don't suppose there is much I can do about that. I'll raise it with the ISP anyway, just for the hell of it.

Thanks all for the input