blob: ec7ed10b8032f88eed1a7e8042357c6f6c08cfd0 [file] [log] [blame]
Austin Schuh6bb8a822021-03-31 23:04:39 -07001#include <sys/stat.h>
2
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07005#include "aos/events/logging/log_reader.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08006#include "aos/events/logging/log_writer.h"
milind1f1dca32021-07-03 13:50:07 -07007#include "aos/events/logging/snappy_encoder.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));
milind1f1dca32021-07-03 13:50:07 -0700171 logger_event_loop->OnRun([base_name1, base_name2, &logger_event_loop,
172 &logger]() {
173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
175 EXPECT_DEATH(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 logger.StartLogging(std::make_unique<LocalLogNamer>(
milind1f1dca32021-07-03 13:50:07 -0700177 base_name2, logger_event_loop.get(), logger_event_loop->node())),
178 "Already logging");
179 });
Brian Silverman1f345222020-09-24 21:14:48 -0700180 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>();
Austin Schuhbfe6c572022-01-27 20:48:20 -0800401 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800402 });
403
404 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
405 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
406 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
407 chrono::microseconds(50));
408 });
409
Brian Silverman1f345222020-09-24 21:14:48 -0700410 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800411 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700412 logger.set_polling_period(std::chrono::milliseconds(100));
413 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800414
415 event_loop_factory_.RunFor(chrono::milliseconds(1000));
416 }
417}
418
James Kuszmauldd0a5042021-10-28 23:38:04 -0700419struct CompressionParams {
420 std::string_view extension;
421 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
422};
423
424std::ostream &operator<<(std::ostream &ostream,
425 const CompressionParams &params) {
426 ostream << "\"" << params.extension << "\"";
427 return ostream;
428}
429
430std::vector<CompressionParams> SupportedCompressionAlgorithms() {
431 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
432 {SnappyDecoder::kExtension,
433 []() { return std::make_unique<SnappyEncoder>(); }},
434#ifdef LZMA
435 {LzmaDecoder::kExtension,
436 []() { return std::make_unique<LzmaEncoder>(3); }}
437#endif // LZMA
438 };
439}
440
Austin Schuh61e973f2021-02-21 21:43:56 -0800441// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700442struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800443 // The config file to use.
444 std::string config;
445 // If true, the RemoteMessage channel should be shared between all the remote
446 // channels. If false, there will be 1 RemoteMessage channel per remote
447 // channel.
448 bool shared;
449 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700450 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800451};
Austin Schuh315b96b2020-12-11 21:21:12 -0800452
James Kuszmauldd0a5042021-10-28 23:38:04 -0700453std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
454 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
455 << ", sha256: \"" << params.sha256 << "\"}";
456 return ostream;
457}
458
Austin Schuh3e20c692021-11-16 20:43:16 -0800459struct LoggerState {
460 static LoggerState MakeLogger(NodeEventLoopFactory *node,
461 SimulatedEventLoopFactory *factory,
462 CompressionParams params,
463 const Configuration *configuration = nullptr) {
464 if (configuration == nullptr) {
465 configuration = factory->configuration();
466 }
467 return {node->MakeEventLoop("logger"),
468 {},
469 configuration,
470 configuration::GetNode(configuration, node->node()),
471 nullptr,
472 params};
473 }
474
475 void StartLogger(std::string logfile_base) {
476 CHECK(!logfile_base.empty());
477
478 logger = std::make_unique<Logger>(event_loop.get(), configuration);
479 logger->set_polling_period(std::chrono::milliseconds(100));
480 logger->set_name(
481 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
482 event_loop->OnRun([this, logfile_base]() {
483 std::unique_ptr<MultiNodeLogNamer> namer =
484 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
485 event_loop.get(), node);
486 namer->set_extension(params.extension);
487 namer->set_encoder_factory(params.encoder_factory);
488 log_namer = namer.get();
489
490 logger->StartLogging(std::move(namer));
491 });
492 }
493
494 std::unique_ptr<EventLoop> event_loop;
495 std::unique_ptr<Logger> logger;
496 const Configuration *configuration;
497 const Node *node;
498 MultiNodeLogNamer *log_namer;
499 CompressionParams params;
500
501 void AppendAllFilenames(std::vector<std::string> *filenames) {
502 for (const std::string &file : log_namer->all_filenames()) {
503 const std::string_view separator =
504 log_namer->base_name().back() == '/' ? "" : "_";
505 filenames->emplace_back(
506 absl::StrCat(log_namer->base_name(), separator, file));
507 }
508 }
509
510 ~LoggerState() {
511 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800512 std::vector<std::string> filenames;
513 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800514 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800515 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800516 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800517 auto x = ReadHeader(file);
518 if (x) {
519 VLOG(1) << aos::FlatbufferToJson(x.value());
520 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800521 }
522 }
523 }
524};
525
Austin Schuhe33c08d2022-02-03 18:15:21 -0800526std::vector<std::pair<std::vector<realtime_clock::time_point>,
527 std::vector<realtime_clock::time_point>>>
528ConfirmReadable(
529 const std::vector<std::string> &files,
530 realtime_clock::time_point start_time = realtime_clock::min_time,
531 realtime_clock::time_point end_time = realtime_clock::max_time) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800532 {
533 LogReader reader(SortParts(files));
534
535 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
536 reader.Register(&log_reader_factory);
537
538 log_reader_factory.Run();
539
540 reader.Deregister();
541 }
542 {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800543 std::vector<std::pair<std::vector<realtime_clock::time_point>,
544 std::vector<realtime_clock::time_point>>>
545 result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800546 LogReader reader(SortParts(files));
547
Austin Schuhe33c08d2022-02-03 18:15:21 -0800548 reader.SetStartTime(start_time);
549 reader.SetEndTime(end_time);
550
Austin Schuh3e20c692021-11-16 20:43:16 -0800551 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
552 reader.RegisterWithoutStarting(&log_reader_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -0800553 result.resize(
554 configuration::NodesCount(log_reader_factory.configuration()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800555 if (configuration::MultiNode(log_reader_factory.configuration())) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800556 size_t i = 0;
Austin Schuh3e20c692021-11-16 20:43:16 -0800557 for (const aos::Node *node :
558 *log_reader_factory.configuration()->nodes()) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800559 LOG(INFO) << "Registering start";
560 reader.OnStart(node, [node, &log_reader_factory, &result,
561 node_index = i]() {
Austin Schuh3e20c692021-11-16 20:43:16 -0800562 LOG(INFO) << "Starting " << node->name()->string_view();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800563 result[node_index].first.push_back(
564 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
Austin Schuh3e20c692021-11-16 20:43:16 -0800565 });
Austin Schuhe33c08d2022-02-03 18:15:21 -0800566 reader.OnEnd(node, [node, &log_reader_factory, &result,
567 node_index = i]() {
568 LOG(INFO) << "Ending " << node->name()->string_view();
569 result[node_index].second.push_back(
570 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
571 });
572 ++i;
Austin Schuh3e20c692021-11-16 20:43:16 -0800573 }
Austin Schuhe33c08d2022-02-03 18:15:21 -0800574 } else {
575 reader.OnStart([&log_reader_factory, &result]() {
576 LOG(INFO) << "Starting";
577 result[0].first.push_back(
578 log_reader_factory.GetNodeEventLoopFactory(nullptr)
579 ->realtime_now());
580 });
581 reader.OnEnd([&log_reader_factory, &result]() {
582 LOG(INFO) << "Ending";
583 result[0].second.push_back(
584 log_reader_factory.GetNodeEventLoopFactory(nullptr)
585 ->realtime_now());
586 });
Austin Schuh3e20c692021-11-16 20:43:16 -0800587 }
588
589 log_reader_factory.Run();
590
591 reader.Deregister();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800592
593 for (auto x : result) {
594 for (auto y : x.first) {
595 VLOG(1) << "Start " << y;
596 }
597 for (auto y : x.second) {
598 VLOG(1) << "End " << y;
599 }
600 }
601 return result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800602 }
603}
604
James Kuszmauldd0a5042021-10-28 23:38:04 -0700605class MultinodeLoggerTest : public ::testing::TestWithParam<
606 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800607 public:
608 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700609 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
610 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800611 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800612 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700613 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800614 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700615 event_loop_factory_.configuration(), pi1_->node())),
616 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800617 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700618 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800619 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800620 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
621 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800622 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800623 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800624 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700625 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700626 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800627 event_loop_factory_.SetTimeConverter(&time_converter_);
628
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700629 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700630 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700631 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800632 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700633 }
634
Austin Schuh268586b2021-03-31 22:24:39 -0700635 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800636 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800637 unlink(file.c_str());
638 }
639
Austin Schuh268586b2021-03-31 22:24:39 -0700640 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800641 unlink(file.c_str());
642 }
643
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700644 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
645 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700646
647 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
648 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700649 }
650
James Kuszmauldd0a5042021-10-28 23:38:04 -0700651 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800652
653 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700654 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800655 size_t pi1_data_count = 3,
656 size_t pi2_data_count = 3) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800657 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700658 result.emplace_back(absl::StrCat(
659 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
660 result.emplace_back(absl::StrCat(
661 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700662 for (size_t i = 0; i < pi1_data_count; ++i) {
663 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700664 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700665 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800666 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700667 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800668 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700669 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700670 for (size_t i = 0; i < pi2_data_count; ++i) {
671 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700672 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700673 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700674 result.emplace_back(logfile_base2 +
675 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
676 Extension());
677 result.emplace_back(logfile_base2 +
678 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
679 Extension());
680 result.emplace_back(logfile_base1 +
681 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
682 Extension());
683 result.emplace_back(logfile_base1 +
684 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
685 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800686 if (shared()) {
687 result.emplace_back(logfile_base1 +
688 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700689 "aos.message_bridge.RemoteMessage.part0" +
690 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800691 result.emplace_back(logfile_base1 +
692 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700693 "aos.message_bridge.RemoteMessage.part1" +
694 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800695 result.emplace_back(logfile_base1 +
696 "_timestamps/pi1/aos/remote_timestamps/pi2/"
697 "aos.message_bridge.RemoteMessage.part2" +
698 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800699 result.emplace_back(logfile_base2 +
700 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700701 "aos.message_bridge.RemoteMessage.part0" +
702 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800703 result.emplace_back(logfile_base2 +
704 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700705 "aos.message_bridge.RemoteMessage.part1" +
706 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800707 } else {
708 result.emplace_back(logfile_base1 +
709 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
710 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700711 "aos.message_bridge.RemoteMessage.part0" +
712 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800713 result.emplace_back(logfile_base1 +
714 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
715 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700716 "aos.message_bridge.RemoteMessage.part1" +
717 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800718 result.emplace_back(logfile_base2 +
719 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
720 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700721 "aos.message_bridge.RemoteMessage.part0" +
722 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800723 result.emplace_back(logfile_base2 +
724 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
725 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700726 "aos.message_bridge.RemoteMessage.part1" +
727 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800728 result.emplace_back(logfile_base1 +
729 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
730 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700731 "aos.message_bridge.RemoteMessage.part0" +
732 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800733 result.emplace_back(logfile_base1 +
734 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
735 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700736 "aos.message_bridge.RemoteMessage.part1" +
737 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800738 }
739
740 return result;
741 }
742
743 std::vector<std::string> MakePi1RebootLogfiles() {
744 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700745 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
746 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
747 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800748 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
749 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800750 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700751 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800752 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700753 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800754 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700755 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700756 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700757 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
758 result.emplace_back(logfile_base1_ +
759 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
760 Extension());
761 result.emplace_back(logfile_base1_ +
762 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
763 Extension());
764 result.emplace_back(logfile_base1_ +
765 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
766 Extension());
767 result.emplace_back(logfile_base1_ +
768 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
769 Extension());
770 result.emplace_back(absl::StrCat(
771 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800772 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800773 for (size_t i = 0; i < 6; ++i) {
774 result.emplace_back(
775 absl::StrCat(logfile_base1_,
776 "_timestamps/pi1/aos/remote_timestamps/pi2/"
777 "aos.message_bridge.RemoteMessage.part",
778 i, Extension()));
779 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800780 } else {
781 result.emplace_back(logfile_base1_ +
782 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
783 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700784 "aos.message_bridge.RemoteMessage.part0" +
785 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800786 result.emplace_back(logfile_base1_ +
787 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
788 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700789 "aos.message_bridge.RemoteMessage.part1" +
790 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800791 result.emplace_back(logfile_base1_ +
792 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
793 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700794 "aos.message_bridge.RemoteMessage.part2" +
795 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700796 result.emplace_back(logfile_base1_ +
797 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
798 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700799 "aos.message_bridge.RemoteMessage.part3" +
800 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800801
802 result.emplace_back(logfile_base1_ +
803 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
804 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700805 "aos.message_bridge.RemoteMessage.part0" +
806 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800807 result.emplace_back(logfile_base1_ +
808 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
809 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700810 "aos.message_bridge.RemoteMessage.part1" +
811 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800812 result.emplace_back(logfile_base1_ +
813 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
814 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700815 "aos.message_bridge.RemoteMessage.part2" +
816 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700817 result.emplace_back(logfile_base1_ +
818 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
819 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700820 "aos.message_bridge.RemoteMessage.part3" +
821 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800822 }
823 return result;
824 }
825
826 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
827 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700828 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
829 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
830 result.emplace_back(logfile_base1_ +
831 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
832 Extension());
833 result.emplace_back(absl::StrCat(
834 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700835 return result;
836 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800837
Austin Schuh510dc622021-08-06 18:47:30 -0700838 std::vector<std::string> MakePi1DeadNodeLogfiles() {
839 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700840 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
841 result.emplace_back(absl::StrCat(
842 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800843 return result;
844 }
845
846 std::vector<std::vector<std::string>> StructureLogFiles() {
847 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800848 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
849 std::vector<std::string>{logfiles_[5], logfiles_[6]},
850 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800851 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800852 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800853
Austin Schuhbfe6c572022-01-27 20:48:20 -0800854 if (shared()) {
855 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
856 logfiles_[16]});
857 result.emplace_back(
858 std::vector<std::string>{logfiles_[17], logfiles_[18]});
859 } else {
860 result.emplace_back(
861 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800862 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700863 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800864 result.emplace_back(
865 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800866 }
867
868 return result;
869 }
870
James Kuszmauldd0a5042021-10-28 23:38:04 -0700871 std::string Extension() {
872 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
873 }
874
Austin Schuh58646e22021-08-23 23:51:46 -0700875 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700876 SimulatedEventLoopFactory *factory = nullptr,
877 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700878 if (factory == nullptr) {
879 factory = &event_loop_factory_;
880 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800881 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
882 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700883 }
884
James Kuszmauldd0a5042021-10-28 23:38:04 -0700885 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700886 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800887 if (logger->event_loop->node()->name()->string_view() == "pi1") {
888 logfile_base = logfile_base1_;
889 } else {
890 logfile_base = logfile_base2_;
891 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700892 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800893 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700894 }
Austin Schuh15649d62019-12-28 16:36:38 -0800895
Austin Schuh3bd4c402020-11-06 18:19:06 -0800896 void VerifyParts(const std::vector<LogFile> &sorted_parts,
897 const std::vector<std::string> &corrupted_parts = {}) {
898 EXPECT_EQ(sorted_parts.size(), 2u);
899
900 // Count up the number of UUIDs and make sure they are what we expect as a
901 // sanity check.
902 std::set<std::string> log_event_uuids;
903 std::set<std::string> parts_uuids;
904 std::set<std::string> both_uuids;
905
906 size_t missing_rt_count = 0;
907
908 std::vector<std::string> logger_nodes;
909 for (const LogFile &log_file : sorted_parts) {
910 EXPECT_FALSE(log_file.log_event_uuid.empty());
911 log_event_uuids.insert(log_file.log_event_uuid);
912 logger_nodes.emplace_back(log_file.logger_node);
913 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800914 EXPECT_TRUE(log_file.config);
915 EXPECT_EQ(log_file.name,
916 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800917
918 for (const LogParts &part : log_file.parts) {
919 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
920 << ": " << part;
921 missing_rt_count +=
922 part.realtime_start_time == aos::realtime_clock::min_time;
923
924 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
925 log_event_uuids.end());
926 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800927 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800928 parts_uuids.insert(part.parts_uuid);
929 both_uuids.insert(part.parts_uuid);
930 }
931 }
932
Austin Schuh61e973f2021-02-21 21:43:56 -0800933 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
934 // start time on remote nodes because we don't know it and would be
935 // guessing. And the log reader can actually do a better job. The number
936 // depends on if we have the remote timestamps split across 2 files, or just
937 // across 1, depending on if we are using a split or combined timestamp
938 // channel config.
939 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800940
941 EXPECT_EQ(log_event_uuids.size(), 2u);
942 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
943 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
944
945 // Test that each list of parts is in order. Don't worry about the ordering
946 // between part file lists though.
947 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -0800948 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -0800949 ::testing::UnorderedElementsAreArray(structured_logfiles_));
950
951 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
952
953 EXPECT_NE(sorted_parts[0].realtime_start_time,
954 aos::realtime_clock::min_time);
955 EXPECT_NE(sorted_parts[1].realtime_start_time,
956 aos::realtime_clock::min_time);
957
958 EXPECT_NE(sorted_parts[0].monotonic_start_time,
959 aos::monotonic_clock::min_time);
960 EXPECT_NE(sorted_parts[1].monotonic_start_time,
961 aos::monotonic_clock::min_time);
962
963 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
964 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
965 }
966
967 void AddExtension(std::string_view extension) {
968 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
969 [extension](const std::string &in) {
970 return absl::StrCat(in, extension);
971 });
972
973 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
974 structured_logfiles_.begin(),
975 [extension](std::vector<std::string> in) {
976 std::transform(in.begin(), in.end(), in.begin(),
977 [extension](const std::string &in_str) {
978 return absl::StrCat(in_str, extension);
979 });
980 return in;
981 });
982 }
983
Austin Schuh15649d62019-12-28 16:36:38 -0800984 // Config and factory.
985 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800986 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800987 SimulatedEventLoopFactory event_loop_factory_;
988
Austin Schuh58646e22021-08-23 23:51:46 -0700989 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800990 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700991 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800992 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700993
994 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800995 std::string logfile_base1_;
996 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800997 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700998 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800999 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001000
1001 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -08001002};
1003
Austin Schuh391e3172020-09-01 22:48:18 -07001004// Counts the number of messages on a channel. Returns (channel name, channel
1005// type, count) for every message matching matcher()
1006std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -08001007 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001008 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -08001009 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -08001010 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -08001011
Austin Schuh6f3babe2020-01-26 20:34:50 -08001012 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001013 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -08001014 if (!msg) {
1015 break;
1016 }
1017
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001018 if (matcher(msg.get())) {
1019 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001020 }
1021 }
1022
Austin Schuh391e3172020-09-01 22:48:18 -07001023 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001024 int channel = 0;
1025 for (size_t i = 0; i < counts.size(); ++i) {
1026 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -08001027 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -07001028 result.push_back(std::make_tuple(channel->name()->str(),
1029 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -08001030 }
1031 ++channel;
1032 }
1033
1034 return result;
1035}
1036
1037// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001038std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -08001039 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -07001040 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001041 return CountChannelsMatching(
1042 config, filename, [](const UnpackedMessageHeader *msg) {
1043 if (msg->span.data() != nullptr) {
1044 CHECK(!msg->monotonic_remote_time.has_value());
1045 CHECK(!msg->realtime_remote_time.has_value());
1046 CHECK(!msg->remote_queue_index.has_value());
1047 return true;
1048 }
1049 return false;
1050 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001051}
1052
1053// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001054std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001055 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001056 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001057 return CountChannelsMatching(
1058 config, filename, [](const UnpackedMessageHeader *msg) {
1059 if (msg->span.data() == nullptr) {
1060 CHECK(msg->monotonic_remote_time.has_value());
1061 CHECK(msg->realtime_remote_time.has_value());
1062 CHECK(msg->remote_queue_index.has_value());
1063 return true;
1064 }
1065 return false;
1066 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001067}
1068
Austin Schuhcde938c2020-02-02 17:30:07 -08001069// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001070TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001071 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001072 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001073
Austin Schuh15649d62019-12-28 16:36:38 -08001074 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001075 LoggerState pi1_logger = MakeLogger(pi1_);
1076 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001077
1078 event_loop_factory_.RunFor(chrono::milliseconds(95));
1079
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001080 StartLogger(&pi1_logger);
1081 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001082
Austin Schuh15649d62019-12-28 16:36:38 -08001083 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001084 pi1_logger.AppendAllFilenames(&actual_filenames);
1085 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001086 }
1087
Austin Schuhbfe6c572022-01-27 20:48:20 -08001088 ASSERT_THAT(actual_filenames,
1089 ::testing::UnorderedElementsAreArray(logfiles_));
1090
Austin Schuh6f3babe2020-01-26 20:34:50 -08001091 {
Austin Schuh64fab802020-09-09 22:47:47 -07001092 std::set<std::string> logfile_uuids;
1093 std::set<std::string> parts_uuids;
1094 // Confirm that we have the expected number of UUIDs for both the logfile
1095 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001096 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001097 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001098 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001099 if (!log_header.back().message().has_configuration()) {
1100 logfile_uuids.insert(
1101 log_header.back().message().log_event_uuid()->str());
1102 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1103 }
Austin Schuh64fab802020-09-09 22:47:47 -07001104 }
Austin Schuh15649d62019-12-28 16:36:38 -08001105
Austin Schuh64fab802020-09-09 22:47:47 -07001106 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001107 if (shared()) {
1108 EXPECT_EQ(parts_uuids.size(), 7u);
1109 } else {
1110 EXPECT_EQ(parts_uuids.size(), 8u);
1111 }
Austin Schuh64fab802020-09-09 22:47:47 -07001112
1113 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001114 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001115 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001116 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1117
Austin Schuh64fab802020-09-09 22:47:47 -07001118 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001119 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001120
Austin Schuhe46492f2021-07-31 19:49:41 -07001121 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001122 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1123 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1124
1125 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1126 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1127
Austin Schuhe46492f2021-07-31 19:49:41 -07001128 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1129 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001130
1131 if (shared()) {
1132 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1133 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001134 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001135
1136 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1137 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1138 } else {
1139 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1140 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1141
1142 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1143 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1144
1145 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1146 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001147 }
Austin Schuh64fab802020-09-09 22:47:47 -07001148
1149 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001150 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001151 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001152 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1153
1154 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1155 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1156
1157 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1158 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1159 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1160
Austin Schuh64fab802020-09-09 22:47:47 -07001161 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1162 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001163
Austin Schuh61e973f2021-02-21 21:43:56 -08001164 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1165 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001166
1167 if (shared()) {
1168 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1169 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1170 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1171
1172 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1173 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1174 } else {
1175 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1176 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1177
Austin Schuhe46492f2021-07-31 19:49:41 -07001178 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1179 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001180
1181 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1182 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001183 }
Austin Schuh64fab802020-09-09 22:47:47 -07001184 }
1185
Austin Schuh8c399962020-12-25 21:51:45 -08001186 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001187 {
Austin Schuh391e3172020-09-01 22:48:18 -07001188 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001189 std::shared_ptr<const aos::Configuration> config =
1190 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001191
Austin Schuh6f3babe2020-01-26 20:34:50 -08001192 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001193 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1194 UnorderedElementsAre(
1195 std::make_tuple("/pi1/aos",
1196 "aos.message_bridge.ServerStatistics", 1),
1197 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001198 << " : " << logfiles_[2];
1199 EXPECT_THAT(
1200 CountChannelsData(config, logfiles_[3]),
1201 UnorderedElementsAre(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001202 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1203 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1204 1)))
1205 << " : " << logfiles_[3];
1206 EXPECT_THAT(
1207 CountChannelsData(config, logfiles_[4]),
1208 UnorderedElementsAre(
1209 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001210 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001211 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001212 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
Austin Schuhbfe6c572022-01-27 20:48:20 -08001213 199),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001214 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001215 std::make_tuple("/test", "aos.examples.Ping", 2000)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001216 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001217 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001218 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1219 UnorderedElementsAre())
1220 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001221 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001222 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001223 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001224 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001225 EXPECT_THAT(
1226 CountChannelsTimestamp(config, logfiles_[4]),
1227 UnorderedElementsAre(
1228 std::make_tuple("/test", "aos.examples.Pong", 2000),
1229 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1230 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001231
1232 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001233 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001234 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001235 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001236 << " : " << logfiles_[5];
1237 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001238 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001239 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001240 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001241
Austin Schuh6f3babe2020-01-26 20:34:50 -08001242 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001243 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1244 UnorderedElementsAre())
1245 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001246 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1247 UnorderedElementsAre())
1248 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001249
1250 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001251 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001252 UnorderedElementsAre(std::make_tuple(
1253 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001254 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001255 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001256 CountChannelsData(config, logfiles_[8]),
1257 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1258 << " : " << logfiles_[8];
1259 EXPECT_THAT(
1260 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001261 UnorderedElementsAre(
1262 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001263 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001264 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001265 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1266 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001267 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001268 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1269 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001270 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001271 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001272 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001273 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001274 EXPECT_THAT(
1275 CountChannelsTimestamp(config, logfiles_[8]),
1276 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1277 << " : " << logfiles_[8];
1278 EXPECT_THAT(
1279 CountChannelsTimestamp(config, logfiles_[9]),
1280 UnorderedElementsAre(
1281 std::make_tuple("/test", "aos.examples.Ping", 2000),
1282 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1283 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001284
1285 // And then test that the remotely logged timestamp data files only have
1286 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001287 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1288 UnorderedElementsAre())
1289 << " : " << logfiles_[10];
1290 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1291 UnorderedElementsAre())
1292 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001293 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1294 UnorderedElementsAre())
1295 << " : " << logfiles_[12];
1296 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1297 UnorderedElementsAre())
1298 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001299
Austin Schuh8c399962020-12-25 21:51:45 -08001300 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001301 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001302 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001303 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001304 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001305 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001306 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001307 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001308
Austin Schuh61e973f2021-02-21 21:43:56 -08001309 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001310 UnorderedElementsAre(std::make_tuple(
1311 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001312 << " : " << logfiles_[12];
1313 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001314 UnorderedElementsAre(std::make_tuple(
1315 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001316 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001317
1318 // Timestamps from pi2 on pi1, and the other way.
1319 if (shared()) {
1320 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1321 UnorderedElementsAre())
1322 << " : " << logfiles_[14];
1323 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1324 UnorderedElementsAre())
1325 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001326 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001327 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001328 << " : " << logfiles_[16];
1329 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001330 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001331 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001332 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1333 UnorderedElementsAre())
1334 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001335
Austin Schuhbfe6c572022-01-27 20:48:20 -08001336 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1337 UnorderedElementsAre(
1338 std::make_tuple("/test", "aos.examples.Ping", 1)))
1339 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001340 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001341 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001342 UnorderedElementsAre(
1343 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001344 std::make_tuple("/test", "aos.examples.Ping", 90)))
1345 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001346 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001347 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001348 UnorderedElementsAre(
1349 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1350 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001351 << " : " << logfiles_[16];
1352 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001353 UnorderedElementsAre(std::make_tuple(
1354 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1355 << " : " << logfiles_[17];
1356 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1357 UnorderedElementsAre(std::make_tuple(
1358 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1359 << " : " << logfiles_[18];
1360 } else {
1361 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1362 UnorderedElementsAre())
1363 << " : " << logfiles_[14];
1364 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1365 UnorderedElementsAre())
1366 << " : " << logfiles_[15];
1367 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1368 UnorderedElementsAre())
1369 << " : " << logfiles_[16];
1370 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1371 UnorderedElementsAre())
1372 << " : " << logfiles_[17];
1373 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1374 UnorderedElementsAre())
1375 << " : " << logfiles_[18];
1376 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1377 UnorderedElementsAre())
1378 << " : " << logfiles_[19];
1379
1380 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1381 UnorderedElementsAre(std::make_tuple(
1382 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1383 << " : " << logfiles_[14];
1384 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1385 UnorderedElementsAre(std::make_tuple(
1386 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1387 << " : " << logfiles_[15];
1388 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1389 UnorderedElementsAre(std::make_tuple(
1390 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1391 << " : " << logfiles_[16];
1392 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1393 UnorderedElementsAre(std::make_tuple(
1394 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1395 << " : " << logfiles_[17];
1396 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1397 UnorderedElementsAre(
1398 std::make_tuple("/test", "aos.examples.Ping", 91)))
1399 << " : " << logfiles_[18];
1400 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001401 UnorderedElementsAre(
1402 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001403 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001404 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001405 }
1406
Austin Schuh8c399962020-12-25 21:51:45 -08001407 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001408
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001409 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001410 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001411
1412 // This sends out the fetched messages and advances time to the start of the
1413 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001414 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001415
Austin Schuhac0771c2020-01-07 18:36:30 -08001416 const Node *pi1 =
1417 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001418 const Node *pi2 =
1419 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001420
Austin Schuh2f8fd752020-09-01 22:38:28 -07001421 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1422 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1423 LOG(INFO) << "now pi1 "
1424 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1425 LOG(INFO) << "now pi2 "
1426 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1427
Austin Schuh07676622021-01-21 18:59:17 -08001428 EXPECT_THAT(reader.LoggedNodes(),
1429 ::testing::ElementsAre(
1430 configuration::GetNode(reader.logged_configuration(), pi1),
1431 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001432
1433 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001434
Austin Schuh6f3babe2020-01-26 20:34:50 -08001435 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001436 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001437 std::unique_ptr<EventLoop> pi2_event_loop =
1438 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001439
Austin Schuh6f3babe2020-01-26 20:34:50 -08001440 int pi1_ping_count = 10;
1441 int pi2_ping_count = 10;
1442 int pi1_pong_count = 10;
1443 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001444
1445 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001446 pi1_event_loop->MakeWatcher(
1447 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001448 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001449 << pi1_event_loop->context().monotonic_remote_time << " -> "
1450 << pi1_event_loop->context().monotonic_event_time;
1451 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1452 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1453 pi1_ping_count * chrono::milliseconds(10) +
1454 monotonic_clock::epoch());
1455 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1456 pi1_ping_count * chrono::milliseconds(10) +
1457 realtime_clock::epoch());
1458 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1459 pi1_event_loop->context().monotonic_event_time);
1460 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1461 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001462
Austin Schuh6f3babe2020-01-26 20:34:50 -08001463 ++pi1_ping_count;
1464 });
1465 pi2_event_loop->MakeWatcher(
1466 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001467 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001468 << pi2_event_loop->context().monotonic_remote_time << " -> "
1469 << pi2_event_loop->context().monotonic_event_time;
1470 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1471
1472 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1473 pi2_ping_count * chrono::milliseconds(10) +
1474 monotonic_clock::epoch());
1475 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1476 pi2_ping_count * chrono::milliseconds(10) +
1477 realtime_clock::epoch());
1478 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1479 chrono::microseconds(150),
1480 pi2_event_loop->context().monotonic_event_time);
1481 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1482 chrono::microseconds(150),
1483 pi2_event_loop->context().realtime_event_time);
1484 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001485 });
1486
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001487 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001488 // Confirm that the ping and pong counts both match, and the value also
1489 // matches.
1490 pi1_event_loop->MakeWatcher(
1491 "/test", [&pi1_event_loop, &pi1_ping_count,
1492 &pi1_pong_count](const examples::Pong &pong) {
1493 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1494 << pi1_event_loop->context().monotonic_remote_time << " -> "
1495 << pi1_event_loop->context().monotonic_event_time;
1496
1497 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1498 pi1_pong_count + kQueueIndexOffset);
1499 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1500 chrono::microseconds(200) +
1501 pi1_pong_count * chrono::milliseconds(10) +
1502 monotonic_clock::epoch());
1503 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1504 chrono::microseconds(200) +
1505 pi1_pong_count * chrono::milliseconds(10) +
1506 realtime_clock::epoch());
1507
1508 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1509 chrono::microseconds(150),
1510 pi1_event_loop->context().monotonic_event_time);
1511 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1512 chrono::microseconds(150),
1513 pi1_event_loop->context().realtime_event_time);
1514
1515 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1516 ++pi1_pong_count;
1517 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1518 });
1519 pi2_event_loop->MakeWatcher(
1520 "/test", [&pi2_event_loop, &pi2_ping_count,
1521 &pi2_pong_count](const examples::Pong &pong) {
1522 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1523 << pi2_event_loop->context().monotonic_remote_time << " -> "
1524 << pi2_event_loop->context().monotonic_event_time;
1525
1526 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001527 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001528
1529 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1530 chrono::microseconds(200) +
1531 pi2_pong_count * chrono::milliseconds(10) +
1532 monotonic_clock::epoch());
1533 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1534 chrono::microseconds(200) +
1535 pi2_pong_count * chrono::milliseconds(10) +
1536 realtime_clock::epoch());
1537
1538 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1539 pi2_event_loop->context().monotonic_event_time);
1540 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1541 pi2_event_loop->context().realtime_event_time);
1542
1543 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1544 ++pi2_pong_count;
1545 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1546 });
1547
1548 log_reader_factory.Run();
1549 EXPECT_EQ(pi1_ping_count, 2010);
1550 EXPECT_EQ(pi2_ping_count, 2010);
1551 EXPECT_EQ(pi1_pong_count, 2010);
1552 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001553
1554 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001555}
1556
James Kuszmaul46d82582020-05-09 19:50:09 -07001557typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1558
1559// Test that if we feed the replay with a mismatched node list that we die on
1560// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001561TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001562 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001563 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001564 LoggerState pi1_logger = MakeLogger(pi1_);
1565 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001566
1567 event_loop_factory_.RunFor(chrono::milliseconds(95));
1568
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001569 StartLogger(&pi1_logger);
1570 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001571
James Kuszmaul46d82582020-05-09 19:50:09 -07001572 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1573 }
1574
1575 // Test that, if we add an additional node to the replay config that the
1576 // logger complains about the mismatch in number of nodes.
1577 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1578 configuration::MergeWithConfig(&config_.message(), R"({
1579 "nodes": [
1580 {
1581 "name": "extra-node"
1582 }
1583 ]
1584 }
1585 )");
1586
Austin Schuh287d43d2020-12-04 20:19:33 -08001587 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1588 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001589 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001590}
1591
Austin Schuhcde938c2020-02-02 17:30:07 -08001592// Tests that we can read log files where they don't start at the same monotonic
1593// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001594TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001595 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001596 std::vector<std::string> actual_filenames;
1597
Austin Schuhcde938c2020-02-02 17:30:07 -08001598 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001599 LoggerState pi1_logger = MakeLogger(pi1_);
1600 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001601
1602 event_loop_factory_.RunFor(chrono::milliseconds(95));
1603
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001604 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001605
1606 event_loop_factory_.RunFor(chrono::milliseconds(200));
1607
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001608 StartLogger(&pi2_logger);
1609
Austin Schuhcde938c2020-02-02 17:30:07 -08001610 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001611 pi1_logger.AppendAllFilenames(&actual_filenames);
1612 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001613 }
1614
Austin Schuhe46492f2021-07-31 19:49:41 -07001615 // Since we delay starting pi2, it already knows about all the timestamps so
1616 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001617 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001618
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001619 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001620 log_reader_factory.set_send_delay(chrono::microseconds(0));
1621
1622 // This sends out the fetched messages and advances time to the start of the
1623 // log file.
1624 reader.Register(&log_reader_factory);
1625
1626 const Node *pi1 =
1627 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1628 const Node *pi2 =
1629 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1630
Austin Schuh07676622021-01-21 18:59:17 -08001631 EXPECT_THAT(reader.LoggedNodes(),
1632 ::testing::ElementsAre(
1633 configuration::GetNode(reader.logged_configuration(), pi1),
1634 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001635
1636 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1637
1638 std::unique_ptr<EventLoop> pi1_event_loop =
1639 log_reader_factory.MakeEventLoop("test", pi1);
1640 std::unique_ptr<EventLoop> pi2_event_loop =
1641 log_reader_factory.MakeEventLoop("test", pi2);
1642
1643 int pi1_ping_count = 30;
1644 int pi2_ping_count = 30;
1645 int pi1_pong_count = 30;
1646 int pi2_pong_count = 30;
1647
1648 // Confirm that the ping value matches.
1649 pi1_event_loop->MakeWatcher(
1650 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1651 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1652 << pi1_event_loop->context().monotonic_remote_time << " -> "
1653 << pi1_event_loop->context().monotonic_event_time;
1654 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1655
1656 ++pi1_ping_count;
1657 });
1658 pi2_event_loop->MakeWatcher(
1659 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1660 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1661 << pi2_event_loop->context().monotonic_remote_time << " -> "
1662 << pi2_event_loop->context().monotonic_event_time;
1663 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1664
1665 ++pi2_ping_count;
1666 });
1667
1668 // Confirm that the ping and pong counts both match, and the value also
1669 // matches.
1670 pi1_event_loop->MakeWatcher(
1671 "/test", [&pi1_event_loop, &pi1_ping_count,
1672 &pi1_pong_count](const examples::Pong &pong) {
1673 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1674 << pi1_event_loop->context().monotonic_remote_time << " -> "
1675 << pi1_event_loop->context().monotonic_event_time;
1676
1677 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1678 ++pi1_pong_count;
1679 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1680 });
1681 pi2_event_loop->MakeWatcher(
1682 "/test", [&pi2_event_loop, &pi2_ping_count,
1683 &pi2_pong_count](const examples::Pong &pong) {
1684 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1685 << pi2_event_loop->context().monotonic_remote_time << " -> "
1686 << pi2_event_loop->context().monotonic_event_time;
1687
1688 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1689 ++pi2_pong_count;
1690 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1691 });
1692
1693 log_reader_factory.Run();
1694 EXPECT_EQ(pi1_ping_count, 2030);
1695 EXPECT_EQ(pi2_ping_count, 2030);
1696 EXPECT_EQ(pi1_pong_count, 2030);
1697 EXPECT_EQ(pi2_pong_count, 2030);
1698
1699 reader.Deregister();
1700}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001701
Austin Schuh8bd96322020-02-13 21:18:22 -08001702// Tests that we can read log files where the monotonic clocks drift and don't
1703// match correctly. While we are here, also test that different ending times
1704// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001705TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001706 // TODO(austin): Negate...
1707 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1708
Austin Schuh66168842021-08-17 19:42:21 -07001709 time_converter_.AddMonotonic(
1710 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001711 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1712 // skew to be 200 uS/s
1713 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1714 {chrono::milliseconds(95),
1715 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1716 // Run another 200 ms to have one logger start first.
1717 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1718 {chrono::milliseconds(200), chrono::milliseconds(200)});
1719 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1720 // go far enough to cause problems if this isn't accounted for.
1721 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1722 {chrono::milliseconds(20000),
1723 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1724 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1725 {chrono::milliseconds(40000),
1726 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1727 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1728 {chrono::milliseconds(400), chrono::milliseconds(400)});
1729
Austin Schuhcde938c2020-02-02 17:30:07 -08001730 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001731 LoggerState pi2_logger = MakeLogger(pi2_);
1732
Austin Schuh58646e22021-08-23 23:51:46 -07001733 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1734 << pi2_->realtime_now() << " distributed "
1735 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001736
Austin Schuh58646e22021-08-23 23:51:46 -07001737 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1738 << pi2_->realtime_now() << " distributed "
1739 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001740
Austin Schuh87dd3832021-01-01 23:07:31 -08001741 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001742
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001743 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001744
Austin Schuh87dd3832021-01-01 23:07:31 -08001745 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001746
Austin Schuh8bd96322020-02-13 21:18:22 -08001747 {
1748 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001749 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001750
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001751 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001752 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001753
Austin Schuh87dd3832021-01-01 23:07:31 -08001754 // Make sure we slewed time far enough so that the difference is greater
1755 // than the network delay. This confirms that if we sort incorrectly, it
1756 // would show in the results.
1757 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001758 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001759 -event_loop_factory_.send_delay() -
1760 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001761
Austin Schuh87dd3832021-01-01 23:07:31 -08001762 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001763
Austin Schuh87dd3832021-01-01 23:07:31 -08001764 // And now check that we went far enough the other way to make sure we
1765 // cover both problems.
1766 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001767 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001768 event_loop_factory_.send_delay() +
1769 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001770 }
1771
1772 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001773 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001774 }
1775
Austin Schuh72211ae2021-08-05 14:02:30 -07001776 LogReader reader(
1777 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001778
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001779 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001780 log_reader_factory.set_send_delay(chrono::microseconds(0));
1781
Austin Schuhcde938c2020-02-02 17:30:07 -08001782 const Node *pi1 =
1783 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1784 const Node *pi2 =
1785 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1786
Austin Schuh2f8fd752020-09-01 22:38:28 -07001787 // This sends out the fetched messages and advances time to the start of the
1788 // log file.
1789 reader.Register(&log_reader_factory);
1790
1791 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1792 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1793 LOG(INFO) << "now pi1 "
1794 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1795 LOG(INFO) << "now pi2 "
1796 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1797
Austin Schuhcde938c2020-02-02 17:30:07 -08001798 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001799 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1800 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001801 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1802 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001803 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1804 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001805 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1806
Austin Schuh07676622021-01-21 18:59:17 -08001807 EXPECT_THAT(reader.LoggedNodes(),
1808 ::testing::ElementsAre(
1809 configuration::GetNode(reader.logged_configuration(), pi1),
1810 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001811
1812 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1813
1814 std::unique_ptr<EventLoop> pi1_event_loop =
1815 log_reader_factory.MakeEventLoop("test", pi1);
1816 std::unique_ptr<EventLoop> pi2_event_loop =
1817 log_reader_factory.MakeEventLoop("test", pi2);
1818
1819 int pi1_ping_count = 30;
1820 int pi2_ping_count = 30;
1821 int pi1_pong_count = 30;
1822 int pi2_pong_count = 30;
1823
1824 // Confirm that the ping value matches.
1825 pi1_event_loop->MakeWatcher(
1826 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1827 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1828 << pi1_event_loop->context().monotonic_remote_time << " -> "
1829 << pi1_event_loop->context().monotonic_event_time;
1830 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1831
1832 ++pi1_ping_count;
1833 });
1834 pi2_event_loop->MakeWatcher(
1835 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1836 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1837 << pi2_event_loop->context().monotonic_remote_time << " -> "
1838 << pi2_event_loop->context().monotonic_event_time;
1839 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1840
1841 ++pi2_ping_count;
1842 });
1843
1844 // Confirm that the ping and pong counts both match, and the value also
1845 // matches.
1846 pi1_event_loop->MakeWatcher(
1847 "/test", [&pi1_event_loop, &pi1_ping_count,
1848 &pi1_pong_count](const examples::Pong &pong) {
1849 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1850 << pi1_event_loop->context().monotonic_remote_time << " -> "
1851 << pi1_event_loop->context().monotonic_event_time;
1852
1853 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1854 ++pi1_pong_count;
1855 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1856 });
1857 pi2_event_loop->MakeWatcher(
1858 "/test", [&pi2_event_loop, &pi2_ping_count,
1859 &pi2_pong_count](const examples::Pong &pong) {
1860 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1861 << pi2_event_loop->context().monotonic_remote_time << " -> "
1862 << pi2_event_loop->context().monotonic_event_time;
1863
1864 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1865 ++pi2_pong_count;
1866 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1867 });
1868
1869 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001870 EXPECT_EQ(pi1_ping_count, 6030);
1871 EXPECT_EQ(pi2_ping_count, 6030);
1872 EXPECT_EQ(pi1_pong_count, 6030);
1873 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001874
1875 reader.Deregister();
1876}
1877
Austin Schuh5212cad2020-09-09 23:12:09 -07001878// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001879TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001880 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001881 // Make a bunch of parts.
1882 {
1883 LoggerState pi1_logger = MakeLogger(pi1_);
1884 LoggerState pi2_logger = MakeLogger(pi2_);
1885
1886 event_loop_factory_.RunFor(chrono::milliseconds(95));
1887
1888 StartLogger(&pi1_logger);
1889 StartLogger(&pi2_logger);
1890
1891 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1892 }
1893
Austin Schuh11d43732020-09-21 17:28:30 -07001894 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001895 VerifyParts(sorted_parts);
1896}
Austin Schuh11d43732020-09-21 17:28:30 -07001897
Austin Schuh3bd4c402020-11-06 18:19:06 -08001898// Tests that we can sort a bunch of parts with an empty part. We should ignore
1899// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001900TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001901 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001902 // Make a bunch of parts.
1903 {
1904 LoggerState pi1_logger = MakeLogger(pi1_);
1905 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001906
Austin Schuh3bd4c402020-11-06 18:19:06 -08001907 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001908
Austin Schuh3bd4c402020-11-06 18:19:06 -08001909 StartLogger(&pi1_logger);
1910 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001911
Austin Schuh3bd4c402020-11-06 18:19:06 -08001912 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001913 }
1914
Austin Schuh3bd4c402020-11-06 18:19:06 -08001915 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001916 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001917
Austin Schuh3bd4c402020-11-06 18:19:06 -08001918 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1919 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001920
Austin Schuh3bd4c402020-11-06 18:19:06 -08001921 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1922 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001923}
1924
James Kuszmauldd0a5042021-10-28 23:38:04 -07001925// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08001926// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001927TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001928 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001929 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001930 // Make a bunch of parts.
1931 {
1932 LoggerState pi1_logger = MakeLogger(pi1_);
1933 LoggerState pi2_logger = MakeLogger(pi2_);
1934
1935 event_loop_factory_.RunFor(chrono::milliseconds(95));
1936
James Kuszmauldd0a5042021-10-28 23:38:04 -07001937 StartLogger(&pi1_logger);
1938 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001939
1940 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001941
1942 pi1_logger.AppendAllFilenames(&actual_filenames);
1943 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001944 }
1945
Austin Schuhbfe6c572022-01-27 20:48:20 -08001946 ASSERT_THAT(actual_filenames,
1947 ::testing::UnorderedElementsAreArray(logfiles_));
1948
Austin Schuh3bd4c402020-11-06 18:19:06 -08001949 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001950 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1951 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08001952 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08001953 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001954
1955 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001956 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001957 compressed_contents.substr(0, compressed_contents.size() - 100));
1958
1959 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1960 VerifyParts(sorted_parts);
1961}
Austin Schuh3bd4c402020-11-06 18:19:06 -08001962
Austin Schuh01b4c352020-09-21 23:09:39 -07001963// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001964TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001965 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001966 {
1967 LoggerState pi1_logger = MakeLogger(pi1_);
1968 LoggerState pi2_logger = MakeLogger(pi2_);
1969
1970 event_loop_factory_.RunFor(chrono::milliseconds(95));
1971
1972 StartLogger(&pi1_logger);
1973 StartLogger(&pi2_logger);
1974
1975 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1976 }
1977
Austin Schuh287d43d2020-12-04 20:19:33 -08001978 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001979
1980 // Remap just on pi1.
1981 reader.RemapLoggedChannel<aos::timing::Report>(
1982 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1983
1984 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1985 log_reader_factory.set_send_delay(chrono::microseconds(0));
1986
Austin Schuh1c227352021-09-17 12:53:54 -07001987 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1988 ASSERT_EQ(remapped_channels.size(), 1u);
1989 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1990 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1991
Austin Schuh01b4c352020-09-21 23:09:39 -07001992 reader.Register(&log_reader_factory);
1993
1994 const Node *pi1 =
1995 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1996 const Node *pi2 =
1997 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1998
1999 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2000 // else should have moved.
2001 std::unique_ptr<EventLoop> pi1_event_loop =
2002 log_reader_factory.MakeEventLoop("test", pi1);
2003 pi1_event_loop->SkipTimingReport();
2004 std::unique_ptr<EventLoop> full_pi1_event_loop =
2005 log_reader_factory.MakeEventLoop("test", pi1);
2006 full_pi1_event_loop->SkipTimingReport();
2007 std::unique_ptr<EventLoop> pi2_event_loop =
2008 log_reader_factory.MakeEventLoop("test", pi2);
2009 pi2_event_loop->SkipTimingReport();
2010
2011 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
2012 "/aos");
2013 MessageCounter<aos::timing::Report> full_pi1_timing_report(
2014 full_pi1_event_loop.get(), "/pi1/aos");
2015 MessageCounter<aos::timing::Report> pi1_original_timing_report(
2016 pi1_event_loop.get(), "/original/aos");
2017 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
2018 full_pi1_event_loop.get(), "/original/pi1/aos");
2019 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
2020 "/aos");
2021
2022 log_reader_factory.Run();
2023
2024 EXPECT_EQ(pi1_timing_report.count(), 0u);
2025 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
2026 EXPECT_NE(pi1_original_timing_report.count(), 0u);
2027 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
2028 EXPECT_NE(pi2_timing_report.count(), 0u);
2029
2030 reader.Deregister();
2031}
2032
Austin Schuh006a9f52021-04-07 16:24:18 -07002033// Tests that we can remap a forwarded channel as well.
2034TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
2035 time_converter_.StartEqual();
2036 {
2037 LoggerState pi1_logger = MakeLogger(pi1_);
2038 LoggerState pi2_logger = MakeLogger(pi2_);
2039
2040 event_loop_factory_.RunFor(chrono::milliseconds(95));
2041
2042 StartLogger(&pi1_logger);
2043 StartLogger(&pi2_logger);
2044
2045 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2046 }
2047
2048 LogReader reader(SortParts(logfiles_));
2049
2050 reader.RemapLoggedChannel<examples::Ping>("/test");
2051
2052 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2053 log_reader_factory.set_send_delay(chrono::microseconds(0));
2054
2055 reader.Register(&log_reader_factory);
2056
2057 const Node *pi1 =
2058 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2059 const Node *pi2 =
2060 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2061
2062 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2063 // else should have moved.
2064 std::unique_ptr<EventLoop> pi1_event_loop =
2065 log_reader_factory.MakeEventLoop("test", pi1);
2066 pi1_event_loop->SkipTimingReport();
2067 std::unique_ptr<EventLoop> full_pi1_event_loop =
2068 log_reader_factory.MakeEventLoop("test", pi1);
2069 full_pi1_event_loop->SkipTimingReport();
2070 std::unique_ptr<EventLoop> pi2_event_loop =
2071 log_reader_factory.MakeEventLoop("test", pi2);
2072 pi2_event_loop->SkipTimingReport();
2073
2074 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2075 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2076 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2077 "/original/test");
2078 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2079 "/original/test");
2080
2081 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2082 pi1_original_ping_timestamp;
2083 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2084 pi1_ping_timestamp;
2085 if (!shared()) {
2086 pi1_original_ping_timestamp =
2087 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2088 pi1_event_loop.get(),
2089 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2090 pi1_ping_timestamp =
2091 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2092 pi1_event_loop.get(),
2093 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2094 }
2095
2096 log_reader_factory.Run();
2097
2098 EXPECT_EQ(pi1_ping.count(), 0u);
2099 EXPECT_EQ(pi2_ping.count(), 0u);
2100 EXPECT_NE(pi1_original_ping.count(), 0u);
2101 EXPECT_NE(pi2_original_ping.count(), 0u);
2102 if (!shared()) {
2103 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2104 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2105 }
2106
2107 reader.Deregister();
2108}
2109
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002110// Tests that we properly recreate forwarded timestamps when replaying a log.
2111// This should be enough that we can then re-run the logger and get a valid log
2112// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002113TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002114 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002115 {
2116 LoggerState pi1_logger = MakeLogger(pi1_);
2117 LoggerState pi2_logger = MakeLogger(pi2_);
2118
2119 event_loop_factory_.RunFor(chrono::milliseconds(95));
2120
2121 StartLogger(&pi1_logger);
2122 StartLogger(&pi2_logger);
2123
2124 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2125 }
2126
Austin Schuh287d43d2020-12-04 20:19:33 -08002127 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002128
2129 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2130 log_reader_factory.set_send_delay(chrono::microseconds(0));
2131
2132 // This sends out the fetched messages and advances time to the start of the
2133 // log file.
2134 reader.Register(&log_reader_factory);
2135
2136 const Node *pi1 =
2137 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2138 const Node *pi2 =
2139 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2140
2141 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2142 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2143 LOG(INFO) << "now pi1 "
2144 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2145 LOG(INFO) << "now pi2 "
2146 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2147
Austin Schuh07676622021-01-21 18:59:17 -08002148 EXPECT_THAT(reader.LoggedNodes(),
2149 ::testing::ElementsAre(
2150 configuration::GetNode(reader.logged_configuration(), pi1),
2151 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002152
2153 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2154
2155 std::unique_ptr<EventLoop> pi1_event_loop =
2156 log_reader_factory.MakeEventLoop("test", pi1);
2157 std::unique_ptr<EventLoop> pi2_event_loop =
2158 log_reader_factory.MakeEventLoop("test", pi2);
2159
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002160 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2161 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2162 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2163 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2164
2165 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2166 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2167 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2168 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2169
2170 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2171 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2172 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2173 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2174
2175 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2176 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2177 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2178 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2179
2180 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2181 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2182 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2183 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2184
2185 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2186 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2187 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2188 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2189
Austin Schuh969cd602021-01-03 00:09:45 -08002190 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002191 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002192
Austin Schuh61e973f2021-02-21 21:43:56 -08002193 for (std::pair<int, std::string> channel :
2194 shared()
2195 ? std::vector<
2196 std::pair<int, std::string>>{{-1,
2197 "/aos/remote_timestamps/pi2"}}
2198 : std::vector<std::pair<int, std::string>>{
2199 {pi1_timestamp_channel,
2200 "/aos/remote_timestamps/pi2/pi1/aos/"
2201 "aos-message_bridge-Timestamp"},
2202 {ping_timestamp_channel,
2203 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2204 pi1_event_loop->MakeWatcher(
2205 channel.second,
2206 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2207 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2208 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2209 &ping_on_pi2_fetcher, network_delay, send_delay,
2210 channel_index = channel.first](const RemoteMessage &header) {
2211 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2212 chrono::nanoseconds(header.monotonic_sent_time()));
2213 const aos::realtime_clock::time_point header_realtime_sent_time(
2214 chrono::nanoseconds(header.realtime_sent_time()));
2215 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2216 chrono::nanoseconds(header.monotonic_remote_time()));
2217 const aos::realtime_clock::time_point header_realtime_remote_time(
2218 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002219
Austin Schuh61e973f2021-02-21 21:43:56 -08002220 if (channel_index != -1) {
2221 ASSERT_EQ(channel_index, header.channel_index());
2222 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002223
Austin Schuh61e973f2021-02-21 21:43:56 -08002224 const Context *pi1_context = nullptr;
2225 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002226
Austin Schuh61e973f2021-02-21 21:43:56 -08002227 if (header.channel_index() == pi1_timestamp_channel) {
2228 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2229 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2230 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2231 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2232 } else if (header.channel_index() == ping_timestamp_channel) {
2233 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2234 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2235 pi1_context = &ping_on_pi1_fetcher.context();
2236 pi2_context = &ping_on_pi2_fetcher.context();
2237 } else {
2238 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2239 << configuration::CleanedChannelToString(
2240 pi1_event_loop->configuration()->channels()->Get(
2241 header.channel_index()));
2242 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002243
Austin Schuh61e973f2021-02-21 21:43:56 -08002244 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002245 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2246 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002247
Austin Schuh61e973f2021-02-21 21:43:56 -08002248 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2249 EXPECT_EQ(pi2_context->remote_queue_index,
2250 header.remote_queue_index());
2251 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002252
Austin Schuh61e973f2021-02-21 21:43:56 -08002253 EXPECT_EQ(pi2_context->monotonic_event_time,
2254 header_monotonic_sent_time);
2255 EXPECT_EQ(pi2_context->realtime_event_time,
2256 header_realtime_sent_time);
2257 EXPECT_EQ(pi2_context->realtime_remote_time,
2258 header_realtime_remote_time);
2259 EXPECT_EQ(pi2_context->monotonic_remote_time,
2260 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002261
Austin Schuh61e973f2021-02-21 21:43:56 -08002262 EXPECT_EQ(pi1_context->realtime_event_time,
2263 header_realtime_remote_time);
2264 EXPECT_EQ(pi1_context->monotonic_event_time,
2265 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002266
Austin Schuh61e973f2021-02-21 21:43:56 -08002267 // Time estimation isn't perfect, but we know the clocks were
2268 // identical when logged, so we know when this should have come back.
2269 // Confirm we got it when we expected.
2270 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2271 pi1_context->monotonic_event_time + 2 * network_delay +
2272 send_delay);
2273 });
2274 }
2275 for (std::pair<int, std::string> channel :
2276 shared()
2277 ? std::vector<
2278 std::pair<int, std::string>>{{-1,
2279 "/aos/remote_timestamps/pi1"}}
2280 : std::vector<std::pair<int, std::string>>{
2281 {pi2_timestamp_channel,
2282 "/aos/remote_timestamps/pi1/pi2/aos/"
2283 "aos-message_bridge-Timestamp"}}) {
2284 pi2_event_loop->MakeWatcher(
2285 channel.second,
2286 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2287 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2288 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2289 &pong_on_pi1_fetcher, network_delay, send_delay,
2290 channel_index = channel.first](const RemoteMessage &header) {
2291 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2292 chrono::nanoseconds(header.monotonic_sent_time()));
2293 const aos::realtime_clock::time_point header_realtime_sent_time(
2294 chrono::nanoseconds(header.realtime_sent_time()));
2295 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2296 chrono::nanoseconds(header.monotonic_remote_time()));
2297 const aos::realtime_clock::time_point header_realtime_remote_time(
2298 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002299
Austin Schuh61e973f2021-02-21 21:43:56 -08002300 if (channel_index != -1) {
2301 ASSERT_EQ(channel_index, header.channel_index());
2302 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002303
Austin Schuh61e973f2021-02-21 21:43:56 -08002304 const Context *pi2_context = nullptr;
2305 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002306
Austin Schuh61e973f2021-02-21 21:43:56 -08002307 if (header.channel_index() == pi2_timestamp_channel) {
2308 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2309 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2310 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2311 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2312 } else if (header.channel_index() == pong_timestamp_channel) {
2313 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2314 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2315 pi2_context = &pong_on_pi2_fetcher.context();
2316 pi1_context = &pong_on_pi1_fetcher.context();
2317 } else {
2318 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2319 << configuration::CleanedChannelToString(
2320 pi2_event_loop->configuration()->channels()->Get(
2321 header.channel_index()));
2322 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002323
Austin Schuh61e973f2021-02-21 21:43:56 -08002324 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002325 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2326 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002327
Austin Schuh61e973f2021-02-21 21:43:56 -08002328 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2329 EXPECT_EQ(pi1_context->remote_queue_index,
2330 header.remote_queue_index());
2331 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002332
Austin Schuh61e973f2021-02-21 21:43:56 -08002333 EXPECT_EQ(pi1_context->monotonic_event_time,
2334 header_monotonic_sent_time);
2335 EXPECT_EQ(pi1_context->realtime_event_time,
2336 header_realtime_sent_time);
2337 EXPECT_EQ(pi1_context->realtime_remote_time,
2338 header_realtime_remote_time);
2339 EXPECT_EQ(pi1_context->monotonic_remote_time,
2340 header_monotonic_remote_time);
2341
2342 EXPECT_EQ(pi2_context->realtime_event_time,
2343 header_realtime_remote_time);
2344 EXPECT_EQ(pi2_context->monotonic_event_time,
2345 header_monotonic_remote_time);
2346
2347 // Time estimation isn't perfect, but we know the clocks were
2348 // identical when logged, so we know when this should have come back.
2349 // Confirm we got it when we expected.
2350 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2351 pi2_context->monotonic_event_time + 2 * network_delay +
2352 send_delay);
2353 });
2354 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002355
2356 // And confirm we can re-create a log again, while checking the contents.
2357 {
2358 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002359 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002360 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002361 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002362
Austin Schuh25b46712021-01-03 00:04:38 -08002363 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2364 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002365
2366 log_reader_factory.Run();
2367 }
2368
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002369 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002370
2371 // And verify that we can run the LogReader over the relogged files without
2372 // hitting any fatal errors.
2373 {
2374 LogReader relogged_reader(SortParts(
2375 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2376 relogged_reader.Register();
2377
2378 relogged_reader.event_loop_factory()->Run();
2379 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002380}
2381
Austin Schuh315b96b2020-12-11 21:21:12 -08002382// Tests that we properly populate and extract the logger_start time by setting
2383// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002384TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002385 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002386 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002387 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002388 {
2389 LoggerState pi1_logger = MakeLogger(pi1_);
2390 LoggerState pi2_logger = MakeLogger(pi2_);
2391
Austin Schuh315b96b2020-12-11 21:21:12 -08002392 StartLogger(&pi1_logger);
2393 StartLogger(&pi2_logger);
2394
2395 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002396
2397 pi1_logger.AppendAllFilenames(&actual_filenames);
2398 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002399 }
2400
Austin Schuhf5f99f32022-02-07 20:05:37 -08002401 ASSERT_THAT(actual_filenames,
2402 ::testing::UnorderedElementsAreArray(logfiles_));
2403
Austin Schuh315b96b2020-12-11 21:21:12 -08002404 for (const LogFile &log_file : SortParts(logfiles_)) {
2405 for (const LogParts &log_part : log_file.parts) {
2406 if (log_part.node == log_file.logger_node) {
2407 EXPECT_EQ(log_part.logger_monotonic_start_time,
2408 aos::monotonic_clock::min_time);
2409 EXPECT_EQ(log_part.logger_realtime_start_time,
2410 aos::realtime_clock::min_time);
2411 } else {
2412 const chrono::seconds offset = log_file.logger_node == "pi1"
2413 ? -chrono::seconds(1000)
2414 : chrono::seconds(1000);
2415 EXPECT_EQ(log_part.logger_monotonic_start_time,
2416 log_part.monotonic_start_time + offset);
2417 EXPECT_EQ(log_part.logger_realtime_start_time,
2418 log_file.realtime_start_time +
2419 (log_part.logger_monotonic_start_time -
2420 log_file.monotonic_start_time));
2421 }
2422 }
2423 }
2424}
2425
Austin Schuh6bb8a822021-03-31 23:04:39 -07002426// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002427TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002428 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2429 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002430 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002431 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002432 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2433 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2434 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2435 LoggerState pi1_logger = MakeLogger(pi1_);
2436 LoggerState pi2_logger = MakeLogger(pi2_);
2437
2438 StartLogger(&pi1_logger);
2439 StartLogger(&pi2_logger);
2440
2441 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2442 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2443 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2444 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2445 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2446 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2447 for (auto &file : logfiles_) {
2448 struct stat s;
2449 EXPECT_EQ(0, stat(file.c_str(), &s));
2450 }
2451}
2452
2453// Test that renaming the file base dies.
2454TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2455 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002456 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002457 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002458 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2459 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2460 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2461 LoggerState pi1_logger = MakeLogger(pi1_);
2462 StartLogger(&pi1_logger);
2463 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2464 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2465 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2466 "Rename of file base from");
2467}
2468
Austin Schuh8bd96322020-02-13 21:18:22 -08002469// TODO(austin): We can write a test which recreates a logfile and confirms that
2470// we get it back. That is the ultimate test.
2471
Austin Schuh315b96b2020-12-11 21:21:12 -08002472// Tests that we properly recreate forwarded timestamps when replaying a log.
2473// This should be enough that we can then re-run the logger and get a valid log
2474// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002475TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002476 std::vector<std::string> actual_filenames;
2477
Austin Schuh58646e22021-08-23 23:51:46 -07002478 const UUID pi1_boot0 = UUID::Random();
2479 const UUID pi2_boot0 = UUID::Random();
2480 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002481 {
Austin Schuh58646e22021-08-23 23:51:46 -07002482 CHECK_EQ(pi1_index_, 0u);
2483 CHECK_EQ(pi2_index_, 1u);
2484
2485 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2486 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2487 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2488
2489 time_converter_.AddNextTimestamp(
2490 distributed_clock::epoch(),
2491 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2492 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2493 time_converter_.AddNextTimestamp(
2494 distributed_clock::epoch() + reboot_time,
2495 {BootTimestamp::epoch() + reboot_time,
2496 BootTimestamp{
2497 .boot = 1,
2498 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2499 }
2500
2501 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002502 LoggerState pi1_logger = MakeLogger(pi1_);
2503
2504 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002505 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2506 pi1_boot0);
2507 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2508 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002509
2510 StartLogger(&pi1_logger);
2511
2512 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2513
Austin Schuh58646e22021-08-23 23:51:46 -07002514 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002515
2516 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002517 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2518 pi1_boot0);
2519 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2520 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002521
2522 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002523 }
2524
Austin Schuhbfe6c572022-01-27 20:48:20 -08002525 std::sort(actual_filenames.begin(), actual_filenames.end());
2526 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2527 ASSERT_THAT(actual_filenames,
2528 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2529
Austin Schuh72211ae2021-08-05 14:02:30 -07002530 // Confirm that our new oldest timestamps properly update as we reboot and
2531 // rotate.
2532 for (const std::string &file : pi1_reboot_logfiles_) {
2533 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2534 ReadHeader(file);
2535 CHECK(log_header);
2536 if (log_header->message().has_configuration()) {
2537 continue;
2538 }
2539
Austin Schuh58646e22021-08-23 23:51:46 -07002540 const monotonic_clock::time_point monotonic_start_time =
2541 monotonic_clock::time_point(
2542 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2543 const UUID source_node_boot_uuid = UUID::FromString(
2544 log_header->message().source_node_boot_uuid()->string_view());
2545
Austin Schuh72211ae2021-08-05 14:02:30 -07002546 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002547 // The remote message channel should rotate later and have more parts.
2548 // This only is true on the log files with shared remote messages.
2549 //
2550 // TODO(austin): I'm not the most thrilled with this test pattern... It
2551 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002552 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2553 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002554 switch (log_header->message().parts_index()) {
2555 case 0:
2556 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2557 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2558 break;
2559 case 1:
2560 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2561 ASSERT_EQ(monotonic_start_time,
2562 monotonic_clock::epoch() + chrono::seconds(1));
2563 break;
2564 case 2:
2565 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2566 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2567 break;
2568 case 3:
2569 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2570 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2571 chrono::nanoseconds(2322999462))
2572 << " on " << file;
2573 break;
2574 default:
2575 FAIL();
2576 break;
2577 }
2578 } else {
2579 switch (log_header->message().parts_index()) {
2580 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002581 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002582 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2583 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2584 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002585 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002586 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2587 ASSERT_EQ(monotonic_start_time,
2588 monotonic_clock::epoch() + chrono::seconds(1));
2589 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002590 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002591 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002592 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2593 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2594 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002595 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002596 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2597 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2598 chrono::nanoseconds(2322999462))
2599 << " on " << file;
2600 break;
2601 default:
2602 FAIL();
2603 break;
2604 }
Austin Schuh58646e22021-08-23 23:51:46 -07002605 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002606 continue;
2607 }
2608 SCOPED_TRACE(file);
2609 SCOPED_TRACE(aos::FlatbufferToJson(
2610 *log_header, {.multi_line = true, .max_vector_size = 100}));
2611 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2612 ASSERT_EQ(
2613 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2614 EXPECT_EQ(
2615 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2616 monotonic_clock::max_time.time_since_epoch().count());
2617 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2618 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2619 2u);
2620 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2621 monotonic_clock::max_time.time_since_epoch().count());
2622 ASSERT_TRUE(log_header->message()
2623 .has_oldest_remote_unreliable_monotonic_timestamps());
2624 ASSERT_EQ(log_header->message()
2625 .oldest_remote_unreliable_monotonic_timestamps()
2626 ->size(),
2627 2u);
2628 EXPECT_EQ(log_header->message()
2629 .oldest_remote_unreliable_monotonic_timestamps()
2630 ->Get(0),
2631 monotonic_clock::max_time.time_since_epoch().count());
2632 ASSERT_TRUE(log_header->message()
2633 .has_oldest_local_unreliable_monotonic_timestamps());
2634 ASSERT_EQ(log_header->message()
2635 .oldest_local_unreliable_monotonic_timestamps()
2636 ->size(),
2637 2u);
2638 EXPECT_EQ(log_header->message()
2639 .oldest_local_unreliable_monotonic_timestamps()
2640 ->Get(0),
2641 monotonic_clock::max_time.time_since_epoch().count());
2642
2643 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2644 monotonic_clock::time_point(chrono::nanoseconds(
2645 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2646 1)));
2647 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2648 monotonic_clock::time_point(chrono::nanoseconds(
2649 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2650 const monotonic_clock::time_point
2651 oldest_remote_unreliable_monotonic_timestamps =
2652 monotonic_clock::time_point(chrono::nanoseconds(
2653 log_header->message()
2654 .oldest_remote_unreliable_monotonic_timestamps()
2655 ->Get(1)));
2656 const monotonic_clock::time_point
2657 oldest_local_unreliable_monotonic_timestamps =
2658 monotonic_clock::time_point(chrono::nanoseconds(
2659 log_header->message()
2660 .oldest_local_unreliable_monotonic_timestamps()
2661 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002662 const monotonic_clock::time_point
2663 oldest_remote_reliable_monotonic_timestamps =
2664 monotonic_clock::time_point(chrono::nanoseconds(
2665 log_header->message()
2666 .oldest_remote_reliable_monotonic_timestamps()
2667 ->Get(1)));
2668 const monotonic_clock::time_point
2669 oldest_local_reliable_monotonic_timestamps =
2670 monotonic_clock::time_point(chrono::nanoseconds(
2671 log_header->message()
2672 .oldest_local_reliable_monotonic_timestamps()
2673 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002674 const monotonic_clock::time_point
2675 oldest_logger_remote_unreliable_monotonic_timestamps =
2676 monotonic_clock::time_point(chrono::nanoseconds(
2677 log_header->message()
2678 .oldest_logger_remote_unreliable_monotonic_timestamps()
2679 ->Get(0)));
2680 const monotonic_clock::time_point
2681 oldest_logger_local_unreliable_monotonic_timestamps =
2682 monotonic_clock::time_point(chrono::nanoseconds(
2683 log_header->message()
2684 .oldest_logger_local_unreliable_monotonic_timestamps()
2685 ->Get(0)));
2686 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2687 monotonic_clock::max_time);
2688 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2689 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002690 switch (log_header->message().parts_index()) {
2691 case 0:
2692 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2693 monotonic_clock::max_time);
2694 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2695 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2696 monotonic_clock::max_time);
2697 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2698 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002699 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2700 monotonic_clock::max_time);
2701 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2702 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002703 break;
2704 case 1:
2705 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2706 monotonic_clock::time_point(chrono::microseconds(90200)));
2707 EXPECT_EQ(oldest_local_monotonic_timestamps,
2708 monotonic_clock::time_point(chrono::microseconds(90350)));
2709 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2710 monotonic_clock::time_point(chrono::microseconds(90200)));
2711 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2712 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002713 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2714 monotonic_clock::max_time);
2715 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2716 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002717 break;
2718 case 2:
2719 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08002720 monotonic_clock::time_point(chrono::microseconds(90200)))
2721 << file;
2722 EXPECT_EQ(oldest_local_monotonic_timestamps,
2723 monotonic_clock::time_point(chrono::microseconds(90350)))
2724 << file;
2725 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2726 monotonic_clock::time_point(chrono::microseconds(90200)))
2727 << file;
2728 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2729 monotonic_clock::time_point(chrono::microseconds(90350)))
2730 << file;
2731 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2732 monotonic_clock::time_point(chrono::microseconds(100000)))
2733 << file;
2734 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2735 monotonic_clock::time_point(chrono::microseconds(100150)))
2736 << file;
2737 break;
2738 case 3:
2739 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002740 monotonic_clock::time_point(chrono::milliseconds(1323) +
2741 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002742 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002743 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002744 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002745 monotonic_clock::time_point(chrono::milliseconds(1323) +
2746 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002747 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2748 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002749 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2750 monotonic_clock::max_time)
2751 << file;
2752 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2753 monotonic_clock::max_time)
2754 << file;
2755 break;
2756 case 4:
2757 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2758 monotonic_clock::time_point(chrono::milliseconds(1323) +
2759 chrono::microseconds(200)));
2760 EXPECT_EQ(oldest_local_monotonic_timestamps,
2761 monotonic_clock::time_point(chrono::microseconds(10100350)));
2762 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2763 monotonic_clock::time_point(chrono::milliseconds(1323) +
2764 chrono::microseconds(200)));
2765 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2766 monotonic_clock::time_point(chrono::microseconds(10100350)));
2767 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2768 monotonic_clock::time_point(chrono::microseconds(1423000)))
2769 << file;
2770 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2771 monotonic_clock::time_point(chrono::microseconds(10200150)))
2772 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07002773 break;
2774 default:
2775 FAIL();
2776 break;
2777 }
2778 }
2779
Austin Schuh315b96b2020-12-11 21:21:12 -08002780 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002781 {
2782 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002783
Austin Schuh58646e22021-08-23 23:51:46 -07002784 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2785 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002786
Austin Schuh58646e22021-08-23 23:51:46 -07002787 // This sends out the fetched messages and advances time to the start of
2788 // the log file.
2789 reader.Register(&log_reader_factory);
2790
2791 log_reader_factory.Run();
2792
2793 reader.Deregister();
2794 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002795}
2796
Austin Schuh5e14d842022-01-21 12:02:15 -08002797// Tests that we can sort a log which only has timestamps from the remote
2798// because the local message_bridge_client failed to connect.
2799TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
2800 const UUID pi1_boot0 = UUID::Random();
2801 const UUID pi2_boot0 = UUID::Random();
2802 const UUID pi2_boot1 = UUID::Random();
2803 {
2804 CHECK_EQ(pi1_index_, 0u);
2805 CHECK_EQ(pi2_index_, 1u);
2806
2807 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2808 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2809 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2810
2811 time_converter_.AddNextTimestamp(
2812 distributed_clock::epoch(),
2813 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2814 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2815 time_converter_.AddNextTimestamp(
2816 distributed_clock::epoch() + reboot_time,
2817 {BootTimestamp::epoch() + reboot_time,
2818 BootTimestamp{
2819 .boot = 1,
2820 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2821 }
2822 pi2_->Disconnect(pi1_->node());
2823
2824 std::vector<std::string> filenames;
2825 {
2826 LoggerState pi1_logger = MakeLogger(pi1_);
2827
2828 event_loop_factory_.RunFor(chrono::milliseconds(95));
2829 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2830 pi1_boot0);
2831 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2832 pi2_boot0);
2833
2834 StartLogger(&pi1_logger);
2835
2836 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2837
2838 VLOG(1) << "Reboot now!";
2839
2840 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2841 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2842 pi1_boot0);
2843 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2844 pi2_boot1);
2845 pi1_logger.AppendAllFilenames(&filenames);
2846 }
2847
Austin Schuhbfe6c572022-01-27 20:48:20 -08002848 std::sort(filenames.begin(), filenames.end());
2849
Austin Schuh5e14d842022-01-21 12:02:15 -08002850 // Confirm that our new oldest timestamps properly update as we reboot and
2851 // rotate.
2852 size_t timestamp_file_count = 0;
2853 for (const std::string &file : filenames) {
2854 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2855 ReadHeader(file);
2856 CHECK(log_header);
2857
2858 if (log_header->message().has_configuration()) {
2859 continue;
2860 }
2861
2862 const monotonic_clock::time_point monotonic_start_time =
2863 monotonic_clock::time_point(
2864 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2865 const UUID source_node_boot_uuid = UUID::FromString(
2866 log_header->message().source_node_boot_uuid()->string_view());
2867
2868 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2869 ASSERT_EQ(
2870 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2871 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2872 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2873 2u);
2874 ASSERT_TRUE(log_header->message()
2875 .has_oldest_remote_unreliable_monotonic_timestamps());
2876 ASSERT_EQ(log_header->message()
2877 .oldest_remote_unreliable_monotonic_timestamps()
2878 ->size(),
2879 2u);
2880 ASSERT_TRUE(log_header->message()
2881 .has_oldest_local_unreliable_monotonic_timestamps());
2882 ASSERT_EQ(log_header->message()
2883 .oldest_local_unreliable_monotonic_timestamps()
2884 ->size(),
2885 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08002886 ASSERT_TRUE(log_header->message()
2887 .has_oldest_remote_reliable_monotonic_timestamps());
2888 ASSERT_EQ(log_header->message()
2889 .oldest_remote_reliable_monotonic_timestamps()
2890 ->size(),
2891 2u);
2892 ASSERT_TRUE(log_header->message()
2893 .has_oldest_local_reliable_monotonic_timestamps());
2894 ASSERT_EQ(log_header->message()
2895 .oldest_local_reliable_monotonic_timestamps()
2896 ->size(),
2897 2u);
2898
2899 ASSERT_TRUE(
2900 log_header->message()
2901 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
2902 ASSERT_EQ(log_header->message()
2903 .oldest_logger_remote_unreliable_monotonic_timestamps()
2904 ->size(),
2905 2u);
2906 ASSERT_TRUE(log_header->message()
2907 .has_oldest_logger_local_unreliable_monotonic_timestamps());
2908 ASSERT_EQ(log_header->message()
2909 .oldest_logger_local_unreliable_monotonic_timestamps()
2910 ->size(),
2911 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08002912
2913 if (log_header->message().node()->name()->string_view() != "pi1") {
2914 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
2915 std::string::npos);
2916
2917 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2918 ReadNthMessage(file, 0);
2919 CHECK(msg);
2920
2921 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2922 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2923
2924 const monotonic_clock::time_point
2925 expected_oldest_local_monotonic_timestamps(
2926 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2927 const monotonic_clock::time_point
2928 expected_oldest_remote_monotonic_timestamps(
2929 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002930 const monotonic_clock::time_point
2931 expected_oldest_timestamp_monotonic_timestamps(
2932 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08002933
2934 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2935 monotonic_clock::min_time);
2936 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2937 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08002938 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
2939 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08002940
2941 ++timestamp_file_count;
2942 // Since the log file is from the perspective of the other node,
2943 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2944 monotonic_clock::time_point(chrono::nanoseconds(
2945 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2946 0)));
2947 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2948 monotonic_clock::time_point(chrono::nanoseconds(
2949 log_header->message().oldest_local_monotonic_timestamps()->Get(
2950 0)));
2951 const monotonic_clock::time_point
2952 oldest_remote_unreliable_monotonic_timestamps =
2953 monotonic_clock::time_point(chrono::nanoseconds(
2954 log_header->message()
2955 .oldest_remote_unreliable_monotonic_timestamps()
2956 ->Get(0)));
2957 const monotonic_clock::time_point
2958 oldest_local_unreliable_monotonic_timestamps =
2959 monotonic_clock::time_point(chrono::nanoseconds(
2960 log_header->message()
2961 .oldest_local_unreliable_monotonic_timestamps()
2962 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002963 const monotonic_clock::time_point
2964 oldest_remote_reliable_monotonic_timestamps =
2965 monotonic_clock::time_point(chrono::nanoseconds(
2966 log_header->message()
2967 .oldest_remote_reliable_monotonic_timestamps()
2968 ->Get(0)));
2969 const monotonic_clock::time_point
2970 oldest_local_reliable_monotonic_timestamps =
2971 monotonic_clock::time_point(chrono::nanoseconds(
2972 log_header->message()
2973 .oldest_local_reliable_monotonic_timestamps()
2974 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002975 const monotonic_clock::time_point
2976 oldest_logger_remote_unreliable_monotonic_timestamps =
2977 monotonic_clock::time_point(chrono::nanoseconds(
2978 log_header->message()
2979 .oldest_logger_remote_unreliable_monotonic_timestamps()
2980 ->Get(1)));
2981 const monotonic_clock::time_point
2982 oldest_logger_local_unreliable_monotonic_timestamps =
2983 monotonic_clock::time_point(chrono::nanoseconds(
2984 log_header->message()
2985 .oldest_logger_local_unreliable_monotonic_timestamps()
2986 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08002987
Austin Schuh01f3b392022-01-25 20:03:09 -08002988 const Channel *channel =
2989 event_loop_factory_.configuration()->channels()->Get(
2990 msg->message().channel_index());
2991 const Connection *connection = configuration::ConnectionToNode(
2992 channel, configuration::GetNode(
2993 event_loop_factory_.configuration(),
2994 log_header->message().node()->name()->string_view()));
2995
2996 const bool reliable = connection->time_to_live() == 0;
2997
Austin Schuhf5f99f32022-02-07 20:05:37 -08002998 SCOPED_TRACE(file);
2999 SCOPED_TRACE(aos::FlatbufferToJson(
3000 *log_header, {.multi_line = true, .max_vector_size = 100}));
3001
Austin Schuh01f3b392022-01-25 20:03:09 -08003002 if (shared()) {
3003 // Confirm that the oldest timestamps match what we expect. Based on
3004 // what we are doing, we know that the oldest time is the first
3005 // message's time.
3006 //
3007 // This makes the test robust to both the split and combined config
3008 // tests.
3009 switch (log_header->message().parts_index()) {
3010 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08003011 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3012 expected_oldest_remote_monotonic_timestamps);
3013 EXPECT_EQ(oldest_local_monotonic_timestamps,
3014 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003015 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3016 expected_oldest_local_monotonic_timestamps) << file;
3017 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3018 expected_oldest_timestamp_monotonic_timestamps) << file;
3019
Austin Schuh01f3b392022-01-25 20:03:09 -08003020 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003021 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3022 expected_oldest_remote_monotonic_timestamps);
3023 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3024 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08003025 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3026 monotonic_clock::max_time);
3027 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3028 monotonic_clock::max_time);
3029 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003030 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3031 monotonic_clock::max_time);
3032 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3033 monotonic_clock::max_time);
3034 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3035 expected_oldest_remote_monotonic_timestamps);
3036 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3037 expected_oldest_local_monotonic_timestamps);
3038 }
3039 break;
3040 case 1:
3041 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3042 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3043 EXPECT_EQ(oldest_local_monotonic_timestamps,
3044 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003045 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3046 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3047 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3048 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003049 if (reliable) {
3050 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3051 expected_oldest_remote_monotonic_timestamps);
3052 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3053 expected_oldest_local_monotonic_timestamps);
3054 EXPECT_EQ(
3055 oldest_remote_unreliable_monotonic_timestamps,
3056 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3057 EXPECT_EQ(
3058 oldest_local_unreliable_monotonic_timestamps,
3059 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3060 } else {
3061 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3062 monotonic_clock::max_time);
3063 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3064 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003065 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3066 expected_oldest_remote_monotonic_timestamps);
3067 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3068 expected_oldest_local_monotonic_timestamps);
3069 }
3070 break;
3071 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003072 EXPECT_EQ(
3073 oldest_remote_monotonic_timestamps,
3074 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3075 EXPECT_EQ(
3076 oldest_local_monotonic_timestamps,
3077 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003078 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3079 expected_oldest_local_monotonic_timestamps) << file;
3080 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3081 expected_oldest_timestamp_monotonic_timestamps) << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003082 if (reliable) {
3083 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3084 expected_oldest_remote_monotonic_timestamps);
3085 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3086 expected_oldest_local_monotonic_timestamps);
3087 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3088 monotonic_clock::max_time);
3089 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3090 monotonic_clock::max_time);
3091 } else {
3092 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3093 monotonic_clock::max_time);
3094 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3095 monotonic_clock::max_time);
3096 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3097 expected_oldest_remote_monotonic_timestamps);
3098 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3099 expected_oldest_local_monotonic_timestamps);
3100 }
3101 break;
3102
3103 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003104 EXPECT_EQ(
3105 oldest_remote_monotonic_timestamps,
3106 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3107 EXPECT_EQ(
3108 oldest_local_monotonic_timestamps,
3109 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3110 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3111 expected_oldest_remote_monotonic_timestamps);
3112 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3113 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003114 EXPECT_EQ(
3115 oldest_logger_remote_unreliable_monotonic_timestamps,
3116 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3117 EXPECT_EQ(
3118 oldest_logger_local_unreliable_monotonic_timestamps,
3119 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003120 break;
3121 default:
3122 FAIL();
3123 break;
3124 }
3125
3126 switch (log_header->message().parts_index()) {
3127 case 0:
3128 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3129 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3130 break;
3131 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003132 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003133 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3134 break;
3135 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003136 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3137 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3138 break;
3139 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003140 if (shared()) {
3141 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3142 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003143 break;
3144 }
3145 [[fallthrough]];
3146 default:
3147 FAIL();
3148 break;
3149 }
3150 } else {
3151 switch (log_header->message().parts_index()) {
3152 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003153 if (reliable) {
3154 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3155 monotonic_clock::max_time);
3156 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3157 monotonic_clock::max_time);
3158 EXPECT_EQ(
3159 oldest_logger_remote_unreliable_monotonic_timestamps,
3160 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3161 << file;
3162 EXPECT_EQ(
3163 oldest_logger_local_unreliable_monotonic_timestamps,
3164 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3165 << file;
3166 } else {
3167 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3168 expected_oldest_remote_monotonic_timestamps);
3169 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3170 expected_oldest_local_monotonic_timestamps);
3171 EXPECT_EQ(
3172 oldest_logger_remote_unreliable_monotonic_timestamps,
3173 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3174 << file;
3175 EXPECT_EQ(
3176 oldest_logger_local_unreliable_monotonic_timestamps,
3177 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3178 << file;
3179 }
3180 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003181 case 1:
3182 if (reliable) {
3183 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3184 monotonic_clock::max_time);
3185 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3186 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003187 EXPECT_EQ(
3188 oldest_logger_remote_unreliable_monotonic_timestamps,
3189 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3190 EXPECT_EQ(
3191 oldest_logger_local_unreliable_monotonic_timestamps,
3192 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003193 } else {
3194 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3195 expected_oldest_remote_monotonic_timestamps);
3196 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3197 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003198 EXPECT_EQ(
3199 oldest_logger_remote_unreliable_monotonic_timestamps,
3200 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3201 EXPECT_EQ(
3202 oldest_logger_local_unreliable_monotonic_timestamps,
3203 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003204 }
3205 break;
3206 default:
3207 FAIL();
3208 break;
3209 }
3210
3211 switch (log_header->message().parts_index()) {
3212 case 0:
3213 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3214 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3215 break;
3216 case 1:
3217 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3218 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3219 break;
3220 default:
3221 FAIL();
3222 break;
3223 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003224 }
3225
3226 continue;
3227 }
3228 EXPECT_EQ(
3229 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3230 monotonic_clock::max_time.time_since_epoch().count());
3231 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3232 monotonic_clock::max_time.time_since_epoch().count());
3233 EXPECT_EQ(log_header->message()
3234 .oldest_remote_unreliable_monotonic_timestamps()
3235 ->Get(0),
3236 monotonic_clock::max_time.time_since_epoch().count());
3237 EXPECT_EQ(log_header->message()
3238 .oldest_local_unreliable_monotonic_timestamps()
3239 ->Get(0),
3240 monotonic_clock::max_time.time_since_epoch().count());
3241
3242 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3243 monotonic_clock::time_point(chrono::nanoseconds(
3244 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3245 1)));
3246 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3247 monotonic_clock::time_point(chrono::nanoseconds(
3248 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3249 const monotonic_clock::time_point
3250 oldest_remote_unreliable_monotonic_timestamps =
3251 monotonic_clock::time_point(chrono::nanoseconds(
3252 log_header->message()
3253 .oldest_remote_unreliable_monotonic_timestamps()
3254 ->Get(1)));
3255 const monotonic_clock::time_point
3256 oldest_local_unreliable_monotonic_timestamps =
3257 monotonic_clock::time_point(chrono::nanoseconds(
3258 log_header->message()
3259 .oldest_local_unreliable_monotonic_timestamps()
3260 ->Get(1)));
3261 switch (log_header->message().parts_index()) {
3262 case 0:
3263 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3264 monotonic_clock::max_time);
3265 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3266 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3267 monotonic_clock::max_time);
3268 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3269 monotonic_clock::max_time);
3270 break;
3271 default:
3272 FAIL();
3273 break;
3274 }
3275 }
3276
Austin Schuh01f3b392022-01-25 20:03:09 -08003277 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003278 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003279 } else {
3280 EXPECT_EQ(timestamp_file_count, 4u);
3281 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003282
Austin Schuhe2373e22022-01-21 12:25:17 -08003283 // Confirm that we can actually sort the resulting log and read it.
3284 {
3285 LogReader reader(SortParts(filenames));
3286
3287 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3288 log_reader_factory.set_send_delay(chrono::microseconds(0));
3289
3290 // This sends out the fetched messages and advances time to the start of
3291 // the log file.
3292 reader.Register(&log_reader_factory);
3293
3294 log_reader_factory.Run();
3295
3296 reader.Deregister();
3297 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003298}
3299
Austin Schuhc9049732020-12-21 22:27:15 -08003300// Tests that we properly handle one direction of message_bridge being
3301// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003302TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003303 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003304 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003305 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003306
3307 time_converter_.AddMonotonic(
3308 {chrono::milliseconds(10000),
3309 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003310 {
3311 LoggerState pi1_logger = MakeLogger(pi1_);
3312
3313 event_loop_factory_.RunFor(chrono::milliseconds(95));
3314
3315 StartLogger(&pi1_logger);
3316
3317 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3318 }
3319
3320 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3321 // to confirm the right thing happened.
3322 ConfirmReadable(pi1_single_direction_logfiles_);
3323}
3324
3325// Tests that we properly handle one direction of message_bridge being
3326// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003327TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003328 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003329 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003330 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003331
3332 time_converter_.AddMonotonic(
3333 {chrono::milliseconds(10000),
3334 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3335 {
3336 LoggerState pi1_logger = MakeLogger(pi1_);
3337
3338 event_loop_factory_.RunFor(chrono::milliseconds(95));
3339
3340 StartLogger(&pi1_logger);
3341
3342 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3343 }
3344
3345 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3346 // to confirm the right thing happened.
3347 ConfirmReadable(pi1_single_direction_logfiles_);
3348}
3349
Austin Schuhe9f00232021-09-16 18:04:23 -07003350// Tests that we explode if someone passes in a part file twice with a better
3351// error than an out of order error.
3352TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3353 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003354 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003355 {
3356 LoggerState pi1_logger = MakeLogger(pi1_);
3357
3358 event_loop_factory_.RunFor(chrono::milliseconds(95));
3359
3360 StartLogger(&pi1_logger);
3361
3362 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3363 }
3364
3365 std::vector<std::string> duplicates;
3366 for (const std::string &f : pi1_single_direction_logfiles_) {
3367 duplicates.emplace_back(f);
3368 duplicates.emplace_back(f);
3369 }
3370 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3371}
3372
Austin Schuh87dd3832021-01-01 23:07:31 -08003373// Tests that we properly handle a dead node. Do this by just disconnecting it
3374// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003375TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003376 pi1_->Disconnect(pi2_->node());
3377 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003378 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003379 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003380 {
3381 LoggerState pi1_logger = MakeLogger(pi1_);
3382
3383 event_loop_factory_.RunFor(chrono::milliseconds(95));
3384
3385 StartLogger(&pi1_logger);
3386
3387 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3388 }
3389
3390 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3391 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003392 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003393}
3394
Austin Schuhcdd90272021-03-15 12:46:16 -07003395constexpr std::string_view kCombinedConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08003396 "b8114cd99e9c606b7517d8f478bf16513aef550f23f317720667314cb261f689");
Austin Schuhcdd90272021-03-15 12:46:16 -07003397constexpr std::string_view kSplitConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08003398 "60943d0a46afa6028c8ae276e7b4900b35892f1f53b1818056e7d04463709c5b");
Austin Schuhcdd90272021-03-15 12:46:16 -07003399
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003400INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003401 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003402 ::testing::Combine(::testing::Values(
3403 ConfigParams{
3404 "multinode_pingpong_combined_config.json", true,
3405 kCombinedConfigSha1},
3406 ConfigParams{"multinode_pingpong_split_config.json",
3407 false, kSplitConfigSha1}),
3408 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003409
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003410INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003411 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003412 ::testing::Combine(::testing::Values(
3413 ConfigParams{
3414 "multinode_pingpong_combined_config.json", true,
3415 kCombinedConfigSha1},
3416 ConfigParams{"multinode_pingpong_split_config.json",
3417 false, kSplitConfigSha1}),
3418 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003419
Austin Schuh5b728b72021-06-16 14:57:15 -07003420// Tests that we can relog with a different config. This makes most sense when
3421// you are trying to edit a log and want to use channel renaming + the original
3422// config in the new log.
3423TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3424 time_converter_.StartEqual();
3425 {
3426 LoggerState pi1_logger = MakeLogger(pi1_);
3427 LoggerState pi2_logger = MakeLogger(pi2_);
3428
3429 event_loop_factory_.RunFor(chrono::milliseconds(95));
3430
3431 StartLogger(&pi1_logger);
3432 StartLogger(&pi2_logger);
3433
3434 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3435 }
3436
3437 LogReader reader(SortParts(logfiles_));
3438 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3439
3440 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3441 log_reader_factory.set_send_delay(chrono::microseconds(0));
3442
3443 // This sends out the fetched messages and advances time to the start of the
3444 // log file.
3445 reader.Register(&log_reader_factory);
3446
3447 const Node *pi1 =
3448 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3449 const Node *pi2 =
3450 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3451
3452 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3453 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3454 LOG(INFO) << "now pi1 "
3455 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3456 LOG(INFO) << "now pi2 "
3457 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3458
3459 EXPECT_THAT(reader.LoggedNodes(),
3460 ::testing::ElementsAre(
3461 configuration::GetNode(reader.logged_configuration(), pi1),
3462 configuration::GetNode(reader.logged_configuration(), pi2)));
3463
3464 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3465
3466 // And confirm we can re-create a log again, while checking the contents.
3467 std::vector<std::string> log_files;
3468 {
3469 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003470 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003471 &log_reader_factory, reader.logged_configuration());
3472 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003473 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003474 &log_reader_factory, reader.logged_configuration());
3475
Austin Schuh3e20c692021-11-16 20:43:16 -08003476 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3477 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003478
3479 log_reader_factory.Run();
3480
3481 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3482 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3483 }
3484 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3485 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3486 }
3487 }
3488
3489 reader.Deregister();
3490
3491 // And verify that we can run the LogReader over the relogged files without
3492 // hitting any fatal errors.
3493 {
3494 LogReader relogged_reader(SortParts(log_files));
3495 relogged_reader.Register();
3496
3497 relogged_reader.event_loop_factory()->Run();
3498 }
3499}
Austin Schuha04efed2021-01-24 18:04:20 -08003500
Austin Schuh3e20c692021-11-16 20:43:16 -08003501// Tests that we properly replay a log where the start time for a node is before
3502// any data on the node. This can happen if the logger starts before data is
3503// published. While the scenario below is a bit convoluted, we have seen logs
3504// like this generated out in the wild.
3505TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3506 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3507 aos::configuration::ReadConfig(ArtifactPath(
3508 "aos/events/logging/multinode_pingpong_split3_config.json"));
3509 message_bridge::TestingTimeConverter time_converter(
3510 configuration::NodesCount(&config.message()));
3511 SimulatedEventLoopFactory event_loop_factory(&config.message());
3512 event_loop_factory.SetTimeConverter(&time_converter);
3513 NodeEventLoopFactory *const pi1 =
3514 event_loop_factory.GetNodeEventLoopFactory("pi1");
3515 const size_t pi1_index = configuration::GetNodeIndex(
3516 event_loop_factory.configuration(), pi1->node());
3517 NodeEventLoopFactory *const pi2 =
3518 event_loop_factory.GetNodeEventLoopFactory("pi2");
3519 const size_t pi2_index = configuration::GetNodeIndex(
3520 event_loop_factory.configuration(), pi2->node());
3521 NodeEventLoopFactory *const pi3 =
3522 event_loop_factory.GetNodeEventLoopFactory("pi3");
3523 const size_t pi3_index = configuration::GetNodeIndex(
3524 event_loop_factory.configuration(), pi3->node());
3525
3526 const std::string kLogfile1_1 =
3527 aos::testing::TestTmpDir() + "/multi_logfile1/";
3528 const std::string kLogfile2_1 =
3529 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3530 const std::string kLogfile2_2 =
3531 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3532 const std::string kLogfile3_1 =
3533 aos::testing::TestTmpDir() + "/multi_logfile3/";
3534 util::UnlinkRecursive(kLogfile1_1);
3535 util::UnlinkRecursive(kLogfile2_1);
3536 util::UnlinkRecursive(kLogfile2_2);
3537 util::UnlinkRecursive(kLogfile3_1);
3538 const UUID pi1_boot0 = UUID::Random();
3539 const UUID pi2_boot0 = UUID::Random();
3540 const UUID pi2_boot1 = UUID::Random();
3541 const UUID pi3_boot0 = UUID::Random();
3542 {
3543 CHECK_EQ(pi1_index, 0u);
3544 CHECK_EQ(pi2_index, 1u);
3545 CHECK_EQ(pi3_index, 2u);
3546
3547 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3548 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3549 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3550 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3551
3552 time_converter.AddNextTimestamp(
3553 distributed_clock::epoch(),
3554 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3555 BootTimestamp::epoch()});
3556 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3557 time_converter.AddNextTimestamp(
3558 distributed_clock::epoch() + reboot_time,
3559 {BootTimestamp::epoch() + reboot_time,
3560 BootTimestamp{
3561 .boot = 1,
3562 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3563 BootTimestamp::epoch() + reboot_time});
3564 }
3565
3566 // Make everything perfectly quiet.
3567 event_loop_factory.SkipTimingReport();
3568 event_loop_factory.DisableStatistics();
3569
3570 std::vector<std::string> filenames;
3571 {
3572 LoggerState pi1_logger = LoggerState::MakeLogger(
3573 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3574 LoggerState pi3_logger = LoggerState::MakeLogger(
3575 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3576 {
3577 // And now start the logger.
3578 LoggerState pi2_logger = LoggerState::MakeLogger(
3579 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3580
3581 event_loop_factory.RunFor(chrono::milliseconds(1000));
3582
3583 pi1_logger.StartLogger(kLogfile1_1);
3584 pi3_logger.StartLogger(kLogfile3_1);
3585 pi2_logger.StartLogger(kLogfile2_1);
3586
3587 event_loop_factory.RunFor(chrono::milliseconds(10000));
3588
3589 // Now that we've got a start time in the past, turn on data.
3590 event_loop_factory.EnableStatistics();
3591 std::unique_ptr<aos::EventLoop> ping_event_loop =
3592 pi1->MakeEventLoop("ping");
3593 Ping ping(ping_event_loop.get());
3594
3595 pi2->AlwaysStart<Pong>("pong");
3596
3597 event_loop_factory.RunFor(chrono::milliseconds(3000));
3598
3599 pi2_logger.AppendAllFilenames(&filenames);
3600
3601 // Stop logging on pi2 before rebooting and completely shut off all
3602 // messages on pi2.
3603 pi2->DisableStatistics();
3604 pi1->Disconnect(pi2->node());
3605 pi2->Disconnect(pi1->node());
3606 }
3607 event_loop_factory.RunFor(chrono::milliseconds(7000));
3608 // pi2 now reboots.
3609 {
3610 event_loop_factory.RunFor(chrono::milliseconds(1000));
3611
3612 // Start logging again on pi2 after it is up.
3613 LoggerState pi2_logger = LoggerState::MakeLogger(
3614 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3615 pi2_logger.StartLogger(kLogfile2_2);
3616
3617 event_loop_factory.RunFor(chrono::milliseconds(10000));
3618 // And, now that we have a start time in the log, turn data back on.
3619 pi2->EnableStatistics();
3620 pi1->Connect(pi2->node());
3621 pi2->Connect(pi1->node());
3622
3623 pi2->AlwaysStart<Pong>("pong");
3624 std::unique_ptr<aos::EventLoop> ping_event_loop =
3625 pi1->MakeEventLoop("ping");
3626 Ping ping(ping_event_loop.get());
3627
3628 event_loop_factory.RunFor(chrono::milliseconds(3000));
3629
3630 pi2_logger.AppendAllFilenames(&filenames);
3631 }
3632
3633 pi1_logger.AppendAllFilenames(&filenames);
3634 pi3_logger.AppendAllFilenames(&filenames);
3635 }
3636
3637 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3638 // to confirm the right thing happened.
3639 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003640 auto result = ConfirmReadable(filenames);
3641 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3642 chrono::seconds(1)));
3643 EXPECT_THAT(result[0].second,
3644 ::testing::ElementsAre(realtime_clock::epoch() +
3645 chrono::microseconds(34990350)));
3646
3647 EXPECT_THAT(result[1].first,
3648 ::testing::ElementsAre(
3649 realtime_clock::epoch() + chrono::seconds(1),
3650 realtime_clock::epoch() + chrono::microseconds(3323000)));
3651 EXPECT_THAT(result[1].second,
3652 ::testing::ElementsAre(
3653 realtime_clock::epoch() + chrono::microseconds(13990200),
3654 realtime_clock::epoch() + chrono::microseconds(16313200)));
3655
3656 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3657 chrono::seconds(1)));
3658 EXPECT_THAT(result[2].second,
3659 ::testing::ElementsAre(realtime_clock::epoch() +
3660 chrono::microseconds(34900150)));
Austin Schuh3e20c692021-11-16 20:43:16 -08003661}
3662
Austin Schuh5dd22842021-11-17 16:09:39 -08003663// Tests that local data before remote data after reboot is properly replayed.
3664// We only trigger a reboot in the timestamp interpolation function when solving
3665// the timestamp problem when we actually have a point in the function. This
3666// originally only happened when a point passes the noncausal filter. At the
3667// start of time for the second boot, if we aren't careful, we will have
3668// messages which need to be published at times before the boot. This happens
3669// when a local message is in the log before a forwarded message, so there is no
3670// point in the interpolation function. This delays the reboot. So, we need to
3671// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08003672TEST(MultinodeRebootLoggerTest,
3673 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08003674 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3675 aos::configuration::ReadConfig(ArtifactPath(
3676 "aos/events/logging/multinode_pingpong_split3_config.json"));
3677 message_bridge::TestingTimeConverter time_converter(
3678 configuration::NodesCount(&config.message()));
3679 SimulatedEventLoopFactory event_loop_factory(&config.message());
3680 event_loop_factory.SetTimeConverter(&time_converter);
3681 NodeEventLoopFactory *const pi1 =
3682 event_loop_factory.GetNodeEventLoopFactory("pi1");
3683 const size_t pi1_index = configuration::GetNodeIndex(
3684 event_loop_factory.configuration(), pi1->node());
3685 NodeEventLoopFactory *const pi2 =
3686 event_loop_factory.GetNodeEventLoopFactory("pi2");
3687 const size_t pi2_index = configuration::GetNodeIndex(
3688 event_loop_factory.configuration(), pi2->node());
3689 NodeEventLoopFactory *const pi3 =
3690 event_loop_factory.GetNodeEventLoopFactory("pi3");
3691 const size_t pi3_index = configuration::GetNodeIndex(
3692 event_loop_factory.configuration(), pi3->node());
3693
3694 const std::string kLogfile1_1 =
3695 aos::testing::TestTmpDir() + "/multi_logfile1/";
3696 const std::string kLogfile2_1 =
3697 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3698 const std::string kLogfile2_2 =
3699 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3700 const std::string kLogfile3_1 =
3701 aos::testing::TestTmpDir() + "/multi_logfile3/";
3702 util::UnlinkRecursive(kLogfile1_1);
3703 util::UnlinkRecursive(kLogfile2_1);
3704 util::UnlinkRecursive(kLogfile2_2);
3705 util::UnlinkRecursive(kLogfile3_1);
3706 const UUID pi1_boot0 = UUID::Random();
3707 const UUID pi2_boot0 = UUID::Random();
3708 const UUID pi2_boot1 = UUID::Random();
3709 const UUID pi3_boot0 = UUID::Random();
3710 {
3711 CHECK_EQ(pi1_index, 0u);
3712 CHECK_EQ(pi2_index, 1u);
3713 CHECK_EQ(pi3_index, 2u);
3714
3715 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3716 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3717 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3718 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3719
3720 time_converter.AddNextTimestamp(
3721 distributed_clock::epoch(),
3722 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3723 BootTimestamp::epoch()});
3724 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3725 time_converter.AddNextTimestamp(
3726 distributed_clock::epoch() + reboot_time,
3727 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003728 BootTimestamp{.boot = 1,
3729 .time = monotonic_clock::epoch() + reboot_time +
3730 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08003731 BootTimestamp::epoch() + reboot_time});
3732 }
3733
3734 std::vector<std::string> filenames;
3735 {
3736 LoggerState pi1_logger = LoggerState::MakeLogger(
3737 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3738 LoggerState pi3_logger = LoggerState::MakeLogger(
3739 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3740 {
3741 // And now start the logger.
3742 LoggerState pi2_logger = LoggerState::MakeLogger(
3743 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3744
3745 pi1_logger.StartLogger(kLogfile1_1);
3746 pi3_logger.StartLogger(kLogfile3_1);
3747 pi2_logger.StartLogger(kLogfile2_1);
3748
3749 event_loop_factory.RunFor(chrono::milliseconds(1005));
3750
3751 // Now that we've got a start time in the past, turn on data.
3752 std::unique_ptr<aos::EventLoop> ping_event_loop =
3753 pi1->MakeEventLoop("ping");
3754 Ping ping(ping_event_loop.get());
3755
3756 pi2->AlwaysStart<Pong>("pong");
3757
3758 event_loop_factory.RunFor(chrono::milliseconds(3000));
3759
3760 pi2_logger.AppendAllFilenames(&filenames);
3761
3762 // Disable any remote messages on pi2.
3763 pi1->Disconnect(pi2->node());
3764 pi2->Disconnect(pi1->node());
3765 }
3766 event_loop_factory.RunFor(chrono::milliseconds(995));
3767 // pi2 now reboots at 5 seconds.
3768 {
3769 event_loop_factory.RunFor(chrono::milliseconds(1000));
3770
3771 // Make local stuff happen before we start logging and connect the remote.
3772 pi2->AlwaysStart<Pong>("pong");
3773 std::unique_ptr<aos::EventLoop> ping_event_loop =
3774 pi1->MakeEventLoop("ping");
3775 Ping ping(ping_event_loop.get());
3776 event_loop_factory.RunFor(chrono::milliseconds(1005));
3777
3778 // Start logging again on pi2 after it is up.
3779 LoggerState pi2_logger = LoggerState::MakeLogger(
3780 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3781 pi2_logger.StartLogger(kLogfile2_2);
3782
3783 // And allow remote messages now that we have some local ones.
3784 pi1->Connect(pi2->node());
3785 pi2->Connect(pi1->node());
3786
3787 event_loop_factory.RunFor(chrono::milliseconds(1000));
3788
3789 event_loop_factory.RunFor(chrono::milliseconds(3000));
3790
3791 pi2_logger.AppendAllFilenames(&filenames);
3792 }
3793
3794 pi1_logger.AppendAllFilenames(&filenames);
3795 pi3_logger.AppendAllFilenames(&filenames);
3796 }
3797
3798 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3799 // to confirm the right thing happened.
3800 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003801 auto result = ConfirmReadable(filenames);
3802
3803 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3804 EXPECT_THAT(result[0].second,
3805 ::testing::ElementsAre(realtime_clock::epoch() +
3806 chrono::microseconds(11000350)));
3807
3808 EXPECT_THAT(result[1].first,
3809 ::testing::ElementsAre(
3810 realtime_clock::epoch(),
3811 realtime_clock::epoch() + chrono::microseconds(107005000)));
3812 EXPECT_THAT(result[1].second,
3813 ::testing::ElementsAre(
3814 realtime_clock::epoch() + chrono::microseconds(4000150),
3815 realtime_clock::epoch() + chrono::microseconds(111000200)));
3816
3817 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3818 EXPECT_THAT(result[2].second,
3819 ::testing::ElementsAre(realtime_clock::epoch() +
3820 chrono::microseconds(11000150)));
3821
3822 auto start_stop_result = ConfirmReadable(
3823 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3824 realtime_clock::epoch() + chrono::milliseconds(3000));
3825
3826 EXPECT_THAT(start_stop_result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3827 chrono::seconds(2)));
3828 EXPECT_THAT(start_stop_result[0].second, ::testing::ElementsAre(realtime_clock::epoch() +
3829 chrono::seconds(3)));
3830 EXPECT_THAT(start_stop_result[1].first, ::testing::ElementsAre(realtime_clock::epoch() +
3831 chrono::seconds(2)));
3832 EXPECT_THAT(start_stop_result[1].second, ::testing::ElementsAre(realtime_clock::epoch() +
3833 chrono::seconds(3)));
3834 EXPECT_THAT(start_stop_result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3835 chrono::seconds(2)));
3836 EXPECT_THAT(start_stop_result[2].second, ::testing::ElementsAre(realtime_clock::epoch() +
3837 chrono::seconds(3)));
Austin Schuh5dd22842021-11-17 16:09:39 -08003838}
3839
Austin Schuhe33c08d2022-02-03 18:15:21 -08003840// Tests that setting the start and stop flags across a reboot works as
3841// expected.
3842TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
3843 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3844 aos::configuration::ReadConfig(ArtifactPath(
3845 "aos/events/logging/multinode_pingpong_split3_config.json"));
3846 message_bridge::TestingTimeConverter time_converter(
3847 configuration::NodesCount(&config.message()));
3848 SimulatedEventLoopFactory event_loop_factory(&config.message());
3849 event_loop_factory.SetTimeConverter(&time_converter);
3850 NodeEventLoopFactory *const pi1 =
3851 event_loop_factory.GetNodeEventLoopFactory("pi1");
3852 const size_t pi1_index = configuration::GetNodeIndex(
3853 event_loop_factory.configuration(), pi1->node());
3854 NodeEventLoopFactory *const pi2 =
3855 event_loop_factory.GetNodeEventLoopFactory("pi2");
3856 const size_t pi2_index = configuration::GetNodeIndex(
3857 event_loop_factory.configuration(), pi2->node());
3858 NodeEventLoopFactory *const pi3 =
3859 event_loop_factory.GetNodeEventLoopFactory("pi3");
3860 const size_t pi3_index = configuration::GetNodeIndex(
3861 event_loop_factory.configuration(), pi3->node());
3862
3863 const std::string kLogfile1_1 =
3864 aos::testing::TestTmpDir() + "/multi_logfile1/";
3865 const std::string kLogfile2_1 =
3866 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3867 const std::string kLogfile2_2 =
3868 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3869 const std::string kLogfile3_1 =
3870 aos::testing::TestTmpDir() + "/multi_logfile3/";
3871 util::UnlinkRecursive(kLogfile1_1);
3872 util::UnlinkRecursive(kLogfile2_1);
3873 util::UnlinkRecursive(kLogfile2_2);
3874 util::UnlinkRecursive(kLogfile3_1);
3875 {
3876 CHECK_EQ(pi1_index, 0u);
3877 CHECK_EQ(pi2_index, 1u);
3878 CHECK_EQ(pi3_index, 2u);
3879
3880 time_converter.AddNextTimestamp(
3881 distributed_clock::epoch(),
3882 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3883 BootTimestamp::epoch()});
3884 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3885 time_converter.AddNextTimestamp(
3886 distributed_clock::epoch() + reboot_time,
3887 {BootTimestamp::epoch() + reboot_time,
3888 BootTimestamp{.boot = 1,
3889 .time = monotonic_clock::epoch() + reboot_time},
3890 BootTimestamp::epoch() + reboot_time});
3891 }
3892
3893 std::vector<std::string> filenames;
3894 {
3895 LoggerState pi1_logger = LoggerState::MakeLogger(
3896 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3897 LoggerState pi3_logger = LoggerState::MakeLogger(
3898 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3899 {
3900 // And now start the logger.
3901 LoggerState pi2_logger = LoggerState::MakeLogger(
3902 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3903
3904 pi1_logger.StartLogger(kLogfile1_1);
3905 pi3_logger.StartLogger(kLogfile3_1);
3906 pi2_logger.StartLogger(kLogfile2_1);
3907
3908 event_loop_factory.RunFor(chrono::milliseconds(1005));
3909
3910 // Now that we've got a start time in the past, turn on data.
3911 std::unique_ptr<aos::EventLoop> ping_event_loop =
3912 pi1->MakeEventLoop("ping");
3913 Ping ping(ping_event_loop.get());
3914
3915 pi2->AlwaysStart<Pong>("pong");
3916
3917 event_loop_factory.RunFor(chrono::milliseconds(3000));
3918
3919 pi2_logger.AppendAllFilenames(&filenames);
3920 }
3921 event_loop_factory.RunFor(chrono::milliseconds(995));
3922 // pi2 now reboots at 5 seconds.
3923 {
3924 event_loop_factory.RunFor(chrono::milliseconds(1000));
3925
3926 // Make local stuff happen before we start logging and connect the remote.
3927 pi2->AlwaysStart<Pong>("pong");
3928 std::unique_ptr<aos::EventLoop> ping_event_loop =
3929 pi1->MakeEventLoop("ping");
3930 Ping ping(ping_event_loop.get());
3931 event_loop_factory.RunFor(chrono::milliseconds(5));
3932
3933 // Start logging again on pi2 after it is up.
3934 LoggerState pi2_logger = LoggerState::MakeLogger(
3935 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3936 pi2_logger.StartLogger(kLogfile2_2);
3937
3938 event_loop_factory.RunFor(chrono::milliseconds(5000));
3939
3940 pi2_logger.AppendAllFilenames(&filenames);
3941 }
3942
3943 pi1_logger.AppendAllFilenames(&filenames);
3944 pi3_logger.AppendAllFilenames(&filenames);
3945 }
3946
3947 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3948 auto result = ConfirmReadable(filenames);
3949
3950 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3951 EXPECT_THAT(result[0].second,
3952 ::testing::ElementsAre(realtime_clock::epoch() +
3953 chrono::microseconds(11000350)));
3954
3955 EXPECT_THAT(result[1].first,
3956 ::testing::ElementsAre(
3957 realtime_clock::epoch(),
3958 realtime_clock::epoch() + chrono::microseconds(6005000)));
3959 EXPECT_THAT(result[1].second,
3960 ::testing::ElementsAre(
3961 realtime_clock::epoch() + chrono::microseconds(4900150),
3962 realtime_clock::epoch() + chrono::microseconds(11000200)));
3963
3964 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3965 EXPECT_THAT(result[2].second,
3966 ::testing::ElementsAre(realtime_clock::epoch() +
3967 chrono::microseconds(11000150)));
3968
3969 // Confirm we observed the correct start and stop times. We should see the
3970 // reboot here.
3971 auto start_stop_result = ConfirmReadable(
3972 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3973 realtime_clock::epoch() + chrono::milliseconds(8000));
3974
3975 EXPECT_THAT(
3976 start_stop_result[0].first,
3977 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3978 EXPECT_THAT(
3979 start_stop_result[0].second,
3980 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3981 EXPECT_THAT(start_stop_result[1].first,
3982 ::testing::ElementsAre(
3983 realtime_clock::epoch() + chrono::seconds(2),
3984 realtime_clock::epoch() + chrono::microseconds(6005000)));
3985 EXPECT_THAT(start_stop_result[1].second,
3986 ::testing::ElementsAre(
3987 realtime_clock::epoch() + chrono::microseconds(4900150),
3988 realtime_clock::epoch() + chrono::seconds(8)));
3989 EXPECT_THAT(
3990 start_stop_result[2].first,
3991 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
3992 EXPECT_THAT(
3993 start_stop_result[2].second,
3994 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
3995}
Austin Schuh5dd22842021-11-17 16:09:39 -08003996
Austin Schuh5c770fa2022-03-11 06:57:22 -08003997// Tests that we properly handle one direction being down.
3998TEST(MissingDirectionTest, OneDirection) {
3999 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4000 aos::configuration::ReadConfig(ArtifactPath(
4001 "aos/events/logging/multinode_pingpong_split4_config.json"));
4002 message_bridge::TestingTimeConverter time_converter(
4003 configuration::NodesCount(&config.message()));
4004 SimulatedEventLoopFactory event_loop_factory(&config.message());
4005 event_loop_factory.SetTimeConverter(&time_converter);
4006
4007 NodeEventLoopFactory *const pi1 =
4008 event_loop_factory.GetNodeEventLoopFactory("pi1");
4009 const size_t pi1_index = configuration::GetNodeIndex(
4010 event_loop_factory.configuration(), pi1->node());
4011 NodeEventLoopFactory *const pi2 =
4012 event_loop_factory.GetNodeEventLoopFactory("pi2");
4013 const size_t pi2_index = configuration::GetNodeIndex(
4014 event_loop_factory.configuration(), pi2->node());
4015 std::vector<std::string> filenames;
4016
4017 {
4018 CHECK_EQ(pi1_index, 0u);
4019 CHECK_EQ(pi2_index, 1u);
4020
4021 time_converter.AddNextTimestamp(
4022 distributed_clock::epoch(),
4023 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4024
4025 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4026 time_converter.AddNextTimestamp(
4027 distributed_clock::epoch() + reboot_time,
4028 {BootTimestamp{.boot = 1,
4029 .time = monotonic_clock::epoch()},
4030 BootTimestamp::epoch() + reboot_time});
4031 }
4032
4033 const std::string kLogfile2_1 =
4034 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4035 const std::string kLogfile1_1 =
4036 aos::testing::TestTmpDir() + "/multi_logfile1.1/";
4037 util::UnlinkRecursive(kLogfile2_1);
4038 util::UnlinkRecursive(kLogfile1_1);
4039
4040 pi2->Disconnect(pi1->node());
4041
4042 pi1->AlwaysStart<Ping>("ping");
4043 pi2->AlwaysStart<Pong>("pong");
4044
4045 {
4046 LoggerState pi2_logger = LoggerState::MakeLogger(
4047 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4048
4049 event_loop_factory.RunFor(chrono::milliseconds(95));
4050
4051 pi2_logger.StartLogger(kLogfile2_1);
4052
4053 event_loop_factory.RunFor(chrono::milliseconds(6000));
4054
4055 pi2->Connect(pi1->node());
4056
4057 LoggerState pi1_logger = LoggerState::MakeLogger(
4058 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4059 pi1_logger.StartLogger(kLogfile1_1);
4060
4061 event_loop_factory.RunFor(chrono::milliseconds(5000));
4062 pi1_logger.AppendAllFilenames(&filenames);
4063 pi2_logger.AppendAllFilenames(&filenames);
4064 }
4065
4066 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4067 ConfirmReadable(filenames);
4068}
4069
Austin Schuhe309d2a2019-11-29 13:25:21 -08004070} // namespace testing
4071} // namespace logger
4072} // namespace aos