Hundreds of "*wm:[2] [EVENT] WIFI_REASON: 8" logs when I disconnect() #1326

robjordan · 2021-12-22T14:56:54Z

Basic Infos

Hardware

WiFimanager Branch/Release: Master
2.0.5-beta+sha.8452df7

Esp32:

Hardware: m5stickc+ (ESP32-PICO-D4 based)

Core Version: 3.4.0

Description

On ESP32 Arduino, my app is a BLE scanner. I have read that WiFi activity can interfere with BLE detection, so I keep WiFi disabled most of the time, but re-enable once a minute to log data to a web server. The way I do that is:

        if (wifiManager.autoConnect()) {
          log_value("sos-battery", batteryLevel);
          log_value("sos-rssi", (avgRSSI==0) ? -100 : avgRSSI);
          log_value("sos-freeheap", ESP.getFreeHeap());
          wifiManager.disconnect();
        } else {
          Serial.println("Failed to connect WiFi.");
        }

After every disconnect(), I see a log message as per the Issue subject, but it is repeated many times, seemingly one additional log message each time I disconnect. Now after running for around 12 hours, there are more than 600 repeated messages.

Settings in IDE

Module: NodeMcu, Wemos D1

Additional libraries:

Sketch

#BEGIN
#include <Arduino.h>

void setup() {
  esp_get_idf_version();
  m5_init();
  wifi_init();  // connect to Wifi, use it, then disconnect.
  config_init(cfgFile, cfg);
  ble_scan_init();
}

void loop() {
  static time_t lastPing = 0;
  static time_t silentTime = 0;
  static time_t lastFeed = now();
  const char *timeUnit[] = {"sec(s)", "min(s)", "hour(s)", "day(s)"};
  unsigned timeUnitIndex = 0;


  char buf[80];

  // If an error occurs that stops the scan, it will be restarted here.
  if(pBLEScan->isScanning() == false) {
      // Start scan with: duration = 5s, no scan end callback, not a continuation of a previous scan.
      pBLEScan->start(5, nullptr, false);
      M5.Lcd.fillScreen(0);
      M5.Lcd.setCursor(0,10);
      print_date_time();
      Serial.print("Scan exited, ping count: ");
      Serial.print(pingCount);

      if (pingCount == 0) {
        // it might be a temporary silence, but track it in case it's a sign
        // of technical failure, beacon turned off, etc.
        silentTime = now() - lastPing;
        if (silentTime > silenceThreshold) {
          M5.Lcd.println("\nALERT: NO BEACON");
          alert(&alerts[silenceAlertIndex]);
        }
        if (silentTime < 60) {
          timeUnitIndex = 0;
        } else if (silentTime < 60*60) {
          silentTime = silentTime / 60;
          timeUnitIndex = 1;
        } else if (silentTime < 24*60*60) {
          silentTime = silentTime / (60*60);
          timeUnitIndex = 2;
        } else {
          silentTime = silentTime / 24*60*60;
          timeUnitIndex = 3;
        }

      } else {
        // we have detected pings - not sure how many yet
        lastPing = now();
        silentTime = 0;
        if (batteryLevel < batteryThreshold) {
          M5.Lcd.println("\nALERT: LOW BATTERY");
          alert(&alerts[batteryAlertIndex]);
        }
        if (pingCount >= pingAlertThreshold) {
          // it's an SOS call, raise the alarm
          M5.Lcd.println("\nALERT: BUTTON PRESS");
          alert(&alerts[sosAlertIndex]);
        } else {
          // it's the normal case of ~1 ping per sample interval
        }
      }

      // Calculate average RSSI, avoiding divide by zero error
      avgRSSI = (pingCount>0) ? (sumRSSI / pingCount) : 0;

      sprintf(buf, 
            "\npings: %d, RSSI: %d\nbattery: %d%%\nsilent: %lu %s", 
            pingCount, 
            avgRSSI,
            batteryLevel,
            silentTime,
            timeUnit[timeUnitIndex]);

      M5.Lcd.println(buf);
      Serial.println(buf);
      if ((now() - lastFeed) > feedInterval) {
        // Log data to MQTT
        if (wifiManager.autoConnect()) {
          log_value("sos-battery", batteryLevel);
          log_value("sos-rssi", (avgRSSI==0) ? -100 : avgRSSI);
          log_value("sos-freeheap", ESP.getFreeHeap());
          wifiManager.disconnect();
        } else {
          Serial.println("Failed to connect WiFi.");
        }
        lastFeed = now();
      }
      pingCount = 0;
      sumRSSI = 0;
  }
}
#END

Debug Messages

*wm:[1] AutoConnect 
*wm:[2] ESP32 event handler enabled 
*wm:[2] Connecting as wifi client... 
*wm:[2] setSTAConfig static ip not set, skipping 
*wm:[1] Connecting to SAVED AP: JM07
*wm:[1] connectTimeout not set, ESP waitForConnectResult... 
*wm:[2] Connection result: WL_CONNECTED
*wm:[1] AutoConnect: SUCCESS 
*wm:[1] STA IP Address: 192.168.1.132
About to post: {"value": 100}
[HTTPS] POST...
[HTTPS] POST... code: 200
{"id":"0EXBBRQ1MWYN84Y86TF96P2PQA","value":"100","feed_id":1772252,"feed_key":"sos-battery","created_at":"2021-12-22T13:35:38Z","created_epoch":1640180138,"expiration":"2022-01-21T13:35:38Z"}
About to post: {"value": -67}
[HTTPS] POST...
[HTTPS] POST... code: 200
{"id":"0EXBBRQM5CKF8C7VEMZVFKKTH9","value":"-67","feed_id":1772254,"feed_key":"sos-rssi","created_at":"2021-12-22T13:35:40Z","created_epoch":1640180140,"expiration":"2022-01-21T13:35:40Z"}
About to post: {"value": 113928}
[HTTPS] POST...
[HTTPS] POST... code: 200
{"id":"0EXBBRRDRM2HF7SE53X232V9AG","value":"113928","feed_id":1772435,"feed_key":"sos-freeheap","created_at":"2021-12-22T13:35:42Z","created_epoch":1640180142,"expiration":"2022-01-21T13:35:42Z"}
*wm:[1] Disconnecting 
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
<hundreds more like this>

The text was updated successfully, but these errors were encountered:

tablatronix · 2021-12-22T23:56:13Z

Thanks, I may have left some debugging on the wrong level when testing S2

robjordan · 2021-12-24T21:21:14Z

Thanks, I appreciate you paying attention to this. I'm not sure I was clear though: it isn't just there is an unwanted debug output. I fear there might be something wrong in the code path, based on the increasing number of these WIFI_REASON messages, i.e. it appears 1x on the first wifiManager.disconnect();, 2x on the second, 3x on the third, Nx on the Nth. And N can be a very large number as I connect and disconnect once every minute. I had it appear literally 600 times in succession after running for a few hours.

tablatronix · 2021-12-25T01:26:40Z

Interesting let me see if I can reproduce what version on esp lib you on?

tablatronix · 2021-12-25T01:27:13Z

Oh nm I see you added all the info above

tablatronix · 2021-12-25T03:15:51Z

WIFI_REASON_ASSOC_LEAVE = 8,

Are you perhaps creating new objects over and over again accidentally? That would make sense if creating more and more event listeners.

Can you share how you are reconnecting over and over? Or reduce your sketch to a simpler one, where is your wm object?

robjordan · 2021-12-26T01:03:50Z

Hi. Not knowingly creating multiple objects. wifiManager is created in global scope. HTTP clients are created on the stack in local variables each time I do an HTTP post. The main loop is basically:
// ... block for 5 seconds checking for BLE advertisements
// ... check whether 1 minute has elapsed since we last logged, if so ...
if (wifiManager.autoConnect("SSID", "PW")) {
log_json(); // which makes an HTTP POST
wifiManager.disconnect();
}

I'll aim to create a simpler test case to reproduce. Maybe in a couple of days though. Thanks for help.

robjordan · 2021-12-27T22:09:39Z

This test case (based on the WiFiManager basic example) demonstrates.

#include <Arduino.h>
#include <WiFi.h>
#include <WiFiManager.h> // https://github.com/tzapu/WiFiManager
#include <HTTPClient.h>

WiFiManager wm;

void setup() {
    WiFi.mode(WIFI_STA); // explicitly set mode, esp defaults to STA+AP
    Serial.begin(115200);
    bool res;

    res = wm.autoConnect("AutoConnectAP","password"); // password protected ap

    if(!res) {
        Serial.println("Failed to connect");
        // ESP.restart();
    } 
    else {
        //if you get here you have connected to the WiFi    
        Serial.println("connected...yeey :)");
        Serial.println("now disconnecting");
        wm.disconnect();
    }

}

void loop() {
    HTTPClient http;
    const char *postUrl="https://ptsv2.com/t/b8a9b-1640614358/post";
    String httpRequestData = "Hello world";
    int httpCode; 

    // put your main code here, to run repeatedly:  
    if (wm.autoConnect()) {
        if (http.begin(postUrl)) {
            httpCode = http.POST(httpRequestData);
            wm.disconnect();
        }
    }
    delay(2000);
}

robjordan · 2021-12-27T22:12:59Z

Debug output:

*wm:[1] AutoConnect 
*wm:[2] ESP32 event handler enabled 
*wm:[2] Connecting as wifi client... 
*wm:[2] setSTAConfig static ip not set, skipping 
*wm:[1] Connecting to SAVED AP: PLUSNET-X8T5
*wm:[1] connectTimeout not set, ESP waitForConnectResult... 
*wm:[2] Connection result: WL_CONNECTED
*wm:[1] AutoConnect: SUCCESS 
*wm:[1] STA IP Address: 192.168.1.102
connected...yeey :)
now disconnecting
*wm:[1] Disconnecting 
*wm:[1] AutoConnect 
*wm:[2] ESP32 event handler enabled*wm:[2] [EVENT] WIFI_REASON:  8
 
*wm:[2] Connecting as wifi client... 
*wm:[2] setSTAConfig static ip not set, skipping 
*wm:[1] Connecting to SAVED AP: PLUSNET-X8T5
*wm:[1] connectTimeout not set, ESP waitForConnectResult... 
*wm:[2] Connection result: WL_CONNECTED
*wm:[1] AutoConnect: SUCCESS 
*wm:[1] STA IP Address: 192.168.1.102
*wm:[1] Disconnecting 
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8                                                                                                     
*wm:[1] AutoConnect                                                                                                                 
*wm:[2] ESP32 event handler enabled                                                                                                 
*wm:[2] Connecting as wifi client...                                                                                                
*wm:[2] setSTAConfig static ip not set, skipping 
*wm:[1] Connecting to SAVED AP: PLUSNET-X8T5
*wm:[1] connectTimeout not set, ESP waitForConnectResult... 
*wm:[2] Connection result: WL_CONNECTED
*wm:[1] AutoConnect: SUCCESS 
*wm:[1] STA IP Address: 192.168.1.102
*wm:[1] Disconnecting 
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[1] AutoConnect 
*wm:[2] ESP32 event handler enabled 
*wm:[2] Connecting as wifi client... 
*wm:[2] setSTAConfig static ip not set, skipping 
*wm:[1] Connecting to SAVED AP: PLUSNET-X8T5
*wm:[1] connectTimeout not set, ESP waitForConnectResult... 
*wm:[2] Connection result: WL_CONNECTED
*wm:[1] AutoConnect: SUCCESS 
*wm:[1] STA IP Address: 192.168.1.102
*wm:[1] Disconnecting 
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[1] AutoConnect 
*wm:[2] ESP32 event handler enabled 
*wm:[2] Connecting as wifi client... 
*wm:[2] setSTAConfig static ip not set, skipping 
*wm:[1] Connecting to SAVED AP: PLUSNET-X8T5
*wm:[1] connectTimeout not set, ESP waitForConnectResult... 
*wm:[2] Connection result: WL_CONNECTED
*wm:[1] AutoConnect: SUCCESS 
*wm:[1] STA IP Address: 192.168.1.102
*wm:[1] Disconnecting 
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[2] [EVENT] WIFI_REASON:  8
*wm:[1] AutoConnect 
*wm:[2] ESP32 event handler enabled 
*wm:[2] Connecting as wifi client... 
*wm:[2] setSTAConfig static ip not set, skipping 
*wm:[1] Connecting to SAVED AP: PLUSNET-X8T5
*wm:[1] connectTimeout not set, ESP waitForConnectResult...

tablatronix · 2022-02-03T02:25:39Z

Ever figure this out?

robjordan · 2022-02-03T21:06:14Z

To be fair, I haven't updated the library since I reported it. It's not a critical problem in my application because I reboot the esp32 every 24 hours. But as far as I know the problem still exists. Did you try the small sample programme I posted?

…

On Thu, 3 Feb 2022, 02:25 Shawn A, ***@***.***> wrote: Ever figure this out? — Reply to this email directly, view it on GitHub <#1326 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAC65F2A75G75HLRU3N5VSTUZHRS3ANCNFSM5KSXPQKQ> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you authored the thread.Message ID: ***@***.***>

tablatronix · 2022-02-03T21:59:27Z

I have to see which event that is
WIFI_REASON_ASSOC_LEAVE OR
8 SYSTEM_EVENT_STA_LOST_IP < ESP32 station lost IP and the IP is reset to 0

Something with your router I doubt its reproducible elsewhere

i can try it though

tablatronix · 2022-02-03T22:14:44Z

Works fine for me

robjordan · 2022-02-04T09:51:52Z

Ok, if not reproducible, it's not worth pursuing. Thanks for looking.

…

On Thu, 3 Feb 2022, 22:14 Shawn A, ***@***.***> wrote: Works fine for me — Reply to this email directly, view it on GitHub <#1326 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAC65F6OP6WA3D3SXGNLHTDUZL457ANCNFSM5KSXPQKQ> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you authored the thread.Message ID: ***@***.***>

OekoSolveMG · 2022-05-19T13:36:13Z

I am assuming you use autoConnect() to reconnect to the wifi while your application is running. Because if you do then this issue is probably because of the same reason as #1383. Hope this helps and is actually causing your problem, because if it does simply integrating the easy fix or using a different way to reconnect fixes that.

robjordan · 2022-05-19T21:28:18Z

I am assuming you use autoConnect() to reconnect to the wifi while your application is running. Because if you do then this issue is probably because of the same reason as #1383. Hope this helps and is actually causing your problem, because if it does simply integrating the easy fix or using a different way to reconnect fixes that.

Thanks, yes I do call autoconnect() repeatedly. I read the issue you mentioned and it's very useful info.

tablatronix · 2022-05-19T21:29:36Z

This should be solved now

tablatronix added the bug Validated BUG label Dec 22, 2021

tablatronix closed this as completed May 19, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Hundreds of "*wm:[2] [EVENT] WIFI_REASON: 8" logs when I disconnect() #1326

Hundreds of "*wm:[2] [EVENT] WIFI_REASON: 8" logs when I disconnect() #1326

robjordan commented Dec 22, 2021

tablatronix commented Dec 22, 2021

robjordan commented Dec 24, 2021

tablatronix commented Dec 25, 2021

tablatronix commented Dec 25, 2021 •

edited

Loading

tablatronix commented Dec 25, 2021 •

edited

Loading

robjordan commented Dec 26, 2021

robjordan commented Dec 27, 2021 •

edited

Loading

robjordan commented Dec 27, 2021

tablatronix commented Feb 3, 2022

robjordan commented Feb 3, 2022 via email

tablatronix commented Feb 3, 2022 •

edited

Loading

tablatronix commented Feb 3, 2022

robjordan commented Feb 4, 2022 via email

OekoSolveMG commented May 19, 2022 •

edited

Loading

robjordan commented May 19, 2022

tablatronix commented May 19, 2022

Hundreds of "*wm:[2] [EVENT] WIFI_REASON: 8" logs when I disconnect() #1326

Hundreds of "*wm:[2] [EVENT] WIFI_REASON: 8" logs when I disconnect() #1326

Comments

robjordan commented Dec 22, 2021

Basic Infos

Hardware

Description

Settings in IDE

Sketch

Debug Messages

tablatronix commented Dec 22, 2021

robjordan commented Dec 24, 2021

tablatronix commented Dec 25, 2021

tablatronix commented Dec 25, 2021 • edited Loading

tablatronix commented Dec 25, 2021 • edited Loading

robjordan commented Dec 26, 2021

robjordan commented Dec 27, 2021 • edited Loading

robjordan commented Dec 27, 2021

tablatronix commented Feb 3, 2022

robjordan commented Feb 3, 2022 via email

tablatronix commented Feb 3, 2022 • edited Loading

tablatronix commented Feb 3, 2022

robjordan commented Feb 4, 2022 via email

OekoSolveMG commented May 19, 2022 • edited Loading

robjordan commented May 19, 2022

tablatronix commented May 19, 2022

tablatronix commented Dec 25, 2021 •

edited

Loading

tablatronix commented Dec 25, 2021 •

edited

Loading

robjordan commented Dec 27, 2021 •

edited

Loading

tablatronix commented Feb 3, 2022 •

edited

Loading

OekoSolveMG commented May 19, 2022 •

edited

Loading