Re: pppoe, dhcpcd v6 and renew

[Roy Marples <roy%marples.name@localhost>]

On 14/11/2017 20:53, Manuel Bouyer wrote:
> On Tue, Nov 14, 2017 at 08:42:46PM +0000, Roy Marples wrote:
> > Could you add the debug directive to /etc/dhcpcd.conf and get some logs
> > about what it claims it's doing please?
>
> Here are the logs:
> Nov 14 21:47:43 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to restart the connection
> Nov 14 21:47:43 chassiron dhcpcd[25688]: pppoe0: carrier lost
> Nov 14 21:48:48 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
> Nov 14 21:48:49 chassiron dhcpcd[25688]: pppoe0: carrier acquired
> Nov 14 21:48:49 chassiron dhcpcd[25688]: pppoe0: IAID 00:00:00:06
> Nov 14 21:48:49 chassiron dhcpcd[25688]: pppoe0: IAID 00:00:00:00
> Nov 14 21:48:51 chassiron dhcpcd[25688]: pppoe0: rebinding prior DHCPv6 lease
> Nov 14 21:49:01 chassiron dhcpcd[25688]: pppoe0: failed to rebind prior delegation
> Nov 14 21:49:01 chassiron dhcpcd[25688]: pppoe0: soliciting a DHCPv6 lease
> Nov 14 21:48:48 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
> Nov 14 21:49:02 chassiron dhcpcd[25688]: pppoe0: ADV 2001:41d0:fe9d:1100::/56 from fe80::230:88ff:fe04:63c9
> Nov 14 21:49:02 chassiron dhcpcd[25688]: pppoe0: REPLY6 received from fe80::230:88ff:fe04:63c9
> Nov 14 21:49:02 chassiron dhcpcd[25688]: pppoe0: renew in 43200, rebind in 69120, expire in 172800 seconds
> Nov 14 21:49:02 chassiron dhcpcd[25688]: pppoe0: delegated prefix 2001:41d0:fe9d:1100::/56
>
> and tcpdump:
> 21:49:02.584997 PPPoE  [ses 0x23de] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 advertise
> 21:49:02.599245 PPPoE  [ses 0x23de] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 reply
>
> I don't see more messages than in my previous post ?
> I just added
> debug
> in the global section

Something is wrong then. Here is sample output - I added -d as an 
argument for the same effect:

# dhcpcd -dB6
dhcpcd-7.0.0-rc3 starting
iwi0: disabling Kernel IPv6 auto link-local support
iwi0: disabling Kernel IPv6 RA support
bge0: executing `/libexec/dhcpcd-run-hooks' PREINIT
bge0: executing `/libexec/dhcpcd-run-hooks' NOCARRIER
iwi0: executing `/libexec/dhcpcd-run-hooks' PREINIT
iwi0: executing `/libexec/dhcpcd-run-hooks' CARRIER
DUID 00:01:00:01:21:42:d9:26:00:13:ce:fc:e1:c0
iwi0: IAID ce:fc:e1:c0
iwi0: IAID 00:00:00:02
iwi0: delaying IPv6 router solicitation for 0.3 seconds
iwi0: reading lease `/var/db/dhcpcd/iwi0-UberNET.lease6'
iwi0: ignoring unrequested IAID ce:fc:e1:c0
iwi0: no useable IA found in lease
iwi0: soliciting a DHCPv6 lease
iwi0: delaying SOLICIT6 (xid 0xfe735a), next in 0.4 seconds
bge0: waiting for carrier
iwi0: soliciting an IPv6 router
iwi0: sending Router Solicitation
iwi0: broadcasting SOLICIT6 (xid 0xfe735a), next in 0.9 seconds
iwi0: ADV fd73:7808:1015:1740::/60 from fe80::1
iwi0: broadcasting REQUEST6 (xid 0x9fb490), next in 1.0 seconds
iwi0: REPLY6 received from fe80::1
iwi0: renew in 37, rebind in 60, expire in 120 seconds
lo0: adding reject route to fd73:7808:1015:1740::/60 via ::1
iwi0: writing lease `/var/db/dhcpcd/iwi0-UberNET.lease6'
iwi0: delegated prefix fd73:7808:1015:1740::/60
bge0: has no carrier, cannot delegate addresses
iwi0: dhcp_envoption 39.0/1: Not supported
iwi0: executing `/libexec/dhcpcd-run-hooks' BOUND6
iwi0: sending Router Solicitation
iwi0: sending Router Solicitation
iwi0: Router Advertisement from fe80::1
iwi0: adding address fd73:7808:1015:0:87d0:2533:65b8:6a91/64
iwi0: pltime 120 seconds, vltime 180 seconds
iwi0: adding route to fd73:7808:1015::/64
iwi0: adding default route via fe80::1
iwi0: waiting for Router Advertisement DAD to complete
iwi0: Router Advertisement DAD completed
iwi0: executing `/libexec/dhcpcd-run-hooks' ROUTERADVERT
iwi0: carrier lost
iwi0: executing `/libexec/dhcpcd-run-hooks' NOCARRIER
iwi0: carrier acquired
iwi0: executing `/libexec/dhcpcd-run-hooks' CARRIER
iwi0: adding address fd73:7808:1015:0:87d0:2533:65b8:6a91/64
iwi0: pltime 0 seconds, vltime 3 seconds
iwi0: IAID ce:fc:e1:c0
iwi0: IAID 00:00:00:02
iwi0: delaying IPv6 router solicitation for 0.2 seconds
iwi0: delaying DHCPv6 soliciation for LL address
iwi0: soliciting an IPv6 router
iwi0: delaying Router Solicitation for LL address
iwi0: reading lease `/var/db/dhcpcd/iwi0-UberNET.lease6'
iwi0: rebinding prior DHCPv6 lease
iwi0: delaying REBIND6 (xid 0x55e5e0), next in 0.0 seconds
iwi0: sending Router Solicitation
iwi0: broadcasting REBIND6 (xid 0x55e5e0), next in 1.1 seconds
iwi0: REPLY6 received from fe80::1
iwi0: renew in 37, rebind in 60, expire in 120 seconds
iwi0: writing lease `/var/db/dhcpcd/iwi0-UberNET.lease6'
iwi0: delegated prefix fd73:7808:1015:1740::/60
bge0: has no carrier, cannot delegate addresses
iwi0: dhcp_envoption 39.0/1: Not supported
iwi0: dhcp_envoption 39.0/1: Not supported
iwi0: executing `/libexec/dhcpcd-run-hooks' REBIND6
iwi0: deleted route to fd73:7808:1015::/64
iwi0: deleted address fd73:7808:1015:0:87d0:2533:65b8:6a91/64
iwi0: sending Router Solicitation
iwi0: Router Advertisement from fe80::1
iwi0: adding address fd73:7808:1015:0:87d0:2533:65b8:6a91/64
iwi0: pltime 120 seconds, vltime 180 seconds
iwi0: adding route to fd73:7808:1015::/64
iwi0: executing `/libexec/dhcpcd-run-hooks' ROUTERADVERT
iwi0: broadcasting RENEW6 (xid 0xd2af4a), next in 10.1 seconds
iwi0: REPLY6 received from fe80::1
iwi0: renew in 37, rebind in 60, expire in 120 seconds
iwi0: writing lease `/var/db/dhcpcd/iwi0-UberNET.lease6'
iwi0: delegated prefix fd73:7808:1015:1740::/60
bge0: has no carrier, cannot delegate addresses
iwi0: dhcp_envoption 39.0/1: Not supported
iwi0: dhcp_envoption 39.0/1: Not supported
iwi0: executing `/libexec/dhcpcd-run-hooks' RENEW6

That's console output, but syslog should be similar.
Maybe you're not capturing LOG_DEBUG? Try using
logfile /var/log/dhcpcd.log
in dhcpcd.conf as an alternative.

Roy