commit b000de62806e93f539bf9e30db6a96bb089788a6
author Austin Schuh <austin.linux@gmail.com> Thu Dec 03 22:00:40 2020 -0800
committer Austin Schuh <austin.linux@gmail.com> Sat Dec 05 15:33:25 2020 -0800
tree e23e9af51a87ecb510aa7cbb24a271f0fe037366
parent d2f961007e9dea00dbcb17a878d7c7c728854e69

Handle messages from before the start time

These messages violate the "max_out_of_order" time by definition.  We
log one message per channel, round robin.  So, queue them all up before
continuing.

Change-Id: Ida38292630a6dd1035ff59e931c3053d127aafd9

aos/events/logging/logfile_utils.cc

diff --git a/aos/events/logging/logfile_utils.cc b/aos/events/logging/logfile_utils.cc
index 2886a8e..ec79f17 100644
--- a/aos/events/logging/logfile_utils.cc
+++ b/aos/events/logging/logfile_utils.cc
@@ -446,9 +446,11 @@
       // time.
       // TODO(austin): Does this work with startup when we don't know the remote
       // start time too?  Look at one of those logs to compare.
-      CHECK_GE(monotonic_sent_time,
-               newest_timestamp_ - max_out_of_order_duration())
-          << ": Max out of order exceeded.";
+      if (monotonic_sent_time > parts_.monotonic_start_time) {
+        CHECK_GE(monotonic_sent_time,
+                 newest_timestamp_ - max_out_of_order_duration())
+            << ": Max out of order exceeded. " << parts_;
+      }
       return message;
     }
     NextLog();
@@ -532,7 +534,8 @@
   // sure the nothing path is checked quickly.
   if (sorted_until() != monotonic_clock::max_time) {
     while (true) {
-      if (!messages_.empty() && messages_.begin()->timestamp < sorted_until()) {
+      if (!messages_.empty() && messages_.begin()->timestamp < sorted_until() &&
+          sorted_until() >= monotonic_start_time()) {
         break;
       }
 
@@ -566,9 +569,12 @@
   // Now that we have enough data queued, return a pointer to the oldest piece
   // of data if it exists.
   if (messages_.empty()) {
+    last_message_time_ = monotonic_clock::max_time;
     return nullptr;
   }
 
+  CHECK_GE(messages_.begin()->timestamp, last_message_time_);
+  last_message_time_ = messages_.begin()->timestamp;
   return &(*messages_.begin());
 }
 
@@ -610,7 +616,9 @@
 Message *NodeMerger::Front() {
   // Return the current Front if we have one, otherwise go compute one.
   if (current_ != nullptr) {
-    return current_->Front();
+    Message *result = current_->Front();
+    CHECK_GE(result->timestamp, last_message_time_);
+    return result;
   }
 
   // Otherwise, do a simple search for the oldest message, deduplicating any
@@ -636,6 +644,13 @@
     sorted_until_ = std::min(sorted_until_, parts_sorter.sorted_until());
   }
 
+  if (oldest) {
+    CHECK_GE(oldest->timestamp, last_message_time_);
+    last_message_time_ = oldest->timestamp;
+  } else {
+    last_message_time_ = monotonic_clock::max_time;
+  }
+
   // Return the oldest message found.  This will be nullptr if nothing was
   // found, indicating there is nothing left.
   return oldest;
@@ -934,7 +949,7 @@
       if (channel_data.messages.empty()) {
         continue;
       }
- 
+
       ss << "  channel " << channel_index << " [\n";
       for (const Message &m : channel_data.messages) {
         ss << "    " << m << "\n";