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

Also available in: Atom PDF