search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
12.98k stars 7.12k forks source link

ASSERT_PARAM(196608 0), in rwbt.c at line 381 (IDFGH-6777) #8405

Open MikitaMinau opened 2 years ago

MikitaMinau commented 2 years ago

Environment

Problem Description

Assert in rwbt.c was called after a client connected to BLE. Before that _lld_pdu_get_tx_flushnb HCI packet count mismatch (2, 1) error happened followed by disconnection event.

Automatic light sleep and dynamic frequency scaling were enabled. BLE was scan was disabled.

Expected Behavior

BLE works stable.

Actual Behavior

Assert was called in rwbt.c.

Steps to reproduce

No specific steps. Assert happened shortly after a client connected to ESP32 over BLE.

Code to reproduce this issue

Unfortunately, I am not able to share project code.

Debug Logs

(314936) KernelInterface.c: Heap size CAP 8bit 3960488
(314946) KernelInterface.c: Heap size CAP 32bit 3961804
(314946) KernelInterface.c: Heap size IRAM 1316
(314956) KernelInterface.c: Heap size EXT RAM 3905872
(314956) KernelInterface.c: EXT RAM largest free block 3905164
(314966) KernelInterface.c: EXT RAM law water mark 3803868
(314976) KernelInterface.c: Heap size INT RAM 55932
(314976) KernelInterface.c: INT RAM largest free block 39012
(314986) KernelInterface.c: INT RAM law water mark 40224
(314996) KernelInterface.c: External RAM heap is valid.
(314996) KernelInterface.c: Internal RAM heap is valid.
(315056) MetricsCollector.c: BLE METRIC STRING:'1643842241;0;0;4;0;61;57;0;1;0;0;0;0'
(315066) BleGatt.c: Select Handle 0x55: attribute index 45, char index 17, callback 0x0
(315076) BleGatt.c: Send notification on char update, handle = 0x55
(315086) BleGatt.c: Select Handle 0x55: attribute index 45, char index 17, callback 0x400e4f48
(315086) MetricsCollector.c: Metrics basket was read by a BLE client and it's allowed not to upload it to the server
(315126) DeviceStatus.c: Collecting status information...
(315156) DeviceStatus.c: BLE STATUS STRING: 1;0;57;100;0;0;3;3;0;0;0;0;1;0;1;0;7304;0;;119;none;0;0;0;0;0;0;0;0;0;0;
(315166) BleGatt.c: Select Handle 0x36: attribute index 14, char index 4, callback 0x0
(315176) BleGatt.c: Send notification on char update, handle = 0x36
(315186) BleGatt.c: Select Handle 0x36: attribute index 14, char index 4, callback 0x400e7cb4
lld_pdu_get_tx_flush_nb HCI packet count mismatch (2, 1)
(315676) BleGatt.c: GATT client disconnect [connection ID: 0; reason 0x8
(315676) BleManager.c: Ble GATT client disconnected
(315676) TimeStats.c: Connection type 0 connection time 313 seconds
(315706) BleGap.c: Advertising has been started
(319616) BleGatt.c: GATT client connect [connection ID: 0; interval: 24; latency: 0; timeout: 72
(319616) BleGap.c: Requested connection parameters: min_int = 36, max_int = 120, latency = 6, timeout = 400
(319626) BleManager.c: BLE GATT client has been connected
(319636) BatteryService.c: A BLE-client was connected, continue to run power-saving FSM
(319646) BleGap.c: Advertising has been stopped
(319766) BleGatt.c: MTU size changed: [connection ID: 0; mtu: 517
(320316) BleGap.c: Updating connection parameters: status = 0, min_int = 36, max_int = 120, conn_int = 120, latency = 6, timeout = 400
ASSERT_PARAM(196608 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0). 

Core  0 register dump:
PC      : 0x40086389  PS      : 0x00060034  A0      : 0x8008c59c  A1      : 0x3ffbe5e0  
A2      : 0x00000001  A3      : 0x00000000  A4      : 0x60008048  A5      : 0x00000000  
A6      : 0x00000004  A7      : 0x3ffbdbe0  A8      : 0x80086384  A9      : 0x3ffbe5c0  
A10     : 0x00000000  A11     : 0x0000002e  A12     : 0x00000014  A13     : 0xffffffff  
A14     : 0x00000000  A15     : 0xfffffffc  SAR     : 0x00000004  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x400862bc  LEND    : 0x400862c3  LCOUNT  : 0x00000000  
Core  0 was running in ISR context:
EPC1    : 0x40201f73  EPC2    : 0x400d9af0  EPC3    : 0x00000000  EPC4    : 0x40086389

Backtrace:0x40086386:0x3ffbe5e0 0x4008c599:0x3ffbe600 0x4008c9b7:0x3ffbe620 0x40085a0d:0x3ffbe640 0x4000bfed:0x3ffb5620 0x4009781b:0x3ffb5630 0x4008e173:0x3ffb5650 0x4008f80a:0x3ffb5670 0x400041bb:0x3ffb56a0 0x4000425a:0x3ffb56c0 0x4009c678:0x3ffb56f0 0x4014e8c2:0x3ffb5710 0x40117459:0x3ffb5730 0x4013fa3b:0x3ffb5750 0x40097565:0x3ffb5780
Core  1 register dump:
PC      : 0x40097c28  PS      : 0x00060334  A0      : 0x80098053  A1      : 0x3ffbc410  
A2      : 0x00000000  A3      : 0x00000001  A4      : 0x00000001  A5      : 0x00060320  
A6      : 0x000000fe  A7      : 0x00000001  A8      : 0x80097e29  A9      : 0x00000004  
A10     : 0x3ffc2f38  A11     : 0x3ffc2f44  A12     : 0x3ffc2f3c  A13     : 0x00060320  
A14     : 0x000000fe  A15     : 0x00000001  SAR     : 0x0000001d  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace:0x40097c25:0x3ffbc410 0x40098050:0x3ffbc430 0x40097565:0x3ffbc450

ELF file SHA256: 7fdc48603bf62a01

Other items if possible

Weijian-Espressif commented 2 years ago

@MikitaMinau Please update to the latest IDF master and try. Please let me know if you have the same issue

MikitaMinau commented 2 years ago

@Weijian-Espressif Thank you for your reply. Could you please provide some more information.

  1. What is the root cause of the assert? Is there any specific commit that fixes this issue.
  2. We use stable release versions of ESP-IDF instead of master as espressif suggests. Does any release version contain the fix?
  3. Are there any plans to create a fix for v4.2.x?

Thanks.

Weijian-Espressif commented 2 years ago

We fix the bug about lld_pdu_get_tx_flush_nb HCI packet count mismatch (2, 1) error, I'm not sure if it's caused by this bug. Please help test whether the latest master still has this problem

MikitaMinau commented 2 years ago

@Weijian-Espressif We cannot use unstable master branch for production. Does any release version contains the fix? Are there plans to include the fix into a release version?

AxelLin commented 2 years ago

We fix the bug about lld_pdu_get_tx_flush_nb HCI packet count mismatch (2, 1) error

Which commit fixed this issue in master?

Weijian-Espressif commented 2 years ago

Please help test whether the latest master still has the problem you feedback, just for testing

MikitaMinau commented 2 years ago

@Weijian-Espressif I understand you point but this bug is difficult to reproduce, it does not happen often. The easiest way to test it would be getting stable ESP-IDF version with the fix, update many devices in production and check if the bug disappeared.

AxelLin commented 2 years ago

We fix the bug about lld_pdu_get_tx_flush_nb HCI packet count mismatch (2, 1) error, I'm not sure if it's caused by this bug. Please help test whether the latest master still has this problem

@Weijian-Espressif lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2) reported on v4.3.2 and v4.4 https://github.com/espressif/esp-idf/issues/8303 And I don't that fix is related to this one, as it does not hit this assert in the bug report.

bbsan2k commented 2 years ago

It seems the bug is still present on 4.4.1. I personally cannot reproduce it on my board, but one of our users complained about it.

It seems to trigger sporadically, even without a connected BLE device.

Strangely the assert looks a bit different:

ASSERT_PARAM(1024 0), in rwbt.c at line 381
                                           Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40090164: f01d092d 00004136 f01d0000
Core  0 register dump:
PC      : 0x4009016b  PS      : 0x00060734  A0      : 0x80083e21  A1      : 0x3ffc1cb8
A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f41436c
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1c28
A10     : 0x00000000  A11     : 0x3ffc1c4b  A12     : 0x3ffc1bf7  A13     : 0x00000031
A14     : 0x00000000  A15     : 0x3ffc1bfc  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x40083d29  LEND    : 0x40083d31  LCOUNT  : 0x00000000

Backtrace:0x40090168:0x3ffc1cb8 |<-CORRUPTED

ELF file SHA256: bea57231b55f25aa
bbsan2k commented 2 years ago

I tried digging deeper, so I monitored my Serial output using IDF Tools and now got this stacktrace on latest release/v4.4 branch (c5deb7a9713887263b63549a891282f51a65d167):

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:2
load:0x3fff0030,len:6624
load:0x40078000,len:14788
ho 0 tail 12 room 4
load:0x40080400,len:3784
0x40080400: _init at ??:?

entry 0x40080694
I (28) boot: ESP-IDF v4.4.1-166-gfe1cf490b9 2nd stage bootloader
I (28) boot: compile time 13:10:40
I (28) boot: chip revision: 1
I (32) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (41) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (49) boot.esp32: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (59) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (70) boot:  0 nvs              WiFi data        01 02 00009000 00005000
I (77) boot:  1 otadata          OTA data         01 00 0000e000 00002000
I (84) boot:  2 app0             OTA app          00 10 00010000 00140000
I (92) boot:  3 app1             OTA app          00 11 00150000 00140000
I (99) boot:  4 spiffs           Unknown data     01 82 00290000 00170000
I (107) boot: End of partition table
I (111) boot: No factory image, trying OTA 0
I (116) boot_comm: chip revision: 1, min. application chip revision: 0
I (123) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=32828h (206888) map
I (207) esp_image: segment 1: paddr=00042850 vaddr=3ffbdb60 size=0562ch ( 22060) load
I (216) esp_image: segment 2: paddr=00047e84 vaddr=40080000 size=08194h ( 33172) load
I (230) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=d7930h (882992) map
I (549) esp_image: segment 4: paddr=00127958 vaddr=40088194 size=15f4ch ( 89932) load
I (586) esp_image: segment 5: paddr=0013d8ac vaddr=50000000 size=00010h (    16) load
I (601) boot: Loaded app from partition at offset 0x10000
I (617) boot: Set actual ota_seq=1 in otadata[0]
I (617) boot: Disabling RNG early entropy source...

--------- Stuff Happening at Serial output for about 30 Minutes ---------

ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x4008feac: f01d092d 00004136 f01d0000
0x4008feac: btdm_sleep_check_duration at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/bt.c:1091

Core  0 register dump:
PC      : 0x4008feb3  PS      : 0x00060734  A0      : 0x80083d45  A1      : 0x3ffc1cb8
0x4008feb3: r_assert at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/bt.c:2019

A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f413730
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1c28
A10     : 0x00000000  A11     : 0x3ffc1c4b  A12     : 0x3ffc1bf7  A13     : 0x00000031
A14     : 0x00000000  A15     : 0x3ffc1bfc  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x40083c4d  LEND    : 0x40083c55  LCOUNT  : 0x00000000
0x40083c4d: r_assert_param at ??:?

0x40083c55: r_assert_param at ??:?

Backtrace:0x4008feb0:0x3ffc1cb8 |<-CORRUPTED
0x4008feb0: r_assert at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/bt.c:2018

ELF file SHA256: d2237e9830afdfb3

Rebooting...

@Weijian-Espressif Any idea what is going on there?

bbsan2k commented 2 years ago

@Weijian-Espressif And another small update: CoreDump when crashing:


Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x4008ff08: f01d092d 00004136 f01d0000
0x4008ff08: btdm_sleep_check_duration at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/bt.c:1091

Core  0 register dump:
PC      : 0x4008ff0f  PS      : 0x00060134  A0      : 0x80083da1  A1      : 0x3ffc2ec0
0x4008ff0f: r_assert at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/bt.c:2019

A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f413770
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc2e30
A10     : 0x00000000  A11     : 0x3ffc2e53  A12     : 0x3ffc2dff  A13     : 0x00000031
A14     : 0x00000000  A15     : 0x3ffc2e04  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x40083ca9  LEND    : 0x40083cb1  LCOUNT  : 0x00000000
0x40083ca9: r_assert_param at ??:?

0x40083cb1: r_assert_param at ??:?

Backtrace:0x4008ff0c:0x3ffc2ec00x40083d9e:0x3ffc2ee0 0x4008a1b9:0x3ffc2f00 0x4008a60b:0x3ffc2f20 0x400834b2:0x3ffc2f40 0x4008342a:0x3ffc2f60 0x4008340e:0x00000000  |<-CORRUPTED
0x4008ff0c: r_assert at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/bt.c:2018

0x40083d9e: r_assert_param at ??:?

0x4008a1b9: r_rwbt_isr at ??:?

0x4008a60b: r_rwbtdm_isr_wrapper at intc.c:?

0x400834b2: hli_c_handler at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/hli_api.c:101

0x4008342a: _highint4_stack_switch at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/hli_vectors.S:185

0x4008340e: xt_highint4 at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/hli_vectors.S:169

ELF file SHA256: 2dfb7f1e39efed5f

Core dump started (further output muted)
Received  27 kB...
Core dump finished!
espcoredump.py v0.4-dev
===============================================================
==================== ESP32 CORE DUMP START ====================

Crashed task handle: 0x3ffbcbf4, name: '', GDB name: 'process 1073466356'

================== CURRENT THREAD REGISTERS ===================
exccause       0xffff (InvalidCauseRegister)
excvaddr       0x0

==================== CURRENT THREAD STACK =====================
pc             0x20000000          0x20000000
lbeg           0x40082a09          1074276873
lend           0x40082a11          1074276881
lcount         0x27                39
sar            0x1c                28
ps             0x30                48
threadptr      <unavailable>
br             <unavailable>
scompare1      <unavailable>
acclo          <unavailable>
acchi          <unavailable>
m0             <unavailable>
m1             <unavailable>
m2             <unavailable>
m3             <unavailable>
expstate       <unavailable>
f64r_lo        <unavailable>
f64r_hi        <unavailable>
f64s           <unavailable>
fcr            <unavailable>
fsr            <unavailable>
a0             0x20000070          536871024
a1             0x0                 0
a2             0x0                 0
a3             0x0                 0
a4             0x60020             393248
a5             0x60023             393251
a6             0x3ffc1de4          1073487332
a7             0x0                 0
a8             0x1                 1
a9             0x3ffbb720          1073461024
a10            0x3ffc4620          1073497632
a11            0x3ffc4620          1073497632
a12            0x40081db0          1074273712
a13            0x3ffdf888          1073608840
a14            0x400d6490          1074619536
a15            0x3ffbb9b4          1073461684
#0  0x20000000 in ?? ()

======================== THREADS INFO =========================
  Id   Target Id          Frame
* 1    process 1073466356 0x20000000 in ?? ()
  2    process 1073468244 0x401a4126 in esp_pm_impl_waiti () at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:183
  3    process 1073588180 0x40093dfc in vTaskDelay (xTicksToDelay=1) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  4    process 1073597808 0x4009274e in xQueueReceive (xQueue=0x3ffdbe94, pvBuffer=0x3ffdccd0, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  5    process 1073466008 0x4000bff0 in ?? ()
  6    process 1073444940 0x400928b8 in xQueueSemaphoreTake (xQueue=0x3ffb71f0, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  7    process 1073657408 0x4009274e in xQueueReceive (xQueue=0x3ffe7564, pvBuffer=0x3ffeb598, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  8    process 1073606456 0x4009274e in xQueueReceive (xQueue=0x3ffdcf4c, pvBuffer=0x3ffdeea0, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  9    process 1073602008 0x4009274e in xQueueReceive (xQueue=0x3ffdd024, pvBuffer=0x3ffddd10, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  10   process 1073445552 0x400928b8 in xQueueSemaphoreTake (xQueue=0x3ffb7a58, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  11   process 1073640440 0x4009274e in xQueueReceive (xQueue=0x3ffe61f4, pvBuffer=0x3ffe7348, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  12   process 1073617056 0x4009274e in xQueueReceive (xQueue=0x3ffdf888, pvBuffer=0x3ffe1800, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  13   process 1073578764 0x4009274e in xQueueReceive (xQueue=0x3ffd7164, pvBuffer=0x3ffd8270, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
  14   process 1073461304 0x4000bff0 in ?? ()

==================== THREAD 1 (TCB: 0x3ffbcbf4, name: 'IDLE') =====================
#0  0x20000000 in ?? ()

==================== THREAD 2 (TCB: 0x3ffbd354, name: 'IDLE') =====================
#0  0x401a4126 in esp_pm_impl_waiti () at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:183
#1  0x400d3e54 in esp_vApplicationIdleHook () at /Users/bbsan/ESP/esp-idf/components/esp_system/freertos_hooks.c:63
#2  0x40092dbb in prvIdleTask (pvParameters=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/freertos/tasks.c:3973

==================== THREAD 3 (TCB: 0x3ffda7d4, name: 'ArduinoTask') =====================
#0  0x40093dfc in vTaskDelay (xTicksToDelay=1) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x400d7f6b in loop () at ../main/arduino_main.cpp:107
#2  0x400e181d in arduino_task (params=0x0) at ../components/bluepad32/uni_platform_arduino_bootstrap.cpp:45

==================== THREAD 4 (TCB: 0x3ffdcd70, name: 'tiT') =====================
#0  0x4009274e in xQueueReceive (xQueue=0x3ffdbe94, pvBuffer=0x3ffdccd0, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x4014904a in sys_arch_mbox_fetch (mbox=<optimized out>, msg=0x3ffdccd0, timeout=350) at /Users/bbsan/ESP/esp-idf/components/lwip/port/esp32/freertos/sys_arch.c:330
#2  0x4013adae in tcpip_timeouts_mbox_fetch (mbox=<optimized out>, msg=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/lwip/lwip/src/api/tcpip.c:110
#3  tcpip_thread (arg=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/lwip/lwip/src/api/tcpip.c:148

==================== THREAD 5 (TCB: 0x3ffbca98, name: 'main') =====================
#0  0x4000bff0 in ?? ()
#1  0x40094e19 in vPortClearInterruptMaskFromISR (prev_level=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/freertos/port/xtensa/include/freertos/portmacro.h:571
#2  vPortExitCritical (mux=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/freertos/port/xtensa/port.c:319
#3  0x4009443e in xTaskGenericNotifyWait (uxIndexToWait=<optimized out>, ulBitsToClearOnEntry=<optimized out>, ulBitsToClearOnExit=4294967295, pulNotificationValue=0x0, xTicksToWait=4294967) at /Users/bbsan/ESP/esp-idf/components/freertos/tasks.c:5478
#4  0x400eb6ec in btstack_run_loop_freertos_execute () at ../components/btstack/platform/freertos/btstack_run_loop_freertos.c:202
#5  0x400e2995 in btstack_run_loop_execute () at ../components/btstack/src/btstack_run_loop.c:293
#6  0x400e14ea in uni_main (argc=0, argv=0x0) at ../components/bluepad32/uni_main.c:43
#7  0x400d7e78 in app_main () at ../main/main.c:49
#8  0x401a78fe in main_task (args=0x0) at /Users/bbsan/ESP/esp-idf/components/freertos/port/port_common.c:129

==================== THREAD 6 (TCB: 0x3ffb784c, name: 'ipc0') =====================
#0  0x400928b8 in xQueueSemaphoreTake (xQueue=0x3ffb71f0, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x4008a8d3 in ipc_task (arg=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/esp_ipc/src/esp_ipc.c:54

==================== THREAD 7 (TCB: 0x3ffeb640, name: 'async_tcp') =====================
#0  0x4009274e in xQueueReceive (xQueue=0x3ffe7564, pvBuffer=0x3ffeb598, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x400f22b6 in _get_async_event (e=<unavailable>) at ../components/AsyncTCP/src/AsyncTCP.cpp:191
#2  _async_service_task (pvParameters=<optimized out>) at ../components/AsyncTCP/src/AsyncTCP.cpp:191

==================== THREAD 8 (TCB: 0x3ffdef38, name: 'arduino_events') =====================
#0  0x4009274e in xQueueReceive (xQueue=0x3ffdcf4c, pvBuffer=0x3ffdeea0, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x400f9fe8 in _arduino_event_task (arg=<optimized out>) at ../components/arduino/libraries/WiFi/src/WiFiGeneric.cpp:247

==================== THREAD 9 (TCB: 0x3ffdddd8, name: 'sys_evt') =====================
#0  0x4009274e in xQueueReceive (xQueue=0x3ffdd024, pvBuffer=0x3ffddd10, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x401a6e88 in esp_event_loop_run (event_loop=0x3ffdbb18, ticks_to_run=4294967295) at /Users/bbsan/ESP/esp-idf/components/esp_event/esp_event.c:632
#2  0x401a6ffb in esp_event_loop_run_task (args=0x3ffdbb18) at /Users/bbsan/ESP/esp-idf/components/esp_event/esp_event.c:115

==================== THREAD 10 (TCB: 0x3ffb7ab0, name: 'ipc1') =====================
#0  0x400928b8 in xQueueSemaphoreTake (xQueue=0x3ffb7a58, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x4008a8d3 in ipc_task (arg=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/esp_ipc/src/esp_ipc.c:54

==================== THREAD 11 (TCB: 0x3ffe73f8, name: 'mdns') =====================
#0  0x4009274e in xQueueReceive (xQueue=0x3ffe61f4, pvBuffer=0x3ffe7348, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x4011c0fe in _mdns_service_task (pvParameters=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/mdns/mdns.c:4591

==================== THREAD 12 (TCB: 0x3ffe18a0, name: 'wifi') =====================
#0  0x4009274e in xQueueReceive (xQueue=0x3ffdf888, pvBuffer=0x3ffe1800, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x400d648c in queue_recv_wrapper (queue=0x3ffdf888, item=0x3ffe1800, block_time_tick=4294967295) at /Users/bbsan/ESP/esp-idf/components/esp_wifi/esp32/esp_adapter.c:375
#2  0x4009a19c in ppTask () at /Users/bbsan/ESP/esp-idf/components/esp_system/freertos_hooks.c:39

==================== THREAD 13 (TCB: 0x3ffd830c, name: 'btController') =====================
#0  0x4009274e in xQueueReceive (xQueue=0x3ffd7164, pvBuffer=0x3ffd8270, xTicksToWait=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/hal/esp32/include/hal/cpu_ll.h:39
#1  0x400837f6 in queue_recv_hlevel_wrapper (queue=0x3ffd71e4, item=0x3ffd8270, block_time_ms=4294967295) at /Users/bbsan/ESP/esp-idf/components/bt/controller/esp32/bt.c:955
#2  0x401027e1 in btdm_controller_task ()

==================== THREAD 14 (TCB: 0x3ffbb838, name: 'esp_timer') =====================
#0  0x4000bff0 in ?? ()
#1  0x40094e19 in vPortClearInterruptMaskFromISR (prev_level=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/freertos/port/xtensa/include/freertos/portmacro.h:571
#2  vPortExitCritical (mux=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/freertos/port/xtensa/port.c:319
#3  0x40094329 in ulTaskGenericNotifyTake (uxIndexToWait=<optimized out>, xClearCountOnExit=1, xTicksToWait=4294967295) at /Users/bbsan/ESP/esp-idf/components/freertos/tasks.c:5387
#4  0x400d749b in timer_task (arg=<optimized out>) at /Users/bbsan/ESP/esp-idf/components/esp_timer/src/esp_timer.c:384

======================= ALL MEMORY REGIONS ========================
Name   Address   Size   Attrs
.rtc.text 0x400c0000 0x0 RW
.rtc.dummy 0x3ff80000 0x0 RW
.rtc.force_fast 0x3ff80000 0x0 RW
.rtc.data 0x50000000 0x10 RW A
.rtc_noinit 0x50000010 0x0 RW
.rtc.force_slow 0x50000010 0x0 RW
.iram0.vectors 0x40080000 0x403 R XA
.iram0.text 0x40080404 0x1df7f R XA
.dram0.data 0x3ffbdb60 0x6834 RW A
.ext_ram_noinit 0x3f800000 0x0 RW
.noinit 0x3ffc4394 0x0 RW
.ext_ram.bss 0x3f800000 0x0 RW
.flash.appdesc 0x3f400020 0x100 R  A
.flash.rodata 0x3f400120 0x32b48 RW A
.flash.text 0x400d0020 0xd7b5f R XA
.phyiram.20 0x401a7b80 0x61 R XA
.phyiram.18 0x401a7be4 0x10e R XA
.phyiram.19 0x401a7cf4 0x90 R XA
.phyiram.17 0x401a7d84 0x2d7 R XA
.phyiram.0 0x401a805c 0x2b R XA
.phyiram.1 0x401a8088 0x7d R XA
.phyiram.2 0x401a8108 0x21e R XA
.phyiram.3 0x401a8328 0xab R XA
.phyiram.4 0x401a83d4 0xff R XA
.phyiram.6 0x401a84d4 0x83 R XA
.phyiram.7 0x401a8558 0x1ff R XA
.phyiram.8 0x401a8758 0x177 R XA
.phyiram.9 0x401a88d0 0x8e R XA
.phyiram.13 0x401a8960 0xba R XA
.phyiram.12 0x401a8a1c 0xeb R XA
.phyiram.14 0x401a8b08 0x1cb R XA
.phyiram.16 0x401a8cd4 0x72 R XA
.phyiram.11 0x401a8d48 0x78 R XA
.phyiram.15 0x401a8dc0 0xba R XA
.phyiram.21 0x401a8e7c 0x4a R XA
.phyiram.22 0x401a8ec8 0x31 R XA
.phyiram.23 0x401a8efc 0x103 R XA
.phyiram.24 0x401a9000 0x87 R XA
.iram0.data 0x4009e384 0x0 RW
.iram0.bss 0x4009e384 0x0 RW
.dram0.heap_start 0x3ffd2328 0x0 RW
.coredump.tasks.data 0x3ffbd354 0x158 RW
.coredump.tasks.data 0x3ffbd920 0x18c RW
.coredump.tasks.data 0x3ffbcbf4 0x158 RW
.coredump.tasks.data 0x20000000 0x70 RW
.coredump.tasks.data 0x3ffda7d4 0x158 RW
.coredump.tasks.data 0x3ffda640 0x18c RW
.coredump.tasks.data 0x3ffdcd70 0x158 RW
.coredump.tasks.data 0x3ffdcba0 0x1c8 RW
.coredump.tasks.data 0x3ffbca98 0x158 RW
.coredump.tasks.data 0x3ffbc870 0x220 RW
.coredump.tasks.data 0x3ffb784c 0x158 RW
.coredump.tasks.data 0x3ffb76c0 0x184 RW
.coredump.tasks.data 0x3ffeb640 0x158 RW
.coredump.tasks.data 0x3ffeb490 0x1a8 RW
.coredump.tasks.data 0x3ffdef38 0x158 RW
.coredump.tasks.data 0x3ffdeda0 0x190 RW
.coredump.tasks.data 0x3ffdddd8 0x158 RW
.coredump.tasks.data 0x3ffddc00 0x1d0 RW
.coredump.tasks.data 0x3ffb7ab0 0x158 RW
.coredump.tasks.data 0x3ffba4f0 0x188 RW
.coredump.tasks.data 0x3ffe73f8 0x158 RW
.coredump.tasks.data 0x3ffe7230 0x1c0 RW
.coredump.tasks.data 0x3ffe18a0 0x158 RW
.coredump.tasks.data 0x3ffe16e0 0x1b8 RW
.coredump.tasks.data 0x3ffd830c 0x158 RW
.coredump.tasks.data 0x3ffd8150 0x1b4 RW
.coredump.tasks.data 0x3ffbb838 0x158 RW
.coredump.tasks.data 0x3ffbb690 0x1a0 RW

===================== ESP32 CORE DUMP END =====================
=============================================================== ```
SatishSolankeEsp commented 2 years ago

Hi @bbsan2k , Could you please tell me the steps to reproduce the issue or example you running ? I have gone through the core dump you have attached looks like the first instruction of r_rwbt_isr funcs caused this assertion. want to check which scenario you are hitting the assert, The core dump says your running the classical BT, is it?

Thanks, Satish

bbsan2k commented 2 years ago

Hi @SatishSolankeEsp , The problem is, it's really hard to reproduce... I tried to track down what influences this crash and it seems it is related to having WiFi turned on and connected in STA mode while using BTStack (https://github.com/bluekitchen/btstack) with a Bluetooth Game Controller (Dual Shock 4) - which is BT 2.1.

Is this of any help? If required I can send you a version of our App, but as the issue is so hard to reproduce it may take up to 5 hours until it finally triggers.

bbsan2k commented 1 year ago

Any update on this @SatishSolankeEsp

zenbooster commented 1 year ago

IDF ver: 4.4.2 (used by arduino core 2.0.5) https://github.com/espressif/arduino-esp32/issues/7376

In my project, I use a devboard esp32-wroom-32, running a telegram-bot, and a task that is constantly trying to connect to a device via bluetooth spp, in order to then receive and process data from it. Recently, while trying to connect with a turned off device, I caught this error:

Failed to connect. Make sure remote device is available and in range.
Failed to connect. Make sure remote device is available and in range.
Failed to connect. Make sure remote device is available and in range.
Failed to connect. Make sure remote device is available and in range.
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x400905f8: 00f01d00 00004136 f01d0000
ftab commented 1 year ago

I'm also running into this with a Bluetooth classic audio application that is connected to a WiFi station and has an open TCP connection for remote DSP control. The TCP connection is not actively doing anything at the time this occurs, so WiFi is mostly idle, aside from whatever it needs to do to maintain the connection. There are times when the application will run like this all day long without a problem, and times when the application will crash within 10 minutes of boot.

Bluetooth modem sleep is disabled. High level interrupt is disabled.

2022-11-03 13:24:07.297904 ASSERT_PARAM(2048 0), in rwbt.c at line 381
2022-11-03 13:24:07.298031 Guru Meditation Error: Core  1 panic'ed (IllegalInstruction). Exception was unhandled.
2022-11-03 13:24:07.298095 Memory dump at 0x400916c4: f01d092d 00004136 f01d0000
2022-11-03 13:24:07.298147 0x400916c4: btdm_sleep_check_duration at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:951
2022-11-03 13:24:07.312438 
Core  1 register dump:
2022-11-03 13:24:07.312600 PC      : 0x400916cb  PS      : 0x00060031  A0      : 0x80085291  A1      : 0x3ffc03e0  
2022-11-03 13:24:07.313216 0x400916cb: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1869
2022-11-03 13:24:07.325749 
A2      : 0x00000000  A3      : 0x00000800  A4      : 0x00000000  A5      : 0x3f422a64  
2022-11-03 13:24:07.325872 A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc0350  
2022-11-03 13:24:07.325928 A10     : 0x00000000  A11     : 0x3ffc0373  A12     : 0x3ffc031f  A13     : 0x00000031  
2022-11-03 13:24:07.326327 A14     : 0x00000000  A15     : 0x3ffc0324  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
2022-11-03 13:24:07.326377 EXCVADDR: 0x00000000  LBEG    : 0x40085199  LEND    : 0x400851a1  LCOUNT  : 0x00000000  
2022-11-03 13:24:07.326415 0x40085199: r_assert_param at ??:?
2022-11-03 13:24:07.352755 
0x400851a1: r_assert_param at ??:?
2022-11-03 13:24:07.376627 

2022-11-03 13:24:07.376791 
2022-11-03 13:24:07.376851 Backtrace: 0x400916c8:0x3ffc03e0 0x4008528e:0x3ffc0400 0x4008b701:0x3ffc0420 0x4008bc67:0x3ffc0440 0x40083351:0x3ffc0460 0x40094b67:0x3ffd5210 0x400dd461:0x3ffd5250 0x4013a51a:0x3ffd5270
2022-11-03 13:24:07.377332 0x400916c8: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1868
2022-11-03 13:24:07.389621 
0x4008528e: r_assert_param at ??:?
2022-11-03 13:24:07.414746 
0x4008b701: r_rwbt_isr at ??:?
2022-11-03 13:24:07.440078 
0x4008bc67: r_rwbtdm_isr_wrapper at intc.c:?
2022-11-03 13:24:07.465799 
0x40083351: _xt_lowint1 at /home/build/esp/esp-adf/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1117
2022-11-03 13:24:07.477784 
0x40094b67: xQueueReceive at /home/build/esp/esp-adf/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:1494
2022-11-03 13:24:07.489934 
0x400dd461: queue_recv_wrapper at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:850
2022-11-03 13:24:07.502282 
0x4013a51a: btdm_controller_task at ??:?
2022-11-03 13:24:07.527341

It would be great if you could release the source code to these files so that these backtraces are more helpful and so I could dig in to have a better idea of what's going on. Other than the assert, there is no line number information for anything in the binary blobs, so I'm not sure what else I can tell you.

SuGlider commented 1 year ago

The Arduino team can't help too much on this issue given it seems related to IDF. We will have to wait for the necessary analysis from IDF Team.

zenbooster commented 1 year ago

I built my project with framework=arduino, espidf and here are 4 cases at different times:

Connection error. Make sure the remote device is enabled and available.
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x4008feac: f01d092d 00004136 f01d0000
Core  0 register dump:
PC      : 0x4008feb3  PS      : 0x00060434  A0      : 0x80089179  A1      : 0x3ffc1c0a  
A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f42b620
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1b7a  
A10     : 0x00000000  A11     : 0x3ffc1b9d  A12     : 0x3ffc1b49  A13     : 0x00000031
A14     : 0x00000000  A15     : 0x3ffc1b4e  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x40089081  LEND    : 0x40089089  LCOUNT  : 0x00000000

Backtrace:0x4008feb0:0x3ffc1c0a |<-CORRUPTED
Connection error. Make sure the remote device is enabled and available.
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x4008feac: f01d092d 00004136 f01d0000
Core  0 register dump:
PC      : 0x4008feb3  PS      : 0x00060634  A0      : 0x80089179  A1      : 0x3ffc1c0a
A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f42b620  
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1b7a
A10     : 0x00000000  A11     : 0x3ffc1b9d  A12     : 0x3ffc1b49  A13     : 0x00000031  
A14     : 0x00000000  A15     : 0x3ffc1b4e  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x40089081  LEND    : 0x40089089  LCOUNT  : 0x00000000  

Backtrace:0x4008feb0:0x3ffc1c0a |<-CORRUPTED
Connection error. Make sure the remote device is enabled and available.
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x4008feac: f01d092d 00004136 f01d0000
Core  0 register dump:
PC      : 0x4008feb3  PS      : 0x00060034  A0      : 0x80089179  A1      : 0x3ffc1c0a
A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f42b620  
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1b7a
A10     : 0x00000000  A11     : 0x3ffc1b9d  A12     : 0x3ffc1b49  A13     : 0x00000031  
A14     : 0x00000000  A15     : 0x3ffc1b4e  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x40089081  LEND    : 0x40089089  LCOUNT  : 0x00000000  

Backtrace:0x4008feb0:0x3ffc1c0a |<-CORRUPTED
Connection error. Make sure the remote device is enabled and available.
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x4008feac: f01d092d 00004136 f01d0000
Core  0 register dump:
PC      : 0x4008feb3  PS      : 0x00060c34  A0      : 0x80089179  A1      : 0x3ffc1c0a
A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f42b620  
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1b7a
A10     : 0x00000000  A11     : 0x3ffc1b9d  A12     : 0x3ffc1b49  A13     : 0x00000031  
A14     : 0x00000000  A15     : 0x3ffc1b4e  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x40089081  LEND    : 0x40089089  LCOUNT  : 0x00000000  

Backtrace:0x4008feb0:0x3ffc1c0a |<-CORRUPTED

Maybe this will help...

zenbooster commented 1 year ago

The Arduino team can't help too much on this issue given it seems related to IDF. We will have to wait for the necessary analysis from IDF Team.

How long do you think it takes approximately to wait, and is anyone dealing with this problem right now?

noqnio commented 1 month ago

This issue still persists with ESP-IDF v5.1 (with esp-adf freertos patch, ESP-ADF version 2.6) Has anybody found a workaround or a way to not trigger that assertion ? This issue is very debilitating, I would highly appreciate any help solving or mitigating it, thanks.

I cannot try a newer IDF version, as 5.1 is the latest one supported by ADF v2.6, the latest ADF version. I cannot upgrade to master at the time being.

ESP32-WROVER-E on a custom board which is a copy of LyraT v4.3 PSRAM enabled Windows, VSCode idf5.1_py3.8_env

I (1994148) BLUETOOTH_SERVICE: Discovery started.
I (2006948) BLUETOOTH_SERVICE: Device discovery failed, continue to discover...
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40091850: 00f01d00 00004136 f01d0000
0x40091850: btdm_sleep_check_duration at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:910

Core  0 register dump:
PC      : 0x40091857  PS      : 0x00060934  A0      : 0x800854b1  A1      : 0x3ffc1ef0
0x40091857: r_assert at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1845

A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f427268
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1e60
A10     : 0x00000000  A11     : 0x3ffc1e83  A12     : 0x3ffc1e2f  A13     : 0x00000031
A14     : 0x00000000  A15     : 0x3ffc1e34  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x400853b9  LEND    : 0x400853c1  LCOUNT  : 0x00000000
0x400853b9: r_assert_param at ??:?
0x400853c1: r_assert_param at ??:?

Backtrace: 0x40091854:0x3ffc1ef0 0x400854ae:0x3ffc1f10 0x4008beb5:0x3ffc1f30 0x4008c41b:0x3ffc1f50 0x40083d06:0x3ffc1f70 0x40083c7d:0x3ffc1f90 0x40083c5f:0x00000000 |<-CORRUPTED
0x40091854: r_assert at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1844
0x400854ae: r_assert_param at ??:?
0x4008beb5: r_rwbt_isr at ??:?
0x4008c41b: r_rwbtdm_isr_wrapper at intc.c:?
0x40083d06: hli_c_handler at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/hli_api.c:92
0x40083c7d: _highint4_stack_switch at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:177
0x40083c5f: xt_highint4 at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:161

ELF file SHA256: 5ec2e5ec458e47a4

Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_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:7084
ho 0 tail 12 room 4
load:0x40078000,len:15592
ho 0 tail 12 room 4
load:0x40080400,len:4
0x40080400: _init at ??:?

load:0x40080404,len:3876
entry 0x4008064c
I (32) boot: ESP-IDF v5.1-dirty 2nd stage bootloader
I (33) boot: compile time Jun  3 2024 11:52:51
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v3.0
I (41) boot.esp32: SPI Speed      : 80MHz
I (46) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 2MB
I (55) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (64) boot: ## Label            Usage          Type ST Offset   Length
I (71) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (79) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  2 factory          factory app      00 00 00010000 001e8480
I (94) boot: End of partition table
I (98) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=4cc50h (314448) map
I (201) esp_image: segment 1: paddr=0005cc78 vaddr=3ffbdb60 size=033a0h ( 13216) load
I (206) esp_image: segment 2: paddr=00060020 vaddr=400d0020 size=12cdfch (1232380) map
I (578) esp_image: segment 3: paddr=0018ce24 vaddr=3ffc0f00 size=021a4h (  8612) load
I (581) esp_image: segment 4: paddr=0018efd0 vaddr=40080000 size=1c6dch (116444) load
I (640) boot: Loaded app from partition at offset 0x10000
I (640) boot: Disabling RNG early entropy source...
I (651) cpu_start: Multicore app
I (652) quad_psram: This chip is ESP32-D0WD
I (652) esp_psram: Found 8MB PSRAM device
I (654) esp_psram: Speed: 80MHz
I (657) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (665) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (674) cpu_start: Pro cpu up.
I (678) cpu_start: Starting app cpu, entry point is 0x40081620
0x40081620: call_start_cpu1 at C:/Users/-/.espressif/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:154

I (668) cpu_start: App cpu up.
I (1172) esp_psram: SPI SRAM memory test OK
I (1180) cpu_start: Pro cpu start user code
I (1180) cpu_start: cpu freq: 240000000 Hz
I (1180) cpu_start: Application information:
I (1183) cpu_start: Project name:     bt_source_demo
I (1189) cpu_start: App version:      d981c93-dirty
I (1195) cpu_start: Compile time:     Jun  3 2024 12:06:39
I (1201) cpu_start: ELF file SHA256:  5ec2e5ec458e47a4...
I (1207) cpu_start: ESP-IDF:          v5.1-dirty
I (1212) cpu_start: Min chip rev:     v0.0
I (1217) cpu_start: Max chip rev:     v3.99 
I (1222) cpu_start: Chip rev:         v3.0
I (1227) heap_init: Initializing. RAM available for dynamic allocation:
I (1234) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1240) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1246) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1253) heap_init: At 3FFC9230 len 00016DD0 (91 KiB): DRAM
I (1259) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1265) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1272) heap_init: At 4009C6DC len 00003924 (14 KiB): IRAM
I (1278) esp_psram: Adding pool of 4096K of PSRAM memory to heap allocator
I (1286) spi_flash: detected chip: generic
I (1290) spi_flash: flash io: dio
W (1294) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (1308) coexist: coex firmware version: ebddf30
I (1313) app_start: Starting scheduler on CPU0
         (1318) app_start: Starting scheduler on CPU1
;32mI (1318) main_task: Started on CPU0
I (1328) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1328) main_task: Calling app_main()
I (1338) encoder: Initialization complete, timer interval: 1ms
I (1338) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1348) gpio: GPIO[13]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1358) gpio: GPIO[14]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1368) encoder: Added rotary encoder 0, A: 14, B: 13, BTN: 4
I (1398) BLUETOOTH_SOURCE_EXAMPLE: [ 1 ] Create Bluetooth service
I (1398) BTDM_INIT: BT controller compile version [ad2b7cd]
I (1398) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1868) BLUETOOTH_SERVICE: Starting device discovery...
I (1878) BLUETOOTH_SOURCE_EXAMPLE: [1.1] Get Bluetooth stream
W (1878) BT_BTC: A2DP Enable with AVRC
ESP-YTGerd commented 1 month ago

This issue still persists with ESP-IDF v5.1 (with esp-adf freertos patch, ESP-ADF version 2.6) Has anybody found a workaround or a way to not trigger that assertion ? This issue is very debilitating, I would highly appreciate any help solving or mitigating it, thanks.

I cannot try a newer IDF version, as 5.1 is the latest one supported by ADF v2.6, the latest ADF version. I cannot upgrade to master at the time being.

ESP32-WROVER-E on a custom board which is a copy of LyraT v4.3 PSRAM enabled Windows, VSCode idf5.1_py3.8_env

I (1994148) BLUETOOTH_SERVICE: Discovery started.
I (2006948) BLUETOOTH_SERVICE: Device discovery failed, continue to discover...
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40091850: 00f01d00 00004136 f01d0000
0x40091850: btdm_sleep_check_duration at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:910

Core  0 register dump:
PC      : 0x40091857  PS      : 0x00060934  A0      : 0x800854b1  A1      : 0x3ffc1ef0
0x40091857: r_assert at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1845

A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f427268
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1e60
A10     : 0x00000000  A11     : 0x3ffc1e83  A12     : 0x3ffc1e2f  A13     : 0x00000031
A14     : 0x00000000  A15     : 0x3ffc1e34  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x400853b9  LEND    : 0x400853c1  LCOUNT  : 0x00000000
0x400853b9: r_assert_param at ??:?
0x400853c1: r_assert_param at ??:?

Backtrace: 0x40091854:0x3ffc1ef0 0x400854ae:0x3ffc1f10 0x4008beb5:0x3ffc1f30 0x4008c41b:0x3ffc1f50 0x40083d06:0x3ffc1f70 0x40083c7d:0x3ffc1f90 0x40083c5f:0x00000000 |<-CORRUPTED
0x40091854: r_assert at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1844
0x400854ae: r_assert_param at ??:?
0x4008beb5: r_rwbt_isr at ??:?
0x4008c41b: r_rwbtdm_isr_wrapper at intc.c:?
0x40083d06: hli_c_handler at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/hli_api.c:92
0x40083c7d: _highint4_stack_switch at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:177
0x40083c5f: xt_highint4 at C:/Users/-/.espressif/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:161

ELF file SHA256: 5ec2e5ec458e47a4

Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_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:7084
ho 0 tail 12 room 4
load:0x40078000,len:15592
ho 0 tail 12 room 4
load:0x40080400,len:4
0x40080400: _init at ??:?

load:0x40080404,len:3876
entry 0x4008064c
I (32) boot: ESP-IDF v5.1-dirty 2nd stage bootloader
I (33) boot: compile time Jun  3 2024 11:52:51
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v3.0
I (41) boot.esp32: SPI Speed      : 80MHz
I (46) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 2MB
I (55) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (64) boot: ## Label            Usage          Type ST Offset   Length
I (71) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (79) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  2 factory          factory app      00 00 00010000 001e8480
I (94) boot: End of partition table
I (98) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=4cc50h (314448) map
I (201) esp_image: segment 1: paddr=0005cc78 vaddr=3ffbdb60 size=033a0h ( 13216) load
I (206) esp_image: segment 2: paddr=00060020 vaddr=400d0020 size=12cdfch (1232380) map
I (578) esp_image: segment 3: paddr=0018ce24 vaddr=3ffc0f00 size=021a4h (  8612) load
I (581) esp_image: segment 4: paddr=0018efd0 vaddr=40080000 size=1c6dch (116444) load
I (640) boot: Loaded app from partition at offset 0x10000
I (640) boot: Disabling RNG early entropy source...
I (651) cpu_start: Multicore app
I (652) quad_psram: This chip is ESP32-D0WD
I (652) esp_psram: Found 8MB PSRAM device
I (654) esp_psram: Speed: 80MHz
I (657) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (665) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (674) cpu_start: Pro cpu up.
I (678) cpu_start: Starting app cpu, entry point is 0x40081620
0x40081620: call_start_cpu1 at C:/Users/-/.espressif/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:154

I (668) cpu_start: App cpu up.
I (1172) esp_psram: SPI SRAM memory test OK
I (1180) cpu_start: Pro cpu start user code
I (1180) cpu_start: cpu freq: 240000000 Hz
I (1180) cpu_start: Application information:
I (1183) cpu_start: Project name:     bt_source_demo
I (1189) cpu_start: App version:      d981c93-dirty
I (1195) cpu_start: Compile time:     Jun  3 2024 12:06:39
I (1201) cpu_start: ELF file SHA256:  5ec2e5ec458e47a4...
I (1207) cpu_start: ESP-IDF:          v5.1-dirty
I (1212) cpu_start: Min chip rev:     v0.0
I (1217) cpu_start: Max chip rev:     v3.99 
I (1222) cpu_start: Chip rev:         v3.0
I (1227) heap_init: Initializing. RAM available for dynamic allocation:
I (1234) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1240) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1246) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1253) heap_init: At 3FFC9230 len 00016DD0 (91 KiB): DRAM
I (1259) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1265) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1272) heap_init: At 4009C6DC len 00003924 (14 KiB): IRAM
I (1278) esp_psram: Adding pool of 4096K of PSRAM memory to heap allocator
I (1286) spi_flash: detected chip: generic
I (1290) spi_flash: flash io: dio
W (1294) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (1308) coexist: coex firmware version: ebddf30
I (1313) app_start: Starting scheduler on CPU0
         (1318) app_start: Starting scheduler on CPU1
;32mI (1318) main_task: Started on CPU0
I (1328) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1328) main_task: Calling app_main()
I (1338) encoder: Initialization complete, timer interval: 1ms
I (1338) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1348) gpio: GPIO[13]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1358) gpio: GPIO[14]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1368) encoder: Added rotary encoder 0, A: 14, B: 13, BTN: 4
I (1398) BLUETOOTH_SOURCE_EXAMPLE: [ 1 ] Create Bluetooth service
I (1398) BTDM_INIT: BT controller compile version [ad2b7cd]
I (1398) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1868) BLUETOOTH_SERVICE: Starting device discovery...
I (1878) BLUETOOTH_SOURCE_EXAMPLE: [1.1] Get Bluetooth stream
W (1878) BT_BTC: A2DP Enable with AVRC
Hi, @noqnio This issue was fixed and MR was merged in branches release/v5.3, release/v5.1, release/v4.4, which will also expected to be synchronized to github within serveral days. The following table lists the commits of fixes: branch commit
master 88774ee
release/v5.3 bfa95cd
release/v5.2 369c297: expected in v5.2.2
release/v5.1 090a775: expected in v5.1.5
release/v5.0 fc17843: expected in v5.0.7
release/v4.4 eee102f: expected in v4.4.8
AxelLin commented 1 month ago

@ESP-YTGerd How about the fix for v5.2 branch?

ESP-YTGerd commented 1 month ago

@ESP-YTGerd How about the fix for v5.2 branch?

Fix for branch release/v5.2 has not been merged internally. I will update this as soon as it gets merged.

noqnio commented 1 month ago

Hi, @noqnio This issue was fixed and MR was merged in branches release/v5.3, release/v5.1, release/v4.4, which will also expected to be synchronized to github within serveral days. The following table lists the commits of fixes: branch commit master 88774ee release/v5.3 bfa95cd release/v5.1 090a775: expected in v5.1.5 release/v5.0 fc17843: expected in v5.0.7 release/v4.4 eee102f: expected in v4.4.8

It seems fixed for me on release/v5.1 Thank you for not giving up on a two year old bug !

ESP-YTGerd commented 1 month ago

@ESP-YTGerd How about the fix for v5.2 branch?

Hi, @AxelLin Fix for branch release/v5.2 has been updated in above table.