UDP or Particle.publish() in Log handler causing freeze with SYSTEM_THREAD

Firmware
1

Sending UDP messages or using Particle.publish() in a custom log handler does not work on a Boron with 1.5.2. The Boron continues breathing cyan but stops executing the main loop and is not reachable from the cloud anymore after sending a log message processed through the custom handler.

This renders the community log handlers for Papertrail and Web Log mentioned in the docs useless in Combination with SYSTEM_THREAD(ENABLED);.

This could be related to Problems getting HTTP response on Argon and Boron

I created a minimal example for reproducing this issue (Boron, 1.5.2):

class TestLogHandler : public LogHandler {
public:
  explicit TestLogHandler(LogLevel level = LOG_LEVEL_INFO, const LogCategoryFilters &filters = {}) : LogHandler(level, filters) {
    LogManager::instance()->addHandler(this);
  }
  virtual ~TestLogHandler() {
    LogManager::instance()->removeHandler(this);
  }

protected:
  void logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) {
    Serial.println(millis());
    Particle.publish("test");
  };
};

SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler(LOG_LEVEL_TRACE);
TestLogHandler testLogHandler(LOG_LEVEL_INFO);

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

void loop() {
  Log.info("online");
  delay(1000);
}

The log output looks (as expected) like this while the Boron is connecting and stops when it starts breathing cyan, being not reachable from the cloud:

0000154951 [app] INFO: online
154951
0000155951 [app] INFO: online
155952

With SYSTEM_THREAD(ENABLED); removed, the Log output starts after the connection to the Particle Cloud (as expected) and the publish works fine.

I need SYSTEM_THREAD(ENABLED);, as my device has to execute code independently of the cellular connection status.

This looks like a bug. If not, what am I doing wrong? Can anyone confirm this issue or present a workaround?

2

You don’t seem to be limiting the scope of your log handler to only emit app logs so I suppose you’ll also get a lot of system events logged out which may hit the rate limit.

Have had a look what SerialLogHandle logHandler(LOG_LEVEL_INFO) puts out when you don’t also instantiate your handler?

3

Thank you for the hint! You are right, I am not limiting the scope to app, but the Device OS has almost no logging with level INFO or above. I tried your suggestion, the log looks like this, only two messages no belonging to my app:

0000002287 [app] INFO: online
0000009086 [hal] INFO: Using internal SIM card
0000011263 [app] INFO: online
[...]
0000079291 [app] INFO: online
0000080267 [system] ERROR: Failed to load session data from persistent storage
0000080291 [app] INFO: online
[...]

If I am logging with INFO every second, of course every additional message hits the rate limit with no chance to recover. To avoid this, I changed my delay to 2000, but this did not have any impact on the bug.

I also tried how rate limiting behaves by publishing from loop() every 800ms. As expected, some messages do not arrive, but the loop remains executing fine.

I’m pretty sure rate limiting is not the cause for my bug.

4

I would recommend not doing anything that takes any time or can block from the log handler. This includes publishing, network, and any shared resource calls like SPI.

In the SdCardLogHandler I use a ring buffer from the log handler to buffer the data. It’s picked up from the loop thread for processing rather than doing it in the context of the log handler callback.

1 Like
5

Thank you @rickkas7! I will adapt the ring buffer technique for my log handler and avoid doing network there.

Although you are mentioning that the community log handlers are not supported by Particle, it is a bit odd to list them in the official docs if you do not recommend the way they are working. Both are doing network stuff in the log handler.

As suggested in the docs, I raised issues in both repos linking to this thread to make this problem visible for users of this handlers:


6

This topic was automatically closed 182 days after the last reply. New replies are no longer allowed.