From dmrz@illinois.edu Mon Feb 29 22:37:31 2016 MIME-Version: 1.0 In-Reply-To: X-Spam-Status: No, score=-1.9 required=5.0 tests=BAYES_00 autolearn=ham autolearn_force=no version=3.4.0 X-RT-Interface: API References: <56D0F465.5010402@illinois.edu> Message-ID: <56D4C826.2030001@illinois.edu> content-type: text/plain; charset="utf-8" X-RT-Original-Encoding: utf-8 Received: from mx.pao1.isc.org (mx.pao1.isc.org [IPv6:2001:4f8:0:2::2b]) by bugs.isc.org (Postfix) with ESMTP id DF2FA71B5A8 for ; Mon, 29 Feb 2016 22:37:31 +0000 (UTC) Received: from golbez.ci.uiuc.edu (golbez.ci.uiuc.edu [192.17.25.102]) by mx.pao1.isc.org (Postfix) with ESMTP id 92552349315 for ; Mon, 29 Feb 2016 22:37:29 +0000 (UTC) Received: from [127.0.0.1] (localhost [127.0.0.1]) by golbez.ci.uiuc.edu (Postfix) with ESMTP id C59082203EF for ; Mon, 29 Feb 2016 16:37:26 -0600 (CST) Delivered-To: dhcp-bugs@bugs.isc.org User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.5.1 Subject: Re: [ISC-Bugs #41815] issues reclaiming abandoned leases Return-Path: X-Original-To: dhcp-bugs@bugs.isc.org Date: Mon, 29 Feb 2016 16:37:26 -0600 X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on mx.pao1.isc.org To: dhcp-bugs@isc.org Content-Transfer-Encoding: 8bit From: "David Zych" RT-Message-ID: Content-Length: 5592 Two additional notes on these issues: 1. I recompiled dhcp-4.3.3-P1 without the experimental options I was using before (now specifying only --prefix, --sysconfdir, and --localstatedir) and was still able to reproduce the bad behaviors. My simplest test case is now a single server running default dhcp-4.3.3-P1 with the following dhcpd.conf: === subnet 128.174.204.0 netmask 255.255.254.0 { not authoritative; } lease-file-name "/services/ts-dhcp/var/lib/dhcpd/dhcpd.leases"; log-facility local7; ping-check true; ping-timeout 1; subnet 172.21.195.0 netmask 255.255.255.240 { option routers 172.21.195.1; option broadcast-address 172.21.195.15; pool { deny dynamic bootp clients; range 172.21.195.13 172.21.195.14; } } === plus two "squatter" VMs occupying both IP addresses, and a single Peppermint 6 client VM attempting to obtain a lease via DHCP (booting from a snapshot with no prior state on this network). Starting from an empty dhcpd.leases, and letting the client run for a few minutes while watching `tail -f dhcpd.leases /var/log/syslog/local7`, I can easily observe all of the following: * inappropriate DHCPOFFER (without ping-checking the address again) when reclaiming an abandoned IP * eventually (after enough tries) a DHCPACK on one of these IPs, leading to an IP conflict with the squatter * abandoned leases mysteriously being set back to free in dhcpd.leases after roughly two minutes ** Having slept on it, this third problem (mysterious freeing of abandoned leases) is actually the one that makes me most nervous, because it can cause trouble even when the pool is not exhausted. 2. Abandoned leases are also mysteriously cleared/discarded upon server startup. Using same dhcpd.conf as above, start from empty dhcpd.leases file, but this time stop as soon as you see the first DHCPDISCOVER appear in the logs. ts-dhcp@dhcp-dev1:~/var/lib/dhcpd$ tail -f dhcpd.leases /var/log/syslog/local7 ==> dhcpd.leases <== # The format of this file is documented in the dhcpd.leases(5) manual page. # This lease file was written by isc-dhcp-4.3.3-P1 server-duid "\000\001\000\001\036g~7\000PV\214Pg"; ==> /var/log/syslog/local7 <== 2016-02-29T16:09:41.343441-06:00 dhcp-dev1 dhcpd: DHCPDISCOVER from 00:10:18:72:58:e9 via eth0: network 128.174.204.0/23: no free leases 2016-02-29T16:09:59.945197-06:00 dhcp-dev1 dhcpd: Internet Systems Consortium DHCP Server 4.3.3-P1 2016-02-29T16:09:59.945221-06:00 dhcp-dev1 dhcpd: Copyright 2004-2016 Internet Systems Consortium. 2016-02-29T16:09:59.945239-06:00 dhcp-dev1 dhcpd: All rights reserved. 2016-02-29T16:09:59.945263-06:00 dhcp-dev1 dhcpd: For info, please visit https://www.isc.org/software/dhcp/ 2016-02-29T16:09:59.945512-06:00 dhcp-dev1 dhcpd: Wrote 0 leases to leases file. 2016-02-29T16:09:59.947758-06:00 dhcp-dev1 dhcpd: Listening on LPF/eth0/00:50:56:8c:50:67/128.174.204.0/23 2016-02-29T16:09:59.947875-06:00 dhcp-dev1 dhcpd: Sending on LPF/eth0/00:50:56:8c:50:67/128.174.204.0/23 2016-02-29T16:09:59.947922-06:00 dhcp-dev1 dhcpd: Sending on Socket/fallback/fallback-net 2016-02-29T16:09:59.949151-06:00 dhcp-dev1 dhcpd: Server starting service. 2016-02-29T16:12:45.070878-06:00 dhcp-dev1 dhcpd: DHCPDISCOVER from 08:00:27:19:62:e0 via 172.21.195.1 ==> dhcpd.leases <== lease 172.21.195.13 { starts 1 2016/02/29 22:12:45; ends 1 2016/02/29 22:12:45; cltt 1 2016/02/29 22:12:45; binding state abandoned; next binding state free; rewind binding state free; client-hostname "p6test3"; } ==> /var/log/syslog/local7 <== 2016-02-29T16:12:45.071433-06:00 dhcp-dev1 dhcpd: Abandoning IP address 172.21.195.13: pinged before offer 2016-02-29T16:12:45.071417-06:00 dhcp-dev1 dhcpd: ICMP Echo reply while lease 172.21.195.13 valid. At this point we halt the client VM so there will be no further DHCPDISCOVERs. Now stop dhcpd (with kill -TERM) and observe that (as expected) it leaves behind a dhcpd.leases containing exactly one abandoned lease: lease 172.21.195.13 { starts 1 2016/02/29 22:12:45; ends 1 2016/02/29 22:12:45; cltt 1 2016/02/29 22:12:45; binding state abandoned; next binding state free; rewind binding state free; client-hostname "p6test3"; } Finally, start dhcpd again. ts-dhcp@dhcp-dev1:~/var/lib/dhcpd$ ~/bin/start_dhcp Internet Systems Consortium DHCP Server 4.3.3-P1 Copyright 2004-2016 Internet Systems Consortium. All rights reserved. For info, please visit https://www.isc.org/software/dhcp/ Config file: /services/ts-dhcp/etc/dhcpd.conf Database file: /services/ts-dhcp/var/lib/dhcpd/dhcpd.leases PID file: /services/ts-dhcp/var/run/dhcpd.pid Wrote 0 leases to leases file. Listening on LPF/eth0/00:50:56:8c:50:67/128.174.204.0/23 Sending on LPF/eth0/00:50:56:8c:50:67/128.174.204.0/23 Sending on Socket/fallback/fallback-net And indeed "Wrote 0 leases" is what we get; the new dhcpd.leases no longer contains any leases. Furthermore, the no-longer-active file dhcpd.leases~ now contains a second entry freeing the formerly-abandoned lease: lease 172.21.195.13 { starts 1 2016/02/29 22:12:45; ends 1 2016/02/29 22:12:45; cltt 1 2016/02/29 22:12:45; binding state abandoned; next binding state free; rewind binding state free; client-hostname "p6test3"; } lease 172.21.195.13 { starts 1 2016/02/29 22:12:45; ends 1 2016/02/29 22:12:45; tstp 1 2016/02/29 22:12:45; cltt 1 2016/02/29 22:12:45; binding state free; client-hostname "p6test3"; } Thanks, David -- David Zych Lead Network Service Engineer University of Illinois Technology Services