Provisioning for base example not working

[maldus]

Hello everyone,
I was trying to test Rainmaker with a couple of ESP32 devices, but unfortunately I can't seem to get past the provisioning part.
I am flashing the switch example using the 4.0 branch of ESP-IDF on a ESP32-WROVER-B development board.
Once the QR code is printed on the terminal I read it through the rainmaker application (Android) with my bluetooth on; I can see a new device called PROV_<random string> in the Bluetooth pairing list, but after a while the Rainmaker app fails with the message "PROV_3a770a device not found".
Changing the transport method to SoftAP in the config yields the same result, and so does switching to the master branch for ESP-IDF.

Am I missing something here? The getting started section is very simple, I don't think I've missed any steps. Is an esp32-s2 saola devboard necessary to use Rainmaker?

[ESP_Piyush]

Hello,

ESP RainMaker examples are indeed supposed to work with the ESP IDF version and the ESP32 module you mentioned. While using BLE provisioning, had you already connected to the board from the Bluetooth Settings? If yes, that could be a reason why the RainMaker app could not find it.However, since you also see the issue with SoftAP, the reason could be different. For SoftAP, did you try manually connecting to the AP, instead of the QR code? Can you share the device side serial terminal logs for the SotfAP use case?

Regards,
Piyush

[maldus]

Thank you for your assistance.

While using BLE provisioning, had you already connected to the board from the Bluetooth Settings? If yes, that could be a reason why the RainMaker app could not find it.

Not really. I made a separate attempt to pair the device beforehand, but other than that I always erased the flash and forgot the device on the phone to prevent any lingering connection.

For SoftAP, did you try manually connecting to the AP, instead of the QR code?

What do you mean? I've tried connecting to the AP and then using the QR code.

Can you share the device side serial terminal logs for the SotfAP use case?

Here I tried to provision the device with the application (first while connected to a separate WiFi, then to the softAP).

Code: Select all

Python requirements from /home/maldus/Source/esp-idf-v4.0/requirements.txt are satisfied.
[1/4] cd /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build/esp-idf/partition_table && /usr/bin/cmake -E echo "Partition table binary generated. Contents:" && /usr/bin/cmake -E echo "*******************************************************************************" && /home/maldus/.espressif/python_env/idf4.0_py3.8_env/bin/python /home/maldus/Source/esp-idf-v4.0/components/partition_table/gen_esp32part.py -q --offset 0x8000 --flash-size 4MB /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build/partition_table/partition-table.bin && /usr/bin/cmake -E echo "*******************************************************************************"
Partition table binary generated. Contents:
*******************************************************************************
# Espressif ESP32 Partition Table
# Name, Type, SubType, Offset, Size, Flags
sec_cert,63,0,0xd000,12K,
nvs,data,nvs,0x10000,24K,
otadata,data,ota,0x16000,8K,
phy_init,data,phy,0x18000,4K,
ota_0,app,ota_0,0x20000,1600K,
ota_1,app,ota_1,0x1b0000,1600K,
fctry,data,nvs,0x340000,24K,
*******************************************************************************
[2/4] Performing build step for 'bootloader'
ninja: no work to do.
esptool.py -p /dev/ttyUSB0 -b 460800 --before default_reset --after hard_reset write_flash --flash_mode dio --flash_freq 40m --flash_size 4MB 0x8000 partition_table/partition-table.bin 0x16000 ota_data_initial.bin 0x1000 bootloader/bootloader.bin 0x20000 switch.bin
esptool.py v2.8
Serial port /dev/ttyUSB0
Connecting....
Detecting chip type... ESP32
Chip is ESP32D0WDQ5 (revision 1)
Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None
Crystal is 40MHz
MAC: 84:0d:8e:e6:ac:14
Uploading stub...
Running stub...
Stub running...
Changing baud rate to 460800
Changed.
Configuring flash size...
Compressed 3072 bytes to 159...

Writing at 0x00008000... (100 %)
Wrote 3072 bytes (159 compressed) at 0x00008000 in 0.0 seconds (effective 4585.4 kbit/s)...
Hash of data verified.
Compressed 8192 bytes to 31...

Writing at 0x00016000... (100 %)
Wrote 8192 bytes (31 compressed) at 0x00016000 in 0.0 seconds (effective 25475.2 kbit/s)...
Hash of data verified.
Compressed 25392 bytes to 14980...

Writing at 0x00001000... (100 %)
Wrote 25392 bytes (14980 compressed) at 0x00001000 in 0.4 seconds (effective 574.9 kbit/s)...
Hash of data verified.
Compressed 1061728 bytes to 650236...

Writing at 0x00020000... (2 %)
Writing at 0x00024000... (5 %)
Writing at 0x00028000... (7 %)
Writing at 0x0002c000... (10 %)
Writing at 0x00030000... (12 %)
Writing at 0x00034000... (15 %)
Writing at 0x00038000... (17 %)
Writing at 0x0003c000... (20 %)
Writing at 0x00040000... (22 %)
Writing at 0x00044000... (25 %)
Writing at 0x00048000... (27 %)
Writing at 0x0004c000... (30 %)
Writing at 0x00050000... (32 %)
Writing at 0x00054000... (35 %)
Writing at 0x00058000... (37 %)
Writing at 0x0005c000... (40 %)
Writing at 0x00060000... (42 %)
Writing at 0x00064000... (45 %)
Writing at 0x00068000... (47 %)
Writing at 0x0006c000... (50 %)
Writing at 0x00070000... (52 %)
Writing at 0x00074000... (55 %)
Writing at 0x00078000... (57 %)
Writing at 0x0007c000... (60 %)
Writing at 0x00080000... (62 %)
Writing at 0x00084000... (65 %)
Writing at 0x00088000... (67 %)
Writing at 0x0008c000... (70 %)
Writing at 0x00090000... (72 %)
Writing at 0x00094000... (75 %)
Writing at 0x00098000... (77 %)
Writing at 0x0009c000... (80 %)
Writing at 0x000a0000... (82 %)
Writing at 0x000a4000... (85 %)
Writing at 0x000a8000... (87 %)
Writing at 0x000ac000... (90 %)
Writing at 0x000b0000... (92 %)
Writing at 0x000b4000... (95 %)
Writing at 0x000b8000... (97 %)
Writing at 0x000bc000... (100 %)
Wrote 1061728 bytes (650236 compressed) at 0x00020000 in 15.4 seconds (effective 550.2 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
+‰±¥¹ÿets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6940
load:0x40078000,len:14052
load:0x40080400,len:4304
entry 0x400806e8
[0;32mI (71) boot: Chip Revision: 1[0m
[0;32mI (71) boot_comm: chip revision: 1, min. bootloader chip revision: 0[0m
[0;32mI (39) boot: ESP-IDF v4.0-beta2-1218-g6093407d7-dirt 2nd stage bootloader[0m
[0;32mI (40) boot: compile time 11:10:46[0m
[0;32mI (41) boot: Enabling RNG early entropy source...[0m
[0;32mI (46) boot: SPI Speed      : 40MHz[0m
[0;32mI (50) boot: SPI Mode       : DIO[0m
[0;32mI (54) boot: SPI Flash Size : 4MB[0m
[0;32mI (58) boot: Partition Table:[0m
[0;32mI (62) boot: ## Label            Usage          Type ST Offset   Length[0m
[0;32mI (69) boot:  0 sec_cert         unknown          3f 00 0000d000 00003000[0m
[0;32mI (77) boot:  1 nvs              WiFi data        01 02 00010000 00006000[0m
[0;32mI (84) boot:  2 otadata          OTA data         01 00 00016000 00002000[0m
[0;32mI (92) boot:  3 phy_init         RF data          01 01 00018000 00001000[0m
[0;32mI (99) boot:  4 ota_0            OTA app          00 10 00020000 00190000[0m
[0;32mI (107) boot:  5 ota_1            OTA app          00 11 001b0000 00190000[0m
[0;32mI (114) boot:  6 fctry            WiFi data        01 02 00340000 00006000[0m
[0;32mI (122) boot: End of partition table[0m
[0;32mI (126) boot: No factory image, trying OTA 0[0m
[0;32mI (131) boot_comm: chip revision: 1, min. application chip revision: 0[0m
[0;32mI (138) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x337ac (210860) map[0m
[0;32mI (223) esp_image: segment 1: paddr=0x000537d4 vaddr=0x3ffbdb60 size=0x03ae8 ( 15080) load[0m
[0;32mI (229) esp_image: segment 2: paddr=0x000572c4 vaddr=0x40080000 size=0x00400 (  1024) load[0m
[0;32mI (230) esp_image: segment 3: paddr=0x000576cc vaddr=0x40080400 size=0x08944 ( 35140) load[0m
[0;32mI (253) esp_image: segment 4: paddr=0x00060018 vaddr=0x400d0018 size=0xb4448 (738376) map[0m
[0;32mI (517) esp_image: segment 5: paddr=0x00114468 vaddr=0x40088d44 size=0x0eec8 ( 61128) load[0m
[0;32mI (558) boot: Loaded app from partition at offset 0x20000[0m
[0;32mI (588) boot: Set actual ota_seq=1 in otadata[0][0m
[0;32mI (588) boot: Disabling RNG early entropy source...[0m
[0;32mI (589) cpu_start: Pro cpu up.[0m
[0;32mI (591) cpu_start: Application information:[0m
[0;32mI (596) cpu_start: Project name:     switch[0m
[0;32mI (601) cpu_start: App version:      1.0[0m
[0;32mI (606) cpu_start: Compile time:     Nov  3 2020 11:10:44[0m
[0;32mI (612) cpu_start: ELF file SHA256:  2de6cec47adc7862...[0m
[0;32mI (618) cpu_start: ESP-IDF:          v4.0-beta2-1218-g6093407d7-dirt[0m
[0;32mI (625) cpu_start: Starting app cpu, entry point is 0x40081374[0m
[0;32mI (0) cpu_start: App cpu up.[0m
[0;32mI (635) heap_init: Initializing. RAM available for dynamic allocation:[0m
[0;32mI (642) heap_init: At 3FFAE6E0 len 0000F480 (61 KiB): DRAM[0m
[0;32mI (648) heap_init: At 3FFC7D20 len 000182E0 (96 KiB): DRAM[0m
[0;32mI (654) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM[0m
[0;32mI (661) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
[0;32mI (667) heap_init: At 40097C0C len 000083F4 (32 KiB): IRAM[0m
[0;32mI (673) cpu_start: Pro cpu start user code[0m
[0;32mI (692) spi_flash: detected chip: generic[0m
[0;32mI (692) spi_flash: flash io: dio[0m
[0;32mI (693) cpu_start: Starting scheduler on PRO CPU.[0m
[0;32mI (0) cpu_start: Starting scheduler on APP CPU.[0m
[0;32mI (701) esp_rmaker_commands: Registering command: up-time[0m
[0;32mI (0) esp_rmaker_console: Initialising UART on port 0[0m
[0;32mI (711) uart: queue free spaces: 8[0m
[0;32mI (721) esp_rmaker_commands: Registering command: mem-dump[0m
[0;32mI (721) esp_rmaker_commands: Registering command: task-dump[0m
[0;32mI (731) esp_rmaker_commands: Registering command: cpu-dump[0m
[0;32mI (731) esp_rmaker_commands: Registering command: sock-dump[0m
[0;32mI (741) esp_rmaker_commands: Registering command: heap-trace[0m
[0;32mI (751) esp_rmaker_commands: Registering command: reset-to-factory[0m
[0;32mI (751) esp_rmaker_commands: Registering command: add-user[0m
[0;32mI (761) esp_rmaker_commands: Registering command: get-node-id[0m
[0;32mI (771) esp_rmaker_commands: Registering command: wifi-prov[0m
[0;32mI (771) esp_rmaker_commands: Registering command: local-time[0m
[0;32mI (781) esp_rmaker_commands: Registering command: tz-set[0m
[0;32mI (791) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 [0m
[0;32mI (791) gpio: GPIO[19]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 [0m
[0;33mW (801) ws2812_led: WS2812 LED is disabled[0m
I (831) wifi:wifi driver task: 3ffba340, prio:23, stack:6656, core=0
[0;32mI (831) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE[0m
[0;32mI (831) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE[0m
I (881) wifi:wifi firmware version: 19abcd9
I (881) wifi:config NVS flash: enabled
I (881) wifi:config nano formating: disabled
I (881) wifi:Init data frame dynamic rx buffer num: 32
I (891) wifi:Init management frame dynamic rx buffer num: 32
I (891) wifi:Init management short buffer num: 32
I (901) wifi:Init dynamic tx buffer num: 32
I (901) wifi:Init static rx buffer size: 1600
I (911) wifi:Init static rx buffer num: 10
I (911) wifi:Init dynamic rx buffer num: 32
[0;32mI (931) esp_claim: Initialising Assisted Claiming. This may take time.[0m
[0;33mW (931) esp_claim: Generating the private key. This may take time.[0m
[0;32mI (12541) app_main: RainMaker Initialised.[0m
[0;32mI (12541) esp_rmaker_node: Node ID ----- 840D8EE6AC14[0m
[0;32mI (12541) esp_rmaker_ota: OTA state = 2[0m
[0;32mI (12541) esp_rmaker_ota_using_params: OTA enabled with Params[0m
[0;32mI (12551) esp_rmaker_time_sync: Initializing SNTP. Using the SNTP server: pool.ntp.org[0m
[0;32mI (12561) esp_rmaker_core: Starting RainMaker Core Task[0m
[0;32mI (12561) app_main: RainMaker Claim Started.[0m
[0;32mI (12561) esp_claim: Waiting for assisted claim to finish.[0m
[0;32mI (12571) app_wifi: Starting provisioning[0m
[0;33mW (12581) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration[0m
[0;32mI (12721) phy: phy_version: 4370, 4e803b3, Aug 11 2020, 14:18:07, 0, 2[0m
I (12731) wifi:mode : sta (84:0d:8e:e6:ac:14)
I (12741) wifi:mode : sta (84:0d:8e:e6:ac:14) + softAP (84:0d:8e:e6:ac:15)
I (12741) wifi:Total power save buffer number: 16
I (12741) wifi:Init max length of beacon: 752/752
I (12741) wifi:Init max length of beacon: 752/752
I (12751) wifi:Total power save buffer number: 16
[0;33mW (12751) wifi_prov_scheme_softap: Error adding mDNS service! Check if mDNS is running[0m
[0;32mI (12761) wifi_prov_mgr: Provisioning started with service name : PROV_f369c6 [0m
[0;32mI (12771) app_wifi: Provisioning started[0m
[0;32mI (12771) app_wifi: Scan this QR code from the phone app for Provisioning.[0m
                                      
  █▀▀▀▀▀█ ▄▀ ▄█ ▄█▄▄▀▀   ██ █▀▀▀▀▀█   
  █ ███ █ ▀███▀  ██▀  ▄ ▀▄█ █ ███ █   
  █ ▀▀▀ █ █▄ ▄ ▀███▀ ▄██▀▀▀ █ ▀▀▀ █   
  ▀▀▀▀▀▀▀ █▄▀ █ ▀ ▀▄▀▄▀▄▀ █ ▀▀▀▀▀▀▀   
  ██▄█  ▀▀▄ █▄ ▀▄▀█ █ ▄█ ▀█▄█▀▀▄▀▀▄   
  ▄▀▄▀ █▀ █▀▀  ▄█▄  ▀█▀█▄▄▄ ▄█    █   
  ▀ ██ ▀▀▄ ▄▄▄█▀▀  ██▄██▀█▄▀█ ▄▄ ▀█   
   ▀ ▀ █▀▀█ ▀ ██   ▄   █ ▀█▀  ▄█ █▄   
  ▄▀ ██ ▀ ▀▀ ▀▀▄  ███▀██  ▄█▀ ▀▀▄ ▀   
  ▄▄██  ▀█ ▄▄▄▄▀█ ▀▄█▄▀██ ▄ █▄▄▄ ▀█   
   ▄▄▀██▀ ▄█  ▄▀▀▀█▄▀▀▀▀▀▄█ ▄▄ █ ▄▄   
  ▀█▄ ██▀▀▀▄▀▄▀▄ ▄▀▀▀▀█▄▀▄▀█  ▄▄ ▀▀   
  ▀ ▀▀▀ ▀▀███ ▀▀  ▀▀▀▄▀██ █▀▀▀█▀ ▄▄   
  █▀▀▀▀▀█ ▀▄▄█▀█▀ ▀█ ▄ █▀▀█ ▀ ██ ▀▄   
  █ ███ █ ▄▀▄▄▄▄  █▀▀▀ ██ ▀████▀ ▄█   
  █ ▀▀▀ █ ▄█ ▄   ▄▀█▀▄▄▄█ ▀  ▄▀█▀▀▀   
  ▀▀▀▀▀▀▀ ▀  ▀▀▀▀    ▀ ▀  ▀ ▀ ▀▀ ▀    
                                      

[0;32mI (12981) app_wifi: If QR code is not visible, copy paste the below URL in a browser.
https://rainmaker.espressif.com/qrcode.html?data={"ver":"v1","name":"PROV_f369c6","pop":"db8a8869","transport":"softap"}[0m
[0;32mI (13001) app_wifi: Provisioning Started. Name : PROV_f369c6, POP : db8a8869[0m
I (76841) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
I (76841) wifi:station: d0:13:fd:26:6b:31 join, AID=1, bgn, 20
[0;32mI (77151) tcpip_adapter: softAP assign IP to station,IP is: 192.168.4.2[0m
[0;33mW (100631) httpd_uri: httpd_uri: URI '/' not found[0m
[0;33mW (100631) httpd_txrx: httpd_resp_send_err: 404 Not Found - This URI does not exist[0m
[0;33m--- idf_monitor on /dev/ttyUSB0 115200 ---[0m
[0;33m--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---[0m
[0;33m0x40080000: _WindowOverflow4 at /home/maldus/Source/esp-idf-v4.0/components/freertos/xtensa_vectors.S:1778
[0m
[0;33m0x400d0018: _stext at ??:?
[0m
[0;33m0x40088d44: prvAcquireItemNoSplit at /home/maldus/Source/esp-idf-v4.0/components/esp_ringbuf/ringbuf.c:324 (discriminator 3)
[0m
[0;33m0x40081374: call_start_cpu1 at /home/maldus/Source/esp-idf-v4.0/components/esp32/cpu_start.c:267
[0m
[0m
Checking Python dependencies...
Adding flash's dependency "all" to list of actions
Executing action: all (aliases: build)
Running ninja in directory /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build
Executing "ninja all"...
Executing action: flash
Choosing default port b'/dev/ttyUSB0' (use '-p PORT' option to set a specific serial port)
Running esptool.py in directory /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build
Executing "/home/maldus/.espressif/python_env/idf4.0_py3.8_env/bin/python /home/maldus/Source/esp-idf-v4.0/components/esptool_py/esptool/esptool.py -p /dev/ttyUSB0 -b 460800 --before default_reset --after hard_reset write_flash @flash_project_args"...
Executing action: monitor
Running idf_monitor in directory /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch
Executing "/home/maldus/.espressif/python_env/idf4.0_py3.8_env/bin/python /home/maldus/Source/esp-idf-v4.0/tools/idf_monitor.py -p /dev/ttyUSB0 -b 115200 /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build/switch.elf -m '/home/maldus/.espressif/python_env/idf4.0_py3.8_env/bin/python' '/home/maldus/Source/esp-idf-v4.0/tools/idf.py'"...
Done

[ESP_Piyush]

What do you mean? I've tried connecting to the AP and then using the QR code.

I meant, choosing the "I don't have a QR code" option then using the "Connect" button to go to settings, connecting to the network with name PROV_xxxxxx and coming back to the app.

From your logs, I can see that the phone has connected to the device, and not disconnected thereafter. However, as you say, the provisioning did not proceed. To get some more information, can you enable the debug logs (idf.py menuconfig -> Component config -> Log output -> Default log verbosity -> Debug) and share them?

Meanwhile, what is your Android version and handset model?

Regards,
Piyush.

[maldus]

Debug level enabled, I've tried first following the normal provisioning route and there was absolutely no log during that time (it failed like all previous attempts). Then I've tried the "I don't have a QR code option" and there was some output on the terminal, but that procedure failed too (see screenshot attached).

Code: Select all

Python requirements from /home/maldus/Source/esp-idf-v4.0/requirements.txt are satisfied.
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6940
load:0x40078000,len:14052
load:0x40080400,len:4304
entry 0x400806e8
[0;32mI (71) boot: Chip Revision: 1[0m
[0;32mI (71) boot_comm: chip revision: 1, min. bootloader chip revision: 0[0m
[0;32mI (39) boot: ESP-IDF v4.0-beta2-1218-g6093407d7-dirt 2nd stage bootloader[0m
[0;32mI (39) boot: compile time 21:37:11[0m
[0;32mI (41) boot: Enabling RNG early entropy source...[0m
[0;32mI (46) boot: SPI Speed      : 40MHz[0m
[0;32mI (50) boot: SPI Mode       : DIO[0m
[0;32mI (54) boot: SPI Flash Size : 4MB[0m
[0;32mI (58) boot: Partition Table:[0m
[0;32mI (62) boot: ## Label            Usage          Type ST Offset   Length[0m
[0;32mI (69) boot:  0 sec_cert         unknown          3f 00 0000d000 00003000[0m
[0;32mI (77) boot:  1 nvs              WiFi data        01 02 00010000 00006000[0m
[0;32mI (84) boot:  2 otadata          OTA data         01 00 00016000 00002000[0m
[0;32mI (92) boot:  3 phy_init         RF data          01 01 00018000 00001000[0m
[0;32mI (99) boot:  4 ota_0            OTA app          00 10 00020000 00190000[0m
[0;32mI (106) boot:  5 ota_1            OTA app          00 11 001b0000 00190000[0m
[0;32mI (114) boot:  6 fctry            WiFi data        01 02 00340000 00006000[0m
[0;32mI (122) boot: End of partition table[0m
[0;32mI (126) boot_comm: chip revision: 1, min. application chip revision: 0[0m
[0;32mI (133) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x3b640 (243264) map[0m
[0;32mI (229) esp_image: segment 1: paddr=0x0005b668 vaddr=0x3ffbdb60 size=0x03b58 ( 15192) load[0m
[0;32mI (235) esp_image: segment 2: paddr=0x0005f1c8 vaddr=0x40080000 size=0x00400 (  1024) load[0m
[0;32mI (236) esp_image: segment 3: paddr=0x0005f5d0 vaddr=0x40080400 size=0x00a40 (  2624) load[0m
[0;32mI (246) esp_image: segment 4: paddr=0x00060018 vaddr=0x400d0018 size=0xb9914 (760084) map[0m
[0;32mI (525) esp_image: segment 5: paddr=0x00119934 vaddr=0x40080e40 size=0x16e3c ( 93756) load[0m
[0;32mI (580) boot: Loaded app from partition at offset 0x20000[0m
[0;32mI (580) boot: Disabling RNG early entropy source...[0m
[0;32mI (580) cpu_start: Pro cpu up.[0m
[0;32mI (584) cpu_start: Application information:[0m
[0;32mI (589) cpu_start: Project name:     switch[0m
[0;32mI (593) cpu_start: App version:      1.0[0m
[0;32mI (598) cpu_start: Compile time:     Nov  3 2020 21:37:09[0m
[0;32mI (604) cpu_start: ELF file SHA256:  e724fb53466574b8...[0m
[0;32mI (610) cpu_start: ESP-IDF:          v4.0-beta2-1218-g6093407d7-dirt[0m
[0;32mI (617) cpu_start: Starting app cpu, entry point is 0x4008138c[0m
[0;32mI (0) cpu_start: App cpu up.[0m
D (627) memory_layout: Checking 7 reserved memory ranges:[0m
D (633) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0[0m
D (639) memory_layout: Reserved memory range 0x3ffbdb60 - 0x3ffc7db8[0m
D (646) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440[0m
D (652) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350[0m
D (658) memory_layout: Reserved memory range 0x40070000 - 0x40078000[0m
D (665) memory_layout: Reserved memory range 0x40078000 - 0x40080000[0m
D (671) memory_layout: Reserved memory range 0x40080000 - 0x40097c7c[0m
D (678) memory_layout: Building list of available memory regions:[0m
D (684) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000[0m
D (690) memory_layout: Available memory region 0x3ffb0000 - 0x3ffb8000[0m
D (697) memory_layout: Available memory region 0x3ffb8000 - 0x3ffbdb60[0m
D (704) memory_layout: Available memory region 0x3ffc7db8 - 0x3ffc8000[0m
D (710) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000[0m
D (717) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000[0m
D (723) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000[0m
D (730) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000[0m
D (737) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000[0m
D (743) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000[0m
D (750) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000[0m
D (756) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000[0m
D (763) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000[0m
D (770) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000[0m
D (776) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000[0m
D (783) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000[0m
D (789) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20[0m
D (796) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000[0m
D (803) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000[0m
D (809) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000[0m
D (816) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000[0m
D (822) memory_layout: Available memory region 0x3fffc000 - 0x40000000[0m
D (829) memory_layout: Available memory region 0x40097c7c - 0x40098000[0m
D (836) memory_layout: Available memory region 0x40098000 - 0x4009a000[0m
D (842) memory_layout: Available memory region 0x4009a000 - 0x4009c000[0m
D (849) memory_layout: Available memory region 0x4009c000 - 0x4009e000[0m
D (855) memory_layout: Available memory region 0x4009e000 - 0x400a0000[0m
[0;32mI (862) heap_init: Initializing. RAM available for dynamic allocation:[0m
D (869) heap_init: New heap initialised at 0x3ffae6e0[0m
[0;32mI (874) heap_init: At 3FFAE6E0 len 0000F480 (61 KiB): DRAM[0m
D (880) heap_init: New heap initialised at 0x3ffc7db8[0m
[0;32mI (886) heap_init: At 3FFC7DB8 len 00018248 (96 KiB): DRAM[0m
[0;32mI (892) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM[0m
[0;32mI (898) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
D (904) heap_init: New heap initialised at 0x40097c7c[0m
[0;32mI (910) heap_init: At 40097C7C len 00008384 (32 KiB): IRAM[0m
[0;32mI (916) cpu_start: Pro cpu start user code[0m
D (928) clk: RTC_SLOW_CLK calibration value: 3278579[0m
D (937) intr_alloc: Connected src 46 to int 2 (cpu 0)[0m
D (938) intr_alloc: Connected src 57 to int 3 (cpu 0)[0m
D (939) intr_alloc: Connected src 24 to int 9 (cpu 0)[0m
D (943) FLASH_HAL: extra_dummy: 1[0m
D (947) spi_flash: trying chip: issi[0m
D (950) spi_flash: trying chip: gd[0m
D (954) spi_flash: trying chip: generic[0m
[0;32mI (958) spi_flash: detected chip: generic[0m
[0;32mI (962) spi_flash: flash io: dio[0m
[0;32mI (966) cpu_start: Starting scheduler on PRO CPU.[0m
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)[0m
[0;32mI (0) cpu_start: Starting scheduler on APP CPU.[0m
D (982) heap_init: New heap initialised at 0x3ffe0440[0m
D (992) heap_init: New heap initialised at 0x3ffe4350[0m
D (1002) intr_alloc: Connected src 16 to int 12 (cpu 0)[0m
[0;32mI (1002) esp_rmaker_commands: Registering command: up-time[0m
[0;32mI (1002) esp_rmaker_console: Initialising UART on port 0[0m
[0;32mI (1012) uart: queue free spaces: 8[0m
D (1022) intr_alloc: Connected src 34 to int 13 (cpu 0)[0m
[0;32mI (1022) esp_rmaker_commands: Registering command: mem-dump[0m
[0;32mI (1032) esp_rmaker_commands: Registering command: task-dump[0m
[0;32mI (1032) esp_rmaker_commands: Registering command: cpu-dump[0m
[0;32mI (1042) esp_rmaker_commands: Registering command: sock-dump[0m
[0;32mI (1052) esp_rmaker_commands: Registering command: heap-trace[0m
[0;32mI (1052) esp_rmaker_commands: Registering command: reset-to-factory[0m
[0;32mI (1062) esp_rmaker_commands: Registering command: add-user[0m
[0;32mI (1072) esp_rmaker_commands: Registering command: get-node-id[0m
[0;32mI (1072) esp_rmaker_commands: Registering command: wifi-prov[0m
[0;32mI (1082) esp_rmaker_commands: Registering command: local-time[0m
[0;32mI (1092) esp_rmaker_commands: Registering command: tz-set[0m
D (1092) intr_alloc: Connected src 22 to int 17 (cpu 0)[0m
[0;32mI (1102) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 [0m
[0;32mI (1112) gpio: GPIO[19]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 [0m
[0;33mW (1122) ws2812_led: WS2812 LED is disabled[0m
D (1122) partition: Loading the partition table[0m
D (1132) nvs: nvs_flash_init_custom partition=nvs start=16 count=6[0m
D (1172) event: running task for loop 0x3ffb7214[0m
D (1172) event: created task for loop 0x3ffb7214[0m
D (1172) event: created event loop 0x3ffb7214[0m
D (1172) nvs: nvs_open_from_partition misc 1[0m
D (1182) nvs: nvs_get_str_or_blob log[0m
I (1192) wifi:wifi driver task: 3ffba4c8, prio:23, stack:6656, core=0
[0;32mI (1192) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE[0m
D (1202) efuse: coding scheme 0[0m
D (1202) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit[0m
D (1212) efuse: coding scheme 0[0m
D (1212) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit[0m
D (1222) efuse: coding scheme 0[0m
D (1222) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit[0m
D (1232) efuse: coding scheme 0[0m
D (1232) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit[0m
D (1242) efuse: coding scheme 0[0m
D (1242) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit[0m
D (1252) efuse: coding scheme 0[0m
D (1252) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit[0m
D (1262) efuse: coding scheme 0[0m
D (1262) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit[0m
[0;32mI (1272) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE[0m
D (1282) efuse: coding scheme 0[0m
D (1282) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit[0m
D (1292) efuse: coding scheme 0[0m
D (1292) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit[0m
D (1302) efuse: coding scheme 0[0m
D (1302) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit[0m
D (1312) efuse: coding scheme 0[0m
D (1312) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit[0m
D (1322) efuse: coding scheme 0[0m
D (1322) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit[0m
D (1332) efuse: coding scheme 0[0m
D (1332) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit[0m
D (1342) efuse: coding scheme 0[0m
D (1342) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit[0m
D (1352) nvs: nvs_open_from_partition nvs.net80211 1[0m
D (1352) nvs: nvs_get opmode 1[0m
D (1362) nvs: nvs_get_str_or_blob sta.ssid[0m
D (1362) nvs: nvs_get_str_or_blob sta.mac[0m
D (1372) nvs: nvs_get sta.authmode 1[0m
D (1372) nvs: nvs_get_str_or_blob sta.pswd[0m
D (1372) nvs: nvs_get_str_or_blob sta.pmk[0m
D (1382) nvs: nvs_get sta.chan 1[0m
D (1382) nvs: nvs_get auto.conn 1[0m
D (1382) nvs: nvs_get bssid.set 1[0m
D (1392) nvs: nvs_get_str_or_blob sta.bssid[0m
D (1392) nvs: nvs_get sta.lis_intval 2[0m
D (1402) nvs: nvs_get sta.phym 1[0m
D (1402) nvs: nvs_get sta.phybw 1[0m
D (1402) nvs: nvs_get_str_or_blob sta.apsw[0m
D (1412) nvs: nvs_get_str_or_blob sta.apinfo[0m
D (1412) nvs: nvs_get sta.scan_method 1[0m
D (1422) nvs: nvs_get sta.sort_method 1[0m
D (1422) nvs: nvs_get sta.minrssi 1[0m
D (1422) nvs: nvs_get sta.minauth 1[0m
D (1432) nvs: nvs_get sta.pmf_e 1[0m
D (1432) nvs: nvs_get sta.pmf_r 1[0m
D (1432) nvs: nvs_get_str_or_blob ap.ssid[0m
D (1442) nvs: nvs_get_str_or_blob ap.mac[0m
D (1442) nvs: nvs_get_str_or_blob ap.passwd[0m
D (1452) nvs: nvs_get_str_or_blob ap.pmk[0m
D (1452) nvs: nvs_get ap.chan 1[0m
D (1452) nvs: nvs_get ap.authmode 1[0m
D (1462) nvs: nvs_get ap.hidden 1[0m
D (1462) nvs: nvs_get ap.max.conn 1[0m
D (1462) nvs: nvs_get bcn.interval 2[0m
D (1472) nvs: nvs_get ap.phym 1[0m
D (1472) nvs: nvs_get ap.phybw 1[0m
D (1472) nvs: nvs_get ap.sndchan 1[0m
D (1482) nvs: nvs_get ap.pmf_e 1[0m
D (1482) nvs: nvs_get ap.pmf_r 1[0m
D (1482) nvs: nvs_get lorate 1[0m
D (1492) nvs: nvs_set ap.sndchan 1 1[0m
D (1492) nvs: nvs_set_blob sta.mac 6[0m
D (1492) nvs: nvs_set_blob ap.mac 6[0m
I (1502) wifi:wifi firmware version: 19abcd9
I (1502) wifi:config NVS flash: enabled
I (1502) wifi:config nano formating: disabled
I (1512) wifi:Init data frame dynamic rx buffer num: 32
I (1512) wifi:Init management frame dynamic rx buffer num: 32
I (1522) wifi:Init management short buffer num: 32
I (1522) wifi:Init dynamic tx buffer num: 32
I (1532) wifi:Init static rx buffer size: 1600
I (1532) wifi:Init static rx buffer num: 10
I (1542) wifi:Init dynamic rx buffer num: 32
D (1542) nvs: nvs_flash_init_custom partition=fctry start=832 count=6[0m
D (1562) nvs: nvs_open_from_partition rmaker_creds 0[0m
D (1562) nvs: nvs_get_str_or_blob node_id[0m
D (1562) esp_rmaker_storage: Failed to read key node_id with error 4354 size 0[0m
D (1562) nvs: nvs_close 3[0m
D (1572) nvs: nvs_open_from_partition rmaker_creds 0[0m
D (1572) nvs: nvs_get_str_or_blob client_key[0m
D (1582) nvs: nvs_get_str_or_blob client_key[0m
D (1592) nvs: nvs_close 4[0m
D (1592) nvs: nvs_open_from_partition rmaker_creds 0[0m
D (1592) nvs: nvs_get_str_or_blob client_cert[0m
D (1592) esp_rmaker_storage: Failed to read key client_cert with error 4354 size 0[0m
D (1602) nvs: nvs_close 5[0m
[0;32mI (1602) esp_claim: Initialising Assisted Claiming. This may take time.[0m
D (1622) nvs: nvs_open_from_partition rmaker_creds 0[0m
D (1622) nvs: nvs_get_str_or_blob client_key[0m
D (1622) nvs: nvs_get_str_or_blob client_key[0m
D (1642) nvs: nvs_close 6[0m
[0;32mI (1642) esp_claim: Private key already exists. No need to re-initialise it.[0m
D (1652) nvs: nvs_open_from_partition rmaker_creds 1[0m
D (1652) nvs: nvs_set_blob random 64[0m
D (1662) nvs: nvs_close 7[0m
D (1662) event: running post RMAKER_EVENT:1 with handler 0x400d7f60 on loop 0x3ffb7214[0m
[0;32mI (1662) app_main: RainMaker Initialised.[0m
[0;32mI (1672) esp_rmaker_node: Node ID ----- 840D8EE6AC14[0m
D (1672) nvs: nvs_open_from_partition Switch 0[0m
D (1682) nvs: nvs_get_str_or_blob Name[0m
D (1682) nvs: nvs_get_str_or_blob Name[0m
D (1692) nvs: nvs_close 8[0m
D (1692) esp_rmaker_device: Param Name added in Switch[0m
D (1692) esp_rmaker_device: Param Power added in Switch[0m
[0;32mI (1702) esp_rmaker_ota: OTA state = 2[0m
D (1702) esp_rmaker_device: Param Status added in OTA[0m
D (1712) esp_rmaker_device: Param Info added in OTA[0m
D (1712) esp_rmaker_device: Param URL added in OTA[0m
[0;32mI (1722) esp_rmaker_ota_using_params: OTA enabled with Params[0m
[0;32mI (1722) esp_rmaker_time_sync: Initializing SNTP. Using the SNTP server: pool.ntp.org[0m
D (1732) nvs: nvs_open_from_partition rmaker_time 0[0m
D (1742) nvs: nvs_open_from_partition Schedule 0[0m
D (1742) nvs: nvs_get_str_or_blob Schedules[0m
D (1752) nvs: nvs_get_str_or_blob Schedules[0m
D (1752) nvs: nvs_close 9[0m
D (1752) esp_rmaker_device: Param Schedules added in Schedule[0m
D (1762) esp_rmaker_schedule: Scheduling Service Enabled[0m
[0;32mI (1762) esp_rmaker_core: Starting RainMaker Core Task[0m
D (1772) wifi_prov_mgr: execute_event_cb : 0[0m
D (1772) event: running post RMAKER_EVENT:2 with handler 0x400d7f60 on loop 0x3ffb7214[0m
[0;32mI (1772) esp_claim: Waiting for assisted claim to finish.[0m
[0;32mI (1782) app_main: RainMaker Claim Started.[0m
D (1792) event: running post WIFI_PROV_EVENT:0 with handler 0x400de3bc on loop 0x3ffb7214[0m
D (1802) event: running post WIFI_PROV_EVENT:0 with handler 0x400da978 on loop 0x3ffb7214[0m
D (1812) event: running post WIFI_PROV_EVENT:0 with handler 0x400dc0bc on loop 0x3ffb7214[0m
[0;32mI (1782) app_wifi: Starting provisioning[0m
D (1822) nvs: nvs_open_from_partition rmaker_creds 0[0m
D (1832) nvs: nvs_get_str_or_blob random[0m
D (1832) nvs: nvs_get_str_or_blob random[0m
D (1842) nvs: nvs_close 10[0m
D (1842) nvs: nvs_open_from_partition rmaker_creds 0[0m
D (1842) nvs: nvs_get_str_or_blob random[0m
D (1852) nvs: nvs_get_str_or_blob random[0m
D (1852) nvs: nvs_close 11[0m
D (1862) RTC_MODULE: Wi-Fi takes adc2 lock.[0m
D (1862) phy_init: loading PHY init data from application binary[0m
D (1872) nvs: nvs_open_from_partition phy 0[0m
D (1872) nvs: nvs_get cal_version 4[0m
D (1872) nvs: nvs_get_str_or_blob cal_mac[0m
D (1882) efuse: coding scheme 0[0m
D (1882) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit[0m
D (1892) efuse: coding scheme 0[0m
D (1892) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit[0m
D (1902) efuse: coding scheme 0[0m
D (1902) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit[0m
D (1912) efuse: coding scheme 0[0m
D (1912) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit[0m
D (1922) efuse: coding scheme 0[0m
D (1922) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit[0m
D (1932) efuse: coding scheme 0[0m
D (1932) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit[0m
D (1942) efuse: coding scheme 0[0m
D (1942) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit[0m
D (1952) nvs: nvs_get_str_or_blob cal_data[0m
D (1962) nvs: nvs_close 12[0m
D (1962) efuse: coding scheme 0[0m
D (1962) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit[0m
D (1972) efuse: coding scheme 0[0m
D (1972) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit[0m
D (1982) efuse: coding scheme 0[0m
D (1982) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit[0m
D (1992) efuse: coding scheme 0[0m
D (1992) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit[0m
D (2002) efuse: coding scheme 0[0m
D (2002) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit[0m
D (2012) efuse: coding scheme 0[0m
D (2012) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit[0m
D (2022) efuse: coding scheme 0[0m
D (2022) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit[0m
[0;32mI (2112) phy: phy_version: 4370, 4e803b3, Aug 11 2020, 14:18:07, 0, 0[0m
I (2112) wifi:mode : sta (84:0d:8e:e6:ac:14)
D (2112) system_event: SYSTEM_EVENT_STA_START[0m
D (2112) event: running post WIFI_EVENT:2 with handler 0x400de3bc on loop 0x3ffb7214[0m
D (2122) event: running post WIFI_EVENT:2 with handler 0x4011c3b0 on loop 0x3ffb7214[0m
D (2132) httpd: httpd_thread: web server started[0m
I (2132) wifi:D (2132) httpd: httpd_server: doing select maxfd+1 = 56[0m
mode : sta (84:0d:8e:e6:ac:14) + softAP (84:0d:8e:e6:ac:15)
I (2152) wifi:Total power save buffer number: 16
I (2152) wifi:Init max length of beacon: 752/752
I (2162) wifi:Init max length of beacon: 752/752
D (2162) system_event: SYSTEM_EVENT_AP_START[0m
D (2162) event: running post WIFI_EVENT:12 with handler 0x400de3bc on loop 0x3ffb7214[0m
D (2172) event: running post WIFI_EVENT:12 with handler 0x4011c1f4 on loop 0x3ffb7214[0m
D (2182) system_event: SYSTEM_EVENT_AP_STOP[0m
D (2182) tcpip_adapter: dhcp server start:(ip: 192.168.4.1, mask: 255.255.255.0, gw: 192.168.4.1)[0m
I (2182) wifi:Total power save buffer number: 16
D (2202) system_event: SYSTEM_EVENT_AP_START[0m
D (2202) event: running post WIFI_EVENT:13 with handler 0x400de3bc on loop 0x3ffb7214[0m
D (2212) event: running post WIFI_EVENT:13 with handler 0x4011c1a8 on loop 0x3ffb7214[0m
[0;33mW (2222) wifi_prov_scheme_softap: Error adding mDNS service! Check if mDNS is running[0m
D (2222) event: running post WIFI_EVENT:12 with handler 0x400de3bc on loop 0x3ffb7214[0m
D (2232) event: running post WIFI_EVENT:12 with handler 0x4011c1f4 on loop 0x3ffb7214[0m
D (2242) tcpip_adapter: dhcp server start:(ip: 192.168.4.1, mask: 255.255.255.0, gw: 192.168.4.1)[0m
D (2242) protocomm_httpd: Adding endpoint : proto-ver[0m
D (2262) httpd_uri: httpd_register_uri_handler: [0] installed /proto-ver[0m
D (2262) protocomm_httpd: Adding endpoint : prov-session[0m
D (2272) httpd_uri: httpd_find_uri_handler: [0] = /proto-ver[0m
D (2272) httpd_uri: httpd_register_uri_handler: [0] exists /proto-ver[0m
D (2282) httpd_uri: httpd_register_uri_handler: [1] installed /prov-session[0m
D (2292) protocomm_httpd: Adding endpoint : prov-config[0m
D (2292) httpd_uri: httpd_find_uri_handler: [0] = /proto-ver[0m
D (2302) httpd_uri: httpd_find_uri_handler: [1] = /prov-session[0m
D (2302) httpd_uri: httpd_register_uri_handler: [0] exists /proto-ver[0m
D (2312) httpd_uri: httpd_register_uri_handler: [1] exists /prov-session[0m
D (2322) httpd_uri: httpd_register_uri_handler: [2] installed /prov-config[0m
D (2322) protocomm_httpd: Adding endpoint : prov-scan[0m
D (2332) httpd_uri: httpd_find_uri_handler: [0] = /proto-ver[0m
D (2332) httpd_uri: httpd_find_uri_handler: [1] = /prov-session[0m
D (2342) httpd_uri: httpd_find_uri_handler: [2] = /prov-config[0m
D (2352) httpd_uri: httpd_register_uri_handler: [0] exists /proto-ver[0m
D (2352) httpd_uri: httpd_register_uri_handler: [1] exists /prov-session[0m
D (2362) httpd_uri: httpd_register_uri_handler: [2] exists /prov-config[0m
D (2372) httpd_uri: httpd_register_uri_handler: [3] installed /prov-scan[0m
[0;32mI (2372) wifi_prov_mgr: Provisioning started with service name : PROV_7d5e6e [0m
D (2382) wifi_prov_mgr: execute_event_cb : 1[0m
D (2392) event: running post WIFI_PROV_EVENT:1 with handler 0x400de3bc on loop 0x3ffb7214[0m
[0;32mI (2392) app_wifi: Provisioning started[0m
D (2402) event: running post WIFI_PROV_EVENT:1 with handler 0x400da978 on loop 0x3ffb7214[0m
D (2412) protocomm_httpd: Adding endpoint : cloud_user_assoc[0m
D (2412) httpd_uri: httpd_find_uri_handler: [0] = /proto-ver[0m
D (2422) httpd_uri: httpd_find_uri_handler: [1] = /prov-session[0m
D (2422) httpd_uri: httpd_find_uri_handler: [2] = /prov-config[0m
D (2432) httpd_uri: httpd_find_uri_handler: [3] = /prov-scan[0m
D (2442) httpd_uri: httpd_register_uri_handler: [0] exists /proto-ver[0m
D (2442) httpd_uri: httpd_register_uri_handler: [1] exists /prov-session[0m
D (2452) httpd_uri: httpd_register_uri_handler: [2] exists /prov-config[0m
D (2462) httpd_uri: httpd_register_uri_handler: [3] exists /prov-scan[0m
D (2462) httpd_uri: httpd_register_uri_handler: [4] installed /cloud_user_assoc[0m
D (2472) event: running post WIFI_PROV_EVENT:1 with handler 0x400dc0bc on loop 0x3ffb7214[0m
D (2482) protocomm_httpd: Adding endpoint : rmaker_claim[0m
D (2482) httpd_uri: httpd_find_uri_handler: [0] = /proto-ver[0m
D (2492) httpd_uri: httpd_find_uri_handler: [1] = /prov-session[0m
D (2492) httpd_uri: httpd_find_uri_handler: [2] = /prov-config[0m
D (2502) httpd_uri: httpd_find_uri_handler: [3] = /prov-scan[0m
D (2512) httpd_uri: httpd_find_uri_handler: [4] = /cloud_user_assoc[0m
D (2512) httpd_uri: httpd_register_uri_handler: [0] exists /proto-ver[0m
D (2522) httpd_uri: httpd_register_uri_handler: [1] exists /prov-session[0m
D (2532) httpd_uri: httpd_register_uri_handler: [2] exists /prov-config[0m
D (2532) httpd_uri: httpd_register_uri_handler: [3] exists /prov-scan[0m
D (2542) httpd_uri: httpd_register_uri_handler: [4] exists /cloud_user_assoc[0m
D (2552) httpd_uri: httpd_register_uri_handler: [5] installed /rmaker_claim[0m
[0;32mI (2552) app_wifi: Scan this QR code from the phone app for Provisioning.[0m
                                      
  █▀▀▀▀▀█ ▀▄▄▀▀█   ▀ ▄█▀▄ █ █▀▀▀▀▀█   
  █ ███ █   ▀ ██▄ ▀▄▄ ▄█  ▄ █ ███ █   
  █ ▀▀▀ █  ▀▄▀▄▄▀ ▀█ ▀▄▀ ▄  █ ▀▀▀ █   
  ▀▀▀▀▀▀▀ █ █▄▀▄█▄█ ▀▄▀ █▄▀ ▀▀▀▀▀▀▀   
  ██ ▀█ ▀  █▀▀▄▄ ▄▀█▀██ ▀▄▄ ▀▄▄ ▄▄▀   
   ██▀  ▀▄ ▄██▄▀▀▀▄█▀▄▀ █▀ █  ▄█▄█▀   
  ▄▄▀ ▀▀▀  █ ▀▀▄██▄ ▀▀▀    ▄▀█ ▀▄▄▀   
  ▄▄█▀ ▄▀▀▄█ █▀ ▄█▄ ▄█▄▀ ▄▀▄▄█  ▄     
  ▀ ▄▄ █▀ ▄ █▄█▀▄█▀▄▄▄▀ ▄█  ███▄ ██   
   ▀█▀▄▄▀ █▄▄▀ ▄▀██▀ ▀█ ▀█ █▀▀ ▀▄▄▀   
  █▀▄▄▄▀▀█ ▄▀█ ▄█▄▀▀█▄█▄█▀▀█ ▀▄ ▄▀    
  █ ████▀█▄▄▀▀█▀▄▀█▄█▄▀▀█▀█ ▄█ ▀▄▄█   
  ▀▀▀▀▀ ▀ ▄▄▄██▄▄██▄█▀█ ▀██▀▀▀█▄▄▀    
  █▀▀▀▀▀█  ▄  █ ███ ▄▀▄ █▄█ ▀ █ ▄▄    
  █ ███ █ █▀ ▀ ▀▄█▀▄█▄▄ ▀██▀▀▀▀▄▄▀▀   
  █ ▀▀▀ █ ▄ █▀▄█▄▀█ █▀ ▀▀███▄▀█ █▄█   
  ▀▀▀▀▀▀▀ ▀▀  ▀ ▀▀ ▀     ▀▀▀▀▀▀       
                                      

[0;32mI (2762) app_wifi: If QR code is not visible, copy paste the below URL in a browser.
https://rainmaker.espressif.com/qrcode.html?data={"ver":"v1","name":"PROV_7d5e6e","pop":"b5b5594e","transport":"softap"}[0m
[0;32mI (2782) app_wifi: Provisioning Started. Name : PROV_7d5e6e, POP : b5b5594e[0m
I (63082) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
I (63082) wifi:station: d0:13:fd:26:6b:31 join, AID=1, bgn, 20
D (63092) system_event: SYSTEM_EVENT_AP_STACONNECTED, mac:d0:13:fd:26:6b:31, aid:1[0m
D (63092) event: running post WIFI_EVENT:14 with handler 0x400de3bc on loop 0x3ffb7214[0m
D (63102) event: running post WIFI_EVENT:14 with handler 0x400e5f7c on loop 0x3ffb7214[0m
[0;32mI (63322) tcpip_adapter: softAP assign IP to station,IP is: 192.168.4.2[0m
D (63322) system_event: SYSTEM_EVENT_AP_STAIPASSIGNED[0m
D (63332) event: no handlers have been registered for event IP_EVENT:2 posted to loop 0x3ffb7214[0m
D (85282) httpd: httpd_server: processing listen socket 54[0m
D (85282) httpd: httpd_accept_conn: newfd = 57[0m
D (85282) httpd_sess: httpd_sess_new: fd = 57[0m
D (85282) httpd: httpd_accept_conn: complete[0m
D (85292) httpd: httpd_server: doing select maxfd+1 = 58[0m
D (85292) httpd: httpd_server: processing socket 57[0m
D (85302) httpd_sess: httpd_sess_process: httpd_req_new[0m
D (85302) httpd_txrx: httpd_recv_with_opt: requested length = 128[0m
D (85312) httpd_txrx: httpd_recv_with_opt: received length = 128[0m
D (85312) httpd_parse: read_block: received HTTP request block size = 128[0m
D (85322) httpd_parse: cb_url: message begin[0m
D (85332) httpd_parse: cb_url: processing url = /proto-ver[0m
D (85332) httpd_parse: verify_url: received URI = /proto-ver[0m
D (85342) httpd_parse: cb_header_field: headers begin[0m
D (85342) httpd_txrx: httpd_unrecv: length = 102[0m
D (85352) httpd_parse: pause_parsing: paused[0m
D (85352) httpd_parse: cb_header_field: processing field = Accept[0m
D (85362) httpd_txrx: httpd_recv_with_opt: requested length = 128[0m
D (85362) httpd_txrx: httpd_recv_with_opt: pending length = 102[0m
D (85372) httpd_parse: read_block: received HTTP request block size = 102[0m
D (85382) httpd_parse: continue_parsing: skip pre-parsed data of size = 7[0m
D (85382) httpd_parse: continue_parsing: un-paused[0m
D (85392) httpd_parse: cb_header_value: processing value = text/plain[0m
D (85392) httpd_parse: cb_header_field: processing field = Content-type[0m
D (85402) httpd_parse: cb_header_value: processing value = application/x-www-form-urlencoded[0m
D (85412) httpd_parse: cb_header_field: processing field = User-Agent[0m
D (85422) httpd_parse: cb_header_value: processing value = Dalvik/2.1.0 (Linux; [0m
D (85422) httpd_parse: parse_block: parsed block size = 102[0m
D (85432) httpd_txrx: httpd_recv_with_opt: requested length = 128[0m
D (85442) httpd_txrx: httpd_recv_with_opt: received length = 128[0m
D (85442) httpd_parse: read_block: received HTTP request block size = 128[0m
D (85452) httpd_parse: cb_header_value: processing value = U; Android 8.1.0; Nexus 5X Build/OPM7.181205.001)[0m
D (85462) httpd_parse: cb_header_field: processing field = Host[0m
D (85462) httpd_parse: cb_header_value: processing value = 192.168.4.1[0m
D (85472) httpd_parse: cb_header_field: processing field = Connection[0m
D (85482) httpd_parse: cb_header_value: processing value = Keep-Alive[0m
D (85482) httpd_parse: cb_header_field: processing field = Accept-Encoding[0m
D (85492) httpd_parse: cb_header_value: processing value = gzip[0m
D (85502) httpd_parse: cb_header_field: processing field = Content-Len[0m
D (85502) httpd_parse: parse_block: parsed block size = 230[0m
D (85512) httpd_txrx: httpd_recv_with_opt: requested length = 128[0m
D (85522) httpd_txrx: httpd_recv_with_opt: received length = 13[0m
D (85522) httpd_parse: read_block: received HTTP request block size = 13[0m
D (85532) httpd_parse: cb_header_field: processing field = gth[0m
D (85532) httpd_parse: cb_header_value: processing value = 3[0m
D (85542) httpd_parse: cb_headers_complete: bytes read     = 268[0m
D (85552) httpd_parse: cb_headers_complete: content length = 3[0m
D (85552) httpd_txrx: httpd_unrecv: length = 3[0m
D (85562) httpd_parse: pause_parsing: paused[0m
D (85562) httpd_parse: cb_on_body: body begins[0m
D (85562) httpd_parse: httpd_parse_req: parsing complete[0m
D (85572) httpd_uri: httpd_uri: request for /proto-ver with type 3[0m
D (85582) httpd_uri: httpd_find_uri_handler: [0] = /proto-ver[0m
[0;32mI (85582) protocomm_httpd: Creating new session: 57[0m
D (85592) protocomm_httpd: New session with ID: 57[0m
D (85592) httpd_txrx: httpd_req_recv: remaining length = 3[0m
D (85602) httpd_txrx: httpd_recv_with_opt: requested length = 3[0m
D (85602) httpd_txrx: httpd_recv_with_opt: pending length = 3[0m
D (85612) httpd_txrx: httpd_req_recv: received length = 3[0m
D (85622) protocomm: VER_EP Req handler returned 0[0m
D (85622) httpd_txrx: httpd_send_all: sent = 63[0m
D (85632) httpd_txrx: httpd_send_all: sent = 2[0m
D (85632) httpd_txrx: httpd_send_all: sent = 109[0m
D (85632) httpd_sess: httpd_sess_process: httpd_req_delete[0m
D (85642) httpd_sess: httpd_sess_process: success[0m
D (85642) httpd: httpd_server: doing select maxfd+1 = 58[0m
[0;33m--- idf_monitor on /dev/ttyUSB0 115200 ---[0m
[0;33m--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---[0m
[0;33m0x40080000: _WindowOverflow4 at /home/maldus/Source/esp-idf-v4.0/components/freertos/xtensa_vectors.S:1778
[0m
[0;33m0x400d0018: _stext at ??:?
[0m
[0;33m0x4008138c: call_start_cpu1 at /home/maldus/Source/esp-idf-v4.0/components/esp32/cpu_start.c:267
[0m
[0;33m0x40080000: _WindowOverflow4 at /home/maldus/Source/esp-idf-v4.0/components/freertos/xtensa_vectors.S:1778
[0m
[0;33m0x40080000: _WindowOverflow4 at /home/maldus/Source/esp-idf-v4.0/components/freertos/xtensa_vectors.S:1778
[0m
[0;33m0x400d7f60: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build/../main/app_main.c:48
[0m
[0;33m0x400d7f60: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build/../main/app_main.c:48
[0m
[0;33m0x400de3bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72
[0m
[0;33m0x400da978: esp_rmaker_user_mapping_event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_user_mapping.c:51
[0m
[0;33m0x400dc0bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_claim.c:767
[0m
[0;33m0x400de3bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72
[0m
[0;33m0x4011c3b0: handle_sta_start at /home/maldus/Source/esp-idf-v4.0/components/tcpip_adapter/event_handlers.c:140
[0m
[0;33m0x400de3bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72
[0m
[0;33m0x4011c1f4: handle_ap_start at /home/maldus/Source/esp-idf-v4.0/components/tcpip_adapter/event_handlers.c:121
[0m
[0;33m0x400de3bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72
[0m
[0;33m0x4011c1a8: handle_ap_stop at /home/maldus/Source/esp-idf-v4.0/components/tcpip_adapter/event_handlers.c:133
[0m
[0;33m0x400de3bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72
[0m
[0;33m0x4011c1f4: handle_ap_start at /home/maldus/Source/esp-idf-v4.0/components/tcpip_adapter/event_handlers.c:121
[0m
[0;33m0x400de3bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72
[0m
[0;33m0x400da978: esp_rmaker_user_mapping_event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_user_mapping.c:51
[0m
[0;33m0x400dc0bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_claim.c:767
[0m
[0;33m0x400de3bc: event_handler at /home/maldus/Projects/pasticci/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72
[0m
[0;33m0x400e5f7c: wifi_prov_mgr_event_handler_internal at /home/maldus/Source/esp-idf-v4.0/components/wifi_provisioning/src/manager.c:805
[0m
[0m
Checking Python dependencies...
Executing action: monitor
Choosing default port b'/dev/ttyUSB0' (use '-p PORT' option to set a specific serial port)
Running idf_monitor in directory /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch
Executing "/home/maldus/.espressif/python_env/idf4.0_py3.8_env/bin/python /home/maldus/Source/esp-idf-v4.0/tools/idf_monitor.py -p /dev/ttyUSB0 -b 115200 /home/maldus/Projects/pasticci/esp-rainmaker/examples/switch/build/switch.elf -m '/home/maldus/.espressif/python_env/idf4.0_py3.8_env/bin/python' '/home/maldus/Source/esp-idf-v4.0/tools/idf.py'"...

My phone is a Nexus 5X updated to Android 8.1.0

[ESP_Piyush]

Hello,

Since assisted claiming works only for BLE provisioning, this message was expected. But this message means that the phone was able to communicate with the board. It is hard to tell why your QR code based provisioning (specifically for BLE) is failing as the device does not even show any logs, as you said. One option could be to check the phone app side logs on Android Studio. However, if you just want to move ahead, a workaround is to use the Host driven claiming and then use the manual mode with SoftAP provisioning.

Regards,
Piyush

[maldus]

It does indeed seem to be an issue on the phone app side. I've tried to claim the device through the rainmaker.py cli tool and then to provision it separately with the ESP softAP provisioning app, but it still did not appear among my registered devices.

By using a different phone (with the same Github account) the procedure worked on the first try.
I doubt I'll be looking any further into this issue as long as I can work around it with a different device. Meanwhile I am grateful for your assistance.

[maldus]

I have an important update to give on this issue.
I tried using different phones to see if I could find a pattern and after failing a couple of times I stumbled upon a model that warned me to activate "location services" before going through with the provisioning procedure.
I finally remembered that on some phone models/versions of Android the user needs to manually activate the GPS function when the application needs to interact with the Bluetooth API. Unfortunately if that is not the case the procedure fails to give a proper error message.

Indeed, by turning on location tracking just during the provisioning procedure it works on all the phones where it previously failed for me. This should be added as a note somewhere in the application (or the online documentation).

[ESP_Piyush]

Hello,

Thanks for debugging this issue yourself and providing your analysis. Surely, we would need some indication in the app, some sort of troubleshooting section, with a pointer in the error popups itself. We will check how it can be done and update the app accordingly.

Regards,
Piyush

[olegos]

Same error on ESP-WROOM-32 on Devkit V1.
At the first attempt I've tried to connect from Xiaomi Mi mix 2 using BLE.
Got these errors.

Code: Select all

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:4
load:0x3fff0034,len:6956
load:0x40078000,len:13072
load:0x40080400,len:3896
0x40080400: _init at ??:?

entry 0x40080688
I (28) boot: ESP-IDF v4.1 2nd stage bootloader
I (29) boot: compile time 15:28:55
I (29) boot: chip revision: 1
I (31) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (38) boot.esp32: SPI Speed      : 40MHz
I (43) boot.esp32: SPI Mode       : DIO
I (47) boot.esp32: SPI Flash Size : 4MB
I (52) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 sec_cert         unknown          3f 00 0000d000 00003000
I (76) boot:  1 nvs              WiFi data        01 02 00010000 00006000
I (83) boot:  2 otadata          OTA data         01 00 00016000 00002000
I (91) boot:  3 phy_init         RF data          01 01 00018000 00001000
I (98) boot:  4 ota_0            OTA app          00 10 00020000 001e0000
I (106) boot:  5 ota_1            OTA app          00 11 00200000 001e0000
I (113) boot:  6 fctry            WiFi data        01 02 003e0000 00006000
I (121) boot: End of partition table
I (125) boot_comm: chip revision: 1, min. application chip revision: 0
I (132) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x5bbec (375788) map
I (284) esp_image: segment 1: paddr=0x0007bc14 vaddr=0x3ffbdb60 size=0x0406c ( 16492) load
I (291) esp_image: segment 2: paddr=0x0007fc88 vaddr=0x40080000 size=0x00390 (   912) load
0x40080000: _WindowOverflow4 at /build/esp-idf/esp-idf-v4.1/components/freertos/xtensa_vectors.S:1778

I (292) esp_image: segment 3: paddr=0x00080020 vaddr=0x400d0020 size=0x1130c0 (1126592) map
0x400d0020: _stext at ??:?

I (729) esp_image: segment 4: paddr=0x001930e8 vaddr=0x40080390 size=0x00074 (   116) load
0x40080390: _UserExceptionVector at ??:?

I (729) esp_image: segment 5: paddr=0x00193164 vaddr=0x40080404 size=0x1d340 (119616) load
I (803) boot: Loaded app from partition at offset 0x20000
I (803) boot: Disabling RNG early entropy source...
I (804) cpu_start: Pro cpu up.
I (807) cpu_start: Application information:
I (812) cpu_start: Project name:     switch
I (817) cpu_start: App version:      1.0
I (822) cpu_start: Compile time:     Nov 12 2020 15:29:05
I (828) cpu_start: ELF file SHA256:  daf283dc5067e001...
I (834) cpu_start: ESP-IDF:          v4.1
I (838) cpu_start: Starting app cpu, entry point is 0x4008137c
0x4008137c: call_start_cpu1 at /build/esp-idf/esp-idf-v4.1/components/esp32/cpu_start.c:271

I (0) cpu_start: App cpu up.
D (849) memory_layout: Checking 11 reserved memory ranges:
D (854) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
D (860) memory_layout: Reserved memory range 0x3ffae6e0 - 0x3ffaff10
D (867) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb6388
D (873) memory_layout: Reserved memory range 0x3ffb8000 - 0x3ffb9a20
D (880) memory_layout: Reserved memory range 0x3ffbdb28 - 0x3ffbdb5c
D (886) memory_layout: Reserved memory range 0x3ffbdb60 - 0x3ffceb10
D (892) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
D (899) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350
D (905) memory_layout: Reserved memory range 0x40070000 - 0x40078000
D (912) memory_layout: Reserved memory range 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at /build/esp-idf/esp-idf-v4.1/components/freertos/xtensa_vectors.S:1778

D (918) memory_layout: Reserved memory range 0x40080000 - 0x4009d744
0x40080000: _WindowOverflow4 at /build/esp-idf/esp-idf-v4.1/components/freertos/xtensa_vectors.S:1778

D (925) memory_layout: Building list of available memory regions:
D (931) memory_layout: Available memory region 0x3ffaff10 - 0x3ffb0000
D (937) memory_layout: Available memory region 0x3ffb6388 - 0x3ffb8000
D (944) memory_layout: Available memory region 0x3ffb9a20 - 0x3ffbdb28
D (951) memory_layout: Available memory region 0x3ffbdb5c - 0x3ffbdb60
D (957) memory_layout: Available memory region 0x3ffceb10 - 0x3ffd0000
D (964) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
D (970) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
D (977) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
D (984) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
D (990) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
D (997) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
D (1003) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
D (1010) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
D (1017) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20
D (1023) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
D (1030) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
D (1037) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
D (1043) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
D (1050) memory_layout: Available memory region 0x3fffc000 - 0x40000000
D (1057) memory_layout: Available memory region 0x4009d744 - 0x4009e000
D (1063) memory_layout: Available memory region 0x4009e000 - 0x400a0000
I (1070) heap_init: Initializing. RAM available for dynamic allocation:
D (1077) heap_init: New heap initialised at 0x3ffaff10
I (1083) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
D (1089) heap_init: New heap initialised at 0x3ffb6388
I (1094) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
D (1100) heap_init: New heap initialised at 0x3ffb9a20
I (1105) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1112) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
D (1118) heap_init: New heap initialised at 0x3ffceb10
I (1123) heap_init: At 3FFCEB10 len 000114F0 (69 KiB): DRAM
I (1129) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1136) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (1142) heap_init: New heap initialised at 0x4009d744
I (1147) heap_init: At 4009D744 len 000028BC (10 KiB): IRAM
I (1154) cpu_start: Pro cpu start user code
D (1166) clk: RTC_SLOW_CLK calibration value: 3350451
D (1175) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (1176) intr_alloc: Connected src 57 to int 3 (cpu 0)
D (1177) intr_alloc: Connected src 24 to int 9 (cpu 0)
D (1182) FLASH_HAL: extra_dummy: 1
D (1185) spi_flash: trying chip: issi
D (1189) spi_flash: trying chip: gd
D (1192) spi_flash: trying chip: generic
I (1196) spi_flash: detected chip: generic
I (1201) spi_flash: flash io: dio
D (1205) chip_generic: set_io_mode: status before 0x0
I (1210) cpu_start: Starting scheduler on PRO CPU.
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (0) cpu_start: Starting scheduler on APP CPU.
D (1226) heap_init: New heap initialised at 0x3ffe0440
D (1236) heap_init: New heap initialised at 0x3ffe4350
D (1246) intr_alloc: Connected src 16 to int 12 (cpu 0)
I (1246) esp_rmaker_commands: Registering command: up-time
I (1246) esp_rmaker_console: Initialising UART on port 0
I (1256) uart: queue free spaces: 8
D (1266) intr_alloc: Connected src 34 to int 13 (cpu 0)
I (1266) esp_rmaker_commands: Registering command: mem-dump
I (1276) esp_rmaker_commands: Registering command: task-dump
I (1276) esp_rmaker_commands: Registering command: cpu-dump
I (1286) esp_rmaker_commands: Registering command: sock-dump
I (1296) esp_rmaker_commands: Registering command: heap-trace
I (1296) esp_rmaker_commands: Registering command: reset-to-factory
I (1306) esp_rmaker_commands: Registering command: add-user
I (1316) esp_rmaker_commands: Registering command: get-node-id
I (1316) esp_rmaker_commands: Registering command: wifi-prov
I (1326) esp_rmaker_commands: Registering command: local-time
I (1336) esp_rmaker_commands: Registering command: tz-set
D (1336) intr_alloc: Connected src 22 to int 17 (cpu 0)
I (1346) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (1356) gpio: GPIO[19]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
D (1366) partition: Loading the partition table
D (1406) esp_netif_lwip: LwIP stack has been initialized
D (1406) esp_netif_lwip: esp-netif has been successfully initialized
D (1406) event: running task for loop 0x3ffd19b4
D (1416) event: created task for loop 0x3ffd19b4
D (1416) event: created event loop 0x3ffd19b4
D (1426) esp_netif_objects: esp_netif_add_to_list 0x3ffd2994
D (1426) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
D (1436) nvs: nvs_open_from_partition misc 1
D (1446) nvs: nvs_get_str_or_blob log
I (1456) wifi:wifi driver task: 3ffd4eac, prio:23, stack:6656, core=0
I (1456) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (1456) efuse: coding scheme 0
D (1466) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (1466) efuse: coding scheme 0
D (1476) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (1486) efuse: coding scheme 0
D (1486) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (1496) efuse: coding scheme 0
D (1496) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (1506) efuse: coding scheme 0
D (1506) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (1516) efuse: coding scheme 0
D (1516) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (1526) efuse: coding scheme 0
D (1526) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
I (1536) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (1546) efuse: coding scheme 0
D (1546) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (1556) efuse: coding scheme 0
D (1556) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (1566) efuse: coding scheme 0
D (1566) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (1576) efuse: coding scheme 0
D (1576) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (1586) efuse: coding scheme 0
D (1586) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (1596) efuse: coding scheme 0
D (1596) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (1606) efuse: coding scheme 0
D (1606) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (1616) nvs: nvs_open_from_partition nvs.net80211 1
D (1616) nvs: nvs_get opmode 1
D (1626) nvs: nvs_get_str_or_blob sta.ssid
D (1626) nvs: nvs_get_str_or_blob sta.mac
D (1636) nvs: nvs_get sta.authmode 1
D (1636) nvs: nvs_get_str_or_blob sta.pswd
D (1636) nvs: nvs_get_str_or_blob sta.pmk
D (1646) nvs: nvs_get sta.chan 1
D (1646) nvs: nvs_get auto.conn 1
D (1646) nvs: nvs_get bssid.set 1
D (1656) nvs: nvs_get_str_or_blob sta.bssid
D (1656) nvs: nvs_get sta.lis_intval 2
D (1656) nvs: nvs_get sta.phym 1
D (1666) nvs: nvs_get sta.phybw 1
D (1666) nvs: nvs_get_str_or_blob sta.apsw
D (1676) nvs: nvs_get_str_or_blob sta.apinfo
D (1676) nvs: nvs_get sta.scan_method 1
D (1676) nvs: nvs_get sta.sort_method 1
D (1686) nvs: nvs_get sta.minrssi 1
D (1686) nvs: nvs_get sta.minauth 1
D (1686) nvs: nvs_get sta.pmf_e 1
D (1696) nvs: nvs_get sta.pmf_r 1
D (1696) nvs: nvs_get_str_or_blob ap.ssid
D (1706) nvs: nvs_get_str_or_blob ap.mac
D (1706) nvs: nvs_get_str_or_blob ap.passwd
D (1706) nvs: nvs_get_str_or_blob ap.pmk
D (1716) nvs: nvs_get ap.chan 1
D (1716) nvs: nvs_get ap.authmode 1
D (1716) nvs: nvs_get ap.hidden 1
D (1726) nvs: nvs_get ap.max.conn 1
D (1726) nvs: nvs_get bcn.interval 2
D (1736) nvs: nvs_get ap.phym 1
D (1736) nvs: nvs_get ap.phybw 1
D (1736) nvs: nvs_get ap.sndchan 1
D (1746) nvs: nvs_get ap.pmf_e 1
D (1746) nvs: nvs_get ap.pmf_r 1
D (1746) nvs: nvs_get lorate 1
D (1756) nvs: nvs_set ap.sndchan 1 1
D (1756) nvs: nvs_set_blob sta.mac 6
D (1756) nvs: nvs_set_blob ap.mac 6
I (1766) wifi:wifi firmware version: 3ea4c76
I (1766) wifi:config NVS flash: enabled
I (1766) wifi:config nano formating: disabled
I (1776) wifi:Init dynamic tx buffer num: 32
I (1776) wifi:Init data frame dynamic rx buffer num: 32
I (1786) wifi:Init management frame dynamic rx buffer num: 32
I (1786) wifi:Init management short buffer num: 32
I (1796) wifi:Init static rx buffer size: 1600
I (1796) wifi:Init static rx buffer num: 10
I (1796) wifi:Init dynamic rx buffer num: 32
D (1816) nvs: nvs_open_from_partition rmaker_creds 0
D (1816) nvs: nvs_get_str_or_blob node_id
D (1816) esp_rmaker_storage: Failed to read key node_id with error 4354 size 0
D (1826) nvs: nvs_close 3
D (1826) nvs: nvs_open_from_partition rmaker_creds 0
D (1826) nvs: nvs_get_str_or_blob client_key
D (1836) nvs: nvs_get_str_or_blob client_key
D (1846) nvs: nvs_close 4
D (1846) nvs: nvs_open_from_partition rmaker_creds 0
D (1846) nvs: nvs_get_str_or_blob client_cert
D (1856) esp_rmaker_storage: Failed to read key client_cert with error 4354 size 0
D (1856) nvs: nvs_close 5
I (1866) esp_claim: Initialising Assisted Claiming. This may take time.
D (1876) nvs: nvs_open_from_partition rmaker_creds 0
D (1876) nvs: nvs_get_str_or_blob client_key
D (1876) nvs: nvs_get_str_or_blob client_key
D (1886) nvs: nvs_close 6
I (1906) esp_claim: Private key already exists. No need to re-initialise it.
D (1906) nvs: nvs_open_from_partition rmaker_creds 1
D (1906) nvs: nvs_set_blob random 64
D (1916) nvs: nvs_close 7
D (1916) event: running post RMAKER_EVENT:1 with handler 0x400dc1e0 on loop 0x3ffd19b4
0x400dc1e0: event_handler at /build/projects/Samples/rainmaker_switch/build/../main/app_main.c:48

I (1916) app_main: RainMaker Initialised.
I (1926) esp_rmaker_node: Node ID ----- FCF5C40E241C
D (1926) nvs: nvs_open_from_partition Switch 0
D (1936) nvs: nvs_get_str_or_blob Name
D (1936) nvs: nvs_get_str_or_blob Name
D (1946) nvs: nvs_close 8
D (1946) esp_rmaker_device: Param Name added in Switch
D (1946) esp_rmaker_device: Param Power added in Switch
I (1956) esp_rmaker_ota: OTA state = 2
D (1956) esp_rmaker_device: Param Status added in OTA
D (1966) esp_rmaker_device: Param Info added in OTA
D (1966) esp_rmaker_device: Param URL added in OTA
I (1976) esp_rmaker_ota_using_params: OTA enabled with Params
I (1976) esp_rmaker_time_sync: Initializing SNTP. Using the SNTP server: pool.ntp.org
D (1986) nvs: nvs_open_from_partition rmaker_time 0
D (1996) nvs: nvs_open_from_partition Schedule 0
D (1996) nvs: nvs_get_str_or_blob Schedules
D (2006) nvs: nvs_get_str_or_blob Schedules
D (2006) nvs: nvs_close 9
D (2006) esp_rmaker_device: Param Schedules added in Schedule
D (2016) esp_rmaker_schedule: Scheduling Service Enabled
I (2026) esp_rmaker_core: Starting RainMaker Core Task
D (2026) event: running post RMAKER_EVENT:2 with handler 0x400dc1e0 on loop 0x3ffd19b4
0x400dc1e0: event_handler at /build/projects/Samples/rainmaker_switch/build/../main/app_main.c:48

I (2026) esp_claim: Waiting for assisted claim to finish.
I (2036) app_main: RainMaker Claim Started.
D (2036) wifi_prov_mgr: execute_event_cb : 0
D (2046) BTDM_INIT: Release DRAM [0x3ffb2730] - [0x3ffb6388]
I (2056) wifi_prov_scheme_ble: BT memory released
D (2066) event: running post WIFI_PROV_EVENT:0 with handler 0x400e2714 on loop 0x3ffd19b4
0x400e2714: event_handler at /build/esp-idf/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72

D (2066) event: running post WIFI_PROV_EVENT:0 with handler 0x400de630 on loop 0x3ffd19b4
0x400de630: esp_rmaker_user_mapping_event_handler at /build/esp-idf/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_user_mapping.c:51

D (2076) event: running post WIFI_PROV_EVENT:0 with handler 0x400dfdc8 on loop 0x3ffd19b4
0x400dfdc8: event_handler at /build/esp-idf/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_claim.c:767

I (2086) app_wifi: Starting provisioning
D (2086) esp_netif_objects: esp_netif_add_to_list 0x3ffb2884
D (2096) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 2)
D (2106) nvs: nvs_open_from_partition rmaker_creds 0
D (2106) nvs: nvs_get_str_or_blob random
D (2116) nvs: nvs_get_str_or_blob random
D (2116) nvs: nvs_close 10
D (2126) nvs: nvs_open_from_partition rmaker_creds 0
D (2126) nvs: nvs_get_str_or_blob random
D (2126) nvs: nvs_get_str_or_blob random
D (2136) nvs: nvs_close 11
D (2136) phy_init: loading PHY init data from application binary
D (2146) nvs: nvs_open_from_partition phy 0
D (2146) nvs: nvs_get cal_version 4
D (2146) nvs: nvs_get_str_or_blob cal_mac
D (2156) efuse: coding scheme 0
D (2156) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2166) efuse: coding scheme 0
D (2166) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2176) efuse: coding scheme 0
D (2176) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2186) efuse: coding scheme 0
D (2186) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2196) efuse: coding scheme 0
D (2196) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2206) efuse: coding scheme 0
D (2206) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2216) efuse: coding scheme 0
D (2216) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (2226) nvs: nvs_get_str_or_blob cal_data
D (2236) nvs: nvs_close 12
D (2236) efuse: coding scheme 0
D (2236) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2246) efuse: coding scheme 0
D (2246) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2256) efuse: coding scheme 0
D (2256) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2266) efuse: coding scheme 0
D (2266) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2276) efuse: coding scheme 0
D (2276) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2286) efuse: coding scheme 0
D (2286) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2296) efuse: coding scheme 0
D (2296) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
I (2396) phy: phy_version: 4180, cb3948e, Sep 12 2019, 16:39:13, 0, 0
I (2396) wifi:mode : sta (fc:f5:c4:0e:24:1c)
D (2396) event: running post WIFI_EVENT:2 with handler 0x400e2714 on loop 0x3ffd19b4
0x400e2714: event_handler at /build/esp-idf/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72

D (2406) event: running post WIFI_EVENT:2 with handler 0x400f58d0 on loop 0x3ffd19b4
0x400f58d0: wifi_default_action_sta_start at /build/esp-idf/esp-idf-v4.1/components/esp_wifi/src/wifi_default.c:70

D (2406) wifi_init_default: wifi_start esp-netif:0x3ffd2994 event-id2
D (2416) wifi_init_default: WIFI mac address: fc f5 c4 e 24 1c
D (2426) esp_netif_handlers: esp_netif action has started with netif0x3ffd2994 from event_id=2
D (2436) esp_netif_lwip: check: remote, if=0x3ffd2994 fn=0x400e9004
0x400e9004: esp_netif_start_api at /build/esp-idf/esp-idf-v4.1/components/esp_netif/lwip/esp_netif_lwip.c:569


D (2436) esp_netif_lwip: esp_netif_start_api 0x3ffd2994
D (2436) simple_ble: Free mem at start of simple_ble_init 155272
D (2446) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (2456) BTDM_INIT: BT controller compile version [219866f]
D (2466) BTDM_INIT: .data initialise [0x3ffae6e0] <== [0x4000d890]
D (2466) BTDM_INIT: .bss initialise [0x3ffb0000] - [0x3ffb09a8]
D (2476) BTDM_INIT: .bss initialise [0x3ffb09a8] - [0x3ffb1ddc]
D (2476) BTDM_INIT: .bss initialise [0x3ffb1ddc] - [0x3ffb2730]
D (2486) BTDM_INIT: .bss initialise [0x3ffb8000] - [0x3ffb9a20]
D (2496) BTDM_INIT: .bss initialise [0x3ffbdb28] - [0x3ffbdb5c]
I (2496) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (2506) efuse: coding scheme 0
D (2506) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2516) efuse: coding scheme 0
D (2516) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2526) efuse: coding scheme 0
D (2536) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2536) efuse: coding scheme 0
D (2546) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2546) efuse: coding scheme 0
D (2556) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2556) efuse: coding scheme 0
D (2566) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2566) efuse: coding scheme 0
D (2576) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (2586) phy_init: loading PHY init data from application binary
D (2586) nvs: nvs_open_from_partition phy 0
D (2586) nvs: nvs_get cal_version 4
D (2596) nvs: nvs_get_str_or_blob cal_mac
D (2596) efuse: coding scheme 0
D (2596) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2606) efuse: coding scheme 0
D (2606) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2616) efuse: coding scheme 0
D (2616) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2626) efuse: coding scheme 0
D (2636) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2636) efuse: coding scheme 0
D (2646) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2646) efuse: coding scheme 0
D (2656) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2656) efuse: coding scheme 0
D (2666) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (2666) nvs: nvs_get_str_or_blob cal_data
D (2686) nvs: nvs_close 13
D (2686) efuse: coding scheme 0
D (2686) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2686) efuse: coding scheme 0
D (2686) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2696) efuse: coding scheme 0
D (2696) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2706) efuse: coding scheme 0
D (2706) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2716) efuse: coding scheme 0
D (2716) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2726) efuse: coding scheme 0
D (2726) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2736) efuse: coding scheme 0
D (2746) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (2986) nvs: nvs_open_from_partition bt_config.conf 1
D (2986) nvs: nvs_get_str_or_blob bt_cfg_key0
D (2986) nvs: nvs_get_str_or_blob bt_cfg_key0
D (2996) nvs: nvs_close 14
D (2996) nvs: nvs_open_from_partition bt_config.conf 1
D (2996) nvs: nvs_set_blob bt_cfg_key0 216
D (3006) nvs: nvs_close 15
D (3096) simple_ble: created attribute table successfully, the number handle = 19
D (3096) simple_ble: Free mem at end of simple_ble_init 115188
D (3096) protocomm_ble: Waiting for client to connect ......
D (3106) simple_ble: SERVICE_START_EVT, status 0, service_handle 40
I (3116) wifi_prov_mgr: Provisioning started with service name : PROV_f795db 
D (3116) wifi_prov_mgr: execute_event_cb : 1
D (3116) event: running post WIFI_PROV_EVENT:1 with handler 0x400e2714 on loop 0x3ffd19b4
0x400e2714: event_handler at /build/esp-idf/esp-rainmaker/examples/common/app_wifi/app_wifi.c:72

I (3126) app_wifi: Provisioning started
D (3136) event: running post WIFI_PROV_EVENT:1 with handler 0x400de630 on loop 0x3ffd19b4
0x400de630: esp_rmaker_user_mapping_event_handler at /build/esp-idf/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_user_mapping.c:51

D (3146) event: running post WIFI_PROV_EVENT:1 with handler 0x400dfdc8 on loop 0x3ffd19b4
0x400dfdc8: event_handler at /build/esp-idf/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_claim.c:767

I (3146) app_wifi: Scan this QR code from the phone app for Provisioning.
                                      
  █▀▀▀▀▀█ █  ▄▄█ ▀▀▀▄▄█▀▀▀▀ █▀▀▀▀▀█   
  █ ███ █ ██▄ █▄ ▄▀▀█▀ ▀▄▄█ █ ███ █   
  █ ▀▀▀ █ ▄██ ▀▀█▀█▄█▄  █▀█ █ ▀▀▀ █   
  ▀▀▀▀▀▀▀ ▀ █▄▀ ▀ ▀▄▀ █▄▀ █ ▀▀▀▀▀▀▀   
  ▀▀▄▄▀▀▀▄  ▀ ▀ ▀█▄▀▀▀▄▀▀▄▀▄ █ ▀█▀▀   
      █▄▀█▀█▀ ▄▀ ███▀ ▀█▄▀██▀▄██▀█    
  █▀▀ ▄ ▀▀▄ ▄▀▄▄█▄█▀▄▀▀▀▀▀ ▄▀▄▀ ▄▄▀   
   ▀▀▀ ▄▀ ▄▄▀█▀▀ ▀▄█▀▄ ▄█▀▄█ ▀ █▀▀▄   
  █   ▄█▀██▄  ▀▄▄▄█▀▄▀█▀   █▀▄▀▀  ▀   
   ███▀ ▀█ ▀▄ ▄▀ ▀▀▄ ▄ ▄█▀█ ▄█▄█▀▀▄   
  ▄▀▀▄ █▀▄ █ ▀▄ ▄█▄▀█ ▄█ ▀▀▀▀ ▀ ▄█▀   
    █▀ ▀▀▀▄  █▀ ▀█▄▄ ▄ █▄▀  █▀▀▀▀▄▄   
  ▀▀ ▀▀▀▀▀█▄█ ▀▄▄▄▄██▀█▀ ▄█▀▀▀██▄▀    
  █▀▀▀▀▀█ ▄▀▄ ▄ █▀██▀  ▄█▀█ ▀ ██▀▀    
  █ ███ █ ▀▄▄▀█▄█▄█▀█▀ ▀█ ███▀█▀▄▄█   
  █ ▀▀▀ █ ▄ ▄██▀ █▀▄ ▄███▀  ▀█▀▄ ▀    
  ▀▀▀▀▀▀▀ ▀ ▀▀    ▀▀  ▀▀▀▀▀▀      ▀   
                                      

I (3356) app_wifi: If QR code is not visible, copy paste the below URL in a browser.
https://rainmaker.espressif.com/qrcode.html?data={"ver":"v1","name":"PROV_f795db","pop":"a5b9b4db","transport":"ble"}
I (3376) app_wifi: Provisioning Started. Name : PROV_f795db, POP : a5b9b4db
D (51726) simple_ble: ESP_GATTS_CONNECT_EVT, conn_id = 0
D (51726) protocomm_ble: Inside BLE connect w/ conn_id - 0
D (71286) simple_ble: ESP_GATTS_DISCONNECT_EVT, reason = 19
D (71286) protocomm_ble: Inside disconnect w/ session - 0

Then I tried to "manual" connect to ESP32 with no success. No wifi network with name Prov_?????? was found.

But! After all I picked up old Iphone 5 SE and provisioning worked well!
I was able to send WiFi credentials using QR code from screen!
It is obvious, that the issue is in android app.