Remove redundant ignore_missing_messages in Register()
Two pieces of code were doing the same thing (ensuring that we don't
complain about mismatched timestamps/data before startup), and one
was only being used in StartAfterRegister() (and had been added earlier).
Remove the redundant check, and make StartAfterRegister() simpler.
This exposed an error in the multinode_logger_test which was incorrectly
ignoring missing message data that occurred between the starts
of a pi1 and pi2 logger due to not reading a log part.
Take the opportunity to add some docs on what "start time" means in the
logger, since I needed to satisfy myself that we were using the start
time correctly in order to be willing to make this change.
Change-Id: I2c4dc98ff5646ecd1f8e85f8ca01e1ad178d3b61
Signed-off-by: James Kuszmaul <jabukuszmaul+collab@gmail.com>
diff --git a/aos/events/logging/log_reader.cc b/aos/events/logging/log_reader.cc
index a299c61..1e7644f 100644
--- a/aos/events/logging/log_reader.cc
+++ b/aos/events/logging/log_reader.cc
@@ -750,18 +750,10 @@
<< ": Hmm, we have a node starting before the start of time. Offset "
"everything.";
- // While we are starting the system up, we might be relying on matching data
- // to timestamps on log files where the timestamp log file starts before the
- // data. In this case, it is reasonable to expect missing data.
{
- const bool prior_ignore_missing_data = ignore_missing_data_;
- ignore_missing_data_ = true;
VLOG(1) << "Running until " << start_time << " in Register";
event_loop_factory_->RunFor(start_time.time_since_epoch());
VLOG(1) << "At start time";
- // Now that we are running for real, missing data means that the log file is
- // corrupted or went wrong.
- ignore_missing_data_ = prior_ignore_missing_data;
}
for (std::unique_ptr<State> &state : states_) {
diff --git a/aos/events/logging/log_reader.h b/aos/events/logging/log_reader.h
index e536c46..ddf9116 100644
--- a/aos/events/logging/log_reader.h
+++ b/aos/events/logging/log_reader.h
@@ -63,6 +63,24 @@
//
// We also need to be able to generate multiple views of a log file depending on
// the target.
+//
+// In general, we aim to guarantee that if you are using the LogReader
+// "normally" you should be able to observe all the messages that existed on the
+// live system between the start time and the end of the logfile, and that
+// CHECK-failures will be generated if the LogReader cannot satisfy that
+// guarantee. There are currently a few deliberate exceptions to this:
+// * Any channel marked NOT_LOGGED in the configuration is known not to
+// have been logged and thus will be silently absent in log replay.
+// * If an incomplete set of log files is provided to the reader (e.g.,
+// only logs logged on a single node on a multi-node system), then
+// any *individual* channel as observed on a given node will be
+// consistent, but similarly to a NOT_LOGGED channel, some data may
+// not be available.
+// * At the end of a log, data for some channels/nodes may end before
+// others; during this time period, you may observe silently dropped
+// messages. This will be most obvious on uncleanly terminated logs or
+// when merging logfiles across nodes (as the logs on different nodes
+// will not finish at identical times).
// Replays all the channels in the logfile to the event loop.
class LogReader {
@@ -153,6 +171,12 @@
std::vector<const Node *> LoggedNodes() const;
// Returns the starting timestamp for the log file.
+ // All logged channels for the specified node should be entirely available
+ // after the specified time (i.e., any message that was available on the node
+ // in question after the monotonic start time but before the logs end and
+ // whose channel is present in any of the provided logs will either be
+ // available in the log or will result in an internal CHECK-failure of the
+ // LogReader if it would be skipped).
monotonic_clock::time_point monotonic_start_time(
const Node *node = nullptr) const;
realtime_clock::time_point realtime_start_time(
diff --git a/aos/events/logging/logger.fbs b/aos/events/logging/logger.fbs
index 71a7b02..ec1a450 100644
--- a/aos/events/logging/logger.fbs
+++ b/aos/events/logging/logger.fbs
@@ -17,8 +17,15 @@
// Time this log file started on the monotonic clock in nanoseconds.
// If this isn't known (the log file is being recorded from another node
// where we don't know the time offset), both timestamps will be min_time.
+ // This log file may contain data from before the start times (e.g.,
+ // fetched message data), but should guarantee that all data within the
+ // logfile *after* start_time is present until the end of the file (note
+ // that there may be incomplete data at the very end of a log if it is
+ // truncated poorly).
+ // These timestamps are from the perspective of `node`.
monotonic_start_time:int64 = -9223372036854775808 (id: 0);
// Time this log file started on the realtime clock in nanoseconds.
+ // Will only be populated if logger_node == node.
realtime_start_time:int64 = -9223372036854775808 (id: 1);
// Messages are not written in order to disk. They will be out of order by
diff --git a/aos/events/logging/multinode_logger_test.cc b/aos/events/logging/multinode_logger_test.cc
index 9e2d3a3..f9eb11e 100644
--- a/aos/events/logging/multinode_logger_test.cc
+++ b/aos/events/logging/multinode_logger_test.cc
@@ -768,7 +768,7 @@
}
LogReader reader(
- SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
+ SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 3)));
SimulatedEventLoopFactory log_reader_factory(reader.configuration());
log_reader_factory.set_send_delay(chrono::microseconds(0));