search

mongoose-os-libs / pppos

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

Core Dump when reconnecting to PPP when GNSS codes are activated #9

Open jonahsee opened 5 years ago

jonahsee commented 5 years ago

Hi, I'm using the GNSS code to pull location data from my cellular modem. I am noticing a 

Error 5 (phase 0), reconnect
PPP: connecting

followed by acore dump everytime the modem loses connection to the network. I have simulated this by setting AT+COPS=2.

Below are the console logs from the moment it loses connection until the system reboots. Once connection is re-established it connects fine and continues running the code until another loss of connection. I have also opened a forum thread here. 

[May 27 11:53:42.020] main.c:68               lat,lon: 3.088168,101.632324 alt: 26.100 speed: 0.00 course: 78.90
[May 27 11:53:44.359] mg_ssl_if_mbedtls.c:35  0x3ffc926c mbedtls_ssl_flush_output() returned -78 (-0x004e)
[May 27 11:53:44.363] mg_ssl_if_mbedtls.c:35  0x3ffc926c mbedtls_ssl_write_record() returned -78 (-0x004e)
[May 27 11:53:44.369] mg_ssl_if_mbedtls.c:35  0x3ffc926c mbedtls_ssl_send_alert_message() returned -78 (-0x004e)
[May 27 11:53:44.381] mgos_mqtt.c:164         MQTT Disconnect
[May 27 11:53:44.381] mgos_mqtt.c:493         MQTT connecting after 1981 ms
[May 27 11:53:46.372] mgos_mqtt.c:427         MQTT connecting to mqtt.googleapis.com:8883
[May 27 11:53:47.017] main.c:33               What is ok 1
[May 27 11:53:47.017] main.c:43               What is fix 3
[May 27 11:53:47.025] 
[May 27 11:53:47.025] main.c:68               lat,lon: 3.088168,101.632324 alt: 26.100 speed: 0.00 course: 78.90
[May 27 11:53:50.351] mgos_pppos.c:189        Error 6 (phase 0), reconnect
[May 27 11:53:50.351] mgos_net.c:85           PPP: connecting
[May 27 11:53:52.917] main.c:33               What is ok 1
[May 27 11:53:52.917] main.c:43               What is fix 3
[May 27 11:53:52.923] 
[May 27 11:53:52.923] main.c:68               lat,lon: 3.088168,101.632324 alt: 26.000 speed: 0.00 course: 78.90
[May 27 11:53:52.943] Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
[May 27 11:53:52.948] Core 0 register dump:
[May 27 11:53:52.948] PC      : 0x40144525  PS      : 0x00060e30  A0      : 0x80100119  A1      : 0x3ffb4f60  
[May 27 11:53:52.959] A2      : 0x00000000  A3      : 0x3ffcc16c  A4      : 0x0000000e  A5      : 0x3ffbae04  
[May 27 11:53:52.964] A6      : 0x00000a0d  A7      : 0x52414320  A8      : 0x80144525  A9      : 0x3ffb4f40  
[May 27 11:53:52.969] A10     : 0x00000000  A11     : 0x3ffcc16c  A12     : 0x0000000e  A13     : 0x00000000  
[May 27 11:53:52.980] A14     : 0x0000000e  A15     : 0x0000000e  SAR     : 0x00000015  EXCCAUSE: 0x0000001c  
[May 27 11:53:52.986] EXCVADDR: 0x00000028  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
[May 27 11:53:52.998] 
[May 27 11:53:52.998] Backtrace: 0x40144525 0x40100116 0x40100129 0x401001c7 0x400e38b8 0x4017e209 0x4008398a 0x40083b25
[May 27 11:53:53.003] 
[May 27 11:53:53.003] --- BEGIN CORE DUMP ---
[May 27 11:53:53.008] mos: catching core dump
[May 27 11:53:55.864] .............
[May 27 11:54:32.891] ---- END CORE DUMP ----
[May 27 11:54:32.899] mos: wrote to c:\mos\orion-test-firmware\PPPOS_GNSS\core-PPPOS_GNSS-esp32-20190527-115432.589954531 (459475 bytes)
[May 27 11:54:32.911] mos: analyzing core dump
Core dump by PPPOS_GNSS/esp32 1.0 20190527-034603/ge622754-master-dirty
Using ELF file at: c:\mos\orion-test-firmware\PPPOS_GNSS\build\objs\PPPOS_GNSS.elf
Using Docker image: docker.io/mgos/esp32-build:3.2-r6
Running docker run --rm -v /c/mos/orion-test-firmware/PPPOS_GNSS/build/objs/PPPOS_GNSS.elf:/fw.elf -v /c/mos/orion-test-firmware/PPPOS_GNSS/core-PPPOS_GNSS-esp32-20190527-115432.589954531:/core -v c:\mos\orion-test-firmware\PPPOS_GNSS:/c/mos/orion-test-firmware/PPPOS_GNSS docker.io/mgos/esp32-build:3.2-r6 bash -c /usr/local/bin/serve_core.py --rom=/opt/Espressif/rom/rom.bin --rom_addr=0x40000000 --xtensa_addr_fixup=true /fw.elf /core & $MGOS_TARGET_GDB /fw.elf -ex 'target remote 127.0.0.1:1234' -ex 'set confirm off' -ex bt -ex quit
GNU gdb (crosstool-NG crosstool-ng-1.22.0-80-g6c4433a) 7.10
Copyright (C) 2015 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=x86_64-build_pc-linux-gnu --target=xtensa-esp32-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /fw.elf...done.
Remote debugging using 127.0.0.1:1234
pppos_input_tcpip (ppp=0x0, 
    s=0x3ffcc16c "\r\nNO CARRIER\r\n351.000,0305.2901N,10137.9393E,1.3,26.0,3,78.9,0.0,0.0,270519,04,02\r\n\r\nOK\r\nNTU\331\301\374?4\302\374?4LCJleHA\364\301\374?1558929229268", l=<optimized out>)
    at /opt/Espressif/esp-idf/components/lwip/lwip/src/netif/ppp/pppos.c:421
421   err = tcpip_inpkt(p, ppp_netif(ppp), pppos_input_sys);
#0  pppos_input_tcpip (ppp=0x0, 
    s=0x3ffcc16c "\r\nNO CARRIER\r\n351.000,0305.2901N,10137.9393E,1.3,26.0,3,78.9,0.0,0.0,270519,04,02\r\n\r\nOK\r\nNTU\331\301\374?4\302\374?4LCJleHA\364\301\374?1558929229268", l=<optimized out>)
    at /opt/Espressif/esp-idf/components/lwip/lwip/src/netif/ppp/pppos.c:421
#1  0x40100119 in mgos_pppos_dispatch_once (pd=0x3ffc26a8)
    at /c/mos/orion-test-firmware/PPPOS_GNSS/deps/pppos/src/mgos_pppos.c:769
#2  0x4010012c in mgos_pppos_dispatch (pd=0x3ffc26a8)
    at /c/mos/orion-test-firmware/PPPOS_GNSS/deps/pppos/src/mgos_pppos.c:779
#3  0x401001ca in mgos_pppos_uart_dispatcher (uart_no=<optimized out>, 
    arg=0x3ffc26a8)
    at /c/mos/orion-test-firmware/PPPOS_GNSS/deps/pppos/src/mgos_pppos.c:805
#4  0x400e38bb in mgos_uart_dispatcher (arg=0x2)
    at /c/mos/orion-test-firmware/PPPOS_GNSS/deps/modules/mongoose-os/src/mgos_uart.c:69
#5  0x4017e20c in mongoose_poll (ms=0)
    at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mgos_mongoose.c:55
#6  0x4008398d in mgos_mg_poll_cb (arg=<optimized out>)
    at /c/mos/orion-test-firmware/PPPOS_GNSS/deps/freertos/src/mgos_freertos.c:101
#7  0x40083b28 in mgos_task (arg=<optimized out>)
    at /c/mos/orion-test-firmware/PPPOS_GNSS/deps/freertos/src/mgos_freertos.c:220
Detaching from program: /fw.elf, Remote target
Waiting for gdb on 1234
Dump contains FreeRTOS task info
Found core at 23 - 459426
Mapping DRAM: 335872 @ 0x3ffae000
Mapping /opt/Espressif/rom/rom.bin at 0x40000000
Mapping /fw.elf .rtc.text: 52 @ 0x400c0000
Mapping /fw.elf .rtc.dummy: 52 @ 0x3ff80000
Mapping /fw.elf .iram0.vectors: 1024 @ 0x40080000
Mapping /fw.elf .iram0.text: 70333 @ 0x40080400
Mapping /fw.elf .dram0.data: 10156 @ 0x3ffb0000
Mapping /fw.elf .dram0.bss: 32832 @ 0x3ffb27b0
Mapping /fw.elf .flash.rodata: 164748 @ 0x3f400020
Mapping /fw.elf .flash.text: 793122 @ 0x400d0018
Loaded core dump from last snippet in  /core
GDB closed the connection
Ending remote debugging.
[May 27 11:54:39.836] Rebooting...
[May 27 11:54:39.836] ets Jun  8 2016 00:22:57
[May 27 11:54:39.836] 
[May 27 11:54:39.836] rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[May 27 11:54:39.836] configsip: 0, SPIWP:0xee
[May 27 11:54:39.836] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[May 27 11:54:39.836] mode:DIO, clock div:1
[May 27 11:54:39.836] load:0x3fff0018,len:4
[May 27 11:54:39.836] load:0x3fff001c,len:6188
[May 27 11:54:39.836] load:0x40078000,len:9588
[May 27 11:54:39.836] load:0x40080400,len:6968
[May 27 11:54:39.836] entry 0x40080740
[May 27 11:54:39.836] I (29) boot: ESP-IDF v3.2-r6 2nd stage bootloader
[May 27 11:54:39.836] I (29) boot: compile time 03:43:39
[May 27 11:54:39.836] I (29) boot: Enabling RNG early entropy source...
[May 27 11:54:39.836] I (34) qio_mode: Enabling default flash chip QIO
[May 27 11:54:39.836] I (39) boot: SPI Speed      : 80MHz
[May 27 11:54:39.836] I (43) boot: SPI Mode       : QIO
[May 27 11:54:39.836] I (47) boot: SPI Flash Size : 4MB
[May 27 11:54:39.836] I (51) boot: Partition Table:
[May 27 11:54:39.836] I (55) boot: ## Label            Usage          Type ST Offset   Length   Flags
[May 27 11:54:39.836] I (63) boot:  0 nvs              WiFi data        01 02 00009000 00004000 00000000
[May 27 11:54:39.836] I (71) boot:  1 otadata          OTA data         01 00 0000d000 00002000 00000000
[May 27 11:54:39.836] I (79) boot:  2 app_0            OTA app          00 10 00010000 00180000 00000000
[May 27 11:54:39.836] I (87) boot:  3 fs_0             SPIFFS           01 82 00190000 00040000 00000000
[May 27 11:54:39.836] I (96) boot:  4 app_1            OTA app          00 11 001d0000 00180000 00000000
[May 27 11:54:39.836] I (104) boot:  5 fs_1             SPIFFS           01 82 00350000 00040000 00000000
[May 27 11:54:39.836] I (112) boot: End of partition table
[May 27 11:54:39.836] I (117) boot: OTA data 0: seq 0x00000001, st 0x10, CRC 0x157a2b85, valid? 1
[May 27 11:54:39.836] I (124) boot: OTA data 1: seq 0x00000000, st 0x00, CRC 0x00000000, valid? 0
[May 27 11:54:39.836] I (132) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2838c (164748) map
[May 27 11:54:39.836] I (184) esp_image: segment 1: paddr=0x000383b4 vaddr=0x3ffb0000 size=0x027ac ( 10156) load
[May 27 11:54:39.836] I (187) esp_image: segment 2: paddr=0x0003ab68 vaddr=0x40080000 size=0x00400 (  1024) load
[May 27 11:54:39.836] I (191) esp_image: segment 3: paddr=0x0003af70 vaddr=0x40080400 size=0x050a0 ( 20640) load
[May 27 11:54:39.836] I (206) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0xc1a24 (793124) map
[May 27 11:54:39.836] I (415) esp_image: segment 5: paddr=0x00101a44 vaddr=0x400854a0 size=0x0c220 ( 49696) load
[May 27 11:54:39.836] I (430) esp_image: segment 6: paddr=0x0010dc6c vaddr=0x400c0000 size=0x00034 (    52) load
[May 27 11:54:39.836] I (441) boot: Loaded app from partition at offset 0x10000
[May 27 11:54:39.836] I (441) boot: Disabling RNG early entropy source...
[May 27 11:54:39.836] I (442) cpu_start: Pro cpu up.
[May 27 11:54:39.836] I (446) cpu_start: Single core mode
[May 27 11:54:39.836] I (450) heap_init: Initializing. RAM available for dynamic allocation:
[May 27 11:54:39.836] I (457) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
[May 27 11:54:39.836] I (463) heap_init: At 3FFBA7F0 len 00025810 (150 KiB): DRAM
[May 27 11:54:39.836] I (469) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM
[May 27 11:54:39.836] I (476) heap_init: At 40078000 len 00008000 (32 KiB): IRAM
[May 27 11:54:39.836] I (482) heap_init: At 400916C0 len 0000E940 (58 KiB): IRAM
[May 27 11:54:39.836] I (488) cpu_start: Pro cpu start user code
[May 27 11:54:39.836] I (170) cpu_start: Starting scheduler on PRO CPU.
[May 27 11:54:39.836] 
[May 27 11:54:39.836] 
[May 27 11:54:39.836] mgos_freertos.c:175     PPPOS_GNSS 1.0 (20190527-034603/ge622754-master-dirty)
[May 27 11:54:39.836] mgos_freertos.c:177     Mongoose OS aee6b1d (20190527-034431/gaee6b1d-master)
[May 27 11:54:39.836] mgos_freertos.c:181     CPU: 160 MHz, FreeRTOS 8.2.0, heap: 289560 total, 257584 free
[May 27 11:54:39.836] mgos_freertos.c:183     Newlib 2.2.0
[May 27 11:54:39.836] esp32_main.c:116        ESP-IDF v3.2-r6
[May 27 11:54:39.836] esp32_main.c:119        Boot partition: app_0; flash: 4M
[May 27 11:54:39.836] mg_lwip_ev_mgr.c:93     Mongoose 6.14, LwIP 2.0.3
[May 27 11:54:39.836] mg_ssl_if_mbedtls.c:57  mbed TLS 2.16.0-cesanta4
[May 27 11:54:39.836] mgos_vfs_dev.c:73       fs_0: esp32part ({"label": "fs_0"}), size 262144
[May 27 11:54:39.836] mgos_vfs_dev.c:73       fs_1: esp32part ({"label": "fs_1"}), size 262144
[May 27 11:54:39.836] mgos_vfs.c:147          /: SPIFFS @ fs_0, opts {"bs": 4096, "ps": 256, "es": 4096}
[May 27 11:54:39.836] mgos_vfs.c:320          /: size 233681, used: 97388, free: 136293
[May 27 11:54:39.836] mgos_sys_config.c:232   Loading conf9.json
[May 27 11:54:39.836] mgos_sys_config.c:368   MAC: 24:0a:c4:1c:a8:48
[May 27 11:54:39.836] mgos_sys_config.c:376   WDT: 30 seconds
[May 27 11:54:39.836] mgos_gcp.c:374          GCP client for project-pegasus-223706/asia-east1/pegasus1/esp32_1CA848, EC key in gcp-esp32_1CA848.key.pem
[May 27 11:54:39.836] mgos_pppos.c:934        PPPoS UART2 (RX:16 TX:17 CTS:14 RTS:15), 115200, fc off, APN 'diginet'
[May 27 11:54:39.836]  mgos_rpc_channel_ua:313 0x3ffc2b74 UART0
[May 27 11:54:39.837] mgos_wifi.c:458         WiFi mode: AP
[May 27 11:54:39.837] esp32_wifi.c:196        WiFi mode: AP
[May 27 11:54:39.837] I (734) wifi: wifi driver task: 3ffc4230, prio:23, stack:3584, core=0
[May 27 11:54:39.837] I (744) wifi: wifi firmware version: 2af77cc
[May 27 11:54:39.837] I (744) wifi: config NVS flash: enabled
[May 27 11:54:39.837] I (744) wifi: config nano formating: disabled
[May 27 11:54:39.837] I (754) wifi: Init dynamic tx buffer num: 32
[May 27 11:54:39.837] I (764) wifi: Init data frame dynamic rx buffer num: 64
[May 27 11:54:39.837] I (764) wifi: Init management frame dynamic rx buffer num: 64
[May 27 11:54:39.837] I (774) wifi: Init management short buffer num: 32
[May 27 11:54:39.837] I (774) wifi: Init static rx buffer size: 1600
[May 27 11:54:39.837] I (784) wifi: Init static rx buffer num: 10
[May 27 11:54:39.837] I (784) wifi: Init dynamic rx buffer num: 0
[May 27 11:54:39.837] I (854) phy: phy_version: 4008, 544f89f, Jan 24 2019, 14:54:06, 0, 0
[May 27 11:54:39.837] I (854) wifi: mode : softAP (24:0a:c4:1c:a8:49)
[May 27 11:54:39.837] I (864) wifi: Total power save buffer number: 16
[May 27 11:54:39.837] I (864) wifi: Init max length of beacon: 752/752
[May 27 11:54:39.837] I (874) wifi: Init max length of beacon: 752/752
[May 27 11:54:39.837] I (874) wifi: Set ps type: 0
[May 27 11:54:39.837] 
[May 27 11:54:39.837] esp32_wifi.c:442        WiFi AP: SSID Mongoose_1CA848, channel 6
[May 27 11:54:39.837] I (1724) wifi: Total power save buffer number: 16
[May 27 11:54:39.837] esp32_wifi.c:492        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
[May 27 11:54:39.837] esp32_wifi.c:497        WiFi AP: SSID Mongoose_1CA848, channel 6
[May 27 11:54:39.837] mgos_init.c:36          Init done, RAM: 288800 total, 220680 free, 220632 min free
[May 27 11:54:39.837] mgos_mongoose.c:66      New heap free LWM: 216384
[May 27 11:54:39.837] mgos_net.c:85           PPP: connecting
[May 27 11:54:39.837] mgos_net.c:85           PPP: connecting
[May 27 11:54:39.837] mgos_pppos.c:608        Connecting (UART2, APN '')...
[May 27 11:54:39.837] mgos_pppos.c:263        332, IMEI: 
[May 27 11:54:39.837] mgos_pppos.c:333        SIM is ready, IMSI: , ICCID: 
[May 27 11:54:39.837] mgos_pppos.c:390        Not connected to mobile network, status 0 (idle)
[May 27 11:54:39.838] mgos_pppos.c:390        Not connected to mobile network, status 0 (idle)