Open trustin opened 4 years ago
What's interesting is that the resolver sends queries to 10.114.0.1
which is not listed in the system DNS server list.
We had similar problem in our framework using Vert.x (that uses Netty under the hood). Our temp solution was to disable Netty DNS Resolver when running on a Windows OS.
@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]
My branch with the tests - https://github.com/anuraaga/armeria/tree/dns-test-windows
I noticed that at the top of my logs it lists the DNS servers that were recognized by DefaultDnsServerAddressStreamProvider , but the original post is missing that log. It could be nice to get that log if available.
While looking for potential other approaches to finding DNS servers on Windows, I came across this
https://github.com/dnsjava/dnsjava/issues/8#issuecomment-493745283
Querying the registry on Windows is a no go. This is what Java is currently doing, and it fails miserably: As soon as you have more than one NIC (i.e. almost every laptop), you have multiple DNS server addresses in the registry. Some of them might be from a WiFi connection that is now offline. Java still queries them... 🤦♂️
So I suspect 10.114.0.1
is from an offline NIC. Either way, from @trustin's log it seems like 210.196.3.183
is working and the log actually looks like a successful DNS resolution to me (in the end it cancels AAAA query presumably because A query resolved and IPV4 is preferred by default). Do you know what the end user exception was, was it actually DnsNameResolverTimeoutException
or is it ResponseTimeoutException
because the query takes forever by querying unreachable DNS servers? If so, then things make sense to me, otherwise still a little confused.
I think the best solution would be doing something similar to what netty now does for macos, using JNI to get the state of the network config of the machine. According to that linked comment, I guess it's hopeless trying to get proper name servers on Windows with Java. A workaround could be for us to wrap the default DNS server names list on Windows with something that can filter out addresses - we can mark server addresses as down in a lifecycle observer that encounters DnsNameResolverTimeoutException
.
For reference,
I've tried to reproduce the error in a netty test case, but it always succeeds since the working DNS server resolves the address.
@Test
public void testOneDnsServerDownFallsBack() {
DnsNameResolver resolver = new DnsNameResolverBuilder(group.next())
.channelType(NioDatagramChannel.class)
.nameServerProvider(new SequentialDnsServerAddressStreamProvider(
new InetSocketAddress("10.123.234.1", 53),
new InetSocketAddress("8.8.8.8", 53)))
.resolveCache(NoopDnsCache.INSTANCE)
.authoritativeDnsServerCache(NoopAuthoritativeDnsServerCache.INSTANCE)
.cnameCache(NoopDnsCnameCache.INSTANCE)
.traceEnabled(true)
.resolvedAddressTypes(ResolvedAddressTypes.IPV4_PREFERRED)
.completeOncePreferredResolved(true)
.build();
try {
InetAddress address = resolver.resolve("echo.jsontest.com").syncUninterruptibly().getNow();
System.out.println(address);
} finally {
resolver.close();
}
}
Basically identical logs to the posted trace:
18:13:25.079 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x765a96b3] WRITE: UDP, [34302: /10.123.234.1:53], DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
18:13:30.096 [nioEventLoopGroup-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /10.123.234.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN A) failure
io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.123.234.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)
18:13:30.097 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x765a96b3] WRITE: UDP, [60232: /8.8.8.8:53], DefaultDnsQuestion(echo.jsontest.com. IN A)
18:13:30.098 [nioEventLoopGroup-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /10.123.234.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN AAAA) failure
io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.123.234.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)
18:13:30.099 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x765a96b3] WRITE: UDP, [58771: /8.8.8.8:53], DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
18:13:30.219 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x765a96b3] RECEIVED: UDP [58771: /8.8.8.8:53], DatagramDnsResponse(from: /8.8.8.8:53, to: /0:0:0:0:0:0:0:0:64591, 58771, QUERY(0), NoError(0), RD RA)
DefaultDnsQuestion(echo.jsontest.com. IN AAAA)
DefaultDnsRawRecord(echo.jsontest.com. 3599 IN CNAME 16B)
DefaultDnsRawRecord(ghs.google.com. 299 IN AAAA 16B)
DefaultDnsRawRecord(OPT flags:0 udp:512 0B)
18:13:30.220 [nioEventLoopGroup-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from null : DefaultDnsQuestion(echo.jsontest.com. IN AAAA) CNAME question DefaultDnsQuestion(ghs.google.com. IN AAAA)
18:13:30.220 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x765a96b3] WRITE: UDP, [48637: /10.123.234.1:53], DefaultDnsQuestion(ghs.google.com. IN AAAA)
18:13:30.368 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x765a96b3] RECEIVED: UDP [60232: /8.8.8.8:53], DatagramDnsResponse(from: /8.8.8.8:53, to: /0:0:0:0:0:0:0:0:64591, 60232, QUERY(0), NoError(0), RD RA)
DefaultDnsQuestion(echo.jsontest.com. IN A)
DefaultDnsRawRecord(echo.jsontest.com. 3599 IN CNAME 16B)
DefaultDnsRawRecord(ghs.google.com. 299 IN A 4B)
DefaultDnsRawRecord(OPT flags:0 udp:512 0B)
18:13:30.368 [nioEventLoopGroup-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from null : DefaultDnsQuestion(echo.jsontest.com. IN A) CNAME question DefaultDnsQuestion(ghs.google.com. IN A)
18:13:30.368 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x765a96b3] WRITE: UDP, [45120: /10.123.234.1:53], DefaultDnsQuestion(ghs.google.com. IN A)
18:13:35.223 [nioEventLoopGroup-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /10.123.234.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN AAAA) failure
io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.123.234.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)
18:13:35.223 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x765a96b3] WRITE: UDP, [13227: /8.8.8.8:53], DefaultDnsQuestion(ghs.google.com. IN AAAA)
18:13:35.266 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x765a96b3] RECEIVED: UDP [13227: /8.8.8.8:53], DatagramDnsResponse(from: /8.8.8.8:53, to: /0:0:0:0:0:0:0:0:64591, 13227, QUERY(0), NoError(0), RD RA)
DefaultDnsQuestion(ghs.google.com. IN AAAA)
DefaultDnsRawRecord(ghs.google.com. 299 IN AAAA 16B)
DefaultDnsRawRecord(OPT flags:0 udp:512 0B)
18:13:35.380 [nioEventLoopGroup-2-1] DEBUG i.n.r.d.TraceDnsQueryLifeCycleObserverFactory - from /10.123.234.1:53 : DefaultDnsQuestion(echo.jsontest.com. IN A) failure
io.netty.resolver.dns.DnsNameResolverTimeoutException: [/10.123.234.1:53] query via UDP timed out after 5000 milliseconds (no stack trace available)
18:13:35.381 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsQueryContext - [id: 0x765a96b3] WRITE: UDP, [22652: /8.8.8.8:53], DefaultDnsQuestion(ghs.google.com. IN A)
18:13:35.463 [nioEventLoopGroup-2-1] DEBUG i.netty.resolver.dns.DnsNameResolver - [id: 0x765a96b3] RECEIVED: UDP [22652: /8.8.8.8:53], DatagramDnsResponse(from: /8.8.8.8:53, to: /0:0:0:0:0:0:0:0:64591, 22652, QUERY(0), NoError(0), RD RA)
DefaultDnsQuestion(ghs.google.com. IN A)
DefaultDnsRawRecord(ghs.google.com. 299 IN A 4B)
DefaultDnsRawRecord(OPT flags:0 udp:512 0B)
echo.jsontest.com/216.58.197.211
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 😅
Went ahead and sent patch for OpenJDK, though we'd probably still need a solution for pre-Java 14 even if it gets accepted.
https://mail.openjdk.java.net/pipermail/net-dev/2019-November/013339.html
Based on my investigation, I think in practice this basically only affects Windows laptops that ever connect to a wired network where that network specified internal DNS servers. It's possible to workaround by specifying DNS servers manually for that adapter or enabling the flag we added. This corner case doesn't seem to be enough to enable the flag by default on Windows to me, so maybe we can close this issue.
@anuraaga I’ve learned a lot from your research. I understood why it does not work for Windows. 🙇
@trustin @ikhoon Just to confirm if Java 14 has the fix and we're happy with having a JVM that works, would we be able to remove this flag post-1.0.0? I guess it's not a breaking change to ignore system properties (and JDK itself doesn't fear flag breakages).
@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. :laughing:
Java 14 is scheduled for a production release on March 17 2020. Maybe Armenia release 1.0.0 is faster than Java 14. I leaned forward to leaving the flag for troubleshooting with Window and ~Java13.
I think we need to confirm the JDK blocking dns resolution this does not cause a deadlock problem(@anuraaga said in https://github.com/line/armeria/pull/2261#issuecomment-55375840) to keep going with it.
I mainly wanted to confirm we're ok with removing flags post-1.0.0. If so, we don't have to worry about it now.
We have three workarounds now, probably a record given the low chance of hitting the corner case ;)
So maybe we can go ahead and close this issue out if that's enough.
How did you come to the conclusion that Java 14 fixes this?
I have a patch almost finished for openjdk (link to email thread is a few comments up) which should get in for it I think.
I saw that patch, but the only reaction was from an Apache developer in November and nothing since. You need to follow up on that or its going to rot there on the mailing list. JDK14 is already in the rampdown phase, so im almost certain your patch won't make it there.
It looks like the web UI doesn't thread across months, please check out the December and January archives too
https://mail.openjdk.java.net/pipermail/net-dev/2019-December/013360.html
https://mail.openjdk.java.net/pipermail/net-dev/
I've been working with a couple Oracle devs to clean it up and have gotten positive responses all in all. You're right that with some year-end delays, I'm not sure if this will hit or be pushed to 15 but given there is no new API I'm hopeful it's still possible.
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!
https://hg.openjdk.java.net/jdk/jdk/rev/559fcd53e782 has finally landed. But unfortunately it does look like it'll have to wait until Java 15 to finally fix this bug :)
:scream:
Not sure if it affects all Windows machines, but got a report from at least one user. Full DNS trace: