hickory-dns
hickory-dns copied to clipboard
SRV/TXT lookup performed after TXT/SRV lookup slow on Windows when using the system resolver config
Describe the bug On Windows, the first TXT lookup performed after an SRV lookup (or vice-versa) when using the system resolver config is very slow. This appears to be a known issue per the README, but I haven't seen any GitHub Issue tracking it yet. Is there any progress towards a fix? Using an alternative resolver config (e.g. Cloudflare) seems to fix the issue.
To Reproduce
let system_resolver = trust_dns_resolver::TokioAsyncResolver::tokio_from_system_conf().unwrap();
let cloudflare_resolver = trust_dns_resolver::TokioAsyncResolver::tokio(
ResolverConfig::cloudflare(),
Default::default(),
)
.unwrap();
let start = std::time::Instant::now();
let srv = system_resolver
.srv_lookup(host)
.await
.unwrap();
println!("system srv elapsed: {}s", start.elapsed().as_secs());
let start = std::time::Instant::now();
let txt = system_resolver
.txt_lookup(host)
.await
.unwrap();
println!("system txt elapsed: {}s", start.elapsed().as_secs());
let start = std::time::Instant::now();
let srv = cloudflare_resolver
.srv_lookup(host)
.await
.unwrap();
println!("cloudflare srv elapsed: {}s", start.elapsed().as_secs());
let start = std::time::Instant::now();
let txt = cloudflare_resolver
.txt_lookup(host)
.await
.unwrap();
println!("cloudflare txt elapsed: {}s", start.elapsed().as_secs());
prints
system srv elapsed: 0s
system txt elapsed: 5s
cloudflare srv elapsed: 0s
cloudflare txt elapsed: 0s
Expected behavior All requests are expected to be fast.
System:
- OS: Microsoft Windows
- Architecture: x86_64
- Version: Server 2016 Datacenter
- rustc version: 1.58.0
Version: Crate: resolver Version: 0.20.4
Additional context
This currently requires users of the mongodb
crate to work around this by manually specifying an alternative resolver, which is not ideal.
Is it possible for you to try 0.21.0.alpha.5
? That has a few performance improvements that may help here.
@djc, I think this might go back to our "trust_nx_responses" flags where local resolvers are not trusted, yet cloudflare, quad9, and google are. I'm not sure of a great strategy here since we know that misconfigured local resolvers will consistently cause us problems. I wonder if we should consider lowering the timeouts on requests?
@patrickfreed, if possible, could you enable debug logging for the trust-dns libraries and share the log output from that? You can use the binary, resolve
from the trust-dns-util
crate to test the resolver performance and pass the --debug
flag which might make it easier to capture this output.
Yeah, 5s seems like a pretty long timeout to have. I think we saw better results at about 2s, although that was with Google public DNS.
So I wasn't able to reproduce the issue using the resolve
utility, since it only seems to happen when performing an SRV/TXT lookup after a TXT/SRV lookup, and resolve
can only perform one at a time.
I was able to get debug logging output from my above example though, hopefully it's helpful:
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::xfer::dns_handle] querying: redacted TXT
[2022-03-25T21:19:44Z DEBUG trust_dns_resolver::name_server::name_server_pool] sending request: [Query { name: Name { is_fqdn: false, label_data: [99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 13, 20, 23] }, query_type: TXT, query_class: IN }]
[2022-03-25T21:19:44Z DEBUG trust_dns_resolver::name_server::name_server] reconnecting: NameServerConfig { socket_addr: 10.122.0.2:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: false }
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 13, 20, 23] }, query_type: TXT, query_class: IN }]
[2022-03-25T21:19:44Z DEBUG trust_dns_resolver::name_server::name_server] reconnecting: NameServerConfig { socket_addr: [fec0:0:0:ffff::1]:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: false }
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 13, 20, 23] }, query_type: TXT, query_class: IN }]
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::udp::udp_client_stream] received message id: 29977
system txt elapsed: 0s
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::xfer::dns_handle] querying: _mongodb._tcp.redacted SRV
[2022-03-25T21:19:44Z DEBUG trust_dns_resolver::name_server::name_server_pool] sending request: [Query { name: Name { is_fqdn: false, label_data: [95, 109, 111, 110, 103, 111, 100, 98, 95, 116, 99, 112, 99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 12, 20, 25, 32, 35] }, query_type: SRV, query_class: IN }]
[2022-03-25T21:19:44Z DEBUG trust_dns_resolver::name_server::name_server] existing connection: NameServerConfig { socket_addr: [fec0:0:0:ffff::1]:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: false }
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [95, 109, 111, 110, 103, 111, 100, 98, 95, 116, 99, 112, 99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 12, 20, 25, 32, 35] }, query_type: SRV, query_class: IN }]
[2022-03-25T21:19:44Z DEBUG trust_dns_resolver::name_server::name_server] reconnecting: NameServerConfig { socket_addr: [fec0:0:0:ffff::2]:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: false }
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [95, 109, 111, 110, 103, 111, 100, 98, 95, 116, 99, 112, 99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 12, 20, 25, 32, 35] }, query_type: SRV, query_class: IN }]
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:44Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:49Z DEBUG trust_dns_resolver::name_server::name_server] name_server connection failure: request timed out
[2022-03-25T21:19:49Z DEBUG trust_dns_resolver::name_server::name_server] name_server connection failure: request timed out
[2022-03-25T21:19:49Z DEBUG trust_dns_resolver::name_server::name_server] reconnecting: NameServerConfig { socket_addr: [fec0:0:0:ffff::3]:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: false }
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [95, 109, 111, 110, 103, 111, 100, 98, 95, 116, 99, 112, 99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 12, 20, 25, 32, 35] }, query_type: SRV, query_class: IN }]
[2022-03-25T21:19:49Z DEBUG trust_dns_resolver::name_server::name_server] existing connection: NameServerConfig { socket_addr: 10.122.0.2:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: false }
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [95, 109, 111, 110, 103, 111, 100, 98, 95, 116, 99, 112, 99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 12, 20, 25, 32, 35] }, query_type: SRV, query_class: IN }]
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::udp::udp_client_stream] received message id: 29363
system srv elapsed: 5s
system srv elapsed: 0s
system srv elapsed: 0s
system txt elapsed: 0s
cloudflare srv elapsed: 0s
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer::dns_handle] querying: redacted TXT
[2022-03-25T21:19:49Z DEBUG trust_dns_resolver::name_server::name_server_pool] sending request: [Query { name: Name { is_fqdn: false, label_data: [99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 13, 20, 23] }, query_type: TXT, query_class: IN }]
[2022-03-25T21:19:49Z DEBUG trust_dns_resolver::name_server::name_server] reconnecting: NameServerConfig { socket_addr: 1.1.1.1:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: true }
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 13, 20, 23] }, query_type: TXT, query_class: IN }]
[2022-03-25T21:19:49Z DEBUG trust_dns_resolver::name_server::name_server] reconnecting: NameServerConfig { socket_addr: 1.0.0.1:53, protocol: Udp, tls_dns_name: None, trust_nx_responses: true }
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer] enqueueing message: [Query { name: Name { is_fqdn: false, label_data: [99, 108, 117, 115, 116, 101, 114, 48, 101, 101, 54, 56, 98, 109, 111, 110, 103, 111, 100, 98, 110, 101, 116], label_ends: [8, 13, 20, 23] }, query_type: TXT, query_class: IN }]
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::udp::udp_stream] created socket successfully
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::udp::udp_client_stream] received message id: 8013
cloudflare txt elapsed: 0s
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer::dns_exchange] io_stream is done, shutting down
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer::dns_exchange] io_stream is done, shutting down
[2022-03-25T21:19:49Z DEBUG trust_dns_proto::xfer::dns_exchange] io_stream is done, shutting down
It looks like it tries to reuse the connection established for the TXT lookup but times out.