esp_mqtt halts the system when Wifi network shuts down (IDFGH-1485)

[ghost]

Environment

• Development Kit: ESP-32 Reltec
• IDF version
  v4.0-dev-1191-g138c941fa
• Build System: MAKE
• Compiler version
  xtensa-esp32-elf-gcc (crosstool-NG esp32-2019r1) 8.2.0
• Operating System: Windows
• Power Supply: USB

Problem Description

Im developing a application for esp32 using ESP-IDF for about 1 year. Last week I've noticed a problem that started happening. When connected through MQTT (using esp-mqtt with auto_reconnect e clean session), the esp-32 HALTS when Wifi network shuts down. It didn't happen before and I know that 'cause I've always tested this scenario.

Reproduce

To reproduce its quite easy: Just connect to any MQTT Server (without SSL), start sending messages (Im using qos=0) and then shut down your wifi-network. You will get the follow logs and then HALT:

E (326934) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=113
E (326944) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1

Debug Logs

352 asm volatile (
(gdb) bt
#0 uxPortCompareSet (set=, compare=3007315967, addr=0x3ffbdafc) at /mnt/c/esp/esp-idf/components/freertos/include/freertos/portmacro.h:352
#1 vPortCPUAcquireMutexIntsDisabledInternal (timeout_cycles=-1, mux=0x3ffbdafc) at /mnt/c/esp/esp-idf/components/freertos/portmux_impl.inc.h:86
#2 vPortCPUAcquireMutexIntsDisabled (timeout_cycles=-1, mux=0x3ffbdafc) at /mnt/c/esp/esp-idf/components/freertos/portmux_impl.h:99
#3 vTaskEnterCritical (mux=0x3ffbdafc) at /mnt/c/esp/esp-idf/components/freertos/tasks.c:4201
#4 0x4009011e in xQueueGenericSend (xQueue=0x3ffbdab4, pvItemToQueue=0x0, xTicksToWait=, xCopyPosition=0) at /mnt/c/esp/esp-idf/components/freertos/queue.c:740
#5 0x40090268 in xQueueGiveMutexRecursive (xMutex=0x3ffbdab4) at /mnt/c/esp/esp-idf/components/freertos/queue.c:590
#6 0x40082ac1 in lock_release_generic (lock=, mutex_type=4 '\004') at /mnt/c/esp/esp-idf/components/newlib/locks.c:205
#7 0x40082b94 in _lock_release_recursive (lock=0x3ffb13ac <s_context+12>) at /mnt/c/esp/esp-idf/components/newlib/locks.c:217
#8 0x400ef3e8 in uart_write (fd=, data=, size=92) at /mnt/c/esp/esp-idf/components/vfs/vfs_uart.c:205
#9 0x400efa1c in esp_vfs_write (r=, fd=, data=0x3ffbae7c, size=92) at /mnt/c/esp/esp-idf/components/vfs/vfs.c:420
#10 0x4000bd86 in ?? ()
#11 0x40001180 in ?? ()
#12 0x40059301 in ?? ()
#13 0x4005937d in ?? ()
#14 0x40058bc2 in ?? ()
#15 0x400dbc52 in __sprint_r (ptr=0x3ffc312c, fp=0x3ffae918, uio=0x3ffd6954) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:433
#16 0x400e11f2 in _vfprintf_r (data=, fp=, fmt0=, ap=...) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:1781
#17 0x400e1354 in vprintf (fmt=0x3f41e574 "\033[0;31mE (%d) %s: %s: mqtt_message_receive() returned %d\033[0m\n", ap=...) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vprintf.c:34
#18 0x400828d4 in esp_log_write (level=, tag=, format=0x3f41e574 "\033[0;31mE (%d) %s: %s: mqtt_message_receive() returned %d\033[0m\n") at /mnt/c/esp/esp-idf/components/log/log.c:217
#19 0x401451ac in mqtt_process_receive (client=0x3ffbe8fc) at /mnt/c/esp/esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:844
#20 0x401454fb in esp_mqtt_task (pv=0x3ffbe8fc) at /mnt/c/esp/esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:1008
#21 0x400906bc in vPortTaskWrapper (pxCode=0x401453b4 <esp_mqtt_task>, pvParameters=0x3ffbe8fc) at /mnt/c/esp/esp-idf/components/freertos/port.c:143

Could anyone help me figure out whats happening? I really appreciate it.

Thanks.

[david-cermak]

Thanks for reporting this issue and putting all the related details with debug logs.
I cannot reproduce the issue though, must be missing something. Could you please post your sdkconfig?
Is this reproducible also with some reduced project, eg. with simple IDF example?

Looks like a deadlock from the backtrace; it wait to release a lock in logging library in ESP_LOGI(),
cannot think of any reason other than obvious submodules out of sync or some nasty memory corruption causing this.
I wonder what would happen if you commented out the log line, would it lock up somewhere else?

[ghost]

Hi,

Thanks for the feedback. I've commented out that line and the error appears in somewhere else, so you're right. I found some issues in my own code and prevented that from happening (for now). So I think I will close this issue. Thanks again!

[thisdream]

@casmeiron ,hello man ,i also meet this problom,Can your teach me how to deal with it. thank your