Add reliable timestamps to the log file header separately
Brian Smartt and I debugged a log reading crash. The crux of the issue
was that we had the following set of boots and timestamps:
Reverse sort, destination pi0 bc9e966b-1f35-4185-8d31-68727ecc5543 -> pi14
boot dd94ef90-fb0a-4bbd-b56f-3a02759d3cfa time {
.oldest_remote_monotonic_timestamp=9.994426078sec,
.oldest_local_monotonic_timestamp=10.532024791sec,
.oldest_remote_unreliable_monotonic_timestamp=3613.686273388sec,
.oldest_local_unreliable_monotonic_timestamp=821.896901804sec
}
boot 17e97238-f85c-48f4-a33e-60e7ecdde4cd time {
.oldest_remote_monotonic_timestamp=2617.511290249sec,
.oldest_local_monotonic_timestamp=2599.454979372sec,
.oldest_remote_unreliable_monotonic_timestamp=2617.511290249sec,
.oldest_local_unreliable_monotonic_timestamp=2599.454979372sec
}
Our current logic is combining the reliable and unreliable timestamps to
enable sorting when the log file header is created. This is actually
making it harder to sort. We found a new case where reliable timestamps
aren't actually being delivered reliably. So by combining them in with
the unreliable timestamps in the header, we are making it very hard to
figure out what happened first.
Looking at the example above, with the reliable and unreliable
timestamps mixed together, we can see that we get a different answer
than purely using the unreliable timestamps.
Given that our goal is to use messages crossing the network as
measurements of the time on both clocks, we want to prioritize messages
without arbitrary delays, ie unreliable messages. This change gives us
the data to do that, though it doesn't yet actually switch over to using
it yet. The goal here is to start collecting the data before using it.
Change-Id: I0f8fec3ef062508dcefbc89db395a1ce454a251d
Signed-off-by: Austin Schuh <austin.schuh@bluerivertech.com>
diff --git a/aos/events/logging/log_namer.cc b/aos/events/logging/log_namer.cc
index b41212c..ceeba95 100644
--- a/aos/events/logging/log_namer.cc
+++ b/aos/events/logging/log_namer.cc
@@ -59,6 +59,10 @@
monotonic_clock::max_time;
state.oldest_local_unreliable_monotonic_timestamp =
monotonic_clock::max_time;
+ state.oldest_remote_reliable_monotonic_timestamp =
+ monotonic_clock::max_time;
+ state.oldest_local_reliable_monotonic_timestamp =
+ monotonic_clock::max_time;
}
state_[node_index_].boot_uuid = source_node_boot_uuid;
@@ -96,6 +100,10 @@
monotonic_clock::max_time;
state.oldest_local_unreliable_monotonic_timestamp =
monotonic_clock::max_time;
+ state.oldest_remote_reliable_monotonic_timestamp =
+ monotonic_clock::max_time;
+ state.oldest_local_reliable_monotonic_timestamp =
+ monotonic_clock::max_time;
rotate = true;
}
@@ -112,6 +120,17 @@
state.oldest_local_unreliable_monotonic_timestamp = monotonic_event_time;
rotate = true;
}
+ } else {
+ if (state.oldest_remote_reliable_monotonic_timestamp >
+ monotonic_remote_time) {
+ VLOG(1) << filename() << " Remote " << remote_node_index
+ << " oldest_remote_reliable_monotonic_timestamp updated from "
+ << state.oldest_remote_reliable_monotonic_timestamp << " to "
+ << monotonic_remote_time;
+ state.oldest_remote_reliable_monotonic_timestamp = monotonic_remote_time;
+ state.oldest_local_reliable_monotonic_timestamp = monotonic_event_time;
+ rotate = true;
+ }
}
// Did any of the timestamps change?
@@ -219,7 +238,7 @@
const UUID &source_node_boot_uuid = state[node_index].boot_uuid;
const Node *const source_node =
configuration::GetNode(configuration_, node_index);
- CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 28u);
+ CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 30u);
flatbuffers::FlatBufferBuilder fbb;
fbb.ForceDefaults(true);
@@ -296,6 +315,16 @@
fbb.CreateUninitializedVector(
state.size(), &unused);
+ flatbuffers::Offset<flatbuffers::Vector<int64_t>>
+ oldest_remote_reliable_monotonic_timestamps_offset =
+ fbb.CreateUninitializedVector(
+ state.size(), &unused);
+
+ flatbuffers::Offset<flatbuffers::Vector<int64_t>>
+ oldest_local_reliable_monotonic_timestamps_offset =
+ fbb.CreateUninitializedVector(
+ state.size(), &unused);
+
for (size_t i = 0; i < state.size(); ++i) {
if (state[i].boot_uuid != UUID::Zero()) {
boot_uuid_offsets.emplace_back(state[i].boot_uuid.PackString(&fbb));
@@ -311,6 +340,10 @@
monotonic_clock::max_time);
CHECK_EQ(state[i].oldest_local_unreliable_monotonic_timestamp,
monotonic_clock::max_time);
+ CHECK_EQ(state[i].oldest_remote_reliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+ CHECK_EQ(state[i].oldest_local_reliable_monotonic_timestamp,
+ monotonic_clock::max_time);
}
flatbuffers::GetMutableTemporaryPointer(
@@ -326,13 +359,28 @@
flatbuffers::GetMutableTemporaryPointer(
fbb, oldest_remote_unreliable_monotonic_timestamps_offset)
->Mutate(i, state[i]
- .oldest_remote_unreliable_monotonic_timestamp.time_since_epoch()
+ .oldest_remote_unreliable_monotonic_timestamp
+ .time_since_epoch()
.count());
flatbuffers::GetMutableTemporaryPointer(
fbb, oldest_local_unreliable_monotonic_timestamps_offset)
->Mutate(i, state[i]
- .oldest_local_unreliable_monotonic_timestamp.time_since_epoch()
+ .oldest_local_unreliable_monotonic_timestamp
+ .time_since_epoch()
.count());
+
+ flatbuffers::GetMutableTemporaryPointer(
+ fbb, oldest_remote_reliable_monotonic_timestamps_offset)
+ ->Mutate(i, state[i]
+ .oldest_remote_reliable_monotonic_timestamp
+ .time_since_epoch()
+ .count());
+ flatbuffers::GetMutableTemporaryPointer(
+ fbb, oldest_local_reliable_monotonic_timestamps_offset)
+ ->Mutate(
+ i, state[i]
+ .oldest_local_reliable_monotonic_timestamp.time_since_epoch()
+ .count());
}
flatbuffers::Offset<
@@ -415,6 +463,10 @@
oldest_remote_unreliable_monotonic_timestamps_offset);
log_file_header_builder.add_oldest_local_unreliable_monotonic_timestamps(
oldest_local_unreliable_monotonic_timestamps_offset);
+ log_file_header_builder.add_oldest_remote_reliable_monotonic_timestamps(
+ oldest_remote_reliable_monotonic_timestamps_offset);
+ log_file_header_builder.add_oldest_local_reliable_monotonic_timestamps(
+ oldest_local_reliable_monotonic_timestamps_offset);
fbb.FinishSizePrefixed(log_file_header_builder.Finish());
aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> result(
fbb.Release());
diff --git a/aos/events/logging/log_namer.h b/aos/events/logging/log_namer.h
index c3fc5d4..207673d 100644
--- a/aos/events/logging/log_namer.h
+++ b/aos/events/logging/log_namer.h
@@ -98,6 +98,15 @@
// oldest_local_unreliable_monotonic_timestamp.
monotonic_clock::time_point oldest_local_unreliable_monotonic_timestamp =
monotonic_clock::max_time;
+
+ // Timestamp on the remote monotonic clock of the oldest message sent to
+ // node_index_, only including messages forwarded with time_to_live() == 0.
+ monotonic_clock::time_point oldest_remote_reliable_monotonic_timestamp =
+ monotonic_clock::max_time;
+ // Timestamp on the local monotonic clock of the message in
+ // oldest_local_reliable_monotonic_timestamp.
+ monotonic_clock::time_point oldest_local_reliable_monotonic_timestamp =
+ monotonic_clock::max_time;
};
private:
diff --git a/aos/events/logging/logfile_sorting.cc b/aos/events/logging/logfile_sorting.cc
index 30de0b5..2cea8b5 100644
--- a/aos/events/logging/logfile_sorting.cc
+++ b/aos/events/logging/logfile_sorting.cc
@@ -93,7 +93,7 @@
}
bool ConfigOnly(const LogFileHeader *header) {
- CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 28u);
+ CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 30u);
if (header->has_monotonic_start_time()) return false;
if (header->has_realtime_start_time()) return false;
if (header->has_max_out_of_order_duration()) return false;
@@ -117,6 +117,8 @@
if (header->has_oldest_local_monotonic_timestamps()) return false;
if (header->has_oldest_remote_unreliable_monotonic_timestamps()) return false;
if (header->has_oldest_local_unreliable_monotonic_timestamps()) return false;
+ if (header->has_oldest_remote_reliable_monotonic_timestamps()) return false;
+ if (header->has_oldest_local_reliable_monotonic_timestamps()) return false;
return header->has_configuration();
}
diff --git a/aos/events/logging/logger.fbs b/aos/events/logging/logger.fbs
index eb70184..72ffe33 100644
--- a/aos/events/logging/logger.fbs
+++ b/aos/events/logging/logger.fbs
@@ -108,30 +108,60 @@
// across the network and using those to determine constraints so we can sort
// a DAG.
//
- // There are 2 main problem cases. Let's say we have 2 channels. /a which
- // is reliable, and /b which isn't, both sent from the same remote node.
+ // There are 5 main cases. Let's say we have 2 channels. /r which
+ // is reliable, and /u which isn't, both sent from the same remote node.
+ // The examples below are listed as the remote node sending the message, and
+ // then the local node receiving and logging the message.
//
- // case 1: /a -> boot 0 received on boot 0.
- // /b -> boot 1 received on boot 0.
+ // case 0: /r -> boot 0 received on boot 0.
+ // /u -> boot 0 received on boot 0.
+ // We log for a bit, then the remote reboots.
+ // /r -> boot 1 received on boot 0.
+ // /u -> boot 1 received on boot 0.
+ //
+ // case 1: /r -> boot 0 received on boot 0.
+ // /u -> boot 1 received on boot 0.
// We start logging after both messages arrive.
//
- // case 2: /a -> boot 0 received on boot 0.
- // /b -> boot 0 received on boot 0.
+ // case 2: /r -> boot 0 received on boot 0.
+ // /u -> boot 0 received on boot 0.
// We log for a bit, then reboot. More messages show up when we reconnect.
- // /a -> boot 0 received on boot 1.
- // /b -> boot 0 received on boot 1.
+ // /r -> boot 0 received on boot 1.
+ // /u -> boot 0 received on boot 1.
+ //
+ // case 3: /u -> boot 0 received on boot 0.
+ // /r -> boot 1 received on boot 0.
+ // /u -> boot 1 received on boot 0.
+ // We start logging after both messages arrive.
+ //
+ // case 4: /u -> boot 0 received on boot 0.
+ // /r -> boot 1 received on boot 0.
+ //
+ // In case 0, we have all the messages showing up and a reboot of the remote.
//
// In case 1: we only have a reliable timestamp from boot 0, but that
- // reliable timestamp makes it clear that /a was before /b, so boot 0 was
+ // reliable timestamp makes it clear that /r was before /u, so boot 0 was
// before boot 1.
//
// In case 2: we have the same reliable timestamp, so that tells us nothing.
- // The unreliable timestamps though tell a different story. /b will be after
- // /a, since any messages on /b generated before the reboot won't get
- // delivered. So, we get an ordering constraint saying that any sent /b's
- // on the second boot were after /b on the first boot.
+ // The unreliable timestamps though tell a different story. /u will be after
+ // /r, since any messages on /u generated before the reboot won't get
+ // delivered. So, we get an ordering constraint saying that any sent /u's
+ // on the second boot were after /u on the first boot.
+ //
+ // In case 3: we only got the reliable message on the second boot for some
+ // reason. Reliable messages aren't 100% reliable. In this case, the
+ // reliable timestamps are actually a distraction and are misleading. We
+ // want to use the unreliable timestamps here.
+ //
+ // In case 4: we have utter madness...
+ //
+ // We expect the nominal case to be case 0, or the first half of case 0 if
+ // there are no reboots.
//
// We believe that any other cases are covered by the same mechanism.
+ // TODO(austin/brian): Shore up this and capture the cases that are 100%
+ // ambiguous and we can't sort.
//
// For all channels sent from a specific node, these vectors hold the
// timestamp of the oldest known message from that node, and the
@@ -150,6 +180,11 @@
corrupted_oldest_local_unreliable_monotonic_timestamps:[int64] (id: 23, deprecated);
oldest_remote_unreliable_monotonic_timestamps:[int64] (id: 26);
oldest_local_unreliable_monotonic_timestamps:[int64] (id: 27);
+
+ // For all channels *excluding* the unreliable channels (ttl != 0), record the
+ // same quantity.
+ oldest_remote_reliable_monotonic_timestamps:[int64] (id: 28);
+ oldest_local_reliable_monotonic_timestamps:[int64] (id: 29);
}
// Table holding a message.
diff --git a/aos/events/logging/logger_test.cc b/aos/events/logging/logger_test.cc
index 081d3c4..e558422 100644
--- a/aos/events/logging/logger_test.cc
+++ b/aos/events/logging/logger_test.cc
@@ -398,8 +398,7 @@
ping_sender.MakeBuilder();
examples::Ping::Builder ping_builder =
builder.MakeBuilder<examples::Ping>();
- CHECK_EQ(builder.Send(ping_builder.Finish()),
- RawSender::Error::kOk);
+ CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
});
// 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
@@ -512,6 +511,7 @@
if (logger) {
std::vector<std::string> filenames;
AppendAllFilenames(&filenames);
+ std::sort(filenames.begin(), filenames.end());
for (const std::string &file : filenames) {
LOG(INFO) << "Wrote to " << file;
auto x = ReadHeader(file);
@@ -604,8 +604,8 @@
std::vector<std::string> MakeLogFiles(std::string logfile_base1,
std::string logfile_base2,
- size_t pi1_data_count = 2,
- size_t pi2_data_count = 2) {
+ size_t pi1_data_count = 3,
+ size_t pi2_data_count = 3) {
std::vector<std::string> result;
result.emplace_back(absl::StrCat(
logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
@@ -644,6 +644,10 @@
"_timestamps/pi1/aos/remote_timestamps/pi2/"
"aos.message_bridge.RemoteMessage.part1" +
Extension());
+ result.emplace_back(logfile_base1 +
+ "_timestamps/pi1/aos/remote_timestamps/pi2/"
+ "aos.message_bridge.RemoteMessage.part2" +
+ Extension());
result.emplace_back(logfile_base2 +
"_timestamps/pi2/aos/remote_timestamps/pi1/"
"aos.message_bridge.RemoteMessage.part0" +
@@ -693,6 +697,8 @@
result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
+ result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
+ result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
result.emplace_back(logfile_base1_ +
"_pi2_data/test/aos.examples.Pong.part0" + Extension());
result.emplace_back(logfile_base1_ +
@@ -716,22 +722,13 @@
result.emplace_back(absl::StrCat(
logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
if (shared()) {
- result.emplace_back(logfile_base1_ +
- "_timestamps/pi1/aos/remote_timestamps/pi2/"
- "aos.message_bridge.RemoteMessage.part0" +
- Extension());
- result.emplace_back(logfile_base1_ +
- "_timestamps/pi1/aos/remote_timestamps/pi2/"
- "aos.message_bridge.RemoteMessage.part1" +
- Extension());
- result.emplace_back(logfile_base1_ +
- "_timestamps/pi1/aos/remote_timestamps/pi2/"
- "aos.message_bridge.RemoteMessage.part2" +
- Extension());
- result.emplace_back(logfile_base1_ +
- "_timestamps/pi1/aos/remote_timestamps/pi2/"
- "aos.message_bridge.RemoteMessage.part3" +
- Extension());
+ for (size_t i = 0; i < 6; ++i) {
+ result.emplace_back(
+ absl::StrCat(logfile_base1_,
+ "_timestamps/pi1/aos/remote_timestamps/pi2/"
+ "aos.message_bridge.RemoteMessage.part",
+ i, Extension()));
+ }
} else {
result.emplace_back(logfile_base1_ +
"_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
@@ -800,17 +797,24 @@
std::vector<std::vector<std::string>> StructureLogFiles() {
std::vector<std::vector<std::string>> result{
- std::vector<std::string>{logfiles_[2], logfiles_[3]},
- std::vector<std::string>{logfiles_[4], logfiles_[5]},
- std::vector<std::string>{logfiles_[6], logfiles_[7]},
- std::vector<std::string>{logfiles_[8], logfiles_[9]},
+ std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
+ std::vector<std::string>{logfiles_[5], logfiles_[6]},
+ std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
std::vector<std::string>{logfiles_[10], logfiles_[11]},
- std::vector<std::string>{logfiles_[12], logfiles_[13]},
- std::vector<std::string>{logfiles_[14], logfiles_[15]}};
+ std::vector<std::string>{logfiles_[12], logfiles_[13]}};
- if (!shared()) {
+ if (shared()) {
+ result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
+ logfiles_[16]});
+ result.emplace_back(
+ std::vector<std::string>{logfiles_[17], logfiles_[18]});
+ } else {
+ result.emplace_back(
+ std::vector<std::string>{logfiles_[14], logfiles_[15]});
result.emplace_back(
std::vector<std::string>{logfiles_[16], logfiles_[17]});
+ result.emplace_back(
+ std::vector<std::string>{logfiles_[18], logfiles_[19]});
}
return result;
@@ -893,7 +897,7 @@
// Test that each list of parts is in order. Don't worry about the ordering
// between part file lists though.
// (inner vectors all need to be in order, but outer one doesn't matter).
- EXPECT_THAT(ToLogReaderVector(sorted_parts),
+ ASSERT_THAT(ToLogReaderVector(sorted_parts),
::testing::UnorderedElementsAreArray(structured_logfiles_));
EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
@@ -1016,7 +1020,9 @@
// Tests that we can write and read simple multi-node log files.
TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
+ std::vector<std::string> actual_filenames;
time_converter_.StartEqual();
+
{
LoggerState pi1_logger = MakeLogger(pi1_);
LoggerState pi2_logger = MakeLogger(pi2_);
@@ -1027,8 +1033,13 @@
StartLogger(&pi2_logger);
event_loop_factory_.RunFor(chrono::milliseconds(20000));
+ pi1_logger.AppendAllFilenames(&actual_filenames);
+ pi2_logger.AppendAllFilenames(&actual_filenames);
}
+ ASSERT_THAT(actual_filenames,
+ ::testing::UnorderedElementsAreArray(logfiles_));
+
{
std::set<std::string> logfile_uuids;
std::set<std::string> parts_uuids;
@@ -1054,41 +1065,73 @@
// And confirm everything is on the correct node.
EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
- EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
+ EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
+
EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
+
EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
- EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
- EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
- EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
- EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
+ EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
+ EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
+
+ EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
+ EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
+
EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
- EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
- EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
- if (!shared()) {
+
+ if (shared()) {
+ EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
+ EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
- EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
+
+ EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
+ EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
+ } else {
+ EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
+ EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
+
+ EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
+ EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
+
+ EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
+ EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
}
// And the parts index matches.
EXPECT_EQ(log_header[2].message().parts_index(), 0);
EXPECT_EQ(log_header[3].message().parts_index(), 1);
- EXPECT_EQ(log_header[4].message().parts_index(), 0);
- EXPECT_EQ(log_header[5].message().parts_index(), 1);
- EXPECT_EQ(log_header[6].message().parts_index(), 0);
- EXPECT_EQ(log_header[7].message().parts_index(), 1);
- EXPECT_EQ(log_header[8].message().parts_index(), 0);
- EXPECT_EQ(log_header[9].message().parts_index(), 1);
+ EXPECT_EQ(log_header[4].message().parts_index(), 2);
+
+ EXPECT_EQ(log_header[5].message().parts_index(), 0);
+ EXPECT_EQ(log_header[6].message().parts_index(), 1);
+
+ EXPECT_EQ(log_header[7].message().parts_index(), 0);
+ EXPECT_EQ(log_header[8].message().parts_index(), 1);
+ EXPECT_EQ(log_header[9].message().parts_index(), 2);
+
EXPECT_EQ(log_header[10].message().parts_index(), 0);
EXPECT_EQ(log_header[11].message().parts_index(), 1);
+
EXPECT_EQ(log_header[12].message().parts_index(), 0);
EXPECT_EQ(log_header[13].message().parts_index(), 1);
- EXPECT_EQ(log_header[14].message().parts_index(), 0);
- EXPECT_EQ(log_header[15].message().parts_index(), 1);
- if (!shared()) {
+
+ if (shared()) {
+ EXPECT_EQ(log_header[14].message().parts_index(), 0);
+ EXPECT_EQ(log_header[15].message().parts_index(), 1);
+ EXPECT_EQ(log_header[16].message().parts_index(), 2);
+
+ EXPECT_EQ(log_header[17].message().parts_index(), 0);
+ EXPECT_EQ(log_header[18].message().parts_index(), 1);
+ } else {
+ EXPECT_EQ(log_header[14].message().parts_index(), 0);
+ EXPECT_EQ(log_header[15].message().parts_index(), 1);
+
EXPECT_EQ(log_header[16].message().parts_index(), 0);
EXPECT_EQ(log_header[17].message().parts_index(), 1);
+
+ EXPECT_EQ(log_header[18].message().parts_index(), 0);
+ EXPECT_EQ(log_header[19].message().parts_index(), 1);
}
}
@@ -1108,50 +1151,65 @@
EXPECT_THAT(
CountChannelsData(config, logfiles_[3]),
UnorderedElementsAre(
- std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
+ std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
+ std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
+ 1)))
+ << " : " << logfiles_[3];
+ EXPECT_THAT(
+ CountChannelsData(config, logfiles_[4]),
+ UnorderedElementsAre(
+ std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
20),
std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
- 200),
+ 199),
std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
std::make_tuple("/test", "aos.examples.Ping", 2000)))
- << " : " << logfiles_[3];
+ << " : " << logfiles_[4];
// Timestamps for pong
EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
UnorderedElementsAre())
<< " : " << logfiles_[2];
EXPECT_THAT(
CountChannelsTimestamp(config, logfiles_[3]),
- UnorderedElementsAre(
- std::make_tuple("/test", "aos.examples.Pong", 2001),
- std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
+ UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
<< " : " << logfiles_[3];
+ EXPECT_THAT(
+ CountChannelsTimestamp(config, logfiles_[4]),
+ UnorderedElementsAre(
+ std::make_tuple("/test", "aos.examples.Pong", 2000),
+ std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
+ << " : " << logfiles_[4];
// Pong data.
EXPECT_THAT(
- CountChannelsData(config, logfiles_[4]),
+ CountChannelsData(config, logfiles_[5]),
UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
- << " : " << logfiles_[4];
- EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
+ << " : " << logfiles_[5];
+ EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
UnorderedElementsAre(
std::make_tuple("/test", "aos.examples.Pong", 1910)))
- << " : " << logfiles_[5];
+ << " : " << logfiles_[6];
// No timestamps
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
- UnorderedElementsAre())
- << " : " << logfiles_[4];
EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
UnorderedElementsAre())
<< " : " << logfiles_[5];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[6];
// Timing reports and pongs.
- EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
+ EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
UnorderedElementsAre(std::make_tuple(
"/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
- << " : " << logfiles_[6];
+ << " : " << logfiles_[7];
EXPECT_THAT(
- CountChannelsData(config, logfiles_[7]),
+ CountChannelsData(config, logfiles_[8]),
+ UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
+ << " : " << logfiles_[8];
+ EXPECT_THAT(
+ CountChannelsData(config, logfiles_[9]),
UnorderedElementsAre(
std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
@@ -1159,120 +1217,142 @@
std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
200),
std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
- std::make_tuple("/test", "aos.examples.Pong", 2001)))
- << " : " << logfiles_[7];
+ std::make_tuple("/test", "aos.examples.Pong", 2000)))
+ << " : " << logfiles_[9];
// And ping timestamps.
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
UnorderedElementsAre())
- << " : " << logfiles_[6];
- EXPECT_THAT(
- CountChannelsTimestamp(config, logfiles_[7]),
- UnorderedElementsAre(
- std::make_tuple("/test", "aos.examples.Ping", 2001),
- std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
<< " : " << logfiles_[7];
+ EXPECT_THAT(
+ CountChannelsTimestamp(config, logfiles_[8]),
+ UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
+ << " : " << logfiles_[8];
+ EXPECT_THAT(
+ CountChannelsTimestamp(config, logfiles_[9]),
+ UnorderedElementsAre(
+ std::make_tuple("/test", "aos.examples.Ping", 2000),
+ std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
+ << " : " << logfiles_[9];
// And then test that the remotely logged timestamp data files only have
// timestamps in them.
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
- UnorderedElementsAre())
- << " : " << logfiles_[8];
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
- UnorderedElementsAre())
- << " : " << logfiles_[9];
EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
UnorderedElementsAre())
<< " : " << logfiles_[10];
EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
UnorderedElementsAre())
<< " : " << logfiles_[11];
-
- EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
- UnorderedElementsAre(std::make_tuple(
- "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
- << " : " << logfiles_[8];
- EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
- UnorderedElementsAre(std::make_tuple(
- "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
- << " : " << logfiles_[9];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[12];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[13];
EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
UnorderedElementsAre(std::make_tuple(
- "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
+ "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
<< " : " << logfiles_[10];
EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
UnorderedElementsAre(std::make_tuple(
- "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
+ "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
<< " : " << logfiles_[11];
- // Timestamps from pi2 on pi1, and the other way.
EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
- UnorderedElementsAre())
+ UnorderedElementsAre(std::make_tuple(
+ "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
<< " : " << logfiles_[12];
EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
- UnorderedElementsAre())
+ UnorderedElementsAre(std::make_tuple(
+ "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
<< " : " << logfiles_[13];
- EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
- UnorderedElementsAre())
- << " : " << logfiles_[14];
- EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
- UnorderedElementsAre())
- << " : " << logfiles_[15];
- if (!shared()) {
+
+ // Timestamps from pi2 on pi1, and the other way.
+ if (shared()) {
+ EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[14];
+ EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[15];
EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
UnorderedElementsAre())
<< " : " << logfiles_[16];
EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
UnorderedElementsAre())
<< " : " << logfiles_[17];
- }
+ EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[18];
- if (shared()) {
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
+ UnorderedElementsAre(
+ std::make_tuple("/test", "aos.examples.Ping", 1)))
+ << " : " << logfiles_[14];
EXPECT_THAT(
- CountChannelsTimestamp(config, logfiles_[12]),
+ CountChannelsTimestamp(config, logfiles_[15]),
UnorderedElementsAre(
std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
- std::make_tuple("/test", "aos.examples.Ping", 91)))
- << " : " << logfiles_[12];
+ std::make_tuple("/test", "aos.examples.Ping", 90)))
+ << " : " << logfiles_[15];
EXPECT_THAT(
- CountChannelsTimestamp(config, logfiles_[13]),
+ CountChannelsTimestamp(config, logfiles_[16]),
UnorderedElementsAre(
std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
std::make_tuple("/test", "aos.examples.Ping", 1910)))
- << " : " << logfiles_[13];
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
- UnorderedElementsAre(std::make_tuple(
- "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
- << " : " << logfiles_[14];
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
- UnorderedElementsAre(std::make_tuple(
- "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
- << " : " << logfiles_[15];
- } else {
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
- UnorderedElementsAre(std::make_tuple(
- "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
- << " : " << logfiles_[12];
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
- UnorderedElementsAre(std::make_tuple(
- "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
- << " : " << logfiles_[13];
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
- UnorderedElementsAre(std::make_tuple(
- "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
- << " : " << logfiles_[14];
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
- UnorderedElementsAre(std::make_tuple(
- "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
- << " : " << logfiles_[15];
- EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
- UnorderedElementsAre(
- std::make_tuple("/test", "aos.examples.Ping", 91)))
<< " : " << logfiles_[16];
EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
+ UnorderedElementsAre(std::make_tuple(
+ "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
+ << " : " << logfiles_[17];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
+ UnorderedElementsAre(std::make_tuple(
+ "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
+ << " : " << logfiles_[18];
+ } else {
+ EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[14];
+ EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[15];
+ EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[16];
+ EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[17];
+ EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[18];
+ EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
+ UnorderedElementsAre())
+ << " : " << logfiles_[19];
+
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
+ UnorderedElementsAre(std::make_tuple(
+ "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
+ << " : " << logfiles_[14];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
+ UnorderedElementsAre(std::make_tuple(
+ "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
+ << " : " << logfiles_[15];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
+ UnorderedElementsAre(std::make_tuple(
+ "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
+ << " : " << logfiles_[16];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
+ UnorderedElementsAre(std::make_tuple(
+ "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
+ << " : " << logfiles_[17];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
+ UnorderedElementsAre(
+ std::make_tuple("/test", "aos.examples.Ping", 91)))
+ << " : " << logfiles_[18];
+ EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
UnorderedElementsAre(
std::make_tuple("/test", "aos.examples.Ping", 1910)))
- << " : " << logfiles_[17];
+ << " : " << logfiles_[19];
}
}
@@ -1465,6 +1545,8 @@
// time.
TEST_P(MultinodeLoggerTest, StaggeredStart) {
time_converter_.StartEqual();
+ std::vector<std::string> actual_filenames;
+
{
LoggerState pi1_logger = MakeLogger(pi1_);
LoggerState pi2_logger = MakeLogger(pi2_);
@@ -1478,12 +1560,13 @@
StartLogger(&pi2_logger);
event_loop_factory_.RunFor(chrono::milliseconds(20000));
+ pi1_logger.AppendAllFilenames(&actual_filenames);
+ pi2_logger.AppendAllFilenames(&actual_filenames);
}
// Since we delay starting pi2, it already knows about all the timestamps so
// we don't end up with extra parts.
- LogReader reader(
- SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
+ LogReader reader(SortParts(actual_filenames));
SimulatedEventLoopFactory log_reader_factory(reader.configuration());
log_reader_factory.set_send_delay(chrono::microseconds(0));
@@ -1794,6 +1877,7 @@
// Tests that we can sort a bunch of parts with the end missing off a
// file. We should use the part we can read.
TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
+ std::vector<std::string> actual_filenames;
time_converter_.StartEqual();
// Make a bunch of parts.
{
@@ -1806,16 +1890,22 @@
StartLogger(&pi2_logger);
event_loop_factory_.RunFor(chrono::milliseconds(2000));
+
+ pi1_logger.AppendAllFilenames(&actual_filenames);
+ pi2_logger.AppendAllFilenames(&actual_filenames);
}
+ ASSERT_THAT(actual_filenames,
+ ::testing::UnorderedElementsAreArray(logfiles_));
+
// Strip off the end of one of the files. Pick one with a lot of data.
// For snappy, needs to have enough data to be >1 chunk of compressed data so
// that we don't corrupt the entire log part.
::std::string compressed_contents =
- aos::util::ReadFileToStringOrDie(logfiles_[3]);
+ aos::util::ReadFileToStringOrDie(logfiles_[4]);
aos::util::WriteStringToFileOrDie(
- logfiles_[3],
+ logfiles_[4],
compressed_contents.substr(0, compressed_contents.size() - 100));
const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
@@ -2328,6 +2418,8 @@
// This should be enough that we can then re-run the logger and get a valid log
// back.
TEST_P(MultinodeLoggerTest, RemoteReboot) {
+ std::vector<std::string> actual_filenames;
+
const UUID pi1_boot0 = UUID::Random();
const UUID pi2_boot0 = UUID::Random();
const UUID pi2_boot1 = UUID::Random();
@@ -2371,8 +2463,15 @@
pi1_boot0);
EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
pi2_boot1);
+
+ pi1_logger.AppendAllFilenames(&actual_filenames);
}
+ std::sort(actual_filenames.begin(), actual_filenames.end());
+ std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
+ ASSERT_THAT(actual_filenames,
+ ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
+
// Confirm that our new oldest timestamps properly update as we reboot and
// rotate.
for (const std::string &file : pi1_reboot_logfiles_) {
@@ -2395,7 +2494,8 @@
//
// TODO(austin): I'm not the most thrilled with this test pattern... It
// feels brittle in a different way.
- if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos || !shared()) {
+ if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
+ !shared()) {
switch (log_header->message().parts_index()) {
case 0:
EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
@@ -2423,20 +2523,21 @@
} else {
switch (log_header->message().parts_index()) {
case 0:
+ case 1:
EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
break;
- case 1:
+ case 2:
EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
ASSERT_EQ(monotonic_start_time,
monotonic_clock::epoch() + chrono::seconds(1));
break;
- case 2:
case 3:
+ case 4:
EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
break;
- case 4:
+ case 5:
EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
chrono::nanoseconds(2322999462))
@@ -2503,6 +2604,18 @@
log_header->message()
.oldest_local_unreliable_monotonic_timestamps()
->Get(1)));
+ const monotonic_clock::time_point
+ oldest_remote_reliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_remote_reliable_monotonic_timestamps()
+ ->Get(1)));
+ const monotonic_clock::time_point
+ oldest_local_reliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_local_reliable_monotonic_timestamps()
+ ->Get(1)));
switch (log_header->message().parts_index()) {
case 0:
EXPECT_EQ(oldest_remote_monotonic_timestamps,
@@ -2512,6 +2625,10 @@
monotonic_clock::max_time);
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
monotonic_clock::max_time);
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
break;
case 1:
EXPECT_EQ(oldest_remote_monotonic_timestamps,
@@ -2522,9 +2639,33 @@
monotonic_clock::time_point(chrono::microseconds(90200)));
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
monotonic_clock::time_point(chrono::microseconds(90350)));
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
break;
case 2:
EXPECT_EQ(oldest_remote_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(90200)))
+ << file;
+ EXPECT_EQ(oldest_local_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(90350)))
+ << file;
+ EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(90200)))
+ << file;
+ EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(90350)))
+ << file;
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(100000)))
+ << file;
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(100150)))
+ << file;
+ break;
+ case 3:
+ EXPECT_EQ(oldest_remote_monotonic_timestamps,
monotonic_clock::time_point(chrono::milliseconds(1323) +
chrono::microseconds(200)));
EXPECT_EQ(oldest_local_monotonic_timestamps,
@@ -2534,6 +2675,30 @@
chrono::microseconds(200)));
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
monotonic_clock::time_point(chrono::microseconds(10100350)));
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::max_time)
+ << file;
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::max_time)
+ << file;
+ break;
+ case 4:
+ EXPECT_EQ(oldest_remote_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::milliseconds(1323) +
+ chrono::microseconds(200)));
+ EXPECT_EQ(oldest_local_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(10100350)));
+ EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::milliseconds(1323) +
+ chrono::microseconds(200)));
+ EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(10100350)));
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(1423000)))
+ << file;
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::time_point(chrono::microseconds(10200150)))
+ << file;
break;
default:
FAIL();
@@ -2609,6 +2774,8 @@
pi1_logger.AppendAllFilenames(&filenames);
}
+ std::sort(filenames.begin(), filenames.end());
+
// Confirm that our new oldest timestamps properly update as we reboot and
// rotate.
size_t timestamp_file_count = 0;
@@ -2691,6 +2858,18 @@
log_header->message()
.oldest_local_unreliable_monotonic_timestamps()
->Get(0)));
+ const monotonic_clock::time_point
+ oldest_remote_reliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_remote_reliable_monotonic_timestamps()
+ ->Get(0)));
+ const monotonic_clock::time_point
+ oldest_local_reliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_local_reliable_monotonic_timestamps()
+ ->Get(0)));
const Channel *channel =
event_loop_factory_.configuration()->channels()->Get(
@@ -2711,17 +2890,51 @@
// tests.
switch (log_header->message().parts_index()) {
case 0:
- case 1:
EXPECT_EQ(oldest_remote_monotonic_timestamps,
expected_oldest_remote_monotonic_timestamps);
EXPECT_EQ(oldest_local_monotonic_timestamps,
expected_oldest_local_monotonic_timestamps);
if (reliable) {
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ expected_oldest_remote_monotonic_timestamps);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps);
EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
monotonic_clock::max_time);
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
monotonic_clock::max_time);
} else {
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
+ expected_oldest_remote_monotonic_timestamps);
+ EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps);
+ }
+ break;
+ case 1:
+ EXPECT_EQ(oldest_remote_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90000000));
+ EXPECT_EQ(oldest_local_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90150000));
+ if (reliable) {
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ expected_oldest_remote_monotonic_timestamps);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps);
+ EXPECT_EQ(
+ oldest_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90000000));
+ EXPECT_EQ(
+ oldest_local_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90150000));
+ } else {
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
expected_oldest_remote_monotonic_timestamps);
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
@@ -2729,6 +2942,34 @@
}
break;
case 2:
+ EXPECT_EQ(
+ oldest_remote_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
+ EXPECT_EQ(
+ oldest_local_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
+ if (reliable) {
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ expected_oldest_remote_monotonic_timestamps);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps);
+ EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ } else {
+ EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
+ expected_oldest_remote_monotonic_timestamps);
+ EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps);
+ }
+ break;
+
+ case 3:
LOG(INFO) << "Shared";
EXPECT_EQ(
oldest_remote_monotonic_timestamps,
@@ -2752,10 +2993,14 @@
EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
break;
case 1:
- EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
+ EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
break;
case 2:
+ EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
+ EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
+ break;
+ case 3:
if (shared()) {
EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
@@ -2855,7 +3100,7 @@
}
if (shared()) {
- EXPECT_EQ(timestamp_file_count, 3u);
+ EXPECT_EQ(timestamp_file_count, 4u);
} else {
EXPECT_EQ(timestamp_file_count, 4u);
}
@@ -3229,7 +3474,8 @@
// when a local message is in the log before a forwarded message, so there is no
// point in the interpolation function. This delays the reboot. So, we need to
// recreate that situation and make sure it doesn't come back.
-TEST(MultinodeRebootLoggerTest, LocalMessageBeforeRemoteBeforeStartAfterReboot) {
+TEST(MultinodeRebootLoggerTest,
+ LocalMessageBeforeRemoteBeforeStartAfterReboot) {
aos::FlatbufferDetachedBuffer<aos::Configuration> config =
aos::configuration::ReadConfig(ArtifactPath(
"aos/events/logging/multinode_pingpong_split3_config.json"));
@@ -3284,9 +3530,9 @@
time_converter.AddNextTimestamp(
distributed_clock::epoch() + reboot_time,
{BootTimestamp::epoch() + reboot_time,
- BootTimestamp{
- .boot = 1,
- .time = monotonic_clock::epoch() + reboot_time + chrono::seconds(100)},
+ BootTimestamp{.boot = 1,
+ .time = monotonic_clock::epoch() + reboot_time +
+ chrono::seconds(100)},
BootTimestamp::epoch() + reboot_time});
}