blob: a7d627d6d0b8aad42628a5cd841e6432fccdac3d [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 Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
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>(
Austin Schuh73340842021-07-30 22:32:06 -0700174 base_name1, logger_event_loop->configuration(),
175 logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700176 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
Austin Schuh73340842021-07-30 22:32:06 -0700177 base_name2, logger_event_loop->configuration(),
178 logger_event_loop->node())),
Brian Silverman1f345222020-09-24 21:14:48 -0700179 "Already logging");
180 });
181 event_loop_factory_.RunFor(chrono::milliseconds(20000));
182 }
183}
184
185// Tests calling StopLogging twice.
186TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800187 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700188 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800189 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700190 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700191 const ::std::string logfile = base_name + ".part0.bfbs";
192 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800193 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700194 unlink(logfile.c_str());
195
196 LOG(INFO) << "Logging data to " << logfile;
197
198 {
199 std::unique_ptr<EventLoop> logger_event_loop =
200 event_loop_factory_.MakeEventLoop("logger");
201
202 event_loop_factory_.RunFor(chrono::milliseconds(95));
203
204 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800205 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700206 logger.set_polling_period(std::chrono::milliseconds(100));
207 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
208 logger.StartLogging(std::make_unique<LocalLogNamer>(
Austin Schuh73340842021-07-30 22:32:06 -0700209 base_name, logger_event_loop->configuration(),
210 logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700211 logger.StopLogging(aos::monotonic_clock::min_time);
212 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
213 "Not logging right now");
214 });
215 event_loop_factory_.RunFor(chrono::milliseconds(20000));
216 }
217}
218
219// Tests that we can startup twice.
220TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800221 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700222 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800223 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700224 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700225 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
226 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800227 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700228 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700229 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
230 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800231 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700232 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800233 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700234
235 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
236
237 {
238 std::unique_ptr<EventLoop> logger_event_loop =
239 event_loop_factory_.MakeEventLoop("logger");
240
241 event_loop_factory_.RunFor(chrono::milliseconds(95));
242
243 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800244 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700245 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh73340842021-07-30 22:32:06 -0700246 logger.StartLogging(std::make_unique<LocalLogNamer>(
247 base_name1, logger_event_loop->configuration(),
248 logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700249 event_loop_factory_.RunFor(chrono::milliseconds(10000));
250 logger.StopLogging(logger_event_loop->monotonic_now());
251 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh73340842021-07-30 22:32:06 -0700252 logger.StartLogging(std::make_unique<LocalLogNamer>(
253 base_name2, logger_event_loop->configuration(),
254 logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700255 event_loop_factory_.RunFor(chrono::milliseconds(10000));
256 }
257
258 for (const auto &logfile :
259 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
260 SCOPED_TRACE(std::get<0>(logfile));
261 LogReader reader(std::get<0>(logfile));
262 reader.Register();
263
Austin Schuh07676622021-01-21 18:59:17 -0800264 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700265
266 std::unique_ptr<EventLoop> test_event_loop =
267 reader.event_loop_factory()->MakeEventLoop("log_reader");
268
269 int ping_count = std::get<1>(logfile);
270 int pong_count = std::get<1>(logfile);
271
272 // Confirm that the ping and pong counts both match, and the value also
273 // matches.
274 test_event_loop->MakeWatcher("/test",
275 [&ping_count](const examples::Ping &ping) {
276 EXPECT_EQ(ping.value(), ping_count + 1);
277 ++ping_count;
278 });
279 test_event_loop->MakeWatcher(
280 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
281 EXPECT_EQ(pong.value(), pong_count + 1);
282 ++pong_count;
283 EXPECT_EQ(ping_count, pong_count);
284 });
285
286 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
287 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
288 }
289}
290
Austin Schuhfa895892020-01-07 20:07:41 -0800291// Tests that we can read and write rotated log files.
292TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800293 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700294 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800295 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700296 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700297 const ::std::string logfile0 = base_name + ".part0.bfbs";
298 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800299 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800300 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800301 unlink(logfile0.c_str());
302 unlink(logfile1.c_str());
303
304 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
305
306 {
Austin Schuhfa895892020-01-07 20:07:41 -0800307 std::unique_ptr<EventLoop> logger_event_loop =
308 event_loop_factory_.MakeEventLoop("logger");
309
310 event_loop_factory_.RunFor(chrono::milliseconds(95));
311
Brian Silverman1f345222020-09-24 21:14:48 -0700312 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800313 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700314 logger.set_polling_period(std::chrono::milliseconds(100));
315 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800316 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700317 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800318 event_loop_factory_.RunFor(chrono::milliseconds(10000));
319 }
320
Austin Schuh64fab802020-09-09 22:47:47 -0700321 {
322 // Confirm that the UUIDs match for both the parts and the logger, and the
323 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800324 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700325 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800326 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700327 }
328
Brian Silvermanae7c0332020-09-30 16:58:23 -0700329 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
330 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700331 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
332 log_header[1].message().parts_uuid()->string_view());
333
334 EXPECT_EQ(log_header[0].message().parts_index(), 0);
335 EXPECT_EQ(log_header[1].message().parts_index(), 1);
336 }
337
Austin Schuhfa895892020-01-07 20:07:41 -0800338 // Even though it doesn't make any difference here, exercise the logic for
339 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800340 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800341
342 // Confirm that we can remap logged channels to point to new buses.
343 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
344
345 // This sends out the fetched messages and advances time to the start of the
346 // log file.
347 reader.Register();
348
Austin Schuh07676622021-01-21 18:59:17 -0800349 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800350
351 std::unique_ptr<EventLoop> test_event_loop =
352 reader.event_loop_factory()->MakeEventLoop("log_reader");
353
354 int ping_count = 10;
355 int pong_count = 10;
356
357 // Confirm that the ping value matches in the remapped channel location.
358 test_event_loop->MakeWatcher("/original/test",
359 [&ping_count](const examples::Ping &ping) {
360 EXPECT_EQ(ping.value(), ping_count + 1);
361 ++ping_count;
362 });
363 // Confirm that the ping and pong counts both match, and the value also
364 // matches.
365 test_event_loop->MakeWatcher(
366 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
367 EXPECT_EQ(pong.value(), pong_count + 1);
368 ++pong_count;
369 EXPECT_EQ(ping_count, pong_count);
370 });
371
372 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
373 EXPECT_EQ(ping_count, 2010);
374}
375
Austin Schuh4c4e0092019-12-22 16:18:03 -0800376// Tests that a large number of messages per second doesn't overwhelm writev.
377TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800378 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700379 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800380 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700381 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700382 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800383 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800384 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800385 unlink(logfile.c_str());
386
387 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700388 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800389
390 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800391 std::unique_ptr<EventLoop> logger_event_loop =
392 event_loop_factory_.MakeEventLoop("logger");
393
394 std::unique_ptr<EventLoop> ping_spammer_event_loop =
395 event_loop_factory_.MakeEventLoop("ping_spammer");
396 aos::Sender<examples::Ping> ping_sender =
397 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
398
399 aos::TimerHandler *timer_handler =
400 ping_spammer_event_loop->AddTimer([&ping_sender]() {
401 aos::Sender<examples::Ping>::Builder builder =
402 ping_sender.MakeBuilder();
403 examples::Ping::Builder ping_builder =
404 builder.MakeBuilder<examples::Ping>();
405 CHECK(builder.Send(ping_builder.Finish()));
406 });
407
408 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
409 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
410 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
411 chrono::microseconds(50));
412 });
413
Brian Silverman1f345222020-09-24 21:14:48 -0700414 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800415 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700416 logger.set_polling_period(std::chrono::milliseconds(100));
417 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800418
419 event_loop_factory_.RunFor(chrono::milliseconds(1000));
420 }
421}
422
Austin Schuh61e973f2021-02-21 21:43:56 -0800423// Parameters to run all the tests with.
424struct Param {
425 // The config file to use.
426 std::string config;
427 // If true, the RemoteMessage channel should be shared between all the remote
428 // channels. If false, there will be 1 RemoteMessage channel per remote
429 // channel.
430 bool shared;
431 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700432 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800433};
Austin Schuh315b96b2020-12-11 21:21:12 -0800434
Austin Schuh61e973f2021-02-21 21:43:56 -0800435class MultinodeLoggerTest : public ::testing::TestWithParam<struct Param> {
Austin Schuh15649d62019-12-28 16:36:38 -0800436 public:
437 MultinodeLoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -0700438 : config_(aos::configuration::ReadConfig(ArtifactPath(
439 absl::StrCat("aos/events/logging/", GetParam().config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800440 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800441 event_loop_factory_(&config_.message()),
Austin Schuhcde938c2020-02-02 17:30:07 -0800442 pi1_(
443 configuration::GetNode(event_loop_factory_.configuration(), "pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800444 pi1_index_(configuration::GetNodeIndex(
445 event_loop_factory_.configuration(), pi1_)),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700446 pi2_(
447 configuration::GetNode(event_loop_factory_.configuration(), "pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800448 pi2_index_(configuration::GetNodeIndex(
449 event_loop_factory_.configuration(), pi2_)),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800450 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800451 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
452 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800453 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800454 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800455 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
456 structured_logfiles_(StructureLogFiles()),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700457 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping", pi1_)),
458 ping_(ping_event_loop_.get()),
459 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong", pi2_)),
460 pong_(pong_event_loop_.get()) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800461 LOG(INFO) << "Config " << GetParam().config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800462 event_loop_factory_.SetTimeConverter(&time_converter_);
463
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700464 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700465 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700466 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800467 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700468 }
469
Austin Schuh268586b2021-03-31 22:24:39 -0700470 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800471 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800472 unlink(file.c_str());
473 }
474
Austin Schuh268586b2021-03-31 22:24:39 -0700475 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800476 unlink(file.c_str());
477 }
478
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700479 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
480 << " and " << logfiles_[2];
481 }
482
Austin Schuh61e973f2021-02-21 21:43:56 -0800483 bool shared() const { return GetParam().shared; }
484
485 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
486 std::string logfile_base2) {
487 std::vector<std::string> result;
488 result.emplace_back(
489 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
490 result.emplace_back(
491 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
492 result.emplace_back(logfile_base1 + "_pi1_data.part0.bfbs");
493 result.emplace_back(logfile_base1 +
494 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
495 result.emplace_back(logfile_base1 +
496 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
497 result.emplace_back(logfile_base2 + "_pi2_data.part0.bfbs");
498 result.emplace_back(
499 logfile_base2 +
500 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
501 result.emplace_back(
502 logfile_base2 +
503 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
504 result.emplace_back(
505 logfile_base1 +
506 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
507 result.emplace_back(
508 logfile_base1 +
509 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
510 if (shared()) {
511 result.emplace_back(logfile_base1 +
512 "_timestamps/pi1/aos/remote_timestamps/pi2/"
513 "aos.message_bridge.RemoteMessage.part0.bfbs");
514 result.emplace_back(logfile_base1 +
515 "_timestamps/pi1/aos/remote_timestamps/pi2/"
516 "aos.message_bridge.RemoteMessage.part1.bfbs");
517 result.emplace_back(logfile_base2 +
518 "_timestamps/pi2/aos/remote_timestamps/pi1/"
519 "aos.message_bridge.RemoteMessage.part0.bfbs");
520 result.emplace_back(logfile_base2 +
521 "_timestamps/pi2/aos/remote_timestamps/pi1/"
522 "aos.message_bridge.RemoteMessage.part1.bfbs");
523 } else {
524 result.emplace_back(logfile_base1 +
525 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
526 "aos-message_bridge-Timestamp/"
527 "aos.message_bridge.RemoteMessage.part0.bfbs");
528 result.emplace_back(logfile_base1 +
529 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
530 "aos-message_bridge-Timestamp/"
531 "aos.message_bridge.RemoteMessage.part1.bfbs");
532 result.emplace_back(logfile_base2 +
533 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
534 "aos-message_bridge-Timestamp/"
535 "aos.message_bridge.RemoteMessage.part0.bfbs");
536 result.emplace_back(logfile_base2 +
537 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
538 "aos-message_bridge-Timestamp/"
539 "aos.message_bridge.RemoteMessage.part1.bfbs");
540 result.emplace_back(logfile_base1 +
541 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
542 "aos-examples-Ping/"
543 "aos.message_bridge.RemoteMessage.part0.bfbs");
544 result.emplace_back(logfile_base1 +
545 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
546 "aos-examples-Ping/"
547 "aos.message_bridge.RemoteMessage.part1.bfbs");
548 }
549
550 return result;
551 }
552
553 std::vector<std::string> MakePi1RebootLogfiles() {
554 std::vector<std::string> result;
555 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
556 result.emplace_back(logfile_base1_ +
557 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
558 result.emplace_back(logfile_base1_ +
559 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
560 result.emplace_back(logfile_base1_ +
561 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
562 result.emplace_back(
563 logfile_base1_ +
564 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
565 result.emplace_back(
566 logfile_base1_ +
567 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
568 result.emplace_back(
569 logfile_base1_ +
570 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
571 result.emplace_back(
572 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
573 if (shared()) {
574 result.emplace_back(logfile_base1_ +
575 "_timestamps/pi1/aos/remote_timestamps/pi2/"
576 "aos.message_bridge.RemoteMessage.part0.bfbs");
577 result.emplace_back(logfile_base1_ +
578 "_timestamps/pi1/aos/remote_timestamps/pi2/"
579 "aos.message_bridge.RemoteMessage.part1.bfbs");
580 result.emplace_back(logfile_base1_ +
581 "_timestamps/pi1/aos/remote_timestamps/pi2/"
582 "aos.message_bridge.RemoteMessage.part2.bfbs");
583 } else {
584 result.emplace_back(logfile_base1_ +
585 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
586 "aos-message_bridge-Timestamp/"
587 "aos.message_bridge.RemoteMessage.part0.bfbs");
588 result.emplace_back(logfile_base1_ +
589 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
590 "aos-message_bridge-Timestamp/"
591 "aos.message_bridge.RemoteMessage.part1.bfbs");
592 result.emplace_back(logfile_base1_ +
593 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
594 "aos-message_bridge-Timestamp/"
595 "aos.message_bridge.RemoteMessage.part2.bfbs");
596
597 result.emplace_back(logfile_base1_ +
598 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
599 "aos-examples-Ping/"
600 "aos.message_bridge.RemoteMessage.part0.bfbs");
601 result.emplace_back(logfile_base1_ +
602 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
603 "aos-examples-Ping/"
604 "aos.message_bridge.RemoteMessage.part1.bfbs");
605 result.emplace_back(logfile_base1_ +
606 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
607 "aos-examples-Ping/"
608 "aos.message_bridge.RemoteMessage.part2.bfbs");
609 }
610 return result;
611 }
612
613 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
614 std::vector<std::string> result;
615 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
616 result.emplace_back(logfile_base1_ +
617 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
618 result.emplace_back(
619 logfile_base1_ +
620 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
621 result.emplace_back(
622 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
623
624 if (shared()) {
625 result.emplace_back(logfile_base1_ +
626 "_timestamps/pi1/aos/remote_timestamps/pi2/"
627 "aos.message_bridge.RemoteMessage.part0.bfbs");
628 } else {
629 result.emplace_back(logfile_base1_ +
630 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
631 "aos-message_bridge-Timestamp/"
632 "aos.message_bridge.RemoteMessage.part0.bfbs");
633 result.emplace_back(logfile_base1_ +
634 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
635 "aos-examples-Ping/"
636 "aos.message_bridge.RemoteMessage.part0.bfbs");
637 }
638 return result;
639 }
640
641 std::vector<std::vector<std::string>> StructureLogFiles() {
642 std::vector<std::vector<std::string>> result{
643 std::vector<std::string>{logfiles_[2]},
644 std::vector<std::string>{logfiles_[3], logfiles_[4]},
645 std::vector<std::string>{logfiles_[5]},
646 std::vector<std::string>{logfiles_[6], logfiles_[7]},
647 std::vector<std::string>{logfiles_[8], logfiles_[9]},
648 std::vector<std::string>{logfiles_[10], logfiles_[11]},
649 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
650
651 if (!shared()) {
652 result.emplace_back(
653 std::vector<std::string>{logfiles_[14], logfiles_[15]});
654 }
655
656 return result;
657 }
658
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700659 struct LoggerState {
660 std::unique_ptr<EventLoop> event_loop;
661 std::unique_ptr<Logger> logger;
662 };
663
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700664 LoggerState MakeLogger(const Node *node,
665 SimulatedEventLoopFactory *factory = nullptr) {
666 if (factory == nullptr) {
667 factory = &event_loop_factory_;
668 }
669 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700670 }
671
Austin Schuh3bd4c402020-11-06 18:19:06 -0800672 void StartLogger(LoggerState *logger, std::string logfile_base = "",
673 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700674 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800675 if (logger->event_loop->node()->name()->string_view() == "pi1") {
676 logfile_base = logfile_base1_;
677 } else {
678 logfile_base = logfile_base2_;
679 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700680 }
681
Brian Silverman1f345222020-09-24 21:14:48 -0700682 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
683 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800684 logger->logger->set_name(absl::StrCat(
685 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800686 logger->event_loop->OnRun([logger, logfile_base, compress]() {
687 std::unique_ptr<MultiNodeLogNamer> namer =
688 std::make_unique<MultiNodeLogNamer>(
689 logfile_base, logger->event_loop->configuration(),
690 logger->event_loop->node());
691 if (compress) {
692#ifdef LZMA
693 namer->set_extension(".xz");
694 namer->set_encoder_factory(
695 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
696#else
697 LOG(FATAL) << "Compression unsupported";
698#endif
699 }
700
701 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700702 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700703 }
Austin Schuh15649d62019-12-28 16:36:38 -0800704
Austin Schuh3bd4c402020-11-06 18:19:06 -0800705 void VerifyParts(const std::vector<LogFile> &sorted_parts,
706 const std::vector<std::string> &corrupted_parts = {}) {
707 EXPECT_EQ(sorted_parts.size(), 2u);
708
709 // Count up the number of UUIDs and make sure they are what we expect as a
710 // sanity check.
711 std::set<std::string> log_event_uuids;
712 std::set<std::string> parts_uuids;
713 std::set<std::string> both_uuids;
714
715 size_t missing_rt_count = 0;
716
717 std::vector<std::string> logger_nodes;
718 for (const LogFile &log_file : sorted_parts) {
719 EXPECT_FALSE(log_file.log_event_uuid.empty());
720 log_event_uuids.insert(log_file.log_event_uuid);
721 logger_nodes.emplace_back(log_file.logger_node);
722 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800723 EXPECT_TRUE(log_file.config);
724 EXPECT_EQ(log_file.name,
725 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800726
727 for (const LogParts &part : log_file.parts) {
728 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
729 << ": " << part;
730 missing_rt_count +=
731 part.realtime_start_time == aos::realtime_clock::min_time;
732
733 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
734 log_event_uuids.end());
735 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800736 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800737 parts_uuids.insert(part.parts_uuid);
738 both_uuids.insert(part.parts_uuid);
739 }
740 }
741
Austin Schuh61e973f2021-02-21 21:43:56 -0800742 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
743 // start time on remote nodes because we don't know it and would be
744 // guessing. And the log reader can actually do a better job. The number
745 // depends on if we have the remote timestamps split across 2 files, or just
746 // across 1, depending on if we are using a split or combined timestamp
747 // channel config.
748 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800749
750 EXPECT_EQ(log_event_uuids.size(), 2u);
751 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
752 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
753
754 // Test that each list of parts is in order. Don't worry about the ordering
755 // between part file lists though.
756 // (inner vectors all need to be in order, but outer one doesn't matter).
757 EXPECT_THAT(ToLogReaderVector(sorted_parts),
758 ::testing::UnorderedElementsAreArray(structured_logfiles_));
759
760 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
761
762 EXPECT_NE(sorted_parts[0].realtime_start_time,
763 aos::realtime_clock::min_time);
764 EXPECT_NE(sorted_parts[1].realtime_start_time,
765 aos::realtime_clock::min_time);
766
767 EXPECT_NE(sorted_parts[0].monotonic_start_time,
768 aos::monotonic_clock::min_time);
769 EXPECT_NE(sorted_parts[1].monotonic_start_time,
770 aos::monotonic_clock::min_time);
771
772 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
773 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
774 }
775
Austin Schuhc9049732020-12-21 22:27:15 -0800776 void ConfirmReadable(const std::vector<std::string> &files) {
777 LogReader reader(SortParts(files));
778
779 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
780 reader.Register(&log_reader_factory);
781
782 log_reader_factory.Run();
783
784 reader.Deregister();
785 }
786
Austin Schuh3bd4c402020-11-06 18:19:06 -0800787 void AddExtension(std::string_view extension) {
788 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
789 [extension](const std::string &in) {
790 return absl::StrCat(in, extension);
791 });
792
793 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
794 structured_logfiles_.begin(),
795 [extension](std::vector<std::string> in) {
796 std::transform(in.begin(), in.end(), in.begin(),
797 [extension](const std::string &in_str) {
798 return absl::StrCat(in_str, extension);
799 });
800 return in;
801 });
802 }
803
Austin Schuh15649d62019-12-28 16:36:38 -0800804 // Config and factory.
805 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800806 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800807 SimulatedEventLoopFactory event_loop_factory_;
808
Austin Schuh87dd3832021-01-01 23:07:31 -0800809 const Node *const pi1_;
810 const size_t pi1_index_;
811 const Node *const pi2_;
812 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700813
814 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800815 std::string logfile_base1_;
816 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800817 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700818 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800819 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700820
821 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700822
823 std::unique_ptr<EventLoop> ping_event_loop_;
824 Ping ping_;
825 std::unique_ptr<EventLoop> pong_event_loop_;
826 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800827};
828
Austin Schuh391e3172020-09-01 22:48:18 -0700829// Counts the number of messages on a channel. Returns (channel name, channel
830// type, count) for every message matching matcher()
831std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800832 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800833 std::function<bool(const MessageHeader *)> matcher) {
834 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800835 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800836
Austin Schuh6f3babe2020-01-26 20:34:50 -0800837 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800838 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800839 message_reader.ReadMessage();
840 if (!msg) {
841 break;
842 }
843
844 if (matcher(&msg.value().message())) {
845 counts[msg.value().message().channel_index()]++;
846 }
847 }
848
Austin Schuh391e3172020-09-01 22:48:18 -0700849 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800850 int channel = 0;
851 for (size_t i = 0; i < counts.size(); ++i) {
852 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800853 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700854 result.push_back(std::make_tuple(channel->name()->str(),
855 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800856 }
857 ++channel;
858 }
859
860 return result;
861}
862
863// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700864std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800865 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700866 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800867 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800868 if (msg->has_data()) {
869 CHECK(!msg->has_monotonic_remote_time());
870 CHECK(!msg->has_realtime_remote_time());
871 CHECK(!msg->has_remote_queue_index());
872 return true;
873 }
874 return false;
875 });
876}
877
878// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700879std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800880 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800881 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800882 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800883 if (!msg->has_data()) {
884 CHECK(msg->has_monotonic_remote_time());
885 CHECK(msg->has_realtime_remote_time());
886 CHECK(msg->has_remote_queue_index());
887 return true;
888 }
889 return false;
890 });
891}
892
Austin Schuhcde938c2020-02-02 17:30:07 -0800893// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800894TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800895 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800896 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700897 LoggerState pi1_logger = MakeLogger(pi1_);
898 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800899
900 event_loop_factory_.RunFor(chrono::milliseconds(95));
901
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700902 StartLogger(&pi1_logger);
903 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800904
Austin Schuh15649d62019-12-28 16:36:38 -0800905 event_loop_factory_.RunFor(chrono::milliseconds(20000));
906 }
907
Austin Schuh6f3babe2020-01-26 20:34:50 -0800908 {
Austin Schuh64fab802020-09-09 22:47:47 -0700909 std::set<std::string> logfile_uuids;
910 std::set<std::string> parts_uuids;
911 // Confirm that we have the expected number of UUIDs for both the logfile
912 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800913 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700914 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800915 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800916 if (!log_header.back().message().has_configuration()) {
917 logfile_uuids.insert(
918 log_header.back().message().log_event_uuid()->str());
919 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
920 }
Austin Schuh64fab802020-09-09 22:47:47 -0700921 }
Austin Schuh15649d62019-12-28 16:36:38 -0800922
Austin Schuh64fab802020-09-09 22:47:47 -0700923 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800924 if (shared()) {
925 EXPECT_EQ(parts_uuids.size(), 7u);
926 } else {
927 EXPECT_EQ(parts_uuids.size(), 8u);
928 }
Austin Schuh64fab802020-09-09 22:47:47 -0700929
930 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800931 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700932 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi2");
933 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
934 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
935 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi1");
936 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800937 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
938 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
Austin Schuh64fab802020-09-09 22:47:47 -0700939 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
940 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800941 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi1");
942 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi1");
943 if (!shared()) {
944 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
945 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
946 }
Austin Schuh64fab802020-09-09 22:47:47 -0700947
948 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800949 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuh64fab802020-09-09 22:47:47 -0700950 EXPECT_EQ(log_header[3].message().parts_index(), 0);
Austin Schuh61e973f2021-02-21 21:43:56 -0800951 EXPECT_EQ(log_header[4].message().parts_index(), 1);
952 EXPECT_EQ(log_header[5].message().parts_index(), 0);
Austin Schuh64fab802020-09-09 22:47:47 -0700953 EXPECT_EQ(log_header[6].message().parts_index(), 0);
954 EXPECT_EQ(log_header[7].message().parts_index(), 1);
955 EXPECT_EQ(log_header[8].message().parts_index(), 0);
956 EXPECT_EQ(log_header[9].message().parts_index(), 1);
957 EXPECT_EQ(log_header[10].message().parts_index(), 0);
958 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800959 EXPECT_EQ(log_header[12].message().parts_index(), 0);
960 EXPECT_EQ(log_header[13].message().parts_index(), 1);
961 if (!shared()) {
962 EXPECT_EQ(log_header[14].message().parts_index(), 0);
963 EXPECT_EQ(log_header[15].message().parts_index(), 1);
964 }
Austin Schuh64fab802020-09-09 22:47:47 -0700965 }
966
Austin Schuh8c399962020-12-25 21:51:45 -0800967 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700968 {
Austin Schuh391e3172020-09-01 22:48:18 -0700969 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800970 std::shared_ptr<const aos::Configuration> config =
971 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700972
Austin Schuh6f3babe2020-01-26 20:34:50 -0800973 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700974 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800975 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700976 UnorderedElementsAre(
977 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800978 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
979 21),
980 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
981 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700982 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800983 std::make_tuple("/test", "aos.examples.Ping", 2001)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800984 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800985 // Timestamps for pong
Austin Schuh2f8fd752020-09-01 22:38:28 -0700986 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800987 CountChannelsTimestamp(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700988 UnorderedElementsAre(
989 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800990 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800991 << " : " << logfiles_[2];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800992
993 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -0800994 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800995 CountChannelsData(config, logfiles_[3]),
Austin Schuh20ac95d2020-12-05 17:24:19 -0800996 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuh61e973f2021-02-21 21:43:56 -0800997 << " : " << logfiles_[3];
998 EXPECT_THAT(CountChannelsData(config, logfiles_[4]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700999 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001000 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001001 << " : " << logfiles_[3];
Austin Schuh391e3172020-09-01 22:48:18 -07001002
Austin Schuh6f3babe2020-01-26 20:34:50 -08001003 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001004 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh25b46712021-01-03 00:04:38 -08001005 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001006 << " : " << logfiles_[3];
1007 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001008 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001009 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001010
1011 // Timing reports and pongs.
Austin Schuh2f8fd752020-09-01 22:38:28 -07001012 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -08001013 CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001014 UnorderedElementsAre(
1015 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001016 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
1017 21),
1018 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1019 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001020 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001021 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001022 << " : " << logfiles_[5];
Austin Schuh61e973f2021-02-21 21:43:56 -08001023 // And ping timestamps.
Austin Schuh2f8fd752020-09-01 22:38:28 -07001024 EXPECT_THAT(
Austin Schuh8c399962020-12-25 21:51:45 -08001025 CountChannelsTimestamp(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001026 UnorderedElementsAre(
Austin Schuh61e973f2021-02-21 21:43:56 -08001027 std::make_tuple("/test", "aos.examples.Ping", 2001),
1028 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001029 << " : " << logfiles_[5];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001030
1031 // And then test that the remotely logged timestamp data files only have
1032 // timestamps in them.
Austin Schuh61e973f2021-02-21 21:43:56 -08001033 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1034 UnorderedElementsAre())
1035 << " : " << logfiles_[6];
1036 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
1037 UnorderedElementsAre())
1038 << " : " << logfiles_[7];
Austin Schuh25b46712021-01-03 00:04:38 -08001039 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1040 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001041 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001042 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1043 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001044 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001045
1046 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1047 UnorderedElementsAre(std::make_tuple(
1048 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1049 << " : " << logfiles_[6];
1050 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
1051 UnorderedElementsAre(std::make_tuple(
1052 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1053 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001054
Austin Schuh8c399962020-12-25 21:51:45 -08001055 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001056 UnorderedElementsAre(std::make_tuple(
Austin Schuh61e973f2021-02-21 21:43:56 -08001057 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001058 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001059 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001060 UnorderedElementsAre(std::make_tuple(
Austin Schuh61e973f2021-02-21 21:43:56 -08001061 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001062 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001063
Austin Schuh61e973f2021-02-21 21:43:56 -08001064 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh8c399962020-12-25 21:51:45 -08001065 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001066 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001067 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001068 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001069 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001070 << " : " << logfiles_[11];
Austin Schuh61e973f2021-02-21 21:43:56 -08001071 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1072 UnorderedElementsAre())
1073 << " : " << logfiles_[12];
1074 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1075 UnorderedElementsAre())
1076 << " : " << logfiles_[13];
1077 if (!shared()) {
1078 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1079 UnorderedElementsAre())
1080 << " : " << logfiles_[14];
1081 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1082 UnorderedElementsAre())
1083 << " : " << logfiles_[15];
1084 }
1085
1086 if (shared()) {
1087 EXPECT_THAT(
1088 CountChannelsTimestamp(config, logfiles_[10]),
1089 UnorderedElementsAre(
1090 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1091 std::make_tuple("/test", "aos.examples.Ping", 91)))
1092 << " : " << logfiles_[10];
1093 EXPECT_THAT(
1094 CountChannelsTimestamp(config, logfiles_[11]),
1095 UnorderedElementsAre(
1096 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1097 std::make_tuple("/test", "aos.examples.Ping", 1910)))
1098 << " : " << logfiles_[11];
1099 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1100 UnorderedElementsAre(std::make_tuple(
1101 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1102 << " : " << logfiles_[12];
1103 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1104 UnorderedElementsAre(std::make_tuple(
1105 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1106 << " : " << logfiles_[13];
1107 } else {
1108 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1109 UnorderedElementsAre(std::make_tuple(
1110 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1111 << " : " << logfiles_[10];
1112 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1113 UnorderedElementsAre(std::make_tuple(
1114 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1115 << " : " << logfiles_[11];
1116 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1117 UnorderedElementsAre(std::make_tuple(
1118 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1119 << " : " << logfiles_[12];
1120 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1121 UnorderedElementsAre(std::make_tuple(
1122 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1123 << " : " << logfiles_[13];
1124 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1125 UnorderedElementsAre(
1126 std::make_tuple("/test", "aos.examples.Ping", 91)))
1127 << " : " << logfiles_[14];
1128 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1129 UnorderedElementsAre(
1130 std::make_tuple("/test", "aos.examples.Ping", 1910)))
1131 << " : " << logfiles_[15];
1132 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001133 }
1134
Austin Schuh8c399962020-12-25 21:51:45 -08001135 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001136
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001137 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001138 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001139
1140 // This sends out the fetched messages and advances time to the start of the
1141 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001142 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001143
Austin Schuhac0771c2020-01-07 18:36:30 -08001144 const Node *pi1 =
1145 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001146 const Node *pi2 =
1147 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001148
Austin Schuh2f8fd752020-09-01 22:38:28 -07001149 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1150 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1151 LOG(INFO) << "now pi1 "
1152 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1153 LOG(INFO) << "now pi2 "
1154 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1155
Austin Schuh07676622021-01-21 18:59:17 -08001156 EXPECT_THAT(reader.LoggedNodes(),
1157 ::testing::ElementsAre(
1158 configuration::GetNode(reader.logged_configuration(), pi1),
1159 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001160
1161 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001162
Austin Schuh6f3babe2020-01-26 20:34:50 -08001163 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001164 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001165 std::unique_ptr<EventLoop> pi2_event_loop =
1166 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001167
Austin Schuh6f3babe2020-01-26 20:34:50 -08001168 int pi1_ping_count = 10;
1169 int pi2_ping_count = 10;
1170 int pi1_pong_count = 10;
1171 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001172
1173 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001174 pi1_event_loop->MakeWatcher(
1175 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001176 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001177 << pi1_event_loop->context().monotonic_remote_time << " -> "
1178 << pi1_event_loop->context().monotonic_event_time;
1179 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1180 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1181 pi1_ping_count * chrono::milliseconds(10) +
1182 monotonic_clock::epoch());
1183 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1184 pi1_ping_count * chrono::milliseconds(10) +
1185 realtime_clock::epoch());
1186 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1187 pi1_event_loop->context().monotonic_event_time);
1188 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1189 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001190
Austin Schuh6f3babe2020-01-26 20:34:50 -08001191 ++pi1_ping_count;
1192 });
1193 pi2_event_loop->MakeWatcher(
1194 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001195 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001196 << pi2_event_loop->context().monotonic_remote_time << " -> "
1197 << pi2_event_loop->context().monotonic_event_time;
1198 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1199
1200 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1201 pi2_ping_count * chrono::milliseconds(10) +
1202 monotonic_clock::epoch());
1203 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1204 pi2_ping_count * chrono::milliseconds(10) +
1205 realtime_clock::epoch());
1206 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1207 chrono::microseconds(150),
1208 pi2_event_loop->context().monotonic_event_time);
1209 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1210 chrono::microseconds(150),
1211 pi2_event_loop->context().realtime_event_time);
1212 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001213 });
1214
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001215 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001216 // Confirm that the ping and pong counts both match, and the value also
1217 // matches.
1218 pi1_event_loop->MakeWatcher(
1219 "/test", [&pi1_event_loop, &pi1_ping_count,
1220 &pi1_pong_count](const examples::Pong &pong) {
1221 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1222 << pi1_event_loop->context().monotonic_remote_time << " -> "
1223 << pi1_event_loop->context().monotonic_event_time;
1224
1225 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1226 pi1_pong_count + kQueueIndexOffset);
1227 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1228 chrono::microseconds(200) +
1229 pi1_pong_count * chrono::milliseconds(10) +
1230 monotonic_clock::epoch());
1231 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1232 chrono::microseconds(200) +
1233 pi1_pong_count * chrono::milliseconds(10) +
1234 realtime_clock::epoch());
1235
1236 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1237 chrono::microseconds(150),
1238 pi1_event_loop->context().monotonic_event_time);
1239 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1240 chrono::microseconds(150),
1241 pi1_event_loop->context().realtime_event_time);
1242
1243 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1244 ++pi1_pong_count;
1245 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1246 });
1247 pi2_event_loop->MakeWatcher(
1248 "/test", [&pi2_event_loop, &pi2_ping_count,
1249 &pi2_pong_count](const examples::Pong &pong) {
1250 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1251 << pi2_event_loop->context().monotonic_remote_time << " -> "
1252 << pi2_event_loop->context().monotonic_event_time;
1253
1254 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001255 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001256
1257 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1258 chrono::microseconds(200) +
1259 pi2_pong_count * chrono::milliseconds(10) +
1260 monotonic_clock::epoch());
1261 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1262 chrono::microseconds(200) +
1263 pi2_pong_count * chrono::milliseconds(10) +
1264 realtime_clock::epoch());
1265
1266 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1267 pi2_event_loop->context().monotonic_event_time);
1268 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1269 pi2_event_loop->context().realtime_event_time);
1270
1271 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1272 ++pi2_pong_count;
1273 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1274 });
1275
1276 log_reader_factory.Run();
1277 EXPECT_EQ(pi1_ping_count, 2010);
1278 EXPECT_EQ(pi2_ping_count, 2010);
1279 EXPECT_EQ(pi1_pong_count, 2010);
1280 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001281
1282 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001283}
1284
James Kuszmaul46d82582020-05-09 19:50:09 -07001285typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1286
1287// Test that if we feed the replay with a mismatched node list that we die on
1288// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001289TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001290 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001291 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001292 LoggerState pi1_logger = MakeLogger(pi1_);
1293 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001294
1295 event_loop_factory_.RunFor(chrono::milliseconds(95));
1296
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001297 StartLogger(&pi1_logger);
1298 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001299
James Kuszmaul46d82582020-05-09 19:50:09 -07001300 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1301 }
1302
1303 // Test that, if we add an additional node to the replay config that the
1304 // logger complains about the mismatch in number of nodes.
1305 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1306 configuration::MergeWithConfig(&config_.message(), R"({
1307 "nodes": [
1308 {
1309 "name": "extra-node"
1310 }
1311 ]
1312 }
1313 )");
1314
Austin Schuh287d43d2020-12-04 20:19:33 -08001315 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1316 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001317 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001318}
1319
Austin Schuhcde938c2020-02-02 17:30:07 -08001320// Tests that we can read log files where they don't start at the same monotonic
1321// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001322TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001323 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001324 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001325 LoggerState pi1_logger = MakeLogger(pi1_);
1326 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001327
1328 event_loop_factory_.RunFor(chrono::milliseconds(95));
1329
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001330 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001331
1332 event_loop_factory_.RunFor(chrono::milliseconds(200));
1333
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001334 StartLogger(&pi2_logger);
1335
Austin Schuhcde938c2020-02-02 17:30:07 -08001336 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1337 }
1338
Austin Schuh287d43d2020-12-04 20:19:33 -08001339 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001340
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001341 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001342 log_reader_factory.set_send_delay(chrono::microseconds(0));
1343
1344 // This sends out the fetched messages and advances time to the start of the
1345 // log file.
1346 reader.Register(&log_reader_factory);
1347
1348 const Node *pi1 =
1349 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1350 const Node *pi2 =
1351 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1352
Austin Schuh07676622021-01-21 18:59:17 -08001353 EXPECT_THAT(reader.LoggedNodes(),
1354 ::testing::ElementsAre(
1355 configuration::GetNode(reader.logged_configuration(), pi1),
1356 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001357
1358 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1359
1360 std::unique_ptr<EventLoop> pi1_event_loop =
1361 log_reader_factory.MakeEventLoop("test", pi1);
1362 std::unique_ptr<EventLoop> pi2_event_loop =
1363 log_reader_factory.MakeEventLoop("test", pi2);
1364
1365 int pi1_ping_count = 30;
1366 int pi2_ping_count = 30;
1367 int pi1_pong_count = 30;
1368 int pi2_pong_count = 30;
1369
1370 // Confirm that the ping value matches.
1371 pi1_event_loop->MakeWatcher(
1372 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1373 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1374 << pi1_event_loop->context().monotonic_remote_time << " -> "
1375 << pi1_event_loop->context().monotonic_event_time;
1376 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1377
1378 ++pi1_ping_count;
1379 });
1380 pi2_event_loop->MakeWatcher(
1381 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1382 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1383 << pi2_event_loop->context().monotonic_remote_time << " -> "
1384 << pi2_event_loop->context().monotonic_event_time;
1385 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1386
1387 ++pi2_ping_count;
1388 });
1389
1390 // Confirm that the ping and pong counts both match, and the value also
1391 // matches.
1392 pi1_event_loop->MakeWatcher(
1393 "/test", [&pi1_event_loop, &pi1_ping_count,
1394 &pi1_pong_count](const examples::Pong &pong) {
1395 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1396 << pi1_event_loop->context().monotonic_remote_time << " -> "
1397 << pi1_event_loop->context().monotonic_event_time;
1398
1399 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1400 ++pi1_pong_count;
1401 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1402 });
1403 pi2_event_loop->MakeWatcher(
1404 "/test", [&pi2_event_loop, &pi2_ping_count,
1405 &pi2_pong_count](const examples::Pong &pong) {
1406 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1407 << pi2_event_loop->context().monotonic_remote_time << " -> "
1408 << pi2_event_loop->context().monotonic_event_time;
1409
1410 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1411 ++pi2_pong_count;
1412 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1413 });
1414
1415 log_reader_factory.Run();
1416 EXPECT_EQ(pi1_ping_count, 2030);
1417 EXPECT_EQ(pi2_ping_count, 2030);
1418 EXPECT_EQ(pi1_pong_count, 2030);
1419 EXPECT_EQ(pi2_pong_count, 2030);
1420
1421 reader.Deregister();
1422}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001423
Austin Schuh8bd96322020-02-13 21:18:22 -08001424// Tests that we can read log files where the monotonic clocks drift and don't
1425// match correctly. While we are here, also test that different ending times
1426// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001427TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001428 // TODO(austin): Negate...
1429 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1430
1431 time_converter_.AddMonotonic({monotonic_clock::epoch(),
1432 monotonic_clock::epoch() + initial_pi2_offset});
1433 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1434 // skew to be 200 uS/s
1435 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1436 {chrono::milliseconds(95),
1437 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1438 // Run another 200 ms to have one logger start first.
1439 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1440 {chrono::milliseconds(200), chrono::milliseconds(200)});
1441 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1442 // go far enough to cause problems if this isn't accounted for.
1443 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1444 {chrono::milliseconds(20000),
1445 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1446 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1447 {chrono::milliseconds(40000),
1448 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1449 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1450 {chrono::milliseconds(400), chrono::milliseconds(400)});
1451
Austin Schuhcde938c2020-02-02 17:30:07 -08001452 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001453 LoggerState pi2_logger = MakeLogger(pi2_);
1454
Austin Schuh87dd3832021-01-01 23:07:31 -08001455 NodeEventLoopFactory *pi1 =
1456 event_loop_factory_.GetNodeEventLoopFactory(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001457 NodeEventLoopFactory *pi2 =
1458 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1459 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1460 << pi2->realtime_now() << " distributed "
1461 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001462
Austin Schuh8bd96322020-02-13 21:18:22 -08001463 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1464 << pi2->realtime_now() << " distributed "
1465 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001466
Austin Schuh87dd3832021-01-01 23:07:31 -08001467 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001468
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001469 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001470
Austin Schuh87dd3832021-01-01 23:07:31 -08001471 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001472
Austin Schuh8bd96322020-02-13 21:18:22 -08001473 {
1474 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001475 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001476
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001477 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001478 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001479
Austin Schuh87dd3832021-01-01 23:07:31 -08001480 // Make sure we slewed time far enough so that the difference is greater
1481 // than the network delay. This confirms that if we sort incorrectly, it
1482 // would show in the results.
1483 EXPECT_LT(
1484 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1485 -event_loop_factory_.send_delay() -
1486 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001487
Austin Schuh87dd3832021-01-01 23:07:31 -08001488 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001489
Austin Schuh87dd3832021-01-01 23:07:31 -08001490 // And now check that we went far enough the other way to make sure we
1491 // cover both problems.
1492 EXPECT_GT(
1493 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1494 event_loop_factory_.send_delay() +
1495 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001496 }
1497
1498 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001499 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001500 }
1501
Austin Schuh287d43d2020-12-04 20:19:33 -08001502 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001503
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001504 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001505 log_reader_factory.set_send_delay(chrono::microseconds(0));
1506
Austin Schuhcde938c2020-02-02 17:30:07 -08001507 const Node *pi1 =
1508 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1509 const Node *pi2 =
1510 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1511
Austin Schuh2f8fd752020-09-01 22:38:28 -07001512 // This sends out the fetched messages and advances time to the start of the
1513 // log file.
1514 reader.Register(&log_reader_factory);
1515
1516 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1517 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1518 LOG(INFO) << "now pi1 "
1519 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1520 LOG(INFO) << "now pi2 "
1521 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1522
Austin Schuhcde938c2020-02-02 17:30:07 -08001523 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001524 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1525 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001526 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1527 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001528 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1529 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001530 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1531
Austin Schuh07676622021-01-21 18:59:17 -08001532 EXPECT_THAT(reader.LoggedNodes(),
1533 ::testing::ElementsAre(
1534 configuration::GetNode(reader.logged_configuration(), pi1),
1535 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001536
1537 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1538
1539 std::unique_ptr<EventLoop> pi1_event_loop =
1540 log_reader_factory.MakeEventLoop("test", pi1);
1541 std::unique_ptr<EventLoop> pi2_event_loop =
1542 log_reader_factory.MakeEventLoop("test", pi2);
1543
1544 int pi1_ping_count = 30;
1545 int pi2_ping_count = 30;
1546 int pi1_pong_count = 30;
1547 int pi2_pong_count = 30;
1548
1549 // Confirm that the ping value matches.
1550 pi1_event_loop->MakeWatcher(
1551 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1552 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1553 << pi1_event_loop->context().monotonic_remote_time << " -> "
1554 << pi1_event_loop->context().monotonic_event_time;
1555 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1556
1557 ++pi1_ping_count;
1558 });
1559 pi2_event_loop->MakeWatcher(
1560 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1561 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1562 << pi2_event_loop->context().monotonic_remote_time << " -> "
1563 << pi2_event_loop->context().monotonic_event_time;
1564 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1565
1566 ++pi2_ping_count;
1567 });
1568
1569 // Confirm that the ping and pong counts both match, and the value also
1570 // matches.
1571 pi1_event_loop->MakeWatcher(
1572 "/test", [&pi1_event_loop, &pi1_ping_count,
1573 &pi1_pong_count](const examples::Pong &pong) {
1574 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1575 << pi1_event_loop->context().monotonic_remote_time << " -> "
1576 << pi1_event_loop->context().monotonic_event_time;
1577
1578 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1579 ++pi1_pong_count;
1580 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1581 });
1582 pi2_event_loop->MakeWatcher(
1583 "/test", [&pi2_event_loop, &pi2_ping_count,
1584 &pi2_pong_count](const examples::Pong &pong) {
1585 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1586 << pi2_event_loop->context().monotonic_remote_time << " -> "
1587 << pi2_event_loop->context().monotonic_event_time;
1588
1589 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1590 ++pi2_pong_count;
1591 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1592 });
1593
1594 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001595 EXPECT_EQ(pi1_ping_count, 6030);
1596 EXPECT_EQ(pi2_ping_count, 6030);
1597 EXPECT_EQ(pi1_pong_count, 6030);
1598 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001599
1600 reader.Deregister();
1601}
1602
Austin Schuh5212cad2020-09-09 23:12:09 -07001603// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001604TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001605 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001606 // Make a bunch of parts.
1607 {
1608 LoggerState pi1_logger = MakeLogger(pi1_);
1609 LoggerState pi2_logger = MakeLogger(pi2_);
1610
1611 event_loop_factory_.RunFor(chrono::milliseconds(95));
1612
1613 StartLogger(&pi1_logger);
1614 StartLogger(&pi2_logger);
1615
1616 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1617 }
1618
Austin Schuh11d43732020-09-21 17:28:30 -07001619 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001620 VerifyParts(sorted_parts);
1621}
Austin Schuh11d43732020-09-21 17:28:30 -07001622
Austin Schuh3bd4c402020-11-06 18:19:06 -08001623// Tests that we can sort a bunch of parts with an empty part. We should ignore
1624// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001625TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001626 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001627 // Make a bunch of parts.
1628 {
1629 LoggerState pi1_logger = MakeLogger(pi1_);
1630 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001631
Austin Schuh3bd4c402020-11-06 18:19:06 -08001632 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001633
Austin Schuh3bd4c402020-11-06 18:19:06 -08001634 StartLogger(&pi1_logger);
1635 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001636
Austin Schuh3bd4c402020-11-06 18:19:06 -08001637 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001638 }
1639
Austin Schuh3bd4c402020-11-06 18:19:06 -08001640 // TODO(austin): Should we flip out if the file can't open?
1641 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001642
Austin Schuh3bd4c402020-11-06 18:19:06 -08001643 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1644 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001645
Austin Schuh3bd4c402020-11-06 18:19:06 -08001646 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1647 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001648}
1649
Austin Schuh3bd4c402020-11-06 18:19:06 -08001650#ifdef LZMA
1651// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1652// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001653TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001654 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001655 // Make a bunch of parts.
1656 {
1657 LoggerState pi1_logger = MakeLogger(pi1_);
1658 LoggerState pi2_logger = MakeLogger(pi2_);
1659
1660 event_loop_factory_.RunFor(chrono::milliseconds(95));
1661
1662 StartLogger(&pi1_logger, "", true);
1663 StartLogger(&pi2_logger, "", true);
1664
1665 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1666 }
1667
1668 // TODO(austin): Should we flip out if the file can't open?
1669 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1670
1671 AddExtension(".xz");
1672
1673 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1674 logfiles_.emplace_back(kEmptyFile);
1675
1676 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1677 VerifyParts(sorted_parts, {kEmptyFile});
1678}
1679
1680// Tests that we can sort a bunch of parts with the end missing off a compressed
1681// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001682TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001683 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001684 // Make a bunch of parts.
1685 {
1686 LoggerState pi1_logger = MakeLogger(pi1_);
1687 LoggerState pi2_logger = MakeLogger(pi2_);
1688
1689 event_loop_factory_.RunFor(chrono::milliseconds(95));
1690
1691 StartLogger(&pi1_logger, "", true);
1692 StartLogger(&pi2_logger, "", true);
1693
1694 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1695 }
1696
1697 // Append everything with .xz.
1698 AddExtension(".xz");
1699
1700 // Strip off the end of one of the files. Pick one with a lot of data.
1701 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001702 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001703
1704 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001705 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001706 compressed_contents.substr(0, compressed_contents.size() - 100));
1707
1708 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1709 VerifyParts(sorted_parts);
1710}
1711#endif
1712
Austin Schuh01b4c352020-09-21 23:09:39 -07001713// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001714TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001715 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001716 {
1717 LoggerState pi1_logger = MakeLogger(pi1_);
1718 LoggerState pi2_logger = MakeLogger(pi2_);
1719
1720 event_loop_factory_.RunFor(chrono::milliseconds(95));
1721
1722 StartLogger(&pi1_logger);
1723 StartLogger(&pi2_logger);
1724
1725 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1726 }
1727
Austin Schuh287d43d2020-12-04 20:19:33 -08001728 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001729
1730 // Remap just on pi1.
1731 reader.RemapLoggedChannel<aos::timing::Report>(
1732 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1733
1734 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1735 log_reader_factory.set_send_delay(chrono::microseconds(0));
1736
1737 reader.Register(&log_reader_factory);
1738
1739 const Node *pi1 =
1740 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1741 const Node *pi2 =
1742 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1743
1744 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1745 // else should have moved.
1746 std::unique_ptr<EventLoop> pi1_event_loop =
1747 log_reader_factory.MakeEventLoop("test", pi1);
1748 pi1_event_loop->SkipTimingReport();
1749 std::unique_ptr<EventLoop> full_pi1_event_loop =
1750 log_reader_factory.MakeEventLoop("test", pi1);
1751 full_pi1_event_loop->SkipTimingReport();
1752 std::unique_ptr<EventLoop> pi2_event_loop =
1753 log_reader_factory.MakeEventLoop("test", pi2);
1754 pi2_event_loop->SkipTimingReport();
1755
1756 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1757 "/aos");
1758 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1759 full_pi1_event_loop.get(), "/pi1/aos");
1760 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1761 pi1_event_loop.get(), "/original/aos");
1762 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1763 full_pi1_event_loop.get(), "/original/pi1/aos");
1764 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1765 "/aos");
1766
1767 log_reader_factory.Run();
1768
1769 EXPECT_EQ(pi1_timing_report.count(), 0u);
1770 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1771 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1772 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1773 EXPECT_NE(pi2_timing_report.count(), 0u);
1774
1775 reader.Deregister();
1776}
1777
Austin Schuh006a9f52021-04-07 16:24:18 -07001778// Tests that we can remap a forwarded channel as well.
1779TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1780 time_converter_.StartEqual();
1781 {
1782 LoggerState pi1_logger = MakeLogger(pi1_);
1783 LoggerState pi2_logger = MakeLogger(pi2_);
1784
1785 event_loop_factory_.RunFor(chrono::milliseconds(95));
1786
1787 StartLogger(&pi1_logger);
1788 StartLogger(&pi2_logger);
1789
1790 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1791 }
1792
1793 LogReader reader(SortParts(logfiles_));
1794
1795 reader.RemapLoggedChannel<examples::Ping>("/test");
1796
1797 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1798 log_reader_factory.set_send_delay(chrono::microseconds(0));
1799
1800 reader.Register(&log_reader_factory);
1801
1802 const Node *pi1 =
1803 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1804 const Node *pi2 =
1805 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1806
1807 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1808 // else should have moved.
1809 std::unique_ptr<EventLoop> pi1_event_loop =
1810 log_reader_factory.MakeEventLoop("test", pi1);
1811 pi1_event_loop->SkipTimingReport();
1812 std::unique_ptr<EventLoop> full_pi1_event_loop =
1813 log_reader_factory.MakeEventLoop("test", pi1);
1814 full_pi1_event_loop->SkipTimingReport();
1815 std::unique_ptr<EventLoop> pi2_event_loop =
1816 log_reader_factory.MakeEventLoop("test", pi2);
1817 pi2_event_loop->SkipTimingReport();
1818
1819 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1820 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1821 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1822 "/original/test");
1823 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1824 "/original/test");
1825
1826 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1827 pi1_original_ping_timestamp;
1828 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1829 pi1_ping_timestamp;
1830 if (!shared()) {
1831 pi1_original_ping_timestamp =
1832 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1833 pi1_event_loop.get(),
1834 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1835 pi1_ping_timestamp =
1836 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1837 pi1_event_loop.get(),
1838 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1839 }
1840
1841 log_reader_factory.Run();
1842
1843 EXPECT_EQ(pi1_ping.count(), 0u);
1844 EXPECT_EQ(pi2_ping.count(), 0u);
1845 EXPECT_NE(pi1_original_ping.count(), 0u);
1846 EXPECT_NE(pi2_original_ping.count(), 0u);
1847 if (!shared()) {
1848 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1849 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1850 }
1851
1852 reader.Deregister();
1853}
1854
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001855// Tests that we properly recreate forwarded timestamps when replaying a log.
1856// This should be enough that we can then re-run the logger and get a valid log
1857// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001858TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001859 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001860 {
1861 LoggerState pi1_logger = MakeLogger(pi1_);
1862 LoggerState pi2_logger = MakeLogger(pi2_);
1863
1864 event_loop_factory_.RunFor(chrono::milliseconds(95));
1865
1866 StartLogger(&pi1_logger);
1867 StartLogger(&pi2_logger);
1868
1869 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1870 }
1871
Austin Schuh287d43d2020-12-04 20:19:33 -08001872 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001873
1874 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1875 log_reader_factory.set_send_delay(chrono::microseconds(0));
1876
1877 // This sends out the fetched messages and advances time to the start of the
1878 // log file.
1879 reader.Register(&log_reader_factory);
1880
1881 const Node *pi1 =
1882 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1883 const Node *pi2 =
1884 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1885
1886 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1887 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1888 LOG(INFO) << "now pi1 "
1889 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1890 LOG(INFO) << "now pi2 "
1891 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1892
Austin Schuh07676622021-01-21 18:59:17 -08001893 EXPECT_THAT(reader.LoggedNodes(),
1894 ::testing::ElementsAre(
1895 configuration::GetNode(reader.logged_configuration(), pi1),
1896 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001897
1898 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1899
1900 std::unique_ptr<EventLoop> pi1_event_loop =
1901 log_reader_factory.MakeEventLoop("test", pi1);
1902 std::unique_ptr<EventLoop> pi2_event_loop =
1903 log_reader_factory.MakeEventLoop("test", pi2);
1904
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001905 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1906 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1907 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1908 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1909
1910 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1911 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1912 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1913 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1914
1915 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1916 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1917 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1918 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1919
1920 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1921 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1922 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1923 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1924
1925 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1926 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1927 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1928 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1929
1930 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1931 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1932 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1933 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1934
Austin Schuh969cd602021-01-03 00:09:45 -08001935 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001936 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001937
Austin Schuh61e973f2021-02-21 21:43:56 -08001938 for (std::pair<int, std::string> channel :
1939 shared()
1940 ? std::vector<
1941 std::pair<int, std::string>>{{-1,
1942 "/aos/remote_timestamps/pi2"}}
1943 : std::vector<std::pair<int, std::string>>{
1944 {pi1_timestamp_channel,
1945 "/aos/remote_timestamps/pi2/pi1/aos/"
1946 "aos-message_bridge-Timestamp"},
1947 {ping_timestamp_channel,
1948 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1949 pi1_event_loop->MakeWatcher(
1950 channel.second,
1951 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1952 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1953 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1954 &ping_on_pi2_fetcher, network_delay, send_delay,
1955 channel_index = channel.first](const RemoteMessage &header) {
1956 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1957 chrono::nanoseconds(header.monotonic_sent_time()));
1958 const aos::realtime_clock::time_point header_realtime_sent_time(
1959 chrono::nanoseconds(header.realtime_sent_time()));
1960 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1961 chrono::nanoseconds(header.monotonic_remote_time()));
1962 const aos::realtime_clock::time_point header_realtime_remote_time(
1963 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001964
Austin Schuh61e973f2021-02-21 21:43:56 -08001965 if (channel_index != -1) {
1966 ASSERT_EQ(channel_index, header.channel_index());
1967 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001968
Austin Schuh61e973f2021-02-21 21:43:56 -08001969 const Context *pi1_context = nullptr;
1970 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001971
Austin Schuh61e973f2021-02-21 21:43:56 -08001972 if (header.channel_index() == pi1_timestamp_channel) {
1973 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1974 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1975 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1976 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1977 } else if (header.channel_index() == ping_timestamp_channel) {
1978 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
1979 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
1980 pi1_context = &ping_on_pi1_fetcher.context();
1981 pi2_context = &ping_on_pi2_fetcher.context();
1982 } else {
1983 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
1984 << configuration::CleanedChannelToString(
1985 pi1_event_loop->configuration()->channels()->Get(
1986 header.channel_index()));
1987 }
Austin Schuh315b96b2020-12-11 21:21:12 -08001988
Austin Schuh61e973f2021-02-21 21:43:56 -08001989 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07001990 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
1991 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001992
Austin Schuh61e973f2021-02-21 21:43:56 -08001993 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
1994 EXPECT_EQ(pi2_context->remote_queue_index,
1995 header.remote_queue_index());
1996 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001997
Austin Schuh61e973f2021-02-21 21:43:56 -08001998 EXPECT_EQ(pi2_context->monotonic_event_time,
1999 header_monotonic_sent_time);
2000 EXPECT_EQ(pi2_context->realtime_event_time,
2001 header_realtime_sent_time);
2002 EXPECT_EQ(pi2_context->realtime_remote_time,
2003 header_realtime_remote_time);
2004 EXPECT_EQ(pi2_context->monotonic_remote_time,
2005 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002006
Austin Schuh61e973f2021-02-21 21:43:56 -08002007 EXPECT_EQ(pi1_context->realtime_event_time,
2008 header_realtime_remote_time);
2009 EXPECT_EQ(pi1_context->monotonic_event_time,
2010 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002011
Austin Schuh61e973f2021-02-21 21:43:56 -08002012 // Time estimation isn't perfect, but we know the clocks were
2013 // identical when logged, so we know when this should have come back.
2014 // Confirm we got it when we expected.
2015 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2016 pi1_context->monotonic_event_time + 2 * network_delay +
2017 send_delay);
2018 });
2019 }
2020 for (std::pair<int, std::string> channel :
2021 shared()
2022 ? std::vector<
2023 std::pair<int, std::string>>{{-1,
2024 "/aos/remote_timestamps/pi1"}}
2025 : std::vector<std::pair<int, std::string>>{
2026 {pi2_timestamp_channel,
2027 "/aos/remote_timestamps/pi1/pi2/aos/"
2028 "aos-message_bridge-Timestamp"}}) {
2029 pi2_event_loop->MakeWatcher(
2030 channel.second,
2031 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2032 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2033 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2034 &pong_on_pi1_fetcher, network_delay, send_delay,
2035 channel_index = channel.first](const RemoteMessage &header) {
2036 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2037 chrono::nanoseconds(header.monotonic_sent_time()));
2038 const aos::realtime_clock::time_point header_realtime_sent_time(
2039 chrono::nanoseconds(header.realtime_sent_time()));
2040 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2041 chrono::nanoseconds(header.monotonic_remote_time()));
2042 const aos::realtime_clock::time_point header_realtime_remote_time(
2043 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002044
Austin Schuh61e973f2021-02-21 21:43:56 -08002045 if (channel_index != -1) {
2046 ASSERT_EQ(channel_index, header.channel_index());
2047 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002048
Austin Schuh61e973f2021-02-21 21:43:56 -08002049 const Context *pi2_context = nullptr;
2050 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002051
Austin Schuh61e973f2021-02-21 21:43:56 -08002052 if (header.channel_index() == pi2_timestamp_channel) {
2053 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2054 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2055 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2056 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2057 } else if (header.channel_index() == pong_timestamp_channel) {
2058 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2059 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2060 pi2_context = &pong_on_pi2_fetcher.context();
2061 pi1_context = &pong_on_pi1_fetcher.context();
2062 } else {
2063 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2064 << configuration::CleanedChannelToString(
2065 pi2_event_loop->configuration()->channels()->Get(
2066 header.channel_index()));
2067 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002068
Austin Schuh61e973f2021-02-21 21:43:56 -08002069 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002070 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2071 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002072
Austin Schuh61e973f2021-02-21 21:43:56 -08002073 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2074 EXPECT_EQ(pi1_context->remote_queue_index,
2075 header.remote_queue_index());
2076 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002077
Austin Schuh61e973f2021-02-21 21:43:56 -08002078 EXPECT_EQ(pi1_context->monotonic_event_time,
2079 header_monotonic_sent_time);
2080 EXPECT_EQ(pi1_context->realtime_event_time,
2081 header_realtime_sent_time);
2082 EXPECT_EQ(pi1_context->realtime_remote_time,
2083 header_realtime_remote_time);
2084 EXPECT_EQ(pi1_context->monotonic_remote_time,
2085 header_monotonic_remote_time);
2086
2087 EXPECT_EQ(pi2_context->realtime_event_time,
2088 header_realtime_remote_time);
2089 EXPECT_EQ(pi2_context->monotonic_event_time,
2090 header_monotonic_remote_time);
2091
2092 // Time estimation isn't perfect, but we know the clocks were
2093 // identical when logged, so we know when this should have come back.
2094 // Confirm we got it when we expected.
2095 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2096 pi2_context->monotonic_event_time + 2 * network_delay +
2097 send_delay);
2098 });
2099 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002100
2101 // And confirm we can re-create a log again, while checking the contents.
2102 {
2103 LoggerState pi1_logger = MakeLogger(
2104 configuration::GetNode(log_reader_factory.configuration(), pi1_),
2105 &log_reader_factory);
2106 LoggerState pi2_logger = MakeLogger(
2107 configuration::GetNode(log_reader_factory.configuration(), pi2_),
2108 &log_reader_factory);
2109
Austin Schuh25b46712021-01-03 00:04:38 -08002110 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2111 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002112
2113 log_reader_factory.Run();
2114 }
2115
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002116 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002117
2118 // And verify that we can run the LogReader over the relogged files without
2119 // hitting any fatal errors.
2120 {
2121 LogReader relogged_reader(SortParts(
2122 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2123 relogged_reader.Register();
2124
2125 relogged_reader.event_loop_factory()->Run();
2126 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002127}
2128
Austin Schuh315b96b2020-12-11 21:21:12 -08002129// Tests that we properly populate and extract the logger_start time by setting
2130// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002131TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002132 time_converter_.AddMonotonic(
2133 {monotonic_clock::epoch(),
2134 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002135 {
2136 LoggerState pi1_logger = MakeLogger(pi1_);
2137 LoggerState pi2_logger = MakeLogger(pi2_);
2138
Austin Schuh315b96b2020-12-11 21:21:12 -08002139 StartLogger(&pi1_logger);
2140 StartLogger(&pi2_logger);
2141
2142 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2143 }
2144
2145 for (const LogFile &log_file : SortParts(logfiles_)) {
2146 for (const LogParts &log_part : log_file.parts) {
2147 if (log_part.node == log_file.logger_node) {
2148 EXPECT_EQ(log_part.logger_monotonic_start_time,
2149 aos::monotonic_clock::min_time);
2150 EXPECT_EQ(log_part.logger_realtime_start_time,
2151 aos::realtime_clock::min_time);
2152 } else {
2153 const chrono::seconds offset = log_file.logger_node == "pi1"
2154 ? -chrono::seconds(1000)
2155 : chrono::seconds(1000);
2156 EXPECT_EQ(log_part.logger_monotonic_start_time,
2157 log_part.monotonic_start_time + offset);
2158 EXPECT_EQ(log_part.logger_realtime_start_time,
2159 log_file.realtime_start_time +
2160 (log_part.logger_monotonic_start_time -
2161 log_file.monotonic_start_time));
2162 }
2163 }
2164 }
2165}
2166
Austin Schuh6bb8a822021-03-31 23:04:39 -07002167// Test that renaming the base, renames the folder.
2168TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002169 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2170 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002171 time_converter_.AddMonotonic(
2172 {monotonic_clock::epoch(),
2173 monotonic_clock::epoch() + chrono::seconds(1000)});
2174 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2175 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2176 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2177 LoggerState pi1_logger = MakeLogger(pi1_);
2178 LoggerState pi2_logger = MakeLogger(pi2_);
2179
2180 StartLogger(&pi1_logger);
2181 StartLogger(&pi2_logger);
2182
2183 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2184 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2185 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2186 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2187 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2188 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2189 for (auto &file : logfiles_) {
2190 struct stat s;
2191 EXPECT_EQ(0, stat(file.c_str(), &s));
2192 }
2193}
2194
2195// Test that renaming the file base dies.
2196TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2197 time_converter_.AddMonotonic(
2198 {monotonic_clock::epoch(),
2199 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002200 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002201 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2202 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2203 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2204 LoggerState pi1_logger = MakeLogger(pi1_);
2205 StartLogger(&pi1_logger);
2206 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2207 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2208 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2209 "Rename of file base from");
2210}
2211
Austin Schuh8bd96322020-02-13 21:18:22 -08002212// TODO(austin): We can write a test which recreates a logfile and confirms that
2213// we get it back. That is the ultimate test.
2214
Austin Schuh315b96b2020-12-11 21:21:12 -08002215// Tests that we properly recreate forwarded timestamps when replaying a log.
2216// This should be enough that we can then re-run the logger and get a valid log
2217// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002218TEST_P(MultinodeLoggerDeathTest, RemoteReboot) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002219 time_converter_.StartEqual();
Austin Schuh315b96b2020-12-11 21:21:12 -08002220 std::string pi2_boot1;
2221 std::string pi2_boot2;
2222 {
2223 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2224 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002225 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002226 LoggerState pi1_logger = MakeLogger(pi1_);
2227
2228 event_loop_factory_.RunFor(chrono::milliseconds(95));
2229
2230 StartLogger(&pi1_logger);
2231
2232 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2233
2234 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
2235
2236 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2237 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002238 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002239
2240 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2241 }
2242
2243 // Confirm that we refuse to replay logs with missing boot uuids.
2244 EXPECT_DEATH(
2245 {
2246 LogReader reader(SortParts(pi1_reboot_logfiles_));
2247
2248 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2249 log_reader_factory.set_send_delay(chrono::microseconds(0));
2250
2251 // This sends out the fetched messages and advances time to the start of
2252 // the log file.
2253 reader.Register(&log_reader_factory);
2254 },
2255 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
2256 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
2257}
2258
Austin Schuhc9049732020-12-21 22:27:15 -08002259// Tests that we properly handle one direction of message_bridge being
2260// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002261TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002262 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002263 time_converter_.AddMonotonic(
2264 {monotonic_clock::epoch(),
2265 monotonic_clock::epoch() + chrono::seconds(1000)});
2266
2267 time_converter_.AddMonotonic(
2268 {chrono::milliseconds(10000),
2269 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002270 {
2271 LoggerState pi1_logger = MakeLogger(pi1_);
2272
2273 event_loop_factory_.RunFor(chrono::milliseconds(95));
2274
2275 StartLogger(&pi1_logger);
2276
2277 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2278 }
2279
2280 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2281 // to confirm the right thing happened.
2282 ConfirmReadable(pi1_single_direction_logfiles_);
2283}
2284
2285// Tests that we properly handle one direction of message_bridge being
2286// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002287TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002288 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002289 time_converter_.AddMonotonic(
2290 {monotonic_clock::epoch(),
2291 monotonic_clock::epoch() + chrono::seconds(500)});
2292
2293 time_converter_.AddMonotonic(
2294 {chrono::milliseconds(10000),
2295 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2296 {
2297 LoggerState pi1_logger = MakeLogger(pi1_);
2298
2299 event_loop_factory_.RunFor(chrono::milliseconds(95));
2300
2301 StartLogger(&pi1_logger);
2302
2303 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2304 }
2305
2306 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2307 // to confirm the right thing happened.
2308 ConfirmReadable(pi1_single_direction_logfiles_);
2309}
2310
2311// Tests that we properly handle a dead node. Do this by just disconnecting it
2312// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002313TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002314 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
2315 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
2316 time_converter_.AddMonotonic(
2317 {monotonic_clock::epoch(),
2318 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002319 {
2320 LoggerState pi1_logger = MakeLogger(pi1_);
2321
2322 event_loop_factory_.RunFor(chrono::milliseconds(95));
2323
2324 StartLogger(&pi1_logger);
2325
2326 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2327 }
2328
2329 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2330 // to confirm the right thing happened.
2331 ConfirmReadable(pi1_single_direction_logfiles_);
2332}
2333
Austin Schuhcdd90272021-03-15 12:46:16 -07002334constexpr std::string_view kCombinedConfigSha1(
milind945708b2021-07-03 13:30:15 -07002335 "4503751edc96327493562f0376f0d6daac172927c0fd64d04ce5d67505186c0b");
Austin Schuhcdd90272021-03-15 12:46:16 -07002336constexpr std::string_view kSplitConfigSha1(
milind945708b2021-07-03 13:30:15 -07002337 "918a748432c5e70a971dfd8934968378bed04ab61cf2efcd35b7f6224053c247");
Austin Schuhcdd90272021-03-15 12:46:16 -07002338
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002339INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002340 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002341 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2342 kCombinedConfigSha1},
2343 Param{"multinode_pingpong_split_config.json", false,
2344 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002345
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002346INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002347 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002348 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2349 kCombinedConfigSha1},
2350 Param{"multinode_pingpong_split_config.json", false,
2351 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002352
Austin Schuha04efed2021-01-24 18:04:20 -08002353// TODO(austin): Make a log file where the remote node has no start time.
2354
Austin Schuhe309d2a2019-11-29 13:25:21 -08002355} // namespace testing
2356} // namespace logger
2357} // namespace aos