Make AOS logging per thread, not global
We noticed that if 2 threads use AOS_LOG, they occasionally crash. The
stack trace looked like 2 messages were being constructed
simultaneously. Digging in, this is possible because there is 1 global
logger which gets passed (patchily) to the per-thread context.
We've got a bunch of different cases and (reasonable) ways to handle
them when ShmEventLoop comes into play.
Simple single threaded appliction:
* Outside Run() -> stderr
* Inside Run() -> /aos
Single event loop appliction with extra threads
* Outside Run() -> stderr
* Inside Run() -> /aos
* Other threads -> stderr
Multiple event loop appliction with extra threads
* Outside Run() -> stderr
* Inside Run() -> /aos
* Other threads -> stderr
Simulation:
* Inside Run -> /aos
* Outside Run -> stderr
This pretty quickly quickly looks like a thread local logging handler
and a fallback to stderr. We don't really need much more, and don't
want to worry about synchronization for much more, so lets just do the
simple thing for now and revise if there are better use cases.
Change-Id: I90d76516a55f0b01a8a0e27ad0434dac5921e261
diff --git a/aos/logging/context.cc b/aos/logging/context.cc
index 446e0df..0628e0e 100644
--- a/aos/logging/context.cc
+++ b/aos/logging/context.cc
@@ -42,7 +42,7 @@
char thread_name_array[kThreadNameLength + 1];
if (prctl(PR_GET_NAME, thread_name_array) != 0) {
- PDie("prctl(PR_GET_NAME, %p) failed", thread_name_array);
+ PLOG(FATAL) << "prctl(PR_GET_NAME, " << thread_name_array << ") failed";
}
#if __has_feature(memory_sanitizer)
// msan doesn't understand PR_GET_NAME, so help it along.
@@ -73,7 +73,7 @@
} // namespace
-Context::Context() : implementation(GetImplementation()), sequence(0) {}
+Context::Context() : sequence(0) {}
// Used in aos/linux_code/init.cc when a thread's name is changed.
void ReloadThreadName() {
diff --git a/aos/logging/context.h b/aos/logging/context.h
index 43ac54f..cc770ba 100644
--- a/aos/logging/context.h
+++ b/aos/logging/context.h
@@ -45,7 +45,8 @@
static void DeleteNow();
// Which one to log to right now.
- // Will be NULL if there is no logging implementation to use right now.
+ // Will be NULL if there is no logging implementation to use right now and we
+ // should use stderr instead.
std::shared_ptr<LogImplementation> implementation;
// A name representing this task/(process and thread).
diff --git a/aos/logging/implementations.cc b/aos/logging/implementations.cc
index 096127a..be54eec 100644
--- a/aos/logging/implementations.cc
+++ b/aos/logging/implementations.cc
@@ -5,33 +5,17 @@
#include <algorithm>
#include <chrono>
-#include <mutex>
-#include "absl/base/call_once.h"
-#include "aos/die.h"
#include "aos/logging/printf_formats.h"
-#include "aos/stl_mutex/stl_mutex.h"
#include "aos/time/time.h"
namespace aos {
namespace logging {
+namespace internal {
namespace {
namespace chrono = ::std::chrono;
-struct GlobalState {
- std::shared_ptr<LogImplementation> implementation;
- aos::stl_mutex lock;
- static GlobalState *Get() {
- static GlobalState r;
- return &r;
- }
-};
-
-} // namespace
-namespace internal {
-namespace {
-
void FillInMessageBase(log_level level,
monotonic_clock::time_point monotonic_now,
LogMessage *message) {
@@ -61,21 +45,15 @@
message->message_length =
ExecuteFormat(message->message, sizeof(message->message), format, ap);
- message->type = LogMessage::Type::kString;
}
void PrintMessage(FILE *output, const LogMessage &message) {
-#define BASE_ARGS \
- AOS_LOGGING_BASE_ARGS( \
- message.name_length, message.name, static_cast<int32_t>(message.source), \
- message.sequence, message.level, message.seconds, message.nseconds)
- switch (message.type) {
- case LogMessage::Type::kString:
- fprintf(output, AOS_LOGGING_BASE_FORMAT "%.*s", BASE_ARGS,
- static_cast<int>(message.message_length), message.message);
- break;
- }
-#undef BASE_ARGS
+ fprintf(output, AOS_LOGGING_BASE_FORMAT "%.*s",
+ AOS_LOGGING_BASE_ARGS(message.name_length, message.name,
+ static_cast<int32_t>(message.source),
+ message.sequence, message.level,
+ message.seconds, message.nseconds),
+ static_cast<int>(message.message_length), message.message);
}
} // namespace internal
@@ -95,55 +73,13 @@
}
void SetImplementation(std::shared_ptr<LogImplementation> implementation) {
- Init();
- GlobalState *const global = GlobalState::Get();
- std::unique_lock<aos::stl_mutex> locker(global->lock);
- global->implementation = std::move(implementation);
-}
-
-std::shared_ptr<LogImplementation> SwapImplementation(
- std::shared_ptr<LogImplementation> implementation) {
- std::shared_ptr<LogImplementation> result;
- {
- GlobalState *const global = GlobalState::Get();
- std::unique_lock<aos::stl_mutex> locker(global->lock);
- result = std::move(global->implementation);
- global->implementation = std::move(implementation);
- }
- Cleanup();
- return result;
+ internal::Context *context = internal::Context::Get();
+ context->implementation = std::move(implementation);
}
std::shared_ptr<LogImplementation> GetImplementation() {
- GlobalState *const global = GlobalState::Get();
- std::unique_lock<aos::stl_mutex> locker(global->lock);
- CHECK(global->implementation);
- return global->implementation;
-}
-
-namespace {
-
-struct DoInit {
- DoInit() {
- GlobalState *const global = GlobalState::Get();
- std::unique_lock<aos::stl_mutex> locker(global->lock);
- CHECK(!global->implementation);
- global->implementation = std::make_shared<StreamLogImplementation>(stdout);
- }
-};
-
-} // namespace
-
-void Init() { static DoInit do_init; }
-
-void Load() { internal::Context::Get(); }
-
-void Cleanup() { internal::Context::Delete(); }
-
-void RegisterCallbackImplementation(
- const ::std::function<void(const LogMessage &)> &callback) {
- Init();
- SetImplementation(std::make_shared<CallbackLogImplementation>(callback));
+ internal::Context *context = internal::Context::Get();
+ return context->implementation;
}
} // namespace logging
diff --git a/aos/logging/implementations.h b/aos/logging/implementations.h
index 962982b..6395c37 100644
--- a/aos/logging/implementations.h
+++ b/aos/logging/implementations.h
@@ -35,8 +35,6 @@
// Contains all of the information about a given logging call.
struct LogMessage {
- enum class Type : uint8_t { kString };
-
int32_t seconds, nseconds;
// message_length is just the length of the actual data (which member depends
// on the type).
@@ -45,26 +43,9 @@
static_assert(sizeof(source) == 4, "that's how they get printed");
// Per task/thread.
uint16_t sequence;
- Type type;
log_level level;
char name[LOG_MESSAGE_NAME_LEN];
- union {
- char message[LOG_MESSAGE_LEN];
- struct {
- uint32_t type_id;
- size_t string_length;
- // The message string and then the serialized structure.
- char serialized[LOG_MESSAGE_LEN - sizeof(type) - sizeof(string_length)];
- } structure;
- struct {
- // The type ID of the element type.
- uint32_t type;
- int rows, cols;
- size_t string_length;
- // The message string and then the serialized matrix.
- char data[LOG_MESSAGE_LEN - sizeof(type) - sizeof(rows) - sizeof(cols)];
- } matrix;
- };
+ char message[LOG_MESSAGE_LEN];
};
static_assert(shm_ok<LogMessage>::value, "it's going in a queue");
@@ -118,20 +99,13 @@
FILE *const stream_;
};
+// Returns the current implementation.
std::shared_ptr<LogImplementation> GetImplementation();
// Sets the current implementation.
void SetImplementation(std::shared_ptr<LogImplementation> implementation);
-// Updates the log implementation, returning the current implementation.
-std::shared_ptr<LogImplementation> SwapImplementation(
- std::shared_ptr<LogImplementation> implementation);
-
-// Must be called at least once per process/load before anything else is
-// called. This function is safe to call multiple times from multiple
-// tasks/threads.
-void Init();
-
+// A logging implementation which just uses a callback.
class CallbackLogImplementation : public HandleMessageLogImplementation {
public:
CallbackLogImplementation(
@@ -144,27 +118,13 @@
::std::function<void(const LogMessage &)> callback_;
};
-// Resets all information in this task/thread to its initial state.
-// NOTE: This is not the opposite of Init(). The state that this deletes is
-// lazily created when needed. It is actually the opposite of Load().
-void Cleanup();
-
-void RegisterCallbackImplementation(
- const ::std::function<void(const LogMessage &)> &callback);
-
class ScopedLogRestorer {
public:
- ScopedLogRestorer() = default;
-
- ~ScopedLogRestorer() {
- if (prev_impl_) {
- SetImplementation(std::move(prev_impl_));
- }
- Cleanup();
- }
+ ScopedLogRestorer() : prev_impl_(GetImplementation()) {}
+ ~ScopedLogRestorer() { SetImplementation(std::move(prev_impl_)); }
void Swap(std::shared_ptr<LogImplementation> new_impl) {
- prev_impl_ = SwapImplementation(std::move(new_impl));
+ SetImplementation(std::move(new_impl));
}
private:
diff --git a/aos/logging/implementations_test.cc b/aos/logging/implementations_test.cc
index f6cdc6f..058baab 100644
--- a/aos/logging/implementations_test.cc
+++ b/aos/logging/implementations_test.cc
@@ -92,7 +92,6 @@
}
void TearDown() override {
SetImplementation(nullptr);
- Cleanup();
internal::Context::DeleteNow();
CHECK_EQ(log_implementation.use_count(), 1);
log_implementation.reset();
diff --git a/aos/logging/interface.cc b/aos/logging/interface.cc
index b2f7b75..0cb0cd8 100644
--- a/aos/logging/interface.cc
+++ b/aos/logging/interface.cc
@@ -9,6 +9,8 @@
#include "aos/die.h"
#include "aos/logging/context.h"
+#include "aos/logging/implementations.h"
+#include "glog/logging.h"
namespace aos {
namespace logging {
@@ -21,8 +23,8 @@
const int ret = vsnprintf(output, size, format, ap);
typedef ::std::common_type<int, size_t>::type RetType;
if (ret < 0) {
- AOS_PLOG(FATAL, "vsnprintf(%p, %zd, %s, args) failed", output, size,
- format);
+ PLOG(FATAL) << "vsnprintf(" << output << ", " << size << ", " << format
+ << ", args) failed";
} else if (static_cast<RetType>(ret) >= static_cast<RetType>(size)) {
// Overwrite the '\0' at the end of the existing data and
// copy in the one on the end of continued.
@@ -31,39 +33,32 @@
return ::std::min<RetType>(ret, size);
}
-void RunWithCurrentImplementation(
- ::std::function<void(LogImplementation *)> function) {
- Context *context = Context::Get();
-
- const std::shared_ptr<LogImplementation> implementation =
- context->implementation;
- if (implementation == NULL) {
- Die("no logging implementation to use\n");
- }
- function(implementation.get());
-}
-
} // namespace internal
using internal::Context;
-void LogImplementation::DoVLog(log_level level, const char *format,
- va_list ap) {
- auto log_impl = [&](LogImplementation *implementation) {
- va_list ap1;
- va_copy(ap1, ap);
- implementation->DoLog(level, format, ap1);
- va_end(ap1);
-
- if (level == FATAL) {
- VDie(format, ap);
- }
- };
- internal::RunWithCurrentImplementation(::std::ref(log_impl));
-}
-
void VLog(log_level level, const char *format, va_list ap) {
- LogImplementation::DoVLog(level, format, ap);
+ va_list ap1;
+ va_copy(ap1, ap);
+
+ Context *context = Context::Get();
+
+ const std::shared_ptr<LogImplementation> implementation =
+ context->implementation;
+ // Log to the implementation if we have it, and stderr as a backup.
+ if (implementation) {
+ implementation->DoLog(level, format, ap1);
+ } else {
+ aos::logging::LogMessage message;
+ aos::logging::internal::FillInMessage(level, aos::monotonic_clock::now(),
+ format, ap, &message);
+ aos::logging::internal::PrintMessage(stderr, message);
+ }
+ va_end(ap1);
+
+ if (level == FATAL) {
+ VDie(format, ap);
+ }
}
} // namespace logging
diff --git a/aos/logging/interface.h b/aos/logging/interface.h
index 3695e40..387e55d 100644
--- a/aos/logging/interface.h
+++ b/aos/logging/interface.h
@@ -21,30 +21,15 @@
// for the current LogImplementation.
void VLog(log_level level, const char *format, va_list ap)
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 2, 0)));
-// Adds to the saved up message.
-void VCork(int line, const char *function, const char *format, va_list ap)
- __attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)));
-// Actually logs the saved up message.
-void VUnCork(int line, const char *function, log_level level, const char *file,
- const char *format, va_list ap)
- __attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 5, 0)));
// Represents a system that can actually take log messages and do something
// useful with them.
-// All of the code (transitively too!) in the DoLog here can make
-// normal LOG and LOG_DYNAMIC calls but can NOT call LOG_CORK/LOG_UNCORK. These
-// calls will not result in DoLog recursing. However, implementations must be
-// safe to call from multiple threads/tasks at the same time. Also, any other
-// overriden methods may end up logging through a given implementation's DoLog.
class LogImplementation {
public:
LogImplementation() {}
virtual ~LogImplementation() {}
- virtual bool fill_type_cache() { return true; }
-
- protected:
// Actually logs the given message. Implementations should somehow create a
// LogMessage and then call internal::FillInMessage.
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0))) virtual void DoLog(
@@ -56,15 +41,6 @@
DoLog(level, format, ap);
va_end(ap);
}
-
- private:
- // These functions call similar methods on the "current" LogImplementation or
- // Die if they can't find one.
- // levels is how many LogImplementations to not use off the stack.
- static void DoVLog(log_level, const char *format, va_list ap)
- __attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 2, 0)));
-
- friend void VLog(log_level, const char *, va_list);
};
namespace internal {
@@ -75,12 +51,6 @@
va_list ap)
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)));
-// Runs the given function with the current LogImplementation (handles switching
-// it out while running function etc).
-// levels is how many LogImplementations to not use off the stack.
-void RunWithCurrentImplementation(
- int levels, ::std::function<void(LogImplementation *)> function);
-
} // namespace internal
} // namespace logging
} // namespace aos