Syslog running crazy - corrupt dhcpd6 lease
-
Hi,
my pfsense router keeps going crazy.
2.2-RELEASE (i386)
built on Thu Jan 22 14:04:25 CST 2015
FreeBSD 10.1-RELEASE-p4Syslog is using nearly all cpu time.
lots of processes:
root 5701 0.0 0.1 5992 1676 - Is 8:19PM 0:00.01 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 7984 0.0 0.1 5992 1676 - Is 8:20PM 0:00.01 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 10311 0.0 0.1 5992 1676 - Is 4:10PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 11105 0.0 0.1 10088 1696 - Is 8:15PM 0:00.02 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 11800 0.0 0.1 5992 1676 - Is 3:10PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 21029 0.0 0.1 5992 1676 - Is Sat10PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 22436 0.0 0.1 5992 1676 - Is 10:02AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 30479 0.0 0.1 5992 1676 - Is 7:18AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 31396 0.0 0.1 5992 1676 - Is Sun05AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 36090 0.0 0.1 5992 1676 - Is 8:21PM 0:00.01 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 38030 0.0 0.1 5992 1676 - Is 4:10PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 40616 0.0 0.1 5992 1676 - Is Sat04PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 52334 0.0 0.1 5992 1676 - Is Sat10PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 52420 0.0 0.1 5992 1676 - Is 9:33PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 53216 0.0 0.1 5992 1676 - Is 10:02AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 66686 0.0 0.1 5992 1676 - Is 4:10PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 68531 0.0 0.1 5992 1676 - Is 9:29AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 70245 0.0 0.1 5992 1676 - Is 10:01AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 71469 0.0 0.1 5992 1676 - Is 7:18AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 73421 0.0 0.1 5992 1676 - Is 8:22PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 76015 0.0 0.1 5992 1676 - Is 8:23PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 80441 0.0 0.1 5992 1676 - Is 1:37PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 91610 0.0 0.1 5992 1676 - Is Sat07PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 92077 0.0 0.1 5992 1676 - Is 8:47AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 93935 0.0 0.1 5992 1676 - Is Sat07PM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 94058 0.0 0.1 5992 1676 - Is Sun05AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 96604 0.0 0.1 5992 1676 - Is 10:01AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases root 97240 0.0 0.1 5992 1676 - Is Sun05AM 0:00.00 /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/prefixes.php|/bin/sh -l /var/dhcpd/var/db/dhcpd6.leases
in /var/log/dhcpd.log via clog -f keep getting this:
Mar 16 08:47:38 pfsense dhcpd: /var/db/dhcpd6.leases line 111: corrupt lease file; expecting ia_na contents, got ' { cltt 0 2015/03/15 22:57:20; iaaddr 2001:870:1909::1275 { binding state active; preferred-life 4500; max-life 7200; ends 1 2015/03/16 00:57:20; } } '
When I look into /var/dhcpd/dhcpd6.leases there are only 55 lines at all.
It also seems that those php processes keep eating all RAM.
I have had this same issue about 2 weeks ago. Deleteing the leases files and restarting dhcpd fixes, but obviously only short-term :-[
What's going on here? -
no one?
-
I just hit the exact same problem.
I killed off all of the dhcpd processes to try to get things back under control.
Next time, I'll try to gather data first.
The dhcpd log file is just spammed with messages of the form:
May 21 13:44:32 fw dhcpd: /var/db/dhcpd6.leases line 43: corrupt lease file; expecting ia_na contents, got ' '
May 21 13:44:32 fw dhcpd:
May 21 13:44:32 fw dhcpd: ^So dhcpd's error handling leaves a lot to be desired in this case.
-
try updating to 2.2.2 first. tons of stuff has been fixed since then.
-
Sorry, I should have said, this is running 2.2.2. I've never had the problem happen before.
It seems there was a parsing bug in ISC dhcpd 4.2.1 but that was fixed in 4.2.2 and we seem to be running 4.2.6 here, so unless there was a regression, it would appear to be a new issue. -
What's the full contents of your /var/dhcpd/var/db/dhcpd6.leases file? Can PM to me if you don't want to post publicly.
-
Ugh,
I did save a copy before removing it from /var/dhcpd/var/db, by copying it to /tmp.
As part of trying to get everything fixed (shotgun killing dhcpd processes), I wound up in a state where check_reload_status was spinning so I rebooted the firewall… forgetting that /tmp gets cleaned up on reboot :-(
So I've managed to lose the evidence from this incident.If it recurs, I'll make sure I get a copy saved before I reboot.
Thanks!
Tim