Closed wevsty closed 2 weeks ago
2024-07-18T21:59:23 Notice dhcp6c re-establishing IA: PD-2 2024-07-18T21:59:23 Notice dhcp6c receive NoBinding against renew/rebind for PD-2 2024-07-18T21:59:23 Notice dhcp6c status code for PD-2: no binding
As far as I remember "no binding" means the server forgot your lease exists (maybe due to a reboot or service restart). We fixed such a case before but there could be more response codes where the client needs to reset as well and send a new solicit instead, see https://github.com/opnsense/dhcp6c/commit/555bdcdeff
But it could also be just a quirk of the server refusing your PD renew for whatever reasons for an unknown time period and the client is helpless.
So it appears to be doing what it is supposed to and the server answers to the nobind initiated request:
status code for PD-2: not on-link
Not sure what this means, but also not very nice from the ISP.
Thank you for creating an issue. Since the ticket doesn't seem to be using one of our templates, we're marking this issue as low priority until further notice.
For more information about the policies for this repository, please read https://github.com/opnsense/core/blob/master/CONTRIBUTING.md for further details.
The easiest option to gain traction is to close this ticket and open a new one using one of our templates.
Not sure what this means, but also not very nice from the ISP.
I can't deny that this could be some kind of weird behavior from ISP.
Obviously I'm not a networking expert, so I can't tell what the problem is.
My personal opinion is that the ISP has forced a prefix change from time to time and is no longer accepting any requests for the old prefix.
For example, usually when connecting for the first time.
The WAN interface also gets a prefix such as 240e:390:4923:1bf0::/64
LAN also gets a prefix 240e:390:4923:1bf1::/64
.
When the ISP forces a prefix change, the WAN may get a new prefix 240e:390:4819:8e40::/64
, but the LAN is still renewing 240e:390:4923:1bf1::/64
immediately after being rejected by the server.
As far as I remember "no binding" means the server forgot your lease exists (maybe due to a reboot or service restart). We fixed such a case before but there could be more response codes where the client needs to reset as well and send a new solicit instead, see https://github.com/opnsense/dhcp6c/commit/555bdcdeff But it could also be just a quirk of the server refusing your PD renew for whatever reasons for an unknown time period and the client is helpless.
I see the commit. I don't seem to see any trace of executing client6_reset()
in the logs. Maybe we need to execute reset in more cases.
In my case, if the reset interface is not performed manually, then the network will not recover and this state will remain for more than a few hours. I think this is still a problem that needs to be solved.
If necessary, I can try to provide more information on how to solve this problem and you can tell me what you think.
I seem to be missing a bit of LOG_INFO output but it's probably broken in the client or redirected elsewhere for a reason I don't want to investigate at the moment. So now there's 3e134cd which handles NOTONLINK for the first time in the client. I have no idea if it works but it's worth a shot. To install:
# pkg add -f https://pkg.opnsense.org/FreeBSD:13:amd64/snapshots/misc/dhcp6c-20240710_1.pkg
And reboot for good measure.
I've installed the new version, let me test it, this may take a few days. I'll come back and update with results.
Thanks in advance!
Thanks in advance!
A little update on the new info. The problem is still existing on dhcp6c-20240710_1.pkg.
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync(,lan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,lan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,lan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,lan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,lan)
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do(,lan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,lan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,lan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,lan)
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync(,wan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,wan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,wan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,wan)
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do(,wan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,wan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,wan))
2024-07-22T22:02:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)
2024-07-22T22:02:44 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'
2024-07-22T22:02:44 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
2024-07-22T22:02:44 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)
2024-07-22T22:02:44 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: keeping inet6 default route to fe80::1%igb0
2024-07-22T22:02:44 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan
2024-07-22T22:02:44 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'
2024-07-22T22:02:36 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))
2024-07-22T22:02:36 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)
2024-07-22T22:02:36 Notice opnsense /usr/local/etc/rc.newwanipv6: IP renewal starting (address: fe80::2e53:4aff:feb0:ddd%igb0, interface: wan, device: igb0)
2024-07-22T22:02:30 Notice dhcp6c got an expected reply, sleeping.
2024-07-22T22:02:30 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-07-22T22:02:30 Notice dhcp6c dhcp6c_script: REQUEST on igb0 renewal
2024-07-22T22:02:30 Notice dhcp6c dhcp6c_script: REQUEST on igb0 executing
2024-07-22T22:02:30 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-07-22T22:02:30 Notice dhcp6c removing an event on igb0, state=REQUEST
2024-07-22T22:02:30 Notice dhcp6c T1(21506) and/or T2(34409) is locally determined
2024-07-22T22:02:30 Notice dhcp6c status code for PD-2: not on-link
2024-07-22T22:02:30 Notice dhcp6c update an IA: PD-2
2024-07-22T22:02:30 Notice dhcp6c nameserver[0] fe80::1
2024-07-22T22:02:30 Notice dhcp6c Received REPLY for REQUEST
2024-07-22T22:02:30 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-07-22T22:02:30 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-07-22T22:02:30 Notice dhcp6c get DHCP option DNS, len 16
2024-07-22T22:02:30 Notice dhcp6c requested option: domain search list
2024-07-22T22:02:30 Notice dhcp6c requested option: DNS
2024-07-22T22:02:30 Notice dhcp6c get DHCP option option request, len 4
2024-07-22T22:02:30 Notice dhcp6c status code: not on-link
2024-07-22T22:02:30 Notice dhcp6c get DHCP option status code, len 2
2024-07-22T22:02:30 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-07-22T22:02:30 Notice dhcp6c get DHCP option IA_PD, len 18
2024-07-22T22:02:30 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-07-22T22:02:30 Notice dhcp6c get DHCP option server ID, len 10
2024-07-22T22:02:30 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-07-22T22:02:30 Notice dhcp6c get DHCP option client ID, len 10
2024-07-22T22:02:30 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-07-22T22:02:30 Notice dhcp6c got an expected reply, sleeping.
2024-07-22T22:02:30 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-07-22T22:02:30 Notice dhcp6c dhcp6c_script: RENEW on igb0 executing
2024-07-22T22:02:30 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-07-22T22:02:30 Notice dhcp6c removing an event on igb0, state=RENEW
2024-07-22T22:02:30 Notice dhcp6c send request to ff02::1:2%igb0
2024-07-22T22:02:30 Notice dhcp6c set IA_PD
2024-07-22T22:02:30 Notice dhcp6c set IA_PD prefix
2024-07-22T22:02:30 Notice dhcp6c set option request (len 4)
2024-07-22T22:02:30 Notice dhcp6c set elapsed time (len 2)
2024-07-22T22:02:30 Notice dhcp6c set server ID (len 10)
2024-07-22T22:02:30 Notice dhcp6c set client ID (len 10)
2024-07-22T22:02:30 Notice dhcp6c a new XID (8a3248) is generated
2024-07-22T22:02:30 Notice dhcp6c Sending Request
2024-07-22T22:02:30 Notice dhcp6c reset a timer on igb0, state=REQUEST, timeo=0, retrans=992
2024-07-22T22:02:30 Notice dhcp6c re-establishing IA: PD-2
2024-07-22T22:02:30 Notice dhcp6c receive NoBinding against renew/rebind for PD-2
2024-07-22T22:02:30 Notice dhcp6c status code for PD-2: no binding
2024-07-22T22:02:30 Notice dhcp6c update an IA: PD-2
2024-07-22T22:02:30 Notice dhcp6c nameserver[0] fe80::1
2024-07-22T22:02:30 Notice dhcp6c Received REPLY for RENEW
2024-07-22T22:02:30 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-07-22T22:02:30 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-07-22T22:02:30 Notice dhcp6c get DHCP option DNS, len 16
2024-07-22T22:02:30 Notice dhcp6c status code: no binding
2024-07-22T22:02:30 Notice dhcp6c get DHCP option status code, len 2
2024-07-22T22:02:30 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-07-22T22:02:30 Notice dhcp6c get DHCP option IA_PD, len 18
2024-07-22T22:02:30 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-07-22T22:02:30 Notice dhcp6c get DHCP option server ID, len 10
2024-07-22T22:02:30 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-07-22T22:02:30 Notice dhcp6c get DHCP option client ID, len 10
2024-07-22T22:02:30 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-07-22T22:02:30 Notice dhcp6c send renew to ff02::1:2%igb0
2024-07-22T22:02:30 Notice dhcp6c set IA_PD
2024-07-22T22:02:30 Notice dhcp6c set IA_PD prefix
2024-07-22T22:02:30 Notice dhcp6c set option request (len 4)
2024-07-22T22:02:30 Notice dhcp6c set elapsed time (len 2)
2024-07-22T22:02:30 Notice dhcp6c set server ID (len 10)
2024-07-22T22:02:30 Notice dhcp6c set client ID (len 10)
2024-07-22T22:02:30 Notice dhcp6c a new XID (8dc367) is generated
2024-07-22T22:02:30 Notice dhcp6c Sending Renew
2024-07-22T22:02:30 Notice dhcp6c reset a timer on igb0, state=RENEW, timeo=0, retrans=9063
2024-07-22T22:02:30 Notice dhcp6c IA timeout for PD-2, state=ACTIVE
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum done
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum interface_086400.sqlite
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum interface_003600.sqlite
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum interface_000300.sqlite
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum interface_000030.sqlite
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum src_addr_086400.sqlite
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum src_addr_003600.sqlite
2024-07-22T16:49:20 Notice flowd_aggregate.py vacuum src_addr_000300.sqlite
2024-07-22T16:49:15 Notice flowd_aggregate.py vacuum src_addr_details_086400.sqlite
2024-07-22T16:49:13 Notice flowd_aggregate.py vacuum dst_port_086400.sqlite
2024-07-22T16:49:13 Notice flowd_aggregate.py vacuum dst_port_003600.sqlite
2024-07-22T16:49:13 Notice flowd_aggregate.py vacuum dst_port_000300.sqlite
2024-07-22T16:42:57 Notice dhclient dhclient-script: Creating resolv.conf
2024-07-22T16:42:57 Notice dhclient dhclient-script: Reason RENEW on igb0 executing
2024-07-22T16:42:57 Error dhclient unknown dhcp option value 0x7d
2024-07-22T10:05:39 Notice dhcp6c got an expected reply, sleeping.
2024-07-22T10:05:39 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-07-22T10:05:39 Notice dhcp6c dhcp6c_script: RENEW on igb0 executing
2024-07-22T10:05:39 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-07-22T10:05:39 Notice dhcp6c removing an event on igb0, state=RENEW
2024-07-22T10:05:39 Notice dhcp6c update a prefix 240e:390:48e9:8e41::/64 pltime=86023, vltime=86023
2024-07-22T10:05:39 Notice dhcp6c update an IA: PD-2
2024-07-22T10:05:39 Notice dhcp6c nameserver[0] fe80::1
2024-07-22T10:05:39 Notice dhcp6c Received REPLY for RENEW
2024-07-22T10:05:39 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-07-22T10:05:39 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-07-22T10:05:39 Notice dhcp6c get DHCP option DNS, len 16
2024-07-22T10:05:39 Notice dhcp6c IA_PD prefix: 240e:390:48e9:8e41::/64 pltime=86023 vltime=86023
2024-07-22T10:05:39 Notice dhcp6c get DHCP option IA_PD prefix, len 25
2024-07-22T10:05:39 Notice dhcp6c IA_PD: ID=2, T1=43011, T2=68818
2024-07-22T10:05:39 Notice dhcp6c get DHCP option IA_PD, len 41
2024-07-22T10:05:39 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-07-22T10:05:39 Notice dhcp6c get DHCP option server ID, len 10
2024-07-22T10:05:39 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-07-22T10:05:39 Notice dhcp6c get DHCP option client ID, len 10
2024-07-22T10:05:39 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-07-22T10:05:39 Notice dhcp6c send renew to ff02::1:2%igb0
2024-07-22T10:05:39 Notice dhcp6c set IA_PD
2024-07-22T10:05:39 Notice dhcp6c set IA_PD prefix
2024-07-22T10:05:39 Notice dhcp6c set option request (len 4)
2024-07-22T10:05:39 Notice dhcp6c set elapsed time (len 2)
2024-07-22T10:05:39 Notice dhcp6c set server ID (len 10)
2024-07-22T10:05:39 Notice dhcp6c set client ID (len 10)
2024-07-22T10:05:39 Notice dhcp6c a new XID (e8d48e) is generated
2024-07-22T10:05:39 Notice dhcp6c Sending Renew
2024-07-22T10:05:39 Notice dhcp6c reset a timer on igb0, state=RENEW, timeo=0, retrans=9831
2024-07-22T10:05:39 Notice dhcp6c IA timeout for PD-2, state=ACTIVE
Looking at the log this time around, it's no different than the one before the update. I still haven't observed a reset log.This makes me think that it might not be the reset message output that is missing.
After the problem, wan still behaves as if it has acquired a new prefix.So I think it's probably not the ISP servers rejecting new allocation requests either.
Maybe we should consider capturing DHCPV6 traffic to diagnose the problem?
I'll try to capture DHCPV6 packets, but that may take a few days pending issues.
@fichtner
The good news is that I think I got more information by capturing the packets. That would explain why the 3e134cd fix didn't work.
To determine when the problem occurs, I use one machine to ping the public IP(2400:3200::1) every 10 seconds on my LAN. With the results of the ping, I determined the initial time of the problem to be between UTC+8 2024-07-31 05:27:50 and 2024-07-31 05:28:22 Corresponding to this time period. I observe that the system log does not have any valid content.
System log for the corresponding time:
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync(,lan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,lan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,lan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,lan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,lan)
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do(,lan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,lan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,lan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,lan)
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync(,wan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,wan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,wan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,wan)
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do(,wan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,wan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,wan))
2024-07-31T11:33:46 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)
2024-07-31T11:33:45 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'
2024-07-31T11:33:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
2024-07-31T11:33:45 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)
2024-07-31T11:33:45 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: keeping inet6 default route to fe80::1%igb0
2024-07-31T11:33:45 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan
2024-07-31T11:33:45 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'
2024-07-31T11:33:29 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))
2024-07-31T11:33:29 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)
2024-07-31T11:33:29 Notice opnsense /usr/local/etc/rc.newwanipv6: IP renewal starting (address: fe80::2e53:4aff:feb0:ddd%igb0, interface: wan, device: igb0)
2024-07-31T11:33:23 Notice dhcp6c got an expected reply, sleeping.
2024-07-31T11:33:23 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-07-31T11:33:23 Notice dhcp6c dhcp6c_script: REQUEST on igb0 renewal
2024-07-31T11:33:23 Notice dhcp6c dhcp6c_script: REQUEST on igb0 executing
2024-07-31T11:33:23 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-07-31T11:33:23 Notice dhcp6c removing an event on igb0, state=REQUEST
2024-07-31T11:33:23 Notice dhcp6c T1(10631) and/or T2(17009) is locally determined
2024-07-31T11:33:23 Notice dhcp6c status code for PD-2: not on-link
2024-07-31T11:33:23 Notice dhcp6c update an IA: PD-2
2024-07-31T11:33:23 Notice dhcp6c nameserver[0] fe80::1
2024-07-31T11:33:23 Notice dhcp6c Received REPLY for REQUEST
2024-07-31T11:33:23 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-07-31T11:33:23 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-07-31T11:33:23 Notice dhcp6c get DHCP option DNS, len 16
2024-07-31T11:33:23 Notice dhcp6c requested option: domain search list
2024-07-31T11:33:23 Notice dhcp6c requested option: DNS
2024-07-31T11:33:23 Notice dhcp6c get DHCP option option request, len 4
2024-07-31T11:33:23 Notice dhcp6c status code: not on-link
2024-07-31T11:33:23 Notice dhcp6c get DHCP option status code, len 2
2024-07-31T11:33:23 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-07-31T11:33:23 Notice dhcp6c get DHCP option IA_PD, len 18
2024-07-31T11:33:23 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-07-31T11:33:23 Notice dhcp6c get DHCP option server ID, len 10
2024-07-31T11:33:23 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-07-31T11:33:23 Notice dhcp6c get DHCP option client ID, len 10
2024-07-31T11:33:23 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-07-31T11:33:23 Notice dhcp6c got an expected reply, sleeping.
2024-07-31T11:33:23 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-07-31T11:33:23 Notice dhcp6c dhcp6c_script: RENEW on igb0 executing
2024-07-31T11:33:23 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-07-31T11:33:23 Notice dhcp6c removing an event on igb0, state=RENEW
2024-07-31T11:33:23 Notice dhcp6c send request to ff02::1:2%igb0
2024-07-31T11:33:23 Notice dhcp6c set IA_PD
2024-07-31T11:33:23 Notice dhcp6c set IA_PD prefix
2024-07-31T11:33:23 Notice dhcp6c set option request (len 4)
2024-07-31T11:33:23 Notice dhcp6c set elapsed time (len 2)
2024-07-31T11:33:23 Notice dhcp6c set server ID (len 10)
2024-07-31T11:33:23 Notice dhcp6c set client ID (len 10)
2024-07-31T11:33:23 Notice dhcp6c a new XID (5e3617) is generated
2024-07-31T11:33:23 Notice dhcp6c Sending Request
2024-07-31T11:33:23 Notice dhcp6c reset a timer on igb0, state=REQUEST, timeo=0, retrans=942
2024-07-31T11:33:23 Notice dhcp6c re-establishing IA: PD-2
2024-07-31T11:33:23 Notice dhcp6c receive NoBinding against renew/rebind for PD-2
2024-07-31T11:33:23 Notice dhcp6c status code for PD-2: no binding
2024-07-31T11:33:23 Notice dhcp6c update an IA: PD-2
2024-07-31T11:33:23 Notice dhcp6c nameserver[0] fe80::1
2024-07-31T11:33:23 Notice dhcp6c Received REPLY for RENEW
2024-07-31T11:33:23 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-07-31T11:33:23 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-07-31T11:33:23 Notice dhcp6c get DHCP option DNS, len 16
2024-07-31T11:33:23 Notice dhcp6c status code: no binding
2024-07-31T11:33:23 Notice dhcp6c get DHCP option status code, len 2
2024-07-31T11:33:23 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-07-31T11:33:23 Notice dhcp6c get DHCP option IA_PD, len 18
2024-07-31T11:33:23 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-07-31T11:33:23 Notice dhcp6c get DHCP option server ID, len 10
2024-07-31T11:33:23 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-07-31T11:33:23 Notice dhcp6c get DHCP option client ID, len 10
2024-07-31T11:33:23 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-07-31T11:33:23 Notice dhcp6c send renew to ff02::1:2%igb0
2024-07-31T11:33:23 Notice dhcp6c set IA_PD
2024-07-31T11:33:23 Notice dhcp6c set IA_PD prefix
2024-07-31T11:33:23 Notice dhcp6c set option request (len 4)
2024-07-31T11:33:23 Notice dhcp6c set elapsed time (len 2)
2024-07-31T11:33:23 Notice dhcp6c set server ID (len 10)
2024-07-31T11:33:23 Notice dhcp6c set client ID (len 10)
2024-07-31T11:33:23 Notice dhcp6c a new XID (7d902b) is generated
2024-07-31T11:33:23 Notice dhcp6c Sending Renew
2024-07-31T11:33:23 Notice dhcp6c reset a timer on igb0, state=RENEW, timeo=0, retrans=9216
2024-07-31T11:33:23 Notice dhcp6c IA timeout for PD-2, state=ACTIVE
2024-07-31T05:39:10 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync(,lan))
2024-07-31T05:39:10 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,lan))
2024-07-31T05:39:10 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
2024-07-31T05:39:10 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,lan))
2024-07-31T05:39:10 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,lan))
2024-07-31T05:39:10 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,lan)
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do(,lan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,lan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,lan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,lan)
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : wireguard_sync(,wan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,wan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,wan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,wan)
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : wireguard_configure_do(,wan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,wan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,wan))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: keeping inet6 default route to fe80::1%igb0
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan
2024-07-31T05:39:09 Notice opnsense /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'
2024-07-31T05:39:06 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))
2024-07-31T05:39:06 Notice opnsense /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)
2024-07-31T05:39:06 Notice opnsense /usr/local/etc/rc.newwanipv6: IP renewal starting (address: fe80::2e53:4aff:feb0:ddd%igb0, interface: wan, device: igb0)
2024-07-31T05:39:00 Notice dhcp6c got an expected reply, sleeping.
2024-07-31T05:39:00 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-07-31T05:38:59 Notice dhcp6c dhcp6c_script: REQUEST on igb0 renewal
2024-07-31T05:38:59 Notice dhcp6c dhcp6c_script: REQUEST on igb0 executing
2024-07-31T05:38:59 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-07-31T05:38:59 Notice dhcp6c removing an event on igb0, state=REQUEST
2024-07-31T05:38:59 Notice dhcp6c T1(21263) and/or T2(34020) is locally determined
2024-07-31T05:38:59 Notice dhcp6c status code for PD-2: not on-link
2024-07-31T05:38:59 Notice dhcp6c update an IA: PD-2
2024-07-31T05:38:59 Notice dhcp6c nameserver[0] fe80::1
2024-07-31T05:38:59 Notice dhcp6c Received REPLY for REQUEST
2024-07-31T05:38:59 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-07-31T05:38:59 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-07-31T05:38:59 Notice dhcp6c get DHCP option DNS, len 16
2024-07-31T05:38:59 Notice dhcp6c requested option: domain search list
2024-07-31T05:38:59 Notice dhcp6c requested option: DNS
2024-07-31T05:38:59 Notice dhcp6c get DHCP option option request, len 4
2024-07-31T05:38:59 Notice dhcp6c status code: not on-link
2024-07-31T05:38:59 Notice dhcp6c get DHCP option status code, len 2
2024-07-31T05:38:59 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-07-31T05:38:59 Notice dhcp6c get DHCP option IA_PD, len 18
2024-07-31T05:38:59 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-07-31T05:38:59 Notice dhcp6c get DHCP option server ID, len 10
2024-07-31T05:38:59 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-07-31T05:38:59 Notice dhcp6c get DHCP option client ID, len 10
2024-07-31T05:38:59 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-07-31T05:38:59 Notice dhcp6c got an expected reply, sleeping.
2024-07-31T05:38:59 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-07-31T05:38:59 Notice dhcp6c dhcp6c_script: RENEW on igb0 executing
2024-07-31T05:38:59 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-07-31T05:38:59 Notice dhcp6c removing an event on igb0, state=RENEW
2024-07-31T05:38:59 Notice dhcp6c send request to ff02::1:2%igb0
2024-07-31T05:38:59 Notice dhcp6c set IA_PD
2024-07-31T05:38:59 Notice dhcp6c set IA_PD prefix
2024-07-31T05:38:59 Notice dhcp6c set option request (len 4)
2024-07-31T05:38:59 Notice dhcp6c set elapsed time (len 2)
2024-07-31T05:38:59 Notice dhcp6c set server ID (len 10)
2024-07-31T05:38:59 Notice dhcp6c set client ID (len 10)
2024-07-31T05:38:59 Notice dhcp6c a new XID (27291) is generated
2024-07-31T05:38:59 Notice dhcp6c Sending Request
2024-07-31T05:38:59 Notice dhcp6c reset a timer on igb0, state=REQUEST, timeo=0, retrans=909
2024-07-31T05:38:59 Notice dhcp6c re-establishing IA: PD-2
2024-07-31T05:38:59 Notice dhcp6c receive NoBinding against renew/rebind for PD-2
2024-07-31T05:38:59 Notice dhcp6c status code for PD-2: no binding
2024-07-31T05:38:59 Notice dhcp6c update an IA: PD-2
2024-07-31T05:38:59 Notice dhcp6c nameserver[0] fe80::1
2024-07-31T05:38:59 Notice dhcp6c Received REPLY for RENEW
2024-07-31T05:38:59 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-07-31T05:38:59 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-07-31T05:38:59 Notice dhcp6c get DHCP option DNS, len 16
2024-07-31T05:38:59 Notice dhcp6c status code: no binding
2024-07-31T05:38:59 Notice dhcp6c get DHCP option status code, len 2
2024-07-31T05:38:59 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-07-31T05:38:59 Notice dhcp6c get DHCP option IA_PD, len 18
2024-07-31T05:38:59 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-07-31T05:38:59 Notice dhcp6c get DHCP option server ID, len 10
2024-07-31T05:38:59 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-07-31T05:38:59 Notice dhcp6c get DHCP option client ID, len 10
2024-07-31T05:38:59 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-07-31T05:38:59 Notice dhcp6c send renew to ff02::1:2%igb0
2024-07-31T05:38:59 Notice dhcp6c set IA_PD
2024-07-31T05:38:59 Notice dhcp6c set IA_PD prefix
2024-07-31T05:38:59 Notice dhcp6c set option request (len 4)
2024-07-31T05:38:59 Notice dhcp6c set elapsed time (len 2)
2024-07-31T05:38:59 Notice dhcp6c set server ID (len 10)
2024-07-31T05:38:59 Notice dhcp6c set client ID (len 10)
2024-07-31T05:38:59 Notice dhcp6c a new XID (753fec) is generated
2024-07-31T05:38:59 Notice dhcp6c Sending Renew
2024-07-31T05:38:59 Notice dhcp6c reset a timer on igb0, state=RENEW, timeo=0, retrans=10830
2024-07-31T05:38:59 Notice dhcp6c IA timeout for PD-2, state=ACTIVE
2024-07-31T05:29:46 Notice flowd_aggregate.py vacuum done
2024-07-31T05:29:46 Notice flowd_aggregate.py vacuum interface_086400.sqlite
2024-07-31T05:29:46 Notice flowd_aggregate.py vacuum interface_003600.sqlite
2024-07-31T05:29:46 Notice flowd_aggregate.py vacuum interface_000300.sqlite
2024-07-31T05:29:46 Notice flowd_aggregate.py vacuum interface_000030.sqlite
2024-07-31T05:29:45 Notice flowd_aggregate.py vacuum src_addr_086400.sqlite
2024-07-31T05:29:45 Notice flowd_aggregate.py vacuum src_addr_003600.sqlite
2024-07-31T05:29:45 Notice flowd_aggregate.py vacuum src_addr_000300.sqlite
2024-07-31T05:29:41 Notice flowd_aggregate.py vacuum src_addr_details_086400.sqlite
2024-07-31T05:29:39 Notice flowd_aggregate.py vacuum dst_port_086400.sqlite
2024-07-31T05:29:39 Notice flowd_aggregate.py vacuum dst_port_003600.sqlite
2024-07-31T05:29:39 Notice flowd_aggregate.py vacuum dst_port_000300.sqlite
2024-07-31T05:27:14 Notice dhclient dhclient-script: Creating resolv.conf
2024-07-31T05:27:14 Notice dhclient dhclient-script: Reason RENEW on igb0 executing
2024-07-31T05:27:14 Error dhclient unknown dhcp option value 0x7d
2024-07-30T21:29:31 Notice flowd_aggregate.py vacuum done
2024-07-30T21:29:31 Notice flowd_aggregate.py vacuum interface_086400.sqlite
2024-07-30T21:29:31 Notice flowd_aggregate.py vacuum interface_003600.sqlite
2024-07-30T21:29:31 Notice flowd_aggregate.py vacuum interface_000300.sqlite
2024-07-30T21:29:31 Notice flowd_aggregate.py vacuum interface_000030.sqlite
2024-07-30T21:29:30 Notice flowd_aggregate.py vacuum src_addr_086400.sqlite
2024-07-30T21:29:30 Notice flowd_aggregate.py vacuum src_addr_003600.sqlite
2024-07-30T21:29:30 Notice flowd_aggregate.py vacuum src_addr_000300.sqlite
2024-07-30T21:29:26 Notice flowd_aggregate.py vacuum src_addr_details_086400.sqlite
2024-07-30T21:29:24 Notice flowd_aggregate.py vacuum dst_port_086400.sqlite
2024-07-30T21:29:24 Notice flowd_aggregate.py vacuum dst_port_003600.sqlite
2024-07-30T21:29:24 Notice flowd_aggregate.py vacuum dst_port_000300.sqlite
DHCP and ICMPV6 packets captured during the syslog time period are in attachment 1722375539_to_1722375665.zip
With the packet capture data, we can see that the ISP first sends down a new prefix(240e:390:4902:4b28::) with a lifetime of 0 via the RA message.
1 second later, the ISP sends the new prefix(240e:390:48c3:eef0::) that actually works through the RA again.
dhcp6c apparently didn't pick up on this change, so it did nothing and still tried to renew the old prefix(240e:390:48ce:c3e1::) 10 minutes later. Apparently, the ISP rejected the request, returning not on-link. and DHCP6C did not properly reset the interface and retry until another renewal attempt was made 6 hours later.
I understand that my ISP behavior may not be great, but I think it's still an issue that needs to be addressed. My suggestion is to have dhcp6c receive RA messages and if it receives a lifetime of 0 message from RA release all IPV6 addresses and prefixes to reacquire a new prefix.
attachment: 1722375539_to_1722375665.zip
Thanks for the further details. What I don't understand is that the client reacts to the NoBinding server response:
https://github.com/opnsense/dhcp6c/blob/master/dhcp6c_ia.c#L178-L197
After which the server babbles on about NotOnLink. I think we can catch the case there too but it could be the server expects a different source address from the client in this case, which would then fail too, but it's worth a try to go step by step.
New patch is https://github.com/opnsense/dhcp6c/commit/1e6fa2e3f80c
# pkg add -f https://pkg.opnsense.org/FreeBSD:14:amd64/snapshots/misc/dhcp6c-20240710_2.pkg
(as always make sure to reboot since dhcp6c runs sticky with SIGHUP)
Cheers, Franco
New patch is 1e6fa2e3f80c
I think it might be effective to remove ia after receiving NoBinding . According to the previous log file, the server returned NoBinding About 6 hours later dhcp6c executed remove ia and then dhcp6c will be able to get the IPV6 prefix.
I do have one more question though. When the server actively sends the RA message for the new address, the connection has been forced to disconnect, but dhcp6c doesn't seem to restart the dhcp request right away, which could mean that we could still lose the connection for a while.
Anyway, I'll be coming to try this this version to see how it will perform. This may still take a few days though and I'll come back with an update on the testing.
I think it might be effective to remove ia after receiving NoBinding .
Which means going out of spec on the client? I don't even know who is out of spec when so let's try not to break cases that may work for others.
When the server actively sends the RA message for the new address, the connection has been forced to disconnect
SLAAC and DHCPv6 addressing is more or less independent except for your ISP for a yet unclear reason. But even then rtsold should receive an advertise and restart dhcp6c via SIGHUP which for one reason or another it doesn't. There is more weirdness going on here than in most IPv6 troubleshooting cases so it's very hard to say.
Please note this client binary is for OPNsense 24.7. It's likely incompatible with 24.1.
Cheers, Franco
Which means going out of spec on the client? I don't even know who is out of spec when so let's try not to break cases that may work for others.
I can't actually say for sure, but I'd be happy to test the patch. So give me some time to see what happens after applying the patch.
Please note this client binary is for OPNsense 24.7. It's likely incompatible with 24.1.
Thanks note, I have updated to 24.7
Updated from 20240818: @fichtner I've confirmed that patch 1e6fa2e3f80c is working. After using this patch dhcp6c can get the new prefix normally when the problem happens. The system logs prove it.
2024-08-16T05:40:56 Error opnsense /usr/local/etc/rc.newwanipv6: The command '/sbin/route add -host -'inet6' 'fe80::1' 'fe80::1%igb0'' returned exit code '1', the output was 'add host fe80::1: gateway fe80::1%igb0 fib 0: route already in table'
2024-08-16T05:40:55 Notice dhcp6c got an expected reply, sleeping.
2024-08-16T05:40:55 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-08-16T05:40:55 Notice dhcp6c dhcp6c_script: REQUEST on igb0 renewal
2024-08-16T05:40:55 Notice dhcp6c dhcp6c_script: REQUEST on igb0 executing
2024-08-16T05:40:55 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-08-16T05:40:55 Notice dhcp6c removing server (ID: 00:03:00:06:f4:b5:aa:b0:8c:f8)
2024-08-16T05:40:55 Notice dhcp6c removing an event on igb0, state=REQUEST
2024-08-16T05:40:55 Notice dhcp6c add an address 240e:390:4722:6e61:a6bb:6dff:febe:5b03/64 on re0
2024-08-16T05:40:55 Notice dhcp6c create a prefix 240e:390:4722:6e61::/64 pltime=85781, vltime=85781
2024-08-16T05:40:55 Notice dhcp6c make an IA: PD-2
2024-08-16T05:40:55 Notice dhcp6c nameserver[0] fe80::1
2024-08-16T05:40:55 Notice dhcp6c Received REPLY for REQUEST
2024-08-16T05:40:55 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-08-16T05:40:55 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-08-16T05:40:55 Notice dhcp6c get DHCP option DNS, len 16
2024-08-16T05:40:55 Notice dhcp6c requested option: domain search list
2024-08-16T05:40:55 Notice dhcp6c requested option: DNS
2024-08-16T05:40:55 Notice dhcp6c get DHCP option option request, len 4
2024-08-16T05:40:55 Notice dhcp6c IA_PD prefix: 240e:390:4722:6e61::/64 pltime=85781 vltime=85781
2024-08-16T05:40:55 Notice dhcp6c get DHCP option IA_PD prefix, len 25
2024-08-16T05:40:55 Notice dhcp6c IA_PD: ID=2, T1=42890, T2=68624
2024-08-16T05:40:55 Notice dhcp6c get DHCP option IA_PD, len 41
2024-08-16T05:40:55 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-08-16T05:40:55 Notice dhcp6c get DHCP option server ID, len 10
2024-08-16T05:40:55 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-08-16T05:40:55 Notice dhcp6c get DHCP option client ID, len 10
2024-08-16T05:40:55 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-08-16T05:40:55 Notice dhcp6c reset a timer on igb0, state=REQUEST, timeo=0, retrans=983
2024-08-16T05:40:55 Notice dhcp6c send request to ff02::1:2%igb0
2024-08-16T05:40:55 Notice dhcp6c set IA_PD
2024-08-16T05:40:55 Notice dhcp6c set IA_PD prefix
2024-08-16T05:40:55 Notice dhcp6c set option request (len 4)
2024-08-16T05:40:55 Notice dhcp6c set elapsed time (len 2)
2024-08-16T05:40:55 Notice dhcp6c set server ID (len 10)
2024-08-16T05:40:55 Notice dhcp6c set client ID (len 10)
2024-08-16T05:40:55 Notice dhcp6c a new XID (b49241) is generated
2024-08-16T05:40:55 Notice dhcp6c Sending Request
2024-08-16T05:40:55 Notice dhcp6c picked a server (ID: 00:03:00:06:f4:b5:aa:b0:8c:f8)
2024-08-16T05:40:54 Notice dhcp6c reset timer for igb0 to 0.946024
2024-08-16T05:40:54 Notice dhcp6c server ID: 00:03:00:06:f4:b5:aa:b0:8c:f8, pref=7
2024-08-16T05:40:54 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-08-16T05:40:54 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-08-16T05:40:54 Notice dhcp6c get DHCP option DNS, len 16
2024-08-16T05:40:54 Notice dhcp6c preference: 7
2024-08-16T05:40:54 Notice dhcp6c get DHCP option preference, len 1
2024-08-16T05:40:54 Notice dhcp6c IA_PD prefix: 240e:390:4722:6e61::/64 pltime=85782 vltime=85782
2024-08-16T05:40:54 Notice dhcp6c get DHCP option IA_PD prefix, len 25
2024-08-16T05:40:54 Notice dhcp6c IA_PD: ID=2, T1=42891, T2=68625
2024-08-16T05:40:54 Notice dhcp6c get DHCP option IA_PD, len 41
2024-08-16T05:40:54 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-08-16T05:40:54 Notice dhcp6c get DHCP option server ID, len 10
2024-08-16T05:40:54 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-08-16T05:40:54 Notice dhcp6c get DHCP option client ID, len 10
2024-08-16T05:40:54 Notice dhcp6c receive advertise from fe80::1%igb0 on igb0
2024-08-16T05:40:54 Notice dhcp6c reset a timer on igb0, state=SOLICIT, timeo=0, retrans=1083
2024-08-16T05:40:54 Notice dhcp6c send solicit to ff02::1:2%igb0
2024-08-16T05:40:54 Notice dhcp6c set IA_PD
2024-08-16T05:40:54 Notice dhcp6c set option request (len 4)
2024-08-16T05:40:54 Notice dhcp6c set elapsed time (len 2)
2024-08-16T05:40:54 Notice dhcp6c set client ID (len 10)
2024-08-16T05:40:54 Notice dhcp6c a new XID (521a3e) is generated
2024-08-16T05:40:54 Notice dhcp6c Sending Solicit
2024-08-16T05:40:54 Notice dhcp6c got an expected reply, sleeping.
2024-08-16T05:40:54 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-08-16T05:40:54 Notice dhcp6c dhcp6c_script: REQUEST on igb0 renewal
2024-08-16T05:40:54 Notice dhcp6c dhcp6c_script: REQUEST on igb0 executing
2024-08-16T05:40:53 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-08-16T05:40:53 Notice dhcp6c removing an event on igb0, state=REQUEST
2024-08-16T05:40:53 Notice dhcp6c reset a timer on igb0, state=INIT, timeo=0, retrans=245
2024-08-16T05:40:53 Notice dhcp6c remove an address 240e:390:48e5:e8c1:a6bb:6dff:febe:5b03/64 on re0
2024-08-16T05:40:53 Notice dhcp6c remove a site prefix 240e:390:48e5:e8c1::/64
2024-08-16T05:40:53 Notice dhcp6c remove an IA: PD-2
2024-08-16T05:40:53 Notice dhcp6c received NotOnLink for PD-2
2024-08-16T05:40:53 Notice dhcp6c status code for PD-2: not on-link
2024-08-16T05:40:53 Notice dhcp6c update an IA: PD-2
2024-08-16T05:40:53 Notice dhcp6c nameserver[0] fe80::1
2024-08-16T05:40:53 Notice dhcp6c Received REPLY for REQUEST
2024-08-16T05:40:53 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-08-16T05:40:53 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-08-16T05:40:53 Notice dhcp6c get DHCP option DNS, len 16
2024-08-16T05:40:53 Notice dhcp6c requested option: domain search list
2024-08-16T05:40:53 Notice dhcp6c requested option: DNS
2024-08-16T05:40:53 Notice dhcp6c get DHCP option option request, len 4
2024-08-16T05:40:53 Notice dhcp6c status code: not on-link
2024-08-16T05:40:53 Notice dhcp6c get DHCP option status code, len 2
2024-08-16T05:40:53 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-08-16T05:40:53 Notice dhcp6c get DHCP option IA_PD, len 18
2024-08-16T05:40:53 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-08-16T05:40:53 Notice dhcp6c get DHCP option server ID, len 10
2024-08-16T05:40:53 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-08-16T05:40:53 Notice dhcp6c get DHCP option client ID, len 10
2024-08-16T05:40:53 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-08-16T05:40:53 Notice dhcp6c got an expected reply, sleeping.
2024-08-16T05:40:53 Notice dhcp6c script "/var/etc/dhcp6c_wan_script.sh" terminated
2024-08-16T05:40:53 Notice dhcp6c dhcp6c_script: RENEW on igb0 executing
2024-08-16T05:40:53 Notice dhcp6c executes /var/etc/dhcp6c_wan_script.sh
2024-08-16T05:40:53 Notice dhcp6c removing an event on igb0, state=RENEW
2024-08-16T05:40:53 Notice dhcp6c send request to ff02::1:2%igb0
2024-08-16T05:40:53 Notice dhcp6c set IA_PD
2024-08-16T05:40:53 Notice dhcp6c set IA_PD prefix
2024-08-16T05:40:53 Notice dhcp6c set option request (len 4)
2024-08-16T05:40:53 Notice dhcp6c set elapsed time (len 2)
2024-08-16T05:40:53 Notice dhcp6c set server ID (len 10)
2024-08-16T05:40:53 Notice dhcp6c set client ID (len 10)
2024-08-16T05:40:53 Notice dhcp6c a new XID (443c9a) is generated
2024-08-16T05:40:53 Notice dhcp6c Sending Request
2024-08-16T05:40:53 Notice dhcp6c reset a timer on igb0, state=REQUEST, timeo=0, retrans=904
2024-08-16T05:40:53 Notice dhcp6c re-establishing IA: PD-2
2024-08-16T05:40:53 Notice dhcp6c receive NoBinding for PD-2
2024-08-16T05:40:53 Notice dhcp6c status code for PD-2: no binding
2024-08-16T05:40:53 Notice dhcp6c update an IA: PD-2
2024-08-16T05:40:53 Notice dhcp6c nameserver[0] fe80::1
2024-08-16T05:40:53 Notice dhcp6c Received REPLY for RENEW
2024-08-16T05:40:53 Notice dhcp6c unknown or unexpected DHCP6 option vendor specific info, len 25
2024-08-16T05:40:53 Notice dhcp6c get DHCP option vendor specific info, len 25
2024-08-16T05:40:53 Notice dhcp6c get DHCP option DNS, len 16
2024-08-16T05:40:53 Notice dhcp6c status code: no binding
2024-08-16T05:40:53 Notice dhcp6c get DHCP option status code, len 2
2024-08-16T05:40:53 Notice dhcp6c IA_PD: ID=2, T1=0, T2=0
2024-08-16T05:40:53 Notice dhcp6c get DHCP option IA_PD, len 18
2024-08-16T05:40:53 Notice dhcp6c DUID: 00:03:00:06:f4:b5:aa:b0:8c:f8
2024-08-16T05:40:53 Notice dhcp6c get DHCP option server ID, len 10
2024-08-16T05:40:53 Notice dhcp6c DUID: 00:03:00:01:34:cf:f6:c5:fd:eb
2024-08-16T05:40:53 Notice dhcp6c get DHCP option client ID, len 10
2024-08-16T05:40:53 Notice dhcp6c receive reply from fe80::1%igb0 on igb0
2024-08-16T05:40:53 Notice dhcp6c send renew to ff02::1:2%igb0
2024-08-16T05:40:53 Notice dhcp6c set IA_PD
2024-08-16T05:40:53 Notice dhcp6c set IA_PD prefix
2024-08-16T05:40:53 Notice dhcp6c set option request (len 4)
2024-08-16T05:40:53 Notice dhcp6c set elapsed time (len 2)
2024-08-16T05:40:53 Notice dhcp6c set server ID (len 10)
2024-08-16T05:40:53 Notice dhcp6c set client ID (len 10)
2024-08-16T05:40:53 Notice dhcp6c a new XID (3448cd) is generated
2024-08-16T05:40:53 Notice dhcp6c Sending Renew
2024-08-16T05:40:53 Notice dhcp6c reset a timer on igb0, state=RENEW, timeo=0, retrans=10060
2024-08-16T05:40:53 Notice dhcp6c IA timeout for PD-2, state=ACTIVE
2024-08-16T05:34:52 Error opnsense /usr/local/etc/rc.newwanipv6: The command '/sbin/route add -host -'inet6' 'fe80::1' 'fe80::1%igb0'' returned exit code '1', the output was 'add host fe80::1: gateway fe80::1%igb0 fib 0: route already in table'
However, from what I can tell from grabbing the packets, dhcp6c acquiring the new prefix occurs about 10 minutes after disconnecting. This means that the network remains disconnected for that 10 minutes, and rtsold
doesn't seem to be specifically notifying dhcp6c of this.
Maybe we should open another issues regarding rtsold ?
I've provided the full system log and capture packets as attachments to make it easier to investigate the problem. debug_0816.zip
Ok, I've merged the fix for a future version and we should look into the rtsold situation. Close this one and carry on in src.git?
Ok, I've merged the fix for a future version and we should look into the rtsold situation. Close this one and carry on in src.git?
Ok, I will close this issue now.I will open a new issue in src.git later.
Describe the bug
In my use of opnsense, the IPV6 connection often disconnects after a few days (not at a fixed time). The problem occurs when I can see from the opnsense admin page that the device from the ISP has assigned a different IPV6 prefix to the WAN, but the LAN is still using an old IPV6 prefix. At this point no other device connected to the LAN can access the internet via IPV6, whereas the opnsense unit can access the IPV6 public address.
I believe the problem is caused by my ISP assigning new IPV6 prefixes from time to time and opnsense not being able to update the IPV6 prefixes on the LAN.
I turned on the debug log for dhcp6c.Here's the log when the problem happened.
Looking at the LOG, the problem occurs at “2024-07-18T21:59:23” and the ISP doesn't seem to have assigned us any IPV6, but according to the admin page, the WAN does get a new IPV6 prefix.![wan_eng_01](https://github.com/user-attachments/assets/39669a58-482d-437d-bf9c-a422986771c4)
After a problem occurs, PCs accessing the LAN can only access the opnsense LAN
opnsense hosting has normal access to the internet via IPV6
If you reset or reload the WAN interface after the problem occurs, it returns to normal.
Expected behavior
Losing IPV6 connectivity at irregular intervals is annoying, and the behavior I would expect should be that you shouldn't lose IPV6 connectivity altogether after changing prefixes.
Environment
OPNsense 24.1.10_3-amd64 Dell Optiplex 3070 MFF Intel(R) Core(TM) i3-8100T CPU @ 3.10GHz (4 cores, 4 threads) Network card: Intel I210 (WAN) Realtek NIC (LAN)