split entries from syslogd

[Stuart Henderson]

I updated some firewalls to -current yesterday (from somewhere between
5.6 and 5.7) and am now seeing a lot of "arp: attempt to add entry"
logged, see below. (Looks like someone has put a machine on the wrong
vlan and it's sending out broadcast arp replies for conflict detection
which are triggering the logs, anyway that's a different problem).

Some of the lines in the logged file get split in half. I'm thinking
this probably warrants further investigation as it could cause log
monitoring programs to not notice certain problems..

I've tried ktracing the syslogd process, but haven't seen the splitting
show itself in that case, though it happens fairly often when it's not
being ktraced.

Any ideas or suggestions for additional debugging to try and track it
down further?

$ tail /var/log/messages
Feb 11 09:29:18 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on vlan411
Feb 11 09:29:18 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on carp411
Feb 11 09:29:19 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on vlan411
Feb 11 09:29:19 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by
Feb 11 09:29:19 fw1 /bsd: 00:26:b9:5d:24:e7 on carp411
Feb 11 09:29:20 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on vlan411
Feb 11 09:29:20 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on carp411
Feb 11 09:29:23 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on vlan411
Feb 11 09:29:23 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on carp411

Other examples of the splitting:

Feb 11 09:30:10 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on car
Feb 11 09:30:10 fw1 /bsd: p411
Feb 11 09:30:13 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on ca
Feb 11 09:30:13 fw1 /bsd: rp411
Feb 11 09:31:15 fw1 /bsd: arp: attempt to add entry for 192.168.43.
Feb 11 09:31:15 fw1 /bsd: 131 on carp432 by 00:26:b9:5d:24:e7 on carp411
Feb 11 09:31:53 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432
Feb 11 09:31:53 fw1 /bsd: by 00:26:b9:5d:24:e7 on carp411
Feb 11 09:35:09 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00
Feb 11 09:35:09 fw1 /bsd: :26:b9:5d:24:e7 on carp411
Feb 11 09:37:54 fw1 /bsd: arp: attempt to add entry for
Feb 11 09:37:54 fw1 /bsd: 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on carp411
Feb 11 09:39:05 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7
Feb 11 09:39:05 fw1 /bsd: on carp411
Feb 11 09:40:04 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on carp4
Feb 11 09:40:04 fw1 /bsd: 11
Feb 11 09:41:36 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 o
Feb 11 09:41:36 fw1 /bsd: n carp411
Feb 11 09:42:01 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by
Feb 11 09:42:01 fw1 /bsd: 00:26:b9:5d:24:e7 on carp411
Feb 11 09:43:01 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432
Feb 11 09:43:01 fw1 /bsd: by 00:26:b9:5d:24:e7 on carp411
Feb 11 09:43:21 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by
Feb 11 09:43:21 fw1 /bsd: 00:26:b9:5d:24:e7 on carp411

[Stuart Henderson]

And an extra-special blank one here :-)

Feb 11 12:51:50 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on vlan411
Feb 11 12:51:50 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on carp411
Feb 11 12:51:50 fw1 /bsd:
Feb 11 12:51:51 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on vlan411
Feb 11 12:51:51 fw1 /bsd: arp: attempt to add entry for 192.168.43.131 on carp432 by 00:26:b9:5d:24:e7 on carp411

[Todd C. Miller]

Post by Stuart Henderson
I updated some firewalls to -current yesterday (from somewhere between
5.6 and 5.7) and am now seeing a lot of "arp: attempt to add entry"
logged, see below. (Looks like someone has put a machine on the wrong
vlan and it's sending out broadcast arp replies for conflict detection
which are triggering the logs, anyway that's a different problem).
Some of the lines in the logged file get split in half. I'm thinking
this probably warrants further investigation as it could cause log
monitoring programs to not notice certain problems..

That's really weird. The /dev/klog fd in syslogd isn't opened
non-blocking and from what I understand, log messages from the
kernel shouldn't be seen from userland until logwakeup() is called
at the end up the message.

Can you try disabling kqueue in syslogd by setting EVENT_NOKQUEUE=1
and see if the behavior changes?

- todd

[Stuart Henderson]

Post by Todd C. Miller

Post by Stuart Henderson
I updated some firewalls to -current yesterday (from somewhere between
5.6 and 5.7) and am now seeing a lot of "arp: attempt to add entry"
logged, see below. (Looks like someone has put a machine on the wrong
vlan and it's sending out broadcast arp replies for conflict detection
which are triggering the logs, anyway that's a different problem).
Some of the lines in the logged file get split in half. I'm thinking
this probably warrants further investigation as it could cause log
monitoring programs to not notice certain problems..

That's really weird. The /dev/klog fd in syslogd isn't opened
non-blocking and from what I understand, log messages from the
kernel shouldn't be seen from userland until logwakeup() is called
at the end up the message.
Can you try disabling kqueue in syslogd by setting EVENT_NOKQUEUE=1
and see if the behavior changes?

It seems like it is probably happening less often, but it hasn't
stopped completely.