mutex assert triggering (IDFGH-7923) #9441

KaeLL · 2022-07-26T23:28:49Z

Environment

Module or chip used: ESP32
IDF version: 36f49f3
Compiler version: crosstool-NG esp-2022r1-RC1

Problem Description

I'm updating a test app of mine to latest IDF, and the assert checking if a mutex is being released by a different thread keeps triggering. Worth noting that it's very hard to reproduce, but when it happens, it's always after the MQTT log (shown below).

Debug Logs

Log

I (20:03:20.314) MQTTS_EXAMPLE: [APP] Free memory: 261568 bytes

assert failed: xQueueGenericSend queue.c:837 (pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle())


Backtrace: 0x40081cb2:0x3ffbd6a0 0x40085c09:0x3ffbd6c0 0x4008bb5d:0x3ffbd6e0 0x400864f8:0x3ffbd800 0x40082b69:0x3ffbd840 0x40082c19:0x3ffbd870 0x40082c8a:0x3ffbd890 0x4012551d:0x3ffbd8c0 0x40121414:0x3ffbd8e0 0x401352f4:0x3ffbd900 0x40104422:0x3ffbd970 0x4010499b:0x3ffbd9a0 0x400d8cbc:0x3ffbd9c0 0x400d9beb:0x3ffbe280 0x40088cda:0x3ffbe2a0
0x40081cb2: panic_abort at /esp-idf/components/esp_system/panic.c:409

0x40085c09: esp_system_abort at /esp-idf/components/esp_system/esp_system.c:135

0x4008bb5d: __assert_func at /esp-idf/components/newlib/assert.c:78

0x400864f8: xQueueGenericSend at /esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:837 (discriminator 8)

0x40082b69: lock_release_generic at /esp-idf/components/newlib/locks.c:192

0x40082c19: _lock_release at /esp-idf/components/newlib/locks.c:198

0x40082c8a: __retarget_lock_release at /esp-idf/components/newlib/locks.c:334

0x4012551d: __tz_unlock at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50

0x40121414: localtime_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123

0x401352f4: esp_log_system_timestamp at /esp-idf/components/log/log_freertos.c:84

0x40104422: esp_http_client_connect at /esp-idf/components/esp_http_client/esp_http_client.c:1262 (discriminator 9)

0x4010499b: esp_http_client_perform at /esp-idf/components/esp_http_client/esp_http_client.c:1121

0x400d8cbc: http_rest_with_url at /ESP32-W5100/components/ex_esp_http_client/esp_http_client_example.c:155

0x400d9beb: http_test_task at /ESP32-W5100/components/ex_esp_http_client/esp_http_client_example.c:871

0x40088cda: vPortTaskWrapper at /esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:150

Other items if possible

defconfig

# This file was generated using idf.py save-defconfig. It can be edited manually.
# Espressif IoT Development Framework (ESP-IDF) Project Minimal Configuration
#
CONFIG_APP_NO_BLOBS=y
CONFIG_BOOTLOADER_COMPILER_OPTIMIZATION_PERF=y
CONFIG_BOOTLOADER_LOG_LEVEL_NONE=y
CONFIG_BOOTLOADER_SKIP_VALIDATE_ALWAYS=y
CONFIG_ESPTOOLPY_FLASHMODE_QIO=y
CONFIG_ESPTOOLPY_FLASHFREQ_80M=y
CONFIG_ESPTOOLPY_FLASHSIZE_4MB=y
CONFIG_ESPTOOLPY_AFTER_NORESET=y
CONFIG_TZ_ENV="BRT+3"
CONFIG_COMPILER_WARN_WRITE_STRINGS=y
# CONFIG_SPI_MASTER_ISR_IN_IRAM is not set
# CONFIG_SPI_SLAVE_ISR_IN_IRAM is not set
# CONFIG_ETH_USE_SPI_ETHERNET is not set
CONFIG_ESP_HTTP_CLIENT_ENABLE_BASIC_AUTH=y
CONFIG_ESP_HTTP_CLIENT_ENABLE_DIGEST_AUTH=y
CONFIG_ESP32_REV_MIN_1=y
# CONFIG_ESP_PHY_CALIBRATION_AND_DATA_STORAGE is not set
CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ_240=y
CONFIG_ESP_SYSTEM_PANIC_PRINT_HALT=y
CONFIG_ESP_CONSOLE_UART_CUSTOM=y
CONFIG_ESP_CONSOLE_UART_BAUDRATE=921600
CONFIG_ESP_INT_WDT_TIMEOUT_MS=20
CONFIG_ESP_TASK_WDT_PANIC=y
CONFIG_ESP_TASK_WDT_TIMEOUT_S=2
CONFIG_ESP_SYSTEM_CHECK_INT_LEVEL_5=y
# CONFIG_ESP32_WIFI_NVS_ENABLED is not set
CONFIG_ESP_COREDUMP_ENABLE_TO_UART=y
CONFIG_ESP_COREDUMP_MAX_TASKS_NUM=20
CONFIG_ESP_COREDUMP_STACK_SIZE=1024
CONFIG_FREERTOS_HZ=1000
CONFIG_FREERTOS_CHECK_STACKOVERFLOW_NONE=y
CONFIG_FREERTOS_CORETIMER_1=y
CONFIG_HEAP_ABORT_WHEN_ALLOCATION_FAILS=y
CONFIG_LOG_DEFAULT_LEVEL_DEBUG=y
CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y
CONFIG_MBEDTLS_TLS_CLIENT_ONLY=y
# CONFIG_MQTT_TRANSPORT_WEBSOCKET is not set
CONFIG_MQTT_SKIP_PUBLISH_IF_DISCONNECTED=y
CONFIG_MQTT_REPORT_DELETED_MESSAGES=y

The text was updated successfully, but these errors were encountered:

Removed double quotes from CMakeLists.txt files as they seem to not be needed. Updated the mqtt and esp_http_client examples. Removed make build system files. Remade the sdkconfig file. Tracking espressif/esp-idf#9441

KaeLL · 2022-07-27T21:45:18Z

Managed to reproduce it pretty consistently with these settings:

defconfig

# This file was generated using idf.py save-defconfig. It can be edited manually.
# Espressif IoT Development Framework (ESP-IDF) Project Minimal Configuration
#
CONFIG_APP_NO_BLOBS=y
CONFIG_BOOTLOADER_COMPILER_OPTIMIZATION_PERF=y
CONFIG_BOOTLOADER_LOG_LEVEL_NONE=y
CONFIG_BOOTLOADER_SKIP_VALIDATE_ALWAYS=y
CONFIG_ESPTOOLPY_FLASHMODE_QIO=y
CONFIG_ESPTOOLPY_FLASHFREQ_80M=y
CONFIG_ESPTOOLPY_FLASHSIZE_4MB=y
CONFIG_ESPTOOLPY_AFTER_NORESET=y
CONFIG_TZ_ENV="BRT+3"
CONFIG_COMPILER_WARN_WRITE_STRINGS=y
# CONFIG_SPI_MASTER_ISR_IN_IRAM is not set
# CONFIG_SPI_SLAVE_ISR_IN_IRAM is not set
# CONFIG_ETH_USE_SPI_ETHERNET is not set
CONFIG_ESP_HTTP_CLIENT_ENABLE_BASIC_AUTH=y
CONFIG_ESP_HTTP_CLIENT_ENABLE_DIGEST_AUTH=y
CONFIG_ESP32_REV_MIN_1=y
# CONFIG_ESP_PHY_CALIBRATION_AND_DATA_STORAGE is not set
CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ_240=y
CONFIG_ESP_SYSTEM_PANIC_PRINT_HALT=y
CONFIG_ESP_CONSOLE_UART_CUSTOM=y
CONFIG_ESP_CONSOLE_UART_BAUDRATE=921600
CONFIG_ESP_INT_WDT_TIMEOUT_MS=20
CONFIG_ESP_TASK_WDT_PANIC=y
CONFIG_ESP_TASK_WDT_TIMEOUT_S=2
CONFIG_ESP_SYSTEM_CHECK_INT_LEVEL_5=y
# CONFIG_ESP32_WIFI_NVS_ENABLED is not set
CONFIG_ESP_COREDUMP_ENABLE_TO_UART=y
CONFIG_ESP_COREDUMP_MAX_TASKS_NUM=20
CONFIG_ESP_COREDUMP_STACK_SIZE=1024
CONFIG_FREERTOS_HZ=1000
CONFIG_FREERTOS_CHECK_STACKOVERFLOW_NONE=y
CONFIG_FREERTOS_CORETIMER_1=y
CONFIG_HEAP_ABORT_WHEN_ALLOCATION_FAILS=y
CONFIG_LOG_DEFAULT_LEVEL_VERBOSE=y
CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y
CONFIG_LWIP_DEBUG=y
CONFIG_LWIP_DEBUG_ESP_LOG=y
CONFIG_LWIP_NETIF_DEBUG=y
CONFIG_LWIP_PBUF_DEBUG=y
CONFIG_LWIP_ETHARP_DEBUG=y
CONFIG_LWIP_API_LIB_DEBUG=y
CONFIG_LWIP_SOCKETS_DEBUG=y
CONFIG_LWIP_IP_DEBUG=y
CONFIG_LWIP_TCP_DEBUG=y
CONFIG_LWIP_DNS_DEBUG=y
CONFIG_MBEDTLS_DEBUG=y
CONFIG_MBEDTLS_TLS_CLIENT_ONLY=y
# CONFIG_MQTT_TRANSPORT_WEBSOCKET is not set
CONFIG_MQTT_SKIP_PUBLISH_IF_DISCONNECTED=y
CONFIG_MQTT_REPORT_DELETED_MESSAGES=y

ELF file:
ESP32-W5100.zip

KaeLL · 2022-08-09T18:50:02Z

Same(?) problem on another app

assert failed: xTaskPriorityDisinherit tasks.c:4976 (pxTCB == pxCurrentTCB[xPortGetCoreID()])


0x400823a2: panic_abort at /esp-idf/components/esp_system/panic.c:412

0x40092855: esp_system_abort at /esp-idf/components/esp_system/esp_system.c:135

0x4009bdd9: __assert_func at /esp-idf/components/newlib/assert.c:78

0x400951b6: xTaskPriorityDisinherit at /esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4976 (discriminator 1)

0x40092c3d: prvCopyDataToQueue at /esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:2261

0x400931b0: xQueueGenericSend at /esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:861

0x40083329: lock_release_generic at /esp-idf/components/newlib/locks.c:192

0x400833d9: _lock_release at /esp-idf/components/newlib/locks.c:198

0x4008344a: __retarget_lock_release at /esp-idf/components/newlib/locks.c:334

0x4018b459: __tz_unlock at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50

0x401832f4: localtime_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123

0x4019fc98: esp_log_system_timestamp at /esp-idf/components/log/log_freertos.c:84

Edit: definitely seems to be related

assert failed: xQueueGenericSend queue.c:837 (pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle())


Backtrace: 0x4008238e:0x3ffe15f0 0x40092699:0x3ffe1610 0x4009bc1d:0x3ffe1630 0x40092fcc:0x3ffe1750 0x40083315:0x3ffe1790 0x400833c5:0x3ffe17c0 0x40083436:0x3ffe17e0 0x4018ae01:0x3ffe1810 0x40182c9c:0x3ffe1830 0x4019f55c:0x3ffe1850 0x400e35d3:0x3ffe18c0 0x400e398f:0x3ffe1910 0x400e162a:0x3ffe19a0 0x40095bee:0x3ffe1a10
0x4008238e: panic_abort at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/esp_system/panic.c:412

0x40092699: esp_system_abort at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/esp_system/esp_system.c:135

0x4009bc1d: __assert_func at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/newlib/assert.c:78

0x40092fcc: xQueueGenericSend at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:837 (discriminator 8)

0x40083315: lock_release_generic at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/newlib/locks.c:192

0x400833c5: _lock_release at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/newlib/locks.c:198

0x40083436: __retarget_lock_release at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/newlib/locks.c:334

0x4018ae01: __tz_unlock at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50

0x40182c9c: localtime_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123

0x4019f55c: esp_log_system_timestamp at /home/nvmd/Documents/code/esp_idf/master/esp-idf/components/log/log_freertos.c:84

IDF ver. d622bcf though.

dizcza · 2022-08-10T20:07:16Z

I have the same issue with the master updated.
It isn't yet fixed, is it?

euripedesrocha · 2022-08-17T14:38:41Z

Hi @dizcza could you please open a new issue with details of your problem.

KaeLL · 2022-10-07T22:25:14Z

Indeed this seems to be a bug. With CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y and thus down the esp_log_system_timestamp code path, newlib's s_common_mutex fails the mutex ownership assert check when a release is attempted here.

Backtrace

assert failed: xQueueGenericSend queue.c:812 (pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle())


Backtrace: 0x4008235a:0x3ffe2210 0x400924f5:0x3ffe2230 0x4009ba71:0x3ffe2250 0x40092e38:0x3ffe2370 0x40083321:0x3ffe23b0 0x400833d1:0x3ffe23e0 0x40083442:0x3ffe2400 0x4017e9e9:0x3ffe2430 0x40176884:0x3ffe2450 0x40191af4:0x3ffe2470 0x400e34c3:0x3ffe24e0 0x400e387f:0x3ffe2530 0x400e1522:0x3ffe25c0
0x4008235a: panic_abort at /esp-idf/components/esp_system/panic.c:417

0x400924f5: esp_system_abort at /esp-idf/components/esp_system/esp_system.c:135

0x4009ba71: __assert_func at /esp-idf/components/newlib/assert.c:78

0x40092e38: xQueueGenericSend at /esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:812 (discriminator 8)

0x40083321: lock_release_generic at /esp-idf/components/newlib/locks.c:192

0x400833d1: _lock_release at /esp-idf/components/newlib/locks.c:198

0x40083442: __retarget_lock_release at /esp-idf/components/newlib/locks.c:334

0x4017e9e9: __tz_unlock at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50

0x40176884: localtime_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123

0x40191af4: esp_log_system_timestamp at /esp-idf/components/log/log_freertos.c:84

Piece of the core dump

==================== CURRENT THREAD STACK =====================
#0  0x4008235d in panic_abort (details=0x3ffe225b \"assert failed: xQueueGenericSend queue.c:812 (pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle())\") at /esp-idf/components/esp_system/panic.c:417
#1  0x400924f8 in esp_system_abort (details=0x3ffe225b \"assert failed: xQueueGenericSend queue.c:812 (pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle())\") at /esp-idf/components/esp_system/esp_system.c:135
#2  0x4009ba74 in __assert_func (file=0x3f402bb6 \"queue.c\", line=<optimized out>, func=<optimized out>, expr=0x3f402ecc \"pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle()\") at /esp-idf/components/newlib/assert.c:78
#3  0x40092e3b in xQueueGenericSend (xQueue=0x3ffc4940 <s_common_mutex>, pvItemToQueue=0x0, xTicksToWait=<optimized out>, xCopyPosition=0) at /esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:812
#4  0x40083324 in lock_release_generic (lock=0x3ffe2400, mutex_type=1 '\\001') at /esp-idf/components/newlib/locks.c:192
#5  0x400833d4 in _lock_release (lock=0x3ffe2400) at /esp-idf/components/newlib/locks.c:198
#6  0x40083445 in __retarget_lock_release (lock=<optimized out>) at /esp-idf/components/newlib/locks.c:334
#7  0x4017e9ec in __tz_unlock () at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50
#8  0x40176887 in localtime_r (tim_p=<optimized out>, res=0x3ffe2480) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123

AxelLin · 2023-01-01T02:07:42Z

Indeed this seems to be a bug. With CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y and thus down the esp_log_system_timestamp code path, newlib's s_common_mutex fails the mutex ownership assert check when a release is attempted here.

Then I suggest reopen this issue otherwise people will still hit this issue with CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y .
e.g. https://www.esp32.com/viewtopic.php?f=13&t=31073

KaeLL · 2023-01-02T16:32:27Z

People from espressif are free to do so should they care enough. As far as I'm concerned, just keeping the config disabled is enough to close this issue on my part.

euripedesrocha · 2023-01-02T16:35:25Z

Hi @AxelLin and @KaeLL, as always the suggestion and bug reporting are welcomed.

Just to let you know that we are handling this already.

tamisoft · 2023-01-12T00:25:47Z

Just manifested at a different assert, but the same CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y removal has fixed it here as well. My assert was at:

assert failed: xTaskPriorityDisinherit tasks.c:4976 (pxTCB == pxCurrentTCB[xPortGetCoreID()])

Backtrace: 0x4008275a:0x3ffd9d60 0x4008d779:0x3ffd9d80 0x40095541:0x3ffd9da0 0x40090531:0x3ffd9ed0 0x4008dc79:0x3ffd9ef0 0x4008e13a:0x3ffd9f10 0x400837f7:0x3ffd9f50 0x400839e9:0x3ffd9f80 0x401d26a1:0x3ffd9fb0 0x401c7e58:0x3ffd9fd0 0x401e7cf5:0x3ffd9ff0 0x400db941:0x3ffda060
0x4008275a: panic_abort at /home/levi/esp/esp-idf/components/esp_system/panic.c:423
0x4008d779: esp_system_abort at /home/levi/esp/esp-idf/components/esp_system/esp_system.c:144
0x40095541: __assert_func at /home/levi/esp/esp-idf/components/newlib/assert.c:78
0x40090531: xTaskPriorityDisinherit at /home/levi/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4976 (discriminator 1)
0x4008dc79: prvCopyDataToQueue at /home/levi/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:2252
0x4008e13a: xQueueGenericSend at /home/levi/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:861
0x400837f7: lock_release_generic at /home/levi/esp/esp-idf/components/newlib/locks.c:192
0x400839e9: _lock_release at /home/levi/esp/esp-idf/components/newlib/locks.c:198
 (inlined by) __retarget_lock_release at /home/levi/esp/esp-idf/components/newlib/locks.c:334
0x401d26a1: __tz_unlock at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50
0x401c7e58: localtime_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123
0x401e7cf5: esp_log_system_timestamp at /home/levi/esp/esp-idf/components/log/log_freertos.c:84

esp-idf at release/v5.0

wuyuanyi135 · 2023-01-20T17:01:53Z

This issue also gave me hours of debugging. If no immediate fix is planned, could you please update the documentation or the Kconfig to warn the problem?

dizcza · 2023-01-31T19:04:23Z

Please let us know if the solution in #10649 fixes the issue.

Meantime, I'm posting the traceback of how I'm getting this error:

Case 1

assert failed: xQueueGenericSend queue.c:837 (pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle())


Backtrace: 0x4008208e:0x3ffd0060 0x4008bb39:0x3ffd0080 0x40092c45:0x3ffd00a0 0x4008c47a:0x3ffd01c0 0x40082eca:0x3ffd0200 0x40082f7d:0x3ffd0230 0x40082fee:0x3ffd0250 0x40168af9:0x3ffd0280 0x40160410:0x3ffd02a0 0x400e6481:0x3ffd02c0 0x400e4e49:0x3ffd0310 0x400e6c40:0x3ffd0340 0x400d62d1:0x3ffd0360 0x400dc47b:0x3ffd0380 0x400d80e3:0x3ffd03a0 0x400d7821:0x3ffd0410 0x4017ba43:0x3ffd04a0
0x4008208e: panic_abort at /home/dizcza/tools/esp-idf/components/esp_system/panic.c:412

0x4008bb39: esp_system_abort at /home/dizcza/tools/esp-idf/components/esp_system/esp_system.c:135

0x40092c45: __assert_func at /home/dizcza/tools/esp-idf/components/newlib/assert.c:78

0x4008c47a: xQueueGenericSend at /home/dizcza/tools/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:828 (discriminator 2)

0x40082eca: lock_release_generic at /home/dizcza/tools/esp-idf/components/newlib/locks.c:192

0x40082f7d: _lock_release at /home/dizcza/tools/esp-idf/components/newlib/locks.c:198

0x40082fee: __retarget_lock_release at /home/dizcza/tools/esp-idf/components/newlib/locks.c:334

0x40168af9: __tz_unlock at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50

0x40160410: localtime_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123

0x400e6481: get_fattime at /home/dizcza/tools/esp-idf/components/fatfs/diskio/diskio.c:109

0x400e4e49: f_sync at /home/dizcza/tools/esp-idf/components/fatfs/src/ff.c:4091

0x400e6c40: vfs_fat_fsync at /home/dizcza/tools/esp-idf/components/fatfs/vfs/vfs_fat.c:527

0x400d62d1: esp_vfs_fsync at /home/dizcza/tools/esp-idf/components/vfs/vfs.c:570 (discriminator 3)

0x400dc47b: sdcard_record_write at /home/dizcza/Projects/Embedded/eclipse-workspace/esp32-sdpsensor/components_esp32/record/record.c:152 (discriminator 2)

Case 2

assert failed: xQueueGenericSend queue.c:837 (pxQueue->pcHead != ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == ((void *)0) || pxQueue->u.xSemaphore.xMutexHolder == xTaskGetCurrentTaskHandle())


Backtrace: 0x4008208e:0x3fff1660 0x4008bb39:0x3fff1680 0x40092c45:0x3fff16a0 0x4008c47a:0x3fff17c0 0x40082eca:0x3fff1800 0x40082f7d:0x3fff1830 0x40082fee:0x3fff1850 0x40168af9:0x3fff1880 0x40160410:0x3fff18a0 0x400d9cce:0x3fff18c0 0x400d9747:0x3fff19b0 0x400dd501:0x3fff1a50 0x400de6f0:0x3fff1a90 0x400dd8ba:0x3fff1b40 0x400dd9d8:0x3fff1b60 0x40175ea2:0x3fff1b80 0x400ddad2:0x3fff1ba0
0x4008208e: panic_abort at /home/dizcza/tools/esp-idf/components/esp_system/panic.c:412

0x4008bb39: esp_system_abort at /home/dizcza/tools/esp-idf/components/esp_system/esp_system.c:135

0x40092c45: __assert_func at /home/dizcza/tools/esp-idf/components/newlib/assert.c:78

0x4008c47a: xQueueGenericSend at /home/dizcza/tools/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:828 (discriminator 2)

0x40082eca: lock_release_generic at /home/dizcza/tools/esp-idf/components/newlib/locks.c:192

0x40082f7d: _lock_release at /home/dizcza/tools/esp-idf/components/newlib/locks.c:198

0x40082fee: __retarget_lock_release at /home/dizcza/tools/esp-idf/components/newlib/locks.c:334

0x40168af9: __tz_unlock at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/tzlock.c:50

0x40160410: localtime_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123

0x400d9cce: oled_print_page_gps at /home/dizcza/Projects/Embedded/eclipse-workspace/esp32-sdpsensor/main/oled.c:190

0x400d9747: webserver_sdp_get_handler at /home/dizcza/Projects/Embedded/eclipse-workspace/esp32-sdpsensor/main/webserver_sdp.c:48

0x400dd501: httpd_uri at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_uri.c:329

0x400de6f0: httpd_parse_req at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_parse.c:659
 (inlined by) httpd_req_new at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_parse.c:787

0x400dd8ba: httpd_sess_process at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_sess.c:419 (discriminator 15)

0x400dd9d8: httpd_process_session at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_main.c:200
 (inlined by) httpd_process_session at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_main.c:185

0x40175ea2: httpd_sess_enum at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_sess.c:50 (discriminator 1)

0x400ddad2: httpd_server at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_main.c:250
 (inlined by) httpd_thread at /home/dizcza/tools/esp-idf/components/esp_http_server/src/httpd_main.c:272

oled_print_page_gps refers to

        localtime_r(&gps_record.time.timespec.tv_sec, &tm);

Each time a new traceback. Crazy. Misleading unless you know about this issue.

dizcza · 2023-02-01T08:48:18Z

Just manifested at a different assert, but the same CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y removal has fixed it here as well.

As you can see from Case 2, CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y removal won't solve the problem. In fact, I set log timestamp source to milliseconds since boot and still have the issue. Because I'm using localtime_r in my code.

KaeLL · 2023-02-01T13:15:19Z

@dizcza Might be more productive to apply #10649 and verify that it works.

dizcza · 2023-02-01T19:38:20Z

@dizcza Might be more productive to apply #10649 and verify that it works.

@KaeLL already have! It's working for an hour with no errors (previously, it could take several hours to finally trigger the error).

Still, I'd like to see someone verifying the fix instead of "oh it works for me, done with it".

Removed double quotes from CMakeLists.txt files as they seem to not be needed. Updated the mqtt and esp_http_client examples. Removed make build system files. Remade the sdkconfig file. Tracking espressif/esp-idf#9441

espressif-bot added the Status: Opened Issue is new label Jul 26, 2022

github-actions bot changed the title ~~mutex assert triggering~~ mutex assert triggering (IDFGH-7923) Jul 26, 2022

espressif-bot assigned euripedesrocha Aug 5, 2022

KaeLL closed this as completed Aug 9, 2022

espressif-bot added Resolution: Won't Do This will not be worked on Status: Done Issue is done internally and removed Status: Opened Issue is new labels Sep 19, 2022

euripedesrocha reopened this Jan 2, 2023

espressif-bot added Status: Opened Issue is new and removed Resolution: Won't Do This will not be worked on Status: Done Issue is done internally labels Jan 4, 2023

espressif-bot unassigned euripedesrocha Jan 4, 2023

smjothen mentioned this issue Jan 30, 2023

Use correct recursive mutex for env and regular mutex for tz (IDFGH-9266) #10649

Merged

igrr linked a pull request Feb 3, 2023 that will close this issue

Use correct recursive mutex for env and regular mutex for tz (IDFGH-9266) #10649

Merged

espressif-bot closed this as completed in #10649 Feb 8, 2023

AxelLin mentioned this issue Feb 19, 2023

HELP!!!!! Exception / Panic in function localtime_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/time/lcltime_r.c:123 (IDFGH-9401) #10771

Closed

3 tasks

espressif-bot added Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: Opened Issue is new labels May 25, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

mutex assert triggering (IDFGH-7923) #9441

mutex assert triggering (IDFGH-7923) #9441

KaeLL commented Jul 26, 2022

KaeLL commented Jul 27, 2022

KaeLL commented Aug 9, 2022 •

edited

Loading

dizcza commented Aug 10, 2022

euripedesrocha commented Aug 17, 2022

KaeLL commented Oct 7, 2022 •

edited

Loading

AxelLin commented Jan 1, 2023

KaeLL commented Jan 2, 2023 •

edited

Loading

euripedesrocha commented Jan 2, 2023

tamisoft commented Jan 12, 2023

wuyuanyi135 commented Jan 20, 2023

dizcza commented Jan 31, 2023

dizcza commented Feb 1, 2023

KaeLL commented Feb 1, 2023

dizcza commented Feb 1, 2023

mutex assert triggering (IDFGH-7923) #9441

mutex assert triggering (IDFGH-7923) #9441

Comments

KaeLL commented Jul 26, 2022

Environment

Problem Description

Debug Logs

Other items if possible

KaeLL commented Jul 27, 2022

KaeLL commented Aug 9, 2022 • edited Loading

dizcza commented Aug 10, 2022

euripedesrocha commented Aug 17, 2022

KaeLL commented Oct 7, 2022 • edited Loading

AxelLin commented Jan 1, 2023

KaeLL commented Jan 2, 2023 • edited Loading

euripedesrocha commented Jan 2, 2023

tamisoft commented Jan 12, 2023

wuyuanyi135 commented Jan 20, 2023

dizcza commented Jan 31, 2023

Case 1

Case 2

dizcza commented Feb 1, 2023

KaeLL commented Feb 1, 2023

dizcza commented Feb 1, 2023

KaeLL commented Aug 9, 2022 •

edited

Loading

KaeLL commented Oct 7, 2022 •

edited

Loading

KaeLL commented Jan 2, 2023 •

edited

Loading