Re: Logging oddity from FreeBSD

On Thu, Oct 25, 2007 at 05:46:34PM -0700, Tina Bird wrote:

> If I assume the obvious place for the break --
> 
> Jun 13 00:57:57 <hostname> kernel: 
> 
> Jun 13 00:57:57 <hostname> named[45636]: transfer of 'example.com/IN' from
> xyz.xyz.xyz.xyz#53: failed to connect: timed out
> 
> Why in the world would the kernel write an empty messager like that? The
> only thing I can come up with (and it's completely unconvincing to me, so I
> assume it's pretty far wrong) is that whatever weirdness happened with the
> linewrap caused the second message to overwrite part of the first message.

I have seen this something similar elsewhere with a different vendor's
*nix + modified kernel (hi, Marcus) + syslogd.  It tended to happen
when the system was busy and logging a *lot* of messages at the kernel
level.  On some *nix systems, logging from kernel space to user space
happens by way of a circular buffer.  I think what happens is that the
kernel is producing logs faster than userspace can actually read them,
so syslogd/klogd gets partial messages at the wraparound point.

You should be able to sim/stim this by setting up a system with a
firewall that does a lot of logging from kernel space, no rate
limiting for the logging, loading up the system with some CPU-hogging
and IO-hogging processes, and throwing a wide variety of bad traffic
at it really fast, for a while.  The kernel log buffer will fill up,
and then syslogd will start reading partial lines.

Oh, and you've made certain that there aren't vt100 or ANSI escapes
that are playing cursor games, right?

- Morty