dhcpcd-discuss

Hi Remi

On 24/03/2019 09:35, Remi Locherer wrote:
> Hi,
>
> I'd like to configure multiple interfaces with a /64. All out of the
> assigned /48 I got from the ISP. This works initially. But after rebind
> dhcpcd does not configure all interfaces.
>
> Is there an error in my configuration?
>
> Versions:
> blau ~$ uname -a
> OpenBSD blau.home 6.5 GENERIC.MP#762 amd64

I currently have OpenBSD-6.4, I'll upgrade my VM, but I doubt that's the 
issue.

> blau ~$ dhcpcd --version
> dhcpcd 7.1.1
> Copyright (c) 2006-2019 Roy Marples
> Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH
> blau ~$ >
>
> /etc/dhcpcd.conf:
> ipv6only
> debug
> duid
> option rapid_commit
> require dhcp_server_identifier
> script /usr/bin/true
> noipv6rs
> allowinterfaces em1 em2 vlan2 vlan5
> interface em2
>          ia_pd 1 em1/1 vlan2/2 vlan5/5

Looks ok.
Any reason why you set the script to /usr/bin/true?
If you don't want a script to run, either of these should save some CPU
script /dev/null
script ""

> The log shows:
> 18:29:21 em1, vlan2, vlan5: add routes and addresses
> 18:59:22 em1, vlan2, vlan5: del routes and addresses
> 18:59:22 em1:               add route and address
> 19:29:23 em1:               del route and address
> 19:29:23 vlan2:             add route and address
> 19:59:24 vlan2:             del route and address
> 19:59:24 vlan5:             add route and address
> [..]
>
>
> The log also shows another issue:
> Renew does not work and dhcpcd needs to do a rebind. This is because the
> DHCPv6 server from my ISP does not answer renew requests sent using unicast.
> --> https://www.as13030.net/status.php#collapse_12863 : issues with PD

These isses look related, explained below.

> grep dhcpcd /var/log/daemon
> Mar 23 18:29:19 blau dhcpcd[72043]: DUID 00:01:00:01:20:e6:6a:2e:00:0d:b9:46:e8:b5
> Mar 23 18:29:19 blau dhcpcd[72043]: em1: IAID b9:46:e8:b5
> Mar 23 18:29:19 blau dhcpcd[72043]: em2: IAID b9:46:e8:b6
> Mar 23 18:29:19 blau dhcpcd[72043]: em2: IA type 25 IAID 00:00:00:01
> Mar 23 18:29:19 blau dhcpcd[72043]: em2: accepted reconfigure key
> Mar 23 18:29:19 blau dhcpcd[72043]: em2: rebinding prior DHCPv6 lease
> Mar 23 18:29:19 blau dhcpcd[72043]: vlan2: IAID ff:00:00:02
> Mar 23 18:29:19 blau dhcpcd[72043]: vlan5: IAID ff:00:00:05
> Mar 23 18:29:20 blau dhcpcd[72043]: em2: fe80::c671:feff:fef4:d0ff: DHCPv6 REPLY missing Prefix
> Mar 23 18:29:20 blau dhcpcd[72043]: em2: no useable IA found in lease
> Mar 23 18:29:20 blau dhcpcd[72043]: em2: soliciting a DHCPv6 lease
> Mar 23 18:29:21 blau dhcpcd[72043]: em2: ADV 2a02:168:69f1::/48 from fe80::c671:feff:fef4:d0ff
> Mar 23 18:29:21 blau dhcpcd[72043]: em2: accepted reconfigure key
> Mar 23 18:29:21 blau dhcpcd[72043]: em2: REPLY6 received from fe80::c671:feff:fef4:d0ff
> Mar 23 18:29:21 blau dhcpcd[72043]: em2: renew in 1200, rebind in 1800, expire in 86400 seconds
> Mar 23 18:29:21 blau dhcpcd[72043]: lo0: adding reject route to 2a02:168:69f1::/48 via ::1
> Mar 23 18:29:21 blau dhcpcd[72043]: em2: delegated prefix 2a02:168:69f1::/48
> Mar 23 18:29:21 blau dhcpcd[72043]: em1: adding address 2a02:168:69f1:1::1/64
> Mar 23 18:29:21 blau dhcpcd[72043]: vlan2: adding address 2a02:168:69f1:2::1/64
> Mar 23 18:29:21 blau dhcpcd[72043]: vlan5: adding address 2a02:168:69f1:5::1/64
> Mar 23 18:29:21 blau dhcpcd[72043]: em1: adding route to 2a02:168:69f1:1::/64
> Mar 23 18:29:21 blau dhcpcd[72043]: vlan2: adding route to 2a02:168:69f1:2::/64
> Mar 23 18:29:21 blau dhcpcd[72043]: vlan5: adding route to 2a02:168:69f1:5::/64
> Mar 23 18:29:21 blau dhcpcd[72043]: forked to background, child pid 56292

At this point everything is good.
Although debug info is missing.
Have you enabled in in syslogd.conf to this file?
If you don't want to, instruct dhcpcd to log to a file as well
logfile /var/log/dhcpcd.log
Then you get a lot more detail.

> Mar 23 18:59:21 blau dhcpcd[56292]: em2: failed to renew DHCPv6, rebinding

Without debug, my best guess is that the upstream server didn't reply.
We can't tell if dhcpcd unicast or not - the default is NOT to unless 
the server asked to be unicast to.

> Mar 23 18:59:22 blau dhcpcd[56292]: em2: fe80::c671:feff:fef4:d0ff: DHCPv6 REPLY missing Prefix
> Mar 23 18:59:22 blau dhcpcd[56292]: em2: no useable IA found in lease

So we got a rely to the rebind, but the IA we requested isn't in it.
It's probably blank.
So dhcpcd drops the lease and re-enters discover mode.

> Mar 23 18:59:22 blau dhcpcd[56292]: em1: deleting address 2a02:168:69f1:1::1/64
> Mar 23 18:59:22 blau dhcpcd[56292]: lo0: deleting reject route to 2a02:168:69f1::/48 via ::1
> Mar 23 18:59:22 blau dhcpcd[56292]: em1: deleting route to 2a02:168:69f1:1::/64
> Mar 23 18:59:22 blau dhcpcd[56292]: vlan2: deleting address 2a02:168:69f1:2::1/64
> Mar 23 18:59:22 blau dhcpcd[56292]: vlan2: deleting route to 2a02:168:69f1:2::/64
> Mar 23 18:59:22 blau dhcpcd[56292]: vlan5: deleting address 2a02:168:69f1:5::1/64
> Mar 23 18:59:22 blau dhcpcd[56292]: vlan5: deleting route to 2a02:168:69f1:5::/64
> Mar 23 18:59:22 blau dhcpcd[56292]: em2: soliciting a DHCPv6 lease
> Mar 23 18:59:22 blau dhcpcd[56292]: em2: ADV 2a02:168:69f1::/48 from fe80::c671:feff:fef4:d0ff
> Mar 23 18:59:22 blau dhcpcd[56292]: em2: accepted reconfigure key
> Mar 23 18:59:22 blau dhcpcd[56292]: lo0: adding reject route to 2a02:168:69f1::/48 via ::1
> Mar 23 18:59:22 blau dhcpcd[56292]: em1: adding address 2a02:168:69f1:1::1/64
> Mar 23 18:59:22 blau dhcpcd[56292]: em1: adding route to 2a02:168:69f1:1::/64

So far so good.

> Mar 23 19:29:22 blau dhcpcd[56292]: em2: failed to renew DHCPv6, rebinding

Here we go again :/

> Mar 23 19:29:23 blau dhcpcd[56292]: em2: fe80::c671:feff:fef4:d0ff: DHCPv6 REPLY missing Prefix
> Mar 23 19:29:23 blau dhcpcd[56292]: em2: no useable IA found in lease
> Mar 23 19:29:23 blau dhcpcd[56292]: lo0: deleting reject route to 2a02:168:69f1::/48 via ::1
> Mar 23 19:29:23 blau dhcpcd[56292]: em1: deleting address 2a02:168:69f1:1::1/64
> Mar 23 19:29:23 blau dhcpcd[56292]: em1: deleting route to 2a02:168:69f1:1::/64
> Mar 23 19:29:23 blau dhcpcd[56292]: em2: soliciting a DHCPv6 lease
> Mar 23 19:29:23 blau dhcpcd[56292]: em2: ADV 2a02:168:69f1::/48 from fe80::c671:feff:fef4:d0ff
> Mar 23 19:29:23 blau dhcpcd[56292]: em2: accepted reconfigure key
> Mar 23 19:29:23 blau dhcpcd[56292]: lo0: adding reject route to 2a02:168:69f1::/48 via ::1
> Mar 23 19:29:23 blau dhcpcd[56292]: vlan2: adding address 2a02:168:69f1:2::1/64
> Mar 23 19:29:23 blau dhcpcd[56292]: vlan2: adding route to 2a02:168:69f1:2::/64

em1 and vlan5 are missing. Why?
Maybe dhcpcd debug can tell us.
Carrier is probably down.

> Mar 23 19:59:23 blau dhcpcd[56292]: em2: failed to renew DHCPv6, rebinding
> Mar 23 19:59:24 blau dhcpcd[56292]: em2: fe80::c671:feff:fef4:d0ff: DHCPv6 REPLY missing Prefix
> Mar 23 19:59:24 blau dhcpcd[56292]: em2: no useable IA found in lease
> Mar 23 19:59:24 blau dhcpcd[56292]: lo0: deleting reject route to 2a02:168:69f1::/48 via ::1
> Mar 23 19:59:24 blau dhcpcd[56292]: vlan2: deleting address 2a02:168:69f1:2::1/64
> Mar 23 19:59:24 blau dhcpcd[56292]: vlan2: deleting route to 2a02:168:69f1:2::/64
> Mar 23 19:59:24 blau dhcpcd[56292]: em2: soliciting a DHCPv6 lease
> Mar 23 19:59:24 blau dhcpcd[56292]: em2: ADV 2a02:168:69f1::/48 from fe80::c671:feff:fef4:d0ff
> Mar 23 19:59:25 blau dhcpcd[56292]: em2: accepted reconfigure key
> Mar 23 19:59:25 blau dhcpcd[56292]: lo0: adding reject route to 2a02:168:69f1::/48 via ::1
> Mar 23 19:59:25 blau dhcpcd[56292]: vlan5: adding address 2a02:168:69f1:5::1/64
> Mar 23 19:59:25 blau dhcpcd[56292]: vlan5: adding route to 2a02:168:69f1:5::/64

Now em1 and vlan2 are missing?

And the log proceeds as such.

So we have three issues
1) Work out why renew fails
2) Work out why the rebind lease is not useable
3) Work out why not all interfaces are being delegated to

To process with this, I think we'll need full dhcpcd debug logs to fix 
issue 3, and wireshark dhcpv6 traces to fix issues 1 and 2.

Roy