[WORKAROUND] 17.1RC1 PPPOE loops attempting to re-connect

[stormy]

I've setup pppoe on one interface, nothing else is connected to the opn box, the pppoe succeeds only after a fresh reboot. As soon as clicking disconnect (or pulling network cable out), then clicking connect, and the session repeatdly fails to connect, for hours..

this is a sample log:

http://pastebin.com/bR48fySu

with ips replaced A.B.C.D (ip isp assigns the opn), and X.Y.Z.X (ip isp's gateway).

Any ideas?

[stormy]

I've setup pppoe on one interface, nothing else is connected to the opn box, the pppoe succeeds only after a fresh reboot. As soon as clicking disconnect (or pulling network cable out), then clicking connect, and the session repeatedly fails to connect, for hours.. rebooting the OPN box, and connection is made right away.

this is a sample log:

Code: [Select]

Jan 23 19:35:13 OPNsense ppp: [opt3_link0] PAP: using authname "stormy@isp"
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] PAP: sending REQUEST #1 len: 23
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: LayerUp
Jan 23 19:35:13 OPNsense ppp: caught fatal signal TERM
Jan 23 19:35:13 OPNsense ppp: [opt3] IFACE: Close event
Jan 23 19:35:13 OPNsense ppp: [opt3] IPCP: Close event
Jan 23 19:35:13 OPNsense ppp: [opt3] IPV6CP: Close event
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] PAP: rec'd ACK #1 len: 5
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: authorization successful
Jan 23 19:35:13 OPNsense ppp: Shutdown sequence in progress, BundJoin() denied
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] link did not validate in bundle
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: parameter negotiation failed
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: state change Opened --> Stopping
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: SendTerminateReq #3
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: LayerDown
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: rec'd Terminate Ack #3 (Stopping)
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: state change Stopping --> Stopped
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: LayerFinish
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] PPPoE: connection closed
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] Link: DOWN event
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] Link: giving up after 0 reconnection attempts
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: Close event
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: state change Stopped --> Closed
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: Down event
Jan 23 19:35:13 OPNsense ppp: [opt3_link0] LCP: state change Closed --> Initial
Jan 23 19:35:15 OPNsense ppp: [opt3] Bundle: Shutdown
Jan 23 19:35:15 OPNsense ppp: [opt3_link0] Link: Shutdown
Jan 23 19:35:15 OPNsense ppp: process 76950 terminated
Jan 23 19:35:15 OPNsense ppp: Multi-link PPP daemon for FreeBSD
Jan 23 19:35:15 OPNsense ppp:
Jan 23 19:35:15 OPNsense ppp: process 18525 started, version 5.8 (root@sensey64 02:26 17-Jan-2017)
Jan 23 19:35:15 OPNsense ppp: web: web is not running
Jan 23 19:35:15 OPNsense ppp: [opt3] Bundle: Interface ng0 created
Jan 23 19:35:15 OPNsense ppp: [opt3_link0] Link: OPEN event
Jan 23 19:35:15 OPNsense ppp: [opt3_link0] LCP: Open event
Jan 23 19:35:15 OPNsense ppp: [opt3_link0] LCP: state change Initial --> Starting
Jan 23 19:35:15 OPNsense ppp: [opt3_link0] LCP: LayerStart
Jan 23 19:35:15 OPNsense ppp: [opt3_link0] PPPoE: Connecting to ''
Jan 23 19:35:18 OPNsense ppp: PPPoE: rec'd ACNAME "182"
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] PPPoE: connection successful
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] Link: UP event
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: Up event
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: state change Starting --> Req-Sent
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: SendConfigReq #1
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   PROTOCOMP
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MAGICNUM 0x7049c571
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Request #55 (Req-Sent)
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   AUTHPROTO PAP
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MAGICNUM 0x66ad8bf6
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: SendConfigAck #55
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   AUTHPROTO PAP
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MAGICNUM 0x66ad8bf6
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: state change Req-Sent --> Ack-Sent
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   PROTOCOMP
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: SendConfigReq #2
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MAGICNUM 0x7049c571
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:18 OPNsense ppp: [opt3_link0]   MAGICNUM 0x7049c571
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: state change Ack-Sent --> Opened
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: auth: peer wants PAP, I want nothing
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] PAP: using authname "stormy@isp"
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] PAP: sending REQUEST #1 len: 23
Jan 23 19:35:18 OPNsense ppp: [opt3_link0] LCP: LayerUp
Jan 23 19:35:19 OPNsense ppp: [opt3_link0] PAP: rec'd ACK #1 len: 5
Jan 23 19:35:19 OPNsense ppp: [opt3_link0] LCP: authorization successful
Jan 23 19:35:19 OPNsense ppp: [opt3_link0] Link: Matched action 'bundle "opt3" ""'
Jan 23 19:35:19 OPNsense ppp: [opt3_link0] Link: Join bundle "opt3"
Jan 23 19:35:19 OPNsense ppp: [opt3] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: Open event
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: state change Initial --> Starting
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: LayerStart
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: Open event
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: state change Initial --> Starting
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: LayerStart
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: Up event
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: state change Starting --> Req-Sent
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: SendConfigReq #1
Jan 23 19:35:19 OPNsense ppp: [opt3]   IPADDR 0.0.0.0
Jan 23 19:35:19 OPNsense ppp: [opt3]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: Up event
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: state change Starting --> Req-Sent
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: SendConfigReq #1
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: rec'd Configure Reject #1 (Req-Sent)
Jan 23 19:35:19 OPNsense ppp: [opt3]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: SendConfigReq #2
Jan 23 19:35:19 OPNsense ppp: [opt3]   IPADDR 0.0.0.0
Jan 23 19:35:19 OPNsense ppp: [opt3_link0] LCP: rec'd Protocol Reject #115 (Opened)
Jan 23 19:35:19 OPNsense ppp: [opt3_link0] LCP: protocol IPV6CP was rejected
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: protocol was rejected by peer
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: state change Req-Sent --> Stopped
Jan 23 19:35:19 OPNsense ppp: [opt3] IPV6CP: LayerFinish
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: rec'd Configure Nak #2 (Req-Sent)
Jan 23 19:35:19 OPNsense ppp: [opt3]   IPADDR A.B.C.D
Jan 23 19:35:19 OPNsense ppp: [opt3]     A.B.C.D is OK
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: SendConfigReq #3
Jan 23 19:35:19 OPNsense ppp: [opt3]   IPADDR A.B.C.D
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: rec'd Configure Ack #3 (Req-Sent)
Jan 23 19:35:19 OPNsense ppp: [opt3]   IPADDR A.B.C.D
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: state change Req-Sent --> Ack-Rcvd
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: rec'd Configure Request #53 (Ack-Rcvd)
Jan 23 19:35:19 OPNsense ppp: [opt3]   IPADDR X.Y.Z.X
Jan 23 19:35:19 OPNsense ppp: [opt3]     X.Y.Z.X is OK
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: SendConfigAck #53
Jan 23 19:35:19 OPNsense ppp: [opt3]   IPADDR X.Y.Z.X
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: state change Ack-Rcvd --> Opened
Jan 23 19:35:19 OPNsense ppp: [opt3] IPCP: LayerUp
Jan 23 19:35:19 OPNsense ppp: [opt3]   A.B.C.D -> X.Y.Z.X
Jan 23 19:35:20 OPNsense ppp: [opt3] IFACE: Up event
Jan 23 19:35:20 OPNsense ppp: [opt3] IFACE: Rename interface ng0 to pppoe0
Jan 23 19:35:21 OPNsense ppp: caught fatal signal TERM
Jan 23 19:35:21 OPNsense ppp: [opt3] IFACE: Close event
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: Close event
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: state change Opened --> Closing
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: SendTerminateReq #4
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: LayerDown
Jan 23 19:35:21 OPNsense ppp: [opt3] IFACE: Delete route 0.0.0.0/0 X.Y.Z.X failed: No such process
Jan 23 19:35:21 OPNsense ppp: [opt3] IFACE: Down event
Jan 23 19:35:21 OPNsense ppp: [opt3] IFACE: Rename interface pppoe0 to pppoe0
Jan 23 19:35:21 OPNsense ppp: [opt3] IPV6CP: Close event
Jan 23 19:35:21 OPNsense ppp: [opt3] IPV6CP: state change Stopped --> Closed
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: rec'd Terminate Ack #4 (Closing)
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: state change Closing --> Closed
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: LayerFinish
Jan 23 19:35:21 OPNsense ppp: [opt3] Bundle: No NCPs left. Closing links...
Jan 23 19:35:21 OPNsense ppp: [opt3] Bundle: closing link "opt3_link0"...
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: rec'd Terminate Request #116 (Opened)
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: state change Opened --> Stopping
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] Link: Leave bundle "opt3"
Jan 23 19:35:21 OPNsense ppp: [opt3] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: Close event
Jan 23 19:35:21 OPNsense ppp: [opt3] IPV6CP: Close event
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: Down event
Jan 23 19:35:21 OPNsense ppp: [opt3] IPCP: state change Closed --> Initial
Jan 23 19:35:21 OPNsense ppp: [opt3] IPV6CP: Down event
Jan 23 19:35:21 OPNsense ppp: [opt3] IPV6CP: state change Closed --> Initial
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: SendTerminateAck #3
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: LayerDown
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] PPPoE: connection closed
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] Link: DOWN event
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] Link: giving up after 0 reconnection attempts
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: Close event
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: state change Stopping --> Closing
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: Down event
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: LayerFinish
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: state change Closing --> Initial
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] Link: CLOSE event
Jan 23 19:35:21 OPNsense ppp: [opt3_link0] LCP: Close event
Jan 23 19:35:23 OPNsense ppp: [opt3] Bundle: Shutdown
Jan 23 19:35:23 OPNsense ppp: [opt3_link0] Link: Shutdown
Jan 23 19:35:23 OPNsense ppp: process 18525 terminated
Jan 23 19:35:23 OPNsense ppp: Multi-link PPP daemon for FreeBSD
Jan 23 19:35:23 OPNsense ppp:
Jan 23 19:35:23 OPNsense ppp: process 53377 started, version 5.8 (root@sensey64 02:26 17-Jan-2017)
Jan 23 19:35:23 OPNsense ppp: web: web is not running
Jan 23 19:35:23 OPNsense ppp: [opt3] Bundle: Interface ng0 created
Jan 23 19:35:23 OPNsense ppp: [opt3_link0] Link: OPEN event
Jan 23 19:35:23 OPNsense ppp: [opt3_link0] LCP: Open event
Jan 23 19:35:23 OPNsense ppp: [opt3_link0] LCP: state change Initial --> Starting
Jan 23 19:35:23 OPNsense ppp: [opt3_link0] LCP: LayerStart
Jan 23 19:35:23 OPNsense ppp: [opt3_link0] PPPoE: Connecting to ''
Jan 23 19:35:26 OPNsense ppp: PPPoE: rec'd ACNAME "182"
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] PPPoE: connection successful
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] Link: UP event
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: Up event
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: state change Starting --> Req-Sent
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: SendConfigReq #1
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   PROTOCOMP
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MAGICNUM 0x4d140f5e
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Request #255 (Req-Sent)
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   AUTHPROTO PAP
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MAGICNUM 0x6e59c8ea
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: SendConfigAck #255
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   AUTHPROTO PAP
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MAGICNUM 0x6e59c8ea
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: state change Req-Sent --> Ack-Sent
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   PROTOCOMP
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: SendConfigReq #2
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MAGICNUM 0x4d140f5e
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:26 OPNsense ppp: [opt3_link0]   MAGICNUM 0x4d140f5e
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: state change Ack-Sent --> Opened
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: auth: peer wants PAP, I want nothing
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] PAP: using authname "stormy@isp"
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] PAP: sending REQUEST #1 len: 23
Jan 23 19:35:26 OPNsense ppp: [opt3_link0] LCP: LayerUp
Jan 23 19:35:26 OPNsense ppp: caught fatal signal TERM
Jan 23 19:35:26 OPNsense ppp: [opt3] IFACE: Close event
Jan 23 19:35:26 OPNsense ppp: [opt3] IPCP: Close event
Jan 23 19:35:26 OPNsense ppp: [opt3] IPV6CP: Close event
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] PAP: rec'd ACK #1 len: 5
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: authorization successful
Jan 23 19:35:27 OPNsense ppp: Shutdown sequence in progress, BundJoin() denied
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] link did not validate in bundle
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: parameter negotiation failed
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: state change Opened --> Stopping
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: SendTerminateReq #3
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: LayerDown
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: rec'd Terminate Ack #3 (Stopping)
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: state change Stopping --> Stopped
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: LayerFinish
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] PPPoE: connection closed
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] Link: DOWN event
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] Link: giving up after 0 reconnection attempts
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: Close event
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: state change Stopped --> Closed
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: Down event
Jan 23 19:35:27 OPNsense ppp: [opt3_link0] LCP: state change Closed --> Initial
Jan 23 19:35:28 OPNsense ppp: [opt3] Bundle: Shutdown
Jan 23 19:35:28 OPNsense ppp: [opt3_link0] Link: Shutdown
Jan 23 19:35:28 OPNsense ppp: process 53377 terminated
Jan 23 19:35:29 OPNsense ppp: Multi-link PPP daemon for FreeBSD
Jan 23 19:35:29 OPNsense ppp:
Jan 23 19:35:29 OPNsense ppp: process 4541 started, version 5.8 (root@sensey64 02:26 17-Jan-2017)
Jan 23 19:35:29 OPNsense ppp: web: web is not running
Jan 23 19:35:29 OPNsense ppp: [opt3] Bundle: Interface ng0 created
Jan 23 19:35:29 OPNsense ppp: [opt3_link0] Link: OPEN event
Jan 23 19:35:29 OPNsense ppp: [opt3_link0] LCP: Open event
Jan 23 19:35:29 OPNsense ppp: [opt3_link0] LCP: state change Initial --> Starting
Jan 23 19:35:29 OPNsense ppp: [opt3_link0] LCP: LayerStart
Jan 23 19:35:29 OPNsense ppp: [opt3_link0] PPPoE: Connecting to ''
Jan 23 19:35:31 OPNsense ppp: PPPoE: rec'd ACNAME "182"
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] PPPoE: connection successful
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] Link: UP event
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: Up event
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: state change Starting --> Req-Sent
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: SendConfigReq #1
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   PROTOCOMP
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MAGICNUM 0xe9aa940e
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Request #136 (Req-Sent)
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   AUTHPROTO PAP
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MAGICNUM 0x3da87eb5
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: SendConfigAck #136
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   AUTHPROTO PAP
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MAGICNUM 0x3da87eb5
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: state change Req-Sent --> Ack-Sent
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   PROTOCOMP
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: SendConfigReq #2
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MAGICNUM 0xe9aa940e
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MRU 1492
Jan 23 19:35:31 OPNsense ppp: [opt3_link0]   MAGICNUM 0xe9aa940e
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: state change Ack-Sent --> Opened
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] LCP: auth: peer wants PAP, I want nothing
Jan 23 19:35:31 OPNsense ppp: [opt3_link0] PAP: using authname "stormy@isp"
with ips replaced A.B.C.D (ip isp assigns the opn), and X.Y.Z.X (ip isp's gateway).

Any ideas?

[stormy]

Looking in /var/etc, found TWO mpd_opt*.conf files:

Code: [Select]

root@OPNsense:/var/etc # diff mpd_opt1.conf mpd_opt3.conf
9c9
<   create bundle static opt1
---
>   create bundle static opt3
11c11
<   set iface name pppoe1
---
>   set iface name pppoe0
19,20c19,20
<   create link static opt1_link0 pppoe
<   set link action bundle opt1
---
>   create link static opt3_link0 pppoe
>   set link action bundle opt3
31c31
<   set pppoe iface igb2
---
>   set pppoe iface igb3

the UI only shows ONE file (opt3/igb3), the other was deleted via the UI many hours ago..  removed it, still problem persisted, so removed all pppoe, and re-created again from the UI, still problem exists (now only one mpd_opt3.conf file exists).


Looking in /var/log/messages, seeing:

Code: [Select]

Jan 23 21:08:32 OPNsense configd.py: [f00082c9-2cc1-44a4-ac9f-a261270fd770] updating dyndns opt3
Jan 23 21:08:32 OPNsense configd.py: [68d909a7-0993-43bd-9db0-1828f2e97fca] Linkup stopping igb3
Jan 23 21:08:32 OPNsense opnsense: /usr/local/etc/rc.linkup: DEVD Ethernet detached event for opt3
Jan 23 21:08:34 OPNsense configd.py: [6f62cfcf-03bb-4a87-82d6-211113f4f245] Linkup starting igb3
Jan 23 21:08:35 OPNsense opnsense: /usr/local/etc/rc.linkup: DEVD Ethernet attached event for opt3
Jan 23 21:08:35 OPNsense opnsense: /usr/local/etc/rc.linkup: HOTPLUG: Configuring interface opt3
Jan 23 21:08:35 OPNsense opnsense: /usr/local/etc/rc.linkup: The command `/sbin/ifconfig -m 'pppoe0'' failed to execute ifconfig: interface pppoe0 does not exist
Jan 23 21:08:35 OPNsense opnsense: /usr/local/etc/rc.linkup: The command '/sbin/ifconfig 'pppoe0' inet6 -accept_rtadv' returned exit code '1', the output was 'ifconfig: interface pppoe0 does not exist'
Jan 23 21:08:35 OPNsense kernel: igb3: link state changed to DOWN
Jan 23 21:08:35 OPNsense kernel: ng0: changing name to 'pppoe0'
Jan 23 21:08:37 OPNsense kernel: igb3: link state changed to UP
Jan 23 21:08:37 OPNsense configd.py: [c7ad18c6-8f04-449f-a9cd-cd9f47934a3f] updating dyndns opt3
Jan 23 21:08:38 OPNsense configd.py: [20fb0f62-6d13-46cc-a292-147cdc696c88] Linkup stopping igb3
Jan 23 21:08:38 OPNsense opnsense: /usr/local/etc/rc.linkup: DEVD Ethernet detached event for opt3


the contents of mdp_opt3.conf appear to be correct:

Code: [Select]

root@OPNsense:/var/etc # cat mpd_opt3.conf
startup:
  # configure the console
  set console close
  # configure the web server
  set web close

default:
pppoeclient:
  create bundle static opt3
  set bundle enable ipv6cp
  set iface name pppoe0
  set iface route default
  set iface disable on-demand
  set iface idle 0
  set iface enable tcpmssfix
  set iface up-script /usr/local/sbin/ppp-linkup
  set iface down-script /usr/local/sbin/ppp-linkdown
  set ipcp ranges 0.0.0.0/0 0.0.0.0/0
  create link static opt3_link0 pppoe
  set link action bundle opt3
  set link disable multilink
  set link keep-alive 10 60
  set link max-redial 0
  set link disable chap pap
  set link accept chap pap eap
  set link disable incoming
  set link mtu 1492
  set auth authname "stormy@isp"
  set auth password mypass
  set pppoe service ""
  set pppoe iface igb3
        open


[stormy]

I've confirmed again, only the first ppp connection works after a fresh reboot. There after, any disconnect , even by button on the UI, the ppp connection cannot be made again..  I can see the mpd process running:

Code: [Select]

root   94850   0.7  0.1  42824  5996  -  Ss   21:56    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_opt3.conf -p /var


[stormy]

Thanks to solution from: https://forum.opnsense.org/index.php?topic=4334.0

managed to boot into 16.7, and pppoe has the exact same behavior there, it works only for the FIRST boot, thereafter, clicking the disconnect button (under interfaces/overview), OR pulling cable for 10sec causes the pppoe to go into an endless loop attempting to connect, and it can run like that for hours on end..

Using the exact same ADSL modem, and cable, i got 4 linksys running tomato/shibby/ddwrt, and the exact same CAT5 wire connected to these connects fine to pppoe using same ISP/credentials, and can disconnect and reconnect 4 times a minute without any issues, all works very fast and easy...

no clue how to debug such a thing..  but, it is not 17.1 related, something specific to my env i guess ..

[stormy]

Looking at the log inside the ADSL modem it shows that link goes UP/DOWN constantly, like so:

Code: [Select]

Jan  2 04:04:17 (none) daemon.crit kernel: eth2 Link UP 100 mbps full duplex  82
Jan  2 04:04:17 (none) daemon.info kernel: br0: port 3(eth2) entering forwarding state  92
Jan  2 04:04:21 (none) daemon.crit kernel: eth2 Link DOWN.  64
Jan  2 04:04:21 (none) daemon.info kernel: br0: port 3(eth2) entering disabled state  90
Jan  2 04:04:23 (none) daemon.crit kernel: eth2 Link UP 100 mbps full duplex  82
Jan  2 04:04:23 (none) daemon.info kernel: br0: port 3(eth2) entering forwarding state  92
Jan  2 04:04:27 (none) daemon.crit kernel: eth2 Link DOWN.  64
Jan  2 04:04:27 (none) daemon.info kernel: br0: port 3(eth2) entering disabled state  90
Jan  2 04:04:28 (none) daemon.crit kernel: eth2 Link UP 100 mbps full duplex  82
Jan  2 04:04:28 (none) daemon.info kernel: br0: port 3(eth2) entering forwarding state  92
Jan  2 04:04:32 (none) daemon.crit kernel: eth2 Link DOWN.  64
Jan  2 04:04:32 (none) daemon.info kernel: br0: port 3(eth2) entering disabled state  90
Jan  2 04:04:34 (none) daemon.crit kernel: eth2 Link UP 100 mbps full duplex  82
Jan  2 04:04:34 (none) daemon.info kernel: br0: port 3(eth2) entering forwarding state  92

Looking at the LEDs that is also confirmed, and also from ifconfig on the OPNS box:

one second the link appears like so:

Code: [Select]

igb3: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=4400b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,VLAN_HWTSO,TXCSUM_IPV6>
        ether 00:xx:yy:zz:aa:bb
        inet6 fe80::21a:70ff:fee1:d41a%igb3 prefixlen 64 scopeid 0x4
        inet 11.0.0.12 netmask 0xffffff00 broadcast 11.0.0.255
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
        media: Ethernet 100baseTX <full-duplex> (autoselect)
        status: no carrier

and the next second it is active:

Code: [Select]

igb3: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=4400b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,VLAN_HWTSO,TXCSUM_IPV6>
        ether 00:xx:yy:zz:aa:bb
        inet6 fe80::21a:70ff:fee1:d41a%igb3 prefixlen 64 scopeid 0x4
        inet 11.0.0.12 netmask 0xffffff00 broadcast 11.0.0.255
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
        media: Ethernet 100baseTX <full-duplex>
        status: active

is this normal? or a side-effect of the pppoe failing?

also, i've tried setting speed/duplex to auto or to 100Full as that's what the adsl modem can do.

Thanks for any ideas.

[stormy]

Sorry for the long post..

Here is more info, pretty much at a loss here..  This is client/PPPOE, it should work, have no clue what's going on here...   

Update thus far:

1) Same behavior in 16.7/17.1
2) Replaced CAT5 cable, same behavior of constant disconnection if UI is used to initiate the pppoe connection.

3) Get this! 
   - disable mpd5 in /usr/local/etc/inc/interfaces.inc  on line #1593 prevents UI from starting pppoe
   - REBOOT. so, no pppoe is started (expected on purpose)
   - run it MANUALLY, using mpd.sh which has:

/usr/local/sbin/mpd5 -k -d /var/etc -f mpd_wan.conf -p /var/run/pppoe_wan.pid -s ppp pppoeclient

connection is made *instantly*, output to screen appears as follows:

Code: [Select]

[wan] IPCP: rec'd Configure Nak #2 (Req-Sent)
[wan]   IPADDR x.y.z.x
[wan]     x.y.z.x is OK
[wan] IPCP: SendConfigReq #3
[wan]   IPADDR x.y.z.x
[wan] IPCP: rec'd Configure Ack #3 (Req-Sent)
[wan]   IPADDR x.y.z.x
[wan] IPCP: state change Req-Sent --> Ack-Rcvd
[wan] IPCP: rec'd Configure Request #52 (Ack-Rcvd)
[wan]   IPADDR a.b.c.d
[wan]     a.b.c.dis OK
[wan] IPCP: SendConfigAck #52
[wan]   IPADDR a.b.c.d
[wan] IPCP: state change Ack-Rcvd --> Opened
[wan] IPCP: LayerUp
[wan]   x.y.z.x -> a.b.c.d
[wan] IFACE: Up event
[wan] IFACE: Rename interface ng0 to pppoe1

a.b.c.d is isp assigned IP, and x.y.z.x is ISPGW.  the last line remains as-is, and nothing is further outputed, the connection can run like that for hours, no failures, no disconnections.

In addition, press ctrl-C, connection is terminated, now, re-run the mpd.sh, and connection is re-established instantly, with different IP.. again, last line is the "Rename interface..."

4) Re-ran the same test as #3 again with mpd5 disabled in interfaces.inc, and added the "-b" flag, to run cmd in background, and still there is success in repeated tests, no matter how many times I pkill mpd5 and re-run, the connection to ISP is made instantly, ip assigned and internet is working fine.

5) now.. comes the bad news

pkill all manually mpd5 processes, restore original interfaces.inc, with pppoe enabled, and REBOOT.

Connection to ISP is established with valid IP.

Now, go to UI, and press the "disconnect" button..

From that point on, there is NO WAY to make another pppoe connection, be it manual or via GUI.. the only thing that fixes it is REBOOTING the box again. 

In some cases, ps output showed TWO mpd5 processes, with parent pid of 1. for example:

Code: [Select]

root@OPNsense:/usr/local/etc/inc # ps xao pid,ppid,sid,comm | grep mpd
34498     1 34498 mpd5
40616     1 40616 mpd5

Maybe UI is restarting them or killing them too frequently?  when the UI runs mpd5 the pings on the interface go up to 2-3 SECONDS, as soon as it is stopped, they drop to 0.2 second:

Code: [Select]

64 bytes from 11.0.0.11: icmp_seq=45 ttl=64 time=4258.030 ms
64 bytes from 11.0.0.11: icmp_seq=47 ttl=64 time=2140.550 ms
64 bytes from 11.0.0.11: icmp_seq=48 ttl=64 time=1116.655 ms
64 bytes from 11.0.0.11: icmp_seq=49 ttl=64 time=0.493 ms
64 bytes from 11.0.0.11: icmp_seq=50 ttl=64 time=4360.046 ms
64 bytes from 11.0.0.11: icmp_seq=51 ttl=64 time=3348.250 ms
64 bytes from 11.0.0.11: icmp_seq=52 ttl=64 time=2333.019 ms
64 bytes from 11.0.0.11: icmp_seq=53 ttl=64 time=1303.352 ms
64 bytes from 11.0.0.11: icmp_seq=55 ttl=64 time=0.207 ms
64 bytes from 11.0.0.11: icmp_seq=56 ttl=64 time=0.262 ms
64 bytes from 11.0.0.11: icmp_seq=57 ttl=64 time=0.205 ms
64 bytes from 11.0.0.11: icmp_seq=58 ttl=64 time=0.286 ms
64 bytes from 11.0.0.11: icmp_seq=59 ttl=64 time=0.268 ms
64 bytes from 11.0.0.11: icmp_seq=60 ttl=64 time=0.173 ms

also, ps output shows pid of mpd5 changes very fast as it fails or gets a TERM signal.

6) Once this state is arrived, without a reboot, go and disable pppoe in interfaces.inc, made sure no mpd5 are lingering, now, ran the mpd5 manually, and pppoe connection shows as ESTABLISHED, an IP is given by the ISP, but for some reason, mpd5 is getting a TERM signal and all goes downhill:

notice the caught fatal signal TERM line in output below:

Code: [Select]

[wan] IPCP: rec'd Configure Ack #3 (Req-Sent)
[wan]   IPADDR v.x.y.z
[wan] IPCP: state change Req-Sent --> Ack-Rcvd
[wan] IPCP: rec'd Configure Request #83 (Ack-Rcvd)
[wan]   IPADDR a.b.c.d
[wan]     a.b.c.d is OK
[wan] IPCP: SendConfigAck #83
[wan]   IPADDR a.b.c.d
[wan] IPCP: state change Ack-Rcvd --> Opened
[wan] IPCP: LayerUp
[wan]   v.x.y.z -> a.b.c.d
[wan] IFACE: Up event
[wan] IFACE: Rename interface ng0 to pppoe1
[b]caught fatal signal TERM[/b]
[wan] IFACE: Close event
[wan] IPCP: Close event
[wan] IPCP: state change Opened --> Closing
[wan] IPCP: SendTerminateReq #4
[wan] IPCP: LayerDown
[wan] IFACE: Down event
[wan] IFACE: Rename interface pppoe1 to pppoe1
[wan] IPV6CP: Close event
[wan] IPV6CP: state change Stopped --> Closed
[wan] IPCP: rec'd Terminate Ack #4 (Closing)
[wan] IPCP: state change Closing --> Closed
[wan] IPCP: LayerFinish
[wan] Bundle: No NCPs left. Closing links...
[wan] Bundle: closing link "wan_link0"...
[wan_link0] LCP: rec'd Terminate Request #121 (Opened)
[wan_link0] LCP: state change Opened --> Stopping
[wan_link0] Link: Leave bundle "wan"

ran the same thing with ktrace, here is the ktrace output showing that SIGTERM:

Code: [Select]

       "<30>Jan 24 22:21:35 ppp: [wan_link0] LCP: LayerUp"
 27970 mpd5     RET   sendto 49/0x31
 27970 mpd5     CALL  write(0x1,0x487dc44c000,0x1a)
 27970 mpd5     GIO   fd 1 wrote 26 bytes
       "[wan_link0] LCP: LayerUp\r
       "
 27970 mpd5     RET   write 26/0x1a
 27970 mpd5     CALL  recvfrom(0x8,0x487dc66110e,0x10fa,0x80<MSG_DONTWAIT>,0x6dc102a4be10,0x6dc102a4be0c)
 27970 mpd5     RET   recvfrom -1 errno 35 Resource temporarily unavailable
 27970 mpd5     CALL  read(0x3,0x2ccec46ff70,0x1)
 27970 mpd5     GIO   fd 3 read 1 byte
       "\0"
 27970 mpd5     RET   read 1
 27970 mpd5     CALL  poll(0x487dc60e008,0xa,0x7d0)
 27970 mpd5     RET   poll -1 errno 4 Interrupted system call
 27970 mpd5     PSIG  SIGTERM caught handler=0x487db67dc60 mask=0x0 code=SI_USER
 27970 mpd5     CALL  sigprocmask(SIG_SETMASK,0x6dc102a4b9e4,0)
 27970 mpd5     RET   sigprocmask 0
 27970 mpd5     CALL  write(0xe,0x6dc102a4b5dc,0x1)
 27970 mpd5     GIO   fd 14 wrote 1 byte
       0x0000 0f                                                                          |.|

 27970 mpd5     RET   write 1
 27970 mpd5     CALL  sigreturn(0x6dc102a4b610)
 27970 mpd5     RET   sigreturn JUSTRETURN
 27970 mpd5     CALL  poll(0x487dc60e008,0xa,0x793)
 27970 mpd5     RET   poll 1
 27970 mpd5     CALL  write(0x4,0x2ccec46ff70,0x1)
 27970 mpd5     GIO   fd 4 wrote 1 byte
       "\0"
 27970 mpd5     RET   write 1
 27970 mpd5     CALL  read(0xd,0x6dc102a4be37,0x1)
 27970 mpd5     GIO   fd 13 read 1 byte
       0x0000 0f                                                                          |.|

 27970 mpd5     RET   read 1
 27970 mpd5     CALL  sendto(0x5,0x6dc102a4ac70,0x31,0,0,0)
 27970 mpd5     GIO   fd 5 wrote 49 bytes
       "<30>Jan 24 22:21:35 ppp: caught fatal signal TERM"
 27970 mpd5     RET   sendto 49/0x31
 27970 mpd5     CALL  write(0x1,0x487dc44c000,0x1a)
 27970 mpd5     GIO   fd 1 wrote 26 bytes
       "caught fatal signal TERM\r
       "
 27970 mpd5     RET   write 26/0x1a
 27970 mpd5     CALL  sigprocmask(SIG_SETMASK,0x487db686bb0,0x6dc102a4b9a8)
 27970 mpd5     RET   sigprocmask 0
From this point on, there is no way to re-establish a pppoe, and a reboot resolves it.

To summarize:

1) PPPOE always works after a fresh reboot.

2) If UI is used to disconnect/reconnect, or cable is pulled or any other of network outage, and opnsense/UI restarts the pppoe, then it gets into a wedged state, and constantly forks mpd5 processes, only way out of it is a REBOOT.

3) If mpd5 is disabled in interfaces.inc, then mpd5 can run manually as many times as desired, and connects just fine, gets IP and internet is working, press ctrl-c as many times, and re-start manually all connects OK.

Any ideas welcomed.

Stormy.

[stormy]

Thanks to suggestions on the chat, modified this in intrefaces.inc:

Code: [Select]

    /* fire up mpd */
    // Killbypid("/var/run/" . escapeshellarg($ppp['type']) . "_{$interface}.pid", 'TERM', true);  // STORMY
    killbyname('mpd5');
    file_put_contents("/tmp/Sleeping_10", '');
    sleep(10);
    @unlink("/tmp/Sleeping_10");
    mwexec_bg("/usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_{$interface}.conf -p /var/run/" .
        escapeshellarg($ppp['type']) . "_{$interface}.pid -s ppp " . escapeshellarg($ppp['type']) . "client");

then ping shows connection is made each time, but mpd5 is getting a TERM signal:

Code: [Select]

ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
64 bytes from 8.8.8.8: icmp_seq=13 ttl=41 time=85.545 ms
64 bytes from 8.8.8.8: icmp_seq=14 ttl=41 time=84.778 ms
64 bytes from 8.8.8.8: icmp_seq=15 ttl=41 time=85.314 ms
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to host
64 bytes from 8.8.8.8: icmp_seq=29 ttl=41 time=87.857 ms
64 bytes from 8.8.8.8: icmp_seq=30 ttl=41 time=87.662 ms
64 bytes from 8.8.8.8: icmp_seq=31 ttl=41 time=87.687 ms
ping: sendto: No route to host
ping: sendto: No route to host
ping: sendto: No route to hos
Using the kill by pid (first line above), and the issue is worse:

running this monitor loop:

Code: [Select]

#!/bin/csh
while ( 0 < 1 )
  ls -l /tmp/Sleep*
  ps aux |grep mpd5|grep -v grep
  sleep 1
end

output when running:

Code: [Select]

root@OPNsense:/tmp # ./mon.sh
ls: No match.
ls: No match.
ls: No match.
ls: No match.
ls: No match.
ls: No match.
ls: No match.
ls: No match.
ls: No match.
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
-rw-r--r--  1 root  wheel  0 Jan 25 11:11 /tmp/Sleeping_10
ls: No match.
root   66845   0.0  0.1  44872  6076  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
ls: No match.
root   66845   0.0  0.1  44872  6616  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
ls: No match.
root   66845   0.0  0.1  44872  6616  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
ls: No match.
root   60752   0.0  0.1  42692  5144  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
root   66845   0.0  0.1  44872  6624  -  Ss   11:11    0:00.01 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
ls: No match.
root   60752   0.0  0.1  42692  5144  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
root   66845   0.0  0.1  44872  6624  -  Ss   11:11    0:00.01 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
ls: No match.
root   60752   0.0  0.1  42692  5144  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
-rw-r-----  1 root  wheel  0 Jan 25 11:12 /tmp/Sleeping_10
root   60752   0.0  0.1  44872  6072  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
-rw-r-----  1 root  wheel  0 Jan 25 11:12 /tmp/Sleeping_10
root   60752   0.0  0.1  44872  6072  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
-rw-r-----  1 root  wheel  0 Jan 25 11:12 /tmp/Sleeping_10
root   60752   0.0  0.1  44872  6072  -  Ss   11:11    0:00.00 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
-rw-r-----  1 root  wheel  0 Jan 25 11:12 /tmp/Sleeping_10
root   60752   0.0  0.1  44872  6612  -  Ss   11:11    0:00.01 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
-rw-r-----  1 root  wheel  0 Jan 25 11:12 /tmp/Sleeping_10
root   60752   0.0  0.1  44872  6612  -  Ss   11:11    0:00.01 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
-rw-r-----  1 root  wheel  0 Jan 25 11:12 /tmp/Sleeping_10
root   60752   0.0  0.1  44872  6612  -  Ss   11:11    0:00.01 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/
-rw-r-----  1 root  wheel  0 Jan 25 11:12 /tmp/Sleeping_10
root   60752   0.0  0.1  44872  6612  -  Ss   11:11    0:00.01 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/

clearly showing TWO mpd5 running, as well as a running process yet the Sleeping_10 file is there? how is this possible??

Only thing that amazes me, how come I'm the only one who hits this ??

[stormy]

After re-imaging the box several times, into 16.7 and 17.1RC1, it kept reproducing, so this time reimaged, and changed NO option at all, just setup the pppoe. and it worked fine.

Went through list of things changed before, and one was the MAC on the pppoe port.

Added it to the WAN interface, and IMMEDIATELY (after apply changes in ui), the setup became unstable, with 2 mpd running, and internet lost and disconnected constantly.  Removed the MAC, apply, and it becomes stable again..

so, for now, do not setup MAC on the WAN interface if PPPOE is used.

[franco]

Tracking this via https://github.com/opnsense/core/issues/1352 now.

Thanks so far, quite the adventure you went through to pin it down.


Cheers,
Franco

[stormy]

I hope that is the real issue, still looking for others to confirm independently.. 

[blubern]

Hi,

we have something similarly .
https://forum.opnsense.org/index.php?topic=4884.msg19460#msg19460

The only case when PPPOE is stable is after a Reboot. Currently i rebooting the Box two times per day via a cron job. But i diden't set a mac address. So the Mac address is empty.

One colleague from germany has also the same issue. after a down from the WAN interface the PPPOE Connection get etablished and then after some time 1-8 minutes we will have a reconnect and that in a loop .
The only thing what will help is a reboot.

How can i do some tracing? Witch logs do you need to get the details of the issue?#

Best Regards
Blubern

[avvid]

Only thing that amazes me, how come I'm the only one who hits this ??

Your not, had the exact same issues, although amplified with MLPPP (multiple PPPoE connections).  I unfortunately had to go back to pfsense, but eagerly waiting for someone to really look at the whole PPPoE issues so I can change back.

[blubern]

Hi,

i setup my opnsense complete new.
Step by Step and i always verify after a step if pppoe is working.

After i setup a OpenVPN server on the WAN interface i got this issue with pppoe.
When i delete the OpenVPN server pppoe works normal.

Somebody and idea what is wrong with pppoe and OpenVPN?

[stormy]

I'm original poster, and running VPN boxes (phone and h/w vpn box), and in many cases the pppoe connection drops several times during the day even though no issue is reported by the ISP.  it looks like this in ppp.log:

Code: [Select]

Apr 25 19:44:30 OPNsense ppp: [wan] IPCP: LayerUp
Apr 25 19:44:30 OPNsense ppp: [wan]   a.b.c.d -> x.y.z.a
Apr 25 19:44:36 OPNsense ppp: [wan] IFACE: Up event
Apr 25 19:44:36 OPNsense ppp: [wan] IFACE: Rename interface ng0 to pppoe0
Apr 25 20:00:54 OPNsense ppp: caught fatal signal TERM
Apr 25 20:00:54 OPNsense ppp: [wan] IFACE: Close event
Apr 25 20:00:54 OPNsense ppp: [wan] IPCP: Close event
Apr 25 20:00:54 OPNsense ppp: [wan] IPCP: state change Opened --> Closing
Apr 25 20:00:54 OPNsense ppp: [wan] IPCP: SendTerminateReq #4
Apr 25 20:00:54 OPNsense ppp: [wan] IPCP: LayerDown
Apr 25 20:00:54 OPNsense ppp: [wan] IFACE: Down event
Apr 25 20:00:54 OPNsense ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0
Apr 25 20:00:54 OPNsense ppp: [wan] IPV6CP: Close event
Apr 25 20:00:54 OPNsense ppp: [wan] IPV6CP: state change Stopped --> Closed
Apr 25 20:00:57 OPNsense ppp: [wan] Bundle: Shutdown
Apr 25 20:00:57 OPNsense ppp: [wan_link0] Link: Shutdown
Apr 25 20:00:57 OPNsense ppp: process 29308 terminated
Apr 25 20:00:57 OPNsense ppp: Multi-link PPP daemon for FreeBSD
Apr 25 20:00:57 OPNsense ppp:
Apr 25 20:00:57 OPNsense ppp: process 76769 started, version 5.8 (root@sensey64 02:26 17-Jan-2017)

The question is why this SIG TERM is taking pace on mpd5 process?

Apr 25 20:00:54 OPNsense ppp: caught fatal signal TERM

Any ideas welcomed, I do not have any MAC cloning...