blob: 2b504f337f09509235c5dd8c0bfb4e01dccb485d [file] [log] [blame]
Austin Schuhb06f03b2021-02-17 22:00:37 -08001#include "aos/events/logging/log_reader.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08002
Austin Schuh6bb8a822021-03-31 23:04:39 -07003#include <sys/stat.h>
4
Austin Schuh315b96b2020-12-11 21:21:12 -08005#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08006#include "aos/events/event_loop.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08007#include "aos/events/logging/log_writer.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuhc243b422020-10-11 15:35:08 -070015#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070016#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080017#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080018#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080019#include "gtest/gtest.h"
20
Austin Schuh3bd4c402020-11-06 18:19:06 -080021#ifdef LZMA
22#include "aos/events/logging/lzma_encoder.h"
23#endif
24
Austin Schuhe309d2a2019-11-29 13:25:21 -080025namespace aos {
26namespace logger {
27namespace testing {
28
29namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080030using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070031using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080032
Austin Schuhee4713b2021-03-21 19:25:17 -070033constexpr std::string_view kSingleConfigSha256(
Austin Schuh25b46712021-01-03 00:04:38 -080034 "bc8c9c2e31589eae6f0e36d766f6a437643e861d9568b7483106841cf7504dea");
Austin Schuh8c399962020-12-25 21:51:45 -080035
Austin Schuhb06f03b2021-02-17 22:00:37 -080036std::vector<std::vector<std::string>> ToLogReaderVector(
37 const std::vector<LogFile> &log_files) {
38 std::vector<std::vector<std::string>> result;
39 for (const LogFile &log_file : log_files) {
40 for (const LogParts &log_parts : log_file.parts) {
41 std::vector<std::string> parts;
42 for (const std::string &part : log_parts.parts) {
43 parts.emplace_back(part);
44 }
45 result.emplace_back(std::move(parts));
46 }
47 }
48 return result;
49}
50
Austin Schuhe309d2a2019-11-29 13:25:21 -080051class LoggerTest : public ::testing::Test {
52 public:
53 LoggerTest()
54 : config_(
55 aos::configuration::ReadConfig("aos/events/pingpong_config.json")),
56 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080057 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080058 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080059 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080060 pong_(pong_event_loop_.get()) {}
61
62 // Config and factory.
63 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
64 SimulatedEventLoopFactory event_loop_factory_;
65
66 // Event loop and app for Ping
67 std::unique_ptr<EventLoop> ping_event_loop_;
68 Ping ping_;
69
70 // Event loop and app for Pong
71 std::unique_ptr<EventLoop> pong_event_loop_;
72 Pong pong_;
73};
74
Brian Silverman1f345222020-09-24 21:14:48 -070075using LoggerDeathTest = LoggerTest;
76
Austin Schuhe309d2a2019-11-29 13:25:21 -080077// Tests that we can startup at all. This confirms that the channels are all in
78// the config.
79TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070080 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070081 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080082 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070083 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080085 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080086 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080087 unlink(logfile.c_str());
88
89 LOG(INFO) << "Logging data to " << logfile;
90
91 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080092 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080093 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080094
95 event_loop_factory_.RunFor(chrono::milliseconds(95));
96
Brian Silverman1f345222020-09-24 21:14:48 -070097 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -080098 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -070099 logger.set_polling_period(std::chrono::milliseconds(100));
100 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800101 event_loop_factory_.RunFor(chrono::milliseconds(20000));
102 }
103
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800104 // Even though it doesn't make any difference here, exercise the logic for
105 // passing in a separate config.
106 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800107
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800108 // Confirm that we can remap logged channels to point to new buses.
109 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
Austin Schuh15649d62019-12-28 16:36:38 -0800111 // This sends out the fetched messages and advances time to the start of the
112 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800113 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800114
Austin Schuh07676622021-01-21 18:59:17 -0800115 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800118 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800119
120 int ping_count = 10;
121 int pong_count = 10;
122
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800123 // Confirm that the ping value matches in the remapped channel location.
124 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800125 [&ping_count](const examples::Ping &ping) {
126 EXPECT_EQ(ping.value(), ping_count + 1);
127 ++ping_count;
128 });
129 // Confirm that the ping and pong counts both match, and the value also
130 // matches.
131 test_event_loop->MakeWatcher(
132 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
133 EXPECT_EQ(pong.value(), pong_count + 1);
134 ++pong_count;
135 EXPECT_EQ(ping_count, pong_count);
136 });
137
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800138 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800139 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800140}
141
Brian Silverman1f345222020-09-24 21:14:48 -0700142// Tests calling StartLogging twice.
143TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800144 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700145 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800146 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700147 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
149 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800150 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700151 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700152 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
153 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800154 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700155 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800156 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700157
158 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
159
160 {
161 std::unique_ptr<EventLoop> logger_event_loop =
162 event_loop_factory_.MakeEventLoop("logger");
163
164 event_loop_factory_.RunFor(chrono::milliseconds(95));
165
166 Logger logger(logger_event_loop.get());
167 logger.set_polling_period(std::chrono::milliseconds(100));
168 logger_event_loop->OnRun(
169 [base_name1, base_name2, &logger_event_loop, &logger]() {
170 logger.StartLogging(std::make_unique<LocalLogNamer>(
171 base_name1, logger_event_loop->node()));
172 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
173 base_name2, logger_event_loop->node())),
174 "Already logging");
175 });
176 event_loop_factory_.RunFor(chrono::milliseconds(20000));
177 }
178}
179
180// Tests calling StopLogging twice.
181TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800182 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700183 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800184 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700185 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700186 const ::std::string logfile = base_name + ".part0.bfbs";
187 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800188 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700189 unlink(logfile.c_str());
190
191 LOG(INFO) << "Logging data to " << logfile;
192
193 {
194 std::unique_ptr<EventLoop> logger_event_loop =
195 event_loop_factory_.MakeEventLoop("logger");
196
197 event_loop_factory_.RunFor(chrono::milliseconds(95));
198
199 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800200 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700201 logger.set_polling_period(std::chrono::milliseconds(100));
202 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
203 logger.StartLogging(std::make_unique<LocalLogNamer>(
204 base_name, logger_event_loop->node()));
205 logger.StopLogging(aos::monotonic_clock::min_time);
206 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
207 "Not logging right now");
208 });
209 event_loop_factory_.RunFor(chrono::milliseconds(20000));
210 }
211}
212
213// Tests that we can startup twice.
214TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800215 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700216 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800217 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700218 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700219 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
220 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800221 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700222 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700223 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
224 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800225 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700226 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800227 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700228
229 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
230
231 {
232 std::unique_ptr<EventLoop> logger_event_loop =
233 event_loop_factory_.MakeEventLoop("logger");
234
235 event_loop_factory_.RunFor(chrono::milliseconds(95));
236
237 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800238 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700239 logger.set_polling_period(std::chrono::milliseconds(100));
240 logger.StartLogging(
241 std::make_unique<LocalLogNamer>(base_name1, logger_event_loop->node()));
242 event_loop_factory_.RunFor(chrono::milliseconds(10000));
243 logger.StopLogging(logger_event_loop->monotonic_now());
244 event_loop_factory_.RunFor(chrono::milliseconds(10000));
245 logger.StartLogging(
246 std::make_unique<LocalLogNamer>(base_name2, logger_event_loop->node()));
247 event_loop_factory_.RunFor(chrono::milliseconds(10000));
248 }
249
250 for (const auto &logfile :
251 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
252 SCOPED_TRACE(std::get<0>(logfile));
253 LogReader reader(std::get<0>(logfile));
254 reader.Register();
255
Austin Schuh07676622021-01-21 18:59:17 -0800256 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700257
258 std::unique_ptr<EventLoop> test_event_loop =
259 reader.event_loop_factory()->MakeEventLoop("log_reader");
260
261 int ping_count = std::get<1>(logfile);
262 int pong_count = std::get<1>(logfile);
263
264 // Confirm that the ping and pong counts both match, and the value also
265 // matches.
266 test_event_loop->MakeWatcher("/test",
267 [&ping_count](const examples::Ping &ping) {
268 EXPECT_EQ(ping.value(), ping_count + 1);
269 ++ping_count;
270 });
271 test_event_loop->MakeWatcher(
272 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
273 EXPECT_EQ(pong.value(), pong_count + 1);
274 ++pong_count;
275 EXPECT_EQ(ping_count, pong_count);
276 });
277
278 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
279 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
280 }
281}
282
Austin Schuhfa895892020-01-07 20:07:41 -0800283// Tests that we can read and write rotated log files.
284TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800285 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700286 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800287 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700288 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700289 const ::std::string logfile0 = base_name + ".part0.bfbs";
290 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800291 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800292 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800293 unlink(logfile0.c_str());
294 unlink(logfile1.c_str());
295
296 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
297
298 {
Austin Schuhfa895892020-01-07 20:07:41 -0800299 std::unique_ptr<EventLoop> logger_event_loop =
300 event_loop_factory_.MakeEventLoop("logger");
301
302 event_loop_factory_.RunFor(chrono::milliseconds(95));
303
Brian Silverman1f345222020-09-24 21:14:48 -0700304 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800305 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700306 logger.set_polling_period(std::chrono::milliseconds(100));
307 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800308 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700309 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800310 event_loop_factory_.RunFor(chrono::milliseconds(10000));
311 }
312
Austin Schuh64fab802020-09-09 22:47:47 -0700313 {
314 // Confirm that the UUIDs match for both the parts and the logger, and the
315 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800316 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700317 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800318 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700319 }
320
Brian Silvermanae7c0332020-09-30 16:58:23 -0700321 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
322 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700323 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
324 log_header[1].message().parts_uuid()->string_view());
325
326 EXPECT_EQ(log_header[0].message().parts_index(), 0);
327 EXPECT_EQ(log_header[1].message().parts_index(), 1);
328 }
329
Austin Schuhfa895892020-01-07 20:07:41 -0800330 // Even though it doesn't make any difference here, exercise the logic for
331 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800332 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800333
334 // Confirm that we can remap logged channels to point to new buses.
335 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
336
337 // This sends out the fetched messages and advances time to the start of the
338 // log file.
339 reader.Register();
340
Austin Schuh07676622021-01-21 18:59:17 -0800341 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800342
343 std::unique_ptr<EventLoop> test_event_loop =
344 reader.event_loop_factory()->MakeEventLoop("log_reader");
345
346 int ping_count = 10;
347 int pong_count = 10;
348
349 // Confirm that the ping value matches in the remapped channel location.
350 test_event_loop->MakeWatcher("/original/test",
351 [&ping_count](const examples::Ping &ping) {
352 EXPECT_EQ(ping.value(), ping_count + 1);
353 ++ping_count;
354 });
355 // Confirm that the ping and pong counts both match, and the value also
356 // matches.
357 test_event_loop->MakeWatcher(
358 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
359 EXPECT_EQ(pong.value(), pong_count + 1);
360 ++pong_count;
361 EXPECT_EQ(ping_count, pong_count);
362 });
363
364 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
365 EXPECT_EQ(ping_count, 2010);
366}
367
Austin Schuh4c4e0092019-12-22 16:18:03 -0800368// Tests that a large number of messages per second doesn't overwhelm writev.
369TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800370 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700371 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800372 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700373 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700374 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800375 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800376 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800377 unlink(logfile.c_str());
378
379 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700380 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800381
382 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800383 std::unique_ptr<EventLoop> logger_event_loop =
384 event_loop_factory_.MakeEventLoop("logger");
385
386 std::unique_ptr<EventLoop> ping_spammer_event_loop =
387 event_loop_factory_.MakeEventLoop("ping_spammer");
388 aos::Sender<examples::Ping> ping_sender =
389 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
390
391 aos::TimerHandler *timer_handler =
392 ping_spammer_event_loop->AddTimer([&ping_sender]() {
393 aos::Sender<examples::Ping>::Builder builder =
394 ping_sender.MakeBuilder();
395 examples::Ping::Builder ping_builder =
396 builder.MakeBuilder<examples::Ping>();
397 CHECK(builder.Send(ping_builder.Finish()));
398 });
399
400 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
401 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
402 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
403 chrono::microseconds(50));
404 });
405
Brian Silverman1f345222020-09-24 21:14:48 -0700406 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800407 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700408 logger.set_polling_period(std::chrono::milliseconds(100));
409 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800410
411 event_loop_factory_.RunFor(chrono::milliseconds(1000));
412 }
413}
414
Austin Schuh61e973f2021-02-21 21:43:56 -0800415// Parameters to run all the tests with.
416struct Param {
417 // The config file to use.
418 std::string config;
419 // If true, the RemoteMessage channel should be shared between all the remote
420 // channels. If false, there will be 1 RemoteMessage channel per remote
421 // channel.
422 bool shared;
423 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700424 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800425};
Austin Schuh315b96b2020-12-11 21:21:12 -0800426
Austin Schuh61e973f2021-02-21 21:43:56 -0800427class MultinodeLoggerTest : public ::testing::TestWithParam<struct Param> {
Austin Schuh15649d62019-12-28 16:36:38 -0800428 public:
429 MultinodeLoggerTest()
430 : config_(aos::configuration::ReadConfig(
Austin Schuh61e973f2021-02-21 21:43:56 -0800431 absl::StrCat("aos/events/logging/", GetParam().config))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800432 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800433 event_loop_factory_(&config_.message()),
Austin Schuhcde938c2020-02-02 17:30:07 -0800434 pi1_(
435 configuration::GetNode(event_loop_factory_.configuration(), "pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800436 pi1_index_(configuration::GetNodeIndex(
437 event_loop_factory_.configuration(), pi1_)),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700438 pi2_(
439 configuration::GetNode(event_loop_factory_.configuration(), "pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800440 pi2_index_(configuration::GetNodeIndex(
441 event_loop_factory_.configuration(), pi2_)),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800442 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800443 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
444 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800445 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800446 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800447 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
448 structured_logfiles_(StructureLogFiles()),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700449 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping", pi1_)),
450 ping_(ping_event_loop_.get()),
451 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong", pi2_)),
452 pong_(pong_event_loop_.get()) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800453 LOG(INFO) << "Config " << GetParam().config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800454 event_loop_factory_.SetTimeConverter(&time_converter_);
455
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700456 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700457 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700458 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800459 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700460 }
461
Austin Schuh268586b2021-03-31 22:24:39 -0700462 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800463 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800464 unlink(file.c_str());
465 }
466
Austin Schuh268586b2021-03-31 22:24:39 -0700467 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800468 unlink(file.c_str());
469 }
470
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700471 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
472 << " and " << logfiles_[2];
473 }
474
Austin Schuh61e973f2021-02-21 21:43:56 -0800475 bool shared() const { return GetParam().shared; }
476
477 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
478 std::string logfile_base2) {
479 std::vector<std::string> result;
480 result.emplace_back(
481 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
482 result.emplace_back(
483 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
484 result.emplace_back(logfile_base1 + "_pi1_data.part0.bfbs");
485 result.emplace_back(logfile_base1 +
486 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
487 result.emplace_back(logfile_base1 +
488 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
489 result.emplace_back(logfile_base2 + "_pi2_data.part0.bfbs");
490 result.emplace_back(
491 logfile_base2 +
492 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
493 result.emplace_back(
494 logfile_base2 +
495 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
496 result.emplace_back(
497 logfile_base1 +
498 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
499 result.emplace_back(
500 logfile_base1 +
501 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
502 if (shared()) {
503 result.emplace_back(logfile_base1 +
504 "_timestamps/pi1/aos/remote_timestamps/pi2/"
505 "aos.message_bridge.RemoteMessage.part0.bfbs");
506 result.emplace_back(logfile_base1 +
507 "_timestamps/pi1/aos/remote_timestamps/pi2/"
508 "aos.message_bridge.RemoteMessage.part1.bfbs");
509 result.emplace_back(logfile_base2 +
510 "_timestamps/pi2/aos/remote_timestamps/pi1/"
511 "aos.message_bridge.RemoteMessage.part0.bfbs");
512 result.emplace_back(logfile_base2 +
513 "_timestamps/pi2/aos/remote_timestamps/pi1/"
514 "aos.message_bridge.RemoteMessage.part1.bfbs");
515 } else {
516 result.emplace_back(logfile_base1 +
517 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
518 "aos-message_bridge-Timestamp/"
519 "aos.message_bridge.RemoteMessage.part0.bfbs");
520 result.emplace_back(logfile_base1 +
521 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
522 "aos-message_bridge-Timestamp/"
523 "aos.message_bridge.RemoteMessage.part1.bfbs");
524 result.emplace_back(logfile_base2 +
525 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
526 "aos-message_bridge-Timestamp/"
527 "aos.message_bridge.RemoteMessage.part0.bfbs");
528 result.emplace_back(logfile_base2 +
529 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
530 "aos-message_bridge-Timestamp/"
531 "aos.message_bridge.RemoteMessage.part1.bfbs");
532 result.emplace_back(logfile_base1 +
533 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
534 "aos-examples-Ping/"
535 "aos.message_bridge.RemoteMessage.part0.bfbs");
536 result.emplace_back(logfile_base1 +
537 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
538 "aos-examples-Ping/"
539 "aos.message_bridge.RemoteMessage.part1.bfbs");
540 }
541
542 return result;
543 }
544
545 std::vector<std::string> MakePi1RebootLogfiles() {
546 std::vector<std::string> result;
547 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
548 result.emplace_back(logfile_base1_ +
549 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
550 result.emplace_back(logfile_base1_ +
551 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
552 result.emplace_back(logfile_base1_ +
553 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
554 result.emplace_back(
555 logfile_base1_ +
556 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
557 result.emplace_back(
558 logfile_base1_ +
559 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
560 result.emplace_back(
561 logfile_base1_ +
562 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
563 result.emplace_back(
564 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
565 if (shared()) {
566 result.emplace_back(logfile_base1_ +
567 "_timestamps/pi1/aos/remote_timestamps/pi2/"
568 "aos.message_bridge.RemoteMessage.part0.bfbs");
569 result.emplace_back(logfile_base1_ +
570 "_timestamps/pi1/aos/remote_timestamps/pi2/"
571 "aos.message_bridge.RemoteMessage.part1.bfbs");
572 result.emplace_back(logfile_base1_ +
573 "_timestamps/pi1/aos/remote_timestamps/pi2/"
574 "aos.message_bridge.RemoteMessage.part2.bfbs");
575 } else {
576 result.emplace_back(logfile_base1_ +
577 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
578 "aos-message_bridge-Timestamp/"
579 "aos.message_bridge.RemoteMessage.part0.bfbs");
580 result.emplace_back(logfile_base1_ +
581 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
582 "aos-message_bridge-Timestamp/"
583 "aos.message_bridge.RemoteMessage.part1.bfbs");
584 result.emplace_back(logfile_base1_ +
585 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
586 "aos-message_bridge-Timestamp/"
587 "aos.message_bridge.RemoteMessage.part2.bfbs");
588
589 result.emplace_back(logfile_base1_ +
590 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
591 "aos-examples-Ping/"
592 "aos.message_bridge.RemoteMessage.part0.bfbs");
593 result.emplace_back(logfile_base1_ +
594 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
595 "aos-examples-Ping/"
596 "aos.message_bridge.RemoteMessage.part1.bfbs");
597 result.emplace_back(logfile_base1_ +
598 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
599 "aos-examples-Ping/"
600 "aos.message_bridge.RemoteMessage.part2.bfbs");
601 }
602 return result;
603 }
604
605 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
606 std::vector<std::string> result;
607 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
608 result.emplace_back(logfile_base1_ +
609 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
610 result.emplace_back(
611 logfile_base1_ +
612 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
613 result.emplace_back(
614 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
615
616 if (shared()) {
617 result.emplace_back(logfile_base1_ +
618 "_timestamps/pi1/aos/remote_timestamps/pi2/"
619 "aos.message_bridge.RemoteMessage.part0.bfbs");
620 } else {
621 result.emplace_back(logfile_base1_ +
622 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
623 "aos-message_bridge-Timestamp/"
624 "aos.message_bridge.RemoteMessage.part0.bfbs");
625 result.emplace_back(logfile_base1_ +
626 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
627 "aos-examples-Ping/"
628 "aos.message_bridge.RemoteMessage.part0.bfbs");
629 }
630 return result;
631 }
632
633 std::vector<std::vector<std::string>> StructureLogFiles() {
634 std::vector<std::vector<std::string>> result{
635 std::vector<std::string>{logfiles_[2]},
636 std::vector<std::string>{logfiles_[3], logfiles_[4]},
637 std::vector<std::string>{logfiles_[5]},
638 std::vector<std::string>{logfiles_[6], logfiles_[7]},
639 std::vector<std::string>{logfiles_[8], logfiles_[9]},
640 std::vector<std::string>{logfiles_[10], logfiles_[11]},
641 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
642
643 if (!shared()) {
644 result.emplace_back(
645 std::vector<std::string>{logfiles_[14], logfiles_[15]});
646 }
647
648 return result;
649 }
650
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700651 struct LoggerState {
652 std::unique_ptr<EventLoop> event_loop;
653 std::unique_ptr<Logger> logger;
654 };
655
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700656 LoggerState MakeLogger(const Node *node,
657 SimulatedEventLoopFactory *factory = nullptr) {
658 if (factory == nullptr) {
659 factory = &event_loop_factory_;
660 }
661 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700662 }
663
Austin Schuh3bd4c402020-11-06 18:19:06 -0800664 void StartLogger(LoggerState *logger, std::string logfile_base = "",
665 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700666 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800667 if (logger->event_loop->node()->name()->string_view() == "pi1") {
668 logfile_base = logfile_base1_;
669 } else {
670 logfile_base = logfile_base2_;
671 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700672 }
673
Brian Silverman1f345222020-09-24 21:14:48 -0700674 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
675 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800676 logger->logger->set_name(absl::StrCat(
677 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800678 logger->event_loop->OnRun([logger, logfile_base, compress]() {
679 std::unique_ptr<MultiNodeLogNamer> namer =
680 std::make_unique<MultiNodeLogNamer>(
681 logfile_base, logger->event_loop->configuration(),
682 logger->event_loop->node());
683 if (compress) {
684#ifdef LZMA
685 namer->set_extension(".xz");
686 namer->set_encoder_factory(
687 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
688#else
689 LOG(FATAL) << "Compression unsupported";
690#endif
691 }
692
693 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700694 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700695 }
Austin Schuh15649d62019-12-28 16:36:38 -0800696
Austin Schuh3bd4c402020-11-06 18:19:06 -0800697 void VerifyParts(const std::vector<LogFile> &sorted_parts,
698 const std::vector<std::string> &corrupted_parts = {}) {
699 EXPECT_EQ(sorted_parts.size(), 2u);
700
701 // Count up the number of UUIDs and make sure they are what we expect as a
702 // sanity check.
703 std::set<std::string> log_event_uuids;
704 std::set<std::string> parts_uuids;
705 std::set<std::string> both_uuids;
706
707 size_t missing_rt_count = 0;
708
709 std::vector<std::string> logger_nodes;
710 for (const LogFile &log_file : sorted_parts) {
711 EXPECT_FALSE(log_file.log_event_uuid.empty());
712 log_event_uuids.insert(log_file.log_event_uuid);
713 logger_nodes.emplace_back(log_file.logger_node);
714 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800715 EXPECT_TRUE(log_file.config);
716 EXPECT_EQ(log_file.name,
717 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800718
719 for (const LogParts &part : log_file.parts) {
720 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
721 << ": " << part;
722 missing_rt_count +=
723 part.realtime_start_time == aos::realtime_clock::min_time;
724
725 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
726 log_event_uuids.end());
727 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800728 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800729 parts_uuids.insert(part.parts_uuid);
730 both_uuids.insert(part.parts_uuid);
731 }
732 }
733
Austin Schuh61e973f2021-02-21 21:43:56 -0800734 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
735 // start time on remote nodes because we don't know it and would be
736 // guessing. And the log reader can actually do a better job. The number
737 // depends on if we have the remote timestamps split across 2 files, or just
738 // across 1, depending on if we are using a split or combined timestamp
739 // channel config.
740 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800741
742 EXPECT_EQ(log_event_uuids.size(), 2u);
743 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
744 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
745
746 // Test that each list of parts is in order. Don't worry about the ordering
747 // between part file lists though.
748 // (inner vectors all need to be in order, but outer one doesn't matter).
749 EXPECT_THAT(ToLogReaderVector(sorted_parts),
750 ::testing::UnorderedElementsAreArray(structured_logfiles_));
751
752 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
753
754 EXPECT_NE(sorted_parts[0].realtime_start_time,
755 aos::realtime_clock::min_time);
756 EXPECT_NE(sorted_parts[1].realtime_start_time,
757 aos::realtime_clock::min_time);
758
759 EXPECT_NE(sorted_parts[0].monotonic_start_time,
760 aos::monotonic_clock::min_time);
761 EXPECT_NE(sorted_parts[1].monotonic_start_time,
762 aos::monotonic_clock::min_time);
763
764 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
765 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
766 }
767
Austin Schuhc9049732020-12-21 22:27:15 -0800768 void ConfirmReadable(const std::vector<std::string> &files) {
769 LogReader reader(SortParts(files));
770
771 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
772 reader.Register(&log_reader_factory);
773
774 log_reader_factory.Run();
775
776 reader.Deregister();
777 }
778
Austin Schuh3bd4c402020-11-06 18:19:06 -0800779 void AddExtension(std::string_view extension) {
780 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
781 [extension](const std::string &in) {
782 return absl::StrCat(in, extension);
783 });
784
785 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
786 structured_logfiles_.begin(),
787 [extension](std::vector<std::string> in) {
788 std::transform(in.begin(), in.end(), in.begin(),
789 [extension](const std::string &in_str) {
790 return absl::StrCat(in_str, extension);
791 });
792 return in;
793 });
794 }
795
Austin Schuh15649d62019-12-28 16:36:38 -0800796 // Config and factory.
797 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800798 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800799 SimulatedEventLoopFactory event_loop_factory_;
800
Austin Schuh87dd3832021-01-01 23:07:31 -0800801 const Node *const pi1_;
802 const size_t pi1_index_;
803 const Node *const pi2_;
804 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700805
806 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800807 std::string logfile_base1_;
808 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800809 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700810 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800811 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700812
813 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700814
815 std::unique_ptr<EventLoop> ping_event_loop_;
816 Ping ping_;
817 std::unique_ptr<EventLoop> pong_event_loop_;
818 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800819};
820
Austin Schuh391e3172020-09-01 22:48:18 -0700821// Counts the number of messages on a channel. Returns (channel name, channel
822// type, count) for every message matching matcher()
823std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800824 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800825 std::function<bool(const MessageHeader *)> matcher) {
826 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800827 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800828
Austin Schuh6f3babe2020-01-26 20:34:50 -0800829 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800830 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800831 message_reader.ReadMessage();
832 if (!msg) {
833 break;
834 }
835
836 if (matcher(&msg.value().message())) {
837 counts[msg.value().message().channel_index()]++;
838 }
839 }
840
Austin Schuh391e3172020-09-01 22:48:18 -0700841 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800842 int channel = 0;
843 for (size_t i = 0; i < counts.size(); ++i) {
844 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800845 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700846 result.push_back(std::make_tuple(channel->name()->str(),
847 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800848 }
849 ++channel;
850 }
851
852 return result;
853}
854
855// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700856std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800857 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700858 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800859 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800860 if (msg->has_data()) {
861 CHECK(!msg->has_monotonic_remote_time());
862 CHECK(!msg->has_realtime_remote_time());
863 CHECK(!msg->has_remote_queue_index());
864 return true;
865 }
866 return false;
867 });
868}
869
870// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700871std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800872 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800873 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800874 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800875 if (!msg->has_data()) {
876 CHECK(msg->has_monotonic_remote_time());
877 CHECK(msg->has_realtime_remote_time());
878 CHECK(msg->has_remote_queue_index());
879 return true;
880 }
881 return false;
882 });
883}
884
Austin Schuhcde938c2020-02-02 17:30:07 -0800885// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800886TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800887 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800888 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700889 LoggerState pi1_logger = MakeLogger(pi1_);
890 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800891
892 event_loop_factory_.RunFor(chrono::milliseconds(95));
893
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700894 StartLogger(&pi1_logger);
895 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800896
Austin Schuh15649d62019-12-28 16:36:38 -0800897 event_loop_factory_.RunFor(chrono::milliseconds(20000));
898 }
899
Austin Schuh6f3babe2020-01-26 20:34:50 -0800900 {
Austin Schuh64fab802020-09-09 22:47:47 -0700901 std::set<std::string> logfile_uuids;
902 std::set<std::string> parts_uuids;
903 // Confirm that we have the expected number of UUIDs for both the logfile
904 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800905 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700906 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800907 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800908 if (!log_header.back().message().has_configuration()) {
909 logfile_uuids.insert(
910 log_header.back().message().log_event_uuid()->str());
911 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
912 }
Austin Schuh64fab802020-09-09 22:47:47 -0700913 }
Austin Schuh15649d62019-12-28 16:36:38 -0800914
Austin Schuh64fab802020-09-09 22:47:47 -0700915 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800916 if (shared()) {
917 EXPECT_EQ(parts_uuids.size(), 7u);
918 } else {
919 EXPECT_EQ(parts_uuids.size(), 8u);
920 }
Austin Schuh64fab802020-09-09 22:47:47 -0700921
922 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800923 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700924 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi2");
925 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
926 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
927 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi1");
928 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800929 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
930 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
Austin Schuh64fab802020-09-09 22:47:47 -0700931 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
932 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800933 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi1");
934 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi1");
935 if (!shared()) {
936 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
937 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
938 }
Austin Schuh64fab802020-09-09 22:47:47 -0700939
940 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800941 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuh64fab802020-09-09 22:47:47 -0700942 EXPECT_EQ(log_header[3].message().parts_index(), 0);
Austin Schuh61e973f2021-02-21 21:43:56 -0800943 EXPECT_EQ(log_header[4].message().parts_index(), 1);
944 EXPECT_EQ(log_header[5].message().parts_index(), 0);
Austin Schuh64fab802020-09-09 22:47:47 -0700945 EXPECT_EQ(log_header[6].message().parts_index(), 0);
946 EXPECT_EQ(log_header[7].message().parts_index(), 1);
947 EXPECT_EQ(log_header[8].message().parts_index(), 0);
948 EXPECT_EQ(log_header[9].message().parts_index(), 1);
949 EXPECT_EQ(log_header[10].message().parts_index(), 0);
950 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800951 EXPECT_EQ(log_header[12].message().parts_index(), 0);
952 EXPECT_EQ(log_header[13].message().parts_index(), 1);
953 if (!shared()) {
954 EXPECT_EQ(log_header[14].message().parts_index(), 0);
955 EXPECT_EQ(log_header[15].message().parts_index(), 1);
956 }
Austin Schuh64fab802020-09-09 22:47:47 -0700957 }
958
Austin Schuh8c399962020-12-25 21:51:45 -0800959 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700960 {
Austin Schuh391e3172020-09-01 22:48:18 -0700961 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800962 std::shared_ptr<const aos::Configuration> config =
963 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700964
Austin Schuh6f3babe2020-01-26 20:34:50 -0800965 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700966 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800967 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700968 UnorderedElementsAre(
969 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800970 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
971 21),
972 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
973 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700974 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800975 std::make_tuple("/test", "aos.examples.Ping", 2001)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800976 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800977 // Timestamps for pong
Austin Schuh2f8fd752020-09-01 22:38:28 -0700978 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800979 CountChannelsTimestamp(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700980 UnorderedElementsAre(
981 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800982 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800983 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800984
985 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800986 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800987 CountChannelsData(config, logfiles_[3]),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800988 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800989 << " : " << logfiles_[3];
990 EXPECT_THAT(CountChannelsData(config, logfiles_[4]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700991 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800992 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800993 << " : " << logfiles_[3];
Austin Schuh391e3172020-09-01 22:48:18 -0700994
Austin Schuh6f3babe2020-01-26 20:34:50 -0800995 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -0800996 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh25b46712021-01-03 00:04:38 -0800997 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -0800998 << " : " << logfiles_[3];
999 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001000 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001001 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001002
1003 // Timing reports and pongs.
Austin Schuh2f8fd752020-09-01 22:38:28 -07001004 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -08001005 CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001006 UnorderedElementsAre(
1007 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001008 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
1009 21),
1010 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1011 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001012 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001013 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001014 << " : " << logfiles_[5];
Austin Schuh61e973f2021-02-21 21:43:56 -08001015 // And ping timestamps.
Austin Schuh2f8fd752020-09-01 22:38:28 -07001016 EXPECT_THAT(
Austin Schuh8c399962020-12-25 21:51:45 -08001017 CountChannelsTimestamp(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001018 UnorderedElementsAre(
Austin Schuh61e973f2021-02-21 21:43:56 -08001019 std::make_tuple("/test", "aos.examples.Ping", 2001),
1020 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001021 << " : " << logfiles_[5];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001022
1023 // And then test that the remotely logged timestamp data files only have
1024 // timestamps in them.
Austin Schuh61e973f2021-02-21 21:43:56 -08001025 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1026 UnorderedElementsAre())
1027 << " : " << logfiles_[6];
1028 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
1029 UnorderedElementsAre())
1030 << " : " << logfiles_[7];
Austin Schuh25b46712021-01-03 00:04:38 -08001031 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1032 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001033 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001034 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1035 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001036 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001037
1038 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1039 UnorderedElementsAre(std::make_tuple(
1040 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1041 << " : " << logfiles_[6];
1042 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
1043 UnorderedElementsAre(std::make_tuple(
1044 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1045 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001046
Austin Schuh8c399962020-12-25 21:51:45 -08001047 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001048 UnorderedElementsAre(std::make_tuple(
Austin Schuh61e973f2021-02-21 21:43:56 -08001049 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001050 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001051 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001052 UnorderedElementsAre(std::make_tuple(
Austin Schuh61e973f2021-02-21 21:43:56 -08001053 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001054 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001055
Austin Schuh61e973f2021-02-21 21:43:56 -08001056 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh8c399962020-12-25 21:51:45 -08001057 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001058 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001059 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001060 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001061 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001062 << " : " << logfiles_[11];
Austin Schuh61e973f2021-02-21 21:43:56 -08001063 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1064 UnorderedElementsAre())
1065 << " : " << logfiles_[12];
1066 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1067 UnorderedElementsAre())
1068 << " : " << logfiles_[13];
1069 if (!shared()) {
1070 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1071 UnorderedElementsAre())
1072 << " : " << logfiles_[14];
1073 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1074 UnorderedElementsAre())
1075 << " : " << logfiles_[15];
1076 }
1077
1078 if (shared()) {
1079 EXPECT_THAT(
1080 CountChannelsTimestamp(config, logfiles_[10]),
1081 UnorderedElementsAre(
1082 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1083 std::make_tuple("/test", "aos.examples.Ping", 91)))
1084 << " : " << logfiles_[10];
1085 EXPECT_THAT(
1086 CountChannelsTimestamp(config, logfiles_[11]),
1087 UnorderedElementsAre(
1088 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1089 std::make_tuple("/test", "aos.examples.Ping", 1910)))
1090 << " : " << logfiles_[11];
1091 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1092 UnorderedElementsAre(std::make_tuple(
1093 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1094 << " : " << logfiles_[12];
1095 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1096 UnorderedElementsAre(std::make_tuple(
1097 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1098 << " : " << logfiles_[13];
1099 } else {
1100 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1101 UnorderedElementsAre(std::make_tuple(
1102 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1103 << " : " << logfiles_[10];
1104 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1105 UnorderedElementsAre(std::make_tuple(
1106 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1107 << " : " << logfiles_[11];
1108 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1109 UnorderedElementsAre(std::make_tuple(
1110 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1111 << " : " << logfiles_[12];
1112 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1113 UnorderedElementsAre(std::make_tuple(
1114 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1115 << " : " << logfiles_[13];
1116 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1117 UnorderedElementsAre(
1118 std::make_tuple("/test", "aos.examples.Ping", 91)))
1119 << " : " << logfiles_[14];
1120 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1121 UnorderedElementsAre(
1122 std::make_tuple("/test", "aos.examples.Ping", 1910)))
1123 << " : " << logfiles_[15];
1124 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001125 }
1126
Austin Schuh8c399962020-12-25 21:51:45 -08001127 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001128
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001129 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001130 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001131
1132 // This sends out the fetched messages and advances time to the start of the
1133 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001134 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001135
Austin Schuhac0771c2020-01-07 18:36:30 -08001136 const Node *pi1 =
1137 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001138 const Node *pi2 =
1139 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001140
Austin Schuh2f8fd752020-09-01 22:38:28 -07001141 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1142 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1143 LOG(INFO) << "now pi1 "
1144 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1145 LOG(INFO) << "now pi2 "
1146 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1147
Austin Schuh07676622021-01-21 18:59:17 -08001148 EXPECT_THAT(reader.LoggedNodes(),
1149 ::testing::ElementsAre(
1150 configuration::GetNode(reader.logged_configuration(), pi1),
1151 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001152
1153 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001154
Austin Schuh6f3babe2020-01-26 20:34:50 -08001155 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001156 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001157 std::unique_ptr<EventLoop> pi2_event_loop =
1158 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001159
Austin Schuh6f3babe2020-01-26 20:34:50 -08001160 int pi1_ping_count = 10;
1161 int pi2_ping_count = 10;
1162 int pi1_pong_count = 10;
1163 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001164
1165 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001166 pi1_event_loop->MakeWatcher(
1167 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001168 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001169 << pi1_event_loop->context().monotonic_remote_time << " -> "
1170 << pi1_event_loop->context().monotonic_event_time;
1171 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1172 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1173 pi1_ping_count * chrono::milliseconds(10) +
1174 monotonic_clock::epoch());
1175 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1176 pi1_ping_count * chrono::milliseconds(10) +
1177 realtime_clock::epoch());
1178 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1179 pi1_event_loop->context().monotonic_event_time);
1180 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1181 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001182
Austin Schuh6f3babe2020-01-26 20:34:50 -08001183 ++pi1_ping_count;
1184 });
1185 pi2_event_loop->MakeWatcher(
1186 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001187 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001188 << pi2_event_loop->context().monotonic_remote_time << " -> "
1189 << pi2_event_loop->context().monotonic_event_time;
1190 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1191
1192 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1193 pi2_ping_count * chrono::milliseconds(10) +
1194 monotonic_clock::epoch());
1195 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1196 pi2_ping_count * chrono::milliseconds(10) +
1197 realtime_clock::epoch());
1198 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1199 chrono::microseconds(150),
1200 pi2_event_loop->context().monotonic_event_time);
1201 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1202 chrono::microseconds(150),
1203 pi2_event_loop->context().realtime_event_time);
1204 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001205 });
1206
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001207 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001208 // Confirm that the ping and pong counts both match, and the value also
1209 // matches.
1210 pi1_event_loop->MakeWatcher(
1211 "/test", [&pi1_event_loop, &pi1_ping_count,
1212 &pi1_pong_count](const examples::Pong &pong) {
1213 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1214 << pi1_event_loop->context().monotonic_remote_time << " -> "
1215 << pi1_event_loop->context().monotonic_event_time;
1216
1217 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1218 pi1_pong_count + kQueueIndexOffset);
1219 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1220 chrono::microseconds(200) +
1221 pi1_pong_count * chrono::milliseconds(10) +
1222 monotonic_clock::epoch());
1223 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1224 chrono::microseconds(200) +
1225 pi1_pong_count * chrono::milliseconds(10) +
1226 realtime_clock::epoch());
1227
1228 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1229 chrono::microseconds(150),
1230 pi1_event_loop->context().monotonic_event_time);
1231 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1232 chrono::microseconds(150),
1233 pi1_event_loop->context().realtime_event_time);
1234
1235 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1236 ++pi1_pong_count;
1237 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1238 });
1239 pi2_event_loop->MakeWatcher(
1240 "/test", [&pi2_event_loop, &pi2_ping_count,
1241 &pi2_pong_count](const examples::Pong &pong) {
1242 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1243 << pi2_event_loop->context().monotonic_remote_time << " -> "
1244 << pi2_event_loop->context().monotonic_event_time;
1245
1246 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001247 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001248
1249 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1250 chrono::microseconds(200) +
1251 pi2_pong_count * chrono::milliseconds(10) +
1252 monotonic_clock::epoch());
1253 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1254 chrono::microseconds(200) +
1255 pi2_pong_count * chrono::milliseconds(10) +
1256 realtime_clock::epoch());
1257
1258 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1259 pi2_event_loop->context().monotonic_event_time);
1260 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1261 pi2_event_loop->context().realtime_event_time);
1262
1263 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1264 ++pi2_pong_count;
1265 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1266 });
1267
1268 log_reader_factory.Run();
1269 EXPECT_EQ(pi1_ping_count, 2010);
1270 EXPECT_EQ(pi2_ping_count, 2010);
1271 EXPECT_EQ(pi1_pong_count, 2010);
1272 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001273
1274 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001275}
1276
James Kuszmaul46d82582020-05-09 19:50:09 -07001277typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1278
1279// Test that if we feed the replay with a mismatched node list that we die on
1280// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001281TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001282 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001283 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001284 LoggerState pi1_logger = MakeLogger(pi1_);
1285 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001286
1287 event_loop_factory_.RunFor(chrono::milliseconds(95));
1288
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001289 StartLogger(&pi1_logger);
1290 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001291
James Kuszmaul46d82582020-05-09 19:50:09 -07001292 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1293 }
1294
1295 // Test that, if we add an additional node to the replay config that the
1296 // logger complains about the mismatch in number of nodes.
1297 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1298 configuration::MergeWithConfig(&config_.message(), R"({
1299 "nodes": [
1300 {
1301 "name": "extra-node"
1302 }
1303 ]
1304 }
1305 )");
1306
Austin Schuh287d43d2020-12-04 20:19:33 -08001307 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1308 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001309 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001310}
1311
Austin Schuhcde938c2020-02-02 17:30:07 -08001312// Tests that we can read log files where they don't start at the same monotonic
1313// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001314TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001315 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001316 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001317 LoggerState pi1_logger = MakeLogger(pi1_);
1318 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001319
1320 event_loop_factory_.RunFor(chrono::milliseconds(95));
1321
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001322 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001323
1324 event_loop_factory_.RunFor(chrono::milliseconds(200));
1325
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001326 StartLogger(&pi2_logger);
1327
Austin Schuhcde938c2020-02-02 17:30:07 -08001328 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1329 }
1330
Austin Schuh287d43d2020-12-04 20:19:33 -08001331 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001332
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001333 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001334 log_reader_factory.set_send_delay(chrono::microseconds(0));
1335
1336 // This sends out the fetched messages and advances time to the start of the
1337 // log file.
1338 reader.Register(&log_reader_factory);
1339
1340 const Node *pi1 =
1341 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1342 const Node *pi2 =
1343 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1344
Austin Schuh07676622021-01-21 18:59:17 -08001345 EXPECT_THAT(reader.LoggedNodes(),
1346 ::testing::ElementsAre(
1347 configuration::GetNode(reader.logged_configuration(), pi1),
1348 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001349
1350 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1351
1352 std::unique_ptr<EventLoop> pi1_event_loop =
1353 log_reader_factory.MakeEventLoop("test", pi1);
1354 std::unique_ptr<EventLoop> pi2_event_loop =
1355 log_reader_factory.MakeEventLoop("test", pi2);
1356
1357 int pi1_ping_count = 30;
1358 int pi2_ping_count = 30;
1359 int pi1_pong_count = 30;
1360 int pi2_pong_count = 30;
1361
1362 // Confirm that the ping value matches.
1363 pi1_event_loop->MakeWatcher(
1364 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1365 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1366 << pi1_event_loop->context().monotonic_remote_time << " -> "
1367 << pi1_event_loop->context().monotonic_event_time;
1368 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1369
1370 ++pi1_ping_count;
1371 });
1372 pi2_event_loop->MakeWatcher(
1373 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1374 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1375 << pi2_event_loop->context().monotonic_remote_time << " -> "
1376 << pi2_event_loop->context().monotonic_event_time;
1377 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1378
1379 ++pi2_ping_count;
1380 });
1381
1382 // Confirm that the ping and pong counts both match, and the value also
1383 // matches.
1384 pi1_event_loop->MakeWatcher(
1385 "/test", [&pi1_event_loop, &pi1_ping_count,
1386 &pi1_pong_count](const examples::Pong &pong) {
1387 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1388 << pi1_event_loop->context().monotonic_remote_time << " -> "
1389 << pi1_event_loop->context().monotonic_event_time;
1390
1391 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1392 ++pi1_pong_count;
1393 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1394 });
1395 pi2_event_loop->MakeWatcher(
1396 "/test", [&pi2_event_loop, &pi2_ping_count,
1397 &pi2_pong_count](const examples::Pong &pong) {
1398 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1399 << pi2_event_loop->context().monotonic_remote_time << " -> "
1400 << pi2_event_loop->context().monotonic_event_time;
1401
1402 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1403 ++pi2_pong_count;
1404 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1405 });
1406
1407 log_reader_factory.Run();
1408 EXPECT_EQ(pi1_ping_count, 2030);
1409 EXPECT_EQ(pi2_ping_count, 2030);
1410 EXPECT_EQ(pi1_pong_count, 2030);
1411 EXPECT_EQ(pi2_pong_count, 2030);
1412
1413 reader.Deregister();
1414}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001415
Austin Schuh8bd96322020-02-13 21:18:22 -08001416// Tests that we can read log files where the monotonic clocks drift and don't
1417// match correctly. While we are here, also test that different ending times
1418// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001419TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001420 // TODO(austin): Negate...
1421 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1422
1423 time_converter_.AddMonotonic({monotonic_clock::epoch(),
1424 monotonic_clock::epoch() + initial_pi2_offset});
1425 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1426 // skew to be 200 uS/s
1427 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1428 {chrono::milliseconds(95),
1429 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1430 // Run another 200 ms to have one logger start first.
1431 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1432 {chrono::milliseconds(200), chrono::milliseconds(200)});
1433 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1434 // go far enough to cause problems if this isn't accounted for.
1435 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1436 {chrono::milliseconds(20000),
1437 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1438 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1439 {chrono::milliseconds(40000),
1440 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1441 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1442 {chrono::milliseconds(400), chrono::milliseconds(400)});
1443
Austin Schuhcde938c2020-02-02 17:30:07 -08001444 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001445 LoggerState pi2_logger = MakeLogger(pi2_);
1446
Austin Schuh87dd3832021-01-01 23:07:31 -08001447 NodeEventLoopFactory *pi1 =
1448 event_loop_factory_.GetNodeEventLoopFactory(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001449 NodeEventLoopFactory *pi2 =
1450 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1451 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1452 << pi2->realtime_now() << " distributed "
1453 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001454
Austin Schuh8bd96322020-02-13 21:18:22 -08001455 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1456 << pi2->realtime_now() << " distributed "
1457 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001458
Austin Schuh87dd3832021-01-01 23:07:31 -08001459 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001460
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001461 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001462
Austin Schuh87dd3832021-01-01 23:07:31 -08001463 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001464
Austin Schuh8bd96322020-02-13 21:18:22 -08001465 {
1466 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001467 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001468
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001469 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001470 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001471
Austin Schuh87dd3832021-01-01 23:07:31 -08001472 // Make sure we slewed time far enough so that the difference is greater
1473 // than the network delay. This confirms that if we sort incorrectly, it
1474 // would show in the results.
1475 EXPECT_LT(
1476 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1477 -event_loop_factory_.send_delay() -
1478 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001479
Austin Schuh87dd3832021-01-01 23:07:31 -08001480 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001481
Austin Schuh87dd3832021-01-01 23:07:31 -08001482 // And now check that we went far enough the other way to make sure we
1483 // cover both problems.
1484 EXPECT_GT(
1485 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1486 event_loop_factory_.send_delay() +
1487 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001488 }
1489
1490 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001491 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001492 }
1493
Austin Schuh287d43d2020-12-04 20:19:33 -08001494 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001495
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001496 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001497 log_reader_factory.set_send_delay(chrono::microseconds(0));
1498
Austin Schuhcde938c2020-02-02 17:30:07 -08001499 const Node *pi1 =
1500 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1501 const Node *pi2 =
1502 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1503
Austin Schuh2f8fd752020-09-01 22:38:28 -07001504 // This sends out the fetched messages and advances time to the start of the
1505 // log file.
1506 reader.Register(&log_reader_factory);
1507
1508 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1509 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1510 LOG(INFO) << "now pi1 "
1511 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1512 LOG(INFO) << "now pi2 "
1513 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1514
Austin Schuhcde938c2020-02-02 17:30:07 -08001515 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001516 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1517 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001518 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1519 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001520 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1521 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001522 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1523
Austin Schuh07676622021-01-21 18:59:17 -08001524 EXPECT_THAT(reader.LoggedNodes(),
1525 ::testing::ElementsAre(
1526 configuration::GetNode(reader.logged_configuration(), pi1),
1527 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001528
1529 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1530
1531 std::unique_ptr<EventLoop> pi1_event_loop =
1532 log_reader_factory.MakeEventLoop("test", pi1);
1533 std::unique_ptr<EventLoop> pi2_event_loop =
1534 log_reader_factory.MakeEventLoop("test", pi2);
1535
1536 int pi1_ping_count = 30;
1537 int pi2_ping_count = 30;
1538 int pi1_pong_count = 30;
1539 int pi2_pong_count = 30;
1540
1541 // Confirm that the ping value matches.
1542 pi1_event_loop->MakeWatcher(
1543 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1544 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1545 << pi1_event_loop->context().monotonic_remote_time << " -> "
1546 << pi1_event_loop->context().monotonic_event_time;
1547 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1548
1549 ++pi1_ping_count;
1550 });
1551 pi2_event_loop->MakeWatcher(
1552 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1553 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1554 << pi2_event_loop->context().monotonic_remote_time << " -> "
1555 << pi2_event_loop->context().monotonic_event_time;
1556 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1557
1558 ++pi2_ping_count;
1559 });
1560
1561 // Confirm that the ping and pong counts both match, and the value also
1562 // matches.
1563 pi1_event_loop->MakeWatcher(
1564 "/test", [&pi1_event_loop, &pi1_ping_count,
1565 &pi1_pong_count](const examples::Pong &pong) {
1566 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1567 << pi1_event_loop->context().monotonic_remote_time << " -> "
1568 << pi1_event_loop->context().monotonic_event_time;
1569
1570 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1571 ++pi1_pong_count;
1572 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1573 });
1574 pi2_event_loop->MakeWatcher(
1575 "/test", [&pi2_event_loop, &pi2_ping_count,
1576 &pi2_pong_count](const examples::Pong &pong) {
1577 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1578 << pi2_event_loop->context().monotonic_remote_time << " -> "
1579 << pi2_event_loop->context().monotonic_event_time;
1580
1581 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1582 ++pi2_pong_count;
1583 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1584 });
1585
1586 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001587 EXPECT_EQ(pi1_ping_count, 6030);
1588 EXPECT_EQ(pi2_ping_count, 6030);
1589 EXPECT_EQ(pi1_pong_count, 6030);
1590 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001591
1592 reader.Deregister();
1593}
1594
Austin Schuh5212cad2020-09-09 23:12:09 -07001595// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001596TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001597 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001598 // Make a bunch of parts.
1599 {
1600 LoggerState pi1_logger = MakeLogger(pi1_);
1601 LoggerState pi2_logger = MakeLogger(pi2_);
1602
1603 event_loop_factory_.RunFor(chrono::milliseconds(95));
1604
1605 StartLogger(&pi1_logger);
1606 StartLogger(&pi2_logger);
1607
1608 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1609 }
1610
Austin Schuh11d43732020-09-21 17:28:30 -07001611 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001612 VerifyParts(sorted_parts);
1613}
Austin Schuh11d43732020-09-21 17:28:30 -07001614
Austin Schuh3bd4c402020-11-06 18:19:06 -08001615// Tests that we can sort a bunch of parts with an empty part. We should ignore
1616// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001617TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001618 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001619 // Make a bunch of parts.
1620 {
1621 LoggerState pi1_logger = MakeLogger(pi1_);
1622 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001623
Austin Schuh3bd4c402020-11-06 18:19:06 -08001624 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001625
Austin Schuh3bd4c402020-11-06 18:19:06 -08001626 StartLogger(&pi1_logger);
1627 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001628
Austin Schuh3bd4c402020-11-06 18:19:06 -08001629 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001630 }
1631
Austin Schuh3bd4c402020-11-06 18:19:06 -08001632 // TODO(austin): Should we flip out if the file can't open?
1633 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001634
Austin Schuh3bd4c402020-11-06 18:19:06 -08001635 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1636 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001637
Austin Schuh3bd4c402020-11-06 18:19:06 -08001638 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1639 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001640}
1641
Austin Schuh3bd4c402020-11-06 18:19:06 -08001642#ifdef LZMA
1643// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1644// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001645TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001646 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001647 // Make a bunch of parts.
1648 {
1649 LoggerState pi1_logger = MakeLogger(pi1_);
1650 LoggerState pi2_logger = MakeLogger(pi2_);
1651
1652 event_loop_factory_.RunFor(chrono::milliseconds(95));
1653
1654 StartLogger(&pi1_logger, "", true);
1655 StartLogger(&pi2_logger, "", true);
1656
1657 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1658 }
1659
1660 // TODO(austin): Should we flip out if the file can't open?
1661 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1662
1663 AddExtension(".xz");
1664
1665 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1666 logfiles_.emplace_back(kEmptyFile);
1667
1668 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1669 VerifyParts(sorted_parts, {kEmptyFile});
1670}
1671
1672// Tests that we can sort a bunch of parts with the end missing off a compressed
1673// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001674TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001675 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001676 // Make a bunch of parts.
1677 {
1678 LoggerState pi1_logger = MakeLogger(pi1_);
1679 LoggerState pi2_logger = MakeLogger(pi2_);
1680
1681 event_loop_factory_.RunFor(chrono::milliseconds(95));
1682
1683 StartLogger(&pi1_logger, "", true);
1684 StartLogger(&pi2_logger, "", true);
1685
1686 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1687 }
1688
1689 // Append everything with .xz.
1690 AddExtension(".xz");
1691
1692 // Strip off the end of one of the files. Pick one with a lot of data.
1693 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001694 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001695
1696 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001697 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001698 compressed_contents.substr(0, compressed_contents.size() - 100));
1699
1700 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1701 VerifyParts(sorted_parts);
1702}
1703#endif
1704
Austin Schuh01b4c352020-09-21 23:09:39 -07001705// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001706TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001707 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001708 {
1709 LoggerState pi1_logger = MakeLogger(pi1_);
1710 LoggerState pi2_logger = MakeLogger(pi2_);
1711
1712 event_loop_factory_.RunFor(chrono::milliseconds(95));
1713
1714 StartLogger(&pi1_logger);
1715 StartLogger(&pi2_logger);
1716
1717 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1718 }
1719
Austin Schuh287d43d2020-12-04 20:19:33 -08001720 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001721
1722 // Remap just on pi1.
1723 reader.RemapLoggedChannel<aos::timing::Report>(
1724 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1725
1726 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1727 log_reader_factory.set_send_delay(chrono::microseconds(0));
1728
1729 reader.Register(&log_reader_factory);
1730
1731 const Node *pi1 =
1732 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1733 const Node *pi2 =
1734 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1735
1736 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1737 // else should have moved.
1738 std::unique_ptr<EventLoop> pi1_event_loop =
1739 log_reader_factory.MakeEventLoop("test", pi1);
1740 pi1_event_loop->SkipTimingReport();
1741 std::unique_ptr<EventLoop> full_pi1_event_loop =
1742 log_reader_factory.MakeEventLoop("test", pi1);
1743 full_pi1_event_loop->SkipTimingReport();
1744 std::unique_ptr<EventLoop> pi2_event_loop =
1745 log_reader_factory.MakeEventLoop("test", pi2);
1746 pi2_event_loop->SkipTimingReport();
1747
1748 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1749 "/aos");
1750 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1751 full_pi1_event_loop.get(), "/pi1/aos");
1752 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1753 pi1_event_loop.get(), "/original/aos");
1754 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1755 full_pi1_event_loop.get(), "/original/pi1/aos");
1756 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1757 "/aos");
1758
1759 log_reader_factory.Run();
1760
1761 EXPECT_EQ(pi1_timing_report.count(), 0u);
1762 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1763 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1764 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1765 EXPECT_NE(pi2_timing_report.count(), 0u);
1766
1767 reader.Deregister();
1768}
1769
Austin Schuh006a9f52021-04-07 16:24:18 -07001770// Tests that we can remap a forwarded channel as well.
1771TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1772 time_converter_.StartEqual();
1773 {
1774 LoggerState pi1_logger = MakeLogger(pi1_);
1775 LoggerState pi2_logger = MakeLogger(pi2_);
1776
1777 event_loop_factory_.RunFor(chrono::milliseconds(95));
1778
1779 StartLogger(&pi1_logger);
1780 StartLogger(&pi2_logger);
1781
1782 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1783 }
1784
1785 LogReader reader(SortParts(logfiles_));
1786
1787 reader.RemapLoggedChannel<examples::Ping>("/test");
1788
1789 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1790 log_reader_factory.set_send_delay(chrono::microseconds(0));
1791
1792 reader.Register(&log_reader_factory);
1793
1794 const Node *pi1 =
1795 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1796 const Node *pi2 =
1797 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1798
1799 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1800 // else should have moved.
1801 std::unique_ptr<EventLoop> pi1_event_loop =
1802 log_reader_factory.MakeEventLoop("test", pi1);
1803 pi1_event_loop->SkipTimingReport();
1804 std::unique_ptr<EventLoop> full_pi1_event_loop =
1805 log_reader_factory.MakeEventLoop("test", pi1);
1806 full_pi1_event_loop->SkipTimingReport();
1807 std::unique_ptr<EventLoop> pi2_event_loop =
1808 log_reader_factory.MakeEventLoop("test", pi2);
1809 pi2_event_loop->SkipTimingReport();
1810
1811 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1812 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1813 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1814 "/original/test");
1815 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1816 "/original/test");
1817
1818 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1819 pi1_original_ping_timestamp;
1820 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1821 pi1_ping_timestamp;
1822 if (!shared()) {
1823 pi1_original_ping_timestamp =
1824 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1825 pi1_event_loop.get(),
1826 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1827 pi1_ping_timestamp =
1828 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1829 pi1_event_loop.get(),
1830 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1831 }
1832
1833 log_reader_factory.Run();
1834
1835 EXPECT_EQ(pi1_ping.count(), 0u);
1836 EXPECT_EQ(pi2_ping.count(), 0u);
1837 EXPECT_NE(pi1_original_ping.count(), 0u);
1838 EXPECT_NE(pi2_original_ping.count(), 0u);
1839 if (!shared()) {
1840 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1841 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1842 }
1843
1844 reader.Deregister();
1845}
1846
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001847// Tests that we properly recreate forwarded timestamps when replaying a log.
1848// This should be enough that we can then re-run the logger and get a valid log
1849// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001850TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001851 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001852 {
1853 LoggerState pi1_logger = MakeLogger(pi1_);
1854 LoggerState pi2_logger = MakeLogger(pi2_);
1855
1856 event_loop_factory_.RunFor(chrono::milliseconds(95));
1857
1858 StartLogger(&pi1_logger);
1859 StartLogger(&pi2_logger);
1860
1861 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1862 }
1863
Austin Schuh287d43d2020-12-04 20:19:33 -08001864 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001865
1866 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1867 log_reader_factory.set_send_delay(chrono::microseconds(0));
1868
1869 // This sends out the fetched messages and advances time to the start of the
1870 // log file.
1871 reader.Register(&log_reader_factory);
1872
1873 const Node *pi1 =
1874 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1875 const Node *pi2 =
1876 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1877
1878 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1879 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1880 LOG(INFO) << "now pi1 "
1881 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1882 LOG(INFO) << "now pi2 "
1883 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1884
Austin Schuh07676622021-01-21 18:59:17 -08001885 EXPECT_THAT(reader.LoggedNodes(),
1886 ::testing::ElementsAre(
1887 configuration::GetNode(reader.logged_configuration(), pi1),
1888 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001889
1890 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1891
1892 std::unique_ptr<EventLoop> pi1_event_loop =
1893 log_reader_factory.MakeEventLoop("test", pi1);
1894 std::unique_ptr<EventLoop> pi2_event_loop =
1895 log_reader_factory.MakeEventLoop("test", pi2);
1896
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001897 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1898 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1899 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1900 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1901
1902 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1903 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1904 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1905 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1906
1907 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1908 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1909 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1910 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1911
1912 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1913 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1914 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1915 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1916
1917 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1918 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1919 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1920 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1921
1922 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1923 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1924 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1925 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1926
Austin Schuh969cd602021-01-03 00:09:45 -08001927 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001928 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001929
Austin Schuh61e973f2021-02-21 21:43:56 -08001930 for (std::pair<int, std::string> channel :
1931 shared()
1932 ? std::vector<
1933 std::pair<int, std::string>>{{-1,
1934 "/aos/remote_timestamps/pi2"}}
1935 : std::vector<std::pair<int, std::string>>{
1936 {pi1_timestamp_channel,
1937 "/aos/remote_timestamps/pi2/pi1/aos/"
1938 "aos-message_bridge-Timestamp"},
1939 {ping_timestamp_channel,
1940 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1941 pi1_event_loop->MakeWatcher(
1942 channel.second,
1943 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1944 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1945 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1946 &ping_on_pi2_fetcher, network_delay, send_delay,
1947 channel_index = channel.first](const RemoteMessage &header) {
1948 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1949 chrono::nanoseconds(header.monotonic_sent_time()));
1950 const aos::realtime_clock::time_point header_realtime_sent_time(
1951 chrono::nanoseconds(header.realtime_sent_time()));
1952 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1953 chrono::nanoseconds(header.monotonic_remote_time()));
1954 const aos::realtime_clock::time_point header_realtime_remote_time(
1955 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001956
Austin Schuh61e973f2021-02-21 21:43:56 -08001957 if (channel_index != -1) {
1958 ASSERT_EQ(channel_index, header.channel_index());
1959 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001960
Austin Schuh61e973f2021-02-21 21:43:56 -08001961 const Context *pi1_context = nullptr;
1962 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001963
Austin Schuh61e973f2021-02-21 21:43:56 -08001964 if (header.channel_index() == pi1_timestamp_channel) {
1965 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1966 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1967 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1968 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1969 } else if (header.channel_index() == ping_timestamp_channel) {
1970 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1971 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1972 pi1_context = &ping_on_pi1_fetcher.context();
1973 pi2_context = &ping_on_pi2_fetcher.context();
1974 } else {
1975 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1976 << configuration::CleanedChannelToString(
1977 pi1_event_loop->configuration()->channels()->Get(
1978 header.channel_index()));
1979 }
Austin Schuh315b96b2020-12-11 21:21:12 -08001980
Austin Schuh61e973f2021-02-21 21:43:56 -08001981 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07001982 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1983 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001984
Austin Schuh61e973f2021-02-21 21:43:56 -08001985 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1986 EXPECT_EQ(pi2_context->remote_queue_index,
1987 header.remote_queue_index());
1988 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001989
Austin Schuh61e973f2021-02-21 21:43:56 -08001990 EXPECT_EQ(pi2_context->monotonic_event_time,
1991 header_monotonic_sent_time);
1992 EXPECT_EQ(pi2_context->realtime_event_time,
1993 header_realtime_sent_time);
1994 EXPECT_EQ(pi2_context->realtime_remote_time,
1995 header_realtime_remote_time);
1996 EXPECT_EQ(pi2_context->monotonic_remote_time,
1997 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08001998
Austin Schuh61e973f2021-02-21 21:43:56 -08001999 EXPECT_EQ(pi1_context->realtime_event_time,
2000 header_realtime_remote_time);
2001 EXPECT_EQ(pi1_context->monotonic_event_time,
2002 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002003
Austin Schuh61e973f2021-02-21 21:43:56 -08002004 // Time estimation isn't perfect, but we know the clocks were
2005 // identical when logged, so we know when this should have come back.
2006 // Confirm we got it when we expected.
2007 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2008 pi1_context->monotonic_event_time + 2 * network_delay +
2009 send_delay);
2010 });
2011 }
2012 for (std::pair<int, std::string> channel :
2013 shared()
2014 ? std::vector<
2015 std::pair<int, std::string>>{{-1,
2016 "/aos/remote_timestamps/pi1"}}
2017 : std::vector<std::pair<int, std::string>>{
2018 {pi2_timestamp_channel,
2019 "/aos/remote_timestamps/pi1/pi2/aos/"
2020 "aos-message_bridge-Timestamp"}}) {
2021 pi2_event_loop->MakeWatcher(
2022 channel.second,
2023 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2024 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2025 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2026 &pong_on_pi1_fetcher, network_delay, send_delay,
2027 channel_index = channel.first](const RemoteMessage &header) {
2028 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2029 chrono::nanoseconds(header.monotonic_sent_time()));
2030 const aos::realtime_clock::time_point header_realtime_sent_time(
2031 chrono::nanoseconds(header.realtime_sent_time()));
2032 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2033 chrono::nanoseconds(header.monotonic_remote_time()));
2034 const aos::realtime_clock::time_point header_realtime_remote_time(
2035 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002036
Austin Schuh61e973f2021-02-21 21:43:56 -08002037 if (channel_index != -1) {
2038 ASSERT_EQ(channel_index, header.channel_index());
2039 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002040
Austin Schuh61e973f2021-02-21 21:43:56 -08002041 const Context *pi2_context = nullptr;
2042 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002043
Austin Schuh61e973f2021-02-21 21:43:56 -08002044 if (header.channel_index() == pi2_timestamp_channel) {
2045 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2046 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2047 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2048 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2049 } else if (header.channel_index() == pong_timestamp_channel) {
2050 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2051 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2052 pi2_context = &pong_on_pi2_fetcher.context();
2053 pi1_context = &pong_on_pi1_fetcher.context();
2054 } else {
2055 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2056 << configuration::CleanedChannelToString(
2057 pi2_event_loop->configuration()->channels()->Get(
2058 header.channel_index()));
2059 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002060
Austin Schuh61e973f2021-02-21 21:43:56 -08002061 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002062 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2063 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002064
Austin Schuh61e973f2021-02-21 21:43:56 -08002065 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2066 EXPECT_EQ(pi1_context->remote_queue_index,
2067 header.remote_queue_index());
2068 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002069
Austin Schuh61e973f2021-02-21 21:43:56 -08002070 EXPECT_EQ(pi1_context->monotonic_event_time,
2071 header_monotonic_sent_time);
2072 EXPECT_EQ(pi1_context->realtime_event_time,
2073 header_realtime_sent_time);
2074 EXPECT_EQ(pi1_context->realtime_remote_time,
2075 header_realtime_remote_time);
2076 EXPECT_EQ(pi1_context->monotonic_remote_time,
2077 header_monotonic_remote_time);
2078
2079 EXPECT_EQ(pi2_context->realtime_event_time,
2080 header_realtime_remote_time);
2081 EXPECT_EQ(pi2_context->monotonic_event_time,
2082 header_monotonic_remote_time);
2083
2084 // Time estimation isn't perfect, but we know the clocks were
2085 // identical when logged, so we know when this should have come back.
2086 // Confirm we got it when we expected.
2087 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2088 pi2_context->monotonic_event_time + 2 * network_delay +
2089 send_delay);
2090 });
2091 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002092
2093 // And confirm we can re-create a log again, while checking the contents.
2094 {
2095 LoggerState pi1_logger = MakeLogger(
2096 configuration::GetNode(log_reader_factory.configuration(), pi1_),
2097 &log_reader_factory);
2098 LoggerState pi2_logger = MakeLogger(
2099 configuration::GetNode(log_reader_factory.configuration(), pi2_),
2100 &log_reader_factory);
2101
Austin Schuh25b46712021-01-03 00:04:38 -08002102 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2103 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002104
2105 log_reader_factory.Run();
2106 }
2107
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002108 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002109
2110 // And verify that we can run the LogReader over the relogged files without
2111 // hitting any fatal errors.
2112 {
2113 LogReader relogged_reader(SortParts(
2114 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2115 relogged_reader.Register();
2116
2117 relogged_reader.event_loop_factory()->Run();
2118 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002119}
2120
Austin Schuh315b96b2020-12-11 21:21:12 -08002121// Tests that we properly populate and extract the logger_start time by setting
2122// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002123TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002124 time_converter_.AddMonotonic(
2125 {monotonic_clock::epoch(),
2126 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002127 {
2128 LoggerState pi1_logger = MakeLogger(pi1_);
2129 LoggerState pi2_logger = MakeLogger(pi2_);
2130
Austin Schuh315b96b2020-12-11 21:21:12 -08002131 StartLogger(&pi1_logger);
2132 StartLogger(&pi2_logger);
2133
2134 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2135 }
2136
2137 for (const LogFile &log_file : SortParts(logfiles_)) {
2138 for (const LogParts &log_part : log_file.parts) {
2139 if (log_part.node == log_file.logger_node) {
2140 EXPECT_EQ(log_part.logger_monotonic_start_time,
2141 aos::monotonic_clock::min_time);
2142 EXPECT_EQ(log_part.logger_realtime_start_time,
2143 aos::realtime_clock::min_time);
2144 } else {
2145 const chrono::seconds offset = log_file.logger_node == "pi1"
2146 ? -chrono::seconds(1000)
2147 : chrono::seconds(1000);
2148 EXPECT_EQ(log_part.logger_monotonic_start_time,
2149 log_part.monotonic_start_time + offset);
2150 EXPECT_EQ(log_part.logger_realtime_start_time,
2151 log_file.realtime_start_time +
2152 (log_part.logger_monotonic_start_time -
2153 log_file.monotonic_start_time));
2154 }
2155 }
2156 }
2157}
2158
Austin Schuh6bb8a822021-03-31 23:04:39 -07002159// Test that renaming the base, renames the folder.
2160TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
2161 time_converter_.AddMonotonic(
2162 {monotonic_clock::epoch(),
2163 monotonic_clock::epoch() + chrono::seconds(1000)});
2164 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2165 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2166 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2167 LoggerState pi1_logger = MakeLogger(pi1_);
2168 LoggerState pi2_logger = MakeLogger(pi2_);
2169
2170 StartLogger(&pi1_logger);
2171 StartLogger(&pi2_logger);
2172
2173 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2174 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2175 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2176 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2177 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2178 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2179 for (auto &file : logfiles_) {
2180 struct stat s;
2181 EXPECT_EQ(0, stat(file.c_str(), &s));
2182 }
2183}
2184
2185// Test that renaming the file base dies.
2186TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2187 time_converter_.AddMonotonic(
2188 {monotonic_clock::epoch(),
2189 monotonic_clock::epoch() + chrono::seconds(1000)});
2190 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2191 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2192 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2193 LoggerState pi1_logger = MakeLogger(pi1_);
2194 StartLogger(&pi1_logger);
2195 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2196 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2197 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2198 "Rename of file base from");
2199}
2200
Austin Schuh8bd96322020-02-13 21:18:22 -08002201// TODO(austin): We can write a test which recreates a logfile and confirms that
2202// we get it back. That is the ultimate test.
2203
Austin Schuh315b96b2020-12-11 21:21:12 -08002204// Tests that we properly recreate forwarded timestamps when replaying a log.
2205// This should be enough that we can then re-run the logger and get a valid log
2206// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002207TEST_P(MultinodeLoggerDeathTest, RemoteReboot) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002208 time_converter_.StartEqual();
Austin Schuh315b96b2020-12-11 21:21:12 -08002209 std::string pi2_boot1;
2210 std::string pi2_boot2;
2211 {
2212 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2213 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002214 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002215 LoggerState pi1_logger = MakeLogger(pi1_);
2216
2217 event_loop_factory_.RunFor(chrono::milliseconds(95));
2218
2219 StartLogger(&pi1_logger);
2220
2221 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2222
2223 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
2224
2225 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2226 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002227 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002228
2229 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2230 }
2231
2232 // Confirm that we refuse to replay logs with missing boot uuids.
2233 EXPECT_DEATH(
2234 {
2235 LogReader reader(SortParts(pi1_reboot_logfiles_));
2236
2237 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2238 log_reader_factory.set_send_delay(chrono::microseconds(0));
2239
2240 // This sends out the fetched messages and advances time to the start of
2241 // the log file.
2242 reader.Register(&log_reader_factory);
2243 },
2244 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
2245 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
2246}
2247
Austin Schuhc9049732020-12-21 22:27:15 -08002248// Tests that we properly handle one direction of message_bridge being
2249// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002250TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002251 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002252 time_converter_.AddMonotonic(
2253 {monotonic_clock::epoch(),
2254 monotonic_clock::epoch() + chrono::seconds(1000)});
2255
2256 time_converter_.AddMonotonic(
2257 {chrono::milliseconds(10000),
2258 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002259 {
2260 LoggerState pi1_logger = MakeLogger(pi1_);
2261
2262 event_loop_factory_.RunFor(chrono::milliseconds(95));
2263
2264 StartLogger(&pi1_logger);
2265
2266 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2267 }
2268
2269 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2270 // to confirm the right thing happened.
2271 ConfirmReadable(pi1_single_direction_logfiles_);
2272}
2273
2274// Tests that we properly handle one direction of message_bridge being
2275// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002276TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002277 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002278 time_converter_.AddMonotonic(
2279 {monotonic_clock::epoch(),
2280 monotonic_clock::epoch() + chrono::seconds(500)});
2281
2282 time_converter_.AddMonotonic(
2283 {chrono::milliseconds(10000),
2284 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2285 {
2286 LoggerState pi1_logger = MakeLogger(pi1_);
2287
2288 event_loop_factory_.RunFor(chrono::milliseconds(95));
2289
2290 StartLogger(&pi1_logger);
2291
2292 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2293 }
2294
2295 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2296 // to confirm the right thing happened.
2297 ConfirmReadable(pi1_single_direction_logfiles_);
2298}
2299
2300// Tests that we properly handle a dead node. Do this by just disconnecting it
2301// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002302TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002303 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
2304 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
2305 time_converter_.AddMonotonic(
2306 {monotonic_clock::epoch(),
2307 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002308 {
2309 LoggerState pi1_logger = MakeLogger(pi1_);
2310
2311 event_loop_factory_.RunFor(chrono::milliseconds(95));
2312
2313 StartLogger(&pi1_logger);
2314
2315 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2316 }
2317
2318 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2319 // to confirm the right thing happened.
2320 ConfirmReadable(pi1_single_direction_logfiles_);
2321}
2322
Austin Schuhcdd90272021-03-15 12:46:16 -07002323constexpr std::string_view kCombinedConfigSha1(
Austin Schuhe61d4382021-03-31 21:33:02 -07002324 "0184681f8b83b5b9902a88ab12504c06b780907f6d156353bd958ebcf9389ef9");
Austin Schuhcdd90272021-03-15 12:46:16 -07002325constexpr std::string_view kSplitConfigSha1(
Austin Schuhe61d4382021-03-31 21:33:02 -07002326 "1020274679a8f8c15ea20a48e4a35dd59a435203e5f31a57e15355e5a6ee31f7");
Austin Schuhcdd90272021-03-15 12:46:16 -07002327
Austin Schuh61e973f2021-02-21 21:43:56 -08002328INSTANTIATE_TEST_CASE_P(
2329 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002330 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2331 kCombinedConfigSha1},
2332 Param{"multinode_pingpong_split_config.json", false,
2333 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002334
2335INSTANTIATE_TEST_CASE_P(
2336 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002337 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2338 kCombinedConfigSha1},
2339 Param{"multinode_pingpong_split_config.json", false,
2340 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002341
Austin Schuha04efed2021-01-24 18:04:20 -08002342// TODO(austin): Make a log file where the remote node has no start time.
2343
Austin Schuhe309d2a2019-11-29 13:25:21 -08002344} // namespace testing
2345} // namespace logger
2346} // namespace aos