patches for improved logging in 9.2.1

Danny Thomas d.thomas at its.uq.edu.au
Sat Jul 20 10:24:19 UTC 2002


Hello,
      we've been interested in moving to bind9 for a long time.
Our initial reluctance came about from the limited options supported by
early versions of rndc. The 9.2.1 release had a sufficiently-featureful
rndc so we installed one instance of a resolving/authoritative server.
This worked fine with our simple method of propagating named.conf from
our master server.

However we were dissatisfied with the logging, and were particularly
surprised to find this didn't seem to be an issue on the bind9 users
or workers list.

Ted Rule did share our concerns:
  http://www.mail-archive.com/bind9-workers@isc.org/msg00553.html
but there doesn't seem to have been any follow-up.

Compared with bind8 we noticed:
  1) syslog file entries show 'syslog' rather than named/pid
  2) the actual query is not included in query-denied messages
     knowing the query can help diagnose problems/misconfigurations
  3) new zones, eg via reconfig, not specially logged
  4) no logging when zones removed
  5) secondaries *do not log anything* when they don't do an update
     because the master has a lower serial number.
  6a) notify error messages do not include the sender's ip address
  6b) successful notifies not logged

These were with 9.2.1 ("severity info"), though a look at the
latest 9.3.0 snapshot does not indicate significant change.

A discussion of each of these situations follows based on a cursory
look at the code, which is more complex than I expected - probably
to support the newer features like DNSSEC.

My patches (3K gz) can be retrieved from
  http://www.its.uq.edu.au/DMT/misc/bind-9.2.1uq1.patch.gz
with the caveat that they need reviewing by somebody who understands
the code.

The EXAMPLE sections represent output from a patched bind.

cheers,
Danny Thomas

PS Ted also noted another logging deficiency:
 "The notify processing code fails to log any message indicating a valid
  notify message has been received. bin/named/notify.c contains a number
  of notify_log() calls for various classes of failure, but no logging of
  success per se.

  This as compared with bind8 which logs both success and failure in the
  notify code."



1) syslog file entries show 'syslog' rather than named/pid
=====================================================================
Jul  7 17:36:36 yarama named[3685]: starting BIND 9.2.1uq1
Jul  7 17:36:36 yarama named[3685]: using 1 CPU
Jul  7 17:36:36 yarama syslog: loading configuration from '/etc/named.conf'
Jul  7 17:36:36 yarama syslog: no IPv6 interfaces found

note the first two statements do include process name/id, but then
becomes just 'syslog'. NB this might be related to our OS, Tru64 4.1D,
because this problem does not happen on a NetBSD 1.5.x/i386 system.

Consequently, I have not looked at patching this.

Logging is done by the long routine isc_log_doit() in lib/isc/log.c
However the critical part is isc_log_opensyslog() which although not
fully fleshed-out yet (see comments in lib/isc/include/isc/log.h) does
not seem called by any code except once in log_test.c

However there is one use each of openlog() in unix/os.c & win32/os.c
called from main() in named/main.c where it should be fed from
program_name == "named". Almost certainly this accounts for the initial
two log statements being from 'named'.



2) denied queries don't log what the query was
=====================================================================
Jun  8 10:14:14 wilma syslog: security: info:
  client 64.71.156.114#65396: query (cache) denied

As Ted Rule mentions, if query-logging is enabled, you can probably
match up the logging of the query request with the denied message,
but that hardly rates as convenient.

this query failure logged around bin/named/query.c/772
        result = ns_client_checkacl(client, "query (cache)",
                        client->view->queryacl,
                        ISC_TRUE,
                        log ? ISC_LOG_INFO :
                          ISC_LOG_DEBUG(3));

compared with one around line 675
        ns_client_aclmsg("query", name,
                 client->view->rdclass,
                 msg, sizeof(msg));
        ns_client_log(client, DNS_LOGCATEGORY_SECURITY,
                  NS_LOGMODULE_QUERY, ISC_LOG_INFO,
                     "%s denied", msg);


NB ns_client_aclmsg() (bin/named/client.c) does log query & class,
but not type

So my patch adds a call to ns_client_aclmsg() immediately prior to 
ns_client_checkacl() at line 772. We precede that with the definition
of a  msgbuf of appropriate size and pass that msgbuf instead of
"query (cache)" to ns_client_checkacl(). Also added name as a parameter
to query_getcachedb() and two its' two calls in query.c.

I briefly tried to add the query type to the msg by replacing the calls
to  ns_client_aclmsg() by calls to a copy of log_query() modified to have
the msgbuf as a parameter, and to output into msgbuf by using snprintf()
instead of ns_client_log().

However type 'ANY' was always printed, perhaps because the code at this
point seems to be structured to produce an RRset. It's left to the
higher-level routines to know the query-type and extract the wanted ones
from the RRset.

Ted also suggested including the transport (udp/tcp) and recursive flag.

EXAMPLE:
 Jun 24 19:45:28 im-ntp named[21779]: security: info:
   client 130.102.152.42#50259: query (cache) '1.0.0.128.in-addr.arpa/IN' denied



3) new zones not specially logged
=====================================================================
In this case it turns out that bind9 logs similarly to bind8,
but we'd still like it improved

bind8
  Jun 27 14:56:51 krefti named[19187]: rcvd NOTIFY(fred.test, IN, SOA)
    from [130.102.128.43].3499
  Jun 27 14:56:51 krefti named[19187]: rcvd NOTIFY for "fred.test",
    name not one of our zones
  Jun 27 15:05:06 krefti named[19187]: slave zone "fred.test" (IN)
    loaded (serial 2002031910)

bind9
  Jun 27 14:56:51 wilma syslog: notify: info:
    received notify for zone 'fred.test': not authoritative
  Jun 27 14:56:51 wilma syslog: notify: info:
    received notify for zone 'fred.test': not authoritative
  Jun 27 15:06:09 wilma syslog: general: info:
    zone fred.test/IN: loaded serial 2002031910


zone_load() looks to be a useful place to add logging
It is directly called only from
      dns_zone_load():  return (zone_load(zone, 0);
   dns_zone_loadnew():  return (zone_load(zone, DNS_ZONELOADFLAG_NOSTAT));
With these functions being passed to iterators over zone tables.
   
Based purely on it's name, it seems we want to specially log zones when
zone_load() is called from dns_zone_loadnew(). We do that by checking
the one-bit set in the flags parameter:
    (flags & DNS_ZONELOADFLAG_NOSTAT) != 0)

I suspect we'd really want the logging statement added to zone_loaddone(),
but I don't think it currently has any parameter info the equivalent of 
zone_load's flags to distinguish loading of new zones.

So for now, the new logging statement was added to zone_load() after a 
successful call to zone_postload().

EXAMPLE:
  Jul  8 11:58:23 yarama syslog: general: warning:
    zone fred.test/IN: loaded new zone



4) no logging when zones removed
=====================================================================
We followed Ted's suggestion by placing a call to dns_zone_log()
in zone_free() from lib/dns/zone.c.

This has to be near the beginning of the function.

However each reconfig also caused two in-built zones to be logged:
  Jul  7 17:10:43 yarama syslog: general: warning:
    zone authors.bind/CH: removing zone
  Jul  7 17:10:43 yarama syslog: general: warning:
    zone version.bind/CH: removing zone
Hence the conditional test.

EXAMPLE:
  Jul  8 11:58:00 yarama syslog: general: warning:
    zone fred.test/IN: removing zone



5) secondaries do not log *anything* when master has a lower serial number
==========================================================================
We rate this a 'critical' bug.

bind8 logs the following every time it tries updating:
  Jun 24 20:07:56 krefti named[19187]:
    Zone "fred.bloggs" (IN) SOA serial# (1999000000)
    rcvd from [130.102.128.43] is < ours (2002000000)


A glance through the code found the following fragment amongst the
consistency checks in zone_postload() of lib/dns/zone.c
        if (zone->db != NULL) {
            if (!isc_serial_ge(serial, zone->serial)) {
                dns_zone_log(zone, ISC_LOG_ERROR,
                         "zone serial has gone backwards");
            }

However this only comes into play once a zone is loaded.

The hack is in lib/dns/zone.c/refresh_callback(), in the else clause after
testing first isc_serial_gt() then isc_serial_eq().

This clause already has a logging statement:
    zone_debuglog(zone, me, 1, "ahead");
but we want something at much higher than debug level, and roughly
corresponding to the bind8 message.

EXAMPLE:
  Jul  8 12:30:26 yarama syslog: general: error: zone fred.bloggs/IN:
    serial num (1999000000) rcvd from 130.102.128.43#53 < ours (2000000000)


6a) notify errors messages do not include the sender's ip address
=====================================================================
we rate this type of bug as 'serious'. Even though the problem is
not with this server, it makes it harder to track problems.

bind8:
  Jun 29 16:28:11 krefti named[19187]:
    unrelated additional info 'www.readnotify.com' type A
    from [193.114.233.33].53

bind9:
  Jul 10 16:36:02 cuscus syslog: notify: info:
    received notify for zone 'qed.qld.gov.au': not authoritative

Seems a relatively simple fix in bin/named/notify.c. Just add a buffer
and dump the client's address into it. Update calls to notify_log().




6b) successful notifies not logged
=====================================================================

bind8:
  Jul  8 15:24:05 krefti named[19187]:
    rcvd NOTIFY(jcu.edu.au, IN, SOA) from [137.219.16.14].1096


EXAMPLE:
  Jul 10 19:47:48 yarama syslog: notify: info:
    received notify for zone 'fred.bloggs': from 130.102.128.43#1100

-- 
   d.thomas at its.uq.edu.au    Danny Thomas,                                    
          +61-7-3365-8221    Infrastructure Management,
 http://www.its.uq.edu.au    ITS, The University of Queensland


More information about the bind-workers mailing list