wifi_set_opmode_current return true but failing?

[tablatronix]

Basic Infos

Hardware

Hardware: ESP-12?
Core Version: staging

Description

Let me know if this sounds familiar or like a known issue or something
I am having an issue with mode, I am setting mode and it returns true, but the mode does not actually change

I will try to produce a sketch, it is very odd, does anyone know how I can debug this further, from my understanding this sounds like an SDK bug (or memory bounds issue?), but maybe I am missing something or we are missing some crucial check before wifi_set_opmode_current().

I am (essentially) doing this

persistent(false);
ret = WiFi.mode(WIFI_AP_STA);
ret = WiFi.mode(WIFI_STA);
...
ret = WiFi.mode(WIFI_AP_STA);
ret TRUE
getMode() is WIFI_STA !!!!!!

which is essentially

wifi_set_opmode_current(3) == true
wifi_set_opmode_current(1) == true
wifi_set_opmode_current(3) == true
wifi_get_opmode = 1 <--- aahhhhhhhhhhhhhhh
// wifi_set_opmode_current() != wifi_get_opmode(), but returns true

lots of boom here (enableSTA, enableAP all fail catastrophically
since there is no sanity checks here, since they return true must be true,
so set config struct blows up )

Could this be a memory issue, where is this memory ?

Settings in IDE

Module: ?Generic ESP8266 Module?
Flash Size: ?4MB/1MB?
CPU Frequency: ?80Mhz?
Flash Mode: ?qio?
Flash Frequency: ?40Mhz?
Upload Using: ?OTA / SERIAL?
Reset Method: ?ck / nodemcu?

[tablatronix]

hmm so there is a delay setting mode, and I have no idea where it comes from, so its some kind of race condition, and I have no idea what causes it yet. Is there a doc that says wtf the debugging means ?
wtf is
add if1
pm close 7
wifi evt: 8 <-- this is the only difference I see in between the two

[enableAP] enabling
3
[mode] wifi_get_opmode BEFORE
1
[mode] wifi_set_opmode_current to
3
mode wifi evt: 8
: sta(2c:3a:e8:39:09:95) + softAP(2e:3a:e8:39:09:95)
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
[mode] wifi_get_opmode AFTER
3

[enableAP] enabling
3
[mode] wifi_get_opmode BEFORE
1
[mode] wifi_set_opmode_current to
3
[mode] wifi_get_opmode AFTER
1
[mode] ERROR MODE SET FAILED!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
mode : sta(2c:3a:e8:39:09:95) + softAP(2e:3a:e8:39:09:95)
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
wifi evt: 8

[tablatronix]

Ok I can repoduce it now, and it only happens the first time after loop() then works again..wierd but not in test sketch so still checking user code.

[tablatronix]

Reproduction

#include <ESP8266WiFi.h>
extern "C" {
  #include "user_interface.h"
}

const char* const modes[] PROGMEM = { "NULL", "STA", "AP", "STA+AP" };

void setup() {
  Serial.begin(115200);
  delay(1000);
  Serial.setDebugOutput(true);  
  Serial.println(F("\n Starting"));
  // Serial.println(modes[WiFi.getMode()]);
  // WiFi.printDiag(Serial);
  // WiFi.mode(WIFI_STA);
  // WiFi.setAutoConnect(true);
  // WiFi.setAutoReconnect(true);
}

void debugSoftAPConfig(){
    softap_config config;
    wifi_softap_get_config(&config);

    Serial.println(F("SoftAP Configuration"));
    Serial.println(F("-----------------------------"));
    Serial.print(F("ssid:            "));Serial.println((char *) config.ssid);
    Serial.print(F("password:        "));Serial.println((char *) config.password);
    Serial.print(F("ssid_len:        "));Serial.println(config.ssid_len);
    Serial.print(F("channel:         "));Serial.println(config.channel);
    Serial.print(F("authmode:        "));Serial.println(config.authmode);
    Serial.print(F("ssid_hidden:     "));Serial.println(config.ssid_hidden);
    Serial.print(F("max_connection:  "));Serial.println(config.max_connection);
    Serial.print(F("beacon_interval: "));Serial.println((String)config.beacon_interval + "(ms)");
    Serial.println(F("-----------------------------"));
}

void startap(){
  bool ret;
  ret = WiFi.softAP("esptestap");
  if(!ret)Serial.println(F("softAP failed BOOOM"));
  debugSoftAPConfig();

  ret = WiFi.softAPdisconnect(true);
  if(!ret)Serial.println(F("softAPdisconnect failed"));

  ret = WiFi.mode(WIFI_STA);
  if(!ret)Serial.println(F("set mode failed"));	
  delay(1000);
}

void loop(){
	startap();
	startap();
}

[tablatronix]

maybe someone can make sense of this, it seems that the second run takes much longer and is asynchronous, I also see more dhcp start than there should be , no idea what the other debugging means.

I am timing the RUN call to set opmode, and the SET of when getmode actually changed, those are the times in micros, there is a yield in there though

Logging

 Starting
RUN 1 -------------------------
[enableAP] enabling
3
[mode] wifi_get_opmode BEFORE
1
mode : sta(2c:3a:e8:39:09:95) + softAP(2e:3a:e8:39:09:95)
add if1
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
[WIFI_SET_OPMODE_CURRENT] ran in 10141
[WIFI_SET_OPMODE_CURRENT] set in 10151
[AP] mode non persistent
3
bcn 0
dewifi evt: 8
l if1
pm open,type:2 0
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
bcn 0
del if1
pm open,type:2 0
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
[enableAP] disabling
[mode] wifi_get_opmode BEFORE
3
bcn 0
del if1
pm open,type:2 0
mode : sta(2c:3a:e8:39:09:95)
[WIFI_SET_OPMODE_CURRENT] ran in 5596
[WIFI_SET_OPMODE_CURRENT] set in 5606
wifi evt: 8
RUN 2 -------------------------
[enableAP] enabling
3
[mode] wifi_get_opmode BEFORE
1
[mode] ERROR MODE SET FAILED!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
mode : sta(2c:3a:e8:39:09:95) + softAP(2e:3a:e8:39:09:95)
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
wifi evt: 8
[WIFI_SET_OPMODE_CURRENT] ran in 73
[WIFI_SET_OPMODE_CURRENT] set in 17129
[AP] mode non persistent
3
bcn 0
del if1
pm open,type:2 0
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
bcn 0
del if1
pm open,type:2 0
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
[enableAP] disabling
[mode] wifi_get_opmode BEFORE
3
bcn 0
del if1
pm open,type:2 0
mode : sta(2c:3a:e8:39:09:95)
[WIFI_SET_OPMODE_CURRENT] ran in 5566
[WIFI_SET_OPMODE_CURRENT] set in 5577
wifi evt: 8
RUN 1 -------------------------
[enableAP] enabling
3
[mode] wifi_get_opmode BEFORE
1
[mode] ERROR MODE SET FAILED!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
mode : sta(2c:3a:e8:39:09:95) + softAP(2e:3a:e8:39:09:95)
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
wifi evt: 8
[WIFI_SET_OPMODE_CURRENT] ran in 80
[WIFI_SET_OPMODE_CURRENT] set in 17011
[AP] mode non persistent
3
bcn 0
del if1
pm open,type:2 0
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
bcn 0
del if1
pm open,type:2 0
add if1
pm close 7
dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
bcn 100
[enableAP] disabling
[mode] wifi_get_opmode BEFORE
3
bcn 0
del if1
pm open,type:2 0
mode : sta(2c:3a:e8:39:09:95)
[WIFI_SET_OPMODE_CURRENT] ran in 5635
[WIFI_SET_OPMODE_CURRENT] set in 5646
wifi evt: 8

I should have messed with GDB instead and actually tried to debug this properly, oh well.

solution for now is to delay after, or while loop it shrug

dirty workaround

/**
 * set new mode
 * @param m WiFiMode_t
 */
bool ESP8266WiFiGenericClass::mode(WiFiMode_t m) {
    if(wifi_get_opmode() == (uint8) m) {
        return true;
    }

    bool ret = false;

    DEBUG_WIFI_GENERIC("[mode] wifi_get_opmode BEFORE\n");    
    DEBUG_WIFI(String(wifi_get_opmode()).c_str());
    DEBUG_WIFI_GENERIC("\n");
 
    bool testing = true;
    uint32_t mark;
    uint32_t end;
    uint32_t start = micros();
    ETS_UART_INTR_DISABLE();
    if(_persistent) {
        ret = wifi_set_opmode(m);
    } else {
        // DEBUG_WIFI_GENERIC("[mode] wifi_set_opmode_current to\n");
        // DEBUG_WIFI_GENERIC(String(m).c_str());
        // DEBUG_WIFI_GENERIC("\n");
        ret = wifi_set_opmode_current(m);
    }
    ETS_UART_INTR_ENABLE();
     mark = micros();

    if(wifi_get_opmode() != (uint8) m) {
        DEBUG_WIFI_GENERIC("[mode] ERROR MODE SET FAILED!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!\n");    
    }

    if(testing){
    while(wifi_get_opmode() != (uint8) m){
        yield();
    }
    end = micros();

    DEBUG_WIFI_GENERIC("[WIFI_SET_OPMODE_CURRENT] ran in ");
    DEBUG_WIFI_GENERIC(String(mark-start).c_str());
    DEBUG_WIFI_GENERIC("\n");
    DEBUG_WIFI_GENERIC("[WIFI_SET_OPMODE_CURRENT] set in ");
    DEBUG_WIFI_GENERIC(String(end-start).c_str());
    DEBUG_WIFI_GENERIC("\n");

    // DEBUG_WIFI_GENERIC("[mode] wifi_get_opmode AFTER\n");    
    // DEBUG_WIFI(String(wifi_get_opmode()).c_str());
    // DEBUG_WIFI_GENERIC("\n");

    }
    return ret;
}

[tablatronix]

@devyte if you could assign someone to take a glance and let me know about this, thanks.

[d-a-v]

Could you give a summary of your findings ?

[tablatronix]

SUMMARY

Race condition, wifi_set_opmode is asynchronous, returns true but get_opmode does not show change for sometime (~1s) after mode() returns, which in turn breaks things that check return value as success and does stuff like set config before its possible.

[tablatronix]

I am not entirely sure why it takes longer SOMETIMES but it might be an sdk thing. Issue contains logs and reproduction info. Someone might be able to glean more info from the hardware output above, i have no idea how to decipher that to see a pattern.

Sometimes defined as the difference between these 2 delays seems to be the factor ( includes a yield() )

good
[WIFI_SET_OPMODE_CURRENT] set in 10151

bad
[WIFI_SET_OPMODE_CURRENT] set in 17129

actual
One direct effect at least in my reproduction sketch and real world, if turning AP on and off more than once results in softap failed to start, and corrupt softap config, because enablesta, did not yet actually enable

bool ESP8266WiFiAPClass::softAP(const char* ssid, const char* passphrase, int channel, int ssid_hidden, int max_connection) {

    if(!WiFi.enableAP(true)) {
        // enable AP failed
        DEBUG_WIFI("[AP] enableAP failed!\n");
        return false;
    }

    // ruh roh NOT SO FAST!, mode still not AP here!

[d-a-v]

So the workaround to wait for opmode to be set to the real value is always working ?

I'm not saying that the workaround should be used or adopted, but if it works, that information would help debugging (here or for espressif's SDK).

[tablatronix]

It appears to be, yes
I added in mode() as above FOR TESTING of course

ESP8266WiFiGenericClass::mode()

while(wifi_get_opmode() != (uint8) m){
        yield();
    }

[tablatronix]

I am not seeing this anymore, it just takes 30-50micros now, it was 6,000+ before
although the entire operation now takes 50ms, which I guess is fine.

[WIFI_SET_OPMODE_CURRENT] ran in 55672
[WIFI_SET_OPMODE_CURRENT] set in 55702

I will close after real testing