armeria: Domain name resolution failure in Windows

Not sure if it affects all Windows machines, but got a report from at least one user. Full DNS trace:

2019-11-09 21:34:02.482 DEBUG 16800 --- [-worker-nio-2-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [24b42788] HTTP GET "/random"
2019-11-09 21:34:02.506 DEBUG 16800 --- [-worker-nio-2-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [24b42788] Mapped to com.linecorp.devday.handson.demo.controller.DemoController#getRandom()
2019-11-09 21:34:02.546 DEBUG 16800 --- [-worker-nio-2-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'application/json' given [*/*] and supported [application/json, application/*+json, text/event-stream]
2019-11-09 21:34:02.546 DEBUG 16800 --- [-worker-nio-2-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [24b42788] 0..1 [com.linecorp.devday.handson.demo.model.DemoModel]
2019-11-09 21:34:02.614 DEBUG 16800 --- [-worker-nio-2-2] o.s.w.r.f.client.ExchangeFunctions       : [7f5065ca] HTTP GET http://echo.jsontest.com/randomNumber/3/uuid/8a5870e4-834b-4359-aaf7-671289f72102
2019-11-09 21:34:02.683 DEBUG 16800 --- [-worker-nio-2-1] i.n.util.ResourceLeakDetectorFactory     : Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@74984073
2019-11-09 21:34:02.698 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [30527: /10.114.0.1:53], DefaultDnsQuestion(echo.jsontest.com. IN A)
2019-11-09 21:34:02.703 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [57985: /10.114.0.1:53], DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
2019-11-09 21:34:07.707 DEBUG 16800 --- [-worker-nio-2-1] .d.TraceDnsQueryLifeCycleObserverFactory : from /10.114.0.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN A) failure

io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.114.0.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)

2019-11-09 21:34:07.707 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [18314: /210.196.3.183:53], DefaultDnsQuestion(echo.jsontest.com. IN A)
2019-11-09 21:34:07.709 DEBUG 16800 --- [-worker-nio-2-1] .d.TraceDnsQueryLifeCycleObserverFactory : from /10.114.0.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN AAAA) failure

io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.114.0.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)

2019-11-09 21:34:07.709 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [51770: /210.196.3.183:53], DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
2019-11-09 21:34:07.725 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsNameResolver    : [id: 0x294edb68] RECEIVED: UDP [51770: /210.196.3.183:53], DatagramDnsResponse(from: /210.196.3.183:53, to: /0:0:0:0:0:0:0:0:55220, 51770, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
	DefaultDnsRawRecord(echo.jsontest.com. 1212 IN CNAME 16B)
	DefaultDnsRawRecord(ghs.google.com. 3 IN AAAA 16B)
	DefaultDnsRawRecord(OPT flags:0 udp:1400 0B)
2019-11-09 21:34:07.727 DEBUG 16800 --- [-worker-nio-2-1] .d.TraceDnsQueryLifeCycleObserverFactory : from null : DefaultDnsQuestion(echo.jsontest.com. IN AAAA) CNAME question DefaultDnsQuestion(ghs.google.com. IN AAAA)
2019-11-09 21:34:07.727 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [44924: /10.114.0.1:53], DefaultDnsQuestion(ghs.google.com. IN AAAA)
2019-11-09 21:34:07.729 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsNameResolver    : [id: 0x294edb68] RECEIVED: UDP [18314: /210.196.3.183:53], DatagramDnsResponse(from: /210.196.3.183:53, to: /0:0:0:0:0:0:0:0:55220, 18314, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(echo.jsontest.com. IN A)
	DefaultDnsRawRecord(echo.jsontest.com. 1212 IN CNAME 16B)
	DefaultDnsRawRecord(ghs.google.com. 3 IN A 4B)
	DefaultDnsRawRecord(OPT flags:0 udp:1400 0B)
2019-11-09 21:34:07.729 DEBUG 16800 --- [-worker-nio-2-1] .d.TraceDnsQueryLifeCycleObserverFactory : from null : DefaultDnsQuestion(echo.jsontest.com. IN A) CNAME question DefaultDnsQuestion(ghs.google.com. IN A)
2019-11-09 21:34:07.729 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [28905: /10.114.0.1:53], DefaultDnsQuestion(ghs.google.com. IN A)
2019-11-09 21:34:12.729 DEBUG 16800 --- [-worker-nio-2-1] .d.TraceDnsQueryLifeCycleObserverFactory : from /10.114.0.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN AAAA) failure

io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.114.0.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)

2019-11-09 21:34:12.729 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [50156: /210.196.3.183:53], DefaultDnsQuestion(ghs.google.com. IN AAAA)
2019-11-09 21:34:12.732 DEBUG 16800 --- [-worker-nio-2-1] .d.TraceDnsQueryLifeCycleObserverFactory : from /10.114.0.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN A) failure

io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.114.0.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)

2019-11-09 21:34:12.732 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsQueryContext    : [id: 0x294edb68] WRITE: UDP, [25459: /210.196.3.183:53], DefaultDnsQuestion(ghs.google.com. IN A)
2019-11-09 21:34:12.746 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsNameResolver    : [id: 0x294edb68] RECEIVED: UDP [25459: /210.196.3.183:53], DatagramDnsResponse(from: /210.196.3.183:53, to: /0:0:0:0:0:0:0:0:55220, 25459, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(ghs.google.com. IN A)
	DefaultDnsRawRecord(ghs.google.com. 298 IN A 4B)
	DefaultDnsRawRecord(OPT flags:0 udp:1400 0B)
2019-11-09 21:34:12.815 DEBUG 16800 --- [-worker-nio-2-1] io.netty.resolver.dns.DnsNameResolver    : [id: 0x294edb68] RECEIVED: UDP [50156: /210.196.3.183:53], DatagramDnsResponse(from: /210.196.3.183:53, to: /0:0:0:0:0:0:0:0:55220, 50156, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(ghs.google.com. IN AAAA)
	DefaultDnsRawRecord(ghs.google.com. 298 IN AAAA 16B)
	DefaultDnsRawRecord(OPT flags:0 udp:1400 0B)
2019-11-09 21:34:12.815 DEBUG 16800 --- [-worker-nio-2-1] .d.TraceDnsQueryLifeCycleObserverFactory : from /210.196.3.183:53 : DefaultDnsQuestion(ghs.google.com. IN AAAA) cancelled with 8 queries remaining

About this issue

  • Original URL
  • State: open
  • Created 5 years ago
  • Reactions: 2
  • Comments: 20 (4 by maintainers)

Commits related to this issue

Most upvoted comments

I indeed missed that because of the threading, thanks for the pointer. And many thanks for keeping up and finally getting this 10+ years old bug fixed in the JDK!

+1
ibauersachs on Jan 8, 2020

@anuraaga OK with removing it, but perhaps it doesn’t harm because it’s off by default? It may even be useful when JDK had a regression. 😆

+1
trustin on Dec 24, 2019

For reference, result of my investigation - https://github.com/netty/netty/pull/9161#issuecomment-557466297

I think I know how to solve the root problem in principle but will take a while to understand how to do Windows SDK development 😅

+1
anuraaga on Nov 22, 2019

@ikhoon had asked on the PR to get logs for my computer and CI for test DNS queries. It’s a bit more annoying to do on CI, but for now, on my Windows 10 computer I get this.

15:51:17.420 [Test worker] DEBUG i.n.r.d.DefaultDnsServerAddressStreamProvider - Default DNS servers: [/1.1.1.1:53, /1.0.0.1:53] (sun.net.dns.ResolverConfiguration)
15:51:17.460 [Test worker] DEBUG c.l.a.i.dns.DefaultDnsNameResolver - [echo.jsontest.com] Sending DNS queries: [DnsQuestion(echo.jsontest.com IN A), DnsQuestion(echo.jsontest.com IN AAAA)]
15:51:17.479 [Test worker] DEBUG i.n.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@beaee26
15:51:17.490 [Test worker] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x3d1381d1] WRITE: UDP, [4883: /1.1.1.1:53], DefaultDnsQuestion(echo.jsontest.com. IN A)
15:51:17.516 [Test worker] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x3d1381d1] WRITE: UDP, [20240: /1.1.1.1:53], DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
15:51:17.598 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x3d1381d1] RECEIVED: UDP [4883: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:53766, 4883, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(echo.jsontest.com. IN A)
	DefaultDnsRawRecord(echo.jsontest.com. 3357 IN CNAME 16B)
	DefaultDnsRawRecord(ghs.google.com. 283 IN A 4B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
15:51:17.600 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from null : DefaultDnsQuestion(echo.jsontest.com. IN A) CNAME question DefaultDnsQuestion(ghs.google.com. IN A)
15:51:17.601 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x3d1381d1] WRITE: UDP, [26474: /1.1.1.1:53], DefaultDnsQuestion(ghs.google.com. IN A)
15:51:17.604 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x3d1381d1] RECEIVED: UDP [20240: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:53766, 20240, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
	DefaultDnsRawRecord(echo.jsontest.com. 3357 IN CNAME 16B)
	DefaultDnsRawRecord(ghs.google.com. 182 IN AAAA 16B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
15:51:17.605 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from null : DefaultDnsQuestion(echo.jsontest.com. IN AAAA) CNAME question DefaultDnsQuestion(ghs.google.com. IN AAAA)
15:51:17.611 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x3d1381d1] WRITE: UDP, [50943: /1.1.1.1:53], DefaultDnsQuestion(ghs.google.com. IN AAAA)
15:51:17.613 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x3d1381d1] RECEIVED: UDP [26474: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:53766, 26474, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(ghs.google.com. IN A)
	DefaultDnsRawRecord(ghs.google.com. 283 IN A 4B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
15:51:17.621 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x3d1381d1] RECEIVED: UDP [50943: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:53766, 50943, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(ghs.google.com. IN AAAA)
	DefaultDnsRawRecord(ghs.google.com. 182 IN AAAA 16B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
	
16:02:40.739 [Test worker] DEBUG i.n.r.d.DefaultDnsServerAddressStreamProvider - Default DNS servers: [/1.1.1.1:53, /1.0.0.1:53] (sun.net.dns.ResolverConfiguration)
16:02:40.787 [Test worker] DEBUG c.l.a.i.dns.DefaultDnsNameResolver - [json.org] Sending DNS queries: [DnsQuestion(json.org IN A), DnsQuestion(json.org IN AAAA)]
16:02:40.846 [Test worker] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0xe220f93f] WRITE: UDP, [41466: /1.1.1.1:53], DefaultDnsQuestion(json.org. IN AAAA)
16:02:40.944 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0xe220f93f] RECEIVED: UDP [61667: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:51996, 61667, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(json.org. IN A)
	DefaultDnsRawRecord(json.org. 3460 IN A 4B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
16:02:41.188 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0xe220f93f] RECEIVED: UDP [41466: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:51996, 41466, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(json.org. IN AAAA)
	DefaultDnsRawRecord(json.org. 300 IN SOA 58B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
16:02:41.191 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /1.1.1.1:53 : DefaultDnsQuestion(json.org. IN AAAA) failure
io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No matching record type found
	at io.netty.resolver.dns.DnsResolveContext.onResponseAorAAAA(..)(Unknown Source)
16:02:41.192 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0xe220f93f] WRITE: UDP, [1151: /1.0.0.1:53], DefaultDnsQuestion(json.org. IN AAAA)
16:02:41.456 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0xe220f93f] RECEIVED: UDP [1151: /1.0.0.1:53], DatagramDnsResponse(from: /1.0.0.1:53, to: /0:0:0:0:0:0:0:0:51996, 1151, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(json.org. IN AAAA)
	DefaultDnsRawRecord(json.org. 300 IN SOA 58B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
16:02:41.456 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /1.0.0.1:53 : DefaultDnsQuestion(json.org. IN AAAA) failure
io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No matching record type found
	at io.netty.resolver.dns.DnsResolveContext.onResponseAorAAAA(..)(Unknown Source)
16:02:41.457 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - DefaultDnsQuestion(json.org. IN AAAA) query never written and failed
io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name servers returned an answer
	at io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)
16:02:41.458 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0xe220f93f] WRITE: UDP, [44787: /1.1.1.1:53], DefaultDnsQuestion(json.org. IN CNAME)
16:02:41.714 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0xe220f93f] RECEIVED: UDP [44787: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:51996, 44787, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(json.org. IN CNAME)
	DefaultDnsRawRecord(json.org. 300 IN SOA 58B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
16:02:41.716 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /1.1.1.1:53 : DefaultDnsQuestion(json.org. IN CNAME) failure
io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No matching CNAME record found
	at io.netty.resolver.dns.DnsResolveContext.onResponseCNAME(..)(Unknown Source)
16:02:41.719 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0xe220f93f] WRITE: UDP, [4284: /1.0.0.1:53], DefaultDnsQuestion(json.org. IN CNAME)
16:02:41.981 [armeria-common-worker-nio-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0xe220f93f] RECEIVED: UDP [4284: /1.0.0.1:53], DatagramDnsResponse(from: /1.0.0.1:53, to: /0:0:0:0:0:0:0:0:51996, 4284, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(json.org. IN CNAME)
	DefaultDnsRawRecord(json.org. 300 IN SOA 58B)
	DefaultDnsRawRecord(OPT flags:0 udp:1452 0B)
16:02:41.981 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /1.0.0.1:53 : DefaultDnsQuestion(json.org. IN CNAME) failure
io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No matching CNAME record found
	at io.netty.resolver.dns.DnsResolveContext.onResponseCNAME(..)(Unknown Source)
16:02:41.981 [armeria-common-worker-nio-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - DefaultDnsQuestion(json.org. IN CNAME) query never written and failed
io.netty.resolver.dns.DnsResolveContext$DnsResolveContextException: No name servers returned an answer
	at io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(..)(Unknown Source)
16:02:42.411 [armeria-common-worker-nio-2-1] DEBUG c.l.a.c.SessionProtocolNegotiationCache - Updated: 'json.org:80' does not support [h2c]
+1
anuraaga on Nov 22, 2019
Read more comments on GitHub
← armeria: Cookie header doesn't work when debugging with DocService
armeria: Fatal error in gRPC coroutines stack caused by "An error occurred while pushing a context" →