Core & Wifi debug output sent to serial port despite "None" Debug Level in Arduino's IDE

[teo1978]

Basic Infos

• [not gonna read that ] This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: https://learn.sparkfun.com/tutorials/esp8266-thing-development-board-hookup-guide?_ga=2.138804790.421092098.1538252036-914235417.1536518212
• Core Version: [2018/09/24 with pull request 5126]
• Development Env: [Arduino IDE]
• Operating System: [Ubuntu]

Settings in IDE

• Module: [Sparkfun ESP8266 Thing Dev]
• Flash Mode: [no clue]
• Flash Size: [512K no SPIFFS is what it says in the Arduino IDE]
• lwip Variant: [v2 Lower Memory]
• Reset Method: [no idea]
• Flash Frequency: [no idea]
• CPU Frequency: [no idea]
• Upload Using: [SERIAL]
• Upload Speed: [any] (serial upload only)

Problem Description

In the Arduino IDE, if I select "None" for the "Debug Level" setting, I expect to not see any debug output in the serial monitor except what I output from my code (or from some third party library).

That worked as expected at least until 2.4.0.

Now with the git version, I'm getting debug output from, I think, WIFI and/or CORE, even though I select "None" as the Debug Level in the IDE.

Arduino Sketch

#include <ESP8266WiFi.h>
#include <ESP8266HTTPClient.h>

#define MYDEBUG;

#ifdef MYDEBUG
  char mybuffer[1024];
#endif


String client_ssid="Sixty-Seven";
String client_password="8791oetifiw";


void setup() 
{
  Serial.begin(115200);
  myDebug("Hello!");



  WiFi.mode(WIFI_STA);
  WiFi.begin(client_ssid.c_str(), client_password.c_str());

  for (int i=0; i<20; i++) {
    myDebug("Trying to connect to Wifi '%s' with password '%s'", client_ssid.c_str(), client_password.c_str());
  
    if (WiFi.status()==WL_CONNECTED) {
      break;
    }
    delay(1000);
  }
  if (WiFi.status()!=WL_CONNECTED)  {
    myDebug("ERROR: Cannot connect to WiFi!!!");
    return;
  }
  
  myDebug("...connected succesfully");
  
  
}

void loop() {
  
}


void myDebug(const char* format, ...) {
  #ifdef MYDEBUG
    va_list arglist;
    va_start(arglist, format);
    vsprintf(mybuffer, reinterpret_cast<const char*>(format), arglist);
    Serial.println(mybuffer);
    va_end(arglist);
  #endif
}

EXPECTED Output (Serial Monitor)

Hello!
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
...connected succesfully

OBSERVED Output (Serial Monitor)

SDK:2.2.1(cfd48f3)/Core:2.4.2-54-gc3bb0b4/lwIP:2.1.0rc1(STABLE-2_1_0_RC1/glue:arduino-2.4.2-10-g5965154)/BearSSL:6d1cefc
Hello!
scandone
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 3
cnt 

connected with Sixty-Seven, channel 1
dhcp client start...
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
ip:192.168.1.150,mask:255.255.255.0,gw:192.168.1.1
Trying to connect to Wifi 'Sixty-Seven' with password '*******'
...connected succesfully
pm open,type:2 0

[dragondaud]

You can prevent unwanted debug output by setting debug port to Disabled. Apparently some debug messages are sent by default, if the port is enabled. Your serial messages are not 'debug' messages from the Core's point of view. I always use Debug Level: 'NoAssert-NDEBUG' with Debug Port: 'Disabled', as that will free up additional heap.

[teo1978]

Apparently some debug messages are sent by default

In previous version they were not, unless I selected CORE and/or WIFI in the "Debug Level". (the Debug Level option in the Arduino's IDE, for some reason, only allows to choose between a predefined set of combinations, e.g. "THIS", "THAT", "THIS+THAT", etc, but not all the combinations. Why they didn't create a set of checkboxes instead of a list of [not all] possible combinations is beyond my understanding).

Until 2.4.2 it behaved as expected, this is a regression.

You can prevent unwanted debug output by setting debug port to Disabled

Yeah, but that will also prevent wanted debug output. I used to be able, for example, to choose only "HTTP_CLIENT", and I would see debug messages related to http client, but not those mentioned above related to wifi, deep sleep etc.

Something is BROKEN.

[dragondaud]

Have you tested this using the git version? There has been code cleanup since 2.4.2's release that may affect this. I have never seen unwanted debug messages myself, but always use the git version. Something in the SDK may have changed and gone unnoticed.

As for the THIS+THAT stuff, this ESP8266 core project has no influence on the Arduino IDE, and can only work within the confines they establish for their board manager. You can participate in that totally separate project at: https://github.com/arduino/Arduino

[teo1978]

Have you tested this using the git version? There has been code cleanup since 2.4.2's

I am testing the git version, as I said. It might not be the very last one, but I cloned it about a week ago.

2.4.2 was the last stable version where I did not observe the issue.

As for the THIS+THAT stuff, this ESP8266 core project has no influence on the Arduino IDE

I know, that's why I said "they". That was just an unrelated rant of mine.

[teo1978]

It might not be the very last one, but I cloned it about a week ago

Just checked with the latest git version, issue still present.

[teo1978]

Until 2.4.2 it behaved as expected,

Actually that's not true. It worked on 2.4.0.

The Arduino IDE sometimes randomly changes its settings (yes, it does), and apparently it changed the "Debug Port" to "Disabled" when I switched to testing with 2.4.2.

I have checked again, and on 2.4.0. it behaves as expected: messages such as these:

wifi evt: 2
wifi evt: 0
wifi evt: 3
STA disconnect: 8

only show up if the selected Debug Level includes WIFI. I don't remember an example of CORE debug messages to redo the test for that too.

However, I now see that the unwanted wifi-related messages in the recent versions are different (quoted in my original report).

Perhaps the issue is that new debug messages have been introduced that do not use the macros (or whatever they are) that are controlled via Debug Level.

[devyte]

Thanks for filling out the template @teo1978 .
@d-a-v do you know if this is on purpose or a bug?

[d-a-v]

wifi evt: 2
wifi evt: 0
wifi evt: 3
STA disconnect: 8

These messages are not ours but fw's.
They are enabled with Serial.setDebugOutput(true) before setup() at Serial.begin() when Serial is used for debug (any debug option).
Before #4467 (after 2.4.0, before 2.4.2), they were enabled only after setup().

[teo1978]

wifi evt: X

Those specific messages don't show up anymore. Now what I see are messages like these:

state: X -> Y

I don't know if these are a replacement for the older ones, or if they are totally unrelated. The fact is, the old ones behaved as expected (used DEBUG_WIFI() and hence would show up only if WIFI was included in Debug Level), while the newer ones always show up unless the Debug Port is set as Disabled, which means you can't disable them without disabling other debug messages.

Then there are these:

scandone
scandone
add 0
aid 3
cnt 
connected with <SSID>, channel 1
dhcp client start...
ip:192.168.1.150,mask:255.255.255.0,gw:192.168.1.1
pm open,type:2 0

and also this one, unrelated to wifi, which I guess should belong to CORE, but shows up whether or not CORE is included in the debug level (doesn't seem to exist in 2.4.0):

enter deep sleep

If any of this is not yours please let me know where I should report the issue/s. This makes debugging a pain in the *** (or rather just undoable) and it's tremendously annoying.

(...)esp8266$ grep -r "enter deep sleep"  # also "ip:.*mask:"
Binary file tools/sdk/lib/libmain.a matches

(...)esp8266$ grep -R scandone  # also "state:.*->"
Binary file tools/sdk/lib/libnet80211.a matches

(...)esp8266$grep -R "connected with.*channel"
Binary file tools/sdk/lib/libwpa.a matches

(...)esp8266$ grep -r "pm open"
Binary file tools/sdk/lib/libpp.a matches

[d-a-v]

They are not ours but espressif's. I doubt they consider this as an issue.
You can try to Serial.setDebugOutput(false); right after Serial.begin();

[devyte]

@d-a-v is correct, those messages come from the SDK, not from our core. You can try opening an issue at the Espressif esp8266 nonos repo. However, you should be aware that they usually take long to respond, if at all. I have issues of much higher priority than some debug msgs aging nicely there, and I've seen many others as well.
If you do open an issue, I strongly suggest the following:

• reduce your sketch to use only sdk api, and not our core. You can do this by tracking our core calls and checking which sdk calls are being called under the hood. This is important, they are very unlikely to try to figure out how our corecore is tied to their api calls on their end.
• clarify in your issue that you're using our Arduino.core build system.
• link the issue there with this one
• if you can, best of all would be to replicate the issue on their build system using only their api, and leave our core and tools. completely out of it. This is not easy the first time, but there should be tutorials out there on how to set it up.

[devyte]

Given that there is nothing to do in our core code at this time, I'm closing this for now. If there is a response from Espressif that implies changes in this repo, we can revisit and I'll reopen, or we can track with a new issue.