Crash after Nimble initialisation on ESP-IDFv.5.0.1, works on v.5.0 (IDFGH-9450)

[jacek12345]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

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.

1. after start, when Nimble_init(); it crashes.

void Nimble_init(void)
{
    if(!FL_OTA_ONTHEFLY)
    {
         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);
    }
}

Debug Logs.

I (19450) app_main: MQTT Published. Msg id: 49289.
I (19450) app_main: MQTT Published. Msg id: 27609.
I (22300) esp_rmaker_ota_using_topics: Fetching OTA details, if any.
I (22520) app_main: MQTT Published. Msg id: 2855.
I (34250) esp_rmaker_time: SNTP Synchronised.
I (34250) esp_rmaker_time: The current time is: Wed Feb 22 07:12:01 2023 +0100[CET], DST: No.
btdm: bss start 0x3fcef180, len 36
btdm: data start 0x3fcef174, data start rom 0x40057350, len 12
MAGIC fadebead VERSION 00010006
I (34710) BT_INIT: BT controller compile version [80abacd]
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4038525f  PS      : 0x00060833  A0      : 0x80383f53  A1      : 0x3fcf3840
0x4038525f: uxListRemove at F:/GitHub/esp-idf-v5.0.1/components/freertos/FreeRTOS-Kernel/list.c:197

A2      : 0x0000858c  A3      : 0x3fca0688  A4      : 0x00060820  A5      : 0x00060823
A6      : 0x00000001  A7      : 0x0000cdcd  A8      : 0x8038543c  A9      : 0x3fcf3810
A10     : 0x00000001  A11     : 0x00000000  A12     : 0x00000000  A13     : 0x01260267
A14     : 0x00000200  A15     : 0x00260000  SAR     : 0x0000001c  EXCCAUSE: 0x0000001c
EXCVADDR: 0x0000859c  LBEG    : 0x4037ed44  LEND    : 0x4037ed50  LCOUNT  : 0x00000000
0x4037ed44: ram_wifi_tx_dig_gain at ??:?

0x4037ed50: ram_wifi_tx_dig_gain at ??:?



Backtrace: 0x4038525c:0x3fcf3840 0x40383f50:0x3fcf3860 0x4202df39:0x3fcf3880 0x4203de0e:0x3fcf38a0 0x4203edf9:0x3fcf38c0 0x4202e633:0x3fcf3910 0x420374a2:0x3fcf3950 0x4200e438:0x3fcf39b0 0x4200ef14:0x3fcf39d0 0x420efe97:0x3fcf3b20 0x403852b6:0x3fcf3b50
0x4038525c: uxListRemove at F:/GitHub/esp-idf-v5.0.1/components/freertos/FreeRTOS-Kernel/list.c:194

0x40383f50: vTaskDelete at F:/GitHub/esp-idf-v5.0.1/components/freertos/FreeRTOS-Kernel/tasks.c:1348 (discriminator 4)

0x4202df39: task_delete_wrapper at F:/GitHub/esp-idf-v5.0.1/components/bt/controller/esp32s3/bt.c:646

0x4203de0e: ble_sm_alg_gen_key_pair at ??:?

0x4203edf9: btdm_controller_init at ??:?

0x4202e633: esp_bt_controller_init at F:/GitHub/esp-idf-v5.0.1/components/bt/controller/esp32s3/bt.c:1312

0x420374a2: nimble_port_init at F:/GitHub/esp-idf-v5.0.1/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:145

0x4200e438: Nimble_init at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:3179

0x4200ef14: app_main at F:/GitHub/esp-rainmaker/examples/j_switch/main/app_main.c:2010

0x420efe97: main_task at F:/GitHub/esp-idf-v5.0.1/components/freertos/FreeRTOS-Kernel/portable/port_common.c:131 (discriminator 2)

0x403852b6: vPortTaskWrapper at F:/GitHub/esp-idf-v5.0.1/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:154

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]

[IshaESP]

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]

Hi @jacek12345 , any updates ?

[jacek12345]

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]

Hi @jacek12345 ,
Can you please send us the debug logs and sdkconfig for us to debug it properly.

To enable debug logs:

1. idf.py menuconfig
2. Component config → Bluetooth → NimBLE Options → NimBLE Host log verbosity → Debug logs
3. Component config → Log output → Default log verbosity → Debug

[jacek12345]

I'm trying to run with enabled debug logs but have:
ERROR A stack overflow in task sys_evt has been detected.

[IshaESP]

Hey,
Try increasing stack size by this:
Component config -> ESP System Settings->ESP_SYSTEM_EVENT_TASK_STACK_SIZE to 4000 for testing purposes

[jacek12345]

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:162

Is it enough or You meed whole log? I'm aware that there can be some secret information. Eventually can send priv?

[jacek12345]

@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);

[jacek12345]

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:162

Attached also sdkconfig
sdkconfig.zip

[jacek12345]

Do You have any idea? Or any example with reusing NimBle after provisioning?

[IshaESP]

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]

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:

1. Added 'bleprph.h' to main folder in 'switch' example
2. Added two blocks of code in app_main.c file:

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