Use the event loop name instead of thread name for AOS_LOG
This kills 2 birds with 1 stone.
1) A simulated event loop should print out the name of each event
loop, not the program name.
2) prctl(PR_GET_NAME, thread_name_array) can require higher privileges
sometimes, and is un-necesary for simulations. See 1)
Change-Id: I48731b1cabe34ec66a97f27ee720ba3081da4e94
Signed-off-by: Austin Schuh <austin.linux@gmail.com>
diff --git a/aos/actions/actor.h b/aos/actions/actor.h
index 560e242..a000257 100644
--- a/aos/actions/actor.h
+++ b/aos/actions/actor.h
@@ -27,13 +27,14 @@
: event_loop_(event_loop),
status_sender_(event_loop->MakeSender<Status>(name)),
goal_fetcher_(event_loop->MakeFetcher<GoalType>(name)) {
- AOS_LOG(INFO, "Constructing action %s\n", name.c_str());
event_loop->MakeWatcher(name,
[this](const GoalType &goal) { HandleGoal(goal); });
// Send out an inital status saying we aren't running to wake up any users
// who might be waiting forever for the previous action.
event_loop->OnRun([this]() {
+ AOS_LOG(INFO, "Constructing action %s\n",
+ status_sender_.channel()->name()->c_str());
auto builder = status_sender_.MakeBuilder();
Status::Builder status_builder = builder.template MakeBuilder<Status>();
status_builder.add_running(0);
diff --git a/aos/events/BUILD b/aos/events/BUILD
index 0f19beb..f36da1e 100644
--- a/aos/events/BUILD
+++ b/aos/events/BUILD
@@ -312,6 +312,7 @@
":test_message_schema",
":timing_report_schema",
"//aos:realtime",
+ "//aos/logging:log_message_fbs",
"//aos/logging:log_message_schema",
"//aos/network:message_bridge_client_schema",
"//aos/network:message_bridge_server_schema",
diff --git a/aos/events/aos_logging.cc b/aos/events/aos_logging.cc
index 5b6f72c..bc4513b 100644
--- a/aos/events/aos_logging.cc
+++ b/aos/events/aos_logging.cc
@@ -2,7 +2,8 @@
namespace aos {
-void AosLogToFbs::Initialize(Sender<logging::LogMessageFbs> log_sender) {
+void AosLogToFbs::Initialize(const std::string *name,
+ Sender<logging::LogMessageFbs> log_sender) {
log_sender_ = std::move(log_sender);
if (log_sender_) {
implementation_ = std::make_shared<logging::CallbackLogImplementation>(
@@ -23,7 +24,8 @@
builder.add_name(name_str);
message.Send(builder.Finish());
- });
+ },
+ name);
}
}
diff --git a/aos/events/aos_logging.h b/aos/events/aos_logging.h
index e99edb7..efb2b25 100644
--- a/aos/events/aos_logging.h
+++ b/aos/events/aos_logging.h
@@ -11,7 +11,10 @@
public:
AosLogToFbs() {}
- void Initialize(Sender<logging::LogMessageFbs> log_sender);
+ // Initializes a sender with the provided name and sender. Note: the name
+ // needs to be valid until this object is destroyed.
+ void Initialize(const std::string *name,
+ Sender<logging::LogMessageFbs> log_sender);
std::shared_ptr<logging::LogImplementation> implementation() const {
return implementation_;
}
diff --git a/aos/events/event_loop_param_test.cc b/aos/events/event_loop_param_test.cc
index d3d21ac..2749f60 100644
--- a/aos/events/event_loop_param_test.cc
+++ b/aos/events/event_loop_param_test.cc
@@ -5,6 +5,8 @@
#include <unordered_set>
#include "aos/flatbuffer_merge.h"
+#include "aos/logging/log_message_generated.h"
+#include "aos/logging/logging.h"
#include "aos/realtime.h"
#include "glog/logging.h"
#include "gmock/gmock.h"
@@ -947,6 +949,74 @@
Run();
}
+// Verify that AOS_LOG has the right name.
+TEST_P(AbstractEventLoopTest, AOSLog) {
+ auto loop2 = MakePrimary("loop1");
+ auto loop1 = Make("loop0");
+
+ auto fetcher = loop1->MakeFetcher<aos::logging::LogMessageFbs>("/aos");
+
+ EXPECT_FALSE(fetcher.Fetch());
+
+ loop2->OnRun([&]() {
+ AOS_LOG(INFO, "Testing123");
+ this->Exit();
+ });
+
+ Run();
+ EXPECT_TRUE(fetcher.Fetch());
+ EXPECT_EQ(fetcher->name()->string_view(), "loop1");
+}
+
+// Verify that AOS_LOG has the right name in a watcher.
+TEST_P(AbstractEventLoopTest, AOSLogWatcher) {
+ auto loop2 = MakePrimary("loop1");
+ auto loop1 = Make("loop0");
+
+ auto fetcher = loop1->MakeFetcher<aos::logging::LogMessageFbs>("/aos");
+
+ EXPECT_FALSE(fetcher.Fetch());
+
+ auto sender = loop1->MakeSender<TestMessage>("/test2");
+
+ loop2->MakeWatcher("/test2", [&](const TestMessage & /*message*/) {
+ AOS_LOG(INFO, "Testing123");
+ this->Exit();
+ });
+
+ loop2->OnRun([&]() {
+ aos::Sender<TestMessage>::Builder msg = sender.MakeBuilder();
+ TestMessage::Builder builder = msg.MakeBuilder<TestMessage>();
+ builder.add_value(200);
+ ASSERT_TRUE(msg.Send(builder.Finish()));
+ });
+
+ Run();
+ EXPECT_TRUE(fetcher.Fetch());
+ EXPECT_EQ(fetcher->name()->string_view(), "loop1");
+}
+
+// Verify that AOS_LOG has the right name in a timer.
+TEST_P(AbstractEventLoopTest, AOSLogTimer) {
+ auto loop2 = MakePrimary("loop1");
+ auto loop1 = Make("loop0");
+
+ auto fetcher = loop1->MakeFetcher<aos::logging::LogMessageFbs>("/aos");
+
+ EXPECT_FALSE(fetcher.Fetch());
+
+ auto test_timer = loop2->AddTimer([&]() {
+ AOS_LOG(INFO, "Testing123");
+ this->Exit();
+ });
+
+ loop2->OnRun([&]() { test_timer->Setup(loop2->monotonic_now()); });
+
+ Run();
+ EXPECT_TRUE(fetcher.Fetch());
+ EXPECT_EQ(fetcher->name()->string_view(), "loop1");
+}
+
// Verify that timer intervals and duration function properly.
TEST_P(AbstractEventLoopTest, TimerIntervalAndDuration) {
// Force a slower rate so we are guaranteed to have reports for our timer.
diff --git a/aos/events/shm_event_loop.cc b/aos/events/shm_event_loop.cc
index c70fef6..a215040 100644
--- a/aos/events/shm_event_loop.cc
+++ b/aos/events/shm_event_loop.cc
@@ -1092,7 +1092,7 @@
logging::ScopedLogRestorer prev_logger;
AosLogToFbs aos_logger;
if (!skip_logger_) {
- aos_logger.Initialize(MakeSender<logging::LogMessageFbs>("/aos"));
+ aos_logger.Initialize(&name_, MakeSender<logging::LogMessageFbs>("/aos"));
prev_logger.Swap(aos_logger.implementation());
}
diff --git a/aos/events/shm_event_loop.h b/aos/events/shm_event_loop.h
index 3245f11..71dff4e 100644
--- a/aos/events/shm_event_loop.h
+++ b/aos/events/shm_event_loop.h
@@ -38,8 +38,11 @@
ShmEventLoop(const Flatbuffer<Configuration> &configuration)
: ShmEventLoop(&configuration.message()) {}
ShmEventLoop(const Configuration *configuration);
+ ShmEventLoop(const ShmEventLoop &) = delete;
~ShmEventLoop() override;
+ void operator=(ShmEventLoop const &) = delete;
+
// Runs the event loop until Exit is called, or ^C is caught.
void Run();
// Exits the event loop. Async safe.
diff --git a/aos/events/simulated_event_loop.cc b/aos/events/simulated_event_loop.cc
index 121e164..9e12481 100644
--- a/aos/events/simulated_event_loop.cc
+++ b/aos/events/simulated_event_loop.cc
@@ -609,6 +609,10 @@
void OnRun(::std::function<void()> on_run) override {
CHECK(!is_running()) << ": Cannot register OnRun callback while running.";
scheduler_->ScheduleOnRun([this, on_run = std::move(on_run)]() {
+ logging::ScopedLogRestorer prev_logger;
+ if (log_impl_) {
+ prev_logger.Swap(log_impl_);
+ }
ScopedMarkRealtimeRestorer rt(priority() > 0);
SetTimerContext(monotonic_now());
on_run();
@@ -638,7 +642,8 @@
void Setup() {
MaybeScheduleTimingReports();
if (!skip_logger_) {
- log_sender_.Initialize(MakeSender<logging::LogMessageFbs>("/aos"));
+ log_sender_.Initialize(&name_,
+ MakeSender<logging::LogMessageFbs>("/aos"));
log_impl_ = log_sender_.implementation();
}
}
diff --git a/aos/logging/context.cc b/aos/logging/context.cc
index b0fd32e..30d275b 100644
--- a/aos/logging/context.cc
+++ b/aos/logging/context.cc
@@ -78,13 +78,23 @@
// Used in aos/linux_code/init.cc when a thread's name is changed.
void ReloadThreadName() {
if (my_context.created()) {
+ my_context->ClearName();
+ }
+}
+
+void Context::ClearName() { name_size = std::numeric_limits<size_t>::max(); }
+
+std::string_view Context::MyName() {
+ if (name_size == std::numeric_limits<size_t>::max()) {
::std::string my_name = GetMyName();
if (my_name.size() + 1 > sizeof(Context::name)) {
Die("logging: process/thread name '%s' is too long\n", my_name.c_str());
}
- strcpy(my_context->name, my_name.c_str());
- my_context->name_size = my_name.size();
+ strcpy(name, my_name.c_str());
+ name_size = my_name.size();
}
+
+ return std::string_view(&name[0], name_size);
}
Context *Context::Get() {
@@ -94,7 +104,7 @@
}
if (__builtin_expect(!my_context.created(), false)) {
my_context.Create();
- ReloadThreadName();
+ my_context->ClearName();
my_context->source = getpid();
}
return my_context.get();
diff --git a/aos/logging/context.h b/aos/logging/context.h
index 25a7233..721b04b 100644
--- a/aos/logging/context.h
+++ b/aos/logging/context.h
@@ -8,6 +8,7 @@
#include <climits>
#include <cstddef>
#include <memory>
+#include <string_view>
#include "aos/logging/sizes.h"
@@ -50,14 +51,19 @@
std::shared_ptr<LogImplementation> implementation;
// A name representing this task/(process and thread).
- char name[LOG_MESSAGE_NAME_LEN];
- size_t name_size;
+ std::string_view MyName();
+ // Clears the cached name so MyName re-checks the thread's actual name.
+ void ClearName();
// What to assign LogMessage::source to in this task/thread.
pid_t source;
// The sequence value to send out with the next message.
uint16_t sequence;
+
+ private:
+ size_t name_size;
+ char name[LOG_MESSAGE_NAME_LEN];
};
} // namespace internal
diff --git a/aos/logging/implementations.cc b/aos/logging/implementations.cc
index 96d00f9..3b4f905 100644
--- a/aos/logging/implementations.cc
+++ b/aos/logging/implementations.cc
@@ -15,15 +15,15 @@
namespace chrono = ::std::chrono;
-void FillInMessageBase(log_level level,
+void FillInMessageBase(log_level level, std::string_view name,
monotonic_clock::time_point monotonic_now,
LogMessage *message) {
Context *context = Context::Get();
message->level = level;
message->source = context->source;
- memcpy(message->name, context->name, context->name_size);
- message->name_length = context->name_size;
+ memcpy(message->name, name.data(), name.size());
+ message->name_length = name.size();
message->seconds =
chrono::duration_cast<chrono::seconds>(monotonic_now.time_since_epoch())
@@ -38,9 +38,10 @@
} // namespace
-void FillInMessage(log_level level, monotonic_clock::time_point monotonic_now,
+void FillInMessage(log_level level, std::string_view name,
+ monotonic_clock::time_point monotonic_now,
const char *format, va_list ap, LogMessage *message) {
- FillInMessageBase(level, monotonic_now, message);
+ FillInMessageBase(level, name, monotonic_now, message);
message->message_length =
ExecuteFormat(message->message, sizeof(message->message), format, ap);
@@ -60,7 +61,8 @@
void HandleMessageLogImplementation::DoLog(log_level level, const char *format,
va_list ap) {
LogMessage message;
- internal::FillInMessage(level, monotonic_now(), format, ap, &message);
+ internal::FillInMessage(level, MyName(), monotonic_now(), format, ap,
+ &message);
HandleMessage(message);
}
diff --git a/aos/logging/implementations.h b/aos/logging/implementations.h
index de1a8dd..36a4411 100644
--- a/aos/logging/implementations.h
+++ b/aos/logging/implementations.h
@@ -13,6 +13,7 @@
#include <functional>
#include <memory>
#include <string>
+#include <string_view>
#include "aos/logging/context.h"
#include "aos/logging/interface.h"
@@ -92,6 +93,12 @@
public:
StreamLogImplementation(FILE *stream);
+ // Returns the name of this actual thread as the name.
+ std::string_view MyName() override {
+ internal::Context *context = internal::Context::Get();
+ return context->MyName();
+ }
+
private:
void HandleMessage(const LogMessage &message) override;
@@ -108,13 +115,18 @@
class CallbackLogImplementation : public HandleMessageLogImplementation {
public:
CallbackLogImplementation(
- const ::std::function<void(const LogMessage &)> &callback)
- : callback_(callback) {}
+ const ::std::function<void(const LogMessage &)> &callback,
+ const std::string *name)
+ : callback_(callback), name_(name) {}
+
+ // Returns the provided name. This is most likely the event loop name.
+ std::string_view MyName() override { return *name_; }
private:
void HandleMessage(const LogMessage &message) override { callback_(message); }
::std::function<void(const LogMessage &)> callback_;
+ const std::string *name_;
};
class ScopedLogRestorer {
@@ -136,18 +148,18 @@
// Fills in *message according to the given inputs (with type kString).
// Used for implementing LogImplementation::DoLog.
-void FillInMessage(log_level level,
+void FillInMessage(log_level level, std::string_view name,
::aos::monotonic_clock::time_point monotonic_now,
const char *format, va_list ap, LogMessage *message)
- __attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0)));
+ __attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 4, 0)));
-__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 4, 5))) static inline void
-FillInMessageVarargs(log_level level,
+__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 5, 6))) static inline void
+FillInMessageVarargs(log_level level, std::string_view name,
::aos::monotonic_clock::time_point monotonic_now,
LogMessage *message, const char *format, ...) {
va_list ap;
va_start(ap, format);
- FillInMessage(level, monotonic_now, format, ap, message);
+ FillInMessage(level, name, monotonic_now, format, ap, message);
va_end(ap);
}
diff --git a/aos/logging/implementations_test.cc b/aos/logging/implementations_test.cc
index 1bbfacf..5f98c35 100644
--- a/aos/logging/implementations_test.cc
+++ b/aos/logging/implementations_test.cc
@@ -24,9 +24,15 @@
return ::aos::monotonic_clock::now();
}
+ std::string_view MyName() override {
+ internal::Context *context = internal::Context::Get();
+ return context->MyName();
+ }
+
__attribute__((format(GOOD_PRINTF_FORMAT_TYPE, 3, 0))) void DoLog(
log_level level, const char *format, va_list ap) override {
- internal::FillInMessage(level, monotonic_now(), format, ap, &message_);
+ internal::FillInMessage(level, MyName(), monotonic_now(), format, ap,
+ &message_);
if (level == FATAL) {
internal::PrintMessage(stderr, message_);
@@ -68,12 +74,13 @@
static_cast<uint32_t>(log_implementation->message().source),
static_cast<uint32_t>(context->source));
}
- if (log_implementation->message().name_length != context->name_size ||
- memcmp(log_implementation->message().name, context->name,
- context->name_size) != 0) {
+ if (log_implementation->message().name_length != context->MyName().size() ||
+ memcmp(log_implementation->message().name, context->MyName().data(),
+ context->MyName().size()) != 0) {
AOS_LOG(FATAL, "got a message from %.*s, but we're %s\n",
static_cast<int>(log_implementation->message().name_length),
- log_implementation->message().name, context->name);
+ log_implementation->message().name,
+ std::string(context->MyName()).c_str());
}
if (strstr(log_implementation->message().message, message.c_str()) ==
NULL) {
@@ -221,11 +228,12 @@
SetImplementation(std::make_shared<StreamLogImplementation>(stdout));
LogImplementation *curr_impl = GetImplementation().get();
+ std::string name = "name";
{
ScopedLogRestorer log_restorer;
- log_restorer.Swap(
- std::make_shared<CallbackLogImplementation>([](const LogMessage &) {}));
+ log_restorer.Swap(std::make_shared<CallbackLogImplementation>(
+ [](const LogMessage &) {}, &name));
ASSERT_NE(curr_impl, GetImplementation().get());
}
diff --git a/aos/logging/interface.cc b/aos/logging/interface.cc
index 39492ad..336dbc0 100644
--- a/aos/logging/interface.cc
+++ b/aos/logging/interface.cc
@@ -49,8 +49,9 @@
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::FillInMessage(level, context->MyName(),
+ aos::monotonic_clock::now(), format,
+ ap, &message);
aos::logging::internal::PrintMessage(stderr, message);
}
va_end(ap1);
diff --git a/aos/logging/interface.h b/aos/logging/interface.h
index f6fa249..d2663e7 100644
--- a/aos/logging/interface.h
+++ b/aos/logging/interface.h
@@ -4,6 +4,7 @@
#include <cstdarg>
#include <functional>
#include <string>
+#include <string_view>
#include "aos/logging/logging.h"
#include "aos/macros.h"
@@ -29,6 +30,10 @@
virtual ~LogImplementation() {}
+ // Returns the identifying name to be used when logging. This could be the
+ // event loop name or the thread name.
+ virtual std::string_view MyName() = 0;
+
// 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(
diff --git a/aos/testing/test_logging.cc b/aos/testing/test_logging.cc
index d0cea26..d2466c9 100644
--- a/aos/testing/test_logging.cc
+++ b/aos/testing/test_logging.cc
@@ -23,6 +23,8 @@
return ::aos::monotonic_clock::now();
}
+ std::string_view MyName() override { return "Name"; }
+
// This class has to be a singleton so that everybody can get access to the
// same instance to read out the messages etc.
static std::shared_ptr<TestLogImplementation> GetInstance() {
diff --git a/aos/util/death_test_log_implementation.h b/aos/util/death_test_log_implementation.h
index 7065141..7765b5b 100644
--- a/aos/util/death_test_log_implementation.h
+++ b/aos/util/death_test_log_implementation.h
@@ -3,6 +3,7 @@
#include <cstdlib>
+#include "aos/logging/context.h"
#include "aos/logging/implementations.h"
namespace aos {
@@ -14,6 +15,10 @@
class DeathTestLogImplementation
: public logging::HandleMessageLogImplementation {
public:
+ std::string_view MyName() override {
+ logging::internal::Context *context = logging::internal::Context::Get();
+ return context->MyName();
+ }
virtual void HandleMessage(const logging::LogMessage &message) override {
if (message.level == FATAL) {
logging::internal::PrintMessage(stderr, message);