Fix the race condition when rotating the logger.
There's a small race condition which allows for over polling_period_ of
data to be written per channel, violating the max out of order duration
in the header.
1) while (LogUntil(last_synchronized_time_ + polling_period_)) flushes
until "now" into the old log. All good there.
2) WriteConfiguration() takes 300ms to compress the config and write
it. The same effect can be triggered by the kernel preempting the
logger for over 300ms here as well. That's not impossible either.
3) WriteHeader() updates last_synchronized_time_, ie over 300ms after we
last flushed data to disk.
4) The new "double logging" portion of the logger which is supposed to
make sure everything gets logged up to the start time in the old log
does this all in 1 go. So, it writes 300ms+ of data per channel, up
to the new last_synchronized_time_ from WriteHeader().
This generates a corrupted log.
To fix this, we just need to pick a start time which is after the last
message in the previous log (step 1), but is guarenteed to be before we
start double logging and needs to be at most polling_period_ since the
last time we flushed. Pick the min of last_synchronized_time_ and right
after we finished flushing in step 1), which is guarenteed to have both
those properties.
Change-Id: I117fc77186e489d3eb8936336ff744d56a2a5fb5
Signed-off-by: James Kuszmaul <james.kuszmaul@bluerivertech.com>
diff --git a/aos/events/logging/log_writer.cc b/aos/events/logging/log_writer.cc
index 8018273..2a53f05 100644
--- a/aos/events/logging/log_writer.cc
+++ b/aos/events/logging/log_writer.cc
@@ -389,8 +389,32 @@
std::unique_ptr<LogNamer> old_log_namer = std::move(log_namer_);
log_namer_ = std::move(log_namer);
+ // Now grab a representative time on both the RT and monotonic clock. Average
+ // a monotonic clock before and after to reduce the error.
const aos::monotonic_clock::time_point beginning_time =
event_loop_->monotonic_now();
+ const aos::realtime_clock::time_point beginning_time_rt =
+ event_loop_->realtime_now();
+ const aos::monotonic_clock::time_point beginning_time2 =
+ event_loop_->monotonic_now();
+
+ if (beginning_time > last_synchronized_time_) {
+ LOG(WARNING) << "Took over " << polling_period_.count()
+ << "ns to swap log_namer";
+ }
+
+ // Since we are going to log all in 1 big go, we need our log start time to be
+ // after the previous LogUntil call finished, but before 1 period after it.
+ // The best way to guarentee that is to pick a start time that is the earliest
+ // of the two. That covers the case where the OS puts us to sleep between
+ // when we finish LogUntil and capture beginning_time.
+ const aos::monotonic_clock::time_point monotonic_start_time =
+ std::min(last_synchronized_time_, beginning_time);
+ const aos::realtime_clock::time_point realtime_start_time =
+ (beginning_time_rt + (monotonic_start_time.time_since_epoch() -
+ ((beginning_time.time_since_epoch() +
+ beginning_time2.time_since_epoch()) /
+ 2)));
auto config_sha256 = WriteConfiguration(log_namer_.get());
@@ -402,8 +426,9 @@
// Note that WriteHeader updates last_synchronized_time_ to be the
// current time when it is called, which is then the "start time"
// of the new (restarted) log. This timestamp will be after
- // the timestamp of the last message fetched on each channel.
- WriteHeader();
+ // the timestamp of the last message fetched on each channel, but is carefully
+ // picked per the comment above to not violate max_out_of_order_duration.
+ WriteHeader(monotonic_start_time, realtime_start_time);
const aos::monotonic_clock::time_point header_time =
event_loop_->monotonic_now();
@@ -507,15 +532,16 @@
return std::move(log_namer_);
}
-void Logger::WriteHeader() {
+void Logger::WriteHeader(aos::monotonic_clock::time_point monotonic_start_time,
+ aos::realtime_clock::time_point realtime_start_time) {
if (configuration::MultiNode(configuration_)) {
server_statistics_fetcher_.Fetch();
}
- const aos::monotonic_clock::time_point monotonic_start_time =
- event_loop_->monotonic_now();
- const aos::realtime_clock::time_point realtime_start_time =
- event_loop_->realtime_now();
+ if (monotonic_start_time == aos::monotonic_clock::min_time) {
+ monotonic_start_time = event_loop_->monotonic_now();
+ realtime_start_time = event_loop_->realtime_now();
+ }
// We need to pick a point in time to declare the log file "started". This
// starts here. It needs to be after everything is fetched so that the
diff --git a/aos/events/logging/log_writer.h b/aos/events/logging/log_writer.h
index 3c75f29..7beef03 100644
--- a/aos/events/logging/log_writer.h
+++ b/aos/events/logging/log_writer.h
@@ -224,7 +224,10 @@
// Start/Restart write configuration into LogNamer space.
std::string WriteConfiguration(LogNamer* log_namer);
- void WriteHeader();
+ void WriteHeader(aos::monotonic_clock::time_point monotonic_start_time =
+ aos::monotonic_clock::min_time,
+ aos::realtime_clock::time_point realtime_start_time =
+ aos::realtime_clock::min_time);
// Makes a template header for all the follower nodes.
aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> MakeHeader(