On Thu, Jul 06, 2017 at 11:28:11AM +0200, Landry Breuil wrote: > On Wed, Jul 05, 2017 at 04:37:39PM +0200, Reyk Floeter wrote: > > Hi, > > > > landry@ sees many log messages 'DHCPINFORM from xx but ciaddr yy is > > not consistent with actual address' in a setup where dhcpd runs behind > > dhcrelay. > > > > The code in dhcpd's dhcpinform() seems wrong - it assumes that ciaddr > > (the client IP) is identical to the packet source address and it > > doesn't consider a relay, indicated by giaddr (gateway). > > > > I looked at isc-dhcpd code and, omg my eyes are bleeding, it seems to > > handle DHCPINFORM from relayed clients with giaddr set. > > > > So it seems that dhcpd never accepted DHCPINFORM from clients behind a > > relay, and the diff below changes it and stops the log spam. But it > > also changes behavior, so it needs some testing and maybe feedback > > from DHCP experts (prodding krw). > > I've put this on a 6.1 vm behind a dhcrelay at work, previously the > w7 clients were apparently sending DHCPINFORM every ~10mn, and in bursts: > > Jul 5 14:52:42 oberalp dhcpd[92834]: DHCPINFORM from 172.20.85.254 but > ciaddr 172.20.85.124 is not consistent with actual address > Jul 5 14:52:45 oberalp dhcpd[92834]: DHCPINFORM from 172.20.85.254 but > ciaddr 172.20.85.124 is not consistent with actual address > Jul 5 14:54:11 oberalp last message repeated 2 times > Jul 5 14:55:23 oberalp dhcpd[92834]: DHCPINFORM from 172.20.85.254 but > ciaddr 172.20.85.107 is not consistent with actual address > Jul 5 14:55:26 oberalp dhcpd[92834]: DHCPINFORM from 172.20.85.254 but > ciaddr 172.20.85.107 is not consistent with actual address > Jul 5 14:56:50 oberalp last message repeated 2 times > > With this diff, now the clients still send DHCPINFORM, some every ~10mn, > some every ~30m, still in bursts, and the DHCPACK is sent back: > > Jul 6 11:08:06 oberalp dhcpd[42317]: DHCPACK to 172.20.85.107 > (<xx:xx:xx:xx:xx:xx>) via 172.20.85.254 > Jul 6 11:08:09 oberalp dhcpd[42317]: DHCPINFORM from 172.20.85.254 > Jul 6 11:08:09 oberalp dhcpd[42317]: DHCPACK to 172.20.85.107 > (<xx:xx:xx:xx:xx:xx>) via 172.20.85.254 > Jul 6 11:18:13 oberalp dhcpd[42317]: DHCPINFORM from 172.20.85.254 > Jul 6 11:18:13 oberalp dhcpd[42317]: DHCPACK to 172.20.85.107 > (<xx:xx:xx:xx:xx:xx>) via 172.20.85.254 > Jul 6 11:18:16 oberalp dhcpd[42317]: DHCPINFORM from 172.20.85.254 > Jul 6 11:18:16 oberalp dhcpd[42317]: DHCPACK to 172.20.85.107 > (<xx:xx:xx:xx:xx:xx>) via 172.20.85.254 > Jul 6 11:19:13 oberalp dhcpd[42317]: DHCPINFORM from 172.20.85.254 > Jul 6 11:19:13 oberalp dhcpd[42317]: DHCPACK to 172.20.85.122 > (<yy:yy:yy:yy:yy:yy>) via 172.20.85.254 > Jul 6 11:19:16 oberalp dhcpd[42317]: DHCPINFORM from 172.20.85.254 > Jul 6 11:19:16 oberalp dhcpd[42317]: DHCPACK to 172.20.85.122 > (<yy:yy:yy:yy:yy:yy>) via 172.20.85.254 > Jul 6 11:20:58 oberalp dhcpd[42317]: DHCPINFORM from 172.20.85.254 > Jul 6 11:20:58 oberalp dhcpd[42317]: DHCPACK to 172.20.85.122 > (<yy:yy:yy:yy:yy:yy>) via 172.20.85.254 > Jul 6 11:21:01 oberalp dhcpd[42317]: DHCPINFORM from 172.20.85.254 > Jul 6 11:21:01 oberalp dhcpd[42317]: DHCPACK to 172.20.85.122 > (<yy:yy:yy:yy:yy:yy>) via 172.20.85.254
And it seems after a while the win7 clients *finally* stop spamming the server with DHCPINFORM requests. Yay. Maybe that's because of the hack put in dhcpd.conf ---- option autoproxy-script "\\n"; ---- Something else, which i dunno is related to this diff or not - before, a dhcpd was receiving a single DHCPREQUEST (ie i ran dhclient on an openbsd client) and replying to it: Jul 5 14:22:15 oberalp dhcpd[92834]: DHCPREQUEST for 172.20.85.109 from 00:24:e8:3d:46:fe via 172.20.85.254 Jul 5 14:22:15 oberalp dhcpd[92834]: DHCPACK on 172.20.85.109 to 00:24:e8:3d:46:fe via 172.20.85.254 Now, for some linux clients which are re-requesting/renewing a lease, i see two REQUESTS in the log, one logged as coming directly on vio0, and one coming from the dhcrelay gateway: Jul 7 06:16:14 oberalp dhcpd[91347]: DHCPREQUEST for 172.20.85.110 from 00:14:fd:12:96:8e via vio0 Jul 7 06:16:14 oberalp dhcpd[91347]: DHCPACK on 172.20.85.110 to 00:14:fd:12:96:8e via vio0 Jul 7 06:16:14 oberalp dhcpd[91347]: DHCPREQUEST for 172.20.85.110 from 00:14:fd:12:96:8e via 172.20.85.254 Jul 7 06:16:14 oberalp dhcpd[91347]: DHCPACK on 172.20.85.110 to 00:14:fd:12:96:8e via 172.20.85.254 Jul 7 06:51:10 oberalp dhcpd[91347]: DHCPREQUEST for 172.20.85.111 from 00:19:b9:fe:b2:10 via vio0 Jul 7 06:51:10 oberalp dhcpd[91347]: DHCPACK on 172.20.85.111 to 00:19:b9:fe:b2:10 via vio0 Jul 7 06:51:10 oberalp dhcpd[91347]: DHCPREQUEST for 172.20.85.111 from 00:19:b9:fe:b2:10 via 172.20.85.254 Jul 7 06:51:10 oberalp dhcpd[91347]: DHCPACK on 172.20.85.111 to 00:19:b9:fe:b2:10 via 172.20.85.254 Dunno if that's an expected behaviour - and it seems it was already this way before the diff. For a new client using DHCPDISCOVER dhcpd only sees a single discover/offer/request/ack sequence: Jul 7 09:11:27 oberalp dhcpd[91347]: DHCPDISCOVER from 00:50:b6:5c:d9:e8 via 172.20.85.254 Jul 7 09:11:27 oberalp dhcpd[91347]: DHCPOFFER on 172.20.85.112 to 00:50:b6:5c:d9:e8 via 172.20.85.254 Jul 7 09:11:27 oberalp dhcpd[91347]: DHCPREQUEST for 172.20.85.112 from 00:50:b6:5c:d9:e8 via 172.20.85.254 Jul 7 09:11:27 oberalp dhcpd[91347]: DHCPACK on 172.20.85.112 to 00:50:b6:5c:d9:e8 via 172.20.85.254 Anyway, it seems reyk's diff improved the situation for my setup. Landry
