search

mongoose-os-libs / pppos

PPPoS / cellullar modem support
Other
27 stars 23 forks source link

Always TimeOut during AT command (with A6 mini Modem) #15

Open DimasPristo opened 4 years ago

DimasPristo commented 4 years ago

This is my first time using PPPOS in ESP32 and noob on that. Can I ask about my problems during my development using Mongoose ESP32? This is my PPPOS config schema:

  - ["pppos.enable", true]
  - ["pppos.uart_no", 2]
  - ["pppos.baud_rate", 115200]
  - ["pppos.fc_enable", false]
  - ["pppos.apn", "Internet"]
  - ["pppos.user", ""]
  - ["pppos.pass", ""]
  - ["pppos.connect_on_startup", true]
  - ["pppos.connect_cmd", "ATD*99***1#"]
  - ["pppos.echo_interval", 10]
  - ["pppos.echo_fails", 3]
  - ["pppos.hexdump_enable", true]

This is my Log preview :

[Dec 11 15:34:58.673]                                                                                                                                  C  +   j% (118) boot: OTA data 0: seq 0x00000001, st 0x10, CRC 0x157a2b85, valid? 1 [0m
[Dec 11 15:34:58.673]  [0;32mI (125) boot: OTA data 1: seq 0x00000000, st 0x00, CRC 0x00000000, valid? 0 [0m
[Dec 11 15:34:58.673]  [0;32mI (133) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2aa50 (174672) map [0m
[Dec 11 15:34:58.739]  [0;32mI (186) esp_image: segment 1: paddr=0x0003aa78 vaddr=0x3ffb0000 size=0x028fc ( 10492) load [0m
[Dec 11 15:34:58.739]  [0;32mI (189) esp_image: segment 2: paddr=0x0003d37c vaddr=0x40080000 size=0x00400 (  1024) load [0m
[Dec 11 15:34:58.739]  [0;32mI (193) esp_image: segment 3: paddr=0x0003d784 vaddr=0x40080400 size=0x0288c ( 10380) load [0m
[Dec 11 15:34:58.739]  [0;32mI (205) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0xbd294 (774804) map [0m
[Dec 11 15:34:58.925]  [0;32mI (405) esp_image: segment 5: paddr=0x000fd2b4 vaddr=0x40082c8c size=0x0cc64 ( 52324) load [0m
[Dec 11 15:34:58.948]  [0;32mI (430) boot: Loaded app from partition at offset 0x10000 [0m
[Dec 11 15:34:58.953]  [0;32mI (430) boot: Disabling RNG early entropy source... [0m
[Dec 11 15:34:58.958]  [0;32mI (431) cpu_start: Pro cpu up. [0m
[Dec 11 15:34:58.963]  [0;32mI (434) cpu_start: Application information: [0m
[Dec 11 15:34:58.966]  [0;32mI (439) cpu_start: Project name:     app2 [0m
[Dec 11 15:34:58.978]  [0;32mI (444) cpu_start: App version:      2.16.0 [0m
[Dec 11 15:34:58.978]  [0;32mI (449) cpu_start: Compile time:     Dec 11 2019 08:26:00 [0m
[Dec 11 15:34:58.997]  [0;32mI (455) cpu_start: ELF file SHA256:  230938dc46561e3e... [0m
[Dec 11 15:34:58.997]  [0;32mI (461) cpu_start: ESP-IDF:          v3.3-r2 [0m
[Dec 11 15:34:58.997]  [0;32mI (466) cpu_start: Single core mode [0m
[Dec 11 15:34:58.997]  [0;32mI (470) heap_init: Initializing. RAM available for dynamic allocation: [0m
[Dec 11 15:34:59.027]  [0;32mI (477) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM [0m
[Dec 11 15:34:59.027]  [0;32mI (483) heap_init: At 3FFBA948 len 000256B8 (149 KiB): DRAM [0m
[Dec 11 15:34:59.027]  [0;32mI (489) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM [0m
[Dec 11 15:34:59.027]  [0;32mI (496) heap_init: At 40078000 len 00008000 (32 KiB): IRAM [0m
[Dec 11 15:34:59.029]  [0;32mI (502) heap_init: At 4008F8F0 len 00010710 (65 KiB): IRAM [0m
[Dec 11 15:34:59.040]  [0;32mI (508) cpu_start: Pro cpu start user code [0m
[Dec 11 15:34:59.068]  [0;32mI (190) cpu_start: Chip Revision: 1 [0m
[Dec 11 15:34:59.068]  [0;33mW (190) cpu_start: Chip revision is higher than the one configured in menuconfig. Suggest to upgrade it. [0m
[Dec 11 15:34:59.068]  [0;32mI (194) esp_core_dump_common: Init core dump to UART [0m
[Dec 11 15:34:59.068]  [0;32mI (200) cpu_start: Starting scheduler on PRO CPU. [0m
[Dec 11 15:34:59.068] 
[Dec 11 15:34:59.068] 
[Dec 11 15:34:59.068] mgos_freertos.c:175     app2 1.0 (20191211-083016)
[Dec 11 15:34:59.081] mgos_freertos.c:177     Mongoose OS 2.16.0 (20191211-082614/2.16.0-g9b779cd)
[Dec 11 15:34:59.081] mgos_freertos.c:181     CPU: 160 MHz, FreeRTOS 8.2.0, heap: 289232 total, 257692 free
[Dec 11 15:34:59.093] mgos_freertos.c:183     Newlib 2.2.0
[Dec 11 15:34:59.093] esp32_main.c:116        ESP-IDF v3.3-r2
[Dec 11 15:34:59.096] esp32_main.c:119        Boot partition: app_0; flash: 4M
[Dec 11 15:34:59.105] mg_lwip_ev_mgr.c:93     Mongoose 6.15, LwIP 2.0.3
[Dec 11 15:34:59.105] mg_ssl_if_mbedtls.c:57  mbed TLS 2.16.3-cesanta2
[Dec 11 15:34:59.116] mgos_vfs_dev.c:73       fs_0: esp32part ({"label": "fs_0"}), size 262144
[Dec 11 15:34:59.116] mgos_vfs_dev.c:73       fs_1: esp32part ({"label": "fs_1"}), size 262144
[Dec 11 15:34:59.129] mgos_vfs.c:147          /: SPIFFS @ fs_0, opts {"bs": 4096, "ps": 256, "es": 4096}
[Dec 11 15:34:59.203] mgos_vfs.c:320          /: size 233681, used: 29618, free: 204063
[Dec 11 15:34:59.298] mgos_sys_config.c:368   MAC: a4:cf:12:72:ae:d4
[Dec 11 15:34:59.298] mgos_sys_config.c:376   WDT: 30 seconds
[Dec 11 15:34:59.298] mgos_deps_init.c:114    init i2c...
[Dec 11 15:34:59.298] mgos_deps_init.c:114    init atca...
[Dec 11 15:34:59.298] mgos_deps_init.c:114    init ota-http-client...
[Dec 11 15:34:59.298] mgos_deps_init.c:114    init shadow...
[Dec 11 15:34:59.298] mgos_deps_init.c:114    init ota-shadow...
[Dec 11 15:34:59.298] mgos_ota_shadow_lib:123 OTA over shadow initialised
[Dec 11 15:34:59.298] mgos_deps_init.c:114    init rpc-common...
[Dec 11 15:34:59.298] mgos_deps_init.c:114    init rpc-ws...
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init dash...
[Dec 11 15:34:59.394] mg_rpc.c:539            0x3ffc1b78 'wss://mdash.net/api/v2/rpc' WSS_out
[Dec 11 15:34:59.394] mgos_dash.c:203         Dash init ok, server: wss://mdash.net/api/v2/rpc)
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init mbedtls...
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init pppos...
[Dec 11 15:34:59.394] mgos_pppos.c:947        PPPoS UART2 (RX:16 TX:17 CTS:14 RTS:15), 115200, fc off, APN 'Internet'
[Dec 11 15:34:59.394] mgos_pppos.c:133        0 -> 1 0.292037 0.000000
[Dec 11 15:34:59.394] mgos_pppos.c:133        1 -> 12 0.296727 0.000000
[Dec 11 15:34:59.394] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init rpc-service-config...
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init rpc-service-fs...
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init rpc-service-gpio...
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init rpc-service-ota...
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init rpc-uart...
[Dec 11 15:34:59.394]  mgos_rpc_channel_ua:313 0x3ffc24bc UART0
[Dec 11 15:34:59.394] mg_rpc.c:539            0x3ffc24bc '' UART
[Dec 11 15:34:59.394] mg_rpc.c:470            0x3ffc24bc CHAN OPEN (UART UART0)
[Dec 11 15:34:59.394] mgos_deps_init.c:114    init wifi...
[Dec 11 15:34:59.394] mgos_wifi.c:458         WiFi mode: AP
[Dec 11 15:34:59.394] esp32_wifi.c:231        cur mode: 0
[Dec 11 15:34:59.394] esp32_wifi.c:196        WiFi mode: AP
[Dec 11 15:34:59.404] I (885) wifi: wifi driver task: 3ffc3c84, prio:23, stack:3584, core=0
[Dec 11 15:34:59.415] I (895) wifi: wifi firmware version: aeed694
[Dec 11 15:34:59.466] I (905) wifi: config NVS flash: enabled
[Dec 11 15:34:59.466] I (905) wifi: config nano formating: disabled
[Dec 11 15:34:59.466] I (905) wifi: Init dynamic tx buffer num: 32
[Dec 11 15:34:59.466] I (915) wifi: Init data frame dynamic rx buffer num: 64
[Dec 11 15:34:59.466] I (915) wifi: Init management frame dynamic rx buffer num: 64
[Dec 11 15:34:59.466] I (925) wifi: Init management short buffer num: 32
[Dec 11 15:34:59.466] I (925) wifi: Init static rx buffer size: 1600
[Dec 11 15:34:59.466] I (935) wifi: Init static rx buffer num: 10
[Dec 11 15:34:59.466] I (935) wifi: Init dynamic rx buffer num: 0
[Dec 11 15:34:59.466]  [0;33mW (935) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration [0m
[Dec 11 15:34:59.636]  [0;32mI (1085) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 2 [0m
[Dec 11 15:34:59.636] I (1085) wifi: mode : softAP (a4:cf:12:72:ae:d5)
[Dec 11 15:34:59.636] I (1095) wifi: Total power save buffer number: 16
[Dec 11 15:34:59.636] I (1095) wifi: Init max length of beacon: 752/752
[Dec 11 15:34:59.636] I (1105) wifi: Init max length of beacon: 752/752
[Dec 11 15:34:59.636] esp32_wifi.c:168        WiFi PS 1 -> 0
[Dec 11 15:34:59.636] I (1115) wifi: Set ps type: 0
[Dec 11 15:34:59.636] 
[Dec 11 15:34:59.636] esp32_wifi.c:449        WiFi AP: SSID Mongoose_72AED4, channel 6
[Dec 11 15:35:00.563] I (1965) wifi: Total power save buffer number: 16
[Dec 11 15:35:00.563] esp32_wifi.c:634        WiFi AP: protocol BGN (0x7)
[Dec 11 15:35:00.563] esp32_wifi.c:506        WiFi AP IP: 192.168.4.1/255.255.255.0 gw 192.168.4.1, DHCP range 192.168.4.2 - 192.168.4.100
[Dec 11 15:35:00.563] esp32_wifi.c:511        WiFi AP: SSID Mongoose_72AED4, channel 6
[Dec 11 15:35:00.563] mgos_init.c:36          Init done, RAM: 288444 total, 226152 free, 226096 min free
[Dec 11 15:35:00.563] mgos_event.c:135        ev MOS0 triggered 0 handlers
[Dec 11 15:35:00.563] mgos_ota_core.c:969     1 0
[Dec 11 15:35:00.563] mgos_pppos.c:112        Trying baud rate 115200 (fc off)...
[Dec 11 15:35:00.563] mgos_pppos.c:133        12 -> 5 1.489759 0.000000
[Dec 11 15:35:00.563] 0000  00                                               .
[Dec 11 15:35:00.563] mgos_ota_core.c:1318    UID: 0f4cbff0514c5e2f, license: none
[Dec 11 15:35:00.563] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:00.563] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:00.563] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:00.563] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:01.811] mgos_pppos.c:133        5 -> 6 2.766035 2.699730
[Dec 11 15:35:03.041] mgos_pppos.c:133        6 -> 7 3.976033 0.000000
[Dec 11 15:35:03.041] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:03.041] mgos_pppos.c:133        7 -> 8 3.986823 0.000000
[Dec 11 15:35:03.041] mgos_pppos.c:133        8 -> 9 3.991400 5.991341
[Dec 11 15:35:03.041] mgos_mongoose.c:66      New heap free LWM: 225932
[Dec 11 15:35:05.143] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:05.143] mgos_pppos.c:133        9 -> 1 6.070294 5.991341
[Dec 11 15:35:05.143] mgos_pppos.c:133        1 -> 12 6.074826 0.000000
[Dec 11 15:35:05.143] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:05.143] mgos_pppos.c:112        Trying baud rate 115200 (fc off)...
[Dec 11 15:35:05.143] mgos_pppos.c:133        12 -> 5 6.089604 0.000000
[Dec 11 15:35:05.143] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:05.143] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:06.121] mgos_mongoose.c:66      New heap free LWM: 224476
[Dec 11 15:35:06.411] mgos_pppos.c:133        5 -> 6 7.366033 7.294209
[Dec 11 15:35:07.636] mgos_pppos.c:133        6 -> 7 8.576026 0.000000
[Dec 11 15:35:07.636] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:07.636] mgos_pppos.c:133        7 -> 8 8.586794 0.000000
[Dec 11 15:35:07.636] mgos_pppos.c:133        8 -> 9 8.591371 10.591312
[Dec 11 15:35:08.711] mgos_mongoose.c:66      New heap free LWM: 222024
[Dec 11 15:35:09.744] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:09.744] mgos_pppos.c:133        9 -> 1 10.670299 10.591312
[Dec 11 15:35:09.744] mgos_pppos.c:133        1 -> 12 10.675034 0.000000
[Dec 11 15:35:09.744] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:09.744] mgos_pppos.c:112        Trying baud rate 230400 (fc off)...
[Dec 11 15:35:09.744] mgos_pppos.c:133        12 -> 5 10.689897 0.000000
[Dec 11 15:35:09.744] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:09.744] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:11.013] mgos_pppos.c:133        5 -> 6 11.966049 11.894525
[Dec 11 15:35:12.237] mgos_pppos.c:133        6 -> 7 13.176030 0.000000
[Dec 11 15:35:12.237] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:12.237] mgos_pppos.c:133        7 -> 8 13.186963 0.000000
[Dec 11 15:35:12.237] mgos_pppos.c:133        8 -> 9 13.191650 15.191591
[Dec 11 15:35:14.344] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:14.344] mgos_pppos.c:133        9 -> 1 15.270282 15.191591
[Dec 11 15:35:14.344] mgos_pppos.c:133        1 -> 12 15.275000 0.000000
[Dec 11 15:35:14.344] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:14.344] mgos_pppos.c:112        Trying baud rate 460800 (fc off)...
[Dec 11 15:35:14.344] mgos_pppos.c:133        12 -> 5 15.289944 0.000000
[Dec 11 15:35:14.344] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:14.344] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:15.611] mgos_pppos.c:133        5 -> 6 16.566046 16.494579
[Dec 11 15:35:16.837] mgos_pppos.c:133        6 -> 7 17.776239 0.000000
[Dec 11 15:35:16.837] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:16.837] mgos_pppos.c:133        7 -> 8 17.787165 0.000000
[Dec 11 15:35:16.837] mgos_pppos.c:133        8 -> 9 17.791852 19.791794
[Dec 11 15:35:18.944] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:18.944] mgos_pppos.c:133        9 -> 1 19.870284 19.791794
[Dec 11 15:35:18.944] mgos_pppos.c:133        1 -> 12 19.874991 0.000000
[Dec 11 15:35:18.944] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:18.944] mgos_pppos.c:112        Trying baud rate 921600 (fc off)...
[Dec 11 15:35:18.944] mgos_pppos.c:133        12 -> 5 19.889899 0.000000
[Dec 11 15:35:18.944] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:18.944] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:20.211] mgos_pppos.c:133        5 -> 6 21.166040 21.094567
[Dec 11 15:35:21.436] mgos_pppos.c:133        6 -> 7 22.376027 0.000000
[Dec 11 15:35:21.436] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:21.436] mgos_pppos.c:133        7 -> 8 22.386915 0.000000
[Dec 11 15:35:21.436] mgos_pppos.c:133        8 -> 9 22.391596 24.391539
[Dec 11 15:35:23.534] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:23.534] mgos_pppos.c:133        9 -> 1 24.460292 24.391539
[Dec 11 15:35:23.534] mgos_pppos.c:133        1 -> 12 24.464992 0.000000
[Dec 11 15:35:23.534] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:23.534] mgos_pppos.c:112        Trying baud rate 115200 (fc off)...
[Dec 11 15:35:23.534] mgos_pppos.c:133        12 -> 5 24.479852 0.000000
[Dec 11 15:35:23.534] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:23.534] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:24.810] mgos_pppos.c:133        5 -> 6 25.766039 25.684553
[Dec 11 15:35:26.015] mgos_pppos.c:133        6 -> 7 26.976036 0.000000
[Dec 11 15:35:26.035] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:26.035] mgos_pppos.c:133        7 -> 8 26.986977 0.000000
[Dec 11 15:35:26.035] mgos_pppos.c:133        8 -> 9 26.991648 28.991589
[Dec 11 15:35:28.143] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:28.143] mgos_pppos.c:133        9 -> 1 29.070293 28.991589
[Dec 11 15:35:28.143] mgos_pppos.c:133        1 -> 12 29.074995 0.000000
[Dec 11 15:35:28.143] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:28.143] mgos_pppos.c:112        Trying baud rate 115200 (fc off)...
[Dec 11 15:35:28.143] mgos_pppos.c:133        12 -> 5 29.089860 0.000000
[Dec 11 15:35:28.143] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:28.143] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:29.411] mgos_pppos.c:133        5 -> 6 30.366038 30.294488
[Dec 11 15:35:30.636] mgos_pppos.c:133        6 -> 7 31.576038 0.000000
[Dec 11 15:35:30.636] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:30.636] mgos_pppos.c:133        7 -> 8 31.586978 0.000000
[Dec 11 15:35:30.636] mgos_pppos.c:133        8 -> 9 31.591651 33.591593
[Dec 11 15:35:32.742] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:32.742] mgos_pppos.c:133        9 -> 1 33.670343 33.591593
[Dec 11 15:35:32.742] mgos_pppos.c:133        1 -> 12 33.675093 0.000000
[Dec 11 15:35:32.742] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:32.742] mgos_pppos.c:112        Trying baud rate 230400 (fc off)...
[Dec 11 15:35:32.742] mgos_pppos.c:133        12 -> 5 33.689957 0.000000
[Dec 11 15:35:32.742] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:32.742] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:34.011] mgos_pppos.c:133        5 -> 6 34.966041 34.894583
[Dec 11 15:35:35.236] mgos_pppos.c:133        6 -> 7 36.176027 0.000000
[Dec 11 15:35:35.236] mgos_pppos.c:613        Connecting (UART2, APN 'Internet')...
[Dec 11 15:35:35.236] mgos_pppos.c:133        7 -> 8 36.186931 0.000000
[Dec 11 15:35:35.236] mgos_pppos.c:133        8 -> 9 36.191610 38.191553
[Dec 11 15:35:37.342] mgos_pppos.c:666        Command timed out: AT
[Dec 11 15:35:37.342] mgos_pppos.c:133        9 -> 1 38.270349 38.191553
[Dec 11 15:35:37.342] mgos_pppos.c:133        1 -> 12 38.275096 0.000000
[Dec 11 15:35:37.342] mgos_event.c:135        ev PoS1 triggered 0 handlers
[Dec 11 15:35:37.342] mgos_pppos.c:112        Trying baud rate 460800 (fc off)...
[Dec 11 15:35:37.342] mgos_pppos.c:133        12 -> 5 38.289957 0.000000
[Dec 11 15:35:37.342] mgos_net.c:86           PPP: connecting
[Dec 11 15:35:37.342] mgos_event.c:135        ev NET1 triggered 1 handlers
[Dec 11 15:35:38.604] mgos_pppos.c:133        5 -> 6 39.566040 39.494583

Thanks A lot Help me figure it out.

rojer commented 4 years ago

modem is not responding to commands, even simple AT. check that these settings are correct:

PPPoS UART2 (RX:16 TX:17 CTS:14 RTS:15)

and the modem is connected and powered on.