PPP doesn't automatically reconnect after LCP timeout

mmorabito606 · Sep 4, 2020, 10:57 PM

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-p1

Below 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

stephenw10 · Sep 6, 2020, 1:44 PM

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

mmorabito606 · Sep 8, 2020, 10:09 PM

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

stephenw10 · Sep 9, 2020, 2:01 PM

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

mmorabito606 · Sep 9, 2020, 7:03 PM

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.

stephenw10 · Sep 10, 2020, 4:01 PM

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