Unbound 1.7.1 failing on some kvm servers

Mon May 28 21:01:15 UTC 2018

>>>>> "WW" == W C A Wijngaards via Unbound-users <unbound-users at unbound.net> writes:

>> Unbound *always* should fall back to urandom(4) when getentropy(3)
>> results in ENOSYS, even when compiled against a kernel which advertizes
>> support for getrandom(2).

WW> But Unbound does that!
WW> It falls back to that when the other results in ENOSYS.

In the strace there is no attempt to open(2) "/dev/urandom".

Once the call to glibc's genentropy(3) fails, it immediately sends a
SIGKILL.

WW> What could be happening is that configure detects arc4random.  If that
WW> is the case, Unbound calls that arc4random.  And then this library call
WW> has to call getentropy, and it could be that that could does not
WW> fallback?

Indeed, compat/arc4random.c:_rs_stir calls genentropy and does not fall back.

WW> You can check the configure output for the arc4random check.
WW> Or afterwards in config.log or config.h (HAVE_ARC4RANDOM is defined or
WW> not defined).

I don't have the configure output; this is debian's compile.

WW> If that is not the case, then we'd need to go for having log printout
WW> for debug to see what happens.

What config is needed for that?  verbosity:5 ?  I don't see anything
else documented in unbound.conf(5).

:; /etc/init.d/unbound start
[....] Starting DNS server: unbound[1527535960] unbound[4025:0] debug: increased limit(open files) from 1024 to 4152
[1527535960] unbound[4025:0] debug: creating udp6 socket ::1 53
[1527535960] unbound[4025:0] debug: creating tcp6 socket ::1 53
[1527535960] unbound[4025:0] debug: creating udp4 socket 127.0.0.1 53
[1527535960] unbound[4025:0] debug: creating tcp4 socket 127.0.0.1 53
[1527535960] unbound[4025:0] debug: creating tcp6 socket ::1 8953
[1527535960] unbound[4025:0] debug: creating tcp4 socket 127.0.0.1 8953
[1527535960] unbound[4025:0] debug: setup SSL certificates
[1527535960] unbound[4025:0] debug: switching log to syslog

and then in syslog:

May 28 19:32:40 tea unbound-anchor: /var/lib/unbound/root.key has content
May 28 19:32:40 tea unbound-anchor: success: the anchor is ok
May 28 19:32:40 tea unbound: [4026:0] debug: chdir to /etc/unbound
May 28 19:32:40 tea unbound: [4026:0] debug: drop user privileges, run as unbound
May 28 19:32:40 tea unbound: [4026:0] debug: module config: "subnetcache validator iterator"
May 28 19:32:40 tea unbound: [4026:0] notice: init module 0: subnet
May 28 19:32:40 tea unbound: [4026:0] debug: subnet: option registered (8)
May 28 19:32:40 tea unbound: [4026:0] notice: init module 1: validator
May 28 19:32:40 tea unbound: [4026:0] debug: reading autotrust anchor file /var/lib/unbound/root.key
May 28 19:32:40 tea unbound: [4026:0] info: trust point . : 1
May 28 19:32:40 tea unbound: [4026:0] info: assembled 0 DS and 2 DNSKEYs
May 28 19:32:40 tea unbound: [4026:0] info: DNSKEY:: .#011172800#011IN#011DNSKEY#011257 3 8 AwEAAagAIKlVZrpC6Ia7gEzahOR+9W29euxhJhVVLOyQbSEW0O8gcCjFFVQUTf6v58fLjwBd0YI0EzrAcQqBGCzh/RStIoO8g0NfnfL2MTJRkxoXbfDaUeVPQuYEhg37NZWAJQ9VnMVDxP/VHL496M/QZxkjf5/Efucp2gaDX6RS6CXpoY68LsvPVjR0ZSwzz1apAzvN9dlzEheX7ICJBBtuA6G3LQpzW5hOA2hzCTMjJPJ8LbqF6dsV6DoBQzgul0sGIcGOYl7OyQdXfZ57relSQageu+ipAdTTJ25AsRTAoub8ONGcLmqrAmRLKBP1dfwhYB4N7knNnulqQxA+Uk1ihz0= ;{id = 19036 (ksk), size = 2048b}
May 28 19:32:40 tea unbound: [4026:0] info: DNSKEY:: .#011172800#011IN#011DNSKEY#011257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMgJzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBxWezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+cn8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b}
May 28 19:32:40 tea unbound: [4026:0] info: file /var/lib/unbound/root.key
May 28 19:32:40 tea unbound: [4026:0] info: last_queried: 1527535960 Mon May 28 19:32:40 2018
May 28 19:32:40 tea unbound: [4026:0] info: last_success: 1527535960 Mon May 28 19:32:40 2018
May 28 19:32:40 tea unbound: [4026:0] info: next_probe_time: 1527575738 Tue May 29 06:35:38 2018
May 28 19:32:40 tea unbound: [4026:0] info: query_interval: 43200
May 28 19:32:40 tea unbound: [4026:0] info: retry_time: 8640
May 28 19:32:40 tea unbound: [4026:0] info: query_failed: 0
May 28 19:32:40 tea unbound: [4026:0] info: [  VALID  ] .#011172800#011IN#011DNSKEY#011257 3 8 AwEAAagAIKlVZrpC6Ia7gEzahOR+9W29euxhJhVVLOyQbSEW0O8gcCjFFVQUTf6v58fLjwBd0YI0EzrAcQqBGCzh/RStIoO8g0NfnfL2MTJRkxoXbfDaUeVPQuYEhg37NZWAJQ9VnMVDxP/VHL496M/QZxkjf5/Efucp2gaDX6RS6CXpoY68LsvPVjR0ZSwzz1apAzvN9dlzEheX7ICJBBtuA6G3LQpzW5hOA2hzCTMjJPJ8LbqF6dsV6DoBQzgul0sGIcGOYl7OyQdXfZ57relSQageu+ipAdTTJ25AsRTAoub8ONGcLmqrAmRLKBP1dfwhYB4N7knNnulqQxA+Uk1ihz0= ;{id = 19036 (ksk), size = 2048b} ;;state:2 ;;pending_count:0 last:Sat Jun 13 03:12:07 2015
May 28 19:32:40 tea unbound: [4026:0] info: [  VALID  ] .#011172800#011IN#011DNSKEY#011257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMgJzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBxWezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+cn8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b} ;;state:2 ;;pending_count:0 last:Thu Aug 10 22:41:16 2017
May 28 19:32:40 tea unbound: [4026:0] debug: validator nsec3cfg keysz 1024 mxiter 150
May 28 19:32:40 tea unbound: [4026:0] debug: validator nsec3cfg keysz 2048 mxiter 500
May 28 19:32:40 tea unbound: [4026:0] debug: validator nsec3cfg keysz 4096 mxiter 2500
May 28 19:32:40 tea unbound: [4026:0] notice: init module 2: iterator
May 28 19:32:40 tea unbound: [4026:0] debug: target fetch policy for level 0 is 3
May 28 19:32:40 tea unbound: [4026:0] debug: target fetch policy for level 1 is 2
May 28 19:32:40 tea unbound: [4026:0] debug: target fetch policy for level 2 is 1
May 28 19:32:40 tea unbound: [4026:0] debug: target fetch policy for level 3 is 0
May 28 19:32:40 tea unbound: [4026:0] debug: target fetch policy for level 4 is 0
May 28 19:32:40 tea unbound: [4026:0] debug: donotq: 127.0.0.0/8
May 28 19:32:40 tea unbound: [4026:0] debug: donotq: ::1
May 28 19:32:40 tea unbound: [4026:0] debug: EDNS known options:
May 28 19:32:40 tea unbound: [4026:0] debug:   Code:    Bypass_cache_stage: Aggregate_mesh:
May 28 19:32:40 tea unbound: [4026:0] debug:   edns-cli NO                  YES            

and then nothing else.

-JimC
-- 
James Cloos <cloos at jhcloos.com>         OpenPGP: 0x997A9F17ED7DAEA6