ARMmbed / mbed-os

Arm Mbed OS is a platform operating system designed for the internet of things
https://mbed.com
Other
4.65k stars 2.97k forks source link

PPP connection hangs with u-blox SARA-R500S #14510

Open jdbruijn opened 3 years ago

jdbruijn commented 3 years ago

Description of defect

Opening a PPP connection with the u-blox SARA-R500S, using LTE Cat M1, hangs until it's timed out. I have noted two things:

  1. APN logged as response on the AT+CGDCONT? command is iot.t-mobile.nl.mnc040.mcc901.gprs, while I've configured it as iot.t-mobile.nl. I believe this is no issue and simply some operator identifier, but please correct me if I'm wrong. I think I've read this somewhere but can't remember and quickly find where.
  2. Weird characters after CONNECT. In the small log section below there are weird characters after the CONNECT<cr><ln> response to start PPP, which I don't see with the other modems we use (u-blox SARA-R410M and u-blox SARA-G350).

Please see the full log at the end, including the expected behaviour from the R410M log. We're using basically the same code with the u-blox SARA-R410M and are able to establish a PPP connection normally with the same SIM, provider and settings.

[INFO][CELL]: CellularContext PPP connect
[INFO][CELL]: AT TX ( 9): ATD*99***
[INFO][CELL]: AT TX ( 1): 1
[INFO][CELL]: AT TX ( 1): #
[INFO][CELL]: AT TX ( 1): <cr>
[INFO][CELL]: AT RX ( 7): <cr><ln>CONNE
[INFO][CELL]: AT RX (27): CT<cr><ln>~<FF>}#<C0>!}!} } }6}"}&} } }
[DBG ][CELL]: ppp_status_cb: event 0, ptr 3
[DBG ][CELL]: callback: 0, ptr: 3
[DBG ][CELL]: process_oob, filehandle is not usable, return...
Connection timed out (180000 ms)
Same log section but with the u-blox SARA-R410M ``` [INFO][CELL]: CellularContext PPP connect [INFO][CELL]: AT TX ( 9): ATD*99*** [INFO][CELL]: AT TX ( 1): 1 [INFO][CELL]: AT TX ( 1): # [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (10): CONNECT [DBG ][CELL]: ppp_status_cb: event 0, ptr 3 [DBG ][CELL]: callback: 0, ptr: 3 [DBG ][CELL]: process_oob, filehandle is not usable, return... [DBG ][CELL]: process_oob, filehandle is not usable, return... [DBG ][CELL]: process_oob, filehandle is not usable, return... [DBG ][CELL]: ppp_status_cb: event 0, ptr 1 [DBG ][CELL]: callback: 0, ptr: 1 Connection status: 3, cellular status: 24 Global IP received but waiting for local IP (48707 ms) Connected as X.X.X.X in 48811 ms ```

Things I've already tried and additional observations.

  1. PPP connect using CGDATA.
  2. Using different MNO profiles (1, 90, 100).
  3. Increasing stack sizes (PPP to 2048, TCPIP to 4096).
  4. We're connected/attached to the cellular network.
  5. Additional logging shows that nsapi_ppp_connect is returning with OK code.
  6. We're getting process_oob, filehandle is not usable, return... only once vs three times with the R410M.
  7. ppp_status_cb isn't called after process_oob, filehandle is not usable, return... log.

Target(s) affected by this defect ?

u-blox?

Toolchain(s) (name and version) displaying this defect ?

arm-none-eabi-gcc --version
arm-none-eabi-gcc (GNU Arm Embedded Toolchain 9-2020-q2-update) 9.3.1 20200408 (release)
Copyright (C) 2019 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

What version of Mbed-os are you using (tag or sha) ?

6.4.0

What version(s) of tools are you using. List all that apply (E.g. mbed-cli)

$ mbed --version
1.10.5

How is this defect reproduced ?

Essentially try to establish a cellular connection with an u-blox SARA-R500S module in non-blocking mode.

mbed::CellularContext::get_default_instance()->connect();

The full logs below show the AT commands and everything to reproduce this further. Also the expected behaviour is shown with the R410M logs.

cellular AT logs from u-blox SARA-R500S ``` [DBG ][TLSW]: mbedtls_ssl_conf_ca_chain() [INFO][CELL]: New CellularContext (0x2000cae0) [INFO][CELL]: CellularContext set blocking 0 Waiting for connect connected 0, conn status 1 [INFO][CELL]: CellularContext set blocking 0 [INFO][CELL]: CellularContext connect Connection status: 2, cellular status: 0 [DBG ][CELL]: callback: 4106, err: 0, data: 4096 Connection status: 2, cellular status: 0 [INFO][CELL]: Start connecting (timeout 1000 ms) [INFO][CELL]: AT TX ( 2): AT [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 [INFO][CELL]: AT TX ( 2): AT [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 [DBG ][CELL]: Init => Power [DBG ][CELL]: callback: 4106, err: 0, data: 4096 Connection status: 2, cellular status: 0 [INFO][CELL]: Modem power ON (timeout 1000 ms) CellularModuleDriver::hard_power_on [DBG ][CELL]: Power => Device ready [DBG ][CELL]: AT OoB readable 1, len 0 [INFO][CELL]: AT RX ( 1): <00> [DBG ][CELL]: AT OoB done [DBG ][CELL]: callback: 4106, err: 0, data: 4096 Connection status: 2, cellular status: 0 [DBG ][CELL]: Device was not ready, calling soft_power_on() CellularModuleDriver::soft_power_on [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 4): ATE0 [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 Last error NOK: -3012 [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 4): ATE0 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 3): ATE [INFO][CELL]: AT RX ( 8): 0OK [INFO][CELL]: AT TX ( 9): AT+CMEE=1 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: AT TX (12): AT+UMNOPROF? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (14): +UMNOPROF: 1 [INFO][CELL]: AT RX (13): ,,1,1OK [INFO][CELL]: AT TX ( 8): AT+CFUN? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): +CFUN: 1,7 [INFO][CELL]: AT RX ( 5): OK CFUN already [INFO][CELL]: AT TX ( 7): AT+CGMI [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (16): u-bloxOK [INFO][CELL]: Modem manufacturer: u-blox [INFO][CELL]: AT TX ( 7): AT+CGMM [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (20): SARA-R500SOK [INFO][CELL]: Modem model: SARA-R500S [INFO][CELL]: AT TX ( 7): AT+CGMR [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): 02.06OK [INFO][CELL]: Modem revision: 02.06 [INFO][CELL]: Modem ready [DBG ][CELL]: callback: 4096, err: 0, data: 4096 Connection status: 2, cellular status: 1 [DBG ][CELL]: Device ready => SIM pin [DBG ][CELL]: callback: 4106, err: 0, data: 4097 Connection status: 2, cellular status: 1 [INFO][CELL]: Setup SIM (timeout 1000 ms) [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 8): AT+CPIN? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (16): +CME ERROR: 3 [INFO][CELL]: AT RX ( 1): [WARN][CELL]: AT error code 3 [DBG ][CELL]: AT error -3012 [WARN][CELL]: SIM state unknown [INFO][CELL]: Waiting for SIM (err while reading)... [DBG ][CELL]: SIM pin: retry 0/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4097, retrycount: 0 Connection status: 2, cellular status: 1 [INFO][CELL]: Continue after 1 seconds [DBG ][CELL]: callback: 4106, err: 0, data: 4097 Connection status: 2, cellular status: 1 [INFO][CELL]: Setup SIM (timeout 1000 ms) [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 8): AT+CPIN? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 4): +C [INFO][CELL]: AT RX (18): PIN: READYOK [INFO][CELL]: AT TX (12): AT+UMNOPROF? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 7): +UMNO [INFO][CELL]: AT RX (20): PROF: 1,,1,1OK [INFO][CELL]: SIM is ready [DBG ][CELL]: callback: 4097, err: 0, data: 0 Connection status: 2, cellular status: 2 [DBG ][CELL]: Automatic network registration [INFO][CELL]: AT TX ( 8): AT+COPS? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): +COP [INFO][CELL]: AT RX (12): S: 0OK [DBG ][CELL]: STM: set_registration: 0, plmn: NULL [INFO][CELL]: AT TX ( 9): AT+CEREG= [INFO][CELL]: AT TX ( 1): 2 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: AT TX ( 8): AT+CREG= [INFO][CELL]: AT TX ( 1): 2 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: AT TX ( 9): AT+CGACT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 4): +C [INFO][CELL]: AT RX (30): GACT: 0,0+CGACT: 1,0OK [INFO][CELL]: AT RX ( 2): [INFO][CELL]: AT TX ( 9): AT+CGATT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (19): +CGATT: 0OK [INFO][CELL]: AT TX (10): AT+CGEREP= [INFO][CELL]: AT TX ( 1): 1 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: SIM pin => Signal quality [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (13): +CSQ: 99,99 [INFO][CELL]: AT RX ( 8): OK [DBG ][CELL]: callback: 4104, err: 0, data: -1 Connection status: 2, cellular status: 2 [DBG ][CELL]: Signal quality => Registering network [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (17): +CSQ: 99,99 [INFO][CELL]: AT RX ( 4): OK [DBG ][CELL]: callback: 4104, err: 0, data: -1 Connection status: 2, cellular status: 2 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (12): +CEREG: 2, [INFO][CELL]: AT RX ( 9): 0OK [DBG ][CELL]: +CEREG: NotRegistered, LAC -1, cell -1, RAT unknown [INFO][CELL]: Network registration (timeout 180000 ms) [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [DBG ][CELL]: Automatic network registration [INFO][CELL]: AT TX ( 8): AT+COPS? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (16): +COPS: 0OK [INFO][CELL]: AT RX ( 2): [DBG ][CELL]: Registering network: retry 0/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4098, retrycount: 0 Connection status: 2, cellular status: 2 [INFO][CELL]: Continue after 1 seconds [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (12): +CSQ: 99,9 [INFO][CELL]: AT RX ( 9): 9OK [DBG ][CELL]: callback: 4104, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (13): +CEREG: 2,0 [INFO][CELL]: AT RX ( 8): OK [DBG ][CELL]: +CEREG: NotRegistered, LAC -1, cell -1, RAT unknown [INFO][CELL]: Network registration (timeout 180000 ms) [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [DBG ][CELL]: Registering network: retry 1/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4098, retrycount: 1 Connection status: 2, cellular status: 2 [INFO][CELL]: Continue after 2 seconds [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 5): +CS [INFO][CELL]: AT RX (16): Q: 99,99OK [DBG ][CELL]: callback: 4104, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (16): +CEREG: 2,0 [DBG ][CELL]: +CEREG: NotRegistered, LAC -1, cell -1, RAT unknown [INFO][CELL]: AT RX ( 5): OK [INFO][CELL]: Network registration (timeout 180000 ms) [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [DBG ][CELL]: Registering network: retry 2/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4098, retrycount: 2 Connection status: 2, cellular status: 2 [INFO][CELL]: Continue after 4 seconds [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): +CSQ: 99,99 [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: callback: 4104, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (14): +CEREG: 2,0 [INFO][CELL]: AT RX ( 7): OK [DBG ][CELL]: +CEREG: NotRegistered, LAC -1, cell -1, RAT unknown [INFO][CELL]: Network registration (timeout 180000 ms) [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [DBG ][CELL]: Registering network: retry 3/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4098, retrycount: 3 Connection status: 2, cellular status: 2 [INFO][CELL]: Continue after 8 seconds [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): +CSQ: 99,99 [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: callback: 4104, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (14): +CEREG: 2,0 [INFO][CELL]: AT RX ( 7): OK [DBG ][CELL]: +CEREG: NotRegistered, LAC -1, cell -1, RAT unknown [INFO][CELL]: Network registration (timeout 180000 ms) [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [DBG ][CELL]: Registering network: retry 4/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4098, retrycount: 4 Connection status: 2, cellular status: 2 [INFO][CELL]: Continue after 16 seconds [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (11): +CSQ: 99, [INFO][CELL]: AT RX (10): 99OK [DBG ][CELL]: callback: 4104, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (21): +CEREG: 2,0OK [DBG ][CELL]: +CEREG: NotRegistered, LAC -1, cell -1, RAT unknown [INFO][CELL]: Network registration (timeout 180000 ms) [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 2 [DBG ][CELL]: Registering network: retry 5/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4098, retrycount: 5 Connection status: 2, cellular status: 2 [INFO][CELL]: Continue after 32 seconds [DBG ][CELL]: AT OoB readable 1, len 0 [INFO][CELL]: AT RX (32): +CREG: 7,"552a","019a5902",7 [DBG ][CELL]: +CREG: RegisteredSMSOnlyRoaming, LAC 21802, cell 26892546, E_UTRAN [DBG ][CELL]: callback: 4101, err: 0, data: 7 Connection status: 2, cellular status: 32 [DBG ][CELL]: callback: 4098, err: 0, data: 7 Connection status: 2, cellular status: 14 [DBG ][CELL]: callback: 4100, err: 0, data: 26892546 Connection status: 2, cellular status: 24 [INFO][CELL]: AT RX (32): +CEREG: 5,"552a","019a5902",7 [INFO][CELL]: AT RX (24): +CGEV: ME PDN ACT 1 [DBG ][CELL]: +CEREG: RegisteredRoaming, LAC 21802, cell 26892546, E_UTRAN [DBG ][CELL]: callback: 4098, err: 0, data: 5 [DBG ][CELL]: creg event, discard... Connection status: 2, cellular status: 12 [DBG ][CELL]: AT OoB done [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (14): +CSQ: 13,2 [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: callback: 4104, err: 0, data: 4098 Connection status: 2, cellular status: 12 [INFO][CELL]: RSSI -87 dBm [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Connection status: 2, cellular status: 12 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (14): +CEREG: 2,5, [INFO][CELL]: AT RX (27): "552a","019a5902",7OK [DBG ][CELL]: +CEREG: RegisteredRoaming, LAC 21802, cell 26892546, E_UTRAN [INFO][CELL]: Roaming 1 Registered 1 [DBG ][CELL]: callback: 4098, err: 0, data: 5 [INFO][CELL]: Registering network => Attaching network Connection status: 2, cellular status: 6 [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (17): +CSQ: 13,2O [INFO][CELL]: AT RX ( 3): K [DBG ][CELL]: callback: 4104, err: 0, data: -1 Connection status: 2, cellular status: 6 [INFO][CELL]: RSSI -87 dBm [DBG ][CELL]: callback: 4106, err: 0, data: 4102 Connection status: 2, cellular status: 6 [INFO][CELL]: Attaching network (timeout 60000 ms) [INFO][CELL]: AT TX ( 9): AT+CGATT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (14): +CGATT: 1 [INFO][CELL]: AT RX ( 5): OK [DBG ][CELL]: callback: 4102, err: 0, data: 1 Connection status: 2, cellular status: 38 [INFO][CELL]: AT TX (11): AT+CGDCONT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (10): +CGDCONT [INFO][CELL]: AT RX (24): : 0,"IPV4V6","iot.t-mobi [INFO][CELL]: AT RX (32): le.nl","0.0.0.0 0.0.0.0.0.0.0.0. [DBG ][CELL]: CID 0 APN "iot.t-mobile.nl" [INFO][CELL]: AT RX (32): 0.0.0.0.0.0.0.0",0,0,0,0,0,0,0,0 [INFO][CELL]: AT RX (32): ,0,0+CGDCONT: 1,"IP","iot.t- [INFO][CELL]: AT RX (32): mobile.nl.mnc040.mcc901.gprs","1 [DBG ][CELL]: CID 1 APN "iot.t-mobile.nl.mnc040.mcc901.gprs" [INFO][CELL]: AT RX (32): 00.67.16.107",0,0,0,2,0,0,0,0,0, [INFO][CELL]: AT RX ( 9): 0OK [INFO][CELL]: Found PDP context 1 [INFO][CELL]: CellularContext PPP connect [INFO][CELL]: AT TX ( 9): ATD*99*** [INFO][CELL]: AT TX ( 1): 1 [INFO][CELL]: AT TX ( 1): # [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 7): CONNE [INFO][CELL]: AT RX (27): CT~}#!}!} } }6}"}&} } } [DBG ][CELL]: ppp_status_cb: event 0, ptr 3 [DBG ][CELL]: callback: 0, ptr: 3 [DBG ][CELL]: process_oob, filehandle is not usable, return... Connection timed out (180000 ms) ```
cellular AT logs from u-blox SARA-R410M ``` [INFO][CELL]: CellularContext set blocking 0 1970-01-01 00:00:23 [16] Connecting to network 1 (/home/jdebruijn/withthegrid/projects/mbed-system/worktrees/feat-restart-cellular-modem/src/main.cpp:278) [INFO][CELL]: CellularContext set blocking 0 [INFO][CELL]: CellularContext connect Connection status: 2, cellular status: 0 [DBG ][CELL]: callback: 4106, err: 0, data: 4096 Unknown cellular status Connection status: 2, cellular status: 0 [INFO][CELL]: Start connecting (timeout 1000 ms) [INFO][CELL]: AT TX ( 2): AT [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 [INFO][CELL]: AT TX ( 2): AT [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 [DBG ][CELL]: Init => Power [DBG ][CELL]: callback: 4106, err: 0, data: 4096 Unknown cellular status Connection status: 2, cellular status: 0 [INFO][CELL]: Modem power ON (timeout 1000 ms) CellularModuleDriver::hard_power_on [DBG ][CELL]: Power => Device ready [DBG ][CELL]: callback: 4106, err: 0, data: 4096 Unknown cellular status Connection status: 2, cellular status: 0 [DBG ][CELL]: Device was not ready, calling soft_power_on() CellularModuleDriver::soft_power_on [DBG ][CELL]: AT flush [INFO][CELL]: AT RX ( 1): <00> [INFO][CELL]: AT TX ( 4): ATE0 [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 4): ATE0 [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 4): ATE0 [INFO][CELL]: AT TX ( 1): [DBG ][CELL]: AT error -3012 [DBG ][CELL]: Device ready: retry 0/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4096, retrycount: 0 Unknown cellular status Connection status: 2, cellular status: 0 [INFO][CELL]: Continue after 1 seconds [DBG ][CELL]: callback: 4106, err: 0, data: 4096 Unknown cellular status Connection status: 2, cellular status: 0 [DBG ][CELL]: Device was not ready, calling soft_power_on() CellularModuleDriver::soft_power_on [WARN][CELL]: URC already added with prefix: +CGEV: NW DEACT [WARN][CELL]: URC already added with prefix: +CGEV: ME DEACT [WARN][CELL]: URC already added with prefix: +CGEV: NW PDN D [WARN][CELL]: URC already added with prefix: +CGEV: ME PDN D [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 4): ATE0 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (11): ATE0OK [INFO][CELL]: AT TX ( 9): AT+CMEE=1 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: AT TX (12): AT+UMNOPROF? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 7): +UMNO [INFO][CELL]: AT RX (16): PROF: 31OK [INFO][CELL]: AT TX ( 9): AT+CFUN=1 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: AT TX ( 7): AT+CGMI [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (16): u-bloxOK [INFO][CELL]: Modem manufacturer: u-blox [INFO][CELL]: AT TX ( 7): AT+CGMM [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (23): SARA-R410M-02BOK [INFO][CELL]: AT RX ( 1): [INFO][CELL]: Modem model: SARA-R410M-02B [INFO][CELL]: AT TX ( 7): AT+CGMR [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (22): L0.0.00.00.05.08 [Ap [INFO][CELL]: AT RX (27): r 17 2019 19:34:02]OK [INFO][CELL]: Modem revision: L0.0.00.00.05.08 [Apr 17 2019 19:34:02] [INFO][CELL]: Modem ready [INFO][CELL]: AT TX ( 9): AT+CGATT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (11): +CGATT: 0 [INFO][CELL]: AT RX ( 8): OK [INFO][CELL]: AT TX ( 9): AT+URAT=7 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: callback: 4096, err: 0, data: 4096 Connection status: 2, cellular status: 1 [DBG ][CELL]: Device ready => SIM pin [DBG ][CELL]: callback: 4106, err: 0, data: 4097 Unknown cellular status Connection status: 2, cellular status: 1 [INFO][CELL]: Setup SIM (timeout 1000 ms) [DBG ][CELL]: AT flush [INFO][CELL]: AT TX ( 8): AT+CPIN? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (16): +CPIN: READY [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: SIM is ready [DBG ][CELL]: callback: 4097, err: 0, data: 0 Connection status: 2, cellular status: 2 [INFO][CELL]: AT_CellularNetwork::clear [INFO][CELL]: AT TX (11): AT+CGDCONT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 1): [INFO][CELL]: AT RX (31): +CGDCONT: 1,"IP","iot.t-mobile [INFO][CELL]: AT RX (30): .nl","0.0.0.0",0,0,0,0OK [DBG ][CELL]: Automatic network registration [INFO][CELL]: AT TX ( 8): AT+COPS? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 4): +C [INFO][CELL]: AT RX (14): OPS: 0OK [DBG ][CELL]: STM: set_registration: 0, plmn: NULL [INFO][CELL]: AT TX ( 9): AT+CEREG= [INFO][CELL]: AT TX ( 1): 2 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: AT TX ( 8): AT+CREG= [INFO][CELL]: AT TX ( 1): 2 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: AT TX ( 9): AT+CGACT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 9): +CGACT: [INFO][CELL]: AT RX (12): 1,0OK [INFO][CELL]: AT TX ( 9): AT+CGATT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (10): +CGATT: [INFO][CELL]: AT RX ( 9): 0OK [INFO][CELL]: AT TX (10): AT+CGEREP= [INFO][CELL]: AT TX ( 1): 1 [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: SIM pin => Signal quality [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): +CSQ: 99,99 [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: callback: 4104, err: 0, data: -1 Connection status: 2, cellular status: 2 [DBG ][CELL]: Signal quality => Registering network [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): +CSQ: 99,99 [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: callback: 4104, err: 0, data: -1 Connection status: 2, cellular status: 2 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Unknown cellular status Connection status: 2, cellular status: 2 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): +CEREG: 2,2 [DBG ][CELL]: +CEREG: SearchingNetwork, LAC -1, cell -1, RAT unknown [INFO][CELL]: AT RX ( 6): OK [INFO][CELL]: Network registration (timeout 180000 ms) [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Unknown cellular status Connection status: 2, cellular status: 2 [DBG ][CELL]: Automatic network registration [INFO][CELL]: AT TX ( 8): AT+COPS? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (18): +COPS: 0OK [DBG ][CELL]: Registering network: retry 0/10 [DBG ][CELL]: callback: CellularStateRetryEvent, err: 0, data: 4098, retrycount: 0 Unknown cellular status Connection status: 2, cellular status: 2 [INFO][CELL]: Continue after 1 seconds [DBG ][CELL]: AT OoB readable 1, len 0 [INFO][CELL]: AT RX (32): +CREG: 0+CEREG: 5,"111","2 [DBG ][CELL]: +CREG: NotRegistered, LAC -1, cell -1, RAT unknown [DBG ][CELL]: callback: 4098, err: 0, data: 0 Connection status: 2, cellular status: 7 [INFO][CELL]: AT RX (10): 55815",7 [DBG ][CELL]: +CEREG: RegisteredRoaming, LAC 273, cell 2447381, E_UTRAN [DBG ][CELL]: callback: 4101, err: 0, data: 7 Connection status: 2, cellular status: 32 [DBG ][CELL]: callback: 4098, err: 0, data: 5 [DBG ][CELL]: creg event, discard... Connection status: 2, cellular status: 12 [DBG ][CELL]: callback: 4100, err: 0, data: 2447381 Connection status: 2, cellular status: 24 [DBG ][CELL]: AT OoB done [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (15): +CSQ: 99,99 [INFO][CELL]: AT RX ( 6): OK [DBG ][CELL]: callback: 4104, err: 0, data: 4098 Connection status: 2, cellular status: 24 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4098 Unknown cellular status Connection status: 2, cellular status: 24 [INFO][CELL]: AT TX ( 9): AT+CEREG? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (16): +CEREG: 2,5,"1 [INFO][CELL]: AT RX (22): 11","255815",7OK [DBG ][CELL]: +CEREG: RegisteredRoaming, LAC 273, cell 2447381, E_UTRAN [INFO][CELL]: Roaming 1 Registered 1 [DBG ][CELL]: callback: 4098, err: 0, data: 5 [INFO][CELL]: Registering network => Attaching network Connection status: 2, cellular status: 6 [INFO][CELL]: AT TX ( 6): AT+CSQ [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX (12): +CSQ: 99,9 [INFO][CELL]: AT RX ( 9): 9OK [DBG ][CELL]: callback: 4104, err: 0, data: -1 Connection status: 2, cellular status: 6 [INFO][CELL]: RSSI unknown [DBG ][CELL]: callback: 4106, err: 0, data: 4102 Unknown cellular status Connection status: 2, cellular status: 6 [INFO][CELL]: Attaching network (timeout 60000 ms) [INFO][CELL]: AT TX ( 9): AT+CGATT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 1): [INFO][CELL]: AT RX (18): +CGATT: 1OK [DBG ][CELL]: callback: 4102, err: 0, data: 1 Connection status: 2, cellular status: 38 [INFO][CELL]: AT TX (11): AT+CGDCONT? [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 2): [INFO][CELL]: AT RX (32): +CGDCONT: 1,"IP","iot.t-mobile.n [INFO][CELL]: AT RX (32): l","X.X.X.X",0,0,0,0OK [DBG ][CELL]: CID 1 APN "iot.t-mobile.nl" pdp_type 1 [INFO][CELL]: Found PDP context 1 [INFO][CELL]: CellularContext PPP connect [INFO][CELL]: AT TX ( 9): ATD*99*** [INFO][CELL]: AT TX ( 1): 1 [INFO][CELL]: AT TX ( 1): # [INFO][CELL]: AT TX ( 1): [INFO][CELL]: AT RX ( 4): CO [INFO][CELL]: AT RX (17): NNECT 150000000 [DBG ][CELL]: ppp_status_cb: event 0, ptr 3 [DBG ][CELL]: callback: 0, ptr: 3 [DBG ][CELL]: process_oob, filehandle is not usable, return... [DBG ][CELL]: ppp_status_cb: event 0, ptr 1 [DBG ][CELL]: callback: 0, ptr: 1 Connection status: 3, cellular status: 38 Global IP received but waiting for local IP (9812 ms) Connected as X.X.X.X in 9916 ms [INFO][CELL]: CellularContext set blocking 1 ```
ciarmcom commented 3 years ago

Thank you for raising this detailed GitHub issue. I am now notifying our internal issue triagers. Internal Jira reference: https://jira.arm.com/browse/IOTOSM-3760

jdbruijn commented 3 years ago

Has anyone had a chance to have a look at this one (bump)?

adbridge commented 3 years ago

@MarceloSalazar do you have any contacts at Ublox that might be willing to look at this ?

MarceloSalazar commented 3 years ago

FYI @ARMmbed/team-ublox