dhcpcd-discuss

Hi Roy,

I am using dhcpcd-7.0.0. PFB log from the start. There dont seem to be
socket listening errors.
From code, it looks like when rebind timesout, the fail handling moves
state to the DH6S_BOUND state causing "DHCPv6 reply received but already
bound*.
DHCP client for v4 and v6 are running simultaneously.

# May 09 18:03:43 [9009]: dhcpcd-7.0.0 starting
May 09 18:03:43 [9009]: eth1: if_disable_autolinklocal: Operation not
supported
May 09 18:03:43 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up' PREINIT
May 09 18:03:43 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up' CARRIER
May 09 18:03:43 [9009]: DUID 00:01:00:01:24:66:f5:4c:54:39:68:16:d5:74
May 09 18:03:43 [9009]: eth1: IAID 68:16:d5:74
May 09 18:03:43 [9009]: eth1: IAID 00:00:00:01
May 09 18:03:43 [9009]: eth1: IAID 00:00:00:02
May 09 18:03:43 [9009]: eth1: delaying IPv6 router solicitation for 0.3
seconds
May 09 18:03:43 [9009]: eth1: reading lease
`/etc/config//dhcpcd-eth1.lease6'
May 09 18:03:43 [9009]: eth1: rebinding prior DHCPv6 lease
May 09 18:03:43 [9009]: eth1: delaying REBIND6 (xid 0xaf3c57), next in 0.7
seconds
May 09 18:03:43 [9009]: eth0: activating for delegation
May 09 18:03:43 [9009]: eth0: executing `/libexec/dhcpcd-run-hooks' PREINIT
May 09 18:03:43 [9009]: script_runreason: /libexec/dhcpcd-run-hooks:
WEXITSTATUS 127
May 09 18:03:43 [9009]: eth0: carrier acquired
May 09 18:03:43 [9009]: eth0: executing `/etc/conf/bin/dhcpcd-up' CARRIER
May 09 18:03:43 [9009]: eth0: IAID 68:16:d5:73
May 09 18:03:43 [9009]: eth1: delaying IPv4 for 0.1 seconds
May 09 18:03:43 [9009]: eth1: using ClientID 01:54:39:68:16:d5:74
May 09 18:03:43 [9009]: eth1: soliciting a DHCP lease
May 09 18:03:43 [9009]: eth1: sending DISCOVER (xid 0xb0e38e4c), next in
4.1 seconds
May 09 18:03:43 [9009]: eth1: soliciting an IPv6 router
May 09 18:03:43 [9009]: eth1: sending Router Solicitation
May 09 18:03:43 [9009]: eth1: Router Advertisement from
fe80::f899:b5ad:6686:f69e
May 09 18:03:43 [9009]: eth1: adding route to 2001:4201:0:50::/64
May 09 18:03:43 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up'
ROUTERADVERT
May 09 18:04:04 [9009]: eth1: broadcasting REBIND6 (xid 0xaf3c57), next in
1.0 seconds
May 09 18:04:04 [9009]: eth1: sending DISCOVER (xid 0xb0e38e4c), next in
8.2 seconds
May 09 18:04:04 [9009]: eth1: failed to rebind prior delegation
May 09 18:04:04 [9009]: eth1: adding address 2001:4201:0:50::104/128
May 09 18:04:04 [9009]: eth1: pltime 593802 seconds, vltime 2581002 seconds
May 09 18:04:04 [9009]: eth1: renew in 3398, rebind in 6998, expire in
2581002 seconds
May 09 18:04:04 [9009]: lo: adding reject route to 2001:4201:0:51:3000::/68
May 09 18:04:04 [9009]: eth1: delegated prefix 2001:4201:0:51:3000::/68
May 09 18:04:04 [9009]: eth0: adding address 2001:4201:0:51:30d0::1/76
May 09 18:04:04 [9009]: eth0: pltime 593802 seconds, vltime 2581002 seconds
May 09 18:04:04 [9009]: eth0: waiting for DHCPv6 DAD to complete
May 09 18:04:04 [9009]: eth0: adding route to 2001:4201:0:51:30d0::/76
May 09 18:04:04 [9009]: eth1: waiting for DHCPv6 DAD to complete
May 09 18:04:04 [9009]: eth1: DHCPv6 reply received but already bound
May 09 18:04:04 [9009]: eth1: deleted route to 2001:4201:0:50::/64
May 09 18:04:12 [9009]: eth1: DHCPv6 DAD completed
May 09 18:04:12 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up' TIMEOUT6
May 09 18:04:12 [9009]: eth0: DHCPv6 DAD completed
May 09 18:04:12 [9009]: eth0: executing `/etc/conf/bin/dhcpcd-up' DELEGATED6
May 09 18:04:34 [9009]: eth1: sending DISCOVER (xid 0xb0e38e4c), next in
15.8 seconds
May 09 18:04:34 [9009]: eth1: Router Advertisement from
fe80::f899:b5ad:6686:f69e
May 09 18:04:34 [9009]: eth1: adding route to 2001:4201:0:50::/64
May 09 18:04:34 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up'
ROUTERADVERT
May 09 18:04:34 [9009]: eth0: deleted route to 2001:4201:0:51:30d0::/76
May 09 18:04:34 [9009]: lo: deleted reject route to 2001:4201:0:51:3000::/68
May 09 18:04:42 [9009]: eth1: Router Advertisement from
fe80::f899:b5ad:6686:f69e
May 09 18:04:42 [9009]: lo: adding reject route to 2001:4201:0:51:3000::/68
May 09 18:04:42 [9009]: eth0: adding route to 2001:4201:0:51:30d0::/76
May 09 18:04:42 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up'
ROUTERADVERT
May 09 18:04:50 [9009]: eth1: sending DISCOVER (xid 0xb0e38e4c), next in
32.1 seconds
May 09 18:05:22 [9009]: eth1: sending DISCOVER (xid 0xb0e38e4c), next in
64.3 seconds
May 09 18:06:10 [9009]: eth1: Router Advertisement from
fe80::f899:b5ad:6686:f69e
May 09 18:06:10 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up'
ROUTERADVERT
May 09 18:06:26 [9009]: eth1: sending DISCOVER (xid 0xb0e38e4c), next in
63.3 seconds
May 09 18:06:36 [9009]: eth1: Router Advertisement from
fe80::f899:b5ad:6686:f69e
May 09 18:06:36 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up'
ROUTERADVERT
May 09 18:07:29 [9009]: eth1: sending DISCOVER (xid 0xb0e38e4c), next in
63.1 seconds
May 09 18:08:10 [9009]: eth1: Router Advertisement from
fe80::f899:b5ad:6686:f69e
May 09 18:08:10 [9009]: eth1: executing `/etc/conf/bin/dhcpcd-up'
ROUTERADVERT

Please let me know if you need other info.

Thanks for your help,
Roy

On Fri, May 10, 2019 at 12:34 AM Roy Marples <roy@xxxxxxxxxxxx> wrote:

> Hi Shweta
>
> On 09/05/2019 17:45, Shweta Kalyani wrote:
> > Hi Roy,
> >
> > I have a dhcpv6 client running which has got an IPv6 address from the
> > server.
>
> What dhcpcd version is this please?
>
> > On rebooting, dhcpcd is trying to rebind to the previously allocated
> > address.
> > In pcap, I see the rebind6 request with rebind6 response coming in
> > within the same second.
> > Dhcpcd however seems to be timing out on the rebind request ~ approx 25
> secs
> > Please see the following log:
> > May 09 15:57:10 [27685]: eth0: executing `/libexec/dhcpcd-run-hooks'
> PREINIT
> > May 09 15:57:10 [27685]: script_runreason: /libexec/dhcpcd-run-hooks:
> > WEXITSTATUS 127
> > May 09 15:57:10 [27685]: eth0: carrier acquired
> > May 09 15:57:10 [27685]: eth0: executing `/etc/conf/bin/dhcpcd-up'
> CARRIER
> > May 09 15:57:10 [27685]: eth0: IAID 68:16:d5:73
> > May 09 15:57:10 [27685]: eth1: delaying IPv4 for 0.3 seconds
> > May 09 15:57:11 [27685]: eth1: using ClientID 01:54:39:68:16:d5:74
> > May 09 15:57:11 [27685]: eth1: soliciting a DHCP lease
> > May 09 15:57:11 [27685]: eth1: sending DISCOVER (xid 0x8266886d), next
> > in 4.3 seconds
> > May 09 15:57:11 [27685]: eth1: soliciting an IPv6 router
> > May 09 15:57:11 [27685]: eth1: sending Router Solicitation
> > May 09 15:57:11 [27685]: eth1: broadcasting REBIND6 (xid 0x1ae134), next
> > in 1.0 seconds
> > May 09 15:57:12 [27685]: eth1: broadcasting REBIND6 (xid 0x1ae134), next
> > in 2.1 seconds
> > May 09 15:57:14 [27685]: eth1: Router Advertisement from
> > fe80::f899:b5ad:6686:f69e
> > May 09 15:57:14 [27685]: eth1: adding route to 2001:4201:0:50::/64
> > May 09 15:57:14 [27685]: eth1: executing `/etc/conf/bin/dhcpcd-up'
> > ROUTERADVERT
> > May 09 15:57:34 [27685]: eth1: broadcasting REBIND6 (xid 0x1ae134), next
> > in 4.2 seconds
> > May 09 15:57:34 [27685]: eth1: sending DISCOVER (xid 0x8266886d), next
> > in 7.4 seconds
> > *May 09 15:57:34 [27685]: eth1: failed to rebind prior delegation*
> > May 09 15:57:34 [27685]: eth1: adding address 2001:4201:0:50::104/128
> > May 09 15:57:34 [27685]: eth1: pltime 601393 seconds, vltime 2588593
> seconds
> > May 09 15:57:34 [27685]: eth1: renew in 1276, rebind in 4876, expire in
> > 2588593 seconds
> > May 09 15:57:34 [27685]: lo: adding reject route to
> 2001:4201:0:51:3000::/68
> > May 09 15:57:34 [27685]: eth1: delegated prefix 2001:4201:0:51:3000::/68
> > May 09 15:57:34 [27685]: eth0: adding address 2001:4201:0:51:30d0::1/76
> > May 09 15:57:34 [27685]: eth0: pltime 601393 seconds, vltime 2588593
> seconds
> > May 09 15:57:34 [27685]: eth0: waiting for DHCPv6 DAD to complete
> > May 09 15:57:34 [27685]: eth0: adding route to 2001:4201:0:51:30d0::/76
> > May 09 15:57:34 [27685]: eth1: waiting for DHCPv6 DAD to complete
> > *May 09 15:57:34 [27685]: eth1: DHCPv6 reply received but already bound*
> >
> > Due to the above, I am not able to get the REBIND6 event in the hook
> script.
> > Could you please let me know what could be going wrong.
>
> The full log from dhcpcd starting would be nice.
> Specifically I am interested in any errors listening to sockets.
> Also, are any other DHCP daemons running?
>
> Roy
>