RE: IPV4LL and EXPIRE
David Hauck
Fri Oct 17 23:02:47 2014
Hi Roy,
I wonder if some of this behaviour is a consequence of running in a multi-homed environment (note my use of testing this 'eth1'). I have an initial interface that's defined statically and after taking a quick look at the code I'm wondering whether there's some mixup related to detecting valid IPV4LL addresses (both after CARRIER and EXPIRE)? For example, the node's ARP table includes *all* the IPV4LL addresses ever issued during the uptime of the node:
Address HWtype HWaddress Flags Mask Iface
169.254.6.164 ether 00:0b:ab:36:1c:fc C eth0
169.254.137.181 ether 00:0b:ab:36:1c:fc C eth0
169.254.85.96 ether 00:0b:ab:36:1c:fc C eth0
169.254.239.209 ether 00:0b:ab:36:1c:fc C eth0
169.254.141.93 ether 00:0b:ab:36:1c:fc C eth0
169.254.102.255 ether 00:0b:ab:36:1c:fc C eth0
169.254.91.215 ether 00:0b:ab:36:1c:fc C eth0
169.254.213.163 ether 00:0b:ab:36:1c:fc C eth0
169.254.213.103 ether 00:0b:ab:36:1c:fc C eth0
169.254.178.40 ether 00:0b:ab:36:1c:fc C eth0
169.254.158.92 ether 00:0b:ab:36:1c:fc C eth0
169.254.250.88 ether 00:0b:ab:36:1c:fc C eth0
169.254.179.113 ether 00:0b:ab:36:1c:fc C eth0
169.254.242.1 ether 00:0b:ab:36:1c:fc C eth0
169.254.200.24 ether 00:0b:ab:36:1c:fc C eth0
169.254.137.153 ether 00:0b:ab:36:1c:fc C eth0
169.254.12.151 ether 00:0b:ab:36:1c:fc C eth0
169.254.99.154 ether 00:0b:ab:36:1c:fc C eth0
169.254.156.90 ether 00:0b:ab:36:1c:fc C eth0
169.254.197.37 ether 00:0b:ab:36:1c:fc C eth0
169.254.141.211 ether 00:0b:ab:36:1c:fc C eth0
169.254.118.176 ether 00:0b:ab:36:1c:fc C eth0
169.254.40.191 ether 00:0b:ab:36:1c:fc C eth0
dhdell.nacc.netacquire. ether 18:03:73:e2:3e:c7 C eth0
169.254.252.49 ether 00:0b:ab:36:1c:fc C eth0
169.254.213.135 ether 00:0b:ab:36:1c:fc C eth0
169.254.141.75 ether 00:0b:ab:36:1c:fc C eth0
169.254.224.247 ether 00:0b:ab:36:1c:fc C eth0
169.254.159.116 ether 00:0b:ab:36:1c:fc C eth0
169.254.103.7 ether 00:0b:ab:36:1c:fc C eth0
169.254.100.217 ether 00:0b:ab:36:1c:fc C eth0
169.254.218.127 ether 00:0b:ab:36:1c:fc C eth0
169.254.7.207 ether 00:0b:ab:36:1c:fc C eth0
169.254.223.197 ether 00:0b:ab:36:1c:fc C eth0
169.254.246.74 ether 00:0b:ab:36:1c:fc C eth0
169.254.127.124 ether 00:0b:ab:36:1c:fc C eth0
169.254.98.75 ether 00:0b:ab:36:1c:fc C eth0
169.254.210.143 ether 00:0b:ab:36:1c:fc C eth0
169.254.24.54 ether 00:0b:ab:36:1c:fc C eth0
169.254.184.234 ether 00:0b:ab:36:1c:fc C eth0
169.254.140.128 ether 00:0b:ab:36:1c:fc C eth0
naccserver1.nacc.netacq ether b8:ac:6f:97:55:be C eth0
test ether 00:0b:ab:36:1c:fc C eth0
169.254.252.47 ether 00:0b:ab:36:1c:fc C eth0
169.254.46.54 ether 00:0b:ab:36:1c:fc C eth0
169.254.173.190 ether 00:0b:ab:36:1c:fc C eth0
169.254.30.240 ether 00:0b:ab:36:1c:fc C eth0
169.254.95.73 ether 00:0b:ab:36:1c:fc C eth0
205.159.216.130 ether 74:44:01:d5:26:06 C eth0
169.254.129.156 ether 00:0b:ab:36:1c:fc C eth0
169.254.25.129 ether 00:0b:ab:36:1c:fc C eth0
169.254.52.241 ether 00:0b:ab:36:1c:fc C eth0
169.254.42.114 ether 00:0b:ab:36:1c:fc C eth0
169.254.91.128 ether 00:0b:ab:36:1c:fc C eth0
169.254.155.165 ether 00:0b:ab:36:1c:fc C eth0
169.254.196.42 ether 00:0b:ab:36:1c:fc C eth0
169.254.129.140 ether 00:0b:ab:36:1c:fc C eth0
169.254.84.9 ether 00:0b:ab:36:1c:fc C eth0
169.254.23.202 ether 00:0b:ab:36:1c:fc C eth0
169.254.124.132 ether 00:0b:ab:36:1c:fc C eth0
169.254.14.64 ether 00:0b:ab:36:1c:fc C eth0
169.254.131.4 ether 00:0b:ab:36:1c:fc C eth0
169.254.31.191 ether 00:0b:ab:36:1c:fc C eth0
169.254.142.131 ether 00:0b:ab:36:1c:fc C eth0
169.254.189.82 ether 00:0b:ab:36:1c:fc C eth0
169.254.85.169 ether 00:0b:ab:36:1c:fc C eth0
169.254.29.133 ether 00:0b:ab:36:1c:fc C eth0
169.254.115.246 ether 00:0b:ab:36:1c:fc C eth0
169.254.218.133 ether 00:0b:ab:36:1c:fc C eth0
169.254.253.103 ether 00:0b:ab:36:1c:fc C eth0
169.254.182.140 ether 00:0b:ab:36:1c:fc C eth0
169.254.39.105 ether 00:0b:ab:36:1c:fc C eth0
169.254.170.69 ether 00:0b:ab:36:1c:fc C eth0
169.254.17.98 ether 00:0b:ab:36:1c:fc C eth0
169.254.183.77 ether 00:0b:ab:36:1c:fc C eth0
169.254.23.60 ether 00:0b:ab:36:1c:fc C eth0
169.254.32.3 ether 00:0b:ab:36:1c:fc C eth0
169.254.93.109 ether 00:0b:ab:36:1c:fc C eth0
169.254.198.140 ether 00:0b:ab:36:1c:fc C eth0
169.254.17.77 ether 00:0b:ab:36:1c:fc C eth0
169.254.219.46 ether 00:0b:ab:36:1c:fc C eth0
169.254.248.78 ether 00:0b:ab:36:1c:fc C eth0
169.254.50.206 ether 00:0b:ab:36:1c:fc C eth0
169.254.188.25 ether 00:0b:ab:36:1c:fc C eth0
169.254.40.30 ether 00:0b:ab:36:1c:fc C eth0
169.254.80.209 ether 00:0b:ab:36:1c:fc C eth0
169.254.82.89 ether 00:0b:ab:36:1c:fc C eth0
205.159.216.145 ether 90:b1:1c:5e:80:bb C eth0
169.254.37.180 ether 00:0b:ab:36:1c:fc C eth0
169.254.63.138 ether 00:0b:ab:36:1c:fc C eth0
169.254.35.255 ether 00:0b:ab:36:1c:fc C eth0
169.254.236.137 ether 00:0b:ab:36:1c:fc C eth0
169.254.5.171 ether 00:0b:ab:36:1c:fc C eth0
naccserver1.nacc.netacq ether b8:ac:6f:97:55:be C eth1
169.254.44.140 ether 00:0b:ab:36:1c:fc C eth0
169.254.129.88 ether 00:0b:ab:36:1c:fc C eth0
169.254.23.183 ether 00:0b:ab:36:1c:fc C eth0
169.254.82.160 ether 00:0b:ab:36:1c:fc C eth0
169.254.141.66 ether 00:0b:ab:36:1c:fc C eth0
169.254.99.210 ether 00:0b:ab:36:1c:fc C eth0
169.254.214.134 ether 00:0b:ab:36:1c:fc C eth0
169.254.93.134 ether 00:0b:ab:36:1c:fc C eth0
169.254.143.66 ether 00:0b:ab:36:1c:fc C eth0
169.254.49.147 ether 00:0b:ab:36:1c:fc C eth0
169.254.202.127 ether 00:0b:ab:36:1c:fc C eth0
169.254.116.117 ether 00:0b:ab:36:1c:fc C eth0
169.254.84.240 ether 00:0b:ab:36:1c:fc C eth0
So the uniqueness test is likely failing. But this is only because the previous IPV4LL address (prior to losing CARRIER) is somehow being re-used after CARRIER is re-established. So there may be two problems here: 1) for some reason not proceeding to a normal DHCP exchange after an IPV4LL state loses CARRIER and then regains CARRIER, and 2) IPV4LL collisions on a multi-homed configuration?
Anyways, just forwarding along additional information. There's no rush to respond on any of this - we can pick things up at your leisure next week.
Thanks,
-David
On Friday, October 17, 2014 2:58 PM, David Hauck wrote:
> On Friday, October 17, 2014 2:52 PM, David Hauck wrote:
>> On Friday, October 17, 2014 2:05 PM, David Hauck wrote:
>>> On Friday, October 17, 2014 2:00 PM, Roy Marples wrote:
>>>> On 2014-10-17 16:56, David Hauck wrote:
>>>>> On Friday, October 17, 2014 6:56 AM, Roy Marples wrote:
>>>>>> On 17/10/2014 14:25, David Hauck wrote:
>>>>>>>> I don't see this problem with dhcpcd-6.5.0 (well, the latest trunk).
>>>>>>>> There was a problem, although unrelated, which resulted in
>>>>>>>> this patch
>>>>>>>>
>>>>>>>> http://roy.marples.name/projects/dhcpcd/ci/4c1f2f8a298ad244f8c73
>>>>>>>> 9 7 1 0b a e46088ea7efd6?sbs=0 But that patch means nothing for
>>>>>>>> 6.1.0.
>>>>>>>>
>>>>>>>> So, can you test 6.5.0 with that patch please?
>>>>>>>
>>>>>>> Sure, I'll test either 6.5.0 of 6.1.0 with the patch, but may
>>>>>>> not get to this
>>>>>> before the end of the day.
>>>>>
>>>>> I did a quick test of this (essentially just a rebuild of 'dhcpcd'
>>>>> v6.5.0 and deploy to the target - I didn't deploy the hooks and
>>>>> this seems OK since the changes there seem to be irrelevant to my
>>>>> configuration) and I'm seeing the same issue.
>>>>>
>>>>> Here's my configuration: hostname option rapid_commit option
>>>>> domain_name_servers, domain_name, domain_search, host_name option
>>>>> classless_static_routes option ntp_servers require
>>>>> dhcp_server_identifier nohook lookup-hostname timeout 20 ipv4only
>>>>> vendor 01,"0"
>>>>>
>>>>> Any ideas for what else to try?
>>>>
>>>> Here's my syslog capture using your config on one interface.
>>>>
>>>> Oct 17 21:42:26 [dhcpcd] version 6.5.0 starting Oct 17 21:42:27
>>>> [dhcpcd] enp3s0: soliciting a DHCP lease Oct 17 21:42:46 [dhcpcd]
>>>> timed out Oct 17 21:42:46 [dhcpcd] allowing 8 seconds for IPv4LL
>>>> timeout Oct
>>>> 17 21:42:47 [dhcpcd] enp3s0: probing for an IPv4LL address Oct 17
>>>> 21:42:52 [dhcpcd] enp3s0: using IPv4LL address 169.254.102.37 Oct
>>>> 17
>>>> 21:42:52 [dhcpcd] enp3s0: adding route to 169.254.0.0/16 Oct 17
>>>> 21:42:52 [dhcpcd] forked to background, child pid 8646 Oct 17
>>>> 21:43:00 [dhcpcd] enp3s0: carrier lost Oct 17 21:43:00 [dhcpcd]
>>>> enp3s0: deleting route to 169.254.0.0/16 Oct 17 21:43:07 [dhcpcd]
>>>> enp3s0: carrier acquired Oct 17 21:43:13 [dhcpcd] enp3s0: using
>>>> IPv4LL address
>>>> 169.254.102.37 Oct 17 21:43:13 [dhcpcd] enp3s0: adding route to
>>>> 169.254.0.0/16 Oct 17 21:43:17 [dhcpcd] enp3s0: soliciting a DHCP
>>>> lease Oct 17 21:43:17 [dhcpcd] enp3s0: offered 10.73.2.30 from
>>>> 10.73.1.1 `uberserver.marples.name' Oct 17 21:43:22 [dhcpcd] enp3s0:
>>>> leased
>>>> 10.73.2.30 for 3600 seconds Oct 17 21:43:22 [dhcpcd] enp3s0:
>>>> adding route to 10.73.2.0/24 Oct 17 21:43:22 [dhcpcd] enp3s0:
>>>> adding default route via 10.73.2.1 Oct 17 21:43:22 [dhcpcd] enp3s0:
>>>> deleting route to
>>>> 169.254.0.0/16
>>>>
>>>> As you can see it works fine.
>>>
>>> Weird, huh...
>>>
>>>> But my version is beyond 6.5.0. However, as I cannot replicate your
>>>> issue with it I'll release 6.5.1 tonight which hopefully you can
>>>> re-test with. Adding the debug option gives a lot more output, you
>>>> should use the same option when reporting back as it tells me a lot
>>>> more about the state of dhcpcd.
>>>
>>> Sure, thanks.
>>
>> I just tried v5.6.1 and it does behave differently (although not
>> like your result above). In the v6.5.1 case I don't see the constant
>> cycling between IPV4LL and EXPIRE states, but I also don't see the
>> expected transition to a new, valid
>> lease:
>>
>> 20141017 14:39:32.114 info daemon(dhcpcd):version 6.5.1 starting
>> 20141017 14:39:32.127 info daemon(dhcpcd):eth1: 60-netacquire:
>> received reason=PREINIT, beeppid=0, ip=, sn=, gw=, dns=, options=,
>> hn=
>> 20141017
>> 14:39:32.141 info daemon(dhcpcd):eth1: 60-netacquire: received
>> reason=NOCARRIER, beeppid=21387, ip=, sn=, gw=, dns=, options=, hn=
>> 20141017 14:39:32.216 info daemon(dhcpcd):eth1: waiting for carrier
>> 20141017 14:39:33.845 info daemon(dhcpcd):eth1: carrier acquired
>> 20141017 14:39:33.859 info daemon(dhcpcd):eth1: 60-netacquire:
>> received reason=CARRIER, beeppid=21387, ip=, sn=, gw=, dns=,
>> options=, hn=
>> 20141017 14:39:33.859 info daemon(dhcpcd):DUID
>> 00:01:00:01:1b:bd:fd:00:00:1b:21:0a:21:03 20141017 14:39:33.860 info
>> daemon(dhcpcd):eth1: IAID ab:36:1c:fc 20141017 14:39:34.330 info
>> daemon(dhcpcd):eth1: soliciting a DHCP lease 20141017 14:39:52.142
>> warning daemon(dhcpcd):allowing 9 seconds for IPv4LL timeout
>> 20141017
>> 14:39:54.332 info daemon(dhcpcd):eth1: probing for an IPv4LL address
>> 20141017 14:39:58.729 info daemon(dhcpcd):eth1: using IPv4LL address
>> 169.254.35.255 20141017 14:39:58.729 info daemon(dhcpcd):eth1:
>> adding route to 169.254.0.0/16 20141017 14:39:58.744 info daemon(dhcpcd):eth1:
>> 60-netacquire: received reason=IPV4LL, beeppid=21387,
>> ip=169.254.35.255, sn=255.255.0.0, gw=, dns=, options=, hn= 20141017
>> 14:39:58.750 info daemon(dhcpcd):forked to background, child pid
>> 21608
>> 20141017
>> 14:40:14.419 info daemon(dhcpcd):eth1: carrier lost 20141017
>> 14:40:14.432 info daemon(dhcpcd):eth1: 60-netacquire: received
>> reason=NOCARRIER, beeppid=0, ip=, sn=, gw=, dns=, options=, hn=
>> 20141017
>> 14:40:14.442 info daemon(dhcpcd):eth1: deleting route to
>> 169.254.0.0/16
>> 20141017 14:40:14.456 info daemon(dhcpcd):eth1: 60-netacquire:
>> received reason=EXPIRE, beeppid=21718, ip=, sn=, gw=, dns=,
>> options=, hn=
>> 20141017 14:40:23.697 info daemon(dhcpcd):eth1: carrier acquired
>> 20141017 14:40:23.711 info daemon(dhcpcd):eth1: 60-netacquire:
>> received reason=CARRIER, beeppid=21718, ip=, sn=, gw=, dns=,
>> options=, hn=
>> 20141017 14:40:23.711 info daemon(dhcpcd):eth1: IAID ab:36:1c:fc
>> 20141017 14:40:29.401 info daemon(dhcpcd):eth1: using IPv4LL address
>> 169.254.35.255 20141017 14:40:29.401 info daemon(dhcpcd):eth1:
>> adding route to 169.254.0.0/16 20141017 14:40:29.416 info daemon(dhcpcd):eth1:
>> 60-netacquire: received reason=IPV4LL, beeppid=21718,
>> ip=169.254.35.255, sn=255.255.0.0, gw=, dns=, options=, hn= 20141017
>> 14:40:31.425 warning
>> daemon(dhcpcd):eth1: IPv4LL 10 second defence failed 20141017
>> 14:40:31.435 info daemon(dhcpcd):eth1: deleting route to
>> 169.254.0.0/16
>> 20141017 14:40:31.447 info daemon(dhcpcd):eth1: 60-netacquire:
>> received reason=EXPIRE, beeppid=0, ip=, sn=, gw=, dns=, options=,
>> hn=
>> 20141017
>> 14:40:32.449 info daemon(dhcpcd):eth1: probing for an IPv4LL address
>> 20141017 14:40:37.593 info daemon(dhcpcd):eth1: 60-netacquire:
>> received reason=EXPIRE, beeppid=21879, ip=, sn=, gw=, dns=,
>> options=, hn=
>>
>> It's now 10mins past the last timestamp above, so I'm not seeing any
>> further transitions/activity with dhcpcd in the log.
>>
>> I'm using 'if{up|down} eth1' to bring the interface up and down -
>> i.e., as
>> follows:
>>
>> 1. ifdown eth1
>> 2. attach C1
>> 3. ifup eth1
>> 4. remove C1
>> 5. attach C2
>> 6. review logs
>
> One quick additional note: here's what I see after step 6 above and
> after the following step:
>
> 7. ifdown eth1
> 8. ifup eth1
>
> 20141017 14:53:21.231 info daemon(dhcpcd):sending signal ARLM to pid
> 21608 20141017 14:53:21.231 info daemon(dhcpcd):received signal ALRM
> from PID 26807, releasing 20141017 14:53:21.231 info
> daemon(dhcpcd):eth1: removing interface 20141017 14:53:21.231 info
> daemon(dhcpcd):waiting for pid 21608 to exit 20141017 14:53:21.245 info
> daemon(dhcpcd):eth1: 60-netacquire: received reason=STOP, beeppid=21879,
> ip=, sn=, gw=, dns=, options=, hn= 20141017 14:53:21.262 info
> daemon(dhcpcd):eth1: 60-netacquire: received reason=STOPPED, beeppid=0,
> ip=, sn=, gw=, dns=, options=, hn= 20141017 14:53:21.268 info
> daemon(dhcpcd):exited 20141017 14:54:50.327 info daemon(dhcpcd):version
> 6.5.1 starting 20141017 14:54:50.340 info daemon(dhcpcd):eth1:
> 60-netacquire: received reason=PREINIT, beeppid=0, ip=, sn=, gw=, dns=,
> options=, hn= 20141017 14:54:50.355 info daemon(dhcpcd):eth1:
> 60-netacquire: received reason=NOCARRIER, beeppid=27393, ip=, sn=, gw=,
> dns=, options=, hn= 20141017 14:54:50.431 info daemon(dhcpcd):eth1:
> waiting for carrier 20141017 14:54:53.476 info daemon(dhcpcd):eth1:
> carrier acquired 20141017 14:54:53.490 info daemon(dhcpcd):eth1:
> 60-netacquire: received reason=CARRIER, beeppid=27393, ip=, sn=, gw=,
> dns=, options=, hn= 20141017 14:54:53.491 info daemon(dhcpcd):DUID
> 00:01:00:01:1b:bd:fd:00:00:1b:21:0a:21:03 20141017 14:54:53.491 info
> daemon(dhcpcd):eth1: IAID ab:36:1c:fc 20141017 14:54:53.580 info
> daemon(dhcpcd):eth1: soliciting a DHCP lease 20141017 14:54:58.556 info
> daemon(dhcpcd):eth1: offered 205.159.216.180 from 205.159.216.146
> 20141017 14:55:03.416 info daemon(dhcpcd):eth1: leased 205.159.216.180
> for 28800 seconds 20141017 14:55:03.416 info daemon(dhcpcd):eth1: adding
> route to 205.159.216.128/25 20141017 14:55:03.416 info
> daemon(dhcpcd):eth1: adding default route via 205.159.216.130 20141017
> 14:55:03.438 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=BOUND, beeppid=27393, ip=205.159.216.180, sn=255.255.255.128,
> gw=205.159.216.130, dns=205.159.216.146 205.159.216.73 172.20.0.3,
> options=, hn= 20141017 14:55:03.445 info daemon(dhcpcd):forked to
> background, child pid 27535
>
> This just demonstrates that, with C2 still connected, a full down/up
> sequence does properly result in a new, valid lease.
>
>> I configured v6.5.1 without --disable-debug. I'm thinking you were
>> referring to something else when mentioned adding the "debug option".
>> What did you mean by this exactly ;)?
>>
>> Thanks,
>> -David
>>
>>> -David
>>>
>>>> Thanks
>>>>
>>>> Roy
Archive administrator: postmaster@marples.name