Re: [lwip-users] Weird PPP behavior

[Sylvain Rochet]

Hi,

On Sun, Feb 28, 2016 at 08:03:31PM +0300, Gennady Shmakov wrote:
> Hello,
> I'm using latest master branch lwip from 28 Feb 2016 in FreeRTOS
> environment.
> I have a problem with PPPoS when interfacing with 3G modem.
> Sometimes ppp netif cannot authenticate/obtain IP address.
> What makes it even more difficult to solve is that it only happen in about
> 30-40% cases.
> 
> Attached logs for both cases:
> ppp_dbg_err.txt - connections attempts with this problem.
> ppp_dbg_ok.txt - when everything connects just fine.
> 
> Could someone give me a hint if this issues can be due to PPP
> misconfiguration in lwipopts.h (I didnt change anything in PPP
> configuration, all settings are default).
> 
> -----
> Regards,
> Gennady
> mob. +7 985 8181210

> ppp phase changed[0]: phase=0
> ppp_connect[0]: holdoff=0
> ppp phase changed[0]: phase=1
> pppos_connect: unit 0: connecting
> ppp_start[0]
> pppos_send_config[0]: out_accm=FF FF FF FF
> ppp_send_config[0]
> pppos_recv_config[0]: in_accm=FF FF FF FF
> ppp_recv_config[0]
> ppp: auth protocols: PAP=1
> sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xcf2759c0> <pcomp> <accomp>]
> pppos_write[0]: len=24
> ppp_start[0]: finished
> pppos_input[0]: got 108 bytes
> rcvd [LCP ConfReq id=0x1 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x543> <auth 0xc223 05>]
> sent [LCP ConfNak id=0x1 <auth pap>]
> pppos_write[0]: len=12
> rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xcf2759c0> <pcomp> <accomp>]
> pppos_input[0]: got 44 bytes
> pppos_input[0]: got 61 bytes
> pppos_input[0]: Dropping bad fcs 0x9e4f proto=0xc021
> pppos_input_drop: pbuf len=21, addr 2001afe8

Bad checksum here, this can't really happen if your 3G is on the same 
board.


> rcvd [LCP ConfReq id=0x2 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x543> <auth pap>]
> sent [LCP ConfAck id=0x2 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x543> <auth pap>]
> pppos_write[0]: len=32
> netif_set_mtu[0]: mtu=1500
> pppos_send_config[0]: out_accm=0 0 0 0
> ppp_send_config[0]
> pppos_recv_config[0]: in_accm=0 0 0 0
> ppp_recv_config[0]
> ppp phase changed[0]: phase=5
> sent [PAP AuthReq id=0x1 user="" password=""]
> pppos_write[0]: len=10
> pppos_input[0]: got 61 bytes
> rcvd [LCP ConfReq id=0x2 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x543> <auth pap>]
> ppp phase changed[0]: phase=4
> pppos_send_config[0]: out_accm=FF FF FF FF
> ppp_send_config[0]
> pppos_recv_config[0]: in_accm=0 0 0 0
> ppp_recv_config[0]
> ppp: auth protocols: PAP=1
> sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0xfdd6a1d8> <pcomp> <accomp>]
> pppos_write[0]: len=24
> sent [LCP ConfAck id=0x2 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x543> <auth pap>]
> pppos_write[0]: len=32
> pppos_input[0]: got 32 bytes
> rcvd [PAP AuthAck id=0x1 "Greetings!!"]
> Discarded non-LCP packet when LCP not open
> rcvd [IPCP ConfReq id=0x1]
> Discarded non-LCP packet when LCP not open
> pppos_input[0]: got 32 bytes
> rcvd [PAP AuthAck id=0x1 "Greetings!!"]
> Discarded non-LCP packet when LCP not open
> rcvd [IPCP ConfReq id=0x1]
> Discarded non-LCP packet when LCP not open

Your modem start Ack'ing a PAP auth we don't even started because LCP 
negotiation is not finished yet… (finished in a sense it negotiated enough
stuff to be UP, nothing is never finished in PPP).


> pppos_input[0]: got 80 bytes
> rcvd [LCP ConfReq id=0x3 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x544> <auth 0xc223 05>]
> sent [LCP ConfNak id=0x3 <auth pap>]
> pppos_write[0]: len=12
> rcvd [LCP ConfNak id=0x2]
> sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0xfdd6a1d8> <pcomp> <accomp>]
> pppos_write[0]: len=24
> pppos_input[0]: got 16 bytes
> pppos_input[0]: got 62 bytes
> pppos_input[0]: Dropping bad fcs 0x3f81 proto=0xc021
> pppos_input_drop: pbuf len=7, addr 2001acb8

Bad checksum here, this can't really happen if your 3G is on the same
board.


> rcvd [LCP ConfReq id=0x4 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x544> <auth pap>]
> sent [LCP ConfAck id=0x4 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x544> <auth pap>]
> pppos_write[0]: len=32
> pppos_input[0]: got 62 bytes
> rcvd [LCP ConfReq id=0x4 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x544> <auth pap>]
> sent [LCP ConfAck id=0x4 <accomp> <pcomp> <asyncmap 0x0> <mru 1500> <magic 
> 0x544> <auth pap>]
> pppos_write[0]: len=32
> pppos_input[0]: got 45 bytes
> rcvd [LCP ConfAck id=0x3 <asyncmap 0x0> <magic 0xfdd6a1d8> <pcomp> <accomp>]
> netif_set_mtu[0]: mtu=1500
> pppos_send_config[0]: out_accm=0 0 0 0
> ppp_send_config[0]
> pppos_recv_config[0]: in_accm=0 0 0 0
> ppp_recv_config[0]
> ppp phase changed[0]: phase=5
> sent [PAP AuthReq id=0x2 user="" password=""]
> pppos_write[0]: len=10
> pppos_input[0]: got 45 bytes
> rcvd [LCP ConfAck id=0x3 <asyncmap 0x0> <magic 0xfdd6a1d8> <pcomp> <accomp>]
> pppos_input[0]: got 32 bytes
> rcvd [PAP AuthAck id=0x2 "Greetings!!"]
> Remote message: Greetings!!
> PAP authentication succeeded
> ppp phase changed[0]: phase=7
> sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> rcvd [IPCP ConfReq id=0x1]
> sent [IPCP ConfNak id=0x1 <addr 0.0.0.Àpppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x3 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x3 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x4 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x3 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x4 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x5 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x4 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x5 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x6 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x6 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x7 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x3]
> sent [IPCP ConfAck id=0x3]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x4]
> sent [IPCP ConfAck id=0x4]
> pppos_write[0]: len=8
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x7 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x8 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x8 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x9 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x9 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0xa <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0xa <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0xb <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0xb <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0xc <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0xc <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0xd <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x5]
> sent [IPCP ConfAck id=0x5]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x6]
> sent [IPCP ConfAck id=0x6]
> pppos_write[0]: len=8
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0xd <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0xe <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0xe <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0xf <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0xf <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x10 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x10 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x11 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x11 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x12 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x12 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x13 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x12 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x7]
> sent [IPCP ConfAck id=0x7]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x7]
> sent [IPCP ConfAck id=0x7]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x8]
> sent [IPCP ConfAck id=0x8]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x8]
> sent [IPCP ConfAck id=0x8]
> pppos_write[0]: len=8
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x13 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x14 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x13 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x14 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x15 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x14 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x15 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x16 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x15 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x16 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x17 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x16 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x17 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x18 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x17 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x18 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x19 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x18 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x9]
> sent [IPCP ConfAck id=0x9]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0x9]
> sent [IPCP ConfAck id=0x9]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xa]
> sent [IPCP ConfAck id=0xa]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xa]
> sent [IPCP ConfAck id=0xa]
> pppos_write[0]: len=8
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x19 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x1a <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x19 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x1a <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x1b <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x1a <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x1b <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x1c <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x1c <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x1d <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x1d <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x1e <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x1e <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x1f <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xb]
> sent [IPCP ConfAck id=0xb]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xc]
> sent [IPCP ConfAck id=0xc]
> pppos_write[0]: len=8
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x1f <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x20 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x20 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x21 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x21 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x22 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x22 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x23 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x23 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x24 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x24 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x25 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xd]
> sent [IPCP ConfAck id=0xd]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xe]
> sent [IPCP ConfAck id=0xe]
> pppos_write[0]: len=8
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x25 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x26 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x26 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x27 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x27 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x28 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x28 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x29 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x29 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x2a <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2a <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x2b <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2a <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xf]
> sent [IPCP ConfAck id=0xf]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP ConfReq id=0xf]
> sent [IPCP ConfAck id=0xf]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermReq id=0x10]
> sent [IPCP TermAck id=0x10]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermReq id=0x10]
> sent [IPCP TermAck id=0x10]
> pppos_write[0]: len=8
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2b <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x2c <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2b <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2c <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x2d <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2c <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2d <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x2e <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2d <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2e <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x2f <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2e <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2f <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x30 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x2f <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x30 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 28 bytes
> rcvd [IPCP ConfNak id=0x30 <compress VJ 0f 01> <ms-dns1 0.0.0.0> <ms-dns2 
> 0.0.0.0>]
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermReq id=0x11]
> sent [IPCP TermAck id=0x11]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermReq id=0x11]
> sent [IPCP TermAck id=0x11]
> pppos_write[0]: len=8
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> sent [IPCP ConfReq id=0x31 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 
> 0.0.0.0> <ms-dns2 0.0.0.0>]
> pppos_write[0]: len=32
> pppos_input[0]: got 10 bytes
> rcvd [IPCP TermAck id=0x31]
> IPCP: timeout sending Config-Requests
> ppp phase changed[0]: phase=9
> ppp phase changed[0]: phase=4
> pppos_send_config[0]: out_accm=FF FF FF FF
> ppp_send_config[0]
> pppos_recv_config[0]: in_accm=0 0 0 0
> ppp_recv_config[0]
> sent [LCP TermReq id=0x4 "No network protocols running"]

We are repeatedly sending IPCP request but your modem never answered 
with a valid IP address, we give up after trying over and over.

This is usually the behavior observed when a 3G modem is currently 
connecting to a mobile network, except it finishes with a success ;-)


> pppos_write[0]: len=36
> pppos_input[0]: got 17 bytes
> rcvd [LCP TermAck id=0x4]
> ppp phase changed[0]: phase=10
> Connection terminated.
> ppp phase changed[0]: phase=0
> ppp_link_terminated[0]
> ppp_end[0]


Long story short: your 3G modem firmware is written by monkeys.

Sylvain

signature.asc
Description: Digital signature