unbound
unbound copied to clipboard
NLnetLabs
DNS response to negative cache ttl is not rfc compliant
Describe the bug RFC 2308 stipulates that for authoritative server responses to nxdomain, the parser unbound needs to be cached according to the minimum of ttl and minimum ttl. But I observed that unbound did not adopt this standard, but directly used the cache-max-negative-ttl value. This is not expected.
"Name servers authoritative for a zone MUST include the SOA record of the zone in the authority section of the response when reporting an NXDOMAIN or indicating that no data of the requested type exists. This is required so that the response may be cached. "
To reproduce Steps to reproduce the behavior:
- dig @127.0.0.1 mail.cinda.com.cn
- result is: cinda.com.cn. 597 IN SOA cinda.com.cn. root.cinda.com.cn. 2006080401 1 86400 2419200 1
Expected behavior the result need to be: cinda.com.cn. 1 IN SOA cinda.com.cn. root.cinda.com.cn. 2006080401 1 86400 2419200 1
System:
- Unbound version: Version 1.14.0
- OS: centos 3.10.0-1160.80.1.el7.x86_64
unbound -Voutput: Version 1.14.0 Configure line: --with-libnghttp2 --prefix=/usr/unbound/ --enable-subnet --with-pthreads --with-libevent --enable-dnstap --enable-cachedb --enable-ipsecmod --enable-ipset --enable-linux-ip-local-port-range --enable-dnscrypt --enable-systemd --with-pythonmodule Linked libs: libevent 2.0.21-stable (it uses epoll), OpenSSL 1.0.2k-fips 26 Jan 2017 Linked modules: dns64 python cachedb ipsecmod subnetcache ipset respip validator iterator DNSCrypt feature available
BSD licensed, see LICENSE in source package for details. Report bugs to [email protected] or https://github.com/NLnetLabs/unbound/issues
Additional information Add any other information that you may have gathered about the issue here.
When I run this query, I get the result with 1 TTL for the SOA. The changelog says this was fixed in 1.13.1, so it should work in 1.14.0. It seems to work with the latest version, from the code repository. It does not seem to go wrong, it correctly picks up the minimum of the SOA TTL and the SOA MINIMUM TTL. And the answer is returned with a SOA record with a TTL of 1 for the query from the issue.
“To reproduce: Steps to reproduce the behavior:
dig @127.0.0.1 mail.cinda.com.cn type65”
I must correct the reproduction steps and use type65 type request instead of the default a type. And I'm sure the ttl of response is wrong.
Yes, because type A exists, another type gives a SOA answer. So if I try it here with the latest version, it seems to work fine. But it does not work where you test it. Could you test this with the latest version, of Unbound. And then capture what unbound is doing during the resolution at a higher verbosity level, like 4 or 5, so Unbound logs what it is doing? Perhaps that can shed light on why it is going wrong, when it works when it is tried without I guess some other issue, over here.
First of all, when a certain type of domain name exists and the client requests a type that does not exist, noerr should be returned instead of nxdomain/soa. However, this is not an unbound error, but an authoritative error. However, the authoritative soa response ttl is 1, but unbound uses cache-max-negative-ttl as the buffering ttl. This is an unbound error.
I did a test using unbound version 1.17.1 and the conclusion is the same.
Dec 12 09:53:19 unbound[27046:2] query: 114.254.1.104 mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: udp request from ip4 114.254.1.104 port 47774 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: mesh_run: start Dec 12 09:53:19 unbound[27046:2] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Dec 12 09:53:19 unbound[27046:2] debug: process_request: new external request event Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state INIT REQUEST STATE Dec 12 09:53:19 unbound[27046:2] info: resolving mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: request has dependency depth of 0 Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2) Dec 12 09:53:19 unbound[27046:2] info: resolving (init part 2): mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3) Dec 12 09:53:19 unbound[27046:2] info: resolving (init part 3): mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state QUERY TARGETS STATE Dec 12 09:53:19 unbound[27046:2] info: processQueryTargets: mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Dec 12 09:53:19 unbound[27046:2] info: DelegationPoint<.>: empty Dec 12 09:53:19 unbound[27046:2] info: auth_zone . query mail.cinda.com.cn. HTTPS, domain cn. notexact notexist, ce cn., rrset NS Dec 12 09:53:19 unbound[27046:2] info: msg from auth zone ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr ; QUERY: 1, ANSWER: 0, AUTHORITY: 8, ADDITIONAL: 11 ;; QUESTION SECTION: mail.cinda.com.cn. IN HTTPS
;; ANSWER SECTION:
;; AUTHORITY SECTION: cn. 172800 IN NS a.dns.cn. cn. 172800 IN NS b.dns.cn. cn. 172800 IN NS c.dns.cn. cn. 172800 IN NS d.dns.cn. cn. 172800 IN NS e.dns.cn. cn. 172800 IN NS ns.cernet.net. cn. 86400 IN DS 57724 8 2 5D0423633EB24A499BE78AA22D1C0C9BA36218FF49FD95A4CDF1A4AD97C67044 cn. 86400 IN RRSIG DS 8 1 86400 20231224220000 20231211210000 46780 . mjbNyoKM3FP6yOjLSNyxYsdiFfE1oe7kOvO7ZEO9dRi0wyaxgEHO2v5lInSqHw9K9b2fovw16RhV680G7Up7o/dxuKs4GSgPwz+RydSeE8zcFuNyazdnmSgCUtQy2qr4ASygF+frOluYExyMmDiG+yYJQPwLm14uyVau2fH6YsRQoySfchDgiH+b2nOjDhRyUlfb2vyzz5xSmvuaEb9hLDHrXCRV6sBLkq4zSEKi4VytXDYCPLHVrMgR5rx3QeRoxK0K0XQWHGz6JDL/rizBNg0dyCkonbxr+eYpvQvdJNGGF5vpsALANoaaej3PkSrh1J9OKtjy8DcKJsDlnlfrFg== ;{id = 46780}
;; ADDITIONAL SECTION: a.dns.cn. 172800 IN A 203.119.25.1 a.dns.cn. 172800 IN AAAA 2001:dc7::1 b.dns.cn. 172800 IN A 203.119.26.1 b.dns.cn. 172800 IN AAAA 2001:dc7:1::1 c.dns.cn. 172800 IN A 203.119.27.1 c.dns.cn. 172800 IN AAAA 2001:dc7:2::1 d.dns.cn. 172800 IN A 203.119.28.1 d.dns.cn. 172800 IN AAAA 2001:dc7:1000::1 e.dns.cn. 172800 IN A 203.119.29.1 e.dns.cn. 172800 IN AAAA 2001:dc7:3::1 ns.cernet.net. 172800 IN A 202.112.0.44 ;; MSG SIZE rcvd: 717
Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state QUERY RESPONSE STATE Dec 12 09:53:19 unbound[27046:2] info: query response was REFERRAL Dec 12 09:53:19 unbound[27046:2] info: found in cache ns.cernet.net. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache e.dns.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache e.dns.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache d.dns.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache d.dns.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache c.dns.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache c.dns.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache b.dns.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache b.dns.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache a.dns.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache a.dns.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: DelegationPoint<cn.>: 6 names (1 missing), 11 addrs (0 result, 11 avail) parentNS Dec 12 09:53:19 unbound[27046:2] info: ns.cernet.net. A Dec 12 09:53:19 unbound[27046:2] info: e.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: d.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: c.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: b.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: a.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] debug: ip4 202.112.0.44 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:3::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.29.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:1000::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.28.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:2::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.27.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:1::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.26.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.25.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: cleared outbound list for next round Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state QUERY TARGETS STATE Dec 12 09:53:19 unbound[27046:2] info: processQueryTargets: mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Dec 12 09:53:19 unbound[27046:2] info: DelegationPoint<cn.>: 6 names (0 missing), 11 addrs (0 result, 11 avail) parentNS Dec 12 09:53:19 unbound[27046:2] info: ns.cernet.net. * A Dec 12 09:53:19 unbound[27046:2] info: e.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: d.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: c.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: b.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: a.dns.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] debug: ip4 202.112.0.44 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:3::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.29.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:1000::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.28.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:2::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.27.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7:1::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.26.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2001:dc7::1 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 203.119.25.1 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: attempt to get extra 2 targets Dec 12 09:53:19 unbound[27046:2] debug: rpz: iterator module callback: have_rpz=0 Dec 12 09:53:19 unbound[27046:2] debug: selrtt 376 Dec 12 09:53:19 unbound[27046:2] info: sending query: mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: sending to target: <cn.> 202.112.0.44#53 Dec 12 09:53:19 unbound[27046:2] debug: dnssec status: not expected Dec 12 09:53:19 unbound[27046:2] debug: mesh_run: iterator module exit state is module_wait_reply Dec 12 09:53:19 unbound[27046:2] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Dec 12 09:53:19 unbound[27046:2] info: 0RDd mod0 rep mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: cache memory msg=264216 rrset=267913 infra=15488 val=0 subnet=0 Dec 12 09:53:19 unbound[27046:2] debug: serviced send timer Dec 12 09:53:19 unbound[27046:2] debug: EDNS lookup known=0 vs=0 Dec 12 09:53:19 unbound[27046:2] debug: serviced query UDP timeout=376 msec Dec 12 09:53:19 unbound[27046:2] debug: inserted new pending reply id=e640 Dec 12 09:53:19 unbound[27046:2] debug: opened UDP if=0 port=46229 Dec 12 09:53:19 unbound[27046:2] debug: comm point start listening 33 (-1 msec) Dec 12 09:53:19 unbound[27046:2] debug: answer cb Dec 12 09:53:19 unbound[27046:2] debug: Incoming reply id = e640 Dec 12 09:53:19 unbound[27046:2] debug: Incoming reply addr = ip4 202.112.0.44 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: lookup size is 1 entries Dec 12 09:53:19 unbound[27046:2] debug: received udp reply. Dec 12 09:53:19 unbound[27046:2] debug: udp message[355:0] E6408010000100000005000B046D61696C0563696E646103636F6D02636E0000410001C01100020001000151800006036E7331C011C01100020001000151800006036E7332C011C01100020001000151800006036E7333C011C01100020001000151800006036E7334C011C01100020001000151800005026E73C011C065000100010001518000043CA88702C05300010001000151800004701B7620C04100010001000151800004DB8DDD6CC02F000100010001518000047C2A7E6CC07700010001000151800004DB8DA56CC065001C0001000151800010240E066000BA00010000000000000002C053001C0001000151800010240987310210004000000000 Dec 12 09:53:19 unbound[27046:2] debug: udp message[355:256] 00000002C041001C0001000151800010240E0604010500030000000000000002C02F001C0001000151800010240E0604020819050000000000000002C077001C0001000151800010240E008390060009000000000000000200002904D0000000000000 Dec 12 09:53:19 unbound[27046:2] debug: outnet handle udp reply Dec 12 09:53:19 unbound[27046:2] debug: serviced query: EDNS works for ip4 202.112.0.44 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: measured roundtrip at 3 msec Dec 12 09:53:19 unbound[27046:2] debug: svcd callbacks start Dec 12 09:53:19 unbound[27046:2] debug: worker svcd callback for qstate 0x16a3760 Dec 12 09:53:19 unbound[27046:2] debug: mesh_run: start Dec 12 09:53:19 unbound[27046:2] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply Dec 12 09:53:19 unbound[27046:2] info: iterator operate: query mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: process_response: new external response event Dec 12 09:53:19 unbound[27046:2] info: scrub for cn. NS IN Dec 12 09:53:19 unbound[27046:2] info: response for mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] info: reply from <cn.> 202.112.0.44#53 Dec 12 09:53:19 unbound[27046:2] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr ; QUERY: 1, ANSWER: 0, AUTHORITY: 5, ADDITIONAL: 10 ;; QUESTION SECTION: mail.cinda.com.cn. IN HTTPS
;; ANSWER SECTION:
;; AUTHORITY SECTION: cinda.com.cn. 86400 IN NS ns1.cinda.com.cn. cinda.com.cn. 86400 IN NS ns2.cinda.com.cn. cinda.com.cn. 86400 IN NS ns3.cinda.com.cn. cinda.com.cn. 86400 IN NS ns4.cinda.com.cn. cinda.com.cn. 86400 IN NS ns.cinda.com.cn.
;; ADDITIONAL SECTION: ns4.cinda.com.cn. 86400 IN A 60.168.135.2 ns3.cinda.com.cn. 86400 IN A 112.27.118.32 ns2.cinda.com.cn. 86400 IN A 219.141.221.108 ns1.cinda.com.cn. 86400 IN A 124.42.126.108 ns.cinda.com.cn. 86400 IN A 219.141.165.108 ns4.cinda.com.cn. 86400 IN AAAA 240e:660:ba:1::2 ns3.cinda.com.cn. 86400 IN AAAA 2409:8731:210:40::2 ns2.cinda.com.cn. 86400 IN AAAA 240e:604:105:3::2 ns1.cinda.com.cn. 86400 IN AAAA 240e:604:208:1905::2 ns.cinda.com.cn. 86400 IN AAAA 240e:83:9006:9::2 ;; MSG SIZE rcvd: 344
Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state QUERY RESPONSE STATE Dec 12 09:53:19 unbound[27046:2] info: query response was REFERRAL Dec 12 09:53:19 unbound[27046:2] info: found in cache ns.cinda.com.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns.cinda.com.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns4.cinda.com.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns4.cinda.com.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns3.cinda.com.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns3.cinda.com.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns2.cinda.com.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns2.cinda.com.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns1.cinda.com.cn. A IN Dec 12 09:53:19 unbound[27046:2] info: found in cache ns1.cinda.com.cn. AAAA IN Dec 12 09:53:19 unbound[27046:2] info: DelegationPoint<cinda.com.cn.>: 5 names (0 missing), 10 addrs (0 result, 10 avail) parentNS Dec 12 09:53:19 unbound[27046:2] info: ns.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns4.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns3.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns2.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns1.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:83:9006:9::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:604:208:1905::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:604:105:3::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2409:8731:210:40::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:660:ba:1::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 219.141.165.108 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 124.42.126.108 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 219.141.221.108 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 112.27.118.32 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 60.168.135.2 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: cleared outbound list for next round Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state QUERY TARGETS STATE Dec 12 09:53:19 unbound[27046:2] info: processQueryTargets: mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Dec 12 09:53:19 unbound[27046:2] info: DelegationPoint<cinda.com.cn.>: 5 names (0 missing), 10 addrs (0 result, 10 avail) parentNS Dec 12 09:53:19 unbound[27046:2] info: ns.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns4.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns3.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns2.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] info: ns1.cinda.com.cn. * A AAAA Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:83:9006:9::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:604:208:1905::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:604:105:3::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 2409:8731:210:40::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip6 240e:660:ba:1::2 port 53 (len 28) Dec 12 09:53:19 unbound[27046:2] debug: ip4 219.141.165.108 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 124.42.126.108 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 219.141.221.108 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 112.27.118.32 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: ip4 60.168.135.2 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: attempt to get extra 2 targets Dec 12 09:53:19 unbound[27046:2] debug: rpz: iterator module callback: have_rpz=0 Dec 12 09:53:19 unbound[27046:2] debug: selrtt 376 Dec 12 09:53:19 unbound[27046:2] info: sending query: mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: sending to target: <cinda.com.cn.> 112.27.118.32#53 Dec 12 09:53:19 unbound[27046:2] debug: dnssec status: not expected Dec 12 09:53:19 unbound[27046:2] debug: mesh_run: iterator module exit state is module_wait_reply Dec 12 09:53:19 unbound[27046:2] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Dec 12 09:53:19 unbound[27046:2] info: 0RDd mod0 rep mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: cache memory msg=264216 rrset=270884 infra=15788 val=0 subnet=0 Dec 12 09:53:19 unbound[27046:2] debug: svcd callbacks end Dec 12 09:53:19 unbound[27046:2] debug: serviced_delete Dec 12 09:53:19 unbound[27046:2] debug: close of port 46229 Dec 12 09:53:19 unbound[27046:2] debug: comm_point_close of 33: event_del Dec 12 09:53:19 unbound[27046:2] debug: close fd 33 Dec 12 09:53:19 unbound[27046:2] debug: serviced send timer Dec 12 09:53:19 unbound[27046:2] debug: EDNS lookup known=0 vs=0 Dec 12 09:53:19 unbound[27046:2] debug: serviced query UDP timeout=376 msec Dec 12 09:53:19 unbound[27046:2] debug: inserted new pending reply id=193b Dec 12 09:53:19 unbound[27046:2] debug: opened UDP if=0 port=32353 Dec 12 09:53:19 unbound[27046:2] debug: comm point start listening 33 (-1 msec) Dec 12 09:53:19 unbound[27046:2] debug: answer cb Dec 12 09:53:19 unbound[27046:2] debug: Incoming reply id = 193b Dec 12 09:53:19 unbound[27046:2] debug: Incoming reply addr = ip4 112.27.118.32 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: lookup size is 1 entries Dec 12 09:53:19 unbound[27046:2] debug: received udp reply. Dec 12 09:53:19 unbound[27046:2] debug: udp message[87:0] 193B84030001000000010001046D61696C0563696E646103636F6D02636E0000410001C0110006000100000001001DC01104726F6F74C01177925B9100000001000151800024EA00000000010000291000000000000000 Dec 12 09:53:19 unbound[27046:2] debug: outnet handle udp reply Dec 12 09:53:19 unbound[27046:2] debug: serviced query: EDNS works for ip4 112.27.118.32 port 53 (len 16) Dec 12 09:53:19 unbound[27046:2] debug: measured roundtrip at 34 msec Dec 12 09:53:19 unbound[27046:2] debug: svcd callbacks start Dec 12 09:53:19 unbound[27046:2] debug: worker svcd callback for qstate 0x16a3760 Dec 12 09:53:19 unbound[27046:2] debug: mesh_run: start Dec 12 09:53:19 unbound[27046:2] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply Dec 12 09:53:19 unbound[27046:2] info: iterator operate: query mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: process_response: new external response event Dec 12 09:53:19 unbound[27046:2] info: scrub for cinda.com.cn. NS IN Dec 12 09:53:19 unbound[27046:2] info: response for mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] info: reply from <cinda.com.cn.> 112.27.118.32#53 Dec 12 09:53:19 unbound[27046:2] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0 ;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 ;; QUESTION SECTION: mail.cinda.com.cn. IN HTTPS
;; ANSWER SECTION:
;; AUTHORITY SECTION: cinda.com.cn. 600 IN SOA cinda.com.cn. root.cinda.com.cn. 2006080401 1 86400 2419200 1
;; ADDITIONAL SECTION: ;; MSG SIZE rcvd: 76
Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state QUERY RESPONSE STATE Dec 12 09:53:19 unbound[27046:2] info: query response was NXDOMAIN ANSWER Dec 12 09:53:19 unbound[27046:2] debug: iter_handle processing q with state FINISHED RESPONSE STATE Dec 12 09:53:19 unbound[27046:2] info: finishing processing for mail.cinda.com.cn. HTTPS IN Dec 12 09:53:19 unbound[27046:2] debug: mesh_run: iterator module exit state is module_finished Dec 12 09:53:19 unbound[27046:2] debug: query took 0.038988 sec Dec 12 09:53:19 unbound[27046:2] reply: 114.254.1.104 mail.cinda.com.cn. HTTPS IN NXDOMAIN 0.038988 0 87 Dec 12 09:53:19 unbound[27046:2] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out Dec 12 09:53:19 unbound[27046:2] info: average recursion processing time 0.038988 sec Dec 12 09:53:19 unbound[27046:2] info: histogram of recursion processing times Dec 12 09:53:19 unbound[27046:2] info: [25%]=0 median[50%]=0 [75%]=0 Dec 12 09:53:19 unbound[27046:2] info: lower(secs) upper(secs) recursions Dec 12 09:53:19 unbound[27046:2] info: 0.032768 0.065536 1 Dec 12 09:53:19 unbound[27046:2] debug: cache memory msg=264475 rrset=271177 infra=16098 val=0 subnet=0 Dec 12 09:53:19 unbound[27046:2] debug: svcd callbacks end Dec 12 09:53:19 unbound[27046:2] debug: serviced_delete Dec 12 09:53:19 unbound[27046:2] debug: close of port 32353 Dec 12 09:53:19 unbound[27046:2] debug: comm_point_close of 33: event_del Dec 12 09:53:19 unbound[27046:2] debug: close fd 33 Dec 12 09:53:19 unbound[27046:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Dec 12 09:53:19 unbound[27046:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0 Dec 12 09:53:19 unbound[27046:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Dec 12 09:53:19 unbound[27046:0] debug: cache memory msg=264475 rrset=271177 infra=16098 val=0 subnet=0 Dec 12 09:53:19 unbound[27046:1] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Dec 12 09:53:19 unbound[27046:1] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0 Dec 12 09:53:19 unbound[27046:1] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Dec 12 09:53:19 unbound[27046:1] debug: cache memory msg=264475 rrset=271177 infra=16098 val=0 subnet=0 Dec 12 09:53:19 unbound[27046:3] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting Dec 12 09:53:19 unbound[27046:3] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0 Dec 12 09:53:19 unbound[27046:3] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Dec 12 09:53:19 unbound[27046:3] debug: cache memory msg=264475 rrset=271177 infra=16098 val=0 subnet=0 Dec 12 09:53:19 unbound[27046:2] info: server stats for thread 2: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting Dec 12 09:53:19 unbound[27046:2] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out Dec 12 09:53:19 unbound[27046:2] info: average recursion processing time 0.038988 sec Dec 12 09:53:19 unbound[27046:2] info: histogram of recursion processing times Dec 12 09:53:19 unbound[27046:2] info: [25%]=0 median[50%]=0 [75%]=0 Dec 12 09:53:19 unbound[27046:2] info: lower(secs) upper(secs) recursions Dec 12 09:53:19 unbound[27046:2] info: 0.032768 0.065536 1
I found the cause of the problem, cache-max-negative-ttl is affected by cache-min-ttl. When the ttl of the response SOA is less than cache-min-ttl, SOA uses cache-min-ttl. This logic is not reflected in the help documentation and conflicts with the explanation of cache-max-negative-ttl.
Strictly follow the effect you want to achieve in the rfc document and help document. The logic here should be like this:
#1027 is now merged, cache-min-negative-ttl can be used to affect the minimum TTL for negative answers.
Closing this.
