Buffered Debug Log (IDFGH-11811)

[mickeyl]

Is your feature request related to a problem?

I love logging. Unfortunately, for handling hardware events, logging via UART completely messes up the timing.

The ESP_LOG functions are very helpful, however they're not buffered.

Describe the solution you'd like.

I'd like to have a configuration option in sdkconfig, so that we could send ESP_LOG entries to memory -- and then an ultra low priority task would pick them up and commit it to the UART. Of course, it needs to have a (configurable?) maximum number of in-flight-messages / buffer size.

Describe alternatives you've considered.

I tried using other peripherals like TM1638, LEDs, Buzzer, etc. to signalize, but it's always much more cumbersome than using ESP_LOG.

Additional context.

On systems with an ultra-low-power coprocessor, instead of using a FreeRTOS task with minimal priority, we could perhaps hand over printing to the ULP. Yes, this will only work if hardware events come burst-wise. This solution will not work if there is a fast continuous stream of events, which would quickly exhaust memory (unless we also use PSRAM to buffer... but the ULP has no access to that memory I'm afraid).

[igrr]

Hi @mickeyl,
We do have an updated version of logging framework in development, it will allow you to get such behavior.

In the meantime, you can implement buffering yourself using one of these methods:

• increase buffering for stdout stream using setvbuf function (e.g. disable the line-buffered mode)
• implement custom output handler function (with buffering) and redirect stdout to it using stdout = fwopen(...) early in app_main
• redirect only esp_log output to a custom handler using esp_log_set_vprintf

[ammaree]

I support this request and can add the following suggestions: 1. Using the RTC Slow SRAM as buffer, it can be accessed from both MCU’s and preserved across reboots. 2. Functionality to support the logging to a SYSLOG host in proper syslog format 3. Additional syslog level selector to determine priority level of messages destined for syslog server in addition to console. 4. Adding the task name, function name and MCU# to syslog output 5. Option to persist host destined SYSLOG messages to FFS/LFS should IP stack not yet be connected. We have all the above functionality in our LOG replacement module and, although a bit convoluted, it works very well in aiding remote/offline debugging On 23/12/31, 16:51, "Ivan Grokhotkov" ***@***.******@***.***>> wrote: Hi @mickeyl<https://github.com/mickeyl>, We do have an updated version of logging framework in development, it will allow you to get such behavior. In the meantime, you can implement buffering yourself using one of these methods: * increase buffering for stdout stream using setvbuf function (e.g. disable the line-buffered mode) * implement custom output handler function (with buffering) and redirect stdout to it using stdout = fwopen(...) early in app_main * redirect only esp_log output to a custom handler using esp_log_set_vprintf — Reply to this email directly, view it on GitHub<#12906 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AAYT7GDGAUH2SBZNG5V3ZJDYMF3V5AVCNFSM6AAAAABBIIQE5OVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQNZSHE3DOMZYGM>. You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[ammaree]

Some additional thoughts....

1. We have a configurable inactivity timeout on the UART port. If no keystroke received from the UART port for a period of (1->16 in our case) minutes the info remain in the Slow RAM buffer until the next keystroke activates output again.

2. We have a flag on the buffer that can be set by any task using ESP_LOGX to (temporarily) halt output from the buffer to the UART should the task represent an alternative destination ie Telnet of HTTP where the console output should be redirected.

[X-Ryl669]

You may take a look to this project which is exactly what you asked for. You can store a log buffer in whatever place you want, use the log macros (which, unlike ESP_LOG counterpart, are compile time checked for correctness) and later dump the log buffer (when your HP core is awake and communicating typically). It's also encoding the logs cleanly, so it takes a lot less space than a real formatted log (formatting is done at dump time, not at log time, log time is deterministic and fast since it only save the va-args parameters and the log formatting string isn't stored in the buffer). If this is still too big for you (or you want to log in the ULP/LP core domain), I have this too:

#ifndef h_ulp_log_h
#define h_ulp_log_h

/** LP CPU memory is too limited to store logs as text. Instead they are stored as tags and values.
    The meaning for each tag is explained below and the expected values too. */
typedef enum
{
    End         = 0,    //!< Sentinel value for the last log, must be 0, no arguments expected
    Started     = 1,    //!< LP CPU started,            2 argument contains the wakeup reason and current state when started
    Error       = 2,    //!< An error happened,         1 argument contains the error code
    Intr        = 3,    //!< Interrupt triggered,       1 argument contains the interrupt type
    PinChanged  = 4,    //!< Pin changed,               1 argument contains the pin number


    MaxLogTag
} log_tag_t;

// Log facilities
volatile uint32_t logBuffer[256/sizeof(uint32_t)] = {0};
uint32_t logTail = 0;

// Compressing the logs as binary as a debugging feature here
static inline void logtag(log_tag_t tag) { logBuffer[logTail++] = (uint32_t)tag; }

static inline void log_1(log_tag_t tag, uint32_t value) { logtag(tag); logBuffer[logTail++] = value; }
static inline void log_2(log_tag_t tag, uint32_t val1, uint32_t val2) { log_1(tag, val1); logBuffer[logTail++] = (uint32_t)val2; }
static inline void log_3(log_tag_t tag, uint32_t val1, uint32_t val2, uint32_t val3) { log_2(tag, val1, val2); logBuffer[logTail++] = (uint32_t)val3; }

static void log_n(log_tag_t tag, uint32_t count, uint32_t * values)
{
    logBuffer[logTail++] = (uint32_t)tag;
    for (uint32_t i = 0; i < count; i++) {
        logBuffer[logTail++] = values[i];
    }
}
// Simple pseudo overload macro for the unique log function selecting the right implementation depending on number of arguments
#define GET_FUNCTION_NAME(_0, _1, _2, _3, _4, NAME, ...) NAME
#define log(...) GET_FUNCTION_NAME(_0, ##__VA_ARGS__, log_3, log_2, log_1, logtag)(__VA_ARGS__)

// Example usage:
// log(Started, ulp_lp_core_get_wakeup_cause(), state);


#ifdef __cplusplus
// This part is only visible to the HP core so we are free to use C++ here and all fancy tricks
extern "C"
{
    /** Example usage:
         @code
             esp_sleep_wakeup_cause_t cause = esp_sleep_get_wakeup_cause();
             if (cause == ESP_SLEEP_WAKEUP_ULP)
                  dumpULPLog(ulp_logBuffer, ulp_logTail); // Output "ULP: Started 2 0" "ULP: End"
         @endcode */
    void dumpULPLog(const uint32_t *buffer, uint32_t count)
    {
        // Follow the same order as your log enumeration above
        static const char * logName[] = { "Execution ended", "Execution start", "Error happened", "Interrupted", "Pin changed" };
        // Contains the expected number of arguments for each log
        static uint32_t logArgCount[]  = { 0, 2, 1, 1, 1 };
        for (uint32_t i = 0; i < count; i++)
        {
            std::string num = "ULP:";
            num += logName[(log_tag_t)buffer[i]]; num += " ";
            for (uint32_t j = 0; j < logArgCount[buffer[i]]; j++)
                num += std::to_string(buffer[i+1+j]);
            printf("%s\n", num.c_str()); // Or whatever log primitive you are using in HP core
            i += logArgCount[buffer[i]];
        }
    }
}
#endif

#endif