error: trust anchor presented twice running unbound-host -D

[cmonty14]

Hi,

to verify DNSSEC I run this command: `unbound-host -D -C /etc/unbound/unbound.conf -v -dd go.dnscheck.tools'

The output includes some errors:

❯ unbound-host -D -C /etc/unbound/unbound.conf -v -dd go.dnscheck.tools
[1707251423] libunbound[279036:0] debug: switching log to stderr
[1707251423] libunbound[279036:0] debug: module config: "validator iterator"
[1707251423] libunbound[279036:0] notice: init module 0: validator
[1707251423] libunbound[279036:0] info: adding trusted key . DNSKEY IN
[1707251423] libunbound[279036:0] error: trust anchor presented twice
[1707251423] libunbound[279036:0] error: could not parse auto-trust-anchor-file /var/lib/unbound/root.key line 2
[1707251423] libunbound[279036:0] error: error reading auto-trust-anchor-file: /var/lib/unbound/root.key
[1707251423] libunbound[279036:0] error: validator: error in trustanchors config
[1707251423] libunbound[279036:0] error: validator: could not apply configuration settings.
[1707251423] libunbound[279036:0] error: module init for module validator failed
resolve error: initialization failure

auto-trust-anchor-file exists with correct permission:

❯ ll /var/lib/unbound/root.key 
-rw-r--r-- 1 root root 758 Feb  6 21:22 /var/lib/unbound/root.key
  ~
❯ file /var/lib/unbound/root.key 
/var/lib/unbound/root.key: ASCII text, with very long lines (491)
  ~ 

Please advise how to fix this issue.

[wcawijngaards]

This happened because the trust anchor is both in the config file that is passed with the -C option, and is also added by the -D option. The -C power user option can be used for many configuration options, and debugging. In this case, if you leave out the -D option, it would work and not have the double trust anchor. Without the -C option likely also works, but then the potential other options in that config file are also not present.

[cmonty14]

Thanks. This error message is gone using command unbound-host -C /etc/unbound/unbound.conf -v -dd go.dnscheck.tools, however the command returns error:

❯ unbound-host -C /etc/unbound/unbound.conf -v -dd go.dnscheck.tools
[1707422628] libunbound[993812:0] debug: switching log to stderr
[1707422628] libunbound[993812:0] debug: module config: "validator iterator"
[1707422628] libunbound[993812:0] notice: init module 0: validator
[1707422628] libunbound[993812:0] notice: init module 1: iterator
[1707422628] libunbound[993812:0] debug: target fetch policy for level 0 is 0
[1707422628] libunbound[993812:0] debug: target fetch policy for level 1 is 0
[1707422628] libunbound[993812:0] debug: target fetch policy for level 2 is 0
[1707422628] libunbound[993812:0] debug: target fetch policy for level 3 is 0
[1707422628] libunbound[993812:0] debug: target fetch policy for level 4 is 0
[1707422628] libunbound[993812:0] debug: Reading root hints from /etc/unbound/root.hints
[1707422628] libunbound[993812:0] info: DelegationPoint<.>: 13 names (0 missing), 26 addrs (0 result, 26 avail) parentNS
resolve error: initialization failure

[wcawijngaards]

If you add more -dd flags, say -dddd it increases the verbosity to a higher level, 4 is a good value here. It could also be specified in the unbound.conf. Then the output likely contains more information about what went wrong and caused the initialisation to fail. I presume it is likely due to the config file that is passed, that seems to be from a file location for the full server, instead of a selection of options for the unbound-host command. But the higher detail output likely contains more information.

[cmonty14]

Running unbound-host with more flags -dddd, but I cannot identify the cause for this issue:

❯ unbound-host -C /etc/unbound/unbound.conf -v -dddd go.dnscheck.tools    
[1707500448] libunbound[1251932:0] debug: switching log to stderr                                                             
[1707500448] libunbound[1251932:0] debug: module config: "validator iterator"                                                 
[1707500448] libunbound[1251932:0] notice: init module 0: validator                                                           
[1707500448] libunbound[1251932:0] debug: reading autotrust anchor file /var/lib/unbound/root.key                             
[1707500448] libunbound[1251932:0] info: trust point . : 1                                                                    
[1707500448] libunbound[1251932:0] info: assembled 0 DS and 1 DNSKEYs                                                         
[1707500448] libunbound[1251932:0] info: DNSKEY:: .     86400   IN      DNSKEY  257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMg
JzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBx
WezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+c
n8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b}                                  

[1707500448] libunbound[1251932:0] info: file /var/lib/unbound/root.key                                                       
[1707500448] libunbound[1251932:0] info: last_queried: 1707459243 Fri Feb  9 07:14:03 2024                                    
[1707500448] libunbound[1251932:0] info: last_success: 1707459243 Fri Feb  9 07:14:03 2024                                    
[1707500448] libunbound[1251932:0] info: next_probe_time: 1707501324 Fri Feb  9 18:55:24 2024                                 
[1707500448] libunbound[1251932:0] info: query_interval: 43200                                                                
[1707500448] libunbound[1251932:0] info: retry_time: 8640
[1707500448] libunbound[1251932:0] info: query_failed: 0
[1707500448] libunbound[1251932:0] info: [  VALID  ] .  86400   IN      DNSKEY  257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMg
JzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBx
WezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+c
n8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b} ;;state:2 ;;pending_count:0 last:
Fri Jan 19 23:38:57 2024
[1707500448] libunbound[1251932:0] debug: validator nsec3cfg keysz 1024 mxiter 150
[1707500448] libunbound[1251932:0] debug: validator nsec3cfg keysz 2048 mxiter 500
[1707500448] libunbound[1251932:0] debug: validator nsec3cfg keysz 4096 mxiter 2500
[1707500448] libunbound[1251932:0] notice: init module 1: iterator
[1707500448] libunbound[1251932:0] debug: target fetch policy for level 0 is 0
[1707500448] libunbound[1251932:0] debug: target fetch policy for level 1 is 0
[1707500448] libunbound[1251932:0] debug: target fetch policy for level 2 is 0
[1707500448] libunbound[1251932:0] debug: target fetch policy for level 3 is 0                                       [15/1975]
[1707500448] libunbound[1251932:0] debug: target fetch policy for level 4 is 0
[1707500448] libunbound[1251932:0] debug: Reading root hints from /etc/unbound/root.hints
[1707500448] libunbound[1251932:0] info: DelegationPoint<.>: 13 names (0 missing), 26 addrs (0 result, 26 avail) parentNS
[1707500448] libunbound[1251932:0] info:   M.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   L.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   K.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   J.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   I.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   H.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   G.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   F.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   E.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   D.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   C.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   B.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] info:   A.ROOT-SERVERS.NET. * A AAAA
[1707500448] libunbound[1251932:0] debug:    ip6 2001:dc3::35 port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 202.12.27.33 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:500:9f::42 port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 199.7.83.42 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:7fd::1 port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 193.0.14.129 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:503:c27::2:30 port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 192.58.128.30 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:7fe::53 port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 192.36.148.17 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:500:1::53 port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 198.97.190.53 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:500:12::d0d port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 192.112.36.4 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:500:2f::f port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 192.5.5.241 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:500:a8::e port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 192.203.230.10 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 199.7.91.13 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:500:2::c port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 192.33.4.12 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2801:1b8:10::b port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 170.247.170.2 port 53 (len 16)
[1707500448] libunbound[1251932:0] debug:    ip6 2001:503:ba3e::2:30 port 53 (len 28)
[1707500448] libunbound[1251932:0] debug:    ip4 198.41.0.4 port 53 (len 16)
resolve error: initialization failure

[wcawijngaards]

Unbound I think should be logging an error for the initialization failure, it is likely connected to the contents of the configuration file that is passed. Not that often is a config file passed like that.

The particular error, 'initialization failure', is returned in one of the following cases: libevent cannot be setup, but this it not actually in use for the command given, or: the module stack cannot start, the local zones cannot get configured, the auth zones cannot get configured, the edns strings option cannot get configured. What is the configuration for these items? I would think unbound would print out the error as the problem why that configuration failed to be applied.

The printout at high verbosity, thanks for that, it includes the module config: .. printout and then the initialization of the validator and iterator modules. That looks fine. So it is not the module stack setup. Next are the localzones and auth zones and ednsstrings option, in the code, so one of those perhaps fails but does not print out the error. The config for these items it perhaps the cause for it, like comment and uncomment to test or if that is not it, it is maybe something else.

[cmonty14]

Could you please point out which information is required to continue analysis?

[wcawijngaards]

Could you try to comment out items in the config, to see which one causes the failure to start? So that, with a small config, the failure can be reproduced, and then say what config causes the problem?

[cmonty14]

After completing this try & error exercise I have identified the root cause: tls-cert-bundle: /etc/ssl/certs/ca-certificates.crt

This file exists:

❯ file /etc/ssl/certs/ca-certificates.crt
/etc/ssl/certs/ca-certificates.crt: PEM certificate

[wcawijngaards]

The only code path that I see that does not print an error there is if unbound is compiled without openssl. But I think this is very unlikely, I guess you have openssl (unbound -V) compiled in. But perhaps this is a code repo checkout, and make clean; make can resolve a dependency problem? Does that fix it perhaps? For it prints for this option when the file does not exist and so on errors like: "error: error in SSL_CTX verify crypto ..". But the file exists and looks okay, so not sure what is going on.

[cmonty14]

I would conclude that unbound is compiled /w openssl:

❯ unbound -V
Version 1.13.1

Configure line: --build=x86_64-linux-gnu --prefix=/usr --includedir=${prefix}/include --mandir=${prefix}/share/man --infodir=${prefix}/share/info --sysconfdir=/etc --localstatedir=/var --disable-option-checking --disable-silent-rules --libdir=${prefix}/lib/x86_64-linux-gnu --libexecdir=${prefix}/lib/x86_64-linux-gnu --disable-maintainer-mode --disable-dependency-tracking --disable-rpath --with-pidfile=/run/unbound.pid --with-rootkey-file=/var/lib/unbound/root.key --with-libevent --with-libnghttp2 --with-pythonmodule --enable-subnet --enable-dnstap --enable-systemd --with-chroot-dir= --with-dnstap-socket-path=/run/dnstap.sock --libdir=/usr/lib
Linked libs: libevent 2.1.12-stable (it uses epoll), OpenSSL 3.0.2 15 Mar 2022
Linked modules: dns64 python subnetcache 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

After renaming /etc/ssl/certs/ca-certificates.crt the error remains the same, means there's no other error saying the file is missing.

❯ sudo mv /etc/ssl/certs/ca-certificates.crt /etc/ssl/certs/ca-certificates.crt.old
❯ sudo unbound-host -C /etc/unbound/unbound.conf -v -d go.dnscheck.tools
[1707750340] libunbound[2290284:0] notice: init module 0: validator
[1707750340] libunbound[2290284:0] notice: init module 1: iterator
resolve error: initialization failure

[wcawijngaards]

For me, this is with the code repo version, it prints errors when the file does not exist. So I think something is wrong, but perhaps a version upgrade to the latest or code repo version could improve matters? But I am not sure, I could not from version differences see what would cause the error to be not printed, but there are some changes in the error printout and handling for the option in question. It would be nice if you could try with the latest version or the code repo version; otherwise it if then persists it is possible to try versions with extra debug around the routines that fail, because then it happens with the latest code and not for me, for a nonexistent file.

[cmonty14]

Understand...

Question: What if I disable option tls-cert-bundle: /etc/ssl/certs/ca-certificates.crt?

My understanding is that it's required for DoT. So my conclusion is: if DoT is not required I can disable this option.

[wcawijngaards]

Yes certainly, the option is not needed by the unbound-host lookups, that are not using DoT. So disabling it works around the issue.