Closed jacek12345 closed 1 year ago
IshaESP
commented
1 year ago Hi @jacek12345, I tried running switch example using ESP-IDFv5.0.1 (BT controller compile version [80abacd]), no crash was observed. Can you send the sdkconfig of the application and the output with debug logs?
rahult-github
commented
1 year ago Hi @jacek12345 , any updates ?
jacek12345
commented
1 year ago Now tried with ESP-IDF-v.5.1-rc1 and still have a problem. The last version when problem didn't occure is v.5.0
btdm: bss start 0x3fcef180, len 36
btdm: data start 0x3fcef174, data start rom 0x40057350, len 12
MAGIC fadebead VERSION 00010006
I (22383) BLE_INIT: BT controller compile version [85b425c]
Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC : 0x420288c1 PS : 0x00060630 A0 : 0x82037a50 A1 : 0x3fcaa5b0
0x420288c1: semphr_delete_wrapper at F:/GitHub/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:528
A2 : 0x1f900040 A3 : 0x00000001 A4 : 0x60006110 A5 : 0x00000000
A6 : 0x3fcaa600 A7 : 0x0000000c A8 : 0x803773fc A9 : 0x3fcaa590
A10 : 0x00000001 A11 : 0x00000000 A12 : 0x3fcb8114 A13 : 0x00000000
A14 : 0x00000000 A15 : 0xb33fffff SAR : 0x00000009 EXCCAUSE: 0x0000001c
EXCVADDR: 0x1f900040 LBEG : 0x4037eaac LEND : 0x4037eab8 LCOUNT : 0x00000000
0x4037eaac: ram_wifi_tx_dig_gain at ??:?
0x4037eab8: ram_wifi_tx_dig_gain at ??:?
Backtrace: 0x420288be:0x3fcaa5b0 0x42037a4d:0x3fcaa5d0 0x4203882c:0x3fcaa5f0 0x42028f63:0x3fcaa640 0x4203196a:0x3fcaa680 0x4200d704:0x3fcaa6e0 0x4200e190:0x3fcaa700 0x420f16a6:0x3fcaa830 0x40381d32:0x3fcaa860
0x420288be: semphr_delete_wrapper at F:/GitHub/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:521
0x42037a4d: ble_sm_alg_gen_key_pair at ??:?
0x4203882c: btdm_controller_init at ??:?
0x42028f63: esp_bt_controller_init at F:/GitHub/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:1305
0x4203196a: nimble_port_init at F:/GitHub/esp-idf-v5.1-rc1/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:153
0x4200d704: Nimble_init at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:3301
0x4200e190: app_main at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:2122
0x420f16a6: main_task at F:/GitHub/esp-idf-v5.1-rc1/components/freertos/app_startup.c:208 (discriminator 13)
0x40381d32: vPortTaskWrapper at F:/GitHub/esp-idf-v5.1-rc1/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162
I made "fullclean" and "set-target esp32-s3". After that, th eoutput was little different, but next run was the same as above. First run:
btdm: bss start 0x3fcef180, len 36
btdm: data start 0x3fcef174, data start rom 0x40057350, len 12
MAGIC fadebead VERSION 00010006
I (22329) BLE_INIT: BT controller compile version [85b425c]
MAGIC fadebead VERSION 00010001
HLI Magic mismatch: 3fc9f4f0, fadebead
Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC : 0x403874ef PS : 0x00060633 A0 : 0x80386ec9 A1 : 0x3fcace30
0x403874ef: block_size at F:/GitHub/esp-idf-v5.1-rc1/components/heap/tlsf/tlsf_block_functions.h:20
(inlined by) block_locate_free at F:/GitHub/esp-idf-v5.1-rc1/components/heap/tlsf/tlsf.c:566
(inlined by) tlsf_malloc at F:/GitHub/esp-idf-v5.1-rc1/components/heap/tlsf/tlsf.c:1004
A2 : 0x3fcef96c A3 : 0x0000000c A4 : 0x3fce02e5 A5 : 0x00000000
A6 : 0x3fcc7f04 A7 : 0x3fcc7e84 A8 : 0x01c08334 A9 : 0x00000004
A10 : 0xfffffff8 A11 : 0x00000000 A12 : 0x00000000 A13 : 0x00060623
A14 : 0xb33fffff A15 : 0xb33fffff SAR : 0x0000001d EXCCAUSE: 0x0000001c
EXCVADDR: 0x01c08338 LBEG : 0x400570e8 LEND : 0x400570f3 LCOUNT : 0x00000000
Backtrace: 0x403874ec:0x3fcace30 0x40386ec6:0x3fcace50 0x40376509:0x3fcace70 0x40376561:0x3fcace90 0x420297ac:0x3fcaceb0 0x40020a5e:0x3fcaced0 |<-CORRUPTED
0x403874ec: block_locate_free at F:/GitHub/esp-idf-v5.1-rc1/components/heap/tlsf/tlsf.c:564
(inlined by) tlsf_malloc at F:/GitHub/esp-idf-v5.1-rc1/components/heap/tlsf/tlsf.c:1004
0x40386ec6: multi_heap_malloc_impl at F:/GitHub/esp-idf-v5.1-rc1/components/heap/multi_heap.c:207
0x40376509: heap_caps_malloc_base at F:/GitHub/esp-idf-v5.1-rc1/components/heap/heap_caps.c:176
0x40376561: heap_caps_malloc at F:/GitHub/esp-idf-v5.1-rc1/components/heap/heap_caps.c:197
0x420297ac: malloc_internal_wrapper at F:/GitHub/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:649
What is the best way for installing new ESP-IDF? I dont't know how to make shortcut for starting ESP-IDF. When i installed a lot of time ago my 4.4.3 version it created "ESP-IDF v4.4.3" shortcut. Now it doesn't create.
IshaESP
commented
1 year ago Hi @jacek12345 , Can you please send us the debug logs and sdkconfig for us to debug it properly.
To enable debug logs:
jacek12345
commented
1 year ago I'm trying to run with enabled debug logs but have: ERROR A stack overflow in task sys_evt has been detected.
IshaESP
commented
1 year ago Hey, Try increasing stack size by this: Component config -> ESP System Settings->ESP_SYSTEM_EVENT_TASK_STACK_SIZE to 4000 for testing purposes
jacek12345
commented
1 year ago Thank You @AxelLin and @IshaESP Now i see:
btdm: bss start 0x3fcef180, len 36
btdm: data start 0x3fcef174, data start rom 0x40057350, len 12
MAGIC fadebead VERSION 00010006
I (27283) BLE_INIT: BT controller compile version [85b425c]
assert failed: heap_caps_free heap_caps.c:387 (heap != NULL && "free() target pointer is outside heap areas")
Backtrace: 0x40375cba:0x3fcad000 0x40381a75:0x3fcad020 0x40388b55:0x3fcad040 0x403766db:0x3fcad160 0x40384dc5:0x3fcad180 0x403825e3:0x3fcad1a0 0x42029dc5:0x3fcad1c0 0x420392d1:0x3fcad1e0 0x4203a0b4:0x3fcad200 0x4202a63f:0x3fcad250 0x42032e5e:0x3fcad290 0x4200dc74:0x3fcad2f0 0x4200e700:0x3fcad310 0x420f69d7:0x3fcad440 0x4038450e:0x3fcad470
0x40375cba: panic_abort at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_system/panic.c:452
0x40381a75: esp_system_abort at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_system/port/esp_system_chip.c:84
0x40388b55: __assert_func at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/newlib/assert.c:81
0x403766db: heap_caps_free at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/heap/heap_caps.c:387 (discriminator 1)
0x40384dc5: vPortFree at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/freertos/heap_idf.c:91
0x403825e3: vQueueDelete at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/freertos/FreeRTOS-Kernel/queue.c:2321
0x42029dc5: semphr_delete_wrapper at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:529
0x420392d1: ble_sm_alg_gen_key_pair at ??:?
0x4203a0b4: btdm_controller_init at ??:?
0x4202a63f: esp_bt_controller_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:1305
0x42032e5e: nimble_port_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:153
0x4200dc74: Nimble_init at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:3301
0x4200e700: app_main at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:2122
0x420f69d7: main_task at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/freertos/app_startup.c:208 (discriminator 13)
0x4038450e: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162Is it enough or You meed whole log? I'm aware that there can be some secret information. Eventually can send priv?
jacek12345
commented
1 year ago @IshaESP This is not switch example. This is only based on switch example project. After RainMaker initialisation I'm waiting 20 sec. and starting NimBle. I'm using NimBle for communication with sensors. Crasch occures on nimble_port_init();
........
err = app_wifi_start(POP_TYPE_NONE);
if (err != ESP_OK) {
ESP_LOGE(TAG, "Could not start Wifi. Aborting!!!");
vTaskDelay(5000/portTICK_PERIOD_MS);
abort();
}
vTaskDelay(2000);
nimble_port_init();
//Initialize the NimBLE host configuration.
ble_hs_cfg.reset_cb = bleprph_on_reset;
ble_hs_cfg.sync_cb = bleprph_on_sync;
nimble_port_freertos_init(bleprph_host_task);I made one more time install.bat and export.bat in v5.1-rc1, and here is log
I (27) boot: ESP-IDF v5.1-rc1 2nd stage bootloader
I (27) boot: compile time Jun 15 2023 18:24:27
I (27) boot: Multicore bootloader
I (30) boot: chip revision: v0.1
I (34) boot.esp32s3: Boot SPI Speed : 80MHz
I (39) boot.esp32s3: SPI Mode : DIO
I (43) boot.esp32s3: SPI Flash Size : 8MB
I (48) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (57) boot: ## Label Usage Type ST Offset Length
I (64) boot: 0 sec_cert unknown 3f 06 0000d000 00003000
I (72) boot: 1 nvs WiFi data 01 02 00010000 00006000
I (79) boot: 2 otadata OTA data 01 00 00016000 00002000
I (87) boot: 3 phy_init RF data 01 01 00018000 00001000
I (94) boot: 4 ota_0 OTA app 00 10 00020000 003c0000
I (102) boot: 5 ota_1 OTA app 00 11 003e0000 003c0000
I (109) boot: 6 fctry WiFi data 01 02 007a0000 00006000
I (117) boot: 7 devdata WiFi data 01 02 007a6000 00003000
I (124) boot: 8 coredump Unknown data 01 03 007a9000 00010000
I (132) boot: End of partition table
I (136) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=55af8h (350968) map
I (208) esp_image: segment 1: paddr=00075b20 vaddr=3fc9b000 size=04e9ch ( 20124) load
I (212) esp_image: segment 2: paddr=0007a9c4 vaddr=40374000 size=05654h ( 22100) load
I (219) esp_image: segment 3: paddr=00080020 vaddr=42000020 size=f5704h (1005316) map
I (402) esp_image: segment 4: paddr=0017572c vaddr=40379654 size=118e8h ( 71912) load
I (428) boot: Loaded app from partition at offset 0x20000
I (428) boot: Disabling RNG early entropy source...
I (440) cpu_start: Multicore app
D (440) flash HPM: HPM with dummy, status is 3
I (440) cpu_start: Pro cpu up.
I (441) cpu_start: Starting app cpu, entry point is 0x40375678
0x40375678: call_start_cpu1 at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_system/port/cpu_start.c:154
I (0) cpu_start: App cpu up.
D (456) clk: RTC_SLOW_CLK calibration value: 3806566
I (468) cpu_start: Pro cpu start user code
I (468) cpu_start: cpu freq: 160000000 Hz
I (468) cpu_start: Application information:
I (471) cpu_start: Project name: neox1
I (476) cpu_start: App version: 1.9
I (480) cpu_start: Compile time: Jun 15 2023 18:23:48
I (486) cpu_start: ELF file SHA256: 1588ec57254788a4...
I (492) cpu_start: ESP-IDF: v5.1-rc1
I (497) cpu_start: Min chip rev: v0.0
I (502) cpu_start: Max chip rev: v0.99
I (507) cpu_start: Chip rev: v0.1
D (512) memory_layout: Checking 5 reserved memory ranges:
D (517) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc9b000
D (524) memory_layout: Reserved memory range 0x3fc9b000 - 0x3fca8230
D (530) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000
D (536) memory_layout: Reserved memory range 0x40374000 - 0x4038b000
0x40374000: _WindowOverflow4 at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:2013
D (543) memory_layout: Reserved memory range 0x600fe000 - 0x600fe010
D (549) memory_layout: Building list of available memory regions:
D (555) memory_layout: Available memory region 0x3fca8230 - 0x3fcb0000
D (562) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000
D (569) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000
D (575) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000
D (582) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710
D (588) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34
D (595) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000
D (602) memory_layout: Available memory region 0x600fe010 - 0x60100000
I (608) heap_init: Initializing. RAM available for dynamic allocation:
D (616) heap_init: New heap initialised at 0x3fca8230
I (621) heap_init: At 3FCA8230 len 000414E0 (261 KiB): DRAM
I (627) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
D (633) heap_init: New heap initialised at 0x3fcf0000
I (639) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (645) heap_init: New heap initialised at 0x600fe010
I (650) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM
D (656) intr_alloc: Connected src 39 to int 2 (cpu 0)
D (662) spi_flash: trying chip: issi
D (665) spi_flash: trying chip: gd
D (668) spi_flash: trying chip: mxic
D (672) spi_flash: trying chip: winbond
D (676) spi_flash: trying chip: boya
D (680) spi_flash: trying chip: th
D (683) spi_flash: trying chip: mxic (opi)
D (687) spi_flash: trying chip: generic
I (691) spi_flash: detected chip: generic
I (696) spi_flash: flash io: dio
D (700) cpu_start: calling init function: 0x420cf8ec
0x420cf8ec: _GLOBAL__sub_I__ZN9__gnu_cxx9__freeresEv at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:342
D (705) cpu_start: calling init function: 0x420cf3cc
0x420cf3cc: _GLOBAL__sub_I__ZN17__eh_globals_init7_S_initE at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:168
D (710) cpu_start: calling init function: 0x42092bd4
0x42092bd4: esp_ds_conn_lock at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/mbedtls/port/esp_ds/esp_rsa_sign_alt.c:49
D (715) cpu_start: calling init function: 0x420734ac
0x420734ac: s_set_default_wifi_log_level at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_wifi/src/wifi_init.c:88
D (720) cpu_start: calling init function: 0x420550ec
0x420550ec: esp_reset_reason_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_system/port/soc/esp32s3/reset_reason.c:59
D (725) cpu_start: calling init function: 0x42054760
0x42054760: esp_ipc_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_system/esp_ipc.c:114
D (730) cpu_start: calling init function: 0x42003470
0x42003470: esp_init_app_elf_sha256 at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_app_format/esp_app_desc.c:69
D (735) cpu_start: calling init function: 0x420088fc on core: 0
0x420088fc: __esp_system_init_fn_esp_timer_startup_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_timer/src/esp_timer.c:575
D (741) intr_alloc: Connected src 59 to int 3 (cpu 0)
D (746) cpu_start: calling init function: 0x420061dc on core: 0
0x420061dc: __esp_system_init_fn_esp_sleep_startup_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_hw_support/sleep_gpio.c:188
I (752) sleep: Configure to isolate all GPIO pins in sleep state
I (759) sleep: Enable automatic switching of GPIO sleep configuration
D (766) cpu_start: calling init function: 0x420045dc on core: 0
0x420045dc: __esp_system_init_fn_init_components0 at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_system/startup.c:486
I (772) coexist: coex firmware version: ebddf30
I (777) coexist: coexist rom version e7ae62f
D (783) intr_alloc: Connected src 79 to int 9 (cpu 0)
I (787) app_start: Starting scheduler on CPU0
D (792) intr_alloc: Connected src 57 to int 12 (cpu 0)
D (792) intr_alloc: Connected src 80 to int 2 (cpu 1)
I (802) app_start: Starting scheduler on CPU1
D (802) intr_alloc: Connected src 58 to int 3 (cpu 1)
I (792) main_task: Started on CPU0
D (812) heap_init: New heap initialised at 0x3fce9710
D (812) intr_alloc: Connected src 52 to int 13 (cpu 0)
I (822) main_task: Calling app_main()
D (822) intr_alloc: Connected src 16 to int 17 (cpu 0)
I (832) gpio: GPIO[2]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
E (842) gpio: gpio_install_isr_service(498): GPIO isr service already installed
I (852) gpio: GPIO[1]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
I (862) gpio: GPIO[14]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (872) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (872) led_serv: led id:0 initialise...
I (882) gpio: GPIO[17]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (892) led_serv: led id:1 initialise...
I (892) gpio: GPIO[16]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (902) led_serv: led id:2 initialise...
I (912) gpio: GPIO[19]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (922) led_serv: led id:3 initialise...
I (922) gpio: GPIO[18]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (932) led_serv: led id:4 initialise...
I (932) gpio: GPIO[15]| InputEn: 1| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (942) led_serv: led 1: pulse slow
W (1012) app_main: reading configuration from NVS
D (1012) nvs: nvs_open_from_partition storage_conf 1
D (1012) nvs: nvs_get_str_or_blob node
D (1012) nvs: nvs_get_str_or_blob out_1
D (1012) nvs: nvs_get_str_or_blob out_2
D (1022) nvs: nvs_get_str_or_blob in_1
D (1022) nvs: nvs_close 1
W (1022) app_main: reading end
D (1032) gptimer: new group (0) @0x3fcaf488
D (1032) gptimer: new gptimer (0,0) at 0x3fcaf3dc, resolution=1000000Hz
D (1042) esp_netif_lwip: LwIP stack has been initialized
D (1042) esp_netif_lwip: esp-netif has been successfully initialized
D (1052) event: running task for loop 0x3fcb0744
D (1052) event: created task for loop 0x3fcb0744
D (1062) event: created event loop 0x3fcb0744
D (1062) esp_netif_objects: esp_netif_add_to_list 0x3fcb1df0
D (1072) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
D (1082) esp_netif_lwip: check: remote, if=0x0 fn=0x42070ce0
0x42070ce0: set_lwip_netif_callback at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_netif/lwip/esp_netif_lwip.c:174
D (1082) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1092) pp: pp rom version: e7ae62f
I (1092) net80211: net80211 rom version: e7ae62f
D (1102) nvs: nvs_open_from_partition misc 1
I (1112) wifi:wifi driver task: 3fcb47a0, prio:23, stack:6656, core=0
D (1112) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1122) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1122) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1132) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1142) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1142) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1152) nvs: nvs_open_from_partition nvs.net80211 1
D (1162) nvs: nvs_get opmode 1
D (1162) nvs: nvs_get_str_or_blob sta.ssid
D (1172) nvs: nvs_get sta.authmode 1
D (1172) nvs: nvs_get_str_or_blob sta.pswd
D (1172) nvs: nvs_get_str_or_blob sta.pmk
D (1182) nvs: nvs_get sta.chan 1
D (1182) nvs: nvs_get auto.conn 1
D (1182) nvs: nvs_get bssid.set 1
D (1192) nvs: nvs_get_str_or_blob sta.bssid
D (1192) nvs: nvs_get sta.lis_intval 2
D (1192) nvs: nvs_get sta.phym 1
D (1202) nvs: nvs_get sta.phybw 1
D (1202) nvs: nvs_get_str_or_blob sta.apsw
D (1212) nvs: nvs_get_str_or_blob sta.apinfo
D (1212) nvs: nvs_get sta.scan_method 1
D (1212) nvs: nvs_get sta.sort_method 1
D (1222) nvs: nvs_get sta.minrssi 1
D (1222) nvs: nvs_get sta.minauth 1
D (1222) nvs: nvs_get sta.pmf_e 1
D (1232) nvs: nvs_get sta.pmf_r 1
D (1232) nvs: nvs_get sta.btm_e 1
D (1232) nvs: nvs_get sta.rrm_e 1
D (1242) nvs: nvs_get sta.mbo_e 1
D (1242) nvs: nvs_get_str_or_blob ap.ssid
D (1252) nvs: nvs_get_str_or_blob ap.passwd
D (1252) nvs: nvs_get_str_or_blob ap.pmk
D (1252) nvs: nvs_get ap.chan 1
D (1262) nvs: nvs_get ap.authmode 1
D (1262) nvs: nvs_get ap.hidden 1
D (1262) nvs: nvs_get ap.max.conn 1
D (1272) nvs: nvs_get bcn.interval 2
D (1272) nvs: nvs_get ap.phym 1
D (1272) nvs: nvs_get ap.phybw 1
D (1282) nvs: nvs_get ap.sndchan 1
D (1282) nvs: nvs_get ap.pmf_e 1
D (1282) nvs: nvs_get ap.pmf_r 1
D (1292) nvs: nvs_get ap.p_cipher 1
D (1292) nvs: nvs_get lorate 1
D (1292) nvs: nvs_get_str_or_blob country
D (1302) nvs: nvs_get ap.ftm_r 1
D (1302) nvs: nvs_get sta.ft 1
D (1312) nvs: nvs_get sta.owe 1
D (1312) nvs: nvs_get sta.trans_d 1
D (1312) nvs: nvs_get sta.sae_h2e 1
D (1322) nvs: nvs_get sta.sae_pk_mode 1
D (1322) nvs: nvs_get sta.bss_retry 1
D (1322) nvs: nvs_get_str_or_blob sta.owe_data
D (1332) nvs: nvs_get sta.he_dcm 1
D (1332) nvs: nvs_get sta.he_dcm_c_tx 1
D (1342) nvs: nvs_get sta.he_dcm_c_rx 1
D (1342) nvs: nvs_get sta.he_mcs9_d 1
D (1342) nvs: nvs_get sta.he_su_b_d 1
D (1352) nvs: nvs_get sta.he_su_b_f_d 1
D (1352) nvs: nvs_get sta.he_mu_b_f_d 1
D (1352) nvs: nvs_get sta.he_cqi_f_d 1
D (1362) nvs: nvs_get_str_or_blob sta.sae_h2e_id
D (1362) nvs: nvs_get ap.sae_h2e 1
D (1372) nvs: nvs_get_str_or_blob ap.pmk_info
D (1372) nvs: nvs_get nan.phym 1
D (1372) nvs: nvs_set ap.sndchan 1 1
I (1382) wifi:wifi firmware version: 10c8635
I (1382) wifi:wifi certification version: v7.0
I (1392) wifi:config NVS flash: enabled
I (1392) wifi:config nano formating: disabled
I (1392) wifi:Init data frame dynamic rx buffer num: 32
I (1402) wifi:Init management frame dynamic rx buffer num: 32
I (1402) wifi:Init management short buffer num: 32
I (1412) wifi:Init dynamic tx buffer num: 32
I (1412) wifi:Init static tx FG buffer num: 2
I (1422) wifi:Init static rx buffer size: 1600
I (1422) wifi:Init static rx buffer num: 10
I (1422) wifi:Init dynamic rx buffer num: 32
I (1432) wifi_init: rx ba win: 6
I (1432) wifi_init: tcpip mbox: 32
I (1442) wifi_init: udp mbox: 6
I (1442) wifi_init: tcp mbox: 6
I (1442) wifi_init: tcp tx win: 5744
I (1452) wifi_init: tcp rx win: 5744
I (1452) wifi_init: tcp mss: 1440
I (1462) wifi_init: WiFi IRAM OP enabled
I (1462) wifi_init: WiFi RX IRAM OP enabled
E (1472) app_main: Inicjalizacja noda
D (1482) nvs: nvs_open_from_partition rmaker_creds 0
D (1482) nvs: nvs_get_str_or_blob node_id
D (1482) nvs: nvs_get_str_or_blob node_id
D (1482) nvs: nvs_close 4
I (1492) esp_rmaker_work_queue: Work Queue created.
D (1492) nvs: nvs_open_from_partition rmaker_creds 0
D (1502) nvs: nvs_get_str_or_blob client_key
D (1502) nvs: nvs_get_str_or_blob client_key
D (1512) nvs: nvs_close 5
D (1512) nvs: nvs_open_from_partition rmaker_creds 0
D (1512) nvs: nvs_get_str_or_blob client_key
D (1522) nvs: nvs_close 6
D (1522) nvs: nvs_open_from_partition rmaker_creds 0
D (1532) nvs: nvs_get_str_or_blob client_cert
D (1532) nvs: nvs_get_str_or_blob client_cert
D (1542) nvs: nvs_close 7
D (1542) nvs: nvs_open_from_partition rmaker_creds 0
D (1542) nvs: nvs_get_str_or_blob client_cert
D (1552) nvs: nvs_close 8
D (1552) nvs: nvs_open_from_partition rmaker_creds 0
D (1552) nvs: nvs_get_str_or_blob mqtt_host
D (1562) nvs: nvs_get_str_or_blob mqtt_host
D (1562) nvs: nvs_close 9
D (1572) aws_ppi: PPI string generator v0.4
D (1572) aws_ppi: PPI inputs pass all checks. String value is shown below:
?Platform=APN3|A0|RM|EX00|RMDev|1x0|70041DAF64B8
I (1582) esp_mqtt_glue: AWS PPI: ?Platform=APN3|A0|RM|EX00|RMDev|1x0|70041DAF64B8
I (1592) esp_mqtt_glue: Initialising MQTT
D (1592) mqtt_client: MQTT client_id=ebje5v5bUdYWat7qSu7ePa
D (1602) event: created event loop 0x3fcbd480
I (1602) esp_rmaker_mqtt_budget: MQTT Budgeting initialised. Default: 100, Max: 1024, Revive count: 1, Revive period: 5
D (1622) nvs: nvs_open_from_partition user_mapping 0
D (1622) nvs: nvs_get_str_or_blob user_id
D (1632) nvs: nvs_close 10
D (1632) event: running post RMAKER_EVENT:1 with handler 0x4200e6b8 and context 0x3fcb9eac on loop 0x3fcb0744
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
I (1642) app_main: RainMaker Initialised.
I (1642) esp_rmaker_node: Node ID ----- ebje5v5bUdYWat7qSu7ePa
D (1652) nvs: nvs_open_from_partition Brama 0
D (1652) nvs: nvs_get_str_or_blob Name
D (1662) nvs: nvs_get_str_or_blob Name
D (1662) nvs: nvs_close 11
D (1662) esp_rmaker_device: Param Name added in Brama
D (1672) esp_rmaker_device: Param St added in Brama
D (1672) esp_rmaker_device: Param TO added in Brama
D (1682) esp_rmaker_device: Param ConSt added in Brama
D (1682) esp_rmaker_device: Param Hd added in Brama
D (1692) nvs: nvs_open_from_partition Furtka 0
D (1692) nvs: nvs_get_str_or_blob Name
D (1702) nvs: nvs_get_str_or_blob Name
D (1702) nvs: nvs_close 12
D (1702) esp_rmaker_device: Param Name added in Furtka
D (1712) esp_rmaker_device: Param St added in Furtka
D (1712) esp_rmaker_device: Param TO added in Furtka
D (1722) esp_rmaker_device: Param ConSt added in Furtka
D (1722) esp_rmaker_device: Param Hd added in Furtka
E (1732) gpio: gpio_install_isr_service(498): GPIO isr service already installed
I (1742) gpio: GPIO[41]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
D (1752) nvs: nvs_open_from_partition Przycisk zewnetrzny 0
D (1752) nvs: nvs_open_from_partition Przycisk zewnetrzny 1
D (1762) esp_rmaker_device: Param Name added in Przycisk zewnetrzny
D (1762) esp_rmaker_device: Param St added in Przycisk zewnetrzny
D (1772) esp_rmaker_device: Param TI added in Przycisk zewnetrzny
D (1782) esp_rmaker_device: Param PtxIon added in Przycisk zewnetrzny
D (1782) esp_rmaker_device: Param PuIon added in Przycisk zewnetrzny
D (1792) esp_rmaker_device: Param PtxIof added in Przycisk zewnetrzny
D (1802) esp_rmaker_device: Param PuIof added in Przycisk zewnetrzny
D (1802) esp_rmaker_device: Param SIrev added in Przycisk zewnetrzny
D (1812) esp_rmaker_device: Param Hd added in Przycisk zewnetrzny
D (1822) esp_rmaker_device: Param ScAc added in MENU_SCAN
D (1822) esp_rmaker_device: Param DelAllAc added in MENU_SCAN
W (1832) app_main: MenuScan creating...
D (1832) esp_rmaker_device: Param DevNm added in MENU_NODE
I (1842) app_main: MAC address: 70:04:1D:AF:64:B8
D (1842) esp_rmaker_device: Param McNd added in MENU_NODE
D (1852) esp_rmaker_device: Param UsEdAl added in MENU_NODE
D (1852) nvs: nvs_open_from_partition storage_sens 1
D (1862) nvs: nvs_get_str_or_blob sens1
W (1862) app_main: name: , type: 0, notification: 0, flag:0
D (1872) nvs: nvs_get_str_or_blob sens2
W (1872) app_main: name: , type: 0, notification: 0, flag:0
D (1882) nvs: nvs_get_str_or_blob sens3
W (1882) app_main: name: , type: 0, notification: 0, flag:0
D (1892) nvs: nvs_get_str_or_blob sens4
W (1892) app_main: name: , type: 0, notification: 0, flag:0
D (1902) nvs: nvs_get_str_or_blob sens5
W (1902) app_main: name: , type: 0, notification: 0, flag:0
D (1912) nvs: nvs_get_str_or_blob sens6
W (1912) app_main: name: , type: 0, notification: 0, flag:0
D (1922) nvs: nvs_get_str_or_blob sens7
W (1922) app_main: name: , type: 0, notification: 0, flag:0
D (1932) nvs: nvs_get_str_or_blob sens8
W (1932) app_main: name: , type: 0, notification: 0, flag:0
D (1942) nvs: nvs_get_str_or_blob sens9
W (1942) app_main: name: , type: 0, notification: 0, flag:0
D (1952) nvs: nvs_get_str_or_blob sens10
W (1952) app_main: name: , type: 0, notification: 0, flag:0
D (1962) nvs: nvs_close 13
W (1962) app_main: UpdateConnectionLists...report=1
I (1972) esp_rmaker_ota_using_topics: OTA enabled with Topics
I (1982) esp_rmaker_ota: OTA state = 2
I (1982) esp_rmaker_time: Initializing SNTP. Using the SNTP server: pool.ntp.org
D (1992) nvs: nvs_open_from_partition rmaker_time 0
D (1992) nvs: nvs_get_str_or_blob tz_posix
D (2002) nvs: nvs_get_str_or_blob tz_posix
D (2002) nvs: nvs_close 14
D (2002) nvs: nvs_open_from_partition rmaker_time 0
D (2012) nvs: nvs_get_str_or_blob tz_posix
D (2012) nvs: nvs_get_str_or_blob tz_posix
D (2022) nvs: nvs_close 15
D (2022) nvs: nvs_open_from_partition rmaker_time 0
D (2022) nvs: nvs_get_str_or_blob tz
D (2032) nvs: nvs_get_str_or_blob tz
D (2032) nvs: nvs_close 16
D (2032) esp_rmaker_device: Param TZ added in Time
D (2042) esp_rmaker_device: Param TZ-POSIX added in Time
I (2042) esp_rmaker_time_service: Time service enabled
I (2052) esp_rmaker_time: SNTP already initialized.
D (2062) nvs: nvs_open_from_partition Schedule 0
D (2062) nvs: nvs_get_str_or_blob Schedules
D (2072) nvs: nvs_get_str_or_blob Schedules
D (2072) nvs: nvs_close 17
D (2072) esp_rmaker_device: Param Schedules added in Schedule
D (2082) esp_rmaker_schedule: Scheduling Service Enabled
D (2082) nvs: nvs_open_from_partition Scenes 0
D (2092) nvs: nvs_get_str_or_blob Scenes
D (2092) nvs: nvs_get_str_or_blob Scenes
D (2102) nvs: nvs_close 18
D (2102) esp_rmaker_device: Param Scenes added in Scenes
D (2102) esp_rmaker_device: Device attribute Scenes.deactivation_support added
D (2112) esp_rmaker_scenes: Scenes Service Enabled
I (2122) esp_rmaker_core: Starting RainMaker Work Queue task
I (2122) esp_rmaker_work_queue: RainMaker Work Queue task started.
D (2132) wifi_prov_mgr: Found Wi-Fi SSID : Jacek
D (2132) wifi_prov_mgr: Found Wi-Fi Password : C**********a
W (2142) app_main: Reset cause: 1
W (2142) app_main: prov: 1, err: 0
D (2152) wifi_prov_mgr: execute_event_cb : 0
I (2152) wifi_prov_scheme_ble: BT memory released
D (2162) event: running post WIFI_PROV_EVENT:0 with handler 0x42017a14 and context 0x3fcb1d58 on loop 0x3fcb0744
0x42017a14: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130
D (2172) event: running post WIFI_PROV_EVENT:0 with handler 0x42012fa8 and context 0x3fcbc418 on loop 0x3fcb0744
0x42012fa8: esp_rmaker_user_mapping_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_user_mapping.c:73
D (2182) wifi_prov_mgr: Found Wi-Fi SSID : Jacek
D (2182) wifi_prov_mgr: Found Wi-Fi Password : C**********a
I (2192) app_wifi: Already provisioned, starting Wi-Fi STA
D (2192) wifi_prov_mgr: Provisioning not running
D (2202) wifi_prov_mgr: execute_event_cb : 6
D (2202) BLE_INIT: Release rom btdm [0x3fcef174] - [0x3fcef1a4], len 48
D (2212) BLE_INIT: Release rom interface btdm [0x3fcef958] - [0x3fceffac], len 1620
D (2222) BLE_INIT: Release BSS [0x3fca6900] - [0x3fca8230], len 6448
D (2222) BLE_INIT: Release data [0x3fc9e250] - [0x3fc9e34c], len 252
I (2232) wifi_prov_scheme_ble: BTDM memory released
D (2242) event: running post WIFI_PROV_EVENT:6 with handler 0x42017a14 and context 0x3fcb1d58 on loop 0x3fcb0744
D (2252) event: running post WIFI_PROV_EVENT:6 with handler 0x42015650 and context 0x3fcbdeec on loop 0x3fcb0744
0x42017a14: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130
0x42015650: esp_rmaker_local_ctrl_prov_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_local_ctrl.c:348
I (2262) esp_rmaker_local: Event 6
D (2262) nvs: nvs_get opmode 1
I (2272) phy_init: phy_version 601,fe52df4,May 10 2023,17:26:54
D (2272) phy_init: loading PHY init data from application binary
D (2282) nvs: nvs_open_from_partition phy 0
D (2282) nvs: nvs_get cal_version 4
D (2292) nvs: nvs_get_str_or_blob cal_mac
D (2292) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (2302) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (2302) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (2312) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (2322) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (2322) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (2332) nvs: nvs_get_str_or_blob cal_data
D (2342) nvs: nvs_close 19
D (2342) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (2342) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (2352) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (2362) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (2372) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (2372) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (2412) wifi:filter: set rx policy=0
I (2412) wifi:mode : sta (70:04:1d:af:64:b8)
I (2412) wifi:enable tsf
D (2412) wifi:filter: set rx policy=1
D (2412) wifi:connect status 0 -> 0
D (2422) event: running post WIFI_EVENT:2 with handler 0x42017a14 and context 0x3fcb1d8c on loop 0x3fcb0744
0x42017a14: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130
D (2422) wifi:Start wifi connect
D (2432) wifi:connect status 0 -> 0
D (2432) wifi:connect chan=0
D (2432) wifi:first chan=11
D (2432) wifi:connect status 0 -> 1
D (2442) wifi:filter: set rx policy=3
D (2442) wifi:clear scan ap list
D (2442) wifi:start scan: type=0x50f, priority=2, cb=0x420b0c7c, arg=0x0, ss_state=0x1, time=2452346, index=0
0x420b0c7c: cnx_start_handoff_cb at ??:?
D (2452) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
D (2462) event: running post WIFI_EVENT:2 with handler 0x42073780 and context 0x3fcb2020 on loop 0x3fcb0744
0x42073780: wifi_default_action_sta_start at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_wifi/src/wifi_default.c:71
D (2472) wifi_init_default: wifi_start esp-netif:0x3fcb1df0 event-id2
D (2482) wifi_init_default: WIFI mac address: 70 4 1d af 64 b8
D (2472) wifi:rsn valid: gcipher=3 ucipher=3 akm=9
D (2492) wifi:profile match: ss_state=0x7
D (2492) esp_netif_lwip: check: remote, if=0x3fcb1df0 fn=0x42070cf0
0x42070cf0: esp_netif_set_mac_api at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_netif/lwip/esp_netif_lwip.c:957
D (2502) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (2502) esp_netif_handlers: esp_netif action has started with netif0x3fcb1df0 from event_id=2
D (2512) esp_netif_lwip: check: remote, if=0x3fcb1df0 fn=0x42071354
0x42071354: esp_netif_start_api at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_netif/lwip/esp_netif_lwip.c:1032
D (2522) esp_netif_lwip: esp_netif_start_api 0x3fcb1df0
D (2522) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fcb1df0
D (2532) esp_netif_lwip: check: local, if=0x3fcb1df0 fn=0x42071cec
0x42071cec: esp_netif_update_default_netif_lwip at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_netif/lwip/esp_netif_lwip.c:327
D (2542) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcb1df0
D (2542) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (2562) wifi:rsn valid: gcipher=3 ucipher=3 akm=9
D (2562) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (2562) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (2572) wifi:profile match: ss_state=0x7
D (2582) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2582) wifi:perform scan: ss_state=0xd, chan<1,0>, dur<0,120>
D (2702) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2702) wifi:perform scan: ss_state=0xd, chan<2,0>, dur<0,120>
D (2832) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2832) wifi:perform scan: ss_state=0xd, chan<3,0>, dur<0,120>
D (2952) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2952) wifi:perform scan: ss_state=0xd, chan<4,0>, dur<0,120>
D (3072) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3072) wifi:perform scan: ss_state=0xd, chan<5,0>, dur<0,120>
D (3192) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3192) wifi:perform scan: ss_state=0xd, chan<6,0>, dur<0,120>
D (3312) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3312) wifi:perform scan: ss_state=0xd, chan<7,0>, dur<0,120>
D (3432) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3432) wifi:perform scan: ss_state=0xd, chan<8,0>, dur<0,120>
D (3562) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3562) wifi:perform scan: ss_state=0xd, chan<9,0>, dur<0,120>
D (3682) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3682) wifi:perform scan: ss_state=0xd, chan<10,0>, dur<0,120>
D (3802) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3802) wifi:perform scan: ss_state=0xd, chan<12,0>, dur<360,360>
D (4162) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4162) wifi:perform scan: ss_state=0xd, chan<13,0>, dur<360,360>
D (4522) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4522) wifi:perform scan: ss_state=0xd, chan<14,0>, dur<360,360>
D (4882) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4882) wifi:filter: set rx policy=4
D (4882) wifi:first chan=1
D (4882) wifi:handoff_cb: status=0
D (4892) wifi:ap found, mac=e8:d2:ff:59:9c:a4
D (4892) wifi:new_bss=0x3fca4e98, cur_bss=0x0, new_chan=<11,0>, cur_chan=1
D (4902) wifi:filter: set rx policy=5
I (4902) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
D (4912) wifi:connect_op: status=0, auth=9, cipher=3
D (4912) wifi:auth mode is not none
D (4912) wifi:connect_bss: auth=1, reconnect=0
I (4922) wifi:state: init -> auth (b0)
D (4922) gdma: new group (0) at 0x3fca8168
D (4932) gdma: new pair (0,0) at 0x3fca81ac
D (4932) gdma: new tx channel (0,0) at 0x3fca8134
D (4942) gdma: new rx channel (0,0) at 0x3fca81cc
D (4942) gdma: tx channel (0,0), (1:32) bytes aligned, burst enabled
D (4952) gdma: rx channel (0,0), (1:32) bytes aligned, burst disabled
D (4962) intr_alloc: Connected src 76 to int 18 (cpu 0)
D (5292) wifi:start 1s AUTH timer
D (5292) wifi:clear scan ap list
D (5312) wifi:recv auth: seq=1, status=126
D (5622) wifi:recv auth: seq=2, status=0
I (5622) wifi:state: auth -> assoc (0)
D (5652) wifi:recv assoc: type=0x10
D (5652) wifi:filter: set rx policy=6
I (5652) wifi:state: assoc -> run (10)
D (5652) wifi:start 10s connect timer for 4 way handshake
I (5672) wifi:connected with Jacek, aid = 34, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (5682) wifi:security: WPA3-SAE, phy: bgn, rssi: -50
D (5682) wifi:remove all except e8:d2:ff:59:9c:a4 from rc list
D (5682) wifi:clear blacklist
D (5692) nvs: nvs_set sta.chan 1 11
D (5692) nvs: nvs_set_blob sta.apinfo 700
D (5702) wifi:filter: set rx policy=7
I (5702) wifi:pm start, type: 1
I (5702) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
D (5712) wifi:Send sta connected event
D (5712) wifi:connect status 1 -> 5
D (5712) wifi:obss scan is disabled
D (5722) wifi:start obss scan: obss scan is stopped
D (5722) event: running post WIFI_EVENT:4 with handler 0x42017a14 and context 0x3fcb1d8c on loop 0x3fcb0744
0x42017a14: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130
D (5732) event: running post WIFI_EVENT:4 with handler 0x420737b0 and context 0x3fcb2080 on loop 0x3fcb0744
0x420737b0: wifi_default_action_sta_connected at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_wifi/src/wifi_default.c:85
I (5732) wifi:AP's beacon interval = 102400 us, DTIM period = 3
D (5752) esp_netif_handlers: esp_netif action connected with netif0x3fcb1df0 from event_id=4
D (5762) esp_netif_lwip: check: remote, if=0x3fcb1df0 fn=0x42071710
0x42071710: esp_netif_up_api at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_netif/lwip/esp_netif_lwip.c:1608
D (5762) esp_netif_lwip: esp_netif_up_api esp_netif:0x3fcb1df0
D (5772) esp_netif_lwip: check: local, if=0x3fcb1df0 fn=0x42071cec
0x42071cec: esp_netif_update_default_netif_lwip at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_netif/lwip/esp_netif_lwip.c:327
D (5772) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcb1df0
D (5782) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (5792) esp_netif_lwip: check: remote, if=0x3fcb1df0 fn=0x420715dc
0x420715dc: esp_netif_dhcpc_start_api at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_netif/lwip/esp_netif_lwip.c:1400
D (5792) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3fcb1df0
D (5802) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcb1df0
D (5812) esp_netif_lwip: if0x3fcb1df0 start ip lost tmr: no need start because netif=0x3fcb1e74 interval=120 ip=0
D (5822) esp_netif_lwip: starting dhcp client
D (5822) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (5862) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
D (6822) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcb1e74
D (6822) esp_netif_lwip: if0x3fcb1df0 ip changed=1
D (6822) event: running post IP_EVENT:0 with handler 0x42017a14 and context 0x3fcb1dd0 on loop 0x3fcb0744
0x42017a14: event_handler at F:/GitHub/esp-rainmaker/examples/common/app_wifi/app_wifi.c:130
I (6832) app_wifi: Connected with IP Address:192.168.1.99
D (6832) event: running post IP_EVENT:0 with handler 0x420735e8 and context 0x3fcb2130 on loop 0x3fcb0744
0x420735e8: wifi_default_action_sta_got_ip at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/esp_wifi/src/wifi_default.c:127
D (6842) wifi_init_default: Got IP wifi default handler entered
D (6852) esp_netif_handlers: esp_netif action got_ip with netif0x3fcb1df0 from event_id=0
I (6862) esp_netif_handlers: sta ip: 192.168.1.99, mask: 255.255.255.0, gw: 192.168.1.1
D (6872) event: running post IP_EVENT:0 with handler 0x42010920 and context 0x3fcc0518 on loop 0x3fcb0744
0x42010920: esp_rmaker_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:205
I (6882) esp_rmaker_cmd_resp: Enabling Command-Response Module.
D (6882) nvs: nvs_open_from_partition local_ctrl 0
D (6892) nvs: nvs_get_str_or_blob pop
D (6892) nvs: nvs_get_str_or_blob pop
D (6892) nvs: nvs_close 20
D (6902) esp_rmaker_device: Param POP added in Local Control
D (6902) esp_rmaker_device: Param Type added in Local Control
D (6912) esp_rmaker_local: Local Control Service Enabled
I (6912) esp_rmaker_local: Starting ESP Local control with HTTP Transport and security version: 1
D (6922) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (6932) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x0
I (6882) led_serv: led 0: pulse slow
D (6942) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x0
D (6952) nvs: nvs_open_from_partition local_ctrl 0
D (6952) nvs: nvs_get_str_or_blob pop
D (6952) nvs: nvs_get_str_or_blob pop
D (6962) nvs: nvs_close 21
I (6972) esp_https_server: Starting server
D (6972) esp_https_server: SSL disabled, using plain HTTP
D (6972) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:1 posted to loop 0x3fcb0744
D (6982) httpd: httpd_thread: web server started
I (6982) esp_https_server: Server listening on port 8080
D (6992) httpd: httpd_server: doing select maxfd+1 = 56
D (6992) protocomm_httpd: Adding endpoint : esp_local_ctrl/version
D (7002) httpd_uri: httpd_register_uri_handler: [0] installed /esp_local_ctrl/version
D (7012) protocomm_httpd: Adding endpoint : esp_local_ctrl/session
D (7022) httpd_uri: httpd_find_uri_handler: [0] = /esp_local_ctrl/version
D (7022) httpd_uri: httpd_register_uri_handler: [0] exists /esp_local_ctrl/version
D (7032) httpd_uri: httpd_register_uri_handler: [1] installed /esp_local_ctrl/session
D (7042) protocomm_httpd: Adding endpoint : esp_local_ctrl/control
D (7052) httpd_uri: httpd_find_uri_handler: [0] = /esp_local_ctrl/version
D (7052) httpd_uri: httpd_find_uri_handler: [1] = /esp_local_ctrl/session
D (7062) httpd_uri: httpd_register_uri_handler: [0] exists /esp_local_ctrl/version
D (7072) httpd_uri: httpd_register_uri_handler: [1] exists /esp_local_ctrl/session
D (7072) httpd_uri: httpd_register_uri_handler: [2] installed /esp_local_ctrl/control
I (7082) esp_rmaker_local: esp_local_ctrl service started with name : ebje5v5bUdYWat7qSu7ePa
D (7092) event: running post RMAKER_EVENT:6 with handler 0x4200e6b8 and context 0x3fcb9eac on loop 0x3fcb0744
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
I (7102) esp_mqtt_glue: Connecting to xxxxxxxxxxxxxxxx-ats.iot.eu-central-1.amazonaws.com
W (7102) app_main: Unhandled RainMaker Event: 6
D (7112) mqtt_client: Core selection disabled
I (7122) esp_rmaker_core: Waiting for MQTT connection
D (7122) event: running post MQTT_EVENTS:7 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
D (7142) esp_mqtt_glue: Other event id:7
D (7142) esp-tls: host:xxxxxxxxxxxxxx-ats.iot.eu-central-1.amazonaws.com: strlen 49
D (7202) esp-tls: [sock=57] Resolved IPv4 address: 18.195.179.209
D (7202) esp-tls: [sock=57] Connecting to server. HOST: xxxxxxxxxxxxxxx-ats.iot.eu-central-1.amazonaws.com, Port: 443
D (7232) esp-tls-mbedtls: Use certificate bundle
D (7252) esp-tls: handshake in progress...
D (7352) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (7352) esp-x509-crt-bundle: 41 certificates in bundle
I (7372) esp-x509-crt-bundle: Certificate validated
D (7652) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (7952) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (8232) mqtt_client: Transport connected to mqtts://xxxxxxxxxxxxxx-ats.iot.eu-central-1.amazonaws.com:443
D (8232) mqtt_client: Sending MQTT CONNECT message, type: 1, id: 0000
D (8252) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (8502) SSL TLS: add mbedtls RX buffer
D (8502) SSL TLS: end
D (8502) SSL TLS: RX left 3 bytes
D (8502) mqtt_client: mqtt_message_receive: first byte: 0x20
D (8512) transport_base: remain data in cache, need to read again
D (8512) SSL TLS: add mbedtls RX buffer
D (8522) SSL TLS: end
D (8522) SSL TLS: RX left 2 bytes
D (8522) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (8532) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (8542) transport_base: remain data in cache, need to read again
D (8542) SSL TLS: add mbedtls RX buffer
D (8552) SSL TLS: end
D (8552) mqtt_client: mqtt_message_receive: read_len=2
D (8552) mqtt_client: mqtt_message_receive: transport_read():4 4
D (8562) mqtt_client: Connected
D (8562) event: running post MQTT_EVENTS:1 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
I (8572) esp_mqtt_glue: MQTT Connected
D (8582) event: running post RMAKER_COMMON_EVENT:3 with handler 0x4200e6b8 and context 0x3fcb9ee0 on loop 0x3fcb0744
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
I (8592) app_main: MQTT Connected.
D (8592) event: running post RMAKER_COMMON_EVENT:3 with handler 0x420107d4 and context 0x3fcc04a0 on loop 0x3fcb0744
0x420107d4: esp_rmaker_mqtt_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:110
D (8602) event: running post RMAKER_COMMON_EVENT:3 with handler 0x42010920 and context 0x3fcc0538 on loop 0x3fcb0744
0x42010920: esp_rmaker_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:205
D (8612) event: running post RMAKER_COMMON_EVENT:3 with handler 0x42010904 and context 0x3fcc05ec on loop 0x3fcb0744
0x42010904: reset_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:95
D (8622) event: running post RMAKER_COMMON_EVENT:3 with handler 0x42015108 and context 0x3fca7378 on loop 0x3fcb0744
0x42015108: event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_cmd_resp_manager.c:118
I (8642) esp_rmaker_cmd_resp: Checking for pending commands.
D (8642) mqtt_client: mqtt_enqueue id: 12819, type=8 successful
D (8652) outbox: ENQUEUE msgid=12819, msg_type=8, len=42, size=42
D (8662) mqtt_client: Sent subscribe topic=node/ebje5v5bUdYWat7qSu7ePa/to-node, id: 12819, type=8 successful
D (8662) esp_mqtt_glue: Subscribed to topic: node/ebje5v5bUdYWat7qSu7ePa/to-node
D (8672) esp_rmaker_common_cmd_resp: Generated empty response for requesting pending commands.
D (8682) esp_mqtt_glue: Publishing to $aws/rules/esp_cmd_resp/node/ebje5v5bUdYWat7qSu7ePa/from-node
D (8692) mqtt_client: mqtt_enqueue id: 40868, type=3 successful
D (8692) outbox: ENQUEUE msgid=40868, msg_type=3, len=73, size=115
D (8702) esp_rmaker_mqtt_budget: MQTT budget decreased to 99.
D (8712) esp_rmaker_node_config: Generated Node config of length 4522
I (8712) esp_rmaker_node_config: Reporting Node Configuration of length 4521 bytes.
D (8722) SSL TLS: add mbedtls RX buffer
D (8722) esp_rmaker_node_config: {"node_id":"ebje5v5bUdYWat7qSu7ePa","config_version":"2020-03-20","info":{"name":"NX-G-1","fw_version":"1.9","type":"NX-G-1","model":"neox1","project_name":"neox1","platform":"esp32s3"},"devices":[{"name":"Brama","type":"esp.device.switch","primary":"St","params":[{"name":"Name","type":"esp.param.name","data_type":"string","properties":["read","write"]},{"name":"St","type":"esp.param.power","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.outstate"},{"name":"TO","type":"esp.param.cust.outtime","data_type":"int","properties":["read","write"],"bounds":{"min":-1,"max":10,"step":1},"ui_type":"esp.ui.cust.outtime"},{"name":"ConSt","type":"esp.param.cust.connections","data_type":"string","properties":["read","write"],"valid_strs":["Brama","Furtka","Przycisk zewn??trzny"],"ui_type":"esp.ui.cust.conns"},{"name":"Hd","type":"esp.param.cust.nodehide","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.hide"}]},{"name":"Furtka","type":"esp.device.switch","primary":"St","params":[{"name":"Name","type":"esp.param.name","data_type":"string","properties":["read","write"]},{"name":"St","type":"esp.param.power","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.outstate"},{"name":"TO","type":"esp.param.cust.outtime","data_type":"int","properties":["read","write"],"bounds":{"min":-1,"max":10,"step":1},"ui_type":"esp.ui.cust.outtime"},{"name":"ConSt","type":"esp.param.cust.connections","data_type":"string","properties":["read","write"],"valid_strs":["Brama","Furtka","Przycisk zewn??trzny"],"ui_type":"esp.ui.cust.conns"},{"name":"Hd","type":"esp.param.cust.nodehide","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.hide"}]},{"name":"Przycisk zewnetrzny","type":"esp.device.contact-sensor","primary":"St","params":[{"name":"Name","type":"esp.param.name","data_type":"string","properties":["read","write"]},{"name":"St","type":"esp.param.contact-detection-state","data_type":"bool","properties":["read"],"ui_type":"esp.ui.cust.instate"},{"name":"TI","type":"esp.param.cust.intime","data_type":"int","properties":["read","write"],"bounds":{"min":0,"max":10,"step":1},"ui_type":"esp.ui.cust.outtime"},{"name":"PtxIon","type":"esp.param.cust.push.text-on","data_type":"string","properties":["read","write"],"ui_type":"esp.ui.cust.pushtext"},{"name":"PuIon","type":"esp.param.cust.push-on","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.push"},{"name":"PtxIof","type":"esp.param.cust.push.text-off","data_type":"string","properties":["read","write"],"ui_type":"esp.ui.cust.pushtext"},{"name":"PuIof","type":"esp.param.cust.push-off","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.push"},{"name":"SIrev","type":"esp.param.cust.loginv","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.loginv"},{"name":"Hd","type":"esp.param.cust.nodehide","data_type":"bool","properties":["read","write"],"ui_type":"esp.ui.cust.hide"}]}],"services":[{"name":"MENU_SCAN","type":"custom.device.menu.scanlist","params":[{"name":"ScAc","type":"esp.param.cust.scansens","data_type":"bool","properties":["write"]},{"name":"DelAllAc","type":"esp.param.cust.delallsens","data_type":"bool","properties":["write"]}]},{"name":"MENU_NODE","type":"custom.device.menu.nodeparams","params":[{"name":"DevNm","type":"esp.param.cust.nodename","data_type":"string","properties":["read","write"]},{"name":"McNd","type":"esp.param.cust.mac","data_type":"string","properties":["read"]},{"name":"UsEdAl","type":"esp.param.cust.editperm","data_type":"bool","properties":["read","write"]}]},{"name":"Time","type":"esp.service.time","params":[{"name":"TZ","type":"esp.param.tz","data_type":"string","properties":["read","write"]},{"name":"TZ-POSIX","type":"esp.param.tz_posix","data_type":"string","properties":["read","write"]}]},{"name":"Schedule","type":"esp.service.schedule","params":[{"name":"Schedules","type":"esp.param.schedules","data_type":"array","properties":["read","write"],"bounds":{"max":10}}]},{"name":"Scenes","type":"esp.service.scenes","attributes":[{"name":"deactivation_support","value":"no"}],"params":[{"name":"Scenes","type":"esp.param.scenes","data_type":"array","properties":["read","write"],"bounds":{"max":10}}]},{"name":"Local Control","type":"esp.service.local_control","params":[{"name":"POP","type":"esp.param.local_control_pop","data_type":"string","properties":["read"]},{"name":"Type","type":"esp.param.local_control_type","data_type":"int","properties":["read"]}]}]}
D (8732) SSL TLS: end
D (9122) esp_mqtt_glue: Publishing to $aws/rules/esp_node_config/node/ebje5v5bUdYWat7qSu7ePa/config
D (9122) SSL TLS: RX left 4 bytes
D (9142) mqtt_client: mqtt_message_receive: first byte: 0x90
D (9142) transport_base: remain data in cache, need to read again
D (9152) SSL TLS: add mbedtls RX buffer
D (9152) SSL TLS: end
D (9152) SSL TLS: RX left 3 bytes
D (9162) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x3
D (9162) mqtt_client: mqtt_message_receive: total message length: 5 (already read: 2)
D (9172) transport_base: remain data in cache, need to read again
D (9182) SSL TLS: add mbedtls RX buffer
D (9182) SSL TLS: end
D (9192) mqtt_client: mqtt_message_receive: read_len=3
D (9192) mqtt_client: mqtt_message_receive: transport_read():5 5
D (9202) mqtt_client: msg_type=9, msg_id=12819
D (9202) mqtt_client: pending_id=40868, pending_msg_count = 2
D (9212) outbox: DELETED msgid=12819, msg_type=8, remain size=73
D (9212) mqtt_client: deliver_suback, message_length_read=5, message_length=5
D (9222) event: running post MQTT_EVENTS:3 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
D (9232) esp_mqtt_glue: MQTT_EVENT_SUBSCRIBED, msg_id=12819
D (9242) mqtt_client: mqtt_enqueue_oversized id: 29708, type=3 successful
D (9242) outbox: ENQUEUE msgid=29708, msg_type=3, len=4589, size=4662
D (9252) mqtt_client: Sending fragmented message, remains to send 3567 bytes of 4521
D (9262) mqtt_client: Sending fragmented message, remains to send 2543 bytes of 4521
D (9272) mqtt_client: Sending fragmented message, remains to send 1519 bytes of 4521
D (9282) mqtt_client: Sending fragmented message, remains to send 495 bytes of 4521
D (9302) esp_rmaker_mqtt_budget: MQTT budget decreased to 98.
D (9302) SSL TLS: add mbedtls RX buffer
D (9302) SSL TLS: end
D (9302) SSL TLS: RX left 3 bytes
D (9302) mqtt_client: mqtt_message_receive: first byte: 0x40
D (9312) transport_base: remain data in cache, need to read again
D (9312) SSL TLS: add mbedtls RX buffer
D (9322) SSL TLS: end
D (9322) SSL TLS: RX left 2 bytes
D (9322) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (9332) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (9342) transport_base: remain data in cache, need to read again
D (9342) SSL TLS: add mbedtls RX buffer
D (9352) SSL TLS: end
D (9352) mqtt_client: mqtt_message_receive: read_len=2
D (9362) mqtt_client: mqtt_message_receive: transport_read():4 4
D (9362) mqtt_client: msg_type=4, msg_id=40868
D (9372) mqtt_client: pending_id=29708, pending_msg_count = 2
D (9372) outbox: DELETED msgid=40868, msg_type=3, remain size=4589
D (9382) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (9392) event: running post MQTT_EVENTS:5 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
0x42010904: reset_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:95
D (9402) esp_mqtt_glue: MQTT_EVENT_PUBLISHED, msg_id=40868
D (9402) event: running post RMAKER_COMMON_EVENT:5 with handler 0x4200e6b8 and context 0x3fcb9ee0 on loop 0x3fcb0744
D (9412) mqtt_client: mqtt_enqueue id: 7537, type=8 successful
D (9422) outbox: ENQUEUE msgid=7537, msg_type=8, len=48, size=4637
I (9412) app_main: MQTT Published. Msg id: 40868.
D (9432) mqtt_client: Sent subscribe topic=node/ebje5v5bUdYWat7qSu7ePa/params/remote, id: 7537, type=8 successful
D (9432) event: running post RMAKER_COMMON_EVENT:5 with handler 0x42010904 and context 0x3fcc05ec on loop 0x3fcb0744
D (9442) esp_mqtt_glue: Subscribed to topic: node/ebje5v5bUdYWat7qSu7ePa/params/remote
D (9442) SSL TLS: add mbedtls RX buffer
D (9412) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
I (9462) esp_rmaker_param: Params MQTT Init done.
D (9462) SSL TLS: end
D (9472) esp_rmaker_param: Allocating s_node_params_buf for size 4096.
D (9482) SSL TLS: RX left 3 bytes
I (9482) esp_rmaker_param: Reporting params (init): {"Brama":{"Name":"Brama","St":false,"TO":1,"ConSt":"ebje5v5bUdYWat7qSu7ePa#Brama","Hd":false},"Furtka":{"Name":"Furtka","St":false,"TO":3,"ConSt":"ebje5v5bUdYWat7qSu7ePa#Furtka","Hd":false},"Przycisk zewnetrzny":{"Name":"Przycisk zewn??trzny","St":true,"TI":0,"PtxIon":"wci??ni??ty","PuIon":false,"PtxIof":"zwolniony","PuIof":false,"SIrev":false,"Hd":false},"MENU_SCAN":{"ScAc":false,"DelAllAc":false},"MENU_NODE":{"DevNm":"Odbiornik bramowy","McNd":"70:04:1D:AF:64:B8","UsEdAl":false},"Time":{"TZ":"Europe/Warsaw","TZ-POSIX":"CET-1CEST,M3.5.0,M10.5.0/3"},"Schedule":{"Schedules":[]},"Scenes":{"Scenes":[]},"Local Control":{"POP":"a0b0410b","Type":1}}
D (9492) mqtt_client: mqtt_message_receive: first byte: 0x40
D (9552) esp_mqtt_glue: Publishing to $aws/rules/esp_init_params/node/ebje5v5bUdYWat7qSu7ePa/params/local/init
D (9552) transport_base: remain data in cache, need to read again
D (9572) SSL TLS: add mbedtls RX buffer
D (9572) SSL TLS: end
D (9582) SSL TLS: RX left 2 bytes
D (9582) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (9592) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (9592) transport_base: remain data in cache, need to read again
D (9602) SSL TLS: add mbedtls RX buffer
D (9602) SSL TLS: end
D (9612) mqtt_client: mqtt_message_receive: read_len=2
D (9612) mqtt_client: mqtt_message_receive: transport_read():4 4
D (9622) mqtt_client: msg_type=4, msg_id=29708
D (9622) mqtt_client: pending_id=7537, pending_msg_count = 2
D (9632) outbox: DELETED msgid=29708, msg_type=3, remain size=48
D (9632) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (9642) event: running post MQTT_EVENTS:5 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
D (9652) esp_mqtt_glue: MQTT_EVENT_PUBLISHED, msg_id=29708
D (9662) event: running post RMAKER_COMMON_EVENT:5 with handler 0x4200e6b8 and context 0x3fcb9ee0 on loop 0x3fcb0744
D (9662) SSL TLS: add mbedtls RX buffer
I (9672) app_main: MQTT Published. Msg id: 29708.
D (9672) SSL TLS: end
D (9682) event: running post RMAKER_COMMON_EVENT:5 with handler 0x42010904 and context 0x3fcc05ec on loop 0x3fcb0744
D (9682) SSL TLS: RX left 4 bytes
D (9692) mqtt_client: mqtt_message_receive: first byte: 0x90
D (9702) transport_base: remain data in cache, need to read again
D (9702) SSL TLS: add mbedtls RX buffer
D (9712) SSL TLS: end
D (9712) SSL TLS: RX left 3 bytes
D (9712) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x3
D (9722) mqtt_client: mqtt_message_receive: total message length: 5 (already read: 2)
D (9732) transport_base: remain data in cache, need to read again
D (9742) SSL TLS: add mbedtls RX buffer
D (9742) SSL TLS: end
D (9742) mqtt_client: mqtt_message_receive: read_len=3
D (9752) mqtt_client: mqtt_message_receive: transport_read():5 5
D (9752) mqtt_client: msg_type=9, msg_id=7537
D (9762) mqtt_client: pending_id=7537, pending_msg_count = 1
D (9762) outbox: DELETED msgid=7537, msg_type=8, remain size=0
D (9772) mqtt_client: deliver_suback, message_length_read=5, message_length=5
D (9782) event: running post MQTT_EVENTS:3 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
D (9792) esp_mqtt_glue: MQTT_EVENT_SUBSCRIBED, msg_id=7537
D (9792) mqtt_client: mqtt_enqueue id: 29647, type=3 successful
D (9802) outbox: ENQUEUE msgid=29647, msg_type=3, len=730, size=730
D (9812) esp_rmaker_mqtt_budget: MQTT budget decreased to 97.
I (9812) esp_rmaker_ota_using_topics: Subscribing to: node/ebje5v5bUdYWat7qSu7ePa/otaurl
D (9822) mqtt_client: mqtt_enqueue id: 8797, type=8 successful
D (9822) outbox: ENQUEUE msgid=8797, msg_type=8, len=41, size=771
D (9832) mqtt_client: Sent subscribe topic=node/ebje5v5bUdYWat7qSu7ePa/otaurl, id: 8797, type=8 successful
D (9842) esp_mqtt_glue: Subscribed to topic: node/ebje5v5bUdYWat7qSu7ePa/otaurl
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
0x42010904: reset_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:95
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
D (10042) SSL TLS: add mbedtls RX buffer
D (10042) SSL TLS: end
D (10042) SSL TLS: RX left 3 bytes
D (10042) mqtt_client: mqtt_message_receive: first byte: 0x40
D (10042) transport_base: remain data in cache, need to read again
D (10052) SSL TLS: add mbedtls RX buffer
D (10052) SSL TLS: end
D (10062) SSL TLS: RX left 2 bytes
D (10062) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (10072) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (10072) transport_base: remain data in cache, need to read again
D (10082) SSL TLS: add mbedtls RX buffer
D (10082) SSL TLS: end
D (10092) mqtt_client: mqtt_message_receive: read_len=2
D (10092) mqtt_client: mqtt_message_receive: transport_read():4 4
D (10102) mqtt_client: msg_type=4, msg_id=29647
D (10102) mqtt_client: pending_id=8797, pending_msg_count = 2
D (10112) outbox: DELETED msgid=29647, msg_type=3, remain size=41
D (10112) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (10122) event: running post MQTT_EVENTS:5 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
D (10132) esp_mqtt_glue: MQTT_EVENT_PUBLISHED, msg_id=29647
D (10142) event: running post RMAKER_COMMON_EVENT:5 with handler 0x4200e6b8 and context 0x3fcb9ee0 on loop 0x3fcb0744
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
I (10152) app_main: MQTT Published. Msg id: 29647.
D (10142) SSL TLS: add mbedtls RX buffer
D (10152) event: running post RMAKER_COMMON_EVENT:5 with handler 0x42010904 and context 0x3fcc05ec on loop 0x3fcb0744
0x42010904: reset_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:95
D (10162) SSL TLS: end
D (10172) SSL TLS: RX left 4 bytes
D (10172) mqtt_client: mqtt_message_receive: first byte: 0x90
D (10182) transport_base: remain data in cache, need to read again
D (10192) SSL TLS: add mbedtls RX buffer
D (10192) SSL TLS: end
D (10192) SSL TLS: RX left 3 bytes
D (10202) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x3
D (10202) mqtt_client: mqtt_message_receive: total message length: 5 (already read: 2)
D (10212) transport_base: remain data in cache, need to read again
D (10222) SSL TLS: add mbedtls RX buffer
D (10222) SSL TLS: end
D (10222) mqtt_client: mqtt_message_receive: read_len=3
D (10232) mqtt_client: mqtt_message_receive: transport_read():5 5
D (10242) mqtt_client: msg_type=9, msg_id=8797
D (10242) mqtt_client: pending_id=8797, pending_msg_count = 1
D (10252) outbox: DELETED msgid=8797, msg_type=8, remain size=0
D (10252) mqtt_client: deliver_suback, message_length_read=5, message_length=5
D (10262) event: running post MQTT_EVENTS:3 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
D (10272) esp_mqtt_glue: MQTT_EVENT_SUBSCRIBED, msg_id=8797
D (10552) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
I (10962) app_driver: INPUT zmiana stanu
I (10962) app_driver: RnmkUpdateInputState
W (10962) app_driver: Input state updated and reported: 1
I (10962) esp_rmaker_param: Reporting params: {"Przycisk zewnetrzny":{"St":true}}
D (10972) esp_mqtt_glue: Publishing to $aws/rules/esp_set_params/node/ebje5v5bUdYWat7qSu7ePa/params/local
D (10982) mqtt_client: mqtt_enqueue id: 65200, type=3 successful
D (10982) outbox: ENQUEUE msgid=65200, msg_type=3, len=107, size=107
D (10992) esp_rmaker_mqtt_budget: MQTT budget decreased to 96.
W (11002) app_main: ########## APP_WIFI_PROV_TRANSPORT_BLE ########
D (11042) SSL TLS: add mbedtls RX buffer
D (11042) SSL TLS: end
D (11042) SSL TLS: RX left 3 bytes
D (11042) mqtt_client: mqtt_message_receive: first byte: 0x40
D (11042) transport_base: remain data in cache, need to read again
D (11052) SSL TLS: add mbedtls RX buffer
D (11052) SSL TLS: end
D (11052) SSL TLS: RX left 2 bytes
D (11062) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (11072) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (11072) transport_base: remain data in cache, need to read again
D (11082) SSL TLS: add mbedtls RX buffer
D (11082) SSL TLS: end
D (11092) mqtt_client: mqtt_message_receive: read_len=2
D (11092) mqtt_client: mqtt_message_receive: transport_read():4 4
D (11102) mqtt_client: msg_type=4, msg_id=65200
D (11102) mqtt_client: pending_id=65200, pending_msg_count = 1
D (11112) outbox: DELETED msgid=65200, msg_type=3, remain size=0
D (11112) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (11122) event: running post MQTT_EVENTS:5 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
D (11132) esp_mqtt_glue: MQTT_EVENT_PUBLISHED, msg_id=65200
D (11142) event: running post RMAKER_COMMON_EVENT:5 with handler 0x4200e6b8 and context 0x3fcb9ee0 on loop 0x3fcb0744
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
I (11152) app_main: MQTT Published. Msg id: 65200.
D (11152) event: running post RMAKER_COMMON_EVENT:5 with handler 0x42010904 and context 0x3fcc05ec on loop 0x3fcb0744
0x42010904: reset_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:95
D (12122) esp_rmaker_mqtt_budget: MQTT budget increased to 97
D (12152) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (13162) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (14172) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
I (14852) esp_rmaker_ota_using_topics: Fetching OTA details, if any.
D (14852) esp_mqtt_glue: Publishing to $aws/rules/esp_node_otafetch/node/ebje5v5bUdYWat7qSu7ePa/otafetch
D (14852) mqtt_client: mqtt_enqueue id: 6516, type=3 successful
D (14862) outbox: ENQUEUE msgid=6516, msg_type=3, len=126, size=126
D (14872) esp_rmaker_mqtt_budget: MQTT budget decreased to 96.
D (14912) SSL TLS: add mbedtls RX buffer
D (14912) SSL TLS: end
D (14912) SSL TLS: RX left 3 bytes
D (14912) mqtt_client: mqtt_message_receive: first byte: 0x40
D (14912) transport_base: remain data in cache, need to read again
D (14922) SSL TLS: add mbedtls RX buffer
D (14922) SSL TLS: end
D (14932) SSL TLS: RX left 2 bytes
D (14932) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (14942) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (14952) transport_base: remain data in cache, need to read again
D (14952) SSL TLS: add mbedtls RX buffer
D (14962) SSL TLS: end
D (14962) mqtt_client: mqtt_message_receive: read_len=2
D (14962) mqtt_client: mqtt_message_receive: transport_read():4 4
D (14972) mqtt_client: msg_type=4, msg_id=6516
D (14972) mqtt_client: pending_id=6516, pending_msg_count = 1
D (14982) outbox: DELETED msgid=6516, msg_type=3, remain size=0
D (14992) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (14992) event: running post MQTT_EVENTS:5 with handler 0x4204c4ac and context 0x3fcbddc0 on loop 0x3fcbd480
0x4204c4ac: mqtt_event_handler at F:/GitHub/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:229
D (15002) esp_mqtt_glue: MQTT_EVENT_PUBLISHED, msg_id=6516
D (15012) event: running post RMAKER_COMMON_EVENT:5 with handler 0x4200e6b8 and context 0x3fcb9ee0 on loop 0x3fcb0744
0x4200e6b8: event_handler at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:1410
I (15022) app_main: MQTT Published. Msg id: 6516.
D (15022) event: running post RMAKER_COMMON_EVENT:5 with handler 0x42010904 and context 0x3fcc05ec on loop 0x3fcb0744
0x42010904: reset_event_handler at F:/GitHub/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_core.c:95
D (16022) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (17032) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (17122) esp_rmaker_mqtt_budget: MQTT budget increased to 97
D (18042) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (19052) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (20062) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (21072) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (22082) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (22122) esp_rmaker_mqtt_budget: MQTT budget increased to 98
D (23092) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (24102) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (25112) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (25702) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (25712) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (25712) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (26012) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (26012) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (26122) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (26932) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
D (26942) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1df0
W (27002) app_main: ########## IDZIE DALEJ ########
btdm: bss start 0x3fcef180, len 36
btdm: data start 0x3fcef174, data start rom 0x40057350, len 12
0x40057350: _data_start_btdm_rom in ROM
MAGIC fadebead VERSION 00010006
I (27002) BLE_INIT: BT controller compile version [85b425c]
Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC : 0x420299d1 PS : 0x00060e30 A0 : 0x82038ee8 A1 : 0x3fcabda0
0x420299d1: semphr_delete_wrapper at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:528
A2 : 0x00000005 A3 : 0x00000001 A4 : 0x60006110 A5 : 0x00000000
A6 : 0x3fcabdf0 A7 : 0x0000000c A8 : 0x80377554 A9 : 0x3fcabd80
A10 : 0x00000001 A11 : 0x00000000 A12 : 0x3fcb9d60 A13 : 0x00000000
A14 : 0x00000000 A15 : 0xb33fffff SAR : 0x00000009 EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000005 LBEG : 0x4037e4d0 LEND : 0x4037e4dc LCOUNT : 0x00000000
0x4037e4d0: ram_wifi_tx_dig_gain at ??:?
0x4037e4dc: ram_wifi_tx_dig_gain at ??:?
Backtrace: 0x420299ce:0x3fcabda0 0x42038ee5:0x3fcabdc0 0x42039cc4:0x3fcabde0 0x4202a253:0x3fcabe30 0x42032a72:0x3fcabe70 0x4200dbe0:0x3fcabed0 0x4200e65f:0x3fcabef0 0x420f4dc3:0x3fcac020 0x403831ae:0x3fcac050
0x420299ce: semphr_delete_wrapper at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:521
0x42038ee5: ble_sm_alg_gen_key_pair at ??:?
0x42039cc4: btdm_controller_init at ??:?
0x4202a253: esp_bt_controller_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/bt/controller/esp32c3/bt.c:1305
0x42032a72: nimble_port_init at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:153
0x4200dbe0: Nimble_init at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:3301
0x4200e65f: app_main at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:2124
0x420f4dc3: main_task at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/freertos/app_startup.c:208 (discriminator 13)
0x403831ae: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf-v5.1-rc1/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162Attached also sdkconfig sdkconfig.zip
jacek12345
commented
1 year ago Do You have any idea? Or any example with reusing NimBle after provisioning?
IshaESP
commented
1 year ago Hey @jacek12345 , We tried on both the versions 5.0 and 5.1, and the IDF and rainmaker examples work cleanly.
Looking at your log, we see that you have somehow by passed the internal nimble initialization which happens via the wifi_provisioning -- protocomm layer endpoint.
Since there appears to be code changes, is it possible for you to suggest any way to use IDF examples to reproduce the issue you have mentioned ? Any minimalistic change we can do to simulate the same scenario as seen at your end.
We would have performed git bisect to find failing commit, but we can do it once we are able to reproduce the issue at our end
jacek12345
commented
1 year ago I just updated ESP-IDF to 5.1 release. Still have a problem. I reproduced this issue on Rainmaker example 'switch' with little code addition. Here is what i added:
On the beginning:
#include "app_priv.h"
//========= My code added =================
#include "esp_nimble_hci.h"
#include "nimble/nimble_port.h"
#include "nimble/nimble_port_freertos.h"
#include "host/ble_hs.h"
#include "host/util/util.h"
#include "console/console.h"
#include "services/gap/ble_svc_gap.h"
#include "bleprph.h"
static void bleprph_on_reset(int reason)
{
ESP_LOGE("app_main", "Resetting state; reason=%d", reason);
}
/**
* The nimble host executes this callback when a GAP event occurs. The
* application associates a GAP event callback with each connection that is
* established. blecent uses the same callback for all connections.
*
* @param event The event being signalled.
* @param arg Application-specified argument; unused by
* blecent.
*
* @return 0 if the application successfully handled the
* event; nonzero on failure. The semantics
* of the return code is specific to the
* particular GAP event being signalled.
*
*
*/
static int blecent_gap_event(struct ble_gap_event *event, void *arg)
{
switch (event->type) {
case BLE_GAP_EVENT_DISC:
ESP_LOGI("app_main", "Event detected");
return 0;
case BLE_GAP_EVENT_DISC_COMPLETE:
MODLOG_DFLT(INFO, "discovery complete; reason=%d\n",
event->disc_complete.reason);
return 0;
case BLE_GAP_EVENT_MTU:
MODLOG_DFLT(INFO, "mtu update event; conn_handle=%d cid=%d mtu=%d\n",
event->mtu.conn_handle,
event->mtu.channel_id,
event->mtu.value);
return 0;
case BLE_GAP_EVENT_REPEAT_PAIRING:
return 0;
default:
return 0;
}
}
/**
* Initiates the GAP general discovery procedure.
*/
static void blecent_scan(void)
{
uint8_t own_addr_type;
struct ble_gap_disc_params disc_params;
int rc;
/* Figure out address to use while advertising (no privacy for now) */
//rc = ble_hs_id_infer_auto(0, &own_addr_type);
rc = ble_hs_id_infer_auto(1, &own_addr_type);
if (rc != 0) {
MODLOG_DFLT(ERROR, "error determining address type; rc=%d\n", rc);
return;
}
/* Tell the controller to filter duplicates; we don't want to process
* repeated advertisements from the same device.
*/
disc_params.filter_duplicates = 0;//1;
/**
* Perform a passive scan. I.e., don't send follow-up scan requests to
* each advertiser.
*/
disc_params.passive = 1;
disc_params.itvl = 800;
disc_params.window = 480;
disc_params.filter_policy = 0;
disc_params.limited = 0;
rc = ble_gap_disc(own_addr_type, BLE_HS_FOREVER, &disc_params, blecent_gap_event, NULL);
if (rc != 0) {
MODLOG_DFLT(ERROR, "Error initiating GAP discovery procedure; rc=%d\n",
rc);
}
}
static void bleprph_on_sync(void)
{
blecent_scan();
}
void bleprph_host_task(void *param)
{
ESP_LOGI("app_main", "BLE Host Task Started");
/* This function will return only when nimble_port_stop() is executed */
nimble_port_run();
nimble_port_freertos_deinit();
}
//END My code added =============
static const char *TAG = "app_main";
esp_rmaker_device_t *switch_device;On the end:
err = app_wifi_start(POP_TYPE_RANDOM);
if (err != ESP_OK) {
ESP_LOGE(TAG, "Could not start Wifi. Aborting!!!");
vTaskDelay(5000/portTICK_PERIOD_MS);
abort();
}
// =========== My code added =================
vTaskDelay(2000);
esp_err_t ret;
ret = nimble_port_init();
if (ret != ESP_OK)
{
ESP_LOGE(TAG, "Failed to init nimble %d ", ret);
return;
}
//Initialize the NimBLE host configuration.
ble_hs_cfg.reset_cb = bleprph_on_reset;
ble_hs_cfg.sync_cb = bleprph_on_sync;
nimble_port_freertos_init(bleprph_host_task);
//END My code added ============== Zipped 'main' folder from Rainmaker 'switch' example. main.zip
IshaESP
commented
1 year ago Hi @jacek12345,
There is a flag WIFI_PROV_KEEP_BLE_ON_AFTER_PROV which keeps the BT stack on after provisioning is done. By default, this flag is disabled. When disabled, it cleans all the memory required for BT stack to init. So now after provisioning is done, the flag is disabled, it cleans up all the memory thus preventing BT stack initializing.
The patch shared above has API's name as bleprph but the code is actually performing blecent role of scanning.
The solution to this is:
WIFI_PROV_KEEP_BLE_ON_AFTER_PROV from Component config -> Wi-Fi Provisioning Manager -> WIFI_PROV_KEEP_BLE_ON_AFTER_PROV /* vTaskDelay(2000);
esp_err_t ret;
ret = nimble_port_init();
if (ret != ESP_OK)
{
ESP_LOGE(TAG, "Failed to init nimble %d ", ret);
return;
}
//Initialize the NimBLE host configuration.
ble_hs_cfg.reset_cb = bleprph_on_reset;
ble_hs_cfg.sync_cb = bleprph_on_sync;
nimble_port_freertos_init(bleprph_host_task); */
//As BT stack is already up, only scanning the device is remaining
blecent_scan();
}@IshaESP , Proposed solution works only when device is unprovisioned and then go throw provisioning process. After restart, when device is already provisioned it doesn't work. I suppose, that BLE is not initialised when device is already provisioned?
So now after provisioning is done, the flag is disabled, it cleans up all the memory thus preventing BT stack initializing
Why it prevents BT stack initialising? If BT is deinitialised after provisioning, it should be abble to initialise it one more time. Isn't it?
I think that the only way is to disable WIFI_PROV_KEEP_BLE_ON_AFTER_PROV and initialise BLE always from the beginning (no matter if provisioning was done or not), after wifi starts.
I also tried to add only nimble_port_stop(); and there is crasch immediately.
err = app_wifi_start(POP_TYPE_RANDOM);
if (err != ESP_OK) {
ESP_LOGE(TAG, "Could not start Wifi. Aborting!!!");
vTaskDelay(5000/portTICK_PERIOD_MS);
abort();
}
// =========== My code added =================
vTaskDelay(1000);
int ret = nimble_port_stop();
}Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC : 0x4202dcdc PS : 0x00060030 A0 : 0x8200b4a6 A1 : 0x3fcab460
0x4202dcdc: ble_npl_sem_init at C:/Espressif/frameworks/esp-idf-v5.0/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:246
(inlined by) nimble_port_stop at C:/Espressif/frameworks/esp-idf-v5.0/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:214
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00000000 A5 : 0x4200b254
0x4200b254: write_cb at F:/GitHub/esp-rainmaker/examples/switch/main/app_main.c:177
A6 : 0x42008204 A7 : 0x0000cdcd A8 : 0x80384903 A9 : 0x3fcab440
0x42008204: timer_task at C:/Espressif/frameworks/esp-idf-v5.0/components/esp_timer/src/esp_timer.c:470
A10 : 0x00000000 A11 : 0x0000056f A12 : 0x3fca1178 A13 : 0x00060623
A14 : 0xffffffff A15 : 0x0000cdcd SAR : 0x0000001a EXCCAUSE: 0x0000001c
EXCVADDR: 0x0000004c LBEG : 0x40056f5c LEND : 0x40056f72 LCOUNT : 0xffffffff
Backtrace: 0x4202dcd9:0x3fcab460 0x4200b4a3:0x3fcab480 0x420ed2f3:0x3fcab4b0 0x40385886:0x3fcab4e0
0x4202dcd9: ble_npl_sem_init at C:/Espressif/frameworks/esp-idf-v5.0/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:246
(inlined by) nimble_port_stop at C:/Espressif/frameworks/esp-idf-v5.0/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:214
0x4200b4a3: app_main at F:/GitHub/esp-rainmaker/examples/switch/main/app_main.c:389
0x420ed2f3: main_task at C:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/portable/port_common.c:131 (discriminator 2)
0x40385886: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:154
Hi @jacek12345,
Yes if the device is already provisioned, BLE stack won't initialize. The current application is suited for most common rainmaker use case. However, you can refer to existing nimble sample applications to how to re - init BT (stack and controller ).
You can use wifi_prov_mgr_is_provisioned API to check if it's already provisioned and then take appropriate steps for initialize or not initialize BT.
This is the documentation . The current use supported is to use BLE stack for provisioning and then turn off stack and release memory . Therefore , memory too is released . But when memory is released, it cannot be reversed.
The use case being suggested here involves rebooting the device. If you enable the flag, and keep running the code, it should work as configured.
jacek12345
commented
1 year ago Thank You for response. Please check if this flow will be correct:
But if i understood, now, when device is already provisioned it should work with my own BT initilaisation regardless of WIFI_PROV_KEEP_BLE_ON_AFTER_PROV, but it crasches. Why?
From the nimble/blecent example:
app_main(void)
{
int rc;
/* Initialize NVS — it is used to store PHY calibration data */
esp_err_t ret = nvs_flash_init();
if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) {
ESP_ERROR_CHECK(nvs_flash_erase());
ret = nvs_flash_init();
}
ESP_ERROR_CHECK(ret);
ret = nimble_port_init();
if (ret != ESP_OK) {
ESP_LOGE(tag, "Failed to init nimble %d ", ret);
return;
}
/* Configure the host. */
ble_hs_cfg.reset_cb = blecent_on_reset;
ble_hs_cfg.sync_cb = blecent_on_sync;
ble_hs_cfg.store_status_cb = ble_store_util_status_rr;
/* Initialize data structures to track connected peers. */
rc = peer_init(MYNEWT_VAL(BLE_MAX_CONNECTIONS), 64, 64, 64);
assert(rc == 0);
/* Set the default device name. */
rc = ble_svc_gap_device_name_set("nimble-blecent");
assert(rc == 0);
/* XXX Need to have template for store */
ble_store_config_init();
nimble_port_freertos_init(blecent_host_task);
#if CONFIG_EXAMPLE_INIT_DEINIT_LOOP
stack_init_deinit();
#endif
}In my case, it crashes on ret = nimble_port_init();
Device is already provisioned.
WIFI_PROV_KEEP_BLE_ON_AFTER_PROV doesn't matter in this case but it is set.
So I suppose that there is also other issue with it. Is it possible that i don't have some submodules installed or wrong version ?
IshaESP
commented
1 year ago Hi @jacek12345 , So you don't have to explicitly set provisioned flag. The API sets the flag if the device is already provisioned.
Here are the 2 cases that need to be addressed:
Device is not provisioned:
Device is provisioned:
jacek12345
commented
1 year ago I have error: corrupt patch at line 20
jacek12345
commented
1 year ago Finally, it looks like the problem was missing: $ENV{IDF_PATH}/examples/bluetooth/nimble/common/nimble_central_utils in CMakeLists.txt. Now it does not crash, only put nimble initialisation error if provisioning was made in this boot (ble is already initialised).
But there is strange issue with WIFI_PROV_KEEP_BLE_ON_AFTER_PROV. If disabled, it crashes on ble initialisation even if there was not provisioning in this boot (ble was not already initialised). If enabled, initialisation take place correctly. This is strange, because it shouldn't be used when there was not provisioning in this boot.
IshaESP
commented
1 year ago Hi Regarding $ENV{IDF_PATH}/examples/bluetooth/nimble/common/nimble_central_utils, if this was the issue the code wouldn't have compiled earlier. Are there any stale files present?
So if provisioning is already done, you need to enable WIFI_PROV_KEEP_BLE_ON_AFTER_PROV for using BLE. During init process, if the flag is disabled, it releases all the memory related to ble thus causing a crash (irrespective of provisioning).
Attaching a log when WIFI_PROV_KEEP_BLE_ON_AFTER_PROV is enabled and provisioning is already done. github_10817_2.txt
rahult-github
commented
1 year ago Hi @jacek12345 , any further updates regarding WIFI_PROV_KEEP_BLE_ON_AFTER_PROV macro usage ?
PhLuReh
commented
1 year ago I ran into the same issue working on an esp-matter based project, which is running on tag v5.1.1. It occurs while booting a commissioned device (this should be the normal state). And let me tell it is very urgent.
I looked around in the files and was thinking about why there is no sanity-check if the element in the linked list actually has a next element. The next element will just be used... I really don't know if there are some specialties on this linked list (like being a closed loop), but anyhow, it is just a guess... Even if it should not appear in reality, there should be a check for NULL.
Here is my stack trace:
E (6086) chip[DL]: Long dispatch time: 1433 ms, for event type 2
I (6086) chip[DL]: WIFI_EVENT_STA_START
I (5686) wifi:state: auth -> assoc (0)
I (6096) chip[DL]: Done driving station state, nothing else to do...
I (6096) wifi:Association refused temporarily, comeback time 1000 (TUs)
I (6106) chip[DL]: CHIPoBLE advertising stopped
Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC : 0x40095ac3 PS : 0x00060933 A0 : 0x800941a9 A1 : 0x3fff33d0
0x40095ac3: uxListRemove at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:197
A2 : 0x00000006 A3 : 0x00060920 A4 : 0x00000000 A5 : 0x00060923
A6 : 0xb33fffff A7 : 0xb33fffff A8 : 0x80095140 A9 : 0x3fff33a0
A10 : 0x00000001 A11 : 0x00000000 A12 : 0x00000000 A13 : 0x00000000
A14 : 0x00000000 A15 : 0x00000000 SAR : 0x0000000a EXCCAUSE: 0x0000001c
EXCVADDR: 0x0000000a LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM
Backtrace: 0x40095ac0:0x3fff33d0 0x400941a6:0x3fff33f0 0x401516cd:0x3fff3410 0x401516e7:0x3fff3430 0x4013ab95:0x3fff3450 0x40094ff6:0x3fff3470
0x40095ac0: uxListRemove at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:192
0x400941a6: vTaskDelete at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:1434 (discriminator 4)
0x401516cd: esp_nimble_disable at /opt/espressif/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:55
0x401516e7: nimble_port_freertos_deinit at /opt/espressif/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:80
0x4013ab95: chip::DeviceLayer::Internal::BLEManagerImpl::bleprph_host_task(void*) at /home/smart/projects/smp_matter/build/esp-idf/chip/../../../../../../../opt/espressif/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:864
0x40094ff6: vPortTaskWrapper at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162EDIT: I guess I guessed wrong, but still, the error is there... so is it some memory corruption?
jacek12345
commented
1 year ago Hi @jacek12345 , any further updates regarding WIFI_PROV_KEEP_BLE_ON_AFTER_PROV macro usage ?
Thank You, I have this enabled and everything works. You can close.
PhLuReh
commented
1 year ago I would say, the flag may ease the symptom by the root is somewhere else. As I wrote, the Matter implementation from Espressif also uses the Nimble-Stack, at completely controls it. So no interaction by my application code. And it still appears.
Should I guide someone from the esp-matter repo here?
rahult-github
commented
1 year ago Hi @PhLuReh , i believe the issue you have raised and the one being discussed on this ticket are not same.
I suggest to please open a fresh ticket on esp-matter repo. Also request you :
I will be closing the current issue.
PhLuReh
commented
1 year ago @rahult-github I will do so. Just to conclude from my side. I added the following line to the list.c code and the abort get's executed:
if (pxItemToRemove < (ListItem_t* const)0xff) abort();
So I would assume, pxItemToRemove get's corrupted, is not NULL but according to the BT pxItemToRemove was 0x0000000a. Did not get any clue how up to now.
Answers checklist.
IDF version.
esp-idf-v5.0.1
Operating System used.
Windows
How did you build your project?
Command line with idf.py
If you are using Windows, please specify command line type.
CMD
Development Kit.
ESP32-S3-DevKitM-1
Power Supply used.
USB
What is the expected behavior?
Nimble initialisation
What is the actual behavior?
Crash
Steps to reproduce.
Used with RainMaker based project.
Nimble_init();it crashes.Debug Logs.
More Information.
It seems that BT controller version is the problem?
When crashing (ESP-IDFv.5.0.1): I (34710) BT_INIT: BT controller compile version [80abacd]
When works (ESP-IDFv.5.0): I (25431) BT_INIT: BT controller compile version [76c24c9]