pppoe, dhcpcd v6 and renew

[Manuel Bouyer]

Hello,
my new DSL provider has an ipv6 setup which requires the client side
to send a Delegated Prefix request to get the NRA to route the ipv6 block
to the client.
I could do this with dhcpcd:
interface pppoe0
noipv6rs
ipv6only
ia_pd 0
ipv6ra_noautoconf
nogateway
nohook resolv.conf, hostname, ntp.conf
noipv4

my router just needs to send a dhcp6 request or rebind, it doesn't need
to handle the reply (everything is static).

The problem is, if for some reason the pppoe session terminates,
the kernel will successfully initiates a new one but dhcpcd doens't send
a rebind, and the ISP stops routing my prefix. I have to manually
restart dhcpcd to fix this.
I tried ifwatchd but pppoe doesn't send events in this case.

I tried to add a 'leasetime 600' in dhcpcd.conf, in the hope that
dhcpcd would periodically send a rebind but it doens't happen.

Any idea how this could be properly fixed ?
I could periodically start dhcpcd from cron but I'd prefer a cleaner
way to achieve this ...

[Christos Zoulas]

Post by Manuel Bouyer
Hello,
my new DSL provider has an ipv6 setup which requires the client side
to send a Delegated Prefix request to get the NRA to route the ipv6 block
to the client.
interface pppoe0
noipv6rs
ipv6only
ia_pd 0
ipv6ra_noautoconf
nogateway
nohook resolv.conf, hostname, ntp.conf
noipv4
my router just needs to send a dhcp6 request or rebind, it doesn't need
to handle the reply (everything is static).
The problem is, if for some reason the pppoe session terminates,
the kernel will successfully initiates a new one but dhcpcd doens't send
a rebind, and the ISP stops routing my prefix. I have to manually
restart dhcpcd to fix this.
I tried ifwatchd but pppoe doesn't send events in this case.

Perhaps pppoe should send events in thst case?

christos


--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

[Roy Marples]

Post by Manuel Bouyer
Hello,
my new DSL provider has an ipv6 setup which requires the client side
to send a Delegated Prefix request to get the NRA to route the ipv6 block
to the client.
interface pppoe0
noipv6rs
ipv6only
ia_pd 0
ipv6ra_noautoconf
nogateway
nohook resolv.conf, hostname, ntp.conf
noipv4
my router just needs to send a dhcp6 request or rebind, it doesn't need
to handle the reply (everything is static).
The problem is, if for some reason the pppoe session terminates,
the kernel will successfully initiates a new one but dhcpcd doens't send
a rebind, and the ISP stops routing my prefix. I have to manually
restart dhcpcd to fix this.
I tried ifwatchd but pppoe doesn't send events in this case.
I tried to add a 'leasetime 600' in dhcpcd.conf, in the hope that
dhcpcd would periodically send a rebind but it doens't happen.
Any idea how this could be properly fixed ?
I could periodically start dhcpcd from cron but I'd prefer a cleaner
way to achieve this ...

PPPoE needs to send the link down media event when the session
terminates and the link up media event when it gets a new one.

Then both dhcpcd and ifwatchd will see this.

Here's the patch I make for PPP for this very thing, it just needs
adapting to PPPoE I think.
http://cvsweb.netbsd.org/bsdweb.cgi/src/sys/net/if_spppsubr.c.diff?r1=1.149&r2=1.150&only_with_tag=MAIN&f=h

Roy

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

[Manuel Bouyer]

Post by Manuel Bouyer
[...]
Any idea how this could be properly fixed ?
I could periodically start dhcpcd from cron but I'd prefer a cleaner
way to achieve this ...

PPPoE needs to send the link down media event when the session terminates
and the link up media event when it gets a new one.

ifconfig did show "status: no network" before switching back to "active".
But no event was sent.

Then both dhcpcd and ifwatchd will see this.
Here's the patch I make for PPP for this very thing, it just needs adapting
to PPPoE I think.
http://cvsweb.netbsd.org/bsdweb.cgi/src/sys/net/if_spppsubr.c.diff?r1=1.149&r2=1.150&only_with_tag=MAIN&f=h

I'll have a look, thanks !

[Manuel Bouyer]

PPPoE needs to send the link down media event when the session terminates
and the link up media event when it gets a new one.
Then both dhcpcd and ifwatchd will see this.
Here's the patch I make for PPP for this very thing, it just needs adapting
to PPPoE I think.
http://cvsweb.netbsd.org/bsdweb.cgi/src/sys/net/if_spppsubr.c.diff?r1=1.149&r2=1.150&only_with_tag=MAIN&f=h

thanks. AFAIK this code is in netbsd-8, and pppoe0 uses if_spppsubr.c for
lcp so it should just work.

When reboot the modem, this time with pppoe0 in debug (ifconfig debug).
Here's the interesting parts of /var/log/messages:
Nov 13 21:04:56 chassiron ifwatchd[6876]: watching interface pppoe0
Nov 13 21:05:40 chassiron /netbsd: pppoe0: lcp output <echo-req id=0x13 len=8 80
-c8-99-c9>
Nov 13 21:05:50 chassiron /netbsd: pppoe0: lcp output <echo-req id=0x14 len=8 80
-c8-99-c9>
Nov 13 21:06:00 chassiron /netbsd: pppoe0: lcp output <echo-req id=0x15 len=8 80
-c8-99-c9>
Nov 13 21:06:10 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to res
tart the connection
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp close(opened)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: phase terminate
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipcp down(opened)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipcp close(starting)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipv6cp down(opened)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipv6cp close(starting)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp output <term-req id=0x16 len=4>
Nov 13 21:06:10 chassiron dhcpcd[1215]: pppoe0: carrier lost
Nov 13 21:06:10 chassiron /netbsd: pppoe0: disconnecting
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp down(stopped)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: phase establish
Nov 13 21:06:10 chassiron /netbsd: pppoe0: Down event (carrier loss), taking interface down.
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp close(starting)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: phase dead
Nov 13 21:06:12 chassiron ntpd[21224]: Deleting interface #13 pppoe0, fe80::43e:
1a93:9ba2:3ac9%6#123, interface stats: received=0, sent=0, dropped=0, active_tim
e=117021 secs
Nov 13 21:06:12 chassiron ntpd[21224]: Deleting interface #14 pppoe0, 151.127.5.
145#123, interface stats: received=1071, sent=1073, dropped=0, active_time=117021 secs
Nov 13 21:06:12 chassiron ntpd[21224]: 132.227.73.242 local addr 151.127.5.145 -> <null>
Nov 13 21:06:12 chassiron ntpd[21224]: 134.157.254.19 local addr 151.127.5.145 -> <null>
Nov 13 21:06:12 chassiron ntpd[21224]: 213.251.128.249 local addr 151.127.5.145 -> <null>
Nov 13 21:06:12 chassiron ntpd[21224]: Deleting interface #15 pppoe0, 2001:41d0:fe9d:1101::1#123, interface stats: received=0, sent=0, dropped=0, active_time=117021 secs
Nov 13 21:07:15 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 13 21:07:15 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 13 21:07:16 chassiron /netbsd: pppoe0: session 0x2303 connected
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp open(initial)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: phase establish
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp up(starting)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp output <conf-req id=0x17 len=14 05-06-80-c8-99-c9-01-04-05-d4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp input(req-sent): <conf-req id=0x8b len=19 01-04-05-d4-03-05-c2-23-05-05-06-0e-44-4a-7e>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp parse opts: mru auth-proto magic
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp parse opt values: mru 1492 auth-proto magic 0xe444a7e send conf-ack
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp output <conf-ack id=0x8b len=19 01-04-05-d4-03-05-c2-23-05-05-06-0e-44-4a-7e>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp input(ack-sent): <conf-ack id=0x17 len=14 05-06-80-c8-99-c9-01-04-05-d4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp tlu
Nov 13 21:07:16 chassiron /netbsd: pppoe0: phase authenticate
Nov 13 21:07:16 chassiron /netbsd: pppoe0: chap input <challenge id=0x1 len=37 name=lns-1-par-se1200 value-size=16 value= xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: chap output <response id=0x1 len=42 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: chap success: CHAP authentication success, unit 7887
Nov 13 21:07:16 chassiron /netbsd: pppoe0: phase network
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp open(initial)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp open(initial)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp up(starting)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp output <conf-req id=0x5 len=4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp up(starting)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp output <conf-req id=0x5 len=14 01-0a-04-3e-1a-93-9b-a2-3a-c9>
Nov 13 21:07:16 chassiron dhcpcd[1215]: pppoe0: carrier acquired
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp input(req-sent): <conf-req id=0xb7 len=10 03-06-b2-20-25-03>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp parse opts: address
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp parse opt values: address 0.0.0.1 [ack] send conf-ack
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp output <conf-ack id=0xb7 len=10 03-06-b2-20-25-03>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp input(ack-sent): <conf-ack id=0x5 len=4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp tlu
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp input(req-sent): <conf-req id=0x67 len=14 01-0a-02-30-88-ff-fe-04-63-c9>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp parse opts: ifid
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp parse opt values: ifid fe80:6::230:88ff:fe04:63c9 [conf-ack] send conf-ack
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp output <conf-ack id=0x67 len=14 01-0a-02-30-88-ff-fe-04-63-c9>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp input(ack-sent): <conf-ack id=0x5 len=14 01-0a-04-3e-1a-93-9b-a2-3a-c9>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp tlu
Nov 13 21:07:16 chassiron dhcpcd[1215]: pppoe0: IAID 00:00:00:06
Nov 13 21:07:16 chassiron dhcpcd[1215]: pppoe0: IAID 00:00:00:06
Nov 13 21:07:19 chassiron ntpd[21224]: Listen normally on 19 pppoe0 [fe80::43e:1a93:9ba2:3ac9%6]:123
Nov 13 21:07:19 chassiron ntpd[21224]: Listen normally on 20 pppoe0 151.127.5.145:123
Nov 13 21:07:19 chassiron ntpd[21224]: Listen normally on 21 pppoe0 [2001:41d0:fe9d:1101::1]:123
Nov 13 21:07:19 chassiron ntpd[21224]: 132.227.73.242 local addr 192.168.2.1 -> 151.127.5.145
Nov 13 21:07:19 chassiron ntpd[21224]: 134.157.254.19 local addr 192.168.2.1 -> 151.127.5.145
Nov 13 21:07:19 chassiron ntpd[21224]: 213.251.128.249 local addr 192.168.2.1 -> 151.127.5.145


So both dhcpcd and ntpd notices that something happens. For ntpd if may be
because the IP addresses are switched to DETACHED while the network is
down.

But ifwatchd doesn't notice the status change:
chassiron#/home/bouyer>ifwatchd -v pppoe0
up_script: (null)
down_script: (null)
arrival_script: (null)
departure_script: (null)
carrier_script: (null)
no_carrier_script: (null)
verbosity = 1
interface "pppoe0" has index 6
[and nothing more]

maybe ifwatchd filters on interface type, or something ?

the other issue is, although dhcpd did notice the interface link down/up,
it didn't resend the ia_pd packet. This is confirmed by a tcpdump on the
interface.

[Manuel Bouyer]

Post by Manuel Bouyer
[...]
chassiron#/home/bouyer>ifwatchd -v pppoe0
up_script: (null)
down_script: (null)
arrival_script: (null)
departure_script: (null)
carrier_script: (null)
no_carrier_script: (null)
verbosity = 1
interface "pppoe0" has index 6
[and nothing more]
maybe ifwatchd filters on interface type, or something ?

reading the sources, I figured that ifwatchd doesn't print events if there's
no script for it, even in verbose mode.
So I added a script which does a dhcpcd -k and start a new one on link up
events, and now ipv6 comes back up automatically after a modem reboot.

Still would be nice if dhcpcd could do this by itself, but at last I have a
workaround ...

[Roy Marples]

Post by Manuel Bouyer

PPPoE needs to send the link down media event when the session terminates
and the link up media event when it gets a new one.
Then both dhcpcd and ifwatchd will see this.
Here's the patch I make for PPP for this very thing, it just needs adapting
to PPPoE I think.
http://cvsweb.netbsd.org/bsdweb.cgi/src/sys/net/if_spppsubr.c.diff?r1=1.149&r2=1.150&only_with_tag=MAIN&f=h

thanks. AFAIK this code is in netbsd-8, and pppoe0 uses if_spppsubr.c for
lcp so it should just work.
When reboot the modem, this time with pppoe0 in debug (ifconfig debug).
Nov 13 21:04:56 chassiron ifwatchd[6876]: watching interface pppoe0
Nov 13 21:05:40 chassiron /netbsd: pppoe0: lcp output <echo-req id=0x13 len=8 80
-c8-99-c9>
Nov 13 21:05:50 chassiron /netbsd: pppoe0: lcp output <echo-req id=0x14 len=8 80
-c8-99-c9>
Nov 13 21:06:00 chassiron /netbsd: pppoe0: lcp output <echo-req id=0x15 len=8 80
-c8-99-c9>
Nov 13 21:06:10 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to res
tart the connection
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp close(opened)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: phase terminate
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipcp down(opened)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipcp close(starting)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipv6cp down(opened)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: ipv6cp close(starting)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp output <term-req id=0x16 len=4>
Nov 13 21:06:10 chassiron dhcpcd[1215]: pppoe0: carrier lost

dhcpcd saw that pppoe0 went down, good

Post by Manuel Bouyer
Nov 13 21:06:10 chassiron /netbsd: pppoe0: disconnecting
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp down(stopped)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: phase establish
Nov 13 21:06:10 chassiron /netbsd: pppoe0: Down event (carrier loss), taking interface down.
Nov 13 21:06:10 chassiron /netbsd: pppoe0: lcp close(starting)
Nov 13 21:06:10 chassiron /netbsd: pppoe0: phase dead
1a93:9ba2:3ac9%6#123, interface stats: received=0, sent=0, dropped=0, active_tim
e=117021 secs
Nov 13 21:06:12 chassiron ntpd[21224]: Deleting interface #14 pppoe0, 151.127.5.
145#123, interface stats: received=1071, sent=1073, dropped=0, active_time=117021 secs
Nov 13 21:06:12 chassiron ntpd[21224]: 132.227.73.242 local addr 151.127.5.145 -> <null>
Nov 13 21:06:12 chassiron ntpd[21224]: 134.157.254.19 local addr 151.127.5.145 -> <null>
Nov 13 21:06:12 chassiron ntpd[21224]: 213.251.128.249 local addr 151.127.5.145 -> <null>
Nov 13 21:06:12 chassiron ntpd[21224]: Deleting interface #15 pppoe0, 2001:41d0:fe9d:1101::1#123, interface stats: received=0, sent=0, dropped=0, active_time=117021 secs
Nov 13 21:07:15 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 13 21:07:15 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 13 21:07:16 chassiron /netbsd: pppoe0: session 0x2303 connected
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp open(initial)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: phase establish
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp up(starting)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp output <conf-req id=0x17 len=14 05-06-80-c8-99-c9-01-04-05-d4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp input(req-sent): <conf-req id=0x8b len=19 01-04-05-d4-03-05-c2-23-05-05-06-0e-44-4a-7e>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp parse opts: mru auth-proto magic
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp parse opt values: mru 1492 auth-proto magic 0xe444a7e send conf-ack
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp output <conf-ack id=0x8b len=19 01-04-05-d4-03-05-c2-23-05-05-06-0e-44-4a-7e>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp input(ack-sent): <conf-ack id=0x17 len=14 05-06-80-c8-99-c9-01-04-05-d4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: lcp tlu
Nov 13 21:07:16 chassiron /netbsd: pppoe0: phase authenticate
Nov 13 21:07:16 chassiron /netbsd: pppoe0: chap input <challenge id=0x1 len=37 name=lns-1-par-se1200 value-size=16 value= xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: chap output <response id=0x1 len=42 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: chap success: CHAP authentication success, unit 7887
Nov 13 21:07:16 chassiron /netbsd: pppoe0: phase network
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp open(initial)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp open(initial)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp up(starting)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp output <conf-req id=0x5 len=4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp up(starting)
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp output <conf-req id=0x5 len=14 01-0a-04-3e-1a-93-9b-a2-3a-c9>
Nov 13 21:07:16 chassiron dhcpcd[1215]: pppoe0: carrier acquired

dhcpcd sees that the carrier is back, good

Post by Manuel Bouyer
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp input(req-sent): <conf-req id=0xb7 len=10 03-06-b2-20-25-03>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp parse opts: address
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp parse opt values: address 0.0.0.1 [ack] send conf-ack
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp output <conf-ack id=0xb7 len=10 03-06-b2-20-25-03>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp input(ack-sent): <conf-ack id=0x5 len=4>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipcp tlu
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp input(req-sent): <conf-req id=0x67 len=14 01-0a-02-30-88-ff-fe-04-63-c9>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp parse opts: ifid
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp parse opt values: ifid fe80:6::230:88ff:fe04:63c9 [conf-ack] send conf-ack
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp output <conf-ack id=0x67 len=14 01-0a-02-30-88-ff-fe-04-63-c9>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp input(ack-sent): <conf-ack id=0x5 len=14 01-0a-04-3e-1a-93-9b-a2-3a-c9>
Nov 13 21:07:16 chassiron /netbsd: pppoe0: ipv6cp tlu
Nov 13 21:07:16 chassiron dhcpcd[1215]: pppoe0: IAID 00:00:00:06
Nov 13 21:07:16 chassiron dhcpcd[1215]: pppoe0: IAID 00:00:00:06

dhcpcd did try and start the interface, but didn't actually do anything.
Can you try the attached patch please?
I've only compile tested it and won't be able to actually try it for a
while.

Roy

[Roy Marples]

Post by Roy Marples
dhcpcd did try and start the interface, but didn't actually do anything.
Can you try the attached patch please?
I've only compile tested it and won't be able to actually try it for a
while.

So that patch caused a few other problems.
This one is more invasive but fixes a whole raft of issues related to
not removing addresses on carrier down, which is exclusive to NetBSD-8.

Let me know how it works!

Roy

[Manuel Bouyer]

Post by Roy Marples

Post by Roy Marples
dhcpcd did try and start the interface, but didn't actually do anything.
Can you try the attached patch please?
I've only compile tested it and won't be able to actually try it for a
while.

So that patch caused a few other problems.
This one is more invasive but fixes a whole raft of issues related to not
removing addresses on carrier down, which is exclusive to NetBSD-8.
Let me know how it works!

I had to fix a conflict for netbsd-8, here's the updated patch.

dhcpcd is now more verbose:
Nov 14 19:29:43 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to restart the connection
Nov 14 19:29:43 chassiron dhcpcd[25536]: pppoe0: carrier lost
Nov 14 19:30:48 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 19:30:48 chassiron dhcpcd[25536]: pppoe0: carrier acquired
Nov 14 19:30:48 chassiron dhcpcd[25536]: pppoe0: IAID 00:00:00:06
Nov 14 19:30:48 chassiron dhcpcd[25536]: pppoe0: IAID 00:00:00:00
Nov 14 19:30:50 chassiron dhcpcd[25536]: pppoe0: rebinding prior DHCPv6 lease

But it didn't send anything on the pppoe0 interface (confirmed by a tcpdump).
Here's what it prints on a fresh start:
Nov 14 19:28:27 chassiron dhcpcd[29292]: forked to background, child pid 25536
Nov 14 19:28:27 chassiron dhcpcd[25536]: DUID 00:01:00:01:21:85:aa:70:02:4a:06:41:92:71
Nov 14 19:28:27 chassiron dhcpcd[25536]: pppoe0: IAID 00:00:00:06
Nov 14 19:28:27 chassiron dhcpcd[25536]: pppoe0: IAID 00:00:00:00
Nov 14 19:28:27 chassiron dhcpcd[25536]: pppoe0: soliciting a DHCPv6 lease
Nov 14 19:28:28 chassiron dhcpcd[25536]: pppoe0: ADV 2001:41d0:fe9d:1100::/56 from fe80::230:88ff:fe04:63c9
Nov 14 19:28:28 chassiron dhcpcd[25536]: pppoe0: REPLY6 received from fe80::230:88ff:fe04:63c9
Nov 14 19:28:28 chassiron dhcpcd[25536]: pppoe0: renew in 43200, rebind in 69120, expire in 172800 seconds
Nov 14 19:28:28 chassiron dhcpcd[25536]: lo0: adding reject route to 2001:41d0:fe9d:1100::/56 via ::1
Nov 14 19:28:28 chassiron dhcpcd[25536]: pppoe0: delegated prefix 2001:41d0:fe9d:1100::/56

[Roy Marples]

Post by Manuel Bouyer

Post by Roy Marples

Post by Roy Marples
dhcpcd did try and start the interface, but didn't actually do anything.
Can you try the attached patch please?
I've only compile tested it and won't be able to actually try it for a
while.

So that patch caused a few other problems.
This one is more invasive but fixes a whole raft of issues related to not
removing addresses on carrier down, which is exclusive to NetBSD-8.
Let me know how it works!

I had to fix a conflict for netbsd-8, here's the updated patch.
Nov 14 19:29:43 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to restart the connection
Nov 14 19:29:43 chassiron dhcpcd[25536]: pppoe0: carrier lost
Nov 14 19:30:48 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 19:30:48 chassiron dhcpcd[25536]: pppoe0: carrier acquired
Nov 14 19:30:48 chassiron dhcpcd[25536]: pppoe0: IAID 00:00:00:06
Nov 14 19:30:48 chassiron dhcpcd[25536]: pppoe0: IAID 00:00:00:00
Nov 14 19:30:50 chassiron dhcpcd[25536]: pppoe0: rebinding prior DHCPv6 lease
But it didn't send anything on the pppoe0 interface (confirmed by a tcpdump).

That's a pity.
I think there's another path needed, but the changelog doesn't give much
clue from what's in NetBSD-8 (or from what's in -current).

Can you try my latest git HEAD? I'll be doing an import soon if that
fixes :)
https://roy.marples.name/git/dhcpcd.git/

Thanks

Roy

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

[Manuel Bouyer]

Post by Roy Marples
That's a pity.
I think there's another path needed, but the changelog doesn't give much
clue from what's in NetBSD-8 (or from what's in -current).
Can you try my latest git HEAD? I'll be doing an import soon if that fixes
:)
https://roy.marples.name/git/dhcpcd.git/

With this one it seems to DTRT on link up.
syslog messages:
Nov 14 20:10:23 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to restart the connection
Nov 14 20:10:23 chassiron dhcpcd[28004]: pppoe0: carrier lost
Nov 14 20:11:28 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: carrier acquired
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: IAID 00:00:00:06
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: IAID 00:00:00:00
Nov 14 20:11:29 chassiron dhcpcd[28004]: pppoe0: rebinding prior DHCPv6 lease
Nov 14 20:11:28 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 20:11:39 chassiron dhcpcd[28004]: pppoe0: failed to rebind prior delegation
Nov 14 20:11:39 chassiron dhcpcd[28004]: pppoe0: soliciting a DHCPv6 lease
Nov 14 20:11:41 chassiron dhcpcd[28004]: pppoe0: ADV 2001:41d0:fe9d:1100::/56 from fe80::230:88ff:fe04:63c9
Nov 14 20:11:41 chassiron dhcpcd[28004]: pppoe0: REPLY6 received from fe80::230:88ff:fe04:63c9
Nov 14 20:11:41 chassiron dhcpcd[28004]: pppoe0: renew in 43200, rebind in 69120, expire in 172800 seconds
Nov 14 20:11:41 chassiron dhcpcd[28004]: pppoe0: delegated prefix 2001:41d0:fe9d:1100::/56


and on tcpdump:
20:11:41.891320 PPPoE [ses 0x21d7] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 advertise
20:11:41.902095 PPPoE [ses 0x21d7] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 reply

So all looks good with this version

[Roy Marples]

Post by Manuel Bouyer

Post by Roy Marples
That's a pity.
I think there's another path needed, but the changelog doesn't give much
clue from what's in NetBSD-8 (or from what's in -current).
Can you try my latest git HEAD? I'll be doing an import soon if that fixes
:)
https://roy.marples.name/git/dhcpcd.git/

With this one it seems to DTRT on link up.

YAY :)

Post by Manuel Bouyer
Nov 14 20:10:23 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to restart the connection
Nov 14 20:10:23 chassiron dhcpcd[28004]: pppoe0: carrier lost
Nov 14 20:11:28 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: carrier acquired
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: IAID 00:00:00:06
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: IAID 00:00:00:00
Nov 14 20:11:29 chassiron dhcpcd[28004]: pppoe0: rebinding prior DHCPv6 lease
Nov 14 20:11:28 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 20:11:39 chassiron dhcpcd[28004]: pppoe0: failed to rebind prior delegation

Hmmm, that is a slight cause for concern.
Did it send out a rebind request that looks ok?
Is the delegation you got the same as the previous one?

Roy

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

[Manuel Bouyer]

Post by Roy Marples

Post by Manuel Bouyer

Post by Roy Marples
That's a pity.
I think there's another path needed, but the changelog doesn't give much
clue from what's in NetBSD-8 (or from what's in -current).
Can you try my latest git HEAD? I'll be doing an import soon if that fixes
:)
https://roy.marples.name/git/dhcpcd.git/

With this one it seems to DTRT on link up.

YAY :)

Post by Manuel Bouyer
Nov 14 20:10:23 chassiron /netbsd: pppoe0: LCP keepalive timed out, going to restart the connection
Nov 14 20:10:23 chassiron dhcpcd[28004]: pppoe0: carrier lost
Nov 14 20:11:28 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: carrier acquired
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: IAID 00:00:00:06
Nov 14 20:11:28 chassiron dhcpcd[28004]: pppoe0: IAID 00:00:00:00
Nov 14 20:11:29 chassiron dhcpcd[28004]: pppoe0: rebinding prior DHCPv6 lease
Nov 14 20:11:28 chassiron /netbsd: pppoe0: connected to lns-1-par-se100
Nov 14 20:11:39 chassiron dhcpcd[28004]: pppoe0: failed to rebind prior delegation

Hmmm, that is a slight cause for concern.
Did it send out a rebind request that looks ok?

I guess it did not, the only thing I see on
tcpdump -n -p -i pppoe0 port 546 or port 457
is:
20:11:41.891320 PPPoE [ses 0x21d7] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 advertise
20:11:41.902095 PPPoE [ses 0x21d7] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 reply

Post by Roy Marples
Is the delegation you got the same as the previous one?

Yes, but it's a static delegation so I wouldn't expect something different.
I don't know what the remote end expects, maybe when a new pppoe session
starts, dhcp state is reset ? This would be consustent with the IPv6
route for my prefix being lost ...

[Roy Marples]

Post by Manuel Bouyer

Post by Roy Marples

Post by Manuel Bouyer
Nov 14 20:11:39 chassiron dhcpcd[28004]: pppoe0: failed to rebind prior delegation

Hmmm, that is a slight cause for concern.
Did it send out a rebind request that looks ok?

I guess it did not, the only thing I see on
tcpdump -n -p -i pppoe0 port 546 or port 457
20:11:41.891320 PPPoE [ses 0x21d7] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 advertise
20:11:41.902095 PPPoE [ses 0x21d7] IP6 fe80::230:88ff:fe04:63c9.547 > fe80::43e:1a93:9ba2:3ac9.546: dhcp6 reply

Post by Roy Marples
Is the delegation you got the same as the previous one?

Yes, but it's a static delegation so I wouldn't expect something different.
I don't know what the remote end expects, maybe when a new pppoe session
starts, dhcp state is reset ? This would be consustent with the IPv6
route for my prefix being lost ...

Could you add the debug directive to /etc/dhcpcd.conf and get some logs
about what it claims it's doing please?

Roy

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

[Manuel Bouyer]

Post by Roy Marples
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

[Roy Marples]

Post by Manuel Bouyer

Post by Roy Marples
Could you add the debug directive to /etc/dhcpcd.conf and get some logs
about what it claims it's doing please?

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

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

[Manuel Bouyer]

Post by Roy Marples
[...]
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.

[Roy Marples]

Post by Manuel Bouyer

Post by Roy Marples
[...]
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 :(
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.

Do the rebind requests look correct?
It's odd that they are ignored. No upstream has ever gotten back to me
on why renews are ignored when this is reported.

Post by Manuel Bouyer
I took your time with my mistakes, I'm sorry for that.

No problem, it was my buggy code that started this, but at least it's
working now!

Roy

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de

[Manuel Bouyer]

Post by Roy Marples
Do the rebind requests look correct?
It's odd that they are ignored. No upstream has ever gotten back to me on
why renews are ignored when this is reported.

Here's how it looks like with tcpdump -v:
11:56:53.918117 PPPoE [ses 0x1807] IP6 (hlim 1, next-header UDP (17) payload length: 191) fe80::43e:1a93:9ba2:3ac9.65463 > ff02::1:2.547: [udp sum ok] dhcp6 rebind (xid=c4ddf4 (client-ID hwaddr/time type 1 time 562408048 024a06419271) (elapsed-time 0) (vendor-class) (IA_PD IAID:0 T1:0 T2:0 (IA_PD-prefix 2001:41d0:fe9d:1100::/56 pltime:86400 vltime:172800)) (Client-FQDN) (reconfigure-accept) (option-request DNS-server DNS-search-list SNTP-servers Client-FQDN opt_82 opt_83))

It looks OK (IA_PD-prefix is the right one) but I don't know dhcp enough
to make sure it's correct.

Attached is the complete output of tcpdump -v, for 2 modem reboot,
so you have the initial request and then the corresponding rebind.