SRV/TXT lookup performed after TXT/SRV lookup slow on Windows when using the system resolver config

[patrickfreed]

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.

[bluejekyll]

Is it possible for you to try 0.21.0.alpha.5? That has a few performance improvements that may help here.

[bluejekyll]

@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.

[djc]

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.

[patrickfreed]

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.