[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