Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
3 tasks done
jacek12345 opened this issue Feb 22, 2023 · 26 comments
Closed
3 tasks done
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally Type: Bug bugs in IDF

Comments

@jacek12345
Copy link

jacek12345 commented Feb 22, 2023

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]

@jacek12345 jacek12345 added the Type: Bug bugs in IDF label Feb 22, 2023
@github-actions github-actions bot changed the title Crash after Nimble initialisation on ESP-IDFv.5.0.1, works on v.5.0 Crash after Nimble initialisation on ESP-IDFv.5.0.1, works on v.5.0 (IDFGH-9450) Feb 22, 2023
@espressif-bot espressif-bot added the Status: Opened Issue is new label Feb 22, 2023
@IshaESP
Copy link
Contributor

IshaESP commented Feb 28, 2023

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
Copy link
Collaborator

Hi @jacek12345 , any updates ?

@jacek12345
Copy link
Author

jacek12345 commented Jun 14, 2023

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
Copy link
Contributor

IshaESP commented Jun 15, 2023

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
Copy link
Author

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

@IshaESP
Copy link
Contributor

IshaESP commented Jun 15, 2023

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

@jacek12345
Copy link
Author

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
Copy link
Author

@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
Copy link
Author

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
Copy link
Author

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

@IshaESP
Copy link
Contributor

IshaESP commented Jun 22, 2023

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
Copy link
Author

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

@IshaESP
Copy link
Contributor

IshaESP commented Jul 4, 2023

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:

  1. idf.py menuconfig
  2. Enable WIFI_PROV_KEEP_BLE_ON_AFTER_PROV from Component config -> Wi-Fi Provisioning Manager -> WIFI_PROV_KEEP_BLE_ON_AFTER_PROV
  3. Replace the BT initialing code with just blecent_scan(), like below:
     /* 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();
 }

@jacek12345
Copy link
Author

jacek12345 commented Jul 5, 2023

@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


@IshaESP
Copy link
Contributor

IshaESP commented Jul 5, 2023

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.

https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/bluetooth/controller_vhci.html#_CPPv418esp_bt_mem_release13esp_bt_mode_t

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
Copy link
Author

jacek12345 commented Jul 5, 2023

Thank You for response.
Please check if this flow will be correct:

  1. Using wifi_prov_mgr_is_provisioned after NVS initialisation and set flag if it is provisioned (FLAG_PROVISIONED=true)
  2. After app_wifi_start(), check FLAG_PROVISIONED. If set (device was already provisioned so BT was not initialised), initialise nimble. If cleared (device was unprovisioned so provisioning was started and BT was initialised and remains initilaised), ommit BT initialisation.

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
Copy link
Contributor

IshaESP commented Jul 5, 2023

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:

  1. Device is not provisioned:
  • Keep the WIFI_PROV_KEEP_BLE_ON_AFTER_PROV flag enabled. After provisioning no need of doing anything extra, just start scan/adv according to the use case.
  1. Device is provisioned:
  • Across reboots, this flag WIFI_PROV_KEEP_BLE_ON_AFTER_PROV will be of no use. So if device is already provisioned , you need to initialize BLE explicitly as reboot will start a clean slate. I have attached a patch which is working for me. Try it once.
    crash_rainmaker.zip

@jacek12345
Copy link
Author

I have error: corrupt patch at line 20

@jacek12345
Copy link
Author

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
Copy link
Contributor

IshaESP commented Jul 12, 2023

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
Copy link
Collaborator

Hi @jacek12345 , any further updates regarding WIFI_PROV_KEEP_BLE_ON_AFTER_PROV macro usage ?

@PhLuReh
Copy link

PhLuReh commented Nov 9, 2023

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

EDIT: I guess I guessed wrong, but still, the error is there... so is it some memory corruption?

@jacek12345
Copy link
Author

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
Copy link

PhLuReh commented Nov 9, 2023

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
Copy link
Collaborator

rahult-github commented Nov 10, 2023

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 :

  1. Mention commit id being used ( Please sync to latest sources to confirm if issue is observed)
  2. Provide complete console log
  3. Mention steps done / chip used in the description to assist looking at at the issue.

I will be closing the current issue.

@espressif-bot espressif-bot added the Status: Done Issue is done internally label Nov 10, 2023
@espressif-bot espressif-bot added Resolution: Done Issue is done internally and removed Status: Opened Issue is new labels Nov 10, 2023
@PhLuReh
Copy link

PhLuReh commented Nov 10, 2023

@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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally Type: Bug bugs in IDF
Projects
None yet
Development

No branches or pull requests

5 participants