search

espressif / esp-protocols

Collection of ESP-IDF components related to networking protocols
195 stars 133 forks source link

cmux_example: Failed to configure multiplexed command mode... exiting (IDFGH-8886) #187

Closed jgus closed 11 months ago

jgus commented 1 year ago

I'm unable to get the simple_cmux_client example (or my own code) working in CMUX mode.

Command and data modes work fine (both in examples and in my own code) but CMUX mode refuses to work.

My issue looks similar to #140, but where that appears to be resolved, I'm seeing this issue in the latest master branch.

I'm using ESP-IDF v5.0, and the latest master branch (457f8335bb876b8af80a65b096e5381f49f29878).

My target device is a LilyGO T-SIM7000G 20200415 (https://github.com/Xinyuan-LilyGO/LilyGO-T-SIM7000G/blob/master/Historical/SIM7000G_20200415/README.MD) with a SIM7000G modem and an ESP-WROVER-E processor. I've set pins appropriately for my device (TX 27, RX 26, RTS & CTS -1, no flow control) and I've verified I can communicate with the modem. Command and data modes work fine and I can successfully communicate over the internet in data mode.

When running the CMUX sample (or trying myself in my own code) the call to dce->set_mode(esp_modem::modem_mode::CMUX_MODE) fails.

Anything I can add to help debug this issue, please let me know.

Verbose log follows:

rst:0x1 (POWERON_RESET),boot:0x13 (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:1
load:0x3fff0030,len:6992
load:0x40078000,len:15456
load:0x40080400,len:3840
0x40080400: _init at ??:?

entry 0x4008064c
I (27) boot: ESP-IDF v5.0 2nd stage bootloader
I (27) boot: compile time 15:51:28
I (27) boot: chip revision: v3.0
I (30) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (37) boot.esp32: SPI Speed      : 80MHz
I (42) boot.esp32: SPI Mode       : DIO
I (46) boot.esp32: SPI Flash Size : 16MB
I (51) boot: Enabling RNG early entropy source...
I (56) boot: Partition Table:
I (60) boot: ## Label            Usage          Type ST Offset   Length
I (67) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (75) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (82) boot:  2 factory          factory app      00 00 00010000 00177000
I (90) boot: End of partition table
I (94) boot_comm: chip revision: 3, min. application chip revision: 0
I (101) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=3fabch (260796) map
I (148) esp_image: segment 1: paddr=0004fae4 vaddr=3ffb0000 size=00534h (  1332) load
I (148) esp_image: segment 2: paddr=00050020 vaddr=400d0020 size=a8c28h (691240) map
I (254) esp_image: segment 3: paddr=000f8c50 vaddr=3ffb0534 size=02cd8h ( 11480) load
I (257) esp_image: segment 4: paddr=000fb930 vaddr=40080000 size=13ba4h ( 80804) load
I (276) esp_image: segment 5: paddr=0010f4dc vaddr=50000000 size=00010h (    16) load
I (286) boot: Loaded app from partition at offset 0x10000
I (286) boot: Disabling RNG early entropy source...
D (298) efuse: In EFUSE_BLK0__DATA3_REG is used 3 bits starting with 9 bit
D (299) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 2 bit
I (303) quad_psram: This chip is ESP32-D0WD
I (309) esp_psram: Found 8MB PSRAM device
I (313) esp_psram: Speed: 80MHz
I (317) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
V (324) mmu: after coalescing, 3 regions are left
V (329) mmu: found laddr is 0x1800000
V (333) esp_psram: 8bit-aligned-range: 0x400000 B, starting from: 0x3f800000
W (340) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (349) cpu_start: Pro cpu up.
I (353) cpu_start: Starting app cpu, entry point is 0x4008174c
0x4008174c: call_start_cpu1 at C:/Users/Josh/esp/esp-idf/components/esp_system/port/cpu_start.c:142

I (0) cpu_start: App cpu up.
I (874) esp_psram: SPI SRAM memory test OK
D (881) clk: RTC_SLOW_CLK calibration value: 3357978
I (886) cpu_start: Pro cpu start user code
I (887) cpu_start: cpu freq: 160000000 Hz
I (887) cpu_start: Application information:
I (891) cpu_start: Project name:     simple_cmux_client
I (897) cpu_start: App version:      6f33c85-dirty
I (903) cpu_start: Compile time:     Dec  4 2022 15:51:16
I (909) cpu_start: ELF file SHA256:  2ce8ffc089f63c26...
I (915) cpu_start: ESP-IDF:          v5.0
V (920) memory_layout: reserved range is 0x3f43fa8c - 0x3f43facc
D (926) memory_layout: Checking 8 reserved memory ranges:
D (931) memory_layout: Reserved memory range 0x3f800000 - 0x3fc00000
D (937) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
D (944) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb63a8
D (950) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
D (957) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350
D (963) memory_layout: Reserved memory range 0x40070000 - 0x40078000
D (970) memory_layout: Reserved memory range 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

D (976) memory_layout: Reserved memory range 0x40080000 - 0x40093ba4
0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

D (982) memory_layout: Building list of available memory regions:
V (989) memory_layout: Examining memory region 0x3f800000 - 0x3fc00000
V (995) memory_layout: Region 0x3f800000 - 0x3fc00000 inside of reserved 0x3f800000 - 0x3fc00000
V (1004) memory_layout: Examining memory region 0x3ffae000 - 0x3ffb0000
V (1011) memory_layout: Start of region 0x3ffae000 - 0x3ffb0000 overlaps reserved 0x3ffae000 - 0x3ffae6e0
D (1020) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000
V (1027) memory_layout: Examining memory region 0x3ffb0000 - 0x3ffb8000
V (1034) memory_layout: Start of region 0x3ffb0000 - 0x3ffb8000 overlaps reserved 0x3ffb0000 - 0x3ffb63a8
D (1043) memory_layout: Available memory region 0x3ffb63a8 - 0x3ffb8000
V (1050) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffc0000
D (1057) memory_layout: Available memory region 0x3ffb8000 - 0x3ffc0000
V (1063) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc2000
D (1070) memory_layout: Available memory region 0x3ffc0000 - 0x3ffc2000
V (1077) memory_layout: Examining memory region 0x3ffc2000 - 0x3ffc4000
D (1083) memory_layout: Available memory region 0x3ffc2000 - 0x3ffc4000
V (1090) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc6000
D (1097) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000
V (1104) memory_layout: Examining memory region 0x3ffc6000 - 0x3ffc8000
D (1110) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000
V (1117) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffca000
D (1124) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000
V (1130) memory_layout: Examining memory region 0x3ffca000 - 0x3ffcc000
D (1137) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000
V (1144) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffce000
D (1150) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000
V (1157) memory_layout: Examining memory region 0x3ffce000 - 0x3ffd0000
D (1164) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000
V (1170) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd2000
D (1177) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
V (1184) memory_layout: Examining memory region 0x3ffd2000 - 0x3ffd4000
D (1190) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
V (1197) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd6000
D (1204) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
V (1210) memory_layout: Examining memory region 0x3ffd6000 - 0x3ffd8000
D (1217) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
V (1224) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffda000
D (1231) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
V (1237) memory_layout: Examining memory region 0x3ffda000 - 0x3ffdc000
D (1244) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
V (1251) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffde000
D (1257) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
V (1264) memory_layout: Examining memory region 0x3ffde000 - 0x3ffe0000
D (1271) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
V (1277) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000
V (1284) memory_layout: Start of region 0x3ffe0000 - 0x3ffe4000 overlaps reserved 0x3ffe0000 - 0x3ffe0440
V (1294) memory_layout: End of region 0x3ffe0440 - 0x3ffe4000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350
D (1303) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20
V (1310) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000
V (1316) memory_layout: Start of region 0x3ffe4000 - 0x3ffe8000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350
D (1326) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
V (1333) memory_layout: Examining memory region 0x3ffe8000 - 0x3fff0000
D (1339) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
V (1346) memory_layout: Examining memory region 0x3fff0000 - 0x3fff8000
D (1353) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
V (1360) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000
D (1366) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
V (1373) memory_layout: Examining memory region 0x3fffc000 - 0x40000000
D (1380) memory_layout: Available memory region 0x3fffc000 - 0x40000000
V (1386) memory_layout: Examining memory region 0x40070000 - 0x40078000
V (1393) memory_layout: Region 0x40070000 - 0x40078000 inside of reserved 0x40070000 - 0x40078000
V (1402) memory_layout: Examining memory region 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1409) memory_layout: Region 0x40078000 - 0x40080000 inside of reserved 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1418) memory_layout: Examining memory region 0x40080000 - 0x40082000
0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

0x40082000: esp_restart_noos at C:/Users/Josh/esp/esp-idf/components/esp_system/port/soc/esp32/system_internal.c:45

V (1424) memory_layout: Region 0x40080000 - 0x40082000 inside of reserved 0x40080000 - 0x40093ba4
0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

0x40082000: esp_restart_noos at C:/Users/Josh/esp/esp-idf/components/esp_system/port/soc/esp32/system_internal.c:45

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1433) memory_layout: Examining memory region 0x40082000 - 0x40084000
0x40082000: esp_restart_noos at C:/Users/Josh/esp/esp-idf/components/esp_system/port/soc/esp32/system_internal.c:45

0x40084000: psram_cmd_recv_start at C:/Users/Josh/esp/esp-idf/components/esp_psram/esp32/esp_psram_impl_quad.c:304 (discriminator 17)

V (1440) memory_layout: Region 0x40082000 - 0x40084000 inside of reserved 0x40080000 - 0x40093ba4
0x40082000: esp_restart_noos at C:/Users/Josh/esp/esp-idf/components/esp_system/port/soc/esp32/system_internal.c:45

0x40084000: psram_cmd_recv_start at C:/Users/Josh/esp/esp-idf/components/esp_psram/esp32/esp_psram_impl_quad.c:304 (discriminator 17)

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1449) memory_layout: Examining memory region 0x40084000 - 0x40086000
0x40084000: psram_cmd_recv_start at C:/Users/Josh/esp/esp-idf/components/esp_psram/esp32/esp_psram_impl_quad.c:304 (discriminator 17)

0x40086000: spi_flash_disable_interrupts_caches_and_other_cpu at C:/Users/Josh/esp/esp-idf/components/spi_flash/cache_utils.c:157

V (1455) memory_layout: Region 0x40084000 - 0x40086000 inside of reserved 0x40080000 - 0x40093ba4
0x40084000: psram_cmd_recv_start at C:/Users/Josh/esp/esp-idf/components/esp_psram/esp32/esp_psram_impl_quad.c:304 (discriminator 17)

0x40086000: spi_flash_disable_interrupts_caches_and_other_cpu at C:/Users/Josh/esp/esp-idf/components/spi_flash/cache_utils.c:157

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1464) memory_layout: Examining memory region 0x40086000 - 0x40088000
0x40086000: spi_flash_disable_interrupts_caches_and_other_cpu at C:/Users/Josh/esp/esp-idf/components/spi_flash/cache_utils.c:157

0x40088000: __memcpy_aux at lib_a-memcpy.o:?

V (1471) memory_layout: Region 0x40086000 - 0x40088000 inside of reserved 0x40080000 - 0x40093ba4
0x40086000: spi_flash_disable_interrupts_caches_and_other_cpu at C:/Users/Josh/esp/esp-idf/components/spi_flash/cache_utils.c:157

0x40088000: __memcpy_aux at lib_a-memcpy.o:?

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1480) memory_layout: Examining memory region 0x40088000 - 0x4008a000
0x40088000: __memcpy_aux at lib_a-memcpy.o:?

0x4008a000: _tzset_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzset_r.c:230

V (1487) memory_layout: Region 0x40088000 - 0x4008a000 inside of reserved 0x40080000 - 0x40093ba4
0x40088000: __memcpy_aux at lib_a-memcpy.o:?

0x4008a000: _tzset_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzset_r.c:230

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1496) memory_layout: Examining memory region 0x4008a000 - 0x4008c000
0x4008a000: _tzset_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzset_r.c:230

0x4008c000: prvSendItemDoneNoSplit at C:/Users/Josh/esp/esp-idf/components/esp_ringbuf/ringbuf.c:415 (discriminator 1)

V (1502) memory_layout: Region 0x4008a000 - 0x4008c000 inside of reserved 0x40080000 - 0x40093ba4
0x4008a000: _tzset_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzset_r.c:230

0x4008c000: prvSendItemDoneNoSplit at C:/Users/Josh/esp/esp-idf/components/esp_ringbuf/ringbuf.c:415 (discriminator 1)

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1511) memory_layout: Examining memory region 0x4008c000 - 0x4008e000
0x4008c000: prvSendItemDoneNoSplit at C:/Users/Josh/esp/esp-idf/components/esp_ringbuf/ringbuf.c:415 (discriminator 1)

0x4008e000: taskSelectHighestPriorityTaskSMP at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:3558

V (1518) memory_layout: Region 0x4008c000 - 0x4008e000 inside of reserved 0x40080000 - 0x40093ba4
0x4008c000: prvSendItemDoneNoSplit at C:/Users/Josh/esp/esp-idf/components/esp_ringbuf/ringbuf.c:415 (discriminator 1)

0x4008e000: taskSelectHighestPriorityTaskSMP at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:3558

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1527) memory_layout: Examining memory region 0x4008e000 - 0x40090000
0x4008e000: taskSelectHighestPriorityTaskSMP at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:3558

0x40090000: vPortClearInterruptMaskFromISR at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:566
 (inlined by) xPortInIsrContext at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:281

V (1534) memory_layout: Region 0x4008e000 - 0x40090000 inside of reserved 0x40080000 - 0x40093ba4
0x4008e000: taskSelectHighestPriorityTaskSMP at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:3558

0x40090000: vPortClearInterruptMaskFromISR at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:566
 (inlined by) xPortInIsrContext at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:281

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1543) memory_layout: Examining memory region 0x40090000 - 0x40092000
0x40090000: vPortClearInterruptMaskFromISR at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:566
 (inlined by) xPortInIsrContext at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:281

0x40092000: mapping_insert at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:272
 (inlined by) block_remove at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:385
 (inlined by) block_merge_next at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:492
 (inlined by) tlsf_realloc at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:1115

V (1549) memory_layout: Region 0x40090000 - 0x40092000 inside of reserved 0x40080000 - 0x40093ba4
0x40090000: vPortClearInterruptMaskFromISR at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:566
 (inlined by) xPortInIsrContext at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:281

0x40092000: mapping_insert at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:272
 (inlined by) block_remove at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:385
 (inlined by) block_merge_next at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:492
 (inlined by) tlsf_realloc at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:1115

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

V (1558) memory_layout: Examining memory region 0x40092000 - 0x40094000
0x40092000: mapping_insert at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:272
 (inlined by) block_remove at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:385
 (inlined by) block_merge_next at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:492
 (inlined by) tlsf_realloc at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:1115

V (1565) memory_layout: Start of region 0x40092000 - 0x40094000 overlaps reserved 0x40080000 - 0x40093ba4
0x40092000: mapping_insert at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:272
 (inlined by) block_remove at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:385
 (inlined by) block_merge_next at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:492
 (inlined by) tlsf_realloc at C:/Users/Josh/esp/esp-idf/components/heap/tlsf/tlsf.c:1115

0x40080000: _WindowOverflow4 at C:/Users/Josh/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

D (1574) memory_layout: Available memory region 0x40093ba4 - 0x40094000
V (1581) memory_layout: Examining memory region 0x40094000 - 0x40096000
D (1588) memory_layout: Available memory region 0x40094000 - 0x40096000
V (1595) memory_layout: Examining memory region 0x40096000 - 0x40098000
D (1601) memory_layout: Available memory region 0x40096000 - 0x40098000
V (1608) memory_layout: Examining memory region 0x40098000 - 0x4009a000
D (1615) memory_layout: Available memory region 0x40098000 - 0x4009a000
V (1621) memory_layout: Examining memory region 0x4009a000 - 0x4009c000
D (1628) memory_layout: Available memory region 0x4009a000 - 0x4009c000
V (1635) memory_layout: Examining memory region 0x4009c000 - 0x4009e000
D (1641) memory_layout: Available memory region 0x4009c000 - 0x4009e000
V (1648) memory_layout: Examining memory region 0x4009e000 - 0x400a0000
D (1655) memory_layout: Available memory region 0x4009e000 - 0x400a0000
I (1661) heap_init: Initializing. RAM available for dynamic allocation:
D (1669) heap_init: New heap initialised at 0x3ffae6e0
I (1674) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (1680) heap_init: New heap initialised at 0x3ffb63a8
I (1685) heap_init: At 3FFB63A8 len 00029C58 (167 KiB): DRAM
I (1692) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1698) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (1705) heap_init: New heap initialised at 0x40093ba4
I (1710) heap_init: At 40093BA4 len 0000C45C (49 KiB): IRAM
I (1716) esp_psram: Adding pool of 4096K of PSRAM memory to heap allocator
V (1724) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1730) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1738) intr_alloc: Connected src 46 to int 2 (cpu 0)
V (1744) memspi: raw_chip_id: 184020

V (1747) memspi: chip_id: 204018

V (1751) memspi: raw_chip_id: 184020

V (1754) memspi: chip_id: 204018

D (1758) spi_flash: trying chip: issi
D (1762) spi_flash: trying chip: gd
D (1765) spi_flash: trying chip: mxic
D (1769) spi_flash: trying chip: winbond
D (1773) spi_flash: trying chip: generic
I (1777) spi_flash: detected chip: generic
I (1781) spi_flash: flash io: dio
D (1785) cpu_start: calling init function: 0x40154c0c
0x40154c0c: _GLOBAL__sub_I__ZNSt12ctype_bynameIwEC2ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEj at cxx11-wlocale-inst.cc:?

D (1790) cpu_start: calling init function: 0x401504bc
0x401504bc: _GLOBAL__sub_I__ZNSt12ctype_bynameIcEC2ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEj at cxx11-locale-inst.cc:?

D (1795) cpu_start: calling init function: 0x40147100
0x40147100: _GLOBAL__sub_I__ZNSt12ctype_bynameIwEC2ERKSsj at wlocale-inst.cc:?

D (1800) cpu_start: calling init function: 0x4013f7ac
0x4013f7ac: _GLOBAL__sub_I__ZNSt12ctype_bynameIcEC2ERKSsj at locale-inst.cc:?

D (1805) cpu_start: calling init function: 0x4013706c
0x4013706c: _GLOBAL__sub_I___cxa_get_globals_fast at eh_globals.cc:?

D (1810) cpu_start: calling init function: 0x40136e74
0x40136e74: _GLOBAL__sub_I__ZN9__gnu_cxx9__freeresEv at eh_alloc.cc:?

D (1815) cpu_start: calling init function: 0x400f318c
0x400f318c: esp_ipc_init at C:/Users/Josh/esp/esp-idf/components/esp_system/esp_ipc.c:115

D (1821) cpu_start: calling init function: 0x400ebf60
0x400ebf60: _GLOBAL__sub_I__ZN3idf5event21PLATFORM_MAX_DELAY_MSE at C:/Users/Josh/esp/esp-idf/examples/cxx/experimental/experimental_cpp_component/esp_event_cxx.cpp:224

V (1826) pthread: pthread_once: call init_routine 0x3ffb0880
V (1831) pthread: pthread_once: call init_routine 0x3ffb0878
D (1839) cpu_start: calling init function: 0x400eafb8
0x400eafb8: _GLOBAL__sub_I__ZN3idf5event18ESPEventAPIDefaultC2Ev at C:/Users/Josh/esp/esp-idf/examples/cxx/experimental/experimental_cpp_component/esp_event_api.cpp:113

D (1842) cpu_start: calling init function: 0x400de304
0x400de304: _GLOBAL__sub_I__ZN10MqttClientC2ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE at C:/Users/Josh/Git/esp-protocols/components/esp_modem/examples/simple_cmux_client/main/simple_mqtt_client.cpp:105

D (1847) cpu_start: calling init function: 0x400dd2fc
0x400dd2fc: _GLOBAL__sub_I_app_main at C:/Users/Josh/Git/esp-protocols/components/esp_modem/examples/simple_cmux_client/main/simple_cmux_client_main.cpp:256

D (1852) cpu_start: calling init function: 0x400d3968
0x400d3968: esp_reset_reason_init at C:/Users/Josh/esp/esp-idf/components/esp_system/port/soc/esp32/reset_reason.c:68

D (1857) cpu_start: calling init function: 0x400d29b0
0x400d29b0: esp_init_app_elf_sha256 at C:/Users/Josh/esp/esp-idf/components/esp_app_format/esp_app_desc.c:69

D (1862) cpu_start: calling init function: 0x400d6d9c on core: 0
0x400d6d9c: __esp_system_init_fn_esp_timer_startup_init at C:/Users/Josh/esp/esp-idf/components/esp_timer/src/esp_timer.c:464

V (1868) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1874) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC02
D (1883) intr_alloc: Connected src 17 to int 3 (cpu 0)
D (1888) cpu_start: calling init function: 0x400d3610 on core: 0
0x400d3610: __esp_system_init_fn_init_components0 at C:/Users/Josh/esp/esp-idf/components/esp_system/startup.c:477

D (1894) cpu_start: Setting C++ exception workarounds.
V (1899) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1905) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1914) intr_alloc: Connected src 24 to int 9 (cpu 0)
I (1919) cpu_start: Starting scheduler on PRO CPU.
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (10) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (10) cpu_start: Starting scheduler on APP CPU.
D (1969) heap_init: New heap initialised at 0x3ffe0440
D (1969) heap_init: New heap initialised at 0x3ffe4350
I (1979) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
D (1989) esp_psram: Allocating block of size 32768 bytes
V (1989) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1999) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (2009) intr_alloc: Connected src 16 to int 12 (cpu 0)
D (2009) event: running task for loop 0x3ffaffa8
D (2019) event: created task for loop 0x3ffaffa8
D (2019) event: created event loop 0x3ffaffa8
D (2029) esp_netif_lwip: LwIP stack has been initialized
D (2029) esp_netif_lwip: esp-netif has been successfully initialized
I (2039) uart: queue free spaces: 30
V (2039) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (2049) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (2059) intr_alloc: Connected src 35 to int 13 (cpu 0)
D (2059) esp_netif_objects: esp_netif_add_to_list 0x3ffc8608
D (2069) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
D (2079) esp-netif_lwip-ppp: esp_netif_new_ppp: PPP connection created: 0x3ffc8914
D (2079) esp-netif_lwip-ppp: Phase Dead
I (2089) cmux_example: not set_flow_control, because 2-wire mode active.
V (2099) command_lib: set_cmux
V (2099) command_lib: generic_command_common
V (2099) command_lib: generic_command
D (2109) command_lib: generic_command command AT+CMUX=0

D (2119) command_lib: Response: AT+CMUX=0
OK

E (3239) cmux_example: Failed to configure multiplexed command mode... exiting
V (3239) intr_alloc: esp_intr_free: Disabling int, killing handler
D (3239) event: deleted loop 0x3ffaffa8
david-cermak commented 1 year ago

@jgus The issue you referenced was fixed for SIM800 device which apparently send additional messages, that we misinterpreted as CMUX close. It's probably another failure you're seeing, maybe related to your device. I think I can get one SIM7000 and test the CMUX mode.

Anything I can add to help debug this issue, please let me know.

I can only suggest enabling verbose logging and sharing results, but see that the V level is included above, but don't see much. So unless you set the log level specifically via runtime API, we can assume that the transition fails early, when we're trying to setup virtual control terminal. In that case I would try to increase a delay between setting the CMUX mode by AT command and the actual CMUX protocol communication:

https://github.com/espressif/esp-protocols/blob/457f8335bb876b8af80a65b096e5381f49f29878/components/esp_modem/src/esp_modem_dce.cpp#L124-L125

Could you please increase the delay to say 500ms?

Another way to try to debug it is to run the console example and use the manual CMUX commands. We've recently introduced commands like CMUX1, CMUX2, CMUX3... CMUX5. So you can try to configure CMUX mode via AT command:

cmd AT+CMUX=0

and then set the manual CMUX transition

setmode CMUX1
david-cermak commented 1 year ago

I've tried to test CMUX mode with SIM7000 and couldn't get it to work, it replies with OK on AT+CMUX. but doesn't seem to switch to the multiplexed mode and doesn't respond to CMUX command any more.

I'll add a brief documentation about the known issues of certain devices, as we've already experienced some problems and limitations with some modems.

david-cermak commented 11 months ago

The note about this device has been added to the docs:

https://github.com/espressif/esp-protocols/blob/0c6bb4bedc98a82947fea28afb537d6bcf587919/docs/esp_modem/en/README.rst?plain=1#L199