Make LogNamer copy a template header rather than modify an input
This sets us up much better for making it so LogNamer can decided when
to rotate to handle boot UUIDs changes. We also have a bug hiding in
log_writer where we get duplicate headers written. This will make that
a lot harder to do by accident once we've got all the tracking
simplified inside LogNamer.
Change-Id: Ib4a2eb5085e12f74c2c61c58d1f511fc2aeb85fa
Signed-off-by: Austin Schuh <austin.schuh@bluerivertech.com>
diff --git a/aos/events/logging/log_writer.cc b/aos/events/logging/log_writer.cc
index abae9a1..71c5750 100644
--- a/aos/events/logging/log_writer.cc
+++ b/aos/events/logging/log_writer.cc
@@ -259,11 +259,7 @@
? configuration_->nodes()->size()
: 1u);
- for (const Node *node : log_namer_->nodes()) {
- const int node_index = configuration::GetNodeIndex(configuration_, node);
-
- node_state_[node_index].log_file_header = MakeHeader(node, config_sha256);
- }
+ log_namer_->SetHeaderTemplate(MakeHeader(config_sha256));
const aos::monotonic_clock::time_point beginning_time =
event_loop_->monotonic_now();
@@ -283,8 +279,9 @@
// Clear out any old timestamps in case we are re-starting logging.
for (size_t i = 0; i < node_state_.size(); ++i) {
- SetStartTime(i, monotonic_clock::min_time, realtime_clock::min_time,
- monotonic_clock::min_time, realtime_clock::min_time);
+ log_namer_->SetStartTimes(
+ i, monotonic_clock::min_time, realtime_clock::min_time,
+ monotonic_clock::min_time, realtime_clock::min_time);
}
const aos::monotonic_clock::time_point fetch_time =
@@ -346,9 +343,9 @@
server_statistics_fetcher_.Fetch();
}
- aos::monotonic_clock::time_point monotonic_start_time =
+ const aos::monotonic_clock::time_point monotonic_start_time =
event_loop_->monotonic_now();
- aos::realtime_clock::time_point realtime_start_time =
+ const aos::realtime_clock::time_point realtime_start_time =
event_loop_->realtime_now();
// We need to pick a point in time to declare the log file "started". This
@@ -399,9 +396,10 @@
//
// header_valid is cleared whenever the remote reboots.
if (node_state_[node_index].header_written) {
- log_namer_->Reboot(node, &node_state_[node_index].log_file_header);
+ VLOG(1) << "Rebooting";
+ log_namer_->Reboot(node);
} else {
- log_namer_->WriteHeader(&node_state_[node_index].log_file_header, node);
+ log_namer_->WriteHeader(node);
node_state_[node_index].header_written = true;
}
@@ -427,77 +425,32 @@
server_statistics_fetcher_.context().realtime_event_time)) {
CHECK(node_state_[node_index].header_written);
CHECK(node_state_[node_index].header_valid);
- log_namer_->Rotate(node, &node_state_[node_index].log_file_header);
+ VLOG(1) << "Rotating because timestamps changed";
+ log_namer_->Rotate(node);
} else {
MaybeWriteHeader(node_index, node);
}
}
}
-void Logger::SetStartTime(
- size_t node_index, aos::monotonic_clock::time_point monotonic_start_time,
- aos::realtime_clock::time_point realtime_start_time,
- aos::monotonic_clock::time_point logger_monotonic_start_time,
- aos::realtime_clock::time_point logger_realtime_start_time) {
- node_state_[node_index].monotonic_start_time = monotonic_start_time;
- node_state_[node_index].realtime_start_time = realtime_start_time;
- node_state_[node_index]
- .log_file_header.mutable_message()
- ->mutate_monotonic_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- monotonic_start_time.time_since_epoch())
- .count());
-
- // Add logger start times if they are available in the log file header.
- if (node_state_[node_index]
- .log_file_header.mutable_message()
- ->has_logger_monotonic_start_time()) {
- node_state_[node_index]
- .log_file_header.mutable_message()
- ->mutate_logger_monotonic_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- logger_monotonic_start_time.time_since_epoch())
- .count());
- }
-
- if (node_state_[node_index]
- .log_file_header.mutable_message()
- ->has_logger_realtime_start_time()) {
- node_state_[node_index]
- .log_file_header.mutable_message()
- ->mutate_logger_realtime_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- logger_realtime_start_time.time_since_epoch())
- .count());
- }
-
- if (node_state_[node_index]
- .log_file_header.mutable_message()
- ->has_realtime_start_time()) {
- node_state_[node_index]
- .log_file_header.mutable_message()
- ->mutate_realtime_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- realtime_start_time.time_since_epoch())
- .count());
- }
-}
-
bool Logger::MaybeUpdateTimestamp(
const Node *node, int node_index,
aos::monotonic_clock::time_point monotonic_start_time,
aos::realtime_clock::time_point realtime_start_time) {
// Bail early if the start times are already set.
- if (node_state_[node_index].monotonic_start_time !=
+ if (log_namer_->monotonic_start_time(node_index) !=
monotonic_clock::min_time) {
return false;
}
if (event_loop_->node() == node ||
!configuration::MultiNode(configuration_)) {
// There are no offsets to compute for ourself, so always succeed.
- SetStartTime(node_index, monotonic_start_time, realtime_start_time,
- monotonic_start_time, realtime_start_time);
- node_state_[node_index].SetBootUUID(event_loop_->boot_uuid());
+ log_namer_->SetStartTimes(node_index, monotonic_start_time,
+ realtime_start_time, monotonic_start_time,
+ realtime_start_time);
+ log_namer_->SetBootUUID(node_index, event_loop_->boot_uuid());
+ node_state_[node_index].header_valid = false;
+ node_state_[node_index].has_source_node_boot_uuid = true;
return true;
} else if (server_statistics_fetcher_.get() != nullptr) {
// We must be a remote node now. Look for the connection and see if it is
@@ -523,11 +476,11 @@
}
// Found it and it is connected. Compensate and go.
- SetStartTime(node_index,
- monotonic_start_time +
- std::chrono::nanoseconds(connection->monotonic_offset()),
- realtime_start_time, monotonic_start_time,
- realtime_start_time);
+ log_namer_->SetStartTimes(
+ node_index,
+ monotonic_start_time +
+ std::chrono::nanoseconds(connection->monotonic_offset()),
+ realtime_start_time, monotonic_start_time, realtime_start_time);
return true;
}
}
@@ -535,8 +488,7 @@
}
aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> Logger::MakeHeader(
- const Node *node, std::string_view config_sha256) {
- // Now write the header with this timestamp in it.
+ std::string_view config_sha256) {
flatbuffers::FlatBufferBuilder fbb;
fbb.ForceDefaults(true);
@@ -570,17 +522,9 @@
const flatbuffers::Offset<flatbuffers::String> logger_node_boot_uuid_offset =
event_loop_->boot_uuid().PackString(&fbb);
- const flatbuffers::Offset<flatbuffers::String> source_node_boot_uuid_offset =
- event_loop_->boot_uuid().PackString(&fbb);
-
- const flatbuffers::Offset<flatbuffers::String> parts_uuid_offset =
- fbb.CreateString("00000000-0000-4000-8000-000000000000");
-
- flatbuffers::Offset<Node> node_offset;
flatbuffers::Offset<Node> logger_node_offset;
if (configuration::MultiNode(configuration_)) {
- node_offset = RecursiveCopyFlatBuffer(node, &fbb);
logger_node_offset = RecursiveCopyFlatBuffer(event_loop_->node(), &fbb);
}
@@ -589,8 +533,7 @@
log_file_header_builder.add_name(name_offset);
// Only add the node if we are running in a multinode configuration.
- if (node != nullptr) {
- log_file_header_builder.add_node(node_offset);
+ if (configuration::MultiNode(configuration_)) {
log_file_header_builder.add_logger_node(logger_node_offset);
}
@@ -605,26 +548,6 @@
log_file_header_builder.add_max_out_of_order_duration(
std::chrono::nanoseconds(3 * polling_period_).count());
- log_file_header_builder.add_monotonic_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- monotonic_clock::min_time.time_since_epoch())
- .count());
- if (node == event_loop_->node()) {
- log_file_header_builder.add_realtime_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- realtime_clock::min_time.time_since_epoch())
- .count());
- } else {
- log_file_header_builder.add_logger_monotonic_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- monotonic_clock::min_time.time_since_epoch())
- .count());
- log_file_header_builder.add_logger_realtime_start_time(
- std::chrono::duration_cast<std::chrono::nanoseconds>(
- realtime_clock::min_time.time_since_epoch())
- .count());
- }
-
log_file_header_builder.add_log_event_uuid(log_event_uuid_offset);
log_file_header_builder.add_logger_instance_uuid(logger_instance_uuid_offset);
if (!log_start_uuid_offset.IsNull()) {
@@ -632,13 +555,6 @@
}
log_file_header_builder.add_logger_node_boot_uuid(
logger_node_boot_uuid_offset);
- log_file_header_builder.add_source_node_boot_uuid(
- source_node_boot_uuid_offset);
-
- log_file_header_builder.add_parts_uuid(parts_uuid_offset);
- log_file_header_builder.add_parts_index(0);
-
- log_file_header_builder.add_configuration_sha256(0);
if (!config_sha256_offset.IsNull()) {
log_file_header_builder.add_configuration_sha256(config_sha256_offset);
@@ -672,8 +588,7 @@
void Logger::Rotate() {
for (const Node *node : log_namer_->nodes()) {
- const int node_index = configuration::GetNodeIndex(configuration_, node);
- log_namer_->Rotate(node, &node_state_[node_index].log_file_header);
+ log_namer_->Rotate(node);
}
}
@@ -712,8 +627,10 @@
// 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().source_boot_uuid)) {
+ if (log_namer_->SetBootUUID(f.data_node_index,
+ f.fetcher->context().source_boot_uuid)) {
+ node_state_[f.data_node_index].header_valid = false;
+ node_state_[f.data_node_index].has_source_node_boot_uuid = true;
MaybeWriteHeader(f.data_node_index);
}
}
@@ -784,8 +701,10 @@
flatbuffers::GetRoot<RemoteMessage>(f.fetcher->context().data);
CHECK(msg->has_boot_uuid()) << ": " << aos::FlatbufferToJson(msg);
- if (node_state_[f.contents_node_index].SetBootUUID(
- UUID::FromVector(msg->boot_uuid()))) {
+ if (log_namer_->SetBootUUID(f.contents_node_index,
+ UUID::FromVector(msg->boot_uuid()))) {
+ node_state_[f.contents_node_index].header_valid = false;
+ node_state_[f.contents_node_index].has_source_node_boot_uuid = true;
MaybeWriteHeader(f.contents_node_index);
}