dhcpcd-discuss

Hi Roy,

This is dhcpv6 client configuration file for your reference.
# cat dhcpcd.conf
hostname
clientid
require dhcp_server_identifier
option interface_mtu
option broadcast_address
option dhcp6_sol_max_rt
option dhcp6_name_servers
option ntp_servers
noipv4ll
lastlease
ipv6ra_noautoconf
noipv6rs
allowinterfaces eth1
interface eth1
ipv6rs
ia_na 1
ia_pd 2 eth0

Thanks,
Shweta
On Fri, May 10, 2019 at 8:23 AM Shweta Kalyani <shwetakalyani@xxxxxxxxx>
wrote:

> 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
>>
>