Unbound 1.7.1 failing on some kvm servers

Tue May 29 07:05:57 UTC 2018

Hi James,

On 28/05/18 23:01, James Cloos wrote:
>>>>>> "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.

But in your strace you have a call to getrandom() that fails.

So, would like to implement the fallback, but where?  getrandom?
arc4random? getentropy?  The strace says getrandom is called and gets
ENOSYS.

In compat/compat/getentropy_linux.c that would result in a fallback to
getentropy_urandom().  That would not fail, and thus not raise SIGKILL.

So perhaps we are executing different code.  What code?  Depends on
configure time detection.

> 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.

Yes that does that.  fall back for some glibc implementation?

> 
> 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.

This is why I want to find out what happens, and what happened at
configure time.  Not sure, but can you run ltrace, it should intercept
the library call and tell us if unbound is calling a function from glibc
(or some other library perhaps, i.e. misexported internal compat
function from another program).  And we'd know more what code in unbound
gets executed?

And then I can find out where the fallback code needs to be?  I can also
make a patch for you in _rs_stir ; but you'd need to compile to try it
(and when you're doing that tell what configure at that compile says
about what library functions are available and which not).

Best regards, Wouter

> 
> 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
> 

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: OpenPGP digital signature
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20180529/7e1a12de/attachment.bin>