blob: eebb594c805d5c68faf10e92d64dddb3884d7f42 [file] [log] [blame]
Austin Schuhb06f03b2021-02-17 22:00:37 -08001#include "aos/events/logging/log_reader.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08002
Austin Schuh6bb8a822021-03-31 23:04:39 -07003#include <sys/stat.h>
4
Austin Schuh315b96b2020-12-11 21:21:12 -08005#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08006#include "aos/events/event_loop.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08007#include "aos/events/logging/log_writer.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
171 logger_event_loop->OnRun(
172 [base_name1, base_name2, &logger_event_loop, &logger]() {
Austin 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
Austin Schuh61e973f2021-02-21 21:43:56 -0800419// Parameters to run all the tests with.
420struct Param {
421 // The config file to use.
422 std::string config;
423 // If true, the RemoteMessage channel should be shared between all the remote
424 // channels. If false, there will be 1 RemoteMessage channel per remote
425 // channel.
426 bool shared;
427 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700428 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800429};
Austin Schuh315b96b2020-12-11 21:21:12 -0800430
Austin Schuh61e973f2021-02-21 21:43:56 -0800431class MultinodeLoggerTest : public ::testing::TestWithParam<struct Param> {
Austin Schuh15649d62019-12-28 16:36:38 -0800432 public:
433 MultinodeLoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -0700434 : config_(aos::configuration::ReadConfig(ArtifactPath(
435 absl::StrCat("aos/events/logging/", GetParam().config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800436 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800437 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700438 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800439 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700440 event_loop_factory_.configuration(), pi1_->node())),
441 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800442 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700443 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800444 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800445 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
446 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800447 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800448 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800449 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700450 structured_logfiles_(StructureLogFiles()) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800451 LOG(INFO) << "Config " << GetParam().config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800452 event_loop_factory_.SetTimeConverter(&time_converter_);
453
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700454 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700455 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700456 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800457 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700458 }
459
Austin Schuh268586b2021-03-31 22:24:39 -0700460 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800461 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800462 unlink(file.c_str());
463 }
464
Austin Schuh268586b2021-03-31 22:24:39 -0700465 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800466 unlink(file.c_str());
467 }
468
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700469 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
470 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700471
472 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
473 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700474 }
475
Austin Schuh61e973f2021-02-21 21:43:56 -0800476 bool shared() const { return GetParam().shared; }
477
478 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700479 std::string logfile_base2,
480 size_t pi1_data_count = 2,
481 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800482 std::vector<std::string> result;
483 result.emplace_back(
484 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
485 result.emplace_back(
486 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
Austin Schuhe46492f2021-07-31 19:49:41 -0700487 for (size_t i = 0; i < pi1_data_count; ++i) {
488 result.emplace_back(
489 absl::StrCat(logfile_base1, "_pi1_data.part", i, ".bfbs"));
490 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800491 result.emplace_back(logfile_base1 +
492 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
493 result.emplace_back(logfile_base1 +
494 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700495 for (size_t i = 0; i < pi2_data_count; ++i) {
496 result.emplace_back(
497 absl::StrCat(logfile_base2, "_pi2_data.part", i, ".bfbs"));
498 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800499 result.emplace_back(
500 logfile_base2 +
501 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
502 result.emplace_back(
503 logfile_base2 +
504 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
505 result.emplace_back(
506 logfile_base1 +
507 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
508 result.emplace_back(
509 logfile_base1 +
510 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
511 if (shared()) {
512 result.emplace_back(logfile_base1 +
513 "_timestamps/pi1/aos/remote_timestamps/pi2/"
514 "aos.message_bridge.RemoteMessage.part0.bfbs");
515 result.emplace_back(logfile_base1 +
516 "_timestamps/pi1/aos/remote_timestamps/pi2/"
517 "aos.message_bridge.RemoteMessage.part1.bfbs");
518 result.emplace_back(logfile_base2 +
519 "_timestamps/pi2/aos/remote_timestamps/pi1/"
520 "aos.message_bridge.RemoteMessage.part0.bfbs");
521 result.emplace_back(logfile_base2 +
522 "_timestamps/pi2/aos/remote_timestamps/pi1/"
523 "aos.message_bridge.RemoteMessage.part1.bfbs");
524 } else {
525 result.emplace_back(logfile_base1 +
526 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
527 "aos-message_bridge-Timestamp/"
528 "aos.message_bridge.RemoteMessage.part0.bfbs");
529 result.emplace_back(logfile_base1 +
530 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
531 "aos-message_bridge-Timestamp/"
532 "aos.message_bridge.RemoteMessage.part1.bfbs");
533 result.emplace_back(logfile_base2 +
534 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
535 "aos-message_bridge-Timestamp/"
536 "aos.message_bridge.RemoteMessage.part0.bfbs");
537 result.emplace_back(logfile_base2 +
538 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
539 "aos-message_bridge-Timestamp/"
540 "aos.message_bridge.RemoteMessage.part1.bfbs");
541 result.emplace_back(logfile_base1 +
542 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
543 "aos-examples-Ping/"
544 "aos.message_bridge.RemoteMessage.part0.bfbs");
545 result.emplace_back(logfile_base1 +
546 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
547 "aos-examples-Ping/"
548 "aos.message_bridge.RemoteMessage.part1.bfbs");
549 }
550
551 return result;
552 }
553
554 std::vector<std::string> MakePi1RebootLogfiles() {
555 std::vector<std::string> result;
556 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700557 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
558 result.emplace_back(logfile_base1_ + "_pi1_data.part2.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800559 result.emplace_back(logfile_base1_ +
560 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
561 result.emplace_back(logfile_base1_ +
562 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
563 result.emplace_back(logfile_base1_ +
564 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700565 result.emplace_back(logfile_base1_ +
566 "_pi2_data/test/aos.examples.Pong.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800567 result.emplace_back(
568 logfile_base1_ +
569 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
570 result.emplace_back(
571 logfile_base1_ +
572 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
573 result.emplace_back(
574 logfile_base1_ +
575 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
576 result.emplace_back(
Austin Schuh58646e22021-08-23 23:51:46 -0700577 logfile_base1_ +
578 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3.bfbs");
579 result.emplace_back(
Austin Schuh61e973f2021-02-21 21:43:56 -0800580 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
581 if (shared()) {
582 result.emplace_back(logfile_base1_ +
583 "_timestamps/pi1/aos/remote_timestamps/pi2/"
584 "aos.message_bridge.RemoteMessage.part0.bfbs");
585 result.emplace_back(logfile_base1_ +
586 "_timestamps/pi1/aos/remote_timestamps/pi2/"
587 "aos.message_bridge.RemoteMessage.part1.bfbs");
588 result.emplace_back(logfile_base1_ +
589 "_timestamps/pi1/aos/remote_timestamps/pi2/"
590 "aos.message_bridge.RemoteMessage.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700591 result.emplace_back(logfile_base1_ +
592 "_timestamps/pi1/aos/remote_timestamps/pi2/"
593 "aos.message_bridge.RemoteMessage.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800594 } else {
595 result.emplace_back(logfile_base1_ +
596 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
597 "aos-message_bridge-Timestamp/"
598 "aos.message_bridge.RemoteMessage.part0.bfbs");
599 result.emplace_back(logfile_base1_ +
600 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
601 "aos-message_bridge-Timestamp/"
602 "aos.message_bridge.RemoteMessage.part1.bfbs");
603 result.emplace_back(logfile_base1_ +
604 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
605 "aos-message_bridge-Timestamp/"
606 "aos.message_bridge.RemoteMessage.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700607 result.emplace_back(logfile_base1_ +
608 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
609 "aos-message_bridge-Timestamp/"
610 "aos.message_bridge.RemoteMessage.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800611
612 result.emplace_back(logfile_base1_ +
613 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
614 "aos-examples-Ping/"
615 "aos.message_bridge.RemoteMessage.part0.bfbs");
616 result.emplace_back(logfile_base1_ +
617 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
618 "aos-examples-Ping/"
619 "aos.message_bridge.RemoteMessage.part1.bfbs");
620 result.emplace_back(logfile_base1_ +
621 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
622 "aos-examples-Ping/"
623 "aos.message_bridge.RemoteMessage.part2.bfbs");
Austin Schuh58646e22021-08-23 23:51:46 -0700624 result.emplace_back(logfile_base1_ +
625 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
626 "aos-examples-Ping/"
627 "aos.message_bridge.RemoteMessage.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800628 }
629 return result;
630 }
631
632 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
633 std::vector<std::string> result;
634 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuh510dc622021-08-06 18:47:30 -0700635 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800636 result.emplace_back(
637 logfile_base1_ +
638 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
639 result.emplace_back(
640 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh510dc622021-08-06 18:47:30 -0700641 return result;
642 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800643
Austin Schuh510dc622021-08-06 18:47:30 -0700644 std::vector<std::string> MakePi1DeadNodeLogfiles() {
645 std::vector<std::string> result;
646 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
647 result.emplace_back(
648 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh61e973f2021-02-21 21:43:56 -0800649 return result;
650 }
651
652 std::vector<std::vector<std::string>> StructureLogFiles() {
653 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700654 std::vector<std::string>{logfiles_[2], logfiles_[3]},
655 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800656 std::vector<std::string>{logfiles_[6], logfiles_[7]},
657 std::vector<std::string>{logfiles_[8], logfiles_[9]},
658 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700659 std::vector<std::string>{logfiles_[12], logfiles_[13]},
660 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800661
662 if (!shared()) {
663 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700664 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800665 }
666
667 return result;
668 }
669
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700670 struct LoggerState {
671 std::unique_ptr<EventLoop> event_loop;
672 std::unique_ptr<Logger> logger;
Austin Schuh5b728b72021-06-16 14:57:15 -0700673 const Configuration *configuration;
674 const Node *node;
675 MultiNodeLogNamer *log_namer;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700676 };
677
Austin Schuh58646e22021-08-23 23:51:46 -0700678 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700679 SimulatedEventLoopFactory *factory = nullptr,
680 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700681 if (factory == nullptr) {
682 factory = &event_loop_factory_;
683 }
Austin Schuh5b728b72021-06-16 14:57:15 -0700684 if (configuration == nullptr) {
685 configuration = factory->configuration();
686 }
Austin Schuh58646e22021-08-23 23:51:46 -0700687 return {node->MakeEventLoop("logger"),
688 {},
689 configuration,
690 configuration::GetNode(configuration, node->node()),
691 nullptr};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700692 }
693
Austin Schuh3bd4c402020-11-06 18:19:06 -0800694 void StartLogger(LoggerState *logger, std::string logfile_base = "",
695 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700696 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800697 if (logger->event_loop->node()->name()->string_view() == "pi1") {
698 logfile_base = logfile_base1_;
699 } else {
700 logfile_base = logfile_base2_;
701 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700702 }
703
Austin Schuh5b728b72021-06-16 14:57:15 -0700704 logger->logger = std::make_unique<Logger>(logger->event_loop.get(),
705 logger->configuration);
Brian Silverman1f345222020-09-24 21:14:48 -0700706 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800707 logger->logger->set_name(absl::StrCat(
708 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800709 logger->event_loop->OnRun([logger, logfile_base, compress]() {
710 std::unique_ptr<MultiNodeLogNamer> namer =
Austin Schuh5b728b72021-06-16 14:57:15 -0700711 std::make_unique<MultiNodeLogNamer>(
712 logfile_base, logger->configuration, logger->event_loop.get(),
713 logger->node);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800714 if (compress) {
715#ifdef LZMA
716 namer->set_extension(".xz");
717 namer->set_encoder_factory(
718 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
719#else
720 LOG(FATAL) << "Compression unsupported";
721#endif
722 }
Austin Schuh5b728b72021-06-16 14:57:15 -0700723 logger->log_namer = namer.get();
Austin Schuh3bd4c402020-11-06 18:19:06 -0800724
725 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700726 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700727 }
Austin Schuh15649d62019-12-28 16:36:38 -0800728
Austin Schuh3bd4c402020-11-06 18:19:06 -0800729 void VerifyParts(const std::vector<LogFile> &sorted_parts,
730 const std::vector<std::string> &corrupted_parts = {}) {
731 EXPECT_EQ(sorted_parts.size(), 2u);
732
733 // Count up the number of UUIDs and make sure they are what we expect as a
734 // sanity check.
735 std::set<std::string> log_event_uuids;
736 std::set<std::string> parts_uuids;
737 std::set<std::string> both_uuids;
738
739 size_t missing_rt_count = 0;
740
741 std::vector<std::string> logger_nodes;
742 for (const LogFile &log_file : sorted_parts) {
743 EXPECT_FALSE(log_file.log_event_uuid.empty());
744 log_event_uuids.insert(log_file.log_event_uuid);
745 logger_nodes.emplace_back(log_file.logger_node);
746 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800747 EXPECT_TRUE(log_file.config);
748 EXPECT_EQ(log_file.name,
749 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800750
751 for (const LogParts &part : log_file.parts) {
752 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
753 << ": " << part;
754 missing_rt_count +=
755 part.realtime_start_time == aos::realtime_clock::min_time;
756
757 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
758 log_event_uuids.end());
759 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800760 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800761 parts_uuids.insert(part.parts_uuid);
762 both_uuids.insert(part.parts_uuid);
763 }
764 }
765
Austin Schuh61e973f2021-02-21 21:43:56 -0800766 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
767 // start time on remote nodes because we don't know it and would be
768 // guessing. And the log reader can actually do a better job. The number
769 // depends on if we have the remote timestamps split across 2 files, or just
770 // across 1, depending on if we are using a split or combined timestamp
771 // channel config.
772 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800773
774 EXPECT_EQ(log_event_uuids.size(), 2u);
775 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
776 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
777
778 // Test that each list of parts is in order. Don't worry about the ordering
779 // between part file lists though.
780 // (inner vectors all need to be in order, but outer one doesn't matter).
781 EXPECT_THAT(ToLogReaderVector(sorted_parts),
782 ::testing::UnorderedElementsAreArray(structured_logfiles_));
783
784 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
785
786 EXPECT_NE(sorted_parts[0].realtime_start_time,
787 aos::realtime_clock::min_time);
788 EXPECT_NE(sorted_parts[1].realtime_start_time,
789 aos::realtime_clock::min_time);
790
791 EXPECT_NE(sorted_parts[0].monotonic_start_time,
792 aos::monotonic_clock::min_time);
793 EXPECT_NE(sorted_parts[1].monotonic_start_time,
794 aos::monotonic_clock::min_time);
795
796 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
797 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
798 }
799
Austin Schuhc9049732020-12-21 22:27:15 -0800800 void ConfirmReadable(const std::vector<std::string> &files) {
801 LogReader reader(SortParts(files));
802
803 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
804 reader.Register(&log_reader_factory);
805
806 log_reader_factory.Run();
807
808 reader.Deregister();
809 }
810
Austin Schuh3bd4c402020-11-06 18:19:06 -0800811 void AddExtension(std::string_view extension) {
812 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
813 [extension](const std::string &in) {
814 return absl::StrCat(in, extension);
815 });
816
817 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
818 structured_logfiles_.begin(),
819 [extension](std::vector<std::string> in) {
820 std::transform(in.begin(), in.end(), in.begin(),
821 [extension](const std::string &in_str) {
822 return absl::StrCat(in_str, extension);
823 });
824 return in;
825 });
826 }
827
Austin Schuh15649d62019-12-28 16:36:38 -0800828 // Config and factory.
829 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800830 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800831 SimulatedEventLoopFactory event_loop_factory_;
832
Austin Schuh58646e22021-08-23 23:51:46 -0700833 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800834 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700835 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800836 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700837
838 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800839 std::string logfile_base1_;
840 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800841 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700842 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800843 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700844
845 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800846};
847
Austin Schuh391e3172020-09-01 22:48:18 -0700848// Counts the number of messages on a channel. Returns (channel name, channel
849// type, count) for every message matching matcher()
850std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800851 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800852 std::function<bool(const MessageHeader *)> matcher) {
853 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800854 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800855
Austin Schuh6f3babe2020-01-26 20:34:50 -0800856 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800857 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800858 message_reader.ReadMessage();
859 if (!msg) {
860 break;
861 }
862
863 if (matcher(&msg.value().message())) {
864 counts[msg.value().message().channel_index()]++;
865 }
866 }
867
Austin Schuh391e3172020-09-01 22:48:18 -0700868 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800869 int channel = 0;
870 for (size_t i = 0; i < counts.size(); ++i) {
871 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800872 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700873 result.push_back(std::make_tuple(channel->name()->str(),
874 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800875 }
876 ++channel;
877 }
878
879 return result;
880}
881
882// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700883std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800884 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700885 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800886 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800887 if (msg->has_data()) {
888 CHECK(!msg->has_monotonic_remote_time());
889 CHECK(!msg->has_realtime_remote_time());
890 CHECK(!msg->has_remote_queue_index());
891 return true;
892 }
893 return false;
894 });
895}
896
897// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700898std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800899 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800900 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800901 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800902 if (!msg->has_data()) {
903 CHECK(msg->has_monotonic_remote_time());
904 CHECK(msg->has_realtime_remote_time());
905 CHECK(msg->has_remote_queue_index());
906 return true;
907 }
908 return false;
909 });
910}
911
Austin Schuhcde938c2020-02-02 17:30:07 -0800912// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800913TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800914 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800915 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700916 LoggerState pi1_logger = MakeLogger(pi1_);
917 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800918
919 event_loop_factory_.RunFor(chrono::milliseconds(95));
920
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700921 StartLogger(&pi1_logger);
922 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800923
Austin Schuh15649d62019-12-28 16:36:38 -0800924 event_loop_factory_.RunFor(chrono::milliseconds(20000));
925 }
926
Austin Schuh6f3babe2020-01-26 20:34:50 -0800927 {
Austin Schuh64fab802020-09-09 22:47:47 -0700928 std::set<std::string> logfile_uuids;
929 std::set<std::string> parts_uuids;
930 // Confirm that we have the expected number of UUIDs for both the logfile
931 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800932 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700933 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800934 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800935 if (!log_header.back().message().has_configuration()) {
936 logfile_uuids.insert(
937 log_header.back().message().log_event_uuid()->str());
938 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
939 }
Austin Schuh64fab802020-09-09 22:47:47 -0700940 }
Austin Schuh15649d62019-12-28 16:36:38 -0800941
Austin Schuh64fab802020-09-09 22:47:47 -0700942 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800943 if (shared()) {
944 EXPECT_EQ(parts_uuids.size(), 7u);
945 } else {
946 EXPECT_EQ(parts_uuids.size(), 8u);
947 }
Austin Schuh64fab802020-09-09 22:47:47 -0700948
949 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800950 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -0700951 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700952 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
953 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700954 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
955 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
956 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
957 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700958 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
959 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700960 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
961 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
962 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
963 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800964 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700965 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
966 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800967 }
Austin Schuh64fab802020-09-09 22:47:47 -0700968
969 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800970 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -0700971 EXPECT_EQ(log_header[3].message().parts_index(), 1);
972 EXPECT_EQ(log_header[4].message().parts_index(), 0);
973 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -0700974 EXPECT_EQ(log_header[6].message().parts_index(), 0);
975 EXPECT_EQ(log_header[7].message().parts_index(), 1);
976 EXPECT_EQ(log_header[8].message().parts_index(), 0);
977 EXPECT_EQ(log_header[9].message().parts_index(), 1);
978 EXPECT_EQ(log_header[10].message().parts_index(), 0);
979 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800980 EXPECT_EQ(log_header[12].message().parts_index(), 0);
981 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -0700982 EXPECT_EQ(log_header[14].message().parts_index(), 0);
983 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800984 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700985 EXPECT_EQ(log_header[16].message().parts_index(), 0);
986 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800987 }
Austin Schuh64fab802020-09-09 22:47:47 -0700988 }
989
Austin Schuh8c399962020-12-25 21:51:45 -0800990 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700991 {
Austin Schuh391e3172020-09-01 22:48:18 -0700992 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800993 std::shared_ptr<const aos::Configuration> config =
994 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700995
Austin Schuh6f3babe2020-01-26 20:34:50 -0800996 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700997 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800998 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700999 UnorderedElementsAre(
Austin Schuhe46492f2021-07-31 19:49:41 -07001000 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
1001 1),
1002 std::make_tuple("/test", "aos.examples.Ping", 1)))
1003 << " : " << logfiles_[2];
1004 EXPECT_THAT(
1005 CountChannelsData(config, logfiles_[3]),
1006 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -07001007 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001008 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001009 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001010 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1011 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001012 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001013 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1014 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001015 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001016 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1017 UnorderedElementsAre())
1018 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001019 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001020 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001021 UnorderedElementsAre(
1022 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001023 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001024 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001025
1026 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001027 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001028 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001029 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001030 << " : " << logfiles_[4];
1031 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001032 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001033 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001034 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001035
Austin Schuh6f3babe2020-01-26 20:34:50 -08001036 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001037 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001038 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001039 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001040 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1041 UnorderedElementsAre())
1042 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001043
1044 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001045 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1046 UnorderedElementsAre(std::make_tuple(
1047 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1048 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001049 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001050 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001051 UnorderedElementsAre(
1052 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001053 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001054 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001055 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1056 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001057 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001058 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001059 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001060 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001061 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1062 UnorderedElementsAre())
1063 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001064 EXPECT_THAT(
1065 CountChannelsTimestamp(config, logfiles_[7]),
1066 UnorderedElementsAre(
1067 std::make_tuple("/test", "aos.examples.Ping", 2001),
1068 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001069 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001070
1071 // And then test that the remotely logged timestamp data files only have
1072 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001073 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1074 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001075 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001076 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1077 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001078 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001079 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1080 UnorderedElementsAre())
1081 << " : " << logfiles_[10];
1082 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1083 UnorderedElementsAre())
1084 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001085
Austin Schuh8c399962020-12-25 21:51:45 -08001086 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001087 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001088 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001089 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001090 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001091 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001092 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001093 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001094
Austin Schuh8c399962020-12-25 21:51:45 -08001095 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001096 UnorderedElementsAre(std::make_tuple(
1097 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001098 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001099 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001100 UnorderedElementsAre(std::make_tuple(
1101 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001102 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001103
1104 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001105 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1106 UnorderedElementsAre())
1107 << " : " << logfiles_[12];
1108 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1109 UnorderedElementsAre())
1110 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001111 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1112 UnorderedElementsAre())
1113 << " : " << logfiles_[14];
1114 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1115 UnorderedElementsAre())
1116 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001117 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001118 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001119 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001120 << " : " << logfiles_[16];
1121 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001122 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001123 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001124 }
1125
1126 if (shared()) {
1127 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001128 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001129 UnorderedElementsAre(
1130 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1131 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001132 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001133 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001134 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001135 UnorderedElementsAre(
1136 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1137 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001138 << " : " << logfiles_[13];
1139 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001140 UnorderedElementsAre(std::make_tuple(
1141 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001142 << " : " << logfiles_[14];
1143 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001144 UnorderedElementsAre(std::make_tuple(
1145 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1146 << " : " << logfiles_[15];
1147 } else {
1148 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1149 UnorderedElementsAre(std::make_tuple(
1150 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1151 << " : " << logfiles_[12];
1152 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1153 UnorderedElementsAre(std::make_tuple(
1154 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1155 << " : " << logfiles_[13];
1156 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1157 UnorderedElementsAre(std::make_tuple(
1158 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1159 << " : " << logfiles_[14];
1160 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1161 UnorderedElementsAre(std::make_tuple(
1162 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1163 << " : " << logfiles_[15];
1164 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1165 UnorderedElementsAre(
1166 std::make_tuple("/test", "aos.examples.Ping", 91)))
1167 << " : " << logfiles_[16];
1168 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001169 UnorderedElementsAre(
1170 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001171 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001172 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001173 }
1174
Austin Schuh8c399962020-12-25 21:51:45 -08001175 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001176
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001177 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001178 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001179
1180 // This sends out the fetched messages and advances time to the start of the
1181 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001182 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001183
Austin Schuhac0771c2020-01-07 18:36:30 -08001184 const Node *pi1 =
1185 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001186 const Node *pi2 =
1187 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001188
Austin Schuh2f8fd752020-09-01 22:38:28 -07001189 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1190 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1191 LOG(INFO) << "now pi1 "
1192 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1193 LOG(INFO) << "now pi2 "
1194 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1195
Austin Schuh07676622021-01-21 18:59:17 -08001196 EXPECT_THAT(reader.LoggedNodes(),
1197 ::testing::ElementsAre(
1198 configuration::GetNode(reader.logged_configuration(), pi1),
1199 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001200
1201 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001202
Austin Schuh6f3babe2020-01-26 20:34:50 -08001203 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001204 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001205 std::unique_ptr<EventLoop> pi2_event_loop =
1206 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001207
Austin Schuh6f3babe2020-01-26 20:34:50 -08001208 int pi1_ping_count = 10;
1209 int pi2_ping_count = 10;
1210 int pi1_pong_count = 10;
1211 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001212
1213 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001214 pi1_event_loop->MakeWatcher(
1215 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001216 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001217 << pi1_event_loop->context().monotonic_remote_time << " -> "
1218 << pi1_event_loop->context().monotonic_event_time;
1219 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1220 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1221 pi1_ping_count * chrono::milliseconds(10) +
1222 monotonic_clock::epoch());
1223 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1224 pi1_ping_count * chrono::milliseconds(10) +
1225 realtime_clock::epoch());
1226 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1227 pi1_event_loop->context().monotonic_event_time);
1228 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1229 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001230
Austin Schuh6f3babe2020-01-26 20:34:50 -08001231 ++pi1_ping_count;
1232 });
1233 pi2_event_loop->MakeWatcher(
1234 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001235 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001236 << pi2_event_loop->context().monotonic_remote_time << " -> "
1237 << pi2_event_loop->context().monotonic_event_time;
1238 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1239
1240 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1241 pi2_ping_count * chrono::milliseconds(10) +
1242 monotonic_clock::epoch());
1243 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1244 pi2_ping_count * chrono::milliseconds(10) +
1245 realtime_clock::epoch());
1246 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1247 chrono::microseconds(150),
1248 pi2_event_loop->context().monotonic_event_time);
1249 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1250 chrono::microseconds(150),
1251 pi2_event_loop->context().realtime_event_time);
1252 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001253 });
1254
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001255 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001256 // Confirm that the ping and pong counts both match, and the value also
1257 // matches.
1258 pi1_event_loop->MakeWatcher(
1259 "/test", [&pi1_event_loop, &pi1_ping_count,
1260 &pi1_pong_count](const examples::Pong &pong) {
1261 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1262 << pi1_event_loop->context().monotonic_remote_time << " -> "
1263 << pi1_event_loop->context().monotonic_event_time;
1264
1265 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1266 pi1_pong_count + kQueueIndexOffset);
1267 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1268 chrono::microseconds(200) +
1269 pi1_pong_count * chrono::milliseconds(10) +
1270 monotonic_clock::epoch());
1271 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1272 chrono::microseconds(200) +
1273 pi1_pong_count * chrono::milliseconds(10) +
1274 realtime_clock::epoch());
1275
1276 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1277 chrono::microseconds(150),
1278 pi1_event_loop->context().monotonic_event_time);
1279 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1280 chrono::microseconds(150),
1281 pi1_event_loop->context().realtime_event_time);
1282
1283 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1284 ++pi1_pong_count;
1285 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1286 });
1287 pi2_event_loop->MakeWatcher(
1288 "/test", [&pi2_event_loop, &pi2_ping_count,
1289 &pi2_pong_count](const examples::Pong &pong) {
1290 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1291 << pi2_event_loop->context().monotonic_remote_time << " -> "
1292 << pi2_event_loop->context().monotonic_event_time;
1293
1294 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001295 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001296
1297 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1298 chrono::microseconds(200) +
1299 pi2_pong_count * chrono::milliseconds(10) +
1300 monotonic_clock::epoch());
1301 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1302 chrono::microseconds(200) +
1303 pi2_pong_count * chrono::milliseconds(10) +
1304 realtime_clock::epoch());
1305
1306 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1307 pi2_event_loop->context().monotonic_event_time);
1308 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1309 pi2_event_loop->context().realtime_event_time);
1310
1311 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1312 ++pi2_pong_count;
1313 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1314 });
1315
1316 log_reader_factory.Run();
1317 EXPECT_EQ(pi1_ping_count, 2010);
1318 EXPECT_EQ(pi2_ping_count, 2010);
1319 EXPECT_EQ(pi1_pong_count, 2010);
1320 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001321
1322 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001323}
1324
James Kuszmaul46d82582020-05-09 19:50:09 -07001325typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1326
1327// Test that if we feed the replay with a mismatched node list that we die on
1328// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001329TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001330 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001331 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001332 LoggerState pi1_logger = MakeLogger(pi1_);
1333 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001334
1335 event_loop_factory_.RunFor(chrono::milliseconds(95));
1336
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001337 StartLogger(&pi1_logger);
1338 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001339
James Kuszmaul46d82582020-05-09 19:50:09 -07001340 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1341 }
1342
1343 // Test that, if we add an additional node to the replay config that the
1344 // logger complains about the mismatch in number of nodes.
1345 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1346 configuration::MergeWithConfig(&config_.message(), R"({
1347 "nodes": [
1348 {
1349 "name": "extra-node"
1350 }
1351 ]
1352 }
1353 )");
1354
Austin Schuh287d43d2020-12-04 20:19:33 -08001355 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1356 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001357 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001358}
1359
Austin Schuhcde938c2020-02-02 17:30:07 -08001360// Tests that we can read log files where they don't start at the same monotonic
1361// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001362TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001363 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001364 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001365 LoggerState pi1_logger = MakeLogger(pi1_);
1366 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001367
1368 event_loop_factory_.RunFor(chrono::milliseconds(95));
1369
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001370 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001371
1372 event_loop_factory_.RunFor(chrono::milliseconds(200));
1373
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001374 StartLogger(&pi2_logger);
1375
Austin Schuhcde938c2020-02-02 17:30:07 -08001376 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1377 }
1378
Austin Schuhe46492f2021-07-31 19:49:41 -07001379 // Since we delay starting pi2, it already knows about all the timestamps so
1380 // we don't end up with extra parts.
1381 LogReader reader(
1382 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001383
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001384 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001385 log_reader_factory.set_send_delay(chrono::microseconds(0));
1386
1387 // This sends out the fetched messages and advances time to the start of the
1388 // log file.
1389 reader.Register(&log_reader_factory);
1390
1391 const Node *pi1 =
1392 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1393 const Node *pi2 =
1394 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1395
Austin Schuh07676622021-01-21 18:59:17 -08001396 EXPECT_THAT(reader.LoggedNodes(),
1397 ::testing::ElementsAre(
1398 configuration::GetNode(reader.logged_configuration(), pi1),
1399 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001400
1401 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1402
1403 std::unique_ptr<EventLoop> pi1_event_loop =
1404 log_reader_factory.MakeEventLoop("test", pi1);
1405 std::unique_ptr<EventLoop> pi2_event_loop =
1406 log_reader_factory.MakeEventLoop("test", pi2);
1407
1408 int pi1_ping_count = 30;
1409 int pi2_ping_count = 30;
1410 int pi1_pong_count = 30;
1411 int pi2_pong_count = 30;
1412
1413 // Confirm that the ping value matches.
1414 pi1_event_loop->MakeWatcher(
1415 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1416 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1417 << pi1_event_loop->context().monotonic_remote_time << " -> "
1418 << pi1_event_loop->context().monotonic_event_time;
1419 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1420
1421 ++pi1_ping_count;
1422 });
1423 pi2_event_loop->MakeWatcher(
1424 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1425 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1426 << pi2_event_loop->context().monotonic_remote_time << " -> "
1427 << pi2_event_loop->context().monotonic_event_time;
1428 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1429
1430 ++pi2_ping_count;
1431 });
1432
1433 // Confirm that the ping and pong counts both match, and the value also
1434 // matches.
1435 pi1_event_loop->MakeWatcher(
1436 "/test", [&pi1_event_loop, &pi1_ping_count,
1437 &pi1_pong_count](const examples::Pong &pong) {
1438 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1439 << pi1_event_loop->context().monotonic_remote_time << " -> "
1440 << pi1_event_loop->context().monotonic_event_time;
1441
1442 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1443 ++pi1_pong_count;
1444 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1445 });
1446 pi2_event_loop->MakeWatcher(
1447 "/test", [&pi2_event_loop, &pi2_ping_count,
1448 &pi2_pong_count](const examples::Pong &pong) {
1449 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1450 << pi2_event_loop->context().monotonic_remote_time << " -> "
1451 << pi2_event_loop->context().monotonic_event_time;
1452
1453 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1454 ++pi2_pong_count;
1455 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1456 });
1457
1458 log_reader_factory.Run();
1459 EXPECT_EQ(pi1_ping_count, 2030);
1460 EXPECT_EQ(pi2_ping_count, 2030);
1461 EXPECT_EQ(pi1_pong_count, 2030);
1462 EXPECT_EQ(pi2_pong_count, 2030);
1463
1464 reader.Deregister();
1465}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001466
Austin Schuh8bd96322020-02-13 21:18:22 -08001467// Tests that we can read log files where the monotonic clocks drift and don't
1468// match correctly. While we are here, also test that different ending times
1469// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001470TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001471 // TODO(austin): Negate...
1472 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1473
Austin Schuh66168842021-08-17 19:42:21 -07001474 time_converter_.AddMonotonic(
1475 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001476 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1477 // skew to be 200 uS/s
1478 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1479 {chrono::milliseconds(95),
1480 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1481 // Run another 200 ms to have one logger start first.
1482 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1483 {chrono::milliseconds(200), chrono::milliseconds(200)});
1484 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1485 // go far enough to cause problems if this isn't accounted for.
1486 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1487 {chrono::milliseconds(20000),
1488 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1489 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1490 {chrono::milliseconds(40000),
1491 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1492 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1493 {chrono::milliseconds(400), chrono::milliseconds(400)});
1494
Austin Schuhcde938c2020-02-02 17:30:07 -08001495 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001496 LoggerState pi2_logger = MakeLogger(pi2_);
1497
Austin Schuh58646e22021-08-23 23:51:46 -07001498 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1499 << pi2_->realtime_now() << " distributed "
1500 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001501
Austin Schuh58646e22021-08-23 23:51:46 -07001502 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1503 << pi2_->realtime_now() << " distributed "
1504 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001505
Austin Schuh87dd3832021-01-01 23:07:31 -08001506 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001507
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001508 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001509
Austin Schuh87dd3832021-01-01 23:07:31 -08001510 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001511
Austin Schuh8bd96322020-02-13 21:18:22 -08001512 {
1513 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001514 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001515
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001516 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001517 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001518
Austin Schuh87dd3832021-01-01 23:07:31 -08001519 // Make sure we slewed time far enough so that the difference is greater
1520 // than the network delay. This confirms that if we sort incorrectly, it
1521 // would show in the results.
1522 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001523 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001524 -event_loop_factory_.send_delay() -
1525 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001526
Austin Schuh87dd3832021-01-01 23:07:31 -08001527 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001528
Austin Schuh87dd3832021-01-01 23:07:31 -08001529 // And now check that we went far enough the other way to make sure we
1530 // cover both problems.
1531 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001532 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001533 event_loop_factory_.send_delay() +
1534 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001535 }
1536
1537 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001538 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001539 }
1540
Austin Schuh72211ae2021-08-05 14:02:30 -07001541 LogReader reader(
1542 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001543
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001544 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001545 log_reader_factory.set_send_delay(chrono::microseconds(0));
1546
Austin Schuhcde938c2020-02-02 17:30:07 -08001547 const Node *pi1 =
1548 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1549 const Node *pi2 =
1550 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1551
Austin Schuh2f8fd752020-09-01 22:38:28 -07001552 // This sends out the fetched messages and advances time to the start of the
1553 // log file.
1554 reader.Register(&log_reader_factory);
1555
1556 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1557 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1558 LOG(INFO) << "now pi1 "
1559 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1560 LOG(INFO) << "now pi2 "
1561 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1562
Austin Schuhcde938c2020-02-02 17:30:07 -08001563 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001564 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1565 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001566 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1567 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001568 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1569 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001570 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1571
Austin Schuh07676622021-01-21 18:59:17 -08001572 EXPECT_THAT(reader.LoggedNodes(),
1573 ::testing::ElementsAre(
1574 configuration::GetNode(reader.logged_configuration(), pi1),
1575 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001576
1577 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1578
1579 std::unique_ptr<EventLoop> pi1_event_loop =
1580 log_reader_factory.MakeEventLoop("test", pi1);
1581 std::unique_ptr<EventLoop> pi2_event_loop =
1582 log_reader_factory.MakeEventLoop("test", pi2);
1583
1584 int pi1_ping_count = 30;
1585 int pi2_ping_count = 30;
1586 int pi1_pong_count = 30;
1587 int pi2_pong_count = 30;
1588
1589 // Confirm that the ping value matches.
1590 pi1_event_loop->MakeWatcher(
1591 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1592 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1593 << pi1_event_loop->context().monotonic_remote_time << " -> "
1594 << pi1_event_loop->context().monotonic_event_time;
1595 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1596
1597 ++pi1_ping_count;
1598 });
1599 pi2_event_loop->MakeWatcher(
1600 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1601 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1602 << pi2_event_loop->context().monotonic_remote_time << " -> "
1603 << pi2_event_loop->context().monotonic_event_time;
1604 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1605
1606 ++pi2_ping_count;
1607 });
1608
1609 // Confirm that the ping and pong counts both match, and the value also
1610 // matches.
1611 pi1_event_loop->MakeWatcher(
1612 "/test", [&pi1_event_loop, &pi1_ping_count,
1613 &pi1_pong_count](const examples::Pong &pong) {
1614 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1615 << pi1_event_loop->context().monotonic_remote_time << " -> "
1616 << pi1_event_loop->context().monotonic_event_time;
1617
1618 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1619 ++pi1_pong_count;
1620 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1621 });
1622 pi2_event_loop->MakeWatcher(
1623 "/test", [&pi2_event_loop, &pi2_ping_count,
1624 &pi2_pong_count](const examples::Pong &pong) {
1625 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1626 << pi2_event_loop->context().monotonic_remote_time << " -> "
1627 << pi2_event_loop->context().monotonic_event_time;
1628
1629 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1630 ++pi2_pong_count;
1631 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1632 });
1633
1634 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001635 EXPECT_EQ(pi1_ping_count, 6030);
1636 EXPECT_EQ(pi2_ping_count, 6030);
1637 EXPECT_EQ(pi1_pong_count, 6030);
1638 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001639
1640 reader.Deregister();
1641}
1642
Austin Schuh5212cad2020-09-09 23:12:09 -07001643// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001644TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001645 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001646 // Make a bunch of parts.
1647 {
1648 LoggerState pi1_logger = MakeLogger(pi1_);
1649 LoggerState pi2_logger = MakeLogger(pi2_);
1650
1651 event_loop_factory_.RunFor(chrono::milliseconds(95));
1652
1653 StartLogger(&pi1_logger);
1654 StartLogger(&pi2_logger);
1655
1656 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1657 }
1658
Austin Schuh11d43732020-09-21 17:28:30 -07001659 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001660 VerifyParts(sorted_parts);
1661}
Austin Schuh11d43732020-09-21 17:28:30 -07001662
Austin Schuh3bd4c402020-11-06 18:19:06 -08001663// Tests that we can sort a bunch of parts with an empty part. We should ignore
1664// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001665TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001666 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001667 // Make a bunch of parts.
1668 {
1669 LoggerState pi1_logger = MakeLogger(pi1_);
1670 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001671
Austin Schuh3bd4c402020-11-06 18:19:06 -08001672 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001673
Austin Schuh3bd4c402020-11-06 18:19:06 -08001674 StartLogger(&pi1_logger);
1675 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001676
Austin Schuh3bd4c402020-11-06 18:19:06 -08001677 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001678 }
1679
Austin Schuh3bd4c402020-11-06 18:19:06 -08001680 // TODO(austin): Should we flip out if the file can't open?
1681 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001682
Austin Schuh3bd4c402020-11-06 18:19:06 -08001683 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1684 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001685
Austin Schuh3bd4c402020-11-06 18:19:06 -08001686 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1687 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001688}
1689
Austin Schuh3bd4c402020-11-06 18:19:06 -08001690#ifdef LZMA
1691// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1692// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001693TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001694 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001695 // Make a bunch of parts.
1696 {
1697 LoggerState pi1_logger = MakeLogger(pi1_);
1698 LoggerState pi2_logger = MakeLogger(pi2_);
1699
1700 event_loop_factory_.RunFor(chrono::milliseconds(95));
1701
1702 StartLogger(&pi1_logger, "", true);
1703 StartLogger(&pi2_logger, "", true);
1704
1705 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1706 }
1707
1708 // TODO(austin): Should we flip out if the file can't open?
1709 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1710
1711 AddExtension(".xz");
1712
1713 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1714 logfiles_.emplace_back(kEmptyFile);
1715
1716 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1717 VerifyParts(sorted_parts, {kEmptyFile});
1718}
1719
1720// Tests that we can sort a bunch of parts with the end missing off a compressed
1721// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001722TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001723 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001724 // Make a bunch of parts.
1725 {
1726 LoggerState pi1_logger = MakeLogger(pi1_);
1727 LoggerState pi2_logger = MakeLogger(pi2_);
1728
1729 event_loop_factory_.RunFor(chrono::milliseconds(95));
1730
1731 StartLogger(&pi1_logger, "", true);
1732 StartLogger(&pi2_logger, "", true);
1733
1734 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1735 }
1736
1737 // Append everything with .xz.
1738 AddExtension(".xz");
1739
1740 // Strip off the end of one of the files. Pick one with a lot of data.
1741 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001742 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001743
1744 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001745 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001746 compressed_contents.substr(0, compressed_contents.size() - 100));
1747
1748 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1749 VerifyParts(sorted_parts);
1750}
1751#endif
1752
Austin Schuh01b4c352020-09-21 23:09:39 -07001753// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001754TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001755 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001756 {
1757 LoggerState pi1_logger = MakeLogger(pi1_);
1758 LoggerState pi2_logger = MakeLogger(pi2_);
1759
1760 event_loop_factory_.RunFor(chrono::milliseconds(95));
1761
1762 StartLogger(&pi1_logger);
1763 StartLogger(&pi2_logger);
1764
1765 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1766 }
1767
Austin Schuh287d43d2020-12-04 20:19:33 -08001768 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001769
1770 // Remap just on pi1.
1771 reader.RemapLoggedChannel<aos::timing::Report>(
1772 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1773
1774 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1775 log_reader_factory.set_send_delay(chrono::microseconds(0));
1776
1777 reader.Register(&log_reader_factory);
1778
1779 const Node *pi1 =
1780 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1781 const Node *pi2 =
1782 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1783
1784 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1785 // else should have moved.
1786 std::unique_ptr<EventLoop> pi1_event_loop =
1787 log_reader_factory.MakeEventLoop("test", pi1);
1788 pi1_event_loop->SkipTimingReport();
1789 std::unique_ptr<EventLoop> full_pi1_event_loop =
1790 log_reader_factory.MakeEventLoop("test", pi1);
1791 full_pi1_event_loop->SkipTimingReport();
1792 std::unique_ptr<EventLoop> pi2_event_loop =
1793 log_reader_factory.MakeEventLoop("test", pi2);
1794 pi2_event_loop->SkipTimingReport();
1795
1796 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1797 "/aos");
1798 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1799 full_pi1_event_loop.get(), "/pi1/aos");
1800 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1801 pi1_event_loop.get(), "/original/aos");
1802 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1803 full_pi1_event_loop.get(), "/original/pi1/aos");
1804 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1805 "/aos");
1806
1807 log_reader_factory.Run();
1808
1809 EXPECT_EQ(pi1_timing_report.count(), 0u);
1810 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1811 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1812 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1813 EXPECT_NE(pi2_timing_report.count(), 0u);
1814
1815 reader.Deregister();
1816}
1817
Austin Schuh006a9f52021-04-07 16:24:18 -07001818// Tests that we can remap a forwarded channel as well.
1819TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1820 time_converter_.StartEqual();
1821 {
1822 LoggerState pi1_logger = MakeLogger(pi1_);
1823 LoggerState pi2_logger = MakeLogger(pi2_);
1824
1825 event_loop_factory_.RunFor(chrono::milliseconds(95));
1826
1827 StartLogger(&pi1_logger);
1828 StartLogger(&pi2_logger);
1829
1830 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1831 }
1832
1833 LogReader reader(SortParts(logfiles_));
1834
1835 reader.RemapLoggedChannel<examples::Ping>("/test");
1836
1837 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1838 log_reader_factory.set_send_delay(chrono::microseconds(0));
1839
1840 reader.Register(&log_reader_factory);
1841
1842 const Node *pi1 =
1843 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1844 const Node *pi2 =
1845 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1846
1847 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1848 // else should have moved.
1849 std::unique_ptr<EventLoop> pi1_event_loop =
1850 log_reader_factory.MakeEventLoop("test", pi1);
1851 pi1_event_loop->SkipTimingReport();
1852 std::unique_ptr<EventLoop> full_pi1_event_loop =
1853 log_reader_factory.MakeEventLoop("test", pi1);
1854 full_pi1_event_loop->SkipTimingReport();
1855 std::unique_ptr<EventLoop> pi2_event_loop =
1856 log_reader_factory.MakeEventLoop("test", pi2);
1857 pi2_event_loop->SkipTimingReport();
1858
1859 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1860 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1861 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1862 "/original/test");
1863 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1864 "/original/test");
1865
1866 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1867 pi1_original_ping_timestamp;
1868 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1869 pi1_ping_timestamp;
1870 if (!shared()) {
1871 pi1_original_ping_timestamp =
1872 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1873 pi1_event_loop.get(),
1874 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1875 pi1_ping_timestamp =
1876 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1877 pi1_event_loop.get(),
1878 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1879 }
1880
1881 log_reader_factory.Run();
1882
1883 EXPECT_EQ(pi1_ping.count(), 0u);
1884 EXPECT_EQ(pi2_ping.count(), 0u);
1885 EXPECT_NE(pi1_original_ping.count(), 0u);
1886 EXPECT_NE(pi2_original_ping.count(), 0u);
1887 if (!shared()) {
1888 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1889 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1890 }
1891
1892 reader.Deregister();
1893}
1894
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001895// Tests that we properly recreate forwarded timestamps when replaying a log.
1896// This should be enough that we can then re-run the logger and get a valid log
1897// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001898TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001899 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001900 {
1901 LoggerState pi1_logger = MakeLogger(pi1_);
1902 LoggerState pi2_logger = MakeLogger(pi2_);
1903
1904 event_loop_factory_.RunFor(chrono::milliseconds(95));
1905
1906 StartLogger(&pi1_logger);
1907 StartLogger(&pi2_logger);
1908
1909 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1910 }
1911
Austin Schuh287d43d2020-12-04 20:19:33 -08001912 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001913
1914 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1915 log_reader_factory.set_send_delay(chrono::microseconds(0));
1916
1917 // This sends out the fetched messages and advances time to the start of the
1918 // log file.
1919 reader.Register(&log_reader_factory);
1920
1921 const Node *pi1 =
1922 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1923 const Node *pi2 =
1924 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1925
1926 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1927 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1928 LOG(INFO) << "now pi1 "
1929 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1930 LOG(INFO) << "now pi2 "
1931 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1932
Austin Schuh07676622021-01-21 18:59:17 -08001933 EXPECT_THAT(reader.LoggedNodes(),
1934 ::testing::ElementsAre(
1935 configuration::GetNode(reader.logged_configuration(), pi1),
1936 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001937
1938 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1939
1940 std::unique_ptr<EventLoop> pi1_event_loop =
1941 log_reader_factory.MakeEventLoop("test", pi1);
1942 std::unique_ptr<EventLoop> pi2_event_loop =
1943 log_reader_factory.MakeEventLoop("test", pi2);
1944
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001945 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1946 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1947 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1948 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1949
1950 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1951 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1952 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1953 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1954
1955 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1956 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1957 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1958 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1959
1960 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1961 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1962 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1963 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1964
1965 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1966 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1967 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1968 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1969
1970 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1971 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1972 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1973 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1974
Austin Schuh969cd602021-01-03 00:09:45 -08001975 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001976 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001977
Austin Schuh61e973f2021-02-21 21:43:56 -08001978 for (std::pair<int, std::string> channel :
1979 shared()
1980 ? std::vector<
1981 std::pair<int, std::string>>{{-1,
1982 "/aos/remote_timestamps/pi2"}}
1983 : std::vector<std::pair<int, std::string>>{
1984 {pi1_timestamp_channel,
1985 "/aos/remote_timestamps/pi2/pi1/aos/"
1986 "aos-message_bridge-Timestamp"},
1987 {ping_timestamp_channel,
1988 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1989 pi1_event_loop->MakeWatcher(
1990 channel.second,
1991 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1992 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1993 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1994 &ping_on_pi2_fetcher, network_delay, send_delay,
1995 channel_index = channel.first](const RemoteMessage &header) {
1996 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1997 chrono::nanoseconds(header.monotonic_sent_time()));
1998 const aos::realtime_clock::time_point header_realtime_sent_time(
1999 chrono::nanoseconds(header.realtime_sent_time()));
2000 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2001 chrono::nanoseconds(header.monotonic_remote_time()));
2002 const aos::realtime_clock::time_point header_realtime_remote_time(
2003 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002004
Austin Schuh61e973f2021-02-21 21:43:56 -08002005 if (channel_index != -1) {
2006 ASSERT_EQ(channel_index, header.channel_index());
2007 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002008
Austin Schuh61e973f2021-02-21 21:43:56 -08002009 const Context *pi1_context = nullptr;
2010 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002011
Austin Schuh61e973f2021-02-21 21:43:56 -08002012 if (header.channel_index() == pi1_timestamp_channel) {
2013 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2014 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2015 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2016 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2017 } else if (header.channel_index() == ping_timestamp_channel) {
2018 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2019 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2020 pi1_context = &ping_on_pi1_fetcher.context();
2021 pi2_context = &ping_on_pi2_fetcher.context();
2022 } else {
2023 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2024 << configuration::CleanedChannelToString(
2025 pi1_event_loop->configuration()->channels()->Get(
2026 header.channel_index()));
2027 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002028
Austin Schuh61e973f2021-02-21 21:43:56 -08002029 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002030 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2031 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002032
Austin Schuh61e973f2021-02-21 21:43:56 -08002033 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2034 EXPECT_EQ(pi2_context->remote_queue_index,
2035 header.remote_queue_index());
2036 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002037
Austin Schuh61e973f2021-02-21 21:43:56 -08002038 EXPECT_EQ(pi2_context->monotonic_event_time,
2039 header_monotonic_sent_time);
2040 EXPECT_EQ(pi2_context->realtime_event_time,
2041 header_realtime_sent_time);
2042 EXPECT_EQ(pi2_context->realtime_remote_time,
2043 header_realtime_remote_time);
2044 EXPECT_EQ(pi2_context->monotonic_remote_time,
2045 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002046
Austin Schuh61e973f2021-02-21 21:43:56 -08002047 EXPECT_EQ(pi1_context->realtime_event_time,
2048 header_realtime_remote_time);
2049 EXPECT_EQ(pi1_context->monotonic_event_time,
2050 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002051
Austin Schuh61e973f2021-02-21 21:43:56 -08002052 // Time estimation isn't perfect, but we know the clocks were
2053 // identical when logged, so we know when this should have come back.
2054 // Confirm we got it when we expected.
2055 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2056 pi1_context->monotonic_event_time + 2 * network_delay +
2057 send_delay);
2058 });
2059 }
2060 for (std::pair<int, std::string> channel :
2061 shared()
2062 ? std::vector<
2063 std::pair<int, std::string>>{{-1,
2064 "/aos/remote_timestamps/pi1"}}
2065 : std::vector<std::pair<int, std::string>>{
2066 {pi2_timestamp_channel,
2067 "/aos/remote_timestamps/pi1/pi2/aos/"
2068 "aos-message_bridge-Timestamp"}}) {
2069 pi2_event_loop->MakeWatcher(
2070 channel.second,
2071 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2072 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2073 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2074 &pong_on_pi1_fetcher, network_delay, send_delay,
2075 channel_index = channel.first](const RemoteMessage &header) {
2076 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2077 chrono::nanoseconds(header.monotonic_sent_time()));
2078 const aos::realtime_clock::time_point header_realtime_sent_time(
2079 chrono::nanoseconds(header.realtime_sent_time()));
2080 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2081 chrono::nanoseconds(header.monotonic_remote_time()));
2082 const aos::realtime_clock::time_point header_realtime_remote_time(
2083 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002084
Austin Schuh61e973f2021-02-21 21:43:56 -08002085 if (channel_index != -1) {
2086 ASSERT_EQ(channel_index, header.channel_index());
2087 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002088
Austin Schuh61e973f2021-02-21 21:43:56 -08002089 const Context *pi2_context = nullptr;
2090 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002091
Austin Schuh61e973f2021-02-21 21:43:56 -08002092 if (header.channel_index() == pi2_timestamp_channel) {
2093 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2094 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2095 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2096 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2097 } else if (header.channel_index() == pong_timestamp_channel) {
2098 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2099 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2100 pi2_context = &pong_on_pi2_fetcher.context();
2101 pi1_context = &pong_on_pi1_fetcher.context();
2102 } else {
2103 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2104 << configuration::CleanedChannelToString(
2105 pi2_event_loop->configuration()->channels()->Get(
2106 header.channel_index()));
2107 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002108
Austin Schuh61e973f2021-02-21 21:43:56 -08002109 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002110 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2111 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002112
Austin Schuh61e973f2021-02-21 21:43:56 -08002113 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2114 EXPECT_EQ(pi1_context->remote_queue_index,
2115 header.remote_queue_index());
2116 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002117
Austin Schuh61e973f2021-02-21 21:43:56 -08002118 EXPECT_EQ(pi1_context->monotonic_event_time,
2119 header_monotonic_sent_time);
2120 EXPECT_EQ(pi1_context->realtime_event_time,
2121 header_realtime_sent_time);
2122 EXPECT_EQ(pi1_context->realtime_remote_time,
2123 header_realtime_remote_time);
2124 EXPECT_EQ(pi1_context->monotonic_remote_time,
2125 header_monotonic_remote_time);
2126
2127 EXPECT_EQ(pi2_context->realtime_event_time,
2128 header_realtime_remote_time);
2129 EXPECT_EQ(pi2_context->monotonic_event_time,
2130 header_monotonic_remote_time);
2131
2132 // Time estimation isn't perfect, but we know the clocks were
2133 // identical when logged, so we know when this should have come back.
2134 // Confirm we got it when we expected.
2135 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2136 pi2_context->monotonic_event_time + 2 * network_delay +
2137 send_delay);
2138 });
2139 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002140
2141 // And confirm we can re-create a log again, while checking the contents.
2142 {
2143 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002144 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002145 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002146 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002147
Austin Schuh25b46712021-01-03 00:04:38 -08002148 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2149 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002150
2151 log_reader_factory.Run();
2152 }
2153
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002154 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002155
2156 // And verify that we can run the LogReader over the relogged files without
2157 // hitting any fatal errors.
2158 {
2159 LogReader relogged_reader(SortParts(
2160 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2161 relogged_reader.Register();
2162
2163 relogged_reader.event_loop_factory()->Run();
2164 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002165}
2166
Austin Schuh315b96b2020-12-11 21:21:12 -08002167// Tests that we properly populate and extract the logger_start time by setting
2168// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002169TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002170 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002171 {BootTimestamp::epoch(),
2172 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002173 {
2174 LoggerState pi1_logger = MakeLogger(pi1_);
2175 LoggerState pi2_logger = MakeLogger(pi2_);
2176
Austin Schuh315b96b2020-12-11 21:21:12 -08002177 StartLogger(&pi1_logger);
2178 StartLogger(&pi2_logger);
2179
2180 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2181 }
2182
2183 for (const LogFile &log_file : SortParts(logfiles_)) {
2184 for (const LogParts &log_part : log_file.parts) {
2185 if (log_part.node == log_file.logger_node) {
2186 EXPECT_EQ(log_part.logger_monotonic_start_time,
2187 aos::monotonic_clock::min_time);
2188 EXPECT_EQ(log_part.logger_realtime_start_time,
2189 aos::realtime_clock::min_time);
2190 } else {
2191 const chrono::seconds offset = log_file.logger_node == "pi1"
2192 ? -chrono::seconds(1000)
2193 : chrono::seconds(1000);
2194 EXPECT_EQ(log_part.logger_monotonic_start_time,
2195 log_part.monotonic_start_time + offset);
2196 EXPECT_EQ(log_part.logger_realtime_start_time,
2197 log_file.realtime_start_time +
2198 (log_part.logger_monotonic_start_time -
2199 log_file.monotonic_start_time));
2200 }
2201 }
2202 }
2203}
2204
Austin Schuh6bb8a822021-03-31 23:04:39 -07002205// Test that renaming the base, renames the folder.
2206TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002207 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2208 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002209 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002210 {BootTimestamp::epoch(),
2211 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002212 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2213 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2214 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2215 LoggerState pi1_logger = MakeLogger(pi1_);
2216 LoggerState pi2_logger = MakeLogger(pi2_);
2217
2218 StartLogger(&pi1_logger);
2219 StartLogger(&pi2_logger);
2220
2221 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2222 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2223 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2224 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2225 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2226 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2227 for (auto &file : logfiles_) {
2228 struct stat s;
2229 EXPECT_EQ(0, stat(file.c_str(), &s));
2230 }
2231}
2232
2233// Test that renaming the file base dies.
2234TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2235 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002236 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002237 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002238 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2239 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2240 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2241 LoggerState pi1_logger = MakeLogger(pi1_);
2242 StartLogger(&pi1_logger);
2243 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2244 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2245 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2246 "Rename of file base from");
2247}
2248
Austin Schuh8bd96322020-02-13 21:18:22 -08002249// TODO(austin): We can write a test which recreates a logfile and confirms that
2250// we get it back. That is the ultimate test.
2251
Austin Schuh315b96b2020-12-11 21:21:12 -08002252// Tests that we properly recreate forwarded timestamps when replaying a log.
2253// This should be enough that we can then re-run the logger and get a valid log
2254// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002255TEST_P(MultinodeLoggerTest, RemoteReboot) {
2256 const UUID pi1_boot0 = UUID::Random();
2257 const UUID pi2_boot0 = UUID::Random();
2258 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002259 {
Austin Schuh58646e22021-08-23 23:51:46 -07002260 CHECK_EQ(pi1_index_, 0u);
2261 CHECK_EQ(pi2_index_, 1u);
2262
2263 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2264 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2265 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2266
2267 time_converter_.AddNextTimestamp(
2268 distributed_clock::epoch(),
2269 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2270 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2271 time_converter_.AddNextTimestamp(
2272 distributed_clock::epoch() + reboot_time,
2273 {BootTimestamp::epoch() + reboot_time,
2274 BootTimestamp{
2275 .boot = 1,
2276 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2277 }
2278
2279 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002280 LoggerState pi1_logger = MakeLogger(pi1_);
2281
2282 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002283 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2284 pi1_boot0);
2285 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2286 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002287
2288 StartLogger(&pi1_logger);
2289
2290 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2291
Austin Schuh58646e22021-08-23 23:51:46 -07002292 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002293
2294 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002295 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2296 pi1_boot0);
2297 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2298 pi2_boot1);
Austin Schuh315b96b2020-12-11 21:21:12 -08002299 }
2300
Austin Schuh72211ae2021-08-05 14:02:30 -07002301 // Confirm that our new oldest timestamps properly update as we reboot and
2302 // rotate.
2303 for (const std::string &file : pi1_reboot_logfiles_) {
2304 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2305 ReadHeader(file);
2306 CHECK(log_header);
2307 if (log_header->message().has_configuration()) {
2308 continue;
2309 }
2310
Austin Schuh58646e22021-08-23 23:51:46 -07002311 const monotonic_clock::time_point monotonic_start_time =
2312 monotonic_clock::time_point(
2313 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2314 const UUID source_node_boot_uuid = UUID::FromString(
2315 log_header->message().source_node_boot_uuid()->string_view());
2316
Austin Schuh72211ae2021-08-05 14:02:30 -07002317 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh58646e22021-08-23 23:51:46 -07002318 switch (log_header->message().parts_index()) {
2319 case 0:
2320 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2321 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2322 break;
2323 case 1:
2324 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2325 ASSERT_EQ(monotonic_start_time,
2326 monotonic_clock::epoch() + chrono::seconds(1));
2327 break;
2328 case 2:
2329 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2330 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2331 break;
2332 case 3:
2333 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2334 ASSERT_EQ(monotonic_start_time,
2335 monotonic_clock::epoch() + chrono::nanoseconds(2322999462));
2336 break;
2337 default:
2338 FAIL();
2339 break;
2340 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002341 continue;
2342 }
2343 SCOPED_TRACE(file);
2344 SCOPED_TRACE(aos::FlatbufferToJson(
2345 *log_header, {.multi_line = true, .max_vector_size = 100}));
2346 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2347 ASSERT_EQ(
2348 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2349 EXPECT_EQ(
2350 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2351 monotonic_clock::max_time.time_since_epoch().count());
2352 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2353 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2354 2u);
2355 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2356 monotonic_clock::max_time.time_since_epoch().count());
2357 ASSERT_TRUE(log_header->message()
2358 .has_oldest_remote_unreliable_monotonic_timestamps());
2359 ASSERT_EQ(log_header->message()
2360 .oldest_remote_unreliable_monotonic_timestamps()
2361 ->size(),
2362 2u);
2363 EXPECT_EQ(log_header->message()
2364 .oldest_remote_unreliable_monotonic_timestamps()
2365 ->Get(0),
2366 monotonic_clock::max_time.time_since_epoch().count());
2367 ASSERT_TRUE(log_header->message()
2368 .has_oldest_local_unreliable_monotonic_timestamps());
2369 ASSERT_EQ(log_header->message()
2370 .oldest_local_unreliable_monotonic_timestamps()
2371 ->size(),
2372 2u);
2373 EXPECT_EQ(log_header->message()
2374 .oldest_local_unreliable_monotonic_timestamps()
2375 ->Get(0),
2376 monotonic_clock::max_time.time_since_epoch().count());
2377
2378 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2379 monotonic_clock::time_point(chrono::nanoseconds(
2380 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2381 1)));
2382 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2383 monotonic_clock::time_point(chrono::nanoseconds(
2384 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2385 const monotonic_clock::time_point
2386 oldest_remote_unreliable_monotonic_timestamps =
2387 monotonic_clock::time_point(chrono::nanoseconds(
2388 log_header->message()
2389 .oldest_remote_unreliable_monotonic_timestamps()
2390 ->Get(1)));
2391 const monotonic_clock::time_point
2392 oldest_local_unreliable_monotonic_timestamps =
2393 monotonic_clock::time_point(chrono::nanoseconds(
2394 log_header->message()
2395 .oldest_local_unreliable_monotonic_timestamps()
2396 ->Get(1)));
2397 switch (log_header->message().parts_index()) {
2398 case 0:
2399 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2400 monotonic_clock::max_time);
2401 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2402 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2403 monotonic_clock::max_time);
2404 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2405 monotonic_clock::max_time);
2406 break;
2407 case 1:
2408 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2409 monotonic_clock::time_point(chrono::microseconds(90200)));
2410 EXPECT_EQ(oldest_local_monotonic_timestamps,
2411 monotonic_clock::time_point(chrono::microseconds(90350)));
2412 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2413 monotonic_clock::time_point(chrono::microseconds(90200)));
2414 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2415 monotonic_clock::time_point(chrono::microseconds(90350)));
2416 break;
2417 case 2:
2418 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002419 monotonic_clock::time_point(chrono::milliseconds(1323) +
2420 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002421 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002422 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002423 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002424 monotonic_clock::time_point(chrono::milliseconds(1323) +
2425 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002426 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2427 monotonic_clock::time_point(chrono::microseconds(10100350)));
2428 break;
2429 default:
2430 FAIL();
2431 break;
2432 }
2433 }
2434
Austin Schuh315b96b2020-12-11 21:21:12 -08002435 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002436 {
2437 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002438
Austin Schuh58646e22021-08-23 23:51:46 -07002439 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2440 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002441
Austin Schuh58646e22021-08-23 23:51:46 -07002442 // This sends out the fetched messages and advances time to the start of
2443 // the log file.
2444 reader.Register(&log_reader_factory);
2445
2446 log_reader_factory.Run();
2447
2448 reader.Deregister();
2449 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002450}
2451
Austin Schuhc9049732020-12-21 22:27:15 -08002452// Tests that we properly handle one direction of message_bridge being
2453// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002454TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002455 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002456 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002457 {BootTimestamp::epoch(),
2458 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002459
2460 time_converter_.AddMonotonic(
2461 {chrono::milliseconds(10000),
2462 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002463 {
2464 LoggerState pi1_logger = MakeLogger(pi1_);
2465
2466 event_loop_factory_.RunFor(chrono::milliseconds(95));
2467
2468 StartLogger(&pi1_logger);
2469
2470 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2471 }
2472
2473 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2474 // to confirm the right thing happened.
2475 ConfirmReadable(pi1_single_direction_logfiles_);
2476}
2477
2478// Tests that we properly handle one direction of message_bridge being
2479// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002480TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002481 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002482 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002483 {BootTimestamp::epoch(),
2484 BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002485
2486 time_converter_.AddMonotonic(
2487 {chrono::milliseconds(10000),
2488 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2489 {
2490 LoggerState pi1_logger = MakeLogger(pi1_);
2491
2492 event_loop_factory_.RunFor(chrono::milliseconds(95));
2493
2494 StartLogger(&pi1_logger);
2495
2496 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2497 }
2498
2499 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2500 // to confirm the right thing happened.
2501 ConfirmReadable(pi1_single_direction_logfiles_);
2502}
2503
Austin Schuhe9f00232021-09-16 18:04:23 -07002504// Tests that we explode if someone passes in a part file twice with a better
2505// error than an out of order error.
2506TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2507 time_converter_.AddMonotonic(
2508 {BootTimestamp::epoch(),
2509 BootTimestamp::epoch() + chrono::seconds(1000)});
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 std::vector<std::string> duplicates;
2521 for (const std::string &f : pi1_single_direction_logfiles_) {
2522 duplicates.emplace_back(f);
2523 duplicates.emplace_back(f);
2524 }
2525 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
2526}
2527
Austin Schuh87dd3832021-01-01 23:07:31 -08002528// Tests that we properly handle a dead node. Do this by just disconnecting it
2529// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002530TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07002531 pi1_->Disconnect(pi2_->node());
2532 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002533 time_converter_.AddMonotonic(
Austin Schuh66168842021-08-17 19:42:21 -07002534 {BootTimestamp::epoch(),
2535 BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002536 {
2537 LoggerState pi1_logger = MakeLogger(pi1_);
2538
2539 event_loop_factory_.RunFor(chrono::milliseconds(95));
2540
2541 StartLogger(&pi1_logger);
2542
2543 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2544 }
2545
2546 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2547 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002548 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002549}
2550
Austin Schuhcdd90272021-03-15 12:46:16 -07002551constexpr std::string_view kCombinedConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002552 "cad3b6838a518ab29470771a959b89945ee034bc7a738080fd1713a1dce51b1f");
Austin Schuhcdd90272021-03-15 12:46:16 -07002553constexpr std::string_view kSplitConfigSha1(
Austin Schuh5f79a5a2021-10-12 17:46:50 -07002554 "aafdd7e43d1942cce5b3e2dd8c6b9706abf7068a43501625a33b7cdfddf6c932");
Austin Schuhcdd90272021-03-15 12:46:16 -07002555
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002556INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002557 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002558 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2559 kCombinedConfigSha1},
2560 Param{"multinode_pingpong_split_config.json", false,
2561 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002562
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002563INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002564 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002565 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2566 kCombinedConfigSha1},
2567 Param{"multinode_pingpong_split_config.json", false,
2568 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002569
Austin Schuh5b728b72021-06-16 14:57:15 -07002570// Tests that we can relog with a different config. This makes most sense when
2571// you are trying to edit a log and want to use channel renaming + the original
2572// config in the new log.
2573TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
2574 time_converter_.StartEqual();
2575 {
2576 LoggerState pi1_logger = MakeLogger(pi1_);
2577 LoggerState pi2_logger = MakeLogger(pi2_);
2578
2579 event_loop_factory_.RunFor(chrono::milliseconds(95));
2580
2581 StartLogger(&pi1_logger);
2582 StartLogger(&pi2_logger);
2583
2584 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2585 }
2586
2587 LogReader reader(SortParts(logfiles_));
2588 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
2589
2590 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2591 log_reader_factory.set_send_delay(chrono::microseconds(0));
2592
2593 // This sends out the fetched messages and advances time to the start of the
2594 // log file.
2595 reader.Register(&log_reader_factory);
2596
2597 const Node *pi1 =
2598 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2599 const Node *pi2 =
2600 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2601
2602 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2603 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2604 LOG(INFO) << "now pi1 "
2605 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2606 LOG(INFO) << "now pi2 "
2607 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2608
2609 EXPECT_THAT(reader.LoggedNodes(),
2610 ::testing::ElementsAre(
2611 configuration::GetNode(reader.logged_configuration(), pi1),
2612 configuration::GetNode(reader.logged_configuration(), pi2)));
2613
2614 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2615
2616 // And confirm we can re-create a log again, while checking the contents.
2617 std::vector<std::string> log_files;
2618 {
2619 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002620 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002621 &log_reader_factory, reader.logged_configuration());
2622 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002623 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002624 &log_reader_factory, reader.logged_configuration());
2625
2626 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2627 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
2628
2629 log_reader_factory.Run();
2630
2631 for (auto &x : pi1_logger.log_namer->all_filenames()) {
2632 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
2633 }
2634 for (auto &x : pi2_logger.log_namer->all_filenames()) {
2635 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
2636 }
2637 }
2638
2639 reader.Deregister();
2640
2641 // And verify that we can run the LogReader over the relogged files without
2642 // hitting any fatal errors.
2643 {
2644 LogReader relogged_reader(SortParts(log_files));
2645 relogged_reader.Register();
2646
2647 relogged_reader.event_loop_factory()->Run();
2648 }
2649}
Austin Schuha04efed2021-01-24 18:04:20 -08002650
Austin Schuhe309d2a2019-11-29 13:25:21 -08002651} // namespace testing
2652} // namespace logger
2653} // namespace aos