[TW#15357] WPS always gets Timed Out at 2 minutes / 120000 ms

[Raienryu97]

Board : ESP32 Dev Module

Latest Local Commit : 050ae50

Issue:

Setting timeout_ms parameter in esp_err_t esp_wifi_wps_start(int timeout_ms); does not make a difference, ESP times out only at 120000ms or 2 minutes
I have tried changing timeout_ms to 1/2/1000/5000 and all of them still timeout only after 2 minutes including 0 too.
I am not sure if it is a bug or if I'm doing something wrong in the code. I've just edited the inbuilt example and changed only the timeout_ms parameter.

Here is my serial log. You can observe that the timeout happens at 120506 ms and the event loop starts at 496 ms , timeout happens after 120000 ms instead of the coded 5000 ms

--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
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:0x3fff0010,len:4
load:0x3fff0014,len:5380
load:0x40078000,len:0
load:0x40078000,len:12136
entry 0x40078f60
I (44) boot: ESP-IDF v3.0-dev-606-g050ae50-dirty 2nd stage bootloader
I (44) boot: compile time 13:47:17
I (48) boot: Enabling RNG early entropy source...
I (65) boot: SPI Speed      : 40MHz
I (77) boot: SPI Mode       : DIO
I (90) boot: SPI Flash Size : 4MB
I (102) boot: Partition Table:
I (113) boot: ## Label            Usage          Type ST Offset   Length
I (136) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (159) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (183) boot:  2 factory          factory app      00 00 00010000 00100000
I (206) boot: End of partition table
I (219) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x0f630 ( 63024) map
I (314) esp_image: segment 1: paddr=0x0001f658 vaddr=0x3ffb0000 size=0x009b8 (  2488) load
I (318) esp_image: segment 2: paddr=0x00020018 vaddr=0x400d0018 size=0x4f114 (323860) map
0x400d0018: _flash_cache_start at ??:?

I (679) esp_image: segment 3: paddr=0x0006f134 vaddr=0x3ffb09b8 size=0x026c8 (  9928) load
I (692) esp_image: segment 4: paddr=0x00071804 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /home/pranav/esp/esp-idf/components/freertos/./xtensa_vectors.S:1675

I (701) esp_image: segment 5: paddr=0x00071c0c vaddr=0x40080400 size=0x0f110 ( 61712) load
I (806) esp_image: segment 6: paddr=0x00080d24 vaddr=0x400c0000 size=0x00000 (     0) load
I (835) boot: Loaded app from partition at offset 0x10000
I (835) boot: Disabling RNG early entropy source...
I (842) cpu_start: Pro cpu up.
I (853) cpu_start: Starting app cpu, entry point is 0x40080ea0
0x40080ea0: call_start_cpu1 at /home/pranav/esp/esp-idf/components/esp32/./cpu_start.c:219

I (0) cpu_start: App cpu up.
I (886) heap_init: Initializing. RAM available for dynamic allocation:
I (906) heap_init: At 3FFAE2A0 len 00001D60 (7 KiB): DRAM
I (925) heap_init: At 3FFB8048 len 00027FB8 (159 KiB): DRAM
I (944) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (964) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (983) heap_init: At 4008F510 len 00010AF0 (66 KiB): IRAM
I (1002) cpu_start: Pro cpu start user code
I (1063) cpu_start: Starting scheduler on PRO CPU.
I (196) cpu_start: Starting scheduler on APP CPU.
I (256) wifi: wifi firmware version: 4acbf1f
I (256) wifi: config NVS flash: enabled
I (256) wifi: config nano formating: disabled
I (256) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (266) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (286) wifi: Init dynamic tx buffer num: 32
I (286) wifi: Init data frame dynamic rx buffer num: 32
I (296) wifi: Init management frame dynamic rx buffer num: 32
I (296) wifi: wifi driver task: 3ffbf1b4, prio:23, stack:4096
I (296) wifi: Init static rx buffer num: 10
I (306) wifi: Init dynamic rx buffer num: 32
I (306) wifi: Init rx ampdu len mblock:7
I (316) wifi: Init lldesc rx ampdu entry mblock:4
I (316) wifi: wifi power manager task: 0x3ffc4518 prio: 21 stack: 2560
W (326) phy_init: failed to load RF calibration data (0xffffffff), falling back to full calibration
I (486) phy: phy_version: 359.0, e79c19d, Aug 31 2017, 17:06:07, 0, 2
I (496) wifi: mode : sta (24:0a:c4:80:55:5c)
I (496) example_wps: start wps...
I (496) wpa: wifi_wps_enable

I (496) example_wps: SYSTEM_EVENT_STA_START
I (1806) example_wps: Is it blocking?
I (120506) example_wps: SYSTEM_EVENT_STA_WPS_ER_TIMEOUT
I (120506) wpa: wifi_wps_disable

Code:

/* WiFi Connection Example using WPS

   This example code is in the Public Domain (or CC0 licensed, at your option.)

   Unless required by applicable law or agreed to in writing, this
   software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
   CONDITIONS OF ANY KIND, either express or implied.
*/

/*
   Showing how to use WPS.

   WPS_TYPE_PBC: Start esp32 and it will enter wps PBC mode. Then push the button of wps on router down. The esp32 will connected to the router.
   WPS_TYPE_PIN: Start esp32, You'll see PIN code which is a eight-digit number showing on COM. Enter the PIN code in router and then the esp32 will connected to router.
*/

#include "freertos/FreeRTOS.h"
#include "freertos/event_groups.h"
#include "esp_wifi.h"
#include "esp_log.h"
#include "esp_wps.h"
#include "esp_event_loop.h"
#include "nvs_flash.h"


/*set wps mode via "make menuconfig"*/
#if CONFIG_EXAMPLE_WPS_TYPE_PBC
#define WPS_TEST_MODE WPS_TYPE_PBC
#elif CONFIG_EXAMPLE_WPS_TYPE_PIN
#define WPS_TEST_MODE WPS_TYPE_PIN
#else
#define WPS_TEST_MODE WPS_TYPE_DISABLE
#endif /*CONFIG_EXAMPLE_WPS_TYPE_PBC*/


#ifndef PIN2STR
#define PIN2STR(a) (a)[0], (a)[1], (a)[2], (a)[3], (a)[4], (a)[5], (a)[6], (a)[7]
#define PINSTR "%c%c%c%c%c%c%c%c"
#endif


static const char *TAG = "example_wps";
static esp_wps_config_t config = WPS_CONFIG_INIT_DEFAULT(WPS_TEST_MODE);

static esp_err_t event_handler(void *ctx, system_event_t *event)
{
    switch(event->event_id) {
    case SYSTEM_EVENT_STA_START:
	ESP_LOGI(TAG, "SYSTEM_EVENT_STA_START");
        break;
    case SYSTEM_EVENT_STA_GOT_IP:
	ESP_LOGI(TAG, "SYSTEM_EVENT_STA_GOT_IP");
	ESP_LOGI(TAG, "got ip:%s\n",
		ip4addr_ntoa(&event->event_info.got_ip.ip_info.ip));
        break;
    case SYSTEM_EVENT_STA_DISCONNECTED:
	ESP_LOGI(TAG, "SYSTEM_EVENT_STA_DISCONNECTED");
	ESP_ERROR_CHECK(esp_wifi_connect());
        break;
    case SYSTEM_EVENT_STA_WPS_ER_SUCCESS:
	/*point: the function esp_wifi_wps_start() only get ssid & password
	 * so call the function esp_wifi_connect() here
	 * */
	ESP_LOGI(TAG, "SYSTEM_EVENT_STA_WPS_ER_SUCCESS");
	ESP_ERROR_CHECK(esp_wifi_wps_disable());
	ESP_ERROR_CHECK(esp_wifi_connect());
	break;
    case SYSTEM_EVENT_STA_WPS_ER_FAILED:
	ESP_LOGI(TAG, "SYSTEM_EVENT_STA_WPS_ER_FAILED");
	ESP_ERROR_CHECK(esp_wifi_wps_disable());
	ESP_ERROR_CHECK(esp_wifi_wps_enable(&config));
	ESP_ERROR_CHECK(esp_wifi_wps_start(5000));
	break;
    case SYSTEM_EVENT_STA_WPS_ER_TIMEOUT:
	ESP_LOGI(TAG, "SYSTEM_EVENT_STA_WPS_ER_TIMEOUT");
	ESP_ERROR_CHECK(esp_wifi_wps_disable());
	ESP_ERROR_CHECK(esp_wifi_wps_enable(&config));
	ESP_ERROR_CHECK(esp_wifi_wps_start(5000));
 	break;
    case SYSTEM_EVENT_STA_WPS_ER_PIN:
	ESP_LOGI(TAG, "SYSTEM_EVENT_STA_WPS_ER_PIN");
	/*show the PIN code here*/
	ESP_LOGI(TAG, "WPS_PIN = "PINSTR, PIN2STR(event->event_info.sta_er_pin.pin_code));
	break;
    default:
        break;
    }
    return ESP_OK;
}

/*init wifi as sta and start wps*/
static void start_wps(void)
{
    tcpip_adapter_init();
    ESP_ERROR_CHECK(esp_event_loop_init(event_handler, NULL));

    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    
    ESP_ERROR_CHECK(esp_wifi_init(&cfg));
    
    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));
    ESP_ERROR_CHECK(esp_wifi_start());
    
    ESP_LOGI(TAG, "start wps...");
    
       
    ESP_ERROR_CHECK(esp_wifi_wps_enable(&config));
    ESP_ERROR_CHECK(esp_wifi_wps_start(5000));
    ESP_LOGI(TAG, "Is it blocking?");
}

void app_main()
{
    /* 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) {
        ESP_ERROR_CHECK(nvs_flash_erase());
        ret = nvs_flash_init();
    }
    ESP_ERROR_CHECK( ret );

    start_wps();
}

Also I dont think the code is actually blocking since wps started at 496th ms and the next ESP_LOGI line of code got executed at 1806th ms
Please let me know if there is any additional configuration required or if this is a bug in the WPS

Thank You

[XinDeng11]

Hi Raienryu97, the time 2 minutes is ruled by protocol, used to check whether WPS progress can finish in 2 minutes, and we have set it in the firmware, it can't be changed, I am not sure whether my answer can be satisfied with you.
Thank you.

[Raienryu97]

@XinDeng11 , In this function

/**
  * @brief     WPS starts to work.
  *
  * @attention WPS can only be used when ESP32 station is enabled.
  *
  * @param     timeout_ms : maximum blocking time before API return.
  *          - 0 : non-blocking
  *          - 1~120000 : blocking time (not supported in IDF v1.0)
  *
  * @return    
  *          - ESP_OK : succeed
  *          - ESP_ERR_WIFI_WPS_TYPE : wps type is invalid
  *          - ESP_ERR_WIFI_WPS_MODE : wifi is not in station mode or sniffer mode is on
  *          - ESP_ERR_WIFI_WPS_SM : wps state machine is not initialized
  *          - ESP_ERR_WIFI_FAIL : wps initialization fails
  */
esp_err_t esp_wifi_wps_start(int timeout_ms);

taken from here , what does the blocking timeout represent then?
I wanted to know if we could set timeout to lower value or something like that. What is the significance of the blocking timeout?

Thanks for the response :)

[XinDeng11]

@Raienryu97 Hi, this parameter is use to block the API until timeout, it is another time different with 2 minutes , and the feature will add in the future, we are on plan, thanks.