Red0 unable to re-establish connections, long-term dhcpcd problem

Networking
21

Failure - op (180) is not BOOTREPLY?! Something worth searching for!

Mar 22 21:42:41 gateway dhcpcd[13881]: dhcpcd-7.2.3 starting
Mar 22 21:42:41 gateway dhcpcd[13881]: red0: executing `/var/ipfire/dhcpc/dhcpcd-run-hooks' PREINIT
Mar 22 21:42:41 gateway dhcpcd[13881]: red0: executing `/var/ipfire/dhcpc/dhcpcd-run-hooks' CARRIER
Mar 22 21:42:41 gateway dhcpcd[13881]: DUID 00:04:03:00:02:00:04:00:05:00:00:06:00:07:00:08:00:09
Mar 22 21:42:41 gateway dhcpcd[13881]: red0: IAID c0:08:aa:bb
Mar 22 21:42:41 gateway dhcpcd[13881]: red0: adding address fe80::c2c1:c0ff:fe08:aabb
Mar 22 21:42:41 gateway dhcpcd[13881]: red0: pltime infinity, vltime infinity
Mar 22 21:42:41 gateway dhcpcd[13881]: ipv6_addaddr1: Permission denied
Mar 22 21:42:41 gateway dhcpcd[13881]: red0: delaying IPv6 router solicitation for 0.5 seconds
Mar 22 21:42:41 gateway dhcpcd[13881]: red0: delaying IPv4 for 0.9 seconds
Mar 22 21:42:42 gateway dhcpcd[13881]: red0: soliciting an IPv6 router
Mar 22 21:42:42 gateway dhcpcd[13881]: red0: delaying Router Solicitation for LL address
Mar 22 21:42:42 gateway dhcpcd[13881]: red0: using hwaddr c0:c1:c0:08:aa:bb
Mar 22 21:42:42 gateway dhcpcd[13881]: red0: soliciting a DHCP lease
Mar 22 21:42:42 gateway dhcpcd[13881]: red0: sending DISCOVER (xid 0xbad3999d), next in 3.6 seconds
Mar 22 21:42:42 gateway dhcpcd[13881]: red0: op (180) is not BOOTREPLY
Mar 22 21:42:46 gateway dhcpcd[13881]: red0: sending DISCOVER (xid 0xbad3999d), next in 7.1 seconds
Mar 22 21:42:53 gateway dhcpcd[13881]: red0: sending DISCOVER (xid 0xbad3999d), next in 16.5 seconds
Mar 22 21:43:09 gateway dhcpcd[13881]: red0: sending DISCOVER (xid 0xbad3999d), next in 33.0 seconds
Mar 22 21:43:11 gateway dhcpcd[13881]: timed out
Mar 22 21:43:11 gateway dhcpcd[13881]: dhcpcd exited

Success - even though the ā€œignoring offerā€ message is displayed

Mar 22 21:45:23 gateway dhcpcd[16156]: dhcpcd-7.2.3 starting
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: executing `/var/ipfire/dhcpc/dhcpcd-run-hooks' PREINIT
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: executing `/var/ipfire/dhcpc/dhcpcd-run-hooks' CARRIER
Mar 22 21:45:23 gateway dhcpcd[16156]: DUID 00:04:03:00:02:00:04:00:05:00:00:06:00:07:00:08:00:09
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: IAID c0:08:aa:bb
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: adding address fe80::c2c1:c0ff:fe08:aabb
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: pltime infinity, vltime infinity
Mar 22 21:45:23 gateway dhcpcd[16156]: ipv6_addaddr1: Permission denied
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: delaying IPv6 router solicitation for 0.8 seconds
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: delaying IPv4 for 0.3 seconds
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: using hwaddr c0:c1:c0:08:aa:bb
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: soliciting a DHCP lease
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: sending DISCOVER (xid 0x5e4794a3), next in 4.0 seconds
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: offered x.x.x.101 from x.x.x.1
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: sending REQUEST (xid 0x5e4794a3), next in 3.9 seconds
Mar 22 21:45:23 gateway dhcpcd[16156]: red0: ignoring offer of x.x.x.101 from x.x.x.1
Mar 22 21:45:24 gateway dhcpcd[16156]: red0: soliciting an IPv6 router
Mar 22 21:45:24 gateway dhcpcd[16156]: red0: delaying Router Solicitation for LL address
Mar 22 21:45:24 gateway dhcpcd[16156]: red0: acknowledged x.x.x.101 from x.x.x.1
Mar 22 21:45:24 gateway dhcpcd[16156]: red0: probing address x.x.x.101/24
Mar 22 21:45:24 gateway dhcpcd[16156]: red0: probing for x.x.x.101
Mar 22 21:45:24 gateway dhcpcd[16156]: red0: ARP probing x.x.x.101 (1 of 3), next in 1.5 seconds
Mar 22 21:45:24 gateway dhcpcd[16156]: red0: probing, ignoring x.x.x.101 from x.x.x.1
Mar 22 21:45:26 gateway dhcpcd[16156]: red0: ARP probing x.x.x.101 (2 of 3), next in 1.4 seconds
Mar 22 21:45:27 gateway dhcpcd[16156]: red0: ARP probing x.x.x.101 (3 of 3), next in 2.0 seconds
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: DAD completed for x.x.x.101
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: leased x.x.x.101 for 600 seconds
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: renew in 300 seconds, rebind in 525 seconds
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: writing lease `/var/ipfire/dhcpc/red0.lease'
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: adding IP address x.x.x.101/24 broadcast x.x.x.255
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: adding route to x.x.x.0/24
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: adding default route via x.x.x.1
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: ARP announcing x.x.x.101 (1 of 2), next in 2.0 seconds
Mar 22 21:45:29 gateway dhcpcd[16156]: red0: executing `/var/ipfire/dhcpc/dhcpcd-run-hooks' BOUND
Mar 22 21:45:29 gateway dhcpcd.exe[16244]: red0 has been (re)configured with IP=x.x.x.101
22

Sadly, this hasnā€™t lead to anything helpful, other than me finding some source code for dhcpcd mentioning checking for BOOTREPLY but the code is unclear to me.

Iā€™m sure my ISP uses Cisco equipment, but either way this is looking like something Iā€™ll have to ask them about.

Unless anyone has any good ideas Iā€™m going to have to go through the RFCs for DHCP! :disappointed:
Might need to get a PCAP from red0 during the problem.

23

Iā€™ve since seen
Mar 23 19:57:36 gateway dhcpcd[13592]: red0: op (141) is not BOOTREPLY
in a few attempts. Usually the respones which are being marked as ā€œnot BOOTREPLYā€ are within the first 4 seconds, making me wonder if a recent change to dhcpcd could have caused this to be a problem for me.

tcpdump for red0 (with no filters) was unable to capture whatever packets caused that error. When I eventually was able to record a successful connection I captured the DHCP offer and DHCP ACK without problems.

24

https://git.ipfire.org/?p=ipfire-2.x.git;a=history;f=lfs/dhcpcd;h=83252e8976d153b033923ffd757687f1598206e5;hb=70af65df4198c58f99a333748faa39b39ad1c3c4

The problem is that we have updated it with core136 and reverted this back because user reported such problems with 8.02 to 8.10.
And now users have the same problems also with the old 7.2.3 version. Im not sure what happens here. Maybee some changes at the ISPā€™s are the real reasonā€¦ But im not sureā€¦

25

Thank you.
Do you have any theories as to what may have changed?

Iā€™ve not been deliberately breaking my connection to test and, without doing that, dhcpcd has been reliably renewing every 5 minutes (my ISP lease time is only 10 minutes).

The problem I described above, happens if for any reason the modem/router is restarted, my link to the ISP is down or the ISP themselves reset their router. While these things happen rarely, when they happen IPFire remains disconnected forever, needing intervention.