blob: 2cf8ffebd4294663dad71c6c39507681cd40d356 [file] [log] [blame]
Brian Smartte67d7112023-03-20 12:06:30 -07001#include <algorithm>
2
Philipp Schrader790cb542023-07-05 21:06:52 -07003#include "gmock/gmock.h"
4#include "gtest/gtest.h"
5
Naman Guptaa63aa132023-03-22 20:06:34 -07006#include "aos/events/logging/log_reader.h"
7#include "aos/events/logging/multinode_logger_test_lib.h"
8#include "aos/events/message_counter.h"
9#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/network/remote_message_generated.h"
12#include "aos/network/timestamp_generated.h"
13#include "aos/testing/tmpdir.h"
Naman Guptaa63aa132023-03-22 20:06:34 -070014
Stephan Pleinesf63bde82024-01-13 15:59:33 -080015namespace aos::logger::testing {
Naman Guptaa63aa132023-03-22 20:06:34 -070016
17namespace chrono = std::chrono;
18using aos::message_bridge::RemoteMessage;
19using aos::testing::ArtifactPath;
20using aos::testing::MessageCounter;
21
Naman Guptaa63aa132023-03-22 20:06:34 -070022INSTANTIATE_TEST_SUITE_P(
23 All, MultinodeLoggerTest,
24 ::testing::Combine(
25 ::testing::Values(
26 ConfigParams{"multinode_pingpong_combined_config.json", true,
Austin Schuh6ecfe902023-08-04 22:44:37 -070027 kCombinedConfigSha1(), kCombinedConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070028 FileStrategy::kKeepSeparate,
29 ForceTimestampBuffering::kForceBufferTimestamps},
30 ConfigParams{"multinode_pingpong_combined_config.json", true,
31 kCombinedConfigSha1(), kCombinedConfigSha1(),
32 FileStrategy::kKeepSeparate,
33 ForceTimestampBuffering::kAutoBuffer},
Naman Guptaa63aa132023-03-22 20:06:34 -070034 ConfigParams{"multinode_pingpong_split_config.json", false,
Austin Schuh6ecfe902023-08-04 22:44:37 -070035 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070036 FileStrategy::kKeepSeparate,
37 ForceTimestampBuffering::kForceBufferTimestamps},
Austin Schuh6ecfe902023-08-04 22:44:37 -070038 ConfigParams{"multinode_pingpong_split_config.json", false,
39 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070040 FileStrategy::kKeepSeparate,
41 ForceTimestampBuffering::kAutoBuffer},
42 ConfigParams{"multinode_pingpong_split_config.json", false,
43 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
44 FileStrategy::kCombine,
45 ForceTimestampBuffering::kForceBufferTimestamps},
46 ConfigParams{"multinode_pingpong_split_config.json", false,
47 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
48 FileStrategy::kCombine,
49 ForceTimestampBuffering::kAutoBuffer}),
Naman Guptaa63aa132023-03-22 20:06:34 -070050 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
51
52INSTANTIATE_TEST_SUITE_P(
53 All, MultinodeLoggerDeathTest,
54 ::testing::Combine(
55 ::testing::Values(
56 ConfigParams{"multinode_pingpong_combined_config.json", true,
Austin Schuh6ecfe902023-08-04 22:44:37 -070057 kCombinedConfigSha1(), kCombinedConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070058 FileStrategy::kKeepSeparate,
59 ForceTimestampBuffering::kForceBufferTimestamps},
60 ConfigParams{"multinode_pingpong_combined_config.json", true,
61 kCombinedConfigSha1(), kCombinedConfigSha1(),
62 FileStrategy::kKeepSeparate,
63 ForceTimestampBuffering::kAutoBuffer},
Naman Guptaa63aa132023-03-22 20:06:34 -070064 ConfigParams{"multinode_pingpong_split_config.json", false,
Austin Schuh6ecfe902023-08-04 22:44:37 -070065 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070066 FileStrategy::kKeepSeparate,
67 ForceTimestampBuffering::kForceBufferTimestamps},
Austin Schuh6ecfe902023-08-04 22:44:37 -070068 ConfigParams{"multinode_pingpong_split_config.json", false,
69 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070070 FileStrategy::kKeepSeparate,
71 ForceTimestampBuffering::kAutoBuffer},
72 ConfigParams{"multinode_pingpong_split_config.json", false,
73 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
74 FileStrategy::kCombine,
75 ForceTimestampBuffering::kForceBufferTimestamps},
76 ConfigParams{"multinode_pingpong_split_config.json", false,
77 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
78 FileStrategy::kCombine,
79 ForceTimestampBuffering::kAutoBuffer}),
Naman Guptaa63aa132023-03-22 20:06:34 -070080 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
81
Austin Schuh633858f2024-03-22 14:34:19 -070082// Class to spam Pong messages blindly.
83class PongSender {
84 public:
85 PongSender(EventLoop *loop, std::string_view channel_name)
86 : sender_(loop->MakeSender<examples::Pong>(channel_name)) {
87 loop->AddPhasedLoop(
88 [this](int) {
89 aos::Sender<examples::Pong>::Builder builder = sender_.MakeBuilder();
90 examples::Pong::Builder pong_builder =
91 builder.MakeBuilder<examples::Pong>();
92 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
93 },
94 chrono::milliseconds(10));
95 }
96
97 private:
98 aos::Sender<examples::Pong> sender_;
99};
100
101// Class to spam Ping messages blindly.
102class PingSender {
103 public:
104 PingSender(EventLoop *loop, std::string_view channel_name)
105 : sender_(loop->MakeSender<examples::Ping>(channel_name)) {
106 loop->AddPhasedLoop(
107 [this](int) {
108 aos::Sender<examples::Ping>::Builder builder = sender_.MakeBuilder();
109 examples::Ping::Builder ping_builder =
110 builder.MakeBuilder<examples::Ping>();
111 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
112 },
113 chrono::milliseconds(10));
114 }
115
116 private:
117 aos::Sender<examples::Ping> sender_;
118};
119
Naman Guptaa63aa132023-03-22 20:06:34 -0700120// Tests that we can write and read simple multi-node log files.
121TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh6ecfe902023-08-04 22:44:37 -0700122 if (file_strategy() == FileStrategy::kCombine) {
123 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
124 }
125
Naman Guptaa63aa132023-03-22 20:06:34 -0700126 std::vector<std::string> actual_filenames;
127 time_converter_.StartEqual();
128
129 {
130 LoggerState pi1_logger = MakeLogger(pi1_);
131 LoggerState pi2_logger = MakeLogger(pi2_);
132
133 event_loop_factory_.RunFor(chrono::milliseconds(95));
134
135 StartLogger(&pi1_logger);
136 StartLogger(&pi2_logger);
137
138 event_loop_factory_.RunFor(chrono::milliseconds(20000));
139 pi1_logger.AppendAllFilenames(&actual_filenames);
140 pi2_logger.AppendAllFilenames(&actual_filenames);
141 }
142
143 ASSERT_THAT(actual_filenames,
144 ::testing::UnorderedElementsAreArray(logfiles_));
145
146 {
147 std::set<std::string> logfile_uuids;
148 std::set<std::string> parts_uuids;
149 // Confirm that we have the expected number of UUIDs for both the logfile
150 // UUIDs and parts UUIDs.
151 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
152 for (std::string_view f : logfiles_) {
153 log_header.emplace_back(ReadHeader(f).value());
154 if (!log_header.back().message().has_configuration()) {
155 logfile_uuids.insert(
156 log_header.back().message().log_event_uuid()->str());
157 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
158 }
159 }
160
161 EXPECT_EQ(logfile_uuids.size(), 2u);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700162 EXPECT_EQ(parts_uuids.size(), 8u);
Naman Guptaa63aa132023-03-22 20:06:34 -0700163
164 // And confirm everything is on the correct node.
165 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
166 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
167 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
168
169 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
170 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700171 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700172
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700173 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
174 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Naman Guptaa63aa132023-03-22 20:06:34 -0700175
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700176 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
177 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700178
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700179 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
180 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
181 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700182
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700183 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
184 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
Naman Guptaa63aa132023-03-22 20:06:34 -0700185
186 // And the parts index matches.
187 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700188
189 EXPECT_EQ(log_header[3].message().parts_index(), 0);
190 EXPECT_EQ(log_header[4].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700191
192 EXPECT_EQ(log_header[5].message().parts_index(), 0);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700193
194 EXPECT_EQ(log_header[6].message().parts_index(), 0);
195 EXPECT_EQ(log_header[7].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700196
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700197 EXPECT_EQ(log_header[8].message().parts_index(), 0);
198 EXPECT_EQ(log_header[9].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700199
200 EXPECT_EQ(log_header[10].message().parts_index(), 0);
201 EXPECT_EQ(log_header[11].message().parts_index(), 1);
202
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700203 EXPECT_EQ(log_header[12].message().parts_index(), 0);
204 EXPECT_EQ(log_header[13].message().parts_index(), 1);
205 EXPECT_EQ(log_header[14].message().parts_index(), 2);
Naman Guptaa63aa132023-03-22 20:06:34 -0700206
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700207 EXPECT_EQ(log_header[15].message().parts_index(), 0);
208 EXPECT_EQ(log_header[16].message().parts_index(), 1);
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700209
210 // And that the data_stored field is right.
211 EXPECT_THAT(*log_header[2].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700212 ::testing::ElementsAre(StoredDataType::DATA));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700213 EXPECT_THAT(*log_header[3].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700214 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700215 EXPECT_THAT(*log_header[4].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700216 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700217
218 EXPECT_THAT(*log_header[5].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700219 ::testing::ElementsAre(StoredDataType::DATA));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700220 EXPECT_THAT(*log_header[6].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700221 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700222 EXPECT_THAT(*log_header[7].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700223 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700224
225 EXPECT_THAT(*log_header[8].message().data_stored(),
226 ::testing::ElementsAre(StoredDataType::DATA));
227 EXPECT_THAT(*log_header[9].message().data_stored(),
228 ::testing::ElementsAre(StoredDataType::DATA));
229
230 EXPECT_THAT(*log_header[10].message().data_stored(),
231 ::testing::ElementsAre(StoredDataType::DATA));
232 EXPECT_THAT(*log_header[11].message().data_stored(),
233 ::testing::ElementsAre(StoredDataType::DATA));
234
235 EXPECT_THAT(*log_header[12].message().data_stored(),
236 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
237 EXPECT_THAT(*log_header[13].message().data_stored(),
238 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
239 EXPECT_THAT(*log_header[14].message().data_stored(),
240 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
241
242 EXPECT_THAT(*log_header[15].message().data_stored(),
243 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
244 EXPECT_THAT(*log_header[16].message().data_stored(),
245 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
Naman Guptaa63aa132023-03-22 20:06:34 -0700246 }
247
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700248 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
249 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -0700250 {
251 using ::testing::UnorderedElementsAre;
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700252 std::shared_ptr<const aos::Configuration> config = sorted_parts[0].config;
Naman Guptaa63aa132023-03-22 20:06:34 -0700253
254 // Timing reports, pings
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700255 if (shared()) {
256 EXPECT_THAT(
257 CountChannelsData(config, logfiles_[2]),
258 UnorderedElementsAre(
259 std::make_tuple("/pi1/aos", "aos.examples.Ping", 2001),
260 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
261 200),
262 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
263 21),
264 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
265 std::make_tuple("/pi1/aos", "aos.timing.Report", 60),
266 std::make_tuple("/test", "aos.examples.Ping", 2001)))
267 << " : " << logfiles_[2];
268 } else {
269 EXPECT_THAT(
270 CountChannelsData(config, logfiles_[2]),
271 UnorderedElementsAre(
272 std::make_tuple("/pi1/aos", "aos.examples.Ping", 2001),
273 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
274 200),
275 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
276 21),
277 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
278 std::make_tuple("/pi1/aos", "aos.timing.Report", 60),
279 std::make_tuple("/test", "aos.examples.Ping", 2001),
280 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
281 "aos-message_bridge-Timestamp",
282 "aos.message_bridge.RemoteMessage", 200)))
283 << " : " << logfiles_[2];
Naman Guptaa63aa132023-03-22 20:06:34 -0700284 }
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700285
286 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
287 ::testing::UnorderedElementsAre())
288 << " : " << logfiles_[3];
289 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
290 ::testing::UnorderedElementsAre())
291 << " : " << logfiles_[4];
292
Naman Guptaa63aa132023-03-22 20:06:34 -0700293 // Timestamps for pong
294 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
295 UnorderedElementsAre())
296 << " : " << logfiles_[2];
297 EXPECT_THAT(
298 CountChannelsTimestamp(config, logfiles_[3]),
299 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
300 << " : " << logfiles_[3];
301 EXPECT_THAT(
302 CountChannelsTimestamp(config, logfiles_[4]),
303 UnorderedElementsAre(
304 std::make_tuple("/test", "aos.examples.Pong", 2000),
305 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
306 << " : " << logfiles_[4];
307
Naman Guptaa63aa132023-03-22 20:06:34 -0700308 // Timing reports and pongs.
Naman Guptaa63aa132023-03-22 20:06:34 -0700309 EXPECT_THAT(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700310 CountChannelsData(config, logfiles_[5]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700311 UnorderedElementsAre(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700312 std::make_tuple("/pi2/aos", "aos.examples.Ping", 2001),
Naman Guptaa63aa132023-03-22 20:06:34 -0700313 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
314 200),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700315 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
316 21),
317 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
Sanjay Narayanan5ec00232022-07-08 15:21:30 -0700318 std::make_tuple("/pi2/aos", "aos.timing.Report", 60),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700319 std::make_tuple("/test", "aos.examples.Pong", 2001)))
320 << " : " << logfiles_[5];
321 EXPECT_THAT(CountChannelsData(config, logfiles_[6]), UnorderedElementsAre())
322 << " : " << logfiles_[6];
323 EXPECT_THAT(CountChannelsData(config, logfiles_[7]), UnorderedElementsAre())
Naman Guptaa63aa132023-03-22 20:06:34 -0700324 << " : " << logfiles_[7];
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700325 // And ping timestamps.
326 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
327 UnorderedElementsAre())
328 << " : " << logfiles_[5];
Naman Guptaa63aa132023-03-22 20:06:34 -0700329 EXPECT_THAT(
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700330 CountChannelsTimestamp(config, logfiles_[6]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700331 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700332 << " : " << logfiles_[6];
Naman Guptaa63aa132023-03-22 20:06:34 -0700333 EXPECT_THAT(
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700334 CountChannelsTimestamp(config, logfiles_[7]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700335 UnorderedElementsAre(
336 std::make_tuple("/test", "aos.examples.Ping", 2000),
337 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700338 << " : " << logfiles_[7];
Naman Guptaa63aa132023-03-22 20:06:34 -0700339
340 // And then test that the remotely logged timestamp data files only have
341 // timestamps in them.
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700342 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
343 UnorderedElementsAre())
344 << " : " << logfiles_[8];
345 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
346 UnorderedElementsAre())
347 << " : " << logfiles_[9];
Naman Guptaa63aa132023-03-22 20:06:34 -0700348 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
349 UnorderedElementsAre())
350 << " : " << logfiles_[10];
351 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
352 UnorderedElementsAre())
353 << " : " << logfiles_[11];
Naman Guptaa63aa132023-03-22 20:06:34 -0700354
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700355 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700356 UnorderedElementsAre(std::make_tuple(
357 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700358 << " : " << logfiles_[8];
359 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700360 UnorderedElementsAre(std::make_tuple(
361 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700362 << " : " << logfiles_[9];
Naman Guptaa63aa132023-03-22 20:06:34 -0700363
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700364 // Pong snd timestamp data.
365 EXPECT_THAT(
366 CountChannelsData(config, logfiles_[10]),
367 UnorderedElementsAre(
368 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 9),
369 std::make_tuple("/test", "aos.examples.Pong", 91)))
370 << " : " << logfiles_[10];
371 EXPECT_THAT(
372 CountChannelsData(config, logfiles_[11]),
373 UnorderedElementsAre(
374 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 191),
375 std::make_tuple("/test", "aos.examples.Pong", 1910)))
376 << " : " << logfiles_[11];
Naman Guptaa63aa132023-03-22 20:06:34 -0700377
378 // Timestamps from pi2 on pi1, and the other way.
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700379 // if (shared()) {
380 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
381 UnorderedElementsAre())
382 << " : " << logfiles_[12];
383 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
384 UnorderedElementsAre())
385 << " : " << logfiles_[13];
386 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
387 UnorderedElementsAre())
388 << " : " << logfiles_[14];
389 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
390 UnorderedElementsAre())
391 << " : " << logfiles_[15];
392 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
393 UnorderedElementsAre())
394 << " : " << logfiles_[16];
Naman Guptaa63aa132023-03-22 20:06:34 -0700395
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700396 EXPECT_THAT(
397 CountChannelsTimestamp(config, logfiles_[12]),
398 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
399 << " : " << logfiles_[12];
400 EXPECT_THAT(
401 CountChannelsTimestamp(config, logfiles_[13]),
402 UnorderedElementsAre(
403 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
404 std::make_tuple("/test", "aos.examples.Ping", 90)))
405 << " : " << logfiles_[13];
406 EXPECT_THAT(
407 CountChannelsTimestamp(config, logfiles_[14]),
408 UnorderedElementsAre(
409 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
410 std::make_tuple("/test", "aos.examples.Ping", 1910)))
411 << " : " << logfiles_[14];
412 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
413 UnorderedElementsAre(std::make_tuple(
414 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
415 << " : " << logfiles_[15];
416 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
417 UnorderedElementsAre(std::make_tuple(
418 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
419 << " : " << logfiles_[16];
Naman Guptaa63aa132023-03-22 20:06:34 -0700420 }
421
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700422 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -0700423
424 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
425 log_reader_factory.set_send_delay(chrono::microseconds(0));
426
427 // This sends out the fetched messages and advances time to the start of the
428 // log file.
429 reader.Register(&log_reader_factory);
430
431 const Node *pi1 =
432 configuration::GetNode(log_reader_factory.configuration(), "pi1");
433 const Node *pi2 =
434 configuration::GetNode(log_reader_factory.configuration(), "pi2");
435
436 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
437 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
438 LOG(INFO) << "now pi1 "
439 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
440 LOG(INFO) << "now pi2 "
441 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
442
443 EXPECT_THAT(reader.LoggedNodes(),
444 ::testing::ElementsAre(
445 configuration::GetNode(reader.logged_configuration(), pi1),
446 configuration::GetNode(reader.logged_configuration(), pi2)));
447
448 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
449
450 std::unique_ptr<EventLoop> pi1_event_loop =
451 log_reader_factory.MakeEventLoop("test", pi1);
452 std::unique_ptr<EventLoop> pi2_event_loop =
453 log_reader_factory.MakeEventLoop("test", pi2);
454
455 int pi1_ping_count = 10;
456 int pi2_ping_count = 10;
457 int pi1_pong_count = 10;
458 int pi2_pong_count = 10;
459
460 // Confirm that the ping value matches.
461 pi1_event_loop->MakeWatcher(
462 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
463 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
464 << pi1_event_loop->context().monotonic_remote_time << " -> "
465 << pi1_event_loop->context().monotonic_event_time;
466 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
467 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
468 pi1_ping_count * chrono::milliseconds(10) +
469 monotonic_clock::epoch());
470 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
471 pi1_ping_count * chrono::milliseconds(10) +
472 realtime_clock::epoch());
473 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
474 pi1_event_loop->context().monotonic_event_time);
475 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
476 pi1_event_loop->context().realtime_event_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -0700477 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_transmit_time,
478 monotonic_clock::min_time);
Naman Guptaa63aa132023-03-22 20:06:34 -0700479
480 ++pi1_ping_count;
481 });
482 pi2_event_loop->MakeWatcher(
483 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
484 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
485 << pi2_event_loop->context().monotonic_remote_time << " -> "
486 << pi2_event_loop->context().monotonic_event_time;
487 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
488
489 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
490 pi2_ping_count * chrono::milliseconds(10) +
491 monotonic_clock::epoch());
492 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
493 pi2_ping_count * chrono::milliseconds(10) +
494 realtime_clock::epoch());
Austin Schuhac6d89e2024-03-27 14:56:09 -0700495 // The message at the start of each second doesn't have wakeup latency
496 // since timing reports and server statistics wake us up already at that
497 // point in time.
498 chrono::nanoseconds offset = chrono::microseconds(150);
499 if (pi2_event_loop->context().monotonic_remote_time.time_since_epoch() %
500 chrono::seconds(1) ==
501 chrono::seconds(0)) {
502 offset = chrono::microseconds(100);
503 }
504 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time + offset,
Naman Guptaa63aa132023-03-22 20:06:34 -0700505 pi2_event_loop->context().monotonic_event_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -0700506 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time -
507 chrono::microseconds(100),
508 pi2_event_loop->context().monotonic_remote_transmit_time);
Austin Schuhac6d89e2024-03-27 14:56:09 -0700509 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time + offset,
Naman Guptaa63aa132023-03-22 20:06:34 -0700510 pi2_event_loop->context().realtime_event_time);
511 ++pi2_ping_count;
512 });
513
514 constexpr ssize_t kQueueIndexOffset = -9;
515 // Confirm that the ping and pong counts both match, and the value also
516 // matches.
Austin Schuhac6d89e2024-03-27 14:56:09 -0700517 pi1_event_loop->MakeWatcher("/test", [&pi1_event_loop, &pi1_ping_count,
518 &pi1_pong_count](
519 const examples::Pong &pong) {
520 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
521 << pi1_event_loop->context().monotonic_remote_time << " -> "
522 << pi1_event_loop->context().monotonic_event_time;
Naman Guptaa63aa132023-03-22 20:06:34 -0700523
Austin Schuhac6d89e2024-03-27 14:56:09 -0700524 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
525 pi1_pong_count + kQueueIndexOffset);
Naman Guptaa63aa132023-03-22 20:06:34 -0700526
Austin Schuhac6d89e2024-03-27 14:56:09 -0700527 chrono::nanoseconds offset = chrono::microseconds(200);
528 if ((pi1_event_loop->context().monotonic_remote_time.time_since_epoch() -
529 chrono::microseconds(150)) %
530 chrono::seconds(1) ==
531 chrono::seconds(0)) {
532 offset = chrono::microseconds(150);
533 }
Naman Guptaa63aa132023-03-22 20:06:34 -0700534
Austin Schuhac6d89e2024-03-27 14:56:09 -0700535 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
536 offset + pi1_pong_count * chrono::milliseconds(10) +
537 monotonic_clock::epoch());
538 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
539 offset + pi1_pong_count * chrono::milliseconds(10) +
540 realtime_clock::epoch());
Naman Guptaa63aa132023-03-22 20:06:34 -0700541
Austin Schuhac6d89e2024-03-27 14:56:09 -0700542 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
543 chrono::microseconds(150),
544 pi1_event_loop->context().monotonic_event_time);
545 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
546 chrono::microseconds(150),
547 pi1_event_loop->context().realtime_event_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -0700548 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_transmit_time,
549 pi1_event_loop->context().monotonic_event_time -
550 chrono::microseconds(100));
Naman Guptaa63aa132023-03-22 20:06:34 -0700551
Austin Schuhac6d89e2024-03-27 14:56:09 -0700552 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
553 ++pi1_pong_count;
554 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
555 });
556 pi2_event_loop->MakeWatcher("/test", [&pi2_event_loop, &pi2_ping_count,
557 &pi2_pong_count](
558 const examples::Pong &pong) {
559 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
560 << pi2_event_loop->context().monotonic_remote_time << " -> "
561 << pi2_event_loop->context().monotonic_event_time;
Naman Guptaa63aa132023-03-22 20:06:34 -0700562
Austin Schuhac6d89e2024-03-27 14:56:09 -0700563 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
564 pi2_pong_count + kQueueIndexOffset);
Naman Guptaa63aa132023-03-22 20:06:34 -0700565
Austin Schuhac6d89e2024-03-27 14:56:09 -0700566 chrono::nanoseconds offset = chrono::microseconds(200);
567 if ((pi2_event_loop->context().monotonic_remote_time.time_since_epoch() -
568 chrono::microseconds(150)) %
569 chrono::seconds(1) ==
570 chrono::seconds(0)) {
571 offset = chrono::microseconds(150);
572 }
573
574 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
575 offset + pi2_pong_count * chrono::milliseconds(10) +
576 monotonic_clock::epoch());
577 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
578 offset + pi2_pong_count * chrono::milliseconds(10) +
579 realtime_clock::epoch());
580
581 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
582 pi2_event_loop->context().monotonic_event_time);
583 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
584 pi2_event_loop->context().realtime_event_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -0700585 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_transmit_time,
586 monotonic_clock::min_time);
Austin Schuhac6d89e2024-03-27 14:56:09 -0700587
588 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
589 ++pi2_pong_count;
590 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
591 });
Naman Guptaa63aa132023-03-22 20:06:34 -0700592
593 log_reader_factory.Run();
594 EXPECT_EQ(pi1_ping_count, 2010);
595 EXPECT_EQ(pi2_ping_count, 2010);
596 EXPECT_EQ(pi1_pong_count, 2010);
597 EXPECT_EQ(pi2_pong_count, 2010);
598
599 reader.Deregister();
600}
601
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600602// MultinodeLoggerTest that tests the mutate callback works across multiple
603// nodes with remapping
604TEST_P(MultinodeLoggerTest, MultiNodeRemapMutateCallback) {
605 time_converter_.StartEqual();
606 std::vector<std::string> actual_filenames;
607
608 {
609 LoggerState pi1_logger = MakeLogger(pi1_);
610 LoggerState pi2_logger = MakeLogger(pi2_);
611
612 event_loop_factory_.RunFor(chrono::milliseconds(95));
613
614 StartLogger(&pi1_logger);
615 StartLogger(&pi2_logger);
616
617 event_loop_factory_.RunFor(chrono::milliseconds(20000));
618 pi1_logger.AppendAllFilenames(&actual_filenames);
619 pi2_logger.AppendAllFilenames(&actual_filenames);
620 }
621
Austin Schuh8fb4b452023-08-04 17:02:27 -0700622 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700623 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600624
625 LogReader reader(sorted_parts, &config_.message());
626 // Remap just on pi1.
627 reader.RemapLoggedChannel<examples::Pong>(
628 "/test", configuration::GetNode(reader.configuration(), "pi1"));
629
630 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
631
632 int pong_count = 0;
633 // Adds a callback which mutates the value of the pong message before the
634 // message is sent which is the feature we are testing here
635 reader.AddBeforeSendCallback("/test",
636 [&pong_count](aos::examples::Pong *pong) {
637 pong->mutate_value(pong->value() + 1);
638 pong_count = pong->value();
639 });
640
641 // This sends out the fetched messages and advances time to the start of the
642 // log file.
643 reader.Register(&log_reader_factory);
644
645 const Node *pi1 =
646 configuration::GetNode(log_reader_factory.configuration(), "pi1");
647 const Node *pi2 =
648 configuration::GetNode(log_reader_factory.configuration(), "pi2");
649
650 EXPECT_THAT(reader.LoggedNodes(),
651 ::testing::ElementsAre(
652 configuration::GetNode(reader.logged_configuration(), pi1),
653 configuration::GetNode(reader.logged_configuration(), pi2)));
654
655 std::unique_ptr<EventLoop> pi1_event_loop =
656 log_reader_factory.MakeEventLoop("test", pi1);
657 std::unique_ptr<EventLoop> pi2_event_loop =
658 log_reader_factory.MakeEventLoop("test", pi2);
659
660 pi1_event_loop->MakeWatcher("/original/test",
661 [&pong_count](const examples::Pong &pong) {
662 EXPECT_EQ(pong_count, pong.value());
663 });
664
665 pi2_event_loop->MakeWatcher("/test",
666 [&pong_count](const examples::Pong &pong) {
667 EXPECT_EQ(pong_count, pong.value());
668 });
669
670 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
671 reader.Deregister();
672
673 EXPECT_EQ(pong_count, 2011);
674}
675
676// MultinodeLoggerTest that tests the mutate callback works across multiple
677// nodes
678TEST_P(MultinodeLoggerTest, MultiNodeMutateCallback) {
679 time_converter_.StartEqual();
680 std::vector<std::string> actual_filenames;
681
682 {
683 LoggerState pi1_logger = MakeLogger(pi1_);
684 LoggerState pi2_logger = MakeLogger(pi2_);
685
686 event_loop_factory_.RunFor(chrono::milliseconds(95));
687
688 StartLogger(&pi1_logger);
689 StartLogger(&pi2_logger);
690
691 event_loop_factory_.RunFor(chrono::milliseconds(20000));
692 pi1_logger.AppendAllFilenames(&actual_filenames);
693 pi2_logger.AppendAllFilenames(&actual_filenames);
694 }
695
Austin Schuh8fb4b452023-08-04 17:02:27 -0700696 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700697 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600698
699 LogReader reader(sorted_parts, &config_.message());
700
701 int pong_count = 0;
702 // Adds a callback which mutates the value of the pong message before the
703 // message is sent which is the feature we are testing here
704 reader.AddBeforeSendCallback("/test",
705 [&pong_count](aos::examples::Pong *pong) {
706 pong->mutate_value(pong->value() + 1);
707 pong_count = pong->value();
708 });
709
710 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
711
712 // This sends out the fetched messages and advances time to the start of the
713 // log file.
714 reader.Register(&log_reader_factory);
715
716 const Node *pi1 =
717 configuration::GetNode(log_reader_factory.configuration(), "pi1");
718 const Node *pi2 =
719 configuration::GetNode(log_reader_factory.configuration(), "pi2");
720
721 EXPECT_THAT(reader.LoggedNodes(),
722 ::testing::ElementsAre(
723 configuration::GetNode(reader.logged_configuration(), pi1),
724 configuration::GetNode(reader.logged_configuration(), pi2)));
725
726 std::unique_ptr<EventLoop> pi1_event_loop =
727 log_reader_factory.MakeEventLoop("test", pi1);
728 std::unique_ptr<EventLoop> pi2_event_loop =
729 log_reader_factory.MakeEventLoop("test", pi2);
730
731 pi1_event_loop->MakeWatcher("/test",
732 [&pong_count](const examples::Pong &pong) {
733 EXPECT_EQ(pong_count, pong.value());
734 });
735
736 pi2_event_loop->MakeWatcher("/test",
737 [&pong_count](const examples::Pong &pong) {
738 EXPECT_EQ(pong_count, pong.value());
739 });
740
741 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
742 reader.Deregister();
743
744 EXPECT_EQ(pong_count, 2011);
745}
746
747// Tests that the before send callback is only called from the sender node if it
748// is forwarded
749TEST_P(MultinodeLoggerTest, OnlyDoBeforeSendCallbackOnSenderNode) {
750 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700751
752 std::vector<std::string> filenames;
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600753 {
754 LoggerState pi1_logger = MakeLogger(pi1_);
755 LoggerState pi2_logger = MakeLogger(pi2_);
756
757 event_loop_factory_.RunFor(chrono::milliseconds(95));
758
759 StartLogger(&pi1_logger);
760 StartLogger(&pi2_logger);
761
762 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700763
764 pi1_logger.AppendAllFilenames(&filenames);
765 pi2_logger.AppendAllFilenames(&filenames);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600766 }
767
Austin Schuh8fb4b452023-08-04 17:02:27 -0700768 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700769 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
770 LogReader reader(sorted_parts);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600771
772 int ping_count = 0;
773 // Adds a callback which mutates the value of the pong message before the
774 // message is sent which is the feature we are testing here
775 reader.AddBeforeSendCallback("/test",
776 [&ping_count](aos::examples::Ping *ping) {
777 ++ping_count;
778 ping->mutate_value(ping_count);
779 });
780
781 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
782 log_reader_factory.set_send_delay(chrono::microseconds(0));
783
784 reader.Register(&log_reader_factory);
785
786 const Node *pi1 =
787 configuration::GetNode(log_reader_factory.configuration(), "pi1");
788 const Node *pi2 =
789 configuration::GetNode(log_reader_factory.configuration(), "pi2");
790
791 std::unique_ptr<EventLoop> pi1_event_loop =
792 log_reader_factory.MakeEventLoop("test", pi1);
793 pi1_event_loop->SkipTimingReport();
794 std::unique_ptr<EventLoop> pi2_event_loop =
795 log_reader_factory.MakeEventLoop("test", pi2);
796 pi2_event_loop->SkipTimingReport();
797
798 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
799 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
800
801 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
802 pi1_ping_timestamp;
803 if (!shared()) {
804 pi1_ping_timestamp =
805 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
806 pi1_event_loop.get(),
807 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
808 }
809
810 log_reader_factory.Run();
811
812 EXPECT_EQ(pi1_ping.count(), 2000u);
813 EXPECT_EQ(pi2_ping.count(), 2000u);
814 // If the BeforeSendCallback is called on both nodes, then the ping count
815 // would be 4002 instead of 2001
816 EXPECT_EQ(ping_count, 2001u);
817 if (!shared()) {
818 EXPECT_EQ(pi1_ping_timestamp->count(), 2000u);
819 }
820
821 reader.Deregister();
822}
823
824// Tests that we do not allow adding callbacks after Register is called
825TEST_P(MultinodeLoggerDeathTest, AddCallbackAfterRegister) {
826 time_converter_.StartEqual();
827 std::vector<std::string> actual_filenames;
828
829 {
830 LoggerState pi1_logger = MakeLogger(pi1_);
831 LoggerState pi2_logger = MakeLogger(pi2_);
832
833 event_loop_factory_.RunFor(chrono::milliseconds(95));
834
835 StartLogger(&pi1_logger);
836 StartLogger(&pi2_logger);
837
838 event_loop_factory_.RunFor(chrono::milliseconds(20000));
839 pi1_logger.AppendAllFilenames(&actual_filenames);
840 pi2_logger.AppendAllFilenames(&actual_filenames);
841 }
842
Austin Schuh8fb4b452023-08-04 17:02:27 -0700843 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700844 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600845
846 LogReader reader(sorted_parts, &config_.message());
847 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
848 reader.Register(&log_reader_factory);
849 EXPECT_DEATH(
850 {
851 reader.AddBeforeSendCallback("/test", [](aos::examples::Pong *) {
852 LOG(FATAL) << "This should not be called";
853 });
854 },
855 "Cannot add callbacks after calling Register");
856 reader.Deregister();
857}
858
Naman Guptaa63aa132023-03-22 20:06:34 -0700859// Test that if we feed the replay with a mismatched node list that we die on
860// the LogReader constructor.
861TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
862 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700863
864 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -0700865 {
866 LoggerState pi1_logger = MakeLogger(pi1_);
867 LoggerState pi2_logger = MakeLogger(pi2_);
868
869 event_loop_factory_.RunFor(chrono::milliseconds(95));
870
871 StartLogger(&pi1_logger);
872 StartLogger(&pi2_logger);
873
874 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700875
876 pi1_logger.AppendAllFilenames(&filenames);
877 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -0700878 }
879
880 // Test that, if we add an additional node to the replay config that the
881 // logger complains about the mismatch in number of nodes.
882 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
883 configuration::MergeWithConfig(&config_.message(), R"({
884 "nodes": [
885 {
886 "name": "extra-node"
887 }
888 ]
889 }
890 )");
891
Austin Schuh8fb4b452023-08-04 17:02:27 -0700892 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700893 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -0700894 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
895 "Log file and replay config need to have matching nodes lists.");
896}
897
898// Tests that we can read log files where they don't start at the same monotonic
899// time.
900TEST_P(MultinodeLoggerTest, StaggeredStart) {
901 time_converter_.StartEqual();
902 std::vector<std::string> actual_filenames;
903
904 {
905 LoggerState pi1_logger = MakeLogger(pi1_);
906 LoggerState pi2_logger = MakeLogger(pi2_);
907
908 event_loop_factory_.RunFor(chrono::milliseconds(95));
909
910 StartLogger(&pi1_logger);
911
912 event_loop_factory_.RunFor(chrono::milliseconds(200));
913
914 StartLogger(&pi2_logger);
915
916 event_loop_factory_.RunFor(chrono::milliseconds(20000));
917 pi1_logger.AppendAllFilenames(&actual_filenames);
918 pi2_logger.AppendAllFilenames(&actual_filenames);
919 }
920
921 // Since we delay starting pi2, it already knows about all the timestamps so
922 // we don't end up with extra parts.
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700923 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
924 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
925 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -0700926
927 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
928 log_reader_factory.set_send_delay(chrono::microseconds(0));
929
930 // This sends out the fetched messages and advances time to the start of the
931 // log file.
932 reader.Register(&log_reader_factory);
933
934 const Node *pi1 =
935 configuration::GetNode(log_reader_factory.configuration(), "pi1");
936 const Node *pi2 =
937 configuration::GetNode(log_reader_factory.configuration(), "pi2");
938
939 EXPECT_THAT(reader.LoggedNodes(),
940 ::testing::ElementsAre(
941 configuration::GetNode(reader.logged_configuration(), pi1),
942 configuration::GetNode(reader.logged_configuration(), pi2)));
943
944 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
945
946 std::unique_ptr<EventLoop> pi1_event_loop =
947 log_reader_factory.MakeEventLoop("test", pi1);
948 std::unique_ptr<EventLoop> pi2_event_loop =
949 log_reader_factory.MakeEventLoop("test", pi2);
950
951 int pi1_ping_count = 30;
952 int pi2_ping_count = 30;
953 int pi1_pong_count = 30;
954 int pi2_pong_count = 30;
955
956 // Confirm that the ping value matches.
957 pi1_event_loop->MakeWatcher(
958 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
959 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
960 << pi1_event_loop->context().monotonic_remote_time << " -> "
961 << pi1_event_loop->context().monotonic_event_time;
962 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
963
964 ++pi1_ping_count;
965 });
966 pi2_event_loop->MakeWatcher(
967 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
968 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
969 << pi2_event_loop->context().monotonic_remote_time << " -> "
970 << pi2_event_loop->context().monotonic_event_time;
971 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
972
973 ++pi2_ping_count;
974 });
975
976 // Confirm that the ping and pong counts both match, and the value also
977 // matches.
978 pi1_event_loop->MakeWatcher(
979 "/test", [&pi1_event_loop, &pi1_ping_count,
980 &pi1_pong_count](const examples::Pong &pong) {
981 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
982 << pi1_event_loop->context().monotonic_remote_time << " -> "
983 << pi1_event_loop->context().monotonic_event_time;
984
985 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
986 ++pi1_pong_count;
987 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
988 });
989 pi2_event_loop->MakeWatcher(
990 "/test", [&pi2_event_loop, &pi2_ping_count,
991 &pi2_pong_count](const examples::Pong &pong) {
992 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
993 << pi2_event_loop->context().monotonic_remote_time << " -> "
994 << pi2_event_loop->context().monotonic_event_time;
995
996 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
997 ++pi2_pong_count;
998 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
999 });
1000
1001 log_reader_factory.Run();
1002 EXPECT_EQ(pi1_ping_count, 2030);
1003 EXPECT_EQ(pi2_ping_count, 2030);
1004 EXPECT_EQ(pi1_pong_count, 2030);
1005 EXPECT_EQ(pi2_pong_count, 2030);
1006
1007 reader.Deregister();
1008}
1009
1010// Tests that we can read log files where the monotonic clocks drift and don't
1011// match correctly. While we are here, also test that different ending times
1012// also is readable.
1013TEST_P(MultinodeLoggerTest, MismatchedClocks) {
1014 // TODO(austin): Negate...
1015 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1016
1017 time_converter_.AddMonotonic(
1018 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
1019 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1020 // skew to be 200 uS/s
1021 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1022 {chrono::milliseconds(95),
1023 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1024 // Run another 200 ms to have one logger start first.
1025 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1026 {chrono::milliseconds(200), chrono::milliseconds(200)});
1027 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1028 // go far enough to cause problems if this isn't accounted for.
1029 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1030 {chrono::milliseconds(20000),
1031 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1032 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1033 {chrono::milliseconds(40000),
1034 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1035 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1036 {chrono::milliseconds(400), chrono::milliseconds(400)});
1037
Austin Schuh8fb4b452023-08-04 17:02:27 -07001038 std::vector<std::string> actual_filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07001039 {
1040 LoggerState pi2_logger = MakeLogger(pi2_);
1041
1042 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1043 << pi2_->realtime_now() << " distributed "
1044 << pi2_->ToDistributedClock(pi2_->monotonic_now());
1045
1046 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1047 << pi2_->realtime_now() << " distributed "
1048 << pi2_->ToDistributedClock(pi2_->monotonic_now());
1049
1050 event_loop_factory_.RunFor(startup_sleep1);
1051
1052 StartLogger(&pi2_logger);
1053
1054 event_loop_factory_.RunFor(startup_sleep2);
1055
1056 {
1057 // Run pi1's logger for only part of the time.
1058 LoggerState pi1_logger = MakeLogger(pi1_);
1059
1060 StartLogger(&pi1_logger);
1061 event_loop_factory_.RunFor(logger_run1);
1062
1063 // Make sure we slewed time far enough so that the difference is greater
1064 // than the network delay. This confirms that if we sort incorrectly, it
1065 // would show in the results.
1066 EXPECT_LT(
1067 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1068 -event_loop_factory_.send_delay() -
1069 event_loop_factory_.network_delay());
1070
1071 event_loop_factory_.RunFor(logger_run2);
1072
1073 // And now check that we went far enough the other way to make sure we
1074 // cover both problems.
1075 EXPECT_GT(
1076 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1077 event_loop_factory_.send_delay() +
1078 event_loop_factory_.network_delay());
Austin Schuh8fb4b452023-08-04 17:02:27 -07001079
1080 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001081 }
1082
1083 // And log a bit more on pi2.
1084 event_loop_factory_.RunFor(logger_run3);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001085
1086 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001087 }
1088
Austin Schuh8fb4b452023-08-04 17:02:27 -07001089 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001090 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1091 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001092
1093 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1094 log_reader_factory.set_send_delay(chrono::microseconds(0));
1095
1096 const Node *pi1 =
1097 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1098 const Node *pi2 =
1099 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1100
1101 // This sends out the fetched messages and advances time to the start of the
1102 // log file.
1103 reader.Register(&log_reader_factory);
1104
1105 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1106 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1107 LOG(INFO) << "now pi1 "
1108 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1109 LOG(INFO) << "now pi2 "
1110 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1111
1112 LOG(INFO) << "Done registering (pi1) "
1113 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1114 << " "
1115 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1116 LOG(INFO) << "Done registering (pi2) "
1117 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1118 << " "
1119 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1120
1121 EXPECT_THAT(reader.LoggedNodes(),
1122 ::testing::ElementsAre(
1123 configuration::GetNode(reader.logged_configuration(), pi1),
1124 configuration::GetNode(reader.logged_configuration(), pi2)));
1125
1126 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1127
1128 std::unique_ptr<EventLoop> pi1_event_loop =
1129 log_reader_factory.MakeEventLoop("test", pi1);
1130 std::unique_ptr<EventLoop> pi2_event_loop =
1131 log_reader_factory.MakeEventLoop("test", pi2);
1132
1133 int pi1_ping_count = 30;
1134 int pi2_ping_count = 30;
1135 int pi1_pong_count = 30;
1136 int pi2_pong_count = 30;
1137
1138 // Confirm that the ping value matches.
1139 pi1_event_loop->MakeWatcher(
1140 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1141 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1142 << pi1_event_loop->context().monotonic_remote_time << " -> "
1143 << pi1_event_loop->context().monotonic_event_time;
1144 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1145
1146 ++pi1_ping_count;
1147 });
1148 pi2_event_loop->MakeWatcher(
1149 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1150 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1151 << pi2_event_loop->context().monotonic_remote_time << " -> "
1152 << pi2_event_loop->context().monotonic_event_time;
1153 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1154
1155 ++pi2_ping_count;
1156 });
1157
1158 // Confirm that the ping and pong counts both match, and the value also
1159 // matches.
1160 pi1_event_loop->MakeWatcher(
1161 "/test", [&pi1_event_loop, &pi1_ping_count,
1162 &pi1_pong_count](const examples::Pong &pong) {
1163 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1164 << pi1_event_loop->context().monotonic_remote_time << " -> "
1165 << pi1_event_loop->context().monotonic_event_time;
1166
1167 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1168 ++pi1_pong_count;
1169 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1170 });
1171 pi2_event_loop->MakeWatcher(
1172 "/test", [&pi2_event_loop, &pi2_ping_count,
1173 &pi2_pong_count](const examples::Pong &pong) {
1174 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1175 << pi2_event_loop->context().monotonic_remote_time << " -> "
1176 << pi2_event_loop->context().monotonic_event_time;
1177
1178 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1179 ++pi2_pong_count;
1180 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1181 });
1182
1183 log_reader_factory.Run();
1184 EXPECT_EQ(pi1_ping_count, 6030);
1185 EXPECT_EQ(pi2_ping_count, 6030);
1186 EXPECT_EQ(pi1_pong_count, 6030);
1187 EXPECT_EQ(pi2_pong_count, 6030);
1188
1189 reader.Deregister();
1190}
1191
1192// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
1193TEST_P(MultinodeLoggerTest, SortParts) {
1194 time_converter_.StartEqual();
1195 // Make a bunch of parts.
1196 {
1197 LoggerState pi1_logger = MakeLogger(pi1_);
1198 LoggerState pi2_logger = MakeLogger(pi2_);
1199
1200 event_loop_factory_.RunFor(chrono::milliseconds(95));
1201
1202 StartLogger(&pi1_logger);
1203 StartLogger(&pi2_logger);
1204
1205 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1206 }
1207
1208 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1209 VerifyParts(sorted_parts);
1210}
1211
1212// Tests that we can sort a bunch of parts with an empty part. We should ignore
1213// it and remove it from the sorted list.
1214TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07001215 std::vector<std::string> actual_filenames;
1216
Naman Guptaa63aa132023-03-22 20:06:34 -07001217 time_converter_.StartEqual();
1218 // Make a bunch of parts.
1219 {
1220 LoggerState pi1_logger = MakeLogger(pi1_);
1221 LoggerState pi2_logger = MakeLogger(pi2_);
1222
1223 event_loop_factory_.RunFor(chrono::milliseconds(95));
1224
1225 StartLogger(&pi1_logger);
1226 StartLogger(&pi2_logger);
1227
1228 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001229 pi1_logger.AppendAllFilenames(&actual_filenames);
1230 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001231 }
1232
1233 // TODO(austin): Should we flip out if the file can't open?
1234 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
1235
1236 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
Austin Schuh8fb4b452023-08-04 17:02:27 -07001237 actual_filenames.emplace_back(kEmptyFile);
Naman Guptaa63aa132023-03-22 20:06:34 -07001238
Austin Schuh8fb4b452023-08-04 17:02:27 -07001239 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001240 VerifyParts(sorted_parts, {kEmptyFile});
1241}
1242
1243// Tests that we can sort a bunch of parts with the end missing off a
1244// file. We should use the part we can read.
1245TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07001246 if (file_strategy() == FileStrategy::kCombine) {
1247 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
1248 }
1249
Naman Guptaa63aa132023-03-22 20:06:34 -07001250 std::vector<std::string> actual_filenames;
1251 time_converter_.StartEqual();
1252 // Make a bunch of parts.
1253 {
1254 LoggerState pi1_logger = MakeLogger(pi1_);
1255 LoggerState pi2_logger = MakeLogger(pi2_);
1256
1257 event_loop_factory_.RunFor(chrono::milliseconds(95));
1258
1259 StartLogger(&pi1_logger);
1260 StartLogger(&pi2_logger);
1261
1262 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1263
1264 pi1_logger.AppendAllFilenames(&actual_filenames);
1265 pi2_logger.AppendAllFilenames(&actual_filenames);
1266 }
1267
1268 ASSERT_THAT(actual_filenames,
1269 ::testing::UnorderedElementsAreArray(logfiles_));
1270
1271 // Strip off the end of one of the files. Pick one with a lot of data.
1272 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1273 // that we don't corrupt the entire log part.
1274 ::std::string compressed_contents =
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001275 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Naman Guptaa63aa132023-03-22 20:06:34 -07001276
1277 aos::util::WriteStringToFileOrDie(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001278 logfiles_[2],
Naman Guptaa63aa132023-03-22 20:06:34 -07001279 compressed_contents.substr(0, compressed_contents.size() - 100));
1280
1281 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1282 VerifyParts(sorted_parts);
1283}
1284
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001285// Tests that if we remap a logged channel, it shows up correctly.
Naman Guptaa63aa132023-03-22 20:06:34 -07001286TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
1287 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -07001288
1289 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07001290 {
1291 LoggerState pi1_logger = MakeLogger(pi1_);
1292 LoggerState pi2_logger = MakeLogger(pi2_);
1293
1294 event_loop_factory_.RunFor(chrono::milliseconds(95));
1295
1296 StartLogger(&pi1_logger);
1297 StartLogger(&pi2_logger);
1298
1299 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001300
1301 pi1_logger.AppendAllFilenames(&filenames);
1302 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001303 }
1304
Austin Schuh8fb4b452023-08-04 17:02:27 -07001305 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001306 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1307 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001308
1309 // Remap just on pi1.
1310 reader.RemapLoggedChannel<aos::timing::Report>(
1311 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1312
1313 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1314 log_reader_factory.set_send_delay(chrono::microseconds(0));
1315
1316 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1317 // Note: An extra channel gets remapped automatically due to a timestamp
1318 // channel being LOCAL_LOGGER'd.
1319 ASSERT_EQ(remapped_channels.size(), std::get<0>(GetParam()).shared ? 1u : 2u);
1320 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1321 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1322 if (!std::get<0>(GetParam()).shared) {
1323 EXPECT_EQ(remapped_channels[1]->name()->string_view(),
1324 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1325 "aos-message_bridge-Timestamp");
1326 EXPECT_EQ(remapped_channels[1]->type()->string_view(),
1327 "aos.message_bridge.RemoteMessage");
1328 }
1329
1330 reader.Register(&log_reader_factory);
1331
1332 const Node *pi1 =
1333 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1334 const Node *pi2 =
1335 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1336
1337 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1338 // else should have moved.
1339 std::unique_ptr<EventLoop> pi1_event_loop =
1340 log_reader_factory.MakeEventLoop("test", pi1);
1341 pi1_event_loop->SkipTimingReport();
1342 std::unique_ptr<EventLoop> full_pi1_event_loop =
1343 log_reader_factory.MakeEventLoop("test", pi1);
1344 full_pi1_event_loop->SkipTimingReport();
1345 std::unique_ptr<EventLoop> pi2_event_loop =
1346 log_reader_factory.MakeEventLoop("test", pi2);
1347 pi2_event_loop->SkipTimingReport();
1348
1349 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1350 "/aos");
1351 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1352 full_pi1_event_loop.get(), "/pi1/aos");
1353 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1354 pi1_event_loop.get(), "/original/aos");
1355 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1356 full_pi1_event_loop.get(), "/original/pi1/aos");
1357 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1358 "/aos");
1359
1360 log_reader_factory.Run();
1361
1362 EXPECT_EQ(pi1_timing_report.count(), 0u);
1363 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1364 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1365 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1366 EXPECT_NE(pi2_timing_report.count(), 0u);
1367
1368 reader.Deregister();
1369}
1370
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001371// Tests that if we rename a logged channel, it shows up correctly.
1372TEST_P(MultinodeLoggerTest, RenameLoggedChannel) {
1373 std::vector<std::string> actual_filenames;
1374 time_converter_.StartEqual();
1375 {
1376 LoggerState pi1_logger = MakeLogger(pi1_);
1377 LoggerState pi2_logger = MakeLogger(pi2_);
1378
1379 event_loop_factory_.RunFor(chrono::milliseconds(95));
1380
1381 StartLogger(&pi1_logger);
1382 StartLogger(&pi2_logger);
1383
1384 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1385
1386 pi1_logger.AppendAllFilenames(&actual_filenames);
1387 pi2_logger.AppendAllFilenames(&actual_filenames);
1388 }
1389
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001390 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1391 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1392 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001393
1394 // Rename just on pi2. Add some global maps just to verify they get added in
1395 // the config and used correctly.
1396 std::vector<MapT> maps;
1397 {
1398 MapT map;
1399 map.match = std::make_unique<ChannelT>();
1400 map.match->name = "/foo*";
1401 map.match->source_node = "pi1";
1402 map.rename = std::make_unique<ChannelT>();
1403 map.rename->name = "/pi1/foo";
1404 maps.emplace_back(std::move(map));
1405 }
1406 {
1407 MapT map;
1408 map.match = std::make_unique<ChannelT>();
1409 map.match->name = "/foo*";
1410 map.match->source_node = "pi2";
1411 map.rename = std::make_unique<ChannelT>();
1412 map.rename->name = "/pi2/foo";
1413 maps.emplace_back(std::move(map));
1414 }
1415 {
1416 MapT map;
1417 map.match = std::make_unique<ChannelT>();
1418 map.match->name = "/foo";
1419 map.match->type = "aos.examples.Ping";
1420 map.rename = std::make_unique<ChannelT>();
1421 map.rename->name = "/foo/renamed";
1422 maps.emplace_back(std::move(map));
1423 }
1424 reader.RenameLoggedChannel<aos::examples::Ping>(
1425 "/aos", configuration::GetNode(reader.configuration(), "pi2"),
1426 "/pi2/foo/renamed", maps);
1427
1428 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1429 log_reader_factory.set_send_delay(chrono::microseconds(0));
1430
1431 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1432 // Note: An extra channel gets remapped automatically due to a timestamp
1433 // channel being LOCAL_LOGGER'd.
1434 const bool shared = std::get<0>(GetParam()).shared;
1435 ASSERT_EQ(remapped_channels.size(), shared ? 1u : 2u);
1436 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->name()->string_view(),
1437 "/pi2/foo/renamed");
1438 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->type()->string_view(),
1439 "aos.examples.Ping");
1440 if (!shared) {
1441 EXPECT_EQ(remapped_channels[0]->name()->string_view(),
1442 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1443 "aos-message_bridge-Timestamp");
1444 EXPECT_EQ(remapped_channels[0]->type()->string_view(),
1445 "aos.message_bridge.RemoteMessage");
1446 }
1447
1448 reader.Register(&log_reader_factory);
1449
1450 const Node *pi1 =
1451 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1452 const Node *pi2 =
1453 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1454
1455 // Confirm we can read the data on the renamed channel, just for pi2. Nothing
1456 // else should have moved.
1457 std::unique_ptr<EventLoop> pi2_event_loop =
1458 log_reader_factory.MakeEventLoop("test", pi2);
1459 pi2_event_loop->SkipTimingReport();
1460 std::unique_ptr<EventLoop> full_pi2_event_loop =
1461 log_reader_factory.MakeEventLoop("test", pi2);
1462 full_pi2_event_loop->SkipTimingReport();
1463 std::unique_ptr<EventLoop> pi1_event_loop =
1464 log_reader_factory.MakeEventLoop("test", pi1);
1465 pi1_event_loop->SkipTimingReport();
1466
1467 MessageCounter<aos::examples::Ping> pi2_ping(pi2_event_loop.get(), "/aos");
1468 MessageCounter<aos::examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1469 "/foo");
1470 MessageCounter<aos::examples::Ping> full_pi2_renamed_ping(
1471 full_pi2_event_loop.get(), "/pi2/foo/renamed");
1472 MessageCounter<aos::examples::Ping> pi1_ping(pi1_event_loop.get(), "/aos");
1473
1474 log_reader_factory.Run();
1475
1476 EXPECT_EQ(pi2_ping.count(), 0u);
1477 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1478 EXPECT_NE(full_pi2_renamed_ping.count(), 0u);
1479 EXPECT_NE(pi1_ping.count(), 0u);
1480
1481 reader.Deregister();
1482}
1483
Naman Guptaa63aa132023-03-22 20:06:34 -07001484// Tests that we can remap a forwarded channel as well.
1485TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1486 time_converter_.StartEqual();
1487 {
1488 LoggerState pi1_logger = MakeLogger(pi1_);
1489 LoggerState pi2_logger = MakeLogger(pi2_);
1490
1491 event_loop_factory_.RunFor(chrono::milliseconds(95));
1492
1493 StartLogger(&pi1_logger);
1494 StartLogger(&pi2_logger);
1495
1496 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1497 }
1498
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001499 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1500 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1501 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001502
1503 reader.RemapLoggedChannel<examples::Ping>("/test");
1504
1505 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1506 log_reader_factory.set_send_delay(chrono::microseconds(0));
1507
1508 reader.Register(&log_reader_factory);
1509
1510 const Node *pi1 =
1511 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1512 const Node *pi2 =
1513 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1514
1515 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1516 // else should have moved.
1517 std::unique_ptr<EventLoop> pi1_event_loop =
1518 log_reader_factory.MakeEventLoop("test", pi1);
1519 pi1_event_loop->SkipTimingReport();
1520 std::unique_ptr<EventLoop> full_pi1_event_loop =
1521 log_reader_factory.MakeEventLoop("test", pi1);
1522 full_pi1_event_loop->SkipTimingReport();
1523 std::unique_ptr<EventLoop> pi2_event_loop =
1524 log_reader_factory.MakeEventLoop("test", pi2);
1525 pi2_event_loop->SkipTimingReport();
1526
1527 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1528 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1529 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1530 "/original/test");
1531 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1532 "/original/test");
1533
1534 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1535 pi1_original_ping_timestamp;
1536 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1537 pi1_ping_timestamp;
1538 if (!shared()) {
1539 pi1_original_ping_timestamp =
1540 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1541 pi1_event_loop.get(),
1542 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1543 pi1_ping_timestamp =
1544 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1545 pi1_event_loop.get(),
1546 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1547 }
1548
1549 log_reader_factory.Run();
1550
1551 EXPECT_EQ(pi1_ping.count(), 0u);
1552 EXPECT_EQ(pi2_ping.count(), 0u);
1553 EXPECT_NE(pi1_original_ping.count(), 0u);
1554 EXPECT_NE(pi2_original_ping.count(), 0u);
1555 if (!shared()) {
1556 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1557 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1558 }
1559
1560 reader.Deregister();
1561}
1562
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001563// Tests that we can rename a forwarded channel as well.
1564TEST_P(MultinodeLoggerTest, RenameForwardedLoggedChannel) {
1565 std::vector<std::string> actual_filenames;
1566 time_converter_.StartEqual();
1567 {
1568 LoggerState pi1_logger = MakeLogger(pi1_);
1569 LoggerState pi2_logger = MakeLogger(pi2_);
1570
1571 event_loop_factory_.RunFor(chrono::milliseconds(95));
1572
1573 StartLogger(&pi1_logger);
1574 StartLogger(&pi2_logger);
1575
1576 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1577
1578 pi1_logger.AppendAllFilenames(&actual_filenames);
1579 pi2_logger.AppendAllFilenames(&actual_filenames);
1580 }
1581
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001582 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1583 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1584 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001585
1586 std::vector<MapT> maps;
1587 {
1588 MapT map;
1589 map.match = std::make_unique<ChannelT>();
1590 map.match->name = "/production*";
1591 map.match->source_node = "pi1";
1592 map.rename = std::make_unique<ChannelT>();
1593 map.rename->name = "/pi1/production";
1594 maps.emplace_back(std::move(map));
1595 }
1596 {
1597 MapT map;
1598 map.match = std::make_unique<ChannelT>();
1599 map.match->name = "/production*";
1600 map.match->source_node = "pi2";
1601 map.rename = std::make_unique<ChannelT>();
1602 map.rename->name = "/pi2/production";
1603 maps.emplace_back(std::move(map));
1604 }
1605 reader.RenameLoggedChannel<aos::examples::Ping>(
1606 "/test", configuration::GetNode(reader.configuration(), "pi1"),
1607 "/pi1/production", maps);
1608
1609 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1610 log_reader_factory.set_send_delay(chrono::microseconds(0));
1611
1612 reader.Register(&log_reader_factory);
1613
1614 const Node *pi1 =
1615 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1616 const Node *pi2 =
1617 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1618
1619 // Confirm we can read the data on the renamed channel, on both the source
1620 // node and the remote node. In case of split timestamp channels, confirm that
1621 // we receive the timestamp messages on the renamed channel as well.
1622 std::unique_ptr<EventLoop> pi1_event_loop =
1623 log_reader_factory.MakeEventLoop("test", pi1);
1624 pi1_event_loop->SkipTimingReport();
1625 std::unique_ptr<EventLoop> full_pi1_event_loop =
1626 log_reader_factory.MakeEventLoop("test", pi1);
1627 full_pi1_event_loop->SkipTimingReport();
1628 std::unique_ptr<EventLoop> pi2_event_loop =
1629 log_reader_factory.MakeEventLoop("test", pi2);
1630 pi2_event_loop->SkipTimingReport();
1631
1632 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1633 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1634 MessageCounter<examples::Ping> pi1_renamed_ping(pi1_event_loop.get(),
1635 "/pi1/production");
1636 MessageCounter<examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1637 "/pi1/production");
1638
1639 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1640 pi1_renamed_ping_timestamp;
1641 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1642 pi1_ping_timestamp;
1643 if (!shared()) {
1644 pi1_renamed_ping_timestamp =
1645 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1646 pi1_event_loop.get(),
1647 "/pi1/aos/remote_timestamps/pi2/pi1/production/aos-examples-Ping");
1648 pi1_ping_timestamp =
1649 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1650 pi1_event_loop.get(),
1651 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1652 }
1653
1654 log_reader_factory.Run();
1655
1656 EXPECT_EQ(pi1_ping.count(), 0u);
1657 EXPECT_EQ(pi2_ping.count(), 0u);
1658 EXPECT_NE(pi1_renamed_ping.count(), 0u);
1659 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1660 if (!shared()) {
1661 EXPECT_NE(pi1_renamed_ping_timestamp->count(), 0u);
1662 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1663 }
1664
1665 reader.Deregister();
1666}
1667
Naman Guptaa63aa132023-03-22 20:06:34 -07001668// Tests that we observe all the same events in log replay (for a given node)
1669// whether we just register an event loop for that node or if we register a full
1670// event loop factory.
1671TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
1672 time_converter_.StartEqual();
1673 constexpr chrono::milliseconds kStartupDelay(95);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001674 std::vector<std::string> filenames;
1675
Naman Guptaa63aa132023-03-22 20:06:34 -07001676 {
1677 LoggerState pi1_logger = MakeLogger(pi1_);
1678 LoggerState pi2_logger = MakeLogger(pi2_);
1679
1680 event_loop_factory_.RunFor(kStartupDelay);
1681
1682 StartLogger(&pi1_logger);
1683 StartLogger(&pi2_logger);
1684
1685 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001686
1687 pi1_logger.AppendAllFilenames(&filenames);
1688 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001689 }
1690
Austin Schuh8fb4b452023-08-04 17:02:27 -07001691 LogReader full_reader(SortParts(filenames));
1692 LogReader single_node_reader(SortParts(filenames));
Naman Guptaa63aa132023-03-22 20:06:34 -07001693
1694 SimulatedEventLoopFactory full_factory(full_reader.configuration());
1695 SimulatedEventLoopFactory single_node_factory(
1696 single_node_reader.configuration());
1697 single_node_factory.SkipTimingReport();
1698 single_node_factory.DisableStatistics();
1699 std::unique_ptr<EventLoop> replay_event_loop =
1700 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
1701 "log_reader");
1702
1703 full_reader.Register(&full_factory);
1704 single_node_reader.Register(replay_event_loop.get());
1705
1706 const Node *full_pi1 =
1707 configuration::GetNode(full_factory.configuration(), "pi1");
1708
1709 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1710 // else should have moved.
1711 std::unique_ptr<EventLoop> full_event_loop =
1712 full_factory.MakeEventLoop("test", full_pi1);
1713 full_event_loop->SkipTimingReport();
1714 full_event_loop->SkipAosLog();
1715 // maps are indexed on channel index.
1716 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
1717 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
1718 observed_messages;
1719 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
1720 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
1721 ++ii) {
1722 const Channel *channel =
1723 full_event_loop->configuration()->channels()->Get(ii);
1724 // We currently don't support replaying remote timestamp channels in
1725 // realtime replay (unless the remote timestamp channel was not NOT_LOGGED,
1726 // in which case it gets auto-remapped and replayed on a /original channel).
1727 if (channel->name()->string_view().find("remote_timestamp") !=
1728 std::string_view::npos &&
1729 channel->name()->string_view().find("/original") ==
1730 std::string_view::npos) {
1731 continue;
1732 }
1733 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
1734 observed_messages[ii] = {};
1735 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
1736 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
1737 if (fetchers[ii]->Fetch()) {
1738 observed_messages[ii].push_back(std::make_pair(
1739 fetchers[ii]->context().monotonic_event_time, true));
1740 }
1741 });
1742 full_event_loop->MakeRawNoArgWatcher(
1743 channel, [ii, &observed_messages](const Context &context) {
1744 observed_messages[ii].push_back(
1745 std::make_pair(context.monotonic_event_time, false));
1746 });
1747 }
1748 }
1749
1750 full_factory.Run();
1751 fetchers.clear();
1752 full_reader.Deregister();
1753
1754 const Node *single_node_pi1 =
1755 configuration::GetNode(single_node_factory.configuration(), "pi1");
1756 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
1757
1758 std::unique_ptr<EventLoop> single_node_event_loop =
1759 single_node_factory.MakeEventLoop("test", single_node_pi1);
1760 single_node_event_loop->SkipTimingReport();
1761 single_node_event_loop->SkipAosLog();
1762 for (size_t ii = 0;
1763 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
1764 const Channel *channel =
1765 single_node_event_loop->configuration()->channels()->Get(ii);
1766 single_node_factory.DisableForwarding(channel);
1767 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
1768 single_node_fetchers[ii] =
1769 single_node_event_loop->MakeRawFetcher(channel);
1770 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
1771 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
1772 << "Single EventLoop replay doesn't support pre-loading fetchers. "
1773 << configuration::StrippedChannelToString(channel);
1774 });
1775 single_node_event_loop->MakeRawNoArgWatcher(
1776 channel, [ii, &observed_messages, channel,
1777 kStartupDelay](const Context &context) {
1778 if (observed_messages[ii].empty()) {
1779 FAIL() << "Observed extra message at "
1780 << context.monotonic_event_time << " on "
1781 << configuration::StrippedChannelToString(channel);
1782 return;
1783 }
1784 const std::pair<monotonic_clock::time_point, bool> &message =
1785 observed_messages[ii].front();
1786 if (message.second) {
1787 EXPECT_LE(message.first,
1788 context.monotonic_event_time + kStartupDelay)
1789 << "Mismatched message times " << context.monotonic_event_time
1790 << " and " << message.first << " on "
1791 << configuration::StrippedChannelToString(channel);
1792 } else {
1793 EXPECT_EQ(message.first,
1794 context.monotonic_event_time + kStartupDelay)
1795 << "Mismatched message times " << context.monotonic_event_time
1796 << " and " << message.first << " on "
1797 << configuration::StrippedChannelToString(channel);
1798 }
1799 observed_messages[ii].erase(observed_messages[ii].begin());
1800 });
1801 }
1802 }
1803
1804 single_node_factory.Run();
1805
1806 single_node_fetchers.clear();
1807
1808 single_node_reader.Deregister();
1809
1810 for (const auto &pair : observed_messages) {
1811 EXPECT_TRUE(pair.second.empty())
1812 << "Missed " << pair.second.size() << " messages on "
1813 << configuration::StrippedChannelToString(
1814 single_node_event_loop->configuration()->channels()->Get(
1815 pair.first));
1816 }
1817}
1818
1819// Tests that we properly recreate forwarded timestamps when replaying a log.
1820// This should be enough that we can then re-run the logger and get a valid log
1821// back.
1822TEST_P(MultinodeLoggerTest, MessageHeader) {
1823 time_converter_.StartEqual();
1824 {
1825 LoggerState pi1_logger = MakeLogger(pi1_);
1826 LoggerState pi2_logger = MakeLogger(pi2_);
1827
1828 event_loop_factory_.RunFor(chrono::milliseconds(95));
1829
1830 StartLogger(&pi1_logger);
1831 StartLogger(&pi2_logger);
1832
1833 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1834 }
1835
1836 LogReader reader(SortParts(logfiles_));
1837
1838 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1839 log_reader_factory.set_send_delay(chrono::microseconds(0));
1840
1841 // This sends out the fetched messages and advances time to the start of the
1842 // log file.
1843 reader.Register(&log_reader_factory);
1844
1845 const Node *pi1 =
1846 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1847 const Node *pi2 =
1848 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1849
1850 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1851 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1852 LOG(INFO) << "now pi1 "
1853 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1854 LOG(INFO) << "now pi2 "
1855 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1856
1857 EXPECT_THAT(reader.LoggedNodes(),
1858 ::testing::ElementsAre(
1859 configuration::GetNode(reader.logged_configuration(), pi1),
1860 configuration::GetNode(reader.logged_configuration(), pi2)));
1861
1862 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1863
1864 std::unique_ptr<EventLoop> pi1_event_loop =
1865 log_reader_factory.MakeEventLoop("test", pi1);
1866 std::unique_ptr<EventLoop> pi2_event_loop =
1867 log_reader_factory.MakeEventLoop("test", pi2);
1868
1869 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1870 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1871 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1872 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1873
1874 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1875 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1876 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1877 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1878
1879 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1880 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1881 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1882 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1883
1884 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1885 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1886 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1887 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1888
1889 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1890 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1891 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1892 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1893
1894 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1895 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1896 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1897 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1898
1899 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
1900 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
1901
1902 for (std::pair<int, std::string> channel :
1903 shared()
1904 ? std::vector<
1905 std::pair<int, std::string>>{{-1,
1906 "/aos/remote_timestamps/pi2"}}
1907 : std::vector<std::pair<int, std::string>>{
1908 {pi1_timestamp_channel,
1909 "/aos/remote_timestamps/pi2/pi1/aos/"
1910 "aos-message_bridge-Timestamp"},
1911 {ping_timestamp_channel,
1912 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1913 pi1_event_loop->MakeWatcher(
1914 channel.second,
1915 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1916 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1917 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1918 &ping_on_pi2_fetcher, network_delay, send_delay,
1919 channel_index = channel.first](const RemoteMessage &header) {
1920 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1921 chrono::nanoseconds(header.monotonic_sent_time()));
1922 const aos::realtime_clock::time_point header_realtime_sent_time(
1923 chrono::nanoseconds(header.realtime_sent_time()));
1924 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1925 chrono::nanoseconds(header.monotonic_remote_time()));
Austin Schuhb5224ec2024-03-27 15:20:09 -07001926 const aos::monotonic_clock::time_point
1927 header_monotonic_remote_transmit_time(
1928 chrono::nanoseconds(header.monotonic_remote_transmit_time()));
Naman Guptaa63aa132023-03-22 20:06:34 -07001929 const aos::realtime_clock::time_point header_realtime_remote_time(
1930 chrono::nanoseconds(header.realtime_remote_time()));
1931
1932 if (channel_index != -1) {
1933 ASSERT_EQ(channel_index, header.channel_index());
1934 }
1935
1936 const Context *pi1_context = nullptr;
1937 const Context *pi2_context = nullptr;
1938
1939 if (header.channel_index() == pi1_timestamp_channel) {
1940 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1941 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1942 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1943 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07001944 // Timestamps don't have wakeup delay, so they show back up after 2
1945 // times the network delay on the source node. Confirm that matches
1946 // when we are reading the log.
1947 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
1948 pi1_context->monotonic_event_time + 2 * network_delay);
Naman Guptaa63aa132023-03-22 20:06:34 -07001949 } else if (header.channel_index() == ping_timestamp_channel) {
1950 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1951 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1952 pi1_context = &ping_on_pi1_fetcher.context();
1953 pi2_context = &ping_on_pi2_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07001954 // Ping messages get picked up faster at the start of each message
1955 // when timers wake up. Verify all that behavior matches exactly as
1956 // expected when reading the log.
1957 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
1958 pi1_context->monotonic_event_time + 2 * network_delay +
1959 ((pi1_event_loop->context().monotonic_event_time -
1960 2 * network_delay)
1961 .time_since_epoch() %
1962 chrono::nanoseconds(1000000000) ==
1963 chrono::nanoseconds(0)
1964 ? chrono::nanoseconds(0)
1965 : send_delay));
Naman Guptaa63aa132023-03-22 20:06:34 -07001966 } else {
1967 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1968 << configuration::CleanedChannelToString(
1969 pi1_event_loop->configuration()->channels()->Get(
1970 header.channel_index()));
1971 }
1972
1973 ASSERT_TRUE(header.has_boot_uuid());
1974 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1975 pi2_event_loop->boot_uuid());
1976
1977 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1978 EXPECT_EQ(pi2_context->remote_queue_index,
1979 header.remote_queue_index());
1980 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
1981
1982 EXPECT_EQ(pi2_context->monotonic_event_time,
1983 header_monotonic_sent_time);
1984 EXPECT_EQ(pi2_context->realtime_event_time,
1985 header_realtime_sent_time);
1986 EXPECT_EQ(pi2_context->realtime_remote_time,
1987 header_realtime_remote_time);
1988 EXPECT_EQ(pi2_context->monotonic_remote_time,
1989 header_monotonic_remote_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -07001990 EXPECT_EQ(pi2_context->monotonic_remote_transmit_time,
1991 header_monotonic_remote_transmit_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07001992
1993 EXPECT_EQ(pi1_context->realtime_event_time,
1994 header_realtime_remote_time);
1995 EXPECT_EQ(pi1_context->monotonic_event_time,
1996 header_monotonic_remote_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07001997 });
1998 }
1999 for (std::pair<int, std::string> channel :
2000 shared()
2001 ? std::vector<
2002 std::pair<int, std::string>>{{-1,
2003 "/aos/remote_timestamps/pi1"}}
2004 : std::vector<std::pair<int, std::string>>{
2005 {pi2_timestamp_channel,
2006 "/aos/remote_timestamps/pi1/pi2/aos/"
2007 "aos-message_bridge-Timestamp"}}) {
2008 pi2_event_loop->MakeWatcher(
2009 channel.second,
2010 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2011 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2012 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2013 &pong_on_pi1_fetcher, network_delay, send_delay,
2014 channel_index = channel.first](const RemoteMessage &header) {
2015 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2016 chrono::nanoseconds(header.monotonic_sent_time()));
2017 const aos::realtime_clock::time_point header_realtime_sent_time(
2018 chrono::nanoseconds(header.realtime_sent_time()));
2019 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2020 chrono::nanoseconds(header.monotonic_remote_time()));
Austin Schuhb5224ec2024-03-27 15:20:09 -07002021 const aos::monotonic_clock::time_point
2022 header_monotonic_remote_transmit_time(
2023 chrono::nanoseconds(header.monotonic_remote_transmit_time()));
Naman Guptaa63aa132023-03-22 20:06:34 -07002024 const aos::realtime_clock::time_point header_realtime_remote_time(
2025 chrono::nanoseconds(header.realtime_remote_time()));
2026
2027 if (channel_index != -1) {
2028 ASSERT_EQ(channel_index, header.channel_index());
2029 }
2030
2031 const Context *pi2_context = nullptr;
2032 const Context *pi1_context = nullptr;
2033
2034 if (header.channel_index() == pi2_timestamp_channel) {
2035 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2036 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2037 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2038 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07002039 // Again, timestamps don't have wakeup delay, so they show back up
2040 // after 2 times the network delay on the source node.
2041 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2042 pi2_context->monotonic_event_time + 2 * network_delay);
Naman Guptaa63aa132023-03-22 20:06:34 -07002043 } else if (header.channel_index() == pong_timestamp_channel) {
2044 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2045 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2046 pi2_context = &pong_on_pi2_fetcher.context();
2047 pi1_context = &pong_on_pi1_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07002048 // And Pong messages come back repeatably since they aren't at the
2049 // start of a second.
2050 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2051 pi2_context->monotonic_event_time + 2 * network_delay +
2052 send_delay);
Naman Guptaa63aa132023-03-22 20:06:34 -07002053 } else {
2054 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2055 << configuration::CleanedChannelToString(
2056 pi2_event_loop->configuration()->channels()->Get(
2057 header.channel_index()));
2058 }
2059
2060 ASSERT_TRUE(header.has_boot_uuid());
2061 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2062 pi1_event_loop->boot_uuid());
2063
2064 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2065 EXPECT_EQ(pi1_context->remote_queue_index,
2066 header.remote_queue_index());
2067 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
2068
2069 EXPECT_EQ(pi1_context->monotonic_event_time,
2070 header_monotonic_sent_time);
2071 EXPECT_EQ(pi1_context->realtime_event_time,
2072 header_realtime_sent_time);
2073 EXPECT_EQ(pi1_context->realtime_remote_time,
2074 header_realtime_remote_time);
2075 EXPECT_EQ(pi1_context->monotonic_remote_time,
2076 header_monotonic_remote_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -07002077 EXPECT_EQ(pi1_context->monotonic_remote_transmit_time,
2078 header_monotonic_remote_transmit_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07002079
2080 EXPECT_EQ(pi2_context->realtime_event_time,
2081 header_realtime_remote_time);
2082 EXPECT_EQ(pi2_context->monotonic_event_time,
2083 header_monotonic_remote_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07002084 });
2085 }
2086
2087 // And confirm we can re-create a log again, while checking the contents.
2088 {
2089 LoggerState pi1_logger = MakeLogger(
2090 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
2091 LoggerState pi2_logger = MakeLogger(
2092 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
2093
Austin Schuh8fb4b452023-08-04 17:02:27 -07002094 StartLogger(&pi1_logger, tmp_dir_ + "/logs/relogged1");
2095 StartLogger(&pi2_logger, tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07002096
2097 log_reader_factory.Run();
2098 }
2099
2100 reader.Deregister();
2101
2102 // And verify that we can run the LogReader over the relogged files without
2103 // hitting any fatal errors.
2104 {
Austin Schuh8fb4b452023-08-04 17:02:27 -07002105 LogReader relogged_reader(SortParts(
2106 MakeLogFiles(tmp_dir_ + "/logs/relogged1", tmp_dir_ + "/logs/relogged2",
2107 1, 1, 2, 2, true)));
Naman Guptaa63aa132023-03-22 20:06:34 -07002108 relogged_reader.Register();
2109
2110 relogged_reader.event_loop_factory()->Run();
2111 }
2112 // And confirm that we can read the logged file using the reader's
2113 // configuration.
2114 {
2115 LogReader relogged_reader(
Austin Schuh8fb4b452023-08-04 17:02:27 -07002116 SortParts(MakeLogFiles(tmp_dir_ + "/logs/relogged1",
2117 tmp_dir_ + "/logs/relogged2", 1, 1, 2, 2, true)),
Naman Guptaa63aa132023-03-22 20:06:34 -07002118 reader.configuration());
2119 relogged_reader.Register();
2120
2121 relogged_reader.event_loop_factory()->Run();
2122 }
2123}
2124
2125// Tests that we properly populate and extract the logger_start time by setting
2126// up a clock difference between 2 nodes and looking at the resulting parts.
2127TEST_P(MultinodeLoggerTest, LoggerStartTime) {
2128 std::vector<std::string> actual_filenames;
2129 time_converter_.AddMonotonic(
2130 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2131 {
2132 LoggerState pi1_logger = MakeLogger(pi1_);
2133 LoggerState pi2_logger = MakeLogger(pi2_);
2134
2135 StartLogger(&pi1_logger);
2136 StartLogger(&pi2_logger);
2137
2138 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2139
2140 pi1_logger.AppendAllFilenames(&actual_filenames);
2141 pi2_logger.AppendAllFilenames(&actual_filenames);
2142 }
2143
2144 ASSERT_THAT(actual_filenames,
2145 ::testing::UnorderedElementsAreArray(logfiles_));
2146
Austin Schuh8fb4b452023-08-04 17:02:27 -07002147 for (const LogFile &log_file : SortParts(actual_filenames)) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002148 for (const LogParts &log_part : log_file.parts) {
2149 if (log_part.node == log_file.logger_node) {
2150 EXPECT_EQ(log_part.logger_monotonic_start_time,
2151 aos::monotonic_clock::min_time);
2152 EXPECT_EQ(log_part.logger_realtime_start_time,
2153 aos::realtime_clock::min_time);
2154 } else {
2155 const chrono::seconds offset = log_file.logger_node == "pi1"
2156 ? -chrono::seconds(1000)
2157 : chrono::seconds(1000);
2158 EXPECT_EQ(log_part.logger_monotonic_start_time,
2159 log_part.monotonic_start_time + offset);
2160 EXPECT_EQ(log_part.logger_realtime_start_time,
2161 log_file.realtime_start_time +
2162 (log_part.logger_monotonic_start_time -
2163 log_file.monotonic_start_time));
2164 }
2165 }
2166 }
2167}
2168
2169// Test that renaming the base, renames the folder.
2170TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002171 time_converter_.AddMonotonic(
2172 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002173 logfile_base1_ = tmp_dir_ + "/logs/renamefolder/multi_logfile1";
2174 logfile_base2_ = tmp_dir_ + "/logs/renamefolder/multi_logfile2";
2175
Naman Guptaa63aa132023-03-22 20:06:34 -07002176 LoggerState pi1_logger = MakeLogger(pi1_);
2177 LoggerState pi2_logger = MakeLogger(pi2_);
2178
2179 StartLogger(&pi1_logger);
2180 StartLogger(&pi2_logger);
2181
2182 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002183 logfile_base1_ = tmp_dir_ + "/logs/new-good/multi_logfile1";
2184 logfile_base2_ = tmp_dir_ + "/logs/new-good/multi_logfile2";
Naman Guptaa63aa132023-03-22 20:06:34 -07002185 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
Alexei Strotscaf17d32023-04-03 22:31:11 -07002186
2187 // Sequence of set_base_name and Rotate simulates rename operation. Since
2188 // rename is not supported by all namers, RenameLogBase moved from logger to
2189 // the higher level abstraction, yet log_namers support rename, and it is
2190 // legal to test it here.
2191 pi1_logger.log_namer->set_base_name(logfile_base1_);
2192 pi1_logger.logger->Rotate();
2193 pi2_logger.log_namer->set_base_name(logfile_base2_);
2194 pi2_logger.logger->Rotate();
2195
Naman Guptaa63aa132023-03-22 20:06:34 -07002196 for (auto &file : logfiles_) {
2197 struct stat s;
2198 EXPECT_EQ(0, stat(file.c_str(), &s));
2199 }
2200}
2201
2202// Test that renaming the file base dies.
2203TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2204 time_converter_.AddMonotonic(
2205 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002206 logfile_base1_ = tmp_dir_ + "/logs/renamefile/multi_logfile1";
2207 logfile_base2_ = tmp_dir_ + "/logs/renamefile/multi_logfile2";
2208
Naman Guptaa63aa132023-03-22 20:06:34 -07002209 LoggerState pi1_logger = MakeLogger(pi1_);
2210 StartLogger(&pi1_logger);
2211 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002212 logfile_base1_ = tmp_dir_ + "/logs/new-renamefile/new_multi_logfile1";
Alexei Strotscaf17d32023-04-03 22:31:11 -07002213 EXPECT_DEATH({ pi1_logger.log_namer->set_base_name(logfile_base1_); },
Naman Guptaa63aa132023-03-22 20:06:34 -07002214 "Rename of file base from");
2215}
2216
2217// TODO(austin): We can write a test which recreates a logfile and confirms that
2218// we get it back. That is the ultimate test.
2219
2220// Tests that we properly recreate forwarded timestamps when replaying a log.
2221// This should be enough that we can then re-run the logger and get a valid log
2222// back.
2223TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002224 if (file_strategy() == FileStrategy::kCombine) {
2225 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2226 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002227 std::vector<std::string> actual_filenames;
2228
2229 const UUID pi1_boot0 = UUID::Random();
2230 const UUID pi2_boot0 = UUID::Random();
2231 const UUID pi2_boot1 = UUID::Random();
2232 {
2233 CHECK_EQ(pi1_index_, 0u);
2234 CHECK_EQ(pi2_index_, 1u);
2235
2236 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2237 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2238 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2239
2240 time_converter_.AddNextTimestamp(
2241 distributed_clock::epoch(),
2242 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2243 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2244 time_converter_.AddNextTimestamp(
2245 distributed_clock::epoch() + reboot_time,
2246 {BootTimestamp::epoch() + reboot_time,
2247 BootTimestamp{
2248 .boot = 1,
2249 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2250 }
2251
2252 {
2253 LoggerState pi1_logger = MakeLogger(pi1_);
2254
2255 event_loop_factory_.RunFor(chrono::milliseconds(95));
2256 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2257 pi1_boot0);
2258 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2259 pi2_boot0);
2260
2261 StartLogger(&pi1_logger);
2262
2263 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2264
2265 VLOG(1) << "Reboot now!";
2266
2267 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2268 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2269 pi1_boot0);
2270 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2271 pi2_boot1);
2272
2273 pi1_logger.AppendAllFilenames(&actual_filenames);
2274 }
2275
2276 std::sort(actual_filenames.begin(), actual_filenames.end());
2277 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2278 ASSERT_THAT(actual_filenames,
2279 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2280
2281 // Confirm that our new oldest timestamps properly update as we reboot and
2282 // rotate.
2283 for (const std::string &file : pi1_reboot_logfiles_) {
2284 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2285 ReadHeader(file);
2286 CHECK(log_header);
2287 if (log_header->message().has_configuration()) {
2288 continue;
2289 }
2290
2291 const monotonic_clock::time_point monotonic_start_time =
2292 monotonic_clock::time_point(
2293 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2294 const UUID source_node_boot_uuid = UUID::FromString(
2295 log_header->message().source_node_boot_uuid()->string_view());
2296
2297 if (log_header->message().node()->name()->string_view() != "pi1") {
2298 // The remote message channel should rotate later and have more parts.
2299 // This only is true on the log files with shared remote messages.
2300 //
2301 // TODO(austin): I'm not the most thrilled with this test pattern... It
2302 // feels brittle in a different way.
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002303 if (file.find("timestamps/remote_pi2") == std::string::npos) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002304 switch (log_header->message().parts_index()) {
2305 case 0:
2306 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2307 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2308 break;
2309 case 1:
2310 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2311 ASSERT_EQ(monotonic_start_time,
2312 monotonic_clock::epoch() + chrono::seconds(1));
2313 break;
2314 case 2:
2315 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2316 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2317 break;
2318 case 3:
2319 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2320 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07002321 chrono::nanoseconds(2323000000))
Naman Guptaa63aa132023-03-22 20:06:34 -07002322 << " on " << file;
2323 break;
2324 default:
2325 FAIL();
2326 break;
2327 }
2328 } else {
2329 switch (log_header->message().parts_index()) {
2330 case 0:
2331 case 1:
2332 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2333 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2334 break;
2335 case 2:
2336 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2337 ASSERT_EQ(monotonic_start_time,
2338 monotonic_clock::epoch() + chrono::seconds(1));
2339 break;
2340 case 3:
2341 case 4:
2342 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2343 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2344 break;
2345 case 5:
2346 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2347 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07002348 chrono::nanoseconds(2323000000))
Naman Guptaa63aa132023-03-22 20:06:34 -07002349 << " on " << file;
2350 break;
2351 default:
2352 FAIL();
2353 break;
2354 }
2355 }
2356 continue;
2357 }
2358 SCOPED_TRACE(file);
2359 SCOPED_TRACE(aos::FlatbufferToJson(
2360 *log_header, {.multi_line = true, .max_vector_size = 100}));
2361 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2362 ASSERT_EQ(
2363 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2364 EXPECT_EQ(
2365 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2366 monotonic_clock::max_time.time_since_epoch().count());
2367 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2368 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2369 2u);
2370 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2371 monotonic_clock::max_time.time_since_epoch().count());
2372 ASSERT_TRUE(log_header->message()
2373 .has_oldest_remote_unreliable_monotonic_timestamps());
2374 ASSERT_EQ(log_header->message()
2375 .oldest_remote_unreliable_monotonic_timestamps()
2376 ->size(),
2377 2u);
2378 EXPECT_EQ(log_header->message()
2379 .oldest_remote_unreliable_monotonic_timestamps()
2380 ->Get(0),
2381 monotonic_clock::max_time.time_since_epoch().count());
2382 ASSERT_TRUE(log_header->message()
2383 .has_oldest_local_unreliable_monotonic_timestamps());
2384 ASSERT_EQ(log_header->message()
2385 .oldest_local_unreliable_monotonic_timestamps()
2386 ->size(),
2387 2u);
2388 EXPECT_EQ(log_header->message()
2389 .oldest_local_unreliable_monotonic_timestamps()
2390 ->Get(0),
2391 monotonic_clock::max_time.time_since_epoch().count());
2392
2393 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2394 monotonic_clock::time_point(chrono::nanoseconds(
2395 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2396 1)));
2397 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2398 monotonic_clock::time_point(chrono::nanoseconds(
2399 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2400 const monotonic_clock::time_point
2401 oldest_remote_unreliable_monotonic_timestamps =
2402 monotonic_clock::time_point(chrono::nanoseconds(
2403 log_header->message()
2404 .oldest_remote_unreliable_monotonic_timestamps()
2405 ->Get(1)));
2406 const monotonic_clock::time_point
2407 oldest_local_unreliable_monotonic_timestamps =
2408 monotonic_clock::time_point(chrono::nanoseconds(
2409 log_header->message()
2410 .oldest_local_unreliable_monotonic_timestamps()
2411 ->Get(1)));
2412 const monotonic_clock::time_point
Austin Schuhb5224ec2024-03-27 15:20:09 -07002413 oldest_remote_reliable_monotonic_transmit_timestamps =
2414 monotonic_clock::time_point(chrono::nanoseconds(
2415 log_header->message()
2416 .oldest_remote_reliable_monotonic_transmit_timestamps()
2417 ->Get(1)));
2418 const monotonic_clock::time_point
2419 oldest_local_reliable_monotonic_transmit_timestamps =
2420 monotonic_clock::time_point(chrono::nanoseconds(
2421 log_header->message()
2422 .oldest_local_reliable_monotonic_transmit_timestamps()
2423 ->Get(1)));
2424 const monotonic_clock::time_point
Naman Guptaa63aa132023-03-22 20:06:34 -07002425 oldest_remote_reliable_monotonic_timestamps =
2426 monotonic_clock::time_point(chrono::nanoseconds(
2427 log_header->message()
2428 .oldest_remote_reliable_monotonic_timestamps()
2429 ->Get(1)));
2430 const monotonic_clock::time_point
2431 oldest_local_reliable_monotonic_timestamps =
2432 monotonic_clock::time_point(chrono::nanoseconds(
2433 log_header->message()
2434 .oldest_local_reliable_monotonic_timestamps()
2435 ->Get(1)));
2436 const monotonic_clock::time_point
2437 oldest_logger_remote_unreliable_monotonic_timestamps =
2438 monotonic_clock::time_point(chrono::nanoseconds(
2439 log_header->message()
2440 .oldest_logger_remote_unreliable_monotonic_timestamps()
2441 ->Get(0)));
2442 const monotonic_clock::time_point
2443 oldest_logger_local_unreliable_monotonic_timestamps =
2444 monotonic_clock::time_point(chrono::nanoseconds(
2445 log_header->message()
2446 .oldest_logger_local_unreliable_monotonic_timestamps()
2447 ->Get(0)));
2448 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2449 monotonic_clock::max_time);
2450 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2451 monotonic_clock::max_time);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002452 if (log_header->message().data_stored()->Get(0) == StoredDataType::DATA) {
2453 switch (log_header->message().parts_index()) {
2454 case 0:
2455 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2456 monotonic_clock::max_time);
2457 EXPECT_EQ(oldest_local_monotonic_timestamps,
2458 monotonic_clock::max_time);
2459 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2460 monotonic_clock::max_time);
2461 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2462 monotonic_clock::max_time);
2463 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2464 monotonic_clock::max_time);
2465 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2466 monotonic_clock::max_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -07002467 EXPECT_EQ(oldest_remote_reliable_monotonic_transmit_timestamps,
2468 monotonic_clock::max_time);
2469 EXPECT_EQ(oldest_local_reliable_monotonic_transmit_timestamps,
2470 monotonic_clock::max_time);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002471 break;
2472 default:
2473 FAIL();
2474 break;
2475 }
2476 } else if (log_header->message().data_stored()->Get(0) ==
2477 StoredDataType::TIMESTAMPS) {
2478 switch (log_header->message().parts_index()) {
2479 case 0:
2480 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2481 monotonic_clock::time_point(chrono::microseconds(90200)));
2482 EXPECT_EQ(oldest_local_monotonic_timestamps,
2483 monotonic_clock::time_point(chrono::microseconds(90350)));
2484 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2485 monotonic_clock::time_point(chrono::microseconds(90200)));
2486 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2487 monotonic_clock::time_point(chrono::microseconds(90350)));
2488 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2489 monotonic_clock::max_time);
2490 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2491 monotonic_clock::max_time);
Austin Schuhb5224ec2024-03-27 15:20:09 -07002492 EXPECT_EQ(oldest_remote_reliable_monotonic_transmit_timestamps,
2493 monotonic_clock::time_point(chrono::microseconds(90250)));
2494 EXPECT_EQ(oldest_local_reliable_monotonic_transmit_timestamps,
2495 monotonic_clock::time_point(chrono::microseconds(90350)));
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002496 break;
2497 case 1:
2498 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2499 monotonic_clock::time_point(chrono::microseconds(90200)))
2500 << file;
2501 EXPECT_EQ(oldest_local_monotonic_timestamps,
2502 monotonic_clock::time_point(chrono::microseconds(90350)))
2503 << file;
2504 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2505 monotonic_clock::time_point(chrono::microseconds(90200)))
2506 << file;
2507 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2508 monotonic_clock::time_point(chrono::microseconds(90350)))
2509 << file;
2510 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2511 monotonic_clock::time_point(chrono::microseconds(100000)))
2512 << file;
2513 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Austin Schuhac6d89e2024-03-27 14:56:09 -07002514 monotonic_clock::time_point(chrono::microseconds(100100)))
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002515 << file;
Austin Schuhb5224ec2024-03-27 15:20:09 -07002516 EXPECT_EQ(oldest_remote_reliable_monotonic_transmit_timestamps,
2517 monotonic_clock::time_point(chrono::microseconds(90250)))
2518 << file;
2519 EXPECT_EQ(oldest_local_reliable_monotonic_transmit_timestamps,
2520 monotonic_clock::time_point(chrono::microseconds(90350)))
2521 << file;
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002522 break;
2523 case 2:
2524 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2525 monotonic_clock::time_point(chrono::milliseconds(1323) +
2526 chrono::microseconds(200)));
2527 EXPECT_EQ(
2528 oldest_local_monotonic_timestamps,
2529 monotonic_clock::time_point(chrono::microseconds(10100350)));
2530 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2531 monotonic_clock::time_point(chrono::milliseconds(1323) +
2532 chrono::microseconds(200)));
2533 EXPECT_EQ(
2534 oldest_local_unreliable_monotonic_timestamps,
2535 monotonic_clock::time_point(chrono::microseconds(10100350)));
2536 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2537 monotonic_clock::max_time)
2538 << file;
2539 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2540 monotonic_clock::max_time)
2541 << file;
Austin Schuhb5224ec2024-03-27 15:20:09 -07002542 EXPECT_EQ(oldest_remote_reliable_monotonic_transmit_timestamps,
2543 monotonic_clock::time_point(chrono::milliseconds(1323) +
2544 chrono::microseconds(250)))
2545 << file;
2546 EXPECT_EQ(oldest_local_reliable_monotonic_transmit_timestamps,
2547 monotonic_clock::time_point(chrono::microseconds(10100350)))
2548 << file;
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002549 break;
2550 case 3:
2551 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2552 monotonic_clock::time_point(chrono::milliseconds(1323) +
2553 chrono::microseconds(200)));
2554 EXPECT_EQ(
2555 oldest_local_monotonic_timestamps,
2556 monotonic_clock::time_point(chrono::microseconds(10100350)));
2557 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2558 monotonic_clock::time_point(chrono::milliseconds(1323) +
2559 chrono::microseconds(200)));
2560 EXPECT_EQ(
2561 oldest_local_unreliable_monotonic_timestamps,
2562 monotonic_clock::time_point(chrono::microseconds(10100350)));
2563 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2564 monotonic_clock::time_point(chrono::microseconds(1423000)))
2565 << file;
2566 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Austin Schuhac6d89e2024-03-27 14:56:09 -07002567 monotonic_clock::time_point(chrono::microseconds(10200100)))
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002568 << file;
Austin Schuhb5224ec2024-03-27 15:20:09 -07002569 EXPECT_EQ(oldest_remote_reliable_monotonic_transmit_timestamps,
2570 monotonic_clock::time_point(chrono::milliseconds(1323) +
2571 chrono::microseconds(250)))
2572 << file;
2573 EXPECT_EQ(oldest_local_reliable_monotonic_transmit_timestamps,
2574 monotonic_clock::time_point(chrono::microseconds(10100350)))
2575 << file;
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002576 break;
2577 default:
2578 FAIL();
2579 break;
2580 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002581 }
2582 }
2583
2584 // Confirm that we refuse to replay logs with missing boot uuids.
2585 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07002586 auto sorted_parts = SortParts(pi1_reboot_logfiles_);
2587 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
2588 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07002589
2590 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2591 log_reader_factory.set_send_delay(chrono::microseconds(0));
2592
2593 // This sends out the fetched messages and advances time to the start of
2594 // the log file.
2595 reader.Register(&log_reader_factory);
2596
2597 log_reader_factory.Run();
2598
2599 reader.Deregister();
2600 }
2601}
2602
2603// Tests that we can sort a log which only has timestamps from the remote
2604// because the local message_bridge_client failed to connect.
2605TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002606 if (file_strategy() == FileStrategy::kCombine) {
2607 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2608 }
2609
Naman Guptaa63aa132023-03-22 20:06:34 -07002610 const UUID pi1_boot0 = UUID::Random();
2611 const UUID pi2_boot0 = UUID::Random();
2612 const UUID pi2_boot1 = UUID::Random();
2613 {
2614 CHECK_EQ(pi1_index_, 0u);
2615 CHECK_EQ(pi2_index_, 1u);
2616
2617 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2618 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2619 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2620
2621 time_converter_.AddNextTimestamp(
2622 distributed_clock::epoch(),
2623 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2624 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2625 time_converter_.AddNextTimestamp(
2626 distributed_clock::epoch() + reboot_time,
2627 {BootTimestamp::epoch() + reboot_time,
2628 BootTimestamp{
2629 .boot = 1,
2630 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2631 }
2632 pi2_->Disconnect(pi1_->node());
2633
2634 std::vector<std::string> filenames;
2635 {
2636 LoggerState pi1_logger = MakeLogger(pi1_);
2637
2638 event_loop_factory_.RunFor(chrono::milliseconds(95));
2639 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2640 pi1_boot0);
2641 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2642 pi2_boot0);
2643
2644 StartLogger(&pi1_logger);
2645
2646 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2647
2648 VLOG(1) << "Reboot now!";
2649
2650 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2651 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2652 pi1_boot0);
2653 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2654 pi2_boot1);
2655 pi1_logger.AppendAllFilenames(&filenames);
2656 }
2657
2658 std::sort(filenames.begin(), filenames.end());
2659
2660 // Confirm that our new oldest timestamps properly update as we reboot and
2661 // rotate.
2662 size_t timestamp_file_count = 0;
2663 for (const std::string &file : filenames) {
2664 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2665 ReadHeader(file);
2666 CHECK(log_header);
2667
2668 if (log_header->message().has_configuration()) {
2669 continue;
2670 }
2671
2672 const monotonic_clock::time_point monotonic_start_time =
2673 monotonic_clock::time_point(
2674 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2675 const UUID source_node_boot_uuid = UUID::FromString(
2676 log_header->message().source_node_boot_uuid()->string_view());
2677
2678 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2679 ASSERT_EQ(
2680 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2681 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2682 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2683 2u);
2684 ASSERT_TRUE(log_header->message()
2685 .has_oldest_remote_unreliable_monotonic_timestamps());
2686 ASSERT_EQ(log_header->message()
2687 .oldest_remote_unreliable_monotonic_timestamps()
2688 ->size(),
2689 2u);
2690 ASSERT_TRUE(log_header->message()
2691 .has_oldest_local_unreliable_monotonic_timestamps());
2692 ASSERT_EQ(log_header->message()
2693 .oldest_local_unreliable_monotonic_timestamps()
2694 ->size(),
2695 2u);
2696 ASSERT_TRUE(log_header->message()
2697 .has_oldest_remote_reliable_monotonic_timestamps());
2698 ASSERT_EQ(log_header->message()
2699 .oldest_remote_reliable_monotonic_timestamps()
2700 ->size(),
2701 2u);
2702 ASSERT_TRUE(
2703 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
2704 ASSERT_EQ(log_header->message()
2705 .oldest_local_reliable_monotonic_timestamps()
2706 ->size(),
2707 2u);
2708
2709 ASSERT_TRUE(
2710 log_header->message()
2711 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
2712 ASSERT_EQ(log_header->message()
2713 .oldest_logger_remote_unreliable_monotonic_timestamps()
2714 ->size(),
2715 2u);
2716 ASSERT_TRUE(log_header->message()
2717 .has_oldest_logger_local_unreliable_monotonic_timestamps());
2718 ASSERT_EQ(log_header->message()
2719 .oldest_logger_local_unreliable_monotonic_timestamps()
2720 ->size(),
2721 2u);
2722
2723 if (log_header->message().node()->name()->string_view() != "pi1") {
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002724 ASSERT_TRUE(file.find("timestamps/remote_pi2") != std::string::npos);
Naman Guptaa63aa132023-03-22 20:06:34 -07002725
2726 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2727 ReadNthMessage(file, 0);
2728 CHECK(msg);
2729
2730 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2731 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2732
2733 const monotonic_clock::time_point
2734 expected_oldest_local_monotonic_timestamps(
2735 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2736 const monotonic_clock::time_point
2737 expected_oldest_remote_monotonic_timestamps(
2738 chrono::nanoseconds(msg->message().monotonic_remote_time()));
2739 const monotonic_clock::time_point
2740 expected_oldest_timestamp_monotonic_timestamps(
2741 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
2742
2743 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2744 monotonic_clock::min_time);
2745 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2746 monotonic_clock::min_time);
2747 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
2748 monotonic_clock::min_time);
2749
2750 ++timestamp_file_count;
2751 // Since the log file is from the perspective of the other node,
2752 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2753 monotonic_clock::time_point(chrono::nanoseconds(
2754 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2755 0)));
2756 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2757 monotonic_clock::time_point(chrono::nanoseconds(
2758 log_header->message().oldest_local_monotonic_timestamps()->Get(
2759 0)));
2760 const monotonic_clock::time_point
2761 oldest_remote_unreliable_monotonic_timestamps =
2762 monotonic_clock::time_point(chrono::nanoseconds(
2763 log_header->message()
2764 .oldest_remote_unreliable_monotonic_timestamps()
2765 ->Get(0)));
2766 const monotonic_clock::time_point
2767 oldest_local_unreliable_monotonic_timestamps =
2768 monotonic_clock::time_point(chrono::nanoseconds(
2769 log_header->message()
2770 .oldest_local_unreliable_monotonic_timestamps()
2771 ->Get(0)));
2772 const monotonic_clock::time_point
2773 oldest_remote_reliable_monotonic_timestamps =
2774 monotonic_clock::time_point(chrono::nanoseconds(
2775 log_header->message()
2776 .oldest_remote_reliable_monotonic_timestamps()
2777 ->Get(0)));
2778 const monotonic_clock::time_point
2779 oldest_local_reliable_monotonic_timestamps =
2780 monotonic_clock::time_point(chrono::nanoseconds(
2781 log_header->message()
2782 .oldest_local_reliable_monotonic_timestamps()
2783 ->Get(0)));
2784 const monotonic_clock::time_point
2785 oldest_logger_remote_unreliable_monotonic_timestamps =
2786 monotonic_clock::time_point(chrono::nanoseconds(
2787 log_header->message()
2788 .oldest_logger_remote_unreliable_monotonic_timestamps()
2789 ->Get(1)));
2790 const monotonic_clock::time_point
2791 oldest_logger_local_unreliable_monotonic_timestamps =
2792 monotonic_clock::time_point(chrono::nanoseconds(
2793 log_header->message()
2794 .oldest_logger_local_unreliable_monotonic_timestamps()
2795 ->Get(1)));
2796
2797 const Channel *channel =
2798 event_loop_factory_.configuration()->channels()->Get(
2799 msg->message().channel_index());
2800 const Connection *connection = configuration::ConnectionToNode(
2801 channel, configuration::GetNode(
2802 event_loop_factory_.configuration(),
2803 log_header->message().node()->name()->string_view()));
2804
2805 const bool reliable = connection->time_to_live() == 0;
2806
2807 SCOPED_TRACE(file);
2808 SCOPED_TRACE(aos::FlatbufferToJson(
2809 *log_header, {.multi_line = true, .max_vector_size = 100}));
2810
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002811 // Confirm that the oldest timestamps match what we expect. Based on
2812 // what we are doing, we know that the oldest time is the first
2813 // message's time.
2814 //
2815 // This makes the test robust to both the split and combined config
2816 // tests.
2817 switch (log_header->message().parts_index()) {
2818 case 0:
2819 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2820 expected_oldest_remote_monotonic_timestamps);
2821 EXPECT_EQ(oldest_local_monotonic_timestamps,
2822 expected_oldest_local_monotonic_timestamps);
2823 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2824 expected_oldest_local_monotonic_timestamps)
2825 << file;
2826 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2827 expected_oldest_timestamp_monotonic_timestamps)
2828 << file;
2829
2830 if (reliable) {
2831 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002832 expected_oldest_remote_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002833 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002834 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002835 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2836 monotonic_clock::max_time);
2837 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2838 monotonic_clock::max_time);
2839 } else {
2840 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2841 monotonic_clock::max_time);
2842 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2843 monotonic_clock::max_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07002844 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2845 expected_oldest_remote_monotonic_timestamps);
2846 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2847 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002848 }
2849 break;
2850 case 1:
2851 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2852 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2853 EXPECT_EQ(oldest_local_monotonic_timestamps,
2854 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2855 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2856 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2857 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2858 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
2859 if (reliable) {
2860 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2861 expected_oldest_remote_monotonic_timestamps);
2862 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2863 expected_oldest_local_monotonic_timestamps);
2864 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2865 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2866 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2867 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2868 } else {
2869 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2870 monotonic_clock::max_time);
2871 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2872 monotonic_clock::max_time);
2873 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2874 expected_oldest_remote_monotonic_timestamps);
2875 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2876 expected_oldest_local_monotonic_timestamps);
2877 }
2878 break;
2879 case 2:
2880 EXPECT_EQ(
2881 oldest_remote_monotonic_timestamps,
2882 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2883 EXPECT_EQ(oldest_local_monotonic_timestamps,
2884 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2885 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2886 expected_oldest_local_monotonic_timestamps)
2887 << file;
2888 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2889 expected_oldest_timestamp_monotonic_timestamps)
2890 << file;
2891 if (reliable) {
2892 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2893 expected_oldest_remote_monotonic_timestamps);
2894 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2895 expected_oldest_local_monotonic_timestamps);
2896 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2897 monotonic_clock::max_time);
2898 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2899 monotonic_clock::max_time);
2900 } else {
2901 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2902 monotonic_clock::max_time);
2903 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2904 monotonic_clock::max_time);
2905 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2906 expected_oldest_remote_monotonic_timestamps);
2907 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2908 expected_oldest_local_monotonic_timestamps);
2909 }
2910 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002911
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002912 case 3:
2913 EXPECT_EQ(
2914 oldest_remote_monotonic_timestamps,
2915 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2916 EXPECT_EQ(oldest_local_monotonic_timestamps,
2917 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2918 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2919 expected_oldest_remote_monotonic_timestamps);
2920 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2921 expected_oldest_local_monotonic_timestamps);
2922 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2923 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2924 EXPECT_EQ(
2925 oldest_logger_local_unreliable_monotonic_timestamps,
2926 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
2927 break;
2928 default:
2929 FAIL();
2930 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002931 }
2932
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002933 switch (log_header->message().parts_index()) {
2934 case 0:
2935 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2936 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2937 break;
2938 case 1:
2939 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2940 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2941 break;
2942 case 2:
2943 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2944 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2945 break;
2946 case 3:
2947 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2948 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2949 break;
2950 [[fallthrough]];
2951 default:
2952 FAIL();
2953 break;
2954 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002955 continue;
2956 }
2957 EXPECT_EQ(
2958 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2959 monotonic_clock::max_time.time_since_epoch().count());
2960 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2961 monotonic_clock::max_time.time_since_epoch().count());
2962 EXPECT_EQ(log_header->message()
2963 .oldest_remote_unreliable_monotonic_timestamps()
2964 ->Get(0),
2965 monotonic_clock::max_time.time_since_epoch().count());
2966 EXPECT_EQ(log_header->message()
2967 .oldest_local_unreliable_monotonic_timestamps()
2968 ->Get(0),
2969 monotonic_clock::max_time.time_since_epoch().count());
2970
2971 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2972 monotonic_clock::time_point(chrono::nanoseconds(
2973 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2974 1)));
2975 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2976 monotonic_clock::time_point(chrono::nanoseconds(
2977 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2978 const monotonic_clock::time_point
2979 oldest_remote_unreliable_monotonic_timestamps =
2980 monotonic_clock::time_point(chrono::nanoseconds(
2981 log_header->message()
2982 .oldest_remote_unreliable_monotonic_timestamps()
2983 ->Get(1)));
2984 const monotonic_clock::time_point
2985 oldest_local_unreliable_monotonic_timestamps =
2986 monotonic_clock::time_point(chrono::nanoseconds(
2987 log_header->message()
2988 .oldest_local_unreliable_monotonic_timestamps()
2989 ->Get(1)));
2990 switch (log_header->message().parts_index()) {
2991 case 0:
2992 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2993 monotonic_clock::max_time);
2994 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2995 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2996 monotonic_clock::max_time);
2997 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2998 monotonic_clock::max_time);
2999 break;
3000 default:
3001 FAIL();
3002 break;
3003 }
3004 }
3005
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003006 EXPECT_EQ(timestamp_file_count, 4u);
Naman Guptaa63aa132023-03-22 20:06:34 -07003007
3008 // Confirm that we can actually sort the resulting log and read it.
3009 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003010 auto sorted_parts = SortParts(filenames);
3011 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3012 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003013
3014 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3015 log_reader_factory.set_send_delay(chrono::microseconds(0));
3016
3017 // This sends out the fetched messages and advances time to the start of
3018 // the log file.
3019 reader.Register(&log_reader_factory);
3020
3021 log_reader_factory.Run();
3022
3023 reader.Deregister();
3024 }
3025}
3026
3027// Tests that we properly handle one direction of message_bridge being
3028// unavailable.
3029TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07003030 std::vector<std::string> actual_filenames;
3031
Naman Guptaa63aa132023-03-22 20:06:34 -07003032 pi1_->Disconnect(pi2_->node());
3033 time_converter_.AddMonotonic(
3034 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3035
3036 time_converter_.AddMonotonic(
3037 {chrono::milliseconds(10000),
3038 chrono::milliseconds(10000) - chrono::milliseconds(1)});
3039 {
3040 LoggerState pi1_logger = MakeLogger(pi1_);
3041
3042 event_loop_factory_.RunFor(chrono::milliseconds(95));
3043
3044 StartLogger(&pi1_logger);
3045
3046 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07003047 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003048 }
3049
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003050 // Confirm that we can parse the result. LogReader has enough internal
3051 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07003052 ConfirmReadable(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003053}
3054
3055// Tests that we properly handle one direction of message_bridge being
3056// unavailable.
3057TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
3058 pi1_->Disconnect(pi2_->node());
3059 time_converter_.AddMonotonic(
3060 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
3061
3062 time_converter_.AddMonotonic(
3063 {chrono::milliseconds(10000),
3064 chrono::milliseconds(10000) + chrono::milliseconds(1)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07003065
3066 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07003067 {
3068 LoggerState pi1_logger = MakeLogger(pi1_);
3069
3070 event_loop_factory_.RunFor(chrono::milliseconds(95));
3071
3072 StartLogger(&pi1_logger);
3073
3074 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07003075 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003076 }
3077
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003078 // Confirm that we can parse the result. LogReader has enough internal
3079 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07003080 ConfirmReadable(filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003081}
3082
3083// Tests that we explode if someone passes in a part file twice with a better
3084// error than an out of order error.
3085TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3086 time_converter_.AddMonotonic(
3087 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07003088
3089 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07003090 {
3091 LoggerState pi1_logger = MakeLogger(pi1_);
3092
3093 event_loop_factory_.RunFor(chrono::milliseconds(95));
3094
3095 StartLogger(&pi1_logger);
3096
3097 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07003098
3099 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003100 }
3101
3102 std::vector<std::string> duplicates;
Austin Schuh8fb4b452023-08-04 17:02:27 -07003103 for (const std::string &f : filenames) {
Naman Guptaa63aa132023-03-22 20:06:34 -07003104 duplicates.emplace_back(f);
3105 duplicates.emplace_back(f);
3106 }
3107 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3108}
3109
3110// Tests that we explode if someone loses a part out of the middle of a log.
3111TEST_P(MultinodeLoggerTest, MissingPartsFromMiddle) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07003112 if (file_strategy() == FileStrategy::kCombine) {
3113 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
3114 }
Naman Guptaa63aa132023-03-22 20:06:34 -07003115 time_converter_.AddMonotonic(
3116 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3117 {
3118 LoggerState pi1_logger = MakeLogger(pi1_);
3119
3120 event_loop_factory_.RunFor(chrono::milliseconds(95));
3121
3122 StartLogger(&pi1_logger);
3123 aos::monotonic_clock::time_point last_rotation_time =
3124 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07003125 pi1_logger.logger->set_on_logged_period(
3126 [&](aos::monotonic_clock::time_point) {
3127 const auto now = pi1_logger.event_loop->monotonic_now();
3128 if (now > last_rotation_time + std::chrono::seconds(5)) {
3129 pi1_logger.logger->Rotate();
3130 last_rotation_time = now;
3131 }
3132 });
Naman Guptaa63aa132023-03-22 20:06:34 -07003133
3134 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3135 }
3136
3137 std::vector<std::string> missing_parts;
3138
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07003139 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part0" +
3140 Extension());
3141 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part2" +
3142 Extension());
Naman Guptaa63aa132023-03-22 20:06:34 -07003143 missing_parts.emplace_back(absl::StrCat(
3144 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
3145
3146 EXPECT_DEATH({ SortParts(missing_parts); },
3147 "Broken log, missing part files between");
3148}
3149
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003150// Tests that we properly handle a dead node. Do this by just disconnecting
3151// it and only using one nodes of logs.
Naman Guptaa63aa132023-03-22 20:06:34 -07003152TEST_P(MultinodeLoggerTest, DeadNode) {
3153 pi1_->Disconnect(pi2_->node());
3154 pi2_->Disconnect(pi1_->node());
3155 time_converter_.AddMonotonic(
3156 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3157 {
3158 LoggerState pi1_logger = MakeLogger(pi1_);
3159
3160 event_loop_factory_.RunFor(chrono::milliseconds(95));
3161
3162 StartLogger(&pi1_logger);
3163
3164 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3165 }
3166
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003167 // Confirm that we can parse the result. LogReader has enough internal
3168 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003169 ConfirmReadable(MakePi1DeadNodeLogfiles());
3170}
3171
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003172// Tests that we can relog with a different config. This makes most sense
3173// when you are trying to edit a log and want to use channel renaming + the
3174// original config in the new log.
Naman Guptaa63aa132023-03-22 20:06:34 -07003175TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3176 time_converter_.StartEqual();
3177 {
3178 LoggerState pi1_logger = MakeLogger(pi1_);
3179 LoggerState pi2_logger = MakeLogger(pi2_);
3180
3181 event_loop_factory_.RunFor(chrono::milliseconds(95));
3182
3183 StartLogger(&pi1_logger);
3184 StartLogger(&pi2_logger);
3185
3186 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3187 }
3188
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003189 auto sorted_parts = SortParts(logfiles_);
3190 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3191 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003192 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3193
3194 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3195 log_reader_factory.set_send_delay(chrono::microseconds(0));
3196
3197 // This sends out the fetched messages and advances time to the start of the
3198 // log file.
3199 reader.Register(&log_reader_factory);
3200
3201 const Node *pi1 =
3202 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3203 const Node *pi2 =
3204 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3205
3206 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3207 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3208 LOG(INFO) << "now pi1 "
3209 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3210 LOG(INFO) << "now pi2 "
3211 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3212
3213 EXPECT_THAT(reader.LoggedNodes(),
3214 ::testing::ElementsAre(
3215 configuration::GetNode(reader.logged_configuration(), pi1),
3216 configuration::GetNode(reader.logged_configuration(), pi2)));
3217
3218 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3219
3220 // And confirm we can re-create a log again, while checking the contents.
3221 std::vector<std::string> log_files;
3222 {
3223 LoggerState pi1_logger =
3224 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
3225 &log_reader_factory, reader.logged_configuration());
3226 LoggerState pi2_logger =
3227 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
3228 &log_reader_factory, reader.logged_configuration());
3229
Austin Schuh7e417682023-08-11 17:05:30 -07003230 pi1_logger.StartLogger(tmp_dir_ + "/logs/relogged1");
3231 pi2_logger.StartLogger(tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07003232
3233 log_reader_factory.Run();
3234
3235 for (auto &x : pi1_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003236 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged1_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003237 }
3238 for (auto &x : pi2_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003239 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged2_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003240 }
3241 }
3242
3243 reader.Deregister();
3244
3245 // And verify that we can run the LogReader over the relogged files without
3246 // hitting any fatal errors.
3247 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003248 auto sorted_parts = SortParts(log_files);
3249 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3250 LogReader relogged_reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003251 relogged_reader.Register();
3252
3253 relogged_reader.event_loop_factory()->Run();
3254 }
3255}
3256
Maxwell Gumley8c1b87f2024-02-13 17:54:52 -07003257// Tests that we can relog with a subset of the original config. This is useful
3258// for excluding obsolete or deprecated channels, so they don't appear in the
3259// configuration when reading the log.
3260TEST_P(MultinodeLoggerTest, LogPartialConfig) {
3261 time_converter_.StartEqual();
3262 {
3263 LoggerState pi1_logger = MakeLogger(pi1_);
3264 LoggerState pi2_logger = MakeLogger(pi2_);
3265
3266 event_loop_factory_.RunFor(chrono::milliseconds(95));
3267
3268 StartLogger(&pi1_logger);
3269 StartLogger(&pi2_logger);
3270
3271 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3272 }
3273
3274 auto sorted_parts = SortParts(logfiles_);
3275 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3276 LogReader reader(sorted_parts);
3277 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3278
3279 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3280 log_reader_factory.set_send_delay(chrono::microseconds(0));
3281
3282 // This sends out the fetched messages and advances time to the start of the
3283 // log file.
3284 reader.Register(&log_reader_factory);
3285
3286 const Node *pi1 =
3287 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3288 const Node *pi2 =
3289 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3290
3291 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3292 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3293 LOG(INFO) << "now pi1 "
3294 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3295 LOG(INFO) << "now pi2 "
3296 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3297
3298 EXPECT_THAT(reader.LoggedNodes(),
3299 ::testing::ElementsAre(
3300 configuration::GetNode(reader.logged_configuration(), pi1),
3301 configuration::GetNode(reader.logged_configuration(), pi2)));
3302
3303 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3304
3305 const FlatbufferDetachedBuffer<Configuration> partial_configuration_buffer =
3306 configuration::GetPartialConfiguration(
3307 *reader.event_loop_factory()->configuration(),
3308 [](const Channel &channel) {
3309 if (channel.name()->string_view().starts_with("/original/")) {
3310 LOG(INFO) << "Omitting channel from save_log, channel: "
3311 << channel.name()->string_view() << ", "
3312 << channel.type()->string_view();
3313 return false;
3314 }
3315 return true;
3316 });
3317
3318 // And confirm we can re-create a log again, while checking the contents.
3319 std::vector<std::string> log_files;
3320 {
3321 const Configuration *partial_configuration =
3322 &(partial_configuration_buffer.message());
3323
3324 LoggerState pi1_logger =
3325 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
3326 &log_reader_factory, partial_configuration);
3327 LoggerState pi2_logger =
3328 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
3329 &log_reader_factory, partial_configuration);
3330
3331 pi1_logger.StartLogger(tmp_dir_ + "/logs/relogged1");
3332 pi2_logger.StartLogger(tmp_dir_ + "/logs/relogged2");
3333
3334 log_reader_factory.Run();
3335
3336 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3337 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged1_", x));
3338 }
3339 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3340 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged2_", x));
3341 }
3342 }
3343
3344 reader.Deregister();
3345
3346 // And verify that we can run the LogReader over the relogged files without
3347 // hitting any fatal errors.
3348 {
3349 auto sorted_parts = SortParts(log_files);
3350 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3351 LogReader relogged_reader(sorted_parts);
3352 relogged_reader.Register();
3353
3354 relogged_reader.event_loop_factory()->Run();
3355 }
3356}
3357
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003358// Tests that we properly replay a log where the start time for a node is
3359// before any data on the node. This can happen if the logger starts before
3360// data is published. While the scenario below is a bit convoluted, we have
3361// seen logs like this generated out in the wild.
Naman Guptaa63aa132023-03-22 20:06:34 -07003362TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
Austin Schuh7e417682023-08-11 17:05:30 -07003363 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3364 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3365
Naman Guptaa63aa132023-03-22 20:06:34 -07003366 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3367 aos::configuration::ReadConfig(ArtifactPath(
3368 "aos/events/logging/multinode_pingpong_split3_config.json"));
3369 message_bridge::TestingTimeConverter time_converter(
3370 configuration::NodesCount(&config.message()));
3371 SimulatedEventLoopFactory event_loop_factory(&config.message());
3372 event_loop_factory.SetTimeConverter(&time_converter);
3373 NodeEventLoopFactory *const pi1 =
3374 event_loop_factory.GetNodeEventLoopFactory("pi1");
3375 const size_t pi1_index = configuration::GetNodeIndex(
3376 event_loop_factory.configuration(), pi1->node());
3377 NodeEventLoopFactory *const pi2 =
3378 event_loop_factory.GetNodeEventLoopFactory("pi2");
3379 const size_t pi2_index = configuration::GetNodeIndex(
3380 event_loop_factory.configuration(), pi2->node());
3381 NodeEventLoopFactory *const pi3 =
3382 event_loop_factory.GetNodeEventLoopFactory("pi3");
3383 const size_t pi3_index = configuration::GetNodeIndex(
3384 event_loop_factory.configuration(), pi3->node());
3385
3386 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003387 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003388 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003389 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003390 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003391 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003392 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003393 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
3394
Naman Guptaa63aa132023-03-22 20:06:34 -07003395 const UUID pi1_boot0 = UUID::Random();
3396 const UUID pi2_boot0 = UUID::Random();
3397 const UUID pi2_boot1 = UUID::Random();
3398 const UUID pi3_boot0 = UUID::Random();
3399 {
3400 CHECK_EQ(pi1_index, 0u);
3401 CHECK_EQ(pi2_index, 1u);
3402 CHECK_EQ(pi3_index, 2u);
3403
3404 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3405 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3406 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3407 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3408
3409 time_converter.AddNextTimestamp(
3410 distributed_clock::epoch(),
3411 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3412 BootTimestamp::epoch()});
3413 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3414 time_converter.AddNextTimestamp(
3415 distributed_clock::epoch() + reboot_time,
3416 {BootTimestamp::epoch() + reboot_time,
3417 BootTimestamp{
3418 .boot = 1,
3419 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3420 BootTimestamp::epoch() + reboot_time});
3421 }
3422
3423 // Make everything perfectly quiet.
3424 event_loop_factory.SkipTimingReport();
3425 event_loop_factory.DisableStatistics();
3426
3427 std::vector<std::string> filenames;
3428 {
3429 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003430 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3431 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003432 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003433 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3434 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003435 {
3436 // And now start the logger.
3437 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003438 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3439 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003440
3441 event_loop_factory.RunFor(chrono::milliseconds(1000));
3442
3443 pi1_logger.StartLogger(kLogfile1_1);
3444 pi3_logger.StartLogger(kLogfile3_1);
3445 pi2_logger.StartLogger(kLogfile2_1);
3446
3447 event_loop_factory.RunFor(chrono::milliseconds(10000));
3448
3449 // Now that we've got a start time in the past, turn on data.
3450 event_loop_factory.EnableStatistics();
3451 std::unique_ptr<aos::EventLoop> ping_event_loop =
3452 pi1->MakeEventLoop("ping");
3453 Ping ping(ping_event_loop.get());
3454
3455 pi2->AlwaysStart<Pong>("pong");
3456
3457 event_loop_factory.RunFor(chrono::milliseconds(3000));
3458
3459 pi2_logger.AppendAllFilenames(&filenames);
3460
3461 // Stop logging on pi2 before rebooting and completely shut off all
3462 // messages on pi2.
3463 pi2->DisableStatistics();
3464 pi1->Disconnect(pi2->node());
3465 pi2->Disconnect(pi1->node());
3466 }
3467 event_loop_factory.RunFor(chrono::milliseconds(7000));
3468 // pi2 now reboots.
3469 {
3470 event_loop_factory.RunFor(chrono::milliseconds(1000));
3471
3472 // Start logging again on pi2 after it is up.
3473 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003474 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3475 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003476 pi2_logger.StartLogger(kLogfile2_2);
3477
3478 event_loop_factory.RunFor(chrono::milliseconds(10000));
3479 // And, now that we have a start time in the log, turn data back on.
3480 pi2->EnableStatistics();
3481 pi1->Connect(pi2->node());
3482 pi2->Connect(pi1->node());
3483
3484 pi2->AlwaysStart<Pong>("pong");
3485 std::unique_ptr<aos::EventLoop> ping_event_loop =
3486 pi1->MakeEventLoop("ping");
3487 Ping ping(ping_event_loop.get());
3488
3489 event_loop_factory.RunFor(chrono::milliseconds(3000));
3490
3491 pi2_logger.AppendAllFilenames(&filenames);
3492 }
3493
3494 pi1_logger.AppendAllFilenames(&filenames);
3495 pi3_logger.AppendAllFilenames(&filenames);
3496 }
3497
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003498 // Confirm that we can parse the result. LogReader has enough internal
3499 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003500 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003501 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003502 auto result = ConfirmReadable(filenames);
3503 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3504 chrono::seconds(1)));
3505 EXPECT_THAT(result[0].second,
3506 ::testing::ElementsAre(realtime_clock::epoch() +
3507 chrono::microseconds(34990350)));
3508
3509 EXPECT_THAT(result[1].first,
3510 ::testing::ElementsAre(
3511 realtime_clock::epoch() + chrono::seconds(1),
3512 realtime_clock::epoch() + chrono::microseconds(3323000)));
3513 EXPECT_THAT(result[1].second,
3514 ::testing::ElementsAre(
3515 realtime_clock::epoch() + chrono::microseconds(13990200),
3516 realtime_clock::epoch() + chrono::microseconds(16313200)));
3517
3518 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3519 chrono::seconds(1)));
3520 EXPECT_THAT(result[2].second,
3521 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003522 chrono::microseconds(34900100)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003523}
3524
3525// Tests that local data before remote data after reboot is properly replayed.
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003526// We only trigger a reboot in the timestamp interpolation function when
3527// solving the timestamp problem when we actually have a point in the
3528// function. This originally only happened when a point passes the noncausal
3529// filter. At the start of time for the second boot, if we aren't careful, we
3530// will have messages which need to be published at times before the boot.
3531// This happens when a local message is in the log before a forwarded message,
3532// so there is no point in the interpolation function. This delays the
3533// reboot. So, we need to recreate that situation and make sure it doesn't
3534// come back.
Naman Guptaa63aa132023-03-22 20:06:34 -07003535TEST(MultinodeRebootLoggerTest,
3536 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003537 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3538 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3539
Naman Guptaa63aa132023-03-22 20:06:34 -07003540 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3541 aos::configuration::ReadConfig(ArtifactPath(
3542 "aos/events/logging/multinode_pingpong_split3_config.json"));
3543 message_bridge::TestingTimeConverter time_converter(
3544 configuration::NodesCount(&config.message()));
3545 SimulatedEventLoopFactory event_loop_factory(&config.message());
3546 event_loop_factory.SetTimeConverter(&time_converter);
3547 NodeEventLoopFactory *const pi1 =
3548 event_loop_factory.GetNodeEventLoopFactory("pi1");
3549 const size_t pi1_index = configuration::GetNodeIndex(
3550 event_loop_factory.configuration(), pi1->node());
3551 NodeEventLoopFactory *const pi2 =
3552 event_loop_factory.GetNodeEventLoopFactory("pi2");
3553 const size_t pi2_index = configuration::GetNodeIndex(
3554 event_loop_factory.configuration(), pi2->node());
3555 NodeEventLoopFactory *const pi3 =
3556 event_loop_factory.GetNodeEventLoopFactory("pi3");
3557 const size_t pi3_index = configuration::GetNodeIndex(
3558 event_loop_factory.configuration(), pi3->node());
3559
3560 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003561 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003562 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003563 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003564 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003565 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003566 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003567 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003568 const UUID pi1_boot0 = UUID::Random();
3569 const UUID pi2_boot0 = UUID::Random();
3570 const UUID pi2_boot1 = UUID::Random();
3571 const UUID pi3_boot0 = UUID::Random();
3572 {
3573 CHECK_EQ(pi1_index, 0u);
3574 CHECK_EQ(pi2_index, 1u);
3575 CHECK_EQ(pi3_index, 2u);
3576
3577 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3578 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3579 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3580 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3581
3582 time_converter.AddNextTimestamp(
3583 distributed_clock::epoch(),
3584 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3585 BootTimestamp::epoch()});
3586 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3587 time_converter.AddNextTimestamp(
3588 distributed_clock::epoch() + reboot_time,
3589 {BootTimestamp::epoch() + reboot_time,
3590 BootTimestamp{.boot = 1,
3591 .time = monotonic_clock::epoch() + reboot_time +
3592 chrono::seconds(100)},
3593 BootTimestamp::epoch() + reboot_time});
3594 }
3595
3596 std::vector<std::string> filenames;
3597 {
3598 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003599 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3600 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003601 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003602 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3603 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003604 {
3605 // And now start the logger.
3606 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003607 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3608 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003609
3610 pi1_logger.StartLogger(kLogfile1_1);
3611 pi3_logger.StartLogger(kLogfile3_1);
3612 pi2_logger.StartLogger(kLogfile2_1);
3613
3614 event_loop_factory.RunFor(chrono::milliseconds(1005));
3615
3616 // Now that we've got a start time in the past, turn on data.
3617 std::unique_ptr<aos::EventLoop> ping_event_loop =
3618 pi1->MakeEventLoop("ping");
3619 Ping ping(ping_event_loop.get());
3620
3621 pi2->AlwaysStart<Pong>("pong");
3622
3623 event_loop_factory.RunFor(chrono::milliseconds(3000));
3624
3625 pi2_logger.AppendAllFilenames(&filenames);
3626
3627 // Disable any remote messages on pi2.
3628 pi1->Disconnect(pi2->node());
3629 pi2->Disconnect(pi1->node());
3630 }
3631 event_loop_factory.RunFor(chrono::milliseconds(995));
3632 // pi2 now reboots at 5 seconds.
3633 {
3634 event_loop_factory.RunFor(chrono::milliseconds(1000));
3635
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003636 // Make local stuff happen before we start logging and connect the
3637 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003638 pi2->AlwaysStart<Pong>("pong");
3639 std::unique_ptr<aos::EventLoop> ping_event_loop =
3640 pi1->MakeEventLoop("ping");
3641 Ping ping(ping_event_loop.get());
3642 event_loop_factory.RunFor(chrono::milliseconds(1005));
3643
3644 // Start logging again on pi2 after it is up.
3645 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003646 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3647 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003648 pi2_logger.StartLogger(kLogfile2_2);
3649
3650 // And allow remote messages now that we have some local ones.
3651 pi1->Connect(pi2->node());
3652 pi2->Connect(pi1->node());
3653
3654 event_loop_factory.RunFor(chrono::milliseconds(1000));
3655
3656 event_loop_factory.RunFor(chrono::milliseconds(3000));
3657
3658 pi2_logger.AppendAllFilenames(&filenames);
3659 }
3660
3661 pi1_logger.AppendAllFilenames(&filenames);
3662 pi3_logger.AppendAllFilenames(&filenames);
3663 }
3664
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003665 // Confirm that we can parse the result. LogReader has enough internal
3666 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003667 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003668 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003669 auto result = ConfirmReadable(filenames);
3670
3671 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3672 EXPECT_THAT(result[0].second,
3673 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003674 chrono::microseconds(11000300)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003675
3676 EXPECT_THAT(result[1].first,
3677 ::testing::ElementsAre(
3678 realtime_clock::epoch(),
3679 realtime_clock::epoch() + chrono::microseconds(107005000)));
3680 EXPECT_THAT(result[1].second,
3681 ::testing::ElementsAre(
Austin Schuhac6d89e2024-03-27 14:56:09 -07003682 realtime_clock::epoch() + chrono::microseconds(4000100),
3683 realtime_clock::epoch() + chrono::microseconds(111000150)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003684
3685 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3686 EXPECT_THAT(result[2].second,
3687 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003688 chrono::microseconds(11000100)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003689
3690 auto start_stop_result = ConfirmReadable(
3691 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3692 realtime_clock::epoch() + chrono::milliseconds(3000));
3693
3694 EXPECT_THAT(
3695 start_stop_result[0].first,
3696 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3697 EXPECT_THAT(
3698 start_stop_result[0].second,
3699 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3700 EXPECT_THAT(
3701 start_stop_result[1].first,
3702 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3703 EXPECT_THAT(
3704 start_stop_result[1].second,
3705 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3706 EXPECT_THAT(
3707 start_stop_result[2].first,
3708 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3709 EXPECT_THAT(
3710 start_stop_result[2].second,
3711 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3712}
3713
3714// Tests that setting the start and stop flags across a reboot works as
3715// expected.
3716TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
Austin Schuh7e417682023-08-11 17:05:30 -07003717 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3718 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3719
Naman Guptaa63aa132023-03-22 20:06:34 -07003720 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3721 aos::configuration::ReadConfig(ArtifactPath(
3722 "aos/events/logging/multinode_pingpong_split3_config.json"));
3723 message_bridge::TestingTimeConverter time_converter(
3724 configuration::NodesCount(&config.message()));
3725 SimulatedEventLoopFactory event_loop_factory(&config.message());
3726 event_loop_factory.SetTimeConverter(&time_converter);
3727 NodeEventLoopFactory *const pi1 =
3728 event_loop_factory.GetNodeEventLoopFactory("pi1");
3729 const size_t pi1_index = configuration::GetNodeIndex(
3730 event_loop_factory.configuration(), pi1->node());
3731 NodeEventLoopFactory *const pi2 =
3732 event_loop_factory.GetNodeEventLoopFactory("pi2");
3733 const size_t pi2_index = configuration::GetNodeIndex(
3734 event_loop_factory.configuration(), pi2->node());
3735 NodeEventLoopFactory *const pi3 =
3736 event_loop_factory.GetNodeEventLoopFactory("pi3");
3737 const size_t pi3_index = configuration::GetNodeIndex(
3738 event_loop_factory.configuration(), pi3->node());
3739
3740 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003741 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003742 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003743 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003744 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003745 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003746 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003747 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003748 {
3749 CHECK_EQ(pi1_index, 0u);
3750 CHECK_EQ(pi2_index, 1u);
3751 CHECK_EQ(pi3_index, 2u);
3752
3753 time_converter.AddNextTimestamp(
3754 distributed_clock::epoch(),
3755 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3756 BootTimestamp::epoch()});
3757 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3758 time_converter.AddNextTimestamp(
3759 distributed_clock::epoch() + reboot_time,
3760 {BootTimestamp::epoch() + reboot_time,
3761 BootTimestamp{.boot = 1,
3762 .time = monotonic_clock::epoch() + reboot_time},
3763 BootTimestamp::epoch() + reboot_time});
3764 }
3765
3766 std::vector<std::string> filenames;
3767 {
3768 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003769 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3770 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003771 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003772 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3773 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003774 {
3775 // And now start the logger.
3776 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003777 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3778 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003779
3780 pi1_logger.StartLogger(kLogfile1_1);
3781 pi3_logger.StartLogger(kLogfile3_1);
3782 pi2_logger.StartLogger(kLogfile2_1);
3783
3784 event_loop_factory.RunFor(chrono::milliseconds(1005));
3785
3786 // Now that we've got a start time in the past, turn on data.
3787 std::unique_ptr<aos::EventLoop> ping_event_loop =
3788 pi1->MakeEventLoop("ping");
3789 Ping ping(ping_event_loop.get());
3790
3791 pi2->AlwaysStart<Pong>("pong");
3792
3793 event_loop_factory.RunFor(chrono::milliseconds(3000));
3794
3795 pi2_logger.AppendAllFilenames(&filenames);
3796 }
3797 event_loop_factory.RunFor(chrono::milliseconds(995));
3798 // pi2 now reboots at 5 seconds.
3799 {
3800 event_loop_factory.RunFor(chrono::milliseconds(1000));
3801
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003802 // Make local stuff happen before we start logging and connect the
3803 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003804 pi2->AlwaysStart<Pong>("pong");
3805 std::unique_ptr<aos::EventLoop> ping_event_loop =
3806 pi1->MakeEventLoop("ping");
3807 Ping ping(ping_event_loop.get());
3808 event_loop_factory.RunFor(chrono::milliseconds(5));
3809
3810 // Start logging again on pi2 after it is up.
3811 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003812 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3813 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003814 pi2_logger.StartLogger(kLogfile2_2);
3815
3816 event_loop_factory.RunFor(chrono::milliseconds(5000));
3817
3818 pi2_logger.AppendAllFilenames(&filenames);
3819 }
3820
3821 pi1_logger.AppendAllFilenames(&filenames);
3822 pi3_logger.AppendAllFilenames(&filenames);
3823 }
3824
3825 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003826 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003827 auto result = ConfirmReadable(filenames);
3828
3829 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3830 EXPECT_THAT(result[0].second,
3831 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003832 chrono::microseconds(11000300)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003833
3834 EXPECT_THAT(result[1].first,
3835 ::testing::ElementsAre(
3836 realtime_clock::epoch(),
3837 realtime_clock::epoch() + chrono::microseconds(6005000)));
3838 EXPECT_THAT(result[1].second,
3839 ::testing::ElementsAre(
Austin Schuhac6d89e2024-03-27 14:56:09 -07003840 realtime_clock::epoch() + chrono::microseconds(4900100),
3841 realtime_clock::epoch() + chrono::microseconds(11000150)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003842
3843 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3844 EXPECT_THAT(result[2].second,
3845 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003846 chrono::microseconds(11000100)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003847
3848 // Confirm we observed the correct start and stop times. We should see the
3849 // reboot here.
3850 auto start_stop_result = ConfirmReadable(
3851 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3852 realtime_clock::epoch() + chrono::milliseconds(8000));
3853
3854 EXPECT_THAT(
3855 start_stop_result[0].first,
3856 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3857 EXPECT_THAT(
3858 start_stop_result[0].second,
3859 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3860 EXPECT_THAT(start_stop_result[1].first,
3861 ::testing::ElementsAre(
3862 realtime_clock::epoch() + chrono::seconds(2),
3863 realtime_clock::epoch() + chrono::microseconds(6005000)));
3864 EXPECT_THAT(start_stop_result[1].second,
3865 ::testing::ElementsAre(
Austin Schuhac6d89e2024-03-27 14:56:09 -07003866 realtime_clock::epoch() + chrono::microseconds(4900100),
Naman Guptaa63aa132023-03-22 20:06:34 -07003867 realtime_clock::epoch() + chrono::seconds(8)));
3868 EXPECT_THAT(
3869 start_stop_result[2].first,
3870 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3871 EXPECT_THAT(
3872 start_stop_result[2].second,
3873 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3874}
3875
3876// Tests that we properly handle one direction being down.
3877TEST(MissingDirectionTest, OneDirection) {
Austin Schuh7e417682023-08-11 17:05:30 -07003878 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3879 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3880
Naman Guptaa63aa132023-03-22 20:06:34 -07003881 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3882 aos::configuration::ReadConfig(ArtifactPath(
3883 "aos/events/logging/multinode_pingpong_split4_config.json"));
3884 message_bridge::TestingTimeConverter time_converter(
3885 configuration::NodesCount(&config.message()));
3886 SimulatedEventLoopFactory event_loop_factory(&config.message());
3887 event_loop_factory.SetTimeConverter(&time_converter);
3888
3889 NodeEventLoopFactory *const pi1 =
3890 event_loop_factory.GetNodeEventLoopFactory("pi1");
3891 const size_t pi1_index = configuration::GetNodeIndex(
3892 event_loop_factory.configuration(), pi1->node());
3893 NodeEventLoopFactory *const pi2 =
3894 event_loop_factory.GetNodeEventLoopFactory("pi2");
3895 const size_t pi2_index = configuration::GetNodeIndex(
3896 event_loop_factory.configuration(), pi2->node());
3897 std::vector<std::string> filenames;
3898
3899 {
3900 CHECK_EQ(pi1_index, 0u);
3901 CHECK_EQ(pi2_index, 1u);
3902
3903 time_converter.AddNextTimestamp(
3904 distributed_clock::epoch(),
3905 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3906
3907 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3908 time_converter.AddNextTimestamp(
3909 distributed_clock::epoch() + reboot_time,
3910 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3911 BootTimestamp::epoch() + reboot_time});
3912 }
3913
3914 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003915 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003916 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003917 aos::testing::TestTmpDir() + "/logs/multi_logfile1.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003918
3919 pi2->Disconnect(pi1->node());
3920
3921 pi1->AlwaysStart<Ping>("ping");
3922 pi2->AlwaysStart<Pong>("pong");
3923
3924 {
3925 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003926 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3927 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003928
3929 event_loop_factory.RunFor(chrono::milliseconds(95));
3930
3931 pi2_logger.StartLogger(kLogfile2_1);
3932
3933 event_loop_factory.RunFor(chrono::milliseconds(6000));
3934
3935 pi2->Connect(pi1->node());
3936
3937 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003938 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3939 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003940 pi1_logger.StartLogger(kLogfile1_1);
3941
3942 event_loop_factory.RunFor(chrono::milliseconds(5000));
3943 pi1_logger.AppendAllFilenames(&filenames);
3944 pi2_logger.AppendAllFilenames(&filenames);
3945 }
3946
3947 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003948 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003949 ConfirmReadable(filenames);
3950}
3951
3952// Tests that we properly handle only one direction ever existing after a
3953// reboot.
3954TEST(MissingDirectionTest, OneDirectionAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003955 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3956 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3957
Naman Guptaa63aa132023-03-22 20:06:34 -07003958 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3959 aos::configuration::ReadConfig(ArtifactPath(
3960 "aos/events/logging/multinode_pingpong_split4_config.json"));
3961 message_bridge::TestingTimeConverter time_converter(
3962 configuration::NodesCount(&config.message()));
3963 SimulatedEventLoopFactory event_loop_factory(&config.message());
3964 event_loop_factory.SetTimeConverter(&time_converter);
3965
3966 NodeEventLoopFactory *const pi1 =
3967 event_loop_factory.GetNodeEventLoopFactory("pi1");
3968 const size_t pi1_index = configuration::GetNodeIndex(
3969 event_loop_factory.configuration(), pi1->node());
3970 NodeEventLoopFactory *const pi2 =
3971 event_loop_factory.GetNodeEventLoopFactory("pi2");
3972 const size_t pi2_index = configuration::GetNodeIndex(
3973 event_loop_factory.configuration(), pi2->node());
3974 std::vector<std::string> filenames;
3975
3976 {
3977 CHECK_EQ(pi1_index, 0u);
3978 CHECK_EQ(pi2_index, 1u);
3979
3980 time_converter.AddNextTimestamp(
3981 distributed_clock::epoch(),
3982 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3983
3984 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3985 time_converter.AddNextTimestamp(
3986 distributed_clock::epoch() + reboot_time,
3987 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3988 BootTimestamp::epoch() + reboot_time});
3989 }
3990
3991 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003992 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003993
3994 pi1->AlwaysStart<Ping>("ping");
3995
3996 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
3997 // makes it such that we will only get timestamps from pi1 -> pi2 on the
3998 // second boot.
3999 {
4000 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004001 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4002 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004003
4004 event_loop_factory.RunFor(chrono::milliseconds(95));
4005
4006 pi2_logger.StartLogger(kLogfile2_1);
4007
4008 event_loop_factory.RunFor(chrono::milliseconds(4000));
4009
4010 pi2->Disconnect(pi1->node());
4011
4012 event_loop_factory.RunFor(chrono::milliseconds(1000));
4013 pi1->AlwaysStart<Ping>("ping");
4014
4015 event_loop_factory.RunFor(chrono::milliseconds(5000));
4016 pi2_logger.AppendAllFilenames(&filenames);
4017 }
4018
4019 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004020 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004021 ConfirmReadable(filenames);
4022}
4023
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004024// Tests that we properly handle only one direction ever existing after a
4025// reboot with only reliable data.
Naman Guptaa63aa132023-03-22 20:06:34 -07004026TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
Austin Schuh7e417682023-08-11 17:05:30 -07004027 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4028 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4029
Naman Guptaa63aa132023-03-22 20:06:34 -07004030 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004031 aos::configuration::ReadConfig(
4032 ArtifactPath("aos/events/logging/"
4033 "multinode_pingpong_split4_reliable_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07004034 message_bridge::TestingTimeConverter time_converter(
4035 configuration::NodesCount(&config.message()));
4036 SimulatedEventLoopFactory event_loop_factory(&config.message());
4037 event_loop_factory.SetTimeConverter(&time_converter);
4038
4039 NodeEventLoopFactory *const pi1 =
4040 event_loop_factory.GetNodeEventLoopFactory("pi1");
4041 const size_t pi1_index = configuration::GetNodeIndex(
4042 event_loop_factory.configuration(), pi1->node());
4043 NodeEventLoopFactory *const pi2 =
4044 event_loop_factory.GetNodeEventLoopFactory("pi2");
4045 const size_t pi2_index = configuration::GetNodeIndex(
4046 event_loop_factory.configuration(), pi2->node());
4047 std::vector<std::string> filenames;
4048
4049 {
4050 CHECK_EQ(pi1_index, 0u);
4051 CHECK_EQ(pi2_index, 1u);
4052
4053 time_converter.AddNextTimestamp(
4054 distributed_clock::epoch(),
4055 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4056
4057 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4058 time_converter.AddNextTimestamp(
4059 distributed_clock::epoch() + reboot_time,
4060 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4061 BootTimestamp::epoch() + reboot_time});
4062 }
4063
4064 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004065 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004066
4067 pi1->AlwaysStart<Ping>("ping");
4068
4069 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4070 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4071 // second boot.
4072 {
4073 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004074 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4075 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004076
4077 event_loop_factory.RunFor(chrono::milliseconds(95));
4078
4079 pi2_logger.StartLogger(kLogfile2_1);
4080
4081 event_loop_factory.RunFor(chrono::milliseconds(4000));
4082
4083 pi2->Disconnect(pi1->node());
4084
4085 event_loop_factory.RunFor(chrono::milliseconds(1000));
4086 pi1->AlwaysStart<Ping>("ping");
4087
4088 event_loop_factory.RunFor(chrono::milliseconds(5000));
4089 pi2_logger.AppendAllFilenames(&filenames);
4090 }
4091
4092 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004093 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004094 ConfirmReadable(filenames);
4095}
4096
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004097// Tests that we properly handle only one direction ever existing after a
4098// reboot with mixed unreliable vs reliable, where reliable has an earlier
4099// timestamp than unreliable.
Brian Smartte67d7112023-03-20 12:06:30 -07004100TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase1) {
Austin Schuh7e417682023-08-11 17:05:30 -07004101 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4102 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4103
Brian Smartte67d7112023-03-20 12:06:30 -07004104 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4105 aos::configuration::ReadConfig(ArtifactPath(
4106 "aos/events/logging/multinode_pingpong_split4_mixed1_config.json"));
4107 message_bridge::TestingTimeConverter time_converter(
4108 configuration::NodesCount(&config.message()));
4109 SimulatedEventLoopFactory event_loop_factory(&config.message());
4110 event_loop_factory.SetTimeConverter(&time_converter);
4111
4112 NodeEventLoopFactory *const pi1 =
4113 event_loop_factory.GetNodeEventLoopFactory("pi1");
4114 const size_t pi1_index = configuration::GetNodeIndex(
4115 event_loop_factory.configuration(), pi1->node());
4116 NodeEventLoopFactory *const pi2 =
4117 event_loop_factory.GetNodeEventLoopFactory("pi2");
4118 const size_t pi2_index = configuration::GetNodeIndex(
4119 event_loop_factory.configuration(), pi2->node());
4120 std::vector<std::string> filenames;
4121
4122 {
4123 CHECK_EQ(pi1_index, 0u);
4124 CHECK_EQ(pi2_index, 1u);
4125
4126 time_converter.AddNextTimestamp(
4127 distributed_clock::epoch(),
4128 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4129
4130 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4131 time_converter.AddNextTimestamp(
4132 distributed_clock::epoch() + reboot_time,
4133 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4134 BootTimestamp::epoch() + reboot_time});
4135 }
4136
4137 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004138 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07004139
4140 // The following sequence using the above reference config creates
4141 // a reliable message timestamp < unreliable message timestamp.
4142 {
4143 pi1->DisableStatistics();
4144 pi2->DisableStatistics();
4145
4146 event_loop_factory.RunFor(chrono::milliseconds(95));
4147
4148 pi1->AlwaysStart<Ping>("ping");
4149
4150 event_loop_factory.RunFor(chrono::milliseconds(5250));
4151
4152 pi1->EnableStatistics();
4153
4154 event_loop_factory.RunFor(chrono::milliseconds(1000));
4155
4156 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004157 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4158 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07004159
4160 pi2_logger.StartLogger(kLogfile2_1);
4161
4162 event_loop_factory.RunFor(chrono::milliseconds(5000));
4163 pi2_logger.AppendAllFilenames(&filenames);
4164 }
4165
4166 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004167 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07004168 ConfirmReadable(filenames);
4169}
4170
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004171// Tests that we properly handle only one direction ever existing after a
4172// reboot with mixed unreliable vs reliable, where unreliable has an earlier
4173// timestamp than reliable.
Brian Smartte67d7112023-03-20 12:06:30 -07004174TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase2) {
Austin Schuh7e417682023-08-11 17:05:30 -07004175 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4176 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4177
Brian Smartte67d7112023-03-20 12:06:30 -07004178 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4179 aos::configuration::ReadConfig(ArtifactPath(
4180 "aos/events/logging/multinode_pingpong_split4_mixed2_config.json"));
4181 message_bridge::TestingTimeConverter time_converter(
4182 configuration::NodesCount(&config.message()));
4183 SimulatedEventLoopFactory event_loop_factory(&config.message());
4184 event_loop_factory.SetTimeConverter(&time_converter);
4185
4186 NodeEventLoopFactory *const pi1 =
4187 event_loop_factory.GetNodeEventLoopFactory("pi1");
4188 const size_t pi1_index = configuration::GetNodeIndex(
4189 event_loop_factory.configuration(), pi1->node());
4190 NodeEventLoopFactory *const pi2 =
4191 event_loop_factory.GetNodeEventLoopFactory("pi2");
4192 const size_t pi2_index = configuration::GetNodeIndex(
4193 event_loop_factory.configuration(), pi2->node());
4194 std::vector<std::string> filenames;
4195
4196 {
4197 CHECK_EQ(pi1_index, 0u);
4198 CHECK_EQ(pi2_index, 1u);
4199
4200 time_converter.AddNextTimestamp(
4201 distributed_clock::epoch(),
4202 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4203
4204 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4205 time_converter.AddNextTimestamp(
4206 distributed_clock::epoch() + reboot_time,
4207 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4208 BootTimestamp::epoch() + reboot_time});
4209 }
4210
4211 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004212 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07004213
4214 // The following sequence using the above reference config creates
4215 // an unreliable message timestamp < reliable message timestamp.
4216 {
4217 pi1->DisableStatistics();
4218 pi2->DisableStatistics();
4219
4220 event_loop_factory.RunFor(chrono::milliseconds(95));
4221
4222 pi1->AlwaysStart<Ping>("ping");
4223
4224 event_loop_factory.RunFor(chrono::milliseconds(5250));
4225
4226 pi1->EnableStatistics();
4227
4228 event_loop_factory.RunFor(chrono::milliseconds(1000));
4229
4230 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004231 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4232 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07004233
4234 pi2_logger.StartLogger(kLogfile2_1);
4235
4236 event_loop_factory.RunFor(chrono::milliseconds(5000));
4237 pi2_logger.AppendAllFilenames(&filenames);
4238 }
4239
4240 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004241 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07004242 ConfirmReadable(filenames);
4243}
4244
Naman Guptaa63aa132023-03-22 20:06:34 -07004245// Tests that we properly handle what used to be a time violation in one
4246// direction. This can occur when one direction goes down after sending some
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004247// data, but the other keeps working. The down direction ends up resolving to
4248// a straight line in the noncausal filter, where the direction which is still
4249// up can cross that line. Really, time progressed along just fine but we
4250// assumed that the offset was a line when it could have deviated by up to
4251// 1ms/second.
Naman Guptaa63aa132023-03-22 20:06:34 -07004252TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4253 std::vector<std::string> filenames;
4254
4255 CHECK_EQ(pi1_index_, 0u);
4256 CHECK_EQ(pi2_index_, 1u);
4257
4258 time_converter_.AddNextTimestamp(
4259 distributed_clock::epoch(),
4260 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4261
4262 const chrono::nanoseconds before_disconnect_duration =
4263 time_converter_.AddMonotonic(
4264 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4265
4266 const chrono::nanoseconds test_duration =
4267 time_converter_.AddMonotonic(
4268 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4269 time_converter_.AddMonotonic(
4270 {chrono::milliseconds(10000),
4271 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4272 time_converter_.AddMonotonic(
4273 {chrono::milliseconds(10000),
4274 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4275
4276 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004277 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004278
4279 {
4280 LoggerState pi2_logger = MakeLogger(pi2_);
4281 pi2_logger.StartLogger(kLogfile);
4282 event_loop_factory_.RunFor(before_disconnect_duration);
4283
4284 pi2_->Disconnect(pi1_->node());
4285
4286 event_loop_factory_.RunFor(test_duration);
4287 pi2_->Connect(pi1_->node());
4288
4289 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4290 pi2_logger.AppendAllFilenames(&filenames);
4291 }
4292
4293 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004294 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004295 ConfirmReadable(filenames);
4296}
4297
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004298// Tests that we can replay a logfile that has timestamps such that at least
4299// one node's epoch is at a positive distributed_clock (and thus will have to
4300// be booted after the other node(s)).
Naman Guptaa63aa132023-03-22 20:06:34 -07004301TEST_P(MultinodeLoggerTest, StartOneNodeBeforeOther) {
4302 std::vector<std::string> filenames;
4303
4304 CHECK_EQ(pi1_index_, 0u);
4305 CHECK_EQ(pi2_index_, 1u);
4306
4307 time_converter_.AddNextTimestamp(
4308 distributed_clock::epoch(),
4309 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4310
4311 const chrono::nanoseconds before_reboot_duration = chrono::milliseconds(1000);
4312 time_converter_.RebootAt(
4313 0, distributed_clock::time_point(before_reboot_duration));
4314
4315 const chrono::nanoseconds test_duration = time_converter_.AddMonotonic(
4316 {chrono::milliseconds(10000), chrono::milliseconds(10000)});
4317
4318 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004319 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004320
4321 pi2_->Disconnect(pi1_->node());
4322 pi1_->Disconnect(pi2_->node());
4323
4324 {
4325 LoggerState pi2_logger = MakeLogger(pi2_);
4326
4327 pi2_logger.StartLogger(kLogfile);
4328 event_loop_factory_.RunFor(before_reboot_duration);
4329
4330 pi2_->Connect(pi1_->node());
4331 pi1_->Connect(pi2_->node());
4332
4333 event_loop_factory_.RunFor(test_duration);
4334
4335 pi2_logger.AppendAllFilenames(&filenames);
4336 }
4337
4338 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004339 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004340 ConfirmReadable(filenames);
4341
4342 {
4343 LogReader reader(sorted_parts);
4344 SimulatedEventLoopFactory replay_factory(reader.configuration());
4345 reader.RegisterWithoutStarting(&replay_factory);
4346
4347 NodeEventLoopFactory *const replay_node =
4348 reader.event_loop_factory()->GetNodeEventLoopFactory("pi1");
4349
4350 std::unique_ptr<EventLoop> test_event_loop =
4351 replay_node->MakeEventLoop("test_reader");
4352 replay_node->OnStartup([replay_node]() {
4353 // Check that we didn't boot until at least t=0.
4354 CHECK_LE(monotonic_clock::epoch(), replay_node->monotonic_now());
4355 });
4356 test_event_loop->OnRun([&test_event_loop]() {
4357 // Check that we didn't boot until at least t=0.
4358 EXPECT_LE(monotonic_clock::epoch(), test_event_loop->monotonic_now());
4359 });
4360 reader.event_loop_factory()->Run();
4361 reader.Deregister();
4362 }
4363}
4364
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004365// Tests that when we have a loop without all the logs at all points in time,
4366// we can sort it properly.
Naman Guptaa63aa132023-03-22 20:06:34 -07004367TEST(MultinodeLoggerLoopTest, Loop) {
Austin Schuh7e417682023-08-11 17:05:30 -07004368 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4369 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4370
Naman Guptaa63aa132023-03-22 20:06:34 -07004371 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004372 aos::configuration::ReadConfig(
4373 ArtifactPath("aos/events/logging/"
4374 "multinode_pingpong_triangle_split_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07004375 message_bridge::TestingTimeConverter time_converter(
4376 configuration::NodesCount(&config.message()));
4377 SimulatedEventLoopFactory event_loop_factory(&config.message());
4378 event_loop_factory.SetTimeConverter(&time_converter);
4379
4380 NodeEventLoopFactory *const pi1 =
4381 event_loop_factory.GetNodeEventLoopFactory("pi1");
4382 NodeEventLoopFactory *const pi2 =
4383 event_loop_factory.GetNodeEventLoopFactory("pi2");
4384 NodeEventLoopFactory *const pi3 =
4385 event_loop_factory.GetNodeEventLoopFactory("pi3");
4386
4387 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004388 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004389 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004390 aos::testing::TestTmpDir() + "/logs/multi_logfile2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004391 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004392 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004393
4394 {
4395 // Make pi1 boot before everything else.
4396 time_converter.AddNextTimestamp(
4397 distributed_clock::epoch(),
4398 {BootTimestamp::epoch(),
4399 BootTimestamp::epoch() - chrono::milliseconds(100),
4400 BootTimestamp::epoch() - chrono::milliseconds(300)});
4401 }
4402
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004403 // We want to setup a situation such that 2 of the 3 legs of the loop are
4404 // very confident about time being X, and the third leg is pulling the
4405 // average off to one side.
Naman Guptaa63aa132023-03-22 20:06:34 -07004406 //
4407 // It's easiest to visualize this in timestamp_plotter.
4408
4409 std::vector<std::string> filenames;
4410 {
4411 // Have pi1 send out a reliable message at startup. This sets up a long
4412 // forwarding time message at the start to bias time.
4413 std::unique_ptr<EventLoop> pi1_event_loop = pi1->MakeEventLoop("ping");
4414 {
4415 aos::Sender<examples::Ping> ping_sender =
4416 pi1_event_loop->MakeSender<examples::Ping>("/reliable");
4417
4418 aos::Sender<examples::Ping>::Builder builder = ping_sender.MakeBuilder();
4419 examples::Ping::Builder ping_builder =
4420 builder.MakeBuilder<examples::Ping>();
4421 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
4422 }
4423
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004424 // Wait a while so there's enough data to let the worst case be rather
4425 // off.
Naman Guptaa63aa132023-03-22 20:06:34 -07004426 event_loop_factory.RunFor(chrono::seconds(1000));
4427
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004428 // Now start a receiving node first. This sets up 2 tight bounds between
4429 // 2 of the nodes.
Naman Guptaa63aa132023-03-22 20:06:34 -07004430 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004431 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4432 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004433 pi2_logger.StartLogger(kLogfile2_1);
4434
4435 event_loop_factory.RunFor(chrono::seconds(100));
4436
4437 // And now start the third leg.
4438 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004439 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4440 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004441 pi3_logger.StartLogger(kLogfile3_1);
4442
4443 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004444 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4445 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004446 pi1_logger.StartLogger(kLogfile1_1);
4447
4448 event_loop_factory.RunFor(chrono::seconds(100));
4449
4450 pi1_logger.AppendAllFilenames(&filenames);
4451 pi2_logger.AppendAllFilenames(&filenames);
4452 pi3_logger.AppendAllFilenames(&filenames);
4453 }
4454
4455 // Make sure we can read this.
4456 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004457 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004458 auto result = ConfirmReadable(filenames);
4459}
4460
Austin Schuh08dba8f2023-05-01 08:29:30 -07004461// Tests that RestartLogging works in the simple case. Unfortunately, the
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004462// failure cases involve simulating time elapsing in callbacks, which is
4463// really hard. The best we can reasonably do is make sure 2 back to back
4464// logs are parseable together.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004465TEST_P(MultinodeLoggerTest, RestartLogging) {
4466 time_converter_.AddMonotonic(
4467 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4468 std::vector<std::string> filenames;
4469 {
4470 LoggerState pi1_logger = MakeLogger(pi1_);
4471
4472 event_loop_factory_.RunFor(chrono::milliseconds(95));
4473
4474 StartLogger(&pi1_logger, logfile_base1_);
4475 aos::monotonic_clock::time_point last_rotation_time =
4476 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07004477 pi1_logger.logger->set_on_logged_period(
4478 [&](aos::monotonic_clock::time_point) {
4479 const auto now = pi1_logger.event_loop->monotonic_now();
4480 if (now > last_rotation_time + std::chrono::seconds(5)) {
4481 pi1_logger.AppendAllFilenames(&filenames);
4482 std::unique_ptr<MultiNodeFilesLogNamer> namer =
4483 pi1_logger.MakeLogNamer(logfile_base2_);
4484 pi1_logger.log_namer = namer.get();
Austin Schuh08dba8f2023-05-01 08:29:30 -07004485
Austin Schuh2f864452023-07-17 14:53:08 -07004486 pi1_logger.logger->RestartLogging(std::move(namer));
4487 last_rotation_time = now;
4488 }
4489 });
Austin Schuh08dba8f2023-05-01 08:29:30 -07004490
4491 event_loop_factory_.RunFor(chrono::milliseconds(7000));
4492
4493 pi1_logger.AppendAllFilenames(&filenames);
4494 }
4495
4496 for (const auto &x : filenames) {
4497 LOG(INFO) << x;
4498 }
4499
4500 EXPECT_GE(filenames.size(), 2u);
4501
4502 ConfirmReadable(filenames);
4503
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004504 // TODO(austin): It would be good to confirm that any one time messages end
4505 // up in both logs correctly.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004506}
4507
Austin Schuh6e93fc22023-08-22 21:27:22 -07004508// Tests that we call OnEnd without --skip_missing_forwarding_entries.
4509TEST_P(MultinodeLoggerTest, SkipMissingForwardingEntries) {
4510 if (file_strategy() == FileStrategy::kCombine) {
4511 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
4512 }
4513 time_converter_.AddMonotonic(
4514 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4515
4516 std::vector<std::string> filenames;
4517 {
4518 LoggerState pi1_logger = MakeLogger(pi1_);
4519
4520 event_loop_factory_.RunFor(chrono::milliseconds(95));
4521
4522 StartLogger(&pi1_logger);
4523 aos::monotonic_clock::time_point last_rotation_time =
4524 pi1_logger.event_loop->monotonic_now();
4525 pi1_logger.logger->set_on_logged_period(
4526 [&](aos::monotonic_clock::time_point) {
4527 const auto now = pi1_logger.event_loop->monotonic_now();
4528 if (now > last_rotation_time + std::chrono::seconds(5)) {
4529 pi1_logger.logger->Rotate();
4530 last_rotation_time = now;
4531 }
4532 });
4533
4534 event_loop_factory_.RunFor(chrono::milliseconds(15000));
4535 pi1_logger.AppendAllFilenames(&filenames);
4536 }
4537
4538 // If we remove the last remote data part, we'll trigger missing data for
4539 // timestamps.
4540 filenames.erase(std::remove_if(filenames.begin(), filenames.end(),
4541 [](const std::string &s) {
4542 return s.find("data/pi2_data.part3.bfbs") !=
4543 std::string::npos;
4544 }),
4545 filenames.end());
4546
4547 auto result = ConfirmReadable(filenames);
4548}
4549
Austin Schuh54ffea42023-08-23 13:27:04 -07004550// Tests that we call OnEnd without --skip_missing_forwarding_entries.
4551TEST(MultinodeLoggerConfigTest, SingleNode) {
4552 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4553 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4554
4555 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4556 aos::configuration::ReadConfig(
4557 ArtifactPath("aos/events/logging/multinode_single_node_config.json"));
4558 message_bridge::TestingTimeConverter time_converter(
4559 configuration::NodesCount(&config.message()));
4560 SimulatedEventLoopFactory event_loop_factory(&config.message());
4561 event_loop_factory.SetTimeConverter(&time_converter);
4562
4563 time_converter.StartEqual();
4564
4565 const std::string kLogfile1_1 =
4566 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
4567
4568 NodeEventLoopFactory *const pi1 =
4569 event_loop_factory.GetNodeEventLoopFactory("pi1");
4570
4571 std::vector<std::string> filenames;
4572
4573 {
4574 // Now start a receiving node first. This sets up 2 tight bounds between
4575 // 2 of the nodes.
4576 LoggerState pi1_logger = MakeLoggerState(
4577 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4578 FileStrategy::kKeepSeparate);
4579 pi1_logger.StartLogger(kLogfile1_1);
4580
4581 event_loop_factory.RunFor(chrono::seconds(10));
4582
4583 pi1_logger.AppendAllFilenames(&filenames);
4584 }
4585
4586 // Make sure we can read this.
4587 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4588 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4589 auto result = ConfirmReadable(filenames);
4590
4591 // TODO(austin): Probably want to stop caring about ServerStatistics,
4592 // ClientStatistics, and Timestamp since they don't really make sense.
4593}
4594
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004595// Tests that when we have evidence of 2 boots, and then start logging, the
4596// max_out_of_order_duration ends up reasonable on the boot with the start time.
4597TEST(MultinodeLoggerLoopTest, PreviousBootData) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004598 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4599 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4600
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004601 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4602 aos::configuration::ReadConfig(ArtifactPath(
4603 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4604 message_bridge::TestingTimeConverter time_converter(
4605 configuration::NodesCount(&config.message()));
4606 SimulatedEventLoopFactory event_loop_factory(&config.message());
4607 event_loop_factory.SetTimeConverter(&time_converter);
4608
4609 const UUID pi1_boot0 = UUID::Random();
4610 const UUID pi2_boot0 = UUID::Random();
4611 const UUID pi2_boot1 = UUID::Random();
4612
4613 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004614 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004615
4616 {
4617 constexpr size_t kPi1Index = 0;
4618 constexpr size_t kPi2Index = 1;
4619 time_converter.set_boot_uuid(kPi1Index, 0, pi1_boot0);
4620 time_converter.set_boot_uuid(kPi2Index, 0, pi2_boot0);
4621 time_converter.set_boot_uuid(kPi2Index, 1, pi2_boot1);
4622
4623 // Make pi1 boot before everything else.
4624 time_converter.AddNextTimestamp(
4625 distributed_clock::epoch(),
4626 {BootTimestamp::epoch(),
4627 BootTimestamp::epoch() - chrono::milliseconds(100)});
4628
4629 const chrono::nanoseconds reboot_time = chrono::seconds(1005);
4630 time_converter.AddNextTimestamp(
4631 distributed_clock::epoch() + reboot_time,
4632 {BootTimestamp::epoch() + reboot_time,
4633 BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()}});
4634 }
4635
4636 NodeEventLoopFactory *const pi1 =
4637 event_loop_factory.GetNodeEventLoopFactory("pi1");
4638 NodeEventLoopFactory *const pi2 =
4639 event_loop_factory.GetNodeEventLoopFactory("pi2");
4640
4641 // What we want is for pi2 to send a message at t=1000 on the first channel
4642 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4643 // the max out of order duration be large.
4644 //
4645 // Then, we reboot, and only send messages on a third channel (/atest2 pong).
4646 // The order is key, they need to sort in this order in the config.
4647
4648 std::vector<std::string> filenames;
4649 {
4650 {
4651 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4652 aos::Sender<examples::Pong> pong_sender =
4653 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4654
4655 pi2_event_loop->OnRun([&]() {
4656 aos::Sender<examples::Pong>::Builder builder =
4657 pong_sender.MakeBuilder();
4658 examples::Pong::Builder pong_builder =
4659 builder.MakeBuilder<examples::Pong>();
4660 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4661 });
4662
4663 event_loop_factory.RunFor(chrono::seconds(1000));
4664 }
4665
4666 {
4667 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4668 aos::Sender<examples::Pong> pong_sender =
4669 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4670
4671 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4672 examples::Pong::Builder pong_builder =
4673 builder.MakeBuilder<examples::Pong>();
4674 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4675 }
4676
4677 event_loop_factory.RunFor(chrono::seconds(10));
4678
4679 // Now start a receiving node first. This sets up 2 tight bounds between
4680 // 2 of the nodes.
4681 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004682 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4683 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004684 pi1_logger.StartLogger(kLogfile1_1);
4685
4686 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4687 aos::Sender<examples::Pong> pong_sender =
4688 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4689
4690 pi2_event_loop->AddPhasedLoop(
4691 [&pong_sender](int) {
4692 aos::Sender<examples::Pong>::Builder builder =
4693 pong_sender.MakeBuilder();
4694 examples::Pong::Builder pong_builder =
4695 builder.MakeBuilder<examples::Pong>();
4696 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4697 },
4698 chrono::milliseconds(10));
4699
4700 event_loop_factory.RunFor(chrono::seconds(100));
4701
4702 pi1_logger.AppendAllFilenames(&filenames);
4703 }
4704
4705 // Make sure we can read this.
4706 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4707 EXPECT_TRUE(AllRebootPartsMatchOutOfOrderDuration(sorted_parts, "pi2"));
4708 auto result = ConfirmReadable(filenames);
4709}
4710
4711// Tests that when we start without a connection, and then start logging, the
4712// max_out_of_order_duration ends up reasonable.
4713TEST(MultinodeLoggerLoopTest, StartDisconnected) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004714 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4715 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4716
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004717 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4718 aos::configuration::ReadConfig(ArtifactPath(
4719 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4720 message_bridge::TestingTimeConverter time_converter(
4721 configuration::NodesCount(&config.message()));
4722 SimulatedEventLoopFactory event_loop_factory(&config.message());
4723 event_loop_factory.SetTimeConverter(&time_converter);
4724
4725 time_converter.StartEqual();
4726
4727 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004728 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004729
4730 NodeEventLoopFactory *const pi1 =
4731 event_loop_factory.GetNodeEventLoopFactory("pi1");
4732 NodeEventLoopFactory *const pi2 =
4733 event_loop_factory.GetNodeEventLoopFactory("pi2");
4734
4735 // What we want is for pi2 to send a message at t=1000 on the first channel
4736 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4737 // the max out of order duration be large.
4738 //
4739 // Then, we disconnect, and only send messages on a third channel
4740 // (/atest2 pong). The order is key, they need to sort in this order in the
4741 // config so we observe them in the order which grows the
4742 // max_out_of_order_duration.
4743
4744 std::vector<std::string> filenames;
4745 {
4746 {
4747 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4748 aos::Sender<examples::Pong> pong_sender =
4749 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4750
4751 pi2_event_loop->OnRun([&]() {
4752 aos::Sender<examples::Pong>::Builder builder =
4753 pong_sender.MakeBuilder();
4754 examples::Pong::Builder pong_builder =
4755 builder.MakeBuilder<examples::Pong>();
4756 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4757 });
4758
4759 event_loop_factory.RunFor(chrono::seconds(1000));
4760 }
4761
4762 {
4763 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4764 aos::Sender<examples::Pong> pong_sender =
4765 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4766
4767 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4768 examples::Pong::Builder pong_builder =
4769 builder.MakeBuilder<examples::Pong>();
4770 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4771 }
4772
4773 event_loop_factory.RunFor(chrono::seconds(10));
4774
4775 pi1->Disconnect(pi2->node());
4776 pi2->Disconnect(pi1->node());
4777
4778 // Make data flow.
4779 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4780 aos::Sender<examples::Pong> pong_sender =
4781 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4782
4783 pi2_event_loop->AddPhasedLoop(
4784 [&pong_sender](int) {
4785 aos::Sender<examples::Pong>::Builder builder =
4786 pong_sender.MakeBuilder();
4787 examples::Pong::Builder pong_builder =
4788 builder.MakeBuilder<examples::Pong>();
4789 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4790 },
4791 chrono::milliseconds(10));
4792
4793 event_loop_factory.RunFor(chrono::seconds(10));
4794
4795 // Now start a receiving node first. This sets up 2 tight bounds between
4796 // 2 of the nodes.
4797 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004798 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4799 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004800 pi1_logger.StartLogger(kLogfile1_1);
4801
4802 event_loop_factory.RunFor(chrono::seconds(10));
4803
4804 // Now, reconnect, and everything should recover.
4805 pi1->Connect(pi2->node());
4806 pi2->Connect(pi1->node());
4807
4808 event_loop_factory.RunFor(chrono::seconds(10));
4809
4810 pi1_logger.AppendAllFilenames(&filenames);
4811 }
4812
4813 // Make sure we can read this.
4814 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4815 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4816 auto result = ConfirmReadable(filenames);
4817}
4818
Austin Schuh633858f2024-03-22 14:34:19 -07004819// Tests that only having a delayed, reliable message from a boot results in a
4820// readable log.
4821//
4822// Note: this is disabled since it doesn't work yet. Un-disable this when the
4823// code is fixed!
Austin Schuhb5224ec2024-03-27 15:20:09 -07004824TEST(MultinodeLoggerLoopTest, ReliableOnlyTimestamps) {
Austin Schuh633858f2024-03-22 14:34:19 -07004825 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4826 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4827
4828 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4829 aos::configuration::ReadConfig(
4830 ArtifactPath("aos/events/logging/"
4831 "multinode_pingpong_reboot_reliable_only_config.json"));
4832 message_bridge::TestingTimeConverter time_converter(
4833 configuration::NodesCount(&config.message()));
4834 SimulatedEventLoopFactory event_loop_factory(&config.message());
4835 event_loop_factory.SetTimeConverter(&time_converter);
4836
4837 constexpr chrono::nanoseconds kRebootTime = chrono::seconds(100);
4838 {
4839 time_converter.AddNextTimestamp(
4840 distributed_clock::epoch(),
4841 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4842 time_converter.AddNextTimestamp(
4843 distributed_clock::epoch() + kRebootTime,
4844 {BootTimestamp::epoch() + kRebootTime,
4845 BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()}});
Austin Schuh1124c512023-08-01 15:20:44 -07004846 }
4847
Austin Schuh633858f2024-03-22 14:34:19 -07004848 const std::string kLogfile1_1 =
4849 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
4850
4851 NodeEventLoopFactory *const pi1 =
4852 event_loop_factory.GetNodeEventLoopFactory("pi1");
4853
4854 // We want unreliable timestamps from one boot, a reliable timestamp from the
4855 // same boot, and then a long delayed reliable timestamp from the second boot.
4856 // This produces conflicting information about when the second boot happened.
4857 std::vector<std::string> filenames;
4858 PingSender *app1 = pi1->AlwaysStart<PingSender>("pingsender", "/atest1");
4859 PingSender *app2 = pi1->AlwaysStart<PingSender>("pingsender", "/atest2");
4860 event_loop_factory.RunFor(chrono::seconds(1));
4861 pi1->Stop(app2);
4862 event_loop_factory.RunFor(kRebootTime - chrono::seconds(2));
4863 pi1->Stop(app1);
4864
4865 event_loop_factory.RunFor(chrono::seconds(1) + kRebootTime * 2);
4866
4867 {
4868 // Collect a small log after reboot.
4869 LoggerState pi1_logger = MakeLoggerState(
4870 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4871 FileStrategy::kKeepSeparate);
4872 pi1_logger.StartLogger(kLogfile1_1);
4873
4874 event_loop_factory.RunFor(chrono::seconds(1));
4875
4876 pi1_logger.AppendAllFilenames(&filenames);
4877 }
4878
4879 // Make sure we can read this.
4880 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4881 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4882 auto result = ConfirmReadable(filenames);
4883}
Austin Schuh1124c512023-08-01 15:20:44 -07004884
4885// Tests that we log correctly as nodes connect slowly.
4886TEST(MultinodeLoggerLoopTest, StaggeredConnect) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004887 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4888 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4889
Austin Schuh1124c512023-08-01 15:20:44 -07004890 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4891 aos::configuration::ReadConfig(ArtifactPath(
4892 "aos/events/logging/multinode_pingpong_pi3_pingpong_config.json"));
4893 message_bridge::TestingTimeConverter time_converter(
4894 configuration::NodesCount(&config.message()));
4895 SimulatedEventLoopFactory event_loop_factory(&config.message());
4896 event_loop_factory.SetTimeConverter(&time_converter);
4897
4898 time_converter.StartEqual();
4899
4900 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004901 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Austin Schuh1124c512023-08-01 15:20:44 -07004902
4903 NodeEventLoopFactory *const pi1 =
4904 event_loop_factory.GetNodeEventLoopFactory("pi1");
4905 NodeEventLoopFactory *const pi2 =
4906 event_loop_factory.GetNodeEventLoopFactory("pi2");
4907 NodeEventLoopFactory *const pi3 =
4908 event_loop_factory.GetNodeEventLoopFactory("pi3");
4909
4910 // What we want is for pi2 to send a message at t=1000 on the first channel
4911 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4912 // the max out of order duration be large.
4913 //
4914 // Then, we disconnect, and only send messages on a third channel
4915 // (/atest2 pong). The order is key, they need to sort in this order in the
4916 // config so we observe them in the order which grows the
4917 // max_out_of_order_duration.
4918
4919 pi1->Disconnect(pi2->node());
4920 pi2->Disconnect(pi1->node());
4921
4922 pi1->Disconnect(pi3->node());
4923 pi3->Disconnect(pi1->node());
4924
4925 std::vector<std::string> filenames;
4926 pi2->AlwaysStart<PongSender>("pongsender", "/test2");
4927 pi3->AlwaysStart<PongSender>("pongsender", "/test3");
4928
4929 event_loop_factory.RunFor(chrono::seconds(10));
4930
4931 {
4932 // Now start a receiving node first. This sets up 2 tight bounds between
4933 // 2 of the nodes.
4934 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004935 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4936 FileStrategy::kKeepSeparate);
Austin Schuh1124c512023-08-01 15:20:44 -07004937 pi1_logger.StartLogger(kLogfile1_1);
4938
4939 event_loop_factory.RunFor(chrono::seconds(10));
4940
4941 // Now, reconnect, and everything should recover.
4942 pi1->Connect(pi2->node());
4943 pi2->Connect(pi1->node());
4944
4945 event_loop_factory.RunFor(chrono::seconds(10));
4946
4947 pi1->Connect(pi3->node());
4948 pi3->Connect(pi1->node());
4949
4950 event_loop_factory.RunFor(chrono::seconds(10));
4951
4952 pi1_logger.AppendAllFilenames(&filenames);
4953 }
4954
4955 // Make sure we can read this.
4956 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4957 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4958 auto result = ConfirmReadable(filenames);
4959}
4960
Stephan Pleinesf63bde82024-01-13 15:59:33 -08004961} // namespace aos::logger::testing