[syslog-ng]kernel source breaks reload on NetBSD

[Ed Ravin]

syslog-ng has some scary behavior when I have a source kernel { } in
my syslog-ng.conf on NetBSD 1.5.x/i386.  The results below are for
syslog-ng 1.5.21, but this isn't a new problem since it also happens
with 1.5.16.

My configuration has a socket to the central server, two unix-dgram
sockets (/var/run/log and a second /var/run/log in a chroot), incoming
TCP sockets from a couple of other servers running syslog-ng, and
several file destinations (in /var/log, similiar to a normal syslogd
config file).  There's also a /dev/console and usertty output, again
trying to emulate regular syslogd.

When I had this source in the config file:

 source kernel {
       file("/dev/klog");
 };

syslog-ng started up properly, although with the annoying message:

       Changing permissions on special file /dev/klog

and created all the file destinations and the socket to the central server.
But when the daemon got HUP'd for rotation of the local logs, things
went awry.  The "Changing permissions" message reappeared and the file
destinations to /var/log/xxxx were closed and not re-opened.  Logging
continued to the central server, but none of the local files were written.

I took out the "source kernel" statement and HUP now works properly,
without losing the local output files.

A ktrace of the buggy configuration shows that syslog-ng is doing something
very weird with all of its file sources - upon HUP, the unix-dgram sockets 
are closed and re-opened twice (!), the kernel source is also re-opened twice,
and the local file destinations are never re-opened.

Here's an annotated highlights of the ktrace of the buggy HUP:

 27793 syslog-ng PSIG  SIGHUP caught handler=0x8049f40 mask=() code=0x0
[...]
 27793 syslog-ng CALL  open(0x480ed515,0,0x1b6)
 27793 syslog-ng NAMI  "/etc/resolv.conf"
[...]
 27793 syslog-ng CALL  open(0x8059b60,0,0x1b6)
 27793 syslog-ng NAMI  "/etc/syslog-ng.conf"

[ re-reads config file ]

[ closes most of the existing file descriptors ]
 27793 syslog-ng CALL  close(0x11)       # TCP socket from client
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x10)       # TCP socket from 2nd client
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x6)        # TCP socket listening for clients
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x5)        # unix-dgram input
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x3)        # unix-dgram input
 27793 syslog-ng RET   close 0

[ unlink, bind, then chown and chmod /var/run/log unix-dgram input ]

[ unlink, bind, then chown and chmod /var/chroot/var/run/log unix-dgram input ]

[ this is weird - says it's changing permissions, but doesn't actually
  do anything ]

 27793 syslog-ng CALL  write(0x2,0xbfbfd4b0,0x2f)
 27793 syslog-ng GIO   fd 2 wrote 47 bytes
       "Changing permissions on special file /dev/klog
       "
 27793 syslog-ng RET   write 47/0x2f

[ now syslog-ng tries to re-open /dev/klog before closing it, which
 doesn't work on NetBSD since the device is allowed for only one user
 at a time ]

 27793 syslog-ng CALL  open(0x8069e68,0x8004,0x180)
 27793 syslog-ng NAMI  "/dev/klog"
 27793 syslog-ng RET   open -1 errno 16 Device busy
 27793 syslog-ng CALL  issetugid
 27793 syslog-ng RET   issetugid 0

[.. call C library to print error message ]

 27793 syslog-ng CALL  write(0x2,0xbfbfd548,0x37)
 27793 syslog-ng GIO   fd 2 wrote 55 bytes
       "Error opening file /dev/klog for reading (Device busy)

 27793 syslog-ng CALL  close(0xf)   #  /var/log/cron
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0xe)   #  /var/log/maillog
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0xd)   #  /var/log/authlog
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0xc)   #  /var/log/daemon.log
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0xb)   #  /var/log/notices
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0xa)   #  /var/log/messages
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x9)   #  /dev/console
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x4)   #  /var/log/poplog
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x8)   #  TCP socket to central server
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x7)   #  /dev/klog
 27793 syslog-ng RET   close 0

[ these file descriptors are already closed (see above), but
  syslog-ng tries to close them a second time ]

 27793 syslog-ng CALL  close(0x6)
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x5)
 27793 syslog-ng RET   close 0
 27793 syslog-ng CALL  close(0x3)
 27793 syslog-ng RET   close 0

[ For a second time, unlinks, binds, chown, then chmod the two
  unix-dgram sockets ]

 27793 syslog-ng CALL  socket(0x1,0x2,0)
 27793 syslog-ng RET   socket 3
[...]
 27793 syslog-ng CALL  __stat13(0xbfbfd8d2,0xbfbfd870)
 27793 syslog-ng NAMI  "/var/run/log"
[...]
 27793 syslog-ng CALL  __stat13(0xbfbfd8d2,0xbfbfd870)
 27793 syslog-ng NAMI  "/var/chroot/var/run/log"

[ recreates the TCP listening socket ]

[ re-opens /dev/klog  - note that it starts with the permissions
  message, yet doesn't seem to actually call chmod() anywhere ]

 27793 syslog-ng CALL  write(0x2,0xbfbfd4b0,0x2f)
 27793 syslog-ng GIO   fd 2 wrote 47 bytes
       "Changing permissions on special file /dev/klog
       "
 27793 syslog-ng RET   write 47/0x2f
 27793 syslog-ng CALL  open(0x805c088,0x8004,0x180)
 27793 syslog-ng NAMI  "/dev/klog"
 27793 syslog-ng RET   open 6
 27793 syslog-ng CALL  lseek(0x6,0,0,0,0x2)
 27793 syslog-ng RET   lseek 0
 27793 syslog-ng CALL  fcntl(0x6,0x3,0x6)
 27793 syslog-ng RET   fcntl 4
 27793 syslog-ng CALL  fcntl(0x6,0x4,0x4)
 27793 syslog-ng RET   fcntl 0
 27793 syslog-ng CALL  fcntl(0x6,0x2,0x1)
 27793 syslog-ng RET   fcntl 0

[ recreates the TCP socket to the central server ]

 27793 syslog-ng CALL  socket(0x2,0x1,0x6)
 27793 syslog-ng RET   socket 7
[...]
 27793 syslog-ng CALL  connect(0x7,0xbfbfd924,0x10)
 27793 syslog-ng RET   connect -1 errno 36 Operation now in progress

Note that the file destinations which were closed were never re-opened.
At this point, syslog-ng begins to receive log messages from the
usual sources and relay them all to the central server, as if the
file destinations were never defined in the first place.  lsof from
before and after the HUP confirms that the file destinations were never
re-opened.

Oh, one more note - I ktrace'd the working configuration, without
the kernel source, and the unix-dgram sockets did NOT get re-opened
twice as in the above ktrace.  Curiouser and curiouser.

Baszi?  What's going on?