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?