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

  • Netgate Administrator

    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
    

  • Netgate Administrator

    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.


  • Netgate Administrator

    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


Log in to reply