dnstap shows little logging at debug 10
Adam Augustine
augustineas at gmail.com
Tue Mar 2 17:36:21 UTC 2021
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 <augustineas at gmail.com> 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 <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/ea310368/attachment-0001.htm>
More information about the bind-users
mailing list