blob: 6ea31936c06256d17cd9896a1520c113a7cc215b [file] [log] [blame]
Austin Schuhb06f03b2021-02-17 22:00:37 -08001#ifndef AOS_EVENTS_LOGGING_LOG_READER_H_
2#define AOS_EVENTS_LOGGING_LOG_READER_H_
Austin Schuhe309d2a2019-11-29 13:25:21 -08003
Austin Schuh8bd96322020-02-13 21:18:22 -08004#include <chrono>
Austin Schuhe309d2a2019-11-29 13:25:21 -08005#include <deque>
Austin Schuh05b70472020-01-01 17:11:17 -08006#include <string_view>
James Kuszmaula16a7912022-06-17 10:58:12 -07007#include <queue>
Austin Schuh2f8fd752020-09-01 22:38:28 -07008#include <tuple>
Austin Schuh6f3babe2020-01-26 20:34:50 -08009#include <vector>
Austin Schuhe309d2a2019-11-29 13:25:21 -080010
Austin Schuhe309d2a2019-11-29 13:25:21 -080011#include "aos/events/event_loop.h"
Austin Schuhf6f9bf32020-10-11 14:37:43 -070012#include "aos/events/logging/logfile_sorting.h"
Austin Schuha36c8902019-12-30 18:07:15 -080013#include "aos/events/logging/logfile_utils.h"
James Kuszmaul38735e82019-12-07 16:42:06 -080014#include "aos/events/logging/logger_generated.h"
James Kuszmaula16a7912022-06-17 10:58:12 -070015#include "aos/events/logging/replay_timing_generated.h"
James Kuszmaul09632422022-05-25 15:56:19 -070016#include "aos/events/shm_event_loop.h"
Austin Schuh92547522019-12-28 14:33:43 -080017#include "aos/events/simulated_event_loop.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070018#include "aos/network/message_bridge_server_generated.h"
Austin Schuh0ca1fd32020-12-18 22:53:05 -080019#include "aos/network/multinode_timestamp_filter.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080020#include "aos/network/remote_message_generated.h"
Austin Schuh8bd96322020-02-13 21:18:22 -080021#include "aos/network/timestamp_filter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080022#include "aos/time/time.h"
Austin Schuh4385b142021-03-14 21:31:13 -070023#include "aos/uuid.h"
James Kuszmaula16a7912022-06-17 10:58:12 -070024#include "aos/util/threaded_queue.h"
25#include "aos/mutex/mutex.h"
26#include "aos/condition.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080027#include "flatbuffers/flatbuffers.h"
28
29namespace aos {
30namespace logger {
31
Austin Schuhe33c08d2022-02-03 18:15:21 -080032class EventNotifier;
33
Austin Schuh6f3babe2020-01-26 20:34:50 -080034// We end up with one of the following 3 log file types.
35//
36// Single node logged as the source node.
37// -> Replayed just on the source node.
38//
39// Forwarding timestamps only logged from the perspective of the destination
40// node.
41// -> Matched with data on source node and logged.
42//
43// Forwarding timestamps with data logged as the destination node.
44// -> Replayed just as the destination
45// -> Replayed as the source (Much harder, ordering is not defined)
46//
47// Duplicate data logged. -> CHECK that it matches and explode otherwise.
48//
49// This can be boiled down to a set of constraints and tools.
50//
51// 1) Forwarding timestamps and data need to be logged separately.
52// 2) Any forwarded data logged on the destination node needs to be logged
53// separately such that it can be sorted.
54//
55// 1) Log reader needs to be able to sort a list of log files.
56// 2) Log reader needs to be able to merge sorted lists of log files.
57// 3) Log reader needs to be able to match timestamps with messages.
58//
59// We also need to be able to generate multiple views of a log file depending on
60// the target.
61
Austin Schuhe309d2a2019-11-29 13:25:21 -080062// Replays all the channels in the logfile to the event loop.
63class LogReader {
64 public:
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -080065 // If you want to supply a new configuration that will be used for replay
66 // (e.g., to change message rates, or to populate an updated schema), then
67 // pass it in here. It must provide all the channels that the original logged
68 // config did.
Austin Schuh6f3babe2020-01-26 20:34:50 -080069 //
Austin Schuh287d43d2020-12-04 20:19:33 -080070 // The single file constructor calls SortParts internally.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -080071 LogReader(std::string_view filename,
72 const Configuration *replay_configuration = nullptr);
Austin Schuh287d43d2020-12-04 20:19:33 -080073 LogReader(std::vector<LogFile> log_files,
Austin Schuh11d43732020-09-21 17:28:30 -070074 const Configuration *replay_configuration = nullptr);
James Kuszmaul7daef362019-12-31 18:28:17 -080075 ~LogReader();
Austin Schuhe309d2a2019-11-29 13:25:21 -080076
Austin Schuh6331ef92020-01-07 18:28:09 -080077 // Registers all the callbacks to send the log file data out on an event loop
78 // created in event_loop_factory. This also updates time to be at the start
79 // of the log file by running until the log file starts.
80 // Note: the configuration used in the factory should be configuration()
81 // below, but can be anything as long as the locations needed to send
82 // everything are available.
James Kuszmaul84ff3e52020-01-03 19:48:53 -080083 void Register(SimulatedEventLoopFactory *event_loop_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -080084
Austin Schuh58646e22021-08-23 23:51:46 -070085 // Registers all the callbacks to send the log file data out to an event loop
86 // factory. This does not start replaying or change the current distributed
87 // time of the factory. It does change the monotonic clocks to be right.
88 void RegisterWithoutStarting(SimulatedEventLoopFactory *event_loop_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -080089 // Runs the log until the last start time. Register above is defined as:
90 // Register(...) {
91 // RegisterWithoutStarting
92 // StartAfterRegister
93 // }
94 // This should generally be considered as a stepping stone to convert from
95 // Register() to RegisterWithoutStarting() incrementally.
96 void StartAfterRegister(SimulatedEventLoopFactory *event_loop_factory);
97
Austin Schuh6331ef92020-01-07 18:28:09 -080098 // Creates an SimulatedEventLoopFactory accessible via event_loop_factory(),
99 // and then calls Register.
100 void Register();
James Kuszmaul09632422022-05-25 15:56:19 -0700101
Austin Schuh6331ef92020-01-07 18:28:09 -0800102 // Registers callbacks for all the events after the log file starts. This is
103 // only useful when replaying live.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 void Register(EventLoop *event_loop);
Austin Schuh6331ef92020-01-07 18:28:09 -0800105
James Kuszmaula16a7912022-06-17 10:58:12 -0700106 // Sets a sender that should be used for tracking timing statistics. If not
107 // set, no statistics will be recorded.
108 void set_timing_accuracy_sender(
109 const Node *node, aos::Sender<timing::ReplayTiming> timing_sender) {
110 states_[configuration::GetNodeIndex(configuration(), node)]
111 ->set_timing_accuracy_sender(std::move(timing_sender));
112 }
113
Austin Schuh58646e22021-08-23 23:51:46 -0700114 // Called whenever a log file starts for a node.
115 void OnStart(std::function<void()> fn);
116 void OnStart(const Node *node, std::function<void()> fn);
117 // Called whenever a log file ends for a node.
118 void OnEnd(std::function<void()> fn);
119 void OnEnd(const Node *node, std::function<void()> fn);
120
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 // Unregisters the senders. You only need to call this if you separately
122 // supplied an event loop or event loop factory and the lifetimes are such
123 // that they need to be explicitly destroyed before the LogReader destructor
124 // gets called.
Austin Schuhe309d2a2019-11-29 13:25:21 -0800125 void Deregister();
126
Austin Schuh0c297012020-09-16 18:41:59 -0700127 // Returns the configuration being used for replay from the log file.
128 // Note that this may be different from the configuration actually used for
129 // handling events. You should generally only use this to create a
130 // SimulatedEventLoopFactory, and then get the configuration from there for
131 // everything else.
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800132 const Configuration *logged_configuration() const;
Austin Schuh11d43732020-09-21 17:28:30 -0700133 // Returns the configuration being used for replay from the log file.
134 // Note that this may be different from the configuration actually used for
135 // handling events. You should generally only use this to create a
136 // SimulatedEventLoopFactory, and then get the configuration from there for
137 // everything else.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800138 // The pointer is invalidated whenever RemapLoggedChannel is called.
Austin Schuh15649d62019-12-28 16:36:38 -0800139 const Configuration *configuration() const;
140
Austin Schuh6f3babe2020-01-26 20:34:50 -0800141 // Returns the nodes that this log file was created on. This is a list of
Austin Schuh07676622021-01-21 18:59:17 -0800142 // pointers to a node in the nodes() list inside logged_configuration().
143 std::vector<const Node *> LoggedNodes() const;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800144
145 // Returns the starting timestamp for the log file.
Austin Schuh11d43732020-09-21 17:28:30 -0700146 monotonic_clock::time_point monotonic_start_time(
147 const Node *node = nullptr) const;
148 realtime_clock::time_point realtime_start_time(
149 const Node *node = nullptr) const;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800150
Austin Schuhe33c08d2022-02-03 18:15:21 -0800151 // Sets the start and end times to replay data until for all nodes. This
152 // overrides the --start_time and --end_time flags. The default is to replay
153 // all data.
154 void SetStartTime(std::string start_time);
155 void SetStartTime(realtime_clock::time_point start_time);
156 void SetEndTime(std::string end_time);
157 void SetEndTime(realtime_clock::time_point end_time);
158
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800159 // Causes the logger to publish the provided channel on a different name so
160 // that replayed applications can publish on the proper channel name without
161 // interference. This operates on raw channel names, without any node or
162 // application specific mappings.
163 void RemapLoggedChannel(std::string_view name, std::string_view type,
Austin Schuh0de30f32020-12-06 12:44:28 -0800164 std::string_view add_prefix = "/original",
165 std::string_view new_type = "");
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800166 template <typename T>
167 void RemapLoggedChannel(std::string_view name,
Austin Schuh0de30f32020-12-06 12:44:28 -0800168 std::string_view add_prefix = "/original",
169 std::string_view new_type = "") {
170 RemapLoggedChannel(name, T::GetFullyQualifiedName(), add_prefix, new_type);
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800171 }
172
Austin Schuh01b4c352020-09-21 23:09:39 -0700173 // Remaps the provided channel, though this respects node mappings, and
174 // preserves them too. This makes it so if /aos -> /pi1/aos on one node,
175 // /original/aos -> /original/pi1/aos on the same node after renaming, just
Austin Schuh0de30f32020-12-06 12:44:28 -0800176 // like you would hope. If new_type is not empty, the new channel will use
177 // the provided type instead. This allows for renaming messages.
Austin Schuh01b4c352020-09-21 23:09:39 -0700178 //
179 // TODO(austin): If you have 2 nodes remapping something to the same channel,
180 // this doesn't handle that. No use cases exist yet for that, so it isn't
181 // being done yet.
182 void RemapLoggedChannel(std::string_view name, std::string_view type,
183 const Node *node,
Austin Schuh0de30f32020-12-06 12:44:28 -0800184 std::string_view add_prefix = "/original",
185 std::string_view new_type = "");
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700186 template <typename T>
Austin Schuh01b4c352020-09-21 23:09:39 -0700187 void RemapLoggedChannel(std::string_view name, const Node *node,
Austin Schuh0de30f32020-12-06 12:44:28 -0800188 std::string_view add_prefix = "/original",
189 std::string_view new_type = "") {
190 RemapLoggedChannel(name, T::GetFullyQualifiedName(), node, add_prefix,
191 new_type);
Austin Schuh01b4c352020-09-21 23:09:39 -0700192 }
193
194 template <typename T>
195 bool HasChannel(std::string_view name, const Node *node = nullptr) {
Austin Schuh0ca51f32020-12-25 21:51:45 -0800196 return configuration::GetChannel(logged_configuration(), name,
Austin Schuh0de30f32020-12-06 12:44:28 -0800197 T::GetFullyQualifiedName(), "", node,
198 true) != nullptr;
Brian Silvermande9f3ff2020-04-28 16:56:58 -0700199 }
200
Austin Schuh82529062021-12-08 12:09:52 -0800201 template <typename T>
202 void MaybeRemapLoggedChannel(std::string_view name,
203 const Node *node = nullptr) {
204 if (HasChannel<T>(name, node)) {
205 RemapLoggedChannel<T>(name, node);
206 }
207 }
208
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800209 // Returns true if the channel exists on the node and was logged.
210 template <typename T>
211 bool HasLoggedChannel(std::string_view name, const Node *node = nullptr) {
Austin Schuh5ee56872021-01-30 16:53:34 -0800212 const Channel *channel =
213 configuration::GetChannel(logged_configuration(), name,
214 T::GetFullyQualifiedName(), "", node, true);
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800215 if (channel == nullptr) return false;
216 return channel->logger() != LoggerConfig::NOT_LOGGED;
217 }
218
Austin Schuh1c227352021-09-17 12:53:54 -0700219 // Returns a list of all the original channels from remapping.
220 std::vector<const Channel *> RemappedChannels() const;
221
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800222 SimulatedEventLoopFactory *event_loop_factory() {
223 return event_loop_factory_;
224 }
225
Austin Schuh0ca51f32020-12-25 21:51:45 -0800226 std::string_view name() const { return log_files_[0].name; }
Austin Schuh0c297012020-09-16 18:41:59 -0700227
James Kuszmaul71a81932020-12-15 21:08:01 -0800228 // Set whether to exit the SimulatedEventLoopFactory when we finish reading
229 // the logfile.
230 void set_exit_on_finish(bool exit_on_finish) {
231 exit_on_finish_ = exit_on_finish;
232 }
233
Austin Schuhe309d2a2019-11-29 13:25:21 -0800234 private:
Austin Schuh58646e22021-08-23 23:51:46 -0700235 void Register(EventLoop *event_loop, const Node *node);
236
237 void RegisterDuringStartup(EventLoop *event_loop, const Node *node);
238
239 const Channel *RemapChannel(const EventLoop *event_loop, const Node *node,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800240 const Channel *channel);
241
Austin Schuhe309d2a2019-11-29 13:25:21 -0800242 // Queues at least max_out_of_order_duration_ messages into channels_.
243 void QueueMessages();
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800244 // Handle constructing a configuration with all the additional remapped
245 // channels from calls to RemapLoggedChannel.
246 void MakeRemappedConfig();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800247
Austin Schuh2f8fd752020-09-01 22:38:28 -0700248 // Returns the number of nodes.
249 size_t nodes_count() const {
250 return !configuration::MultiNode(logged_configuration())
251 ? 1u
252 : logged_configuration()->nodes()->size();
253 }
254
Austin Schuh287d43d2020-12-04 20:19:33 -0800255 const std::vector<LogFile> log_files_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800256
Austin Schuh969cd602021-01-03 00:09:45 -0800257 // Class to manage sending RemoteMessages on the provided node after the
258 // correct delay.
Austin Schuh5ee56872021-01-30 16:53:34 -0800259 class RemoteMessageSender {
Austin Schuh969cd602021-01-03 00:09:45 -0800260 public:
261 RemoteMessageSender(aos::Sender<message_bridge::RemoteMessage> sender,
262 EventLoop *event_loop);
263 RemoteMessageSender(RemoteMessageSender const &) = delete;
264 RemoteMessageSender &operator=(RemoteMessageSender const &) = delete;
265
266 // Sends the provided message. If monotonic_timestamp_time is min_time,
267 // send it immediately.
268 void Send(
269 FlatbufferDetachedBuffer<message_bridge::RemoteMessage> remote_message,
Austin Schuh58646e22021-08-23 23:51:46 -0700270 BootTimestamp monotonic_timestamp_time, size_t source_boot_count);
Austin Schuh969cd602021-01-03 00:09:45 -0800271
272 private:
273 // Handles actually sending the timestamp if we were delayed.
274 void SendTimestamp();
275 // Handles scheduling the timer to send at the correct time.
276 void ScheduleTimestamp();
277
278 EventLoop *event_loop_;
279 aos::Sender<message_bridge::RemoteMessage> sender_;
280 aos::TimerHandler *timer_;
281
282 // Time we are scheduled for, or min_time if we aren't scheduled.
283 monotonic_clock::time_point scheduled_time_ = monotonic_clock::min_time;
284
285 struct Timestamp {
286 Timestamp(FlatbufferDetachedBuffer<message_bridge::RemoteMessage>
287 new_remote_message,
288 monotonic_clock::time_point new_monotonic_timestamp_time)
289 : remote_message(std::move(new_remote_message)),
290 monotonic_timestamp_time(new_monotonic_timestamp_time) {}
291 FlatbufferDetachedBuffer<message_bridge::RemoteMessage> remote_message;
292 monotonic_clock::time_point monotonic_timestamp_time;
293 };
294
295 // List of messages to send. The timer works through them and then disables
296 // itself automatically.
297 std::deque<Timestamp> remote_timestamps_;
298 };
299
Austin Schuh6f3babe2020-01-26 20:34:50 -0800300 // State per node.
Austin Schuh858c9f32020-08-31 16:56:12 -0700301 class State {
302 public:
James Kuszmaula16a7912022-06-17 10:58:12 -0700303 // Whether we should spin up a separate thread for buffering up messages.
304 // Only allowed in realtime replay--see comments on threading_ member for
305 // details.
306 enum class ThreadedBuffering { kYes, kNo };
James Kuszmaul09632422022-05-25 15:56:19 -0700307 State(std::unique_ptr<TimestampMapper> timestamp_mapper,
308 message_bridge::MultiNodeNoncausalOffsetEstimator *multinode_filters,
James Kuszmaula16a7912022-06-17 10:58:12 -0700309 const Node *node, ThreadedBuffering threading);
Austin Schuh287d43d2020-12-04 20:19:33 -0800310
311 // Connects up the timestamp mappers.
312 void AddPeer(State *peer);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800313
Austin Schuhe639ea12021-01-25 13:00:22 -0800314 TimestampMapper *timestamp_mapper() { return timestamp_mapper_.get(); }
315
Austin Schuhdda74ec2021-01-03 19:30:37 -0800316 // Returns the next sorted message with all the timestamps extracted and
317 // matched.
318 TimestampedMessage PopOldest();
Austin Schuh188eabe2020-12-29 23:41:13 -0800319
Austin Schuh858c9f32020-08-31 16:56:12 -0700320 // Returns the monotonic time of the oldest message.
James Kuszmaula16a7912022-06-17 10:58:12 -0700321 BootTimestamp SingleThreadedOldestMessageTime();
322 // Returns the monotonic time of the oldest message, handling querying the
323 // separate thread of ThreadedBuffering was set.
324 BootTimestamp MultiThreadedOldestMessageTime();
Austin Schuh58646e22021-08-23 23:51:46 -0700325
326 size_t boot_count() const {
327 // If we are replaying directly into an event loop, we can't reboot. So
328 // we will stay stuck on the 0th boot.
James Kuszmaul09632422022-05-25 15:56:19 -0700329 if (!node_event_loop_factory_) {
330 if (event_loop_ == nullptr) {
331 // If boot_count is being checked after startup for any of the
332 // non-primary nodes, then returning 0 may not be accurate (since
333 // remote nodes *can* reboot even if the EventLoop being played to
334 // can't).
335 CHECK(!started_);
336 CHECK(!stopped_);
337 }
338 return 0u;
339 }
Austin Schuh58646e22021-08-23 23:51:46 -0700340 return node_event_loop_factory_->boot_count();
341 }
Austin Schuh858c9f32020-08-31 16:56:12 -0700342
343 // Primes the queues inside State. Should be called before calling
344 // OldestMessageTime.
345 void SeedSortedMessages();
Austin Schuh8bd96322020-02-13 21:18:22 -0800346
Austin Schuh58646e22021-08-23 23:51:46 -0700347 void SetupStartupTimer() {
348 const monotonic_clock::time_point start_time =
349 monotonic_start_time(boot_count());
350 if (start_time == monotonic_clock::min_time) {
351 LOG(ERROR)
352 << "No start time, skipping, please figure out when this happens";
Austin Schuhe33c08d2022-02-03 18:15:21 -0800353 NotifyLogfileStart();
Austin Schuh58646e22021-08-23 23:51:46 -0700354 return;
355 }
James Kuszmaul09632422022-05-25 15:56:19 -0700356 if (node_event_loop_factory_) {
357 CHECK_GE(start_time + clock_offset(), event_loop_->monotonic_now());
358 }
359 startup_timer_->Setup(start_time + clock_offset());
Austin Schuh58646e22021-08-23 23:51:46 -0700360 }
361
362 void set_startup_timer(TimerHandler *timer_handler) {
363 startup_timer_ = timer_handler;
364 if (startup_timer_) {
365 if (event_loop_->node() != nullptr) {
366 startup_timer_->set_name(absl::StrCat(
367 event_loop_->node()->name()->string_view(), "_startup"));
368 } else {
369 startup_timer_->set_name("startup");
370 }
371 }
372 }
373
Austin Schuh858c9f32020-08-31 16:56:12 -0700374 // Returns the starting time for this node.
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700375 monotonic_clock::time_point monotonic_start_time(size_t boot_count) const {
376 return timestamp_mapper_
377 ? timestamp_mapper_->monotonic_start_time(boot_count)
378 : monotonic_clock::min_time;
Austin Schuh858c9f32020-08-31 16:56:12 -0700379 }
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700380 realtime_clock::time_point realtime_start_time(size_t boot_count) const {
381 return timestamp_mapper_
382 ? timestamp_mapper_->realtime_start_time(boot_count)
383 : realtime_clock::min_time;
Austin Schuh858c9f32020-08-31 16:56:12 -0700384 }
385
386 // Sets the node event loop factory for replaying into a
387 // SimulatedEventLoopFactory. Returns the EventLoop to use.
Austin Schuh60e77942022-05-16 17:48:24 -0700388 void SetNodeEventLoopFactory(NodeEventLoopFactory *node_event_loop_factory,
389 SimulatedEventLoopFactory *event_loop_factory);
Austin Schuh858c9f32020-08-31 16:56:12 -0700390
391 // Sets and gets the event loop to use.
392 void set_event_loop(EventLoop *event_loop) { event_loop_ = event_loop; }
393 EventLoop *event_loop() { return event_loop_; }
394
Austin Schuh58646e22021-08-23 23:51:46 -0700395 const Node *node() const { return node_; }
396
397 void Register(EventLoop *event_loop);
398
399 void OnStart(std::function<void()> fn);
400 void OnEnd(std::function<void()> fn);
401
Austin Schuh858c9f32020-08-31 16:56:12 -0700402 // Sets the current realtime offset from the monotonic clock for this node
403 // (if we are on a simulated event loop).
404 void SetRealtimeOffset(monotonic_clock::time_point monotonic_time,
405 realtime_clock::time_point realtime_time) {
406 if (node_event_loop_factory_ != nullptr) {
407 node_event_loop_factory_->SetRealtimeOffset(monotonic_time,
408 realtime_time);
409 }
410 }
411
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700412 // Returns the MessageHeader sender to log delivery timestamps to for the
413 // provided remote node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800414 RemoteMessageSender *RemoteTimestampSender(const Channel *channel,
415 const Connection *connection);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700416
Austin Schuh858c9f32020-08-31 16:56:12 -0700417 // Converts a timestamp from the monotonic clock on this node to the
418 // distributed clock.
419 distributed_clock::time_point ToDistributedClock(
420 monotonic_clock::time_point time) {
James Kuszmaul09632422022-05-25 15:56:19 -0700421 CHECK(node_event_loop_factory_);
Austin Schuh858c9f32020-08-31 16:56:12 -0700422 return node_event_loop_factory_->ToDistributedClock(time);
423 }
424
Austin Schuh858c9f32020-08-31 16:56:12 -0700425 // Returns the current time on the remote node which sends messages on
426 // channel_index.
Austin Schuh58646e22021-08-23 23:51:46 -0700427 BootTimestamp monotonic_remote_now(size_t channel_index) {
428 State *s = channel_source_state_[channel_index];
429 return BootTimestamp{
430 .boot = s->boot_count(),
431 .time = s->node_event_loop_factory_->monotonic_now()};
Austin Schuh858c9f32020-08-31 16:56:12 -0700432 }
433
Austin Schuh5ee56872021-01-30 16:53:34 -0800434 // Returns the start time of the remote for the provided channel.
435 monotonic_clock::time_point monotonic_remote_start_time(
Austin Schuh58646e22021-08-23 23:51:46 -0700436 size_t boot_count, size_t channel_index) {
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700437 return channel_source_state_[channel_index]->monotonic_start_time(
438 boot_count);
Austin Schuh5ee56872021-01-30 16:53:34 -0800439 }
440
Austin Schuh58646e22021-08-23 23:51:46 -0700441 void DestroyEventLoop() { event_loop_unique_ptr_.reset(); }
442
443 EventLoop *MakeEventLoop() {
444 CHECK(!event_loop_unique_ptr_);
James Kuszmaul890c2492022-04-06 14:59:31 -0700445 // TODO(james): Enable exclusive senders on LogReader to allow us to
446 // ensure we are remapping channels correctly.
447 event_loop_unique_ptr_ = node_event_loop_factory_->MakeEventLoop(
448 "log_reader", {NodeEventLoopFactory::CheckSentTooFast::kNo,
449 NodeEventLoopFactory::ExclusiveSenders::kNo});
Austin Schuh58646e22021-08-23 23:51:46 -0700450 return event_loop_unique_ptr_.get();
451 }
452
Austin Schuh2f8fd752020-09-01 22:38:28 -0700453 distributed_clock::time_point RemoteToDistributedClock(
454 size_t channel_index, monotonic_clock::time_point time) {
James Kuszmaul09632422022-05-25 15:56:19 -0700455 CHECK(node_event_loop_factory_);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700456 return channel_source_state_[channel_index]
457 ->node_event_loop_factory_->ToDistributedClock(time);
Austin Schuh2f8fd752020-09-01 22:38:28 -0700458 }
459
460 const Node *remote_node(size_t channel_index) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700461 return channel_source_state_[channel_index]
462 ->node_event_loop_factory_->node();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700463 }
464
Stephan Pleines559fa6c2022-01-06 17:23:51 -0800465 monotonic_clock::time_point monotonic_now() const {
James Kuszmaul09632422022-05-25 15:56:19 -0700466 return event_loop_->monotonic_now();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700467 }
468
Austin Schuh858c9f32020-08-31 16:56:12 -0700469 // Sets the number of channels.
470 void SetChannelCount(size_t count);
471
472 // Sets the sender, filter, and target factory for a channel.
Austin Schuh969cd602021-01-03 00:09:45 -0800473 void SetChannel(size_t logged_channel_index, size_t factory_channel_index,
474 std::unique_ptr<RawSender> sender,
475 message_bridge::NoncausalOffsetEstimator *filter,
Austin Schuh58646e22021-08-23 23:51:46 -0700476 bool is_forwarded, State *source_state);
477
478 void SetRemoteTimestampSender(size_t logged_channel_index,
479 RemoteMessageSender *remote_timestamp_sender);
480
481 void RunOnStart();
482 void RunOnEnd();
Austin Schuh858c9f32020-08-31 16:56:12 -0700483
Austin Schuhe33c08d2022-02-03 18:15:21 -0800484 // Handles a logfile start event to potentially call the OnStart callbacks.
485 void NotifyLogfileStart();
486 // Handles a start time flag start event to potentially call the OnStart
487 // callbacks.
488 void NotifyFlagStart();
489
490 // Handles a logfile end event to potentially call the OnEnd callbacks.
491 void NotifyLogfileEnd();
492 // Handles a end time flag start event to potentially call the OnEnd
493 // callbacks.
494 void NotifyFlagEnd();
495
Austin Schuh858c9f32020-08-31 16:56:12 -0700496 // Unregisters everything so we can destory the event loop.
Austin Schuh58646e22021-08-23 23:51:46 -0700497 // TODO(austin): Is this needed? OnShutdown should be able to serve this
498 // need.
Austin Schuh858c9f32020-08-31 16:56:12 -0700499 void Deregister();
500
501 // Sets the current TimerHandle for the replay callback.
502 void set_timer_handler(TimerHandler *timer_handler) {
503 timer_handler_ = timer_handler;
Austin Schuh58646e22021-08-23 23:51:46 -0700504 if (timer_handler_) {
505 if (event_loop_->node() != nullptr) {
506 timer_handler_->set_name(absl::StrCat(
507 event_loop_->node()->name()->string_view(), "_main"));
508 } else {
509 timer_handler_->set_name("main");
510 }
511 }
Austin Schuh858c9f32020-08-31 16:56:12 -0700512 }
513
Austin Schuhe33c08d2022-02-03 18:15:21 -0800514 // Creates and registers the --start_time and --end_time event callbacks.
515 void SetStartTimeFlag(realtime_clock::time_point start_time);
516 void SetEndTimeFlag(realtime_clock::time_point end_time);
517
518 // Notices the next message to update the start/end time callbacks.
519 void ObserveNextMessage(monotonic_clock::time_point monotonic_event,
520 realtime_clock::time_point realtime_event);
521
522 // Clears the start and end time flag handlers so we can delete the event
523 // loop.
524 void ClearTimeFlags();
525
Austin Schuh858c9f32020-08-31 16:56:12 -0700526 // Sets the next wakeup time on the replay callback.
527 void Setup(monotonic_clock::time_point next_time) {
James Kuszmaul8866e642022-06-10 16:00:36 -0700528 timer_handler_->Setup(
529 std::max(monotonic_now(), next_time + clock_offset()));
Austin Schuh858c9f32020-08-31 16:56:12 -0700530 }
531
532 // Sends a buffer on the provided channel index.
Austin Schuh287d43d2020-12-04 20:19:33 -0800533 bool Send(const TimestampedMessage &timestamped_message);
Austin Schuh858c9f32020-08-31 16:56:12 -0700534
James Kuszmaul09632422022-05-25 15:56:19 -0700535 void SetClockOffset();
536 std::chrono::nanoseconds clock_offset() const { return clock_offset_; }
537
Austin Schuh858c9f32020-08-31 16:56:12 -0700538 // Returns a debug string for the channel merger.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700539 std::string DebugString() const {
Austin Schuh287d43d2020-12-04 20:19:33 -0800540 if (!timestamp_mapper_) {
Austin Schuhe639ea12021-01-25 13:00:22 -0800541 return "";
Austin Schuh287d43d2020-12-04 20:19:33 -0800542 }
Austin Schuhe639ea12021-01-25 13:00:22 -0800543 return timestamp_mapper_->DebugString();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700544 }
Austin Schuh858c9f32020-08-31 16:56:12 -0700545
Austin Schuh58646e22021-08-23 23:51:46 -0700546 void ClearRemoteTimestampSenders() {
547 channel_timestamp_loggers_.clear();
548 timestamp_loggers_.clear();
549 }
550
Austin Schuhbd5f74a2021-11-11 20:55:38 -0800551 void SetFoundLastMessage(bool val) {
552 found_last_message_ = val;
553 last_message_.resize(factory_channel_index_.size(), false);
554 }
555 bool found_last_message() const { return found_last_message_; }
556
557 void set_last_message(size_t channel_index) {
558 CHECK_LT(channel_index, last_message_.size());
559 last_message_[channel_index] = true;
560 }
561
562 bool last_message(size_t channel_index) {
563 CHECK_LT(channel_index, last_message_.size());
564 return last_message_[channel_index];
565 }
566
James Kuszmaula16a7912022-06-17 10:58:12 -0700567 void set_timing_accuracy_sender(
568 aos::Sender<timing::ReplayTiming> timing_sender) {
569 timing_statistics_sender_ = std::move(timing_sender);
570 OnEnd([this]() { SendMessageTimings(); });
571 }
572
573 // If running with ThreadedBuffering::kYes, will start the processing thread
574 // and queue up messages until the specified time. No-op of
575 // ThreadedBuffering::kNo is set. Should only be called once.
576 void QueueThreadUntil(BootTimestamp time);
577
Austin Schuh858c9f32020-08-31 16:56:12 -0700578 private:
James Kuszmaula16a7912022-06-17 10:58:12 -0700579 void TrackMessageSendTiming(
580 const RawSender &sender,
581 monotonic_clock::time_point expected_send_time);
582 void SendMessageTimings();
Austin Schuh858c9f32020-08-31 16:56:12 -0700583 // Log file.
Austin Schuh287d43d2020-12-04 20:19:33 -0800584 std::unique_ptr<TimestampMapper> timestamp_mapper_;
Austin Schuh858c9f32020-08-31 16:56:12 -0700585
Austin Schuh858c9f32020-08-31 16:56:12 -0700586 // Senders.
587 std::vector<std::unique_ptr<RawSender>> channels_;
Austin Schuh969cd602021-01-03 00:09:45 -0800588 std::vector<RemoteMessageSender *> remote_timestamp_senders_;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700589 // The mapping from logged channel index to sent channel index. Needed for
590 // sending out MessageHeaders.
591 std::vector<int> factory_channel_index_;
592
Austin Schuh9942bae2021-01-07 22:06:44 -0800593 struct ContiguousSentTimestamp {
594 // Most timestamps make it through the network, so it saves a ton of
595 // memory and CPU to store the start and end, and search for valid ranges.
596 // For one of the logs I looked at, we had 2 ranges for 4 days.
597 //
598 // Save monotonic times as well to help if a queue index ever wraps. Odds
599 // are very low, but doesn't hurt.
600 //
601 // The starting time and matching queue index.
602 monotonic_clock::time_point starting_monotonic_event_time =
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700603 monotonic_clock::min_time;
Austin Schuh9942bae2021-01-07 22:06:44 -0800604 uint32_t starting_queue_index = 0xffffffff;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700605
Austin Schuh9942bae2021-01-07 22:06:44 -0800606 // Ending time and queue index.
607 monotonic_clock::time_point ending_monotonic_event_time =
608 monotonic_clock::max_time;
609 uint32_t ending_queue_index = 0xffffffff;
610
611 // The queue index that the first message was *actually* sent with. The
612 // queue indices are assumed to be contiguous through this range.
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700613 uint32_t actual_queue_index = 0xffffffff;
614 };
615
616 // Stores all the timestamps that have been sent on this channel. This is
617 // only done for channels which are forwarded and on the node which
Austin Schuh9942bae2021-01-07 22:06:44 -0800618 // initially sends the message. Compress using ranges and offsets.
619 std::vector<std::unique_ptr<std::vector<ContiguousSentTimestamp>>>
620 queue_index_map_;
Austin Schuh858c9f32020-08-31 16:56:12 -0700621
622 // Factory (if we are in sim) that this loop was created on.
623 NodeEventLoopFactory *node_event_loop_factory_ = nullptr;
Austin Schuhe33c08d2022-02-03 18:15:21 -0800624 SimulatedEventLoopFactory *event_loop_factory_ = nullptr;
625
Austin Schuh858c9f32020-08-31 16:56:12 -0700626 std::unique_ptr<EventLoop> event_loop_unique_ptr_;
627 // Event loop.
Austin Schuh58646e22021-08-23 23:51:46 -0700628 const Node *node_ = nullptr;
Austin Schuh858c9f32020-08-31 16:56:12 -0700629 EventLoop *event_loop_ = nullptr;
630 // And timer used to send messages.
Austin Schuh58646e22021-08-23 23:51:46 -0700631 TimerHandler *timer_handler_ = nullptr;
632 TimerHandler *startup_timer_ = nullptr;
Austin Schuh858c9f32020-08-31 16:56:12 -0700633
Austin Schuhe33c08d2022-02-03 18:15:21 -0800634 std::unique_ptr<EventNotifier> start_event_notifier_;
635 std::unique_ptr<EventNotifier> end_event_notifier_;
636
Austin Schuh8bd96322020-02-13 21:18:22 -0800637 // Filters (or nullptr if it isn't a forwarded channel) for each channel.
638 // This corresponds to the object which is shared among all the channels
639 // going between 2 nodes. The second element in the tuple indicates if this
640 // is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700641 std::vector<message_bridge::NoncausalOffsetEstimator *> filters_;
James Kuszmaul09632422022-05-25 15:56:19 -0700642 message_bridge::MultiNodeNoncausalOffsetEstimator *multinode_filters_;
Austin Schuh8bd96322020-02-13 21:18:22 -0800643
644 // List of NodeEventLoopFactorys (or nullptr if it isn't a forwarded
645 // channel) which correspond to the originating node.
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700646 std::vector<State *> channel_source_state_;
647
Austin Schuh61e973f2021-02-21 21:43:56 -0800648 // This is a cache for channel, connection mapping to the corresponding
649 // sender.
650 absl::btree_map<std::pair<const Channel *, const Connection *>,
651 std::shared_ptr<RemoteMessageSender>>
652 channel_timestamp_loggers_;
653
654 // Mapping from resolved RemoteMessage channel to RemoteMessage sender. This
655 // is the channel that timestamps are published to.
656 absl::btree_map<const Channel *, std::shared_ptr<RemoteMessageSender>>
657 timestamp_loggers_;
Austin Schuh58646e22021-08-23 23:51:46 -0700658
James Kuszmaul09632422022-05-25 15:56:19 -0700659 // Time offset between the log's monotonic clock and the current event
660 // loop's monotonic clock. Useful when replaying logs with non-simulated
661 // event loops.
662 std::chrono::nanoseconds clock_offset_{0};
663
Austin Schuh58646e22021-08-23 23:51:46 -0700664 std::vector<std::function<void()>> on_starts_;
665 std::vector<std::function<void()>> on_ends_;
666
James Kuszmaula16a7912022-06-17 10:58:12 -0700667 std::atomic<bool> stopped_ = false;
668 std::atomic<bool> started_ = false;
Austin Schuhbd5f74a2021-11-11 20:55:38 -0800669
670 bool found_last_message_ = false;
671 std::vector<bool> last_message_;
James Kuszmaula16a7912022-06-17 10:58:12 -0700672
673 std::vector<timing::MessageTimingT> send_timings_;
674 aos::Sender<timing::ReplayTiming> timing_statistics_sender_;
675
676 // Protects access to any internal state after Run() is called. Designed
677 // assuming that only one node is actually executing in replay.
678 // Threading design:
679 // * The worker passed to message_queuer_ has full ownership over all
680 // the log-reading code, timestamp filters, last_queued_message_, etc.
681 // * The main thread should only have exclusive access to the replay
682 // event loop and associated features (mainly senders).
683 // It will pop an item out of the queue (which does maintain a shared_ptr
684 // reference which may also be being used by the message_queuer_ thread,
685 // but having shared_ptr's accessing the same memory from
686 // separate threads is permissible).
687 // Enabling this in simulation is currently infeasible due to a lack of
688 // synchronization in the MultiNodeNoncausalOffsetEstimator. Essentially,
689 // when the message_queuer_ thread attempts to read/pop messages from the
690 // timestamp_mapper_, it will end up calling callbacks that update the
691 // internal state of the MultiNodeNoncausalOffsetEstimator. Simultaneously,
692 // the event scheduler that is running in the main thread to orchestrate the
693 // simulation will be querying the estimator to know what the clocks on the
694 // various nodes are at, leading to potential issues.
695 ThreadedBuffering threading_;
696 std::optional<BootTimestamp> last_queued_message_;
697 std::optional<util::ThreadedQueue<TimestampedMessage, BootTimestamp>>
698 message_queuer_;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800699 };
700
Austin Schuh8bd96322020-02-13 21:18:22 -0800701 // Node index -> State.
702 std::vector<std::unique_ptr<State>> states_;
703
704 // Creates the requested filter if it doesn't exist, regardless of whether
705 // these nodes can actually communicate directly. The second return value
706 // reports if this is the primary direction or not.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700707 message_bridge::NoncausalOffsetEstimator *GetFilter(const Node *node_a,
708 const Node *node_b);
Austin Schuh8bd96322020-02-13 21:18:22 -0800709
Austin Schuh8bd96322020-02-13 21:18:22 -0800710 // List of filters for a connection. The pointer to the first node will be
711 // less than the second node.
Austin Schuh0ca1fd32020-12-18 22:53:05 -0800712 std::unique_ptr<message_bridge::MultiNodeNoncausalOffsetEstimator> filters_;
Austin Schuh8bd96322020-02-13 21:18:22 -0800713
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800714 std::unique_ptr<FlatbufferDetachedBuffer<Configuration>>
715 remapped_configuration_buffer_;
716
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800717 std::unique_ptr<SimulatedEventLoopFactory> event_loop_factory_unique_ptr_;
718 SimulatedEventLoopFactory *event_loop_factory_ = nullptr;
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800719
720 // Map of channel indices to new name. The channel index will be an index into
721 // logged_configuration(), and the string key will be the name of the channel
722 // to send on instead of the logged channel name.
Austin Schuh0de30f32020-12-06 12:44:28 -0800723 struct RemappedChannel {
724 std::string remapped_name;
725 std::string new_type;
726 };
727 std::map<size_t, RemappedChannel> remapped_channels_;
Austin Schuh01b4c352020-09-21 23:09:39 -0700728 std::vector<MapT> maps_;
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800729
Austin Schuh6f3babe2020-01-26 20:34:50 -0800730 // Number of nodes which still have data to send. This is used to figure out
731 // when to exit.
732 size_t live_nodes_ = 0;
733
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800734 const Configuration *remapped_configuration_ = nullptr;
735 const Configuration *replay_configuration_ = nullptr;
Austin Schuhcde938c2020-02-02 17:30:07 -0800736
737 // If true, the replay timer will ignore any missing data. This is used
738 // during startup when we are bootstrapping everything and trying to get to
739 // the start of all the log files.
740 bool ignore_missing_data_ = false;
James Kuszmaul71a81932020-12-15 21:08:01 -0800741
742 // Whether to exit the SimulatedEventLoop when we finish reading the logs.
743 bool exit_on_finish_ = true;
Austin Schuhe33c08d2022-02-03 18:15:21 -0800744
745 realtime_clock::time_point start_time_ = realtime_clock::min_time;
746 realtime_clock::time_point end_time_ = realtime_clock::max_time;
Austin Schuhe309d2a2019-11-29 13:25:21 -0800747};
748
749} // namespace logger
750} // namespace aos
751
Austin Schuhb06f03b2021-02-17 22:00:37 -0800752#endif // AOS_EVENTS_LOGGING_LOG_READER_H_