esp_log_set_vprintf not redirecting system_api, phy, event, ...

[markwj]

I'm using esp_log_set_vprintf to redirect log output, but some is not getting redirected.

For example, after calling esp_log_set_vprintf then starting a wifi station mode connection, I get:

Code: Select all

I (5455) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (5455) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (7485) phy: phy_version: 355.1, 59464c5, Jun 14 2017, 20:25:06, 0, 0
I (5455) wifi: wifi firmware version: 407bb27
I (5455) wifi: config NVS flash: enabled
I (5455) wifi: config nano formating: disabled
I (5465) wifi: Init dynamic tx buffer num: 32
I (5465) wifi: Init dynamic rx buffer num: 32
I (5465) wifi: wifi driver task: 3ffcfc7c, prio:23, stack:4096
I (5465) wifi: Init static rx buffer num: 10
I (5465) wifi: Init dynamic rx buffer num: 32
I (5465) wifi: Init rx ampdu len mblock:7
I (5465) wifi: Init lldesc rx ampdu entry mblock:4
I (9685) wifi: n:10 0, o:1 0, ap:255 255, sta:10 0, prof:1
I (10335) wifi: state: init -> auth (b0)
I (10345) wifi: state: auth -> assoc (0)
I (10345) wifi: state: assoc -> run (10)
I (10365) wifi: connected with XXXX, channel 10
I (14975) event: ip: X.X.X.X, mask: Y.Y.Y.Y, gw: Z.Z.Z.Z
I (20355) wifi: pm start, type:0

But, of those only the 'wifi' tagged lines actually go through my vprintf style redirection. The system_api, phy and event tagged logs don't (they go direct to the console).

The problem can be replicated by esp_log_set_vprintf with a callback function that just silently drops traffic. In that case, the wifi logs are dropped, but the others are still shown on the console:

Code: Select all

Starting WIFI as a client...
I (15805) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (15805) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (15845) phy: phy_version: 355.1, 59464c5, Jun 14 2017, 20:25:06, 0, 0
I (20505) event: ip: X.X.X.X, mask: Y.Y.Y.Y, gw: Z.Z.Z.Z

Using 2.1 ESP-IDF. Any ideas?

[kolban]

Might it be related to the notion of "_EARLY" log messages which may not be piped through ets_vprintf(). See:

http://esp-idf.readthedocs.io/en/latest ... m/log.html

Might we also be using "printf()" statements in some of the logging messages?

[markwj]

I grepped those messages, and they don't seem to directly use the _EARLY variants:

components/esp32/system_api.c
ESP_LOGI(TAG, "Base MAC address is not set, read default base MAC address from BLK0 of EFUSE");

components/esp32/event_default_handlers.c
ESP_LOGI(TAG, "ip: " IPSTR ", mask: " IPSTR ", gw: " IPSTR,
IP2STR(&event->event_info.got_ip.ip_info.ip),
IP2STR(&event->event_info.got_ip.ip_info.netmask),
IP2STR(&event->event_info.got_ip.ip_info.gw));

But in esp_log.h these macros are wrapped around an #ifndef BOOTLOADER_BUILD.

So, I guess these are somehow built into the boot loader, and then merely referenced from the app? Strange, because I thought the boot loader was entirely separate. It is certainly in a separate binary image file, and no dynamic linking on ESP32.

It seems these are all in the components/esp32 directory and that does have -DBOOTLOADER_BUILD in the makefile.

So, I guess I'm uncovering something a bit more nasty. The esp32 system components are built for the boot loader, but then used like that in both the boot loader and application images.

[WiFive]

The source code is shared but the binary code is not shared. BOOTLOADER_BUILD should only be defined when make is building the bootloader binary, not the app binary.

[ESP_igrr]

So, I guess I'm uncovering something a bit more nasty. The esp32 system components are built for the boot loader, but then used like that in both the boot loader and application images.

Indeed, there was such a bug, it was fixed in https://github.com/espressif/esp-idf/co ... 3869176c30.

[markwj]

Indeed, there was such a bug, it was fixed in https://github.com/espressif/esp-idf/co ... 3869176c30.

It would be good if that could be applied to the 2.1 stable release, as it is impacting stable production builds.