Switch Logger over to using the new context UUID
We got a lovely kersplat when Jim rebooted one of the pi's and I tried
to restart the logger. We've seen this occasionally in a bunch of
spots randomly.
F0313 17:40:26.905807 1893 log_writer.cc:677] Check failed: node_state_[f.data_node_index].header_valid : Can't write data before the header on channel { "name": "/pi2/aos", "type": "aos.message_bridge.Timestamp", "frequency": 10, "max_size": 200, "num_senders": 2, "source_node": "pi2", "destination_nodes": [ { "name": "roborio", "timestamp_logger": "LOCAL_AND_REMOTE_LOGGER", "timestamp_logger_nodes": [ "roborio" ], "priority": 1, "time_to_live": 5000000 }, { "name": "laptop", "priority": 1, "time_to_live": 5000000 } ], "logger": "LOCAL_AND_REMOTE_LOGGER", "logger_nodes": [ "roborio", "laptop" ] }
*** Check failure stack trace: ***
@ 0x53c888 google::LogMessage::Fail()
@ 0x53e418 google::LogMessage::SendToLog()
@ 0x53c508 google::LogMessage::Flush()
@ 0x53cbec google::LogMessageFatal::~LogMessageFatal()
@ 0x4e2f00 aos::logger::Logger::LogUntil()
@ 0x4e5784 aos::logger::Logger::StartLogging()
@ 0x4d90f0 _ZNSt17_Function_handlerIFvvEZ4mainEUlvE_E9_M_invokeERKSt9_Any_data
@ 0x4f6cac aos::ShmEventLoop::Run()
@ 0x4d4288 main
@ 0xb6c1e580 __libc_start_main
This is because we are using the ServerStatistics message for the boot
UUID of a node. If the logger starts up and there is data on a channel
from a node which isn't currently active, we don't have a way of telling
which boot that data is from. That means we can't log the header, so we
can't log the data.
Instead of using the ServerStatistics message, use the new
remote_boot_uuid for the message. That tells us exactly which boot is
is from reliably. Since it is attached to the message, it can never get
out of sync.
The downside here is that we are adding another 16 bytes to each message
that is being sent. That is close to doubling our overhead, but should
be significantly less than a simple flatbuffer.
Another option could have been to drop the data. But, in the case of
parameters messages from other nodes which are low frequency and
critical for operating the system, we would not be able to reproduce the
state reliably.
Alternatives could also be to make the ServerStatistics message
complicated enough to track what messages came from what boot. This
would likely end up being wack-a-mole to try to figure out how to
describe which messages from a bunch of vintages could be from which
boots in the queues.
Change-Id: Idc531ca1ff1628c38efc4877661f121c94641e78
diff --git a/aos/events/logging/log_writer.cc b/aos/events/logging/log_writer.cc
index 400ad8d..0b08c94 100644
--- a/aos/events/logging/log_writer.cc
+++ b/aos/events/logging/log_writer.cc
@@ -241,7 +241,8 @@
WriteHeader();
LOG(INFO) << "Logging node as " << FlatbufferToJson(event_loop_->node())
- << " start_time " << last_synchronized_time_;
+ << " start_time " << last_synchronized_time_ << " boot uuid "
+ << event_loop_->boot_uuid();
// Force logging up until the start of the log file now, so the messages at
// the start are always ordered before the rest of the messages.
@@ -451,19 +452,6 @@
break;
}
- // Update the boot UUID as soon as we know we are connected.
- if (!connection->has_boot_uuid()) {
- VLOG(1) << "Missing boot_uuid for node " << aos::FlatbufferToJson(node);
- break;
- }
-
- if (!node_state_[node_index].has_source_node_boot_uuid ||
- node_state_[node_index].source_node_boot_uuid !=
- connection->boot_uuid()->string_view()) {
- node_state_[node_index].SetBootUUID(
- connection->boot_uuid()->string_view());
- }
-
if (!connection->has_monotonic_offset()) {
VLOG(1) << "Missing monotonic offset for setting start time for node "
<< aos::FlatbufferToJson(node);
@@ -631,6 +619,9 @@
// reboots which may have happened.
WriteMissingTimestamps();
+ int our_node_index = aos::configuration::GetNodeIndex(
+ event_loop_->configuration(), event_loop_->node());
+
// Write each channel to disk, one at a time.
for (FetcherStruct &f : fetchers_) {
while (true) {
@@ -653,6 +644,16 @@
break;
}
if (f.writer != nullptr) {
+ // Only check if the boot UUID has changed if this is data from another
+ // node. Our UUID can't change without restarting the application.
+ if (our_node_index != f.data_node_index) {
+ // And update our boot UUID if the UUID has changed.
+ if (node_state_[f.data_node_index].SetBootUUID(
+ f.fetcher->context().remote_boot_uuid)) {
+ MaybeWriteHeader(f.data_node_index);
+ }
+ }
+
// Write!
const auto start = event_loop_->monotonic_now();
flatbuffers::FlatBufferBuilder fbb(f.fetcher->context().size +
@@ -719,12 +720,8 @@
flatbuffers::GetRoot<RemoteMessage>(f.fetcher->context().data);
CHECK(msg->has_boot_uuid()) << ": " << aos::FlatbufferToJson(msg);
- if (!node_state_[f.contents_node_index].has_source_node_boot_uuid ||
- node_state_[f.contents_node_index].source_node_boot_uuid !=
- msg->boot_uuid()->string_view()) {
- node_state_[f.contents_node_index].SetBootUUID(
- msg->boot_uuid()->string_view());
-
+ if (node_state_[f.contents_node_index].SetBootUUID(
+ UUID::FromVector(msg->boot_uuid()))) {
MaybeWriteHeader(f.contents_node_index);
}