10.8 Logging Dynamic Updates

10.8.1 Problem

You want to log the dynamic updates received by a name server.

10.8.2 Solution

By default, a name server will log dynamic updates it receives, both successful and failed, at severity info. For each successful dynamic update, you'll see a message like this in the name server's syslog output:

Jun 25 19:55:38 ns1 named[54132]: client 192.168.0.1#2206: updating zone 'foo.
example/IN': deleting an rrset

For each failed dynamic update, you'll see a message like this:

Jun 25 19:57:39 ns1 named[54132]: client 192.168.0.1#2213: update 'foo.example/IN' 
denied

Or, for an update that failed because a prerequisite wasn't met, you'll see a message like this one:

Jun 25 20:00:02 ns1 named[54132]: client 192.168.0.1#2220: updating zone 'foo.
example/IN': update failed: 'name in use' prerequisite not satisfied (NXDOMAIN)

The first and last types of dynamic update messages are logged in the update category; the middle variety is logged in the security category. You can separate these messages from others by adding a logging statement to the name server's named.conf file that sends messages in each of these categories to special files. For example:

logging {

    channel update_log {
        file "update.log";
        severity info;
        print-time yes;
    };

    channel security_log {
        file "security.log";
        severity info;
        print-time yes;
    };

    category update { update_log; };
    category security { security_log; };

};

10.8.3 Discussion

If you don't see any messages in the syslog output, check the host's syslog.conf file and make sure syslogd is logging all messages at severity info or higher. named usually logs to the facility daemon, so an entry to log all of those messages might look like this:

daemon.info    /var/log/messages

Note that there are many different security-related messages in the security category, most of them unrelated to dynamic updates. In BIND 9.3.0, the name server separates update- from other security-related messages by placing "update denied" messages into update-security category.

As you can see from the messages cited so far in this recipe, the standard syslog messages about dynamic updates say very little about the contents of an update (that is, the change that the update made or tried to make), except the zone that the update tried to modify. To see the changes that were made, you'd have to look at the dynamic update log file. In BIND 8, the dynamic update log file is named after the zone data file, with .log on the end. In BIND 9, the file ends in .jnl. The .log file is in ASCII format and contains human-readable entries like this:

;BIND LOG V8
[DYNAMIC_UPDATE] id 56537 from [192.168.0.1].4662 at 1019882646 (named pid 21378):
zone:   origin foo.example class IN serial 2002042600
update: {add} test.foo.example 3600 IN A 10.0.0.93

These entries, significantly, include a timestamp that indicates when the update was processed; for this update, the timestamp is 1019882646, the number of seconds since the Unix epoch. To convert that to a date and time, you can use the date command:

$ date -r 1019882646
Fri Apr 26 22:44:06 MDT 2002

The timestamp may help you correlate this change with a particular message from the name server's syslog output.

The .jnl file is in a binary format. To decipher it, build the journalprint program from the BIND distribution:

$ cd bin/tests
$ make journalprint

To run journalprint, just specify the journal file you want to decode as the argument:

$ journalprint db.foo.example.jnl
del foo.example.                86400   IN      SOA     ns1.foo.example. root.foo.
example. 2002062500 3600 900 2592000 3600
add foo.example.                86400   IN      SOA     ns1.foo.example. root.foo.
example. 2002062501 3600 900 2592000 3600
add mail.foo.example.   3600    IN      A       192.168.0.2
add foo.example.                3600    IN      MX      0 mail.foo.example.
add foo.example.                3600    IN      TXT     "Test update"

The lines that begin with del indicate records deleted, while lines that begin with add . . . well, you get the idea. You'll see the zone's SOA record being added and deleted with every update: that's actually just the serial number incrementing automatically.

Since there's no timestamp in the journal file, it's not generally possible to correlate individual changes with particular syslog messages.

10.8.4 See Also

Section 3.11, for allowing dynamic updates to a zone.