Handle log files with only one direction of data
We have seen some log files where A -> B works, but B -> A hasn't
started up yet when interesting things are happening in the log. There
is enough information to order events causally between nodes, though not
well. So, use this information to fit what we have.
This doesn't yet handle transitioning between not having both directions
and having both directions. Both of those behaviors should result in a
jump in time and therefore a crash.
Change-Id: I684c1b61eb18efe2caaedc0e1e86f147c1e30f70
diff --git a/aos/events/logging/logger.cc b/aos/events/logging/logger.cc
index b16ea6f..24c0427 100644
--- a/aos/events/logging/logger.cc
+++ b/aos/events/logging/logger.cc
@@ -1424,8 +1424,6 @@
// which involves time before changing it. That especially includes
// sending the message.
if (update_time) {
- filters_->LogFit("");
-
VLOG(1) << MaybeNodeName(state->event_loop()->node())
<< "updating offsets";
@@ -1436,20 +1434,10 @@
return state->monotonic_now();
});
- for (size_t i = 0; i < states_.size(); ++i) {
- VLOG(1) << MaybeNodeName(states_[i]->event_loop()->node()) << "before "
- << states_[i]->monotonic_now();
- }
-
UpdateOffsets();
VLOG(1) << MaybeNodeName(state->event_loop()->node()) << "Now is now "
<< state->monotonic_now();
- for (size_t i = 0; i < states_.size(); ++i) {
- VLOG(1) << MaybeNodeName(states_[i]->event_loop()->node()) << "after "
- << states_[i]->monotonic_now();
- }
-
// TODO(austin): We should be perfect.
const std::chrono::nanoseconds kTolerance{3};
if (!FLAGS_skip_order_validation) {
@@ -1462,7 +1450,7 @@
<< MaybeNodeName(states_[i]->event_loop()->node());
CHECK_LE(states_[i]->monotonic_now(), before_times[i] + kTolerance)
<< ": Time changed too much on node "
- << states_[i]->event_loop()->node()->name()->string_view();
+ << MaybeNodeName(states_[i]->event_loop()->node());
}
} else {
if (next_time < state->monotonic_now()) {
diff --git a/aos/events/logging/logger_test.cc b/aos/events/logging/logger_test.cc
index 3f4893e..315a272 100644
--- a/aos/events/logging/logger_test.cc
+++ b/aos/events/logging/logger_test.cc
@@ -415,6 +415,13 @@
logfile_base_ +
"_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs"}),
logfiles_(MakeLogFiles(logfile_base_)),
+ pi1_single_direction_logfiles_(
+ {logfile_base_ + "_pi1_data.part0.bfbs",
+ logfile_base_ + "_pi2_data/test/aos.examples.Pong.part0.bfbs",
+ logfile_base_ + "_timestamps/pi1/aos/remote_timestamps/pi2/"
+ "aos.message_bridge.RemoteMessage.part0.bfbs",
+ logfile_base_ +
+ "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs"}),
structured_logfiles_{
std::vector<std::string>{logfiles_[0]},
std::vector<std::string>{logfiles_[1], logfiles_[2]},
@@ -549,6 +556,17 @@
EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
}
+ void ConfirmReadable(const std::vector<std::string> &files) {
+ LogReader reader(SortParts(files));
+
+ SimulatedEventLoopFactory log_reader_factory(reader.configuration());
+ reader.Register(&log_reader_factory);
+
+ log_reader_factory.Run();
+
+ reader.Deregister();
+ }
+
void AddExtension(std::string_view extension) {
std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
[extension](const std::string &in) {
@@ -577,6 +595,7 @@
std::string logfile_base_;
std::vector<std::string> pi1_reboot_logfiles_;
std::vector<std::string> logfiles_;
+ std::vector<std::string> pi1_single_direction_logfiles_;
std::vector<std::vector<std::string>> structured_logfiles_;
@@ -1727,6 +1746,48 @@
pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
}
+// Tests that we properly handle one direction of message_bridge being
+// unavailable.
+TEST_F(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
+ event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
+ event_loop_factory_.GetNodeEventLoopFactory(pi2_)->SetDistributedOffset(
+ chrono::seconds(1000), 0.99999);
+ {
+ LoggerState pi1_logger = MakeLogger(pi1_);
+
+ event_loop_factory_.RunFor(chrono::milliseconds(95));
+
+ StartLogger(&pi1_logger);
+
+ event_loop_factory_.RunFor(chrono::milliseconds(10000));
+ }
+
+ // Confirm that we can parse the result. LogReader has enough internal CHECKs
+ // to confirm the right thing happened.
+ ConfirmReadable(pi1_single_direction_logfiles_);
+}
+
+// Tests that we properly handle one direction of message_bridge being
+// unavailable.
+TEST_F(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
+ event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
+ event_loop_factory_.GetNodeEventLoopFactory(pi2_)->SetDistributedOffset(
+ chrono::seconds(500), 1.00001);
+ {
+ LoggerState pi1_logger = MakeLogger(pi1_);
+
+ event_loop_factory_.RunFor(chrono::milliseconds(95));
+
+ StartLogger(&pi1_logger);
+
+ event_loop_factory_.RunFor(chrono::milliseconds(10000));
+ }
+
+ // Confirm that we can parse the result. LogReader has enough internal CHECKs
+ // to confirm the right thing happened.
+ ConfirmReadable(pi1_single_direction_logfiles_);
+}
+
} // namespace testing
} // namespace logger
} // namespace aos