We've recently updated our dependency on dnsjava from 2.1.8 to 3.0.1 in spotify/dns-java#38. But when testing this out with some services, we started seeing timeouts on lookups.
After some debugging, I managed to isolate a scenario that causes this to happen. In our case it's caused by SRV queries on names that contain many records. We see that it first gets a truncated response over UDP and then switches to TCP. This query works fine in itself, but all subsequent queries hang for some time and hit the timeout.
It's hard to reproduce if you don't have a set of SRV records available that would trigger a switch to TCP. But here's the code that reproduces it consistently for us:
public static void main(String[] args) throws TextParseException, InterruptedException {
final String name = "_redacted1._tcp.redacted.net"; // this name contains 28 SRV records
final String name2 = "_redacted2._tcp.redacted.net"; // this name contains i SRV records
final Lookup lookup = new Lookup(name, Type.SRV, DClass.IN);
final Record[] records = lookup.run();
if (records != null) {
System.out.println("records.length = " + records.length);
} else {
System.out.println("records is null");
}
final Lookup lookup2 = new Lookup(name2, Type.SRV, DClass.IN);
final Record[] records2 = lookup2.run();
if (records2 != null) {
System.out.println("records2.length = " + records2.length);
} else {
System.out.println("records2 is null");
}
}The output is
2020-03-16 19:53:38:229 +0100 [main] DEBUG org.xbill.DNS.config.ResolvConfResolverConfigProvider - Added spotify.net. to search paths
2020-03-16 19:53:38:230 +0100 [main] DEBUG org.xbill.DNS.config.ResolvConfResolverConfigProvider - Added /1.1.1.1:53 to nameservers
2020-03-16 19:53:38:289 +0100 [main] DEBUG org.xbill.DNS.Lookup - lookup _redacted1._tcp.redacted.net. SRV, cache answer: unknown
2020-03-16 19:53:38:328 +0100 [main] DEBUG org.xbill.DNS.ExtendedResolver - Sending _redacted1._tcp.redacted.net./SRV, id=27665 to resolver 0 (SimpleResolver [/1.1.1.1:53]), attempt 1 of 3
2020-03-16 19:53:38:330 +0100 [main] DEBUG org.xbill.DNS.SimpleResolver - Sending _redacted1._tcp.redacted.net./SRV, id=27665 to udp/1.1.1.1:53
2020-03-16 19:53:38:332 +0100 [main] DEBUG org.xbill.DNS.Client - Starting dnsjava NIO selector thread
2020-03-16 19:53:38:497 +0100 [ForkJoinPool.commonPool-worker-3] DEBUG org.xbill.DNS.SimpleResolver - Got truncated response for id 27665, retrying via TCP
2020-03-16 19:53:38:497 +0100 [ForkJoinPool.commonPool-worker-3] DEBUG org.xbill.DNS.SimpleResolver - Sending _redacted1._tcp.redacted.net./SRV, id=27665 to tcp/1.1.1.1:53
2020-03-16 19:53:38:792 +0100 [main] DEBUG org.xbill.DNS.Cache - caching successful for _redacted1._tcp.redacted.net.
2020-03-16 19:53:38:793 +0100 [main] DEBUG org.xbill.DNS.Lookup - Queried _redacted1._tcp.redacted.net. SRV: successful
2020-03-16 19:53:38:800 +0100 [main] DEBUG org.xbill.DNS.Lookup - lookup _redacted2._tcp.redacted.net. SRV, cache answer: unknown
2020-03-16 19:53:38:800 +0100 [main] DEBUG org.xbill.DNS.ExtendedResolver - Sending _redacted2._tcp.redacted.net./SRV, id=31420 to resolver 0 (SimpleResolver [/1.1.1.1:53]), attempt 1 of 3
2020-03-16 19:53:38:800 +0100 [main] DEBUG org.xbill.DNS.SimpleResolver - Sending _redacted2._tcp.redacted.net./SRV, id=31420 to udp/1.1.1.1:53
records.length = 28
// freezing for 10 seconds
2020-03-16 19:53:48:808 +0100 [main] DEBUG org.xbill.DNS.Lookup - Lookup failed using resolver ExtendedResolver of [SimpleResolver [/1.1.1.1:53]]
java.net.SocketTimeoutException
at org.xbill.DNS.Resolver.send(Resolver.java:156)
at org.xbill.DNS.Lookup.lookup(Lookup.java:493)
at org.xbill.DNS.Lookup.resolve(Lookup.java:543)
at org.xbill.DNS.Lookup.run(Lookup.java:561)
at org.xbill.DNS.BasicUse.main(BasicUse.java:18)
2020-03-16 19:53:48:809 +0100 [main] DEBUG org.xbill.DNS.Lookup - lookup _redacted2._tcp.redacted.net.spotify.net. SRV, cache answer: unknown
2020-03-16 19:53:48:809 +0100 [main] DEBUG org.xbill.DNS.ExtendedResolver - Sending _redacted2._tcp.redacted.net.spotify.net./SRV, id=58929 to resolver 0 (SimpleResolver [/1.1.1.1:53]), attempt 1 of 3
2020-03-16 19:53:48:810 +0100 [main] DEBUG org.xbill.DNS.SimpleResolver - Sending _redacted2._tcp.redacted.net.spotify.net./SRV, id=58929 to udp/1.1.1.1:53
2020-03-16 19:53:58:813 +0100 [main] DEBUG org.xbill.DNS.Lookup - Lookup failed using resolver ExtendedResolver of [SimpleResolver [/1.1.1.1:53]]
java.net.SocketTimeoutException
at org.xbill.DNS.Resolver.send(Resolver.java:156)
at org.xbill.DNS.Lookup.lookup(Lookup.java:493)
at org.xbill.DNS.Lookup.resolve(Lookup.java:543)
at org.xbill.DNS.Lookup.run(Lookup.java:568)
at org.xbill.DNS.BasicUse.main(BasicUse.java:18)
records2 is null
Debugging this a bit lead me to org.xbill.DNS.Client. After the TCP Transaction is done, the NIO selector thread goes into a busy spin where selector.select(..) always returns 1 signalling that the TCP channel is writable. But since there's nothing to write, the processReadyKey method on ChannelState just returns. I have not debugged further, but I noticed this since the above program started using one core at 100% (the selector thread). I'm guessing this is what is causing subsequent requests not to process and timeout.
We've recently updated our dependency on
dnsjavafrom2.1.8to3.0.1in spotify/dns-java#38. But when testing this out with some services, we started seeing timeouts on lookups.After some debugging, I managed to isolate a scenario that causes this to happen. In our case it's caused by SRV queries on names that contain many records. We see that it first gets a truncated response over UDP and then switches to TCP. This query works fine in itself, but all subsequent queries hang for some time and hit the timeout.
It's hard to reproduce if you don't have a set of SRV records available that would trigger a switch to TCP. But here's the code that reproduces it consistently for us:
The output is
Debugging this a bit lead me to
org.xbill.DNS.Client. After the TCP Transaction is done, the NIO selector thread goes into a busy spin whereselector.select(..)always returns1signalling that the TCP channel is writable. But since there's nothing to write, theprocessReadyKeymethod onChannelStatejust returns. I have not debugged further, but I noticed this since the above program started using one core at 100% (the selector thread). I'm guessing this is what is causing subsequent requests not to process and timeout.