IPv6 fallback issues when IPv6 is not properly enabled/configured

[mzealey]

If I have a server which has an IPv6 interface but it is not connected to the internet (eg a default docker container or most linux servers these days), the first time I run a query for 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net it returns a SERVFAIL. If I set prefer-ip4: yes it fails similarly. The only way to make this resolve correctly the first time is to do-ip6: no.

From what I can see the difference is if there is ipv6 enabled we get this log line repeated a few times (even if prefer-ip4: yes for some reason):

[1613241220] unbound[1:0] error: udp connect failed: Cannot assign requested address for 2a00:ab00:603:96::32 port 53
[1613241220] unbound[1:0] info: error sending query to auth server 2a00:ab00:603:96::32 port 53

It also tries to do IPv6 queries even when there is only an ipv4 address listed in outgoing-interface.

Unbound 1.13.0

[wcawijngaards]

This should be harmless, in that it should retry to other servers since IPv6 does not work. The UDP connect error printout should likely be squelched, eg. not shown in the logs prominently, and then it just tries IPv6 and moves on when that does not work.

So the resolution failure should not really be fixed by disabling IPv6, but you report it does, what goes wrong when IPv6 is enabled? It should switch over to the IPv4 address and then find the name.

If it tries to perform IPv6 queries when there is only an IPv4 address listed in the outgoing interface, I am thinking that perhaps you are editing the wrong config file? Some distributions have several, or the file listed on a webpage is not the location used. Because it should not be able to connect to IPv6 from an IPv4 socket.

[mzealey]

I think it may be something dnssec related because when running very verbose logging it looks like it gets some dnssec failure on the ipv4 and then retries on ipv6 but I'm not totally sure. It definitely returns servfail though as the logs (when at lower verbosity - I missed it first time) show:

[1613380210] unbound[1:2] info: 172.17.0.1 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613380211] unbound[1:2] error: SERVFAIL <04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN>: exceeded the maximum number of sends
[1613380211] unbound[1:2] info: 172.17.0.1 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN SERVFAIL 1.553623 0 95

but when i query a second time it works correctly:

[1613380365] unbound[1:6] info: 172.17.0.1 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613380365] unbound[1:6] info: 172.17.0.1 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN NOERROR 0.037100 0 111

I'm using only a single config file (this is in a docker container so specifying it clearly) and have outgoing-interface: 172.17.0.2. Actually it seems like I probably don't even have IPv6 enabled on the interface or within unbound in general:

ip addr
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
1096: eth0@if1097: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default 
    link/ether 02:42:ac:11:00:02 brd ff:ff:ff:ff:ff:ff link-netnsid 0
    inet 172.17.0.2/16 brd 172.17.255.255 scope global eth0
       valid_lft forever preferred_lft forever

root@23d0f04087c3:/opt/unbound# ss -nlp
Netid             State               Recv-Q              Send-Q                           Local Address:Port                                Peer Address:Port             
nl                UNCONN              0                   0                                            0:0                                               *                 
nl                UNCONN              0                   0                                            0:2301                                            *                 
nl                UNCONN              768                 0                                            4:0                                               *                 
nl                UNCONN              4352                0                                            4:21                                              *                 
nl                UNCONN              0                   0                                            6:0                                               *                 
nl                UNCONN              0                   0                                            9:0                                               *                 
nl                UNCONN              0                   0                                           10:0                                               *                 
nl                UNCONN              0                   0                                           12:0                                               *                 
nl                UNCONN              0                   0                                           15:0                                               *                 
nl                UNCONN              0                   0                                           16:0                                               *                 
u_str             LISTEN              0                   256                              /control.sock 129602260                                      * 0                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
udp               UNCONN              0                   0                                      0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                
tcp               LISTEN              0                   256                                    0.0.0.0:53                                       0.0.0.0:*                

[wcawijngaards]

The maximum number of sends is there to stop unbound from falling for several CVEs that are about lots and lots of nameservers that need to be probed before a working one is found. This must be the case for this name. Unbound caches the failed lookups from the first time, so when you try it the second time it has enough send count available to find the working option and then returns with the answer.

This also explains why the IPv6 setting matters, if you turn it off, unbound does not attempt over IPv6 and thus reaches that hard to find nameserver within a lower send count number.

The domain is not really resolvable. It has lots and lots of failing servers and unbound has a hard time finding the working server. I cannot really make unbound try that hard for all cases, because of infinite send loops that would result in. So, what you could do is something like. List a number of the failed servers as do-not-query-address , eg. do not send queries there, that should make unbound succeed faster. Or make a stub-zone entry for the domain, where you list the working servers, by name or by ip-address. Or make a local-data and local-zone with the content you with to see for the name.

[mzealey]

But looking at the nameserver setup and the unbound logs I find it hard to believe that it is infra-related for this domain:

[1613242273] unbound[1:5] info: iterator operate: query 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613242273] unbound[1:5] info: response for 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613242273] unbound[1:5] info: reply from <eu.dotnxdomain.net.> 139.162.149.100#53
[1613242273] unbound[1:5] info: query response was DNSSEC LAME
[1613242273] unbound[1:5] info: processQueryTargets: 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613242273] unbound[1:5] info: sending query: 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613242273] unbound[1:5] debug: sending to target: <eu.dotnxdomain.net.> 2a01:7e01::f03c:91ff:fe12:6bfe#53
[1613242273] unbound[1:5] error: udp connect failed: Cannot assign requested address for 2a01:7e01::f03c:91ff:fe12:6bfe port 53
[1613242273] unbound[1:5] info: error sending query to auth server 2a01:7e01::f03c:91ff:fe12:6bfe port 53
[1613242273] unbound[1:5] info: processQueryTargets: 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613242273] unbound[1:5] info: sending query: 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net. A IN
[1613242273] unbound[1:5] debug: sending to target: <eu.dotnxdomain.net.> 2a01:7e01::f03c:91ff:fe12:6bfe#53
[1613242273] unbound[1:5] error: udp connect failed: Cannot assign requested address for 2a01:7e01::f03c:91ff:fe12:6bfe port 53
[1613242273] unbound[1:5] info: error sending query to auth server 2a01:7e01::f03c:91ff:fe12:6bfe port 53
... lots of repeats always about the same address ...

$ dig +short nseu.dotnxdomain.net AAAA
2a01:7e01::f03c:91ff:fe12:6bfe
$ dig +short nseu.dotnxdomain.net A
139.162.149.100

As I say, the second time through it always works.

The lookup after the first time is:

$ docker exec -it unbound-test unbound-control -c /etc/unbound.conf lookup 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net
The following name servers are used for lookup of 04u-ua5db72ef-c12-a2093-s1613236523-i52dab726-0.eu.dotnxdomain.net.
;rrset 3597 1 0 2 0
eu.dotnxdomain.net.     3597    IN      NS      nseu.dotnxdomain.net.
;rrset 3597 2 1 2 0
eu.dotnxdomain.net.     3597    IN      DS      13681 13 1 2070A152E70A95F32435DCA220C5B93FF2AD0172
eu.dotnxdomain.net.     3597    IN      DS      13681 13 2 2A33187027987E05B0975A40108423D4CEE0EB08749243BE502C2F6BEEDB616D
eu.dotnxdomain.net.     3597    IN      RRSIG   DS 5 3 3600 20210724235900 20210120150324 15135 dotnxdomain.net. 29jusVdRX5+xPv155BiUGa3oQRmDeCnLN6g2/10yRB29VDtIndBywHOnEZ0rfYBi22H2r5hKaxN6Hy5T5c2/jWh/Xo3uO66SgHvPc9GU3NJuCLGJG3VCNZW7338BA/3WQw2DBcX86+NRsRYIfZVjmvejtsxyXydpOFnR6x/CvTY= ;{id = 15135}
;rrset 3597 1 1 1 0
nseu.dotnxdomain.net.   3597    IN      A       139.162.149.100
nseu.dotnxdomain.net.   3597    IN      RRSIG   A 5 3 3600 20210724235900 20210120150324 15135 dotnxdomain.net. bcA9KodubzOex0Y5QO7cAktU9UwIsuqAdZupuldkIYg1n/nloNUvDJZw8q/60gsXpYgnEc6PcMsN/O+4HuNr/+XZGOyDDSy+G6fKyAJY3vL3wH/Z37an0optwvoYAY8nRaAFlFFGQEKyMrQVDC/+jwkTiYRGxEqsECaLextzMTU= ;{id = 15135}
;rrset 3597 1 1 1 0
nseu.dotnxdomain.net.   3597    IN      AAAA    2a01:7e01::f03c:91ff:fe12:6bfe
nseu.dotnxdomain.net.   3597    IN      RRSIG   AAAA 5 3 3600 20210724235900 20210120150324 15135 dotnxdomain.net. FprE/2GxVnrOJHySchsEW9rlzU4rWM2w9kr8MFkBJZbw41tI6ehXgmmYsf2e7fWGPuH/b6L6rR/hzthxpZClJ6cDC4Ybyk/NJ1PTAMzkpRTZXlheOgAauXDQWuJwkyzWJU+cb21L6sT0wBneBoIi9epKSkW1DzxYIdjyftYRTs4= ;{id = 15135}
Delegation with 1 names, of which 0 can be examined to query further addresses.
It provides 2 IP addresses.
2a01:7e01::f03c:91ff:fe12:6bfe  rto 376 msec, ttl 897, ping 0 var 94 rtt 376, tA 0, tAAAA 0, tother 0, EDNS 0 assumed.
139.162.149.100         rto 49 msec, ttl 897, ping 21 var 7 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.

[wcawijngaards]

Yes that does not look like loads of nameservers. The log message that is quoted, DNSSEC lame, explains that it may be less servers but retries caused by DNSSEC lameness are causing extra send attempts.

The DNSSEC lame is what unbound logs when it expects DNSSEC but does not receive any. It expects DNSSEC because there is a DS record in the parent zone. But then the destination child zone has no DNSSEC. And that is going to fail validation, so it then tries again, and again, to find DNSSEC information. The zone should sign, load the signed zonefile into the authority servers, or remove the DS from the parent.

[mzealey]

The bit I'm not understanding is why the first and second queries would return different results - if the dnssec is badly broken then it should return servfail all the time, if not then the first one should also return successfully. The above results hold whether or not val-permissive is set

[wcawijngaards]

Likely the issue is then searching for a domain. When everything fails, and takes a long time, unbound tries other fallback options to resolve. Likely these happen the second time (or the first when you disable ipv6 and there is less to search). These are like nameserver that are only registered at the parent, but not registered at the child. Or glue that is registered at the parent but not available from the child. In some cases, glue from the child that is different from the parent. One of these is a working server. But the lack of DNSSEC makes me think that it may not be owned by the same owner, eg, for domain sale if someone resigned with a different key, then everything broken and failing lookups, but the (misconfigured) not removed server from a previous zone owner could then be found and used, and that could be happening. Or the same owner with misconfigured servers and failing servers.

[mzealey]

I'm thinking there may be similar with info.dot.gov mx as well:

[1613384995] unbound[1:6] error: SERVFAIL <info.dot.gov. MX IN>: exceeded the maximum number of sends
[1613384995] unbound[1:6] info: 172.17.0.1 info.dot.gov. MX IN SERVFAIL 5.986347 0 41

the first time but next times are NOERROR

$ docker exec -it unbound-test unbound-control -c /etc/unbound.conf lookup info.dot.gov
The following name servers are used for lookup of info.dot.gov.
;rrset 86362 3 0 2 0
dot.gov.        86362   IN      NS      edns1.dot.gov.
dot.gov.        86362   IN      NS      edns3.dot.gov.
dot.gov.        86362   IN      NS      edns2.dot.gov.
;rrset 3562 2 1 11 5
dot.gov.        3562    IN      DS      49516 8 2 9AA47F5C66254BA614D87F1CFDF4AA55E527B9D18FA38BE42270C103FF496DD5
dot.gov.        3562    IN      DS      49516 8 1 81475A8639B7A5FF5BE9285DD4CD0A5948D8F289
dot.gov.        3562    IN      RRSIG   DS 8 2 3600 20210222091009 20210215091009 27306 gov. C7pAO5xCEoj0Ol7g6/nN2hFFnRVOW8k+Rm7zqh8OOS4sMCx9aebhJwBAyqrsYo1Ud2iXViol9zCuAQoQhdoMFVUT944icHwkPlbjev4MlB3Gy3nCjSbhUuqO/uHPakHdYL/Io0KKTPAu8fbTgOisilbBkz8l9M7zYyRIRMADci0WLEUAoiGY9XiCsVDs5kpZ3+BPphyOt8ng2GAYNxCSaA== ;{id = 27306}
;rrset 562 1 1 8 0
edns2.dot.gov.  562     IN      A       204.68.194.200
edns2.dot.gov.  562     IN      RRSIG   A 8 3 600 20210219053424 20210215045702 14553 dot.gov. ZaiB2YjRbZsqGShge37IRICBxKBPCALmEx5KO7U8wmqWSBRKNVwWir8puLJySrFwzUx/kDFLyol4D8k4HOH/RYwkyqhiAoHzrR0iU0z+DcrV3zKwKGLAwsa9ibDYK46FwXh3CDj+y0t6+UPdUFtuTCVyQscJ9HNfA7xO41NzaYk= ;{id = 14553}
;rrset 563 1 1 8 0
edns2.dot.gov.  563     IN      AAAA    2001:19e8:d::200
edns2.dot.gov.  563     IN      RRSIG   AAAA 8 3 600 20210219042452 20210215040437 14553 dot.gov. KqU3///BYoGZPurjv2FS7or/5fw/WArDEECrzrtYG7nHdXoyWwDO5e6JrJiSECd3x44dVPv3M8PCGtqBC7HL67lsjgsm6E1KVv9NMpcPaFmZrg5LK3MFoecAACtSBA0zAQ+AOWp7nf8bea4eSLUXkpvHSFzIfImjXSviXBPZerw= ;{id = 14553}
;rrset 562 1 1 8 0
edns3.dot.gov.  562     IN      A       204.152.44.100
edns3.dot.gov.  562     IN      RRSIG   A 8 3 600 20210219034720 20210215034204 14553 dot.gov. HtGuTIF9YIJKTOXKtgom0U+GTGlD4Ne4KCFkcLtWcW7MVJZ+xNEDKboKn4ijBqX4WCnnBPrRcURdt145d25+OhlUD75Jml/RXvLkIFOUQuMMAFUngwi3aJgPLQU44tNlMs5jLzzT/tJTBqSMsqWnVLgBoHolBcnrQSZkuHiZoHU= ;{id = 14553}
;rrset 1163 1 1 8 0
edns3.dot.gov.  1163    IN      AAAA    2001:19e8:d4::100
edns3.dot.gov.  1163    IN      RRSIG   AAAA 8 3 1200 20210219054038 20210215044205 14553 dot.gov. oSrE3wCaV88WwzPrck1ehvThzLm8xzDogg68hy3q2lOLUxa7QIV4FBC1ilXdn/A1rMC88fKA4BPkjK9XSf93wRBK49JKYaYPInx1MXQLC0bU1b3N84IGNsb1WSBfaomVSWqQrelAz7K8zXew+cu19ceEB8+AhCqTESDGblvek8o= ;{id = 14553}
;rrset 562 1 1 8 0
edns1.dot.gov.  562     IN      A       204.68.194.100
edns1.dot.gov.  562     IN      RRSIG   A 8 3 600 20210219030502 20210215021453 14553 dot.gov. PERKxvTiyUO8YmlvXDOcZnhehdxwRT9V8rFT2ODlgZe4Jd2CTs0ghtm7xKSyPdPePs2fJudikU3IgC4olub4iBhq8v3UXBD2AWTG64VYaTsKB/arKul0EtgoVx6VRpXQq+Eo5YaXXhpRJJHasUcRQ4Np+1tOgVOvOogcIBAqvtI= ;{id = 14553}
;rrset 563 1 1 8 0
edns1.dot.gov.  563     IN      AAAA    2001:19e8:d::100
edns1.dot.gov.  563     IN      RRSIG   AAAA 8 3 600 20210219003524 20210214235529 14553 dot.gov. iazt/LHatDw4AiSPb/JbxnPTRTjX/nJ8X4FXkRd6zq1yzvvIWnMBOCAiBi46pk46hCLaq0r/F9UV2hUg8ocTQT1DIBDkltVbFrRSCdY0Kd7z4z6bSv/OCDCftiKwivwOBtfr4PyxLm00MA8/Bt17fntnHPdomRK+WBlQEUH9v7E= ;{id = 14553}
Delegation with 3 names, of which 0 can be examined to query further addresses.
It provides 6 IP addresses.
2001:19e8:d::100        rto 376 msec, ttl 863, ping 0 var 94 rtt 376, tA 0, tAAAA 0, tother 0, EDNS 0 assumed.
204.68.194.100          rto 451 msec, ttl 862, ping 135 var 79 rtt 451, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:19e8:d4::100       rto 376 msec, ttl 863, ping 0 var 94 rtt 376, tA 0, tAAAA 0, tother 0, EDNS 0 assumed.
204.152.44.100          rto 375 msec, ttl 862, ping 167 var 52 rtt 375, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:19e8:d::200        rto 376 msec, ttl 863, ping 0 var 94 rtt 376, tA 0, tAAAA 0, tother 0, EDNS 0 assumed.
204.68.194.200          rto 343 msec, ttl 862, ping 135 var 52 rtt 343, tA 0, tAAAA 0, tother 0, EDNS 0 probed.

[wcawijngaards]

The servers for dot.gov and info.dot.gov are co-hosted, they host both zones. But dot.gov is signed and info.dot.gov is not. Unbound expects DNSSEC because dot.gov is signed, and it saw a DS record, and the reply is not signed because of the also-hosted more specific zone that is not signed is used for the answer. That makes unbound think that DNSSEC is missing. It starts searching and fails. But then on the second attempt, unbound has cached more information, it attempts a 'just use the information anyway' that succeeds because it probes the unsigned domain proof. That is then cached for a longer time in the key cache and that should keep it working for a while.

domain-insecure: "info.dot.gov" makes this problem go away, it should then reply much faster on the first attempt.

[mzealey]

(as a side-note, according to the docs, I would have expected the val-permissive: yes flag to prevent dnssec issues such as this from affecting responses)

[mzealey]

Setting domain-insecure: "info.dot.gov" does not solve the issue. However setting domain-insecure: "dot.gov" does. Alternatively, setting do-ip6: no solves the problem here...

[mzealey]

So if I run this on a server with ipv6 enabled it displays the same issue when outgoing-interface is only set to the ipv4 address. ie it's still trying to do some ipv6 resolution & repeatedly failing because it doesn't have the interface to do this.

If I add the ipv6 address to outgoing-interface then it performs the lookup and returns correctly first time for both of the domains mentioned in this ticket, exactly the same as if we have do-ip6: no.

So it does look to me that the base issue here is to do with ipv6 being tried in unbound even when it is not available.

[wcawijngaards]

That is not something I can fix, the ipv6 is not available. If you know, you can set do-ip6 to the right value. Otherwise, unbound really has no way to detect if ipv6 is available, other than to try it. Some routes may be up, and some may not, so cannot detect from the previous attempt to the next. Apart from guessing, perhaps, but that seems failure prone. So it just tries them.

[mzealey]

But if there is no ipv6 outbound-interface specified it should probably behave the same as if do-ip6: no is set?

[wcawijngaards]

That is a point, right now it does not. It attempts to look up AAAA adresses and so on, because of the do-ip6 setting, and then when it attempts to make the connection there happens to not be one.