IPFire Core 144. Red interface is setup with dynamic IP. When a reconnection happens, it won’t automatically assign a new IPv4 address. ifconfig shows no address.
Reconnection examples: power-cycle the modem attached to red0, or do ifconfig red0 down; ifconfig red0 up.
IP can be manually assigned with dhcpcd red0 .
This is a problem whenever my modem resets on its own. My whole setup loses internet connectivity until I manually intervene.
Is this expected behavior? What would be the best way to make dhcpcd reassign an IP address to red0 upon reconnection?
Thanks!
1 Like
Are there any errors in /var/log/messages?
Just do grep dhcpcd /var/log/messages
Yes, there are error messages as follows. At 10:28 I manually invoked dhcpcd on red0.
Jun 5 04:52:06 ipfire dhcpcd[4416]: red0: failed to renew DHCP, rebinding
Jun 5 04:52:06 ipfire dhcpcd[4416]: red0: reject NAK via 192.168.100.1
Jun 5 04:52:11 ipfire dhcpcd[4416]: red0: reject NAK via 192.168.100.1
Jun 5 04:52:15 ipfire dhcpcd[4416]: red0: reject NAK via 192.168.100.1
Jun 5 04:52:19 ipfire dhcpcd[4416]: red0: reject NAK via 192.168.100.1
Jun 5 04:52:23 ipfire dhcpcd[4416]: red0: reject NAK via 192.168.100.1
[Hundreds of times, every 4 seconds]
Jun 5 05:14:29 ipfire dhcpcd[4416]: red0: reject NAK via 192.168.100.1
Jun 5 05:14:33 ipfire dhcpcd[4416]: red0: reject NAK via 192.168.100.1
Jun 5 05:14:36 ipfire dhcpcd[4416]: red0: DHCP lease expired
Jun 5 05:14:36 ipfire dhcpcd[4416]: red0: deleting route to 100.65.64.0/19
Jun 5 05:14:36 ipfire dhcpcd[4416]: red0: deleting default route via 100.65.64.1
Jun 5 05:14:36 ipfire dhcpcd.exe[6637]: red0 has been brought down (EXPIRE)
Jun 5 05:14:37 ipfire dhcpcd[4416]: red0: soliciting a DHCP lease
Jun 5 05:14:37 ipfire dhcpcd[4416]: red0: offered 192.168.100.10 from 192.168.100.1
Jun 5 05:14:38 ipfire dhcpcd[4416]: red0: probing address 192.168.100.10/24
Jun 5 05:14:43 ipfire dhcpcd[4416]: red0: leased 192.168.100.10 for 30 seconds
Jun 5 05:14:43 ipfire dhcpcd[4416]: red0: adding route to 192.168.100.0/24
Jun 5 05:14:43 ipfire dhcpcd[4416]: red0: adding default route via 192.168.100.1
Jun 5 05:14:43 ipfire dhcpcd.exe[6808]: red0 has been (re)configured with IP=192.168.100.10
Jun 5 05:15:00 ipfire dhcpcd[4417]: ps_root_recvmsg: Connection refused
Jun 5 05:15:05 ipfire dhcpcd[4416]: red0: dhcp_sendudp: Connection refused
Jun 5 05:15:05 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 05:15:09 ipfire dhcpcd[4416]: red0: failed to renew DHCP, rebinding
Jun 5 05:15:09 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 05:15:13 ipfire dhcpcd[4416]: red0: DHCP lease expired
Jun 5 05:15:13 ipfire dhcpcd[4416]: arp_change: Transport endpoint is not connected
Jun 5 05:15:13 ipfire dhcpcd[4416]: arp_close: Transport endpoint is not connected
Jun 5 05:15:13 ipfire dhcpcd[4416]: red0: ipv4_deladdr: Transport endpoint is not connected
Jun 5 05:15:13 ipfire dhcpcd[4416]: red0: deleting route to 192.168.100.0/24
Jun 5 05:15:13 ipfire dhcpcd[4416]: rt_delete: Transport endpoint is not connected
Jun 5 05:15:13 ipfire dhcpcd[4416]: red0: deleting default route via 192.168.100.1
Jun 5 05:15:13 ipfire dhcpcd[4416]: rt_delete: Transport endpoint is not connected
Jun 5 05:15:13 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 05:15:13 ipfire dhcpcd[4416]: red0: soliciting a DHCP lease
Jun 5 05:15:13 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 05:15:18 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 05:15:26 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
[Hundreds of times, every minute or so]
Jun 5 09:51:40 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:52:44 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:53:14 ipfire dhcpcd[4416]: red0: carrier lost
Jun 5 09:53:14 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 09:53:14 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 09:53:20 ipfire dhcpcd[4416]: red0: carrier acquired
Jun 5 09:53:20 ipfire dhcpcd[4416]: read_config: ps_root_copychroot `/var/ipfire/dhcpc/dhcpcd.conf': Transport endpoint is not connected
Jun 5 09:53:20 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 09:53:20 ipfire dhcpcd[4416]: red0: IAID 67:14:ce:ee
Jun 5 09:53:20 ipfire dhcpcd[4416]: red0: soliciting an IPv6 router
Jun 5 09:53:21 ipfire dhcpcd[4416]: red0: soliciting a DHCP lease
Jun 5 09:53:21 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:53:25 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:53:31 ipfire dhcpcd[4416]: red0: carrier lost
Jun 5 09:53:31 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 09:53:31 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 09:54:22 ipfire dhcpcd[4416]: red0: carrier acquired
Jun 5 09:54:22 ipfire dhcpcd[4416]: read_config: ps_root_copychroot `/var/ipfire/dhcpc/dhcpcd.conf': Transport endpoint is not connected
Jun 5 09:54:22 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 09:54:22 ipfire dhcpcd[4416]: red0: IAID 67:14:ce:ee
Jun 5 09:54:23 ipfire dhcpcd[4416]: red0: soliciting an IPv6 router
Jun 5 09:54:23 ipfire dhcpcd[4416]: red0: soliciting a DHCP lease
Jun 5 09:54:23 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:54:27 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:54:34 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:54:51 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:55:23 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:56:27 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:57:31 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:58:35 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 09:59:38 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:00:41 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:01:44 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:02:48 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:03:52 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:04:57 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:06:00 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:07:04 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:08:07 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:09:12 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:10:15 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:11:19 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:12:22 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:13:25 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:14:28 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:15:33 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:16:36 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:17:41 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:18:45 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:19:49 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:20:52 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:21:57 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:23:00 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:24:05 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:25:09 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:26:14 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:27:17 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:28:12 ipfire dhcpcd[18092]: sending commands to dhcpcd process
Jun 5 10:28:12 ipfire dhcpcd[4416]: control command: dhcpcd red0
Jun 5 10:28:12 ipfire dhcpcd[4416]: read_config: ps_root_copychroot `/var/ipfire/dhcpc/dhcpcd.conf': Transport endpoint is not connected
Jun 5 10:28:12 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 10:28:21 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:29:14 ipfire dhcpcd[6807]: ps_bpf_recvbpf: Network is down
Jun 5 10:29:14 ipfire dhcpcd[4416]: red0: carrier lost
Jun 5 10:29:14 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 10:29:14 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 10:29:21 ipfire dhcpcd[4416]: red0: carrier acquired
Jun 5 10:29:21 ipfire dhcpcd[4416]: read_config: ps_root_copychroot `/var/ipfire/dhcpc/dhcpcd.conf': Transport endpoint is not connected
Jun 5 10:29:21 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 10:29:21 ipfire dhcpcd[4416]: red0: IAID 67:14:ce:ee
Jun 5 10:29:22 ipfire dhcpcd[4416]: red0: soliciting an IPv6 router
Jun 5 10:29:22 ipfire dhcpcd[4416]: red0: soliciting a DHCP lease
Jun 5 10:29:22 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:29:26 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:29:35 ipfire dhcpcd[4416]: dhcp_openbpf: Transport endpoint is not connected
Jun 5 10:29:37 ipfire dhcpcd[18380]: sending commands to dhcpcd process
Jun 5 10:29:37 ipfire dhcpcd[4416]: control command: dhcpcd red0
Jun 5 10:29:37 ipfire dhcpcd[4416]: read_config: ps_root_copychroot `/var/ipfire/dhcpc/dhcpcd.conf': Transport endpoint is not connected
Jun 5 10:29:37 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 10:29:50 ipfire dhcpcd[4416]: received SIGTERM, stopping
Jun 5 10:29:50 ipfire dhcpcd[4416]: red0: removing interface
Jun 5 10:29:50 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 10:29:50 ipfire dhcpcd[4416]: script_runreason: Transport endpoint is not connected
Jun 5 10:29:50 ipfire dhcpcd[4416]: main: control_stop: Transport endpoint is not connected
Jun 5 10:29:50 ipfire dhcpcd[4416]: ps_dostop: Connection refused
Jun 5 10:29:50 ipfire dhcpcd[4416]: ps_dostop: Transport endpoint is not connected
Jun 5 10:29:52 ipfire dhcpcd[18417]: dhcpcd-9.0.2 starting
Jun 5 10:29:52 ipfire dhcpcd[18430]: DUID 00:01:00:01:26:58:75:5f:00:e0:67:14:ce:ee
Jun 5 10:29:52 ipfire dhcpcd[18430]: red0: IAID 67:14:ce:ee
Jun 5 10:29:52 ipfire dhcpcd[18430]: red0: adding address fe80::2e0:67ff:fe14:ceee
Jun 5 10:29:52 ipfire dhcpcd[18430]: ipv6_addaddr1: Permission denied
Jun 5 10:29:53 ipfire dhcpcd[18430]: red0: soliciting an IPv6 router
Jun 5 10:29:54 ipfire dhcpcd[18430]: red0: soliciting a DHCP lease
Jun 5 10:29:58 ipfire dhcpcd[18430]: red0: offered 100.65.82.70 from 189.6.0.175
Jun 5 10:29:58 ipfire dhcpcd[18430]: red0: probing address 100.65.82.70/19
Jun 5 10:30:03 ipfire dhcpcd[18430]: red0: leased 100.65.82.70 for 10800 seconds
Jun 5 10:30:03 ipfire dhcpcd[18430]: red0: adding route to 100.65.64.0/19
Jun 5 10:30:03 ipfire dhcpcd[18430]: red0: adding default route via 100.65.64.1
Jun 5 10:30:03 ipfire dhcpcd.exe[18590]: red0 has been (re)configured with IP=100.65.82.70
Jun 5 10:31:16 ipfire dhcpcd[18430]: red0: carrier lost
Jun 5 10:31:16 ipfire dhcpcd[18430]: red0: deleting route to 100.65.64.0/19
Jun 5 10:31:16 ipfire dhcpcd[18430]: red0: deleting default route via 100.65.64.1
Jun 5 10:31:16 ipfire dhcpcd.exe[19410]: red0 has been brought down (EXPIRE)
Jun 5 10:31:40 ipfire dhcpcd[18430]: red0: carrier acquired
Jun 5 10:31:40 ipfire dhcpcd[18430]: red0: IAID 67:14:ce:ee
Jun 5 10:31:40 ipfire dhcpcd[18430]: red0: rebinding lease of 100.65.82.70
Jun 5 10:31:40 ipfire dhcpcd[18430]: red0: soliciting an IPv6 router
Jun 5 10:31:45 ipfire dhcpcd[18430]: red0: DHCP lease expired
Jun 5 10:31:46 ipfire dhcpcd.exe[19661]: red0 has been brought down (EXPIRE)
Jun 5 10:31:46 ipfire dhcpcd[18430]: red0: soliciting a DHCP lease
Jun 5 10:31:49 ipfire dhcpcd[18430]: red0: carrier lost
Jun 5 10:31:49 ipfire dhcpcd.exe[19851]: red0 has been brought down (EXPIRE)
Jun 5 10:32:40 ipfire dhcpcd[18430]: red0: carrier acquired
Jun 5 10:32:41 ipfire dhcpcd[18430]: red0: IAID 67:14:ce:ee
Jun 5 10:32:41 ipfire dhcpcd[18430]: red0: soliciting an IPv6 router
Jun 5 10:32:41 ipfire dhcpcd[18430]: red0: soliciting a DHCP lease
Jun 5 10:32:46 ipfire dhcpcd[18430]: red0: offered 192.168.100.10 from 192.168.100.1
Jun 5 10:32:47 ipfire dhcpcd[18430]: red0: probing address 192.168.100.10/24
Jun 5 10:32:52 ipfire dhcpcd[18430]: red0: leased 192.168.100.10 for 30 seconds
Jun 5 10:32:52 ipfire dhcpcd[18430]: red0: adding route to 192.168.100.0/24
Jun 5 10:32:52 ipfire dhcpcd[18430]: red0: adding default route via 192.168.100.1
Jun 5 10:32:52 ipfire dhcpcd.exe[20211]: red0 has been (re)configured with IP=192.168.100.10
Jun 5 10:33:18 ipfire dhcpcd[18430]: red0: failed to renew DHCP, rebinding
Jun 5 10:33:18 ipfire dhcpcd[18430]: red0: NAK: This lease may no longer be renewed: CIADDR mismatch from 189.6.0.175
Jun 5 10:33:18 ipfire dhcpcd[18430]: red0: message: This lease may no longer be renewed: CIADDR mismatch
Jun 5 10:33:18 ipfire dhcpcd[18430]: red0: deleting route to 192.168.100.0/24
Jun 5 10:33:18 ipfire dhcpcd[18430]: red0: deleting default route via 192.168.100.1
Jun 5 10:33:18 ipfire dhcpcd.exe[20903]: red0 has been brought down (NAK)
Jun 5 10:33:19 ipfire dhcpcd[18430]: red0: soliciting a DHCP lease
Jun 5 10:33:19 ipfire dhcpcd[18430]: red0: offered 100.65.82.70 from 189.6.0.175
Jun 5 10:33:19 ipfire dhcpcd[18430]: red0: probing address 100.65.82.70/19
Jun 5 10:33:24 ipfire dhcpcd[18430]: red0: leased 100.65.82.70 for 10800 seconds
Jun 5 10:33:24 ipfire dhcpcd[18430]: red0: adding route to 100.65.64.0/19
Jun 5 10:33:24 ipfire dhcpcd[18430]: red0: adding default route via 100.65.64.1
Jun 5 10:33:24 ipfire dhcpcd.exe[21085]: red0 has been (re)configured with IP=100.65.82.70
What kind of WAN connection do you have?
Cable modem?
Seems, there is a very unstable internet connection.
The temporary IPs out of 192.168.100.0/24 are used e.g. by DOCSIS if no WAN connection is up.
Yes, it’s a DOCSIS cable modem.
I’ve just updated to core 145 and tried to power-cycle the modem. dhcpcd worked as expected this time and got a new WAN IP address when the modem was back online. So, apparently the issue may have been fixed with the update.
Maybe the issue on the modem/WAN fixed at the same time as the update.
Don’t know whether dhcpcd was updated with core 145.
I’m having a similar issue. I also have a DOCSIS cable modem connected to RED0 with DHCP enabled. If the connection to the head-end goes down (which occasionally happens with my provider), RED0 gets stuck with the modem-internal 192.168.100.10 address and can’t seem to recover when the true connection comes back up.
What is odd is that once IPFire gets into this state, dhcpcd can no longer be shut down in the normal manner. I tried running “/etc/init.d/networking/red stop”, but it froze until I hit ctrl-c. The only way I’ve found to recover from this state is to run “killall -9 dhcpcd” followed by “/etc/init.d/networking/red start”. (“killall dhcpcd” without the “-9” did not end the process - it seems to be locked up.)
The last time this happened, I was on Core 144, but have since upgraded to 145. The version of dhcpcd is 9.0.2 for both of them. If there’s anything I can do to get more info on this problem, please let me know.
I’ll paste my log below for completeness (with public IP stripped), but it’s very similar to the other poster in this thread.
Jun 3 14:03:05 ipfire dhcpcd[794]: red0: carrier lost
Jun 3 14:03:05 ipfire dhcpcd[794]: red0: deleting route to XX.XX.XX.XX/22
Jun 3 14:03:05 ipfire dhcpcd[794]: red0: deleting default route via XX.XX.XX.XX
Jun 3 14:03:05 ipfire dhcpcd.exe[25462]: red0 has been brought down (EXPIRE)
Jun 3 14:03:18 ipfire dhcpcd[794]: red0: carrier acquired
Jun 3 14:03:18 ipfire dhcpcd[794]: red0: IAID XX:XX:XX:XX
Jun 3 14:03:19 ipfire dhcpcd[794]: red0: soliciting an IPv6 router
Jun 3 14:03:20 ipfire dhcpcd[794]: red0: rebinding lease of XX.XX.XX.XX
Jun 3 14:03:23 ipfire dhcpcd[794]: red0: carrier lost
Jun 3 14:03:23 ipfire dhcpcd.exe[25656]: red0 has been brought down (EXPIRE)
Jun 3 14:03:25 ipfire dhcpcd[794]: red0: carrier acquired
Jun 3 14:03:25 ipfire dhcpcd[794]: red0: IAID XX:XX:XX:XX
Jun 3 14:03:26 ipfire dhcpcd[794]: red0: rebinding lease of XX.XX.XX.XX
Jun 3 14:03:26 ipfire dhcpcd[794]: red0: soliciting an IPv6 router
Jun 3 14:03:30 ipfire dhcpcd[794]: red0: NAK: from 192.168.100.1
Jun 3 14:03:31 ipfire dhcpcd.exe[25837]: red0 has been brought down (NAK)
Jun 3 14:03:31 ipfire dhcpcd[794]: red0: soliciting a DHCP lease
Jun 3 14:03:34 ipfire dhcpcd[794]: red0: offered 192.168.100.10 from 192.168.100.1
Jun 3 14:03:34 ipfire dhcpcd[794]: red0: probing address 192.168.100.10/24
Jun 3 14:03:39 ipfire dhcpcd[794]: red0: leased 192.168.100.10 for 20 seconds
Jun 3 14:03:39 ipfire dhcpcd[794]: red0: adding route to 192.168.100.0/24
Jun 3 14:03:39 ipfire dhcpcd[794]: red0: adding default route via 192.168.100.1
Jun 3 14:03:40 ipfire dhcpcd.exe[26009]: red0 has been (re)configured with IP=192.168.100.10
Jun 3 14:04:11 ipfire dhcpcd[794]: red0: failed to renew DHCP, rebinding
Jun 3 14:04:11 ipfire dhcpcd[794]: red0: DHCP lease expired
Jun 3 14:04:11 ipfire dhcpcd[794]: red0: deleting route to 192.168.100.0/24
Jun 3 14:04:11 ipfire dhcpcd[794]: red0: deleting default route via 192.168.100.1
Jun 3 14:04:11 ipfire dhcpcd[26871]: ps_inet_listenin: Cannot assign requested address
Jun 3 14:04:11 ipfire dhcpcd[26871]: ps_root_recvmsg: Cannot assign requested address
Jun 3 14:04:11 ipfire dhcpcd.exe[26873]: red0 has been brought down (EXPIRE)
Jun 3 14:04:12 ipfire dhcpcd[794]: red0: soliciting a DHCP lease
Jun 3 14:04:12 ipfire dhcpcd[794]: red0: offered 192.168.100.10 from 192.168.100.1
Jun 3 14:04:12 ipfire dhcpcd[794]: red0: probing address 192.168.100.10/24
Jun 3 14:04:18 ipfire dhcpcd[794]: red0: leased 192.168.100.10 for 20 seconds
Jun 3 14:04:18 ipfire dhcpcd[794]: red0: adding route to 192.168.100.0/24
Jun 3 14:04:18 ipfire dhcpcd[794]: red0: adding default route via 192.168.100.1
Jun 3 14:04:18 ipfire dhcpcd.exe[27050]: red0 has been (re)configured with IP=192.168.100.10
Jun 3 14:04:47 ipfire dhcpcd[794]: red0: failed to renew DHCP, rebinding
Jun 3 14:04:47 ipfire dhcpcd[795]: ps_root_recvmsg: Connection refused
Jun 3 14:04:47 ipfire dhcpcd[794]: red0: DHCP lease expired
Jun 3 14:15:40 ipfire dhcpcd[28944]: dhcpcd-9.0.2 starting
Jun 3 14:15:40 ipfire dhcpcd[28959]: DUID XX:XX:XX:XX:XX:XX:XX:XX:XX:XX
Jun 3 14:15:40 ipfire dhcpcd[28959]: red0: IAID XX:XX:XX:XX
Jun 3 14:15:40 ipfire dhcpcd[28959]: red0: adding address XXXX::XXXX:XXXX:XXXX:XXXX
Jun 3 14:15:40 ipfire dhcpcd[28959]: ipv6_addaddr1: Permission denied
Jun 3 14:15:41 ipfire dhcpcd[28959]: red0: soliciting a DHCP lease
Jun 3 14:15:41 ipfire dhcpcd[28959]: red0: soliciting an IPv6 router
Jun 3 14:15:43 ipfire dhcpcd[28959]: red0: offered 192.168.100.10 from 192.168.100.1
Jun 3 14:15:43 ipfire dhcpcd[28959]: red0: probing address 192.168.100.10/24
Jun 3 14:15:49 ipfire dhcpcd[28959]: red0: leased 192.168.100.10 for 20 seconds
Jun 3 14:15:49 ipfire dhcpcd[28959]: red0: adding route to 192.168.100.0/24
Jun 3 14:15:49 ipfire dhcpcd[28959]: red0: adding default route via 192.168.100.1
Jun 3 14:15:49 ipfire dhcpcd.exe[29010]: red0 has been (re)configured with IP=192.168.100.10
Jun 3 14:16:20 ipfire dhcpcd[28959]: red0: failed to renew DHCP, rebinding
Jun 3 14:16:20 ipfire dhcpcd[28959]: red0: DHCP lease expired
Jun 3 14:16:20 ipfire dhcpcd[29949]: ps_inet_listenin: Cannot assign requested address
Jun 3 14:16:20 ipfire dhcpcd[29949]: ps_root_recvmsg: Cannot assign requested address
Jun 3 14:16:20 ipfire dhcpcd[28959]: red0: deleting route to 192.168.100.0/24
Jun 3 14:16:20 ipfire dhcpcd[28959]: red0: deleting default route via 192.168.100.1
Jun 3 14:16:20 ipfire dhcpcd.exe[29955]: red0 has been brought down (EXPIRE)
Jun 3 14:16:21 ipfire dhcpcd[28959]: red0: soliciting a DHCP lease
Jun 3 14:16:21 ipfire dhcpcd[28959]: red0: offered 192.168.100.10 from 192.168.100.1
Jun 3 14:16:21 ipfire dhcpcd[28959]: red0: probing address 192.168.100.10/24
Jun 3 14:16:26 ipfire dhcpcd[28959]: red0: leased 192.168.100.10 for 20 seconds
Jun 3 14:16:26 ipfire dhcpcd[28959]: red0: adding route to 192.168.100.0/24
Jun 3 14:16:26 ipfire dhcpcd[28959]: red0: adding default route via 192.168.100.1
Jun 3 14:16:27 ipfire dhcpcd.exe[30169]: red0 has been (re)configured with IP=192.168.100.10
Jun 3 14:16:57 ipfire dhcpcd[28959]: red0: failed to renew DHCP, rebinding
Jun 3 14:16:57 ipfire dhcpcd[28960]: ps_root_recvmsg: Connection refused
Jun 3 14:16:57 ipfire dhcpcd[28959]: red0: DHCP lease expired
Jun 3 15:26:19 ipfire dhcpcd[6275]: dhcpcd-9.0.2 starting
The last line is when I manually restarted the service.
I’ve just made a short test:
- power down/up the modem
- connection loss at red0
- red0 gets 192.168.100.x (leastime 20 sec)
- retrials all 20 seconds
- modem reboots and gets connected to the ISP
- red0 gets a “normal” IP
- system runs as before
I know this test isn’t really complete.
To simulate the faulty condition, I’ll disconnect the broadband cable ( “antenna cable” ) from the modem for short time. A power off of the amplifier is no way at the moment because of the TV listening of the family. 
I’ll report my results, then.
BTW: Can you read the status of the modem ( line quality, errors, etc. )? Some ( most?) DOCSIS modems have at web page at 192.168.100.1, which is more or less accessible while the modem searches to reach the ISP ( CMTS ).
I can read the status, but only when the connection is up. IPFire loses the route to 192.168.100.0/24 at some point in the logs.
You may have to disconnect the cable rather than powering down the modem. I’m not certain that the modem (or at least my modem) will fall back to the 192.168.100.x subnet internal DHCP until it fails to connect to the head-end.
Update: Due to another cable outage last night, I can confirm that the problem is still occurring on Core 145. I also verified that the problem does not occur if the cable modem is simply reset. The problem only seems to show if the cable modem falls back to its internal dhcp server after failing to connect to its head-end.
What was the reason of the outage? How long did it last?
Until now, I saw only a clean transition from 192.168.100.0/24 to the public net of my ISP, even with core 145.
I know of some problems of the actual versions of dhcpcd. But as far I know a core developper of IPFire ( Arne?) had an eye on this.
Means I’ll have to lower the link quality of my modem ( by switching off the cable amplifier ) tonight for a test. Hope the family isn’t watching TV to long this evening.
First test.
I’ve disconnected the modem from the TV cable. Modem switches to 192.168.100.0/24 net, dhcpcd gets this, after some renew attempts dhcpcd is stuck, even after reconnection of the cable. Killing the dhcpcd process(es) (kill -9 xx) and restart ( /etc/rc.d/init.d/network restart red ) restores the working state. Uhmm.
Lowering of Cable link quality has to be tested yet. Maybe tomorrow. Today I’m to tired to wait until after midnight.
The outage this time was several hours (long enough I gave up waiting and went to bed, and then found it back up the next morning). I think it was weather related. That said, I’ve seen similar issues from short gaps in service. I’m fairly certain it’s the switch to the internal modem DHCP that’s the issue. Just hypothesizing here, but could dhcpcd have problems with very short leases?
From your later post, it looks like you’ve reproduced the problem. Let me know if you think it would help for me to post another log. I expect it would be similar to the one I posted earlier, though.
I think not. I have set 5min in my network. The only thing that i know is that the dhcp client get a problem if link was detected but repeated requests was not answered within the timeout. (default 30s)
So i suggest to remove a switch between modem and red lan if exist. Because then the lancard can dettect the link loss from the modem.
I do not have a switch between modem and IPFire. The error can be reproduced nevertheless.
Same here - I have no switch between the modem and Red0 interface. In the log I posted, there are “carrier lost” and “carrier acquired” events when service was lost and regained. I’ve also in the past tried physically disconnecting and reconnecting the Red0 Ethernet cable in this case, as well as removing and restoring power to the modem, but did not see any recovery.
Also, the cable modem is giving out extremely short leases - only 20 seconds. That’s the only reason that I hypothesized that as a problem. I could see that as the type of corner case that might have escaped testing.
At any rate, thanks for looking at this. If there’s any more information I can gather - increased log verbosity or otherwise - let me know and I’ll be glad to help.
Just checked the problem with low level of coax signal ( hope so, I don’t an instrument to measure the level without amplifier ).
Nearly same behaviour. unbound throws errors. A network restart red helps.
Didn’t try to restart dhcpcd only.
The issue has happened again. red0 lost its IP lease for whatever reason and didn’t reacquire automatically. I had to issue dhcpcd red0 to get a new lease. Core 145 does NOT solve the issue.
Some days ago I had the same issue. My modem/the CMTS decided to give IPFire a new IP address. dhcpcd tried to get the old IP, without success.
Because of the time elapsed since the address change ( about 01:00h in the night ) until my discovery ( about 09:30 ) I did a restart of IPFire. Thus I can’t report exactly which erroneous behaviour showed up.
BTW: Since a year I notice dhcpcd can’t renew his IP. After some time the demon decides to rebind. This rebinding succeeds, maybefor the same IP but not for different value.
Since beginning of this year, I think, is a discussion about issues resembling ours. Didn’t follow this in depth, but maybe there a patch for this problem under way.
Possibly a core developer working on this module knows more.
Log into your ISP modem, and find the setting to reserve an IP address, for the MAC Address of your Red Interface in IP Fire. Do it so that it is out of your DHCP range on your ISP Modem.
Example.
Set the DHCP Range on your modem from 192.168.1.2 to 192.168.1.240
Then that leaves you 241 to 254 - 13 addresses you can use as a manual assignment.
Heck, you only need 1 for your task, so that will be way more than enough.
Once the Modem Reboots, you should automatically have IPFires Red Interface polling for a connection. It would be at this time that the Modem sees the Static…Dynamic MAC address assignment for the IP you give Red0, which for example might be 192.168.1.241. This will keep you from having to deal with DHCP anything on your Red Interface.