Re: pppoe, dhcpcd v6 and renew

[Manuel Bouyer <bouyer%antioche.eu.org@localhost>]

On Wed, Nov 15, 2017 at 09:52:18AM +0000, Roy Marples wrote:
> [...]
> 
> 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.

Indeed I don't log LOG_DEBUG.
I added a logfile directve, here's the output

Nov 15 11:28:55 [5139]: pppoe0: carrier lost
Nov 15 11:28:55 [5139]: pppoe0: executing `/libexec/dhcpcd-run-hooks' NOCARRIER
Nov 15 11:30:00 [5139]: pppoe0: carrier acquired
Nov 15 11:30:00 [5139]: pppoe0: executing `/libexec/dhcpcd-run-hooks' CARRIER
Nov 15 11:30:00 [5139]: pppoe0: IAID 00:00:00:06
Nov 15 11:30:00 [5139]: pppoe0: IAID 00:00:00:00
Nov 15 11:30:00 [5139]: pppoe0: delaying DHCPv6 soliciation for LL address
Nov 15 11:30:01 [5139]: pppoe0: reading lease `/var/db/dhcpcd/pppoe0.lease6'
Nov 15 11:30:01 [5139]: pppoe0: rebinding prior DHCPv6 lease
Nov 15 11:30:01 [5139]: pppoe0: delaying REBIND6 (xid 0xb2126e), next in 1.4 seconds
Nov 15 11:30:03 [5139]: pppoe0: broadcasting REBIND6 (xid 0xb2126e), next in 0.9 seconds
Nov 15 11:30:04 [5139]: pppoe0: broadcasting REBIND6 (xid 0xb2126e), next in 1.9 seconds
Nov 15 11:30:06 [5139]: pppoe0: broadcasting REBIND6 (xid 0xb2126e), next in 3.8 seconds
Nov 15 11:30:10 [5139]: pppoe0: broadcasting REBIND6 (xid 0xb2126e), next in 4.1 seconds
Nov 15 11:30:11 [5139]: pppoe0: failed to rebind prior delegation
Nov 15 11:30:11 [5139]: pppoe0: soliciting a DHCPv6 lease
Nov 15 11:30:11 [5139]: pppoe0: delaying SOLICIT6 (xid 0x848f3d), next in 1.7 seconds
Nov 15 11:30:13 [5139]: pppoe0: broadcasting SOLICIT6 (xid 0x848f3d), next in 1.1 seconds
Nov 15 11:30:13 [5139]: pppoe0: ADV 2001:41d0:fe9d:1100::/56 from fe80::230:88ff:fe04:63c9
Nov 15 11:30:13 [5139]: pppoe0: broadcasting REQUEST6 (xid 0x1fb09f), next in 0.9 seconds
Nov 15 11:30:13 [5139]: pppoe0: REPLY6 received from fe80::230:88ff:fe04:63c9
Nov 15 11:30:13 [5139]: pppoe0: renew in 43200, rebind in 69120, expire in 172800 seconds
Nov 15 11:30:13 [5139]: pppoe0: writing lease `/var/db/dhcpcd/pppoe0.lease6'
Nov 15 11:30:13 [5139]: pppoe0: delegated prefix 2001:41d0:fe9d:1100::/56
Nov 15 11:30:13 [5139]: pppoe0: executing `/libexec/dhcpcd-run-hooks' BOUND6

And it looks like I had a typo in my tcpdump filter :(
Here's the tcpdump ouput with the typo fixed:
11:30:03.383439 PPPoE  [ses 0x1659] IP6 fe80::43e:1a93:9ba2:3ac9.65464 > ff02::1:2.547: dhcp6 rebind
11:30:04.313522 PPPoE  [ses 0x1659] IP6 fe80::43e:1a93:9ba2:3ac9.65464 > ff02::1:2.547: dhcp6 rebind
11:30:06.243566 PPPoE  [ses 0x1659] IP6 fe80::43e:1a93:9ba2:3ac9.65464 > ff02::1:2.547: dhcp6 rebind
11:30:10.043636 PPPoE  [ses 0x1659] IP6 fe80::43e:1a93:9ba2:3ac9.65464 > ff02::1:2.547: dhcp6 rebind
11:30:13.683849 PPPoE  [ses 0x1659] IP6 fe80::43e:1a93:9ba2:3ac9.65464 > ff02::1:2.547: dhcp6 solicit
11:30:13.692788 PPPoE  [ses 0x1659] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 advertise
11:30:13.693821 PPPoE  [ses 0x1659] IP6 fe80::43e:1a93:9ba2:3ac9.65464 > ff02::1:2.547: dhcp6 request
11:30:13.703013 PPPoE  [ses 0x1659] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 reply

So there are indeed rebind requests sent, but they are ignored by the
remote end.

I took your time with my mistakes, I'm sorry for that.

-- 
Manuel Bouyer <bouyer%antioche.eu.org@localhost>
     NetBSD: 26 ans d'experience feront toujours la difference
--