dnstap in Unbound 1.12.0 on FreeBSD 12-STABLE doesn't work

[rallenh]

Hi,

I have been trying to get dnstap via a file socket on FreeBSD 12-STABLE. I can't seem to make it work following: http://dnstap.info/Tutorials/NANOG60/ (even thought it's dated).

I have the Go dnstap utility installed. I use it to create and listen to the socket via:

sudo -u unbound ~/go/bin/dnstap -u /usr/local/etc/unbound/dnstap.sock -w /tmp/dnstap.out

Here's my unbound.conf dnsp section:

dnstap:
        dnstap-enable: yes
        # dnstap-bidirectional: yes
        dnstap-socket-path: "dnstap.sock"
        # dnstap-ip: ""
        # dnstap-tls: yes
        # dnstap-tls-server-name: ""
        # dnstap-tls-cert-bundle: ""
        # dnstap-tls-client-key-file: ""
        # dnstap-tls-client-cert-file: ""
        dnstap-send-identity: yes
        dnstap-send-version: yes
        # dnstap-identity: ""
        # dnstap-version: ""
        dnstap-log-resolver-query-messages: yes
        dnstap-log-resolver-response-messages: yes
        dnstap-log-client-query-messages: yes
        dnstap-log-client-response-messages: yes
        dnstap-log-forwarder-query-messages: yes
        dnstap-log-forwarder-response-messages: yes

FreeBSD uses the chroot option (chroot: "/usr/local/etc/unbound") for unbound. Here's what I see in the log (to syslog):

Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: init module 0: validator
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: init module 1: iterator
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: attempting to connect to dnstap socket /usr/local/etc/unbound/dnstap.sock
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] warning: could not open dnstap-socket-path: /usr/local/etc/unbound/dnstap.sock, No such file or directory
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap identity field set to "blah-blah-blah-blah"
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap version field set to "unbound 1.12.0"
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap Message/RESOLVER_QUERY enabled
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap Message/RESOLVER_RESPONSE enabled
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap Message/CLIENT_QUERY enabled
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap Message/CLIENT_RESPONSE enabled
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap Message/FORWARDER_QUERY enabled
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] notice: dnstap Message/FORWARDER_RESPONSE enabled
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:0] info: start of service (unbound 1.12.0).
Nov 29 22:52:59 blah-blah-blah-blah unbound[5929]: [5929:2] error: dnstap io: failed to connect to "/usr/local/etc/unbound/dnstap.sock": No such file or directory
Nov 29 22:52:59 static-173-53-110-7 syslogd: last message repeated 1 times

Here's a stat on the file:

stat -x /usr/local/etc/unbound/dnstap.sock
  File: "/usr/local/etc/unbound/dnstap.sock"
  Size: 0            FileType: Socket
  Mode: (0755/srwxr-xr-x)         Uid: (   59/ unbound)  Gid: (    0/   wheel)
Device: 0,112   Inode: 2053109887    Links: 1
Access: Sun Nov 29 22:38:59 2020
Modify: Sun Nov 29 22:38:59 2020
Change: Sun Nov 29 22:38:59 2020

I found this FreeBSD b/z https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=248828 which suggests to come here and report the issue.

I can make dnstap work via a network socket:

dnstap:
        dnstap-enable: yes
        # dnstap-bidirectional: yes
        # dnstap-socket-path: "dnstap.sock"
         dnstap-ip: 127.0.0.1@5353
         dnstap-tls: no
        # dnstap-tls-server-name: ""
        # dnstap-tls-cert-bundle: ""
        # dnstap-tls-client-key-file: ""
        # dnstap-tls-client-cert-file: ""
        dnstap-send-identity: yes
        dnstap-send-version: yes
        # dnstap-identity: ""
        # dnstap-version: ""
        dnstap-log-resolver-query-messages: yes
        dnstap-log-resolver-response-messages: yes
        dnstap-log-client-query-messages: yes
        dnstap-log-client-response-messages: yes
        dnstap-log-forwarder-query-messages: yes
        dnstap-log-forwarder-response-messages: yes

sudo -u unbound ~/go/bin/dnstap -l 127.0.0.1:5353 -w /tmp/dnstap.out
dnstap.FrameStreamSockInput: accepted a socket connection

sudo ~/go/bin/dnstap -r /tmp/dnstap.out | head -n 3
dnstap: opened input file /tmp/dnstap.out
23:12:10.430397 CQ 9.8.7.6 UDP 41b "api.useragentswitch.com." IN A
23:12:10.430696 FQ 1.2.3.4 TCP 52b "api.useragentswitch.com." IN A
23:12:10.591342 FR 1.2.3.4 TCP 122b "api.useragentswitch.com." IN A

[wcawijngaards]

Hi rallenh,
In the new 1.13.0 release there is a bugfix for dnstap and chroot,
- Fix dnstap socket and the chroot not applied properly to the dnstap socket path.

It is in pre-release and available for download, https://lists.nlnetlabs.nl/pipermail/unbound-users/2020-November/007091.html

[wcawijngaards]

Instead pick up rc4 with bug fixes, or final releases by checking the nlnetlabs.nl downloads. Unbound 1.13.0rc4 can be found here: https://lists.nlnetlabs.nl/pipermail/unbound-users/2020-November/007095.html

[rallenh]

@wcawijngaards ,

I was able to test 1.13.0rc4 out.

$ unbound -V
Version 1.13.0rc4

Configure line: --with-ssl=/usr --with-libexpat=/usr/local --disable-dnscrypt --enable-dnstap --enable-ecdsa --disable-event-api --enable-gost --with-libevent --disable-subnet --enable-tfo-client --enable-tfo-server --with-pthreads --prefix=/usr/local --localstatedir=/var --mandir=/usr/local/man --infodir=/usr/local/share/info/ --build=amd64-portbld-freebsd12.2
Linked libs: libevent 2.1.12-stable (it uses kqueue), OpenSSL 1.1.1h-freebsd  22 Sep 2020
Linked modules: dns64 respip validator iterator
TCP Fastopen feature available

BSD licensed, see LICENSE in source package for details.
Report bugs to unbound-bugs@nlnetlabs.nl or https://github.com/NLnetLabs/unbound/issues

1.13.0.rc4 does work for me:

$ sudo -u unbound ~/go/bin/dnstap -u /usr/local/etc/unbound/dnstap.sock -w /tmp/dnstap.out
dnstap: opened input socket /usr/local/etc/unbound/dnstap.sock
dnstap.FrameStreamSockInput: accepted a socket connection

$ sudo ~/go/bin/dnstap -r /tmp/dnstap.out | head -n 3
dnstap: opened input file /tmp/dnstap.out
21:33:25.570653 CQ 1.2.3.4 UDP 38b "substrate.office.com." IN A
21:33:24.978115 CQ 1.2.3.5 UDP 41b "api.useragentswitch.com." IN A
21:33:25.570832 FQ 9.8.7.6 TCP 49b "SUBsTrate.OfFICE.coM." IN A

But, I am now getting this on startup (where I didn't previously):

$ sudo service unbound restart
Stopping unbound.
Waiting for PIDS: 58956.
Obtaining a trust anchor..[1606790154] libunbound[34147:0] error: udp connect failed: No route to host for 2001:500:a8::e port 53
[1606790154] libunbound[34147:0] error: udp connect failed: No route to host for 2001:500:2::c port 53
[1606790154] libunbound[34147:0] error: udp connect failed: No route to host for 2001:500:9f::42 port 53
[1606790154] libunbound[34147:0] error: udp connect failed: No route to host for 2001:500:2::c port 53
[1606790155] libunbound[34147:0] error: udp connect failed: No route to host for 2001:dc3::35 port 53
[1606790155] libunbound[34147:0] error: udp connect failed: No route to host for 2001:500:12::d0d port 53
[1606790155] libunbound[34147:0] error: udp connect failed: No route to host for 2001:7fe::53 port 53
[1606790155] libunbound[34147:0] error: udp connect failed: No route to host for 2001:503:c27::2:30 port 53

I have do-ip6: no (and no IPv6 configuration on my interfaces) in my unbound.conf. It looks like these are from the root.hints file?

It's also nondeterministic:

$ sudo service unbound restart
Stopping unbound.
Waiting for PIDS: 75416.
Obtaining a trust anchor...
Starting unbound.

$ sudo service unbound restart
Stopping unbound.
Waiting for PIDS: 6858.
Obtaining a trust anchor..[1606790594] libunbound[16435:0] error: udp connect failed: No route to host for 2001:500:12::d0d port 53
.
Starting unbound.

$ sudo service unbound restart
Stopping unbound.
Waiting for PIDS: 17693.
Obtaining a trust anchor..[1606790601] libunbound[28625:0] error: udp connect failed: No route to host for 2001:500:1::53 port 53
[1606790601] libunbound[28625:0] error: udp connect failed: No route to host for 2001:7fe::53 port 53
.
Starting unbound.

[wcawijngaards]

Thanks for the test with 1.13.0rc4, good to know that the dnstap stuff works. For the udp connect error I made a bugfix. It ignores that error, it is harmless, and only prints it on high verbosity levels.

In your case I think it only means IPv6 network is not connected, or not connected to those destination subnets, and it reports that. For Unbound it can continue fine. Likely this change is not in 1.13.0, but in a later release, it is in the code repo. If you want you can get the patch by applying that commit to your version as a diff.