Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Patch request - ignore advertise messages with none of requested data and missed status codes #25

Closed
Greelan opened this issue Dec 7, 2020 · 11 comments
Closed

Patch request - ignore advertise messages with none of requested data and missed status codes #25

Greelan opened this issue Dec 7, 2020 · 11 comments
Assignees
@fichtner
Labels
bug Something isn't working

Comments

@Greelan
Copy link

Greelan commented Dec 7, 2020

I was hoping to get a sense of whether a wide-dhcpv6 patch that was introduced in the upstream in 2015 will make it into OPNsense.

The issue is this (as explained to me by my ISP). Whenever dhcp6c on OPNsense sends a release to my ISP, and then (as is usual) tries to send a solicit straight after the release to obtain a new lease, the ISP's BNG responds with a DHCPv6 UnspecFail advertise. Apparently, somewhere between the DHCPv6 proxy and DHCPv6 server running on the BNG, the release process has not been finalised (and so the lease is not considered available to the client again) when dhcp6c sends the new solicit, hence the UnspecFail response.

However, dhcp6c does not interpret this correctly and instead assumes the BNG is trying to advertise the prefix, and so dhcp6c sends a DHCPv6 request for a blank prefix back to the BNG. The BNG of course drops this as invalid. dhcp6c then eventually gives up trying to get a DHCPv6 lease, and accordingly no WAN GUA or IPv6 PD is received, until dhcp6c is reloaded or restarted.

The behaviour can be seen in these logs (anonymised):

2020-12-07T09:27:04	dhclient[59442]	My address (xxx.xxx.xxx.140) was deleted, dhclient exiting
2020-12-07T09:27:04	dhclient[78405]	Starting delete_old_states()
2020-12-07T09:27:04	dhclient[72525]	Comparing IPs: Old: xxx.xxx.xxx.xxx New:
2020-12-07T09:27:04	dhclient[44634]	Removing states from old IP 'xxx.xxx.xxx.140' (new IP '')
2020-12-07T09:27:04	dhclient[59442]	connection closed
2020-12-07T09:27:04	dhclient[59442]	exiting.
2020-12-07T09:27:04	dhclient[16850]	Starting delete_old_states()
2020-12-07T09:27:04	dhclient[94879]	Comparing IPs: Old: xxx.xxx.xxx.140 New:
2020-12-07T09:27:04	dhclient[42526]	Removing states from old IP 'xxx.xxx.xxx.140' (new IP '')
2020-12-07T09:27:04	dhclient[72953]	DHCPREQUEST on igb0 to 255.255.255.255 port 67
2020-12-07T09:27:04	dhclient[72953]	DHCPACK from xxx.xxx.xxx.1
2020-12-07T09:27:04	dhclient[23989]	Starting delete_old_states()
2020-12-07T09:27:04	dhclient[72164]	Comparing IPs: Old: xxx.xxx.xxx.140 New: xxx.xxx.xxx.140
2020-12-07T09:27:04	dhclient[39437]	New IP Address (igb0): xxx.xxx.xxx.140
2020-12-07T09:27:04	dhclient[52716]	New Subnet Mask (igb0): 255.255.252.0
2020-12-07T09:27:04	dhclient[95879]	New Broadcast Address (igb0): xxx.xxx.xxx.255
2020-12-07T09:27:04	dhclient[31371]	New Routers (igb0): xxx.xxx.xxx.1
2020-12-07T09:27:04	dhclient[79817]	route add default xxx.xxx.xxx.1
2020-12-07T09:27:04	dhclient[99820]	Creating resolv.conf
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'igb0'
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: On (IP address: xxx.xxx.xxx.140) (interface: WAN[wan]) (real interface: igb0).
2020-12-07T09:27:04	opnsense[6163]	plugins_configure hosts ()
2020-12-07T09:27:04	opnsense[6163]	plugins_configure hosts (execute task : dnsmasq_hosts_generate())
2020-12-07T09:27:04	opnsense[6163]	plugins_configure hosts (execute task : unbound_hosts_generate())
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: ROUTING: entering configure using 'wan'
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: ROUTING: IPv4 default gateway set to wan
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: ROUTING: setting IPv4 default route to xxx.xxx.xxx.1
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: ROUTING: keeping current default gateway 'xxx.xxx.xxx.1'
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: ROUTING: IPv6 default gateway set to wan
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: ROUTING: skipping IPv6 default route
2020-12-07T09:27:04	opnsense[6163]	plugins_configure monitor ()
2020-12-07T09:27:04	opnsense[6163]	plugins_configure monitor (execute task : dpinger_configure_do())
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: The WAN_DHCP6 monitor address is empty, skipping.
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: The WAN_DHCP monitor address is empty, skipping.
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: The OpenVPNv6 monitor address is empty, skipping.
2020-12-07T09:27:04	opnsense[6163]	/usr/local/etc/rc.newwanip: The OpenVPNv4 monitor address is empty, skipping.
2020-12-07T09:27:05	opnsense[6163]	plugins_configure vpn (,wan)
2020-12-07T09:27:05	kernel	pflog0: promiscuous mode disabled
2020-12-07T09:27:05	kernel	pflog0: promiscuous mode enabled
2020-12-07T09:27:05	opnsense[6163]	plugins_configure vpn (execute task : ipsec_configure_do(,wan))
2020-12-07T09:27:05	opnsense[6163]	plugins_configure vpn (execute task : openvpn_configure_do(,wan))
2020-12-07T09:27:05	opnsense[6163]	/usr/local/etc/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (,wan)
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (execute task : dyndns_configure_do(,wan))
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (execute task : ntpd_configure_defer())
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (execute task : opendns_configure_do())
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (execute task : openssh_configure_do(,wan))
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (execute task : unbound_configure_do(,wan))
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (execute task : vxlan_configure_interface())
2020-12-07T09:27:05	opnsense[6163]	plugins_configure newwanip (execute task : webgui_configure_do(,wan))
2020-12-07T09:27:05	dhclient[72953]	bound to xxx.xxx.xxx.140 -- renewal in 900 seconds.
2020-12-07T09:27:05	opnsense[17528]	/usr/local/etc/rc.configure_interface: Accept router advertisements on interface igb0
2020-12-07T09:27:05	dhcp6c[7137]	RTSOLD script - Sending SIGHUP to dhcp6c
2020-12-07T09:27:05	dhcp6c[41467]	restarting
2020-12-07T09:27:05	dhcp6c[41467]	Start address release
2020-12-07T09:27:05	dhcp6c[41467]	release an IA: NA-0
2020-12-07T09:27:05	dhcp6c[41467]	reset a timer on igb0, state=RELEASE, timeo=0, retrans=1033
2020-12-07T09:27:05	dhcp6c[41467]	Sending Release
2020-12-07T09:27:05	dhcp6c[41467]	a new XID (d304b7) is generated
2020-12-07T09:27:05	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:05	dhcp6c[41467]	set server ID (len 14)
2020-12-07T09:27:05	dhcp6c[41467]	set IA address
2020-12-07T09:27:05	dhcp6c[41467]	set identity association
2020-12-07T09:27:05	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:05	dhcp6c[41467]	send release to ff02::1:2%igb0
2020-12-07T09:27:05	dhcp6c[41467]	remove an IA: NA-0
2020-12-07T09:27:05	dhcp6c[41467]	remove an address xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:8671
2020-12-07T09:27:05	dhcp6c[41467]	failed to remove an address on igb0: Can't assign requested address
2020-12-07T09:27:05	dhcp6c[41467]	reset a timer on igb0, state=INIT, timeo=0, retrans=174
2020-12-07T09:27:05	dhcp6c[41467]	Start address release
2020-12-07T09:27:05	dhcp6c[41467]	release an IA: PD-0
2020-12-07T09:27:05	dhcp6c[41467]	reset a timer on igb0, state=RELEASE, timeo=0, retrans=930
2020-12-07T09:27:05	dhcp6c[41467]	Sending Release
2020-12-07T09:27:05	dhcp6c[41467]	a new XID (1527b4) is generated
2020-12-07T09:27:05	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:05	dhcp6c[41467]	set server ID (len 14)
2020-12-07T09:27:05	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:05	dhcp6c[41467]	set IA_PD prefix
2020-12-07T09:27:05	dhcp6c[41467]	set IA_PD
2020-12-07T09:27:05	dhcp6c[41467]	send release to ff02::1:2%igb0
2020-12-07T09:27:05	dhcp6c[41467]	remove an IA: PD-0
2020-12-07T09:27:05	dhcp6c[41467]	remove a site prefix xxxx:xxxx:xxxx:xxxx::/56
2020-12-07T09:27:05	dhcp6c[41467]	remove an address xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:3261/64 on igb1_vlan66
2020-12-07T09:27:05	dhcp6c[41467]	remove an address xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:3261/64 on igb1
2020-12-07T09:27:05	dhcp6c[41467]	remove an address xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:3261/64 on igb1_vlan10
2020-12-07T09:27:05	dhcp6c[41467]	remove an address xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:3261/64 on igb1_vlan99
2020-12-07T09:27:05	dhcp6c[41467]	remove an address xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:3261/64 on igb1_vlan49
2020-12-07T09:27:05	dhcp6c[41467]	reset a timer on igb0, state=INIT, timeo=0, retrans=16
2020-12-07T09:27:05	dhcp6c[41467]	removing an event on igb0, state=INIT
2020-12-07T09:27:05	dhcp6c[41467]	removing an event on igb0, state=INIT
2020-12-07T09:27:05	dhcp6c[41467]	<3>[interface] (9)
2020-12-07T09:27:05	dhcp6c[41467]	<5>[igb0] (4)
2020-12-07T09:27:05	dhcp6c[41467]	<3>begin of closure [{] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[send] (4)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[ia-na] (5)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[0] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of sentence [;] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>comment [# request stateful address] (26)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of sentence [;] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<5>[igb1_vlan10] (11)
2020-12-07T09:27:05	dhcp6c[41467]	<3>begin of closure [{] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[sla-id] (6)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[16] (2)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of sentence [;] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[sla-len] (7)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[8] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of sentence [;] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of closure [}] (1)
2020-12-07T09:27:05	dhcp6c[41467]	called
2020-12-07T09:27:05	dhcp6c[41467]	called
2020-12-07T09:27:05	dhcp6c[41467]	duplicated interface: igb0
2020-12-07T09:27:05	dhcp6c[41467]	<3>[interface] (9)
2020-12-07T09:27:05	dhcp6c[41467]	<5>[igb0] (4)
2020-12-07T09:27:05	dhcp6c[41467]	<3>begin of closure [{] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[send] (4)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[ia-na] (5)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[0] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of sentence [;] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>comment [# we'd like some nameservers please] (35)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[id-assoc] (8)
2020-12-07T09:27:05	dhcp6c[41467]	<13>[na] (2)
2020-12-07T09:27:05	dhcp6c[41467]	<13>[0] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<13>begin of closure [{] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of closure [}] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>end of sentence [;] (1)
2020-12-07T09:27:05	dhcp6c[41467]	<3>[id-assoc] (8)
2020-12-07T09:27:05	dhcp6c[41467]	<13>[pd] (2)
2020-12-07T09:27:05	dhcp6c[41467]	<13>[0] (1)
2020-12-07T09:27:05	opnsense[17528]	/usr/local/etc/rc.configure_interface: ROUTING: entering configure using 'wan'
2020-12-07T09:27:05	dhcp6c[41467]	receive reply from fe80::2a2:ff:feb2:c2%igb0 on igb0
2020-12-07T09:27:05	dhcp6c[41467]	get DHCP option client ID, len 14
2020-12-07T09:27:05	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:60
2020-12-07T09:27:05	dhcp6c[41467]	get DHCP option server ID, len 14
2020-12-07T09:27:05	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:d0
2020-12-07T09:27:05	dhcp6c[41467]	get DHCP option identity association, len 63
2020-12-07T09:27:05	dhcp6c[41467]	IA_NA: ID=0, T1=0, T2=0
2020-12-07T09:27:05	dhcp6c[41467]	get DHCP option status code, len 47
2020-12-07T09:27:05	dhcp6c[41467]	status code: success
2020-12-07T09:27:05	dhcp6c[41467]	get DHCP option status code, len 41
2020-12-07T09:27:05	dhcp6c[41467]	status code: success
2020-12-07T09:27:05	dhcp6c[41467]	Received REPLY for RELEASE
2020-12-07T09:27:05	dhcp6c[41467]	status code: success
2020-12-07T09:27:05	dhcp6c[33283]	dhcp6c RELEASE on igb0
2020-12-07T09:27:05	dhcp6c[80681]	dhcp6c RELEASE on igb0 - running newipv6
2020-12-07T09:27:05	opnsense[99831]	/usr/local/etc/rc.newwanipv6: IPv6 renewal is starting on 'igb0'
2020-12-07T09:27:05	opnsense[17528]	/usr/local/etc/rc.configure_interface: ROUTING: IPv4 default gateway set to wan
2020-12-07T09:27:05	opnsense[17528]	/usr/local/etc/rc.configure_interface: ROUTING: setting IPv4 default route to xxx.xxx.xxx.1
2020-12-07T09:27:05	opnsense[99831]	/usr/local/etc/rc.newwanipv6: On (IP address: ) (interface: WAN[wan]) (real interface: igb0).
2020-12-07T09:27:05	opnsense[99831]	/usr/local/etc/rc.newwanipv6: Failed to detect IP for WAN[wan]
2020-12-07T09:27:05	opnsense[17528]	/usr/local/etc/rc.configure_interface: ROUTING: keeping current default gateway 'xxx.xxx.xxx.1'
2020-12-07T09:27:05	opnsense[17528]	/usr/local/etc/rc.configure_interface: ROUTING: IPv6 default gateway set to wan
2020-12-07T09:27:05	opnsense[17528]	/usr/local/etc/rc.configure_interface: ROUTING: skipping IPv6 default route
2020-12-07T09:27:05	dhcp6c[41467]	script "/var/etc/dhcp6c_wan_script.sh" terminated
2020-12-07T09:27:05	dhcp6c[41467]	removing an event on igb0, state=RELEASE
2020-12-07T09:27:05	dhcp6c[41467]	got an expected reply, sleeping.
2020-12-07T09:27:05	opnsense[17528]	plugins_configure ipsec (1,wan)
2020-12-07T09:27:05	opnsense[17528]	plugins_configure ipsec (execute task : ipsec_configure_do(1,wan))
2020-12-07T09:27:05	opnsense[17528]	plugins_configure dhcp (1)
2020-12-07T09:27:05	opnsense[17528]	plugins_configure dhcp (execute task : dhcpd_dhcp_configure(1))
2020-12-07T09:27:06	dhcp6c[41467]	Sending Solicit
2020-12-07T09:27:06	dhcp6c[41467]	a new XID (2efce5) is generated
2020-12-07T09:27:06	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:06	dhcp6c[41467]	set identity association
2020-12-07T09:27:06	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:06	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:27:06	dhcp6c[41467]	set IA_PD prefix
2020-12-07T09:27:06	dhcp6c[41467]	set IA_PD
2020-12-07T09:27:06	dhcp6c[41467]	send solicit to ff02::1:2%igb0
2020-12-07T09:27:06	dhcp6c[41467]	reset a timer on igb0, state=SOLICIT, timeo=0, retrans=1085
2020-12-07T09:27:06	dhcp6c[41467]	receive advertise from fe80::2a2:ff:feb2:c2%igb0 on igb0
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option server ID, len 10
2020-12-07T09:27:06	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:28
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option client ID, len 14
2020-12-07T09:27:06	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:60
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option status code, len 2
2020-12-07T09:27:06	dhcp6c[41467]	status code: unspec failure
2020-12-07T09:27:06	dhcp6c[41467]	server ID: xx:xx:xx:xx:xx:xx:xx:xx:xx:28, pref=-1
2020-12-07T09:27:06	dhcp6c[41467]	reset timer for igb0 to 0.992740
2020-12-07T09:27:06	dhcp6c[41467]	receive advertise from fe80::2a2:ff:feb2:c2%igb0 on igb0
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option server ID, len 10
2020-12-07T09:27:06	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:28
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option client ID, len 14
2020-12-07T09:27:06	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:60
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option status code, len 2
2020-12-07T09:27:06	dhcp6c[41467]	status code: unspec failure
2020-12-07T09:27:06	dhcp6c[41467]	server ID: xx:xx:xx:xx:xx:xx:xx:xx:xx:28, pref=-1
2020-12-07T09:27:06	dhcp6c[41467]	duplicated server (ID: xx:xx:xx:xx:xx:xx:xx:xx:xx:28)
2020-12-07T09:27:06	opnsense[17528]	plugins_configure dns (1)
2020-12-07T09:27:06	opnsense[17528]	plugins_configure dns (execute task : dnsmasq_configure_do(1))
2020-12-07T09:27:06	opnsense[17528]	plugins_configure dns (execute task : unbound_configure_do(1))
2020-12-07T09:27:06	dhcp6c[41467]	Sending Release
2020-12-07T09:27:06	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:06	dhcp6c[41467]	set server ID (len 14)
2020-12-07T09:27:06	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:06	dhcp6c[41467]	set IA_PD prefix
2020-12-07T09:27:06	dhcp6c[41467]	set IA_PD
2020-12-07T09:27:06	dhcp6c[41467]	send release to ff02::1:2%igb0
2020-12-07T09:27:06	dhcp6c[41467]	reset a timer on igb0, state=RELEASE, timeo=1, retrans=1770
2020-12-07T09:27:06	dhcp6c[41467]	receive reply from fe80::2a2:ff:feb2:c2%igb0 on igb0
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option client ID, len 14
2020-12-07T09:27:06	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:60
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option server ID, len 14
2020-12-07T09:27:06	dhcp6c[41467]	DUID: xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:d0
2020-12-07T09:27:06	dhcp6c[41467]	get DHCP option status code, len 2
2020-12-07T09:27:06	dhcp6c[41467]	status code: no binding
2020-12-07T09:27:06	dhcp6c[41467]	Received REPLY for RELEASE
2020-12-07T09:27:06	dhcp6c[41467]	status code: no binding
2020-12-07T09:27:06	dhcp6c[41467]	executes /var/etc/dhcp6c_wan_script.sh
2020-12-07T09:27:06	dhcp6c[44127]	dhcp6c RELEASE on igb0
2020-12-07T09:27:06	dhcp6c[60627]	dhcp6c RELEASE on igb0 - running newipv6
2020-12-07T09:27:06	opnsense[56651]	/usr/local/etc/rc.newwanipv6: IPv6 renewal is starting on 'igb0'
2020-12-07T09:27:06	opnsense[56651]	/usr/local/etc/rc.newwanipv6: On (IP address: ) (interface: WAN[wan]) (real interface: igb0).
2020-12-07T09:27:06	opnsense[56651]	/usr/local/etc/rc.newwanipv6: Failed to detect IP for WAN[wan]
2020-12-07T09:27:06	dhcp6c[41467]	script "/var/etc/dhcp6c_wan_script.sh" terminated
2020-12-07T09:27:06	dhcp6c[41467]	removing an event on igb0, state=RELEASE
2020-12-07T09:27:06	dhcp6c[41467]	got an expected reply, sleeping.
2020-12-07T09:27:07	dhcp6c[41467]	picked a server (ID: xx:xx:xx:xx:xx:xx:xx:xx:xx:28)
2020-12-07T09:27:07	dhcp6c[41467]	Sending Request
2020-12-07T09:27:07	dhcp6c[41467]	a new XID (2f1201) is generated
2020-12-07T09:27:07	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:07	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:27:07	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:07	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:27:07	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:27:07	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=0, retrans=907
2020-12-07T09:27:07	dhcp6c[41467]	Sending Request
2020-12-07T09:27:07	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:07	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:27:07	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:07	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:27:07	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:27:07	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=1, retrans=1895
2020-12-07T09:27:09	dhcp6c[41467]	Sending Request
2020-12-07T09:27:09	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:09	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:27:09	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:09	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:27:09	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:27:09	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=2, retrans=3731
2020-12-07T09:27:13	dhcp6c[41467]	Sending Request
2020-12-07T09:27:13	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:13	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:27:13	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:13	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:27:13	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:27:13	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=3, retrans=7516
2020-12-07T09:27:21	dhcp6c[41467]	Sending Request
2020-12-07T09:27:21	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:21	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:27:21	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:21	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:27:21	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:27:21	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=4, retrans=14760
2020-12-07T09:27:35	dhcp6c[41467]	Sending Request
2020-12-07T09:27:35	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:27:35	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:27:35	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:27:35	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:27:35	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:27:35	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=5, retrans=28144
2020-12-07T09:28:03	dhcp6c[41467]	Sending Request
2020-12-07T09:28:03	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:28:03	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:28:03	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:28:03	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:28:03	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:28:03	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=6, retrans=31284
2020-12-07T09:28:35	dhcp6c[41467]	Sending Request
2020-12-07T09:28:35	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:28:35	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:28:35	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:28:35	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:28:35	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:28:35	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=7, retrans=32607
2020-12-07T09:29:07	dhcp6c[41467]	Sending Request
2020-12-07T09:29:07	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:29:07	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:29:07	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:29:07	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:29:07	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:29:07	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=8, retrans=31383
2020-12-07T09:29:39	dhcp6c[41467]	Sending Request
2020-12-07T09:29:39	dhcp6c[41467]	set client ID (len 14)
2020-12-07T09:29:39	dhcp6c[41467]	set server ID (len 10)
2020-12-07T09:29:39	dhcp6c[41467]	set elapsed time (len 2)
2020-12-07T09:29:39	dhcp6c[41467]	set option request (len 4)
2020-12-07T09:29:39	dhcp6c[41467]	send request to ff02::1:2%igb0
2020-12-07T09:29:39	dhcp6c[41467]	reset a timer on igb0, state=REQUEST, timeo=9, retrans=30951
2020-12-07T09:30:10	dhcp6c[41467]	no responses were received
2020-12-07T09:30:10	dhcp6c[41467]	removing an event on igb0, state=REQUEST
2020-12-07T09:30:10	dhcp6c[41467]	removing server (ID: xx:xx:xx:xx:xx:xx:xx:xx:xx:28)

The BNG's behaviour (my ISP uses Cisco routers) is actually RFC compliant, according to my ISP (and I understand Cisco, with whom my ISP has apparently been discussing the issue). Per RFC 3315 (https://tools.ietf.org/html/rfc3315#section-15):

If a server receives a message that contains options it should not contain (such as an Information-request message with an IA option), is missing options that it should contain, or is otherwise not valid, it MAY send a Reply (or Advertise as appropriate) with a Server Identifier option, a Client Identifier option if one was included in the message and a Status Code option with status UnSpecFail.

Same for the updated RFC 8415 (https://tools.ietf.org/html/rfc8415#section-16):

If a server receives a message that it considers invalid, it MAY send a Reply message (or Advertise message, as appropriate) with a Server Identifier option (see Section 21.3), a Client Identifier option (see Section 21.2) (if one was included in the message), and a Status Code option (see Section 21.13) with status UnspecFail.

The issue of wide-dhcpv6 / dhcp6c not responding correctly to UnspecFail advertises was, I am told, addressed in the upstream. My research suggests that occurred in 2015: https://sourceforge.net/p/wide-dhcpv6/bugs/34/. Specifically, item 4:

4) dhcpv6: ignore advertise messages with none of requested data and missed status codes.

This patch was implemented in Debian in March 2018: https://metadata.ftp-master.debian.org/changelogs//main/w/wide-dhcpv6/wide-dhcpv6_20080615-23_changelog. Specifically, patch 0018:

- Add patch 0018 to ignore advertise messages with none of requested data and missed status codes.
Thanks to Roman Mamedov for the report and Evgeniy Manachkin for the patch (Closes: #765453).

What I understand to be the content of the patch is attached: 0018-dhcpv6-ignore-advertise-messages-with-none-of-reques.patch.txt

My ISP tells me that they believe Netcomm has implemented the patch, and I have seen comments from Ubiquiti on their forums that they plan to implement the patch, at least for their Edgerouter line.

But this patch does not appear to have made it into FreeBSD or OPNsense.

Curiously, some of the items addressed by the upstream patch in 2015 have been implemented - in FreeBSD in Jan 2016 (based on the descriptions in https://www.freshports.org/net/dhcp6 for version 20080615_4) and in OPNsense in December 2016 (based on the commit descriptions in https://github.com/opnsense/dhcp6c/commits/master). But not item 4.

Is there any prospect of this patch being implemented in OPNsense?
fichtner added a commit that referenced this issue Dec 7, 2020
@fichtner
dhcp6c: ignore advertise messages with none of requested data and mis…
437b308 
…sed status codes

PR: #25
Taken from: Evgeniy Manachkin <sfstudio@mail.ru>
Also see: https://sourceforge.net/p/wide-dhcpv6/bugs/34/
@fichtner fichtner self-assigned this Dec 7, 2020
@fichtner fichtner added the bug Something isn't working label Dec 7, 2020
@fichtner
Copy link
Member

fichtner commented Dec 7, 2020

Hi @Greelan,

Thanks for the detailed context. Is 437b308 + cff2641 what you are looking for? :)

If you need a test package I can provide one tomorrow.

Cheers,
Franco

@Greelan
Copy link
Author

Greelan commented Dec 7, 2020

Wow, incredible response time! Thank you.

I will check out the commits but given my C coding days are more than 25 years ago, I likely will have little to add ;) (also the reason why I didn't create a PR myself). Happy to test though.

Again, thanks for being so responsive.

@Greelan
Copy link
Author

Greelan commented Dec 8, 2020

The commits look consistent with the Debian patch contents (with the d_printf function adjustment to match the OPNsense context). Here's hoping it works!

@Greelan
Copy link
Author

Greelan commented Dec 8, 2020

Actually, I do note that these changes in the Debian patch aren't in your commit (they relate to lines 1266 and 1269 of OPNsense's dhcp6c):

@@ -1484,10 +1484,10 @@ client6_recv()
 
 	switch(dh6->dh6_msgtype) {
 	case DH6_ADVERTISE:
-		(void)client6_recvadvert(ifp, dh6, len, &optinfo);
+		client6_recvadvert(ifp, dh6, len, &optinfo);
 		break;
 	case DH6_REPLY:
-		(void)client6_recvreply(ifp, dh6, len, &optinfo);
+		client6_recvreply(ifp, dh6, len, &optinfo);

Presume there is a reason not to add these?

@fichtner
Copy link
Member

fichtner commented Dec 8, 2020

I omitted the non-functional changes. I presume the person doing the patch neither cared about -Werror or 80 character line limits. 😉 The tabs were also off in some functional lines so the end result looks a bit different.

Also just for readability it would be better to do non-functional updates in separate commits.

@fichtner
Copy link
Member

fichtner commented Dec 8, 2020

To test:

# pkg add -f https://pkg.opnsense.org/FreeBSD:12:amd64/20.7/misc/dhcp6c-20200512_1.txz

To revert:

# opnsense-revert dhcp6c

@Greelan
Copy link
Author

Greelan commented Dec 8, 2020 •
edited

Thank you. Initial testing looks good. I see in the logs dhcp6c receiving an UnspecFail status code, and as a consequence reporting advertise contains no address/prefix. So it resends the solicit. Sometimes the process is repeated, ie it receives another UnspecFail status code. Eventually it receives a correct advertise and then successfully requests the address and prefix.

I will continue to monitor, but it is looking positive. :)

@Greelan
Copy link
Author

Greelan commented Dec 10, 2020

Heads up that I am still seeing some odd behaviour with dhcp6c.

The patch does address the issue of dhcp6c wrongly responding to an UnspecFail as if it was an address/prefix advertise. It sends another solicit instead, until an address/prefix is actually received.

However, I have noticed on at least one occasion dhcp6c sending another release immediately after receiving an address/prefix. It then sends a request, but that request is ineffective because of the release. The end result is that no address/prefix is received despite repeated requests being made.

The odd behaviour is the sending of the release - it is not clear why that happens at that point in the process.

I will post some logs when I get a chance later, to show the sequence. I will also do some more testing to see whether this is consistent behaviour or happens only intermittently.

@Greelan
Copy link
Author

Greelan commented Dec 10, 2020

Attached are the promised logs: dhcplogs.txt

This shows a reload event on the WAN (Interfaces->Overview->WAN->Reload), from when dhcp6c is SIGHUPed. A release is sent, a reply to the release is received, and a solicit is then sent. The first response is an UnspecFail. So dhcp6c sends another solicit. This time the response is to advertise a GUA for the WAN and a prefix.

At this point it would be expected that dhcp6c would request the address and prefix. But first another release is sent, and replied to, before the request is made. Presumably because of the release, the request is not responded to, so it is repeated.

The logs then show another reload event. On this occasion, the sequence follows as expected - release, response, solicit, advertise, request, response. There is no UnspecFail on this occasion because the dhcpv6 server and proxy don't have a lease assigned to the client.

In the first reload event, there is a release both after the GUA/prefix is received, and also immediately after the UnspecFail is received (so: UnspecFail response, release (no response), solicit, response, release, response, request...).

I don't profess to know a lot about dhcp6c, but I wonder whether the two releases are related? Eg, is the second based off a timer after the first? Should the first be happening at all?

While not scientific, I did do some more testing to see if I could replicate the behaviour, by hitting reload on the WAN again. I couldn't replicate the behaviour. On the first occasion, the UnspecFail response was followed by a release being sent, but then the solicit, response and request sequence happened as expected. On the second occasion, the sequence was: UnspecFail, solicit, UnspecFail, solicit, response, request - which I would have thought is the expected behaviour with the patch.

My initial testing straight after installing the patch also did not exhibit the behaviour I just experienced today. So it is a bit of a mystery.

Sorry I can't shed more light.

@Greelan
Copy link
Author

Greelan commented Dec 10, 2020

BTW, an aside on the logs. I had to run OPNsense's logs through tail -r to get them into reverse order, which I find more natural to read. Not sure if I am missing something, but is there no way of having the GUI display OPNsense's logs in reverse order (oldest to newest)? I thought I saw on some screenshots online of an earlier version a checkbox for exactly that, but it seems to have disappeared.

@thelittlefireman thelittlefireman mentioned this issue Jan 11, 2021
Closed
2 tasks
@fichtner
Copy link
Member

fichtner commented Jan 20, 2021 •
edited

@Greelan use clog -f for tail -f or clog for cat behaviour. I haven't looked closer yet. We may be looking at an implementation limitation in dhcp6c as the HUP was added by us so the only way to reload prior was stopping and starting so the same lease will very likely not be acquired anyway.

@Greelan Greelan closed this as completed May 2, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@fichtner fichtner

Labels
bug Something isn't working
Milestone
No milestone
Development

No branches or pull requests
2 participants
@fichtner @Greelan