notify and views

Hi,
I'm running BIND 9.3.0 (installed from pkgsrc) on two NetBSD 2.0 i386
systems. Both systems run a authoritative only (master and slave) and
a caching only server. The master has two views defined (one for internal
and one for external queries).

If I edit and reload a zone on the master (urchin), the slave (grouper)
gets notified just fine:

Jan 13 15:15:24 urchin named[7209]: general: info: zone salmi.ch/IN/internal: loaded serial 2005011304
Jan 13 15:15:24 urchin named[7209]: general: info: zone salmi.ch/IN/external: loaded serial 2005011304
Jan 13 15:15:24 urchin named[7209]: notify: info: zone salmi.ch/IN/internal: sending notifies (serial 2005011304)
Jan 13 15:15:24 urchin named[7209]: notify: info: zone salmi.ch/IN/external: sending notifies (serial 2005011304)

The slave receives the notify messages and starts the transfer:

Jan 13 15:15:24 grouper named[24623]: notify: info: client 212.254.26.66#59176: view internal: received notify for zone 'salmi.ch'
Jan 13 15:15:24 grouper named[24623]: general: info: zone salmi.ch/IN/internal: Transfer started.
Jan 13 15:15:24 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: connected using 212.254.26.67#60788
Jan 13 15:15:24 grouper named[24623]: general: info: zone salmi.ch/IN/internal: transferred serial 2005011304: TSIG 'ns1-ns2.key'
Jan 13 15:15:24 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: end of transfer

The master logs the following:

Jan 13 15:15:24 urchin named[7209]: xfer-out: info: client 212.254.26.67#60788: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR started: TSIG ns1-ns2.key
Jan 13 15:15:24 urchin named[7209]: xfer-out: info: client 212.254.26.67#60788: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR ended

So far so good, the internal view on the slave is up to date now. But then,
instead of updating the external view as well, the slave tries to update
the internal view again (this happens immediately after the successful
transfer shown above; see the timestamps):

Jan 13 15:15:24 grouper named[24623]: notify: info: client 212.254.26.66#59176: view internal: received notify for zone 'salmi.ch'
Jan 13 15:15:24 grouper named[24623]: general: info: zone salmi.ch/IN/internal: notify from 212.254.26.66#59176: zone is up to date

Hmm. Of course it's up to date, it was fetched less than a second ago...

About 12 minutes later, the external view is eventually fetched:

Jan 13 15:27:18 grouper named[24623]: general: info: zone salmi.ch/IN/external: Transfer started.
Jan 13 15:27:18 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: connected using 212.254.26.67#60784
Jan 13 15:27:19 grouper named[24623]: general: info: zone salmi.ch/IN/external: transferred serial 2005011304: TSIG 'ns1-ns2.key'
Jan 13 15:27:19 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: end of transfer

However, the master logs this as if the internal view was transferred:

Jan 13 15:27:19 urchin named[7209]: xfer-out: info: client 212.254.26.67#60784: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR started: TSIG ns1-ns2.key
Jan 13 15:27:19 urchin named[7209]: xfer-out: info: client 212.254.26.67#60784: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR ended


Hmm, strange. At least for me. Some questions:

- Why does the slave try to update the internal view twice at first?
- Why is the second transfer (external view) delayed by about 12 min.?
(I tried twice, both times it was ~12 min...)
- Why does the master think the slave fetches the internal view while
the slave fetches the external view?


Hints are appreciated!

TIA, Jukka

P.S.: Because it might be more clearly arranged, the logs shown above
are attached, sorted by server and then chronologically.

--
bashian roulette:
$ ((RANDOM%6)) || rm -rf ~


-- Attached file included as plaintext by Ecartis --

master:

Jan 13 15:15:24 urchin named[7209]: general: info: zone salmi.ch/IN/internal: loaded serial 2005011304
Jan 13 15:15:24 urchin named[7209]: general: info: zone salmi.ch/IN/external: loaded serial 2005011304
Jan 13 15:15:24 urchin named[7209]: notify: info: zone salmi.ch/IN/internal: sending notifies (serial 2005011304)
Jan 13 15:15:24 urchin named[7209]: notify: info: zone salmi.ch/IN/external: sending notifies (serial 2005011304)
Jan 13 15:15:24 urchin named[7209]: xfer-out: info: client 212.254.26.67#60788: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR started: TSIG ns1-ns2.key
Jan 13 15:15:24 urchin named[7209]: xfer-out: info: client 212.254.26.67#60788: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR ended
Jan 13 15:27:19 urchin named[7209]: xfer-out: info: client 212.254.26.67#60784: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR started: TSIG ns1-ns2.key
Jan 13 15:27:19 urchin named[7209]: xfer-out: info: client 212.254.26.67#60784: view internal: transfer of 'salmi.ch/IN': AXFR-style IXFR ended


slave:

Jan 13 15:15:24 grouper named[24623]: notify: info: client 212.254.26.66#59176: view internal: received notify for zone 'salmi.ch'
Jan 13 15:15:24 grouper named[24623]: general: info: zone salmi.ch/IN/internal: Transfer started.
Jan 13 15:15:24 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: connected using 212.254.26.67#60788
Jan 13 15:15:24 grouper named[24623]: general: info: zone salmi.ch/IN/internal: transferred serial 2005011304: TSIG 'ns1-ns2.key'
Jan 13 15:15:24 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: end of transfer
Jan 13 15:15:24 grouper named[24623]: notify: info: client 212.254.26.66#59176: view internal: received notify for zone 'salmi.ch'
Jan 13 15:15:24 grouper named[24623]: general: info: zone salmi.ch/IN/internal: notify from 212.254.26.66#59176: zone is up to date
Jan 13 15:27:18 grouper named[24623]: general: info: zone salmi.ch/IN/external: Transfer started.
Jan 13 15:27:18 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: connected using 212.254.26.67#60784
Jan 13 15:27:19 grouper named[24623]: general: info: zone salmi.ch/IN/external: transferred serial 2005011304: TSIG 'ns1-ns2.key'
Jan 13 15:27:19 grouper named[24623]: xfer-in: info: transfer of 'salmi.ch/IN' from 212.254.26.66#53: end of transfer