Re: pppoe, dhcpcd v6 and renew

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

On Sun, Nov 12, 2017 at 02:56:08PM +0000, Roy Marples wrote:
> 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 <bouyer%antioche.eu.org@localhost>
     NetBSD: 26 ans d'experience feront toujours la difference
--