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 [email protected]. .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
_______________________________________________ lwip-users mailing list [email protected] https://lists.nongnu.org/mailman/listinfo/lwip-users
