blob: a02f4ea8e5ee473e55485202472c0a6a0b950e5d [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,
Austin Schuhe46492f2021-07-31 19:49:41 -0700486 std::string logfile_base2,
487 size_t pi1_data_count = 2,
488 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800489 std::vector<std::string> result;
490 result.emplace_back(
491 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
492 result.emplace_back(
493 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
Austin Schuhe46492f2021-07-31 19:49:41 -0700494 for (size_t i = 0; i < pi1_data_count; ++i) {
495 result.emplace_back(
496 absl::StrCat(logfile_base1, "_pi1_data.part", i, ".bfbs"));
497 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800498 result.emplace_back(logfile_base1 +
499 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
500 result.emplace_back(logfile_base1 +
501 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700502 for (size_t i = 0; i < pi2_data_count; ++i) {
503 result.emplace_back(
504 absl::StrCat(logfile_base2, "_pi2_data.part", i, ".bfbs"));
505 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800506 result.emplace_back(
507 logfile_base2 +
508 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
509 result.emplace_back(
510 logfile_base2 +
511 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
512 result.emplace_back(
513 logfile_base1 +
514 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
515 result.emplace_back(
516 logfile_base1 +
517 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
518 if (shared()) {
519 result.emplace_back(logfile_base1 +
520 "_timestamps/pi1/aos/remote_timestamps/pi2/"
521 "aos.message_bridge.RemoteMessage.part0.bfbs");
522 result.emplace_back(logfile_base1 +
523 "_timestamps/pi1/aos/remote_timestamps/pi2/"
524 "aos.message_bridge.RemoteMessage.part1.bfbs");
525 result.emplace_back(logfile_base2 +
526 "_timestamps/pi2/aos/remote_timestamps/pi1/"
527 "aos.message_bridge.RemoteMessage.part0.bfbs");
528 result.emplace_back(logfile_base2 +
529 "_timestamps/pi2/aos/remote_timestamps/pi1/"
530 "aos.message_bridge.RemoteMessage.part1.bfbs");
531 } else {
532 result.emplace_back(logfile_base1 +
533 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
534 "aos-message_bridge-Timestamp/"
535 "aos.message_bridge.RemoteMessage.part0.bfbs");
536 result.emplace_back(logfile_base1 +
537 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
538 "aos-message_bridge-Timestamp/"
539 "aos.message_bridge.RemoteMessage.part1.bfbs");
540 result.emplace_back(logfile_base2 +
541 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
542 "aos-message_bridge-Timestamp/"
543 "aos.message_bridge.RemoteMessage.part0.bfbs");
544 result.emplace_back(logfile_base2 +
545 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
546 "aos-message_bridge-Timestamp/"
547 "aos.message_bridge.RemoteMessage.part1.bfbs");
548 result.emplace_back(logfile_base1 +
549 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
550 "aos-examples-Ping/"
551 "aos.message_bridge.RemoteMessage.part0.bfbs");
552 result.emplace_back(logfile_base1 +
553 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
554 "aos-examples-Ping/"
555 "aos.message_bridge.RemoteMessage.part1.bfbs");
556 }
557
558 return result;
559 }
560
561 std::vector<std::string> MakePi1RebootLogfiles() {
562 std::vector<std::string> result;
563 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700564 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
565 result.emplace_back(logfile_base1_ + "_pi1_data.part2.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800566 result.emplace_back(logfile_base1_ +
567 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
568 result.emplace_back(logfile_base1_ +
569 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
570 result.emplace_back(logfile_base1_ +
571 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
572 result.emplace_back(
573 logfile_base1_ +
574 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
575 result.emplace_back(
576 logfile_base1_ +
577 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
578 result.emplace_back(
579 logfile_base1_ +
580 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
581 result.emplace_back(
582 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
583 if (shared()) {
584 result.emplace_back(logfile_base1_ +
585 "_timestamps/pi1/aos/remote_timestamps/pi2/"
586 "aos.message_bridge.RemoteMessage.part0.bfbs");
587 result.emplace_back(logfile_base1_ +
588 "_timestamps/pi1/aos/remote_timestamps/pi2/"
589 "aos.message_bridge.RemoteMessage.part1.bfbs");
590 result.emplace_back(logfile_base1_ +
591 "_timestamps/pi1/aos/remote_timestamps/pi2/"
592 "aos.message_bridge.RemoteMessage.part2.bfbs");
593 } else {
594 result.emplace_back(logfile_base1_ +
595 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
596 "aos-message_bridge-Timestamp/"
597 "aos.message_bridge.RemoteMessage.part0.bfbs");
598 result.emplace_back(logfile_base1_ +
599 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
600 "aos-message_bridge-Timestamp/"
601 "aos.message_bridge.RemoteMessage.part1.bfbs");
602 result.emplace_back(logfile_base1_ +
603 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
604 "aos-message_bridge-Timestamp/"
605 "aos.message_bridge.RemoteMessage.part2.bfbs");
606
607 result.emplace_back(logfile_base1_ +
608 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
609 "aos-examples-Ping/"
610 "aos.message_bridge.RemoteMessage.part0.bfbs");
611 result.emplace_back(logfile_base1_ +
612 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
613 "aos-examples-Ping/"
614 "aos.message_bridge.RemoteMessage.part1.bfbs");
615 result.emplace_back(logfile_base1_ +
616 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
617 "aos-examples-Ping/"
618 "aos.message_bridge.RemoteMessage.part2.bfbs");
619 }
620 return result;
621 }
622
623 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
624 std::vector<std::string> result;
625 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
626 result.emplace_back(logfile_base1_ +
627 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
628 result.emplace_back(
629 logfile_base1_ +
630 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
631 result.emplace_back(
632 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
633
634 if (shared()) {
635 result.emplace_back(logfile_base1_ +
636 "_timestamps/pi1/aos/remote_timestamps/pi2/"
637 "aos.message_bridge.RemoteMessage.part0.bfbs");
638 } else {
639 result.emplace_back(logfile_base1_ +
640 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
641 "aos-message_bridge-Timestamp/"
642 "aos.message_bridge.RemoteMessage.part0.bfbs");
643 result.emplace_back(logfile_base1_ +
644 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
645 "aos-examples-Ping/"
646 "aos.message_bridge.RemoteMessage.part0.bfbs");
647 }
648 return result;
649 }
650
651 std::vector<std::vector<std::string>> StructureLogFiles() {
652 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700653 std::vector<std::string>{logfiles_[2], logfiles_[3]},
654 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800655 std::vector<std::string>{logfiles_[6], logfiles_[7]},
656 std::vector<std::string>{logfiles_[8], logfiles_[9]},
657 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700658 std::vector<std::string>{logfiles_[12], logfiles_[13]},
659 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800660
661 if (!shared()) {
662 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700663 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800664 }
665
666 return result;
667 }
668
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700669 struct LoggerState {
670 std::unique_ptr<EventLoop> event_loop;
671 std::unique_ptr<Logger> logger;
672 };
673
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700674 LoggerState MakeLogger(const Node *node,
675 SimulatedEventLoopFactory *factory = nullptr) {
676 if (factory == nullptr) {
677 factory = &event_loop_factory_;
678 }
679 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700680 }
681
Austin Schuh3bd4c402020-11-06 18:19:06 -0800682 void StartLogger(LoggerState *logger, std::string logfile_base = "",
683 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700684 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800685 if (logger->event_loop->node()->name()->string_view() == "pi1") {
686 logfile_base = logfile_base1_;
687 } else {
688 logfile_base = logfile_base2_;
689 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700690 }
691
Brian Silverman1f345222020-09-24 21:14:48 -0700692 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
693 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800694 logger->logger->set_name(absl::StrCat(
695 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800696 logger->event_loop->OnRun([logger, logfile_base, compress]() {
697 std::unique_ptr<MultiNodeLogNamer> namer =
698 std::make_unique<MultiNodeLogNamer>(
699 logfile_base, logger->event_loop->configuration(),
700 logger->event_loop->node());
701 if (compress) {
702#ifdef LZMA
703 namer->set_extension(".xz");
704 namer->set_encoder_factory(
705 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
706#else
707 LOG(FATAL) << "Compression unsupported";
708#endif
709 }
710
711 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700712 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700713 }
Austin Schuh15649d62019-12-28 16:36:38 -0800714
Austin Schuh3bd4c402020-11-06 18:19:06 -0800715 void VerifyParts(const std::vector<LogFile> &sorted_parts,
716 const std::vector<std::string> &corrupted_parts = {}) {
717 EXPECT_EQ(sorted_parts.size(), 2u);
718
719 // Count up the number of UUIDs and make sure they are what we expect as a
720 // sanity check.
721 std::set<std::string> log_event_uuids;
722 std::set<std::string> parts_uuids;
723 std::set<std::string> both_uuids;
724
725 size_t missing_rt_count = 0;
726
727 std::vector<std::string> logger_nodes;
728 for (const LogFile &log_file : sorted_parts) {
729 EXPECT_FALSE(log_file.log_event_uuid.empty());
730 log_event_uuids.insert(log_file.log_event_uuid);
731 logger_nodes.emplace_back(log_file.logger_node);
732 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800733 EXPECT_TRUE(log_file.config);
734 EXPECT_EQ(log_file.name,
735 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800736
737 for (const LogParts &part : log_file.parts) {
738 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
739 << ": " << part;
740 missing_rt_count +=
741 part.realtime_start_time == aos::realtime_clock::min_time;
742
743 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
744 log_event_uuids.end());
745 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800746 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800747 parts_uuids.insert(part.parts_uuid);
748 both_uuids.insert(part.parts_uuid);
749 }
750 }
751
Austin Schuh61e973f2021-02-21 21:43:56 -0800752 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
753 // start time on remote nodes because we don't know it and would be
754 // guessing. And the log reader can actually do a better job. The number
755 // depends on if we have the remote timestamps split across 2 files, or just
756 // across 1, depending on if we are using a split or combined timestamp
757 // channel config.
758 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800759
760 EXPECT_EQ(log_event_uuids.size(), 2u);
761 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
762 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
763
764 // Test that each list of parts is in order. Don't worry about the ordering
765 // between part file lists though.
766 // (inner vectors all need to be in order, but outer one doesn't matter).
767 EXPECT_THAT(ToLogReaderVector(sorted_parts),
768 ::testing::UnorderedElementsAreArray(structured_logfiles_));
769
770 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
771
772 EXPECT_NE(sorted_parts[0].realtime_start_time,
773 aos::realtime_clock::min_time);
774 EXPECT_NE(sorted_parts[1].realtime_start_time,
775 aos::realtime_clock::min_time);
776
777 EXPECT_NE(sorted_parts[0].monotonic_start_time,
778 aos::monotonic_clock::min_time);
779 EXPECT_NE(sorted_parts[1].monotonic_start_time,
780 aos::monotonic_clock::min_time);
781
782 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
783 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
784 }
785
Austin Schuhc9049732020-12-21 22:27:15 -0800786 void ConfirmReadable(const std::vector<std::string> &files) {
787 LogReader reader(SortParts(files));
788
789 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
790 reader.Register(&log_reader_factory);
791
792 log_reader_factory.Run();
793
794 reader.Deregister();
795 }
796
Austin Schuh3bd4c402020-11-06 18:19:06 -0800797 void AddExtension(std::string_view extension) {
798 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
799 [extension](const std::string &in) {
800 return absl::StrCat(in, extension);
801 });
802
803 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
804 structured_logfiles_.begin(),
805 [extension](std::vector<std::string> in) {
806 std::transform(in.begin(), in.end(), in.begin(),
807 [extension](const std::string &in_str) {
808 return absl::StrCat(in_str, extension);
809 });
810 return in;
811 });
812 }
813
Austin Schuh15649d62019-12-28 16:36:38 -0800814 // Config and factory.
815 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800816 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800817 SimulatedEventLoopFactory event_loop_factory_;
818
Austin Schuh87dd3832021-01-01 23:07:31 -0800819 const Node *const pi1_;
820 const size_t pi1_index_;
821 const Node *const pi2_;
822 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700823
824 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800825 std::string logfile_base1_;
826 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800827 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700828 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800829 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700830
831 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700832
833 std::unique_ptr<EventLoop> ping_event_loop_;
834 Ping ping_;
835 std::unique_ptr<EventLoop> pong_event_loop_;
836 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800837};
838
Austin Schuh391e3172020-09-01 22:48:18 -0700839// Counts the number of messages on a channel. Returns (channel name, channel
840// type, count) for every message matching matcher()
841std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800842 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800843 std::function<bool(const MessageHeader *)> matcher) {
844 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800845 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800846
Austin Schuh6f3babe2020-01-26 20:34:50 -0800847 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800848 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800849 message_reader.ReadMessage();
850 if (!msg) {
851 break;
852 }
853
854 if (matcher(&msg.value().message())) {
855 counts[msg.value().message().channel_index()]++;
856 }
857 }
858
Austin Schuh391e3172020-09-01 22:48:18 -0700859 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800860 int channel = 0;
861 for (size_t i = 0; i < counts.size(); ++i) {
862 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800863 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700864 result.push_back(std::make_tuple(channel->name()->str(),
865 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800866 }
867 ++channel;
868 }
869
870 return result;
871}
872
873// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700874std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800875 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700876 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800877 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800878 if (msg->has_data()) {
879 CHECK(!msg->has_monotonic_remote_time());
880 CHECK(!msg->has_realtime_remote_time());
881 CHECK(!msg->has_remote_queue_index());
882 return true;
883 }
884 return false;
885 });
886}
887
888// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700889std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800890 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800891 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800892 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800893 if (!msg->has_data()) {
894 CHECK(msg->has_monotonic_remote_time());
895 CHECK(msg->has_realtime_remote_time());
896 CHECK(msg->has_remote_queue_index());
897 return true;
898 }
899 return false;
900 });
901}
902
Austin Schuhcde938c2020-02-02 17:30:07 -0800903// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800904TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800905 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800906 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700907 LoggerState pi1_logger = MakeLogger(pi1_);
908 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800909
910 event_loop_factory_.RunFor(chrono::milliseconds(95));
911
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700912 StartLogger(&pi1_logger);
913 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800914
Austin Schuh15649d62019-12-28 16:36:38 -0800915 event_loop_factory_.RunFor(chrono::milliseconds(20000));
916 }
917
Austin Schuh6f3babe2020-01-26 20:34:50 -0800918 {
Austin Schuh64fab802020-09-09 22:47:47 -0700919 std::set<std::string> logfile_uuids;
920 std::set<std::string> parts_uuids;
921 // Confirm that we have the expected number of UUIDs for both the logfile
922 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800923 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700924 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800925 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800926 if (!log_header.back().message().has_configuration()) {
927 logfile_uuids.insert(
928 log_header.back().message().log_event_uuid()->str());
929 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
930 }
Austin Schuh64fab802020-09-09 22:47:47 -0700931 }
Austin Schuh15649d62019-12-28 16:36:38 -0800932
Austin Schuh64fab802020-09-09 22:47:47 -0700933 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800934 if (shared()) {
935 EXPECT_EQ(parts_uuids.size(), 7u);
936 } else {
937 EXPECT_EQ(parts_uuids.size(), 8u);
938 }
Austin Schuh64fab802020-09-09 22:47:47 -0700939
940 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800941 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -0700942 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700943 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
944 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700945 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
946 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
947 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
948 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700949 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
950 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700951 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
952 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
953 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
954 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800955 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700956 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
957 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800958 }
Austin Schuh64fab802020-09-09 22:47:47 -0700959
960 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800961 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -0700962 EXPECT_EQ(log_header[3].message().parts_index(), 1);
963 EXPECT_EQ(log_header[4].message().parts_index(), 0);
964 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -0700965 EXPECT_EQ(log_header[6].message().parts_index(), 0);
966 EXPECT_EQ(log_header[7].message().parts_index(), 1);
967 EXPECT_EQ(log_header[8].message().parts_index(), 0);
968 EXPECT_EQ(log_header[9].message().parts_index(), 1);
969 EXPECT_EQ(log_header[10].message().parts_index(), 0);
970 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800971 EXPECT_EQ(log_header[12].message().parts_index(), 0);
972 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -0700973 EXPECT_EQ(log_header[14].message().parts_index(), 0);
974 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800975 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700976 EXPECT_EQ(log_header[16].message().parts_index(), 0);
977 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800978 }
Austin Schuh64fab802020-09-09 22:47:47 -0700979 }
980
Austin Schuh8c399962020-12-25 21:51:45 -0800981 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700982 {
Austin Schuh391e3172020-09-01 22:48:18 -0700983 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800984 std::shared_ptr<const aos::Configuration> config =
985 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700986
Austin Schuh6f3babe2020-01-26 20:34:50 -0800987 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700988 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800989 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700990 UnorderedElementsAre(
Austin Schuhe46492f2021-07-31 19:49:41 -0700991 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
992 1),
993 std::make_tuple("/test", "aos.examples.Ping", 1)))
994 << " : " << logfiles_[2];
995 EXPECT_THAT(
996 CountChannelsData(config, logfiles_[3]),
997 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -0700998 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800999 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001000 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001001 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1002 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001003 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001004 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1005 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001006 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001007 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1008 UnorderedElementsAre())
1009 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001010 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001011 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001012 UnorderedElementsAre(
1013 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001014 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001015 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001016
1017 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001018 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001019 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001020 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001021 << " : " << logfiles_[4];
1022 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001023 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001024 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001025 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001026
Austin Schuh6f3babe2020-01-26 20:34:50 -08001027 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001028 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001029 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001030 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001031 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1032 UnorderedElementsAre())
1033 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001034
1035 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001036 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1037 UnorderedElementsAre(std::make_tuple(
1038 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1039 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001040 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001041 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001042 UnorderedElementsAre(
1043 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001044 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001045 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001046 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1047 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001048 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001049 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001050 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001051 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001052 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1053 UnorderedElementsAre())
1054 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001055 EXPECT_THAT(
1056 CountChannelsTimestamp(config, logfiles_[7]),
1057 UnorderedElementsAre(
1058 std::make_tuple("/test", "aos.examples.Ping", 2001),
1059 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001060 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001061
1062 // And then test that the remotely logged timestamp data files only have
1063 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001064 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1065 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001066 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001067 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1068 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001069 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001070 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1071 UnorderedElementsAre())
1072 << " : " << logfiles_[10];
1073 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1074 UnorderedElementsAre())
1075 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001076
Austin Schuh8c399962020-12-25 21:51:45 -08001077 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001078 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001079 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001080 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001081 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001082 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001083 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001084 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001085
Austin Schuh8c399962020-12-25 21:51:45 -08001086 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001087 UnorderedElementsAre(std::make_tuple(
1088 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001089 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001090 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001091 UnorderedElementsAre(std::make_tuple(
1092 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001093 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001094
1095 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001096 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1097 UnorderedElementsAre())
1098 << " : " << logfiles_[12];
1099 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1100 UnorderedElementsAre())
1101 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001102 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1103 UnorderedElementsAre())
1104 << " : " << logfiles_[14];
1105 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1106 UnorderedElementsAre())
1107 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001108 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001109 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001110 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001111 << " : " << logfiles_[16];
1112 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001113 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001114 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001115 }
1116
1117 if (shared()) {
1118 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001119 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001120 UnorderedElementsAre(
1121 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1122 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001123 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001124 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001125 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001126 UnorderedElementsAre(
1127 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1128 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001129 << " : " << logfiles_[13];
1130 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001131 UnorderedElementsAre(std::make_tuple(
1132 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001133 << " : " << logfiles_[14];
1134 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001135 UnorderedElementsAre(std::make_tuple(
1136 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1137 << " : " << logfiles_[15];
1138 } else {
1139 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1140 UnorderedElementsAre(std::make_tuple(
1141 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1142 << " : " << logfiles_[12];
1143 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1144 UnorderedElementsAre(std::make_tuple(
1145 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1146 << " : " << logfiles_[13];
1147 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1148 UnorderedElementsAre(std::make_tuple(
1149 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1150 << " : " << logfiles_[14];
1151 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1152 UnorderedElementsAre(std::make_tuple(
1153 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1154 << " : " << logfiles_[15];
1155 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1156 UnorderedElementsAre(
1157 std::make_tuple("/test", "aos.examples.Ping", 91)))
1158 << " : " << logfiles_[16];
1159 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001160 UnorderedElementsAre(
1161 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001162 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001163 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001164 }
1165
Austin Schuh8c399962020-12-25 21:51:45 -08001166 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001167
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001168 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001169 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001170
1171 // This sends out the fetched messages and advances time to the start of the
1172 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001173 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001174
Austin Schuhac0771c2020-01-07 18:36:30 -08001175 const Node *pi1 =
1176 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001177 const Node *pi2 =
1178 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001179
Austin Schuh2f8fd752020-09-01 22:38:28 -07001180 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1181 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1182 LOG(INFO) << "now pi1 "
1183 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1184 LOG(INFO) << "now pi2 "
1185 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1186
Austin Schuh07676622021-01-21 18:59:17 -08001187 EXPECT_THAT(reader.LoggedNodes(),
1188 ::testing::ElementsAre(
1189 configuration::GetNode(reader.logged_configuration(), pi1),
1190 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001191
1192 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001193
Austin Schuh6f3babe2020-01-26 20:34:50 -08001194 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001195 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001196 std::unique_ptr<EventLoop> pi2_event_loop =
1197 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001198
Austin Schuh6f3babe2020-01-26 20:34:50 -08001199 int pi1_ping_count = 10;
1200 int pi2_ping_count = 10;
1201 int pi1_pong_count = 10;
1202 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001203
1204 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001205 pi1_event_loop->MakeWatcher(
1206 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001207 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001208 << pi1_event_loop->context().monotonic_remote_time << " -> "
1209 << pi1_event_loop->context().monotonic_event_time;
1210 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1211 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1212 pi1_ping_count * chrono::milliseconds(10) +
1213 monotonic_clock::epoch());
1214 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1215 pi1_ping_count * chrono::milliseconds(10) +
1216 realtime_clock::epoch());
1217 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1218 pi1_event_loop->context().monotonic_event_time);
1219 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1220 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001221
Austin Schuh6f3babe2020-01-26 20:34:50 -08001222 ++pi1_ping_count;
1223 });
1224 pi2_event_loop->MakeWatcher(
1225 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001226 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001227 << pi2_event_loop->context().monotonic_remote_time << " -> "
1228 << pi2_event_loop->context().monotonic_event_time;
1229 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1230
1231 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1232 pi2_ping_count * chrono::milliseconds(10) +
1233 monotonic_clock::epoch());
1234 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1235 pi2_ping_count * chrono::milliseconds(10) +
1236 realtime_clock::epoch());
1237 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1238 chrono::microseconds(150),
1239 pi2_event_loop->context().monotonic_event_time);
1240 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1241 chrono::microseconds(150),
1242 pi2_event_loop->context().realtime_event_time);
1243 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001244 });
1245
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001246 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001247 // Confirm that the ping and pong counts both match, and the value also
1248 // matches.
1249 pi1_event_loop->MakeWatcher(
1250 "/test", [&pi1_event_loop, &pi1_ping_count,
1251 &pi1_pong_count](const examples::Pong &pong) {
1252 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1253 << pi1_event_loop->context().monotonic_remote_time << " -> "
1254 << pi1_event_loop->context().monotonic_event_time;
1255
1256 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1257 pi1_pong_count + kQueueIndexOffset);
1258 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1259 chrono::microseconds(200) +
1260 pi1_pong_count * chrono::milliseconds(10) +
1261 monotonic_clock::epoch());
1262 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1263 chrono::microseconds(200) +
1264 pi1_pong_count * chrono::milliseconds(10) +
1265 realtime_clock::epoch());
1266
1267 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1268 chrono::microseconds(150),
1269 pi1_event_loop->context().monotonic_event_time);
1270 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1271 chrono::microseconds(150),
1272 pi1_event_loop->context().realtime_event_time);
1273
1274 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1275 ++pi1_pong_count;
1276 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1277 });
1278 pi2_event_loop->MakeWatcher(
1279 "/test", [&pi2_event_loop, &pi2_ping_count,
1280 &pi2_pong_count](const examples::Pong &pong) {
1281 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1282 << pi2_event_loop->context().monotonic_remote_time << " -> "
1283 << pi2_event_loop->context().monotonic_event_time;
1284
1285 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001286 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001287
1288 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1289 chrono::microseconds(200) +
1290 pi2_pong_count * chrono::milliseconds(10) +
1291 monotonic_clock::epoch());
1292 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1293 chrono::microseconds(200) +
1294 pi2_pong_count * chrono::milliseconds(10) +
1295 realtime_clock::epoch());
1296
1297 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1298 pi2_event_loop->context().monotonic_event_time);
1299 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1300 pi2_event_loop->context().realtime_event_time);
1301
1302 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1303 ++pi2_pong_count;
1304 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1305 });
1306
1307 log_reader_factory.Run();
1308 EXPECT_EQ(pi1_ping_count, 2010);
1309 EXPECT_EQ(pi2_ping_count, 2010);
1310 EXPECT_EQ(pi1_pong_count, 2010);
1311 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001312
1313 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001314}
1315
James Kuszmaul46d82582020-05-09 19:50:09 -07001316typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1317
1318// Test that if we feed the replay with a mismatched node list that we die on
1319// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001320TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001321 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001322 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001323 LoggerState pi1_logger = MakeLogger(pi1_);
1324 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001325
1326 event_loop_factory_.RunFor(chrono::milliseconds(95));
1327
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001328 StartLogger(&pi1_logger);
1329 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001330
James Kuszmaul46d82582020-05-09 19:50:09 -07001331 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1332 }
1333
1334 // Test that, if we add an additional node to the replay config that the
1335 // logger complains about the mismatch in number of nodes.
1336 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1337 configuration::MergeWithConfig(&config_.message(), R"({
1338 "nodes": [
1339 {
1340 "name": "extra-node"
1341 }
1342 ]
1343 }
1344 )");
1345
Austin Schuh287d43d2020-12-04 20:19:33 -08001346 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1347 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001348 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001349}
1350
Austin Schuhcde938c2020-02-02 17:30:07 -08001351// Tests that we can read log files where they don't start at the same monotonic
1352// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001353TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001354 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001355 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001356 LoggerState pi1_logger = MakeLogger(pi1_);
1357 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001358
1359 event_loop_factory_.RunFor(chrono::milliseconds(95));
1360
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001361 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001362
1363 event_loop_factory_.RunFor(chrono::milliseconds(200));
1364
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001365 StartLogger(&pi2_logger);
1366
Austin Schuhcde938c2020-02-02 17:30:07 -08001367 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1368 }
1369
Austin Schuhe46492f2021-07-31 19:49:41 -07001370 // Since we delay starting pi2, it already knows about all the timestamps so
1371 // we don't end up with extra parts.
1372 LogReader reader(
1373 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001374
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001375 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001376 log_reader_factory.set_send_delay(chrono::microseconds(0));
1377
1378 // This sends out the fetched messages and advances time to the start of the
1379 // log file.
1380 reader.Register(&log_reader_factory);
1381
1382 const Node *pi1 =
1383 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1384 const Node *pi2 =
1385 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1386
Austin Schuh07676622021-01-21 18:59:17 -08001387 EXPECT_THAT(reader.LoggedNodes(),
1388 ::testing::ElementsAre(
1389 configuration::GetNode(reader.logged_configuration(), pi1),
1390 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001391
1392 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1393
1394 std::unique_ptr<EventLoop> pi1_event_loop =
1395 log_reader_factory.MakeEventLoop("test", pi1);
1396 std::unique_ptr<EventLoop> pi2_event_loop =
1397 log_reader_factory.MakeEventLoop("test", pi2);
1398
1399 int pi1_ping_count = 30;
1400 int pi2_ping_count = 30;
1401 int pi1_pong_count = 30;
1402 int pi2_pong_count = 30;
1403
1404 // Confirm that the ping value matches.
1405 pi1_event_loop->MakeWatcher(
1406 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1407 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1408 << pi1_event_loop->context().monotonic_remote_time << " -> "
1409 << pi1_event_loop->context().monotonic_event_time;
1410 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1411
1412 ++pi1_ping_count;
1413 });
1414 pi2_event_loop->MakeWatcher(
1415 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1416 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1417 << pi2_event_loop->context().monotonic_remote_time << " -> "
1418 << pi2_event_loop->context().monotonic_event_time;
1419 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1420
1421 ++pi2_ping_count;
1422 });
1423
1424 // Confirm that the ping and pong counts both match, and the value also
1425 // matches.
1426 pi1_event_loop->MakeWatcher(
1427 "/test", [&pi1_event_loop, &pi1_ping_count,
1428 &pi1_pong_count](const examples::Pong &pong) {
1429 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1430 << pi1_event_loop->context().monotonic_remote_time << " -> "
1431 << pi1_event_loop->context().monotonic_event_time;
1432
1433 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1434 ++pi1_pong_count;
1435 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1436 });
1437 pi2_event_loop->MakeWatcher(
1438 "/test", [&pi2_event_loop, &pi2_ping_count,
1439 &pi2_pong_count](const examples::Pong &pong) {
1440 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1441 << pi2_event_loop->context().monotonic_remote_time << " -> "
1442 << pi2_event_loop->context().monotonic_event_time;
1443
1444 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1445 ++pi2_pong_count;
1446 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1447 });
1448
1449 log_reader_factory.Run();
1450 EXPECT_EQ(pi1_ping_count, 2030);
1451 EXPECT_EQ(pi2_ping_count, 2030);
1452 EXPECT_EQ(pi1_pong_count, 2030);
1453 EXPECT_EQ(pi2_pong_count, 2030);
1454
1455 reader.Deregister();
1456}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001457
Austin Schuh8bd96322020-02-13 21:18:22 -08001458// Tests that we can read log files where the monotonic clocks drift and don't
1459// match correctly. While we are here, also test that different ending times
1460// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001461TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001462 // TODO(austin): Negate...
1463 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1464
1465 time_converter_.AddMonotonic({monotonic_clock::epoch(),
1466 monotonic_clock::epoch() + initial_pi2_offset});
1467 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1468 // skew to be 200 uS/s
1469 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1470 {chrono::milliseconds(95),
1471 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1472 // Run another 200 ms to have one logger start first.
1473 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1474 {chrono::milliseconds(200), chrono::milliseconds(200)});
1475 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1476 // go far enough to cause problems if this isn't accounted for.
1477 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1478 {chrono::milliseconds(20000),
1479 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1480 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1481 {chrono::milliseconds(40000),
1482 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1483 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1484 {chrono::milliseconds(400), chrono::milliseconds(400)});
1485
Austin Schuhcde938c2020-02-02 17:30:07 -08001486 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001487 LoggerState pi2_logger = MakeLogger(pi2_);
1488
Austin Schuh87dd3832021-01-01 23:07:31 -08001489 NodeEventLoopFactory *pi1 =
1490 event_loop_factory_.GetNodeEventLoopFactory(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001491 NodeEventLoopFactory *pi2 =
1492 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1493 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1494 << pi2->realtime_now() << " distributed "
1495 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001496
Austin Schuh8bd96322020-02-13 21:18:22 -08001497 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1498 << pi2->realtime_now() << " distributed "
1499 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001500
Austin Schuh87dd3832021-01-01 23:07:31 -08001501 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001502
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001503 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001504
Austin Schuh87dd3832021-01-01 23:07:31 -08001505 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001506
Austin Schuh8bd96322020-02-13 21:18:22 -08001507 {
1508 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001509 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001510
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001511 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001512 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001513
Austin Schuh87dd3832021-01-01 23:07:31 -08001514 // Make sure we slewed time far enough so that the difference is greater
1515 // than the network delay. This confirms that if we sort incorrectly, it
1516 // would show in the results.
1517 EXPECT_LT(
1518 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1519 -event_loop_factory_.send_delay() -
1520 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001521
Austin Schuh87dd3832021-01-01 23:07:31 -08001522 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001523
Austin Schuh87dd3832021-01-01 23:07:31 -08001524 // And now check that we went far enough the other way to make sure we
1525 // cover both problems.
1526 EXPECT_GT(
1527 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1528 event_loop_factory_.send_delay() +
1529 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001530 }
1531
1532 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001533 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001534 }
1535
Austin Schuh287d43d2020-12-04 20:19:33 -08001536 LogReader reader(SortParts(logfiles_));
Austin Schuhcde938c2020-02-02 17:30:07 -08001537
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001538 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001539 log_reader_factory.set_send_delay(chrono::microseconds(0));
1540
Austin Schuhcde938c2020-02-02 17:30:07 -08001541 const Node *pi1 =
1542 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1543 const Node *pi2 =
1544 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1545
Austin Schuh2f8fd752020-09-01 22:38:28 -07001546 // This sends out the fetched messages and advances time to the start of the
1547 // log file.
1548 reader.Register(&log_reader_factory);
1549
1550 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1551 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1552 LOG(INFO) << "now pi1 "
1553 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1554 LOG(INFO) << "now pi2 "
1555 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1556
Austin Schuhcde938c2020-02-02 17:30:07 -08001557 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001558 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1559 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001560 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1561 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001562 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1563 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001564 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1565
Austin Schuh07676622021-01-21 18:59:17 -08001566 EXPECT_THAT(reader.LoggedNodes(),
1567 ::testing::ElementsAre(
1568 configuration::GetNode(reader.logged_configuration(), pi1),
1569 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001570
1571 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1572
1573 std::unique_ptr<EventLoop> pi1_event_loop =
1574 log_reader_factory.MakeEventLoop("test", pi1);
1575 std::unique_ptr<EventLoop> pi2_event_loop =
1576 log_reader_factory.MakeEventLoop("test", pi2);
1577
1578 int pi1_ping_count = 30;
1579 int pi2_ping_count = 30;
1580 int pi1_pong_count = 30;
1581 int pi2_pong_count = 30;
1582
1583 // Confirm that the ping value matches.
1584 pi1_event_loop->MakeWatcher(
1585 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1586 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1587 << pi1_event_loop->context().monotonic_remote_time << " -> "
1588 << pi1_event_loop->context().monotonic_event_time;
1589 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1590
1591 ++pi1_ping_count;
1592 });
1593 pi2_event_loop->MakeWatcher(
1594 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1595 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1596 << pi2_event_loop->context().monotonic_remote_time << " -> "
1597 << pi2_event_loop->context().monotonic_event_time;
1598 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1599
1600 ++pi2_ping_count;
1601 });
1602
1603 // Confirm that the ping and pong counts both match, and the value also
1604 // matches.
1605 pi1_event_loop->MakeWatcher(
1606 "/test", [&pi1_event_loop, &pi1_ping_count,
1607 &pi1_pong_count](const examples::Pong &pong) {
1608 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1609 << pi1_event_loop->context().monotonic_remote_time << " -> "
1610 << pi1_event_loop->context().monotonic_event_time;
1611
1612 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1613 ++pi1_pong_count;
1614 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1615 });
1616 pi2_event_loop->MakeWatcher(
1617 "/test", [&pi2_event_loop, &pi2_ping_count,
1618 &pi2_pong_count](const examples::Pong &pong) {
1619 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1620 << pi2_event_loop->context().monotonic_remote_time << " -> "
1621 << pi2_event_loop->context().monotonic_event_time;
1622
1623 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1624 ++pi2_pong_count;
1625 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1626 });
1627
1628 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001629 EXPECT_EQ(pi1_ping_count, 6030);
1630 EXPECT_EQ(pi2_ping_count, 6030);
1631 EXPECT_EQ(pi1_pong_count, 6030);
1632 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001633
1634 reader.Deregister();
1635}
1636
Austin Schuh5212cad2020-09-09 23:12:09 -07001637// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001638TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001639 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001640 // Make a bunch of parts.
1641 {
1642 LoggerState pi1_logger = MakeLogger(pi1_);
1643 LoggerState pi2_logger = MakeLogger(pi2_);
1644
1645 event_loop_factory_.RunFor(chrono::milliseconds(95));
1646
1647 StartLogger(&pi1_logger);
1648 StartLogger(&pi2_logger);
1649
1650 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1651 }
1652
Austin Schuh11d43732020-09-21 17:28:30 -07001653 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001654 VerifyParts(sorted_parts);
1655}
Austin Schuh11d43732020-09-21 17:28:30 -07001656
Austin Schuh3bd4c402020-11-06 18:19:06 -08001657// Tests that we can sort a bunch of parts with an empty part. We should ignore
1658// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001659TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001660 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001661 // Make a bunch of parts.
1662 {
1663 LoggerState pi1_logger = MakeLogger(pi1_);
1664 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001665
Austin Schuh3bd4c402020-11-06 18:19:06 -08001666 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001667
Austin Schuh3bd4c402020-11-06 18:19:06 -08001668 StartLogger(&pi1_logger);
1669 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001670
Austin Schuh3bd4c402020-11-06 18:19:06 -08001671 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001672 }
1673
Austin Schuh3bd4c402020-11-06 18:19:06 -08001674 // TODO(austin): Should we flip out if the file can't open?
1675 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001676
Austin Schuh3bd4c402020-11-06 18:19:06 -08001677 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1678 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001679
Austin Schuh3bd4c402020-11-06 18:19:06 -08001680 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1681 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001682}
1683
Austin Schuh3bd4c402020-11-06 18:19:06 -08001684#ifdef LZMA
1685// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1686// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001687TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001688 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001689 // Make a bunch of parts.
1690 {
1691 LoggerState pi1_logger = MakeLogger(pi1_);
1692 LoggerState pi2_logger = MakeLogger(pi2_);
1693
1694 event_loop_factory_.RunFor(chrono::milliseconds(95));
1695
1696 StartLogger(&pi1_logger, "", true);
1697 StartLogger(&pi2_logger, "", true);
1698
1699 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1700 }
1701
1702 // TODO(austin): Should we flip out if the file can't open?
1703 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1704
1705 AddExtension(".xz");
1706
1707 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1708 logfiles_.emplace_back(kEmptyFile);
1709
1710 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1711 VerifyParts(sorted_parts, {kEmptyFile});
1712}
1713
1714// Tests that we can sort a bunch of parts with the end missing off a compressed
1715// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001716TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001717 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001718 // Make a bunch of parts.
1719 {
1720 LoggerState pi1_logger = MakeLogger(pi1_);
1721 LoggerState pi2_logger = MakeLogger(pi2_);
1722
1723 event_loop_factory_.RunFor(chrono::milliseconds(95));
1724
1725 StartLogger(&pi1_logger, "", true);
1726 StartLogger(&pi2_logger, "", true);
1727
1728 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1729 }
1730
1731 // Append everything with .xz.
1732 AddExtension(".xz");
1733
1734 // Strip off the end of one of the files. Pick one with a lot of data.
1735 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001736 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001737
1738 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001739 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001740 compressed_contents.substr(0, compressed_contents.size() - 100));
1741
1742 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1743 VerifyParts(sorted_parts);
1744}
1745#endif
1746
Austin Schuh01b4c352020-09-21 23:09:39 -07001747// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001748TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001749 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001750 {
1751 LoggerState pi1_logger = MakeLogger(pi1_);
1752 LoggerState pi2_logger = MakeLogger(pi2_);
1753
1754 event_loop_factory_.RunFor(chrono::milliseconds(95));
1755
1756 StartLogger(&pi1_logger);
1757 StartLogger(&pi2_logger);
1758
1759 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1760 }
1761
Austin Schuh287d43d2020-12-04 20:19:33 -08001762 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001763
1764 // Remap just on pi1.
1765 reader.RemapLoggedChannel<aos::timing::Report>(
1766 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1767
1768 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1769 log_reader_factory.set_send_delay(chrono::microseconds(0));
1770
1771 reader.Register(&log_reader_factory);
1772
1773 const Node *pi1 =
1774 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1775 const Node *pi2 =
1776 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1777
1778 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1779 // else should have moved.
1780 std::unique_ptr<EventLoop> pi1_event_loop =
1781 log_reader_factory.MakeEventLoop("test", pi1);
1782 pi1_event_loop->SkipTimingReport();
1783 std::unique_ptr<EventLoop> full_pi1_event_loop =
1784 log_reader_factory.MakeEventLoop("test", pi1);
1785 full_pi1_event_loop->SkipTimingReport();
1786 std::unique_ptr<EventLoop> pi2_event_loop =
1787 log_reader_factory.MakeEventLoop("test", pi2);
1788 pi2_event_loop->SkipTimingReport();
1789
1790 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1791 "/aos");
1792 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1793 full_pi1_event_loop.get(), "/pi1/aos");
1794 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1795 pi1_event_loop.get(), "/original/aos");
1796 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1797 full_pi1_event_loop.get(), "/original/pi1/aos");
1798 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1799 "/aos");
1800
1801 log_reader_factory.Run();
1802
1803 EXPECT_EQ(pi1_timing_report.count(), 0u);
1804 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1805 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1806 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1807 EXPECT_NE(pi2_timing_report.count(), 0u);
1808
1809 reader.Deregister();
1810}
1811
Austin Schuh006a9f52021-04-07 16:24:18 -07001812// Tests that we can remap a forwarded channel as well.
1813TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1814 time_converter_.StartEqual();
1815 {
1816 LoggerState pi1_logger = MakeLogger(pi1_);
1817 LoggerState pi2_logger = MakeLogger(pi2_);
1818
1819 event_loop_factory_.RunFor(chrono::milliseconds(95));
1820
1821 StartLogger(&pi1_logger);
1822 StartLogger(&pi2_logger);
1823
1824 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1825 }
1826
1827 LogReader reader(SortParts(logfiles_));
1828
1829 reader.RemapLoggedChannel<examples::Ping>("/test");
1830
1831 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1832 log_reader_factory.set_send_delay(chrono::microseconds(0));
1833
1834 reader.Register(&log_reader_factory);
1835
1836 const Node *pi1 =
1837 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1838 const Node *pi2 =
1839 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1840
1841 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1842 // else should have moved.
1843 std::unique_ptr<EventLoop> pi1_event_loop =
1844 log_reader_factory.MakeEventLoop("test", pi1);
1845 pi1_event_loop->SkipTimingReport();
1846 std::unique_ptr<EventLoop> full_pi1_event_loop =
1847 log_reader_factory.MakeEventLoop("test", pi1);
1848 full_pi1_event_loop->SkipTimingReport();
1849 std::unique_ptr<EventLoop> pi2_event_loop =
1850 log_reader_factory.MakeEventLoop("test", pi2);
1851 pi2_event_loop->SkipTimingReport();
1852
1853 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1854 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1855 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1856 "/original/test");
1857 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1858 "/original/test");
1859
1860 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1861 pi1_original_ping_timestamp;
1862 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1863 pi1_ping_timestamp;
1864 if (!shared()) {
1865 pi1_original_ping_timestamp =
1866 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1867 pi1_event_loop.get(),
1868 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1869 pi1_ping_timestamp =
1870 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1871 pi1_event_loop.get(),
1872 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1873 }
1874
1875 log_reader_factory.Run();
1876
1877 EXPECT_EQ(pi1_ping.count(), 0u);
1878 EXPECT_EQ(pi2_ping.count(), 0u);
1879 EXPECT_NE(pi1_original_ping.count(), 0u);
1880 EXPECT_NE(pi2_original_ping.count(), 0u);
1881 if (!shared()) {
1882 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1883 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1884 }
1885
1886 reader.Deregister();
1887}
1888
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001889// Tests that we properly recreate forwarded timestamps when replaying a log.
1890// This should be enough that we can then re-run the logger and get a valid log
1891// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001892TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001893 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001894 {
1895 LoggerState pi1_logger = MakeLogger(pi1_);
1896 LoggerState pi2_logger = MakeLogger(pi2_);
1897
1898 event_loop_factory_.RunFor(chrono::milliseconds(95));
1899
1900 StartLogger(&pi1_logger);
1901 StartLogger(&pi2_logger);
1902
1903 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1904 }
1905
Austin Schuh287d43d2020-12-04 20:19:33 -08001906 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001907
1908 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1909 log_reader_factory.set_send_delay(chrono::microseconds(0));
1910
1911 // This sends out the fetched messages and advances time to the start of the
1912 // log file.
1913 reader.Register(&log_reader_factory);
1914
1915 const Node *pi1 =
1916 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1917 const Node *pi2 =
1918 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1919
1920 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1921 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1922 LOG(INFO) << "now pi1 "
1923 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1924 LOG(INFO) << "now pi2 "
1925 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1926
Austin Schuh07676622021-01-21 18:59:17 -08001927 EXPECT_THAT(reader.LoggedNodes(),
1928 ::testing::ElementsAre(
1929 configuration::GetNode(reader.logged_configuration(), pi1),
1930 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001931
1932 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1933
1934 std::unique_ptr<EventLoop> pi1_event_loop =
1935 log_reader_factory.MakeEventLoop("test", pi1);
1936 std::unique_ptr<EventLoop> pi2_event_loop =
1937 log_reader_factory.MakeEventLoop("test", pi2);
1938
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001939 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1940 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1941 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1942 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1943
1944 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1945 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1946 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1947 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1948
1949 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1950 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1951 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1952 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1953
1954 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1955 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1956 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1957 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1958
1959 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1960 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1961 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1962 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1963
1964 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1965 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1966 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1967 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1968
Austin Schuh969cd602021-01-03 00:09:45 -08001969 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001970 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001971
Austin Schuh61e973f2021-02-21 21:43:56 -08001972 for (std::pair<int, std::string> channel :
1973 shared()
1974 ? std::vector<
1975 std::pair<int, std::string>>{{-1,
1976 "/aos/remote_timestamps/pi2"}}
1977 : std::vector<std::pair<int, std::string>>{
1978 {pi1_timestamp_channel,
1979 "/aos/remote_timestamps/pi2/pi1/aos/"
1980 "aos-message_bridge-Timestamp"},
1981 {ping_timestamp_channel,
1982 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1983 pi1_event_loop->MakeWatcher(
1984 channel.second,
1985 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1986 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1987 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1988 &ping_on_pi2_fetcher, network_delay, send_delay,
1989 channel_index = channel.first](const RemoteMessage &header) {
1990 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1991 chrono::nanoseconds(header.monotonic_sent_time()));
1992 const aos::realtime_clock::time_point header_realtime_sent_time(
1993 chrono::nanoseconds(header.realtime_sent_time()));
1994 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1995 chrono::nanoseconds(header.monotonic_remote_time()));
1996 const aos::realtime_clock::time_point header_realtime_remote_time(
1997 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001998
Austin Schuh61e973f2021-02-21 21:43:56 -08001999 if (channel_index != -1) {
2000 ASSERT_EQ(channel_index, header.channel_index());
2001 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002002
Austin Schuh61e973f2021-02-21 21:43:56 -08002003 const Context *pi1_context = nullptr;
2004 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002005
Austin Schuh61e973f2021-02-21 21:43:56 -08002006 if (header.channel_index() == pi1_timestamp_channel) {
2007 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2008 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2009 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2010 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2011 } else if (header.channel_index() == ping_timestamp_channel) {
2012 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2013 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2014 pi1_context = &ping_on_pi1_fetcher.context();
2015 pi2_context = &ping_on_pi2_fetcher.context();
2016 } else {
2017 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2018 << configuration::CleanedChannelToString(
2019 pi1_event_loop->configuration()->channels()->Get(
2020 header.channel_index()));
2021 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002022
Austin Schuh61e973f2021-02-21 21:43:56 -08002023 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002024 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2025 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002026
Austin Schuh61e973f2021-02-21 21:43:56 -08002027 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2028 EXPECT_EQ(pi2_context->remote_queue_index,
2029 header.remote_queue_index());
2030 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002031
Austin Schuh61e973f2021-02-21 21:43:56 -08002032 EXPECT_EQ(pi2_context->monotonic_event_time,
2033 header_monotonic_sent_time);
2034 EXPECT_EQ(pi2_context->realtime_event_time,
2035 header_realtime_sent_time);
2036 EXPECT_EQ(pi2_context->realtime_remote_time,
2037 header_realtime_remote_time);
2038 EXPECT_EQ(pi2_context->monotonic_remote_time,
2039 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002040
Austin Schuh61e973f2021-02-21 21:43:56 -08002041 EXPECT_EQ(pi1_context->realtime_event_time,
2042 header_realtime_remote_time);
2043 EXPECT_EQ(pi1_context->monotonic_event_time,
2044 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002045
Austin Schuh61e973f2021-02-21 21:43:56 -08002046 // Time estimation isn't perfect, but we know the clocks were
2047 // identical when logged, so we know when this should have come back.
2048 // Confirm we got it when we expected.
2049 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2050 pi1_context->monotonic_event_time + 2 * network_delay +
2051 send_delay);
2052 });
2053 }
2054 for (std::pair<int, std::string> channel :
2055 shared()
2056 ? std::vector<
2057 std::pair<int, std::string>>{{-1,
2058 "/aos/remote_timestamps/pi1"}}
2059 : std::vector<std::pair<int, std::string>>{
2060 {pi2_timestamp_channel,
2061 "/aos/remote_timestamps/pi1/pi2/aos/"
2062 "aos-message_bridge-Timestamp"}}) {
2063 pi2_event_loop->MakeWatcher(
2064 channel.second,
2065 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2066 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2067 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2068 &pong_on_pi1_fetcher, network_delay, send_delay,
2069 channel_index = channel.first](const RemoteMessage &header) {
2070 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2071 chrono::nanoseconds(header.monotonic_sent_time()));
2072 const aos::realtime_clock::time_point header_realtime_sent_time(
2073 chrono::nanoseconds(header.realtime_sent_time()));
2074 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2075 chrono::nanoseconds(header.monotonic_remote_time()));
2076 const aos::realtime_clock::time_point header_realtime_remote_time(
2077 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002078
Austin Schuh61e973f2021-02-21 21:43:56 -08002079 if (channel_index != -1) {
2080 ASSERT_EQ(channel_index, header.channel_index());
2081 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002082
Austin Schuh61e973f2021-02-21 21:43:56 -08002083 const Context *pi2_context = nullptr;
2084 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002085
Austin Schuh61e973f2021-02-21 21:43:56 -08002086 if (header.channel_index() == pi2_timestamp_channel) {
2087 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2088 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2089 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2090 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2091 } else if (header.channel_index() == pong_timestamp_channel) {
2092 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2093 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2094 pi2_context = &pong_on_pi2_fetcher.context();
2095 pi1_context = &pong_on_pi1_fetcher.context();
2096 } else {
2097 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2098 << configuration::CleanedChannelToString(
2099 pi2_event_loop->configuration()->channels()->Get(
2100 header.channel_index()));
2101 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002102
Austin Schuh61e973f2021-02-21 21:43:56 -08002103 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002104 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2105 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002106
Austin Schuh61e973f2021-02-21 21:43:56 -08002107 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2108 EXPECT_EQ(pi1_context->remote_queue_index,
2109 header.remote_queue_index());
2110 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002111
Austin Schuh61e973f2021-02-21 21:43:56 -08002112 EXPECT_EQ(pi1_context->monotonic_event_time,
2113 header_monotonic_sent_time);
2114 EXPECT_EQ(pi1_context->realtime_event_time,
2115 header_realtime_sent_time);
2116 EXPECT_EQ(pi1_context->realtime_remote_time,
2117 header_realtime_remote_time);
2118 EXPECT_EQ(pi1_context->monotonic_remote_time,
2119 header_monotonic_remote_time);
2120
2121 EXPECT_EQ(pi2_context->realtime_event_time,
2122 header_realtime_remote_time);
2123 EXPECT_EQ(pi2_context->monotonic_event_time,
2124 header_monotonic_remote_time);
2125
2126 // Time estimation isn't perfect, but we know the clocks were
2127 // identical when logged, so we know when this should have come back.
2128 // Confirm we got it when we expected.
2129 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2130 pi2_context->monotonic_event_time + 2 * network_delay +
2131 send_delay);
2132 });
2133 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002134
2135 // And confirm we can re-create a log again, while checking the contents.
2136 {
2137 LoggerState pi1_logger = MakeLogger(
2138 configuration::GetNode(log_reader_factory.configuration(), pi1_),
2139 &log_reader_factory);
2140 LoggerState pi2_logger = MakeLogger(
2141 configuration::GetNode(log_reader_factory.configuration(), pi2_),
2142 &log_reader_factory);
2143
Austin Schuh25b46712021-01-03 00:04:38 -08002144 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2145 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002146
2147 log_reader_factory.Run();
2148 }
2149
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002150 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002151
2152 // And verify that we can run the LogReader over the relogged files without
2153 // hitting any fatal errors.
2154 {
2155 LogReader relogged_reader(SortParts(
2156 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2157 relogged_reader.Register();
2158
2159 relogged_reader.event_loop_factory()->Run();
2160 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002161}
2162
Austin Schuh315b96b2020-12-11 21:21:12 -08002163// Tests that we properly populate and extract the logger_start time by setting
2164// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002165TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002166 time_converter_.AddMonotonic(
2167 {monotonic_clock::epoch(),
2168 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002169 {
2170 LoggerState pi1_logger = MakeLogger(pi1_);
2171 LoggerState pi2_logger = MakeLogger(pi2_);
2172
Austin Schuh315b96b2020-12-11 21:21:12 -08002173 StartLogger(&pi1_logger);
2174 StartLogger(&pi2_logger);
2175
2176 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2177 }
2178
2179 for (const LogFile &log_file : SortParts(logfiles_)) {
2180 for (const LogParts &log_part : log_file.parts) {
2181 if (log_part.node == log_file.logger_node) {
2182 EXPECT_EQ(log_part.logger_monotonic_start_time,
2183 aos::monotonic_clock::min_time);
2184 EXPECT_EQ(log_part.logger_realtime_start_time,
2185 aos::realtime_clock::min_time);
2186 } else {
2187 const chrono::seconds offset = log_file.logger_node == "pi1"
2188 ? -chrono::seconds(1000)
2189 : chrono::seconds(1000);
2190 EXPECT_EQ(log_part.logger_monotonic_start_time,
2191 log_part.monotonic_start_time + offset);
2192 EXPECT_EQ(log_part.logger_realtime_start_time,
2193 log_file.realtime_start_time +
2194 (log_part.logger_monotonic_start_time -
2195 log_file.monotonic_start_time));
2196 }
2197 }
2198 }
2199}
2200
Austin Schuh6bb8a822021-03-31 23:04:39 -07002201// Test that renaming the base, renames the folder.
2202TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002203 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2204 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002205 time_converter_.AddMonotonic(
2206 {monotonic_clock::epoch(),
2207 monotonic_clock::epoch() + chrono::seconds(1000)});
2208 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2209 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2210 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2211 LoggerState pi1_logger = MakeLogger(pi1_);
2212 LoggerState pi2_logger = MakeLogger(pi2_);
2213
2214 StartLogger(&pi1_logger);
2215 StartLogger(&pi2_logger);
2216
2217 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2218 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2219 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2220 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2221 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2222 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2223 for (auto &file : logfiles_) {
2224 struct stat s;
2225 EXPECT_EQ(0, stat(file.c_str(), &s));
2226 }
2227}
2228
2229// Test that renaming the file base dies.
2230TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2231 time_converter_.AddMonotonic(
2232 {monotonic_clock::epoch(),
2233 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002234 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002235 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2236 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2237 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2238 LoggerState pi1_logger = MakeLogger(pi1_);
2239 StartLogger(&pi1_logger);
2240 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2241 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2242 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2243 "Rename of file base from");
2244}
2245
Austin Schuh8bd96322020-02-13 21:18:22 -08002246// TODO(austin): We can write a test which recreates a logfile and confirms that
2247// we get it back. That is the ultimate test.
2248
Austin Schuh315b96b2020-12-11 21:21:12 -08002249// Tests that we properly recreate forwarded timestamps when replaying a log.
2250// This should be enough that we can then re-run the logger and get a valid log
2251// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002252TEST_P(MultinodeLoggerDeathTest, RemoteReboot) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002253 time_converter_.StartEqual();
Austin Schuh315b96b2020-12-11 21:21:12 -08002254 std::string pi2_boot1;
2255 std::string pi2_boot2;
2256 {
2257 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2258 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002259 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002260 LoggerState pi1_logger = MakeLogger(pi1_);
2261
2262 event_loop_factory_.RunFor(chrono::milliseconds(95));
2263
2264 StartLogger(&pi1_logger);
2265
2266 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2267
2268 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
2269
2270 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2271 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002272 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002273
2274 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2275 }
2276
2277 // Confirm that we refuse to replay logs with missing boot uuids.
2278 EXPECT_DEATH(
2279 {
2280 LogReader reader(SortParts(pi1_reboot_logfiles_));
2281
2282 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2283 log_reader_factory.set_send_delay(chrono::microseconds(0));
2284
2285 // This sends out the fetched messages and advances time to the start of
2286 // the log file.
2287 reader.Register(&log_reader_factory);
2288 },
2289 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
2290 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
2291}
2292
Austin Schuhc9049732020-12-21 22:27:15 -08002293// Tests that we properly handle one direction of message_bridge being
2294// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002295TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002296 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002297 time_converter_.AddMonotonic(
2298 {monotonic_clock::epoch(),
2299 monotonic_clock::epoch() + chrono::seconds(1000)});
2300
2301 time_converter_.AddMonotonic(
2302 {chrono::milliseconds(10000),
2303 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002304 {
2305 LoggerState pi1_logger = MakeLogger(pi1_);
2306
2307 event_loop_factory_.RunFor(chrono::milliseconds(95));
2308
2309 StartLogger(&pi1_logger);
2310
2311 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2312 }
2313
2314 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2315 // to confirm the right thing happened.
2316 ConfirmReadable(pi1_single_direction_logfiles_);
2317}
2318
2319// Tests that we properly handle one direction of message_bridge being
2320// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002321TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002322 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002323 time_converter_.AddMonotonic(
2324 {monotonic_clock::epoch(),
2325 monotonic_clock::epoch() + chrono::seconds(500)});
2326
2327 time_converter_.AddMonotonic(
2328 {chrono::milliseconds(10000),
2329 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2330 {
2331 LoggerState pi1_logger = MakeLogger(pi1_);
2332
2333 event_loop_factory_.RunFor(chrono::milliseconds(95));
2334
2335 StartLogger(&pi1_logger);
2336
2337 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2338 }
2339
2340 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2341 // to confirm the right thing happened.
2342 ConfirmReadable(pi1_single_direction_logfiles_);
2343}
2344
2345// Tests that we properly handle a dead node. Do this by just disconnecting it
2346// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002347TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002348 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
2349 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
2350 time_converter_.AddMonotonic(
2351 {monotonic_clock::epoch(),
2352 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002353 {
2354 LoggerState pi1_logger = MakeLogger(pi1_);
2355
2356 event_loop_factory_.RunFor(chrono::milliseconds(95));
2357
2358 StartLogger(&pi1_logger);
2359
2360 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2361 }
2362
2363 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2364 // to confirm the right thing happened.
2365 ConfirmReadable(pi1_single_direction_logfiles_);
2366}
2367
Austin Schuhcdd90272021-03-15 12:46:16 -07002368constexpr std::string_view kCombinedConfigSha1(
milind945708b2021-07-03 13:30:15 -07002369 "4503751edc96327493562f0376f0d6daac172927c0fd64d04ce5d67505186c0b");
Austin Schuhcdd90272021-03-15 12:46:16 -07002370constexpr std::string_view kSplitConfigSha1(
milind945708b2021-07-03 13:30:15 -07002371 "918a748432c5e70a971dfd8934968378bed04ab61cf2efcd35b7f6224053c247");
Austin Schuhcdd90272021-03-15 12:46:16 -07002372
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002373INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002374 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002375 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2376 kCombinedConfigSha1},
2377 Param{"multinode_pingpong_split_config.json", false,
2378 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002379
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002380INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002381 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002382 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2383 kCombinedConfigSha1},
2384 Param{"multinode_pingpong_split_config.json", false,
2385 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002386
Austin Schuha04efed2021-01-24 18:04:20 -08002387// TODO(austin): Make a log file where the remote node has no start time.
2388
Austin Schuhe309d2a2019-11-29 13:25:21 -08002389} // namespace testing
2390} // namespace logger
2391} // namespace aos