Re: dnstap shows little logging at debug 10
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 bind-users@lists.isc.org https://lists.isc.org/mailman/listinfo/bind-users
Re: dnstap shows little logging at debug 10
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 aux | 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:s0named 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 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
Re: dnstap shows little logging at debug 10
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 wrote:
> Do you have something reading the pipe?
>
>
> > On 2 Mar 2021, at 10:30, Adam Augustine 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:s054
> 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@lists.isc.org
> > https://lists.isc.org/mailman/listinfo/bind-users
>
> --
> Mark Andrews, ISC
> 1 Seymour St., Dundas Valley, NSW 2117, Australia
> PHONE: +61
Re: dnstap shows little logging at debug 10
Do you have something reading the pipe?
> On 2 Mar 2021, at 10:30, Adam Augustine 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:s054 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@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: ma...@isc.org
___
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@lists.isc.org
https://lists.isc.org/mailman/listinfo/bind-users
dnstap shows little logging at debug 10
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:s054 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@lists.isc.org
https://lists.isc.org/mailman/listinfo/bind-users
