Merge "Plot currents in the AngularSystem plots"
diff --git a/aos/actions/actor.h b/aos/actions/actor.h
index 33e70f2..b906059 100644
--- a/aos/actions/actor.h
+++ b/aos/actions/actor.h
@@ -90,7 +90,7 @@
::aos::EventLoop *event_loop() { return event_loop_; }
- ::aos::monotonic_clock::time_point monotonic_now() {
+ ::aos::monotonic_clock::time_point monotonic_now() const {
return event_loop_->monotonic_now();
}
diff --git a/aos/events/event_loop.h b/aos/events/event_loop.h
index c81fa1e..11368ae 100644
--- a/aos/events/event_loop.h
+++ b/aos/events/event_loop.h
@@ -542,8 +542,8 @@
virtual ~EventLoop();
// Current time.
- virtual monotonic_clock::time_point monotonic_now() = 0;
- virtual realtime_clock::time_point realtime_now() = 0;
+ virtual monotonic_clock::time_point monotonic_now() const = 0;
+ virtual realtime_clock::time_point realtime_now() const = 0;
template <typename T>
const Channel *GetChannel(const std::string_view channel_name) {
diff --git a/aos/events/logging/log_namer.cc b/aos/events/logging/log_namer.cc
index b41212c..f269f43 100644
--- a/aos/events/logging/log_namer.cc
+++ b/aos/events/logging/log_namer.cc
@@ -18,10 +18,13 @@
namespace logger {
NewDataWriter::NewDataWriter(LogNamer *log_namer, const Node *node,
+ const Node *logger_node,
std::function<void(NewDataWriter *)> reopen,
std::function<void(NewDataWriter *)> close)
: node_(node),
node_index_(configuration::GetNodeIndex(log_namer->configuration_, node)),
+ logger_node_index_(
+ configuration::GetNodeIndex(log_namer->configuration_, logger_node)),
log_namer_(log_namer),
reopen_(std::move(reopen)),
close_(std::move(close)) {
@@ -59,6 +62,13 @@
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.oldest_logger_remote_unreliable_monotonic_timestamp =
+ monotonic_clock::max_time;
+ state.oldest_logger_local_unreliable_monotonic_timestamp =
+ monotonic_clock::max_time;
}
state_[node_index_].boot_uuid = source_node_boot_uuid;
@@ -78,8 +88,8 @@
void NewDataWriter::UpdateRemote(
const size_t remote_node_index, const UUID &remote_node_boot_uuid,
const monotonic_clock::time_point monotonic_remote_time,
- const monotonic_clock::time_point monotonic_event_time,
- const bool reliable) {
+ const monotonic_clock::time_point monotonic_event_time, const bool reliable,
+ monotonic_clock::time_point monotonic_timestamp_time) {
// Trigger rotation if anything in the header changes.
bool rotate = false;
CHECK_LT(remote_node_index, state_.size());
@@ -96,6 +106,13 @@
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.oldest_logger_remote_unreliable_monotonic_timestamp =
+ monotonic_clock::max_time;
+ state.oldest_logger_local_unreliable_monotonic_timestamp =
+ monotonic_clock::max_time;
rotate = true;
}
@@ -112,6 +129,38 @@
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;
+ }
+ }
+
+ // Track the logger timestamps too.
+ if (monotonic_timestamp_time != monotonic_clock::min_time) {
+ State &logger_state = state_[node_index_];
+ CHECK_EQ(remote_node_index, logger_node_index_);
+ if (monotonic_event_time <
+ logger_state.oldest_logger_remote_unreliable_monotonic_timestamp) {
+ VLOG(1)
+ << filename() << " Remote " << node_index_
+ << " oldest_logger_remote_unreliable_monotonic_timestamp updated "
+ "from "
+ << logger_state.oldest_logger_remote_unreliable_monotonic_timestamp
+ << " to " << monotonic_event_time;
+ logger_state.oldest_logger_remote_unreliable_monotonic_timestamp =
+ monotonic_event_time;
+ logger_state.oldest_logger_local_unreliable_monotonic_timestamp =
+ monotonic_timestamp_time;
+
+ rotate = true;
+ }
}
// Did any of the timestamps change?
@@ -219,7 +268,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, 32u);
flatbuffers::FlatBufferBuilder fbb;
fbb.ForceDefaults(true);
@@ -279,22 +328,36 @@
int64_t *unused;
flatbuffers::Offset<flatbuffers::Vector<int64_t>>
- oldest_remote_monotonic_timestamps_offset = fbb.CreateUninitializedVector(
- state.size(), &unused);
+ oldest_remote_monotonic_timestamps_offset =
+ fbb.CreateUninitializedVector(state.size(), &unused);
flatbuffers::Offset<flatbuffers::Vector<int64_t>>
- oldest_local_monotonic_timestamps_offset = fbb.CreateUninitializedVector(
- state.size(), &unused);
+ oldest_local_monotonic_timestamps_offset =
+ fbb.CreateUninitializedVector(state.size(), &unused);
flatbuffers::Offset<flatbuffers::Vector<int64_t>>
oldest_remote_unreliable_monotonic_timestamps_offset =
- fbb.CreateUninitializedVector(
- state.size(), &unused);
+ fbb.CreateUninitializedVector(state.size(), &unused);
flatbuffers::Offset<flatbuffers::Vector<int64_t>>
oldest_local_unreliable_monotonic_timestamps_offset =
- fbb.CreateUninitializedVector(
- state.size(), &unused);
+ 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);
+
+ flatbuffers::Offset<flatbuffers::Vector<int64_t>>
+ oldest_logger_remote_unreliable_monotonic_timestamps_offset =
+ fbb.CreateUninitializedVector(state.size(), &unused);
+
+ flatbuffers::Offset<flatbuffers::Vector<int64_t>>
+ oldest_logger_local_unreliable_monotonic_timestamps_offset =
+ fbb.CreateUninitializedVector(state.size(), &unused);
for (size_t i = 0; i < state.size(); ++i) {
if (state[i].boot_uuid != UUID::Zero()) {
@@ -311,6 +374,14 @@
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);
+ CHECK_EQ(state[i].oldest_logger_remote_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+ CHECK_EQ(state[i].oldest_logger_local_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
}
flatbuffers::GetMutableTemporaryPointer(
@@ -326,12 +397,40 @@
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::GetMutableTemporaryPointer(
+ fbb, oldest_logger_remote_unreliable_monotonic_timestamps_offset)
+ ->Mutate(i, state[i]
+ .oldest_logger_remote_unreliable_monotonic_timestamp
+ .time_since_epoch()
+ .count());
+ flatbuffers::GetMutableTemporaryPointer(
+ fbb, oldest_logger_local_unreliable_monotonic_timestamps_offset)
+ ->Mutate(i, state[i]
+ .oldest_logger_local_unreliable_monotonic_timestamp
+ .time_since_epoch()
.count());
}
@@ -415,6 +514,16 @@
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);
+ log_file_header_builder
+ .add_oldest_logger_remote_unreliable_monotonic_timestamps(
+ oldest_logger_remote_unreliable_monotonic_timestamps_offset);
+ log_file_header_builder
+ .add_oldest_logger_local_unreliable_monotonic_timestamps(
+ oldest_logger_local_unreliable_monotonic_timestamps_offset);
fbb.FinishSizePrefixed(log_file_header_builder.Finish());
aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> result(
fbb.Release());
@@ -556,13 +665,14 @@
nodes_.emplace_back(source_node);
}
- NewDataWriter data_writer(this, source_node,
- [this, channel](NewDataWriter *data_writer) {
- OpenWriter(channel, data_writer);
- },
- [this](NewDataWriter *data_writer) {
- CloseWriter(&data_writer->writer);
- });
+ NewDataWriter data_writer(
+ this, source_node, node_,
+ [this, channel](NewDataWriter *data_writer) {
+ OpenWriter(channel, data_writer);
+ },
+ [this](NewDataWriter *data_writer) {
+ CloseWriter(&data_writer->writer);
+ });
return &(
data_writers_.emplace(channel, std::move(data_writer)).first->second);
}
@@ -580,14 +690,14 @@
nodes_.emplace_back(node);
}
- NewDataWriter data_writer(this, configuration::GetNode(configuration_, node),
- [this, channel](NewDataWriter *data_writer) {
- OpenForwardedTimestampWriter(channel,
- data_writer);
- },
- [this](NewDataWriter *data_writer) {
- CloseWriter(&data_writer->writer);
- });
+ NewDataWriter data_writer(
+ this, configuration::GetNode(configuration_, node), node_,
+ [this, channel](NewDataWriter *data_writer) {
+ OpenForwardedTimestampWriter(channel, data_writer);
+ },
+ [this](NewDataWriter *data_writer) {
+ CloseWriter(&data_writer->writer);
+ });
return &(
data_writers_.emplace(channel, std::move(data_writer)).first->second);
}
@@ -652,7 +762,7 @@
void MultiNodeLogNamer::OpenDataWriter() {
if (!data_writer_) {
data_writer_ = std::make_unique<NewDataWriter>(
- this, node_,
+ this, node_, node_,
[this](NewDataWriter *writer) {
std::string name;
if (node() != nullptr) {
diff --git a/aos/events/logging/log_namer.h b/aos/events/logging/log_namer.h
index c3fc5d4..4a1e74f 100644
--- a/aos/events/logging/log_namer.h
+++ b/aos/events/logging/log_namer.h
@@ -36,7 +36,7 @@
// node is the node whom's prespective we are logging from.
// reopen is called whenever a file needs to be reopened.
// close is called to close that file and extract any statistics.
- NewDataWriter(LogNamer *log_namer, const Node *node,
+ NewDataWriter(LogNamer *log_namer, const Node *node, const Node *logger_node,
std::function<void(NewDataWriter *)> reopen,
std::function<void(NewDataWriter *)> close);
@@ -50,10 +50,14 @@
// Rotates the log file, delaying writing the new header until data arrives.
void Rotate();
+ // Updates all the metadata in the log file about the remote node which this
+ // message is from.
void UpdateRemote(size_t remote_node_index, const UUID &remote_node_boot_uuid,
monotonic_clock::time_point monotonic_remote_time,
monotonic_clock::time_point monotonic_event_time,
- bool reliable);
+ bool reliable,
+ monotonic_clock::time_point monotonic_timestamp_time =
+ monotonic_clock::min_time);
// Queues up a message with the provided boot UUID.
void QueueMessage(flatbuffers::FlatBufferBuilder *fbb,
const UUID &node_boot_uuid,
@@ -98,6 +102,27 @@
// 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;
+
+ // Timestamp on the remote monotonic clock of the oldest message timestamp
+ // sent back to logger_node_index_. The remote here will be the node this
+ // part is from the perspective of, ie node_index_.
+ monotonic_clock::time_point
+ oldest_logger_remote_unreliable_monotonic_timestamp =
+ monotonic_clock::max_time;
+ // The time on the monotonic clock of the logger when this timestamp made it
+ // back to the logger (logger_node_index_).
+ monotonic_clock::time_point
+ oldest_logger_local_unreliable_monotonic_timestamp =
+ monotonic_clock::max_time;
};
private:
@@ -113,6 +138,7 @@
const Node *node_ = nullptr;
size_t node_index_ = 0;
+ size_t logger_node_index_ = 0;
LogNamer *log_namer_;
UUID parts_uuid_ = UUID::Random();
size_t parts_index_ = 0;
@@ -271,14 +297,15 @@
const aos::Node *node)
: LogNamer(event_loop->configuration(), event_loop, node),
base_name_(base_name),
- data_writer_(this, node,
- [this](NewDataWriter *writer) {
- writer->writer = std::make_unique<DetachedBufferWriter>(
- absl::StrCat(base_name_, ".part",
- writer->parts_index(), ".bfbs"),
- std::make_unique<aos::logger::DummyEncoder>());
- },
- [](NewDataWriter * /*writer*/) {}) {}
+ data_writer_(
+ this, node, event_loop->node(),
+ [this](NewDataWriter *writer) {
+ writer->writer = std::make_unique<DetachedBufferWriter>(
+ absl::StrCat(base_name_, ".part", writer->parts_index(),
+ ".bfbs"),
+ std::make_unique<aos::logger::DummyEncoder>());
+ },
+ [](NewDataWriter * /*writer*/) {}) {}
LocalLogNamer(const LocalLogNamer &) = delete;
LocalLogNamer(LocalLogNamer &&) = delete;
diff --git a/aos/events/logging/log_reader.cc b/aos/events/logging/log_reader.cc
index 63eba05..e58ccd2 100644
--- a/aos/events/logging/log_reader.cc
+++ b/aos/events/logging/log_reader.cc
@@ -292,8 +292,7 @@
states_[configuration::GetNodeIndex(configuration(), node)].get();
CHECK(state != nullptr) << ": Unknown node " << FlatbufferToJson(node);
- // TODO(austin): Un-hard-code the 0 boot count.
- return state->monotonic_start_time(0);
+ return state->monotonic_start_time(state->boot_count());
}
realtime_clock::time_point LogReader::realtime_start_time(
@@ -302,8 +301,7 @@
states_[configuration::GetNodeIndex(configuration(), node)].get();
CHECK(state != nullptr) << ": Unknown node " << FlatbufferToJson(node);
- // TODO(austin): Un-hard-code the 0 boot count.
- return state->realtime_start_time(0);
+ return state->realtime_start_time(state->boot_count());
}
void LogReader::OnStart(std::function<void()> fn) {
diff --git a/aos/events/logging/log_reader.h b/aos/events/logging/log_reader.h
index 5cccdeb..3eebba7 100644
--- a/aos/events/logging/log_reader.h
+++ b/aos/events/logging/log_reader.h
@@ -400,7 +400,7 @@
->node_event_loop_factory_->node();
}
- monotonic_clock::time_point monotonic_now() {
+ monotonic_clock::time_point monotonic_now() const {
return node_event_loop_factory_->monotonic_now();
}
diff --git a/aos/events/logging/log_writer.cc b/aos/events/logging/log_writer.cc
index 5931200..0e1dece 100644
--- a/aos/events/logging/log_writer.cc
+++ b/aos/events/logging/log_writer.cc
@@ -729,10 +729,10 @@
message_header_builder.add_remote_queue_index(
msg->remote_queue_index());
+ const aos::monotonic_clock::time_point monotonic_timestamp_time =
+ f.fetcher->context().monotonic_event_time;
message_header_builder.add_monotonic_timestamp_time(
- f.fetcher->context()
- .monotonic_event_time.time_since_epoch()
- .count());
+ monotonic_timestamp_time.time_since_epoch().count());
fbb.FinishSizePrefixed(message_header_builder.Finish());
const auto end = event_loop_->monotonic_now();
@@ -755,7 +755,7 @@
chrono::nanoseconds(msg->monotonic_remote_time())),
monotonic_clock::time_point(
chrono::nanoseconds(msg->monotonic_sent_time())),
- reliable);
+ reliable, monotonic_timestamp_time);
f.contents_writer->QueueMessage(
&fbb, UUID::FromVector(msg->boot_uuid()), end);
diff --git a/aos/events/logging/logfile_sorting.cc b/aos/events/logging/logfile_sorting.cc
index 30de0b5..1e7c817 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, 32u);
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,10 @@
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;
+ if (header->has_oldest_logger_remote_unreliable_monotonic_timestamps()) return false;
+ if (header->has_oldest_logger_local_unreliable_monotonic_timestamps()) return false;
return header->has_configuration();
}
@@ -259,6 +263,13 @@
// For a pair of nodes, this holds the oldest times that messages were
// transfered.
+//
+// TODO(austin): We are finding that the timestamps in
+// oldest_remote_monotonic_timestamp are not very useful because there may not
+// be reliable messages on both boots in the log. Figure out how to use that
+// data better (or really, use the new reliable remote timestamps field) and
+// update this code. I think we can delay a bit until someone figures out how
+// to get here without other code paths sorting us first.
struct BootPairTimes {
// Pair of local and remote timestamps for the oldest message forwarded to
// this node.
@@ -616,6 +627,21 @@
log_header->message()
.oldest_remote_unreliable_monotonic_timestamps()
->size());
+ CHECK_EQ(log_header->message()
+ .has_oldest_logger_local_unreliable_monotonic_timestamps(),
+ log_header->message()
+ .has_oldest_logger_remote_unreliable_monotonic_timestamps());
+ if (log_header->message()
+ .has_oldest_logger_local_unreliable_monotonic_timestamps()) {
+ CHECK_EQ(boot_uuids_size,
+ log_header->message()
+ .oldest_logger_local_unreliable_monotonic_timestamps()
+ ->size());
+ CHECK_EQ(boot_uuids_size,
+ log_header->message()
+ .oldest_logger_remote_unreliable_monotonic_timestamps()
+ ->size());
+ }
CHECK(!logger_boot_uuid.empty());
CHECK(!source_boot_uuid.empty());
for (size_t node_index = 0; node_index < boot_uuids_size; ++node_index) {
@@ -640,7 +666,26 @@
log_header->message()
.oldest_remote_unreliable_monotonic_timestamps()
->Get(node_index)));
- if (boot_uuid.empty() || boot_uuid == source_boot_uuid) {
+
+ const monotonic_clock::time_point
+ oldest_logger_local_unreliable_monotonic_timestamp =
+ log_header->message()
+ .has_oldest_logger_local_unreliable_monotonic_timestamps()
+ ? monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_logger_local_unreliable_monotonic_timestamps()
+ ->Get(node_index)))
+ : monotonic_clock::max_time;
+ const monotonic_clock::time_point
+ oldest_logger_remote_unreliable_monotonic_timestamp =
+ log_header->message()
+ .has_oldest_logger_remote_unreliable_monotonic_timestamps()
+ ? monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_logger_remote_unreliable_monotonic_timestamps()
+ ->Get(node_index)))
+ : monotonic_clock::max_time;
+ if (boot_uuid.empty()) {
CHECK_EQ(oldest_local_monotonic_timestamp, monotonic_clock::max_time);
CHECK_EQ(oldest_remote_monotonic_timestamp,
monotonic_clock::max_time);
@@ -648,9 +693,113 @@
monotonic_clock::max_time);
CHECK_EQ(oldest_remote_unreliable_monotonic_timestamp,
monotonic_clock::max_time);
+ CHECK_EQ(oldest_logger_local_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+ CHECK_EQ(oldest_logger_remote_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
continue;
}
+ if (boot_uuid == source_boot_uuid) {
+ CHECK_EQ(oldest_local_monotonic_timestamp, monotonic_clock::max_time);
+ CHECK_EQ(oldest_remote_monotonic_timestamp,
+ monotonic_clock::max_time);
+ CHECK_EQ(oldest_local_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+ CHECK_EQ(oldest_remote_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+ if (oldest_logger_local_unreliable_monotonic_timestamp !=
+ monotonic_clock::max_time) {
+ CHECK_NE(oldest_logger_remote_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+ // Now, we found a timestamp going the other way. Add it in!
+ auto logger_node_boot_times_it = boot_times.find(logger_node);
+ if (logger_node_boot_times_it == boot_times.end()) {
+ logger_node_boot_times_it =
+ boot_times
+ .emplace(
+ logger_node,
+ absl::btree_map<
+ std::string,
+ absl::btree_map<
+ size_t, absl::btree_map<
+ std::string,
+ std::vector<BootPairTimes>>>>())
+ .first;
+ }
+
+ auto logger_source_boot_times_it =
+ logger_node_boot_times_it->second.find(
+ std::string(logger_boot_uuid));
+
+ if (logger_source_boot_times_it ==
+ logger_node_boot_times_it->second.end()) {
+ logger_source_boot_times_it =
+ logger_node_boot_times_it->second
+ .emplace(
+ logger_boot_uuid,
+ absl::btree_map<
+ size_t,
+ absl::btree_map<std::string,
+ std::vector<BootPairTimes>>>())
+ .first;
+ }
+
+ // We need the index of the source node. Luckily, since we are at
+ // the index in the boot UUID list which matches the source node
+ // boot uuid, we know it's index!
+ auto logger_destination_boot_times_it =
+ logger_source_boot_times_it->second.find(node_index);
+ if (logger_destination_boot_times_it ==
+ logger_source_boot_times_it->second.end()) {
+ logger_destination_boot_times_it =
+ logger_source_boot_times_it->second
+ .emplace(node_index,
+ absl::btree_map<std::string,
+ std::vector<BootPairTimes>>())
+ .first;
+ }
+
+ auto logger_boot_times_it =
+ logger_destination_boot_times_it->second.find(
+ std::string(source_boot_uuid));
+
+ if (logger_boot_times_it ==
+ logger_destination_boot_times_it->second.end()) {
+ // We have a new boot UUID pairing. Copy over the data we have.
+ logger_destination_boot_times_it->second.emplace(
+ source_boot_uuid,
+ std::vector<BootPairTimes>{BootPairTimes{
+ .oldest_remote_monotonic_timestamp =
+ monotonic_clock::max_time,
+ .oldest_local_monotonic_timestamp =
+ monotonic_clock::max_time,
+ .oldest_remote_unreliable_monotonic_timestamp =
+ oldest_logger_remote_unreliable_monotonic_timestamp,
+ .oldest_local_unreliable_monotonic_timestamp =
+ oldest_logger_local_unreliable_monotonic_timestamp}});
+ } else {
+ logger_boot_times_it->second.emplace_back(BootPairTimes{
+ .oldest_remote_monotonic_timestamp =
+ monotonic_clock::max_time,
+ .oldest_local_monotonic_timestamp = monotonic_clock::max_time,
+ .oldest_remote_unreliable_monotonic_timestamp =
+ oldest_logger_remote_unreliable_monotonic_timestamp,
+ .oldest_local_unreliable_monotonic_timestamp =
+ oldest_logger_local_unreliable_monotonic_timestamp});
+ }
+ }
+ continue;
+ }
+
+ // There is no supported way to get logger timestamps from anything but
+ // the source node. Since we've already handled that above, we should
+ // always expect max_time here.
+ CHECK_EQ(oldest_logger_local_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+ CHECK_EQ(oldest_logger_remote_unreliable_monotonic_timestamp,
+ monotonic_clock::max_time);
+
// Now, we have a valid pairing.
auto destination_boot_times_it =
source_boot_times_it->second.find(node_index);
@@ -946,24 +1095,9 @@
source_boot_times.begin(), source_boot_times.end(),
[](const std::tuple<std::string, BootPairTimes, BootPairTimes> &a,
const std::tuple<std::string, BootPairTimes, BootPairTimes> &b) {
- // There are cases where we will only have a reliable timestamp.
- // In that case, we need to use oldest_local_monotonic_timestamp.
- // But, that may result in collisions if the same message gets
- // forwarded to both boots, so it will have the same timestamp.
- // Solve that by breaking the tie with the unreliable messages.
- if (std::get<1>(a).oldest_local_monotonic_timestamp ==
- std::get<1>(b).oldest_local_monotonic_timestamp) {
- CHECK_NE(
- std::get<1>(a).oldest_local_unreliable_monotonic_timestamp,
- std::get<1>(b).oldest_local_unreliable_monotonic_timestamp);
- return std::get<1>(a)
- .oldest_local_unreliable_monotonic_timestamp <
- std::get<1>(b)
- .oldest_local_unreliable_monotonic_timestamp;
- } else {
- return std::get<1>(a).oldest_local_monotonic_timestamp <
- std::get<1>(b).oldest_local_monotonic_timestamp;
- }
+ return std::get<1>(a)
+ .oldest_local_unreliable_monotonic_timestamp <
+ std::get<1>(b).oldest_local_unreliable_monotonic_timestamp;
});
// The last time from the source node on the logger node.
@@ -1087,21 +1221,8 @@
destination_boot_times.begin(), destination_boot_times.end(),
[](const std::pair<std::string, BootPairTimes> &a,
const std::pair<std::string, BootPairTimes> &b) {
- // There are cases where we will only have a reliable timestamp.
- // In that case, we need to use oldest_remote_monotonic_timestamp.
- // But, that may result in collisions if the same message gets
- // forwarded to both boots, so it will have the same timestamp.
- // Solve that by breaking the tie with the unreliable messages.
- if (a.second.oldest_remote_monotonic_timestamp ==
- b.second.oldest_remote_monotonic_timestamp) {
- CHECK_NE(a.second.oldest_remote_unreliable_monotonic_timestamp,
- b.second.oldest_remote_unreliable_monotonic_timestamp);
- return a.second.oldest_remote_unreliable_monotonic_timestamp <
- b.second.oldest_remote_unreliable_monotonic_timestamp;
- } else {
- return a.second.oldest_remote_monotonic_timestamp <
- b.second.oldest_remote_monotonic_timestamp;
- }
+ return a.second.oldest_remote_unreliable_monotonic_timestamp <
+ b.second.oldest_remote_unreliable_monotonic_timestamp;
});
for (size_t boot_id = 0; boot_id < destination_boot_times.size();
diff --git a/aos/events/logging/logger.fbs b/aos/events/logging/logger.fbs
index eb70184..0fe6253 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 all three 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,17 @@
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);
+
+ // For all the remote timestamps which come back to the logger. The "local"
+ // time here is the logger node boot, and "remote" is the node which sent the
+ // timestamps.
+ oldest_logger_remote_unreliable_monotonic_timestamps:[int64] (id: 30);
+ oldest_logger_local_unreliable_monotonic_timestamps:[int64] (id: 31);
}
// Table holding a message.
diff --git a/aos/events/logging/logger_test.cc b/aos/events/logging/logger_test.cc
index 081d3c4..1732549 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_);
@@ -2244,6 +2334,7 @@
// Tests that we properly populate and extract the logger_start time by setting
// up a clock difference between 2 nodes and looking at the resulting parts.
TEST_P(MultinodeLoggerTest, LoggerStartTime) {
+ std::vector<std::string> actual_filenames;
time_converter_.AddMonotonic(
{BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
{
@@ -2254,8 +2345,14 @@
StartLogger(&pi2_logger);
event_loop_factory_.RunFor(chrono::milliseconds(10000));
+
+ pi1_logger.AppendAllFilenames(&actual_filenames);
+ pi2_logger.AppendAllFilenames(&actual_filenames);
}
+ ASSERT_THAT(actual_filenames,
+ ::testing::UnorderedElementsAreArray(logfiles_));
+
for (const LogFile &log_file : SortParts(logfiles_)) {
for (const LogParts &log_part : log_file.parts) {
if (log_part.node == log_file.logger_node) {
@@ -2328,6 +2425,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 +2470,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 +2501,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 +2530,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 +2611,34 @@
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)));
+ const monotonic_clock::time_point
+ oldest_logger_remote_unreliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_logger_remote_unreliable_monotonic_timestamps()
+ ->Get(0)));
+ const monotonic_clock::time_point
+ oldest_logger_local_unreliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_logger_local_unreliable_monotonic_timestamps()
+ ->Get(0)));
+ EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
+ monotonic_clock::max_time);
switch (log_header->message().parts_index()) {
case 0:
EXPECT_EQ(oldest_remote_monotonic_timestamps,
@@ -2512,6 +2648,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 +2662,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 +2698,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 +2797,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;
@@ -2645,6 +2835,32 @@
.oldest_local_unreliable_monotonic_timestamps()
->size(),
2u);
+ ASSERT_TRUE(log_header->message()
+ .has_oldest_remote_reliable_monotonic_timestamps());
+ ASSERT_EQ(log_header->message()
+ .oldest_remote_reliable_monotonic_timestamps()
+ ->size(),
+ 2u);
+ ASSERT_TRUE(log_header->message()
+ .has_oldest_local_reliable_monotonic_timestamps());
+ ASSERT_EQ(log_header->message()
+ .oldest_local_reliable_monotonic_timestamps()
+ ->size(),
+ 2u);
+
+ ASSERT_TRUE(
+ log_header->message()
+ .has_oldest_logger_remote_unreliable_monotonic_timestamps());
+ ASSERT_EQ(log_header->message()
+ .oldest_logger_remote_unreliable_monotonic_timestamps()
+ ->size(),
+ 2u);
+ ASSERT_TRUE(log_header->message()
+ .has_oldest_logger_local_unreliable_monotonic_timestamps());
+ ASSERT_EQ(log_header->message()
+ .oldest_logger_local_unreliable_monotonic_timestamps()
+ ->size(),
+ 2u);
if (log_header->message().node()->name()->string_view() != "pi1") {
ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
@@ -2663,11 +2879,16 @@
const monotonic_clock::time_point
expected_oldest_remote_monotonic_timestamps(
chrono::nanoseconds(msg->message().monotonic_remote_time()));
+ const monotonic_clock::time_point
+ expected_oldest_timestamp_monotonic_timestamps(
+ chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
EXPECT_NE(expected_oldest_local_monotonic_timestamps,
monotonic_clock::min_time);
EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
monotonic_clock::min_time);
+ EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
+ monotonic_clock::min_time);
++timestamp_file_count;
// Since the log file is from the perspective of the other node,
@@ -2691,6 +2912,30 @@
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 monotonic_clock::time_point
+ oldest_logger_remote_unreliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_logger_remote_unreliable_monotonic_timestamps()
+ ->Get(1)));
+ const monotonic_clock::time_point
+ oldest_logger_local_unreliable_monotonic_timestamps =
+ monotonic_clock::time_point(chrono::nanoseconds(
+ log_header->message()
+ .oldest_logger_local_unreliable_monotonic_timestamps()
+ ->Get(1)));
const Channel *channel =
event_loop_factory_.configuration()->channels()->Get(
@@ -2702,6 +2947,10 @@
const bool reliable = connection->time_to_live() == 0;
+ SCOPED_TRACE(file);
+ SCOPED_TRACE(aos::FlatbufferToJson(
+ *log_header, {.multi_line = true, .max_vector_size = 100}));
+
if (shared()) {
// Confirm that the oldest timestamps match what we expect. Based on
// what we are doing, we know that the oldest time is the first
@@ -2711,17 +2960,60 @@
// 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);
+ EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps) << file;
+ EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
+ expected_oldest_timestamp_monotonic_timestamps) << file;
+
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));
+ EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90150000));
+ EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90250000));
+ 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,7 +3021,38 @@
}
break;
case 2:
- LOG(INFO) << "Shared";
+ EXPECT_EQ(
+ oldest_remote_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
+ EXPECT_EQ(
+ oldest_local_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
+ EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps) << file;
+ EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
+ expected_oldest_timestamp_monotonic_timestamps) << file;
+ 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:
EXPECT_EQ(
oldest_remote_monotonic_timestamps,
monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
@@ -2740,6 +3063,12 @@
expected_oldest_remote_monotonic_timestamps);
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
expected_oldest_local_monotonic_timestamps);
+ EXPECT_EQ(
+ oldest_logger_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
+ EXPECT_EQ(
+ oldest_logger_local_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
break;
default:
FAIL();
@@ -2752,14 +3081,17 @@
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);
- LOG(INFO) << "Shared";
break;
}
[[fallthrough]];
@@ -2770,17 +3102,57 @@
} else {
switch (log_header->message().parts_index()) {
case 0:
+ if (reliable) {
+ EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
+ monotonic_clock::max_time);
+ EXPECT_EQ(
+ oldest_logger_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(100150000))
+ << file;
+ EXPECT_EQ(
+ oldest_logger_local_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(100250000))
+ << file;
+ } else {
+ EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
+ expected_oldest_remote_monotonic_timestamps);
+ EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
+ expected_oldest_local_monotonic_timestamps);
+ EXPECT_EQ(
+ oldest_logger_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90150000))
+ << file;
+ EXPECT_EQ(
+ oldest_logger_local_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(90250000))
+ << file;
+ }
+ break;
case 1:
if (reliable) {
EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
monotonic_clock::max_time);
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
monotonic_clock::max_time);
+ EXPECT_EQ(
+ oldest_logger_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
+ EXPECT_EQ(
+ oldest_logger_local_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
} else {
EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
expected_oldest_remote_monotonic_timestamps);
EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
expected_oldest_local_monotonic_timestamps);
+ EXPECT_EQ(
+ oldest_logger_remote_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
+ EXPECT_EQ(
+ oldest_logger_local_unreliable_monotonic_timestamps,
+ monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
}
break;
default:
@@ -2855,7 +3227,7 @@
}
if (shared()) {
- EXPECT_EQ(timestamp_file_count, 3u);
+ EXPECT_EQ(timestamp_file_count, 4u);
} else {
EXPECT_EQ(timestamp_file_count, 4u);
}
@@ -3229,7 +3601,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 +3657,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});
}
diff --git a/aos/events/shm_event_loop.h b/aos/events/shm_event_loop.h
index 71dff4e..e51f21b 100644
--- a/aos/events/shm_event_loop.h
+++ b/aos/events/shm_event_loop.h
@@ -48,10 +48,10 @@
// Exits the event loop. Async safe.
void Exit();
- aos::monotonic_clock::time_point monotonic_now() override {
+ aos::monotonic_clock::time_point monotonic_now() const override {
return aos::monotonic_clock::now();
}
- aos::realtime_clock::time_point realtime_now() override {
+ aos::realtime_clock::time_point realtime_now() const override {
return aos::realtime_clock::now();
}
diff --git a/aos/events/simulated_event_loop.cc b/aos/events/simulated_event_loop.cc
index 2a276e7..a2428a4 100644
--- a/aos/events/simulated_event_loop.cc
+++ b/aos/events/simulated_event_loop.cc
@@ -584,11 +584,11 @@
send_delay_ = send_delay;
}
- monotonic_clock::time_point monotonic_now() override {
+ monotonic_clock::time_point monotonic_now() const override {
return node_event_loop_factory_->monotonic_now();
}
- realtime_clock::time_point realtime_now() override {
+ realtime_clock::time_point realtime_now() const override {
return node_event_loop_factory_->realtime_now();
}
diff --git a/aos/network/message_bridge_server_lib.cc b/aos/network/message_bridge_server_lib.cc
index 2ca8e48..e8e0261 100644
--- a/aos/network/message_bridge_server_lib.cc
+++ b/aos/network/message_bridge_server_lib.cc
@@ -257,7 +257,7 @@
}) {
CHECK(event_loop_->node() != nullptr) << ": No nodes configured.";
- int32_t max_size = 0;
+ size_t max_size = 0;
// Seed up all the per-node connection state.
// We are making the assumption here that every connection is bidirectional
@@ -269,14 +269,14 @@
// Find the largest connection message so we can size our buffers big enough
// to receive a connection message. The connect message comes from the
// client to the server, so swap the node arguments.
- const int32_t connect_size = static_cast<int32_t>(
+ const size_t connect_size =
MakeConnectMessage(event_loop->configuration(),
configuration::GetNode(event_loop->configuration(),
destination_node_name),
event_loop->node()->name()->string_view(),
UUID::Zero())
.span()
- .size());
+ .size();
VLOG(1) << "Connection to " << destination_node_name << " has size "
<< connect_size;
max_size = std::max(max_size, connect_size);
@@ -310,7 +310,10 @@
any_reliable = true;
}
}
- max_size = std::max(channel->max_size(), max_size);
+ max_size =
+ std::max(static_cast<size_t>(channel->max_size() *
+ channel->destination_nodes()->size()),
+ max_size);
std::unique_ptr<ChannelState> state(new ChannelState{
channel, channel_index,
any_reliable ? event_loop_->MakeRawFetcher(channel) : nullptr});
@@ -371,7 +374,7 @@
// Buffer up the max size a bit so everything fits nicely.
LOG(INFO) << "Max message size for all clients is " << max_size;
- server_.SetMaxSize(max_size + 100);
+ server_.SetMaxSize(max_size + 100u);
}
void MessageBridgeServer::NodeConnected(sctp_assoc_t assoc_id) {
diff --git a/aos/network/sctp_lib.cc b/aos/network/sctp_lib.cc
index 33d3352..5bc1b37 100644
--- a/aos/network/sctp_lib.cc
+++ b/aos/network/sctp_lib.cc
@@ -319,6 +319,9 @@
if (size == -1) {
if (errno == EPIPE || errno == EAGAIN || errno == ESHUTDOWN ||
errno == EINTR) {
+ if (VLOG_IS_ON(1)) {
+ PLOG(WARNING) << "sendmsg on sctp socket failed";
+ }
return false;
}
PLOG(FATAL) << "sendmsg on sctp socket failed";
diff --git a/aos/time/time.cc b/aos/time/time.cc
index a956f94..05510e9 100644
--- a/aos/time/time.cc
+++ b/aos/time/time.cc
@@ -91,11 +91,11 @@
return std::nullopt;
}
- if (now.substr(now.size() - 13, 1) != ".") {
+ if (now[now.size() - 13] != '.') {
return std::nullopt;
}
- bool negative = now.substr(0, 1) == "-";
+ bool negative = now[0] == '-';
std::string sec(
now.substr(negative ? 1 : 0, now.size() - (negative ? 14 : 13)));
@@ -119,7 +119,7 @@
return std::nullopt;
}
- if (now.substr(now.size() - 10, 1) != ".") {
+ if (now[now.size() - 10] != '.') {
return std::nullopt;
}