[Unbound-users] stub-prime unexpected behavior

[Aaron Hopkins]

I internally override an externally visible domain to be able to give
different answers with a config like:

stub-zone:
     name: "example.com"
     stub-addr: 10.1.2.3
     stub-addr: 10.1.2.4
     stub-prime: yes

I recently upgraded from Unbound 1.4.4 to 1.4.19 and after running for a few
hours was noticing that queries for foo.bar.example.com (an internal-only
name) started returning NXDOMAIN.  When this happens, "dig -t ns
example.com" shows the external NS records.

It turned out that I had poorly configured a subdomain of example.com with a
lame delegation to itself, and Unbound would eventually stop talking to
10.1.2.3 and 10.1.2.4 because of this, claiming "debug: No more query
targets, attempting last resort".  It then it does what the documentation
for "stub-first" claims, even though I don't have it enabled, and goes and
looks up the nameservers for "example.com" starting with the roots. 
Unfortunately, this means it starts answering queries using the external
nameservers instead of the internal ones.

Is this the expected behavior of stub-prime?  It seems to be a change from
how it was behaving in Unbound 1.4.4.

Disabling stub-prime seems to fix this.

See the sanitized relevant snippet of unbound-host output below.  I can send
a larger unsanitized chunk privately if this isn't enough.

Thanks!

                                     -- Aaron

---

Mar 20 13:03:34 libunbound[13226:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Mar 20 13:03:34 libunbound[13226:0] info: query response was THROWAWAY
Mar 20 13:03:34 libunbound[13226:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Mar 20 13:03:34 libunbound[13226:0] info: processQueryTargets: blah.example.com.example.com. AAAA IN
Mar 20 13:03:34 libunbound[13226:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 10
Mar 20 13:03:34 libunbound[13226:0] info: DelegationPoint<example.com.example.com.>: 2 names (0 missing), 2 addrs (0 result, 0 avail) parentNS
Mar 20 13:03:34 libunbound[13226:0] info:   dnsmaster1.foo.example.com. * A
Mar 20 13:03:34 libunbound[13226:0] info:   dnsmaster2.foo.example.com. * A
Mar 20 13:03:34 libunbound[13226:0] debug:    ip4 10.1.2.4 port 53 (len 16)
Mar 20 13:03:34 libunbound[13226:0] debug:    ip4 10.1.2.3 port 53 (len 16)
Mar 20 13:03:34 libunbound[13226:0] debug: No more query targets, attempting last resort
Mar 20 13:03:34 libunbound[13226:0] info: found in cache dnsmaster1.foo.example.com. A IN
Mar 20 13:03:34 libunbound[13226:0] info: found in cache dnsmaster2.foo.example.com. A IN
Mar 20 13:03:34 libunbound[13226:0] info: new pside target dnsmaster1.foo.example.com. A IN
Mar 20 13:03:34 libunbound[13226:0] debug: try parent-side glue lookup
Mar 20 13:03:34 libunbound[13226:0] debug: mesh_run: iterator module exit state is module_wait_subquery
Mar 20 13:03:34 libunbound[13226:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Mar 20 13:03:34 libunbound[13226:0] info: iterator operate: query dnsmaster1.foo.example.com. A IN
Mar 20 13:03:34 libunbound[13226:0] debug: iter_handle processing q with state INIT REQUEST STATE
Mar 20 13:03:34 libunbound[13226:0] info: resolving dnsmaster1.foo.example.com. A IN
Mar 20 13:03:34 libunbound[13226:0] debug: request has dependency depth of 1
Mar 20 13:03:34 libunbound[13226:0] debug: cache blacklisted, going to the network
Mar 20 13:03:34 libunbound[13226:0] info: priming . IN NS
Mar 20 13:03:34 libunbound[13226:0] debug: mesh_run: iterator module exit state is module_wait_subquery
Mar 20 13:03:34 libunbound[13226:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Mar 20 13:03:34 libunbound[13226:0] info: iterator operate: query . NS IN
Mar 20 13:03:34 libunbound[13226:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Mar 20 13:03:34 libunbound[13226:0] info: processQueryTargets: . NS IN
Mar 20 13:03:34 libunbound[13226:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Mar 20 13:03:34 libunbound[13226:0] info: DelegationPoint<.>: 13 names (0 missing), 13 addrs (0 result, 13 avail) parentNS
Mar 20 13:03:34 libunbound[13226:0] info:   A.ROOT-SERVERS.NET. * A
Mar 20 13:03:34 libunbound[13226:0] info:   B.ROOT-SERVERS.NET. * A
Mar 20 13:03:34 libunbound[13226:0] info:   C.ROOT-SERVERS.NET. * A
Mar 20 13:03:34 libunbound[13226:0] info:   D.ROOT-SERVERS.NET. * A