dhcpcd-discuss

Hi,

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?

Thanks,
Michael