blob: a923cf6a95c69ef092448bd280b7f2375958820e [file] [log] [blame]
Austin Schuh6bb8a822021-03-31 23:04:39 -07001#include <sys/stat.h>
2
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07005#include "aos/events/logging/log_reader.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08006#include "aos/events/logging/log_writer.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07007#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08008#include "aos/events/ping_lib.h"
9#include "aos/events/pong_lib.h"
10#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080011#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080012#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070013#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070014#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070015#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070016#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080017#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080018#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080019#include "gtest/gtest.h"
20
Austin Schuh3bd4c402020-11-06 18:19:06 -080021#ifdef LZMA
22#include "aos/events/logging/lzma_encoder.h"
23#endif
24
Austin Schuhe309d2a2019-11-29 13:25:21 -080025namespace aos {
26namespace logger {
27namespace testing {
28
Austin Schuh373f1762021-06-02 21:07:09 -070029using aos::testing::ArtifactPath;
30
Austin Schuhe309d2a2019-11-29 13:25:21 -080031namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080032using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070033using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080034
Austin Schuhee4713b2021-03-21 19:25:17 -070035constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070036 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080037
Austin Schuhb06f03b2021-02-17 22:00:37 -080038std::vector<std::vector<std::string>> ToLogReaderVector(
39 const std::vector<LogFile> &log_files) {
40 std::vector<std::vector<std::string>> result;
41 for (const LogFile &log_file : log_files) {
42 for (const LogParts &log_parts : log_file.parts) {
43 std::vector<std::string> parts;
44 for (const std::string &part : log_parts.parts) {
45 parts.emplace_back(part);
46 }
47 result.emplace_back(std::move(parts));
48 }
49 }
50 return result;
51}
52
Austin Schuhe309d2a2019-11-29 13:25:21 -080053class LoggerTest : public ::testing::Test {
54 public:
55 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070056 : config_(aos::configuration::ReadConfig(
57 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080058 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080059 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080060 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080061 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080062 pong_(pong_event_loop_.get()) {}
63
64 // Config and factory.
65 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
66 SimulatedEventLoopFactory event_loop_factory_;
67
68 // Event loop and app for Ping
69 std::unique_ptr<EventLoop> ping_event_loop_;
70 Ping ping_;
71
72 // Event loop and app for Pong
73 std::unique_ptr<EventLoop> pong_event_loop_;
74 Pong pong_;
75};
76
Brian Silverman1f345222020-09-24 21:14:48 -070077using LoggerDeathTest = LoggerTest;
78
Austin Schuhe309d2a2019-11-29 13:25:21 -080079// Tests that we can startup at all. This confirms that the channels are all in
80// the config.
81TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070082 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070083 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080084 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070085 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070086 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080087 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080088 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080089 unlink(logfile.c_str());
90
91 LOG(INFO) << "Logging data to " << logfile;
92
93 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080094 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080095 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080096
97 event_loop_factory_.RunFor(chrono::milliseconds(95));
98
Brian Silverman1f345222020-09-24 21:14:48 -070099 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800100 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700101 logger.set_polling_period(std::chrono::milliseconds(100));
102 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800103 event_loop_factory_.RunFor(chrono::milliseconds(20000));
104 }
105
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800106 // Even though it doesn't make any difference here, exercise the logic for
107 // passing in a separate config.
108 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800109
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800110 // Confirm that we can remap logged channels to point to new buses.
111 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800112
Austin Schuh15649d62019-12-28 16:36:38 -0800113 // This sends out the fetched messages and advances time to the start of the
114 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800115 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800116
Austin Schuh07676622021-01-21 18:59:17 -0800117 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800118
Austin Schuhe309d2a2019-11-29 13:25:21 -0800119 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800120 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800121
122 int ping_count = 10;
123 int pong_count = 10;
124
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800125 // Confirm that the ping value matches in the remapped channel location.
126 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800127 [&ping_count](const examples::Ping &ping) {
128 EXPECT_EQ(ping.value(), ping_count + 1);
129 ++ping_count;
130 });
131 // Confirm that the ping and pong counts both match, and the value also
132 // matches.
133 test_event_loop->MakeWatcher(
134 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
135 EXPECT_EQ(pong.value(), pong_count + 1);
136 ++pong_count;
137 EXPECT_EQ(ping_count, pong_count);
138 });
139
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800140 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800141 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142}
143
Brian Silverman1f345222020-09-24 21:14:48 -0700144// Tests calling StartLogging twice.
145TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800146 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700147 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800148 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700149 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700150 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
151 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800152 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700153 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700154 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
155 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800156 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700157 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800158 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700159
160 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
161
162 {
163 std::unique_ptr<EventLoop> logger_event_loop =
164 event_loop_factory_.MakeEventLoop("logger");
165
166 event_loop_factory_.RunFor(chrono::milliseconds(95));
167
168 Logger logger(logger_event_loop.get());
169 logger.set_polling_period(std::chrono::milliseconds(100));
170 logger_event_loop->OnRun(
171 [base_name1, base_name2, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700172 logger.StartLogging(std::make_unique<LocalLogNamer>(
173 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700174 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
Austin Schuh5b728b72021-06-16 14:57:15 -0700175 base_name2, logger_event_loop.get(),
176 logger_event_loop->node())),
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 Schuh5b728b72021-06-16 14:57:15 -0700206 logger.StartLogging(std::make_unique<LocalLogNamer>(
207 base_name, logger_event_loop.get(), logger_event_loop->node()));
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 Schuh5b728b72021-06-16 14:57:15 -0700243 logger.StartLogging(std::make_unique<LocalLogNamer>(
244 base_name1, logger_event_loop.get(), logger_event_loop->node()));
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 Schuh5b728b72021-06-16 14:57:15 -0700248 logger.StartLogging(std::make_unique<LocalLogNamer>(
249 base_name2, logger_event_loop.get(), logger_event_loop->node()));
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 Schuh58646e22021-08-23 23:51:46 -0700437 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800438 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700439 event_loop_factory_.configuration(), pi1_->node())),
440 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800441 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700442 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800443 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800444 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
445 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800446 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800447 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800448 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700449 structured_logfiles_(StructureLogFiles()) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800450 LOG(INFO) << "Config " << GetParam().config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800451 event_loop_factory_.SetTimeConverter(&time_converter_);
452
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700453 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700454 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700455 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800456 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700457 }
458
Austin Schuh268586b2021-03-31 22:24:39 -0700459 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800460 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800461 unlink(file.c_str());
462 }
463
Austin Schuh268586b2021-03-31 22:24:39 -0700464 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800465 unlink(file.c_str());
466 }
467
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700468 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
469 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700470
471 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
472 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700473 }
474
Austin Schuh61e973f2021-02-21 21:43:56 -0800475 bool shared() const { return GetParam().shared; }
476
477 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700478 std::string logfile_base2,
479 size_t pi1_data_count = 2,
480 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800481 std::vector<std::string> result;
482 result.emplace_back(
483 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
484 result.emplace_back(
485 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
Austin Schuhe46492f2021-07-31 19:49:41 -0700486 for (size_t i = 0; i < pi1_data_count; ++i) {
487 result.emplace_back(
488 absl::StrCat(logfile_base1, "_pi1_data.part", i, ".bfbs"));
489 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800490 result.emplace_back(logfile_base1 +
491 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
492 result.emplace_back(logfile_base1 +
493 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700494 for (size_t i = 0; i < pi2_data_count; ++i) {
495 result.emplace_back(
496 absl::StrCat(logfile_base2, "_pi2_data.part", i, ".bfbs"));
497 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800498 result.emplace_back(
499 logfile_base2 +
500 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
501 result.emplace_back(
502 logfile_base2 +
503 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
504 result.emplace_back(
505 logfile_base1 +
506 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
507 result.emplace_back(
508 logfile_base1 +
509 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
510 if (shared()) {
511 result.emplace_back(logfile_base1 +
512 "_timestamps/pi1/aos/remote_timestamps/pi2/"
513 "aos.message_bridge.RemoteMessage.part0.bfbs");
514 result.emplace_back(logfile_base1 +
515 "_timestamps/pi1/aos/remote_timestamps/pi2/"
516 "aos.message_bridge.RemoteMessage.part1.bfbs");
517 result.emplace_back(logfile_base2 +
518 "_timestamps/pi2/aos/remote_timestamps/pi1/"
519 "aos.message_bridge.RemoteMessage.part0.bfbs");
520 result.emplace_back(logfile_base2 +
521 "_timestamps/pi2/aos/remote_timestamps/pi1/"
522 "aos.message_bridge.RemoteMessage.part1.bfbs");
523 } else {
524 result.emplace_back(logfile_base1 +
525 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
526 "aos-message_bridge-Timestamp/"
527 "aos.message_bridge.RemoteMessage.part0.bfbs");
528 result.emplace_back(logfile_base1 +
529 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
530 "aos-message_bridge-Timestamp/"
531 "aos.message_bridge.RemoteMessage.part1.bfbs");
532 result.emplace_back(logfile_base2 +
533 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
534 "aos-message_bridge-Timestamp/"
535 "aos.message_bridge.RemoteMessage.part0.bfbs");
536 result.emplace_back(logfile_base2 +
537 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
538 "aos-message_bridge-Timestamp/"
539 "aos.message_bridge.RemoteMessage.part1.bfbs");
540 result.emplace_back(logfile_base1 +
541 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
542 "aos-examples-Ping/"
543 "aos.message_bridge.RemoteMessage.part0.bfbs");
544 result.emplace_back(logfile_base1 +
545 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
546 "aos-examples-Ping/"
547 "aos.message_bridge.RemoteMessage.part1.bfbs");
548 }
549
550 return result;
551 }
552
553 std::vector<std::string> MakePi1RebootLogfiles() {
554 std::vector<std::string> result;
555 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700556 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
557 result.emplace_back(logfile_base1_ + "_pi1_data.part2.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800558 result.emplace_back(logfile_base1_ +
559 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
560 result.emplace_back(logfile_base1_ +
561 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
562 result.emplace_back(logfile_base1_ +
563 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700564 result.emplace_back(logfile_base1_ +
565 "_pi2_data/test/aos.examples.Pong.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800566 result.emplace_back(
567 logfile_base1_ +
568 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
569 result.emplace_back(
570 logfile_base1_ +
571 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
572 result.emplace_back(
573 logfile_base1_ +
574 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
575 result.emplace_back(
Austin Schuh58646e22021-08-23 23:51:46 -0700576 logfile_base1_ +
577 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3.bfbs");
578 result.emplace_back(
Austin Schuh61e973f2021-02-21 21:43:56 -0800579 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
580 if (shared()) {
581 result.emplace_back(logfile_base1_ +
582 "_timestamps/pi1/aos/remote_timestamps/pi2/"
583 "aos.message_bridge.RemoteMessage.part0.bfbs");
584 result.emplace_back(logfile_base1_ +
585 "_timestamps/pi1/aos/remote_timestamps/pi2/"
586 "aos.message_bridge.RemoteMessage.part1.bfbs");
587 result.emplace_back(logfile_base1_ +
588 "_timestamps/pi1/aos/remote_timestamps/pi2/"
589 "aos.message_bridge.RemoteMessage.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700590 result.emplace_back(logfile_base1_ +
591 "_timestamps/pi1/aos/remote_timestamps/pi2/"
592 "aos.message_bridge.RemoteMessage.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800593 } else {
594 result.emplace_back(logfile_base1_ +
595 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
596 "aos-message_bridge-Timestamp/"
597 "aos.message_bridge.RemoteMessage.part0.bfbs");
598 result.emplace_back(logfile_base1_ +
599 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
600 "aos-message_bridge-Timestamp/"
601 "aos.message_bridge.RemoteMessage.part1.bfbs");
602 result.emplace_back(logfile_base1_ +
603 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
604 "aos-message_bridge-Timestamp/"
605 "aos.message_bridge.RemoteMessage.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700606 result.emplace_back(logfile_base1_ +
607 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
608 "aos-message_bridge-Timestamp/"
609 "aos.message_bridge.RemoteMessage.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800610
611 result.emplace_back(logfile_base1_ +
612 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
613 "aos-examples-Ping/"
614 "aos.message_bridge.RemoteMessage.part0.bfbs");
615 result.emplace_back(logfile_base1_ +
616 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
617 "aos-examples-Ping/"
618 "aos.message_bridge.RemoteMessage.part1.bfbs");
619 result.emplace_back(logfile_base1_ +
620 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
621 "aos-examples-Ping/"
622 "aos.message_bridge.RemoteMessage.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700623 result.emplace_back(logfile_base1_ +
624 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
625 "aos-examples-Ping/"
626 "aos.message_bridge.RemoteMessage.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800627 }
628 return result;
629 }
630
631 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
632 std::vector<std::string> result;
633 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuh510dc622021-08-06 18:47:30 -0700634 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800635 result.emplace_back(
636 logfile_base1_ +
637 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
638 result.emplace_back(
639 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh510dc622021-08-06 18:47:30 -0700640 return result;
641 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800642
Austin Schuh510dc622021-08-06 18:47:30 -0700643 std::vector<std::string> MakePi1DeadNodeLogfiles() {
644 std::vector<std::string> result;
645 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
646 result.emplace_back(
647 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh61e973f2021-02-21 21:43:56 -0800648 return result;
649 }
650
651 std::vector<std::vector<std::string>> StructureLogFiles() {
652 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700653 std::vector<std::string>{logfiles_[2], logfiles_[3]},
654 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800655 std::vector<std::string>{logfiles_[6], logfiles_[7]},
656 std::vector<std::string>{logfiles_[8], logfiles_[9]},
657 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700658 std::vector<std::string>{logfiles_[12], logfiles_[13]},
659 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800660
661 if (!shared()) {
662 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700663 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800664 }
665
666 return result;
667 }
668
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700669 struct LoggerState {
670 std::unique_ptr<EventLoop> event_loop;
671 std::unique_ptr<Logger> logger;
Austin Schuh5b728b72021-06-16 14:57:15 -0700672 const Configuration *configuration;
673 const Node *node;
674 MultiNodeLogNamer *log_namer;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700675 };
676
Austin Schuh58646e22021-08-23 23:51:46 -0700677 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700678 SimulatedEventLoopFactory *factory = nullptr,
679 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700680 if (factory == nullptr) {
681 factory = &event_loop_factory_;
682 }
Austin Schuh5b728b72021-06-16 14:57:15 -0700683 if (configuration == nullptr) {
684 configuration = factory->configuration();
685 }
Austin Schuh58646e22021-08-23 23:51:46 -0700686 return {node->MakeEventLoop("logger"),
687 {},
688 configuration,
689 configuration::GetNode(configuration, node->node()),
690 nullptr};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700691 }
692
Austin Schuh3bd4c402020-11-06 18:19:06 -0800693 void StartLogger(LoggerState *logger, std::string logfile_base = "",
694 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700695 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800696 if (logger->event_loop->node()->name()->string_view() == "pi1") {
697 logfile_base = logfile_base1_;
698 } else {
699 logfile_base = logfile_base2_;
700 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700701 }
702
Austin Schuh5b728b72021-06-16 14:57:15 -0700703 logger->logger = std::make_unique<Logger>(logger->event_loop.get(),
704 logger->configuration);
Brian Silverman1f345222020-09-24 21:14:48 -0700705 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800706 logger->logger->set_name(absl::StrCat(
707 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800708 logger->event_loop->OnRun([logger, logfile_base, compress]() {
709 std::unique_ptr<MultiNodeLogNamer> namer =
Austin Schuh5b728b72021-06-16 14:57:15 -0700710 std::make_unique<MultiNodeLogNamer>(
711 logfile_base, logger->configuration, logger->event_loop.get(),
712 logger->node);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800713 if (compress) {
714#ifdef LZMA
715 namer->set_extension(".xz");
716 namer->set_encoder_factory(
717 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
718#else
719 LOG(FATAL) << "Compression unsupported";
720#endif
721 }
Austin Schuh5b728b72021-06-16 14:57:15 -0700722 logger->log_namer = namer.get();
Austin Schuh3bd4c402020-11-06 18:19:06 -0800723
724 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700725 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700726 }
Austin Schuh15649d62019-12-28 16:36:38 -0800727
Austin Schuh3bd4c402020-11-06 18:19:06 -0800728 void VerifyParts(const std::vector<LogFile> &sorted_parts,
729 const std::vector<std::string> &corrupted_parts = {}) {
730 EXPECT_EQ(sorted_parts.size(), 2u);
731
732 // Count up the number of UUIDs and make sure they are what we expect as a
733 // sanity check.
734 std::set<std::string> log_event_uuids;
735 std::set<std::string> parts_uuids;
736 std::set<std::string> both_uuids;
737
738 size_t missing_rt_count = 0;
739
740 std::vector<std::string> logger_nodes;
741 for (const LogFile &log_file : sorted_parts) {
742 EXPECT_FALSE(log_file.log_event_uuid.empty());
743 log_event_uuids.insert(log_file.log_event_uuid);
744 logger_nodes.emplace_back(log_file.logger_node);
745 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800746 EXPECT_TRUE(log_file.config);
747 EXPECT_EQ(log_file.name,
748 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800749
750 for (const LogParts &part : log_file.parts) {
751 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
752 << ": " << part;
753 missing_rt_count +=
754 part.realtime_start_time == aos::realtime_clock::min_time;
755
756 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
757 log_event_uuids.end());
758 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800759 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800760 parts_uuids.insert(part.parts_uuid);
761 both_uuids.insert(part.parts_uuid);
762 }
763 }
764
Austin Schuh61e973f2021-02-21 21:43:56 -0800765 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
766 // start time on remote nodes because we don't know it and would be
767 // guessing. And the log reader can actually do a better job. The number
768 // depends on if we have the remote timestamps split across 2 files, or just
769 // across 1, depending on if we are using a split or combined timestamp
770 // channel config.
771 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800772
773 EXPECT_EQ(log_event_uuids.size(), 2u);
774 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
775 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
776
777 // Test that each list of parts is in order. Don't worry about the ordering
778 // between part file lists though.
779 // (inner vectors all need to be in order, but outer one doesn't matter).
780 EXPECT_THAT(ToLogReaderVector(sorted_parts),
781 ::testing::UnorderedElementsAreArray(structured_logfiles_));
782
783 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
784
785 EXPECT_NE(sorted_parts[0].realtime_start_time,
786 aos::realtime_clock::min_time);
787 EXPECT_NE(sorted_parts[1].realtime_start_time,
788 aos::realtime_clock::min_time);
789
790 EXPECT_NE(sorted_parts[0].monotonic_start_time,
791 aos::monotonic_clock::min_time);
792 EXPECT_NE(sorted_parts[1].monotonic_start_time,
793 aos::monotonic_clock::min_time);
794
795 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
796 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
797 }
798
Austin Schuhc9049732020-12-21 22:27:15 -0800799 void ConfirmReadable(const std::vector<std::string> &files) {
800 LogReader reader(SortParts(files));
801
802 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
803 reader.Register(&log_reader_factory);
804
805 log_reader_factory.Run();
806
807 reader.Deregister();
808 }
809
Austin Schuh3bd4c402020-11-06 18:19:06 -0800810 void AddExtension(std::string_view extension) {
811 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
812 [extension](const std::string &in) {
813 return absl::StrCat(in, extension);
814 });
815
816 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
817 structured_logfiles_.begin(),
818 [extension](std::vector<std::string> in) {
819 std::transform(in.begin(), in.end(), in.begin(),
820 [extension](const std::string &in_str) {
821 return absl::StrCat(in_str, extension);
822 });
823 return in;
824 });
825 }
826
Austin Schuh15649d62019-12-28 16:36:38 -0800827 // Config and factory.
828 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800829 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800830 SimulatedEventLoopFactory event_loop_factory_;
831
Austin Schuh58646e22021-08-23 23:51:46 -0700832 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800833 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700834 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800835 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700836
837 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800838 std::string logfile_base1_;
839 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800840 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700841 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800842 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700843
844 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800845};
846
Austin Schuh391e3172020-09-01 22:48:18 -0700847// Counts the number of messages on a channel. Returns (channel name, channel
848// type, count) for every message matching matcher()
849std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800850 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700851 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800852 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800853 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800854
Austin Schuh6f3babe2020-01-26 20:34:50 -0800855 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700856 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800857 if (!msg) {
858 break;
859 }
860
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700861 if (matcher(msg.get())) {
862 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800863 }
864 }
865
Austin Schuh391e3172020-09-01 22:48:18 -0700866 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800867 int channel = 0;
868 for (size_t i = 0; i < counts.size(); ++i) {
869 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800870 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700871 result.push_back(std::make_tuple(channel->name()->str(),
872 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800873 }
874 ++channel;
875 }
876
877 return result;
878}
879
880// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700881std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800882 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700883 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700884 return CountChannelsMatching(
885 config, filename, [](const UnpackedMessageHeader *msg) {
886 if (msg->span.data() != nullptr) {
887 CHECK(!msg->monotonic_remote_time.has_value());
888 CHECK(!msg->realtime_remote_time.has_value());
889 CHECK(!msg->remote_queue_index.has_value());
890 return true;
891 }
892 return false;
893 });
Austin Schuh6f3babe2020-01-26 20:34:50 -0800894}
895
896// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700897std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800898 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800899 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700900 return CountChannelsMatching(
901 config, filename, [](const UnpackedMessageHeader *msg) {
902 if (msg->span.data() == nullptr) {
903 CHECK(msg->monotonic_remote_time.has_value());
904 CHECK(msg->realtime_remote_time.has_value());
905 CHECK(msg->remote_queue_index.has_value());
906 return true;
907 }
908 return false;
909 });
Austin Schuh6f3babe2020-01-26 20:34:50 -0800910}
911
Austin Schuhcde938c2020-02-02 17:30:07 -0800912// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800913TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800914 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800915 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700916 LoggerState pi1_logger = MakeLogger(pi1_);
917 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800918
919 event_loop_factory_.RunFor(chrono::milliseconds(95));
920
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700921 StartLogger(&pi1_logger);
922 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800923
Austin Schuh15649d62019-12-28 16:36:38 -0800924 event_loop_factory_.RunFor(chrono::milliseconds(20000));
925 }
926
Austin Schuh6f3babe2020-01-26 20:34:50 -0800927 {
Austin Schuh64fab802020-09-09 22:47:47 -0700928 std::set<std::string> logfile_uuids;
929 std::set<std::string> parts_uuids;
930 // Confirm that we have the expected number of UUIDs for both the logfile
931 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800932 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700933 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800934 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800935 if (!log_header.back().message().has_configuration()) {
936 logfile_uuids.insert(
937 log_header.back().message().log_event_uuid()->str());
938 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
939 }
Austin Schuh64fab802020-09-09 22:47:47 -0700940 }
Austin Schuh15649d62019-12-28 16:36:38 -0800941
Austin Schuh64fab802020-09-09 22:47:47 -0700942 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800943 if (shared()) {
944 EXPECT_EQ(parts_uuids.size(), 7u);
945 } else {
946 EXPECT_EQ(parts_uuids.size(), 8u);
947 }
Austin Schuh64fab802020-09-09 22:47:47 -0700948
949 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800950 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -0700951 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700952 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
953 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700954 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
955 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
956 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
957 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700958 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
959 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700960 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
961 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
962 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
963 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800964 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700965 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
966 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800967 }
Austin Schuh64fab802020-09-09 22:47:47 -0700968
969 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800970 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -0700971 EXPECT_EQ(log_header[3].message().parts_index(), 1);
972 EXPECT_EQ(log_header[4].message().parts_index(), 0);
973 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -0700974 EXPECT_EQ(log_header[6].message().parts_index(), 0);
975 EXPECT_EQ(log_header[7].message().parts_index(), 1);
976 EXPECT_EQ(log_header[8].message().parts_index(), 0);
977 EXPECT_EQ(log_header[9].message().parts_index(), 1);
978 EXPECT_EQ(log_header[10].message().parts_index(), 0);
979 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800980 EXPECT_EQ(log_header[12].message().parts_index(), 0);
981 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -0700982 EXPECT_EQ(log_header[14].message().parts_index(), 0);
983 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800984 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700985 EXPECT_EQ(log_header[16].message().parts_index(), 0);
986 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800987 }
Austin Schuh64fab802020-09-09 22:47:47 -0700988 }
989
Austin Schuh8c399962020-12-25 21:51:45 -0800990 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700991 {
Austin Schuh391e3172020-09-01 22:48:18 -0700992 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800993 std::shared_ptr<const aos::Configuration> config =
994 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700995
Austin Schuh6f3babe2020-01-26 20:34:50 -0800996 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700997 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800998 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700999 UnorderedElementsAre(
Austin Schuhe46492f2021-07-31 19:49:41 -07001000 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
1001 1),
1002 std::make_tuple("/test", "aos.examples.Ping", 1)))
1003 << " : " << logfiles_[2];
1004 EXPECT_THAT(
1005 CountChannelsData(config, logfiles_[3]),
1006 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -07001007 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001008 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001009 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001010 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1011 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001012 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001013 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1014 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001015 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001016 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1017 UnorderedElementsAre())
1018 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001019 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001020 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001021 UnorderedElementsAre(
1022 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001023 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001024 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001025
1026 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001027 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001028 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001029 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001030 << " : " << logfiles_[4];
1031 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001032 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001033 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001034 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001035
Austin Schuh6f3babe2020-01-26 20:34:50 -08001036 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001037 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001038 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001039 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001040 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1041 UnorderedElementsAre())
1042 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001043
1044 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001045 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1046 UnorderedElementsAre(std::make_tuple(
1047 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1048 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001049 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001050 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001051 UnorderedElementsAre(
1052 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001053 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001054 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001055 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1056 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001057 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001058 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001059 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001060 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001061 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1062 UnorderedElementsAre())
1063 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001064 EXPECT_THAT(
1065 CountChannelsTimestamp(config, logfiles_[7]),
1066 UnorderedElementsAre(
1067 std::make_tuple("/test", "aos.examples.Ping", 2001),
1068 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001069 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001070
1071 // And then test that the remotely logged timestamp data files only have
1072 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001073 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1074 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001075 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001076 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1077 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001078 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001079 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1080 UnorderedElementsAre())
1081 << " : " << logfiles_[10];
1082 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1083 UnorderedElementsAre())
1084 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001085
Austin Schuh8c399962020-12-25 21:51:45 -08001086 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001087 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001088 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001089 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001090 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001091 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001092 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001093 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001094
Austin Schuh8c399962020-12-25 21:51:45 -08001095 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001096 UnorderedElementsAre(std::make_tuple(
1097 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001098 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001099 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001100 UnorderedElementsAre(std::make_tuple(
1101 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001102 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001103
1104 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001105 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1106 UnorderedElementsAre())
1107 << " : " << logfiles_[12];
1108 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1109 UnorderedElementsAre())
1110 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001111 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1112 UnorderedElementsAre())
1113 << " : " << logfiles_[14];
1114 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1115 UnorderedElementsAre())
1116 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001117 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001118 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001119 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001120 << " : " << logfiles_[16];
1121 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001122 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001123 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001124 }
1125
1126 if (shared()) {
1127 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001128 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001129 UnorderedElementsAre(
1130 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1131 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001132 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001133 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001134 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001135 UnorderedElementsAre(
1136 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1137 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001138 << " : " << logfiles_[13];
1139 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001140 UnorderedElementsAre(std::make_tuple(
1141 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001142 << " : " << logfiles_[14];
1143 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001144 UnorderedElementsAre(std::make_tuple(
1145 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1146 << " : " << logfiles_[15];
1147 } else {
1148 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1149 UnorderedElementsAre(std::make_tuple(
1150 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1151 << " : " << logfiles_[12];
1152 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1153 UnorderedElementsAre(std::make_tuple(
1154 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1155 << " : " << logfiles_[13];
1156 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1157 UnorderedElementsAre(std::make_tuple(
1158 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1159 << " : " << logfiles_[14];
1160 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1161 UnorderedElementsAre(std::make_tuple(
1162 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1163 << " : " << logfiles_[15];
1164 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1165 UnorderedElementsAre(
1166 std::make_tuple("/test", "aos.examples.Ping", 91)))
1167 << " : " << logfiles_[16];
1168 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001169 UnorderedElementsAre(
1170 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001171 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001172 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001173 }
1174
Austin Schuh8c399962020-12-25 21:51:45 -08001175 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001176
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001177 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001178 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001179
1180 // This sends out the fetched messages and advances time to the start of the
1181 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001182 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001183
Austin Schuhac0771c2020-01-07 18:36:30 -08001184 const Node *pi1 =
1185 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001186 const Node *pi2 =
1187 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001188
Austin Schuh2f8fd752020-09-01 22:38:28 -07001189 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1190 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1191 LOG(INFO) << "now pi1 "
1192 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1193 LOG(INFO) << "now pi2 "
1194 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1195
Austin Schuh07676622021-01-21 18:59:17 -08001196 EXPECT_THAT(reader.LoggedNodes(),
1197 ::testing::ElementsAre(
1198 configuration::GetNode(reader.logged_configuration(), pi1),
1199 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001200
1201 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001202
Austin Schuh6f3babe2020-01-26 20:34:50 -08001203 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001204 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001205 std::unique_ptr<EventLoop> pi2_event_loop =
1206 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001207
Austin Schuh6f3babe2020-01-26 20:34:50 -08001208 int pi1_ping_count = 10;
1209 int pi2_ping_count = 10;
1210 int pi1_pong_count = 10;
1211 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001212
1213 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001214 pi1_event_loop->MakeWatcher(
1215 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001216 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001217 << pi1_event_loop->context().monotonic_remote_time << " -> "
1218 << pi1_event_loop->context().monotonic_event_time;
1219 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1220 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1221 pi1_ping_count * chrono::milliseconds(10) +
1222 monotonic_clock::epoch());
1223 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1224 pi1_ping_count * chrono::milliseconds(10) +
1225 realtime_clock::epoch());
1226 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1227 pi1_event_loop->context().monotonic_event_time);
1228 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1229 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001230
Austin Schuh6f3babe2020-01-26 20:34:50 -08001231 ++pi1_ping_count;
1232 });
1233 pi2_event_loop->MakeWatcher(
1234 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001235 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001236 << pi2_event_loop->context().monotonic_remote_time << " -> "
1237 << pi2_event_loop->context().monotonic_event_time;
1238 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1239
1240 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1241 pi2_ping_count * chrono::milliseconds(10) +
1242 monotonic_clock::epoch());
1243 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1244 pi2_ping_count * chrono::milliseconds(10) +
1245 realtime_clock::epoch());
1246 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1247 chrono::microseconds(150),
1248 pi2_event_loop->context().monotonic_event_time);
1249 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1250 chrono::microseconds(150),
1251 pi2_event_loop->context().realtime_event_time);
1252 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001253 });
1254
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001255 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001256 // Confirm that the ping and pong counts both match, and the value also
1257 // matches.
1258 pi1_event_loop->MakeWatcher(
1259 "/test", [&pi1_event_loop, &pi1_ping_count,
1260 &pi1_pong_count](const examples::Pong &pong) {
1261 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1262 << pi1_event_loop->context().monotonic_remote_time << " -> "
1263 << pi1_event_loop->context().monotonic_event_time;
1264
1265 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1266 pi1_pong_count + kQueueIndexOffset);
1267 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1268 chrono::microseconds(200) +
1269 pi1_pong_count * chrono::milliseconds(10) +
1270 monotonic_clock::epoch());
1271 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1272 chrono::microseconds(200) +
1273 pi1_pong_count * chrono::milliseconds(10) +
1274 realtime_clock::epoch());
1275
1276 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1277 chrono::microseconds(150),
1278 pi1_event_loop->context().monotonic_event_time);
1279 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1280 chrono::microseconds(150),
1281 pi1_event_loop->context().realtime_event_time);
1282
1283 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1284 ++pi1_pong_count;
1285 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1286 });
1287 pi2_event_loop->MakeWatcher(
1288 "/test", [&pi2_event_loop, &pi2_ping_count,
1289 &pi2_pong_count](const examples::Pong &pong) {
1290 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1291 << pi2_event_loop->context().monotonic_remote_time << " -> "
1292 << pi2_event_loop->context().monotonic_event_time;
1293
1294 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001295 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001296
1297 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1298 chrono::microseconds(200) +
1299 pi2_pong_count * chrono::milliseconds(10) +
1300 monotonic_clock::epoch());
1301 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1302 chrono::microseconds(200) +
1303 pi2_pong_count * chrono::milliseconds(10) +
1304 realtime_clock::epoch());
1305
1306 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1307 pi2_event_loop->context().monotonic_event_time);
1308 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1309 pi2_event_loop->context().realtime_event_time);
1310
1311 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1312 ++pi2_pong_count;
1313 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1314 });
1315
1316 log_reader_factory.Run();
1317 EXPECT_EQ(pi1_ping_count, 2010);
1318 EXPECT_EQ(pi2_ping_count, 2010);
1319 EXPECT_EQ(pi1_pong_count, 2010);
1320 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001321
1322 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001323}
1324
James Kuszmaul46d82582020-05-09 19:50:09 -07001325typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1326
1327// Test that if we feed the replay with a mismatched node list that we die on
1328// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001329TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001330 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001331 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001332 LoggerState pi1_logger = MakeLogger(pi1_);
1333 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001334
1335 event_loop_factory_.RunFor(chrono::milliseconds(95));
1336
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001337 StartLogger(&pi1_logger);
1338 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001339
James Kuszmaul46d82582020-05-09 19:50:09 -07001340 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1341 }
1342
1343 // Test that, if we add an additional node to the replay config that the
1344 // logger complains about the mismatch in number of nodes.
1345 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1346 configuration::MergeWithConfig(&config_.message(), R"({
1347 "nodes": [
1348 {
1349 "name": "extra-node"
1350 }
1351 ]
1352 }
1353 )");
1354
Austin Schuh287d43d2020-12-04 20:19:33 -08001355 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1356 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001357 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001358}
1359
Austin Schuhcde938c2020-02-02 17:30:07 -08001360// Tests that we can read log files where they don't start at the same monotonic
1361// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001362TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001363 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001364 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001365 LoggerState pi1_logger = MakeLogger(pi1_);
1366 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001367
1368 event_loop_factory_.RunFor(chrono::milliseconds(95));
1369
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001370 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001371
1372 event_loop_factory_.RunFor(chrono::milliseconds(200));
1373
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001374 StartLogger(&pi2_logger);
1375
Austin Schuhcde938c2020-02-02 17:30:07 -08001376 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1377 }
1378
Austin Schuhe46492f2021-07-31 19:49:41 -07001379 // Since we delay starting pi2, it already knows about all the timestamps so
1380 // we don't end up with extra parts.
1381 LogReader reader(
1382 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001383
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001384 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001385 log_reader_factory.set_send_delay(chrono::microseconds(0));
1386
1387 // This sends out the fetched messages and advances time to the start of the
1388 // log file.
1389 reader.Register(&log_reader_factory);
1390
1391 const Node *pi1 =
1392 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1393 const Node *pi2 =
1394 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1395
Austin Schuh07676622021-01-21 18:59:17 -08001396 EXPECT_THAT(reader.LoggedNodes(),
1397 ::testing::ElementsAre(
1398 configuration::GetNode(reader.logged_configuration(), pi1),
1399 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001400
1401 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1402
1403 std::unique_ptr<EventLoop> pi1_event_loop =
1404 log_reader_factory.MakeEventLoop("test", pi1);
1405 std::unique_ptr<EventLoop> pi2_event_loop =
1406 log_reader_factory.MakeEventLoop("test", pi2);
1407
1408 int pi1_ping_count = 30;
1409 int pi2_ping_count = 30;
1410 int pi1_pong_count = 30;
1411 int pi2_pong_count = 30;
1412
1413 // Confirm that the ping value matches.
1414 pi1_event_loop->MakeWatcher(
1415 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1416 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1417 << pi1_event_loop->context().monotonic_remote_time << " -> "
1418 << pi1_event_loop->context().monotonic_event_time;
1419 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1420
1421 ++pi1_ping_count;
1422 });
1423 pi2_event_loop->MakeWatcher(
1424 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1425 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1426 << pi2_event_loop->context().monotonic_remote_time << " -> "
1427 << pi2_event_loop->context().monotonic_event_time;
1428 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1429
1430 ++pi2_ping_count;
1431 });
1432
1433 // Confirm that the ping and pong counts both match, and the value also
1434 // matches.
1435 pi1_event_loop->MakeWatcher(
1436 "/test", [&pi1_event_loop, &pi1_ping_count,
1437 &pi1_pong_count](const examples::Pong &pong) {
1438 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1439 << pi1_event_loop->context().monotonic_remote_time << " -> "
1440 << pi1_event_loop->context().monotonic_event_time;
1441
1442 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1443 ++pi1_pong_count;
1444 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1445 });
1446 pi2_event_loop->MakeWatcher(
1447 "/test", [&pi2_event_loop, &pi2_ping_count,
1448 &pi2_pong_count](const examples::Pong &pong) {
1449 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1450 << pi2_event_loop->context().monotonic_remote_time << " -> "
1451 << pi2_event_loop->context().monotonic_event_time;
1452
1453 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1454 ++pi2_pong_count;
1455 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1456 });
1457
1458 log_reader_factory.Run();
1459 EXPECT_EQ(pi1_ping_count, 2030);
1460 EXPECT_EQ(pi2_ping_count, 2030);
1461 EXPECT_EQ(pi1_pong_count, 2030);
1462 EXPECT_EQ(pi2_pong_count, 2030);
1463
1464 reader.Deregister();
1465}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001466
Austin Schuh8bd96322020-02-13 21:18:22 -08001467// Tests that we can read log files where the monotonic clocks drift and don't
1468// match correctly. While we are here, also test that different ending times
1469// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001470TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001471 // TODO(austin): Negate...
1472 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1473
Austin Schuh66168842021-08-17 19:42:21 -07001474 time_converter_.AddMonotonic(
1475 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001476 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1477 // skew to be 200 uS/s
1478 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1479 {chrono::milliseconds(95),
1480 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1481 // Run another 200 ms to have one logger start first.
1482 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1483 {chrono::milliseconds(200), chrono::milliseconds(200)});
1484 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1485 // go far enough to cause problems if this isn't accounted for.
1486 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1487 {chrono::milliseconds(20000),
1488 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1489 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1490 {chrono::milliseconds(40000),
1491 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1492 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1493 {chrono::milliseconds(400), chrono::milliseconds(400)});
1494
Austin Schuhcde938c2020-02-02 17:30:07 -08001495 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001496 LoggerState pi2_logger = MakeLogger(pi2_);
1497
Austin Schuh58646e22021-08-23 23:51:46 -07001498 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1499 << pi2_->realtime_now() << " distributed "
1500 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001501
Austin Schuh58646e22021-08-23 23:51:46 -07001502 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1503 << pi2_->realtime_now() << " distributed "
1504 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001505
Austin Schuh87dd3832021-01-01 23:07:31 -08001506 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001507
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001508 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001509
Austin Schuh87dd3832021-01-01 23:07:31 -08001510 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001511
Austin Schuh8bd96322020-02-13 21:18:22 -08001512 {
1513 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001514 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001515
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001516 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001517 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001518
Austin Schuh87dd3832021-01-01 23:07:31 -08001519 // Make sure we slewed time far enough so that the difference is greater
1520 // than the network delay. This confirms that if we sort incorrectly, it
1521 // would show in the results.
1522 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001523 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001524 -event_loop_factory_.send_delay() -
1525 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001526
Austin Schuh87dd3832021-01-01 23:07:31 -08001527 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001528
Austin Schuh87dd3832021-01-01 23:07:31 -08001529 // And now check that we went far enough the other way to make sure we
1530 // cover both problems.
1531 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001532 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001533 event_loop_factory_.send_delay() +
1534 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001535 }
1536
1537 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001538 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001539 }
1540
Austin Schuh72211ae2021-08-05 14:02:30 -07001541 LogReader reader(
1542 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001543
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001544 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001545 log_reader_factory.set_send_delay(chrono::microseconds(0));
1546
Austin Schuhcde938c2020-02-02 17:30:07 -08001547 const Node *pi1 =
1548 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1549 const Node *pi2 =
1550 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1551
Austin Schuh2f8fd752020-09-01 22:38:28 -07001552 // This sends out the fetched messages and advances time to the start of the
1553 // log file.
1554 reader.Register(&log_reader_factory);
1555
1556 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1557 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1558 LOG(INFO) << "now pi1 "
1559 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1560 LOG(INFO) << "now pi2 "
1561 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1562
Austin Schuhcde938c2020-02-02 17:30:07 -08001563 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001564 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1565 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001566 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1567 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001568 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1569 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001570 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1571
Austin Schuh07676622021-01-21 18:59:17 -08001572 EXPECT_THAT(reader.LoggedNodes(),
1573 ::testing::ElementsAre(
1574 configuration::GetNode(reader.logged_configuration(), pi1),
1575 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001576
1577 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1578
1579 std::unique_ptr<EventLoop> pi1_event_loop =
1580 log_reader_factory.MakeEventLoop("test", pi1);
1581 std::unique_ptr<EventLoop> pi2_event_loop =
1582 log_reader_factory.MakeEventLoop("test", pi2);
1583
1584 int pi1_ping_count = 30;
1585 int pi2_ping_count = 30;
1586 int pi1_pong_count = 30;
1587 int pi2_pong_count = 30;
1588
1589 // Confirm that the ping value matches.
1590 pi1_event_loop->MakeWatcher(
1591 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1592 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1593 << pi1_event_loop->context().monotonic_remote_time << " -> "
1594 << pi1_event_loop->context().monotonic_event_time;
1595 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1596
1597 ++pi1_ping_count;
1598 });
1599 pi2_event_loop->MakeWatcher(
1600 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1601 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1602 << pi2_event_loop->context().monotonic_remote_time << " -> "
1603 << pi2_event_loop->context().monotonic_event_time;
1604 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1605
1606 ++pi2_ping_count;
1607 });
1608
1609 // Confirm that the ping and pong counts both match, and the value also
1610 // matches.
1611 pi1_event_loop->MakeWatcher(
1612 "/test", [&pi1_event_loop, &pi1_ping_count,
1613 &pi1_pong_count](const examples::Pong &pong) {
1614 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1615 << pi1_event_loop->context().monotonic_remote_time << " -> "
1616 << pi1_event_loop->context().monotonic_event_time;
1617
1618 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1619 ++pi1_pong_count;
1620 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1621 });
1622 pi2_event_loop->MakeWatcher(
1623 "/test", [&pi2_event_loop, &pi2_ping_count,
1624 &pi2_pong_count](const examples::Pong &pong) {
1625 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1626 << pi2_event_loop->context().monotonic_remote_time << " -> "
1627 << pi2_event_loop->context().monotonic_event_time;
1628
1629 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1630 ++pi2_pong_count;
1631 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1632 });
1633
1634 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001635 EXPECT_EQ(pi1_ping_count, 6030);
1636 EXPECT_EQ(pi2_ping_count, 6030);
1637 EXPECT_EQ(pi1_pong_count, 6030);
1638 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001639
1640 reader.Deregister();
1641}
1642
Austin Schuh5212cad2020-09-09 23:12:09 -07001643// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001644TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001645 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001646 // Make a bunch of parts.
1647 {
1648 LoggerState pi1_logger = MakeLogger(pi1_);
1649 LoggerState pi2_logger = MakeLogger(pi2_);
1650
1651 event_loop_factory_.RunFor(chrono::milliseconds(95));
1652
1653 StartLogger(&pi1_logger);
1654 StartLogger(&pi2_logger);
1655
1656 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1657 }
1658
Austin Schuh11d43732020-09-21 17:28:30 -07001659 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001660 VerifyParts(sorted_parts);
1661}
Austin Schuh11d43732020-09-21 17:28:30 -07001662
Austin Schuh3bd4c402020-11-06 18:19:06 -08001663// Tests that we can sort a bunch of parts with an empty part. We should ignore
1664// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001665TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001666 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001667 // Make a bunch of parts.
1668 {
1669 LoggerState pi1_logger = MakeLogger(pi1_);
1670 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001671
Austin Schuh3bd4c402020-11-06 18:19:06 -08001672 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001673
Austin Schuh3bd4c402020-11-06 18:19:06 -08001674 StartLogger(&pi1_logger);
1675 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001676
Austin Schuh3bd4c402020-11-06 18:19:06 -08001677 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001678 }
1679
Austin Schuh3bd4c402020-11-06 18:19:06 -08001680 // TODO(austin): Should we flip out if the file can't open?
1681 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001682
Austin Schuh3bd4c402020-11-06 18:19:06 -08001683 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1684 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001685
Austin Schuh3bd4c402020-11-06 18:19:06 -08001686 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1687 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001688}
1689
Austin Schuh3bd4c402020-11-06 18:19:06 -08001690#ifdef LZMA
1691// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1692// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001693TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001694 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001695 // Make a bunch of parts.
1696 {
1697 LoggerState pi1_logger = MakeLogger(pi1_);
1698 LoggerState pi2_logger = MakeLogger(pi2_);
1699
1700 event_loop_factory_.RunFor(chrono::milliseconds(95));
1701
1702 StartLogger(&pi1_logger, "", true);
1703 StartLogger(&pi2_logger, "", true);
1704
1705 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1706 }
1707
1708 // TODO(austin): Should we flip out if the file can't open?
1709 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1710
1711 AddExtension(".xz");
1712
1713 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1714 logfiles_.emplace_back(kEmptyFile);
1715
1716 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1717 VerifyParts(sorted_parts, {kEmptyFile});
1718}
1719
1720// Tests that we can sort a bunch of parts with the end missing off a compressed
1721// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001722TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001723 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001724 // Make a bunch of parts.
1725 {
1726 LoggerState pi1_logger = MakeLogger(pi1_);
1727 LoggerState pi2_logger = MakeLogger(pi2_);
1728
1729 event_loop_factory_.RunFor(chrono::milliseconds(95));
1730
1731 StartLogger(&pi1_logger, "", true);
1732 StartLogger(&pi2_logger, "", true);
1733
1734 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1735 }
1736
1737 // Append everything with .xz.
1738 AddExtension(".xz");
1739
1740 // Strip off the end of one of the files. Pick one with a lot of data.
1741 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001742 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001743
1744 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001745 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001746 compressed_contents.substr(0, compressed_contents.size() - 100));
1747
1748 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1749 VerifyParts(sorted_parts);
1750}
1751#endif
1752
Austin Schuh01b4c352020-09-21 23:09:39 -07001753// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001754TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001755 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001756 {
1757 LoggerState pi1_logger = MakeLogger(pi1_);
1758 LoggerState pi2_logger = MakeLogger(pi2_);
1759
1760 event_loop_factory_.RunFor(chrono::milliseconds(95));
1761
1762 StartLogger(&pi1_logger);
1763 StartLogger(&pi2_logger);
1764
1765 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1766 }
1767
Austin Schuh287d43d2020-12-04 20:19:33 -08001768 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001769
1770 // Remap just on pi1.
1771 reader.RemapLoggedChannel<aos::timing::Report>(
1772 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1773
1774 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1775 log_reader_factory.set_send_delay(chrono::microseconds(0));
1776
Austin Schuh1c227352021-09-17 12:53:54 -07001777 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1778 ASSERT_EQ(remapped_channels.size(), 1u);
1779 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1780 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1781
Austin Schuh01b4c352020-09-21 23:09:39 -07001782 reader.Register(&log_reader_factory);
1783
1784 const Node *pi1 =
1785 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1786 const Node *pi2 =
1787 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1788
1789 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1790 // else should have moved.
1791 std::unique_ptr<EventLoop> pi1_event_loop =
1792 log_reader_factory.MakeEventLoop("test", pi1);
1793 pi1_event_loop->SkipTimingReport();
1794 std::unique_ptr<EventLoop> full_pi1_event_loop =
1795 log_reader_factory.MakeEventLoop("test", pi1);
1796 full_pi1_event_loop->SkipTimingReport();
1797 std::unique_ptr<EventLoop> pi2_event_loop =
1798 log_reader_factory.MakeEventLoop("test", pi2);
1799 pi2_event_loop->SkipTimingReport();
1800
1801 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1802 "/aos");
1803 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1804 full_pi1_event_loop.get(), "/pi1/aos");
1805 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1806 pi1_event_loop.get(), "/original/aos");
1807 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1808 full_pi1_event_loop.get(), "/original/pi1/aos");
1809 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1810 "/aos");
1811
1812 log_reader_factory.Run();
1813
1814 EXPECT_EQ(pi1_timing_report.count(), 0u);
1815 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1816 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1817 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1818 EXPECT_NE(pi2_timing_report.count(), 0u);
1819
1820 reader.Deregister();
1821}
1822
Austin Schuh006a9f52021-04-07 16:24:18 -07001823// Tests that we can remap a forwarded channel as well.
1824TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1825 time_converter_.StartEqual();
1826 {
1827 LoggerState pi1_logger = MakeLogger(pi1_);
1828 LoggerState pi2_logger = MakeLogger(pi2_);
1829
1830 event_loop_factory_.RunFor(chrono::milliseconds(95));
1831
1832 StartLogger(&pi1_logger);
1833 StartLogger(&pi2_logger);
1834
1835 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1836 }
1837
1838 LogReader reader(SortParts(logfiles_));
1839
1840 reader.RemapLoggedChannel<examples::Ping>("/test");
1841
1842 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1843 log_reader_factory.set_send_delay(chrono::microseconds(0));
1844
1845 reader.Register(&log_reader_factory);
1846
1847 const Node *pi1 =
1848 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1849 const Node *pi2 =
1850 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1851
1852 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1853 // else should have moved.
1854 std::unique_ptr<EventLoop> pi1_event_loop =
1855 log_reader_factory.MakeEventLoop("test", pi1);
1856 pi1_event_loop->SkipTimingReport();
1857 std::unique_ptr<EventLoop> full_pi1_event_loop =
1858 log_reader_factory.MakeEventLoop("test", pi1);
1859 full_pi1_event_loop->SkipTimingReport();
1860 std::unique_ptr<EventLoop> pi2_event_loop =
1861 log_reader_factory.MakeEventLoop("test", pi2);
1862 pi2_event_loop->SkipTimingReport();
1863
1864 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1865 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1866 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1867 "/original/test");
1868 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1869 "/original/test");
1870
1871 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1872 pi1_original_ping_timestamp;
1873 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1874 pi1_ping_timestamp;
1875 if (!shared()) {
1876 pi1_original_ping_timestamp =
1877 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1878 pi1_event_loop.get(),
1879 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1880 pi1_ping_timestamp =
1881 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1882 pi1_event_loop.get(),
1883 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1884 }
1885
1886 log_reader_factory.Run();
1887
1888 EXPECT_EQ(pi1_ping.count(), 0u);
1889 EXPECT_EQ(pi2_ping.count(), 0u);
1890 EXPECT_NE(pi1_original_ping.count(), 0u);
1891 EXPECT_NE(pi2_original_ping.count(), 0u);
1892 if (!shared()) {
1893 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1894 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1895 }
1896
1897 reader.Deregister();
1898}
1899
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001900// Tests that we properly recreate forwarded timestamps when replaying a log.
1901// This should be enough that we can then re-run the logger and get a valid log
1902// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001903TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001904 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001905 {
1906 LoggerState pi1_logger = MakeLogger(pi1_);
1907 LoggerState pi2_logger = MakeLogger(pi2_);
1908
1909 event_loop_factory_.RunFor(chrono::milliseconds(95));
1910
1911 StartLogger(&pi1_logger);
1912 StartLogger(&pi2_logger);
1913
1914 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1915 }
1916
Austin Schuh287d43d2020-12-04 20:19:33 -08001917 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001918
1919 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1920 log_reader_factory.set_send_delay(chrono::microseconds(0));
1921
1922 // This sends out the fetched messages and advances time to the start of the
1923 // log file.
1924 reader.Register(&log_reader_factory);
1925
1926 const Node *pi1 =
1927 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1928 const Node *pi2 =
1929 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1930
1931 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1932 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1933 LOG(INFO) << "now pi1 "
1934 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1935 LOG(INFO) << "now pi2 "
1936 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1937
Austin Schuh07676622021-01-21 18:59:17 -08001938 EXPECT_THAT(reader.LoggedNodes(),
1939 ::testing::ElementsAre(
1940 configuration::GetNode(reader.logged_configuration(), pi1),
1941 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001942
1943 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1944
1945 std::unique_ptr<EventLoop> pi1_event_loop =
1946 log_reader_factory.MakeEventLoop("test", pi1);
1947 std::unique_ptr<EventLoop> pi2_event_loop =
1948 log_reader_factory.MakeEventLoop("test", pi2);
1949
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001950 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1951 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1952 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1953 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1954
1955 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1956 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1957 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1958 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1959
1960 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1961 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1962 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1963 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1964
1965 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1966 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1967 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1968 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1969
1970 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1971 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1972 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1973 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1974
1975 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1976 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1977 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1978 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1979
Austin Schuh969cd602021-01-03 00:09:45 -08001980 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001981 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001982
Austin Schuh61e973f2021-02-21 21:43:56 -08001983 for (std::pair<int, std::string> channel :
1984 shared()
1985 ? std::vector<
1986 std::pair<int, std::string>>{{-1,
1987 "/aos/remote_timestamps/pi2"}}
1988 : std::vector<std::pair<int, std::string>>{
1989 {pi1_timestamp_channel,
1990 "/aos/remote_timestamps/pi2/pi1/aos/"
1991 "aos-message_bridge-Timestamp"},
1992 {ping_timestamp_channel,
1993 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1994 pi1_event_loop->MakeWatcher(
1995 channel.second,
1996 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1997 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1998 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1999 &ping_on_pi2_fetcher, network_delay, send_delay,
2000 channel_index = channel.first](const RemoteMessage &header) {
2001 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2002 chrono::nanoseconds(header.monotonic_sent_time()));
2003 const aos::realtime_clock::time_point header_realtime_sent_time(
2004 chrono::nanoseconds(header.realtime_sent_time()));
2005 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2006 chrono::nanoseconds(header.monotonic_remote_time()));
2007 const aos::realtime_clock::time_point header_realtime_remote_time(
2008 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002009
Austin Schuh61e973f2021-02-21 21:43:56 -08002010 if (channel_index != -1) {
2011 ASSERT_EQ(channel_index, header.channel_index());
2012 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002013
Austin Schuh61e973f2021-02-21 21:43:56 -08002014 const Context *pi1_context = nullptr;
2015 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002016
Austin Schuh61e973f2021-02-21 21:43:56 -08002017 if (header.channel_index() == pi1_timestamp_channel) {
2018 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2019 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2020 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2021 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2022 } else if (header.channel_index() == ping_timestamp_channel) {
2023 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2024 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2025 pi1_context = &ping_on_pi1_fetcher.context();
2026 pi2_context = &ping_on_pi2_fetcher.context();
2027 } else {
2028 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2029 << configuration::CleanedChannelToString(
2030 pi1_event_loop->configuration()->channels()->Get(
2031 header.channel_index()));
2032 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002033
Austin Schuh61e973f2021-02-21 21:43:56 -08002034 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002035 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2036 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002037
Austin Schuh61e973f2021-02-21 21:43:56 -08002038 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2039 EXPECT_EQ(pi2_context->remote_queue_index,
2040 header.remote_queue_index());
2041 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002042
Austin Schuh61e973f2021-02-21 21:43:56 -08002043 EXPECT_EQ(pi2_context->monotonic_event_time,
2044 header_monotonic_sent_time);
2045 EXPECT_EQ(pi2_context->realtime_event_time,
2046 header_realtime_sent_time);
2047 EXPECT_EQ(pi2_context->realtime_remote_time,
2048 header_realtime_remote_time);
2049 EXPECT_EQ(pi2_context->monotonic_remote_time,
2050 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002051
Austin Schuh61e973f2021-02-21 21:43:56 -08002052 EXPECT_EQ(pi1_context->realtime_event_time,
2053 header_realtime_remote_time);
2054 EXPECT_EQ(pi1_context->monotonic_event_time,
2055 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002056
Austin Schuh61e973f2021-02-21 21:43:56 -08002057 // Time estimation isn't perfect, but we know the clocks were
2058 // identical when logged, so we know when this should have come back.
2059 // Confirm we got it when we expected.
2060 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2061 pi1_context->monotonic_event_time + 2 * network_delay +
2062 send_delay);
2063 });
2064 }
2065 for (std::pair<int, std::string> channel :
2066 shared()
2067 ? std::vector<
2068 std::pair<int, std::string>>{{-1,
2069 "/aos/remote_timestamps/pi1"}}
2070 : std::vector<std::pair<int, std::string>>{
2071 {pi2_timestamp_channel,
2072 "/aos/remote_timestamps/pi1/pi2/aos/"
2073 "aos-message_bridge-Timestamp"}}) {
2074 pi2_event_loop->MakeWatcher(
2075 channel.second,
2076 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2077 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2078 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2079 &pong_on_pi1_fetcher, network_delay, send_delay,
2080 channel_index = channel.first](const RemoteMessage &header) {
2081 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2082 chrono::nanoseconds(header.monotonic_sent_time()));
2083 const aos::realtime_clock::time_point header_realtime_sent_time(
2084 chrono::nanoseconds(header.realtime_sent_time()));
2085 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2086 chrono::nanoseconds(header.monotonic_remote_time()));
2087 const aos::realtime_clock::time_point header_realtime_remote_time(
2088 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002089
Austin Schuh61e973f2021-02-21 21:43:56 -08002090 if (channel_index != -1) {
2091 ASSERT_EQ(channel_index, header.channel_index());
2092 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002093
Austin Schuh61e973f2021-02-21 21:43:56 -08002094 const Context *pi2_context = nullptr;
2095 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002096
Austin Schuh61e973f2021-02-21 21:43:56 -08002097 if (header.channel_index() == pi2_timestamp_channel) {
2098 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2099 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2100 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2101 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2102 } else if (header.channel_index() == pong_timestamp_channel) {
2103 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2104 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2105 pi2_context = &pong_on_pi2_fetcher.context();
2106 pi1_context = &pong_on_pi1_fetcher.context();
2107 } else {
2108 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2109 << configuration::CleanedChannelToString(
2110 pi2_event_loop->configuration()->channels()->Get(
2111 header.channel_index()));
2112 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002113
Austin Schuh61e973f2021-02-21 21:43:56 -08002114 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002115 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2116 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002117
Austin Schuh61e973f2021-02-21 21:43:56 -08002118 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2119 EXPECT_EQ(pi1_context->remote_queue_index,
2120 header.remote_queue_index());
2121 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002122
Austin Schuh61e973f2021-02-21 21:43:56 -08002123 EXPECT_EQ(pi1_context->monotonic_event_time,
2124 header_monotonic_sent_time);
2125 EXPECT_EQ(pi1_context->realtime_event_time,
2126 header_realtime_sent_time);
2127 EXPECT_EQ(pi1_context->realtime_remote_time,
2128 header_realtime_remote_time);
2129 EXPECT_EQ(pi1_context->monotonic_remote_time,
2130 header_monotonic_remote_time);
2131
2132 EXPECT_EQ(pi2_context->realtime_event_time,
2133 header_realtime_remote_time);
2134 EXPECT_EQ(pi2_context->monotonic_event_time,
2135 header_monotonic_remote_time);
2136
2137 // Time estimation isn't perfect, but we know the clocks were
2138 // identical when logged, so we know when this should have come back.
2139 // Confirm we got it when we expected.
2140 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2141 pi2_context->monotonic_event_time + 2 * network_delay +
2142 send_delay);
2143 });
2144 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002145
2146 // And confirm we can re-create a log again, while checking the contents.
2147 {
2148 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002149 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002150 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002151 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002152
Austin Schuh25b46712021-01-03 00:04:38 -08002153 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2154 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002155
2156 log_reader_factory.Run();
2157 }
2158
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002159 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002160
2161 // And verify that we can run the LogReader over the relogged files without
2162 // hitting any fatal errors.
2163 {
2164 LogReader relogged_reader(SortParts(
2165 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2166 relogged_reader.Register();
2167
2168 relogged_reader.event_loop_factory()->Run();
2169 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002170}
2171
Austin Schuh315b96b2020-12-11 21:21:12 -08002172// Tests that we properly populate and extract the logger_start time by setting
2173// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002174TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002175 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002176 {BootTimestamp::epoch(),
2177 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002178 {
2179 LoggerState pi1_logger = MakeLogger(pi1_);
2180 LoggerState pi2_logger = MakeLogger(pi2_);
2181
Austin Schuh315b96b2020-12-11 21:21:12 -08002182 StartLogger(&pi1_logger);
2183 StartLogger(&pi2_logger);
2184
2185 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2186 }
2187
2188 for (const LogFile &log_file : SortParts(logfiles_)) {
2189 for (const LogParts &log_part : log_file.parts) {
2190 if (log_part.node == log_file.logger_node) {
2191 EXPECT_EQ(log_part.logger_monotonic_start_time,
2192 aos::monotonic_clock::min_time);
2193 EXPECT_EQ(log_part.logger_realtime_start_time,
2194 aos::realtime_clock::min_time);
2195 } else {
2196 const chrono::seconds offset = log_file.logger_node == "pi1"
2197 ? -chrono::seconds(1000)
2198 : chrono::seconds(1000);
2199 EXPECT_EQ(log_part.logger_monotonic_start_time,
2200 log_part.monotonic_start_time + offset);
2201 EXPECT_EQ(log_part.logger_realtime_start_time,
2202 log_file.realtime_start_time +
2203 (log_part.logger_monotonic_start_time -
2204 log_file.monotonic_start_time));
2205 }
2206 }
2207 }
2208}
2209
Austin Schuh6bb8a822021-03-31 23:04:39 -07002210// Test that renaming the base, renames the folder.
2211TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002212 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2213 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002214 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002215 {BootTimestamp::epoch(),
2216 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002217 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2218 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2219 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2220 LoggerState pi1_logger = MakeLogger(pi1_);
2221 LoggerState pi2_logger = MakeLogger(pi2_);
2222
2223 StartLogger(&pi1_logger);
2224 StartLogger(&pi2_logger);
2225
2226 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2227 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2228 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2229 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2230 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2231 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2232 for (auto &file : logfiles_) {
2233 struct stat s;
2234 EXPECT_EQ(0, stat(file.c_str(), &s));
2235 }
2236}
2237
2238// Test that renaming the file base dies.
2239TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2240 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002241 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002242 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002243 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2244 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2245 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2246 LoggerState pi1_logger = MakeLogger(pi1_);
2247 StartLogger(&pi1_logger);
2248 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2249 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2250 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2251 "Rename of file base from");
2252}
2253
Austin Schuh8bd96322020-02-13 21:18:22 -08002254// TODO(austin): We can write a test which recreates a logfile and confirms that
2255// we get it back. That is the ultimate test.
2256
Austin Schuh315b96b2020-12-11 21:21:12 -08002257// Tests that we properly recreate forwarded timestamps when replaying a log.
2258// This should be enough that we can then re-run the logger and get a valid log
2259// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002260TEST_P(MultinodeLoggerTest, RemoteReboot) {
2261 const UUID pi1_boot0 = UUID::Random();
2262 const UUID pi2_boot0 = UUID::Random();
2263 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002264 {
Austin Schuh58646e22021-08-23 23:51:46 -07002265 CHECK_EQ(pi1_index_, 0u);
2266 CHECK_EQ(pi2_index_, 1u);
2267
2268 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2269 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2270 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2271
2272 time_converter_.AddNextTimestamp(
2273 distributed_clock::epoch(),
2274 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2275 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2276 time_converter_.AddNextTimestamp(
2277 distributed_clock::epoch() + reboot_time,
2278 {BootTimestamp::epoch() + reboot_time,
2279 BootTimestamp{
2280 .boot = 1,
2281 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2282 }
2283
2284 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002285 LoggerState pi1_logger = MakeLogger(pi1_);
2286
2287 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002288 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2289 pi1_boot0);
2290 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2291 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002292
2293 StartLogger(&pi1_logger);
2294
2295 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2296
Austin Schuh58646e22021-08-23 23:51:46 -07002297 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002298
2299 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002300 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2301 pi1_boot0);
2302 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2303 pi2_boot1);
Austin Schuh315b96b2020-12-11 21:21:12 -08002304 }
2305
Austin Schuh72211ae2021-08-05 14:02:30 -07002306 // Confirm that our new oldest timestamps properly update as we reboot and
2307 // rotate.
2308 for (const std::string &file : pi1_reboot_logfiles_) {
2309 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2310 ReadHeader(file);
2311 CHECK(log_header);
2312 if (log_header->message().has_configuration()) {
2313 continue;
2314 }
2315
Austin Schuh58646e22021-08-23 23:51:46 -07002316 const monotonic_clock::time_point monotonic_start_time =
2317 monotonic_clock::time_point(
2318 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2319 const UUID source_node_boot_uuid = UUID::FromString(
2320 log_header->message().source_node_boot_uuid()->string_view());
2321
Austin Schuh72211ae2021-08-05 14:02:30 -07002322 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh58646e22021-08-23 23:51:46 -07002323 switch (log_header->message().parts_index()) {
2324 case 0:
2325 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2326 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2327 break;
2328 case 1:
2329 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2330 ASSERT_EQ(monotonic_start_time,
2331 monotonic_clock::epoch() + chrono::seconds(1));
2332 break;
2333 case 2:
2334 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2335 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2336 break;
2337 case 3:
2338 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2339 ASSERT_EQ(monotonic_start_time,
2340 monotonic_clock::epoch() + chrono::nanoseconds(2322999462));
2341 break;
2342 default:
2343 FAIL();
2344 break;
2345 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002346 continue;
2347 }
2348 SCOPED_TRACE(file);
2349 SCOPED_TRACE(aos::FlatbufferToJson(
2350 *log_header, {.multi_line = true, .max_vector_size = 100}));
2351 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2352 ASSERT_EQ(
2353 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2354 EXPECT_EQ(
2355 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2356 monotonic_clock::max_time.time_since_epoch().count());
2357 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2358 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2359 2u);
2360 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2361 monotonic_clock::max_time.time_since_epoch().count());
2362 ASSERT_TRUE(log_header->message()
2363 .has_oldest_remote_unreliable_monotonic_timestamps());
2364 ASSERT_EQ(log_header->message()
2365 .oldest_remote_unreliable_monotonic_timestamps()
2366 ->size(),
2367 2u);
2368 EXPECT_EQ(log_header->message()
2369 .oldest_remote_unreliable_monotonic_timestamps()
2370 ->Get(0),
2371 monotonic_clock::max_time.time_since_epoch().count());
2372 ASSERT_TRUE(log_header->message()
2373 .has_oldest_local_unreliable_monotonic_timestamps());
2374 ASSERT_EQ(log_header->message()
2375 .oldest_local_unreliable_monotonic_timestamps()
2376 ->size(),
2377 2u);
2378 EXPECT_EQ(log_header->message()
2379 .oldest_local_unreliable_monotonic_timestamps()
2380 ->Get(0),
2381 monotonic_clock::max_time.time_since_epoch().count());
2382
2383 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2384 monotonic_clock::time_point(chrono::nanoseconds(
2385 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2386 1)));
2387 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2388 monotonic_clock::time_point(chrono::nanoseconds(
2389 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2390 const monotonic_clock::time_point
2391 oldest_remote_unreliable_monotonic_timestamps =
2392 monotonic_clock::time_point(chrono::nanoseconds(
2393 log_header->message()
2394 .oldest_remote_unreliable_monotonic_timestamps()
2395 ->Get(1)));
2396 const monotonic_clock::time_point
2397 oldest_local_unreliable_monotonic_timestamps =
2398 monotonic_clock::time_point(chrono::nanoseconds(
2399 log_header->message()
2400 .oldest_local_unreliable_monotonic_timestamps()
2401 ->Get(1)));
2402 switch (log_header->message().parts_index()) {
2403 case 0:
2404 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2405 monotonic_clock::max_time);
2406 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2407 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2408 monotonic_clock::max_time);
2409 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2410 monotonic_clock::max_time);
2411 break;
2412 case 1:
2413 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2414 monotonic_clock::time_point(chrono::microseconds(90200)));
2415 EXPECT_EQ(oldest_local_monotonic_timestamps,
2416 monotonic_clock::time_point(chrono::microseconds(90350)));
2417 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2418 monotonic_clock::time_point(chrono::microseconds(90200)));
2419 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2420 monotonic_clock::time_point(chrono::microseconds(90350)));
2421 break;
2422 case 2:
2423 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002424 monotonic_clock::time_point(chrono::milliseconds(1323) +
2425 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002426 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002427 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002428 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002429 monotonic_clock::time_point(chrono::milliseconds(1323) +
2430 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002431 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2432 monotonic_clock::time_point(chrono::microseconds(10100350)));
2433 break;
2434 default:
2435 FAIL();
2436 break;
2437 }
2438 }
2439
Austin Schuh315b96b2020-12-11 21:21:12 -08002440 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002441 {
2442 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002443
Austin Schuh58646e22021-08-23 23:51:46 -07002444 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2445 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002446
Austin Schuh58646e22021-08-23 23:51:46 -07002447 // This sends out the fetched messages and advances time to the start of
2448 // the log file.
2449 reader.Register(&log_reader_factory);
2450
2451 log_reader_factory.Run();
2452
2453 reader.Deregister();
2454 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002455}
2456
Austin Schuhc9049732020-12-21 22:27:15 -08002457// Tests that we properly handle one direction of message_bridge being
2458// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002459TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002460 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002461 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002462 {BootTimestamp::epoch(),
2463 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002464
2465 time_converter_.AddMonotonic(
2466 {chrono::milliseconds(10000),
2467 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002468 {
2469 LoggerState pi1_logger = MakeLogger(pi1_);
2470
2471 event_loop_factory_.RunFor(chrono::milliseconds(95));
2472
2473 StartLogger(&pi1_logger);
2474
2475 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2476 }
2477
2478 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2479 // to confirm the right thing happened.
2480 ConfirmReadable(pi1_single_direction_logfiles_);
2481}
2482
2483// Tests that we properly handle one direction of message_bridge being
2484// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002485TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002486 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002487 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002488 {BootTimestamp::epoch(),
2489 BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002490
2491 time_converter_.AddMonotonic(
2492 {chrono::milliseconds(10000),
2493 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2494 {
2495 LoggerState pi1_logger = MakeLogger(pi1_);
2496
2497 event_loop_factory_.RunFor(chrono::milliseconds(95));
2498
2499 StartLogger(&pi1_logger);
2500
2501 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2502 }
2503
2504 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2505 // to confirm the right thing happened.
2506 ConfirmReadable(pi1_single_direction_logfiles_);
2507}
2508
Austin Schuhe9f00232021-09-16 18:04:23 -07002509// Tests that we explode if someone passes in a part file twice with a better
2510// error than an out of order error.
2511TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2512 time_converter_.AddMonotonic(
2513 {BootTimestamp::epoch(),
2514 BootTimestamp::epoch() + chrono::seconds(1000)});
2515 {
2516 LoggerState pi1_logger = MakeLogger(pi1_);
2517
2518 event_loop_factory_.RunFor(chrono::milliseconds(95));
2519
2520 StartLogger(&pi1_logger);
2521
2522 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2523 }
2524
2525 std::vector<std::string> duplicates;
2526 for (const std::string &f : pi1_single_direction_logfiles_) {
2527 duplicates.emplace_back(f);
2528 duplicates.emplace_back(f);
2529 }
2530 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
2531}
2532
Austin Schuh87dd3832021-01-01 23:07:31 -08002533// Tests that we properly handle a dead node. Do this by just disconnecting it
2534// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002535TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07002536 pi1_->Disconnect(pi2_->node());
2537 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002538 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002539 {BootTimestamp::epoch(),
2540 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002541 {
2542 LoggerState pi1_logger = MakeLogger(pi1_);
2543
2544 event_loop_factory_.RunFor(chrono::milliseconds(95));
2545
2546 StartLogger(&pi1_logger);
2547
2548 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2549 }
2550
2551 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2552 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002553 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002554}
2555
Austin Schuhcdd90272021-03-15 12:46:16 -07002556constexpr std::string_view kCombinedConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002557 "cad3b6838a518ab29470771a959b89945ee034bc7a738080fd1713a1dce51b1f");
Austin Schuhcdd90272021-03-15 12:46:16 -07002558constexpr std::string_view kSplitConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002559 "aafdd7e43d1942cce5b3e2dd8c6b9706abf7068a43501625a33b7cdfddf6c932");
Austin Schuhcdd90272021-03-15 12:46:16 -07002560
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002561INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002562 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002563 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2564 kCombinedConfigSha1},
2565 Param{"multinode_pingpong_split_config.json", false,
2566 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002567
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002568INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002569 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002570 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2571 kCombinedConfigSha1},
2572 Param{"multinode_pingpong_split_config.json", false,
2573 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002574
Austin Schuh5b728b72021-06-16 14:57:15 -07002575// Tests that we can relog with a different config. This makes most sense when
2576// you are trying to edit a log and want to use channel renaming + the original
2577// config in the new log.
2578TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
2579 time_converter_.StartEqual();
2580 {
2581 LoggerState pi1_logger = MakeLogger(pi1_);
2582 LoggerState pi2_logger = MakeLogger(pi2_);
2583
2584 event_loop_factory_.RunFor(chrono::milliseconds(95));
2585
2586 StartLogger(&pi1_logger);
2587 StartLogger(&pi2_logger);
2588
2589 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2590 }
2591
2592 LogReader reader(SortParts(logfiles_));
2593 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
2594
2595 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2596 log_reader_factory.set_send_delay(chrono::microseconds(0));
2597
2598 // This sends out the fetched messages and advances time to the start of the
2599 // log file.
2600 reader.Register(&log_reader_factory);
2601
2602 const Node *pi1 =
2603 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2604 const Node *pi2 =
2605 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2606
2607 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2608 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2609 LOG(INFO) << "now pi1 "
2610 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2611 LOG(INFO) << "now pi2 "
2612 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2613
2614 EXPECT_THAT(reader.LoggedNodes(),
2615 ::testing::ElementsAre(
2616 configuration::GetNode(reader.logged_configuration(), pi1),
2617 configuration::GetNode(reader.logged_configuration(), pi2)));
2618
2619 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2620
2621 // And confirm we can re-create a log again, while checking the contents.
2622 std::vector<std::string> log_files;
2623 {
2624 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002625 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002626 &log_reader_factory, reader.logged_configuration());
2627 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002628 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002629 &log_reader_factory, reader.logged_configuration());
2630
2631 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2632 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
2633
2634 log_reader_factory.Run();
2635
2636 for (auto &x : pi1_logger.log_namer->all_filenames()) {
2637 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
2638 }
2639 for (auto &x : pi2_logger.log_namer->all_filenames()) {
2640 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
2641 }
2642 }
2643
2644 reader.Deregister();
2645
2646 // And verify that we can run the LogReader over the relogged files without
2647 // hitting any fatal errors.
2648 {
2649 LogReader relogged_reader(SortParts(log_files));
2650 relogged_reader.Register();
2651
2652 relogged_reader.event_loop_factory()->Run();
2653 }
2654}
Austin Schuha04efed2021-01-24 18:04:20 -08002655
Austin Schuhe309d2a2019-11-29 13:25:21 -08002656} // namespace testing
2657} // namespace logger
2658} // namespace aos