Got an odd one here. I've been switching from Serial.println to Log.info but I've found it doesn't work within a system events handler for button pushes. The Serial.println works within it, and I can save the message and Log it from loop() and it works. I've confirmed this with 0.9.0 and 1.1.0, Argon and Xenon. I've also tested this with individual events instead of all_events and had the same issue.
Here's my test code:
//SYSTEM_THREAD(ENABLED); //Makes no difference
SerialLogHandler logHandler(LOG_LEVEL_NONE, { // Logging level for non-application messages
{ "app", LOG_LEVEL_TRACE } // Default logging level for all application messages
});
String message = "";
bool showMessage = false;
void handle_all_the_events(system_event_t event, int param)
{
Serial.println(""); //always works
Log.info("In handle_all_the_events...");
// 64 to 32 bit workaround: https://community.particle.io/t/system-events-param-problem/32071/13
Log.info("EVENT_H: %lu EVENT_L: %lu DATA: %d", (uint32_t)(event>>32), (uint32_t)event, param);
message = String::format("EVENT_H: %lu EVENT_L: %lu DATA: %d", (uint32_t)(event>>32), (uint32_t)event, param); //save, and try again later
showMessage=true;
Log.info(message);
Serial.println(message); //always works
}
void setup() {
System.on(all_events, handle_all_the_events);
Log.info("Setup complete");
}
void loop() {
if (showMessage) {
Log.warn("in loop...");
Log.warn(message);
showMessage=false;
}
}
The output from this after I push the button is:
0000001170 [app] INFO: Setup complete
0000001331 [app] INFO: In handle_all_the_events...
0000001332 [app] INFO: EVENT_H: 0 EVENT_L: 16384 DATA: 1
0000001333 [app] INFO: EVENT_H: 0 EVENT_L: 16384 DATA: 1
EVENT_H: 0 EVENT_L: 16384 DATA: 1
0000001336 [app] WARN: in loop...
0000001336 [app] WARN: EVENT_H: 0 EVENT_L: 16384 DATA: 1EVENT_H: 0 EVENT_L: 128 DATA: 0
0000038597 [app] WARN: in loop...
0000038597 [app] WARN: EVENT_H: 0 EVENT_L: 128 DATA: 0EVENT_H: 0 EVENT_L: 128 DATA: 150
EVENT_H: 0 EVENT_L: 4096 DATA: 1
0000038748 [app] WARN: in loop...
0000038748 [app] WARN: EVENT_H: 0 EVENT_L: 4096 DATA: 1EVENT_H: 0 EVENT_L: 8192 DATA: 1
0000039748 [app] WARN: in loop...
0000039749 [app] WARN: EVENT_H: 0 EVENT_L: 8192 DATA: 1
What's interesting is the automatic/system events I've seen like, the 1st one above (Time changed), as well as the firmware update and reset work fine with Log.info, but you can see the next group when I push the button has no Log.info output. It's only when the loop next runs do we see the output. In other words when I push the button I see 1 serial output from the handler, then the 2 Log outputs from loop. What I would expect is like that time changed event where there are 3 Log outputs in the handler, then the 2 in the loop.
Any ideas?