blob: 5532caf81fbb64e7d752e891e460eb60d747a0e0 [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 Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuh25b46712021-01-03 00:04:38 -080037 "bc8c9c2e31589eae6f0e36d766f6a437643e861d9568b7483106841cf7504dea");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
171 logger_event_loop->OnRun(
172 [base_name1, base_name2, &logger_event_loop, &logger]() {
173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop->node()));
175 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
176 base_name2, logger_event_loop->node())),
177 "Already logging");
178 });
179 event_loop_factory_.RunFor(chrono::milliseconds(20000));
180 }
181}
182
183// Tests calling StopLogging twice.
184TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800185 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700186 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800187 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700188 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700189 const ::std::string logfile = base_name + ".part0.bfbs";
190 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800191 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700192 unlink(logfile.c_str());
193
194 LOG(INFO) << "Logging data to " << logfile;
195
196 {
197 std::unique_ptr<EventLoop> logger_event_loop =
198 event_loop_factory_.MakeEventLoop("logger");
199
200 event_loop_factory_.RunFor(chrono::milliseconds(95));
201
202 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800203 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700204 logger.set_polling_period(std::chrono::milliseconds(100));
205 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
206 logger.StartLogging(std::make_unique<LocalLogNamer>(
207 base_name, logger_event_loop->node()));
208 logger.StopLogging(aos::monotonic_clock::min_time);
209 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
210 "Not logging right now");
211 });
212 event_loop_factory_.RunFor(chrono::milliseconds(20000));
213 }
214}
215
216// Tests that we can startup twice.
217TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800218 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700219 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800220 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700221 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700222 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
223 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800224 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700225 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700226 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
227 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800228 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700229 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800230 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700231
232 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
233
234 {
235 std::unique_ptr<EventLoop> logger_event_loop =
236 event_loop_factory_.MakeEventLoop("logger");
237
238 event_loop_factory_.RunFor(chrono::milliseconds(95));
239
240 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800241 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700242 logger.set_polling_period(std::chrono::milliseconds(100));
243 logger.StartLogging(
244 std::make_unique<LocalLogNamer>(base_name1, logger_event_loop->node()));
245 event_loop_factory_.RunFor(chrono::milliseconds(10000));
246 logger.StopLogging(logger_event_loop->monotonic_now());
247 event_loop_factory_.RunFor(chrono::milliseconds(10000));
248 logger.StartLogging(
249 std::make_unique<LocalLogNamer>(base_name2, logger_event_loop->node()));
250 event_loop_factory_.RunFor(chrono::milliseconds(10000));
251 }
252
253 for (const auto &logfile :
254 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
255 SCOPED_TRACE(std::get<0>(logfile));
256 LogReader reader(std::get<0>(logfile));
257 reader.Register();
258
Austin Schuh07676622021-01-21 18:59:17 -0800259 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700260
261 std::unique_ptr<EventLoop> test_event_loop =
262 reader.event_loop_factory()->MakeEventLoop("log_reader");
263
264 int ping_count = std::get<1>(logfile);
265 int pong_count = std::get<1>(logfile);
266
267 // Confirm that the ping and pong counts both match, and the value also
268 // matches.
269 test_event_loop->MakeWatcher("/test",
270 [&ping_count](const examples::Ping &ping) {
271 EXPECT_EQ(ping.value(), ping_count + 1);
272 ++ping_count;
273 });
274 test_event_loop->MakeWatcher(
275 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
276 EXPECT_EQ(pong.value(), pong_count + 1);
277 ++pong_count;
278 EXPECT_EQ(ping_count, pong_count);
279 });
280
281 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
282 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
283 }
284}
285
Austin Schuhfa895892020-01-07 20:07:41 -0800286// Tests that we can read and write rotated log files.
287TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800288 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700289 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800290 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700291 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700292 const ::std::string logfile0 = base_name + ".part0.bfbs";
293 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800294 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800295 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800296 unlink(logfile0.c_str());
297 unlink(logfile1.c_str());
298
299 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
300
301 {
Austin Schuhfa895892020-01-07 20:07:41 -0800302 std::unique_ptr<EventLoop> logger_event_loop =
303 event_loop_factory_.MakeEventLoop("logger");
304
305 event_loop_factory_.RunFor(chrono::milliseconds(95));
306
Brian Silverman1f345222020-09-24 21:14:48 -0700307 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800308 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700309 logger.set_polling_period(std::chrono::milliseconds(100));
310 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800311 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700312 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800313 event_loop_factory_.RunFor(chrono::milliseconds(10000));
314 }
315
Austin Schuh64fab802020-09-09 22:47:47 -0700316 {
317 // Confirm that the UUIDs match for both the parts and the logger, and the
318 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800319 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700320 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800321 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700322 }
323
Brian Silvermanae7c0332020-09-30 16:58:23 -0700324 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
325 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700326 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
327 log_header[1].message().parts_uuid()->string_view());
328
329 EXPECT_EQ(log_header[0].message().parts_index(), 0);
330 EXPECT_EQ(log_header[1].message().parts_index(), 1);
331 }
332
Austin Schuhfa895892020-01-07 20:07:41 -0800333 // Even though it doesn't make any difference here, exercise the logic for
334 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800335 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800336
337 // Confirm that we can remap logged channels to point to new buses.
338 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
339
340 // This sends out the fetched messages and advances time to the start of the
341 // log file.
342 reader.Register();
343
Austin Schuh07676622021-01-21 18:59:17 -0800344 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800345
346 std::unique_ptr<EventLoop> test_event_loop =
347 reader.event_loop_factory()->MakeEventLoop("log_reader");
348
349 int ping_count = 10;
350 int pong_count = 10;
351
352 // Confirm that the ping value matches in the remapped channel location.
353 test_event_loop->MakeWatcher("/original/test",
354 [&ping_count](const examples::Ping &ping) {
355 EXPECT_EQ(ping.value(), ping_count + 1);
356 ++ping_count;
357 });
358 // Confirm that the ping and pong counts both match, and the value also
359 // matches.
360 test_event_loop->MakeWatcher(
361 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
362 EXPECT_EQ(pong.value(), pong_count + 1);
363 ++pong_count;
364 EXPECT_EQ(ping_count, pong_count);
365 });
366
367 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
368 EXPECT_EQ(ping_count, 2010);
369}
370
Austin Schuh4c4e0092019-12-22 16:18:03 -0800371// Tests that a large number of messages per second doesn't overwhelm writev.
372TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800373 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700374 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800375 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700376 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700377 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800378 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800379 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800380 unlink(logfile.c_str());
381
382 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700383 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800384
385 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800386 std::unique_ptr<EventLoop> logger_event_loop =
387 event_loop_factory_.MakeEventLoop("logger");
388
389 std::unique_ptr<EventLoop> ping_spammer_event_loop =
390 event_loop_factory_.MakeEventLoop("ping_spammer");
391 aos::Sender<examples::Ping> ping_sender =
392 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
393
394 aos::TimerHandler *timer_handler =
395 ping_spammer_event_loop->AddTimer([&ping_sender]() {
396 aos::Sender<examples::Ping>::Builder builder =
397 ping_sender.MakeBuilder();
398 examples::Ping::Builder ping_builder =
399 builder.MakeBuilder<examples::Ping>();
400 CHECK(builder.Send(ping_builder.Finish()));
401 });
402
403 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
404 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
405 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
406 chrono::microseconds(50));
407 });
408
Brian Silverman1f345222020-09-24 21:14:48 -0700409 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800410 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700411 logger.set_polling_period(std::chrono::milliseconds(100));
412 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800413
414 event_loop_factory_.RunFor(chrono::milliseconds(1000));
415 }
416}
417
Austin Schuh61e973f2021-02-21 21:43:56 -0800418// Parameters to run all the tests with.
419struct Param {
420 // The config file to use.
421 std::string config;
422 // If true, the RemoteMessage channel should be shared between all the remote
423 // channels. If false, there will be 1 RemoteMessage channel per remote
424 // channel.
425 bool shared;
426 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700427 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800428};
Austin Schuh315b96b2020-12-11 21:21:12 -0800429
Austin Schuh61e973f2021-02-21 21:43:56 -0800430class MultinodeLoggerTest : public ::testing::TestWithParam<struct Param> {
Austin Schuh15649d62019-12-28 16:36:38 -0800431 public:
432 MultinodeLoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -0700433 : config_(aos::configuration::ReadConfig(ArtifactPath(
434 absl::StrCat("aos/events/logging/", GetParam().config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800435 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800436 event_loop_factory_(&config_.message()),
Austin Schuhcde938c2020-02-02 17:30:07 -0800437 pi1_(
438 configuration::GetNode(event_loop_factory_.configuration(), "pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800439 pi1_index_(configuration::GetNodeIndex(
440 event_loop_factory_.configuration(), pi1_)),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700441 pi2_(
442 configuration::GetNode(event_loop_factory_.configuration(), "pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800443 pi2_index_(configuration::GetNodeIndex(
444 event_loop_factory_.configuration(), pi2_)),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800445 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800446 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
447 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800448 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800449 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800450 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
451 structured_logfiles_(StructureLogFiles()),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700452 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping", pi1_)),
453 ping_(ping_event_loop_.get()),
454 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong", pi2_)),
455 pong_(pong_event_loop_.get()) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800456 LOG(INFO) << "Config " << GetParam().config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800457 event_loop_factory_.SetTimeConverter(&time_converter_);
458
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700459 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700460 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700461 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800462 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700463 }
464
Austin Schuh268586b2021-03-31 22:24:39 -0700465 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800466 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800467 unlink(file.c_str());
468 }
469
Austin Schuh268586b2021-03-31 22:24:39 -0700470 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800471 unlink(file.c_str());
472 }
473
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700474 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
475 << " and " << logfiles_[2];
476 }
477
Austin Schuh61e973f2021-02-21 21:43:56 -0800478 bool shared() const { return GetParam().shared; }
479
480 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
481 std::string logfile_base2) {
482 std::vector<std::string> result;
483 result.emplace_back(
484 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
485 result.emplace_back(
486 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
487 result.emplace_back(logfile_base1 + "_pi1_data.part0.bfbs");
488 result.emplace_back(logfile_base1 +
489 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
490 result.emplace_back(logfile_base1 +
491 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
492 result.emplace_back(logfile_base2 + "_pi2_data.part0.bfbs");
493 result.emplace_back(
494 logfile_base2 +
495 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
496 result.emplace_back(
497 logfile_base2 +
498 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
499 result.emplace_back(
500 logfile_base1 +
501 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
502 result.emplace_back(
503 logfile_base1 +
504 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
505 if (shared()) {
506 result.emplace_back(logfile_base1 +
507 "_timestamps/pi1/aos/remote_timestamps/pi2/"
508 "aos.message_bridge.RemoteMessage.part0.bfbs");
509 result.emplace_back(logfile_base1 +
510 "_timestamps/pi1/aos/remote_timestamps/pi2/"
511 "aos.message_bridge.RemoteMessage.part1.bfbs");
512 result.emplace_back(logfile_base2 +
513 "_timestamps/pi2/aos/remote_timestamps/pi1/"
514 "aos.message_bridge.RemoteMessage.part0.bfbs");
515 result.emplace_back(logfile_base2 +
516 "_timestamps/pi2/aos/remote_timestamps/pi1/"
517 "aos.message_bridge.RemoteMessage.part1.bfbs");
518 } else {
519 result.emplace_back(logfile_base1 +
520 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
521 "aos-message_bridge-Timestamp/"
522 "aos.message_bridge.RemoteMessage.part0.bfbs");
523 result.emplace_back(logfile_base1 +
524 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
525 "aos-message_bridge-Timestamp/"
526 "aos.message_bridge.RemoteMessage.part1.bfbs");
527 result.emplace_back(logfile_base2 +
528 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
529 "aos-message_bridge-Timestamp/"
530 "aos.message_bridge.RemoteMessage.part0.bfbs");
531 result.emplace_back(logfile_base2 +
532 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
533 "aos-message_bridge-Timestamp/"
534 "aos.message_bridge.RemoteMessage.part1.bfbs");
535 result.emplace_back(logfile_base1 +
536 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
537 "aos-examples-Ping/"
538 "aos.message_bridge.RemoteMessage.part0.bfbs");
539 result.emplace_back(logfile_base1 +
540 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
541 "aos-examples-Ping/"
542 "aos.message_bridge.RemoteMessage.part1.bfbs");
543 }
544
545 return result;
546 }
547
548 std::vector<std::string> MakePi1RebootLogfiles() {
549 std::vector<std::string> result;
550 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
551 result.emplace_back(logfile_base1_ +
552 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
553 result.emplace_back(logfile_base1_ +
554 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
555 result.emplace_back(logfile_base1_ +
556 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
557 result.emplace_back(
558 logfile_base1_ +
559 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
560 result.emplace_back(
561 logfile_base1_ +
562 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
563 result.emplace_back(
564 logfile_base1_ +
565 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
566 result.emplace_back(
567 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
568 if (shared()) {
569 result.emplace_back(logfile_base1_ +
570 "_timestamps/pi1/aos/remote_timestamps/pi2/"
571 "aos.message_bridge.RemoteMessage.part0.bfbs");
572 result.emplace_back(logfile_base1_ +
573 "_timestamps/pi1/aos/remote_timestamps/pi2/"
574 "aos.message_bridge.RemoteMessage.part1.bfbs");
575 result.emplace_back(logfile_base1_ +
576 "_timestamps/pi1/aos/remote_timestamps/pi2/"
577 "aos.message_bridge.RemoteMessage.part2.bfbs");
578 } else {
579 result.emplace_back(logfile_base1_ +
580 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
581 "aos-message_bridge-Timestamp/"
582 "aos.message_bridge.RemoteMessage.part0.bfbs");
583 result.emplace_back(logfile_base1_ +
584 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
585 "aos-message_bridge-Timestamp/"
586 "aos.message_bridge.RemoteMessage.part1.bfbs");
587 result.emplace_back(logfile_base1_ +
588 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
589 "aos-message_bridge-Timestamp/"
590 "aos.message_bridge.RemoteMessage.part2.bfbs");
591
592 result.emplace_back(logfile_base1_ +
593 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
594 "aos-examples-Ping/"
595 "aos.message_bridge.RemoteMessage.part0.bfbs");
596 result.emplace_back(logfile_base1_ +
597 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
598 "aos-examples-Ping/"
599 "aos.message_bridge.RemoteMessage.part1.bfbs");
600 result.emplace_back(logfile_base1_ +
601 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
602 "aos-examples-Ping/"
603 "aos.message_bridge.RemoteMessage.part2.bfbs");
604 }
605 return result;
606 }
607
608 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
609 std::vector<std::string> result;
610 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
611 result.emplace_back(logfile_base1_ +
612 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
613 result.emplace_back(
614 logfile_base1_ +
615 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
616 result.emplace_back(
617 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
618
619 if (shared()) {
620 result.emplace_back(logfile_base1_ +
621 "_timestamps/pi1/aos/remote_timestamps/pi2/"
622 "aos.message_bridge.RemoteMessage.part0.bfbs");
623 } else {
624 result.emplace_back(logfile_base1_ +
625 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
626 "aos-message_bridge-Timestamp/"
627 "aos.message_bridge.RemoteMessage.part0.bfbs");
628 result.emplace_back(logfile_base1_ +
629 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
630 "aos-examples-Ping/"
631 "aos.message_bridge.RemoteMessage.part0.bfbs");
632 }
633 return result;
634 }
635
636 std::vector<std::vector<std::string>> StructureLogFiles() {
637 std::vector<std::vector<std::string>> result{
638 std::vector<std::string>{logfiles_[2]},
639 std::vector<std::string>{logfiles_[3], logfiles_[4]},
640 std::vector<std::string>{logfiles_[5]},
641 std::vector<std::string>{logfiles_[6], logfiles_[7]},
642 std::vector<std::string>{logfiles_[8], logfiles_[9]},
643 std::vector<std::string>{logfiles_[10], logfiles_[11]},
644 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
645
646 if (!shared()) {
647 result.emplace_back(
648 std::vector<std::string>{logfiles_[14], logfiles_[15]});
649 }
650
651 return result;
652 }
653
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700654 struct LoggerState {
655 std::unique_ptr<EventLoop> event_loop;
656 std::unique_ptr<Logger> logger;
657 };
658
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700659 LoggerState MakeLogger(const Node *node,
660 SimulatedEventLoopFactory *factory = nullptr) {
661 if (factory == nullptr) {
662 factory = &event_loop_factory_;
663 }
664 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700665 }
666
Austin Schuh3bd4c402020-11-06 18:19:06 -0800667 void StartLogger(LoggerState *logger, std::string logfile_base = "",
668 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700669 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800670 if (logger->event_loop->node()->name()->string_view() == "pi1") {
671 logfile_base = logfile_base1_;
672 } else {
673 logfile_base = logfile_base2_;
674 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700675 }
676
Brian Silverman1f345222020-09-24 21:14:48 -0700677 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
678 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800679 logger->logger->set_name(absl::StrCat(
680 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800681 logger->event_loop->OnRun([logger, logfile_base, compress]() {
682 std::unique_ptr<MultiNodeLogNamer> namer =
683 std::make_unique<MultiNodeLogNamer>(
684 logfile_base, logger->event_loop->configuration(),
685 logger->event_loop->node());
686 if (compress) {
687#ifdef LZMA
688 namer->set_extension(".xz");
689 namer->set_encoder_factory(
690 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
691#else
692 LOG(FATAL) << "Compression unsupported";
693#endif
694 }
695
696 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700697 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700698 }
Austin Schuh15649d62019-12-28 16:36:38 -0800699
Austin Schuh3bd4c402020-11-06 18:19:06 -0800700 void VerifyParts(const std::vector<LogFile> &sorted_parts,
701 const std::vector<std::string> &corrupted_parts = {}) {
702 EXPECT_EQ(sorted_parts.size(), 2u);
703
704 // Count up the number of UUIDs and make sure they are what we expect as a
705 // sanity check.
706 std::set<std::string> log_event_uuids;
707 std::set<std::string> parts_uuids;
708 std::set<std::string> both_uuids;
709
710 size_t missing_rt_count = 0;
711
712 std::vector<std::string> logger_nodes;
713 for (const LogFile &log_file : sorted_parts) {
714 EXPECT_FALSE(log_file.log_event_uuid.empty());
715 log_event_uuids.insert(log_file.log_event_uuid);
716 logger_nodes.emplace_back(log_file.logger_node);
717 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800718 EXPECT_TRUE(log_file.config);
719 EXPECT_EQ(log_file.name,
720 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800721
722 for (const LogParts &part : log_file.parts) {
723 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
724 << ": " << part;
725 missing_rt_count +=
726 part.realtime_start_time == aos::realtime_clock::min_time;
727
728 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
729 log_event_uuids.end());
730 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800731 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800732 parts_uuids.insert(part.parts_uuid);
733 both_uuids.insert(part.parts_uuid);
734 }
735 }
736
Austin Schuh61e973f2021-02-21 21:43:56 -0800737 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
738 // start time on remote nodes because we don't know it and would be
739 // guessing. And the log reader can actually do a better job. The number
740 // depends on if we have the remote timestamps split across 2 files, or just
741 // across 1, depending on if we are using a split or combined timestamp
742 // channel config.
743 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800744
745 EXPECT_EQ(log_event_uuids.size(), 2u);
746 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
747 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
748
749 // Test that each list of parts is in order. Don't worry about the ordering
750 // between part file lists though.
751 // (inner vectors all need to be in order, but outer one doesn't matter).
752 EXPECT_THAT(ToLogReaderVector(sorted_parts),
753 ::testing::UnorderedElementsAreArray(structured_logfiles_));
754
755 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
756
757 EXPECT_NE(sorted_parts[0].realtime_start_time,
758 aos::realtime_clock::min_time);
759 EXPECT_NE(sorted_parts[1].realtime_start_time,
760 aos::realtime_clock::min_time);
761
762 EXPECT_NE(sorted_parts[0].monotonic_start_time,
763 aos::monotonic_clock::min_time);
764 EXPECT_NE(sorted_parts[1].monotonic_start_time,
765 aos::monotonic_clock::min_time);
766
767 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
768 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
769 }
770
Austin Schuhc9049732020-12-21 22:27:15 -0800771 void ConfirmReadable(const std::vector<std::string> &files) {
772 LogReader reader(SortParts(files));
773
774 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
775 reader.Register(&log_reader_factory);
776
777 log_reader_factory.Run();
778
779 reader.Deregister();
780 }
781
Austin Schuh3bd4c402020-11-06 18:19:06 -0800782 void AddExtension(std::string_view extension) {
783 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
784 [extension](const std::string &in) {
785 return absl::StrCat(in, extension);
786 });
787
788 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
789 structured_logfiles_.begin(),
790 [extension](std::vector<std::string> in) {
791 std::transform(in.begin(), in.end(), in.begin(),
792 [extension](const std::string &in_str) {
793 return absl::StrCat(in_str, extension);
794 });
795 return in;
796 });
797 }
798
Austin Schuh15649d62019-12-28 16:36:38 -0800799 // Config and factory.
800 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800801 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800802 SimulatedEventLoopFactory event_loop_factory_;
803
Austin Schuh87dd3832021-01-01 23:07:31 -0800804 const Node *const pi1_;
805 const size_t pi1_index_;
806 const Node *const pi2_;
807 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700808
809 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800810 std::string logfile_base1_;
811 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800812 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700813 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800814 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700815
816 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700817
818 std::unique_ptr<EventLoop> ping_event_loop_;
819 Ping ping_;
820 std::unique_ptr<EventLoop> pong_event_loop_;
821 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800822};
823
Austin Schuh391e3172020-09-01 22:48:18 -0700824// Counts the number of messages on a channel. Returns (channel name, channel
825// type, count) for every message matching matcher()
826std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800827 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800828 std::function<bool(const MessageHeader *)> matcher) {
829 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800830 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800831
Austin Schuh6f3babe2020-01-26 20:34:50 -0800832 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800833 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800834 message_reader.ReadMessage();
835 if (!msg) {
836 break;
837 }
838
839 if (matcher(&msg.value().message())) {
840 counts[msg.value().message().channel_index()]++;
841 }
842 }
843
Austin Schuh391e3172020-09-01 22:48:18 -0700844 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800845 int channel = 0;
846 for (size_t i = 0; i < counts.size(); ++i) {
847 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800848 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700849 result.push_back(std::make_tuple(channel->name()->str(),
850 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800851 }
852 ++channel;
853 }
854
855 return result;
856}
857
858// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700859std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800860 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700861 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800862 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800863 if (msg->has_data()) {
864 CHECK(!msg->has_monotonic_remote_time());
865 CHECK(!msg->has_realtime_remote_time());
866 CHECK(!msg->has_remote_queue_index());
867 return true;
868 }
869 return false;
870 });
871}
872
873// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700874std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800875 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800876 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800877 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800878 if (!msg->has_data()) {
879 CHECK(msg->has_monotonic_remote_time());
880 CHECK(msg->has_realtime_remote_time());
881 CHECK(msg->has_remote_queue_index());
882 return true;
883 }
884 return false;
885 });
886}
887
Austin Schuhcde938c2020-02-02 17:30:07 -0800888// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800889TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800890 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800891 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700892 LoggerState pi1_logger = MakeLogger(pi1_);
893 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800894
895 event_loop_factory_.RunFor(chrono::milliseconds(95));
896
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700897 StartLogger(&pi1_logger);
898 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800899
Austin Schuh15649d62019-12-28 16:36:38 -0800900 event_loop_factory_.RunFor(chrono::milliseconds(20000));
901 }
902
Austin Schuh6f3babe2020-01-26 20:34:50 -0800903 {
Austin Schuh64fab802020-09-09 22:47:47 -0700904 std::set<std::string> logfile_uuids;
905 std::set<std::string> parts_uuids;
906 // Confirm that we have the expected number of UUIDs for both the logfile
907 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800908 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700909 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800910 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800911 if (!log_header.back().message().has_configuration()) {
912 logfile_uuids.insert(
913 log_header.back().message().log_event_uuid()->str());
914 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
915 }
Austin Schuh64fab802020-09-09 22:47:47 -0700916 }
Austin Schuh15649d62019-12-28 16:36:38 -0800917
Austin Schuh64fab802020-09-09 22:47:47 -0700918 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800919 if (shared()) {
920 EXPECT_EQ(parts_uuids.size(), 7u);
921 } else {
922 EXPECT_EQ(parts_uuids.size(), 8u);
923 }
Austin Schuh64fab802020-09-09 22:47:47 -0700924
925 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800926 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700927 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi2");
928 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
929 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
930 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi1");
931 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800932 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
933 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
Austin Schuh64fab802020-09-09 22:47:47 -0700934 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
935 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800936 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi1");
937 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi1");
938 if (!shared()) {
939 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
940 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
941 }
Austin Schuh64fab802020-09-09 22:47:47 -0700942
943 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800944 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuh64fab802020-09-09 22:47:47 -0700945 EXPECT_EQ(log_header[3].message().parts_index(), 0);
Austin Schuh61e973f2021-02-21 21:43:56 -0800946 EXPECT_EQ(log_header[4].message().parts_index(), 1);
947 EXPECT_EQ(log_header[5].message().parts_index(), 0);
Austin Schuh64fab802020-09-09 22:47:47 -0700948 EXPECT_EQ(log_header[6].message().parts_index(), 0);
949 EXPECT_EQ(log_header[7].message().parts_index(), 1);
950 EXPECT_EQ(log_header[8].message().parts_index(), 0);
951 EXPECT_EQ(log_header[9].message().parts_index(), 1);
952 EXPECT_EQ(log_header[10].message().parts_index(), 0);
953 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800954 EXPECT_EQ(log_header[12].message().parts_index(), 0);
955 EXPECT_EQ(log_header[13].message().parts_index(), 1);
956 if (!shared()) {
957 EXPECT_EQ(log_header[14].message().parts_index(), 0);
958 EXPECT_EQ(log_header[15].message().parts_index(), 1);
959 }
Austin Schuh64fab802020-09-09 22:47:47 -0700960 }
961
Austin Schuh8c399962020-12-25 21:51:45 -0800962 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700963 {
Austin Schuh391e3172020-09-01 22:48:18 -0700964 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800965 std::shared_ptr<const aos::Configuration> config =
966 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700967
Austin Schuh6f3babe2020-01-26 20:34:50 -0800968 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700969 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800970 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700971 UnorderedElementsAre(
972 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800973 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
974 21),
975 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
976 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700977 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800978 std::make_tuple("/test", "aos.examples.Ping", 2001)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800979 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800980 // Timestamps for pong
Austin Schuh2f8fd752020-09-01 22:38:28 -0700981 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800982 CountChannelsTimestamp(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700983 UnorderedElementsAre(
984 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800985 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800986 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800987
988 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800989 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800990 CountChannelsData(config, logfiles_[3]),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800991 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800992 << " : " << logfiles_[3];
993 EXPECT_THAT(CountChannelsData(config, logfiles_[4]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700994 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -0800995 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800996 << " : " << logfiles_[3];
Austin Schuh391e3172020-09-01 22:48:18 -0700997
Austin Schuh6f3babe2020-01-26 20:34:50 -0800998 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -0800999 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh25b46712021-01-03 00:04:38 -08001000 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001001 << " : " << logfiles_[3];
1002 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001003 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001004 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001005
1006 // Timing reports and pongs.
Austin Schuh2f8fd752020-09-01 22:38:28 -07001007 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -08001008 CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001009 UnorderedElementsAre(
1010 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001011 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
1012 21),
1013 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1014 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001015 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001016 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001017 << " : " << logfiles_[5];
Austin Schuh61e973f2021-02-21 21:43:56 -08001018 // And ping timestamps.
Austin Schuh2f8fd752020-09-01 22:38:28 -07001019 EXPECT_THAT(
Austin Schuh8c399962020-12-25 21:51:45 -08001020 CountChannelsTimestamp(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001021 UnorderedElementsAre(
Austin Schuh61e973f2021-02-21 21:43:56 -08001022 std::make_tuple("/test", "aos.examples.Ping", 2001),
1023 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001024 << " : " << logfiles_[5];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001025
1026 // And then test that the remotely logged timestamp data files only have
1027 // timestamps in them.
Austin Schuh61e973f2021-02-21 21:43:56 -08001028 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1029 UnorderedElementsAre())
1030 << " : " << logfiles_[6];
1031 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
1032 UnorderedElementsAre())
1033 << " : " << logfiles_[7];
Austin Schuh25b46712021-01-03 00:04:38 -08001034 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1035 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001036 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001037 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1038 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001039 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001040
1041 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1042 UnorderedElementsAre(std::make_tuple(
1043 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1044 << " : " << logfiles_[6];
1045 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
1046 UnorderedElementsAre(std::make_tuple(
1047 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1048 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001049
Austin Schuh8c399962020-12-25 21:51:45 -08001050 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001051 UnorderedElementsAre(std::make_tuple(
Austin Schuh61e973f2021-02-21 21:43:56 -08001052 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001053 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001054 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001055 UnorderedElementsAre(std::make_tuple(
Austin Schuh61e973f2021-02-21 21:43:56 -08001056 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001057 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001058
Austin Schuh61e973f2021-02-21 21:43:56 -08001059 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh8c399962020-12-25 21:51:45 -08001060 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001061 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001062 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001063 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001064 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001065 << " : " << logfiles_[11];
Austin Schuh61e973f2021-02-21 21:43:56 -08001066 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1067 UnorderedElementsAre())
1068 << " : " << logfiles_[12];
1069 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1070 UnorderedElementsAre())
1071 << " : " << logfiles_[13];
1072 if (!shared()) {
1073 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1074 UnorderedElementsAre())
1075 << " : " << logfiles_[14];
1076 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1077 UnorderedElementsAre())
1078 << " : " << logfiles_[15];
1079 }
1080
1081 if (shared()) {
1082 EXPECT_THAT(
1083 CountChannelsTimestamp(config, logfiles_[10]),
1084 UnorderedElementsAre(
1085 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1086 std::make_tuple("/test", "aos.examples.Ping", 91)))
1087 << " : " << logfiles_[10];
1088 EXPECT_THAT(
1089 CountChannelsTimestamp(config, logfiles_[11]),
1090 UnorderedElementsAre(
1091 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1092 std::make_tuple("/test", "aos.examples.Ping", 1910)))
1093 << " : " << logfiles_[11];
1094 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1095 UnorderedElementsAre(std::make_tuple(
1096 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1097 << " : " << logfiles_[12];
1098 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1099 UnorderedElementsAre(std::make_tuple(
1100 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1101 << " : " << logfiles_[13];
1102 } else {
1103 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1104 UnorderedElementsAre(std::make_tuple(
1105 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1106 << " : " << logfiles_[10];
1107 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1108 UnorderedElementsAre(std::make_tuple(
1109 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1110 << " : " << logfiles_[11];
1111 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1112 UnorderedElementsAre(std::make_tuple(
1113 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1114 << " : " << logfiles_[12];
1115 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1116 UnorderedElementsAre(std::make_tuple(
1117 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1118 << " : " << logfiles_[13];
1119 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1120 UnorderedElementsAre(
1121 std::make_tuple("/test", "aos.examples.Ping", 91)))
1122 << " : " << logfiles_[14];
1123 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1124 UnorderedElementsAre(
1125 std::make_tuple("/test", "aos.examples.Ping", 1910)))
1126 << " : " << logfiles_[15];
1127 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001128 }
1129
Austin Schuh8c399962020-12-25 21:51:45 -08001130 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001131
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001132 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001133 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001134
1135 // This sends out the fetched messages and advances time to the start of the
1136 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001137 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001138
Austin Schuhac0771c2020-01-07 18:36:30 -08001139 const Node *pi1 =
1140 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001141 const Node *pi2 =
1142 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001143
Austin Schuh2f8fd752020-09-01 22:38:28 -07001144 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1145 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1146 LOG(INFO) << "now pi1 "
1147 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1148 LOG(INFO) << "now pi2 "
1149 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1150
Austin Schuh07676622021-01-21 18:59:17 -08001151 EXPECT_THAT(reader.LoggedNodes(),
1152 ::testing::ElementsAre(
1153 configuration::GetNode(reader.logged_configuration(), pi1),
1154 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001155
1156 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001157
Austin Schuh6f3babe2020-01-26 20:34:50 -08001158 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001159 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001160 std::unique_ptr<EventLoop> pi2_event_loop =
1161 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001162
Austin Schuh6f3babe2020-01-26 20:34:50 -08001163 int pi1_ping_count = 10;
1164 int pi2_ping_count = 10;
1165 int pi1_pong_count = 10;
1166 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001167
1168 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001169 pi1_event_loop->MakeWatcher(
1170 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001171 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001172 << pi1_event_loop->context().monotonic_remote_time << " -> "
1173 << pi1_event_loop->context().monotonic_event_time;
1174 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1175 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1176 pi1_ping_count * chrono::milliseconds(10) +
1177 monotonic_clock::epoch());
1178 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1179 pi1_ping_count * chrono::milliseconds(10) +
1180 realtime_clock::epoch());
1181 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1182 pi1_event_loop->context().monotonic_event_time);
1183 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1184 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001185
Austin Schuh6f3babe2020-01-26 20:34:50 -08001186 ++pi1_ping_count;
1187 });
1188 pi2_event_loop->MakeWatcher(
1189 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001190 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001191 << pi2_event_loop->context().monotonic_remote_time << " -> "
1192 << pi2_event_loop->context().monotonic_event_time;
1193 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1194
1195 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1196 pi2_ping_count * chrono::milliseconds(10) +
1197 monotonic_clock::epoch());
1198 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1199 pi2_ping_count * chrono::milliseconds(10) +
1200 realtime_clock::epoch());
1201 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1202 chrono::microseconds(150),
1203 pi2_event_loop->context().monotonic_event_time);
1204 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1205 chrono::microseconds(150),
1206 pi2_event_loop->context().realtime_event_time);
1207 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001208 });
1209
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001210 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001211 // Confirm that the ping and pong counts both match, and the value also
1212 // matches.
1213 pi1_event_loop->MakeWatcher(
1214 "/test", [&pi1_event_loop, &pi1_ping_count,
1215 &pi1_pong_count](const examples::Pong &pong) {
1216 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1217 << pi1_event_loop->context().monotonic_remote_time << " -> "
1218 << pi1_event_loop->context().monotonic_event_time;
1219
1220 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1221 pi1_pong_count + kQueueIndexOffset);
1222 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1223 chrono::microseconds(200) +
1224 pi1_pong_count * chrono::milliseconds(10) +
1225 monotonic_clock::epoch());
1226 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1227 chrono::microseconds(200) +
1228 pi1_pong_count * chrono::milliseconds(10) +
1229 realtime_clock::epoch());
1230
1231 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1232 chrono::microseconds(150),
1233 pi1_event_loop->context().monotonic_event_time);
1234 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1235 chrono::microseconds(150),
1236 pi1_event_loop->context().realtime_event_time);
1237
1238 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1239 ++pi1_pong_count;
1240 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1241 });
1242 pi2_event_loop->MakeWatcher(
1243 "/test", [&pi2_event_loop, &pi2_ping_count,
1244 &pi2_pong_count](const examples::Pong &pong) {
1245 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1246 << pi2_event_loop->context().monotonic_remote_time << " -> "
1247 << pi2_event_loop->context().monotonic_event_time;
1248
1249 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001250 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001251
1252 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1253 chrono::microseconds(200) +
1254 pi2_pong_count * chrono::milliseconds(10) +
1255 monotonic_clock::epoch());
1256 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1257 chrono::microseconds(200) +
1258 pi2_pong_count * chrono::milliseconds(10) +
1259 realtime_clock::epoch());
1260
1261 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1262 pi2_event_loop->context().monotonic_event_time);
1263 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1264 pi2_event_loop->context().realtime_event_time);
1265
1266 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1267 ++pi2_pong_count;
1268 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1269 });
1270
1271 log_reader_factory.Run();
1272 EXPECT_EQ(pi1_ping_count, 2010);
1273 EXPECT_EQ(pi2_ping_count, 2010);
1274 EXPECT_EQ(pi1_pong_count, 2010);
1275 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001276
1277 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001278}
1279
James Kuszmaul46d82582020-05-09 19:50:09 -07001280typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1281
1282// Test that if we feed the replay with a mismatched node list that we die on
1283// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001284TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001285 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001286 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001287 LoggerState pi1_logger = MakeLogger(pi1_);
1288 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001289
1290 event_loop_factory_.RunFor(chrono::milliseconds(95));
1291
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001292 StartLogger(&pi1_logger);
1293 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001294
James Kuszmaul46d82582020-05-09 19:50:09 -07001295 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1296 }
1297
1298 // Test that, if we add an additional node to the replay config that the
1299 // logger complains about the mismatch in number of nodes.
1300 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1301 configuration::MergeWithConfig(&config_.message(), R"({
1302 "nodes": [
1303 {
1304 "name": "extra-node"
1305 }
1306 ]
1307 }
1308 )");
1309
Austin Schuh287d43d2020-12-04 20:19:33 -08001310 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1311 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001312 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001313}
1314
Austin Schuhcde938c2020-02-02 17:30:07 -08001315// Tests that we can read log files where they don't start at the same monotonic
1316// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001317TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001318 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001319 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001320 LoggerState pi1_logger = MakeLogger(pi1_);
1321 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001322
1323 event_loop_factory_.RunFor(chrono::milliseconds(95));
1324
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001325 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001326
1327 event_loop_factory_.RunFor(chrono::milliseconds(200));
1328
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001329 StartLogger(&pi2_logger);
1330
Austin Schuhcde938c2020-02-02 17:30:07 -08001331 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1332 }
1333
Austin Schuh287d43d2020-12-04 20:19:33 -08001334 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001335
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001336 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001337 log_reader_factory.set_send_delay(chrono::microseconds(0));
1338
1339 // This sends out the fetched messages and advances time to the start of the
1340 // log file.
1341 reader.Register(&log_reader_factory);
1342
1343 const Node *pi1 =
1344 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1345 const Node *pi2 =
1346 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1347
Austin Schuh07676622021-01-21 18:59:17 -08001348 EXPECT_THAT(reader.LoggedNodes(),
1349 ::testing::ElementsAre(
1350 configuration::GetNode(reader.logged_configuration(), pi1),
1351 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001352
1353 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1354
1355 std::unique_ptr<EventLoop> pi1_event_loop =
1356 log_reader_factory.MakeEventLoop("test", pi1);
1357 std::unique_ptr<EventLoop> pi2_event_loop =
1358 log_reader_factory.MakeEventLoop("test", pi2);
1359
1360 int pi1_ping_count = 30;
1361 int pi2_ping_count = 30;
1362 int pi1_pong_count = 30;
1363 int pi2_pong_count = 30;
1364
1365 // Confirm that the ping value matches.
1366 pi1_event_loop->MakeWatcher(
1367 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1368 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1369 << pi1_event_loop->context().monotonic_remote_time << " -> "
1370 << pi1_event_loop->context().monotonic_event_time;
1371 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1372
1373 ++pi1_ping_count;
1374 });
1375 pi2_event_loop->MakeWatcher(
1376 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1377 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1378 << pi2_event_loop->context().monotonic_remote_time << " -> "
1379 << pi2_event_loop->context().monotonic_event_time;
1380 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1381
1382 ++pi2_ping_count;
1383 });
1384
1385 // Confirm that the ping and pong counts both match, and the value also
1386 // matches.
1387 pi1_event_loop->MakeWatcher(
1388 "/test", [&pi1_event_loop, &pi1_ping_count,
1389 &pi1_pong_count](const examples::Pong &pong) {
1390 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1391 << pi1_event_loop->context().monotonic_remote_time << " -> "
1392 << pi1_event_loop->context().monotonic_event_time;
1393
1394 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1395 ++pi1_pong_count;
1396 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1397 });
1398 pi2_event_loop->MakeWatcher(
1399 "/test", [&pi2_event_loop, &pi2_ping_count,
1400 &pi2_pong_count](const examples::Pong &pong) {
1401 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1402 << pi2_event_loop->context().monotonic_remote_time << " -> "
1403 << pi2_event_loop->context().monotonic_event_time;
1404
1405 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1406 ++pi2_pong_count;
1407 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1408 });
1409
1410 log_reader_factory.Run();
1411 EXPECT_EQ(pi1_ping_count, 2030);
1412 EXPECT_EQ(pi2_ping_count, 2030);
1413 EXPECT_EQ(pi1_pong_count, 2030);
1414 EXPECT_EQ(pi2_pong_count, 2030);
1415
1416 reader.Deregister();
1417}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001418
Austin Schuh8bd96322020-02-13 21:18:22 -08001419// Tests that we can read log files where the monotonic clocks drift and don't
1420// match correctly. While we are here, also test that different ending times
1421// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001422TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001423 // TODO(austin): Negate...
1424 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1425
1426 time_converter_.AddMonotonic({monotonic_clock::epoch(),
1427 monotonic_clock::epoch() + initial_pi2_offset});
1428 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1429 // skew to be 200 uS/s
1430 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1431 {chrono::milliseconds(95),
1432 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1433 // Run another 200 ms to have one logger start first.
1434 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1435 {chrono::milliseconds(200), chrono::milliseconds(200)});
1436 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1437 // go far enough to cause problems if this isn't accounted for.
1438 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1439 {chrono::milliseconds(20000),
1440 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1441 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1442 {chrono::milliseconds(40000),
1443 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1444 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1445 {chrono::milliseconds(400), chrono::milliseconds(400)});
1446
Austin Schuhcde938c2020-02-02 17:30:07 -08001447 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001448 LoggerState pi2_logger = MakeLogger(pi2_);
1449
Austin Schuh87dd3832021-01-01 23:07:31 -08001450 NodeEventLoopFactory *pi1 =
1451 event_loop_factory_.GetNodeEventLoopFactory(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001452 NodeEventLoopFactory *pi2 =
1453 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1454 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1455 << pi2->realtime_now() << " distributed "
1456 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001457
Austin Schuh8bd96322020-02-13 21:18:22 -08001458 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1459 << pi2->realtime_now() << " distributed "
1460 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001461
Austin Schuh87dd3832021-01-01 23:07:31 -08001462 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001463
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001464 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001465
Austin Schuh87dd3832021-01-01 23:07:31 -08001466 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001467
Austin Schuh8bd96322020-02-13 21:18:22 -08001468 {
1469 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001470 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001471
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001472 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001473 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001474
Austin Schuh87dd3832021-01-01 23:07:31 -08001475 // Make sure we slewed time far enough so that the difference is greater
1476 // than the network delay. This confirms that if we sort incorrectly, it
1477 // would show in the results.
1478 EXPECT_LT(
1479 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1480 -event_loop_factory_.send_delay() -
1481 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001482
Austin Schuh87dd3832021-01-01 23:07:31 -08001483 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001484
Austin Schuh87dd3832021-01-01 23:07:31 -08001485 // And now check that we went far enough the other way to make sure we
1486 // cover both problems.
1487 EXPECT_GT(
1488 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1489 event_loop_factory_.send_delay() +
1490 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001491 }
1492
1493 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001494 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001495 }
1496
Austin Schuh287d43d2020-12-04 20:19:33 -08001497 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001498
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001499 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001500 log_reader_factory.set_send_delay(chrono::microseconds(0));
1501
Austin Schuhcde938c2020-02-02 17:30:07 -08001502 const Node *pi1 =
1503 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1504 const Node *pi2 =
1505 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1506
Austin Schuh2f8fd752020-09-01 22:38:28 -07001507 // This sends out the fetched messages and advances time to the start of the
1508 // log file.
1509 reader.Register(&log_reader_factory);
1510
1511 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1512 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1513 LOG(INFO) << "now pi1 "
1514 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1515 LOG(INFO) << "now pi2 "
1516 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1517
Austin Schuhcde938c2020-02-02 17:30:07 -08001518 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001519 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1520 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001521 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1522 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001523 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1524 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001525 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1526
Austin Schuh07676622021-01-21 18:59:17 -08001527 EXPECT_THAT(reader.LoggedNodes(),
1528 ::testing::ElementsAre(
1529 configuration::GetNode(reader.logged_configuration(), pi1),
1530 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001531
1532 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1533
1534 std::unique_ptr<EventLoop> pi1_event_loop =
1535 log_reader_factory.MakeEventLoop("test", pi1);
1536 std::unique_ptr<EventLoop> pi2_event_loop =
1537 log_reader_factory.MakeEventLoop("test", pi2);
1538
1539 int pi1_ping_count = 30;
1540 int pi2_ping_count = 30;
1541 int pi1_pong_count = 30;
1542 int pi2_pong_count = 30;
1543
1544 // Confirm that the ping value matches.
1545 pi1_event_loop->MakeWatcher(
1546 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1547 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1548 << pi1_event_loop->context().monotonic_remote_time << " -> "
1549 << pi1_event_loop->context().monotonic_event_time;
1550 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1551
1552 ++pi1_ping_count;
1553 });
1554 pi2_event_loop->MakeWatcher(
1555 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1556 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1557 << pi2_event_loop->context().monotonic_remote_time << " -> "
1558 << pi2_event_loop->context().monotonic_event_time;
1559 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1560
1561 ++pi2_ping_count;
1562 });
1563
1564 // Confirm that the ping and pong counts both match, and the value also
1565 // matches.
1566 pi1_event_loop->MakeWatcher(
1567 "/test", [&pi1_event_loop, &pi1_ping_count,
1568 &pi1_pong_count](const examples::Pong &pong) {
1569 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1570 << pi1_event_loop->context().monotonic_remote_time << " -> "
1571 << pi1_event_loop->context().monotonic_event_time;
1572
1573 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1574 ++pi1_pong_count;
1575 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1576 });
1577 pi2_event_loop->MakeWatcher(
1578 "/test", [&pi2_event_loop, &pi2_ping_count,
1579 &pi2_pong_count](const examples::Pong &pong) {
1580 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1581 << pi2_event_loop->context().monotonic_remote_time << " -> "
1582 << pi2_event_loop->context().monotonic_event_time;
1583
1584 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1585 ++pi2_pong_count;
1586 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1587 });
1588
1589 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001590 EXPECT_EQ(pi1_ping_count, 6030);
1591 EXPECT_EQ(pi2_ping_count, 6030);
1592 EXPECT_EQ(pi1_pong_count, 6030);
1593 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001594
1595 reader.Deregister();
1596}
1597
Austin Schuh5212cad2020-09-09 23:12:09 -07001598// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001599TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001600 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001601 // Make a bunch of parts.
1602 {
1603 LoggerState pi1_logger = MakeLogger(pi1_);
1604 LoggerState pi2_logger = MakeLogger(pi2_);
1605
1606 event_loop_factory_.RunFor(chrono::milliseconds(95));
1607
1608 StartLogger(&pi1_logger);
1609 StartLogger(&pi2_logger);
1610
1611 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1612 }
1613
Austin Schuh11d43732020-09-21 17:28:30 -07001614 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001615 VerifyParts(sorted_parts);
1616}
Austin Schuh11d43732020-09-21 17:28:30 -07001617
Austin Schuh3bd4c402020-11-06 18:19:06 -08001618// Tests that we can sort a bunch of parts with an empty part. We should ignore
1619// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001620TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001621 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001622 // Make a bunch of parts.
1623 {
1624 LoggerState pi1_logger = MakeLogger(pi1_);
1625 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001626
Austin Schuh3bd4c402020-11-06 18:19:06 -08001627 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001628
Austin Schuh3bd4c402020-11-06 18:19:06 -08001629 StartLogger(&pi1_logger);
1630 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001631
Austin Schuh3bd4c402020-11-06 18:19:06 -08001632 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001633 }
1634
Austin Schuh3bd4c402020-11-06 18:19:06 -08001635 // TODO(austin): Should we flip out if the file can't open?
1636 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001637
Austin Schuh3bd4c402020-11-06 18:19:06 -08001638 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1639 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001640
Austin Schuh3bd4c402020-11-06 18:19:06 -08001641 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1642 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001643}
1644
Austin Schuh3bd4c402020-11-06 18:19:06 -08001645#ifdef LZMA
1646// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1647// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001648TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001649 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001650 // Make a bunch of parts.
1651 {
1652 LoggerState pi1_logger = MakeLogger(pi1_);
1653 LoggerState pi2_logger = MakeLogger(pi2_);
1654
1655 event_loop_factory_.RunFor(chrono::milliseconds(95));
1656
1657 StartLogger(&pi1_logger, "", true);
1658 StartLogger(&pi2_logger, "", true);
1659
1660 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1661 }
1662
1663 // TODO(austin): Should we flip out if the file can't open?
1664 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1665
1666 AddExtension(".xz");
1667
1668 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1669 logfiles_.emplace_back(kEmptyFile);
1670
1671 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1672 VerifyParts(sorted_parts, {kEmptyFile});
1673}
1674
1675// Tests that we can sort a bunch of parts with the end missing off a compressed
1676// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001677TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001678 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001679 // Make a bunch of parts.
1680 {
1681 LoggerState pi1_logger = MakeLogger(pi1_);
1682 LoggerState pi2_logger = MakeLogger(pi2_);
1683
1684 event_loop_factory_.RunFor(chrono::milliseconds(95));
1685
1686 StartLogger(&pi1_logger, "", true);
1687 StartLogger(&pi2_logger, "", true);
1688
1689 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1690 }
1691
1692 // Append everything with .xz.
1693 AddExtension(".xz");
1694
1695 // Strip off the end of one of the files. Pick one with a lot of data.
1696 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001697 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001698
1699 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001700 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001701 compressed_contents.substr(0, compressed_contents.size() - 100));
1702
1703 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1704 VerifyParts(sorted_parts);
1705}
1706#endif
1707
Austin Schuh01b4c352020-09-21 23:09:39 -07001708// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001709TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001710 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001711 {
1712 LoggerState pi1_logger = MakeLogger(pi1_);
1713 LoggerState pi2_logger = MakeLogger(pi2_);
1714
1715 event_loop_factory_.RunFor(chrono::milliseconds(95));
1716
1717 StartLogger(&pi1_logger);
1718 StartLogger(&pi2_logger);
1719
1720 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1721 }
1722
Austin Schuh287d43d2020-12-04 20:19:33 -08001723 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001724
1725 // Remap just on pi1.
1726 reader.RemapLoggedChannel<aos::timing::Report>(
1727 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1728
1729 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1730 log_reader_factory.set_send_delay(chrono::microseconds(0));
1731
1732 reader.Register(&log_reader_factory);
1733
1734 const Node *pi1 =
1735 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1736 const Node *pi2 =
1737 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1738
1739 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1740 // else should have moved.
1741 std::unique_ptr<EventLoop> pi1_event_loop =
1742 log_reader_factory.MakeEventLoop("test", pi1);
1743 pi1_event_loop->SkipTimingReport();
1744 std::unique_ptr<EventLoop> full_pi1_event_loop =
1745 log_reader_factory.MakeEventLoop("test", pi1);
1746 full_pi1_event_loop->SkipTimingReport();
1747 std::unique_ptr<EventLoop> pi2_event_loop =
1748 log_reader_factory.MakeEventLoop("test", pi2);
1749 pi2_event_loop->SkipTimingReport();
1750
1751 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1752 "/aos");
1753 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1754 full_pi1_event_loop.get(), "/pi1/aos");
1755 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1756 pi1_event_loop.get(), "/original/aos");
1757 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1758 full_pi1_event_loop.get(), "/original/pi1/aos");
1759 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1760 "/aos");
1761
1762 log_reader_factory.Run();
1763
1764 EXPECT_EQ(pi1_timing_report.count(), 0u);
1765 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1766 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1767 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1768 EXPECT_NE(pi2_timing_report.count(), 0u);
1769
1770 reader.Deregister();
1771}
1772
Austin Schuh006a9f52021-04-07 16:24:18 -07001773// Tests that we can remap a forwarded channel as well.
1774TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1775 time_converter_.StartEqual();
1776 {
1777 LoggerState pi1_logger = MakeLogger(pi1_);
1778 LoggerState pi2_logger = MakeLogger(pi2_);
1779
1780 event_loop_factory_.RunFor(chrono::milliseconds(95));
1781
1782 StartLogger(&pi1_logger);
1783 StartLogger(&pi2_logger);
1784
1785 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1786 }
1787
1788 LogReader reader(SortParts(logfiles_));
1789
1790 reader.RemapLoggedChannel<examples::Ping>("/test");
1791
1792 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1793 log_reader_factory.set_send_delay(chrono::microseconds(0));
1794
1795 reader.Register(&log_reader_factory);
1796
1797 const Node *pi1 =
1798 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1799 const Node *pi2 =
1800 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1801
1802 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1803 // else should have moved.
1804 std::unique_ptr<EventLoop> pi1_event_loop =
1805 log_reader_factory.MakeEventLoop("test", pi1);
1806 pi1_event_loop->SkipTimingReport();
1807 std::unique_ptr<EventLoop> full_pi1_event_loop =
1808 log_reader_factory.MakeEventLoop("test", pi1);
1809 full_pi1_event_loop->SkipTimingReport();
1810 std::unique_ptr<EventLoop> pi2_event_loop =
1811 log_reader_factory.MakeEventLoop("test", pi2);
1812 pi2_event_loop->SkipTimingReport();
1813
1814 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1815 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1816 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1817 "/original/test");
1818 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1819 "/original/test");
1820
1821 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1822 pi1_original_ping_timestamp;
1823 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1824 pi1_ping_timestamp;
1825 if (!shared()) {
1826 pi1_original_ping_timestamp =
1827 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1828 pi1_event_loop.get(),
1829 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1830 pi1_ping_timestamp =
1831 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1832 pi1_event_loop.get(),
1833 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1834 }
1835
1836 log_reader_factory.Run();
1837
1838 EXPECT_EQ(pi1_ping.count(), 0u);
1839 EXPECT_EQ(pi2_ping.count(), 0u);
1840 EXPECT_NE(pi1_original_ping.count(), 0u);
1841 EXPECT_NE(pi2_original_ping.count(), 0u);
1842 if (!shared()) {
1843 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1844 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1845 }
1846
1847 reader.Deregister();
1848}
1849
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001850// Tests that we properly recreate forwarded timestamps when replaying a log.
1851// This should be enough that we can then re-run the logger and get a valid log
1852// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001853TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001854 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001855 {
1856 LoggerState pi1_logger = MakeLogger(pi1_);
1857 LoggerState pi2_logger = MakeLogger(pi2_);
1858
1859 event_loop_factory_.RunFor(chrono::milliseconds(95));
1860
1861 StartLogger(&pi1_logger);
1862 StartLogger(&pi2_logger);
1863
1864 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1865 }
1866
Austin Schuh287d43d2020-12-04 20:19:33 -08001867 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001868
1869 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1870 log_reader_factory.set_send_delay(chrono::microseconds(0));
1871
1872 // This sends out the fetched messages and advances time to the start of the
1873 // log file.
1874 reader.Register(&log_reader_factory);
1875
1876 const Node *pi1 =
1877 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1878 const Node *pi2 =
1879 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1880
1881 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1882 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1883 LOG(INFO) << "now pi1 "
1884 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1885 LOG(INFO) << "now pi2 "
1886 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1887
Austin Schuh07676622021-01-21 18:59:17 -08001888 EXPECT_THAT(reader.LoggedNodes(),
1889 ::testing::ElementsAre(
1890 configuration::GetNode(reader.logged_configuration(), pi1),
1891 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001892
1893 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1894
1895 std::unique_ptr<EventLoop> pi1_event_loop =
1896 log_reader_factory.MakeEventLoop("test", pi1);
1897 std::unique_ptr<EventLoop> pi2_event_loop =
1898 log_reader_factory.MakeEventLoop("test", pi2);
1899
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001900 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1901 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1902 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1903 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1904
1905 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1906 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1907 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1908 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1909
1910 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1911 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1912 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1913 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1914
1915 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1916 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1917 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1918 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1919
1920 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1921 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1922 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1923 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1924
1925 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1926 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1927 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1928 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1929
Austin Schuh969cd602021-01-03 00:09:45 -08001930 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001931 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001932
Austin Schuh61e973f2021-02-21 21:43:56 -08001933 for (std::pair<int, std::string> channel :
1934 shared()
1935 ? std::vector<
1936 std::pair<int, std::string>>{{-1,
1937 "/aos/remote_timestamps/pi2"}}
1938 : std::vector<std::pair<int, std::string>>{
1939 {pi1_timestamp_channel,
1940 "/aos/remote_timestamps/pi2/pi1/aos/"
1941 "aos-message_bridge-Timestamp"},
1942 {ping_timestamp_channel,
1943 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1944 pi1_event_loop->MakeWatcher(
1945 channel.second,
1946 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1947 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1948 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1949 &ping_on_pi2_fetcher, network_delay, send_delay,
1950 channel_index = channel.first](const RemoteMessage &header) {
1951 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1952 chrono::nanoseconds(header.monotonic_sent_time()));
1953 const aos::realtime_clock::time_point header_realtime_sent_time(
1954 chrono::nanoseconds(header.realtime_sent_time()));
1955 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1956 chrono::nanoseconds(header.monotonic_remote_time()));
1957 const aos::realtime_clock::time_point header_realtime_remote_time(
1958 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001959
Austin Schuh61e973f2021-02-21 21:43:56 -08001960 if (channel_index != -1) {
1961 ASSERT_EQ(channel_index, header.channel_index());
1962 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001963
Austin Schuh61e973f2021-02-21 21:43:56 -08001964 const Context *pi1_context = nullptr;
1965 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001966
Austin Schuh61e973f2021-02-21 21:43:56 -08001967 if (header.channel_index() == pi1_timestamp_channel) {
1968 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1969 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1970 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1971 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1972 } else if (header.channel_index() == ping_timestamp_channel) {
1973 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1974 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1975 pi1_context = &ping_on_pi1_fetcher.context();
1976 pi2_context = &ping_on_pi2_fetcher.context();
1977 } else {
1978 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1979 << configuration::CleanedChannelToString(
1980 pi1_event_loop->configuration()->channels()->Get(
1981 header.channel_index()));
1982 }
Austin Schuh315b96b2020-12-11 21:21:12 -08001983
Austin Schuh61e973f2021-02-21 21:43:56 -08001984 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07001985 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1986 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001987
Austin Schuh61e973f2021-02-21 21:43:56 -08001988 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1989 EXPECT_EQ(pi2_context->remote_queue_index,
1990 header.remote_queue_index());
1991 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001992
Austin Schuh61e973f2021-02-21 21:43:56 -08001993 EXPECT_EQ(pi2_context->monotonic_event_time,
1994 header_monotonic_sent_time);
1995 EXPECT_EQ(pi2_context->realtime_event_time,
1996 header_realtime_sent_time);
1997 EXPECT_EQ(pi2_context->realtime_remote_time,
1998 header_realtime_remote_time);
1999 EXPECT_EQ(pi2_context->monotonic_remote_time,
2000 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002001
Austin Schuh61e973f2021-02-21 21:43:56 -08002002 EXPECT_EQ(pi1_context->realtime_event_time,
2003 header_realtime_remote_time);
2004 EXPECT_EQ(pi1_context->monotonic_event_time,
2005 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002006
Austin Schuh61e973f2021-02-21 21:43:56 -08002007 // Time estimation isn't perfect, but we know the clocks were
2008 // identical when logged, so we know when this should have come back.
2009 // Confirm we got it when we expected.
2010 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2011 pi1_context->monotonic_event_time + 2 * network_delay +
2012 send_delay);
2013 });
2014 }
2015 for (std::pair<int, std::string> channel :
2016 shared()
2017 ? std::vector<
2018 std::pair<int, std::string>>{{-1,
2019 "/aos/remote_timestamps/pi1"}}
2020 : std::vector<std::pair<int, std::string>>{
2021 {pi2_timestamp_channel,
2022 "/aos/remote_timestamps/pi1/pi2/aos/"
2023 "aos-message_bridge-Timestamp"}}) {
2024 pi2_event_loop->MakeWatcher(
2025 channel.second,
2026 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2027 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2028 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2029 &pong_on_pi1_fetcher, network_delay, send_delay,
2030 channel_index = channel.first](const RemoteMessage &header) {
2031 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2032 chrono::nanoseconds(header.monotonic_sent_time()));
2033 const aos::realtime_clock::time_point header_realtime_sent_time(
2034 chrono::nanoseconds(header.realtime_sent_time()));
2035 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2036 chrono::nanoseconds(header.monotonic_remote_time()));
2037 const aos::realtime_clock::time_point header_realtime_remote_time(
2038 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002039
Austin Schuh61e973f2021-02-21 21:43:56 -08002040 if (channel_index != -1) {
2041 ASSERT_EQ(channel_index, header.channel_index());
2042 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002043
Austin Schuh61e973f2021-02-21 21:43:56 -08002044 const Context *pi2_context = nullptr;
2045 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002046
Austin Schuh61e973f2021-02-21 21:43:56 -08002047 if (header.channel_index() == pi2_timestamp_channel) {
2048 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2049 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2050 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2051 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2052 } else if (header.channel_index() == pong_timestamp_channel) {
2053 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2054 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2055 pi2_context = &pong_on_pi2_fetcher.context();
2056 pi1_context = &pong_on_pi1_fetcher.context();
2057 } else {
2058 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2059 << configuration::CleanedChannelToString(
2060 pi2_event_loop->configuration()->channels()->Get(
2061 header.channel_index()));
2062 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002063
Austin Schuh61e973f2021-02-21 21:43:56 -08002064 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002065 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2066 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002067
Austin Schuh61e973f2021-02-21 21:43:56 -08002068 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2069 EXPECT_EQ(pi1_context->remote_queue_index,
2070 header.remote_queue_index());
2071 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002072
Austin Schuh61e973f2021-02-21 21:43:56 -08002073 EXPECT_EQ(pi1_context->monotonic_event_time,
2074 header_monotonic_sent_time);
2075 EXPECT_EQ(pi1_context->realtime_event_time,
2076 header_realtime_sent_time);
2077 EXPECT_EQ(pi1_context->realtime_remote_time,
2078 header_realtime_remote_time);
2079 EXPECT_EQ(pi1_context->monotonic_remote_time,
2080 header_monotonic_remote_time);
2081
2082 EXPECT_EQ(pi2_context->realtime_event_time,
2083 header_realtime_remote_time);
2084 EXPECT_EQ(pi2_context->monotonic_event_time,
2085 header_monotonic_remote_time);
2086
2087 // Time estimation isn't perfect, but we know the clocks were
2088 // identical when logged, so we know when this should have come back.
2089 // Confirm we got it when we expected.
2090 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2091 pi2_context->monotonic_event_time + 2 * network_delay +
2092 send_delay);
2093 });
2094 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002095
2096 // And confirm we can re-create a log again, while checking the contents.
2097 {
2098 LoggerState pi1_logger = MakeLogger(
2099 configuration::GetNode(log_reader_factory.configuration(), pi1_),
2100 &log_reader_factory);
2101 LoggerState pi2_logger = MakeLogger(
2102 configuration::GetNode(log_reader_factory.configuration(), pi2_),
2103 &log_reader_factory);
2104
Austin Schuh25b46712021-01-03 00:04:38 -08002105 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2106 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002107
2108 log_reader_factory.Run();
2109 }
2110
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002111 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002112
2113 // And verify that we can run the LogReader over the relogged files without
2114 // hitting any fatal errors.
2115 {
2116 LogReader relogged_reader(SortParts(
2117 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2118 relogged_reader.Register();
2119
2120 relogged_reader.event_loop_factory()->Run();
2121 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002122}
2123
Austin Schuh315b96b2020-12-11 21:21:12 -08002124// Tests that we properly populate and extract the logger_start time by setting
2125// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002126TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002127 time_converter_.AddMonotonic(
2128 {monotonic_clock::epoch(),
2129 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002130 {
2131 LoggerState pi1_logger = MakeLogger(pi1_);
2132 LoggerState pi2_logger = MakeLogger(pi2_);
2133
Austin Schuh315b96b2020-12-11 21:21:12 -08002134 StartLogger(&pi1_logger);
2135 StartLogger(&pi2_logger);
2136
2137 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2138 }
2139
2140 for (const LogFile &log_file : SortParts(logfiles_)) {
2141 for (const LogParts &log_part : log_file.parts) {
2142 if (log_part.node == log_file.logger_node) {
2143 EXPECT_EQ(log_part.logger_monotonic_start_time,
2144 aos::monotonic_clock::min_time);
2145 EXPECT_EQ(log_part.logger_realtime_start_time,
2146 aos::realtime_clock::min_time);
2147 } else {
2148 const chrono::seconds offset = log_file.logger_node == "pi1"
2149 ? -chrono::seconds(1000)
2150 : chrono::seconds(1000);
2151 EXPECT_EQ(log_part.logger_monotonic_start_time,
2152 log_part.monotonic_start_time + offset);
2153 EXPECT_EQ(log_part.logger_realtime_start_time,
2154 log_file.realtime_start_time +
2155 (log_part.logger_monotonic_start_time -
2156 log_file.monotonic_start_time));
2157 }
2158 }
2159 }
2160}
2161
Austin Schuh6bb8a822021-03-31 23:04:39 -07002162// Test that renaming the base, renames the folder.
2163TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
2164 time_converter_.AddMonotonic(
2165 {monotonic_clock::epoch(),
2166 monotonic_clock::epoch() + chrono::seconds(1000)});
2167 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2168 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2169 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2170 LoggerState pi1_logger = MakeLogger(pi1_);
2171 LoggerState pi2_logger = MakeLogger(pi2_);
2172
2173 StartLogger(&pi1_logger);
2174 StartLogger(&pi2_logger);
2175
2176 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2177 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2178 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2179 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2180 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2181 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2182 for (auto &file : logfiles_) {
2183 struct stat s;
2184 EXPECT_EQ(0, stat(file.c_str(), &s));
2185 }
2186}
2187
2188// Test that renaming the file base dies.
2189TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2190 time_converter_.AddMonotonic(
2191 {monotonic_clock::epoch(),
2192 monotonic_clock::epoch() + chrono::seconds(1000)});
2193 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2194 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2195 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2196 LoggerState pi1_logger = MakeLogger(pi1_);
2197 StartLogger(&pi1_logger);
2198 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2199 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2200 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2201 "Rename of file base from");
2202}
2203
Austin Schuh8bd96322020-02-13 21:18:22 -08002204// TODO(austin): We can write a test which recreates a logfile and confirms that
2205// we get it back. That is the ultimate test.
2206
Austin Schuh315b96b2020-12-11 21:21:12 -08002207// Tests that we properly recreate forwarded timestamps when replaying a log.
2208// This should be enough that we can then re-run the logger and get a valid log
2209// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002210TEST_P(MultinodeLoggerDeathTest, RemoteReboot) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002211 time_converter_.StartEqual();
Austin Schuh315b96b2020-12-11 21:21:12 -08002212 std::string pi2_boot1;
2213 std::string pi2_boot2;
2214 {
2215 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2216 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002217 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002218 LoggerState pi1_logger = MakeLogger(pi1_);
2219
2220 event_loop_factory_.RunFor(chrono::milliseconds(95));
2221
2222 StartLogger(&pi1_logger);
2223
2224 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2225
2226 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
2227
2228 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2229 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002230 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002231
2232 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2233 }
2234
2235 // Confirm that we refuse to replay logs with missing boot uuids.
2236 EXPECT_DEATH(
2237 {
2238 LogReader reader(SortParts(pi1_reboot_logfiles_));
2239
2240 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2241 log_reader_factory.set_send_delay(chrono::microseconds(0));
2242
2243 // This sends out the fetched messages and advances time to the start of
2244 // the log file.
2245 reader.Register(&log_reader_factory);
2246 },
2247 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
2248 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
2249}
2250
Austin Schuhc9049732020-12-21 22:27:15 -08002251// Tests that we properly handle one direction of message_bridge being
2252// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002253TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002254 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002255 time_converter_.AddMonotonic(
2256 {monotonic_clock::epoch(),
2257 monotonic_clock::epoch() + chrono::seconds(1000)});
2258
2259 time_converter_.AddMonotonic(
2260 {chrono::milliseconds(10000),
2261 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002262 {
2263 LoggerState pi1_logger = MakeLogger(pi1_);
2264
2265 event_loop_factory_.RunFor(chrono::milliseconds(95));
2266
2267 StartLogger(&pi1_logger);
2268
2269 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2270 }
2271
2272 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2273 // to confirm the right thing happened.
2274 ConfirmReadable(pi1_single_direction_logfiles_);
2275}
2276
2277// Tests that we properly handle one direction of message_bridge being
2278// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002279TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002280 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002281 time_converter_.AddMonotonic(
2282 {monotonic_clock::epoch(),
2283 monotonic_clock::epoch() + chrono::seconds(500)});
2284
2285 time_converter_.AddMonotonic(
2286 {chrono::milliseconds(10000),
2287 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2288 {
2289 LoggerState pi1_logger = MakeLogger(pi1_);
2290
2291 event_loop_factory_.RunFor(chrono::milliseconds(95));
2292
2293 StartLogger(&pi1_logger);
2294
2295 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2296 }
2297
2298 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2299 // to confirm the right thing happened.
2300 ConfirmReadable(pi1_single_direction_logfiles_);
2301}
2302
2303// Tests that we properly handle a dead node. Do this by just disconnecting it
2304// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002305TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002306 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
2307 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
2308 time_converter_.AddMonotonic(
2309 {monotonic_clock::epoch(),
2310 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002311 {
2312 LoggerState pi1_logger = MakeLogger(pi1_);
2313
2314 event_loop_factory_.RunFor(chrono::milliseconds(95));
2315
2316 StartLogger(&pi1_logger);
2317
2318 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2319 }
2320
2321 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2322 // to confirm the right thing happened.
2323 ConfirmReadable(pi1_single_direction_logfiles_);
2324}
2325
Austin Schuhcdd90272021-03-15 12:46:16 -07002326constexpr std::string_view kCombinedConfigSha1(
milind945708b2021-07-03 13:30:15 -07002327 "4503751edc96327493562f0376f0d6daac172927c0fd64d04ce5d67505186c0b");
Austin Schuhcdd90272021-03-15 12:46:16 -07002328constexpr std::string_view kSplitConfigSha1(
milind945708b2021-07-03 13:30:15 -07002329 "918a748432c5e70a971dfd8934968378bed04ab61cf2efcd35b7f6224053c247");
Austin Schuhcdd90272021-03-15 12:46:16 -07002330
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002331INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002332 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002333 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2334 kCombinedConfigSha1},
2335 Param{"multinode_pingpong_split_config.json", false,
2336 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002337
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002338INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002339 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002340 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2341 kCombinedConfigSha1},
2342 Param{"multinode_pingpong_split_config.json", false,
2343 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002344
Austin Schuha04efed2021-01-24 18:04:20 -08002345// TODO(austin): Make a log file where the remote node has no start time.
2346
Austin Schuhe309d2a2019-11-29 13:25:21 -08002347} // namespace testing
2348} // namespace logger
2349} // namespace aos