[lwip-users] R: Solved: PPP no IP address assigned

[Bettega Stefano]

Hi all,
I have the same problem, but working with NO_SYS=0 (ucOS-II), and lwIP 1.4.1 
from stable repository branch.

My modem (Cinterion MC55i) connects to network by AT commands, then PPP session 
is started.
Authentication mode is set to PAP with empty user and password.
Following there is ppp dump with my serial reading dump (I see there are some 
AT command echo passed to PPP,
which in turns that discard them, but I think this is not a real problem).
Protocol negotiation seems to freeze after receiving a protocol reject packet:

[[[ lcp_rprotrej: Rcvd Protocol-Reject packet for 8021! ]]]

I applied suggested patch [2] to raise accepted NACKs to 100, but this doesn't 
seem to help anyway.
Some time after protocol reject packet, modem disconnect from network, I 
suppose because of PPP session
timeout, then PPP detects the error condition and closes. Callback is called 
with PPPERR_PROTOCOL, and
my task is able to detect that connection is lost. I then restart connection by 
hardware resetting modem,
sending configuration and dial commands again, but connection never comes up. 
Modem correctly works with
Windows, so this is not a modem/network problem.

Am I missing something? Anyone could help?

Thanks in advance,
Stefano

********************************************************************************************************

----------------
 0d 0a 43 4f 4e 4e 45 43 54 0d 0a 7e ff 7d 23 c0  ..CONNECT..~#▒
 21 7d 21 7d 23 7d 20 7d 39                       !}!}#} }9
----------------
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: Up event in state 2 (LS_CLOSED)!
LCP: lowerup state 2 (LS_CLOSED) -> 2 (LS_CLOSED)
auth_reset: 0
lcp_addci: L opt=2 0
lcp_addci: L opt=5 5B49D1AF
lcp_addci: opt=7
lcp_addci: opt=8
pppWrite[0]: len=44
fsm_sdata(LCP): Sent code 1,43,20.
LCP: sending Configure-Request, id 43
LCP: open state 2 (LS_CLOSED) -> 6 (LS_REQSENT)
pppStart: finished
----------------
 41 54 44 54 2a 39 39 2a 2a 2a 31 23 0d 0d 0a 43  ATDT*99***1#...C
 4f 4e 4e 45 43 54 0d 0a 7e ff 7d 23 c0 21 7d 21  ONNECT..~#▒!}!
 7d 23 7d 20 7d 39                                }#} }9
----------------
pppInProc[0]: got 38 bytes
----------------
 7d 22 7d 26 7d 20 7d 2a 7d 20 7d 20 7d 27 7d 22  }"}&} }*} } }'}"
 7d 28 7d 22 7d 25 7d 26 b2 5a 50 fb 7d 23 7d 25  }(}"}%}&▒ZP▒}#}%
 c2 23 7d 25 6d 7d 2d 7e                          ▒#}%m}-~
----------------
pppInProc[0]: got 40 bytes
pppInput[0]: LCP len=25
fsm_input(LCP):1,3,25
fsm_rconfreq(LCP): Rcvd id 3 state=6 (LS_REQSENT)
lcp_reqci: rcvd ASYNCMAP=A0000 PCOMPRESSION ACCOMPRESSION MAGICNUMBER (B25A50FB)
lcp_reqci: Nak AUTHTYPE CHAP not allowed
lcp_reqci: returning CONFNAK.
pppWrite[0]: len=22
fsm_sdata(LCP): Sent code 3,3,8.
pppInput[0]: packet processed
----------------
 7e ff 7d 23 c0 21 7d 23 2b 7d 20 7d 2a 7d 22 7d  ~#▒!}#+} }*}"}
 26 7d 20 7d 2a 7d 20 7d 20 65 43 7e              &} }*} } eC~
----------------
pppInProc[0]: got 28 bytes
pppInput[0]: LCP len=10
fsm_input(LCP):3,43,10
fsm_rconfnakrej(LCP): Rcvd id 43 state=6 (LS_REQSENT)
lcp_addci: L opt=2 A0000
lcp_addci: L opt=5 5B49D1AF
lcp_addci: opt=7
lcp_addci: opt=8
pppWrite[0]: len=43
fsm_sdata(LCP): Sent code 1,44,20.
LCP: sending Configure-Request, id 44
pppInput[0]: packet processed
----------------
 7e ff 7d 23 c0 21 7d 22 2c 7d 20 7d 34 7d 22 7d  ~#▒!}",} }4}"}
 26 7d 20 7d 2a 7d 20 7d 20 7d 25 7d 26 5b 49     &} }*} } }%}&[I
----------------
pppInProc[0]: got 31 bytes
----------------
 d1 af 7d 27 7d 22 7d 28 7d 22 ad 7d 2c 7e        ѯ}'}"}(}"▒},~
----------------
pppInProc[0]: got 14 bytes
pppInput[0]: LCP len=20
fsm_input(LCP):2,44,20
fsm_rconfack(LCP): Rcvd id 44 state=6 (LS_REQSENT)
lcp_acki: Ack
pppInput[0]: packet processed
----------------
 7e ff 7d 23 c0 21 7d 21 7d 23 7d 20 7d 39 7d 22  ~#▒!}!}#} }9}"
 7d 26 7d 20 7d 2a 7d 20 7d 20 7d 27 7d 22 7d 28  }&} }*} } }'}"}(
 7d 22 7d 25 7d 26 b2 5a 50 fb 7d 23 7d 25 c2 23  }"}%}&▒ZP▒}#}%▒#
 7d 25 6d 7d 2d 7e                                }%m}-~
----------------
pppInProc[0]: got 54 bytes
pppInput[0]: LCP len=25
fsm_input(LCP):1,3,25
fsm_rconfreq(LCP): Rcvd id 3 state=7 (LS_ACKRCVD)
lcp_reqci: rcvd ASYNCMAP=A0000 PCOMPRESSION ACCOMPRESSION MAGICNUMBER (B25A50FB)
lcp_reqci: Nak AUTHTYPE CHAP not allowed
lcp_reqci: returning CONFNAK.
pppWrite[0]: len=23
fsm_sdata(LCP): Sent code 3,3,8.
pppInput[0]: packet processed
----------------
 7e ff 7d 23 c0 21 7d 21 7d 25 7d 20 7d 38 7d 22  ~#▒!}!}%} }8}"
 7d 26 7d 20 7d 2a 7d 20 7d 20 7d 27 7d 22 7d 28  }&} }*} } }'}"}(
 7d 22 7d 25 7d 26 b2 5a 50 fb 7d 23 7d 24 c0 23  }"}%}&▒ZP▒}#}$▒#
 da                                               ▒
----------------
pppInProc[0]: got 49 bytes
----------------
 b8 7e                                            ▒~
----------------
pppInProc[0]: got 2 bytes
pppInput[0]: LCP len=24
fsm_input(LCP):1,5,24
fsm_rconfreq(LCP): Rcvd id 5 state=7 (LS_ACKRCVD)
lcp_reqci: rcvd ASYNCMAP=A0000 PCOMPRESSION ACCOMPRESSION MAGICNUMBER (B25A50FB)
lcp_reqci:  PAP (C023)
lcp_reqci: returning CONFACK.
pppWrite[0]: len=51
fsm_sdata(LCP): Sent code 2,5,24.
ppp_send_config[0]: outACCM=0 0 A 0
ppp_recv_config[0]: inACCM=0 0 A 0
link_established: unit 0; Lowering up all protocols...
IPCP: lowerup state 0 (LS_INITIAL) -> 2 (LS_CLOSED)
pppWrite[0]: len=29
fsm_sdata(IPCP): Sent code 1,22,22.
IPCP: sending Configure-Request, id 22
IPCP: open state 2 (LS_CLOSED) -> 6 (LS_REQSENT)
pppInput[0]: packet processed
IPCP: timeout resending Config-Request state=6 (LS_REQSENT)
pppWrite[0]: len=30
fsm_sdata(IPCP): Sent code 1,22,22.
IPCP: sending Configure-Request, id 22
----------------
 7e ff 7d 23 c0 21 7d 21 7d 25 7d 20 7d 38 7d 22  ~#▒!}!}%} }8}"
 7d 26 7d 20 7d 2a 7d 20 7d 20 7d 27 7d 22 7d 28  }&} }*} } }'}"}(
 7d 22 7d 25 7d 26 b2 5a 50 fb 7d 23 7d 24 c0 23  }"}%}&▒ZP▒}#}$▒#
 da b8 7e                                         ڸ~
----------------
pppInProc[0]: got 51 bytes
pppInput[0]: LCP len=24
fsm_input(LCP):1,5,24
fsm_rconfreq(LCP): Rcvd id 5 state=9 (LS_OPENED)
link_down: 0
IPCP: lowerdown state 6 (LS_REQSENT) -> 1 (LS_STARTING)
IPCP: close reason=LCP down state 1 (LS_STARTING) -> 0 (LS_INITIAL)
pppLinkDown: unit 0
pppRecvWakeup: unit 0
ppp_send_config[0]: outACCM=FF FF FF FF
ppp_recv_config[0]: inACCM=0 0 A 0
auth_reset: 0
lcp_addci: L opt=2 0
lcp_addci: L opt=5 83051F0F
lcp_addci: opt=7
lcp_addci: opt=8
pppWrite[0]: len=47
fsm_sdata(LCP): Sent code 1,45,20.
LCP: sending Configure-Request, id 45
lcp_reqci: rcvd ASYNCMAP=A0000 PCOMPRESSION ACCOMPRESSION MAGICNUMBER (B25A50FB)
lcp_reqci:  PAP (C023)
lcp_reqci: returning CONFACK.
pppWrite[0]: len=51
fsm_sdata(LCP): Sent code 2,5,24.
pppInput[0]: packet processed
----------------
 7e ff 7d 23 c0 21 7d 23 2d 7d 20 7d 2a 7d 22 7d  ~#▒!}#-} }*}"}
 26 7d 20 7d 2a 7d                                &} }*}
----------------
pppInProc[0]: got 22 bytes
----------------
 20 7d 20 7a e7 7e                                 } z▒~
----------------
pppInProc[0]: got 6 bytes
pppInput[0]: LCP len=10
fsm_input(LCP):3,45,10
fsm_rconfnakrej(LCP): Rcvd id 45 state=8 (LS_ACKSENT)
lcp_addci: L opt=2 A0000
lcp_addci: L opt=5 83051F0F
lcp_addci: opt=7
lcp_addci: opt=8
pppWrite[0]: len=46
fsm_sdata(LCP): Sent code 1,46,20.
LCP: sending Configure-Request, id 46
pppInput[0]: packet processed
LCP: timeout resending Config-Request state=8 (LS_ACKSENT)
lcp_addci: L opt=2 A0000
lcp_addci: L opt=5 83051F0F
lcp_addci: opt=7
lcp_addci: opt=8
pppWrite[0]: len=47
fsm_sdata(LCP): Sent code 1,46,20.
LCP: sending Configure-Request, id 46
----------------
 7e ff 7d 23 c0 21 7d 22 2e 7d 20 7d 34 7d 22 7d  ~#▒!}".} }4}"}
 26 7d 20 7d 2a 7d 20 7d 20 7d 25 7d 26 83 7d 25  &} }*} } }%}&▒}%
 7d 3f 7d 2f 7d 27 7d 22 7d 28 7d 22 70 58 7e     }?}/}'}"}(}"pX~
----------------
pppInProc[0]: got 47 bytes
pppInput[0]: LCP len=20
fsm_input(LCP):2,46,20
fsm_rconfack(LCP): Rcvd id 46 state=8 (LS_ACKSENT)
lcp_acki: Ack
ppp_send_config[0]: outACCM=0 0 A 0
ppp_recv_config[0]: inACCM=0 0 A 0
link_established: unit 0; Lowering up all protocols...
IPCP: lowerup state 0 (LS_INITIAL) -> 2 (LS_CLOSED)
pppWrite[0]: len=29
fsm_sdata(IPCP): Sent code 1,23,22.
IPCP: sending Configure-Request, id 23
IPCP: open state 2 (LS_CLOSED) -> 6 (LS_REQSENT)
pppInput[0]: packet processed
IPCP: timeout resending Config-Request state=6 (LS_REQSENT)
pppWrite[0]: len=30
fsm_sdata(IPCP): Sent code 1,23,22.
IPCP: sending Configure-Request, id 23
----------------
 7e ff 03 c0 21 08 06 00 7d 31 80 21 01 17 00 16  ~▒!...}1▒!....
 03 06 00 00 00 00 81 f3 14 7e                    ......▒▒.~
----------------
pppInProc[0]: got 26 bytes
pppInput[0]: LCP len=17
fsm_input(LCP):8,6,17
fsm_input(LCP): default:
lcp_rprotrej: Rcvd Protocol-Reject packet for 8021!
IPCP: lowerdown state 6 (LS_REQSENT) -> 1 (LS_STARTING)
pppInput[0]: packet processed

-------------------------------- here comes a pause..... 
--------------------------------

----------------
 0d 0a 4e 4f 20 43 41 52 52 49 45 52 0d 0a        ..NO CARRIER..
----------------
pppInProc[0]: got 14 bytes
LCP: timeout sending Terminate-Request state=5 (LS_STOPPING)
link_terminated: 0
Connection terminated.
pppLinkTerminated: unit 0
pppRecvWakeup: unit 0
pppLinkTerminated: unit 0: linkStatusCB=08040199 errCode=0
linkStatusCB ctx = 0x6804A3E0, errCode = -8, arg = 0x00000000: PPPERR_PROTOCOL
pppLinkTerminated: finished.
pppClose() called
pppClose: unit 0 kill_link -> pppStop
pppStop: unit 0
LCP: close reason=User request state 3 (LS_STOPPED) -> 2 (LS_CLOSED)
pppRecvWakeup: unit 0

********************************************************************************************************

-----Messaggio originale-----
Hello Michael,


On Thu, Apr 02, 2015 at 10:48:09AM +0200, Michael Waeber wrote:
>
> Many thanks for your help! Now I've managed to get an IP address
> assigned. Details see below.

Yeah!, happy to hear that.


> On 01.04.2015 21:56, Sylvain Rochet wrote:
> > On Wed, Apr 01, 2015 at 05:27:41PM +0200, Michael Waeber wrote:
> > > On 01.04.2015 14:02, Sylvain Rochet wrote:
> > > >
> > > > Looks like your lwIP timeouts are not working or you don't have enough
> > > > of them, PPP needs a lot of timeouts, could you check that first ?
> > >
> > > What do you exactly mean with "timeouts"? We have set NO_SYS=1, so
> > > there is no such thing as OS timeout. Is the PPP part not driven by
> > > the TCP main task tcp_tmr()? Do i have to call another function for
> > > PPP if NO_SYS=1?
> >
> > You don't have to, tcp_tmr() should do the job.
>
> It does not, see below.

I misread, of course it does not, this is TCP_tmr… that's only apply for
TCP sessions.


> > It really should retry a few seconds later, could you dig what is
> > happening in IPCP (ipcp.c/fsm.c) ?
>
> This was the crucial hint!
>
> ipcp.c/fsm.c isn't run if no answer is received and only tcp_tmr() is
> called.
>
> We have called the various timers tcp_tmr, etharp_tmr, ip_reass_tmr and
> others from our main loop. This was OK back in pre 1.4.x time and
> obviously works if only ethernet is used.
>
> Now I've changed to call sys_check_timeouts()

Indeed *_tmr() are deprecated[1] AFAIK, you have to use
sys_check_timeouts().


> and now fsm_timeout() in fsm.c is called. The IPCP request is repeated
> after 6.8 s. To the second request the modem answers with a request on
> his part. The IP address is assigned and the callback is called with
> PPPERR_NONE.

IPCP was not designed to wait until the modem knows its IP from the
network mainly because that was not necessary for dialup where the PPP
session is end to end. That's also true for any other PPP protocol,
there is no such concept of telling the remote to wait in PPP.

Some modems are using NAK and we have a workaround for that[2], your
choose to not answer at all, which is the method I prefer, you can
decrease FSM_DEFTIMEOUT and increase FSM_DEFMAXCONFREQS so your session
will come up a little faster.

Sylvain


[1] 
http://git.savannah.gnu.org/cgit/lwip/lwip-contrib.git/commit/?id=9a8c3c0283b1481d436d3b360fd07ef05ff30662
[2] http://git.savannah.gnu.org/cgit/lwip.git/tree/src/netif/ppp/ipcp.c#n606


---
Questa e-mail è stata controllata per individuare virus con Avast antivirus.
https://www.avast.com/antivirus