search

espressif / esp-idf

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

ASSERT_PARAM(131072 0), in rwble.c at line 235 (IDFGH-1094) #3415

Closed no1seman closed 4 years ago

no1seman commented 5 years ago

Environment

Problem Description

When using BLE GAP ADV & BLE GAP SCAN & MQTT & WIFI STA & calling from HTTP Server handler uxTaskGetSystemState() got ASSERT_PARAM(131072 0), in rwble.c at line 235 If uxTaskGetSystemState() is not called everything works fine for at least a few weeks (see code here: https://github.com/no1seman/esp_rwble_bug)

Is there a problem when calling uxTaskGetSystemState() from pthred?

Expected Behavior

No error

Actual Behavior

got ASSERT_PARAM(131072 0), in rwble.c at line 235

Steps to repropduce

  1. Run the code on device
  2. After it starts run in a separate console the following script:

    !/bin/bash

    while true do curl http://IP_OF_DEVICE/ps echo -e "\n" done

  3. After some time you we got ASSERT_PARAM(131072 0), in rwble.c at line 235

N.B. Intensive pulling of device by curl is needed only for reducing time to get error, under other circumstances, the error still occurs, but after a few hours/days

Code to reproduce this issue

https://github.com/no1seman/esp_rwble_bug

Debug Logs

log.zip

Weijian-Espressif commented 5 years ago

@no1seman, I will try to reproduce the issue with your test code, thanks,

no1seman commented 5 years ago

@Weijian-Espressif,

FYI, last days I tried to move from BlueDroid to NimBLE preview stack and i've got ASSERT_PARAM(64 0), in rwble.c at line 235. Same line, but another assert. My goal is the same: to scan and advertice simultaneously and in the end I need that one device can act as GATT client and GATT server at the same time, but seems that there is some data race or deadlock in BLE controller code because when I made high load (intensively scan and advertise) I've got assertion on in rwble.c at line 235 or there is some mistake in my code??

rochamorelli commented 5 years ago

I'm having a similar (maybe same) problem, ASSERT_PARAM(8 0), in rwble.c at line 235 on a linux, using make and an ESP32-WROOM-32D.

git describe --tags -> v4.0-dev-311-g70eda3d22 xtensa-esp32-elf-gcc --version -> xtensa-esp32-elf-gcc (crosstool-NG crosstool-ng-1.22.0-80-g6c4433a) 5.2.0

It can take from a few hours up to a few days before happening, but I've seen it only during light sleep. Have ble scanning before entering light sleep, not making any king of connection, and wifi enabled only during ota (not active during the crash).

ASSERT_PARAM(8 0), in rwble.c at line 235

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Core 0 register dump:
PC      : 0x40086acd  PS      : 0x00060034  A0      : 0x8008a9ac  A1      : 0x3ffbf2b0  
A2      : 0x00000001  A3      : 0x00000000  A4      : 0x00000000  A5      : 0x60008054  
A6      : 0x3ffbdccc  A7      : 0x60008050  A8      : 0x80086acd  A9      : 0x3ffbf290  
A10     : 0x00000004  A11     : 0x00000000  A12     : 0x6000804c  A13     : 0xffffffff  
A14     : 0x00000000  A15     : 0xfffffffc  SAR     : 0x00000004  EXCCAUSE: 0x00000005  

EXCVADDR: 0x00000000  LBEG    : 0x40086a05  LEND    : 0x40086a0c  LCOUNT  : 0x00000000  

Core 0 was running in ISR context:
EPC1    : 0x4000bff0  EPC2    : 0x4000bff0  EPC3    : 0x00000000  EPC4    : 0x40086acd
ELF file SHA256: 1d23366b13d0df1a6ad1e4e1586e1c0d959a3798c831c2989bfe18c9ed62cd6b

Backtrace: 0x40086acd:0x3ffbf2b0 0x4008a9a9:0x3ffbf2d0 0x4008b597:0x3ffbf2f0 0x40085016:0x3ffbf310 0x4000bfed:0x3ffbb9f0 0x40093da1:0x3ffbba00 0x4016fe73:0x3ffbba20 0x401072f5:0x3ffbba50 0x400d072c:0x3ffbba90 0x40093289:0x3ffbbab0

0x40086acd: r_assert_param at ??:?
0x4008a9a9: r_rwble_isr at ??:?
0x4008b597: r_rwbtdm_isr_wrapper at intc.c:?
0x40085016: _xt_lowint1 at /home/esp/esp-idf/components/freertos/xtensa_vectors.S:1154
0x4000bfed: ?? ??:0
0x40093da1: vTaskExitCritical at /home/esp/esp-idf/components/freertos/tasks.c:3508
0x4016fe73: esp_light_sleep_start at /home/esp/esp-idf/components/esp32/sleep_modes.c:524
0x401072f5: app_main at /home/esp/project/xxx/main/xxx_main.cpp:169
0x400d072c: main_task at /home/esp/esp-idf/components/esp32/cpu_start.c:529
0x40093289: vPortTaskWrapper at /home/esp/esp-idf/components/freertos/port.c:403
no1seman commented 5 years ago

@Weijian-Espressif, still faced with: ASSERT_PARAM(64 0), in rwble.c at line 235 Guru Meditation Error: Core 0 panic'ed (Interrupt wdt timeout on CPU0) Core 0 register dump: PC : 0x4008423d PS : 0x00060034 A0 : 0x80088140 A1 : 0x3ffbe240
0x4008423d: r_assert_param at ??:?

A2 : 0x00000001 A3 : 0x00000000 A4 : 0x00000000 A5 : 0x60008054
A6 : 0x3ffbdbb4 A7 : 0x60008050 A8 : 0x8008423d A9 : 0x3ffbe220
A10 : 0x00000004 A11 : 0x00000000 A12 : 0x6000804c A13 : 0xffffffff
A14 : 0x00000000 A15 : 0xfffffffc SAR : 0x00000004 EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000 LBEG : 0x40084175 LEND : 0x4008417c LCOUNT : 0x00000000
0x40084175: r_assert_param at ??:?

0x4008417c: r_assert_param at ??:?

Core 0 was running in ISR context: EPC1 : 0x4010d4b6 EPC2 : 0x00000000 EPC3 : 0x00000000 EPC4 : 0x4008423d 0x4010d4b6: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

0x4008423d: r_assert_param at ??:? ELF file SHA256: 2c322fb8728b298940f4cdd90e575794a390d88a8ba84d8279afc01a6c54d3fb Backtrace: 0x4008423d:0x3ffbe240 0x4008813d:0x3ffbe260 0x40088d2b:0x3ffbe280 0x4008278d:0x3ffbe2a0 0x4010d4b3:0x3ffbbec0 0x400d291f:0x3ffbbee0 0x4008d591:0x3ffbbf00 0x4008bb0d:0x3ffbbf20 0x4008423d: r_assert_param at ??:? 0x4008813d: r_rwble_isr at ??:? 0x40088d2b: r_rwbtdm_isr_wrapper at intc.c:? 0x4008278d: _xt_lowint1 at /home/user/esp/esp-mdf/esp-idf/components/freertos/xtensa_vectors.S:1154 0x4010d4b3: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493 0x400d291f: esp_vApplicationIdleHook at /home/user/esp/esp-mdf/esp-idf/components/esp_common/src/freertos_hooks.c:86 0x4008d591: prvIdleTask at /home/user/esp/esp-mdf/esp-idf/components/freertos/tasks.c:3508 0x4008bb0d: vPortTaskWrapper at /home/user/esp/esp-mdf/esp-idf/components/freertos/port.c:403

Core 1 register dump: PC : 0x4010d4b6 PS : 0x00060034 A0 : 0x800d2922 A1 : 0x3ffbc640
0x4010d4b6: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

A2 : 0x00000000 A3 : 0x00000001 A4 : 0x8008bd16 A5 : 0x3ffbc570
A6 : 0x00000003 A7 : 0x00060023 A8 : 0x800d23be A9 : 0x3ffbc610
A10 : 0x00000000 A11 : 0x00000001 A12 : 0x8008bd16 A13 : 0x3ffbc550
A14 : 0x00000003 A15 : 0x00060023 SAR : 0x00000000 EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000 LBEG : 0x00000000 LEND : 0x00000000 LCOUNT : 0x00000000

ELF file SHA256: 2c322fb8728b298940f4cdd90e575794a390d88a8ba84d8279afc01a6c54d3fb Backtrace: 0x4010d4b6:0x3ffbc640 0x400d291f:0x3ffbc660 0x4008d591:0x3ffbc680 0x4008bb0d:0x3ffbc6a0 0x4010d4b6: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493 0x400d291f: esp_vApplicationIdleHook at /home/user/esp/esp-mdf/esp-idf/components/esp_common/src/freertos_hooks.c:86 0x4008d591: prvIdleTask at /home/user/esp/esp-mdf/esp-idf/components/freertos/tasks.c:3508 0x4008bb0d: vPortTaskWrapper at /home/user/esp/esp-mdf/esp-idf/components/freertos/port.c:403

CPU halted.

Weijian-Espressif commented 5 years ago

@rochamorelli ,

  1. Currently, ESP-IDF does not support Bluetooth controller enable and enters light sleep mode. Because some power domains of the system will be clock gated, Bluetooth will not work properly.

  2. If you look at $IDF_PATH/components/bt/bt.c, it will be called in the esp_bt_controller_enable function: esp_pm_lock_acquire(s_light_sleep_pm_lock); This is to prevent the system from automatically entering light sleep after Bluetooth is turned on (in the case of automatic light sleep) Bottom), but can't prevent users from calling esp_pm_light_sleep() to enter light sleep

  3. If the you wants to use light sleep, then you need to call the esp_bt_controller_disable function to turn off the Bluetooth function before the light sleep.

Weijian-Espressif commented 5 years ago

@no1seman , This bug has appeared only once, we can't reproduce the issue stably, so the debug is very difficult for us. We have also used the customer's test code and there is no stable reproduce. We don't know where the difference is. If you have a better way to reproduce, please let me know.

no1seman commented 5 years ago

@Weijian-Espressif, right now I run again my test code (https://github.com/no1seman/esp_rwble_bug) and got the same error on latest ESP-IDF: v4.0-dev-667-gda13efc17. I set power management off, wifi & BT coexist in balance mode and got the same behaivor on different boards: Wrover kit 4.1, TTGO T4, TTGO T8, own design board based on WROVER-B. For me it reproduces stable after 1-30 minutes run. All you need is to change WIFI_SSID and WIFI_PASSWORD in main.h to able board to connect to wifi, set MAX_CPU_FREQUENCY to 80Mhz, build my code, place 2-3 beacons (Eddystone TLM) near test device and run provided script to provoke the error:

!/bin/bash

while true do curl http://IP_OF_DEVICE/ps echo -e "\n" done PS As you can see in code theres no any power managemt usage, but error is related to power managent: ASSERT_PARAM(131072 0), in rwble.c at line 235 Guru Meditation Error: Core 0 panic'ed (Interrupt wdt timeout on CPU0) Core 0 register dump: PC : 0x400871b6 PS : 0x00060c34 A0 : 0x8008b078 A1 : 0x3ffbe6e0
0x400871b6: r_assert_param at ??:?

A2 : 0x00000001 A3 : 0x00000000 A4 : 0x00000000 A5 : 0x60008054
A6 : 0x3ffbdccc A7 : 0x60008050 A8 : 0x800871b1 A9 : 0x3ffbe6c0
A10 : 0x00000004 A11 : 0x00000000 A12 : 0x6000804c A13 : 0xffffffff
A14 : 0x00000000 A15 : 0xfffffffc SAR : 0x00000004 EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000 LBEG : 0x400870e9 LEND : 0x400870f0 LCOUNT : 0x00000000
0x400870e9: r_assert_param at ??:?

0x400870f0: r_assert_param at ??:?

Core 0 was running in ISR context: EPC1 : 0x40089ae5 EPC2 : 0x00000000 EPC3 : 0x00000000 EPC4 : 0x400871b6 0x40089ae5: r_lld_evt_end_isr at ??:?

0x400871b6: r_assert_param at ??:?

ELF file SHA256: 74c1a4467b408d96f7fda314a59821441306759363e7b1608c6535d4e40c7d50

Backtrace: 0x400871b6:0x3ffbe6e0 0x4008b075:0x3ffbe700 0x4008bc63:0x3ffbe720 0x4008554d:0x3ffbe740 0x4008bc75:0x3ffbb620 0x400d6f66:0x3ffbb640 0x40094041:0x3ffbb660 0x400920d9:0x3ffbb680 0x400871b6: r_assert_param at ??:?

0x4008b075: r_rwble_isr at ??:?

0x4008bc63: r_rwbtdm_isr_wrapper at intc.c:?

0x4008554d: _xt_lowint1 at /home/user/esp/esp-mdf/esp-idf/components/freertos/xtensa_vectors.S:1154

0x4008bc75: r_rwbtdm_isr_wrapper at intc.c:?

0x400d6f66: esp_vApplicationIdleHook at /home/user/esp/esp-mdf/esp-idf/components/esp_common/src/freertos_hooks.c:86

0x40094041: prvIdleTask at /home/user/esp/esp-mdf/esp-idf/components/freertos/tasks.c:4538

0x400920d9: vPortTaskWrapper at /home/user/esp/esp-mdf/esp-idf/components/freertos/port.c:435

Core 1 register dump: PC : 0x401c715a PS : 0x00060334 A0 : 0x800d6f69 A1 : 0x3ffbbbc0
0x401c715a: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

A2 : 0x00000000 A3 : 0x00000001 A4 : 0x800922d2 A5 : 0x3ffbbaf0
A6 : 0x00000003 A7 : 0x00060023 A8 : 0x800d690e A9 : 0x3ffbbb90
A10 : 0x00000000 A11 : 0x00000001 A12 : 0x00000000 A13 : 0x00000000
A14 : 0x02ffffff A15 : 0x00060023 SAR : 0x00000000 EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000 LBEG : 0x40099cc4 LEND : 0x40099ccf LCOUNT : 0xffffffff
0x40099cc4: memset at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xtensa/../../../../.././newlib/libc/machine/xtensa/memset.S:142

0x40099ccf: memset at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xtensa/../../../../.././newlib/libc/machine/xtensa/memset.S:152

ELF file SHA256: 74c1a4467b408d96f7fda314a59821441306759363e7b1608c6535d4e40c7d50

Backtrace: 0x401c715a:0x3ffbbbc0 0x400d6f66:0x3ffbbbe0 0x40094041:0x3ffbbc00 0x400920d9:0x3ffbbc20 0x401c715a: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

0x400d6f66: esp_vApplicationIdleHook at /home/user/esp/esp-mdf/esp-idf/components/esp_common/src/freertos_hooks.c:86

0x40094041: prvIdleTask at /home/user/esp/esp-mdf/esp-idf/components/freertos/tasks.c:4538

0x400920d9: vPortTaskWrapper at /home/user/esp/esp-mdf/esp-idf/components/freertos/port.c:435

CPU halted.

Weijian-Espressif commented 5 years ago

@no1seman , The issue I am talking about is ASSERT_PARAM(64 0), in rwble.c at line 235, Is there a way to reproduce this issue?

no1seman commented 5 years ago

@Weijian-Espressif, I've got this issue when I experimented with nimble stack. I can't provide working code cause I've to change them but I'll try to reproduce it. What can you say about: ASSERT_PARAM(131072 0), in rwble.c at line 235 error? Is there some config mistakes or my code errors or it's a problem in bt controller code?

Weijian-Espressif commented 5 years ago

@no1seman, I build your esp_rwble_bug

It alaways reset 

Leaving...
Hard resetting via RTS pin...
MONITOR
--- WARNING: Serial ports accessed as /dev/tty.* will hang gdb if launched.
--- Using /dev/cu.usbserial-00002714B instead...
--- idf_monitor on /dev/cu.usbserial-00002714B 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
?ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x1e (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:0x3fff0018,len:4
load:0x3fff001c,len:1048
load:0x40078000,len:10204
load:0x40080400,len:6424
entry 0x400806a8
ets Jun  8 2016 00:22:57

rst:0x3 (SW_RESET),boot:0x1e (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:0x3fff0018,len:4
load:0x3fff001c,len:1048
load:0x40078000,len:10204
load:0x40080400,len:6424
entry 0x400806a8
ets Jun  8 2016 00:22:57

rst:0x3 (SW_RESET),boot:0x1e (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:0x3fff0018,len:4
load:0x3fff001c,len:1048
load:0x40078000,len:10204
load:0x40080400,len:6424
entry 0x400806a8
ets Jun  8 2016 00:22:57

rst:0x3 (SW_RESET),boot:0x1e (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:0x3fff0018,len:4
load:0x3fff001c,len:1048
load:0x40078000,len:10204
load:0x40080400,len:6424
entry 0x400806a8
ets Jun  8 2016 00:22:57
no1seman commented 5 years ago

@Weijian-Espressif, I'm using cmake not make, and you have to set Serial flasher config and SPI RAM, on my boards i'm using 16Mb flash and 4M SPI-RAM

no1seman commented 5 years ago

@Weijian-Espressif, I restored the code that throws ASSERT_PARAM(64 0), in rwble.c at line 235 after 3,75 hours run with nimble stack, here is the log: I (13500103) BLE: Eddystone TLM: {MAC: B8:27:EB:AF:07:89, Name: '0000jffjtv', Adv data RSSI: -59 dBm, Scan resp RSSI: -59, Version: 0, Battery: 200 mV, Temperature: 43.0, Count: 20245, Uptime: 1213819.0 s} ASSERT_PARAM(64 0), in rwble.c at line 235 Guru Meditation Error: Core 0 panic'ed (Interrupt wdt timeout on CPU0) Core 0 register dump: PC : 0x40084241 PS : 0x00060034 A0 : 0x80088144 A1 : 0x3ffbe240
0x40084241: r_assert_param at ??:?

A2 : 0x00000001 A3 : 0x00000000 A4 : 0x00000000 A5 : 0x60008054
A6 : 0x3ffbdbb4 A7 : 0x60008050 A8 : 0x80084241 A9 : 0x3ffbe220
A10 : 0x00000004 A11 : 0x00000000 A12 : 0x6000804c A13 : 0xffffffff
A14 : 0x00000000 A15 : 0xfffffffc SAR : 0x00000004 EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000 LBEG : 0x40084179 LEND : 0x40084180 LCOUNT : 0x00000000
0x40084179: r_assert_param at ??:?

0x40084180: r_assert_param at ??:?

Core 0 was running in ISR context: EPC1 : 0x4010d4b6 EPC2 : 0x00000000 EPC3 : 0x00000000 EPC4 : 0x40084241 0x4010d4b6: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

0x40084241: r_assert_param at ??:?

ELF file SHA256: 4230e9956ef2988f68025bb61f1796ac8fd32a6fbfc826d97e2c675bf347b5db

Backtrace: 0x40084241:0x3ffbe240 0x40088141:0x3ffbe260 0x40088d2f:0x3ffbe280 0x40082791:0x3ffbe2a0 0x4010d4b3:0x3ffbbec0 0x400d291f:0x3ffbbee0 0x4008d595:0x3ffbbf00 0x4008bb11:0x3ffbbf20 0x40084241: r_assert_param at ??:?

0x40088141: r_rwble_isr at ??:?

0x40088d2f: r_rwbtdm_isr_wrapper at intc.c:?

0x40082791: _xt_lowint1 at /home/user/esp/esp-mdf/esp-idf/components/freertos/xtensa_vectors.S:1154

0x4010d4b3: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

0x400d291f: esp_vApplicationIdleHook at /home/user/esp/esp-mdf/esp-idf/components/esp_common/src/freertos_hooks.c:86

0x4008d595: prvIdleTask at /home/user/esp/esp-mdf/esp-idf/components/freertos/tasks.c:3508

0x4008bb11: vPortTaskWrapper at /home/user/esp/esp-mdf/esp-idf/components/freertos/port.c:403

Core 1 register dump: PC : 0x4010d4b6 PS : 0x00060034 A0 : 0x800d2922 A1 : 0x3ffbc640
0x4010d4b6: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

A2 : 0x00000000 A3 : 0x00000001 A4 : 0x8008bd1a A5 : 0x3ffbc570
A6 : 0x00000003 A7 : 0x00060023 A8 : 0x800d23be A9 : 0x3ffbc610
A10 : 0x00000000 A11 : 0x00000001 A12 : 0x8008bd1a A13 : 0x3ffbc550
A14 : 0x00000003 A15 : 0x00060023 SAR : 0x00000000 EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000 LBEG : 0x00000000 LEND : 0x00000000 LCOUNT : 0x00000000

ELF file SHA256: 4230e9956ef2988f68025bb61f1796ac8fd32a6fbfc826d97e2c675bf347b5db

Backtrace: 0x4010d4b6:0x3ffbc640 0x400d291f:0x3ffbc660 0x4008d595:0x3ffbc680 0x4008bb11:0x3ffbc6a0 0x4010d4b6: esp_pm_impl_waiti at /home/user/esp/esp-mdf/esp-idf/components/esp32/pm_esp32.c:493

0x400d291f: esp_vApplicationIdleHook at /home/user/esp/esp-mdf/esp-idf/components/esp_common/src/freertos_hooks.c:86

0x4008d595: prvIdleTask at /home/user/esp/esp-mdf/esp-idf/components/freertos/tasks.c:3508

0x4008bb11: vPortTaskWrapper at /home/user/esp/esp-mdf/esp-idf/components/freertos/port.c:403

CPU halted. PS I don't want to publish source code, but if you need it - tell me how can I send it to you?

Weijian-Espressif commented 5 years ago

@no1seman , I can not run your test code, it alaways 

rst:0x3 (SW_RESET),boot:0x1e (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:0x3fff0018,len:4
load:0x3fff001c,len:1048
load:0x40078000,len:10204
load:0x40080400,len:6424
entry 0x400806a8
ets Jun  8 2016 00:22:57

rst:0x3 (SW_RESET),boot:0x1e (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:0x3fff0018,len:4
load:0x3fff001c,len:1048
load:0x40078000,len:10204
load:0x40080400,len:6424
entry 0x400806a8
ets Jun  8 2016 00:22:57

ASSERT_PARAM(131072 0) indicates that the previous interrupt has not been processed yet, and the next interrupt is coming again. It should be that the controller processing is delayed, I will provide you a new lib to test later.

You can also set the CPU frequency to 160MHz or 240MHz, and try again.

no1seman commented 5 years ago

@Weijian-Espressif, thanks for diagnostic of the problem, now I understand the root of the problem, but anyway increasing CPU frequency to 160MHz or 240MHz is not a solution, because I began that tests after my devices running on 240 Mhz halt after a week or two weeks, or after a day, at some point there was a situation when the load on the BLE and Wi-Fi coincided in time, the processor didn't process interrupts and the system fell out in halt or reboot (depens on sdkconfig settings). It's not a good situation when IoT device may halt in any time. Also I seems to me that it's not right logic, that ISR handler hang system execution if previous interrupt is not finished execution, especially on esp32 where BT and Wi-Fi uses single RF. In such situation Ethernet is droping the data and goes on.

Weijian-Espressif commented 5 years ago

@no1seman , I build and flash your test code, it always reset. I can not reproduce the issue. Can you help me do a test ? Please update to the latest IDF, replace the Bluetooth lib in components/bt/lib/libbtdm_app.a and try. Bluetooth lib will print BLE TEST CRASH_131072 three times. BLE_TEST_CRASH_131072.zip

no1seman commented 5 years ago

@Weijian-Espressif, sure, here it is: log on latest IDF before replacing libbtdm: vanilla_libbtdm_app.a.zip

log on latest IDF after replacing libbtdm: modified_libbtdm_app.a.zip

Now I've got: ASSERT_PARAM(0 0), in rwble.c at line 241 ...

P.S. can't understand why it always reset. Are you using sdkconfig settings from my repo? May be the problem is in Use RTC watchdog in start code or QIO mode flash settings. Is it possible that problem is in using external PSRAM with agressive SPIRAM_MALLOC_ALWAYSINTERNAL = 128?

Weijian-Espressif commented 5 years ago

@no1seman Sorry, I add a print in the lib, please try again, thanks. NEW_LIB.zip

no1seman commented 5 years ago

@Weijian-Espressif,

no problem, here is a new log: new_log.zip

no1seman commented 5 years ago

@Weijian-Espressif,

still facing the ASSERT_PARAM(131072 0), in rwble.c at line 235 error on latest IDF version: v4.0-dev-1275-gfdab15dc7. If there any chances to fix the problem or recomendations for workaround? Need any involvement?

MrHezhisheng commented 5 years ago

I'm having trouble rebooting. Here's the print log:

ASSERT_PARAM(1024 0), in rwble.c at line 230 ets Jun 8 2016 00:22:57

rst:0x8 (TG1WDT_SYS_RESET),boot:0x33 (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:0x3fff0018,len:4 load:0x3fff001c,len:720 ho 0 tail 12 room 4 load:0x40078000,len:6940 load:0x40080000,len:5812 entry 0x40080e08 eFuse Two Point: NOT supported firmware version is:25.01.005 build time: Jul 22 2019, 17:08:32 篚�\0�廊趔?\0\0\0鬗icroPython 7adfb6c2-dirty on 2019-07-22; ESP32 module with ESP32 Type "help()" for more information.

Can you give me some advice?

no1seman commented 5 years ago

Hi All! Just updated to v4.0-dev-1329-g308d03456 and got the same bug. I pushed some changes to test example that reproduces the issue: https://github.com/no1seman/esp_rwble_bug To reproduce you have to:

  1. clone repo

  2. change 3 defines in main.h:

    define WIFI_SSID "*" //WiFi SSID name

    define WIFI_PASSWORD "*" //actual password for AP

    define MQTT_CRED "1yi5q0xqwl" //login\pasword to access local mqtt server, may be needed some code changes to connect to your mqtt server

  3. build and flash (you may use run.sh from repo under linux but may be need to change some pathes)

  4. You need at least one Eddystone TLM beacon with 250 ms adv period

  5. Then flash just change IP ip in test.sh to actual ip of esp32 wifi sta interface and run it

So, after that I've got stable error - ASSERT_PARAM(131072 0), in rwble.c at line 235:

Hard resetting via RTS pin... --- idf_monitor on /dev/ttyUSB0 115200 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ets Jun 8 2016 00:22:57

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:0x3fff0018,len:4 load:0x3fff001c,len:1300 load:0x40078000,len:11024 load:0x40080400,len:6728 entry 0x400806ac I (498) psram: This chip is ESP32-D0WD I (499) spiram: Found 64MBit SPI RAM device I (499) spiram: SPI RAM mode: flash 40m sram 40m I (502) spiram: PSRAM initialized, cache is in low/high (2-core) mode. I (509) cpu_start: Pro cpu up. I (513) cpu_start: Application information: I (517) cpu_start: Project name: rwble_bug I (523) cpu_start: App version: 2fa3c42-dirty I (528) cpu_start: Compile time: Jul 25 2019 11:23:08 I (534) cpu_start: ELF file SHA256: d94f810fed7502ed... I (540) cpu_start: ESP-IDF: v4.0-dev-1329-g308d03456-dirty I (547) cpu_start: Starting app cpu, entry point is 0x400816b8 0x400816b8: call_start_cpu1 at /home/user/esp/esp-mdf/esp-idf/components/esp32/cpu_start.c:283

I (0) cpu_start: App cpu up. I (559) heap_init: Initializing. RAM available for dynamic allocation: I (564) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (570) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (577) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (583) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM I (589) heap_init: At 3FFC3B48 len 0001C4B8 (113 KiB): DRAM I (595) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (601) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (608) heap_init: At 4009F0F4 len 00000F0C (3 KiB): IRAM I (614) cpu_start: Pro cpu start user code I (619) spiram: Adding pool of 4077K of external SPI memory to heap allocator I (1202) spi_flash: detected chip: generic I (1203) spi_flash: flash io: qio I (1204) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (1212) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations I (1322) rwble_bug: Initialize ESP32 NVS... I (1392) rwble_bug: Initialize WiFi... I (1422) wifi: wifi driver task: 3ffbd940, prio:23, stack:3584, core=0 I (1422) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (1422) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (1662) wifi: wifi firmware version: fc2a27d I (1662) wifi: config NVS flash: enabled I (1662) wifi: config nano formating: disabled I (1662) wifi: Init dynamic tx buffer num: 32 I (1662) wifi: Init data frame dynamic rx buffer num: 16 I (1672) wifi: Init management frame dynamic rx buffer num: 16 I (1672) wifi: Init management short buffer num: 16 I (1682) wifi: Init static tx buffer num: 10 I (1692) wifi: Init static rx buffer size: 1600 I (1692) wifi: Init static rx buffer num: 10 I (1692) wifi: Init dynamic rx buffer num: 16 W (1822) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration I (1962) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 2 I (2082) wifi: mode : sta (b4:e6:2d:ee:7e:75) I (2082) wifi: Set ps type: 0

I (2202) wifi: new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1 I (4452) wifi: state: init -> auth (b0) I (4462) wifi: state: auth -> assoc (0) I (4462) wifi: state: assoc -> run (10) I (4482) wifi: connected with NNE1, channel 1, 40U, bssid = 6c:3b:6b:19:6e:47 I (4542) wifi: pm start, type: 0

I (5462) tcpip_adapter: sta ip: 192.168.3.130, mask: 255.255.255.0, gw: 192.168.3.1 I (5462) rwble_bug: SYSTEM_EVENT_STA_GOT_IP I (5462) esp_https_server: Starting server I (5462) rwble_bug: MQTT_EVENT_BEFORE_CONNECT I (5472) esp_https_server: Server listening on port 80 I (5482) rwble_bug: WiFi init finished! I (5482) rwble_bug: Setting up BLE GAP ... I (5492) MQTT_CLIENT: Sending MQTT CONNECT message, type: 1, id: 0000 I (5502) BTDM_INIT: BT controller compile version [4d3bde7] I (5502) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (5522) rwble_bug: MQTT client connected I (6352) rwble_bug: Scan started successfully I (13402) rwble_bug: Eddystone TLM: {MAC: B8:27:EB:C0:7C:C3, Name: 0000124mfzd, RSSI: -39 dBm, Version: 0, Battery: 0 mV, Temperature: 63.0, Count: 2301070, Uptime: 2502435.0 s} I (13532) rwble_bug: MQTT message published: msg_id=36880 I (20032) rwble_bug: Eddystone TLM: {MAC: B8:27:EB:C0:7C:C3, Name: 0000124mfzd, RSSI: -38 dBm, Version: 0, Battery: 0 mV, Temperature: 63.0, Count: 2301076, Uptime: 2502441.0 s} I (20292) rwble_bug: MQTT message published: msg_id=13545 I (24252) rwble_bug: Eddystone TLM: {MAC: B8:27:EB:C0:7C:C3, Name: 0000124mfzd, RSSI: -39 dBm, Version: 0, Battery: 0 mV, Temperature: 63.0, Count: 2301080, Uptime: 2502445.0 s} I (24502) rwble_bug: MQTT message published: msg_id=12157 I (25462) rwble_bug: Eddystone TLM: {MAC: B8:27:EB:C0:7C:C3, Name: 0000124mfzd, RSSI: -38 dBm, Version: 0, Battery: 0 mV, Temperature: 63.0, Count: 2301081, Uptime: 2502447.0 s} I (25502) rwble_bug: MQTT message published: msg_id=12073 I (26612) rwble_bug: Eddystone TLM: {MAC: B8:27:EB:C0:7C:C3, Name: 0000124mfzd, RSSI: -39 dBm, Version: 0, Battery: 0 mV, Temperature: 63.0, Count: 2301082, Uptime: 2502448.0 s} I (26752) rwble_bug: MQTT message published: msg_id=19810 I (31902) rwble_bug: Eddystone TLM: {MAC: B8:27:EB:C0:7C:C3, Name: 0000124mfzd, RSSI: -38 dBm, Version: 0, Battery: 0 mV, Temperature: 63.0, Count: 2301087, Uptime: 2502453.0 s} <---------- Here is a point in time when test.sh run I (31962) rwble_bug: MQTT message published: msg_id=44112 I (35102) rwble_bug: Eddystone TLM: {MAC: B8:27:EB:C0:7C:C3, Name: 0000124mfzd, RSSI: -37 dBm, Version: 0, Battery: 0 mV, Temperature: 64.0, Count: 2301090, Uptime: 2502456.0 s} I (35162) rwble_bug: MQTT message published: msg_id=58376 <-------- MQTT client disconnect because of intensive use of wifi connection by http (test.h) E (40162) MQTT_CLIENT: No PING_RESP, disconnected I (40172) rwble_bug: MQTT client disconnected I (50192) rwble_bug: MQTT_EVENT_BEFORE_CONNECT I (50202) MQTT_CLIENT: Sending MQTT CONNECT message, type: 1, id: 0000 I (50222) rwble_bug: MQTT client connected ASSERT_PARAM(131072 0), in rwble.c at line 235

Does anybody try to run that test and confirm the issue?

P.S. Yes? I know that this example is synthetic and that it's not good idea to DDOS esp32 that way, but in real application i've got 1-2 weeks run and then in some moment, when the stars parted in the sky I've got ASSERT_PARAM(131072 0), in rwble.c at line 235. Intensive usage of http over wifi is only the way to reduce the time to get error.

rochamorelli commented 5 years ago

I've been using 3.3-beta3 and it is far more stable for me, using BLE intensively with light sleep and not disabling BLE because looping through enabling/disabling for sleep crashes really quick

no1seman commented 5 years ago

@rochamorelli, on 3.3 I've got the same error, so it's not a solution

rochamorelli commented 5 years ago

Definitely not, but it's more stable for my use case. Maybe it would work better for someone else fiddling on the internet while we wait for a fix :)

gengyuchao commented 5 years ago

You can try to unzip and replace this file in the "/esp-idf/components/bt/controller/lib/libbtdm_app.a" directory and try to see if it works. I hope to get your feedback. libbtdm_app.a.zip

no1seman commented 5 years ago

@gengyuchao, well, after an hour-long intensive test, the error ASSERT_PARAM(131072 0), in rwble.c at line 235 does not occur. I'll continue tests but seems that everything works well with provided version of bt lib. Thanks for solution, sure it will be commited to master branch soon

PS Periodically got 'ELx20000' in console log. It's bt lib (ld_acl.c) debug logging or smth else?

gengyuchao commented 5 years ago

@gengyuchao, well, after an hour-long intensive test, the error ASSERT_PARAM(131072 0), in rwble.c at line 235 does not occur. I'll continue tests but seems that everything works well with provided version of bt lib. Thanks for solution, sure it will be commited to master branch soon

PS Periodically got 'ELx20000' in console log. It's bt lib (ld_acl.c) debug logging or smth else?

Yes, that's the debug log, and this shows the previous situation happened again and a new code was run. I am debugging it. I want to know if it will affect your functionality or will it create new problems when you see this log? If there is no problem that is really great.

no1seman commented 5 years ago

@gengyuchao, presently i'm using only nimble: GAP advertise, GAP discovery, GATT peripheral without bonding simalteneously. At first look everything works fine. If there some problems I'll infrorm you. Thank you for solving the issue.

no1seman commented 4 years ago

After latest update of esp-idf (master branch: https://github.com/espressif/esp-idf/commit/d57890cdff10648371bc13956230635d2944d254), framework (bt controller: https://github.com/espressif/esp32-bt-lib/commit/dfe091f45f8a46cc46ea095e5e58021128e3d35f) again got ASSERT_PARAM(64 0), in rwble.c at line 235 after longtime test. My app crashed after ~2 h.

pschlan commented 4 years ago

After latest update of esp-idf (master branch: d57890c), framework (bt controller: espressif/esp32-bt-lib@dfe091f) again got ASSERT_PARAM(64 0), in rwble.c at line 235 after longtime test. My app crashed after ~2 h.

Seeing this as well after a couple of hours. Any news here? Thanks.

GYC-Espressif commented 4 years ago

Hello, this is a new issue. we cannot reproduce this issue through the code above. Can you open a new issue and provide some related information to help us reproduce this problem? Thank you.

Alvin1Zhang commented 4 years ago

@no1seman Thanks for reporting, for the original issue in this ticket, https://github.com/espressif/esp-idf/commits/7d39f435 has fixed, right? And for the new issue "After latest update of esp-idf (master branch: d57890c), framework (bt controller: espressif/esp32-bt-lib@dfe091f) again got ASSERT_PARAM(64 0), in rwble.c at line 235 after longtime test. My app crashed after ~2 h.", would you please help file a separate ticket? We would like to close this ticket and follow up in your new issue. Thanks.