Bug: DHCPv6 Server not able to read its own lease file (4.1.1)

Maurice Massar massar at unix-ag.uni-kl.de
Wed Feb 3 12:06:23 UTC 2010


hi,

On Sun, Jan 31, 2010 at 01:06:37AM +0100, Maurice Massar wrote:
> I got to this problem because our "dhcpd -6" process dies silently,
> sometimes serveral times a day .. sometimes running for a few days..
> -tf does write a tracefile, but -play seems unable to read it:
> subnet_number():inet.c:52: Addr/mask length mismatch: 4 (000000000b000000402d000000c61608) != 16 (ffffffffffffffff0000000000000000)
> (I added a dump of addr and mask struct in the log_fatal() call)
> I'll keep poking on this one.... (I did not enable coredumps yet, and
> will run tcpdump -w in parallel .. other ideas?)

I got some more info on this:

I suspect that it happens when an expired lease gets renewed.
Contributing to an increased chance of this happening is that the order
of entries in the lease-file seems wrong:

minnehaha:/srv/dhcp6-debug# awk -v RS='\n\n' '{print gensub(".*iaaddr ([^ ]*) .*", "\\1", 1), gensub(".*cltt ([^;]*);.*", "\\1", 1)}' dhcpd6.leases-1265191941 | fgrep 2001:638:208:fd5f:0:ff:fe00:102c
2001:638:208:fd5f:0:ff:fe00:102c 2 2010/02/02 14:43:30
2001:638:208:fd5f:0:ff:fe00:102c 3 2010/02/03 07:43:01
2001:638:208:fd5f:0:ff:fe00:102c 3 2010/02/03 08:13:44
2001:638:208:fd5f:0:ff:fe00:102c 3 2010/02/03 08:05:51
2001:638:208:fd5f:0:ff:fe00:102c 3 2010/02/03 07:38:05
2001:638:208:fd5f:0:ff:fe00:102c 3 2010/02/03 07:40:32
2001:638:208:fd5f:0:ff:fe00:102c 3 2010/02/03 08:22:49

dhcpd: heap.c:198: isc_heap_delete: Assertion `index >= 1 && index <= heap->last' failed.
dhcpd: heap.c:222: isc_heap_decreased: Assertion `index >= 1 && index <= heap->last' failed.
(sometimes the first, sometimes the second)

running gdb on a corefile (1 out of 1388):

$ gdb /usr/sbin/dhcpd ../../core-foo/core-dhcpd-1265188430-23225
GNU gdb (GDB) 7.0-debian
Copyright (C) 2009 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "i486-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/sbin/dhcpd...Reading symbols from /usr/lib/debug/usr/sbin/dhcpd...done.
(no debugging symbols found)...done.

warning: Can't read pathname for load map: Input/output error.

warning: .dynamic section for "/usr/lib/i686/cmov/libcrypto.so.0.9.8" is not at the expected address (wrong library or version mismatch?)

warning: .dynamic section for "/lib/i686/cmov/libc.so.6" is not at the expected address (wrong library or version mismatch?)

warning: .dynamic section for "/usr/lib/libz.so.1" is not at the expected address (wrong library or version mismatch?)

warning: .dynamic section for "/lib/ld-linux.so.2" is not at the expected address (wrong library or version mismatch?)
Reading symbols from /usr/lib/i686/cmov/libcrypto.so.0.9.8...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/i686/cmov/libcrypto.so.0.9.8
Reading symbols from /lib/i686/cmov/libc.so.6...Reading symbols from /usr/lib/debug/lib/i686/cmov/libc-2.10.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/i686/cmov/libc.so.6
Reading symbols from /lib/i686/cmov/libdl.so.2...Reading symbols from /usr/lib/debug/lib/i686/cmov/libdl-2.10.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/i686/cmov/libdl.so.2
Reading symbols from /usr/lib/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libz.so.1
Reading symbols from /lib/ld-linux.so.2...Reading symbols from /usr/lib/debug/lib/ld-2.10.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /lib/i686/cmov/libnss_files.so.2...Reading symbols from /usr/lib/debug/lib/i686/cmov/libnss_files-2.10.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/i686/cmov/libnss_files.so.2
Error while mapping shared library sections:
f32_Rela): No such file or directory.
Core was generated by `/etc/dhcp3/v6/dhcpd -6 -cf /etc/dhcp3/v6/dhcpd6.conf -lf /var/lib/dhcp3/dhcpd6.'.
Program terminated with signal 6, Aborted.
#0  0xb7fbe424 in __kernel_vsyscall ()
(gdb) bt
#0  0xb7fbe424 in __kernel_vsyscall ()
#1  0xb7d35640 in ?? () from /lib/i686/cmov/libc.so.6
#2  0xb7d37018 in __mpn_add_1 (prodp=0xa706278, up=0xb7e464c4, size=175137400, 
    tspace=0xb7e44657) at ../stdlib/gmp.h:454
#3  __mpn_impn_sqr_n (prodp=0xa706278, up=0xb7e464c4, size=175137400, 
    tspace=0xb7e44657) at mul_n.c:351
#4  0xb7d2e5be in set_binding_values (domainname=0x80e3679 "isc_heap_delete", 
    dirnamep=0xb7e44657, codesetp=0x80e3580) at bindtextdom.c:336
#5  0x080b7724 in isc_heap_delete (heap=0x9cac298, index=64) at heap.c:198
#6  0x08088b6e in move_lease_to_active (pool=0x9cae920, lease=0xa31a438)
    at mdb6.c:997
#7  0x080820aa in reply_process_ia_na (reply_ret=0xbfce6f54, packet=0x9c17938, 
    client_id=<value optimized out>, server_id=0xbfce6e54) at dhcpv6.c:1838
#8  lease_to_client (reply_ret=0xbfce6f54, packet=0x9c17938, 
    client_id=<value optimized out>, server_id=0xbfce6e54) at dhcpv6.c:1301
#9  0x080861b7 in dhcpv6_request (reply=0xbfce6f54, packet=0x9c17938)
    at dhcpv6.c:4116
#10 build_dhcpv6_reply (reply=0xbfce6f54, packet=0x9c17938) at dhcpv6.c:5694
#11 0x0808642a in dhcpv6_relay_forw (reply=0xbfce7008, packet=0xa7061d0)
    at dhcpv6.c:5516
#12 build_dhcpv6_reply (reply=0xbfce7008, packet=0xa7061d0) at dhcpv6.c:5721
#13 0x08086a17 in dhcpv6 (packet=0xa7061d0) at dhcpv6.c:5814
#14 0x0809f4d5 in do_packet6 (interface=0x9c17610, packet=0xbfce7098 "\f", 
    len=211, from_port=8962, from=0xbfcf70b4, was_unicast=isc_boolean_true)
    at options.c:3877
#15 0x080916a1 in got_one_v6 (h=0x9c17b78) at discover.c:1452
#16 0x080bf2f3 in omapi_one_dispatch (wo=0x0, t=0xbfcf749c) at dispatch.c:520
#17 0x08093668 in dispatch () at dispatch.c:92
#18 0x0804c2e8 in main (argc=11, argv=0xbfcf75e4) at dhcpd.c:833
(gdb) up 5
#5  0x080b7724 in isc_heap_delete (heap=0x9cac298, index=64) at heap.c:198
198		REQUIRE(index >= 1 && index <= heap->last);
(gdb) print *heap
$1 = {size = 2048, size_increment = 1024, last = 0, array = 0xa6f78e8, 
  compare = 0x80878f0 <lease_older>, index = 0x8086e20 <lease_index_changed>}
(gdb) cd ../server
Working directory /home/rm/c/tmp/dhcp/isc-dhcp-4.1.1/server.
(gdb) up
#6  0x08088b6e in move_lease_to_active (pool=0x9cae920, lease=0xa31a438)
    at mdb6.c:997
997			isc_heap_delete(pool->inactive_timeouts, old_heap_index);
(gdb) print *pool
$2 = {refcnt = 470, pool_type = 3, start_addr = {in6_u = {
      u6_addr8 = " \001\006\070\002\b\375_\000\000\000\377\376\000\020", 
      u6_addr16 = {288, 14342, 2050, 24573, 0, 65280, 254, 16}, u6_addr32 = {
        939917600, 1610418178, 4278190080, 1048830}}}, bits = 119, 
  units = 128, leases = 0x9cae960, num_active = 98, 
  active_timeouts = 0x9ca1a58, num_inactive = 0, 
  inactive_timeouts = 0x9cac298, shared_network = 0x9cae830, 
  subnet = 0x9cae890}
(gdb) print *lease
$3 = {refcnt = 3, addr = {in6_u = {
      u6_addr8 = " \001\006\070\002\b\375_\000\000\000\377\376\000\021", <incomplete sequence \314>, u6_addr16 = {288, 14342, 2050, 24573, 0, 65280, 254, 
        52241}, u6_addr32 = {939917600, 1610418178, 4278190080, 3423666430}}}, 
  plen = 0 '\000', state = 5 '\005', scope = 0x0, 
  hard_lifetime_end_time = 1265195630, soft_lifetime_end_time = 0, 
  prefer = 4500, valid = 7200, ia = 0x9c184f8, ipv6_pool = 0x9cae920, 
  heap_index = 99}
(gdb) up
#7  0x080820aa in reply_process_ia_na (reply_ret=0xbfce6f54, packet=0x9c17938, 
    client_id=<value optimized out>, server_id=0xbfce6e54) at dhcpv6.c:1838
1838				renew_lease6(tmp->ipv6_pool, tmp);
(gdb) print *tmp
$4 = {refcnt = 3, addr = {in6_u = {
      u6_addr8 = " \001\006\070\002\b\375_\000\000\000\377\376\000\021", <incomplete sequence \314>, u6_addr16 = {288, 14342, 2050, 24573, 0, 65280, 254, 
        52241}, u6_addr32 = {939917600, 1610418178, 4278190080, 3423666430}}}, 
  plen = 0 '\000', state = 5 '\005', scope = 0x0, 
  hard_lifetime_end_time = 1265195630, soft_lifetime_end_time = 0, 
  prefer = 4500, valid = 7200, ia = 0x9c184f8, ipv6_pool = 0x9cae920, 
  heap_index = 99}
(gdb) print *tmp->ipv6_pool
$5 = {refcnt = 470, pool_type = 3, start_addr = {in6_u = {
      u6_addr8 = " \001\006\070\002\b\375_\000\000\000\377\376\000\020", 
      u6_addr16 = {288, 14342, 2050, 24573, 0, 65280, 254, 16}, u6_addr32 = {
        939917600, 1610418178, 4278190080, 1048830}}}, bits = 119, 
  units = 128, leases = 0x9cae960, num_active = 98, 
  active_timeouts = 0x9ca1a58, num_inactive = 0, 
  inactive_timeouts = 0x9cac298, shared_network = 0x9cae830, 
  subnet = 0x9cae890}
(gdb) print *tmp->ipv6_pool->active_timeouts
$6 = {size = 1024, size_increment = 1024, last = 99, array = 0x9c18c28, 
  compare = 0x80878f0 <lease_older>, index = 0x8086e20 <lease_index_changed>}
(gdb) print *tmp->ipv6_pool->inactive_timeouts
$7 = {size = 2048, size_increment = 1024, last = 0, array = 0xa6f78e8, 
  compare = 0x80878f0 <lease_older>, index = 0x8086e20 <lease_index_changed>}
(gdb) quit


I've disabled coredumping for now .. 16 GB of corefiles filled up the
partition (-;
anyway, my current workarounds before restarting dhcpd -6 are:

sed -i 's/ends never;$/ends never;;/' /var/lib/dhcp/dhcpd6.leases
awk -v RS='\n\n' '! /binding state (expired|released)/ {IP=gensub(".*iaaddr ([^ ]*) .*", "\\1", 1); T=gensub(".*cltt ([^;]*);.*", "\\1", 1); if (T > TS[IP]) {BIND[IP] = $0; TS[IP]=T}}  END {for (IP in BIND) {print BIND[IP]"\n"}}' /var/lib/dhcp/dhcpd6.leases /var/lib/dhcp/dhcpd6.leases-AWK ; mv /var/lib/dhcp/dhcpd6.leases-AWK /var/lib/dhcp/dhcpd6.leases

cu
Maurice Massar



More information about the dhcp-users mailing list