Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Photon/P1/Electron] Recursive logging freezes the application thread while the LogHandler is trying to acquire a lock on the resource. #1517

Merged
merged 4 commits into from Apr 5, 2018
Merged
Changes from 3 commits
Commits
File filter...
Filter file types
Jump to…
Jump to file or symbol
Failed to load files and symbols.

Always

Just for now

@@ -0,0 +1,91 @@

#include "application.h"
#include "unit-test/unit-test.h"

class RecursiveLogger : LogHandler
{
private:

volatile bool active;
int count;

public:

RecursiveLogger(LogLevel level = LOG_LEVEL_INFO) : LogHandler(level)
{
active = false;
count = 0;
}

void addHandler() {
LogManager::instance()->addHandler(this);
}

void removeHandler() {
LogManager::instance()->removeHandler(this);
}

int getCount() {
return count;
}

void logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr)
{
if (active) {
// Fail if we are allowed to re-enter this logging handler,
// as the count won't increase to 10. It will remain pinned to 5.
count--;
return;
}
active = true;

// Serial.printlnf("logMessage: %d", count); // DEBUG
if (count++ >= 5) {
Log.info("attempt re-entry into this logMessage function: %d", count); // DEBUG
}

active = false;
}
};

// SerialLogHandler logHandler(LOG_LEVEL_ALL); // DEBUG

/**
* This tests two things related to Issue #1497: https://github.com/particle-iot/firmware/issues/1497
* 1) that the application thread doesn't lock up waiting for a logger mutex to clear
* 2) that the logMessage function isn't allowed to be called in a recursive manner
*/
test(LOGGING_01_recursive_log_handling)
{
Serial.println("IF THIS HANGS HERE, THE TEST FAILED!");
RecursiveLogger recursiveLogger;
recursiveLogger.addHandler();
for (int x=0; x<10; x++) {
Log.info("recursive logging %lu", millis());
}
recursiveLogger.removeHandler();
assertEqual(recursiveLogger.getCount(), 10);
}
test(LOGGING_02_multiple_recursive_log_handling)
{
Serial.println("IF THIS HANGS HERE, THE TEST FAILED!");
RecursiveLogger recursiveLogger1;
RecursiveLogger recursiveLogger2;
RecursiveLogger recursiveLogger3;
RecursiveLogger recursiveLogger4;
recursiveLogger1.addHandler();
recursiveLogger2.addHandler();
recursiveLogger3.addHandler();
recursiveLogger4.addHandler();
for (int x=0; x<10; x++) {
Log.info("recursive logging %lu", millis());
}
recursiveLogger1.removeHandler();
recursiveLogger2.removeHandler();
recursiveLogger3.removeHandler();
recursiveLogger4.removeHandler();
assertEqual(recursiveLogger1.getCount(), 10);
assertEqual(recursiveLogger2.getCount(), 10);
assertEqual(recursiveLogger3.getCount(), 10);
assertEqual(recursiveLogger4.getCount(), 10);
}
@@ -577,14 +577,16 @@ class LogManager {

Vector<LogHandler*> activeHandlers_;

volatile bool output_active_;

This comment has been minimized.

Copy link
@sergeuz

sergeuz Apr 5, 2018

Member

I know we tend to mix different styles in the code, but let's at least make sure that the code within a single file follows the same naming convention :) Also, volatile isn't really necessary here, since the access to this member variable is already guarded by a mutex.

This comment has been minimized.

Copy link
@technobly

technobly Apr 5, 2018

Author Member

I started with the word active_ and then thought it would be better to say what exactly is active. It wasn't my intention to mix snake_case with camelCase. I'll fix it :)


#if Wiring_LogConfig
Vector<FactoryHandler> factoryHandlers_;
LogHandlerFactory *handlerFactory_;
OutputStreamFactory *streamFactory_;
#endif

#if PLATFORM_THREADING
Mutex mutex_; // TODO: Use read-write lock?
RecursiveMutex mutex_; // TODO: Use read-write lock?
#endif

// This class can be instantiated only via instance() method
@@ -602,6 +604,9 @@ class LogManager {
static void logMessage(const char *msg, int level, const char *category, const LogAttributes *attr, void *reserved);
static void logWrite(const char *data, size_t size, int level, const char *category, void *reserved);
static int logEnabled(int level, const char *category, void *reserved);

bool isActive() const;
void setActive(bool output_active);
};

#if Wiring_LogConfig
@@ -674,6 +674,7 @@ spark::LogManager::LogManager() {
handlerFactory_ = DefaultLogHandlerFactory::instance();
streamFactory_ = DefaultOutputStreamFactory::instance();
#endif
output_active_ = false;
}

spark::LogManager::~LogManager() {
@@ -839,9 +840,15 @@ void spark::LogManager::logMessage(const char *msg, int level, const char *categ
#endif
LogManager *that = instance();
LOG_WITH_LOCK(that->mutex_) {
// prevent re-entry
if (that->isActive()) {
return;
}
that->setActive(true);
for (LogHandler *handler: that->activeHandlers_) {
handler->message(msg, (LogLevel)level, category, *attr);
}
that->setActive(false);
}
}

@@ -853,9 +860,15 @@ void spark::LogManager::logWrite(const char *data, size_t size, int level, const
#endif
LogManager *that = instance();
LOG_WITH_LOCK(that->mutex_) {
// prevent re-entry
if (that->isActive()) {
return;
}
that->setActive(true);
for (LogHandler *handler: that->activeHandlers_) {
handler->write(data, size, (LogLevel)level, category);
}
that->setActive(false);
}
}

@@ -878,6 +891,14 @@ int spark::LogManager::logEnabled(int level, const char *category, void *reserve
return (level >= minLevel);
}

inline bool spark::LogManager::isActive() const {
return output_active_;
}

inline void spark::LogManager::setActive(bool output_active) {
output_active_ = output_active;
}

#if Wiring_LogConfig

// spark::
ProTip! Use n and p to navigate between commits in a pull request.
You can’t perform that action at this time.