named startup problems upgrading from 7.1p4 to 7.1p5 or 7.1p6

[no-spam at people.net.au]

Sorry for starting a new thread with this - my ISP's mail server seems to rejecting all mail recipients when I 
send email with a mail client, so I'm having to use webmail instead. Their tech says they won't help - they 
only support Outlook! Grrr!

On Sun, 28 Jun 2009 23:27:07 Matthew Seaman wrote:
> Ian wrote:
> > Well the fact that if I run  /etc/rc.d/named manually after the system
> > has booted, the script also hangs suggests it's not the next process I
> > have just check however & ntpdate is the next one in the list to be
> > started and that does start correctly - you can see it report the clock
> > being adjusted. Also, when you do a Ctrl+C to break the named script on
> > bootup, it says "Script /etc/rc.d/named interrupted".
> >
> > Something I've just realised is that named stays loaded even when you
> > 'break' the script. on bootup and DNS lookups work (I didn't think that
> > was the case originally, but it is).

Actually, some careful checking tonight shows that I had forgotten I had a 
second DNS server in resolv.conf that was doing the DNS resolution - in fact 
bind on this server is not working even though a bind process appears to be 
running :/

> Hmmm....
>
> Anything interesting from named in the system logs?  You might want to
> enable /var/log/all.log by following the instructions in /etc/syslog.conf
> and then see what output you get by bouncing named.  It's usually pretty
> good at pointing out exactly what it thinks the problem is.

I've enabled all.log, it only shows the following output when starting named:
Jun 29 20:51:43 msgserver named[1593]: starting BIND 9.4.2-P2 -t /var/named -u 
bind
Jun 29 20:51:43 msgserver named[1593]: found 1 CPU, using 1 worker thread

a ps axw | grep named gives the following output after running /etc/rc.d/named 
start:
 1988  ??  Is     0:00.00 /usr/sbin/named -t /var/named -u bind
 1930  p0  I+     0:00.06 /bin/sh -x /etc/rc.d/named start
 1987  p0  I+     0:00.01 /usr/sbin/named -t /var/named -u bind

and then after doing a Ctrl+C in the terminal where /etc/rc.d/named start is 
running, only one process continues to run:
 1988  ??  Is     0:00.00 /usr/sbin/named -t /var/named -u bind

This process doesn't respond to DNS queries, to rndc commands, 
to /etc/rc.d/named stop (says no process is running because there is no pid 
file being created) or by a kill command other than kill -9.
(All named processes were killed before stating named)

>
> You could also try running:
>
>    # /bin/sh -x /etc/rc.d/named start


> -- make sure named isn't running when you do that.  There will be quite
> a lot of output as the rc system loads all of the various config files,
> but you should be able to trace exactly where it's got to when it does
> hang.

Here's the edited highlights of output, I can't see anything that helps:
> + _rc_subr_loaded=:
> + name=named
> + rcvar=named_enable
> + command=/usr/sbin/named
> + extra_commands=reload
> + start_precmd=named_precmd
> + start_postcmd=make_symlinks
> + reload_cmd=named_reload
> + stop_cmd=named_stop
> + stop_postcmd=named_poststop
> + load_rc_config named
> + _name=named
> + [ -z named ]
> + false
> + [ -r /etc/defaults/rc.conf ]
>
> <snip>
>
> + named_enable=NO
> + named_program=/usr/sbin/named
> + named_pidfile=/var/run/named/pid
> + named_uid=bind
> + named_chrootdir=/var/named
> + named_chroot_autoupdate=YES
> + named_symlink_enable=YES
>
> <snip>
>
> + sourced_files=:/etc/rc.conf::/etc/rc.conf.local:
> + [ -r /etc/rc.conf.local ]
> + _rc_conf_loaded=true
> + [ -f /etc/rc.conf.d/named ]
> + required_dirs=/var/named
> + pidfile=/var/run/named/pid
> + command_args=-u bind
> + run_rc_command start
> + _return=0
> + rc_arg=start
> + [ -z named ]
> + shift 1
> + rc_extra_args=
> + _rc_prefix=
> + eval _override_command=$named_program
> + _override_command=/usr/sbin/named
> + command=/usr/sbin/named
> + _keywords=start stop restart rcvar reload
> + rc_pid=
> + _pidcmd=
> + _procname=/usr/sbin/named
> + [ -n /usr/sbin/named ]
> + [ -n /var/run/named/pid ]
> + _pidcmd=rc_pid=$(check_pidfile /var/run/named/pid /usr/sbin/named )
> + [ -n rc_pid=$(check_pidfile /var/run/named/pid /usr/sbin/named ) ]
> + _keywords=start stop restart rcvar reload status poll
> + [ -z start ]
> + [ -n  ]
> + eval rc_flags=$named_flags
> + rc_flags=
> + eval _chdir=$named_chdir _chroot=$named_chroot _nice=$named_nice
> _user=$named_user _group=$named_group _groups=$named_groups
> + _chdir= _chroot= _nice= _user= _group= _groups=
> + [ -n  ]
> + [ -n named_enable -a start != rcvar ]
> + checkyesno named_enable
> + eval _value=$named_enable
> + _value=YES
> + debug checkyesno: named_enable is set to YES.
> + return 0
> + eval rc_pid=$(check_pidfile /var/run/named/pid /usr/sbin/named )
> + check_pidfile /var/run/named/pid /usr/sbin/named
> + _pidfile=/var/run/named/pid
> + _procname=/usr/sbin/named
> + _interpreter=
> + [ -z /var/run/named/pid -o -z /usr/sbin/named ]
> + [ ! -f /var/run/named/pid ]
> + debug pid file (/var/run/named/pid): not readable.
> + return
> + rc_pid=
> + [ start != start ]
> + eval _cmd=$start_cmd _precmd=$start_precmd _postcmd=$start_postcmd
> + _cmd= _precmd=named_precmd _postcmd=make_symlinks
> + [ -n  ]
> + [ -z  -a -n  ]
> + [ ! -x /usr/sbin/named ]
> + _run_rc_precmd
> + check_required_before start
> + local _f
> + [ ! -d /var/named/. ]
> + return 0
> + [ -n named_precmd ]
> + debug run_rc_command: start_precmd: named_precmd
> + eval named_precmd
> + named_precmd
> + [ -n /var/named ]
> + rc_flags= -t /var/named
> + checkyesno named_chroot_autoupdate
> + eval _value=$named_chroot_autoupdate
> + _value=YES
> + debug checkyesno: named_chroot_autoupdate is set to YES.
> + return 0
> + chroot_autoupdate
> + [ -r /etc/mtree/BIND.chroot.dist ]
> + mtree -deU -f /etc/mtree/BIND.chroot.dist -p /var/named
> + [ ! -L /etc/namedb ]
> + ln -shf /var/named/etc/namedb /etc/namedb
> + umount /var/named/dev
> + devfs_domount /var/named/dev devfsrules_hide_all
> + local devdir rs _me
> + devdir=/var/named/dev
> + [ -n devfsrules_hide_all ]
> + rs=devfsrules_hide_all
> + _me=devfs_domount()
> + [ -z /var/named/dev ]
> + debug devfs_domount(): mount-point is (/var/named/dev), ruleset is
>
> <snip> (whole lot of devfs stuff)
>
> + devfs_set_ruleset devfsrules_hide_all /var/named/dev
> + local devdir rs _me
> + [ -n devfsrules_hide_all ]
> + eval rs=$devfsrules_hide_all
> + rs=1
> + [ -n /var/named/dev ]
> + devdir=-m /var/named/dev
> + _me=devfs_set_ruleset
> + [ -z 1 ]
> + debug devfs_set_ruleset: setting ruleset (1) on mount-point
> (/var/named/dev) + /sbin/devfs -m /var/named/dev ruleset 1
> + return 0
> + devfs -m /var/named/dev rule applyset
> + return 0
> + devfs -m /var/named/dev rule apply path null unhide
> + devfs -m /var/named/dev rule apply path random unhide
> + [ -r /etc/localtime ]
> + cmp -s /etc/localtime /var/named/etc/localtime
> + [ -s /var/named/etc/namedb/rndc.conf ]
> + return 0
> + _return=0
> + [ 0 -ne 0 ]
> + check_required_after start
> + local _f _args
> + return 0
> + return 0
> + echo Starting named.
> Starting named.
> + [ -n  ]
> + _doit=/usr/sbin/named  -t /var/named -u bind
> + [ -n  ]
> + [ -n  ]
> + _run_rc_doit /usr/sbin/named  -t /var/named -u bind
> + debug run_rc_command: doit: /usr/sbin/named  -t /var/named -u bind
> + eval /usr/sbin/named  -t /var/named -u bind
> + /usr/sbin/named -t /var/named -u bind


and that's where it hangs! The only thing that looks vaguely like an error to 
me is about halfway down: + debug pid file (/var/run/named/pid): not 
readable. 
There is no /var/run/named/pid file being created, but then named isn't 
loading properly, so it may not be an issue.

>
> You're using the system-supplied copy of bind aren't you?  Have you got
> a valid /etc/named/rndc.conf or /etc/named/rndc.key file so you can use
> rndc(8)?  If not, try running:
>
>     # rndc-confgen > /etc/namedb/rndc.conf
>
> and then cut'n'paste the indicated key and controls statements from that
> file into named.conf, stripping out the comment characters as you do (of
> course).

Yes, it's the system supplied version & yes I have a  /etc/named/rndc.key that 
I assume is valid - I could run rndc commands in p4 (and still can if I 
rollback to that version).
I've generated a new rndc.conf (having renamed rndc.key) to see that helps, 
but it doesn't.

Running any rndc command (like rndc status or rndc debug) causes rndc to load 
and hang, the only way to kill it is with a kill -9, Ctrl+C or Ctrl+D don't 
work. The same applies if I just run /usr/sbin/named -t /var/named -u bind.


I'm beginning to think there is something wrong with my named.conf or zone 
files or dynamic update config, though they work just fine in -p4.

Cheers,
 
Ian