blob: 3f4893e296dc514b95f6b0e6e9be3b1fb81b3c16 [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 Schuh2f8fd752020-09-01 22:38:28 -0700418 structured_logfiles_{
419 std::vector<std::string>{logfiles_[0]},
420 std::vector<std::string>{logfiles_[1], logfiles_[2]},
421 std::vector<std::string>{logfiles_[3]},
422 std::vector<std::string>{logfiles_[4], logfiles_[5]},
423 std::vector<std::string>{logfiles_[6], logfiles_[7]},
424 std::vector<std::string>{logfiles_[8], logfiles_[9]},
425 std::vector<std::string>{logfiles_[10], logfiles_[11]}},
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700426 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping", pi1_)),
427 ping_(ping_event_loop_.get()),
428 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong", pi2_)),
429 pong_(pong_event_loop_.get()) {
430 // Go through and remove the logfiles if they already exist.
431 for (const auto file : logfiles_) {
432 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800433 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700434 }
435
Austin Schuh315b96b2020-12-11 21:21:12 -0800436 for (const auto file : MakeLogFiles("relogged")) {
437 unlink(file.c_str());
438 }
439
440 for (const auto file : pi1_reboot_logfiles_) {
441 unlink(file.c_str());
442 }
443
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700444 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
445 << " and " << logfiles_[2];
446 }
447
448 struct LoggerState {
449 std::unique_ptr<EventLoop> event_loop;
450 std::unique_ptr<Logger> logger;
451 };
452
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700453 LoggerState MakeLogger(const Node *node,
454 SimulatedEventLoopFactory *factory = nullptr) {
455 if (factory == nullptr) {
456 factory = &event_loop_factory_;
457 }
458 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700459 }
460
Austin Schuh3bd4c402020-11-06 18:19:06 -0800461 void StartLogger(LoggerState *logger, std::string logfile_base = "",
462 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700463 if (logfile_base.empty()) {
464 logfile_base = logfile_base_;
465 }
466
Brian Silverman1f345222020-09-24 21:14:48 -0700467 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
468 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800469 logger->event_loop->OnRun([logger, logfile_base, compress]() {
470 std::unique_ptr<MultiNodeLogNamer> namer =
471 std::make_unique<MultiNodeLogNamer>(
472 logfile_base, logger->event_loop->configuration(),
473 logger->event_loop->node());
474 if (compress) {
475#ifdef LZMA
476 namer->set_extension(".xz");
477 namer->set_encoder_factory(
478 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
479#else
480 LOG(FATAL) << "Compression unsupported";
481#endif
482 }
483
484 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700485 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700486 }
Austin Schuh15649d62019-12-28 16:36:38 -0800487
Austin Schuh3bd4c402020-11-06 18:19:06 -0800488 void VerifyParts(const std::vector<LogFile> &sorted_parts,
489 const std::vector<std::string> &corrupted_parts = {}) {
490 EXPECT_EQ(sorted_parts.size(), 2u);
491
492 // Count up the number of UUIDs and make sure they are what we expect as a
493 // sanity check.
494 std::set<std::string> log_event_uuids;
495 std::set<std::string> parts_uuids;
496 std::set<std::string> both_uuids;
497
498 size_t missing_rt_count = 0;
499
500 std::vector<std::string> logger_nodes;
501 for (const LogFile &log_file : sorted_parts) {
502 EXPECT_FALSE(log_file.log_event_uuid.empty());
503 log_event_uuids.insert(log_file.log_event_uuid);
504 logger_nodes.emplace_back(log_file.logger_node);
505 both_uuids.insert(log_file.log_event_uuid);
506
507 for (const LogParts &part : log_file.parts) {
508 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
509 << ": " << part;
510 missing_rt_count +=
511 part.realtime_start_time == aos::realtime_clock::min_time;
512
513 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
514 log_event_uuids.end());
515 EXPECT_NE(part.node, "");
516 parts_uuids.insert(part.parts_uuid);
517 both_uuids.insert(part.parts_uuid);
518 }
519 }
520
521 // We won't have RT timestamps for 5 log files. We don't log the RT start
522 // time on remote nodes because we don't know it and would be guessing. And
523 // the log reader can actually do a better job.
524 EXPECT_EQ(missing_rt_count, 5u);
525
526 EXPECT_EQ(log_event_uuids.size(), 2u);
527 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
528 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
529
530 // Test that each list of parts is in order. Don't worry about the ordering
531 // between part file lists though.
532 // (inner vectors all need to be in order, but outer one doesn't matter).
533 EXPECT_THAT(ToLogReaderVector(sorted_parts),
534 ::testing::UnorderedElementsAreArray(structured_logfiles_));
535
536 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
537
538 EXPECT_NE(sorted_parts[0].realtime_start_time,
539 aos::realtime_clock::min_time);
540 EXPECT_NE(sorted_parts[1].realtime_start_time,
541 aos::realtime_clock::min_time);
542
543 EXPECT_NE(sorted_parts[0].monotonic_start_time,
544 aos::monotonic_clock::min_time);
545 EXPECT_NE(sorted_parts[1].monotonic_start_time,
546 aos::monotonic_clock::min_time);
547
548 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
549 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
550 }
551
552 void AddExtension(std::string_view extension) {
553 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
554 [extension](const std::string &in) {
555 return absl::StrCat(in, extension);
556 });
557
558 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
559 structured_logfiles_.begin(),
560 [extension](std::vector<std::string> in) {
561 std::transform(in.begin(), in.end(), in.begin(),
562 [extension](const std::string &in_str) {
563 return absl::StrCat(in_str, extension);
564 });
565 return in;
566 });
567 }
568
Austin Schuh15649d62019-12-28 16:36:38 -0800569 // Config and factory.
570 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
571 SimulatedEventLoopFactory event_loop_factory_;
572
Austin Schuhcde938c2020-02-02 17:30:07 -0800573 const Node *pi1_;
574 const Node *pi2_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700575
576 std::string tmp_dir_;
577 std::string logfile_base_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800578 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700579 std::vector<std::string> logfiles_;
580
581 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700582
583 std::unique_ptr<EventLoop> ping_event_loop_;
584 Ping ping_;
585 std::unique_ptr<EventLoop> pong_event_loop_;
586 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800587};
588
Austin Schuh391e3172020-09-01 22:48:18 -0700589// Counts the number of messages on a channel. Returns (channel name, channel
590// type, count) for every message matching matcher()
591std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh6f3babe2020-01-26 20:34:50 -0800592 std::string_view filename,
593 std::function<bool(const MessageHeader *)> matcher) {
594 MessageReader message_reader(filename);
595 std::vector<int> counts(
596 message_reader.log_file_header()->configuration()->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800597
Austin Schuh6f3babe2020-01-26 20:34:50 -0800598 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800599 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800600 message_reader.ReadMessage();
601 if (!msg) {
602 break;
603 }
604
605 if (matcher(&msg.value().message())) {
606 counts[msg.value().message().channel_index()]++;
607 }
608 }
609
Austin Schuh391e3172020-09-01 22:48:18 -0700610 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800611 int channel = 0;
612 for (size_t i = 0; i < counts.size(); ++i) {
613 if (counts[i] != 0) {
Austin Schuh391e3172020-09-01 22:48:18 -0700614 const Channel *channel =
615 message_reader.log_file_header()->configuration()->channels()->Get(i);
616 result.push_back(std::make_tuple(channel->name()->str(),
617 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800618 }
619 ++channel;
620 }
621
622 return result;
623}
624
625// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700626std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
627 std::string_view filename) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800628 return CountChannelsMatching(filename, [](const MessageHeader *msg) {
629 if (msg->has_data()) {
630 CHECK(!msg->has_monotonic_remote_time());
631 CHECK(!msg->has_realtime_remote_time());
632 CHECK(!msg->has_remote_queue_index());
633 return true;
634 }
635 return false;
636 });
637}
638
639// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700640std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh6f3babe2020-01-26 20:34:50 -0800641 std::string_view filename) {
642 return CountChannelsMatching(filename, [](const MessageHeader *msg) {
643 if (!msg->has_data()) {
644 CHECK(msg->has_monotonic_remote_time());
645 CHECK(msg->has_realtime_remote_time());
646 CHECK(msg->has_remote_queue_index());
647 return true;
648 }
649 return false;
650 });
651}
652
Austin Schuhcde938c2020-02-02 17:30:07 -0800653// Tests that we can write and read simple multi-node log files.
654TEST_F(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh15649d62019-12-28 16:36:38 -0800655 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700656 LoggerState pi1_logger = MakeLogger(pi1_);
657 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800658
659 event_loop_factory_.RunFor(chrono::milliseconds(95));
660
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700661 StartLogger(&pi1_logger);
662 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800663
Austin Schuh15649d62019-12-28 16:36:38 -0800664 event_loop_factory_.RunFor(chrono::milliseconds(20000));
665 }
666
Austin Schuh6f3babe2020-01-26 20:34:50 -0800667 {
Austin Schuh64fab802020-09-09 22:47:47 -0700668 std::set<std::string> logfile_uuids;
669 std::set<std::string> parts_uuids;
670 // Confirm that we have the expected number of UUIDs for both the logfile
671 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800672 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700673 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800674 log_header.emplace_back(ReadHeader(f).value());
Brian Silvermanae7c0332020-09-30 16:58:23 -0700675 logfile_uuids.insert(log_header.back().message().log_event_uuid()->str());
Austin Schuh64fab802020-09-09 22:47:47 -0700676 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
677 }
Austin Schuh15649d62019-12-28 16:36:38 -0800678
Austin Schuh64fab802020-09-09 22:47:47 -0700679 EXPECT_EQ(logfile_uuids.size(), 2u);
680 EXPECT_EQ(parts_uuids.size(), 7u);
681
682 // And confirm everything is on the correct node.
683 EXPECT_EQ(log_header[0].message().node()->name()->string_view(), "pi1");
684 EXPECT_EQ(log_header[1].message().node()->name()->string_view(), "pi2");
685 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi2");
686 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi2");
687 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
688 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
689 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi1");
690 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi1");
691 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
692 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
693 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
694 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
695
696 // And the parts index matches.
697 EXPECT_EQ(log_header[0].message().parts_index(), 0);
698 EXPECT_EQ(log_header[1].message().parts_index(), 0);
699 EXPECT_EQ(log_header[2].message().parts_index(), 1);
700 EXPECT_EQ(log_header[3].message().parts_index(), 0);
701 EXPECT_EQ(log_header[4].message().parts_index(), 0);
702 EXPECT_EQ(log_header[5].message().parts_index(), 1);
703 EXPECT_EQ(log_header[6].message().parts_index(), 0);
704 EXPECT_EQ(log_header[7].message().parts_index(), 1);
705 EXPECT_EQ(log_header[8].message().parts_index(), 0);
706 EXPECT_EQ(log_header[9].message().parts_index(), 1);
707 EXPECT_EQ(log_header[10].message().parts_index(), 0);
708 EXPECT_EQ(log_header[11].message().parts_index(), 1);
709 }
710
711 {
Austin Schuh391e3172020-09-01 22:48:18 -0700712 using ::testing::UnorderedElementsAre;
713
Austin Schuh6f3babe2020-01-26 20:34:50 -0800714 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700715 EXPECT_THAT(
716 CountChannelsData(logfiles_[0]),
717 UnorderedElementsAre(
718 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
719 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800720 std::make_tuple("/test", "aos.examples.Ping", 2001)))
721 << " : " << logfiles_[0];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800722 // Timestamps for pong
Austin Schuh2f8fd752020-09-01 22:38:28 -0700723 EXPECT_THAT(
724 CountChannelsTimestamp(logfiles_[0]),
725 UnorderedElementsAre(
726 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800727 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
728 << " : " << logfiles_[0];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800729
730 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800731 EXPECT_THAT(
732 CountChannelsData(logfiles_[1]),
733 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
734 << " : " << logfiles_[1];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700735 EXPECT_THAT(CountChannelsData(logfiles_[2]),
736 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800737 std::make_tuple("/test", "aos.examples.Pong", 1910)))
738 << " : " << logfiles_[1];
Austin Schuh391e3172020-09-01 22:48:18 -0700739
Austin Schuh6f3babe2020-01-26 20:34:50 -0800740 // No timestamps
Austin Schuh20ac95d2020-12-05 17:24:19 -0800741 EXPECT_THAT(CountChannelsTimestamp(logfiles_[1]), UnorderedElementsAre())
742 << " : " << logfiles_[1];
743 EXPECT_THAT(CountChannelsTimestamp(logfiles_[2]), UnorderedElementsAre())
744 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800745
746 // Timing reports and pongs.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700747 EXPECT_THAT(
748 CountChannelsData(logfiles_[3]),
749 UnorderedElementsAre(
750 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
751 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800752 std::make_tuple("/test", "aos.examples.Pong", 2001)))
753 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800754 // And ping timestamps.
Austin Schuh2f8fd752020-09-01 22:38:28 -0700755 EXPECT_THAT(
756 CountChannelsTimestamp(logfiles_[3]),
757 UnorderedElementsAre(
758 std::make_tuple("/test", "aos.examples.Ping", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800759 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
760 << " : " << logfiles_[3];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700761
762 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800763 EXPECT_THAT(CountChannelsData(logfiles_[4]), UnorderedElementsAre())
764 << " : " << logfiles_[4];
765 EXPECT_THAT(CountChannelsData(logfiles_[5]), UnorderedElementsAre())
766 << " : " << logfiles_[5];
767 EXPECT_THAT(CountChannelsData(logfiles_[6]), UnorderedElementsAre())
768 << " : " << logfiles_[6];
769 EXPECT_THAT(CountChannelsData(logfiles_[7]), UnorderedElementsAre())
770 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700771 EXPECT_THAT(
772 CountChannelsTimestamp(logfiles_[4]),
773 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800774 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
775 std::make_tuple("/test", "aos.examples.Ping", 91)))
776 << " : " << logfiles_[4];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700777 EXPECT_THAT(
778 CountChannelsTimestamp(logfiles_[5]),
779 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800780 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
781 std::make_tuple("/test", "aos.examples.Ping", 1910)))
782 << " : " << logfiles_[5];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700783 EXPECT_THAT(CountChannelsTimestamp(logfiles_[6]),
784 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800785 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
786 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700787 EXPECT_THAT(CountChannelsTimestamp(logfiles_[7]),
788 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800789 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
790 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700791
792 // And then test that the remotely logged timestamp data files only have
793 // timestamps in them.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800794 EXPECT_THAT(CountChannelsTimestamp(logfiles_[8]), UnorderedElementsAre())
795 << " : " << logfiles_[8];
796 EXPECT_THAT(CountChannelsTimestamp(logfiles_[9]), UnorderedElementsAre())
797 << " : " << logfiles_[9];
798 EXPECT_THAT(CountChannelsTimestamp(logfiles_[10]), UnorderedElementsAre())
799 << " : " << logfiles_[10];
800 EXPECT_THAT(CountChannelsTimestamp(logfiles_[11]), UnorderedElementsAre())
801 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700802
803 EXPECT_THAT(CountChannelsData(logfiles_[8]),
804 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800805 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
806 << " : " << logfiles_[8];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700807 EXPECT_THAT(CountChannelsData(logfiles_[9]),
808 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800809 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
810 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700811
812 EXPECT_THAT(CountChannelsData(logfiles_[10]),
813 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800814 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
815 << " : " << logfiles_[10];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700816 EXPECT_THAT(CountChannelsData(logfiles_[11]),
817 UnorderedElementsAre(std::make_tuple(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800818 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
819 << " : " << logfiles_[11];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800820 }
821
Austin Schuh287d43d2020-12-04 20:19:33 -0800822 LogReader reader(SortParts(logfiles_));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800823
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700824 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -0800825 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -0800826
827 // This sends out the fetched messages and advances time to the start of the
828 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -0800829 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800830
Austin Schuhac0771c2020-01-07 18:36:30 -0800831 const Node *pi1 =
832 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -0800833 const Node *pi2 =
834 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -0800835
Austin Schuh2f8fd752020-09-01 22:38:28 -0700836 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
837 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
838 LOG(INFO) << "now pi1 "
839 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
840 LOG(INFO) << "now pi2 "
841 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
842
Austin Schuh6f3babe2020-01-26 20:34:50 -0800843 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800844
845 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -0800846
Austin Schuh6f3babe2020-01-26 20:34:50 -0800847 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -0800848 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800849 std::unique_ptr<EventLoop> pi2_event_loop =
850 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -0800851
Austin Schuh6f3babe2020-01-26 20:34:50 -0800852 int pi1_ping_count = 10;
853 int pi2_ping_count = 10;
854 int pi1_pong_count = 10;
855 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -0800856
857 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -0800858 pi1_event_loop->MakeWatcher(
859 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -0700860 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -0800861 << pi1_event_loop->context().monotonic_remote_time << " -> "
862 << pi1_event_loop->context().monotonic_event_time;
863 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
864 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
865 pi1_ping_count * chrono::milliseconds(10) +
866 monotonic_clock::epoch());
867 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
868 pi1_ping_count * chrono::milliseconds(10) +
869 realtime_clock::epoch());
870 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
871 pi1_event_loop->context().monotonic_event_time);
872 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
873 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -0800874
Austin Schuh6f3babe2020-01-26 20:34:50 -0800875 ++pi1_ping_count;
876 });
877 pi2_event_loop->MakeWatcher(
878 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -0700879 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -0800880 << pi2_event_loop->context().monotonic_remote_time << " -> "
881 << pi2_event_loop->context().monotonic_event_time;
882 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
883
884 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
885 pi2_ping_count * chrono::milliseconds(10) +
886 monotonic_clock::epoch());
887 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
888 pi2_ping_count * chrono::milliseconds(10) +
889 realtime_clock::epoch());
890 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
891 chrono::microseconds(150),
892 pi2_event_loop->context().monotonic_event_time);
893 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
894 chrono::microseconds(150),
895 pi2_event_loop->context().realtime_event_time);
896 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -0800897 });
898
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700899 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800900 // Confirm that the ping and pong counts both match, and the value also
901 // matches.
902 pi1_event_loop->MakeWatcher(
903 "/test", [&pi1_event_loop, &pi1_ping_count,
904 &pi1_pong_count](const examples::Pong &pong) {
905 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
906 << pi1_event_loop->context().monotonic_remote_time << " -> "
907 << pi1_event_loop->context().monotonic_event_time;
908
909 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
910 pi1_pong_count + kQueueIndexOffset);
911 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
912 chrono::microseconds(200) +
913 pi1_pong_count * chrono::milliseconds(10) +
914 monotonic_clock::epoch());
915 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
916 chrono::microseconds(200) +
917 pi1_pong_count * chrono::milliseconds(10) +
918 realtime_clock::epoch());
919
920 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
921 chrono::microseconds(150),
922 pi1_event_loop->context().monotonic_event_time);
923 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
924 chrono::microseconds(150),
925 pi1_event_loop->context().realtime_event_time);
926
927 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
928 ++pi1_pong_count;
929 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
930 });
931 pi2_event_loop->MakeWatcher(
932 "/test", [&pi2_event_loop, &pi2_ping_count,
933 &pi2_pong_count](const examples::Pong &pong) {
934 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
935 << pi2_event_loop->context().monotonic_remote_time << " -> "
936 << pi2_event_loop->context().monotonic_event_time;
937
938 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700939 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -0800940
941 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
942 chrono::microseconds(200) +
943 pi2_pong_count * chrono::milliseconds(10) +
944 monotonic_clock::epoch());
945 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
946 chrono::microseconds(200) +
947 pi2_pong_count * chrono::milliseconds(10) +
948 realtime_clock::epoch());
949
950 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
951 pi2_event_loop->context().monotonic_event_time);
952 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
953 pi2_event_loop->context().realtime_event_time);
954
955 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
956 ++pi2_pong_count;
957 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
958 });
959
960 log_reader_factory.Run();
961 EXPECT_EQ(pi1_ping_count, 2010);
962 EXPECT_EQ(pi2_ping_count, 2010);
963 EXPECT_EQ(pi1_pong_count, 2010);
964 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -0800965
966 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -0800967}
968
James Kuszmaul46d82582020-05-09 19:50:09 -0700969typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
970
971// Test that if we feed the replay with a mismatched node list that we die on
972// the LogReader constructor.
973TEST_F(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
James Kuszmaul46d82582020-05-09 19:50:09 -0700974 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700975 LoggerState pi1_logger = MakeLogger(pi1_);
976 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -0700977
978 event_loop_factory_.RunFor(chrono::milliseconds(95));
979
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700980 StartLogger(&pi1_logger);
981 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -0700982
James Kuszmaul46d82582020-05-09 19:50:09 -0700983 event_loop_factory_.RunFor(chrono::milliseconds(20000));
984 }
985
986 // Test that, if we add an additional node to the replay config that the
987 // logger complains about the mismatch in number of nodes.
988 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
989 configuration::MergeWithConfig(&config_.message(), R"({
990 "nodes": [
991 {
992 "name": "extra-node"
993 }
994 ]
995 }
996 )");
997
Austin Schuh287d43d2020-12-04 20:19:33 -0800998 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
999 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001000 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001001}
1002
Austin Schuhcde938c2020-02-02 17:30:07 -08001003// Tests that we can read log files where they don't start at the same monotonic
1004// time.
1005TEST_F(MultinodeLoggerTest, StaggeredStart) {
Austin Schuhcde938c2020-02-02 17:30:07 -08001006 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001007 LoggerState pi1_logger = MakeLogger(pi1_);
1008 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001009
1010 event_loop_factory_.RunFor(chrono::milliseconds(95));
1011
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001012 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001013
1014 event_loop_factory_.RunFor(chrono::milliseconds(200));
1015
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001016 StartLogger(&pi2_logger);
1017
Austin Schuhcde938c2020-02-02 17:30:07 -08001018 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1019 }
1020
Austin Schuh287d43d2020-12-04 20:19:33 -08001021 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001022
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001023 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001024 log_reader_factory.set_send_delay(chrono::microseconds(0));
1025
1026 // This sends out the fetched messages and advances time to the start of the
1027 // log file.
1028 reader.Register(&log_reader_factory);
1029
1030 const Node *pi1 =
1031 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1032 const Node *pi2 =
1033 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1034
1035 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
1036
1037 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1038
1039 std::unique_ptr<EventLoop> pi1_event_loop =
1040 log_reader_factory.MakeEventLoop("test", pi1);
1041 std::unique_ptr<EventLoop> pi2_event_loop =
1042 log_reader_factory.MakeEventLoop("test", pi2);
1043
1044 int pi1_ping_count = 30;
1045 int pi2_ping_count = 30;
1046 int pi1_pong_count = 30;
1047 int pi2_pong_count = 30;
1048
1049 // Confirm that the ping value matches.
1050 pi1_event_loop->MakeWatcher(
1051 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1052 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1053 << pi1_event_loop->context().monotonic_remote_time << " -> "
1054 << pi1_event_loop->context().monotonic_event_time;
1055 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1056
1057 ++pi1_ping_count;
1058 });
1059 pi2_event_loop->MakeWatcher(
1060 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1061 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1062 << pi2_event_loop->context().monotonic_remote_time << " -> "
1063 << pi2_event_loop->context().monotonic_event_time;
1064 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1065
1066 ++pi2_ping_count;
1067 });
1068
1069 // Confirm that the ping and pong counts both match, and the value also
1070 // matches.
1071 pi1_event_loop->MakeWatcher(
1072 "/test", [&pi1_event_loop, &pi1_ping_count,
1073 &pi1_pong_count](const examples::Pong &pong) {
1074 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1075 << pi1_event_loop->context().monotonic_remote_time << " -> "
1076 << pi1_event_loop->context().monotonic_event_time;
1077
1078 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1079 ++pi1_pong_count;
1080 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1081 });
1082 pi2_event_loop->MakeWatcher(
1083 "/test", [&pi2_event_loop, &pi2_ping_count,
1084 &pi2_pong_count](const examples::Pong &pong) {
1085 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1086 << pi2_event_loop->context().monotonic_remote_time << " -> "
1087 << pi2_event_loop->context().monotonic_event_time;
1088
1089 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1090 ++pi2_pong_count;
1091 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1092 });
1093
1094 log_reader_factory.Run();
1095 EXPECT_EQ(pi1_ping_count, 2030);
1096 EXPECT_EQ(pi2_ping_count, 2030);
1097 EXPECT_EQ(pi1_pong_count, 2030);
1098 EXPECT_EQ(pi2_pong_count, 2030);
1099
1100 reader.Deregister();
1101}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001102
Austin Schuh8bd96322020-02-13 21:18:22 -08001103// Tests that we can read log files where the monotonic clocks drift and don't
1104// match correctly. While we are here, also test that different ending times
1105// also is readable.
1106TEST_F(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuhcde938c2020-02-02 17:30:07 -08001107 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001108 LoggerState pi2_logger = MakeLogger(pi2_);
1109
Austin Schuh8bd96322020-02-13 21:18:22 -08001110 NodeEventLoopFactory *pi2 =
1111 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1112 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1113 << pi2->realtime_now() << " distributed "
1114 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001115
Austin Schuh8bd96322020-02-13 21:18:22 -08001116 const chrono::nanoseconds initial_pi2_offset = -chrono::seconds(1000);
1117 chrono::nanoseconds pi2_offset = initial_pi2_offset;
Austin Schuhcde938c2020-02-02 17:30:07 -08001118
Austin Schuhbe69cf32020-08-27 11:38:33 -07001119 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001120 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1121 << pi2->realtime_now() << " distributed "
1122 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001123
Austin Schuh8bd96322020-02-13 21:18:22 -08001124 for (int i = 0; i < 95; ++i) {
1125 pi2_offset += chrono::nanoseconds(200);
Austin Schuhbe69cf32020-08-27 11:38:33 -07001126 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001127 event_loop_factory_.RunFor(chrono::milliseconds(1));
1128 }
Austin Schuhcde938c2020-02-02 17:30:07 -08001129
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001130 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001131
Austin Schuh8bd96322020-02-13 21:18:22 -08001132 event_loop_factory_.RunFor(chrono::milliseconds(200));
Austin Schuhcde938c2020-02-02 17:30:07 -08001133
Austin Schuh8bd96322020-02-13 21:18:22 -08001134 {
1135 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001136 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001137
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001138 StartLogger(&pi1_logger);
Austin Schuh8bd96322020-02-13 21:18:22 -08001139
1140 for (int i = 0; i < 20000; ++i) {
1141 pi2_offset += chrono::nanoseconds(200);
Austin Schuhbe69cf32020-08-27 11:38:33 -07001142 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001143 event_loop_factory_.RunFor(chrono::milliseconds(1));
1144 }
1145
1146 EXPECT_GT(pi2_offset - initial_pi2_offset,
1147 event_loop_factory_.send_delay() +
1148 event_loop_factory_.network_delay());
1149
1150 for (int i = 0; i < 40000; ++i) {
1151 pi2_offset -= chrono::nanoseconds(200);
Austin Schuhbe69cf32020-08-27 11:38:33 -07001152 pi2->SetDistributedOffset(-pi2_offset, 1.0);
Austin Schuh8bd96322020-02-13 21:18:22 -08001153 event_loop_factory_.RunFor(chrono::milliseconds(1));
1154 }
1155 }
1156
1157 // And log a bit more on pi2.
1158 event_loop_factory_.RunFor(chrono::milliseconds(400));
Austin Schuhcde938c2020-02-02 17:30:07 -08001159 }
1160
Austin Schuh287d43d2020-12-04 20:19:33 -08001161 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001162
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001163 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001164 log_reader_factory.set_send_delay(chrono::microseconds(0));
1165
Austin Schuhcde938c2020-02-02 17:30:07 -08001166 const Node *pi1 =
1167 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1168 const Node *pi2 =
1169 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1170
Austin Schuh2f8fd752020-09-01 22:38:28 -07001171 // This sends out the fetched messages and advances time to the start of the
1172 // log file.
1173 reader.Register(&log_reader_factory);
1174
1175 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1176 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1177 LOG(INFO) << "now pi1 "
1178 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1179 LOG(INFO) << "now pi2 "
1180 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1181
Austin Schuhcde938c2020-02-02 17:30:07 -08001182 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001183 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1184 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001185 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1186 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001187 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1188 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001189 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1190
1191 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
1192
1193 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1194
1195 std::unique_ptr<EventLoop> pi1_event_loop =
1196 log_reader_factory.MakeEventLoop("test", pi1);
1197 std::unique_ptr<EventLoop> pi2_event_loop =
1198 log_reader_factory.MakeEventLoop("test", pi2);
1199
1200 int pi1_ping_count = 30;
1201 int pi2_ping_count = 30;
1202 int pi1_pong_count = 30;
1203 int pi2_pong_count = 30;
1204
1205 // Confirm that the ping value matches.
1206 pi1_event_loop->MakeWatcher(
1207 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1208 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1209 << pi1_event_loop->context().monotonic_remote_time << " -> "
1210 << pi1_event_loop->context().monotonic_event_time;
1211 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1212
1213 ++pi1_ping_count;
1214 });
1215 pi2_event_loop->MakeWatcher(
1216 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1217 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1218 << pi2_event_loop->context().monotonic_remote_time << " -> "
1219 << pi2_event_loop->context().monotonic_event_time;
1220 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1221
1222 ++pi2_ping_count;
1223 });
1224
1225 // Confirm that the ping and pong counts both match, and the value also
1226 // matches.
1227 pi1_event_loop->MakeWatcher(
1228 "/test", [&pi1_event_loop, &pi1_ping_count,
1229 &pi1_pong_count](const examples::Pong &pong) {
1230 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1231 << pi1_event_loop->context().monotonic_remote_time << " -> "
1232 << pi1_event_loop->context().monotonic_event_time;
1233
1234 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1235 ++pi1_pong_count;
1236 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1237 });
1238 pi2_event_loop->MakeWatcher(
1239 "/test", [&pi2_event_loop, &pi2_ping_count,
1240 &pi2_pong_count](const examples::Pong &pong) {
1241 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1242 << pi2_event_loop->context().monotonic_remote_time << " -> "
1243 << pi2_event_loop->context().monotonic_event_time;
1244
1245 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1246 ++pi2_pong_count;
1247 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1248 });
1249
1250 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001251 EXPECT_EQ(pi1_ping_count, 6030);
1252 EXPECT_EQ(pi2_ping_count, 6030);
1253 EXPECT_EQ(pi1_pong_count, 6030);
1254 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001255
1256 reader.Deregister();
1257}
1258
Austin Schuh5212cad2020-09-09 23:12:09 -07001259// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
1260TEST_F(MultinodeLoggerTest, SortParts) {
1261 // Make a bunch of parts.
1262 {
1263 LoggerState pi1_logger = MakeLogger(pi1_);
1264 LoggerState pi2_logger = MakeLogger(pi2_);
1265
1266 event_loop_factory_.RunFor(chrono::milliseconds(95));
1267
1268 StartLogger(&pi1_logger);
1269 StartLogger(&pi2_logger);
1270
1271 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1272 }
1273
Austin Schuh11d43732020-09-21 17:28:30 -07001274 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001275 VerifyParts(sorted_parts);
1276}
Austin Schuh11d43732020-09-21 17:28:30 -07001277
Austin Schuh3bd4c402020-11-06 18:19:06 -08001278// Tests that we can sort a bunch of parts with an empty part. We should ignore
1279// it and remove it from the sorted list.
1280TEST_F(MultinodeLoggerTest, SortEmptyParts) {
1281 // Make a bunch of parts.
1282 {
1283 LoggerState pi1_logger = MakeLogger(pi1_);
1284 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001285
Austin Schuh3bd4c402020-11-06 18:19:06 -08001286 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001287
Austin Schuh3bd4c402020-11-06 18:19:06 -08001288 StartLogger(&pi1_logger);
1289 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001290
Austin Schuh3bd4c402020-11-06 18:19:06 -08001291 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001292 }
1293
Austin Schuh3bd4c402020-11-06 18:19:06 -08001294 // TODO(austin): Should we flip out if the file can't open?
1295 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001296
Austin Schuh3bd4c402020-11-06 18:19:06 -08001297 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1298 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001299
Austin Schuh3bd4c402020-11-06 18:19:06 -08001300 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1301 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001302}
1303
Austin Schuh3bd4c402020-11-06 18:19:06 -08001304#ifdef LZMA
1305// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1306// empty file should be ignored.
1307TEST_F(MultinodeLoggerTest, SortEmptyCompressedParts) {
1308 // Make a bunch of parts.
1309 {
1310 LoggerState pi1_logger = MakeLogger(pi1_);
1311 LoggerState pi2_logger = MakeLogger(pi2_);
1312
1313 event_loop_factory_.RunFor(chrono::milliseconds(95));
1314
1315 StartLogger(&pi1_logger, "", true);
1316 StartLogger(&pi2_logger, "", true);
1317
1318 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1319 }
1320
1321 // TODO(austin): Should we flip out if the file can't open?
1322 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1323
1324 AddExtension(".xz");
1325
1326 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1327 logfiles_.emplace_back(kEmptyFile);
1328
1329 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1330 VerifyParts(sorted_parts, {kEmptyFile});
1331}
1332
1333// Tests that we can sort a bunch of parts with the end missing off a compressed
1334// file. We should use the part we can read.
1335TEST_F(MultinodeLoggerTest, SortTruncatedCompressedParts) {
1336 // Make a bunch of parts.
1337 {
1338 LoggerState pi1_logger = MakeLogger(pi1_);
1339 LoggerState pi2_logger = MakeLogger(pi2_);
1340
1341 event_loop_factory_.RunFor(chrono::milliseconds(95));
1342
1343 StartLogger(&pi1_logger, "", true);
1344 StartLogger(&pi2_logger, "", true);
1345
1346 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1347 }
1348
1349 // Append everything with .xz.
1350 AddExtension(".xz");
1351
1352 // Strip off the end of one of the files. Pick one with a lot of data.
1353 ::std::string compressed_contents =
1354 aos::util::ReadFileToStringOrDie(logfiles_[0]);
1355
1356 aos::util::WriteStringToFileOrDie(
1357 logfiles_[0],
1358 compressed_contents.substr(0, compressed_contents.size() - 100));
1359
1360 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1361 VerifyParts(sorted_parts);
1362}
1363#endif
1364
Austin Schuh01b4c352020-09-21 23:09:39 -07001365// Tests that if we remap a remapped channel, it shows up correctly.
1366TEST_F(MultinodeLoggerTest, RemapLoggedChannel) {
1367 {
1368 LoggerState pi1_logger = MakeLogger(pi1_);
1369 LoggerState pi2_logger = MakeLogger(pi2_);
1370
1371 event_loop_factory_.RunFor(chrono::milliseconds(95));
1372
1373 StartLogger(&pi1_logger);
1374 StartLogger(&pi2_logger);
1375
1376 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1377 }
1378
Austin Schuh287d43d2020-12-04 20:19:33 -08001379 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001380
1381 // Remap just on pi1.
1382 reader.RemapLoggedChannel<aos::timing::Report>(
1383 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1384
1385 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1386 log_reader_factory.set_send_delay(chrono::microseconds(0));
1387
1388 reader.Register(&log_reader_factory);
1389
1390 const Node *pi1 =
1391 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1392 const Node *pi2 =
1393 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1394
1395 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1396 // else should have moved.
1397 std::unique_ptr<EventLoop> pi1_event_loop =
1398 log_reader_factory.MakeEventLoop("test", pi1);
1399 pi1_event_loop->SkipTimingReport();
1400 std::unique_ptr<EventLoop> full_pi1_event_loop =
1401 log_reader_factory.MakeEventLoop("test", pi1);
1402 full_pi1_event_loop->SkipTimingReport();
1403 std::unique_ptr<EventLoop> pi2_event_loop =
1404 log_reader_factory.MakeEventLoop("test", pi2);
1405 pi2_event_loop->SkipTimingReport();
1406
1407 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1408 "/aos");
1409 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1410 full_pi1_event_loop.get(), "/pi1/aos");
1411 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1412 pi1_event_loop.get(), "/original/aos");
1413 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1414 full_pi1_event_loop.get(), "/original/pi1/aos");
1415 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1416 "/aos");
1417
1418 log_reader_factory.Run();
1419
1420 EXPECT_EQ(pi1_timing_report.count(), 0u);
1421 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1422 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1423 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1424 EXPECT_NE(pi2_timing_report.count(), 0u);
1425
1426 reader.Deregister();
1427}
1428
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001429// Tests that we properly recreate forwarded timestamps when replaying a log.
1430// This should be enough that we can then re-run the logger and get a valid log
1431// back.
1432TEST_F(MultinodeLoggerTest, MessageHeader) {
1433 {
1434 LoggerState pi1_logger = MakeLogger(pi1_);
1435 LoggerState pi2_logger = MakeLogger(pi2_);
1436
1437 event_loop_factory_.RunFor(chrono::milliseconds(95));
1438
1439 StartLogger(&pi1_logger);
1440 StartLogger(&pi2_logger);
1441
1442 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1443 }
1444
Austin Schuh287d43d2020-12-04 20:19:33 -08001445 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001446
1447 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1448 log_reader_factory.set_send_delay(chrono::microseconds(0));
1449
1450 // This sends out the fetched messages and advances time to the start of the
1451 // log file.
1452 reader.Register(&log_reader_factory);
1453
1454 const Node *pi1 =
1455 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1456 const Node *pi2 =
1457 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1458
1459 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1460 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1461 LOG(INFO) << "now pi1 "
1462 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1463 LOG(INFO) << "now pi2 "
1464 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1465
1466 EXPECT_THAT(reader.Nodes(), ::testing::ElementsAre(pi1, pi2));
1467
1468 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1469
1470 std::unique_ptr<EventLoop> pi1_event_loop =
1471 log_reader_factory.MakeEventLoop("test", pi1);
1472 std::unique_ptr<EventLoop> pi2_event_loop =
1473 log_reader_factory.MakeEventLoop("test", pi2);
1474
Austin Schuh0de30f32020-12-06 12:44:28 -08001475 MessageCounter<RemoteMessage> pi1_original_message_header_counter(
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001476 pi1_event_loop.get(), "/original/aos/remote_timestamps/pi2");
Austin Schuh0de30f32020-12-06 12:44:28 -08001477 MessageCounter<RemoteMessage> pi2_original_message_header_counter(
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001478 pi2_event_loop.get(), "/original/aos/remote_timestamps/pi1");
1479
1480 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1481 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1482 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1483 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1484
1485 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1486 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1487 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1488 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1489
1490 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1491 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1492 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1493 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1494
1495 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1496 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1497 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1498 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1499
1500 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1501 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1502 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1503 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1504
1505 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1506 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1507 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1508 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1509
1510 pi1_event_loop->MakeWatcher(
1511 "/aos/remote_timestamps/pi2",
Austin Schuh315b96b2020-12-11 21:21:12 -08001512 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1513 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1514 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
Austin Schuh0de30f32020-12-06 12:44:28 -08001515 &ping_on_pi2_fetcher](const RemoteMessage &header) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001516 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1517 chrono::nanoseconds(header.monotonic_sent_time()));
1518 const aos::realtime_clock::time_point header_realtime_sent_time(
1519 chrono::nanoseconds(header.realtime_sent_time()));
1520 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1521 chrono::nanoseconds(header.monotonic_remote_time()));
1522 const aos::realtime_clock::time_point header_realtime_remote_time(
1523 chrono::nanoseconds(header.realtime_remote_time()));
1524
1525 const Context *pi1_context = nullptr;
1526 const Context *pi2_context = nullptr;
1527
1528 if (header.channel_index() == pi1_timestamp_channel) {
1529 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1530 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1531 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1532 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1533 } else if (header.channel_index() == ping_timestamp_channel) {
1534 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1535 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1536 pi1_context = &ping_on_pi1_fetcher.context();
1537 pi2_context = &ping_on_pi2_fetcher.context();
1538 } else {
1539 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1540 << configuration::CleanedChannelToString(
1541 pi1_event_loop->configuration()->channels()->Get(
1542 header.channel_index()));
1543 }
1544
Austin Schuh315b96b2020-12-11 21:21:12 -08001545 ASSERT_TRUE(header.has_boot_uuid());
1546 EXPECT_EQ(header.boot_uuid()->string_view(),
1547 pi2_event_loop->boot_uuid().string_view());
1548
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001549 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1550 EXPECT_EQ(pi2_context->remote_queue_index, header.remote_queue_index());
1551 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
1552
1553 EXPECT_EQ(pi2_context->monotonic_event_time,
1554 header_monotonic_sent_time);
1555 EXPECT_EQ(pi2_context->realtime_event_time, header_realtime_sent_time);
1556 EXPECT_EQ(pi2_context->realtime_remote_time,
1557 header_realtime_remote_time);
1558 EXPECT_EQ(pi2_context->monotonic_remote_time,
1559 header_monotonic_remote_time);
1560
1561 EXPECT_EQ(pi1_context->realtime_event_time,
1562 header_realtime_remote_time);
1563 EXPECT_EQ(pi1_context->monotonic_event_time,
1564 header_monotonic_remote_time);
1565 });
1566 pi2_event_loop->MakeWatcher(
1567 "/aos/remote_timestamps/pi1",
Austin Schuh315b96b2020-12-11 21:21:12 -08001568 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
1569 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
1570 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
Austin Schuh0de30f32020-12-06 12:44:28 -08001571 &pong_on_pi1_fetcher](const RemoteMessage &header) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001572 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1573 chrono::nanoseconds(header.monotonic_sent_time()));
1574 const aos::realtime_clock::time_point header_realtime_sent_time(
1575 chrono::nanoseconds(header.realtime_sent_time()));
1576 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1577 chrono::nanoseconds(header.monotonic_remote_time()));
1578 const aos::realtime_clock::time_point header_realtime_remote_time(
1579 chrono::nanoseconds(header.realtime_remote_time()));
1580
1581 const Context *pi2_context = nullptr;
1582 const Context *pi1_context = nullptr;
1583
1584 if (header.channel_index() == pi2_timestamp_channel) {
1585 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
1586 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
1587 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
1588 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
1589 } else if (header.channel_index() == pong_timestamp_channel) {
1590 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
1591 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
1592 pi2_context = &pong_on_pi2_fetcher.context();
1593 pi1_context = &pong_on_pi1_fetcher.context();
1594 } else {
1595 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1596 << configuration::CleanedChannelToString(
1597 pi2_event_loop->configuration()->channels()->Get(
1598 header.channel_index()));
1599 }
1600
Austin Schuh315b96b2020-12-11 21:21:12 -08001601 ASSERT_TRUE(header.has_boot_uuid());
1602 EXPECT_EQ(header.boot_uuid()->string_view(),
1603 pi1_event_loop->boot_uuid().string_view());
1604
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001605 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
1606 EXPECT_EQ(pi1_context->remote_queue_index, header.remote_queue_index());
1607 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
1608
1609 EXPECT_EQ(pi1_context->monotonic_event_time,
1610 header_monotonic_sent_time);
1611 EXPECT_EQ(pi1_context->realtime_event_time, header_realtime_sent_time);
1612 EXPECT_EQ(pi1_context->realtime_remote_time,
1613 header_realtime_remote_time);
1614 EXPECT_EQ(pi1_context->monotonic_remote_time,
1615 header_monotonic_remote_time);
1616
1617 EXPECT_EQ(pi2_context->realtime_event_time,
1618 header_realtime_remote_time);
1619 EXPECT_EQ(pi2_context->monotonic_event_time,
1620 header_monotonic_remote_time);
1621 });
1622
1623 // And confirm we can re-create a log again, while checking the contents.
1624 {
1625 LoggerState pi1_logger = MakeLogger(
1626 configuration::GetNode(log_reader_factory.configuration(), pi1_),
1627 &log_reader_factory);
1628 LoggerState pi2_logger = MakeLogger(
1629 configuration::GetNode(log_reader_factory.configuration(), pi2_),
1630 &log_reader_factory);
1631
1632 StartLogger(&pi1_logger, "relogged");
1633 StartLogger(&pi2_logger, "relogged");
1634
1635 log_reader_factory.Run();
1636 }
1637
1638 EXPECT_EQ(pi2_original_message_header_counter.count(), 0u);
1639 EXPECT_EQ(pi1_original_message_header_counter.count(), 0u);
1640
1641 reader.Deregister();
1642}
1643
Austin Schuh315b96b2020-12-11 21:21:12 -08001644// Tests that we properly populate and extract the logger_start time by setting
1645// up a clock difference between 2 nodes and looking at the resulting parts.
1646TEST_F(MultinodeLoggerTest, LoggerStartTime) {
1647 {
1648 LoggerState pi1_logger = MakeLogger(pi1_);
1649 LoggerState pi2_logger = MakeLogger(pi2_);
1650
1651 NodeEventLoopFactory *pi2 =
1652 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1653
1654 pi2->SetDistributedOffset(chrono::seconds(1000), 1.0);
1655
1656 StartLogger(&pi1_logger);
1657 StartLogger(&pi2_logger);
1658
1659 event_loop_factory_.RunFor(chrono::milliseconds(10000));
1660 }
1661
1662 for (const LogFile &log_file : SortParts(logfiles_)) {
1663 for (const LogParts &log_part : log_file.parts) {
1664 if (log_part.node == log_file.logger_node) {
1665 EXPECT_EQ(log_part.logger_monotonic_start_time,
1666 aos::monotonic_clock::min_time);
1667 EXPECT_EQ(log_part.logger_realtime_start_time,
1668 aos::realtime_clock::min_time);
1669 } else {
1670 const chrono::seconds offset = log_file.logger_node == "pi1"
1671 ? -chrono::seconds(1000)
1672 : chrono::seconds(1000);
1673 EXPECT_EQ(log_part.logger_monotonic_start_time,
1674 log_part.monotonic_start_time + offset);
1675 EXPECT_EQ(log_part.logger_realtime_start_time,
1676 log_file.realtime_start_time +
1677 (log_part.logger_monotonic_start_time -
1678 log_file.monotonic_start_time));
1679 }
1680 }
1681 }
1682}
1683
Austin Schuh8bd96322020-02-13 21:18:22 -08001684// TODO(austin): We can write a test which recreates a logfile and confirms that
1685// we get it back. That is the ultimate test.
1686
Austin Schuh315b96b2020-12-11 21:21:12 -08001687// Tests that we properly recreate forwarded timestamps when replaying a log.
1688// This should be enough that we can then re-run the logger and get a valid log
1689// back.
1690TEST_F(MultinodeLoggerDeathTest, RemoteReboot) {
1691 std::string pi2_boot1;
1692 std::string pi2_boot2;
1693 {
1694 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
1695 ->boot_uuid()
1696 .string_view();
1697 LoggerState pi1_logger = MakeLogger(pi1_);
1698
1699 event_loop_factory_.RunFor(chrono::milliseconds(95));
1700
1701 StartLogger(&pi1_logger);
1702
1703 event_loop_factory_.RunFor(chrono::milliseconds(10000));
1704
1705 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
1706
1707 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
1708 ->boot_uuid()
1709 .string_view();
1710
1711 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1712 }
1713
1714 // Confirm that we refuse to replay logs with missing boot uuids.
1715 EXPECT_DEATH(
1716 {
1717 LogReader reader(SortParts(pi1_reboot_logfiles_));
1718
1719 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1720 log_reader_factory.set_send_delay(chrono::microseconds(0));
1721
1722 // This sends out the fetched messages and advances time to the start of
1723 // the log file.
1724 reader.Register(&log_reader_factory);
1725 },
1726 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
1727 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
1728}
1729
Austin Schuhe309d2a2019-11-29 13:25:21 -08001730} // namespace testing
1731} // namespace logger
1732} // namespace aos