This site is now 100% read-only, and retired.

XML logo

Lenny Bind9 takes 5 minutes to restart?
Posted by muondude on Thu 23 Apr 2009 at 20:10
I recently upgraded from etch to lenny. I then found that bind "seems" to be working but is acting strange. Here's some output from the process start and stop and the /etc/bind9 config file list. Note that the "start" after stopping can take up to 5 minutes.

I'm running on a Mac Mini (PPC version). All other processes (mail, web) seem to be working okay.

Thoughts on why this is occurring?

-- Sam



ls -l /etc/bind
-rw-r--r-- 1 root root 237 2007-01-29 06:00 db.0
-rw-r--r-- 1 root root 271 2007-01-29 06:00 db.127
-rw-r--r-- 1 root bind 959 2009-03-05 18:24 db.168.192
-rw-r--r-- 1 root root 237 2007-01-29 06:00 db.255
-rw-r--r-- 1 root root 353 2007-01-29 06:00 db.empty
-rw-r--r-- 1 root bind 1337 2009-04-22 09:39 db.gasster
-rw-r--r-- 1 root root 270 2009-03-18 20:39 db.local
-rw-r--r-- 1 root root 2878 2009-03-18 20:39 db.root
-rw-r--r-- 1 root bind 907 2009-03-18 20:39 named.conf
-rw-r--r-- 1 root bind 851 2008-01-03 15:08 named.conf.local
-rw-r--r-- 1 root bind 1253 2009-04-22 08:47 named.conf.options
-rw-r--r-- 1 root bind 572 2009-03-18 20:39 named.conf.options.dpkg-dist
-rw-r----- 1 bind bind 77 2007-04-16 22:44 rndc.key
-rw-r--r-- 1 root root 1317 2007-01-29 06:00 zones.rfc1918


<cut>


# sh -x /etc/init.d/bind9 stop
+ PATH=/sbin:/bin:/usr/sbin:/usr/bin
+ OPTIONS=
+ RESOLVCONF=no
+ test -f /etc/default/bind9
+ . /etc/default/bind9
++ OPTIONS='-u bind'
++ RESOLVCONF=yes
+ test -x /usr/sbin/rndc
+ . /lib/lsb/init-functions
++ FANCYTTY=
++ '[' -e /etc/lsb-base-logging.sh ']'
++ true
++ lsb_release -is
++ echo Debian
+ DISTRO=Debian
+ PIDFILE=/var/run/bind/run/named.pid
+ case "$1" in
+ log_daemon_msg 'Stopping domain name service...' bind9
+ '[' -z 'Stopping domain name service...' ']'
+ log_daemon_msg_pre 'Stopping domain name service...' bind9
+ :
+ '[' -z bind9 ']'
+ echo -n 'Stopping domain name service...: bind9'
Stopping domain name service...: bind9+ log_daemon_msg_post 'Stopping domain name service...' bind9
+ :
+ check_network
+ '[' -x /usr/bin/uname ']'
+ IFCONFIG_OPTS=
++ /sbin/ifconfig
+ '[' -z 'eth1 Link encap:Ethernet HWaddr 00:11:24:77:0b:b8
inet addr:192.168.2.3 Bcast:192.168.2.255 Mask:255.255.255.0
inet6 addr: fe80::211:24ff:fe77:bb8/64 Scope:Link
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:123706 errors:0 dropped:0 overruns:0 frame:0
TX packets:67968 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:22298030 (21.2 MiB) TX bytes:12382456 (11.8 MiB)
Interrupt:41 Base address:0x5400

lo Link encap:Local Loopback
inet addr:127.0.0.1 Mask:255.0.0.0
inet6 addr: ::1/128 Scope:Host
UP LOOPBACK RUNNING MTU:16436 Metric:1
RX packets:50750 errors:0 dropped:0 overruns:0 frame:0
TX packets:50750 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:10115571 (9.6 MiB) TX bytes:10115571 (9.6 MiB)' ']'
+ return 0
+ '[' Xyes '!=' Xno ']'
+ '[' -x /sbin/resolvconf ']'
++ /usr/sbin/rndc stop -p
++ awk '/^pid:/ {print $2}'
+ pid=8435
+ '[' -n 8435 ']'
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_progress_msg 'waiting for pid 8435 to die'
+ '[' -z 'waiting for pid 8435 to die' ']'
+ echo -n ' waiting for pid 8435 to die'
waiting for pid 8435 to die+ sleep 1
+ kill -0 8435
+ log_end_msg 0
+ '[' -z 0 ']'
+ retval=0
+ log_end_msg_pre 0
+ :
+ log_use_fancy_output
+ TPUT=/usr/bin/tput
+ EXPR=/usr/bin/expr
+ '[' -t 1 ']'
+ '[' xxterm '!=' '' ']'
+ '[' xxterm '!=' xdumb ']'
+ '[' -x /usr/bin/tput ']'
+ '[' -x /usr/bin/expr ']'
+ /usr/bin/tput hpa 60
+ /usr/bin/tput setaf 1
+ '[' -z ']'
+ FANCYTTY=1
+ case "$FANCYTTY" in
+ true
++ /usr/bin/tput setaf 1
+ RED=''
++ /usr/bin/tput setaf 3
+ YELLOW=''
++ /usr/bin/tput op
+ NORMAL=''
+ '[' 0 -eq 0 ']'
+ echo .
.
+ log_end_msg_post 0
+ :
+ return 0
+ exit 0

------
# sh -x /etc/init.d/bind9 start
+ PATH=/sbin:/bin:/usr/sbin:/usr/bin
+ OPTIONS=
+ RESOLVCONF=no
+ test -f /etc/default/bind9
+ . /etc/default/bind9
++ OPTIONS='-u bind'
++ RESOLVCONF=yes
+ test -x /usr/sbin/rndc
+ . /lib/lsb/init-functions
++ FANCYTTY=
++ '[' -e /etc/lsb-base-logging.sh ']'
++ true
++ lsb_release -is
++ echo Debian
+ DISTRO=Debian
+ PIDFILE=/var/run/bind/run/named.pid
+ case "$1" in
+ log_daemon_msg 'Starting domain name service...' bind9
+ '[' -z 'Starting domain name service...' ']'
+ log_daemon_msg_pre 'Starting domain name service...' bind9
+ :
+ '[' -z bind9 ']'
+ echo -n 'Starting domain name service...: bind9'
Starting domain name service...: bind9+ log_daemon_msg_post 'Starting domain name service...' bind9
+ :
+ modprobe capability
+ true
+ mkdir -p /var/run/bind/run
+ chmod 775 /var/run/bind/run
+ chown root:bind /var/run/bind/run
+ '[' '!' -x /usr/sbin/named ']'
+ check_network
+ '[' -x /usr/bin/uname ']'
+ IFCONFIG_OPTS=
++ /sbin/ifconfig
+ '[' -z 'eth1 Link encap:Ethernet HWaddr 00:11:24:77:0b:b8
inet addr:192.168.2.3 Bcast:192.168.2.255 Mask:255.255.255.0
inet6 addr: fe80::211:24ff:fe77:bb8/64 Scope:Link
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:124259 errors:0 dropped:0 overruns:0 frame:0
TX packets:68338 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:22365956 (21.3 MiB) TX bytes:12435929 (11.8 MiB)
Interrupt:41 Base address:0x5400

lo Link encap:Local Loopback
inet addr:127.0.0.1 Mask:255.0.0.0
inet6 addr: ::1/128 Scope:Host
UP LOOPBACK RUNNING MTU:16436 Metric:1
RX packets:50834 errors:0 dropped:0 overruns:0 frame:0
TX packets:50834 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:10122909 (9.6 MiB) TX bytes:10122909 (9.6 MiB)' ']'
+ return 0
+ start-stop-daemon --start --oknodo --quiet --exec /usr/sbin/named --pidfile /var/run/bind/run/named.pid -- -u bind
+ '[' Xyes '!=' Xno ']'
+ '[' -x /sbin/resolvconf ']'
+ log_end_msg 0
+ '[' -z 0 ']'
+ retval=0
+ log_end_msg_pre 0
+ :
+ log_use_fancy_output
+ TPUT=/usr/bin/tput
+ EXPR=/usr/bin/expr
+ '[' -t 1 ']'
+ '[' xxterm '!=' '' ']'
+ '[' xxterm '!=' xdumb ']'
+ '[' -x /usr/bin/tput ']'
+ '[' -x /usr/bin/expr ']'
+ /usr/bin/tput hpa 60
+ /usr/bin/tput setaf 1
+ '[' -z ']'
+ FANCYTTY=1
+ case "$FANCYTTY" in
+ true
++ /usr/bin/tput setaf 1
+ RED=''
++ /usr/bin/tput setaf 3
+ YELLOW=''
++ /usr/bin/tput op
+ NORMAL=''
+ '[' 0 -eq 0 ']'
+ echo .
.
+ log_end_msg_post 0
+ :
+ return 0
+ exit 0

# /etc/init.d/bind9 status
bind9 is running.

bind 8646 0.0 4.0 57212 20864 ? Ssl 12:00 0:00 /usr/sbin/named -u bind


Finally -- Some syslog output

Apr 23 11:58:02 lithium named[8435]: received control channel command 'stop -p'
Apr 23 11:58:07 lithium named[8435]: shutting down: flushing changes
Apr 23 11:58:12 lithium named[8435]: stopping command channel on 127.0.0.1#953
Apr 23 11:58:17 lithium named[8435]: no longer listening on ::#53
Apr 23 11:58:22 lithium named[8435]: no longer listening on 127.0.0.1#53
Apr 23 11:58:29 lithium named[8435]: no longer listening on 192.168.2.3#53
Apr 23 11:58:34 lithium named[8435]: exiting
Apr 23 12:00:16 lithium named[8646]: starting BIND 9.5.1-P1 -u bind
Apr 23 12:00:26 lithium named[8646]: found 1 CPU, using 1 worker thread
Apr 23 12:00:36 lithium named[8646]: using up to 4096 sockets
Apr 23 12:00:46 lithium named[8646]: loading configuration from '/etc/bind/named.conf'
Apr 23 12:00:56 lithium named[8646]: max open files (1024) is smaller than max sockets (4096)
Apr 23 12:01:06 lithium named[8646]: using default UDP/IPv4 port range: [1024, 65535]
Apr 23 12:01:16 lithium named[8646]: using default UDP/IPv6 port range: [1024, 65535]
Apr 23 12:01:27 lithium named[8646]: listening on IPv6 interfaces, port 53
Apr 23 12:01:37 lithium named[8646]: listening on IPv4 interface lo, 127.0.0.1#53
Apr 23 12:01:47 lithium named[8646]: listening on IPv4 interface eth1, 192.168.2.3#53
Apr 23 12:01:57 lithium named[8646]: automatic empty zone: view external: 254.169.IN-ADDR.ARPA
Apr 23 12:02:07 lithium named[8646]: automatic empty zone: view external: 2.0.192.IN-ADDR.ARPA
Apr 23 12:02:17 lithium named[8646]: automatic empty zone: view external: 255.255.255.255.IN-ADDR.ARPA
Apr 23 12:02:27 lithium named[8646]: automatic empty zone: view external: 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
Apr 23 12:02:37 lithium named[8646]: automatic empty zone: view external: 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
Apr 23 12:02:47 lithium named[8646]: automatic empty zone: view external: D.F.IP6.ARPA
Apr 23 12:02:58 lithium named[8646]: automatic empty zone: view external: 8.E.F.IP6.ARPA
Apr 23 12:03:08 lithium named[8646]: automatic empty zone: view external: 9.E.F.IP6.ARPA
Apr 23 12:03:18 lithium named[8646]: automatic empty zone: view external: A.E.F.IP6.ARPA
Apr 23 12:03:28 lithium named[8646]: automatic empty zone: view external: B.E.F.IP6.ARPA
Apr 23 12:03:38 lithium named[8646]: automatic empty zone: view internal: 254.169.IN-ADDR.ARPA
Apr 23 12:03:48 lithium named[8646]: automatic empty zone: view internal: 2.0.192.IN-ADDR.ARPA
Apr 23 12:03:58 lithium named[8646]: automatic empty zone: view internal: 255.255.255.255.IN-ADDR.ARPA
Apr 23 12:04:08 lithium named[8646]: 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
Apr 23 12:04:18 lithium named[8646]: 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
Apr 23 12:04:28 lithium named[8646]: automatic empty zone: view internal: D.F.IP6.ARPA
Apr 23 12:04:39 lithium named[8646]: automatic empty zone: view internal: 8.E.F.IP6.ARPA
Apr 23 12:04:49 lithium named[8646]: automatic empty zone: view internal: 9.E.F.IP6.ARPA
Apr 23 12:04:59 lithium named[8646]: automatic empty zone: view internal: A.E.F.IP6.ARPA
Apr 23 12:05:09 lithium named[8646]: automatic empty zone: view internal: B.E.F.IP6.ARPA
Apr 23 12:05:19 lithium named[8646]: command channel listening on 127.0.0.1#953
Apr 23 12:05:29 lithium named[8646]: zone 0.in-addr.arpa/IN/external: loaded serial 1
Apr 23 12:05:39 lithium named[8646]: zone 127.in-addr.arpa/IN/external: loaded serial 1
Apr 23 12:05:44 lithium named[8646]: zone 255.in-addr.arpa/IN/external: loaded serial 1
Apr 23 12:05:49 lithium named[8646]: zone localhost/IN/external: loaded serial 2
Apr 23 12:05:54 lithium named[8646]: zone 0.in-addr.arpa/IN/internal: loaded serial 1
Apr 23 12:05:59 lithium named[8646]: zone 127.in-addr.arpa/IN/internal: loaded serial 1
Apr 23 12:06:09 lithium named[8646]: zone 168.192.in-addr.arpa/IN/internal: loaded serial 20080103
Apr 23 12:06:14 lithium named[8646]: zone 255.in-addr.arpa/IN/internal: loaded serial 1
Apr 23 12:06:24 lithium named[8646]: zone gasster.com/IN/internal: loaded serial 20080103
Apr 23 12:06:29 lithium named[8646]: zone localhost/IN/internal: loaded serial 2
Apr 23 12:06:34 lithium named[8646]: running
__end __

 

Comments on this Entry

Re: Lenny Bind9 takes 5 minutes to restart?
Posted by rossen (212.147.xx.xx) on Fri 24 Apr 2009 at 13:40
[ View Weblogs ]
I had a similar difficulty with bind9 on a small Lenny system.

The problem came from the (optional) program lsb_release that is called by the bind9 startup script.

lsb_release checks the version level of the system by running apt-cache. If there are lots of package lists in /etc/apt/sources, not much RAM in the system, and the main file system on a compact flash, apt-cache is terribly slow and the bind9 startup takes "forever".

There were two ways of getting rid of the problem:

1. deinstall lsb-release since it is optional

2. put only essential package lists in /etc/apt/sources.list

[ Parent ]

Re: Lenny Bind9 takes 5 minutes to restart?
Posted by Anonymous (81.5.xx.xx) on Fri 24 Apr 2009 at 15:59
not sure what it does with DISTRO which is set from there though.

the waiting stuff I can explain (since I wrote it). the restart used to do "call stop, (wait 2 secs)?, start". this meant that occasionally it would start before it had finished stopping and hence leave you with no bind :(

it seems to be taking about 20 seconds to die for you - I wonder why.

[ Parent ]

Re: Lenny Bind9 takes 5 minutes to restart?
Posted by suspended user muondude (206.117.xx.xx) on Sat 25 Apr 2009 at 06:07
[ View Weblogs ]
The sh -x /etc/init.d/bind9 stop
only takes a few seconds to complete.
The sh -x /etc/init.d/bind9 start seems to hang on the
+ start-stop-daemon --start --oknodo --quiet --exec /usr/sbin/named --pidfile /var/run/bind/run/named.pid -- -u bind
command.

I ran aptitude and lsb_release isn't installed (? p). I also did an aptitude autoclean. and the bind9 start still takes ... a very long time - over 5 minutes! .... and
seems to hang and the start-stop-daemon command.

But once running it seems to be working okay.

[ Parent ]

Re: Lenny Bind9 takes 5 minutes to restart?
Posted by Anonymous (67.162.xx.xx) on Tue 12 May 2009 at 14:37
Is named listening on an interface that bind9 is not communicating on? By default named is on lo. Is bind9 on a different interface and unable to communicate with named?

[ Parent ]

Re: Lenny Bind9 takes 5 minutes to restart?
Posted by cvenn (89.240.xx.xx) on Wed 17 Mar 2010 at 12:28
Did you ever find the solution?
I'm running Lenny (was on Etch and that had the same problem).
I notice that you have a consistent time delay between each log entry.
I'm getting exactly 15 seconds delay between log entries and it is taking 10 minutes to start bind9.
This only happens if I stop/restart bind when the system is running. During a normal boot it starts much faster.

[ Parent ]

Re: Lenny Bind9 takes 5 minutes to restart?
Posted by Anonymous (188.64.xx.xx) on Mon 6 Sep 2010 at 09:09
The problem is in /etc/network/if-up.d/bind9. It tries to run `rndc reconfigure` everytime an interface is brough up, and fails with connection timeout when lo is down (happens if eth0 is brough up before lo). I just deleted this script because it's pontless in my case.

[ Parent ]