Handle large, single direction timestamp outages when estimating time
Brian Smartt had the clever idea of taking the max of both directions.
This essentially warps any long stretches of time such that they always
stay above the other direction with more fresh timestamps. Because the
lines then don't cross, we can solve like we used to.
We only really need to introduce this concept into FindTimestamps.
Everything else works off a valid timestamp pair so it stays the same.
Add a test to reproduce this behavior (it happens occasionally in the
wild) and then fix it.
Change-Id: I999280fc1db1f178835092a8d024a9862144d7cb
Signed-off-by: Austin Schuh <austin.schuh@bluerivertech.com>
diff --git a/aos/events/logging/boot_timestamp.h b/aos/events/logging/boot_timestamp.h
index 7eead2e..d0fde73 100644
--- a/aos/events/logging/boot_timestamp.h
+++ b/aos/events/logging/boot_timestamp.h
@@ -19,6 +19,11 @@
return {boot, duration + d};
}
+ BootDuration operator-() const { return {boot, -duration}; }
+ BootDuration operator-(monotonic_clock::duration d) const {
+ return {boot, duration - d};
+ }
+
bool operator==(const BootDuration &m2) const {
return boot == m2.boot && duration == m2.duration;
}
diff --git a/aos/events/logging/logger_test.cc b/aos/events/logging/logger_test.cc
index ec273a8..bb5b41e 100644
--- a/aos/events/logging/logger_test.cc
+++ b/aos/events/logging/logger_test.cc
@@ -4297,6 +4297,58 @@
ConfirmReadable(filenames);
}
+// Tests that we properly handle what used to be a time violation in one
+// direction. This can occur when one direction goes down after sending some
+// data, but the other keeps working. The down direction ends up resolving to a
+// straight line in the noncausal filter, where the direction which is still up
+// can cross that line. Really, time progressed along just fine but we assumed
+// that the offset was a line when it could have deviated by up to 1ms/second.
+TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
+ std::vector<std::string> filenames;
+
+ CHECK_EQ(pi1_index_, 0u);
+ CHECK_EQ(pi2_index_, 1u);
+
+ time_converter_.AddNextTimestamp(
+ distributed_clock::epoch(),
+ {BootTimestamp::epoch(), BootTimestamp::epoch()});
+
+ const chrono::nanoseconds before_disconnect_duration =
+ time_converter_.AddMonotonic(
+ {chrono::milliseconds(1000), chrono::milliseconds(1000)});
+
+ const chrono::nanoseconds test_duration =
+ time_converter_.AddMonotonic(
+ {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
+ time_converter_.AddMonotonic(
+ {chrono::milliseconds(10000),
+ chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
+ time_converter_.AddMonotonic(
+ {chrono::milliseconds(10000),
+ chrono::milliseconds(10000) + chrono::milliseconds(5)});
+
+ const std::string kLogfile =
+ aos::testing::TestTmpDir() + "/multi_logfile2.1/";
+ util::UnlinkRecursive(kLogfile);
+
+ {
+ LoggerState pi2_logger = MakeLogger(pi2_);
+ pi2_logger.StartLogger(kLogfile);
+ event_loop_factory_.RunFor(before_disconnect_duration);
+
+ pi2_->Disconnect(pi1_->node());
+
+ event_loop_factory_.RunFor(test_duration);
+ pi2_->Connect(pi1_->node());
+
+ event_loop_factory_.RunFor(chrono::milliseconds(5000));
+ pi2_logger.AppendAllFilenames(&filenames);
+ }
+
+ const std::vector<LogFile> sorted_parts = SortParts(filenames);
+ ConfirmReadable(filenames);
+}
+
} // namespace testing
} // namespace logger
} // namespace aos