Client6_recvadvert: XID mismatch since two days

mav

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!

Cino

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

mav

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?

mav

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?

dotOne

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.

mav

@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.