Client6_recvadvert: XID mismatch since two days



  • I've been running pfsense 2.1.2 since it came out and had no problems whatsoever with ipv6. However, since two days it suddenly stopped working at like 2:30AM.  :-[
    The day it went down:
    dhcp6c[37496]: client6_recvadvert: XID mismatch
    dhcp6c[37496]: client6_recvadvert: XID mismatch
    dhcp6c[37496]: client6_timo: no responses were received
    dhcp6c[37496]: check_exit: exiting

    Now (box has been rebooted) log keeps spamming:
    dhcp6c[64477]: client6_recvadvert: XID mismatch

    What does this mean?

    Provider is XS4ALL from the Netherlands (vdsl)
    WAN interface is set to DHCP6 and LAN interfaces track it. PD size is set to 48 which has always worked. ipv4 still works though.

    Any help with this would be greatly appreciated!



  • Maybe something changed with your ISP? Wondering if they changed PD to /56 or /64



  • I have a feeling the problem is located on my side. Disabled DHCP6 and let it sit for a day.
    Started it up again and it worked. Could it be my ISP's dhcp6 server just ignores you after certain failed requests?



  • It crapped out again after pfsense detects an ip change (gateway went down for a moment). Disabled state killing but getting XID mismatch again and no IPV6.

    Now I killed dhcp6c and ran it from cli by hand with:
    /usr/local/sbin/dhcp6c -f -d -D -c /var/etc/dhcp6c_wan.conf -p /var/run/dhcp6c_pppoe0.pid pppoe0
    And everything just worked at once:

    Jun/18/2014 21:17:38: clear_poolconf: called
    Jun/18/2014 21:17:38: dhcp6_reset_timer: reset a timer on pppoe0, state=INIT, timeo=0, retrans=383
    Jun/18/2014 21:17:38: client6_send: a new XID (8ff5d6) is generated
    Jun/18/2014 21:17:38: copy_option: set client ID (len 14)
    Jun/18/2014 21:17:38: copy_option: set elapsed time (len 2)
    Jun/18/2014 21:17:38: copy_option: set option request (len 4)
    Jun/18/2014 21:17:38: copyout_option: set IA_PD
    Jun/18/2014 21:17:38: client6_send: send solicit to ff02::1:2%pppoe0
    Jun/18/2014 21:17:38: dhcp6_reset_timer: reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1088
    Jun/18/2014 21:17:38: client6_recv: receive advertise from fe80::2a0:a50f:fc7d:e542%pppoe0 on pppoe0
    Jun/18/2014 21:17:38: dhcp6_get_options: get DHCP option client ID, len 14
    Jun/18/2014 21:17:38:   DUID: 00:01:00:01:1b:21:6f:51:00:30:18:a8:7c:65
    Jun/18/2014 21:17:38: dhcp6_get_options: get DHCP option server ID, len 26
    Jun/18/2014 21:17:38:   DUID: 00:02:00:00:05:83:4a:4e:31:32:32:38:37:31:38:41:46:41:00:00:00:00:00:00:00:00
    Jun/18/2014 21:17:38: dhcp6_get_options: get DHCP option IA_PD, len 41
    Jun/18/2014 21:17:38:   IA_PD: ID=0, T1=3600, T2=5760
    Jun/18/2014 21:17:38: copyin_option: get DHCP option IA_PD prefix, len 25
    Jun/18/2014 21:17:38: copyin_option:   IA_PD prefix: 2001:xxx:xxxx::/48 pltime=7200 vltime=7200
    Jun/18/2014 21:17:38: dhcp6_get_options: get DHCP option DNS, len 32
    Jun/18/2014 21:17:38: client6_recvadvert: server ID: 00:02:00:00:05:83:4a:4e:31:32:32:38:37:31:38:41:46:41:00:00:00:00:00:00:00:00, pref=-1
    Jun/18/2014 21:17:38: client6_recvadvert: reset timer for pppoe0 to 0.977093
    Jun/18/2014 21:17:39: select_server: picked a server (ID: 00:02:00:00:05:83:4a:4e:31:32:32:38:37:31:38:41:46:41:00:00:00:00:00:00:00:00)
    Jun/18/2014 21:17:39: client6_send: a new XID (da6e8f) is generated
    Jun/18/2014 21:17:39: copy_option: set client ID (len 14)
    Jun/18/2014 21:17:39: copy_option: set server ID (len 26)
    Jun/18/2014 21:17:39: copy_option: set elapsed time (len 2)
    Jun/18/2014 21:17:39: copy_option: set option request (len 4)
    Jun/18/2014 21:17:39: copyout_option: set IA_PD prefix
    Jun/18/2014 21:17:39: copyout_option: set IA_PD
    Jun/18/2014 21:17:39: client6_send: send request to ff02::1:2%pppoe0
    Jun/18/2014 21:17:39: dhcp6_reset_timer: reset a timer on pppoe0, state=REQUEST, timeo=0, retrans=977
    Jun/18/2014 21:17:40: client6_recv: receive reply from fe80::2a0:a50f:fc7d:e542%pppoe0 on pppoe0
    Jun/18/2014 21:17:40: dhcp6_get_options: get DHCP option client ID, len 14
    Jun/18/2014 21:17:40:   DUID: 00:01:00:01:1b:21:6f:51:00:30:18:a8:7c:65
    Jun/18/2014 21:17:40: dhcp6_get_options: get DHCP option server ID, len 26
    Jun/18/2014 21:17:40:   DUID: 00:02:00:00:05:83:4a:4e:31:32:32:38:37:31:38:41:46:41:00:00:00:00:00:00:00:00
    Jun/18/2014 21:17:40: dhcp6_get_options: get DHCP option IA_PD, len 41
    Jun/18/2014 21:17:40:   IA_PD: ID=0, T1=3600, T2=5760
    Jun/18/2014 21:17:40: copyin_option: get DHCP option IA_PD prefix, len 25
    Jun/18/2014 21:17:40: copyin_option:   IA_PD prefix: 2001:xxx:xxxx::/48 pltime=7200 vltime=7200
    Jun/18/2014 21:17:40: dhcp6_get_options: get DHCP option DNS, len 32
    Jun/18/2014 21:17:40: info_printf: nameserver[0] 2001:888:0:6::66
    Jun/18/2014 21:17:40: info_printf: nameserver[1] 2001:888:0:9::99
    Jun/18/2014 21:17:40: get_ia: make an IA: PD-0
    Jun/18/2014 21:17:40: update_prefix: create a prefix 2001:xxx:xxxx::/48 pltime=7200, vltime=7200
    Jun/18/2014 21:17:40: ifaddrconf: add an address 2001:xxx:xxxx:0:21c:f0ff:fe6d:a5d8/64 on re1
    Jun/18/2014 21:17:40: ifaddrconf: add an address 2001:xxx:xxxx:1:21c:f0ff:fe6d:a5d8/64 on re1_vlan2
    Jun/18/2014 21:17:40: client6_recvreply: executes /var/etc/dhcp6c_wan_script.sh
    Jun/18/2014 21:17:48: client6_script: script "/var/etc/dhcp6c_wan_script.sh" terminated
    Jun/18/2014 21:17:48: dhcp6_remove_event: removing an event on pppoe0, state=REQUEST
    Jun/18/2014 21:17:48: dhcp6_remove_event: removing server (ID: 00:02:00:00:05:83:4a:4e:31:32:32:38:37:31:38:41:46:41:00:00:00:00:00:00:00:00)
    Jun/18/2014 21:17:48: client6_recvreply: got an expected reply, sleeping.
    
    

    Does anyone have a clue whats going on here? Why doesnt it just work automatically?  Is there a way for me to debug this further?



  • This very much resembles the thing I have.
    I always have to start the DHCPv6 by hand. In my opinion it is because the PPPoE isn't stable when the DHCPv6 is starting.



  • @avink:

    This very much resembles the thing I have.
    I always have to start the DHCPv6 by hand. In my opinion it is because the PPPoE isn't stable when the DHCPv6 is starting.

    I actually got the dhcp6c command from your bugreport on redmine, thanks for that  ;)
    Running dhcp6c in a tmux by hand now, seems stable so far.


Log in to reply