blob: 4980b50ca099d88ae03b18ad8a755f7330152d01 [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
15namespace aos {
16namespace logger {
17namespace testing {
18
19namespace chrono = std::chrono;
20using aos::message_bridge::RemoteMessage;
21using aos::testing::ArtifactPath;
22using aos::testing::MessageCounter;
23
Naman Guptaa63aa132023-03-22 20:06:34 -070024INSTANTIATE_TEST_SUITE_P(
25 All, MultinodeLoggerTest,
26 ::testing::Combine(
27 ::testing::Values(
28 ConfigParams{"multinode_pingpong_combined_config.json", true,
Austin Schuh6ecfe902023-08-04 22:44:37 -070029 kCombinedConfigSha1(), kCombinedConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070030 FileStrategy::kKeepSeparate,
31 ForceTimestampBuffering::kForceBufferTimestamps},
32 ConfigParams{"multinode_pingpong_combined_config.json", true,
33 kCombinedConfigSha1(), kCombinedConfigSha1(),
34 FileStrategy::kKeepSeparate,
35 ForceTimestampBuffering::kAutoBuffer},
Naman Guptaa63aa132023-03-22 20:06:34 -070036 ConfigParams{"multinode_pingpong_split_config.json", false,
Austin Schuh6ecfe902023-08-04 22:44:37 -070037 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070038 FileStrategy::kKeepSeparate,
39 ForceTimestampBuffering::kForceBufferTimestamps},
Austin Schuh6ecfe902023-08-04 22:44:37 -070040 ConfigParams{"multinode_pingpong_split_config.json", false,
41 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070042 FileStrategy::kKeepSeparate,
43 ForceTimestampBuffering::kAutoBuffer},
44 ConfigParams{"multinode_pingpong_split_config.json", false,
45 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
46 FileStrategy::kCombine,
47 ForceTimestampBuffering::kForceBufferTimestamps},
48 ConfigParams{"multinode_pingpong_split_config.json", false,
49 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
50 FileStrategy::kCombine,
51 ForceTimestampBuffering::kAutoBuffer}),
Naman Guptaa63aa132023-03-22 20:06:34 -070052 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
53
54INSTANTIATE_TEST_SUITE_P(
55 All, MultinodeLoggerDeathTest,
56 ::testing::Combine(
57 ::testing::Values(
58 ConfigParams{"multinode_pingpong_combined_config.json", true,
Austin Schuh6ecfe902023-08-04 22:44:37 -070059 kCombinedConfigSha1(), kCombinedConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070060 FileStrategy::kKeepSeparate,
61 ForceTimestampBuffering::kForceBufferTimestamps},
62 ConfigParams{"multinode_pingpong_combined_config.json", true,
63 kCombinedConfigSha1(), kCombinedConfigSha1(),
64 FileStrategy::kKeepSeparate,
65 ForceTimestampBuffering::kAutoBuffer},
Naman Guptaa63aa132023-03-22 20:06:34 -070066 ConfigParams{"multinode_pingpong_split_config.json", false,
Austin Schuh6ecfe902023-08-04 22:44:37 -070067 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070068 FileStrategy::kKeepSeparate,
69 ForceTimestampBuffering::kForceBufferTimestamps},
Austin Schuh6ecfe902023-08-04 22:44:37 -070070 ConfigParams{"multinode_pingpong_split_config.json", false,
71 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070072 FileStrategy::kKeepSeparate,
73 ForceTimestampBuffering::kAutoBuffer},
74 ConfigParams{"multinode_pingpong_split_config.json", false,
75 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
76 FileStrategy::kCombine,
77 ForceTimestampBuffering::kForceBufferTimestamps},
78 ConfigParams{"multinode_pingpong_split_config.json", false,
79 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
80 FileStrategy::kCombine,
81 ForceTimestampBuffering::kAutoBuffer}),
Naman Guptaa63aa132023-03-22 20:06:34 -070082 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
83
84// Tests that we can write and read simple multi-node log files.
85TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh6ecfe902023-08-04 22:44:37 -070086 if (file_strategy() == FileStrategy::kCombine) {
87 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
88 }
89
Naman Guptaa63aa132023-03-22 20:06:34 -070090 std::vector<std::string> actual_filenames;
91 time_converter_.StartEqual();
92
93 {
94 LoggerState pi1_logger = MakeLogger(pi1_);
95 LoggerState pi2_logger = MakeLogger(pi2_);
96
97 event_loop_factory_.RunFor(chrono::milliseconds(95));
98
99 StartLogger(&pi1_logger);
100 StartLogger(&pi2_logger);
101
102 event_loop_factory_.RunFor(chrono::milliseconds(20000));
103 pi1_logger.AppendAllFilenames(&actual_filenames);
104 pi2_logger.AppendAllFilenames(&actual_filenames);
105 }
106
107 ASSERT_THAT(actual_filenames,
108 ::testing::UnorderedElementsAreArray(logfiles_));
109
110 {
111 std::set<std::string> logfile_uuids;
112 std::set<std::string> parts_uuids;
113 // Confirm that we have the expected number of UUIDs for both the logfile
114 // UUIDs and parts UUIDs.
115 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
116 for (std::string_view f : logfiles_) {
117 log_header.emplace_back(ReadHeader(f).value());
118 if (!log_header.back().message().has_configuration()) {
119 logfile_uuids.insert(
120 log_header.back().message().log_event_uuid()->str());
121 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
122 }
123 }
124
125 EXPECT_EQ(logfile_uuids.size(), 2u);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700126 EXPECT_EQ(parts_uuids.size(), 8u);
Naman Guptaa63aa132023-03-22 20:06:34 -0700127
128 // And confirm everything is on the correct node.
129 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
130 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
131 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
132
133 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
134 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700135 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700136
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700137 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
138 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Naman Guptaa63aa132023-03-22 20:06:34 -0700139
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700140 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
141 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700142
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700143 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
144 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
145 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700146
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700147 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
148 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
Naman Guptaa63aa132023-03-22 20:06:34 -0700149
150 // And the parts index matches.
151 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700152
153 EXPECT_EQ(log_header[3].message().parts_index(), 0);
154 EXPECT_EQ(log_header[4].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700155
156 EXPECT_EQ(log_header[5].message().parts_index(), 0);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700157
158 EXPECT_EQ(log_header[6].message().parts_index(), 0);
159 EXPECT_EQ(log_header[7].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700160
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700161 EXPECT_EQ(log_header[8].message().parts_index(), 0);
162 EXPECT_EQ(log_header[9].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700163
164 EXPECT_EQ(log_header[10].message().parts_index(), 0);
165 EXPECT_EQ(log_header[11].message().parts_index(), 1);
166
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700167 EXPECT_EQ(log_header[12].message().parts_index(), 0);
168 EXPECT_EQ(log_header[13].message().parts_index(), 1);
169 EXPECT_EQ(log_header[14].message().parts_index(), 2);
Naman Guptaa63aa132023-03-22 20:06:34 -0700170
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700171 EXPECT_EQ(log_header[15].message().parts_index(), 0);
172 EXPECT_EQ(log_header[16].message().parts_index(), 1);
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700173
174 // And that the data_stored field is right.
175 EXPECT_THAT(*log_header[2].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700176 ::testing::ElementsAre(StoredDataType::DATA));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700177 EXPECT_THAT(*log_header[3].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700178 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700179 EXPECT_THAT(*log_header[4].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700180 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700181
182 EXPECT_THAT(*log_header[5].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700183 ::testing::ElementsAre(StoredDataType::DATA));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700184 EXPECT_THAT(*log_header[6].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700185 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700186 EXPECT_THAT(*log_header[7].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700187 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700188
189 EXPECT_THAT(*log_header[8].message().data_stored(),
190 ::testing::ElementsAre(StoredDataType::DATA));
191 EXPECT_THAT(*log_header[9].message().data_stored(),
192 ::testing::ElementsAre(StoredDataType::DATA));
193
194 EXPECT_THAT(*log_header[10].message().data_stored(),
195 ::testing::ElementsAre(StoredDataType::DATA));
196 EXPECT_THAT(*log_header[11].message().data_stored(),
197 ::testing::ElementsAre(StoredDataType::DATA));
198
199 EXPECT_THAT(*log_header[12].message().data_stored(),
200 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
201 EXPECT_THAT(*log_header[13].message().data_stored(),
202 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
203 EXPECT_THAT(*log_header[14].message().data_stored(),
204 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
205
206 EXPECT_THAT(*log_header[15].message().data_stored(),
207 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
208 EXPECT_THAT(*log_header[16].message().data_stored(),
209 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
Naman Guptaa63aa132023-03-22 20:06:34 -0700210 }
211
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700212 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
213 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -0700214 {
215 using ::testing::UnorderedElementsAre;
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700216 std::shared_ptr<const aos::Configuration> config = sorted_parts[0].config;
Naman Guptaa63aa132023-03-22 20:06:34 -0700217
218 // Timing reports, pings
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700219 if (shared()) {
220 EXPECT_THAT(
221 CountChannelsData(config, logfiles_[2]),
222 UnorderedElementsAre(
223 std::make_tuple("/pi1/aos", "aos.examples.Ping", 2001),
224 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
225 200),
226 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
227 21),
228 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
229 std::make_tuple("/pi1/aos", "aos.timing.Report", 60),
230 std::make_tuple("/test", "aos.examples.Ping", 2001)))
231 << " : " << logfiles_[2];
232 } else {
233 EXPECT_THAT(
234 CountChannelsData(config, logfiles_[2]),
235 UnorderedElementsAre(
236 std::make_tuple("/pi1/aos", "aos.examples.Ping", 2001),
237 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
238 200),
239 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
240 21),
241 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
242 std::make_tuple("/pi1/aos", "aos.timing.Report", 60),
243 std::make_tuple("/test", "aos.examples.Ping", 2001),
244 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
245 "aos-message_bridge-Timestamp",
246 "aos.message_bridge.RemoteMessage", 200)))
247 << " : " << logfiles_[2];
Naman Guptaa63aa132023-03-22 20:06:34 -0700248 }
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700249
250 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
251 ::testing::UnorderedElementsAre())
252 << " : " << logfiles_[3];
253 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
254 ::testing::UnorderedElementsAre())
255 << " : " << logfiles_[4];
256
Naman Guptaa63aa132023-03-22 20:06:34 -0700257 // Timestamps for pong
258 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
259 UnorderedElementsAre())
260 << " : " << logfiles_[2];
261 EXPECT_THAT(
262 CountChannelsTimestamp(config, logfiles_[3]),
263 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
264 << " : " << logfiles_[3];
265 EXPECT_THAT(
266 CountChannelsTimestamp(config, logfiles_[4]),
267 UnorderedElementsAre(
268 std::make_tuple("/test", "aos.examples.Pong", 2000),
269 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
270 << " : " << logfiles_[4];
271
Naman Guptaa63aa132023-03-22 20:06:34 -0700272 // Timing reports and pongs.
Naman Guptaa63aa132023-03-22 20:06:34 -0700273 EXPECT_THAT(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700274 CountChannelsData(config, logfiles_[5]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700275 UnorderedElementsAre(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700276 std::make_tuple("/pi2/aos", "aos.examples.Ping", 2001),
Naman Guptaa63aa132023-03-22 20:06:34 -0700277 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
278 200),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700279 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
280 21),
281 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
Sanjay Narayanan5ec00232022-07-08 15:21:30 -0700282 std::make_tuple("/pi2/aos", "aos.timing.Report", 60),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700283 std::make_tuple("/test", "aos.examples.Pong", 2001)))
284 << " : " << logfiles_[5];
285 EXPECT_THAT(CountChannelsData(config, logfiles_[6]), UnorderedElementsAre())
286 << " : " << logfiles_[6];
287 EXPECT_THAT(CountChannelsData(config, logfiles_[7]), UnorderedElementsAre())
Naman Guptaa63aa132023-03-22 20:06:34 -0700288 << " : " << logfiles_[7];
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700289 // And ping timestamps.
290 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
291 UnorderedElementsAre())
292 << " : " << logfiles_[5];
Naman Guptaa63aa132023-03-22 20:06:34 -0700293 EXPECT_THAT(
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700294 CountChannelsTimestamp(config, logfiles_[6]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700295 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700296 << " : " << logfiles_[6];
Naman Guptaa63aa132023-03-22 20:06:34 -0700297 EXPECT_THAT(
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700298 CountChannelsTimestamp(config, logfiles_[7]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700299 UnorderedElementsAre(
300 std::make_tuple("/test", "aos.examples.Ping", 2000),
301 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700302 << " : " << logfiles_[7];
Naman Guptaa63aa132023-03-22 20:06:34 -0700303
304 // And then test that the remotely logged timestamp data files only have
305 // timestamps in them.
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700306 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
307 UnorderedElementsAre())
308 << " : " << logfiles_[8];
309 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
310 UnorderedElementsAre())
311 << " : " << logfiles_[9];
Naman Guptaa63aa132023-03-22 20:06:34 -0700312 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
313 UnorderedElementsAre())
314 << " : " << logfiles_[10];
315 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
316 UnorderedElementsAre())
317 << " : " << logfiles_[11];
Naman Guptaa63aa132023-03-22 20:06:34 -0700318
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700319 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700320 UnorderedElementsAre(std::make_tuple(
321 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700322 << " : " << logfiles_[8];
323 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700324 UnorderedElementsAre(std::make_tuple(
325 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700326 << " : " << logfiles_[9];
Naman Guptaa63aa132023-03-22 20:06:34 -0700327
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700328 // Pong snd timestamp data.
329 EXPECT_THAT(
330 CountChannelsData(config, logfiles_[10]),
331 UnorderedElementsAre(
332 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 9),
333 std::make_tuple("/test", "aos.examples.Pong", 91)))
334 << " : " << logfiles_[10];
335 EXPECT_THAT(
336 CountChannelsData(config, logfiles_[11]),
337 UnorderedElementsAre(
338 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 191),
339 std::make_tuple("/test", "aos.examples.Pong", 1910)))
340 << " : " << logfiles_[11];
Naman Guptaa63aa132023-03-22 20:06:34 -0700341
342 // Timestamps from pi2 on pi1, and the other way.
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700343 // if (shared()) {
344 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
345 UnorderedElementsAre())
346 << " : " << logfiles_[12];
347 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
348 UnorderedElementsAre())
349 << " : " << logfiles_[13];
350 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
351 UnorderedElementsAre())
352 << " : " << logfiles_[14];
353 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
354 UnorderedElementsAre())
355 << " : " << logfiles_[15];
356 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
357 UnorderedElementsAre())
358 << " : " << logfiles_[16];
Naman Guptaa63aa132023-03-22 20:06:34 -0700359
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700360 EXPECT_THAT(
361 CountChannelsTimestamp(config, logfiles_[12]),
362 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
363 << " : " << logfiles_[12];
364 EXPECT_THAT(
365 CountChannelsTimestamp(config, logfiles_[13]),
366 UnorderedElementsAre(
367 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
368 std::make_tuple("/test", "aos.examples.Ping", 90)))
369 << " : " << logfiles_[13];
370 EXPECT_THAT(
371 CountChannelsTimestamp(config, logfiles_[14]),
372 UnorderedElementsAre(
373 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
374 std::make_tuple("/test", "aos.examples.Ping", 1910)))
375 << " : " << logfiles_[14];
376 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
377 UnorderedElementsAre(std::make_tuple(
378 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
379 << " : " << logfiles_[15];
380 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
381 UnorderedElementsAre(std::make_tuple(
382 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
383 << " : " << logfiles_[16];
Naman Guptaa63aa132023-03-22 20:06:34 -0700384 }
385
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700386 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -0700387
388 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
389 log_reader_factory.set_send_delay(chrono::microseconds(0));
390
391 // This sends out the fetched messages and advances time to the start of the
392 // log file.
393 reader.Register(&log_reader_factory);
394
395 const Node *pi1 =
396 configuration::GetNode(log_reader_factory.configuration(), "pi1");
397 const Node *pi2 =
398 configuration::GetNode(log_reader_factory.configuration(), "pi2");
399
400 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
401 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
402 LOG(INFO) << "now pi1 "
403 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
404 LOG(INFO) << "now pi2 "
405 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
406
407 EXPECT_THAT(reader.LoggedNodes(),
408 ::testing::ElementsAre(
409 configuration::GetNode(reader.logged_configuration(), pi1),
410 configuration::GetNode(reader.logged_configuration(), pi2)));
411
412 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
413
414 std::unique_ptr<EventLoop> pi1_event_loop =
415 log_reader_factory.MakeEventLoop("test", pi1);
416 std::unique_ptr<EventLoop> pi2_event_loop =
417 log_reader_factory.MakeEventLoop("test", pi2);
418
419 int pi1_ping_count = 10;
420 int pi2_ping_count = 10;
421 int pi1_pong_count = 10;
422 int pi2_pong_count = 10;
423
424 // Confirm that the ping value matches.
425 pi1_event_loop->MakeWatcher(
426 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
427 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
428 << pi1_event_loop->context().monotonic_remote_time << " -> "
429 << pi1_event_loop->context().monotonic_event_time;
430 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
431 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
432 pi1_ping_count * chrono::milliseconds(10) +
433 monotonic_clock::epoch());
434 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
435 pi1_ping_count * chrono::milliseconds(10) +
436 realtime_clock::epoch());
437 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
438 pi1_event_loop->context().monotonic_event_time);
439 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
440 pi1_event_loop->context().realtime_event_time);
441
442 ++pi1_ping_count;
443 });
444 pi2_event_loop->MakeWatcher(
445 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
446 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
447 << pi2_event_loop->context().monotonic_remote_time << " -> "
448 << pi2_event_loop->context().monotonic_event_time;
449 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
450
451 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
452 pi2_ping_count * chrono::milliseconds(10) +
453 monotonic_clock::epoch());
454 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
455 pi2_ping_count * chrono::milliseconds(10) +
456 realtime_clock::epoch());
457 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
458 chrono::microseconds(150),
459 pi2_event_loop->context().monotonic_event_time);
460 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
461 chrono::microseconds(150),
462 pi2_event_loop->context().realtime_event_time);
463 ++pi2_ping_count;
464 });
465
466 constexpr ssize_t kQueueIndexOffset = -9;
467 // Confirm that the ping and pong counts both match, and the value also
468 // matches.
469 pi1_event_loop->MakeWatcher(
470 "/test", [&pi1_event_loop, &pi1_ping_count,
471 &pi1_pong_count](const examples::Pong &pong) {
472 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
473 << pi1_event_loop->context().monotonic_remote_time << " -> "
474 << pi1_event_loop->context().monotonic_event_time;
475
476 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
477 pi1_pong_count + kQueueIndexOffset);
478 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
479 chrono::microseconds(200) +
480 pi1_pong_count * chrono::milliseconds(10) +
481 monotonic_clock::epoch());
482 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
483 chrono::microseconds(200) +
484 pi1_pong_count * chrono::milliseconds(10) +
485 realtime_clock::epoch());
486
487 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
488 chrono::microseconds(150),
489 pi1_event_loop->context().monotonic_event_time);
490 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
491 chrono::microseconds(150),
492 pi1_event_loop->context().realtime_event_time);
493
494 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
495 ++pi1_pong_count;
496 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
497 });
498 pi2_event_loop->MakeWatcher(
499 "/test", [&pi2_event_loop, &pi2_ping_count,
500 &pi2_pong_count](const examples::Pong &pong) {
501 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
502 << pi2_event_loop->context().monotonic_remote_time << " -> "
503 << pi2_event_loop->context().monotonic_event_time;
504
505 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
506 pi2_pong_count + kQueueIndexOffset);
507
508 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
509 chrono::microseconds(200) +
510 pi2_pong_count * chrono::milliseconds(10) +
511 monotonic_clock::epoch());
512 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
513 chrono::microseconds(200) +
514 pi2_pong_count * chrono::milliseconds(10) +
515 realtime_clock::epoch());
516
517 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
518 pi2_event_loop->context().monotonic_event_time);
519 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
520 pi2_event_loop->context().realtime_event_time);
521
522 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
523 ++pi2_pong_count;
524 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
525 });
526
527 log_reader_factory.Run();
528 EXPECT_EQ(pi1_ping_count, 2010);
529 EXPECT_EQ(pi2_ping_count, 2010);
530 EXPECT_EQ(pi1_pong_count, 2010);
531 EXPECT_EQ(pi2_pong_count, 2010);
532
533 reader.Deregister();
534}
535
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600536// MultinodeLoggerTest that tests the mutate callback works across multiple
537// nodes with remapping
538TEST_P(MultinodeLoggerTest, MultiNodeRemapMutateCallback) {
539 time_converter_.StartEqual();
540 std::vector<std::string> actual_filenames;
541
542 {
543 LoggerState pi1_logger = MakeLogger(pi1_);
544 LoggerState pi2_logger = MakeLogger(pi2_);
545
546 event_loop_factory_.RunFor(chrono::milliseconds(95));
547
548 StartLogger(&pi1_logger);
549 StartLogger(&pi2_logger);
550
551 event_loop_factory_.RunFor(chrono::milliseconds(20000));
552 pi1_logger.AppendAllFilenames(&actual_filenames);
553 pi2_logger.AppendAllFilenames(&actual_filenames);
554 }
555
Austin Schuh8fb4b452023-08-04 17:02:27 -0700556 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700557 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600558
559 LogReader reader(sorted_parts, &config_.message());
560 // Remap just on pi1.
561 reader.RemapLoggedChannel<examples::Pong>(
562 "/test", configuration::GetNode(reader.configuration(), "pi1"));
563
564 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
565
566 int pong_count = 0;
567 // Adds a callback which mutates the value of the pong message before the
568 // message is sent which is the feature we are testing here
569 reader.AddBeforeSendCallback("/test",
570 [&pong_count](aos::examples::Pong *pong) {
571 pong->mutate_value(pong->value() + 1);
572 pong_count = pong->value();
573 });
574
575 // This sends out the fetched messages and advances time to the start of the
576 // log file.
577 reader.Register(&log_reader_factory);
578
579 const Node *pi1 =
580 configuration::GetNode(log_reader_factory.configuration(), "pi1");
581 const Node *pi2 =
582 configuration::GetNode(log_reader_factory.configuration(), "pi2");
583
584 EXPECT_THAT(reader.LoggedNodes(),
585 ::testing::ElementsAre(
586 configuration::GetNode(reader.logged_configuration(), pi1),
587 configuration::GetNode(reader.logged_configuration(), pi2)));
588
589 std::unique_ptr<EventLoop> pi1_event_loop =
590 log_reader_factory.MakeEventLoop("test", pi1);
591 std::unique_ptr<EventLoop> pi2_event_loop =
592 log_reader_factory.MakeEventLoop("test", pi2);
593
594 pi1_event_loop->MakeWatcher("/original/test",
595 [&pong_count](const examples::Pong &pong) {
596 EXPECT_EQ(pong_count, pong.value());
597 });
598
599 pi2_event_loop->MakeWatcher("/test",
600 [&pong_count](const examples::Pong &pong) {
601 EXPECT_EQ(pong_count, pong.value());
602 });
603
604 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
605 reader.Deregister();
606
607 EXPECT_EQ(pong_count, 2011);
608}
609
610// MultinodeLoggerTest that tests the mutate callback works across multiple
611// nodes
612TEST_P(MultinodeLoggerTest, MultiNodeMutateCallback) {
613 time_converter_.StartEqual();
614 std::vector<std::string> actual_filenames;
615
616 {
617 LoggerState pi1_logger = MakeLogger(pi1_);
618 LoggerState pi2_logger = MakeLogger(pi2_);
619
620 event_loop_factory_.RunFor(chrono::milliseconds(95));
621
622 StartLogger(&pi1_logger);
623 StartLogger(&pi2_logger);
624
625 event_loop_factory_.RunFor(chrono::milliseconds(20000));
626 pi1_logger.AppendAllFilenames(&actual_filenames);
627 pi2_logger.AppendAllFilenames(&actual_filenames);
628 }
629
Austin Schuh8fb4b452023-08-04 17:02:27 -0700630 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700631 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600632
633 LogReader reader(sorted_parts, &config_.message());
634
635 int pong_count = 0;
636 // Adds a callback which mutates the value of the pong message before the
637 // message is sent which is the feature we are testing here
638 reader.AddBeforeSendCallback("/test",
639 [&pong_count](aos::examples::Pong *pong) {
640 pong->mutate_value(pong->value() + 1);
641 pong_count = pong->value();
642 });
643
644 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
645
646 // This sends out the fetched messages and advances time to the start of the
647 // log file.
648 reader.Register(&log_reader_factory);
649
650 const Node *pi1 =
651 configuration::GetNode(log_reader_factory.configuration(), "pi1");
652 const Node *pi2 =
653 configuration::GetNode(log_reader_factory.configuration(), "pi2");
654
655 EXPECT_THAT(reader.LoggedNodes(),
656 ::testing::ElementsAre(
657 configuration::GetNode(reader.logged_configuration(), pi1),
658 configuration::GetNode(reader.logged_configuration(), pi2)));
659
660 std::unique_ptr<EventLoop> pi1_event_loop =
661 log_reader_factory.MakeEventLoop("test", pi1);
662 std::unique_ptr<EventLoop> pi2_event_loop =
663 log_reader_factory.MakeEventLoop("test", pi2);
664
665 pi1_event_loop->MakeWatcher("/test",
666 [&pong_count](const examples::Pong &pong) {
667 EXPECT_EQ(pong_count, pong.value());
668 });
669
670 pi2_event_loop->MakeWatcher("/test",
671 [&pong_count](const examples::Pong &pong) {
672 EXPECT_EQ(pong_count, pong.value());
673 });
674
675 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
676 reader.Deregister();
677
678 EXPECT_EQ(pong_count, 2011);
679}
680
681// Tests that the before send callback is only called from the sender node if it
682// is forwarded
683TEST_P(MultinodeLoggerTest, OnlyDoBeforeSendCallbackOnSenderNode) {
684 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700685
686 std::vector<std::string> filenames;
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600687 {
688 LoggerState pi1_logger = MakeLogger(pi1_);
689 LoggerState pi2_logger = MakeLogger(pi2_);
690
691 event_loop_factory_.RunFor(chrono::milliseconds(95));
692
693 StartLogger(&pi1_logger);
694 StartLogger(&pi2_logger);
695
696 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700697
698 pi1_logger.AppendAllFilenames(&filenames);
699 pi2_logger.AppendAllFilenames(&filenames);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600700 }
701
Austin Schuh8fb4b452023-08-04 17:02:27 -0700702 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700703 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
704 LogReader reader(sorted_parts);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600705
706 int ping_count = 0;
707 // Adds a callback which mutates the value of the pong message before the
708 // message is sent which is the feature we are testing here
709 reader.AddBeforeSendCallback("/test",
710 [&ping_count](aos::examples::Ping *ping) {
711 ++ping_count;
712 ping->mutate_value(ping_count);
713 });
714
715 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
716 log_reader_factory.set_send_delay(chrono::microseconds(0));
717
718 reader.Register(&log_reader_factory);
719
720 const Node *pi1 =
721 configuration::GetNode(log_reader_factory.configuration(), "pi1");
722 const Node *pi2 =
723 configuration::GetNode(log_reader_factory.configuration(), "pi2");
724
725 std::unique_ptr<EventLoop> pi1_event_loop =
726 log_reader_factory.MakeEventLoop("test", pi1);
727 pi1_event_loop->SkipTimingReport();
728 std::unique_ptr<EventLoop> pi2_event_loop =
729 log_reader_factory.MakeEventLoop("test", pi2);
730 pi2_event_loop->SkipTimingReport();
731
732 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
733 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
734
735 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
736 pi1_ping_timestamp;
737 if (!shared()) {
738 pi1_ping_timestamp =
739 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
740 pi1_event_loop.get(),
741 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
742 }
743
744 log_reader_factory.Run();
745
746 EXPECT_EQ(pi1_ping.count(), 2000u);
747 EXPECT_EQ(pi2_ping.count(), 2000u);
748 // If the BeforeSendCallback is called on both nodes, then the ping count
749 // would be 4002 instead of 2001
750 EXPECT_EQ(ping_count, 2001u);
751 if (!shared()) {
752 EXPECT_EQ(pi1_ping_timestamp->count(), 2000u);
753 }
754
755 reader.Deregister();
756}
757
758// Tests that we do not allow adding callbacks after Register is called
759TEST_P(MultinodeLoggerDeathTest, AddCallbackAfterRegister) {
760 time_converter_.StartEqual();
761 std::vector<std::string> actual_filenames;
762
763 {
764 LoggerState pi1_logger = MakeLogger(pi1_);
765 LoggerState pi2_logger = MakeLogger(pi2_);
766
767 event_loop_factory_.RunFor(chrono::milliseconds(95));
768
769 StartLogger(&pi1_logger);
770 StartLogger(&pi2_logger);
771
772 event_loop_factory_.RunFor(chrono::milliseconds(20000));
773 pi1_logger.AppendAllFilenames(&actual_filenames);
774 pi2_logger.AppendAllFilenames(&actual_filenames);
775 }
776
Austin Schuh8fb4b452023-08-04 17:02:27 -0700777 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700778 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600779
780 LogReader reader(sorted_parts, &config_.message());
781 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
782 reader.Register(&log_reader_factory);
783 EXPECT_DEATH(
784 {
785 reader.AddBeforeSendCallback("/test", [](aos::examples::Pong *) {
786 LOG(FATAL) << "This should not be called";
787 });
788 },
789 "Cannot add callbacks after calling Register");
790 reader.Deregister();
791}
792
Naman Guptaa63aa132023-03-22 20:06:34 -0700793// Test that if we feed the replay with a mismatched node list that we die on
794// the LogReader constructor.
795TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
796 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700797
798 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -0700799 {
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));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700809
810 pi1_logger.AppendAllFilenames(&filenames);
811 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -0700812 }
813
814 // Test that, if we add an additional node to the replay config that the
815 // logger complains about the mismatch in number of nodes.
816 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
817 configuration::MergeWithConfig(&config_.message(), R"({
818 "nodes": [
819 {
820 "name": "extra-node"
821 }
822 ]
823 }
824 )");
825
Austin Schuh8fb4b452023-08-04 17:02:27 -0700826 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700827 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -0700828 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
829 "Log file and replay config need to have matching nodes lists.");
830}
831
832// Tests that we can read log files where they don't start at the same monotonic
833// time.
834TEST_P(MultinodeLoggerTest, StaggeredStart) {
835 time_converter_.StartEqual();
836 std::vector<std::string> actual_filenames;
837
838 {
839 LoggerState pi1_logger = MakeLogger(pi1_);
840 LoggerState pi2_logger = MakeLogger(pi2_);
841
842 event_loop_factory_.RunFor(chrono::milliseconds(95));
843
844 StartLogger(&pi1_logger);
845
846 event_loop_factory_.RunFor(chrono::milliseconds(200));
847
848 StartLogger(&pi2_logger);
849
850 event_loop_factory_.RunFor(chrono::milliseconds(20000));
851 pi1_logger.AppendAllFilenames(&actual_filenames);
852 pi2_logger.AppendAllFilenames(&actual_filenames);
853 }
854
855 // Since we delay starting pi2, it already knows about all the timestamps so
856 // we don't end up with extra parts.
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700857 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
858 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
859 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -0700860
861 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
862 log_reader_factory.set_send_delay(chrono::microseconds(0));
863
864 // This sends out the fetched messages and advances time to the start of the
865 // log file.
866 reader.Register(&log_reader_factory);
867
868 const Node *pi1 =
869 configuration::GetNode(log_reader_factory.configuration(), "pi1");
870 const Node *pi2 =
871 configuration::GetNode(log_reader_factory.configuration(), "pi2");
872
873 EXPECT_THAT(reader.LoggedNodes(),
874 ::testing::ElementsAre(
875 configuration::GetNode(reader.logged_configuration(), pi1),
876 configuration::GetNode(reader.logged_configuration(), pi2)));
877
878 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
879
880 std::unique_ptr<EventLoop> pi1_event_loop =
881 log_reader_factory.MakeEventLoop("test", pi1);
882 std::unique_ptr<EventLoop> pi2_event_loop =
883 log_reader_factory.MakeEventLoop("test", pi2);
884
885 int pi1_ping_count = 30;
886 int pi2_ping_count = 30;
887 int pi1_pong_count = 30;
888 int pi2_pong_count = 30;
889
890 // Confirm that the ping value matches.
891 pi1_event_loop->MakeWatcher(
892 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
893 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
894 << pi1_event_loop->context().monotonic_remote_time << " -> "
895 << pi1_event_loop->context().monotonic_event_time;
896 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
897
898 ++pi1_ping_count;
899 });
900 pi2_event_loop->MakeWatcher(
901 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
902 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
903 << pi2_event_loop->context().monotonic_remote_time << " -> "
904 << pi2_event_loop->context().monotonic_event_time;
905 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
906
907 ++pi2_ping_count;
908 });
909
910 // Confirm that the ping and pong counts both match, and the value also
911 // matches.
912 pi1_event_loop->MakeWatcher(
913 "/test", [&pi1_event_loop, &pi1_ping_count,
914 &pi1_pong_count](const examples::Pong &pong) {
915 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
916 << pi1_event_loop->context().monotonic_remote_time << " -> "
917 << pi1_event_loop->context().monotonic_event_time;
918
919 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
920 ++pi1_pong_count;
921 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
922 });
923 pi2_event_loop->MakeWatcher(
924 "/test", [&pi2_event_loop, &pi2_ping_count,
925 &pi2_pong_count](const examples::Pong &pong) {
926 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
927 << pi2_event_loop->context().monotonic_remote_time << " -> "
928 << pi2_event_loop->context().monotonic_event_time;
929
930 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
931 ++pi2_pong_count;
932 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
933 });
934
935 log_reader_factory.Run();
936 EXPECT_EQ(pi1_ping_count, 2030);
937 EXPECT_EQ(pi2_ping_count, 2030);
938 EXPECT_EQ(pi1_pong_count, 2030);
939 EXPECT_EQ(pi2_pong_count, 2030);
940
941 reader.Deregister();
942}
943
944// Tests that we can read log files where the monotonic clocks drift and don't
945// match correctly. While we are here, also test that different ending times
946// also is readable.
947TEST_P(MultinodeLoggerTest, MismatchedClocks) {
948 // TODO(austin): Negate...
949 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
950
951 time_converter_.AddMonotonic(
952 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
953 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
954 // skew to be 200 uS/s
955 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
956 {chrono::milliseconds(95),
957 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
958 // Run another 200 ms to have one logger start first.
959 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
960 {chrono::milliseconds(200), chrono::milliseconds(200)});
961 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
962 // go far enough to cause problems if this isn't accounted for.
963 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
964 {chrono::milliseconds(20000),
965 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
966 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
967 {chrono::milliseconds(40000),
968 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
969 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
970 {chrono::milliseconds(400), chrono::milliseconds(400)});
971
Austin Schuh8fb4b452023-08-04 17:02:27 -0700972 std::vector<std::string> actual_filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -0700973 {
974 LoggerState pi2_logger = MakeLogger(pi2_);
975
976 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
977 << pi2_->realtime_now() << " distributed "
978 << pi2_->ToDistributedClock(pi2_->monotonic_now());
979
980 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
981 << pi2_->realtime_now() << " distributed "
982 << pi2_->ToDistributedClock(pi2_->monotonic_now());
983
984 event_loop_factory_.RunFor(startup_sleep1);
985
986 StartLogger(&pi2_logger);
987
988 event_loop_factory_.RunFor(startup_sleep2);
989
990 {
991 // Run pi1's logger for only part of the time.
992 LoggerState pi1_logger = MakeLogger(pi1_);
993
994 StartLogger(&pi1_logger);
995 event_loop_factory_.RunFor(logger_run1);
996
997 // Make sure we slewed time far enough so that the difference is greater
998 // than the network delay. This confirms that if we sort incorrectly, it
999 // would show in the results.
1000 EXPECT_LT(
1001 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1002 -event_loop_factory_.send_delay() -
1003 event_loop_factory_.network_delay());
1004
1005 event_loop_factory_.RunFor(logger_run2);
1006
1007 // And now check that we went far enough the other way to make sure we
1008 // cover both problems.
1009 EXPECT_GT(
1010 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1011 event_loop_factory_.send_delay() +
1012 event_loop_factory_.network_delay());
Austin Schuh8fb4b452023-08-04 17:02:27 -07001013
1014 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001015 }
1016
1017 // And log a bit more on pi2.
1018 event_loop_factory_.RunFor(logger_run3);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001019
1020 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001021 }
1022
Austin Schuh8fb4b452023-08-04 17:02:27 -07001023 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001024 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1025 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001026
1027 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1028 log_reader_factory.set_send_delay(chrono::microseconds(0));
1029
1030 const Node *pi1 =
1031 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1032 const Node *pi2 =
1033 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1034
1035 // This sends out the fetched messages and advances time to the start of the
1036 // log file.
1037 reader.Register(&log_reader_factory);
1038
1039 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1040 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1041 LOG(INFO) << "now pi1 "
1042 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1043 LOG(INFO) << "now pi2 "
1044 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1045
1046 LOG(INFO) << "Done registering (pi1) "
1047 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1048 << " "
1049 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1050 LOG(INFO) << "Done registering (pi2) "
1051 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1052 << " "
1053 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1054
1055 EXPECT_THAT(reader.LoggedNodes(),
1056 ::testing::ElementsAre(
1057 configuration::GetNode(reader.logged_configuration(), pi1),
1058 configuration::GetNode(reader.logged_configuration(), pi2)));
1059
1060 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1061
1062 std::unique_ptr<EventLoop> pi1_event_loop =
1063 log_reader_factory.MakeEventLoop("test", pi1);
1064 std::unique_ptr<EventLoop> pi2_event_loop =
1065 log_reader_factory.MakeEventLoop("test", pi2);
1066
1067 int pi1_ping_count = 30;
1068 int pi2_ping_count = 30;
1069 int pi1_pong_count = 30;
1070 int pi2_pong_count = 30;
1071
1072 // Confirm that the ping value matches.
1073 pi1_event_loop->MakeWatcher(
1074 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1075 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1076 << pi1_event_loop->context().monotonic_remote_time << " -> "
1077 << pi1_event_loop->context().monotonic_event_time;
1078 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1079
1080 ++pi1_ping_count;
1081 });
1082 pi2_event_loop->MakeWatcher(
1083 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1084 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1085 << pi2_event_loop->context().monotonic_remote_time << " -> "
1086 << pi2_event_loop->context().monotonic_event_time;
1087 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1088
1089 ++pi2_ping_count;
1090 });
1091
1092 // Confirm that the ping and pong counts both match, and the value also
1093 // matches.
1094 pi1_event_loop->MakeWatcher(
1095 "/test", [&pi1_event_loop, &pi1_ping_count,
1096 &pi1_pong_count](const examples::Pong &pong) {
1097 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1098 << pi1_event_loop->context().monotonic_remote_time << " -> "
1099 << pi1_event_loop->context().monotonic_event_time;
1100
1101 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1102 ++pi1_pong_count;
1103 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1104 });
1105 pi2_event_loop->MakeWatcher(
1106 "/test", [&pi2_event_loop, &pi2_ping_count,
1107 &pi2_pong_count](const examples::Pong &pong) {
1108 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1109 << pi2_event_loop->context().monotonic_remote_time << " -> "
1110 << pi2_event_loop->context().monotonic_event_time;
1111
1112 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1113 ++pi2_pong_count;
1114 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1115 });
1116
1117 log_reader_factory.Run();
1118 EXPECT_EQ(pi1_ping_count, 6030);
1119 EXPECT_EQ(pi2_ping_count, 6030);
1120 EXPECT_EQ(pi1_pong_count, 6030);
1121 EXPECT_EQ(pi2_pong_count, 6030);
1122
1123 reader.Deregister();
1124}
1125
1126// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
1127TEST_P(MultinodeLoggerTest, SortParts) {
1128 time_converter_.StartEqual();
1129 // Make a bunch of parts.
1130 {
1131 LoggerState pi1_logger = MakeLogger(pi1_);
1132 LoggerState pi2_logger = MakeLogger(pi2_);
1133
1134 event_loop_factory_.RunFor(chrono::milliseconds(95));
1135
1136 StartLogger(&pi1_logger);
1137 StartLogger(&pi2_logger);
1138
1139 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1140 }
1141
1142 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1143 VerifyParts(sorted_parts);
1144}
1145
1146// Tests that we can sort a bunch of parts with an empty part. We should ignore
1147// it and remove it from the sorted list.
1148TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07001149 std::vector<std::string> actual_filenames;
1150
Naman Guptaa63aa132023-03-22 20:06:34 -07001151 time_converter_.StartEqual();
1152 // Make a bunch of parts.
1153 {
1154 LoggerState pi1_logger = MakeLogger(pi1_);
1155 LoggerState pi2_logger = MakeLogger(pi2_);
1156
1157 event_loop_factory_.RunFor(chrono::milliseconds(95));
1158
1159 StartLogger(&pi1_logger);
1160 StartLogger(&pi2_logger);
1161
1162 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001163 pi1_logger.AppendAllFilenames(&actual_filenames);
1164 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001165 }
1166
1167 // TODO(austin): Should we flip out if the file can't open?
1168 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
1169
1170 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
Austin Schuh8fb4b452023-08-04 17:02:27 -07001171 actual_filenames.emplace_back(kEmptyFile);
Naman Guptaa63aa132023-03-22 20:06:34 -07001172
Austin Schuh8fb4b452023-08-04 17:02:27 -07001173 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001174 VerifyParts(sorted_parts, {kEmptyFile});
1175}
1176
1177// Tests that we can sort a bunch of parts with the end missing off a
1178// file. We should use the part we can read.
1179TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07001180 if (file_strategy() == FileStrategy::kCombine) {
1181 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
1182 }
1183
Naman Guptaa63aa132023-03-22 20:06:34 -07001184 std::vector<std::string> actual_filenames;
1185 time_converter_.StartEqual();
1186 // Make a bunch of parts.
1187 {
1188 LoggerState pi1_logger = MakeLogger(pi1_);
1189 LoggerState pi2_logger = MakeLogger(pi2_);
1190
1191 event_loop_factory_.RunFor(chrono::milliseconds(95));
1192
1193 StartLogger(&pi1_logger);
1194 StartLogger(&pi2_logger);
1195
1196 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1197
1198 pi1_logger.AppendAllFilenames(&actual_filenames);
1199 pi2_logger.AppendAllFilenames(&actual_filenames);
1200 }
1201
1202 ASSERT_THAT(actual_filenames,
1203 ::testing::UnorderedElementsAreArray(logfiles_));
1204
1205 // Strip off the end of one of the files. Pick one with a lot of data.
1206 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1207 // that we don't corrupt the entire log part.
1208 ::std::string compressed_contents =
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001209 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Naman Guptaa63aa132023-03-22 20:06:34 -07001210
1211 aos::util::WriteStringToFileOrDie(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001212 logfiles_[2],
Naman Guptaa63aa132023-03-22 20:06:34 -07001213 compressed_contents.substr(0, compressed_contents.size() - 100));
1214
1215 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1216 VerifyParts(sorted_parts);
1217}
1218
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001219// Tests that if we remap a logged channel, it shows up correctly.
Naman Guptaa63aa132023-03-22 20:06:34 -07001220TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
1221 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -07001222
1223 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07001224 {
1225 LoggerState pi1_logger = MakeLogger(pi1_);
1226 LoggerState pi2_logger = MakeLogger(pi2_);
1227
1228 event_loop_factory_.RunFor(chrono::milliseconds(95));
1229
1230 StartLogger(&pi1_logger);
1231 StartLogger(&pi2_logger);
1232
1233 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001234
1235 pi1_logger.AppendAllFilenames(&filenames);
1236 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001237 }
1238
Austin Schuh8fb4b452023-08-04 17:02:27 -07001239 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001240 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1241 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001242
1243 // Remap just on pi1.
1244 reader.RemapLoggedChannel<aos::timing::Report>(
1245 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1246
1247 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1248 log_reader_factory.set_send_delay(chrono::microseconds(0));
1249
1250 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1251 // Note: An extra channel gets remapped automatically due to a timestamp
1252 // channel being LOCAL_LOGGER'd.
1253 ASSERT_EQ(remapped_channels.size(), std::get<0>(GetParam()).shared ? 1u : 2u);
1254 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1255 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1256 if (!std::get<0>(GetParam()).shared) {
1257 EXPECT_EQ(remapped_channels[1]->name()->string_view(),
1258 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1259 "aos-message_bridge-Timestamp");
1260 EXPECT_EQ(remapped_channels[1]->type()->string_view(),
1261 "aos.message_bridge.RemoteMessage");
1262 }
1263
1264 reader.Register(&log_reader_factory);
1265
1266 const Node *pi1 =
1267 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1268 const Node *pi2 =
1269 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1270
1271 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1272 // else should have moved.
1273 std::unique_ptr<EventLoop> pi1_event_loop =
1274 log_reader_factory.MakeEventLoop("test", pi1);
1275 pi1_event_loop->SkipTimingReport();
1276 std::unique_ptr<EventLoop> full_pi1_event_loop =
1277 log_reader_factory.MakeEventLoop("test", pi1);
1278 full_pi1_event_loop->SkipTimingReport();
1279 std::unique_ptr<EventLoop> pi2_event_loop =
1280 log_reader_factory.MakeEventLoop("test", pi2);
1281 pi2_event_loop->SkipTimingReport();
1282
1283 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1284 "/aos");
1285 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1286 full_pi1_event_loop.get(), "/pi1/aos");
1287 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1288 pi1_event_loop.get(), "/original/aos");
1289 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1290 full_pi1_event_loop.get(), "/original/pi1/aos");
1291 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1292 "/aos");
1293
1294 log_reader_factory.Run();
1295
1296 EXPECT_EQ(pi1_timing_report.count(), 0u);
1297 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1298 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1299 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1300 EXPECT_NE(pi2_timing_report.count(), 0u);
1301
1302 reader.Deregister();
1303}
1304
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001305// Tests that if we rename a logged channel, it shows up correctly.
1306TEST_P(MultinodeLoggerTest, RenameLoggedChannel) {
1307 std::vector<std::string> actual_filenames;
1308 time_converter_.StartEqual();
1309 {
1310 LoggerState pi1_logger = MakeLogger(pi1_);
1311 LoggerState pi2_logger = MakeLogger(pi2_);
1312
1313 event_loop_factory_.RunFor(chrono::milliseconds(95));
1314
1315 StartLogger(&pi1_logger);
1316 StartLogger(&pi2_logger);
1317
1318 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1319
1320 pi1_logger.AppendAllFilenames(&actual_filenames);
1321 pi2_logger.AppendAllFilenames(&actual_filenames);
1322 }
1323
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001324 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1325 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1326 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001327
1328 // Rename just on pi2. Add some global maps just to verify they get added in
1329 // the config and used correctly.
1330 std::vector<MapT> maps;
1331 {
1332 MapT map;
1333 map.match = std::make_unique<ChannelT>();
1334 map.match->name = "/foo*";
1335 map.match->source_node = "pi1";
1336 map.rename = std::make_unique<ChannelT>();
1337 map.rename->name = "/pi1/foo";
1338 maps.emplace_back(std::move(map));
1339 }
1340 {
1341 MapT map;
1342 map.match = std::make_unique<ChannelT>();
1343 map.match->name = "/foo*";
1344 map.match->source_node = "pi2";
1345 map.rename = std::make_unique<ChannelT>();
1346 map.rename->name = "/pi2/foo";
1347 maps.emplace_back(std::move(map));
1348 }
1349 {
1350 MapT map;
1351 map.match = std::make_unique<ChannelT>();
1352 map.match->name = "/foo";
1353 map.match->type = "aos.examples.Ping";
1354 map.rename = std::make_unique<ChannelT>();
1355 map.rename->name = "/foo/renamed";
1356 maps.emplace_back(std::move(map));
1357 }
1358 reader.RenameLoggedChannel<aos::examples::Ping>(
1359 "/aos", configuration::GetNode(reader.configuration(), "pi2"),
1360 "/pi2/foo/renamed", maps);
1361
1362 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1363 log_reader_factory.set_send_delay(chrono::microseconds(0));
1364
1365 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1366 // Note: An extra channel gets remapped automatically due to a timestamp
1367 // channel being LOCAL_LOGGER'd.
1368 const bool shared = std::get<0>(GetParam()).shared;
1369 ASSERT_EQ(remapped_channels.size(), shared ? 1u : 2u);
1370 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->name()->string_view(),
1371 "/pi2/foo/renamed");
1372 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->type()->string_view(),
1373 "aos.examples.Ping");
1374 if (!shared) {
1375 EXPECT_EQ(remapped_channels[0]->name()->string_view(),
1376 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1377 "aos-message_bridge-Timestamp");
1378 EXPECT_EQ(remapped_channels[0]->type()->string_view(),
1379 "aos.message_bridge.RemoteMessage");
1380 }
1381
1382 reader.Register(&log_reader_factory);
1383
1384 const Node *pi1 =
1385 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1386 const Node *pi2 =
1387 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1388
1389 // Confirm we can read the data on the renamed channel, just for pi2. Nothing
1390 // else should have moved.
1391 std::unique_ptr<EventLoop> pi2_event_loop =
1392 log_reader_factory.MakeEventLoop("test", pi2);
1393 pi2_event_loop->SkipTimingReport();
1394 std::unique_ptr<EventLoop> full_pi2_event_loop =
1395 log_reader_factory.MakeEventLoop("test", pi2);
1396 full_pi2_event_loop->SkipTimingReport();
1397 std::unique_ptr<EventLoop> pi1_event_loop =
1398 log_reader_factory.MakeEventLoop("test", pi1);
1399 pi1_event_loop->SkipTimingReport();
1400
1401 MessageCounter<aos::examples::Ping> pi2_ping(pi2_event_loop.get(), "/aos");
1402 MessageCounter<aos::examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1403 "/foo");
1404 MessageCounter<aos::examples::Ping> full_pi2_renamed_ping(
1405 full_pi2_event_loop.get(), "/pi2/foo/renamed");
1406 MessageCounter<aos::examples::Ping> pi1_ping(pi1_event_loop.get(), "/aos");
1407
1408 log_reader_factory.Run();
1409
1410 EXPECT_EQ(pi2_ping.count(), 0u);
1411 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1412 EXPECT_NE(full_pi2_renamed_ping.count(), 0u);
1413 EXPECT_NE(pi1_ping.count(), 0u);
1414
1415 reader.Deregister();
1416}
1417
Naman Guptaa63aa132023-03-22 20:06:34 -07001418// Tests that we can remap a forwarded channel as well.
1419TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1420 time_converter_.StartEqual();
1421 {
1422 LoggerState pi1_logger = MakeLogger(pi1_);
1423 LoggerState pi2_logger = MakeLogger(pi2_);
1424
1425 event_loop_factory_.RunFor(chrono::milliseconds(95));
1426
1427 StartLogger(&pi1_logger);
1428 StartLogger(&pi2_logger);
1429
1430 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1431 }
1432
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001433 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1434 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1435 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001436
1437 reader.RemapLoggedChannel<examples::Ping>("/test");
1438
1439 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1440 log_reader_factory.set_send_delay(chrono::microseconds(0));
1441
1442 reader.Register(&log_reader_factory);
1443
1444 const Node *pi1 =
1445 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1446 const Node *pi2 =
1447 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1448
1449 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1450 // else should have moved.
1451 std::unique_ptr<EventLoop> pi1_event_loop =
1452 log_reader_factory.MakeEventLoop("test", pi1);
1453 pi1_event_loop->SkipTimingReport();
1454 std::unique_ptr<EventLoop> full_pi1_event_loop =
1455 log_reader_factory.MakeEventLoop("test", pi1);
1456 full_pi1_event_loop->SkipTimingReport();
1457 std::unique_ptr<EventLoop> pi2_event_loop =
1458 log_reader_factory.MakeEventLoop("test", pi2);
1459 pi2_event_loop->SkipTimingReport();
1460
1461 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1462 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1463 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1464 "/original/test");
1465 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1466 "/original/test");
1467
1468 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1469 pi1_original_ping_timestamp;
1470 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1471 pi1_ping_timestamp;
1472 if (!shared()) {
1473 pi1_original_ping_timestamp =
1474 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1475 pi1_event_loop.get(),
1476 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1477 pi1_ping_timestamp =
1478 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1479 pi1_event_loop.get(),
1480 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1481 }
1482
1483 log_reader_factory.Run();
1484
1485 EXPECT_EQ(pi1_ping.count(), 0u);
1486 EXPECT_EQ(pi2_ping.count(), 0u);
1487 EXPECT_NE(pi1_original_ping.count(), 0u);
1488 EXPECT_NE(pi2_original_ping.count(), 0u);
1489 if (!shared()) {
1490 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1491 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1492 }
1493
1494 reader.Deregister();
1495}
1496
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001497// Tests that we can rename a forwarded channel as well.
1498TEST_P(MultinodeLoggerTest, RenameForwardedLoggedChannel) {
1499 std::vector<std::string> actual_filenames;
1500 time_converter_.StartEqual();
1501 {
1502 LoggerState pi1_logger = MakeLogger(pi1_);
1503 LoggerState pi2_logger = MakeLogger(pi2_);
1504
1505 event_loop_factory_.RunFor(chrono::milliseconds(95));
1506
1507 StartLogger(&pi1_logger);
1508 StartLogger(&pi2_logger);
1509
1510 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1511
1512 pi1_logger.AppendAllFilenames(&actual_filenames);
1513 pi2_logger.AppendAllFilenames(&actual_filenames);
1514 }
1515
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001516 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1517 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1518 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001519
1520 std::vector<MapT> maps;
1521 {
1522 MapT map;
1523 map.match = std::make_unique<ChannelT>();
1524 map.match->name = "/production*";
1525 map.match->source_node = "pi1";
1526 map.rename = std::make_unique<ChannelT>();
1527 map.rename->name = "/pi1/production";
1528 maps.emplace_back(std::move(map));
1529 }
1530 {
1531 MapT map;
1532 map.match = std::make_unique<ChannelT>();
1533 map.match->name = "/production*";
1534 map.match->source_node = "pi2";
1535 map.rename = std::make_unique<ChannelT>();
1536 map.rename->name = "/pi2/production";
1537 maps.emplace_back(std::move(map));
1538 }
1539 reader.RenameLoggedChannel<aos::examples::Ping>(
1540 "/test", configuration::GetNode(reader.configuration(), "pi1"),
1541 "/pi1/production", maps);
1542
1543 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1544 log_reader_factory.set_send_delay(chrono::microseconds(0));
1545
1546 reader.Register(&log_reader_factory);
1547
1548 const Node *pi1 =
1549 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1550 const Node *pi2 =
1551 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1552
1553 // Confirm we can read the data on the renamed channel, on both the source
1554 // node and the remote node. In case of split timestamp channels, confirm that
1555 // we receive the timestamp messages on the renamed channel as well.
1556 std::unique_ptr<EventLoop> pi1_event_loop =
1557 log_reader_factory.MakeEventLoop("test", pi1);
1558 pi1_event_loop->SkipTimingReport();
1559 std::unique_ptr<EventLoop> full_pi1_event_loop =
1560 log_reader_factory.MakeEventLoop("test", pi1);
1561 full_pi1_event_loop->SkipTimingReport();
1562 std::unique_ptr<EventLoop> pi2_event_loop =
1563 log_reader_factory.MakeEventLoop("test", pi2);
1564 pi2_event_loop->SkipTimingReport();
1565
1566 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1567 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1568 MessageCounter<examples::Ping> pi1_renamed_ping(pi1_event_loop.get(),
1569 "/pi1/production");
1570 MessageCounter<examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1571 "/pi1/production");
1572
1573 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1574 pi1_renamed_ping_timestamp;
1575 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1576 pi1_ping_timestamp;
1577 if (!shared()) {
1578 pi1_renamed_ping_timestamp =
1579 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1580 pi1_event_loop.get(),
1581 "/pi1/aos/remote_timestamps/pi2/pi1/production/aos-examples-Ping");
1582 pi1_ping_timestamp =
1583 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1584 pi1_event_loop.get(),
1585 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1586 }
1587
1588 log_reader_factory.Run();
1589
1590 EXPECT_EQ(pi1_ping.count(), 0u);
1591 EXPECT_EQ(pi2_ping.count(), 0u);
1592 EXPECT_NE(pi1_renamed_ping.count(), 0u);
1593 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1594 if (!shared()) {
1595 EXPECT_NE(pi1_renamed_ping_timestamp->count(), 0u);
1596 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1597 }
1598
1599 reader.Deregister();
1600}
1601
Naman Guptaa63aa132023-03-22 20:06:34 -07001602// Tests that we observe all the same events in log replay (for a given node)
1603// whether we just register an event loop for that node or if we register a full
1604// event loop factory.
1605TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
1606 time_converter_.StartEqual();
1607 constexpr chrono::milliseconds kStartupDelay(95);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001608 std::vector<std::string> filenames;
1609
Naman Guptaa63aa132023-03-22 20:06:34 -07001610 {
1611 LoggerState pi1_logger = MakeLogger(pi1_);
1612 LoggerState pi2_logger = MakeLogger(pi2_);
1613
1614 event_loop_factory_.RunFor(kStartupDelay);
1615
1616 StartLogger(&pi1_logger);
1617 StartLogger(&pi2_logger);
1618
1619 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001620
1621 pi1_logger.AppendAllFilenames(&filenames);
1622 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001623 }
1624
Austin Schuh8fb4b452023-08-04 17:02:27 -07001625 LogReader full_reader(SortParts(filenames));
1626 LogReader single_node_reader(SortParts(filenames));
Naman Guptaa63aa132023-03-22 20:06:34 -07001627
1628 SimulatedEventLoopFactory full_factory(full_reader.configuration());
1629 SimulatedEventLoopFactory single_node_factory(
1630 single_node_reader.configuration());
1631 single_node_factory.SkipTimingReport();
1632 single_node_factory.DisableStatistics();
1633 std::unique_ptr<EventLoop> replay_event_loop =
1634 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
1635 "log_reader");
1636
1637 full_reader.Register(&full_factory);
1638 single_node_reader.Register(replay_event_loop.get());
1639
1640 const Node *full_pi1 =
1641 configuration::GetNode(full_factory.configuration(), "pi1");
1642
1643 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1644 // else should have moved.
1645 std::unique_ptr<EventLoop> full_event_loop =
1646 full_factory.MakeEventLoop("test", full_pi1);
1647 full_event_loop->SkipTimingReport();
1648 full_event_loop->SkipAosLog();
1649 // maps are indexed on channel index.
1650 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
1651 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
1652 observed_messages;
1653 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
1654 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
1655 ++ii) {
1656 const Channel *channel =
1657 full_event_loop->configuration()->channels()->Get(ii);
1658 // We currently don't support replaying remote timestamp channels in
1659 // realtime replay (unless the remote timestamp channel was not NOT_LOGGED,
1660 // in which case it gets auto-remapped and replayed on a /original channel).
1661 if (channel->name()->string_view().find("remote_timestamp") !=
1662 std::string_view::npos &&
1663 channel->name()->string_view().find("/original") ==
1664 std::string_view::npos) {
1665 continue;
1666 }
1667 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
1668 observed_messages[ii] = {};
1669 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
1670 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
1671 if (fetchers[ii]->Fetch()) {
1672 observed_messages[ii].push_back(std::make_pair(
1673 fetchers[ii]->context().monotonic_event_time, true));
1674 }
1675 });
1676 full_event_loop->MakeRawNoArgWatcher(
1677 channel, [ii, &observed_messages](const Context &context) {
1678 observed_messages[ii].push_back(
1679 std::make_pair(context.monotonic_event_time, false));
1680 });
1681 }
1682 }
1683
1684 full_factory.Run();
1685 fetchers.clear();
1686 full_reader.Deregister();
1687
1688 const Node *single_node_pi1 =
1689 configuration::GetNode(single_node_factory.configuration(), "pi1");
1690 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
1691
1692 std::unique_ptr<EventLoop> single_node_event_loop =
1693 single_node_factory.MakeEventLoop("test", single_node_pi1);
1694 single_node_event_loop->SkipTimingReport();
1695 single_node_event_loop->SkipAosLog();
1696 for (size_t ii = 0;
1697 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
1698 const Channel *channel =
1699 single_node_event_loop->configuration()->channels()->Get(ii);
1700 single_node_factory.DisableForwarding(channel);
1701 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
1702 single_node_fetchers[ii] =
1703 single_node_event_loop->MakeRawFetcher(channel);
1704 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
1705 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
1706 << "Single EventLoop replay doesn't support pre-loading fetchers. "
1707 << configuration::StrippedChannelToString(channel);
1708 });
1709 single_node_event_loop->MakeRawNoArgWatcher(
1710 channel, [ii, &observed_messages, channel,
1711 kStartupDelay](const Context &context) {
1712 if (observed_messages[ii].empty()) {
1713 FAIL() << "Observed extra message at "
1714 << context.monotonic_event_time << " on "
1715 << configuration::StrippedChannelToString(channel);
1716 return;
1717 }
1718 const std::pair<monotonic_clock::time_point, bool> &message =
1719 observed_messages[ii].front();
1720 if (message.second) {
1721 EXPECT_LE(message.first,
1722 context.monotonic_event_time + kStartupDelay)
1723 << "Mismatched message times " << context.monotonic_event_time
1724 << " and " << message.first << " on "
1725 << configuration::StrippedChannelToString(channel);
1726 } else {
1727 EXPECT_EQ(message.first,
1728 context.monotonic_event_time + kStartupDelay)
1729 << "Mismatched message times " << context.monotonic_event_time
1730 << " and " << message.first << " on "
1731 << configuration::StrippedChannelToString(channel);
1732 }
1733 observed_messages[ii].erase(observed_messages[ii].begin());
1734 });
1735 }
1736 }
1737
1738 single_node_factory.Run();
1739
1740 single_node_fetchers.clear();
1741
1742 single_node_reader.Deregister();
1743
1744 for (const auto &pair : observed_messages) {
1745 EXPECT_TRUE(pair.second.empty())
1746 << "Missed " << pair.second.size() << " messages on "
1747 << configuration::StrippedChannelToString(
1748 single_node_event_loop->configuration()->channels()->Get(
1749 pair.first));
1750 }
1751}
1752
1753// Tests that we properly recreate forwarded timestamps when replaying a log.
1754// This should be enough that we can then re-run the logger and get a valid log
1755// back.
1756TEST_P(MultinodeLoggerTest, MessageHeader) {
1757 time_converter_.StartEqual();
1758 {
1759 LoggerState pi1_logger = MakeLogger(pi1_);
1760 LoggerState pi2_logger = MakeLogger(pi2_);
1761
1762 event_loop_factory_.RunFor(chrono::milliseconds(95));
1763
1764 StartLogger(&pi1_logger);
1765 StartLogger(&pi2_logger);
1766
1767 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1768 }
1769
1770 LogReader reader(SortParts(logfiles_));
1771
1772 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1773 log_reader_factory.set_send_delay(chrono::microseconds(0));
1774
1775 // This sends out the fetched messages and advances time to the start of the
1776 // log file.
1777 reader.Register(&log_reader_factory);
1778
1779 const Node *pi1 =
1780 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1781 const Node *pi2 =
1782 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1783
1784 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1785 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1786 LOG(INFO) << "now pi1 "
1787 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1788 LOG(INFO) << "now pi2 "
1789 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1790
1791 EXPECT_THAT(reader.LoggedNodes(),
1792 ::testing::ElementsAre(
1793 configuration::GetNode(reader.logged_configuration(), pi1),
1794 configuration::GetNode(reader.logged_configuration(), pi2)));
1795
1796 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1797
1798 std::unique_ptr<EventLoop> pi1_event_loop =
1799 log_reader_factory.MakeEventLoop("test", pi1);
1800 std::unique_ptr<EventLoop> pi2_event_loop =
1801 log_reader_factory.MakeEventLoop("test", pi2);
1802
1803 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1804 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1805 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1806 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1807
1808 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1809 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1810 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1811 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1812
1813 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1814 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1815 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1816 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1817
1818 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1819 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1820 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1821 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1822
1823 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1824 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1825 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1826 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1827
1828 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1829 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1830 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1831 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1832
1833 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
1834 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
1835
1836 for (std::pair<int, std::string> channel :
1837 shared()
1838 ? std::vector<
1839 std::pair<int, std::string>>{{-1,
1840 "/aos/remote_timestamps/pi2"}}
1841 : std::vector<std::pair<int, std::string>>{
1842 {pi1_timestamp_channel,
1843 "/aos/remote_timestamps/pi2/pi1/aos/"
1844 "aos-message_bridge-Timestamp"},
1845 {ping_timestamp_channel,
1846 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1847 pi1_event_loop->MakeWatcher(
1848 channel.second,
1849 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1850 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1851 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1852 &ping_on_pi2_fetcher, network_delay, send_delay,
1853 channel_index = channel.first](const RemoteMessage &header) {
1854 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1855 chrono::nanoseconds(header.monotonic_sent_time()));
1856 const aos::realtime_clock::time_point header_realtime_sent_time(
1857 chrono::nanoseconds(header.realtime_sent_time()));
1858 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1859 chrono::nanoseconds(header.monotonic_remote_time()));
1860 const aos::realtime_clock::time_point header_realtime_remote_time(
1861 chrono::nanoseconds(header.realtime_remote_time()));
1862
1863 if (channel_index != -1) {
1864 ASSERT_EQ(channel_index, header.channel_index());
1865 }
1866
1867 const Context *pi1_context = nullptr;
1868 const Context *pi2_context = nullptr;
1869
1870 if (header.channel_index() == pi1_timestamp_channel) {
1871 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1872 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1873 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1874 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1875 } else if (header.channel_index() == ping_timestamp_channel) {
1876 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1877 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1878 pi1_context = &ping_on_pi1_fetcher.context();
1879 pi2_context = &ping_on_pi2_fetcher.context();
1880 } else {
1881 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1882 << configuration::CleanedChannelToString(
1883 pi1_event_loop->configuration()->channels()->Get(
1884 header.channel_index()));
1885 }
1886
1887 ASSERT_TRUE(header.has_boot_uuid());
1888 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1889 pi2_event_loop->boot_uuid());
1890
1891 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1892 EXPECT_EQ(pi2_context->remote_queue_index,
1893 header.remote_queue_index());
1894 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
1895
1896 EXPECT_EQ(pi2_context->monotonic_event_time,
1897 header_monotonic_sent_time);
1898 EXPECT_EQ(pi2_context->realtime_event_time,
1899 header_realtime_sent_time);
1900 EXPECT_EQ(pi2_context->realtime_remote_time,
1901 header_realtime_remote_time);
1902 EXPECT_EQ(pi2_context->monotonic_remote_time,
1903 header_monotonic_remote_time);
1904
1905 EXPECT_EQ(pi1_context->realtime_event_time,
1906 header_realtime_remote_time);
1907 EXPECT_EQ(pi1_context->monotonic_event_time,
1908 header_monotonic_remote_time);
1909
1910 // Time estimation isn't perfect, but we know the clocks were
1911 // identical when logged, so we know when this should have come back.
1912 // Confirm we got it when we expected.
1913 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
1914 pi1_context->monotonic_event_time + 2 * network_delay +
1915 send_delay);
1916 });
1917 }
1918 for (std::pair<int, std::string> channel :
1919 shared()
1920 ? std::vector<
1921 std::pair<int, std::string>>{{-1,
1922 "/aos/remote_timestamps/pi1"}}
1923 : std::vector<std::pair<int, std::string>>{
1924 {pi2_timestamp_channel,
1925 "/aos/remote_timestamps/pi1/pi2/aos/"
1926 "aos-message_bridge-Timestamp"}}) {
1927 pi2_event_loop->MakeWatcher(
1928 channel.second,
1929 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
1930 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
1931 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
1932 &pong_on_pi1_fetcher, network_delay, send_delay,
1933 channel_index = channel.first](const RemoteMessage &header) {
1934 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1935 chrono::nanoseconds(header.monotonic_sent_time()));
1936 const aos::realtime_clock::time_point header_realtime_sent_time(
1937 chrono::nanoseconds(header.realtime_sent_time()));
1938 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1939 chrono::nanoseconds(header.monotonic_remote_time()));
1940 const aos::realtime_clock::time_point header_realtime_remote_time(
1941 chrono::nanoseconds(header.realtime_remote_time()));
1942
1943 if (channel_index != -1) {
1944 ASSERT_EQ(channel_index, header.channel_index());
1945 }
1946
1947 const Context *pi2_context = nullptr;
1948 const Context *pi1_context = nullptr;
1949
1950 if (header.channel_index() == pi2_timestamp_channel) {
1951 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
1952 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
1953 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
1954 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
1955 } else if (header.channel_index() == pong_timestamp_channel) {
1956 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
1957 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
1958 pi2_context = &pong_on_pi2_fetcher.context();
1959 pi1_context = &pong_on_pi1_fetcher.context();
1960 } else {
1961 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1962 << configuration::CleanedChannelToString(
1963 pi2_event_loop->configuration()->channels()->Get(
1964 header.channel_index()));
1965 }
1966
1967 ASSERT_TRUE(header.has_boot_uuid());
1968 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1969 pi1_event_loop->boot_uuid());
1970
1971 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
1972 EXPECT_EQ(pi1_context->remote_queue_index,
1973 header.remote_queue_index());
1974 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
1975
1976 EXPECT_EQ(pi1_context->monotonic_event_time,
1977 header_monotonic_sent_time);
1978 EXPECT_EQ(pi1_context->realtime_event_time,
1979 header_realtime_sent_time);
1980 EXPECT_EQ(pi1_context->realtime_remote_time,
1981 header_realtime_remote_time);
1982 EXPECT_EQ(pi1_context->monotonic_remote_time,
1983 header_monotonic_remote_time);
1984
1985 EXPECT_EQ(pi2_context->realtime_event_time,
1986 header_realtime_remote_time);
1987 EXPECT_EQ(pi2_context->monotonic_event_time,
1988 header_monotonic_remote_time);
1989
1990 // Time estimation isn't perfect, but we know the clocks were
1991 // identical when logged, so we know when this should have come back.
1992 // Confirm we got it when we expected.
1993 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
1994 pi2_context->monotonic_event_time + 2 * network_delay +
1995 send_delay);
1996 });
1997 }
1998
1999 // And confirm we can re-create a log again, while checking the contents.
2000 {
2001 LoggerState pi1_logger = MakeLogger(
2002 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
2003 LoggerState pi2_logger = MakeLogger(
2004 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
2005
Austin Schuh8fb4b452023-08-04 17:02:27 -07002006 StartLogger(&pi1_logger, tmp_dir_ + "/logs/relogged1");
2007 StartLogger(&pi2_logger, tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07002008
2009 log_reader_factory.Run();
2010 }
2011
2012 reader.Deregister();
2013
2014 // And verify that we can run the LogReader over the relogged files without
2015 // hitting any fatal errors.
2016 {
Austin Schuh8fb4b452023-08-04 17:02:27 -07002017 LogReader relogged_reader(SortParts(
2018 MakeLogFiles(tmp_dir_ + "/logs/relogged1", tmp_dir_ + "/logs/relogged2",
2019 1, 1, 2, 2, true)));
Naman Guptaa63aa132023-03-22 20:06:34 -07002020 relogged_reader.Register();
2021
2022 relogged_reader.event_loop_factory()->Run();
2023 }
2024 // And confirm that we can read the logged file using the reader's
2025 // configuration.
2026 {
2027 LogReader relogged_reader(
Austin Schuh8fb4b452023-08-04 17:02:27 -07002028 SortParts(MakeLogFiles(tmp_dir_ + "/logs/relogged1",
2029 tmp_dir_ + "/logs/relogged2", 1, 1, 2, 2, true)),
Naman Guptaa63aa132023-03-22 20:06:34 -07002030 reader.configuration());
2031 relogged_reader.Register();
2032
2033 relogged_reader.event_loop_factory()->Run();
2034 }
2035}
2036
2037// Tests that we properly populate and extract the logger_start time by setting
2038// up a clock difference between 2 nodes and looking at the resulting parts.
2039TEST_P(MultinodeLoggerTest, LoggerStartTime) {
2040 std::vector<std::string> actual_filenames;
2041 time_converter_.AddMonotonic(
2042 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2043 {
2044 LoggerState pi1_logger = MakeLogger(pi1_);
2045 LoggerState pi2_logger = MakeLogger(pi2_);
2046
2047 StartLogger(&pi1_logger);
2048 StartLogger(&pi2_logger);
2049
2050 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2051
2052 pi1_logger.AppendAllFilenames(&actual_filenames);
2053 pi2_logger.AppendAllFilenames(&actual_filenames);
2054 }
2055
2056 ASSERT_THAT(actual_filenames,
2057 ::testing::UnorderedElementsAreArray(logfiles_));
2058
Austin Schuh8fb4b452023-08-04 17:02:27 -07002059 for (const LogFile &log_file : SortParts(actual_filenames)) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002060 for (const LogParts &log_part : log_file.parts) {
2061 if (log_part.node == log_file.logger_node) {
2062 EXPECT_EQ(log_part.logger_monotonic_start_time,
2063 aos::monotonic_clock::min_time);
2064 EXPECT_EQ(log_part.logger_realtime_start_time,
2065 aos::realtime_clock::min_time);
2066 } else {
2067 const chrono::seconds offset = log_file.logger_node == "pi1"
2068 ? -chrono::seconds(1000)
2069 : chrono::seconds(1000);
2070 EXPECT_EQ(log_part.logger_monotonic_start_time,
2071 log_part.monotonic_start_time + offset);
2072 EXPECT_EQ(log_part.logger_realtime_start_time,
2073 log_file.realtime_start_time +
2074 (log_part.logger_monotonic_start_time -
2075 log_file.monotonic_start_time));
2076 }
2077 }
2078 }
2079}
2080
2081// Test that renaming the base, renames the folder.
2082TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002083 time_converter_.AddMonotonic(
2084 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002085 logfile_base1_ = tmp_dir_ + "/logs/renamefolder/multi_logfile1";
2086 logfile_base2_ = tmp_dir_ + "/logs/renamefolder/multi_logfile2";
2087
Naman Guptaa63aa132023-03-22 20:06:34 -07002088 LoggerState pi1_logger = MakeLogger(pi1_);
2089 LoggerState pi2_logger = MakeLogger(pi2_);
2090
2091 StartLogger(&pi1_logger);
2092 StartLogger(&pi2_logger);
2093
2094 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002095 logfile_base1_ = tmp_dir_ + "/logs/new-good/multi_logfile1";
2096 logfile_base2_ = tmp_dir_ + "/logs/new-good/multi_logfile2";
Naman Guptaa63aa132023-03-22 20:06:34 -07002097 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
Alexei Strotscaf17d32023-04-03 22:31:11 -07002098
2099 // Sequence of set_base_name and Rotate simulates rename operation. Since
2100 // rename is not supported by all namers, RenameLogBase moved from logger to
2101 // the higher level abstraction, yet log_namers support rename, and it is
2102 // legal to test it here.
2103 pi1_logger.log_namer->set_base_name(logfile_base1_);
2104 pi1_logger.logger->Rotate();
2105 pi2_logger.log_namer->set_base_name(logfile_base2_);
2106 pi2_logger.logger->Rotate();
2107
Naman Guptaa63aa132023-03-22 20:06:34 -07002108 for (auto &file : logfiles_) {
2109 struct stat s;
2110 EXPECT_EQ(0, stat(file.c_str(), &s));
2111 }
2112}
2113
2114// Test that renaming the file base dies.
2115TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2116 time_converter_.AddMonotonic(
2117 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002118 logfile_base1_ = tmp_dir_ + "/logs/renamefile/multi_logfile1";
2119 logfile_base2_ = tmp_dir_ + "/logs/renamefile/multi_logfile2";
2120
Naman Guptaa63aa132023-03-22 20:06:34 -07002121 LoggerState pi1_logger = MakeLogger(pi1_);
2122 StartLogger(&pi1_logger);
2123 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002124 logfile_base1_ = tmp_dir_ + "/logs/new-renamefile/new_multi_logfile1";
Alexei Strotscaf17d32023-04-03 22:31:11 -07002125 EXPECT_DEATH({ pi1_logger.log_namer->set_base_name(logfile_base1_); },
Naman Guptaa63aa132023-03-22 20:06:34 -07002126 "Rename of file base from");
2127}
2128
2129// TODO(austin): We can write a test which recreates a logfile and confirms that
2130// we get it back. That is the ultimate test.
2131
2132// Tests that we properly recreate forwarded timestamps when replaying a log.
2133// This should be enough that we can then re-run the logger and get a valid log
2134// back.
2135TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002136 if (file_strategy() == FileStrategy::kCombine) {
2137 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2138 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002139 std::vector<std::string> actual_filenames;
2140
2141 const UUID pi1_boot0 = UUID::Random();
2142 const UUID pi2_boot0 = UUID::Random();
2143 const UUID pi2_boot1 = UUID::Random();
2144 {
2145 CHECK_EQ(pi1_index_, 0u);
2146 CHECK_EQ(pi2_index_, 1u);
2147
2148 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2149 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2150 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2151
2152 time_converter_.AddNextTimestamp(
2153 distributed_clock::epoch(),
2154 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2155 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2156 time_converter_.AddNextTimestamp(
2157 distributed_clock::epoch() + reboot_time,
2158 {BootTimestamp::epoch() + reboot_time,
2159 BootTimestamp{
2160 .boot = 1,
2161 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2162 }
2163
2164 {
2165 LoggerState pi1_logger = MakeLogger(pi1_);
2166
2167 event_loop_factory_.RunFor(chrono::milliseconds(95));
2168 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2169 pi1_boot0);
2170 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2171 pi2_boot0);
2172
2173 StartLogger(&pi1_logger);
2174
2175 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2176
2177 VLOG(1) << "Reboot now!";
2178
2179 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2180 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2181 pi1_boot0);
2182 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2183 pi2_boot1);
2184
2185 pi1_logger.AppendAllFilenames(&actual_filenames);
2186 }
2187
2188 std::sort(actual_filenames.begin(), actual_filenames.end());
2189 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2190 ASSERT_THAT(actual_filenames,
2191 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2192
2193 // Confirm that our new oldest timestamps properly update as we reboot and
2194 // rotate.
2195 for (const std::string &file : pi1_reboot_logfiles_) {
2196 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2197 ReadHeader(file);
2198 CHECK(log_header);
2199 if (log_header->message().has_configuration()) {
2200 continue;
2201 }
2202
2203 const monotonic_clock::time_point monotonic_start_time =
2204 monotonic_clock::time_point(
2205 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2206 const UUID source_node_boot_uuid = UUID::FromString(
2207 log_header->message().source_node_boot_uuid()->string_view());
2208
2209 if (log_header->message().node()->name()->string_view() != "pi1") {
2210 // The remote message channel should rotate later and have more parts.
2211 // This only is true on the log files with shared remote messages.
2212 //
2213 // TODO(austin): I'm not the most thrilled with this test pattern... It
2214 // feels brittle in a different way.
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002215 if (file.find("timestamps/remote_pi2") == std::string::npos) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002216 switch (log_header->message().parts_index()) {
2217 case 0:
2218 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2219 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2220 break;
2221 case 1:
2222 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2223 ASSERT_EQ(monotonic_start_time,
2224 monotonic_clock::epoch() + chrono::seconds(1));
2225 break;
2226 case 2:
2227 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2228 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2229 break;
2230 case 3:
2231 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2232 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2233 chrono::nanoseconds(2322999462))
2234 << " on " << file;
2235 break;
2236 default:
2237 FAIL();
2238 break;
2239 }
2240 } else {
2241 switch (log_header->message().parts_index()) {
2242 case 0:
2243 case 1:
2244 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2245 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2246 break;
2247 case 2:
2248 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2249 ASSERT_EQ(monotonic_start_time,
2250 monotonic_clock::epoch() + chrono::seconds(1));
2251 break;
2252 case 3:
2253 case 4:
2254 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2255 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2256 break;
2257 case 5:
2258 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2259 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2260 chrono::nanoseconds(2322999462))
2261 << " on " << file;
2262 break;
2263 default:
2264 FAIL();
2265 break;
2266 }
2267 }
2268 continue;
2269 }
2270 SCOPED_TRACE(file);
2271 SCOPED_TRACE(aos::FlatbufferToJson(
2272 *log_header, {.multi_line = true, .max_vector_size = 100}));
2273 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2274 ASSERT_EQ(
2275 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2276 EXPECT_EQ(
2277 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2278 monotonic_clock::max_time.time_since_epoch().count());
2279 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2280 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2281 2u);
2282 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2283 monotonic_clock::max_time.time_since_epoch().count());
2284 ASSERT_TRUE(log_header->message()
2285 .has_oldest_remote_unreliable_monotonic_timestamps());
2286 ASSERT_EQ(log_header->message()
2287 .oldest_remote_unreliable_monotonic_timestamps()
2288 ->size(),
2289 2u);
2290 EXPECT_EQ(log_header->message()
2291 .oldest_remote_unreliable_monotonic_timestamps()
2292 ->Get(0),
2293 monotonic_clock::max_time.time_since_epoch().count());
2294 ASSERT_TRUE(log_header->message()
2295 .has_oldest_local_unreliable_monotonic_timestamps());
2296 ASSERT_EQ(log_header->message()
2297 .oldest_local_unreliable_monotonic_timestamps()
2298 ->size(),
2299 2u);
2300 EXPECT_EQ(log_header->message()
2301 .oldest_local_unreliable_monotonic_timestamps()
2302 ->Get(0),
2303 monotonic_clock::max_time.time_since_epoch().count());
2304
2305 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2306 monotonic_clock::time_point(chrono::nanoseconds(
2307 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2308 1)));
2309 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2310 monotonic_clock::time_point(chrono::nanoseconds(
2311 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2312 const monotonic_clock::time_point
2313 oldest_remote_unreliable_monotonic_timestamps =
2314 monotonic_clock::time_point(chrono::nanoseconds(
2315 log_header->message()
2316 .oldest_remote_unreliable_monotonic_timestamps()
2317 ->Get(1)));
2318 const monotonic_clock::time_point
2319 oldest_local_unreliable_monotonic_timestamps =
2320 monotonic_clock::time_point(chrono::nanoseconds(
2321 log_header->message()
2322 .oldest_local_unreliable_monotonic_timestamps()
2323 ->Get(1)));
2324 const monotonic_clock::time_point
2325 oldest_remote_reliable_monotonic_timestamps =
2326 monotonic_clock::time_point(chrono::nanoseconds(
2327 log_header->message()
2328 .oldest_remote_reliable_monotonic_timestamps()
2329 ->Get(1)));
2330 const monotonic_clock::time_point
2331 oldest_local_reliable_monotonic_timestamps =
2332 monotonic_clock::time_point(chrono::nanoseconds(
2333 log_header->message()
2334 .oldest_local_reliable_monotonic_timestamps()
2335 ->Get(1)));
2336 const monotonic_clock::time_point
2337 oldest_logger_remote_unreliable_monotonic_timestamps =
2338 monotonic_clock::time_point(chrono::nanoseconds(
2339 log_header->message()
2340 .oldest_logger_remote_unreliable_monotonic_timestamps()
2341 ->Get(0)));
2342 const monotonic_clock::time_point
2343 oldest_logger_local_unreliable_monotonic_timestamps =
2344 monotonic_clock::time_point(chrono::nanoseconds(
2345 log_header->message()
2346 .oldest_logger_local_unreliable_monotonic_timestamps()
2347 ->Get(0)));
2348 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2349 monotonic_clock::max_time);
2350 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2351 monotonic_clock::max_time);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002352 if (log_header->message().data_stored()->Get(0) == StoredDataType::DATA) {
2353 switch (log_header->message().parts_index()) {
2354 case 0:
2355 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2356 monotonic_clock::max_time);
2357 EXPECT_EQ(oldest_local_monotonic_timestamps,
2358 monotonic_clock::max_time);
2359 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2360 monotonic_clock::max_time);
2361 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2362 monotonic_clock::max_time);
2363 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2364 monotonic_clock::max_time);
2365 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2366 monotonic_clock::max_time);
2367 break;
2368 default:
2369 FAIL();
2370 break;
2371 }
2372 } else if (log_header->message().data_stored()->Get(0) ==
2373 StoredDataType::TIMESTAMPS) {
2374 switch (log_header->message().parts_index()) {
2375 case 0:
2376 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2377 monotonic_clock::time_point(chrono::microseconds(90200)));
2378 EXPECT_EQ(oldest_local_monotonic_timestamps,
2379 monotonic_clock::time_point(chrono::microseconds(90350)));
2380 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2381 monotonic_clock::time_point(chrono::microseconds(90200)));
2382 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2383 monotonic_clock::time_point(chrono::microseconds(90350)));
2384 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2385 monotonic_clock::max_time);
2386 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2387 monotonic_clock::max_time);
2388 break;
2389 case 1:
2390 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2391 monotonic_clock::time_point(chrono::microseconds(90200)))
2392 << file;
2393 EXPECT_EQ(oldest_local_monotonic_timestamps,
2394 monotonic_clock::time_point(chrono::microseconds(90350)))
2395 << file;
2396 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2397 monotonic_clock::time_point(chrono::microseconds(90200)))
2398 << file;
2399 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2400 monotonic_clock::time_point(chrono::microseconds(90350)))
2401 << file;
2402 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2403 monotonic_clock::time_point(chrono::microseconds(100000)))
2404 << file;
2405 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2406 monotonic_clock::time_point(chrono::microseconds(100150)))
2407 << file;
2408 break;
2409 case 2:
2410 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2411 monotonic_clock::time_point(chrono::milliseconds(1323) +
2412 chrono::microseconds(200)));
2413 EXPECT_EQ(
2414 oldest_local_monotonic_timestamps,
2415 monotonic_clock::time_point(chrono::microseconds(10100350)));
2416 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2417 monotonic_clock::time_point(chrono::milliseconds(1323) +
2418 chrono::microseconds(200)));
2419 EXPECT_EQ(
2420 oldest_local_unreliable_monotonic_timestamps,
2421 monotonic_clock::time_point(chrono::microseconds(10100350)));
2422 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2423 monotonic_clock::max_time)
2424 << file;
2425 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2426 monotonic_clock::max_time)
2427 << file;
2428 break;
2429 case 3:
2430 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2431 monotonic_clock::time_point(chrono::milliseconds(1323) +
2432 chrono::microseconds(200)));
2433 EXPECT_EQ(
2434 oldest_local_monotonic_timestamps,
2435 monotonic_clock::time_point(chrono::microseconds(10100350)));
2436 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2437 monotonic_clock::time_point(chrono::milliseconds(1323) +
2438 chrono::microseconds(200)));
2439 EXPECT_EQ(
2440 oldest_local_unreliable_monotonic_timestamps,
2441 monotonic_clock::time_point(chrono::microseconds(10100350)));
2442 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2443 monotonic_clock::time_point(chrono::microseconds(1423000)))
2444 << file;
2445 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2446 monotonic_clock::time_point(chrono::microseconds(10200150)))
2447 << file;
2448 break;
2449 default:
2450 FAIL();
2451 break;
2452 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002453 }
2454 }
2455
2456 // Confirm that we refuse to replay logs with missing boot uuids.
2457 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07002458 auto sorted_parts = SortParts(pi1_reboot_logfiles_);
2459 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
2460 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07002461
2462 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2463 log_reader_factory.set_send_delay(chrono::microseconds(0));
2464
2465 // This sends out the fetched messages and advances time to the start of
2466 // the log file.
2467 reader.Register(&log_reader_factory);
2468
2469 log_reader_factory.Run();
2470
2471 reader.Deregister();
2472 }
2473}
2474
2475// Tests that we can sort a log which only has timestamps from the remote
2476// because the local message_bridge_client failed to connect.
2477TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002478 if (file_strategy() == FileStrategy::kCombine) {
2479 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2480 }
2481
Naman Guptaa63aa132023-03-22 20:06:34 -07002482 const UUID pi1_boot0 = UUID::Random();
2483 const UUID pi2_boot0 = UUID::Random();
2484 const UUID pi2_boot1 = UUID::Random();
2485 {
2486 CHECK_EQ(pi1_index_, 0u);
2487 CHECK_EQ(pi2_index_, 1u);
2488
2489 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2490 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2491 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2492
2493 time_converter_.AddNextTimestamp(
2494 distributed_clock::epoch(),
2495 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2496 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2497 time_converter_.AddNextTimestamp(
2498 distributed_clock::epoch() + reboot_time,
2499 {BootTimestamp::epoch() + reboot_time,
2500 BootTimestamp{
2501 .boot = 1,
2502 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2503 }
2504 pi2_->Disconnect(pi1_->node());
2505
2506 std::vector<std::string> filenames;
2507 {
2508 LoggerState pi1_logger = MakeLogger(pi1_);
2509
2510 event_loop_factory_.RunFor(chrono::milliseconds(95));
2511 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2512 pi1_boot0);
2513 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2514 pi2_boot0);
2515
2516 StartLogger(&pi1_logger);
2517
2518 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2519
2520 VLOG(1) << "Reboot now!";
2521
2522 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2523 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2524 pi1_boot0);
2525 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2526 pi2_boot1);
2527 pi1_logger.AppendAllFilenames(&filenames);
2528 }
2529
2530 std::sort(filenames.begin(), filenames.end());
2531
2532 // Confirm that our new oldest timestamps properly update as we reboot and
2533 // rotate.
2534 size_t timestamp_file_count = 0;
2535 for (const std::string &file : filenames) {
2536 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2537 ReadHeader(file);
2538 CHECK(log_header);
2539
2540 if (log_header->message().has_configuration()) {
2541 continue;
2542 }
2543
2544 const monotonic_clock::time_point monotonic_start_time =
2545 monotonic_clock::time_point(
2546 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2547 const UUID source_node_boot_uuid = UUID::FromString(
2548 log_header->message().source_node_boot_uuid()->string_view());
2549
2550 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2551 ASSERT_EQ(
2552 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2553 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2554 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2555 2u);
2556 ASSERT_TRUE(log_header->message()
2557 .has_oldest_remote_unreliable_monotonic_timestamps());
2558 ASSERT_EQ(log_header->message()
2559 .oldest_remote_unreliable_monotonic_timestamps()
2560 ->size(),
2561 2u);
2562 ASSERT_TRUE(log_header->message()
2563 .has_oldest_local_unreliable_monotonic_timestamps());
2564 ASSERT_EQ(log_header->message()
2565 .oldest_local_unreliable_monotonic_timestamps()
2566 ->size(),
2567 2u);
2568 ASSERT_TRUE(log_header->message()
2569 .has_oldest_remote_reliable_monotonic_timestamps());
2570 ASSERT_EQ(log_header->message()
2571 .oldest_remote_reliable_monotonic_timestamps()
2572 ->size(),
2573 2u);
2574 ASSERT_TRUE(
2575 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
2576 ASSERT_EQ(log_header->message()
2577 .oldest_local_reliable_monotonic_timestamps()
2578 ->size(),
2579 2u);
2580
2581 ASSERT_TRUE(
2582 log_header->message()
2583 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
2584 ASSERT_EQ(log_header->message()
2585 .oldest_logger_remote_unreliable_monotonic_timestamps()
2586 ->size(),
2587 2u);
2588 ASSERT_TRUE(log_header->message()
2589 .has_oldest_logger_local_unreliable_monotonic_timestamps());
2590 ASSERT_EQ(log_header->message()
2591 .oldest_logger_local_unreliable_monotonic_timestamps()
2592 ->size(),
2593 2u);
2594
2595 if (log_header->message().node()->name()->string_view() != "pi1") {
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002596 ASSERT_TRUE(file.find("timestamps/remote_pi2") != std::string::npos);
Naman Guptaa63aa132023-03-22 20:06:34 -07002597
2598 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2599 ReadNthMessage(file, 0);
2600 CHECK(msg);
2601
2602 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2603 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2604
2605 const monotonic_clock::time_point
2606 expected_oldest_local_monotonic_timestamps(
2607 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2608 const monotonic_clock::time_point
2609 expected_oldest_remote_monotonic_timestamps(
2610 chrono::nanoseconds(msg->message().monotonic_remote_time()));
2611 const monotonic_clock::time_point
2612 expected_oldest_timestamp_monotonic_timestamps(
2613 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
2614
2615 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2616 monotonic_clock::min_time);
2617 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2618 monotonic_clock::min_time);
2619 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
2620 monotonic_clock::min_time);
2621
2622 ++timestamp_file_count;
2623 // Since the log file is from the perspective of the other node,
2624 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2625 monotonic_clock::time_point(chrono::nanoseconds(
2626 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2627 0)));
2628 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2629 monotonic_clock::time_point(chrono::nanoseconds(
2630 log_header->message().oldest_local_monotonic_timestamps()->Get(
2631 0)));
2632 const monotonic_clock::time_point
2633 oldest_remote_unreliable_monotonic_timestamps =
2634 monotonic_clock::time_point(chrono::nanoseconds(
2635 log_header->message()
2636 .oldest_remote_unreliable_monotonic_timestamps()
2637 ->Get(0)));
2638 const monotonic_clock::time_point
2639 oldest_local_unreliable_monotonic_timestamps =
2640 monotonic_clock::time_point(chrono::nanoseconds(
2641 log_header->message()
2642 .oldest_local_unreliable_monotonic_timestamps()
2643 ->Get(0)));
2644 const monotonic_clock::time_point
2645 oldest_remote_reliable_monotonic_timestamps =
2646 monotonic_clock::time_point(chrono::nanoseconds(
2647 log_header->message()
2648 .oldest_remote_reliable_monotonic_timestamps()
2649 ->Get(0)));
2650 const monotonic_clock::time_point
2651 oldest_local_reliable_monotonic_timestamps =
2652 monotonic_clock::time_point(chrono::nanoseconds(
2653 log_header->message()
2654 .oldest_local_reliable_monotonic_timestamps()
2655 ->Get(0)));
2656 const monotonic_clock::time_point
2657 oldest_logger_remote_unreliable_monotonic_timestamps =
2658 monotonic_clock::time_point(chrono::nanoseconds(
2659 log_header->message()
2660 .oldest_logger_remote_unreliable_monotonic_timestamps()
2661 ->Get(1)));
2662 const monotonic_clock::time_point
2663 oldest_logger_local_unreliable_monotonic_timestamps =
2664 monotonic_clock::time_point(chrono::nanoseconds(
2665 log_header->message()
2666 .oldest_logger_local_unreliable_monotonic_timestamps()
2667 ->Get(1)));
2668
2669 const Channel *channel =
2670 event_loop_factory_.configuration()->channels()->Get(
2671 msg->message().channel_index());
2672 const Connection *connection = configuration::ConnectionToNode(
2673 channel, configuration::GetNode(
2674 event_loop_factory_.configuration(),
2675 log_header->message().node()->name()->string_view()));
2676
2677 const bool reliable = connection->time_to_live() == 0;
2678
2679 SCOPED_TRACE(file);
2680 SCOPED_TRACE(aos::FlatbufferToJson(
2681 *log_header, {.multi_line = true, .max_vector_size = 100}));
2682
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002683 // Confirm that the oldest timestamps match what we expect. Based on
2684 // what we are doing, we know that the oldest time is the first
2685 // message's time.
2686 //
2687 // This makes the test robust to both the split and combined config
2688 // tests.
2689 switch (log_header->message().parts_index()) {
2690 case 0:
2691 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2692 expected_oldest_remote_monotonic_timestamps);
2693 EXPECT_EQ(oldest_local_monotonic_timestamps,
2694 expected_oldest_local_monotonic_timestamps);
2695 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2696 expected_oldest_local_monotonic_timestamps)
2697 << file;
2698 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2699 expected_oldest_timestamp_monotonic_timestamps)
2700 << file;
2701
2702 if (reliable) {
2703 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002704 expected_oldest_remote_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002705 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002706 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002707 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2708 monotonic_clock::max_time);
2709 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2710 monotonic_clock::max_time);
2711 } else {
2712 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2713 monotonic_clock::max_time);
2714 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2715 monotonic_clock::max_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07002716 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2717 expected_oldest_remote_monotonic_timestamps);
2718 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2719 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002720 }
2721 break;
2722 case 1:
2723 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2724 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2725 EXPECT_EQ(oldest_local_monotonic_timestamps,
2726 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2727 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2728 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2729 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2730 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
2731 if (reliable) {
2732 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2733 expected_oldest_remote_monotonic_timestamps);
2734 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2735 expected_oldest_local_monotonic_timestamps);
2736 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2737 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2738 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2739 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2740 } else {
2741 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2742 monotonic_clock::max_time);
2743 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2744 monotonic_clock::max_time);
2745 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2746 expected_oldest_remote_monotonic_timestamps);
2747 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2748 expected_oldest_local_monotonic_timestamps);
2749 }
2750 break;
2751 case 2:
2752 EXPECT_EQ(
2753 oldest_remote_monotonic_timestamps,
2754 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2755 EXPECT_EQ(oldest_local_monotonic_timestamps,
2756 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2757 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2758 expected_oldest_local_monotonic_timestamps)
2759 << file;
2760 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2761 expected_oldest_timestamp_monotonic_timestamps)
2762 << file;
2763 if (reliable) {
2764 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2765 expected_oldest_remote_monotonic_timestamps);
2766 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2767 expected_oldest_local_monotonic_timestamps);
2768 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2769 monotonic_clock::max_time);
2770 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2771 monotonic_clock::max_time);
2772 } else {
2773 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2774 monotonic_clock::max_time);
2775 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2776 monotonic_clock::max_time);
2777 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2778 expected_oldest_remote_monotonic_timestamps);
2779 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2780 expected_oldest_local_monotonic_timestamps);
2781 }
2782 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002783
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002784 case 3:
2785 EXPECT_EQ(
2786 oldest_remote_monotonic_timestamps,
2787 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2788 EXPECT_EQ(oldest_local_monotonic_timestamps,
2789 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2790 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2791 expected_oldest_remote_monotonic_timestamps);
2792 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2793 expected_oldest_local_monotonic_timestamps);
2794 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2795 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2796 EXPECT_EQ(
2797 oldest_logger_local_unreliable_monotonic_timestamps,
2798 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
2799 break;
2800 default:
2801 FAIL();
2802 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002803 }
2804
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002805 switch (log_header->message().parts_index()) {
2806 case 0:
2807 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2808 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2809 break;
2810 case 1:
2811 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2812 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2813 break;
2814 case 2:
2815 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2816 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2817 break;
2818 case 3:
2819 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2820 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2821 break;
2822 [[fallthrough]];
2823 default:
2824 FAIL();
2825 break;
2826 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002827 continue;
2828 }
2829 EXPECT_EQ(
2830 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2831 monotonic_clock::max_time.time_since_epoch().count());
2832 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2833 monotonic_clock::max_time.time_since_epoch().count());
2834 EXPECT_EQ(log_header->message()
2835 .oldest_remote_unreliable_monotonic_timestamps()
2836 ->Get(0),
2837 monotonic_clock::max_time.time_since_epoch().count());
2838 EXPECT_EQ(log_header->message()
2839 .oldest_local_unreliable_monotonic_timestamps()
2840 ->Get(0),
2841 monotonic_clock::max_time.time_since_epoch().count());
2842
2843 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2844 monotonic_clock::time_point(chrono::nanoseconds(
2845 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2846 1)));
2847 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2848 monotonic_clock::time_point(chrono::nanoseconds(
2849 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2850 const monotonic_clock::time_point
2851 oldest_remote_unreliable_monotonic_timestamps =
2852 monotonic_clock::time_point(chrono::nanoseconds(
2853 log_header->message()
2854 .oldest_remote_unreliable_monotonic_timestamps()
2855 ->Get(1)));
2856 const monotonic_clock::time_point
2857 oldest_local_unreliable_monotonic_timestamps =
2858 monotonic_clock::time_point(chrono::nanoseconds(
2859 log_header->message()
2860 .oldest_local_unreliable_monotonic_timestamps()
2861 ->Get(1)));
2862 switch (log_header->message().parts_index()) {
2863 case 0:
2864 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2865 monotonic_clock::max_time);
2866 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2867 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2868 monotonic_clock::max_time);
2869 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2870 monotonic_clock::max_time);
2871 break;
2872 default:
2873 FAIL();
2874 break;
2875 }
2876 }
2877
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002878 EXPECT_EQ(timestamp_file_count, 4u);
Naman Guptaa63aa132023-03-22 20:06:34 -07002879
2880 // Confirm that we can actually sort the resulting log and read it.
2881 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07002882 auto sorted_parts = SortParts(filenames);
2883 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
2884 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07002885
2886 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2887 log_reader_factory.set_send_delay(chrono::microseconds(0));
2888
2889 // This sends out the fetched messages and advances time to the start of
2890 // the log file.
2891 reader.Register(&log_reader_factory);
2892
2893 log_reader_factory.Run();
2894
2895 reader.Deregister();
2896 }
2897}
2898
2899// Tests that we properly handle one direction of message_bridge being
2900// unavailable.
2901TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07002902 std::vector<std::string> actual_filenames;
2903
Naman Guptaa63aa132023-03-22 20:06:34 -07002904 pi1_->Disconnect(pi2_->node());
2905 time_converter_.AddMonotonic(
2906 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2907
2908 time_converter_.AddMonotonic(
2909 {chrono::milliseconds(10000),
2910 chrono::milliseconds(10000) - chrono::milliseconds(1)});
2911 {
2912 LoggerState pi1_logger = MakeLogger(pi1_);
2913
2914 event_loop_factory_.RunFor(chrono::milliseconds(95));
2915
2916 StartLogger(&pi1_logger);
2917
2918 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002919 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002920 }
2921
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002922 // Confirm that we can parse the result. LogReader has enough internal
2923 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07002924 ConfirmReadable(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002925}
2926
2927// Tests that we properly handle one direction of message_bridge being
2928// unavailable.
2929TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
2930 pi1_->Disconnect(pi2_->node());
2931 time_converter_.AddMonotonic(
2932 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
2933
2934 time_converter_.AddMonotonic(
2935 {chrono::milliseconds(10000),
2936 chrono::milliseconds(10000) + chrono::milliseconds(1)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002937
2938 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07002939 {
2940 LoggerState pi1_logger = MakeLogger(pi1_);
2941
2942 event_loop_factory_.RunFor(chrono::milliseconds(95));
2943
2944 StartLogger(&pi1_logger);
2945
2946 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002947 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002948 }
2949
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002950 // Confirm that we can parse the result. LogReader has enough internal
2951 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07002952 ConfirmReadable(filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002953}
2954
2955// Tests that we explode if someone passes in a part file twice with a better
2956// error than an out of order error.
2957TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2958 time_converter_.AddMonotonic(
2959 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002960
2961 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07002962 {
2963 LoggerState pi1_logger = MakeLogger(pi1_);
2964
2965 event_loop_factory_.RunFor(chrono::milliseconds(95));
2966
2967 StartLogger(&pi1_logger);
2968
2969 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002970
2971 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002972 }
2973
2974 std::vector<std::string> duplicates;
Austin Schuh8fb4b452023-08-04 17:02:27 -07002975 for (const std::string &f : filenames) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002976 duplicates.emplace_back(f);
2977 duplicates.emplace_back(f);
2978 }
2979 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
2980}
2981
2982// Tests that we explode if someone loses a part out of the middle of a log.
2983TEST_P(MultinodeLoggerTest, MissingPartsFromMiddle) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002984 if (file_strategy() == FileStrategy::kCombine) {
2985 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2986 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002987 time_converter_.AddMonotonic(
2988 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2989 {
2990 LoggerState pi1_logger = MakeLogger(pi1_);
2991
2992 event_loop_factory_.RunFor(chrono::milliseconds(95));
2993
2994 StartLogger(&pi1_logger);
2995 aos::monotonic_clock::time_point last_rotation_time =
2996 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07002997 pi1_logger.logger->set_on_logged_period(
2998 [&](aos::monotonic_clock::time_point) {
2999 const auto now = pi1_logger.event_loop->monotonic_now();
3000 if (now > last_rotation_time + std::chrono::seconds(5)) {
3001 pi1_logger.logger->Rotate();
3002 last_rotation_time = now;
3003 }
3004 });
Naman Guptaa63aa132023-03-22 20:06:34 -07003005
3006 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3007 }
3008
3009 std::vector<std::string> missing_parts;
3010
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07003011 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part0" +
3012 Extension());
3013 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part2" +
3014 Extension());
Naman Guptaa63aa132023-03-22 20:06:34 -07003015 missing_parts.emplace_back(absl::StrCat(
3016 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
3017
3018 EXPECT_DEATH({ SortParts(missing_parts); },
3019 "Broken log, missing part files between");
3020}
3021
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003022// Tests that we properly handle a dead node. Do this by just disconnecting
3023// it and only using one nodes of logs.
Naman Guptaa63aa132023-03-22 20:06:34 -07003024TEST_P(MultinodeLoggerTest, DeadNode) {
3025 pi1_->Disconnect(pi2_->node());
3026 pi2_->Disconnect(pi1_->node());
3027 time_converter_.AddMonotonic(
3028 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3029 {
3030 LoggerState pi1_logger = MakeLogger(pi1_);
3031
3032 event_loop_factory_.RunFor(chrono::milliseconds(95));
3033
3034 StartLogger(&pi1_logger);
3035
3036 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3037 }
3038
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003039 // Confirm that we can parse the result. LogReader has enough internal
3040 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003041 ConfirmReadable(MakePi1DeadNodeLogfiles());
3042}
3043
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003044// Tests that we can relog with a different config. This makes most sense
3045// when you are trying to edit a log and want to use channel renaming + the
3046// original config in the new log.
Naman Guptaa63aa132023-03-22 20:06:34 -07003047TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3048 time_converter_.StartEqual();
3049 {
3050 LoggerState pi1_logger = MakeLogger(pi1_);
3051 LoggerState pi2_logger = MakeLogger(pi2_);
3052
3053 event_loop_factory_.RunFor(chrono::milliseconds(95));
3054
3055 StartLogger(&pi1_logger);
3056 StartLogger(&pi2_logger);
3057
3058 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3059 }
3060
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003061 auto sorted_parts = SortParts(logfiles_);
3062 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3063 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003064 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3065
3066 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3067 log_reader_factory.set_send_delay(chrono::microseconds(0));
3068
3069 // This sends out the fetched messages and advances time to the start of the
3070 // log file.
3071 reader.Register(&log_reader_factory);
3072
3073 const Node *pi1 =
3074 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3075 const Node *pi2 =
3076 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3077
3078 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3079 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3080 LOG(INFO) << "now pi1 "
3081 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3082 LOG(INFO) << "now pi2 "
3083 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3084
3085 EXPECT_THAT(reader.LoggedNodes(),
3086 ::testing::ElementsAre(
3087 configuration::GetNode(reader.logged_configuration(), pi1),
3088 configuration::GetNode(reader.logged_configuration(), pi2)));
3089
3090 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3091
3092 // And confirm we can re-create a log again, while checking the contents.
3093 std::vector<std::string> log_files;
3094 {
3095 LoggerState pi1_logger =
3096 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
3097 &log_reader_factory, reader.logged_configuration());
3098 LoggerState pi2_logger =
3099 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
3100 &log_reader_factory, reader.logged_configuration());
3101
Austin Schuh7e417682023-08-11 17:05:30 -07003102 pi1_logger.StartLogger(tmp_dir_ + "/logs/relogged1");
3103 pi2_logger.StartLogger(tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07003104
3105 log_reader_factory.Run();
3106
3107 for (auto &x : pi1_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003108 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged1_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003109 }
3110 for (auto &x : pi2_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003111 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged2_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003112 }
3113 }
3114
3115 reader.Deregister();
3116
3117 // And verify that we can run the LogReader over the relogged files without
3118 // hitting any fatal errors.
3119 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003120 auto sorted_parts = SortParts(log_files);
3121 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3122 LogReader relogged_reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003123 relogged_reader.Register();
3124
3125 relogged_reader.event_loop_factory()->Run();
3126 }
3127}
3128
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003129// Tests that we properly replay a log where the start time for a node is
3130// before any data on the node. This can happen if the logger starts before
3131// data is published. While the scenario below is a bit convoluted, we have
3132// seen logs like this generated out in the wild.
Naman Guptaa63aa132023-03-22 20:06:34 -07003133TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
Austin Schuh7e417682023-08-11 17:05:30 -07003134 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3135 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3136
Naman Guptaa63aa132023-03-22 20:06:34 -07003137 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3138 aos::configuration::ReadConfig(ArtifactPath(
3139 "aos/events/logging/multinode_pingpong_split3_config.json"));
3140 message_bridge::TestingTimeConverter time_converter(
3141 configuration::NodesCount(&config.message()));
3142 SimulatedEventLoopFactory event_loop_factory(&config.message());
3143 event_loop_factory.SetTimeConverter(&time_converter);
3144 NodeEventLoopFactory *const pi1 =
3145 event_loop_factory.GetNodeEventLoopFactory("pi1");
3146 const size_t pi1_index = configuration::GetNodeIndex(
3147 event_loop_factory.configuration(), pi1->node());
3148 NodeEventLoopFactory *const pi2 =
3149 event_loop_factory.GetNodeEventLoopFactory("pi2");
3150 const size_t pi2_index = configuration::GetNodeIndex(
3151 event_loop_factory.configuration(), pi2->node());
3152 NodeEventLoopFactory *const pi3 =
3153 event_loop_factory.GetNodeEventLoopFactory("pi3");
3154 const size_t pi3_index = configuration::GetNodeIndex(
3155 event_loop_factory.configuration(), pi3->node());
3156
3157 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003158 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003159 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003160 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003161 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003162 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003163 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003164 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
3165
Naman Guptaa63aa132023-03-22 20:06:34 -07003166 const UUID pi1_boot0 = UUID::Random();
3167 const UUID pi2_boot0 = UUID::Random();
3168 const UUID pi2_boot1 = UUID::Random();
3169 const UUID pi3_boot0 = UUID::Random();
3170 {
3171 CHECK_EQ(pi1_index, 0u);
3172 CHECK_EQ(pi2_index, 1u);
3173 CHECK_EQ(pi3_index, 2u);
3174
3175 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3176 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3177 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3178 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3179
3180 time_converter.AddNextTimestamp(
3181 distributed_clock::epoch(),
3182 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3183 BootTimestamp::epoch()});
3184 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3185 time_converter.AddNextTimestamp(
3186 distributed_clock::epoch() + reboot_time,
3187 {BootTimestamp::epoch() + reboot_time,
3188 BootTimestamp{
3189 .boot = 1,
3190 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3191 BootTimestamp::epoch() + reboot_time});
3192 }
3193
3194 // Make everything perfectly quiet.
3195 event_loop_factory.SkipTimingReport();
3196 event_loop_factory.DisableStatistics();
3197
3198 std::vector<std::string> filenames;
3199 {
3200 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003201 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3202 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003203 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003204 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3205 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003206 {
3207 // And now start the logger.
3208 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003209 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3210 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003211
3212 event_loop_factory.RunFor(chrono::milliseconds(1000));
3213
3214 pi1_logger.StartLogger(kLogfile1_1);
3215 pi3_logger.StartLogger(kLogfile3_1);
3216 pi2_logger.StartLogger(kLogfile2_1);
3217
3218 event_loop_factory.RunFor(chrono::milliseconds(10000));
3219
3220 // Now that we've got a start time in the past, turn on data.
3221 event_loop_factory.EnableStatistics();
3222 std::unique_ptr<aos::EventLoop> ping_event_loop =
3223 pi1->MakeEventLoop("ping");
3224 Ping ping(ping_event_loop.get());
3225
3226 pi2->AlwaysStart<Pong>("pong");
3227
3228 event_loop_factory.RunFor(chrono::milliseconds(3000));
3229
3230 pi2_logger.AppendAllFilenames(&filenames);
3231
3232 // Stop logging on pi2 before rebooting and completely shut off all
3233 // messages on pi2.
3234 pi2->DisableStatistics();
3235 pi1->Disconnect(pi2->node());
3236 pi2->Disconnect(pi1->node());
3237 }
3238 event_loop_factory.RunFor(chrono::milliseconds(7000));
3239 // pi2 now reboots.
3240 {
3241 event_loop_factory.RunFor(chrono::milliseconds(1000));
3242
3243 // Start logging again on pi2 after it is up.
3244 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003245 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3246 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003247 pi2_logger.StartLogger(kLogfile2_2);
3248
3249 event_loop_factory.RunFor(chrono::milliseconds(10000));
3250 // And, now that we have a start time in the log, turn data back on.
3251 pi2->EnableStatistics();
3252 pi1->Connect(pi2->node());
3253 pi2->Connect(pi1->node());
3254
3255 pi2->AlwaysStart<Pong>("pong");
3256 std::unique_ptr<aos::EventLoop> ping_event_loop =
3257 pi1->MakeEventLoop("ping");
3258 Ping ping(ping_event_loop.get());
3259
3260 event_loop_factory.RunFor(chrono::milliseconds(3000));
3261
3262 pi2_logger.AppendAllFilenames(&filenames);
3263 }
3264
3265 pi1_logger.AppendAllFilenames(&filenames);
3266 pi3_logger.AppendAllFilenames(&filenames);
3267 }
3268
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003269 // Confirm that we can parse the result. LogReader has enough internal
3270 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003271 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003272 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003273 auto result = ConfirmReadable(filenames);
3274 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3275 chrono::seconds(1)));
3276 EXPECT_THAT(result[0].second,
3277 ::testing::ElementsAre(realtime_clock::epoch() +
3278 chrono::microseconds(34990350)));
3279
3280 EXPECT_THAT(result[1].first,
3281 ::testing::ElementsAre(
3282 realtime_clock::epoch() + chrono::seconds(1),
3283 realtime_clock::epoch() + chrono::microseconds(3323000)));
3284 EXPECT_THAT(result[1].second,
3285 ::testing::ElementsAre(
3286 realtime_clock::epoch() + chrono::microseconds(13990200),
3287 realtime_clock::epoch() + chrono::microseconds(16313200)));
3288
3289 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3290 chrono::seconds(1)));
3291 EXPECT_THAT(result[2].second,
3292 ::testing::ElementsAre(realtime_clock::epoch() +
3293 chrono::microseconds(34900150)));
3294}
3295
3296// Tests that local data before remote data after reboot is properly replayed.
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003297// We only trigger a reboot in the timestamp interpolation function when
3298// solving the timestamp problem when we actually have a point in the
3299// function. This originally only happened when a point passes the noncausal
3300// filter. At the start of time for the second boot, if we aren't careful, we
3301// will have messages which need to be published at times before the boot.
3302// This happens when a local message is in the log before a forwarded message,
3303// so there is no point in the interpolation function. This delays the
3304// reboot. So, we need to recreate that situation and make sure it doesn't
3305// come back.
Naman Guptaa63aa132023-03-22 20:06:34 -07003306TEST(MultinodeRebootLoggerTest,
3307 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003308 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3309 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3310
Naman Guptaa63aa132023-03-22 20:06:34 -07003311 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3312 aos::configuration::ReadConfig(ArtifactPath(
3313 "aos/events/logging/multinode_pingpong_split3_config.json"));
3314 message_bridge::TestingTimeConverter time_converter(
3315 configuration::NodesCount(&config.message()));
3316 SimulatedEventLoopFactory event_loop_factory(&config.message());
3317 event_loop_factory.SetTimeConverter(&time_converter);
3318 NodeEventLoopFactory *const pi1 =
3319 event_loop_factory.GetNodeEventLoopFactory("pi1");
3320 const size_t pi1_index = configuration::GetNodeIndex(
3321 event_loop_factory.configuration(), pi1->node());
3322 NodeEventLoopFactory *const pi2 =
3323 event_loop_factory.GetNodeEventLoopFactory("pi2");
3324 const size_t pi2_index = configuration::GetNodeIndex(
3325 event_loop_factory.configuration(), pi2->node());
3326 NodeEventLoopFactory *const pi3 =
3327 event_loop_factory.GetNodeEventLoopFactory("pi3");
3328 const size_t pi3_index = configuration::GetNodeIndex(
3329 event_loop_factory.configuration(), pi3->node());
3330
3331 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003332 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003333 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003334 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003335 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003336 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003337 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003338 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003339 const UUID pi1_boot0 = UUID::Random();
3340 const UUID pi2_boot0 = UUID::Random();
3341 const UUID pi2_boot1 = UUID::Random();
3342 const UUID pi3_boot0 = UUID::Random();
3343 {
3344 CHECK_EQ(pi1_index, 0u);
3345 CHECK_EQ(pi2_index, 1u);
3346 CHECK_EQ(pi3_index, 2u);
3347
3348 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3349 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3350 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3351 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3352
3353 time_converter.AddNextTimestamp(
3354 distributed_clock::epoch(),
3355 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3356 BootTimestamp::epoch()});
3357 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3358 time_converter.AddNextTimestamp(
3359 distributed_clock::epoch() + reboot_time,
3360 {BootTimestamp::epoch() + reboot_time,
3361 BootTimestamp{.boot = 1,
3362 .time = monotonic_clock::epoch() + reboot_time +
3363 chrono::seconds(100)},
3364 BootTimestamp::epoch() + reboot_time});
3365 }
3366
3367 std::vector<std::string> filenames;
3368 {
3369 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003370 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3371 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003372 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003373 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3374 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003375 {
3376 // And now start the logger.
3377 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003378 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3379 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003380
3381 pi1_logger.StartLogger(kLogfile1_1);
3382 pi3_logger.StartLogger(kLogfile3_1);
3383 pi2_logger.StartLogger(kLogfile2_1);
3384
3385 event_loop_factory.RunFor(chrono::milliseconds(1005));
3386
3387 // Now that we've got a start time in the past, turn on data.
3388 std::unique_ptr<aos::EventLoop> ping_event_loop =
3389 pi1->MakeEventLoop("ping");
3390 Ping ping(ping_event_loop.get());
3391
3392 pi2->AlwaysStart<Pong>("pong");
3393
3394 event_loop_factory.RunFor(chrono::milliseconds(3000));
3395
3396 pi2_logger.AppendAllFilenames(&filenames);
3397
3398 // Disable any remote messages on pi2.
3399 pi1->Disconnect(pi2->node());
3400 pi2->Disconnect(pi1->node());
3401 }
3402 event_loop_factory.RunFor(chrono::milliseconds(995));
3403 // pi2 now reboots at 5 seconds.
3404 {
3405 event_loop_factory.RunFor(chrono::milliseconds(1000));
3406
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003407 // Make local stuff happen before we start logging and connect the
3408 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003409 pi2->AlwaysStart<Pong>("pong");
3410 std::unique_ptr<aos::EventLoop> ping_event_loop =
3411 pi1->MakeEventLoop("ping");
3412 Ping ping(ping_event_loop.get());
3413 event_loop_factory.RunFor(chrono::milliseconds(1005));
3414
3415 // Start logging again on pi2 after it is up.
3416 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003417 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3418 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003419 pi2_logger.StartLogger(kLogfile2_2);
3420
3421 // And allow remote messages now that we have some local ones.
3422 pi1->Connect(pi2->node());
3423 pi2->Connect(pi1->node());
3424
3425 event_loop_factory.RunFor(chrono::milliseconds(1000));
3426
3427 event_loop_factory.RunFor(chrono::milliseconds(3000));
3428
3429 pi2_logger.AppendAllFilenames(&filenames);
3430 }
3431
3432 pi1_logger.AppendAllFilenames(&filenames);
3433 pi3_logger.AppendAllFilenames(&filenames);
3434 }
3435
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003436 // Confirm that we can parse the result. LogReader has enough internal
3437 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003438 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003439 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003440 auto result = ConfirmReadable(filenames);
3441
3442 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3443 EXPECT_THAT(result[0].second,
3444 ::testing::ElementsAre(realtime_clock::epoch() +
3445 chrono::microseconds(11000350)));
3446
3447 EXPECT_THAT(result[1].first,
3448 ::testing::ElementsAre(
3449 realtime_clock::epoch(),
3450 realtime_clock::epoch() + chrono::microseconds(107005000)));
3451 EXPECT_THAT(result[1].second,
3452 ::testing::ElementsAre(
3453 realtime_clock::epoch() + chrono::microseconds(4000150),
3454 realtime_clock::epoch() + chrono::microseconds(111000200)));
3455
3456 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3457 EXPECT_THAT(result[2].second,
3458 ::testing::ElementsAre(realtime_clock::epoch() +
3459 chrono::microseconds(11000150)));
3460
3461 auto start_stop_result = ConfirmReadable(
3462 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3463 realtime_clock::epoch() + chrono::milliseconds(3000));
3464
3465 EXPECT_THAT(
3466 start_stop_result[0].first,
3467 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3468 EXPECT_THAT(
3469 start_stop_result[0].second,
3470 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3471 EXPECT_THAT(
3472 start_stop_result[1].first,
3473 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3474 EXPECT_THAT(
3475 start_stop_result[1].second,
3476 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3477 EXPECT_THAT(
3478 start_stop_result[2].first,
3479 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3480 EXPECT_THAT(
3481 start_stop_result[2].second,
3482 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3483}
3484
3485// Tests that setting the start and stop flags across a reboot works as
3486// expected.
3487TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
Austin Schuh7e417682023-08-11 17:05:30 -07003488 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3489 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3490
Naman Guptaa63aa132023-03-22 20:06:34 -07003491 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3492 aos::configuration::ReadConfig(ArtifactPath(
3493 "aos/events/logging/multinode_pingpong_split3_config.json"));
3494 message_bridge::TestingTimeConverter time_converter(
3495 configuration::NodesCount(&config.message()));
3496 SimulatedEventLoopFactory event_loop_factory(&config.message());
3497 event_loop_factory.SetTimeConverter(&time_converter);
3498 NodeEventLoopFactory *const pi1 =
3499 event_loop_factory.GetNodeEventLoopFactory("pi1");
3500 const size_t pi1_index = configuration::GetNodeIndex(
3501 event_loop_factory.configuration(), pi1->node());
3502 NodeEventLoopFactory *const pi2 =
3503 event_loop_factory.GetNodeEventLoopFactory("pi2");
3504 const size_t pi2_index = configuration::GetNodeIndex(
3505 event_loop_factory.configuration(), pi2->node());
3506 NodeEventLoopFactory *const pi3 =
3507 event_loop_factory.GetNodeEventLoopFactory("pi3");
3508 const size_t pi3_index = configuration::GetNodeIndex(
3509 event_loop_factory.configuration(), pi3->node());
3510
3511 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003512 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003513 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003514 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003515 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003516 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003517 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003518 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003519 {
3520 CHECK_EQ(pi1_index, 0u);
3521 CHECK_EQ(pi2_index, 1u);
3522 CHECK_EQ(pi3_index, 2u);
3523
3524 time_converter.AddNextTimestamp(
3525 distributed_clock::epoch(),
3526 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3527 BootTimestamp::epoch()});
3528 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3529 time_converter.AddNextTimestamp(
3530 distributed_clock::epoch() + reboot_time,
3531 {BootTimestamp::epoch() + reboot_time,
3532 BootTimestamp{.boot = 1,
3533 .time = monotonic_clock::epoch() + reboot_time},
3534 BootTimestamp::epoch() + reboot_time});
3535 }
3536
3537 std::vector<std::string> filenames;
3538 {
3539 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003540 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3541 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003542 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003543 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3544 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003545 {
3546 // And now start the logger.
3547 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003548 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3549 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003550
3551 pi1_logger.StartLogger(kLogfile1_1);
3552 pi3_logger.StartLogger(kLogfile3_1);
3553 pi2_logger.StartLogger(kLogfile2_1);
3554
3555 event_loop_factory.RunFor(chrono::milliseconds(1005));
3556
3557 // Now that we've got a start time in the past, turn on data.
3558 std::unique_ptr<aos::EventLoop> ping_event_loop =
3559 pi1->MakeEventLoop("ping");
3560 Ping ping(ping_event_loop.get());
3561
3562 pi2->AlwaysStart<Pong>("pong");
3563
3564 event_loop_factory.RunFor(chrono::milliseconds(3000));
3565
3566 pi2_logger.AppendAllFilenames(&filenames);
3567 }
3568 event_loop_factory.RunFor(chrono::milliseconds(995));
3569 // pi2 now reboots at 5 seconds.
3570 {
3571 event_loop_factory.RunFor(chrono::milliseconds(1000));
3572
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003573 // Make local stuff happen before we start logging and connect the
3574 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003575 pi2->AlwaysStart<Pong>("pong");
3576 std::unique_ptr<aos::EventLoop> ping_event_loop =
3577 pi1->MakeEventLoop("ping");
3578 Ping ping(ping_event_loop.get());
3579 event_loop_factory.RunFor(chrono::milliseconds(5));
3580
3581 // Start logging again on pi2 after it is up.
3582 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003583 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3584 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003585 pi2_logger.StartLogger(kLogfile2_2);
3586
3587 event_loop_factory.RunFor(chrono::milliseconds(5000));
3588
3589 pi2_logger.AppendAllFilenames(&filenames);
3590 }
3591
3592 pi1_logger.AppendAllFilenames(&filenames);
3593 pi3_logger.AppendAllFilenames(&filenames);
3594 }
3595
3596 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003597 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003598 auto result = ConfirmReadable(filenames);
3599
3600 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3601 EXPECT_THAT(result[0].second,
3602 ::testing::ElementsAre(realtime_clock::epoch() +
3603 chrono::microseconds(11000350)));
3604
3605 EXPECT_THAT(result[1].first,
3606 ::testing::ElementsAre(
3607 realtime_clock::epoch(),
3608 realtime_clock::epoch() + chrono::microseconds(6005000)));
3609 EXPECT_THAT(result[1].second,
3610 ::testing::ElementsAre(
3611 realtime_clock::epoch() + chrono::microseconds(4900150),
3612 realtime_clock::epoch() + chrono::microseconds(11000200)));
3613
3614 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3615 EXPECT_THAT(result[2].second,
3616 ::testing::ElementsAre(realtime_clock::epoch() +
3617 chrono::microseconds(11000150)));
3618
3619 // Confirm we observed the correct start and stop times. We should see the
3620 // reboot here.
3621 auto start_stop_result = ConfirmReadable(
3622 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3623 realtime_clock::epoch() + chrono::milliseconds(8000));
3624
3625 EXPECT_THAT(
3626 start_stop_result[0].first,
3627 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3628 EXPECT_THAT(
3629 start_stop_result[0].second,
3630 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3631 EXPECT_THAT(start_stop_result[1].first,
3632 ::testing::ElementsAre(
3633 realtime_clock::epoch() + chrono::seconds(2),
3634 realtime_clock::epoch() + chrono::microseconds(6005000)));
3635 EXPECT_THAT(start_stop_result[1].second,
3636 ::testing::ElementsAre(
3637 realtime_clock::epoch() + chrono::microseconds(4900150),
3638 realtime_clock::epoch() + chrono::seconds(8)));
3639 EXPECT_THAT(
3640 start_stop_result[2].first,
3641 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3642 EXPECT_THAT(
3643 start_stop_result[2].second,
3644 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3645}
3646
3647// Tests that we properly handle one direction being down.
3648TEST(MissingDirectionTest, OneDirection) {
Austin Schuh7e417682023-08-11 17:05:30 -07003649 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3650 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3651
Naman Guptaa63aa132023-03-22 20:06:34 -07003652 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3653 aos::configuration::ReadConfig(ArtifactPath(
3654 "aos/events/logging/multinode_pingpong_split4_config.json"));
3655 message_bridge::TestingTimeConverter time_converter(
3656 configuration::NodesCount(&config.message()));
3657 SimulatedEventLoopFactory event_loop_factory(&config.message());
3658 event_loop_factory.SetTimeConverter(&time_converter);
3659
3660 NodeEventLoopFactory *const pi1 =
3661 event_loop_factory.GetNodeEventLoopFactory("pi1");
3662 const size_t pi1_index = configuration::GetNodeIndex(
3663 event_loop_factory.configuration(), pi1->node());
3664 NodeEventLoopFactory *const pi2 =
3665 event_loop_factory.GetNodeEventLoopFactory("pi2");
3666 const size_t pi2_index = configuration::GetNodeIndex(
3667 event_loop_factory.configuration(), pi2->node());
3668 std::vector<std::string> filenames;
3669
3670 {
3671 CHECK_EQ(pi1_index, 0u);
3672 CHECK_EQ(pi2_index, 1u);
3673
3674 time_converter.AddNextTimestamp(
3675 distributed_clock::epoch(),
3676 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3677
3678 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3679 time_converter.AddNextTimestamp(
3680 distributed_clock::epoch() + reboot_time,
3681 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3682 BootTimestamp::epoch() + reboot_time});
3683 }
3684
3685 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003686 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003687 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003688 aos::testing::TestTmpDir() + "/logs/multi_logfile1.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003689
3690 pi2->Disconnect(pi1->node());
3691
3692 pi1->AlwaysStart<Ping>("ping");
3693 pi2->AlwaysStart<Pong>("pong");
3694
3695 {
3696 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003697 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3698 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003699
3700 event_loop_factory.RunFor(chrono::milliseconds(95));
3701
3702 pi2_logger.StartLogger(kLogfile2_1);
3703
3704 event_loop_factory.RunFor(chrono::milliseconds(6000));
3705
3706 pi2->Connect(pi1->node());
3707
3708 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003709 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3710 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003711 pi1_logger.StartLogger(kLogfile1_1);
3712
3713 event_loop_factory.RunFor(chrono::milliseconds(5000));
3714 pi1_logger.AppendAllFilenames(&filenames);
3715 pi2_logger.AppendAllFilenames(&filenames);
3716 }
3717
3718 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003719 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003720 ConfirmReadable(filenames);
3721}
3722
3723// Tests that we properly handle only one direction ever existing after a
3724// reboot.
3725TEST(MissingDirectionTest, OneDirectionAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003726 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3727 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3728
Naman Guptaa63aa132023-03-22 20:06:34 -07003729 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3730 aos::configuration::ReadConfig(ArtifactPath(
3731 "aos/events/logging/multinode_pingpong_split4_config.json"));
3732 message_bridge::TestingTimeConverter time_converter(
3733 configuration::NodesCount(&config.message()));
3734 SimulatedEventLoopFactory event_loop_factory(&config.message());
3735 event_loop_factory.SetTimeConverter(&time_converter);
3736
3737 NodeEventLoopFactory *const pi1 =
3738 event_loop_factory.GetNodeEventLoopFactory("pi1");
3739 const size_t pi1_index = configuration::GetNodeIndex(
3740 event_loop_factory.configuration(), pi1->node());
3741 NodeEventLoopFactory *const pi2 =
3742 event_loop_factory.GetNodeEventLoopFactory("pi2");
3743 const size_t pi2_index = configuration::GetNodeIndex(
3744 event_loop_factory.configuration(), pi2->node());
3745 std::vector<std::string> filenames;
3746
3747 {
3748 CHECK_EQ(pi1_index, 0u);
3749 CHECK_EQ(pi2_index, 1u);
3750
3751 time_converter.AddNextTimestamp(
3752 distributed_clock::epoch(),
3753 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3754
3755 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3756 time_converter.AddNextTimestamp(
3757 distributed_clock::epoch() + reboot_time,
3758 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3759 BootTimestamp::epoch() + reboot_time});
3760 }
3761
3762 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003763 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003764
3765 pi1->AlwaysStart<Ping>("ping");
3766
3767 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
3768 // makes it such that we will only get timestamps from pi1 -> pi2 on the
3769 // second boot.
3770 {
3771 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003772 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3773 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003774
3775 event_loop_factory.RunFor(chrono::milliseconds(95));
3776
3777 pi2_logger.StartLogger(kLogfile2_1);
3778
3779 event_loop_factory.RunFor(chrono::milliseconds(4000));
3780
3781 pi2->Disconnect(pi1->node());
3782
3783 event_loop_factory.RunFor(chrono::milliseconds(1000));
3784 pi1->AlwaysStart<Ping>("ping");
3785
3786 event_loop_factory.RunFor(chrono::milliseconds(5000));
3787 pi2_logger.AppendAllFilenames(&filenames);
3788 }
3789
3790 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003791 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003792 ConfirmReadable(filenames);
3793}
3794
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003795// Tests that we properly handle only one direction ever existing after a
3796// reboot with only reliable data.
Naman Guptaa63aa132023-03-22 20:06:34 -07003797TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
Austin Schuh7e417682023-08-11 17:05:30 -07003798 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3799 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3800
Naman Guptaa63aa132023-03-22 20:06:34 -07003801 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003802 aos::configuration::ReadConfig(
3803 ArtifactPath("aos/events/logging/"
3804 "multinode_pingpong_split4_reliable_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07003805 message_bridge::TestingTimeConverter time_converter(
3806 configuration::NodesCount(&config.message()));
3807 SimulatedEventLoopFactory event_loop_factory(&config.message());
3808 event_loop_factory.SetTimeConverter(&time_converter);
3809
3810 NodeEventLoopFactory *const pi1 =
3811 event_loop_factory.GetNodeEventLoopFactory("pi1");
3812 const size_t pi1_index = configuration::GetNodeIndex(
3813 event_loop_factory.configuration(), pi1->node());
3814 NodeEventLoopFactory *const pi2 =
3815 event_loop_factory.GetNodeEventLoopFactory("pi2");
3816 const size_t pi2_index = configuration::GetNodeIndex(
3817 event_loop_factory.configuration(), pi2->node());
3818 std::vector<std::string> filenames;
3819
3820 {
3821 CHECK_EQ(pi1_index, 0u);
3822 CHECK_EQ(pi2_index, 1u);
3823
3824 time_converter.AddNextTimestamp(
3825 distributed_clock::epoch(),
3826 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3827
3828 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3829 time_converter.AddNextTimestamp(
3830 distributed_clock::epoch() + reboot_time,
3831 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3832 BootTimestamp::epoch() + reboot_time});
3833 }
3834
3835 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003836 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003837
3838 pi1->AlwaysStart<Ping>("ping");
3839
3840 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
3841 // makes it such that we will only get timestamps from pi1 -> pi2 on the
3842 // second boot.
3843 {
3844 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003845 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3846 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003847
3848 event_loop_factory.RunFor(chrono::milliseconds(95));
3849
3850 pi2_logger.StartLogger(kLogfile2_1);
3851
3852 event_loop_factory.RunFor(chrono::milliseconds(4000));
3853
3854 pi2->Disconnect(pi1->node());
3855
3856 event_loop_factory.RunFor(chrono::milliseconds(1000));
3857 pi1->AlwaysStart<Ping>("ping");
3858
3859 event_loop_factory.RunFor(chrono::milliseconds(5000));
3860 pi2_logger.AppendAllFilenames(&filenames);
3861 }
3862
3863 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003864 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003865 ConfirmReadable(filenames);
3866}
3867
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003868// Tests that we properly handle only one direction ever existing after a
3869// reboot with mixed unreliable vs reliable, where reliable has an earlier
3870// timestamp than unreliable.
Brian Smartte67d7112023-03-20 12:06:30 -07003871TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase1) {
Austin Schuh7e417682023-08-11 17:05:30 -07003872 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3873 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3874
Brian Smartte67d7112023-03-20 12:06:30 -07003875 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3876 aos::configuration::ReadConfig(ArtifactPath(
3877 "aos/events/logging/multinode_pingpong_split4_mixed1_config.json"));
3878 message_bridge::TestingTimeConverter time_converter(
3879 configuration::NodesCount(&config.message()));
3880 SimulatedEventLoopFactory event_loop_factory(&config.message());
3881 event_loop_factory.SetTimeConverter(&time_converter);
3882
3883 NodeEventLoopFactory *const pi1 =
3884 event_loop_factory.GetNodeEventLoopFactory("pi1");
3885 const size_t pi1_index = configuration::GetNodeIndex(
3886 event_loop_factory.configuration(), pi1->node());
3887 NodeEventLoopFactory *const pi2 =
3888 event_loop_factory.GetNodeEventLoopFactory("pi2");
3889 const size_t pi2_index = configuration::GetNodeIndex(
3890 event_loop_factory.configuration(), pi2->node());
3891 std::vector<std::string> filenames;
3892
3893 {
3894 CHECK_EQ(pi1_index, 0u);
3895 CHECK_EQ(pi2_index, 1u);
3896
3897 time_converter.AddNextTimestamp(
3898 distributed_clock::epoch(),
3899 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3900
3901 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3902 time_converter.AddNextTimestamp(
3903 distributed_clock::epoch() + reboot_time,
3904 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3905 BootTimestamp::epoch() + reboot_time});
3906 }
3907
3908 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003909 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07003910
3911 // The following sequence using the above reference config creates
3912 // a reliable message timestamp < unreliable message timestamp.
3913 {
3914 pi1->DisableStatistics();
3915 pi2->DisableStatistics();
3916
3917 event_loop_factory.RunFor(chrono::milliseconds(95));
3918
3919 pi1->AlwaysStart<Ping>("ping");
3920
3921 event_loop_factory.RunFor(chrono::milliseconds(5250));
3922
3923 pi1->EnableStatistics();
3924
3925 event_loop_factory.RunFor(chrono::milliseconds(1000));
3926
3927 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003928 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3929 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07003930
3931 pi2_logger.StartLogger(kLogfile2_1);
3932
3933 event_loop_factory.RunFor(chrono::milliseconds(5000));
3934 pi2_logger.AppendAllFilenames(&filenames);
3935 }
3936
3937 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003938 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07003939 ConfirmReadable(filenames);
3940}
3941
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003942// Tests that we properly handle only one direction ever existing after a
3943// reboot with mixed unreliable vs reliable, where unreliable has an earlier
3944// timestamp than reliable.
Brian Smartte67d7112023-03-20 12:06:30 -07003945TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase2) {
Austin Schuh7e417682023-08-11 17:05:30 -07003946 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3947 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3948
Brian Smartte67d7112023-03-20 12:06:30 -07003949 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3950 aos::configuration::ReadConfig(ArtifactPath(
3951 "aos/events/logging/multinode_pingpong_split4_mixed2_config.json"));
3952 message_bridge::TestingTimeConverter time_converter(
3953 configuration::NodesCount(&config.message()));
3954 SimulatedEventLoopFactory event_loop_factory(&config.message());
3955 event_loop_factory.SetTimeConverter(&time_converter);
3956
3957 NodeEventLoopFactory *const pi1 =
3958 event_loop_factory.GetNodeEventLoopFactory("pi1");
3959 const size_t pi1_index = configuration::GetNodeIndex(
3960 event_loop_factory.configuration(), pi1->node());
3961 NodeEventLoopFactory *const pi2 =
3962 event_loop_factory.GetNodeEventLoopFactory("pi2");
3963 const size_t pi2_index = configuration::GetNodeIndex(
3964 event_loop_factory.configuration(), pi2->node());
3965 std::vector<std::string> filenames;
3966
3967 {
3968 CHECK_EQ(pi1_index, 0u);
3969 CHECK_EQ(pi2_index, 1u);
3970
3971 time_converter.AddNextTimestamp(
3972 distributed_clock::epoch(),
3973 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3974
3975 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3976 time_converter.AddNextTimestamp(
3977 distributed_clock::epoch() + reboot_time,
3978 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3979 BootTimestamp::epoch() + reboot_time});
3980 }
3981
3982 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003983 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07003984
3985 // The following sequence using the above reference config creates
3986 // an unreliable message timestamp < reliable message timestamp.
3987 {
3988 pi1->DisableStatistics();
3989 pi2->DisableStatistics();
3990
3991 event_loop_factory.RunFor(chrono::milliseconds(95));
3992
3993 pi1->AlwaysStart<Ping>("ping");
3994
3995 event_loop_factory.RunFor(chrono::milliseconds(5250));
3996
3997 pi1->EnableStatistics();
3998
3999 event_loop_factory.RunFor(chrono::milliseconds(1000));
4000
4001 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004002 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4003 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07004004
4005 pi2_logger.StartLogger(kLogfile2_1);
4006
4007 event_loop_factory.RunFor(chrono::milliseconds(5000));
4008 pi2_logger.AppendAllFilenames(&filenames);
4009 }
4010
4011 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004012 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07004013 ConfirmReadable(filenames);
4014}
4015
Naman Guptaa63aa132023-03-22 20:06:34 -07004016// Tests that we properly handle what used to be a time violation in one
4017// direction. This can occur when one direction goes down after sending some
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004018// data, but the other keeps working. The down direction ends up resolving to
4019// a straight line in the noncausal filter, where the direction which is still
4020// up can cross that line. Really, time progressed along just fine but we
4021// assumed that the offset was a line when it could have deviated by up to
4022// 1ms/second.
Naman Guptaa63aa132023-03-22 20:06:34 -07004023TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4024 std::vector<std::string> filenames;
4025
4026 CHECK_EQ(pi1_index_, 0u);
4027 CHECK_EQ(pi2_index_, 1u);
4028
4029 time_converter_.AddNextTimestamp(
4030 distributed_clock::epoch(),
4031 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4032
4033 const chrono::nanoseconds before_disconnect_duration =
4034 time_converter_.AddMonotonic(
4035 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4036
4037 const chrono::nanoseconds test_duration =
4038 time_converter_.AddMonotonic(
4039 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4040 time_converter_.AddMonotonic(
4041 {chrono::milliseconds(10000),
4042 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4043 time_converter_.AddMonotonic(
4044 {chrono::milliseconds(10000),
4045 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4046
4047 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004048 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004049
4050 {
4051 LoggerState pi2_logger = MakeLogger(pi2_);
4052 pi2_logger.StartLogger(kLogfile);
4053 event_loop_factory_.RunFor(before_disconnect_duration);
4054
4055 pi2_->Disconnect(pi1_->node());
4056
4057 event_loop_factory_.RunFor(test_duration);
4058 pi2_->Connect(pi1_->node());
4059
4060 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4061 pi2_logger.AppendAllFilenames(&filenames);
4062 }
4063
4064 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004065 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004066 ConfirmReadable(filenames);
4067}
4068
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004069// Tests that we can replay a logfile that has timestamps such that at least
4070// one node's epoch is at a positive distributed_clock (and thus will have to
4071// be booted after the other node(s)).
Naman Guptaa63aa132023-03-22 20:06:34 -07004072TEST_P(MultinodeLoggerTest, StartOneNodeBeforeOther) {
4073 std::vector<std::string> filenames;
4074
4075 CHECK_EQ(pi1_index_, 0u);
4076 CHECK_EQ(pi2_index_, 1u);
4077
4078 time_converter_.AddNextTimestamp(
4079 distributed_clock::epoch(),
4080 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4081
4082 const chrono::nanoseconds before_reboot_duration = chrono::milliseconds(1000);
4083 time_converter_.RebootAt(
4084 0, distributed_clock::time_point(before_reboot_duration));
4085
4086 const chrono::nanoseconds test_duration = time_converter_.AddMonotonic(
4087 {chrono::milliseconds(10000), chrono::milliseconds(10000)});
4088
4089 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004090 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004091
4092 pi2_->Disconnect(pi1_->node());
4093 pi1_->Disconnect(pi2_->node());
4094
4095 {
4096 LoggerState pi2_logger = MakeLogger(pi2_);
4097
4098 pi2_logger.StartLogger(kLogfile);
4099 event_loop_factory_.RunFor(before_reboot_duration);
4100
4101 pi2_->Connect(pi1_->node());
4102 pi1_->Connect(pi2_->node());
4103
4104 event_loop_factory_.RunFor(test_duration);
4105
4106 pi2_logger.AppendAllFilenames(&filenames);
4107 }
4108
4109 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004110 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004111 ConfirmReadable(filenames);
4112
4113 {
4114 LogReader reader(sorted_parts);
4115 SimulatedEventLoopFactory replay_factory(reader.configuration());
4116 reader.RegisterWithoutStarting(&replay_factory);
4117
4118 NodeEventLoopFactory *const replay_node =
4119 reader.event_loop_factory()->GetNodeEventLoopFactory("pi1");
4120
4121 std::unique_ptr<EventLoop> test_event_loop =
4122 replay_node->MakeEventLoop("test_reader");
4123 replay_node->OnStartup([replay_node]() {
4124 // Check that we didn't boot until at least t=0.
4125 CHECK_LE(monotonic_clock::epoch(), replay_node->monotonic_now());
4126 });
4127 test_event_loop->OnRun([&test_event_loop]() {
4128 // Check that we didn't boot until at least t=0.
4129 EXPECT_LE(monotonic_clock::epoch(), test_event_loop->monotonic_now());
4130 });
4131 reader.event_loop_factory()->Run();
4132 reader.Deregister();
4133 }
4134}
4135
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004136// Tests that when we have a loop without all the logs at all points in time,
4137// we can sort it properly.
Naman Guptaa63aa132023-03-22 20:06:34 -07004138TEST(MultinodeLoggerLoopTest, Loop) {
Austin Schuh7e417682023-08-11 17:05:30 -07004139 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4140 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4141
Naman Guptaa63aa132023-03-22 20:06:34 -07004142 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004143 aos::configuration::ReadConfig(
4144 ArtifactPath("aos/events/logging/"
4145 "multinode_pingpong_triangle_split_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07004146 message_bridge::TestingTimeConverter time_converter(
4147 configuration::NodesCount(&config.message()));
4148 SimulatedEventLoopFactory event_loop_factory(&config.message());
4149 event_loop_factory.SetTimeConverter(&time_converter);
4150
4151 NodeEventLoopFactory *const pi1 =
4152 event_loop_factory.GetNodeEventLoopFactory("pi1");
4153 NodeEventLoopFactory *const pi2 =
4154 event_loop_factory.GetNodeEventLoopFactory("pi2");
4155 NodeEventLoopFactory *const pi3 =
4156 event_loop_factory.GetNodeEventLoopFactory("pi3");
4157
4158 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004159 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004160 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004161 aos::testing::TestTmpDir() + "/logs/multi_logfile2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004162 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004163 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004164
4165 {
4166 // Make pi1 boot before everything else.
4167 time_converter.AddNextTimestamp(
4168 distributed_clock::epoch(),
4169 {BootTimestamp::epoch(),
4170 BootTimestamp::epoch() - chrono::milliseconds(100),
4171 BootTimestamp::epoch() - chrono::milliseconds(300)});
4172 }
4173
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004174 // We want to setup a situation such that 2 of the 3 legs of the loop are
4175 // very confident about time being X, and the third leg is pulling the
4176 // average off to one side.
Naman Guptaa63aa132023-03-22 20:06:34 -07004177 //
4178 // It's easiest to visualize this in timestamp_plotter.
4179
4180 std::vector<std::string> filenames;
4181 {
4182 // Have pi1 send out a reliable message at startup. This sets up a long
4183 // forwarding time message at the start to bias time.
4184 std::unique_ptr<EventLoop> pi1_event_loop = pi1->MakeEventLoop("ping");
4185 {
4186 aos::Sender<examples::Ping> ping_sender =
4187 pi1_event_loop->MakeSender<examples::Ping>("/reliable");
4188
4189 aos::Sender<examples::Ping>::Builder builder = ping_sender.MakeBuilder();
4190 examples::Ping::Builder ping_builder =
4191 builder.MakeBuilder<examples::Ping>();
4192 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
4193 }
4194
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004195 // Wait a while so there's enough data to let the worst case be rather
4196 // off.
Naman Guptaa63aa132023-03-22 20:06:34 -07004197 event_loop_factory.RunFor(chrono::seconds(1000));
4198
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004199 // Now start a receiving node first. This sets up 2 tight bounds between
4200 // 2 of the nodes.
Naman Guptaa63aa132023-03-22 20:06:34 -07004201 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004202 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4203 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004204 pi2_logger.StartLogger(kLogfile2_1);
4205
4206 event_loop_factory.RunFor(chrono::seconds(100));
4207
4208 // And now start the third leg.
4209 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004210 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4211 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004212 pi3_logger.StartLogger(kLogfile3_1);
4213
4214 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004215 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4216 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004217 pi1_logger.StartLogger(kLogfile1_1);
4218
4219 event_loop_factory.RunFor(chrono::seconds(100));
4220
4221 pi1_logger.AppendAllFilenames(&filenames);
4222 pi2_logger.AppendAllFilenames(&filenames);
4223 pi3_logger.AppendAllFilenames(&filenames);
4224 }
4225
4226 // Make sure we can read this.
4227 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004228 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004229 auto result = ConfirmReadable(filenames);
4230}
4231
Austin Schuh08dba8f2023-05-01 08:29:30 -07004232// Tests that RestartLogging works in the simple case. Unfortunately, the
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004233// failure cases involve simulating time elapsing in callbacks, which is
4234// really hard. The best we can reasonably do is make sure 2 back to back
4235// logs are parseable together.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004236TEST_P(MultinodeLoggerTest, RestartLogging) {
4237 time_converter_.AddMonotonic(
4238 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4239 std::vector<std::string> filenames;
4240 {
4241 LoggerState pi1_logger = MakeLogger(pi1_);
4242
4243 event_loop_factory_.RunFor(chrono::milliseconds(95));
4244
4245 StartLogger(&pi1_logger, logfile_base1_);
4246 aos::monotonic_clock::time_point last_rotation_time =
4247 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07004248 pi1_logger.logger->set_on_logged_period(
4249 [&](aos::monotonic_clock::time_point) {
4250 const auto now = pi1_logger.event_loop->monotonic_now();
4251 if (now > last_rotation_time + std::chrono::seconds(5)) {
4252 pi1_logger.AppendAllFilenames(&filenames);
4253 std::unique_ptr<MultiNodeFilesLogNamer> namer =
4254 pi1_logger.MakeLogNamer(logfile_base2_);
4255 pi1_logger.log_namer = namer.get();
Austin Schuh08dba8f2023-05-01 08:29:30 -07004256
Austin Schuh2f864452023-07-17 14:53:08 -07004257 pi1_logger.logger->RestartLogging(std::move(namer));
4258 last_rotation_time = now;
4259 }
4260 });
Austin Schuh08dba8f2023-05-01 08:29:30 -07004261
4262 event_loop_factory_.RunFor(chrono::milliseconds(7000));
4263
4264 pi1_logger.AppendAllFilenames(&filenames);
4265 }
4266
4267 for (const auto &x : filenames) {
4268 LOG(INFO) << x;
4269 }
4270
4271 EXPECT_GE(filenames.size(), 2u);
4272
4273 ConfirmReadable(filenames);
4274
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004275 // TODO(austin): It would be good to confirm that any one time messages end
4276 // up in both logs correctly.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004277}
4278
Austin Schuh6e93fc22023-08-22 21:27:22 -07004279// Tests that we call OnEnd without --skip_missing_forwarding_entries.
4280TEST_P(MultinodeLoggerTest, SkipMissingForwardingEntries) {
4281 if (file_strategy() == FileStrategy::kCombine) {
4282 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
4283 }
4284 time_converter_.AddMonotonic(
4285 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4286
4287 std::vector<std::string> filenames;
4288 {
4289 LoggerState pi1_logger = MakeLogger(pi1_);
4290
4291 event_loop_factory_.RunFor(chrono::milliseconds(95));
4292
4293 StartLogger(&pi1_logger);
4294 aos::monotonic_clock::time_point last_rotation_time =
4295 pi1_logger.event_loop->monotonic_now();
4296 pi1_logger.logger->set_on_logged_period(
4297 [&](aos::monotonic_clock::time_point) {
4298 const auto now = pi1_logger.event_loop->monotonic_now();
4299 if (now > last_rotation_time + std::chrono::seconds(5)) {
4300 pi1_logger.logger->Rotate();
4301 last_rotation_time = now;
4302 }
4303 });
4304
4305 event_loop_factory_.RunFor(chrono::milliseconds(15000));
4306 pi1_logger.AppendAllFilenames(&filenames);
4307 }
4308
4309 // If we remove the last remote data part, we'll trigger missing data for
4310 // timestamps.
4311 filenames.erase(std::remove_if(filenames.begin(), filenames.end(),
4312 [](const std::string &s) {
4313 return s.find("data/pi2_data.part3.bfbs") !=
4314 std::string::npos;
4315 }),
4316 filenames.end());
4317
4318 auto result = ConfirmReadable(filenames);
4319}
4320
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004321// Tests that when we have evidence of 2 boots, and then start logging, the
4322// max_out_of_order_duration ends up reasonable on the boot with the start time.
4323TEST(MultinodeLoggerLoopTest, PreviousBootData) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004324 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4325 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4326
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004327 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4328 aos::configuration::ReadConfig(ArtifactPath(
4329 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4330 message_bridge::TestingTimeConverter time_converter(
4331 configuration::NodesCount(&config.message()));
4332 SimulatedEventLoopFactory event_loop_factory(&config.message());
4333 event_loop_factory.SetTimeConverter(&time_converter);
4334
4335 const UUID pi1_boot0 = UUID::Random();
4336 const UUID pi2_boot0 = UUID::Random();
4337 const UUID pi2_boot1 = UUID::Random();
4338
4339 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004340 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004341
4342 {
4343 constexpr size_t kPi1Index = 0;
4344 constexpr size_t kPi2Index = 1;
4345 time_converter.set_boot_uuid(kPi1Index, 0, pi1_boot0);
4346 time_converter.set_boot_uuid(kPi2Index, 0, pi2_boot0);
4347 time_converter.set_boot_uuid(kPi2Index, 1, pi2_boot1);
4348
4349 // Make pi1 boot before everything else.
4350 time_converter.AddNextTimestamp(
4351 distributed_clock::epoch(),
4352 {BootTimestamp::epoch(),
4353 BootTimestamp::epoch() - chrono::milliseconds(100)});
4354
4355 const chrono::nanoseconds reboot_time = chrono::seconds(1005);
4356 time_converter.AddNextTimestamp(
4357 distributed_clock::epoch() + reboot_time,
4358 {BootTimestamp::epoch() + reboot_time,
4359 BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()}});
4360 }
4361
4362 NodeEventLoopFactory *const pi1 =
4363 event_loop_factory.GetNodeEventLoopFactory("pi1");
4364 NodeEventLoopFactory *const pi2 =
4365 event_loop_factory.GetNodeEventLoopFactory("pi2");
4366
4367 // What we want is for pi2 to send a message at t=1000 on the first channel
4368 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4369 // the max out of order duration be large.
4370 //
4371 // Then, we reboot, and only send messages on a third channel (/atest2 pong).
4372 // The order is key, they need to sort in this order in the config.
4373
4374 std::vector<std::string> filenames;
4375 {
4376 {
4377 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4378 aos::Sender<examples::Pong> pong_sender =
4379 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4380
4381 pi2_event_loop->OnRun([&]() {
4382 aos::Sender<examples::Pong>::Builder builder =
4383 pong_sender.MakeBuilder();
4384 examples::Pong::Builder pong_builder =
4385 builder.MakeBuilder<examples::Pong>();
4386 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4387 });
4388
4389 event_loop_factory.RunFor(chrono::seconds(1000));
4390 }
4391
4392 {
4393 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4394 aos::Sender<examples::Pong> pong_sender =
4395 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4396
4397 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4398 examples::Pong::Builder pong_builder =
4399 builder.MakeBuilder<examples::Pong>();
4400 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4401 }
4402
4403 event_loop_factory.RunFor(chrono::seconds(10));
4404
4405 // Now start a receiving node first. This sets up 2 tight bounds between
4406 // 2 of the nodes.
4407 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004408 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4409 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004410 pi1_logger.StartLogger(kLogfile1_1);
4411
4412 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4413 aos::Sender<examples::Pong> pong_sender =
4414 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4415
4416 pi2_event_loop->AddPhasedLoop(
4417 [&pong_sender](int) {
4418 aos::Sender<examples::Pong>::Builder builder =
4419 pong_sender.MakeBuilder();
4420 examples::Pong::Builder pong_builder =
4421 builder.MakeBuilder<examples::Pong>();
4422 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4423 },
4424 chrono::milliseconds(10));
4425
4426 event_loop_factory.RunFor(chrono::seconds(100));
4427
4428 pi1_logger.AppendAllFilenames(&filenames);
4429 }
4430
4431 // Make sure we can read this.
4432 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4433 EXPECT_TRUE(AllRebootPartsMatchOutOfOrderDuration(sorted_parts, "pi2"));
4434 auto result = ConfirmReadable(filenames);
4435}
4436
4437// Tests that when we start without a connection, and then start logging, the
4438// max_out_of_order_duration ends up reasonable.
4439TEST(MultinodeLoggerLoopTest, StartDisconnected) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004440 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4441 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4442
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004443 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4444 aos::configuration::ReadConfig(ArtifactPath(
4445 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4446 message_bridge::TestingTimeConverter time_converter(
4447 configuration::NodesCount(&config.message()));
4448 SimulatedEventLoopFactory event_loop_factory(&config.message());
4449 event_loop_factory.SetTimeConverter(&time_converter);
4450
4451 time_converter.StartEqual();
4452
4453 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004454 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004455
4456 NodeEventLoopFactory *const pi1 =
4457 event_loop_factory.GetNodeEventLoopFactory("pi1");
4458 NodeEventLoopFactory *const pi2 =
4459 event_loop_factory.GetNodeEventLoopFactory("pi2");
4460
4461 // What we want is for pi2 to send a message at t=1000 on the first channel
4462 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4463 // the max out of order duration be large.
4464 //
4465 // Then, we disconnect, and only send messages on a third channel
4466 // (/atest2 pong). The order is key, they need to sort in this order in the
4467 // config so we observe them in the order which grows the
4468 // max_out_of_order_duration.
4469
4470 std::vector<std::string> filenames;
4471 {
4472 {
4473 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4474 aos::Sender<examples::Pong> pong_sender =
4475 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4476
4477 pi2_event_loop->OnRun([&]() {
4478 aos::Sender<examples::Pong>::Builder builder =
4479 pong_sender.MakeBuilder();
4480 examples::Pong::Builder pong_builder =
4481 builder.MakeBuilder<examples::Pong>();
4482 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4483 });
4484
4485 event_loop_factory.RunFor(chrono::seconds(1000));
4486 }
4487
4488 {
4489 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4490 aos::Sender<examples::Pong> pong_sender =
4491 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4492
4493 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4494 examples::Pong::Builder pong_builder =
4495 builder.MakeBuilder<examples::Pong>();
4496 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4497 }
4498
4499 event_loop_factory.RunFor(chrono::seconds(10));
4500
4501 pi1->Disconnect(pi2->node());
4502 pi2->Disconnect(pi1->node());
4503
4504 // Make data flow.
4505 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4506 aos::Sender<examples::Pong> pong_sender =
4507 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4508
4509 pi2_event_loop->AddPhasedLoop(
4510 [&pong_sender](int) {
4511 aos::Sender<examples::Pong>::Builder builder =
4512 pong_sender.MakeBuilder();
4513 examples::Pong::Builder pong_builder =
4514 builder.MakeBuilder<examples::Pong>();
4515 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4516 },
4517 chrono::milliseconds(10));
4518
4519 event_loop_factory.RunFor(chrono::seconds(10));
4520
4521 // Now start a receiving node first. This sets up 2 tight bounds between
4522 // 2 of the nodes.
4523 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004524 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4525 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004526 pi1_logger.StartLogger(kLogfile1_1);
4527
4528 event_loop_factory.RunFor(chrono::seconds(10));
4529
4530 // Now, reconnect, and everything should recover.
4531 pi1->Connect(pi2->node());
4532 pi2->Connect(pi1->node());
4533
4534 event_loop_factory.RunFor(chrono::seconds(10));
4535
4536 pi1_logger.AppendAllFilenames(&filenames);
4537 }
4538
4539 // Make sure we can read this.
4540 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4541 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4542 auto result = ConfirmReadable(filenames);
4543}
4544
Austin Schuh1124c512023-08-01 15:20:44 -07004545// Class to spam Pong messages blindly.
4546class PongSender {
4547 public:
4548 PongSender(EventLoop *loop, std::string_view channel_name)
4549 : sender_(loop->MakeSender<examples::Pong>(channel_name)) {
4550 loop->AddPhasedLoop(
4551 [this](int) {
4552 aos::Sender<examples::Pong>::Builder builder = sender_.MakeBuilder();
4553 examples::Pong::Builder pong_builder =
4554 builder.MakeBuilder<examples::Pong>();
4555 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4556 },
4557 chrono::milliseconds(10));
4558 }
4559
4560 private:
4561 aos::Sender<examples::Pong> sender_;
4562};
4563
4564// Tests that we log correctly as nodes connect slowly.
4565TEST(MultinodeLoggerLoopTest, StaggeredConnect) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004566 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4567 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4568
Austin Schuh1124c512023-08-01 15:20:44 -07004569 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4570 aos::configuration::ReadConfig(ArtifactPath(
4571 "aos/events/logging/multinode_pingpong_pi3_pingpong_config.json"));
4572 message_bridge::TestingTimeConverter time_converter(
4573 configuration::NodesCount(&config.message()));
4574 SimulatedEventLoopFactory event_loop_factory(&config.message());
4575 event_loop_factory.SetTimeConverter(&time_converter);
4576
4577 time_converter.StartEqual();
4578
4579 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004580 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Austin Schuh1124c512023-08-01 15:20:44 -07004581
4582 NodeEventLoopFactory *const pi1 =
4583 event_loop_factory.GetNodeEventLoopFactory("pi1");
4584 NodeEventLoopFactory *const pi2 =
4585 event_loop_factory.GetNodeEventLoopFactory("pi2");
4586 NodeEventLoopFactory *const pi3 =
4587 event_loop_factory.GetNodeEventLoopFactory("pi3");
4588
4589 // What we want is for pi2 to send a message at t=1000 on the first channel
4590 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4591 // the max out of order duration be large.
4592 //
4593 // Then, we disconnect, and only send messages on a third channel
4594 // (/atest2 pong). The order is key, they need to sort in this order in the
4595 // config so we observe them in the order which grows the
4596 // max_out_of_order_duration.
4597
4598 pi1->Disconnect(pi2->node());
4599 pi2->Disconnect(pi1->node());
4600
4601 pi1->Disconnect(pi3->node());
4602 pi3->Disconnect(pi1->node());
4603
4604 std::vector<std::string> filenames;
4605 pi2->AlwaysStart<PongSender>("pongsender", "/test2");
4606 pi3->AlwaysStart<PongSender>("pongsender", "/test3");
4607
4608 event_loop_factory.RunFor(chrono::seconds(10));
4609
4610 {
4611 // Now start a receiving node first. This sets up 2 tight bounds between
4612 // 2 of the nodes.
4613 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004614 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4615 FileStrategy::kKeepSeparate);
Austin Schuh1124c512023-08-01 15:20:44 -07004616 pi1_logger.StartLogger(kLogfile1_1);
4617
4618 event_loop_factory.RunFor(chrono::seconds(10));
4619
4620 // Now, reconnect, and everything should recover.
4621 pi1->Connect(pi2->node());
4622 pi2->Connect(pi1->node());
4623
4624 event_loop_factory.RunFor(chrono::seconds(10));
4625
4626 pi1->Connect(pi3->node());
4627 pi3->Connect(pi1->node());
4628
4629 event_loop_factory.RunFor(chrono::seconds(10));
4630
4631 pi1_logger.AppendAllFilenames(&filenames);
4632 }
4633
4634 // Make sure we can read this.
4635 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4636 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4637 auto result = ConfirmReadable(filenames);
4638}
4639
Naman Guptaa63aa132023-03-22 20:06:34 -07004640} // namespace testing
4641} // namespace logger
4642} // namespace aos