blob: a0ae78a6dfc4bdbc9beaa1f1fbc5f9694c872768 [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
459class MultinodeLoggerTest : public ::testing::TestWithParam<
460 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800461 public:
462 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700463 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
464 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800465 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800466 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700467 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800468 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700469 event_loop_factory_.configuration(), pi1_->node())),
470 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800471 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700472 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800473 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800474 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
475 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800476 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800477 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800478 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700479 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700480 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800481 event_loop_factory_.SetTimeConverter(&time_converter_);
482
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700483 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700484 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700485 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800486 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700487 }
488
Austin Schuh268586b2021-03-31 22:24:39 -0700489 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800490 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800491 unlink(file.c_str());
492 }
493
Austin Schuh268586b2021-03-31 22:24:39 -0700494 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800495 unlink(file.c_str());
496 }
497
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700498 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
499 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700500
501 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
502 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700503 }
504
James Kuszmauldd0a5042021-10-28 23:38:04 -0700505 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800506
507 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700508 std::string logfile_base2,
509 size_t pi1_data_count = 2,
510 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800511 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700512 result.emplace_back(absl::StrCat(
513 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
514 result.emplace_back(absl::StrCat(
515 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700516 for (size_t i = 0; i < pi1_data_count; ++i) {
517 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700518 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700519 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800520 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700521 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800522 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700523 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700524 for (size_t i = 0; i < pi2_data_count; ++i) {
525 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700526 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700527 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700528 result.emplace_back(logfile_base2 +
529 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
530 Extension());
531 result.emplace_back(logfile_base2 +
532 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
533 Extension());
534 result.emplace_back(logfile_base1 +
535 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
536 Extension());
537 result.emplace_back(logfile_base1 +
538 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
539 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800540 if (shared()) {
541 result.emplace_back(logfile_base1 +
542 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700543 "aos.message_bridge.RemoteMessage.part0" +
544 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800545 result.emplace_back(logfile_base1 +
546 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700547 "aos.message_bridge.RemoteMessage.part1" +
548 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800549 result.emplace_back(logfile_base2 +
550 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700551 "aos.message_bridge.RemoteMessage.part0" +
552 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800553 result.emplace_back(logfile_base2 +
554 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700555 "aos.message_bridge.RemoteMessage.part1" +
556 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800557 } else {
558 result.emplace_back(logfile_base1 +
559 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
560 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700561 "aos.message_bridge.RemoteMessage.part0" +
562 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800563 result.emplace_back(logfile_base1 +
564 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
565 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700566 "aos.message_bridge.RemoteMessage.part1" +
567 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800568 result.emplace_back(logfile_base2 +
569 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
570 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700571 "aos.message_bridge.RemoteMessage.part0" +
572 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800573 result.emplace_back(logfile_base2 +
574 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
575 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700576 "aos.message_bridge.RemoteMessage.part1" +
577 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800578 result.emplace_back(logfile_base1 +
579 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
580 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700581 "aos.message_bridge.RemoteMessage.part0" +
582 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800583 result.emplace_back(logfile_base1 +
584 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
585 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700586 "aos.message_bridge.RemoteMessage.part1" +
587 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800588 }
589
590 return result;
591 }
592
593 std::vector<std::string> MakePi1RebootLogfiles() {
594 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700595 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
596 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
597 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800598 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700599 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800600 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700601 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800602 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700603 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700604 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700605 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
606 result.emplace_back(logfile_base1_ +
607 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
608 Extension());
609 result.emplace_back(logfile_base1_ +
610 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
611 Extension());
612 result.emplace_back(logfile_base1_ +
613 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
614 Extension());
615 result.emplace_back(logfile_base1_ +
616 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
617 Extension());
618 result.emplace_back(absl::StrCat(
619 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800620 if (shared()) {
621 result.emplace_back(logfile_base1_ +
622 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700623 "aos.message_bridge.RemoteMessage.part0" +
624 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800625 result.emplace_back(logfile_base1_ +
626 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700627 "aos.message_bridge.RemoteMessage.part1" +
628 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800629 result.emplace_back(logfile_base1_ +
630 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700631 "aos.message_bridge.RemoteMessage.part2" +
632 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700633 result.emplace_back(logfile_base1_ +
634 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700635 "aos.message_bridge.RemoteMessage.part3" +
636 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800637 } else {
638 result.emplace_back(logfile_base1_ +
639 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
640 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700641 "aos.message_bridge.RemoteMessage.part0" +
642 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800643 result.emplace_back(logfile_base1_ +
644 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
645 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700646 "aos.message_bridge.RemoteMessage.part1" +
647 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800648 result.emplace_back(logfile_base1_ +
649 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
650 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700651 "aos.message_bridge.RemoteMessage.part2" +
652 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700653 result.emplace_back(logfile_base1_ +
654 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
655 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700656 "aos.message_bridge.RemoteMessage.part3" +
657 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800658
659 result.emplace_back(logfile_base1_ +
660 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
661 "aos-examples-Ping/"
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_base1_ +
665 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
666 "aos-examples-Ping/"
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.part2" +
673 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700674 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.part3" +
678 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800679 }
680 return result;
681 }
682
683 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
684 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700685 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
686 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
687 result.emplace_back(logfile_base1_ +
688 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
689 Extension());
690 result.emplace_back(absl::StrCat(
691 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700692 return result;
693 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800694
Austin Schuh510dc622021-08-06 18:47:30 -0700695 std::vector<std::string> MakePi1DeadNodeLogfiles() {
696 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700697 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
698 result.emplace_back(absl::StrCat(
699 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800700 return result;
701 }
702
703 std::vector<std::vector<std::string>> StructureLogFiles() {
704 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700705 std::vector<std::string>{logfiles_[2], logfiles_[3]},
706 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800707 std::vector<std::string>{logfiles_[6], logfiles_[7]},
708 std::vector<std::string>{logfiles_[8], logfiles_[9]},
709 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700710 std::vector<std::string>{logfiles_[12], logfiles_[13]},
711 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800712
713 if (!shared()) {
714 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700715 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800716 }
717
718 return result;
719 }
720
James Kuszmauldd0a5042021-10-28 23:38:04 -0700721 std::string Extension() {
722 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
723 }
724
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700725 struct LoggerState {
726 std::unique_ptr<EventLoop> event_loop;
727 std::unique_ptr<Logger> logger;
Austin Schuh5b728b72021-06-16 14:57:15 -0700728 const Configuration *configuration;
729 const Node *node;
730 MultiNodeLogNamer *log_namer;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700731 };
732
Austin Schuh58646e22021-08-23 23:51:46 -0700733 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700734 SimulatedEventLoopFactory *factory = nullptr,
735 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700736 if (factory == nullptr) {
737 factory = &event_loop_factory_;
738 }
Austin Schuh5b728b72021-06-16 14:57:15 -0700739 if (configuration == nullptr) {
740 configuration = factory->configuration();
741 }
Austin Schuh58646e22021-08-23 23:51:46 -0700742 return {node->MakeEventLoop("logger"),
743 {},
744 configuration,
745 configuration::GetNode(configuration, node->node()),
746 nullptr};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700747 }
748
James Kuszmauldd0a5042021-10-28 23:38:04 -0700749 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700750 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800751 if (logger->event_loop->node()->name()->string_view() == "pi1") {
752 logfile_base = logfile_base1_;
753 } else {
754 logfile_base = logfile_base2_;
755 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700756 }
757
Austin Schuh5b728b72021-06-16 14:57:15 -0700758 logger->logger = std::make_unique<Logger>(logger->event_loop.get(),
759 logger->configuration);
Brian Silverman1f345222020-09-24 21:14:48 -0700760 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800761 logger->logger->set_name(absl::StrCat(
762 "name_prefix_", logger->event_loop->node()->name()->str()));
James Kuszmauldd0a5042021-10-28 23:38:04 -0700763 logger->event_loop->OnRun([logger, logfile_base]() {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800764 std::unique_ptr<MultiNodeLogNamer> namer =
Austin Schuh5b728b72021-06-16 14:57:15 -0700765 std::make_unique<MultiNodeLogNamer>(
766 logfile_base, logger->configuration, logger->event_loop.get(),
767 logger->node);
James Kuszmauldd0a5042021-10-28 23:38:04 -0700768 namer->set_extension(std::get<1>(GetParam()).extension);
769 namer->set_encoder_factory(std::get<1>(GetParam()).encoder_factory);
Austin Schuh5b728b72021-06-16 14:57:15 -0700770 logger->log_namer = namer.get();
Austin Schuh3bd4c402020-11-06 18:19:06 -0800771
772 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700773 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700774 }
Austin Schuh15649d62019-12-28 16:36:38 -0800775
Austin Schuh3bd4c402020-11-06 18:19:06 -0800776 void VerifyParts(const std::vector<LogFile> &sorted_parts,
777 const std::vector<std::string> &corrupted_parts = {}) {
778 EXPECT_EQ(sorted_parts.size(), 2u);
779
780 // Count up the number of UUIDs and make sure they are what we expect as a
781 // sanity check.
782 std::set<std::string> log_event_uuids;
783 std::set<std::string> parts_uuids;
784 std::set<std::string> both_uuids;
785
786 size_t missing_rt_count = 0;
787
788 std::vector<std::string> logger_nodes;
789 for (const LogFile &log_file : sorted_parts) {
790 EXPECT_FALSE(log_file.log_event_uuid.empty());
791 log_event_uuids.insert(log_file.log_event_uuid);
792 logger_nodes.emplace_back(log_file.logger_node);
793 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800794 EXPECT_TRUE(log_file.config);
795 EXPECT_EQ(log_file.name,
796 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800797
798 for (const LogParts &part : log_file.parts) {
799 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
800 << ": " << part;
801 missing_rt_count +=
802 part.realtime_start_time == aos::realtime_clock::min_time;
803
804 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
805 log_event_uuids.end());
806 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800807 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800808 parts_uuids.insert(part.parts_uuid);
809 both_uuids.insert(part.parts_uuid);
810 }
811 }
812
Austin Schuh61e973f2021-02-21 21:43:56 -0800813 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
814 // start time on remote nodes because we don't know it and would be
815 // guessing. And the log reader can actually do a better job. The number
816 // depends on if we have the remote timestamps split across 2 files, or just
817 // across 1, depending on if we are using a split or combined timestamp
818 // channel config.
819 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800820
821 EXPECT_EQ(log_event_uuids.size(), 2u);
822 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
823 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
824
825 // Test that each list of parts is in order. Don't worry about the ordering
826 // between part file lists though.
827 // (inner vectors all need to be in order, but outer one doesn't matter).
828 EXPECT_THAT(ToLogReaderVector(sorted_parts),
829 ::testing::UnorderedElementsAreArray(structured_logfiles_));
830
831 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
832
833 EXPECT_NE(sorted_parts[0].realtime_start_time,
834 aos::realtime_clock::min_time);
835 EXPECT_NE(sorted_parts[1].realtime_start_time,
836 aos::realtime_clock::min_time);
837
838 EXPECT_NE(sorted_parts[0].monotonic_start_time,
839 aos::monotonic_clock::min_time);
840 EXPECT_NE(sorted_parts[1].monotonic_start_time,
841 aos::monotonic_clock::min_time);
842
843 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
844 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
845 }
846
Austin Schuhc9049732020-12-21 22:27:15 -0800847 void ConfirmReadable(const std::vector<std::string> &files) {
848 LogReader reader(SortParts(files));
849
850 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
851 reader.Register(&log_reader_factory);
852
853 log_reader_factory.Run();
854
855 reader.Deregister();
856 }
857
Austin Schuh3bd4c402020-11-06 18:19:06 -0800858 void AddExtension(std::string_view extension) {
859 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
860 [extension](const std::string &in) {
861 return absl::StrCat(in, extension);
862 });
863
864 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
865 structured_logfiles_.begin(),
866 [extension](std::vector<std::string> in) {
867 std::transform(in.begin(), in.end(), in.begin(),
868 [extension](const std::string &in_str) {
869 return absl::StrCat(in_str, extension);
870 });
871 return in;
872 });
873 }
874
Austin Schuh15649d62019-12-28 16:36:38 -0800875 // Config and factory.
876 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800877 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800878 SimulatedEventLoopFactory event_loop_factory_;
879
Austin Schuh58646e22021-08-23 23:51:46 -0700880 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800881 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700882 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800883 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700884
885 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800886 std::string logfile_base1_;
887 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800888 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700889 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800890 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700891
892 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800893};
894
Austin Schuh391e3172020-09-01 22:48:18 -0700895// Counts the number of messages on a channel. Returns (channel name, channel
896// type, count) for every message matching matcher()
897std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800898 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700899 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800900 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800901 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800902
Austin Schuh6f3babe2020-01-26 20:34:50 -0800903 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700904 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800905 if (!msg) {
906 break;
907 }
908
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700909 if (matcher(msg.get())) {
910 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800911 }
912 }
913
Austin Schuh391e3172020-09-01 22:48:18 -0700914 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800915 int channel = 0;
916 for (size_t i = 0; i < counts.size(); ++i) {
917 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800918 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700919 result.push_back(std::make_tuple(channel->name()->str(),
920 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800921 }
922 ++channel;
923 }
924
925 return result;
926}
927
928// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700929std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800930 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700931 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700932 return CountChannelsMatching(
933 config, filename, [](const UnpackedMessageHeader *msg) {
934 if (msg->span.data() != nullptr) {
935 CHECK(!msg->monotonic_remote_time.has_value());
936 CHECK(!msg->realtime_remote_time.has_value());
937 CHECK(!msg->remote_queue_index.has_value());
938 return true;
939 }
940 return false;
941 });
Austin Schuh6f3babe2020-01-26 20:34:50 -0800942}
943
944// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700945std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800946 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800947 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700948 return CountChannelsMatching(
949 config, filename, [](const UnpackedMessageHeader *msg) {
950 if (msg->span.data() == nullptr) {
951 CHECK(msg->monotonic_remote_time.has_value());
952 CHECK(msg->realtime_remote_time.has_value());
953 CHECK(msg->remote_queue_index.has_value());
954 return true;
955 }
956 return false;
957 });
Austin Schuh6f3babe2020-01-26 20:34:50 -0800958}
959
Austin Schuhcde938c2020-02-02 17:30:07 -0800960// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800961TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800962 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800963 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700964 LoggerState pi1_logger = MakeLogger(pi1_);
965 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800966
967 event_loop_factory_.RunFor(chrono::milliseconds(95));
968
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700969 StartLogger(&pi1_logger);
970 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800971
Austin Schuh15649d62019-12-28 16:36:38 -0800972 event_loop_factory_.RunFor(chrono::milliseconds(20000));
973 }
974
Austin Schuh6f3babe2020-01-26 20:34:50 -0800975 {
Austin Schuh64fab802020-09-09 22:47:47 -0700976 std::set<std::string> logfile_uuids;
977 std::set<std::string> parts_uuids;
978 // Confirm that we have the expected number of UUIDs for both the logfile
979 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800980 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700981 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800982 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800983 if (!log_header.back().message().has_configuration()) {
984 logfile_uuids.insert(
985 log_header.back().message().log_event_uuid()->str());
986 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
987 }
Austin Schuh64fab802020-09-09 22:47:47 -0700988 }
Austin Schuh15649d62019-12-28 16:36:38 -0800989
Austin Schuh64fab802020-09-09 22:47:47 -0700990 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800991 if (shared()) {
992 EXPECT_EQ(parts_uuids.size(), 7u);
993 } else {
994 EXPECT_EQ(parts_uuids.size(), 8u);
995 }
Austin Schuh64fab802020-09-09 22:47:47 -0700996
997 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800998 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -0700999 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001000 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
1001 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001002 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
1003 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
1004 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
1005 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001006 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
1007 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001008 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1009 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
1010 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
1011 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -08001012 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001013 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
1014 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001015 }
Austin Schuh64fab802020-09-09 22:47:47 -07001016
1017 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001018 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001019 EXPECT_EQ(log_header[3].message().parts_index(), 1);
1020 EXPECT_EQ(log_header[4].message().parts_index(), 0);
1021 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -07001022 EXPECT_EQ(log_header[6].message().parts_index(), 0);
1023 EXPECT_EQ(log_header[7].message().parts_index(), 1);
1024 EXPECT_EQ(log_header[8].message().parts_index(), 0);
1025 EXPECT_EQ(log_header[9].message().parts_index(), 1);
1026 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1027 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001028 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1029 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -07001030 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1031 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001032 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001033 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1034 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001035 }
Austin Schuh64fab802020-09-09 22:47:47 -07001036 }
1037
Austin Schuh8c399962020-12-25 21:51:45 -08001038 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001039 {
Austin Schuh391e3172020-09-01 22:48:18 -07001040 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001041 std::shared_ptr<const aos::Configuration> config =
1042 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001043
Austin Schuh6f3babe2020-01-26 20:34:50 -08001044 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -07001045 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -08001046 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001047 UnorderedElementsAre(
Austin Schuhe46492f2021-07-31 19:49:41 -07001048 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
1049 1),
1050 std::make_tuple("/test", "aos.examples.Ping", 1)))
1051 << " : " << logfiles_[2];
1052 EXPECT_THAT(
1053 CountChannelsData(config, logfiles_[3]),
1054 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -07001055 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001056 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001057 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001058 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1059 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001060 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001061 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1062 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001063 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001064 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1065 UnorderedElementsAre())
1066 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001067 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001068 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001069 UnorderedElementsAre(
1070 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001071 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001072 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001073
1074 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001075 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001076 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001077 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001078 << " : " << logfiles_[4];
1079 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001080 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001081 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001082 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001083
Austin Schuh6f3babe2020-01-26 20:34:50 -08001084 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001085 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001086 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001087 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001088 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1089 UnorderedElementsAre())
1090 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001091
1092 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001093 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1094 UnorderedElementsAre(std::make_tuple(
1095 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1096 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001097 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001098 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001099 UnorderedElementsAre(
1100 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001101 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001102 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001103 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1104 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001105 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001106 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001107 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001108 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001109 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1110 UnorderedElementsAre())
1111 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001112 EXPECT_THAT(
1113 CountChannelsTimestamp(config, logfiles_[7]),
1114 UnorderedElementsAre(
1115 std::make_tuple("/test", "aos.examples.Ping", 2001),
1116 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001117 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001118
1119 // And then test that the remotely logged timestamp data files only have
1120 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001121 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1122 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001123 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001124 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1125 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001126 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001127 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1128 UnorderedElementsAre())
1129 << " : " << logfiles_[10];
1130 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1131 UnorderedElementsAre())
1132 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001133
Austin Schuh8c399962020-12-25 21:51:45 -08001134 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001135 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001136 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001137 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001138 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001139 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001140 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001141 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001142
Austin Schuh8c399962020-12-25 21:51:45 -08001143 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001144 UnorderedElementsAre(std::make_tuple(
1145 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001146 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001147 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001148 UnorderedElementsAre(std::make_tuple(
1149 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001150 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001151
1152 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001153 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1154 UnorderedElementsAre())
1155 << " : " << logfiles_[12];
1156 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1157 UnorderedElementsAre())
1158 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001159 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1160 UnorderedElementsAre())
1161 << " : " << logfiles_[14];
1162 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1163 UnorderedElementsAre())
1164 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001165 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001166 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001167 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001168 << " : " << logfiles_[16];
1169 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001170 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001171 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001172 }
1173
1174 if (shared()) {
1175 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001176 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001177 UnorderedElementsAre(
1178 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1179 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001180 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001181 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001182 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001183 UnorderedElementsAre(
1184 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1185 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001186 << " : " << logfiles_[13];
1187 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001188 UnorderedElementsAre(std::make_tuple(
1189 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001190 << " : " << logfiles_[14];
1191 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001192 UnorderedElementsAre(std::make_tuple(
1193 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1194 << " : " << logfiles_[15];
1195 } else {
1196 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1197 UnorderedElementsAre(std::make_tuple(
1198 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1199 << " : " << logfiles_[12];
1200 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1201 UnorderedElementsAre(std::make_tuple(
1202 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1203 << " : " << logfiles_[13];
1204 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1205 UnorderedElementsAre(std::make_tuple(
1206 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1207 << " : " << logfiles_[14];
1208 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1209 UnorderedElementsAre(std::make_tuple(
1210 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1211 << " : " << logfiles_[15];
1212 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1213 UnorderedElementsAre(
1214 std::make_tuple("/test", "aos.examples.Ping", 91)))
1215 << " : " << logfiles_[16];
1216 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001217 UnorderedElementsAre(
1218 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001219 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001220 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001221 }
1222
Austin Schuh8c399962020-12-25 21:51:45 -08001223 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001224
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001225 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001226 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001227
1228 // This sends out the fetched messages and advances time to the start of the
1229 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001230 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001231
Austin Schuhac0771c2020-01-07 18:36:30 -08001232 const Node *pi1 =
1233 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001234 const Node *pi2 =
1235 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001236
Austin Schuh2f8fd752020-09-01 22:38:28 -07001237 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1238 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1239 LOG(INFO) << "now pi1 "
1240 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1241 LOG(INFO) << "now pi2 "
1242 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1243
Austin Schuh07676622021-01-21 18:59:17 -08001244 EXPECT_THAT(reader.LoggedNodes(),
1245 ::testing::ElementsAre(
1246 configuration::GetNode(reader.logged_configuration(), pi1),
1247 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001248
1249 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001250
Austin Schuh6f3babe2020-01-26 20:34:50 -08001251 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001252 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001253 std::unique_ptr<EventLoop> pi2_event_loop =
1254 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001255
Austin Schuh6f3babe2020-01-26 20:34:50 -08001256 int pi1_ping_count = 10;
1257 int pi2_ping_count = 10;
1258 int pi1_pong_count = 10;
1259 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001260
1261 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001262 pi1_event_loop->MakeWatcher(
1263 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001264 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001265 << pi1_event_loop->context().monotonic_remote_time << " -> "
1266 << pi1_event_loop->context().monotonic_event_time;
1267 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1268 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1269 pi1_ping_count * chrono::milliseconds(10) +
1270 monotonic_clock::epoch());
1271 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1272 pi1_ping_count * chrono::milliseconds(10) +
1273 realtime_clock::epoch());
1274 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1275 pi1_event_loop->context().monotonic_event_time);
1276 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1277 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001278
Austin Schuh6f3babe2020-01-26 20:34:50 -08001279 ++pi1_ping_count;
1280 });
1281 pi2_event_loop->MakeWatcher(
1282 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001283 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001284 << pi2_event_loop->context().monotonic_remote_time << " -> "
1285 << pi2_event_loop->context().monotonic_event_time;
1286 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1287
1288 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1289 pi2_ping_count * chrono::milliseconds(10) +
1290 monotonic_clock::epoch());
1291 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1292 pi2_ping_count * chrono::milliseconds(10) +
1293 realtime_clock::epoch());
1294 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1295 chrono::microseconds(150),
1296 pi2_event_loop->context().monotonic_event_time);
1297 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1298 chrono::microseconds(150),
1299 pi2_event_loop->context().realtime_event_time);
1300 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001301 });
1302
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001303 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001304 // Confirm that the ping and pong counts both match, and the value also
1305 // matches.
1306 pi1_event_loop->MakeWatcher(
1307 "/test", [&pi1_event_loop, &pi1_ping_count,
1308 &pi1_pong_count](const examples::Pong &pong) {
1309 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1310 << pi1_event_loop->context().monotonic_remote_time << " -> "
1311 << pi1_event_loop->context().monotonic_event_time;
1312
1313 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1314 pi1_pong_count + kQueueIndexOffset);
1315 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1316 chrono::microseconds(200) +
1317 pi1_pong_count * chrono::milliseconds(10) +
1318 monotonic_clock::epoch());
1319 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1320 chrono::microseconds(200) +
1321 pi1_pong_count * chrono::milliseconds(10) +
1322 realtime_clock::epoch());
1323
1324 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1325 chrono::microseconds(150),
1326 pi1_event_loop->context().monotonic_event_time);
1327 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1328 chrono::microseconds(150),
1329 pi1_event_loop->context().realtime_event_time);
1330
1331 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1332 ++pi1_pong_count;
1333 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1334 });
1335 pi2_event_loop->MakeWatcher(
1336 "/test", [&pi2_event_loop, &pi2_ping_count,
1337 &pi2_pong_count](const examples::Pong &pong) {
1338 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1339 << pi2_event_loop->context().monotonic_remote_time << " -> "
1340 << pi2_event_loop->context().monotonic_event_time;
1341
1342 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001343 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001344
1345 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1346 chrono::microseconds(200) +
1347 pi2_pong_count * chrono::milliseconds(10) +
1348 monotonic_clock::epoch());
1349 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1350 chrono::microseconds(200) +
1351 pi2_pong_count * chrono::milliseconds(10) +
1352 realtime_clock::epoch());
1353
1354 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1355 pi2_event_loop->context().monotonic_event_time);
1356 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1357 pi2_event_loop->context().realtime_event_time);
1358
1359 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1360 ++pi2_pong_count;
1361 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1362 });
1363
1364 log_reader_factory.Run();
1365 EXPECT_EQ(pi1_ping_count, 2010);
1366 EXPECT_EQ(pi2_ping_count, 2010);
1367 EXPECT_EQ(pi1_pong_count, 2010);
1368 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001369
1370 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001371}
1372
James Kuszmaul46d82582020-05-09 19:50:09 -07001373typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1374
1375// Test that if we feed the replay with a mismatched node list that we die on
1376// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001377TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001378 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001379 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001380 LoggerState pi1_logger = MakeLogger(pi1_);
1381 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001382
1383 event_loop_factory_.RunFor(chrono::milliseconds(95));
1384
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001385 StartLogger(&pi1_logger);
1386 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001387
James Kuszmaul46d82582020-05-09 19:50:09 -07001388 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1389 }
1390
1391 // Test that, if we add an additional node to the replay config that the
1392 // logger complains about the mismatch in number of nodes.
1393 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1394 configuration::MergeWithConfig(&config_.message(), R"({
1395 "nodes": [
1396 {
1397 "name": "extra-node"
1398 }
1399 ]
1400 }
1401 )");
1402
Austin Schuh287d43d2020-12-04 20:19:33 -08001403 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1404 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001405 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001406}
1407
Austin Schuhcde938c2020-02-02 17:30:07 -08001408// Tests that we can read log files where they don't start at the same monotonic
1409// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001410TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001411 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001412 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001413 LoggerState pi1_logger = MakeLogger(pi1_);
1414 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001415
1416 event_loop_factory_.RunFor(chrono::milliseconds(95));
1417
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001418 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001419
1420 event_loop_factory_.RunFor(chrono::milliseconds(200));
1421
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001422 StartLogger(&pi2_logger);
1423
Austin Schuhcde938c2020-02-02 17:30:07 -08001424 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1425 }
1426
Austin Schuhe46492f2021-07-31 19:49:41 -07001427 // Since we delay starting pi2, it already knows about all the timestamps so
1428 // we don't end up with extra parts.
1429 LogReader reader(
1430 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001431
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001432 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001433 log_reader_factory.set_send_delay(chrono::microseconds(0));
1434
1435 // This sends out the fetched messages and advances time to the start of the
1436 // log file.
1437 reader.Register(&log_reader_factory);
1438
1439 const Node *pi1 =
1440 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1441 const Node *pi2 =
1442 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1443
Austin Schuh07676622021-01-21 18:59:17 -08001444 EXPECT_THAT(reader.LoggedNodes(),
1445 ::testing::ElementsAre(
1446 configuration::GetNode(reader.logged_configuration(), pi1),
1447 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001448
1449 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1450
1451 std::unique_ptr<EventLoop> pi1_event_loop =
1452 log_reader_factory.MakeEventLoop("test", pi1);
1453 std::unique_ptr<EventLoop> pi2_event_loop =
1454 log_reader_factory.MakeEventLoop("test", pi2);
1455
1456 int pi1_ping_count = 30;
1457 int pi2_ping_count = 30;
1458 int pi1_pong_count = 30;
1459 int pi2_pong_count = 30;
1460
1461 // Confirm that the ping value matches.
1462 pi1_event_loop->MakeWatcher(
1463 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1464 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1465 << pi1_event_loop->context().monotonic_remote_time << " -> "
1466 << pi1_event_loop->context().monotonic_event_time;
1467 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1468
1469 ++pi1_ping_count;
1470 });
1471 pi2_event_loop->MakeWatcher(
1472 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1473 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1474 << pi2_event_loop->context().monotonic_remote_time << " -> "
1475 << pi2_event_loop->context().monotonic_event_time;
1476 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1477
1478 ++pi2_ping_count;
1479 });
1480
1481 // Confirm that the ping and pong counts both match, and the value also
1482 // matches.
1483 pi1_event_loop->MakeWatcher(
1484 "/test", [&pi1_event_loop, &pi1_ping_count,
1485 &pi1_pong_count](const examples::Pong &pong) {
1486 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1487 << pi1_event_loop->context().monotonic_remote_time << " -> "
1488 << pi1_event_loop->context().monotonic_event_time;
1489
1490 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1491 ++pi1_pong_count;
1492 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1493 });
1494 pi2_event_loop->MakeWatcher(
1495 "/test", [&pi2_event_loop, &pi2_ping_count,
1496 &pi2_pong_count](const examples::Pong &pong) {
1497 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1498 << pi2_event_loop->context().monotonic_remote_time << " -> "
1499 << pi2_event_loop->context().monotonic_event_time;
1500
1501 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1502 ++pi2_pong_count;
1503 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1504 });
1505
1506 log_reader_factory.Run();
1507 EXPECT_EQ(pi1_ping_count, 2030);
1508 EXPECT_EQ(pi2_ping_count, 2030);
1509 EXPECT_EQ(pi1_pong_count, 2030);
1510 EXPECT_EQ(pi2_pong_count, 2030);
1511
1512 reader.Deregister();
1513}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001514
Austin Schuh8bd96322020-02-13 21:18:22 -08001515// Tests that we can read log files where the monotonic clocks drift and don't
1516// match correctly. While we are here, also test that different ending times
1517// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001518TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001519 // TODO(austin): Negate...
1520 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1521
Austin Schuh66168842021-08-17 19:42:21 -07001522 time_converter_.AddMonotonic(
1523 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001524 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1525 // skew to be 200 uS/s
1526 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1527 {chrono::milliseconds(95),
1528 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1529 // Run another 200 ms to have one logger start first.
1530 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1531 {chrono::milliseconds(200), chrono::milliseconds(200)});
1532 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1533 // go far enough to cause problems if this isn't accounted for.
1534 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1535 {chrono::milliseconds(20000),
1536 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1537 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1538 {chrono::milliseconds(40000),
1539 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1540 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1541 {chrono::milliseconds(400), chrono::milliseconds(400)});
1542
Austin Schuhcde938c2020-02-02 17:30:07 -08001543 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001544 LoggerState pi2_logger = MakeLogger(pi2_);
1545
Austin Schuh58646e22021-08-23 23:51:46 -07001546 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1547 << pi2_->realtime_now() << " distributed "
1548 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001549
Austin Schuh58646e22021-08-23 23:51:46 -07001550 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1551 << pi2_->realtime_now() << " distributed "
1552 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001553
Austin Schuh87dd3832021-01-01 23:07:31 -08001554 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001555
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001556 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001557
Austin Schuh87dd3832021-01-01 23:07:31 -08001558 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001559
Austin Schuh8bd96322020-02-13 21:18:22 -08001560 {
1561 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001562 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001563
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001564 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001565 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001566
Austin Schuh87dd3832021-01-01 23:07:31 -08001567 // Make sure we slewed time far enough so that the difference is greater
1568 // than the network delay. This confirms that if we sort incorrectly, it
1569 // would show in the results.
1570 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001571 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001572 -event_loop_factory_.send_delay() -
1573 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001574
Austin Schuh87dd3832021-01-01 23:07:31 -08001575 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001576
Austin Schuh87dd3832021-01-01 23:07:31 -08001577 // And now check that we went far enough the other way to make sure we
1578 // cover both problems.
1579 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001580 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001581 event_loop_factory_.send_delay() +
1582 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001583 }
1584
1585 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001586 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001587 }
1588
Austin Schuh72211ae2021-08-05 14:02:30 -07001589 LogReader reader(
1590 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001591
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001592 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001593 log_reader_factory.set_send_delay(chrono::microseconds(0));
1594
Austin Schuhcde938c2020-02-02 17:30:07 -08001595 const Node *pi1 =
1596 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1597 const Node *pi2 =
1598 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1599
Austin Schuh2f8fd752020-09-01 22:38:28 -07001600 // This sends out the fetched messages and advances time to the start of the
1601 // log file.
1602 reader.Register(&log_reader_factory);
1603
1604 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1605 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1606 LOG(INFO) << "now pi1 "
1607 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1608 LOG(INFO) << "now pi2 "
1609 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1610
Austin Schuhcde938c2020-02-02 17:30:07 -08001611 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001612 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1613 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001614 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1615 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001616 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1617 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001618 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1619
Austin Schuh07676622021-01-21 18:59:17 -08001620 EXPECT_THAT(reader.LoggedNodes(),
1621 ::testing::ElementsAre(
1622 configuration::GetNode(reader.logged_configuration(), pi1),
1623 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001624
1625 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1626
1627 std::unique_ptr<EventLoop> pi1_event_loop =
1628 log_reader_factory.MakeEventLoop("test", pi1);
1629 std::unique_ptr<EventLoop> pi2_event_loop =
1630 log_reader_factory.MakeEventLoop("test", pi2);
1631
1632 int pi1_ping_count = 30;
1633 int pi2_ping_count = 30;
1634 int pi1_pong_count = 30;
1635 int pi2_pong_count = 30;
1636
1637 // Confirm that the ping value matches.
1638 pi1_event_loop->MakeWatcher(
1639 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1640 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1641 << pi1_event_loop->context().monotonic_remote_time << " -> "
1642 << pi1_event_loop->context().monotonic_event_time;
1643 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1644
1645 ++pi1_ping_count;
1646 });
1647 pi2_event_loop->MakeWatcher(
1648 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1649 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1650 << pi2_event_loop->context().monotonic_remote_time << " -> "
1651 << pi2_event_loop->context().monotonic_event_time;
1652 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1653
1654 ++pi2_ping_count;
1655 });
1656
1657 // Confirm that the ping and pong counts both match, and the value also
1658 // matches.
1659 pi1_event_loop->MakeWatcher(
1660 "/test", [&pi1_event_loop, &pi1_ping_count,
1661 &pi1_pong_count](const examples::Pong &pong) {
1662 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1663 << pi1_event_loop->context().monotonic_remote_time << " -> "
1664 << pi1_event_loop->context().monotonic_event_time;
1665
1666 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1667 ++pi1_pong_count;
1668 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1669 });
1670 pi2_event_loop->MakeWatcher(
1671 "/test", [&pi2_event_loop, &pi2_ping_count,
1672 &pi2_pong_count](const examples::Pong &pong) {
1673 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1674 << pi2_event_loop->context().monotonic_remote_time << " -> "
1675 << pi2_event_loop->context().monotonic_event_time;
1676
1677 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1678 ++pi2_pong_count;
1679 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1680 });
1681
1682 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001683 EXPECT_EQ(pi1_ping_count, 6030);
1684 EXPECT_EQ(pi2_ping_count, 6030);
1685 EXPECT_EQ(pi1_pong_count, 6030);
1686 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001687
1688 reader.Deregister();
1689}
1690
Austin Schuh5212cad2020-09-09 23:12:09 -07001691// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001692TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001693 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001694 // Make a bunch of parts.
1695 {
1696 LoggerState pi1_logger = MakeLogger(pi1_);
1697 LoggerState pi2_logger = MakeLogger(pi2_);
1698
1699 event_loop_factory_.RunFor(chrono::milliseconds(95));
1700
1701 StartLogger(&pi1_logger);
1702 StartLogger(&pi2_logger);
1703
1704 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1705 }
1706
Austin Schuh11d43732020-09-21 17:28:30 -07001707 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001708 VerifyParts(sorted_parts);
1709}
Austin Schuh11d43732020-09-21 17:28:30 -07001710
Austin Schuh3bd4c402020-11-06 18:19:06 -08001711// Tests that we can sort a bunch of parts with an empty part. We should ignore
1712// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001713TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001714 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001715 // Make a bunch of parts.
1716 {
1717 LoggerState pi1_logger = MakeLogger(pi1_);
1718 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001719
Austin Schuh3bd4c402020-11-06 18:19:06 -08001720 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001721
Austin Schuh3bd4c402020-11-06 18:19:06 -08001722 StartLogger(&pi1_logger);
1723 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001724
Austin Schuh3bd4c402020-11-06 18:19:06 -08001725 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001726 }
1727
Austin Schuh3bd4c402020-11-06 18:19:06 -08001728 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001729 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001730
Austin Schuh3bd4c402020-11-06 18:19:06 -08001731 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1732 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001733
Austin Schuh3bd4c402020-11-06 18:19:06 -08001734 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1735 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001736}
1737
James Kuszmauldd0a5042021-10-28 23:38:04 -07001738// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08001739// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001740TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001741 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001742 // Make a bunch of parts.
1743 {
1744 LoggerState pi1_logger = MakeLogger(pi1_);
1745 LoggerState pi2_logger = MakeLogger(pi2_);
1746
1747 event_loop_factory_.RunFor(chrono::milliseconds(95));
1748
James Kuszmauldd0a5042021-10-28 23:38:04 -07001749 StartLogger(&pi1_logger);
1750 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001751
1752 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1753 }
1754
Austin Schuh3bd4c402020-11-06 18:19:06 -08001755 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001756 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1757 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08001758 ::std::string compressed_contents =
James Kuszmauldd0a5042021-10-28 23:38:04 -07001759 aos::util::ReadFileToStringOrDie(logfiles_[3]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001760
1761 aos::util::WriteStringToFileOrDie(
James Kuszmauldd0a5042021-10-28 23:38:04 -07001762 logfiles_[3],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001763 compressed_contents.substr(0, compressed_contents.size() - 100));
1764
1765 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1766 VerifyParts(sorted_parts);
1767}
Austin Schuh3bd4c402020-11-06 18:19:06 -08001768
Austin Schuh01b4c352020-09-21 23:09:39 -07001769// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001770TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001771 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001772 {
1773 LoggerState pi1_logger = MakeLogger(pi1_);
1774 LoggerState pi2_logger = MakeLogger(pi2_);
1775
1776 event_loop_factory_.RunFor(chrono::milliseconds(95));
1777
1778 StartLogger(&pi1_logger);
1779 StartLogger(&pi2_logger);
1780
1781 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1782 }
1783
Austin Schuh287d43d2020-12-04 20:19:33 -08001784 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001785
1786 // Remap just on pi1.
1787 reader.RemapLoggedChannel<aos::timing::Report>(
1788 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1789
1790 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1791 log_reader_factory.set_send_delay(chrono::microseconds(0));
1792
Austin Schuh1c227352021-09-17 12:53:54 -07001793 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1794 ASSERT_EQ(remapped_channels.size(), 1u);
1795 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1796 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1797
Austin Schuh01b4c352020-09-21 23:09:39 -07001798 reader.Register(&log_reader_factory);
1799
1800 const Node *pi1 =
1801 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1802 const Node *pi2 =
1803 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1804
1805 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1806 // else should have moved.
1807 std::unique_ptr<EventLoop> pi1_event_loop =
1808 log_reader_factory.MakeEventLoop("test", pi1);
1809 pi1_event_loop->SkipTimingReport();
1810 std::unique_ptr<EventLoop> full_pi1_event_loop =
1811 log_reader_factory.MakeEventLoop("test", pi1);
1812 full_pi1_event_loop->SkipTimingReport();
1813 std::unique_ptr<EventLoop> pi2_event_loop =
1814 log_reader_factory.MakeEventLoop("test", pi2);
1815 pi2_event_loop->SkipTimingReport();
1816
1817 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1818 "/aos");
1819 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1820 full_pi1_event_loop.get(), "/pi1/aos");
1821 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1822 pi1_event_loop.get(), "/original/aos");
1823 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1824 full_pi1_event_loop.get(), "/original/pi1/aos");
1825 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1826 "/aos");
1827
1828 log_reader_factory.Run();
1829
1830 EXPECT_EQ(pi1_timing_report.count(), 0u);
1831 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1832 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1833 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1834 EXPECT_NE(pi2_timing_report.count(), 0u);
1835
1836 reader.Deregister();
1837}
1838
Austin Schuh006a9f52021-04-07 16:24:18 -07001839// Tests that we can remap a forwarded channel as well.
1840TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1841 time_converter_.StartEqual();
1842 {
1843 LoggerState pi1_logger = MakeLogger(pi1_);
1844 LoggerState pi2_logger = MakeLogger(pi2_);
1845
1846 event_loop_factory_.RunFor(chrono::milliseconds(95));
1847
1848 StartLogger(&pi1_logger);
1849 StartLogger(&pi2_logger);
1850
1851 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1852 }
1853
1854 LogReader reader(SortParts(logfiles_));
1855
1856 reader.RemapLoggedChannel<examples::Ping>("/test");
1857
1858 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1859 log_reader_factory.set_send_delay(chrono::microseconds(0));
1860
1861 reader.Register(&log_reader_factory);
1862
1863 const Node *pi1 =
1864 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1865 const Node *pi2 =
1866 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1867
1868 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1869 // else should have moved.
1870 std::unique_ptr<EventLoop> pi1_event_loop =
1871 log_reader_factory.MakeEventLoop("test", pi1);
1872 pi1_event_loop->SkipTimingReport();
1873 std::unique_ptr<EventLoop> full_pi1_event_loop =
1874 log_reader_factory.MakeEventLoop("test", pi1);
1875 full_pi1_event_loop->SkipTimingReport();
1876 std::unique_ptr<EventLoop> pi2_event_loop =
1877 log_reader_factory.MakeEventLoop("test", pi2);
1878 pi2_event_loop->SkipTimingReport();
1879
1880 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1881 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1882 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1883 "/original/test");
1884 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1885 "/original/test");
1886
1887 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1888 pi1_original_ping_timestamp;
1889 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1890 pi1_ping_timestamp;
1891 if (!shared()) {
1892 pi1_original_ping_timestamp =
1893 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1894 pi1_event_loop.get(),
1895 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1896 pi1_ping_timestamp =
1897 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1898 pi1_event_loop.get(),
1899 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1900 }
1901
1902 log_reader_factory.Run();
1903
1904 EXPECT_EQ(pi1_ping.count(), 0u);
1905 EXPECT_EQ(pi2_ping.count(), 0u);
1906 EXPECT_NE(pi1_original_ping.count(), 0u);
1907 EXPECT_NE(pi2_original_ping.count(), 0u);
1908 if (!shared()) {
1909 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1910 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1911 }
1912
1913 reader.Deregister();
1914}
1915
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001916// Tests that we properly recreate forwarded timestamps when replaying a log.
1917// This should be enough that we can then re-run the logger and get a valid log
1918// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001919TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001920 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001921 {
1922 LoggerState pi1_logger = MakeLogger(pi1_);
1923 LoggerState pi2_logger = MakeLogger(pi2_);
1924
1925 event_loop_factory_.RunFor(chrono::milliseconds(95));
1926
1927 StartLogger(&pi1_logger);
1928 StartLogger(&pi2_logger);
1929
1930 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1931 }
1932
Austin Schuh287d43d2020-12-04 20:19:33 -08001933 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001934
1935 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1936 log_reader_factory.set_send_delay(chrono::microseconds(0));
1937
1938 // This sends out the fetched messages and advances time to the start of the
1939 // log file.
1940 reader.Register(&log_reader_factory);
1941
1942 const Node *pi1 =
1943 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1944 const Node *pi2 =
1945 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1946
1947 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1948 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1949 LOG(INFO) << "now pi1 "
1950 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1951 LOG(INFO) << "now pi2 "
1952 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1953
Austin Schuh07676622021-01-21 18:59:17 -08001954 EXPECT_THAT(reader.LoggedNodes(),
1955 ::testing::ElementsAre(
1956 configuration::GetNode(reader.logged_configuration(), pi1),
1957 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001958
1959 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1960
1961 std::unique_ptr<EventLoop> pi1_event_loop =
1962 log_reader_factory.MakeEventLoop("test", pi1);
1963 std::unique_ptr<EventLoop> pi2_event_loop =
1964 log_reader_factory.MakeEventLoop("test", pi2);
1965
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001966 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1967 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1968 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1969 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1970
1971 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1972 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1973 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1974 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1975
1976 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1977 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1978 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1979 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1980
1981 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1982 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1983 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1984 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1985
1986 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1987 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1988 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1989 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1990
1991 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1992 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1993 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1994 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1995
Austin Schuh969cd602021-01-03 00:09:45 -08001996 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001997 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001998
Austin Schuh61e973f2021-02-21 21:43:56 -08001999 for (std::pair<int, std::string> channel :
2000 shared()
2001 ? std::vector<
2002 std::pair<int, std::string>>{{-1,
2003 "/aos/remote_timestamps/pi2"}}
2004 : std::vector<std::pair<int, std::string>>{
2005 {pi1_timestamp_channel,
2006 "/aos/remote_timestamps/pi2/pi1/aos/"
2007 "aos-message_bridge-Timestamp"},
2008 {ping_timestamp_channel,
2009 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2010 pi1_event_loop->MakeWatcher(
2011 channel.second,
2012 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2013 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2014 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2015 &ping_on_pi2_fetcher, network_delay, send_delay,
2016 channel_index = channel.first](const RemoteMessage &header) {
2017 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2018 chrono::nanoseconds(header.monotonic_sent_time()));
2019 const aos::realtime_clock::time_point header_realtime_sent_time(
2020 chrono::nanoseconds(header.realtime_sent_time()));
2021 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2022 chrono::nanoseconds(header.monotonic_remote_time()));
2023 const aos::realtime_clock::time_point header_realtime_remote_time(
2024 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002025
Austin Schuh61e973f2021-02-21 21:43:56 -08002026 if (channel_index != -1) {
2027 ASSERT_EQ(channel_index, header.channel_index());
2028 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002029
Austin Schuh61e973f2021-02-21 21:43:56 -08002030 const Context *pi1_context = nullptr;
2031 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002032
Austin Schuh61e973f2021-02-21 21:43:56 -08002033 if (header.channel_index() == pi1_timestamp_channel) {
2034 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2035 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2036 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2037 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2038 } else if (header.channel_index() == ping_timestamp_channel) {
2039 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2040 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2041 pi1_context = &ping_on_pi1_fetcher.context();
2042 pi2_context = &ping_on_pi2_fetcher.context();
2043 } else {
2044 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2045 << configuration::CleanedChannelToString(
2046 pi1_event_loop->configuration()->channels()->Get(
2047 header.channel_index()));
2048 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002049
Austin Schuh61e973f2021-02-21 21:43:56 -08002050 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002051 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2052 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002053
Austin Schuh61e973f2021-02-21 21:43:56 -08002054 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2055 EXPECT_EQ(pi2_context->remote_queue_index,
2056 header.remote_queue_index());
2057 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002058
Austin Schuh61e973f2021-02-21 21:43:56 -08002059 EXPECT_EQ(pi2_context->monotonic_event_time,
2060 header_monotonic_sent_time);
2061 EXPECT_EQ(pi2_context->realtime_event_time,
2062 header_realtime_sent_time);
2063 EXPECT_EQ(pi2_context->realtime_remote_time,
2064 header_realtime_remote_time);
2065 EXPECT_EQ(pi2_context->monotonic_remote_time,
2066 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002067
Austin Schuh61e973f2021-02-21 21:43:56 -08002068 EXPECT_EQ(pi1_context->realtime_event_time,
2069 header_realtime_remote_time);
2070 EXPECT_EQ(pi1_context->monotonic_event_time,
2071 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002072
Austin Schuh61e973f2021-02-21 21:43:56 -08002073 // Time estimation isn't perfect, but we know the clocks were
2074 // identical when logged, so we know when this should have come back.
2075 // Confirm we got it when we expected.
2076 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2077 pi1_context->monotonic_event_time + 2 * network_delay +
2078 send_delay);
2079 });
2080 }
2081 for (std::pair<int, std::string> channel :
2082 shared()
2083 ? std::vector<
2084 std::pair<int, std::string>>{{-1,
2085 "/aos/remote_timestamps/pi1"}}
2086 : std::vector<std::pair<int, std::string>>{
2087 {pi2_timestamp_channel,
2088 "/aos/remote_timestamps/pi1/pi2/aos/"
2089 "aos-message_bridge-Timestamp"}}) {
2090 pi2_event_loop->MakeWatcher(
2091 channel.second,
2092 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2093 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2094 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2095 &pong_on_pi1_fetcher, network_delay, send_delay,
2096 channel_index = channel.first](const RemoteMessage &header) {
2097 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2098 chrono::nanoseconds(header.monotonic_sent_time()));
2099 const aos::realtime_clock::time_point header_realtime_sent_time(
2100 chrono::nanoseconds(header.realtime_sent_time()));
2101 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2102 chrono::nanoseconds(header.monotonic_remote_time()));
2103 const aos::realtime_clock::time_point header_realtime_remote_time(
2104 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002105
Austin Schuh61e973f2021-02-21 21:43:56 -08002106 if (channel_index != -1) {
2107 ASSERT_EQ(channel_index, header.channel_index());
2108 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002109
Austin Schuh61e973f2021-02-21 21:43:56 -08002110 const Context *pi2_context = nullptr;
2111 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002112
Austin Schuh61e973f2021-02-21 21:43:56 -08002113 if (header.channel_index() == pi2_timestamp_channel) {
2114 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2115 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2116 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2117 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2118 } else if (header.channel_index() == pong_timestamp_channel) {
2119 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2120 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2121 pi2_context = &pong_on_pi2_fetcher.context();
2122 pi1_context = &pong_on_pi1_fetcher.context();
2123 } else {
2124 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2125 << configuration::CleanedChannelToString(
2126 pi2_event_loop->configuration()->channels()->Get(
2127 header.channel_index()));
2128 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002129
Austin Schuh61e973f2021-02-21 21:43:56 -08002130 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002131 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2132 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002133
Austin Schuh61e973f2021-02-21 21:43:56 -08002134 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2135 EXPECT_EQ(pi1_context->remote_queue_index,
2136 header.remote_queue_index());
2137 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002138
Austin Schuh61e973f2021-02-21 21:43:56 -08002139 EXPECT_EQ(pi1_context->monotonic_event_time,
2140 header_monotonic_sent_time);
2141 EXPECT_EQ(pi1_context->realtime_event_time,
2142 header_realtime_sent_time);
2143 EXPECT_EQ(pi1_context->realtime_remote_time,
2144 header_realtime_remote_time);
2145 EXPECT_EQ(pi1_context->monotonic_remote_time,
2146 header_monotonic_remote_time);
2147
2148 EXPECT_EQ(pi2_context->realtime_event_time,
2149 header_realtime_remote_time);
2150 EXPECT_EQ(pi2_context->monotonic_event_time,
2151 header_monotonic_remote_time);
2152
2153 // Time estimation isn't perfect, but we know the clocks were
2154 // identical when logged, so we know when this should have come back.
2155 // Confirm we got it when we expected.
2156 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2157 pi2_context->monotonic_event_time + 2 * network_delay +
2158 send_delay);
2159 });
2160 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002161
2162 // And confirm we can re-create a log again, while checking the contents.
2163 {
2164 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002165 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002166 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002167 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002168
Austin Schuh25b46712021-01-03 00:04:38 -08002169 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2170 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002171
2172 log_reader_factory.Run();
2173 }
2174
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002175 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002176
2177 // And verify that we can run the LogReader over the relogged files without
2178 // hitting any fatal errors.
2179 {
2180 LogReader relogged_reader(SortParts(
2181 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2182 relogged_reader.Register();
2183
2184 relogged_reader.event_loop_factory()->Run();
2185 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002186}
2187
Austin Schuh315b96b2020-12-11 21:21:12 -08002188// Tests that we properly populate and extract the logger_start time by setting
2189// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002190TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002191 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002192 {BootTimestamp::epoch(),
2193 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002194 {
2195 LoggerState pi1_logger = MakeLogger(pi1_);
2196 LoggerState pi2_logger = MakeLogger(pi2_);
2197
Austin Schuh315b96b2020-12-11 21:21:12 -08002198 StartLogger(&pi1_logger);
2199 StartLogger(&pi2_logger);
2200
2201 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2202 }
2203
2204 for (const LogFile &log_file : SortParts(logfiles_)) {
2205 for (const LogParts &log_part : log_file.parts) {
2206 if (log_part.node == log_file.logger_node) {
2207 EXPECT_EQ(log_part.logger_monotonic_start_time,
2208 aos::monotonic_clock::min_time);
2209 EXPECT_EQ(log_part.logger_realtime_start_time,
2210 aos::realtime_clock::min_time);
2211 } else {
2212 const chrono::seconds offset = log_file.logger_node == "pi1"
2213 ? -chrono::seconds(1000)
2214 : chrono::seconds(1000);
2215 EXPECT_EQ(log_part.logger_monotonic_start_time,
2216 log_part.monotonic_start_time + offset);
2217 EXPECT_EQ(log_part.logger_realtime_start_time,
2218 log_file.realtime_start_time +
2219 (log_part.logger_monotonic_start_time -
2220 log_file.monotonic_start_time));
2221 }
2222 }
2223 }
2224}
2225
Austin Schuh6bb8a822021-03-31 23:04:39 -07002226// Test that renaming the base, renames the folder.
2227TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002228 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2229 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002230 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002231 {BootTimestamp::epoch(),
2232 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002233 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2234 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2235 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2236 LoggerState pi1_logger = MakeLogger(pi1_);
2237 LoggerState pi2_logger = MakeLogger(pi2_);
2238
2239 StartLogger(&pi1_logger);
2240 StartLogger(&pi2_logger);
2241
2242 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2243 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2244 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2245 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2246 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2247 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2248 for (auto &file : logfiles_) {
2249 struct stat s;
2250 EXPECT_EQ(0, stat(file.c_str(), &s));
2251 }
2252}
2253
2254// Test that renaming the file base dies.
2255TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2256 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002257 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002258 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002259 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2260 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2261 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2262 LoggerState pi1_logger = MakeLogger(pi1_);
2263 StartLogger(&pi1_logger);
2264 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2265 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2266 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2267 "Rename of file base from");
2268}
2269
Austin Schuh8bd96322020-02-13 21:18:22 -08002270// TODO(austin): We can write a test which recreates a logfile and confirms that
2271// we get it back. That is the ultimate test.
2272
Austin Schuh315b96b2020-12-11 21:21:12 -08002273// Tests that we properly recreate forwarded timestamps when replaying a log.
2274// This should be enough that we can then re-run the logger and get a valid log
2275// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002276TEST_P(MultinodeLoggerTest, RemoteReboot) {
2277 const UUID pi1_boot0 = UUID::Random();
2278 const UUID pi2_boot0 = UUID::Random();
2279 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002280 {
Austin Schuh58646e22021-08-23 23:51:46 -07002281 CHECK_EQ(pi1_index_, 0u);
2282 CHECK_EQ(pi2_index_, 1u);
2283
2284 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2285 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2286 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2287
2288 time_converter_.AddNextTimestamp(
2289 distributed_clock::epoch(),
2290 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2291 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2292 time_converter_.AddNextTimestamp(
2293 distributed_clock::epoch() + reboot_time,
2294 {BootTimestamp::epoch() + reboot_time,
2295 BootTimestamp{
2296 .boot = 1,
2297 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2298 }
2299
2300 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002301 LoggerState pi1_logger = MakeLogger(pi1_);
2302
2303 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002304 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2305 pi1_boot0);
2306 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2307 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002308
2309 StartLogger(&pi1_logger);
2310
2311 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2312
Austin Schuh58646e22021-08-23 23:51:46 -07002313 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002314
2315 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002316 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2317 pi1_boot0);
2318 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2319 pi2_boot1);
Austin Schuh315b96b2020-12-11 21:21:12 -08002320 }
2321
Austin Schuh72211ae2021-08-05 14:02:30 -07002322 // Confirm that our new oldest timestamps properly update as we reboot and
2323 // rotate.
2324 for (const std::string &file : pi1_reboot_logfiles_) {
2325 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2326 ReadHeader(file);
2327 CHECK(log_header);
2328 if (log_header->message().has_configuration()) {
2329 continue;
2330 }
2331
Austin Schuh58646e22021-08-23 23:51:46 -07002332 const monotonic_clock::time_point monotonic_start_time =
2333 monotonic_clock::time_point(
2334 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2335 const UUID source_node_boot_uuid = UUID::FromString(
2336 log_header->message().source_node_boot_uuid()->string_view());
2337
Austin Schuh72211ae2021-08-05 14:02:30 -07002338 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh58646e22021-08-23 23:51:46 -07002339 switch (log_header->message().parts_index()) {
2340 case 0:
2341 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2342 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2343 break;
2344 case 1:
2345 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2346 ASSERT_EQ(monotonic_start_time,
2347 monotonic_clock::epoch() + chrono::seconds(1));
2348 break;
2349 case 2:
2350 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2351 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2352 break;
2353 case 3:
2354 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2355 ASSERT_EQ(monotonic_start_time,
2356 monotonic_clock::epoch() + chrono::nanoseconds(2322999462));
2357 break;
2358 default:
2359 FAIL();
2360 break;
2361 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002362 continue;
2363 }
2364 SCOPED_TRACE(file);
2365 SCOPED_TRACE(aos::FlatbufferToJson(
2366 *log_header, {.multi_line = true, .max_vector_size = 100}));
2367 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2368 ASSERT_EQ(
2369 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2370 EXPECT_EQ(
2371 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2372 monotonic_clock::max_time.time_since_epoch().count());
2373 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2374 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2375 2u);
2376 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2377 monotonic_clock::max_time.time_since_epoch().count());
2378 ASSERT_TRUE(log_header->message()
2379 .has_oldest_remote_unreliable_monotonic_timestamps());
2380 ASSERT_EQ(log_header->message()
2381 .oldest_remote_unreliable_monotonic_timestamps()
2382 ->size(),
2383 2u);
2384 EXPECT_EQ(log_header->message()
2385 .oldest_remote_unreliable_monotonic_timestamps()
2386 ->Get(0),
2387 monotonic_clock::max_time.time_since_epoch().count());
2388 ASSERT_TRUE(log_header->message()
2389 .has_oldest_local_unreliable_monotonic_timestamps());
2390 ASSERT_EQ(log_header->message()
2391 .oldest_local_unreliable_monotonic_timestamps()
2392 ->size(),
2393 2u);
2394 EXPECT_EQ(log_header->message()
2395 .oldest_local_unreliable_monotonic_timestamps()
2396 ->Get(0),
2397 monotonic_clock::max_time.time_since_epoch().count());
2398
2399 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2400 monotonic_clock::time_point(chrono::nanoseconds(
2401 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2402 1)));
2403 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2404 monotonic_clock::time_point(chrono::nanoseconds(
2405 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2406 const monotonic_clock::time_point
2407 oldest_remote_unreliable_monotonic_timestamps =
2408 monotonic_clock::time_point(chrono::nanoseconds(
2409 log_header->message()
2410 .oldest_remote_unreliable_monotonic_timestamps()
2411 ->Get(1)));
2412 const monotonic_clock::time_point
2413 oldest_local_unreliable_monotonic_timestamps =
2414 monotonic_clock::time_point(chrono::nanoseconds(
2415 log_header->message()
2416 .oldest_local_unreliable_monotonic_timestamps()
2417 ->Get(1)));
2418 switch (log_header->message().parts_index()) {
2419 case 0:
2420 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2421 monotonic_clock::max_time);
2422 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2423 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2424 monotonic_clock::max_time);
2425 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2426 monotonic_clock::max_time);
2427 break;
2428 case 1:
2429 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2430 monotonic_clock::time_point(chrono::microseconds(90200)));
2431 EXPECT_EQ(oldest_local_monotonic_timestamps,
2432 monotonic_clock::time_point(chrono::microseconds(90350)));
2433 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2434 monotonic_clock::time_point(chrono::microseconds(90200)));
2435 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2436 monotonic_clock::time_point(chrono::microseconds(90350)));
2437 break;
2438 case 2:
2439 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002440 monotonic_clock::time_point(chrono::milliseconds(1323) +
2441 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002442 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002443 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002444 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002445 monotonic_clock::time_point(chrono::milliseconds(1323) +
2446 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002447 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2448 monotonic_clock::time_point(chrono::microseconds(10100350)));
2449 break;
2450 default:
2451 FAIL();
2452 break;
2453 }
2454 }
2455
Austin Schuh315b96b2020-12-11 21:21:12 -08002456 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002457 {
2458 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002459
Austin Schuh58646e22021-08-23 23:51:46 -07002460 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2461 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002462
Austin Schuh58646e22021-08-23 23:51:46 -07002463 // This sends out the fetched messages and advances time to the start of
2464 // the log file.
2465 reader.Register(&log_reader_factory);
2466
2467 log_reader_factory.Run();
2468
2469 reader.Deregister();
2470 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002471}
2472
Austin Schuhc9049732020-12-21 22:27:15 -08002473// Tests that we properly handle one direction of message_bridge being
2474// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002475TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002476 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002477 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002478 {BootTimestamp::epoch(),
2479 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002480
2481 time_converter_.AddMonotonic(
2482 {chrono::milliseconds(10000),
2483 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002484 {
2485 LoggerState pi1_logger = MakeLogger(pi1_);
2486
2487 event_loop_factory_.RunFor(chrono::milliseconds(95));
2488
2489 StartLogger(&pi1_logger);
2490
2491 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2492 }
2493
2494 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2495 // to confirm the right thing happened.
2496 ConfirmReadable(pi1_single_direction_logfiles_);
2497}
2498
2499// Tests that we properly handle one direction of message_bridge being
2500// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002501TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002502 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002503 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002504 {BootTimestamp::epoch(),
2505 BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002506
2507 time_converter_.AddMonotonic(
2508 {chrono::milliseconds(10000),
2509 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2510 {
2511 LoggerState pi1_logger = MakeLogger(pi1_);
2512
2513 event_loop_factory_.RunFor(chrono::milliseconds(95));
2514
2515 StartLogger(&pi1_logger);
2516
2517 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2518 }
2519
2520 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2521 // to confirm the right thing happened.
2522 ConfirmReadable(pi1_single_direction_logfiles_);
2523}
2524
Austin Schuhe9f00232021-09-16 18:04:23 -07002525// Tests that we explode if someone passes in a part file twice with a better
2526// error than an out of order error.
2527TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2528 time_converter_.AddMonotonic(
2529 {BootTimestamp::epoch(),
2530 BootTimestamp::epoch() + chrono::seconds(1000)});
2531 {
2532 LoggerState pi1_logger = MakeLogger(pi1_);
2533
2534 event_loop_factory_.RunFor(chrono::milliseconds(95));
2535
2536 StartLogger(&pi1_logger);
2537
2538 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2539 }
2540
2541 std::vector<std::string> duplicates;
2542 for (const std::string &f : pi1_single_direction_logfiles_) {
2543 duplicates.emplace_back(f);
2544 duplicates.emplace_back(f);
2545 }
2546 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
2547}
2548
Austin Schuh87dd3832021-01-01 23:07:31 -08002549// Tests that we properly handle a dead node. Do this by just disconnecting it
2550// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002551TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07002552 pi1_->Disconnect(pi2_->node());
2553 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002554 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002555 {BootTimestamp::epoch(),
2556 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002557 {
2558 LoggerState pi1_logger = MakeLogger(pi1_);
2559
2560 event_loop_factory_.RunFor(chrono::milliseconds(95));
2561
2562 StartLogger(&pi1_logger);
2563
2564 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2565 }
2566
2567 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2568 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002569 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002570}
2571
Austin Schuhcdd90272021-03-15 12:46:16 -07002572constexpr std::string_view kCombinedConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002573 "cad3b6838a518ab29470771a959b89945ee034bc7a738080fd1713a1dce51b1f");
Austin Schuhcdd90272021-03-15 12:46:16 -07002574constexpr std::string_view kSplitConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002575 "aafdd7e43d1942cce5b3e2dd8c6b9706abf7068a43501625a33b7cdfddf6c932");
Austin Schuhcdd90272021-03-15 12:46:16 -07002576
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002577INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002578 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002579 ::testing::Combine(::testing::Values(
2580 ConfigParams{
2581 "multinode_pingpong_combined_config.json", true,
2582 kCombinedConfigSha1},
2583 ConfigParams{"multinode_pingpong_split_config.json",
2584 false, kSplitConfigSha1}),
2585 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002586
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002587INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002588 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002589 ::testing::Combine(::testing::Values(
2590 ConfigParams{
2591 "multinode_pingpong_combined_config.json", true,
2592 kCombinedConfigSha1},
2593 ConfigParams{"multinode_pingpong_split_config.json",
2594 false, kSplitConfigSha1}),
2595 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002596
Austin Schuh5b728b72021-06-16 14:57:15 -07002597// Tests that we can relog with a different config. This makes most sense when
2598// you are trying to edit a log and want to use channel renaming + the original
2599// config in the new log.
2600TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
2601 time_converter_.StartEqual();
2602 {
2603 LoggerState pi1_logger = MakeLogger(pi1_);
2604 LoggerState pi2_logger = MakeLogger(pi2_);
2605
2606 event_loop_factory_.RunFor(chrono::milliseconds(95));
2607
2608 StartLogger(&pi1_logger);
2609 StartLogger(&pi2_logger);
2610
2611 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2612 }
2613
2614 LogReader reader(SortParts(logfiles_));
2615 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
2616
2617 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2618 log_reader_factory.set_send_delay(chrono::microseconds(0));
2619
2620 // This sends out the fetched messages and advances time to the start of the
2621 // log file.
2622 reader.Register(&log_reader_factory);
2623
2624 const Node *pi1 =
2625 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2626 const Node *pi2 =
2627 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2628
2629 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2630 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2631 LOG(INFO) << "now pi1 "
2632 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2633 LOG(INFO) << "now pi2 "
2634 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2635
2636 EXPECT_THAT(reader.LoggedNodes(),
2637 ::testing::ElementsAre(
2638 configuration::GetNode(reader.logged_configuration(), pi1),
2639 configuration::GetNode(reader.logged_configuration(), pi2)));
2640
2641 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2642
2643 // And confirm we can re-create a log again, while checking the contents.
2644 std::vector<std::string> log_files;
2645 {
2646 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002647 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002648 &log_reader_factory, reader.logged_configuration());
2649 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002650 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002651 &log_reader_factory, reader.logged_configuration());
2652
2653 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2654 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
2655
2656 log_reader_factory.Run();
2657
2658 for (auto &x : pi1_logger.log_namer->all_filenames()) {
2659 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
2660 }
2661 for (auto &x : pi2_logger.log_namer->all_filenames()) {
2662 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
2663 }
2664 }
2665
2666 reader.Deregister();
2667
2668 // And verify that we can run the LogReader over the relogged files without
2669 // hitting any fatal errors.
2670 {
2671 LogReader relogged_reader(SortParts(log_files));
2672 relogged_reader.Register();
2673
2674 relogged_reader.event_loop_factory()->Run();
2675 }
2676}
Austin Schuha04efed2021-01-24 18:04:20 -08002677
Austin Schuhe309d2a2019-11-29 13:25:21 -08002678} // namespace testing
2679} // namespace logger
2680} // namespace aos