PPPoE client disconnects from ISP's PPPoE server

krystianpe · Thu Feb 09, 2023 1:13 am

Hi, my PPPoE client on hAP ac2 (RouterOS 7.7) keeps disconnecting from ISP's PPPoE server. I do not see any Term requests in logs.
The session is established and then after couple of EchoReq/Rep it disconnects. Usually around id=0x76. Is it something on ISP's side then?

PPPoE settings:

name="pppoe-ostnet2" max-mtu=1500 max-mru=auto mrru=disabled interface=wan user="*****" password="*****" profile=default keepalive-timeout=60 service-name="" ac-name="" add-default-route=yes default-route-distance=1 dial-on-demand=no use-peer-dns=no allow=pap,chap,mschap1,mschap2

Logs:

 23:55:04 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x73
 23:55:04 pppoe,ppp,debug,packet     <magic 0x9ee24fb5>
 23:55:04 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoRep id=0x73
 23:55:04 pppoe,ppp,debug,packet     <magic 0x586c2b62>
 23:55:19 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x74
 23:55:19 pppoe,ppp,debug,packet     <magic 0x9ee24fb5>
 23:55:19 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoRep id=0x74
 23:55:19 pppoe,ppp,debug,packet     <magic 0x586c2b62>
 23:55:34 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x75
 23:55:34 pppoe,ppp,debug,packet     <magic 0x9ee24fb5>
 23:55:34 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoRep id=0x75
 23:55:34 pppoe,ppp,debug,packet     <magic 0x586c2b62>
 23:55:49 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x76
 23:55:49 pppoe,ppp,debug,packet     <magic 0x9ee24fb5>
 23:55:49 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoRep id=0x76
 23:55:49 pppoe,ppp,debug,packet     <magic 0x586c2b62>
 23:56:04 interface,info wan link down
 23:56:04 pppoe,debug wan: terminating sessions: interface state changed
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: LCP lowerdown
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: LCP closed
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: CCP lowerdown
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: BCP lowerdown
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: BCP down event in starting state
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: IPCP lowerdown
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: IPCP closed
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: IPV6CP lowerdown
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: IPV6CP down event in starting state
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: MPLSCP lowerdown
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: CCP close
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: BCP close
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: IPCP close
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: IPV6CP close
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: MPLSCP close
 23:56:04 pppoe,ppp,info pppoe-ostnet2: terminating... - disconnected
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: LCP lowerdown
 23:56:04 pppoe,ppp,debug pppoe-ostnet2: LCP down event in starting state
 23:56:04 pppoe,ppp,info pppoe-ostnet2: disconnected
 23:56:04 pppoe,ppp,info pppoe-ostnet2: initializing...
 23:56:04 pppoe,ppp,info pppoe-ostnet2: connecting...
 23:56:08 netwatch,info event down [ type: simple, host: 8.8.8.8 ]
 23:56:15 pppoe,ppp,debug pppoe-ostnet2: CCP close
 23:56:15 pppoe,ppp,debug pppoe-ostnet2: BCP close
 23:56:15 pppoe,ppp,debug pppoe-ostnet2: IPCP close
 23:56:15 pppoe,ppp,debug pppoe-ostnet2: IPV6CP close
 23:56:15 pppoe,ppp,debug pppoe-ostnet2: MPLSCP close
 23:56:15 pppoe,ppp,info pppoe-ostnet2: terminating... - disconnected
 23:56:15 pppoe,ppp,debug pppoe-ostnet2: LCP lowerdown
 23:56:15 pppoe,ppp,debug pppoe-ostnet2: LCP down event in starting state
 23:56:15 pppoe,ppp,info pppoe-ostnet2: disconnected
 23:56:15 pppoe,ppp,info pppoe-ostnet2: initializing...
 23:56:15 pppoe,ppp,info pppoe-ostnet2: connecting...
 23:56:25 pppoe,ppp,debug pppoe-ostnet2: CCP close
 23:56:25 pppoe,ppp,debug pppoe-ostnet2: BCP close
 23:56:25 pppoe,ppp,debug pppoe-ostnet2: IPCP close
 23:56:25 pppoe,ppp,debug pppoe-ostnet2: IPV6CP close
 23:56:25 pppoe,ppp,debug pppoe-ostnet2: MPLSCP close
 23:56:25 pppoe,ppp,info pppoe-ostnet2: terminating... - disconnected
 23:56:25 pppoe,ppp,debug pppoe-ostnet2: LCP lowerdown
 23:56:25 pppoe,ppp,debug pppoe-ostnet2: LCP down event in starting state
 23:56:25 pppoe,ppp,info pppoe-ostnet2: disconnected
 23:56:25 pppoe,ppp,info pppoe-ostnet2: initializing...
 23:56:25 pppoe,ppp,info pppoe-ostnet2: connecting...
 23:56:29 interface,info wan link up (speed 1G, full duplex)
 23:56:29 interface,info wan detect UNKNOWN
 23:56:29 pppoe,debug,packet wan: sent PADI to FF:FF:FF:FF:FF:FF
 23:56:29 pppoe,debug,packet     session-id=0x0000
 23:56:29 pppoe,debug,packet     host-uniq=0x690613
 23:56:29 pppoe,debug,packet     service-name=
 23:56:29 pppoe,debug,packet     ppp-max-payload=1492
 23:56:30 pppoe,debug,packet wan: sent PADI to FF:FF:FF:FF:FF:FF
 23:56:30 pppoe,debug,packet     session-id=0x0000
 23:56:30 pppoe,debug,packet     host-uniq=0x690613
 23:56:30 pppoe,debug,packet     service-name=
 23:56:30 pppoe,debug,packet     ppp-max-payload=1492
 23:56:31 pppoe,debug,packet wan: sent PADI to FF:FF:FF:FF:FF:FF
 23:56:31 pppoe,debug,packet     session-id=0x0000
 23:56:31 pppoe,debug,packet     host-uniq=0x690613
 23:56:31 pppoe,debug,packet     service-name=
 23:56:31 pppoe,debug,packet     ppp-max-payload=1492
 23:56:32 pppoe,debug,packet wan: sent PADI to FF:FF:FF:FF:FF:FF
 23:56:32 pppoe,debug,packet     session-id=0x0000
 23:56:32 pppoe,debug,packet     host-uniq=0x690613
 23:56:32 pppoe,debug,packet     service-name=
 23:56:32 pppoe,debug,packet     ppp-max-payload=1492
 23:56:33 pppoe,debug,packet wan: sent PADI to FF:FF:FF:FF:FF:FF
 23:56:33 pppoe,debug,packet     session-id=0x0000
 23:56:33 pppoe,debug,packet     host-uniq=0x690613
 23:56:33 pppoe,debug,packet     service-name=
 23:56:33 pppoe,debug,packet     ppp-max-payload=1492
 23:56:33 pppoe,debug,packet wan: rcvd PADO from C4:A4:02:37:75:2A
 23:56:33 pppoe,debug,packet     session-id=0x0000
 23:56:33 pppoe,debug,packet     host-uniq=0x690613
 23:56:33 pppoe,debug,packet     service-name=
 23:56:33 pppoe,debug,packet     ppp-max-payload=1492
 23:56:33 pppoe,debug,packet     ac-name=ostbras
 23:56:33 pppoe,debug,packet wan: sent PADR to C4:A4:02:37:75:2A
 23:56:33 pppoe,debug,packet     session-id=0x0000
 23:56:33 pppoe,debug,packet     host-uniq=0x690614
 23:56:33 pppoe,debug,packet     service-name=
 23:56:33 pppoe,debug,packet     ppp-max-payload=1492
 23:56:33 pppoe,debug,packet wan: rcvd PADT from C4:A4:02:37:75:2A
 23:56:33 pppoe,debug,packet     session-id=0x4e9e
 23:56:35 interface,info wan detect WAN
 23:56:36 pppoe,debug,packet wan: sent PADR to C4:A4:02:37:75:2A
 23:56:36 pppoe,debug,packet     session-id=0x0000
 23:56:36 pppoe,debug,packet     host-uniq=0x690615
 23:56:36 pppoe,debug,packet     service-name=
 23:56:36 pppoe,debug,packet     ppp-max-payload=1492
 23:56:36 pppoe,debug,packet wan: rcvd PADS from C4:A4:02:37:75:2A
 23:56:36 pppoe,debug,packet     session-id=0x2728
 23:56:36 pppoe,debug,packet     host-uniq=0x690615
 23:56:36 pppoe,debug,packet     service-name=
 23:56:36 pppoe,debug,packet     ppp-max-payload=1492
 23:56:36 pppoe,ppp,debug pppoe-ostnet2: LCP lowerup
 23:56:36 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP ConfReq id=0x53
 23:56:36 pppoe,ppp,debug,packet    <mru 1492>
 23:56:36 pppoe,ppp,debug,packet    <magic 0x54a6435d>
 23:56:36 pppoe,ppp,debug pppoe-ostnet2: LCP open
 23:56:36 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP ConfAck id=0x53
 23:56:36 pppoe,ppp,debug,packet    <mru 1492>
 23:56:36 pppoe,ppp,debug,packet    <magic 0x54a6435d>
 23:56:37 pppoe,ppp,debug pppoe-ostnet2: LCP timer
 23:56:37 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP ConfReq id=0x54
 23:56:37 pppoe,ppp,debug,packet    <mru 1492>
 23:56:37 pppoe,ppp,debug,packet    <magic 0x54a6435d>
 23:56:37 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP ConfAck id=0x54
 23:56:37 pppoe,ppp,debug,packet    <mru 1492>
 23:56:37 pppoe,ppp,debug,packet    <magic 0x54a6435d>
 23:56:38 pppoe,ppp,debug pppoe-ostnet2: LCP timer
 23:56:38 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP ConfReq id=0x55
 23:56:38 pppoe,ppp,debug,packet    <mru 1492>
 23:56:38 pppoe,ppp,debug,packet    <magic 0x54a6435d>
 23:56:38 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP ConfAck id=0x55
 23:56:38 pppoe,ppp,debug,packet    <mru 1492>
 23:56:38 pppoe,ppp,debug,packet    <magic 0x54a6435d>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP ConfReq id=0x2
 23:56:39 pppoe,ppp,debug,packet    <mru 1492>
 23:56:39 pppoe,ppp,debug,packet    <magic 0xf4e85ca9>
 23:56:39 pppoe,ppp,debug,packet    <auth  chap>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP ConfAck id=0x2
 23:56:39 pppoe,ppp,debug,packet    <mru 1492>
 23:56:39 pppoe,ppp,debug,packet    <magic 0xf4e85ca9>
 23:56:39 pppoe,ppp,debug,packet    <auth  chap>
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: LCP opened
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd CHAP Challenge id=0x1
 23:56:39 pppoe,ppp,debug,packet     <challenge len=16>
 23:56:39 pppoe,ppp,debug,packet     <name Huawei>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent CHAP Response id=0x1
 23:56:39 pppoe,ppp,debug,packet     <response len=16>
 23:56:39 pppoe,ppp,debug,packet     <name *****>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd CHAP Success id=0x1
 23:56:39 pppoe,ppp,debug,packet     Authentication success,Welcome!
 23:56:39 pppoe,ppp,info pppoe-ostnet2: authenticated
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: IPCP lowerup
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: IPCP open
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent IPCP ConfReq id=0x2b
 23:56:39 pppoe,ppp,debug,packet     <addr 0.0.0.0>
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: IPV6CP open
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: MPLSCP lowerup
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: MPLSCP open
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent MPLSCP ConfReq id=0x16
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: BCP open
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: CCP lowerup
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: CCP open
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd IPCP ConfReq id=0x1
 23:56:39 pppoe,ppp,debug,packet     <addr 62.133.143.1>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent IPCP ConfAck id=0x1
 23:56:39 pppoe,ppp,debug,packet     <addr 62.133.143.1>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoReq id=0x0
 23:56:39 pppoe,ppp,debug,packet     <magic 0x54a6435d>
 23:56:39 pppoe,ppp,debug,packet     <data len=1484>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd IPV6CP ConfReq id=0x1
 23:56:39 pppoe,ppp,debug,packet     <interface-identifier c6a4:2ff:fe37:752a>
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: received unsupported protocol 0x8057
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP ProtRej id=0x56
 23:56:39 pppoe,ppp,debug,packet      80 57 01 01 00 0e 01 0a c6 a4 02 ff fe 37 75 2a
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP ProtRej id=0x3
 23:56:39 pppoe,ppp,debug,packet      82 81
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd IPCP ConfNak id=0x2b
 23:56:39 pppoe,ppp,debug,packet     <addr *****>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: sent IPCP ConfReq id=0x2c
 23:56:39 pppoe,ppp,debug,packet     <addr *****>
 23:56:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd IPCP ConfAck id=0x2c
 23:56:39 pppoe,ppp,debug,packet     <addr *****>
 23:56:39 pppoe,ppp,debug pppoe-ostnet2: IPCP opened
 23:56:39 pppoe,ppp,info pppoe-ostnet2: connected
 23:56:39 interface,info pppoe-ostnet2 detect UNKNOWN
 23:56:40 pppoe,ppp,debug pppoe-ostnet2: LCP missed echo reply
 23:56:40 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoReq id=0x1
 23:56:40 pppoe,ppp,debug,packet     <magic 0x54a6435d>
 23:56:40 pppoe,ppp,debug,packet     <data len=1484>
 23:56:40 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoRep id=0x1
 23:56:40 pppoe,ppp,debug,packet     <magic 0xf4e85ca9>
 23:56:40 pppoe,ppp,debug,packet     <data len=1484>
 23:56:45 interface,info pppoe-ostnet2 detect INTERNET
 23:56:54 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x1
 23:56:54 pppoe,ppp,debug,packet     <magic 0xf4e85ca9>
 23:56:54 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoRep id=0x1
 23:56:54 pppoe,ppp,debug,packet     <magic 0x54a6435d>
 23:57:08 netwatch,info event up [ type: simple, host: 8.8.8.8 ]
 23:57:09 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x2
 23:57:09 pppoe,ppp,debug,packet     <magic 0xf4e85ca9>
 23:57:09 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoRep id=0x2
 23:57:09 pppoe,ppp,debug,packet     <magic 0x54a6435d>
 23:57:24 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x3
 23:57:24 pppoe,ppp,debug,packet     <magic 0xf4e85ca9>
 23:57:24 pppoe,ppp,debug,packet  pppoe-ostnet2: sent LCP EchoRep id=0x3
 23:57:24 pppoe,ppp,debug,packet     <magic 0x54a6435d>
 23:57:39 pppoe,ppp,debug,packet  pppoe-ostnet2: rcvd LCP EchoReq id=0x4

matd · Fri Feb 10, 2023 8:32 pm

23:56:04 interface,info wan link down
23:56:04 pppoe,debug wan: terminating sessions: interface state changed
23:56:04 pppoe,ppp,debug pppoe-ostnet2: LCP lowerdown
23:56:04 pppoe,ppp,debug pppoe-ostnet2: LCP closed

Hi, from your log it seems that it's your wan ethernet interface, that went down, so it turns down also pppoe-client interface that is bind on them.
Maybe check your ethernet cabling or device you are connected into.

PPPoE client disconnects from ISP's PPPoE server

PPPoE client disconnects from ISP's PPPoE server

Re: PPPoE client disconnects from ISP's PPPoE server

Who is online