blob: 7313b8f10047144808a3d50091def4d9c41ffcf7 [file] [log] [blame]
James Kuszmaul38735e82019-12-07 16:42:06 -08001#include "aos/events/logging/logger.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08002
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07005#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08006#include "aos/events/ping_lib.h"
7#include "aos/events/pong_lib.h"
8#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -08009#include "aos/network/remote_message_generated.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070010#include "aos/network/timestamp_generated.h"
Austin Schuhc243b422020-10-11 15:35:08 -070011#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070012#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080013#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080014#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080015#include "gtest/gtest.h"
16
Austin Schuh3bd4c402020-11-06 18:19:06 -080017#ifdef LZMA
18#include "aos/events/logging/lzma_encoder.h"
19#endif
20
Austin Schuhe309d2a2019-11-29 13:25:21 -080021namespace aos {
22namespace logger {
23namespace testing {
24
25namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080026using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070027using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080028
29class LoggerTest : public ::testing::Test {
30 public:
31 LoggerTest()
32 : config_(
33 aos::configuration::ReadConfig("aos/events/pingpong_config.json")),
34 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080035 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080036 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080037 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080038 pong_(pong_event_loop_.get()) {}
39
40 // Config and factory.
41 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
42 SimulatedEventLoopFactory event_loop_factory_;
43
44 // Event loop and app for Ping
45 std::unique_ptr<EventLoop> ping_event_loop_;
46 Ping ping_;
47
48 // Event loop and app for Pong
49 std::unique_ptr<EventLoop> pong_event_loop_;
50 Pong pong_;
51};
52
Brian Silverman1f345222020-09-24 21:14:48 -070053using LoggerDeathTest = LoggerTest;
54
Austin Schuhe309d2a2019-11-29 13:25:21 -080055// Tests that we can startup at all. This confirms that the channels are all in
56// the config.
57TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070058 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070059 const ::std::string base_name = tmpdir + "/logfile";
60 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 // Remove it.
62 unlink(logfile.c_str());
63
64 LOG(INFO) << "Logging data to " << logfile;
65
66 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080067 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080068 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080069
70 event_loop_factory_.RunFor(chrono::milliseconds(95));
71
Brian Silverman1f345222020-09-24 21:14:48 -070072 Logger logger(logger_event_loop.get());
73 logger.set_polling_period(std::chrono::milliseconds(100));
74 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -080075 event_loop_factory_.RunFor(chrono::milliseconds(20000));
76 }
77
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -080078 // Even though it doesn't make any difference here, exercise the logic for
79 // passing in a separate config.
80 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -080081
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -080082 // Confirm that we can remap logged channels to point to new buses.
83 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -080084
Austin Schuh15649d62019-12-28 16:36:38 -080085 // This sends out the fetched messages and advances time to the start of the
86 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -080087 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -080088
Austin Schuh6f3babe2020-01-26 20:34:50 -080089 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -080090
Austin Schuhe309d2a2019-11-29 13:25:21 -080091 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -080092 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -080093
94 int ping_count = 10;
95 int pong_count = 10;
96
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -080097 // Confirm that the ping value matches in the remapped channel location.
98 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -080099 [&ping_count](const examples::Ping &ping) {
100 EXPECT_EQ(ping.value(), ping_count + 1);
101 ++ping_count;
102 });
103 // Confirm that the ping and pong counts both match, and the value also
104 // matches.
105 test_event_loop->MakeWatcher(
106 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
107 EXPECT_EQ(pong.value(), pong_count + 1);
108 ++pong_count;
109 EXPECT_EQ(ping_count, pong_count);
110 });
111
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800112 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800114}
115
Brian Silverman1f345222020-09-24 21:14:48 -0700116// Tests calling StartLogging twice.
117TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800118 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700119 const ::std::string base_name1 = tmpdir + "/logfile1";
120 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
121 const ::std::string base_name2 = tmpdir + "/logfile2";
122 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
123 unlink(logfile1.c_str());
124 unlink(logfile2.c_str());
125
126 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
127
128 {
129 std::unique_ptr<EventLoop> logger_event_loop =
130 event_loop_factory_.MakeEventLoop("logger");
131
132 event_loop_factory_.RunFor(chrono::milliseconds(95));
133
134 Logger logger(logger_event_loop.get());
135 logger.set_polling_period(std::chrono::milliseconds(100));
136 logger_event_loop->OnRun(
137 [base_name1, base_name2, &logger_event_loop, &logger]() {
138 logger.StartLogging(std::make_unique<LocalLogNamer>(
139 base_name1, logger_event_loop->node()));
140 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
141 base_name2, logger_event_loop->node())),
142 "Already logging");
143 });
144 event_loop_factory_.RunFor(chrono::milliseconds(20000));
145 }
146}
147
148// Tests calling StopLogging twice.
149TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800150 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string base_name = tmpdir + "/logfile";
152 const ::std::string logfile = base_name + ".part0.bfbs";
153 // Remove it.
154 unlink(logfile.c_str());
155
156 LOG(INFO) << "Logging data to " << logfile;
157
158 {
159 std::unique_ptr<EventLoop> logger_event_loop =
160 event_loop_factory_.MakeEventLoop("logger");
161
162 event_loop_factory_.RunFor(chrono::milliseconds(95));
163
164 Logger logger(logger_event_loop.get());
165 logger.set_polling_period(std::chrono::milliseconds(100));
166 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
167 logger.StartLogging(std::make_unique<LocalLogNamer>(
168 base_name, logger_event_loop->node()));
169 logger.StopLogging(aos::monotonic_clock::min_time);
170 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
171 "Not logging right now");
172 });
173 event_loop_factory_.RunFor(chrono::milliseconds(20000));
174 }
175}
176
177// Tests that we can startup twice.
178TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800179 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700180 const ::std::string base_name1 = tmpdir + "/logfile1";
181 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
182 const ::std::string base_name2 = tmpdir + "/logfile2";
183 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
184 unlink(logfile1.c_str());
185 unlink(logfile2.c_str());
186
187 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
188
189 {
190 std::unique_ptr<EventLoop> logger_event_loop =
191 event_loop_factory_.MakeEventLoop("logger");
192
193 event_loop_factory_.RunFor(chrono::milliseconds(95));
194
195 Logger logger(logger_event_loop.get());
196 logger.set_polling_period(std::chrono::milliseconds(100));
197 logger.StartLogging(
198 std::make_unique<LocalLogNamer>(base_name1, logger_event_loop->node()));
199 event_loop_factory_.RunFor(chrono::milliseconds(10000));
200 logger.StopLogging(logger_event_loop->monotonic_now());
201 event_loop_factory_.RunFor(chrono::milliseconds(10000));
202 logger.StartLogging(
203 std::make_unique<LocalLogNamer>(base_name2, logger_event_loop->node()));
204 event_loop_factory_.RunFor(chrono::milliseconds(10000));
205 }
206
207 for (const auto &logfile :
208 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
209 SCOPED_TRACE(std::get<0>(logfile));
210 LogReader reader(std::get<0>(logfile));
211 reader.Register();
212
213 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(nullptr));
214
215 std::unique_ptr<EventLoop> test_event_loop =
216 reader.event_loop_factory()->MakeEventLoop("log_reader");
217
218 int ping_count = std::get<1>(logfile);
219 int pong_count = std::get<1>(logfile);
220
221 // Confirm that the ping and pong counts both match, and the value also
222 // matches.
223 test_event_loop->MakeWatcher("/test",
224 [&ping_count](const examples::Ping &ping) {
225 EXPECT_EQ(ping.value(), ping_count + 1);
226 ++ping_count;
227 });
228 test_event_loop->MakeWatcher(
229 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
230 EXPECT_EQ(pong.value(), pong_count + 1);
231 ++pong_count;
232 EXPECT_EQ(ping_count, pong_count);
233 });
234
235 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
236 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
237 }
238}
239
Austin Schuhfa895892020-01-07 20:07:41 -0800240// Tests that we can read and write rotated log files.
241TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800242 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700243 const ::std::string base_name = tmpdir + "/logfile";
244 const ::std::string logfile0 = base_name + ".part0.bfbs";
245 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800246 // Remove it.
247 unlink(logfile0.c_str());
248 unlink(logfile1.c_str());
249
250 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
251
252 {
Austin Schuhfa895892020-01-07 20:07:41 -0800253 std::unique_ptr<EventLoop> logger_event_loop =
254 event_loop_factory_.MakeEventLoop("logger");
255
256 event_loop_factory_.RunFor(chrono::milliseconds(95));
257
Brian Silverman1f345222020-09-24 21:14:48 -0700258 Logger logger(logger_event_loop.get());
259 logger.set_polling_period(std::chrono::milliseconds(100));
260 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800261 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700262 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800263 event_loop_factory_.RunFor(chrono::milliseconds(10000));
264 }
265
Austin Schuh64fab802020-09-09 22:47:47 -0700266 {
267 // Confirm that the UUIDs match for both the parts and the logger, and the
268 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800269 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700270 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800271 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700272 }
273
Brian Silvermanae7c0332020-09-30 16:58:23 -0700274 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
275 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700276 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
277 log_header[1].message().parts_uuid()->string_view());
278
279 EXPECT_EQ(log_header[0].message().parts_index(), 0);
280 EXPECT_EQ(log_header[1].message().parts_index(), 1);
281 }
282
Austin Schuhfa895892020-01-07 20:07:41 -0800283 // Even though it doesn't make any difference here, exercise the logic for
284 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800285 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800286
287 // Confirm that we can remap logged channels to point to new buses.
288 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
289
290 // This sends out the fetched messages and advances time to the start of the
291 // log file.
292 reader.Register();
293
Austin Schuh6f3babe2020-01-26 20:34:50 -0800294 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800295
296 std::unique_ptr<EventLoop> test_event_loop =
297 reader.event_loop_factory()->MakeEventLoop("log_reader");
298
299 int ping_count = 10;
300 int pong_count = 10;
301
302 // Confirm that the ping value matches in the remapped channel location.
303 test_event_loop->MakeWatcher("/original/test",
304 [&ping_count](const examples::Ping &ping) {
305 EXPECT_EQ(ping.value(), ping_count + 1);
306 ++ping_count;
307 });
308 // Confirm that the ping and pong counts both match, and the value also
309 // matches.
310 test_event_loop->MakeWatcher(
311 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
312 EXPECT_EQ(pong.value(), pong_count + 1);
313 ++pong_count;
314 EXPECT_EQ(ping_count, pong_count);
315 });
316
317 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
318 EXPECT_EQ(ping_count, 2010);
319}
320
Austin Schuh4c4e0092019-12-22 16:18:03 -0800321// Tests that a large number of messages per second doesn't overwhelm writev.
322TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800323 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700324 const ::std::string base_name = tmpdir + "/logfile";
325 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800326 // Remove the log file.
327 unlink(logfile.c_str());
328
329 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700330 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800331
332 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800333 std::unique_ptr<EventLoop> logger_event_loop =
334 event_loop_factory_.MakeEventLoop("logger");
335
336 std::unique_ptr<EventLoop> ping_spammer_event_loop =
337 event_loop_factory_.MakeEventLoop("ping_spammer");
338 aos::Sender<examples::Ping> ping_sender =
339 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
340
341 aos::TimerHandler *timer_handler =
342 ping_spammer_event_loop->AddTimer([&ping_sender]() {
343 aos::Sender<examples::Ping>::Builder builder =
344 ping_sender.MakeBuilder();
345 examples::Ping::Builder ping_builder =
346 builder.MakeBuilder<examples::Ping>();
347 CHECK(builder.Send(ping_builder.Finish()));
348 });
349
350 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
351 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
352 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
353 chrono::microseconds(50));
354 });
355
Brian Silverman1f345222020-09-24 21:14:48 -0700356 Logger logger(logger_event_loop.get());
357 logger.set_polling_period(std::chrono::milliseconds(100));
358 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800359
360 event_loop_factory_.RunFor(chrono::milliseconds(1000));
361 }
362}
363
Austin Schuh315b96b2020-12-11 21:21:12 -0800364std::vector<std::string> MakeLogFiles(std::string logfile_base) {
365 return std::vector<std::string>(
366 {logfile_base + "_pi1_data.part0.bfbs",
367 logfile_base + "_pi2_data/test/aos.examples.Pong.part0.bfbs",
368 logfile_base + "_pi2_data/test/aos.examples.Pong.part1.bfbs",
369 logfile_base + "_pi2_data.part0.bfbs",
370 logfile_base + "_timestamps/pi1/aos/remote_timestamps/pi2/"
371 "aos.message_bridge.RemoteMessage.part0.bfbs",
372 logfile_base + "_timestamps/pi1/aos/remote_timestamps/pi2/"
373 "aos.message_bridge.RemoteMessage.part1.bfbs",
374 logfile_base + "_timestamps/pi2/aos/remote_timestamps/pi1/"
375 "aos.message_bridge.RemoteMessage.part0.bfbs",
376 logfile_base + "_timestamps/pi2/aos/remote_timestamps/pi1/"
377 "aos.message_bridge.RemoteMessage.part1.bfbs",
378 logfile_base +
379 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs",
380 logfile_base +
381 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs",
382 logfile_base +
383 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs",
384 logfile_base +
385 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs"});
386}
387
Austin Schuh15649d62019-12-28 16:36:38 -0800388class MultinodeLoggerTest : public ::testing::Test {
389 public:
390 MultinodeLoggerTest()
391 : config_(aos::configuration::ReadConfig(
Austin Schuhe84c3ed2019-12-14 15:29:48 -0800392 "aos/events/logging/multinode_pingpong_config.json")),
Austin Schuhac0771c2020-01-07 18:36:30 -0800393 event_loop_factory_(&config_.message()),
Austin Schuhcde938c2020-02-02 17:30:07 -0800394 pi1_(
395 configuration::GetNode(event_loop_factory_.configuration(), "pi1")),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700396 pi2_(
397 configuration::GetNode(event_loop_factory_.configuration(), "pi2")),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800398 tmp_dir_(aos::testing::TestTmpDir()),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700399 logfile_base_(tmp_dir_ + "/multi_logfile"),
Austin Schuh315b96b2020-12-11 21:21:12 -0800400 pi1_reboot_logfiles_(
Austin Schuh2f8fd752020-09-01 22:38:28 -0700401 {logfile_base_ + "_pi1_data.part0.bfbs",
402 logfile_base_ + "_pi2_data/test/aos.examples.Pong.part0.bfbs",
403 logfile_base_ + "_pi2_data/test/aos.examples.Pong.part1.bfbs",
Austin Schuh315b96b2020-12-11 21:21:12 -0800404 logfile_base_ + "_pi2_data/test/aos.examples.Pong.part2.bfbs",
Austin Schuh2f8fd752020-09-01 22:38:28 -0700405 logfile_base_ + "_timestamps/pi1/aos/remote_timestamps/pi2/"
Austin Schuh0de30f32020-12-06 12:44:28 -0800406 "aos.message_bridge.RemoteMessage.part0.bfbs",
Austin Schuh2f8fd752020-09-01 22:38:28 -0700407 logfile_base_ + "_timestamps/pi1/aos/remote_timestamps/pi2/"
Austin Schuh0de30f32020-12-06 12:44:28 -0800408 "aos.message_bridge.RemoteMessage.part1.bfbs",
Austin Schuh315b96b2020-12-11 21:21:12 -0800409 logfile_base_ + "_timestamps/pi1/aos/remote_timestamps/pi2/"
410 "aos.message_bridge.RemoteMessage.part2.bfbs",
Austin Schuh2f8fd752020-09-01 22:38:28 -0700411 logfile_base_ +
412 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs",
413 logfile_base_ +
Austin Schuh315b96b2020-12-11 21:21:12 -0800414 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs",
415 logfile_base_ +
416 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs"}),
417 logfiles_(MakeLogFiles(logfile_base_)),
Austin Schuhc9049732020-12-21 22:27:15 -0800418 pi1_single_direction_logfiles_(
419 {logfile_base_ + "_pi1_data.part0.bfbs",
420 logfile_base_ + "_pi2_data/test/aos.examples.Pong.part0.bfbs",
421 logfile_base_ + "_timestamps/pi1/aos/remote_timestamps/pi2/"
422 "aos.message_bridge.RemoteMessage.part0.bfbs",
423 logfile_base_ +
424 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs"}),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700425 structured_logfiles_{
426 std::vector<std::string>{logfiles_[0]},
427 std::vector<std::string>{logfiles_[1], logfiles_[2]},
428 std::vector<std::string>{logfiles_[3]},
429 std::vector<std::string>{logfiles_[4], logfiles_[5]},
430 std::vector<std::string>{logfiles_[6], logfiles_[7]},
431 std::vector<std::string>{logfiles_[8], logfiles_[9]},
432 std::vector<std::string>{logfiles_[10], logfiles_[11]}},
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700433 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping", pi1_)),
434 ping_(ping_event_loop_.get()),
435 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong", pi2_)),
436 pong_(pong_event_loop_.get()) {
437 // Go through and remove the logfiles if they already exist.
438 for (const auto file : logfiles_) {
439 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800440 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700441 }
442
Austin Schuh315b96b2020-12-11 21:21:12 -0800443 for (const auto file : MakeLogFiles("relogged")) {
444 unlink(file.c_str());
445 }
446
447 for (const auto file : pi1_reboot_logfiles_) {
448 unlink(file.c_str());
449 }
450
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700451 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
452 << " and " << logfiles_[2];
453 }
454
455 struct LoggerState {
456 std::unique_ptr<EventLoop> event_loop;
457 std::unique_ptr<Logger> logger;
458 };
459
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700460 LoggerState MakeLogger(const Node *node,
461 SimulatedEventLoopFactory *factory = nullptr) {
462 if (factory == nullptr) {
463 factory = &event_loop_factory_;
464 }
465 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700466 }
467
Austin Schuh3bd4c402020-11-06 18:19:06 -0800468 void StartLogger(LoggerState *logger, std::string logfile_base = "",
469 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700470 if (logfile_base.empty()) {
471 logfile_base = logfile_base_;
472 }
473
Brian Silverman1f345222020-09-24 21:14:48 -0700474 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
475 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800476 logger->logger->set_name(absl::StrCat(
477 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800478 logger->event_loop->OnRun([logger, logfile_base, compress]() {
479 std::unique_ptr<MultiNodeLogNamer> namer =
480 std::make_unique<MultiNodeLogNamer>(
481 logfile_base, logger->event_loop->configuration(),
482 logger->event_loop->node());
483 if (compress) {
484#ifdef LZMA
485 namer->set_extension(".xz");
486 namer->set_encoder_factory(
487 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
488#else
489 LOG(FATAL) << "Compression unsupported";
490#endif
491 }
492
493 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700494 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700495 }
Austin Schuh15649d62019-12-28 16:36:38 -0800496
Austin Schuh3bd4c402020-11-06 18:19:06 -0800497 void VerifyParts(const std::vector<LogFile> &sorted_parts,
498 const std::vector<std::string> &corrupted_parts = {}) {
499 EXPECT_EQ(sorted_parts.size(), 2u);
500
501 // Count up the number of UUIDs and make sure they are what we expect as a
502 // sanity check.
503 std::set<std::string> log_event_uuids;
504 std::set<std::string> parts_uuids;
505 std::set<std::string> both_uuids;
506
507 size_t missing_rt_count = 0;
508
509 std::vector<std::string> logger_nodes;
510 for (const LogFile &log_file : sorted_parts) {
511 EXPECT_FALSE(log_file.log_event_uuid.empty());
512 log_event_uuids.insert(log_file.log_event_uuid);
513 logger_nodes.emplace_back(log_file.logger_node);
514 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800515 EXPECT_TRUE(log_file.config);
516 EXPECT_EQ(log_file.name,
517 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800518
519 for (const LogParts &part : log_file.parts) {
520 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
521 << ": " << part;
522 missing_rt_count +=
523 part.realtime_start_time == aos::realtime_clock::min_time;
524
525 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
526 log_event_uuids.end());
527 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800528 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800529 parts_uuids.insert(part.parts_uuid);
530 both_uuids.insert(part.parts_uuid);
531 }
532 }
533
534 // We won't have RT timestamps for 5 log files. We don't log the RT start
535 // time on remote nodes because we don't know it and would be guessing. And
536 // the log reader can actually do a better job.
537 EXPECT_EQ(missing_rt_count, 5u);
538
539 EXPECT_EQ(log_event_uuids.size(), 2u);
540 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
541 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
542
543 // Test that each list of parts is in order. Don't worry about the ordering
544 // between part file lists though.
545 // (inner vectors all need to be in order, but outer one doesn't matter).
546 EXPECT_THAT(ToLogReaderVector(sorted_parts),
547 ::testing::UnorderedElementsAreArray(structured_logfiles_));
548
549 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
550
551 EXPECT_NE(sorted_parts[0].realtime_start_time,
552 aos::realtime_clock::min_time);
553 EXPECT_NE(sorted_parts[1].realtime_start_time,
554 aos::realtime_clock::min_time);
555
556 EXPECT_NE(sorted_parts[0].monotonic_start_time,
557 aos::monotonic_clock::min_time);
558 EXPECT_NE(sorted_parts[1].monotonic_start_time,
559 aos::monotonic_clock::min_time);
560
561 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
562 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
563 }
564
Austin Schuhc9049732020-12-21 22:27:15 -0800565 void ConfirmReadable(const std::vector<std::string> &files) {
566 LogReader reader(SortParts(files));
567
568 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
569 reader.Register(&log_reader_factory);
570
571 log_reader_factory.Run();
572
573 reader.Deregister();
574 }
575
Austin Schuh3bd4c402020-11-06 18:19:06 -0800576 void AddExtension(std::string_view extension) {
577 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
578 [extension](const std::string &in) {
579 return absl::StrCat(in, extension);
580 });
581
582 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
583 structured_logfiles_.begin(),
584 [extension](std::vector<std::string> in) {
585 std::transform(in.begin(), in.end(), in.begin(),
586 [extension](const std::string &in_str) {
587 return absl::StrCat(in_str, extension);
588 });
589 return in;
590 });
591 }
592
Austin Schuh15649d62019-12-28 16:36:38 -0800593 // Config and factory.
594 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
595 SimulatedEventLoopFactory event_loop_factory_;
596
Austin Schuhcde938c2020-02-02 17:30:07 -0800597 const Node *pi1_;
598 const Node *pi2_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700599
600 std::string tmp_dir_;
601 std::string logfile_base_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800602 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700603 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800604 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700605
606 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700607
608 std::unique_ptr<EventLoop> ping_event_loop_;
609 Ping ping_;
610 std::unique_ptr<EventLoop> pong_event_loop_;
611 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800612};
613
Austin Schuh391e3172020-09-01 22:48:18 -0700614// Counts the number of messages on a channel. Returns (channel name, channel
615// type, count) for every message matching matcher()
616std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh6f3babe2020-01-26 20:34:50 -0800617 std::string_view filename,
618 std::function<bool(const MessageHeader *)> matcher) {
619 MessageReader message_reader(filename);
620 std::vector<int> counts(
621 message_reader.log_file_header()->configuration()->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800622
Austin Schuh6f3babe2020-01-26 20:34:50 -0800623 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800624 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800625 message_reader.ReadMessage();
626 if (!msg) {
627 break;
628 }
629
630 if (matcher(&msg.value().message())) {
631 counts[msg.value().message().channel_index()]++;
632 }
633 }
634
Austin Schuh391e3172020-09-01 22:48:18 -0700635 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800636 int channel = 0;
637 for (size_t i = 0; i < counts.size(); ++i) {
638 if (counts[i] != 0) {
Austin Schuh391e3172020-09-01 22:48:18 -0700639 const Channel *channel =
640 message_reader.log_file_header()->configuration()->channels()->Get(i);
641 result.push_back(std::make_tuple(channel->name()->str(),
642 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800643 }
644 ++channel;
645 }
646
647 return result;
648}
649
650// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700651std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
652 std::string_view filename) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800653 return CountChannelsMatching(filename, [](const MessageHeader *msg) {
654 if (msg->has_data()) {
655 CHECK(!msg->has_monotonic_remote_time());
656 CHECK(!msg->has_realtime_remote_time());
657 CHECK(!msg->has_remote_queue_index());
658 return true;
659 }
660 return false;
661 });
662}
663
664// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700665std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh6f3babe2020-01-26 20:34:50 -0800666 std::string_view filename) {
667 return CountChannelsMatching(filename, [](const MessageHeader *msg) {
668 if (!msg->has_data()) {
669 CHECK(msg->has_monotonic_remote_time());
670 CHECK(msg->has_realtime_remote_time());
671 CHECK(msg->has_remote_queue_index());
672 return true;
673 }
674 return false;
675 });
676}
677
Austin Schuhcde938c2020-02-02 17:30:07 -0800678// Tests that we can write and read simple multi-node log files.
679TEST_F(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh15649d62019-12-28 16:36:38 -0800680 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700681 LoggerState pi1_logger = MakeLogger(pi1_);
682 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800683
684 event_loop_factory_.RunFor(chrono::milliseconds(95));
685
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700686 StartLogger(&pi1_logger);
687 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800688
Austin Schuh15649d62019-12-28 16:36:38 -0800689 event_loop_factory_.RunFor(chrono::milliseconds(20000));
690 }
691
Austin Schuh6f3babe2020-01-26 20:34:50 -0800692 {
Austin Schuh64fab802020-09-09 22:47:47 -0700693 std::set<std::string> logfile_uuids;
694 std::set<std::string> parts_uuids;
695 // Confirm that we have the expected number of UUIDs for both the logfile
696 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800697 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700698 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800699 log_header.emplace_back(ReadHeader(f).value());
Brian Silvermanae7c0332020-09-30 16:58:23 -0700700 logfile_uuids.insert(log_header.back().message().log_event_uuid()->str());
Austin Schuh64fab802020-09-09 22:47:47 -0700701 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
702 }
Austin Schuh15649d62019-12-28 16:36:38 -0800703
Austin Schuh64fab802020-09-09 22:47:47 -0700704 EXPECT_EQ(logfile_uuids.size(), 2u);
705 EXPECT_EQ(parts_uuids.size(), 7u);
706
707 // And confirm everything is on the correct node.
708 EXPECT_EQ(log_header[0].message().node()->name()->string_view(), "pi1");
709 EXPECT_EQ(log_header[1].message().node()->name()->string_view(), "pi2");
710 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi2");
711 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi2");
712 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
713 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
714 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi1");
715 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi1");
716 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
717 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
718 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
719 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
720
721 // And the parts index matches.
722 EXPECT_EQ(log_header[0].message().parts_index(), 0);
723 EXPECT_EQ(log_header[1].message().parts_index(), 0);
724 EXPECT_EQ(log_header[2].message().parts_index(), 1);
725 EXPECT_EQ(log_header[3].message().parts_index(), 0);
726 EXPECT_EQ(log_header[4].message().parts_index(), 0);
727 EXPECT_EQ(log_header[5].message().parts_index(), 1);
728 EXPECT_EQ(log_header[6].message().parts_index(), 0);
729 EXPECT_EQ(log_header[7].message().parts_index(), 1);
730 EXPECT_EQ(log_header[8].message().parts_index(), 0);
731 EXPECT_EQ(log_header[9].message().parts_index(), 1);
732 EXPECT_EQ(log_header[10].message().parts_index(), 0);
733 EXPECT_EQ(log_header[11].message().parts_index(), 1);
734 }
735
736 {
Austin Schuh391e3172020-09-01 22:48:18 -0700737 using ::testing::UnorderedElementsAre;
738
Austin Schuh6f3babe2020-01-26 20:34:50 -0800739 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700740 EXPECT_THAT(
741 CountChannelsData(logfiles_[0]),
742 UnorderedElementsAre(
743 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
744 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800745 std::make_tuple("/test", "aos.examples.Ping", 2001)))
746 << " : " << logfiles_[0];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800747 // Timestamps for pong
Austin Schuh2f8fd752020-09-01 22:38:28 -0700748 EXPECT_THAT(
749 CountChannelsTimestamp(logfiles_[0]),
750 UnorderedElementsAre(
751 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800752 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
753 << " : " << logfiles_[0];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800754
755 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800756 EXPECT_THAT(
757 CountChannelsData(logfiles_[1]),
758 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
759 << " : " << logfiles_[1];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700760 EXPECT_THAT(CountChannelsData(logfiles_[2]),
761 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800762 std::make_tuple("/test", "aos.examples.Pong", 1910)))
763 << " : " << logfiles_[1];
Austin Schuh391e3172020-09-01 22:48:18 -0700764
Austin Schuh6f3babe2020-01-26 20:34:50 -0800765 // No timestamps
Austin Schuh20ac95d2020-12-05 17:24:19 -0800766 EXPECT_THAT(CountChannelsTimestamp(logfiles_[1]), UnorderedElementsAre())
767 << " : " << logfiles_[1];
768 EXPECT_THAT(CountChannelsTimestamp(logfiles_[2]), UnorderedElementsAre())
769 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800770
771 // Timing reports and pongs.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700772 EXPECT_THAT(
773 CountChannelsData(logfiles_[3]),
774 UnorderedElementsAre(
775 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
776 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800777 std::make_tuple("/test", "aos.examples.Pong", 2001)))
778 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800779 // And ping timestamps.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700780 EXPECT_THAT(
781 CountChannelsTimestamp(logfiles_[3]),
782 UnorderedElementsAre(
783 std::make_tuple("/test", "aos.examples.Ping", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800784 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
785 << " : " << logfiles_[3];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700786
787 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800788 EXPECT_THAT(CountChannelsData(logfiles_[4]), UnorderedElementsAre())
789 << " : " << logfiles_[4];
790 EXPECT_THAT(CountChannelsData(logfiles_[5]), UnorderedElementsAre())
791 << " : " << logfiles_[5];
792 EXPECT_THAT(CountChannelsData(logfiles_[6]), UnorderedElementsAre())
793 << " : " << logfiles_[6];
794 EXPECT_THAT(CountChannelsData(logfiles_[7]), UnorderedElementsAre())
795 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700796 EXPECT_THAT(
797 CountChannelsTimestamp(logfiles_[4]),
798 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800799 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
800 std::make_tuple("/test", "aos.examples.Ping", 91)))
801 << " : " << logfiles_[4];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700802 EXPECT_THAT(
803 CountChannelsTimestamp(logfiles_[5]),
804 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800805 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
806 std::make_tuple("/test", "aos.examples.Ping", 1910)))
807 << " : " << logfiles_[5];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700808 EXPECT_THAT(CountChannelsTimestamp(logfiles_[6]),
809 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800810 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
811 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700812 EXPECT_THAT(CountChannelsTimestamp(logfiles_[7]),
813 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800814 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
815 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700816
817 // And then test that the remotely logged timestamp data files only have
818 // timestamps in them.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800819 EXPECT_THAT(CountChannelsTimestamp(logfiles_[8]), UnorderedElementsAre())
820 << " : " << logfiles_[8];
821 EXPECT_THAT(CountChannelsTimestamp(logfiles_[9]), UnorderedElementsAre())
822 << " : " << logfiles_[9];
823 EXPECT_THAT(CountChannelsTimestamp(logfiles_[10]), UnorderedElementsAre())
824 << " : " << logfiles_[10];
825 EXPECT_THAT(CountChannelsTimestamp(logfiles_[11]), UnorderedElementsAre())
826 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700827
828 EXPECT_THAT(CountChannelsData(logfiles_[8]),
829 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800830 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
831 << " : " << logfiles_[8];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700832 EXPECT_THAT(CountChannelsData(logfiles_[9]),
833 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800834 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
835 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700836
837 EXPECT_THAT(CountChannelsData(logfiles_[10]),
838 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800839 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
840 << " : " << logfiles_[10];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700841 EXPECT_THAT(CountChannelsData(logfiles_[11]),
842 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800843 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
844 << " : " << logfiles_[11];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800845 }
846
Austin Schuh287d43d2020-12-04 20:19:33 -0800847 LogReader reader(SortParts(logfiles_));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800848
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700849 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -0800850 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -0800851
852 // This sends out the fetched messages and advances time to the start of the
853 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -0800854 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800855
Austin Schuhac0771c2020-01-07 18:36:30 -0800856 const Node *pi1 =
857 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -0800858 const Node *pi2 =
859 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -0800860
Austin Schuh2f8fd752020-09-01 22:38:28 -0700861 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
862 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
863 LOG(INFO) << "now pi1 "
864 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
865 LOG(INFO) << "now pi2 "
866 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
867
Austin Schuh6f3babe2020-01-26 20:34:50 -0800868 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800869
870 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -0800871
Austin Schuh6f3babe2020-01-26 20:34:50 -0800872 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -0800873 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800874 std::unique_ptr<EventLoop> pi2_event_loop =
875 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -0800876
Austin Schuh6f3babe2020-01-26 20:34:50 -0800877 int pi1_ping_count = 10;
878 int pi2_ping_count = 10;
879 int pi1_pong_count = 10;
880 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -0800881
882 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800883 pi1_event_loop->MakeWatcher(
884 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -0700885 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -0800886 << pi1_event_loop->context().monotonic_remote_time << " -> "
887 << pi1_event_loop->context().monotonic_event_time;
888 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
889 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
890 pi1_ping_count * chrono::milliseconds(10) +
891 monotonic_clock::epoch());
892 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
893 pi1_ping_count * chrono::milliseconds(10) +
894 realtime_clock::epoch());
895 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
896 pi1_event_loop->context().monotonic_event_time);
897 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
898 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -0800899
Austin Schuh6f3babe2020-01-26 20:34:50 -0800900 ++pi1_ping_count;
901 });
902 pi2_event_loop->MakeWatcher(
903 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -0700904 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -0800905 << pi2_event_loop->context().monotonic_remote_time << " -> "
906 << pi2_event_loop->context().monotonic_event_time;
907 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
908
909 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
910 pi2_ping_count * chrono::milliseconds(10) +
911 monotonic_clock::epoch());
912 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
913 pi2_ping_count * chrono::milliseconds(10) +
914 realtime_clock::epoch());
915 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
916 chrono::microseconds(150),
917 pi2_event_loop->context().monotonic_event_time);
918 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
919 chrono::microseconds(150),
920 pi2_event_loop->context().realtime_event_time);
921 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -0800922 });
923
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700924 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800925 // Confirm that the ping and pong counts both match, and the value also
926 // matches.
927 pi1_event_loop->MakeWatcher(
928 "/test", [&pi1_event_loop, &pi1_ping_count,
929 &pi1_pong_count](const examples::Pong &pong) {
930 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
931 << pi1_event_loop->context().monotonic_remote_time << " -> "
932 << pi1_event_loop->context().monotonic_event_time;
933
934 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
935 pi1_pong_count + kQueueIndexOffset);
936 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
937 chrono::microseconds(200) +
938 pi1_pong_count * chrono::milliseconds(10) +
939 monotonic_clock::epoch());
940 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
941 chrono::microseconds(200) +
942 pi1_pong_count * chrono::milliseconds(10) +
943 realtime_clock::epoch());
944
945 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
946 chrono::microseconds(150),
947 pi1_event_loop->context().monotonic_event_time);
948 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
949 chrono::microseconds(150),
950 pi1_event_loop->context().realtime_event_time);
951
952 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
953 ++pi1_pong_count;
954 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
955 });
956 pi2_event_loop->MakeWatcher(
957 "/test", [&pi2_event_loop, &pi2_ping_count,
958 &pi2_pong_count](const examples::Pong &pong) {
959 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
960 << pi2_event_loop->context().monotonic_remote_time << " -> "
961 << pi2_event_loop->context().monotonic_event_time;
962
963 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700964 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800965
966 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
967 chrono::microseconds(200) +
968 pi2_pong_count * chrono::milliseconds(10) +
969 monotonic_clock::epoch());
970 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
971 chrono::microseconds(200) +
972 pi2_pong_count * chrono::milliseconds(10) +
973 realtime_clock::epoch());
974
975 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
976 pi2_event_loop->context().monotonic_event_time);
977 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
978 pi2_event_loop->context().realtime_event_time);
979
980 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
981 ++pi2_pong_count;
982 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
983 });
984
985 log_reader_factory.Run();
986 EXPECT_EQ(pi1_ping_count, 2010);
987 EXPECT_EQ(pi2_ping_count, 2010);
988 EXPECT_EQ(pi1_pong_count, 2010);
989 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -0800990
991 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -0800992}
993
James Kuszmaul46d82582020-05-09 19:50:09 -0700994typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
995
996// Test that if we feed the replay with a mismatched node list that we die on
997// the LogReader constructor.
998TEST_F(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
James Kuszmaul46d82582020-05-09 19:50:09 -0700999 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001000 LoggerState pi1_logger = MakeLogger(pi1_);
1001 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001002
1003 event_loop_factory_.RunFor(chrono::milliseconds(95));
1004
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001005 StartLogger(&pi1_logger);
1006 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001007
James Kuszmaul46d82582020-05-09 19:50:09 -07001008 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1009 }
1010
1011 // Test that, if we add an additional node to the replay config that the
1012 // logger complains about the mismatch in number of nodes.
1013 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1014 configuration::MergeWithConfig(&config_.message(), R"({
1015 "nodes": [
1016 {
1017 "name": "extra-node"
1018 }
1019 ]
1020 }
1021 )");
1022
Austin Schuh287d43d2020-12-04 20:19:33 -08001023 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1024 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001025 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001026}
1027
Austin Schuhcde938c2020-02-02 17:30:07 -08001028// Tests that we can read log files where they don't start at the same monotonic
1029// time.
1030TEST_F(MultinodeLoggerTest, StaggeredStart) {
Austin Schuhcde938c2020-02-02 17:30:07 -08001031 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001032 LoggerState pi1_logger = MakeLogger(pi1_);
1033 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001034
1035 event_loop_factory_.RunFor(chrono::milliseconds(95));
1036
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001037 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001038
1039 event_loop_factory_.RunFor(chrono::milliseconds(200));
1040
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001041 StartLogger(&pi2_logger);
1042
Austin Schuhcde938c2020-02-02 17:30:07 -08001043 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1044 }
1045
Austin Schuh287d43d2020-12-04 20:19:33 -08001046 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001047
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001048 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001049 log_reader_factory.set_send_delay(chrono::microseconds(0));
1050
1051 // This sends out the fetched messages and advances time to the start of the
1052 // log file.
1053 reader.Register(&log_reader_factory);
1054
1055 const Node *pi1 =
1056 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1057 const Node *pi2 =
1058 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1059
1060 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
1061
1062 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1063
1064 std::unique_ptr<EventLoop> pi1_event_loop =
1065 log_reader_factory.MakeEventLoop("test", pi1);
1066 std::unique_ptr<EventLoop> pi2_event_loop =
1067 log_reader_factory.MakeEventLoop("test", pi2);
1068
1069 int pi1_ping_count = 30;
1070 int pi2_ping_count = 30;
1071 int pi1_pong_count = 30;
1072 int pi2_pong_count = 30;
1073
1074 // Confirm that the ping value matches.
1075 pi1_event_loop->MakeWatcher(
1076 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1077 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1078 << pi1_event_loop->context().monotonic_remote_time << " -> "
1079 << pi1_event_loop->context().monotonic_event_time;
1080 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1081
1082 ++pi1_ping_count;
1083 });
1084 pi2_event_loop->MakeWatcher(
1085 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1086 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1087 << pi2_event_loop->context().monotonic_remote_time << " -> "
1088 << pi2_event_loop->context().monotonic_event_time;
1089 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1090
1091 ++pi2_ping_count;
1092 });
1093
1094 // Confirm that the ping and pong counts both match, and the value also
1095 // matches.
1096 pi1_event_loop->MakeWatcher(
1097 "/test", [&pi1_event_loop, &pi1_ping_count,
1098 &pi1_pong_count](const examples::Pong &pong) {
1099 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1100 << pi1_event_loop->context().monotonic_remote_time << " -> "
1101 << pi1_event_loop->context().monotonic_event_time;
1102
1103 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1104 ++pi1_pong_count;
1105 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1106 });
1107 pi2_event_loop->MakeWatcher(
1108 "/test", [&pi2_event_loop, &pi2_ping_count,
1109 &pi2_pong_count](const examples::Pong &pong) {
1110 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1111 << pi2_event_loop->context().monotonic_remote_time << " -> "
1112 << pi2_event_loop->context().monotonic_event_time;
1113
1114 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1115 ++pi2_pong_count;
1116 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1117 });
1118
1119 log_reader_factory.Run();
1120 EXPECT_EQ(pi1_ping_count, 2030);
1121 EXPECT_EQ(pi2_ping_count, 2030);
1122 EXPECT_EQ(pi1_pong_count, 2030);
1123 EXPECT_EQ(pi2_pong_count, 2030);
1124
1125 reader.Deregister();
1126}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001127
Austin Schuh8bd96322020-02-13 21:18:22 -08001128// Tests that we can read log files where the monotonic clocks drift and don't
1129// match correctly. While we are here, also test that different ending times
1130// also is readable.
1131TEST_F(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuhcde938c2020-02-02 17:30:07 -08001132 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001133 LoggerState pi2_logger = MakeLogger(pi2_);
1134
Austin Schuh8bd96322020-02-13 21:18:22 -08001135 NodeEventLoopFactory *pi2 =
1136 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1137 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1138 << pi2->realtime_now() << " distributed "
1139 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001140
Austin Schuh8bd96322020-02-13 21:18:22 -08001141 const chrono::nanoseconds initial_pi2_offset = -chrono::seconds(1000);
1142 chrono::nanoseconds pi2_offset = initial_pi2_offset;
Austin Schuhcde938c2020-02-02 17:30:07 -08001143
Austin Schuhbe69cf32020-08-27 11:38:33 -07001144 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001145 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1146 << pi2->realtime_now() << " distributed "
1147 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001148
Austin Schuh8bd96322020-02-13 21:18:22 -08001149 for (int i = 0; i < 95; ++i) {
1150 pi2_offset += chrono::nanoseconds(200);
Austin Schuhbe69cf32020-08-27 11:38:33 -07001151 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001152 event_loop_factory_.RunFor(chrono::milliseconds(1));
1153 }
Austin Schuhcde938c2020-02-02 17:30:07 -08001154
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001155 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001156
Austin Schuh8bd96322020-02-13 21:18:22 -08001157 event_loop_factory_.RunFor(chrono::milliseconds(200));
Austin Schuhcde938c2020-02-02 17:30:07 -08001158
Austin Schuh8bd96322020-02-13 21:18:22 -08001159 {
1160 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001161 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001162
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001163 StartLogger(&pi1_logger);
Austin Schuh8bd96322020-02-13 21:18:22 -08001164
1165 for (int i = 0; i < 20000; ++i) {
1166 pi2_offset += chrono::nanoseconds(200);
Austin Schuhbe69cf32020-08-27 11:38:33 -07001167 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001168 event_loop_factory_.RunFor(chrono::milliseconds(1));
1169 }
1170
1171 EXPECT_GT(pi2_offset - initial_pi2_offset,
1172 event_loop_factory_.send_delay() +
1173 event_loop_factory_.network_delay());
1174
1175 for (int i = 0; i < 40000; ++i) {
1176 pi2_offset -= chrono::nanoseconds(200);
Austin Schuhbe69cf32020-08-27 11:38:33 -07001177 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001178 event_loop_factory_.RunFor(chrono::milliseconds(1));
1179 }
1180 }
1181
1182 // And log a bit more on pi2.
1183 event_loop_factory_.RunFor(chrono::milliseconds(400));
Austin Schuhcde938c2020-02-02 17:30:07 -08001184 }
1185
Austin Schuh287d43d2020-12-04 20:19:33 -08001186 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001187
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001188 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001189 log_reader_factory.set_send_delay(chrono::microseconds(0));
1190
Austin Schuhcde938c2020-02-02 17:30:07 -08001191 const Node *pi1 =
1192 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1193 const Node *pi2 =
1194 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1195
Austin Schuh2f8fd752020-09-01 22:38:28 -07001196 // This sends out the fetched messages and advances time to the start of the
1197 // log file.
1198 reader.Register(&log_reader_factory);
1199
1200 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1201 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1202 LOG(INFO) << "now pi1 "
1203 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1204 LOG(INFO) << "now pi2 "
1205 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1206
Austin Schuhcde938c2020-02-02 17:30:07 -08001207 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001208 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1209 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001210 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1211 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001212 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1213 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001214 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1215
1216 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
1217
1218 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1219
1220 std::unique_ptr<EventLoop> pi1_event_loop =
1221 log_reader_factory.MakeEventLoop("test", pi1);
1222 std::unique_ptr<EventLoop> pi2_event_loop =
1223 log_reader_factory.MakeEventLoop("test", pi2);
1224
1225 int pi1_ping_count = 30;
1226 int pi2_ping_count = 30;
1227 int pi1_pong_count = 30;
1228 int pi2_pong_count = 30;
1229
1230 // Confirm that the ping value matches.
1231 pi1_event_loop->MakeWatcher(
1232 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1233 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1234 << pi1_event_loop->context().monotonic_remote_time << " -> "
1235 << pi1_event_loop->context().monotonic_event_time;
1236 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1237
1238 ++pi1_ping_count;
1239 });
1240 pi2_event_loop->MakeWatcher(
1241 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1242 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1243 << pi2_event_loop->context().monotonic_remote_time << " -> "
1244 << pi2_event_loop->context().monotonic_event_time;
1245 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1246
1247 ++pi2_ping_count;
1248 });
1249
1250 // Confirm that the ping and pong counts both match, and the value also
1251 // matches.
1252 pi1_event_loop->MakeWatcher(
1253 "/test", [&pi1_event_loop, &pi1_ping_count,
1254 &pi1_pong_count](const examples::Pong &pong) {
1255 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1256 << pi1_event_loop->context().monotonic_remote_time << " -> "
1257 << pi1_event_loop->context().monotonic_event_time;
1258
1259 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1260 ++pi1_pong_count;
1261 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1262 });
1263 pi2_event_loop->MakeWatcher(
1264 "/test", [&pi2_event_loop, &pi2_ping_count,
1265 &pi2_pong_count](const examples::Pong &pong) {
1266 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1267 << pi2_event_loop->context().monotonic_remote_time << " -> "
1268 << pi2_event_loop->context().monotonic_event_time;
1269
1270 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1271 ++pi2_pong_count;
1272 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1273 });
1274
1275 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001276 EXPECT_EQ(pi1_ping_count, 6030);
1277 EXPECT_EQ(pi2_ping_count, 6030);
1278 EXPECT_EQ(pi1_pong_count, 6030);
1279 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001280
1281 reader.Deregister();
1282}
1283
Austin Schuh5212cad2020-09-09 23:12:09 -07001284// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
1285TEST_F(MultinodeLoggerTest, SortParts) {
1286 // Make a bunch of parts.
1287 {
1288 LoggerState pi1_logger = MakeLogger(pi1_);
1289 LoggerState pi2_logger = MakeLogger(pi2_);
1290
1291 event_loop_factory_.RunFor(chrono::milliseconds(95));
1292
1293 StartLogger(&pi1_logger);
1294 StartLogger(&pi2_logger);
1295
1296 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1297 }
1298
Austin Schuh11d43732020-09-21 17:28:30 -07001299 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001300 VerifyParts(sorted_parts);
1301}
Austin Schuh11d43732020-09-21 17:28:30 -07001302
Austin Schuh3bd4c402020-11-06 18:19:06 -08001303// Tests that we can sort a bunch of parts with an empty part. We should ignore
1304// it and remove it from the sorted list.
1305TEST_F(MultinodeLoggerTest, SortEmptyParts) {
1306 // Make a bunch of parts.
1307 {
1308 LoggerState pi1_logger = MakeLogger(pi1_);
1309 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001310
Austin Schuh3bd4c402020-11-06 18:19:06 -08001311 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001312
Austin Schuh3bd4c402020-11-06 18:19:06 -08001313 StartLogger(&pi1_logger);
1314 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001315
Austin Schuh3bd4c402020-11-06 18:19:06 -08001316 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001317 }
1318
Austin Schuh3bd4c402020-11-06 18:19:06 -08001319 // TODO(austin): Should we flip out if the file can't open?
1320 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001321
Austin Schuh3bd4c402020-11-06 18:19:06 -08001322 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1323 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001324
Austin Schuh3bd4c402020-11-06 18:19:06 -08001325 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1326 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001327}
1328
Austin Schuh3bd4c402020-11-06 18:19:06 -08001329#ifdef LZMA
1330// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1331// empty file should be ignored.
1332TEST_F(MultinodeLoggerTest, SortEmptyCompressedParts) {
1333 // Make a bunch of parts.
1334 {
1335 LoggerState pi1_logger = MakeLogger(pi1_);
1336 LoggerState pi2_logger = MakeLogger(pi2_);
1337
1338 event_loop_factory_.RunFor(chrono::milliseconds(95));
1339
1340 StartLogger(&pi1_logger, "", true);
1341 StartLogger(&pi2_logger, "", true);
1342
1343 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1344 }
1345
1346 // TODO(austin): Should we flip out if the file can't open?
1347 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1348
1349 AddExtension(".xz");
1350
1351 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1352 logfiles_.emplace_back(kEmptyFile);
1353
1354 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1355 VerifyParts(sorted_parts, {kEmptyFile});
1356}
1357
1358// Tests that we can sort a bunch of parts with the end missing off a compressed
1359// file. We should use the part we can read.
1360TEST_F(MultinodeLoggerTest, SortTruncatedCompressedParts) {
1361 // Make a bunch of parts.
1362 {
1363 LoggerState pi1_logger = MakeLogger(pi1_);
1364 LoggerState pi2_logger = MakeLogger(pi2_);
1365
1366 event_loop_factory_.RunFor(chrono::milliseconds(95));
1367
1368 StartLogger(&pi1_logger, "", true);
1369 StartLogger(&pi2_logger, "", true);
1370
1371 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1372 }
1373
1374 // Append everything with .xz.
1375 AddExtension(".xz");
1376
1377 // Strip off the end of one of the files. Pick one with a lot of data.
1378 ::std::string compressed_contents =
1379 aos::util::ReadFileToStringOrDie(logfiles_[0]);
1380
1381 aos::util::WriteStringToFileOrDie(
1382 logfiles_[0],
1383 compressed_contents.substr(0, compressed_contents.size() - 100));
1384
1385 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1386 VerifyParts(sorted_parts);
1387}
1388#endif
1389
Austin Schuh01b4c352020-09-21 23:09:39 -07001390// Tests that if we remap a remapped channel, it shows up correctly.
1391TEST_F(MultinodeLoggerTest, RemapLoggedChannel) {
1392 {
1393 LoggerState pi1_logger = MakeLogger(pi1_);
1394 LoggerState pi2_logger = MakeLogger(pi2_);
1395
1396 event_loop_factory_.RunFor(chrono::milliseconds(95));
1397
1398 StartLogger(&pi1_logger);
1399 StartLogger(&pi2_logger);
1400
1401 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1402 }
1403
Austin Schuh287d43d2020-12-04 20:19:33 -08001404 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001405
1406 // Remap just on pi1.
1407 reader.RemapLoggedChannel<aos::timing::Report>(
1408 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1409
1410 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1411 log_reader_factory.set_send_delay(chrono::microseconds(0));
1412
1413 reader.Register(&log_reader_factory);
1414
1415 const Node *pi1 =
1416 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1417 const Node *pi2 =
1418 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1419
1420 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1421 // else should have moved.
1422 std::unique_ptr<EventLoop> pi1_event_loop =
1423 log_reader_factory.MakeEventLoop("test", pi1);
1424 pi1_event_loop->SkipTimingReport();
1425 std::unique_ptr<EventLoop> full_pi1_event_loop =
1426 log_reader_factory.MakeEventLoop("test", pi1);
1427 full_pi1_event_loop->SkipTimingReport();
1428 std::unique_ptr<EventLoop> pi2_event_loop =
1429 log_reader_factory.MakeEventLoop("test", pi2);
1430 pi2_event_loop->SkipTimingReport();
1431
1432 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1433 "/aos");
1434 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1435 full_pi1_event_loop.get(), "/pi1/aos");
1436 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1437 pi1_event_loop.get(), "/original/aos");
1438 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1439 full_pi1_event_loop.get(), "/original/pi1/aos");
1440 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1441 "/aos");
1442
1443 log_reader_factory.Run();
1444
1445 EXPECT_EQ(pi1_timing_report.count(), 0u);
1446 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1447 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1448 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1449 EXPECT_NE(pi2_timing_report.count(), 0u);
1450
1451 reader.Deregister();
1452}
1453
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001454// Tests that we properly recreate forwarded timestamps when replaying a log.
1455// This should be enough that we can then re-run the logger and get a valid log
1456// back.
1457TEST_F(MultinodeLoggerTest, MessageHeader) {
1458 {
1459 LoggerState pi1_logger = MakeLogger(pi1_);
1460 LoggerState pi2_logger = MakeLogger(pi2_);
1461
1462 event_loop_factory_.RunFor(chrono::milliseconds(95));
1463
1464 StartLogger(&pi1_logger);
1465 StartLogger(&pi2_logger);
1466
1467 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1468 }
1469
Austin Schuh287d43d2020-12-04 20:19:33 -08001470 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001471
1472 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1473 log_reader_factory.set_send_delay(chrono::microseconds(0));
1474
1475 // This sends out the fetched messages and advances time to the start of the
1476 // log file.
1477 reader.Register(&log_reader_factory);
1478
1479 const Node *pi1 =
1480 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1481 const Node *pi2 =
1482 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1483
1484 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1485 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1486 LOG(INFO) << "now pi1 "
1487 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1488 LOG(INFO) << "now pi2 "
1489 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1490
1491 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
1492
1493 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1494
1495 std::unique_ptr<EventLoop> pi1_event_loop =
1496 log_reader_factory.MakeEventLoop("test", pi1);
1497 std::unique_ptr<EventLoop> pi2_event_loop =
1498 log_reader_factory.MakeEventLoop("test", pi2);
1499
Austin Schuh0de30f32020-12-06 12:44:28 -08001500 MessageCounter<RemoteMessage> pi1_original_message_header_counter(
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001501 pi1_event_loop.get(), "/original/aos/remote_timestamps/pi2");
Austin Schuh0de30f32020-12-06 12:44:28 -08001502 MessageCounter<RemoteMessage> pi2_original_message_header_counter(
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001503 pi2_event_loop.get(), "/original/aos/remote_timestamps/pi1");
1504
1505 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1506 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1507 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1508 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1509
1510 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1511 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1512 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1513 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1514
1515 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1516 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1517 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1518 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1519
1520 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1521 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1522 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1523 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1524
1525 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1526 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1527 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1528 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1529
1530 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1531 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1532 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1533 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1534
1535 pi1_event_loop->MakeWatcher(
1536 "/aos/remote_timestamps/pi2",
Austin Schuh315b96b2020-12-11 21:21:12 -08001537 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1538 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1539 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
Austin Schuh0de30f32020-12-06 12:44:28 -08001540 &ping_on_pi2_fetcher](const RemoteMessage &header) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001541 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1542 chrono::nanoseconds(header.monotonic_sent_time()));
1543 const aos::realtime_clock::time_point header_realtime_sent_time(
1544 chrono::nanoseconds(header.realtime_sent_time()));
1545 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1546 chrono::nanoseconds(header.monotonic_remote_time()));
1547 const aos::realtime_clock::time_point header_realtime_remote_time(
1548 chrono::nanoseconds(header.realtime_remote_time()));
1549
1550 const Context *pi1_context = nullptr;
1551 const Context *pi2_context = nullptr;
1552
1553 if (header.channel_index() == pi1_timestamp_channel) {
1554 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1555 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1556 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1557 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1558 } else if (header.channel_index() == ping_timestamp_channel) {
1559 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1560 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1561 pi1_context = &ping_on_pi1_fetcher.context();
1562 pi2_context = &ping_on_pi2_fetcher.context();
1563 } else {
1564 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1565 << configuration::CleanedChannelToString(
1566 pi1_event_loop->configuration()->channels()->Get(
1567 header.channel_index()));
1568 }
1569
Austin Schuh315b96b2020-12-11 21:21:12 -08001570 ASSERT_TRUE(header.has_boot_uuid());
1571 EXPECT_EQ(header.boot_uuid()->string_view(),
1572 pi2_event_loop->boot_uuid().string_view());
1573
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001574 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1575 EXPECT_EQ(pi2_context->remote_queue_index, header.remote_queue_index());
1576 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
1577
1578 EXPECT_EQ(pi2_context->monotonic_event_time,
1579 header_monotonic_sent_time);
1580 EXPECT_EQ(pi2_context->realtime_event_time, header_realtime_sent_time);
1581 EXPECT_EQ(pi2_context->realtime_remote_time,
1582 header_realtime_remote_time);
1583 EXPECT_EQ(pi2_context->monotonic_remote_time,
1584 header_monotonic_remote_time);
1585
1586 EXPECT_EQ(pi1_context->realtime_event_time,
1587 header_realtime_remote_time);
1588 EXPECT_EQ(pi1_context->monotonic_event_time,
1589 header_monotonic_remote_time);
1590 });
1591 pi2_event_loop->MakeWatcher(
1592 "/aos/remote_timestamps/pi1",
Austin Schuh315b96b2020-12-11 21:21:12 -08001593 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
1594 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
1595 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
Austin Schuh0de30f32020-12-06 12:44:28 -08001596 &pong_on_pi1_fetcher](const RemoteMessage &header) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001597 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1598 chrono::nanoseconds(header.monotonic_sent_time()));
1599 const aos::realtime_clock::time_point header_realtime_sent_time(
1600 chrono::nanoseconds(header.realtime_sent_time()));
1601 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1602 chrono::nanoseconds(header.monotonic_remote_time()));
1603 const aos::realtime_clock::time_point header_realtime_remote_time(
1604 chrono::nanoseconds(header.realtime_remote_time()));
1605
1606 const Context *pi2_context = nullptr;
1607 const Context *pi1_context = nullptr;
1608
1609 if (header.channel_index() == pi2_timestamp_channel) {
1610 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
1611 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
1612 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
1613 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
1614 } else if (header.channel_index() == pong_timestamp_channel) {
1615 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
1616 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
1617 pi2_context = &pong_on_pi2_fetcher.context();
1618 pi1_context = &pong_on_pi1_fetcher.context();
1619 } else {
1620 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1621 << configuration::CleanedChannelToString(
1622 pi2_event_loop->configuration()->channels()->Get(
1623 header.channel_index()));
1624 }
1625
Austin Schuh315b96b2020-12-11 21:21:12 -08001626 ASSERT_TRUE(header.has_boot_uuid());
1627 EXPECT_EQ(header.boot_uuid()->string_view(),
1628 pi1_event_loop->boot_uuid().string_view());
1629
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001630 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
1631 EXPECT_EQ(pi1_context->remote_queue_index, header.remote_queue_index());
1632 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
1633
1634 EXPECT_EQ(pi1_context->monotonic_event_time,
1635 header_monotonic_sent_time);
1636 EXPECT_EQ(pi1_context->realtime_event_time, header_realtime_sent_time);
1637 EXPECT_EQ(pi1_context->realtime_remote_time,
1638 header_realtime_remote_time);
1639 EXPECT_EQ(pi1_context->monotonic_remote_time,
1640 header_monotonic_remote_time);
1641
1642 EXPECT_EQ(pi2_context->realtime_event_time,
1643 header_realtime_remote_time);
1644 EXPECT_EQ(pi2_context->monotonic_event_time,
1645 header_monotonic_remote_time);
1646 });
1647
1648 // And confirm we can re-create a log again, while checking the contents.
1649 {
1650 LoggerState pi1_logger = MakeLogger(
1651 configuration::GetNode(log_reader_factory.configuration(), pi1_),
1652 &log_reader_factory);
1653 LoggerState pi2_logger = MakeLogger(
1654 configuration::GetNode(log_reader_factory.configuration(), pi2_),
1655 &log_reader_factory);
1656
1657 StartLogger(&pi1_logger, "relogged");
1658 StartLogger(&pi2_logger, "relogged");
1659
1660 log_reader_factory.Run();
1661 }
1662
1663 EXPECT_EQ(pi2_original_message_header_counter.count(), 0u);
1664 EXPECT_EQ(pi1_original_message_header_counter.count(), 0u);
1665
1666 reader.Deregister();
1667}
1668
Austin Schuh315b96b2020-12-11 21:21:12 -08001669// Tests that we properly populate and extract the logger_start time by setting
1670// up a clock difference between 2 nodes and looking at the resulting parts.
1671TEST_F(MultinodeLoggerTest, LoggerStartTime) {
1672 {
1673 LoggerState pi1_logger = MakeLogger(pi1_);
1674 LoggerState pi2_logger = MakeLogger(pi2_);
1675
1676 NodeEventLoopFactory *pi2 =
1677 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1678
1679 pi2->SetDistributedOffset(chrono::seconds(1000), 1.0);
1680
1681 StartLogger(&pi1_logger);
1682 StartLogger(&pi2_logger);
1683
1684 event_loop_factory_.RunFor(chrono::milliseconds(10000));
1685 }
1686
1687 for (const LogFile &log_file : SortParts(logfiles_)) {
1688 for (const LogParts &log_part : log_file.parts) {
1689 if (log_part.node == log_file.logger_node) {
1690 EXPECT_EQ(log_part.logger_monotonic_start_time,
1691 aos::monotonic_clock::min_time);
1692 EXPECT_EQ(log_part.logger_realtime_start_time,
1693 aos::realtime_clock::min_time);
1694 } else {
1695 const chrono::seconds offset = log_file.logger_node == "pi1"
1696 ? -chrono::seconds(1000)
1697 : chrono::seconds(1000);
1698 EXPECT_EQ(log_part.logger_monotonic_start_time,
1699 log_part.monotonic_start_time + offset);
1700 EXPECT_EQ(log_part.logger_realtime_start_time,
1701 log_file.realtime_start_time +
1702 (log_part.logger_monotonic_start_time -
1703 log_file.monotonic_start_time));
1704 }
1705 }
1706 }
1707}
1708
Austin Schuh8bd96322020-02-13 21:18:22 -08001709// TODO(austin): We can write a test which recreates a logfile and confirms that
1710// we get it back. That is the ultimate test.
1711
Austin Schuh315b96b2020-12-11 21:21:12 -08001712// Tests that we properly recreate forwarded timestamps when replaying a log.
1713// This should be enough that we can then re-run the logger and get a valid log
1714// back.
1715TEST_F(MultinodeLoggerDeathTest, RemoteReboot) {
1716 std::string pi2_boot1;
1717 std::string pi2_boot2;
1718 {
1719 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
1720 ->boot_uuid()
1721 .string_view();
1722 LoggerState pi1_logger = MakeLogger(pi1_);
1723
1724 event_loop_factory_.RunFor(chrono::milliseconds(95));
1725
1726 StartLogger(&pi1_logger);
1727
1728 event_loop_factory_.RunFor(chrono::milliseconds(10000));
1729
1730 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
1731
1732 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
1733 ->boot_uuid()
1734 .string_view();
1735
1736 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1737 }
1738
1739 // Confirm that we refuse to replay logs with missing boot uuids.
1740 EXPECT_DEATH(
1741 {
1742 LogReader reader(SortParts(pi1_reboot_logfiles_));
1743
1744 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1745 log_reader_factory.set_send_delay(chrono::microseconds(0));
1746
1747 // This sends out the fetched messages and advances time to the start of
1748 // the log file.
1749 reader.Register(&log_reader_factory);
1750 },
1751 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
1752 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
1753}
1754
Austin Schuhc9049732020-12-21 22:27:15 -08001755// Tests that we properly handle one direction of message_bridge being
1756// unavailable.
1757TEST_F(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
1758 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
1759 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->SetDistributedOffset(
1760 chrono::seconds(1000), 0.99999);
1761 {
1762 LoggerState pi1_logger = MakeLogger(pi1_);
1763
1764 event_loop_factory_.RunFor(chrono::milliseconds(95));
1765
1766 StartLogger(&pi1_logger);
1767
1768 event_loop_factory_.RunFor(chrono::milliseconds(10000));
1769 }
1770
1771 // Confirm that we can parse the result. LogReader has enough internal CHECKs
1772 // to confirm the right thing happened.
1773 ConfirmReadable(pi1_single_direction_logfiles_);
1774}
1775
1776// Tests that we properly handle one direction of message_bridge being
1777// unavailable.
1778TEST_F(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
1779 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
1780 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->SetDistributedOffset(
1781 chrono::seconds(500), 1.00001);
1782 {
1783 LoggerState pi1_logger = MakeLogger(pi1_);
1784
1785 event_loop_factory_.RunFor(chrono::milliseconds(95));
1786
1787 StartLogger(&pi1_logger);
1788
1789 event_loop_factory_.RunFor(chrono::milliseconds(10000));
1790 }
1791
1792 // Confirm that we can parse the result. LogReader has enough internal CHECKs
1793 // to confirm the right thing happened.
1794 ConfirmReadable(pi1_single_direction_logfiles_);
1795}
1796
Austin Schuhe309d2a2019-11-29 13:25:21 -08001797} // namespace testing
1798} // namespace logger
1799} // namespace aos