search

NLnetLabs / unbound

Unbound is a validating, recursive, and caching DNS resolver.
https://nlnetlabs.nl/unbound
BSD 3-Clause "New" or "Revised" License
3.03k stars 347 forks source link

Unbound returns SERVFAIL if NS servers in AUTHORITY SECTION are unreachable #844

Open kmadac opened 1 year ago

kmadac commented 1 year ago

Describe the bug I our specific internal infrastructure scenario we have following response from internal upstream DNS recusror:

; <<>> DiG 9.16.1-Ubuntu <<>> @100.64.16.9 www.slov-lex.sk
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 21776
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 2, ADDITIONAL: 5

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;www.slov-lex.sk.       IN  A

;; ANSWER SECTION:
www.slov-lex.sk.    1239    IN  A   195.80.182.170

;; AUTHORITY SECTION:
slov-lex.sk.        3403    IN  NS  ns1.gov.sk.
slov-lex.sk.        3403    IN  NS  ns2.gov.sk.

;; ADDITIONAL SECTION:
ns1.gov.sk.     3403    IN  A   195.49.191.162
ns1.gov.sk.     3403    IN  AAAA    2001:67c:1bd4:8080::10
ns2.gov.sk.     3403    IN  A   195.49.191.160
ns2.gov.sk.     3403    IN  AAAA    2001:67c:1bd4:8080::20

;; Query time: 3 msec
;; SERVER: 100.64.16.9#53(100.64.16.9)
;; WHEN: Fri Feb 10 09:35:40 CET 2023
;; MSG SIZE  rcvd: 188

Unfortunately ns1.gov.sk and ns2.gov.sk are not reachable in our infrastructure (those NS records are incorrectly leaking in some special cases, but I'm not able to change it as it is not under our control) and unbound returns SERVFAIL to client even correct A record is in ANSWER SECTION.

Here are unbound logs:

2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: cannot validate non-answer, rcode SERVFAIL  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator: nextmodule returned  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: return error response SERVFAIL  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: store error response in message cache   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: out of query targets -- returning SERVFAIL  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: found parent-side ns2.gov.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: ns2.gov.sk. * A AAAA     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: DelegationPoint<slov-lex.sk.>: 2 names (0 missing), 0 addrs (0 result, 0 avail) cacheNS  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processQueryTargets: www.slov-lex.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state QUERY TARGETS STATE     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: iterator operate: query www.slov-lex.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator[module 1] operate: extstate:module_wait_subquery event:module_event_pass   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator TargetResponse failed  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processTargetResponse super www.slov-lex.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: not validating response, is valrec(validation recursion lookup)     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state FINISHED RESPONSE STATE     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: returning answer from cache.    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: msg ttl is 3174, prefetch ttl 2814  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 ;; QUESTION SECTION: ns1.gov.sk. IN A ;; ANSWER SECTION: ;; AUTHORITY SECTION: gov.sk. 3174 IN SOA g2nsg1.gov.sk. hostmaster.gov.sk. 2023020201 21600 3600 604800 3600 ;; ADDITIONAL SECTION: ;; MSG SIZE rcvd: 82     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: request has dependency depth of 1   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: resolving ns1.gov.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state INIT REQUEST STATE  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: iterator operate: query ns1.gov.sk. A IN     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: iterator module exit state is module_wait_subquery    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: no current targets -- waiting for 1 targets to resolve.     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: ns1.gov.sk. * AAAA   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: ns2.gov.sk. * A AAAA     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: DelegationPoint<slov-lex.sk.>: 2 names (0 missing), 0 addrs (0 result, 0 avail) cacheNS  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: processQueryTargets: targetqueries 1, currentqueries 0 sentcount 0  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processQueryTargets: www.slov-lex.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state QUERY TARGETS STATE     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: iterator operate: query www.slov-lex.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator[module 1] operate: extstate:module_wait_subquery event:module_event_pass   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator TargetResponse failed  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processTargetResponse super www.slov-lex.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processTargetResponse ns2.gov.sk. AAAA IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: validator module exit state is module_finished    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: not validating response, is valrec(validation recursion lookup)     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator: nextmodule returned  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: validator operate: query ns2.gov.sk. AAAA IN     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: iterator module exit state is module_finished     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: finishing processing for ns2.gov.sk. AAAA IN     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state FINISHED RESPONSE STATE     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: returning answer from cache.    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: msg ttl is 3174, prefetch ttl 2814  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 ;; QUESTION SECTION: ns2.gov.sk. IN AAAA ;; ANSWER SECTION: ;; AUTHORITY SECTION: gov.sk. 3174 IN SOA g2nsg1.gov.sk. hostmaster.gov.sk. 2023020201 21600 3600 604800 3600 ;; ADDITIONAL SECTION: ;; MSG SIZE rcvd: 82  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: request has dependency depth of 1   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: resolving ns2.gov.sk. AAAA IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state INIT REQUEST STATE  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: iterator operate: query ns2.gov.sk. AAAA IN  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator TargetResponse failed  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processTargetResponse super www.slov-lex.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processTargetResponse ns2.gov.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: validator module exit state is module_finished    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: not validating response, is valrec(validation recursion lookup)     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator: nextmodule returned  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: validator operate: query ns2.gov.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: iterator module exit state is module_finished     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: finishing processing for ns2.gov.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state FINISHED RESPONSE STATE     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: returning answer from cache.    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: msg ttl is 3174, prefetch ttl 2814  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 ;; QUESTION SECTION: ns2.gov.sk. IN A ;; ANSWER SECTION: ;; AUTHORITY SECTION: gov.sk. 3174 IN SOA g2nsg1.gov.sk. hostmaster.gov.sk. 2023020201 21600 3600 604800 3600 ;; ADDITIONAL SECTION: ;; MSG SIZE rcvd: 82     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: request has dependency depth of 1   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: resolving ns2.gov.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state INIT REQUEST STATE  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: iterator operate: query ns2.gov.sk. A IN     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator TargetResponse failed  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processTargetResponse super www.slov-lex.sk. A IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processTargetResponse ns1.gov.sk. AAAA IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: validator module exit state is module_finished    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: not validating response, is valrec(validation recursion lookup)     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator: nextmodule returned  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: validator operate: query ns1.gov.sk. AAAA IN     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: iterator module exit state is module_finished     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: finishing processing for ns1.gov.sk. AAAA IN     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state FINISHED RESPONSE STATE     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: returning answer from cache.    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: msg ttl is 3174, prefetch ttl 2814  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 ;; QUESTION SECTION: ns1.gov.sk. IN AAAA ;; ANSWER SECTION: ;; AUTHORITY SECTION: gov.sk. 3174 IN SOA g2nsg1.gov.sk. hostmaster.gov.sk. 2023020201 21600 3600 604800 3600 ;; ADDITIONAL SECTION: ;; MSG SIZE rcvd: 82  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: request has dependency depth of 1   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: resolving ns1.gov.sk. AAAA IN    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state INIT REQUEST STATE  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: iterator operate: query ns1.gov.sk. AAAA IN  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: iterator module exit state is module_wait_subquery    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: no current targets -- waiting for 4 targets to resolve.     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: new target ns1.gov.sk. A IN  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: new target ns1.gov.sk. AAAA IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: new target ns2.gov.sk. A IN  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: new target ns2.gov.sk. AAAA IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: attempt to get extra 3 targets  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: ns1.gov.sk.  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: ns2.gov.sk.  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: DelegationPoint<slov-lex.sk.>: 2 names (2 missing), 0 addrs (0 result, 0 avail) cacheNS  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: processQueryTargets: www.slov-lex.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state QUERY TARGETS STATE     
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: resolving (init part 3): www.slov-lex.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)    
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: resolving (init part 2): www.slov-lex.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)    
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: ns1.gov.sk.  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: ns2.gov.sk.  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: DelegationPoint<slov-lex.sk.>: 2 names (2 missing), 0 addrs (0 result, 0 avail) cacheNS  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: cache delegation returns delegpt    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: request has dependency depth of 0   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: resolving www.slov-lex.sk. A IN  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iter_handle processing q with state INIT REQUEST STATE  
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: process_request: new external request event     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: validator module exit state is module_wait_module     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator: pass to next module  
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: validator operate: query www.slov-lex.sk. A IN   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: mesh_run: start     
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: udp request from ip4 192.168.1.99 port 49865 (len 16)   
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: answer from the cache failed    
2023-02-09T22:12:54 unbound[83625]  [83625:1] debug: using localzone . transparent   
2023-02-09T22:12:54 unbound[83625]  [83625:1] info: 192.168.1.99 www.slov-lex.sk. A IN

To reproduce Steps to reproduce the behavior: Forbid access to NS server IP addresses on firewall which are in particular DNS server response and try to resolve it via Unbound.

Expected behavior Send NOERROR response to client with A record without trying to contact NS servers as A record is already in response :

System:

Version 1.13.2

Configure line: --with-ssl=/usr/local --with-libexpat=/usr/local --disable-dnscrypt --disable-dnstap --with-libnghttp2 --enable-ecdsa --disable-event-api --enable-gost --with-libevent --with-pyunbound=yes --with-pythonmodule=yes LDFLAGS=-L/usr/local/lib ac_cv_path_SWIG=/usr/local/bin/swig --disable-subnet --disable-tfo-client --disable-tfo-server --with-pthreads --prefix=/usr/local --localstatedir=/var --mandir=/usr/local/man --infodir=/usr/local/share/info/ --build=amd64-portbld-freebsd12.1 Linked libs: libevent 2.1.12-stable (it uses kqueue), OpenSSL 1.1.1l 24 Aug 2021 Linked modules: dns64 python respip validator iterator

BSD licensed, see LICENSE in source package for details. Report bugs to unbound-bugs@nlnetlabs.nl or https://github.com/NLnetLabs/unbound/issues

Additional information Add any other information that you may have gathered about the issue here.

ShipeiXu commented 1 year ago

I reproduced this problem. There is a domain name in China, www.cscec.com. When it sends a cscec-ipv6.cscec.com resolution request to its authoritative server, the server responds with icmp host not unreachable. Observe the unbound log, and it is always resolving this domain (cscec-ipv6 .cscec.com). Eventually serverfail was responded. There is a problem with the authoritative server, but unbound is not robust enough.

ShipeiXu commented 1 year ago

I try to modify the code, in the file iterator/iter_resptype.c, in the response_type_from_server function, why do the following checks: if( (msg->rep->flags&BIT_RA) && !(msg->rep->flags&BIT_AA) && !rdset) { return RESPONSE_TYPE_REC_LAME; }

I don't think it makes sense. When I comment out this code, unbound can be parsed correctly. But there are still some problems. Need to continue analyzing the code.