blob: 5dddc6052d1787797abc5796c2dd5dd01d4f6159 [file] [log] [blame]
Brian Smartte67d7112023-03-20 12:06:30 -07001#include <algorithm>
2
Philipp Schrader790cb542023-07-05 21:06:52 -07003#include "gmock/gmock.h"
4#include "gtest/gtest.h"
5
Naman Guptaa63aa132023-03-22 20:06:34 -07006#include "aos/events/logging/log_reader.h"
7#include "aos/events/logging/multinode_logger_test_lib.h"
8#include "aos/events/message_counter.h"
9#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/network/remote_message_generated.h"
12#include "aos/network/timestamp_generated.h"
13#include "aos/testing/tmpdir.h"
Naman Guptaa63aa132023-03-22 20:06:34 -070014
Stephan Pleinesf63bde82024-01-13 15:59:33 -080015namespace aos::logger::testing {
Naman Guptaa63aa132023-03-22 20:06:34 -070016
17namespace chrono = std::chrono;
18using aos::message_bridge::RemoteMessage;
19using aos::testing::ArtifactPath;
20using aos::testing::MessageCounter;
21
Naman Guptaa63aa132023-03-22 20:06:34 -070022INSTANTIATE_TEST_SUITE_P(
23 All, MultinodeLoggerTest,
24 ::testing::Combine(
25 ::testing::Values(
26 ConfigParams{"multinode_pingpong_combined_config.json", true,
Austin Schuh6ecfe902023-08-04 22:44:37 -070027 kCombinedConfigSha1(), kCombinedConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070028 FileStrategy::kKeepSeparate,
29 ForceTimestampBuffering::kForceBufferTimestamps},
30 ConfigParams{"multinode_pingpong_combined_config.json", true,
31 kCombinedConfigSha1(), kCombinedConfigSha1(),
32 FileStrategy::kKeepSeparate,
33 ForceTimestampBuffering::kAutoBuffer},
Naman Guptaa63aa132023-03-22 20:06:34 -070034 ConfigParams{"multinode_pingpong_split_config.json", false,
Austin Schuh6ecfe902023-08-04 22:44:37 -070035 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070036 FileStrategy::kKeepSeparate,
37 ForceTimestampBuffering::kForceBufferTimestamps},
Austin Schuh6ecfe902023-08-04 22:44:37 -070038 ConfigParams{"multinode_pingpong_split_config.json", false,
39 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070040 FileStrategy::kKeepSeparate,
41 ForceTimestampBuffering::kAutoBuffer},
42 ConfigParams{"multinode_pingpong_split_config.json", false,
43 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
44 FileStrategy::kCombine,
45 ForceTimestampBuffering::kForceBufferTimestamps},
46 ConfigParams{"multinode_pingpong_split_config.json", false,
47 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
48 FileStrategy::kCombine,
49 ForceTimestampBuffering::kAutoBuffer}),
Naman Guptaa63aa132023-03-22 20:06:34 -070050 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
51
52INSTANTIATE_TEST_SUITE_P(
53 All, MultinodeLoggerDeathTest,
54 ::testing::Combine(
55 ::testing::Values(
56 ConfigParams{"multinode_pingpong_combined_config.json", true,
Austin Schuh6ecfe902023-08-04 22:44:37 -070057 kCombinedConfigSha1(), kCombinedConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070058 FileStrategy::kKeepSeparate,
59 ForceTimestampBuffering::kForceBufferTimestamps},
60 ConfigParams{"multinode_pingpong_combined_config.json", true,
61 kCombinedConfigSha1(), kCombinedConfigSha1(),
62 FileStrategy::kKeepSeparate,
63 ForceTimestampBuffering::kAutoBuffer},
Naman Guptaa63aa132023-03-22 20:06:34 -070064 ConfigParams{"multinode_pingpong_split_config.json", false,
Austin Schuh6ecfe902023-08-04 22:44:37 -070065 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070066 FileStrategy::kKeepSeparate,
67 ForceTimestampBuffering::kForceBufferTimestamps},
Austin Schuh6ecfe902023-08-04 22:44:37 -070068 ConfigParams{"multinode_pingpong_split_config.json", false,
69 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
Austin Schuh63097262023-08-16 17:04:29 -070070 FileStrategy::kKeepSeparate,
71 ForceTimestampBuffering::kAutoBuffer},
72 ConfigParams{"multinode_pingpong_split_config.json", false,
73 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
74 FileStrategy::kCombine,
75 ForceTimestampBuffering::kForceBufferTimestamps},
76 ConfigParams{"multinode_pingpong_split_config.json", false,
77 kSplitConfigSha1(), kReloggedSplitConfigSha1(),
78 FileStrategy::kCombine,
79 ForceTimestampBuffering::kAutoBuffer}),
Naman Guptaa63aa132023-03-22 20:06:34 -070080 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
81
Austin Schuh633858f2024-03-22 14:34:19 -070082// Class to spam Pong messages blindly.
83class PongSender {
84 public:
85 PongSender(EventLoop *loop, std::string_view channel_name)
86 : sender_(loop->MakeSender<examples::Pong>(channel_name)) {
87 loop->AddPhasedLoop(
88 [this](int) {
89 aos::Sender<examples::Pong>::Builder builder = sender_.MakeBuilder();
90 examples::Pong::Builder pong_builder =
91 builder.MakeBuilder<examples::Pong>();
92 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
93 },
94 chrono::milliseconds(10));
95 }
96
97 private:
98 aos::Sender<examples::Pong> sender_;
99};
100
101// Class to spam Ping messages blindly.
102class PingSender {
103 public:
104 PingSender(EventLoop *loop, std::string_view channel_name)
105 : sender_(loop->MakeSender<examples::Ping>(channel_name)) {
106 loop->AddPhasedLoop(
107 [this](int) {
108 aos::Sender<examples::Ping>::Builder builder = sender_.MakeBuilder();
109 examples::Ping::Builder ping_builder =
110 builder.MakeBuilder<examples::Ping>();
111 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
112 },
113 chrono::milliseconds(10));
114 }
115
116 private:
117 aos::Sender<examples::Ping> sender_;
118};
119
Naman Guptaa63aa132023-03-22 20:06:34 -0700120// Tests that we can write and read simple multi-node log files.
121TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh6ecfe902023-08-04 22:44:37 -0700122 if (file_strategy() == FileStrategy::kCombine) {
123 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
124 }
125
Naman Guptaa63aa132023-03-22 20:06:34 -0700126 std::vector<std::string> actual_filenames;
127 time_converter_.StartEqual();
128
129 {
130 LoggerState pi1_logger = MakeLogger(pi1_);
131 LoggerState pi2_logger = MakeLogger(pi2_);
132
133 event_loop_factory_.RunFor(chrono::milliseconds(95));
134
135 StartLogger(&pi1_logger);
136 StartLogger(&pi2_logger);
137
138 event_loop_factory_.RunFor(chrono::milliseconds(20000));
139 pi1_logger.AppendAllFilenames(&actual_filenames);
140 pi2_logger.AppendAllFilenames(&actual_filenames);
141 }
142
143 ASSERT_THAT(actual_filenames,
144 ::testing::UnorderedElementsAreArray(logfiles_));
145
146 {
147 std::set<std::string> logfile_uuids;
148 std::set<std::string> parts_uuids;
149 // Confirm that we have the expected number of UUIDs for both the logfile
150 // UUIDs and parts UUIDs.
151 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
152 for (std::string_view f : logfiles_) {
153 log_header.emplace_back(ReadHeader(f).value());
154 if (!log_header.back().message().has_configuration()) {
155 logfile_uuids.insert(
156 log_header.back().message().log_event_uuid()->str());
157 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
158 }
159 }
160
161 EXPECT_EQ(logfile_uuids.size(), 2u);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700162 EXPECT_EQ(parts_uuids.size(), 8u);
Naman Guptaa63aa132023-03-22 20:06:34 -0700163
164 // And confirm everything is on the correct node.
165 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
166 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
167 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
168
169 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
170 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700171 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700172
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700173 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
174 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Naman Guptaa63aa132023-03-22 20:06:34 -0700175
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700176 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
177 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700178
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700179 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
180 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
181 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
Naman Guptaa63aa132023-03-22 20:06:34 -0700182
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700183 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
184 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
Naman Guptaa63aa132023-03-22 20:06:34 -0700185
186 // And the parts index matches.
187 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700188
189 EXPECT_EQ(log_header[3].message().parts_index(), 0);
190 EXPECT_EQ(log_header[4].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700191
192 EXPECT_EQ(log_header[5].message().parts_index(), 0);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700193
194 EXPECT_EQ(log_header[6].message().parts_index(), 0);
195 EXPECT_EQ(log_header[7].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700196
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700197 EXPECT_EQ(log_header[8].message().parts_index(), 0);
198 EXPECT_EQ(log_header[9].message().parts_index(), 1);
Naman Guptaa63aa132023-03-22 20:06:34 -0700199
200 EXPECT_EQ(log_header[10].message().parts_index(), 0);
201 EXPECT_EQ(log_header[11].message().parts_index(), 1);
202
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700203 EXPECT_EQ(log_header[12].message().parts_index(), 0);
204 EXPECT_EQ(log_header[13].message().parts_index(), 1);
205 EXPECT_EQ(log_header[14].message().parts_index(), 2);
Naman Guptaa63aa132023-03-22 20:06:34 -0700206
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700207 EXPECT_EQ(log_header[15].message().parts_index(), 0);
208 EXPECT_EQ(log_header[16].message().parts_index(), 1);
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700209
210 // And that the data_stored field is right.
211 EXPECT_THAT(*log_header[2].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700212 ::testing::ElementsAre(StoredDataType::DATA));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700213 EXPECT_THAT(*log_header[3].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700214 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700215 EXPECT_THAT(*log_header[4].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700216 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700217
218 EXPECT_THAT(*log_header[5].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700219 ::testing::ElementsAre(StoredDataType::DATA));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700220 EXPECT_THAT(*log_header[6].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700221 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700222 EXPECT_THAT(*log_header[7].message().data_stored(),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700223 ::testing::ElementsAre(StoredDataType::TIMESTAMPS));
Mithun Bharadwaja5f9d482023-08-02 16:10:40 -0700224
225 EXPECT_THAT(*log_header[8].message().data_stored(),
226 ::testing::ElementsAre(StoredDataType::DATA));
227 EXPECT_THAT(*log_header[9].message().data_stored(),
228 ::testing::ElementsAre(StoredDataType::DATA));
229
230 EXPECT_THAT(*log_header[10].message().data_stored(),
231 ::testing::ElementsAre(StoredDataType::DATA));
232 EXPECT_THAT(*log_header[11].message().data_stored(),
233 ::testing::ElementsAre(StoredDataType::DATA));
234
235 EXPECT_THAT(*log_header[12].message().data_stored(),
236 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
237 EXPECT_THAT(*log_header[13].message().data_stored(),
238 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
239 EXPECT_THAT(*log_header[14].message().data_stored(),
240 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
241
242 EXPECT_THAT(*log_header[15].message().data_stored(),
243 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
244 EXPECT_THAT(*log_header[16].message().data_stored(),
245 ::testing::ElementsAre(StoredDataType::REMOTE_TIMESTAMPS));
Naman Guptaa63aa132023-03-22 20:06:34 -0700246 }
247
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700248 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
249 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -0700250 {
251 using ::testing::UnorderedElementsAre;
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700252 std::shared_ptr<const aos::Configuration> config = sorted_parts[0].config;
Naman Guptaa63aa132023-03-22 20:06:34 -0700253
254 // Timing reports, pings
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700255 if (shared()) {
256 EXPECT_THAT(
257 CountChannelsData(config, logfiles_[2]),
258 UnorderedElementsAre(
259 std::make_tuple("/pi1/aos", "aos.examples.Ping", 2001),
260 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
261 200),
262 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
263 21),
264 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
265 std::make_tuple("/pi1/aos", "aos.timing.Report", 60),
266 std::make_tuple("/test", "aos.examples.Ping", 2001)))
267 << " : " << logfiles_[2];
268 } else {
269 EXPECT_THAT(
270 CountChannelsData(config, logfiles_[2]),
271 UnorderedElementsAre(
272 std::make_tuple("/pi1/aos", "aos.examples.Ping", 2001),
273 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
274 200),
275 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
276 21),
277 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
278 std::make_tuple("/pi1/aos", "aos.timing.Report", 60),
279 std::make_tuple("/test", "aos.examples.Ping", 2001),
280 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
281 "aos-message_bridge-Timestamp",
282 "aos.message_bridge.RemoteMessage", 200)))
283 << " : " << logfiles_[2];
Naman Guptaa63aa132023-03-22 20:06:34 -0700284 }
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700285
286 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
287 ::testing::UnorderedElementsAre())
288 << " : " << logfiles_[3];
289 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
290 ::testing::UnorderedElementsAre())
291 << " : " << logfiles_[4];
292
Naman Guptaa63aa132023-03-22 20:06:34 -0700293 // Timestamps for pong
294 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
295 UnorderedElementsAre())
296 << " : " << logfiles_[2];
297 EXPECT_THAT(
298 CountChannelsTimestamp(config, logfiles_[3]),
299 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
300 << " : " << logfiles_[3];
301 EXPECT_THAT(
302 CountChannelsTimestamp(config, logfiles_[4]),
303 UnorderedElementsAre(
304 std::make_tuple("/test", "aos.examples.Pong", 2000),
305 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
306 << " : " << logfiles_[4];
307
Naman Guptaa63aa132023-03-22 20:06:34 -0700308 // Timing reports and pongs.
Naman Guptaa63aa132023-03-22 20:06:34 -0700309 EXPECT_THAT(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700310 CountChannelsData(config, logfiles_[5]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700311 UnorderedElementsAre(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700312 std::make_tuple("/pi2/aos", "aos.examples.Ping", 2001),
Naman Guptaa63aa132023-03-22 20:06:34 -0700313 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
314 200),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700315 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
316 21),
317 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
Sanjay Narayanan5ec00232022-07-08 15:21:30 -0700318 std::make_tuple("/pi2/aos", "aos.timing.Report", 60),
Mithun Bharadwajc54aa022023-08-02 16:10:41 -0700319 std::make_tuple("/test", "aos.examples.Pong", 2001)))
320 << " : " << logfiles_[5];
321 EXPECT_THAT(CountChannelsData(config, logfiles_[6]), UnorderedElementsAre())
322 << " : " << logfiles_[6];
323 EXPECT_THAT(CountChannelsData(config, logfiles_[7]), UnorderedElementsAre())
Naman Guptaa63aa132023-03-22 20:06:34 -0700324 << " : " << logfiles_[7];
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700325 // And ping timestamps.
326 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
327 UnorderedElementsAre())
328 << " : " << logfiles_[5];
Naman Guptaa63aa132023-03-22 20:06:34 -0700329 EXPECT_THAT(
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700330 CountChannelsTimestamp(config, logfiles_[6]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700331 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700332 << " : " << logfiles_[6];
Naman Guptaa63aa132023-03-22 20:06:34 -0700333 EXPECT_THAT(
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700334 CountChannelsTimestamp(config, logfiles_[7]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700335 UnorderedElementsAre(
336 std::make_tuple("/test", "aos.examples.Ping", 2000),
337 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700338 << " : " << logfiles_[7];
Naman Guptaa63aa132023-03-22 20:06:34 -0700339
340 // And then test that the remotely logged timestamp data files only have
341 // timestamps in them.
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700342 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
343 UnorderedElementsAre())
344 << " : " << logfiles_[8];
345 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
346 UnorderedElementsAre())
347 << " : " << logfiles_[9];
Naman Guptaa63aa132023-03-22 20:06:34 -0700348 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
349 UnorderedElementsAre())
350 << " : " << logfiles_[10];
351 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
352 UnorderedElementsAre())
353 << " : " << logfiles_[11];
Naman Guptaa63aa132023-03-22 20:06:34 -0700354
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700355 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700356 UnorderedElementsAre(std::make_tuple(
357 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700358 << " : " << logfiles_[8];
359 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Naman Guptaa63aa132023-03-22 20:06:34 -0700360 UnorderedElementsAre(std::make_tuple(
361 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700362 << " : " << logfiles_[9];
Naman Guptaa63aa132023-03-22 20:06:34 -0700363
Mithun Bharadwaj0c629932023-08-02 16:10:40 -0700364 // Pong snd timestamp data.
365 EXPECT_THAT(
366 CountChannelsData(config, logfiles_[10]),
367 UnorderedElementsAre(
368 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 9),
369 std::make_tuple("/test", "aos.examples.Pong", 91)))
370 << " : " << logfiles_[10];
371 EXPECT_THAT(
372 CountChannelsData(config, logfiles_[11]),
373 UnorderedElementsAre(
374 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 191),
375 std::make_tuple("/test", "aos.examples.Pong", 1910)))
376 << " : " << logfiles_[11];
Naman Guptaa63aa132023-03-22 20:06:34 -0700377
378 // Timestamps from pi2 on pi1, and the other way.
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700379 // if (shared()) {
380 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
381 UnorderedElementsAre())
382 << " : " << logfiles_[12];
383 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
384 UnorderedElementsAre())
385 << " : " << logfiles_[13];
386 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
387 UnorderedElementsAre())
388 << " : " << logfiles_[14];
389 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
390 UnorderedElementsAre())
391 << " : " << logfiles_[15];
392 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
393 UnorderedElementsAre())
394 << " : " << logfiles_[16];
Naman Guptaa63aa132023-03-22 20:06:34 -0700395
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -0700396 EXPECT_THAT(
397 CountChannelsTimestamp(config, logfiles_[12]),
398 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
399 << " : " << logfiles_[12];
400 EXPECT_THAT(
401 CountChannelsTimestamp(config, logfiles_[13]),
402 UnorderedElementsAre(
403 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
404 std::make_tuple("/test", "aos.examples.Ping", 90)))
405 << " : " << logfiles_[13];
406 EXPECT_THAT(
407 CountChannelsTimestamp(config, logfiles_[14]),
408 UnorderedElementsAre(
409 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
410 std::make_tuple("/test", "aos.examples.Ping", 1910)))
411 << " : " << logfiles_[14];
412 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
413 UnorderedElementsAre(std::make_tuple(
414 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
415 << " : " << logfiles_[15];
416 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
417 UnorderedElementsAre(std::make_tuple(
418 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
419 << " : " << logfiles_[16];
Naman Guptaa63aa132023-03-22 20:06:34 -0700420 }
421
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700422 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -0700423
424 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
425 log_reader_factory.set_send_delay(chrono::microseconds(0));
426
427 // This sends out the fetched messages and advances time to the start of the
428 // log file.
429 reader.Register(&log_reader_factory);
430
431 const Node *pi1 =
432 configuration::GetNode(log_reader_factory.configuration(), "pi1");
433 const Node *pi2 =
434 configuration::GetNode(log_reader_factory.configuration(), "pi2");
435
436 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
437 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
438 LOG(INFO) << "now pi1 "
439 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
440 LOG(INFO) << "now pi2 "
441 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
442
443 EXPECT_THAT(reader.LoggedNodes(),
444 ::testing::ElementsAre(
445 configuration::GetNode(reader.logged_configuration(), pi1),
446 configuration::GetNode(reader.logged_configuration(), pi2)));
447
448 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
449
450 std::unique_ptr<EventLoop> pi1_event_loop =
451 log_reader_factory.MakeEventLoop("test", pi1);
452 std::unique_ptr<EventLoop> pi2_event_loop =
453 log_reader_factory.MakeEventLoop("test", pi2);
454
455 int pi1_ping_count = 10;
456 int pi2_ping_count = 10;
457 int pi1_pong_count = 10;
458 int pi2_pong_count = 10;
459
460 // Confirm that the ping value matches.
461 pi1_event_loop->MakeWatcher(
462 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
463 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
464 << pi1_event_loop->context().monotonic_remote_time << " -> "
465 << pi1_event_loop->context().monotonic_event_time;
466 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
467 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
468 pi1_ping_count * chrono::milliseconds(10) +
469 monotonic_clock::epoch());
470 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
471 pi1_ping_count * chrono::milliseconds(10) +
472 realtime_clock::epoch());
473 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
474 pi1_event_loop->context().monotonic_event_time);
475 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
476 pi1_event_loop->context().realtime_event_time);
477
478 ++pi1_ping_count;
479 });
480 pi2_event_loop->MakeWatcher(
481 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
482 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
483 << pi2_event_loop->context().monotonic_remote_time << " -> "
484 << pi2_event_loop->context().monotonic_event_time;
485 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
486
487 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
488 pi2_ping_count * chrono::milliseconds(10) +
489 monotonic_clock::epoch());
490 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
491 pi2_ping_count * chrono::milliseconds(10) +
492 realtime_clock::epoch());
Austin Schuhac6d89e2024-03-27 14:56:09 -0700493 // The message at the start of each second doesn't have wakeup latency
494 // since timing reports and server statistics wake us up already at that
495 // point in time.
496 chrono::nanoseconds offset = chrono::microseconds(150);
497 if (pi2_event_loop->context().monotonic_remote_time.time_since_epoch() %
498 chrono::seconds(1) ==
499 chrono::seconds(0)) {
500 offset = chrono::microseconds(100);
501 }
502 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time + offset,
Naman Guptaa63aa132023-03-22 20:06:34 -0700503 pi2_event_loop->context().monotonic_event_time);
Austin Schuhac6d89e2024-03-27 14:56:09 -0700504 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time + offset,
Naman Guptaa63aa132023-03-22 20:06:34 -0700505 pi2_event_loop->context().realtime_event_time);
506 ++pi2_ping_count;
507 });
508
509 constexpr ssize_t kQueueIndexOffset = -9;
510 // Confirm that the ping and pong counts both match, and the value also
511 // matches.
Austin Schuhac6d89e2024-03-27 14:56:09 -0700512 pi1_event_loop->MakeWatcher("/test", [&pi1_event_loop, &pi1_ping_count,
513 &pi1_pong_count](
514 const examples::Pong &pong) {
515 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
516 << pi1_event_loop->context().monotonic_remote_time << " -> "
517 << pi1_event_loop->context().monotonic_event_time;
Naman Guptaa63aa132023-03-22 20:06:34 -0700518
Austin Schuhac6d89e2024-03-27 14:56:09 -0700519 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
520 pi1_pong_count + kQueueIndexOffset);
Naman Guptaa63aa132023-03-22 20:06:34 -0700521
Austin Schuhac6d89e2024-03-27 14:56:09 -0700522 chrono::nanoseconds offset = chrono::microseconds(200);
523 if ((pi1_event_loop->context().monotonic_remote_time.time_since_epoch() -
524 chrono::microseconds(150)) %
525 chrono::seconds(1) ==
526 chrono::seconds(0)) {
527 offset = chrono::microseconds(150);
528 }
Naman Guptaa63aa132023-03-22 20:06:34 -0700529
Austin Schuhac6d89e2024-03-27 14:56:09 -0700530 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
531 offset + pi1_pong_count * chrono::milliseconds(10) +
532 monotonic_clock::epoch());
533 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
534 offset + pi1_pong_count * chrono::milliseconds(10) +
535 realtime_clock::epoch());
Naman Guptaa63aa132023-03-22 20:06:34 -0700536
Austin Schuhac6d89e2024-03-27 14:56:09 -0700537 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
538 chrono::microseconds(150),
539 pi1_event_loop->context().monotonic_event_time);
540 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
541 chrono::microseconds(150),
542 pi1_event_loop->context().realtime_event_time);
Naman Guptaa63aa132023-03-22 20:06:34 -0700543
Austin Schuhac6d89e2024-03-27 14:56:09 -0700544 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
545 ++pi1_pong_count;
546 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
547 });
548 pi2_event_loop->MakeWatcher("/test", [&pi2_event_loop, &pi2_ping_count,
549 &pi2_pong_count](
550 const examples::Pong &pong) {
551 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
552 << pi2_event_loop->context().monotonic_remote_time << " -> "
553 << pi2_event_loop->context().monotonic_event_time;
Naman Guptaa63aa132023-03-22 20:06:34 -0700554
Austin Schuhac6d89e2024-03-27 14:56:09 -0700555 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
556 pi2_pong_count + kQueueIndexOffset);
Naman Guptaa63aa132023-03-22 20:06:34 -0700557
Austin Schuhac6d89e2024-03-27 14:56:09 -0700558 chrono::nanoseconds offset = chrono::microseconds(200);
559 if ((pi2_event_loop->context().monotonic_remote_time.time_since_epoch() -
560 chrono::microseconds(150)) %
561 chrono::seconds(1) ==
562 chrono::seconds(0)) {
563 offset = chrono::microseconds(150);
564 }
565
566 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
567 offset + pi2_pong_count * chrono::milliseconds(10) +
568 monotonic_clock::epoch());
569 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
570 offset + pi2_pong_count * chrono::milliseconds(10) +
571 realtime_clock::epoch());
572
573 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
574 pi2_event_loop->context().monotonic_event_time);
575 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
576 pi2_event_loop->context().realtime_event_time);
577
578 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
579 ++pi2_pong_count;
580 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
581 });
Naman Guptaa63aa132023-03-22 20:06:34 -0700582
583 log_reader_factory.Run();
584 EXPECT_EQ(pi1_ping_count, 2010);
585 EXPECT_EQ(pi2_ping_count, 2010);
586 EXPECT_EQ(pi1_pong_count, 2010);
587 EXPECT_EQ(pi2_pong_count, 2010);
588
589 reader.Deregister();
590}
591
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600592// MultinodeLoggerTest that tests the mutate callback works across multiple
593// nodes with remapping
594TEST_P(MultinodeLoggerTest, MultiNodeRemapMutateCallback) {
595 time_converter_.StartEqual();
596 std::vector<std::string> actual_filenames;
597
598 {
599 LoggerState pi1_logger = MakeLogger(pi1_);
600 LoggerState pi2_logger = MakeLogger(pi2_);
601
602 event_loop_factory_.RunFor(chrono::milliseconds(95));
603
604 StartLogger(&pi1_logger);
605 StartLogger(&pi2_logger);
606
607 event_loop_factory_.RunFor(chrono::milliseconds(20000));
608 pi1_logger.AppendAllFilenames(&actual_filenames);
609 pi2_logger.AppendAllFilenames(&actual_filenames);
610 }
611
Austin Schuh8fb4b452023-08-04 17:02:27 -0700612 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700613 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600614
615 LogReader reader(sorted_parts, &config_.message());
616 // Remap just on pi1.
617 reader.RemapLoggedChannel<examples::Pong>(
618 "/test", configuration::GetNode(reader.configuration(), "pi1"));
619
620 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
621
622 int pong_count = 0;
623 // Adds a callback which mutates the value of the pong message before the
624 // message is sent which is the feature we are testing here
625 reader.AddBeforeSendCallback("/test",
626 [&pong_count](aos::examples::Pong *pong) {
627 pong->mutate_value(pong->value() + 1);
628 pong_count = pong->value();
629 });
630
631 // This sends out the fetched messages and advances time to the start of the
632 // log file.
633 reader.Register(&log_reader_factory);
634
635 const Node *pi1 =
636 configuration::GetNode(log_reader_factory.configuration(), "pi1");
637 const Node *pi2 =
638 configuration::GetNode(log_reader_factory.configuration(), "pi2");
639
640 EXPECT_THAT(reader.LoggedNodes(),
641 ::testing::ElementsAre(
642 configuration::GetNode(reader.logged_configuration(), pi1),
643 configuration::GetNode(reader.logged_configuration(), pi2)));
644
645 std::unique_ptr<EventLoop> pi1_event_loop =
646 log_reader_factory.MakeEventLoop("test", pi1);
647 std::unique_ptr<EventLoop> pi2_event_loop =
648 log_reader_factory.MakeEventLoop("test", pi2);
649
650 pi1_event_loop->MakeWatcher("/original/test",
651 [&pong_count](const examples::Pong &pong) {
652 EXPECT_EQ(pong_count, pong.value());
653 });
654
655 pi2_event_loop->MakeWatcher("/test",
656 [&pong_count](const examples::Pong &pong) {
657 EXPECT_EQ(pong_count, pong.value());
658 });
659
660 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
661 reader.Deregister();
662
663 EXPECT_EQ(pong_count, 2011);
664}
665
666// MultinodeLoggerTest that tests the mutate callback works across multiple
667// nodes
668TEST_P(MultinodeLoggerTest, MultiNodeMutateCallback) {
669 time_converter_.StartEqual();
670 std::vector<std::string> actual_filenames;
671
672 {
673 LoggerState pi1_logger = MakeLogger(pi1_);
674 LoggerState pi2_logger = MakeLogger(pi2_);
675
676 event_loop_factory_.RunFor(chrono::milliseconds(95));
677
678 StartLogger(&pi1_logger);
679 StartLogger(&pi2_logger);
680
681 event_loop_factory_.RunFor(chrono::milliseconds(20000));
682 pi1_logger.AppendAllFilenames(&actual_filenames);
683 pi2_logger.AppendAllFilenames(&actual_filenames);
684 }
685
Austin Schuh8fb4b452023-08-04 17:02:27 -0700686 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700687 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600688
689 LogReader reader(sorted_parts, &config_.message());
690
691 int pong_count = 0;
692 // Adds a callback which mutates the value of the pong message before the
693 // message is sent which is the feature we are testing here
694 reader.AddBeforeSendCallback("/test",
695 [&pong_count](aos::examples::Pong *pong) {
696 pong->mutate_value(pong->value() + 1);
697 pong_count = pong->value();
698 });
699
700 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
701
702 // This sends out the fetched messages and advances time to the start of the
703 // log file.
704 reader.Register(&log_reader_factory);
705
706 const Node *pi1 =
707 configuration::GetNode(log_reader_factory.configuration(), "pi1");
708 const Node *pi2 =
709 configuration::GetNode(log_reader_factory.configuration(), "pi2");
710
711 EXPECT_THAT(reader.LoggedNodes(),
712 ::testing::ElementsAre(
713 configuration::GetNode(reader.logged_configuration(), pi1),
714 configuration::GetNode(reader.logged_configuration(), pi2)));
715
716 std::unique_ptr<EventLoop> pi1_event_loop =
717 log_reader_factory.MakeEventLoop("test", pi1);
718 std::unique_ptr<EventLoop> pi2_event_loop =
719 log_reader_factory.MakeEventLoop("test", pi2);
720
721 pi1_event_loop->MakeWatcher("/test",
722 [&pong_count](const examples::Pong &pong) {
723 EXPECT_EQ(pong_count, pong.value());
724 });
725
726 pi2_event_loop->MakeWatcher("/test",
727 [&pong_count](const examples::Pong &pong) {
728 EXPECT_EQ(pong_count, pong.value());
729 });
730
731 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
732 reader.Deregister();
733
734 EXPECT_EQ(pong_count, 2011);
735}
736
737// Tests that the before send callback is only called from the sender node if it
738// is forwarded
739TEST_P(MultinodeLoggerTest, OnlyDoBeforeSendCallbackOnSenderNode) {
740 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700741
742 std::vector<std::string> filenames;
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600743 {
744 LoggerState pi1_logger = MakeLogger(pi1_);
745 LoggerState pi2_logger = MakeLogger(pi2_);
746
747 event_loop_factory_.RunFor(chrono::milliseconds(95));
748
749 StartLogger(&pi1_logger);
750 StartLogger(&pi2_logger);
751
752 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700753
754 pi1_logger.AppendAllFilenames(&filenames);
755 pi2_logger.AppendAllFilenames(&filenames);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600756 }
757
Austin Schuh8fb4b452023-08-04 17:02:27 -0700758 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700759 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
760 LogReader reader(sorted_parts);
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600761
762 int ping_count = 0;
763 // Adds a callback which mutates the value of the pong message before the
764 // message is sent which is the feature we are testing here
765 reader.AddBeforeSendCallback("/test",
766 [&ping_count](aos::examples::Ping *ping) {
767 ++ping_count;
768 ping->mutate_value(ping_count);
769 });
770
771 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
772 log_reader_factory.set_send_delay(chrono::microseconds(0));
773
774 reader.Register(&log_reader_factory);
775
776 const Node *pi1 =
777 configuration::GetNode(log_reader_factory.configuration(), "pi1");
778 const Node *pi2 =
779 configuration::GetNode(log_reader_factory.configuration(), "pi2");
780
781 std::unique_ptr<EventLoop> pi1_event_loop =
782 log_reader_factory.MakeEventLoop("test", pi1);
783 pi1_event_loop->SkipTimingReport();
784 std::unique_ptr<EventLoop> pi2_event_loop =
785 log_reader_factory.MakeEventLoop("test", pi2);
786 pi2_event_loop->SkipTimingReport();
787
788 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
789 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
790
791 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
792 pi1_ping_timestamp;
793 if (!shared()) {
794 pi1_ping_timestamp =
795 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
796 pi1_event_loop.get(),
797 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
798 }
799
800 log_reader_factory.Run();
801
802 EXPECT_EQ(pi1_ping.count(), 2000u);
803 EXPECT_EQ(pi2_ping.count(), 2000u);
804 // If the BeforeSendCallback is called on both nodes, then the ping count
805 // would be 4002 instead of 2001
806 EXPECT_EQ(ping_count, 2001u);
807 if (!shared()) {
808 EXPECT_EQ(pi1_ping_timestamp->count(), 2000u);
809 }
810
811 reader.Deregister();
812}
813
814// Tests that we do not allow adding callbacks after Register is called
815TEST_P(MultinodeLoggerDeathTest, AddCallbackAfterRegister) {
816 time_converter_.StartEqual();
817 std::vector<std::string> actual_filenames;
818
819 {
820 LoggerState pi1_logger = MakeLogger(pi1_);
821 LoggerState pi2_logger = MakeLogger(pi2_);
822
823 event_loop_factory_.RunFor(chrono::milliseconds(95));
824
825 StartLogger(&pi1_logger);
826 StartLogger(&pi2_logger);
827
828 event_loop_factory_.RunFor(chrono::milliseconds(20000));
829 pi1_logger.AppendAllFilenames(&actual_filenames);
830 pi2_logger.AppendAllFilenames(&actual_filenames);
831 }
832
Austin Schuh8fb4b452023-08-04 17:02:27 -0700833 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700834 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Eric Schmiedebergae00e732023-04-12 15:53:17 -0600835
836 LogReader reader(sorted_parts, &config_.message());
837 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
838 reader.Register(&log_reader_factory);
839 EXPECT_DEATH(
840 {
841 reader.AddBeforeSendCallback("/test", [](aos::examples::Pong *) {
842 LOG(FATAL) << "This should not be called";
843 });
844 },
845 "Cannot add callbacks after calling Register");
846 reader.Deregister();
847}
848
Naman Guptaa63aa132023-03-22 20:06:34 -0700849// Test that if we feed the replay with a mismatched node list that we die on
850// the LogReader constructor.
851TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
852 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -0700853
854 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -0700855 {
856 LoggerState pi1_logger = MakeLogger(pi1_);
857 LoggerState pi2_logger = MakeLogger(pi2_);
858
859 event_loop_factory_.RunFor(chrono::milliseconds(95));
860
861 StartLogger(&pi1_logger);
862 StartLogger(&pi2_logger);
863
864 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -0700865
866 pi1_logger.AppendAllFilenames(&filenames);
867 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -0700868 }
869
870 // Test that, if we add an additional node to the replay config that the
871 // logger complains about the mismatch in number of nodes.
872 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
873 configuration::MergeWithConfig(&config_.message(), R"({
874 "nodes": [
875 {
876 "name": "extra-node"
877 }
878 ]
879 }
880 )");
881
Austin Schuh8fb4b452023-08-04 17:02:27 -0700882 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700883 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -0700884 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
885 "Log file and replay config need to have matching nodes lists.");
886}
887
888// Tests that we can read log files where they don't start at the same monotonic
889// time.
890TEST_P(MultinodeLoggerTest, StaggeredStart) {
891 time_converter_.StartEqual();
892 std::vector<std::string> actual_filenames;
893
894 {
895 LoggerState pi1_logger = MakeLogger(pi1_);
896 LoggerState pi2_logger = MakeLogger(pi2_);
897
898 event_loop_factory_.RunFor(chrono::milliseconds(95));
899
900 StartLogger(&pi1_logger);
901
902 event_loop_factory_.RunFor(chrono::milliseconds(200));
903
904 StartLogger(&pi2_logger);
905
906 event_loop_factory_.RunFor(chrono::milliseconds(20000));
907 pi1_logger.AppendAllFilenames(&actual_filenames);
908 pi2_logger.AppendAllFilenames(&actual_filenames);
909 }
910
911 // Since we delay starting pi2, it already knows about all the timestamps so
912 // we don't end up with extra parts.
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -0700913 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
914 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
915 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -0700916
917 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
918 log_reader_factory.set_send_delay(chrono::microseconds(0));
919
920 // This sends out the fetched messages and advances time to the start of the
921 // log file.
922 reader.Register(&log_reader_factory);
923
924 const Node *pi1 =
925 configuration::GetNode(log_reader_factory.configuration(), "pi1");
926 const Node *pi2 =
927 configuration::GetNode(log_reader_factory.configuration(), "pi2");
928
929 EXPECT_THAT(reader.LoggedNodes(),
930 ::testing::ElementsAre(
931 configuration::GetNode(reader.logged_configuration(), pi1),
932 configuration::GetNode(reader.logged_configuration(), pi2)));
933
934 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
935
936 std::unique_ptr<EventLoop> pi1_event_loop =
937 log_reader_factory.MakeEventLoop("test", pi1);
938 std::unique_ptr<EventLoop> pi2_event_loop =
939 log_reader_factory.MakeEventLoop("test", pi2);
940
941 int pi1_ping_count = 30;
942 int pi2_ping_count = 30;
943 int pi1_pong_count = 30;
944 int pi2_pong_count = 30;
945
946 // Confirm that the ping value matches.
947 pi1_event_loop->MakeWatcher(
948 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
949 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
950 << pi1_event_loop->context().monotonic_remote_time << " -> "
951 << pi1_event_loop->context().monotonic_event_time;
952 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
953
954 ++pi1_ping_count;
955 });
956 pi2_event_loop->MakeWatcher(
957 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
958 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
959 << pi2_event_loop->context().monotonic_remote_time << " -> "
960 << pi2_event_loop->context().monotonic_event_time;
961 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
962
963 ++pi2_ping_count;
964 });
965
966 // Confirm that the ping and pong counts both match, and the value also
967 // matches.
968 pi1_event_loop->MakeWatcher(
969 "/test", [&pi1_event_loop, &pi1_ping_count,
970 &pi1_pong_count](const examples::Pong &pong) {
971 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
972 << pi1_event_loop->context().monotonic_remote_time << " -> "
973 << pi1_event_loop->context().monotonic_event_time;
974
975 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
976 ++pi1_pong_count;
977 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
978 });
979 pi2_event_loop->MakeWatcher(
980 "/test", [&pi2_event_loop, &pi2_ping_count,
981 &pi2_pong_count](const examples::Pong &pong) {
982 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
983 << pi2_event_loop->context().monotonic_remote_time << " -> "
984 << pi2_event_loop->context().monotonic_event_time;
985
986 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
987 ++pi2_pong_count;
988 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
989 });
990
991 log_reader_factory.Run();
992 EXPECT_EQ(pi1_ping_count, 2030);
993 EXPECT_EQ(pi2_ping_count, 2030);
994 EXPECT_EQ(pi1_pong_count, 2030);
995 EXPECT_EQ(pi2_pong_count, 2030);
996
997 reader.Deregister();
998}
999
1000// Tests that we can read log files where the monotonic clocks drift and don't
1001// match correctly. While we are here, also test that different ending times
1002// also is readable.
1003TEST_P(MultinodeLoggerTest, MismatchedClocks) {
1004 // TODO(austin): Negate...
1005 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1006
1007 time_converter_.AddMonotonic(
1008 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
1009 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1010 // skew to be 200 uS/s
1011 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1012 {chrono::milliseconds(95),
1013 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1014 // Run another 200 ms to have one logger start first.
1015 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1016 {chrono::milliseconds(200), chrono::milliseconds(200)});
1017 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1018 // go far enough to cause problems if this isn't accounted for.
1019 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1020 {chrono::milliseconds(20000),
1021 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1022 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1023 {chrono::milliseconds(40000),
1024 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1025 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1026 {chrono::milliseconds(400), chrono::milliseconds(400)});
1027
Austin Schuh8fb4b452023-08-04 17:02:27 -07001028 std::vector<std::string> actual_filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07001029 {
1030 LoggerState pi2_logger = MakeLogger(pi2_);
1031
1032 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1033 << pi2_->realtime_now() << " distributed "
1034 << pi2_->ToDistributedClock(pi2_->monotonic_now());
1035
1036 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1037 << pi2_->realtime_now() << " distributed "
1038 << pi2_->ToDistributedClock(pi2_->monotonic_now());
1039
1040 event_loop_factory_.RunFor(startup_sleep1);
1041
1042 StartLogger(&pi2_logger);
1043
1044 event_loop_factory_.RunFor(startup_sleep2);
1045
1046 {
1047 // Run pi1's logger for only part of the time.
1048 LoggerState pi1_logger = MakeLogger(pi1_);
1049
1050 StartLogger(&pi1_logger);
1051 event_loop_factory_.RunFor(logger_run1);
1052
1053 // Make sure we slewed time far enough so that the difference is greater
1054 // than the network delay. This confirms that if we sort incorrectly, it
1055 // would show in the results.
1056 EXPECT_LT(
1057 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1058 -event_loop_factory_.send_delay() -
1059 event_loop_factory_.network_delay());
1060
1061 event_loop_factory_.RunFor(logger_run2);
1062
1063 // And now check that we went far enough the other way to make sure we
1064 // cover both problems.
1065 EXPECT_GT(
1066 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
1067 event_loop_factory_.send_delay() +
1068 event_loop_factory_.network_delay());
Austin Schuh8fb4b452023-08-04 17:02:27 -07001069
1070 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001071 }
1072
1073 // And log a bit more on pi2.
1074 event_loop_factory_.RunFor(logger_run3);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001075
1076 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001077 }
1078
Austin Schuh8fb4b452023-08-04 17:02:27 -07001079 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001080 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1081 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001082
1083 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1084 log_reader_factory.set_send_delay(chrono::microseconds(0));
1085
1086 const Node *pi1 =
1087 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1088 const Node *pi2 =
1089 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1090
1091 // This sends out the fetched messages and advances time to the start of the
1092 // log file.
1093 reader.Register(&log_reader_factory);
1094
1095 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1096 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1097 LOG(INFO) << "now pi1 "
1098 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1099 LOG(INFO) << "now pi2 "
1100 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1101
1102 LOG(INFO) << "Done registering (pi1) "
1103 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1104 << " "
1105 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1106 LOG(INFO) << "Done registering (pi2) "
1107 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1108 << " "
1109 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1110
1111 EXPECT_THAT(reader.LoggedNodes(),
1112 ::testing::ElementsAre(
1113 configuration::GetNode(reader.logged_configuration(), pi1),
1114 configuration::GetNode(reader.logged_configuration(), pi2)));
1115
1116 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1117
1118 std::unique_ptr<EventLoop> pi1_event_loop =
1119 log_reader_factory.MakeEventLoop("test", pi1);
1120 std::unique_ptr<EventLoop> pi2_event_loop =
1121 log_reader_factory.MakeEventLoop("test", pi2);
1122
1123 int pi1_ping_count = 30;
1124 int pi2_ping_count = 30;
1125 int pi1_pong_count = 30;
1126 int pi2_pong_count = 30;
1127
1128 // Confirm that the ping value matches.
1129 pi1_event_loop->MakeWatcher(
1130 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1131 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1132 << pi1_event_loop->context().monotonic_remote_time << " -> "
1133 << pi1_event_loop->context().monotonic_event_time;
1134 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1135
1136 ++pi1_ping_count;
1137 });
1138 pi2_event_loop->MakeWatcher(
1139 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1140 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1141 << pi2_event_loop->context().monotonic_remote_time << " -> "
1142 << pi2_event_loop->context().monotonic_event_time;
1143 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1144
1145 ++pi2_ping_count;
1146 });
1147
1148 // Confirm that the ping and pong counts both match, and the value also
1149 // matches.
1150 pi1_event_loop->MakeWatcher(
1151 "/test", [&pi1_event_loop, &pi1_ping_count,
1152 &pi1_pong_count](const examples::Pong &pong) {
1153 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1154 << pi1_event_loop->context().monotonic_remote_time << " -> "
1155 << pi1_event_loop->context().monotonic_event_time;
1156
1157 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1158 ++pi1_pong_count;
1159 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1160 });
1161 pi2_event_loop->MakeWatcher(
1162 "/test", [&pi2_event_loop, &pi2_ping_count,
1163 &pi2_pong_count](const examples::Pong &pong) {
1164 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1165 << pi2_event_loop->context().monotonic_remote_time << " -> "
1166 << pi2_event_loop->context().monotonic_event_time;
1167
1168 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1169 ++pi2_pong_count;
1170 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1171 });
1172
1173 log_reader_factory.Run();
1174 EXPECT_EQ(pi1_ping_count, 6030);
1175 EXPECT_EQ(pi2_ping_count, 6030);
1176 EXPECT_EQ(pi1_pong_count, 6030);
1177 EXPECT_EQ(pi2_pong_count, 6030);
1178
1179 reader.Deregister();
1180}
1181
1182// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
1183TEST_P(MultinodeLoggerTest, SortParts) {
1184 time_converter_.StartEqual();
1185 // Make a bunch of parts.
1186 {
1187 LoggerState pi1_logger = MakeLogger(pi1_);
1188 LoggerState pi2_logger = MakeLogger(pi2_);
1189
1190 event_loop_factory_.RunFor(chrono::milliseconds(95));
1191
1192 StartLogger(&pi1_logger);
1193 StartLogger(&pi2_logger);
1194
1195 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1196 }
1197
1198 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1199 VerifyParts(sorted_parts);
1200}
1201
1202// Tests that we can sort a bunch of parts with an empty part. We should ignore
1203// it and remove it from the sorted list.
1204TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07001205 std::vector<std::string> actual_filenames;
1206
Naman Guptaa63aa132023-03-22 20:06:34 -07001207 time_converter_.StartEqual();
1208 // Make a bunch of parts.
1209 {
1210 LoggerState pi1_logger = MakeLogger(pi1_);
1211 LoggerState pi2_logger = MakeLogger(pi2_);
1212
1213 event_loop_factory_.RunFor(chrono::milliseconds(95));
1214
1215 StartLogger(&pi1_logger);
1216 StartLogger(&pi2_logger);
1217
1218 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001219 pi1_logger.AppendAllFilenames(&actual_filenames);
1220 pi2_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001221 }
1222
1223 // TODO(austin): Should we flip out if the file can't open?
1224 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
1225
1226 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
Austin Schuh8fb4b452023-08-04 17:02:27 -07001227 actual_filenames.emplace_back(kEmptyFile);
Naman Guptaa63aa132023-03-22 20:06:34 -07001228
Austin Schuh8fb4b452023-08-04 17:02:27 -07001229 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001230 VerifyParts(sorted_parts, {kEmptyFile});
1231}
1232
1233// Tests that we can sort a bunch of parts with the end missing off a
1234// file. We should use the part we can read.
1235TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07001236 if (file_strategy() == FileStrategy::kCombine) {
1237 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
1238 }
1239
Naman Guptaa63aa132023-03-22 20:06:34 -07001240 std::vector<std::string> actual_filenames;
1241 time_converter_.StartEqual();
1242 // Make a bunch of parts.
1243 {
1244 LoggerState pi1_logger = MakeLogger(pi1_);
1245 LoggerState pi2_logger = MakeLogger(pi2_);
1246
1247 event_loop_factory_.RunFor(chrono::milliseconds(95));
1248
1249 StartLogger(&pi1_logger);
1250 StartLogger(&pi2_logger);
1251
1252 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1253
1254 pi1_logger.AppendAllFilenames(&actual_filenames);
1255 pi2_logger.AppendAllFilenames(&actual_filenames);
1256 }
1257
1258 ASSERT_THAT(actual_filenames,
1259 ::testing::UnorderedElementsAreArray(logfiles_));
1260
1261 // Strip off the end of one of the files. Pick one with a lot of data.
1262 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1263 // that we don't corrupt the entire log part.
1264 ::std::string compressed_contents =
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001265 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Naman Guptaa63aa132023-03-22 20:06:34 -07001266
1267 aos::util::WriteStringToFileOrDie(
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07001268 logfiles_[2],
Naman Guptaa63aa132023-03-22 20:06:34 -07001269 compressed_contents.substr(0, compressed_contents.size() - 100));
1270
1271 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1272 VerifyParts(sorted_parts);
1273}
1274
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001275// Tests that if we remap a logged channel, it shows up correctly.
Naman Guptaa63aa132023-03-22 20:06:34 -07001276TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
1277 time_converter_.StartEqual();
Austin Schuh8fb4b452023-08-04 17:02:27 -07001278
1279 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07001280 {
1281 LoggerState pi1_logger = MakeLogger(pi1_);
1282 LoggerState pi2_logger = MakeLogger(pi2_);
1283
1284 event_loop_factory_.RunFor(chrono::milliseconds(95));
1285
1286 StartLogger(&pi1_logger);
1287 StartLogger(&pi2_logger);
1288
1289 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001290
1291 pi1_logger.AppendAllFilenames(&filenames);
1292 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001293 }
1294
Austin Schuh8fb4b452023-08-04 17:02:27 -07001295 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001296 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1297 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001298
1299 // Remap just on pi1.
1300 reader.RemapLoggedChannel<aos::timing::Report>(
1301 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1302
1303 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1304 log_reader_factory.set_send_delay(chrono::microseconds(0));
1305
1306 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1307 // Note: An extra channel gets remapped automatically due to a timestamp
1308 // channel being LOCAL_LOGGER'd.
1309 ASSERT_EQ(remapped_channels.size(), std::get<0>(GetParam()).shared ? 1u : 2u);
1310 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1311 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1312 if (!std::get<0>(GetParam()).shared) {
1313 EXPECT_EQ(remapped_channels[1]->name()->string_view(),
1314 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1315 "aos-message_bridge-Timestamp");
1316 EXPECT_EQ(remapped_channels[1]->type()->string_view(),
1317 "aos.message_bridge.RemoteMessage");
1318 }
1319
1320 reader.Register(&log_reader_factory);
1321
1322 const Node *pi1 =
1323 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1324 const Node *pi2 =
1325 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1326
1327 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1328 // else should have moved.
1329 std::unique_ptr<EventLoop> pi1_event_loop =
1330 log_reader_factory.MakeEventLoop("test", pi1);
1331 pi1_event_loop->SkipTimingReport();
1332 std::unique_ptr<EventLoop> full_pi1_event_loop =
1333 log_reader_factory.MakeEventLoop("test", pi1);
1334 full_pi1_event_loop->SkipTimingReport();
1335 std::unique_ptr<EventLoop> pi2_event_loop =
1336 log_reader_factory.MakeEventLoop("test", pi2);
1337 pi2_event_loop->SkipTimingReport();
1338
1339 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1340 "/aos");
1341 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1342 full_pi1_event_loop.get(), "/pi1/aos");
1343 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1344 pi1_event_loop.get(), "/original/aos");
1345 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1346 full_pi1_event_loop.get(), "/original/pi1/aos");
1347 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1348 "/aos");
1349
1350 log_reader_factory.Run();
1351
1352 EXPECT_EQ(pi1_timing_report.count(), 0u);
1353 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1354 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1355 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1356 EXPECT_NE(pi2_timing_report.count(), 0u);
1357
1358 reader.Deregister();
1359}
1360
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001361// Tests that if we rename a logged channel, it shows up correctly.
1362TEST_P(MultinodeLoggerTest, RenameLoggedChannel) {
1363 std::vector<std::string> actual_filenames;
1364 time_converter_.StartEqual();
1365 {
1366 LoggerState pi1_logger = MakeLogger(pi1_);
1367 LoggerState pi2_logger = MakeLogger(pi2_);
1368
1369 event_loop_factory_.RunFor(chrono::milliseconds(95));
1370
1371 StartLogger(&pi1_logger);
1372 StartLogger(&pi2_logger);
1373
1374 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1375
1376 pi1_logger.AppendAllFilenames(&actual_filenames);
1377 pi2_logger.AppendAllFilenames(&actual_filenames);
1378 }
1379
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001380 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1381 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1382 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001383
1384 // Rename just on pi2. Add some global maps just to verify they get added in
1385 // the config and used correctly.
1386 std::vector<MapT> maps;
1387 {
1388 MapT map;
1389 map.match = std::make_unique<ChannelT>();
1390 map.match->name = "/foo*";
1391 map.match->source_node = "pi1";
1392 map.rename = std::make_unique<ChannelT>();
1393 map.rename->name = "/pi1/foo";
1394 maps.emplace_back(std::move(map));
1395 }
1396 {
1397 MapT map;
1398 map.match = std::make_unique<ChannelT>();
1399 map.match->name = "/foo*";
1400 map.match->source_node = "pi2";
1401 map.rename = std::make_unique<ChannelT>();
1402 map.rename->name = "/pi2/foo";
1403 maps.emplace_back(std::move(map));
1404 }
1405 {
1406 MapT map;
1407 map.match = std::make_unique<ChannelT>();
1408 map.match->name = "/foo";
1409 map.match->type = "aos.examples.Ping";
1410 map.rename = std::make_unique<ChannelT>();
1411 map.rename->name = "/foo/renamed";
1412 maps.emplace_back(std::move(map));
1413 }
1414 reader.RenameLoggedChannel<aos::examples::Ping>(
1415 "/aos", configuration::GetNode(reader.configuration(), "pi2"),
1416 "/pi2/foo/renamed", maps);
1417
1418 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1419 log_reader_factory.set_send_delay(chrono::microseconds(0));
1420
1421 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1422 // Note: An extra channel gets remapped automatically due to a timestamp
1423 // channel being LOCAL_LOGGER'd.
1424 const bool shared = std::get<0>(GetParam()).shared;
1425 ASSERT_EQ(remapped_channels.size(), shared ? 1u : 2u);
1426 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->name()->string_view(),
1427 "/pi2/foo/renamed");
1428 EXPECT_EQ(remapped_channels[shared ? 0 : 1]->type()->string_view(),
1429 "aos.examples.Ping");
1430 if (!shared) {
1431 EXPECT_EQ(remapped_channels[0]->name()->string_view(),
1432 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1433 "aos-message_bridge-Timestamp");
1434 EXPECT_EQ(remapped_channels[0]->type()->string_view(),
1435 "aos.message_bridge.RemoteMessage");
1436 }
1437
1438 reader.Register(&log_reader_factory);
1439
1440 const Node *pi1 =
1441 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1442 const Node *pi2 =
1443 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1444
1445 // Confirm we can read the data on the renamed channel, just for pi2. Nothing
1446 // else should have moved.
1447 std::unique_ptr<EventLoop> pi2_event_loop =
1448 log_reader_factory.MakeEventLoop("test", pi2);
1449 pi2_event_loop->SkipTimingReport();
1450 std::unique_ptr<EventLoop> full_pi2_event_loop =
1451 log_reader_factory.MakeEventLoop("test", pi2);
1452 full_pi2_event_loop->SkipTimingReport();
1453 std::unique_ptr<EventLoop> pi1_event_loop =
1454 log_reader_factory.MakeEventLoop("test", pi1);
1455 pi1_event_loop->SkipTimingReport();
1456
1457 MessageCounter<aos::examples::Ping> pi2_ping(pi2_event_loop.get(), "/aos");
1458 MessageCounter<aos::examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1459 "/foo");
1460 MessageCounter<aos::examples::Ping> full_pi2_renamed_ping(
1461 full_pi2_event_loop.get(), "/pi2/foo/renamed");
1462 MessageCounter<aos::examples::Ping> pi1_ping(pi1_event_loop.get(), "/aos");
1463
1464 log_reader_factory.Run();
1465
1466 EXPECT_EQ(pi2_ping.count(), 0u);
1467 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1468 EXPECT_NE(full_pi2_renamed_ping.count(), 0u);
1469 EXPECT_NE(pi1_ping.count(), 0u);
1470
1471 reader.Deregister();
1472}
1473
Naman Guptaa63aa132023-03-22 20:06:34 -07001474// Tests that we can remap a forwarded channel as well.
1475TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1476 time_converter_.StartEqual();
1477 {
1478 LoggerState pi1_logger = MakeLogger(pi1_);
1479 LoggerState pi2_logger = MakeLogger(pi2_);
1480
1481 event_loop_factory_.RunFor(chrono::milliseconds(95));
1482
1483 StartLogger(&pi1_logger);
1484 StartLogger(&pi2_logger);
1485
1486 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1487 }
1488
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001489 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1490 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1491 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07001492
1493 reader.RemapLoggedChannel<examples::Ping>("/test");
1494
1495 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1496 log_reader_factory.set_send_delay(chrono::microseconds(0));
1497
1498 reader.Register(&log_reader_factory);
1499
1500 const Node *pi1 =
1501 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1502 const Node *pi2 =
1503 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1504
1505 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1506 // else should have moved.
1507 std::unique_ptr<EventLoop> pi1_event_loop =
1508 log_reader_factory.MakeEventLoop("test", pi1);
1509 pi1_event_loop->SkipTimingReport();
1510 std::unique_ptr<EventLoop> full_pi1_event_loop =
1511 log_reader_factory.MakeEventLoop("test", pi1);
1512 full_pi1_event_loop->SkipTimingReport();
1513 std::unique_ptr<EventLoop> pi2_event_loop =
1514 log_reader_factory.MakeEventLoop("test", pi2);
1515 pi2_event_loop->SkipTimingReport();
1516
1517 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1518 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1519 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1520 "/original/test");
1521 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1522 "/original/test");
1523
1524 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1525 pi1_original_ping_timestamp;
1526 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1527 pi1_ping_timestamp;
1528 if (!shared()) {
1529 pi1_original_ping_timestamp =
1530 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1531 pi1_event_loop.get(),
1532 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1533 pi1_ping_timestamp =
1534 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1535 pi1_event_loop.get(),
1536 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1537 }
1538
1539 log_reader_factory.Run();
1540
1541 EXPECT_EQ(pi1_ping.count(), 0u);
1542 EXPECT_EQ(pi2_ping.count(), 0u);
1543 EXPECT_NE(pi1_original_ping.count(), 0u);
1544 EXPECT_NE(pi2_original_ping.count(), 0u);
1545 if (!shared()) {
1546 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1547 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1548 }
1549
1550 reader.Deregister();
1551}
1552
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001553// Tests that we can rename a forwarded channel as well.
1554TEST_P(MultinodeLoggerTest, RenameForwardedLoggedChannel) {
1555 std::vector<std::string> actual_filenames;
1556 time_converter_.StartEqual();
1557 {
1558 LoggerState pi1_logger = MakeLogger(pi1_);
1559 LoggerState pi2_logger = MakeLogger(pi2_);
1560
1561 event_loop_factory_.RunFor(chrono::milliseconds(95));
1562
1563 StartLogger(&pi1_logger);
1564 StartLogger(&pi2_logger);
1565
1566 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1567
1568 pi1_logger.AppendAllFilenames(&actual_filenames);
1569 pi2_logger.AppendAllFilenames(&actual_filenames);
1570 }
1571
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07001572 const std::vector<LogFile> sorted_parts = SortParts(actual_filenames);
1573 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
1574 LogReader reader(sorted_parts);
Sanjay Narayanan5ec00232022-07-08 15:21:30 -07001575
1576 std::vector<MapT> maps;
1577 {
1578 MapT map;
1579 map.match = std::make_unique<ChannelT>();
1580 map.match->name = "/production*";
1581 map.match->source_node = "pi1";
1582 map.rename = std::make_unique<ChannelT>();
1583 map.rename->name = "/pi1/production";
1584 maps.emplace_back(std::move(map));
1585 }
1586 {
1587 MapT map;
1588 map.match = std::make_unique<ChannelT>();
1589 map.match->name = "/production*";
1590 map.match->source_node = "pi2";
1591 map.rename = std::make_unique<ChannelT>();
1592 map.rename->name = "/pi2/production";
1593 maps.emplace_back(std::move(map));
1594 }
1595 reader.RenameLoggedChannel<aos::examples::Ping>(
1596 "/test", configuration::GetNode(reader.configuration(), "pi1"),
1597 "/pi1/production", maps);
1598
1599 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1600 log_reader_factory.set_send_delay(chrono::microseconds(0));
1601
1602 reader.Register(&log_reader_factory);
1603
1604 const Node *pi1 =
1605 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1606 const Node *pi2 =
1607 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1608
1609 // Confirm we can read the data on the renamed channel, on both the source
1610 // node and the remote node. In case of split timestamp channels, confirm that
1611 // we receive the timestamp messages on the renamed channel as well.
1612 std::unique_ptr<EventLoop> pi1_event_loop =
1613 log_reader_factory.MakeEventLoop("test", pi1);
1614 pi1_event_loop->SkipTimingReport();
1615 std::unique_ptr<EventLoop> full_pi1_event_loop =
1616 log_reader_factory.MakeEventLoop("test", pi1);
1617 full_pi1_event_loop->SkipTimingReport();
1618 std::unique_ptr<EventLoop> pi2_event_loop =
1619 log_reader_factory.MakeEventLoop("test", pi2);
1620 pi2_event_loop->SkipTimingReport();
1621
1622 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1623 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1624 MessageCounter<examples::Ping> pi1_renamed_ping(pi1_event_loop.get(),
1625 "/pi1/production");
1626 MessageCounter<examples::Ping> pi2_renamed_ping(pi2_event_loop.get(),
1627 "/pi1/production");
1628
1629 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1630 pi1_renamed_ping_timestamp;
1631 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1632 pi1_ping_timestamp;
1633 if (!shared()) {
1634 pi1_renamed_ping_timestamp =
1635 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1636 pi1_event_loop.get(),
1637 "/pi1/aos/remote_timestamps/pi2/pi1/production/aos-examples-Ping");
1638 pi1_ping_timestamp =
1639 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1640 pi1_event_loop.get(),
1641 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1642 }
1643
1644 log_reader_factory.Run();
1645
1646 EXPECT_EQ(pi1_ping.count(), 0u);
1647 EXPECT_EQ(pi2_ping.count(), 0u);
1648 EXPECT_NE(pi1_renamed_ping.count(), 0u);
1649 EXPECT_NE(pi2_renamed_ping.count(), 0u);
1650 if (!shared()) {
1651 EXPECT_NE(pi1_renamed_ping_timestamp->count(), 0u);
1652 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1653 }
1654
1655 reader.Deregister();
1656}
1657
Naman Guptaa63aa132023-03-22 20:06:34 -07001658// Tests that we observe all the same events in log replay (for a given node)
1659// whether we just register an event loop for that node or if we register a full
1660// event loop factory.
1661TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
1662 time_converter_.StartEqual();
1663 constexpr chrono::milliseconds kStartupDelay(95);
Austin Schuh8fb4b452023-08-04 17:02:27 -07001664 std::vector<std::string> filenames;
1665
Naman Guptaa63aa132023-03-22 20:06:34 -07001666 {
1667 LoggerState pi1_logger = MakeLogger(pi1_);
1668 LoggerState pi2_logger = MakeLogger(pi2_);
1669
1670 event_loop_factory_.RunFor(kStartupDelay);
1671
1672 StartLogger(&pi1_logger);
1673 StartLogger(&pi2_logger);
1674
1675 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07001676
1677 pi1_logger.AppendAllFilenames(&filenames);
1678 pi2_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07001679 }
1680
Austin Schuh8fb4b452023-08-04 17:02:27 -07001681 LogReader full_reader(SortParts(filenames));
1682 LogReader single_node_reader(SortParts(filenames));
Naman Guptaa63aa132023-03-22 20:06:34 -07001683
1684 SimulatedEventLoopFactory full_factory(full_reader.configuration());
1685 SimulatedEventLoopFactory single_node_factory(
1686 single_node_reader.configuration());
1687 single_node_factory.SkipTimingReport();
1688 single_node_factory.DisableStatistics();
1689 std::unique_ptr<EventLoop> replay_event_loop =
1690 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
1691 "log_reader");
1692
1693 full_reader.Register(&full_factory);
1694 single_node_reader.Register(replay_event_loop.get());
1695
1696 const Node *full_pi1 =
1697 configuration::GetNode(full_factory.configuration(), "pi1");
1698
1699 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1700 // else should have moved.
1701 std::unique_ptr<EventLoop> full_event_loop =
1702 full_factory.MakeEventLoop("test", full_pi1);
1703 full_event_loop->SkipTimingReport();
1704 full_event_loop->SkipAosLog();
1705 // maps are indexed on channel index.
1706 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
1707 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
1708 observed_messages;
1709 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
1710 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
1711 ++ii) {
1712 const Channel *channel =
1713 full_event_loop->configuration()->channels()->Get(ii);
1714 // We currently don't support replaying remote timestamp channels in
1715 // realtime replay (unless the remote timestamp channel was not NOT_LOGGED,
1716 // in which case it gets auto-remapped and replayed on a /original channel).
1717 if (channel->name()->string_view().find("remote_timestamp") !=
1718 std::string_view::npos &&
1719 channel->name()->string_view().find("/original") ==
1720 std::string_view::npos) {
1721 continue;
1722 }
1723 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
1724 observed_messages[ii] = {};
1725 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
1726 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
1727 if (fetchers[ii]->Fetch()) {
1728 observed_messages[ii].push_back(std::make_pair(
1729 fetchers[ii]->context().monotonic_event_time, true));
1730 }
1731 });
1732 full_event_loop->MakeRawNoArgWatcher(
1733 channel, [ii, &observed_messages](const Context &context) {
1734 observed_messages[ii].push_back(
1735 std::make_pair(context.monotonic_event_time, false));
1736 });
1737 }
1738 }
1739
1740 full_factory.Run();
1741 fetchers.clear();
1742 full_reader.Deregister();
1743
1744 const Node *single_node_pi1 =
1745 configuration::GetNode(single_node_factory.configuration(), "pi1");
1746 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
1747
1748 std::unique_ptr<EventLoop> single_node_event_loop =
1749 single_node_factory.MakeEventLoop("test", single_node_pi1);
1750 single_node_event_loop->SkipTimingReport();
1751 single_node_event_loop->SkipAosLog();
1752 for (size_t ii = 0;
1753 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
1754 const Channel *channel =
1755 single_node_event_loop->configuration()->channels()->Get(ii);
1756 single_node_factory.DisableForwarding(channel);
1757 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
1758 single_node_fetchers[ii] =
1759 single_node_event_loop->MakeRawFetcher(channel);
1760 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
1761 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
1762 << "Single EventLoop replay doesn't support pre-loading fetchers. "
1763 << configuration::StrippedChannelToString(channel);
1764 });
1765 single_node_event_loop->MakeRawNoArgWatcher(
1766 channel, [ii, &observed_messages, channel,
1767 kStartupDelay](const Context &context) {
1768 if (observed_messages[ii].empty()) {
1769 FAIL() << "Observed extra message at "
1770 << context.monotonic_event_time << " on "
1771 << configuration::StrippedChannelToString(channel);
1772 return;
1773 }
1774 const std::pair<monotonic_clock::time_point, bool> &message =
1775 observed_messages[ii].front();
1776 if (message.second) {
1777 EXPECT_LE(message.first,
1778 context.monotonic_event_time + kStartupDelay)
1779 << "Mismatched message times " << context.monotonic_event_time
1780 << " and " << message.first << " on "
1781 << configuration::StrippedChannelToString(channel);
1782 } else {
1783 EXPECT_EQ(message.first,
1784 context.monotonic_event_time + kStartupDelay)
1785 << "Mismatched message times " << context.monotonic_event_time
1786 << " and " << message.first << " on "
1787 << configuration::StrippedChannelToString(channel);
1788 }
1789 observed_messages[ii].erase(observed_messages[ii].begin());
1790 });
1791 }
1792 }
1793
1794 single_node_factory.Run();
1795
1796 single_node_fetchers.clear();
1797
1798 single_node_reader.Deregister();
1799
1800 for (const auto &pair : observed_messages) {
1801 EXPECT_TRUE(pair.second.empty())
1802 << "Missed " << pair.second.size() << " messages on "
1803 << configuration::StrippedChannelToString(
1804 single_node_event_loop->configuration()->channels()->Get(
1805 pair.first));
1806 }
1807}
1808
1809// Tests that we properly recreate forwarded timestamps when replaying a log.
1810// This should be enough that we can then re-run the logger and get a valid log
1811// back.
1812TEST_P(MultinodeLoggerTest, MessageHeader) {
1813 time_converter_.StartEqual();
1814 {
1815 LoggerState pi1_logger = MakeLogger(pi1_);
1816 LoggerState pi2_logger = MakeLogger(pi2_);
1817
1818 event_loop_factory_.RunFor(chrono::milliseconds(95));
1819
1820 StartLogger(&pi1_logger);
1821 StartLogger(&pi2_logger);
1822
1823 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1824 }
1825
1826 LogReader reader(SortParts(logfiles_));
1827
1828 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1829 log_reader_factory.set_send_delay(chrono::microseconds(0));
1830
1831 // This sends out the fetched messages and advances time to the start of the
1832 // log file.
1833 reader.Register(&log_reader_factory);
1834
1835 const Node *pi1 =
1836 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1837 const Node *pi2 =
1838 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1839
1840 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1841 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1842 LOG(INFO) << "now pi1 "
1843 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1844 LOG(INFO) << "now pi2 "
1845 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1846
1847 EXPECT_THAT(reader.LoggedNodes(),
1848 ::testing::ElementsAre(
1849 configuration::GetNode(reader.logged_configuration(), pi1),
1850 configuration::GetNode(reader.logged_configuration(), pi2)));
1851
1852 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1853
1854 std::unique_ptr<EventLoop> pi1_event_loop =
1855 log_reader_factory.MakeEventLoop("test", pi1);
1856 std::unique_ptr<EventLoop> pi2_event_loop =
1857 log_reader_factory.MakeEventLoop("test", pi2);
1858
1859 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1860 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1861 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1862 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1863
1864 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1865 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1866 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1867 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1868
1869 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1870 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1871 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1872 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1873
1874 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1875 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1876 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1877 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1878
1879 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1880 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1881 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1882 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1883
1884 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1885 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1886 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1887 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1888
1889 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
1890 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
1891
1892 for (std::pair<int, std::string> channel :
1893 shared()
1894 ? std::vector<
1895 std::pair<int, std::string>>{{-1,
1896 "/aos/remote_timestamps/pi2"}}
1897 : std::vector<std::pair<int, std::string>>{
1898 {pi1_timestamp_channel,
1899 "/aos/remote_timestamps/pi2/pi1/aos/"
1900 "aos-message_bridge-Timestamp"},
1901 {ping_timestamp_channel,
1902 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1903 pi1_event_loop->MakeWatcher(
1904 channel.second,
1905 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1906 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1907 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1908 &ping_on_pi2_fetcher, network_delay, send_delay,
1909 channel_index = channel.first](const RemoteMessage &header) {
1910 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1911 chrono::nanoseconds(header.monotonic_sent_time()));
1912 const aos::realtime_clock::time_point header_realtime_sent_time(
1913 chrono::nanoseconds(header.realtime_sent_time()));
1914 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1915 chrono::nanoseconds(header.monotonic_remote_time()));
1916 const aos::realtime_clock::time_point header_realtime_remote_time(
1917 chrono::nanoseconds(header.realtime_remote_time()));
1918
1919 if (channel_index != -1) {
1920 ASSERT_EQ(channel_index, header.channel_index());
1921 }
1922
1923 const Context *pi1_context = nullptr;
1924 const Context *pi2_context = nullptr;
1925
1926 if (header.channel_index() == pi1_timestamp_channel) {
1927 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1928 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1929 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1930 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07001931 // Timestamps don't have wakeup delay, so they show back up after 2
1932 // times the network delay on the source node. Confirm that matches
1933 // when we are reading the log.
1934 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
1935 pi1_context->monotonic_event_time + 2 * network_delay);
Naman Guptaa63aa132023-03-22 20:06:34 -07001936 } else if (header.channel_index() == ping_timestamp_channel) {
1937 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1938 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1939 pi1_context = &ping_on_pi1_fetcher.context();
1940 pi2_context = &ping_on_pi2_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07001941 // Ping messages get picked up faster at the start of each message
1942 // when timers wake up. Verify all that behavior matches exactly as
1943 // expected when reading the log.
1944 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
1945 pi1_context->monotonic_event_time + 2 * network_delay +
1946 ((pi1_event_loop->context().monotonic_event_time -
1947 2 * network_delay)
1948 .time_since_epoch() %
1949 chrono::nanoseconds(1000000000) ==
1950 chrono::nanoseconds(0)
1951 ? chrono::nanoseconds(0)
1952 : send_delay));
Naman Guptaa63aa132023-03-22 20:06:34 -07001953 } else {
1954 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1955 << configuration::CleanedChannelToString(
1956 pi1_event_loop->configuration()->channels()->Get(
1957 header.channel_index()));
1958 }
1959
1960 ASSERT_TRUE(header.has_boot_uuid());
1961 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1962 pi2_event_loop->boot_uuid());
1963
1964 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1965 EXPECT_EQ(pi2_context->remote_queue_index,
1966 header.remote_queue_index());
1967 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
1968
1969 EXPECT_EQ(pi2_context->monotonic_event_time,
1970 header_monotonic_sent_time);
1971 EXPECT_EQ(pi2_context->realtime_event_time,
1972 header_realtime_sent_time);
1973 EXPECT_EQ(pi2_context->realtime_remote_time,
1974 header_realtime_remote_time);
1975 EXPECT_EQ(pi2_context->monotonic_remote_time,
1976 header_monotonic_remote_time);
1977
1978 EXPECT_EQ(pi1_context->realtime_event_time,
1979 header_realtime_remote_time);
1980 EXPECT_EQ(pi1_context->monotonic_event_time,
1981 header_monotonic_remote_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07001982 });
1983 }
1984 for (std::pair<int, std::string> channel :
1985 shared()
1986 ? std::vector<
1987 std::pair<int, std::string>>{{-1,
1988 "/aos/remote_timestamps/pi1"}}
1989 : std::vector<std::pair<int, std::string>>{
1990 {pi2_timestamp_channel,
1991 "/aos/remote_timestamps/pi1/pi2/aos/"
1992 "aos-message_bridge-Timestamp"}}) {
1993 pi2_event_loop->MakeWatcher(
1994 channel.second,
1995 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
1996 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
1997 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
1998 &pong_on_pi1_fetcher, network_delay, send_delay,
1999 channel_index = channel.first](const RemoteMessage &header) {
2000 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2001 chrono::nanoseconds(header.monotonic_sent_time()));
2002 const aos::realtime_clock::time_point header_realtime_sent_time(
2003 chrono::nanoseconds(header.realtime_sent_time()));
2004 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2005 chrono::nanoseconds(header.monotonic_remote_time()));
2006 const aos::realtime_clock::time_point header_realtime_remote_time(
2007 chrono::nanoseconds(header.realtime_remote_time()));
2008
2009 if (channel_index != -1) {
2010 ASSERT_EQ(channel_index, header.channel_index());
2011 }
2012
2013 const Context *pi2_context = nullptr;
2014 const Context *pi1_context = nullptr;
2015
2016 if (header.channel_index() == pi2_timestamp_channel) {
2017 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2018 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2019 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2020 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07002021 // Again, timestamps don't have wakeup delay, so they show back up
2022 // after 2 times the network delay on the source node.
2023 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2024 pi2_context->monotonic_event_time + 2 * network_delay);
Naman Guptaa63aa132023-03-22 20:06:34 -07002025 } else if (header.channel_index() == pong_timestamp_channel) {
2026 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2027 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2028 pi2_context = &pong_on_pi2_fetcher.context();
2029 pi1_context = &pong_on_pi1_fetcher.context();
Austin Schuhac6d89e2024-03-27 14:56:09 -07002030 // And Pong messages come back repeatably since they aren't at the
2031 // start of a second.
2032 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2033 pi2_context->monotonic_event_time + 2 * network_delay +
2034 send_delay);
Naman Guptaa63aa132023-03-22 20:06:34 -07002035 } else {
2036 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2037 << configuration::CleanedChannelToString(
2038 pi2_event_loop->configuration()->channels()->Get(
2039 header.channel_index()));
2040 }
2041
2042 ASSERT_TRUE(header.has_boot_uuid());
2043 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2044 pi1_event_loop->boot_uuid());
2045
2046 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2047 EXPECT_EQ(pi1_context->remote_queue_index,
2048 header.remote_queue_index());
2049 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
2050
2051 EXPECT_EQ(pi1_context->monotonic_event_time,
2052 header_monotonic_sent_time);
2053 EXPECT_EQ(pi1_context->realtime_event_time,
2054 header_realtime_sent_time);
2055 EXPECT_EQ(pi1_context->realtime_remote_time,
2056 header_realtime_remote_time);
2057 EXPECT_EQ(pi1_context->monotonic_remote_time,
2058 header_monotonic_remote_time);
2059
2060 EXPECT_EQ(pi2_context->realtime_event_time,
2061 header_realtime_remote_time);
2062 EXPECT_EQ(pi2_context->monotonic_event_time,
2063 header_monotonic_remote_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07002064 });
2065 }
2066
2067 // And confirm we can re-create a log again, while checking the contents.
2068 {
2069 LoggerState pi1_logger = MakeLogger(
2070 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
2071 LoggerState pi2_logger = MakeLogger(
2072 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
2073
Austin Schuh8fb4b452023-08-04 17:02:27 -07002074 StartLogger(&pi1_logger, tmp_dir_ + "/logs/relogged1");
2075 StartLogger(&pi2_logger, tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07002076
2077 log_reader_factory.Run();
2078 }
2079
2080 reader.Deregister();
2081
2082 // And verify that we can run the LogReader over the relogged files without
2083 // hitting any fatal errors.
2084 {
Austin Schuh8fb4b452023-08-04 17:02:27 -07002085 LogReader relogged_reader(SortParts(
2086 MakeLogFiles(tmp_dir_ + "/logs/relogged1", tmp_dir_ + "/logs/relogged2",
2087 1, 1, 2, 2, true)));
Naman Guptaa63aa132023-03-22 20:06:34 -07002088 relogged_reader.Register();
2089
2090 relogged_reader.event_loop_factory()->Run();
2091 }
2092 // And confirm that we can read the logged file using the reader's
2093 // configuration.
2094 {
2095 LogReader relogged_reader(
Austin Schuh8fb4b452023-08-04 17:02:27 -07002096 SortParts(MakeLogFiles(tmp_dir_ + "/logs/relogged1",
2097 tmp_dir_ + "/logs/relogged2", 1, 1, 2, 2, true)),
Naman Guptaa63aa132023-03-22 20:06:34 -07002098 reader.configuration());
2099 relogged_reader.Register();
2100
2101 relogged_reader.event_loop_factory()->Run();
2102 }
2103}
2104
2105// Tests that we properly populate and extract the logger_start time by setting
2106// up a clock difference between 2 nodes and looking at the resulting parts.
2107TEST_P(MultinodeLoggerTest, LoggerStartTime) {
2108 std::vector<std::string> actual_filenames;
2109 time_converter_.AddMonotonic(
2110 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2111 {
2112 LoggerState pi1_logger = MakeLogger(pi1_);
2113 LoggerState pi2_logger = MakeLogger(pi2_);
2114
2115 StartLogger(&pi1_logger);
2116 StartLogger(&pi2_logger);
2117
2118 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2119
2120 pi1_logger.AppendAllFilenames(&actual_filenames);
2121 pi2_logger.AppendAllFilenames(&actual_filenames);
2122 }
2123
2124 ASSERT_THAT(actual_filenames,
2125 ::testing::UnorderedElementsAreArray(logfiles_));
2126
Austin Schuh8fb4b452023-08-04 17:02:27 -07002127 for (const LogFile &log_file : SortParts(actual_filenames)) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002128 for (const LogParts &log_part : log_file.parts) {
2129 if (log_part.node == log_file.logger_node) {
2130 EXPECT_EQ(log_part.logger_monotonic_start_time,
2131 aos::monotonic_clock::min_time);
2132 EXPECT_EQ(log_part.logger_realtime_start_time,
2133 aos::realtime_clock::min_time);
2134 } else {
2135 const chrono::seconds offset = log_file.logger_node == "pi1"
2136 ? -chrono::seconds(1000)
2137 : chrono::seconds(1000);
2138 EXPECT_EQ(log_part.logger_monotonic_start_time,
2139 log_part.monotonic_start_time + offset);
2140 EXPECT_EQ(log_part.logger_realtime_start_time,
2141 log_file.realtime_start_time +
2142 (log_part.logger_monotonic_start_time -
2143 log_file.monotonic_start_time));
2144 }
2145 }
2146 }
2147}
2148
2149// Test that renaming the base, renames the folder.
2150TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002151 time_converter_.AddMonotonic(
2152 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002153 logfile_base1_ = tmp_dir_ + "/logs/renamefolder/multi_logfile1";
2154 logfile_base2_ = tmp_dir_ + "/logs/renamefolder/multi_logfile2";
2155
Naman Guptaa63aa132023-03-22 20:06:34 -07002156 LoggerState pi1_logger = MakeLogger(pi1_);
2157 LoggerState pi2_logger = MakeLogger(pi2_);
2158
2159 StartLogger(&pi1_logger);
2160 StartLogger(&pi2_logger);
2161
2162 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002163 logfile_base1_ = tmp_dir_ + "/logs/new-good/multi_logfile1";
2164 logfile_base2_ = tmp_dir_ + "/logs/new-good/multi_logfile2";
Naman Guptaa63aa132023-03-22 20:06:34 -07002165 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
Alexei Strotscaf17d32023-04-03 22:31:11 -07002166
2167 // Sequence of set_base_name and Rotate simulates rename operation. Since
2168 // rename is not supported by all namers, RenameLogBase moved from logger to
2169 // the higher level abstraction, yet log_namers support rename, and it is
2170 // legal to test it here.
2171 pi1_logger.log_namer->set_base_name(logfile_base1_);
2172 pi1_logger.logger->Rotate();
2173 pi2_logger.log_namer->set_base_name(logfile_base2_);
2174 pi2_logger.logger->Rotate();
2175
Naman Guptaa63aa132023-03-22 20:06:34 -07002176 for (auto &file : logfiles_) {
2177 struct stat s;
2178 EXPECT_EQ(0, stat(file.c_str(), &s));
2179 }
2180}
2181
2182// Test that renaming the file base dies.
2183TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2184 time_converter_.AddMonotonic(
2185 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07002186 logfile_base1_ = tmp_dir_ + "/logs/renamefile/multi_logfile1";
2187 logfile_base2_ = tmp_dir_ + "/logs/renamefile/multi_logfile2";
2188
Naman Guptaa63aa132023-03-22 20:06:34 -07002189 LoggerState pi1_logger = MakeLogger(pi1_);
2190 StartLogger(&pi1_logger);
2191 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002192 logfile_base1_ = tmp_dir_ + "/logs/new-renamefile/new_multi_logfile1";
Alexei Strotscaf17d32023-04-03 22:31:11 -07002193 EXPECT_DEATH({ pi1_logger.log_namer->set_base_name(logfile_base1_); },
Naman Guptaa63aa132023-03-22 20:06:34 -07002194 "Rename of file base from");
2195}
2196
2197// TODO(austin): We can write a test which recreates a logfile and confirms that
2198// we get it back. That is the ultimate test.
2199
2200// Tests that we properly recreate forwarded timestamps when replaying a log.
2201// This should be enough that we can then re-run the logger and get a valid log
2202// back.
2203TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002204 if (file_strategy() == FileStrategy::kCombine) {
2205 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2206 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002207 std::vector<std::string> actual_filenames;
2208
2209 const UUID pi1_boot0 = UUID::Random();
2210 const UUID pi2_boot0 = UUID::Random();
2211 const UUID pi2_boot1 = UUID::Random();
2212 {
2213 CHECK_EQ(pi1_index_, 0u);
2214 CHECK_EQ(pi2_index_, 1u);
2215
2216 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2217 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2218 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2219
2220 time_converter_.AddNextTimestamp(
2221 distributed_clock::epoch(),
2222 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2223 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2224 time_converter_.AddNextTimestamp(
2225 distributed_clock::epoch() + reboot_time,
2226 {BootTimestamp::epoch() + reboot_time,
2227 BootTimestamp{
2228 .boot = 1,
2229 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2230 }
2231
2232 {
2233 LoggerState pi1_logger = MakeLogger(pi1_);
2234
2235 event_loop_factory_.RunFor(chrono::milliseconds(95));
2236 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2237 pi1_boot0);
2238 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2239 pi2_boot0);
2240
2241 StartLogger(&pi1_logger);
2242
2243 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2244
2245 VLOG(1) << "Reboot now!";
2246
2247 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2248 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2249 pi1_boot0);
2250 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2251 pi2_boot1);
2252
2253 pi1_logger.AppendAllFilenames(&actual_filenames);
2254 }
2255
2256 std::sort(actual_filenames.begin(), actual_filenames.end());
2257 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2258 ASSERT_THAT(actual_filenames,
2259 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2260
2261 // Confirm that our new oldest timestamps properly update as we reboot and
2262 // rotate.
2263 for (const std::string &file : pi1_reboot_logfiles_) {
2264 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2265 ReadHeader(file);
2266 CHECK(log_header);
2267 if (log_header->message().has_configuration()) {
2268 continue;
2269 }
2270
2271 const monotonic_clock::time_point monotonic_start_time =
2272 monotonic_clock::time_point(
2273 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2274 const UUID source_node_boot_uuid = UUID::FromString(
2275 log_header->message().source_node_boot_uuid()->string_view());
2276
2277 if (log_header->message().node()->name()->string_view() != "pi1") {
2278 // The remote message channel should rotate later and have more parts.
2279 // This only is true on the log files with shared remote messages.
2280 //
2281 // TODO(austin): I'm not the most thrilled with this test pattern... It
2282 // feels brittle in a different way.
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002283 if (file.find("timestamps/remote_pi2") == std::string::npos) {
Naman Guptaa63aa132023-03-22 20:06:34 -07002284 switch (log_header->message().parts_index()) {
2285 case 0:
2286 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2287 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2288 break;
2289 case 1:
2290 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2291 ASSERT_EQ(monotonic_start_time,
2292 monotonic_clock::epoch() + chrono::seconds(1));
2293 break;
2294 case 2:
2295 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2296 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2297 break;
2298 case 3:
2299 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2300 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07002301 chrono::nanoseconds(2323000000))
Naman Guptaa63aa132023-03-22 20:06:34 -07002302 << " on " << file;
2303 break;
2304 default:
2305 FAIL();
2306 break;
2307 }
2308 } else {
2309 switch (log_header->message().parts_index()) {
2310 case 0:
2311 case 1:
2312 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2313 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2314 break;
2315 case 2:
2316 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2317 ASSERT_EQ(monotonic_start_time,
2318 monotonic_clock::epoch() + chrono::seconds(1));
2319 break;
2320 case 3:
2321 case 4:
2322 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2323 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2324 break;
2325 case 5:
2326 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2327 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07002328 chrono::nanoseconds(2323000000))
Naman Guptaa63aa132023-03-22 20:06:34 -07002329 << " on " << file;
2330 break;
2331 default:
2332 FAIL();
2333 break;
2334 }
2335 }
2336 continue;
2337 }
2338 SCOPED_TRACE(file);
2339 SCOPED_TRACE(aos::FlatbufferToJson(
2340 *log_header, {.multi_line = true, .max_vector_size = 100}));
2341 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2342 ASSERT_EQ(
2343 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2344 EXPECT_EQ(
2345 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2346 monotonic_clock::max_time.time_since_epoch().count());
2347 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2348 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2349 2u);
2350 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2351 monotonic_clock::max_time.time_since_epoch().count());
2352 ASSERT_TRUE(log_header->message()
2353 .has_oldest_remote_unreliable_monotonic_timestamps());
2354 ASSERT_EQ(log_header->message()
2355 .oldest_remote_unreliable_monotonic_timestamps()
2356 ->size(),
2357 2u);
2358 EXPECT_EQ(log_header->message()
2359 .oldest_remote_unreliable_monotonic_timestamps()
2360 ->Get(0),
2361 monotonic_clock::max_time.time_since_epoch().count());
2362 ASSERT_TRUE(log_header->message()
2363 .has_oldest_local_unreliable_monotonic_timestamps());
2364 ASSERT_EQ(log_header->message()
2365 .oldest_local_unreliable_monotonic_timestamps()
2366 ->size(),
2367 2u);
2368 EXPECT_EQ(log_header->message()
2369 .oldest_local_unreliable_monotonic_timestamps()
2370 ->Get(0),
2371 monotonic_clock::max_time.time_since_epoch().count());
2372
2373 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2374 monotonic_clock::time_point(chrono::nanoseconds(
2375 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2376 1)));
2377 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2378 monotonic_clock::time_point(chrono::nanoseconds(
2379 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2380 const monotonic_clock::time_point
2381 oldest_remote_unreliable_monotonic_timestamps =
2382 monotonic_clock::time_point(chrono::nanoseconds(
2383 log_header->message()
2384 .oldest_remote_unreliable_monotonic_timestamps()
2385 ->Get(1)));
2386 const monotonic_clock::time_point
2387 oldest_local_unreliable_monotonic_timestamps =
2388 monotonic_clock::time_point(chrono::nanoseconds(
2389 log_header->message()
2390 .oldest_local_unreliable_monotonic_timestamps()
2391 ->Get(1)));
2392 const monotonic_clock::time_point
2393 oldest_remote_reliable_monotonic_timestamps =
2394 monotonic_clock::time_point(chrono::nanoseconds(
2395 log_header->message()
2396 .oldest_remote_reliable_monotonic_timestamps()
2397 ->Get(1)));
2398 const monotonic_clock::time_point
2399 oldest_local_reliable_monotonic_timestamps =
2400 monotonic_clock::time_point(chrono::nanoseconds(
2401 log_header->message()
2402 .oldest_local_reliable_monotonic_timestamps()
2403 ->Get(1)));
2404 const monotonic_clock::time_point
2405 oldest_logger_remote_unreliable_monotonic_timestamps =
2406 monotonic_clock::time_point(chrono::nanoseconds(
2407 log_header->message()
2408 .oldest_logger_remote_unreliable_monotonic_timestamps()
2409 ->Get(0)));
2410 const monotonic_clock::time_point
2411 oldest_logger_local_unreliable_monotonic_timestamps =
2412 monotonic_clock::time_point(chrono::nanoseconds(
2413 log_header->message()
2414 .oldest_logger_local_unreliable_monotonic_timestamps()
2415 ->Get(0)));
2416 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2417 monotonic_clock::max_time);
2418 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2419 monotonic_clock::max_time);
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002420 if (log_header->message().data_stored()->Get(0) == StoredDataType::DATA) {
2421 switch (log_header->message().parts_index()) {
2422 case 0:
2423 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2424 monotonic_clock::max_time);
2425 EXPECT_EQ(oldest_local_monotonic_timestamps,
2426 monotonic_clock::max_time);
2427 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2428 monotonic_clock::max_time);
2429 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2430 monotonic_clock::max_time);
2431 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2432 monotonic_clock::max_time);
2433 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2434 monotonic_clock::max_time);
2435 break;
2436 default:
2437 FAIL();
2438 break;
2439 }
2440 } else if (log_header->message().data_stored()->Get(0) ==
2441 StoredDataType::TIMESTAMPS) {
2442 switch (log_header->message().parts_index()) {
2443 case 0:
2444 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2445 monotonic_clock::time_point(chrono::microseconds(90200)));
2446 EXPECT_EQ(oldest_local_monotonic_timestamps,
2447 monotonic_clock::time_point(chrono::microseconds(90350)));
2448 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2449 monotonic_clock::time_point(chrono::microseconds(90200)));
2450 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2451 monotonic_clock::time_point(chrono::microseconds(90350)));
2452 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2453 monotonic_clock::max_time);
2454 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2455 monotonic_clock::max_time);
2456 break;
2457 case 1:
2458 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2459 monotonic_clock::time_point(chrono::microseconds(90200)))
2460 << file;
2461 EXPECT_EQ(oldest_local_monotonic_timestamps,
2462 monotonic_clock::time_point(chrono::microseconds(90350)))
2463 << file;
2464 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2465 monotonic_clock::time_point(chrono::microseconds(90200)))
2466 << file;
2467 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2468 monotonic_clock::time_point(chrono::microseconds(90350)))
2469 << file;
2470 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2471 monotonic_clock::time_point(chrono::microseconds(100000)))
2472 << file;
2473 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Austin Schuhac6d89e2024-03-27 14:56:09 -07002474 monotonic_clock::time_point(chrono::microseconds(100100)))
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002475 << file;
2476 break;
2477 case 2:
2478 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2479 monotonic_clock::time_point(chrono::milliseconds(1323) +
2480 chrono::microseconds(200)));
2481 EXPECT_EQ(
2482 oldest_local_monotonic_timestamps,
2483 monotonic_clock::time_point(chrono::microseconds(10100350)));
2484 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2485 monotonic_clock::time_point(chrono::milliseconds(1323) +
2486 chrono::microseconds(200)));
2487 EXPECT_EQ(
2488 oldest_local_unreliable_monotonic_timestamps,
2489 monotonic_clock::time_point(chrono::microseconds(10100350)));
2490 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2491 monotonic_clock::max_time)
2492 << file;
2493 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2494 monotonic_clock::max_time)
2495 << file;
2496 break;
2497 case 3:
2498 ASSERT_EQ(oldest_remote_monotonic_timestamps,
2499 monotonic_clock::time_point(chrono::milliseconds(1323) +
2500 chrono::microseconds(200)));
2501 EXPECT_EQ(
2502 oldest_local_monotonic_timestamps,
2503 monotonic_clock::time_point(chrono::microseconds(10100350)));
2504 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2505 monotonic_clock::time_point(chrono::milliseconds(1323) +
2506 chrono::microseconds(200)));
2507 EXPECT_EQ(
2508 oldest_local_unreliable_monotonic_timestamps,
2509 monotonic_clock::time_point(chrono::microseconds(10100350)));
2510 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2511 monotonic_clock::time_point(chrono::microseconds(1423000)))
2512 << file;
2513 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Austin Schuhac6d89e2024-03-27 14:56:09 -07002514 monotonic_clock::time_point(chrono::microseconds(10200100)))
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002515 << file;
2516 break;
2517 default:
2518 FAIL();
2519 break;
2520 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002521 }
2522 }
2523
2524 // Confirm that we refuse to replay logs with missing boot uuids.
2525 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07002526 auto sorted_parts = SortParts(pi1_reboot_logfiles_);
2527 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
2528 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07002529
2530 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2531 log_reader_factory.set_send_delay(chrono::microseconds(0));
2532
2533 // This sends out the fetched messages and advances time to the start of
2534 // the log file.
2535 reader.Register(&log_reader_factory);
2536
2537 log_reader_factory.Run();
2538
2539 reader.Deregister();
2540 }
2541}
2542
2543// Tests that we can sort a log which only has timestamps from the remote
2544// because the local message_bridge_client failed to connect.
2545TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07002546 if (file_strategy() == FileStrategy::kCombine) {
2547 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
2548 }
2549
Naman Guptaa63aa132023-03-22 20:06:34 -07002550 const UUID pi1_boot0 = UUID::Random();
2551 const UUID pi2_boot0 = UUID::Random();
2552 const UUID pi2_boot1 = UUID::Random();
2553 {
2554 CHECK_EQ(pi1_index_, 0u);
2555 CHECK_EQ(pi2_index_, 1u);
2556
2557 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2558 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2559 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2560
2561 time_converter_.AddNextTimestamp(
2562 distributed_clock::epoch(),
2563 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2564 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2565 time_converter_.AddNextTimestamp(
2566 distributed_clock::epoch() + reboot_time,
2567 {BootTimestamp::epoch() + reboot_time,
2568 BootTimestamp{
2569 .boot = 1,
2570 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2571 }
2572 pi2_->Disconnect(pi1_->node());
2573
2574 std::vector<std::string> filenames;
2575 {
2576 LoggerState pi1_logger = MakeLogger(pi1_);
2577
2578 event_loop_factory_.RunFor(chrono::milliseconds(95));
2579 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2580 pi1_boot0);
2581 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2582 pi2_boot0);
2583
2584 StartLogger(&pi1_logger);
2585
2586 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2587
2588 VLOG(1) << "Reboot now!";
2589
2590 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2591 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2592 pi1_boot0);
2593 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2594 pi2_boot1);
2595 pi1_logger.AppendAllFilenames(&filenames);
2596 }
2597
2598 std::sort(filenames.begin(), filenames.end());
2599
2600 // Confirm that our new oldest timestamps properly update as we reboot and
2601 // rotate.
2602 size_t timestamp_file_count = 0;
2603 for (const std::string &file : filenames) {
2604 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2605 ReadHeader(file);
2606 CHECK(log_header);
2607
2608 if (log_header->message().has_configuration()) {
2609 continue;
2610 }
2611
2612 const monotonic_clock::time_point monotonic_start_time =
2613 monotonic_clock::time_point(
2614 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2615 const UUID source_node_boot_uuid = UUID::FromString(
2616 log_header->message().source_node_boot_uuid()->string_view());
2617
2618 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2619 ASSERT_EQ(
2620 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2621 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2622 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2623 2u);
2624 ASSERT_TRUE(log_header->message()
2625 .has_oldest_remote_unreliable_monotonic_timestamps());
2626 ASSERT_EQ(log_header->message()
2627 .oldest_remote_unreliable_monotonic_timestamps()
2628 ->size(),
2629 2u);
2630 ASSERT_TRUE(log_header->message()
2631 .has_oldest_local_unreliable_monotonic_timestamps());
2632 ASSERT_EQ(log_header->message()
2633 .oldest_local_unreliable_monotonic_timestamps()
2634 ->size(),
2635 2u);
2636 ASSERT_TRUE(log_header->message()
2637 .has_oldest_remote_reliable_monotonic_timestamps());
2638 ASSERT_EQ(log_header->message()
2639 .oldest_remote_reliable_monotonic_timestamps()
2640 ->size(),
2641 2u);
2642 ASSERT_TRUE(
2643 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
2644 ASSERT_EQ(log_header->message()
2645 .oldest_local_reliable_monotonic_timestamps()
2646 ->size(),
2647 2u);
2648
2649 ASSERT_TRUE(
2650 log_header->message()
2651 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
2652 ASSERT_EQ(log_header->message()
2653 .oldest_logger_remote_unreliable_monotonic_timestamps()
2654 ->size(),
2655 2u);
2656 ASSERT_TRUE(log_header->message()
2657 .has_oldest_logger_local_unreliable_monotonic_timestamps());
2658 ASSERT_EQ(log_header->message()
2659 .oldest_logger_local_unreliable_monotonic_timestamps()
2660 ->size(),
2661 2u);
2662
2663 if (log_header->message().node()->name()->string_view() != "pi1") {
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07002664 ASSERT_TRUE(file.find("timestamps/remote_pi2") != std::string::npos);
Naman Guptaa63aa132023-03-22 20:06:34 -07002665
2666 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2667 ReadNthMessage(file, 0);
2668 CHECK(msg);
2669
2670 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2671 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2672
2673 const monotonic_clock::time_point
2674 expected_oldest_local_monotonic_timestamps(
2675 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2676 const monotonic_clock::time_point
2677 expected_oldest_remote_monotonic_timestamps(
2678 chrono::nanoseconds(msg->message().monotonic_remote_time()));
2679 const monotonic_clock::time_point
2680 expected_oldest_timestamp_monotonic_timestamps(
2681 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
2682
2683 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2684 monotonic_clock::min_time);
2685 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2686 monotonic_clock::min_time);
2687 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
2688 monotonic_clock::min_time);
2689
2690 ++timestamp_file_count;
2691 // Since the log file is from the perspective of the other node,
2692 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2693 monotonic_clock::time_point(chrono::nanoseconds(
2694 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2695 0)));
2696 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2697 monotonic_clock::time_point(chrono::nanoseconds(
2698 log_header->message().oldest_local_monotonic_timestamps()->Get(
2699 0)));
2700 const monotonic_clock::time_point
2701 oldest_remote_unreliable_monotonic_timestamps =
2702 monotonic_clock::time_point(chrono::nanoseconds(
2703 log_header->message()
2704 .oldest_remote_unreliable_monotonic_timestamps()
2705 ->Get(0)));
2706 const monotonic_clock::time_point
2707 oldest_local_unreliable_monotonic_timestamps =
2708 monotonic_clock::time_point(chrono::nanoseconds(
2709 log_header->message()
2710 .oldest_local_unreliable_monotonic_timestamps()
2711 ->Get(0)));
2712 const monotonic_clock::time_point
2713 oldest_remote_reliable_monotonic_timestamps =
2714 monotonic_clock::time_point(chrono::nanoseconds(
2715 log_header->message()
2716 .oldest_remote_reliable_monotonic_timestamps()
2717 ->Get(0)));
2718 const monotonic_clock::time_point
2719 oldest_local_reliable_monotonic_timestamps =
2720 monotonic_clock::time_point(chrono::nanoseconds(
2721 log_header->message()
2722 .oldest_local_reliable_monotonic_timestamps()
2723 ->Get(0)));
2724 const monotonic_clock::time_point
2725 oldest_logger_remote_unreliable_monotonic_timestamps =
2726 monotonic_clock::time_point(chrono::nanoseconds(
2727 log_header->message()
2728 .oldest_logger_remote_unreliable_monotonic_timestamps()
2729 ->Get(1)));
2730 const monotonic_clock::time_point
2731 oldest_logger_local_unreliable_monotonic_timestamps =
2732 monotonic_clock::time_point(chrono::nanoseconds(
2733 log_header->message()
2734 .oldest_logger_local_unreliable_monotonic_timestamps()
2735 ->Get(1)));
2736
2737 const Channel *channel =
2738 event_loop_factory_.configuration()->channels()->Get(
2739 msg->message().channel_index());
2740 const Connection *connection = configuration::ConnectionToNode(
2741 channel, configuration::GetNode(
2742 event_loop_factory_.configuration(),
2743 log_header->message().node()->name()->string_view()));
2744
2745 const bool reliable = connection->time_to_live() == 0;
2746
2747 SCOPED_TRACE(file);
2748 SCOPED_TRACE(aos::FlatbufferToJson(
2749 *log_header, {.multi_line = true, .max_vector_size = 100}));
2750
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002751 // Confirm that the oldest timestamps match what we expect. Based on
2752 // what we are doing, we know that the oldest time is the first
2753 // message's time.
2754 //
2755 // This makes the test robust to both the split and combined config
2756 // tests.
2757 switch (log_header->message().parts_index()) {
2758 case 0:
2759 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2760 expected_oldest_remote_monotonic_timestamps);
2761 EXPECT_EQ(oldest_local_monotonic_timestamps,
2762 expected_oldest_local_monotonic_timestamps);
2763 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2764 expected_oldest_local_monotonic_timestamps)
2765 << file;
2766 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2767 expected_oldest_timestamp_monotonic_timestamps)
2768 << file;
2769
2770 if (reliable) {
2771 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002772 expected_oldest_remote_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002773 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
Naman Guptaa63aa132023-03-22 20:06:34 -07002774 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002775 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2776 monotonic_clock::max_time);
2777 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2778 monotonic_clock::max_time);
2779 } else {
2780 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2781 monotonic_clock::max_time);
2782 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2783 monotonic_clock::max_time);
Naman Guptaa63aa132023-03-22 20:06:34 -07002784 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2785 expected_oldest_remote_monotonic_timestamps);
2786 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2787 expected_oldest_local_monotonic_timestamps);
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002788 }
2789 break;
2790 case 1:
2791 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2792 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2793 EXPECT_EQ(oldest_local_monotonic_timestamps,
2794 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2795 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2796 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2797 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2798 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
2799 if (reliable) {
2800 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2801 expected_oldest_remote_monotonic_timestamps);
2802 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2803 expected_oldest_local_monotonic_timestamps);
2804 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2805 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2806 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2807 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2808 } else {
2809 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2810 monotonic_clock::max_time);
2811 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2812 monotonic_clock::max_time);
2813 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2814 expected_oldest_remote_monotonic_timestamps);
2815 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2816 expected_oldest_local_monotonic_timestamps);
2817 }
2818 break;
2819 case 2:
2820 EXPECT_EQ(
2821 oldest_remote_monotonic_timestamps,
2822 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2823 EXPECT_EQ(oldest_local_monotonic_timestamps,
2824 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2825 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2826 expected_oldest_local_monotonic_timestamps)
2827 << file;
2828 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2829 expected_oldest_timestamp_monotonic_timestamps)
2830 << file;
2831 if (reliable) {
2832 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2833 expected_oldest_remote_monotonic_timestamps);
2834 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2835 expected_oldest_local_monotonic_timestamps);
2836 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2837 monotonic_clock::max_time);
2838 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2839 monotonic_clock::max_time);
2840 } else {
2841 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2842 monotonic_clock::max_time);
2843 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2844 monotonic_clock::max_time);
2845 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2846 expected_oldest_remote_monotonic_timestamps);
2847 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2848 expected_oldest_local_monotonic_timestamps);
2849 }
2850 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002851
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002852 case 3:
2853 EXPECT_EQ(
2854 oldest_remote_monotonic_timestamps,
2855 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2856 EXPECT_EQ(oldest_local_monotonic_timestamps,
2857 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2858 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2859 expected_oldest_remote_monotonic_timestamps);
2860 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2861 expected_oldest_local_monotonic_timestamps);
2862 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2863 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2864 EXPECT_EQ(
2865 oldest_logger_local_unreliable_monotonic_timestamps,
2866 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
2867 break;
2868 default:
2869 FAIL();
2870 break;
Naman Guptaa63aa132023-03-22 20:06:34 -07002871 }
2872
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002873 switch (log_header->message().parts_index()) {
2874 case 0:
2875 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2876 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2877 break;
2878 case 1:
2879 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2880 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2881 break;
2882 case 2:
2883 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2884 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2885 break;
2886 case 3:
2887 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2888 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2889 break;
2890 [[fallthrough]];
2891 default:
2892 FAIL();
2893 break;
2894 }
Naman Guptaa63aa132023-03-22 20:06:34 -07002895 continue;
2896 }
2897 EXPECT_EQ(
2898 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2899 monotonic_clock::max_time.time_since_epoch().count());
2900 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2901 monotonic_clock::max_time.time_since_epoch().count());
2902 EXPECT_EQ(log_header->message()
2903 .oldest_remote_unreliable_monotonic_timestamps()
2904 ->Get(0),
2905 monotonic_clock::max_time.time_since_epoch().count());
2906 EXPECT_EQ(log_header->message()
2907 .oldest_local_unreliable_monotonic_timestamps()
2908 ->Get(0),
2909 monotonic_clock::max_time.time_since_epoch().count());
2910
2911 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2912 monotonic_clock::time_point(chrono::nanoseconds(
2913 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2914 1)));
2915 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2916 monotonic_clock::time_point(chrono::nanoseconds(
2917 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2918 const monotonic_clock::time_point
2919 oldest_remote_unreliable_monotonic_timestamps =
2920 monotonic_clock::time_point(chrono::nanoseconds(
2921 log_header->message()
2922 .oldest_remote_unreliable_monotonic_timestamps()
2923 ->Get(1)));
2924 const monotonic_clock::time_point
2925 oldest_local_unreliable_monotonic_timestamps =
2926 monotonic_clock::time_point(chrono::nanoseconds(
2927 log_header->message()
2928 .oldest_local_unreliable_monotonic_timestamps()
2929 ->Get(1)));
2930 switch (log_header->message().parts_index()) {
2931 case 0:
2932 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2933 monotonic_clock::max_time);
2934 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2935 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2936 monotonic_clock::max_time);
2937 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2938 monotonic_clock::max_time);
2939 break;
2940 default:
2941 FAIL();
2942 break;
2943 }
2944 }
2945
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002946 EXPECT_EQ(timestamp_file_count, 4u);
Naman Guptaa63aa132023-03-22 20:06:34 -07002947
2948 // Confirm that we can actually sort the resulting log and read it.
2949 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07002950 auto sorted_parts = SortParts(filenames);
2951 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
2952 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07002953
2954 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2955 log_reader_factory.set_send_delay(chrono::microseconds(0));
2956
2957 // This sends out the fetched messages and advances time to the start of
2958 // the log file.
2959 reader.Register(&log_reader_factory);
2960
2961 log_reader_factory.Run();
2962
2963 reader.Deregister();
2964 }
2965}
2966
2967// Tests that we properly handle one direction of message_bridge being
2968// unavailable.
2969TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07002970 std::vector<std::string> actual_filenames;
2971
Naman Guptaa63aa132023-03-22 20:06:34 -07002972 pi1_->Disconnect(pi2_->node());
2973 time_converter_.AddMonotonic(
2974 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
2975
2976 time_converter_.AddMonotonic(
2977 {chrono::milliseconds(10000),
2978 chrono::milliseconds(10000) - chrono::milliseconds(1)});
2979 {
2980 LoggerState pi1_logger = MakeLogger(pi1_);
2981
2982 event_loop_factory_.RunFor(chrono::milliseconds(95));
2983
2984 StartLogger(&pi1_logger);
2985
2986 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07002987 pi1_logger.AppendAllFilenames(&actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002988 }
2989
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07002990 // Confirm that we can parse the result. LogReader has enough internal
2991 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07002992 ConfirmReadable(actual_filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07002993}
2994
2995// Tests that we properly handle one direction of message_bridge being
2996// unavailable.
2997TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
2998 pi1_->Disconnect(pi2_->node());
2999 time_converter_.AddMonotonic(
3000 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
3001
3002 time_converter_.AddMonotonic(
3003 {chrono::milliseconds(10000),
3004 chrono::milliseconds(10000) + chrono::milliseconds(1)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07003005
3006 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07003007 {
3008 LoggerState pi1_logger = MakeLogger(pi1_);
3009
3010 event_loop_factory_.RunFor(chrono::milliseconds(95));
3011
3012 StartLogger(&pi1_logger);
3013
3014 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07003015 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003016 }
3017
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003018 // Confirm that we can parse the result. LogReader has enough internal
3019 // CHECKs to confirm the right thing happened.
Austin Schuh8fb4b452023-08-04 17:02:27 -07003020 ConfirmReadable(filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003021}
3022
3023// Tests that we explode if someone passes in a part file twice with a better
3024// error than an out of order error.
3025TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3026 time_converter_.AddMonotonic(
3027 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh8fb4b452023-08-04 17:02:27 -07003028
3029 std::vector<std::string> filenames;
Naman Guptaa63aa132023-03-22 20:06:34 -07003030 {
3031 LoggerState pi1_logger = MakeLogger(pi1_);
3032
3033 event_loop_factory_.RunFor(chrono::milliseconds(95));
3034
3035 StartLogger(&pi1_logger);
3036
3037 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh8fb4b452023-08-04 17:02:27 -07003038
3039 pi1_logger.AppendAllFilenames(&filenames);
Naman Guptaa63aa132023-03-22 20:06:34 -07003040 }
3041
3042 std::vector<std::string> duplicates;
Austin Schuh8fb4b452023-08-04 17:02:27 -07003043 for (const std::string &f : filenames) {
Naman Guptaa63aa132023-03-22 20:06:34 -07003044 duplicates.emplace_back(f);
3045 duplicates.emplace_back(f);
3046 }
3047 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3048}
3049
3050// Tests that we explode if someone loses a part out of the middle of a log.
3051TEST_P(MultinodeLoggerTest, MissingPartsFromMiddle) {
Austin Schuh6ecfe902023-08-04 22:44:37 -07003052 if (file_strategy() == FileStrategy::kCombine) {
3053 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
3054 }
Naman Guptaa63aa132023-03-22 20:06:34 -07003055 time_converter_.AddMonotonic(
3056 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3057 {
3058 LoggerState pi1_logger = MakeLogger(pi1_);
3059
3060 event_loop_factory_.RunFor(chrono::milliseconds(95));
3061
3062 StartLogger(&pi1_logger);
3063 aos::monotonic_clock::time_point last_rotation_time =
3064 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07003065 pi1_logger.logger->set_on_logged_period(
3066 [&](aos::monotonic_clock::time_point) {
3067 const auto now = pi1_logger.event_loop->monotonic_now();
3068 if (now > last_rotation_time + std::chrono::seconds(5)) {
3069 pi1_logger.logger->Rotate();
3070 last_rotation_time = now;
3071 }
3072 });
Naman Guptaa63aa132023-03-22 20:06:34 -07003073
3074 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3075 }
3076
3077 std::vector<std::string> missing_parts;
3078
Mithun Bharadwajc54aa022023-08-02 16:10:41 -07003079 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part0" +
3080 Extension());
3081 missing_parts.emplace_back(logfile_base1_ + "_pi1_timestamps.part2" +
3082 Extension());
Naman Guptaa63aa132023-03-22 20:06:34 -07003083 missing_parts.emplace_back(absl::StrCat(
3084 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
3085
3086 EXPECT_DEATH({ SortParts(missing_parts); },
3087 "Broken log, missing part files between");
3088}
3089
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003090// Tests that we properly handle a dead node. Do this by just disconnecting
3091// it and only using one nodes of logs.
Naman Guptaa63aa132023-03-22 20:06:34 -07003092TEST_P(MultinodeLoggerTest, DeadNode) {
3093 pi1_->Disconnect(pi2_->node());
3094 pi2_->Disconnect(pi1_->node());
3095 time_converter_.AddMonotonic(
3096 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3097 {
3098 LoggerState pi1_logger = MakeLogger(pi1_);
3099
3100 event_loop_factory_.RunFor(chrono::milliseconds(95));
3101
3102 StartLogger(&pi1_logger);
3103
3104 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3105 }
3106
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003107 // Confirm that we can parse the result. LogReader has enough internal
3108 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003109 ConfirmReadable(MakePi1DeadNodeLogfiles());
3110}
3111
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003112// Tests that we can relog with a different config. This makes most sense
3113// when you are trying to edit a log and want to use channel renaming + the
3114// original config in the new log.
Naman Guptaa63aa132023-03-22 20:06:34 -07003115TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3116 time_converter_.StartEqual();
3117 {
3118 LoggerState pi1_logger = MakeLogger(pi1_);
3119 LoggerState pi2_logger = MakeLogger(pi2_);
3120
3121 event_loop_factory_.RunFor(chrono::milliseconds(95));
3122
3123 StartLogger(&pi1_logger);
3124 StartLogger(&pi2_logger);
3125
3126 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3127 }
3128
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003129 auto sorted_parts = SortParts(logfiles_);
3130 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3131 LogReader reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003132 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3133
3134 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3135 log_reader_factory.set_send_delay(chrono::microseconds(0));
3136
3137 // This sends out the fetched messages and advances time to the start of the
3138 // log file.
3139 reader.Register(&log_reader_factory);
3140
3141 const Node *pi1 =
3142 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3143 const Node *pi2 =
3144 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3145
3146 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3147 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3148 LOG(INFO) << "now pi1 "
3149 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3150 LOG(INFO) << "now pi2 "
3151 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3152
3153 EXPECT_THAT(reader.LoggedNodes(),
3154 ::testing::ElementsAre(
3155 configuration::GetNode(reader.logged_configuration(), pi1),
3156 configuration::GetNode(reader.logged_configuration(), pi2)));
3157
3158 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3159
3160 // And confirm we can re-create a log again, while checking the contents.
3161 std::vector<std::string> log_files;
3162 {
3163 LoggerState pi1_logger =
3164 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
3165 &log_reader_factory, reader.logged_configuration());
3166 LoggerState pi2_logger =
3167 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
3168 &log_reader_factory, reader.logged_configuration());
3169
Austin Schuh7e417682023-08-11 17:05:30 -07003170 pi1_logger.StartLogger(tmp_dir_ + "/logs/relogged1");
3171 pi2_logger.StartLogger(tmp_dir_ + "/logs/relogged2");
Naman Guptaa63aa132023-03-22 20:06:34 -07003172
3173 log_reader_factory.Run();
3174
3175 for (auto &x : pi1_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003176 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged1_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003177 }
3178 for (auto &x : pi2_logger.log_namer->all_filenames()) {
Austin Schuh7e417682023-08-11 17:05:30 -07003179 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged2_", x));
Naman Guptaa63aa132023-03-22 20:06:34 -07003180 }
3181 }
3182
3183 reader.Deregister();
3184
3185 // And verify that we can run the LogReader over the relogged files without
3186 // hitting any fatal errors.
3187 {
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003188 auto sorted_parts = SortParts(log_files);
3189 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3190 LogReader relogged_reader(sorted_parts);
Naman Guptaa63aa132023-03-22 20:06:34 -07003191 relogged_reader.Register();
3192
3193 relogged_reader.event_loop_factory()->Run();
3194 }
3195}
3196
Maxwell Gumley8c1b87f2024-02-13 17:54:52 -07003197// Tests that we can relog with a subset of the original config. This is useful
3198// for excluding obsolete or deprecated channels, so they don't appear in the
3199// configuration when reading the log.
3200TEST_P(MultinodeLoggerTest, LogPartialConfig) {
3201 time_converter_.StartEqual();
3202 {
3203 LoggerState pi1_logger = MakeLogger(pi1_);
3204 LoggerState pi2_logger = MakeLogger(pi2_);
3205
3206 event_loop_factory_.RunFor(chrono::milliseconds(95));
3207
3208 StartLogger(&pi1_logger);
3209 StartLogger(&pi2_logger);
3210
3211 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3212 }
3213
3214 auto sorted_parts = SortParts(logfiles_);
3215 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3216 LogReader reader(sorted_parts);
3217 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3218
3219 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3220 log_reader_factory.set_send_delay(chrono::microseconds(0));
3221
3222 // This sends out the fetched messages and advances time to the start of the
3223 // log file.
3224 reader.Register(&log_reader_factory);
3225
3226 const Node *pi1 =
3227 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3228 const Node *pi2 =
3229 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3230
3231 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3232 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3233 LOG(INFO) << "now pi1 "
3234 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3235 LOG(INFO) << "now pi2 "
3236 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3237
3238 EXPECT_THAT(reader.LoggedNodes(),
3239 ::testing::ElementsAre(
3240 configuration::GetNode(reader.logged_configuration(), pi1),
3241 configuration::GetNode(reader.logged_configuration(), pi2)));
3242
3243 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3244
3245 const FlatbufferDetachedBuffer<Configuration> partial_configuration_buffer =
3246 configuration::GetPartialConfiguration(
3247 *reader.event_loop_factory()->configuration(),
3248 [](const Channel &channel) {
3249 if (channel.name()->string_view().starts_with("/original/")) {
3250 LOG(INFO) << "Omitting channel from save_log, channel: "
3251 << channel.name()->string_view() << ", "
3252 << channel.type()->string_view();
3253 return false;
3254 }
3255 return true;
3256 });
3257
3258 // And confirm we can re-create a log again, while checking the contents.
3259 std::vector<std::string> log_files;
3260 {
3261 const Configuration *partial_configuration =
3262 &(partial_configuration_buffer.message());
3263
3264 LoggerState pi1_logger =
3265 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
3266 &log_reader_factory, partial_configuration);
3267 LoggerState pi2_logger =
3268 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
3269 &log_reader_factory, partial_configuration);
3270
3271 pi1_logger.StartLogger(tmp_dir_ + "/logs/relogged1");
3272 pi2_logger.StartLogger(tmp_dir_ + "/logs/relogged2");
3273
3274 log_reader_factory.Run();
3275
3276 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3277 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged1_", x));
3278 }
3279 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3280 log_files.emplace_back(absl::StrCat(tmp_dir_, "/logs/relogged2_", x));
3281 }
3282 }
3283
3284 reader.Deregister();
3285
3286 // And verify that we can run the LogReader over the relogged files without
3287 // hitting any fatal errors.
3288 {
3289 auto sorted_parts = SortParts(log_files);
3290 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
3291 LogReader relogged_reader(sorted_parts);
3292 relogged_reader.Register();
3293
3294 relogged_reader.event_loop_factory()->Run();
3295 }
3296}
3297
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003298// Tests that we properly replay a log where the start time for a node is
3299// before any data on the node. This can happen if the logger starts before
3300// data is published. While the scenario below is a bit convoluted, we have
3301// seen logs like this generated out in the wild.
Naman Guptaa63aa132023-03-22 20:06:34 -07003302TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
Austin Schuh7e417682023-08-11 17:05:30 -07003303 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3304 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3305
Naman Guptaa63aa132023-03-22 20:06:34 -07003306 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3307 aos::configuration::ReadConfig(ArtifactPath(
3308 "aos/events/logging/multinode_pingpong_split3_config.json"));
3309 message_bridge::TestingTimeConverter time_converter(
3310 configuration::NodesCount(&config.message()));
3311 SimulatedEventLoopFactory event_loop_factory(&config.message());
3312 event_loop_factory.SetTimeConverter(&time_converter);
3313 NodeEventLoopFactory *const pi1 =
3314 event_loop_factory.GetNodeEventLoopFactory("pi1");
3315 const size_t pi1_index = configuration::GetNodeIndex(
3316 event_loop_factory.configuration(), pi1->node());
3317 NodeEventLoopFactory *const pi2 =
3318 event_loop_factory.GetNodeEventLoopFactory("pi2");
3319 const size_t pi2_index = configuration::GetNodeIndex(
3320 event_loop_factory.configuration(), pi2->node());
3321 NodeEventLoopFactory *const pi3 =
3322 event_loop_factory.GetNodeEventLoopFactory("pi3");
3323 const size_t pi3_index = configuration::GetNodeIndex(
3324 event_loop_factory.configuration(), pi3->node());
3325
3326 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003327 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003328 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003329 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003330 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003331 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003332 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003333 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
3334
Naman Guptaa63aa132023-03-22 20:06:34 -07003335 const UUID pi1_boot0 = UUID::Random();
3336 const UUID pi2_boot0 = UUID::Random();
3337 const UUID pi2_boot1 = UUID::Random();
3338 const UUID pi3_boot0 = UUID::Random();
3339 {
3340 CHECK_EQ(pi1_index, 0u);
3341 CHECK_EQ(pi2_index, 1u);
3342 CHECK_EQ(pi3_index, 2u);
3343
3344 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3345 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3346 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3347 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3348
3349 time_converter.AddNextTimestamp(
3350 distributed_clock::epoch(),
3351 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3352 BootTimestamp::epoch()});
3353 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3354 time_converter.AddNextTimestamp(
3355 distributed_clock::epoch() + reboot_time,
3356 {BootTimestamp::epoch() + reboot_time,
3357 BootTimestamp{
3358 .boot = 1,
3359 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3360 BootTimestamp::epoch() + reboot_time});
3361 }
3362
3363 // Make everything perfectly quiet.
3364 event_loop_factory.SkipTimingReport();
3365 event_loop_factory.DisableStatistics();
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 event_loop_factory.RunFor(chrono::milliseconds(1000));
3382
3383 pi1_logger.StartLogger(kLogfile1_1);
3384 pi3_logger.StartLogger(kLogfile3_1);
3385 pi2_logger.StartLogger(kLogfile2_1);
3386
3387 event_loop_factory.RunFor(chrono::milliseconds(10000));
3388
3389 // Now that we've got a start time in the past, turn on data.
3390 event_loop_factory.EnableStatistics();
3391 std::unique_ptr<aos::EventLoop> ping_event_loop =
3392 pi1->MakeEventLoop("ping");
3393 Ping ping(ping_event_loop.get());
3394
3395 pi2->AlwaysStart<Pong>("pong");
3396
3397 event_loop_factory.RunFor(chrono::milliseconds(3000));
3398
3399 pi2_logger.AppendAllFilenames(&filenames);
3400
3401 // Stop logging on pi2 before rebooting and completely shut off all
3402 // messages on pi2.
3403 pi2->DisableStatistics();
3404 pi1->Disconnect(pi2->node());
3405 pi2->Disconnect(pi1->node());
3406 }
3407 event_loop_factory.RunFor(chrono::milliseconds(7000));
3408 // pi2 now reboots.
3409 {
3410 event_loop_factory.RunFor(chrono::milliseconds(1000));
3411
3412 // Start logging again on pi2 after it is up.
3413 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003414 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3415 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003416 pi2_logger.StartLogger(kLogfile2_2);
3417
3418 event_loop_factory.RunFor(chrono::milliseconds(10000));
3419 // And, now that we have a start time in the log, turn data back on.
3420 pi2->EnableStatistics();
3421 pi1->Connect(pi2->node());
3422 pi2->Connect(pi1->node());
3423
3424 pi2->AlwaysStart<Pong>("pong");
3425 std::unique_ptr<aos::EventLoop> ping_event_loop =
3426 pi1->MakeEventLoop("ping");
3427 Ping ping(ping_event_loop.get());
3428
3429 event_loop_factory.RunFor(chrono::milliseconds(3000));
3430
3431 pi2_logger.AppendAllFilenames(&filenames);
3432 }
3433
3434 pi1_logger.AppendAllFilenames(&filenames);
3435 pi3_logger.AppendAllFilenames(&filenames);
3436 }
3437
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003438 // Confirm that we can parse the result. LogReader has enough internal
3439 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003440 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003441 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003442 auto result = ConfirmReadable(filenames);
3443 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3444 chrono::seconds(1)));
3445 EXPECT_THAT(result[0].second,
3446 ::testing::ElementsAre(realtime_clock::epoch() +
3447 chrono::microseconds(34990350)));
3448
3449 EXPECT_THAT(result[1].first,
3450 ::testing::ElementsAre(
3451 realtime_clock::epoch() + chrono::seconds(1),
3452 realtime_clock::epoch() + chrono::microseconds(3323000)));
3453 EXPECT_THAT(result[1].second,
3454 ::testing::ElementsAre(
3455 realtime_clock::epoch() + chrono::microseconds(13990200),
3456 realtime_clock::epoch() + chrono::microseconds(16313200)));
3457
3458 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3459 chrono::seconds(1)));
3460 EXPECT_THAT(result[2].second,
3461 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003462 chrono::microseconds(34900100)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003463}
3464
3465// Tests that local data before remote data after reboot is properly replayed.
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003466// We only trigger a reboot in the timestamp interpolation function when
3467// solving the timestamp problem when we actually have a point in the
3468// function. This originally only happened when a point passes the noncausal
3469// filter. At the start of time for the second boot, if we aren't careful, we
3470// will have messages which need to be published at times before the boot.
3471// This happens when a local message is in the log before a forwarded message,
3472// so there is no point in the interpolation function. This delays the
3473// reboot. So, we need to recreate that situation and make sure it doesn't
3474// come back.
Naman Guptaa63aa132023-03-22 20:06:34 -07003475TEST(MultinodeRebootLoggerTest,
3476 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003477 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3478 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3479
Naman Guptaa63aa132023-03-22 20:06:34 -07003480 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3481 aos::configuration::ReadConfig(ArtifactPath(
3482 "aos/events/logging/multinode_pingpong_split3_config.json"));
3483 message_bridge::TestingTimeConverter time_converter(
3484 configuration::NodesCount(&config.message()));
3485 SimulatedEventLoopFactory event_loop_factory(&config.message());
3486 event_loop_factory.SetTimeConverter(&time_converter);
3487 NodeEventLoopFactory *const pi1 =
3488 event_loop_factory.GetNodeEventLoopFactory("pi1");
3489 const size_t pi1_index = configuration::GetNodeIndex(
3490 event_loop_factory.configuration(), pi1->node());
3491 NodeEventLoopFactory *const pi2 =
3492 event_loop_factory.GetNodeEventLoopFactory("pi2");
3493 const size_t pi2_index = configuration::GetNodeIndex(
3494 event_loop_factory.configuration(), pi2->node());
3495 NodeEventLoopFactory *const pi3 =
3496 event_loop_factory.GetNodeEventLoopFactory("pi3");
3497 const size_t pi3_index = configuration::GetNodeIndex(
3498 event_loop_factory.configuration(), pi3->node());
3499
3500 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003501 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003502 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003503 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003504 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003505 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003506 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003507 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003508 const UUID pi1_boot0 = UUID::Random();
3509 const UUID pi2_boot0 = UUID::Random();
3510 const UUID pi2_boot1 = UUID::Random();
3511 const UUID pi3_boot0 = UUID::Random();
3512 {
3513 CHECK_EQ(pi1_index, 0u);
3514 CHECK_EQ(pi2_index, 1u);
3515 CHECK_EQ(pi3_index, 2u);
3516
3517 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3518 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3519 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3520 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3521
3522 time_converter.AddNextTimestamp(
3523 distributed_clock::epoch(),
3524 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3525 BootTimestamp::epoch()});
3526 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3527 time_converter.AddNextTimestamp(
3528 distributed_clock::epoch() + reboot_time,
3529 {BootTimestamp::epoch() + reboot_time,
3530 BootTimestamp{.boot = 1,
3531 .time = monotonic_clock::epoch() + reboot_time +
3532 chrono::seconds(100)},
3533 BootTimestamp::epoch() + reboot_time});
3534 }
3535
3536 std::vector<std::string> filenames;
3537 {
3538 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003539 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3540 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003541 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003542 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3543 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003544 {
3545 // And now start the logger.
3546 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003547 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3548 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003549
3550 pi1_logger.StartLogger(kLogfile1_1);
3551 pi3_logger.StartLogger(kLogfile3_1);
3552 pi2_logger.StartLogger(kLogfile2_1);
3553
3554 event_loop_factory.RunFor(chrono::milliseconds(1005));
3555
3556 // Now that we've got a start time in the past, turn on data.
3557 std::unique_ptr<aos::EventLoop> ping_event_loop =
3558 pi1->MakeEventLoop("ping");
3559 Ping ping(ping_event_loop.get());
3560
3561 pi2->AlwaysStart<Pong>("pong");
3562
3563 event_loop_factory.RunFor(chrono::milliseconds(3000));
3564
3565 pi2_logger.AppendAllFilenames(&filenames);
3566
3567 // Disable any remote messages on pi2.
3568 pi1->Disconnect(pi2->node());
3569 pi2->Disconnect(pi1->node());
3570 }
3571 event_loop_factory.RunFor(chrono::milliseconds(995));
3572 // pi2 now reboots at 5 seconds.
3573 {
3574 event_loop_factory.RunFor(chrono::milliseconds(1000));
3575
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003576 // Make local stuff happen before we start logging and connect the
3577 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003578 pi2->AlwaysStart<Pong>("pong");
3579 std::unique_ptr<aos::EventLoop> ping_event_loop =
3580 pi1->MakeEventLoop("ping");
3581 Ping ping(ping_event_loop.get());
3582 event_loop_factory.RunFor(chrono::milliseconds(1005));
3583
3584 // Start logging again on pi2 after it is up.
3585 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003586 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3587 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003588 pi2_logger.StartLogger(kLogfile2_2);
3589
3590 // And allow remote messages now that we have some local ones.
3591 pi1->Connect(pi2->node());
3592 pi2->Connect(pi1->node());
3593
3594 event_loop_factory.RunFor(chrono::milliseconds(1000));
3595
3596 event_loop_factory.RunFor(chrono::milliseconds(3000));
3597
3598 pi2_logger.AppendAllFilenames(&filenames);
3599 }
3600
3601 pi1_logger.AppendAllFilenames(&filenames);
3602 pi3_logger.AppendAllFilenames(&filenames);
3603 }
3604
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003605 // Confirm that we can parse the result. LogReader has enough internal
3606 // CHECKs to confirm the right thing happened.
Naman Guptaa63aa132023-03-22 20:06:34 -07003607 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003608 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003609 auto result = ConfirmReadable(filenames);
3610
3611 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3612 EXPECT_THAT(result[0].second,
3613 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003614 chrono::microseconds(11000300)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003615
3616 EXPECT_THAT(result[1].first,
3617 ::testing::ElementsAre(
3618 realtime_clock::epoch(),
3619 realtime_clock::epoch() + chrono::microseconds(107005000)));
3620 EXPECT_THAT(result[1].second,
3621 ::testing::ElementsAre(
Austin Schuhac6d89e2024-03-27 14:56:09 -07003622 realtime_clock::epoch() + chrono::microseconds(4000100),
3623 realtime_clock::epoch() + chrono::microseconds(111000150)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003624
3625 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3626 EXPECT_THAT(result[2].second,
3627 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003628 chrono::microseconds(11000100)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003629
3630 auto start_stop_result = ConfirmReadable(
3631 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3632 realtime_clock::epoch() + chrono::milliseconds(3000));
3633
3634 EXPECT_THAT(
3635 start_stop_result[0].first,
3636 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3637 EXPECT_THAT(
3638 start_stop_result[0].second,
3639 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3640 EXPECT_THAT(
3641 start_stop_result[1].first,
3642 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3643 EXPECT_THAT(
3644 start_stop_result[1].second,
3645 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3646 EXPECT_THAT(
3647 start_stop_result[2].first,
3648 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3649 EXPECT_THAT(
3650 start_stop_result[2].second,
3651 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
3652}
3653
3654// Tests that setting the start and stop flags across a reboot works as
3655// expected.
3656TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
Austin Schuh7e417682023-08-11 17:05:30 -07003657 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3658 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3659
Naman Guptaa63aa132023-03-22 20:06:34 -07003660 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3661 aos::configuration::ReadConfig(ArtifactPath(
3662 "aos/events/logging/multinode_pingpong_split3_config.json"));
3663 message_bridge::TestingTimeConverter time_converter(
3664 configuration::NodesCount(&config.message()));
3665 SimulatedEventLoopFactory event_loop_factory(&config.message());
3666 event_loop_factory.SetTimeConverter(&time_converter);
3667 NodeEventLoopFactory *const pi1 =
3668 event_loop_factory.GetNodeEventLoopFactory("pi1");
3669 const size_t pi1_index = configuration::GetNodeIndex(
3670 event_loop_factory.configuration(), pi1->node());
3671 NodeEventLoopFactory *const pi2 =
3672 event_loop_factory.GetNodeEventLoopFactory("pi2");
3673 const size_t pi2_index = configuration::GetNodeIndex(
3674 event_loop_factory.configuration(), pi2->node());
3675 NodeEventLoopFactory *const pi3 =
3676 event_loop_factory.GetNodeEventLoopFactory("pi3");
3677 const size_t pi3_index = configuration::GetNodeIndex(
3678 event_loop_factory.configuration(), pi3->node());
3679
3680 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003681 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003682 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003683 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003684 const std::string kLogfile2_2 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003685 aos::testing::TestTmpDir() + "/logs/multi_logfile2.2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003686 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003687 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003688 {
3689 CHECK_EQ(pi1_index, 0u);
3690 CHECK_EQ(pi2_index, 1u);
3691 CHECK_EQ(pi3_index, 2u);
3692
3693 time_converter.AddNextTimestamp(
3694 distributed_clock::epoch(),
3695 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3696 BootTimestamp::epoch()});
3697 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3698 time_converter.AddNextTimestamp(
3699 distributed_clock::epoch() + reboot_time,
3700 {BootTimestamp::epoch() + reboot_time,
3701 BootTimestamp{.boot = 1,
3702 .time = monotonic_clock::epoch() + reboot_time},
3703 BootTimestamp::epoch() + reboot_time});
3704 }
3705
3706 std::vector<std::string> filenames;
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 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003712 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3713 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003714 {
3715 // And now start the logger.
3716 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003717 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3718 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003719
3720 pi1_logger.StartLogger(kLogfile1_1);
3721 pi3_logger.StartLogger(kLogfile3_1);
3722 pi2_logger.StartLogger(kLogfile2_1);
3723
3724 event_loop_factory.RunFor(chrono::milliseconds(1005));
3725
3726 // Now that we've got a start time in the past, turn on data.
3727 std::unique_ptr<aos::EventLoop> ping_event_loop =
3728 pi1->MakeEventLoop("ping");
3729 Ping ping(ping_event_loop.get());
3730
3731 pi2->AlwaysStart<Pong>("pong");
3732
3733 event_loop_factory.RunFor(chrono::milliseconds(3000));
3734
3735 pi2_logger.AppendAllFilenames(&filenames);
3736 }
3737 event_loop_factory.RunFor(chrono::milliseconds(995));
3738 // pi2 now reboots at 5 seconds.
3739 {
3740 event_loop_factory.RunFor(chrono::milliseconds(1000));
3741
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003742 // Make local stuff happen before we start logging and connect the
3743 // remote.
Naman Guptaa63aa132023-03-22 20:06:34 -07003744 pi2->AlwaysStart<Pong>("pong");
3745 std::unique_ptr<aos::EventLoop> ping_event_loop =
3746 pi1->MakeEventLoop("ping");
3747 Ping ping(ping_event_loop.get());
3748 event_loop_factory.RunFor(chrono::milliseconds(5));
3749
3750 // Start logging again on pi2 after it is up.
3751 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003752 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3753 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003754 pi2_logger.StartLogger(kLogfile2_2);
3755
3756 event_loop_factory.RunFor(chrono::milliseconds(5000));
3757
3758 pi2_logger.AppendAllFilenames(&filenames);
3759 }
3760
3761 pi1_logger.AppendAllFilenames(&filenames);
3762 pi3_logger.AppendAllFilenames(&filenames);
3763 }
3764
3765 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003766 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003767 auto result = ConfirmReadable(filenames);
3768
3769 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3770 EXPECT_THAT(result[0].second,
3771 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003772 chrono::microseconds(11000300)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003773
3774 EXPECT_THAT(result[1].first,
3775 ::testing::ElementsAre(
3776 realtime_clock::epoch(),
3777 realtime_clock::epoch() + chrono::microseconds(6005000)));
3778 EXPECT_THAT(result[1].second,
3779 ::testing::ElementsAre(
Austin Schuhac6d89e2024-03-27 14:56:09 -07003780 realtime_clock::epoch() + chrono::microseconds(4900100),
3781 realtime_clock::epoch() + chrono::microseconds(11000150)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003782
3783 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3784 EXPECT_THAT(result[2].second,
3785 ::testing::ElementsAre(realtime_clock::epoch() +
Austin Schuhac6d89e2024-03-27 14:56:09 -07003786 chrono::microseconds(11000100)));
Naman Guptaa63aa132023-03-22 20:06:34 -07003787
3788 // Confirm we observed the correct start and stop times. We should see the
3789 // reboot here.
3790 auto start_stop_result = ConfirmReadable(
3791 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3792 realtime_clock::epoch() + chrono::milliseconds(8000));
3793
3794 EXPECT_THAT(
3795 start_stop_result[0].first,
3796 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3797 EXPECT_THAT(
3798 start_stop_result[0].second,
3799 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3800 EXPECT_THAT(start_stop_result[1].first,
3801 ::testing::ElementsAre(
3802 realtime_clock::epoch() + chrono::seconds(2),
3803 realtime_clock::epoch() + chrono::microseconds(6005000)));
3804 EXPECT_THAT(start_stop_result[1].second,
3805 ::testing::ElementsAre(
Austin Schuhac6d89e2024-03-27 14:56:09 -07003806 realtime_clock::epoch() + chrono::microseconds(4900100),
Naman Guptaa63aa132023-03-22 20:06:34 -07003807 realtime_clock::epoch() + chrono::seconds(8)));
3808 EXPECT_THAT(
3809 start_stop_result[2].first,
3810 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3811 EXPECT_THAT(
3812 start_stop_result[2].second,
3813 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3814}
3815
3816// Tests that we properly handle one direction being down.
3817TEST(MissingDirectionTest, OneDirection) {
Austin Schuh7e417682023-08-11 17:05:30 -07003818 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3819 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3820
Naman Guptaa63aa132023-03-22 20:06:34 -07003821 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3822 aos::configuration::ReadConfig(ArtifactPath(
3823 "aos/events/logging/multinode_pingpong_split4_config.json"));
3824 message_bridge::TestingTimeConverter time_converter(
3825 configuration::NodesCount(&config.message()));
3826 SimulatedEventLoopFactory event_loop_factory(&config.message());
3827 event_loop_factory.SetTimeConverter(&time_converter);
3828
3829 NodeEventLoopFactory *const pi1 =
3830 event_loop_factory.GetNodeEventLoopFactory("pi1");
3831 const size_t pi1_index = configuration::GetNodeIndex(
3832 event_loop_factory.configuration(), pi1->node());
3833 NodeEventLoopFactory *const pi2 =
3834 event_loop_factory.GetNodeEventLoopFactory("pi2");
3835 const size_t pi2_index = configuration::GetNodeIndex(
3836 event_loop_factory.configuration(), pi2->node());
3837 std::vector<std::string> filenames;
3838
3839 {
3840 CHECK_EQ(pi1_index, 0u);
3841 CHECK_EQ(pi2_index, 1u);
3842
3843 time_converter.AddNextTimestamp(
3844 distributed_clock::epoch(),
3845 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3846
3847 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3848 time_converter.AddNextTimestamp(
3849 distributed_clock::epoch() + reboot_time,
3850 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3851 BootTimestamp::epoch() + reboot_time});
3852 }
3853
3854 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003855 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003856 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003857 aos::testing::TestTmpDir() + "/logs/multi_logfile1.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003858
3859 pi2->Disconnect(pi1->node());
3860
3861 pi1->AlwaysStart<Ping>("ping");
3862 pi2->AlwaysStart<Pong>("pong");
3863
3864 {
3865 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003866 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3867 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003868
3869 event_loop_factory.RunFor(chrono::milliseconds(95));
3870
3871 pi2_logger.StartLogger(kLogfile2_1);
3872
3873 event_loop_factory.RunFor(chrono::milliseconds(6000));
3874
3875 pi2->Connect(pi1->node());
3876
3877 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003878 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3879 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003880 pi1_logger.StartLogger(kLogfile1_1);
3881
3882 event_loop_factory.RunFor(chrono::milliseconds(5000));
3883 pi1_logger.AppendAllFilenames(&filenames);
3884 pi2_logger.AppendAllFilenames(&filenames);
3885 }
3886
3887 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003888 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003889 ConfirmReadable(filenames);
3890}
3891
3892// Tests that we properly handle only one direction ever existing after a
3893// reboot.
3894TEST(MissingDirectionTest, OneDirectionAfterReboot) {
Austin Schuh7e417682023-08-11 17:05:30 -07003895 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3896 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3897
Naman Guptaa63aa132023-03-22 20:06:34 -07003898 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3899 aos::configuration::ReadConfig(ArtifactPath(
3900 "aos/events/logging/multinode_pingpong_split4_config.json"));
3901 message_bridge::TestingTimeConverter time_converter(
3902 configuration::NodesCount(&config.message()));
3903 SimulatedEventLoopFactory event_loop_factory(&config.message());
3904 event_loop_factory.SetTimeConverter(&time_converter);
3905
3906 NodeEventLoopFactory *const pi1 =
3907 event_loop_factory.GetNodeEventLoopFactory("pi1");
3908 const size_t pi1_index = configuration::GetNodeIndex(
3909 event_loop_factory.configuration(), pi1->node());
3910 NodeEventLoopFactory *const pi2 =
3911 event_loop_factory.GetNodeEventLoopFactory("pi2");
3912 const size_t pi2_index = configuration::GetNodeIndex(
3913 event_loop_factory.configuration(), pi2->node());
3914 std::vector<std::string> filenames;
3915
3916 {
3917 CHECK_EQ(pi1_index, 0u);
3918 CHECK_EQ(pi2_index, 1u);
3919
3920 time_converter.AddNextTimestamp(
3921 distributed_clock::epoch(),
3922 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3923
3924 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3925 time_converter.AddNextTimestamp(
3926 distributed_clock::epoch() + reboot_time,
3927 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
3928 BootTimestamp::epoch() + reboot_time});
3929 }
3930
3931 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07003932 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07003933
3934 pi1->AlwaysStart<Ping>("ping");
3935
3936 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
3937 // makes it such that we will only get timestamps from pi1 -> pi2 on the
3938 // second boot.
3939 {
3940 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07003941 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
3942 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07003943
3944 event_loop_factory.RunFor(chrono::milliseconds(95));
3945
3946 pi2_logger.StartLogger(kLogfile2_1);
3947
3948 event_loop_factory.RunFor(chrono::milliseconds(4000));
3949
3950 pi2->Disconnect(pi1->node());
3951
3952 event_loop_factory.RunFor(chrono::milliseconds(1000));
3953 pi1->AlwaysStart<Ping>("ping");
3954
3955 event_loop_factory.RunFor(chrono::milliseconds(5000));
3956 pi2_logger.AppendAllFilenames(&filenames);
3957 }
3958
3959 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07003960 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07003961 ConfirmReadable(filenames);
3962}
3963
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003964// Tests that we properly handle only one direction ever existing after a
3965// reboot with only reliable data.
Naman Guptaa63aa132023-03-22 20:06:34 -07003966TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
Austin Schuh7e417682023-08-11 17:05:30 -07003967 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
3968 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
3969
Naman Guptaa63aa132023-03-22 20:06:34 -07003970 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07003971 aos::configuration::ReadConfig(
3972 ArtifactPath("aos/events/logging/"
3973 "multinode_pingpong_split4_reliable_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07003974 message_bridge::TestingTimeConverter time_converter(
3975 configuration::NodesCount(&config.message()));
3976 SimulatedEventLoopFactory event_loop_factory(&config.message());
3977 event_loop_factory.SetTimeConverter(&time_converter);
3978
3979 NodeEventLoopFactory *const pi1 =
3980 event_loop_factory.GetNodeEventLoopFactory("pi1");
3981 const size_t pi1_index = configuration::GetNodeIndex(
3982 event_loop_factory.configuration(), pi1->node());
3983 NodeEventLoopFactory *const pi2 =
3984 event_loop_factory.GetNodeEventLoopFactory("pi2");
3985 const size_t pi2_index = configuration::GetNodeIndex(
3986 event_loop_factory.configuration(), pi2->node());
3987 std::vector<std::string> filenames;
3988
3989 {
3990 CHECK_EQ(pi1_index, 0u);
3991 CHECK_EQ(pi2_index, 1u);
3992
3993 time_converter.AddNextTimestamp(
3994 distributed_clock::epoch(),
3995 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3996
3997 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3998 time_converter.AddNextTimestamp(
3999 distributed_clock::epoch() + reboot_time,
4000 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4001 BootTimestamp::epoch() + reboot_time});
4002 }
4003
4004 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004005 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004006
4007 pi1->AlwaysStart<Ping>("ping");
4008
4009 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4010 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4011 // second boot.
4012 {
4013 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004014 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4015 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004016
4017 event_loop_factory.RunFor(chrono::milliseconds(95));
4018
4019 pi2_logger.StartLogger(kLogfile2_1);
4020
4021 event_loop_factory.RunFor(chrono::milliseconds(4000));
4022
4023 pi2->Disconnect(pi1->node());
4024
4025 event_loop_factory.RunFor(chrono::milliseconds(1000));
4026 pi1->AlwaysStart<Ping>("ping");
4027
4028 event_loop_factory.RunFor(chrono::milliseconds(5000));
4029 pi2_logger.AppendAllFilenames(&filenames);
4030 }
4031
4032 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004033 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004034 ConfirmReadable(filenames);
4035}
4036
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004037// Tests that we properly handle only one direction ever existing after a
4038// reboot with mixed unreliable vs reliable, where reliable has an earlier
4039// timestamp than unreliable.
Brian Smartte67d7112023-03-20 12:06:30 -07004040TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase1) {
Austin Schuh7e417682023-08-11 17:05:30 -07004041 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4042 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4043
Brian Smartte67d7112023-03-20 12:06:30 -07004044 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4045 aos::configuration::ReadConfig(ArtifactPath(
4046 "aos/events/logging/multinode_pingpong_split4_mixed1_config.json"));
4047 message_bridge::TestingTimeConverter time_converter(
4048 configuration::NodesCount(&config.message()));
4049 SimulatedEventLoopFactory event_loop_factory(&config.message());
4050 event_loop_factory.SetTimeConverter(&time_converter);
4051
4052 NodeEventLoopFactory *const pi1 =
4053 event_loop_factory.GetNodeEventLoopFactory("pi1");
4054 const size_t pi1_index = configuration::GetNodeIndex(
4055 event_loop_factory.configuration(), pi1->node());
4056 NodeEventLoopFactory *const pi2 =
4057 event_loop_factory.GetNodeEventLoopFactory("pi2");
4058 const size_t pi2_index = configuration::GetNodeIndex(
4059 event_loop_factory.configuration(), pi2->node());
4060 std::vector<std::string> filenames;
4061
4062 {
4063 CHECK_EQ(pi1_index, 0u);
4064 CHECK_EQ(pi2_index, 1u);
4065
4066 time_converter.AddNextTimestamp(
4067 distributed_clock::epoch(),
4068 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4069
4070 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4071 time_converter.AddNextTimestamp(
4072 distributed_clock::epoch() + reboot_time,
4073 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4074 BootTimestamp::epoch() + reboot_time});
4075 }
4076
4077 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004078 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07004079
4080 // The following sequence using the above reference config creates
4081 // a reliable message timestamp < unreliable message timestamp.
4082 {
4083 pi1->DisableStatistics();
4084 pi2->DisableStatistics();
4085
4086 event_loop_factory.RunFor(chrono::milliseconds(95));
4087
4088 pi1->AlwaysStart<Ping>("ping");
4089
4090 event_loop_factory.RunFor(chrono::milliseconds(5250));
4091
4092 pi1->EnableStatistics();
4093
4094 event_loop_factory.RunFor(chrono::milliseconds(1000));
4095
4096 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004097 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4098 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07004099
4100 pi2_logger.StartLogger(kLogfile2_1);
4101
4102 event_loop_factory.RunFor(chrono::milliseconds(5000));
4103 pi2_logger.AppendAllFilenames(&filenames);
4104 }
4105
4106 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004107 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07004108 ConfirmReadable(filenames);
4109}
4110
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004111// Tests that we properly handle only one direction ever existing after a
4112// reboot with mixed unreliable vs reliable, where unreliable has an earlier
4113// timestamp than reliable.
Brian Smartte67d7112023-03-20 12:06:30 -07004114TEST(MissingDirectionTest, OneDirectionAfterRebootMixedCase2) {
Austin Schuh7e417682023-08-11 17:05:30 -07004115 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4116 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4117
Brian Smartte67d7112023-03-20 12:06:30 -07004118 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4119 aos::configuration::ReadConfig(ArtifactPath(
4120 "aos/events/logging/multinode_pingpong_split4_mixed2_config.json"));
4121 message_bridge::TestingTimeConverter time_converter(
4122 configuration::NodesCount(&config.message()));
4123 SimulatedEventLoopFactory event_loop_factory(&config.message());
4124 event_loop_factory.SetTimeConverter(&time_converter);
4125
4126 NodeEventLoopFactory *const pi1 =
4127 event_loop_factory.GetNodeEventLoopFactory("pi1");
4128 const size_t pi1_index = configuration::GetNodeIndex(
4129 event_loop_factory.configuration(), pi1->node());
4130 NodeEventLoopFactory *const pi2 =
4131 event_loop_factory.GetNodeEventLoopFactory("pi2");
4132 const size_t pi2_index = configuration::GetNodeIndex(
4133 event_loop_factory.configuration(), pi2->node());
4134 std::vector<std::string> filenames;
4135
4136 {
4137 CHECK_EQ(pi1_index, 0u);
4138 CHECK_EQ(pi2_index, 1u);
4139
4140 time_converter.AddNextTimestamp(
4141 distributed_clock::epoch(),
4142 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4143
4144 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4145 time_converter.AddNextTimestamp(
4146 distributed_clock::epoch() + reboot_time,
4147 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4148 BootTimestamp::epoch() + reboot_time});
4149 }
4150
4151 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004152 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Brian Smartte67d7112023-03-20 12:06:30 -07004153
4154 // The following sequence using the above reference config creates
4155 // an unreliable message timestamp < reliable message timestamp.
4156 {
4157 pi1->DisableStatistics();
4158 pi2->DisableStatistics();
4159
4160 event_loop_factory.RunFor(chrono::milliseconds(95));
4161
4162 pi1->AlwaysStart<Ping>("ping");
4163
4164 event_loop_factory.RunFor(chrono::milliseconds(5250));
4165
4166 pi1->EnableStatistics();
4167
4168 event_loop_factory.RunFor(chrono::milliseconds(1000));
4169
4170 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004171 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4172 FileStrategy::kKeepSeparate);
Brian Smartte67d7112023-03-20 12:06:30 -07004173
4174 pi2_logger.StartLogger(kLogfile2_1);
4175
4176 event_loop_factory.RunFor(chrono::milliseconds(5000));
4177 pi2_logger.AppendAllFilenames(&filenames);
4178 }
4179
4180 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004181 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Brian Smartte67d7112023-03-20 12:06:30 -07004182 ConfirmReadable(filenames);
4183}
4184
Naman Guptaa63aa132023-03-22 20:06:34 -07004185// Tests that we properly handle what used to be a time violation in one
4186// direction. This can occur when one direction goes down after sending some
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004187// data, but the other keeps working. The down direction ends up resolving to
4188// a straight line in the noncausal filter, where the direction which is still
4189// up can cross that line. Really, time progressed along just fine but we
4190// assumed that the offset was a line when it could have deviated by up to
4191// 1ms/second.
Naman Guptaa63aa132023-03-22 20:06:34 -07004192TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4193 std::vector<std::string> filenames;
4194
4195 CHECK_EQ(pi1_index_, 0u);
4196 CHECK_EQ(pi2_index_, 1u);
4197
4198 time_converter_.AddNextTimestamp(
4199 distributed_clock::epoch(),
4200 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4201
4202 const chrono::nanoseconds before_disconnect_duration =
4203 time_converter_.AddMonotonic(
4204 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4205
4206 const chrono::nanoseconds test_duration =
4207 time_converter_.AddMonotonic(
4208 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4209 time_converter_.AddMonotonic(
4210 {chrono::milliseconds(10000),
4211 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4212 time_converter_.AddMonotonic(
4213 {chrono::milliseconds(10000),
4214 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4215
4216 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004217 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004218
4219 {
4220 LoggerState pi2_logger = MakeLogger(pi2_);
4221 pi2_logger.StartLogger(kLogfile);
4222 event_loop_factory_.RunFor(before_disconnect_duration);
4223
4224 pi2_->Disconnect(pi1_->node());
4225
4226 event_loop_factory_.RunFor(test_duration);
4227 pi2_->Connect(pi1_->node());
4228
4229 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4230 pi2_logger.AppendAllFilenames(&filenames);
4231 }
4232
4233 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004234 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004235 ConfirmReadable(filenames);
4236}
4237
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004238// Tests that we can replay a logfile that has timestamps such that at least
4239// one node's epoch is at a positive distributed_clock (and thus will have to
4240// be booted after the other node(s)).
Naman Guptaa63aa132023-03-22 20:06:34 -07004241TEST_P(MultinodeLoggerTest, StartOneNodeBeforeOther) {
4242 std::vector<std::string> filenames;
4243
4244 CHECK_EQ(pi1_index_, 0u);
4245 CHECK_EQ(pi2_index_, 1u);
4246
4247 time_converter_.AddNextTimestamp(
4248 distributed_clock::epoch(),
4249 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4250
4251 const chrono::nanoseconds before_reboot_duration = chrono::milliseconds(1000);
4252 time_converter_.RebootAt(
4253 0, distributed_clock::time_point(before_reboot_duration));
4254
4255 const chrono::nanoseconds test_duration = time_converter_.AddMonotonic(
4256 {chrono::milliseconds(10000), chrono::milliseconds(10000)});
4257
4258 const std::string kLogfile =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004259 aos::testing::TestTmpDir() + "/logs/multi_logfile2.1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004260
4261 pi2_->Disconnect(pi1_->node());
4262 pi1_->Disconnect(pi2_->node());
4263
4264 {
4265 LoggerState pi2_logger = MakeLogger(pi2_);
4266
4267 pi2_logger.StartLogger(kLogfile);
4268 event_loop_factory_.RunFor(before_reboot_duration);
4269
4270 pi2_->Connect(pi1_->node());
4271 pi1_->Connect(pi2_->node());
4272
4273 event_loop_factory_.RunFor(test_duration);
4274
4275 pi2_logger.AppendAllFilenames(&filenames);
4276 }
4277
4278 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004279 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004280 ConfirmReadable(filenames);
4281
4282 {
4283 LogReader reader(sorted_parts);
4284 SimulatedEventLoopFactory replay_factory(reader.configuration());
4285 reader.RegisterWithoutStarting(&replay_factory);
4286
4287 NodeEventLoopFactory *const replay_node =
4288 reader.event_loop_factory()->GetNodeEventLoopFactory("pi1");
4289
4290 std::unique_ptr<EventLoop> test_event_loop =
4291 replay_node->MakeEventLoop("test_reader");
4292 replay_node->OnStartup([replay_node]() {
4293 // Check that we didn't boot until at least t=0.
4294 CHECK_LE(monotonic_clock::epoch(), replay_node->monotonic_now());
4295 });
4296 test_event_loop->OnRun([&test_event_loop]() {
4297 // Check that we didn't boot until at least t=0.
4298 EXPECT_LE(monotonic_clock::epoch(), test_event_loop->monotonic_now());
4299 });
4300 reader.event_loop_factory()->Run();
4301 reader.Deregister();
4302 }
4303}
4304
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004305// Tests that when we have a loop without all the logs at all points in time,
4306// we can sort it properly.
Naman Guptaa63aa132023-03-22 20:06:34 -07004307TEST(MultinodeLoggerLoopTest, Loop) {
Austin Schuh7e417682023-08-11 17:05:30 -07004308 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4309 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4310
Naman Guptaa63aa132023-03-22 20:06:34 -07004311 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004312 aos::configuration::ReadConfig(
4313 ArtifactPath("aos/events/logging/"
4314 "multinode_pingpong_triangle_split_config.json"));
Naman Guptaa63aa132023-03-22 20:06:34 -07004315 message_bridge::TestingTimeConverter time_converter(
4316 configuration::NodesCount(&config.message()));
4317 SimulatedEventLoopFactory event_loop_factory(&config.message());
4318 event_loop_factory.SetTimeConverter(&time_converter);
4319
4320 NodeEventLoopFactory *const pi1 =
4321 event_loop_factory.GetNodeEventLoopFactory("pi1");
4322 NodeEventLoopFactory *const pi2 =
4323 event_loop_factory.GetNodeEventLoopFactory("pi2");
4324 NodeEventLoopFactory *const pi3 =
4325 event_loop_factory.GetNodeEventLoopFactory("pi3");
4326
4327 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004328 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004329 const std::string kLogfile2_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004330 aos::testing::TestTmpDir() + "/logs/multi_logfile2/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004331 const std::string kLogfile3_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004332 aos::testing::TestTmpDir() + "/logs/multi_logfile3/";
Naman Guptaa63aa132023-03-22 20:06:34 -07004333
4334 {
4335 // Make pi1 boot before everything else.
4336 time_converter.AddNextTimestamp(
4337 distributed_clock::epoch(),
4338 {BootTimestamp::epoch(),
4339 BootTimestamp::epoch() - chrono::milliseconds(100),
4340 BootTimestamp::epoch() - chrono::milliseconds(300)});
4341 }
4342
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004343 // We want to setup a situation such that 2 of the 3 legs of the loop are
4344 // very confident about time being X, and the third leg is pulling the
4345 // average off to one side.
Naman Guptaa63aa132023-03-22 20:06:34 -07004346 //
4347 // It's easiest to visualize this in timestamp_plotter.
4348
4349 std::vector<std::string> filenames;
4350 {
4351 // Have pi1 send out a reliable message at startup. This sets up a long
4352 // forwarding time message at the start to bias time.
4353 std::unique_ptr<EventLoop> pi1_event_loop = pi1->MakeEventLoop("ping");
4354 {
4355 aos::Sender<examples::Ping> ping_sender =
4356 pi1_event_loop->MakeSender<examples::Ping>("/reliable");
4357
4358 aos::Sender<examples::Ping>::Builder builder = ping_sender.MakeBuilder();
4359 examples::Ping::Builder ping_builder =
4360 builder.MakeBuilder<examples::Ping>();
4361 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
4362 }
4363
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004364 // Wait a while so there's enough data to let the worst case be rather
4365 // off.
Naman Guptaa63aa132023-03-22 20:06:34 -07004366 event_loop_factory.RunFor(chrono::seconds(1000));
4367
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004368 // Now start a receiving node first. This sets up 2 tight bounds between
4369 // 2 of the nodes.
Naman Guptaa63aa132023-03-22 20:06:34 -07004370 LoggerState pi2_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004371 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4372 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004373 pi2_logger.StartLogger(kLogfile2_1);
4374
4375 event_loop_factory.RunFor(chrono::seconds(100));
4376
4377 // And now start the third leg.
4378 LoggerState pi3_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004379 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4380 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004381 pi3_logger.StartLogger(kLogfile3_1);
4382
4383 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004384 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4385 FileStrategy::kKeepSeparate);
Naman Guptaa63aa132023-03-22 20:06:34 -07004386 pi1_logger.StartLogger(kLogfile1_1);
4387
4388 event_loop_factory.RunFor(chrono::seconds(100));
4389
4390 pi1_logger.AppendAllFilenames(&filenames);
4391 pi2_logger.AppendAllFilenames(&filenames);
4392 pi3_logger.AppendAllFilenames(&filenames);
4393 }
4394
4395 // Make sure we can read this.
4396 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Mithun Bharadwaja5cb8e02023-08-02 16:10:40 -07004397 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
Naman Guptaa63aa132023-03-22 20:06:34 -07004398 auto result = ConfirmReadable(filenames);
4399}
4400
Austin Schuh08dba8f2023-05-01 08:29:30 -07004401// Tests that RestartLogging works in the simple case. Unfortunately, the
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004402// failure cases involve simulating time elapsing in callbacks, which is
4403// really hard. The best we can reasonably do is make sure 2 back to back
4404// logs are parseable together.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004405TEST_P(MultinodeLoggerTest, RestartLogging) {
4406 time_converter_.AddMonotonic(
4407 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4408 std::vector<std::string> filenames;
4409 {
4410 LoggerState pi1_logger = MakeLogger(pi1_);
4411
4412 event_loop_factory_.RunFor(chrono::milliseconds(95));
4413
4414 StartLogger(&pi1_logger, logfile_base1_);
4415 aos::monotonic_clock::time_point last_rotation_time =
4416 pi1_logger.event_loop->monotonic_now();
Austin Schuh2f864452023-07-17 14:53:08 -07004417 pi1_logger.logger->set_on_logged_period(
4418 [&](aos::monotonic_clock::time_point) {
4419 const auto now = pi1_logger.event_loop->monotonic_now();
4420 if (now > last_rotation_time + std::chrono::seconds(5)) {
4421 pi1_logger.AppendAllFilenames(&filenames);
4422 std::unique_ptr<MultiNodeFilesLogNamer> namer =
4423 pi1_logger.MakeLogNamer(logfile_base2_);
4424 pi1_logger.log_namer = namer.get();
Austin Schuh08dba8f2023-05-01 08:29:30 -07004425
Austin Schuh2f864452023-07-17 14:53:08 -07004426 pi1_logger.logger->RestartLogging(std::move(namer));
4427 last_rotation_time = now;
4428 }
4429 });
Austin Schuh08dba8f2023-05-01 08:29:30 -07004430
4431 event_loop_factory_.RunFor(chrono::milliseconds(7000));
4432
4433 pi1_logger.AppendAllFilenames(&filenames);
4434 }
4435
4436 for (const auto &x : filenames) {
4437 LOG(INFO) << x;
4438 }
4439
4440 EXPECT_GE(filenames.size(), 2u);
4441
4442 ConfirmReadable(filenames);
4443
Mithun Bharadwaj99aec9e2023-08-02 16:10:40 -07004444 // TODO(austin): It would be good to confirm that any one time messages end
4445 // up in both logs correctly.
Austin Schuh08dba8f2023-05-01 08:29:30 -07004446}
4447
Austin Schuh6e93fc22023-08-22 21:27:22 -07004448// Tests that we call OnEnd without --skip_missing_forwarding_entries.
4449TEST_P(MultinodeLoggerTest, SkipMissingForwardingEntries) {
4450 if (file_strategy() == FileStrategy::kCombine) {
4451 GTEST_SKIP() << "We don't need to test the combined file writer this deep.";
4452 }
4453 time_converter_.AddMonotonic(
4454 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
4455
4456 std::vector<std::string> filenames;
4457 {
4458 LoggerState pi1_logger = MakeLogger(pi1_);
4459
4460 event_loop_factory_.RunFor(chrono::milliseconds(95));
4461
4462 StartLogger(&pi1_logger);
4463 aos::monotonic_clock::time_point last_rotation_time =
4464 pi1_logger.event_loop->monotonic_now();
4465 pi1_logger.logger->set_on_logged_period(
4466 [&](aos::monotonic_clock::time_point) {
4467 const auto now = pi1_logger.event_loop->monotonic_now();
4468 if (now > last_rotation_time + std::chrono::seconds(5)) {
4469 pi1_logger.logger->Rotate();
4470 last_rotation_time = now;
4471 }
4472 });
4473
4474 event_loop_factory_.RunFor(chrono::milliseconds(15000));
4475 pi1_logger.AppendAllFilenames(&filenames);
4476 }
4477
4478 // If we remove the last remote data part, we'll trigger missing data for
4479 // timestamps.
4480 filenames.erase(std::remove_if(filenames.begin(), filenames.end(),
4481 [](const std::string &s) {
4482 return s.find("data/pi2_data.part3.bfbs") !=
4483 std::string::npos;
4484 }),
4485 filenames.end());
4486
4487 auto result = ConfirmReadable(filenames);
4488}
4489
Austin Schuh54ffea42023-08-23 13:27:04 -07004490// Tests that we call OnEnd without --skip_missing_forwarding_entries.
4491TEST(MultinodeLoggerConfigTest, SingleNode) {
4492 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4493 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4494
4495 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4496 aos::configuration::ReadConfig(
4497 ArtifactPath("aos/events/logging/multinode_single_node_config.json"));
4498 message_bridge::TestingTimeConverter time_converter(
4499 configuration::NodesCount(&config.message()));
4500 SimulatedEventLoopFactory event_loop_factory(&config.message());
4501 event_loop_factory.SetTimeConverter(&time_converter);
4502
4503 time_converter.StartEqual();
4504
4505 const std::string kLogfile1_1 =
4506 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
4507
4508 NodeEventLoopFactory *const pi1 =
4509 event_loop_factory.GetNodeEventLoopFactory("pi1");
4510
4511 std::vector<std::string> filenames;
4512
4513 {
4514 // Now start a receiving node first. This sets up 2 tight bounds between
4515 // 2 of the nodes.
4516 LoggerState pi1_logger = MakeLoggerState(
4517 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4518 FileStrategy::kKeepSeparate);
4519 pi1_logger.StartLogger(kLogfile1_1);
4520
4521 event_loop_factory.RunFor(chrono::seconds(10));
4522
4523 pi1_logger.AppendAllFilenames(&filenames);
4524 }
4525
4526 // Make sure we can read this.
4527 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4528 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4529 auto result = ConfirmReadable(filenames);
4530
4531 // TODO(austin): Probably want to stop caring about ServerStatistics,
4532 // ClientStatistics, and Timestamp since they don't really make sense.
4533}
4534
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004535// Tests that when we have evidence of 2 boots, and then start logging, the
4536// max_out_of_order_duration ends up reasonable on the boot with the start time.
4537TEST(MultinodeLoggerLoopTest, PreviousBootData) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004538 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4539 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4540
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004541 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4542 aos::configuration::ReadConfig(ArtifactPath(
4543 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4544 message_bridge::TestingTimeConverter time_converter(
4545 configuration::NodesCount(&config.message()));
4546 SimulatedEventLoopFactory event_loop_factory(&config.message());
4547 event_loop_factory.SetTimeConverter(&time_converter);
4548
4549 const UUID pi1_boot0 = UUID::Random();
4550 const UUID pi2_boot0 = UUID::Random();
4551 const UUID pi2_boot1 = UUID::Random();
4552
4553 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004554 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004555
4556 {
4557 constexpr size_t kPi1Index = 0;
4558 constexpr size_t kPi2Index = 1;
4559 time_converter.set_boot_uuid(kPi1Index, 0, pi1_boot0);
4560 time_converter.set_boot_uuid(kPi2Index, 0, pi2_boot0);
4561 time_converter.set_boot_uuid(kPi2Index, 1, pi2_boot1);
4562
4563 // Make pi1 boot before everything else.
4564 time_converter.AddNextTimestamp(
4565 distributed_clock::epoch(),
4566 {BootTimestamp::epoch(),
4567 BootTimestamp::epoch() - chrono::milliseconds(100)});
4568
4569 const chrono::nanoseconds reboot_time = chrono::seconds(1005);
4570 time_converter.AddNextTimestamp(
4571 distributed_clock::epoch() + reboot_time,
4572 {BootTimestamp::epoch() + reboot_time,
4573 BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()}});
4574 }
4575
4576 NodeEventLoopFactory *const pi1 =
4577 event_loop_factory.GetNodeEventLoopFactory("pi1");
4578 NodeEventLoopFactory *const pi2 =
4579 event_loop_factory.GetNodeEventLoopFactory("pi2");
4580
4581 // What we want is for pi2 to send a message at t=1000 on the first channel
4582 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4583 // the max out of order duration be large.
4584 //
4585 // Then, we reboot, and only send messages on a third channel (/atest2 pong).
4586 // The order is key, they need to sort in this order in the config.
4587
4588 std::vector<std::string> filenames;
4589 {
4590 {
4591 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4592 aos::Sender<examples::Pong> pong_sender =
4593 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4594
4595 pi2_event_loop->OnRun([&]() {
4596 aos::Sender<examples::Pong>::Builder builder =
4597 pong_sender.MakeBuilder();
4598 examples::Pong::Builder pong_builder =
4599 builder.MakeBuilder<examples::Pong>();
4600 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4601 });
4602
4603 event_loop_factory.RunFor(chrono::seconds(1000));
4604 }
4605
4606 {
4607 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4608 aos::Sender<examples::Pong> pong_sender =
4609 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4610
4611 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4612 examples::Pong::Builder pong_builder =
4613 builder.MakeBuilder<examples::Pong>();
4614 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4615 }
4616
4617 event_loop_factory.RunFor(chrono::seconds(10));
4618
4619 // Now start a receiving node first. This sets up 2 tight bounds between
4620 // 2 of the nodes.
4621 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004622 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4623 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004624 pi1_logger.StartLogger(kLogfile1_1);
4625
4626 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4627 aos::Sender<examples::Pong> pong_sender =
4628 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4629
4630 pi2_event_loop->AddPhasedLoop(
4631 [&pong_sender](int) {
4632 aos::Sender<examples::Pong>::Builder builder =
4633 pong_sender.MakeBuilder();
4634 examples::Pong::Builder pong_builder =
4635 builder.MakeBuilder<examples::Pong>();
4636 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4637 },
4638 chrono::milliseconds(10));
4639
4640 event_loop_factory.RunFor(chrono::seconds(100));
4641
4642 pi1_logger.AppendAllFilenames(&filenames);
4643 }
4644
4645 // Make sure we can read this.
4646 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4647 EXPECT_TRUE(AllRebootPartsMatchOutOfOrderDuration(sorted_parts, "pi2"));
4648 auto result = ConfirmReadable(filenames);
4649}
4650
4651// Tests that when we start without a connection, and then start logging, the
4652// max_out_of_order_duration ends up reasonable.
4653TEST(MultinodeLoggerLoopTest, StartDisconnected) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004654 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4655 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4656
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004657 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4658 aos::configuration::ReadConfig(ArtifactPath(
4659 "aos/events/logging/multinode_pingpong_reboot_ooo_config.json"));
4660 message_bridge::TestingTimeConverter time_converter(
4661 configuration::NodesCount(&config.message()));
4662 SimulatedEventLoopFactory event_loop_factory(&config.message());
4663 event_loop_factory.SetTimeConverter(&time_converter);
4664
4665 time_converter.StartEqual();
4666
4667 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004668 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004669
4670 NodeEventLoopFactory *const pi1 =
4671 event_loop_factory.GetNodeEventLoopFactory("pi1");
4672 NodeEventLoopFactory *const pi2 =
4673 event_loop_factory.GetNodeEventLoopFactory("pi2");
4674
4675 // What we want is for pi2 to send a message at t=1000 on the first channel
4676 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4677 // the max out of order duration be large.
4678 //
4679 // Then, we disconnect, and only send messages on a third channel
4680 // (/atest2 pong). The order is key, they need to sort in this order in the
4681 // config so we observe them in the order which grows the
4682 // max_out_of_order_duration.
4683
4684 std::vector<std::string> filenames;
4685 {
4686 {
4687 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4688 aos::Sender<examples::Pong> pong_sender =
4689 pi2_event_loop->MakeSender<examples::Pong>("/atest3");
4690
4691 pi2_event_loop->OnRun([&]() {
4692 aos::Sender<examples::Pong>::Builder builder =
4693 pong_sender.MakeBuilder();
4694 examples::Pong::Builder pong_builder =
4695 builder.MakeBuilder<examples::Pong>();
4696 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4697 });
4698
4699 event_loop_factory.RunFor(chrono::seconds(1000));
4700 }
4701
4702 {
4703 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4704 aos::Sender<examples::Pong> pong_sender =
4705 pi2_event_loop->MakeSender<examples::Pong>("/atest1");
4706
4707 aos::Sender<examples::Pong>::Builder builder = pong_sender.MakeBuilder();
4708 examples::Pong::Builder pong_builder =
4709 builder.MakeBuilder<examples::Pong>();
4710 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4711 }
4712
4713 event_loop_factory.RunFor(chrono::seconds(10));
4714
4715 pi1->Disconnect(pi2->node());
4716 pi2->Disconnect(pi1->node());
4717
4718 // Make data flow.
4719 std::unique_ptr<EventLoop> pi2_event_loop = pi2->MakeEventLoop("pong");
4720 aos::Sender<examples::Pong> pong_sender =
4721 pi2_event_loop->MakeSender<examples::Pong>("/atest2");
4722
4723 pi2_event_loop->AddPhasedLoop(
4724 [&pong_sender](int) {
4725 aos::Sender<examples::Pong>::Builder builder =
4726 pong_sender.MakeBuilder();
4727 examples::Pong::Builder pong_builder =
4728 builder.MakeBuilder<examples::Pong>();
4729 CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
4730 },
4731 chrono::milliseconds(10));
4732
4733 event_loop_factory.RunFor(chrono::seconds(10));
4734
4735 // Now start a receiving node first. This sets up 2 tight bounds between
4736 // 2 of the nodes.
4737 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004738 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4739 FileStrategy::kKeepSeparate);
Mithun Bharadwajdec32d92023-08-02 16:10:41 -07004740 pi1_logger.StartLogger(kLogfile1_1);
4741
4742 event_loop_factory.RunFor(chrono::seconds(10));
4743
4744 // Now, reconnect, and everything should recover.
4745 pi1->Connect(pi2->node());
4746 pi2->Connect(pi1->node());
4747
4748 event_loop_factory.RunFor(chrono::seconds(10));
4749
4750 pi1_logger.AppendAllFilenames(&filenames);
4751 }
4752
4753 // Make sure we can read this.
4754 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4755 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4756 auto result = ConfirmReadable(filenames);
4757}
4758
Austin Schuh633858f2024-03-22 14:34:19 -07004759// Tests that only having a delayed, reliable message from a boot results in a
4760// readable log.
4761//
4762// Note: this is disabled since it doesn't work yet. Un-disable this when the
4763// code is fixed!
4764TEST(MultinodeLoggerLoopTest, DISABLED_ReliableOnlyTimestamps) {
4765 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4766 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4767
4768 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4769 aos::configuration::ReadConfig(
4770 ArtifactPath("aos/events/logging/"
4771 "multinode_pingpong_reboot_reliable_only_config.json"));
4772 message_bridge::TestingTimeConverter time_converter(
4773 configuration::NodesCount(&config.message()));
4774 SimulatedEventLoopFactory event_loop_factory(&config.message());
4775 event_loop_factory.SetTimeConverter(&time_converter);
4776
4777 constexpr chrono::nanoseconds kRebootTime = chrono::seconds(100);
4778 {
4779 time_converter.AddNextTimestamp(
4780 distributed_clock::epoch(),
4781 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4782 time_converter.AddNextTimestamp(
4783 distributed_clock::epoch() + kRebootTime,
4784 {BootTimestamp::epoch() + kRebootTime,
4785 BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()}});
Austin Schuh1124c512023-08-01 15:20:44 -07004786 }
4787
Austin Schuh633858f2024-03-22 14:34:19 -07004788 const std::string kLogfile1_1 =
4789 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
4790
4791 NodeEventLoopFactory *const pi1 =
4792 event_loop_factory.GetNodeEventLoopFactory("pi1");
4793
4794 // We want unreliable timestamps from one boot, a reliable timestamp from the
4795 // same boot, and then a long delayed reliable timestamp from the second boot.
4796 // This produces conflicting information about when the second boot happened.
4797 std::vector<std::string> filenames;
4798 PingSender *app1 = pi1->AlwaysStart<PingSender>("pingsender", "/atest1");
4799 PingSender *app2 = pi1->AlwaysStart<PingSender>("pingsender", "/atest2");
4800 event_loop_factory.RunFor(chrono::seconds(1));
4801 pi1->Stop(app2);
4802 event_loop_factory.RunFor(kRebootTime - chrono::seconds(2));
4803 pi1->Stop(app1);
4804
4805 event_loop_factory.RunFor(chrono::seconds(1) + kRebootTime * 2);
4806
4807 {
4808 // Collect a small log after reboot.
4809 LoggerState pi1_logger = MakeLoggerState(
4810 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4811 FileStrategy::kKeepSeparate);
4812 pi1_logger.StartLogger(kLogfile1_1);
4813
4814 event_loop_factory.RunFor(chrono::seconds(1));
4815
4816 pi1_logger.AppendAllFilenames(&filenames);
4817 }
4818
4819 // Make sure we can read this.
4820 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4821 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4822 auto result = ConfirmReadable(filenames);
4823}
Austin Schuh1124c512023-08-01 15:20:44 -07004824
4825// Tests that we log correctly as nodes connect slowly.
4826TEST(MultinodeLoggerLoopTest, StaggeredConnect) {
Austin Schuh8fb4b452023-08-04 17:02:27 -07004827 util::UnlinkRecursive(aos::testing::TestTmpDir() + "/logs");
4828 std::filesystem::create_directory(aos::testing::TestTmpDir() + "/logs");
4829
Austin Schuh1124c512023-08-01 15:20:44 -07004830 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4831 aos::configuration::ReadConfig(ArtifactPath(
4832 "aos/events/logging/multinode_pingpong_pi3_pingpong_config.json"));
4833 message_bridge::TestingTimeConverter time_converter(
4834 configuration::NodesCount(&config.message()));
4835 SimulatedEventLoopFactory event_loop_factory(&config.message());
4836 event_loop_factory.SetTimeConverter(&time_converter);
4837
4838 time_converter.StartEqual();
4839
4840 const std::string kLogfile1_1 =
Austin Schuh8fb4b452023-08-04 17:02:27 -07004841 aos::testing::TestTmpDir() + "/logs/multi_logfile1/";
Austin Schuh1124c512023-08-01 15:20:44 -07004842
4843 NodeEventLoopFactory *const pi1 =
4844 event_loop_factory.GetNodeEventLoopFactory("pi1");
4845 NodeEventLoopFactory *const pi2 =
4846 event_loop_factory.GetNodeEventLoopFactory("pi2");
4847 NodeEventLoopFactory *const pi3 =
4848 event_loop_factory.GetNodeEventLoopFactory("pi3");
4849
4850 // What we want is for pi2 to send a message at t=1000 on the first channel
4851 // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
4852 // the max out of order duration be large.
4853 //
4854 // Then, we disconnect, and only send messages on a third channel
4855 // (/atest2 pong). The order is key, they need to sort in this order in the
4856 // config so we observe them in the order which grows the
4857 // max_out_of_order_duration.
4858
4859 pi1->Disconnect(pi2->node());
4860 pi2->Disconnect(pi1->node());
4861
4862 pi1->Disconnect(pi3->node());
4863 pi3->Disconnect(pi1->node());
4864
4865 std::vector<std::string> filenames;
4866 pi2->AlwaysStart<PongSender>("pongsender", "/test2");
4867 pi3->AlwaysStart<PongSender>("pongsender", "/test3");
4868
4869 event_loop_factory.RunFor(chrono::seconds(10));
4870
4871 {
4872 // Now start a receiving node first. This sets up 2 tight bounds between
4873 // 2 of the nodes.
4874 LoggerState pi1_logger = MakeLoggerState(
Austin Schuh6ecfe902023-08-04 22:44:37 -07004875 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0],
4876 FileStrategy::kKeepSeparate);
Austin Schuh1124c512023-08-01 15:20:44 -07004877 pi1_logger.StartLogger(kLogfile1_1);
4878
4879 event_loop_factory.RunFor(chrono::seconds(10));
4880
4881 // Now, reconnect, and everything should recover.
4882 pi1->Connect(pi2->node());
4883 pi2->Connect(pi1->node());
4884
4885 event_loop_factory.RunFor(chrono::seconds(10));
4886
4887 pi1->Connect(pi3->node());
4888 pi3->Connect(pi1->node());
4889
4890 event_loop_factory.RunFor(chrono::seconds(10));
4891
4892 pi1_logger.AppendAllFilenames(&filenames);
4893 }
4894
4895 // Make sure we can read this.
4896 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4897 EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
4898 auto result = ConfirmReadable(filenames);
4899}
4900
Stephan Pleinesf63bde82024-01-13 15:59:33 -08004901} // namespace aos::logger::testing