dnstap shows little logging at debug 10

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

dnstap shows little logging at debug 10

Adam Augustine
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
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users
Reply | Threaded
Open this post in threaded view
|

Re: dnstap shows little logging at debug 10

Mark Andrews
Do you have something reading the pipe?


> On 2 Mar 2021, at 10:30, Adam Augustine <[hidden email]> 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
> [hidden email]
> 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: [hidden email]

_______________________________________________
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
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users
Reply | Threaded
Open this post in threaded view
|

Re: dnstap shows little logging at debug 10

Adam Augustine
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 <[hidden email]> wrote:
Do you have something reading the pipe?


> On 2 Mar 2021, at 10:30, Adam Augustine <[hidden email]> 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
> [hidden email]
> 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: [hidden email]


_______________________________________________
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
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users
Reply | Threaded
Open this post in threaded view
|

Re: dnstap shows little logging at debug 10

Adam Augustine
Well, I don't know what I have done exactly, but now when I start named as root it seems to be working properly, as far as the pipe goes. I am getting data via the fstrm_capture process written to the "example.dnstap" file. I see a number of startup queries when I decode the file.

I can't get it to do the same when I start it with "systemctl start isc-bind-named.service" though. So it is clearly a problem with the environment named is running in when launched by systemd.

My procedure so far (not production worthy, obviously) looks like this for those who may see this in the future:

1) run '/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"
2) "chown named.named /var/opt/isc/scls/isc-bind/log/named/dnstap.sock"
3) run "/opt/isc/isc-bind/root/usr/sbin/named -u named" from a root shell
4) go look at "example.dnstap" and see queries.

Following that process but replacing step #3 with "systemctl start isc-bind-named.service" results in everything otherwise working properly, but nothing getting added to "example.dnstap".

"ps auwwwwx | grep named" shows the same user owning the "named" process in both cases. here is the output when run in by root:

# ps auwwwxZ | grep named
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 root 7606 0.0  0.0 11060 1104 pts/0 S+ 10:05   0:00 /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
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 named 7745 0.0  1.0 531520 41720 ? Ssl 10:23   0:00 /opt/isc/isc-bind/root/usr/sbin/named -u named
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 root 7757 0.0  0.0 12116 972 pts/3 S+ 10:24   0:00 grep --color=auto named

And here is the output when run by "systemctl start isc-bind-named.service":
# ps auwwwxZ | grep named
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 root 7606 0.0  0.0 11060 1104 pts/0 S+ 10:05   0:00 /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
system_u:system_r:named_t:s0    named       7781  0.0  1.0 531516 40860 ?        Ssl  10:25   0:00 /opt/isc/isc-bind/root/usr/sbin/named -u named
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 root 7793 0.0  0.0 12116 1084 pts/3 S+ 10:26   0:00 grep --color=auto named
m_capture -t protobuf:dnstap.Dnstap -u /var/opt/isc/scls/isc-bind/log/named/dnstap.sock -w /var/tmp/example.dnstap
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 named 7745 0.0  1.0 531520 41720 ? Ssl 10:23   0:00 /opt/isc/isc-bind/root/usr/sbin/named -u named
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 root 7757 0.0  0.0 12116 972 pts/3 S+ 10:24   0:00 grep --color=auto named

So clearly it is an SELinux permissions problem. And now I am seeing denies in the /var/log/audit/audit.log.... grrr. I know there was nothing there before, so it must have been hung up on regular unix permissions or something and once I fixed that it was the SELinux permissions issue.

Sorry for wasting everyone's time. I appreciate you being there as a sounding board though. Thanks Mark for looking beyond my initial concern.

I would like to see that sort of permissions error get logged in the dnstap logs at some severity level though. I am still not clear what I am doing wrong on that front.

Thanks again.


On Tue, Mar 2, 2021 at 9:32 AM Adam Augustine <[hidden email]> wrote:
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 <[hidden email]> wrote:
Do you have something reading the pipe?


> On 2 Mar 2021, at 10:30, Adam Augustine <[hidden email]> 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
> [hidden email]
> 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: [hidden email]


_______________________________________________
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
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users
Reply | Threaded
Open this post in threaded view
|

Re: dnstap shows little logging at debug 10

Fred Morris
In reply to this post by Adam Augustine
Greetings.

On Tue, 2 Mar 2021, Adam Augustine wrote:

> # ncat -l -U /var/opt/isc/scls/isc-bind/log/named/dnstap.sock
> I "chown named.named ./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:
>
> [...]
>
> 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.

The way they did framestream initialization it requires the "optional"
handshake. I documented it (pydoc) here:

     https://github.com/m3047/shodohflo/blob/master/shodohflo/fstrm.py

--

Fred Morris

_______________________________________________
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
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users