[BusyBox] DHCP client renewal "storm" = LOG DETAILS

Brett Stewart brett.stewart at acumera.net
Tue Sep 2 13:57:46 UTC 2003


On Tue, 2003-09-02 at 02:02, Russ Dill wrote:
> On Mon, 2003-09-01 at 22:24, Joshua Jackson wrote:
> > Whenever the DHCP client goes to renew an address, I get the following in the 
> > system log.
> 
> can you be more specific as to versions involed, actual lease times,
> etc?

I too am seeing these relnew 'storms'

I am cross-target to an ARM, using uClibc 0.9.20 and the Busybox 'pre2'
tarball.  The DHCP server is a recent ISC DHCP server by Ted Lemon.

Leases are being issued for two hours..

Here is an excerpt from my logs - by the way, this prompted me to
propose the sylog feature I've seen somewhere else (can't remember
where, though) where repeated lines are suppressed with "above repeated
n times" - for those doing circular log buffer on limited memory
systems, such a feature might be very helpful.

Client Log snippet:

Jan  1 00:00:02 MMG local0.info udhcpc[49]: client (v0.9.9-pre) started
Jan  1 00:00:03 MMG local0.debug udhcpc[49]: Sending discover...
Jan  1 00:00:05 MMG local0.debug udhcpc[49]: Sending discover...
Jan  1 00:00:05 MMG local0.debug udhcpc[49]: Sending select for 172.16.0.111...
Jan  1 00:00:05 MMG local0.info udhcpc[49]: Lease of 172.16.0.111 obtained, lease time 7200

(We have to get a lease in order to set the time)
...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  1 23:28:59 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200

(You'd think the server were too slow were it not for the timestamps)
...
Sep  2 02:28:59 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 02:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 02:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 03:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 03:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200

(this is an interesting block - what the server said at 2:28 is below)

Sep  2 04:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 04:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 05:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 05:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 06:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 06:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 07:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 07:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 08:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 08:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 09:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 09:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 10:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 10:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 11:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 11:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200
Sep  2 12:51:29 MMG local0.debug udhcpc[72]: Sending renew...
Sep  2 12:51:29 MMG local0.info udhcpc[72]: Lease of 172.16.0.111 obtained, lease time 7200

(this all looks normal)
(now the server logs - unfortunately they are timestamped in CDT instead of UTC and there is a few seconds of skew)

Sep  1 17:29:16 internal dhcpd-2.2.x: DHCPDISCOVER from 00:80:5e:01:01:01 via eth1
Sep  1 17:29:16 internal dhcpd-2.2.x: DHCPOFFER on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 17:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 17:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1

(server sees one discover, client claims to have sent two)

Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 18:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
Sep  1 18:34:09 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.10 from 00:50:41:01:7d:56 via eth1
Sep  1 18:34:09 internal dhcpd-2.2.x: DHCPACK on 172.16.0.10 to 00:50:41:01:7d:56 via eth1

(sure looks like the server side of a client-generated storm)

Sep  1 19:29:15 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 19:29:15 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1

(this is a 'normal' renew, perhaps slightly premature.  I think the spec says the client should renew with half the lease used up)
(now, in the 'interesting' client block above, there is another request 22:30 or so later, but it doesn't appear in the logs on the server)

Sep  1 20:29:16 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 20:29:16 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1

(looks normal)

Sep  1 21:51:47 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 21:51:47 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
...
Sep  1 22:51:46 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 22:51:46 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
...
Sep  1 23:51:46 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  1 23:51:46 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
...
Sep  2 00:51:45 internal dhcpd-2.2.x: DHCPREQUEST for 172.16.0.111 from 00:80:5e:01:01:01 via eth1
Sep  2 00:51:45 internal dhcpd-2.2.x: DHCPACK on 172.16.0.111 to 00:80:5e:01:01:01 via eth1
...

(all looking normal - but the time is peculiar again, even tho it settles down.)


All this suggests a small bug in the client code, perhaps relating to it's notion of time.


Hope this helps.

> -- 
> Brett Stewart <brett.stewart at acumera.net>
> Acumera, Inc.




More information about the busybox mailing list