blob: a3cda4337fd7875ed6681c2742d2eba34318f7a4 [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);
477
478 ++pi1_ping_count;
479 });
480 pi2_event_loop->MakeWatcher(
481 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
482 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
483 << pi2_event_loop->context().monotonic_remote_time << " -> "
484 << pi2_event_loop->context().monotonic_event_time;
485 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
486
487 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
488 pi2_ping_count * chrono::milliseconds(10) +
489 monotonic_clock::epoch());
490 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
491 pi2_ping_count * chrono::milliseconds(10) +
492 realtime_clock::epoch());
493 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
494 chrono::microseconds(150),
495 pi2_event_loop->context().monotonic_event_time);
496 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
497 chrono::microseconds(150),
498 pi2_event_loop->context().realtime_event_time);
499 ++pi2_ping_count;
500 });
501
502 constexpr ssize_t kQueueIndexOffset = -9;
503 // Confirm that the ping and pong counts both match, and the value also
504 // matches.
505 pi1_event_loop->MakeWatcher(
506 "/test", [&pi1_event_loop, &pi1_ping_count,
507 &pi1_pong_count](const examples::Pong &pong) {
508 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
509 << pi1_event_loop->context().monotonic_remote_time << " -> "
510 << pi1_event_loop->context().monotonic_event_time;
511
512 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
513 pi1_pong_count + kQueueIndexOffset);
514 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
515 chrono::microseconds(200) +
516 pi1_pong_count * chrono::milliseconds(10) +
517 monotonic_clock::epoch());
518 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
519 chrono::microseconds(200) +
520 pi1_pong_count * chrono::milliseconds(10) +
521 realtime_clock::epoch());
522
523 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
524 chrono::microseconds(150),
525 pi1_event_loop->context().monotonic_event_time);
526 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
527 chrono::microseconds(150),
528 pi1_event_loop->context().realtime_event_time);
529
530 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
531 ++pi1_pong_count;
532 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
533 });
534 pi2_event_loop->MakeWatcher(
535 "/test", [&pi2_event_loop, &pi2_ping_count,
536 &pi2_pong_count](const examples::Pong &pong) {
537 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
538 << pi2_event_loop->context().monotonic_remote_time << " -> "
539 << pi2_event_loop->context().monotonic_event_time;
540
541 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
542 pi2_pong_count + kQueueIndexOffset);
543
544 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
545 chrono::microseconds(200) +
546 pi2_pong_count * chrono::milliseconds(10) +
547 monotonic_clock::epoch());
548 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
549 chrono::microseconds(200) +
550 pi2_pong_count * chrono::milliseconds(10) +
551 realtime_clock::epoch());
552
553 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
554 pi2_event_loop->context().monotonic_event_time);
555 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
556 pi2_event_loop->context().realtime_event_time);
557
558 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
559 ++pi2_pong_count;
560 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
561 });
562
563 log_reader_factory.Run();
564 EXPECT_EQ(pi1_ping_count, 2010);
565 EXPECT_EQ(pi2_ping_count, 2010);
566 EXPECT_EQ(pi1_pong_count, 2010);
567 EXPECT_EQ(pi2_pong_count, 2010);
568
569 reader.Deregister();
570}
571
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600572// MultinodeLoggerTest that tests the mutate callback works across multiple
573// nodes with remapping
574TEST_P(MultinodeLoggerTest, MultiNodeRemapMutateCallback) {
575 time_converter_.StartEqual();
576 std::vector<std::string> actual_filenames;
577
578 {
579 LoggerState pi1_logger = MakeLogger(pi1_);
580 LoggerState pi2_logger = MakeLogger(pi2_);
581
582 event_loop_factory_.RunFor(chrono::milliseconds(95));
583
584 StartLogger(&pi1_logger);
585 StartLogger(&pi2_logger);
586
587 event_loop_factory_.RunFor(chrono::milliseconds(20000));
588 pi1_logger.AppendAllFilenames(&actual_filenames);
589 pi2_logger.AppendAllFilenames(&actual_filenames);
590 }
591
Austin Schuh8fb4b452023-08-04 17:02:27 -0700592 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700593 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600594
595 LogReader reader(sorted_parts, &config_.message());
596 // Remap just on pi1.
597 reader.RemapLoggedChannel<examples::Pong>(
598 "/test", configuration::GetNode(reader.configuration(), "pi1"));
599
600 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
601
602 int pong_count = 0;
603 // Adds a callback which mutates the value of the pong message before the
604 // message is sent which is the feature we are testing here
605 reader.AddBeforeSendCallback("/test",
606 [&pong_count](aos::examples::Pong *pong) {
607 pong->mutate_value(pong->value() + 1);
608 pong_count = pong->value();
609 });
610
611 // This sends out the fetched messages and advances time to the start of the
612 // log file.
613 reader.Register(&log_reader_factory);
614
615 const Node *pi1 =
616 configuration::GetNode(log_reader_factory.configuration(), "pi1");
617 const Node *pi2 =
618 configuration::GetNode(log_reader_factory.configuration(), "pi2");
619
620 EXPECT_THAT(reader.LoggedNodes(),
621 ::testing::ElementsAre(
622 configuration::GetNode(reader.logged_configuration(), pi1),
623 configuration::GetNode(reader.logged_configuration(), pi2)));
624
625 std::unique_ptr<EventLoop> pi1_event_loop =
626 log_reader_factory.MakeEventLoop("test", pi1);
627 std::unique_ptr<EventLoop> pi2_event_loop =
628 log_reader_factory.MakeEventLoop("test", pi2);
629
630 pi1_event_loop->MakeWatcher("/original/test",
631 [&pong_count](const examples::Pong &pong) {
632 EXPECT_EQ(pong_count, pong.value());
633 });
634
635 pi2_event_loop->MakeWatcher("/test",
636 [&pong_count](const examples::Pong &pong) {
637 EXPECT_EQ(pong_count, pong.value());
638 });
639
640 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
641 reader.Deregister();
642
643 EXPECT_EQ(pong_count, 2011);
644}
645
646// MultinodeLoggerTest that tests the mutate callback works across multiple
647// nodes
648TEST_P(MultinodeLoggerTest, MultiNodeMutateCallback) {
649 time_converter_.StartEqual();
650 std::vector<std::string> actual_filenames;
651
652 {
653 LoggerState pi1_logger = MakeLogger(pi1_);
654 LoggerState pi2_logger = MakeLogger(pi2_);
655
656 event_loop_factory_.RunFor(chrono::milliseconds(95));
657
658 StartLogger(&pi1_logger);
659 StartLogger(&pi2_logger);
660
661 event_loop_factory_.RunFor(chrono::milliseconds(20000));
662 pi1_logger.AppendAllFilenames(&actual_filenames);
663 pi2_logger.AppendAllFilenames(&actual_filenames);
664 }
665
Austin Schuh8fb4b452023-08-04 17:02:27 -0700666 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700667 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600668
669 LogReader reader(sorted_parts, &config_.message());
670
671 int pong_count = 0;
672 // Adds a callback which mutates the value of the pong message before the
673 // message is sent which is the feature we are testing here
674 reader.AddBeforeSendCallback("/test",
675 [&pong_count](aos::examples::Pong *pong) {
676 pong->mutate_value(pong->value() + 1);
677 pong_count = pong->value();
678 });
679
680 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
681
682 // This sends out the fetched messages and advances time to the start of the
683 // log file.
684 reader.Register(&log_reader_factory);
685
686 const Node *pi1 =
687 configuration::GetNode(log_reader_factory.configuration(), "pi1");
688 const Node *pi2 =
689 configuration::GetNode(log_reader_factory.configuration(), "pi2");
690
691 EXPECT_THAT(reader.LoggedNodes(),
692 ::testing::ElementsAre(
693 configuration::GetNode(reader.logged_configuration(), pi1),
694 configuration::GetNode(reader.logged_configuration(), pi2)));
695
696 std::unique_ptr<EventLoop> pi1_event_loop =
697 log_reader_factory.MakeEventLoop("test", pi1);
698 std::unique_ptr<EventLoop> pi2_event_loop =
699 log_reader_factory.MakeEventLoop("test", pi2);
700
701 pi1_event_loop->MakeWatcher("/test",
702 [&pong_count](const examples::Pong &pong) {
703 EXPECT_EQ(pong_count, pong.value());
704 });
705
706 pi2_event_loop->MakeWatcher("/test",
707 [&pong_count](const examples::Pong &pong) {
708 EXPECT_EQ(pong_count, pong.value());
709 });
710
711 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
712 reader.Deregister();
713
714 EXPECT_EQ(pong_count, 2011);
715}
716
717// Tests that the before send callback is only called from the sender node if it
718// is forwarded
719TEST_P(MultinodeLoggerTest, OnlyDoBeforeSendCallbackOnSenderNode) {
720 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700721
722 std::vector<std::string> filenames;
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600723 {
724 LoggerState pi1_logger = MakeLogger(pi1_);
725 LoggerState pi2_logger = MakeLogger(pi2_);
726
727 event_loop_factory_.RunFor(chrono::milliseconds(95));
728
729 StartLogger(&pi1_logger);
730 StartLogger(&pi2_logger);
731
732 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700733
734 pi1_logger.AppendAllFilenames(&filenames);
735 pi2_logger.AppendAllFilenames(&filenames);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600736 }
737
Austin Schuh8fb4b452023-08-04 17:02:27 -0700738 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700739 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
740 LogReader reader(sorted_parts);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600741
742 int ping_count = 0;
743 // Adds a callback which mutates the value of the pong message before the
744 // message is sent which is the feature we are testing here
745 reader.AddBeforeSendCallback("/test",
746 [&ping_count](aos::examples::Ping *ping) {
747 ++ping_count;
748 ping->mutate_value(ping_count);
749 });
750
751 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
752 log_reader_factory.set_send_delay(chrono::microseconds(0));
753
754 reader.Register(&log_reader_factory);
755
756 const Node *pi1 =
757 configuration::GetNode(log_reader_factory.configuration(), "pi1");
758 const Node *pi2 =
759 configuration::GetNode(log_reader_factory.configuration(), "pi2");
760
761 std::unique_ptr<EventLoop> pi1_event_loop =
762 log_reader_factory.MakeEventLoop("test", pi1);
763 pi1_event_loop->SkipTimingReport();
764 std::unique_ptr<EventLoop> pi2_event_loop =
765 log_reader_factory.MakeEventLoop("test", pi2);
766 pi2_event_loop->SkipTimingReport();
767
768 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
769 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
770
771 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
772 pi1_ping_timestamp;
773 if (!shared()) {
774 pi1_ping_timestamp =
775 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
776 pi1_event_loop.get(),
777 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
778 }
779
780 log_reader_factory.Run();
781
782 EXPECT_EQ(pi1_ping.count(), 2000u);
783 EXPECT_EQ(pi2_ping.count(), 2000u);
784 // If the BeforeSendCallback is called on both nodes, then the ping count
785 // would be 4002 instead of 2001
786 EXPECT_EQ(ping_count, 2001u);
787 if (!shared()) {
788 EXPECT_EQ(pi1_ping_timestamp->count(), 2000u);
789 }
790
791 reader.Deregister();
792}
793
794// Tests that we do not allow adding callbacks after Register is called
795TEST_P(MultinodeLoggerDeathTest, AddCallbackAfterRegister) {
796 time_converter_.StartEqual();
797 std::vector<std::string> actual_filenames;
798
799 {
800 LoggerState pi1_logger = MakeLogger(pi1_);
801 LoggerState pi2_logger = MakeLogger(pi2_);
802
803 event_loop_factory_.RunFor(chrono::milliseconds(95));
804
805 StartLogger(&pi1_logger);
806 StartLogger(&pi2_logger);
807
808 event_loop_factory_.RunFor(chrono::milliseconds(20000));
809 pi1_logger.AppendAllFilenames(&actual_filenames);
810 pi2_logger.AppendAllFilenames(&actual_filenames);
811 }
812
Austin Schuh8fb4b452023-08-04 17:02:27 -0700813 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700814 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600815
816 LogReader reader(sorted_parts, &config_.message());
817 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
818 reader.Register(&log_reader_factory);
819 EXPECT_DEATH(
820 {
821 reader.AddBeforeSendCallback("/test", [](aos::examples::Pong *) {
822 LOG(FATAL) << "This should not be called";
823 });
824 },
825 "Cannot add callbacks after calling Register");
826 reader.Deregister();
827}
828
Naman Guptaa63aa132023-03-22 20:06:34 -0700829// Test that if we feed the replay with a mismatched node list that we die on
830// the LogReader constructor.
831TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
832 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700833
834 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -0700835 {
836 LoggerState pi1_logger = MakeLogger(pi1_);
837 LoggerState pi2_logger = MakeLogger(pi2_);
838
839 event_loop_factory_.RunFor(chrono::milliseconds(95));
840
841 StartLogger(&pi1_logger);
842 StartLogger(&pi2_logger);
843
844 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700845
846 pi1_logger.AppendAllFilenames(&filenames);
847 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -0700848 }
849
850 // Test that, if we add an additional node to the replay config that the
851 // logger complains about the mismatch in number of nodes.
852 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
853 configuration::MergeWithConfig(&config_.message(), R"({
854 "nodes": [
855 {
856 "name": "extra-node"
857 }
858 ]
859 }
860 )");
861
Austin Schuh8fb4b452023-08-04 17:02:27 -0700862 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700863 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -0700864 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
865 "Log file and replay config need to have matching nodes lists.");
866}
867
868// Tests that we can read log files where they don't start at the same monotonic
869// time.
870TEST_P(MultinodeLoggerTest, StaggeredStart) {
871 time_converter_.StartEqual();
872 std::vector<std::string> actual_filenames;
873
874 {
875 LoggerState pi1_logger = MakeLogger(pi1_);
876 LoggerState pi2_logger = MakeLogger(pi2_);
877
878 event_loop_factory_.RunFor(chrono::milliseconds(95));
879
880 StartLogger(&pi1_logger);
881
882 event_loop_factory_.RunFor(chrono::milliseconds(200));
883
884 StartLogger(&pi2_logger);
885
886 event_loop_factory_.RunFor(chrono::milliseconds(20000));
887 pi1_logger.AppendAllFilenames(&actual_filenames);
888 pi2_logger.AppendAllFilenames(&actual_filenames);
889 }
890
891 // Since we delay starting pi2, it already knows about all the timestamps so
892 // we don't end up with extra parts.
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700893 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
894 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
895 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -0700896
897 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
898 log_reader_factory.set_send_delay(chrono::microseconds(0));
899
900 // This sends out the fetched messages and advances time to the start of the
901 // log file.
902 reader.Register(&log_reader_factory);
903
904 const Node *pi1 =
905 configuration::GetNode(log_reader_factory.configuration(), "pi1");
906 const Node *pi2 =
907 configuration::GetNode(log_reader_factory.configuration(), "pi2");
908
909 EXPECT_THAT(reader.LoggedNodes(),
910 ::testing::ElementsAre(
911 configuration::GetNode(reader.logged_configuration(), pi1),
912 configuration::GetNode(reader.logged_configuration(), pi2)));
913
914 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
915
916 std::unique_ptr<EventLoop> pi1_event_loop =
917 log_reader_factory.MakeEventLoop("test", pi1);
918 std::unique_ptr<EventLoop> pi2_event_loop =
919 log_reader_factory.MakeEventLoop("test", pi2);
920
921 int pi1_ping_count = 30;
922 int pi2_ping_count = 30;
923 int pi1_pong_count = 30;
924 int pi2_pong_count = 30;
925
926 // Confirm that the ping value matches.
927 pi1_event_loop->MakeWatcher(
928 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
929 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
930 << pi1_event_loop->context().monotonic_remote_time << " -> "
931 << pi1_event_loop->context().monotonic_event_time;
932 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
933
934 ++pi1_ping_count;
935 });
936 pi2_event_loop->MakeWatcher(
937 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
938 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
939 << pi2_event_loop->context().monotonic_remote_time << " -> "
940 << pi2_event_loop->context().monotonic_event_time;
941 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
942
943 ++pi2_ping_count;
944 });
945
946 // Confirm that the ping and pong counts both match, and the value also
947 // matches.
948 pi1_event_loop->MakeWatcher(
949 "/test", [&pi1_event_loop, &pi1_ping_count,
950 &pi1_pong_count](const examples::Pong &pong) {
951 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
952 << pi1_event_loop->context().monotonic_remote_time << " -> "
953 << pi1_event_loop->context().monotonic_event_time;
954
955 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
956 ++pi1_pong_count;
957 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
958 });
959 pi2_event_loop->MakeWatcher(
960 "/test", [&pi2_event_loop, &pi2_ping_count,
961 &pi2_pong_count](const examples::Pong &pong) {
962 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
963 << pi2_event_loop->context().monotonic_remote_time << " -> "
964 << pi2_event_loop->context().monotonic_event_time;
965
966 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
967 ++pi2_pong_count;
968 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
969 });
970
971 log_reader_factory.Run();
972 EXPECT_EQ(pi1_ping_count, 2030);
973 EXPECT_EQ(pi2_ping_count, 2030);
974 EXPECT_EQ(pi1_pong_count, 2030);
975 EXPECT_EQ(pi2_pong_count, 2030);
976
977 reader.Deregister();
978}
979
980// Tests that we can read log files where the monotonic clocks drift and don't
981// match correctly. While we are here, also test that different ending times
982// also is readable.
983TEST_P(MultinodeLoggerTest, MismatchedClocks) {
984 // TODO(austin): Negate...
985 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
986
987 time_converter_.AddMonotonic(
988 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
989 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
990 // skew to be 200 uS/s
991 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
992 {chrono::milliseconds(95),
993 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
994 // Run another 200 ms to have one logger start first.
995 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
996 {chrono::milliseconds(200), chrono::milliseconds(200)});
997 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
998 // go far enough to cause problems if this isn't accounted for.
999 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1000 {chrono::milliseconds(20000),
1001 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1002 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1003 {chrono::milliseconds(40000),
1004 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1005 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1006 {chrono::milliseconds(400), chrono::milliseconds(400)});
1007
Austin Schuh8fb4b452023-08-04 17:02:27 -07001008 std::vector<std::string> actual_filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07001009 {
1010 LoggerState pi2_logger = MakeLogger(pi2_);
1011
1012 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1013 << pi2_->realtime_now() << " distributed "
1014 << pi2_->ToDistributedClock(pi2_->monotonic_now());
1015
1016 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1017 << pi2_->realtime_now() << " distributed "
1018 << pi2_->ToDistributedClock(pi2_->monotonic_now());
1019
1020 event_loop_factory_.RunFor(startup_sleep1);
1021
1022 StartLogger(&pi2_logger);
1023
1024 event_loop_factory_.RunFor(startup_sleep2);
1025
1026 {
1027 // Run pi1's logger for only part of the time.
1028 LoggerState pi1_logger = MakeLogger(pi1_);
1029
1030 StartLogger(&pi1_logger);
1031 event_loop_factory_.RunFor(logger_run1);
1032
1033 // Make sure we slewed time far enough so that the difference is greater
1034 // than the network delay. This confirms that if we sort incorrectly, it
1035 // would show in the results.
1036 EXPECT_LT(
1037 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1038 -event_loop_factory_.send_delay() -
1039 event_loop_factory_.network_delay());
1040
1041 event_loop_factory_.RunFor(logger_run2);
1042
1043 // And now check that we went far enough the other way to make sure we
1044 // cover both problems.
1045 EXPECT_GT(
1046 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1047 event_loop_factory_.send_delay() +
1048 event_loop_factory_.network_delay());
Austin Schuh8fb4b452023-08-04 17:02:27 -07001049
1050 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001051 }
1052
1053 // And log a bit more on pi2.
1054 event_loop_factory_.RunFor(logger_run3);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001055
1056 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001057 }
1058
Austin Schuh8fb4b452023-08-04 17:02:27 -07001059 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001060 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1061 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001062
1063 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1064 log_reader_factory.set_send_delay(chrono::microseconds(0));
1065
1066 const Node *pi1 =
1067 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1068 const Node *pi2 =
1069 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1070
1071 // This sends out the fetched messages and advances time to the start of the
1072 // log file.
1073 reader.Register(&log_reader_factory);
1074
1075 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1076 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1077 LOG(INFO) << "now pi1 "
1078 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1079 LOG(INFO) << "now pi2 "
1080 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1081
1082 LOG(INFO) << "Done registering (pi1) "
1083 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1084 << " "
1085 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1086 LOG(INFO) << "Done registering (pi2) "
1087 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1088 << " "
1089 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1090
1091 EXPECT_THAT(reader.LoggedNodes(),
1092 ::testing::ElementsAre(
1093 configuration::GetNode(reader.logged_configuration(), pi1),
1094 configuration::GetNode(reader.logged_configuration(), pi2)));
1095
1096 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1097
1098 std::unique_ptr<EventLoop> pi1_event_loop =
1099 log_reader_factory.MakeEventLoop("test", pi1);
1100 std::unique_ptr<EventLoop> pi2_event_loop =
1101 log_reader_factory.MakeEventLoop("test", pi2);
1102
1103 int pi1_ping_count = 30;
1104 int pi2_ping_count = 30;
1105 int pi1_pong_count = 30;
1106 int pi2_pong_count = 30;
1107
1108 // Confirm that the ping value matches.
1109 pi1_event_loop->MakeWatcher(
1110 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1111 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1112 << pi1_event_loop->context().monotonic_remote_time << " -> "
1113 << pi1_event_loop->context().monotonic_event_time;
1114 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1115
1116 ++pi1_ping_count;
1117 });
1118 pi2_event_loop->MakeWatcher(
1119 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1120 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1121 << pi2_event_loop->context().monotonic_remote_time << " -> "
1122 << pi2_event_loop->context().monotonic_event_time;
1123 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1124
1125 ++pi2_ping_count;
1126 });
1127
1128 // Confirm that the ping and pong counts both match, and the value also
1129 // matches.
1130 pi1_event_loop->MakeWatcher(
1131 "/test", [&pi1_event_loop, &pi1_ping_count,
1132 &pi1_pong_count](const examples::Pong &pong) {
1133 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1134 << pi1_event_loop->context().monotonic_remote_time << " -> "
1135 << pi1_event_loop->context().monotonic_event_time;
1136
1137 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1138 ++pi1_pong_count;
1139 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1140 });
1141 pi2_event_loop->MakeWatcher(
1142 "/test", [&pi2_event_loop, &pi2_ping_count,
1143 &pi2_pong_count](const examples::Pong &pong) {
1144 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1145 << pi2_event_loop->context().monotonic_remote_time << " -> "
1146 << pi2_event_loop->context().monotonic_event_time;
1147
1148 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1149 ++pi2_pong_count;
1150 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1151 });
1152
1153 log_reader_factory.Run();
1154 EXPECT_EQ(pi1_ping_count, 6030);
1155 EXPECT_EQ(pi2_ping_count, 6030);
1156 EXPECT_EQ(pi1_pong_count, 6030);
1157 EXPECT_EQ(pi2_pong_count, 6030);
1158
1159 reader.Deregister();
1160}
1161
1162// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
1163TEST_P(MultinodeLoggerTest, SortParts) {
1164 time_converter_.StartEqual();
1165 // Make a bunch of parts.
1166 {
1167 LoggerState pi1_logger = MakeLogger(pi1_);
1168 LoggerState pi2_logger = MakeLogger(pi2_);
1169
1170 event_loop_factory_.RunFor(chrono::milliseconds(95));
1171
1172 StartLogger(&pi1_logger);
1173 StartLogger(&pi2_logger);
1174
1175 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1176 }
1177
1178 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1179 VerifyParts(sorted_parts);
1180}
1181
1182// Tests that we can sort a bunch of parts with an empty part. We should ignore
1183// it and remove it from the sorted list.
1184TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07001185 std::vector<std::string> actual_filenames;
1186
Naman Guptaa63aa132023-03-22 20:06:34 -07001187 time_converter_.StartEqual();
1188 // Make a bunch of parts.
1189 {
1190 LoggerState pi1_logger = MakeLogger(pi1_);
1191 LoggerState pi2_logger = MakeLogger(pi2_);
1192
1193 event_loop_factory_.RunFor(chrono::milliseconds(95));
1194
1195 StartLogger(&pi1_logger);
1196 StartLogger(&pi2_logger);
1197
1198 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001199 pi1_logger.AppendAllFilenames(&actual_filenames);
1200 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001201 }
1202
1203 // TODO(austin): Should we flip out if the file can't open?
1204 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
1205
1206 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
Austin Schuh8fb4b452023-08-04 17:02:27 -07001207 actual_filenames.emplace_back(kEmptyFile);
Naman Guptaa63aa132023-03-22 20:06:34 -07001208
Austin Schuh8fb4b452023-08-04 17:02:27 -07001209 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001210 VerifyParts(sorted_parts, {kEmptyFile});
1211}
1212
1213// Tests that we can sort a bunch of parts with the end missing off a
1214// file. We should use the part we can read.
1215TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07001216 if (file_strategy() == FileStrategy::kCombine) {
1217 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
1218 }
1219
Naman Guptaa63aa132023-03-22 20:06:34 -07001220 std::vector<std::string> actual_filenames;
1221 time_converter_.StartEqual();
1222 // Make a bunch of parts.
1223 {
1224 LoggerState pi1_logger = MakeLogger(pi1_);
1225 LoggerState pi2_logger = MakeLogger(pi2_);
1226
1227 event_loop_factory_.RunFor(chrono::milliseconds(95));
1228
1229 StartLogger(&pi1_logger);
1230 StartLogger(&pi2_logger);
1231
1232 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1233
1234 pi1_logger.AppendAllFilenames(&actual_filenames);
1235 pi2_logger.AppendAllFilenames(&actual_filenames);
1236 }
1237
1238 ASSERT_THAT(actual_filenames,
1239 ::testing::UnorderedElementsAreArray(logfiles_));
1240
1241 // Strip off the end of one of the files. Pick one with a lot of data.
1242 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1243 // that we don't corrupt the entire log part.
1244 ::std::string compressed_contents =
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001245 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Naman Guptaa63aa132023-03-22 20:06:34 -07001246
1247 aos::util::WriteStringToFileOrDie(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001248 logfiles_[2],
Naman Guptaa63aa132023-03-22 20:06:34 -07001249 compressed_contents.substr(0, compressed_contents.size() - 100));
1250
1251 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1252 VerifyParts(sorted_parts);
1253}
1254
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001255// Tests that if we remap a logged channel, it shows up correctly.
Naman Guptaa63aa132023-03-22 20:06:34 -07001256TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
1257 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -07001258
1259 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07001260 {
1261 LoggerState pi1_logger = MakeLogger(pi1_);
1262 LoggerState pi2_logger = MakeLogger(pi2_);
1263
1264 event_loop_factory_.RunFor(chrono::milliseconds(95));
1265
1266 StartLogger(&pi1_logger);
1267 StartLogger(&pi2_logger);
1268
1269 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001270
1271 pi1_logger.AppendAllFilenames(&filenames);
1272 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001273 }
1274
Austin Schuh8fb4b452023-08-04 17:02:27 -07001275 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001276 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1277 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001278
1279 // Remap just on pi1.
1280 reader.RemapLoggedChannel<aos::timing::Report>(
1281 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1282
1283 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1284 log_reader_factory.set_send_delay(chrono::microseconds(0));
1285
1286 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1287 // Note: An extra channel gets remapped automatically due to a timestamp
1288 // channel being LOCAL_LOGGER'd.
1289 ASSERT_EQ(remapped_channels.size(), std::get<0>(GetParam()).shared ? 1u : 2u);
1290 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1291 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1292 if (!std::get<0>(GetParam()).shared) {
1293 EXPECT_EQ(remapped_channels[1]->name()->string_view(),
1294 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1295 "aos-message_bridge-Timestamp");
1296 EXPECT_EQ(remapped_channels[1]->type()->string_view(),
1297 "aos.message_bridge.RemoteMessage");
1298 }
1299
1300 reader.Register(&log_reader_factory);
1301
1302 const Node *pi1 =
1303 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1304 const Node *pi2 =
1305 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1306
1307 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1308 // else should have moved.
1309 std::unique_ptr<EventLoop> pi1_event_loop =
1310 log_reader_factory.MakeEventLoop("test", pi1);
1311 pi1_event_loop->SkipTimingReport();
1312 std::unique_ptr<EventLoop> full_pi1_event_loop =
1313 log_reader_factory.MakeEventLoop("test", pi1);
1314 full_pi1_event_loop->SkipTimingReport();
1315 std::unique_ptr<EventLoop> pi2_event_loop =
1316 log_reader_factory.MakeEventLoop("test", pi2);
1317 pi2_event_loop->SkipTimingReport();
1318
1319 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1320 "/aos");
1321 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1322 full_pi1_event_loop.get(), "/pi1/aos");
1323 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1324 pi1_event_loop.get(), "/original/aos");
1325 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1326 full_pi1_event_loop.get(), "/original/pi1/aos");
1327 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1328 "/aos");
1329
1330 log_reader_factory.Run();
1331
1332 EXPECT_EQ(pi1_timing_report.count(), 0u);
1333 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1334 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1335 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1336 EXPECT_NE(pi2_timing_report.count(), 0u);
1337
1338 reader.Deregister();
1339}
1340
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001341// Tests that if we rename a logged channel, it shows up correctly.
1342TEST_P(MultinodeLoggerTest, RenameLoggedChannel) {
1343 std::vector<std::string> actual_filenames;
1344 time_converter_.StartEqual();
1345 {
1346 LoggerState pi1_logger = MakeLogger(pi1_);
1347 LoggerState pi2_logger = MakeLogger(pi2_);
1348
1349 event_loop_factory_.RunFor(chrono::milliseconds(95));
1350
1351 StartLogger(&pi1_logger);
1352 StartLogger(&pi2_logger);
1353
1354 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1355
1356 pi1_logger.AppendAllFilenames(&actual_filenames);
1357 pi2_logger.AppendAllFilenames(&actual_filenames);
1358 }
1359
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001360 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1361 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1362 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001363
1364 // Rename just on pi2. Add some global maps just to verify they get added in
1365 // the config and used correctly.
1366 std::vector<MapT> maps;
1367 {
1368 MapT map;
1369 map.match = std::make_unique<ChannelT>();
1370 map.match->name = "/foo*";
1371 map.match->source_node = "pi1";
1372 map.rename = std::make_unique<ChannelT>();
1373 map.rename->name = "/pi1/foo";
1374 maps.emplace_back(std::move(map));
1375 }
1376 {
1377 MapT map;
1378 map.match = std::make_unique<ChannelT>();
1379 map.match->name = "/foo*";
1380 map.match->source_node = "pi2";
1381 map.rename = std::make_unique<ChannelT>();
1382 map.rename->name = "/pi2/foo";
1383 maps.emplace_back(std::move(map));
1384 }
1385 {
1386 MapT map;
1387 map.match = std::make_unique<ChannelT>();
1388 map.match->name = "/foo";
1389 map.match->type = "aos.examples.Ping";
1390 map.rename = std::make_unique<ChannelT>();
1391 map.rename->name = "/foo/renamed";
1392 maps.emplace_back(std::move(map));
1393 }
1394 reader.RenameLoggedChannel<aos::examples::Ping>(
1395 "/aos", configuration::GetNode(reader.configuration(), "pi2"),
1396 "/pi2/foo/renamed", maps);
1397
1398 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1399 log_reader_factory.set_send_delay(chrono::microseconds(0));
1400
1401 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1402 // Note: An extra channel gets remapped automatically due to a timestamp
1403 // channel being LOCAL_LOGGER'd.
1404 const bool shared = std::get<0>(GetParam()).shared;
1405 ASSERT_EQ(remapped_channels.size(), shared ? 1u : 2u);
1406 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->name()->string_view(),
1407 "/pi2/foo/renamed");
1408 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->type()->string_view(),
1409 "aos.examples.Ping");
1410 if (!shared) {
1411 EXPECT_EQ(remapped_channels[0]->name()->string_view(),
1412 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1413 "aos-message_bridge-Timestamp");
1414 EXPECT_EQ(remapped_channels[0]->type()->string_view(),
1415 "aos.message_bridge.RemoteMessage");
1416 }
1417
1418 reader.Register(&log_reader_factory);
1419
1420 const Node *pi1 =
1421 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1422 const Node *pi2 =
1423 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1424
1425 // Confirm we can read the data on the renamed channel, just for pi2. Nothing
1426 // else should have moved.
1427 std::unique_ptr<EventLoop> pi2_event_loop =
1428 log_reader_factory.MakeEventLoop("test", pi2);
1429 pi2_event_loop->SkipTimingReport();
1430 std::unique_ptr<EventLoop> full_pi2_event_loop =
1431 log_reader_factory.MakeEventLoop("test", pi2);
1432 full_pi2_event_loop->SkipTimingReport();
1433 std::unique_ptr<EventLoop> pi1_event_loop =
1434 log_reader_factory.MakeEventLoop("test", pi1);
1435 pi1_event_loop->SkipTimingReport();
1436
1437 MessageCounter<aos::examples::Ping> pi2_ping(pi2_event_loop.get(), "/aos");
1438 MessageCounter<aos::examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1439 "/foo");
1440 MessageCounter<aos::examples::Ping> full_pi2_renamed_ping(
1441 full_pi2_event_loop.get(), "/pi2/foo/renamed");
1442 MessageCounter<aos::examples::Ping> pi1_ping(pi1_event_loop.get(), "/aos");
1443
1444 log_reader_factory.Run();
1445
1446 EXPECT_EQ(pi2_ping.count(), 0u);
1447 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1448 EXPECT_NE(full_pi2_renamed_ping.count(), 0u);
1449 EXPECT_NE(pi1_ping.count(), 0u);
1450
1451 reader.Deregister();
1452}
1453
Naman Guptaa63aa132023-03-22 20:06:34 -07001454// Tests that we can remap a forwarded channel as well.
1455TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1456 time_converter_.StartEqual();
1457 {
1458 LoggerState pi1_logger = MakeLogger(pi1_);
1459 LoggerState pi2_logger = MakeLogger(pi2_);
1460
1461 event_loop_factory_.RunFor(chrono::milliseconds(95));
1462
1463 StartLogger(&pi1_logger);
1464 StartLogger(&pi2_logger);
1465
1466 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1467 }
1468
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001469 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1470 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1471 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001472
1473 reader.RemapLoggedChannel<examples::Ping>("/test");
1474
1475 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1476 log_reader_factory.set_send_delay(chrono::microseconds(0));
1477
1478 reader.Register(&log_reader_factory);
1479
1480 const Node *pi1 =
1481 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1482 const Node *pi2 =
1483 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1484
1485 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1486 // else should have moved.
1487 std::unique_ptr<EventLoop> pi1_event_loop =
1488 log_reader_factory.MakeEventLoop("test", pi1);
1489 pi1_event_loop->SkipTimingReport();
1490 std::unique_ptr<EventLoop> full_pi1_event_loop =
1491 log_reader_factory.MakeEventLoop("test", pi1);
1492 full_pi1_event_loop->SkipTimingReport();
1493 std::unique_ptr<EventLoop> pi2_event_loop =
1494 log_reader_factory.MakeEventLoop("test", pi2);
1495 pi2_event_loop->SkipTimingReport();
1496
1497 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1498 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1499 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1500 "/original/test");
1501 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1502 "/original/test");
1503
1504 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1505 pi1_original_ping_timestamp;
1506 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1507 pi1_ping_timestamp;
1508 if (!shared()) {
1509 pi1_original_ping_timestamp =
1510 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1511 pi1_event_loop.get(),
1512 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1513 pi1_ping_timestamp =
1514 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1515 pi1_event_loop.get(),
1516 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1517 }
1518
1519 log_reader_factory.Run();
1520
1521 EXPECT_EQ(pi1_ping.count(), 0u);
1522 EXPECT_EQ(pi2_ping.count(), 0u);
1523 EXPECT_NE(pi1_original_ping.count(), 0u);
1524 EXPECT_NE(pi2_original_ping.count(), 0u);
1525 if (!shared()) {
1526 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1527 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1528 }
1529
1530 reader.Deregister();
1531}
1532
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001533// Tests that we can rename a forwarded channel as well.
1534TEST_P(MultinodeLoggerTest, RenameForwardedLoggedChannel) {
1535 std::vector<std::string> actual_filenames;
1536 time_converter_.StartEqual();
1537 {
1538 LoggerState pi1_logger = MakeLogger(pi1_);
1539 LoggerState pi2_logger = MakeLogger(pi2_);
1540
1541 event_loop_factory_.RunFor(chrono::milliseconds(95));
1542
1543 StartLogger(&pi1_logger);
1544 StartLogger(&pi2_logger);
1545
1546 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1547
1548 pi1_logger.AppendAllFilenames(&actual_filenames);
1549 pi2_logger.AppendAllFilenames(&actual_filenames);
1550 }
1551
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001552 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1553 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1554 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001555
1556 std::vector<MapT> maps;
1557 {
1558 MapT map;
1559 map.match = std::make_unique<ChannelT>();
1560 map.match->name = "/production*";
1561 map.match->source_node = "pi1";
1562 map.rename = std::make_unique<ChannelT>();
1563 map.rename->name = "/pi1/production";
1564 maps.emplace_back(std::move(map));
1565 }
1566 {
1567 MapT map;
1568 map.match = std::make_unique<ChannelT>();
1569 map.match->name = "/production*";
1570 map.match->source_node = "pi2";
1571 map.rename = std::make_unique<ChannelT>();
1572 map.rename->name = "/pi2/production";
1573 maps.emplace_back(std::move(map));
1574 }
1575 reader.RenameLoggedChannel<aos::examples::Ping>(
1576 "/test", configuration::GetNode(reader.configuration(), "pi1"),
1577 "/pi1/production", maps);
1578
1579 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1580 log_reader_factory.set_send_delay(chrono::microseconds(0));
1581
1582 reader.Register(&log_reader_factory);
1583
1584 const Node *pi1 =
1585 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1586 const Node *pi2 =
1587 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1588
1589 // Confirm we can read the data on the renamed channel, on both the source
1590 // node and the remote node. In case of split timestamp channels, confirm that
1591 // we receive the timestamp messages on the renamed channel as well.
1592 std::unique_ptr<EventLoop> pi1_event_loop =
1593 log_reader_factory.MakeEventLoop("test", pi1);
1594 pi1_event_loop->SkipTimingReport();
1595 std::unique_ptr<EventLoop> full_pi1_event_loop =
1596 log_reader_factory.MakeEventLoop("test", pi1);
1597 full_pi1_event_loop->SkipTimingReport();
1598 std::unique_ptr<EventLoop> pi2_event_loop =
1599 log_reader_factory.MakeEventLoop("test", pi2);
1600 pi2_event_loop->SkipTimingReport();
1601
1602 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1603 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1604 MessageCounter<examples::Ping> pi1_renamed_ping(pi1_event_loop.get(),
1605 "/pi1/production");
1606 MessageCounter<examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1607 "/pi1/production");
1608
1609 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1610 pi1_renamed_ping_timestamp;
1611 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1612 pi1_ping_timestamp;
1613 if (!shared()) {
1614 pi1_renamed_ping_timestamp =
1615 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1616 pi1_event_loop.get(),
1617 "/pi1/aos/remote_timestamps/pi2/pi1/production/aos-examples-Ping");
1618 pi1_ping_timestamp =
1619 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1620 pi1_event_loop.get(),
1621 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1622 }
1623
1624 log_reader_factory.Run();
1625
1626 EXPECT_EQ(pi1_ping.count(), 0u);
1627 EXPECT_EQ(pi2_ping.count(), 0u);
1628 EXPECT_NE(pi1_renamed_ping.count(), 0u);
1629 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1630 if (!shared()) {
1631 EXPECT_NE(pi1_renamed_ping_timestamp->count(), 0u);
1632 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1633 }
1634
1635 reader.Deregister();
1636}
1637
Naman Guptaa63aa132023-03-22 20:06:34 -07001638// Tests that we observe all the same events in log replay (for a given node)
1639// whether we just register an event loop for that node or if we register a full
1640// event loop factory.
1641TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
1642 time_converter_.StartEqual();
1643 constexpr chrono::milliseconds kStartupDelay(95);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001644 std::vector<std::string> filenames;
1645
Naman Guptaa63aa132023-03-22 20:06:34 -07001646 {
1647 LoggerState pi1_logger = MakeLogger(pi1_);
1648 LoggerState pi2_logger = MakeLogger(pi2_);
1649
1650 event_loop_factory_.RunFor(kStartupDelay);
1651
1652 StartLogger(&pi1_logger);
1653 StartLogger(&pi2_logger);
1654
1655 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001656
1657 pi1_logger.AppendAllFilenames(&filenames);
1658 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001659 }
1660
Austin Schuh8fb4b452023-08-04 17:02:27 -07001661 LogReader full_reader(SortParts(filenames));
1662 LogReader single_node_reader(SortParts(filenames));
Naman Guptaa63aa132023-03-22 20:06:34 -07001663
1664 SimulatedEventLoopFactory full_factory(full_reader.configuration());
1665 SimulatedEventLoopFactory single_node_factory(
1666 single_node_reader.configuration());
1667 single_node_factory.SkipTimingReport();
1668 single_node_factory.DisableStatistics();
1669 std::unique_ptr<EventLoop> replay_event_loop =
1670 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
1671 "log_reader");
1672
1673 full_reader.Register(&full_factory);
1674 single_node_reader.Register(replay_event_loop.get());
1675
1676 const Node *full_pi1 =
1677 configuration::GetNode(full_factory.configuration(), "pi1");
1678
1679 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1680 // else should have moved.
1681 std::unique_ptr<EventLoop> full_event_loop =
1682 full_factory.MakeEventLoop("test", full_pi1);
1683 full_event_loop->SkipTimingReport();
1684 full_event_loop->SkipAosLog();
1685 // maps are indexed on channel index.
1686 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
1687 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
1688 observed_messages;
1689 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
1690 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
1691 ++ii) {
1692 const Channel *channel =
1693 full_event_loop->configuration()->channels()->Get(ii);
1694 // We currently don't support replaying remote timestamp channels in
1695 // realtime replay (unless the remote timestamp channel was not NOT_LOGGED,
1696 // in which case it gets auto-remapped and replayed on a /original channel).
1697 if (channel->name()->string_view().find("remote_timestamp") !=
1698 std::string_view::npos &&
1699 channel->name()->string_view().find("/original") ==
1700 std::string_view::npos) {
1701 continue;
1702 }
1703 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
1704 observed_messages[ii] = {};
1705 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
1706 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
1707 if (fetchers[ii]->Fetch()) {
1708 observed_messages[ii].push_back(std::make_pair(
1709 fetchers[ii]->context().monotonic_event_time, true));
1710 }
1711 });
1712 full_event_loop->MakeRawNoArgWatcher(
1713 channel, [ii, &observed_messages](const Context &context) {
1714 observed_messages[ii].push_back(
1715 std::make_pair(context.monotonic_event_time, false));
1716 });
1717 }
1718 }
1719
1720 full_factory.Run();
1721 fetchers.clear();
1722 full_reader.Deregister();
1723
1724 const Node *single_node_pi1 =
1725 configuration::GetNode(single_node_factory.configuration(), "pi1");
1726 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
1727
1728 std::unique_ptr<EventLoop> single_node_event_loop =
1729 single_node_factory.MakeEventLoop("test", single_node_pi1);
1730 single_node_event_loop->SkipTimingReport();
1731 single_node_event_loop->SkipAosLog();
1732 for (size_t ii = 0;
1733 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
1734 const Channel *channel =
1735 single_node_event_loop->configuration()->channels()->Get(ii);
1736 single_node_factory.DisableForwarding(channel);
1737 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
1738 single_node_fetchers[ii] =
1739 single_node_event_loop->MakeRawFetcher(channel);
1740 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
1741 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
1742 << "Single EventLoop replay doesn't support pre-loading fetchers. "
1743 << configuration::StrippedChannelToString(channel);
1744 });
1745 single_node_event_loop->MakeRawNoArgWatcher(
1746 channel, [ii, &observed_messages, channel,
1747 kStartupDelay](const Context &context) {
1748 if (observed_messages[ii].empty()) {
1749 FAIL() << "Observed extra message at "
1750 << context.monotonic_event_time << " on "
1751 << configuration::StrippedChannelToString(channel);
1752 return;
1753 }
1754 const std::pair<monotonic_clock::time_point, bool> &message =
1755 observed_messages[ii].front();
1756 if (message.second) {
1757 EXPECT_LE(message.first,
1758 context.monotonic_event_time + kStartupDelay)
1759 << "Mismatched message times " << context.monotonic_event_time
1760 << " and " << message.first << " on "
1761 << configuration::StrippedChannelToString(channel);
1762 } else {
1763 EXPECT_EQ(message.first,
1764 context.monotonic_event_time + kStartupDelay)
1765 << "Mismatched message times " << context.monotonic_event_time
1766 << " and " << message.first << " on "
1767 << configuration::StrippedChannelToString(channel);
1768 }
1769 observed_messages[ii].erase(observed_messages[ii].begin());
1770 });
1771 }
1772 }
1773
1774 single_node_factory.Run();
1775
1776 single_node_fetchers.clear();
1777
1778 single_node_reader.Deregister();
1779
1780 for (const auto &pair : observed_messages) {
1781 EXPECT_TRUE(pair.second.empty())
1782 << "Missed " << pair.second.size() << " messages on "
1783 << configuration::StrippedChannelToString(
1784 single_node_event_loop->configuration()->channels()->Get(
1785 pair.first));
1786 }
1787}
1788
1789// Tests that we properly recreate forwarded timestamps when replaying a log.
1790// This should be enough that we can then re-run the logger and get a valid log
1791// back.
1792TEST_P(MultinodeLoggerTest, MessageHeader) {
1793 time_converter_.StartEqual();
1794 {
1795 LoggerState pi1_logger = MakeLogger(pi1_);
1796 LoggerState pi2_logger = MakeLogger(pi2_);
1797
1798 event_loop_factory_.RunFor(chrono::milliseconds(95));
1799
1800 StartLogger(&pi1_logger);
1801 StartLogger(&pi2_logger);
1802
1803 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1804 }
1805
1806 LogReader reader(SortParts(logfiles_));
1807
1808 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1809 log_reader_factory.set_send_delay(chrono::microseconds(0));
1810
1811 // This sends out the fetched messages and advances time to the start of the
1812 // log file.
1813 reader.Register(&log_reader_factory);
1814
1815 const Node *pi1 =
1816 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1817 const Node *pi2 =
1818 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1819
1820 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1821 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1822 LOG(INFO) << "now pi1 "
1823 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1824 LOG(INFO) << "now pi2 "
1825 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1826
1827 EXPECT_THAT(reader.LoggedNodes(),
1828 ::testing::ElementsAre(
1829 configuration::GetNode(reader.logged_configuration(), pi1),
1830 configuration::GetNode(reader.logged_configuration(), pi2)));
1831
1832 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1833
1834 std::unique_ptr<EventLoop> pi1_event_loop =
1835 log_reader_factory.MakeEventLoop("test", pi1);
1836 std::unique_ptr<EventLoop> pi2_event_loop =
1837 log_reader_factory.MakeEventLoop("test", pi2);
1838
1839 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1840 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1841 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1842 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1843
1844 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1845 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1846 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1847 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1848
1849 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1850 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1851 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1852 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1853
1854 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1855 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1856 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1857 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1858
1859 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1860 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1861 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1862 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1863
1864 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1865 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1866 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1867 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1868
1869 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
1870 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
1871
1872 for (std::pair<int, std::string> channel :
1873 shared()
1874 ? std::vector<
1875 std::pair<int, std::string>>{{-1,
1876 "/aos/remote_timestamps/pi2"}}
1877 : std::vector<std::pair<int, std::string>>{
1878 {pi1_timestamp_channel,
1879 "/aos/remote_timestamps/pi2/pi1/aos/"
1880 "aos-message_bridge-Timestamp"},
1881 {ping_timestamp_channel,
1882 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1883 pi1_event_loop->MakeWatcher(
1884 channel.second,
1885 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1886 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1887 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1888 &ping_on_pi2_fetcher, network_delay, send_delay,
1889 channel_index = channel.first](const RemoteMessage &header) {
1890 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1891 chrono::nanoseconds(header.monotonic_sent_time()));
1892 const aos::realtime_clock::time_point header_realtime_sent_time(
1893 chrono::nanoseconds(header.realtime_sent_time()));
1894 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1895 chrono::nanoseconds(header.monotonic_remote_time()));
1896 const aos::realtime_clock::time_point header_realtime_remote_time(
1897 chrono::nanoseconds(header.realtime_remote_time()));
1898
1899 if (channel_index != -1) {
1900 ASSERT_EQ(channel_index, header.channel_index());
1901 }
1902
1903 const Context *pi1_context = nullptr;
1904 const Context *pi2_context = nullptr;
1905
1906 if (header.channel_index() == pi1_timestamp_channel) {
1907 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1908 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1909 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1910 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1911 } else if (header.channel_index() == ping_timestamp_channel) {
1912 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1913 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1914 pi1_context = &ping_on_pi1_fetcher.context();
1915 pi2_context = &ping_on_pi2_fetcher.context();
1916 } else {
1917 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1918 << configuration::CleanedChannelToString(
1919 pi1_event_loop->configuration()->channels()->Get(
1920 header.channel_index()));
1921 }
1922
1923 ASSERT_TRUE(header.has_boot_uuid());
1924 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1925 pi2_event_loop->boot_uuid());
1926
1927 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1928 EXPECT_EQ(pi2_context->remote_queue_index,
1929 header.remote_queue_index());
1930 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
1931
1932 EXPECT_EQ(pi2_context->monotonic_event_time,
1933 header_monotonic_sent_time);
1934 EXPECT_EQ(pi2_context->realtime_event_time,
1935 header_realtime_sent_time);
1936 EXPECT_EQ(pi2_context->realtime_remote_time,
1937 header_realtime_remote_time);
1938 EXPECT_EQ(pi2_context->monotonic_remote_time,
1939 header_monotonic_remote_time);
1940
1941 EXPECT_EQ(pi1_context->realtime_event_time,
1942 header_realtime_remote_time);
1943 EXPECT_EQ(pi1_context->monotonic_event_time,
1944 header_monotonic_remote_time);
1945
1946 // Time estimation isn't perfect, but we know the clocks were
1947 // identical when logged, so we know when this should have come back.
1948 // Confirm we got it when we expected.
1949 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
1950 pi1_context->monotonic_event_time + 2 * network_delay +
1951 send_delay);
1952 });
1953 }
1954 for (std::pair<int, std::string> channel :
1955 shared()
1956 ? std::vector<
1957 std::pair<int, std::string>>{{-1,
1958 "/aos/remote_timestamps/pi1"}}
1959 : std::vector<std::pair<int, std::string>>{
1960 {pi2_timestamp_channel,
1961 "/aos/remote_timestamps/pi1/pi2/aos/"
1962 "aos-message_bridge-Timestamp"}}) {
1963 pi2_event_loop->MakeWatcher(
1964 channel.second,
1965 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
1966 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
1967 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
1968 &pong_on_pi1_fetcher, network_delay, send_delay,
1969 channel_index = channel.first](const RemoteMessage &header) {
1970 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1971 chrono::nanoseconds(header.monotonic_sent_time()));
1972 const aos::realtime_clock::time_point header_realtime_sent_time(
1973 chrono::nanoseconds(header.realtime_sent_time()));
1974 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1975 chrono::nanoseconds(header.monotonic_remote_time()));
1976 const aos::realtime_clock::time_point header_realtime_remote_time(
1977 chrono::nanoseconds(header.realtime_remote_time()));
1978
1979 if (channel_index != -1) {
1980 ASSERT_EQ(channel_index, header.channel_index());
1981 }
1982
1983 const Context *pi2_context = nullptr;
1984 const Context *pi1_context = nullptr;
1985
1986 if (header.channel_index() == pi2_timestamp_channel) {
1987 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
1988 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
1989 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
1990 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
1991 } else if (header.channel_index() == pong_timestamp_channel) {
1992 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
1993 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
1994 pi2_context = &pong_on_pi2_fetcher.context();
1995 pi1_context = &pong_on_pi1_fetcher.context();
1996 } else {
1997 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1998 << configuration::CleanedChannelToString(
1999 pi2_event_loop->configuration()->channels()->Get(
2000 header.channel_index()));
2001 }
2002
2003 ASSERT_TRUE(header.has_boot_uuid());
2004 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2005 pi1_event_loop->boot_uuid());
2006
2007 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2008 EXPECT_EQ(pi1_context->remote_queue_index,
2009 header.remote_queue_index());
2010 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
2011
2012 EXPECT_EQ(pi1_context->monotonic_event_time,
2013 header_monotonic_sent_time);
2014 EXPECT_EQ(pi1_context->realtime_event_time,
2015 header_realtime_sent_time);
2016 EXPECT_EQ(pi1_context->realtime_remote_time,
2017 header_realtime_remote_time);
2018 EXPECT_EQ(pi1_context->monotonic_remote_time,
2019 header_monotonic_remote_time);
2020
2021 EXPECT_EQ(pi2_context->realtime_event_time,
2022 header_realtime_remote_time);
2023 EXPECT_EQ(pi2_context->monotonic_event_time,
2024 header_monotonic_remote_time);
2025
2026 // Time estimation isn't perfect, but we know the clocks were
2027 // identical when logged, so we know when this should have come back.
2028 // Confirm we got it when we expected.
2029 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2030 pi2_context->monotonic_event_time + 2 * network_delay +
2031 send_delay);
2032 });
2033 }
2034
2035 // And confirm we can re-create a log again, while checking the contents.
2036 {
2037 LoggerState pi1_logger = MakeLogger(
2038 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
2039 LoggerState pi2_logger = MakeLogger(
2040 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
2041
Austin Schuh8fb4b452023-08-04 17:02:27 -07002042 StartLogger(&pi1_logger, tmp_dir_ + "/logs/relogged1");
2043 StartLogger(&pi2_logger, tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07002044
2045 log_reader_factory.Run();
2046 }
2047
2048 reader.Deregister();
2049
2050 // And verify that we can run the LogReader over the relogged files without
2051 // hitting any fatal errors.
2052 {
Austin Schuh8fb4b452023-08-04 17:02:27 -07002053 LogReader relogged_reader(SortParts(
2054 MakeLogFiles(tmp_dir_ + "/logs/relogged1", tmp_dir_ + "/logs/relogged2",
2055 1, 1, 2, 2, true)));
Naman Guptaa63aa132023-03-22 20:06:34 -07002056 relogged_reader.Register();
2057
2058 relogged_reader.event_loop_factory()->Run();
2059 }
2060 // And confirm that we can read the logged file using the reader's
2061 // configuration.
2062 {
2063 LogReader relogged_reader(
Austin Schuh8fb4b452023-08-04 17:02:27 -07002064 SortParts(MakeLogFiles(tmp_dir_ + "/logs/relogged1",
2065 tmp_dir_ + "/logs/relogged2", 1, 1, 2, 2, true)),
Naman Guptaa63aa132023-03-22 20:06:34 -07002066 reader.configuration());
2067 relogged_reader.Register();
2068
2069 relogged_reader.event_loop_factory()->Run();
2070 }
2071}
2072
2073// Tests that we properly populate and extract the logger_start time by setting
2074// up a clock difference between 2 nodes and looking at the resulting parts.
2075TEST_P(MultinodeLoggerTest, LoggerStartTime) {
2076 std::vector<std::string> actual_filenames;
2077 time_converter_.AddMonotonic(
2078 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2079 {
2080 LoggerState pi1_logger = MakeLogger(pi1_);
2081 LoggerState pi2_logger = MakeLogger(pi2_);
2082
2083 StartLogger(&pi1_logger);
2084 StartLogger(&pi2_logger);
2085
2086 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2087
2088 pi1_logger.AppendAllFilenames(&actual_filenames);
2089 pi2_logger.AppendAllFilenames(&actual_filenames);
2090 }
2091
2092 ASSERT_THAT(actual_filenames,
2093 ::testing::UnorderedElementsAreArray(logfiles_));
2094
Austin Schuh8fb4b452023-08-04 17:02:27 -07002095 for (const LogFile &log_file : SortParts(actual_filenames)) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002096 for (const LogParts &log_part : log_file.parts) {
2097 if (log_part.node == log_file.logger_node) {
2098 EXPECT_EQ(log_part.logger_monotonic_start_time,
2099 aos::monotonic_clock::min_time);
2100 EXPECT_EQ(log_part.logger_realtime_start_time,
2101 aos::realtime_clock::min_time);
2102 } else {
2103 const chrono::seconds offset = log_file.logger_node == "pi1"
2104 ? -chrono::seconds(1000)
2105 : chrono::seconds(1000);
2106 EXPECT_EQ(log_part.logger_monotonic_start_time,
2107 log_part.monotonic_start_time + offset);
2108 EXPECT_EQ(log_part.logger_realtime_start_time,
2109 log_file.realtime_start_time +
2110 (log_part.logger_monotonic_start_time -
2111 log_file.monotonic_start_time));
2112 }
2113 }
2114 }
2115}
2116
2117// Test that renaming the base, renames the folder.
2118TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002119 time_converter_.AddMonotonic(
2120 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002121 logfile_base1_ = tmp_dir_ + "/logs/renamefolder/multi_logfile1";
2122 logfile_base2_ = tmp_dir_ + "/logs/renamefolder/multi_logfile2";
2123
Naman Guptaa63aa132023-03-22 20:06:34 -07002124 LoggerState pi1_logger = MakeLogger(pi1_);
2125 LoggerState pi2_logger = MakeLogger(pi2_);
2126
2127 StartLogger(&pi1_logger);
2128 StartLogger(&pi2_logger);
2129
2130 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002131 logfile_base1_ = tmp_dir_ + "/logs/new-good/multi_logfile1";
2132 logfile_base2_ = tmp_dir_ + "/logs/new-good/multi_logfile2";
Naman Guptaa63aa132023-03-22 20:06:34 -07002133 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
Alexei Strotscaf17d32023-04-03 22:31:11 -07002134
2135 // Sequence of set_base_name and Rotate simulates rename operation. Since
2136 // rename is not supported by all namers, RenameLogBase moved from logger to
2137 // the higher level abstraction, yet log_namers support rename, and it is
2138 // legal to test it here.
2139 pi1_logger.log_namer->set_base_name(logfile_base1_);
2140 pi1_logger.logger->Rotate();
2141 pi2_logger.log_namer->set_base_name(logfile_base2_);
2142 pi2_logger.logger->Rotate();
2143
Naman Guptaa63aa132023-03-22 20:06:34 -07002144 for (auto &file : logfiles_) {
2145 struct stat s;
2146 EXPECT_EQ(0, stat(file.c_str(), &s));
2147 }
2148}
2149
2150// Test that renaming the file base dies.
2151TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2152 time_converter_.AddMonotonic(
2153 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002154 logfile_base1_ = tmp_dir_ + "/logs/renamefile/multi_logfile1";
2155 logfile_base2_ = tmp_dir_ + "/logs/renamefile/multi_logfile2";
2156
Naman Guptaa63aa132023-03-22 20:06:34 -07002157 LoggerState pi1_logger = MakeLogger(pi1_);
2158 StartLogger(&pi1_logger);
2159 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002160 logfile_base1_ = tmp_dir_ + "/logs/new-renamefile/new_multi_logfile1";
Alexei Strotscaf17d32023-04-03 22:31:11 -07002161 EXPECT_DEATH({ pi1_logger.log_namer->set_base_name(logfile_base1_); },
Naman Guptaa63aa132023-03-22 20:06:34 -07002162 "Rename of file base from");
2163}
2164
2165// TODO(austin): We can write a test which recreates a logfile and confirms that
2166// we get it back. That is the ultimate test.
2167
2168// Tests that we properly recreate forwarded timestamps when replaying a log.
2169// This should be enough that we can then re-run the logger and get a valid log
2170// back.
2171TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002172 if (file_strategy() == FileStrategy::kCombine) {
2173 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2174 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002175 std::vector<std::string> actual_filenames;
2176
2177 const UUID pi1_boot0 = UUID::Random();
2178 const UUID pi2_boot0 = UUID::Random();
2179 const UUID pi2_boot1 = UUID::Random();
2180 {
2181 CHECK_EQ(pi1_index_, 0u);
2182 CHECK_EQ(pi2_index_, 1u);
2183
2184 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2185 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2186 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2187
2188 time_converter_.AddNextTimestamp(
2189 distributed_clock::epoch(),
2190 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2191 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2192 time_converter_.AddNextTimestamp(
2193 distributed_clock::epoch() + reboot_time,
2194 {BootTimestamp::epoch() + reboot_time,
2195 BootTimestamp{
2196 .boot = 1,
2197 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2198 }
2199
2200 {
2201 LoggerState pi1_logger = MakeLogger(pi1_);
2202
2203 event_loop_factory_.RunFor(chrono::milliseconds(95));
2204 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2205 pi1_boot0);
2206 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2207 pi2_boot0);
2208
2209 StartLogger(&pi1_logger);
2210
2211 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2212
2213 VLOG(1) << "Reboot now!";
2214
2215 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2216 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2217 pi1_boot0);
2218 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2219 pi2_boot1);
2220
2221 pi1_logger.AppendAllFilenames(&actual_filenames);
2222 }
2223
2224 std::sort(actual_filenames.begin(), actual_filenames.end());
2225 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2226 ASSERT_THAT(actual_filenames,
2227 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2228
2229 // Confirm that our new oldest timestamps properly update as we reboot and
2230 // rotate.
2231 for (const std::string &file : pi1_reboot_logfiles_) {
2232 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2233 ReadHeader(file);
2234 CHECK(log_header);
2235 if (log_header->message().has_configuration()) {
2236 continue;
2237 }
2238
2239 const monotonic_clock::time_point monotonic_start_time =
2240 monotonic_clock::time_point(
2241 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2242 const UUID source_node_boot_uuid = UUID::FromString(
2243 log_header->message().source_node_boot_uuid()->string_view());
2244
2245 if (log_header->message().node()->name()->string_view() != "pi1") {
2246 // The remote message channel should rotate later and have more parts.
2247 // This only is true on the log files with shared remote messages.
2248 //
2249 // TODO(austin): I'm not the most thrilled with this test pattern... It
2250 // feels brittle in a different way.
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002251 if (file.find("timestamps/remote_pi2") == std::string::npos) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002252 switch (log_header->message().parts_index()) {
2253 case 0:
2254 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2255 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2256 break;
2257 case 1:
2258 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2259 ASSERT_EQ(monotonic_start_time,
2260 monotonic_clock::epoch() + chrono::seconds(1));
2261 break;
2262 case 2:
2263 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2264 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2265 break;
2266 case 3:
2267 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2268 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2269 chrono::nanoseconds(2322999462))
2270 << " on " << file;
2271 break;
2272 default:
2273 FAIL();
2274 break;
2275 }
2276 } else {
2277 switch (log_header->message().parts_index()) {
2278 case 0:
2279 case 1:
2280 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2281 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2282 break;
2283 case 2:
2284 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2285 ASSERT_EQ(monotonic_start_time,
2286 monotonic_clock::epoch() + chrono::seconds(1));
2287 break;
2288 case 3:
2289 case 4:
2290 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2291 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2292 break;
2293 case 5:
2294 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2295 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2296 chrono::nanoseconds(2322999462))
2297 << " on " << file;
2298 break;
2299 default:
2300 FAIL();
2301 break;
2302 }
2303 }
2304 continue;
2305 }
2306 SCOPED_TRACE(file);
2307 SCOPED_TRACE(aos::FlatbufferToJson(
2308 *log_header, {.multi_line = true, .max_vector_size = 100}));
2309 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2310 ASSERT_EQ(
2311 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2312 EXPECT_EQ(
2313 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2314 monotonic_clock::max_time.time_since_epoch().count());
2315 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2316 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2317 2u);
2318 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2319 monotonic_clock::max_time.time_since_epoch().count());
2320 ASSERT_TRUE(log_header->message()
2321 .has_oldest_remote_unreliable_monotonic_timestamps());
2322 ASSERT_EQ(log_header->message()
2323 .oldest_remote_unreliable_monotonic_timestamps()
2324 ->size(),
2325 2u);
2326 EXPECT_EQ(log_header->message()
2327 .oldest_remote_unreliable_monotonic_timestamps()
2328 ->Get(0),
2329 monotonic_clock::max_time.time_since_epoch().count());
2330 ASSERT_TRUE(log_header->message()
2331 .has_oldest_local_unreliable_monotonic_timestamps());
2332 ASSERT_EQ(log_header->message()
2333 .oldest_local_unreliable_monotonic_timestamps()
2334 ->size(),
2335 2u);
2336 EXPECT_EQ(log_header->message()
2337 .oldest_local_unreliable_monotonic_timestamps()
2338 ->Get(0),
2339 monotonic_clock::max_time.time_since_epoch().count());
2340
2341 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2342 monotonic_clock::time_point(chrono::nanoseconds(
2343 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2344 1)));
2345 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2346 monotonic_clock::time_point(chrono::nanoseconds(
2347 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2348 const monotonic_clock::time_point
2349 oldest_remote_unreliable_monotonic_timestamps =
2350 monotonic_clock::time_point(chrono::nanoseconds(
2351 log_header->message()
2352 .oldest_remote_unreliable_monotonic_timestamps()
2353 ->Get(1)));
2354 const monotonic_clock::time_point
2355 oldest_local_unreliable_monotonic_timestamps =
2356 monotonic_clock::time_point(chrono::nanoseconds(
2357 log_header->message()
2358 .oldest_local_unreliable_monotonic_timestamps()
2359 ->Get(1)));
2360 const monotonic_clock::time_point
2361 oldest_remote_reliable_monotonic_timestamps =
2362 monotonic_clock::time_point(chrono::nanoseconds(
2363 log_header->message()
2364 .oldest_remote_reliable_monotonic_timestamps()
2365 ->Get(1)));
2366 const monotonic_clock::time_point
2367 oldest_local_reliable_monotonic_timestamps =
2368 monotonic_clock::time_point(chrono::nanoseconds(
2369 log_header->message()
2370 .oldest_local_reliable_monotonic_timestamps()
2371 ->Get(1)));
2372 const monotonic_clock::time_point
2373 oldest_logger_remote_unreliable_monotonic_timestamps =
2374 monotonic_clock::time_point(chrono::nanoseconds(
2375 log_header->message()
2376 .oldest_logger_remote_unreliable_monotonic_timestamps()
2377 ->Get(0)));
2378 const monotonic_clock::time_point
2379 oldest_logger_local_unreliable_monotonic_timestamps =
2380 monotonic_clock::time_point(chrono::nanoseconds(
2381 log_header->message()
2382 .oldest_logger_local_unreliable_monotonic_timestamps()
2383 ->Get(0)));
2384 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2385 monotonic_clock::max_time);
2386 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2387 monotonic_clock::max_time);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002388 if (log_header->message().data_stored()->Get(0) == StoredDataType::DATA) {
2389 switch (log_header->message().parts_index()) {
2390 case 0:
2391 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2392 monotonic_clock::max_time);
2393 EXPECT_EQ(oldest_local_monotonic_timestamps,
2394 monotonic_clock::max_time);
2395 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2396 monotonic_clock::max_time);
2397 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2398 monotonic_clock::max_time);
2399 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2400 monotonic_clock::max_time);
2401 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2402 monotonic_clock::max_time);
2403 break;
2404 default:
2405 FAIL();
2406 break;
2407 }
2408 } else if (log_header->message().data_stored()->Get(0) ==
2409 StoredDataType::TIMESTAMPS) {
2410 switch (log_header->message().parts_index()) {
2411 case 0:
2412 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2413 monotonic_clock::time_point(chrono::microseconds(90200)));
2414 EXPECT_EQ(oldest_local_monotonic_timestamps,
2415 monotonic_clock::time_point(chrono::microseconds(90350)));
2416 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2417 monotonic_clock::time_point(chrono::microseconds(90200)));
2418 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2419 monotonic_clock::time_point(chrono::microseconds(90350)));
2420 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2421 monotonic_clock::max_time);
2422 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2423 monotonic_clock::max_time);
2424 break;
2425 case 1:
2426 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2427 monotonic_clock::time_point(chrono::microseconds(90200)))
2428 << file;
2429 EXPECT_EQ(oldest_local_monotonic_timestamps,
2430 monotonic_clock::time_point(chrono::microseconds(90350)))
2431 << file;
2432 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2433 monotonic_clock::time_point(chrono::microseconds(90200)))
2434 << file;
2435 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2436 monotonic_clock::time_point(chrono::microseconds(90350)))
2437 << file;
2438 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2439 monotonic_clock::time_point(chrono::microseconds(100000)))
2440 << file;
2441 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2442 monotonic_clock::time_point(chrono::microseconds(100150)))
2443 << file;
2444 break;
2445 case 2:
2446 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2447 monotonic_clock::time_point(chrono::milliseconds(1323) +
2448 chrono::microseconds(200)));
2449 EXPECT_EQ(
2450 oldest_local_monotonic_timestamps,
2451 monotonic_clock::time_point(chrono::microseconds(10100350)));
2452 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2453 monotonic_clock::time_point(chrono::milliseconds(1323) +
2454 chrono::microseconds(200)));
2455 EXPECT_EQ(
2456 oldest_local_unreliable_monotonic_timestamps,
2457 monotonic_clock::time_point(chrono::microseconds(10100350)));
2458 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2459 monotonic_clock::max_time)
2460 << file;
2461 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2462 monotonic_clock::max_time)
2463 << file;
2464 break;
2465 case 3:
2466 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2467 monotonic_clock::time_point(chrono::milliseconds(1323) +
2468 chrono::microseconds(200)));
2469 EXPECT_EQ(
2470 oldest_local_monotonic_timestamps,
2471 monotonic_clock::time_point(chrono::microseconds(10100350)));
2472 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2473 monotonic_clock::time_point(chrono::milliseconds(1323) +
2474 chrono::microseconds(200)));
2475 EXPECT_EQ(
2476 oldest_local_unreliable_monotonic_timestamps,
2477 monotonic_clock::time_point(chrono::microseconds(10100350)));
2478 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2479 monotonic_clock::time_point(chrono::microseconds(1423000)))
2480 << file;
2481 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2482 monotonic_clock::time_point(chrono::microseconds(10200150)))
2483 << file;
2484 break;
2485 default:
2486 FAIL();
2487 break;
2488 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002489 }
2490 }
2491
2492 // Confirm that we refuse to replay logs with missing boot uuids.
2493 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07002494 auto sorted_parts = SortParts(pi1_reboot_logfiles_);
2495 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
2496 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07002497
2498 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2499 log_reader_factory.set_send_delay(chrono::microseconds(0));
2500
2501 // This sends out the fetched messages and advances time to the start of
2502 // the log file.
2503 reader.Register(&log_reader_factory);
2504
2505 log_reader_factory.Run();
2506
2507 reader.Deregister();
2508 }
2509}
2510
2511// Tests that we can sort a log which only has timestamps from the remote
2512// because the local message_bridge_client failed to connect.
2513TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002514 if (file_strategy() == FileStrategy::kCombine) {
2515 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2516 }
2517
Naman Guptaa63aa132023-03-22 20:06:34 -07002518 const UUID pi1_boot0 = UUID::Random();
2519 const UUID pi2_boot0 = UUID::Random();
2520 const UUID pi2_boot1 = UUID::Random();
2521 {
2522 CHECK_EQ(pi1_index_, 0u);
2523 CHECK_EQ(pi2_index_, 1u);
2524
2525 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2526 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2527 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2528
2529 time_converter_.AddNextTimestamp(
2530 distributed_clock::epoch(),
2531 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2532 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2533 time_converter_.AddNextTimestamp(
2534 distributed_clock::epoch() + reboot_time,
2535 {BootTimestamp::epoch() + reboot_time,
2536 BootTimestamp{
2537 .boot = 1,
2538 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2539 }
2540 pi2_->Disconnect(pi1_->node());
2541
2542 std::vector<std::string> filenames;
2543 {
2544 LoggerState pi1_logger = MakeLogger(pi1_);
2545
2546 event_loop_factory_.RunFor(chrono::milliseconds(95));
2547 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2548 pi1_boot0);
2549 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2550 pi2_boot0);
2551
2552 StartLogger(&pi1_logger);
2553
2554 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2555
2556 VLOG(1) << "Reboot now!";
2557
2558 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2559 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2560 pi1_boot0);
2561 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2562 pi2_boot1);
2563 pi1_logger.AppendAllFilenames(&filenames);
2564 }
2565
2566 std::sort(filenames.begin(), filenames.end());
2567
2568 // Confirm that our new oldest timestamps properly update as we reboot and
2569 // rotate.
2570 size_t timestamp_file_count = 0;
2571 for (const std::string &file : filenames) {
2572 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2573 ReadHeader(file);
2574 CHECK(log_header);
2575
2576 if (log_header->message().has_configuration()) {
2577 continue;
2578 }
2579
2580 const monotonic_clock::time_point monotonic_start_time =
2581 monotonic_clock::time_point(
2582 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2583 const UUID source_node_boot_uuid = UUID::FromString(
2584 log_header->message().source_node_boot_uuid()->string_view());
2585
2586 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2587 ASSERT_EQ(
2588 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2589 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2590 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2591 2u);
2592 ASSERT_TRUE(log_header->message()
2593 .has_oldest_remote_unreliable_monotonic_timestamps());
2594 ASSERT_EQ(log_header->message()
2595 .oldest_remote_unreliable_monotonic_timestamps()
2596 ->size(),
2597 2u);
2598 ASSERT_TRUE(log_header->message()
2599 .has_oldest_local_unreliable_monotonic_timestamps());
2600 ASSERT_EQ(log_header->message()
2601 .oldest_local_unreliable_monotonic_timestamps()
2602 ->size(),
2603 2u);
2604 ASSERT_TRUE(log_header->message()
2605 .has_oldest_remote_reliable_monotonic_timestamps());
2606 ASSERT_EQ(log_header->message()
2607 .oldest_remote_reliable_monotonic_timestamps()
2608 ->size(),
2609 2u);
2610 ASSERT_TRUE(
2611 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
2612 ASSERT_EQ(log_header->message()
2613 .oldest_local_reliable_monotonic_timestamps()
2614 ->size(),
2615 2u);
2616
2617 ASSERT_TRUE(
2618 log_header->message()
2619 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
2620 ASSERT_EQ(log_header->message()
2621 .oldest_logger_remote_unreliable_monotonic_timestamps()
2622 ->size(),
2623 2u);
2624 ASSERT_TRUE(log_header->message()
2625 .has_oldest_logger_local_unreliable_monotonic_timestamps());
2626 ASSERT_EQ(log_header->message()
2627 .oldest_logger_local_unreliable_monotonic_timestamps()
2628 ->size(),
2629 2u);
2630
2631 if (log_header->message().node()->name()->string_view() != "pi1") {
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002632 ASSERT_TRUE(file.find("timestamps/remote_pi2") != std::string::npos);
Naman Guptaa63aa132023-03-22 20:06:34 -07002633
2634 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2635 ReadNthMessage(file, 0);
2636 CHECK(msg);
2637
2638 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2639 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2640
2641 const monotonic_clock::time_point
2642 expected_oldest_local_monotonic_timestamps(
2643 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2644 const monotonic_clock::time_point
2645 expected_oldest_remote_monotonic_timestamps(
2646 chrono::nanoseconds(msg->message().monotonic_remote_time()));
2647 const monotonic_clock::time_point
2648 expected_oldest_timestamp_monotonic_timestamps(
2649 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
2650
2651 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2652 monotonic_clock::min_time);
2653 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2654 monotonic_clock::min_time);
2655 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
2656 monotonic_clock::min_time);
2657
2658 ++timestamp_file_count;
2659 // Since the log file is from the perspective of the other node,
2660 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2661 monotonic_clock::time_point(chrono::nanoseconds(
2662 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2663 0)));
2664 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2665 monotonic_clock::time_point(chrono::nanoseconds(
2666 log_header->message().oldest_local_monotonic_timestamps()->Get(
2667 0)));
2668 const monotonic_clock::time_point
2669 oldest_remote_unreliable_monotonic_timestamps =
2670 monotonic_clock::time_point(chrono::nanoseconds(
2671 log_header->message()
2672 .oldest_remote_unreliable_monotonic_timestamps()
2673 ->Get(0)));
2674 const monotonic_clock::time_point
2675 oldest_local_unreliable_monotonic_timestamps =
2676 monotonic_clock::time_point(chrono::nanoseconds(
2677 log_header->message()
2678 .oldest_local_unreliable_monotonic_timestamps()
2679 ->Get(0)));
2680 const monotonic_clock::time_point
2681 oldest_remote_reliable_monotonic_timestamps =
2682 monotonic_clock::time_point(chrono::nanoseconds(
2683 log_header->message()
2684 .oldest_remote_reliable_monotonic_timestamps()
2685 ->Get(0)));
2686 const monotonic_clock::time_point
2687 oldest_local_reliable_monotonic_timestamps =
2688 monotonic_clock::time_point(chrono::nanoseconds(
2689 log_header->message()
2690 .oldest_local_reliable_monotonic_timestamps()
2691 ->Get(0)));
2692 const monotonic_clock::time_point
2693 oldest_logger_remote_unreliable_monotonic_timestamps =
2694 monotonic_clock::time_point(chrono::nanoseconds(
2695 log_header->message()
2696 .oldest_logger_remote_unreliable_monotonic_timestamps()
2697 ->Get(1)));
2698 const monotonic_clock::time_point
2699 oldest_logger_local_unreliable_monotonic_timestamps =
2700 monotonic_clock::time_point(chrono::nanoseconds(
2701 log_header->message()
2702 .oldest_logger_local_unreliable_monotonic_timestamps()
2703 ->Get(1)));
2704
2705 const Channel *channel =
2706 event_loop_factory_.configuration()->channels()->Get(
2707 msg->message().channel_index());
2708 const Connection *connection = configuration::ConnectionToNode(
2709 channel, configuration::GetNode(
2710 event_loop_factory_.configuration(),
2711 log_header->message().node()->name()->string_view()));
2712
2713 const bool reliable = connection->time_to_live() == 0;
2714
2715 SCOPED_TRACE(file);
2716 SCOPED_TRACE(aos::FlatbufferToJson(
2717 *log_header, {.multi_line = true, .max_vector_size = 100}));
2718
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002719 // Confirm that the oldest timestamps match what we expect. Based on
2720 // what we are doing, we know that the oldest time is the first
2721 // message's time.
2722 //
2723 // This makes the test robust to both the split and combined config
2724 // tests.
2725 switch (log_header->message().parts_index()) {
2726 case 0:
2727 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2728 expected_oldest_remote_monotonic_timestamps);
2729 EXPECT_EQ(oldest_local_monotonic_timestamps,
2730 expected_oldest_local_monotonic_timestamps);
2731 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2732 expected_oldest_local_monotonic_timestamps)
2733 << file;
2734 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2735 expected_oldest_timestamp_monotonic_timestamps)
2736 << file;
2737
2738 if (reliable) {
2739 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002740 expected_oldest_remote_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002741 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002742 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002743 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2744 monotonic_clock::max_time);
2745 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2746 monotonic_clock::max_time);
2747 } else {
2748 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2749 monotonic_clock::max_time);
2750 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2751 monotonic_clock::max_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07002752 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2753 expected_oldest_remote_monotonic_timestamps);
2754 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2755 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002756 }
2757 break;
2758 case 1:
2759 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2760 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2761 EXPECT_EQ(oldest_local_monotonic_timestamps,
2762 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2763 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2764 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2765 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2766 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
2767 if (reliable) {
2768 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2769 expected_oldest_remote_monotonic_timestamps);
2770 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2771 expected_oldest_local_monotonic_timestamps);
2772 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2773 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2774 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2775 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2776 } else {
2777 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2778 monotonic_clock::max_time);
2779 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2780 monotonic_clock::max_time);
2781 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2782 expected_oldest_remote_monotonic_timestamps);
2783 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2784 expected_oldest_local_monotonic_timestamps);
2785 }
2786 break;
2787 case 2:
2788 EXPECT_EQ(
2789 oldest_remote_monotonic_timestamps,
2790 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2791 EXPECT_EQ(oldest_local_monotonic_timestamps,
2792 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2793 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2794 expected_oldest_local_monotonic_timestamps)
2795 << file;
2796 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2797 expected_oldest_timestamp_monotonic_timestamps)
2798 << file;
2799 if (reliable) {
2800 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2801 expected_oldest_remote_monotonic_timestamps);
2802 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2803 expected_oldest_local_monotonic_timestamps);
2804 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2805 monotonic_clock::max_time);
2806 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2807 monotonic_clock::max_time);
2808 } else {
2809 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2810 monotonic_clock::max_time);
2811 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2812 monotonic_clock::max_time);
2813 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2814 expected_oldest_remote_monotonic_timestamps);
2815 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2816 expected_oldest_local_monotonic_timestamps);
2817 }
2818 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002819
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002820 case 3:
2821 EXPECT_EQ(
2822 oldest_remote_monotonic_timestamps,
2823 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2824 EXPECT_EQ(oldest_local_monotonic_timestamps,
2825 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2826 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2827 expected_oldest_remote_monotonic_timestamps);
2828 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2829 expected_oldest_local_monotonic_timestamps);
2830 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2831 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2832 EXPECT_EQ(
2833 oldest_logger_local_unreliable_monotonic_timestamps,
2834 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
2835 break;
2836 default:
2837 FAIL();
2838 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002839 }
2840
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002841 switch (log_header->message().parts_index()) {
2842 case 0:
2843 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2844 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2845 break;
2846 case 1:
2847 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2848 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2849 break;
2850 case 2:
2851 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2852 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2853 break;
2854 case 3:
2855 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2856 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2857 break;
2858 [[fallthrough]];
2859 default:
2860 FAIL();
2861 break;
2862 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002863 continue;
2864 }
2865 EXPECT_EQ(
2866 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2867 monotonic_clock::max_time.time_since_epoch().count());
2868 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2869 monotonic_clock::max_time.time_since_epoch().count());
2870 EXPECT_EQ(log_header->message()
2871 .oldest_remote_unreliable_monotonic_timestamps()
2872 ->Get(0),
2873 monotonic_clock::max_time.time_since_epoch().count());
2874 EXPECT_EQ(log_header->message()
2875 .oldest_local_unreliable_monotonic_timestamps()
2876 ->Get(0),
2877 monotonic_clock::max_time.time_since_epoch().count());
2878
2879 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2880 monotonic_clock::time_point(chrono::nanoseconds(
2881 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2882 1)));
2883 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2884 monotonic_clock::time_point(chrono::nanoseconds(
2885 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2886 const monotonic_clock::time_point
2887 oldest_remote_unreliable_monotonic_timestamps =
2888 monotonic_clock::time_point(chrono::nanoseconds(
2889 log_header->message()
2890 .oldest_remote_unreliable_monotonic_timestamps()
2891 ->Get(1)));
2892 const monotonic_clock::time_point
2893 oldest_local_unreliable_monotonic_timestamps =
2894 monotonic_clock::time_point(chrono::nanoseconds(
2895 log_header->message()
2896 .oldest_local_unreliable_monotonic_timestamps()
2897 ->Get(1)));
2898 switch (log_header->message().parts_index()) {
2899 case 0:
2900 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2901 monotonic_clock::max_time);
2902 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2903 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2904 monotonic_clock::max_time);
2905 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2906 monotonic_clock::max_time);
2907 break;
2908 default:
2909 FAIL();
2910 break;
2911 }
2912 }
2913
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002914 EXPECT_EQ(timestamp_file_count, 4u);
Naman Guptaa63aa132023-03-22 20:06:34 -07002915
2916 // Confirm that we can actually sort the resulting log and read it.
2917 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07002918 auto sorted_parts = SortParts(filenames);
2919 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
2920 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07002921
2922 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2923 log_reader_factory.set_send_delay(chrono::microseconds(0));
2924
2925 // This sends out the fetched messages and advances time to the start of
2926 // the log file.
2927 reader.Register(&log_reader_factory);
2928
2929 log_reader_factory.Run();
2930
2931 reader.Deregister();
2932 }
2933}
2934
2935// Tests that we properly handle one direction of message_bridge being
2936// unavailable.
2937TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07002938 std::vector<std::string> actual_filenames;
2939
Naman Guptaa63aa132023-03-22 20:06:34 -07002940 pi1_->Disconnect(pi2_->node());
2941 time_converter_.AddMonotonic(
2942 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2943
2944 time_converter_.AddMonotonic(
2945 {chrono::milliseconds(10000),
2946 chrono::milliseconds(10000) - chrono::milliseconds(1)});
2947 {
2948 LoggerState pi1_logger = MakeLogger(pi1_);
2949
2950 event_loop_factory_.RunFor(chrono::milliseconds(95));
2951
2952 StartLogger(&pi1_logger);
2953
2954 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002955 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002956 }
2957
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002958 // Confirm that we can parse the result. LogReader has enough internal
2959 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07002960 ConfirmReadable(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002961}
2962
2963// Tests that we properly handle one direction of message_bridge being
2964// unavailable.
2965TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
2966 pi1_->Disconnect(pi2_->node());
2967 time_converter_.AddMonotonic(
2968 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
2969
2970 time_converter_.AddMonotonic(
2971 {chrono::milliseconds(10000),
2972 chrono::milliseconds(10000) + chrono::milliseconds(1)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002973
2974 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07002975 {
2976 LoggerState pi1_logger = MakeLogger(pi1_);
2977
2978 event_loop_factory_.RunFor(chrono::milliseconds(95));
2979
2980 StartLogger(&pi1_logger);
2981
2982 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002983 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002984 }
2985
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002986 // Confirm that we can parse the result. LogReader has enough internal
2987 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07002988 ConfirmReadable(filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002989}
2990
2991// Tests that we explode if someone passes in a part file twice with a better
2992// error than an out of order error.
2993TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2994 time_converter_.AddMonotonic(
2995 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002996
2997 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07002998 {
2999 LoggerState pi1_logger = MakeLogger(pi1_);
3000
3001 event_loop_factory_.RunFor(chrono::milliseconds(95));
3002
3003 StartLogger(&pi1_logger);
3004
3005 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07003006
3007 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003008 }
3009
3010 std::vector<std::string> duplicates;
Austin Schuh8fb4b452023-08-04 17:02:27 -07003011 for (const std::string &f : filenames) {
Naman Guptaa63aa132023-03-22 20:06:34 -07003012 duplicates.emplace_back(f);
3013 duplicates.emplace_back(f);
3014 }
3015 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3016}
3017
3018// Tests that we explode if someone loses a part out of the middle of a log.
3019TEST_P(MultinodeLoggerTest, MissingPartsFromMiddle) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07003020 if (file_strategy() == FileStrategy::kCombine) {
3021 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
3022 }
Naman Guptaa63aa132023-03-22 20:06:34 -07003023 time_converter_.AddMonotonic(
3024 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3025 {
3026 LoggerState pi1_logger = MakeLogger(pi1_);
3027
3028 event_loop_factory_.RunFor(chrono::milliseconds(95));
3029
3030 StartLogger(&pi1_logger);
3031 aos::monotonic_clock::time_point last_rotation_time =
3032 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07003033 pi1_logger.logger->set_on_logged_period(
3034 [&](aos::monotonic_clock::time_point) {
3035 const auto now = pi1_logger.event_loop->monotonic_now();
3036 if (now > last_rotation_time + std::chrono::seconds(5)) {
3037 pi1_logger.logger->Rotate();
3038 last_rotation_time = now;
3039 }
3040 });
Naman Guptaa63aa132023-03-22 20:06:34 -07003041
3042 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3043 }
3044
3045 std::vector<std::string> missing_parts;
3046
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07003047 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part0" +
3048 Extension());
3049 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part2" +
3050 Extension());
Naman Guptaa63aa132023-03-22 20:06:34 -07003051 missing_parts.emplace_back(absl::StrCat(
3052 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
3053
3054 EXPECT_DEATH({ SortParts(missing_parts); },
3055 "Broken log, missing part files between");
3056}
3057
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003058// Tests that we properly handle a dead node. Do this by just disconnecting
3059// it and only using one nodes of logs.
Naman Guptaa63aa132023-03-22 20:06:34 -07003060TEST_P(MultinodeLoggerTest, DeadNode) {
3061 pi1_->Disconnect(pi2_->node());
3062 pi2_->Disconnect(pi1_->node());
3063 time_converter_.AddMonotonic(
3064 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3065 {
3066 LoggerState pi1_logger = MakeLogger(pi1_);
3067
3068 event_loop_factory_.RunFor(chrono::milliseconds(95));
3069
3070 StartLogger(&pi1_logger);
3071
3072 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3073 }
3074
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003075 // Confirm that we can parse the result. LogReader has enough internal
3076 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003077 ConfirmReadable(MakePi1DeadNodeLogfiles());
3078}
3079
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003080// Tests that we can relog with a different config. This makes most sense
3081// when you are trying to edit a log and want to use channel renaming + the
3082// original config in the new log.
Naman Guptaa63aa132023-03-22 20:06:34 -07003083TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3084 time_converter_.StartEqual();
3085 {
3086 LoggerState pi1_logger = MakeLogger(pi1_);
3087 LoggerState pi2_logger = MakeLogger(pi2_);
3088
3089 event_loop_factory_.RunFor(chrono::milliseconds(95));
3090
3091 StartLogger(&pi1_logger);
3092 StartLogger(&pi2_logger);
3093
3094 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3095 }
3096
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003097 auto sorted_parts = SortParts(logfiles_);
3098 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3099 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003100 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3101
3102 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3103 log_reader_factory.set_send_delay(chrono::microseconds(0));
3104
3105 // This sends out the fetched messages and advances time to the start of the
3106 // log file.
3107 reader.Register(&log_reader_factory);
3108
3109 const Node *pi1 =
3110 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3111 const Node *pi2 =
3112 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3113
3114 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3115 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3116 LOG(INFO) << "now pi1 "
3117 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3118 LOG(INFO) << "now pi2 "
3119 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3120
3121 EXPECT_THAT(reader.LoggedNodes(),
3122 ::testing::ElementsAre(
3123 configuration::GetNode(reader.logged_configuration(), pi1),
3124 configuration::GetNode(reader.logged_configuration(), pi2)));
3125
3126 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3127
3128 // And confirm we can re-create a log again, while checking the contents.
3129 std::vector<std::string> log_files;
3130 {
3131 LoggerState pi1_logger =
3132 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
3133 &log_reader_factory, reader.logged_configuration());
3134 LoggerState pi2_logger =
3135 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
3136 &log_reader_factory, reader.logged_configuration());
3137
Austin Schuh7e417682023-08-11 17:05:30 -07003138 pi1_logger.StartLogger(tmp_dir_ + "/logs/relogged1");
3139 pi2_logger.StartLogger(tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07003140
3141 log_reader_factory.Run();
3142
3143 for (auto &x : pi1_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003144 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged1_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003145 }
3146 for (auto &x : pi2_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003147 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged2_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003148 }
3149 }
3150
3151 reader.Deregister();
3152
3153 // And verify that we can run the LogReader over the relogged files without
3154 // hitting any fatal errors.
3155 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003156 auto sorted_parts = SortParts(log_files);
3157 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3158 LogReader relogged_reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003159 relogged_reader.Register();
3160
3161 relogged_reader.event_loop_factory()->Run();
3162 }
3163}
3164
Maxwell Gumley8c1b87f2024-02-13 17:54:52 -07003165// Tests that we can relog with a subset of the original config. This is useful
3166// for excluding obsolete or deprecated channels, so they don't appear in the
3167// configuration when reading the log.
3168TEST_P(MultinodeLoggerTest, LogPartialConfig) {
3169 time_converter_.StartEqual();
3170 {
3171 LoggerState pi1_logger = MakeLogger(pi1_);
3172 LoggerState pi2_logger = MakeLogger(pi2_);
3173
3174 event_loop_factory_.RunFor(chrono::milliseconds(95));
3175
3176 StartLogger(&pi1_logger);
3177 StartLogger(&pi2_logger);
3178
3179 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3180 }
3181
3182 auto sorted_parts = SortParts(logfiles_);
3183 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3184 LogReader reader(sorted_parts);
3185 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3186
3187 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3188 log_reader_factory.set_send_delay(chrono::microseconds(0));
3189
3190 // This sends out the fetched messages and advances time to the start of the
3191 // log file.
3192 reader.Register(&log_reader_factory);
3193
3194 const Node *pi1 =
3195 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3196 const Node *pi2 =
3197 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3198
3199 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3200 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3201 LOG(INFO) << "now pi1 "
3202 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3203 LOG(INFO) << "now pi2 "
3204 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3205
3206 EXPECT_THAT(reader.LoggedNodes(),
3207 ::testing::ElementsAre(
3208 configuration::GetNode(reader.logged_configuration(), pi1),
3209 configuration::GetNode(reader.logged_configuration(), pi2)));
3210
3211 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3212
3213 const FlatbufferDetachedBuffer<Configuration> partial_configuration_buffer =
3214 configuration::GetPartialConfiguration(
3215 *reader.event_loop_factory()->configuration(),
3216 [](const Channel &channel) {
3217 if (channel.name()->string_view().starts_with("/original/")) {
3218 LOG(INFO) << "Omitting channel from save_log, channel: "
3219 << channel.name()->string_view() << ", "
3220 << channel.type()->string_view();
3221 return false;
3222 }
3223 return true;
3224 });
3225
3226 // And confirm we can re-create a log again, while checking the contents.
3227 std::vector<std::string> log_files;
3228 {
3229 const Configuration *partial_configuration =
3230 &(partial_configuration_buffer.message());
3231
3232 LoggerState pi1_logger =
3233 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
3234 &log_reader_factory, partial_configuration);
3235 LoggerState pi2_logger =
3236 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
3237 &log_reader_factory, partial_configuration);
3238
3239 pi1_logger.StartLogger(tmp_dir_ + "/logs/relogged1");
3240 pi2_logger.StartLogger(tmp_dir_ + "/logs/relogged2");
3241
3242 log_reader_factory.Run();
3243
3244 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3245 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged1_", x));
3246 }
3247 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3248 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged2_", x));
3249 }
3250 }
3251
3252 reader.Deregister();
3253
3254 // And verify that we can run the LogReader over the relogged files without
3255 // hitting any fatal errors.
3256 {
3257 auto sorted_parts = SortParts(log_files);
3258 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3259 LogReader relogged_reader(sorted_parts);
3260 relogged_reader.Register();
3261
3262 relogged_reader.event_loop_factory()->Run();
3263 }
3264}
3265
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003266// Tests that we properly replay a log where the start time for a node is
3267// before any data on the node. This can happen if the logger starts before
3268// data is published. While the scenario below is a bit convoluted, we have
3269// seen logs like this generated out in the wild.
Naman Guptaa63aa132023-03-22 20:06:34 -07003270TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
Austin Schuh7e417682023-08-11 17:05:30 -07003271 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3272 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3273
Naman Guptaa63aa132023-03-22 20:06:34 -07003274 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3275 aos::configuration::ReadConfig(ArtifactPath(
3276 "aos/events/logging/multinode_pingpong_split3_config.json"));
3277 message_bridge::TestingTimeConverter time_converter(
3278 configuration::NodesCount(&config.message()));
3279 SimulatedEventLoopFactory event_loop_factory(&config.message());
3280 event_loop_factory.SetTimeConverter(&time_converter);
3281 NodeEventLoopFactory *const pi1 =
3282 event_loop_factory.GetNodeEventLoopFactory("pi1");
3283 const size_t pi1_index = configuration::GetNodeIndex(
3284 event_loop_factory.configuration(), pi1->node());
3285 NodeEventLoopFactory *const pi2 =
3286 event_loop_factory.GetNodeEventLoopFactory("pi2");
3287 const size_t pi2_index = configuration::GetNodeIndex(
3288 event_loop_factory.configuration(), pi2->node());
3289 NodeEventLoopFactory *const pi3 =
3290 event_loop_factory.GetNodeEventLoopFactory("pi3");
3291 const size_t pi3_index = configuration::GetNodeIndex(
3292 event_loop_factory.configuration(), pi3->node());
3293
3294 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003295 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003296 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003297 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003298 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003299 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003300 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003301 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
3302
Naman Guptaa63aa132023-03-22 20:06:34 -07003303 const UUID pi1_boot0 = UUID::Random();
3304 const UUID pi2_boot0 = UUID::Random();
3305 const UUID pi2_boot1 = UUID::Random();
3306 const UUID pi3_boot0 = UUID::Random();
3307 {
3308 CHECK_EQ(pi1_index, 0u);
3309 CHECK_EQ(pi2_index, 1u);
3310 CHECK_EQ(pi3_index, 2u);
3311
3312 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3313 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3314 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3315 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3316
3317 time_converter.AddNextTimestamp(
3318 distributed_clock::epoch(),
3319 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3320 BootTimestamp::epoch()});
3321 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3322 time_converter.AddNextTimestamp(
3323 distributed_clock::epoch() + reboot_time,
3324 {BootTimestamp::epoch() + reboot_time,
3325 BootTimestamp{
3326 .boot = 1,
3327 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3328 BootTimestamp::epoch() + reboot_time});
3329 }
3330
3331 // Make everything perfectly quiet.
3332 event_loop_factory.SkipTimingReport();
3333 event_loop_factory.DisableStatistics();
3334
3335 std::vector<std::string> filenames;
3336 {
3337 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003338 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3339 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003340 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003341 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3342 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003343 {
3344 // And now start the logger.
3345 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003346 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3347 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003348
3349 event_loop_factory.RunFor(chrono::milliseconds(1000));
3350
3351 pi1_logger.StartLogger(kLogfile1_1);
3352 pi3_logger.StartLogger(kLogfile3_1);
3353 pi2_logger.StartLogger(kLogfile2_1);
3354
3355 event_loop_factory.RunFor(chrono::milliseconds(10000));
3356
3357 // Now that we've got a start time in the past, turn on data.
3358 event_loop_factory.EnableStatistics();
3359 std::unique_ptr<aos::EventLoop> ping_event_loop =
3360 pi1->MakeEventLoop("ping");
3361 Ping ping(ping_event_loop.get());
3362
3363 pi2->AlwaysStart<Pong>("pong");
3364
3365 event_loop_factory.RunFor(chrono::milliseconds(3000));
3366
3367 pi2_logger.AppendAllFilenames(&filenames);
3368
3369 // Stop logging on pi2 before rebooting and completely shut off all
3370 // messages on pi2.
3371 pi2->DisableStatistics();
3372 pi1->Disconnect(pi2->node());
3373 pi2->Disconnect(pi1->node());
3374 }
3375 event_loop_factory.RunFor(chrono::milliseconds(7000));
3376 // pi2 now reboots.
3377 {
3378 event_loop_factory.RunFor(chrono::milliseconds(1000));
3379
3380 // Start logging again on pi2 after it is up.
3381 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003382 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3383 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003384 pi2_logger.StartLogger(kLogfile2_2);
3385
3386 event_loop_factory.RunFor(chrono::milliseconds(10000));
3387 // And, now that we have a start time in the log, turn data back on.
3388 pi2->EnableStatistics();
3389 pi1->Connect(pi2->node());
3390 pi2->Connect(pi1->node());
3391
3392 pi2->AlwaysStart<Pong>("pong");
3393 std::unique_ptr<aos::EventLoop> ping_event_loop =
3394 pi1->MakeEventLoop("ping");
3395 Ping ping(ping_event_loop.get());
3396
3397 event_loop_factory.RunFor(chrono::milliseconds(3000));
3398
3399 pi2_logger.AppendAllFilenames(&filenames);
3400 }
3401
3402 pi1_logger.AppendAllFilenames(&filenames);
3403 pi3_logger.AppendAllFilenames(&filenames);
3404 }
3405
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003406 // Confirm that we can parse the result. LogReader has enough internal
3407 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003408 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003409 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003410 auto result = ConfirmReadable(filenames);
3411 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3412 chrono::seconds(1)));
3413 EXPECT_THAT(result[0].second,
3414 ::testing::ElementsAre(realtime_clock::epoch() +
3415 chrono::microseconds(34990350)));
3416
3417 EXPECT_THAT(result[1].first,
3418 ::testing::ElementsAre(
3419 realtime_clock::epoch() + chrono::seconds(1),
3420 realtime_clock::epoch() + chrono::microseconds(3323000)));
3421 EXPECT_THAT(result[1].second,
3422 ::testing::ElementsAre(
3423 realtime_clock::epoch() + chrono::microseconds(13990200),
3424 realtime_clock::epoch() + chrono::microseconds(16313200)));
3425
3426 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3427 chrono::seconds(1)));
3428 EXPECT_THAT(result[2].second,
3429 ::testing::ElementsAre(realtime_clock::epoch() +
3430 chrono::microseconds(34900150)));
3431}
3432
3433// Tests that local data before remote data after reboot is properly replayed.
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003434// We only trigger a reboot in the timestamp interpolation function when
3435// solving the timestamp problem when we actually have a point in the
3436// function. This originally only happened when a point passes the noncausal
3437// filter. At the start of time for the second boot, if we aren't careful, we
3438// will have messages which need to be published at times before the boot.
3439// This happens when a local message is in the log before a forwarded message,
3440// so there is no point in the interpolation function. This delays the
3441// reboot. So, we need to recreate that situation and make sure it doesn't
3442// come back.
Naman Guptaa63aa132023-03-22 20:06:34 -07003443TEST(MultinodeRebootLoggerTest,
3444 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003445 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3446 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3447
Naman Guptaa63aa132023-03-22 20:06:34 -07003448 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3449 aos::configuration::ReadConfig(ArtifactPath(
3450 "aos/events/logging/multinode_pingpong_split3_config.json"));
3451 message_bridge::TestingTimeConverter time_converter(
3452 configuration::NodesCount(&config.message()));
3453 SimulatedEventLoopFactory event_loop_factory(&config.message());
3454 event_loop_factory.SetTimeConverter(&time_converter);
3455 NodeEventLoopFactory *const pi1 =
3456 event_loop_factory.GetNodeEventLoopFactory("pi1");
3457 const size_t pi1_index = configuration::GetNodeIndex(
3458 event_loop_factory.configuration(), pi1->node());
3459 NodeEventLoopFactory *const pi2 =
3460 event_loop_factory.GetNodeEventLoopFactory("pi2");
3461 const size_t pi2_index = configuration::GetNodeIndex(
3462 event_loop_factory.configuration(), pi2->node());
3463 NodeEventLoopFactory *const pi3 =
3464 event_loop_factory.GetNodeEventLoopFactory("pi3");
3465 const size_t pi3_index = configuration::GetNodeIndex(
3466 event_loop_factory.configuration(), pi3->node());
3467
3468 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003469 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003470 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003471 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003472 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003473 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003474 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003475 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003476 const UUID pi1_boot0 = UUID::Random();
3477 const UUID pi2_boot0 = UUID::Random();
3478 const UUID pi2_boot1 = UUID::Random();
3479 const UUID pi3_boot0 = UUID::Random();
3480 {
3481 CHECK_EQ(pi1_index, 0u);
3482 CHECK_EQ(pi2_index, 1u);
3483 CHECK_EQ(pi3_index, 2u);
3484
3485 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3486 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3487 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3488 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3489
3490 time_converter.AddNextTimestamp(
3491 distributed_clock::epoch(),
3492 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3493 BootTimestamp::epoch()});
3494 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3495 time_converter.AddNextTimestamp(
3496 distributed_clock::epoch() + reboot_time,
3497 {BootTimestamp::epoch() + reboot_time,
3498 BootTimestamp{.boot = 1,
3499 .time = monotonic_clock::epoch() + reboot_time +
3500 chrono::seconds(100)},
3501 BootTimestamp::epoch() + reboot_time});
3502 }
3503
3504 std::vector<std::string> filenames;
3505 {
3506 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003507 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3508 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003509 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003510 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3511 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003512 {
3513 // And now start the logger.
3514 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003515 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3516 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003517
3518 pi1_logger.StartLogger(kLogfile1_1);
3519 pi3_logger.StartLogger(kLogfile3_1);
3520 pi2_logger.StartLogger(kLogfile2_1);
3521
3522 event_loop_factory.RunFor(chrono::milliseconds(1005));
3523
3524 // Now that we've got a start time in the past, turn on data.
3525 std::unique_ptr<aos::EventLoop> ping_event_loop =
3526 pi1->MakeEventLoop("ping");
3527 Ping ping(ping_event_loop.get());
3528
3529 pi2->AlwaysStart<Pong>("pong");
3530
3531 event_loop_factory.RunFor(chrono::milliseconds(3000));
3532
3533 pi2_logger.AppendAllFilenames(&filenames);
3534
3535 // Disable any remote messages on pi2.
3536 pi1->Disconnect(pi2->node());
3537 pi2->Disconnect(pi1->node());
3538 }
3539 event_loop_factory.RunFor(chrono::milliseconds(995));
3540 // pi2 now reboots at 5 seconds.
3541 {
3542 event_loop_factory.RunFor(chrono::milliseconds(1000));
3543
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003544 // Make local stuff happen before we start logging and connect the
3545 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003546 pi2->AlwaysStart<Pong>("pong");
3547 std::unique_ptr<aos::EventLoop> ping_event_loop =
3548 pi1->MakeEventLoop("ping");
3549 Ping ping(ping_event_loop.get());
3550 event_loop_factory.RunFor(chrono::milliseconds(1005));
3551
3552 // Start logging again on pi2 after it is up.
3553 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003554 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3555 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003556 pi2_logger.StartLogger(kLogfile2_2);
3557
3558 // And allow remote messages now that we have some local ones.
3559 pi1->Connect(pi2->node());
3560 pi2->Connect(pi1->node());
3561
3562 event_loop_factory.RunFor(chrono::milliseconds(1000));
3563
3564 event_loop_factory.RunFor(chrono::milliseconds(3000));
3565
3566 pi2_logger.AppendAllFilenames(&filenames);
3567 }
3568
3569 pi1_logger.AppendAllFilenames(&filenames);
3570 pi3_logger.AppendAllFilenames(&filenames);
3571 }
3572
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003573 // Confirm that we can parse the result. LogReader has enough internal
3574 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003575 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003576 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003577 auto result = ConfirmReadable(filenames);
3578
3579 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3580 EXPECT_THAT(result[0].second,
3581 ::testing::ElementsAre(realtime_clock::epoch() +
3582 chrono::microseconds(11000350)));
3583
3584 EXPECT_THAT(result[1].first,
3585 ::testing::ElementsAre(
3586 realtime_clock::epoch(),
3587 realtime_clock::epoch() + chrono::microseconds(107005000)));
3588 EXPECT_THAT(result[1].second,
3589 ::testing::ElementsAre(
3590 realtime_clock::epoch() + chrono::microseconds(4000150),
3591 realtime_clock::epoch() + chrono::microseconds(111000200)));
3592
3593 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3594 EXPECT_THAT(result[2].second,
3595 ::testing::ElementsAre(realtime_clock::epoch() +
3596 chrono::microseconds(11000150)));
3597
3598 auto start_stop_result = ConfirmReadable(
3599 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3600 realtime_clock::epoch() + chrono::milliseconds(3000));
3601
3602 EXPECT_THAT(
3603 start_stop_result[0].first,
3604 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3605 EXPECT_THAT(
3606 start_stop_result[0].second,
3607 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3608 EXPECT_THAT(
3609 start_stop_result[1].first,
3610 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3611 EXPECT_THAT(
3612 start_stop_result[1].second,
3613 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3614 EXPECT_THAT(
3615 start_stop_result[2].first,
3616 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3617 EXPECT_THAT(
3618 start_stop_result[2].second,
3619 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3620}
3621
3622// Tests that setting the start and stop flags across a reboot works as
3623// expected.
3624TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
Austin Schuh7e417682023-08-11 17:05:30 -07003625 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3626 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3627
Naman Guptaa63aa132023-03-22 20:06:34 -07003628 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3629 aos::configuration::ReadConfig(ArtifactPath(
3630 "aos/events/logging/multinode_pingpong_split3_config.json"));
3631 message_bridge::TestingTimeConverter time_converter(
3632 configuration::NodesCount(&config.message()));
3633 SimulatedEventLoopFactory event_loop_factory(&config.message());
3634 event_loop_factory.SetTimeConverter(&time_converter);
3635 NodeEventLoopFactory *const pi1 =
3636 event_loop_factory.GetNodeEventLoopFactory("pi1");
3637 const size_t pi1_index = configuration::GetNodeIndex(
3638 event_loop_factory.configuration(), pi1->node());
3639 NodeEventLoopFactory *const pi2 =
3640 event_loop_factory.GetNodeEventLoopFactory("pi2");
3641 const size_t pi2_index = configuration::GetNodeIndex(
3642 event_loop_factory.configuration(), pi2->node());
3643 NodeEventLoopFactory *const pi3 =
3644 event_loop_factory.GetNodeEventLoopFactory("pi3");
3645 const size_t pi3_index = configuration::GetNodeIndex(
3646 event_loop_factory.configuration(), pi3->node());
3647
3648 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003649 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003650 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003651 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003652 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003653 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003654 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003655 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003656 {
3657 CHECK_EQ(pi1_index, 0u);
3658 CHECK_EQ(pi2_index, 1u);
3659 CHECK_EQ(pi3_index, 2u);
3660
3661 time_converter.AddNextTimestamp(
3662 distributed_clock::epoch(),
3663 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3664 BootTimestamp::epoch()});
3665 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3666 time_converter.AddNextTimestamp(
3667 distributed_clock::epoch() + reboot_time,
3668 {BootTimestamp::epoch() + reboot_time,
3669 BootTimestamp{.boot = 1,
3670 .time = monotonic_clock::epoch() + reboot_time},
3671 BootTimestamp::epoch() + reboot_time});
3672 }
3673
3674 std::vector<std::string> filenames;
3675 {
3676 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003677 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3678 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003679 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003680 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3681 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003682 {
3683 // And now start the logger.
3684 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003685 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3686 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003687
3688 pi1_logger.StartLogger(kLogfile1_1);
3689 pi3_logger.StartLogger(kLogfile3_1);
3690 pi2_logger.StartLogger(kLogfile2_1);
3691
3692 event_loop_factory.RunFor(chrono::milliseconds(1005));
3693
3694 // Now that we've got a start time in the past, turn on data.
3695 std::unique_ptr<aos::EventLoop> ping_event_loop =
3696 pi1->MakeEventLoop("ping");
3697 Ping ping(ping_event_loop.get());
3698
3699 pi2->AlwaysStart<Pong>("pong");
3700
3701 event_loop_factory.RunFor(chrono::milliseconds(3000));
3702
3703 pi2_logger.AppendAllFilenames(&filenames);
3704 }
3705 event_loop_factory.RunFor(chrono::milliseconds(995));
3706 // pi2 now reboots at 5 seconds.
3707 {
3708 event_loop_factory.RunFor(chrono::milliseconds(1000));
3709
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003710 // Make local stuff happen before we start logging and connect the
3711 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003712 pi2->AlwaysStart<Pong>("pong");
3713 std::unique_ptr<aos::EventLoop> ping_event_loop =
3714 pi1->MakeEventLoop("ping");
3715 Ping ping(ping_event_loop.get());
3716 event_loop_factory.RunFor(chrono::milliseconds(5));
3717
3718 // Start logging again on pi2 after it is up.
3719 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003720 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3721 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003722 pi2_logger.StartLogger(kLogfile2_2);
3723
3724 event_loop_factory.RunFor(chrono::milliseconds(5000));
3725
3726 pi2_logger.AppendAllFilenames(&filenames);
3727 }
3728
3729 pi1_logger.AppendAllFilenames(&filenames);
3730 pi3_logger.AppendAllFilenames(&filenames);
3731 }
3732
3733 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003734 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003735 auto result = ConfirmReadable(filenames);
3736
3737 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3738 EXPECT_THAT(result[0].second,
3739 ::testing::ElementsAre(realtime_clock::epoch() +
3740 chrono::microseconds(11000350)));
3741
3742 EXPECT_THAT(result[1].first,
3743 ::testing::ElementsAre(
3744 realtime_clock::epoch(),
3745 realtime_clock::epoch() + chrono::microseconds(6005000)));
3746 EXPECT_THAT(result[1].second,
3747 ::testing::ElementsAre(
3748 realtime_clock::epoch() + chrono::microseconds(4900150),
3749 realtime_clock::epoch() + chrono::microseconds(11000200)));
3750
3751 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3752 EXPECT_THAT(result[2].second,
3753 ::testing::ElementsAre(realtime_clock::epoch() +
3754 chrono::microseconds(11000150)));
3755
3756 // Confirm we observed the correct start and stop times. We should see the
3757 // reboot here.
3758 auto start_stop_result = ConfirmReadable(
3759 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3760 realtime_clock::epoch() + chrono::milliseconds(8000));
3761
3762 EXPECT_THAT(
3763 start_stop_result[0].first,
3764 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3765 EXPECT_THAT(
3766 start_stop_result[0].second,
3767 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3768 EXPECT_THAT(start_stop_result[1].first,
3769 ::testing::ElementsAre(
3770 realtime_clock::epoch() + chrono::seconds(2),
3771 realtime_clock::epoch() + chrono::microseconds(6005000)));
3772 EXPECT_THAT(start_stop_result[1].second,
3773 ::testing::ElementsAre(
3774 realtime_clock::epoch() + chrono::microseconds(4900150),
3775 realtime_clock::epoch() + chrono::seconds(8)));
3776 EXPECT_THAT(
3777 start_stop_result[2].first,
3778 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3779 EXPECT_THAT(
3780 start_stop_result[2].second,
3781 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3782}
3783
3784// Tests that we properly handle one direction being down.
3785TEST(MissingDirectionTest, OneDirection) {
Austin Schuh7e417682023-08-11 17:05:30 -07003786 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3787 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3788
Naman Guptaa63aa132023-03-22 20:06:34 -07003789 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3790 aos::configuration::ReadConfig(ArtifactPath(
3791 "aos/events/logging/multinode_pingpong_split4_config.json"));
3792 message_bridge::TestingTimeConverter time_converter(
3793 configuration::NodesCount(&config.message()));
3794 SimulatedEventLoopFactory event_loop_factory(&config.message());
3795 event_loop_factory.SetTimeConverter(&time_converter);
3796
3797 NodeEventLoopFactory *const pi1 =
3798 event_loop_factory.GetNodeEventLoopFactory("pi1");
3799 const size_t pi1_index = configuration::GetNodeIndex(
3800 event_loop_factory.configuration(), pi1->node());
3801 NodeEventLoopFactory *const pi2 =
3802 event_loop_factory.GetNodeEventLoopFactory("pi2");
3803 const size_t pi2_index = configuration::GetNodeIndex(
3804 event_loop_factory.configuration(), pi2->node());
3805 std::vector<std::string> filenames;
3806
3807 {
3808 CHECK_EQ(pi1_index, 0u);
3809 CHECK_EQ(pi2_index, 1u);
3810
3811 time_converter.AddNextTimestamp(
3812 distributed_clock::epoch(),
3813 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3814
3815 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3816 time_converter.AddNextTimestamp(
3817 distributed_clock::epoch() + reboot_time,
3818 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3819 BootTimestamp::epoch() + reboot_time});
3820 }
3821
3822 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003823 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003824 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003825 aos::testing::TestTmpDir() + "/logs/multi_logfile1.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003826
3827 pi2->Disconnect(pi1->node());
3828
3829 pi1->AlwaysStart<Ping>("ping");
3830 pi2->AlwaysStart<Pong>("pong");
3831
3832 {
3833 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003834 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3835 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003836
3837 event_loop_factory.RunFor(chrono::milliseconds(95));
3838
3839 pi2_logger.StartLogger(kLogfile2_1);
3840
3841 event_loop_factory.RunFor(chrono::milliseconds(6000));
3842
3843 pi2->Connect(pi1->node());
3844
3845 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003846 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3847 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003848 pi1_logger.StartLogger(kLogfile1_1);
3849
3850 event_loop_factory.RunFor(chrono::milliseconds(5000));
3851 pi1_logger.AppendAllFilenames(&filenames);
3852 pi2_logger.AppendAllFilenames(&filenames);
3853 }
3854
3855 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003856 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003857 ConfirmReadable(filenames);
3858}
3859
3860// Tests that we properly handle only one direction ever existing after a
3861// reboot.
3862TEST(MissingDirectionTest, OneDirectionAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003863 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3864 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3865
Naman Guptaa63aa132023-03-22 20:06:34 -07003866 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3867 aos::configuration::ReadConfig(ArtifactPath(
3868 "aos/events/logging/multinode_pingpong_split4_config.json"));
3869 message_bridge::TestingTimeConverter time_converter(
3870 configuration::NodesCount(&config.message()));
3871 SimulatedEventLoopFactory event_loop_factory(&config.message());
3872 event_loop_factory.SetTimeConverter(&time_converter);
3873
3874 NodeEventLoopFactory *const pi1 =
3875 event_loop_factory.GetNodeEventLoopFactory("pi1");
3876 const size_t pi1_index = configuration::GetNodeIndex(
3877 event_loop_factory.configuration(), pi1->node());
3878 NodeEventLoopFactory *const pi2 =
3879 event_loop_factory.GetNodeEventLoopFactory("pi2");
3880 const size_t pi2_index = configuration::GetNodeIndex(
3881 event_loop_factory.configuration(), pi2->node());
3882 std::vector<std::string> filenames;
3883
3884 {
3885 CHECK_EQ(pi1_index, 0u);
3886 CHECK_EQ(pi2_index, 1u);
3887
3888 time_converter.AddNextTimestamp(
3889 distributed_clock::epoch(),
3890 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3891
3892 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3893 time_converter.AddNextTimestamp(
3894 distributed_clock::epoch() + reboot_time,
3895 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3896 BootTimestamp::epoch() + reboot_time});
3897 }
3898
3899 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003900 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003901
3902 pi1->AlwaysStart<Ping>("ping");
3903
3904 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
3905 // makes it such that we will only get timestamps from pi1 -> pi2 on the
3906 // second boot.
3907 {
3908 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003909 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3910 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003911
3912 event_loop_factory.RunFor(chrono::milliseconds(95));
3913
3914 pi2_logger.StartLogger(kLogfile2_1);
3915
3916 event_loop_factory.RunFor(chrono::milliseconds(4000));
3917
3918 pi2->Disconnect(pi1->node());
3919
3920 event_loop_factory.RunFor(chrono::milliseconds(1000));
3921 pi1->AlwaysStart<Ping>("ping");
3922
3923 event_loop_factory.RunFor(chrono::milliseconds(5000));
3924 pi2_logger.AppendAllFilenames(&filenames);
3925 }
3926
3927 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003928 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003929 ConfirmReadable(filenames);
3930}
3931
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003932// Tests that we properly handle only one direction ever existing after a
3933// reboot with only reliable data.
Naman Guptaa63aa132023-03-22 20:06:34 -07003934TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
Austin Schuh7e417682023-08-11 17:05:30 -07003935 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3936 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3937
Naman Guptaa63aa132023-03-22 20:06:34 -07003938 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003939 aos::configuration::ReadConfig(
3940 ArtifactPath("aos/events/logging/"
3941 "multinode_pingpong_split4_reliable_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07003942 message_bridge::TestingTimeConverter time_converter(
3943 configuration::NodesCount(&config.message()));
3944 SimulatedEventLoopFactory event_loop_factory(&config.message());
3945 event_loop_factory.SetTimeConverter(&time_converter);
3946
3947 NodeEventLoopFactory *const pi1 =
3948 event_loop_factory.GetNodeEventLoopFactory("pi1");
3949 const size_t pi1_index = configuration::GetNodeIndex(
3950 event_loop_factory.configuration(), pi1->node());
3951 NodeEventLoopFactory *const pi2 =
3952 event_loop_factory.GetNodeEventLoopFactory("pi2");
3953 const size_t pi2_index = configuration::GetNodeIndex(
3954 event_loop_factory.configuration(), pi2->node());
3955 std::vector<std::string> filenames;
3956
3957 {
3958 CHECK_EQ(pi1_index, 0u);
3959 CHECK_EQ(pi2_index, 1u);
3960
3961 time_converter.AddNextTimestamp(
3962 distributed_clock::epoch(),
3963 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3964
3965 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3966 time_converter.AddNextTimestamp(
3967 distributed_clock::epoch() + reboot_time,
3968 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3969 BootTimestamp::epoch() + reboot_time});
3970 }
3971
3972 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003973 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003974
3975 pi1->AlwaysStart<Ping>("ping");
3976
3977 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
3978 // makes it such that we will only get timestamps from pi1 -> pi2 on the
3979 // second boot.
3980 {
3981 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003982 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3983 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003984
3985 event_loop_factory.RunFor(chrono::milliseconds(95));
3986
3987 pi2_logger.StartLogger(kLogfile2_1);
3988
3989 event_loop_factory.RunFor(chrono::milliseconds(4000));
3990
3991 pi2->Disconnect(pi1->node());
3992
3993 event_loop_factory.RunFor(chrono::milliseconds(1000));
3994 pi1->AlwaysStart<Ping>("ping");
3995
3996 event_loop_factory.RunFor(chrono::milliseconds(5000));
3997 pi2_logger.AppendAllFilenames(&filenames);
3998 }
3999
4000 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004001 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004002 ConfirmReadable(filenames);
4003}
4004
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004005// Tests that we properly handle only one direction ever existing after a
4006// reboot with mixed unreliable vs reliable, where reliable has an earlier
4007// timestamp than unreliable.
Brian Smartte67d7112023-03-20 12:06:30 -07004008TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase1) {
Austin Schuh7e417682023-08-11 17:05:30 -07004009 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4010 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4011
Brian Smartte67d7112023-03-20 12:06:30 -07004012 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4013 aos::configuration::ReadConfig(ArtifactPath(
4014 "aos/events/logging/multinode_pingpong_split4_mixed1_config.json"));
4015 message_bridge::TestingTimeConverter time_converter(
4016 configuration::NodesCount(&config.message()));
4017 SimulatedEventLoopFactory event_loop_factory(&config.message());
4018 event_loop_factory.SetTimeConverter(&time_converter);
4019
4020 NodeEventLoopFactory *const pi1 =
4021 event_loop_factory.GetNodeEventLoopFactory("pi1");
4022 const size_t pi1_index = configuration::GetNodeIndex(
4023 event_loop_factory.configuration(), pi1->node());
4024 NodeEventLoopFactory *const pi2 =
4025 event_loop_factory.GetNodeEventLoopFactory("pi2");
4026 const size_t pi2_index = configuration::GetNodeIndex(
4027 event_loop_factory.configuration(), pi2->node());
4028 std::vector<std::string> filenames;
4029
4030 {
4031 CHECK_EQ(pi1_index, 0u);
4032 CHECK_EQ(pi2_index, 1u);
4033
4034 time_converter.AddNextTimestamp(
4035 distributed_clock::epoch(),
4036 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4037
4038 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4039 time_converter.AddNextTimestamp(
4040 distributed_clock::epoch() + reboot_time,
4041 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4042 BootTimestamp::epoch() + reboot_time});
4043 }
4044
4045 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004046 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07004047
4048 // The following sequence using the above reference config creates
4049 // a reliable message timestamp < unreliable message timestamp.
4050 {
4051 pi1->DisableStatistics();
4052 pi2->DisableStatistics();
4053
4054 event_loop_factory.RunFor(chrono::milliseconds(95));
4055
4056 pi1->AlwaysStart<Ping>("ping");
4057
4058 event_loop_factory.RunFor(chrono::milliseconds(5250));
4059
4060 pi1->EnableStatistics();
4061
4062 event_loop_factory.RunFor(chrono::milliseconds(1000));
4063
4064 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004065 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4066 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07004067
4068 pi2_logger.StartLogger(kLogfile2_1);
4069
4070 event_loop_factory.RunFor(chrono::milliseconds(5000));
4071 pi2_logger.AppendAllFilenames(&filenames);
4072 }
4073
4074 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004075 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07004076 ConfirmReadable(filenames);
4077}
4078
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004079// Tests that we properly handle only one direction ever existing after a
4080// reboot with mixed unreliable vs reliable, where unreliable has an earlier
4081// timestamp than reliable.
Brian Smartte67d7112023-03-20 12:06:30 -07004082TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase2) {
Austin Schuh7e417682023-08-11 17:05:30 -07004083 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4084 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4085
Brian Smartte67d7112023-03-20 12:06:30 -07004086 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4087 aos::configuration::ReadConfig(ArtifactPath(
4088 "aos/events/logging/multinode_pingpong_split4_mixed2_config.json"));
4089 message_bridge::TestingTimeConverter time_converter(
4090 configuration::NodesCount(&config.message()));
4091 SimulatedEventLoopFactory event_loop_factory(&config.message());
4092 event_loop_factory.SetTimeConverter(&time_converter);
4093
4094 NodeEventLoopFactory *const pi1 =
4095 event_loop_factory.GetNodeEventLoopFactory("pi1");
4096 const size_t pi1_index = configuration::GetNodeIndex(
4097 event_loop_factory.configuration(), pi1->node());
4098 NodeEventLoopFactory *const pi2 =
4099 event_loop_factory.GetNodeEventLoopFactory("pi2");
4100 const size_t pi2_index = configuration::GetNodeIndex(
4101 event_loop_factory.configuration(), pi2->node());
4102 std::vector<std::string> filenames;
4103
4104 {
4105 CHECK_EQ(pi1_index, 0u);
4106 CHECK_EQ(pi2_index, 1u);
4107
4108 time_converter.AddNextTimestamp(
4109 distributed_clock::epoch(),
4110 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4111
4112 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4113 time_converter.AddNextTimestamp(
4114 distributed_clock::epoch() + reboot_time,
4115 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4116 BootTimestamp::epoch() + reboot_time});
4117 }
4118
4119 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004120 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07004121
4122 // The following sequence using the above reference config creates
4123 // an unreliable message timestamp < reliable message timestamp.
4124 {
4125 pi1->DisableStatistics();
4126 pi2->DisableStatistics();
4127
4128 event_loop_factory.RunFor(chrono::milliseconds(95));
4129
4130 pi1->AlwaysStart<Ping>("ping");
4131
4132 event_loop_factory.RunFor(chrono::milliseconds(5250));
4133
4134 pi1->EnableStatistics();
4135
4136 event_loop_factory.RunFor(chrono::milliseconds(1000));
4137
4138 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004139 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4140 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07004141
4142 pi2_logger.StartLogger(kLogfile2_1);
4143
4144 event_loop_factory.RunFor(chrono::milliseconds(5000));
4145 pi2_logger.AppendAllFilenames(&filenames);
4146 }
4147
4148 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004149 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07004150 ConfirmReadable(filenames);
4151}
4152
Naman Guptaa63aa132023-03-22 20:06:34 -07004153// Tests that we properly handle what used to be a time violation in one
4154// direction. This can occur when one direction goes down after sending some
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004155// data, but the other keeps working. The down direction ends up resolving to
4156// a straight line in the noncausal filter, where the direction which is still
4157// up can cross that line. Really, time progressed along just fine but we
4158// assumed that the offset was a line when it could have deviated by up to
4159// 1ms/second.
Naman Guptaa63aa132023-03-22 20:06:34 -07004160TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4161 std::vector<std::string> filenames;
4162
4163 CHECK_EQ(pi1_index_, 0u);
4164 CHECK_EQ(pi2_index_, 1u);
4165
4166 time_converter_.AddNextTimestamp(
4167 distributed_clock::epoch(),
4168 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4169
4170 const chrono::nanoseconds before_disconnect_duration =
4171 time_converter_.AddMonotonic(
4172 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4173
4174 const chrono::nanoseconds test_duration =
4175 time_converter_.AddMonotonic(
4176 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4177 time_converter_.AddMonotonic(
4178 {chrono::milliseconds(10000),
4179 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4180 time_converter_.AddMonotonic(
4181 {chrono::milliseconds(10000),
4182 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4183
4184 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004185 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004186
4187 {
4188 LoggerState pi2_logger = MakeLogger(pi2_);
4189 pi2_logger.StartLogger(kLogfile);
4190 event_loop_factory_.RunFor(before_disconnect_duration);
4191
4192 pi2_->Disconnect(pi1_->node());
4193
4194 event_loop_factory_.RunFor(test_duration);
4195 pi2_->Connect(pi1_->node());
4196
4197 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4198 pi2_logger.AppendAllFilenames(&filenames);
4199 }
4200
4201 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004202 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004203 ConfirmReadable(filenames);
4204}
4205
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004206// Tests that we can replay a logfile that has timestamps such that at least
4207// one node's epoch is at a positive distributed_clock (and thus will have to
4208// be booted after the other node(s)).
Naman Guptaa63aa132023-03-22 20:06:34 -07004209TEST_P(MultinodeLoggerTest, StartOneNodeBeforeOther) {
4210 std::vector<std::string> filenames;
4211
4212 CHECK_EQ(pi1_index_, 0u);
4213 CHECK_EQ(pi2_index_, 1u);
4214
4215 time_converter_.AddNextTimestamp(
4216 distributed_clock::epoch(),
4217 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4218
4219 const chrono::nanoseconds before_reboot_duration = chrono::milliseconds(1000);
4220 time_converter_.RebootAt(
4221 0, distributed_clock::time_point(before_reboot_duration));
4222
4223 const chrono::nanoseconds test_duration = time_converter_.AddMonotonic(
4224 {chrono::milliseconds(10000), chrono::milliseconds(10000)});
4225
4226 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004227 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004228
4229 pi2_->Disconnect(pi1_->node());
4230 pi1_->Disconnect(pi2_->node());
4231
4232 {
4233 LoggerState pi2_logger = MakeLogger(pi2_);
4234
4235 pi2_logger.StartLogger(kLogfile);
4236 event_loop_factory_.RunFor(before_reboot_duration);
4237
4238 pi2_->Connect(pi1_->node());
4239 pi1_->Connect(pi2_->node());
4240
4241 event_loop_factory_.RunFor(test_duration);
4242
4243 pi2_logger.AppendAllFilenames(&filenames);
4244 }
4245
4246 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004247 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004248 ConfirmReadable(filenames);
4249
4250 {
4251 LogReader reader(sorted_parts);
4252 SimulatedEventLoopFactory replay_factory(reader.configuration());
4253 reader.RegisterWithoutStarting(&replay_factory);
4254
4255 NodeEventLoopFactory *const replay_node =
4256 reader.event_loop_factory()->GetNodeEventLoopFactory("pi1");
4257
4258 std::unique_ptr<EventLoop> test_event_loop =
4259 replay_node->MakeEventLoop("test_reader");
4260 replay_node->OnStartup([replay_node]() {
4261 // Check that we didn't boot until at least t=0.
4262 CHECK_LE(monotonic_clock::epoch(), replay_node->monotonic_now());
4263 });
4264 test_event_loop->OnRun([&test_event_loop]() {
4265 // Check that we didn't boot until at least t=0.
4266 EXPECT_LE(monotonic_clock::epoch(), test_event_loop->monotonic_now());
4267 });
4268 reader.event_loop_factory()->Run();
4269 reader.Deregister();
4270 }
4271}
4272
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004273// Tests that when we have a loop without all the logs at all points in time,
4274// we can sort it properly.
Naman Guptaa63aa132023-03-22 20:06:34 -07004275TEST(MultinodeLoggerLoopTest, Loop) {
Austin Schuh7e417682023-08-11 17:05:30 -07004276 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4277 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4278
Naman Guptaa63aa132023-03-22 20:06:34 -07004279 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004280 aos::configuration::ReadConfig(
4281 ArtifactPath("aos/events/logging/"
4282 "multinode_pingpong_triangle_split_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07004283 message_bridge::TestingTimeConverter time_converter(
4284 configuration::NodesCount(&config.message()));
4285 SimulatedEventLoopFactory event_loop_factory(&config.message());
4286 event_loop_factory.SetTimeConverter(&time_converter);
4287
4288 NodeEventLoopFactory *const pi1 =
4289 event_loop_factory.GetNodeEventLoopFactory("pi1");
4290 NodeEventLoopFactory *const pi2 =
4291 event_loop_factory.GetNodeEventLoopFactory("pi2");
4292 NodeEventLoopFactory *const pi3 =
4293 event_loop_factory.GetNodeEventLoopFactory("pi3");
4294
4295 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004296 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004297 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004298 aos::testing::TestTmpDir() + "/logs/multi_logfile2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004299 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004300 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004301
4302 {
4303 // Make pi1 boot before everything else.
4304 time_converter.AddNextTimestamp(
4305 distributed_clock::epoch(),
4306 {BootTimestamp::epoch(),
4307 BootTimestamp::epoch() - chrono::milliseconds(100),
4308 BootTimestamp::epoch() - chrono::milliseconds(300)});
4309 }
4310
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004311 // We want to setup a situation such that 2 of the 3 legs of the loop are
4312 // very confident about time being X, and the third leg is pulling the
4313 // average off to one side.
Naman Guptaa63aa132023-03-22 20:06:34 -07004314 //
4315 // It's easiest to visualize this in timestamp_plotter.
4316
4317 std::vector<std::string> filenames;
4318 {
4319 // Have pi1 send out a reliable message at startup. This sets up a long
4320 // forwarding time message at the start to bias time.
4321 std::unique_ptr<EventLoop> pi1_event_loop = pi1->MakeEventLoop("ping");
4322 {
4323 aos::Sender<examples::Ping> ping_sender =
4324 pi1_event_loop->MakeSender<examples::Ping>("/reliable");
4325
4326 aos::Sender<examples::Ping>::Builder builder = ping_sender.MakeBuilder();
4327 examples::Ping::Builder ping_builder =
4328 builder.MakeBuilder<examples::Ping>();
4329 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
4330 }
4331
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004332 // Wait a while so there's enough data to let the worst case be rather
4333 // off.
Naman Guptaa63aa132023-03-22 20:06:34 -07004334 event_loop_factory.RunFor(chrono::seconds(1000));
4335
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004336 // Now start a receiving node first. This sets up 2 tight bounds between
4337 // 2 of the nodes.
Naman Guptaa63aa132023-03-22 20:06:34 -07004338 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004339 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4340 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004341 pi2_logger.StartLogger(kLogfile2_1);
4342
4343 event_loop_factory.RunFor(chrono::seconds(100));
4344
4345 // And now start the third leg.
4346 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004347 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4348 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004349 pi3_logger.StartLogger(kLogfile3_1);
4350
4351 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004352 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4353 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004354 pi1_logger.StartLogger(kLogfile1_1);
4355
4356 event_loop_factory.RunFor(chrono::seconds(100));
4357
4358 pi1_logger.AppendAllFilenames(&filenames);
4359 pi2_logger.AppendAllFilenames(&filenames);
4360 pi3_logger.AppendAllFilenames(&filenames);
4361 }
4362
4363 // Make sure we can read this.
4364 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004365 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004366 auto result = ConfirmReadable(filenames);
4367}
4368
Austin Schuh08dba8f2023-05-01 08:29:30 -07004369// Tests that RestartLogging works in the simple case. Unfortunately, the
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004370// failure cases involve simulating time elapsing in callbacks, which is
4371// really hard. The best we can reasonably do is make sure 2 back to back
4372// logs are parseable together.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004373TEST_P(MultinodeLoggerTest, RestartLogging) {
4374 time_converter_.AddMonotonic(
4375 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4376 std::vector<std::string> filenames;
4377 {
4378 LoggerState pi1_logger = MakeLogger(pi1_);
4379
4380 event_loop_factory_.RunFor(chrono::milliseconds(95));
4381
4382 StartLogger(&pi1_logger, logfile_base1_);
4383 aos::monotonic_clock::time_point last_rotation_time =
4384 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07004385 pi1_logger.logger->set_on_logged_period(
4386 [&](aos::monotonic_clock::time_point) {
4387 const auto now = pi1_logger.event_loop->monotonic_now();
4388 if (now > last_rotation_time + std::chrono::seconds(5)) {
4389 pi1_logger.AppendAllFilenames(&filenames);
4390 std::unique_ptr<MultiNodeFilesLogNamer> namer =
4391 pi1_logger.MakeLogNamer(logfile_base2_);
4392 pi1_logger.log_namer = namer.get();
Austin Schuh08dba8f2023-05-01 08:29:30 -07004393
Austin Schuh2f864452023-07-17 14:53:08 -07004394 pi1_logger.logger->RestartLogging(std::move(namer));
4395 last_rotation_time = now;
4396 }
4397 });
Austin Schuh08dba8f2023-05-01 08:29:30 -07004398
4399 event_loop_factory_.RunFor(chrono::milliseconds(7000));
4400
4401 pi1_logger.AppendAllFilenames(&filenames);
4402 }
4403
4404 for (const auto &x : filenames) {
4405 LOG(INFO) << x;
4406 }
4407
4408 EXPECT_GE(filenames.size(), 2u);
4409
4410 ConfirmReadable(filenames);
4411
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004412 // TODO(austin): It would be good to confirm that any one time messages end
4413 // up in both logs correctly.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004414}
4415
Austin Schuh6e93fc22023-08-22 21:27:22 -07004416// Tests that we call OnEnd without --skip_missing_forwarding_entries.
4417TEST_P(MultinodeLoggerTest, SkipMissingForwardingEntries) {
4418 if (file_strategy() == FileStrategy::kCombine) {
4419 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
4420 }
4421 time_converter_.AddMonotonic(
4422 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4423
4424 std::vector<std::string> filenames;
4425 {
4426 LoggerState pi1_logger = MakeLogger(pi1_);
4427
4428 event_loop_factory_.RunFor(chrono::milliseconds(95));
4429
4430 StartLogger(&pi1_logger);
4431 aos::monotonic_clock::time_point last_rotation_time =
4432 pi1_logger.event_loop->monotonic_now();
4433 pi1_logger.logger->set_on_logged_period(
4434 [&](aos::monotonic_clock::time_point) {
4435 const auto now = pi1_logger.event_loop->monotonic_now();
4436 if (now > last_rotation_time + std::chrono::seconds(5)) {
4437 pi1_logger.logger->Rotate();
4438 last_rotation_time = now;
4439 }
4440 });
4441
4442 event_loop_factory_.RunFor(chrono::milliseconds(15000));
4443 pi1_logger.AppendAllFilenames(&filenames);
4444 }
4445
4446 // If we remove the last remote data part, we'll trigger missing data for
4447 // timestamps.
4448 filenames.erase(std::remove_if(filenames.begin(), filenames.end(),
4449 [](const std::string &s) {
4450 return s.find("data/pi2_data.part3.bfbs") !=
4451 std::string::npos;
4452 }),
4453 filenames.end());
4454
4455 auto result = ConfirmReadable(filenames);
4456}
4457
Austin Schuh54ffea42023-08-23 13:27:04 -07004458// Tests that we call OnEnd without --skip_missing_forwarding_entries.
4459TEST(MultinodeLoggerConfigTest, SingleNode) {
4460 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4461 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4462
4463 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4464 aos::configuration::ReadConfig(
4465 ArtifactPath("aos/events/logging/multinode_single_node_config.json"));
4466 message_bridge::TestingTimeConverter time_converter(
4467 configuration::NodesCount(&config.message()));
4468 SimulatedEventLoopFactory event_loop_factory(&config.message());
4469 event_loop_factory.SetTimeConverter(&time_converter);
4470
4471 time_converter.StartEqual();
4472
4473 const std::string kLogfile1_1 =
4474 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
4475
4476 NodeEventLoopFactory *const pi1 =
4477 event_loop_factory.GetNodeEventLoopFactory("pi1");
4478
4479 std::vector<std::string> filenames;
4480
4481 {
4482 // Now start a receiving node first. This sets up 2 tight bounds between
4483 // 2 of the nodes.
4484 LoggerState pi1_logger = MakeLoggerState(
4485 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4486 FileStrategy::kKeepSeparate);
4487 pi1_logger.StartLogger(kLogfile1_1);
4488
4489 event_loop_factory.RunFor(chrono::seconds(10));
4490
4491 pi1_logger.AppendAllFilenames(&filenames);
4492 }
4493
4494 // Make sure we can read this.
4495 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4496 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4497 auto result = ConfirmReadable(filenames);
4498
4499 // TODO(austin): Probably want to stop caring about ServerStatistics,
4500 // ClientStatistics, and Timestamp since they don't really make sense.
4501}
4502
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004503// Tests that when we have evidence of 2 boots, and then start logging, the
4504// max_out_of_order_duration ends up reasonable on the boot with the start time.
4505TEST(MultinodeLoggerLoopTest, PreviousBootData) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004506 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4507 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4508
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004509 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4510 aos::configuration::ReadConfig(ArtifactPath(
4511 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4512 message_bridge::TestingTimeConverter time_converter(
4513 configuration::NodesCount(&config.message()));
4514 SimulatedEventLoopFactory event_loop_factory(&config.message());
4515 event_loop_factory.SetTimeConverter(&time_converter);
4516
4517 const UUID pi1_boot0 = UUID::Random();
4518 const UUID pi2_boot0 = UUID::Random();
4519 const UUID pi2_boot1 = UUID::Random();
4520
4521 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004522 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004523
4524 {
4525 constexpr size_t kPi1Index = 0;
4526 constexpr size_t kPi2Index = 1;
4527 time_converter.set_boot_uuid(kPi1Index, 0, pi1_boot0);
4528 time_converter.set_boot_uuid(kPi2Index, 0, pi2_boot0);
4529 time_converter.set_boot_uuid(kPi2Index, 1, pi2_boot1);
4530
4531 // Make pi1 boot before everything else.
4532 time_converter.AddNextTimestamp(
4533 distributed_clock::epoch(),
4534 {BootTimestamp::epoch(),
4535 BootTimestamp::epoch() - chrono::milliseconds(100)});
4536
4537 const chrono::nanoseconds reboot_time = chrono::seconds(1005);
4538 time_converter.AddNextTimestamp(
4539 distributed_clock::epoch() + reboot_time,
4540 {BootTimestamp::epoch() + reboot_time,
4541 BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()}});
4542 }
4543
4544 NodeEventLoopFactory *const pi1 =
4545 event_loop_factory.GetNodeEventLoopFactory("pi1");
4546 NodeEventLoopFactory *const pi2 =
4547 event_loop_factory.GetNodeEventLoopFactory("pi2");
4548
4549 // What we want is for pi2 to send a message at t=1000 on the first channel
4550 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4551 // the max out of order duration be large.
4552 //
4553 // Then, we reboot, and only send messages on a third channel (/atest2 pong).
4554 // The order is key, they need to sort in this order in the config.
4555
4556 std::vector<std::string> filenames;
4557 {
4558 {
4559 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4560 aos::Sender<examples::Pong> pong_sender =
4561 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4562
4563 pi2_event_loop->OnRun([&]() {
4564 aos::Sender<examples::Pong>::Builder builder =
4565 pong_sender.MakeBuilder();
4566 examples::Pong::Builder pong_builder =
4567 builder.MakeBuilder<examples::Pong>();
4568 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4569 });
4570
4571 event_loop_factory.RunFor(chrono::seconds(1000));
4572 }
4573
4574 {
4575 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4576 aos::Sender<examples::Pong> pong_sender =
4577 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4578
4579 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4580 examples::Pong::Builder pong_builder =
4581 builder.MakeBuilder<examples::Pong>();
4582 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4583 }
4584
4585 event_loop_factory.RunFor(chrono::seconds(10));
4586
4587 // Now start a receiving node first. This sets up 2 tight bounds between
4588 // 2 of the nodes.
4589 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004590 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4591 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004592 pi1_logger.StartLogger(kLogfile1_1);
4593
4594 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4595 aos::Sender<examples::Pong> pong_sender =
4596 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4597
4598 pi2_event_loop->AddPhasedLoop(
4599 [&pong_sender](int) {
4600 aos::Sender<examples::Pong>::Builder builder =
4601 pong_sender.MakeBuilder();
4602 examples::Pong::Builder pong_builder =
4603 builder.MakeBuilder<examples::Pong>();
4604 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4605 },
4606 chrono::milliseconds(10));
4607
4608 event_loop_factory.RunFor(chrono::seconds(100));
4609
4610 pi1_logger.AppendAllFilenames(&filenames);
4611 }
4612
4613 // Make sure we can read this.
4614 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4615 EXPECT_TRUE(AllRebootPartsMatchOutOfOrderDuration(sorted_parts, "pi2"));
4616 auto result = ConfirmReadable(filenames);
4617}
4618
4619// Tests that when we start without a connection, and then start logging, the
4620// max_out_of_order_duration ends up reasonable.
4621TEST(MultinodeLoggerLoopTest, StartDisconnected) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004622 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4623 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4624
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004625 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4626 aos::configuration::ReadConfig(ArtifactPath(
4627 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4628 message_bridge::TestingTimeConverter time_converter(
4629 configuration::NodesCount(&config.message()));
4630 SimulatedEventLoopFactory event_loop_factory(&config.message());
4631 event_loop_factory.SetTimeConverter(&time_converter);
4632
4633 time_converter.StartEqual();
4634
4635 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004636 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004637
4638 NodeEventLoopFactory *const pi1 =
4639 event_loop_factory.GetNodeEventLoopFactory("pi1");
4640 NodeEventLoopFactory *const pi2 =
4641 event_loop_factory.GetNodeEventLoopFactory("pi2");
4642
4643 // What we want is for pi2 to send a message at t=1000 on the first channel
4644 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4645 // the max out of order duration be large.
4646 //
4647 // Then, we disconnect, and only send messages on a third channel
4648 // (/atest2 pong). The order is key, they need to sort in this order in the
4649 // config so we observe them in the order which grows the
4650 // max_out_of_order_duration.
4651
4652 std::vector<std::string> filenames;
4653 {
4654 {
4655 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4656 aos::Sender<examples::Pong> pong_sender =
4657 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4658
4659 pi2_event_loop->OnRun([&]() {
4660 aos::Sender<examples::Pong>::Builder builder =
4661 pong_sender.MakeBuilder();
4662 examples::Pong::Builder pong_builder =
4663 builder.MakeBuilder<examples::Pong>();
4664 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4665 });
4666
4667 event_loop_factory.RunFor(chrono::seconds(1000));
4668 }
4669
4670 {
4671 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4672 aos::Sender<examples::Pong> pong_sender =
4673 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4674
4675 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4676 examples::Pong::Builder pong_builder =
4677 builder.MakeBuilder<examples::Pong>();
4678 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4679 }
4680
4681 event_loop_factory.RunFor(chrono::seconds(10));
4682
4683 pi1->Disconnect(pi2->node());
4684 pi2->Disconnect(pi1->node());
4685
4686 // Make data flow.
4687 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4688 aos::Sender<examples::Pong> pong_sender =
4689 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4690
4691 pi2_event_loop->AddPhasedLoop(
4692 [&pong_sender](int) {
4693 aos::Sender<examples::Pong>::Builder builder =
4694 pong_sender.MakeBuilder();
4695 examples::Pong::Builder pong_builder =
4696 builder.MakeBuilder<examples::Pong>();
4697 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4698 },
4699 chrono::milliseconds(10));
4700
4701 event_loop_factory.RunFor(chrono::seconds(10));
4702
4703 // Now start a receiving node first. This sets up 2 tight bounds between
4704 // 2 of the nodes.
4705 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004706 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4707 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004708 pi1_logger.StartLogger(kLogfile1_1);
4709
4710 event_loop_factory.RunFor(chrono::seconds(10));
4711
4712 // Now, reconnect, and everything should recover.
4713 pi1->Connect(pi2->node());
4714 pi2->Connect(pi1->node());
4715
4716 event_loop_factory.RunFor(chrono::seconds(10));
4717
4718 pi1_logger.AppendAllFilenames(&filenames);
4719 }
4720
4721 // Make sure we can read this.
4722 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4723 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4724 auto result = ConfirmReadable(filenames);
4725}
4726
Austin Schuh633858f2024-03-22 14:34:19 -07004727// Tests that only having a delayed, reliable message from a boot results in a
4728// readable log.
4729//
4730// Note: this is disabled since it doesn't work yet. Un-disable this when the
4731// code is fixed!
4732TEST(MultinodeLoggerLoopTest, DISABLED_ReliableOnlyTimestamps) {
4733 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4734 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4735
4736 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4737 aos::configuration::ReadConfig(
4738 ArtifactPath("aos/events/logging/"
4739 "multinode_pingpong_reboot_reliable_only_config.json"));
4740 message_bridge::TestingTimeConverter time_converter(
4741 configuration::NodesCount(&config.message()));
4742 SimulatedEventLoopFactory event_loop_factory(&config.message());
4743 event_loop_factory.SetTimeConverter(&time_converter);
4744
4745 constexpr chrono::nanoseconds kRebootTime = chrono::seconds(100);
4746 {
4747 time_converter.AddNextTimestamp(
4748 distributed_clock::epoch(),
4749 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4750 time_converter.AddNextTimestamp(
4751 distributed_clock::epoch() + kRebootTime,
4752 {BootTimestamp::epoch() + kRebootTime,
4753 BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()}});
Austin Schuh1124c512023-08-01 15:20:44 -07004754 }
4755
Austin Schuh633858f2024-03-22 14:34:19 -07004756 const std::string kLogfile1_1 =
4757 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
4758
4759 NodeEventLoopFactory *const pi1 =
4760 event_loop_factory.GetNodeEventLoopFactory("pi1");
4761
4762 // We want unreliable timestamps from one boot, a reliable timestamp from the
4763 // same boot, and then a long delayed reliable timestamp from the second boot.
4764 // This produces conflicting information about when the second boot happened.
4765 std::vector<std::string> filenames;
4766 PingSender *app1 = pi1->AlwaysStart<PingSender>("pingsender", "/atest1");
4767 PingSender *app2 = pi1->AlwaysStart<PingSender>("pingsender", "/atest2");
4768 event_loop_factory.RunFor(chrono::seconds(1));
4769 pi1->Stop(app2);
4770 event_loop_factory.RunFor(kRebootTime - chrono::seconds(2));
4771 pi1->Stop(app1);
4772
4773 event_loop_factory.RunFor(chrono::seconds(1) + kRebootTime * 2);
4774
4775 {
4776 // Collect a small log after reboot.
4777 LoggerState pi1_logger = MakeLoggerState(
4778 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4779 FileStrategy::kKeepSeparate);
4780 pi1_logger.StartLogger(kLogfile1_1);
4781
4782 event_loop_factory.RunFor(chrono::seconds(1));
4783
4784 pi1_logger.AppendAllFilenames(&filenames);
4785 }
4786
4787 // Make sure we can read this.
4788 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4789 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4790 auto result = ConfirmReadable(filenames);
4791}
Austin Schuh1124c512023-08-01 15:20:44 -07004792
4793// Tests that we log correctly as nodes connect slowly.
4794TEST(MultinodeLoggerLoopTest, StaggeredConnect) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004795 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4796 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4797
Austin Schuh1124c512023-08-01 15:20:44 -07004798 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4799 aos::configuration::ReadConfig(ArtifactPath(
4800 "aos/events/logging/multinode_pingpong_pi3_pingpong_config.json"));
4801 message_bridge::TestingTimeConverter time_converter(
4802 configuration::NodesCount(&config.message()));
4803 SimulatedEventLoopFactory event_loop_factory(&config.message());
4804 event_loop_factory.SetTimeConverter(&time_converter);
4805
4806 time_converter.StartEqual();
4807
4808 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004809 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Austin Schuh1124c512023-08-01 15:20:44 -07004810
4811 NodeEventLoopFactory *const pi1 =
4812 event_loop_factory.GetNodeEventLoopFactory("pi1");
4813 NodeEventLoopFactory *const pi2 =
4814 event_loop_factory.GetNodeEventLoopFactory("pi2");
4815 NodeEventLoopFactory *const pi3 =
4816 event_loop_factory.GetNodeEventLoopFactory("pi3");
4817
4818 // What we want is for pi2 to send a message at t=1000 on the first channel
4819 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4820 // the max out of order duration be large.
4821 //
4822 // Then, we disconnect, and only send messages on a third channel
4823 // (/atest2 pong). The order is key, they need to sort in this order in the
4824 // config so we observe them in the order which grows the
4825 // max_out_of_order_duration.
4826
4827 pi1->Disconnect(pi2->node());
4828 pi2->Disconnect(pi1->node());
4829
4830 pi1->Disconnect(pi3->node());
4831 pi3->Disconnect(pi1->node());
4832
4833 std::vector<std::string> filenames;
4834 pi2->AlwaysStart<PongSender>("pongsender", "/test2");
4835 pi3->AlwaysStart<PongSender>("pongsender", "/test3");
4836
4837 event_loop_factory.RunFor(chrono::seconds(10));
4838
4839 {
4840 // Now start a receiving node first. This sets up 2 tight bounds between
4841 // 2 of the nodes.
4842 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004843 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4844 FileStrategy::kKeepSeparate);
Austin Schuh1124c512023-08-01 15:20:44 -07004845 pi1_logger.StartLogger(kLogfile1_1);
4846
4847 event_loop_factory.RunFor(chrono::seconds(10));
4848
4849 // Now, reconnect, and everything should recover.
4850 pi1->Connect(pi2->node());
4851 pi2->Connect(pi1->node());
4852
4853 event_loop_factory.RunFor(chrono::seconds(10));
4854
4855 pi1->Connect(pi3->node());
4856 pi3->Connect(pi1->node());
4857
4858 event_loop_factory.RunFor(chrono::seconds(10));
4859
4860 pi1_logger.AppendAllFilenames(&filenames);
4861 }
4862
4863 // Make sure we can read this.
4864 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4865 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4866 auto result = ConfirmReadable(filenames);
4867}
4868
Stephan Pleinesf63bde82024-01-13 15:59:33 -08004869} // namespace aos::logger::testing