Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Incoherent WiFiEvent() calls #3006

Closed
jjmonteiro opened this issue Jul 18, 2019 · 8 comments
Closed

Incoherent WiFiEvent() calls #3006

jjmonteiro opened this issue Jul 18, 2019 · 8 comments
Labels
Status: Stale Issue is stale stage (outdated/stuck)

Comments

@jjmonteiro
Copy link

jjmonteiro commented Jul 18, 2019

Hardware:

Board: ESP32 Dev Module
Core Installation version: ?1.0.0
IDE name: Arduino IDE
--------------------------
Chip Rev: 1
Sdk Ver : v3.2-111-g524308c98
Cpu Freq: 240
Cycles  : 11074815
--------------------------
Heap Size  : 342420
Free Heap  : 316340
SPIRam Size: 0
SPIRam Free: 0
Flash Mode : 2
Flash Size : 4194304
Flash Speed: 80000000
--------------------------
Computer OS: Windows 10

Description:

Calls to WiFiEvent(WiFiEvent_t event) are not making sense

Sketch: (leave the backquotes for [code formatting]

#include <WiFi.h>


void WiFiEvent(WiFiEvent_t event) {

    switch (event) {

    case SYSTEM_EVENT_WIFI_READY:
        Serial.println("SYSTEM_EVENT_WIFI_READY");
        break;

    case SYSTEM_EVENT_SCAN_DONE:
        Serial.println("SYSTEM_EVENT_SCAN_DONE");
        break;

    case SYSTEM_EVENT_STA_START:
        Serial.println("SYSTEM_EVENT_STA_START");
        break;

    case SYSTEM_EVENT_STA_STOP:
        Serial.println("SYSTEM_EVENT_STA_STOP");
        break;

    case SYSTEM_EVENT_STA_CONNECTED://or STARTED ?
        Serial.println("SYSTEM_EVENT_STA_CONNECTED");
        break;

    case SYSTEM_EVENT_STA_DISCONNECTED:
        Serial.println("SYSTEM_EVENT_STA_DISCONNECTED");
        break;

    case SYSTEM_EVENT_STA_AUTHMODE_CHANGE:
        Serial.println("SYSTEM_EVENT_STA_AUTHMODE_CHANGE");
        break;

    case SYSTEM_EVENT_STA_GOT_IP:
        Serial.println("SYSTEM_EVENT_STA_GOT_IP");
        break;

    case SYSTEM_EVENT_STA_LOST_IP:
        Serial.println("SYSTEM_EVENT_STA_LOST_IP");
        break;

    case SYSTEM_EVENT_AP_START:
        Serial.println("SYSTEM_EVENT_AP_START");
        break;

    case SYSTEM_EVENT_AP_STOP:
        Serial.println("SYSTEM_EVENT_AP_STOP");
        break;

    case SYSTEM_EVENT_AP_STACONNECTED:
        Serial.println("SYSTEM_EVENT_AP_STACONNECTED");
        break;

    case SYSTEM_EVENT_AP_STADISCONNECTED:
        Serial.println("SYSTEM_EVENT_AP_STADISCONNECTED");
        break;

    case SYSTEM_EVENT_AP_STAIPASSIGNED:
        Serial.println("SYSTEM_EVENT_AP_STAIPASSIGNED");
        break;

    case SYSTEM_EVENT_AP_PROBEREQRECVED:
        Serial.println("SYSTEM_EVENT_AP_PROBEREQRECVED");
        break;

    default:
        Serial.println("UNKNOWN EVENT: " + event);
        break;
    }
}

void setup() {
  Serial.begin(115200);
  WiFi.onEvent(WiFiEvent);

  
  //select test nr 1-3
  switch(1){
    case 1:
      WiFi.mode(WIFI_MODE_AP);
      break;
    
    case 2:
      WiFi.mode(WIFI_MODE_STA);
      WiFi.begin();
      break;

    case 3:
      WiFi.mode(WIFI_MODE_APSTA);
      WiFi.begin();
      break;
  }

}

void loop() {}

Debug Messages:

test#1
AP_START without WiFi.softAP() call?
Misfires: WIFI_READY (sometimes)
output:

[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
SYSTEM_EVENT_WIFI_READY
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 13 - AP_START

sometimes: (after using WiFi.softAP)

[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 13 - AP_START
SYSTEM_EVENT_AP_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 13 - AP_START

test#2
STA_CONNECTED before getting an IP?
Misfires: STA_GOT_IP
output:

[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
SYSTEM_EVENT_STA_START
SYSTEM_EVENT_WIFI_READY
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 4 - STA_CONNECTED
SYSTEM_EVENT_STA_CONNECTED
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 7 - STA_GOT_IP
[D][WiFiGeneric.cpp:379] _eventCallback(): STA IP: 192.168.1.150, MASK: 255.255.255.0, GW: 192.168.1.1

test#3
Why two AP_START calls?
Misfires: WIFI_READY and STA_GOT_IP
output:

[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 13 - AP_START
SYSTEM_EVENT_AP_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 13 - AP_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 4 - STA_CONNECTED
SYSTEM_EVENT_STA_CONNECTED
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 7 - STA_GOT_IP
[D][WiFiGeneric.cpp:379] _eventCallback(): STA IP: 192.168.1.150, MASK: 255.255.255.0, GW: 192.168.1.1
@stickbreaker
Copy link
Contributor

@jjmonteiro These are debug output, you have yourCORE DEBUG LEVELset to Either DEBUG or VERBOSE. They are conditional if you only want to see your own debug line, reduce the CORE DEBUG LEVEL below DEBUG, i.e. INFO, WARNING, ERROR, or NONE.

[D][WiFiGeneric.cpp:336]

This one says it is a LOG_D() at line 336 of WiFiGeneric.cpp.

Chuck.

@jjmonteiro
Copy link
Author

jjmonteiro commented Jul 19, 2019

@stickbreaker yes, I intentionally enabled CORE DEBUG LEVEL: DEBUG for comparison.
Some internal events are not passed forward to the application, I believe, thus not being triggered under WiFi.onEvent(WiFiEvent);

@edoardoo
Copy link
Contributor

edoardoo commented Aug 8, 2019

Hi,
I think we are experiencing the same issue.

Hardware

ESP32 240MHz, 320KB RAM, 4MB Flash

Description

Using:

  • platform.io
  • esp32dev
  • framework-arduinoespressif32 2.10002.190628 (1.0.2)

The SYSTEM_EVENT_STA_DISCONNECTED event is never fired.

Sketch

Using this sketch, which, correct me if I'm wrong, should be the wifi events example:

/*
 *  This sketch shows the WiFi event usage
 *
*/

/*
* WiFi Events

0  SYSTEM_EVENT_WIFI_READY               < ESP32 WiFi ready
1  SYSTEM_EVENT_SCAN_DONE                < ESP32 finish scanning AP
2  SYSTEM_EVENT_STA_START                < ESP32 station start
3  SYSTEM_EVENT_STA_STOP                 < ESP32 station stop
4  SYSTEM_EVENT_STA_CONNECTED            < ESP32 station connected to AP
5  SYSTEM_EVENT_STA_DISCONNECTED         < ESP32 station disconnected from AP
6  SYSTEM_EVENT_STA_AUTHMODE_CHANGE      < the auth mode of AP connected by ESP32 station changed
7  SYSTEM_EVENT_STA_GOT_IP               < ESP32 station got IP from connected AP
8  SYSTEM_EVENT_STA_LOST_IP              < ESP32 station lost IP and the IP is reset to 0
9  SYSTEM_EVENT_STA_WPS_ER_SUCCESS       < ESP32 station wps succeeds in enrollee mode
10 SYSTEM_EVENT_STA_WPS_ER_FAILED        < ESP32 station wps fails in enrollee mode
11 SYSTEM_EVENT_STA_WPS_ER_TIMEOUT       < ESP32 station wps timeout in enrollee mode
12 SYSTEM_EVENT_STA_WPS_ER_PIN           < ESP32 station wps pin code in enrollee mode
13 SYSTEM_EVENT_AP_START                 < ESP32 soft-AP start
14 SYSTEM_EVENT_AP_STOP                  < ESP32 soft-AP stop
15 SYSTEM_EVENT_AP_STACONNECTED          < a station connected to ESP32 soft-AP
16 SYSTEM_EVENT_AP_STADISCONNECTED       < a station disconnected from ESP32 soft-AP
17 SYSTEM_EVENT_AP_STAIPASSIGNED         < ESP32 soft-AP assign an IP to a connected station
18 SYSTEM_EVENT_AP_PROBEREQRECVED        < Receive probe request packet in soft-AP interface
19 SYSTEM_EVENT_GOT_IP6                  < ESP32 station or ap or ethernet interface v6IP addr is preferred
20 SYSTEM_EVENT_ETH_START                < ESP32 ethernet start
21 SYSTEM_EVENT_ETH_STOP                 < ESP32 ethernet stop
22 SYSTEM_EVENT_ETH_CONNECTED            < ESP32 ethernet phy link up
23 SYSTEM_EVENT_ETH_DISCONNECTED         < ESP32 ethernet phy link down
24 SYSTEM_EVENT_ETH_GOT_IP               < ESP32 ethernet got IP from connected AP
25 SYSTEM_EVENT_MAX
*/

#include <WiFi.h>

const char* ssid     = "superWifi";
const char* password = "superPassword";


void WiFiEvent(WiFiEvent_t event)
{
    Serial.printf("[WiFi-event] event: %d\n", event);

    switch (event) {
        case SYSTEM_EVENT_WIFI_READY: 
            Serial.println("WiFi interface ready");
            break;
        case SYSTEM_EVENT_SCAN_DONE:
            Serial.println("Completed scan for access points");
            break;
        case SYSTEM_EVENT_STA_START:
            Serial.println("WiFi client started");
            break;
        case SYSTEM_EVENT_STA_STOP:
            Serial.println("WiFi clients stopped");
            break;
        case SYSTEM_EVENT_STA_CONNECTED:
            Serial.println("Connected to access point");
            break;
        case SYSTEM_EVENT_STA_DISCONNECTED:
            Serial.println("Disconnected from WiFi access point");
            break;
        case SYSTEM_EVENT_STA_AUTHMODE_CHANGE:
            Serial.println("Authentication mode of access point has changed");
            break;
        case SYSTEM_EVENT_STA_GOT_IP:
            Serial.print("Obtained IP address: ");
            Serial.println(WiFi.localIP());
            break;
        case SYSTEM_EVENT_STA_LOST_IP:
            Serial.println("Lost IP address and IP address is reset to 0");
            break;
        case SYSTEM_EVENT_STA_WPS_ER_SUCCESS:
            Serial.println("WiFi Protected Setup (WPS): succeeded in enrollee mode");
            break;
        case SYSTEM_EVENT_STA_WPS_ER_FAILED:
            Serial.println("WiFi Protected Setup (WPS): failed in enrollee mode");
            break;
        case SYSTEM_EVENT_STA_WPS_ER_TIMEOUT:
            Serial.println("WiFi Protected Setup (WPS): timeout in enrollee mode");
            break;
        case SYSTEM_EVENT_STA_WPS_ER_PIN:
            Serial.println("WiFi Protected Setup (WPS): pin code in enrollee mode");
            break;
        case SYSTEM_EVENT_AP_START:
            Serial.println("WiFi access point started");
            break;
        case SYSTEM_EVENT_AP_STOP:
            Serial.println("WiFi access point  stopped");
            break;
        case SYSTEM_EVENT_AP_STACONNECTED:
            Serial.println("Client connected");
            break;
        case SYSTEM_EVENT_AP_STADISCONNECTED:
            Serial.println("Client disconnected");
            break;
        case SYSTEM_EVENT_AP_STAIPASSIGNED:
            Serial.println("Assigned IP address to client");
            break;
        case SYSTEM_EVENT_AP_PROBEREQRECVED:
            Serial.println("Received probe request");
            break;
        case SYSTEM_EVENT_GOT_IP6:
            Serial.println("IPv6 is preferred");
            break;
        case SYSTEM_EVENT_ETH_START:
            Serial.println("Ethernet started");
            break;
        case SYSTEM_EVENT_ETH_STOP:
            Serial.println("Ethernet stopped");
            break;
        case SYSTEM_EVENT_ETH_CONNECTED:
            Serial.println("Ethernet connected");
            break;
        case SYSTEM_EVENT_ETH_DISCONNECTED:
            Serial.println("Ethernet disconnected");
            break;
        case SYSTEM_EVENT_ETH_GOT_IP:
            Serial.println("Obtained IP address");
            break;
    }}

void WiFiGotIP(WiFiEvent_t event, WiFiEventInfo_t info)
{
    Serial.println("WiFi connected");
    Serial.println("IP address: ");
    Serial.println(IPAddress(info.got_ip.ip_info.ip.addr));
}

void setup()
{
    Serial.begin(57600);

    // delete old config
    WiFi.disconnect(true);

    delay(1000);

    // Examples of different ways to register wifi events
    WiFi.onEvent(WiFiEvent);
    WiFi.onEvent(WiFiGotIP, WiFiEvent_t::SYSTEM_EVENT_STA_GOT_IP);
    WiFiEventId_t eventID = WiFi.onEvent([](WiFiEvent_t event, WiFiEventInfo_t info){
        Serial.print("WiFi lost connection. Reason: ");
        Serial.println(info.disconnected.reason);
    }, WiFiEvent_t::SYSTEM_EVENT_STA_DISCONNECTED);

    // Remove WiFi event
    Serial.print("WiFi Event ID: ");
    Serial.println(eventID);
    // WiFi.removeEvent(eventID);

    WiFi.begin(ssid, password);

    Serial.println();
    Serial.println();
    Serial.println("Wait for WiFi... ");
}

void loop()
{
    delay(1000);
}

I got this output in the console:

WiFi client started
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 5 - STA_DISCONNECTED
[W][WiFiGeneric.cpp:351] _eventCallback(): Reason: 201 - NO_AP_FOUND
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
[WiFi-event] event: 2
WiFi client started
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 5 - STA_DISCONNECTED
[W][WiFiGeneric.cpp:351] _eventCallback(): Reason: 201 - NO_AP_FOUND
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
[WiFi-event] event: 2
WiFi client started
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 5 - STA_DISCONNECTED
[W][WiFiGeneric.cpp:351] _eventCallback(): Reason: 201 - NO_AP_FOUND
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
[WiFi-event] event: 2
WiFi client started
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 5 - STA_DISCONNECTED
[W][WiFiGeneric.cpp:351] _eventCallback(): Reason: 201 - NO_AP_FOUND
[D][WiFiGeneric.cpp:336] _eventCallback(): Event: 0 - WIFI_READY
[WiFi-event] event: 2

As you can see WiFi.onEvent() with event 5 is never called.

@CircuitSetup
Copy link

As you can see WiFi.onEvent() with event 5 is never called.

Curious if you ever figured anything out with this? It seems like the library has everything in place to actually trigger the eventCallback, but it's not. Maybe this is because something else is triggered first - I'm not sure.

@edoardoo
Copy link
Contributor

I've attached the ESP-WROOM-KIT and debugged the WiFiGeneric.cpp file with JTAG and Platform.io (just in case someone else need to debug this library).

Basically _eventCallback() gets called twice when the device disconnects, following this flow:

  • _eventCallback() with SYSTEM_EVENT_STA_DISCONNECTED
    • WiFi.disconnect(true)
    • WiFi.begin()
    • _eventCallback() with SYSTEM_EVENT_WIFI_READY
    • SYSTEM_EVENT_WIFI_READY gets propagated and function returns
  • void: the execution should return to the first _eventCallback() to propagate the SYSTEM_EVENT_STA_DISCONNECTED event but this never happens.

I've tracked down the bug to:

...
 } else if(event->event_id == SYSTEM_EVENT_STA_DISCONNECTED) {
        uint8_t reason = event->event_info.disconnected.reason;
        log_w("Reason: %u - %s", reason, reason2str(reason));
        ...
        if(((reason == WIFI_REASON_AUTH_EXPIRE) ||
            (reason >= WIFI_REASON_BEACON_TIMEOUT && reason != WIFI_REASON_AUTH_FAIL)) &&
            WiFi.getAutoReconnect())
        {
            WiFi.disconnect(true); // <= this true shut the WiFi off
            WiFi.begin();
        }
    }

What the true means is that the esp wifi module will be stopped (WiFiSTA.cpp) :

//wifioff is the parameter reflecting the `true` above
 if(wifioff) {
             return WiFi.enableSTA(false);
        }

which at the end of the stack will cause the function esp_wifi_stop() from the esp library to be called. This, somehow, will prevent the the code to return inside _eventCallback() to propagate the SYSTEM_EVENT_STA_DISCONNECTED event.

Therefore, removing the true will cause the esp_wifi_stop() not to be called and the SYSTEM_EVENT_STA_DISCONNECTED event will naturally propagate.

I don't know if this is a viable solution or just a workaround. There are probably reasons why someone put that true there and I'd like to hear some maintainer voice about it.

@lbernstone
Copy link
Contributor

If you submit the PR, then @me-no-dev will take a look at it and comment.

@stale
Copy link

stale bot commented Oct 11, 2019

[STALE_SET] This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

@stale stale bot added the Status: Stale Issue is stale stage (outdated/stuck) label Oct 11, 2019
@stale
Copy link

stale bot commented Oct 25, 2019

[STALE_DEL] This stale issue has been automatically closed. Thank you for your contributions.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Stale Issue is stale stage (outdated/stuck)
Projects
None yet
Development

No branches or pull requests

5 participants