[lwip-users] PPPoS : no response from modem after link established

[Sergey A. Borshch]

Hi.

I want to use ppp connection via SIM800C GPRS modem.
I use last lwIP sources from git HEAD.

The problem is identical to to described at 
https://lists.gnu.org/archive/html/lwip-users/2017-10/msg00084.html (but there 
was no solution proposed) - modem stops responding after status_cb: connected. I 
checked twice with logic analyzer - there is to responses to frames with 
proto=0x21. I tried two SIM cards from different mobile providers (one requires 
authentication, the other not) with exactly same result - I can get IP, DNS etc 
but no data exchange.

What did I missed to do?

Here is my ppp/modem log, can anyone point me to what's wrong with it?

00:00:04.10 GSM< AT
00:00:04.10 GSM> AT...OK.., response OK detected (result code 0)
00:00:04.10 GSM< AT+IFC=2,2
00:00:04.10 GSM> AT+IFC=2,2...OK.., response OK detected (result code 0)
00:00:04.10 GSM< ATE0
00:00:04.10 GSM> ATE0...OK.., response OK detected (result code 0)
00:00:04.10 GSM< AT+IPR=115200
00:00:04.11 GSM> ..OK.., response OK detected (result code 0)
00:00:04.12 GSM< AT+IPR=230400
00:00:04.12 GSM> ..OK.., response OK detected (result code 0)
00:00:04.13 GSM< AT+IPR=460800
00:00:04.13 GSM> ..OK.., response OK detected (result code 0)
00:00:04.14 GSM< AT+IPR=921600
00:00:04.15 GSM> ..ERROR.., response ERROR detected (result code 1)
00:00:04.15 GSM< AT+CMEE=1
00:00:04.15 GSM> ..OK.., response OK detected (result code 0)
00:00:04.15 GSM< AT+CREG=1
00:00:04.15 GSM> ..OK.., response OK detected (result code 0)
00:00:05.69 GSM> ..+CPIN: READY, response +CPIN: READY detected (result code 1)
00:00:05.69 GSM< AT+CPIN?
00:00:05.69 GSM> ....+CPIN: READY, response +CPIN: READY detected (result code 
1)
00:00:05.69 GSM> ....OK.., response OK detected (result code 0)
No PIN required
00:00:06.36 GSM> ..+CREG:, response +CREG: detected (result code 4) 2.
CREG state change detected: 2
00:00:06.36 GSM> ...+CREG:, response +CREG: detected (result code 4) 1.
CREG state change detected: 1
00:00:10.21 GSM> ...Call Ready.., response Call Ready detected (result code 0)
00:00:29.80 GSM init completed
00:00:29.80 GSM: no errors
ppp phase changed[0]: phase=0
00:00:29.80 GSM< AT+CGDCONT=1,"IP","internet.lmt.lv"
00:00:29.80 GSM> ..OK.., response OK detected (result code 0)
00:00:29.80 GSM< AT+CGQMIN=1,0,0,0,0,0
00:00:29.81 GSM> ..OK.., response OK detected (result code 0)
00:00:29.81 GSM< AT+CGQREQ=1,2,4,3,6,31
00:00:29.81 GSM> ..OK.., response OK detected (result code 0)
00:00:29.81 GSM< AT+CSQ
00:00:29.81 GSM> ..+CSQ: 23,0....OK.., response OK detected (result code 0)
00:00:29.81 GSM< ATD*99***1#
00:00:29.82 GSM> ..CONNECT, response CONNECT detected (result code 0)
ppp_connect[0]: holdoff=0
ppp phase changed[0]: phase=3
pppos_connect: unit 0: connecting
ppp_start[0]
ppp phase changed[0]: phase=6
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=0 CHAP=0 CHAP_MD5=0 CHAP_MS=0 CHAP_MS2=0 EAP=0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe9e79ca1> <pcomp> <accomp>]
00:00:29.82 GSM< 45 bytes:
 7E FF 7D 23 C0 21 7D 21 7D 21 7D 20 7D 34 7D 22
 7D 26 7D 20 7D 20 7D 20 7D 20 7D 25 7D 26 E9 E7
 9C A1 7D 27 7D 22 7D 28 7D 22 29 D7 7E
pppos_write[0]: len=24
ppp_start[0]: finished
00:00:29.82 GSM> 2 bytes
pppos_input[0]: got 2 bytes
pppos_input[0]: Dropping ACCM char <13>
pppos_input[0]: Dropping ACCM char <10>
00:00:30.82 GSM> 43 bytes
pppos_input[0]: got 43 bytes
rcvd [LCP ConfReq id=0x1 <asyncmap 0xa0000> <auth pap> <pcomp> <accomp>]
No auth is possible
sent [LCP ConfRej id=0x1 <auth pap>]
00:00:30.82 GSM< 23 bytes:
 7E FF 7D 23 C0 21 7D 24 7D 21 7D 20 7D 28 7D 23
 7D 24 C0 23 2C D4 7E
pppos_write[0]: len=12
00:00:30.83 GSM> 37 bytes
pppos_input[0]: got 37 bytes
rcvd [LCP ConfReq id=0x2 <asyncmap 0xa0000> <pcomp> <accomp>]
sent [LCP ConfAck id=0x2 <asyncmap 0xa0000> <pcomp> <accomp>]
00:00:30.83 GSM< 36 bytes:
 FF 7D 23 C0 21 7D 22 7D 22 7D 20 7D 2E 7D 22 7D
 26 7D 20 7D 2A 7D 20 7D 20 7D 27 7D 22 7D 28 7D
 22 EE 50 7E
pppos_write[0]: len=18
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe9e79ca1> <pcomp> <accomp>]
00:00:35.82 GSM< 45 bytes:
 7E FF 7D 23 C0 21 7D 21 7D 21 7D 20 7D 34 7D 22
 7D 26 7D 20 7D 20 7D 20 7D 20 7D 25 7D 26 E9 E7
 9C A1 7D 27 7D 22 7D 28 7D 22 29 D7 7E
pppos_write[0]: len=24
00:00:35.82 GSM> 29 bytes
pppos_input[0]: got 29 bytes
rcvd [LCP ConfNak id=0x1 <asyncmap 0xa0000>]
sent [LCP ConfReq id=0x2 <asyncmap 0xa0000> <magic 0xe9e79ca1> <pcomp> <accomp>]
00:00:35.82 GSM< 44 bytes:
 FF 7D 23 C0 21 7D 21 7D 22 7D 20 7D 34 7D 22 7D
 26 7D 20 7D 2A 7D 20 7D 20 7D 25 7D 26 E9 E7 9C
 A1 7D 27 7D 22 7D 28 7D 22 D1 4C 7E
pppos_write[0]: len=24
00:00:35.83 GSM> 61 bytes
pppos_input[0]: got 61 bytes
rcvd [LCP ConfAck id=0x2 <asyncmap 0xa0000> <magic 0xe9e79ca1> <pcomp> <accomp>]
netif_set_mtu[0]: mtu=1500
pppos_send_config[0]: out_accm=0 0 A 0
ppp_send_config[0]
pppos_recv_config[0]: in_accm=0 0 A 0
ppp_recv_config[0]
ppp phase changed[0]: phase=7
ppp phase changed[0]: phase=9
ccp_set[0]: is_open=1, is_up=0, receive_method=0, transmit_method=0
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>]
00:00:35.83 GSM< 35 bytes:
 FF 03 80 21 01 01 00 1C 02 06 00 2D 0F 01 03 06
 00 00 00 00 81 06 00 00 00 00 83 06 00 00 00 00
 55 15 7E
pppos_write[0]: len=32
rcvd [IPCP ConfReq id=0x1 <addr 192.168.254.254>]
sent [IPCP ConfAck id=0x1 <addr 192.168.254.254>]
00:00:35.83 GSM< 17 bytes:
 FF 03 80 21 02 01 00 0A 03 06 C0 A8 FE FE 5F 56
 7E
pppos_write[0]: len=14
00:00:35.83 GSM> 16 bytes
pppos_input[0]: got 16 bytes
rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
00:00:35.83 GSM< 29 bytes:
 FF 03 80 21 01 02 00 16 03 06 00 00 00 00 81 06
 00 00 00 00 83 06 00 00 00 00 DA 82 7E
pppos_write[0]: len=26
00:00:36.77 GSM> 28 bytes
pppos_input[0]: got 28 bytes
rcvd [IPCP ConfNak id=0x2 <addr 10.87.162.136> <ms-dns1 212.93.97.75> <ms-dns2 
212.93.96.2>]
sent [IPCP ConfReq id=0x3 <addr 10.87.162.136> <ms-dns1 212.93.97.75> <ms-dns2 
212.93.96.2>]
00:00:36.77 GSM< 30 bytes:
 7E FF 03 80 21 01 03 00 16 03 06 0A 57 A2 88 81
 06 D4 5D 61 4B 83 06 D4 5D 60 02 BE DB 7E
pppos_write[0]: len=26
00:00:36.77 GSM> 28 bytes
pppos_input[0]: got 28 bytes
rcvd [IPCP ConfAck id=0x3 <addr 10.87.162.136> <ms-dns1 212.93.97.75> <ms-dns2 
212.93.96.2>]
sifvjcomp[0]: VJ compress enable=0 slot=0 max slot=0
sifup[0]: err_code=0
PPP link status changed to 0
status_cb: Connected
local  IP address 10.87.162.136
remote IP address 192.168.254.254
primary   DNS address 212.93.97.75
secondary DNS address 212.93.96.2
ppp phase changed[0]: phase=10
00:01:02.00 GSM< 80 bytes:
 7E 21 45 00 00 49 00 00 00 00 FF 7D 31 00 00 0A
 57 A2 88 D4 5D 61 4B F2 30 00 35 00 35 00 00 F2
 30 01 00 00 01 00 00 00 00 00 00 10 68 74 74 70
 73 3A 2F 2F 73 61 76 61 6E 6E 61 68 06 6E 6F 6E
 67 6E 75 03 6F 72 67 00 00 01 00 01 EF 7D 33 7E
pppos_netif_output[0]: proto=0x21, len = 73
00:01:03.00 GSM< 79 bytes:
 7E 21 45 00 00 49 00 01 00 00 FF 7D 31 00 00 0A
 57 A2 88 D4 5D 61 4B F2 30 00 35 00 35 00 00 F2
 30 01 00 00 01 00 00 00 00 00 00 10 68 74 74 70
 73 3A 2F 2F 73 61 76 61 6E 6E 61 68 06 6E 6F 6E
 67 6E 75 03 6F 72 67 00 00 01 00 01 F2 2B 7E
pppos_netif_output[0]: proto=0x21, len = 73
00:01:04.00 GSM< 79 bytes:
 7E 21 45 00 00 49 00 02 00 00 FF 7D 31 00 00 0A
 57 A2 88 D4 5D 61 4B F2 30 00 35 00 35 00 00 F2
 30 01 00 00 01 00 00 00 00 00 00 10 68 74 74 70
 73 3A 2F 2F 73 61 76 61 6E 6E 61 68 06 6E 6F 6E
 67 6E 75 03 6F 72 67 00 00 01 00 01 D5 63 7E
pppos_netif_output[0]: proto=0x21, len = 73
00:01:06.00 GSM< 79 bytes:
 7E 21 45 00 00 49 00 03 00 00 FF 7D 31 00 00 0A
 57 A2 88 D4 5D 61 4B F2 30 00 35 00 35 00 00 F2
 30 01 00 00 01 00 00 00 00 00 00 10 68 74 74 70
 73 3A 2F 2F 73 61 76 61 6E 6E 61 68 06 6E 6F 6E
 67 6E 75 03 6F 72 67 00 00 01 00 01 C8 5B 7E
pppos_netif_output[0]: proto=0x21, len = 73


--
Regards,
  Sergey A. Borshch            mailto: address@hidden
    SB ELDI ltd. Riga, Latvia