You are viewing a static version of the site. Enable JavaScript to benefit from the
full functionality of this site and enable such things as forum posting.
Odd behaviour re print and debug
ullix:
I am having trouble with a BME680 sensor, and while reducing my sketch more and more to find clues, I stumbled over this strange behavior of uecide; this is the minimum sketch:
#include <Wire.h>
void setup() {
Serial.begin(115200);
delay(2000);
Serial.println(F("BME680 async test -----------------------------------"));
Serial.println("Doing: Wire1.begin(21, 22)");
// from hereon no more print in setup
Wire1.begin(21, 22);
Serial.println("Doing: Wire1.setClock(400000)");
Wire1.setClock(400000);
Serial.println(F("BME680 setup done -----------------------------------\n"));
Serial.print("Test\n");
}
void loop() {
Serial.print(".");
delay(100);
}
and this is its output:
BME680 async test -----------------------------------
Doing: Wire1.begin(21, 22)
[V][esp32-hal-i2c.c:1486] i2cInit(): num=1 sda=21 scl=22 freq=0
[V][esp32-hal-i2c.c:1682] i2cSetFrequency(): freq=100000Hz
[V][esp32-hal-i2c.c:1698] i2cSetFrequency(): cpu Freq=240Mhz, i2c Freq=100000Hz
[V][esp32-hal-i2c.c:1706] i2cSetFrequency(): Fifo delta=1
D[V][esp32-hal-i2c.c:1682] i2cSetFrequency(): freq=400000Hz
[V][esp32-hal-i2c.c:1698] i2cSetFrequency(): cpu Freq=240Mhz, i2c Freq=400000Hz
[V][esp32-hal-i2c.c:1706] i2cSetFrequency(): Fifo delta=3
...............................................................
Note that the first 2 prints are done, but once Wire is called, only Verbose Debug output from esp32-hal-i2c is printed.
Ok, then inactivate the Debug output - well, actually the Hardware-->Options-->Debug setting is already at 'None', yet it is still outputted. Making other changes to the Debug setting does not result in any changes.
Once in the Loop, the print is working again.
Why is it not doing a simple print?
And why not responding to the Debug setting?
(One observation: the 7th line in the output begins with a 'D'.Perhaps the firt letter of 'Doing'? I Verbose output overwriting print output?)
matt:
Which board are you compiling for? At the moment all I get is a panic with that code.
matt:
Actually that may have been a corrupt installation. I did a clean one and it now runs. But it does run properly, with just your debugging and nothing else.
Note though that the "debug" option doesn't (currently) purge the cache (it should do, but doesn't).
In fact, even after turning on debugging and purging the cache I don't get any debugging output.
ullix:
I use ESP32.
What is 'properly'? When I switch on DEBUG-->Verbose, I expect it to blab out everything, while still putting out my print commands? But you are getting nothing?
How do I do a 'clean' install? Delete everything and start all over?
matt:
The quickest way to to a temporary clean install is to specify a new data directory when you run uecide. uecide --datadir=.fooecide will load UECIDE with a fresh setup in .fooecide so you can try things without interfering with your existing installation.
All I am getting at the moment is your Serial.print() output, and no verbose logging. I am not sure why, since -DCORE_DEBUG_LEVEL=5 is being set in the compilation command line.
matt:
And yes, I know you use ESP32, but specifically which board is selected in the IDE?
ullix:
'ESP32 Dev Module'
ullix:
I did exactly this uecide --datadir=.fooecide and installed the ESP-Dev board. Now I also get only the Serial.print output, and no Debug output, irrespective of the Debug Level setting?
matt:
Have you tried it in the Arduino IDE (ugh...)? Maybe debugging is generally broken at the moment...
In fact, I can't see how there can be much debugging controllable through that flag, since 99% of the code is in precompiled libraries, so can't be affected by compile time -D flags.
ullix:
The ESP API has a logging library https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/system/log.html and here are some example commands
log_d("Status: %s", sc_status_strings[st % 5]);
log_e("dhcp client start failed!");
log_e("no Default SDA Pin for Second Peripheral");
log_e("i2c=%p",i2c);
log_i("dev=%p date=%p",i2c->dev,i2c->dev->date);
found in the libs WiFi, Wire and ESP32-hal-i2c.c, which have "bugged" me the most, and I found it helpful to see problems at least with one eye, as opposed of being totally blind. And this output is switched on by the Debug Level command in the IDE.
Or so I thought. Now that you challenged me, I compared the output of Debug Level Verbose (looks like this gives all log_e, _d, _w, _i, and _v output), and Debug Level None. Bummer, the output is the same; this setting has no effect that I can see???
Yet, I do get the log_X output, but only in the old uecide setup. In the clean one I get nothing. (Can't check my big script on Arduino IDE, as I have customized some libs, so far available only under uecide).
So, what on earth have I modified in uecide, which makes it provide log_X output? I surely want to keep this!
ullix:
To be sure I am not hallucinating after too many hours of coding, this is some selection of the log_X output from WiFi, Wire and esp32-hal-i2c:
[D][WiFiGeneric.cpp:337] _eventCallback(): Event: 7 - STA_GOT_IP
[D][WiFiGeneric.cpp:381] _eventCallback(): STA IP: 10.0.0.85, MASK: 255.255.255.0, GW: 10.0.0.1
[V][esp32-hal-i2c.c:1486] i2cInit(): num=0 sda=25 scl=26 freq=0
[V][esp32-hal-i2c.c:1682] i2cSetFrequency(): freq=800000Hz
[V][esp32-hal-i2c.c:1698] i2cSetFrequency(): cpu Freq=240Mhz, i2c Freq=800000Hz
[V][esp32-hal-i2c.c:1706] i2cSetFrequency(): Fifo delta=6
[E][esp32-hal-i2c.c:320] i2cDumpI2c(): i2c=0x3ffbee3c
[I][esp32-hal-i2c.c:321] i2cDumpI2c(): dev=0x60027000 date=0x16042000
[V][esp32-hal-i2c.c:1698] i2cSetFrequency(): cpu Freq=240Mhz, i2c Freq=100000Hz
[V][esp32-hal-i2c.c:1706] i2cSetFrequency(): Fifo delta=1
[W][esp32-hal-i2c.c:1413] i2cCheckLineState(): invalid state sda(21)=0, scl(22)=1
[D][esp32-hal-i2c.c:1421] i2cCheckLineState(): Recovered after 1 Cycles
matt:
Yeah, I know about the ESP-IDF logging. But the Arduino code doesn't use that directly. Instead you have such things as:
#if ARDUHAL_LOG_LEVEL >= ARDUHAL_LOG_LEVEL_VERBOSE
#define log_v(format, ...) log_printf(ARDUHAL_LOG_FORMAT(V, format), ##__VA_ARGS__)
#define isr_log_v(format, ...) ets_printf(ARDUHAL_LOG_FORMAT(V, format), ##__VA_ARGS__)
#else
#define log_v(format, ...)
#define isr_log_v(format, ...)
#endif
There's a few bits of log_* spattered around the core, but relatively little. The rest is in the Arduino libraries themselves. If there's any optional debugging in the ESP-IDF precompiled libraries I can see no way of it getting turned on, since it doesn't get compiled. So really the only debugging must be what is in the HAL and libraries.
So the question is, why is that not being turned on? Or if it is being turned on, why is it not going to the right location?
matt:
Well, this is most strange. Debugging is working. I can manually use log_v, etc, in my sketch and it shows up. I see debugging that comes from libraries. However I can't see any debugging that comes from the core. I can't even see the strings that are supposed to be being output in the debugging in the compiled elf file!
matt:
The only verbose logging that's ever included seems to be verbose logging that I specifically use in my sketch.
ullix:
but as you do see above, I also get the D, E, I and W log output (from the WiFi and hal-i2c libs.)
ullix:
and with that modification to my simple clip:
...
void loop() {
log_e("Stupid");
log_i("Error");
log_d("Loggin'");
log_w("in the");
log_v("IDE");
delay(100);
}
I get this output to serial:
[V][esp32-hal-i2c.c:1682] i2cSetFrequency(): freq=400000Hz
[V][esp32-hal-i2c.c:1698] i2cSetFrequency(): cpu Freq=240Mhz, i2c Freq=400000Hz
[V][esp32-hal-i2c.c:1706] i2cSetFrequency(): Fifo delta=3
[E][TEST_BME680asyncclip.ino:21] loop(): Stupid
[I][TEST_BME680asyncclip.ino:22] loop(): Error
[D][TEST_BME680asyncclip.ino:23] loop(): Loggin'
[W][TEST_BME680asyncclip.ino:24] loop(): in the
[V][TEST_BME680asyncclip.ino:25] loop(): IDE
[E][TEST_BME680asyncclip.ino:21] loop(): Stupid
This is with the Hardware-->Option-->Debug Level=verbose. When this is set to None the ESP32-hal-i2c created messages do still come out, however, not the ones programmed in the sketch.
ullix:
Some clear-up: in the hal-I2C code I myself activated the debug:
in: esp32-hal-i2c.c
// enabled by ullix 2020-06-06
//#define ENABLE_I2C_DEBUG_BUFFER
#define ENABLE_I2C_DEBUG_BUFFER
#if (ARDUHAL_LOG_LEVEL >= ARDUHAL_LOG_LEVEL_INFO) && (defined ENABLE_I2C_DEBUG_BUFFER)
#define INTBUFFMAX 64
#define FIFOMAX 512
static uint32_t intBuff[INTBUFFMAX][3][2];
static uint32_t intPos[2]= {0,0};
static uint16_t fifoBuffer[FIFOMAX];
static uint16_t fifoPos = 0;
#endif
and this debug output does NOT depend on the setting of Debug level in the uecide IDE. Though it seems to be that the #if ... lines not activate it if Debug level NONE is selected?
But even when the I2C debug is disabled I still get the log output from WiFi, and I am pretty sure I have not modified any settings (at least now I can't even find anything that relates to debug). And while I can find the esp_wifi.h file, there is no esp_wifi.c file anywhere?
So, what remains now from my original problem is that the log output overwrites and/or deletes the Serial.print output. How is that possible?
matt:
Once you change the setting in the menu you must shift-click the compile button to do a clean build, otherwise it won't recompile the core or library files and pick up the new setting.
ullix:
That is an important reminder and not obvious. Wouldn't it be prudent to automatically make such a setting in your code?
matt:
Yes, and it can be done, and will be done. Not till the next time I release the ESP32 core and rebuild all the boards. It just needs one setting adding in every board file for that one option.
matt:
Actually, thinking about it, I separated the boards from the core, didn't I... so I can just rebuild the boards and release them now.
