blob: c974511720efbf5d3a03b59788e71233796fb7d4 [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]() {
Austin Schuha499cea2021-07-31 19:49:53 -0700173 logger.StartLogging(
174 std::make_unique<LocalLogNamer>(base_name1, logger_event_loop.get()));
Brian Silverman1f345222020-09-24 21:14:48 -0700175 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
Austin Schuha499cea2021-07-31 19:49:53 -0700176 base_name2, logger_event_loop.get())),
Brian Silverman1f345222020-09-24 21:14:48 -0700177 "Already logging");
178 });
179 event_loop_factory_.RunFor(chrono::milliseconds(20000));
180 }
181}
182
183// Tests calling StopLogging twice.
184TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800185 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700186 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800187 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700188 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700189 const ::std::string logfile = base_name + ".part0.bfbs";
190 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800191 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700192 unlink(logfile.c_str());
193
194 LOG(INFO) << "Logging data to " << logfile;
195
196 {
197 std::unique_ptr<EventLoop> logger_event_loop =
198 event_loop_factory_.MakeEventLoop("logger");
199
200 event_loop_factory_.RunFor(chrono::milliseconds(95));
201
202 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800203 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700204 logger.set_polling_period(std::chrono::milliseconds(100));
205 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuha499cea2021-07-31 19:49:53 -0700206 logger.StartLogging(
207 std::make_unique<LocalLogNamer>(base_name, logger_event_loop.get()));
Brian Silverman1f345222020-09-24 21:14:48 -0700208 logger.StopLogging(aos::monotonic_clock::min_time);
209 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
210 "Not logging right now");
211 });
212 event_loop_factory_.RunFor(chrono::milliseconds(20000));
213 }
214}
215
216// Tests that we can startup twice.
217TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800218 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700219 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800220 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700221 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700222 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
223 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800224 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700225 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700226 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
227 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800228 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700229 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800230 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700231
232 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
233
234 {
235 std::unique_ptr<EventLoop> logger_event_loop =
236 event_loop_factory_.MakeEventLoop("logger");
237
238 event_loop_factory_.RunFor(chrono::milliseconds(95));
239
240 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800241 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700242 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuha499cea2021-07-31 19:49:53 -0700243 logger.StartLogging(
244 std::make_unique<LocalLogNamer>(base_name1, logger_event_loop.get()));
Brian Silverman1f345222020-09-24 21:14:48 -0700245 event_loop_factory_.RunFor(chrono::milliseconds(10000));
246 logger.StopLogging(logger_event_loop->monotonic_now());
247 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuha499cea2021-07-31 19:49:53 -0700248 logger.StartLogging(
249 std::make_unique<LocalLogNamer>(base_name2, logger_event_loop.get()));
Brian Silverman1f345222020-09-24 21:14:48 -0700250 event_loop_factory_.RunFor(chrono::milliseconds(10000));
251 }
252
253 for (const auto &logfile :
254 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
255 SCOPED_TRACE(std::get<0>(logfile));
256 LogReader reader(std::get<0>(logfile));
257 reader.Register();
258
Austin Schuh07676622021-01-21 18:59:17 -0800259 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700260
261 std::unique_ptr<EventLoop> test_event_loop =
262 reader.event_loop_factory()->MakeEventLoop("log_reader");
263
264 int ping_count = std::get<1>(logfile);
265 int pong_count = std::get<1>(logfile);
266
267 // Confirm that the ping and pong counts both match, and the value also
268 // matches.
269 test_event_loop->MakeWatcher("/test",
270 [&ping_count](const examples::Ping &ping) {
271 EXPECT_EQ(ping.value(), ping_count + 1);
272 ++ping_count;
273 });
274 test_event_loop->MakeWatcher(
275 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
276 EXPECT_EQ(pong.value(), pong_count + 1);
277 ++pong_count;
278 EXPECT_EQ(ping_count, pong_count);
279 });
280
281 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
282 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
283 }
284}
285
Austin Schuhfa895892020-01-07 20:07:41 -0800286// Tests that we can read and write rotated log files.
287TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800288 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700289 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800290 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700291 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700292 const ::std::string logfile0 = base_name + ".part0.bfbs";
293 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800294 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800295 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800296 unlink(logfile0.c_str());
297 unlink(logfile1.c_str());
298
299 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
300
301 {
Austin Schuhfa895892020-01-07 20:07:41 -0800302 std::unique_ptr<EventLoop> logger_event_loop =
303 event_loop_factory_.MakeEventLoop("logger");
304
305 event_loop_factory_.RunFor(chrono::milliseconds(95));
306
Brian Silverman1f345222020-09-24 21:14:48 -0700307 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800308 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700309 logger.set_polling_period(std::chrono::milliseconds(100));
310 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800311 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700312 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800313 event_loop_factory_.RunFor(chrono::milliseconds(10000));
314 }
315
Austin Schuh64fab802020-09-09 22:47:47 -0700316 {
317 // Confirm that the UUIDs match for both the parts and the logger, and the
318 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800319 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700320 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800321 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700322 }
323
Brian Silvermanae7c0332020-09-30 16:58:23 -0700324 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
325 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700326 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
327 log_header[1].message().parts_uuid()->string_view());
328
329 EXPECT_EQ(log_header[0].message().parts_index(), 0);
330 EXPECT_EQ(log_header[1].message().parts_index(), 1);
331 }
332
Austin Schuhfa895892020-01-07 20:07:41 -0800333 // Even though it doesn't make any difference here, exercise the logic for
334 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800335 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800336
337 // Confirm that we can remap logged channels to point to new buses.
338 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
339
340 // This sends out the fetched messages and advances time to the start of the
341 // log file.
342 reader.Register();
343
Austin Schuh07676622021-01-21 18:59:17 -0800344 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800345
346 std::unique_ptr<EventLoop> test_event_loop =
347 reader.event_loop_factory()->MakeEventLoop("log_reader");
348
349 int ping_count = 10;
350 int pong_count = 10;
351
352 // Confirm that the ping value matches in the remapped channel location.
353 test_event_loop->MakeWatcher("/original/test",
354 [&ping_count](const examples::Ping &ping) {
355 EXPECT_EQ(ping.value(), ping_count + 1);
356 ++ping_count;
357 });
358 // Confirm that the ping and pong counts both match, and the value also
359 // matches.
360 test_event_loop->MakeWatcher(
361 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
362 EXPECT_EQ(pong.value(), pong_count + 1);
363 ++pong_count;
364 EXPECT_EQ(ping_count, pong_count);
365 });
366
367 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
368 EXPECT_EQ(ping_count, 2010);
369}
370
Austin Schuh4c4e0092019-12-22 16:18:03 -0800371// Tests that a large number of messages per second doesn't overwhelm writev.
372TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800373 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700374 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800375 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700376 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700377 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800378 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800379 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800380 unlink(logfile.c_str());
381
382 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700383 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800384
385 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800386 std::unique_ptr<EventLoop> logger_event_loop =
387 event_loop_factory_.MakeEventLoop("logger");
388
389 std::unique_ptr<EventLoop> ping_spammer_event_loop =
390 event_loop_factory_.MakeEventLoop("ping_spammer");
391 aos::Sender<examples::Ping> ping_sender =
392 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
393
394 aos::TimerHandler *timer_handler =
395 ping_spammer_event_loop->AddTimer([&ping_sender]() {
396 aos::Sender<examples::Ping>::Builder builder =
397 ping_sender.MakeBuilder();
398 examples::Ping::Builder ping_builder =
399 builder.MakeBuilder<examples::Ping>();
400 CHECK(builder.Send(ping_builder.Finish()));
401 });
402
403 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
404 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
405 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
406 chrono::microseconds(50));
407 });
408
Brian Silverman1f345222020-09-24 21:14:48 -0700409 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800410 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700411 logger.set_polling_period(std::chrono::milliseconds(100));
412 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800413
414 event_loop_factory_.RunFor(chrono::milliseconds(1000));
415 }
416}
417
Austin Schuh61e973f2021-02-21 21:43:56 -0800418// Parameters to run all the tests with.
419struct Param {
420 // The config file to use.
421 std::string config;
422 // If true, the RemoteMessage channel should be shared between all the remote
423 // channels. If false, there will be 1 RemoteMessage channel per remote
424 // channel.
425 bool shared;
426 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700427 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800428};
Austin Schuh315b96b2020-12-11 21:21:12 -0800429
Austin Schuh61e973f2021-02-21 21:43:56 -0800430class MultinodeLoggerTest : public ::testing::TestWithParam<struct Param> {
Austin Schuh15649d62019-12-28 16:36:38 -0800431 public:
432 MultinodeLoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -0700433 : config_(aos::configuration::ReadConfig(ArtifactPath(
434 absl::StrCat("aos/events/logging/", GetParam().config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800435 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800436 event_loop_factory_(&config_.message()),
Austin Schuhcde938c2020-02-02 17:30:07 -0800437 pi1_(
438 configuration::GetNode(event_loop_factory_.configuration(), "pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800439 pi1_index_(configuration::GetNodeIndex(
440 event_loop_factory_.configuration(), pi1_)),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700441 pi2_(
442 configuration::GetNode(event_loop_factory_.configuration(), "pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800443 pi2_index_(configuration::GetNodeIndex(
444 event_loop_factory_.configuration(), pi2_)),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800445 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800446 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
447 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800448 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800449 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800450 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
451 structured_logfiles_(StructureLogFiles()),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700452 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping", pi1_)),
453 ping_(ping_event_loop_.get()),
454 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong", pi2_)),
455 pong_(pong_event_loop_.get()) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800456 LOG(INFO) << "Config " << GetParam().config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800457 event_loop_factory_.SetTimeConverter(&time_converter_);
458
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700459 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700460 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700461 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800462 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700463 }
464
Austin Schuh268586b2021-03-31 22:24:39 -0700465 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800466 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800467 unlink(file.c_str());
468 }
469
Austin Schuh268586b2021-03-31 22:24:39 -0700470 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800471 unlink(file.c_str());
472 }
473
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700474 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
475 << " and " << logfiles_[2];
476 }
477
Austin Schuh61e973f2021-02-21 21:43:56 -0800478 bool shared() const { return GetParam().shared; }
479
480 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700481 std::string logfile_base2,
482 size_t pi1_data_count = 2,
483 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800484 std::vector<std::string> result;
485 result.emplace_back(
486 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
487 result.emplace_back(
488 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
Austin Schuhe46492f2021-07-31 19:49:41 -0700489 for (size_t i = 0; i < pi1_data_count; ++i) {
490 result.emplace_back(
491 absl::StrCat(logfile_base1, "_pi1_data.part", i, ".bfbs"));
492 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800493 result.emplace_back(logfile_base1 +
494 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
495 result.emplace_back(logfile_base1 +
496 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700497 for (size_t i = 0; i < pi2_data_count; ++i) {
498 result.emplace_back(
499 absl::StrCat(logfile_base2, "_pi2_data.part", i, ".bfbs"));
500 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800501 result.emplace_back(
502 logfile_base2 +
503 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
504 result.emplace_back(
505 logfile_base2 +
506 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
507 result.emplace_back(
508 logfile_base1 +
509 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
510 result.emplace_back(
511 logfile_base1 +
512 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
513 if (shared()) {
514 result.emplace_back(logfile_base1 +
515 "_timestamps/pi1/aos/remote_timestamps/pi2/"
516 "aos.message_bridge.RemoteMessage.part0.bfbs");
517 result.emplace_back(logfile_base1 +
518 "_timestamps/pi1/aos/remote_timestamps/pi2/"
519 "aos.message_bridge.RemoteMessage.part1.bfbs");
520 result.emplace_back(logfile_base2 +
521 "_timestamps/pi2/aos/remote_timestamps/pi1/"
522 "aos.message_bridge.RemoteMessage.part0.bfbs");
523 result.emplace_back(logfile_base2 +
524 "_timestamps/pi2/aos/remote_timestamps/pi1/"
525 "aos.message_bridge.RemoteMessage.part1.bfbs");
526 } else {
527 result.emplace_back(logfile_base1 +
528 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
529 "aos-message_bridge-Timestamp/"
530 "aos.message_bridge.RemoteMessage.part0.bfbs");
531 result.emplace_back(logfile_base1 +
532 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
533 "aos-message_bridge-Timestamp/"
534 "aos.message_bridge.RemoteMessage.part1.bfbs");
535 result.emplace_back(logfile_base2 +
536 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
537 "aos-message_bridge-Timestamp/"
538 "aos.message_bridge.RemoteMessage.part0.bfbs");
539 result.emplace_back(logfile_base2 +
540 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
541 "aos-message_bridge-Timestamp/"
542 "aos.message_bridge.RemoteMessage.part1.bfbs");
543 result.emplace_back(logfile_base1 +
544 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
545 "aos-examples-Ping/"
546 "aos.message_bridge.RemoteMessage.part0.bfbs");
547 result.emplace_back(logfile_base1 +
548 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
549 "aos-examples-Ping/"
550 "aos.message_bridge.RemoteMessage.part1.bfbs");
551 }
552
553 return result;
554 }
555
556 std::vector<std::string> MakePi1RebootLogfiles() {
557 std::vector<std::string> result;
558 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700559 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
560 result.emplace_back(logfile_base1_ + "_pi1_data.part2.bfbs");
Austin Schuh72211ae2021-08-05 14:02:30 -0700561 result.emplace_back(logfile_base1_ + "_pi1_data.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800562 result.emplace_back(logfile_base1_ +
563 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
564 result.emplace_back(logfile_base1_ +
565 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
566 result.emplace_back(logfile_base1_ +
567 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
568 result.emplace_back(
569 logfile_base1_ +
570 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
571 result.emplace_back(
572 logfile_base1_ +
573 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
574 result.emplace_back(
575 logfile_base1_ +
576 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
577 result.emplace_back(
578 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
579 if (shared()) {
580 result.emplace_back(logfile_base1_ +
581 "_timestamps/pi1/aos/remote_timestamps/pi2/"
582 "aos.message_bridge.RemoteMessage.part0.bfbs");
583 result.emplace_back(logfile_base1_ +
584 "_timestamps/pi1/aos/remote_timestamps/pi2/"
585 "aos.message_bridge.RemoteMessage.part1.bfbs");
586 result.emplace_back(logfile_base1_ +
587 "_timestamps/pi1/aos/remote_timestamps/pi2/"
588 "aos.message_bridge.RemoteMessage.part2.bfbs");
589 } else {
590 result.emplace_back(logfile_base1_ +
591 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
592 "aos-message_bridge-Timestamp/"
593 "aos.message_bridge.RemoteMessage.part0.bfbs");
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.part1.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.part2.bfbs");
602
603 result.emplace_back(logfile_base1_ +
604 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
605 "aos-examples-Ping/"
606 "aos.message_bridge.RemoteMessage.part0.bfbs");
607 result.emplace_back(logfile_base1_ +
608 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
609 "aos-examples-Ping/"
610 "aos.message_bridge.RemoteMessage.part1.bfbs");
611 result.emplace_back(logfile_base1_ +
612 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
613 "aos-examples-Ping/"
614 "aos.message_bridge.RemoteMessage.part2.bfbs");
615 }
616 return result;
617 }
618
619 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
620 std::vector<std::string> result;
621 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuh510dc622021-08-06 18:47:30 -0700622 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800623 result.emplace_back(
624 logfile_base1_ +
625 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
626 result.emplace_back(
627 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh510dc622021-08-06 18:47:30 -0700628 return result;
629 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800630
Austin Schuh510dc622021-08-06 18:47:30 -0700631 std::vector<std::string> MakePi1DeadNodeLogfiles() {
632 std::vector<std::string> result;
633 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
634 result.emplace_back(
635 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh61e973f2021-02-21 21:43:56 -0800636 return result;
637 }
638
639 std::vector<std::vector<std::string>> StructureLogFiles() {
640 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700641 std::vector<std::string>{logfiles_[2], logfiles_[3]},
642 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800643 std::vector<std::string>{logfiles_[6], logfiles_[7]},
644 std::vector<std::string>{logfiles_[8], logfiles_[9]},
645 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700646 std::vector<std::string>{logfiles_[12], logfiles_[13]},
647 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800648
649 if (!shared()) {
650 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700651 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800652 }
653
654 return result;
655 }
656
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700657 struct LoggerState {
658 std::unique_ptr<EventLoop> event_loop;
659 std::unique_ptr<Logger> logger;
660 };
661
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700662 LoggerState MakeLogger(const Node *node,
663 SimulatedEventLoopFactory *factory = nullptr) {
664 if (factory == nullptr) {
665 factory = &event_loop_factory_;
666 }
667 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700668 }
669
Austin Schuh3bd4c402020-11-06 18:19:06 -0800670 void StartLogger(LoggerState *logger, std::string logfile_base = "",
671 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700672 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800673 if (logger->event_loop->node()->name()->string_view() == "pi1") {
674 logfile_base = logfile_base1_;
675 } else {
676 logfile_base = logfile_base2_;
677 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700678 }
679
Brian Silverman1f345222020-09-24 21:14:48 -0700680 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
681 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800682 logger->logger->set_name(absl::StrCat(
683 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800684 logger->event_loop->OnRun([logger, logfile_base, compress]() {
685 std::unique_ptr<MultiNodeLogNamer> namer =
Austin Schuha499cea2021-07-31 19:49:53 -0700686 std::make_unique<MultiNodeLogNamer>(logfile_base,
687 logger->event_loop.get());
Austin Schuh3bd4c402020-11-06 18:19:06 -0800688 if (compress) {
689#ifdef LZMA
690 namer->set_extension(".xz");
691 namer->set_encoder_factory(
692 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
693#else
694 LOG(FATAL) << "Compression unsupported";
695#endif
696 }
697
698 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700699 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700700 }
Austin Schuh15649d62019-12-28 16:36:38 -0800701
Austin Schuh3bd4c402020-11-06 18:19:06 -0800702 void VerifyParts(const std::vector<LogFile> &sorted_parts,
703 const std::vector<std::string> &corrupted_parts = {}) {
704 EXPECT_EQ(sorted_parts.size(), 2u);
705
706 // Count up the number of UUIDs and make sure they are what we expect as a
707 // sanity check.
708 std::set<std::string> log_event_uuids;
709 std::set<std::string> parts_uuids;
710 std::set<std::string> both_uuids;
711
712 size_t missing_rt_count = 0;
713
714 std::vector<std::string> logger_nodes;
715 for (const LogFile &log_file : sorted_parts) {
716 EXPECT_FALSE(log_file.log_event_uuid.empty());
717 log_event_uuids.insert(log_file.log_event_uuid);
718 logger_nodes.emplace_back(log_file.logger_node);
719 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800720 EXPECT_TRUE(log_file.config);
721 EXPECT_EQ(log_file.name,
722 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800723
724 for (const LogParts &part : log_file.parts) {
725 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
726 << ": " << part;
727 missing_rt_count +=
728 part.realtime_start_time == aos::realtime_clock::min_time;
729
730 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
731 log_event_uuids.end());
732 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800733 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800734 parts_uuids.insert(part.parts_uuid);
735 both_uuids.insert(part.parts_uuid);
736 }
737 }
738
Austin Schuh61e973f2021-02-21 21:43:56 -0800739 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
740 // start time on remote nodes because we don't know it and would be
741 // guessing. And the log reader can actually do a better job. The number
742 // depends on if we have the remote timestamps split across 2 files, or just
743 // across 1, depending on if we are using a split or combined timestamp
744 // channel config.
745 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800746
747 EXPECT_EQ(log_event_uuids.size(), 2u);
748 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
749 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
750
751 // Test that each list of parts is in order. Don't worry about the ordering
752 // between part file lists though.
753 // (inner vectors all need to be in order, but outer one doesn't matter).
754 EXPECT_THAT(ToLogReaderVector(sorted_parts),
755 ::testing::UnorderedElementsAreArray(structured_logfiles_));
756
757 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
758
759 EXPECT_NE(sorted_parts[0].realtime_start_time,
760 aos::realtime_clock::min_time);
761 EXPECT_NE(sorted_parts[1].realtime_start_time,
762 aos::realtime_clock::min_time);
763
764 EXPECT_NE(sorted_parts[0].monotonic_start_time,
765 aos::monotonic_clock::min_time);
766 EXPECT_NE(sorted_parts[1].monotonic_start_time,
767 aos::monotonic_clock::min_time);
768
769 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
770 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
771 }
772
Austin Schuhc9049732020-12-21 22:27:15 -0800773 void ConfirmReadable(const std::vector<std::string> &files) {
774 LogReader reader(SortParts(files));
775
776 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
777 reader.Register(&log_reader_factory);
778
779 log_reader_factory.Run();
780
781 reader.Deregister();
782 }
783
Austin Schuh3bd4c402020-11-06 18:19:06 -0800784 void AddExtension(std::string_view extension) {
785 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
786 [extension](const std::string &in) {
787 return absl::StrCat(in, extension);
788 });
789
790 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
791 structured_logfiles_.begin(),
792 [extension](std::vector<std::string> in) {
793 std::transform(in.begin(), in.end(), in.begin(),
794 [extension](const std::string &in_str) {
795 return absl::StrCat(in_str, extension);
796 });
797 return in;
798 });
799 }
800
Austin Schuh15649d62019-12-28 16:36:38 -0800801 // Config and factory.
802 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800803 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800804 SimulatedEventLoopFactory event_loop_factory_;
805
Austin Schuh87dd3832021-01-01 23:07:31 -0800806 const Node *const pi1_;
807 const size_t pi1_index_;
808 const Node *const pi2_;
809 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700810
811 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800812 std::string logfile_base1_;
813 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800814 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700815 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800816 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700817
818 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700819
820 std::unique_ptr<EventLoop> ping_event_loop_;
821 Ping ping_;
822 std::unique_ptr<EventLoop> pong_event_loop_;
823 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800824};
825
Austin Schuh391e3172020-09-01 22:48:18 -0700826// Counts the number of messages on a channel. Returns (channel name, channel
827// type, count) for every message matching matcher()
828std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800829 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800830 std::function<bool(const MessageHeader *)> matcher) {
831 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800832 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800833
Austin Schuh6f3babe2020-01-26 20:34:50 -0800834 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800835 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800836 message_reader.ReadMessage();
837 if (!msg) {
838 break;
839 }
840
841 if (matcher(&msg.value().message())) {
842 counts[msg.value().message().channel_index()]++;
843 }
844 }
845
Austin Schuh391e3172020-09-01 22:48:18 -0700846 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800847 int channel = 0;
848 for (size_t i = 0; i < counts.size(); ++i) {
849 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800850 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700851 result.push_back(std::make_tuple(channel->name()->str(),
852 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800853 }
854 ++channel;
855 }
856
857 return result;
858}
859
860// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700861std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800862 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700863 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800864 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800865 if (msg->has_data()) {
866 CHECK(!msg->has_monotonic_remote_time());
867 CHECK(!msg->has_realtime_remote_time());
868 CHECK(!msg->has_remote_queue_index());
869 return true;
870 }
871 return false;
872 });
873}
874
875// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700876std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800877 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800878 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800879 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800880 if (!msg->has_data()) {
881 CHECK(msg->has_monotonic_remote_time());
882 CHECK(msg->has_realtime_remote_time());
883 CHECK(msg->has_remote_queue_index());
884 return true;
885 }
886 return false;
887 });
888}
889
Austin Schuhcde938c2020-02-02 17:30:07 -0800890// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800891TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800892 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800893 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700894 LoggerState pi1_logger = MakeLogger(pi1_);
895 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800896
897 event_loop_factory_.RunFor(chrono::milliseconds(95));
898
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700899 StartLogger(&pi1_logger);
900 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800901
Austin Schuh15649d62019-12-28 16:36:38 -0800902 event_loop_factory_.RunFor(chrono::milliseconds(20000));
903 }
904
Austin Schuh6f3babe2020-01-26 20:34:50 -0800905 {
Austin Schuh64fab802020-09-09 22:47:47 -0700906 std::set<std::string> logfile_uuids;
907 std::set<std::string> parts_uuids;
908 // Confirm that we have the expected number of UUIDs for both the logfile
909 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800910 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700911 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800912 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800913 if (!log_header.back().message().has_configuration()) {
914 logfile_uuids.insert(
915 log_header.back().message().log_event_uuid()->str());
916 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
917 }
Austin Schuh64fab802020-09-09 22:47:47 -0700918 }
Austin Schuh15649d62019-12-28 16:36:38 -0800919
Austin Schuh64fab802020-09-09 22:47:47 -0700920 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800921 if (shared()) {
922 EXPECT_EQ(parts_uuids.size(), 7u);
923 } else {
924 EXPECT_EQ(parts_uuids.size(), 8u);
925 }
Austin Schuh64fab802020-09-09 22:47:47 -0700926
927 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800928 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -0700929 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700930 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
931 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700932 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
933 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
934 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
935 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700936 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
937 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700938 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
939 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
940 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
941 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800942 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700943 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
944 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800945 }
Austin Schuh64fab802020-09-09 22:47:47 -0700946
947 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800948 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -0700949 EXPECT_EQ(log_header[3].message().parts_index(), 1);
950 EXPECT_EQ(log_header[4].message().parts_index(), 0);
951 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -0700952 EXPECT_EQ(log_header[6].message().parts_index(), 0);
953 EXPECT_EQ(log_header[7].message().parts_index(), 1);
954 EXPECT_EQ(log_header[8].message().parts_index(), 0);
955 EXPECT_EQ(log_header[9].message().parts_index(), 1);
956 EXPECT_EQ(log_header[10].message().parts_index(), 0);
957 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800958 EXPECT_EQ(log_header[12].message().parts_index(), 0);
959 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -0700960 EXPECT_EQ(log_header[14].message().parts_index(), 0);
961 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800962 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700963 EXPECT_EQ(log_header[16].message().parts_index(), 0);
964 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800965 }
Austin Schuh64fab802020-09-09 22:47:47 -0700966 }
967
Austin Schuh8c399962020-12-25 21:51:45 -0800968 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700969 {
Austin Schuh391e3172020-09-01 22:48:18 -0700970 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800971 std::shared_ptr<const aos::Configuration> config =
972 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700973
Austin Schuh6f3babe2020-01-26 20:34:50 -0800974 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700975 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800976 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700977 UnorderedElementsAre(
Austin Schuhe46492f2021-07-31 19:49:41 -0700978 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
979 1),
980 std::make_tuple("/test", "aos.examples.Ping", 1)))
981 << " : " << logfiles_[2];
982 EXPECT_THAT(
983 CountChannelsData(config, logfiles_[3]),
984 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -0700985 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800986 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -0700987 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800988 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
989 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700990 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -0700991 std::make_tuple("/test", "aos.examples.Ping", 2000)))
992 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -0800993 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -0700994 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
995 UnorderedElementsAre())
996 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -0700997 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -0700998 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700999 UnorderedElementsAre(
1000 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001001 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001002 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001003
1004 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001005 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001006 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001007 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001008 << " : " << logfiles_[4];
1009 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001010 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001011 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001012 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001013
Austin Schuh6f3babe2020-01-26 20:34:50 -08001014 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001015 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001016 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001017 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001018 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1019 UnorderedElementsAre())
1020 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001021
1022 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001023 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1024 UnorderedElementsAre(std::make_tuple(
1025 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1026 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001027 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001028 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001029 UnorderedElementsAre(
1030 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001031 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001032 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001033 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1034 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001035 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001036 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001037 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001038 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001039 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1040 UnorderedElementsAre())
1041 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001042 EXPECT_THAT(
1043 CountChannelsTimestamp(config, logfiles_[7]),
1044 UnorderedElementsAre(
1045 std::make_tuple("/test", "aos.examples.Ping", 2001),
1046 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001047 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001048
1049 // And then test that the remotely logged timestamp data files only have
1050 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001051 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1052 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001053 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001054 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1055 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001056 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001057 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1058 UnorderedElementsAre())
1059 << " : " << logfiles_[10];
1060 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1061 UnorderedElementsAre())
1062 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001063
Austin Schuh8c399962020-12-25 21:51:45 -08001064 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001065 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001066 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001067 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001068 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001069 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001070 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001071 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001072
Austin Schuh8c399962020-12-25 21:51:45 -08001073 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001074 UnorderedElementsAre(std::make_tuple(
1075 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001076 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001077 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001078 UnorderedElementsAre(std::make_tuple(
1079 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001080 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001081
1082 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001083 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1084 UnorderedElementsAre())
1085 << " : " << logfiles_[12];
1086 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1087 UnorderedElementsAre())
1088 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001089 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1090 UnorderedElementsAre())
1091 << " : " << logfiles_[14];
1092 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1093 UnorderedElementsAre())
1094 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001095 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001096 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001097 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001098 << " : " << logfiles_[16];
1099 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001100 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001101 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001102 }
1103
1104 if (shared()) {
1105 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001106 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001107 UnorderedElementsAre(
1108 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1109 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001110 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001111 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001112 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001113 UnorderedElementsAre(
1114 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1115 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001116 << " : " << logfiles_[13];
1117 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001118 UnorderedElementsAre(std::make_tuple(
1119 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001120 << " : " << logfiles_[14];
1121 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001122 UnorderedElementsAre(std::make_tuple(
1123 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1124 << " : " << logfiles_[15];
1125 } else {
1126 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1127 UnorderedElementsAre(std::make_tuple(
1128 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1129 << " : " << logfiles_[12];
1130 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1131 UnorderedElementsAre(std::make_tuple(
1132 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1133 << " : " << logfiles_[13];
1134 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1135 UnorderedElementsAre(std::make_tuple(
1136 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1137 << " : " << logfiles_[14];
1138 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1139 UnorderedElementsAre(std::make_tuple(
1140 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1141 << " : " << logfiles_[15];
1142 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1143 UnorderedElementsAre(
1144 std::make_tuple("/test", "aos.examples.Ping", 91)))
1145 << " : " << logfiles_[16];
1146 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001147 UnorderedElementsAre(
1148 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001149 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001150 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001151 }
1152
Austin Schuh8c399962020-12-25 21:51:45 -08001153 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001154
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001155 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001156 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001157
1158 // This sends out the fetched messages and advances time to the start of the
1159 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001160 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001161
Austin Schuhac0771c2020-01-07 18:36:30 -08001162 const Node *pi1 =
1163 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001164 const Node *pi2 =
1165 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001166
Austin Schuh2f8fd752020-09-01 22:38:28 -07001167 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1168 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1169 LOG(INFO) << "now pi1 "
1170 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1171 LOG(INFO) << "now pi2 "
1172 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1173
Austin Schuh07676622021-01-21 18:59:17 -08001174 EXPECT_THAT(reader.LoggedNodes(),
1175 ::testing::ElementsAre(
1176 configuration::GetNode(reader.logged_configuration(), pi1),
1177 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001178
1179 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001180
Austin Schuh6f3babe2020-01-26 20:34:50 -08001181 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001182 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001183 std::unique_ptr<EventLoop> pi2_event_loop =
1184 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001185
Austin Schuh6f3babe2020-01-26 20:34:50 -08001186 int pi1_ping_count = 10;
1187 int pi2_ping_count = 10;
1188 int pi1_pong_count = 10;
1189 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001190
1191 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001192 pi1_event_loop->MakeWatcher(
1193 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001194 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001195 << pi1_event_loop->context().monotonic_remote_time << " -> "
1196 << pi1_event_loop->context().monotonic_event_time;
1197 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1198 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1199 pi1_ping_count * chrono::milliseconds(10) +
1200 monotonic_clock::epoch());
1201 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1202 pi1_ping_count * chrono::milliseconds(10) +
1203 realtime_clock::epoch());
1204 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1205 pi1_event_loop->context().monotonic_event_time);
1206 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1207 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001208
Austin Schuh6f3babe2020-01-26 20:34:50 -08001209 ++pi1_ping_count;
1210 });
1211 pi2_event_loop->MakeWatcher(
1212 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001213 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001214 << pi2_event_loop->context().monotonic_remote_time << " -> "
1215 << pi2_event_loop->context().monotonic_event_time;
1216 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1217
1218 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1219 pi2_ping_count * chrono::milliseconds(10) +
1220 monotonic_clock::epoch());
1221 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1222 pi2_ping_count * chrono::milliseconds(10) +
1223 realtime_clock::epoch());
1224 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1225 chrono::microseconds(150),
1226 pi2_event_loop->context().monotonic_event_time);
1227 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1228 chrono::microseconds(150),
1229 pi2_event_loop->context().realtime_event_time);
1230 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001231 });
1232
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001233 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001234 // Confirm that the ping and pong counts both match, and the value also
1235 // matches.
1236 pi1_event_loop->MakeWatcher(
1237 "/test", [&pi1_event_loop, &pi1_ping_count,
1238 &pi1_pong_count](const examples::Pong &pong) {
1239 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1240 << pi1_event_loop->context().monotonic_remote_time << " -> "
1241 << pi1_event_loop->context().monotonic_event_time;
1242
1243 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1244 pi1_pong_count + kQueueIndexOffset);
1245 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1246 chrono::microseconds(200) +
1247 pi1_pong_count * chrono::milliseconds(10) +
1248 monotonic_clock::epoch());
1249 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1250 chrono::microseconds(200) +
1251 pi1_pong_count * chrono::milliseconds(10) +
1252 realtime_clock::epoch());
1253
1254 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1255 chrono::microseconds(150),
1256 pi1_event_loop->context().monotonic_event_time);
1257 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1258 chrono::microseconds(150),
1259 pi1_event_loop->context().realtime_event_time);
1260
1261 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1262 ++pi1_pong_count;
1263 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1264 });
1265 pi2_event_loop->MakeWatcher(
1266 "/test", [&pi2_event_loop, &pi2_ping_count,
1267 &pi2_pong_count](const examples::Pong &pong) {
1268 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1269 << pi2_event_loop->context().monotonic_remote_time << " -> "
1270 << pi2_event_loop->context().monotonic_event_time;
1271
1272 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001273 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001274
1275 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1276 chrono::microseconds(200) +
1277 pi2_pong_count * chrono::milliseconds(10) +
1278 monotonic_clock::epoch());
1279 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1280 chrono::microseconds(200) +
1281 pi2_pong_count * chrono::milliseconds(10) +
1282 realtime_clock::epoch());
1283
1284 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1285 pi2_event_loop->context().monotonic_event_time);
1286 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1287 pi2_event_loop->context().realtime_event_time);
1288
1289 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1290 ++pi2_pong_count;
1291 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1292 });
1293
1294 log_reader_factory.Run();
1295 EXPECT_EQ(pi1_ping_count, 2010);
1296 EXPECT_EQ(pi2_ping_count, 2010);
1297 EXPECT_EQ(pi1_pong_count, 2010);
1298 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001299
1300 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001301}
1302
James Kuszmaul46d82582020-05-09 19:50:09 -07001303typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1304
1305// Test that if we feed the replay with a mismatched node list that we die on
1306// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001307TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001308 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001309 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001310 LoggerState pi1_logger = MakeLogger(pi1_);
1311 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001312
1313 event_loop_factory_.RunFor(chrono::milliseconds(95));
1314
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001315 StartLogger(&pi1_logger);
1316 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001317
James Kuszmaul46d82582020-05-09 19:50:09 -07001318 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1319 }
1320
1321 // Test that, if we add an additional node to the replay config that the
1322 // logger complains about the mismatch in number of nodes.
1323 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1324 configuration::MergeWithConfig(&config_.message(), R"({
1325 "nodes": [
1326 {
1327 "name": "extra-node"
1328 }
1329 ]
1330 }
1331 )");
1332
Austin Schuh287d43d2020-12-04 20:19:33 -08001333 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1334 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001335 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001336}
1337
Austin Schuhcde938c2020-02-02 17:30:07 -08001338// Tests that we can read log files where they don't start at the same monotonic
1339// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001340TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001341 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001342 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001343 LoggerState pi1_logger = MakeLogger(pi1_);
1344 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001345
1346 event_loop_factory_.RunFor(chrono::milliseconds(95));
1347
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001348 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001349
1350 event_loop_factory_.RunFor(chrono::milliseconds(200));
1351
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001352 StartLogger(&pi2_logger);
1353
Austin Schuhcde938c2020-02-02 17:30:07 -08001354 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1355 }
1356
Austin Schuhe46492f2021-07-31 19:49:41 -07001357 // Since we delay starting pi2, it already knows about all the timestamps so
1358 // we don't end up with extra parts.
1359 LogReader reader(
1360 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001361
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001362 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001363 log_reader_factory.set_send_delay(chrono::microseconds(0));
1364
1365 // This sends out the fetched messages and advances time to the start of the
1366 // log file.
1367 reader.Register(&log_reader_factory);
1368
1369 const Node *pi1 =
1370 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1371 const Node *pi2 =
1372 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1373
Austin Schuh07676622021-01-21 18:59:17 -08001374 EXPECT_THAT(reader.LoggedNodes(),
1375 ::testing::ElementsAre(
1376 configuration::GetNode(reader.logged_configuration(), pi1),
1377 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001378
1379 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1380
1381 std::unique_ptr<EventLoop> pi1_event_loop =
1382 log_reader_factory.MakeEventLoop("test", pi1);
1383 std::unique_ptr<EventLoop> pi2_event_loop =
1384 log_reader_factory.MakeEventLoop("test", pi2);
1385
1386 int pi1_ping_count = 30;
1387 int pi2_ping_count = 30;
1388 int pi1_pong_count = 30;
1389 int pi2_pong_count = 30;
1390
1391 // Confirm that the ping value matches.
1392 pi1_event_loop->MakeWatcher(
1393 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1394 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1395 << pi1_event_loop->context().monotonic_remote_time << " -> "
1396 << pi1_event_loop->context().monotonic_event_time;
1397 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1398
1399 ++pi1_ping_count;
1400 });
1401 pi2_event_loop->MakeWatcher(
1402 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1403 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1404 << pi2_event_loop->context().monotonic_remote_time << " -> "
1405 << pi2_event_loop->context().monotonic_event_time;
1406 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1407
1408 ++pi2_ping_count;
1409 });
1410
1411 // Confirm that the ping and pong counts both match, and the value also
1412 // matches.
1413 pi1_event_loop->MakeWatcher(
1414 "/test", [&pi1_event_loop, &pi1_ping_count,
1415 &pi1_pong_count](const examples::Pong &pong) {
1416 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1417 << pi1_event_loop->context().monotonic_remote_time << " -> "
1418 << pi1_event_loop->context().monotonic_event_time;
1419
1420 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1421 ++pi1_pong_count;
1422 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1423 });
1424 pi2_event_loop->MakeWatcher(
1425 "/test", [&pi2_event_loop, &pi2_ping_count,
1426 &pi2_pong_count](const examples::Pong &pong) {
1427 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1428 << pi2_event_loop->context().monotonic_remote_time << " -> "
1429 << pi2_event_loop->context().monotonic_event_time;
1430
1431 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1432 ++pi2_pong_count;
1433 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1434 });
1435
1436 log_reader_factory.Run();
1437 EXPECT_EQ(pi1_ping_count, 2030);
1438 EXPECT_EQ(pi2_ping_count, 2030);
1439 EXPECT_EQ(pi1_pong_count, 2030);
1440 EXPECT_EQ(pi2_pong_count, 2030);
1441
1442 reader.Deregister();
1443}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001444
Austin Schuh8bd96322020-02-13 21:18:22 -08001445// Tests that we can read log files where the monotonic clocks drift and don't
1446// match correctly. While we are here, also test that different ending times
1447// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001448TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001449 // TODO(austin): Negate...
1450 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1451
1452 time_converter_.AddMonotonic({monotonic_clock::epoch(),
1453 monotonic_clock::epoch() + initial_pi2_offset});
1454 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1455 // skew to be 200 uS/s
1456 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1457 {chrono::milliseconds(95),
1458 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1459 // Run another 200 ms to have one logger start first.
1460 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1461 {chrono::milliseconds(200), chrono::milliseconds(200)});
1462 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1463 // go far enough to cause problems if this isn't accounted for.
1464 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1465 {chrono::milliseconds(20000),
1466 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1467 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1468 {chrono::milliseconds(40000),
1469 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1470 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1471 {chrono::milliseconds(400), chrono::milliseconds(400)});
1472
Austin Schuhcde938c2020-02-02 17:30:07 -08001473 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001474 LoggerState pi2_logger = MakeLogger(pi2_);
1475
Austin Schuh87dd3832021-01-01 23:07:31 -08001476 NodeEventLoopFactory *pi1 =
1477 event_loop_factory_.GetNodeEventLoopFactory(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001478 NodeEventLoopFactory *pi2 =
1479 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1480 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1481 << pi2->realtime_now() << " distributed "
1482 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001483
Austin Schuh8bd96322020-02-13 21:18:22 -08001484 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1485 << pi2->realtime_now() << " distributed "
1486 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001487
Austin Schuh87dd3832021-01-01 23:07:31 -08001488 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001489
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001490 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001491
Austin Schuh87dd3832021-01-01 23:07:31 -08001492 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001493
Austin Schuh8bd96322020-02-13 21:18:22 -08001494 {
1495 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001496 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001497
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001498 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001499 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001500
Austin Schuh87dd3832021-01-01 23:07:31 -08001501 // Make sure we slewed time far enough so that the difference is greater
1502 // than the network delay. This confirms that if we sort incorrectly, it
1503 // would show in the results.
1504 EXPECT_LT(
1505 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1506 -event_loop_factory_.send_delay() -
1507 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001508
Austin Schuh87dd3832021-01-01 23:07:31 -08001509 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001510
Austin Schuh87dd3832021-01-01 23:07:31 -08001511 // And now check that we went far enough the other way to make sure we
1512 // cover both problems.
1513 EXPECT_GT(
1514 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1515 event_loop_factory_.send_delay() +
1516 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001517 }
1518
1519 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001520 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001521 }
1522
Austin Schuh72211ae2021-08-05 14:02:30 -07001523 LogReader reader(
1524 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001525
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001526 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001527 log_reader_factory.set_send_delay(chrono::microseconds(0));
1528
Austin Schuhcde938c2020-02-02 17:30:07 -08001529 const Node *pi1 =
1530 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1531 const Node *pi2 =
1532 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1533
Austin Schuh2f8fd752020-09-01 22:38:28 -07001534 // This sends out the fetched messages and advances time to the start of the
1535 // log file.
1536 reader.Register(&log_reader_factory);
1537
1538 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1539 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1540 LOG(INFO) << "now pi1 "
1541 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1542 LOG(INFO) << "now pi2 "
1543 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1544
Austin Schuhcde938c2020-02-02 17:30:07 -08001545 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001546 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1547 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001548 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1549 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001550 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1551 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001552 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1553
Austin Schuh07676622021-01-21 18:59:17 -08001554 EXPECT_THAT(reader.LoggedNodes(),
1555 ::testing::ElementsAre(
1556 configuration::GetNode(reader.logged_configuration(), pi1),
1557 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001558
1559 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1560
1561 std::unique_ptr<EventLoop> pi1_event_loop =
1562 log_reader_factory.MakeEventLoop("test", pi1);
1563 std::unique_ptr<EventLoop> pi2_event_loop =
1564 log_reader_factory.MakeEventLoop("test", pi2);
1565
1566 int pi1_ping_count = 30;
1567 int pi2_ping_count = 30;
1568 int pi1_pong_count = 30;
1569 int pi2_pong_count = 30;
1570
1571 // Confirm that the ping value matches.
1572 pi1_event_loop->MakeWatcher(
1573 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1574 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1575 << pi1_event_loop->context().monotonic_remote_time << " -> "
1576 << pi1_event_loop->context().monotonic_event_time;
1577 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1578
1579 ++pi1_ping_count;
1580 });
1581 pi2_event_loop->MakeWatcher(
1582 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1583 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1584 << pi2_event_loop->context().monotonic_remote_time << " -> "
1585 << pi2_event_loop->context().monotonic_event_time;
1586 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1587
1588 ++pi2_ping_count;
1589 });
1590
1591 // Confirm that the ping and pong counts both match, and the value also
1592 // matches.
1593 pi1_event_loop->MakeWatcher(
1594 "/test", [&pi1_event_loop, &pi1_ping_count,
1595 &pi1_pong_count](const examples::Pong &pong) {
1596 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1597 << pi1_event_loop->context().monotonic_remote_time << " -> "
1598 << pi1_event_loop->context().monotonic_event_time;
1599
1600 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1601 ++pi1_pong_count;
1602 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1603 });
1604 pi2_event_loop->MakeWatcher(
1605 "/test", [&pi2_event_loop, &pi2_ping_count,
1606 &pi2_pong_count](const examples::Pong &pong) {
1607 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1608 << pi2_event_loop->context().monotonic_remote_time << " -> "
1609 << pi2_event_loop->context().monotonic_event_time;
1610
1611 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1612 ++pi2_pong_count;
1613 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1614 });
1615
1616 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001617 EXPECT_EQ(pi1_ping_count, 6030);
1618 EXPECT_EQ(pi2_ping_count, 6030);
1619 EXPECT_EQ(pi1_pong_count, 6030);
1620 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001621
1622 reader.Deregister();
1623}
1624
Austin Schuh5212cad2020-09-09 23:12:09 -07001625// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001626TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001627 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001628 // Make a bunch of parts.
1629 {
1630 LoggerState pi1_logger = MakeLogger(pi1_);
1631 LoggerState pi2_logger = MakeLogger(pi2_);
1632
1633 event_loop_factory_.RunFor(chrono::milliseconds(95));
1634
1635 StartLogger(&pi1_logger);
1636 StartLogger(&pi2_logger);
1637
1638 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1639 }
1640
Austin Schuh11d43732020-09-21 17:28:30 -07001641 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001642 VerifyParts(sorted_parts);
1643}
Austin Schuh11d43732020-09-21 17:28:30 -07001644
Austin Schuh3bd4c402020-11-06 18:19:06 -08001645// Tests that we can sort a bunch of parts with an empty part. We should ignore
1646// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001647TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001648 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001649 // Make a bunch of parts.
1650 {
1651 LoggerState pi1_logger = MakeLogger(pi1_);
1652 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001653
Austin Schuh3bd4c402020-11-06 18:19:06 -08001654 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001655
Austin Schuh3bd4c402020-11-06 18:19:06 -08001656 StartLogger(&pi1_logger);
1657 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001658
Austin Schuh3bd4c402020-11-06 18:19:06 -08001659 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001660 }
1661
Austin Schuh3bd4c402020-11-06 18:19:06 -08001662 // TODO(austin): Should we flip out if the file can't open?
1663 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001664
Austin Schuh3bd4c402020-11-06 18:19:06 -08001665 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1666 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001667
Austin Schuh3bd4c402020-11-06 18:19:06 -08001668 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1669 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001670}
1671
Austin Schuh3bd4c402020-11-06 18:19:06 -08001672#ifdef LZMA
1673// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1674// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001675TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001676 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001677 // Make a bunch of parts.
1678 {
1679 LoggerState pi1_logger = MakeLogger(pi1_);
1680 LoggerState pi2_logger = MakeLogger(pi2_);
1681
1682 event_loop_factory_.RunFor(chrono::milliseconds(95));
1683
1684 StartLogger(&pi1_logger, "", true);
1685 StartLogger(&pi2_logger, "", true);
1686
1687 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1688 }
1689
1690 // TODO(austin): Should we flip out if the file can't open?
1691 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1692
1693 AddExtension(".xz");
1694
1695 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1696 logfiles_.emplace_back(kEmptyFile);
1697
1698 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1699 VerifyParts(sorted_parts, {kEmptyFile});
1700}
1701
1702// Tests that we can sort a bunch of parts with the end missing off a compressed
1703// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001704TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001705 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001706 // Make a bunch of parts.
1707 {
1708 LoggerState pi1_logger = MakeLogger(pi1_);
1709 LoggerState pi2_logger = MakeLogger(pi2_);
1710
1711 event_loop_factory_.RunFor(chrono::milliseconds(95));
1712
1713 StartLogger(&pi1_logger, "", true);
1714 StartLogger(&pi2_logger, "", true);
1715
1716 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1717 }
1718
1719 // Append everything with .xz.
1720 AddExtension(".xz");
1721
1722 // Strip off the end of one of the files. Pick one with a lot of data.
1723 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001724 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001725
1726 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001727 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001728 compressed_contents.substr(0, compressed_contents.size() - 100));
1729
1730 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1731 VerifyParts(sorted_parts);
1732}
1733#endif
1734
Austin Schuh01b4c352020-09-21 23:09:39 -07001735// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001736TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001737 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001738 {
1739 LoggerState pi1_logger = MakeLogger(pi1_);
1740 LoggerState pi2_logger = MakeLogger(pi2_);
1741
1742 event_loop_factory_.RunFor(chrono::milliseconds(95));
1743
1744 StartLogger(&pi1_logger);
1745 StartLogger(&pi2_logger);
1746
1747 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1748 }
1749
Austin Schuh287d43d2020-12-04 20:19:33 -08001750 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001751
1752 // Remap just on pi1.
1753 reader.RemapLoggedChannel<aos::timing::Report>(
1754 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1755
1756 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1757 log_reader_factory.set_send_delay(chrono::microseconds(0));
1758
1759 reader.Register(&log_reader_factory);
1760
1761 const Node *pi1 =
1762 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1763 const Node *pi2 =
1764 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1765
1766 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1767 // else should have moved.
1768 std::unique_ptr<EventLoop> pi1_event_loop =
1769 log_reader_factory.MakeEventLoop("test", pi1);
1770 pi1_event_loop->SkipTimingReport();
1771 std::unique_ptr<EventLoop> full_pi1_event_loop =
1772 log_reader_factory.MakeEventLoop("test", pi1);
1773 full_pi1_event_loop->SkipTimingReport();
1774 std::unique_ptr<EventLoop> pi2_event_loop =
1775 log_reader_factory.MakeEventLoop("test", pi2);
1776 pi2_event_loop->SkipTimingReport();
1777
1778 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1779 "/aos");
1780 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1781 full_pi1_event_loop.get(), "/pi1/aos");
1782 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1783 pi1_event_loop.get(), "/original/aos");
1784 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1785 full_pi1_event_loop.get(), "/original/pi1/aos");
1786 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1787 "/aos");
1788
1789 log_reader_factory.Run();
1790
1791 EXPECT_EQ(pi1_timing_report.count(), 0u);
1792 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1793 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1794 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1795 EXPECT_NE(pi2_timing_report.count(), 0u);
1796
1797 reader.Deregister();
1798}
1799
Austin Schuh006a9f52021-04-07 16:24:18 -07001800// Tests that we can remap a forwarded channel as well.
1801TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1802 time_converter_.StartEqual();
1803 {
1804 LoggerState pi1_logger = MakeLogger(pi1_);
1805 LoggerState pi2_logger = MakeLogger(pi2_);
1806
1807 event_loop_factory_.RunFor(chrono::milliseconds(95));
1808
1809 StartLogger(&pi1_logger);
1810 StartLogger(&pi2_logger);
1811
1812 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1813 }
1814
1815 LogReader reader(SortParts(logfiles_));
1816
1817 reader.RemapLoggedChannel<examples::Ping>("/test");
1818
1819 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1820 log_reader_factory.set_send_delay(chrono::microseconds(0));
1821
1822 reader.Register(&log_reader_factory);
1823
1824 const Node *pi1 =
1825 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1826 const Node *pi2 =
1827 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1828
1829 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1830 // else should have moved.
1831 std::unique_ptr<EventLoop> pi1_event_loop =
1832 log_reader_factory.MakeEventLoop("test", pi1);
1833 pi1_event_loop->SkipTimingReport();
1834 std::unique_ptr<EventLoop> full_pi1_event_loop =
1835 log_reader_factory.MakeEventLoop("test", pi1);
1836 full_pi1_event_loop->SkipTimingReport();
1837 std::unique_ptr<EventLoop> pi2_event_loop =
1838 log_reader_factory.MakeEventLoop("test", pi2);
1839 pi2_event_loop->SkipTimingReport();
1840
1841 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1842 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1843 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1844 "/original/test");
1845 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1846 "/original/test");
1847
1848 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1849 pi1_original_ping_timestamp;
1850 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1851 pi1_ping_timestamp;
1852 if (!shared()) {
1853 pi1_original_ping_timestamp =
1854 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1855 pi1_event_loop.get(),
1856 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1857 pi1_ping_timestamp =
1858 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1859 pi1_event_loop.get(),
1860 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1861 }
1862
1863 log_reader_factory.Run();
1864
1865 EXPECT_EQ(pi1_ping.count(), 0u);
1866 EXPECT_EQ(pi2_ping.count(), 0u);
1867 EXPECT_NE(pi1_original_ping.count(), 0u);
1868 EXPECT_NE(pi2_original_ping.count(), 0u);
1869 if (!shared()) {
1870 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1871 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1872 }
1873
1874 reader.Deregister();
1875}
1876
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001877// Tests that we properly recreate forwarded timestamps when replaying a log.
1878// This should be enough that we can then re-run the logger and get a valid log
1879// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001880TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001881 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001882 {
1883 LoggerState pi1_logger = MakeLogger(pi1_);
1884 LoggerState pi2_logger = MakeLogger(pi2_);
1885
1886 event_loop_factory_.RunFor(chrono::milliseconds(95));
1887
1888 StartLogger(&pi1_logger);
1889 StartLogger(&pi2_logger);
1890
1891 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1892 }
1893
Austin Schuh287d43d2020-12-04 20:19:33 -08001894 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001895
1896 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1897 log_reader_factory.set_send_delay(chrono::microseconds(0));
1898
1899 // This sends out the fetched messages and advances time to the start of the
1900 // log file.
1901 reader.Register(&log_reader_factory);
1902
1903 const Node *pi1 =
1904 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1905 const Node *pi2 =
1906 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1907
1908 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1909 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1910 LOG(INFO) << "now pi1 "
1911 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1912 LOG(INFO) << "now pi2 "
1913 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1914
Austin Schuh07676622021-01-21 18:59:17 -08001915 EXPECT_THAT(reader.LoggedNodes(),
1916 ::testing::ElementsAre(
1917 configuration::GetNode(reader.logged_configuration(), pi1),
1918 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001919
1920 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1921
1922 std::unique_ptr<EventLoop> pi1_event_loop =
1923 log_reader_factory.MakeEventLoop("test", pi1);
1924 std::unique_ptr<EventLoop> pi2_event_loop =
1925 log_reader_factory.MakeEventLoop("test", pi2);
1926
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001927 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1928 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1929 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1930 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1931
1932 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1933 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1934 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1935 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1936
1937 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1938 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1939 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1940 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1941
1942 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1943 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1944 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1945 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1946
1947 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1948 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1949 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1950 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1951
1952 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1953 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1954 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1955 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1956
Austin Schuh969cd602021-01-03 00:09:45 -08001957 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001958 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001959
Austin Schuh61e973f2021-02-21 21:43:56 -08001960 for (std::pair<int, std::string> channel :
1961 shared()
1962 ? std::vector<
1963 std::pair<int, std::string>>{{-1,
1964 "/aos/remote_timestamps/pi2"}}
1965 : std::vector<std::pair<int, std::string>>{
1966 {pi1_timestamp_channel,
1967 "/aos/remote_timestamps/pi2/pi1/aos/"
1968 "aos-message_bridge-Timestamp"},
1969 {ping_timestamp_channel,
1970 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1971 pi1_event_loop->MakeWatcher(
1972 channel.second,
1973 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1974 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1975 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1976 &ping_on_pi2_fetcher, network_delay, send_delay,
1977 channel_index = channel.first](const RemoteMessage &header) {
1978 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1979 chrono::nanoseconds(header.monotonic_sent_time()));
1980 const aos::realtime_clock::time_point header_realtime_sent_time(
1981 chrono::nanoseconds(header.realtime_sent_time()));
1982 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1983 chrono::nanoseconds(header.monotonic_remote_time()));
1984 const aos::realtime_clock::time_point header_realtime_remote_time(
1985 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001986
Austin Schuh61e973f2021-02-21 21:43:56 -08001987 if (channel_index != -1) {
1988 ASSERT_EQ(channel_index, header.channel_index());
1989 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001990
Austin Schuh61e973f2021-02-21 21:43:56 -08001991 const Context *pi1_context = nullptr;
1992 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001993
Austin Schuh61e973f2021-02-21 21:43:56 -08001994 if (header.channel_index() == pi1_timestamp_channel) {
1995 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
1996 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
1997 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
1998 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
1999 } else if (header.channel_index() == ping_timestamp_channel) {
2000 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2001 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2002 pi1_context = &ping_on_pi1_fetcher.context();
2003 pi2_context = &ping_on_pi2_fetcher.context();
2004 } else {
2005 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2006 << configuration::CleanedChannelToString(
2007 pi1_event_loop->configuration()->channels()->Get(
2008 header.channel_index()));
2009 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002010
Austin Schuh61e973f2021-02-21 21:43:56 -08002011 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002012 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2013 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002014
Austin Schuh61e973f2021-02-21 21:43:56 -08002015 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2016 EXPECT_EQ(pi2_context->remote_queue_index,
2017 header.remote_queue_index());
2018 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002019
Austin Schuh61e973f2021-02-21 21:43:56 -08002020 EXPECT_EQ(pi2_context->monotonic_event_time,
2021 header_monotonic_sent_time);
2022 EXPECT_EQ(pi2_context->realtime_event_time,
2023 header_realtime_sent_time);
2024 EXPECT_EQ(pi2_context->realtime_remote_time,
2025 header_realtime_remote_time);
2026 EXPECT_EQ(pi2_context->monotonic_remote_time,
2027 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002028
Austin Schuh61e973f2021-02-21 21:43:56 -08002029 EXPECT_EQ(pi1_context->realtime_event_time,
2030 header_realtime_remote_time);
2031 EXPECT_EQ(pi1_context->monotonic_event_time,
2032 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002033
Austin Schuh61e973f2021-02-21 21:43:56 -08002034 // Time estimation isn't perfect, but we know the clocks were
2035 // identical when logged, so we know when this should have come back.
2036 // Confirm we got it when we expected.
2037 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2038 pi1_context->monotonic_event_time + 2 * network_delay +
2039 send_delay);
2040 });
2041 }
2042 for (std::pair<int, std::string> channel :
2043 shared()
2044 ? std::vector<
2045 std::pair<int, std::string>>{{-1,
2046 "/aos/remote_timestamps/pi1"}}
2047 : std::vector<std::pair<int, std::string>>{
2048 {pi2_timestamp_channel,
2049 "/aos/remote_timestamps/pi1/pi2/aos/"
2050 "aos-message_bridge-Timestamp"}}) {
2051 pi2_event_loop->MakeWatcher(
2052 channel.second,
2053 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2054 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2055 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2056 &pong_on_pi1_fetcher, network_delay, send_delay,
2057 channel_index = channel.first](const RemoteMessage &header) {
2058 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2059 chrono::nanoseconds(header.monotonic_sent_time()));
2060 const aos::realtime_clock::time_point header_realtime_sent_time(
2061 chrono::nanoseconds(header.realtime_sent_time()));
2062 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2063 chrono::nanoseconds(header.monotonic_remote_time()));
2064 const aos::realtime_clock::time_point header_realtime_remote_time(
2065 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002066
Austin Schuh61e973f2021-02-21 21:43:56 -08002067 if (channel_index != -1) {
2068 ASSERT_EQ(channel_index, header.channel_index());
2069 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002070
Austin Schuh61e973f2021-02-21 21:43:56 -08002071 const Context *pi2_context = nullptr;
2072 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002073
Austin Schuh61e973f2021-02-21 21:43:56 -08002074 if (header.channel_index() == pi2_timestamp_channel) {
2075 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2076 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2077 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2078 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2079 } else if (header.channel_index() == pong_timestamp_channel) {
2080 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2081 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2082 pi2_context = &pong_on_pi2_fetcher.context();
2083 pi1_context = &pong_on_pi1_fetcher.context();
2084 } else {
2085 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2086 << configuration::CleanedChannelToString(
2087 pi2_event_loop->configuration()->channels()->Get(
2088 header.channel_index()));
2089 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002090
Austin Schuh61e973f2021-02-21 21:43:56 -08002091 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002092 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2093 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002094
Austin Schuh61e973f2021-02-21 21:43:56 -08002095 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2096 EXPECT_EQ(pi1_context->remote_queue_index,
2097 header.remote_queue_index());
2098 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002099
Austin Schuh61e973f2021-02-21 21:43:56 -08002100 EXPECT_EQ(pi1_context->monotonic_event_time,
2101 header_monotonic_sent_time);
2102 EXPECT_EQ(pi1_context->realtime_event_time,
2103 header_realtime_sent_time);
2104 EXPECT_EQ(pi1_context->realtime_remote_time,
2105 header_realtime_remote_time);
2106 EXPECT_EQ(pi1_context->monotonic_remote_time,
2107 header_monotonic_remote_time);
2108
2109 EXPECT_EQ(pi2_context->realtime_event_time,
2110 header_realtime_remote_time);
2111 EXPECT_EQ(pi2_context->monotonic_event_time,
2112 header_monotonic_remote_time);
2113
2114 // Time estimation isn't perfect, but we know the clocks were
2115 // identical when logged, so we know when this should have come back.
2116 // Confirm we got it when we expected.
2117 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2118 pi2_context->monotonic_event_time + 2 * network_delay +
2119 send_delay);
2120 });
2121 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002122
2123 // And confirm we can re-create a log again, while checking the contents.
2124 {
2125 LoggerState pi1_logger = MakeLogger(
2126 configuration::GetNode(log_reader_factory.configuration(), pi1_),
2127 &log_reader_factory);
2128 LoggerState pi2_logger = MakeLogger(
2129 configuration::GetNode(log_reader_factory.configuration(), pi2_),
2130 &log_reader_factory);
2131
Austin Schuh25b46712021-01-03 00:04:38 -08002132 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2133 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002134
2135 log_reader_factory.Run();
2136 }
2137
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002138 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002139
2140 // And verify that we can run the LogReader over the relogged files without
2141 // hitting any fatal errors.
2142 {
2143 LogReader relogged_reader(SortParts(
2144 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2145 relogged_reader.Register();
2146
2147 relogged_reader.event_loop_factory()->Run();
2148 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002149}
2150
Austin Schuh315b96b2020-12-11 21:21:12 -08002151// Tests that we properly populate and extract the logger_start time by setting
2152// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002153TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002154 time_converter_.AddMonotonic(
2155 {monotonic_clock::epoch(),
2156 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002157 {
2158 LoggerState pi1_logger = MakeLogger(pi1_);
2159 LoggerState pi2_logger = MakeLogger(pi2_);
2160
Austin Schuh315b96b2020-12-11 21:21:12 -08002161 StartLogger(&pi1_logger);
2162 StartLogger(&pi2_logger);
2163
2164 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2165 }
2166
2167 for (const LogFile &log_file : SortParts(logfiles_)) {
2168 for (const LogParts &log_part : log_file.parts) {
2169 if (log_part.node == log_file.logger_node) {
2170 EXPECT_EQ(log_part.logger_monotonic_start_time,
2171 aos::monotonic_clock::min_time);
2172 EXPECT_EQ(log_part.logger_realtime_start_time,
2173 aos::realtime_clock::min_time);
2174 } else {
2175 const chrono::seconds offset = log_file.logger_node == "pi1"
2176 ? -chrono::seconds(1000)
2177 : chrono::seconds(1000);
2178 EXPECT_EQ(log_part.logger_monotonic_start_time,
2179 log_part.monotonic_start_time + offset);
2180 EXPECT_EQ(log_part.logger_realtime_start_time,
2181 log_file.realtime_start_time +
2182 (log_part.logger_monotonic_start_time -
2183 log_file.monotonic_start_time));
2184 }
2185 }
2186 }
2187}
2188
Austin Schuh6bb8a822021-03-31 23:04:39 -07002189// Test that renaming the base, renames the folder.
2190TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002191 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2192 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002193 time_converter_.AddMonotonic(
2194 {monotonic_clock::epoch(),
2195 monotonic_clock::epoch() + chrono::seconds(1000)});
2196 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2197 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2198 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2199 LoggerState pi1_logger = MakeLogger(pi1_);
2200 LoggerState pi2_logger = MakeLogger(pi2_);
2201
2202 StartLogger(&pi1_logger);
2203 StartLogger(&pi2_logger);
2204
2205 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2206 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2207 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2208 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2209 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2210 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2211 for (auto &file : logfiles_) {
2212 struct stat s;
2213 EXPECT_EQ(0, stat(file.c_str(), &s));
2214 }
2215}
2216
2217// Test that renaming the file base dies.
2218TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2219 time_converter_.AddMonotonic(
2220 {monotonic_clock::epoch(),
2221 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002222 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002223 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2224 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2225 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2226 LoggerState pi1_logger = MakeLogger(pi1_);
2227 StartLogger(&pi1_logger);
2228 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2229 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2230 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2231 "Rename of file base from");
2232}
2233
Austin Schuh8bd96322020-02-13 21:18:22 -08002234// TODO(austin): We can write a test which recreates a logfile and confirms that
2235// we get it back. That is the ultimate test.
2236
Austin Schuh315b96b2020-12-11 21:21:12 -08002237// Tests that we properly recreate forwarded timestamps when replaying a log.
2238// This should be enough that we can then re-run the logger and get a valid log
2239// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002240TEST_P(MultinodeLoggerDeathTest, RemoteReboot) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002241 time_converter_.StartEqual();
Austin Schuh315b96b2020-12-11 21:21:12 -08002242 std::string pi2_boot1;
2243 std::string pi2_boot2;
2244 {
2245 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2246 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002247 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002248 LoggerState pi1_logger = MakeLogger(pi1_);
2249
2250 event_loop_factory_.RunFor(chrono::milliseconds(95));
2251
2252 StartLogger(&pi1_logger);
2253
2254 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2255
2256 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
2257
2258 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2259 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002260 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002261
2262 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2263 }
2264
Austin Schuh72211ae2021-08-05 14:02:30 -07002265 // Confirm that our new oldest timestamps properly update as we reboot and
2266 // rotate.
2267 for (const std::string &file : pi1_reboot_logfiles_) {
2268 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2269 ReadHeader(file);
2270 CHECK(log_header);
2271 if (log_header->message().has_configuration()) {
2272 continue;
2273 }
2274
2275 if (log_header->message().node()->name()->string_view() != "pi1") {
2276 continue;
2277 }
2278 SCOPED_TRACE(file);
2279 SCOPED_TRACE(aos::FlatbufferToJson(
2280 *log_header, {.multi_line = true, .max_vector_size = 100}));
2281 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2282 ASSERT_EQ(
2283 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2284 EXPECT_EQ(
2285 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2286 monotonic_clock::max_time.time_since_epoch().count());
2287 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2288 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2289 2u);
2290 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2291 monotonic_clock::max_time.time_since_epoch().count());
2292 ASSERT_TRUE(log_header->message()
2293 .has_oldest_remote_unreliable_monotonic_timestamps());
2294 ASSERT_EQ(log_header->message()
2295 .oldest_remote_unreliable_monotonic_timestamps()
2296 ->size(),
2297 2u);
2298 EXPECT_EQ(log_header->message()
2299 .oldest_remote_unreliable_monotonic_timestamps()
2300 ->Get(0),
2301 monotonic_clock::max_time.time_since_epoch().count());
2302 ASSERT_TRUE(log_header->message()
2303 .has_oldest_local_unreliable_monotonic_timestamps());
2304 ASSERT_EQ(log_header->message()
2305 .oldest_local_unreliable_monotonic_timestamps()
2306 ->size(),
2307 2u);
2308 EXPECT_EQ(log_header->message()
2309 .oldest_local_unreliable_monotonic_timestamps()
2310 ->Get(0),
2311 monotonic_clock::max_time.time_since_epoch().count());
2312
2313 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2314 monotonic_clock::time_point(chrono::nanoseconds(
2315 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2316 1)));
2317 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2318 monotonic_clock::time_point(chrono::nanoseconds(
2319 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2320 const monotonic_clock::time_point
2321 oldest_remote_unreliable_monotonic_timestamps =
2322 monotonic_clock::time_point(chrono::nanoseconds(
2323 log_header->message()
2324 .oldest_remote_unreliable_monotonic_timestamps()
2325 ->Get(1)));
2326 const monotonic_clock::time_point
2327 oldest_local_unreliable_monotonic_timestamps =
2328 monotonic_clock::time_point(chrono::nanoseconds(
2329 log_header->message()
2330 .oldest_local_unreliable_monotonic_timestamps()
2331 ->Get(1)));
2332 switch (log_header->message().parts_index()) {
2333 case 0:
2334 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2335 monotonic_clock::max_time);
2336 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2337 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2338 monotonic_clock::max_time);
2339 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2340 monotonic_clock::max_time);
2341 break;
2342 case 1:
2343 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2344 monotonic_clock::time_point(chrono::microseconds(90200)));
2345 EXPECT_EQ(oldest_local_monotonic_timestamps,
2346 monotonic_clock::time_point(chrono::microseconds(90350)));
2347 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2348 monotonic_clock::time_point(chrono::microseconds(90200)));
2349 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2350 monotonic_clock::time_point(chrono::microseconds(90350)));
2351 break;
2352 case 2:
2353 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2354 monotonic_clock::time_point(chrono::microseconds(10100000)));
2355 EXPECT_EQ(oldest_local_monotonic_timestamps,
2356 monotonic_clock::time_point(chrono::microseconds(10100150)));
2357 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2358 monotonic_clock::max_time);
2359 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2360 monotonic_clock::max_time);
2361 break;
2362 case 3:
2363 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2364 monotonic_clock::time_point(chrono::microseconds(10100000)));
2365 EXPECT_EQ(oldest_local_monotonic_timestamps,
2366 monotonic_clock::time_point(chrono::microseconds(10100150)));
2367 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2368 monotonic_clock::time_point(chrono::microseconds(10100200)));
2369 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2370 monotonic_clock::time_point(chrono::microseconds(10100350)));
2371 break;
2372 default:
2373 FAIL();
2374 break;
2375 }
2376 }
2377
Austin Schuh315b96b2020-12-11 21:21:12 -08002378 // Confirm that we refuse to replay logs with missing boot uuids.
2379 EXPECT_DEATH(
2380 {
2381 LogReader reader(SortParts(pi1_reboot_logfiles_));
2382
2383 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2384 log_reader_factory.set_send_delay(chrono::microseconds(0));
2385
2386 // This sends out the fetched messages and advances time to the start of
2387 // the log file.
2388 reader.Register(&log_reader_factory);
2389 },
2390 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
2391 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
2392}
2393
Austin Schuhc9049732020-12-21 22:27:15 -08002394// Tests that we properly handle one direction of message_bridge being
2395// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002396TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002397 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002398 time_converter_.AddMonotonic(
2399 {monotonic_clock::epoch(),
2400 monotonic_clock::epoch() + chrono::seconds(1000)});
2401
2402 time_converter_.AddMonotonic(
2403 {chrono::milliseconds(10000),
2404 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002405 {
2406 LoggerState pi1_logger = MakeLogger(pi1_);
2407
2408 event_loop_factory_.RunFor(chrono::milliseconds(95));
2409
2410 StartLogger(&pi1_logger);
2411
2412 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2413 }
2414
2415 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2416 // to confirm the right thing happened.
2417 ConfirmReadable(pi1_single_direction_logfiles_);
2418}
2419
2420// Tests that we properly handle one direction of message_bridge being
2421// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002422TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002423 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002424 time_converter_.AddMonotonic(
2425 {monotonic_clock::epoch(),
2426 monotonic_clock::epoch() + chrono::seconds(500)});
2427
2428 time_converter_.AddMonotonic(
2429 {chrono::milliseconds(10000),
2430 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2431 {
2432 LoggerState pi1_logger = MakeLogger(pi1_);
2433
2434 event_loop_factory_.RunFor(chrono::milliseconds(95));
2435
2436 StartLogger(&pi1_logger);
2437
2438 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2439 }
2440
2441 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2442 // to confirm the right thing happened.
2443 ConfirmReadable(pi1_single_direction_logfiles_);
2444}
2445
2446// Tests that we properly handle a dead node. Do this by just disconnecting it
2447// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002448TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002449 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
2450 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
2451 time_converter_.AddMonotonic(
2452 {monotonic_clock::epoch(),
2453 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002454 {
2455 LoggerState pi1_logger = MakeLogger(pi1_);
2456
2457 event_loop_factory_.RunFor(chrono::milliseconds(95));
2458
2459 StartLogger(&pi1_logger);
2460
2461 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2462 }
2463
2464 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2465 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002466 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002467}
2468
Austin Schuhcdd90272021-03-15 12:46:16 -07002469constexpr std::string_view kCombinedConfigSha1(
milind945708b2021-07-03 13:30:15 -07002470 "4503751edc96327493562f0376f0d6daac172927c0fd64d04ce5d67505186c0b");
Austin Schuhcdd90272021-03-15 12:46:16 -07002471constexpr std::string_view kSplitConfigSha1(
milind945708b2021-07-03 13:30:15 -07002472 "918a748432c5e70a971dfd8934968378bed04ab61cf2efcd35b7f6224053c247");
Austin Schuhcdd90272021-03-15 12:46:16 -07002473
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002474INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002475 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002476 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2477 kCombinedConfigSha1},
2478 Param{"multinode_pingpong_split_config.json", false,
2479 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002480
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002481INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002482 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002483 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2484 kCombinedConfigSha1},
2485 Param{"multinode_pingpong_split_config.json", false,
2486 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002487
Austin Schuha04efed2021-01-24 18:04:20 -08002488// TODO(austin): Make a log file where the remote node has no start time.
2489
Austin Schuhe309d2a2019-11-29 13:25:21 -08002490} // namespace testing
2491} // namespace logger
2492} // namespace aos