Bug 1126 - libunbound error: module init for module validator failed
libunbound error: module init for module validator failed
Status: REOPENED
Product: unbound
Classification: Unclassified
Component: server
1.5.10
Other All
: P5 normal
Assigned To: unbound team
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2016-10-07 16:37 CEST by ruga
Modified: 2016-10-18 14:56 CEST (History)
3 users (show)

See Also:


Attachments
debug (9.25 KB, text/plain)
2016-10-18 12:00 CEST, ruga
Details

Note You need to log in before you can comment on or make changes to this bug.
Description ruga 2016-10-07 16:37:13 CEST
Hello, 

For reasons that are sufficient to us, the local unbound has been configured as follows. 
All variables below are shorthands for their values in the configuration files. 

run="${prefix}/var/run"; # Note: $run != /var/run

config_options="--prefix=${prefix} \
   --with-run-dir=${prefix} \
   --with-chroot-dir=${prefix} \
   --bindir=${prefix}/bin \
   --sbindir=${prefix}/sbin \
   --libexecdir=${prefix}/libexec \
   --includedir=${prefix}/include \
   --libdir=${prefix}/lib \
   --sysconfdir=${prefix}/etc \
   --with-conf-file=${prefix}/etc/unbound.conf \
   --localstatedir=${prefix}/var \
   --with-pidfile=${run}/unbound.pid \
   --with-rootkey-file=${run}/root.key \
   --with-rootcert-file=${run}/icannbundle.pem \
   --with-share-dir=${share} \
   --datarootdir=${share} \
   --datadir=${share} \
   --mandir=${man} \
   --docdir=${doc} \
   --with-ssl=${share}/libressl \
   --disable-gost \
   --with-libexpat=${share}/expat \
   --without-pyunbound \
   --without-pythonmodule \
   --enable-static=yes \
   --enable-shared=yes \
   --disable-largefile \
   --enable-checking \
   --with-username=${username}"; 

The runtime configuration adds paths to the above:

chroot: "$prefix"
directory: "$prefix"
pidfile: "${run}/unbound.pid"
root-hints: "$prefix/etc/named.root"
auto-trust-anchor-file: "$run/root.key"
dlv-anchor-file: "$prefix/etc/dlv.isc.org.key"
include: "$prefix/etc/blacklist.unbound"
server-key-file: "$prefix/etc/unbound_server.key"
...
include: "$prefix/etc/unbound_stub_zones.conf"

The resulting unbound behaves as follows:

> unbound-host -rv -C $prefix/etc/unbound.conf nlnetlabs.nl
Oct 07 16:33:26 libunbound[67198:0] notice: init module 0: validator
Oct 07 16:33:26 libunbound[67198:0] error: unable to open /var/run/root.key for reading: No such file or directory
Oct 07 16:33:26 libunbound[67198:0] error: error reading auto-trust-anchor-file: $run/root.key
Oct 07 16:33:26 libunbound[67198:0] error: validator: error in trustanchors config
Oct 07 16:33:26 libunbound[67198:0] error: validator: could not apply configuration settings.
Oct 07 16:33:26 libunbound[67198:0] error: module init for module validator failed
resolve error: initialization failure

> ls -l $prefix/etc/dlv.isc.org.key
-rw-r--r--  1 root  wheel  386 Sep 29 19:47 $prefix/etc/dlv.isc.org.key

However, the following succeeds: 

> unbound-host -rvD nlnetlabs.nl 
nlnetlabs.nl has address 185.49.140.10 (secure)
nlnetlabs.nl has IPv6 address 2a04:b900::1:0:0:10 (secure)
nlnetlabs.nl mail is handled by 50 open.nlnetlabs.nl. (secure)
nlnetlabs.nl mail is handled by 90 mcvax.nlnet.nl. (secure)

> man unbound-host  
...
-D   Enables DNSSEC validation. Reads the root anchor from the default configured root anchor
     at the default location, $run/root.key.
...


In summary, why "libunbound -C" fails?
Comment 1 ruga 2016-10-07 16:40:20 CEST
>ls -l $run/root.key                                                                                                                           
-rw-r--r--  1 $owner  $group  759 Oct  7 16:33 $run/root.key
Comment 2 ruga 2016-10-07 18:42:45 CEST
> sudo ln -s $run/root.key  /var/run/
> sudo ln -s $prefix/etc/named.root /etc/ 
> unbound-host -rv -C $prefix/etc/unbound.conf unbound.net
Oct 07 18:36:56 libunbound[97733:0] notice: init module 0: validator
Oct 07 18:36:56 libunbound[97733:0] notice: init module 1: iterator
Host unbound.net not found: 2(SERVFAIL). (insecure)
Host unbound.net not found: 2(SERVFAIL). (insecure)
Host unbound.net not found: 2(SERVFAIL). (insecure)
Comment 3 Ralph Dolmans 2016-10-10 15:42:58 CEST
Hi,

Thanks for reporting.

The problem is the explicitly set chroot configuration option. The chroot directory for libunbound is by default set to NULL, which differs from the default used by the unbound daemon.

So, by setting the chroot dir, that part is stripped from the file locations. However, libunbound does never do a chroot(2), and thus the files can not be found. Without -C libunbound does not set a chroot dir, and can find the files.

I see that the difference in default values in not very well documented, I will make some updates there.

-- Ralph
Comment 4 ruga 2016-10-11 15:54:33 CEST
This problem impacts opendkim when using ResolverConfiguration:

https://sourceforge.net/p/opendkim/support-requests/35/

# ResolverConfiguration (string)
#    Provides the given string as configuration information to the underlying
#    resolver. For the standard UNIX resolver, this is unused; for Unbound,
#    the string contains a filename that is considered to be a configuration
#    file. There is no default.
Comment 5 Wouter Wijngaards 2016-10-17 10:45:37 CEST
Hi Ruga,

So, the libunbound needs a different config file, one that does not have this statement:

chroot: "$prefix"

in it.  Because then it thinks you are chroot-ed.  Only add this if your application performed a chroot.

Best regards, Wouter
Comment 6 ruga 2016-10-18 11:31:04 CEST
Results of 
- recompiling without <<--with-chroot-dir=${prefix}>>
- removing <<chroot: "$prefix">> from unbound_for_opendkim.config and
- adding <<ResolverConfiguration $prefix/etc/unbound_for_opendkim.conf>> to opendkim.conf

> unbound-host -rv -D unbound.net
unbound.net has address 185.49.140.10 (secure)
unbound.net has IPv6 address 2a04:b900::1:0:0:10 (secure)
unbound.net mail is handled by 70 open.nlnetlabs.nl. (secure)

> sudo unbound-host -rv -C $prefix/etc/unbound.conf unbound.net
Oct 18 11:29:38 libunbound[2606:0] notice: init module 0: validator
Oct 18 11:29:38 libunbound[2606:0] notice: init module 1: iterator
Host unbound.net not found: 2(SERVFAIL). (insecure)
Host unbound.net not found: 2(SERVFAIL). (insecure)
Host unbound.net not found: 2(SERVFAIL). (insecure)

> unbound-host -rv -C $prefix/etc/unbound_for_opendkim.conf unbound.net
Oct 18 11:13:35 libunbound[88731:0] notice: init module 0: validator
Oct 18 11:13:35 libunbound[88731:0] notice: init module 1: iterator
Host unbound.net not found: 2(SERVFAIL). (insecure)
Host unbound.net not found: 2(SERVFAIL). (insecure)
Host unbound.net not found: 2(SERVFAIL). (insecure)



> opendkim[85387]: can't configure DKIM library: failed to add resolver configuration file
Comment 7 Wouter Wijngaards 2016-10-18 11:34:05 CEST
Hi Ruga,

Can you do this one again, with -dddd (that adds a lot of output) and -t A (only lookup one name, we will get more than enough debug output):

unbound-host -rv -dddd -t A -C $prefix/etc/unbound_for_opendkim.conf unbound.net

and then give the output?  That should explain the SERVFAIL.

Best regards, Wouter
Comment 8 ruga 2016-10-18 12:00:56 CEST
Created attachment 360 [details]
debug
Comment 9 Wouter Wijngaards 2016-10-18 12:04:29 CEST
Hi Ruga,

These two lines reveal the issue you have now:

Oct 18 11:48:23 libunbound[3824:0] debug:    ip4 127.0.0.1 port 53 (len 16)
Oct 18 11:48:23 libunbound[3824:0] debug: skip addr on the donotquery list ip4 127.0.0.1 port 53 (len 16)

The -r resolv.conf has 127.0.0.1 and the conf does not allow connects there.  Use this in unbound_for_opendkim.conf
do-not-query-localhost: no

(or remove the 127.0.0.1 from do-not-query-address: config statements if you have that).

Best regards, Wouter
Comment 10 ruga 2016-10-18 14:17:51 CEST
I had none of it: both do-not-query-address and do-not-query-localhost were at their default values. Now I have "do-not-query-localhost: no" enabled, and "-C" works. 

> sudo unbound-host -rv -C $prefix/etc/unbound.conf unbound.net
Oct 18 13:59:59 libunbound[17190:0] notice: init module 0: validator
Oct 18 13:59:59 libunbound[17190:0] notice: init module 1: iterator
unbound.net has address 185.49.140.10 (secure)
unbound.net has IPv6 address 2a04:b900::1:0:0:10 (secure)
unbound.net mail is handled by 70 open.nlnetlabs.nl. (secure)

> sudo unbound-host -rv -C $prefix/etc/unbound_for_opendkim.conf unbound.net
Oct 18 14:01:36 libunbound[17286:0] notice: init module 0: validator
Oct 18 14:01:36 libunbound[17286:0] notice: init module 1: iterator
unbound.net has address 185.49.140.10 (secure)
unbound.net has IPv6 address 2a04:b900::1:0:0:10 (secure)
unbound.net mail is handled by 70 open.nlnetlabs.nl. (secure)

Thank you so far. 

The opendkim side is still broken: 

[...]
opendkim[67043]: 8B80CF496A38: signature=CQaeQzxJ domain=gmail.com selector=20120113 result="key DNS query failed"
opendkim[67043]: 8B80CF496A38: key retrieval failed (s=20120113, d=gmail.com): '20120113._domainkey.gmail.com' query failed
[...]

>sudo unbound-host -rvD -tTXT 20120113._domainkey.gmail.com   
20120113._domainkey.gmail.com has TXT record "k=rsa; p=MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEA1Kd87/UeJjenpabgbFwh+eBCsSTrqmwIYYvywlbhbqoo2DymndFkbjOVIPIldNs/m40KF+yzMn1skyoxcTUGCQs8g3FgD2Ap3ZB5DekAo5wMmk4wimDO+U8QzI3SD0" "7y2+07wlNWwIt8svnxgdxGkVbbhzY8i+RQ9DpSVpPbF7ykQxtKXkv/ahW3KjViiAH+ghvvIhkx4xYSIc9oSwVmAl5OctMEeWUwg8Istjqz8BZeTWbf41fbNhte7Y+YqZOwq1Sd0DbvYAD9NOZK9vlfuac0598HY+vtSBczUiKERHv1yRbcaQtZFh5wtiRrN04BLUTD21MycBX5jYchHjPY/wIDAQAB" (insecure)

Removing the chroot made no difference for opendkim.
Comment 11 Wouter Wijngaards 2016-10-18 14:42:04 CEST
Hi Ruga,

Well it seems to have fixed unbound's invocation.  Not sure what opendkim does.  It's opendkim debugging, I guess.  If that does not have logs, perhaps set verbosity very high in the conf file and also specify a logfile, then, afterwards, find that logfile and see what unbound was trying to do.

Best regards, Wouter
Comment 12 ruga 2016-10-18 14:56:31 CEST
In case anyone bumps into this problem again, 
this is the DNS error from opendkim: 

https://sourceforge.net/p/opendkim/support-requests/35/