AOS_LOG to messages
Change-Id: I0cb78a957a180f4472fc3e78a75eade63e4e43b8
diff --git a/aos/aos_dump.cc b/aos/aos_dump.cc
index 8d6c2b1..2ecfe5e 100644
--- a/aos/aos_dump.cc
+++ b/aos/aos_dump.cc
@@ -27,6 +27,7 @@
const aos::Configuration *config_msg = &config.message();
::aos::ShmEventLoop event_loop(config_msg);
event_loop.SkipTimingReport();
+ event_loop.SkipAosLog();
if (argc == 1) {
std::cout << "Channels:\n";
diff --git a/aos/controls/control_loop_test.h b/aos/controls/control_loop_test.h
index 25e1a45..76e82eb 100644
--- a/aos/controls/control_loop_test.h
+++ b/aos/controls/control_loop_test.h
@@ -4,8 +4,6 @@
#include <chrono>
#include <string_view>
-#include "gtest/gtest.h"
-
#include "aos/events/simulated_event_loop.h"
#include "aos/flatbuffers.h"
#include "aos/json_to_flatbuffer.h"
@@ -13,6 +11,7 @@
#include "aos/robot_state/robot_state_generated.h"
#include "aos/testing/test_logging.h"
#include "aos/time/time.h"
+#include "gtest/gtest.h"
namespace aos {
namespace testing {
@@ -80,9 +79,7 @@
// Simulate a reset of the process reading sensors, which tells loops that all
// index counts etc will be reset.
- void SimulateSensorReset() {
- ++reader_pid_;
- }
+ void SimulateSensorReset() { ++reader_pid_; }
// Sets the battery voltage in robot_state.
void set_battery_voltage(double battery_voltage) {
@@ -186,7 +183,8 @@
ControlLoopTestTemplated<TestBaseClass>::kTimeTick;
template <typename TestBaseClass>
-constexpr ::std::chrono::milliseconds ControlLoopTestTemplated<TestBaseClass>::kDSPacketTime;
+constexpr ::std::chrono::milliseconds
+ ControlLoopTestTemplated<TestBaseClass>::kDSPacketTime;
} // namespace testing
} // namespace aos
diff --git a/aos/events/BUILD b/aos/events/BUILD
index 9cfdf10..0470b6e 100644
--- a/aos/events/BUILD
+++ b/aos/events/BUILD
@@ -69,6 +69,7 @@
"//aos:configuration_fbs",
"//aos:flatbuffers",
"//aos/ipc_lib:data_alignment",
+ "//aos/logging:implementations",
"//aos/time",
"//aos/util:phased_loop",
"@com_github_google_flatbuffers//:flatbuffers",
@@ -114,6 +115,7 @@
src = "aos.json",
flatbuffers = [
":event_loop_fbs",
+ "//aos/logging:log_message_fbs",
],
)
@@ -215,6 +217,7 @@
hdrs = ["shm_event_loop.h"],
visibility = ["//visibility:public"],
deps = [
+ ":aos_logging",
":epoll",
":event_loop",
":event_loop_fbs",
@@ -291,6 +294,7 @@
],
visibility = ["//visibility:public"],
deps = [
+ ":aos_logging",
":event_loop",
":simple_channel",
"//aos/ipc_lib:index",
@@ -298,3 +302,19 @@
"@com_google_absl//absl/container:btree",
],
)
+
+cc_library(
+ name = "aos_logging",
+ srcs = [
+ "aos_logging.cc",
+ ],
+ hdrs = [
+ "aos_logging.h",
+ ],
+ visibility = ["//visibility:public"],
+ deps = [
+ ":event_loop",
+ "//aos/logging:implementations",
+ "//aos/logging:log_message_fbs",
+ ],
+)
diff --git a/aos/events/aos.json b/aos/events/aos.json
index 5d00baa..36b4610 100644
--- a/aos/events/aos.json
+++ b/aos/events/aos.json
@@ -7,6 +7,12 @@
"frequency": 50,
"num_senders": 20,
"max_size": 2048
+ },
+ {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "frequency": 200,
+ "num_senders": 20
}
]
}
diff --git a/aos/events/aos_logging.cc b/aos/events/aos_logging.cc
new file mode 100644
index 0000000..f831071
--- /dev/null
+++ b/aos/events/aos_logging.cc
@@ -0,0 +1,31 @@
+#include "aos/events/aos_logging.h"
+
+namespace aos {
+
+void AosLogToFbs::Initialize(Sender<logging::LogMessageFbs> log_sender) {
+ log_sender_ = std::move(log_sender);
+ if (log_sender_) {
+ logging::RegisterCallbackImplementation(
+ [this](const logging::LogMessage &message_data) {
+ aos::Sender<logging::LogMessageFbs>::Builder message =
+ log_sender_.MakeBuilder();
+ auto message_str = message.fbb()->CreateString(
+ message_data.message, message_data.message_length);
+ auto name_str = message.fbb()->CreateString(message_data.name,
+ message_data.name_length);
+
+ ::aos::logging::LogMessageFbs::Builder builder =
+ message.MakeBuilder<::aos::logging::LogMessageFbs>();
+ builder.add_message(message_str);
+ builder.add_level(
+ static_cast<::aos::logging::Level>(message_data.level));
+ builder.add_source(message_data.source);
+ builder.add_name(name_str);
+
+ message.Send(builder.Finish());
+ },
+ false);
+ }
+}
+
+} // namespace aos
diff --git a/aos/events/aos_logging.h b/aos/events/aos_logging.h
new file mode 100644
index 0000000..b50569c
--- /dev/null
+++ b/aos/events/aos_logging.h
@@ -0,0 +1,25 @@
+#ifndef AOS_LOGGING_H_
+#define AOS_LOGGING_H_
+
+#include "aos/events/event_loop.h"
+#include "aos/logging/implementations.h"
+#include "aos/logging/log_message_generated.h"
+
+namespace aos {
+
+class AosLogToFbs {
+ public:
+ AosLogToFbs() {}
+
+ // TODO(Tyler): Deregister logger on destruction to avoid memory leaks
+
+ void Initialize(Sender<logging::LogMessageFbs> log_sender);
+
+ private:
+ Sender<logging::LogMessageFbs> log_sender_;
+ logging::ScopedLogRestorer prev_logger_;
+};
+
+} // namespace aos
+
+#endif // AOS_LOGGING_H_
diff --git a/aos/events/event_loop.cc b/aos/events/event_loop.cc
index 76b83c9..5b6f5c6 100644
--- a/aos/events/event_loop.cc
+++ b/aos/events/event_loop.cc
@@ -2,6 +2,7 @@
#include "aos/configuration.h"
#include "aos/configuration_generated.h"
+#include "aos/logging/implementations.h"
#include "glog/logging.h"
DEFINE_bool(timing_reports, true, "Publish timing reports.");
@@ -65,6 +66,12 @@
PhasedLoopHandler::~PhasedLoopHandler() {}
+EventLoop::EventLoop(const Configuration *configuration)
+ : timing_report_(flatbuffers::DetachedBuffer()),
+ configuration_(configuration) {
+ logging::Init();
+}
+
EventLoop::~EventLoop() {
CHECK_EQ(senders_.size(), 0u) << ": Not all senders destroyed";
CHECK_EQ(events_.size(), 0u) << ": Not all events unregistered";
diff --git a/aos/events/event_loop.h b/aos/events/event_loop.h
index 3fe46ec..581f41c 100644
--- a/aos/events/event_loop.h
+++ b/aos/events/event_loop.h
@@ -288,6 +288,10 @@
// Returns the name of the underlying queue.
const Channel *channel() const { return sender_->channel(); }
+ operator bool() {
+ return sender_ ? true : false;
+ }
+
private:
friend class EventLoop;
Sender(std::unique_ptr<RawSender> sender) : sender_(std::move(sender)) {}
@@ -378,9 +382,7 @@
class EventLoop {
public:
- EventLoop(const Configuration *configuration)
- : timing_report_(flatbuffers::DetachedBuffer()),
- configuration_(configuration) {}
+ EventLoop(const Configuration *configuration);
virtual ~EventLoop();
@@ -504,6 +506,9 @@
// Prevents the event loop from sending a timing report.
void SkipTimingReport() { skip_timing_report_ = true; }
+ // Prevents AOS_LOG being sent to message on /aos
+ void SkipAosLog() { skip_logger_ = true; }
+
protected:
// Sets the name of the event loop. This is the application name.
virtual void set_name(const std::string_view name) = 0;
@@ -573,6 +578,9 @@
std::vector<EventLoopEvent *> events_;
+ // If true, don't send AOS_LOG to /aos
+ bool skip_logger_ = false;
+
private:
virtual pid_t GetTid() = 0;
diff --git a/aos/events/event_loop_param_test.cc b/aos/events/event_loop_param_test.cc
index b72a8e2..096d84a 100644
--- a/aos/events/event_loop_param_test.cc
+++ b/aos/events/event_loop_param_test.cc
@@ -2,13 +2,11 @@
#include <chrono>
-#include "glog/logging.h"
-#include "gmock/gmock.h"
-#include "gtest/gtest.h"
-
#include "aos/events/test_message_generated.h"
#include "aos/flatbuffer_merge.h"
#include "glog/logging.h"
+#include "gmock/gmock.h"
+#include "gtest/gtest.h"
namespace aos {
namespace testing {
@@ -409,21 +407,19 @@
EXPECT_THAT(values, ::testing::ElementsAreArray({201, 202, 204}));
}
-
// Tests that FetchNext behaves correctly when we get two messages in the queue
// but don't consume the first until after the second has been sent.
TEST_P(AbstractEventLoopTest, FetchNextTest) {
-
auto send_loop = Make();
auto fetch_loop = Make();
auto sender = send_loop->MakeSender<TestMessage>("/test");
Fetcher<TestMessage> fetcher = fetch_loop->MakeFetcher<TestMessage>("/test");
{
- aos::Sender<TestMessage>::Builder msg = sender.MakeBuilder();
- TestMessage::Builder builder = msg.MakeBuilder<TestMessage>();
- builder.add_value(100);
- ASSERT_TRUE(msg.Send(builder.Finish()));
+ aos::Sender<TestMessage>::Builder msg = sender.MakeBuilder();
+ TestMessage::Builder builder = msg.MakeBuilder<TestMessage>();
+ builder.add_value(100);
+ ASSERT_TRUE(msg.Send(builder.Finish()));
}
{
@@ -642,7 +638,7 @@
EXPECT_EQ(report.message().name()->string_view(), "primary");
ASSERT_NE(report.message().senders(), nullptr);
- EXPECT_EQ(report.message().senders()->size(), 1);
+ EXPECT_EQ(report.message().senders()->size(), 2);
ASSERT_NE(report.message().timers(), nullptr);
EXPECT_EQ(report.message().timers()->size(), 2);
@@ -690,13 +686,10 @@
iteration_list.push_back(loop->monotonic_now());
});
- auto ender_timer = loop->AddTimer([&test_timer]() {
- test_timer->Disable();
- });
+ auto ender_timer = loop->AddTimer([&test_timer]() { test_timer->Disable(); });
test_timer->Setup(loop->monotonic_now(), ::std::chrono::milliseconds(20));
- ender_timer->Setup(loop->monotonic_now() +
- ::std::chrono::milliseconds(45));
+ ender_timer->Setup(loop->monotonic_now() + ::std::chrono::milliseconds(45));
EndEventLoop(loop.get(), ::std::chrono::milliseconds(150));
Run();
@@ -708,7 +701,8 @@
TEST_P(AbstractEventLoopDeathTest, InvalidChannel) {
auto loop = MakePrimary();
- const Channel *channel = loop->configuration()->channels()->Get(1);
+ const Channel *channel = configuration::GetChannel(
+ loop->configuration(), "/test", "aos.TestMessage", "", nullptr);
FlatbufferDetachedBuffer<Channel> channel_copy = CopyFlatBuffer(channel);
@@ -754,8 +748,7 @@
const aos::monotonic_clock::time_point monotonic_now =
loop1->monotonic_now();
- const aos::realtime_clock::time_point realtime_now =
- loop1->realtime_now();
+ const aos::realtime_clock::time_point realtime_now = loop1->realtime_now();
EXPECT_LE(loop1->context().monotonic_event_time, monotonic_now);
EXPECT_LE(loop1->context().realtime_event_time, realtime_now);
@@ -932,7 +925,7 @@
EXPECT_EQ(report.message().name()->string_view(), "primary");
ASSERT_NE(report.message().senders(), nullptr);
- EXPECT_EQ(report.message().senders()->size(), 1);
+ EXPECT_EQ(report.message().senders()->size(), 2);
ASSERT_NE(report.message().timers(), nullptr);
EXPECT_EQ(report.message().timers()->size(), 1);
@@ -996,7 +989,7 @@
EXPECT_EQ(primary_report.message().name()->string_view(), "primary");
ASSERT_NE(primary_report.message().senders(), nullptr);
- EXPECT_EQ(primary_report.message().senders()->size(), 2);
+ EXPECT_EQ(primary_report.message().senders()->size(), 3);
// Confirm that the sender looks sane.
EXPECT_EQ(
@@ -1148,7 +1141,7 @@
EXPECT_EQ(primary_report.message().name()->string_view(), "primary");
ASSERT_NE(primary_report.message().senders(), nullptr);
- EXPECT_EQ(primary_report.message().senders()->size(), 1);
+ EXPECT_EQ(primary_report.message().senders()->size(), 2);
ASSERT_NE(primary_report.message().timers(), nullptr);
EXPECT_EQ(primary_report.message().timers()->size(), 4);
@@ -1164,10 +1157,8 @@
EXPECT_EQ(primary_report.message().fetchers()->Get(0)->count(), 1);
EXPECT_GE(primary_report.message().fetchers()->Get(0)->latency()->average(),
0.1);
- EXPECT_GE(primary_report.message().fetchers()->Get(0)->latency()->min(),
- 0.1);
- EXPECT_GE(primary_report.message().fetchers()->Get(0)->latency()->max(),
- 0.1);
+ EXPECT_GE(primary_report.message().fetchers()->Get(0)->latency()->min(), 0.1);
+ EXPECT_GE(primary_report.message().fetchers()->Get(0)->latency()->max(), 0.1);
EXPECT_EQ(primary_report.message()
.fetchers()
->Get(0)
@@ -1188,17 +1179,20 @@
const std::string kData("971 is the best");
std::unique_ptr<aos::RawSender> sender =
- loop1->MakeRawSender(loop1->configuration()->channels()->Get(1));
+ loop1->MakeRawSender(configuration::GetChannel(
+ loop1->configuration(), "/test", "aos.TestMessage", "", nullptr));
std::unique_ptr<aos::RawFetcher> fetcher =
- loop3->MakeRawFetcher(loop3->configuration()->channels()->Get(1));
+ loop3->MakeRawFetcher(configuration::GetChannel(
+ loop3->configuration(), "/test", "aos.TestMessage", "", nullptr));
loop2->OnRun(
[&]() { EXPECT_TRUE(sender->Send(kData.data(), kData.size())); });
bool happened = false;
loop2->MakeRawWatcher(
- loop2->configuration()->channels()->Get(1),
+ configuration::GetChannel(loop2->configuration(), "/test",
+ "aos.TestMessage", "", nullptr),
[this, &kData, &fetcher, &happened](const Context &context,
const void *message) {
happened = true;
@@ -1239,10 +1233,12 @@
aos::realtime_clock::time_point(chrono::seconds(3132));
std::unique_ptr<aos::RawSender> sender =
- loop1->MakeRawSender(loop1->configuration()->channels()->Get(1));
+ loop1->MakeRawSender(configuration::GetChannel(
+ loop1->configuration(), "/test", "aos.TestMessage", "", nullptr));
std::unique_ptr<aos::RawFetcher> fetcher =
- loop3->MakeRawFetcher(loop3->configuration()->channels()->Get(1));
+ loop3->MakeRawFetcher(configuration::GetChannel(
+ loop3->configuration(), "/test", "aos.TestMessage", "", nullptr));
loop2->OnRun([&]() {
EXPECT_TRUE(sender->Send(kData.data(), kData.size(), monotonic_remote_time,
@@ -1251,7 +1247,8 @@
bool happened = false;
loop2->MakeRawWatcher(
- loop2->configuration()->channels()->Get(1),
+ configuration::GetChannel(loop2->configuration(), "/test",
+ "aos.TestMessage", "", nullptr),
[this, monotonic_remote_time, realtime_remote_time, &fetcher, &happened](
const Context &context, const void * /*message*/) {
happened = true;
@@ -1279,12 +1276,11 @@
const std::string kData("971 is the best");
std::unique_ptr<aos::RawSender> sender =
- loop1->MakeRawSender(loop1->configuration()->channels()->Get(1));
+ loop1->MakeRawSender(configuration::GetChannel(
+ loop1->configuration(), "/test", "aos.TestMessage", "", nullptr));
- const aos::monotonic_clock::time_point monotonic_now =
- loop1->monotonic_now();
- const aos::realtime_clock::time_point realtime_now =
- loop1->realtime_now();
+ const aos::monotonic_clock::time_point monotonic_now = loop1->monotonic_now();
+ const aos::realtime_clock::time_point realtime_now = loop1->realtime_now();
EXPECT_TRUE(sender->Send(kData.data(), kData.size()));
@@ -1334,8 +1330,10 @@
auto loop1 = Make();
auto loop2 = Make();
loop1->MakeWatcher("/test", [](const TestMessage &) {});
- loop2->MakeRawWatcher(configuration()->channels()->Get(1),
- [](const Context &, const void *) {});
+ loop2->MakeRawWatcher(
+ configuration::GetChannel(configuration(), "/test", "aos.TestMessage", "",
+ nullptr),
+ [](const Context &, const void *) {});
}
// Tests that fetcher work with a node setup.
@@ -1344,7 +1342,8 @@
auto loop1 = Make();
auto fetcher = loop1->MakeFetcher<TestMessage>("/test");
- auto raw_fetcher = loop1->MakeRawFetcher(configuration()->channels()->Get(1));
+ auto raw_fetcher = loop1->MakeRawFetcher(configuration::GetChannel(
+ configuration(), "/test", "aos.TestMessage", "", nullptr));
}
// Tests that sender work with a node setup.
@@ -1365,8 +1364,10 @@
"node");
EXPECT_DEATH(
{
- loop2->MakeRawWatcher(configuration()->channels()->Get(1),
- [](const Context &, const void *) {});
+ loop2->MakeRawWatcher(
+ configuration::GetChannel(configuration(), "/test",
+ "aos.TestMessage", "", nullptr),
+ [](const Context &, const void *) {});
},
"node");
}
@@ -1380,8 +1381,8 @@
"node");
EXPECT_DEATH(
{
- auto raw_fetcher =
- loop1->MakeRawFetcher(configuration()->channels()->Get(1));
+ auto raw_fetcher = loop1->MakeRawFetcher(configuration::GetChannel(
+ configuration(), "/test", "aos.TestMessage", "", nullptr));
},
"node");
}
diff --git a/aos/events/event_loop_param_test.h b/aos/events/event_loop_param_test.h
index 89e80ae..cbd5cd1 100644
--- a/aos/events/event_loop_param_test.h
+++ b/aos/events/event_loop_param_test.h
@@ -19,6 +19,10 @@
" \"channels\": [ \n"
" {\n"
" \"name\": \"/aos\",\n"
+ " \"type\": \"aos.logging.LogMessageFbs\"\n"
+ " },\n"
+ " {\n"
+ " \"name\": \"/aos\",\n"
" \"type\": \"aos.timing.Report\"\n"
" },\n"
" {\n"
@@ -58,6 +62,16 @@
std::string json = R"config({
"channels": [
{
+ "name": "/aos/me",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "me"
+ },
+ {
+ "name": "/aos/them",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "them"
+ },
+ {
"name": "/aos",
"type": "aos.timing.Report",
"source_node": "me"
@@ -87,6 +101,28 @@
"name": "them",
"hostname": "themhostname"
}
+ ],
+ "maps": [
+ {
+ "match": {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "me"
+ },
+ "rename": {
+ "name": "/aos/me"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "them"
+ },
+ "rename": {
+ "name": "/aos/them"
+ }
+ }
]
})config";
diff --git a/aos/events/event_scheduler.cc b/aos/events/event_scheduler.cc
index 57f20ae..26752b1 100644
--- a/aos/events/event_scheduler.cc
+++ b/aos/events/event_scheduler.cc
@@ -4,6 +4,7 @@
#include <deque>
#include "aos/events/event_loop.h"
+#include "aos/logging/implementations.h"
namespace aos {
@@ -19,6 +20,7 @@
void EventScheduler::RunFor(distributed_clock::duration duration) {
const distributed_clock::time_point end_time =
distributed_now() + duration;
+ logging::ScopedLogRestorer prev_logger;
is_running_ = true;
for (std::function<void()> &on_run : on_run_) {
on_run();
@@ -39,6 +41,7 @@
}
void EventScheduler::Run() {
+ logging::ScopedLogRestorer prev_logger;
is_running_ = true;
for (std::function<void()> &on_run : on_run_) {
on_run();
diff --git a/aos/events/logging/log_cat.cc b/aos/events/logging/log_cat.cc
index 80ec8e7..f2427b8 100644
--- a/aos/events/logging/log_cat.cc
+++ b/aos/events/logging/log_cat.cc
@@ -33,6 +33,7 @@
std::unique_ptr<aos::EventLoop> printer_event_loop =
reader.event_loop_factory()->MakeEventLoop("printer", reader.node());
printer_event_loop->SkipTimingReport();
+ printer_event_loop->SkipAosLog();
bool found_channel = false;
const flatbuffers::Vector<flatbuffers::Offset<aos::Channel>> *channels =
diff --git a/aos/events/logging/log_stats.cc b/aos/events/logging/log_stats.cc
index c766fe6..65da871 100644
--- a/aos/events/logging/log_stats.cc
+++ b/aos/events/logging/log_stats.cc
@@ -67,6 +67,7 @@
std::unique_ptr<aos::EventLoop> stats_event_loop =
log_reader_factory.MakeEventLoop("logstats", reader.node());
stats_event_loop->SkipTimingReport();
+ stats_event_loop->SkipAosLog();
// Read channel info and store in vector
bool found_channel = false;
diff --git a/aos/events/logging/logger.cc b/aos/events/logging/logger.cc
index 2de17d7..c501d7b 100644
--- a/aos/events/logging/logger.cc
+++ b/aos/events/logging/logger.cc
@@ -299,8 +299,12 @@
void LogReader::Register(EventLoop *event_loop) {
event_loop_ = event_loop;
+ // We don't run timing reports when trying to print out logged data, because
+ // otherwise we would end up printing out the timing reports themselves...
+ // This is only really relevant when we are replaying into a simulation.
// Otherwise we replay the timing report and try to resend it...
event_loop_->SkipTimingReport();
+ event_loop_->SkipAosLog();
for (size_t i = 0; i < channels_.size(); ++i) {
const Channel *const original_channel =
diff --git a/aos/events/logging/multinode_pingpong.json b/aos/events/logging/multinode_pingpong.json
index f85a4e1..be8a402 100644
--- a/aos/events/logging/multinode_pingpong.json
+++ b/aos/events/logging/multinode_pingpong.json
@@ -1,5 +1,21 @@
{
"channels": [
+ {
+ "name": "/aos/pi1",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi1",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/aos/pi2",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi2",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
/* Logged on pi1 locally */
{
"name": "/aos/pi1",
@@ -57,6 +73,26 @@
}
],
"maps": [
+ {
+ "match": {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi1"
+ },
+ "rename": {
+ "name": "/aos/pi1"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi2"
+ },
+ "rename": {
+ "name": "/aos/pi2"
+ }
+ },
{
"match": {
"name": "/aos",
diff --git a/aos/events/multinode_pingpong.json b/aos/events/multinode_pingpong.json
index c0c5087..80ffe76 100644
--- a/aos/events/multinode_pingpong.json
+++ b/aos/events/multinode_pingpong.json
@@ -2,6 +2,38 @@
"channels": [
{
"name": "/aos/pi1",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi1",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/aos/pi2",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi2",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/aos/pi3",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi3",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/aos/roborio",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "roborio",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/aos/pi1",
"type": "aos.message_bridge.ServerStatistics",
"source_node": "pi1",
"frequency": 2
@@ -137,6 +169,46 @@
{
"match": {
"name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi1"
+ },
+ "rename": {
+ "name": "/aos/pi1"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi2"
+ },
+ "rename": {
+ "name": "/aos/pi2"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi3"
+ },
+ "rename": {
+ "name": "/aos/pi3"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "roborio"
+ },
+ "rename": {
+ "name": "/aos/roborio"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos",
"type": "aos.timing.Report",
"source_node": "pi1"
},
diff --git a/aos/events/shm_event_loop.cc b/aos/events/shm_event_loop.cc
index b4578cb..b3026fa 100644
--- a/aos/events/shm_event_loop.cc
+++ b/aos/events/shm_event_loop.cc
@@ -5,12 +5,14 @@
#include <sys/syscall.h>
#include <sys/types.h>
#include <unistd.h>
+
#include <algorithm>
#include <atomic>
#include <chrono>
#include <iterator>
#include <stdexcept>
+#include "aos/events/aos_logging.h"
#include "aos/events/epoll.h"
#include "aos/events/event_loop_generated.h"
#include "aos/events/timing_statistics.h"
@@ -760,38 +762,45 @@
ReserveEvents();
- aos::SetCurrentThreadName(name_.substr(0, 16));
- // Now, all the callbacks are setup. Lock everything into memory and go RT.
- if (priority_ != 0) {
- ::aos::InitRT();
+ {
+ AosLogToFbs aos_logger;
+ if (!skip_logger_) {
+ aos_logger.Initialize(MakeSender<logging::LogMessageFbs>("/aos"));
+ }
- LOG(INFO) << "Setting priority to " << priority_;
- ::aos::SetCurrentThreadRealtimePriority(priority_);
+ aos::SetCurrentThreadName(name_.substr(0, 16));
+ // Now, all the callbacks are setup. Lock everything into memory and go RT.
+ if (priority_ != 0) {
+ ::aos::InitRT();
+
+ LOG(INFO) << "Setting priority to " << priority_;
+ ::aos::SetCurrentThreadRealtimePriority(priority_);
+ }
+
+ set_is_running(true);
+
+ // Now that we are realtime (but before the OnRun handlers run), snap the
+ // queue index.
+ for (::std::unique_ptr<WatcherState> &watcher : watchers_) {
+ watcher->Startup(this);
+ }
+
+ // Now that we are RT, run all the OnRun handlers.
+ for (const auto &run : on_run_) {
+ run();
+ }
+
+ // And start our main event loop which runs all the timers and handles Quit.
+ epoll_.Run();
+
+ // Once epoll exits, there is no useful nonrt work left to do.
+ set_is_running(false);
+
+ // Nothing time or synchronization critical needs to happen after this
+ // point. Drop RT priority.
+ ::aos::UnsetCurrentThreadRealtimePriority();
}
- set_is_running(true);
-
- // Now that we are realtime (but before the OnRun handlers run), snap the
- // queue index.
- for (::std::unique_ptr<WatcherState> &watcher : watchers_) {
- watcher->Startup(this);
- }
-
- // Now that we are RT, run all the OnRun handlers.
- for (const auto &run : on_run_) {
- run();
- }
-
- // And start our main event loop which runs all the timers and handles Quit.
- epoll_.Run();
-
- // Once epoll exits, there is no useful nonrt work left to do.
- set_is_running(false);
-
- // Nothing time or synchronization critical needs to happen after this point.
- // Drop RT priority.
- ::aos::UnsetCurrentThreadRealtimePriority();
-
for (::std::unique_ptr<WatcherState> &base_watcher : watchers_) {
internal::WatcherState *watcher =
reinterpret_cast<internal::WatcherState *>(base_watcher.get());
diff --git a/aos/events/shm_event_loop_test.cc b/aos/events/shm_event_loop_test.cc
index 984f978..87411d2 100644
--- a/aos/events/shm_event_loop_test.cc
+++ b/aos/events/shm_event_loop_test.cc
@@ -32,6 +32,7 @@
unlink((FLAGS_shm_base + "/test2/aos.TestMessage.v1").c_str());
unlink((FLAGS_shm_base + "/test2/aos.TestMessage.v1").c_str());
unlink((FLAGS_shm_base + "/aos/aos.timing.Report.v1").c_str());
+ unlink((FLAGS_shm_base + "/aos/aos.logging.LogMessageFbs.v1").c_str());
}
~ShmEventLoopTestFactory() { FLAGS_override_hostname = ""; }
diff --git a/aos/events/simulated_event_loop.cc b/aos/events/simulated_event_loop.cc
index c857bb6..01574fa 100644
--- a/aos/events/simulated_event_loop.cc
+++ b/aos/events/simulated_event_loop.cc
@@ -8,6 +8,7 @@
#include "aos/events/simulated_network_bridge.h"
#include "aos/json_to_flatbuffer.h"
#include "aos/util/phased_loop.h"
+#include "aos/events/aos_logging.h"
namespace aos {
@@ -419,7 +420,14 @@
int priority() const override { return priority_; }
- void Setup() { MaybeScheduleTimingReports(); }
+ void Setup() {
+ MaybeScheduleTimingReports();
+ if (!skip_logger_) {
+ logging::ScopedLogRestorer prev_logger;
+ log_sender_.Initialize(MakeSender<logging::LogMessageFbs>("/aos"));
+ log_impl_ = logging::GetImplementation();
+ }
+ }
private:
friend class SimulatedTimerHandler;
@@ -455,6 +463,9 @@
const Node *const node_;
const pid_t tid_;
+
+ AosLogToFbs log_sender_;
+ logging::LogImplementation *log_impl_ = nullptr;
};
void SimulatedEventLoopFactory::set_send_delay(
@@ -553,6 +564,10 @@
const monotonic_clock::time_point monotonic_now =
simulated_event_loop_->monotonic_now();
+ logging::ScopedLogRestorer prev_logger;
+ if (simulated_event_loop_->log_impl_ != nullptr) {
+ logging::SetImplementation(simulated_event_loop_->log_impl_);
+ }
Context context = msgs_.front()->context;
if (context.remote_queue_index == 0xffffffffu) {
@@ -660,6 +675,10 @@
void SimulatedTimerHandler::HandleEvent() {
const ::aos::monotonic_clock::time_point monotonic_now =
simulated_event_loop_->monotonic_now();
+ logging::ScopedLogRestorer prev_logger;
+ if (simulated_event_loop_->log_impl_ != nullptr) {
+ logging::SetImplementation(simulated_event_loop_->log_impl_);
+ }
if (repeat_offset_ != ::aos::monotonic_clock::zero()) {
// Reschedule.
while (base_ <= monotonic_now) base_ += repeat_offset_;
@@ -706,6 +725,10 @@
void SimulatedPhasedLoopHandler::HandleEvent() {
monotonic_clock::time_point monotonic_now =
simulated_event_loop_->monotonic_now();
+ logging::ScopedLogRestorer prev_logger;
+ if (simulated_event_loop_->log_impl_ != nullptr) {
+ logging::SetImplementation(simulated_event_loop_->log_impl_);
+ }
Call(
[monotonic_now]() { return monotonic_now; },
[this](monotonic_clock::time_point sleep_time) { Schedule(sleep_time); });
diff --git a/aos/logging/BUILD b/aos/logging/BUILD
index 4931696..214df63 100644
--- a/aos/logging/BUILD
+++ b/aos/logging/BUILD
@@ -1,3 +1,5 @@
+load("@com_github_google_flatbuffers//:build_defs.bzl", "flatbuffer_cc_library")
+
# The primary client logging interface.
cc_library(
name = "logging",
@@ -150,3 +152,10 @@
"@com_google_absl//absl/base",
],
)
+
+flatbuffer_cc_library(
+ name = "log_message_fbs",
+ srcs = ["log_message.fbs"],
+ visibility = ["//visibility:public"],
+ gen_reflections = 1,
+)
diff --git a/aos/logging/implementations.cc b/aos/logging/implementations.cc
index cfc14c0..04831a2 100644
--- a/aos/logging/implementations.cc
+++ b/aos/logging/implementations.cc
@@ -131,10 +131,6 @@
void SetImplementation(LogImplementation *implementation, bool update_global) {
internal::Context *context = internal::Context::Get();
- if (implementation == nullptr) {
- AOS_LOG(FATAL, "SetImplementation got invalid implementation");
- }
-
context->implementation = implementation;
if (update_global) {
SetGlobalImplementation(implementation);
@@ -150,6 +146,10 @@
return old;
}
+LogImplementation *GetImplementation() {
+ return internal::Context::Get()->implementation;
+}
+
void Init() {
static absl::once_flag once;
absl::call_once(once, DoInit);
@@ -264,7 +264,7 @@
void RegisterCallbackImplementation(
const ::std::function<void(const LogMessage &)> &callback,
- bool update_global = true) {
+ bool update_global) {
Init();
SetImplementation(new CallbackLogImplementation(callback), update_global);
}
diff --git a/aos/logging/implementations.h b/aos/logging/implementations.h
index 78980ff..6cf8376 100644
--- a/aos/logging/implementations.h
+++ b/aos/logging/implementations.h
@@ -132,6 +132,7 @@
// when needed or by calling Load()).
// The logging system takes ownership of implementation. It will delete it if
// necessary, so it must be created with new.
+// TODO: Log implementations are never deleted. Need means to safely deregister.
void SetImplementation(LogImplementation *implementation,
bool update_global = true);
@@ -139,6 +140,8 @@
// implementation.
LogImplementation *SwapImplementation(LogImplementation *implementation);
+LogImplementation *GetImplementation();
+
// 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.
@@ -164,7 +167,18 @@
void RegisterQueueImplementation();
void RegisterCallbackImplementation(
- const ::std::function<void(const LogMessage &)> &callback);
+ const ::std::function<void(const LogMessage &)> &callback,
+ bool update_global = true);
+
+class ScopedLogRestorer {
+ public:
+ ScopedLogRestorer() { prev_impl_ = GetImplementation(); }
+
+ ~ScopedLogRestorer() { SetImplementation(prev_impl_); }
+
+ private:
+ LogImplementation *prev_impl_;
+};
// This is where all of the code that is only used by actual LogImplementations
// goes.
diff --git a/aos/logging/implementations_test.cc b/aos/logging/implementations_test.cc
index a7b8b7d..272214a 100644
--- a/aos/logging/implementations_test.cc
+++ b/aos/logging/implementations_test.cc
@@ -244,6 +244,19 @@
EXPECT_EQ(kExpected1, ::std::string(buffer));
}
+TEST(ScopedLogRestorerTest, RestoreTest) {
+ LogImplementation *curr_impl = GetImplementation();
+
+ {
+ ScopedLogRestorer log_restorer;
+
+ logging::RegisterCallbackImplementation([] (const LogMessage&) {});
+ ASSERT_NE(curr_impl, GetImplementation());
+ }
+
+ ASSERT_EQ(curr_impl, GetImplementation());
+}
+
} // namespace testing
} // namespace logging
} // namespace aos
diff --git a/aos/logging/log_message.fbs b/aos/logging/log_message.fbs
new file mode 100644
index 0000000..789724f
--- /dev/null
+++ b/aos/logging/log_message.fbs
@@ -0,0 +1,27 @@
+namespace aos.logging;
+
+// Log level, corresponding to levels in logging.h
+enum Level : byte {
+ ERROR = -1,
+ DEBUG = 0,
+ INFO = 1,
+ WARNING = 2,
+ FATAL = 4,
+ LOG_UNKNOWN = 5
+}
+
+table LogMessageFbs {
+ // Text of the log message, includng file name and line
+ message:string (id: 0);
+
+ // Severity of the log message
+ level:Level (id: 1);
+
+ // Pid of the process creating the log message
+ source:int (id:2);
+
+ // Application name
+ name:string (id:3);
+}
+
+root_type LogMessageFbs;
diff --git a/aos/network/message_bridge_test_common.json b/aos/network/message_bridge_test_common.json
index d0085c2..a073869 100644
--- a/aos/network/message_bridge_test_common.json
+++ b/aos/network/message_bridge_test_common.json
@@ -2,6 +2,22 @@
"channels": [
{
"name": "/aos/pi1",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi1",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/aos/pi2",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi2",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/aos/pi1",
"type": "aos.message_bridge.ServerStatistics",
"source_node": "pi1",
"frequency": 2