This is current/amd64 on an APU2.E2.
It is connected via pppoe over vlan over em as follows:
$ cat /etc/hostname.em0
up
$ cat /etc/hostname.vlan848
descr UVTNET vlan 848 vlandev em0 up
$ cat /etc/hostname.pppoe0
inet 0.0.0.0 255.255.255.255 NONE pppoedev vlan848 \
authproto 'pap' authname 'X' authkey 'PASS' up
dest 0.0.0.1
!/sbin/route add default 0.0.0.1
(The 'X' and 'PASS' are actual bogus values,
the ISP filters by the link I am connected to.)
$ ifconfig em0
em0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 1500
lladdr 00:0d:b9:56:5e:fc
index 1 priority 0 llprio 3
media: Ethernet autoselect (1000baseT full-duplex)
status: active
$ ifconfig vlan848
vlan848: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 1500
lladdr 00:0d:b9:56:5e:fc
description: UVTNET
index 8 priority 0 llprio 3
encap: vnetid 848 parent em0 txprio packet rxprio outer
groups: vlan
media: Ethernet autoselect (1000baseT full-duplex)
status: active
$ ifconfig pppoe0
pppoe0: flags=8851<UP,POINTOPOINT,RUNNING,SIMPLEX,MULTICAST> mtu 1492
index 7 priority 0 llprio 3
dev: vlan848 state: session
sid: 0x1 PADI retries: 5 PADR retries: 0 time: 00:03:17
sppp: phase network authproto pap authname "X"
groups: pppoe egress
status: active
inet6 fe80::20d:b9ff:fe56:5efc%pppoe0 -> prefixlen 64 scopeid 0x7
inet 185.63.96.79 --> 10.11.5.146 netmask 0xffffffff
The connection works just fine, except it drops every five minutes
- I mean after exactly five minutes, for the last ten hours.
This is the test I did:
(1) in one script, keep pinging out
(2) in another script, watch the pppoe up time in a loop:
while true ; do date ; ifconfig pppoe0 ; sleep 1; done
(3) run a tcpdump during that
This is what the pinging looks like:
$ ping stary.fit.cvut.cz
PING stary.fit.cvut.cz (147.32.232.84): 56 data bytes
64 bytes from 147.32.232.84: icmp_seq=0 ttl=246 time=6.632 ms
64 bytes from 147.32.232.84: icmp_seq=1 ttl=246 time=7.339 ms
64 bytes from 147.32.232.84: icmp_seq=2 ttl=246 time=6.762 ms
64 bytes from 147.32.232.84: icmp_seq=3 ttl=246 time=6.438 ms
64 bytes from 147.32.232.84: icmp_seq=4 ttl=246 time=6.626 ms
64 bytes from 147.32.232.84: icmp_seq=5 ttl=246 time=6.989 ms
64 bytes from 147.32.232.84: icmp_seq=6 ttl=246 time=6.951 ms
64 bytes from 147.32.232.84: icmp_seq=7 ttl=246 time=7.136 ms
64 bytes from 147.32.232.84: icmp_seq=8 ttl=246 time=7.620 ms
64 bytes from 147.32.232.84: icmp_seq=9 ttl=246 time=7.404 ms
^^^^^^^^^^^
[no reply for about 50 seconds]
64 bytes from 147.32.232.84: icmp_seq=60 ttl=246 time=6.786 ms
^^^^^^^^^^^^^
64 bytes from 147.32.232.84: icmp_seq=61 ttl=246 time=7.316 ms
64 bytes from 147.32.232.84: icmp_seq=62 ttl=246 time=7.570 ms
64 bytes from 147.32.232.84: icmp_seq=63 ttl=246 time=7.296 ms
[getting replies for precisely 300 pings, then repeats]
The drop happens exactly when ifconfig pppoe0 says
the interface has been up for 5 minues:
Fri Apr 24 13:13:28 CEST 2020
pppoe0: flags=8951<UP,POINTOPOINT,RUNNING,PROMISC,SIMPLEX,MULTICAST> mtu 1492
index 7 priority 0 llprio 3
dev: vlan848 state: session
sid: 0x1 PADI retries: 5 PADR retries: 0 time: 00:05:00
^^^^^^^^^^^^^^^
sppp: phase network authproto pap authname "X"
groups: pppoe egress
status: active
inet 185.63.96.79 --> 10.11.5.146 netmask 0xffffffff
For almost exactly 50 seconds then, the pings are not getting replies.
This is what tcpdump says:
[pinging away]
13:13:26.840342 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:26.847192 147.32.232.84 > 185.63.96.79: icmp: echo reply
13:13:27.840399 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:27.847448 147.32.232.84 > 185.63.96.79: icmp: echo reply
13:13:28.840398 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:28.847934 147.32.232.84 > 185.63.96.79: icmp: echo reply
[ifconfig pppoe0 shows time 00:05:00]
[The pings are no longer getting replies]
13:13:29.450416 IPV6CP Configure-Request Id=0xff:
IPv6-Interface-Id=427c:7dff:feea:db03
13:13:29.450438 IPV6CP Configure-Ack Id=0xff:
IPv6-Interface-Id=427c:7dff:feea:db03
13:13:29.840366 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:29.847671 147.32.232.84 > 185.63.96.79: icmp: echo reply
13:13:30.840381 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:31.840472 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:32.840499 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:33.840449 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:34.840401 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:35.840431 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:36.840437 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:37.840422 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:38.840517 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:39.840458 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:40.840429 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:41.840439 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:42.840476 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:43.840449 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:44.840542 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:45.840470 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:46.840453 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:47.840552 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:48.840503 185.63.96.79 > 147.32.232.84: icmp: echo request
[20 seconds later:]
13:13:48.850457 LCP Echo-Request Id=0x55: Magic-Number=618222534
13:13:49.840504 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:50.840586 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:51.840524 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:52.840564 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:53.840526 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:54.840618 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:55.840620 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:56.840572 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:57.840538 185.63.96.79 > 147.32.232.84: icmp: echo request
13:13:58.840636 185.63.96.79 > 147.32.232.84: icmp: echo request
[Another 10 seconds later:]
13:13:58.850493 LCP Echo-Request Id=0x56: Magic-Number=618222534
13:13:59.840597 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:00.840649 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:01.840733 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:02.840669 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:03.840650 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:04.840627 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:05.840679 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:06.840626 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:07.840607 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:08.840754 185.63.96.79 > 147.32.232.84: icmp: echo request
[Another 10 seconds later:]
13:14:08.850555 LCP Echo-Request Id=0x57: Magic-Number=618222534
13:14:09.840621 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:10.840642 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:11.840703 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:12.840656 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:13.840669 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:14.840698 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:15.840652 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:16.840668 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:17.840718 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:18.840672 185.63.96.79 > 147.32.232.84: icmp: echo request
[Another 10 seconds later:]
[The connection is being terminated and negotiated anew:]
13:14:18.851096 LCP Terminate-Request Id=0x58:
13:14:18.891903 LCP Configure-Request Id=0x59: Magic-Number=2572512523
Max-Rx-Unit=1492
13:14:18.891910 LCP Configure-Request Id=0xd4: Max-Rx-Unit=1492 Auth-Prot=PAP
Magic-Number=893838117
13:14:18.891920 LCP Configure-Ack Id=0xd4: Max-Rx-Unit=1492 Auth-Prot=PAP
Magic-Number=893838117
13:14:18.897864 LCP Configure-Ack Id=0x59: Magic-Number=2572512523
Max-Rx-Unit=1492
13:14:18.898186 PAP Authenticate-Request Id=0x5a: Peer-Id=X Passwd=PASS
13:14:18.945411 PAP Authenticate-Ack Id=0x5a: Message=Login ok
13:14:18.945421 IPCP Configure-Request Id=0x5b: IP-Address=0.0.0.0
13:14:18.945741 IPCP Configure-Request Id=0xa0: IP-Address=10.11.5.146
13:14:18.945750 IPCP Configure-Ack Id=0xa0: IP-Address=10.11.5.146
13:14:18.945758 IPV6CP Configure-Request Id=0x78:
IPv6-Interface-Id=427c:7dff:feea:db03
13:14:18.945770 IPV6CP Configure-Ack Id=0x78:
IPv6-Interface-Id=427c:7dff:feea:db03
13:14:18.952139 IPCP Configure-Nak Id=0x5b: IP-Address=185.63.96.79
13:14:18.952145 IPCP Configure-Request Id=0x5c: IP-Address=185.63.96.79
13:14:18.958390 IPCP Configure-Ack Id=0x5c: IP-Address=185.63.96.79
[The pings start getting replies again:]
13:14:19.840764 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:20.840713 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:20.847426 147.32.232.84 > 185.63.96.79: icmp: echo reply
13:14:21.790674 IPV6CP Configure-Request Id=0xff:
IPv6-Interface-Id=427c:7dff:feea:db03
13:14:21.790689 IPV6CP Configure-Ack Id=0xff:
IPv6-Interface-Id=427c:7dff:feea:db03
13:14:21.840725 185.63.96.79 > 147.32.232.84: icmp: echo request
13:14:21.847889 147.32.232.84 > 185.63.96.79: icmp: echo reply
Note the time seqence:
* when ifconfig says time 00:05:00, pings die
* after 20 seconds, a LCP Echo Request comes
* after another 10 seconds, another LCP Echo Request comes
* after another 10 seconds, another LCP Echo Request comes
* after another 10 seconds, a LCP Terminate Request comes
and the connection is established anew.
This pattern has been repeating since the last midnight.
It looks to me like my ISP is cutting me off every 5 minutes,
and than it takes 50 seconds to realize the connection is down,
which is when it sends the Terminate,
and then the connection is re-established.
Has anyone seen the same?
Is this a known issue with pppoe connections?
Searching the archives, I found this:
https://marc.info/?l=openbsd-misc&m=155053560723855&w=2
(but see the entire thread for other details).
Adam's issue 2 rings a bell, because the drop
happens when I get a new IP6 configuraion request.
I do have the "inet6 eui64" in my setup though.
(I don't really know the LCP protocol, but issue 3
is the ISP "disagreeing" about the proposed 0.0.0.0
and offering the real address instead, right?)
Jan
