PPP doesn't automatically reconnect after LCP timeout
-
Hello All,
It seems like every time LCP times out on my PPP interface the PPP daemon gets caught in some strange "initial" state which causes the PPP interface to hang completely instead of attempting to reconnect.
This issue happens about once every other month and to resolve it I have to login to the pfSense web administration, navigate to "Status -> Interfaces" and manually click the connect button on the PPP interface.
It almost seems like my issue is exactly this which doesn't seem to have a documented solution. (https://redmine.pfsense.org/issues/1811)
The reason that this is such an issue for me is that this PPP interface is the "backup/disaster" interface into my network. If the other network interface I have configured were to fail catastrophically then I would like to be certain that my backup PPP interface will be working and not need any sort or manual maintenance to ensure it's up and working properly.
Any help with this issue would be much appreciated.
My physical hardware is as follows:
Mini PC: Qotom Q190G4N
Cellular Modem: Sierra Wireless MC7455
Carrier: Verizon 4G LTE (vzwinternet)
pfSense Version: 2.4.5-RELEASE-p1Below is the the output of 'uname -a':
[2.4.5-RELEASE][root@ovid]/root: uname -a FreeBSD ovid 11.3-STABLE FreeBSD 11.3-STABLE #243 abf8cba50ce(RELENG_2_4_5): Tue Jun 2 17:53:37 EDT 2020 root@buildbot1-nyi.netgate.com:/build/ce-crossbuild-245/obj/amd64/YNx4Qq3j/build/ce-crossbuild-245/sources/FreeBSD-src/sys/pfSense amd64
And log output from the PPP service when the issues occur:
Sep 4 15:44:15 ovid ppp: [opt1_link0] LCP: no reply to 1 echo request(s) Sep 4 15:44:25 ovid ppp: [opt1_link0] LCP: no reply to 2 echo request(s) Sep 4 15:44:35 ovid ppp: [opt1_link0] LCP: no reply to 3 echo request(s) Sep 4 15:44:45 ovid ppp: [opt1_link0] LCP: no reply to 4 echo request(s) Sep 4 15:44:55 ovid ppp: [opt1_link0] LCP: no reply to 5 echo request(s) Sep 4 15:44:55 ovid ppp: [opt1_link0] LCP: peer not responding to echo requests Sep 4 15:44:55 ovid ppp: [opt1_link0] LCP: state change Opened --> Stopping Sep 4 15:44:55 ovid ppp: [opt1_link0] Link: Leave bundle "opt1" Sep 4 15:44:55 ovid ppp: [opt1] Bundle: Status update: up 0 links, total bandwidth 9600 bps Sep 4 15:44:55 ovid ppp: [opt1] IPCP: Close event Sep 4 15:44:55 ovid ppp: [opt1] IPCP: state change Opened --> Closing Sep 4 15:44:55 ovid ppp: [opt1] IPCP: SendTerminateReq #4 Sep 4 15:44:55 ovid ppp: [opt1] IPCP: LayerDown Sep 4 15:44:55 ovid ppp: [opt1] IFACE: Down event Sep 4 15:44:55 ovid ppp: [opt1] IFACE: Rename interface ppp0 to ppp0 Sep 4 15:44:55 ovid ppp: [opt1] IPV6CP: Close event Sep 4 15:44:55 ovid ppp: [opt1] IPV6CP: state change Stopped --> Closed Sep 4 15:44:55 ovid ppp: [opt1] IPCP: Down event Sep 4 15:44:55 ovid ppp: [opt1] IPCP: LayerFinish Sep 4 15:44:55 ovid ppp: [opt1] Bundle: No NCPs left. Closing links... Sep 4 15:44:55 ovid ppp: [opt1] IPCP: state change Closing --> Initial Sep 4 15:44:55 ovid ppp: [opt1] IPV6CP: Down event Sep 4 15:44:55 ovid ppp: [opt1] IPV6CP: state change Closed --> Initial Sep 4 15:44:55 ovid ppp: [opt1_link0] LCP: SendTerminateReq #2 Sep 4 15:44:55 ovid ppp: [opt1_link0] LCP: LayerDown Sep 4 15:44:57 ovid ppp: [opt1_link0] LCP: SendTerminateReq #3 Sep 4 15:44:59 ovid ppp: [opt1_link0] LCP: state change Stopping --> Stopped Sep 4 15:44:59 ovid ppp: [opt1_link0] LCP: LayerFinish Sep 4 15:44:59 ovid ppp: [opt1_link0] Link: DOWN event Sep 4 15:44:59 ovid ppp: [opt1_link0] LCP: Down event Sep 4 15:44:59 ovid ppp: [opt1_link0] LCP: state change Stopped --> Starting Sep 4 15:44:59 ovid ppp: [opt1_link0] LCP: LayerStart Sep 4 15:44:59 ovid ppp: [opt1_link0] Link: reconnection attempt 1 in 4 seconds Sep 4 15:45:03 ovid ppp: [opt1_link0] Link: reconnection attempt 1 Sep 4 15:45:03 ovid ppp: [opt1_link0] CHAT: Detected Hayes compatible modem. Sep 4 15:45:04 ovid ppp: [opt1_link0] CHAT: Dialing server at *99#... Sep 4 15:45:04 ovid ppp: [opt1_link0] CHAT: ATDT*99# Sep 4 15:45:04 ovid ppp: [opt1_link0] CHAT: Connected at 150000000. Sep 4 15:45:04 ovid ppp: [opt1_link0] MODEM: chat script succeeded Sep 4 15:45:04 ovid ppp: [opt1_link0] Link: UP event Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: Up event Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: state change Starting --> Req-Sent Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: SendConfigReq #4 Sep 4 15:45:04 ovid ppp: [opt1_link0] ACFCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] ACCMAP 0x000a0000 Sep 4 15:45:04 ovid ppp: [opt1_link0] MRU 1500 Sep 4 15:45:04 ovid ppp: [opt1_link0] MAGICNUM 0x652dd849 Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: rec'd Configure Request #36 (Req-Sent) Sep 4 15:45:04 ovid ppp: [opt1_link0] ACCMAP 0x00000000 Sep 4 15:45:04 ovid ppp: [opt1_link0] AUTHPROTO CHAP MD5 Sep 4 15:45:04 ovid ppp: [opt1_link0] MAGICNUM 0xcd29d063 Sep 4 15:45:04 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] ACFCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: SendConfigAck #36 Sep 4 15:45:04 ovid ppp: [opt1_link0] ACCMAP 0x00000000 Sep 4 15:45:04 ovid ppp: [opt1_link0] AUTHPROTO CHAP MD5 Sep 4 15:45:04 ovid ppp: [opt1_link0] MAGICNUM 0xcd29d063 Sep 4 15:45:04 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] ACFCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: state change Req-Sent --> Ack-Sent Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: rec'd Configure Ack #4 (Ack-Sent) Sep 4 15:45:04 ovid ppp: [opt1_link0] ACFCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 15:45:04 ovid ppp: [opt1_link0] ACCMAP 0x000a0000 Sep 4 15:45:04 ovid ppp: [opt1_link0] MRU 1500 Sep 4 15:45:04 ovid ppp: [opt1_link0] MAGICNUM 0x652dd849 Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: state change Ack-Sent --> Opened Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: auth: peer wants CHAP, I want nothing Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: LayerUp Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: rec'd Discard Request #37 (Opened) Sep 4 15:45:04 ovid ppp: [opt1_link0] CHAP: rec'd CHALLENGE #1 len: 35 Sep 4 15:45:04 ovid ppp: [opt1_link0] Name: "UMTS_CHAP_SRVR" Sep 4 15:45:04 ovid ppp: [opt1_link0] CHAP: Using authname "user" Sep 4 15:45:04 ovid ppp: [opt1_link0] CHAP: sending RESPONSE #1 len: 25 Sep 4 15:45:04 ovid ppp: [opt1_link0] CHAP: rec'd SUCCESS #1 len: 4 Sep 4 15:45:04 ovid ppp: [opt1_link0] LCP: authorization successful Sep 4 15:45:04 ovid ppp: [opt1_link0] Link: Matched action 'bundle "opt1" ""' Sep 4 15:45:04 ovid ppp: [opt1_link0] Link: Join bundle "opt1" Sep 4 15:45:04 ovid ppp: [opt1] Bundle: Status update: up 1 link, total bandwidth 150000000 bps Sep 4 15:45:04 ovid ppp: [opt1] IPCP: Open event Sep 4 15:45:04 ovid ppp: [opt1] IPCP: state change Initial --> Starting Sep 4 15:45:04 ovid ppp: [opt1] IPCP: LayerStart Sep 4 15:45:04 ovid ppp: [opt1] IPV6CP: Open event Sep 4 15:45:04 ovid ppp: [opt1] IPV6CP: state change Initial --> Starting Sep 4 15:45:04 ovid ppp: [opt1] IPV6CP: LayerStart Sep 4 15:45:04 ovid ppp: [opt1] IPCP: Up event Sep 4 15:45:04 ovid ppp: [opt1] IPCP: state change Starting --> Req-Sent Sep 4 15:45:04 ovid ppp: [opt1] IPCP: SendConfigReq #5 Sep 4 15:45:04 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:04 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:04 ovid ppp: [opt1] IPV6CP: Up event Sep 4 15:45:04 ovid ppp: [opt1] IPV6CP: state change Starting --> Req-Sent Sep 4 15:45:04 ovid ppp: [opt1] IPV6CP: SendConfigReq #11 Sep 4 15:45:06 ovid ppp: [opt1] IPV6CP: SendConfigReq #12 Sep 4 15:45:06 ovid ppp: [opt1] IPCP: SendConfigReq #6 Sep 4 15:45:06 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:06 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:08 ovid ppp: [opt1] IPCP: SendConfigReq #7 Sep 4 15:45:08 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:08 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:08 ovid ppp: [opt1] IPV6CP: SendConfigReq #13 Sep 4 15:45:10 ovid ppp: [opt1] IPV6CP: SendConfigReq #14 Sep 4 15:45:10 ovid ppp: [opt1] IPCP: SendConfigReq #8 Sep 4 15:45:10 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:10 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:12 ovid ppp: [opt1] IPCP: SendConfigReq #9 Sep 4 15:45:12 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:12 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:12 ovid ppp: [opt1] IPV6CP: SendConfigReq #15 Sep 4 15:45:14 ovid ppp: [opt1] IPV6CP: SendConfigReq #16 Sep 4 15:45:14 ovid ppp: [opt1] IPCP: SendConfigReq #10 Sep 4 15:45:14 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:14 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:16 ovid ppp: [opt1] IPCP: SendConfigReq #11 Sep 4 15:45:16 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:16 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:16 ovid ppp: [opt1] IPV6CP: SendConfigReq #17 Sep 4 15:45:18 ovid ppp: [opt1] IPV6CP: SendConfigReq #18 Sep 4 15:45:18 ovid ppp: [opt1] IPCP: SendConfigReq #12 Sep 4 15:45:18 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:18 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:20 ovid ppp: [opt1] IPCP: SendConfigReq #13 Sep 4 15:45:20 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:20 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:20 ovid ppp: [opt1] IPV6CP: SendConfigReq #19 Sep 4 15:45:22 ovid ppp: [opt1] IPV6CP: SendConfigReq #20 Sep 4 15:45:22 ovid ppp: [opt1] IPCP: SendConfigReq #14 Sep 4 15:45:22 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 15:45:22 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 15:45:24 ovid ppp: [opt1_link0] LCP: no reply to 1 echo request(s) Sep 4 15:45:24 ovid ppp: [opt1] IPCP: parameter negotiation failed Sep 4 15:45:24 ovid ppp: [opt1] IPCP: state change Req-Sent --> Stopped Sep 4 15:45:24 ovid ppp: [opt1] IPCP: LayerFinish Sep 4 15:45:24 ovid ppp: [opt1] IPV6CP: parameter negotiation failed Sep 4 15:45:24 ovid ppp: [opt1] IPV6CP: state change Req-Sent --> Stopped Sep 4 15:45:24 ovid ppp: [opt1] IPV6CP: LayerFinish Sep 4 15:45:24 ovid ppp: [opt1] Bundle: No NCPs left. Closing links... Sep 4 15:45:24 ovid ppp: [opt1] Bundle: closing link "opt1_link0"... Sep 4 15:45:24 ovid ppp: [opt1_link0] Link: CLOSE event Sep 4 15:45:24 ovid ppp: [opt1_link0] LCP: Close event Sep 4 15:45:24 ovid ppp: [opt1_link0] LCP: state change Opened --> Closing Sep 4 15:45:24 ovid ppp: [opt1_link0] Link: Leave bundle "opt1" Sep 4 15:45:24 ovid ppp: [opt1] Bundle: Status update: up 0 links, total bandwidth 9600 bps Sep 4 15:45:24 ovid ppp: [opt1] IPCP: Close event Sep 4 15:45:24 ovid ppp: [opt1] IPCP: state change Stopped --> Closed Sep 4 15:45:24 ovid ppp: [opt1] IPV6CP: Close event Sep 4 15:45:24 ovid ppp: [opt1] IPV6CP: state change Stopped --> Closed Sep 4 15:45:24 ovid ppp: [opt1] IPCP: Down event Sep 4 15:45:24 ovid ppp: [opt1] IPCP: state change Closed --> Initial Sep 4 15:45:24 ovid ppp: [opt1] IPV6CP: Down event Sep 4 15:45:24 ovid ppp: [opt1] IPV6CP: state change Closed --> Initial Sep 4 15:45:24 ovid ppp: [opt1_link0] LCP: SendTerminateReq #5 Sep 4 15:45:24 ovid ppp: [opt1_link0] LCP: LayerDown Sep 4 15:45:26 ovid ppp: [opt1_link0] LCP: SendTerminateReq #6 Sep 4 15:45:28 ovid ppp: [opt1_link0] LCP: state change Closing --> Closed Sep 4 15:45:28 ovid ppp: [opt1_link0] LCP: LayerFinish Sep 4 15:45:28 ovid ppp: [opt1_link0] Link: DOWN event Sep 4 15:45:28 ovid ppp: [opt1_link0] LCP: Down event Sep 4 15:45:28 ovid ppp: [opt1_link0] LCP: state change Closed --> Initial
-
Does it just loop around with that same error each time after that?
How does that compare with a successful connection?
Hard to see why it would be doing something different but it looks like one end must be. It is trying to reconnect and the other end is responding just not with what we are requesting it looks like.
Steve
-
Hello Steve,
No it does not loop around with that same error. The attached log is everything that is generated when this issue occurs.
Below is the log output of what happens after I click the connect button from "Status -> Interfaces" after the issues occurs. From the log below it seems like what solves the issue is restarting mpd:
Sep 4 17:56:24 ovid ppp: Multi-link PPP daemon for FreeBSD Sep 4 17:56:24 ovid ppp: Sep 4 17:56:24 ovid ppp: process 13681 started, version 5.8 (root@pfSense_v2_4_5_amd64-pfSense_v2_4_5-job-04 20:28 17-Dec-2019) Sep 4 17:56:24 ovid ppp: waiting for process 75791 to die... Sep 4 17:56:24 ovid ppp: caught fatal signal TERM Sep 4 17:56:24 ovid ppp: [opt1] IFACE: Close event Sep 4 17:56:24 ovid ppp: [opt1] IPCP: Close event Sep 4 17:56:24 ovid ppp: [opt1] IPV6CP: Close event Sep 4 17:56:25 ovid ppp: waiting for process 75791 to die... Sep 4 17:56:26 ovid ppp: [opt1] Bundle: Shutdown Sep 4 17:56:26 ovid ppp: waiting for process 75791 to die... Sep 4 17:56:26 ovid ppp: [opt1_link0] Link: Shutdown Sep 4 17:56:26 ovid ppp: process 75791 terminated Sep 4 17:56:27 ovid ppp: web: web is not running Sep 4 17:56:27 ovid ppp: [opt1] Bundle: Interface ng0 created Sep 4 17:56:27 ovid ppp: [opt1_link0] Link: OPEN event Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: Open event Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: state change Initial --> Starting Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: LayerStart Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAT: +CGDCONT=1,"IP","vzwinternet" Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAT: Detected Hayes compatible modem. Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAT: Dialing server at *99#... Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAT: ATDT*99# Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAT: Connected at 150000000. Sep 4 17:56:27 ovid ppp: [opt1_link0] MODEM: chat script succeeded Sep 4 17:56:27 ovid ppp: [opt1_link0] Link: UP event Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: Up event Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: state change Starting --> Req-Sent Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: SendConfigReq #1 Sep 4 17:56:27 ovid ppp: [opt1_link0] ACFCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] ACCMAP 0x000a0000 Sep 4 17:56:27 ovid ppp: [opt1_link0] MRU 1500 Sep 4 17:56:27 ovid ppp: [opt1_link0] MAGICNUM 0xed53e684 Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: rec'd Configure Request #38 (Req-Sent) Sep 4 17:56:27 ovid ppp: [opt1_link0] ACCMAP 0x00000000 Sep 4 17:56:27 ovid ppp: [opt1_link0] AUTHPROTO CHAP MD5 Sep 4 17:56:27 ovid ppp: [opt1_link0] MAGICNUM 0xcda21b6a Sep 4 17:56:27 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] ACFCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: SendConfigAck #38 Sep 4 17:56:27 ovid ppp: [opt1_link0] ACCMAP 0x00000000 Sep 4 17:56:27 ovid ppp: [opt1_link0] AUTHPROTO CHAP MD5 Sep 4 17:56:27 ovid ppp: [opt1_link0] MAGICNUM 0xcda21b6a Sep 4 17:56:27 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] ACFCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: state change Req-Sent --> Ack-Sent Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Sep 4 17:56:27 ovid ppp: [opt1_link0] ACFCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] PROTOCOMP Sep 4 17:56:27 ovid ppp: [opt1_link0] ACCMAP 0x000a0000 Sep 4 17:56:27 ovid ppp: [opt1_link0] MRU 1500 Sep 4 17:56:27 ovid ppp: [opt1_link0] MAGICNUM 0xed53e684 Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: state change Ack-Sent --> Opened Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: auth: peer wants CHAP, I want nothing Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: LayerUp Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: rec'd Discard Request #39 (Opened) Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAP: rec'd CHALLENGE #1 len: 35 Sep 4 17:56:27 ovid ppp: [opt1_link0] Name: "UMTS_CHAP_SRVR" Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAP: Using authname "user" Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAP: sending RESPONSE #1 len: 25 Sep 4 17:56:27 ovid ppp: [opt1_link0] CHAP: rec'd SUCCESS #1 len: 4 Sep 4 17:56:27 ovid ppp: [opt1_link0] LCP: authorization successful Sep 4 17:56:27 ovid ppp: [opt1_link0] Link: Matched action 'bundle "opt1" ""' Sep 4 17:56:27 ovid ppp: [opt1_link0] Link: Join bundle "opt1" Sep 4 17:56:27 ovid ppp: [opt1] Bundle: Status update: up 1 link, total bandwidth 150000000 bps Sep 4 17:56:27 ovid ppp: [opt1] IPCP: Open event Sep 4 17:56:27 ovid ppp: [opt1] IPCP: state change Initial --> Starting Sep 4 17:56:27 ovid ppp: [opt1] IPCP: LayerStart Sep 4 17:56:27 ovid ppp: [opt1] IPV6CP: Open event Sep 4 17:56:27 ovid ppp: [opt1] IPV6CP: state change Initial --> Starting Sep 4 17:56:27 ovid ppp: [opt1] IPV6CP: LayerStart Sep 4 17:56:27 ovid ppp: [opt1] IPCP: Up event Sep 4 17:56:27 ovid ppp: [opt1] IPCP: state change Starting --> Req-Sent Sep 4 17:56:27 ovid ppp: [opt1] IPCP: SendConfigReq #1 Sep 4 17:56:27 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 17:56:27 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 17:56:27 ovid ppp: [opt1] IPV6CP: Up event Sep 4 17:56:27 ovid ppp: [opt1] IPV6CP: state change Starting --> Req-Sent Sep 4 17:56:27 ovid ppp: [opt1] IPV6CP: SendConfigReq #1 Sep 4 17:56:27 ovid ppp: [opt1] IPCP: rec'd Configure Request #12 (Req-Sent) Sep 4 17:56:27 ovid ppp: [opt1] IPCP: SendConfigAck #12 Sep 4 17:56:27 ovid ppp: [opt1] IPCP: state change Req-Sent --> Ack-Sent Sep 4 17:56:27 ovid ppp: [opt1] IPCP: rec'd Configure Reject #1 (Ack-Sent) Sep 4 17:56:27 ovid ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 4 17:56:27 ovid ppp: [opt1] IPCP: SendConfigReq #2 Sep 4 17:56:27 ovid ppp: [opt1] IPADDR 0.0.0.0 Sep 4 17:56:27 ovid ppp: [opt1] IPCP: rec'd Configure Nak #2 (Ack-Sent) Sep 4 17:56:27 ovid ppp: [opt1] IPADDR XXX.XXX.XXX.XXX (REDADCTED) Sep 4 17:56:27 ovid ppp: [opt1] XXX.XXX.XXX.XXX (REDADCTED) is OK Sep 4 17:56:27 ovid ppp: [opt1] IPCP: SendConfigReq #3 Sep 4 17:56:27 ovid ppp: [opt1] IPADDR XXX.XXX.XXX.XXX (REDADCTED) Sep 4 17:56:27 ovid ppp: [opt1] IPCP: rec'd Configure Ack #3 (Ack-Sent) Sep 4 17:56:27 ovid ppp: [opt1] IPADDR XXX.XXX.XXX.XXX (REDADCTED) Sep 4 17:56:27 ovid ppp: [opt1] IPCP: state change Ack-Sent --> Opened Sep 4 17:56:27 ovid ppp: [opt1] IPCP: LayerUp Sep 4 17:56:27 ovid ppp: [opt1] XXX.XXX.XXX.XXX (REDADCTED) -> XXX.XXX.XXX.XXX (REDADCTED) Sep 4 17:56:27 ovid ppp: [opt1] IFACE: Up event Sep 4 17:56:27 ovid ppp: [opt1] IFACE: Rename interface ng0 to ppp0 Sep 4 17:56:29 ovid ppp: [opt1] IPV6CP: SendConfigReq #2 Sep 4 17:56:31 ovid ppp: [opt1] IPV6CP: SendConfigReq #3 Sep 4 17:56:33 ovid ppp: [opt1] IPV6CP: SendConfigReq #4 Sep 4 17:56:35 ovid ppp: [opt1] IPV6CP: SendConfigReq #5 Sep 4 17:56:37 ovid ppp: [opt1] IPV6CP: SendConfigReq #6 Sep 4 17:56:39 ovid ppp: [opt1] IPV6CP: SendConfigReq #7 Sep 4 17:56:41 ovid ppp: [opt1] IPV6CP: SendConfigReq #8 Sep 4 17:56:43 ovid ppp: [opt1] IPV6CP: SendConfigReq #9 Sep 4 17:56:45 ovid ppp: [opt1] IPV6CP: SendConfigReq #10 Sep 4 17:56:47 ovid ppp: [opt1] IPV6CP: parameter negotiation failed Sep 4 17:56:47 ovid ppp: [opt1] IPV6CP: state change Req-Sent --> Stopped Sep 4 17:56:47 ovid ppp: [opt1] IPV6CP: LayerFinish
-
It isn't that bug you linked, it's not stuck in 'initial'. It appears to be trying to pull a v6 IP and failing.
Do you have IPv6 enabled on that connection?
Steve
-
I should have been more clear I apologize. The log in my first post was directly after the 'initial' failure. The log in my second post is a successful connection.
The log in my second post was the modem successfully connecting by clicking the connect button on the "Status -> Interfaces" page after encountering the 'initial' issue. You can see that MPD gets restarted at the beginning of the log output which means me clicking that "connect" button is completely restarting MPD. I verified that I can get out to the internet after the established connection in the second log.
As for the IPV6CP error, I attempted to resolve that without success and figured since the internet was working it didn't have significance. To fix the error I tried enabling SLAAC and of course that didn't work. I then attempted DHCPv6 with and without the two options "Request a IPv6 prefix/information through the IPv4 connectivity link" and "Send an IPv6 prefix hint to indicate the desired prefix size for delegation" enabled. The IPV6CP error still shows no matter what but what is interesting is that dhclient can not seem to find ppp0 as if the interface hasn't been created yet. I'm wondering if DHCP is requesting an IPv6 address before the ppp0 interface is ready by MPD. Here is the output of the DHCP (dhclient) log:
Apr 4 02:35:55 dhclient PREINIT Apr 4 02:35:55 dhclient 96790 ppp0: not found Apr 4 02:35:55 dhclient 96790 exiting.
I see that the time in this log file is completely off because it should be reading today's date and time. I ensured the system time is set correctly, maybe dhclient is using DHCP time or something? Not sure if that is of any importance.
Could it be possible that the Verizon 4G LTE connection requires the IPV6CP to properly restart and manage the modem state? Which is why I'm getting such wonky interaction?
Just a side note that I have my firewall on this PPP interface temporarily set to allow everything during all this testing just to ensure I'm not running into a firewall issue.
-
Ah, sorry I see that now.
Hmm. Does it happen everytime it loses link?
Seems like it must be either specific to your provider or maybe something in the card, different firmware version? I know quite a few people are using that modem.
Can you test a different cell provider?Steve