DHCPv6 Client Broken in latest snapshot

[jimp]

@darkfire said in DHCPv6 Client Broken in latest snapshot:

I have the exact same problem with my DHCPv6 Client since the last update to 2.4.3-RELEASE-p1.

Are you also using "Do not wait for RA"?

[darkfire]

Yes, i do. Without “Do not wait for RA” the dhcp6c client will not start anymore.

/var/etc/dhcp6c_wan.conf

interface em0 {
	send ia-pd 0;
	script "/var/etc/dhcp6c_wan_script.sh";
};
id-assoc pd { };

logs with “Do not wait for RA”

May 29 23:02:14 	dhcp6c 	53193 	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
May 29 23:02:14 	dhcp6c 	53193 	failed initialize control message authentication
May 29 23:02:14 	dhcp6c 	53193 	skip opening control port
May 29 23:02:15 	dhcp6c 	53211 	Sending Solicit
May 29 23:02:15 	dhcp6c 	53211 	transmit failed: Can't assign requested address
May 29 23:02:16 	dhcp6c 	53211 	Sending Solicit
May 29 23:02:16 	dhcp6c 	53211 	transmit failed: Can't assign requested address 

process list

ps aux | grep dhcp6c
root   53211   0.0  0.1   8380  2364  -  Is   23:02       0:00.00 /usr/local/sbin/dhcp6c -d -c /var/etc/dhcp6c_wan.conf -p /var/run/dhcp6c_em0.pid em0

[jimp]

@darkfire said in DHCPv6 Client Broken in latest snapshot:

Without “Do not wait for RA” the dhcp6c client will not start anymore.

So it fails without that enabled? Or it fails both ways but with different errors?

[bimmerdriver]

My system behaves differently. If I disable do not wait for ra, dhcp6c never runs, because it's waiting for an RA, which will not be sent. Also, the error message is different.

[darkfire]

If i disable “Do not wait for RA” the client won't start. If i enable “Do not wait for RA” the client starts, but I do not get a prefix delegation.

[bimmerdriver]

I'm bumping this thread to see if anyone else is experiencing this issue. I'm dead in the water trying to find out the cause, at least without the snapshots from the April time frame.

[jimp]

I haven't seen any additional complaints, and though I have kept one of my boxes here configured with "do not wait for RA", I have yet to see the same errors others have posted here.

The error messages above, transmit failed: Can't assign requested address, would seem to imply that an address disappeared from the interface at some point but it's a fairly generic error even in the source. And since there is no address specified in the config file, that makes me curious how that is happening. The previous error, transmit failed: Input/output error is also very generic.

If you can, please go into the WAN options in the dhcp6 section and check Start DHCP6 client in debug mode and see if anything more informative gets put in the logs, and post anything in the logs from dhcp6c.

[bimmerdriver]

I enabled DHCP debug. The DHCP log from the start of a reboot is below. The only thing that appears to be abnormal is the transmit failed: Input/output error.

Jun 9 09:21:41	dhcp6c	11661	reset a timer on hn1, state=SOLICIT, timeo=5, retrans=31928
Jun 9 09:21:41	dhcp6c	11661	transmit failed: Input/output error
Jun 9 09:21:41	dhcp6c	11661	set IA_PD
Jun 9 09:21:41	dhcp6c	11661	set option request (len 4)
Jun 9 09:21:41	dhcp6c	11661	set elapsed time (len 2)
Jun 9 09:21:41	dhcp6c	11661	set client ID (len 14)
Jun 9 09:21:41	dhcp6c	11661	Sending Solicit
Jun 9 09:21:34	dhcpd		Server starting service.
Jun 9 09:21:34	dhcpd		Sending on Socket/fallback/fallback-net
Jun 9 09:21:34	dhcpd		Sending on BPF/hn0/00:15:5d:5c:e2:31/192.168.1.0/24
Jun 9 09:21:34	dhcpd		Listening on BPF/hn0/00:15:5d:5c:e2:31/192.168.1.0/24
Jun 9 09:21:33	dhcpd		Wrote 1 leases to leases file.
Jun 9 09:21:33	dhcpd		For info, please visit https://www.isc.org/software/dhcp/
Jun 9 09:21:33	dhcpd		All rights reserved.
Jun 9 09:21:33	dhcpd		Copyright 2004-2018 Internet Systems Consortium.
Jun 9 09:21:33	dhcpd		Internet Systems Consortium DHCP Server 4.3.6-P1
Jun 9 09:21:33	dhcpd		PID file: /var/run/dhcpd.pid
Jun 9 09:21:33	dhcpd		Database file: /var/db/dhcpd.leases
Jun 9 09:21:33	dhcpd		Config file: /etc/dhcpd.conf
Jun 9 09:21:33	dhcpd		For info, please visit https://www.isc.org/software/dhcp/
Jun 9 09:21:33	dhcpd		All rights reserved.
Jun 9 09:21:33	dhcpd		Copyright 2004-2018 Internet Systems Consortium.
Jun 9 09:21:33	dhcpd		Internet Systems Consortium DHCP Server 4.3.6-P1
Jun 9 09:21:25	dhcp6c	11661	reset a timer on hn1, state=SOLICIT, timeo=4, retrans=16326
Jun 9 09:21:25	dhcp6c	11661	transmit failed: Input/output error
Jun 9 09:21:25	dhcp6c	11661	set IA_PD
Jun 9 09:21:25	dhcp6c	11661	set option request (len 4)
Jun 9 09:21:25	dhcp6c	11661	set elapsed time (len 2)
Jun 9 09:21:25	dhcp6c	11661	set client ID (len 14)
Jun 9 09:21:25	dhcp6c	11661	Sending Solicit
Jun 9 09:21:17	dhcp6c	11661	reset a timer on hn1, state=SOLICIT, timeo=3, retrans=8065
Jun 9 09:21:17	dhcp6c	11661	transmit failed: Input/output error
Jun 9 09:21:17	dhcp6c	11661	set IA_PD
Jun 9 09:21:17	dhcp6c	11661	set option request (len 4)
Jun 9 09:21:17	dhcp6c	11661	set elapsed time (len 2)
Jun 9 09:21:17	dhcp6c	11661	set client ID (len 14)
Jun 9 09:21:17	dhcp6c	11661	Sending Solicit
Jun 9 09:21:13	dhcp6c	11661	reset a timer on hn1, state=SOLICIT, timeo=2, retrans=3982
Jun 9 09:21:13	dhcp6c	11661	transmit failed: Input/output error
Jun 9 09:21:13	dhcp6c	11661	set IA_PD
Jun 9 09:21:13	dhcp6c	11661	set option request (len 4)
Jun 9 09:21:13	dhcp6c	11661	set elapsed time (len 2)
Jun 9 09:21:13	dhcp6c	11661	set client ID (len 14)
Jun 9 09:21:13	dhcp6c	11661	Sending Solicit
Jun 9 09:21:11	dhcp6c	11661	reset a timer on hn1, state=SOLICIT, timeo=1, retrans=2083
Jun 9 09:21:11	dhcp6c	11661	transmit failed: Input/output error
Jun 9 09:21:11	dhcp6c	11661	set IA_PD
Jun 9 09:21:11	dhcp6c	11661	set option request (len 4)
Jun 9 09:21:11	dhcp6c	11661	set elapsed time (len 2)
Jun 9 09:21:11	dhcp6c	11661	set client ID (len 14)
Jun 9 09:21:11	dhcp6c	11661	Sending Solicit
Jun 9 09:21:09	dhcp6c	11661	reset a timer on hn1, state=SOLICIT, timeo=0, retrans=1091
Jun 9 09:21:09	dhcp6c	11661	transmit failed: Input/output error
Jun 9 09:21:09	dhcp6c	11661	set IA_PD
Jun 9 09:21:09	dhcp6c	11661	set option request (len 4)
Jun 9 09:21:09	dhcp6c	11661	set elapsed time (len 2)
Jun 9 09:21:09	dhcp6c	11661	set client ID (len 14)
Jun 9 09:21:09	dhcp6c	11661	a new XID (1bb44a) is generated
Jun 9 09:21:09	dhcp6c	11661	Sending Solicit
Jun 9 09:21:09	dhcp6c	11661	reset a timer on hn1, state=INIT, timeo=0, retrans=891
Jun 9 09:21:09	dhcp6c	11654	called
Jun 9 09:21:09	dhcp6c	11654	called
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>end of closure [}] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>end of closure [}] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[8] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[sla-len] (7)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[0] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[sla-id] (6)
Jun 9 09:21:09	dhcp6c	11654	<3>begin of closure [{] (1)
Jun 9 09:21:09	dhcp6c	11654	<5>[hn0] (3)
Jun 9 09:21:09	dhcp6c	11654	<3>[prefix-interface] (16)
Jun 9 09:21:09	dhcp6c	11654	<13>begin of closure [{] (1)
Jun 9 09:21:09	dhcp6c	11654	<13>[0] (1)
Jun 9 09:21:09	dhcp6c	11654	<13>[pd] (2)
Jun 9 09:21:09	dhcp6c	11654	<3>[id-assoc] (8)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>end of closure [}] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>comment [# we'd like nameservers and RTSOLD to do all the work] (53)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>["/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh"] (46)
Jun 9 09:21:09	dhcp6c	11654	<3>[script] (6)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[domain-name] (11)
Jun 9 09:21:09	dhcp6c	11654	<3>[request] (7)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[domain-name-servers] (19)
Jun 9 09:21:09	dhcp6c	11654	<3>[request] (7)
Jun 9 09:21:09	dhcp6c	11654	<3>comment [# request prefix delegation] (27)
Jun 9 09:21:09	dhcp6c	11654	<3>end of sentence [;] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[0] (1)
Jun 9 09:21:09	dhcp6c	11654	<3>[ia-pd] (5)
Jun 9 09:21:09	dhcp6c	11654	<3>[send] (4)
Jun 9 09:21:09	dhcp6c	11654	<3>begin of closure [{] (1)
Jun 9 09:21:09	dhcp6c	11654	<5>[hn1] (3)
Jun 9 09:21:09	dhcp6c	11654	<3>[interface] (9)
Jun 9 09:21:09	dhcp6c	11654	skip opening control port
Jun 9 09:21:09	dhcp6c	11654	failed initialize control message authentication
Jun 9 09:21:09	dhcp6c	11654	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Jun 9 09:21:09	dhcp6c	11654	extracted an existing DUID from /var/db/dhcp6c_duid: 00:01:00:01:22:95:fa:13:00:15:5d:5c:e2:31
Jun 9 09:21:05	dhclient		Creating resolv.conf
Jun 9 09:21:05	dhclient		/sbin/route add default 154.20.116.1
Jun 9 09:21:05	dhclient		Adding new routes to interface: hn1
Jun 9 09:21:05	dhclient		New Routers (hn1): 154.20.116.1
Jun 9 09:21:05	dhclient		New Broadcast Address (hn1): 154.20.119.255
Jun 9 09:21:05	dhclient		New Subnet Mask (hn1): 255.255.252.0
Jun 9 09:21:05	dhclient		New IP Address (hn1): 154.20.119.154
Jun 9 09:21:05	dhclient		ifconfig hn1 inet 154.20.119.154 netmask 255.255.252.0 broadcast 154.20.119.255
Jun 9 09:21:05	dhclient		Starting add_new_address()
Jun 9 09:21:05	dhclient		REBOOT
Jun 9 09:21:04	dhclient		PREINIT

[jimp]

Do you have a different piece of hardware (real or virtual) you can try here to see if it's isolated to those hnX NICs or your environment (hyperv?)?

Also we recently, in the last few days, resynchronized with FreeBSD 11.2 so it's possible we picked up a bug fix, so it's worth testing on the latest snapshot.

[bimmerdriver]

@jimp said in DHCPv6 Client Broken in latest snapshot:

Do you have a different piece of hardware (real or virtual) you can try here to see if it's isolated to those hnX NICs or your environment (hyperv?)?

Also we recently, in the last few days, resynchronized with FreeBSD 11.2 so it's possible we picked up a bug fix, so it's worth testing on the latest snapshot.

Unfortunately, I don't have any other hardware to try.

I just updated to the latest snapshot and unfortunately, the error is exactly the same.

If it would be useful to you, I could set up teamviewer so you can get on the system and take a look.

[darkfire]

@jimp is there something we can do to help you?

[darkfire]

a link to a related issue on the pfsense bug tracker
https://redmine.pfsense.org/issues/8489

[jimp]

@darkfire said in DHCPv6 Client Broken in latest snapshot:

@jimp is there something we can do to help you?

Find a way to reproduce it reliably that doesn't rely on being connected to an ISP that requires "do not wait for RA".

As far as I'm aware, nobody here has been able to replicate the problem behavior or error message(s).

[bimmerdriver]

@darkfire said in DHCPv6 Client Broken in latest snapshot:

a link to a related issue on the pfsense bug tracker
https://redmine.pfsense.org/issues/8489

Issue 8489 isn't a "related issue". It's the bug report for the issue I reported in this thread.

[bimmerdriver]

@jimp said in DHCPv6 Client Broken in latest snapshot:

@darkfire said in DHCPv6 Client Broken in latest snapshot:

@jimp is there something we can do to help you?

Find a way to reproduce it reliably that doesn't rely on being connected to an ISP that requires "do not wait for RA".

As far as I'm aware, nobody here has been able to replicate the problem behavior or error message(s).

That doesn't bode well for this ever getting fixed. Something changed in April and without the snapshots being available to isolate which one introduced the change that's causing the problem, the uselessly vague error message is all there is to go on.

[bimmerdriver]

I made some configuration changes on my hyper-v server. It's using Intel I350 NIC for WAN and LAN. I updated to the latest version of the Intel driver. I also disabled VMQ. Neither change made any difference. I'm still seeing the same error in the log and ipv6 is not working.

[bimmerdriver]

Just to be clear, the configuration change included switching the WAN from the built-in HP NIC to the Intel NIC. So the WAN is using different hardware, a proven NIC with the latest driver. My other system was on 2.3.5 and is now on 2.4.3 and it's working fine. I don't see what else this could be but a regression.

[jimp]

I agree, it could be a regression, but that still doesn't explain why it only affects certain people or configurations. We need a reliable way to reproduce the error. So far, just setting that one option doesn't produce that error for any system I've tried. There must be some other component to it.

[bimmerdriver]

@jimp said in DHCPv6 Client Broken in latest snapshot:

I agree, it could be a regression, but that still doesn't explain why it only affects certain people or configurations. We need a reliable way to reproduce the error. So far, just setting that one option doesn't produce that error for any system I've tried. There must be some other component to it.

If you would like to try my system, you're welcome to. We can use teamviewer.

[lakekeman]

I have this problem after upgrading to 2.4.4-RELEASE.

No more IPv6 addresses for me.

Sep 24 20:38:29 dhcp6c 6839 transmit failed: Input/output error
Sep 24 20:38:29 dhcp6c 6839 Sending Solicit

My pfsense is a Hyper-v VM.
Internet provider is Vodafone Cable in germany - and yes I need the "do not wait for RA" option.