Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PPP re-initialization fails (IDFGH-4140) #6005

Closed
kannannair084 opened this issue Oct 20, 2020 · 46 comments
Closed

PPP re-initialization fails (IDFGH-4140) #6005

kannannair084 opened this issue Oct 20, 2020 · 46 comments

Comments

@kannannair084
Copy link

kannannair084 commented Oct 20, 2020

I am handling a reconnect of PPP which esp_modem_setup_ppp(dte) and esp_modem_exit_ppp(dte)

i am getting stuck at as i found on debugging code.
esp_dte->ppp = pppapi_pppos_create(&(esp_dte->pppif), pppos_low_level_output, on_ppp_status_changed, dte);

could someone please recommend a proper init and de-init sequence for PPP.

boot: Chip Revision: 1
I (69) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (39) boot: ESP-IDF v4.0.1-dirty 2nd stage bootloader
I (39) boot: compile time 20:29:59
I (39) boot: Enabling RNG early entropy source...
I (44) boot: SPI Speed : 40MHz
I (48) boot: SPI Mode : DIO
I (52) boot: SPI Flash Size : 16MB

my reference project was pppos_client. i have to do LteModemInitialisation_LtePPPModule and LteModemDeInit_LtePPPModule in sequence and esp32 doesn't move past pppapi_pppos_create in the second iteration.

uint8_t LteModemInitialisation_LtePPPModule()
{
ESP_LOGI(TAG, "Delay 30 Seconds for Modem Readiness");
Reset_LtePPPModule();
for(int i = 0; i < 30; i++)
{
vTaskDelay(1000 / portTICK_PERIOD_MS);
}
ESP_LOGI(TAG, "Delay completed");
//InitFlash();
if(FirstDteInit == 0)
{
tcpip_adapter_init();
FirstDteInit = 1;
}
event_group = xEventGroupCreate();
esp_modem_dte_config_t config = ESP_MODEM_DTE_DEFAULT_CONFIG();
// create dce object
dte = esp_modem_dte_init(&config);
// Register event handler
ESP_ERROR_CHECK(esp_modem_add_event_handler(dte, modem_event_handler, NULL));
dce = bg96_init(dte);
if(dce == NULL)
{
goto skipitall;
}

ESP_ERROR_CHECK(dce->set_flow_ctrl(dce, MODEM_FLOW_CONTROL_NONE));
ESP_ERROR_CHECK(dce->store_profile(dce));
// Get signal quality
uint32_t rssi = 0, ber = 0;
ESP_ERROR_CHECK(dce->get_signal_quality(dce, &rssi, &ber));
// Setup PPP environment
esp_err_t modemstattus = esp_modem_setup_ppp(dte);
if(modemstattus != ESP_OK)
{
goto failedmodem;
}
// Wait for IP address
TRACE("Waiting for IP addres");
xEventGroupWaitBits(event_group, CONNECT_BIT, pdTRUE, pdTRUE, portMAX_DELAY);
return 0;
failedmodem:
ESP_LOGI(TAG, "PPP Init Failed");
return 3;
skipitall:
ESP_LOGI(TAG, "BG96 Init Failed");
return 2;
}

To de-initialize
void LteModemDeInit_LtePPPModule()
{
// Exit PPP mode
if(dte != NULL)
{
ESP_ERROR_CHECK(esp_modem_exit_ppp(dte));
xEventGroupWaitBits(event_group, STOP_BIT, pdTRUE, pdTRUE, portMAX_DELAY);
}

if(dce != NULL)
{
	// Power down module
	ESP_ERROR_CHECK(dce->power_down(dce));
	ESP_LOGI(TAG, "Power down");
	dce->deinit(dce);
}
if(dte != NULL)
{
	TRACE(" DTE is not Null");
	//esp_modem_remove_event_handler(dte,modem_event_handler);

	dte->deinit(dte);
	FirstDteInit = 0;
}
if( event_group != NULL)
{
	vEventGroupDelete(event_group);
	ESP_ERROR_CHECK(esp_event_loop_delete_default());
	event_group = NULL;
}

}

@github-actions github-actions bot changed the title PPP re-initialization fails PPP re-initialization fails (IDFGH-4140) Oct 20, 2020
@Alvin1Zhang
Copy link
Collaborator

@kannannair084 Thanks for reporting. Would you please help provide more details as suggested in the issue template? Information like elf, sdk configuration, backtrace, log outputs, commit ID, hardware and etc. would help us debug further. Thanks.

@kannannair084
Copy link
Author

esp_err_t esp_modem_setup_ppp(modem_dte_t *dte)
{
modem_dce_t *dce = dte->dce;
MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
esp_modem_dte_t esp_dte = __containerof(dte, esp_modem_dte_t, parent);
/
Set PDP Context /
MODEM_CHECK(dce->define_pdp_context(dce, 1, "IP", CONFIG_EXAMPLE_MODEM_APN) == ESP_OK, "set MODEM APN failed", err);
/
Enter PPP mode /
MODEM_CHECK(dte->change_mode(dte, MODEM_PPP_MODE) == ESP_OK, "enter ppp mode failed", err);
/
Create PPPoS interface /
printf("PPPOS create \n");
esp_dte->ppp = pppapi_pppos_create(&(esp_dte->pppif), pppos_low_level_output, on_ppp_status_changed, dte);
MODEM_CHECK(esp_dte->ppp, "create pppos interface failed", err);
#if PPP_NOTIFY_PHASE
ppp_set_notify_phase_callback(esp_dte->ppp, on_ppp_notify_phase);
#endif
/
Initiate PPP client connection /
/
Set default route /
printf("PPPOS set default \n");
MODEM_CHECK(pppapi_set_default(esp_dte->ppp) == ERR_OK, "set default route failed", err);
/
Ask the peer for up to 2 DNS server addresses /
ppp_set_usepeerdns(esp_dte->ppp, 1);
/
Auth configuration /
#if PAP_SUPPORT
pppapi_set_auth(esp_dte->ppp, PPPAUTHTYPE_PAP, CONFIG_EXAMPLE_MODEM_PPP_AUTH_USERNAME, CONFIG_EXAMPLE_MODEM_PPP_AUTH_PASSWORD);
#elif CHAP_SUPPORT
pppapi_set_auth(esp_dte->ppp, PPPAUTHTYPE_CHAP, CONFIG_ESP_MODEM_PPP_AUTH_USERNAME, CONFIG_ESP_MODEM_PPP_AUTH_PASSWORD);
#else
#error "Unsupported AUTH Negotiation"
#endif
/
Initiate PPP negotiation, without waiting */
printf("PPPOS connect \n");
MODEM_CHECK(pppapi_connect(esp_dte->ppp, 0) == ERR_OK, "initiate ppp negotiation failed", err);
esp_event_post_to(esp_dte->event_loop_hdl, ESP_MODEM_EVENT, MODEM_EVENT_PPP_START, NULL, 0, 0);
return ESP_OK;
err:
return ESP_FAIL;
}

esp_err_t esp_modem_exit_ppp(modem_dte_t *dte)
{
modem_dce_t *dce = dte->dce;
MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
esp_modem_dte_t esp_dte = __containerof(dte, esp_modem_dte_t, parent);
/
Shutdown of PPP protocols /
MODEM_CHECK(pppapi_close(esp_dte->ppp, 0) == ERR_OK, "close ppp connection failed", err);
/
Enter command mode /
MODEM_CHECK(dte->change_mode(dte, MODEM_COMMAND_MODE) == ESP_OK, "enter command mode failed", err);
/
Hang up */
MODEM_CHECK(dce->hang_up(dce) == ESP_OK, "hang up failed", err);
return ESP_OK;
err:
return ESP_FAIL;
}

@kannannair084
Copy link
Author

image

@kannannair084
Copy link
Author

i think this issue is very similar to another thread
#4268

just that, not clear what needs to be done to resolve the issue. I am currently using IDF v4.0.1, do i need to update IDF?

@kannannair084
Copy link
Author

Also, tried to change IDF to version 4.2 and i am not able to get the IP address

entry 0x40080688
I (28) boot: ESP-IDF v4.2-beta1-227-gf0e87c933 2nd stage bootloader
I (28) boot: compile time 09:51:10
I (29) boot: chip revision: 1
I (33) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (40) boot.esp32: SPI Speed : 40MHz
I (45) boot.esp32: SPI Mode : DIO
I (49) boot.esp32: SPI Flash Size : 16MB
I (54) boot: Enabling RNG early entropy source...
I (59) boot: Partition Table:
I (63) boot: ## Label Usage Type ST Offset Length
I (70) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (78) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (85) boot: 2 factory factory app 00 00 00010000 00100000
I (93) boot: End of partition table
I (97) boot_comm: chip revision: 1, min. application chip revision: 0
I (104) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x18e74 (102004) map
I (152) esp_image: segment 1: paddr=0x00028e9c vaddr=0x3ffb0000 size=0x02194 ( 8596) load
I (156) esp_image: segment 2: paddr=0x0002b038 vaddr=0x40080000 size=0x00404 ( 1028) load
0x40080000: _WindowOverflow4 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/xtensa_vectors.S:1730

I (159) esp_image: segment 3: paddr=0x0002b444 vaddr=0x40080404 size=0x04bd4 ( 19412) load
I (176) esp_image: segment 4: paddr=0x00030020 vaddr=0x400d0020 size=0x631a0 (405920) map
0x400d0020: _stext at ??:?

I (331) esp_image: segment 5: paddr=0x000931c8 vaddr=0x40084fd8 size=0x0676c ( 26476) load
0x40084fd8: panic_print_dec at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:101

I (349) boot: Loaded app from partition at offset 0x10000
I (349) boot: Disabling RNG early entropy source...
I (350) cpu_start: Pro cpu up.
I (353) cpu_start: Application information:
I (358) cpu_start: Project name: pppos_client
I (363) cpu_start: App version: 1
I (368) cpu_start: Compile time: Oct 21 2020 09:50:33
I (374) cpu_start: ELF file SHA256: 21e1d8438c072f35...
I (380) cpu_start: ESP-IDF: v4.2-beta1-227-gf0e87c933
I (386) cpu_start: Starting app cpu, entry point is 0x400818e4
0x400818e4: call_start_cpu1 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/cpu_start.c:287

I (0) cpu_start: App cpu up.
I (397) heap_init: Initializing. RAM available for dynamic allocation:
I (404) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (410) heap_init: At 3FFB3A20 len 0002C5E0 (177 KiB): DRAM
I (416) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (422) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (429) heap_init: At 4008B744 len 000148BC (82 KiB): IRAM
I (435) cpu_start: Pro cpu start user code
I (453) spi_flash: detected chip: gd
I (454) spi_flash: flash io: dio
I (454) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (464) uart: queue free spaces: 30
I (1624) pppos_example: Module: BG96
I (1624) pppos_example: Operator: "Telstra Mobile SORACOM"
I (1624) pppos_example: IMEI: 862785041881510
I (1624) pppos_example: IMSI: 295050911339686
I (1824) pppos_example: rssi: 15, ber: 99
I (2024) pppos_example: Battery voltage: 3857 mV
I (2224) pppos_example: Modem PPP Started
I (74374) esp-netif_lwip-ppp: Connection lost
I (74374) pppos_example: Modem Disconnect from PPP Server

This is based on the example ppos_client

@kannannair084
Copy link
Author

Rebooting...
ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:4
load:0x3fff0034,len:7260
load:0x40078000,len:13732
load:0x40080400,len:3988
0x40080400: _init at ??:?

entry 0x40080688
I (29) boot: ESP-IDF v4.2-beta1-227-gf0e87c933 2nd stage bootloader
I (29) boot: compile time 11:09:36
I (29) boot: chip revision: 1
I (33) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (41) boot.esp32: SPI Speed : 40MHz
I (45) boot.esp32: SPI Mode : DIO
I (50) boot.esp32: SPI Flash Size : 16MB
I (54) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (63) boot: ## Label Usage Type ST Offset Length
I (71) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (78) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (86) boot: 2 factory factory app 00 00 00010000 00100000
I (93) boot: End of partition table
I (97) boot_comm: chip revision: 1, min. application chip revision: 0
I (104) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x18e10 (101904) map
I (152) esp_image: segment 1: paddr=0x00028e38 vaddr=0x3ffb0000 size=0x035dc ( 13788) load
I (158) esp_image: segment 2: paddr=0x0002c41c vaddr=0x40080000 size=0x00404 ( 1028) load
0x40080000: _WindowOverflow4 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/xtensa_vectors.S:1730

I (159) esp_image: segment 3: paddr=0x0002c828 vaddr=0x40080404 size=0x037f0 ( 14320) load
I (174) esp_image: segment 4: paddr=0x00030020 vaddr=0x400d0020 size=0x6456c (410988) map
0x400d0020: _stext at ??:?

I (333) esp_image: segment 5: paddr=0x00094594 vaddr=0x40083bf4 size=0x07dd8 ( 32216) load
0x40083bf4: spi_flash_mmap at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/spi_flash/flash_mmap.c:143

I (354) boot: Loaded app from partition at offset 0x10000
I (355) boot: Disabling RNG early entropy source...
I (355) cpu_start: Pro cpu up.
I (359) cpu_start: Application information:
I (363) cpu_start: Project name: pppos_client
I (369) cpu_start: App version: 1
I (373) cpu_start: Compile time: Oct 21 2020 11:38:38
I (379) cpu_start: ELF file SHA256: 8b358d93eb67733f...
I (385) cpu_start: ESP-IDF: v4.2-beta1-227-gf0e87c933
I (392) cpu_start: Starting app cpu, entry point is 0x4008192c
0x4008192c: call_start_cpu1 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/cpu_start.c:287

I (384) cpu_start: App cpu up.
I (402) heap_init: Initializing. RAM available for dynamic allocation:
I (409) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (415) heap_init: At 3FFB54B8 len 0002AB48 (170 KiB): DRAM
I (422) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (428) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (434) heap_init: At 4008B9CC len 00014634 (81 KiB): IRAM
I (441) cpu_start: Pro cpu start user code
I (459) spi_flash: detected chip: gd
I (459) spi_flash: flash io: dio
I (460) esp_core_dump_uart: Init core dump to UART
I (462) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (476) uart: queue free spaces: 30
I (1636) pppos_example: Module: BG96
I (1636) pppos_example: Operator: "Telstra Mobile SORACOM"
I (1636) pppos_example: IMEI: 862785041881510
I (1636) pppos_example: IMSI: 295050911339686
I (1836) pppos_example: rssi: 12, ber: 99
I (2036) pppos_example: Battery voltage: 3855 mV
I (2236) pppos_example: Modem PPP Started
I (2536) esp-netif_lwip-ppp: Connected
I (2536) esp-netif_lwip-ppp: Name Server1: 100.127.0.53
I (2536) esp-netif_lwip-ppp: Name Server2: 100.127.1.53
I (2536) pppos_example: Modem Connect to PPP Server
I (2546) pppos_example: ~~~~~~~~~~~~~~
I (2546) pppos_example: IP : 10.170.33.19
I (2556) pppos_example: Netmask : 255.255.255.255
I (2556) pppos_example: Gateway : 10.64.64.64
I (2566) pppos_example: Name Server1: 100.127.0.53
I (2566) pppos_example: Name Server2: 100.127.1.53
I (2576) pppos_example: ~~~~~~~~~~~~~~
I (2576) pppos_example: GOT ip event!!!
I (2586) system_api: Base MAC address is not set
I (2586) system_api: read default base MAC address from EFUSE
I (2596) pppos_example: MQTT other event id: 7
I (4586) pppos_example: MQTT_EVENT_CONNECTED
I (4586) pppos_example: sent subscribe successful, msg_id=53437
I (5236) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=53437
I (5236) pppos_example: sent publish successful, msg_id=0
I (5836) pppos_example: MQTT_EVENT_DATA
TOPIC=/topic/esp-pppos
DATA=esp32-pppos
I (6486) pppos_example: Modem PPP Stopped
I (6536) esp-netif_lwip-ppp: User interrupt
W (8036) esp-modem: Pattern Queue Size too small
W (8136) esp-modem: Pattern Queue Size too small
E (9486) esp-modem: esp_modem_dte_send_cmd(229): process command timeout
E (9486) bg96: bg96_set_working_mode(298): send command failed
E (9486) esp-modem: esp_modem_dte_change_mode(319): set new working mode:0 failed
E (9496) esp-modem: esp_modem_stop_ppp(499): enter command mode failed
ESP_ERROR_CHECK failed: esp_err_t 0xffffffff (ESP_FAIL) at 0x40083ec0
0x40083ec0: _esp_error_check_failed at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/esp_err.c:45

file: "../main/pppos_client_main.c" line 296
func: app_main
expression: esp_modem_stop_ppp(dte)

abort() was called at PC 0x40083ec3 on core 0
0x40083ec3: _esp_error_check_failed at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/esp_err.c:46

Backtrace:0x40085013:0x3ffb71f0 0x40085701:0x3ffb7210 0x4008959a:0x3ffb7230 0x40083ec3:0x3ffb72a0 0x400d6ca2:0x3ffb72c0 0x400d5282:0x3ffb73f0 0x40085709:0x3ffb7420
0x40085013: panic_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:330

0x40085701: esp_system_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/system_api.c:106

0x4008959a: abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/newlib/abort.c:46

0x40083ec3: _esp_error_check_failed at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/esp_err.c:46

0x400d6ca2: app_main at c:\olf\development\firmware\ppos\pppos_client\build/../main/pppos_client_main.c:296 (discriminator 1)

0x400d5282: main_task at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/cpu_start.c:600 (discriminator 2)

0x40085709: vPortTaskWrapper at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

ELF file SHA256: 8b358d93eb67733f

Initiating core dump!
I (9533) esp_core_dump_uart: Press Enter to print core dump to UART...
I (9542) esp_core_dump_uart: Print core dump to uart...
I (9546) esp_core_dump_elf: Found tasks: 10
Core dump started (further output muted)
Received 21 kB...
Core dump finished!
espcoredump.py v0.4-dev

==================== ESP32 CORE DUMP START ====================

Crashed task handle: 0x3ffb74b0, name: 'main', GDB name: 'process 1073444016'

================== CURRENT THREAD REGISTERS ===================
exccause 0x1d (StoreProhibitedCause)
excvaddr 0x0
epc1 0x0
epc2 0x0
epc3 0x0
epc4 0x0
epc5 0x0
epc6 0x0
epc7 0x0
eps2 0x0
eps3 0x0
eps4 0x0
eps5 0x0
eps6 0x0
eps7 0x40130fc3
pc 0x40085016 0x40085016 <panic_abort+18>
lbeg 0x4000c349 1073791817
lend 0x4000c36b 1073791851
lcount 0x0 0
sar 0x10 16
ps 0x60220 393760
threadptr
br
scompare1
acclo
acchi
m0
m1
m2
m3
expstate
f64r_lo
f64r_hi
f64s
fcr
fsr
a0 0x80085704 -2146937084
a1 0x3ffb71f0 1073443312
a2 0x3ffb723b 1073443387
a3 0x3ffb7268 1073443432
a4 0xa 10
a5 0x36 54
a6 0x0 0
a7 0x3ffb71a4 1073443236
a8 0x0 0
a9 0x1 1
a10 0x3ffb7239 1073443385
a11 0x3ffb7239 1073443385
a12 0x0 0
a13 0x2000 8192
a14 0x3ffb71a2 1073443234
a15 0x3ffb70e0 1073443040

==================== CURRENT THREAD STACK =====================
#0 0x40085016 in panic_abort (details=0x3ffb723b "abort() was called at PC 0x40083ec3 on core 0") at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:341
#1 0x40085704 in esp_system_abort (details=0x3ffb723b "abort() was called at PC 0x40083ec3 on core 0") at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/system_api.c:106
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

======================== THREADS INFO =========================
Id Target Id Frame

  • 1 process 1073444016 0x40085016 in panic_abort (details=0x3ffb723b "abort() was called at PC 0x40083ec3 on core 0") at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:341
    2 process 1073447824 0x40131c92 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
    3 process 1073445920 0x40131c92 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
    4 process 1073460204 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    5 process 1073477080 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    6 process 1073450492 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    7 process 1073412748 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    8 process 1073438192 0x400886fc in xQueueGenericReceive (xQueue=0x3ffb5990, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
    9 process 1073464296 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    10 process 1073413704 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115

==================== THREAD 1 (TCB: 0x3ffb74b0, name: 'main') =====================
#0 0x40085016 in panic_abort (details=0x3ffb723b "abort() was called at PC 0x40083ec3 on core 0") at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:341
#1 0x40085704 in esp_system_abort (details=0x3ffb723b "abort() was called at PC 0x40083ec3 on core 0") at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/system_api.c:106
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

==================== THREAD 2 (TCB: 0x3ffb8390, name: 'IDLE1') =====================
#0 0x40131c92 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
#1 0x400d5fd6 in esp_vApplicationIdleHook () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/freertos_hooks.c:63
#2 0x400860e0 in prvIdleTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:3386
#3 0x4008570c in vPortTaskWrapper (pxCode=0x400860d4 , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 3 (TCB: 0x3ffb7c20, name: 'IDLE0') =====================
#0 0x40131c92 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
#1 0x400d5fd6 in esp_vApplicationIdleHook () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/freertos_hooks.c:63
#2 0x400860e0 in prvIdleTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:3386
#3 0x4008570c in vPortTaskWrapper (pxCode=0x400860d4 , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 4 (TCB: 0x3ffbb3ec, name: 'tiT') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffb91cc, pvBuffer=0x3ffbb330, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x400f1f48 in sys_arch_mbox_fetch (mbox=, msg=0x3ffbb330, timeout=100) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/port/esp32/freertos/sys_arch.c:325
#3 0x400dec37 in tcpip_timeouts_mbox_fetch (mbox=0x3ffb44a8 <tcpip_mbox>, msg=0x3ffbb330) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:110
#4 0x400decef in tcpip_thread (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:148
#5 0x4008570c in vPortTaskWrapper (pxCode=0x400decd4 <tcpip_thread>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 5 (TCB: 0x3ffbf5d8, name: 'uart_event') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffbebc0, pvBuffer=0x3ffbf4e0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x40133bbc in esp_event_loop_run (event_loop=0x3ffbe090, ticks_to_run=5) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:624
#3 0x400d6f85 in uart_event_task_entry (param=0x3ffbdb70) at ../components/modem/src/esp_modem.c:201
#4 0x4008570c in vPortTaskWrapper (pxCode=0x400d6ea0 <uart_event_task_entry>, pvParameters=0x3ffbdb70) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 6 (TCB: 0x3ffb8dfc, name: 'Tmr Svc') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40087a4e in prvProcessTimerOrBlockTask (xNextExpireTime=, xListWasEmpty=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x40087b3b in prvTimerTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/timers.c:544
#3 0x4008570c in vPortTaskWrapper (pxCode=0x40087b2c , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 7 (TCB: 0x3ffafa8c, name: 'esp_timer') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffaea2c, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x400d615f in timer_task (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_timer/src/esp_timer.c:329
#3 0x4008570c in vPortTaskWrapper (pxCode=0x400d614c <timer_task>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 8 (TCB: 0x3ffb5df0, name: 'ipc1') =====================
#0 0x400886fc in xQueueGenericReceive (xQueue=0x3ffb5990, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#1 0x400831af in ipc_task (arg=0x1) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_ipc/ipc.c:51
#2 0x4008570c in vPortTaskWrapper (pxCode=0x4008317c <ipc_task>, pvParameters=0x1) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 9 (TCB: 0x3ffbc3e8, name: 'sys_evt') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffbb62c, pvBuffer=0x3ffbc300, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x40133bbc in esp_event_loop_run (event_loop=0x3ffbb610, ticks_to_run=4294967295) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:624
#3 0x40133bd4 in esp_event_loop_run_task (args=0x3ffbb610) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:115
#4 0x4008570c in vPortTaskWrapper (pxCode=0x40133bc8 <esp_event_loop_run_task>, pvParameters=0x3ffbb610) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 10 (TCB: 0x3ffafe48, name: 'ipc0') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffafdec, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x400831af in ipc_task (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_ipc/ipc.c:51
#3 0x4008570c in vPortTaskWrapper (pxCode=0x4008317c <ipc_task>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

======================= ALL MEMORY REGIONS ========================
Name Address Size Attrs
.rtc.text 0x400c0000 0x0 RW
.rtc.dummy 0x3ff80000 0x0 RW
.rtc.force_fast 0x3ff80000 0x0 RW
.rtc_noinit 0x50000000 0x0 RW
.rtc.force_slow 0x50000000 0x0 RW
.iram0.vectors 0x40080000 0x404 R XA
.iram0.text 0x40080404 0xb5c8 R XA
.dram0.data 0x3ffb0000 0x35dc RW A
.noinit 0x3ffb35dc 0x0 RW
.flash.rodata 0x3f400020 0x18e10 RW A
.flash.text 0x400d0020 0x6456c R XA
.iram0.data 0x4008b9cc 0x0 RW
.iram0.bss 0x4008b9cc 0x0 RW
.dram0.heap_start 0x3ffb54b8 0x0 RW
.coredump.tasks.data 0x3ffb74b0 0x168 RW
.coredump.tasks.data 0x3ffb7130 0x378 RW
.coredump.tasks.data 0x3ffb8390 0x168 RW
.coredump.tasks.data 0x3ffb81e0 0x1a8 RW
.coredump.tasks.data 0x3ffb7c20 0x168 RW
.coredump.tasks.data 0x3ffb7a70 0x1a8 RW
.coredump.tasks.data 0x3ffbb3ec 0x168 RW
.coredump.tasks.data 0x3ffbb1c0 0x224 RW
.coredump.tasks.data 0x3ffbf5d8 0x168 RW
.coredump.tasks.data 0x3ffbf3c0 0x210 RW
.coredump.tasks.data 0x3ffb8dfc 0x168 RW
.coredump.tasks.data 0x3ffb8c30 0x1c4 RW
.coredump.tasks.data 0x3ffafa8c 0x168 RW
.coredump.tasks.data 0x3ffaf8c0 0x1c4 RW
.coredump.tasks.data 0x3ffb5df0 0x168 RW
.coredump.tasks.data 0x3ffb5c40 0x1a8 RW
.coredump.tasks.data 0x3ffbc3e8 0x168 RW
.coredump.tasks.data 0x3ffbc1e0 0x200 RW
.coredump.tasks.data 0x3ffafe48 0x168 RW
.coredump.tasks.data 0x3ffb5710 0x1c0 RW

===================== ESP32 CORE DUMP END =====================

Done!
Coredump SHA256='29db22facabe59548fff08f240fd3a7107b59f203db90ea8b3b9f49458b6a017'
I (11474) esp_core_dump_uart: Core dump has been written to uart.
Rebooting...

@kannannair084
Copy link
Author

Narrowed down the issue to be that BG96 doesn't enter Command mode in the esp_modem_stop_ppp.

is there a way to fix this?

@kannannair084
Copy link
Author

@Alvin1Zhang could you help, our project has entered a critical juncture and this issue is impeding the progress.

@david-cermak
Copy link
Collaborator

Hi @kannannair084

Thanks for the report and your investigation, is this a random issue or does the happen consistently, all the time?
Possible reasons, why the modem couldn't not enter the command mode, are:

  1. +++ command is mistaken by data (there should be 1s delay before and after the command)
  2. the modem is already in command mode (cause by a disconnection from PPP server)
  3. the modem doesn't respond for some reason (reset or power line should be pulled down)

The current PPPoS example doesn't correctly address points 1) and 2), unfortunately. Could you please add this debugging line to esp_modem.c into the esp_handle_uart_data() function:

    if (length) {
        ESP_LOG_BUFFER_HEXDUMP(MODEM_TAG, esp_dte->buffer, length, ESP_LOG_INFO);
        esp_dte->receive_cb(esp_dte->buffer, length, esp_dte->receive_cb_ctx);
    }

So that we understand the issue better.
The output could be for example:

I (2875) pppos_example: PPP state changed event 256
D (2885) event: running post NETIF_PPP_STATUS:5 with handler 0x400d86bc and context 0x3ffbbb38 on loop 0x3ffbabb4
0x400d86bc: on_ppp_changed at /home/david/dev3/esp-idf/examples/protocols/pppos_client/build/../main/pppos_client_main.c:172

I (2895) pppos_example: PPP state changed event 5
I (2905) pppos_example: User interrupted event from netif:0x3ffb6574
I (3955) esp-modem: 0x3ffbbbc8   0d 0a 4e 4f 20 43 41 52  52 49 45 52 0d 0a 0d 0a  |..NO CARRIER....|
I (3955) esp-modem: 0x3ffbbbd8   2b 50 50 50 44 3a 20 44  49 53 43 4f 4e 4e 45 43  |+PPPD: DISCONNEC|
I (3965) esp-modem: 0x3ffbbbe8   54 45 44 0d 0a                                    |TED..|
D (13755) bg96: Sending +++!
E (23755) esp-modem: esp_modem_dte_send_cmd(247): process command timeout

The above shows the issue where the device already exited data mode, sending commands, but the esp_modem still assumes data mode.

@david-cermak
Copy link
Collaborator

Could you please test with the below patch?

0001-esp_modem-Fixed-stop_ppp-to-fist-exit-the-data-mode-.patch.txt

It works around the problem to first switch back to the command mode and then exit the networking mode of the PPP client. I've also added some debug prints and retries to better understand the issue.

@kannannair084
Copy link
Author

It failed but not showing the set mode change error any more:

I (38953) pppos_example: GOT ip event!!!
I (38963) system_api: Base MAC address is not set
I (38963) system_api: read default base MAC address from EFUSE
I (38973) pppos_example: MQTT other event id: 7
pppos_netif_output[0]: proto=0x21, len = 62
pppos_netif_output[0]: proto=0x21, len = 62
I (39763) esp-modem: 0x3ffbd924 7e 21 45 00 00 |!E..|
pppos_input[0]: got 5 bytes
I (39813) esp-modem: 0x3ffbd924 4e 63 63 00 00 40 11 86 cb 64 7f 00 35 0a aa 21 |[email protected]..!|
I (39813) esp-modem: 0x3ffbd934 13 00 35 3b b5 00 3a e5 8c 78 3b 81 80 00 01 00 |..5;..:..x;.....|
I (39813) esp-modem: 0x3ffbd944 01 00 00 00 00 04 6d 71 74 74 07 65 63 6c 69 70 |......mqtt.eclip|
I (39823) esp-modem: 0x3ffbd954 73 65 03 6f 72 67 00 00 01 00 01 c0 0c 00 01 00 |se.org..........|
I (39833) esp-modem: 0x3ffbd964 01 00 00 4e bf 00 04 89 87 53 d9 ec 88 7e |...N.....S...
|
pppos_input[0]: got 78 bytes
ppp_input[0]: ip in pbuf len=78
pppos_netif_output[0]: proto=0x21, len = 44
I (39953) esp-modem: 0x3ffbd924 7e 21 45 00 00 4e 63 87 00 00 40 11 86 a7 64 7f |[email protected].|
I (39953) esp-modem: 0x3ffbd934 00 35 0a aa 21 13 00 35 3b b5 00 3a e5 8d 78 3b |.5..!..5;..:..x;|
I (39953) esp-modem: 0x3ffbd944 81 80 00 01 00 01 00 00 00 00 04 6d 71 74 74 07 |...........mqtt.|
I (39963) esp-modem: 0x3ffbd954 65 63 6c 69 70 73 65 03 6f 72 67 00 00 01 00 01 |eclipse.org.....|
I (39973) esp-modem: 0x3ffbd964 c0 0c 00 01 00 01 00 00 4e be 00 04 89 87 53 d9 |........N.....S.|
I (39983) esp-modem: 0x3ffbd974 ce 95 7e |..
|
pppos_input[0]: got 83 bytes
ppp_input[0]: ip in pbuf len=78
pppos_netif_output[0]: proto=0x21, len = 56
I (40353) esp-modem: 0x3ffbd924 7e 21 45 00 00 2c 00 00 40 00 16 06 5b af 89 87 |!E..,..@...[...|
I (40353) esp-modem: 0x3ffbd934 53 d9 0a aa 21 13 07 5b dc 0c c5 fc 0d 0c 00 00 |S...!..[........|
I (40353) esp-modem: 0x3ffbd944 19 6e 60 12 fa f0 c4 a3 00 00 02 04 05 3a d2 0e |.n`..........:..|
I (40363) esp-modem: 0x3ffbd954 7e |
|
pppos_input[0]: got 49 bytes
ppp_input[0]: ip in pbuf len=44
pppos_netif_output[0]: proto=0x21, len = 40
pppos_netif_output[0]: proto=0x21, len = 66
I (41083) esp-modem: 0x3ffbd924 7e 21 45 00 00 28 e0 0c 40 00 16 06 7b a6 89 87 |!E..(..@...{...|
I (41083) esp-modem: 0x3ffbd934 53 d9 0a aa 21 13 07 5b dc 0c c5 fc 0d 0d 00 00 |S...!..[........|
I (41093) esp-modem: 0x3ffbd944 19 88 50 10 fa d6 db e6 00 00 50 b1 7e 7e 21 45 |..P.......P.~~!E|
I (41103) esp-modem: 0x3ffbd954 00 00 2c e0 0d 40 00 16 06 7b a1 89 87 53 d9 0a |..,..@...{...S..|
I (41113) esp-modem: 0x3ffbd964 aa 21 13 07 5b dc 0c c5 fc 0d 0d 00 00 19 88 50 |.!..[..........P|
I (41113) esp-modem: 0x3ffbd974 18 fa d6 bb d8 00 00 20 02 00 00 d5 14 7e |....... .....
|
pppos_input[0]: got 94 bytes
ppp_input[0]: ip in pbuf len=40
ppp_input[0]: ip in pbuf len=44
I (41143) pppos_example: MQTT_EVENT_CONNECTED
pppos_netif_output[0]: proto=0x21, len = 63
I (41143) pppos_example: sent subscribe successful, msg_id=49215
I (41733) esp-modem: 0x3ffbd924 7e 21 45 00 00 2d e0 0e 40 00 16 06 7b 9f 89 87 |!E..-..@...{...|
I (41733) esp-modem: 0x3ffbd934 53 d9 0a aa 21 13 07 5b dc 0c c5 fc 0d 11 00 00 |S...!..[........|
I (41733) esp-modem: 0x3ffbd944 19 9f 50 18 fa bf 8b 92 00 00 90 03 c0 3f 00 8b |..P..........?..|
I (41743) esp-modem: 0x3ffbd954 37 7e |7
|
pppos_input[0]: got 50 bytes
ppp_input[0]: ip in pbuf len=45
I (41763) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=49215
pppos_netif_output[0]: proto=0x21, len = 71
I (41773) pppos_example: sent publish successful, msg_id=0
I (42363) esp-modem: 0x3ffbd924 7e 21 45 00 00 47 e0 0f 40 00 16 06 7b 84 89 87 |!E..G..@...{...|
I (42363) esp-modem: 0x3ffbd934 53 d9 0a aa 21 13 07 5b dc 0c c5 fc 0d 16 00 00 |S...!..[........|
I (42363) esp-modem: 0x3ffbd944 19 be 50 18 fa a0 97 63 00 00 30 1d 00 10 2f 74 |..P....c..0.../t|
I (42373) esp-modem: 0x3ffbd954 6f 70 69 63 2f 65 73 70 2d 70 70 70 6f 73 65 73 |opic/esp-ppposes|
I (42383) esp-modem: 0x3ffbd964 70 33 32 2d 70 70 70 6f 73 c2 bb 7e |p32-pppos..
|
pppos_input[0]: got 76 bytes
ppp_input[0]: ip in pbuf len=71
I (42403) pppos_example: MQTT_EVENT_DATA
TOPIC=/topic/esp-pppos
DATA=esp32-pppos
pppos_netif_output[0]: proto=0x21, len = 42
I (43003) esp-modem: 0x3ffbd924 7e 21 45 00 00 28 e0 10 40 00 16 06 7b a2 89 87 |!E..(..@...{...|
I (43003) esp-modem: 0x3ffbd934 53 d9 0a aa 21 13 07 5b dc 0c c5 fc 0d 35 00 00 |S...!..[.....5..|
I (43003) esp-modem: 0x3ffbd944 19 c0 50 11 fa 9e db bd 00 00 38 36 7e |..P.......86
|
pppos_input[0]: got 45 bytes
ppp_input[0]: ip in pbuf len=40
pppos_netif_output[0]: proto=0x21, len = 40
pppos_netif_output[0]: proto=0x21, len = 40
I (46033) pppos_example: Modem PPP Stopped
ppp_close[0]: kill_link -> lcp_close
ppp phase changed[0]: phase=11
ppp phase changed[0]: phase=9
sifvjcomp[0]: VJ compress enable=0 slot=0 max slot=0
sifdown[0]: err_code=5
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=0 0 0 0
ppp_recv_config[0]
sent [LCP TermReq id=0x2 "User request"]
pppos_write[0]: len=20
I (46253) pppos_example: Power down
I (46253) pppos_example: Restart after 60 seconds
sent [LCP TermReq id=0x3 "User request"]
Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.

Core 0 register dump:
PC : 0x40132819 PS : 0x00060630 A0 : 0x80132bfe A1 : 0x3ffbb1d0
0x40132819: esp_modem_dte_transmit at c:\olf\development\firmware\ppos\pppos_client\build/../components/modem/src/esp_modem_netif.c:43

A2 : 0x3ffb6278 A3 : 0x3ffbfae0 A4 : 0x0000001d A5 : 0x3ffbad90
A6 : 0x00000020 A7 : 0x00000010 A8 : 0x00000000 A9 : 0x3ffbb1a0
A10 : 0x3ffb4fa0 A11 : 0x3ffae8f0 A12 : 0x00000000 A13 : 0x3ffbf500
A14 : 0x3ffbf4f0 A15 : 0x00000001 SAR : 0x00000010 EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000064 LBEG : 0x400014fd LEND : 0x4000150d LCOUNT : 0xfffffff5

Backtrace:0x40132816:0x3ffbb1d0 0x40132bfb:0x3ffbb1f0 0x400de225:0x3ffbb210 0x400f0570:0x3ffbb230 0x400f0759:0x3ffbb250 0x400efc1a:0x3ffbb280 0x400fadd7:0x3ffbb2a0 0x400fae2f:0x3ffbb2d0 0x400e71a5:0x3ffbb2f0 0x400deeda:0x3ffbb310 0x400def8c:0x3ffbb330 0x40085709:0x3ffbb360
0x40132816: esp_modem_dte_transmit at c:\olf\development\firmware\ppos\pppos_client\build/../components/modem/src/esp_modem_netif.c:41

0x40132bfb: esp_netif_transmit at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip.c:756

0x400de225: pppos_low_level_output at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip_ppp.c:233

0x400f0570: pppos_output_last at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:878

0x400f0759: pppos_write at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:244

0x400efc1a: ppp_write at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/ppp.c:993

0x400fadd7: fsm_sdata at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:796

0x400fae2f: fsm_timeout at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:282

0x400e71a5: sys_check_timeouts at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/core/timeouts.c:400

0x400deeda: tcpip_timeouts_mbox_fetch at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:115

0x400def8c: tcpip_thread at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:148

0x40085709: vPortTaskWrapper at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

@kannannair084
Copy link
Author

Not sure why, i couldnt post it correctly, so attaching as text file:
Log_and_dump.txt

@kannannair084
Copy link
Author

These are the modified functions as per patch , please double check if i have missed any or mis-placed it

/* esp modem netif */
static esp_err_t esp_modem_dte_transmit(void *h, void *buffer, size_t len)
 {
     modem_dte_t *dte = h;
    if (dte->dce->mode == MODEM_COMMAND_MODE) 
	{
       return ESP_OK;
    }
    if (dte->send_data(dte, (const char *)buffer, len) > 0) 
	{
       return ESP_OK;
    }
	return ESP_FAIL;
 }

//esp_modem.c
esp_err_t esp_modem_stop_ppp(modem_dte_t *dte)
{
    modem_dce_t *dce = dte->dce;
    MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
    esp_modem_dte_t *esp_dte = __containerof(dte, esp_modem_dte_t, parent);
   /* Fist enter the command mode */
     MODEM_CHECK(dte->change_mode(dte, MODEM_COMMAND_MODE) == ESP_OK, "enter command mode failed", err);
     /* Hang up */
     MODEM_CHECK(dce->hang_up(dce) == ESP_OK, "hang up failed", err);
   /* Next exit PPP network interface */
    /* post PPP mode stopped event */
    esp_event_post_to(esp_dte->event_loop_hdl, ESP_MODEM_EVENT, ESP_MODEM_EVENT_PPP_STOP, NULL, 0, 0);
    return ESP_OK;
err:
    return ESP_FAIL;
}

static esp_err_t esp_modem_dte_change_mode(modem_dte_t *dte, modem_mode_t new_mode)
{
    modem_dce_t *dce = dte->dce;
    MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
    esp_modem_dte_t *esp_dte = __containerof(dte, esp_modem_dte_t, parent);
    MODEM_CHECK(dce->mode != new_mode, "already in mode: %d", err, new_mode);
    switch (new_mode) {
    case MODEM_PPP_MODE:
        MODEM_CHECK(dce->set_working_mode(dce, new_mode) == ESP_OK, "set new working mode:%d failed", err, new_mode);
        uart_disable_pattern_det_intr(esp_dte->uart_port);
        uart_enable_rx_intr(esp_dte->uart_port);
        break;
    case MODEM_COMMAND_MODE:
        uart_flush(esp_dte->uart_port);
		uart_enable_pattern_det_baud_intr(esp_dte->uart_port, '\n', 1, MIN_PATTERN_INTERVAL, MIN_POST_IDLE, MIN_PRE_IDLE);
		uart_disable_rx_intr(esp_dte->uart_port);        
        uart_pattern_queue_reset(esp_dte->uart_port, esp_dte->pattern_queue_size);
        dce->mode = MODEM_COMMAND_MODE;
        vTaskDelay(pdMS_TO_TICKS(1000));
        MODEM_CHECK(dce->set_working_mode(dce, new_mode) == ESP_OK, "set new working mode:%d failed", err, new_mode);
        vTaskDelay(pdMS_TO_TICKS(1000));
        break;
    default:
        break;
    }
    return ESP_OK;
err:
    return ESP_FAIL;
}

static void esp_handle_uart_data(esp_modem_dte_t *esp_dte)
{
    if (esp_dte->parent.dce->mode != MODEM_PPP_MODE) {
       // ESP_LOGE(MODEM_TAG, "Error: Got data event in PPP mode");
        /* pattern detection mode -> ignore date event on uart
         * (should never happen, but if it does, we could still
         * read the valid data once pattern detect event fired) */
        return;
    }
    size_t length = 0;
    uart_get_buffered_data_len(esp_dte->uart_port, &length);
    length = MIN(esp_dte->line_buffer_size, length);
    length = uart_read_bytes(esp_dte->uart_port, esp_dte->buffer, length, portMAX_DELAY);
    /* pass the input data to configured callback */
    if (length) {
        ESP_LOG_BUFFER_HEXDUMP(MODEM_TAG, esp_dte->buffer, length, ESP_LOG_INFO);
         esp_dte->receive_cb(esp_dte->buffer, length, esp_dte->receive_cb_ctx);
    }
}

/**
 * @brief Returns true if the supplied string contains only CR or LF
 *
 * @param str string to check
 * @param len length of string
 */
static inline bool is_only_cr_lf(const char *str, uint32_t len)
{
    for (int i=0; i<len; ++i) {
        if (str[i] != '\r' && str[i] != '\n') {
            return false;
        }
    }
   return true;
}


static esp_err_t esp_dte_handle_line(esp_modem_dte_t *esp_dte)
{
    modem_dce_t *dce = esp_dte->parent.dce;
    MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
    const char *line = (const char *)(esp_dte->buffer);
	size_t len = strlen(line);
    /* Skip pure "\r\n" lines */
    if (len > 2 && !is_only_cr_lf(line, len)) {
		ESP_LOGD(MODEM_TAG, "LINE=\"%s\"", line);
        MODEM_CHECK(dce->handle_line, "no handler for line", err_handle);
        MODEM_CHECK(dce->handle_line(dce, line) == ESP_OK, "handle line failed", err_handle);
    }
    return ESP_OK;
err_handle:
    /* Send ESP_MODEM_EVENT_UNKNOWN signal to event loop */
    esp_event_post_to(esp_dte->event_loop_hdl, ESP_MODEM_EVENT, ESP_MODEM_EVENT_UNKNOWN,
                      (void *)line, strlen(line) + 1, pdMS_TO_TICKS(100));
err:
    return ESP_FAIL;
}


/// modified code in bg96.c



static esp_err_t bg96_handle_exit_data_mode(modem_dce_t *dce, const char *line)
{
   esp_err_t err = ESP_OK;
	if (strstr(line, MODEM_RESULT_CODE_SUCCESS)) {
         err = esp_modem_process_command_done(dce, MODEM_STATE_SUCCESS);
     } else if (strstr(line, MODEM_RESULT_CODE_NO_CARRIER)) {
        err = esp_modem_process_command_done(dce, MODEM_STATE_SUCCESS);
    } else if (strstr(line, MODEM_RESULT_CODE_ERROR)) {
        err = esp_modem_process_command_done(dce, MODEM_STATE_FAIL);
    }
    return err;
}


static esp_err_t bg96_set_working_mode(modem_dce_t *dce, modem_mode_t mode)
{
    modem_dte_t *dte = dce->dte;
	int retry = 0;
    switch (mode) {
    case MODEM_COMMAND_MODE:
again:
	   if (retry++ > 5) goto err;
	   if (retry > 3) {
		   ESP_LOGD(DCE_TAG, "Sending AT command for %d time", retry);
		   dce->handle_line = esp_modem_dce_handle_response_default;
		   DCE_CHECK(dte->send_cmd(dte, "AT\r", MODEM_COMMAND_TIMEOUT_DEFAULT) == ESP_OK, "send command failed", again);
		} else {
			ESP_LOGD(DCE_TAG, "Sending +++ for %d time", retry);
			dce->handle_line = bg96_handle_exit_data_mode;
			DCE_CHECK(dte->send_cmd(dte, "+++", 20000) == ESP_OK, "send command failed", again);
			DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter command mode failed", err);
		}
        ESP_LOGD(DCE_TAG, "enter command mode ok");
        dce->mode = MODEM_COMMAND_MODE;
        break;
    case MODEM_PPP_MODE:
        dce->handle_line = bg96_handle_atd_ppp;
        DCE_CHECK(dte->send_cmd(dte, "ATD*99***1#\r", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) == ESP_OK, "send command failed", err);
        DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter ppp mode failed", err);
        ESP_LOGD(DCE_TAG, "enter ppp mode ok");
        dce->mode = MODEM_PPP_MODE;
        break;
    default:
        ESP_LOGW(DCE_TAG, "unsupported working mode: %d", mode);
        goto err;
        break;
		
    }
    return ESP_OK;
err:
    return ESP_FAIL;
}

@kannannair084
Copy link
Author

ELF file SHA256: da60e7829b14a192

Initiating core dump!
I (25290) esp_core_dump_uart: Press Enter to print core dump to UART...
I (25299) esp_core_dump_uart: Print core dump to uart...
I (25303) esp_core_dump_elf: Found tasks: 10
Core dump started (further output muted)
Received 21 kB...
Core dump finished!
espcoredump.py v0.4-dev

==================== ESP32 CORE DUMP START ====================

Crashed task handle: 0x3ffbb3ec, name: 'tiT', GDB name: 'process 1073460204'

================== CURRENT THREAD REGISTERS ===================
exccause 0x1c (LoadProhibitedCause)
excvaddr 0x64
epc1 0x0
epc2 0x0
epc3 0x0
epc4 0x0
epc5 0x0
epc6 0x0
epc7 0x0
eps2 0x0
eps3 0x0
eps4 0x0
eps5 0x0
eps6 0x0
eps7 0x4013278f
pc 0x40132819 0x40132819 <esp_modem_dte_transmit+5>
lbeg 0x400014fd 1073747197
lend 0x4000150d 1073747213
lcount 0xfffffff5 4294967285
sar 0x10 16
ps 0x60420 394272
threadptr
br
scompare1
acclo
acchi
m0
m1
m2
m3
expstate
f64r_lo
f64r_hi
f64s
fcr
fsr
a0 0x80132bfe -2146227202
a1 0x3ffbb1d0 1073459664
a2 0x3ffb6278 1073439352
a3 0x3ffbfae0 1073478368
a4 0x1d 29
a5 0x3ffbad90 1073458576
a6 0x20 32
a7 0x10 16
a8 0x0 0
a9 0x3ffbb1a0 1073459616
a10 0x3ffb4fa0 1073434528
a11 0x3ffae8f0 1073408240
a12 0x0 0
a13 0x3ffbf500 1073476864
a14 0x3ffbf4f0 1073476848
a15 0x1 1

==================== CURRENT THREAD STACK =====================
#0 0x40132819 in esp_modem_dte_transmit (h=0x3ffb6278, buffer=0x3ffbfae0, len=29) at ../components/modem/src/esp_modem_netif.c:43
#1 0x40132bfe in esp_netif_transmit (esp_netif=0x3ffb5f5c, data=0x3ffbfae0, len=29) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip.c:756
#2 0x400de228 in pppos_low_level_output (pcb=0x3ffbc69c, data=0x3ffbfae0 <error: Cannot access memory at address 0x3ffbfae0>, len=29, netif=0x3ffb5f5c) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip_ppp.c:233
#3 0x400f0573 in pppos_output_last (pppos=0x3ffb61fc, err=0 '\000', nb=0x3ffbfac8, fcs=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:878
#4 0x400f075c in pppos_write (ppp=0x3ffbc69c, ctx=0x3ffb61fc, p=0x3ffbf4d4) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:244
#5 0x400efc1d in ppp_write (pcb=0x3ffbc69c, p=0x3ffbf4d4) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/ppp.c:993
#6 0x400fadda in fsm_sdata (f=, code=5 '\005', id=3 '\003', data=0x3f40c150 "User request", datalen=12) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:796
#7 0x400fae32 in fsm_timeout (arg=0x3ffbc6e4) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:282
#8 0x400e71a8 in sys_check_timeouts () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/core/timeouts.c:400
#9 0x400deedd in tcpip_timeouts_mbox_fetch (mbox=0x3ffb44a8 <tcpip_mbox>, msg=0x3ffbb330) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:115
#10 0x400def8f in tcpip_thread (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:148
#11 0x4008570c in vPortTaskWrapper (pxCode=0x400def74 <tcpip_thread>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

======================== THREADS INFO =========================
Id Target Id Frame

  • 1 process 1073460204 0x40132819 in esp_modem_dte_transmit (h=0x3ffb6278, buffer=0x3ffbfae0, len=29) at ../components/modem/src/esp_modem_netif.c:43
    2 process 1073475960 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    3 process 1073447824 0x4013335a in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
    4 process 1073445920 0x4013335a in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
    5 process 1073444016 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    6 process 1073450492 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    7 process 1073412748 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    8 process 1073438192 0x400886fc in xQueueGenericReceive (xQueue=0x3ffb5990, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
    9 process 1073464296 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    10 process 1073413704 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115

==================== THREAD 1 (TCB: 0x3ffbb3ec, name: 'tiT') =====================
#0 0x40132819 in esp_modem_dte_transmit (h=0x3ffb6278, buffer=0x3ffbfae0, len=29) at ../components/modem/src/esp_modem_netif.c:43
#1 0x40132bfe in esp_netif_transmit (esp_netif=0x3ffb5f5c, data=0x3ffbfae0, len=29) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip.c:756
#2 0x400de228 in pppos_low_level_output (pcb=0x3ffbc69c, data=0x3ffbfae0 <error: Cannot access memory at address 0x3ffbfae0>, len=29, netif=0x3ffb5f5c) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip_ppp.c:233
#3 0x400f0573 in pppos_output_last (pppos=0x3ffb61fc, err=0 '\000', nb=0x3ffbfac8, fcs=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:878
#4 0x400f075c in pppos_write (ppp=0x3ffbc69c, ctx=0x3ffb61fc, p=0x3ffbf4d4) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:244
#5 0x400efc1d in ppp_write (pcb=0x3ffbc69c, p=0x3ffbf4d4) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/ppp.c:993
#6 0x400fadda in fsm_sdata (f=, code=5 '\005', id=3 '\003', data=0x3f40c150 "User request", datalen=12) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:796
#7 0x400fae32 in fsm_timeout (arg=0x3ffbc6e4) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:282
#8 0x400e71a8 in sys_check_timeouts () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/core/timeouts.c:400
#9 0x400deedd in tcpip_timeouts_mbox_fetch (mbox=0x3ffb44a8 <tcpip_mbox>, msg=0x3ffbb330) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:115
#10 0x400def8f in tcpip_thread (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:148
#11 0x4008570c in vPortTaskWrapper (pxCode=0x400def74 <tcpip_thread>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 2 (TCB: 0x3ffbf178, name: 'uart_event') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffbe760, pvBuffer=0x3ffbf080, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x4013566c in esp_event_loop_run (event_loop=0x3ffbdcf4, ticks_to_run=5) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:624
#3 0x400d71d1 in uart_event_task_entry (param=0x3ffb6260) at ../components/modem/src/esp_modem.c:221
#4 0x4008570c in vPortTaskWrapper (pxCode=0x400d70ec <uart_event_task_entry>, pvParameters=0x3ffb6260) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 3 (TCB: 0x3ffb8390, name: 'IDLE1') =====================
#0 0x4013335a in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
#1 0x400d60da in esp_vApplicationIdleHook () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/freertos_hooks.c:63
#2 0x400860e0 in prvIdleTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:3386
#3 0x4008570c in vPortTaskWrapper (pxCode=0x400860d4 , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 4 (TCB: 0x3ffb7c20, name: 'IDLE0') =====================
#0 0x4013335a in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
#1 0x400d60da in esp_vApplicationIdleHook () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/freertos_hooks.c:63
#2 0x400860e0 in prvIdleTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:3386
#3 0x4008570c in vPortTaskWrapper (pxCode=0x400860d4 , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 5 (TCB: 0x3ffb74b0, name: 'main') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40087272 in vTaskDelay (xTicksToDelay=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x400d6f41 in app_main () at ../main/pppos_client_main.c:305
#3 0x400d5389 in main_task (args=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/cpu_start.c:600
#4 0x4008570c in vPortTaskWrapper (pxCode=0x400d530c <main_task>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 6 (TCB: 0x3ffb8dfc, name: 'Tmr Svc') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40087a4e in prvProcessTimerOrBlockTask (xNextExpireTime=, xListWasEmpty=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x40087b3b in prvTimerTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/timers.c:544
#3 0x4008570c in vPortTaskWrapper (pxCode=0x40087b2c , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 7 (TCB: 0x3ffafa8c, name: 'esp_timer') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffaea2c, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x400d6263 in timer_task (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_timer/src/esp_timer.c:329
#3 0x4008570c in vPortTaskWrapper (pxCode=0x400d6250 <timer_task>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 8 (TCB: 0x3ffb5df0, name: 'ipc1') =====================
#0 0x400886fc in xQueueGenericReceive (xQueue=0x3ffb5990, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#1 0x400831af in ipc_task (arg=0x1) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_ipc/ipc.c:51
#2 0x4008570c in vPortTaskWrapper (pxCode=0x4008317c <ipc_task>, pvParameters=0x1) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 9 (TCB: 0x3ffbc3e8, name: 'sys_evt') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffbb62c, pvBuffer=0x3ffbc300, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x4013566c in esp_event_loop_run (event_loop=0x3ffbb610, ticks_to_run=4294967295) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:624
#3 0x40135684 in esp_event_loop_run_task (args=0x3ffbb610) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:115
#4 0x4008570c in vPortTaskWrapper (pxCode=0x40135678 <esp_event_loop_run_task>, pvParameters=0x3ffbb610) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 10 (TCB: 0x3ffafe48, name: 'ipc0') =====================
#0 0x40081bf0 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x400886fc in xQueueGenericReceive (xQueue=0x3ffafdec, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x400831af in ipc_task (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_ipc/ipc.c:51
#3 0x4008570c in vPortTaskWrapper (pxCode=0x4008317c <ipc_task>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

======================= ALL MEMORY REGIONS ========================
Name Address Size Attrs
.rtc.text 0x400c0000 0x0 RW
.rtc.dummy 0x3ff80000 0x0 RW
.rtc.force_fast 0x3ff80000 0x0 RW
.rtc_noinit 0x50000000 0x0 RW
.rtc.force_slow 0x50000000 0x0 RW
.iram0.vectors 0x40080000 0x404 R XA
.iram0.text 0x40080404 0xb5c8 R XA
.dram0.data 0x3ffb0000 0x35dc RW A
.noinit 0x3ffb35dc 0x0 RW
.flash.rodata 0x3f400020 0x1ad84 RW A
.flash.text 0x400d0020 0x6601c R XA
.iram0.data 0x4008b9cc 0x0 RW
.iram0.bss 0x4008b9cc 0x0 RW
.dram0.heap_start 0x3ffb54b8 0x0 RW
.coredump.tasks.data 0x3ffbb3ec 0x168 RW
.coredump.tasks.data 0x3ffbb110 0x2d4 RW
.coredump.tasks.data 0x3ffbf178 0x168 RW
.coredump.tasks.data 0x3ffbef60 0x210 RW
.coredump.tasks.data 0x3ffb8390 0x168 RW
.coredump.tasks.data 0x3ffb81e0 0x1a8 RW
.coredump.tasks.data 0x3ffb7c20 0x168 RW
.coredump.tasks.data 0x3ffb7a70 0x1a8 RW
.coredump.tasks.data 0x3ffb74b0 0x168 RW
.coredump.tasks.data 0x3ffb71c0 0x2e8 RW
.coredump.tasks.data 0x3ffb8dfc 0x168 RW
.coredump.tasks.data 0x3ffb8c30 0x1c4 RW
.coredump.tasks.data 0x3ffafa8c 0x168 RW
.coredump.tasks.data 0x3ffaf8c0 0x1c4 RW
.coredump.tasks.data 0x3ffb5df0 0x168 RW
.coredump.tasks.data 0x3ffb5c40 0x1a8 RW
.coredump.tasks.data 0x3ffbc3e8 0x168 RW
.coredump.tasks.data 0x3ffbc1e0 0x200 RW
.coredump.tasks.data 0x3ffafe48 0x168 RW
.coredump.tasks.data 0x3ffb5710 0x1c0 RW

===================== ESP32 CORE DUMP END =====================

Done!
Coredump SHA256='216b7a7a1a0af98a174f0491d5d606254fd54acc3c02d2228bc0a1586c5763b7'
I (392) esp_core_dump_uart: Core dump has been written to uart.
Rebooting...

@kannannair084
Copy link
Author

After a while running like this, it gets stuck

image

ppp_recv_config[0]
sent [LCP TermReq id=0x2 "User request"]
pppos_write[0]: len=20
I (46863) pppos_example: Power down
I (46863) pppos_example: Restart after 60 seconds
sent [LCP TermReq id=0x3 "User request"]
Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.

Core 0 register dump:
PC : 0x40132819 PS : 0x00060430 A0 : 0x80132bfe A1 : 0x3ffbb1d0
0x40132819: esp_modem_dte_transmit at c:\olf\development\firmware\ppos\pppos_client\build/../components/modem/src/esp_modem_netif.c:43

A2 : 0x3ffb6278 A3 : 0x3ffbfae0 A4 : 0x0000001d A5 : 0x3ffbad90
A6 : 0x00000020 A7 : 0x00000010 A8 : 0x00000000 A9 : 0x3ffbb1a0
A10 : 0x3ffb4fa0 A11 : 0x3ffae8f0 A12 : 0x00000000 A13 : 0x3ffbf500
A14 : 0x3ffbf4f0 A15 : 0x00000001 SAR : 0x00000010 EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000064 LBEG : 0x400014fd LEND : 0x4000150d LCOUNT : 0xfffffff5

Backtrace:0x40132816:0x3ffbb1d0 0x40132bfb:0x3ffbb1f0 0x400de225:0x3ffbb210 0x400f0570:0x3ffbb230 0x400f0759:0x3ffbb250 0x400efc1a:0x3ffbb280 0x400fadd7:0x3ffbb2a0 0x400fae2f:0x3ffbb2d0 0x400e71a5:0x3ffbb2f0 0x400deeda:0x3ffbb310 0x400def8c:0x3ffbb330 0x40085709:0x3ffbb360
0x40132816: esp_modem_dte_transmit at c:\olf\development\firmware\ppos\pppos_client\build/../components/modem/src/esp_modem_netif.c:41

0x40132bfb: esp_netif_transmit at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip.c:756

0x400de225: pppos_low_level_output at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_netif/lwip/esp_netif_lwip_ppp.c:233

0x400f0570: pppos_output_last at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:878

0x400f0759: pppos_write at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/pppos.c:244

0x400efc1a: ppp_write at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/ppp.c:993

0x400fadd7: fsm_sdata at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:796

0x400fae2f: fsm_timeout at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/netif/ppp/fsm.c:282

0x400e71a5: sys_check_timeouts at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/core/timeouts.c:400

0x400deeda: tcpip_timeouts_mbox_fetch at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:115

0x400def8c: tcpip_thread at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:148

0x40085709: vPortTaskWrapper at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

ELF file SHA256: da60e7829b14a192

Initiating core dump!
I (25590) esp_core_dump_uart: Press Enter to print core dump to UART...
I (25599) esp_core_dump_uart: Print core dump to uart...
I (25603) esp_core_dump_elf: Found tasks: 10
Core dump started (further output muted)
Received 21 kB...
Core dump finished!
Failed to run espcoredump script: Command '['C:\OLF\Development\Firmware\ESP-IDF\tools_4_2\.espressif\python_env\idf4.2_py3.8_env\Scripts\python.exe', 'C:\OLF\Development\Firmware\ESP-IDF\esp-idf_4_2\tools\..\components\espcoredump\espcoredump.py', 'info_corefile', '--core', 'C:\Users\SUMESH~1\AppData\Local\Temp\tmp9koor4iw', '--core-format', 'b64', 'c:\olf\development\firmware\ppos\pppos_client\build\pppos_client.elf']' returned non-zero exit status 1.

================= CORE DUMP START =================
2D0AAAEBAAAKAAAAaAEAAAAAAAA=
f0VMRgEBAQAAAAAAAAAAAAQAXgABAAAAAAAAADQAAAAAAAAAAAAAADQAIAAWACgA
AAAAAA==
BAAAAPQCAAAAAAAAAAAAAMAXAADAFwAABgAAAAAAAAA=
AQAAALQaAADss/s/7LP7P2gBAABoAQAABgAAAAAAAAA=
AQAAABwcAAAQsfs/ELH7P9QCAADUAgAABgAAAAAAAAA=
AQAAAPAeAACQg/s/kIP7P2gBAABoAQAABgAAAAAAAAA=
AQAAAFggAADggfs/4IH7P6gBAACoAQAABgAAAAAAAAA=
AQAAAAAiAAAgfPs/IHz7P2gBAABoAQAABgAAAAAAAAA=
AQAAAGgjAABwevs/cHr7P6gBAACoAQAABgAAAAAAAAA=
AQAAABAlAACwdPs/sHT7P2gBAABoAQAABgAAAAAAAAA=
AQAAAHgmAADAcfs/wHH7P+gCAADoAgAABgAAAAAAAAA=
AQAAAGApAAB48fs/ePH7P2gBAABoAQAABgAAAAAAAAA=
AQAAAMgqAACg7/s/oO/7P9ABAADQAQAABgAAAAAAAAA=
AQAAAJgsAAD8jfs//I37P2gBAABoAQAABgAAAAAAAAA=
AQAAAAAuAAAwjPs/MIz7P8QBAADEAQAABgAAAAAAAAA=
AQAAAMQvAACM+vo/jPr6P2gBAABoAQAABgAAAAAAAAA=
AQAAACwxAADA+Po/wPj6P8QBAADEAQAABgAAAAAAAAA=
AQAAAPAyAADwXfs/8F37P2gBAABoAQAABgAAAAAAAAA=
AQAAAFg0AABAXPs/QFz7P6gBAACoAQAABgAAAAAAAAA=
AQAAAAA2AADow/s/6MP7P2gBAABoAQAABgAAAAAAAAA=
AQAAAGg3AADgwfs/4MH7PwACAAAAAgAABgAAAAAAAAA=
AQAAAGg5AABI/vo/SP76P2gBAABoAQAABgAAAAAAAAA=
AQAAANA6AAAQV/s/EFf7P8ABAADAAQAABgAAAAAAAAA=
BAAAAJA8AAAAAAAAAAAAABQBAAAUAQAABgAAAAAAAAA=
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA7LP7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAGSgTQCAEBgD9FABADRUAQPX///8QAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAP4rE4DQsfs/
eGL7P+D6+z8dAAAAkK37PyAAAAAQAAAAAAAAAKCx+z+gT/s/8Oj6PwAAAAAA9fs/
8PT7PwEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAkIP7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAWjMTQCADBgAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAANpgDYCggvs/
AAAAAAEAAAABAAAAAQAAgAMAAAAjAAYALmANgHCC+z8AAAAASB0AQAAAAAAjBQYA
AQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAIHz7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAWjMTQCAMBgAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAANpgDYAwe/s/
AAAAAAEAAAABAAAAAQAAgLzF+z//////LmANgAB7+z8AAAAASB0AQCAABgAjAAYA
AQAAACgAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAsHT7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA8BsIQCAOBgD9FABADRUAQPz///8EAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHJyCICAcvs/
AAAAAI4pAAAsPEA/HwAAAAEAAAABAAAA8BsIgGBy+z/cAPA/AQAAALQQ+z8jDgYA
AQAAAAAAAP8AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAePH7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA8BsIQCAMBgD9FABADRUAQPz///8YAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAPyGCIBg8Ps/
AAAAAAoAAACMQfs/AAAAAAEAAAAOAAAA8BsIgEDw+z/cAPA/AQAAALQQ+z8jDAYA
AQAAAAAAAP8AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA/I37PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA8BsIQCAFBgAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAE56CIDwjPs/
AAAAAAAAAABMhfs/AAAAAAAAAAAjCgYA8BsIgNCM+z/cAPA/AQAAALQQ+z/QYfs/
VFQNQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAjPr6PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA8BsIQCAABgAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAPyGCICA+fo/
AAAAAAAAAACMQfs/1wEAAAgMQD8AAAAA8BsIgGD5+j/cAPA/AQAAALQQ+z8jAAYA
AQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA8F37PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA/IYIQCACBgAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAK8xCIAAXfs/
kFn7PwAAAADgWfs/AAAAAAEAAAABAAAA/IYIgOBc+z8BAAAABAAAAJBB+z8KAAAA
AACAABwA9D8AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA6MP7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA8BsIQCAABgDgwgBA9sIAQP////8EAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAPyGCICgwvs/
AAAAAAAAAACMQfs/AAAAAAAAAAA1AAAA8BsIgIDC+z/cAPA/AQAAALQQ+z8jAAYA
AQAAAPwA/D8AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
CAAAAEwCAAABAAAA
Q09SRQAAAAA=
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAASP76PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA8BsIQCAKBgAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAPyGCIDQV/s/
AAAAAAAAAACMQfs/8Dr+PwMAAAAjAQYA8BsIgLBX+z/cAPA/AQAAALQQ+z8jAAYA
AQAAACMBBgAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAA
wLH7P4Cz+z9EFAAACEH7PwhB+z/ss/s/AEH7PwcAAAD4kfs/+JH7P+yz+z8AAAAA
EgAAAKiS+z90aVQAY/dP4MDCwVqmqXYA////f+Sz+z8MAAAACQYwABIAAAAAAAAA
AAAAAAAAAACG75YDAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAp4zv
776t3hkoE0AwBAYA/isTgNCx+z94Yvs/4Pr7Px0AAACQrfs/IAAAABAAAAAAAAAA
oLH7P6BP+z/w6Po/AAAAAAD1+z/w9Ps/AQAAABAAAAAcAAAAZAAAAP0UAEANFQBA
9f///wAAAAAA9fs/XCUIQOwF+j8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAGCy+z/cAPA/AQAAALQQ+z8o4g2A8LH7P1xf+z/g+vs/
NBMOgACy+z8IhkA/ZNxAP3MFD4AQsvs/nMb7P+D6+z8dAAAAadxAP2ncQD8AAAAA
XAcPgDCy+z/8Yfs/AAAAAB0AAABcX/s/HAAAAB0AAAAd/A6AULL7P5zG+z/8Yfs/
yPr7PwAAAAAc4g1AnMb7P9qtD4CAsvs/nMb7P9T0+z+GhA+AgLL7P5zG+z/U9Ps/
1PT7P///AAAA9fs/yPr7PzKuD4Cgsvs/AAAAAOz0+z8MAAAAAPX7P3Vlc3QgcmVx
qHEOgNCy+z/kxvs/nMb7PwUAAAADAAAAUMFAPyDn+z/U9Ps/EAAAAMAAAACcxvs/
3e4NgPCy+z/crQ9AqMoAAAEAAAAAAAAAAQAAAAEAAACP7w2AELP7P6hE+z8ws/s/
5Mb7PyCC+z+oPvs/ZI/7PwxXCIAws/s/AAAAAAAAAAAjAAYAIwAGAAEAAAD5//0/
AAAAAGCz+z907w1AAAAAAAAAAAAAAAAAAAAAAAAAAAAjAAYACEH7P+yz+z8AAAAA
AAAAAICz+z8AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAACMs/s/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAA==
4IH7PyCD+z9XEf3ToD/7Pyh8+z+Qg/s/mD/7PxkAAAAd5HJOFnjiI5CD+z8AAAAA
AAAAAIx9+z9JRExFMQCYlW1CGq7+PzAAAQAAAIiD+z8HAAAA9D8g0AAAAAAAAAAA
AAAAAAAAAADiUNftAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAA3OwN
wCUIQFozE0AwAwYA2mANgKCC+z8AAAAAAQAAAAEAAAABAACAAwAAACMABgAuYA2A
cIL7PwAAAABIHQBAAAAAACMFBgABAAAAAAAAAAAAAAD//wAAAAAAAAAAAAAAAAAA
AAAAAMQnCEAjBQYA0FkIQIzV+T8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AQAAAAAAAAAAAAAAAAAAAAAAAADUYAhAAAAAAAAAAADgYAiAwIL7PwgAAAABAAAA
AQAAAAEAAIADAAAAIwAGAAxXCIDggvs/AAAAAAAAAAABAAAAIwAGAAEAAAAAAAAA
AAAAAACD+z/UYAhAAAAAACMABgCgP/s/IHz7PwAAAAAAAAAAIIP7PwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAACyD+z8AAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA==
cHr7P7B7+z8Tj39kmIP7P6A/+z8gfPs/mD/7PxkAAADBwrSTJ6L8iCB8+z8AAAAA
AAAAABx2+z9JRExFMADrnFkeEUcW+4oAAAAAABh8+z8GAAAAet7O8gAAAAAAAAAA
AAAAAAAAAABBHVXmAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAp2cP
wCUIQFozE0AwDAYA2mANgDB7+z8AAAAAAQAAAAEAAAABAACAvMX7P/////8uYA2A
AHv7PwAAAABIHQBAIAAGACMABgABAAAAKAAAAAAAAAD//wAAAAAAAAAAAAAAAAAA
AAAAAMQnCEAjAAYA0FkIQBzO+T8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAACAABgAjAAYAAQAAACgAAADgYAiAUHv7PwgAAAAAAAAA
AQAAAAEAAIC8xfs//////wxXCIBwe/s/AAAAAAAAAAABAAAAIwAGAAEAAAAjDQYA
AAAAAJB7+z/UYAhAAAAAACMABgCgP/s/kIP7PwAAAAAAAAAAsHv7PwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAALx7+z8AAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA==
wHH7P0B0+z+OKQAAjD/7P4Dx+z+wdPs/hD/7PxgAAABE6fs/ROn7P7B0+z8AAAAA
AQAAAKxk+z9tYWluABgryNp6dW7sR0sAAAAAAKh0+z8FAAAAknhhugEAAAAAAAAA
5GH7P7A7DUBr/pAAAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAFWIB
wCUIQPAbCEAwDgYAcnIIgIBy+z8AAAAAjikAACw8QD8fAAAAAQAAAAEAAADwGwiA
YHL7P9wA8D8BAAAAtBD7PyMOBgABAAAAAAAA/wQAAAD//wAAAAAAAP0UAEANFQBA
/P///8QnCEAjDgYA0FkIQKzG+T8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAIlTDYDAcvs/uPP7P1xf+z9Bbw2AoHL7P44pAACsJfs/
iVMNgMBy+z+48/s/D7cAAIlTDYDAcvs/uPP7P1xf+z8sPEA/D7cAAEgyQD+8xfs/
DFcIgPBz+z8AAAAAAAAAAGMAAAClpaWlpaWlpaWlpaVQc0A/AAAAAEB+QD8BAAAA
AwAAAAEAAAAAAAAAAAAAAADCAQAhAAAAGQAAAA4AAAAaAAAAAAQAAAACAAAUAAAA
HgAAAAAIAAAFAAAAAAIAAGxnDUAAAAAAAAAAAKw7QD8AAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAARgAAAAAAAAARDwAAYwAAAA4AAAAAAAAA
DH8NQHhi+z8AAAAABPP7PwAAAAAgdPs/DFMNQAAAAAAAAAAAAID0PwAAAAAAAAAA
IwAGALQ/+z+wdPs/AAAAAAAAAABAdPs/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAATHT7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
oO/7PxDx+z9JFAAAuHT7P4w/+z948fs/hD/7PxQAAABM3fs/TN37P3jx+z9E3fs/
BQAAAHTp+z91YXJ0X2V2ZW50AKqN+M4A////f3Dx+z8OAAAAbTrqoQUAAAAAAAAA
vPT7P7A7DUAWrQYEAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAA1wrI
wCUIQPAbCEAwDAYA/IYIgGDw+z8AAAAACgAAAIxB+z8AAAAAAQAAAA4AAADwGwiA
QPD7P9wA8D8BAAAAtBD7PyMMBgABAAAAAAAA/xgAAAD//wAAAAAAAP0UAEANFQBA
/P///8QnCEAjDAYA0FkIQHxD+j8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAA6FAAA9Nz7PwUAAAD9cA2AgPD7PyDd+z/A8Ps/
sOf7PwAAAAABAAAADgAAAAxXCIDA8Ps/YGL7PwAAAAAAAAAAPxQAAAAAAAAAAAAA
CgAAAAAAAAA6FAAAAAAAAHDd+z8AAAAAAQAAAAMAAAAAAAAA8PD7P+xwDUBgYvs/
BwAAAAMAAAABAAAAAAAAACMABgAEQPs/ePH7PwAAAAAAAAAAEPH7PwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABzx+z8AAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=
MIz7P5CN+z8AAAAAeD/7P3g/+z/8jfs/cD/7PxgAAAAohfs/KIX7P/yN+z8ghfs/
AQAAAPiF+z9UbXIgU3ZjAPhN4KRVzZYAAAAAAPSN+z8IAAAAqn+CBgEAAAAAAAAA
AAAAAAAAAABhHAAAAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAA1pcD
wCUIQPAbCEAwBQYATnoIgPCM+z8AAAAAAAAAAEyF+z8AAAAAAAAAACMKBgDwGwiA
0Iz7P9wA8D8BAAAAtBD7P9Bh+z9UVA1AAAAAAAAAAAD//wAAAAAAAAAAAAAAAAAA
AAAAAMQnCEDQYfs/0FkIQPzf+T8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAEVwhAMAAFAAAAAAA7ewiAEI37P5hB+z8AAAAA
AAAAACx7CEAAAAAAAAAAAAxXCIBAjfs/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AQAAACMABgABAAAAIwAGAAAAAABwjfs/LHsIQAAAAAABAAAAAAAAAAAAAAAAAAAA
IwAGALQ/+z+wdPs/AAAAAAAAAACQjfs/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAnI37PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAA=
wPj6PyD6+j8ysqnr+F37P1D++j+M+vo/FD/7PwMAAABY6vo/WOr6P4z6+j9Q6vo/
FgAAAIjq+j9lc3BfdGltZXIA5sKKtnkAAAAAAIT6+j8BAAAASflRixYAAAAAAAAA
AAAAAAAAAAAUFgAAAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAA5sg8
wCUIQPAbCEAwAAYA/IYIgID5+j8AAAAAAAAAAIxB+z/XAQAACAxAPwAAAADwGwiA
YPn6P9wA8D8BAAAAtBD7PyMABgABAAAAAAAAAAAAAAD//wAAAAAAAAAAAAAAAAAA
AAAAAMQnCEAjAAYA0FkIQIxM+T8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAMAlCEAEVwhAMAAFAAAAAABjYg2AoPn6Pyzq+j8AAAAA
AAAAAFBiDUAAAAAAAAAAAAxXCIDg+fo/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
/////wAAAAAAAAAAAAAAAHzq+j8AAAAAAQAAACMKBgAAAAAAAPr6P1BiDUAAAAAA
IwAGAFhB+z+M+vo/AAAAAAAAAAAg+vo/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAALPr6PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAA=
QFz7P4Bd+z+mzUUL8MP7P5T6+j/wXfs/FD/7PwEAAAC8Wfs/vFn7P/Bd+z+0Wfs/
GAAAAOxZ+z9pcGMxAH/k0SS48nH9wVYAAQAAAOhd+z8DAAAACiMxaxgAAAAAAAAA
AAAAAAAAAACbLE4CAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAALsth
wCUIQPyGCEAwAgYArzEIgABd+z+QWfs/AAAAAOBZ+z8AAAAAAQAAAAEAAAD8hgiA
4Fz7PwEAAAAEAAAAkEH7PwoAAAAAAIAAHAD0PwAAAAD//wAAAAAAAAAAAAAAAAAA
AAAAAMQnCEAKAAAA0FkIQOyv+T8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAB8MQhAAQAAAAAAAAAMVwiAQF37PwEAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAP////8AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAGBd+z98MQhAAQAAACAHBgCAQfs/8F37PwAAAAAAAAAAgF37PwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAHoZCICAff4/KgAAACoAAAAAAAAAAAAAAIxd+z8AAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA==
4MH7P4DD+z8zRLtPHD/7P/hd+z/ow/s/FD/7PwUAAABYtvs/WLb7P+jD+z9Qtvs/
FAAAAOS4+z9zeXNfZXZ0ACC10LvP6KUAAAAAAODD+z8NAAAAufXRoRQAAAAAAAAA
AAAAAAAAAAALKHQAAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAPBRD
wCUIQPAbCEAwAAYA/IYIgKDC+z8AAAAAAAAAAIxB+z8AAAAAAAAAADUAAADwGwiA
gML7P9wA8D8BAAAAtBD7PyMABgABAAAA/AD8PwQAAAD//wAAAAAAAODCAED2wgBA
/////8QnCEAjAAYA0FkIQOwV+j8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAKWlpaWlpaWlpaWlpaWlpaVsVhOAwML7Pyy2+z8Aw/s/
paWlpaWlpaWlpaWlpaWlpYRWE4AAw/s/ELb7P/////8AAAAACQ8AABC2+z//////
/////whzQD8FAAAA5AD8P3y2+z8AAAAAAQAAAOQA/D8MVwiAQMP7PxC2+z8AAAAA
AAAAAAAAAAAAAAAAAAAAAP////8AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAIc0A/
AAAAAGDD+z94VhNAELb7PyMABgAwQfs/6MP7PwAAAAAAAAAAgMP7PwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAIzD+z8AAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=
EFf7P3BY+z8Uofq/lPr6Pxw/+z9I/vo/FD/7PwEAAAAY/vo/GP76P0j++j8Q/vo/
GAAAANRU+z9pcGMwAGPZz3qGVxtJdtsAAAAAANBY+z8CAAAAKvDOjBgAAAAAAAAA
AAAAAAAAAADkB40EAAAAAIjo+j/w6Po/WOn6PwAAAAAAAAAAAQAAAAAAAAAAAAAA
AAAAAEgdAEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAEpc7
wCUIQPAbCEAwCgYA/IYIgNBX+z8AAAAAAAAAAIxB+z/wOv4/AwAAACMBBgDwGwiA
sFf7P9wA8D8BAAAAtBD7PyMABgABAAAAIwEGAAAAAAD//wAAAAAAAAAAAAAAAAAA
AAAAAMQnCEAjAAYA0FkIQNyq+T8AAAAAAAAAAAAAAAD//z+zAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAMAlCEAEVwhAMAAFAAAAAACvMQiA8Ff7P+z9+j8AAAAA
AAAAAHwxCEAAAAAAAAAAAAxXCIAwWPs/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
/////wAAAAAAAAAAAAAAADz++j8AAAAAAQAAAAIAAAAAAAAAUFj7P3wxCEAAAAAA
Iw8GAIBB+z9I/vo/AQAAAAAAAABwWPs/AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
6RgIgLA7/j/8Pvs/CAxAPwAAAAAAAAAAfFj7PwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAA==
FAAAAEgAAABKIAAA
RVNQX0NPUkVfRFVNUF9JTkZPAAA=
AQEAAGRhNjBlNzgyOWIxNGExOTIAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
DAAAAJQAAAClAgAA
RVhUUkFfSU5GTwAA
7LP7P+gAAAAcAAAA7gAAAGQAAADCAAAAAAAAAMMAAAAAAAAAxAAAAAAAAADFAAAA
AAAAAMYAAAAAAAAAsQAAAI8nE0CyAAAAAAAAALMAAAAAAAAAtAAAAAAAAAC1AAAA
AAAAALYAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAA==
ZxV5HJMH/KvJm1QJHKlp2NLqf6YV8jY24veSpWLggSg=
================= CORE DUMP END =================
Coredump SHA256='6715791c9307fcabc99b54091ca969d8d2ea7fa615f23636e2f792a562e08128'
I (685) esp_core_dump_uart: Core dump has been written to uart.
Rebooting...
ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:4
load:0x3fff0034,len:7260
load:0x40078000,len:13732
load:0x40080400,len:3988
0x40080400: _init at ??:?

entry 0x40080688
I (29) boot: ESP-IDF v4.2-beta1-227-gf0e87c933 2nd stage bootloader
I (29) boot: compile time 11:09:36
I (29) boot: chip revision: 1
I (33) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (41) boot.esp32: SPI Speed : 40MHz
I (45) boot.esp32: SPI Mode : DIO
I (50) boot.esp32: SPI Flash Size : 16MB
I (54) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (63) boot: ## Label Usage Type ST Offset Length
I (71) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (78) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (86) boot: 2 factory factory app 00 00 00010000 00100000
I (93) boot: End of partition table
I (97) boot_comm: chip revision: 1, min. application chip revision: 0
I (104) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x1ad84 (109956) map
I (155) esp_image: segment 1: paddr=0x0002adac vaddr=0x3ffb0000 size=0x035dc ( 13788) load
I (161) esp_image: segment 2: paddr=0x0002e390 vaddr=0x40080000 size=0x00404 ( 1028) load
0x40080000: _WindowOverflow4 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/xtensa_vectors.S:1730

I (162) esp_image: segment 3: paddr=0x0002e79c vaddr=0x40080404 size=0x0187c ( 6268) load
I (174) esp_image: segment 4: paddr=0x00030020 vaddr=0x400d0020 size=0x6601c (417820) map
0x400d0020: _stext at ??:?

I (339) esp_image: segment 5: paddr=0x00096044 vaddr=0x40081c80 size=0x09d4c ( 40268) load
0x40081c80: esp_dport_access_stall_other_cpu_start at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/dport_access.c:99 (discriminator 1)

I (364) boot: Loaded app from partition at offset 0x10000
I (364) boot: Disabling RNG early entropy source...
I (364) cpu_start: Pro cpu up.
I (368) cpu_start: Application information:
I (373) cpu_start: Project name: pppos_client
I (378) cpu_start: App version: 1
I (382) cpu_start: Compile time: Oct 22 2020 15:36:19
I (389) cpu_start: ELF file SHA256: da60e7829b14a192...
I (395) cpu_start: ESP-IDF: v4.2-beta1-227-gf0e87c933
I (401) cpu_start: Starting app cpu, entry point is 0x4008192c
0x4008192c: call_start_cpu1 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/cpu_start.c:287

I (393) cpu_start: App cpu up.
I (412) heap_init: Initializing. RAM available for dynamic allocation:
I (419) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (425) heap_init: At 3FFB54B8 len 0002AB48 (170 KiB): DRAM
I (431) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (437) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (444) heap_init: At 4008B9CC len 00014634 (81 KiB): IRAM
I (450) cpu_start: Pro cpu start user code
I (468) spi_flash: detected chip: gd
I (469) spi_flash: flash io: dio
I (469) esp_core_dump_uart: Init core dump to UART
I (471) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (483) gpio: GPIO[12]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (493) gpio: GPIO[18]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
Success with Setting GPIO
Set power button to low
ppp phase changed[0]: phase=0
I (1203) uart: queue free spaces: 30
turning on
Peripheral manager done init..
I (5313) pppos_example: Delay 30 Seconds for Modem Readiness
E (10653) esp-modem: esp_dte_handle_line(103): DTE has not yet bind with DCE
E (10703) esp-modem: esp_dte_handle_line(103): DTE has not yet bind with DCE
E (11353) esp-modem: esp_dte_handle_line(103): DTE has not yet bind with DCE
E (11403) esp-modem: esp_dte_handle_line(103): DTE has not yet bind with DCE
I (36613) pppos_example: Delay completed
E (37503) esp-modem: esp_dte_handle_line(110): handle line failed
W (37503) pppos_example: Unknow line received: +COPS: 0

I (37803) pppos_example: Module: BG96
I (37803) pppos_example: Operator:
I (37803) pppos_example: IMEI: 862785041881510
I (37803) pppos_example: IMSI: 295050911339686
I (38003) pppos_example: rssi: 99, ber: 99
I (38203) pppos_example: Battery voltage: 3856 mV
I (38403) pppos_example: Modem PPP Started
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=1
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x7316535e> ]
pppos_write[0]: len=24
ppp_start[0]: finished
I (38483) esp-modem: 0x3ffbd924 7e ff 7d 23 c0 21 7d 21 7d 20 7d 20 7d 39 7d 22 |.}#.!}!} } }9}"|
I (38483) esp-modem: 0x3ffbd934 7d 26 7d 20 7d 20 7d 20 7d 20 7d 23 7d 25 c2 23 |}&} } } } }#}%.#|
I (38493) esp-modem: 0x3ffbd944 7d 25 7d 25 7d 26 d0 84 64 94 7d 27 7d 22 7d 28 |}%}%}&..d.}'}"}(|
I (38503) esp-modem: 0x3ffbd954 7d 22 d2 96 7e 7e ff 7d 23 c0 21 7d 22 7d 21 7d |}"..~~.}#.!}"}!}|
I (38513) esp-modem: 0x3ffbd964 20 7d 34 7d 22 7d 26 7d 20 7d 20 7d 20 7d 20 7d | }4}"}&} } } } }|
I (38523) esp-modem: 0x3ffbd974 25 7d 26 73 7d 36 53 5e 7d 27 7d 22 7d 28 7d 22 |%}&s}6S^}'}"}(}"|
I (38533) esp-modem: 0x3ffbd984 af cf 7e |..
|
pppos_input[0]: got 99 bytes
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth 0xc223 05> <magic 0xd0846494> ]
sent [LCP ConfNak id=0x0 ]
pppos_write[0]: len=12
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x7316535e> ]
I (38593) esp-modem: 0x3ffbd924 7e ff 7d 23 c0 21 7d 21 7d 21 7d 20 7d 38 7d 22 |.}#.!}!}!} }8}"|
I (38593) esp-modem: 0x3ffbd934 7d 26 7d 20 7d 20 7d 20 7d 20 7d 23 7d 24 c0 23 |}&} } } } }#}$.#|
I (38593) esp-modem: 0x3ffbd944 7d 25 7d 26 d0 84 64 94 7d 27 7d 22 7d 28 7d 22 |}%}&..d.}'}"}(}"|
I (38603) esp-modem: 0x3ffbd954 c0 a3 7e |..
|
pppos_input[0]: got 51 bytes
rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd0846494> ]
sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xd0846494> ]
pppos_write[0]: len=28
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=7
sent [PAP AuthReq id=0x1 user="sora" password="sora"]
pppos_write[0]: len=18
I (38673) esp-modem: 0x3ffbd924 7e ff 7d 23 c0 21 7d 2b 7d 22 7d 20 7d 28 d0 84 |.}#.!}+}"} }(..|
I (38673) esp-modem: 0x3ffbd934 64 94 7d 22 7d 35 7e 7e c0 23 02 01 00 05 00 fd |d.}"}5~~.#......|
I (38683) esp-modem: 0x3ffbd944 30 7e |0
|
pppos_input[0]: got 34 bytes
rcvd [LCP DiscReq id=0x2 magic=0xd0846494]
rcvd [PAP AuthAck id=0x1 ""]
PAP authentication succeeded
ppp phase changed[0]: phase=9
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
I (38743) esp-modem: 0x3ffbd924 0d 0a 4e 4f 20 43 41 52 52 49 45 52 0d 0a |..NO CARRIER..|
pppos_input[0]: got 14 bytes
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
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
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
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
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
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
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
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
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
IPCP: timeout sending Config-Requests
ppp phase changed[0]: phase=11
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=0 0 0 0
ppp_recv_config[0]
sent [LCP TermReq id=0x2 "No network protocols running"]
pppos_write[0]: len=36
sent [LCP TermReq id=0x3 "No network protocols running"]
pppos_write[0]: len=36
ppp phase changed[0]: phase=12
Connection terminated.
ppp_link_terminated[0]
ppp_link_end[0]
ppp phase changed[0]: phase=0
I (110723) esp-netif_lwip-ppp: Connection lost
I (110723) pppos_example: Modem Disconnect from PPP Server
ppp_link_terminated[0]: finished.

@kannannair084
Copy link
Author

image

image

I am seeing that there is a power down message gets sent, and it is crashing after that?

image

Also, could this crash be triggered by POWER DOWN output from BG96?

@kannannair084
Copy link
Author

@kannannair084
Copy link
Author

@kannannair084
Copy link
Author

pppos_client_main.txt

Please check if making any out of sequence calls or missing something

@kannannair084
Copy link
Author

kannannair084 commented Oct 23, 2020

I made the following change and it started working , basically added a 10 sec delay before powering down and after stop.

  /* Exit PPP mode */
        ESP_ERROR_CHECK(esp_modem_stop_ppp(dte));
		xEventGroupWaitBits(event_group, STOP_BIT, pdTRUE, pdTRUE, portMAX_DELAY);
		ESP_LOGI(TAG, "10 sec delay start");		
		 vTaskDelay(pdMS_TO_TICKS(10000));
		 ESP_LOGI(TAG, "10 sec delay end");	
   /* Power down module */
    ESP_ERROR_CHECK(dce->power_down(dce));
    ESP_LOGI(TAG, "Power down");
    ESP_ERROR_CHECK(dce->deinit(dce));	
    ESP_LOGI(TAG, "Restart after 60 seconds");
    vTaskDelay(pdMS_TO_TICKS(60000));		

@david-cermak
Copy link
Collaborator

Also, could this crash be triggered by POWER DOWN output from BG96?

Not really, from the coredump it looks more like the ppp mode in lwip is still active and trying to send data to dce, which as been already destroyed in line

ESP_ERROR_CHECK(dce->deinit(dce))

it looks like the +++ command workaround did work, but need to wait until netif really stops.

I made the following change and it started working , basically added a 10 sec delay before powering down and after stop.

Yes, it makes sense, needed to wait for the lwip PPP netif to stop


Okay, thanks very much for testing this, now I understand the problem so that it could be properly fixed.

@kannannair084
Copy link
Author

however, after a couple of runs, i ran into this.
I (153653) pppos_example: Module: BG96
I (153653) pppos_example: Operator:
I (153653) pppos_example: IMEI: 862785041881510
I (153653) pppos_example: IMSI: 295050911339686
I (154103) pppos_example: rssi: 99, ber: 99
I (154453) pppos_example: Battery voltage: 3855 mV
I (154803) pppos_example: Modem PPP Started
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=1
sent [LCP ConfReq id=0x4 <asyncmap 0x0> <magic 0xd0131f3a> ]
pppos_write[0]: len=24
ppp_start[0]: finished
I (154883) esp-modem: 0x3ffbd924 7e ff 7d 23 c0 21 7d 21 7d 20 7d 20 7d 39 7d 22 |.}#.!}!} } }9}"|
I (154883) esp-modem: 0x3ffbd934 7d 26 7d 20 7d 20 7d 20 7d 20 7d 23 7d 25 c2 23 |}&} } } } }#}%.#|
I (154893) esp-modem: 0x3ffbd944 7d 25 7d 25 7d 26 d0 84 69 7d 2a 7d 27 7d 22 7d |}%}%}&..i}*}'}"}|
I (154903) esp-modem: 0x3ffbd954 28 7d 22 a0 fc 7e 7e ff 7d 23 c0 21 7d 22 7d 24 |(}"..~~.}#.!}"}$|
I (154913) esp-modem: 0x3ffbd964 7d 20 7d 34 7d 22 7d 26 7d 20 7d 20 7d 20 7d 20 |} }4}"}&} } } } |
I (154923) esp-modem: 0x3ffbd974 7d 25 7d 26 d0 7d 33 7d 3f 3a 7d 27 7d 22 7d 28 |}%}&.}3}?:}'}"}(|
I (154933) esp-modem: 0x3ffbd984 7d 22 7d 27 b9 7e |}"}'.
|
pppos_input[0]: got 102 bytes
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth 0xc223 05> <magic 0xd084690a> ]
sent [LCP ConfNak id=0x0 ]
pppos_write[0]: len=12
rcvd [LCP ConfAck id=0x4 <asyncmap 0x0> <magic 0xd0131f3a> ]
I (154993) esp-modem: 0x3ffbd924 7e ff 7d 23 c0 21 7d 21 7d 21 7d 20 7d 38 7d 22 |.}#.!}!}!} }8}"|
I (154993) esp-modem: 0x3ffbd934 7d 26 7d 20 7d 20 7d 20 7d 20 7d 23 7d 24 c0 23 |}&} } } } }#}$.#|
I (155003) esp-modem: 0x3ffbd944 7d 25 7d 26 d0 84 69 7d 2a 7d 27 7d 22 7d 28 7d |}%}&..i}*}'}"}(}|
I (155003) esp-modem: 0x3ffbd954 22 b2 c9 7e |"..
|
pppos_input[0]: got 52 bytes
rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd084690a> ]
sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xd084690a> ]
pppos_write[0]: len=28
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=7
sent [PAP AuthReq id=0x2 user="sora" password="sora"]
pppos_write[0]: len=18
I (155073) esp-modem: 0x3ffbd924 7e ff 7d 23 c0 21 7d 2b 7d 22 7d 20 7d 28 d0 84 |.}#.!}+}"} }(..|
I (155073) esp-modem: 0x3ffbd934 69 7d 2a 8d d8 7e 7e c0 23 02 02 00 05 00 30 15 |i}*..~~.#.....0.|
I (155083) esp-modem: 0x3ffbd944 7e |
|
pppos_input[0]: got 33 bytes
rcvd [LCP DiscReq id=0x2 magic=0xd084690a]
rcvd [PAP AuthAck id=0x2 ""]
PAP authentication succeeded
ppp phase changed[0]: phase=9
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
I (155143) esp-modem: 0x3ffbd924 0d 0a 4e 4f 20 43 41 52 52 49 45 52 0d 0a |..NO CARRIER..|
pppos_input[0]: got 14 bytes
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
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
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
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
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
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
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
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
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
IPCP: timeout sending Config-Requests
ppp phase changed[0]: phase=11
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=0 0 0 0
ppp_recv_config[0]
sent [LCP TermReq id=0x5 "No network protocols running"]
pppos_write[0]: len=36
sent [LCP TermReq id=0x6 "No network protocols running"]
pppos_write[0]: len=36
ppp phase changed[0]: phase=12
Connection terminated.
ppp_link_terminated[0]
ppp_link_end[0]
ppp phase changed[0]: phase=0
I (227123) esp-netif_lwip-ppp: User interrupt
ppp_link_terminated[0]: finished.

@kannannair084
Copy link
Author

it is waiting for the started bit , i think here

xEventGroupWaitBits(event_group, GOT_DATA_BIT, pdTRUE, pdTRUE, portMAX_DELAY);

how to avoid this from happening, as my code gets stuck there.

@david-cermak
Copy link
Collaborator

I (155143) esp-modem: 0x3ffbd924 0d 0a 4e 4f 20 43 41 52 52 49 45 52 0d 0a |..NO CARRIER..|

Seem like a connection problem with your modem here -- no connection, so way to get an IP address.

@kannannair084
Copy link
Author

I (41773) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=48260
pppos_netif_output[0]: proto=0x21, len = 71
I (41783) pppos_example: sent publish successful, msg_id=0
I (42373) esp-modem: 0x3ffbd92c 7e 21 45 00 00 47 3a 38 40 00 23 06 14 5c 89 87 |!E..G:8@.#....|
I (42373) esp-modem: 0x3ffbd93c 53 d9 0a aa 21 13 07 5b d0 29 82 06 f3 07 00 00 |S...!..[.)......|
I (42373) esp-modem: 0x3ffbd94c 19 be 50 18 fa a0 01 4b 00 00 30 1d 00 10 2f 74 |..P....K..0.../t|
I (42383) esp-modem: 0x3ffbd95c 6f 70 69 63 2f 65 73 70 2d 70 70 70 6f 73 65 73 |opic/esp-ppposes|
I (42393) esp-modem: 0x3ffbd96c 70 33 32 2d 70 70 70 6f 73 bb d5 7e |p32-pppos..
|
pppos_input[0]: got 76 bytes
ppp_input[0]: ip in pbuf len=71
I (42413) pppos_example: MQTT_EVENT_DATA
TOPIC=/topic/esp-pppos
DATA=esp32-pppos
pppos_netif_output[0]: proto=0x21, len = 42
I (43013) esp-modem: 0x3ffbd92c 7e 21 45 00 00 28 3a 39 40 00 23 06 14 7a 89 87 |!E..(:9@.#..z..|
I (43013) esp-modem: 0x3ffbd93c 53 d9 0a aa 21 13 07 5b d0 29 82 06 f3 26 00 00 |S...!..[.)...&..|
I (43013) esp-modem: 0x3ffbd94c 19 c0 50 11 fa 9e 45 a5 00 00 d6 4e 7e |..P...E....N
|

ERROR A stack overflow in task uart_event has been detected.

Backtrace:0x40085013:0x3ffbedb0 0x40085701:0x3ffbedd0 0x400859a9:0x3ffbedf0 0x4008671d:0x3ffbee70 0x40085a9c:0x3ffbee90 0x40085a52:0x00000001 |<-CORRUPTED
0x40085013: panic_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:330

0x40085701: esp_system_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/system_api.c:106

0x400859a9: vApplicationStackOverflowHook at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:436

0x4008671d: vTaskSwitchContext at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:2771

0x40085a9c: _frxt_dispatch at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/portasm.S:431

0x40085a52: _frxt_int_exit at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/portasm.S:231

ELF file SHA256: f3b33259a1a38b48

Initiating core dump!
I (16205) esp_core_dump_uart: Press Enter to print core dump to UART...
I (16215) esp_core_dump_uart: Print core dump to uart...
I (16219) esp_core_dump_elf: Found tasks: 11
Core dump started (further output muted)
Received 24 kB...
Core dump finished!
Failed to run espcoredump script: Command '['C:\OLF\Development\Firmware\ESP-IDF\tools_4_2\.espressif\python_env\idf4.2_py3.8_env\Scripts\python.exe', 'C:\OLF\Development\Firmware\ESP-IDF\esp-idf_4_2\tools\..\components\espcoredump\espcoredump.py', 'info_corefile', '--core', 'C:\Users\SUMESH~1\AppData\Local\Temp\tmprycxpjdd', '--core-format', 'b64', 'c:\olf\development\firmware\ppos\pppos_client\build\pppos_client.elf']' returned non-zero exit status 1.

@kannannair084
Copy link
Author

@david-cermak could you take a look at the logs, i am just running it in a loop to see how reliable this is and i am still getting crashes. seems like miles away from destination and have a tight schedule to meet.

crashing.txt

@kannannair084
Copy link
Author

It is crashing every 5th or 6th iteration...

I (739323) pppos_example: GOT ip event!!!
I (739333) pppos_example: MQTT other event id: 7
pppos_netif_output[0]: proto=0x21, len = 44
I (740483) esp-modem: 0x3ffbd934 7e 21 45 00 00 2c 00 00 40 00 14 06 5d af 89 87 |!E..,..@...]...|
I (740483) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b fa 68 2f e8 ff b5 00 00 |S...!..[.h/.....|
I (740493) esp-modem: 0x3ffbd954 1a 93 60 12 fa f0 48 8d 00 00 02 04 05 3a 89 21 |..`...H......:.!|
I (740503) esp-modem: 0x3ffbd964 7e |
|
pppos_input[0]: got 49 bytes
ppp_input[0]: ip in pbuf len=44
pppos_netif_output[0]: proto=0x21, len = 40
pppos_netif_output[0]: proto=0x21, len = 66
I (741113) esp-modem: 0x3ffbd934 7e 21 45 00 00 28 58 9c 40 00 14 06 05 17 89 87 |!E..(X.@.......|
I (741113) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b fa 68 2f e8 ff b6 00 00 |S...!..[.h/.....|
I (741123) esp-modem: 0x3ffbd954 1a ad 50 10 fa d6 5f d0 00 00 21 7b 7e 7e 21 45 |..P..._...!{~~!E|
I (741133) esp-modem: 0x3ffbd964 00 00 2c 58 9d 40 00 14 06 05 12 89 87 53 d9 0a |..,[email protected]..|
I (741143) esp-modem: 0x3ffbd974 aa 21 13 07 5b fa 68 2f e8 ff b6 00 00 1a ad 50 |.!..[.h/.......P|
I (741153) esp-modem: 0x3ffbd984 18 fa d6 3f c2 00 00 20 02 00 00 14 79 7e |...?... ....y
|
pppos_input[0]: got 94 bytes
ppp_input[0]: ip in pbuf len=40
ppp_input[0]: ip in pbuf len=44
I (741173) pppos_example: MQTT_EVENT_CONNECTED
pppos_netif_output[0]: proto=0x21, len = 63
I (741173) pppos_example: sent subscribe successful, msg_id=29658
I (741763) esp-modem: 0x3ffbd934 7e 21 45 00 00 2d 58 9e 40 00 14 06 05 10 89 87 |!E..-X.@.......|
I (741763) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b fa 68 2f e8 ff ba 00 00 |S...!..[.h/.....|
I (741763) esp-modem: 0x3ffbd954 1a c4 50 18 fa bf 5b e1 00 00 90 03 73 da 00 d2 |..P...[.....s...|
I (741773) esp-modem: 0x3ffbd964 e3 7e |.
|
pppos_input[0]: got 50 bytes
ppp_input[0]: ip in pbuf len=45
I (741793) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=29658
pppos_netif_output[0]: proto=0x21, len = 71
I (741803) pppos_example: sent publish successful, msg_id=0
I (742393) esp-modem: 0x3ffbd934 7e 21 45 00 00 47 58 9f 40 00 14 06 04 f5 89 87 |!E..GX.@.......|
I (742393) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b fa 68 2f e8 ff bf 00 00 |S...!..[.h/.....|
I (742403) esp-modem: 0x3ffbd954 1a e3 50 18 fa a0 1b 4d 00 00 30 1d 00 10 2f 74 |..P....M..0.../t|
I (742413) esp-modem: 0x3ffbd964 6f 70 69 63 2f 65 73 70 2d 70 70 70 6f 73 65 73 |opic/esp-ppposes|
I (742423) esp-modem: 0x3ffbd974 70 33 32 2d 70 70 70 6f 73 90 13 7e |p32-pppos..
|

ERROR A stack overflow in task uart_event has been detected.

Backtrace:0x40085013:0x3ffbedc0 0x40085701:0x3ffbede0 0x400859a9:0x3ffbee00 0x4008671d:0x3ffbee80 0x40085a9c:0x3ffbeea0 0x40085a52:0x00000001 |<-CORRUPTED
0x40085013: panic_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:330

0x40085701: esp_system_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/system_api.c:106

0x400859a9: vApplicationStackOverflowHook at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:436

0x4008671d: vTaskSwitchContext at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:2771

0x40085a9c: _frxt_dispatch at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/portasm.S:431

0x40085a52: _frxt_int_exit at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/portasm.S:231

ELF file SHA256: dd787fca6e349398

@kannannair084
Copy link
Author

6th_round_crashing.txt

@kannannair084
Copy link
Author

@kannannair084
Copy link
Author

I (130893156) pppos_example: GOT ip event!!!
I (130894156) pppos_example: MQTT other event id: 7
pppos_netif_output[0]: proto=0x21, len = 44
pppos_netif_output[0]: proto=0x21, len = 44
I (130898406) esp-modem: 0x3ffbd934 7e 21 45 00 00 2c 00 00 40 00 11 06 60 af 89 87 |!E..,..@......| I (130898406) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b e3 52 93 b5 4a 99 00 3a |S...!..[.R..J..:| I (130898416) esp-modem: 0x3ffbd954 ef 1a 60 12 fa f0 dc 30 00 00 02 04 05 3a 50 e0 |......0.....:P.|
I (130898426) esp-modem: 0x3ffbd964 7e |
|
pppos_input[0]: got 49 bytes
ppp_input[0]: ip in pbuf len=44
pppos_netif_output[0]: proto=0x21, len = 40
pppos_netif_output[0]: proto=0x21, len = 66
I (130898486) esp-modem: 0x3ffbd934 7e 21 45 00 00 2c 00 00 40 00 11 06 60 af 89 87 |!E..,..@......| I (130898486) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b e3 52 93 b5 4a 99 00 3a |S...!..[.R..J..:| I (130898496) esp-modem: 0x3ffbd954 ef 1a 60 12 fa f0 dc 30 00 00 02 04 05 3a 50 e0 |......0.....:P.|
I (130898506) esp-modem: 0x3ffbd964 7e |
|
pppos_input[0]: got 49 bytes
ppp_input[0]: ip in pbuf len=44
pppos_netif_output[0]: proto=0x21, len = 40
pppos_netif_output[0]: proto=0x21, len = 66
I (130902746) esp-modem: 0x3ffbd934 7e 21 45 00 00 28 29 d5 |!E..().|
pppos_input[0]: got 8 bytes
I (130902796) esp-modem: 0x3ffbd934 40 00 11 06 36 de 89 87 53 d9 0a aa 21 13 07 5b |@...6...S...!..[|
I (130902796) esp-modem: 0x3ffbd944 e3 52 93 b5 4a 9a 00 3a ef 34 50 10 fa d6 f3 73 |.R..J..:.4P....s|
I (130902806) esp-modem: 0x3ffbd954 00 00 e1 63 7e |...c
|
pppos_input[0]: got 37 bytes
ppp_input[0]: ip in pbuf len=40
I (130902966) esp-modem: 0x3ffbd934 7e 21 45 00 00 2c 29 d6 40 00 11 06 36 d9 89 87 |!E..,)[email protected]...|
I (130902966) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b e3 52 93 b5 4a 9a 00 3a |S...!..[.R..J..:|
I (130902976) esp-modem: 0x3ffbd954 ef 34 50 18 fa d6 d3 65 00 00 20 02 00 00 07 1e |.4P....e.. .....|
I (130902986) esp-modem: 0x3ffbd964 7e 7e 21 45 00 00 28 29 d8 40 00 11 06 36 db 89 |!E..()[email protected]..|
I (130902996) esp-modem: 0x3ffbd974 87 53 d9 0a aa 21 13 07 5b e3 52 93 b5 4a 9e 00 |.S...!..[.R..J..|
I (130903006) esp-modem: 0x3ffbd984 3a ef 34 50 10 fa d6 f3 6f 00 00 b0 00 7e 7e 21 |:.4P....o....
!|
I (130903016) esp-modem: 0x3ffbd994 45 00 00 2c 29 d7 40 00 11 06 36 d8 89 87 53 d9 |E..,)[email protected].|
I (130903026) esp-modem: 0x3ffbd9a4 0a aa 21 13 07 5b e3 52 93 b5 4a 9a 00 3a ef 34 |..!..[.R..J..:.4|
I (130903036) esp-modem: 0x3ffbd9b4 50 18 fa d6 d3 65 00 00 20 02 00 00 8a 14 7e |P....e.. .....
|
pppos_input[0]: got 143 bytes
ppp_input[0]: ip in pbuf len=44
ppp_input[0]: ip in pbuf len=40
ppp_input[0]: ip in pbuf len=44
pppos_netif_output[0]: proto=0x21, len = 40
I (130903056) pppos_example: MQTT_EVENT_CONNECTED
pppos_netif_output[0]: proto=0x21, len = 63
I (130903066) pppos_example: sent subscribe successful, msg_id=21850
I (130903846) esp-modem: 0x3ffbd934 7e 21 45 00 00 28 29 d9 40 00 11 06 36 da 89 87 |!E..()[email protected]...|
I (130903846) esp-modem: 0x3ffbd944 53 d9 0a aa 21 13 07 5b e3 52 93 b5 4a 9e 00 3a |S...!..[.R..J..:|
I (130903856) esp-modem: 0x3ffbd954 ef 4b 50 10 fa bf f3 6f 00 00 89 7c 7e 7e 21 45 |.KP....o...|~~!E|
I (130903866) esp-modem: 0x3ffbd964 00 00 2d 29 da 40 00 11 06 36 d4 89 87 53 d9 0a |..-)[email protected]..|
I (130903876) esp-modem: 0x3ffbd974 aa 21 13 07 5b e3 52 93 b5 4a 9e 00 3a ef 4b 50 |.!..[.R..J..:.KP|
I (130903886) esp-modem: 0x3ffbd984 18 fa bf 0e 05 00 00 90 03 55 5a 00 a6 d6 7e |.........UZ...
|
pppos_input[0]: got 95 bytes
ppp_input[0]: ip in pbuf len=40
ppp_input[0]: ip in pbuf len=45
pppos_netif_output[0]: proto=0x21, len = 40
I (130903906) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=21850
pppos_netif_output[0]: proto=0x21, len = 71
I (130903916) pppos_example: sent publish successful, msg_id=0
pppos_netif_output[0]: proto=0x21, len = 71
I (130909786) esp-modem: 0x3ffbd934 7e 21 45 00 00 |!E..|
pppos_input[0]: got 5 bytes
I (130909836) esp-modem: 0x3ffbd934 47 29 db 40 00 11 06 36 b9 89 87 53 d9 0a aa 21 |G)[email protected]...!|
I (130909836) esp-modem: 0x3ffbd944 13 07 5b e3 52 93 b5 4a a3 00 3a ef 6a 50 18 fa |..[.R..J..:.jP..|
I (130909846) esp-modem: 0x3ffbd954 a0 ae f0 00 00 30 1d 00 10 2f 74 6f 70 69 63 2f |.....0.../topic/|
I (130909856) esp-modem: 0x3ffbd964 65 73 70 2d 70 70 70 6f 73 65 73 70 33 32 2d 70 |esp-ppposesp32-p|
I (130909866) esp-modem: 0x3ffbd974 70 70 6f 73 97 ec 7e 7e 21 45 00 00 28 29 dd 40 |ppos..!E..().@|
I (130909876) esp-modem: 0x3ffbd984 00 11 06 36 d6 89 87 53 d9 0a aa 21 13 07 5b e3 |...6...S...!..[.|
I (130909886) esp-modem: 0x3ffbd994 52 93 b5 4a c2 00 3a ef 6a 50 10 fa a0 f3 4b 00 |R..J..:.jP....K.|
I (130909896) esp-modem: 0x3ffbd9a4 00 1a 43 7e 7e 21 45 00 00 47 29 dc 40 00 11 06 |..C
!E..G).@...|
I (130909906) esp-modem: 0x3ffbd9b4 36 b8 89 87 53 d9 0a aa 21 13 07 5b e3 52 93 b5 |6...S...!..[.R..|
I (130909916) esp-modem: 0x3ffbd9c4 4a a3 00 3a ef 6a 50 18 fa a0 ae f0 00 00 30 1d |J..:.jP.......0.|
I (130909926) esp-modem: 0x3ffbd9d4 00 10 2f 74 6f 70 69 63 2f 65 73 70 2d 70 70 70 |../topic/esp-ppp|
I (130909936) esp-modem: 0x3ffbd9e4 6f 73 65 73 70 33 32 2d 70 70 70 6f 73 93 09 7e |osesp32-pppos..
|
pppos_input[0]: got 192 bytes
ppp_input[0]: ip in pbuf len=71
ppp_input[0]: ip in pbuf len=40
ppp_input[0]: ip in pbuf len=71
pppos_netif_output[0]: proto=0x21, len = 40
I (130909966) pppos_example: MQTT_EVENT_DATA
TOPIC=/topic/esp-pppos
DATA=esp32-pppos
pppos_netif_output[0]: proto=0x21, len = 42
pppos_netif_output[0]: proto=0x21, len = 40
W (130911966) MQTT_CLIENT: Client asked to stop, but was not started
E (130912346) esp-modem: esp_dte_handle_line(109): no handler for line
W (130912346) pppos_example: Unknow line received: ~!E
pppos_netif_output[0]: proto=0x21, len = 42
pppos_netif_output[0]: proto=0x21, len = 40
pppos_netif_output[0]: proto=0x21, len = 42
pppos_netif_output[0]: proto=0x21, len = 40
E (130932966) esp-modem: esp_modem_dte_send_cmd(249): process command timeout
E (130932966) bg96: bg96_set_working_mode(352): send command failed
pppos_netif_output[0]: proto=0x21, len = 42
pppos_netif_output[0]: proto=0x21, len = 40
E (130952966) esp-modem: esp_modem_dte_send_cmd(249): process command timeout
E (130952966) bg96: bg96_set_working_mode(352): send command failed
E (130972966) esp-modem: esp_modem_dte_send_cmd(249): process command timeout
E (130972966) bg96: bg96_set_working_mode(352): send command failed
I (130973996) pppos_example: Modem PPP Stopped
ppp_close[0]: kill_link -> lcp_close
ppp phase changed[0]: phase=11
ppp phase changed[0]: phase=9
sifvjcomp[0]: VJ compress enable=0 slot=0 max slot=0
sifdown[0]: err_code=5
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=0 0 0 0
ppp_recv_config[0]
sent [LCP TermReq id=0xfe "User request"]
pppos_write[0]: len=20
I (130974026) pppos_example: 30 sec delay start
sent [LCP TermReq id=0xff "User request"]
pppos_write[0]: len=20
ppp phase changed[0]: phase=12
Connection terminated.
ppp_link_terminated[0]
ppp_link_end[0]
ppp phase changed[0]: phase=0
I (130986026) esp-netif_lwip-ppp: User interrupt
ppp_link_terminated[0]: finished.
I (131004026) pppos_example: 30 sec delay end
E (131005026) esp-modem: esp_modem_dte_send_cmd(249): process command timeout
E (131005026) bg96: bg96_power_down(390): send command failed
ESP_ERROR_CHECK failed: esp_err_t 0xffffffff (ESP_FAIL) at 0x40083ec0
0x40083ec0: _esp_error_check_failed at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/esp_err.c:45

file: "../main/pppos_client_main.c" line 343
func: app_main
expression: dce->power_down(dce)

abort() was called at PC 0x40083ec3 on core 0
0x40083ec3: _esp_error_check_failed at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/esp_err.c:46

Backtrace:0x40085013:0x3ffb7200 0x40085701:0x3ffb7220 0x4008959a:0x3ffb7240 0x40083ec3:0x3ffb72b0 0x400d6fc4:0x3ffb72d0 0x400d539e:0x3ffb7400 0x40085709:0x3ffb7430
0x40085013: panic_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/panic.c:330

0x40085701: esp_system_abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/system_api.c:106

0x4008959a: abort at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/newlib/abort.c:46

0x40083ec3: _esp_error_check_failed at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/esp_err.c:46

0x400d6fc4: app_main at c:\olf\development\firmware\ppos\pppos_client\build/../main/pppos_client_main.c:343 (discriminator 1)

0x400d539e: main_task at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/cpu_start.c:600 (discriminator 2)

0x40085709: vPortTaskWrapper at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

ELF file SHA256: 55179065fefdb290

@david-cermak
Copy link
Collaborator

Thanks for testing this, it looks like this works for switching modes, but has multiple other issues in power_down() etc. No need to post any other crashes, just wanted to understand your issue. Now I think it is clear, and we have to:

  • synchronize closing the PPP netif with switching modes
  • include 6d70b7c (which wasn't present on your branch AFAIK)

Added the two fixes into the following patch
0001-esp_moded-Fix-PPP-reinit-on-v4.1.patch.txt

Could you please test it and let us know if it works in your setup? This is the patch against f0e87c9 version (i believe that's the version of IDF you've indicated above)

@kannannair084
Copy link
Author

hi David,

my idf was 4.0.1 and since that didnt use the netif and didn't had modem_stop.. so i upgraded the IDF to v4.2-beta1-227-gf0e87c933-dirty ( 4.2 stable release) and fix you suggested started working on 4.2

however, there are still issues as indicated in my crash report above, based on this, could you recommend what i need to change?

i have added the 6d70b7c by changing timeout to 5000 and adding two lines
res = uart_set_rx_timeout(esp_dte->uart_port, 1);
MODEM_CHECK(res == ESP_OK, "set rx timeout failed", err_uart_config);

but i don't know how to do this:

  • synchronize closing the PPP netif with switching modes.

considering my idf version is IDF to v4.2-beta1-227-gf0e87c933-dirty , the 0001-esp_moded-Fix-PPP-reinit-on-v4.1.patch.txt is it still applicable?

@david-cermak
Copy link
Collaborator

Hi @kannannair084

Thanks for explaining on the versions. Okay, so the v4.2-beta1 it is, sorry I somehow missed it and posted the wrong v4.1 patch.

Here's the correct one, based on this commit f0e87c9:
0001-esp_moded-Fix-PPP-reinit-on-v4.2-beta1.txt

(Note: this already includes the 6d70b7c, here's how you can apply it:

$ git checkout v4.2-beta1-227-gf0e87c933
$ git checkout -b test/ppp_reinit_fix
$ git am < 0001-esp_moded-Fix-PPP-reinit-on-v4.2-beta1.txt

@kannannair084
Copy link
Author

Thank you David for explaining, i didnt use git to get the IDF, i think i downloaded the zip and extracted it.. however, i will follow the change list as per 0001-esp_moded-Fix-PPP-reinit-on-v4.2-beta1.txt and will run it tonight and get back to you.

@kannannair084
Copy link
Author

i am facing another issue, that is, when i enable PPP in port_num = UART_NUM_1, my UART_NUM_2 is getting affected..

to show an example,
when PPP is not initialized and connected.
image
above is intended byte[] to send and actual sent is matching
image

however, once the PPP is intialized, Although i am sending the same Message
it only sends it partially, and the remaining is sent in the next sent cycle.
image

image

@kannannair084
Copy link
Author

this is one such sending cycle
image

@kannannair084
Copy link
Author

kannannair084 commented Oct 28, 2020

image

It looks like the data is getting repositioned...

image

void UARTSendCMD_PAMgr(const uint8_t* data, uint32_t len)
{
	gpio_set_level(PA_RX_TX_SWITCH_PIN, 1);
	memset(ui8pPADeviceReadBuffer, '\0', PA_RXBUF_SIZE);
	uart_write_bytes(UART_NUM_2, (char*)data, len);
	//Delay(14);
	ESP_ERROR_CHECK(uart_wait_tx_done(UART_NUM_2, (100 / portTICK_PERIOD_MS))); // original was 100 ticks
	gpio_set_level(PA_RX_TX_SWITCH_PIN, 0);
}

This is my data sending function, which is working fine, untill i init dte

dte = esp_modem_dte_init(&config);

where 
#define ESP_MODEM_DTE_DEFAULT_CONFIG()          \
    {                                           \
        .port_num = UART_NUM_1,                 \
        .data_bits = UART_DATA_8_BITS,          \
        .stop_bits = UART_STOP_BITS_1,          \
        .parity = UART_PARITY_DISABLE,          \
        .baud_rate = 115200,                    \
        .flow_control = MODEM_FLOW_CONTROL_NONE,\
        .tx_io_num = 33,                        \
        .rx_io_num = 25,                        \
        .rts_io_num = 14,                       \
        .cts_io_num = 26,                       \
        .rx_buffer_size = 2048,                 \
        .tx_buffer_size = 1024,                  \
        .pattern_queue_size = 30,               \
        .event_queue_size = 35,                 \
        .event_task_stack_size = 4096,          \
        .event_task_priority = 5,               \
        .line_buffer_size = 1024                 \
    }



@kannannair084
Copy link
Author

Also, i noticed that, issue starts to appear after this step in esp_modem.c in the function esp_modem_dte_init(), i tried commenting out section by section to identify where it starts.

/*    MODEM_CHECK(uart_param_config(esp_dte->uart_port, &uart_config) == ESP_OK, "config uart parameter failed", err_uart_config);
    if (config->flow_control == MODEM_FLOW_CONTROL_HW) {
        res = uart_set_pin(esp_dte->uart_port, config->tx_io_num, config->rx_io_num,
                           config->rts_io_num, config->cts_io_num);
    } else {
        res = uart_set_pin(esp_dte->uart_port, config->tx_io_num, config->rx_io_num,
                           UART_PIN_NO_CHANGE, UART_PIN_NO_CHANGE);
    }
    MODEM_CHECK(res == ESP_OK, "config uart gpio failed", err_uart_config); */
    /* Set flow control threshold */

@kannannair084
Copy link
Author

@david-cermak i need to fix the issues and deliver a working solution by end of this week.. i could stay back late as i understand our time differences.. i am blocked by this issue.

It would be great if you could take a look and suggest a way to fix this.. i could stick around.. please keep an eye on this thread..

@kannannair084
Copy link
Author

@david-cermak could you respond when you come online and see my msg. i am here so that this issue could be resolved at the earliest. sorry for pushing this so hard, like i said, i am blocked by this issue to meet my end of the week delivery timeline.

@kannannair084
Copy link
Author

kannannair084 commented Oct 29, 2020

i got this issue, UART 2 getting corrupted, resolved by commenting this line in uart.c,

esp_err_t uart_param_config(uart_port_t uart_num, const uart_config_t *uart_config)
  // uart_hal_txfifo_rst(&(uart_context[uart_num].hal));

@kannannair084
Copy link
Author

i am having an issue now, with this ESP_IDF change, when i connect to ble, it is crashing and after the reboot it says issue in modem.c

I (6083) NewEsp: CREATE_SERVICE_EVT, status 0, service_handle 40

I (6083) NewEsp: REGISTER_APP_EVT, status 0, app_id 1

I (6093) NewEsp: REGISTER_APP_EVT, status 0, app_id 2

I (6093) NewEsp: REGISTER_APP_EVT, status 0, app_id 3

I (6103) NewEsp: BluetoothLE has been started!
I (6123) NewEsp: SERVICE_START_EVT, status 0, service_handle 40

I (6123) NewEsp: CREATE_SERVICE_EVT, status 0, service_handle 46

I (6123) NewEsp: CREATE_SERVICE_EVT, status 0, service_handle 62

I (6133) NewEsp: CREATE_SERVICE_EVT, status 0, service_handle 78

I (6133) NewEsp: REGISTER_APP_EVT, status 0, app_id 4

I (6143) NewEsp: REGISTER_APP_EVT, status 0, app_id 5

I (6153) NewEsp: SERVICE_START_EVT, status 0, service_handle 46

I (6153) NewEsp: SERVICE_START_EVT, status 0, service_handle 62

I (6163) NewEsp: SERVICE_START_EVT, status 0, service_handle 78

I (6163) NewEsp: CREATE_SERVICE_EVT, status 0, service_handle 98

I (6173) NewEsp: CREATE_SERVICE_EVT, status 0, service_handle 102

I (6183) NewEsp: SERVICE_START_EVT, status 0, service_handle 98

I (6193) NewEsp: SERVICE_START_EVT, status 0, service_handle 102

I (6733) NewEsp: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 78:59:f7:4f:cc:ab:
I (6733) NewEsp: CONNECT_EVT, conn_id 0, remote 78:59:f7:4f:cc:ab:
E (6733) esp-modem: esp_dte_handle_line(103): DTE has not yet bind with DCE
I (6733) NewEsp: CONNECT_EVT, conn_id 0, remote 78:59:f7:4f:cc:ab:
I (6743) NewEsp: CONNECT_EVT, conn_id 0, remote 78:59:f7:4f:cc:ab:
I (6753) NewEsp: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 78:59:f7:4f:cc:ab:
I (6763) NewEsp: CONNECT_EVT, conn_id 0, remote 78:59:f7:4f:cc:ab:
W (6773) BT_L2CAP: l2cble_start_conn_update, the last connection update command still pending.
E (6793) esp-modem: esp_dte_handle_line(103): DTE has not yet bind with DCE
ets Jun 8 2016 00:22:57

rst:0x8 (TG1WDT_SYS_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:4
load:0x3fff0034,len:6036
load:0x40078000,len:13372
load:0x40080400,len:3820
0x40080400: _init at ??:?

entry 0x40080658
I (58) boot: ESP-IDF v4.2-beta1-227-gf0e87c933-dirty 2nd stage bootloader
I (58) boot: compile time 11:25:57
I (60) boot: chip revision: 1
I (63) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (71) boot.esp32: SPI Speed : 40MHz
I (75) boot.esp32: SPI Mode : DIO
I (80) boot.esp32: SPI Flash Size : 16MB
W (84) boot.esp32: PRO CPU has been reset by WDT.
W (90) boot.esp32: WDT reset info: PRO CPU PC=0x40092e9f
0x40092e9f: xthal_save_extra_nw at /Users/igrokhotkov/e/esp32/hal/hal/state_asm.S:72

W (96) boot.esp32: WDT reset info: APP CPU PC=0x4008f810
0x4008f810: panic_handler at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_system/port/panic_handler.c:487 (discriminator 1)

I (102) boot: Enabling RNG early entropy source...
I (107) boot: Partition Table:
I (111) boot: ## Label Usage Type ST Offset Length
I (118) boot: 0 nvs WiFi data 01 02 00011000 00004000
I (126) boot: 1 otadata OTA data 01 00 00015000 00002000
I (133) boot: 2 phy_init RF data 01 01 00017000 00020000
I (141) boot: 3 factory factory app 00 00 00040000 00200000
I (148) boot: 4 ota_0 OTA app 00 10 00240000 00200000
I (156) boot: 5 ota_1 OTA app 00 11 00440000 00200000
I (164) boot: End of partition table
I (168) boot: Defaulting to factory image
I (173) boot_comm: chip revision: 1, min. application chip revision: 0
I (180) esp_image: segment 0: paddr=0x00040020 vaddr=0x3f400020 size=0x2c694 (181908) map
I (257) esp_image: segment 1: paddr=0x0006c6bc vaddr=0x3ffbdb60 size=0x0395c ( 14684) load
I (264) esp_image: segment 2: paddr=0x00070020 vaddr=0x400d0020 size=0xd12c4 (856772) map
0x400d0020: _stext at ??:?

I (587) esp_image: segment 3: paddr=0x001412ec vaddr=0x3ffc14bc size=0x00e98 ( 3736) load
I (589) esp_image: segment 4: paddr=0x0014218c vaddr=0x40080000 size=0x00404 ( 1028) load
0x40080000: _WindowOverflow4 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/xtensa_vectors.S:1730

I (595) esp_image: segment 5: paddr=0x00142598 vaddr=0x40080404 size=0x15994 ( 88468) load
I (654) boot: Loaded app from partition at offset 0x40000
I (654) boot: Disabling RNG early entropy source...
I (655) cpu_start: Pro cpu up.
I (658) cpu_start: Application information:
I (663) cpu_start: Project name: olfirmware-esp32-lte-dlc
I (669) cpu_start: App version: 1
I (674) cpu_start: Compile time: Oct 29 2020 15:47:05
I (680) cpu_start: ELF file SHA256: 48f0ff3b34a46a98...
I (686) cpu_start: ESP-IDF: v4.2-beta1-227-gf0e87c933-dirty
I (693) cpu_start: Starting app cpu, entry point is 0x400817e0
0x400817e0: call_start_cpu1 at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/cpu_start.c:287

I (0) cpu_start: App cpu up.
I (703) heap_init: Initializing. RAM available for dynamic allocation:
I (710) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (716) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (722) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (728) heap_init: At 3FFCF900 len 00010700 (65 KiB): DRAM
I (735) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (741) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (747) heap_init: At 40095D98 len 0000A268 (40 KiB): IRAM
I (753) cpu_start: Pro cpu start user code
I (772) esp_core_dump_uart: Init core dump to UART
I (772) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
����I (1193) NewEsp: ===End===
I (1193) NewEsp: OL Firmware started. Version 9.0.16
I (1193) NewEsp: Started initialization...
just finished init NFC
I (1353) gpio: GPIO[15]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:2
Success with NFC Setting GPIO
I (1353) NewEsp: Initializing Power Analyser module...
I (1353) NewEsp: Power Analyser UART is initialized!
I (1363) gpio: GPIO[2]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1373) NewEsp: GPIO pin is initialized for Power Analyser!
I (1373) NewEsp: Power Analyser module initialization is done!
E (1383) NewEsp: Error (4354) reading data from NVS!

E (1393) NewEsp: Error (4354) reading data from NVS!

E (1393) NewEsp: Error (4354) reading NVS RELAY NEW CONFIG!
E (1403) NewEsp: Error (4354) reading NVS RELAY NEW SCHEDULE!
I (1403) NewEsp: Relay Schedule loaded
I (1413) NewEsp: BArray content: 0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
E (1433) NewEsp: Error (4354) reading NVS RELAY CONFIG!
I (1433) NewEsp: Relay Config
I (1443) NewEsp: BArray content: 0000000000000000000000000
I (1443) NewEsp: Registered Phase information, BARRAY
I (1453) NewEsp: BArray content: 00000000
I (1453) NewEsp: Failed to read the PA update flag, May be not Initialized before
ui8BleTurnOnPostRebootFlag = 0
PA config
I (1473) NewEsp: BArray content: 00ffffffffffffffffffffffffffffffff
Relay config
I (1473) NewEsp: BArray content: 00000000000000000
I (1483) NewEsp: Initializing SigFox timer...
I (1493) NewEsp: Timer initialization is done!
I (1493) NewEsp: Initializing Power Analyser timer...
I (1503) NewEsp: Timer initialization is done!
I (1503) HTTP_CLIENT: Going to pre-initialize ESP32 Modem
I (1513) gpio: GPIO[12]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1523) gpio: GPIO[18]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
Success with Setting GPIO
Set power button to low
I (2233) uart: queue free spaces: 35
Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled.

Core 1 register dump:
PC : 0x400e3141 PS : 0x00060030 A0 : 0x800e331a A1 : 0x3ffd60d0
0x400e3141: esp_handle_uart_data at c:\olf\development\firmware\olfirmware-esp32-lte-dlc\build/../components/LteModem/src/esp_modem.c:160

A2 : 0x3ffb5fc0 A3 : 0x00000000 A4 : 0x3ffd4038 A5 : 0x00000000
A6 : 0x3ffd41d8 A7 : 0x00060f23 A8 : 0x00000000 A9 : 0x3ffd60a0
A10 : 0x3ffc9b4c A11 : 0x3ffd6100 A12 : 0x8008fdd8 A13 : 0x3ffb5450
A14 : 0x00000003 A15 : 0x00060723 SAR : 0x00000000 EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000078 LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff

Backtrace:0x400e313e:0x3ffd60d0 0x400e3317:0x3ffd6100 0x4008fc29:0x3ffd6130
0x400e313e: esp_handle_uart_data at c:\olf\development\firmware\olfirmware-esp32-lte-dlc\build/../components/LteModem/src/esp_modem.c:159

0x400e3317: uart_event_task_entry at c:\olf\development\firmware\olfirmware-esp32-lte-dlc\build/../components/LteModem/src/esp_modem.c:191

0x4008fc29: vPortTaskWrapper at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

ELF file SHA256: 48f0ff3b34a46a98

Initiating core dump!
I (1350) esp_core_dump_uart: Press Enter to print core dump to UART...
I (1358) esp_core_dump_uart: Print core dump to uart...
I (1364) esp_core_dump_elf: Found tasks: 10
Core dump started (further output muted)
Received 20 kB...
Core dump finished!
espcoredump.py v0.4-dev

==================== ESP32 CORE DUMP START ====================

Crashed task handle: 0x3ffd61bc, name: 'uart_event', GDB name: 'process 1073570236'

================== CURRENT THREAD REGISTERS ===================
exccause 0x1c (LoadProhibitedCause)
excvaddr 0x78
epc1 0x0
epc2 0x0
epc3 0x40089e45
epc4 0x0
epc5 0x0
epc6 0x0
epc7 0x0
eps2 0x0
eps3 0x0
eps4 0x60820
eps5 0x0
eps6 0x0
eps7 0x4019be93
pc 0x400e3141 0x400e3141 <esp_handle_uart_data+5>
lbeg 0x4000c2e0 1073791712
lend 0x4000c2f6 1073791734
lcount 0xffffffff 4294967295
sar 0x0 0
ps 0x60020 393248
threadptr
br
scompare1
acclo
acchi
m0
m1
m2
m3
expstate
f64r_lo
f64r_hi
f64s
fcr
fsr
a0 0x800e331a -2146553062
a1 0x3ffd60d0 1073570000
a2 0x3ffb5fc0 1073438656
a3 0x0 0
a4 0x3ffd4038 1073561656
a5 0x0 0
a6 0x3ffd41d8 1073562072
a7 0x60f23 397091
a8 0x0 0
a9 0x3ffd60a0 1073569952
a10 0x3ffc9b4c 1073519436
a11 0x3ffd6100 1073570048
a12 0x8008fdd8 -2146894376
a13 0x3ffb5450 1073435728
a14 0x3 3
a15 0x60723 395043

==================== CURRENT THREAD STACK =====================
#0 0x400e3141 in esp_handle_uart_data (esp_dte=0x3ffb5fc0) at ../components/LteModem/src/esp_modem.c:160
#1 0x400e331a in uart_event_task_entry (param=0x3ffb5fc0) at ../components/LteModem/src/esp_modem.c:191
#2 0x4008fc2c in vPortTaskWrapper (pxCode=0x400e32ec <uart_event_task_entry>, pvParameters=0x3ffb5fc0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

======================== THREADS INFO =========================
Id Target Id Frame

  • 1 process 1073570236 0x400e3141 in esp_handle_uart_data (esp_dte=0x3ffb5fc0) at ../components/LteModem/src/esp_modem.c:160
    2 process 1073465400 0x4000bff0 in ?? ()
    3 process 1073469316 0x4019e192 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
    4 process 1073467424 0x4019e192 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
    5 process 1073436172 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    6 process 1073545504 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    7 process 1073453628 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    8 process 1073455008 0x40092a08 in xQueueGenericReceive (xQueue=0x3ffb7fa0, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
    9 process 1073437400 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
    10 process 1073444524 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115

==================== THREAD 1 (TCB: 0x3ffd61bc, name: 'uart_event') =====================
#0 0x400e3141 in esp_handle_uart_data (esp_dte=0x3ffb5fc0) at ../components/LteModem/src/esp_modem.c:160
#1 0x400e331a in uart_event_task_entry (param=0x3ffb5fc0) at ../components/LteModem/src/esp_modem.c:191
#2 0x4008fc2c in vPortTaskWrapper (pxCode=0x400e32ec <uart_event_task_entry>, pvParameters=0x3ffb5fc0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 2 (TCB: 0x3ffbc838, name: 'main') =====================
#0 0x4000bff0 in ?? ()
#1 0x4008fdd8 in vPortExitCritical (mux=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:419
Backtrace stopped: Cannot access memory at address 0xfffffff4

==================== THREAD 3 (TCB: 0x3ffbd784, name: 'IDLE1') =====================
#0 0x4019e192 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
#1 0x400d6785 in esp_vApplicationIdleHook () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/freertos_hooks.c:63
#2 0x40090548 in prvIdleTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:3386
#3 0x4008fc2c in vPortTaskWrapper (pxCode=0x4009053c , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 4 (TCB: 0x3ffbd020, name: 'IDLE0') =====================
#0 0x4019e192 in esp_pm_impl_waiti () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/pm_esp32.c:484
#1 0x400d6785 in esp_vApplicationIdleHook () at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_common/src/freertos_hooks.c:63
#2 0x40090548 in prvIdleTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/tasks.c:3386
#3 0x4008fc2c in vPortTaskWrapper (pxCode=0x4009053c , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 5 (TCB: 0x3ffb560c, name: 'tiT') =====================
#0 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40092a08 in xQueueGenericReceive (xQueue=0x3ffb33f4, pvBuffer=0x3ffb5550, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x40151df4 in sys_arch_mbox_fetch (mbox=, msg=0x3ffb5550, timeout=100) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/port/esp32/freertos/sys_arch.c:325
#3 0x4013e93b in tcpip_timeouts_mbox_fetch (mbox=0x3ffce5c4 <tcpip_mbox>, msg=0x3ffb5550) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:110
#4 0x4013e9db in tcpip_thread (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/lwip/lwip/src/api/tcpip.c:148
#5 0x4008fc2c in vPortTaskWrapper (pxCode=0x4013e9c0 <tcpip_thread>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 6 (TCB: 0x3ffd0120, name: 'Tmr Svc') =====================
#0 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40091da6 in prvProcessTimerOrBlockTask (xNextExpireTime=, xListWasEmpty=) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x40091e93 in prvTimerTask (pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/timers.c:544
#3 0x4008fc2c in vPortTaskWrapper (pxCode=0x40091e84 , pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 7 (TCB: 0x3ffb9a3c, name: 'ipc0') =====================
#0 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40092a08 in xQueueGenericReceive (xQueue=0x3ffb7aa0, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x40089d53 in ipc_task (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_ipc/ipc.c:51
#3 0x4008fc2c in vPortTaskWrapper (pxCode=0x40089d3c <ipc_task>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 8 (TCB: 0x3ffb9fa0, name: 'ipc1') =====================
#0 0x40092a08 in xQueueGenericReceive (xQueue=0x3ffb7fa0, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#1 0x40089d53 in ipc_task (arg=0x1) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_ipc/ipc.c:51
#2 0x4008fc2c in vPortTaskWrapper (pxCode=0x40089d3c <ipc_task>, pvParameters=0x1) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 9 (TCB: 0x3ffb5ad8, name: 'sys_evt') =====================
#0 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40092a08 in xQueueGenericReceive (xQueue=0x3ffb5830, pvBuffer=0x3ffd2870, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x401a0a74 in esp_event_loop_run (event_loop=0x3ffb5814, ticks_to_run=4294967295) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:624
#3 0x401a0a8c in esp_event_loop_run_task (args=0x3ffb5814) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_event/esp_event.c:115
#4 0x4008fc2c in vPortTaskWrapper (pxCode=0x401a0a80 <esp_event_loop_run_task>, pvParameters=0x3ffb5814) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

==================== THREAD 10 (TCB: 0x3ffb76ac, name: 'esp_timer') =====================
#0 0x40081a90 in esp_crosscore_int_send_yield (core_id=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp32/crosscore_int.c:115
#1 0x40092a08 in xQueueGenericReceive (xQueue=0x3ffb6654, pvBuffer=0x0, xTicksToWait=, xJustPeeking=0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/soc/src/esp32/include/hal/cpu_ll.h:39
#2 0x400d690f in timer_task (arg=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/esp_timer/src/esp_timer.c:329
#3 0x4008fc2c in vPortTaskWrapper (pxCode=0x400d68fc <timer_task>, pvParameters=0x0) at C:/OLF/Development/Firmware/ESP-IDF/esp-idf_4_2/components/freertos/xtensa/port.c:143

======================= ALL MEMORY REGIONS ========================
Name Address Size Attrs
.rtc.text 0x400c0000 0x0 RW
.rtc.dummy 0x3ff80000 0x0 RW
.rtc.force_fast 0x3ff80000 0x0 RW
.rtc_noinit 0x50000000 0x0 RW
.rtc.force_slow 0x50000000 0x0 RW
.iram0.vectors 0x40080000 0x404 R XA
.iram0.text 0x40080404 0x15994 R XA
.dram0.data 0x3ffbdb60 0x47f4 RW A
.noinit 0x3ffc2354 0x0 RW
.flash.rodata 0x3f400020 0x2c694 RW A
.flash.text 0x400d0020 0xd12c4 R XA
.iram0.text_end 0x40095d98 0x0 RW
.iram0.data 0x40095d98 0x0 RW
.iram0.bss 0x40095d98 0x0 RW
.dram0.heap_start 0x3ffcf900 0x0 RW
.coredump.tasks.data 0x3ffd61bc 0x15c RW
.coredump.tasks.data 0x3ffd6010 0x1a4 RW
.coredump.tasks.data 0x3ffbc838 0x15c RW
.coredump.tasks.data 0x3ffbc500 0x330 RW
.coredump.tasks.data 0x3ffbd784 0x15c RW
.coredump.tasks.data 0x3ffbd5d0 0x1ac RW
.coredump.tasks.data 0x3ffbd020 0x15c RW
.coredump.tasks.data 0x3ffbce70 0x1a8 RW
.coredump.tasks.data 0x3ffb560c 0x15c RW
.coredump.tasks.data 0x3ffb53e0 0x224 RW
.coredump.tasks.data 0x3ffd0120 0x15c RW
.coredump.tasks.data 0x3ffcff50 0x1c8 RW
.coredump.tasks.data 0x3ffb9a3c 0x15c RW
.coredump.tasks.data 0x3ffb7d30 0x1c0 RW
.coredump.tasks.data 0x3ffb9fa0 0x15c RW
.coredump.tasks.data 0x3ffb9df0 0x1a8 RW
.coredump.tasks.data 0x3ffb5ad8 0x15c RW
.coredump.tasks.data 0x3ffd2750 0x20c RW
.coredump.tasks.data 0x3ffb76ac 0x15c RW
.coredump.tasks.data 0x3ffb74e0 0x1c4 RW

===================== ESP32 CORE DUMP END =====================

Done!
I (3248) esp_core_dump_uart: Core dump has been written to uart.
Rebooting...
ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:4
load:0x3fff0034,len:6036
load:0x40078000,len:13372
load:0x40080400,len:3820
0x40080400: _init at ??:?

entry 0x40080658

@david-cermak
Copy link
Collaborator

Hi @kannannair084

If I understand correctly, now the modem/ppp work okay until you get a BLE crash, consequent reboot and yet another crash from the modem then? If so, it seems like the modem is in the data mode sending packets to the ESP32 which hasn't yet initialized the data mode, thus failing.

@david-cermak
Copy link
Collaborator

@kannannair084 The crash you're experiencing looks similar to one in another issue. Could you please try if applying the patch from this comment helps?

@kannannair084
Copy link
Author

@david-cermak thank you for getting back, sure, will try this and let you know how it goes.

@kannannair084
Copy link
Author

hi David, i have made the modification as suggested and no longer see issues happening... you may close this thread.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants