blob: 8cad4863b3db03ee42cfe79808c82d17b8c13286 [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");
622 result.emplace_back(logfile_base1_ +
623 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
624 result.emplace_back(
625 logfile_base1_ +
626 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
627 result.emplace_back(
628 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
629
630 if (shared()) {
631 result.emplace_back(logfile_base1_ +
632 "_timestamps/pi1/aos/remote_timestamps/pi2/"
633 "aos.message_bridge.RemoteMessage.part0.bfbs");
634 } else {
635 result.emplace_back(logfile_base1_ +
636 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
637 "aos-message_bridge-Timestamp/"
638 "aos.message_bridge.RemoteMessage.part0.bfbs");
639 result.emplace_back(logfile_base1_ +
640 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
641 "aos-examples-Ping/"
642 "aos.message_bridge.RemoteMessage.part0.bfbs");
643 }
644 return result;
645 }
646
647 std::vector<std::vector<std::string>> StructureLogFiles() {
648 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700649 std::vector<std::string>{logfiles_[2], logfiles_[3]},
650 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800651 std::vector<std::string>{logfiles_[6], logfiles_[7]},
652 std::vector<std::string>{logfiles_[8], logfiles_[9]},
653 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700654 std::vector<std::string>{logfiles_[12], logfiles_[13]},
655 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800656
657 if (!shared()) {
658 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700659 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800660 }
661
662 return result;
663 }
664
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700665 struct LoggerState {
666 std::unique_ptr<EventLoop> event_loop;
667 std::unique_ptr<Logger> logger;
668 };
669
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700670 LoggerState MakeLogger(const Node *node,
671 SimulatedEventLoopFactory *factory = nullptr) {
672 if (factory == nullptr) {
673 factory = &event_loop_factory_;
674 }
675 return {factory->MakeEventLoop("logger", node), {}};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700676 }
677
Austin Schuh3bd4c402020-11-06 18:19:06 -0800678 void StartLogger(LoggerState *logger, std::string logfile_base = "",
679 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700680 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800681 if (logger->event_loop->node()->name()->string_view() == "pi1") {
682 logfile_base = logfile_base1_;
683 } else {
684 logfile_base = logfile_base2_;
685 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700686 }
687
Brian Silverman1f345222020-09-24 21:14:48 -0700688 logger->logger = std::make_unique<Logger>(logger->event_loop.get());
689 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800690 logger->logger->set_name(absl::StrCat(
691 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800692 logger->event_loop->OnRun([logger, logfile_base, compress]() {
693 std::unique_ptr<MultiNodeLogNamer> namer =
Austin Schuha499cea2021-07-31 19:49:53 -0700694 std::make_unique<MultiNodeLogNamer>(logfile_base,
695 logger->event_loop.get());
Austin Schuh3bd4c402020-11-06 18:19:06 -0800696 if (compress) {
697#ifdef LZMA
698 namer->set_extension(".xz");
699 namer->set_encoder_factory(
700 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
701#else
702 LOG(FATAL) << "Compression unsupported";
703#endif
704 }
705
706 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700707 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700708 }
Austin Schuh15649d62019-12-28 16:36:38 -0800709
Austin Schuh3bd4c402020-11-06 18:19:06 -0800710 void VerifyParts(const std::vector<LogFile> &sorted_parts,
711 const std::vector<std::string> &corrupted_parts = {}) {
712 EXPECT_EQ(sorted_parts.size(), 2u);
713
714 // Count up the number of UUIDs and make sure they are what we expect as a
715 // sanity check.
716 std::set<std::string> log_event_uuids;
717 std::set<std::string> parts_uuids;
718 std::set<std::string> both_uuids;
719
720 size_t missing_rt_count = 0;
721
722 std::vector<std::string> logger_nodes;
723 for (const LogFile &log_file : sorted_parts) {
724 EXPECT_FALSE(log_file.log_event_uuid.empty());
725 log_event_uuids.insert(log_file.log_event_uuid);
726 logger_nodes.emplace_back(log_file.logger_node);
727 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800728 EXPECT_TRUE(log_file.config);
729 EXPECT_EQ(log_file.name,
730 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800731
732 for (const LogParts &part : log_file.parts) {
733 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
734 << ": " << part;
735 missing_rt_count +=
736 part.realtime_start_time == aos::realtime_clock::min_time;
737
738 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
739 log_event_uuids.end());
740 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800741 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800742 parts_uuids.insert(part.parts_uuid);
743 both_uuids.insert(part.parts_uuid);
744 }
745 }
746
Austin Schuh61e973f2021-02-21 21:43:56 -0800747 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
748 // start time on remote nodes because we don't know it and would be
749 // guessing. And the log reader can actually do a better job. The number
750 // depends on if we have the remote timestamps split across 2 files, or just
751 // across 1, depending on if we are using a split or combined timestamp
752 // channel config.
753 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800754
755 EXPECT_EQ(log_event_uuids.size(), 2u);
756 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
757 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
758
759 // Test that each list of parts is in order. Don't worry about the ordering
760 // between part file lists though.
761 // (inner vectors all need to be in order, but outer one doesn't matter).
762 EXPECT_THAT(ToLogReaderVector(sorted_parts),
763 ::testing::UnorderedElementsAreArray(structured_logfiles_));
764
765 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
766
767 EXPECT_NE(sorted_parts[0].realtime_start_time,
768 aos::realtime_clock::min_time);
769 EXPECT_NE(sorted_parts[1].realtime_start_time,
770 aos::realtime_clock::min_time);
771
772 EXPECT_NE(sorted_parts[0].monotonic_start_time,
773 aos::monotonic_clock::min_time);
774 EXPECT_NE(sorted_parts[1].monotonic_start_time,
775 aos::monotonic_clock::min_time);
776
777 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
778 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
779 }
780
Austin Schuhc9049732020-12-21 22:27:15 -0800781 void ConfirmReadable(const std::vector<std::string> &files) {
782 LogReader reader(SortParts(files));
783
784 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
785 reader.Register(&log_reader_factory);
786
787 log_reader_factory.Run();
788
789 reader.Deregister();
790 }
791
Austin Schuh3bd4c402020-11-06 18:19:06 -0800792 void AddExtension(std::string_view extension) {
793 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
794 [extension](const std::string &in) {
795 return absl::StrCat(in, extension);
796 });
797
798 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
799 structured_logfiles_.begin(),
800 [extension](std::vector<std::string> in) {
801 std::transform(in.begin(), in.end(), in.begin(),
802 [extension](const std::string &in_str) {
803 return absl::StrCat(in_str, extension);
804 });
805 return in;
806 });
807 }
808
Austin Schuh15649d62019-12-28 16:36:38 -0800809 // Config and factory.
810 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800811 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800812 SimulatedEventLoopFactory event_loop_factory_;
813
Austin Schuh87dd3832021-01-01 23:07:31 -0800814 const Node *const pi1_;
815 const size_t pi1_index_;
816 const Node *const pi2_;
817 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700818
819 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800820 std::string logfile_base1_;
821 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800822 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700823 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800824 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700825
826 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700827
828 std::unique_ptr<EventLoop> ping_event_loop_;
829 Ping ping_;
830 std::unique_ptr<EventLoop> pong_event_loop_;
831 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800832};
833
Austin Schuh391e3172020-09-01 22:48:18 -0700834// Counts the number of messages on a channel. Returns (channel name, channel
835// type, count) for every message matching matcher()
836std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800837 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800838 std::function<bool(const MessageHeader *)> matcher) {
839 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800840 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800841
Austin Schuh6f3babe2020-01-26 20:34:50 -0800842 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800843 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800844 message_reader.ReadMessage();
845 if (!msg) {
846 break;
847 }
848
849 if (matcher(&msg.value().message())) {
850 counts[msg.value().message().channel_index()]++;
851 }
852 }
853
Austin Schuh391e3172020-09-01 22:48:18 -0700854 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800855 int channel = 0;
856 for (size_t i = 0; i < counts.size(); ++i) {
857 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800858 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700859 result.push_back(std::make_tuple(channel->name()->str(),
860 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800861 }
862 ++channel;
863 }
864
865 return result;
866}
867
868// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700869std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800870 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700871 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800872 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800873 if (msg->has_data()) {
874 CHECK(!msg->has_monotonic_remote_time());
875 CHECK(!msg->has_realtime_remote_time());
876 CHECK(!msg->has_remote_queue_index());
877 return true;
878 }
879 return false;
880 });
881}
882
883// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700884std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800885 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800886 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800887 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800888 if (!msg->has_data()) {
889 CHECK(msg->has_monotonic_remote_time());
890 CHECK(msg->has_realtime_remote_time());
891 CHECK(msg->has_remote_queue_index());
892 return true;
893 }
894 return false;
895 });
896}
897
Austin Schuhcde938c2020-02-02 17:30:07 -0800898// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800899TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800900 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800901 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700902 LoggerState pi1_logger = MakeLogger(pi1_);
903 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800904
905 event_loop_factory_.RunFor(chrono::milliseconds(95));
906
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700907 StartLogger(&pi1_logger);
908 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800909
Austin Schuh15649d62019-12-28 16:36:38 -0800910 event_loop_factory_.RunFor(chrono::milliseconds(20000));
911 }
912
Austin Schuh6f3babe2020-01-26 20:34:50 -0800913 {
Austin Schuh64fab802020-09-09 22:47:47 -0700914 std::set<std::string> logfile_uuids;
915 std::set<std::string> parts_uuids;
916 // Confirm that we have the expected number of UUIDs for both the logfile
917 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800918 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700919 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800920 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800921 if (!log_header.back().message().has_configuration()) {
922 logfile_uuids.insert(
923 log_header.back().message().log_event_uuid()->str());
924 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
925 }
Austin Schuh64fab802020-09-09 22:47:47 -0700926 }
Austin Schuh15649d62019-12-28 16:36:38 -0800927
Austin Schuh64fab802020-09-09 22:47:47 -0700928 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800929 if (shared()) {
930 EXPECT_EQ(parts_uuids.size(), 7u);
931 } else {
932 EXPECT_EQ(parts_uuids.size(), 8u);
933 }
Austin Schuh64fab802020-09-09 22:47:47 -0700934
935 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800936 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -0700937 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700938 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
939 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700940 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
941 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
942 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
943 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700944 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
945 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700946 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
947 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
948 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
949 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800950 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700951 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
952 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800953 }
Austin Schuh64fab802020-09-09 22:47:47 -0700954
955 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800956 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -0700957 EXPECT_EQ(log_header[3].message().parts_index(), 1);
958 EXPECT_EQ(log_header[4].message().parts_index(), 0);
959 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -0700960 EXPECT_EQ(log_header[6].message().parts_index(), 0);
961 EXPECT_EQ(log_header[7].message().parts_index(), 1);
962 EXPECT_EQ(log_header[8].message().parts_index(), 0);
963 EXPECT_EQ(log_header[9].message().parts_index(), 1);
964 EXPECT_EQ(log_header[10].message().parts_index(), 0);
965 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800966 EXPECT_EQ(log_header[12].message().parts_index(), 0);
967 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -0700968 EXPECT_EQ(log_header[14].message().parts_index(), 0);
969 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800970 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700971 EXPECT_EQ(log_header[16].message().parts_index(), 0);
972 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800973 }
Austin Schuh64fab802020-09-09 22:47:47 -0700974 }
975
Austin Schuh8c399962020-12-25 21:51:45 -0800976 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700977 {
Austin Schuh391e3172020-09-01 22:48:18 -0700978 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800979 std::shared_ptr<const aos::Configuration> config =
980 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700981
Austin Schuh6f3babe2020-01-26 20:34:50 -0800982 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700983 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800984 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700985 UnorderedElementsAre(
Austin Schuhe46492f2021-07-31 19:49:41 -0700986 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
987 1),
988 std::make_tuple("/test", "aos.examples.Ping", 1)))
989 << " : " << logfiles_[2];
990 EXPECT_THAT(
991 CountChannelsData(config, logfiles_[3]),
992 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -0700993 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800994 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -0700995 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -0800996 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
997 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700998 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -0700999 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1000 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001001 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001002 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1003 UnorderedElementsAre())
1004 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001005 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001006 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001007 UnorderedElementsAre(
1008 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001009 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001010 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001011
1012 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001013 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001014 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001015 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001016 << " : " << logfiles_[4];
1017 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001018 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001019 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001020 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001021
Austin Schuh6f3babe2020-01-26 20:34:50 -08001022 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001023 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001024 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001025 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001026 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1027 UnorderedElementsAre())
1028 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001029
1030 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001031 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1032 UnorderedElementsAre(std::make_tuple(
1033 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1034 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001035 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001036 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001037 UnorderedElementsAre(
1038 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001039 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001040 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001041 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1042 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001043 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001044 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001045 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001046 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001047 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1048 UnorderedElementsAre())
1049 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001050 EXPECT_THAT(
1051 CountChannelsTimestamp(config, logfiles_[7]),
1052 UnorderedElementsAre(
1053 std::make_tuple("/test", "aos.examples.Ping", 2001),
1054 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001055 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001056
1057 // And then test that the remotely logged timestamp data files only have
1058 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001059 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1060 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001061 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001062 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1063 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001064 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001065 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1066 UnorderedElementsAre())
1067 << " : " << logfiles_[10];
1068 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1069 UnorderedElementsAre())
1070 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001071
Austin Schuh8c399962020-12-25 21:51:45 -08001072 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001073 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001074 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001075 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001076 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001077 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001078 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001079 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001080
Austin Schuh8c399962020-12-25 21:51:45 -08001081 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001082 UnorderedElementsAre(std::make_tuple(
1083 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001084 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001085 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001086 UnorderedElementsAre(std::make_tuple(
1087 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001088 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001089
1090 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001091 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1092 UnorderedElementsAre())
1093 << " : " << logfiles_[12];
1094 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1095 UnorderedElementsAre())
1096 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001097 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1098 UnorderedElementsAre())
1099 << " : " << logfiles_[14];
1100 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1101 UnorderedElementsAre())
1102 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001103 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001104 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001105 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001106 << " : " << logfiles_[16];
1107 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001108 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001109 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001110 }
1111
1112 if (shared()) {
1113 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001114 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001115 UnorderedElementsAre(
1116 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1117 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001118 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001119 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001120 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001121 UnorderedElementsAre(
1122 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1123 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001124 << " : " << logfiles_[13];
1125 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001126 UnorderedElementsAre(std::make_tuple(
1127 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001128 << " : " << logfiles_[14];
1129 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001130 UnorderedElementsAre(std::make_tuple(
1131 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1132 << " : " << logfiles_[15];
1133 } else {
1134 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1135 UnorderedElementsAre(std::make_tuple(
1136 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1137 << " : " << logfiles_[12];
1138 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1139 UnorderedElementsAre(std::make_tuple(
1140 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1141 << " : " << logfiles_[13];
1142 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1143 UnorderedElementsAre(std::make_tuple(
1144 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1145 << " : " << logfiles_[14];
1146 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1147 UnorderedElementsAre(std::make_tuple(
1148 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1149 << " : " << logfiles_[15];
1150 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1151 UnorderedElementsAre(
1152 std::make_tuple("/test", "aos.examples.Ping", 91)))
1153 << " : " << logfiles_[16];
1154 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001155 UnorderedElementsAre(
1156 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001157 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001158 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001159 }
1160
Austin Schuh8c399962020-12-25 21:51:45 -08001161 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001162
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001163 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001164 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001165
1166 // This sends out the fetched messages and advances time to the start of the
1167 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001168 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001169
Austin Schuhac0771c2020-01-07 18:36:30 -08001170 const Node *pi1 =
1171 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001172 const Node *pi2 =
1173 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001174
Austin Schuh2f8fd752020-09-01 22:38:28 -07001175 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1176 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1177 LOG(INFO) << "now pi1 "
1178 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1179 LOG(INFO) << "now pi2 "
1180 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1181
Austin Schuh07676622021-01-21 18:59:17 -08001182 EXPECT_THAT(reader.LoggedNodes(),
1183 ::testing::ElementsAre(
1184 configuration::GetNode(reader.logged_configuration(), pi1),
1185 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001186
1187 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001188
Austin Schuh6f3babe2020-01-26 20:34:50 -08001189 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001190 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001191 std::unique_ptr<EventLoop> pi2_event_loop =
1192 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001193
Austin Schuh6f3babe2020-01-26 20:34:50 -08001194 int pi1_ping_count = 10;
1195 int pi2_ping_count = 10;
1196 int pi1_pong_count = 10;
1197 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001198
1199 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001200 pi1_event_loop->MakeWatcher(
1201 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001202 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001203 << pi1_event_loop->context().monotonic_remote_time << " -> "
1204 << pi1_event_loop->context().monotonic_event_time;
1205 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1206 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1207 pi1_ping_count * chrono::milliseconds(10) +
1208 monotonic_clock::epoch());
1209 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1210 pi1_ping_count * chrono::milliseconds(10) +
1211 realtime_clock::epoch());
1212 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1213 pi1_event_loop->context().monotonic_event_time);
1214 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1215 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001216
Austin Schuh6f3babe2020-01-26 20:34:50 -08001217 ++pi1_ping_count;
1218 });
1219 pi2_event_loop->MakeWatcher(
1220 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001221 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001222 << pi2_event_loop->context().monotonic_remote_time << " -> "
1223 << pi2_event_loop->context().monotonic_event_time;
1224 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1225
1226 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1227 pi2_ping_count * chrono::milliseconds(10) +
1228 monotonic_clock::epoch());
1229 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1230 pi2_ping_count * chrono::milliseconds(10) +
1231 realtime_clock::epoch());
1232 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1233 chrono::microseconds(150),
1234 pi2_event_loop->context().monotonic_event_time);
1235 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1236 chrono::microseconds(150),
1237 pi2_event_loop->context().realtime_event_time);
1238 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001239 });
1240
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001241 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001242 // Confirm that the ping and pong counts both match, and the value also
1243 // matches.
1244 pi1_event_loop->MakeWatcher(
1245 "/test", [&pi1_event_loop, &pi1_ping_count,
1246 &pi1_pong_count](const examples::Pong &pong) {
1247 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1248 << pi1_event_loop->context().monotonic_remote_time << " -> "
1249 << pi1_event_loop->context().monotonic_event_time;
1250
1251 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1252 pi1_pong_count + kQueueIndexOffset);
1253 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1254 chrono::microseconds(200) +
1255 pi1_pong_count * chrono::milliseconds(10) +
1256 monotonic_clock::epoch());
1257 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1258 chrono::microseconds(200) +
1259 pi1_pong_count * chrono::milliseconds(10) +
1260 realtime_clock::epoch());
1261
1262 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1263 chrono::microseconds(150),
1264 pi1_event_loop->context().monotonic_event_time);
1265 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1266 chrono::microseconds(150),
1267 pi1_event_loop->context().realtime_event_time);
1268
1269 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1270 ++pi1_pong_count;
1271 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1272 });
1273 pi2_event_loop->MakeWatcher(
1274 "/test", [&pi2_event_loop, &pi2_ping_count,
1275 &pi2_pong_count](const examples::Pong &pong) {
1276 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1277 << pi2_event_loop->context().monotonic_remote_time << " -> "
1278 << pi2_event_loop->context().monotonic_event_time;
1279
1280 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001281 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001282
1283 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1284 chrono::microseconds(200) +
1285 pi2_pong_count * chrono::milliseconds(10) +
1286 monotonic_clock::epoch());
1287 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1288 chrono::microseconds(200) +
1289 pi2_pong_count * chrono::milliseconds(10) +
1290 realtime_clock::epoch());
1291
1292 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1293 pi2_event_loop->context().monotonic_event_time);
1294 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1295 pi2_event_loop->context().realtime_event_time);
1296
1297 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1298 ++pi2_pong_count;
1299 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1300 });
1301
1302 log_reader_factory.Run();
1303 EXPECT_EQ(pi1_ping_count, 2010);
1304 EXPECT_EQ(pi2_ping_count, 2010);
1305 EXPECT_EQ(pi1_pong_count, 2010);
1306 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001307
1308 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001309}
1310
James Kuszmaul46d82582020-05-09 19:50:09 -07001311typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1312
1313// Test that if we feed the replay with a mismatched node list that we die on
1314// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001315TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001316 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001317 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001318 LoggerState pi1_logger = MakeLogger(pi1_);
1319 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001320
1321 event_loop_factory_.RunFor(chrono::milliseconds(95));
1322
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001323 StartLogger(&pi1_logger);
1324 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001325
James Kuszmaul46d82582020-05-09 19:50:09 -07001326 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1327 }
1328
1329 // Test that, if we add an additional node to the replay config that the
1330 // logger complains about the mismatch in number of nodes.
1331 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1332 configuration::MergeWithConfig(&config_.message(), R"({
1333 "nodes": [
1334 {
1335 "name": "extra-node"
1336 }
1337 ]
1338 }
1339 )");
1340
Austin Schuh287d43d2020-12-04 20:19:33 -08001341 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1342 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001343 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001344}
1345
Austin Schuhcde938c2020-02-02 17:30:07 -08001346// Tests that we can read log files where they don't start at the same monotonic
1347// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001348TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001349 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001350 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001351 LoggerState pi1_logger = MakeLogger(pi1_);
1352 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001353
1354 event_loop_factory_.RunFor(chrono::milliseconds(95));
1355
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001356 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001357
1358 event_loop_factory_.RunFor(chrono::milliseconds(200));
1359
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001360 StartLogger(&pi2_logger);
1361
Austin Schuhcde938c2020-02-02 17:30:07 -08001362 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1363 }
1364
Austin Schuhe46492f2021-07-31 19:49:41 -07001365 // Since we delay starting pi2, it already knows about all the timestamps so
1366 // we don't end up with extra parts.
1367 LogReader reader(
1368 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001369
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001370 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001371 log_reader_factory.set_send_delay(chrono::microseconds(0));
1372
1373 // This sends out the fetched messages and advances time to the start of the
1374 // log file.
1375 reader.Register(&log_reader_factory);
1376
1377 const Node *pi1 =
1378 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1379 const Node *pi2 =
1380 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1381
Austin Schuh07676622021-01-21 18:59:17 -08001382 EXPECT_THAT(reader.LoggedNodes(),
1383 ::testing::ElementsAre(
1384 configuration::GetNode(reader.logged_configuration(), pi1),
1385 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001386
1387 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1388
1389 std::unique_ptr<EventLoop> pi1_event_loop =
1390 log_reader_factory.MakeEventLoop("test", pi1);
1391 std::unique_ptr<EventLoop> pi2_event_loop =
1392 log_reader_factory.MakeEventLoop("test", pi2);
1393
1394 int pi1_ping_count = 30;
1395 int pi2_ping_count = 30;
1396 int pi1_pong_count = 30;
1397 int pi2_pong_count = 30;
1398
1399 // Confirm that the ping value matches.
1400 pi1_event_loop->MakeWatcher(
1401 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1402 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1403 << pi1_event_loop->context().monotonic_remote_time << " -> "
1404 << pi1_event_loop->context().monotonic_event_time;
1405 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1406
1407 ++pi1_ping_count;
1408 });
1409 pi2_event_loop->MakeWatcher(
1410 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1411 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1412 << pi2_event_loop->context().monotonic_remote_time << " -> "
1413 << pi2_event_loop->context().monotonic_event_time;
1414 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1415
1416 ++pi2_ping_count;
1417 });
1418
1419 // Confirm that the ping and pong counts both match, and the value also
1420 // matches.
1421 pi1_event_loop->MakeWatcher(
1422 "/test", [&pi1_event_loop, &pi1_ping_count,
1423 &pi1_pong_count](const examples::Pong &pong) {
1424 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1425 << pi1_event_loop->context().monotonic_remote_time << " -> "
1426 << pi1_event_loop->context().monotonic_event_time;
1427
1428 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1429 ++pi1_pong_count;
1430 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1431 });
1432 pi2_event_loop->MakeWatcher(
1433 "/test", [&pi2_event_loop, &pi2_ping_count,
1434 &pi2_pong_count](const examples::Pong &pong) {
1435 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1436 << pi2_event_loop->context().monotonic_remote_time << " -> "
1437 << pi2_event_loop->context().monotonic_event_time;
1438
1439 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1440 ++pi2_pong_count;
1441 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1442 });
1443
1444 log_reader_factory.Run();
1445 EXPECT_EQ(pi1_ping_count, 2030);
1446 EXPECT_EQ(pi2_ping_count, 2030);
1447 EXPECT_EQ(pi1_pong_count, 2030);
1448 EXPECT_EQ(pi2_pong_count, 2030);
1449
1450 reader.Deregister();
1451}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001452
Austin Schuh8bd96322020-02-13 21:18:22 -08001453// Tests that we can read log files where the monotonic clocks drift and don't
1454// match correctly. While we are here, also test that different ending times
1455// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001456TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001457 // TODO(austin): Negate...
1458 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1459
1460 time_converter_.AddMonotonic({monotonic_clock::epoch(),
1461 monotonic_clock::epoch() + initial_pi2_offset});
1462 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1463 // skew to be 200 uS/s
1464 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1465 {chrono::milliseconds(95),
1466 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1467 // Run another 200 ms to have one logger start first.
1468 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1469 {chrono::milliseconds(200), chrono::milliseconds(200)});
1470 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1471 // go far enough to cause problems if this isn't accounted for.
1472 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1473 {chrono::milliseconds(20000),
1474 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1475 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1476 {chrono::milliseconds(40000),
1477 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1478 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1479 {chrono::milliseconds(400), chrono::milliseconds(400)});
1480
Austin Schuhcde938c2020-02-02 17:30:07 -08001481 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001482 LoggerState pi2_logger = MakeLogger(pi2_);
1483
Austin Schuh87dd3832021-01-01 23:07:31 -08001484 NodeEventLoopFactory *pi1 =
1485 event_loop_factory_.GetNodeEventLoopFactory(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001486 NodeEventLoopFactory *pi2 =
1487 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1488 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1489 << pi2->realtime_now() << " distributed "
1490 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001491
Austin Schuh8bd96322020-02-13 21:18:22 -08001492 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1493 << pi2->realtime_now() << " distributed "
1494 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001495
Austin Schuh87dd3832021-01-01 23:07:31 -08001496 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001497
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001498 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001499
Austin Schuh87dd3832021-01-01 23:07:31 -08001500 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001501
Austin Schuh8bd96322020-02-13 21:18:22 -08001502 {
1503 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001504 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001505
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001506 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001507 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001508
Austin Schuh87dd3832021-01-01 23:07:31 -08001509 // Make sure we slewed time far enough so that the difference is greater
1510 // than the network delay. This confirms that if we sort incorrectly, it
1511 // would show in the results.
1512 EXPECT_LT(
1513 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1514 -event_loop_factory_.send_delay() -
1515 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001516
Austin Schuh87dd3832021-01-01 23:07:31 -08001517 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001518
Austin Schuh87dd3832021-01-01 23:07:31 -08001519 // And now check that we went far enough the other way to make sure we
1520 // cover both problems.
1521 EXPECT_GT(
1522 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1523 event_loop_factory_.send_delay() +
1524 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001525 }
1526
1527 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001528 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001529 }
1530
Austin Schuh72211ae2021-08-05 14:02:30 -07001531 LogReader reader(
1532 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001533
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001534 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001535 log_reader_factory.set_send_delay(chrono::microseconds(0));
1536
Austin Schuhcde938c2020-02-02 17:30:07 -08001537 const Node *pi1 =
1538 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1539 const Node *pi2 =
1540 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1541
Austin Schuh2f8fd752020-09-01 22:38:28 -07001542 // This sends out the fetched messages and advances time to the start of the
1543 // log file.
1544 reader.Register(&log_reader_factory);
1545
1546 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1547 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1548 LOG(INFO) << "now pi1 "
1549 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1550 LOG(INFO) << "now pi2 "
1551 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1552
Austin Schuhcde938c2020-02-02 17:30:07 -08001553 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001554 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1555 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001556 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1557 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001558 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1559 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001560 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1561
Austin Schuh07676622021-01-21 18:59:17 -08001562 EXPECT_THAT(reader.LoggedNodes(),
1563 ::testing::ElementsAre(
1564 configuration::GetNode(reader.logged_configuration(), pi1),
1565 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001566
1567 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1568
1569 std::unique_ptr<EventLoop> pi1_event_loop =
1570 log_reader_factory.MakeEventLoop("test", pi1);
1571 std::unique_ptr<EventLoop> pi2_event_loop =
1572 log_reader_factory.MakeEventLoop("test", pi2);
1573
1574 int pi1_ping_count = 30;
1575 int pi2_ping_count = 30;
1576 int pi1_pong_count = 30;
1577 int pi2_pong_count = 30;
1578
1579 // Confirm that the ping value matches.
1580 pi1_event_loop->MakeWatcher(
1581 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1582 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1583 << pi1_event_loop->context().monotonic_remote_time << " -> "
1584 << pi1_event_loop->context().monotonic_event_time;
1585 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1586
1587 ++pi1_ping_count;
1588 });
1589 pi2_event_loop->MakeWatcher(
1590 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1591 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1592 << pi2_event_loop->context().monotonic_remote_time << " -> "
1593 << pi2_event_loop->context().monotonic_event_time;
1594 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1595
1596 ++pi2_ping_count;
1597 });
1598
1599 // Confirm that the ping and pong counts both match, and the value also
1600 // matches.
1601 pi1_event_loop->MakeWatcher(
1602 "/test", [&pi1_event_loop, &pi1_ping_count,
1603 &pi1_pong_count](const examples::Pong &pong) {
1604 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1605 << pi1_event_loop->context().monotonic_remote_time << " -> "
1606 << pi1_event_loop->context().monotonic_event_time;
1607
1608 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1609 ++pi1_pong_count;
1610 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1611 });
1612 pi2_event_loop->MakeWatcher(
1613 "/test", [&pi2_event_loop, &pi2_ping_count,
1614 &pi2_pong_count](const examples::Pong &pong) {
1615 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1616 << pi2_event_loop->context().monotonic_remote_time << " -> "
1617 << pi2_event_loop->context().monotonic_event_time;
1618
1619 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1620 ++pi2_pong_count;
1621 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1622 });
1623
1624 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001625 EXPECT_EQ(pi1_ping_count, 6030);
1626 EXPECT_EQ(pi2_ping_count, 6030);
1627 EXPECT_EQ(pi1_pong_count, 6030);
1628 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001629
1630 reader.Deregister();
1631}
1632
Austin Schuh5212cad2020-09-09 23:12:09 -07001633// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001634TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001635 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001636 // Make a bunch of parts.
1637 {
1638 LoggerState pi1_logger = MakeLogger(pi1_);
1639 LoggerState pi2_logger = MakeLogger(pi2_);
1640
1641 event_loop_factory_.RunFor(chrono::milliseconds(95));
1642
1643 StartLogger(&pi1_logger);
1644 StartLogger(&pi2_logger);
1645
1646 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1647 }
1648
Austin Schuh11d43732020-09-21 17:28:30 -07001649 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001650 VerifyParts(sorted_parts);
1651}
Austin Schuh11d43732020-09-21 17:28:30 -07001652
Austin Schuh3bd4c402020-11-06 18:19:06 -08001653// Tests that we can sort a bunch of parts with an empty part. We should ignore
1654// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001655TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001656 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001657 // Make a bunch of parts.
1658 {
1659 LoggerState pi1_logger = MakeLogger(pi1_);
1660 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001661
Austin Schuh3bd4c402020-11-06 18:19:06 -08001662 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001663
Austin Schuh3bd4c402020-11-06 18:19:06 -08001664 StartLogger(&pi1_logger);
1665 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001666
Austin Schuh3bd4c402020-11-06 18:19:06 -08001667 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001668 }
1669
Austin Schuh3bd4c402020-11-06 18:19:06 -08001670 // TODO(austin): Should we flip out if the file can't open?
1671 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001672
Austin Schuh3bd4c402020-11-06 18:19:06 -08001673 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1674 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001675
Austin Schuh3bd4c402020-11-06 18:19:06 -08001676 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1677 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001678}
1679
Austin Schuh3bd4c402020-11-06 18:19:06 -08001680#ifdef LZMA
1681// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1682// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001683TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001684 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001685 // Make a bunch of parts.
1686 {
1687 LoggerState pi1_logger = MakeLogger(pi1_);
1688 LoggerState pi2_logger = MakeLogger(pi2_);
1689
1690 event_loop_factory_.RunFor(chrono::milliseconds(95));
1691
1692 StartLogger(&pi1_logger, "", true);
1693 StartLogger(&pi2_logger, "", true);
1694
1695 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1696 }
1697
1698 // TODO(austin): Should we flip out if the file can't open?
1699 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1700
1701 AddExtension(".xz");
1702
1703 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1704 logfiles_.emplace_back(kEmptyFile);
1705
1706 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1707 VerifyParts(sorted_parts, {kEmptyFile});
1708}
1709
1710// Tests that we can sort a bunch of parts with the end missing off a compressed
1711// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001712TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001713 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001714 // Make a bunch of parts.
1715 {
1716 LoggerState pi1_logger = MakeLogger(pi1_);
1717 LoggerState pi2_logger = MakeLogger(pi2_);
1718
1719 event_loop_factory_.RunFor(chrono::milliseconds(95));
1720
1721 StartLogger(&pi1_logger, "", true);
1722 StartLogger(&pi2_logger, "", true);
1723
1724 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1725 }
1726
1727 // Append everything with .xz.
1728 AddExtension(".xz");
1729
1730 // Strip off the end of one of the files. Pick one with a lot of data.
1731 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001732 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001733
1734 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001735 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001736 compressed_contents.substr(0, compressed_contents.size() - 100));
1737
1738 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1739 VerifyParts(sorted_parts);
1740}
1741#endif
1742
Austin Schuh01b4c352020-09-21 23:09:39 -07001743// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001744TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001745 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001746 {
1747 LoggerState pi1_logger = MakeLogger(pi1_);
1748 LoggerState pi2_logger = MakeLogger(pi2_);
1749
1750 event_loop_factory_.RunFor(chrono::milliseconds(95));
1751
1752 StartLogger(&pi1_logger);
1753 StartLogger(&pi2_logger);
1754
1755 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1756 }
1757
Austin Schuh287d43d2020-12-04 20:19:33 -08001758 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001759
1760 // Remap just on pi1.
1761 reader.RemapLoggedChannel<aos::timing::Report>(
1762 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1763
1764 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1765 log_reader_factory.set_send_delay(chrono::microseconds(0));
1766
1767 reader.Register(&log_reader_factory);
1768
1769 const Node *pi1 =
1770 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1771 const Node *pi2 =
1772 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1773
1774 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1775 // else should have moved.
1776 std::unique_ptr<EventLoop> pi1_event_loop =
1777 log_reader_factory.MakeEventLoop("test", pi1);
1778 pi1_event_loop->SkipTimingReport();
1779 std::unique_ptr<EventLoop> full_pi1_event_loop =
1780 log_reader_factory.MakeEventLoop("test", pi1);
1781 full_pi1_event_loop->SkipTimingReport();
1782 std::unique_ptr<EventLoop> pi2_event_loop =
1783 log_reader_factory.MakeEventLoop("test", pi2);
1784 pi2_event_loop->SkipTimingReport();
1785
1786 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1787 "/aos");
1788 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1789 full_pi1_event_loop.get(), "/pi1/aos");
1790 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1791 pi1_event_loop.get(), "/original/aos");
1792 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1793 full_pi1_event_loop.get(), "/original/pi1/aos");
1794 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1795 "/aos");
1796
1797 log_reader_factory.Run();
1798
1799 EXPECT_EQ(pi1_timing_report.count(), 0u);
1800 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1801 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1802 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1803 EXPECT_NE(pi2_timing_report.count(), 0u);
1804
1805 reader.Deregister();
1806}
1807
Austin Schuh006a9f52021-04-07 16:24:18 -07001808// Tests that we can remap a forwarded channel as well.
1809TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1810 time_converter_.StartEqual();
1811 {
1812 LoggerState pi1_logger = MakeLogger(pi1_);
1813 LoggerState pi2_logger = MakeLogger(pi2_);
1814
1815 event_loop_factory_.RunFor(chrono::milliseconds(95));
1816
1817 StartLogger(&pi1_logger);
1818 StartLogger(&pi2_logger);
1819
1820 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1821 }
1822
1823 LogReader reader(SortParts(logfiles_));
1824
1825 reader.RemapLoggedChannel<examples::Ping>("/test");
1826
1827 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1828 log_reader_factory.set_send_delay(chrono::microseconds(0));
1829
1830 reader.Register(&log_reader_factory);
1831
1832 const Node *pi1 =
1833 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1834 const Node *pi2 =
1835 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1836
1837 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1838 // else should have moved.
1839 std::unique_ptr<EventLoop> pi1_event_loop =
1840 log_reader_factory.MakeEventLoop("test", pi1);
1841 pi1_event_loop->SkipTimingReport();
1842 std::unique_ptr<EventLoop> full_pi1_event_loop =
1843 log_reader_factory.MakeEventLoop("test", pi1);
1844 full_pi1_event_loop->SkipTimingReport();
1845 std::unique_ptr<EventLoop> pi2_event_loop =
1846 log_reader_factory.MakeEventLoop("test", pi2);
1847 pi2_event_loop->SkipTimingReport();
1848
1849 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1850 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1851 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1852 "/original/test");
1853 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1854 "/original/test");
1855
1856 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1857 pi1_original_ping_timestamp;
1858 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1859 pi1_ping_timestamp;
1860 if (!shared()) {
1861 pi1_original_ping_timestamp =
1862 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1863 pi1_event_loop.get(),
1864 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1865 pi1_ping_timestamp =
1866 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1867 pi1_event_loop.get(),
1868 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1869 }
1870
1871 log_reader_factory.Run();
1872
1873 EXPECT_EQ(pi1_ping.count(), 0u);
1874 EXPECT_EQ(pi2_ping.count(), 0u);
1875 EXPECT_NE(pi1_original_ping.count(), 0u);
1876 EXPECT_NE(pi2_original_ping.count(), 0u);
1877 if (!shared()) {
1878 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1879 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1880 }
1881
1882 reader.Deregister();
1883}
1884
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001885// Tests that we properly recreate forwarded timestamps when replaying a log.
1886// This should be enough that we can then re-run the logger and get a valid log
1887// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001888TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001889 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001890 {
1891 LoggerState pi1_logger = MakeLogger(pi1_);
1892 LoggerState pi2_logger = MakeLogger(pi2_);
1893
1894 event_loop_factory_.RunFor(chrono::milliseconds(95));
1895
1896 StartLogger(&pi1_logger);
1897 StartLogger(&pi2_logger);
1898
1899 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1900 }
1901
Austin Schuh287d43d2020-12-04 20:19:33 -08001902 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001903
1904 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1905 log_reader_factory.set_send_delay(chrono::microseconds(0));
1906
1907 // This sends out the fetched messages and advances time to the start of the
1908 // log file.
1909 reader.Register(&log_reader_factory);
1910
1911 const Node *pi1 =
1912 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1913 const Node *pi2 =
1914 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1915
1916 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1917 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1918 LOG(INFO) << "now pi1 "
1919 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1920 LOG(INFO) << "now pi2 "
1921 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1922
Austin Schuh07676622021-01-21 18:59:17 -08001923 EXPECT_THAT(reader.LoggedNodes(),
1924 ::testing::ElementsAre(
1925 configuration::GetNode(reader.logged_configuration(), pi1),
1926 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001927
1928 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1929
1930 std::unique_ptr<EventLoop> pi1_event_loop =
1931 log_reader_factory.MakeEventLoop("test", pi1);
1932 std::unique_ptr<EventLoop> pi2_event_loop =
1933 log_reader_factory.MakeEventLoop("test", pi2);
1934
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001935 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1936 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1937 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1938 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1939
1940 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1941 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1942 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1943 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1944
1945 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1946 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1947 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1948 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1949
1950 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1951 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1952 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1953 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1954
1955 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1956 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1957 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1958 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1959
1960 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1961 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1962 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1963 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1964
Austin Schuh969cd602021-01-03 00:09:45 -08001965 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001966 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001967
Austin Schuh61e973f2021-02-21 21:43:56 -08001968 for (std::pair<int, std::string> channel :
1969 shared()
1970 ? std::vector<
1971 std::pair<int, std::string>>{{-1,
1972 "/aos/remote_timestamps/pi2"}}
1973 : std::vector<std::pair<int, std::string>>{
1974 {pi1_timestamp_channel,
1975 "/aos/remote_timestamps/pi2/pi1/aos/"
1976 "aos-message_bridge-Timestamp"},
1977 {ping_timestamp_channel,
1978 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1979 pi1_event_loop->MakeWatcher(
1980 channel.second,
1981 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1982 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1983 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1984 &ping_on_pi2_fetcher, network_delay, send_delay,
1985 channel_index = channel.first](const RemoteMessage &header) {
1986 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1987 chrono::nanoseconds(header.monotonic_sent_time()));
1988 const aos::realtime_clock::time_point header_realtime_sent_time(
1989 chrono::nanoseconds(header.realtime_sent_time()));
1990 const aos::monotonic_clock::time_point header_monotonic_remote_time(
1991 chrono::nanoseconds(header.monotonic_remote_time()));
1992 const aos::realtime_clock::time_point header_realtime_remote_time(
1993 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001994
Austin Schuh61e973f2021-02-21 21:43:56 -08001995 if (channel_index != -1) {
1996 ASSERT_EQ(channel_index, header.channel_index());
1997 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001998
Austin Schuh61e973f2021-02-21 21:43:56 -08001999 const Context *pi1_context = nullptr;
2000 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002001
Austin Schuh61e973f2021-02-21 21:43:56 -08002002 if (header.channel_index() == pi1_timestamp_channel) {
2003 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2004 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2005 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2006 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2007 } else if (header.channel_index() == ping_timestamp_channel) {
2008 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2009 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2010 pi1_context = &ping_on_pi1_fetcher.context();
2011 pi2_context = &ping_on_pi2_fetcher.context();
2012 } else {
2013 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2014 << configuration::CleanedChannelToString(
2015 pi1_event_loop->configuration()->channels()->Get(
2016 header.channel_index()));
2017 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002018
Austin Schuh61e973f2021-02-21 21:43:56 -08002019 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002020 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2021 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002022
Austin Schuh61e973f2021-02-21 21:43:56 -08002023 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2024 EXPECT_EQ(pi2_context->remote_queue_index,
2025 header.remote_queue_index());
2026 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002027
Austin Schuh61e973f2021-02-21 21:43:56 -08002028 EXPECT_EQ(pi2_context->monotonic_event_time,
2029 header_monotonic_sent_time);
2030 EXPECT_EQ(pi2_context->realtime_event_time,
2031 header_realtime_sent_time);
2032 EXPECT_EQ(pi2_context->realtime_remote_time,
2033 header_realtime_remote_time);
2034 EXPECT_EQ(pi2_context->monotonic_remote_time,
2035 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002036
Austin Schuh61e973f2021-02-21 21:43:56 -08002037 EXPECT_EQ(pi1_context->realtime_event_time,
2038 header_realtime_remote_time);
2039 EXPECT_EQ(pi1_context->monotonic_event_time,
2040 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002041
Austin Schuh61e973f2021-02-21 21:43:56 -08002042 // Time estimation isn't perfect, but we know the clocks were
2043 // identical when logged, so we know when this should have come back.
2044 // Confirm we got it when we expected.
2045 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2046 pi1_context->monotonic_event_time + 2 * network_delay +
2047 send_delay);
2048 });
2049 }
2050 for (std::pair<int, std::string> channel :
2051 shared()
2052 ? std::vector<
2053 std::pair<int, std::string>>{{-1,
2054 "/aos/remote_timestamps/pi1"}}
2055 : std::vector<std::pair<int, std::string>>{
2056 {pi2_timestamp_channel,
2057 "/aos/remote_timestamps/pi1/pi2/aos/"
2058 "aos-message_bridge-Timestamp"}}) {
2059 pi2_event_loop->MakeWatcher(
2060 channel.second,
2061 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2062 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2063 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2064 &pong_on_pi1_fetcher, network_delay, send_delay,
2065 channel_index = channel.first](const RemoteMessage &header) {
2066 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2067 chrono::nanoseconds(header.monotonic_sent_time()));
2068 const aos::realtime_clock::time_point header_realtime_sent_time(
2069 chrono::nanoseconds(header.realtime_sent_time()));
2070 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2071 chrono::nanoseconds(header.monotonic_remote_time()));
2072 const aos::realtime_clock::time_point header_realtime_remote_time(
2073 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002074
Austin Schuh61e973f2021-02-21 21:43:56 -08002075 if (channel_index != -1) {
2076 ASSERT_EQ(channel_index, header.channel_index());
2077 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002078
Austin Schuh61e973f2021-02-21 21:43:56 -08002079 const Context *pi2_context = nullptr;
2080 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002081
Austin Schuh61e973f2021-02-21 21:43:56 -08002082 if (header.channel_index() == pi2_timestamp_channel) {
2083 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2084 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2085 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2086 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2087 } else if (header.channel_index() == pong_timestamp_channel) {
2088 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2089 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2090 pi2_context = &pong_on_pi2_fetcher.context();
2091 pi1_context = &pong_on_pi1_fetcher.context();
2092 } else {
2093 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2094 << configuration::CleanedChannelToString(
2095 pi2_event_loop->configuration()->channels()->Get(
2096 header.channel_index()));
2097 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002098
Austin Schuh61e973f2021-02-21 21:43:56 -08002099 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002100 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2101 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002102
Austin Schuh61e973f2021-02-21 21:43:56 -08002103 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2104 EXPECT_EQ(pi1_context->remote_queue_index,
2105 header.remote_queue_index());
2106 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002107
Austin Schuh61e973f2021-02-21 21:43:56 -08002108 EXPECT_EQ(pi1_context->monotonic_event_time,
2109 header_monotonic_sent_time);
2110 EXPECT_EQ(pi1_context->realtime_event_time,
2111 header_realtime_sent_time);
2112 EXPECT_EQ(pi1_context->realtime_remote_time,
2113 header_realtime_remote_time);
2114 EXPECT_EQ(pi1_context->monotonic_remote_time,
2115 header_monotonic_remote_time);
2116
2117 EXPECT_EQ(pi2_context->realtime_event_time,
2118 header_realtime_remote_time);
2119 EXPECT_EQ(pi2_context->monotonic_event_time,
2120 header_monotonic_remote_time);
2121
2122 // Time estimation isn't perfect, but we know the clocks were
2123 // identical when logged, so we know when this should have come back.
2124 // Confirm we got it when we expected.
2125 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2126 pi2_context->monotonic_event_time + 2 * network_delay +
2127 send_delay);
2128 });
2129 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002130
2131 // And confirm we can re-create a log again, while checking the contents.
2132 {
2133 LoggerState pi1_logger = MakeLogger(
2134 configuration::GetNode(log_reader_factory.configuration(), pi1_),
2135 &log_reader_factory);
2136 LoggerState pi2_logger = MakeLogger(
2137 configuration::GetNode(log_reader_factory.configuration(), pi2_),
2138 &log_reader_factory);
2139
Austin Schuh25b46712021-01-03 00:04:38 -08002140 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2141 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002142
2143 log_reader_factory.Run();
2144 }
2145
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002146 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002147
2148 // And verify that we can run the LogReader over the relogged files without
2149 // hitting any fatal errors.
2150 {
2151 LogReader relogged_reader(SortParts(
2152 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2153 relogged_reader.Register();
2154
2155 relogged_reader.event_loop_factory()->Run();
2156 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002157}
2158
Austin Schuh315b96b2020-12-11 21:21:12 -08002159// Tests that we properly populate and extract the logger_start time by setting
2160// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002161TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002162 time_converter_.AddMonotonic(
2163 {monotonic_clock::epoch(),
2164 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002165 {
2166 LoggerState pi1_logger = MakeLogger(pi1_);
2167 LoggerState pi2_logger = MakeLogger(pi2_);
2168
Austin Schuh315b96b2020-12-11 21:21:12 -08002169 StartLogger(&pi1_logger);
2170 StartLogger(&pi2_logger);
2171
2172 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2173 }
2174
2175 for (const LogFile &log_file : SortParts(logfiles_)) {
2176 for (const LogParts &log_part : log_file.parts) {
2177 if (log_part.node == log_file.logger_node) {
2178 EXPECT_EQ(log_part.logger_monotonic_start_time,
2179 aos::monotonic_clock::min_time);
2180 EXPECT_EQ(log_part.logger_realtime_start_time,
2181 aos::realtime_clock::min_time);
2182 } else {
2183 const chrono::seconds offset = log_file.logger_node == "pi1"
2184 ? -chrono::seconds(1000)
2185 : chrono::seconds(1000);
2186 EXPECT_EQ(log_part.logger_monotonic_start_time,
2187 log_part.monotonic_start_time + offset);
2188 EXPECT_EQ(log_part.logger_realtime_start_time,
2189 log_file.realtime_start_time +
2190 (log_part.logger_monotonic_start_time -
2191 log_file.monotonic_start_time));
2192 }
2193 }
2194 }
2195}
2196
Austin Schuh6bb8a822021-03-31 23:04:39 -07002197// Test that renaming the base, renames the folder.
2198TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002199 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2200 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002201 time_converter_.AddMonotonic(
2202 {monotonic_clock::epoch(),
2203 monotonic_clock::epoch() + chrono::seconds(1000)});
2204 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2205 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2206 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2207 LoggerState pi1_logger = MakeLogger(pi1_);
2208 LoggerState pi2_logger = MakeLogger(pi2_);
2209
2210 StartLogger(&pi1_logger);
2211 StartLogger(&pi2_logger);
2212
2213 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2214 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2215 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2216 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2217 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2218 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2219 for (auto &file : logfiles_) {
2220 struct stat s;
2221 EXPECT_EQ(0, stat(file.c_str(), &s));
2222 }
2223}
2224
2225// Test that renaming the file base dies.
2226TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2227 time_converter_.AddMonotonic(
2228 {monotonic_clock::epoch(),
2229 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002230 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002231 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2232 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2233 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2234 LoggerState pi1_logger = MakeLogger(pi1_);
2235 StartLogger(&pi1_logger);
2236 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2237 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2238 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2239 "Rename of file base from");
2240}
2241
Austin Schuh8bd96322020-02-13 21:18:22 -08002242// TODO(austin): We can write a test which recreates a logfile and confirms that
2243// we get it back. That is the ultimate test.
2244
Austin Schuh315b96b2020-12-11 21:21:12 -08002245// Tests that we properly recreate forwarded timestamps when replaying a log.
2246// This should be enough that we can then re-run the logger and get a valid log
2247// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002248TEST_P(MultinodeLoggerDeathTest, RemoteReboot) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002249 time_converter_.StartEqual();
Austin Schuh315b96b2020-12-11 21:21:12 -08002250 std::string pi2_boot1;
2251 std::string pi2_boot2;
2252 {
2253 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2254 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002255 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002256 LoggerState pi1_logger = MakeLogger(pi1_);
2257
2258 event_loop_factory_.RunFor(chrono::milliseconds(95));
2259
2260 StartLogger(&pi1_logger);
2261
2262 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2263
2264 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
2265
2266 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2267 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002268 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002269
2270 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2271 }
2272
Austin Schuh72211ae2021-08-05 14:02:30 -07002273 // Confirm that our new oldest timestamps properly update as we reboot and
2274 // rotate.
2275 for (const std::string &file : pi1_reboot_logfiles_) {
2276 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2277 ReadHeader(file);
2278 CHECK(log_header);
2279 if (log_header->message().has_configuration()) {
2280 continue;
2281 }
2282
2283 if (log_header->message().node()->name()->string_view() != "pi1") {
2284 continue;
2285 }
2286 SCOPED_TRACE(file);
2287 SCOPED_TRACE(aos::FlatbufferToJson(
2288 *log_header, {.multi_line = true, .max_vector_size = 100}));
2289 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2290 ASSERT_EQ(
2291 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2292 EXPECT_EQ(
2293 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2294 monotonic_clock::max_time.time_since_epoch().count());
2295 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2296 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2297 2u);
2298 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2299 monotonic_clock::max_time.time_since_epoch().count());
2300 ASSERT_TRUE(log_header->message()
2301 .has_oldest_remote_unreliable_monotonic_timestamps());
2302 ASSERT_EQ(log_header->message()
2303 .oldest_remote_unreliable_monotonic_timestamps()
2304 ->size(),
2305 2u);
2306 EXPECT_EQ(log_header->message()
2307 .oldest_remote_unreliable_monotonic_timestamps()
2308 ->Get(0),
2309 monotonic_clock::max_time.time_since_epoch().count());
2310 ASSERT_TRUE(log_header->message()
2311 .has_oldest_local_unreliable_monotonic_timestamps());
2312 ASSERT_EQ(log_header->message()
2313 .oldest_local_unreliable_monotonic_timestamps()
2314 ->size(),
2315 2u);
2316 EXPECT_EQ(log_header->message()
2317 .oldest_local_unreliable_monotonic_timestamps()
2318 ->Get(0),
2319 monotonic_clock::max_time.time_since_epoch().count());
2320
2321 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2322 monotonic_clock::time_point(chrono::nanoseconds(
2323 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2324 1)));
2325 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2326 monotonic_clock::time_point(chrono::nanoseconds(
2327 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2328 const monotonic_clock::time_point
2329 oldest_remote_unreliable_monotonic_timestamps =
2330 monotonic_clock::time_point(chrono::nanoseconds(
2331 log_header->message()
2332 .oldest_remote_unreliable_monotonic_timestamps()
2333 ->Get(1)));
2334 const monotonic_clock::time_point
2335 oldest_local_unreliable_monotonic_timestamps =
2336 monotonic_clock::time_point(chrono::nanoseconds(
2337 log_header->message()
2338 .oldest_local_unreliable_monotonic_timestamps()
2339 ->Get(1)));
2340 switch (log_header->message().parts_index()) {
2341 case 0:
2342 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2343 monotonic_clock::max_time);
2344 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2345 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2346 monotonic_clock::max_time);
2347 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2348 monotonic_clock::max_time);
2349 break;
2350 case 1:
2351 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2352 monotonic_clock::time_point(chrono::microseconds(90200)));
2353 EXPECT_EQ(oldest_local_monotonic_timestamps,
2354 monotonic_clock::time_point(chrono::microseconds(90350)));
2355 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2356 monotonic_clock::time_point(chrono::microseconds(90200)));
2357 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2358 monotonic_clock::time_point(chrono::microseconds(90350)));
2359 break;
2360 case 2:
2361 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2362 monotonic_clock::time_point(chrono::microseconds(10100000)));
2363 EXPECT_EQ(oldest_local_monotonic_timestamps,
2364 monotonic_clock::time_point(chrono::microseconds(10100150)));
2365 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2366 monotonic_clock::max_time);
2367 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2368 monotonic_clock::max_time);
2369 break;
2370 case 3:
2371 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2372 monotonic_clock::time_point(chrono::microseconds(10100000)));
2373 EXPECT_EQ(oldest_local_monotonic_timestamps,
2374 monotonic_clock::time_point(chrono::microseconds(10100150)));
2375 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2376 monotonic_clock::time_point(chrono::microseconds(10100200)));
2377 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2378 monotonic_clock::time_point(chrono::microseconds(10100350)));
2379 break;
2380 default:
2381 FAIL();
2382 break;
2383 }
2384 }
2385
Austin Schuh315b96b2020-12-11 21:21:12 -08002386 // Confirm that we refuse to replay logs with missing boot uuids.
2387 EXPECT_DEATH(
2388 {
2389 LogReader reader(SortParts(pi1_reboot_logfiles_));
2390
2391 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2392 log_reader_factory.set_send_delay(chrono::microseconds(0));
2393
2394 // This sends out the fetched messages and advances time to the start of
2395 // the log file.
2396 reader.Register(&log_reader_factory);
2397 },
2398 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
2399 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
2400}
2401
Austin Schuhc9049732020-12-21 22:27:15 -08002402// Tests that we properly handle one direction of message_bridge being
2403// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002404TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002405 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002406 time_converter_.AddMonotonic(
2407 {monotonic_clock::epoch(),
2408 monotonic_clock::epoch() + chrono::seconds(1000)});
2409
2410 time_converter_.AddMonotonic(
2411 {chrono::milliseconds(10000),
2412 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002413 {
2414 LoggerState pi1_logger = MakeLogger(pi1_);
2415
2416 event_loop_factory_.RunFor(chrono::milliseconds(95));
2417
2418 StartLogger(&pi1_logger);
2419
2420 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2421 }
2422
2423 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2424 // to confirm the right thing happened.
2425 ConfirmReadable(pi1_single_direction_logfiles_);
2426}
2427
2428// Tests that we properly handle one direction of message_bridge being
2429// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002430TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002431 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002432 time_converter_.AddMonotonic(
2433 {monotonic_clock::epoch(),
2434 monotonic_clock::epoch() + chrono::seconds(500)});
2435
2436 time_converter_.AddMonotonic(
2437 {chrono::milliseconds(10000),
2438 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2439 {
2440 LoggerState pi1_logger = MakeLogger(pi1_);
2441
2442 event_loop_factory_.RunFor(chrono::milliseconds(95));
2443
2444 StartLogger(&pi1_logger);
2445
2446 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2447 }
2448
2449 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2450 // to confirm the right thing happened.
2451 ConfirmReadable(pi1_single_direction_logfiles_);
2452}
2453
2454// Tests that we properly handle a dead node. Do this by just disconnecting it
2455// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002456TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002457 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
2458 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
2459 time_converter_.AddMonotonic(
2460 {monotonic_clock::epoch(),
2461 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002462 {
2463 LoggerState pi1_logger = MakeLogger(pi1_);
2464
2465 event_loop_factory_.RunFor(chrono::milliseconds(95));
2466
2467 StartLogger(&pi1_logger);
2468
2469 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2470 }
2471
2472 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2473 // to confirm the right thing happened.
2474 ConfirmReadable(pi1_single_direction_logfiles_);
2475}
2476
Austin Schuhcdd90272021-03-15 12:46:16 -07002477constexpr std::string_view kCombinedConfigSha1(
milind945708b2021-07-03 13:30:15 -07002478 "4503751edc96327493562f0376f0d6daac172927c0fd64d04ce5d67505186c0b");
Austin Schuhcdd90272021-03-15 12:46:16 -07002479constexpr std::string_view kSplitConfigSha1(
milind945708b2021-07-03 13:30:15 -07002480 "918a748432c5e70a971dfd8934968378bed04ab61cf2efcd35b7f6224053c247");
Austin Schuhcdd90272021-03-15 12:46:16 -07002481
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002482INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002483 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002484 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2485 kCombinedConfigSha1},
2486 Param{"multinode_pingpong_split_config.json", false,
2487 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002488
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002489INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002490 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002491 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2492 kCombinedConfigSha1},
2493 Param{"multinode_pingpong_split_config.json", false,
2494 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002495
Austin Schuha04efed2021-01-24 18:04:20 -08002496// TODO(austin): Make a log file where the remote node has no start time.
2497
Austin Schuhe309d2a2019-11-29 13:25:21 -08002498} // namespace testing
2499} // namespace logger
2500} // namespace aos