Log - PANIC from Software Timer Callback

I have a fault with the Log.trace method within my DumpMem() utility routine which causes me grief at times.

I have been able to reliably reproduce the fault via a timer callback, but I have had similar issues in other instances.

Here is the test code:

/* LOG_TEST_04

Testing v0.8.0.rc1 logging

Reproduce PANIC caused by DumpMem()


*/

/* Version History
2018-01-14 HR
- Created

*/

 #define CAUSE_PANIC

// Set up logger with filters
SerialLogHandler logHandler(LOG_LEVEL_NONE,         // Logging level for non-application messages
    {   // Logging Category Filters
        { "app", LOG_LEVEL_NONE },                  // Default logging level for all application messages
        { "app.network", LOG_LEVEL_TRACE },         // Logging level for networking messages
        { "app.setup", LOG_LEVEL_WARN }             // Logging level for setup messages
    });


void DumpMem(char * pszDesc, uint8_t * pucData, size_t uLen);
void DumpMem16(uint8_t * pucData, size_t uLen, size_t startIdx);

void onTimeout();

// CallbackClass callback;
Timer timer(10000L, onTimeout);


void setup() {

    Serial.begin(9600L);
    USBSerial1.begin(9600L);

    // ==== Dynamically set up logger =====
    
    // Get log manager's instance
    auto logManager = LogManager::instance();

    LogCategoryFilters filters;
    
    filters.append({ "app", LOG_LEVEL_TRACE });

    auto logHandler1 = new StreamLogHandler(USBSerial1, LOG_LEVEL_WARN /* Default level */, filters);

    logManager->addHandler(logHandler1);
  
    delay(2000L);
    
    timer.start(); // starts timer if stopped or resets it if started.
    
    DumpMem("TEST", (uint8_t *) "0123456789",  10);
    Log.trace("Setup exit");
}

void loop() {
    
    static int i = 0;
    
    Log.trace("Loop %d", i);
    onTimeout();                    // <== OK WHEN CALLED FROM HERE
 
    i++;
    
    delay(1000L);
}

void onTimeout()
{
    Log.trace("onTimeout() entry");
    DumpMem("onTimeout()", (uint8_t *) "0123456789",  10);
    Log.trace("onTimeout() exit");
}


//
// Dump data as Hex and Printable ASCII to USBSerial1
//
void DumpMem(char * pszDesc, uint8_t * pucData, size_t uLen)
{
    Log.trace("%s n=%d", pszDesc, uLen);

    // dump in blocks of sixteen
    for (size_t i=0; i < uLen; i= i + 16)
        DumpMem16(pucData, uLen, i);
}

void DumpMem16(uint8_t * pucData, size_t uLen, size_t startIdx)
{
   	char szT[4];
    char szLine[96];
    size_t i;

    
    sprintf(szLine, "  %04X: ", startIdx);

    // print out in Hex
    for (i=startIdx; (i < uLen) && (i < (startIdx + 16)); i++)
    {
        sprintf(szT, "%02X ", (uint8_t) pucData[i]);
        strcat(szLine, szT);
        if (i == startIdx + 7)
            strcat(szLine, "- ");
    }

    // Pad out rest of block
    for (int j = i; j < (startIdx + 16); j++) 
    {
        strcat(szLine, "   ");
        if (j == startIdx + 7)
            strcat(szLine, "- ");
    }

    // output ASCII
    szT[1] = '\0';

    for (i=startIdx; (i < uLen) && (i < (startIdx + 16)); i++)
    {
      	if (((unsigned char) pucData[i] < 0x20) ||
             ((unsigned char) pucData[i] > 0x7F))
            szT[0] = '.';
        else 
            szT[0] = (unsigned char) pucData[i];
            
        strcat(szLine,szT);
    }
    
 #ifdef CAUSE_PANIC
    Log.trace(szLine);              // <== PANICS WHEN CALED FROM upon a timer
 #else
    USBSerial1.printlnf(szLine);      // <== OK
 #endif

} // DumpMem16()

The problem is specifically in the DumpMem16() funcrtion.

It works a.okay if I use USBSerial1 to output, but a 13 flash SOS PANIC is kicked off when the timer expires if I use Log.trace() (which has been configured to use USBSerial1) .

Also, if I don’t call DumpMem16(), DumpMem() runs okay, ie the Log.trace() in that routine works just fine.

I am calling the callback within loop() to show that there is no issue outside of a timer expiration.

I understand fully that long winded routines with output is bad news with Timer callbacks…

Any thoughts?

We have seen several thread where logging inside timer callbacks (or other “critical” sections) cause a panic crash.
Could you file a GitHub issue about that? I thought there already was one, but couldn’t find it - maybe I was wrong.

Also, let’s not forget the Timer stack depth is limited.

1 Like

@peekay123, good point and 100% relevant, makes sense and explains a lot of things; 13 SOS blinks == Stack overflow.

@ScruffR, confirmed, have not raised a GitHub issue as I had not reproduced the fault until now (was getting problems in non timer instantiated instances). Will do so shortly.

The fact that USBSerial1.printlnf(szLine) works and Log.trace(szLine) doesn’t shows me that this should be repairable.

2 Likes

@ScruffR, done!

Fingers crossed.

1 Like

Solved.

Advice from @sergey (hopefully this is “sergeuz” from GitHub fame) was to try Log.print() because this has a much lower stack memory requirement than Log.trace().

As well as fixing this test app, it fixed the originating issue which was also within a timer callback.

Case closed with thanks!

3 Likes