Issues setting up dnstap logging

[Robert Edmonds]

Patrik Lundin via Unbound-users wrote:
> Hello,
> 
> I am curious if anyone is running a successful dnstap logging setup for
> unbound and what tools you are using for solving this.
> 
> Currently I am playing around with this on a debian buster machine with
> backports enabled so I can install unbound 1.12. My goal is to have binary
> dnstap files being created on disk, with logfile rotation over some interval so
> you can clean up older files over time.
> 
> For my initial attempt I tried using fstrm_capture since it is already
> available from the "fstrm-bin" package in buster and also supports logfile
> rotation. I have noticed however that fstrm_capture will often crash when
> stopping unbound.
> 
> Based on the man page example I start the process like so:
> ```
> sudo -u unbound /usr/bin/fstrm_capture -ddddd -t protobuf:dnstap.Dnstap \
>                  -u /var/lib/unbound/dnstap.sock \
>                  -w /var/log/dnstap/dnstap-%F-%T.fstrm \
>                  -s 3600 --gmtime
> ```

Hi, Patrik:

I have a very similar setup where I run fstrm_capture on a Debian buster
system with unbound 1.12.0 from backports and fstrm-bin/libfstrm0 0.6.0
from unstable. I run fstrm_capture as a service:

    ExecStart=/usr/bin/fstrm_capture --type protobuf:dnstap.Dnstap --unix /var/log/dnstap/.sock --localtime -w /var/log/dnstap/dnstap.%%Y%%m%%d.%%H%%M.%%s

with a monthly cron that rotates the output file:

    @monthly root systemctl kill --kill-who=main --signal=SIGUSR1 fstrm_capture 2>&1

I have not seen fstrm_capture crash with SIGPIPE. However, on another
machine running unbound 1.13.0 I have noticed fstrm_capture logs the
following message when unbound is stopped, but fstrm_capture keeps
running:

    fstrm_capture: connection fd 8: libevent error: Broken pipe (32)

That makes sense to me, because if fstrm_capture is handling and logging
an EPIPE from libevent then the process isn't being killed with SIGPIPE.
But I'm not sure why the behavior differs between your fstrm_capture
instance and mine.

> I was confused by the exiting beaviour at first, it looks like the process just
> disappears for no obvious reason but after attaching gdb I saw the following:
> ````
> fstrm_capture: connection fd 8: reading control frame (12 bytes): "\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x03"
> fstrm_capture: connection fd 8: received FSTRM_CONTROL_STOP (3)
> fstrm_capture: connection fd 8: sending FSTRM_CONTROL_FINISH (5)
> fstrm_capture: connection fd 8: writing frame (12) bytes: "\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x05"
> 
> Program received signal SIGPIPE, Broken pipe.
> 0x00007ffff7c74504 in __GI___writev (fd=8, iov=0x7fffffffe010, iovcnt=1) at ../sysdeps/unix/sysv/linux/writev.c:26
> 26      ../sysdeps/unix/sysv/linux/writev.c: Permission denied.
> ```

Technically, since unbound is shutting down, it's not a big deal that it
didn't wait to receive the FSTRM_CONTROL_FINISH frame from
fstrm_capture. You might try compiling fstrm 0.6.0 from source from
https://github.com/farsightsec/fstrm with the attached patch to ignore
SIGPIPE and see if that works for you. If it does I'll submit a pull
request upstream for fstrm.

-- 
Robert Edmonds
edmonds at debian.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: fstrm_capture-ignore-SIGPIPE.patch
Type: text/x-diff
Size: 363 bytes
Desc: not available
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20201227/6a593598/attachment.bin>