Project

General

Profile

Actions
Copy link

Feature #1811

closed

Monitor PPP for connections stuck in "initial" state

Added by Ross Williamson over 13 years ago. Updated over 8 years ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Category:
Interfaces
Target version:
-
Start date:
08/21/2011
Due date:
% Done:

0%

Estimated time:
Plus Target Version:
Release Notes:

Description

I've been trying to help debug an issue with dynamic DNS updates on 3G connections (1545) but keep getting hampered by the 3G connection getting stuck in the PPP "Initial" state. I don't believe this is a bug in pfsense but it would be fantastic if PPP connections could be monitored for connections stuck in this state and reset them.

Example log:
(PPP connection has been running for a while, and the ISP has obviously decided to force an IP change)
Aug 22 01:17:37 janus ppp: [opt2_link0] LCP: rec'd Terminate Request #64 (Opened)
Aug 22 01:17:37 janus ppp: [opt2_link0] LCP: state change Opened --> Stopping
Aug 22 01:17:37 janus ppp: [opt2_link0] Link: Leave bundle "opt2"
Aug 22 01:17:37 janus ppp: [opt2] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 22 01:17:37 janus ppp: [opt2] IPCP: Close event
Aug 22 01:17:37 janus ppp: [opt2] IPCP: state change Opened --> Closing
Aug 22 01:17:37 janus ppp: [opt2] IPCP: SendTerminateReq #12
Aug 22 01:17:37 janus ppp: [opt2] IPCP: LayerDown
Aug 22 01:17:38 janus ppp: [opt2] IFACE: Down event
Aug 22 01:17:38 janus ppp: [opt2] IPCP: Down event
Aug 22 01:17:38 janus ppp: [opt2] IPCP: LayerFinish
Aug 22 01:17:38 janus ppp: [opt2] Bundle: No NCPs left. Closing links...
Aug 22 01:17:38 janus ppp: [opt2] IPCP: state change Closing --> Initial
Aug 22 01:17:38 janus ppp: [opt2_link0] LCP: SendTerminateAck #4
Aug 22 01:17:38 janus ppp: [opt2_link0] LCP: LayerDown
Aug 22 01:17:40 janus ppp: [opt2_link0] LCP: state change Stopping --> Stopped
Aug 22 01:17:40 janus ppp: [opt2_link0] LCP: LayerFinish
Aug 22 01:17:40 janus ppp: [opt2_link0] Link: DOWN event
Aug 22 01:17:40 janus ppp: [opt2_link0] LCP: Down event
Aug 22 01:17:40 janus ppp: [opt2_link0] LCP: state change Stopped --> Starting
Aug 22 01:17:40 janus ppp: [opt2_link0] LCP: LayerStart
Aug 22 01:17:40 janus ppp: [opt2_link0] Link: reconnection attempt 1 in 1 seconds
Aug 22 01:17:41 janus ppp: [opt2_link0] Link: reconnection attempt 1
Aug 22 01:17:43 janus ppp: [opt2_link0] chat: Detected Hayes compatible modem.
Aug 22 01:17:43 janus ppp: [opt2_link0] chat: Dialing server at *99#...
Aug 22 01:17:43 janus ppp: [opt2_link0] chat: Connected at an unknown speed.
Aug 22 01:17:43 janus ppp: [opt2_link0] MODEM: chat script succeeded
Aug 22 01:17:43 janus ppp: [opt2_link0] Link: UP event
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: Up event
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: state change Starting --> Req-Sent
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: SendConfigReq #5
Aug 22 01:17:43 janus ppp: [opt2_link0] ACFCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] PROTOCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] ACCMAP 0x000a0000
Aug 22 01:17:43 janus ppp: [opt2_link0] MRU 1500
Aug 22 01:17:43 janus ppp: [opt2_link0] MAGICNUM f2bb8ec0
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: rec'd Configure Request #65 (Req-Sent)
Aug 22 01:17:43 janus ppp: [opt2_link0] ACCMAP 0x00000000
Aug 22 01:17:43 janus ppp: [opt2_link0] AUTHPROTO CHAP MD5
Aug 22 01:17:43 janus ppp: [opt2_link0] MAGICNUM 5c5a2b64
Aug 22 01:17:43 janus ppp: [opt2_link0] PROTOCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] ACFCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: SendConfigAck #65
Aug 22 01:17:43 janus ppp: [opt2_link0] ACCMAP 0x00000000
Aug 22 01:17:43 janus ppp: [opt2_link0] AUTHPROTO CHAP MD5
Aug 22 01:17:43 janus ppp: [opt2_link0] MAGICNUM 5c5a2b64
Aug 22 01:17:43 janus ppp: [opt2_link0] PROTOCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] ACFCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: state change Req-Sent --> Ack-Sent
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: rec'd Configure Ack #5 (Ack-Sent)
Aug 22 01:17:43 janus ppp: [opt2_link0] ACFCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] PROTOCOMP
Aug 22 01:17:43 janus ppp: [opt2_link0] ACCMAP 0x000a0000
Aug 22 01:17:43 janus ppp: [opt2_link0] MRU 1500
Aug 22 01:17:43 janus ppp: [opt2_link0] MAGICNUM f2bb8ec0
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: state change Ack-Sent --> Opened
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: auth: peer wants CHAP, I want nothing
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: LayerUp
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: rec'd Discard Request #66 (Opened)
Aug 22 01:17:43 janus ppp: [opt2_link0] CHAP: rec'd CHALLENGE #1 len: 35
Aug 22 01:17:43 janus ppp: [opt2_link0] Name: "UMTS_CHAP_SRVR"
Aug 22 01:17:43 janus ppp: [opt2_link0] CHAP: Using authname "user"
Aug 22 01:17:43 janus ppp: [opt2_link0] CHAP: sending RESPONSE #1 len: 25
Aug 22 01:17:43 janus ppp: [opt2_link0] CHAP: rec'd SUCCESS #1 len: 4
Aug 22 01:17:43 janus ppp: [opt2_link0] LCP: authorization successful
Aug 22 01:17:43 janus ppp: [opt2_link0] Link: Matched action 'bundle "opt2" ""'
Aug 22 01:17:43 janus ppp: [opt2_link0] Link: Join bundle "opt2"
Aug 22 01:17:43 janus ppp: [opt2] Bundle: Status update: up 1 link, total bandwidth 28800 bps
Aug 22 01:17:43 janus ppp: [opt2] IPCP: Open event
Aug 22 01:17:43 janus ppp: [opt2] IPCP: state change Initial --> Starting
Aug 22 01:17:43 janus ppp: [opt2] IPCP: LayerStart
Aug 22 01:17:43 janus ppp: [opt2] IPCP: Up event
Aug 22 01:17:43 janus ppp: [opt2] IPCP: state change Starting --> Req-Sent
Aug 22 01:17:43 janus ppp: [opt2] IPCP: SendConfigReq #13
Aug 22 01:17:43 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:43 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:44 janus ppp: [opt2] IPCP: rec'd Configure Nak #13 (Req-Sent)
Aug 22 01:17:44 janus ppp: [opt2] PRIDNS 10.11.12.13
Aug 22 01:17:44 janus ppp: [opt2] SECDNS 10.11.12.14
Aug 22 01:17:44 janus ppp: [opt2] IPCP: SendConfigReq #14
Aug 22 01:17:44 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:44 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:45 janus ppp: [opt2] IPCP: rec'd Configure Nak #14 (Req-Sent)
Aug 22 01:17:45 janus ppp: [opt2] PRIDNS 10.11.12.13
Aug 22 01:17:45 janus ppp: [opt2] SECDNS 10.11.12.14
Aug 22 01:17:45 janus ppp: [opt2] IPCP: SendConfigReq #15
Aug 22 01:17:45 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:45 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:47 janus ppp: [opt2] IPCP: SendConfigReq #16
Aug 22 01:17:47 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:47 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:49 janus ppp: [opt2] IPCP: SendConfigReq #17
Aug 22 01:17:49 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:49 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:51 janus ppp: [opt2] IPCP: SendConfigReq #18
Aug 22 01:17:51 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:51 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:53 janus ppp: [opt2] IPCP: SendConfigReq #19
Aug 22 01:17:53 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:53 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:55 janus ppp: [opt2] IPCP: SendConfigReq #20
Aug 22 01:17:55 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:55 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:57 janus ppp: [opt2] IPCP: SendConfigReq #21
Aug 22 01:17:57 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:57 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:17:59 janus ppp: [opt2] IPCP: SendConfigReq #22
Aug 22 01:17:59 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:17:59 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:18:01 janus ppp: [opt2] IPCP: SendConfigReq #23
Aug 22 01:18:01 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:18:01 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:18:03 janus ppp: [opt2] IPCP: SendConfigReq #24
Aug 22 01:18:03 janus ppp: [opt2] IPADDR 0.0.0.0
Aug 22 01:18:03 janus ppp: [opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 22 01:18:05 janus ppp: [opt2] IPCP: parameter negotiation failed
Aug 22 01:18:05 janus ppp: [opt2] IPCP: state change Req-Sent --> Stopped
Aug 22 01:18:05 janus ppp: [opt2] IPCP: LayerFinish
Aug 22 01:18:05 janus ppp: [opt2] Bundle: No NCPs left. Closing links...
Aug 22 01:18:05 janus ppp: [opt2] Bundle: closing link "opt2_link0"...
Aug 22 01:18:05 janus ppp: [opt2_link0] Link: CLOSE event
Aug 22 01:18:05 janus ppp: [opt2_link0] LCP: Close event
Aug 22 01:18:05 janus ppp: [opt2_link0] LCP: state change Opened --> Closing
Aug 22 01:18:05 janus ppp: [opt2_link0] Link: Leave bundle "opt2"
Aug 22 01:18:05 janus ppp: [opt2] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 22 01:18:05 janus ppp: [opt2] IPCP: Close event
Aug 22 01:18:05 janus ppp: [opt2] IPCP: state change Stopped --> Closed
Aug 22 01:18:05 janus ppp: [opt2] IPCP: Down event
Aug 22 01:18:05 janus ppp: [opt2] IPCP: state change Closed --> Initial
Aug 22 01:18:05 janus ppp: [opt2_link0] LCP: SendTerminateReq #6
Aug 22 01:18:05 janus ppp: [opt2_link0] LCP: LayerDown
Aug 22 01:18:07 janus ppp: [opt2_link0] LCP: SendTerminateReq #7
Aug 22 01:18:09 janus ppp: [opt2_link0] LCP: state change Closing --> Closed
Aug 22 01:18:09 janus ppp: [opt2_link0] LCP: LayerFinish
Aug 22 01:18:09 janus ppp: [opt2_link0] Link: DOWN event
Aug 22 01:18:09 janus ppp: [opt2_link0] LCP: Down event
Aug 22 01:18:09 janus ppp: [opt2_link0] LCP: state change Closed --> Initial

The state stays in "Initial" state until manually restarted. Note this only happens maybe 1 in 5 times the IP changes but if uncaught means the connection stays down.

Actions
Copy link
 #1

Updated by Noah O'Donoghue over 11 years ago

I also have this issue. PPP sometimes get stuck in Initial state and PfSense does nothing to retry, thus you have to manually restart the interface or reboot. This is a big reliability problem with PfSense, as with the link down I have to come onsite to fix the problem!

Aug 7 01:42:43 ppp: [wan_link0] PPPoE: connection closed
Aug 7 01:42:43 ppp: [wan_link0] Link: DOWN event
Aug 7 01:42:43 ppp: [wan_link0] LCP: Down event
Aug 7 01:42:43 ppp: [wan_link0] LCP: state change Opened --> Starting
Aug 7 01:42:43 ppp: [wan_link0] Link: Leave bundle "wan"
Aug 7 01:42:43 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 7 01:42:43 ppp: [wan] IPCP: Close event
Aug 7 01:42:43 ppp: [wan] IPCP: state change Opened --> Closing
Aug 7 01:42:43 ppp: [wan] IPCP: SendTerminateReq #26
Aug 7 01:42:43 ppp: [wan] IPCP: LayerDown
Aug 7 01:42:43 ppp: [wan] IFACE: Down event
Aug 7 01:42:43 ppp: [wan] IFACE: Rename interface pppoe1 to pppoe1
Aug 7 01:42:43 ppp: [wan] IPCP: Down event
Aug 7 01:42:43 ppp: [wan] IPCP: LayerFinish
Aug 7 01:42:43 ppp: [wan] Bundle: No NCPs left. Closing links...
Aug 7 01:42:43 ppp: [wan] IPCP: state change Closing --> Initial
Aug 7 01:42:43 ppp: [wan_link0] LCP: LayerDown
Aug 7 01:42:43 ppp: [wan_link0] Link: reconnection attempt 1 in 2 seconds
Aug 7 01:42:45 ppp: [wan_link0] Link: reconnection attempt 1
Aug 7 01:42:45 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:42:52 ppp: PPPoE: rec'd ACNAME "mel-pipe-bng1"
Aug 7 01:42:54 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:42:54 ppp: [wan_link0] Link: DOWN event
Aug 7 01:42:54 ppp: [wan_link0] LCP: Down event
Aug 7 01:42:54 ppp: [wan_link0] Link: reconnection attempt 2 in 3 seconds
Aug 7 01:42:57 ppp: [wan_link0] Link: reconnection attempt 2
Aug 7 01:42:57 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:42:58 ppp: PPPoE: rec'd ACNAME "mel-pipe-bng1"
Aug 7 01:42:58 ppp: [wan_link0] PPPoE: connection successful
Aug 7 01:42:58 ppp: [wan_link0] Link: UP event
Aug 7 01:42:58 ppp: [wan_link0] LCP: Up event
Aug 7 01:42:58 ppp: [wan_link0] LCP: state change Starting --> Req-Sent
Aug 7 01:42:58 ppp: [wan_link0] LCP: SendConfigReq #29
Aug 7 01:42:58 ppp: [wan_link0] PROTOCOMP
Aug 7 01:42:58 ppp: [wan_link0] MRU 1492
Aug 7 01:42:58 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:42:58 ppp: [wan_link0] LCP: rec'd Configure Request #136 (Req-Sent)
Aug 7 01:42:58 ppp: [wan_link0] MRU 1492
Aug 7 01:42:58 ppp: [wan_link0] AUTHPROTO PAP
Aug 7 01:42:58 ppp: [wan_link0] MAGICNUM 734e4394
Aug 7 01:42:58 ppp: [wan_link0] LCP: SendConfigAck #136
Aug 7 01:42:58 ppp: [wan_link0] MRU 1492
Aug 7 01:42:58 ppp: [wan_link0] AUTHPROTO PAP
Aug 7 01:42:58 ppp: [wan_link0] MAGICNUM 734e4394
Aug 7 01:42:58 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent
Aug 7 01:43:00 ppp: [wan_link0] LCP: SendConfigReq #30
Aug 7 01:43:00 ppp: [wan_link0] PROTOCOMP
Aug 7 01:43:00 ppp: [wan_link0] MRU 1492
Aug 7 01:43:00 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:02 ppp: [wan_link0] LCP: SendConfigReq #31
Aug 7 01:43:02 ppp: [wan_link0] PROTOCOMP
Aug 7 01:43:02 ppp: [wan_link0] MRU 1492
Aug 7 01:43:02 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:02 ppp: [wan_link0] LCP: rec'd Configure Reject #31 (Ack-Sent)
Aug 7 01:43:02 ppp: [wan_link0] PROTOCOMP
Aug 7 01:43:02 ppp: [wan_link0] LCP: SendConfigReq #32
Aug 7 01:43:02 ppp: [wan_link0] MRU 1492
Aug 7 01:43:02 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:02 ppp: [wan_link0] LCP: rec'd Configure Ack #32 (Ack-Sent)
Aug 7 01:43:02 ppp: [wan_link0] MRU 1492
Aug 7 01:43:02 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:02 ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
Aug 7 01:43:02 ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
Aug 7 01:43:02 ppp: [wan_link0] PAP: using authname "zigouras_master"
Aug 7 01:43:02 ppp: [wan_link0] PAP: sending REQUEST #1 len: 30
Aug 7 01:43:02 ppp: [wan_link0] LCP: LayerUp
Aug 7 01:43:04 ppp: [wan_link0] PAP: using authname "zigouras_master"
Aug 7 01:43:04 ppp: [wan_link0] PAP: sending REQUEST #2 len: 30
Aug 7 01:43:06 ppp: [wan_link0] PAP: using authname "zigouras_master"
Aug 7 01:43:06 ppp: [wan_link0] PAP: sending REQUEST #3 len: 30
Aug 7 01:43:07 ppp: [wan_link0] LCP: rec'd Configure Request #136 (Opened)
Aug 7 01:43:07 ppp: [wan_link0] MRU 1492
Aug 7 01:43:07 ppp: [wan_link0] AUTHPROTO PAP
Aug 7 01:43:07 ppp: [wan_link0] MAGICNUM 734e4394
Aug 7 01:43:07 ppp: [wan_link0] LCP: LayerDown
Aug 7 01:43:07 ppp: [wan_link0] LCP: SendConfigReq #33
Aug 7 01:43:07 ppp: [wan_link0] MRU 1492
Aug 7 01:43:07 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:07 ppp: [wan_link0] LCP: SendConfigAck #136
Aug 7 01:43:07 ppp: [wan_link0] MRU 1492
Aug 7 01:43:07 ppp: [wan_link0] AUTHPROTO PAP
Aug 7 01:43:07 ppp: [wan_link0] MAGICNUM 734e4394
Aug 7 01:43:07 ppp: [wan_link0] LCP: state change Opened --> Ack-Sent
Aug 7 01:43:09 ppp: [wan_link0] LCP: SendConfigReq #34
Aug 7 01:43:09 ppp: [wan_link0] MRU 1492
Aug 7 01:43:09 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:11 ppp: [wan_link0] LCP: SendConfigReq #35
Aug 7 01:43:11 ppp: [wan_link0] MRU 1492
Aug 7 01:43:11 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:13 ppp: [wan_link0] LCP: SendConfigReq #36
Aug 7 01:43:13 ppp: [wan_link0] MRU 1492
Aug 7 01:43:13 ppp: [wan_link0] MAGICNUM ff458b74
Aug 7 01:43:13 ppp: [wan_link0] PPPoE: connection closed
Aug 7 01:43:13 ppp: [wan_link0] Link: DOWN event
Aug 7 01:43:13 ppp: [wan_link0] LCP: Down event
Aug 7 01:43:13 ppp: [wan_link0] LCP: state change Ack-Sent --> Starting
Aug 7 01:43:13 ppp: [wan_link0] Link: reconnection attempt 3 in 2 seconds
Aug 7 01:43:15 ppp: [wan_link0] Link: reconnection attempt 3
Aug 7 01:43:15 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:43:24 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:43:24 ppp: [wan_link0] Link: DOWN event
Aug 7 01:43:24 ppp: [wan_link0] LCP: Down event
Aug 7 01:43:24 ppp: [wan_link0] Link: reconnection attempt 4 in 1 seconds
Aug 7 01:43:25 ppp: [wan_link0] Link: reconnection attempt 4
Aug 7 01:43:25 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:43:34 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:43:34 ppp: [wan_link0] Link: DOWN event
Aug 7 01:43:34 ppp: [wan_link0] LCP: Down event
Aug 7 01:43:34 ppp: [wan_link0] Link: reconnection attempt 5 in 3 seconds
Aug 7 01:43:37 ppp: [wan_link0] Link: reconnection attempt 5
Aug 7 01:43:37 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:43:46 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:43:46 ppp: [wan_link0] Link: DOWN event
Aug 7 01:43:46 ppp: [wan_link0] LCP: Down event
Aug 7 01:43:46 ppp: [wan_link0] Link: reconnection attempt 6 in 1 seconds
Aug 7 01:43:47 ppp: [wan_link0] Link: reconnection attempt 6
Aug 7 01:43:47 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:43:56 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:43:56 ppp: [wan_link0] Link: DOWN event
Aug 7 01:43:56 ppp: [wan_link0] LCP: Down event
Aug 7 01:43:56 ppp: [wan_link0] Link: reconnection attempt 7 in 2 seconds
Aug 7 01:43:58 ppp: [wan_link0] Link: reconnection attempt 7
Aug 7 01:43:58 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:44:07 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:44:07 ppp: [wan_link0] Link: DOWN event
Aug 7 01:44:07 ppp: [wan_link0] LCP: Down event
Aug 7 01:44:07 ppp: [wan_link0] Link: reconnection attempt 8 in 2 seconds
Aug 7 01:44:09 ppp: [wan_link0] Link: reconnection attempt 8
Aug 7 01:44:09 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:44:18 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:44:18 ppp: [wan_link0] Link: DOWN event
Aug 7 01:44:18 ppp: [wan_link0] LCP: Down event
Aug 7 01:44:18 ppp: [wan_link0] Link: reconnection attempt 9 in 3 seconds
Aug 7 01:44:21 ppp: [wan_link0] Link: reconnection attempt 9
Aug 7 01:44:21 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:44:30 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:44:30 ppp: [wan_link0] Link: DOWN event
Aug 7 01:44:30 ppp: [wan_link0] LCP: Down event
Aug 7 01:44:30 ppp: [wan_link0] Link: reconnection attempt 10 in 2 seconds
Aug 7 01:44:32 ppp: [wan_link0] Link: reconnection attempt 10
Aug 7 01:44:32 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:44:41 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:44:41 ppp: [wan_link0] Link: DOWN event
Aug 7 01:44:41 ppp: [wan_link0] LCP: Down event
Aug 7 01:44:41 ppp: [wan_link0] Link: reconnection attempt 11 in 1 seconds
Aug 7 01:44:42 ppp: [wan_link0] Link: reconnection attempt 11
Aug 7 01:44:42 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:44:51 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Aug 7 01:44:51 ppp: [wan_link0] Link: DOWN event
Aug 7 01:44:51 ppp: [wan_link0] LCP: Down event
Aug 7 01:44:51 ppp: [wan_link0] Link: reconnection attempt 12 in 2 seconds
Aug 7 01:44:53 ppp: [wan_link0] Link: reconnection attempt 12
Aug 7 01:44:53 ppp: [wan_link0] PPPoE: Connecting to ''
Aug 7 01:44:53 ppp: PPPoE: rec'd ACNAME "mel-pipe-bng1"
Aug 7 01:44:54 ppp: [wan_link0] PPPoE: connection successful
Aug 7 01:44:54 ppp: [wan_link0] Link: UP event
Aug 7 01:44:54 ppp: [wan_link0] LCP: Up event
Aug 7 01:44:54 ppp: [wan_link0] LCP: state change Starting --> Req-Sent
Aug 7 01:44:54 ppp: [wan_link0] LCP: SendConfigReq #37
Aug 7 01:44:54 ppp: [wan_link0] PROTOCOMP
Aug 7 01:44:54 ppp: [wan_link0] MRU 1492
Aug 7 01:44:54 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:44:56 ppp: [wan_link0] LCP: SendConfigReq #38
Aug 7 01:44:56 ppp: [wan_link0] PROTOCOMP
Aug 7 01:44:56 ppp: [wan_link0] MRU 1492
Aug 7 01:44:56 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:44:58 ppp: [wan_link0] LCP: SendConfigReq #39
Aug 7 01:44:58 ppp: [wan_link0] PROTOCOMP
Aug 7 01:44:58 ppp: [wan_link0] MRU 1492
Aug 7 01:44:58 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:00 ppp: [wan_link0] LCP: SendConfigReq #40
Aug 7 01:45:00 ppp: [wan_link0] PROTOCOMP
Aug 7 01:45:00 ppp: [wan_link0] MRU 1492
Aug 7 01:45:00 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:02 ppp: [wan_link0] LCP: SendConfigReq #41
Aug 7 01:45:02 ppp: [wan_link0] PROTOCOMP
Aug 7 01:45:02 ppp: [wan_link0] MRU 1492
Aug 7 01:45:02 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:02 ppp: [wan_link0] LCP: rec'd Configure Reject #41 (Req-Sent)
Aug 7 01:45:02 ppp: [wan_link0] PROTOCOMP
Aug 7 01:45:02 ppp: [wan_link0] LCP: SendConfigReq #42
Aug 7 01:45:02 ppp: [wan_link0] MRU 1492
Aug 7 01:45:02 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:02 ppp: [wan_link0] LCP: rec'd Configure Ack #42 (Req-Sent)
Aug 7 01:45:02 ppp: [wan_link0] MRU 1492
Aug 7 01:45:02 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:02 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
Aug 7 01:45:04 ppp: [wan_link0] LCP: state change Ack-Rcvd --> Req-Sent
Aug 7 01:45:04 ppp: [wan_link0] LCP: SendConfigReq #43
Aug 7 01:45:04 ppp: [wan_link0] MRU 1492
Aug 7 01:45:04 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:06 ppp: [wan_link0] LCP: SendConfigReq #44
Aug 7 01:45:06 ppp: [wan_link0] MRU 1492
Aug 7 01:45:06 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:06 ppp: [wan_link0] LCP: rec'd Configure Ack #44 (Req-Sent)
Aug 7 01:45:06 ppp: [wan_link0] MRU 1492
Aug 7 01:45:06 ppp: [wan_link0] MAGICNUM 19d1d23b
Aug 7 01:45:06 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
Aug 7 01:45:06 ppp: [wan_link0] LCP: rec'd Configure Request #231 (Ack-Rcvd)
Aug 7 01:45:06 ppp: [wan_link0] MRU 1492
Aug 7 01:45:06 ppp: [wan_link0] AUTHPROTO PAP
Aug 7 01:45:06 ppp: [wan_link0] MAGICNUM 00ae2abf
Aug 7 01:45:06 ppp: [wan_link0] LCP: SendConfigAck #231
Aug 7 01:45:06 ppp: [wan_link0] MRU 1492
Aug 7 01:45:06 ppp: [wan_link0] AUTHPROTO PAP
Aug 7 01:45:06 ppp: [wan_link0] MAGICNUM 00ae2abf
Aug 7 01:45:06 ppp: [wan_link0] LCP: state change Ack-Rcvd --> Opened
Aug 7 01:45:06 ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
Aug 7 01:45:06 ppp: [wan_link0] PAP: using authname "zigouras_master"
Aug 7 01:45:06 ppp: [wan_link0] PAP: sending REQUEST #1 len: 30
Aug 7 01:45:06 ppp: [wan_link0] LCP: LayerUp
Aug 7 01:45:06 ppp: [wan_link0] PAP: rec'd ACK #1 len: 5
Aug 7 01:45:06 ppp: [wan_link0] LCP: authorization successful
Aug 7 01:45:06 ppp: [wan_link0] Link: Matched action 'bundle "wan" ""'
Aug 7 01:45:06 ppp: [wan_link0] Link: Join bundle "wan"
Aug 7 01:45:06 ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Aug 7 01:45:06 ppp: [wan] IPCP: Open event
Aug 7 01:45:06 ppp: [wan] IPCP: state change Initial --> Starting
Aug 7 01:45:06 ppp: [wan] IPCP: LayerStart
Aug 7 01:45:06 ppp: [wan] IPCP: Up event
Aug 7 01:45:06 ppp: [wan] IPCP: state change Starting --> Req-Sent
Aug 7 01:45:06 ppp: [wan] IPCP: SendConfigReq #27
Aug 7 01:45:06 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:06 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 7 01:45:06 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:06 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:08 ppp: [wan] IPCP: SendConfigReq #28
Aug 7 01:45:08 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:08 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 7 01:45:08 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:08 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:08 ppp: [wan] IPCP: rec'd Configure Reject #28 (Req-Sent)
Aug 7 01:45:08 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 7 01:45:08 ppp: [wan] IPCP: SendConfigReq #29
Aug 7 01:45:08 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:08 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:08 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:10 ppp: [wan] IPCP: SendConfigReq #30
Aug 7 01:45:10 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:10 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:10 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:12 ppp: [wan] IPCP: SendConfigReq #31
Aug 7 01:45:12 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:12 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:12 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:14 ppp: [wan] IPCP: SendConfigReq #32
Aug 7 01:45:14 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:14 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:14 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:15 ppp: [wan] IPCP: rec'd Configure Request #86 (Req-Sent)
Aug 7 01:45:15 ppp: [wan] IPADDR 203.215.7.251
Aug 7 01:45:15 ppp: [wan] 203.215.7.251 is OK
Aug 7 01:45:15 ppp: [wan] IPCP: SendConfigAck #86
Aug 7 01:45:15 ppp: [wan] IPADDR 203.215.7.251
Aug 7 01:45:15 ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent
Aug 7 01:45:16 ppp: [wan] IPCP: SendConfigReq #33
Aug 7 01:45:16 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:16 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:16 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:18 ppp: [wan] IPCP: SendConfigReq #34
Aug 7 01:45:18 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:18 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:18 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:18 ppp: [wan] IPCP: rec'd Configure Request #86 (Ack-Sent)
Aug 7 01:45:18 ppp: [wan] IPADDR 203.215.7.251
Aug 7 01:45:18 ppp: [wan] 203.215.7.251 is OK
Aug 7 01:45:18 ppp: [wan] IPCP: SendConfigAck #86
Aug 7 01:45:18 ppp: [wan] IPADDR 203.215.7.251
Aug 7 01:45:20 ppp: [wan] IPCP: SendConfigReq #35
Aug 7 01:45:20 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:20 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:20 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:21 ppp: [wan] IPCP: rec'd Configure Request #86 (Ack-Sent)
Aug 7 01:45:21 ppp: [wan] IPADDR 203.215.7.251
Aug 7 01:45:21 ppp: [wan] 203.215.7.251 is OK
Aug 7 01:45:21 ppp: [wan] IPCP: SendConfigAck #86
Aug 7 01:45:21 ppp: [wan] IPADDR 203.215.7.251
Aug 7 01:45:22 ppp: [wan] IPCP: SendConfigReq #36
Aug 7 01:45:22 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:22 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:22 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:24 ppp: [wan] IPCP: SendConfigReq #37
Aug 7 01:45:24 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:24 ppp: [wan] PRIDNS 0.0.0.0
Aug 7 01:45:24 ppp: [wan] SECDNS 0.0.0.0
Aug 7 01:45:24 ppp: [wan] IPCP: rec'd Configure Reject #37 (Ack-Sent)
Aug 7 01:45:24 ppp: [wan] IPADDR 0.0.0.0
Aug 7 01:45:24 ppp: [wan] Problem: I need an IP address!
Aug 7 01:45:24 ppp: [wan] PRIDNS 203.0.178.191
Aug 7 01:45:24 ppp: [wan] SECDNS 203.215.29.191
Aug 7 01:45:24 ppp: [wan] IPCP: not converging
Aug 7 01:45:24 ppp: [wan] IPCP: parameter negotiation failed
Aug 7 01:45:24 ppp: [wan] IPCP: state change Ack-Sent --> Stopped
Aug 7 01:45:24 ppp: [wan] IPCP: LayerFinish
Aug 7 01:45:24 ppp: [wan] Bundle: No NCPs left. Closing links...
Aug 7 01:45:24 ppp: [wan] Bundle: closing link "wan_link0"...
Aug 7 01:45:24 ppp: [wan_link0] Link: CLOSE event
Aug 7 01:45:24 ppp: [wan_link0] LCP: Close event
Aug 7 01:45:24 ppp: [wan_link0] LCP: state change Opened --> Closing
Aug 7 01:45:24 ppp: [wan_link0] Link: Leave bundle "wan"
Aug 7 01:45:24 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 7 01:45:24 ppp: [wan] IPCP: Close event
Aug 7 01:45:24 ppp: [wan] IPCP: state change Stopped --> Closed
Aug 7 01:45:24 ppp: [wan] IPCP: Down event
Aug 7 01:45:24 ppp: [wan] IPCP: state change Closed --> Initial
Aug 7 01:45:24 ppp: [wan_link0] LCP: SendTerminateReq #45
Aug 7 01:45:24 ppp: [wan_link0] LCP: LayerDown
Aug 7 01:45:24 ppp: [wan_link0] LCP: rec'd Terminate Ack #45 (Closing)
Aug 7 01:45:24 ppp: [wan_link0] LCP: state change Closing --> Closed
Aug 7 01:45:24 ppp: [wan_link0] LCP: LayerFinish
Aug 7 01:45:24 ppp: [wan_link0] Link: DOWN event
Aug 7 01:45:24 ppp: [wan_link0] LCP: Down event
Aug 7 01:45:24 ppp: [wan_link0] LCP: state change Closed --> Initial

Gets stuck on Initial, Doesn't retry. I have to come in 10 minutes later and reset --> then succeeds.

Aug 7 01:57:43 ppp: PPPoE: rec'd ACNAME "mel-pipe-bng1"
Aug 7 01:57:43 ppp: [wan_link0] PPPoE: connection successful

Actions
Copy link
 #2

Updated by Noah O'Donoghue about 11 years ago

Confirming this bug still exists in 2.1-RELEASE

Nov 2 13:59:47 ppp: [wan_link0] LCP: rec'd Terminate Request #5 (Opened)
Nov 2 13:59:47 ppp: [wan_link0] LCP: state change Opened --> Stopping
Nov 2 13:59:47 ppp: [wan_link0] Link: Leave bundle "wan"
Nov 2 13:59:47 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Nov 2 13:59:47 ppp: [wan] IPCP: Close event
Nov 2 13:59:47 ppp: [wan] IPCP: state change Opened --> Closing
Nov 2 13:59:47 ppp: [wan] IPCP: SendTerminateReq #4
Nov 2 13:59:47 ppp: [wan] IPCP: LayerDown
Nov 2 13:59:47 ppp: [wan] IFACE: Down event
Nov 2 13:59:47 ppp: [wan] IFACE: Rename interface pppoe1 to pppoe1
Nov 2 13:59:47 ppp: [wan] IPV6CP: Close event
Nov 2 13:59:47 ppp: [wan] IPV6CP: state change Stopped --> Closed
Nov 2 13:59:47 ppp: [wan] IPCP: Down event
Nov 2 13:59:47 ppp: [wan] IPCP: LayerFinish
Nov 2 13:59:47 ppp: [wan] Bundle: No NCPs left. Closing links...
Nov 2 13:59:47 ppp: [wan] IPCP: state change Closing --> Initial
Nov 2 13:59:47 ppp: [wan] IPV6CP: Down event
Nov 2 13:59:47 ppp: [wan] IPV6CP: state change Closed --> Initial
Nov 2 13:59:47 ppp: [wan_link0] LCP: SendTerminateAck #3
Nov 2 13:59:47 ppp: [wan_link0] LCP: LayerDown
Nov 2 13:59:49 ppp: [wan_link0] PPPoE: connection closed
Nov 2 13:59:49 ppp: [wan_link0] Link: DOWN event
Nov 2 13:59:49 ppp: [wan_link0] LCP: Down event
Nov 2 13:59:49 ppp: [wan_link0] LCP: state change Stopping --> Starting
Nov 2 13:59:49 ppp: [wan_link0] Link: reconnection attempt 1 in 2 seconds
Nov 2 13:59:51 ppp: [wan_link0] Link: reconnection attempt 1
Nov 2 13:59:51 ppp: [wan_link0] PPPoE: Connecting to ''
Nov 2 13:59:53 ppp: PPPoE: rec'd ACNAME "mel-pipe-bng1"
Nov 2 13:59:53 ppp: [wan_link0] PPPoE: connection successful
Nov 2 13:59:53 ppp: [wan_link0] Link: UP event
Nov 2 13:59:53 ppp: [wan_link0] LCP: Up event
Nov 2 13:59:53 ppp: [wan_link0] LCP: state change Starting --> Req-Sent
Nov 2 13:59:53 ppp: [wan_link0] LCP: SendConfigReq #4
Nov 2 13:59:53 ppp: [wan_link0] PROTOCOMP
Nov 2 13:59:53 ppp: [wan_link0] MRU 1492
Nov 2 13:59:53 ppp: [wan_link0] MAGICNUM 965e2658
Nov 2 13:59:55 ppp: [wan_link0] LCP: SendConfigReq #5
Nov 2 13:59:55 ppp: [wan_link0] PROTOCOMP
Nov 2 13:59:55 ppp: [wan_link0] MRU 1492
Nov 2 13:59:55 ppp: [wan_link0] MAGICNUM 965e2658
Nov 2 13:59:57 ppp: [wan_link0] LCP: SendConfigReq #6
Nov 2 13:59:57 ppp: [wan_link0] PROTOCOMP
Nov 2 13:59:57 ppp: [wan_link0] MRU 1492
Nov 2 13:59:57 ppp: [wan_link0] MAGICNUM 965e2658
Nov 2 13:59:57 ppp: [wan_link0] LCP: rec'd Configure Reject #6 (Req-Sent)
Nov 2 13:59:57 ppp: [wan_link0] PROTOCOMP
Nov 2 13:59:57 ppp: [wan_link0] LCP: SendConfigReq #7
Nov 2 13:59:57 ppp: [wan_link0] MRU 1492
Nov 2 13:59:57 ppp: [wan_link0] MAGICNUM 965e2658
Nov 2 13:59:59 ppp: [wan_link0] LCP: SendConfigReq #8
Nov 2 13:59:59 ppp: [wan_link0] MRU 1492
Nov 2 13:59:59 ppp: [wan_link0] MAGICNUM 965e2658
Nov 2 14:00:01 ppp: [wan_link0] LCP: SendConfigReq #9
Nov 2 14:00:01 ppp: [wan_link0] MRU 1492
Nov 2 14:00:01 ppp: [wan_link0] MAGICNUM 965e2658
Nov 2 14:00:01 ppp: [wan_link0] LCP: rec'd Configure Ack #9 (Req-Sent)
Nov 2 14:00:01 ppp: [wan_link0] MRU 1492
Nov 2 14:00:01 ppp: [wan_link0] MAGICNUM 965e2658
Nov 2 14:00:01 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
Nov 2 14:00:03 ppp: [wan_link0] LCP: rec'd Configure Request #208 (Ack-Rcvd)
Nov 2 14:00:03 ppp: [wan_link0] MRU 1492
Nov 2 14:00:03 ppp: [wan_link0] AUTHPROTO PAP
Nov 2 14:00:03 ppp: [wan_link0] MAGICNUM 2adf56f5
Nov 2 14:00:03 ppp: [wan_link0] LCP: SendConfigAck #208
Nov 2 14:00:03 ppp: [wan_link0] MRU 1492
Nov 2 14:00:03 ppp: [wan_link0] AUTHPROTO PAP
Nov 2 14:00:03 ppp: [wan_link0] MAGICNUM 2adf56f5
Nov 2 14:00:03 ppp: [wan_link0] LCP: state change Ack-Rcvd --> Opened
Nov 2 14:00:03 ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
Nov 2 14:00:03 ppp: [wan_link0] PAP: using authname "zigouras_master"
Nov 2 14:00:03 ppp: [wan_link0] PAP: sending REQUEST #1 len: 30
Nov 2 14:00:03 ppp: [wan_link0] LCP: LayerUp
Nov 2 14:00:03 ppp: [wan_link0] PAP: rec'd ACK #1 len: 5
Nov 2 14:00:03 ppp: [wan_link0] LCP: authorization successful
Nov 2 14:00:03 ppp: [wan_link0] Link: Matched action 'bundle "wan" ""'
Nov 2 14:00:03 ppp: [wan_link0] Link: Join bundle "wan"
Nov 2 14:00:03 ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Nov 2 14:00:03 ppp: [wan] IPCP: Open event
Nov 2 14:00:03 ppp: [wan] IPCP: state change Initial --> Starting
Nov 2 14:00:03 ppp: [wan] IPCP: LayerStart
Nov 2 14:00:03 ppp: [wan] IPV6CP: Open event
Nov 2 14:00:03 ppp: [wan] IPV6CP: state change Initial --> Starting
Nov 2 14:00:03 ppp: [wan] IPV6CP: LayerStart
Nov 2 14:00:03 ppp: [wan] IPCP: Up event
Nov 2 14:00:03 ppp: [wan] IPCP: state change Starting --> Req-Sent
Nov 2 14:00:03 ppp: [wan] IPCP: SendConfigReq #5
Nov 2 14:00:03 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:03 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:03 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:03 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:03 ppp: [wan] IPV6CP: Up event
Nov 2 14:00:03 ppp: [wan] IPV6CP: state change Starting --> Req-Sent
Nov 2 14:00:03 ppp: [wan] IPV6CP: SendConfigReq #2
Nov 2 14:00:03 ppp: [wan_link0] LCP: rec'd Protocol Reject #209 (Opened)
Nov 2 14:00:03 ppp: [wan_link0] LCP: protocol IPV6CP was rejected
Nov 2 14:00:03 ppp: [wan] IPV6CP: protocol was rejected by peer
Nov 2 14:00:03 ppp: [wan] IPV6CP: state change Req-Sent --> Stopped
Nov 2 14:00:03 ppp: [wan] IPV6CP: LayerFinish
Nov 2 14:00:05 ppp: [wan] IPCP: SendConfigReq #6
Nov 2 14:00:05 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:05 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:05 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:05 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:06 ppp: [wan] IPCP: rec'd Configure Request #103 (Req-Sent)
Nov 2 14:00:06 ppp: [wan] IPADDR 203.215.7.251
Nov 2 14:00:06 ppp: [wan] 203.215.7.251 is OK
Nov 2 14:00:06 ppp: [wan] IPCP: SendConfigAck #103
Nov 2 14:00:06 ppp: [wan] IPADDR 203.215.7.251
Nov 2 14:00:06 ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent
Nov 2 14:00:07 ppp: [wan] IPCP: SendConfigReq #7
Nov 2 14:00:07 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:07 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:07 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:07 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:09 ppp: [wan] IPCP: SendConfigReq #8
Nov 2 14:00:09 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:09 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:09 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:09 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:11 ppp: [wan] IPCP: SendConfigReq #9
Nov 2 14:00:11 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:11 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:11 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:11 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:13 ppp: [wan] IPCP: SendConfigReq #10
Nov 2 14:00:13 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:13 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:13 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:13 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:15 ppp: [wan] IPCP: SendConfigReq #11
Nov 2 14:00:15 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:15 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:15 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:15 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:17 ppp: [wan] IPCP: SendConfigReq #12
Nov 2 14:00:17 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:17 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:17 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:17 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:18 ppp: [wan] IPCP: rec'd Configure Request #103 (Ack-Sent)
Nov 2 14:00:18 ppp: [wan] IPADDR 203.215.7.251
Nov 2 14:00:18 ppp: [wan] 203.215.7.251 is OK
Nov 2 14:00:18 ppp: [wan] IPCP: SendConfigAck #103
Nov 2 14:00:18 ppp: [wan] IPADDR 203.215.7.251
Nov 2 14:00:19 ppp: [wan] IPCP: SendConfigReq #13
Nov 2 14:00:19 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:19 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:19 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:19 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:21 ppp: [wan] IPCP: SendConfigReq #14
Nov 2 14:00:21 ppp: [wan] IPADDR 0.0.0.0
Nov 2 14:00:21 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 2 14:00:21 ppp: [wan] PRIDNS 0.0.0.0
Nov 2 14:00:21 ppp: [wan] SECDNS 0.0.0.0
Nov 2 14:00:21 ppp: [wan] IPCP: rec'd Configure Request #103 (Ack-Sent)
Nov 2 14:00:21 ppp: [wan] IPADDR 203.215.7.251
Nov 2 14:00:21 ppp: [wan] 203.215.7.251 is OK
Nov 2 14:00:21 ppp: [wan] IPCP: SendConfigAck #103
Nov 2 14:00:21 ppp: [wan] IPADDR 203.215.7.251
Nov 2 14:00:23 ppp: [wan] IPCP: parameter negotiation failed
Nov 2 14:00:23 ppp: [wan] IPCP: state change Ack-Sent --> Stopped
Nov 2 14:00:23 ppp: [wan] IPCP: LayerFinish
Nov 2 14:00:23 ppp: [wan] Bundle: No NCPs left. Closing links...
Nov 2 14:00:23 ppp: [wan] Bundle: closing link "wan_link0"...
Nov 2 14:00:23 ppp: [wan_link0] Link: CLOSE event
Nov 2 14:00:23 ppp: [wan_link0] LCP: Close event
Nov 2 14:00:23 ppp: [wan_link0] LCP: state change Opened --> Closing
Nov 2 14:00:23 ppp: [wan_link0] Link: Leave bundle "wan"
Nov 2 14:00:23 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Nov 2 14:00:23 ppp: [wan] IPCP: Close event
Nov 2 14:00:23 ppp: [wan] IPCP: state change Stopped --> Closed
Nov 2 14:00:23 ppp: [wan] IPV6CP: Close event
Nov 2 14:00:23 ppp: [wan] IPV6CP: state change Stopped --> Closed
Nov 2 14:00:23 ppp: [wan] IPCP: Down event
Nov 2 14:00:23 ppp: [wan] IPCP: state change Closed --> Initial
Nov 2 14:00:23 ppp: [wan] IPV6CP: Down event
Nov 2 14:00:23 ppp: [wan] IPV6CP: state change Closed --> Initial
Nov 2 14:00:23 ppp: [wan_link0] LCP: SendTerminateReq #10
Nov 2 14:00:23 ppp: [wan_link0] LCP: LayerDown
Nov 2 14:00:23 ppp: [wan_link0] LCP: rec'd Terminate Ack #10 (Closing)
Nov 2 14:00:23 ppp: [wan_link0] LCP: state change Closing --> Closed
Nov 2 14:00:23 ppp: [wan_link0] LCP: LayerFinish
Nov 2 14:00:23 ppp: [wan_link0] Link: DOWN event
Nov 2 14:00:23 ppp: [wan_link0] LCP: Down event
Nov 2 14:00:23 ppp: [wan_link0] LCP: state change Closed --> Initial
[Manually reset] Nov 4 09:10:50 ppp: caught fatal signal term

Actions
Copy link
 #3

Updated by Chris Buechler almost 9 years ago

  • Category set to Interfaces
  • Status changed from New to Closed

subject isn't necessary. Root issue likely doesn't exist in 2.2.x or 2.3 and newer. If it does, we'll need updated details and logs.

Actions
Copy link
 #4

Updated by Andrew Cronin over 8 years ago

I just experienced this issue.
PPPOE connection went down and failed to re-establish itself, becoming stuck at "LCP: state change Closed --> Initial."
Clicking the connect button on the interface page successfully established the link.

It appears this has happened at another one of my sites as it is offline as well - same ISP, same pfSense setup (esxi, 2.3, pppoe).

I notice that the "PPPoE: rec'd ACNAME" changed from "syd-sot-ken-bras21" to "syd-gls-har-bras21".

Logs - redacted authname and ip.

Log from disconnect to getting stuck
Apr 23 17:51:31 ppp [wan_link0] LCP: state change Closed --> Initial
Apr 23 17:51:31 ppp [wan_link0] LCP: Down event
Apr 23 17:51:31 ppp [wan_link0] Link: DOWN event
Apr 23 17:51:31 ppp [wan_link0] LCP: LayerFinish
Apr 23 17:51:31 ppp [wan_link0] LCP: state change Closing --> Closed
Apr 23 17:51:31 ppp [wan_link0] LCP: rec'd Terminate Ack #5 (Closing)
Apr 23 17:51:31 ppp [wan_link0] LCP: LayerDown
Apr 23 17:51:31 ppp [wan_link0] LCP: SendTerminateReq #5
Apr 23 17:51:31 ppp [wan] IPV6CP: state change Closed --> Initial
Apr 23 17:51:31 ppp [wan] IPV6CP: Down event
Apr 23 17:51:31 ppp [wan] IPCP: state change Closed --> Initial
Apr 23 17:51:31 ppp [wan] IPCP: Down event
Apr 23 17:51:31 ppp [wan] IPV6CP: state change Stopped --> Closed
Apr 23 17:51:31 ppp [wan] IPV6CP: Close event
Apr 23 17:51:31 ppp [wan] IPCP: state change Stopped --> Closed
Apr 23 17:51:31 ppp [wan] IPCP: Close event
Apr 23 17:51:31 ppp [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Apr 23 17:51:31 ppp [wan_link0] Link: Leave bundle "wan"
Apr 23 17:51:31 ppp [wan_link0] LCP: state change Opened --> Closing
Apr 23 17:51:31 ppp [wan_link0] LCP: Close event
Apr 23 17:51:31 ppp [wan_link0] Link: CLOSE event
Apr 23 17:51:31 ppp [wan] Bundle: closing link "wan_link0"...
Apr 23 17:51:31 ppp [wan] Bundle: No NCPs left. Closing links...
Apr 23 17:51:31 ppp [wan] IPCP: LayerFinish
Apr 23 17:51:31 ppp [wan] IPCP: state change Ack-Sent --> Stopped
Apr 23 17:51:31 ppp [wan] IPCP: parameter negotiation failed
Apr 23 17:51:31 ppp [wan] IPCP: not converging
Apr 23 17:51:31 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:31 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:31 ppp [wan] IPCP: rec'd Configure Reject #15 (Ack-Sent)
Apr 23 17:51:31 ppp [wan] IPADDR 10.20.22.133
Apr 23 17:51:31 ppp [wan] IPCP: SendConfigAck #2
Apr 23 17:51:31 ppp [wan] 10.20.22.133 is OK
Apr 23 17:51:31 ppp [wan] IPADDR 10.20.22.133
Apr 23 17:51:31 ppp [wan] IPCP: rec'd Configure Request #2 (Ack-Sent)
Apr 23 17:51:31 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:31 ppp [wan] IPCP: SendConfigReq #15
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #14
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #13 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #13
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #12 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #12
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #11 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #11
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #10 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #10
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #9 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #9
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #8 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #8
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #7 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #7
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #6 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPV6CP: LayerFinish
Apr 23 17:51:29 ppp [wan] IPV6CP: state change Req-Sent --> Stopped
Apr 23 17:51:29 ppp [wan] IPV6CP: protocol was rejected by peer
Apr 23 17:51:29 ppp [wan_link0] LCP: protocol IPV6CP was rejected
Apr 23 17:51:29 ppp [wan_link0] LCP: rec'd Protocol Reject #2 (Opened)
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #6
Apr 23 17:51:29 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Apr 23 17:51:29 ppp [wan] Problem: I need an IP address!
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Reject #5 (Ack-Sent)
Apr 23 17:51:29 ppp [wan] IPCP: state change Req-Sent --> Ack-Sent
Apr 23 17:51:29 ppp [wan] IPADDR 10.20.22.133
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigAck #1
Apr 23 17:51:29 ppp [wan] 10.20.22.133 is OK
Apr 23 17:51:29 ppp [wan] IPADDR 10.20.22.133
Apr 23 17:51:29 ppp [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
Apr 23 17:51:29 ppp [wan] IPV6CP: SendConfigReq #2
Apr 23 17:51:29 ppp [wan] IPV6CP: state change Starting --> Req-Sent
Apr 23 17:51:29 ppp [wan] IPV6CP: Up event
Apr 23 17:51:29 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Apr 23 17:51:29 ppp [wan] IPADDR 0.0.0.0
Apr 23 17:51:29 ppp [wan] IPCP: SendConfigReq #5
Apr 23 17:51:29 ppp [wan] IPCP: state change Starting --> Req-Sent
Apr 23 17:51:29 ppp [wan] IPCP: Up event
Apr 23 17:51:29 ppp [wan] IPV6CP: LayerStart
Apr 23 17:51:29 ppp [wan] IPV6CP: state change Initial --> Starting
Apr 23 17:51:29 ppp [wan] IPV6CP: Open event
Apr 23 17:51:29 ppp [wan] IPCP: LayerStart
Apr 23 17:51:29 ppp [wan] IPCP: state change Initial --> Starting
Apr 23 17:51:29 ppp [wan] IPCP: Open event
Apr 23 17:51:29 ppp [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Apr 23 17:51:29 ppp [wan_link0] Link: Join bundle "wan"
Apr 23 17:51:29 ppp [wan_link0] Link: Matched action 'bundle "wan" ""'
Apr 23 17:51:29 ppp [wan_link0] LCP: authorization successful
Apr 23 17:51:29 ppp [wan_link0] PAP: rec'd ACK #1 len: 5
Apr 23 17:51:29 ppp [wan_link0] LCP: LayerUp
Apr 23 17:51:29 ppp [wan_link0] PAP: sending REQUEST #1 len: 28
Apr 23 17:51:29 ppp [wan_link0] PAP: using authname "XXXXXXXXXXXX"
Apr 23 17:51:29 ppp [wan_link0] LCP: auth: peer wants PAP, I want nothing
Apr 23 17:51:29 ppp [wan_link0] LCP: state change Ack-Sent --> Opened
Apr 23 17:51:29 ppp [wan_link0] MAGICNUM 0x072f58c1
Apr 23 17:51:29 ppp [wan_link0] MRU 1492
Apr 23 17:51:29 ppp [wan_link0] PROTOCOMP
Apr 23 17:51:29 ppp [wan_link0] LCP: rec'd Configure Ack #4 (Ack-Sent)
Apr 23 17:51:29 ppp [wan_link0] LCP: state change Req-Sent --> Ack-Sent
Apr 23 17:51:29 ppp [wan_link0] MAGICNUM 0xe4ba7b86
Apr 23 17:51:29 ppp [wan_link0] AUTHPROTO PAP
Apr 23 17:51:29 ppp [wan_link0] MRU 1492
Apr 23 17:51:29 ppp [wan_link0] LCP: SendConfigAck #1
Apr 23 17:51:29 ppp [wan_link0] MAGICNUM 0xe4ba7b86
Apr 23 17:51:29 ppp [wan_link0] AUTHPROTO PAP
Apr 23 17:51:29 ppp [wan_link0] MRU 1492
Apr 23 17:51:29 ppp [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent)
Apr 23 17:51:29 ppp [wan_link0] MAGICNUM 0x072f58c1
Apr 23 17:51:29 ppp [wan_link0] MRU 1492
Apr 23 17:51:29 ppp [wan_link0] PROTOCOMP
Apr 23 17:51:29 ppp [wan_link0] LCP: SendConfigReq #4
Apr 23 17:51:29 ppp [wan_link0] LCP: state change Starting --> Req-Sent
Apr 23 17:51:29 ppp [wan_link0] LCP: Up event
Apr 23 17:51:29 ppp [wan_link0] Link: UP event
Apr 23 17:51:29 ppp [wan_link0] PPPoE: connection successful
Apr 23 17:51:29 ppp PPPoE: rec'd ACNAME "syd-sot-ken-bras21"
Apr 23 17:51:29 ppp [wan_link0] PPPoE: Connecting to ''
Apr 23 17:51:29 ppp [wan_link0] Link: reconnection attempt 1
Apr 23 17:51:27 ppp [wan_link0] Link: reconnection attempt 1 in 2 seconds
Apr 23 17:51:27 ppp [wan_link0] LCP: LayerStart
Apr 23 17:51:27 ppp [wan_link0] LCP: state change Stopped --> Starting
Apr 23 17:51:27 ppp [wan_link0] LCP: Down event
Apr 23 17:51:27 ppp [wan_link0] Link: DOWN event
Apr 23 17:51:27 ppp [wan_link0] PPPoE: connection closed
Apr 23 17:51:27 ppp [wan_link0] LCP: LayerFinish
Apr 23 17:51:27 ppp [wan_link0] LCP: state change Stopping --> Stopped
Apr 23 17:51:25 ppp [wan_link0] LCP: SendTerminateReq #3
Apr 23 17:51:23 ppp [wan_link0] LCP: LayerDown
Apr 23 17:51:23 ppp [wan_link0] LCP: SendTerminateReq #2
Apr 23 17:51:23 ppp [wan] IPV6CP: state change Closed --> Initial
Apr 23 17:51:23 ppp [wan] IPV6CP: Down event
Apr 23 17:51:23 ppp [wan] IPCP: state change Closing --> Initial
Apr 23 17:51:23 ppp [wan] Bundle: No NCPs left. Closing links...
Apr 23 17:51:23 ppp [wan] IPCP: LayerFinish
Apr 23 17:51:23 ppp [wan] IPCP: Down event
Apr 23 17:51:23 ppp [wan] IPV6CP: state change Stopped --> Closed
Apr 23 17:51:23 ppp [wan] IPV6CP: Close event
Apr 23 17:51:23 ppp [wan] IFACE: Rename interface pppoe0 to pppoe0
Apr 23 17:51:23 ppp [wan] IFACE: Down event
Apr 23 17:51:23 ppp [wan] IPCP: LayerDown
Apr 23 17:51:23 ppp [wan] IPCP: SendTerminateReq #4
Apr 23 17:51:23 ppp [wan] IPCP: state change Opened --> Closing
Apr 23 17:51:23 ppp [wan] IPCP: Close event
Apr 23 17:51:23 ppp [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Apr 23 17:51:23 ppp [wan_link0] Link: Leave bundle "wan"
Apr 23 17:51:23 ppp [wan_link0] LCP: state change Opened --> Stopping
Apr 23 17:51:23 ppp [wan_link0] LCP: peer not responding to echo requests
Apr 23 17:51:23 ppp [wan_link0] LCP: no reply to 5 echo request(s)
Apr 23 17:51:13 ppp [wan_link0] LCP: no reply to 4 echo request(s)
Apr 23 17:51:03 ppp [wan_link0] LCP: no reply to 3 echo request(s)
Apr 23 17:50:53 ppp [wan_link0] LCP: no reply to 2 echo request(s)
Apr 23 17:50:43 ppp [wan_link0] LCP: no reply to 1 echo request(s)

Log from clicking Connect on interface page
Apr 23 18:37:52 ppp [wan] IFACE: Rename interface ng0 to pppoe0
Apr 23 18:37:52 ppp [wan] IFACE: Up event
Apr 23 18:37:52 ppp [wan] XXX.XXX.XXX.XXX > 10.20.22.119
Apr 23 18:37:52 ppp [wan] IPCP: LayerUp
Apr 23 18:37:52 ppp [wan] IPCP: state change Ack-Sent -> Opened
Apr 23 18:37:52 ppp [wan] IPADDR XXX.XXX.XXX.XXX
Apr 23 18:37:52 ppp [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Apr 23 18:37:52 ppp [wan] IPADDR XXX.XXX.XXX.XXX
Apr 23 18:37:52 ppp [wan] IPCP: SendConfigReq #3
Apr 23 18:37:52 ppp [wan] XXX.XXX.XXX.XXX is OK
Apr 23 18:37:52 ppp [wan] IPADDR XXX.XXX.XXX.XXX
Apr 23 18:37:52 ppp [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Apr 23 18:37:52 ppp [wan] IPV6CP: LayerFinish
Apr 23 18:37:52 ppp [wan] IPV6CP: state change Req-Sent --> Stopped
Apr 23 18:37:52 ppp [wan] IPV6CP: protocol was rejected by peer
Apr 23 18:37:52 ppp [wan_link0] LCP: protocol IPV6CP was rejected
Apr 23 18:37:52 ppp [wan_link0] LCP: rec'd Protocol Reject #2 (Opened)
Apr 23 18:37:52 ppp [wan] IPADDR 0.0.0.0
Apr 23 18:37:52 ppp [wan] IPCP: SendConfigReq #2
Apr 23 18:37:52 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Apr 23 18:37:52 ppp [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
Apr 23 18:37:52 ppp [wan] IPCP: state change Req-Sent --> Ack-Sent
Apr 23 18:37:52 ppp [wan] IPADDR 10.20.22.119
Apr 23 18:37:52 ppp [wan] IPCP: SendConfigAck #1
Apr 23 18:37:52 ppp [wan] 10.20.22.119 is OK
Apr 23 18:37:52 ppp [wan] IPADDR 10.20.22.119
Apr 23 18:37:52 ppp [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
Apr 23 18:37:52 ppp [wan] IPV6CP: SendConfigReq #1
Apr 23 18:37:52 ppp [wan] IPV6CP: state change Starting --> Req-Sent
Apr 23 18:37:52 ppp [wan] IPV6CP: Up event
Apr 23 18:37:52 ppp [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Apr 23 18:37:52 ppp [wan] IPADDR 0.0.0.0
Apr 23 18:37:52 ppp [wan] IPCP: SendConfigReq #1
Apr 23 18:37:52 ppp [wan] IPCP: state change Starting --> Req-Sent
Apr 23 18:37:52 ppp [wan] IPCP: Up event
Apr 23 18:37:52 ppp [wan] IPV6CP: LayerStart
Apr 23 18:37:52 ppp [wan] IPV6CP: state change Initial --> Starting
Apr 23 18:37:52 ppp [wan] IPV6CP: Open event
Apr 23 18:37:52 ppp [wan] IPCP: LayerStart
Apr 23 18:37:52 ppp [wan] IPCP: state change Initial --> Starting
Apr 23 18:37:52 ppp [wan] IPCP: Open event
Apr 23 18:37:52 ppp [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Apr 23 18:37:52 ppp [wan_link0] Link: Join bundle "wan"
Apr 23 18:37:52 ppp [wan_link0] Link: Matched action 'bundle "wan" ""'
Apr 23 18:37:52 ppp [wan_link0] LCP: authorization successful
Apr 23 18:37:52 ppp [wan_link0] PAP: rec'd ACK #1 len: 5
Apr 23 18:37:51 ppp [wan_link0] LCP: LayerUp
Apr 23 18:37:51 ppp [wan_link0] PAP: sending REQUEST #1 len: 28
Apr 23 18:37:51 ppp [wan_link0] PAP: using authname "XXXXXXXXXX"
Apr 23 18:37:51 ppp [wan_link0] LCP: auth: peer wants PAP, I want nothing
Apr 23 18:37:51 ppp [wan_link0] LCP: state change Ack-Sent --> Opened
Apr 23 18:37:51 ppp [wan_link0] MAGICNUM 0x88c75b00
Apr 23 18:37:51 ppp [wan_link0] MRU 1492
Apr 23 18:37:51 ppp [wan_link0] PROTOCOMP
Apr 23 18:37:51 ppp [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
Apr 23 18:37:51 ppp [wan_link0] LCP: state change Req-Sent --> Ack-Sent
Apr 23 18:37:51 ppp [wan_link0] MAGICNUM 0xe52881ea
Apr 23 18:37:51 ppp [wan_link0] AUTHPROTO PAP
Apr 23 18:37:51 ppp [wan_link0] MRU 1492
Apr 23 18:37:51 ppp [wan_link0] LCP: SendConfigAck #1
Apr 23 18:37:51 ppp [wan_link0] MAGICNUM 0xe52881ea
Apr 23 18:37:51 ppp [wan_link0] AUTHPROTO PAP
Apr 23 18:37:51 ppp [wan_link0] MRU 1492
Apr 23 18:37:51 ppp [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent)
Apr 23 18:37:51 ppp [wan_link0] MAGICNUM 0x88c75b00
Apr 23 18:37:51 ppp [wan_link0] MRU 1492
Apr 23 18:37:51 ppp [wan_link0] PROTOCOMP
Apr 23 18:37:51 ppp [wan_link0] LCP: SendConfigReq #1
Apr 23 18:37:51 ppp [wan_link0] LCP: state change Starting --> Req-Sent
Apr 23 18:37:51 ppp [wan_link0] LCP: Up event
Apr 23 18:37:51 ppp [wan_link0] Link: UP event
Apr 23 18:37:51 ppp [wan_link0] PPPoE: connection successful
Apr 23 18:37:51 ppp PPPoE: rec'd ACNAME "syd-gls-har-bras21"
Apr 23 18:37:51 ppp [wan_link0] PPPoE: Connecting to ''
Apr 23 18:37:51 ppp [wan_link0] LCP: LayerStart
Apr 23 18:37:51 ppp [wan_link0] LCP: state change Initial --> Starting
Apr 23 18:37:51 ppp [wan_link0] LCP: Open event
Apr 23 18:37:51 ppp [wan_link0] Link: OPEN event
Apr 23 18:37:51 ppp [wan] Bundle: Interface ng0 created
Apr 23 18:37:51 ppp web: web is not running
Apr 23 18:37:51 ppp process 6517 terminated
Apr 23 18:37:51 ppp [wan_link0] Link: Shutdown
Apr 23 18:37:51 ppp [wan] Bundle: Shutdown
Apr 23 18:37:50 ppp waiting for process 6517 to die...
Apr 23 18:37:49 ppp [wan] IPV6CP: Close event
Apr 23 18:37:49 ppp [wan] IPCP: Close event
Apr 23 18:37:49 ppp [wan] IFACE: Close event
Apr 23 18:37:49 ppp caught fatal signal TERM
Apr 23 18:37:49 ppp waiting for process 6517 to die...
Apr 23 18:37:49 ppp process 35584 started, version 5.8 (root@pfSense_v2_3_0_amd64-pfSense_v2_3_0-job-14 22:52 6-Apr-2016)
Apr 23 18:37:49 ppp Multi-link PPP daemon for FreeBSD

Actions
Copy link
 #5

Updated by Chris Buechler over 8 years ago

Andrew: please start a thread on the forum and we can help troubleshoot. There might be some root cause problem there, but it's not related to subject of this issue, which is closed.

Actions
Copy link

Also available in: Atom PDF