dhcpcd-discuss

Hi Roy,

Using dhcpcd 7.0.0.

A router is configured for DHCP on eth1. When the WAN connection is
switched from one network to another, TIMEOUT event is observed after it
tries to renew the currently assigned lease.
After TIMEOUT a DHCP DISCOVER is sent. To which an ip is offered from
another server.
But the router is not able to acquire this lease. It keeps on sending DHCP
REQUEST to the server. Attached logs for reference.

I observed this behaviour is because the old ip lease is maintained after
TIMEOUT.
Since the old ip lease is not cleared, the DHCP REQUEST is sent back to the
previous DHCP Server and not the one which has assigned a new IP Address.

Can You help in understanding why this behaviour is observed on TIMEOUT
when the dhcp server network is changed?

I tested by explicitly clearing the old lease by making the s_addr =
0.0.0.0 in the DHCP DISCOVER. In this case the DHCP DISCOVER and DHCP
REQUEST both are broadcast.
It accepts the ip which is offered by the server.

Can you please guide on how the TIMEOUT needs to be handled? Does the
application need to reset the interfaces and release the dhcp lease?

Thank you for your help.

Regards,
Shyamlee

Jul 31 13:49:05 [6308]: dhcpcd-7.0.0 starting
Jul 31 13:49:05 [6308]: all: disabling kernel IPv6 RA support
Jul 31 13:49:05 [6308]: eth1: if_disable_autolinklocal: Operation not supported
Jul 31 13:49:05 [6308]: eth1: executing `/etc/conf/bin/dhcpcd-up' PREINIT
Jul 31 13:49:05 [6308]: eth1: executing `/etc/conf/bin/dhcpcd-up' CARRIER
Jul 31 13:49:05 [6308]: eth1: delaying IPv4 for 0.3 seconds
Jul 31 13:49:05 [6308]: eth1: using ClientID 01:54:39:68:17:5c:dd
Jul 31 13:49:05 [6308]: eth1: reading lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 13:49:05 [6308]: eth1: discarding expired lease
Jul 31 13:49:05 [6308]: eth1: soliciting a DHCP lease
Jul 31 13:49:05 [6308]: eth1: sending DISCOVER (xid 0xb2196eeb), next in 4.2 seconds
Jul 31 13:49:06 [6308]: eth1: offered 66.170.65.115 from 66.170.64.1
Jul 31 13:49:06 [6308]: eth1: sending REQUEST (xid 0xb2196eeb), next in 3.3 seconds
Jul 31 13:49:06 [6308]: eth1: acknowledged 66.170.65.115 from 66.170.64.1
Jul 31 13:49:06 [6308]: eth1: leased 66.170.65.115 for 28800 seconds
Jul 31 13:49:06 [6308]: eth1: renew in 14400 seconds, rebind in 25200 seconds
Jul 31 13:49:06 [6308]: eth1: writing lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 13:49:06 [6308]: eth1: IP address 66.170.65.115/22 already exists
Jul 31 13:49:06 [6308]: eth1: adding route to 66.170.64.0/22
Jul 31 13:49:06 [6308]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 13:49:06 [6308]: eth1: executing `/etc/conf/bin/dhcpcd-up' BOUND
Jul 31 13:49:08 [6308]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 13:51:33 [6991]: dhcpcd-7.0.0 starting
Jul 31 13:51:33 [6991]: eth1: if_disable_autolinklocal: Operation not supported
Jul 31 13:51:33 [6991]: eth1: executing `/etc/conf/bin/dhcpcd-up' PREINIT
Jul 31 13:51:33 [6991]: eth1: executing `/etc/conf/bin/dhcpcd-up' CARRIER
Jul 31 13:51:33 [6991]: eth1: delaying IPv4 for 0.1 seconds
Jul 31 13:51:34 [6991]: eth1: using ClientID 01:54:39:68:17:5c:dd
Jul 31 13:51:34 [6991]: eth1: reading lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 13:51:34 [6991]: eth1: rebinding lease of 66.170.65.115
Jul 31 13:51:34 [6991]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 13:51:34 [6991]: eth1: sending REQUEST (xid 0xba015052), next in 4.9 seconds
Jul 31 13:51:34 [6991]: eth1: acknowledged 66.170.65.115 from 66.170.64.1
Jul 31 13:51:34 [6991]: eth1: leased 66.170.65.115 for 28800 seconds
Jul 31 13:51:34 [6991]: eth1: renew in 14400 seconds, rebind in 25200 seconds
Jul 31 13:51:34 [6991]: eth1: writing lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 13:51:34 [6991]: eth1: IP address 66.170.65.115/22 already exists
Jul 31 13:51:34 [6991]: eth1: adding route to 66.170.64.0/22
Jul 31 13:51:34 [6991]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 13:51:34 [6991]: eth1: executing `/etc/conf/bin/dhcpcd-up' REBOOT
Jul 31 13:51:36 [6991]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 13:55:32 [7450]: dhcpcd-7.0.0 starting
Jul 31 13:55:32 [7450]: eth1: if_disable_autolinklocal: Operation not supported
Jul 31 13:55:32 [7450]: eth1: executing `/etc/conf/bin/dhcpcd-up' PREINIT
Jul 31 13:55:32 [7450]: eth1: executing `/etc/conf/bin/dhcpcd-up' CARRIER
Jul 31 13:55:32 [7450]: eth1: delaying IPv4 for 0.3 seconds
Jul 31 13:55:32 [7450]: eth1: using ClientID 01:54:39:68:17:5c:dd
Jul 31 13:55:32 [7450]: eth1: reading lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 13:55:32 [7450]: eth1: rebinding lease of 66.170.65.115
Jul 31 13:55:32 [7450]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 13:55:32 [7450]: eth1: sending REQUEST (xid 0x410d107a), next in 4.2 seconds
Jul 31 13:55:32 [7450]: eth1: acknowledged 66.170.65.115 from 66.170.64.1
Jul 31 13:55:32 [7450]: eth1: leased 66.170.65.115 for 28800 seconds
Jul 31 13:55:32 [7450]: eth1: renew in 14400 seconds, rebind in 25200 seconds
Jul 31 13:55:32 [7450]: eth1: writing lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 13:55:32 [7450]: eth1: IP address 66.170.65.115/22 already exists
Jul 31 13:55:32 [7450]: eth1: adding route to 66.170.64.0/22
Jul 31 13:55:32 [7450]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 13:55:32 [7450]: eth1: executing `/etc/conf/bin/dhcpcd-up' REBOOT
Jul 31 13:55:34 [7450]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 13:58:04 [7450]: eth1: carrier lost
Jul 31 13:58:04 [7450]: eth1: executing `/etc/conf/bin/dhcpcd-up' NOCARRIER
Jul 31 13:58:19 [7450]: eth1: carrier acquired
Jul 31 13:58:19 [7450]: eth1: if_disable_autolinklocal: Operation not supported
Jul 31 13:58:19 [7450]: eth1: executing `/etc/conf/bin/dhcpcd-up' CARRIER
Jul 31 13:58:20 [7450]: eth1: delaying IPv4 for 0.5 seconds
Jul 31 13:58:20 [7450]: received SIGUSR1, renewing
Jul 31 13:58:20 [7450]: eth1: renewing lease of 66.170.65.115
Jul 31 13:58:20 [7450]: eth1: sending REQUEST (xid 0xd6d8f320), next in 4.0 seconds
Jul 31 13:58:20 [7450]: eth1: using ClientID 01:54:39:68:17:5c:dd
Jul 31 13:58:20 [7450]: eth1: reading lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 13:58:20 [7450]: eth1: rebinding lease of 66.170.65.115
Jul 31 13:58:20 [7450]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 13:58:20 [7450]: eth1: sending REQUEST (xid 0xc587f28a), next in 3.5 seconds
Jul 31 13:58:22 [7450]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 13:58:24 [7450]: eth1: sending REQUEST (xid 0xc587f28a), next in 7.4 seconds
Jul 31 13:58:25 [7450]: eth1: timed out contacting a DHCP server, using last lease
Jul 31 13:58:25 [7450]: eth1: leased 66.170.65.115 for 28800 seconds
Jul 31 13:58:25 [7450]: eth1: renew in 14400 seconds, rebind in 25200 seconds
Jul 31 13:58:25 [7450]: eth1: IP address 66.170.65.115/22 already exists
Jul 31 13:58:25 [7450]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 13:58:25 [7450]: eth1: executing `/etc/conf/bin/dhcpcd-up' TIMEOUT
Jul 31 13:58:25 [7450]: eth1: soliciting a DHCP lease
Jul 31 13:58:25 [7450]: eth1: sending DISCOVER (xid 0x10f2c5f3), next in 3.3 seconds
Jul 31 13:58:26 [7450]: eth1: offered 192.168.44.6 from 192.168.44.1
Jul 31 13:58:26 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 4.4 seconds
Jul 31 13:58:27 [7450]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 13:58:31 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 8.7 seconds
Jul 31 13:58:39 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 16.7 seconds
Jul 31 13:58:56 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 32.8 seconds
Jul 31 13:59:29 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.1 seconds
Jul 31 14:00:33 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.9 seconds
Jul 31 14:01:37 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.2 seconds
Jul 31 14:02:41 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.3 seconds
Jul 31 14:03:46 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.1 seconds
Jul 31 14:04:50 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.2 seconds
Jul 31 14:05:54 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.2 seconds
Jul 31 14:06:57 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.7 seconds
Jul 31 14:08:02 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.6 seconds
Jul 31 14:09:07 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.4 seconds
Jul 31 14:10:10 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.4 seconds
Jul 31 14:11:15 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.4 seconds
Jul 31 14:12:19 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.0 seconds
Jul 31 14:13:23 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.3 seconds
Jul 31 14:14:28 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.8 seconds
Jul 31 14:15:31 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.7 seconds
Jul 31 14:16:35 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.9 seconds
Jul 31 14:17:39 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.7 seconds
Jul 31 14:18:44 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 64.8 seconds
Jul 31 14:19:49 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.8 seconds
Jul 31 14:20:53 [7450]: eth1: sending REQUEST (xid 0x10f2c5f3), next in 63.6 seconds
Jul 31 14:21:45 [10789]: dhcpcd-7.0.0 starting
Jul 31 14:21:45 [10789]: eth1: if_disable_autolinklocal: Operation not supported
Jul 31 14:21:45 [10789]: eth1: executing `/etc/conf/bin/dhcpcd-up' PREINIT
Jul 31 14:21:45 [10789]: eth1: executing `/etc/conf/bin/dhcpcd-up' CARRIER
Jul 31 14:21:45 [10789]: eth1: delaying IPv4 for 0.2 seconds
Jul 31 14:21:45 [10789]: eth1: using ClientID 01:54:39:68:17:5c:dd
Jul 31 14:21:45 [10789]: eth1: reading lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 14:21:45 [10789]: eth1: rebinding lease of 66.170.65.115
Jul 31 14:21:45 [10789]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 14:21:45 [10789]: eth1: sending REQUEST (xid 0xbfdda3a1), next in 4.8 seconds
Jul 31 14:21:45 [10789]: eth1: acknowledged 66.170.65.115 from 66.170.64.1
Jul 31 14:21:45 [10789]: eth1: leased 66.170.65.115 for 28800 seconds
Jul 31 14:21:45 [10789]: eth1: renew in 14400 seconds, rebind in 25200 seconds
Jul 31 14:21:45 [10789]: eth1: writing lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 14:21:45 [10789]: eth1: IP address 66.170.65.115/22 already exists
Jul 31 14:21:45 [10789]: eth1: adding route to 66.170.64.0/22
Jul 31 14:21:45 [10789]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 14:21:45 [10789]: eth1: executing `/etc/conf/bin/dhcpcd-up' REBOOT
Jul 31 14:21:47 [10789]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 14:27:07 [11327]: dhcpcd-7.0.0 starting
Jul 31 14:27:07 [11327]: eth1: if_disable_autolinklocal: Operation not supported
Jul 31 14:27:07 [11327]: eth1: executing `/etc/conf/bin/dhcpcd-up' PREINIT
Jul 31 14:27:07 [11327]: eth1: executing `/etc/conf/bin/dhcpcd-up' CARRIER
Jul 31 14:27:07 [11327]: eth1: delaying IPv4 for 0.5 seconds
Jul 31 14:27:08 [11327]: eth1: using ClientID 01:54:39:68:17:5c:dd
Jul 31 14:27:08 [11327]: eth1: reading lease `/etc/config//dhcpcd-eth1.lease'
Jul 31 14:27:08 [11327]: eth1: rebinding lease of 66.170.65.115
Jul 31 14:27:08 [11327]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 14:27:08 [11327]: eth1: sending REQUEST (xid 0xc6f92b32), next in 3.2 seconds
Jul 31 14:27:10 [11327]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 14:27:11 [11327]: eth1: sending REQUEST (xid 0xc6f92b32), next in 9.0 seconds
Jul 31 14:27:13 [11327]: eth1: timed out contacting a DHCP server, using last lease
Jul 31 14:27:13 [11327]: eth1: leased 66.170.65.115 for 28800 seconds
Jul 31 14:27:13 [11327]: eth1: renew in 14400 seconds, rebind in 25200 seconds
Jul 31 14:27:13 [11327]: eth1: IP address 66.170.65.115/22 already exists
Jul 31 14:27:13 [11327]: eth1: adding route to 66.170.64.0/22
Jul 31 14:27:13 [11327]: eth1: ARP announcing 66.170.65.115 (1 of 2), next in 2.0 seconds
Jul 31 14:27:13 [11327]: eth1: executing `/etc/conf/bin/dhcpcd-up' TIMEOUT
Jul 31 14:27:13 [11327]: eth1: soliciting a DHCP lease
Jul 31 14:27:13 [11327]: eth1: sending DISCOVER (xid 0x416e18b5), next in 4.7 seconds
Jul 31 14:27:14 [11327]: eth1: offered 192.168.44.6 from 192.168.44.1
Jul 31 14:27:14 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 4.6 seconds
Jul 31 14:27:15 [11327]: eth1: ARP announcing 66.170.65.115 (2 of 2)
Jul 31 14:27:19 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 8.7 seconds
Jul 31 14:27:27 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 16.0 seconds
Jul 31 14:27:43 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 31.2 seconds
Jul 31 14:28:15 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 63.3 seconds
Jul 31 14:29:18 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 63.9 seconds
Jul 31 14:30:22 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 64.4 seconds
Jul 31 14:31:26 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 63.7 seconds
Jul 31 14:32:30 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 64.6 seconds
Jul 31 14:33:35 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 64.1 seconds
Jul 31 14:34:39 [11327]: eth1: sending REQUEST (xid 0x416e18b5), next in 63.7 seconds