lwip-users
[Top][All Lists]
Advanced
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[lwip-users] LCP fails to negotiate options continuously after many prev

From: Andrew Westberg
Subject: [lwip-users] LCP fails to negotiate options continuously after many previous successes
Date: Fri, 16 May 2014 09:01:15 -0400
I'm using lwip on a PIC32 chip connected via USB to a Sierra Wireless SL5011 modem for an M2M application. The application is designed to connect to the modem/network every 5 minutes to send some data.

After a good number of hours (between 8 and 12), LCP is unable to successfully negotiate connection options. Before that, it chugs along happily sending data every 5 minutes. After it gets into this state, every subsequent data call will fail in the same manner. In this state, each attempt finally gives up with PPPERR_PROTOCOL and shuts down the connection. I'm using PPPoS via USB-CDC to communicate with the modem.

What I've tried so far:
 - reboot the modem every 50 data calls in case it was an issue with modem firmware (had no effect)
 - restart the USB connection every 50 data calls in case it was an issue with the USB layer (had no effect)
 - turn on memp logging to see if some buffer overrun/underrun was happening (it wasn't)
 - re-initialize ppp before each data call to ensure connection options are reset (had no effect)
 - use the latest dev code from github that had a few fixes for ppp in it (had no effect)
 - turn off ao->neg_pcompression and ao->neg_accompression (had no effect)

See below log from the first failed data call. This was the one with neg_pcompression and neg_accompression off and the latest dev code from github. Any help pointing me in the right direction or where to put in additional logging would be appreciated.

Thanks,
- Andrew Westberg

--------------------------
Modem Init... 110.
.Sending ATH0E0V0..
.MODEM_INIT - OK.
...CnS: Send HDR_HYBRID_PREF.
.CnS: SERVICE_INDICATION: RPLY - OK.
CnS: SERVICE_INDICATION: 0x0002.
...CnS: Send HDR_SERVICE_STATE.
...CnS: HDR_SERVICE_STATE: RPLY - OK.
.CnS: HDR_SERVICE_STATE: 0x0004.
...CnS: PROTOCOL_REVISION: RPLY - OK.
.CnS: PROTOCOL_REVISION: 0x0006.
CnS: Send ROAMING.
.CnS: ROAMING: RPLY - NO.
...NETWORK: 1xEVDO Rev. A and 1XRTT.
..pppSetAuth: user address@hidden.
.pppSetAuth: pass .Om.g.....=8O..H.
.lcp_init: xmit_accm=0 0 0 0.
...Sending ATD#777. at 34283.84s.
.CONNECTING - OK.
pppOpen().
.pppOverSerialOpen: unit 0: Connecting.
.pppStart: unit 0.
..ppp_set_xaccm[0]: outACCM=0 0 0 0.
.ppp_send_config[0]: outACCM=FF FF FF FF.
...ppp_recv_config[0]: inACCM=0 0 0 0.
lcp_lowerup: asyncmap=0 0 0 0.
.LCP: lowerup state 0 (LS_INITIAL) -> 2 (LS_CLOSED).
auth_reset: 0.
.lcp_addci: L opt=2 0.
..lcp_addci: L opt=5 5F2457FF.
...lcp_addci: opt=7.
..lcp_addci: opt=8.
..pppInProc[0]: got 51 bytes.
pppInProc[0]: got 52 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,75,24.
fsm_rconfreq(LCP): Rcvd id 75 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,76,24.
fsm_rconfreq(LCP): Rcvd id 76 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,76,8..
.pppInput[0]: packet processed.
.pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,77,24.
fsm_rconfreq(LCP): Rcvd id 77 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,78,24.
fsm_rconfreq(LCP): Rcvd id 78 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,79,24.
fsm_rconfreq(LCP): Rcvd id 79 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,79,8..
.pppInput[0]: packet processed.
.pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,80,24.
fsm_rconfreq(LCP): Rcvd id 80 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,80,8..
.pppInput[0]: packet processed.
LCP: timeout resending Config-Request state=7 (LS_ACKRCVD).
lcp_addci: L opt=2 0.
..lcp_addci: L opt=5 5F2457FF.
...lcp_addci: opt=7.
..lcp_addci: opt=8.
..pppWrite[0]: len=46.
...fsm_sdata(LCP): Sent code 1,1,20..
.pppInProc[0]: got 45 bytes.
pppInput[0]: LCP len=20.
...fsm_input(LCP):2,1,20.
.fsm_rconfack(LCP): Rcvd id 1 state=6 (LS_REQSENT).
.lcp_acki: Ack.
.pppInput[0]: packet processed.
.pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,81,24.
fsm_rconfreq(LCP): Rcvd id 81 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,82,24.
fsm_rconfreq(LCP): Rcvd id 82 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,82,8..
.pppInput[0]: packet processed.
.pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,83,24.
fsm_rconfreq(LCP): Rcvd id 83 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
pppInProc[0]: got 52 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,84,24.
fsm_rconfreq(LCP): Rcvd id 84 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,84,8..
.pppInput[0]: packet processed.
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,85,24.
fsm_rconfreq(LCP): Rcvd id 85 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,85,8..
.pppInput[0]: packet processed.
.pppInProc[0]: got 52 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,86,24.
fsm_rconfreq(LCP): Rcvd id 86 st
LCP: timeout resending Config-Request state=7 (LS_ACKRCVD).
lcp_addci: L opt=2 0.
..lcp_addci: L opt=5 5F2457FF.
...lcp_addci: opt=7.
..lcp_addci: opt=8.
..pppWrite[0]: len=46.
...pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,87,24.
fsm_rconfreq(LCP): Rcvd id 87 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,87,8..
.pppInput[0]: packet processed.
.pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,88,24.
fsm_rconfreq(LCP): Rcvd id 88 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,88,8..
.pppInput[0]: packet processed.
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,89,24.
fsm_rconfreq(LCP): Rcvd id 89 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,89,8..
.pppInput[0]: packet processed.
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,90,24.
fsm_rconfreq(LCP): Rcvd id 90 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,90,8..
.pppI
pppInProc[0]: got 52 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,91,24.
fsm_rconfreq(LCP): Rcvd id 91 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,91,8..
.pppInput[0]: packet processed.
pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,92,24.
fsm_rconfreq(LCP): Rcvd id 92 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.fsm_sdata(LCP): Sent code 4,92,8..
.pppInput[0]: packet processed.
.pppInProc[0]: got 51 bytes.
pppInput[0]: LCP len=24.
...fsm_input(LCP):1,93,24.
fsm_rconfreq(LCP): Rcvd id 93 state=7 (LS_ACKRCVD).
lcp_reqci: rcvd MRU 1500 ASYNCMAP=0 MAGICNUMBER (749FB521) PCOMPRESSION.
...lcp_reqci:  ACCOMPRESSION.
.lcp_reqci: returning CONFREJ..
.LCP: timeout resending Config-Request state=7 (LS_ACKRCVD).
lcp_addci: L opt=2 0.
..lcp_addci: L opt=5 5F2457FF.
...lcp_addci: opt=7.
..lcp_addci: opt=8.
..pppWrite[0]: len=46.
...fsm_sdata(LCP): Sent code 1,1,20..
.pppInProc[0]: got 45 bytes.
pppInput[0]: LCP len=20.
...fsm_input(LCP):2,1,20.
.fsm_rconfack(LCP): Rcvd id 1 state=6 (LS_REQSENT).
.lcp_acki: Ack.
.pppInput[0]: packet processed.
pppSigHUP: unit 0 sig_hup -> pppHupCB.
.pppHupCB: unit 0.
..LCP: lowerdown state 7 (LS_ACKRCVD) -> 1 (LS_STARTING).
link_terminated: 0.
Connection terminated..
pppLinkTerminated: unit 0.
.pppLinkTerminated: unit 0: linkStatusCB=9D0084C4 errCode=0.
.
..In linkStatusCB(), errCode: -8.
linkStatusCB: PPPERR_PROTOCOL.
.pppLinkTerminated: finished..
..NO_CARRIER
reply via email to
[Prev in Thread] Current Thread [Next in Thread]