blob: 7bf947894971eb7639d2ccd409ddaa39a76c2041 [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"
James Kuszmauldd0a5042021-10-28 23:38:04 -07006#include "aos/events/logging/snappy_encoder.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08007#include "aos/events/logging/log_writer.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
171 logger_event_loop->OnRun(
172 [base_name1, base_name2, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700175 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 base_name2, logger_event_loop.get(),
177 logger_event_loop->node())),
Brian Silverman1f345222020-09-24 21:14:48 -0700178 "Already logging");
179 });
180 event_loop_factory_.RunFor(chrono::milliseconds(20000));
181 }
182}
183
184// Tests calling StopLogging twice.
185TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800186 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700187 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800188 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700189 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700190 const ::std::string logfile = base_name + ".part0.bfbs";
191 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800192 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700193 unlink(logfile.c_str());
194
195 LOG(INFO) << "Logging data to " << logfile;
196
197 {
198 std::unique_ptr<EventLoop> logger_event_loop =
199 event_loop_factory_.MakeEventLoop("logger");
200
201 event_loop_factory_.RunFor(chrono::milliseconds(95));
202
203 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800204 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700205 logger.set_polling_period(std::chrono::milliseconds(100));
206 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700207 logger.StartLogging(std::make_unique<LocalLogNamer>(
208 base_name, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700209 logger.StopLogging(aos::monotonic_clock::min_time);
210 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
211 "Not logging right now");
212 });
213 event_loop_factory_.RunFor(chrono::milliseconds(20000));
214 }
215}
216
217// Tests that we can startup twice.
218TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800219 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700220 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800221 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700222 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700223 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
224 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800225 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700226 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700227 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
228 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800229 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700230 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800231 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700232
233 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
234
235 {
236 std::unique_ptr<EventLoop> logger_event_loop =
237 event_loop_factory_.MakeEventLoop("logger");
238
239 event_loop_factory_.RunFor(chrono::milliseconds(95));
240
241 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800242 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700243 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh5b728b72021-06-16 14:57:15 -0700244 logger.StartLogging(std::make_unique<LocalLogNamer>(
245 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700246 event_loop_factory_.RunFor(chrono::milliseconds(10000));
247 logger.StopLogging(logger_event_loop->monotonic_now());
248 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh5b728b72021-06-16 14:57:15 -0700249 logger.StartLogging(std::make_unique<LocalLogNamer>(
250 base_name2, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700251 event_loop_factory_.RunFor(chrono::milliseconds(10000));
252 }
253
254 for (const auto &logfile :
255 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
256 SCOPED_TRACE(std::get<0>(logfile));
257 LogReader reader(std::get<0>(logfile));
258 reader.Register();
259
Austin Schuh07676622021-01-21 18:59:17 -0800260 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700261
262 std::unique_ptr<EventLoop> test_event_loop =
263 reader.event_loop_factory()->MakeEventLoop("log_reader");
264
265 int ping_count = std::get<1>(logfile);
266 int pong_count = std::get<1>(logfile);
267
268 // Confirm that the ping and pong counts both match, and the value also
269 // matches.
270 test_event_loop->MakeWatcher("/test",
271 [&ping_count](const examples::Ping &ping) {
272 EXPECT_EQ(ping.value(), ping_count + 1);
273 ++ping_count;
274 });
275 test_event_loop->MakeWatcher(
276 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
277 EXPECT_EQ(pong.value(), pong_count + 1);
278 ++pong_count;
279 EXPECT_EQ(ping_count, pong_count);
280 });
281
282 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
283 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
284 }
285}
286
Austin Schuhfa895892020-01-07 20:07:41 -0800287// Tests that we can read and write rotated log files.
288TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800289 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700290 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800291 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700292 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700293 const ::std::string logfile0 = base_name + ".part0.bfbs";
294 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800295 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800296 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800297 unlink(logfile0.c_str());
298 unlink(logfile1.c_str());
299
300 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
301
302 {
Austin Schuhfa895892020-01-07 20:07:41 -0800303 std::unique_ptr<EventLoop> logger_event_loop =
304 event_loop_factory_.MakeEventLoop("logger");
305
306 event_loop_factory_.RunFor(chrono::milliseconds(95));
307
Brian Silverman1f345222020-09-24 21:14:48 -0700308 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800309 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700310 logger.set_polling_period(std::chrono::milliseconds(100));
311 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800312 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700313 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800314 event_loop_factory_.RunFor(chrono::milliseconds(10000));
315 }
316
Austin Schuh64fab802020-09-09 22:47:47 -0700317 {
318 // Confirm that the UUIDs match for both the parts and the logger, and the
319 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800320 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700321 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800322 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700323 }
324
Brian Silvermanae7c0332020-09-30 16:58:23 -0700325 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
326 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700327 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
328 log_header[1].message().parts_uuid()->string_view());
329
330 EXPECT_EQ(log_header[0].message().parts_index(), 0);
331 EXPECT_EQ(log_header[1].message().parts_index(), 1);
332 }
333
Austin Schuhfa895892020-01-07 20:07:41 -0800334 // Even though it doesn't make any difference here, exercise the logic for
335 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800336 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800337
338 // Confirm that we can remap logged channels to point to new buses.
339 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
340
341 // This sends out the fetched messages and advances time to the start of the
342 // log file.
343 reader.Register();
344
Austin Schuh07676622021-01-21 18:59:17 -0800345 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800346
347 std::unique_ptr<EventLoop> test_event_loop =
348 reader.event_loop_factory()->MakeEventLoop("log_reader");
349
350 int ping_count = 10;
351 int pong_count = 10;
352
353 // Confirm that the ping value matches in the remapped channel location.
354 test_event_loop->MakeWatcher("/original/test",
355 [&ping_count](const examples::Ping &ping) {
356 EXPECT_EQ(ping.value(), ping_count + 1);
357 ++ping_count;
358 });
359 // Confirm that the ping and pong counts both match, and the value also
360 // matches.
361 test_event_loop->MakeWatcher(
362 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
363 EXPECT_EQ(pong.value(), pong_count + 1);
364 ++pong_count;
365 EXPECT_EQ(ping_count, pong_count);
366 });
367
368 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
369 EXPECT_EQ(ping_count, 2010);
370}
371
Austin Schuh4c4e0092019-12-22 16:18:03 -0800372// Tests that a large number of messages per second doesn't overwhelm writev.
373TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800374 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700375 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800376 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700377 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700378 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800379 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800380 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800381 unlink(logfile.c_str());
382
383 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700384 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800385
386 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800387 std::unique_ptr<EventLoop> logger_event_loop =
388 event_loop_factory_.MakeEventLoop("logger");
389
390 std::unique_ptr<EventLoop> ping_spammer_event_loop =
391 event_loop_factory_.MakeEventLoop("ping_spammer");
392 aos::Sender<examples::Ping> ping_sender =
393 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
394
395 aos::TimerHandler *timer_handler =
396 ping_spammer_event_loop->AddTimer([&ping_sender]() {
397 aos::Sender<examples::Ping>::Builder builder =
398 ping_sender.MakeBuilder();
399 examples::Ping::Builder ping_builder =
400 builder.MakeBuilder<examples::Ping>();
401 CHECK(builder.Send(ping_builder.Finish()));
402 });
403
404 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
405 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
406 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
407 chrono::microseconds(50));
408 });
409
Brian Silverman1f345222020-09-24 21:14:48 -0700410 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800411 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700412 logger.set_polling_period(std::chrono::milliseconds(100));
413 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800414
415 event_loop_factory_.RunFor(chrono::milliseconds(1000));
416 }
417}
418
James Kuszmauldd0a5042021-10-28 23:38:04 -0700419struct CompressionParams {
420 std::string_view extension;
421 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
422};
423
424std::ostream &operator<<(std::ostream &ostream,
425 const CompressionParams &params) {
426 ostream << "\"" << params.extension << "\"";
427 return ostream;
428}
429
430std::vector<CompressionParams> SupportedCompressionAlgorithms() {
431 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
432 {SnappyDecoder::kExtension,
433 []() { return std::make_unique<SnappyEncoder>(); }},
434#ifdef LZMA
435 {LzmaDecoder::kExtension,
436 []() { return std::make_unique<LzmaEncoder>(3); }}
437#endif // LZMA
438 };
439}
440
Austin Schuh61e973f2021-02-21 21:43:56 -0800441// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700442struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800443 // The config file to use.
444 std::string config;
445 // If true, the RemoteMessage channel should be shared between all the remote
446 // channels. If false, there will be 1 RemoteMessage channel per remote
447 // channel.
448 bool shared;
449 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700450 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800451};
Austin Schuh315b96b2020-12-11 21:21:12 -0800452
James Kuszmauldd0a5042021-10-28 23:38:04 -0700453std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
454 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
455 << ", sha256: \"" << params.sha256 << "\"}";
456 return ostream;
457}
458
Austin Schuh3e20c692021-11-16 20:43:16 -0800459struct LoggerState {
460 static LoggerState MakeLogger(NodeEventLoopFactory *node,
461 SimulatedEventLoopFactory *factory,
462 CompressionParams params,
463 const Configuration *configuration = nullptr) {
464 if (configuration == nullptr) {
465 configuration = factory->configuration();
466 }
467 return {node->MakeEventLoop("logger"),
468 {},
469 configuration,
470 configuration::GetNode(configuration, node->node()),
471 nullptr,
472 params};
473 }
474
475 void StartLogger(std::string logfile_base) {
476 CHECK(!logfile_base.empty());
477
478 logger = std::make_unique<Logger>(event_loop.get(), configuration);
479 logger->set_polling_period(std::chrono::milliseconds(100));
480 logger->set_name(
481 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
482 event_loop->OnRun([this, logfile_base]() {
483 std::unique_ptr<MultiNodeLogNamer> namer =
484 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
485 event_loop.get(), node);
486 namer->set_extension(params.extension);
487 namer->set_encoder_factory(params.encoder_factory);
488 log_namer = namer.get();
489
490 logger->StartLogging(std::move(namer));
491 });
492 }
493
494 std::unique_ptr<EventLoop> event_loop;
495 std::unique_ptr<Logger> logger;
496 const Configuration *configuration;
497 const Node *node;
498 MultiNodeLogNamer *log_namer;
499 CompressionParams params;
500
501 void AppendAllFilenames(std::vector<std::string> *filenames) {
502 for (const std::string &file : log_namer->all_filenames()) {
503 const std::string_view separator =
504 log_namer->base_name().back() == '/' ? "" : "_";
505 filenames->emplace_back(
506 absl::StrCat(log_namer->base_name(), separator, file));
507 }
508 }
509
510 ~LoggerState() {
511 if (logger) {
512 for (const std::string &file : log_namer->all_filenames()) {
513 LOG(INFO) << "Wrote to " << file;
514 }
515 }
516 }
517};
518
519void ConfirmReadable(const std::vector<std::string> &files) {
520 {
521 LogReader reader(SortParts(files));
522
523 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
524 reader.Register(&log_reader_factory);
525
526 log_reader_factory.Run();
527
528 reader.Deregister();
529 }
530 {
531 LogReader reader(SortParts(files));
532
533 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
534 reader.RegisterWithoutStarting(&log_reader_factory);
535 if (configuration::MultiNode(log_reader_factory.configuration())) {
536 for (const aos::Node *node :
537 *log_reader_factory.configuration()->nodes()) {
538 reader.OnStart(node, [node]() {
539 LOG(INFO) << "Starting " << node->name()->string_view();
540 });
541 }
542 }
543
544 log_reader_factory.Run();
545
546 reader.Deregister();
547 }
548}
549
James Kuszmauldd0a5042021-10-28 23:38:04 -0700550class MultinodeLoggerTest : public ::testing::TestWithParam<
551 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800552 public:
553 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700554 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
555 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800556 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800557 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700558 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800559 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700560 event_loop_factory_.configuration(), pi1_->node())),
561 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800562 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700563 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800564 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800565 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
566 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800567 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800568 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800569 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700570 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700571 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800572 event_loop_factory_.SetTimeConverter(&time_converter_);
573
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700574 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700575 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700576 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800577 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700578 }
579
Austin Schuh268586b2021-03-31 22:24:39 -0700580 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800581 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800582 unlink(file.c_str());
583 }
584
Austin Schuh268586b2021-03-31 22:24:39 -0700585 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800586 unlink(file.c_str());
587 }
588
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700589 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
590 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700591
592 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
593 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700594 }
595
James Kuszmauldd0a5042021-10-28 23:38:04 -0700596 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800597
598 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700599 std::string logfile_base2,
600 size_t pi1_data_count = 2,
601 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800602 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700603 result.emplace_back(absl::StrCat(
604 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
605 result.emplace_back(absl::StrCat(
606 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700607 for (size_t i = 0; i < pi1_data_count; ++i) {
608 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700609 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700610 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800611 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700612 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800613 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700614 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700615 for (size_t i = 0; i < pi2_data_count; ++i) {
616 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700617 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700618 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700619 result.emplace_back(logfile_base2 +
620 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
621 Extension());
622 result.emplace_back(logfile_base2 +
623 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
624 Extension());
625 result.emplace_back(logfile_base1 +
626 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
627 Extension());
628 result.emplace_back(logfile_base1 +
629 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
630 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800631 if (shared()) {
632 result.emplace_back(logfile_base1 +
633 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700634 "aos.message_bridge.RemoteMessage.part0" +
635 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800636 result.emplace_back(logfile_base1 +
637 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700638 "aos.message_bridge.RemoteMessage.part1" +
639 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800640 result.emplace_back(logfile_base2 +
641 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700642 "aos.message_bridge.RemoteMessage.part0" +
643 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800644 result.emplace_back(logfile_base2 +
645 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700646 "aos.message_bridge.RemoteMessage.part1" +
647 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800648 } else {
649 result.emplace_back(logfile_base1 +
650 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
651 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700652 "aos.message_bridge.RemoteMessage.part0" +
653 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800654 result.emplace_back(logfile_base1 +
655 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
656 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700657 "aos.message_bridge.RemoteMessage.part1" +
658 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800659 result.emplace_back(logfile_base2 +
660 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
661 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700662 "aos.message_bridge.RemoteMessage.part0" +
663 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800664 result.emplace_back(logfile_base2 +
665 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
666 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700667 "aos.message_bridge.RemoteMessage.part1" +
668 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800669 result.emplace_back(logfile_base1 +
670 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
671 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700672 "aos.message_bridge.RemoteMessage.part0" +
673 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800674 result.emplace_back(logfile_base1 +
675 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
676 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700677 "aos.message_bridge.RemoteMessage.part1" +
678 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800679 }
680
681 return result;
682 }
683
684 std::vector<std::string> MakePi1RebootLogfiles() {
685 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700686 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
687 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
688 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800689 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700690 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800691 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700692 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800693 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700694 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700695 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700696 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
697 result.emplace_back(logfile_base1_ +
698 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
699 Extension());
700 result.emplace_back(logfile_base1_ +
701 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
702 Extension());
703 result.emplace_back(logfile_base1_ +
704 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
705 Extension());
706 result.emplace_back(logfile_base1_ +
707 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
708 Extension());
709 result.emplace_back(absl::StrCat(
710 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800711 if (shared()) {
712 result.emplace_back(logfile_base1_ +
713 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700714 "aos.message_bridge.RemoteMessage.part0" +
715 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800716 result.emplace_back(logfile_base1_ +
717 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700718 "aos.message_bridge.RemoteMessage.part1" +
719 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800720 result.emplace_back(logfile_base1_ +
721 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700722 "aos.message_bridge.RemoteMessage.part2" +
723 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700724 result.emplace_back(logfile_base1_ +
725 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700726 "aos.message_bridge.RemoteMessage.part3" +
727 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800728 } else {
729 result.emplace_back(logfile_base1_ +
730 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
731 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700732 "aos.message_bridge.RemoteMessage.part0" +
733 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800734 result.emplace_back(logfile_base1_ +
735 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
736 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700737 "aos.message_bridge.RemoteMessage.part1" +
738 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800739 result.emplace_back(logfile_base1_ +
740 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
741 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700742 "aos.message_bridge.RemoteMessage.part2" +
743 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700744 result.emplace_back(logfile_base1_ +
745 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
746 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700747 "aos.message_bridge.RemoteMessage.part3" +
748 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800749
750 result.emplace_back(logfile_base1_ +
751 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
752 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700753 "aos.message_bridge.RemoteMessage.part0" +
754 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800755 result.emplace_back(logfile_base1_ +
756 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
757 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700758 "aos.message_bridge.RemoteMessage.part1" +
759 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800760 result.emplace_back(logfile_base1_ +
761 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
762 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700763 "aos.message_bridge.RemoteMessage.part2" +
764 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700765 result.emplace_back(logfile_base1_ +
766 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
767 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700768 "aos.message_bridge.RemoteMessage.part3" +
769 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800770 }
771 return result;
772 }
773
774 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
775 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700776 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
777 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
778 result.emplace_back(logfile_base1_ +
779 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
780 Extension());
781 result.emplace_back(absl::StrCat(
782 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700783 return result;
784 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800785
Austin Schuh510dc622021-08-06 18:47:30 -0700786 std::vector<std::string> MakePi1DeadNodeLogfiles() {
787 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700788 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
789 result.emplace_back(absl::StrCat(
790 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800791 return result;
792 }
793
794 std::vector<std::vector<std::string>> StructureLogFiles() {
795 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700796 std::vector<std::string>{logfiles_[2], logfiles_[3]},
797 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800798 std::vector<std::string>{logfiles_[6], logfiles_[7]},
799 std::vector<std::string>{logfiles_[8], logfiles_[9]},
800 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700801 std::vector<std::string>{logfiles_[12], logfiles_[13]},
802 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800803
804 if (!shared()) {
805 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700806 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800807 }
808
809 return result;
810 }
811
James Kuszmauldd0a5042021-10-28 23:38:04 -0700812 std::string Extension() {
813 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
814 }
815
Austin Schuh58646e22021-08-23 23:51:46 -0700816 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700817 SimulatedEventLoopFactory *factory = nullptr,
818 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700819 if (factory == nullptr) {
820 factory = &event_loop_factory_;
821 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800822 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
823 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700824 }
825
James Kuszmauldd0a5042021-10-28 23:38:04 -0700826 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700827 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800828 if (logger->event_loop->node()->name()->string_view() == "pi1") {
829 logfile_base = logfile_base1_;
830 } else {
831 logfile_base = logfile_base2_;
832 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700833 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800834 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700835 }
Austin Schuh15649d62019-12-28 16:36:38 -0800836
Austin Schuh3bd4c402020-11-06 18:19:06 -0800837 void VerifyParts(const std::vector<LogFile> &sorted_parts,
838 const std::vector<std::string> &corrupted_parts = {}) {
839 EXPECT_EQ(sorted_parts.size(), 2u);
840
841 // Count up the number of UUIDs and make sure they are what we expect as a
842 // sanity check.
843 std::set<std::string> log_event_uuids;
844 std::set<std::string> parts_uuids;
845 std::set<std::string> both_uuids;
846
847 size_t missing_rt_count = 0;
848
849 std::vector<std::string> logger_nodes;
850 for (const LogFile &log_file : sorted_parts) {
851 EXPECT_FALSE(log_file.log_event_uuid.empty());
852 log_event_uuids.insert(log_file.log_event_uuid);
853 logger_nodes.emplace_back(log_file.logger_node);
854 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800855 EXPECT_TRUE(log_file.config);
856 EXPECT_EQ(log_file.name,
857 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800858
859 for (const LogParts &part : log_file.parts) {
860 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
861 << ": " << part;
862 missing_rt_count +=
863 part.realtime_start_time == aos::realtime_clock::min_time;
864
865 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
866 log_event_uuids.end());
867 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800868 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800869 parts_uuids.insert(part.parts_uuid);
870 both_uuids.insert(part.parts_uuid);
871 }
872 }
873
Austin Schuh61e973f2021-02-21 21:43:56 -0800874 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
875 // start time on remote nodes because we don't know it and would be
876 // guessing. And the log reader can actually do a better job. The number
877 // depends on if we have the remote timestamps split across 2 files, or just
878 // across 1, depending on if we are using a split or combined timestamp
879 // channel config.
880 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800881
882 EXPECT_EQ(log_event_uuids.size(), 2u);
883 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
884 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
885
886 // Test that each list of parts is in order. Don't worry about the ordering
887 // between part file lists though.
888 // (inner vectors all need to be in order, but outer one doesn't matter).
889 EXPECT_THAT(ToLogReaderVector(sorted_parts),
890 ::testing::UnorderedElementsAreArray(structured_logfiles_));
891
892 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
893
894 EXPECT_NE(sorted_parts[0].realtime_start_time,
895 aos::realtime_clock::min_time);
896 EXPECT_NE(sorted_parts[1].realtime_start_time,
897 aos::realtime_clock::min_time);
898
899 EXPECT_NE(sorted_parts[0].monotonic_start_time,
900 aos::monotonic_clock::min_time);
901 EXPECT_NE(sorted_parts[1].monotonic_start_time,
902 aos::monotonic_clock::min_time);
903
904 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
905 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
906 }
907
908 void AddExtension(std::string_view extension) {
909 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
910 [extension](const std::string &in) {
911 return absl::StrCat(in, extension);
912 });
913
914 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
915 structured_logfiles_.begin(),
916 [extension](std::vector<std::string> in) {
917 std::transform(in.begin(), in.end(), in.begin(),
918 [extension](const std::string &in_str) {
919 return absl::StrCat(in_str, extension);
920 });
921 return in;
922 });
923 }
924
Austin Schuh15649d62019-12-28 16:36:38 -0800925 // Config and factory.
926 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800927 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800928 SimulatedEventLoopFactory event_loop_factory_;
929
Austin Schuh58646e22021-08-23 23:51:46 -0700930 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800931 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700932 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800933 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700934
935 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800936 std::string logfile_base1_;
937 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800938 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700939 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800940 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700941
942 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800943};
944
Austin Schuh391e3172020-09-01 22:48:18 -0700945// Counts the number of messages on a channel. Returns (channel name, channel
946// type, count) for every message matching matcher()
947std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800948 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700949 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800950 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800951 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800952
Austin Schuh6f3babe2020-01-26 20:34:50 -0800953 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700954 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800955 if (!msg) {
956 break;
957 }
958
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700959 if (matcher(msg.get())) {
960 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800961 }
962 }
963
Austin Schuh391e3172020-09-01 22:48:18 -0700964 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800965 int channel = 0;
966 for (size_t i = 0; i < counts.size(); ++i) {
967 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800968 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700969 result.push_back(std::make_tuple(channel->name()->str(),
970 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800971 }
972 ++channel;
973 }
974
975 return result;
976}
977
978// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700979std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800980 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700981 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700982 return CountChannelsMatching(
983 config, filename, [](const UnpackedMessageHeader *msg) {
984 if (msg->span.data() != nullptr) {
985 CHECK(!msg->monotonic_remote_time.has_value());
986 CHECK(!msg->realtime_remote_time.has_value());
987 CHECK(!msg->remote_queue_index.has_value());
988 return true;
989 }
990 return false;
991 });
Austin Schuh6f3babe2020-01-26 20:34:50 -0800992}
993
994// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700995std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800996 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800997 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700998 return CountChannelsMatching(
999 config, filename, [](const UnpackedMessageHeader *msg) {
1000 if (msg->span.data() == nullptr) {
1001 CHECK(msg->monotonic_remote_time.has_value());
1002 CHECK(msg->realtime_remote_time.has_value());
1003 CHECK(msg->remote_queue_index.has_value());
1004 return true;
1005 }
1006 return false;
1007 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001008}
1009
Austin Schuhcde938c2020-02-02 17:30:07 -08001010// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001011TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001012 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -08001013 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001014 LoggerState pi1_logger = MakeLogger(pi1_);
1015 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001016
1017 event_loop_factory_.RunFor(chrono::milliseconds(95));
1018
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001019 StartLogger(&pi1_logger);
1020 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001021
Austin Schuh15649d62019-12-28 16:36:38 -08001022 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1023 }
1024
Austin Schuh6f3babe2020-01-26 20:34:50 -08001025 {
Austin Schuh64fab802020-09-09 22:47:47 -07001026 std::set<std::string> logfile_uuids;
1027 std::set<std::string> parts_uuids;
1028 // Confirm that we have the expected number of UUIDs for both the logfile
1029 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001030 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001031 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001032 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001033 if (!log_header.back().message().has_configuration()) {
1034 logfile_uuids.insert(
1035 log_header.back().message().log_event_uuid()->str());
1036 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1037 }
Austin Schuh64fab802020-09-09 22:47:47 -07001038 }
Austin Schuh15649d62019-12-28 16:36:38 -08001039
Austin Schuh64fab802020-09-09 22:47:47 -07001040 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001041 if (shared()) {
1042 EXPECT_EQ(parts_uuids.size(), 7u);
1043 } else {
1044 EXPECT_EQ(parts_uuids.size(), 8u);
1045 }
Austin Schuh64fab802020-09-09 22:47:47 -07001046
1047 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001048 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001049 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001050 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
1051 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001052 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
1053 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
1054 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
1055 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001056 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
1057 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001058 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1059 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
1060 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
1061 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -08001062 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001063 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
1064 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001065 }
Austin Schuh64fab802020-09-09 22:47:47 -07001066
1067 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001068 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001069 EXPECT_EQ(log_header[3].message().parts_index(), 1);
1070 EXPECT_EQ(log_header[4].message().parts_index(), 0);
1071 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -07001072 EXPECT_EQ(log_header[6].message().parts_index(), 0);
1073 EXPECT_EQ(log_header[7].message().parts_index(), 1);
1074 EXPECT_EQ(log_header[8].message().parts_index(), 0);
1075 EXPECT_EQ(log_header[9].message().parts_index(), 1);
1076 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1077 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001078 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1079 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -07001080 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1081 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001082 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001083 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1084 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001085 }
Austin Schuh64fab802020-09-09 22:47:47 -07001086 }
1087
Austin Schuh8c399962020-12-25 21:51:45 -08001088 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001089 {
Austin Schuh391e3172020-09-01 22:48:18 -07001090 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001091 std::shared_ptr<const aos::Configuration> config =
1092 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001093
Austin Schuh6f3babe2020-01-26 20:34:50 -08001094 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001095 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1096 UnorderedElementsAre(
1097 std::make_tuple("/pi1/aos",
1098 "aos.message_bridge.ServerStatistics", 1),
1099 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001100 << " : " << logfiles_[2];
1101 EXPECT_THAT(
1102 CountChannelsData(config, logfiles_[3]),
1103 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -07001104 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001105 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001106 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001107 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1108 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001109 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001110 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1111 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001112 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001113 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1114 UnorderedElementsAre())
1115 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001116 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001117 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001118 UnorderedElementsAre(
1119 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001120 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001121 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001122
1123 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001124 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001125 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001126 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001127 << " : " << logfiles_[4];
1128 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001129 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001130 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001131 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001132
Austin Schuh6f3babe2020-01-26 20:34:50 -08001133 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001134 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001135 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001136 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001137 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1138 UnorderedElementsAre())
1139 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001140
1141 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001142 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1143 UnorderedElementsAre(std::make_tuple(
1144 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1145 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001146 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001147 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001148 UnorderedElementsAre(
1149 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001150 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001151 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001152 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1153 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001154 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001155 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001156 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001157 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001158 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1159 UnorderedElementsAre())
1160 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001161 EXPECT_THAT(
1162 CountChannelsTimestamp(config, logfiles_[7]),
1163 UnorderedElementsAre(
1164 std::make_tuple("/test", "aos.examples.Ping", 2001),
1165 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001166 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001167
1168 // And then test that the remotely logged timestamp data files only have
1169 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001170 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1171 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001172 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001173 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1174 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001175 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001176 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1177 UnorderedElementsAre())
1178 << " : " << logfiles_[10];
1179 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1180 UnorderedElementsAre())
1181 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001182
Austin Schuh8c399962020-12-25 21:51:45 -08001183 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001184 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001185 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001186 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001187 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001188 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001189 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001190 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001191
Austin Schuh8c399962020-12-25 21:51:45 -08001192 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001193 UnorderedElementsAre(std::make_tuple(
1194 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001195 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001196 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001197 UnorderedElementsAre(std::make_tuple(
1198 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001199 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001200
1201 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001202 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1203 UnorderedElementsAre())
1204 << " : " << logfiles_[12];
1205 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1206 UnorderedElementsAre())
1207 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001208 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1209 UnorderedElementsAre())
1210 << " : " << logfiles_[14];
1211 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1212 UnorderedElementsAre())
1213 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001214 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001215 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001216 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001217 << " : " << logfiles_[16];
1218 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001219 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001220 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001221 }
1222
1223 if (shared()) {
1224 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001225 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001226 UnorderedElementsAre(
1227 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1228 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001229 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001230 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001231 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001232 UnorderedElementsAre(
1233 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1234 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001235 << " : " << logfiles_[13];
1236 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001237 UnorderedElementsAre(std::make_tuple(
1238 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001239 << " : " << logfiles_[14];
1240 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001241 UnorderedElementsAre(std::make_tuple(
1242 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1243 << " : " << logfiles_[15];
1244 } else {
1245 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1246 UnorderedElementsAre(std::make_tuple(
1247 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1248 << " : " << logfiles_[12];
1249 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1250 UnorderedElementsAre(std::make_tuple(
1251 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1252 << " : " << logfiles_[13];
1253 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1254 UnorderedElementsAre(std::make_tuple(
1255 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1256 << " : " << logfiles_[14];
1257 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1258 UnorderedElementsAre(std::make_tuple(
1259 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1260 << " : " << logfiles_[15];
1261 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1262 UnorderedElementsAre(
1263 std::make_tuple("/test", "aos.examples.Ping", 91)))
1264 << " : " << logfiles_[16];
1265 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001266 UnorderedElementsAre(
1267 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001268 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001269 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001270 }
1271
Austin Schuh8c399962020-12-25 21:51:45 -08001272 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001273
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001274 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001275 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001276
1277 // This sends out the fetched messages and advances time to the start of the
1278 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001279 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001280
Austin Schuhac0771c2020-01-07 18:36:30 -08001281 const Node *pi1 =
1282 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001283 const Node *pi2 =
1284 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001285
Austin Schuh2f8fd752020-09-01 22:38:28 -07001286 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1287 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1288 LOG(INFO) << "now pi1 "
1289 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1290 LOG(INFO) << "now pi2 "
1291 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1292
Austin Schuh07676622021-01-21 18:59:17 -08001293 EXPECT_THAT(reader.LoggedNodes(),
1294 ::testing::ElementsAre(
1295 configuration::GetNode(reader.logged_configuration(), pi1),
1296 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001297
1298 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001299
Austin Schuh6f3babe2020-01-26 20:34:50 -08001300 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001301 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001302 std::unique_ptr<EventLoop> pi2_event_loop =
1303 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001304
Austin Schuh6f3babe2020-01-26 20:34:50 -08001305 int pi1_ping_count = 10;
1306 int pi2_ping_count = 10;
1307 int pi1_pong_count = 10;
1308 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001309
1310 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001311 pi1_event_loop->MakeWatcher(
1312 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001313 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001314 << pi1_event_loop->context().monotonic_remote_time << " -> "
1315 << pi1_event_loop->context().monotonic_event_time;
1316 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1317 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1318 pi1_ping_count * chrono::milliseconds(10) +
1319 monotonic_clock::epoch());
1320 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1321 pi1_ping_count * chrono::milliseconds(10) +
1322 realtime_clock::epoch());
1323 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1324 pi1_event_loop->context().monotonic_event_time);
1325 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1326 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001327
Austin Schuh6f3babe2020-01-26 20:34:50 -08001328 ++pi1_ping_count;
1329 });
1330 pi2_event_loop->MakeWatcher(
1331 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001332 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001333 << pi2_event_loop->context().monotonic_remote_time << " -> "
1334 << pi2_event_loop->context().monotonic_event_time;
1335 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1336
1337 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1338 pi2_ping_count * chrono::milliseconds(10) +
1339 monotonic_clock::epoch());
1340 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1341 pi2_ping_count * chrono::milliseconds(10) +
1342 realtime_clock::epoch());
1343 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1344 chrono::microseconds(150),
1345 pi2_event_loop->context().monotonic_event_time);
1346 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1347 chrono::microseconds(150),
1348 pi2_event_loop->context().realtime_event_time);
1349 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001350 });
1351
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001352 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001353 // Confirm that the ping and pong counts both match, and the value also
1354 // matches.
1355 pi1_event_loop->MakeWatcher(
1356 "/test", [&pi1_event_loop, &pi1_ping_count,
1357 &pi1_pong_count](const examples::Pong &pong) {
1358 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1359 << pi1_event_loop->context().monotonic_remote_time << " -> "
1360 << pi1_event_loop->context().monotonic_event_time;
1361
1362 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1363 pi1_pong_count + kQueueIndexOffset);
1364 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1365 chrono::microseconds(200) +
1366 pi1_pong_count * chrono::milliseconds(10) +
1367 monotonic_clock::epoch());
1368 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1369 chrono::microseconds(200) +
1370 pi1_pong_count * chrono::milliseconds(10) +
1371 realtime_clock::epoch());
1372
1373 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1374 chrono::microseconds(150),
1375 pi1_event_loop->context().monotonic_event_time);
1376 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1377 chrono::microseconds(150),
1378 pi1_event_loop->context().realtime_event_time);
1379
1380 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1381 ++pi1_pong_count;
1382 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1383 });
1384 pi2_event_loop->MakeWatcher(
1385 "/test", [&pi2_event_loop, &pi2_ping_count,
1386 &pi2_pong_count](const examples::Pong &pong) {
1387 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1388 << pi2_event_loop->context().monotonic_remote_time << " -> "
1389 << pi2_event_loop->context().monotonic_event_time;
1390
1391 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001392 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001393
1394 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1395 chrono::microseconds(200) +
1396 pi2_pong_count * chrono::milliseconds(10) +
1397 monotonic_clock::epoch());
1398 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1399 chrono::microseconds(200) +
1400 pi2_pong_count * chrono::milliseconds(10) +
1401 realtime_clock::epoch());
1402
1403 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1404 pi2_event_loop->context().monotonic_event_time);
1405 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1406 pi2_event_loop->context().realtime_event_time);
1407
1408 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1409 ++pi2_pong_count;
1410 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1411 });
1412
1413 log_reader_factory.Run();
1414 EXPECT_EQ(pi1_ping_count, 2010);
1415 EXPECT_EQ(pi2_ping_count, 2010);
1416 EXPECT_EQ(pi1_pong_count, 2010);
1417 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001418
1419 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001420}
1421
James Kuszmaul46d82582020-05-09 19:50:09 -07001422typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1423
1424// Test that if we feed the replay with a mismatched node list that we die on
1425// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001426TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001427 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001428 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001429 LoggerState pi1_logger = MakeLogger(pi1_);
1430 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001431
1432 event_loop_factory_.RunFor(chrono::milliseconds(95));
1433
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001434 StartLogger(&pi1_logger);
1435 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001436
James Kuszmaul46d82582020-05-09 19:50:09 -07001437 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1438 }
1439
1440 // Test that, if we add an additional node to the replay config that the
1441 // logger complains about the mismatch in number of nodes.
1442 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1443 configuration::MergeWithConfig(&config_.message(), R"({
1444 "nodes": [
1445 {
1446 "name": "extra-node"
1447 }
1448 ]
1449 }
1450 )");
1451
Austin Schuh287d43d2020-12-04 20:19:33 -08001452 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1453 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001454 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001455}
1456
Austin Schuhcde938c2020-02-02 17:30:07 -08001457// Tests that we can read log files where they don't start at the same monotonic
1458// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001459TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001460 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001461 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001462 LoggerState pi1_logger = MakeLogger(pi1_);
1463 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001464
1465 event_loop_factory_.RunFor(chrono::milliseconds(95));
1466
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001467 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001468
1469 event_loop_factory_.RunFor(chrono::milliseconds(200));
1470
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001471 StartLogger(&pi2_logger);
1472
Austin Schuhcde938c2020-02-02 17:30:07 -08001473 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1474 }
1475
Austin Schuhe46492f2021-07-31 19:49:41 -07001476 // Since we delay starting pi2, it already knows about all the timestamps so
1477 // we don't end up with extra parts.
1478 LogReader reader(
1479 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001480
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001481 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001482 log_reader_factory.set_send_delay(chrono::microseconds(0));
1483
1484 // This sends out the fetched messages and advances time to the start of the
1485 // log file.
1486 reader.Register(&log_reader_factory);
1487
1488 const Node *pi1 =
1489 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1490 const Node *pi2 =
1491 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1492
Austin Schuh07676622021-01-21 18:59:17 -08001493 EXPECT_THAT(reader.LoggedNodes(),
1494 ::testing::ElementsAre(
1495 configuration::GetNode(reader.logged_configuration(), pi1),
1496 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001497
1498 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1499
1500 std::unique_ptr<EventLoop> pi1_event_loop =
1501 log_reader_factory.MakeEventLoop("test", pi1);
1502 std::unique_ptr<EventLoop> pi2_event_loop =
1503 log_reader_factory.MakeEventLoop("test", pi2);
1504
1505 int pi1_ping_count = 30;
1506 int pi2_ping_count = 30;
1507 int pi1_pong_count = 30;
1508 int pi2_pong_count = 30;
1509
1510 // Confirm that the ping value matches.
1511 pi1_event_loop->MakeWatcher(
1512 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1513 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1514 << pi1_event_loop->context().monotonic_remote_time << " -> "
1515 << pi1_event_loop->context().monotonic_event_time;
1516 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1517
1518 ++pi1_ping_count;
1519 });
1520 pi2_event_loop->MakeWatcher(
1521 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1522 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1523 << pi2_event_loop->context().monotonic_remote_time << " -> "
1524 << pi2_event_loop->context().monotonic_event_time;
1525 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1526
1527 ++pi2_ping_count;
1528 });
1529
1530 // Confirm that the ping and pong counts both match, and the value also
1531 // matches.
1532 pi1_event_loop->MakeWatcher(
1533 "/test", [&pi1_event_loop, &pi1_ping_count,
1534 &pi1_pong_count](const examples::Pong &pong) {
1535 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1536 << pi1_event_loop->context().monotonic_remote_time << " -> "
1537 << pi1_event_loop->context().monotonic_event_time;
1538
1539 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1540 ++pi1_pong_count;
1541 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1542 });
1543 pi2_event_loop->MakeWatcher(
1544 "/test", [&pi2_event_loop, &pi2_ping_count,
1545 &pi2_pong_count](const examples::Pong &pong) {
1546 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1547 << pi2_event_loop->context().monotonic_remote_time << " -> "
1548 << pi2_event_loop->context().monotonic_event_time;
1549
1550 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1551 ++pi2_pong_count;
1552 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1553 });
1554
1555 log_reader_factory.Run();
1556 EXPECT_EQ(pi1_ping_count, 2030);
1557 EXPECT_EQ(pi2_ping_count, 2030);
1558 EXPECT_EQ(pi1_pong_count, 2030);
1559 EXPECT_EQ(pi2_pong_count, 2030);
1560
1561 reader.Deregister();
1562}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001563
Austin Schuh8bd96322020-02-13 21:18:22 -08001564// Tests that we can read log files where the monotonic clocks drift and don't
1565// match correctly. While we are here, also test that different ending times
1566// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001567TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001568 // TODO(austin): Negate...
1569 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1570
Austin Schuh66168842021-08-17 19:42:21 -07001571 time_converter_.AddMonotonic(
1572 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001573 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1574 // skew to be 200 uS/s
1575 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1576 {chrono::milliseconds(95),
1577 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1578 // Run another 200 ms to have one logger start first.
1579 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1580 {chrono::milliseconds(200), chrono::milliseconds(200)});
1581 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1582 // go far enough to cause problems if this isn't accounted for.
1583 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1584 {chrono::milliseconds(20000),
1585 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1586 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1587 {chrono::milliseconds(40000),
1588 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1589 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1590 {chrono::milliseconds(400), chrono::milliseconds(400)});
1591
Austin Schuhcde938c2020-02-02 17:30:07 -08001592 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001593 LoggerState pi2_logger = MakeLogger(pi2_);
1594
Austin Schuh58646e22021-08-23 23:51:46 -07001595 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1596 << pi2_->realtime_now() << " distributed "
1597 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001598
Austin Schuh58646e22021-08-23 23:51:46 -07001599 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1600 << pi2_->realtime_now() << " distributed "
1601 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001602
Austin Schuh87dd3832021-01-01 23:07:31 -08001603 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001604
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001605 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001606
Austin Schuh87dd3832021-01-01 23:07:31 -08001607 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001608
Austin Schuh8bd96322020-02-13 21:18:22 -08001609 {
1610 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001611 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001612
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001613 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001614 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001615
Austin Schuh87dd3832021-01-01 23:07:31 -08001616 // Make sure we slewed time far enough so that the difference is greater
1617 // than the network delay. This confirms that if we sort incorrectly, it
1618 // would show in the results.
1619 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001620 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001621 -event_loop_factory_.send_delay() -
1622 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001623
Austin Schuh87dd3832021-01-01 23:07:31 -08001624 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001625
Austin Schuh87dd3832021-01-01 23:07:31 -08001626 // And now check that we went far enough the other way to make sure we
1627 // cover both problems.
1628 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001629 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001630 event_loop_factory_.send_delay() +
1631 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001632 }
1633
1634 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001635 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001636 }
1637
Austin Schuh72211ae2021-08-05 14:02:30 -07001638 LogReader reader(
1639 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001640
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001641 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001642 log_reader_factory.set_send_delay(chrono::microseconds(0));
1643
Austin Schuhcde938c2020-02-02 17:30:07 -08001644 const Node *pi1 =
1645 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1646 const Node *pi2 =
1647 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1648
Austin Schuh2f8fd752020-09-01 22:38:28 -07001649 // This sends out the fetched messages and advances time to the start of the
1650 // log file.
1651 reader.Register(&log_reader_factory);
1652
1653 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1654 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1655 LOG(INFO) << "now pi1 "
1656 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1657 LOG(INFO) << "now pi2 "
1658 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1659
Austin Schuhcde938c2020-02-02 17:30:07 -08001660 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001661 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1662 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001663 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1664 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001665 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1666 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001667 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1668
Austin Schuh07676622021-01-21 18:59:17 -08001669 EXPECT_THAT(reader.LoggedNodes(),
1670 ::testing::ElementsAre(
1671 configuration::GetNode(reader.logged_configuration(), pi1),
1672 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001673
1674 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1675
1676 std::unique_ptr<EventLoop> pi1_event_loop =
1677 log_reader_factory.MakeEventLoop("test", pi1);
1678 std::unique_ptr<EventLoop> pi2_event_loop =
1679 log_reader_factory.MakeEventLoop("test", pi2);
1680
1681 int pi1_ping_count = 30;
1682 int pi2_ping_count = 30;
1683 int pi1_pong_count = 30;
1684 int pi2_pong_count = 30;
1685
1686 // Confirm that the ping value matches.
1687 pi1_event_loop->MakeWatcher(
1688 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1689 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1690 << pi1_event_loop->context().monotonic_remote_time << " -> "
1691 << pi1_event_loop->context().monotonic_event_time;
1692 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1693
1694 ++pi1_ping_count;
1695 });
1696 pi2_event_loop->MakeWatcher(
1697 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1698 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1699 << pi2_event_loop->context().monotonic_remote_time << " -> "
1700 << pi2_event_loop->context().monotonic_event_time;
1701 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1702
1703 ++pi2_ping_count;
1704 });
1705
1706 // Confirm that the ping and pong counts both match, and the value also
1707 // matches.
1708 pi1_event_loop->MakeWatcher(
1709 "/test", [&pi1_event_loop, &pi1_ping_count,
1710 &pi1_pong_count](const examples::Pong &pong) {
1711 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1712 << pi1_event_loop->context().monotonic_remote_time << " -> "
1713 << pi1_event_loop->context().monotonic_event_time;
1714
1715 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1716 ++pi1_pong_count;
1717 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1718 });
1719 pi2_event_loop->MakeWatcher(
1720 "/test", [&pi2_event_loop, &pi2_ping_count,
1721 &pi2_pong_count](const examples::Pong &pong) {
1722 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1723 << pi2_event_loop->context().monotonic_remote_time << " -> "
1724 << pi2_event_loop->context().monotonic_event_time;
1725
1726 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1727 ++pi2_pong_count;
1728 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1729 });
1730
1731 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001732 EXPECT_EQ(pi1_ping_count, 6030);
1733 EXPECT_EQ(pi2_ping_count, 6030);
1734 EXPECT_EQ(pi1_pong_count, 6030);
1735 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001736
1737 reader.Deregister();
1738}
1739
Austin Schuh5212cad2020-09-09 23:12:09 -07001740// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001741TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001742 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001743 // Make a bunch of parts.
1744 {
1745 LoggerState pi1_logger = MakeLogger(pi1_);
1746 LoggerState pi2_logger = MakeLogger(pi2_);
1747
1748 event_loop_factory_.RunFor(chrono::milliseconds(95));
1749
1750 StartLogger(&pi1_logger);
1751 StartLogger(&pi2_logger);
1752
1753 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1754 }
1755
Austin Schuh11d43732020-09-21 17:28:30 -07001756 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001757 VerifyParts(sorted_parts);
1758}
Austin Schuh11d43732020-09-21 17:28:30 -07001759
Austin Schuh3bd4c402020-11-06 18:19:06 -08001760// Tests that we can sort a bunch of parts with an empty part. We should ignore
1761// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001762TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001763 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001764 // Make a bunch of parts.
1765 {
1766 LoggerState pi1_logger = MakeLogger(pi1_);
1767 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001768
Austin Schuh3bd4c402020-11-06 18:19:06 -08001769 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001770
Austin Schuh3bd4c402020-11-06 18:19:06 -08001771 StartLogger(&pi1_logger);
1772 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001773
Austin Schuh3bd4c402020-11-06 18:19:06 -08001774 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001775 }
1776
Austin Schuh3bd4c402020-11-06 18:19:06 -08001777 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001778 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001779
Austin Schuh3bd4c402020-11-06 18:19:06 -08001780 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1781 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001782
Austin Schuh3bd4c402020-11-06 18:19:06 -08001783 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1784 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001785}
1786
James Kuszmauldd0a5042021-10-28 23:38:04 -07001787// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08001788// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001789TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001790 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001791 // Make a bunch of parts.
1792 {
1793 LoggerState pi1_logger = MakeLogger(pi1_);
1794 LoggerState pi2_logger = MakeLogger(pi2_);
1795
1796 event_loop_factory_.RunFor(chrono::milliseconds(95));
1797
James Kuszmauldd0a5042021-10-28 23:38:04 -07001798 StartLogger(&pi1_logger);
1799 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001800
1801 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1802 }
1803
Austin Schuh3bd4c402020-11-06 18:19:06 -08001804 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001805 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1806 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08001807 ::std::string compressed_contents =
James Kuszmauldd0a5042021-10-28 23:38:04 -07001808 aos::util::ReadFileToStringOrDie(logfiles_[3]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001809
1810 aos::util::WriteStringToFileOrDie(
James Kuszmauldd0a5042021-10-28 23:38:04 -07001811 logfiles_[3],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001812 compressed_contents.substr(0, compressed_contents.size() - 100));
1813
1814 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1815 VerifyParts(sorted_parts);
1816}
Austin Schuh3bd4c402020-11-06 18:19:06 -08001817
Austin Schuh01b4c352020-09-21 23:09:39 -07001818// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001819TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001820 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001821 {
1822 LoggerState pi1_logger = MakeLogger(pi1_);
1823 LoggerState pi2_logger = MakeLogger(pi2_);
1824
1825 event_loop_factory_.RunFor(chrono::milliseconds(95));
1826
1827 StartLogger(&pi1_logger);
1828 StartLogger(&pi2_logger);
1829
1830 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1831 }
1832
Austin Schuh287d43d2020-12-04 20:19:33 -08001833 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001834
1835 // Remap just on pi1.
1836 reader.RemapLoggedChannel<aos::timing::Report>(
1837 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1838
1839 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1840 log_reader_factory.set_send_delay(chrono::microseconds(0));
1841
Austin Schuh1c227352021-09-17 12:53:54 -07001842 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1843 ASSERT_EQ(remapped_channels.size(), 1u);
1844 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1845 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1846
Austin Schuh01b4c352020-09-21 23:09:39 -07001847 reader.Register(&log_reader_factory);
1848
1849 const Node *pi1 =
1850 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1851 const Node *pi2 =
1852 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1853
1854 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1855 // else should have moved.
1856 std::unique_ptr<EventLoop> pi1_event_loop =
1857 log_reader_factory.MakeEventLoop("test", pi1);
1858 pi1_event_loop->SkipTimingReport();
1859 std::unique_ptr<EventLoop> full_pi1_event_loop =
1860 log_reader_factory.MakeEventLoop("test", pi1);
1861 full_pi1_event_loop->SkipTimingReport();
1862 std::unique_ptr<EventLoop> pi2_event_loop =
1863 log_reader_factory.MakeEventLoop("test", pi2);
1864 pi2_event_loop->SkipTimingReport();
1865
1866 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1867 "/aos");
1868 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1869 full_pi1_event_loop.get(), "/pi1/aos");
1870 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1871 pi1_event_loop.get(), "/original/aos");
1872 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1873 full_pi1_event_loop.get(), "/original/pi1/aos");
1874 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1875 "/aos");
1876
1877 log_reader_factory.Run();
1878
1879 EXPECT_EQ(pi1_timing_report.count(), 0u);
1880 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1881 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1882 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1883 EXPECT_NE(pi2_timing_report.count(), 0u);
1884
1885 reader.Deregister();
1886}
1887
Austin Schuh006a9f52021-04-07 16:24:18 -07001888// Tests that we can remap a forwarded channel as well.
1889TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1890 time_converter_.StartEqual();
1891 {
1892 LoggerState pi1_logger = MakeLogger(pi1_);
1893 LoggerState pi2_logger = MakeLogger(pi2_);
1894
1895 event_loop_factory_.RunFor(chrono::milliseconds(95));
1896
1897 StartLogger(&pi1_logger);
1898 StartLogger(&pi2_logger);
1899
1900 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1901 }
1902
1903 LogReader reader(SortParts(logfiles_));
1904
1905 reader.RemapLoggedChannel<examples::Ping>("/test");
1906
1907 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1908 log_reader_factory.set_send_delay(chrono::microseconds(0));
1909
1910 reader.Register(&log_reader_factory);
1911
1912 const Node *pi1 =
1913 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1914 const Node *pi2 =
1915 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1916
1917 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1918 // else should have moved.
1919 std::unique_ptr<EventLoop> pi1_event_loop =
1920 log_reader_factory.MakeEventLoop("test", pi1);
1921 pi1_event_loop->SkipTimingReport();
1922 std::unique_ptr<EventLoop> full_pi1_event_loop =
1923 log_reader_factory.MakeEventLoop("test", pi1);
1924 full_pi1_event_loop->SkipTimingReport();
1925 std::unique_ptr<EventLoop> pi2_event_loop =
1926 log_reader_factory.MakeEventLoop("test", pi2);
1927 pi2_event_loop->SkipTimingReport();
1928
1929 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1930 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1931 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1932 "/original/test");
1933 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1934 "/original/test");
1935
1936 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1937 pi1_original_ping_timestamp;
1938 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1939 pi1_ping_timestamp;
1940 if (!shared()) {
1941 pi1_original_ping_timestamp =
1942 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1943 pi1_event_loop.get(),
1944 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1945 pi1_ping_timestamp =
1946 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1947 pi1_event_loop.get(),
1948 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1949 }
1950
1951 log_reader_factory.Run();
1952
1953 EXPECT_EQ(pi1_ping.count(), 0u);
1954 EXPECT_EQ(pi2_ping.count(), 0u);
1955 EXPECT_NE(pi1_original_ping.count(), 0u);
1956 EXPECT_NE(pi2_original_ping.count(), 0u);
1957 if (!shared()) {
1958 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1959 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1960 }
1961
1962 reader.Deregister();
1963}
1964
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001965// Tests that we properly recreate forwarded timestamps when replaying a log.
1966// This should be enough that we can then re-run the logger and get a valid log
1967// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001968TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001969 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001970 {
1971 LoggerState pi1_logger = MakeLogger(pi1_);
1972 LoggerState pi2_logger = MakeLogger(pi2_);
1973
1974 event_loop_factory_.RunFor(chrono::milliseconds(95));
1975
1976 StartLogger(&pi1_logger);
1977 StartLogger(&pi2_logger);
1978
1979 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1980 }
1981
Austin Schuh287d43d2020-12-04 20:19:33 -08001982 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001983
1984 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1985 log_reader_factory.set_send_delay(chrono::microseconds(0));
1986
1987 // This sends out the fetched messages and advances time to the start of the
1988 // log file.
1989 reader.Register(&log_reader_factory);
1990
1991 const Node *pi1 =
1992 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1993 const Node *pi2 =
1994 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1995
1996 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1997 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1998 LOG(INFO) << "now pi1 "
1999 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2000 LOG(INFO) << "now pi2 "
2001 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2002
Austin Schuh07676622021-01-21 18:59:17 -08002003 EXPECT_THAT(reader.LoggedNodes(),
2004 ::testing::ElementsAre(
2005 configuration::GetNode(reader.logged_configuration(), pi1),
2006 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002007
2008 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2009
2010 std::unique_ptr<EventLoop> pi1_event_loop =
2011 log_reader_factory.MakeEventLoop("test", pi1);
2012 std::unique_ptr<EventLoop> pi2_event_loop =
2013 log_reader_factory.MakeEventLoop("test", pi2);
2014
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002015 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2016 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2017 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2018 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2019
2020 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2021 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2022 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2023 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2024
2025 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2026 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2027 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2028 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2029
2030 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2031 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2032 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2033 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2034
2035 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2036 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2037 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2038 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2039
2040 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2041 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2042 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2043 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2044
Austin Schuh969cd602021-01-03 00:09:45 -08002045 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002046 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002047
Austin Schuh61e973f2021-02-21 21:43:56 -08002048 for (std::pair<int, std::string> channel :
2049 shared()
2050 ? std::vector<
2051 std::pair<int, std::string>>{{-1,
2052 "/aos/remote_timestamps/pi2"}}
2053 : std::vector<std::pair<int, std::string>>{
2054 {pi1_timestamp_channel,
2055 "/aos/remote_timestamps/pi2/pi1/aos/"
2056 "aos-message_bridge-Timestamp"},
2057 {ping_timestamp_channel,
2058 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2059 pi1_event_loop->MakeWatcher(
2060 channel.second,
2061 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2062 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2063 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2064 &ping_on_pi2_fetcher, network_delay, send_delay,
2065 channel_index = channel.first](const RemoteMessage &header) {
2066 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2067 chrono::nanoseconds(header.monotonic_sent_time()));
2068 const aos::realtime_clock::time_point header_realtime_sent_time(
2069 chrono::nanoseconds(header.realtime_sent_time()));
2070 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2071 chrono::nanoseconds(header.monotonic_remote_time()));
2072 const aos::realtime_clock::time_point header_realtime_remote_time(
2073 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002074
Austin Schuh61e973f2021-02-21 21:43:56 -08002075 if (channel_index != -1) {
2076 ASSERT_EQ(channel_index, header.channel_index());
2077 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002078
Austin Schuh61e973f2021-02-21 21:43:56 -08002079 const Context *pi1_context = nullptr;
2080 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002081
Austin Schuh61e973f2021-02-21 21:43:56 -08002082 if (header.channel_index() == pi1_timestamp_channel) {
2083 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2084 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2085 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2086 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2087 } else if (header.channel_index() == ping_timestamp_channel) {
2088 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2089 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2090 pi1_context = &ping_on_pi1_fetcher.context();
2091 pi2_context = &ping_on_pi2_fetcher.context();
2092 } else {
2093 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2094 << configuration::CleanedChannelToString(
2095 pi1_event_loop->configuration()->channels()->Get(
2096 header.channel_index()));
2097 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002098
Austin Schuh61e973f2021-02-21 21:43:56 -08002099 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002100 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2101 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002102
Austin Schuh61e973f2021-02-21 21:43:56 -08002103 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2104 EXPECT_EQ(pi2_context->remote_queue_index,
2105 header.remote_queue_index());
2106 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002107
Austin Schuh61e973f2021-02-21 21:43:56 -08002108 EXPECT_EQ(pi2_context->monotonic_event_time,
2109 header_monotonic_sent_time);
2110 EXPECT_EQ(pi2_context->realtime_event_time,
2111 header_realtime_sent_time);
2112 EXPECT_EQ(pi2_context->realtime_remote_time,
2113 header_realtime_remote_time);
2114 EXPECT_EQ(pi2_context->monotonic_remote_time,
2115 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002116
Austin Schuh61e973f2021-02-21 21:43:56 -08002117 EXPECT_EQ(pi1_context->realtime_event_time,
2118 header_realtime_remote_time);
2119 EXPECT_EQ(pi1_context->monotonic_event_time,
2120 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002121
Austin Schuh61e973f2021-02-21 21:43:56 -08002122 // Time estimation isn't perfect, but we know the clocks were
2123 // identical when logged, so we know when this should have come back.
2124 // Confirm we got it when we expected.
2125 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2126 pi1_context->monotonic_event_time + 2 * network_delay +
2127 send_delay);
2128 });
2129 }
2130 for (std::pair<int, std::string> channel :
2131 shared()
2132 ? std::vector<
2133 std::pair<int, std::string>>{{-1,
2134 "/aos/remote_timestamps/pi1"}}
2135 : std::vector<std::pair<int, std::string>>{
2136 {pi2_timestamp_channel,
2137 "/aos/remote_timestamps/pi1/pi2/aos/"
2138 "aos-message_bridge-Timestamp"}}) {
2139 pi2_event_loop->MakeWatcher(
2140 channel.second,
2141 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2142 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2143 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2144 &pong_on_pi1_fetcher, network_delay, send_delay,
2145 channel_index = channel.first](const RemoteMessage &header) {
2146 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2147 chrono::nanoseconds(header.monotonic_sent_time()));
2148 const aos::realtime_clock::time_point header_realtime_sent_time(
2149 chrono::nanoseconds(header.realtime_sent_time()));
2150 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2151 chrono::nanoseconds(header.monotonic_remote_time()));
2152 const aos::realtime_clock::time_point header_realtime_remote_time(
2153 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002154
Austin Schuh61e973f2021-02-21 21:43:56 -08002155 if (channel_index != -1) {
2156 ASSERT_EQ(channel_index, header.channel_index());
2157 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002158
Austin Schuh61e973f2021-02-21 21:43:56 -08002159 const Context *pi2_context = nullptr;
2160 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002161
Austin Schuh61e973f2021-02-21 21:43:56 -08002162 if (header.channel_index() == pi2_timestamp_channel) {
2163 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2164 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2165 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2166 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2167 } else if (header.channel_index() == pong_timestamp_channel) {
2168 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2169 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2170 pi2_context = &pong_on_pi2_fetcher.context();
2171 pi1_context = &pong_on_pi1_fetcher.context();
2172 } else {
2173 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2174 << configuration::CleanedChannelToString(
2175 pi2_event_loop->configuration()->channels()->Get(
2176 header.channel_index()));
2177 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002178
Austin Schuh61e973f2021-02-21 21:43:56 -08002179 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002180 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2181 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002182
Austin Schuh61e973f2021-02-21 21:43:56 -08002183 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2184 EXPECT_EQ(pi1_context->remote_queue_index,
2185 header.remote_queue_index());
2186 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002187
Austin Schuh61e973f2021-02-21 21:43:56 -08002188 EXPECT_EQ(pi1_context->monotonic_event_time,
2189 header_monotonic_sent_time);
2190 EXPECT_EQ(pi1_context->realtime_event_time,
2191 header_realtime_sent_time);
2192 EXPECT_EQ(pi1_context->realtime_remote_time,
2193 header_realtime_remote_time);
2194 EXPECT_EQ(pi1_context->monotonic_remote_time,
2195 header_monotonic_remote_time);
2196
2197 EXPECT_EQ(pi2_context->realtime_event_time,
2198 header_realtime_remote_time);
2199 EXPECT_EQ(pi2_context->monotonic_event_time,
2200 header_monotonic_remote_time);
2201
2202 // Time estimation isn't perfect, but we know the clocks were
2203 // identical when logged, so we know when this should have come back.
2204 // Confirm we got it when we expected.
2205 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2206 pi2_context->monotonic_event_time + 2 * network_delay +
2207 send_delay);
2208 });
2209 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002210
2211 // And confirm we can re-create a log again, while checking the contents.
2212 {
2213 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002214 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002215 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002216 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002217
Austin Schuh25b46712021-01-03 00:04:38 -08002218 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2219 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002220
2221 log_reader_factory.Run();
2222 }
2223
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002224 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002225
2226 // And verify that we can run the LogReader over the relogged files without
2227 // hitting any fatal errors.
2228 {
2229 LogReader relogged_reader(SortParts(
2230 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2231 relogged_reader.Register();
2232
2233 relogged_reader.event_loop_factory()->Run();
2234 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002235}
2236
Austin Schuh315b96b2020-12-11 21:21:12 -08002237// Tests that we properly populate and extract the logger_start time by setting
2238// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002239TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002240 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002241 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002242 {
2243 LoggerState pi1_logger = MakeLogger(pi1_);
2244 LoggerState pi2_logger = MakeLogger(pi2_);
2245
Austin Schuh315b96b2020-12-11 21:21:12 -08002246 StartLogger(&pi1_logger);
2247 StartLogger(&pi2_logger);
2248
2249 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2250 }
2251
2252 for (const LogFile &log_file : SortParts(logfiles_)) {
2253 for (const LogParts &log_part : log_file.parts) {
2254 if (log_part.node == log_file.logger_node) {
2255 EXPECT_EQ(log_part.logger_monotonic_start_time,
2256 aos::monotonic_clock::min_time);
2257 EXPECT_EQ(log_part.logger_realtime_start_time,
2258 aos::realtime_clock::min_time);
2259 } else {
2260 const chrono::seconds offset = log_file.logger_node == "pi1"
2261 ? -chrono::seconds(1000)
2262 : chrono::seconds(1000);
2263 EXPECT_EQ(log_part.logger_monotonic_start_time,
2264 log_part.monotonic_start_time + offset);
2265 EXPECT_EQ(log_part.logger_realtime_start_time,
2266 log_file.realtime_start_time +
2267 (log_part.logger_monotonic_start_time -
2268 log_file.monotonic_start_time));
2269 }
2270 }
2271 }
2272}
2273
Austin Schuh6bb8a822021-03-31 23:04:39 -07002274// Test that renaming the base, renames the folder.
2275TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002276 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2277 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002278 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002279 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002280 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2281 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2282 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2283 LoggerState pi1_logger = MakeLogger(pi1_);
2284 LoggerState pi2_logger = MakeLogger(pi2_);
2285
2286 StartLogger(&pi1_logger);
2287 StartLogger(&pi2_logger);
2288
2289 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2290 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2291 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2292 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2293 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2294 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2295 for (auto &file : logfiles_) {
2296 struct stat s;
2297 EXPECT_EQ(0, stat(file.c_str(), &s));
2298 }
2299}
2300
2301// Test that renaming the file base dies.
2302TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2303 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002304 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002305 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002306 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2307 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2308 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2309 LoggerState pi1_logger = MakeLogger(pi1_);
2310 StartLogger(&pi1_logger);
2311 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2312 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2313 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2314 "Rename of file base from");
2315}
2316
Austin Schuh8bd96322020-02-13 21:18:22 -08002317// TODO(austin): We can write a test which recreates a logfile and confirms that
2318// we get it back. That is the ultimate test.
2319
Austin Schuh315b96b2020-12-11 21:21:12 -08002320// Tests that we properly recreate forwarded timestamps when replaying a log.
2321// This should be enough that we can then re-run the logger and get a valid log
2322// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002323TEST_P(MultinodeLoggerTest, RemoteReboot) {
2324 const UUID pi1_boot0 = UUID::Random();
2325 const UUID pi2_boot0 = UUID::Random();
2326 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002327 {
Austin Schuh58646e22021-08-23 23:51:46 -07002328 CHECK_EQ(pi1_index_, 0u);
2329 CHECK_EQ(pi2_index_, 1u);
2330
2331 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2332 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2333 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2334
2335 time_converter_.AddNextTimestamp(
2336 distributed_clock::epoch(),
2337 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2338 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2339 time_converter_.AddNextTimestamp(
2340 distributed_clock::epoch() + reboot_time,
2341 {BootTimestamp::epoch() + reboot_time,
2342 BootTimestamp{
2343 .boot = 1,
2344 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2345 }
2346
2347 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002348 LoggerState pi1_logger = MakeLogger(pi1_);
2349
2350 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002351 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2352 pi1_boot0);
2353 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2354 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002355
2356 StartLogger(&pi1_logger);
2357
2358 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2359
Austin Schuh58646e22021-08-23 23:51:46 -07002360 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002361
2362 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002363 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2364 pi1_boot0);
2365 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2366 pi2_boot1);
Austin Schuh315b96b2020-12-11 21:21:12 -08002367 }
2368
Austin Schuh72211ae2021-08-05 14:02:30 -07002369 // Confirm that our new oldest timestamps properly update as we reboot and
2370 // rotate.
2371 for (const std::string &file : pi1_reboot_logfiles_) {
2372 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2373 ReadHeader(file);
2374 CHECK(log_header);
2375 if (log_header->message().has_configuration()) {
2376 continue;
2377 }
2378
Austin Schuh58646e22021-08-23 23:51:46 -07002379 const monotonic_clock::time_point monotonic_start_time =
2380 monotonic_clock::time_point(
2381 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2382 const UUID source_node_boot_uuid = UUID::FromString(
2383 log_header->message().source_node_boot_uuid()->string_view());
2384
Austin Schuh72211ae2021-08-05 14:02:30 -07002385 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh58646e22021-08-23 23:51:46 -07002386 switch (log_header->message().parts_index()) {
2387 case 0:
2388 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2389 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2390 break;
2391 case 1:
2392 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2393 ASSERT_EQ(monotonic_start_time,
2394 monotonic_clock::epoch() + chrono::seconds(1));
2395 break;
2396 case 2:
2397 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2398 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2399 break;
2400 case 3:
2401 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2402 ASSERT_EQ(monotonic_start_time,
2403 monotonic_clock::epoch() + chrono::nanoseconds(2322999462));
2404 break;
2405 default:
2406 FAIL();
2407 break;
2408 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002409 continue;
2410 }
2411 SCOPED_TRACE(file);
2412 SCOPED_TRACE(aos::FlatbufferToJson(
2413 *log_header, {.multi_line = true, .max_vector_size = 100}));
2414 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2415 ASSERT_EQ(
2416 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2417 EXPECT_EQ(
2418 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2419 monotonic_clock::max_time.time_since_epoch().count());
2420 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2421 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2422 2u);
2423 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2424 monotonic_clock::max_time.time_since_epoch().count());
2425 ASSERT_TRUE(log_header->message()
2426 .has_oldest_remote_unreliable_monotonic_timestamps());
2427 ASSERT_EQ(log_header->message()
2428 .oldest_remote_unreliable_monotonic_timestamps()
2429 ->size(),
2430 2u);
2431 EXPECT_EQ(log_header->message()
2432 .oldest_remote_unreliable_monotonic_timestamps()
2433 ->Get(0),
2434 monotonic_clock::max_time.time_since_epoch().count());
2435 ASSERT_TRUE(log_header->message()
2436 .has_oldest_local_unreliable_monotonic_timestamps());
2437 ASSERT_EQ(log_header->message()
2438 .oldest_local_unreliable_monotonic_timestamps()
2439 ->size(),
2440 2u);
2441 EXPECT_EQ(log_header->message()
2442 .oldest_local_unreliable_monotonic_timestamps()
2443 ->Get(0),
2444 monotonic_clock::max_time.time_since_epoch().count());
2445
2446 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2447 monotonic_clock::time_point(chrono::nanoseconds(
2448 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2449 1)));
2450 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2451 monotonic_clock::time_point(chrono::nanoseconds(
2452 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2453 const monotonic_clock::time_point
2454 oldest_remote_unreliable_monotonic_timestamps =
2455 monotonic_clock::time_point(chrono::nanoseconds(
2456 log_header->message()
2457 .oldest_remote_unreliable_monotonic_timestamps()
2458 ->Get(1)));
2459 const monotonic_clock::time_point
2460 oldest_local_unreliable_monotonic_timestamps =
2461 monotonic_clock::time_point(chrono::nanoseconds(
2462 log_header->message()
2463 .oldest_local_unreliable_monotonic_timestamps()
2464 ->Get(1)));
2465 switch (log_header->message().parts_index()) {
2466 case 0:
2467 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2468 monotonic_clock::max_time);
2469 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2470 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2471 monotonic_clock::max_time);
2472 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2473 monotonic_clock::max_time);
2474 break;
2475 case 1:
2476 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2477 monotonic_clock::time_point(chrono::microseconds(90200)));
2478 EXPECT_EQ(oldest_local_monotonic_timestamps,
2479 monotonic_clock::time_point(chrono::microseconds(90350)));
2480 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2481 monotonic_clock::time_point(chrono::microseconds(90200)));
2482 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2483 monotonic_clock::time_point(chrono::microseconds(90350)));
2484 break;
2485 case 2:
2486 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002487 monotonic_clock::time_point(chrono::milliseconds(1323) +
2488 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002489 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002490 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002491 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002492 monotonic_clock::time_point(chrono::milliseconds(1323) +
2493 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002494 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2495 monotonic_clock::time_point(chrono::microseconds(10100350)));
2496 break;
2497 default:
2498 FAIL();
2499 break;
2500 }
2501 }
2502
Austin Schuh315b96b2020-12-11 21:21:12 -08002503 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002504 {
2505 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002506
Austin Schuh58646e22021-08-23 23:51:46 -07002507 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2508 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002509
Austin Schuh58646e22021-08-23 23:51:46 -07002510 // This sends out the fetched messages and advances time to the start of
2511 // the log file.
2512 reader.Register(&log_reader_factory);
2513
2514 log_reader_factory.Run();
2515
2516 reader.Deregister();
2517 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002518}
2519
Austin Schuhc9049732020-12-21 22:27:15 -08002520// Tests that we properly handle one direction of message_bridge being
2521// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002522TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002523 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002524 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002525 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002526
2527 time_converter_.AddMonotonic(
2528 {chrono::milliseconds(10000),
2529 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002530 {
2531 LoggerState pi1_logger = MakeLogger(pi1_);
2532
2533 event_loop_factory_.RunFor(chrono::milliseconds(95));
2534
2535 StartLogger(&pi1_logger);
2536
2537 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2538 }
2539
2540 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2541 // to confirm the right thing happened.
2542 ConfirmReadable(pi1_single_direction_logfiles_);
2543}
2544
2545// Tests that we properly handle one direction of message_bridge being
2546// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002547TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002548 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002549 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002550 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002551
2552 time_converter_.AddMonotonic(
2553 {chrono::milliseconds(10000),
2554 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2555 {
2556 LoggerState pi1_logger = MakeLogger(pi1_);
2557
2558 event_loop_factory_.RunFor(chrono::milliseconds(95));
2559
2560 StartLogger(&pi1_logger);
2561
2562 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2563 }
2564
2565 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2566 // to confirm the right thing happened.
2567 ConfirmReadable(pi1_single_direction_logfiles_);
2568}
2569
Austin Schuhe9f00232021-09-16 18:04:23 -07002570// Tests that we explode if someone passes in a part file twice with a better
2571// error than an out of order error.
2572TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2573 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002574 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07002575 {
2576 LoggerState pi1_logger = MakeLogger(pi1_);
2577
2578 event_loop_factory_.RunFor(chrono::milliseconds(95));
2579
2580 StartLogger(&pi1_logger);
2581
2582 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2583 }
2584
2585 std::vector<std::string> duplicates;
2586 for (const std::string &f : pi1_single_direction_logfiles_) {
2587 duplicates.emplace_back(f);
2588 duplicates.emplace_back(f);
2589 }
2590 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
2591}
2592
Austin Schuh87dd3832021-01-01 23:07:31 -08002593// Tests that we properly handle a dead node. Do this by just disconnecting it
2594// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002595TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07002596 pi1_->Disconnect(pi2_->node());
2597 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002598 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002599 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002600 {
2601 LoggerState pi1_logger = MakeLogger(pi1_);
2602
2603 event_loop_factory_.RunFor(chrono::milliseconds(95));
2604
2605 StartLogger(&pi1_logger);
2606
2607 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2608 }
2609
2610 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2611 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002612 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002613}
2614
Austin Schuhcdd90272021-03-15 12:46:16 -07002615constexpr std::string_view kCombinedConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002616 "cad3b6838a518ab29470771a959b89945ee034bc7a738080fd1713a1dce51b1f");
Austin Schuhcdd90272021-03-15 12:46:16 -07002617constexpr std::string_view kSplitConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002618 "aafdd7e43d1942cce5b3e2dd8c6b9706abf7068a43501625a33b7cdfddf6c932");
Austin Schuhcdd90272021-03-15 12:46:16 -07002619
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002620INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002621 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002622 ::testing::Combine(::testing::Values(
2623 ConfigParams{
2624 "multinode_pingpong_combined_config.json", true,
2625 kCombinedConfigSha1},
2626 ConfigParams{"multinode_pingpong_split_config.json",
2627 false, kSplitConfigSha1}),
2628 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002629
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002630INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002631 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002632 ::testing::Combine(::testing::Values(
2633 ConfigParams{
2634 "multinode_pingpong_combined_config.json", true,
2635 kCombinedConfigSha1},
2636 ConfigParams{"multinode_pingpong_split_config.json",
2637 false, kSplitConfigSha1}),
2638 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002639
Austin Schuh5b728b72021-06-16 14:57:15 -07002640// Tests that we can relog with a different config. This makes most sense when
2641// you are trying to edit a log and want to use channel renaming + the original
2642// config in the new log.
2643TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
2644 time_converter_.StartEqual();
2645 {
2646 LoggerState pi1_logger = MakeLogger(pi1_);
2647 LoggerState pi2_logger = MakeLogger(pi2_);
2648
2649 event_loop_factory_.RunFor(chrono::milliseconds(95));
2650
2651 StartLogger(&pi1_logger);
2652 StartLogger(&pi2_logger);
2653
2654 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2655 }
2656
2657 LogReader reader(SortParts(logfiles_));
2658 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
2659
2660 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2661 log_reader_factory.set_send_delay(chrono::microseconds(0));
2662
2663 // This sends out the fetched messages and advances time to the start of the
2664 // log file.
2665 reader.Register(&log_reader_factory);
2666
2667 const Node *pi1 =
2668 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2669 const Node *pi2 =
2670 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2671
2672 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2673 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2674 LOG(INFO) << "now pi1 "
2675 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2676 LOG(INFO) << "now pi2 "
2677 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2678
2679 EXPECT_THAT(reader.LoggedNodes(),
2680 ::testing::ElementsAre(
2681 configuration::GetNode(reader.logged_configuration(), pi1),
2682 configuration::GetNode(reader.logged_configuration(), pi2)));
2683
2684 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2685
2686 // And confirm we can re-create a log again, while checking the contents.
2687 std::vector<std::string> log_files;
2688 {
2689 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002690 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002691 &log_reader_factory, reader.logged_configuration());
2692 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002693 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002694 &log_reader_factory, reader.logged_configuration());
2695
Austin Schuh3e20c692021-11-16 20:43:16 -08002696 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
2697 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07002698
2699 log_reader_factory.Run();
2700
2701 for (auto &x : pi1_logger.log_namer->all_filenames()) {
2702 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
2703 }
2704 for (auto &x : pi2_logger.log_namer->all_filenames()) {
2705 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
2706 }
2707 }
2708
2709 reader.Deregister();
2710
2711 // And verify that we can run the LogReader over the relogged files without
2712 // hitting any fatal errors.
2713 {
2714 LogReader relogged_reader(SortParts(log_files));
2715 relogged_reader.Register();
2716
2717 relogged_reader.event_loop_factory()->Run();
2718 }
2719}
Austin Schuha04efed2021-01-24 18:04:20 -08002720
Austin Schuh3e20c692021-11-16 20:43:16 -08002721// Tests that we properly replay a log where the start time for a node is before
2722// any data on the node. This can happen if the logger starts before data is
2723// published. While the scenario below is a bit convoluted, we have seen logs
2724// like this generated out in the wild.
2725TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
2726 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
2727 aos::configuration::ReadConfig(ArtifactPath(
2728 "aos/events/logging/multinode_pingpong_split3_config.json"));
2729 message_bridge::TestingTimeConverter time_converter(
2730 configuration::NodesCount(&config.message()));
2731 SimulatedEventLoopFactory event_loop_factory(&config.message());
2732 event_loop_factory.SetTimeConverter(&time_converter);
2733 NodeEventLoopFactory *const pi1 =
2734 event_loop_factory.GetNodeEventLoopFactory("pi1");
2735 const size_t pi1_index = configuration::GetNodeIndex(
2736 event_loop_factory.configuration(), pi1->node());
2737 NodeEventLoopFactory *const pi2 =
2738 event_loop_factory.GetNodeEventLoopFactory("pi2");
2739 const size_t pi2_index = configuration::GetNodeIndex(
2740 event_loop_factory.configuration(), pi2->node());
2741 NodeEventLoopFactory *const pi3 =
2742 event_loop_factory.GetNodeEventLoopFactory("pi3");
2743 const size_t pi3_index = configuration::GetNodeIndex(
2744 event_loop_factory.configuration(), pi3->node());
2745
2746 const std::string kLogfile1_1 =
2747 aos::testing::TestTmpDir() + "/multi_logfile1/";
2748 const std::string kLogfile2_1 =
2749 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
2750 const std::string kLogfile2_2 =
2751 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
2752 const std::string kLogfile3_1 =
2753 aos::testing::TestTmpDir() + "/multi_logfile3/";
2754 util::UnlinkRecursive(kLogfile1_1);
2755 util::UnlinkRecursive(kLogfile2_1);
2756 util::UnlinkRecursive(kLogfile2_2);
2757 util::UnlinkRecursive(kLogfile3_1);
2758 const UUID pi1_boot0 = UUID::Random();
2759 const UUID pi2_boot0 = UUID::Random();
2760 const UUID pi2_boot1 = UUID::Random();
2761 const UUID pi3_boot0 = UUID::Random();
2762 {
2763 CHECK_EQ(pi1_index, 0u);
2764 CHECK_EQ(pi2_index, 1u);
2765 CHECK_EQ(pi3_index, 2u);
2766
2767 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
2768 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
2769 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
2770 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
2771
2772 time_converter.AddNextTimestamp(
2773 distributed_clock::epoch(),
2774 {BootTimestamp::epoch(), BootTimestamp::epoch(),
2775 BootTimestamp::epoch()});
2776 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
2777 time_converter.AddNextTimestamp(
2778 distributed_clock::epoch() + reboot_time,
2779 {BootTimestamp::epoch() + reboot_time,
2780 BootTimestamp{
2781 .boot = 1,
2782 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
2783 BootTimestamp::epoch() + reboot_time});
2784 }
2785
2786 // Make everything perfectly quiet.
2787 event_loop_factory.SkipTimingReport();
2788 event_loop_factory.DisableStatistics();
2789
2790 std::vector<std::string> filenames;
2791 {
2792 LoggerState pi1_logger = LoggerState::MakeLogger(
2793 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2794 LoggerState pi3_logger = LoggerState::MakeLogger(
2795 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2796 {
2797 // And now start the logger.
2798 LoggerState pi2_logger = LoggerState::MakeLogger(
2799 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2800
2801 event_loop_factory.RunFor(chrono::milliseconds(1000));
2802
2803 pi1_logger.StartLogger(kLogfile1_1);
2804 pi3_logger.StartLogger(kLogfile3_1);
2805 pi2_logger.StartLogger(kLogfile2_1);
2806
2807 event_loop_factory.RunFor(chrono::milliseconds(10000));
2808
2809 // Now that we've got a start time in the past, turn on data.
2810 event_loop_factory.EnableStatistics();
2811 std::unique_ptr<aos::EventLoop> ping_event_loop =
2812 pi1->MakeEventLoop("ping");
2813 Ping ping(ping_event_loop.get());
2814
2815 pi2->AlwaysStart<Pong>("pong");
2816
2817 event_loop_factory.RunFor(chrono::milliseconds(3000));
2818
2819 pi2_logger.AppendAllFilenames(&filenames);
2820
2821 // Stop logging on pi2 before rebooting and completely shut off all
2822 // messages on pi2.
2823 pi2->DisableStatistics();
2824 pi1->Disconnect(pi2->node());
2825 pi2->Disconnect(pi1->node());
2826 }
2827 event_loop_factory.RunFor(chrono::milliseconds(7000));
2828 // pi2 now reboots.
2829 {
2830 event_loop_factory.RunFor(chrono::milliseconds(1000));
2831
2832 // Start logging again on pi2 after it is up.
2833 LoggerState pi2_logger = LoggerState::MakeLogger(
2834 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2835 pi2_logger.StartLogger(kLogfile2_2);
2836
2837 event_loop_factory.RunFor(chrono::milliseconds(10000));
2838 // And, now that we have a start time in the log, turn data back on.
2839 pi2->EnableStatistics();
2840 pi1->Connect(pi2->node());
2841 pi2->Connect(pi1->node());
2842
2843 pi2->AlwaysStart<Pong>("pong");
2844 std::unique_ptr<aos::EventLoop> ping_event_loop =
2845 pi1->MakeEventLoop("ping");
2846 Ping ping(ping_event_loop.get());
2847
2848 event_loop_factory.RunFor(chrono::milliseconds(3000));
2849
2850 pi2_logger.AppendAllFilenames(&filenames);
2851 }
2852
2853 pi1_logger.AppendAllFilenames(&filenames);
2854 pi3_logger.AppendAllFilenames(&filenames);
2855 }
2856
2857 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2858 // to confirm the right thing happened.
2859 const std::vector<LogFile> sorted_parts = SortParts(filenames);
2860 ConfirmReadable(filenames);
2861}
2862
Austin Schuh5dd22842021-11-17 16:09:39 -08002863// Tests that local data before remote data after reboot is properly replayed.
2864// We only trigger a reboot in the timestamp interpolation function when solving
2865// the timestamp problem when we actually have a point in the function. This
2866// originally only happened when a point passes the noncausal filter. At the
2867// start of time for the second boot, if we aren't careful, we will have
2868// messages which need to be published at times before the boot. This happens
2869// when a local message is in the log before a forwarded message, so there is no
2870// point in the interpolation function. This delays the reboot. So, we need to
2871// recreate that situation and make sure it doesn't come back.
2872TEST(MultinodeRebootLoggerTest, LocalMessageBeforeRemoteBeforeStartAfterReboot) {
2873 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
2874 aos::configuration::ReadConfig(ArtifactPath(
2875 "aos/events/logging/multinode_pingpong_split3_config.json"));
2876 message_bridge::TestingTimeConverter time_converter(
2877 configuration::NodesCount(&config.message()));
2878 SimulatedEventLoopFactory event_loop_factory(&config.message());
2879 event_loop_factory.SetTimeConverter(&time_converter);
2880 NodeEventLoopFactory *const pi1 =
2881 event_loop_factory.GetNodeEventLoopFactory("pi1");
2882 const size_t pi1_index = configuration::GetNodeIndex(
2883 event_loop_factory.configuration(), pi1->node());
2884 NodeEventLoopFactory *const pi2 =
2885 event_loop_factory.GetNodeEventLoopFactory("pi2");
2886 const size_t pi2_index = configuration::GetNodeIndex(
2887 event_loop_factory.configuration(), pi2->node());
2888 NodeEventLoopFactory *const pi3 =
2889 event_loop_factory.GetNodeEventLoopFactory("pi3");
2890 const size_t pi3_index = configuration::GetNodeIndex(
2891 event_loop_factory.configuration(), pi3->node());
2892
2893 const std::string kLogfile1_1 =
2894 aos::testing::TestTmpDir() + "/multi_logfile1/";
2895 const std::string kLogfile2_1 =
2896 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
2897 const std::string kLogfile2_2 =
2898 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
2899 const std::string kLogfile3_1 =
2900 aos::testing::TestTmpDir() + "/multi_logfile3/";
2901 util::UnlinkRecursive(kLogfile1_1);
2902 util::UnlinkRecursive(kLogfile2_1);
2903 util::UnlinkRecursive(kLogfile2_2);
2904 util::UnlinkRecursive(kLogfile3_1);
2905 const UUID pi1_boot0 = UUID::Random();
2906 const UUID pi2_boot0 = UUID::Random();
2907 const UUID pi2_boot1 = UUID::Random();
2908 const UUID pi3_boot0 = UUID::Random();
2909 {
2910 CHECK_EQ(pi1_index, 0u);
2911 CHECK_EQ(pi2_index, 1u);
2912 CHECK_EQ(pi3_index, 2u);
2913
2914 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
2915 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
2916 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
2917 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
2918
2919 time_converter.AddNextTimestamp(
2920 distributed_clock::epoch(),
2921 {BootTimestamp::epoch(), BootTimestamp::epoch(),
2922 BootTimestamp::epoch()});
2923 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
2924 time_converter.AddNextTimestamp(
2925 distributed_clock::epoch() + reboot_time,
2926 {BootTimestamp::epoch() + reboot_time,
2927 BootTimestamp{
2928 .boot = 1,
2929 .time = monotonic_clock::epoch() + reboot_time + chrono::seconds(100)},
2930 BootTimestamp::epoch() + reboot_time});
2931 }
2932
2933 std::vector<std::string> filenames;
2934 {
2935 LoggerState pi1_logger = LoggerState::MakeLogger(
2936 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2937 LoggerState pi3_logger = LoggerState::MakeLogger(
2938 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2939 {
2940 // And now start the logger.
2941 LoggerState pi2_logger = LoggerState::MakeLogger(
2942 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2943
2944 pi1_logger.StartLogger(kLogfile1_1);
2945 pi3_logger.StartLogger(kLogfile3_1);
2946 pi2_logger.StartLogger(kLogfile2_1);
2947
2948 event_loop_factory.RunFor(chrono::milliseconds(1005));
2949
2950 // Now that we've got a start time in the past, turn on data.
2951 std::unique_ptr<aos::EventLoop> ping_event_loop =
2952 pi1->MakeEventLoop("ping");
2953 Ping ping(ping_event_loop.get());
2954
2955 pi2->AlwaysStart<Pong>("pong");
2956
2957 event_loop_factory.RunFor(chrono::milliseconds(3000));
2958
2959 pi2_logger.AppendAllFilenames(&filenames);
2960
2961 // Disable any remote messages on pi2.
2962 pi1->Disconnect(pi2->node());
2963 pi2->Disconnect(pi1->node());
2964 }
2965 event_loop_factory.RunFor(chrono::milliseconds(995));
2966 // pi2 now reboots at 5 seconds.
2967 {
2968 event_loop_factory.RunFor(chrono::milliseconds(1000));
2969
2970 // Make local stuff happen before we start logging and connect the remote.
2971 pi2->AlwaysStart<Pong>("pong");
2972 std::unique_ptr<aos::EventLoop> ping_event_loop =
2973 pi1->MakeEventLoop("ping");
2974 Ping ping(ping_event_loop.get());
2975 event_loop_factory.RunFor(chrono::milliseconds(1005));
2976
2977 // Start logging again on pi2 after it is up.
2978 LoggerState pi2_logger = LoggerState::MakeLogger(
2979 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2980 pi2_logger.StartLogger(kLogfile2_2);
2981
2982 // And allow remote messages now that we have some local ones.
2983 pi1->Connect(pi2->node());
2984 pi2->Connect(pi1->node());
2985
2986 event_loop_factory.RunFor(chrono::milliseconds(1000));
2987
2988 event_loop_factory.RunFor(chrono::milliseconds(3000));
2989
2990 pi2_logger.AppendAllFilenames(&filenames);
2991 }
2992
2993 pi1_logger.AppendAllFilenames(&filenames);
2994 pi3_logger.AppendAllFilenames(&filenames);
2995 }
2996
2997 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2998 // to confirm the right thing happened.
2999 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3000 ConfirmReadable(filenames);
3001}
3002
3003
Austin Schuhe309d2a2019-11-29 13:25:21 -08003004} // namespace testing
3005} // namespace logger
3006} // namespace aos