How to redirect all console output

[zekageri]

Board

esp-wrover-kit

Device Description

ESP32_Wrover_E --> 8mb PSram, 16mb flash

Hardware Configuration

• SPI
• Eth_Lan8720
• I2C

Version

latest master (checkout manually)

IDE Name

Platform IO

Operating System

Windows 10

Flash frequency

80Mhz

PSRAM enabled

yes

Upload speed

115200

Description

int _log_vprintf(const char *fmt, va_list args) does not redirect everything.

Sketch

File routerFile;
char log_print_buffer[512];
#define REROUTE_PATH "/testlog.txt"
int _log_vprintf(const char *fmt, va_list args) {
    int ret = vsnprintf(log_print_buffer, sizeof(log_print_buffer), fmt, args);
    if (ret >= 0){
        routerFile = LittleFS.open(REROUTE_PATH, FILE_APPEND);
        routerFile.write((uint8_t *)log_print_buffer, (size_t)ret);
        routerFile.close();
    }
    return vprintf(fmt, args);
}

void setReroute(){
    esp_log_set_vprintf(_log_vprintf);
    esp_log_level_set("*", ESP_LOG_VERBOSE);
}

void setup(){
    Serial.begin(115200);
    setReroute();
}

void loop(){
}

Debug Message

Everything goes to the serial except some messages like these ones:


E (1746) gpio: gpio_set_level(226): GPIO output gpio_num error
E (1779) gpio: gpio_set_level(226): GPIO output gpio_num error

Other Steps to Reproduce

No

I have checked existing issues, online documentation and the Troubleshooting Guide

• I confirm I have checked existing issues, online documentation and Troubleshooting guide.

[igrr]

@zekageri i think this function is only supposed to redirect log messages which are produced using ESP_LOG macros in IDF. Everything else — output of printf, output of Arduino log macros, output of Serial.print — is not redirected.
If you explain the behavior you'd like to achieve, we may suggest a different mechanism which would solve your problem.

[zekageri]

Thank you for the response.

I would need to redirect every stdout.
(including every espressif/arduino log)
Everything which goes out on uart i want to log to a file or send it via server events / websockets.

[igrr]

You can redirect stdout using fwopen (using a callback function) or freopen functions.

However, keep in mind that this will only redirect the output sent to stdout. Output passed directly to the UART driver (such as Serial) doesn't pass through stdout and will not be redirected.

Another thing to keep in mind is reentrancy. If some error occurs in the process of writing to a file and this error produces a log line, you need some mechanism to avoid re-entering your log redirection function.

[zekageri]

Thank you for the suggestion.
I will investigate these functions!

[zekageri]

I can't find any solution to redirect either fwopen nor freopen.
I have tried the following:

int app_printf(void *cookie, const char *data, int size) {
    fprintf(stderr, "app_printf: %.*s", size, data);
    return size;
}

char* stdout_buf = (char *)malloc(128);
void setup(){
  fclose(stdout);
  stdout = fwopen(NULL, &app_printf);
  setvbuf(stdout, stdout_buf, _IOLBF, 128);
}

I already got warnings:

#define fwopen(__cookie,__fn) funopen(__cookie, (int (*)())0, __fn, (fpos_t (*)())0, (int (*)())0)
Expands to:

funopen(__null, (int (*)())0, &app_printf, (fpos_t (*)())0, (int (*)())0)
argument of type "int (*)()" is incompatible with parameter of type "int (*)(void *__cookie, char *__buf, int __n)"C/C++(167)
invalid conversion from 'fpos_t (*)()' {aka 'long int (*)()'} to 'fpos_t (*)(void*, fpos_t, int)' {aka 'long int (*)(void*,

and compiler errors:

In file included from C:/Users/Pc/.platformio/packages/framework-arduinoespressif32/cores/esp32/Arduino.h:27,
                 from src/drivers/system/Sys.h:4,
                 from src/drivers/system/Sys.cpp:1:
src/drivers/system/Sys.cpp: In member function 'void Sys::setReroute()':
src/drivers/system/Sys.cpp:356:14: error: invalid conversion from 'int (*)()' to 'int (*)(void*, char*, int)' [-fpermissive]
     stdout = fwopen(NULL, &app_printf);
              ^~~~~~
c:\users\pc\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\sys-include\stdio.h:602:9: note:   initializing argument 2 of 'FILE* funopen(const void*, int (*)(void*, char*, int), int (*)(void*, const char*, int), fpos_t (*)(void*, fpos_t, int), int (*)(void*))'
   int (*__readfn)(void *__cookie, char *__buf,
   ~~~~~~^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
     _READ_WRITE_BUFSIZE_TYPE __n),
     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
src/drivers/system/Sys.cpp:356:14: error: invalid conversion from 'fpos_t (*)()' {aka 'long int (*)()'} to 'fpos_t (*)(void*, fpos_t, int)' {aka 'long int (*)(void*, 
long int, int)'} [-fpermissive]
     stdout = fwopen(NULL, &app_printf);
              ^~~~~~
c:\users\pc\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\sys-include\stdio.h:606:12: note:   initializing argument 4 of 'FILE* funopen(const void*, int (*)(void*, char*, int), int (*)(void*, const char*, int), fpos_t (*)(void*, fpos_t, int), int (*)(void*))'
   fpos_t (*__seekfn)(void *__cookie, fpos_t __off, int __whence),
   ~~~~~~~~~^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
src/drivers/system/Sys.cpp:356:14: error: invalid conversion from 'int (*)()' to 'int (*)(void*)' [-fpermissive]
     stdout = fwopen(NULL, &app_printf);
              ^~~~~~
c:\users\pc\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\sys-include\stdio.h:607:9: note:   initializing argument 5 of 'FILE* funopen(const void*, int (*)(void*, char*, int), int (*)(void*, const char*, int), fpos_t (*)(void*, fpos_t, int), int (*)(void*))'
   int (*__closefn)(void *__cookie));
   ~~~~~~^~~~~~~~~~~~~~~~~~~~~~~~~~
*** [.pio\build\esp-wrover-kit\src\drivers\system\Sys.cpp.o] Error 1

[igrr]

Indeed there is an issue with fwopen, I'll open a bug report for that in IDF.

In the meantime it can be replaced with funopen as follows: https://wokwi.com/projects/346783796954137171

Edit: i have renamed the issue title to better reflect the problem.

[zekageri]

Thank you thank you.
I will test this.

Is wokwi a reliable test environment?

[igrr]

I think for code which isn't very close to hardware, it should be quite reliable! For peripherals emulation your mileage may vary; my experience with it has been very good so far.

[zekageri]

Thank you for everything. I will come back with test results to this question.

[zekageri]

Does it redirect crash dumbs too?

[zekageri]

I made this sketch:

ssize_t write_fn(void *cookie, const char *buf, ssize_t size) {
    /* redirect the bytes somewhere; writing to Serial just for an example */
    File file = LittleFS.open(DEBUG_PATH, FILE_APPEND);
    file.write((uint8_t *)buf, (size_t)size);
    file.close();
    return size;
}

void ets_putc_handler(char c) {
    /* this gets called from various ets_printf / esp_rom_printf calls */
    static char buf[256];
    static size_t buf_pos = 0;
    buf[buf_pos] = c;
    buf_pos++;
    if (c == '\n' || buf_pos == sizeof(buf)) {
        /* flush */
        write_fn(NULL, buf, buf_pos);
        buf_pos = 0;
    }
}

void setReroute() {
    // creates path if not exists.
    fileSys.createPath(DEBUG_PATH);
    /* redirect stdout */
    stdout = funopen(NULL, NULL, &write_fn, NULL, NULL);
    setvbuf(stdout, linebuf, _IOLBF, sizeof(linebuf));

    /* redirect ets_printf / esp_rom_printf output */
    ets_install_putc1(&ets_putc_handler);
}

void setup(){
    Serial.begin(115200);
    setReroute();
}

void loop(){
}

I crashed my esp with this crash:

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0). 

Core  0 register dump:
PC      : 0x40091e24  PS      : 0x00060635  A0      : 0x80090b42  A1      : 0x3ffbe52c
A2      : 0x3ffb7c1c  A3      : 0x3ffd66f4  A4      : 0x00000000  A5      : 0x00060623
A6      : 0x00060623  A7      : 0x00000001  A8      : 0x3ffd66f4  A9      : 0x00000001
A10     : 0x3ffd66f4  A11     : 0x00000001  A12     : 0x00000040  A13     : 0x3ffb9380  
A14     : 0x007bf1e8  A15     : 0x003fffff  SAR     : 0x00000018  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x4008af3c  LEND    : 0x4008af52  LCOUNT  : 0xffffffff
Core  0 was running in ISR context:
EPC1    : 0x4010173b  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x00000000


Backtrace:0x40091e21:0x3ffbe52c |<-CORRUPTED

  #0  0x40091e21:0x3ffbe52c in vListInsert at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/freertos/list.c:166 (discriminator 1)       


Core  1 register dump:
PC      : 0x40091fa3  PS      : 0x00060935  A0      : 0x8008f7b0  A1      : 0x3ffba590
A2      : 0x3ffb7c44  A3      : 0xb33fffff  A4      : 0x0000cdcd  A5      : 0x00060923
A6      : 0x00060920  A7      : 0x0000abab  A8      : 0x0000cdcd  A9      : 0xffffffff
A10     : 0x00000003  A11     : 0x00060923  A12     : 0x00060920  A13     : 0x00060d23
A14     : 0x007b7c44  A15     : 0x003fffff  SAR     : 0x00000001  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000


Backtrace:0x40091fa0:0x3ffba5900x4008f7ad:0x3ffba5d0 0x400868c6:0x3ffba610  

  #0  0x40091fa0:0x3ffba590 in compare_and_set_native at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_hw_support/include/soc/compare_set.h:25
      (inlined by) spinlock_acquire at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_hw_support/include/soc/spinlock.h:103
      (inlined by) xPortEnterCriticalTimeout at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/freertos/port/xtensa/port.c:288
  #1  0x4008f7ad:0x3ffba5d0 in vPortEnterCritical at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/freertos/port/xtensa/include/freertos/portmacro.h:578
      (inlined by) xQueueGenericSend at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/freertos/queue.c:840
  #2  0x400868c6:0x3ffba610 in ipc_task at /Users/ficeto/Desktop/ESP32/ESP32S2/esp-idf-public/components/esp_ipc/src/esp_ipc.c:75




ELF file SHA256: 0000000000000000

Rebooting...

But i only got logged some basic thing..

E (1740) gpio: gpio_set_level(226): GPIO output gpio_num error
E (2118) gpio: gpio_set_level(226): GPIO output gpio_num error
E (1709) gpio: gpio_set_level(226): GPIO output gpio_num error
E (2089) gpio: gpio_set_level(226): GPIO output gpio_num error
E (1763) gpio: gpio_set_level(226): GPIO output gpio_num error
E (2123) gpio: gpio_set_level(226): GPIO output gpio_num error
E (1732) gpio: gpio_set_level(226): GPIO output gpio_num error
E (2095) gpio: gpio_set_level(226): GPIO output gpio_num error