esp-tls: [sock=54] select() timeout (IDFGH-10481)

Noushadalik commented 1 year ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

V4.4.1

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

CMD

Development Kit.

ESP32-WROOM-32D

Power Supply used.

External 3.3V

What is the expected behavior?

Publish a message by connecting MQTT clients seamlessly.

What is the actual behavior?

we have encountered while testing the Cavli C16QS GSM board with various network providers. Specifically,we have successfully tested the board with Jio and VI networks. However, When we are connecting MQTT clients experiencing intermittent TLS connectivity problems when using Airtel SIM cards, despite being able to establish a connection to the SNTP server without any issues ESP IDF error log mentioned below

E (29032) esp-tls: [sock=54] select() timeout E (29032) esp-tls: Failed to open new connection E (29032) TRANSPORT_BASE: Failed to open a new connection E (29032) MQTT_CLIENT: Error transport connect E (49262) MQTT: MQTT_EVENT_DISCONNECTED

Steps to reproduce.

Connect Cavli c16QS gsm board to esp32 and run ESP ppos example code.

Debug Logs.

verbose logs :

I (10) boot: ESP-IDF v4.4.1-dirty 2nd stage bootloader
I (10) boot: compile time 13:46:35
I (10) boot: chip revision: 1
I (12) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (19) boot.esp32: SPI Speed      : 80MHz
I (24) boot.esp32: SPI Mode       : DIO
I (28) boot.esp32: SPI Flash Size : 4MB
I (33) boot: Enabling RNG early entropy source...
I (38) boot: Partition Table:
I (42) boot: ## Label            Usage          Type ST Offset   Length
I (49) boot:  0 nvs              WiFi data        01 02 00009000 00005000
I (56) boot:  1 otadata          OTA data         01 00 0000e000 00002000
I (64) boot:  2 app0             OTA app          00 10 00010000 00100000
I (71) boot:  3 app1             OTA app          00 11 00110000 00100000
I (79) boot:  4 spiffs           Unknown data     01 82 00210000 001f0000
I (86) boot: End of partition table
I (90) boot_comm: chip revision: 1, min. application chip revision: 0
I (97) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=23310h (144144) map
I (150) esp_image: segment 1: paddr=00033338 vaddr=3ffbdb60 size=03788h ( 14216) load
I (155) esp_image: segment 2: paddr=00036ac8 vaddr=40080000 size=09550h ( 38224) load
I (169) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=72acch (469708) map
I (311) esp_image: segment 4: paddr=000b2af4 vaddr=40089550 size=03bfch ( 15356) load
I (317) esp_image: segment 5: paddr=000b66f8 vaddr=50000000 size=00010h (    16) load
I (324) boot: Loaded app from partition at offset 0x10000
I (324) boot: Disabling RNG early entropy source...
I (340) cpu_start: Pro cpu up.
D (340) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 15 bit
D (340) efuse: In EFUSE_BLK0__DATA5_REG is used 1 bits starting with 20 bit
D (346) efuse: In EFUSE_BLK0__DATA3_REG is used 3 bits starting with 9 bit
D (353) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 2 bit
I (360) cpu_start: Starting app cpu, entry point is 0x40081274
0x40081274: call_start_cpu1 at C:/Users/rhmna/esp/esp-idf/components/esp_system/port/cpu_start.c:160

I (0) cpu_start: App cpu up.
D (374) clk: RTC_SLOW_CLK calibration value: 3240832
I (387) cpu_start: Pro cpu start user code
I (387) cpu_start: cpu freq: 160000000
I (387) cpu_start: Application information:
I (391) cpu_start: Project name:     Bolt_4G
I (396) cpu_start: App version:      1
I (401) cpu_start: Compile time:     Jun 22 2023 14:55:00
I (407) cpu_start: ELF file SHA256:  63568e2ad9c86b91...
I (413) cpu_start: ESP-IDF:          v4.4.1-dirty
V (418) memory_layout: reserved range is 0x3f4232f8 - 0x3f423330
D (424) memory_layout: Checking 7 reserved memory ranges:
D (430) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
D (436) memory_layout: Reserved memory range 0x3ffbdb60 - 0x3ffc2d70
D (443) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
D (449) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350
D (456) memory_layout: Reserved memory range 0x40070000 - 0x40078000
D (462) memory_layout: Reserved memory range 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

D (468) memory_layout: Reserved memory range 0x40080000 - 0x4008d14c
0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

D (475) memory_layout: Building list of available memory regions:
V (481) memory_layout: Examining memory region 0x3ffae000 - 0x3ffb0000
V (488) memory_layout: Start of region 0x3ffae000 - 0x3ffb0000 overlaps reserved 0x3ffae000 - 0x3ffae6e0
D (497) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000
V (504) memory_layout: Examining memory region 0x3ffb0000 - 0x3ffb8000
D (510) memory_layout: Available memory region 0x3ffb0000 - 0x3ffb8000
V (517) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffc0000
V (523) memory_layout: End of region 0x3ffb8000 - 0x3ffc0000 overlaps reserved 0x3ffbdb60 - 0x3ffc2d70
D (533) memory_layout: Available memory region 0x3ffb8000 - 0x3ffbdb60
V (539) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc2000
V (546) memory_layout: Region 0x3ffc0000 - 0x3ffc2000 inside of reserved 0x3ffbdb60 - 0x3ffc2d70
V (555) memory_layout: Examining memory region 0x3ffc2000 - 0x3ffc4000
V (561) memory_layout: Start of region 0x3ffc2000 - 0x3ffc4000 overlaps reserved 0x3ffbdb60 - 0x3ffc2d70
D (571) memory_layout: Available memory region 0x3ffc2d70 - 0x3ffc4000
V (578) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc6000
D (584) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000
V (591) memory_layout: Examining memory region 0x3ffc6000 - 0x3ffc8000
D (597) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000
V (604) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffca000
D (611) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000
V (617) memory_layout: Examining memory region 0x3ffca000 - 0x3ffcc000
D (624) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000
V (630) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffce000
D (637) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000
V (644) memory_layout: Examining memory region 0x3ffce000 - 0x3ffd0000
D (650) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000
V (657) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd2000
D (663) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
V (670) memory_layout: Examining memory region 0x3ffd2000 - 0x3ffd4000
D (677) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
V (683) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd6000
D (690) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
V (696) memory_layout: Examining memory region 0x3ffd6000 - 0x3ffd8000
D (703) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
V (710) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffda000
D (716) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
V (723) memory_layout: Examining memory region 0x3ffda000 - 0x3ffdc000
D (729) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
V (736) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffde000
D (743) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
V (749) memory_layout: Examining memory region 0x3ffde000 - 0x3ffe0000
D (756) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
V (762) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000
V (769) memory_layout: Start of region 0x3ffe0000 - 0x3ffe4000 overlaps reserved 0x3ffe0000 - 0x3ffe0440
V (779) memory_layout: End of region 0x3ffe0440 - 0x3ffe4000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350
D (788) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20
V (794) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000
V (801) memory_layout: Start of region 0x3ffe4000 - 0x3ffe8000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350
D (811) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
V (817) memory_layout: Examining memory region 0x3ffe8000 - 0x3fff0000
D (824) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
V (830) memory_layout: Examining memory region 0x3fff0000 - 0x3fff8000
D (837) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
V (844) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000
D (850) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
V (857) memory_layout: Examining memory region 0x3fffc000 - 0x40000000
D (863) memory_layout: Available memory region 0x3fffc000 - 0x40000000
V (870) memory_layout: Examining memory region 0x40070000 - 0x40078000
V (877) memory_layout: Region 0x40070000 - 0x40078000 inside of reserved 0x40070000 - 0x40078000
V (885) memory_layout: Examining memory region 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (892) memory_layout: Region 0x40078000 - 0x40080000 inside of reserved 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (901) memory_layout: Examining memory region 0x40080000 - 0x40082000
0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

0x40082000: esp_timer_impl_set_alarm_id at C:/Users/rhmna/esp/esp-idf/components/esp_timer/src/esp_timer_impl_lac.c:163 (discriminator 1)

V (907) memory_layout: Region 0x40080000 - 0x40082000 inside of reserved 0x40080000 - 0x4008d14c
0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

0x40082000: esp_timer_impl_set_alarm_id at C:/Users/rhmna/esp/esp-idf/components/esp_timer/src/esp_timer_impl_lac.c:163 (discriminator 1)

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (916) memory_layout: Examining memory region 0x40082000 - 0x40084000
0x40082000: esp_timer_impl_set_alarm_id at C:/Users/rhmna/esp/esp-idf/components/esp_timer/src/esp_timer_impl_lac.c:163 (discriminator 1)

0x40084000: spi_flash_mmap_pages at C:/Users/rhmna/esp/esp-idf/components/spi_flash/flash_mmap.c:207 (discriminator 1)

V (923) memory_layout: Region 0x40082000 - 0x40084000 inside of reserved 0x40080000 - 0x4008d14c
0x40082000: esp_timer_impl_set_alarm_id at C:/Users/rhmna/esp/esp-idf/components/esp_timer/src/esp_timer_impl_lac.c:163 (discriminator 1)

0x40084000: spi_flash_mmap_pages at C:/Users/rhmna/esp/esp-idf/components/spi_flash/flash_mmap.c:207 (discriminator 1)

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (932) memory_layout: Examining memory region 0x40084000 - 0x40086000
0x40084000: spi_flash_mmap_pages at C:/Users/rhmna/esp/esp-idf/components/spi_flash/flash_mmap.c:207 (discriminator 1)

0x40086000: prvReceiveGeneric at C:/Users/rhmna/esp/esp-idf/components/esp_ringbuf/ringbuf.c:797

V (938) memory_layout: Region 0x40084000 - 0x40086000 inside of reserved 0x40080000 - 0x4008d14c
0x40084000: spi_flash_mmap_pages at C:/Users/rhmna/esp/esp-idf/components/spi_flash/flash_mmap.c:207 (discriminator 1)

0x40086000: prvReceiveGeneric at C:/Users/rhmna/esp/esp-idf/components/esp_ringbuf/ringbuf.c:797

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (947) memory_layout: Examining memory region 0x40086000 - 0x40088000
0x40086000: prvReceiveGeneric at C:/Users/rhmna/esp/esp-idf/components/esp_ringbuf/ringbuf.c:797

0x40088000: taskYIELD_OTHER_CORE at C:/Users/rhmna/esp/esp-idf/components/freertos/tasks.c:643

V (954) memory_layout: Region 0x40086000 - 0x40088000 inside of reserved 0x40080000 - 0x4008d14c
0x40086000: prvReceiveGeneric at C:/Users/rhmna/esp/esp-idf/components/esp_ringbuf/ringbuf.c:797

0x40088000: taskYIELD_OTHER_CORE at C:/Users/rhmna/esp/esp-idf/components/freertos/tasks.c:643

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (963) memory_layout: Examining memory region 0x40088000 - 0x4008a000
0x40088000: taskYIELD_OTHER_CORE at C:/Users/rhmna/esp/esp-idf/components/freertos/tasks.c:643

0x4008a000: spi_flash_ll_set_read_mode at C:/Users/rhmna/esp/esp-idf/components/hal/esp32/include/hal/spi_flash_ll.h:258
 (inlined by) spi_flash_hal_configure_host_io_mode at C:/Users/rhmna/esp/esp-idf/components/hal/spi_flash_hal_common.inc:128

V (969) memory_layout: Region 0x40088000 - 0x4008a000 inside of reserved 0x40080000 - 0x4008d14c
0x40088000: taskYIELD_OTHER_CORE at C:/Users/rhmna/esp/esp-idf/components/freertos/tasks.c:643

0x4008a000: spi_flash_ll_set_read_mode at C:/Users/rhmna/esp/esp-idf/components/hal/esp32/include/hal/spi_flash_ll.h:258
 (inlined by) spi_flash_hal_configure_host_io_mode at C:/Users/rhmna/esp/esp-idf/components/hal/spi_flash_hal_common.inc:128

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (978) memory_layout: Examining memory region 0x4008a000 - 0x4008c000
0x4008a000: spi_flash_ll_set_read_mode at C:/Users/rhmna/esp/esp-idf/components/hal/esp32/include/hal/spi_flash_ll.h:258
 (inlined by) spi_flash_hal_configure_host_io_mode at C:/Users/rhmna/esp/esp-idf/components/hal/spi_flash_hal_common.inc:128

0x4008c000: memspi_host_read_id_hs at C:/Users/rhmna/esp/esp-idf/components/spi_flash/memspi_host_driver.c:110 (discriminator 1)

V (985) memory_layout: Region 0x4008a000 - 0x4008c000 inside of reserved 0x40080000 - 0x4008d14c
0x4008a000: spi_flash_ll_set_read_mode at C:/Users/rhmna/esp/esp-idf/components/hal/esp32/include/hal/spi_flash_ll.h:258
 (inlined by) spi_flash_hal_configure_host_io_mode at C:/Users/rhmna/esp/esp-idf/components/hal/spi_flash_hal_common.inc:128

0x4008c000: memspi_host_read_id_hs at C:/Users/rhmna/esp/esp-idf/components/spi_flash/memspi_host_driver.c:110 (discriminator 1)

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (994) memory_layout: Examining memory region 0x4008c000 - 0x4008e000
0x4008c000: memspi_host_read_id_hs at C:/Users/rhmna/esp/esp-idf/components/spi_flash/memspi_host_driver.c:110 (discriminator 1)

V (1000) memory_layout: Start of region 0x4008c000 - 0x4008e000 overlaps reserved 0x40080000 - 0x4008d14c
0x4008c000: memspi_host_read_id_hs at C:/Users/rhmna/esp/esp-idf/components/spi_flash/memspi_host_driver.c:110 (discriminator 1)

0x40080000: _WindowOverflow4 at C:/Users/rhmna/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

D (1010) memory_layout: Available memory region 0x4008d14c - 0x4008e000
V (1017) memory_layout: Examining memory region 0x4008e000 - 0x40090000
D (1023) memory_layout: Available memory region 0x4008e000 - 0x40090000
V (1030) memory_layout: Examining memory region 0x40090000 - 0x40092000
D (1037) memory_layout: Available memory region 0x40090000 - 0x40092000
V (1043) memory_layout: Examining memory region 0x40092000 - 0x40094000
D (1050) memory_layout: Available memory region 0x40092000 - 0x40094000
V (1057) memory_layout: Examining memory region 0x40094000 - 0x40096000
D (1063) memory_layout: Available memory region 0x40094000 - 0x40096000
V (1070) memory_layout: Examining memory region 0x40096000 - 0x40098000
D (1077) memory_layout: Available memory region 0x40096000 - 0x40098000
V (1083) memory_layout: Examining memory region 0x40098000 - 0x4009a000
D (1090) memory_layout: Available memory region 0x40098000 - 0x4009a000
V (1097) memory_layout: Examining memory region 0x4009a000 - 0x4009c000
D (1103) memory_layout: Available memory region 0x4009a000 - 0x4009c000
V (1110) memory_layout: Examining memory region 0x4009c000 - 0x4009e000
D (1117) memory_layout: Available memory region 0x4009c000 - 0x4009e000
V (1123) memory_layout: Examining memory region 0x4009e000 - 0x400a0000
D (1130) memory_layout: Available memory region 0x4009e000 - 0x400a0000
I (1137) heap_init: Initializing. RAM available for dynamic allocation:
D (1144) heap_init: New heap initialised at 0x3ffae6e0
I (1149) heap_init: At 3FFAE6E0 len 0000F480 (61 KiB): DRAM
D (1156) heap_init: New heap initialised at 0x3ffc2d70
I (1161) heap_init: At 3FFC2D70 len 0001D290 (116 KiB): DRAM
I (1167) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1174) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (1180) heap_init: New heap initialised at 0x4008d14c
I (1185) heap_init: At 4008D14C len 00012EB4 (75 KiB): IRAM
V (1192) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1198) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1206) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (1212) FLASH_HAL: extra_dummy: 2
V (1215) memspi: raw_chip_id: 164068

V (1219) memspi: chip_id: 684016

V (1222) memspi: raw_chip_id: 164068

V (1226) memspi: chip_id: 684016

D (1229) spi_flash: trying chip: issi
D (1233) spi_flash: trying chip: gd
D (1237) spi_flash: trying chip: mxic
D (1240) spi_flash: trying chip: winbond
D (1244) spi_flash: trying chip: generic
I (1248) spi_flash: detected chip: generic
I (1253) spi_flash: flash io: dio
D (1257) cpu_start: calling init function: 0x4012b4b8
0x4012b4b8: _GLOBAL__sub_I___cxa_get_globals_fast at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:145

D (1262) cpu_start: calling init function: 0x400e5208
0x400e5208: s_set_default_wifi_log_level at C:/Users/rhmna/esp/esp-idf/components/esp_wifi/src/wifi_init.c:63

D (1267) cpu_start: calling init function: 0x400e1f14
0x400e1f14: esp_ipc_init at C:/Users/rhmna/esp/esp-idf/components/esp_ipc/src/esp_ipc.c:102

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

D (1278) cpu_start: calling init function: 0x400d3338
0x400d3338: esp_ota_init_app_elf_sha256 at C:/Users/rhmna/esp/esp-idf/components/app_update/esp_app_desc.c:68

V (1283) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1289) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC02
D (1297) intr_alloc: Connected src 17 to int 3 (cpu 0)
V (1303) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1309) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1317) intr_alloc: Connected src 24 to int 9 (cpu 0)
I (1322) 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 (1372) heap_init: New heap initialised at 0x3ffe0440
D (1372) heap_init: New heap initialised at 0x3ffe4350
V (1382) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1382) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1382) intr_alloc: Connected src 16 to int 12 (cpu 0)
D (1402) esp_netif_lwip: LwIP stack has been initialized
D (1412) esp_netif_lwip: esp-netif has been successfully initialized
D (1412) esp_netif_lwip: esp-netif has been successfully initialized
D (1422) event: running task for loop 0x3ffb4778
D (1422) event: created task for loop 0x3ffb4778
D (1432) event: created event loop 0x3ffb4778
I (1432) GSM_C16QS: UART_1 initializing at 115200 Baudrate........
I (1442) uart: queue free spaces: 30
V (1442) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1442) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1442) intr_alloc: Connected src 35 to int 13 (cpu 0)
D (1462) event: created event loop 0x3ffb664c
D (1472) esp_netif_objects: esp_netif_add_to_list 0x3ffb7a6c
D (1472) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
D (1482) esp-netif_lwip-ppp: esp_netif_new_ppp: PPP connection created: 0x3ffb7d9c
I (1492) GSM_C16QS: Waiting for modem to sync..
I (1492) GSM_C16QS: GSM POWER Off !!
I (5502) GSM_C16QS: GSM POWER ON !!
D (5552) esp-modem: Ignore UART event for DTE with no DCE attached
D (5992) esp-modem: Ignore UART event for DTE with no DCE attached
D (6462) esp-modem: Ignore UART event for DTE with no DCE attached
D (6472) esp-modem: Ignore UART event for DTE with no DCE attached
D (7002) esp-modem: Sending command:AT
V (7002) esp-modem: uart_get_buffered_data_len()=6
V (7002) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (7002) esp-modem: Handling line: >>OK
<<
D (7012) dce_service: sync ok
D (7012) esp-modem: Sending command:AT+CREG=2
V (7022) esp-modem: uart_get_buffered_data_len()=6
V (7022) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (7032) esp-modem: Handling line: >>OK
<<
D (7032) dce_service: registration ok
D (7042) esp-modem: Sending command:ATE0
V (7042) esp-modem: uart_get_buffered_data_len()=6
V (7052) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (7062) esp-modem: Handling line: >>OK
<<
D (7062) dce_service: disable echo ok
D (7062) esp-modem: Sending command:AT+CGMM
V (7072) esp-modem: uart_get_buffered_data_len()=16
V (7072) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 2b 43 47 4d 4d 3a  20 43 31 36 51 53 0d 0a  |..+CGMM: C16QS..|
D (7092) esp-modem: Handling line: >>+CGMM: C16QS
<<
V (7092) esp-modem: uart_get_buffered_data_len()=6
V (7102) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (7112) esp-modem: Handling line: >>OK
<<
D (7112) dce_service: get module name ok
D (7112) esp-modem: Sending command:AT+CGSN
V (7122) esp-modem: uart_get_buffered_data_len()=13
V (7122) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 51 43 4c 43 31 31  31 35 53 0d 0a           |..QCLC1115S..|
D (7132) esp-modem: Handling line: >>QCLC1115S
<<
V (7142) esp-modem: uart_get_buffered_data_len()=6
V (7142) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (7152) esp-modem: Handling line: >>OK
<<
D (7162) dce_service: get imei number ok
D (7162) esp-modem: Sending command:AT+CIMI
V (7172) esp-modem: uart_get_buffered_data_len()=19
V (7172) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 34 30 34 39 35 30  39 38 32 35 37 37 30 35  |..40495098257705|
V (7182) esp-modem: pattern-detection: 0x3ffb57a4   38 0d 0a                                          |8..|
D (7192) esp-modem: Handling line: >>404950982577058
<<
V (7202) esp-modem: uart_get_buffered_data_len()=6
V (7202) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (7212) esp-modem: Handling line: >>OK
<<
D (7222) dce_service: get imsi number ok
V (7602) esp-modem: uart_get_buffered_data_len()=32
V (7602) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 2b 43 52 45 47 3a  20 31 2c 22 30 44 32 30  |..+CREG: 1,"0D20|
V (7612) esp-modem: pattern-detection: 0x3ffb57a4   22 2c 22 30 44 42 46 44  45 35 33 22 2c 37 0d 0a  |","0DBFDE53",7..|
D (12222) esp-modem: Sending command:AT+COPS?
V (12222) esp-modem: uart_get_buffered_data_len()=24
V (12222) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 2b 43 4f 50 53 3a  20 30 2c 32 2c 22 34 30  |..+COPS: 0,2,"40|
V (12232) esp-modem: pattern-detection: 0x3ffb57a4   34 39 35 22 2c 37 0d 0a                           |495",7..|
D (12242) esp-modem: Handling line: >>+COPS: 0,2,"40495",7
<<
V (12242) esp-modem: uart_get_buffered_data_len()=6
V (12252) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (12262) esp-modem: Handling line: >>OK
<<
D (12262) dce_service: get network operator ok
D (12272) esp-modem: Sending command:AT+CFUN=1
V (12282) esp-modem: uart_get_buffered_data_len()=6
V (12282) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (12292) esp-modem: Handling line: >>OK
<<
D (12292) dce_service: full function ok
I (12302) GSM_C16QS: GSM modem sync successful...
D (12302) esp-modem: Sending command:AT+IFC=0,0
V (12312) esp-modem: uart_get_buffered_data_len()=6
V (12312) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (12322) esp-modem: Handling line: >>OK
<<
D (12332) dce_service: set flow control ok
D (12332) esp-modem: Sending command:AT&W
V (12342) esp-modem: uart_get_buffered_data_len()=6
V (12342) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (12352) esp-modem: Handling line: >>OK
<<
D (12352) dce_service: save settings ok
I (12362) GSM_C16QS: Module: +CGMM: C16QS
I (12362) GSM_C16QS: Operator: "40495"
I (12372) GSM_C16QS: IMEI: QCLC1115S
I (12372) GSM_C16QS: IMSI: 404950982577058
D (12372) esp-modem: Sending command:AT+CSQ
V (12382) esp-modem: uart_get_buffered_data_len()=14
V (12382) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 2b 43 53 51 3a 20  33 31 2c 30 0d 0a        |..+CSQ: 31,0..|
D (12402) esp-modem: Handling line: >>+CSQ: 31,0
<<
V (12402) esp-modem: uart_get_buffered_data_len()=6
V (12412) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (12422) esp-modem: Handling line: >>OK
<<
D (12422) dce_service: inquire signal quality ok
I (12422) GSM_C16QS: rssi: 31, ber: 0
D (12432) esp-modem: Sending command:AT+CGDCONT=1,"IP","airtelgprs.com"
V (12442) esp-modem: uart_get_buffered_data_len()=6
V (12442) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (12452) esp-modem: Handling line: >>OK
<<
D (12462) dce_service: define pdp context ok
D (12462) esp-modem: Sending command:ATD*99***1#
V (12472) esp-modem: uart_get_buffered_data_len()=11
V (12472) esp-modem: pattern-detection: 0x3ffb5794   0d 0a 43 4f 4e 4e 45 43  54 0d 0a                 |..CONNECT..|
D (12482) esp-modem: Handling line: >>CONNECT
<<
D (12482) GSM_C16QS: enter ppp mode ok
D (12582) event: running post ESP_MODEM_EVENT:0 with handler 0x400dc6e8 and context 0x3ffb7a4c on loop 0x3ffb664c
0x400dc6e8: modem_event_handler at C:\Users\rhmna\Bolt_4G_module_V2\build/../main/C16QS.c:67

I (12582) GSM_C16QS: Modem PPP Started
D (12582) event: running post ESP_MODEM_EVENT:0 with handler 0x400e300c and context 0x3ffb908c on loop 0x3ffb664c
0x400e300c: esp_netif_action_start at C:/Users/rhmna/esp/esp-idf/components/esp_netif/esp_netif_handlers.c:32

D (12592) esp_netif_handlers: esp_netif action has started with netif0x3ffb7a6c from event_id=0
D (12602) esp-netif_lwip-ppp: esp_netif_start_ppp: Starting PPP connection: 0x3ffb7d9c
D (12612) esp_netif_lwip: check: remote, if=0x3ffb7a6c fn=0x400e43dc
0x400e43dc: esp_netif_update_default_netif_lwip at C:/Users/rhmna/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:188

D (12612) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffb7a6c
V (12622) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffb7a6c
D (12632) esp_netif_lwip: call api in lwip: ret=0x0, give sem
V (12632) esp-modem: uart_get_buffered_data_len()=92
V (12642) esp-modem: uart_get_buffered_data_len()=0
V (12642) esp-modem: uart_get_buffered_data_len()=0
V (12652) esp-modem: uart_get_buffered_data_len()=0
V (12652) esp-modem: uart_get_buffered_data_len()=28
V (12662) esp-modem: uart_get_buffered_data_len()=42
I (12662) esp-netif_lwip-ppp: Connected
V (12672) esp-modem: uart_get_buffered_data_len()=11
I (12672) esp-netif_lwip-ppp: Got IPv6 address fe80:0000:0000:0000:3055:8508:77de:4be0
V (12682) esp-modem: uart_get_buffered_data_len()=29
D (12682) event: running post IP_EVENT:3 with handler 0x400dc748 and context 0x3ffb56c8 on loop 0x3ffb4778
0x400dc748: on_ip_event at C:\Users\rhmna\Bolt_4G_module_V2\build/../main/C16QS.c:101

V (12692) esp-modem: uart_get_buffered_data_len()=0
D (12692) GSM_C16QS: IP event! 3
V (12702) esp-modem: uart_get_buffered_data_len()=29
I (12702) GSM_C16QS: GOT IPv6 event!
I (12712) esp-netif_lwip-ppp: Connected
I (12712) GSM_C16QS: Got IPv6 address fe80:0000:0000:0000:3055:8508:77de:4be0
I (12722) esp-netif_lwip-ppp: Name Server1: 117.96.122.44
V (12712) esp-modem: uart_get_buffered_data_len()=0
I (12732) esp-netif_lwip-ppp: Name Server2: 203.145.160.7
D (12742) event: running post IP_EVENT:6 with handler 0x400dc748 and context 0x3ffb56c8 on loop 0x3ffb4778
0x400dc748: on_ip_event at C:\Users\rhmna\Bolt_4G_module_V2\build/../main/C16QS.c:101

D (12752) GSM_C16QS: IP event! 6
I (12752) GSM_C16QS: Modem Connect to PPP Server
I (12762) GSM_C16QS: ~~~~~~~~~~~~~~
I (12762) GSM_C16QS: IP          : 100.94.102.240
I (12772) GSM_C16QS: Netmask     : 255.255.255.255
I (12772) GSM_C16QS: Gateway     : 10.64.64.64
I (12782) GSM_C16QS: Name Server1: 117.96.122.44
I (12792) GSM_C16QS: Name Server2: 203.145.160.7
I (12792) GSM_C16QS: ~~~~~~~~~~~~~~
I (12792) GSM_C16QS: GOT ip event!!!
D (12802) event: running post IP_EVENT:6 with handler 0x400e3054 and context 0x3ffb90ec on loop 0x3ffb4778
0x400e3054: esp_netif_action_connected at C:/Users/rhmna/esp/esp-idf/components/esp_netif/esp_netif_handlers.c:44

D (12812) esp_netif_handlers: esp_netif action connected with netif0x3ffb7a6c from event_id=6
D (12822) esp_netif_lwip: check: remote, if=0x3ffb7a6c fn=0x400e3d20
0x400e3d20: esp_netif_up_api at C:/Users/rhmna/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1256

D (12822) esp_netif_lwip: esp_netif_up_api esp_netif:0x3ffb7a6c
Waiting for system time to be set... (1/10)
D (12832) esp_netif_lwip: check: local, if=0x3ffb7a6c fn=0x400e43dc
0x400e43dc: esp_netif_update_default_netif_lwip at C:/Users/rhmna/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:188

D (12842) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffb7a6c
V (12852) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffb7a6c
D (12852) esp_netif_lwip: call api in lwip: ret=0x0, give sem
V (14552) esp-modem: uart_get_buffered_data_len()=1
V (14552) esp-modem: uart_get_buffered_data_len()=64
V (14562) esp-modem: uart_get_buffered_data_len()=64
V (14562) esp-modem: uart_get_buffered_data_len()=1
V (14632) esp-modem: uart_get_buffered_data_len()=64
V (14642) esp-modem: uart_get_buffered_data_len()=19
System time set successfully
Current time: Thu Jun 22 11:28:21 2023
I (14862) MQTT: MQTT initialising
D (14862) MQTT_CLIENT: MQTT client_id=adapter3_test
D (14862) event: created event loop 0x3ffb98ac
D (14862) MQTT_CLIENT: Core selection disabled
I (14872) MQTT_MESSAGE: {"DeviceId":"adapter3_test","EnclosureTemp":200}
I (14872) MQTT: MQTT other event id: 7
D (14882) esp-tls: host:onesensetestnewhub.azure-devices.net: strlen 36
V (14992) esp-modem: uart_get_buffered_data_len()=1
V (14992) esp-modem: uart_get_buffered_data_len()=64
V (15002) esp-modem: uart_get_buffered_data_len()=64
V (15002) esp-modem: uart_get_buffered_data_len()=44
D (15002) esp-tls: [sock=54] Resolved IPv4 address: 20.37.199.0
D (15012) esp-tls: [sock=54] Connecting to server. HOST: onesensetestnewhub.azure-devices.net, Port: 8883
E (25022) esp-tls: [sock=54] select() timeout
E (25022) esp-tls: Failed to open new connection
E (25022) TRANSPORT_BASE: Failed to open a new connection
E (25022) MQTT_CLIENT: Error transport connect
I (25032) MQTT: MQTT_EVENT_ERROR
D (25032) MQTT_CLIENT: Reconnect after 10000 ms
E (25032) MQTT: MQTT_EVENT_DISCONNECTED
D (25042) MQTT_CLIENT: mqtt_enqueue id: 55933, type=3 successful
D (25042) OUTBOX: ENQUEUE msgid=55933, msg_type=3, len=145, size=145
D (25052) MQTT_CLIENT: Publish: client is not connected
D (35042) MQTT_CLIENT: Reconnecting...
I (35042) MQTT: MQTT other event id: 7
D (35042) esp-tls: host:onesensetestnewhub.azure-devices.net: strlen 36
V (35232) esp-modem: uart_get_buffered_data_len()=1
V (35232) esp-modem: uart_get_buffered_data_len()=64
V (35242) esp-modem: uart_get_buffered_data_len()=64
V (35242) esp-modem: uart_get_buffered_data_len()=44
D (35242) esp-tls: [sock=54] Resolved IPv4 address: 20.37.199.0
D (35242) esp-tls: [sock=54] Connecting to server. HOST: onesensetestnewhub.azure-devices.net, Port: 8883
E (45252) esp-tls: [sock=54] select() timeout
E (45252) esp-tls: Failed to open new connection
E (45252) TRANSPORT_BASE: Failed to open a new connection
E (45252) MQTT_CLIENT: Error transport connect
I (45262) MQTT: MQTT_EVENT_ERROR
D (45262) MQTT_CLIENT: Reconnect after 10000 ms
E (45262) MQTT: MQTT_EVENT_DISCONNECTED

More Information.

No response

ESP-YJM commented 1 year ago

@Noushadalik It seems the TCP connect fail. It seems the TCP SYN packet not successfully sent to esp_modem. It may not find a suitable router or netif to send the SYN packet.

I think you can enable lwip log. Such as LWIP_TCP_DEBUG, LWIP_IP_DEBUG, LWIP_NETIF_DEBUG and share the log.

TAMILOLI commented 1 year ago

@ESP-YJM Same Issues will return to me; I can shared here my LWIP log information; IDF version : 4.4

This code run it 2 weeks before just now this issues happened? please suggest solution.

I (0) cpu_start: App cpu up. I (357) cpu_start: Pro cpu start user code I (357) cpu_start: cpu freq: 240000000 I (357) cpu_start: Application information: I (362) cpu_start: Project name: app_project I (367) cpu_start: App version: 1 I (372) cpu_start: Compile time: Jul 17 2023 19:15:29 I (378) cpu_start: ELF file SHA256: dfe2a91043b8e219... I (384) cpu_start: ESP-IDF: v4.4.4-dirty I (389) heap_init: Initializing. RAM available for dynamic allocation: I (396) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (402) heap_init: At 3FFB4A38 len 0002B5C8 (173 KiB): DRAM I (409) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (415) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (421) heap_init: At 4008E01C len 00011FE4 (71 KiB): IRAM I (429) spi_flash: detected chip: generic I (432) spi_flash: flash io: dio I (437) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (476) GSM: Module GSM un-powered I (977) GSM: Module GSM powered I (1477) GSM: Module GSM PWKEY LOW I (2577) GSM: Module GSM PWKEY HIGH netif: netmask of interface set to 255.0.0.0 netif: GW address of interface set to 127.0.0.1 netif_set_ipaddr: netif address being changed netif: added interface lo IP addr 127.0.0.1 netmask 255.0.0.0 gw 127.0.0.1 I (12587) GSM: STATE GSM_STATE_FIRSTINIT I (12691) GSM: AT COMMAND: [AT..] I (12894) GSM: AT RESPONSE: [..OK..] I (12994) GSM: AT COMMAND: [ATZ..] I (13197) GSM: AT RESPONSE: [..OK..] I (13297) GSM: AT COMMAND: [ATE0..] I (13500) GSM: AT RESPONSE: [..OK..] I (13600) GSM: AT COMMAND: [AT+CFUN=4..] I (16261) GSM: AT RESPONSE: [..OK..] I (17361) GSM: AT COMMAND: [ATH..] I (17564) GSM: AT RESPONSE: [..OK..] I (17664) GSM: AT COMMAND: [AT+CFUN=1..] I (17871) GSM: AT RESPONSE: [..OK..] I (18971) GSM: AT COMMAND: [AT+CPIN?..] I (19365) GSM: AT RESPONSE: [..+CPIN: READY....OK....SMS Ready..] I (19465) GSM: AT COMMAND: [AT+CREG?..] E (34569) GSM: AT: TIMEOUT W (34569) GSM: Wrong response, restarting... I (37569) GSM: Skip command: [AT..] I (37569) GSM: Skip command: [ATZ..] I (37569) GSM: Skip command: [ATE0..] I (37570) GSM: Skip command: [AT+CFUN=4..] I (37575) GSM: Skip command: [ATH..] I (37579) GSM: Skip command: [AT+CFUN=1..] I (37584) GSM: Skip command: [AT+CPIN?..] I (37689) GSM: AT COMMAND: [AT+CREG?..] I (37894) GSM: AT RESPONSE: [..+CREG: 0,1....OK..] I (39994) GSM: AT COMMAND: [AT+CGDCONT=1,"IP","airtelgprs.com"..] I (40203) GSM: AT RESPONSE: [..OK..] I (40303) GSM: AT COMMAND: [AT+CGDATA="PPP",1..] I (40508) GSM: AT RESPONSE: [..CONNECT..] E (41508) GSM: inicializando PPPoS... netif: netmask of interface set to 255.255.255.255 netif: added interface pp IP addr 0.0.0.0 netmask 255.255.255.255 gw 0.0.0.0 netif: setting default interface pp netif: GW address of interface pp set to 192.168.254.254 netif_set_ipaddr: netif address being changed I (44700) GSM: status_cb: Connected I (44702) GSM: ipaddr = 100.109.13.253 I (44707) GSM: gateway = 192.168.254.254 I (44712) GSM: netmask = 255.255.255.255 I (44717) GSM: ip6addr = :: I (44722) system_api: Base MAC address is not set I (44727) system_api: read default base MAC address from EFUSE I (44735) main: : MQTT_EVENT_BEFORE_CONNECT Screenshot from 2023-07-17 19-43-57

ESP-YJM commented 1 year ago

@TAMILOLI It seems the TCP SYN is no response. Could you confirm that the PPPoS module is access to Internet. Besides, you can ping your PPP IP to check the PPP connection is OK.

TAMILOLI commented 1 year ago

@TAMILOLI It seems the TCP SYN is no response. Could you confirm that the PPPoS module is access to Internet. Besides, you can ping your PPP IP to check the PPP connection is OK.

Yes correct, it's my internet data issues now it's working.. Thank you...

Alvin1Zhang commented 1 year ago

Thanks for reporting and sharing the updates, feel free to reopen.

wenjiaxing974959 commented 10 months ago

怎么解决的，我现在也是遇到的同样的问题，esp-tls: [sock=54] select() timeout；TRANSPORT_BASE: Failed to open a new connection: 32774；log和上述是一致的

ESP-YJM commented 10 months ago

这个错误的原因是 TCP SYN 包没有人回，所以你需要确认下服务器是否有问题，设备发的 TCP SYN 包是否发送成功，是否发送正确。

wenjiaxing974959 commented 10 months ago

怎么查看这个设备发的 TCP SYN 包呢

ESP-YJM commented 10 months ago

抓包或者打开 lwip 层 TCP 相关的日志。

vitara-campbell commented 3 months ago

@TAMILOLI It seems the TCP SYN is no response. Could you confirm that the PPPoS module is access to Internet. Besides, you can ping your PPP IP to check the PPP connection is OK.

How is the PPPoS module accessed in the menuconfig?

espressif / esp-idf