E (57534) wifi_prov_mgr: Failed to start scan (MEGH-5122)

[PegasusFlyMe]

Answers checklist.

• I have read the Rainmaker documentation and the issue is not addressed there.
• I have updated my IDF branch (release/vX.Y) to the latest version and checked that the issue is present there. This is not applicable if you are using Rainmaker with Arduino.
• I have searched the Rainmaker forum and issue tracker for a similar issue and not found a similar issue.

General issue report

choose BLE mode ,after connect with my phone, it can not scan WiFi,i want to know how to solve it,or what should I set in idf.py menuconfig?

E (57534) wifi_prov_mgr: Failed to start scan

[shahpiyushv]

Which board and esp-idf version are you using? It would have been better to use "Runtime bug report" template to provide clearer information.

[PegasusFlyMe]

ESP32C3
version : esp-idf-v5.1.1
When I click the "Select Network" button on the phone, the serial port displays : WiFi_ Prov_ Mgr: Failed to start scan character.
When I directly use the binary files on the blog for flash, WiFi can connect normally.（https://blog.csdn.net/weixin_42880082/article/details/130449186 ）

[novflying]

rainmaker_idf_5.1.2_wifi_prov_mgr_Failed to start scan.txt
Rainmaker is mainstream, use the led_light example.
Same issue, detail log is attached. The error code returned by esp_wifi_scan_start is ESP_ERR_WIFI_NOT_STARTED .

[mphe]

Can confirm this issue still exists.
Tested with the "switch" and "led_light" example project and both fail with wifi_prov_mgr related errors.
There are no custom configurations, just the defaults.

After scanning the QR Code, there are no Wifi networks listed and the console logs wifi_prov_mgr: Failed to start scan errors. Same happens when pressing "Rescan" button.
When using the "Join other network" button and entering credentials manually, Failed to set Wi-Fi configuration and Failed to apply Wi-Fi Credentials errors are logged.

Board: ESP32-S3
ESP IDF Version: 5.2.2
ESP Rainmaker Version: Current master (8da28b0)

Also using regular build procedure:

$ cd esp-rainmaker/examples/switch/
$ idf.py set-target esp32s3
$ idf.py build
$ idf.py erase-flash
$ idf.py flash monitor

Log:

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3810,len:0x178c
load:0x403c9700,len:0x4
load:0x403c9704,len:0xcbc
load:0x403cc700,len:0x2de0
entry 0x403c9914
I (33) boot: ESP-IDF v5.2.2-dirty 2nd stage bootloader
I (33) boot: compile time Jun 19 2024 11:53:13
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v0.1
I (41) boot.esp32s3: Boot SPI Speed : 80MHz
I (45) boot.esp32s3: SPI Mode       : SLOW READ
I (51) boot.esp32s3: SPI Flash Size : 4MB
I (55) boot: Enabling RNG early entropy source...
I (61) boot: Partition Table:
I (64) boot: ## Label            Usage          Type ST Offset   Length
I (72) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (79) boot:  1 nvs_key          NVS keys         01 04 0000f000 00001000
I (87) boot:  2 nvs              WiFi data        01 02 00010000 00006000
I (94) boot:  3 otadata          OTA data         01 00 00016000 00002000
I (102) boot:  4 phy_init         RF data          01 01 00018000 00001000
I (109) boot:  5 ota_0            OTA app          00 10 00020000 00190000
I (117) boot:  6 ota_1            OTA app          00 11 001b0000 00190000
I (124) boot:  7 fctry            WiFi data        01 02 00340000 00006000
I (132) boot: End of partition table
I (136) boot: No factory image, trying OTA 0
I (141) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=4cfd0h (315344) map
I (224) esp_image: segment 1: paddr=0006cff8 vaddr=3fc9e100 size=03020h ( 12320) load
I (228) esp_image: segment 2: paddr=00070020 vaddr=42000020 size=fe000h (1040384) map
I (477) esp_image: segment 3: paddr=0016e028 vaddr=3fca1120 size=02054h (  8276) load
I (480) esp_image: segment 4: paddr=00170084 vaddr=40374000 size=1a06ch (106604) load
I (523) boot: Loaded app from partition at offset 0x20000
I (549) boot: Set actual ota_seq=1 in otadata[0]
I (549) boot: Disabling RNG early entropy source...
I (560) cpu_start: Multicore app
I (569) cpu_start: Pro cpu start user code
I (569) cpu_start: cpu freq: 160000000 Hz
I (569) cpu_start: Application information:
I (572) cpu_start: Project name:     switch
I (577) cpu_start: App version:      1.0
I (582) cpu_start: Compile time:     Jun 19 2024 11:53:15
I (588) cpu_start: ELF file SHA256:  19961a3bb...
I (593) cpu_start: ESP-IDF:          v5.2.2-dirty
I (599) cpu_start: Min chip rev:     v0.0
I (603) cpu_start: Max chip rev:     v0.99
I (608) cpu_start: Chip rev:         v0.1
I (613) heap_init: Initializing. RAM available for dynamic allocation:
I (620) heap_init: At 3FCA9B70 len 0003FBA0 (254 KiB): RAM
I (626) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (632) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (638) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
W (645) spi_flash: Octal flash chip is using but dio mode is selected, will automatically swich to Octal mode
I (655) spi_flash: detected chip: mxic (opi)
I (660) spi_flash: flash io: opi_str
W (664) spi_flash: Detected size(32768k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
W (678) rmt(legacy): legacy driver is deprecated, please migrate to `driver/rmt_tx.h` and/or `driver/rmt_rx.h`
I (688) sleep: Configure to isolate all GPIO pins in sleep state
I (695) sleep: Enable automatic switching of GPIO sleep configuration
I (702) coexist: coex firmware version: d96c1e51f
I (708) coexist: coexist rom version e7ae62f
I (713) main_task: Started on CPU0
I (723) main_task: Calling app_main()
I (723) esp_rmaker_console: Initialising UART on port 0
I (723) uart: queue free spaces: 8
I (733) esp_rmaker_commands: Registering command: reboot
I (733) esp_rmaker_commands: Registering command: up-time
I (743) esp_rmaker_commands: Registering command: mem-dump
I (753) esp_rmaker_commands: Registering command: task-dump
I (753) esp_rmaker_commands: Registering command: cpu-dump
I (763) esp_rmaker_commands: Registering command: sock-dump
I (763) esp_rmaker_commands: Registering command: heap-trace
I (773) esp_rmaker_commands: Registering command: reset-to-factory
I (783) esp_rmaker_commands: Registering command: local-time
I (783) esp_rmaker_commands: Registering command: tz-set
I (793) esp_rmaker_commands: Registering command: add-user
I (803) esp_rmaker_commands: Registering command: get-node-id
I (803) esp_rmaker_commands: Registering command: wifi-prov
I (813) esp_rmaker_commands: Registering command: cmd
I (823) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
I (823) gpio: GPIO[19]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (863) pp: pp rom version: e7ae62f
I (863) net80211: net80211 rom version: e7ae62f
I (873) wifi:wifi driver task: 3fcb6cac, prio:23, stack:6656, core=0
I (873) wifi:wifi firmware version: 3e0076f
I (873) wifi:wifi certification version: v7.0
I (873) wifi:config NVS flash: enabled
I (873) wifi:config nano formating: disabled
I (883) wifi:Init data frame dynamic rx buffer num: 32
I (883) wifi:Init static rx mgmt buffer num: 5
I (893) wifi:Init management short buffer num: 32
I (893) wifi:Init dynamic tx buffer num: 32
I (903) wifi:Init static tx FG buffer num: 2
I (903) wifi:Init static rx buffer size: 1600
I (903) wifi:Init static rx buffer num: 10
I (913) wifi:Init dynamic rx buffer num: 32
I (913) wifi_init: rx ba win: 6
I (923) wifi_init: tcpip mbox: 32
I (923) wifi_init: udp mbox: 6
I (923) wifi_init: tcp mbox: 6
I (933) wifi_init: tcp tx win: 5760
I (933) wifi_init: tcp rx win: 5760
I (943) wifi_init: tcp mss: 1440
I (943) wifi_init: WiFi IRAM OP enabled
I (943) wifi_init: WiFi RX IRAM OP enabled
I (963) esp_rmaker_work_queue: Work Queue created.
I (973) esp_claim: Initialising Self Claiming. This may take time.
I (1273) esp_claim: Private key already exists. No need to re-initialise it.
I (2123) app_main: RainMaker Initialised.
I (2123) esp_rmaker_node: Node ID ----- 348518A13F68
I (2123) esp_rmaker_ota_using_topics: OTA enabled with Topics
I (2123) esp_rmaker_ota: OTA state = 2
I (2133) esp_rmaker_time: Initializing SNTP. Using the SNTP server: pool.ntp.org
I (2143) esp_rmaker_time_service: Time service enabled
I (2143) esp_rmaker_time: SNTP already initialized.
I (2153) app_insights: Enable CONFIG_ESP_INSIGHTS_ENABLED to get Insights.
I (2153) esp_rmaker_core: Starting RainMaker Work Queue task
I (2163) esp_rmaker_work_queue: RainMaker Work Queue task started.
I (2173) tag: 0x3fcc0fd4   e5 02 4e 6f 76 61 00 01  00 80 01 00              |..Nova......|
I (2183) wifi_prov_scheme_ble: BT memory released
I (2183) app_wifi: Starting provisioning
I (2193) BLE_INIT: BT controller compile version [c23ab4c]
I (2193) BLE_INIT: Bluetooth MAC: 34:85:18:a1:3f:6a
I (2203) phy_init: phy_version 670,b7bc9b9,Apr 30 2024,10:54:13
I (2243) protocomm_nimble: BLE Host Task Started
I (2253) NimBLE: GAP procedure initiated: stop advertising.

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

I (2273) wifi_prov_mgr: Provisioning started with service name : PROV_fc0760
I (2273) app_wifi: Provisioning started
I (2283) esp_rmaker_local: Event 1
I (2283) app_wifi: Scan this QR code from the ESP RainMaker phone app for Provisioning.

[QR code here]


I (2493) app_wifi: If QR code is not visible, copy paste the below URL in a browser.
[URL here]
I (2503) app_main: Provisioning QR : [Json here]
I (2513) app_wifi: Provisioning Started. Name : [Name here], POP : [POP here]
I (2523) app_wifi: Provisioning will auto stop after 30 minute(s).
I (17923) protocomm_nimble: mtu update event; conn_handle=1 cid=4 mtu=256
I (19073) app_wifi: Secured session established!
E (19253) wifi_prov_mgr: Failed to start scan
E (27213) wifi_prov_mgr: Failed to start scan
I (40133) esp_rmaker_user_mapping: Received request for node details
I (40133) esp_rmaker_user_mapping: Got user_id = [user id here], secret_key = [secret key here]
I (40143) esp_rmaker_user_mapping: User Node mapping reset detected.
I (40143) esp_rmaker_user_mapping: Sending status SUCCESS
E (40493) wifi_prov_mgr: Failed to set Wi-Fi configuration
E (40493) wifi_prov_handlers: Failed to apply Wi-Fi Credentials

[sfeutrier]

Hello! Is there any update or workaround?
I have exactly this issue with ESP-IDF 5.2.2 and ESP32C3

Update: the "Failed to start scan" event comes from an error of 0x3002 which means "ESP_ERR_WIFI_NOT_STARTED". So it seems WiFi has just never been started. I'm still investigating though

[mphe]

It works with ESP-IDF 5.2 and 5.2.1, so the problem appeared somewhere in 5.2.2.

[sfeutrier]

Here is my problem: espressif/esp-mesh-lite#129. The version of ESP-IDF downloaded is not the tagged v5.2.2 (in fact it is but with some files with changes). I don't know if it applies for rainmaker though

[shahpiyushv]

With the led_light example on esp32c3, using idf v5.2.2 worked fine for me. Does the wifi_prov_mgr example work for you with the exact same idf and board?

[mphe]

The wifi_prov_mgr example fails with the same error on 5.2.2 but works with 5.2.1.
So I guess this is an ESP-IDF bug, not a RainMaker bug.

[shahpiyushv]

@mphe , can you share your sdkconfig for wifi_prov_mgr example?

[mphe]

sdkconfig_5.2.1.txt
sdkconfig_5.2.2.txt

[sfeutrier]

@mphe if you look at your esp-idf v5.2.2 folder with a GIT interface, do you have local changes on some files?

[mphe]

Yes, there are some modified files.
Here is a git status and git diff: diff.txt

[sfeutrier]

@mphe you have the same issue I had. You are on the tagged v5.2.2 branch but there are additional changes on wifi_prov_mgmr and dhcp.
Revert all your local change and it will work!

[mphe]

Thanks, I will try on Monday and report back.

[mphe]

Indeed it works fine with latest master. Thanks!

[robocircuits]

I have v5.3 and i have the same issue.
E (18968) wifi_prov_mgr: Failed to start scan