Date: Wed, 26 May 2004 14:20:07 -0400 From: "Vladislav Staroselskiy" <inet@vladstar.pp.ru> To: <freebsd-bugs@freebsd.org> Subject: dhclient weird behavior Message-ID: <012801c4434e$172e0ae0$1baca18d@VStar>
next in thread | raw e-mail | index | archive | help
Hi ! I am tired of weird behavior of "new" dhclient in FreeBSD. Older 4.5 version of FreeBSD never had this kind of problems, but I got problems when I upgraded FreeBSD from 4.5 to 5.0, and then 5.2.1. I use dhclient to obtain DHCP IP address from Comcast, which was pretty permanent before (changed 1-2 times per year), now my IP is changing every day/few days. It's not Comcast's DHCP server fault, because the FreeBSD 4.5, that I have also configured at my neighbor's, connected to the same DHCP server within the same DHCP scope with the same settings, still keeps it's IP address for few months already and doesn't have any problem like that. According to RFC1531 (http://rfc.net/rfc1531.html#s4.4.4), it supposed to get IP address, then try to renew it at 50% of lease time, etc. Last time, I have completely disabled firewall rules (to make sure, that it's not issue with ipfw rules), then logged all packets for 67-68 ports using both tcpdump and ipfw logging. Let's take a look on my configuration and logs: There is nothing special here: === /etc/dhclient.conf === timeout 60; reboot 10; retry 60; select-timeout 5; initial-interval 2; interface "xl0" { send dhcp-lease-time 86400; # 86400 - request 1 day lease prepend domain-name-servers 127.0.0.1; prepend domain-name "homenet "; } === /etc/dhclient.conf === Allow&log everything on 67-68 ports into /var/log/security, allow everything else: === ipfw show === 00050 1855891 360726880 divert 8668 ip from any to any via xl0 00100 524536 65820482 allow ip from any to any via lo0 00200 0 0 deny ip from any to 127.0.0.0/8 00300 0 0 deny ip from 127.0.0.0/8 to any 00400 5012 1659789 allow log udp from any 67-68 to any dst-port 67-68 65000 2958562 573131391 allow ip from any to any 65535 31 3589 deny ip from any to any === ipfw show === Got DHCP lease and IP address: === /var/log/messages === May 24 01:11:03 vladstar kernel: xl0: promiscuous mode enabled May 24 01:11:12 vladstar dhclient: send_packet: No route to host May 24 01:11:17 vladstar dhclient: New IP Address (xl0): x.y.240.28 May 24 01:11:17 vladstar dhclient: New Subnet Mask (xl0): 255.255.252.0 May 24 01:11:17 vladstar dhclient: New Broadcast Address (xl0): x.y.243.255 May 24 01:11:17 vladstar dhclient: New Routers: x.y.240.1 === /var/log/messages === === tcpdump.txt === 01:11:12.008849 0.0.0.0.bootpc > 255.255.255.255.bootps: xid:0x66d0a757 [|bootp] [tos 0x10] 01:11:12.166209 10.70.208.1.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 Y:<myhost>.comcast.net S:172.30.100.36 G:<mydefaultrouter>.comcast.net [|bootp] 01:11:17.002811 0.0.0.0.bootpc > 255.255.255.255.bootps: xid:0x66d0a757 [|bootp] [tos 0x10] 01:11:17.019096 10.70.208.1.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 Y:<myhost>.comcast.net S:172.30.100.36 G:<mydefaultrouter>.comcast.net [|bootp] === tcpdump.txt === === /var/db/dhclient.leases === lease { interface "xl0"; fixed-address x.y.240.28; filename "mdcm245_v1_silver_c01"; option subnet-mask 255.255.252.0; option routers x.y.240.1; option dhcp-lease-time 86400; option dhcp-message-type 5; option dhcp-server-identifier 172.30.100.36; option domain-name-servers 127.0.0.1,x.y.0.6,x.z.96.16,x.y.0.12,x.z.96.15; option domain-name "homenet <mydomain>.comcast.net"; renew 2 2004/5/25 03:09:39; rebind 2 2004/5/25 14:05:02; expire 2 2004/5/25 17:05:02; } === /var/db/dhclient.leases === Note, that "renew" time is 05/25/2003, 03:09:39 ... then tcpdump catched bunch of UDP packets with "my" xid, timing randomly and originating from my dhclient (what the hell is that ? renewals, I guess ?): === tcpdump.txt === [ 04/24/2004 ] 01:54:18.081414 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 01:54:18.096871 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 02:00:21.007380 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 02:00:21.021850 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 02:13:49.010454 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 02:13:49.025109 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 02:15:13.003374 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 02:15:13.016276 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 03:04:29.007347 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 03:04:29.023318 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 03:43:06.144105 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 03:43:06.160207 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 07:50:04.011853 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 07:50:04.030484 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 09:41:06.003924 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 09:41:09.672413 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] [ ... ] [ 04/25/2004 ] 00:04:06.006259 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 00:04:06.019820 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 00:22:36.003374 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 00:22:36.015645 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 02:22:21.207862 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 02:22:21.220962 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] [ it supposed to send "renew" here, according to dhclient.leases, shown above, but looks like it's doing that all of the time ] 04:28:36.217769 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 04:28:36.231794 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 04:35:25.003623 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 04:35:25.017490 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] [...] 21:01:44.006698 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 21:01:44.019958 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 21:08:53.003275 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 21:08:57.002846 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 secs:4 C:<myhost>.comcast.net [|bootp] 21:09:00.511881 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 21:09:00.797786 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 21:10:12.003013 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 21:10:15.002711 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 secs:3 C:<myhost>.comcast.net [|bootp] 21:10:21.002722 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 secs:9 C:<myhost>.comcast.net [|bootp] 21:10:21.019382 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 21:45:28.003566 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 21:45:28.018021 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] 21:56:55.003778 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 21:56:55.023477 172.30.100.36.bootps > <myhost>.comcast.net.bootpc: xid:0x66d0a757 C:<myhost>.comcast.net Y:<myhost>.comcast.net S:172.30.100.36 [|bootp] === tcpdump.txt === === /var/log/security === [...] May 24 02:00:21 vladstar kernel: ipfw: 400 Accept UDP x.y.240.28:68 172.30.100.36:67 out via xl0 May 24 02:00:21 vladstar kernel: ipfw: 400 Accept UDP 172.30.100.36:67 x.y.240.28:68 in via xl0 May 24 02:02:03 vladstar kernel: ipfw: 400 Accept UDP 10.70.208.1:67 255.255.255.255:68 in via xl0 May 24 02:02:04 vladstar kernel: ipfw: 400 Accept UDP 10.70.208.1:67 255.255.255.255:68 in via xl0 May 24 02:11:36 vladstar kernel: ipfw: 400 Accept UDP 10.70.208.1:67 255.255.255.255:68 in via xl0 May 24 02:11:37 vladstar kernel: ipfw: 400 Accept UDP 10.70.208.1:67 255.255.255.255:68 in via xl0 May 24 02:13:49 vladstar kernel: ipfw: 400 Accept UDP x.y.240.28:68 172.30.100.36:67 out via xl0 May 24 02:13:49 vladstar kernel: ipfw: 400 Accept UDP 172.30.100.36:67 x.y.240.28:68 in via xl0 May 24 02:15:13 vladstar kernel: ipfw: 400 Accept UDP x.y.240.28:68 172.30.100.36:67 out via xl0 May 24 02:15:13 vladstar kernel: ipfw: 400 Accept UDP 172.30.100.36:67 x.y.240.28:68 in via xl0 May 24 02:18:37 vladstar kernel: ipfw: 400 Accept UDP 10.70.208.1:67 255.255.255.255:68 in via xl0 May 24 02:18:37 vladstar kernel: ipfw: 400 Accept UDP 10.70.208.1:67 255.255.255.255:68 in via xl0 May 24 02:21:48 vladstar kernel: ipfw: 400 Accept UDP 10.70.208.1:67 255.255.255.255:68 in via xl0 [...] === /var/log/security === ok, now is the most "interesting" and weird part: === tcpdump.txt === 22:41:56.003937 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 C:<myhost>.comcast.net [|bootp] 22:42:00.002402 <myhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x66d0a757 secs:4 C:<myhost>.comcast.net [|bootp] 22:42:10.002740 0.0.0.0.bootpc > 255.255.255.255.bootps: xid:0x3855a41d [|bootp] [tos 0x10] 22:42:14.001380 0.0.0.0.bootpc > 255.255.255.255.bootps: xid:0x3855a41d secs:4 [|bootp] [tos 0x10] 22:42:14.037267 10.70.208.1.bootps > <mynewhost>.comcast.net.bootpc: xid:0x3855a41d Y:<mynewhost>.comcast.net S:172.30.100.36 G:<mydefaultrouter>.comcast.net [|bootp] 22:42:14.040999 <myhost>.comcast.net.bootps > <mynewhost>.comcast.net.bootpc: xid:0x3855a41d Y:<mynewhost>.comcast.net S:172.30.100.36 G:<mydefaultrouter>.comcast.net ether 0:60:97:33:8c:e5 [|bootp] 22:42:15.002885 0.0.0.0.bootpc > 255.255.255.255.bootps: xid:0x3855a41d secs:4 [|bootp] [tos 0x10] 22:42:15.021251 10.70.208.1.bootps > <mynewhost>.comcast.net.bootpc: xid:0x3855a41d Y:<mynewhost>.comcast.net S:172.30.100.36 G:<mydefaultrouter>.comcast.net [|bootp] 22:42:15.024686 <myhost>.comcast.net.bootps > <mynewhost>.comcast.net.bootpc: xid:0x3855a41d Y:<mynewhost>.comcast.net S:172.30.100.36 G:<mydefaultrouter>.comcast.net ether 0:60:97:33:8c:e5 [|bootp] 22:42:15.694544 10.70.208.1.bootps > <myhost>.comcast.net.bootpc: C:<myhost>.comcast.net G:<mydefaultrouter>.comcast.net ether Broadcast [|bootp] 22:42:31.003569 <mynewhost>.comcast.net.bootpc > 172.30.100.36.bootps: xid:0x3855a41d C:<mynewhost>.comcast.net [|bootp] 22:42:31.016474 172.30.100.36.bootps > <mynewhost>.comcast.net.bootpc: xid:0x3855a41d C:<mynewhost>.comcast.net Y:<mynewhost>.comcast.net S:172.30.100.36 [|bootp] === tcpdump.txt === === /var/log/messages === May 25 22:42:16 vladstar dhclient: New IP Address (xl0): x.y.244.208 May 25 22:42:16 vladstar dhclient: New Subnet Mask (xl0): 255.255.255.0 May 25 22:42:16 vladstar dhclient: New Broadcast Address (xl0): x.y.244.255 May 25 22:42:16 vladstar dhclient: New Routers: x.y.244.1 === /var/log/messages === === /var/db/dhclient.leases === lease { interface "xl0"; fixed-address x.y.240.28; filename "mdcm245_v1_silver_c01"; option subnet-mask 255.255.252.0; option routers x.y.240.1; option dhcp-lease-time 86400; option dhcp-message-type 5; option dhcp-server-identifier 172.30.100.36; option domain-name-servers 127.0.0.1,x.y.0.6,x.z.96.16,x.y.0.12,x.z.96.15; option domain-name "homenet <mydomain>.comcast.net"; renew 3 2004/5/26 12:15:24; rebind 3 2004/5/26 22:56:55; expire 4 2004/5/27 01:56:55; } lease { interface "xl0"; fixed-address x.y.244.208; filename "mdcm245_v1_silver_c01"; option subnet-mask 255.255.255.0; option routers x.y.244.1; option dhcp-lease-time 86400; option dhcp-message-type 5; option dhcp-server-identifier 172.30.100.36; option domain-name-servers 127.0.0.1,x.y.0.6,x.z.96.16,x.y.0.12,x.z.96.15; option domain-name "homenet "; renew 3 2004/5/26 13:18:11; rebind 3 2004/5/26 23:42:31; expire 4 2004/5/27 02:42:31; } === dhclient.leases === If you pay attention on dhclient.leases, "renew" date for old x.y.240.28 IP address is already set to 2004/5/26 12:15:24. So, why the hell has it dropped existing and requested new address ??? Based on last 2 non-responded packets within 4-sec interval ? It doesn't look normal for me... P.S. This dhclient, that I played above, was compiled from the latest CVSUP. Standard dhclients from 5.2.1-RELEASE and previously installed 5.0-RELEASE had shown the same behavior. Sincerely yours, Vladislav Staroselskiy.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?012801c4434e$172e0ae0$1baca18d>