Excessive DHCP requests in /var/log/messages: DHCPINFORM, DHCPACK and DHCPREQUEST repeated

Question

I have a CentOS 5 system running DHCP for several subnets. In /var/log/messages, I'm seeing constant DHCPINFORM, DHCPACK and DHCPREQUEST messages. I don't understand why these requests are more frequent here than in other installations. The messages come in bursts every few seconds, resulting in extremely large logfiles.

The bulk of the devices here are wireless handheld devices (using a Windows CE TCP stack). I'd appreciate any insight into quelling the constant messages.

/etc/dhcpd.conf

default-lease-time 28800;
authoritative;
allow bootp;
ddns-update-style none;
option subnet-mask 255.255.255.0;
option domain-name-servers  10.1.1.3;
option domain-name "xxxinc.com";
option tftp-server-name "10.1.1.3";
option ntp-servers 17.151.16.21;

subnet 10.1.1.0 netmask 255.255.255.0 {
        range dynamic-bootp 10.1.1.120 10.1.1.211;
        option tftp-server-name "10.1.1.3";
        next-server 10.1.1.3;
        filename "/dsl/pxelinux.0";
        option routers 10.1.1.1;
}

subnet 10.1.2.0 netmask 255.255.255.0 {
        range dynamic-bootp 10.1.2.130 10.1.2.199;
        option tftp-server-name "10.1.1.3";
        next-server 10.1.1.3;
        filename "/dsl/pxelinux.0";
        option routers 10.1.2.1;
}

/var/log/messages

Apr  4 10:59:44 General dhcpd: DHCPINFORM from 10.1.1.136 via eth0
Apr  4 10:59:44 General dhcpd: DHCPACK to 10.1.1.136 (00:16:35:07:1e:61) via eth0
Apr  4 10:59:44 General dhcpd: DHCPINFORM from 10.1.1.136 via eth0
Apr  4 10:59:44 General dhcpd: DHCPACK to 10.1.1.136 (00:16:35:07:1e:61) via eth0
Apr  4 10:59:44 General dhcpd: DHCPINFORM from 10.1.1.136 via 10.1.1.254
Apr  4 10:59:44 General dhcpd: DHCPACK to 10.1.1.136 (00:16:35:07:1e:61) via eth0
Apr  4 10:59:44 General dhcpd: DHCPINFORM from 10.1.1.136 via 10.1.1.254
Apr  4 10:59:44 General dhcpd: DHCPACK to 10.1.1.136 (00:16:35:07:1e:61) via eth0
Apr  4 10:59:44 General dhcpd: DHCPINFORM from 10.1.1.136 via 10.1.1.2
Apr  4 10:59:44 General dhcpd: DHCPACK to 10.1.1.136 (00:16:35:07:1e:61) via eth0
Apr  4 10:59:46 General dhcpd: DHCPREQUEST for 10.1.1.137 from 00:15:70:85:9b:ea via eth0
Apr  4 10:59:46 General dhcpd: DHCPACK on 10.1.1.137 to 00:15:70:85:9b:ea via eth0
Apr  4 10:59:46 General dhcpd: DHCPREQUEST for 10.1.1.137 from 00:15:70:85:9b:ea via eth0
Apr  4 10:59:46 General dhcpd: DHCPACK on 10.1.1.137 to 00:15:70:85:9b:ea via eth0
Apr  4 10:59:46 General dhcpd: DHCPREQUEST for 10.1.1.137 from 00:15:70:85:9b:ea via 10.1.1.254
Apr  4 10:59:46 General dhcpd: DHCPACK on 10.1.1.137 to 00:15:70:85:9b:ea via 10.1.1.254
Apr  4 10:59:46 General dhcpd: DHCPREQUEST for 10.1.1.137 from 00:15:70:85:9b:ea via 10.1.1.254
Apr  4 10:59:46 General dhcpd: DHCPACK on 10.1.1.137 to 00:15:70:85:9b:ea via 10.1.1.254
Apr  4 10:59:46 General dhcpd: DHCPREQUEST for 10.1.1.137 from 00:15:70:85:9b:ea via 10.1.1.2
Apr  4 10:59:46 General dhcpd: DHCPACK on 10.1.1.137 to 00:15:70:85:9b:ea via 10.1.1.2
Apr  4 10:59:47 General dhcpd: DHCPINFORM from 10.1.2.193 via 10.1.2.1
Apr  4 10:59:47 General dhcpd: DHCPACK to 10.1.2.193 (00:1a:4b:c0:e0:a4) via eth0
Apr  4 10:59:47 General dhcpd: DHCPINFORM from 10.1.1.147 via eth0
Apr  4 10:59:47 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Apr  4 10:59:47 General dhcpd: DHCPINFORM from 10.1.1.147 via eth0
Apr  4 10:59:47 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Apr  4 10:59:47 General dhcpd: DHCPINFORM from 10.1.1.147 via 10.1.1.254
Apr  4 10:59:47 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Apr  4 10:59:47 General dhcpd: DHCPINFORM from 10.1.1.147 via 10.1.1.254
Apr  4 10:59:47 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Apr  4 10:59:47 General dhcpd: DHCPINFORM from 10.1.1.147 via 10.1.1.2
Apr  4 10:59:47 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Apr  4 10:59:49 General dhcpd: DHCPREQUEST for 10.1.1.198 from 00:15:70:86:dc:b9 via eth0
Apr  4 10:59:49 General dhcpd: DHCPACK on 10.1.1.198 to 00:15:70:86:dc:b9 via eth0
Apr  4 10:59:49 General dhcpd: DHCPREQUEST for 10.1.1.198 from 00:15:70:86:dc:b9 via eth0
Apr  4 10:59:49 General dhcpd: DHCPACK on 10.1.1.198 to 00:15:70:86:dc:b9 via eth0
Apr  4 10:59:49 General dhcpd: DHCPREQUEST for 10.1.1.198 from 00:15:70:86:dc:b9 via 10.1.1.254
Apr  4 10:59:49 General dhcpd: DHCPACK on 10.1.1.198 to 00:15:70:86:dc:b9 via 10.1.1.254
Apr  4 10:59:49 General dhcpd: DHCPREQUEST for 10.1.1.198 from 00:15:70:86:dc:b9 via 10.1.1.254
Apr  4 10:59:49 General dhcpd: DHCPACK on 10.1.1.198 to 00:15:70:86:dc:b9 via 10.1.1.254
Apr  4 10:59:49 General dhcpd: DHCPREQUEST for 10.1.1.198 from 00:15:70:86:dc:b9 via 10.1.1.2
Apr  4 10:59:49 General dhcpd: DHCPACK on 10.1.1.198 to 00:15:70:86:dc:b9 via 10.1.1.2

UPDATE

I've removed some extraneous ip helper-address entries from some the DHCP server-side routers. Much of the traffic has subsided, however I'm still getting a lot of DHCPINFORM,DHCPACK...

Oct 26 17:22:23 General dhcpd: DHCPINFORM from 10.1.1.140 via eth0
Oct 26 17:22:23 General dhcpd: DHCPACK to 10.1.1.140 (00:16:35:07:1e:2c) via eth0
Oct 26 17:22:27 General dhcpd: DHCPINFORM from 10.1.1.147 via eth0
Oct 26 17:22:27 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Oct 26 17:22:27 General dhcpd: DHCPINFORM from 10.1.1.140 via eth0
Oct 26 17:22:27 General dhcpd: DHCPACK to 10.1.1.140 (00:16:35:07:1e:2c) via eth0
Oct 26 17:22:39 General dhcpd: DHCPINFORM from 10.1.1.182 via eth0
Oct 26 17:22:39 General dhcpd: DHCPACK to 10.1.1.182 (00:19:bb:d3:ec:f1) via eth0
Oct 26 17:22:43 General dhcpd: DHCPINFORM from 10.1.1.182 via eth0
Oct 26 17:22:43 General dhcpd: DHCPACK to 10.1.1.182 (00:19:bb:d3:ec:f1) via eth0
Oct 26 17:22:49 General dhcpd: DHCPINFORM from 10.1.2.198 via 10.1.2.1
Oct 26 17:22:49 General dhcpd: DHCPACK to 10.1.2.198 (00:1e:0b:79:e5:15) via eth0
Oct 26 17:23:01 General dhcpd: DHCPINFORM from 10.1.1.194 via eth0
Oct 26 17:23:01 General dhcpd: DHCPACK to 10.1.1.194 (00:1e:0b:7b:2d:d6) via eth0
Oct 26 17:23:04 General dhcpd: DHCPINFORM from 10.1.1.136 via eth0
Oct 26 17:23:04 General dhcpd: DHCPACK to 10.1.1.136 (00:16:35:07:1e:61) via eth0
Oct 26 17:23:07 General dhcpd: DHCPINFORM from 10.1.1.136 via eth0
Oct 26 17:23:07 General dhcpd: DHCPACK to 10.1.1.136 (00:16:35:07:1e:61) via eth0
Oct 26 17:23:09 General dhcpd: DHCPINFORM from 10.1.2.193 via 10.1.2.1
Oct 26 17:23:09 General dhcpd: DHCPACK to 10.1.2.193 (00:1a:4b:c0:e0:a4) via eth0
Oct 26 17:23:12 General dhcpd: DHCPINFORM from 10.1.2.179 via 10.1.2.1
Oct 26 17:23:12 General dhcpd: DHCPACK to 10.1.2.179 (00:19:bb:d3:f6:26) via eth0
Oct 26 17:23:13 General dhcpd: DHCPINFORM from 10.1.2.193 via 10.1.2.1
Oct 26 17:23:13 General dhcpd: DHCPACK to 10.1.2.193 (00:1a:4b:c0:e0:a4) via eth0
Oct 26 17:23:15 General dhcpd: DHCPINFORM from 10.1.2.179 via 10.1.2.1
Oct 26 17:23:15 General dhcpd: DHCPACK to 10.1.2.179 (00:19:bb:d3:f6:26) via eth0
Oct 26 17:23:36 General dhcpd: DHCPINFORM from 10.1.1.140 via eth0
Oct 26 17:23:36 General dhcpd: DHCPACK to 10.1.1.140 (00:16:35:07:1e:2c) via eth0
Oct 26 17:23:37 General dhcpd: DHCPINFORM from 10.1.1.147 via eth0
Oct 26 17:23:37 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Oct 26 17:23:40 General dhcpd: DHCPINFORM from 10.1.1.140 via eth0
Oct 26 17:23:40 General dhcpd: DHCPACK to 10.1.1.140 (00:16:35:07:1e:2c) via eth0
Oct 26 17:23:41 General dhcpd: DHCPINFORM from 10.1.1.147 via eth0
Oct 26 17:23:41 General dhcpd: DHCPACK to 10.1.1.147 (00:19:bb:d3:bc:e8) via eth0
Oct 26 17:23:50 General dhcpd: DHCPINFORM from 10.1.2.198 via 10.1.2.1
Oct 26 17:23:50 General dhcpd: DHCPACK to 10.1.2.198 (00:1e:0b:79:e5:15) via eth0
Oct 26 17:23:51 General dhcpd: DHCPINFORM from 10.1.1.182 via eth0
Oct 26 17:23:51 General dhcpd: DHCPACK to 10.1.1.182 (00:19:bb:d3:ec:f1) via eth0

Solution 1

Looks like you have clients connected to multiple subnets (or routers that are relaying dhcp helper to each other). Since I am not privy to your topology, I can't say for sure.

A few things to check:

1. Does this happen to all clients? Or just those located on a specific network segment?
2. Are those clients connected to multiple subnets?
3. Have you verified that there's no bridging between your subnets?

And you should look at each of your clients, perhaps with ethreal, and determine if they are receiving multiple DHCPACK from multiple routers (they probably are).

Solution 2

Some clients (notably Windows 7) constantly sends DHCPINFORM messages if there is no WPAD option specified in the DHCPACK response.

You can fix this for ISC DHCP by adding the following lines to your config:

option wpad code 252 = text;

subnet xxx {
    option wpad "\n";
}

You can fix this for dnsmasq by adding the following to the dnsmasq.conf file:

dhcp-option=252,"\n"

Solution 3

Your DHCP server appears to be listening on the same interface multiple times, with different sockets (look at the "via" bits -- it talks about eth0 and two different IP addresses). If you have explicitly configured the DHCP server's listening sockets, check that you only have one socket per interface.

Other than that, the traffic looks pretty normal. Windows hosts often query additional parameters that they didn't cache using a DHCPINFORM, and WinCE has pretty small caches anyway.

Comments

[Admin]

which machines have 10.1.1.254 and 10.1.1.2?

[Admin]

Has this question really been open for months?

[Admin]

Yes. It has been unanswered for months.

[Admin]

Wow. That's a shame, I hope I got you on the right track. :-)

[ddm-j]

In that case, should these also repeat messages received from a subnet back to the same subnet? Because that is what they seem to be doing.

[ewwhite]

I found helper-address entries on the dhcp server's local subnet's routers. Those have been removed and I'm monitoring the traffic to see if the logging subsides.

[Joseph Kern]

Yeah ... it seems like your routers are repeating the DHCP broadcasts from AND to each other, this is why you see two of every broadcast in sets of three. You are creating small DHCP broadcast storms.