dhcpcd-discuss

Thanks for the quick response Roy,

On 10 June 2018 at 17:59, Roy Marples <roy@xxxxxxxxxxxx> wrote:
> Hi Michael
>
>
> On 10/06/2018 12:05, Michael van der Westhuizen wrote:
>>
>> I've recently run into what I suspect is a bug in dhcpcd (we're running
>> 6.11.3).
>>
>> For context, I have a large number of devices that run 24/7 and get
>> addressing via DHCPv6. SLAAC is also available on these network
>> segments.
>>
>> The logs suggest that from time to time, the renew and rebind periods
>> are incorrectly calculated from the old values for those variables
>> rather than being based on the preferred lifetime of the lease as sent
>> by the server.  I've confirmed with our network team that they do not
>> try to set any renew or rebind intervals in the lease delivered to the
>> client, so this ought to work off the preferred lifetime (as far as I
>> know).
>>
>> Here's a set of logs showing this problem.
>>
>> 2018-05-25T17:25:06.248579-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::dab1:2200:c97c:69b4
>> 2018-05-25T17:25:06.248684-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-05-25T17:25:06.248988-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 40499, rebind in 64799, expire in 178199 seconds
>> 2018-05-26T04:40:05.306547-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::dab1:2200:c97c:69b4
>> 2018-05-26T04:40:05.306657-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-05-26T04:40:05.306913-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 40499, rebind in 64799, expire in 259200 seconds
>> 2018-05-26T15:55:04.363003-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::dab1:2200:c97c:69b4
>> 2018-05-26T15:55:04.363114-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-05-26T15:55:04.363386-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 20250, rebind in 32400, expire in 218701 seconds
>> 2018-05-26T21:32:34.507763-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::dab1:2200:c97c:69b4
>> 2018-05-26T21:32:34.507946-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-05-26T21:32:34.508213-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 20250, rebind in 32400, expire in 198451 seconds
>> 2018-05-27T03:10:04.610879-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::dab1:2200:c97c:69b4
>> 2018-05-27T03:10:04.610994-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-05-27T03:10:04.611253-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 20250, rebind in 32400, expire in 178201 seconds
>> 2018-05-27T08:47:34.710488-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::dab1:2200:c97c:69b4
>> 2018-05-27T08:47:34.710597-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-05-27T08:47:34.710927-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 20250, rebind in 32400, expire in 259200 seconds
>> 2018-05-27T14:25:04.810482-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::dab1:2200:c97c:69b4
>> 2018-05-27T14:25:04.810588-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-05-27T14:25:04.810901-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 10125, rebind in 16200, expire in 238950 seconds
>>
>> This continues until we get to the point of DDoSing the DHCP infra:
>>
>> 2018-06-08T12:34:27.703186-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::200:5eff:fe00:201
>> 2018-06-08T12:34:27.703302-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::70d/128
>> 2018-06-08T12:34:27.703563-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 5, rebind in 8, expire in 214678 seconds
>> 2018-06-08T12:34:35.707230-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> failed to renew DHCPv6, rebinding
>> 2018-06-08T12:34:35.749436-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::200:5eff:fe00:201
>> 2018-06-08T12:34:35.749538-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> deleting address 2620:10d:c0a3:1305::70d/128
>> 2018-06-08T12:34:35.749985-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-06-08T12:34:35.750195-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 5, rebind in 8, expire in 209183 seconds
>> 2018-06-08T12:34:41.148555-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> REPLY6 received from fe80::200:5eff:fe00:201
>> 2018-06-08T12:34:41.148673-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> adding address 2620:10d:c0a3:1305::b0d/128
>> 2018-06-08T12:34:41.149037-07:00 2048869908700569 dhcpcd[2253]: eth0:
>> renew in 5, rebind in 8, expire in 209178 seconds
>>
>> Does this behaviour ring any bells?  Are there more logs I can gather
>> to help identify the problem?
>
>
> dhcpcd-6.11.4 fixed a lot of DHCP6 issues, including timing related ones.
> dhcpcd-6.11.5 is the last release from the -6 branch.
>
> No-one has reported any timing issues with either that or the -7 branch.
> Could you test the latest one of either please and let me know?

I'm preparing a dhcpcd-7.0.5b upgrade for our platform and will test
side-by-side with our existing 6.11.3 and report back to the list.

Michael

>
> Roy
>