search

espressif / esp-rainmaker

ESP RainMaker Agent for firmware development
Apache License 2.0
431 stars 145 forks source link

'assert failed: spinlock_acquire....' during provisioning (MEGH-4227) #229

Closed jacek12345 closed 1 year ago

jacek12345 commented 1 year ago

Everything works for some time. Since some moment i can't make provisioning. The only thing that fix it is erase-flash command. Then it works for some time. I enabled Debug in menuconfig and see assert failed: spinlock_acquire spinlock.h:123 ((result == SPINLOCK_FREE) == (lock->count == 0))

Whole log:

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3808,len:0x1660
load:0x403c9700,len:0xbb8
load:0x403cc700,len:0x2e8c
entry 0x403c9954
I (24) boot: ESP-IDF v4.4.3 2nd stage bootloader
I (25) boot: compile time 15:16:06
I (25) boot: chip revision: 0
I (26) boot.esp32s3: Boot SPI Speed : 80MHz
I (31) boot.esp32s3: SPI Mode       : DIO
I (36) boot.esp32s3: SPI Flash Size : 8MB
I (40) boot: Enabling RNG early entropy source...
I (46) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 sec_cert         unknown          3f 06 0000d000 00003000
I (64) boot:  1 nvs              WiFi data        01 02 00010000 00006000
I (72) boot:  2 otadata          OTA data         01 00 00016000 00002000
I (79) boot:  3 phy_init         RF data          01 01 00018000 00001000
I (87) boot:  4 ota_0            OTA app          00 10 00020000 003c0000
I (94) boot:  5 ota_1            OTA app          00 11 003e0000 003c0000
I (102) boot:  6 fctry            WiFi data        01 02 007a0000 00006000
I (109) boot:  7 devdata          WiFi data        01 02 007a6000 00003000
I (117) boot:  8 coredump         Unknown data     01 03 007a9000 00010000
I (124) boot: End of partition table
I (129) boot: No factory image, trying OTA 0
I (133) esp_image: segment 0: paddr=00020020 vaddr=3c0f0020 size=480ech (295148) map
I (195) esp_image: segment 1: paddr=00068114 vaddr=3fc9a240 size=04b24h ( 19236) load
I (199) esp_image: segment 2: paddr=0006cc40 vaddr=40374000 size=033d8h ( 13272) load
I (204) esp_image: segment 3: paddr=00070020 vaddr=42000020 size=ef288h (979592) map
I (385) esp_image: segment 4: paddr=0015f2b0 vaddr=403773d8 size=12e64h ( 77412) load
I (402) esp_image: segment 5: paddr=0017211c vaddr=50000000 size=00010h (    16) load
I (411) boot: Loaded app from partition at offset 0x20000
I (468) boot: Set actual ota_seq=1 in otadata[0]
I (468) boot: Disabling RNG early entropy source...
I (479) cpu_start: Pro cpu up.
I (479) cpu_start: Starting app cpu, entry point is 0x40375458
0x40375458: call_start_cpu1 at F:/GitHub/esp-idf-v4.4.3/components/esp_system/port/cpu_start.c:148

Fm(0) cpu_staDt:47p) epus :p.
_BLK2__DATA4_REG is used 2 bits starting with 0 bit
D (486) efuse: In EFUSE_BLK2__DATA4_REG is used 8 bits starting with 13 bit
D (493) efuse: In EFUSE_BLK1__DATA3_REG is used 3 bits starting with 24 bit
D (500) efuse: In EFUSE_BLK2__DATA4_REG is used 2 bits starting with 0 bit
D (507) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit
D (514) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit
D (521) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 11 bit
D (528) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit
D (535) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit
D (542) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit
D (549) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit
D (556) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit
D (563) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit
D (570) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit
D (577) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit
D (584) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit
D (591) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit
D (606) clk: RTC_SLOW_CLK calibration value: 3799194
I (615) cpu_start: Pro cpu start user code
I (615) cpu_start: cpu freq: 160000000
I (615) cpu_start: Application information:
I (618) cpu_start: Project name:     dtmiot1
I (623) cpu_start: App version:      1.1
I (627) cpu_start: Compile time:     Jan 19 2023 15:56:00
I (633) cpu_start: ELF file SHA256:  f6331a4a1df66736...
I (639) cpu_start: ESP-IDF:          v4.4.3
D (644) memory_layout: Checking 5 reserved memory ranges:
D (650) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc9a23c
D (656) memory_layout: Reserved memory range 0x3fc9a240 - 0x3fca6558
D (662) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000
D (669) memory_layout: Reserved memory range 0x40374000 - 0x4038a23c
0x40374000: _WindowOverflow4 at F:/GitHub/esp-idf-v4.4.3/components/freertos/port/xtensa/xtensa_vectors.S:1736

D (675) memory_layout: Reserved memory range 0x600fe000 - 0x600fe000
D (682) memory_layout: Building list of available memory regions:
D (688) memory_layout: Available memory region 0x3fca6558 - 0x3fcb0000
D (694) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000
D (701) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000
D (708) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000
D (714) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710
D (721) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34
D (727) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000
D (734) memory_layout: Available memory region 0x600fe000 - 0x60100000
I (741) heap_init: Initializing. RAM available for dynamic allocation:
D (748) heap_init: New heap initialised at 0x3fca6558
I (753) heap_init: At 3FCA6558 len 000431B8 (268 KiB): D/IRAM
I (759) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
D (766) heap_init: New heap initialised at 0x3fcf0000
I (771) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (777) heap_init: New heap initialised at 0x600fe000
I (782) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
D (789) FLASH_HAL: extra_dummy: 0
D (792) spi_flash: trying chip: issi
D (796) spi_flash: trying chip: gd
D (799) spi_flash: trying chip: mxic
D (803) spi_flash: trying chip: winbond
D (807) spi_flash: trying chip: boya
D (811) spi_flash: trying chip: th
D (814) spi_flash: trying chip: mxic (opi)
D (818) spi_flash: trying chip: generic
I (822) spi_flash: detected chip: generic
I (827) spi_flash: flash io: dio
D (831) cpu_start: calling init function: 0x420d1500
0x420d1500: _GLOBAL__sub_I___cxa_get_globals_fast at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:145

D (836) cpu_start: calling init function: 0x4209bf34
0x4209bf34: esp_ds_conn_lock at F:/GitHub/esp-idf-v4.4.3/components/mbedtls/port/esp_ds/esp_rsa_sign_alt.c:60

D (841) cpu_start: calling init function: 0x4205e4bc
0x4205e4bc: s_set_default_wifi_log_level at F:/GitHub/esp-idf-v4.4.3/components/esp_wifi/src/wifi_init.c:63

D (846) cpu_start: calling init function: 0x4205b048
0x4205b048: esp_reset_reason_init at F:/GitHub/esp-idf-v4.4.3/components/esp_system/port/soc/esp32s3/reset_reason.c:67

D (851) cpu_start: calling init function: 0x4204e534
0x4204e534: esp_ipc_init at F:/GitHub/esp-idf-v4.4.3/components/esp_ipc/src/esp_ipc.c:105

D (856) cpu_start: calling init function: 0x420035ac
0x420035ac: esp_ota_init_app_elf_sha256 at F:/GitHub/esp-idf-v4.4.3/components/app_update/esp_app_desc.c:68

D (861) intr_alloc: Connected src 59 to int 2 (cpu 0)
I (866) sleep: Configure to isolate all GPIO pins in sleep state
I (873) sleep: Enable automatic switching of GPIO sleep configuration
I (880) coexist: coexist rom version e7ae62f
D (885) intr_alloc: Connected src 79 to int 3 (cpu 0)
I (890) cpu_start: Starting scheduler on PRO CPU.
D (896) intr_alloc: Connected src 57 to int 9 (cpu 0)
D (896) intr_alloc: Connected src 80 to int 2 (cpu 1)
I (906) cpu_start: Starting scheduler on APP CPU.
D (906) intr_alloc: Connected src 58 to int 3 (cpu 1)
D (916) heap_init: New heap initialised at 0x3fce9710
D (916) intr_alloc: Connected src 52 to int 12 (cpu 0)
I (926) esp_rmaker_console: Initialising UART on port 0
I (926) esp_rmaker_commands: Registering command: up-time
I (926) uart: queue free spaces: 8
D (936) intr_alloc: Connected src 27 to int 13 (cpu 0)
I (946) esp_rmaker_commands: Registering command: mem-dump
I (946) esp_rmaker_commands: Registering command: task-dump
I (956) esp_rmaker_commands: Registering command: cpu-dump
I (966) esp_rmaker_commands: Registering command: sock-dump
I (966) esp_rmaker_commands: Registering command: heap-trace
I (976) esp_rmaker_commands: Registering command: reset-to-factory
I (986) esp_rmaker_commands: Registering command: add-user
I (986) esp_rmaker_commands: Registering command: get-node-id
I (996) esp_rmaker_commands: Registering command: wifi-prov
I (996) esp_rmaker_commands: Registering command: local-time
I (1006) esp_rmaker_commands: Registering command: tz-set
I (1016) esp_rmaker_commands: Registering command: cmd
D (1016) intr_alloc: Connected src 16 to int 17 (cpu 0)
I (1026) gpio: GPIO[2]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
E (1036) gpio: gpio_install_isr_service(449): GPIO isr service already installed
I (1046) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
I (1046) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1056) gpio: GPIO[18]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
D (1066) rmt: rmt_source_clk_hz: 80000000

D (1076) rmt: Rmt Tx Channel 0|Gpio 48|Sclk_Hz 80000000|Div 2|Carrier_Hz 38000|Duty 33
D (1086) intr_alloc: Connected src 40 to int 18 (cpu 0)
D (1086) rmt: RMT translator init done
I (1086) led_serv: led id:0 initialise...
I (1096) gpio: GPIO[1]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1106) led_serv: led id:1 initialise...
I (1106) gpio: GPIO[11]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1116) led_serv: led id:2 initialise...
I (1126) gpio: GPIO[19]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1136) led_serv: led id:3 initialise...
I (1136) gpio: GPIO[10]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1146) led_serv: led id:4 initialise...
I (1156) gpio: GPIO[6]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
D (1156) partition: Loading the partition table
D (1166) partition: Partition table MD5 verified
W (1226) app_main: reading configuration from NVS
D (1226) nvs: nvs_open_from_partition storage_conf 1
D (1226) nvs: nvs_get_str_or_blob node
D (1226) nvs: nvs_get_str_or_blob out_1
D (1236) nvs: nvs_get_str_or_blob out_2
D (1236) nvs: nvs_get_str_or_blob in_1
D (1236) nvs: nvs_close 1
W (1246) app_main: reading end
D (1246) esp_netif_lwip: LwIP stack has been initialized
D (1246) esp_netif_lwip: esp-netif has been successfully initialized
D (1256) event: running task for loop 0x3fcedeec
D (1266) event: created task for loop 0x3fcedeec
D (1266) event: created event loop 0x3fcedeec
D (1276) esp_netif_objects: esp_netif_add_to_list 0x3fcf60dc
D (1276) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
I (1286) pp: pp rom version: e7ae62f
I (1286) net80211: net80211 rom version: e7ae62f
D (1296) nvs: nvs_open_from_partition misc 1
I (1306) wifi:wifi driver task: 3fcf70ac, prio:23, stack:6656, core=0
I (1306) system_api: Base MAC address is not set
I (1306) system_api: read default base MAC address from EFUSE
D (1316) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1326) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1326) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1336) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1346) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1356) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1356) nvs: nvs_open_from_partition nvs.net80211 1
D (1366) nvs: nvs_get opmode 1
D (1366) nvs: nvs_get_str_or_blob sta.ssid
D (1376) nvs: nvs_get sta.authmode 1
D (1376) nvs: nvs_get_str_or_blob sta.pswd
D (1376) nvs: nvs_get_str_or_blob sta.pmk
D (1386) nvs: nvs_get sta.chan 1
D (1386) nvs: nvs_get auto.conn 1
D (1386) nvs: nvs_get bssid.set 1
D (1396) nvs: nvs_get_str_or_blob sta.bssid
D (1396) nvs: nvs_get sta.lis_intval 2
D (1406) nvs: nvs_get sta.phym 1
D (1406) nvs: nvs_get sta.phybw 1
D (1406) nvs: nvs_get_str_or_blob sta.apsw
D (1416) nvs: nvs_get_str_or_blob sta.apinfo
D (1416) nvs: nvs_get sta.scan_method 1
D (1416) nvs: nvs_get sta.sort_method 1
D (1426) nvs: nvs_get sta.minrssi 1
D (1426) nvs: nvs_get sta.minauth 1
D (1436) nvs: nvs_get sta.pmf_e 1
D (1436) nvs: nvs_get sta.pmf_r 1
D (1436) nvs: nvs_get sta.btm_e 1
D (1446) nvs: nvs_get sta.rrm_e 1
D (1446) nvs: nvs_get sta.mbo_e 1
D (1446) nvs: nvs_get_str_or_blob ap.ssid
D (1456) nvs: nvs_get_str_or_blob ap.passwd
D (1456) nvs: nvs_get_str_or_blob ap.pmk
D (1466) nvs: nvs_get ap.chan 1
D (1466) nvs: nvs_get ap.authmode 1
D (1466) nvs: nvs_get ap.hidden 1
D (1476) nvs: nvs_get ap.max.conn 1
D (1476) nvs: nvs_get bcn.interval 2
D (1476) nvs: nvs_get ap.phym 1
D (1486) nvs: nvs_get ap.phybw 1
D (1486) nvs: nvs_get ap.sndchan 1
D (1486) nvs: nvs_get ap.pmf_e 1
D (1496) nvs: nvs_get ap.pmf_r 1
D (1496) nvs: nvs_get ap.p_cipher 1
D (1496) nvs: nvs_get lorate 1
D (1506) nvs: nvs_get_str_or_blob country
D (1506) nvs: nvs_get ap.ftm_r 1
D (1506) nvs: nvs_set ap.sndchan 1 1
I (1516) wifi:wifi firmware version: 8cb87ff
I (1516) wifi:wifi certification version: v7.0
I (1516) wifi:config NVS flash: enabled
I (1526) wifi:config nano formating: disabled
I (1526) wifi:Init data frame dynamic rx buffer num: 32
I (1536) wifi:Init management frame dynamic rx buffer num: 32
I (1536) wifi:Init management short buffer num: 32
I (1546) wifi:Init dynamic tx buffer num: 32
I (1546) wifi:Init static tx FG buffer num: 2
I (1556) wifi:Init static rx buffer size: 1600
I (1556) wifi:Init static rx buffer num: 10
I (1556) wifi:Init dynamic rx buffer num: 32
I (1566) wifi_init: rx ba win: 6
I (1566) wifi_init: tcpip mbox: 32
I (1576) wifi_init: udp mbox: 6
I (1576) wifi_init: tcp mbox: 6
I (1576) wifi_init: tcp tx win: 5744
I (1586) wifi_init: tcp rx win: 5744
I (1586) wifi_init: tcp mss: 1440
I (1596) wifi_init: WiFi IRAM OP enabled
I (1596) wifi_init: WiFi RX IRAM OP enabled
D (1616) nvs: nvs_open_from_partition rmaker_creds 0
D (1616) nvs: nvs_get_str_or_blob node_id
D (1616) esp_rmaker_fctry: Failed to read key node_id with error 4354 size 0
D (1616) nvs: nvs_close 4
I (1616) esp_rmaker_work_queue: Work Queue created.
D (1626) nvs: nvs_open_from_partition rmaker_creds 0
D (1636) nvs: nvs_get_str_or_blob client_key
D (1636) nvs: nvs_get_str_or_blob client_key
D (1646) nvs: nvs_close 5
D (1646) nvs: nvs_open_from_partition rmaker_creds 0
D (1646) nvs: nvs_get_str_or_blob client_cert
D (1656) nvs: nvs_get_str_or_blob client_cert
D (1666) nvs: nvs_close 6
D (1666) nvs: nvs_open_from_partition rmaker_creds 0
D (1666) nvs: nvs_get_str_or_blob mqtt_host
D (1666) esp_rmaker_fctry: Failed to read key mqtt_host with error 4354 size 0
D (1676) nvs: nvs_close 7
D (1676) aws_ppi: PPI string generator v0.4
D (1686) aws_ppi: PPI inputs pass all checks. String value is shown below:

?Platform=APN3|A0|RM|EX00|RMDev|1x0|7CDFA1E25EA0
I (1696) esp_mqtt_glue: AWS PPI: ?Platform=APN3|A0|RM|EX00|RMDev|1x0|7CDFA1E25EA0
I (1706) esp_mqtt_glue: Initialising MQTT
D (1706) MQTT_CLIENT: MQTT client_id=7CDFA1E25EA0
D (1716) event: created event loop 0x3fcb1024
I (1716) esp_rmaker_mqtt_budget: MQTT Budgeting initialised. Default: 100, Max: 1024, Revive count: 1, Revive period: 5
D (1726) nvs: nvs_open_from_partition user_mapping 0
D (1736) event: running post RMAKER_EVENT:1 with handler 0x4200c5a8 and context 0x3fcf7fe0 on loop 0x3fcedeec
0x4200c5a8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1170

I (1746) app_main: RainMaker Initialised.
I (1746) esp_rmaker_node: Node ID ----- 7CDFA1E25EA0
D (1756) nvs: nvs_open_from_partition Brama 0
D (1756) nvs: nvs_get_str_or_blob Name
D (1766) nvs: nvs_get_str_or_blob Name
D (1766) nvs: nvs_close 8
D (1766) esp_rmaker_device: Param Name added in Brama
D (1776) esp_rmaker_device: Param Stan added in Brama
D (1776) esp_rmaker_device: Param Pokazuj stan akcesorium added in Brama
D (1786) nvs: nvs_open_from_partition Furtka 0
D (1786) nvs: nvs_get_str_or_blob Name
D (1796) nvs: nvs_get_str_or_blob Name
D (1796) nvs: nvs_close 9
D (1796) esp_rmaker_device: Param Name added in Furtka
D (1806) esp_rmaker_device: Param Stan added in Furtka
D (1806) esp_rmaker_device: Param Czas [s] added in Furtka
D (1816) esp_rmaker_device: Param Pokazuj stan akcesorium added in Furtka
E (1826) gpio: gpio_install_isr_service(449): GPIO isr service already installed
I (1826) gpio: GPIO[5]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
D (1836) nvs: nvs_open_from_partition Przycisk 0
D (1846) nvs: nvs_get_str_or_blob Name
D (1846) nvs: nvs_get_str_or_blob Name
D (1856) nvs: nvs_close 10
D (1856) esp_rmaker_device: Param Name added in Przycisk
D (1856) esp_rmaker_device: Param Stan added in Przycisk
D (1866) esp_rmaker_device: Param Min. czas pobudzenia [s] added in Przycisk
D (1876) esp_rmaker_device: Param Powiadom gdy aktywne added in Przycisk
D (1876) esp_rmaker_device: Param Powiadom gdy nieaktywne added in Przycisk
D (1886) esp_rmaker_device: Param Odwroc logike added in Przycisk
D (1896) esp_rmaker_device: Param Wykryj nowe czujniki added in MENU_SCAN
D (1896) esp_rmaker_device: Param Usun wszystkie czujniki added in MENU_SCAN
W (1906) app_main: MenuScan creating...
D (1916) nvs: nvs_open_from_partition MENU_NODE 0
D (1916) nvs: nvs_get_str_or_blob Nazwa urzadzenia
D (1916) nvs: nvs_get_str_or_blob Nazwa urzadzenia
D (1926) nvs: nvs_close 11
D (1926) nvs: nvs_open_from_partition MENU_NODE 1
D (1936) nvs: nvs_set_blob Nazwa urzadzenia 17
D (1936) nvs: nvs_close 12
D (1936) esp_rmaker_device: Param Nazwa urzadzenia added in MENU_NODE
D (1946) esp_rmaker_device: Param Ukryj komponent OUT 1 added in MENU_NODE
D (1956) esp_rmaker_device: Param Ukryj komponent OUT 2 added in MENU_NODE
D (1956) esp_rmaker_device: Param Ukryj komponent IN 1 added in MENU_NODE
D (1966) esp_rmaker_device: Param Zezw. użytk. na edycję added in MENU_NODE
D (1976) nvs: nvs_open_from_partition storage_sens 1
D (1976) nvs: nvs_get_str_or_blob sens1
W (1986) app_main: name: , type: 0, notification: 0, flag:0
D (1986) nvs: nvs_get_str_or_blob sens2
W (1996) app_main: name: , type: 0, notification: 0, flag:0
D (1996) nvs: nvs_get_str_or_blob sens3
W (2006) app_main: name: , type: 0, notification: 0, flag:0
D (2006) nvs: nvs_get_str_or_blob sens4
W (2016) app_main: name: , type: 0, notification: 0, flag:0
D (2016) nvs: nvs_get_str_or_blob sens5
W (2026) app_main: name: , type: 0, notification: 0, flag:0
D (2026) nvs: nvs_get_str_or_blob sens6
W (2036) app_main: name: , type: 0, notification: 0, flag:0
D (2036) nvs: nvs_get_str_or_blob sens7
W (2046) app_main: name: , type: 0, notification: 0, flag:0
D (2056) nvs: nvs_get_str_or_blob sens8
W (2056) app_main: name: , type: 0, notification: 0, flag:0
D (2066) nvs: nvs_get_str_or_blob sens9
W (2066) app_main: name: , type: 0, notification: 0, flag:0
D (2076) nvs: nvs_get_str_or_blob sens10
W (2076) app_main: name: , type: 0, notification: 0, flag:0
D (2086) nvs: nvs_close 13
I (2086) esp_rmaker_ota_using_topics: OTA enabled with Topics
I (2096) esp_rmaker_ota: OTA state = 2
D (2096) nvs: nvs_open_from_partition rmaker_time 0
D (2096) nvs: nvs_open_from_partition rmaker_time 0
D (2106) esp_rmaker_device: Param TZ added in Time
D (2106) esp_rmaker_device: Param TZ-POSIX added in Time
I (2116) esp_rmaker_time_service: Time service enabled
I (2126) esp_rmaker_time: Initializing SNTP. Using the SNTP server: pool.ntp.org
D (2126) nvs: nvs_open_from_partition rmaker_time 0
D (2136) nvs: nvs_open_from_partition Schedule 0
D (2136) nvs: nvs_get_str_or_blob Schedules
D (2146) nvs: nvs_get_str_or_blob Schedules
D (2146) nvs: nvs_close 14
D (2146) esp_rmaker_device: Param Schedules added in Schedule
D (2156) esp_rmaker_schedule: Scheduling Service Enabled
D (2166) nvs: nvs_open_from_partition Scenes 0
D (2166) nvs: nvs_get_str_or_blob Scenes
D (2166) nvs: nvs_get_str_or_blob Scenes
D (2176) nvs: nvs_close 15
D (2176) esp_rmaker_device: Param Scenes added in Scenes
D (2186) esp_rmaker_device: Device attribute Scenes.deactivation_support added
D (2186) esp_rmaker_scenes: Scenes Service Enabled
I (2196) esp_rmaker_core: Starting RainMaker Work Queue task
I (2196) esp_rmaker_work_queue: RainMaker Work Queue task started.
D (2196) wifi_prov_mgr: execute_event_cb : 0
W (2216) BT_INIT: esp_bt_mem_release not implemented, return OK
I (2216) wifi_prov_scheme_ble: BT memory released
D (2226) event: running post WIFI_PROV_EVENT:0 with handler 0x42016f8c and context 0x3fcf3218 on loop 0x3fcedeec
0x42016f8c: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130

D (2236) event: running post WIFI_PROV_EVENT:0 with handler 0x42011130 and context 0x3fcaf0f4 on loop 0x3fcedeec
0x42011130: esp_rmaker_user_mapping_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_user_mapping.c:72

I (2246) app_wifi: Starting provisioning
D (2246) esp_netif_objects: esp_netif_add_to_list 0x3fcb41e4
D (2256) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 2)
D (2266) nvs: nvs_open_from_partition rmaker_creds 0
D (2266) nvs: nvs_get_str_or_blob random
D (2276) nvs: nvs_get_str_or_blob random
D (2276) nvs: nvs_close 16
D (2276) nvs: nvs_get opmode 1
D (2286) ADC: Wi-Fi takes adc2 lock.
I (2286) phy_init: phy_version 503,13653eb,Jun  1 2022,17:47:08
D (2296) phy_init: loading PHY init data from application binary
D (2296) nvs: nvs_open_from_partition phy 0
D (2306) nvs: nvs_get cal_version 4
D (2306) nvs: nvs_get_str_or_blob cal_mac
D (2306) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (2316) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (2326) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (2336) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (2336) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (2346) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (2356) nvs: nvs_get_str_or_blob cal_data
D (2366) nvs: nvs_close 17
D (2366) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (2366) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (2376) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (2376) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (2386) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (2396) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (2426) wifi:filter: set rx policy=0
I (2436) wifi:mode : sta (7c:df:a1:e2:5e:a0)
I (2436) wifi:enable tsf
D (2436) wifi:filter: set rx policy=1
D (2436) wifi:connect status 0 -> 0
D (2436) event: running post WIFI_EVENT:2 with handler 0x42016f8c and context 0x3fcf6078 on loop 0x3fcedeec
0x42016f8c: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130

D (2446) wifi:clear blacklist
D (2446) wifi:Start wifi disconnect
D (2456) wifi:connect status 0 -> 0
D (2456) wifi:filter: set rx policy=8
D (2456) wifi:Start wifi connect
D (2466) wifi:connect status 0 -> 0
D (2466) wifi:sta_connect: invalid ssid
D (2466) event: running post WIFI_EVENT:2 with handler 0x4205e790 and context 0x3fcf6330 on loop 0x3fcedeec
0x4205e790: wifi_default_action_sta_start at F:/GitHub/esp-idf-v4.4.3/components/esp_wifi/src/wifi_default.c:67

D (2476) wifi_init_default: wifi_start esp-netif:0x3fcf60dc event-id2
D (2486) wifi_init_default: WIFI mac address: 7c df a1 e2 5e a0
D (2486) esp_netif_handlers: esp_netif action has started with netif0x3fcf60dc from event_id=2
D (2496) esp_netif_lwip: check: remote, if=0x3fcf60dc fn=0x4205c2c8
0x4205c2c8: esp_netif_start_api at F:/GitHub/esp-idf-v4.4.3/components/esp_netif/lwip/esp_netif_lwip.c:700

D (2506) esp_netif_lwip: esp_netif_start_api 0x3fcf60dc
D (2506) protocomm_nimble: Free memory at start of simple_ble_init 221736
D (2516) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fcf60dc
D (2526) esp_netif_lwip: check: local, if=0x3fcf60dc fn=0x4205cc30
0x4205cc30: esp_netif_update_default_netif_lwip at F:/GitHub/esp-idf-v4.4.3/components/esp_netif/lwip/esp_netif_lwip.c:188

D (2526) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcf60dc
D (2536) esp_netif_lwip: call api in lwip: ret=0x0, give sem
W (2546) BT_INIT: esp_bt_controller_mem_release not implemented, return OK
I (2546) BT_INIT: BT controller compile version [421c279]
I (2556) BT_INIT: Bluetooth MAC: 7c:df:a1:e2:5e:a2

D (2566) nvs: nvs_open_from_partition nimble_bond 1
D (2566) nvs: nvs_get_str_or_blob our_sec_1
D (2576) nvs: nvs_close 18
D (2576) nvs: nvs_open_from_partition nimble_bond 1
D (2576) nvs: nvs_get_str_or_blob our_sec_2
D (2586) nvs: nvs_close 19
D (2586) nvs: nvs_open_from_partition nimble_bond 1
D (2596) nvs: nvs_get_str_or_blob our_sec_3
D (2596) nvs: nvs_close 20
D (2596) NIMBLE_NVS: ble_store_config_our_secs restored 0 bonds
D (2606) nvs: nvs_open_from_partition nimble_bond 1
D (2606) nvs: nvs_get_str_or_blob peer_sec_1
D (2616) nvs: nvs_close 21
D (2616) nvs: nvs_open_from_partition nimble_bond 1
D (2626) nvs: nvs_get_str_or_blob peer_sec_2
D (2626) nvs: nvs_close 22
D (2626) nvs: nvs_open_from_partition nimble_bond 1
D (2636) nvs: nvs_get_str_or_blob peer_sec_3
D (2636) nvs: nvs_close 23
D (2636) NIMBLE_NVS: ble_store_config_peer_secs restored 0 bonds
D (2646) nvs: nvs_open_from_partition nimble_bond 1
D (2656) nvs: nvs_get_str_or_blob cccd_sec_1
D (2656) nvs: nvs_close 24
D (2656) nvs: nvs_open_from_partition nimble_bond 1
D (2666) nvs: nvs_get_str_or_blob cccd_sec_2
D (2666) nvs: nvs_close 25
D (2666) nvs: nvs_open_from_partition nimble_bond 1
D (2676) nvs: nvs_get_str_or_blob cccd_sec_3
D (2676) nvs: nvs_close 26
D (2686) nvs: nvs_open_from_partition nimble_bond 1
D (2686) nvs: nvs_get_str_or_blob cccd_sec_4
D (2696) nvs: nvs_close 27
D (2696) nvs: nvs_open_from_partition nimble_bond 1
D (2696) nvs: nvs_get_str_or_blob cccd_sec_5
D (2706) nvs: nvs_close 28
D (2706) nvs: nvs_open_from_partition nimble_bond 1
D (2716) nvs: nvs_get_str_or_blob cccd_sec_6
D (2716) nvs: nvs_close 29
D (2716) nvs: nvs_open_from_partition nimble_bond 1
D (2726) nvs: nvs_get_str_or_blob cccd_sec_7
D (2726) nvs: nvs_close 30
D (2736) nvs: nvs_open_from_partition nimble_bond 1
D (2736) nvs: nvs_get_str_or_blob cccd_sec_8
D (2736) nvs: nvs_close 31
D (2746) NIMBLE_NVS: ble_store_config_cccds restored 0 bonds
I (2746) protocomm_nimble: BLE Host Task Started
D (2756) protocomm_nimble: registering service 021a9004-0382-4aea-bff4-6b3f1c5adfb4 with handle=1 TYPE =128
D (2766) protocomm_nimble: registering characteristic 021aff50-0382-4aea-bff4-6b3f1c5adfb4 with def_handle=2 val_handle=3 , TYPE = 128
D (2776) protocomm_nimble: registering descriptor 0x2901 with handle=4
D (2786) protocomm_nimble: registering characteristic 021aff51-0382-4aea-bff4-6b3f1c5adfb4 with def_handle=5 val_handle=6 , TYPE = 128
D (2796) protocomm_nimble: registering descriptor 0x2901 with handle=7
D (2806) protocomm_nimble: registering characteristic 021aff52-0382-4aea-bff4-6b3f1c5adfb4 with def_handle=8 val_handle=9 , TYPE = 128
D (2816) protocomm_nimble: registering descriptor 0x2901 with handle=10
D (2816) protocomm_nimble: registering characteristic 021aff53-0382-4aea-bff4-6b3f1c5adfb4 with def_handle=11 val_handle=12 , TYPE = 128
D (2836) protocomm_nimble: registering descriptor 0x2901 with handle=13
D (2836) protocomm_nimble: registering characteristic 021aff54-0382-4aea-bff4-6b3f1c5adfb4 with def_handle=14 val_handle=15 , TYPE = 128
D (2856) protocomm_nimble: registering descriptor 0x2901 with handle=16
I (2866) NimBLE: GAP procedure initiated: stop advertising.

I (2866) NimBLE: GAP procedure initiated: advertise;
I (2866) NimBLE: disc_mode=2
I (2876) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=256 adv_itvl_max=256
I (2886) NimBLE:

D (2886) protocomm_nimble: Minimum free heap size = 168768, free Heap size = 168768
D (2896) protocomm_nimble: Free Heap size after simple_ble_start= 168768
I (2906) wifi_prov_mgr: Provisioning started with service name : NEOX_09c940
D (2906) wifi_prov_mgr: execute_event_cb : 1
D (2916) event: running post WIFI_PROV_EVENT:1 with handler 0x42016f8c and context 0x3fcf3218 on loop 0x3fcedeec
0x42016f8c: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130

I (2926) app_wifi: Provisioning started
D (2926) event: running post WIFI_PROV_EVENT:1 with handler 0x42011130 and context 0x3fcaf124 on loop 0x3fcedeec
0x42011130: esp_rmaker_user_mapping_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_user_mapping.c:72

D (2936) event: running post WIFI_PROV_EVENT:1 with handler 0x42014444 and context 0x3fcb1acc on loop 0x3fcedeec
0x42014444: esp_rmaker_local_ctrl_prov_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_local_ctrl.c:346

I (2946) esp_rmaker_local: Event 1
I (2956) app_wifi: Scan this QR code from the ESP RainMaker phone app for Provisioning.
D (2966) qrcode: Encoding below text with ECC LVL 0 & QR Code Version 5
D (2966) qrcode: {"ver":"v1","name":"NEOX_09c940","transport":"ble"}

  █▀▀▀▀▀█ ▄█ █  ▀█▄▀█ ▄ █▀▀▀▀▀█
  █ ███ █ ▀▄ ▄▀ ████▄▄▀ █ ███ █
  █ ▀▀▀ █ █▀▄▀█ ▀█▀▀ █▄ █ ▀▀▀ █
  ▀▀▀▀▀▀▀ █ █▄█ ▀▄▀▄▀▄█ ▀▀▀▀▀▀▀
  ██▄▀▄ ▀█▄▄ ▀███ ▄▀▄█▄▄██▀ ▀█▄
  █▄▄▄█ ▀▄█▄▄ █▄▀  ▀▄▀█▄▄▄█ ██▄
   ▄▄▄█ ▀█▄ ▀▀█▀▄ ███▄▀█▀▄ ▀ ▀▀
  ▄▀ ▄█▄▀▄▄▀▄▀▀▄ ▄██▀  █▄█ ▄▀██
    █▀▄▀▀ ▀ ▀▄█ ▄▀ ██ ▄█▄  █▄▄▄
  ▀  █▄ ▀  ▀█ ▀▀▄ █▄█▄▀ ██▀   ▀
  ▀ ▀▀▀▀▀ ▄▀▄▀▀██ ▀▄ ▄█▀▀▀███ ▄
  █▀▀▀▀▀█ ▀█▄▄▀▄█▄ ▀█▄█ ▀ ██▄▀▄
  █ ███ █ ▄▀▄▀ ▀▄ ▄▀█▄▀▀█▀█   ▀
  █ ▀▀▀ █ ▄▄▄▀▀▄▀▄████▄ ▄██ ▀▄▀
  ▀▀▀▀▀▀▀ ▀▀▀ ▀ ▀ ▀▀▀ ▀▀ ▀▀  ▀

I (3126) app_wifi: If QR code is not visible, copy paste the below URL in a browser.
https://rainmaker.espressif.com/qrcode.html?data={"ver":"v1","name":"NEOX_09c940","transport":"ble"}
D (3146) event: running post APP_WIFI_EVENT:1 with handler 0x4200c5a8 and context 0x3fcacab4 on loop 0x3fcedeec
0x4200c5a8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1170

I (3156) app_main: Provisioning QR : {"ver":"v1","name":"NEOX_09c940","transport":"ble"}
I (3166) app_wifi: Provisioning Started. Name : NEOX_09c940, POP : <null>
I (3166) app_wifi: Provisioning will auto stop after 2 minute(s).
D (17876) protocomm_nimble: Inside BLE connect w/ conn_id - 1
I (18376) protocomm_nimble: mtu update event; conn_handle=1 cid=4 mtu=256

D (20116) gdma: new group (0) at 0x3fcc1fbc
D (20116) gdma: new pair (0,0) at 0x3fcc1ff8
D (20116) gdma: new tx channel (0,0) at 0x3fcc1f8c
D (20116) gdma: new rx channel (0,0) at 0x3fcc2018
D (20126) gdma: tx channel (0,0), (1:16) bytes aligned, burst enabled
D (20136) gdma: rx channel (0,0), (1:16) bytes aligned, burst disabled

assert failed: spinlock_acquire spinlock.h:123 ((result == SPINLOCK_FREE) == (lock->count == 0))

Backtrace: 0x40375d82:0x3fcc1540 0x4037fddd:0x3fcc1560 0x40387805:0x3fcc1580 0x40383be1:0x3fcc16a0 0x40380ff1:0x3fcc16c0 0x40381168:0x3fcc1700 0x4202e61d:0x3fcc1720 0x42026304:0x3fcc1740 0x4202631b:0x3fcc1760 0x42033c78:0x3fcc1780 0x42031296:0x3fcc17b0 0x42026d2a:0x3fcc17f0 0x42026331:0x3fcc1820 0x42026343:0x3fcc1840 0x4202eaca:0x3fcc1860 0x42024706:0x3fcc1880 0x403839fa:0x3fcc18a0
0x40375d82: panic_abort at F:/GitHub/esp-idf-v4.4.3/components/esp_system/panic.c:402

0x4037fddd: esp_system_abort at F:/GitHub/esp-idf-v4.4.3/components/esp_system/esp_system.c:128

0x40387805: __assert_func at F:/GitHub/esp-idf-v4.4.3/components/newlib/assert.c:85

0x40383be1: spinlock_acquire at F:/GitHub/esp-idf-v4.4.3/components/esp_hw_support/include/soc/spinlock.h:123
 (inlined by) xPortEnterCriticalTimeout at F:/GitHub/esp-idf-v4.4.3/components/freertos/port/xtensa/port.c:288

0x40380ff1: vPortEnterCritical at F:/GitHub/esp-idf-v4.4.3/components/freertos/port/xtensa/include/freertos/portmacro.h:578
 (inlined by) xQueueSemaphoreTake at F:/GitHub/esp-idf-v4.4.3/components/freertos/queue.c:1563

0x40381168: xQueueTakeMutexRecursive at F:/GitHub/esp-idf-v4.4.3/components/freertos/queue.c:731

0x4202e61d: npl_freertos_mutex_pend at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/porting/npl/freertos/src/npl_os_freertos.c:194

0x42026304: ble_npl_mutex_pend at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:176
 (inlined by) ble_hs_lock_nested at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:165

0x4202631b: ble_hs_lock at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:210

0x42033c78: ble_sm_sc_public_key_rx at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/nimble/host/src/ble_sm_sc.c:622

0x42031296: ble_sm_rx at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/nimble/host/src/ble_sm.c:2654

0x42026d2a: ble_hs_hci_evt_acl_process at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:971

0x42026331: ble_hs_process_rx_data_queue at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:238

0x42026343: ble_hs_event_rx_data at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:532

0x4202eaca: ble_npl_event_run at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:125
 (inlined by) nimble_port_run at F:/GitHub/esp-idf-v4.4.3/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:78

0x42024706: nimble_host_task at F:/GitHub/esp-idf-v4.4.3/components/protocomm/src/transports/protocomm_nimble.c:475

0x403839fa: vPortTaskWrapper at F:/GitHub/esp-idf-v4.4.3/components/freertos/port/xtensa/port.c:131

ELF file SHA256: f6331a4a1df66736

Rebooting...
�ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x40375a20
0x40375a20: esp_restart_noos at F:/GitHub/esp-idf-v4.4.3/components/esp_system/port/soc/esp32s3/system_internal.c:151 (discriminator 1)

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3808,len:0x1660
load:0x403c9700,len:0xbb8
load:0x403cc700,len:0x2e8c
entry 0x403c9954
shahpiyushv commented 1 year ago

Is this ust a normal Rainmaker project with your own params and the Provisioning timeout reduced to 2 min, with no other changes?

jacek12345 commented 1 year ago

Generally yes. + nimble for communication with sensors. No changes in RainMaker core. Only using available RainMaker API. Also using own NVS for devices and params storage. With no POP. And this change https://github.com/espressif/esp-rainmaker/issues/222#issuecomment-1396806804

jacek12345 commented 1 year ago

without change #222 i have stack overflow when Debug enabled and this is a few rows earlier than last assert failed (that was with #222 added) so think that both are lack of memory issues. If disable Debug logging (free some memory) it works again (meaby on the "bleeding edge")

D (15095) protocomm_nimble: UUID did not match... 51
D (15095) protocomm_nimble: UUID (0x51) matched with proto-name = prov-session
D (15105) security1: Request to handle setup0_command
D (15115) gdma: new group (0) at 0x3fcc2634
D (15115) gdma: new pair (0,0) at 0x3fcc2670
D (15125) gdma: new
***ERROR*** A stack overflow in task ble has been detected.

Increased nimble stack and seems to be good now also with #222 and with debug enabled

Tianbawen commented 3 months ago

I also have this problem, how to solve it?

jacek12345 commented 3 months ago

Increase memory for nimble stack