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-p4

    Syslog 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