Replying to myself,
On Aug 18 20:51:26, Jan Stary wrote:
> This is -current as of a few weeks back, running on ALIX2C3.
> Works smoothly as my home router/fw/dns, but when booting
> gets to starting named, there is a strange slowdown:
<snip>
> Aug 18 19:48:58 gw named[15560]: starting BIND 9.4.2-P1
> Aug 18 19:49:03 gw named[15560]: loading configuration from '/etc/named.conf'
> Aug 18 19:49:03 gw named[15560]: listening on IPv6 interfaces, port 53
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface lo0, 127.0.0.1#53
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr0,
> 192.167.167.1#53
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr1,
> 192.168.111.1#53
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: listening on IPv4 interface vr2,
> 192.168.222.1#53
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:04 gw named[15560]: Binding privsep
> Aug 18 19:49:04 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:05 gw named[15560]: Binding locally
> Aug 18 19:49:05 gw named[15560]: Binding locally
> Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal:
> 254.169.IN-ADDR.ARPA
> Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal:
> 2.0.192.IN-ADDR.ARPA
> Aug 18 19:49:06 gw named[15560]: automatic empty zone: view internal:
> 255.255.255.255.IN-ADDR.ARPA
>
> # took about 8 seconds up to here; but then
>
> Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
> 0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA
>
> # what could possibly take 25 seconds when loading an automatic empty zone?
Could we possibly be waiting for 'ntpd -s'? See:
> Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
> 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA
> Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
> D.F.IP6.ARPA
> Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
> 8.E.F.IP6.ARPA
> Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
> 9.E.F.IP6.ARPA
> Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
> A.E.F.IP6.ARPA
> Aug 18 19:49:31 gw named[15560]: automatic empty zone: view internal:
> B.E.F.IP6.ARPA
> Aug 18 19:49:31 gw named[15560]: Binding privsep
> Aug 18 19:49:31 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:31 gw named[15560]: command channel listening on 127.0.0.1#953
> Aug 18 19:49:31 gw named[15560]: Binding privsep
> Aug 18 19:49:31 gw named[29233]: [priv]: msg PRIV_BIND received
> Aug 18 19:49:31 gw named[15560]: command channel listening on ::1#953
> Aug 18 19:49:31 gw named[15560]: zone 127.in-addr.arpa/IN/internal: loaded
> serial 1
> Aug 18 19:49:31 gw named[15560]: zone 111.168.192.in-addr.arpa/IN/internal:
> loaded serial 1
> Aug 18 19:49:31 gw named[15560]: zone 222.168.192.in-addr.arpa/IN/internal:
> loaded serial 1
> Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/internal: loaded serial
> 2008060101
> Aug 18 19:49:31 gw named[15560]: zone localhost/IN/internal: loaded serial 1
> Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/external: loaded serial
> 2008052901
> Aug 18 19:49:31 gw named[15560]: running
> Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/internal: sending notifies
> (serial 2008060101)
> Aug 18 19:49:31 gw named[15560]: zone stare.cz/IN/external: sending notifies
> (serial 2008052901)
> Aug 18 19:49:31 gw named[15560]: client 79.98.73.150#7375: view external:
> received notify for zone 'stare.cz'
> Aug 18 19:49:31 gw ntpd[26108]: ntp engine ready
The timestamp when named spoke again
is the same time when ntpd said 'ntp engine ready'.
It is started as 'ntpd -s'; is there any interaction between ntpd and
named during startup, or is this just a coincidence?
> Aug 18 19:49:31 gw named[15560]: Binding locally
> # This message keeps appearing in the log even after bootup.
>
> Aug 18 19:49:32 gw last message repeated 3 times
> Aug 18 19:49:33 gw ntpd[13902]: set local clock to Mon Aug 18 19:49:33 CEST
> 2008 (offset 1.270602s)
> Aug 18 19:49:34 gw savecore: /dev/wd0b: Device not configured
> Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.167.167.1 port 2222.
> Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.168.222.1 port 22.
> Aug 18 19:49:37 gw sshd[9870]: Server listening on 192.168.111.1 port 22.
> Aug 18 19:49:37 gw cron[26797]: (CRON) STARTUP (V5.0)
> Aug 18 19:49:39 gw postfix/postfix-script[31730]: starting the Postfix mail
> system
> Aug 18 19:49:39 gw postfix/master[29430]: daemon started -- version 2.5.1,
> configuration /etc/postfix
> Aug 18 19:49:49 gw login: ROOT LOGIN (root) ON tty00
> Aug 18 19:49:52 gw ntpd[26108]: peer 147.251.48.140 now valid
> Aug 18 19:49:54 gw ntpd[26108]: peer 84.242.87.238 now valid
> Aug 18 19:49:57 gw ntpd[26108]: peer 212.71.128.157 now valid
> Aug 18 19:50:08 gw named[15560]: Binding locally
> Aug 18 19:50:09 gw last message repeated 2 times
> Aug 18 19:52:28 gw last message repeated 3 times
> Aug 18 19:54:28 gw last message repeated 4 times
> Aug 18 19:55:05 gw ntpd[26108]: clock is now synced
> Aug 18 19:56:31 gw named[15560]: Binding locally
> Aug 18 19:56:54 gw last message repeated 10 times
> 2. Why does BIND keep 'binding locally'?
Thanks
Jan
