[dhclient] Client did not bind to the address even after receiving DHCPACK
Describe the bug
Usually, every DHCPACK message is followed by a bound log message.
Mar 29 10:20:46.328836 sonic INFO dhclient[3350]: DHCPREQUEST for 10.210.24.228 on eth0 to 255.255.255.255 port 67
Mar 29 10:20:46.329931 sonic INFO dhclient[3350]: DHCPACK of 10.210.24.228 from 10.211.0.124
Mar 29 10:20:46.584251 sonic INFO dhclient[3350]: bound to 10.210.24.228 -- renewal in 1536 seconds.
Mar 29 10:21:19.521847 sonic INFO dhclient[7991]: DHCPRELEASE of 10.210.24.228 on eth0 to 10.211.0.124 port 67
DHCPRELEASE because there were systemd restarts in between and it made the dhclient to explicitly release the IP Address.
After a few such cycles and following the last DHCPACK, there was no bound to log message and the connection to the device was lost (no lease was generated as expected in the host file). We manually had to run dhclient eth0
to get the IP Addr back.
Mar 29 10:25:54.446311 r-anaconda-70 INFO dhclient[3544]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 11
Mar 29 10:25:54.447348 r-anaconda-70 INFO dhclient[3544]: DHCPOFFER of 10.210.24.228 from 10.211.0.124
Mar 29 10:25:54.447477 r-anaconda-70 INFO dhclient[3544]: DHCPREQUEST for 10.210.24.228 on eth0 to 255.255.255.255 port 67
Mar 29 10:25:54.448561 r-anaconda-70 INFO dhclient[3544]: DHCPACK of 10.210.24.228 from 10.211.0.124
...
Mar 29 17:29:53.334129 r-anaconda-70 INFO dhclient[3544]: bound to 10.210.24.228 -- renewal in -23800 seconds.
The process though is surprisingly not dead, and it threw this bound to message after we manually ran 'dhclient eth0'. (Looked like it kinda stuck in a loop/deadlock)
The -23800 seconds signifies that the dhclient reached that point way after the lease has expired. Ref: https://gitlab.isc.org/isc-projects/dhcp/-/blob/master/client/dhclient.c#L1616
log_info("bound to %s -- renewal in %ld seconds.",
piaddr(client->active->address),
(long)(client->active->renewal - cur_time));
We suspected Dhclient Script Failure could be a reason. (845c8522) but not entirely sure of it.
This is hard to reproduce but happens every now and then.
Any inputs on why such behavior could arise and any suggestions on how to avoid it are appreciated.
Environment:
Version: isc-dhclient-4.4.1 (Not Compiled from source)
dhclient.conf
option rfc3442-classless-static-routes code 121 = array of unsigned integer 8;
option snmp-community code 224 = text;
option minigraph-url code 225 = text;
option acl-url code 226 = text;
option tftp-server-name code 66 = text;
option bootfile-name code 67 = text;
option user-class code 77 = text;
option provisioning-script-url code 239 = text;
option dhcp6.user-class code 15 = text;
option dhcp6.provisioning-script-url code 239 = text;
option dhcp6.boot-file-url code 59 = text;
send host-name = gethostname();
request subnet-mask, broadcast-address, time-offset, routers,
domain-name, domain-name-servers, domain-search, host-name,
dhcp6.name-servers, dhcp6.domain-search, interface-mtu, dhcp6.fqdn,
rfc3442-classless-static-routes, ntp-servers, log-servers,snmp-community, minigraph-url, acl-url;