"SERVER_TIMEOUT" in response to relay unresponsiveness can be misleading

[tmo1]

Hi,

I recently experienced frequent but intermittent resolution failure (timeouts). I checked the logs, and when resolution was failing, I saw "SERVER_TIMEOUT" errors, from a variety of different servers. The same servers, however, would eventually start working again, with no action on my part. It seemed strange that there would be so much outage among the standard servers (I'm using the default list), and I eventually realized that the problem was not actually with the servers, but with one of my relays - I'm using Anonymized DNS, and one of my specified relays, anon-plan9-dns, had gone down (link, link).

I understand that the fact that DNScrypt / Anonymized DNS uses UDP makes it hard to distinguish between an unresponsive resolver and an unresponsize relay, but I think it would be useful if dnscrypt-proxy included some kind of check to see if the relay is responsive, at least upon encountering (repeated) SERVER_TIMEOUTs. Reporting SERVER_TIMEOUT when the issue is with a relay can be somewhat misleading.

[lifenjoiner]

I learnt the code about anonymized DNS relays.
The strange part from your descriptions is that: the specified relay should not in the latest relayNames, and there should not be those SERVER_TIMEOUTs, but you you got it intermittently.
Was your relays.md refreshed successfully and in time? refresh_delay = 72. Maybe it is just some delay after the source updates, which caused those. You used an old relays.md, and the relay is not totally down ... maybe.

[tmo1]

Thank you. I just tried configuring dnscrypt-proxy to use the relay which is no longer in relays.md, and it just gets ignored, with no SERVER_TIMEOUT. Perhaps you're right that my problem was due to an old relays.md - I suppose I could comb through my backups to try to figure out whether that was indeed the case, but I'm not sure it's worth it.

I'm curious now about the results of my little experiment - if I'm interpreting the results correctly, when invalid relays are provided, they're just ignored and the resolvers are contacted directly. Isn't this a potential privacy leak? If I configure Anonymized DNS, I may not want dnscrypt-proxy to make direct connections just because my relay configuration is invalid.

[lifenjoiner]

if I'm interpreting the results correctly, when invalid relays are provided, they're just ignored and the resolvers are contacted directly. Isn't this a potential privacy leak?

Hmm... Maybe you found a potential issue.

@jedisct1

I did a test with anonymized DNS turned on by routes = [{ server_name='*', via=['NonExist'] }], queried help.github.com, and got:

Click to expand

D:\GreenSoftWares\DNS\dnscrypt-proxy\test>..\dnscrypt-proxy.exe -config test-nonExistRelay.toml
[2022-06-15 09:01:44] [NOTICE] dnscrypt-proxy 2.1.1
[2022-06-15 09:01:44] [NOTICE] Network connectivity detected
[2022-06-15 09:01:44] [NOTICE] Now listening to 127.0.0.1:53053 [UDP]
[2022-06-15 09:01:44] [NOTICE] Now listening to 127.0.0.1:53053 [TCP]
[2022-06-15 09:01:50] [NOTICE] Source [public-resolvers] loaded
[2022-06-15 09:01:51] [NOTICE] Source [relays] loaded
[2022-06-15 09:01:51] [NOTICE] Anonymized DNS: routing everything via [NonExist]
[2022-06-15 09:01:51] [NOTICE] Firefox workaround initialized
[2022-06-15 09:01:52] [NOTICE] [ams-doh-nl] OK (DoH) - rtt: 217ms
[2022-06-15 09:01:52] [WARNING] Empty relay set for [acsacsar-ams-ipv4]
[2022-06-15 09:01:53] [NOTICE] [acsacsar-ams-ipv4] OK (DNSCrypt) - rtt: 281ms
[2022-06-15 09:01:55] [NOTICE] System DNS configuration not usable yet, exceptionally resolving [doh.mullvad.net] using bootstrap resolvers over tcp
[2022-06-15 09:01:57] [NOTICE] Bootstrap resolvers didn't respond - Trying with the system resolver as a last resort
[2022-06-15 09:02:09] [NOTICE] [dns.ryan-palmer] OK (DoH) - rtt: 268ms
[2022-06-15 09:02:15] [NOTICE] [uncensoreddns-dk-ipv4] OK (DoH) - rtt: 251ms
[2022-06-15 09:02:31] [WARNING] Empty relay set for [dct-at1]
[2022-06-15 09:02:36] [NOTICE] [dct-at1] TIMEOUT
[2022-06-15 09:02:36] [WARNING] Empty relay set for [quad9-dnscrypt-ip4-nofilter-pri]
[2022-06-15 09:02:41] [NOTICE] [quad9-dnscrypt-ip4-nofilter-pri] OK (DNSCrypt) - rtt: 224ms
[2022-06-15 09:02:41] [NOTICE] [quad9-dnscrypt-ip4-nofilter-pri] OK (DNSCrypt) - rtt: 224ms - additional certificate
[2022-06-15 09:02:42] [NOTICE] [adguard-dns-unfiltered-doh] OK (DoH) - rtt: 232ms
[2022-06-15 09:02:42] [WARNING] Empty relay set for [dnswarden-us-uncensor-dcv4]
[2022-06-15 09:02:42] [NOTICE] [dnswarden-us-uncensor-dcv4] OK (DNSCrypt) - rtt: 178ms
[2022-06-15 09:02:42] [NOTICE] [dnswarden-us-uncensor-dcv4] OK (DNSCrypt) - rtt: 178ms - additional certificate
[2022-06-15 09:02:42] [WARNING] Empty relay set for [scaleway-ams]
[2022-06-15 09:02:47] [NOTICE] [scaleway-ams] TIMEOUT
[2022-06-15 09:02:47] [WARNING] Empty relay set for [wevpn-uswest]
[2022-06-15 09:02:52] [NOTICE] [wevpn-uswest] OK (DNSCrypt) - rtt: 281ms
[2022-06-15 09:03:08] [NOTICE] [dnscrypt.ca-2-doh] OK (DoH) - rtt: 1719ms
[2022-06-15 09:03:08] [WARNING] Empty relay set for [ffmuc.net]
[2022-06-15 09:03:13] [NOTICE] [ffmuc.net] OK (DNSCrypt) - rtt: 229ms
[2022-06-15 09:03:23] [WARNING] Empty relay set for [d0wn-tz-ns1]
[2022-06-15 09:03:23] [NOTICE] [d0wn-tz-ns1] OK (DNSCrypt) - rtt: 243ms
[2022-06-15 09:03:23] [WARNING] Empty relay set for [dnscrypt.ca-2]
[2022-06-15 09:03:24] [NOTICE] [dnscrypt.ca-2] OK (DNSCrypt) - rtt: 309ms
[2022-06-15 09:03:24] [WARNING] Empty relay set for [dnscrypt.pl]
[2022-06-15 09:03:29] [NOTICE] [dnscrypt.pl] OK (DNSCrypt) - rtt: 230ms
[2022-06-15 09:03:30] [NOTICE] [uncensoreddns-ipv4] OK (DoH) - rtt: 231ms
[2022-06-15 09:03:31] [CRITICAL] [hdns] may be a lying resolver
[2022-06-15 09:03:31] [NOTICE] [hdns] OK (DoH) - rtt: 251ms
[2022-06-15 09:03:31] [WARNING] Empty relay set for [dct-ru1]
[2022-06-15 09:03:36] [NOTICE] [dct-ru1] TIMEOUT
[2022-06-15 09:03:36] [WARNING] Empty relay set for [altername]
[2022-06-15 09:03:41] [NOTICE] [altername] TIMEOUT
[2022-06-15 09:03:41] [WARNING] Empty relay set for [techsaviours.org-dnscrypt]
[2022-06-15 09:03:46] [NOTICE] [techsaviours.org-dnscrypt] OK (DNSCrypt) - rtt: 190ms
[2022-06-15 09:03:46] [WARNING] Empty relay set for [moulticast-sg-ipv4]
[2022-06-15 09:03:51] [NOTICE] [moulticast-sg-ipv4] OK (DNSCrypt) - rtt: 255ms
[2022-06-15 09:03:51] [WARNING] Empty relay set for [moulticast-de-ipv4]
[2022-06-15 09:03:56] [NOTICE] [moulticast-de-ipv4] OK (DNSCrypt) - rtt: 226ms
[2022-06-15 09:03:56] [WARNING] Empty relay set for [dnscrypt.eu-nl]
[2022-06-15 09:04:01] [NOTICE] [dnscrypt.eu-nl] OK (DNSCrypt) - rtt: 215ms
[2022-06-15 09:04:03] [WARNING] Empty relay set for [faelix-uk-ipv4]
[2022-06-15 09:04:03] [NOTICE] [faelix-uk-ipv4] OK (DNSCrypt) - rtt: 264ms
[2022-06-15 09:04:03] [WARNING] Empty relay set for [dct-de1]
[2022-06-15 09:04:08] [NOTICE] [dct-de1] TIMEOUT
[2022-06-15 09:04:08] [WARNING] Empty relay set for [dnswarden-asia-uncensor-dcv4]
[2022-06-15 09:04:13] [NOTICE] [dnswarden-asia-uncensor-dcv4] OK (DNSCrypt) - rtt: 320ms
[2022-06-15 09:04:13] [NOTICE] [dnswarden-asia-uncensor-dcv4] OK (DNSCrypt) - rtt: 320ms - additional certificate
[2022-06-15 09:04:13] [WARNING] Empty relay set for [dnscrypt.ca-1]
[2022-06-15 09:04:13] [NOTICE] [dnscrypt.ca-1] OK (DNSCrypt) - rtt: 230ms
[2022-06-15 09:04:13] [WARNING] Empty relay set for [quad9-dnscrypt-ip4-nofilter-ecs-pri]
[2022-06-15 09:04:18] [NOTICE] [quad9-dnscrypt-ip4-nofilter-ecs-pri] OK (DNSCrypt) - rtt: 223ms
[2022-06-15 09:04:18] [NOTICE] [quad9-dnscrypt-ip4-nofilter-ecs-pri] OK (DNSCrypt) - rtt: 223ms - additional certificate
[2022-06-15 09:04:18] [WARNING] Empty relay set for [moulticast-uk-ipv4]
[2022-06-15 09:04:23] [NOTICE] [moulticast-uk-ipv4] OK (DNSCrypt) - rtt: 254ms
[2022-06-15 09:04:23] [WARNING] Empty relay set for [dns.watch]
[2022-06-15 09:04:28] [NOTICE] [dns.watch] OK (DNSCrypt) - rtt: 232ms
[2022-06-15 09:04:29] [WARNING] Empty relay set for [bcn-dnscrypt]
[2022-06-15 09:04:29] [NOTICE] [bcn-dnscrypt] OK (DNSCrypt) - rtt: 268ms
[2022-06-15 09:04:29] [WARNING] Empty relay set for [faelix-ch-ipv4]
[2022-06-15 09:04:34] [NOTICE] [faelix-ch-ipv4] OK (DNSCrypt) - rtt: 195ms
[2022-06-15 09:04:35] [NOTICE] [dnshome-doh] OK (DoH) - rtt: 199ms
[2022-06-15 09:04:37] [NOTICE] [bcn-doh] OK (DoH) - rtt: 228ms
[2022-06-15 09:04:38] [NOTICE] [bortzmeyer] OK (DoH) - rtt: 279ms
[2022-06-15 09:04:49] [NOTICE] [v.dnscrypt.uk-doh-ipv4] OK (DoH) - rtt: 256ms
[2022-06-15 09:04:49] [WARNING] Empty relay set for [dnswarden-eu-uncensor-dcv4]
[2022-06-15 09:04:54] [NOTICE] [dnswarden-eu-uncensor-dcv4] OK (DNSCrypt) - rtt: 252ms
[2022-06-15 09:04:54] [WARNING] Empty relay set for [saldns02-conoha-ipv4]
[2022-06-15 09:04:54] [NOTICE] [saldns02-conoha-ipv4] OK (DNSCrypt) - rtt: 73ms
[2022-06-15 09:04:54] [WARNING] Empty relay set for [saldns01-conoha-ipv4]
[2022-06-15 09:04:55] [NOTICE] [saldns01-conoha-ipv4] OK (DNSCrypt) - rtt: 66ms
[2022-06-15 09:05:00] [WARNING] Empty relay set for [dnscrypt.be]
[2022-06-15 09:05:05] [NOTICE] [dnscrypt.be] TIMEOUT
[2022-06-15 09:05:05] [WARNING] Empty relay set for [v.dnscrypt.uk-ipv4]
[2022-06-15 09:05:06] [NOTICE] [v.dnscrypt.uk-ipv4] OK (DNSCrypt) - rtt: 252ms
[2022-06-15 09:05:17] [WARNING] Empty relay set for [pryv8boi]
[2022-06-15 09:05:22] [NOTICE] [pryv8boi] OK (DNSCrypt) - rtt: 274ms
[2022-06-15 09:05:22] [WARNING] Empty relay set for [dnscrypt.uk-ipv4]
[2022-06-15 09:05:27] [NOTICE] [dnscrypt.uk-ipv4] TIMEOUT
[2022-06-15 09:05:27] [WARNING] Empty relay set for [wevpn-useast]
[2022-06-15 09:05:32] [NOTICE] [wevpn-useast] OK (DNSCrypt) - rtt: 200ms
[2022-06-15 09:05:32] [WARNING] Empty relay set for [resolver4.dns.openinternet.io]
[2022-06-15 09:05:37] [NOTICE] [resolver4.dns.openinternet.io] OK (DNSCrypt) - rtt: 136ms
[2022-06-15 09:05:42] [WARNING] Empty relay set for [serbica]
[2022-06-15 09:05:47] [NOTICE] [serbica] OK (DNSCrypt) - rtt: 186ms
[2022-06-15 09:05:47] [WARNING] Empty relay set for [opennic-R4SAS]
[2022-06-15 09:05:48] [NOTICE] [opennic-R4SAS] OK (DNSCrypt) - rtt: 259ms
[2022-06-15 09:05:48] [NOTICE] [quad101] OK (DoH) - rtt: 65ms
[2022-06-15 09:05:48] [WARNING] Empty relay set for [meganerd]
[2022-06-15 09:05:48] [NOTICE] [meganerd] OK (DNSCrypt) - rtt: 247ms
[2022-06-15 09:05:48] [WARNING] Empty relay set for [deffer-dns.au]
[2022-06-15 09:05:48] [NOTICE] [deffer-dns.au] OK (DNSCrypt) - rtt: 162ms
[2022-06-15 09:05:49] [NOTICE] [dns.digitale-gesellschaft.ch] OK (DoH) - rtt: 272ms
[2022-06-15 09:05:51] [NOTICE] [doh.appliedprivacy.net] OK (DoH) - rtt: 246ms
[2022-06-15 09:05:51] [WARNING] Empty relay set for [wevpn-singapore]
[2022-06-15 09:05:51] [NOTICE] [wevpn-singapore] OK (DNSCrypt) - rtt: 205ms
[2022-06-15 09:05:52] [NOTICE] [sth-doh-se] OK (DoH) - rtt: 241ms
[2022-06-15 09:05:52] [WARNING] Empty relay set for [sth-dnscrypt-se]
[2022-06-15 09:05:52] [NOTICE] [sth-dnscrypt-se] OK (DNSCrypt) - rtt: 242ms
[2022-06-15 09:05:52] [WARNING] Empty relay set for [ibksturm]
[2022-06-15 09:05:57] [NOTICE] [ibksturm] TIMEOUT
[2022-06-15 09:05:57] [WARNING] Empty relay set for [ams-dnscrypt-nl]
[2022-06-15 09:06:02] [NOTICE] [ams-dnscrypt-nl] OK (DNSCrypt) - rtt: 226ms
[2022-06-15 09:06:23] [WARNING] Empty relay set for [moulticast-fr-ipv4]
[2022-06-15 09:06:28] [NOTICE] [moulticast-fr-ipv4] OK (DNSCrypt) - rtt: 206ms
[2022-06-15 09:06:30] [WARNING] Empty relay set for [plan9-ns2]
[2022-06-15 09:06:30] [NOTICE] [plan9-ns2] OK (DNSCrypt) - rtt: 188ms
[2022-06-15 09:06:37] [NOTICE] [dnscrypt.ca-1-doh] OK (DoH) - rtt: 226ms
[2022-06-15 09:06:52] [WARNING] Empty relay set for [scaleway-fr]
[2022-06-15 09:06:53] [NOTICE] [scaleway-fr] OK (DNSCrypt) - rtt: 378ms
[2022-06-15 09:06:53] [WARNING] Empty relay set for [jp.tiar.app]
[2022-06-15 09:06:58] [NOTICE] [jp.tiar.app] TIMEOUT
[2022-06-15 09:06:58] [WARNING] Empty relay set for [sgp-dn53]
[2022-06-15 09:06:58] [NOTICE] [sgp-dn53] OK (DNSCrypt) - rtt: 281ms
[2022-06-15 09:07:01] [NOTICE] [dns.digitale-gesellschaft.ch-2] OK (DoH) - rtt: 288ms
[2022-06-15 09:07:07] [NOTICE] [njalla-doh] OK (DoH) - rtt: 196ms
[2022-06-15 09:07:07] [WARNING] Empty relay set for [saldnssg01-conoha-ipv4]
[2022-06-15 09:07:12] [NOTICE] [saldnssg01-conoha-ipv4] TIMEOUT
[2022-06-15 09:07:12] [WARNING] Empty relay set for [pwoss.org-dnscrypt]
[2022-06-15 09:07:12] [NOTICE] [pwoss.org-dnscrypt] OK (DNSCrypt) - rtt: 197ms
[2022-06-15 09:07:12] [NOTICE] Sorted latencies:
[2022-06-15 09:07:12] [NOTICE] -    65ms quad101
[2022-06-15 09:07:12] [NOTICE] -    66ms saldns01-conoha-ipv4
[2022-06-15 09:07:12] [NOTICE] -    73ms saldns02-conoha-ipv4
[2022-06-15 09:07:12] [NOTICE] -   136ms resolver4.dns.openinternet.io
[2022-06-15 09:07:12] [NOTICE] -   162ms deffer-dns.au
[2022-06-15 09:07:12] [NOTICE] -   178ms dnswarden-us-uncensor-dcv4
[2022-06-15 09:07:12] [NOTICE] -   186ms serbica
[2022-06-15 09:07:12] [NOTICE] -   188ms plan9-ns2
[2022-06-15 09:07:12] [NOTICE] -   190ms techsaviours.org-dnscrypt
[2022-06-15 09:07:12] [NOTICE] -   195ms faelix-ch-ipv4
[2022-06-15 09:07:12] [NOTICE] -   196ms njalla-doh
[2022-06-15 09:07:12] [NOTICE] -   197ms pwoss.org-dnscrypt
[2022-06-15 09:07:12] [NOTICE] -   199ms dnshome-doh
[2022-06-15 09:07:12] [NOTICE] -   200ms wevpn-useast
[2022-06-15 09:07:12] [NOTICE] -   205ms wevpn-singapore
[2022-06-15 09:07:12] [NOTICE] -   206ms moulticast-fr-ipv4
[2022-06-15 09:07:12] [NOTICE] -   215ms dnscrypt.eu-nl
[2022-06-15 09:07:12] [NOTICE] -   217ms ams-doh-nl
[2022-06-15 09:07:12] [NOTICE] -   223ms quad9-dnscrypt-ip4-nofilter-ecs-pri
[2022-06-15 09:07:12] [NOTICE] -   224ms quad9-dnscrypt-ip4-nofilter-pri
[2022-06-15 09:07:12] [NOTICE] -   226ms moulticast-de-ipv4
[2022-06-15 09:07:12] [NOTICE] -   226ms ams-dnscrypt-nl
[2022-06-15 09:07:12] [NOTICE] -   226ms dnscrypt.ca-1-doh
[2022-06-15 09:07:12] [NOTICE] -   228ms bcn-doh
[2022-06-15 09:07:12] [NOTICE] -   229ms ffmuc.net
[2022-06-15 09:07:12] [NOTICE] -   230ms dnscrypt.pl
[2022-06-15 09:07:12] [NOTICE] -   230ms dnscrypt.ca-1
[2022-06-15 09:07:12] [NOTICE] -   231ms uncensoreddns-ipv4
[2022-06-15 09:07:12] [NOTICE] -   232ms adguard-dns-unfiltered-doh
[2022-06-15 09:07:12] [NOTICE] -   232ms dns.watch
[2022-06-15 09:07:12] [NOTICE] -   241ms sth-doh-se
[2022-06-15 09:07:12] [NOTICE] -   242ms sth-dnscrypt-se
[2022-06-15 09:07:12] [NOTICE] -   243ms d0wn-tz-ns1
[2022-06-15 09:07:12] [NOTICE] -   246ms doh.appliedprivacy.net
[2022-06-15 09:07:12] [NOTICE] -   247ms meganerd
[2022-06-15 09:07:12] [NOTICE] -   251ms uncensoreddns-dk-ipv4
[2022-06-15 09:07:12] [NOTICE] -   251ms hdns
[2022-06-15 09:07:12] [NOTICE] -   252ms dnswarden-eu-uncensor-dcv4
[2022-06-15 09:07:12] [NOTICE] -   252ms v.dnscrypt.uk-ipv4
[2022-06-15 09:07:12] [NOTICE] -   254ms moulticast-uk-ipv4
[2022-06-15 09:07:12] [NOTICE] -   255ms moulticast-sg-ipv4
[2022-06-15 09:07:12] [NOTICE] -   256ms v.dnscrypt.uk-doh-ipv4
[2022-06-15 09:07:12] [NOTICE] -   259ms opennic-R4SAS
[2022-06-15 09:07:12] [NOTICE] -   264ms faelix-uk-ipv4
[2022-06-15 09:07:12] [NOTICE] -   268ms dns.ryan-palmer
[2022-06-15 09:07:12] [NOTICE] -   268ms bcn-dnscrypt
[2022-06-15 09:07:12] [NOTICE] -   272ms dns.digitale-gesellschaft.ch
[2022-06-15 09:07:12] [NOTICE] -   274ms pryv8boi
[2022-06-15 09:07:12] [NOTICE] -   279ms bortzmeyer
[2022-06-15 09:07:12] [NOTICE] -   281ms acsacsar-ams-ipv4
[2022-06-15 09:07:12] [NOTICE] -   281ms wevpn-uswest
[2022-06-15 09:07:12] [NOTICE] -   281ms sgp-dn53
[2022-06-15 09:07:12] [NOTICE] -   288ms dns.digitale-gesellschaft.ch-2
[2022-06-15 09:07:12] [NOTICE] -   309ms dnscrypt.ca-2
[2022-06-15 09:07:12] [NOTICE] -   320ms dnswarden-asia-uncensor-dcv4
[2022-06-15 09:07:12] [NOTICE] -   378ms scaleway-fr
[2022-06-15 09:07:12] [NOTICE] -  1719ms dnscrypt.ca-2-doh
[2022-06-15 09:07:12] [NOTICE] Server with the lowest initial latency: quad101 (rtt: 65ms)
[2022-06-15 09:07:12] [NOTICE] dnscrypt-proxy is ready - live servers: 57
[2022-06-15 09:07:33]   127.0.0.1       help.github.com A       PASS    222ms   techsaviours.org-dnscrypt

There is [WARNING] Empty relay set for while validating servers, but no warning during client querying.

I located it here. It returns nil, and will connect directly:

dnscrypt-proxy/dnscrypt-proxy/serversInfo.go

Lines 469 to 472 in 0a0b69d

	if len(relayStamps) == 0 {
	dlog.Warnf("Empty relay set for [%v]", name)
	return nil, nil
	}

Is there a better strategy, returning an error which will stop further fetching? I'm not sure.

[lifenjoiner]

PR #2128 for this.

[lifenjoiner]

It has been patched. Thanks for your feedback!

[tmo1]

Thank you!