dnstap shows little logging at debug 10

Tue Mar 2 16:32:13 UTC 2021

Sorry, I replied to just Mark rather than the list.

Yes, here is the command I am using:

# ncat -l -U /var/opt/isc/scls/isc-bind/log/named/dnstap.sock
I "chown named.named ./dnstap.sock" :

  0 srwxr-xr-x. 1 named named unconfined_u:object_r:named_log_t:s0      0
Mar  2 09:23 dnstap.sock

But regardless I don't get anything from the pipe when using the normal
"systemctl start isc-bind-named.service" followed by some "dig" commands to
test (but see below). I was previously using fstrm_capture like this:

# /opt/isc/isc-bind/root/usr/bin/fstrm_capture -t protobuf:dnstap.Dnstap -u
/var/opt/isc/scls/isc-bind/log/named/dnstap.sock -w /var/tmp/example.dnstap

But I was only seeing 46 bytes in the "example.dnstap" and nothing decoded
when I run "dnstap-read ./example.dnstap". After "systemctl stop
isc-bind-named.service" and stopping the "fstrm_capture" process the file
increased to 54 bytes, but "dnstap-read" still doesn't decode anything.

I am reasonably confident that I am doing something boneheaded somewhere,
likely a typo in my config or bad permission somewhere, but I admit I can't
see it and without any error messages or debug information I am struggling.
The config is pretty simple, just the option stanza below and logging
settings (mostly copy-pasted from the ISC website just in case).

In an effort to figure out the problem I went so far as to:

# strace -a 120 /opt/isc/isc-bind/root/usr/sbin/named -f -u named 2>&1 |
tee temp.file

And I do suddenly get "protobuf:dnstap.Dnstap" on the pipe, but nothing
further. So my root problem seems to be with how systemd is managing the
process (maybe a user ID problem with the pipe). But my grepping the strace
didn't catch anything opening the "dnstap.sock" pipe.

I admit I don't know what I am doing wrong or how to get better
information, short of maybe stepping through with GDB to try to see where
it is failing.

Running named with this in the options:

      dnstap-output file "/var/opt/isc/scls/isc-bind/log/named/dnstap.log";

Does work just fine with lots of wonderful data, so it isn't a problem with
dnstap per se, it is something with how I am setting up the pipe or
environment named is running in.

On Mon, Mar 1, 2021 at 6:53 PM Mark Andrews <marka at isc.org> wrote:

> Do you have something reading the pipe?
>
>
> > On 2 Mar 2021, at 10:30, Adam Augustine <augustineas at gmail.com> wrote:
> >
> > I can't seem to get any debug information out of BIND for
> troubleshooting a dnstap problem I am having.
> >
> > I have a CentOS 8.3.2011 VM with the COPR packages installed.
> >
> > My /etc/opt/isc/scls/isc-bind/named.conf :
> > options {
> >         directory "/var/opt/isc/scls/isc-bind/named/data";
> >         listen-on { any; };
> >         listen-on-v6 { any; };
> >         dnssec-validation auto;
> >         dnstap {all;};
> > //      dnstap-output unix
> "/var/opt/isc/scls/isc-bind/run/named/dnstap.sock";
> >         dnstap-output unix
> "/var/opt/isc/scls/isc-bind/log/named/dnstap.sock";
> >         dnstap-identity "dnstap01.ldschurch.org";
> >         dnstap-version "bind-9.16.12";
> > };
> >
> > logging {
> > [SNIP]
> >      channel dnstap_log {
> >           file "/var/opt/isc/scls/isc-bind/log/named/dnstap" versions 3
> size 20m;
> >           print-time yes;
> >           print-category yes;
> >           print-severity yes;
> >           severity debug 10;
> >      };
> > [SNIP]
> >      category dnstap { dnstap_log; default_debug; };
> > };
> >
> > On startup, the /var/opt/isc/scls/isc-bind/log/named/dnstap file is
> created, but no information is logged:
> >
> >  4 -rw-r--r--. 1 named named system_u:object_r:named_log_t:s0        54
> Mar  1 16:23 dnstap
> >
> > This is despite /var/log/messages having the following line:
> >
> >  opening dnstap destination
> '/var/opt/isc/scls/isc-bind/log/named/dnstap.sock'
> >
> > Which I would have expected to see logged in
> /var/opt/isc/scls/isc-bind/log/named/dnstap . On shutdown, this single
> entry is logged in /var/opt/isc/scls/isc-bind/log/named/dnstap:
> >
> > 01-Mar-2021 16:23:31.597 dnstap: info: closing dnstap
> >
> > There is nothing relevant in /var/log/audit/audit.log, so I don't think
> it is SELinux related, especially since there is successful log entry on
> shutdown.
> >
> > I have tried changing the severity level from "info", to "debug 1", to
> "debug 3", and then to "debug 10", but I can't seem to get any more
> information out other than the single message about "closing dnstap".
> >
> > Any idea what I am doing wrong?
> >
> > _______________________________________________
> > Please visit https://lists.isc.org/mailman/listinfo/bind-users to
> unsubscribe from this list
> >
> > ISC funds the development of this software with paid support
> subscriptions. Contact us at https://www.isc.org/contact/ for more
> information.
> >
> >
> > bind-users mailing list
> > bind-users at lists.isc.org
> > https://lists.isc.org/mailman/listinfo/bind-users
>
> --
> Mark Andrews, ISC
> 1 Seymour St., Dundas Valley, NSW 2117, Australia
> PHONE: +61 2 9871 4742              INTERNET: marka at isc.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.isc.org/pipermail/bind-users/attachments/20210302/ad832fbe/attachment.htm>