blob: 02081fd51e14a7a35c49fd984cd61610f90b2013 [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 Kuszmaul890c2492022-04-06 14:59:31 -0700419// Tests that we can read a logfile that has channels which were sent too fast.
420TEST(SingleNodeLoggerNoFixtureTest, ReadTooFast) {
421 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
422 aos::configuration::ReadConfig(
423 ArtifactPath("aos/events/pingpong_config.json"));
424 SimulatedEventLoopFactory event_loop_factory(&config.message());
425 const ::std::string tmpdir = aos::testing::TestTmpDir();
426 const ::std::string base_name = tmpdir + "/logfile";
427 const ::std::string config_file =
428 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
429 const ::std::string logfile = base_name + ".part0.bfbs";
430 // Remove the log file.
431 unlink(config_file.c_str());
432 unlink(logfile.c_str());
433
434 LOG(INFO) << "Logging data to " << logfile;
435
436 int sent_messages = 0;
437
438 {
439 std::unique_ptr<EventLoop> logger_event_loop =
440 event_loop_factory.MakeEventLoop("logger");
441
442 std::unique_ptr<EventLoop> ping_spammer_event_loop =
443 event_loop_factory.GetNodeEventLoopFactory(nullptr)->MakeEventLoop(
444 "ping_spammer", {NodeEventLoopFactory::CheckSentTooFast::kNo,
445 NodeEventLoopFactory::ExclusiveSenders::kNo});
446 aos::Sender<examples::Ping> ping_sender =
447 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
448
449 aos::TimerHandler *timer_handler =
450 ping_spammer_event_loop->AddTimer([&ping_sender, &sent_messages]() {
451 aos::Sender<examples::Ping>::Builder builder =
452 ping_sender.MakeBuilder();
453 examples::Ping::Builder ping_builder =
454 builder.MakeBuilder<examples::Ping>();
455 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
456 ++sent_messages;
457 });
458
459 constexpr std::chrono::microseconds kSendPeriod{10};
460 const int max_legal_messages =
461 ping_sender.channel()->frequency() *
462 event_loop_factory.configuration()->channel_storage_duration() /
463 1000000000;
464
465 ping_spammer_event_loop->OnRun(
466 [&ping_spammer_event_loop, kSendPeriod, timer_handler]() {
467 timer_handler->Setup(
468 ping_spammer_event_loop->monotonic_now() + kSendPeriod / 2,
469 kSendPeriod);
470 });
471
472 Logger logger(logger_event_loop.get());
473 logger.set_separate_config(false);
474 logger.set_polling_period(std::chrono::milliseconds(100));
475 logger.StartLoggingLocalNamerOnRun(base_name);
476
477 event_loop_factory.RunFor(kSendPeriod * max_legal_messages * 2);
478 }
479
480 LogReader reader(logfile);
481
482 reader.Register();
483
484 std::unique_ptr<EventLoop> test_event_loop =
485 reader.event_loop_factory()->MakeEventLoop("log_reader");
486
487 int replay_count = 0;
488
489 test_event_loop->MakeWatcher(
490 "/test", [&replay_count](const examples::Ping &) { ++replay_count; });
491
492 reader.event_loop_factory()->Run();
493 EXPECT_EQ(replay_count, sent_messages);
494}
495
James Kuszmauldd0a5042021-10-28 23:38:04 -0700496struct CompressionParams {
497 std::string_view extension;
498 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
499};
500
501std::ostream &operator<<(std::ostream &ostream,
502 const CompressionParams &params) {
503 ostream << "\"" << params.extension << "\"";
504 return ostream;
505}
506
507std::vector<CompressionParams> SupportedCompressionAlgorithms() {
508 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
509 {SnappyDecoder::kExtension,
510 []() { return std::make_unique<SnappyEncoder>(); }},
511#ifdef LZMA
512 {LzmaDecoder::kExtension,
513 []() { return std::make_unique<LzmaEncoder>(3); }}
514#endif // LZMA
515 };
516}
517
Austin Schuh61e973f2021-02-21 21:43:56 -0800518// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700519struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800520 // The config file to use.
521 std::string config;
522 // If true, the RemoteMessage channel should be shared between all the remote
523 // channels. If false, there will be 1 RemoteMessage channel per remote
524 // channel.
525 bool shared;
526 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700527 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800528};
Austin Schuh315b96b2020-12-11 21:21:12 -0800529
James Kuszmauldd0a5042021-10-28 23:38:04 -0700530std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
531 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
532 << ", sha256: \"" << params.sha256 << "\"}";
533 return ostream;
534}
535
Austin Schuh3e20c692021-11-16 20:43:16 -0800536struct LoggerState {
537 static LoggerState MakeLogger(NodeEventLoopFactory *node,
538 SimulatedEventLoopFactory *factory,
539 CompressionParams params,
540 const Configuration *configuration = nullptr) {
541 if (configuration == nullptr) {
542 configuration = factory->configuration();
543 }
544 return {node->MakeEventLoop("logger"),
545 {},
546 configuration,
547 configuration::GetNode(configuration, node->node()),
548 nullptr,
549 params};
550 }
551
552 void StartLogger(std::string logfile_base) {
553 CHECK(!logfile_base.empty());
554
555 logger = std::make_unique<Logger>(event_loop.get(), configuration);
556 logger->set_polling_period(std::chrono::milliseconds(100));
557 logger->set_name(
558 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
Austin Schuhfa712682022-05-11 16:43:42 -0700559 logger->set_logger_sha1(
560 absl::StrCat("logger_sha1_", event_loop->node()->name()->str()));
561 logger->set_logger_version(
562 absl::StrCat("logger_version_", event_loop->node()->name()->str()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800563 event_loop->OnRun([this, logfile_base]() {
564 std::unique_ptr<MultiNodeLogNamer> namer =
565 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
566 event_loop.get(), node);
567 namer->set_extension(params.extension);
568 namer->set_encoder_factory(params.encoder_factory);
569 log_namer = namer.get();
570
571 logger->StartLogging(std::move(namer));
572 });
573 }
574
575 std::unique_ptr<EventLoop> event_loop;
576 std::unique_ptr<Logger> logger;
577 const Configuration *configuration;
578 const Node *node;
579 MultiNodeLogNamer *log_namer;
580 CompressionParams params;
581
582 void AppendAllFilenames(std::vector<std::string> *filenames) {
583 for (const std::string &file : log_namer->all_filenames()) {
584 const std::string_view separator =
585 log_namer->base_name().back() == '/' ? "" : "_";
586 filenames->emplace_back(
587 absl::StrCat(log_namer->base_name(), separator, file));
588 }
589 }
590
591 ~LoggerState() {
592 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800593 std::vector<std::string> filenames;
594 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800595 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800596 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800597 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800598 auto x = ReadHeader(file);
599 if (x) {
600 VLOG(1) << aos::FlatbufferToJson(x.value());
601 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800602 }
603 }
604 }
605};
606
Austin Schuhe33c08d2022-02-03 18:15:21 -0800607std::vector<std::pair<std::vector<realtime_clock::time_point>,
608 std::vector<realtime_clock::time_point>>>
609ConfirmReadable(
610 const std::vector<std::string> &files,
611 realtime_clock::time_point start_time = realtime_clock::min_time,
612 realtime_clock::time_point end_time = realtime_clock::max_time) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800613 {
614 LogReader reader(SortParts(files));
615
616 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
617 reader.Register(&log_reader_factory);
618
619 log_reader_factory.Run();
620
621 reader.Deregister();
622 }
623 {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800624 std::vector<std::pair<std::vector<realtime_clock::time_point>,
625 std::vector<realtime_clock::time_point>>>
626 result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800627 LogReader reader(SortParts(files));
628
Austin Schuhe33c08d2022-02-03 18:15:21 -0800629 reader.SetStartTime(start_time);
630 reader.SetEndTime(end_time);
631
Austin Schuh3e20c692021-11-16 20:43:16 -0800632 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
633 reader.RegisterWithoutStarting(&log_reader_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -0800634 result.resize(
635 configuration::NodesCount(log_reader_factory.configuration()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800636 if (configuration::MultiNode(log_reader_factory.configuration())) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800637 size_t i = 0;
Austin Schuh3e20c692021-11-16 20:43:16 -0800638 for (const aos::Node *node :
639 *log_reader_factory.configuration()->nodes()) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800640 LOG(INFO) << "Registering start";
641 reader.OnStart(node, [node, &log_reader_factory, &result,
642 node_index = i]() {
Austin Schuh3e20c692021-11-16 20:43:16 -0800643 LOG(INFO) << "Starting " << node->name()->string_view();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800644 result[node_index].first.push_back(
645 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
Austin Schuh3e20c692021-11-16 20:43:16 -0800646 });
Austin Schuhe33c08d2022-02-03 18:15:21 -0800647 reader.OnEnd(node, [node, &log_reader_factory, &result,
648 node_index = i]() {
649 LOG(INFO) << "Ending " << node->name()->string_view();
650 result[node_index].second.push_back(
651 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
652 });
653 ++i;
Austin Schuh3e20c692021-11-16 20:43:16 -0800654 }
Austin Schuhe33c08d2022-02-03 18:15:21 -0800655 } else {
656 reader.OnStart([&log_reader_factory, &result]() {
657 LOG(INFO) << "Starting";
658 result[0].first.push_back(
659 log_reader_factory.GetNodeEventLoopFactory(nullptr)
660 ->realtime_now());
661 });
662 reader.OnEnd([&log_reader_factory, &result]() {
663 LOG(INFO) << "Ending";
664 result[0].second.push_back(
665 log_reader_factory.GetNodeEventLoopFactory(nullptr)
666 ->realtime_now());
667 });
Austin Schuh3e20c692021-11-16 20:43:16 -0800668 }
669
670 log_reader_factory.Run();
671
672 reader.Deregister();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800673
674 for (auto x : result) {
675 for (auto y : x.first) {
676 VLOG(1) << "Start " << y;
677 }
678 for (auto y : x.second) {
679 VLOG(1) << "End " << y;
680 }
681 }
682 return result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800683 }
684}
685
James Kuszmauldd0a5042021-10-28 23:38:04 -0700686class MultinodeLoggerTest : public ::testing::TestWithParam<
687 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800688 public:
689 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700690 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
691 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800692 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800693 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700694 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800695 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700696 event_loop_factory_.configuration(), pi1_->node())),
697 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800698 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700699 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800700 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800701 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
702 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800703 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800704 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800705 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700706 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700707 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800708 event_loop_factory_.SetTimeConverter(&time_converter_);
709
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700710 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700711 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700712 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800713 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700714 }
715
Austin Schuh268586b2021-03-31 22:24:39 -0700716 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800717 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800718 unlink(file.c_str());
719 }
720
Austin Schuh268586b2021-03-31 22:24:39 -0700721 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800722 unlink(file.c_str());
723 }
724
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700725 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
726 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700727
728 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
729 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700730 }
731
James Kuszmauldd0a5042021-10-28 23:38:04 -0700732 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800733
734 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700735 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800736 size_t pi1_data_count = 3,
737 size_t pi2_data_count = 3) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800738 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700739 result.emplace_back(absl::StrCat(
740 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
741 result.emplace_back(absl::StrCat(
742 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700743 for (size_t i = 0; i < pi1_data_count; ++i) {
744 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700745 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700746 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800747 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700748 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800749 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700750 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700751 for (size_t i = 0; i < pi2_data_count; ++i) {
752 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700753 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700754 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700755 result.emplace_back(logfile_base2 +
756 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
757 Extension());
758 result.emplace_back(logfile_base2 +
759 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
760 Extension());
761 result.emplace_back(logfile_base1 +
762 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
763 Extension());
764 result.emplace_back(logfile_base1 +
765 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
766 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800767 if (shared()) {
768 result.emplace_back(logfile_base1 +
769 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700770 "aos.message_bridge.RemoteMessage.part0" +
771 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800772 result.emplace_back(logfile_base1 +
773 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700774 "aos.message_bridge.RemoteMessage.part1" +
775 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800776 result.emplace_back(logfile_base1 +
777 "_timestamps/pi1/aos/remote_timestamps/pi2/"
778 "aos.message_bridge.RemoteMessage.part2" +
779 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800780 result.emplace_back(logfile_base2 +
781 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700782 "aos.message_bridge.RemoteMessage.part0" +
783 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800784 result.emplace_back(logfile_base2 +
785 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700786 "aos.message_bridge.RemoteMessage.part1" +
787 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800788 } else {
789 result.emplace_back(logfile_base1 +
790 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
791 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700792 "aos.message_bridge.RemoteMessage.part0" +
793 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800794 result.emplace_back(logfile_base1 +
795 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
796 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700797 "aos.message_bridge.RemoteMessage.part1" +
798 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800799 result.emplace_back(logfile_base2 +
800 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
801 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700802 "aos.message_bridge.RemoteMessage.part0" +
803 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800804 result.emplace_back(logfile_base2 +
805 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
806 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700807 "aos.message_bridge.RemoteMessage.part1" +
808 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800809 result.emplace_back(logfile_base1 +
810 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
811 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700812 "aos.message_bridge.RemoteMessage.part0" +
813 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800814 result.emplace_back(logfile_base1 +
815 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
816 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700817 "aos.message_bridge.RemoteMessage.part1" +
818 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800819 }
820
821 return result;
822 }
823
824 std::vector<std::string> MakePi1RebootLogfiles() {
825 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700826 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
827 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
828 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800829 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
830 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800831 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700832 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800833 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700834 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800835 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700836 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700837 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700838 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
839 result.emplace_back(logfile_base1_ +
840 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
841 Extension());
842 result.emplace_back(logfile_base1_ +
843 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
844 Extension());
845 result.emplace_back(logfile_base1_ +
846 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
847 Extension());
848 result.emplace_back(logfile_base1_ +
849 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
850 Extension());
851 result.emplace_back(absl::StrCat(
852 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800853 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800854 for (size_t i = 0; i < 6; ++i) {
855 result.emplace_back(
856 absl::StrCat(logfile_base1_,
857 "_timestamps/pi1/aos/remote_timestamps/pi2/"
858 "aos.message_bridge.RemoteMessage.part",
859 i, Extension()));
860 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800861 } else {
862 result.emplace_back(logfile_base1_ +
863 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
864 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700865 "aos.message_bridge.RemoteMessage.part0" +
866 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800867 result.emplace_back(logfile_base1_ +
868 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
869 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700870 "aos.message_bridge.RemoteMessage.part1" +
871 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800872 result.emplace_back(logfile_base1_ +
873 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
874 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700875 "aos.message_bridge.RemoteMessage.part2" +
876 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700877 result.emplace_back(logfile_base1_ +
878 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
879 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700880 "aos.message_bridge.RemoteMessage.part3" +
881 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800882
883 result.emplace_back(logfile_base1_ +
884 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
885 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700886 "aos.message_bridge.RemoteMessage.part0" +
887 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800888 result.emplace_back(logfile_base1_ +
889 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
890 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700891 "aos.message_bridge.RemoteMessage.part1" +
892 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800893 result.emplace_back(logfile_base1_ +
894 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
895 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700896 "aos.message_bridge.RemoteMessage.part2" +
897 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700898 result.emplace_back(logfile_base1_ +
899 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
900 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700901 "aos.message_bridge.RemoteMessage.part3" +
902 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800903 }
904 return result;
905 }
906
907 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
908 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700909 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
910 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
911 result.emplace_back(logfile_base1_ +
912 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
913 Extension());
914 result.emplace_back(absl::StrCat(
915 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700916 return result;
917 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800918
Austin Schuh510dc622021-08-06 18:47:30 -0700919 std::vector<std::string> MakePi1DeadNodeLogfiles() {
920 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700921 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
922 result.emplace_back(absl::StrCat(
923 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800924 return result;
925 }
926
927 std::vector<std::vector<std::string>> StructureLogFiles() {
928 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800929 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
930 std::vector<std::string>{logfiles_[5], logfiles_[6]},
931 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800932 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800933 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800934
Austin Schuhbfe6c572022-01-27 20:48:20 -0800935 if (shared()) {
936 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
937 logfiles_[16]});
938 result.emplace_back(
939 std::vector<std::string>{logfiles_[17], logfiles_[18]});
940 } else {
941 result.emplace_back(
942 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800943 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700944 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800945 result.emplace_back(
946 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800947 }
948
949 return result;
950 }
951
James Kuszmauldd0a5042021-10-28 23:38:04 -0700952 std::string Extension() {
953 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
954 }
955
Austin Schuh58646e22021-08-23 23:51:46 -0700956 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700957 SimulatedEventLoopFactory *factory = nullptr,
958 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700959 if (factory == nullptr) {
960 factory = &event_loop_factory_;
961 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800962 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
963 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700964 }
965
James Kuszmauldd0a5042021-10-28 23:38:04 -0700966 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700967 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800968 if (logger->event_loop->node()->name()->string_view() == "pi1") {
969 logfile_base = logfile_base1_;
970 } else {
971 logfile_base = logfile_base2_;
972 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700973 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800974 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700975 }
Austin Schuh15649d62019-12-28 16:36:38 -0800976
Austin Schuh3bd4c402020-11-06 18:19:06 -0800977 void VerifyParts(const std::vector<LogFile> &sorted_parts,
978 const std::vector<std::string> &corrupted_parts = {}) {
979 EXPECT_EQ(sorted_parts.size(), 2u);
980
981 // Count up the number of UUIDs and make sure they are what we expect as a
982 // sanity check.
983 std::set<std::string> log_event_uuids;
984 std::set<std::string> parts_uuids;
985 std::set<std::string> both_uuids;
986
987 size_t missing_rt_count = 0;
988
989 std::vector<std::string> logger_nodes;
990 for (const LogFile &log_file : sorted_parts) {
991 EXPECT_FALSE(log_file.log_event_uuid.empty());
992 log_event_uuids.insert(log_file.log_event_uuid);
993 logger_nodes.emplace_back(log_file.logger_node);
994 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800995 EXPECT_TRUE(log_file.config);
996 EXPECT_EQ(log_file.name,
997 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuhfa712682022-05-11 16:43:42 -0700998 EXPECT_EQ(log_file.logger_sha1,
999 absl::StrCat("logger_sha1_", log_file.logger_node));
1000 EXPECT_EQ(log_file.logger_version,
1001 absl::StrCat("logger_version_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -08001002
1003 for (const LogParts &part : log_file.parts) {
1004 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
1005 << ": " << part;
1006 missing_rt_count +=
1007 part.realtime_start_time == aos::realtime_clock::min_time;
1008
1009 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
1010 log_event_uuids.end());
1011 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -08001012 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001013 parts_uuids.insert(part.parts_uuid);
1014 both_uuids.insert(part.parts_uuid);
1015 }
1016 }
1017
Austin Schuh61e973f2021-02-21 21:43:56 -08001018 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
1019 // start time on remote nodes because we don't know it and would be
1020 // guessing. And the log reader can actually do a better job. The number
1021 // depends on if we have the remote timestamps split across 2 files, or just
1022 // across 1, depending on if we are using a split or combined timestamp
1023 // channel config.
1024 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001025
1026 EXPECT_EQ(log_event_uuids.size(), 2u);
1027 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
1028 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
1029
1030 // Test that each list of parts is in order. Don't worry about the ordering
1031 // between part file lists though.
1032 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -08001033 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -08001034 ::testing::UnorderedElementsAreArray(structured_logfiles_));
1035
1036 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
1037
1038 EXPECT_NE(sorted_parts[0].realtime_start_time,
1039 aos::realtime_clock::min_time);
1040 EXPECT_NE(sorted_parts[1].realtime_start_time,
1041 aos::realtime_clock::min_time);
1042
1043 EXPECT_NE(sorted_parts[0].monotonic_start_time,
1044 aos::monotonic_clock::min_time);
1045 EXPECT_NE(sorted_parts[1].monotonic_start_time,
1046 aos::monotonic_clock::min_time);
1047
1048 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
1049 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
1050 }
1051
1052 void AddExtension(std::string_view extension) {
1053 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
1054 [extension](const std::string &in) {
1055 return absl::StrCat(in, extension);
1056 });
1057
1058 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
1059 structured_logfiles_.begin(),
1060 [extension](std::vector<std::string> in) {
1061 std::transform(in.begin(), in.end(), in.begin(),
1062 [extension](const std::string &in_str) {
1063 return absl::StrCat(in_str, extension);
1064 });
1065 return in;
1066 });
1067 }
1068
Austin Schuh15649d62019-12-28 16:36:38 -08001069 // Config and factory.
1070 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001071 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -08001072 SimulatedEventLoopFactory event_loop_factory_;
1073
Austin Schuh58646e22021-08-23 23:51:46 -07001074 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001075 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -07001076 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001077 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001078
1079 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -08001080 std::string logfile_base1_;
1081 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -08001082 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001083 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -08001084 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001085
1086 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -08001087};
1088
Austin Schuh391e3172020-09-01 22:48:18 -07001089// Counts the number of messages on a channel. Returns (channel name, channel
1090// type, count) for every message matching matcher()
1091std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -08001092 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001093 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -08001094 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -08001095 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -08001096
Austin Schuh6f3babe2020-01-26 20:34:50 -08001097 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001098 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -08001099 if (!msg) {
1100 break;
1101 }
1102
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001103 if (matcher(msg.get())) {
1104 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001105 }
1106 }
1107
Austin Schuh391e3172020-09-01 22:48:18 -07001108 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001109 int channel = 0;
1110 for (size_t i = 0; i < counts.size(); ++i) {
1111 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -08001112 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -07001113 result.push_back(std::make_tuple(channel->name()->str(),
1114 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -08001115 }
1116 ++channel;
1117 }
1118
1119 return result;
1120}
1121
1122// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001123std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -08001124 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -07001125 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001126 return CountChannelsMatching(
1127 config, filename, [](const UnpackedMessageHeader *msg) {
1128 if (msg->span.data() != nullptr) {
1129 CHECK(!msg->monotonic_remote_time.has_value());
1130 CHECK(!msg->realtime_remote_time.has_value());
1131 CHECK(!msg->remote_queue_index.has_value());
1132 return true;
1133 }
1134 return false;
1135 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001136}
1137
1138// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001139std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001140 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001141 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001142 return CountChannelsMatching(
1143 config, filename, [](const UnpackedMessageHeader *msg) {
1144 if (msg->span.data() == nullptr) {
1145 CHECK(msg->monotonic_remote_time.has_value());
1146 CHECK(msg->realtime_remote_time.has_value());
1147 CHECK(msg->remote_queue_index.has_value());
1148 return true;
1149 }
1150 return false;
1151 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001152}
1153
Austin Schuhcde938c2020-02-02 17:30:07 -08001154// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001155TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001156 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001157 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001158
Austin Schuh15649d62019-12-28 16:36:38 -08001159 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001160 LoggerState pi1_logger = MakeLogger(pi1_);
1161 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001162
1163 event_loop_factory_.RunFor(chrono::milliseconds(95));
1164
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001165 StartLogger(&pi1_logger);
1166 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001167
Austin Schuh15649d62019-12-28 16:36:38 -08001168 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001169 pi1_logger.AppendAllFilenames(&actual_filenames);
1170 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001171 }
1172
Austin Schuhbfe6c572022-01-27 20:48:20 -08001173 ASSERT_THAT(actual_filenames,
1174 ::testing::UnorderedElementsAreArray(logfiles_));
1175
Austin Schuh6f3babe2020-01-26 20:34:50 -08001176 {
Austin Schuh64fab802020-09-09 22:47:47 -07001177 std::set<std::string> logfile_uuids;
1178 std::set<std::string> parts_uuids;
1179 // Confirm that we have the expected number of UUIDs for both the logfile
1180 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001181 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001182 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001183 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001184 if (!log_header.back().message().has_configuration()) {
1185 logfile_uuids.insert(
1186 log_header.back().message().log_event_uuid()->str());
1187 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1188 }
Austin Schuh64fab802020-09-09 22:47:47 -07001189 }
Austin Schuh15649d62019-12-28 16:36:38 -08001190
Austin Schuh64fab802020-09-09 22:47:47 -07001191 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001192 if (shared()) {
1193 EXPECT_EQ(parts_uuids.size(), 7u);
1194 } else {
1195 EXPECT_EQ(parts_uuids.size(), 8u);
1196 }
Austin Schuh64fab802020-09-09 22:47:47 -07001197
1198 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001199 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001200 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001201 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1202
Austin Schuh64fab802020-09-09 22:47:47 -07001203 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001204 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001205
Austin Schuhe46492f2021-07-31 19:49:41 -07001206 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001207 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1208 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1209
1210 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1211 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1212
Austin Schuhe46492f2021-07-31 19:49:41 -07001213 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1214 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001215
1216 if (shared()) {
1217 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1218 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001219 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001220
1221 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1222 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1223 } else {
1224 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1225 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1226
1227 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1228 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1229
1230 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1231 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001232 }
Austin Schuh64fab802020-09-09 22:47:47 -07001233
1234 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001235 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001236 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001237 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1238
1239 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1240 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1241
1242 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1243 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1244 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1245
Austin Schuh64fab802020-09-09 22:47:47 -07001246 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1247 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001248
Austin Schuh61e973f2021-02-21 21:43:56 -08001249 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1250 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001251
1252 if (shared()) {
1253 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1254 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1255 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1256
1257 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1258 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1259 } else {
1260 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1261 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1262
Austin Schuhe46492f2021-07-31 19:49:41 -07001263 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1264 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001265
1266 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1267 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001268 }
Austin Schuh64fab802020-09-09 22:47:47 -07001269 }
1270
Austin Schuh8c399962020-12-25 21:51:45 -08001271 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001272 {
Austin Schuh391e3172020-09-01 22:48:18 -07001273 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001274 std::shared_ptr<const aos::Configuration> config =
1275 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001276
Austin Schuh6f3babe2020-01-26 20:34:50 -08001277 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001278 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1279 UnorderedElementsAre(
1280 std::make_tuple("/pi1/aos",
1281 "aos.message_bridge.ServerStatistics", 1),
1282 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001283 << " : " << logfiles_[2];
1284 EXPECT_THAT(
1285 CountChannelsData(config, logfiles_[3]),
1286 UnorderedElementsAre(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001287 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1288 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1289 1)))
1290 << " : " << logfiles_[3];
1291 EXPECT_THAT(
1292 CountChannelsData(config, logfiles_[4]),
1293 UnorderedElementsAre(
1294 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001295 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001296 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001297 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
Austin Schuhbfe6c572022-01-27 20:48:20 -08001298 199),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001299 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001300 std::make_tuple("/test", "aos.examples.Ping", 2000)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001301 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001302 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001303 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1304 UnorderedElementsAre())
1305 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001306 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001307 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001308 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001309 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001310 EXPECT_THAT(
1311 CountChannelsTimestamp(config, logfiles_[4]),
1312 UnorderedElementsAre(
1313 std::make_tuple("/test", "aos.examples.Pong", 2000),
1314 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1315 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001316
1317 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001318 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001319 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001320 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001321 << " : " << logfiles_[5];
1322 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001323 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001324 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001325 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001326
Austin Schuh6f3babe2020-01-26 20:34:50 -08001327 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001328 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1329 UnorderedElementsAre())
1330 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001331 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1332 UnorderedElementsAre())
1333 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001334
1335 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001336 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001337 UnorderedElementsAre(std::make_tuple(
1338 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001339 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001340 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001341 CountChannelsData(config, logfiles_[8]),
1342 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1343 << " : " << logfiles_[8];
1344 EXPECT_THAT(
1345 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001346 UnorderedElementsAre(
1347 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001348 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001349 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001350 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1351 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001352 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001353 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1354 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001355 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001356 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001357 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001358 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001359 EXPECT_THAT(
1360 CountChannelsTimestamp(config, logfiles_[8]),
1361 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1362 << " : " << logfiles_[8];
1363 EXPECT_THAT(
1364 CountChannelsTimestamp(config, logfiles_[9]),
1365 UnorderedElementsAre(
1366 std::make_tuple("/test", "aos.examples.Ping", 2000),
1367 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1368 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001369
1370 // And then test that the remotely logged timestamp data files only have
1371 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001372 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1373 UnorderedElementsAre())
1374 << " : " << logfiles_[10];
1375 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1376 UnorderedElementsAre())
1377 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001378 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1379 UnorderedElementsAre())
1380 << " : " << logfiles_[12];
1381 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1382 UnorderedElementsAre())
1383 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001384
Austin Schuh8c399962020-12-25 21:51:45 -08001385 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001386 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001387 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001388 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001389 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001390 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001391 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001392 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001393
Austin Schuh61e973f2021-02-21 21:43:56 -08001394 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001395 UnorderedElementsAre(std::make_tuple(
1396 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001397 << " : " << logfiles_[12];
1398 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001399 UnorderedElementsAre(std::make_tuple(
1400 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001401 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001402
1403 // Timestamps from pi2 on pi1, and the other way.
1404 if (shared()) {
1405 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1406 UnorderedElementsAre())
1407 << " : " << logfiles_[14];
1408 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1409 UnorderedElementsAre())
1410 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001411 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001412 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001413 << " : " << logfiles_[16];
1414 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001415 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001416 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001417 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1418 UnorderedElementsAre())
1419 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001420
Austin Schuhbfe6c572022-01-27 20:48:20 -08001421 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1422 UnorderedElementsAre(
1423 std::make_tuple("/test", "aos.examples.Ping", 1)))
1424 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001425 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001426 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001427 UnorderedElementsAre(
1428 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001429 std::make_tuple("/test", "aos.examples.Ping", 90)))
1430 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001431 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001432 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001433 UnorderedElementsAre(
1434 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1435 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001436 << " : " << logfiles_[16];
1437 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001438 UnorderedElementsAre(std::make_tuple(
1439 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1440 << " : " << logfiles_[17];
1441 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1442 UnorderedElementsAre(std::make_tuple(
1443 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1444 << " : " << logfiles_[18];
1445 } else {
1446 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1447 UnorderedElementsAre())
1448 << " : " << logfiles_[14];
1449 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1450 UnorderedElementsAre())
1451 << " : " << logfiles_[15];
1452 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1453 UnorderedElementsAre())
1454 << " : " << logfiles_[16];
1455 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1456 UnorderedElementsAre())
1457 << " : " << logfiles_[17];
1458 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1459 UnorderedElementsAre())
1460 << " : " << logfiles_[18];
1461 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1462 UnorderedElementsAre())
1463 << " : " << logfiles_[19];
1464
1465 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1466 UnorderedElementsAre(std::make_tuple(
1467 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1468 << " : " << logfiles_[14];
1469 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1470 UnorderedElementsAre(std::make_tuple(
1471 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1472 << " : " << logfiles_[15];
1473 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1474 UnorderedElementsAre(std::make_tuple(
1475 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1476 << " : " << logfiles_[16];
1477 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1478 UnorderedElementsAre(std::make_tuple(
1479 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1480 << " : " << logfiles_[17];
1481 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1482 UnorderedElementsAre(
1483 std::make_tuple("/test", "aos.examples.Ping", 91)))
1484 << " : " << logfiles_[18];
1485 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001486 UnorderedElementsAre(
1487 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001488 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001489 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001490 }
1491
Austin Schuh8c399962020-12-25 21:51:45 -08001492 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001493
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001494 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001495 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001496
1497 // This sends out the fetched messages and advances time to the start of the
1498 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001499 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001500
Austin Schuhac0771c2020-01-07 18:36:30 -08001501 const Node *pi1 =
1502 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001503 const Node *pi2 =
1504 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001505
Austin Schuh2f8fd752020-09-01 22:38:28 -07001506 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1507 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1508 LOG(INFO) << "now pi1 "
1509 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1510 LOG(INFO) << "now pi2 "
1511 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1512
Austin Schuh07676622021-01-21 18:59:17 -08001513 EXPECT_THAT(reader.LoggedNodes(),
1514 ::testing::ElementsAre(
1515 configuration::GetNode(reader.logged_configuration(), pi1),
1516 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001517
1518 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001519
Austin Schuh6f3babe2020-01-26 20:34:50 -08001520 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001521 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001522 std::unique_ptr<EventLoop> pi2_event_loop =
1523 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001524
Austin Schuh6f3babe2020-01-26 20:34:50 -08001525 int pi1_ping_count = 10;
1526 int pi2_ping_count = 10;
1527 int pi1_pong_count = 10;
1528 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001529
1530 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001531 pi1_event_loop->MakeWatcher(
1532 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001533 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001534 << pi1_event_loop->context().monotonic_remote_time << " -> "
1535 << pi1_event_loop->context().monotonic_event_time;
1536 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1537 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1538 pi1_ping_count * chrono::milliseconds(10) +
1539 monotonic_clock::epoch());
1540 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1541 pi1_ping_count * chrono::milliseconds(10) +
1542 realtime_clock::epoch());
1543 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1544 pi1_event_loop->context().monotonic_event_time);
1545 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1546 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001547
Austin Schuh6f3babe2020-01-26 20:34:50 -08001548 ++pi1_ping_count;
1549 });
1550 pi2_event_loop->MakeWatcher(
1551 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001552 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001553 << pi2_event_loop->context().monotonic_remote_time << " -> "
1554 << pi2_event_loop->context().monotonic_event_time;
1555 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1556
1557 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1558 pi2_ping_count * chrono::milliseconds(10) +
1559 monotonic_clock::epoch());
1560 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1561 pi2_ping_count * chrono::milliseconds(10) +
1562 realtime_clock::epoch());
1563 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1564 chrono::microseconds(150),
1565 pi2_event_loop->context().monotonic_event_time);
1566 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1567 chrono::microseconds(150),
1568 pi2_event_loop->context().realtime_event_time);
1569 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001570 });
1571
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001572 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001573 // Confirm that the ping and pong counts both match, and the value also
1574 // matches.
1575 pi1_event_loop->MakeWatcher(
1576 "/test", [&pi1_event_loop, &pi1_ping_count,
1577 &pi1_pong_count](const examples::Pong &pong) {
1578 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1579 << pi1_event_loop->context().monotonic_remote_time << " -> "
1580 << pi1_event_loop->context().monotonic_event_time;
1581
1582 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1583 pi1_pong_count + kQueueIndexOffset);
1584 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1585 chrono::microseconds(200) +
1586 pi1_pong_count * chrono::milliseconds(10) +
1587 monotonic_clock::epoch());
1588 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1589 chrono::microseconds(200) +
1590 pi1_pong_count * chrono::milliseconds(10) +
1591 realtime_clock::epoch());
1592
1593 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1594 chrono::microseconds(150),
1595 pi1_event_loop->context().monotonic_event_time);
1596 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1597 chrono::microseconds(150),
1598 pi1_event_loop->context().realtime_event_time);
1599
1600 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1601 ++pi1_pong_count;
1602 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1603 });
1604 pi2_event_loop->MakeWatcher(
1605 "/test", [&pi2_event_loop, &pi2_ping_count,
1606 &pi2_pong_count](const examples::Pong &pong) {
1607 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1608 << pi2_event_loop->context().monotonic_remote_time << " -> "
1609 << pi2_event_loop->context().monotonic_event_time;
1610
1611 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001612 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001613
1614 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1615 chrono::microseconds(200) +
1616 pi2_pong_count * chrono::milliseconds(10) +
1617 monotonic_clock::epoch());
1618 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1619 chrono::microseconds(200) +
1620 pi2_pong_count * chrono::milliseconds(10) +
1621 realtime_clock::epoch());
1622
1623 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1624 pi2_event_loop->context().monotonic_event_time);
1625 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1626 pi2_event_loop->context().realtime_event_time);
1627
1628 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1629 ++pi2_pong_count;
1630 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1631 });
1632
1633 log_reader_factory.Run();
1634 EXPECT_EQ(pi1_ping_count, 2010);
1635 EXPECT_EQ(pi2_ping_count, 2010);
1636 EXPECT_EQ(pi1_pong_count, 2010);
1637 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001638
1639 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001640}
1641
James Kuszmaul46d82582020-05-09 19:50:09 -07001642typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1643
1644// Test that if we feed the replay with a mismatched node list that we die on
1645// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001646TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001647 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001648 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001649 LoggerState pi1_logger = MakeLogger(pi1_);
1650 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001651
1652 event_loop_factory_.RunFor(chrono::milliseconds(95));
1653
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001654 StartLogger(&pi1_logger);
1655 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001656
James Kuszmaul46d82582020-05-09 19:50:09 -07001657 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1658 }
1659
1660 // Test that, if we add an additional node to the replay config that the
1661 // logger complains about the mismatch in number of nodes.
1662 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1663 configuration::MergeWithConfig(&config_.message(), R"({
1664 "nodes": [
1665 {
1666 "name": "extra-node"
1667 }
1668 ]
1669 }
1670 )");
1671
Austin Schuh287d43d2020-12-04 20:19:33 -08001672 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1673 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001674 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001675}
1676
Austin Schuhcde938c2020-02-02 17:30:07 -08001677// Tests that we can read log files where they don't start at the same monotonic
1678// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001679TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001680 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001681 std::vector<std::string> actual_filenames;
1682
Austin Schuhcde938c2020-02-02 17:30:07 -08001683 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001684 LoggerState pi1_logger = MakeLogger(pi1_);
1685 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001686
1687 event_loop_factory_.RunFor(chrono::milliseconds(95));
1688
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001689 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001690
1691 event_loop_factory_.RunFor(chrono::milliseconds(200));
1692
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001693 StartLogger(&pi2_logger);
1694
Austin Schuhcde938c2020-02-02 17:30:07 -08001695 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001696 pi1_logger.AppendAllFilenames(&actual_filenames);
1697 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001698 }
1699
Austin Schuhe46492f2021-07-31 19:49:41 -07001700 // Since we delay starting pi2, it already knows about all the timestamps so
1701 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001702 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001703
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001704 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001705 log_reader_factory.set_send_delay(chrono::microseconds(0));
1706
1707 // This sends out the fetched messages and advances time to the start of the
1708 // log file.
1709 reader.Register(&log_reader_factory);
1710
1711 const Node *pi1 =
1712 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1713 const Node *pi2 =
1714 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1715
Austin Schuh07676622021-01-21 18:59:17 -08001716 EXPECT_THAT(reader.LoggedNodes(),
1717 ::testing::ElementsAre(
1718 configuration::GetNode(reader.logged_configuration(), pi1),
1719 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001720
1721 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1722
1723 std::unique_ptr<EventLoop> pi1_event_loop =
1724 log_reader_factory.MakeEventLoop("test", pi1);
1725 std::unique_ptr<EventLoop> pi2_event_loop =
1726 log_reader_factory.MakeEventLoop("test", pi2);
1727
1728 int pi1_ping_count = 30;
1729 int pi2_ping_count = 30;
1730 int pi1_pong_count = 30;
1731 int pi2_pong_count = 30;
1732
1733 // Confirm that the ping value matches.
1734 pi1_event_loop->MakeWatcher(
1735 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1736 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1737 << pi1_event_loop->context().monotonic_remote_time << " -> "
1738 << pi1_event_loop->context().monotonic_event_time;
1739 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1740
1741 ++pi1_ping_count;
1742 });
1743 pi2_event_loop->MakeWatcher(
1744 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1745 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1746 << pi2_event_loop->context().monotonic_remote_time << " -> "
1747 << pi2_event_loop->context().monotonic_event_time;
1748 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1749
1750 ++pi2_ping_count;
1751 });
1752
1753 // Confirm that the ping and pong counts both match, and the value also
1754 // matches.
1755 pi1_event_loop->MakeWatcher(
1756 "/test", [&pi1_event_loop, &pi1_ping_count,
1757 &pi1_pong_count](const examples::Pong &pong) {
1758 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1759 << pi1_event_loop->context().monotonic_remote_time << " -> "
1760 << pi1_event_loop->context().monotonic_event_time;
1761
1762 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1763 ++pi1_pong_count;
1764 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1765 });
1766 pi2_event_loop->MakeWatcher(
1767 "/test", [&pi2_event_loop, &pi2_ping_count,
1768 &pi2_pong_count](const examples::Pong &pong) {
1769 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1770 << pi2_event_loop->context().monotonic_remote_time << " -> "
1771 << pi2_event_loop->context().monotonic_event_time;
1772
1773 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1774 ++pi2_pong_count;
1775 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1776 });
1777
1778 log_reader_factory.Run();
1779 EXPECT_EQ(pi1_ping_count, 2030);
1780 EXPECT_EQ(pi2_ping_count, 2030);
1781 EXPECT_EQ(pi1_pong_count, 2030);
1782 EXPECT_EQ(pi2_pong_count, 2030);
1783
1784 reader.Deregister();
1785}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001786
Austin Schuh8bd96322020-02-13 21:18:22 -08001787// Tests that we can read log files where the monotonic clocks drift and don't
1788// match correctly. While we are here, also test that different ending times
1789// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001790TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001791 // TODO(austin): Negate...
1792 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1793
Austin Schuh66168842021-08-17 19:42:21 -07001794 time_converter_.AddMonotonic(
1795 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001796 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1797 // skew to be 200 uS/s
1798 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1799 {chrono::milliseconds(95),
1800 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1801 // Run another 200 ms to have one logger start first.
1802 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1803 {chrono::milliseconds(200), chrono::milliseconds(200)});
1804 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1805 // go far enough to cause problems if this isn't accounted for.
1806 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1807 {chrono::milliseconds(20000),
1808 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1809 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1810 {chrono::milliseconds(40000),
1811 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1812 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1813 {chrono::milliseconds(400), chrono::milliseconds(400)});
1814
Austin Schuhcde938c2020-02-02 17:30:07 -08001815 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001816 LoggerState pi2_logger = MakeLogger(pi2_);
1817
Austin Schuh58646e22021-08-23 23:51:46 -07001818 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1819 << pi2_->realtime_now() << " distributed "
1820 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001821
Austin Schuh58646e22021-08-23 23:51:46 -07001822 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1823 << pi2_->realtime_now() << " distributed "
1824 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001825
Austin Schuh87dd3832021-01-01 23:07:31 -08001826 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001827
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001828 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001829
Austin Schuh87dd3832021-01-01 23:07:31 -08001830 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001831
Austin Schuh8bd96322020-02-13 21:18:22 -08001832 {
1833 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001834 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001835
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001836 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001837 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001838
Austin Schuh87dd3832021-01-01 23:07:31 -08001839 // Make sure we slewed time far enough so that the difference is greater
1840 // than the network delay. This confirms that if we sort incorrectly, it
1841 // would show in the results.
1842 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001843 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001844 -event_loop_factory_.send_delay() -
1845 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001846
Austin Schuh87dd3832021-01-01 23:07:31 -08001847 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001848
Austin Schuh87dd3832021-01-01 23:07:31 -08001849 // And now check that we went far enough the other way to make sure we
1850 // cover both problems.
1851 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001852 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001853 event_loop_factory_.send_delay() +
1854 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001855 }
1856
1857 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001858 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001859 }
1860
Austin Schuh72211ae2021-08-05 14:02:30 -07001861 LogReader reader(
1862 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001863
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001864 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001865 log_reader_factory.set_send_delay(chrono::microseconds(0));
1866
Austin Schuhcde938c2020-02-02 17:30:07 -08001867 const Node *pi1 =
1868 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1869 const Node *pi2 =
1870 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1871
Austin Schuh2f8fd752020-09-01 22:38:28 -07001872 // This sends out the fetched messages and advances time to the start of the
1873 // log file.
1874 reader.Register(&log_reader_factory);
1875
1876 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1877 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1878 LOG(INFO) << "now pi1 "
1879 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1880 LOG(INFO) << "now pi2 "
1881 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1882
Austin Schuhcde938c2020-02-02 17:30:07 -08001883 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001884 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1885 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001886 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1887 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001888 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1889 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001890 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1891
Austin Schuh07676622021-01-21 18:59:17 -08001892 EXPECT_THAT(reader.LoggedNodes(),
1893 ::testing::ElementsAre(
1894 configuration::GetNode(reader.logged_configuration(), pi1),
1895 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001896
1897 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1898
1899 std::unique_ptr<EventLoop> pi1_event_loop =
1900 log_reader_factory.MakeEventLoop("test", pi1);
1901 std::unique_ptr<EventLoop> pi2_event_loop =
1902 log_reader_factory.MakeEventLoop("test", pi2);
1903
1904 int pi1_ping_count = 30;
1905 int pi2_ping_count = 30;
1906 int pi1_pong_count = 30;
1907 int pi2_pong_count = 30;
1908
1909 // Confirm that the ping value matches.
1910 pi1_event_loop->MakeWatcher(
1911 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1912 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1913 << pi1_event_loop->context().monotonic_remote_time << " -> "
1914 << pi1_event_loop->context().monotonic_event_time;
1915 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1916
1917 ++pi1_ping_count;
1918 });
1919 pi2_event_loop->MakeWatcher(
1920 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1921 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1922 << pi2_event_loop->context().monotonic_remote_time << " -> "
1923 << pi2_event_loop->context().monotonic_event_time;
1924 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1925
1926 ++pi2_ping_count;
1927 });
1928
1929 // Confirm that the ping and pong counts both match, and the value also
1930 // matches.
1931 pi1_event_loop->MakeWatcher(
1932 "/test", [&pi1_event_loop, &pi1_ping_count,
1933 &pi1_pong_count](const examples::Pong &pong) {
1934 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1935 << pi1_event_loop->context().monotonic_remote_time << " -> "
1936 << pi1_event_loop->context().monotonic_event_time;
1937
1938 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1939 ++pi1_pong_count;
1940 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1941 });
1942 pi2_event_loop->MakeWatcher(
1943 "/test", [&pi2_event_loop, &pi2_ping_count,
1944 &pi2_pong_count](const examples::Pong &pong) {
1945 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1946 << pi2_event_loop->context().monotonic_remote_time << " -> "
1947 << pi2_event_loop->context().monotonic_event_time;
1948
1949 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1950 ++pi2_pong_count;
1951 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1952 });
1953
1954 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001955 EXPECT_EQ(pi1_ping_count, 6030);
1956 EXPECT_EQ(pi2_ping_count, 6030);
1957 EXPECT_EQ(pi1_pong_count, 6030);
1958 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001959
1960 reader.Deregister();
1961}
1962
Austin Schuh5212cad2020-09-09 23:12:09 -07001963// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001964TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001965 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001966 // Make a bunch of parts.
1967 {
1968 LoggerState pi1_logger = MakeLogger(pi1_);
1969 LoggerState pi2_logger = MakeLogger(pi2_);
1970
1971 event_loop_factory_.RunFor(chrono::milliseconds(95));
1972
1973 StartLogger(&pi1_logger);
1974 StartLogger(&pi2_logger);
1975
1976 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1977 }
1978
Austin Schuh11d43732020-09-21 17:28:30 -07001979 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001980 VerifyParts(sorted_parts);
1981}
Austin Schuh11d43732020-09-21 17:28:30 -07001982
Austin Schuh3bd4c402020-11-06 18:19:06 -08001983// Tests that we can sort a bunch of parts with an empty part. We should ignore
1984// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001985TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001986 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001987 // Make a bunch of parts.
1988 {
1989 LoggerState pi1_logger = MakeLogger(pi1_);
1990 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001991
Austin Schuh3bd4c402020-11-06 18:19:06 -08001992 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001993
Austin Schuh3bd4c402020-11-06 18:19:06 -08001994 StartLogger(&pi1_logger);
1995 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001996
Austin Schuh3bd4c402020-11-06 18:19:06 -08001997 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001998 }
1999
Austin Schuh3bd4c402020-11-06 18:19:06 -08002000 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07002001 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07002002
Austin Schuh3bd4c402020-11-06 18:19:06 -08002003 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
2004 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07002005
Austin Schuh3bd4c402020-11-06 18:19:06 -08002006 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2007 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07002008}
2009
James Kuszmauldd0a5042021-10-28 23:38:04 -07002010// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08002011// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002012TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002013 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002014 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002015 // Make a bunch of parts.
2016 {
2017 LoggerState pi1_logger = MakeLogger(pi1_);
2018 LoggerState pi2_logger = MakeLogger(pi2_);
2019
2020 event_loop_factory_.RunFor(chrono::milliseconds(95));
2021
James Kuszmauldd0a5042021-10-28 23:38:04 -07002022 StartLogger(&pi1_logger);
2023 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002024
2025 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002026
2027 pi1_logger.AppendAllFilenames(&actual_filenames);
2028 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002029 }
2030
Austin Schuhbfe6c572022-01-27 20:48:20 -08002031 ASSERT_THAT(actual_filenames,
2032 ::testing::UnorderedElementsAreArray(logfiles_));
2033
Austin Schuh3bd4c402020-11-06 18:19:06 -08002034 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002035 // For snappy, needs to have enough data to be >1 chunk of compressed data so
2036 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08002037 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08002038 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002039
2040 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08002041 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08002042 compressed_contents.substr(0, compressed_contents.size() - 100));
2043
2044 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2045 VerifyParts(sorted_parts);
2046}
Austin Schuh3bd4c402020-11-06 18:19:06 -08002047
Austin Schuh01b4c352020-09-21 23:09:39 -07002048// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08002049TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002050 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07002051 {
2052 LoggerState pi1_logger = MakeLogger(pi1_);
2053 LoggerState pi2_logger = MakeLogger(pi2_);
2054
2055 event_loop_factory_.RunFor(chrono::milliseconds(95));
2056
2057 StartLogger(&pi1_logger);
2058 StartLogger(&pi2_logger);
2059
2060 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2061 }
2062
Austin Schuh287d43d2020-12-04 20:19:33 -08002063 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07002064
2065 // Remap just on pi1.
2066 reader.RemapLoggedChannel<aos::timing::Report>(
2067 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
2068
2069 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2070 log_reader_factory.set_send_delay(chrono::microseconds(0));
2071
Austin Schuh1c227352021-09-17 12:53:54 -07002072 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
2073 ASSERT_EQ(remapped_channels.size(), 1u);
2074 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
2075 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
2076
Austin Schuh01b4c352020-09-21 23:09:39 -07002077 reader.Register(&log_reader_factory);
2078
2079 const Node *pi1 =
2080 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2081 const Node *pi2 =
2082 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2083
2084 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2085 // else should have moved.
2086 std::unique_ptr<EventLoop> pi1_event_loop =
2087 log_reader_factory.MakeEventLoop("test", pi1);
2088 pi1_event_loop->SkipTimingReport();
2089 std::unique_ptr<EventLoop> full_pi1_event_loop =
2090 log_reader_factory.MakeEventLoop("test", pi1);
2091 full_pi1_event_loop->SkipTimingReport();
2092 std::unique_ptr<EventLoop> pi2_event_loop =
2093 log_reader_factory.MakeEventLoop("test", pi2);
2094 pi2_event_loop->SkipTimingReport();
2095
2096 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
2097 "/aos");
2098 MessageCounter<aos::timing::Report> full_pi1_timing_report(
2099 full_pi1_event_loop.get(), "/pi1/aos");
2100 MessageCounter<aos::timing::Report> pi1_original_timing_report(
2101 pi1_event_loop.get(), "/original/aos");
2102 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
2103 full_pi1_event_loop.get(), "/original/pi1/aos");
2104 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
2105 "/aos");
2106
2107 log_reader_factory.Run();
2108
2109 EXPECT_EQ(pi1_timing_report.count(), 0u);
2110 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
2111 EXPECT_NE(pi1_original_timing_report.count(), 0u);
2112 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
2113 EXPECT_NE(pi2_timing_report.count(), 0u);
2114
2115 reader.Deregister();
2116}
2117
Austin Schuh006a9f52021-04-07 16:24:18 -07002118// Tests that we can remap a forwarded channel as well.
2119TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
2120 time_converter_.StartEqual();
2121 {
2122 LoggerState pi1_logger = MakeLogger(pi1_);
2123 LoggerState pi2_logger = MakeLogger(pi2_);
2124
2125 event_loop_factory_.RunFor(chrono::milliseconds(95));
2126
2127 StartLogger(&pi1_logger);
2128 StartLogger(&pi2_logger);
2129
2130 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2131 }
2132
2133 LogReader reader(SortParts(logfiles_));
2134
2135 reader.RemapLoggedChannel<examples::Ping>("/test");
2136
2137 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2138 log_reader_factory.set_send_delay(chrono::microseconds(0));
2139
2140 reader.Register(&log_reader_factory);
2141
2142 const Node *pi1 =
2143 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2144 const Node *pi2 =
2145 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2146
2147 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2148 // else should have moved.
2149 std::unique_ptr<EventLoop> pi1_event_loop =
2150 log_reader_factory.MakeEventLoop("test", pi1);
2151 pi1_event_loop->SkipTimingReport();
2152 std::unique_ptr<EventLoop> full_pi1_event_loop =
2153 log_reader_factory.MakeEventLoop("test", pi1);
2154 full_pi1_event_loop->SkipTimingReport();
2155 std::unique_ptr<EventLoop> pi2_event_loop =
2156 log_reader_factory.MakeEventLoop("test", pi2);
2157 pi2_event_loop->SkipTimingReport();
2158
2159 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2160 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2161 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2162 "/original/test");
2163 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2164 "/original/test");
2165
2166 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2167 pi1_original_ping_timestamp;
2168 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2169 pi1_ping_timestamp;
2170 if (!shared()) {
2171 pi1_original_ping_timestamp =
2172 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2173 pi1_event_loop.get(),
2174 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2175 pi1_ping_timestamp =
2176 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2177 pi1_event_loop.get(),
2178 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2179 }
2180
2181 log_reader_factory.Run();
2182
2183 EXPECT_EQ(pi1_ping.count(), 0u);
2184 EXPECT_EQ(pi2_ping.count(), 0u);
2185 EXPECT_NE(pi1_original_ping.count(), 0u);
2186 EXPECT_NE(pi2_original_ping.count(), 0u);
2187 if (!shared()) {
2188 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2189 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2190 }
2191
2192 reader.Deregister();
2193}
2194
James Kuszmaul09632422022-05-25 15:56:19 -07002195// Tests that we observe all the same events in log replay (for a given node)
2196// whether we just register an event loop for that node or if we register a full
2197// event loop factory.
2198TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
2199 time_converter_.StartEqual();
2200 constexpr chrono::milliseconds kStartupDelay(95);
2201 {
2202 LoggerState pi1_logger = MakeLogger(pi1_);
2203 LoggerState pi2_logger = MakeLogger(pi2_);
2204
2205 event_loop_factory_.RunFor(kStartupDelay);
2206
2207 StartLogger(&pi1_logger);
2208 StartLogger(&pi2_logger);
2209
2210 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2211 }
2212
2213 LogReader full_reader(SortParts(logfiles_));
2214 LogReader single_node_reader(SortParts(logfiles_));
2215
2216 SimulatedEventLoopFactory full_factory(full_reader.configuration());
2217 SimulatedEventLoopFactory single_node_factory(
2218 single_node_reader.configuration());
2219 std::unique_ptr<EventLoop> replay_event_loop =
2220 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
2221 "log_reader");
2222
2223 full_reader.Register(&full_factory);
2224 single_node_reader.Register(replay_event_loop.get());
2225 single_node_factory.SkipTimingReport();
2226 single_node_factory.DisableStatistics();
2227
2228 const Node *full_pi1 =
2229 configuration::GetNode(full_factory.configuration(), "pi1");
2230
2231 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2232 // else should have moved.
2233 std::unique_ptr<EventLoop> full_event_loop =
2234 full_factory.MakeEventLoop("test", full_pi1);
2235 full_event_loop->SkipTimingReport();
2236 full_event_loop->SkipAosLog();
2237 // maps are indexed on channel index.
2238 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
2239 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
2240 observed_messages;
2241 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
2242 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
2243 ++ii) {
2244 const Channel *channel =
2245 full_event_loop->configuration()->channels()->Get(ii);
2246 // We currently don't support replaying remote timestamp channels in
2247 // realtime replay.
2248 if (channel->name()->string_view().find("remote_timestamp") !=
2249 std::string_view::npos) {
2250 continue;
2251 }
2252 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
2253 observed_messages[ii] = {};
2254 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
2255 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
2256 if (fetchers[ii]->Fetch()) {
2257 observed_messages[ii].push_back(std::make_pair(
2258 fetchers[ii]->context().monotonic_event_time, true));
2259 }
2260 });
2261 full_event_loop->MakeRawNoArgWatcher(
2262 channel, [ii, &observed_messages](const Context &context) {
2263 observed_messages[ii].push_back(
2264 std::make_pair(context.monotonic_event_time, false));
2265 });
2266 }
2267 }
2268
2269 full_factory.Run();
2270 fetchers.clear();
2271 full_reader.Deregister();
2272
2273 const Node *single_node_pi1 =
2274 configuration::GetNode(single_node_factory.configuration(), "pi1");
2275 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
2276
2277 std::unique_ptr<EventLoop> single_node_event_loop =
2278 single_node_factory.MakeEventLoop("test", single_node_pi1);
2279 single_node_event_loop->SkipTimingReport();
2280 single_node_event_loop->SkipAosLog();
2281 for (size_t ii = 0;
2282 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
2283 const Channel *channel =
2284 single_node_event_loop->configuration()->channels()->Get(ii);
2285 single_node_factory.DisableForwarding(channel);
2286 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
2287 single_node_fetchers[ii] =
2288 single_node_event_loop->MakeRawFetcher(channel);
2289 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
2290 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
2291 << "Single EventLoop replay doesn't support pre-loading fetchers. "
2292 << configuration::StrippedChannelToString(channel);
2293 });
2294 single_node_event_loop->MakeRawNoArgWatcher(
2295 channel, [ii, &observed_messages, channel,
2296 kStartupDelay](const Context &context) {
2297 if (observed_messages[ii].empty()) {
2298 FAIL() << "Observed extra message at "
2299 << context.monotonic_event_time << " on "
2300 << configuration::StrippedChannelToString(channel);
2301 return;
2302 }
2303 const std::pair<monotonic_clock::time_point, bool> &message =
2304 observed_messages[ii].front();
2305 if (message.second) {
2306 EXPECT_LE(message.first,
2307 context.monotonic_event_time + kStartupDelay)
2308 << "Mismatched message times " << context.monotonic_event_time
2309 << " and " << message.first << " on "
2310 << configuration::StrippedChannelToString(channel);
2311 } else {
2312 EXPECT_EQ(message.first,
2313 context.monotonic_event_time + kStartupDelay)
2314 << "Mismatched message times " << context.monotonic_event_time
2315 << " and " << message.first << " on "
2316 << configuration::StrippedChannelToString(channel);
2317 }
2318 observed_messages[ii].erase(observed_messages[ii].begin());
2319 });
2320 }
2321 }
2322
2323 single_node_factory.Run();
2324
2325 single_node_fetchers.clear();
2326
2327 single_node_reader.Deregister();
2328
2329 for (const auto &pair : observed_messages) {
2330 EXPECT_TRUE(pair.second.empty())
2331 << "Missed " << pair.second.size() << " messages on "
2332 << configuration::StrippedChannelToString(
2333 single_node_event_loop->configuration()->channels()->Get(
2334 pair.first));
2335 }
2336}
2337
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002338// Tests that we properly recreate forwarded timestamps when replaying a log.
2339// This should be enough that we can then re-run the logger and get a valid log
2340// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002341TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002342 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002343 {
2344 LoggerState pi1_logger = MakeLogger(pi1_);
2345 LoggerState pi2_logger = MakeLogger(pi2_);
2346
2347 event_loop_factory_.RunFor(chrono::milliseconds(95));
2348
2349 StartLogger(&pi1_logger);
2350 StartLogger(&pi2_logger);
2351
2352 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2353 }
2354
Austin Schuh287d43d2020-12-04 20:19:33 -08002355 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002356
2357 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2358 log_reader_factory.set_send_delay(chrono::microseconds(0));
2359
2360 // This sends out the fetched messages and advances time to the start of the
2361 // log file.
2362 reader.Register(&log_reader_factory);
2363
2364 const Node *pi1 =
2365 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2366 const Node *pi2 =
2367 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2368
2369 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2370 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2371 LOG(INFO) << "now pi1 "
2372 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2373 LOG(INFO) << "now pi2 "
2374 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2375
Austin Schuh07676622021-01-21 18:59:17 -08002376 EXPECT_THAT(reader.LoggedNodes(),
2377 ::testing::ElementsAre(
2378 configuration::GetNode(reader.logged_configuration(), pi1),
2379 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002380
2381 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2382
2383 std::unique_ptr<EventLoop> pi1_event_loop =
2384 log_reader_factory.MakeEventLoop("test", pi1);
2385 std::unique_ptr<EventLoop> pi2_event_loop =
2386 log_reader_factory.MakeEventLoop("test", pi2);
2387
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002388 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2389 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2390 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2391 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2392
2393 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2394 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2395 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2396 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2397
2398 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2399 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2400 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2401 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2402
2403 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2404 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2405 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2406 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2407
2408 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2409 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2410 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2411 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2412
2413 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2414 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2415 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2416 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2417
Austin Schuh969cd602021-01-03 00:09:45 -08002418 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002419 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002420
Austin Schuh61e973f2021-02-21 21:43:56 -08002421 for (std::pair<int, std::string> channel :
2422 shared()
2423 ? std::vector<
2424 std::pair<int, std::string>>{{-1,
2425 "/aos/remote_timestamps/pi2"}}
2426 : std::vector<std::pair<int, std::string>>{
2427 {pi1_timestamp_channel,
2428 "/aos/remote_timestamps/pi2/pi1/aos/"
2429 "aos-message_bridge-Timestamp"},
2430 {ping_timestamp_channel,
2431 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2432 pi1_event_loop->MakeWatcher(
2433 channel.second,
2434 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2435 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2436 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2437 &ping_on_pi2_fetcher, network_delay, send_delay,
2438 channel_index = channel.first](const RemoteMessage &header) {
2439 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2440 chrono::nanoseconds(header.monotonic_sent_time()));
2441 const aos::realtime_clock::time_point header_realtime_sent_time(
2442 chrono::nanoseconds(header.realtime_sent_time()));
2443 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2444 chrono::nanoseconds(header.monotonic_remote_time()));
2445 const aos::realtime_clock::time_point header_realtime_remote_time(
2446 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002447
Austin Schuh61e973f2021-02-21 21:43:56 -08002448 if (channel_index != -1) {
2449 ASSERT_EQ(channel_index, header.channel_index());
2450 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002451
Austin Schuh61e973f2021-02-21 21:43:56 -08002452 const Context *pi1_context = nullptr;
2453 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002454
Austin Schuh61e973f2021-02-21 21:43:56 -08002455 if (header.channel_index() == pi1_timestamp_channel) {
2456 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2457 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2458 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2459 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2460 } else if (header.channel_index() == ping_timestamp_channel) {
2461 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2462 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2463 pi1_context = &ping_on_pi1_fetcher.context();
2464 pi2_context = &ping_on_pi2_fetcher.context();
2465 } else {
2466 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2467 << configuration::CleanedChannelToString(
2468 pi1_event_loop->configuration()->channels()->Get(
2469 header.channel_index()));
2470 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002471
Austin Schuh61e973f2021-02-21 21:43:56 -08002472 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002473 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2474 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002475
Austin Schuh61e973f2021-02-21 21:43:56 -08002476 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2477 EXPECT_EQ(pi2_context->remote_queue_index,
2478 header.remote_queue_index());
2479 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002480
Austin Schuh61e973f2021-02-21 21:43:56 -08002481 EXPECT_EQ(pi2_context->monotonic_event_time,
2482 header_monotonic_sent_time);
2483 EXPECT_EQ(pi2_context->realtime_event_time,
2484 header_realtime_sent_time);
2485 EXPECT_EQ(pi2_context->realtime_remote_time,
2486 header_realtime_remote_time);
2487 EXPECT_EQ(pi2_context->monotonic_remote_time,
2488 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002489
Austin Schuh61e973f2021-02-21 21:43:56 -08002490 EXPECT_EQ(pi1_context->realtime_event_time,
2491 header_realtime_remote_time);
2492 EXPECT_EQ(pi1_context->monotonic_event_time,
2493 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002494
Austin Schuh61e973f2021-02-21 21:43:56 -08002495 // Time estimation isn't perfect, but we know the clocks were
2496 // identical when logged, so we know when this should have come back.
2497 // Confirm we got it when we expected.
2498 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2499 pi1_context->monotonic_event_time + 2 * network_delay +
2500 send_delay);
2501 });
2502 }
2503 for (std::pair<int, std::string> channel :
2504 shared()
2505 ? std::vector<
2506 std::pair<int, std::string>>{{-1,
2507 "/aos/remote_timestamps/pi1"}}
2508 : std::vector<std::pair<int, std::string>>{
2509 {pi2_timestamp_channel,
2510 "/aos/remote_timestamps/pi1/pi2/aos/"
2511 "aos-message_bridge-Timestamp"}}) {
2512 pi2_event_loop->MakeWatcher(
2513 channel.second,
2514 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2515 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2516 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2517 &pong_on_pi1_fetcher, network_delay, send_delay,
2518 channel_index = channel.first](const RemoteMessage &header) {
2519 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2520 chrono::nanoseconds(header.monotonic_sent_time()));
2521 const aos::realtime_clock::time_point header_realtime_sent_time(
2522 chrono::nanoseconds(header.realtime_sent_time()));
2523 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2524 chrono::nanoseconds(header.monotonic_remote_time()));
2525 const aos::realtime_clock::time_point header_realtime_remote_time(
2526 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002527
Austin Schuh61e973f2021-02-21 21:43:56 -08002528 if (channel_index != -1) {
2529 ASSERT_EQ(channel_index, header.channel_index());
2530 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002531
Austin Schuh61e973f2021-02-21 21:43:56 -08002532 const Context *pi2_context = nullptr;
2533 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002534
Austin Schuh61e973f2021-02-21 21:43:56 -08002535 if (header.channel_index() == pi2_timestamp_channel) {
2536 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2537 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2538 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2539 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2540 } else if (header.channel_index() == pong_timestamp_channel) {
2541 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2542 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2543 pi2_context = &pong_on_pi2_fetcher.context();
2544 pi1_context = &pong_on_pi1_fetcher.context();
2545 } else {
2546 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2547 << configuration::CleanedChannelToString(
2548 pi2_event_loop->configuration()->channels()->Get(
2549 header.channel_index()));
2550 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002551
Austin Schuh61e973f2021-02-21 21:43:56 -08002552 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002553 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2554 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002555
Austin Schuh61e973f2021-02-21 21:43:56 -08002556 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2557 EXPECT_EQ(pi1_context->remote_queue_index,
2558 header.remote_queue_index());
2559 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002560
Austin Schuh61e973f2021-02-21 21:43:56 -08002561 EXPECT_EQ(pi1_context->monotonic_event_time,
2562 header_monotonic_sent_time);
2563 EXPECT_EQ(pi1_context->realtime_event_time,
2564 header_realtime_sent_time);
2565 EXPECT_EQ(pi1_context->realtime_remote_time,
2566 header_realtime_remote_time);
2567 EXPECT_EQ(pi1_context->monotonic_remote_time,
2568 header_monotonic_remote_time);
2569
2570 EXPECT_EQ(pi2_context->realtime_event_time,
2571 header_realtime_remote_time);
2572 EXPECT_EQ(pi2_context->monotonic_event_time,
2573 header_monotonic_remote_time);
2574
2575 // Time estimation isn't perfect, but we know the clocks were
2576 // identical when logged, so we know when this should have come back.
2577 // Confirm we got it when we expected.
2578 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2579 pi2_context->monotonic_event_time + 2 * network_delay +
2580 send_delay);
2581 });
2582 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002583
2584 // And confirm we can re-create a log again, while checking the contents.
2585 {
2586 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002587 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002588 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002589 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002590
Austin Schuh25b46712021-01-03 00:04:38 -08002591 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2592 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002593
2594 log_reader_factory.Run();
2595 }
2596
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002597 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002598
2599 // And verify that we can run the LogReader over the relogged files without
2600 // hitting any fatal errors.
2601 {
2602 LogReader relogged_reader(SortParts(
2603 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2604 relogged_reader.Register();
2605
2606 relogged_reader.event_loop_factory()->Run();
2607 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002608}
2609
Austin Schuh315b96b2020-12-11 21:21:12 -08002610// Tests that we properly populate and extract the logger_start time by setting
2611// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002612TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002613 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002614 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002615 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002616 {
2617 LoggerState pi1_logger = MakeLogger(pi1_);
2618 LoggerState pi2_logger = MakeLogger(pi2_);
2619
Austin Schuh315b96b2020-12-11 21:21:12 -08002620 StartLogger(&pi1_logger);
2621 StartLogger(&pi2_logger);
2622
2623 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002624
2625 pi1_logger.AppendAllFilenames(&actual_filenames);
2626 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002627 }
2628
Austin Schuhf5f99f32022-02-07 20:05:37 -08002629 ASSERT_THAT(actual_filenames,
2630 ::testing::UnorderedElementsAreArray(logfiles_));
2631
Austin Schuh315b96b2020-12-11 21:21:12 -08002632 for (const LogFile &log_file : SortParts(logfiles_)) {
2633 for (const LogParts &log_part : log_file.parts) {
2634 if (log_part.node == log_file.logger_node) {
2635 EXPECT_EQ(log_part.logger_monotonic_start_time,
2636 aos::monotonic_clock::min_time);
2637 EXPECT_EQ(log_part.logger_realtime_start_time,
2638 aos::realtime_clock::min_time);
2639 } else {
2640 const chrono::seconds offset = log_file.logger_node == "pi1"
2641 ? -chrono::seconds(1000)
2642 : chrono::seconds(1000);
2643 EXPECT_EQ(log_part.logger_monotonic_start_time,
2644 log_part.monotonic_start_time + offset);
2645 EXPECT_EQ(log_part.logger_realtime_start_time,
2646 log_file.realtime_start_time +
2647 (log_part.logger_monotonic_start_time -
2648 log_file.monotonic_start_time));
2649 }
2650 }
2651 }
2652}
2653
Austin Schuh6bb8a822021-03-31 23:04:39 -07002654// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002655TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002656 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2657 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002658 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002659 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002660 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2661 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2662 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2663 LoggerState pi1_logger = MakeLogger(pi1_);
2664 LoggerState pi2_logger = MakeLogger(pi2_);
2665
2666 StartLogger(&pi1_logger);
2667 StartLogger(&pi2_logger);
2668
2669 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2670 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2671 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2672 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2673 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2674 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2675 for (auto &file : logfiles_) {
2676 struct stat s;
2677 EXPECT_EQ(0, stat(file.c_str(), &s));
2678 }
2679}
2680
2681// Test that renaming the file base dies.
2682TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2683 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002684 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002685 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002686 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2687 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2688 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2689 LoggerState pi1_logger = MakeLogger(pi1_);
2690 StartLogger(&pi1_logger);
2691 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2692 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2693 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2694 "Rename of file base from");
2695}
2696
Austin Schuh8bd96322020-02-13 21:18:22 -08002697// TODO(austin): We can write a test which recreates a logfile and confirms that
2698// we get it back. That is the ultimate test.
2699
Austin Schuh315b96b2020-12-11 21:21:12 -08002700// Tests that we properly recreate forwarded timestamps when replaying a log.
2701// This should be enough that we can then re-run the logger and get a valid log
2702// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002703TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002704 std::vector<std::string> actual_filenames;
2705
Austin Schuh58646e22021-08-23 23:51:46 -07002706 const UUID pi1_boot0 = UUID::Random();
2707 const UUID pi2_boot0 = UUID::Random();
2708 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002709 {
Austin Schuh58646e22021-08-23 23:51:46 -07002710 CHECK_EQ(pi1_index_, 0u);
2711 CHECK_EQ(pi2_index_, 1u);
2712
2713 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2714 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2715 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2716
2717 time_converter_.AddNextTimestamp(
2718 distributed_clock::epoch(),
2719 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2720 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2721 time_converter_.AddNextTimestamp(
2722 distributed_clock::epoch() + reboot_time,
2723 {BootTimestamp::epoch() + reboot_time,
2724 BootTimestamp{
2725 .boot = 1,
2726 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2727 }
2728
2729 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002730 LoggerState pi1_logger = MakeLogger(pi1_);
2731
2732 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002733 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2734 pi1_boot0);
2735 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2736 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002737
2738 StartLogger(&pi1_logger);
2739
2740 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2741
Austin Schuh58646e22021-08-23 23:51:46 -07002742 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002743
2744 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002745 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2746 pi1_boot0);
2747 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2748 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002749
2750 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002751 }
2752
Austin Schuhbfe6c572022-01-27 20:48:20 -08002753 std::sort(actual_filenames.begin(), actual_filenames.end());
2754 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2755 ASSERT_THAT(actual_filenames,
2756 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2757
Austin Schuh72211ae2021-08-05 14:02:30 -07002758 // Confirm that our new oldest timestamps properly update as we reboot and
2759 // rotate.
2760 for (const std::string &file : pi1_reboot_logfiles_) {
2761 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2762 ReadHeader(file);
2763 CHECK(log_header);
2764 if (log_header->message().has_configuration()) {
2765 continue;
2766 }
2767
Austin Schuh58646e22021-08-23 23:51:46 -07002768 const monotonic_clock::time_point monotonic_start_time =
2769 monotonic_clock::time_point(
2770 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2771 const UUID source_node_boot_uuid = UUID::FromString(
2772 log_header->message().source_node_boot_uuid()->string_view());
2773
Austin Schuh72211ae2021-08-05 14:02:30 -07002774 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002775 // The remote message channel should rotate later and have more parts.
2776 // This only is true on the log files with shared remote messages.
2777 //
2778 // TODO(austin): I'm not the most thrilled with this test pattern... It
2779 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002780 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2781 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002782 switch (log_header->message().parts_index()) {
2783 case 0:
2784 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2785 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2786 break;
2787 case 1:
2788 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2789 ASSERT_EQ(monotonic_start_time,
2790 monotonic_clock::epoch() + chrono::seconds(1));
2791 break;
2792 case 2:
2793 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2794 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2795 break;
2796 case 3:
2797 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2798 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2799 chrono::nanoseconds(2322999462))
2800 << " on " << file;
2801 break;
2802 default:
2803 FAIL();
2804 break;
2805 }
2806 } else {
2807 switch (log_header->message().parts_index()) {
2808 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002809 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002810 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2811 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2812 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002813 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002814 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2815 ASSERT_EQ(monotonic_start_time,
2816 monotonic_clock::epoch() + chrono::seconds(1));
2817 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002818 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002819 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002820 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2821 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2822 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002823 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002824 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2825 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2826 chrono::nanoseconds(2322999462))
2827 << " on " << file;
2828 break;
2829 default:
2830 FAIL();
2831 break;
2832 }
Austin Schuh58646e22021-08-23 23:51:46 -07002833 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002834 continue;
2835 }
2836 SCOPED_TRACE(file);
2837 SCOPED_TRACE(aos::FlatbufferToJson(
2838 *log_header, {.multi_line = true, .max_vector_size = 100}));
2839 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2840 ASSERT_EQ(
2841 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2842 EXPECT_EQ(
2843 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2844 monotonic_clock::max_time.time_since_epoch().count());
2845 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2846 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2847 2u);
2848 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2849 monotonic_clock::max_time.time_since_epoch().count());
2850 ASSERT_TRUE(log_header->message()
2851 .has_oldest_remote_unreliable_monotonic_timestamps());
2852 ASSERT_EQ(log_header->message()
2853 .oldest_remote_unreliable_monotonic_timestamps()
2854 ->size(),
2855 2u);
2856 EXPECT_EQ(log_header->message()
2857 .oldest_remote_unreliable_monotonic_timestamps()
2858 ->Get(0),
2859 monotonic_clock::max_time.time_since_epoch().count());
2860 ASSERT_TRUE(log_header->message()
2861 .has_oldest_local_unreliable_monotonic_timestamps());
2862 ASSERT_EQ(log_header->message()
2863 .oldest_local_unreliable_monotonic_timestamps()
2864 ->size(),
2865 2u);
2866 EXPECT_EQ(log_header->message()
2867 .oldest_local_unreliable_monotonic_timestamps()
2868 ->Get(0),
2869 monotonic_clock::max_time.time_since_epoch().count());
2870
2871 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2872 monotonic_clock::time_point(chrono::nanoseconds(
2873 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2874 1)));
2875 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2876 monotonic_clock::time_point(chrono::nanoseconds(
2877 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2878 const monotonic_clock::time_point
2879 oldest_remote_unreliable_monotonic_timestamps =
2880 monotonic_clock::time_point(chrono::nanoseconds(
2881 log_header->message()
2882 .oldest_remote_unreliable_monotonic_timestamps()
2883 ->Get(1)));
2884 const monotonic_clock::time_point
2885 oldest_local_unreliable_monotonic_timestamps =
2886 monotonic_clock::time_point(chrono::nanoseconds(
2887 log_header->message()
2888 .oldest_local_unreliable_monotonic_timestamps()
2889 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002890 const monotonic_clock::time_point
2891 oldest_remote_reliable_monotonic_timestamps =
2892 monotonic_clock::time_point(chrono::nanoseconds(
2893 log_header->message()
2894 .oldest_remote_reliable_monotonic_timestamps()
2895 ->Get(1)));
2896 const monotonic_clock::time_point
2897 oldest_local_reliable_monotonic_timestamps =
2898 monotonic_clock::time_point(chrono::nanoseconds(
2899 log_header->message()
2900 .oldest_local_reliable_monotonic_timestamps()
2901 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002902 const monotonic_clock::time_point
2903 oldest_logger_remote_unreliable_monotonic_timestamps =
2904 monotonic_clock::time_point(chrono::nanoseconds(
2905 log_header->message()
2906 .oldest_logger_remote_unreliable_monotonic_timestamps()
2907 ->Get(0)));
2908 const monotonic_clock::time_point
2909 oldest_logger_local_unreliable_monotonic_timestamps =
2910 monotonic_clock::time_point(chrono::nanoseconds(
2911 log_header->message()
2912 .oldest_logger_local_unreliable_monotonic_timestamps()
2913 ->Get(0)));
2914 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2915 monotonic_clock::max_time);
2916 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2917 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002918 switch (log_header->message().parts_index()) {
2919 case 0:
2920 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2921 monotonic_clock::max_time);
2922 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2923 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2924 monotonic_clock::max_time);
2925 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2926 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002927 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2928 monotonic_clock::max_time);
2929 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2930 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002931 break;
2932 case 1:
2933 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2934 monotonic_clock::time_point(chrono::microseconds(90200)));
2935 EXPECT_EQ(oldest_local_monotonic_timestamps,
2936 monotonic_clock::time_point(chrono::microseconds(90350)));
2937 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2938 monotonic_clock::time_point(chrono::microseconds(90200)));
2939 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2940 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002941 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2942 monotonic_clock::max_time);
2943 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2944 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002945 break;
2946 case 2:
2947 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08002948 monotonic_clock::time_point(chrono::microseconds(90200)))
2949 << file;
2950 EXPECT_EQ(oldest_local_monotonic_timestamps,
2951 monotonic_clock::time_point(chrono::microseconds(90350)))
2952 << file;
2953 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2954 monotonic_clock::time_point(chrono::microseconds(90200)))
2955 << file;
2956 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2957 monotonic_clock::time_point(chrono::microseconds(90350)))
2958 << file;
2959 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2960 monotonic_clock::time_point(chrono::microseconds(100000)))
2961 << file;
2962 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2963 monotonic_clock::time_point(chrono::microseconds(100150)))
2964 << file;
2965 break;
2966 case 3:
2967 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002968 monotonic_clock::time_point(chrono::milliseconds(1323) +
2969 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002970 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002971 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002972 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002973 monotonic_clock::time_point(chrono::milliseconds(1323) +
2974 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002975 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2976 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002977 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2978 monotonic_clock::max_time)
2979 << file;
2980 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2981 monotonic_clock::max_time)
2982 << file;
2983 break;
2984 case 4:
2985 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2986 monotonic_clock::time_point(chrono::milliseconds(1323) +
2987 chrono::microseconds(200)));
2988 EXPECT_EQ(oldest_local_monotonic_timestamps,
2989 monotonic_clock::time_point(chrono::microseconds(10100350)));
2990 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2991 monotonic_clock::time_point(chrono::milliseconds(1323) +
2992 chrono::microseconds(200)));
2993 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2994 monotonic_clock::time_point(chrono::microseconds(10100350)));
2995 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2996 monotonic_clock::time_point(chrono::microseconds(1423000)))
2997 << file;
2998 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2999 monotonic_clock::time_point(chrono::microseconds(10200150)))
3000 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07003001 break;
3002 default:
3003 FAIL();
3004 break;
3005 }
3006 }
3007
Austin Schuh315b96b2020-12-11 21:21:12 -08003008 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07003009 {
3010 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08003011
Austin Schuh58646e22021-08-23 23:51:46 -07003012 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3013 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08003014
Austin Schuh58646e22021-08-23 23:51:46 -07003015 // This sends out the fetched messages and advances time to the start of
3016 // the log file.
3017 reader.Register(&log_reader_factory);
3018
3019 log_reader_factory.Run();
3020
3021 reader.Deregister();
3022 }
Austin Schuh315b96b2020-12-11 21:21:12 -08003023}
3024
Austin Schuh5e14d842022-01-21 12:02:15 -08003025// Tests that we can sort a log which only has timestamps from the remote
3026// because the local message_bridge_client failed to connect.
3027TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
3028 const UUID pi1_boot0 = UUID::Random();
3029 const UUID pi2_boot0 = UUID::Random();
3030 const UUID pi2_boot1 = UUID::Random();
3031 {
3032 CHECK_EQ(pi1_index_, 0u);
3033 CHECK_EQ(pi2_index_, 1u);
3034
3035 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
3036 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
3037 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
3038
3039 time_converter_.AddNextTimestamp(
3040 distributed_clock::epoch(),
3041 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3042 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
3043 time_converter_.AddNextTimestamp(
3044 distributed_clock::epoch() + reboot_time,
3045 {BootTimestamp::epoch() + reboot_time,
3046 BootTimestamp{
3047 .boot = 1,
3048 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
3049 }
3050 pi2_->Disconnect(pi1_->node());
3051
3052 std::vector<std::string> filenames;
3053 {
3054 LoggerState pi1_logger = MakeLogger(pi1_);
3055
3056 event_loop_factory_.RunFor(chrono::milliseconds(95));
3057 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3058 pi1_boot0);
3059 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3060 pi2_boot0);
3061
3062 StartLogger(&pi1_logger);
3063
3064 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3065
3066 VLOG(1) << "Reboot now!";
3067
3068 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3069 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3070 pi1_boot0);
3071 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3072 pi2_boot1);
3073 pi1_logger.AppendAllFilenames(&filenames);
3074 }
3075
Austin Schuhbfe6c572022-01-27 20:48:20 -08003076 std::sort(filenames.begin(), filenames.end());
3077
Austin Schuh5e14d842022-01-21 12:02:15 -08003078 // Confirm that our new oldest timestamps properly update as we reboot and
3079 // rotate.
3080 size_t timestamp_file_count = 0;
3081 for (const std::string &file : filenames) {
3082 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
3083 ReadHeader(file);
3084 CHECK(log_header);
3085
3086 if (log_header->message().has_configuration()) {
3087 continue;
3088 }
3089
3090 const monotonic_clock::time_point monotonic_start_time =
3091 monotonic_clock::time_point(
3092 chrono::nanoseconds(log_header->message().monotonic_start_time()));
3093 const UUID source_node_boot_uuid = UUID::FromString(
3094 log_header->message().source_node_boot_uuid()->string_view());
3095
3096 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
3097 ASSERT_EQ(
3098 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
3099 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
3100 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
3101 2u);
3102 ASSERT_TRUE(log_header->message()
3103 .has_oldest_remote_unreliable_monotonic_timestamps());
3104 ASSERT_EQ(log_header->message()
3105 .oldest_remote_unreliable_monotonic_timestamps()
3106 ->size(),
3107 2u);
3108 ASSERT_TRUE(log_header->message()
3109 .has_oldest_local_unreliable_monotonic_timestamps());
3110 ASSERT_EQ(log_header->message()
3111 .oldest_local_unreliable_monotonic_timestamps()
3112 ->size(),
3113 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003114 ASSERT_TRUE(log_header->message()
3115 .has_oldest_remote_reliable_monotonic_timestamps());
3116 ASSERT_EQ(log_header->message()
3117 .oldest_remote_reliable_monotonic_timestamps()
3118 ->size(),
3119 2u);
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003120 ASSERT_TRUE(
3121 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
Austin Schuhf5f99f32022-02-07 20:05:37 -08003122 ASSERT_EQ(log_header->message()
3123 .oldest_local_reliable_monotonic_timestamps()
3124 ->size(),
3125 2u);
3126
3127 ASSERT_TRUE(
3128 log_header->message()
3129 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
3130 ASSERT_EQ(log_header->message()
3131 .oldest_logger_remote_unreliable_monotonic_timestamps()
3132 ->size(),
3133 2u);
3134 ASSERT_TRUE(log_header->message()
3135 .has_oldest_logger_local_unreliable_monotonic_timestamps());
3136 ASSERT_EQ(log_header->message()
3137 .oldest_logger_local_unreliable_monotonic_timestamps()
3138 ->size(),
3139 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08003140
3141 if (log_header->message().node()->name()->string_view() != "pi1") {
3142 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
3143 std::string::npos);
3144
3145 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
3146 ReadNthMessage(file, 0);
3147 CHECK(msg);
3148
3149 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
3150 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
3151
3152 const monotonic_clock::time_point
3153 expected_oldest_local_monotonic_timestamps(
3154 chrono::nanoseconds(msg->message().monotonic_sent_time()));
3155 const monotonic_clock::time_point
3156 expected_oldest_remote_monotonic_timestamps(
3157 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003158 const monotonic_clock::time_point
3159 expected_oldest_timestamp_monotonic_timestamps(
3160 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08003161
3162 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
3163 monotonic_clock::min_time);
3164 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
3165 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003166 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
3167 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08003168
3169 ++timestamp_file_count;
3170 // Since the log file is from the perspective of the other node,
3171 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3172 monotonic_clock::time_point(chrono::nanoseconds(
3173 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3174 0)));
3175 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3176 monotonic_clock::time_point(chrono::nanoseconds(
3177 log_header->message().oldest_local_monotonic_timestamps()->Get(
3178 0)));
3179 const monotonic_clock::time_point
3180 oldest_remote_unreliable_monotonic_timestamps =
3181 monotonic_clock::time_point(chrono::nanoseconds(
3182 log_header->message()
3183 .oldest_remote_unreliable_monotonic_timestamps()
3184 ->Get(0)));
3185 const monotonic_clock::time_point
3186 oldest_local_unreliable_monotonic_timestamps =
3187 monotonic_clock::time_point(chrono::nanoseconds(
3188 log_header->message()
3189 .oldest_local_unreliable_monotonic_timestamps()
3190 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003191 const monotonic_clock::time_point
3192 oldest_remote_reliable_monotonic_timestamps =
3193 monotonic_clock::time_point(chrono::nanoseconds(
3194 log_header->message()
3195 .oldest_remote_reliable_monotonic_timestamps()
3196 ->Get(0)));
3197 const monotonic_clock::time_point
3198 oldest_local_reliable_monotonic_timestamps =
3199 monotonic_clock::time_point(chrono::nanoseconds(
3200 log_header->message()
3201 .oldest_local_reliable_monotonic_timestamps()
3202 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003203 const monotonic_clock::time_point
3204 oldest_logger_remote_unreliable_monotonic_timestamps =
3205 monotonic_clock::time_point(chrono::nanoseconds(
3206 log_header->message()
3207 .oldest_logger_remote_unreliable_monotonic_timestamps()
3208 ->Get(1)));
3209 const monotonic_clock::time_point
3210 oldest_logger_local_unreliable_monotonic_timestamps =
3211 monotonic_clock::time_point(chrono::nanoseconds(
3212 log_header->message()
3213 .oldest_logger_local_unreliable_monotonic_timestamps()
3214 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08003215
Austin Schuh01f3b392022-01-25 20:03:09 -08003216 const Channel *channel =
3217 event_loop_factory_.configuration()->channels()->Get(
3218 msg->message().channel_index());
3219 const Connection *connection = configuration::ConnectionToNode(
3220 channel, configuration::GetNode(
3221 event_loop_factory_.configuration(),
3222 log_header->message().node()->name()->string_view()));
3223
3224 const bool reliable = connection->time_to_live() == 0;
3225
Austin Schuhf5f99f32022-02-07 20:05:37 -08003226 SCOPED_TRACE(file);
3227 SCOPED_TRACE(aos::FlatbufferToJson(
3228 *log_header, {.multi_line = true, .max_vector_size = 100}));
3229
Austin Schuh01f3b392022-01-25 20:03:09 -08003230 if (shared()) {
3231 // Confirm that the oldest timestamps match what we expect. Based on
3232 // what we are doing, we know that the oldest time is the first
3233 // message's time.
3234 //
3235 // This makes the test robust to both the split and combined config
3236 // tests.
3237 switch (log_header->message().parts_index()) {
3238 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08003239 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3240 expected_oldest_remote_monotonic_timestamps);
3241 EXPECT_EQ(oldest_local_monotonic_timestamps,
3242 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003243 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003244 expected_oldest_local_monotonic_timestamps)
3245 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003246 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003247 expected_oldest_timestamp_monotonic_timestamps)
3248 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003249
Austin Schuh01f3b392022-01-25 20:03:09 -08003250 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003251 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3252 expected_oldest_remote_monotonic_timestamps);
3253 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3254 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08003255 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3256 monotonic_clock::max_time);
3257 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3258 monotonic_clock::max_time);
3259 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003260 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3261 monotonic_clock::max_time);
3262 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3263 monotonic_clock::max_time);
3264 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3265 expected_oldest_remote_monotonic_timestamps);
3266 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3267 expected_oldest_local_monotonic_timestamps);
3268 }
3269 break;
3270 case 1:
3271 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3272 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3273 EXPECT_EQ(oldest_local_monotonic_timestamps,
3274 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003275 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3276 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3277 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3278 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003279 if (reliable) {
3280 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3281 expected_oldest_remote_monotonic_timestamps);
3282 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3283 expected_oldest_local_monotonic_timestamps);
3284 EXPECT_EQ(
3285 oldest_remote_unreliable_monotonic_timestamps,
3286 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3287 EXPECT_EQ(
3288 oldest_local_unreliable_monotonic_timestamps,
3289 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3290 } else {
3291 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3292 monotonic_clock::max_time);
3293 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3294 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003295 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3296 expected_oldest_remote_monotonic_timestamps);
3297 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3298 expected_oldest_local_monotonic_timestamps);
3299 }
3300 break;
3301 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003302 EXPECT_EQ(
3303 oldest_remote_monotonic_timestamps,
3304 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3305 EXPECT_EQ(
3306 oldest_local_monotonic_timestamps,
3307 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003308 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003309 expected_oldest_local_monotonic_timestamps)
3310 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003311 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003312 expected_oldest_timestamp_monotonic_timestamps)
3313 << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003314 if (reliable) {
3315 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3316 expected_oldest_remote_monotonic_timestamps);
3317 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3318 expected_oldest_local_monotonic_timestamps);
3319 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3320 monotonic_clock::max_time);
3321 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3322 monotonic_clock::max_time);
3323 } else {
3324 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3325 monotonic_clock::max_time);
3326 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3327 monotonic_clock::max_time);
3328 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3329 expected_oldest_remote_monotonic_timestamps);
3330 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3331 expected_oldest_local_monotonic_timestamps);
3332 }
3333 break;
3334
3335 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003336 EXPECT_EQ(
3337 oldest_remote_monotonic_timestamps,
3338 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3339 EXPECT_EQ(
3340 oldest_local_monotonic_timestamps,
3341 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3342 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3343 expected_oldest_remote_monotonic_timestamps);
3344 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3345 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003346 EXPECT_EQ(
3347 oldest_logger_remote_unreliable_monotonic_timestamps,
3348 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3349 EXPECT_EQ(
3350 oldest_logger_local_unreliable_monotonic_timestamps,
3351 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003352 break;
3353 default:
3354 FAIL();
3355 break;
3356 }
3357
3358 switch (log_header->message().parts_index()) {
3359 case 0:
3360 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3361 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3362 break;
3363 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003364 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003365 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3366 break;
3367 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003368 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3369 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3370 break;
3371 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003372 if (shared()) {
3373 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3374 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003375 break;
3376 }
3377 [[fallthrough]];
3378 default:
3379 FAIL();
3380 break;
3381 }
3382 } else {
3383 switch (log_header->message().parts_index()) {
3384 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003385 if (reliable) {
3386 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3387 monotonic_clock::max_time);
3388 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3389 monotonic_clock::max_time);
3390 EXPECT_EQ(
3391 oldest_logger_remote_unreliable_monotonic_timestamps,
3392 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3393 << file;
3394 EXPECT_EQ(
3395 oldest_logger_local_unreliable_monotonic_timestamps,
3396 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3397 << file;
3398 } else {
3399 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3400 expected_oldest_remote_monotonic_timestamps);
3401 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3402 expected_oldest_local_monotonic_timestamps);
3403 EXPECT_EQ(
3404 oldest_logger_remote_unreliable_monotonic_timestamps,
3405 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3406 << file;
3407 EXPECT_EQ(
3408 oldest_logger_local_unreliable_monotonic_timestamps,
3409 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3410 << file;
3411 }
3412 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003413 case 1:
3414 if (reliable) {
3415 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3416 monotonic_clock::max_time);
3417 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3418 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003419 EXPECT_EQ(
3420 oldest_logger_remote_unreliable_monotonic_timestamps,
3421 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3422 EXPECT_EQ(
3423 oldest_logger_local_unreliable_monotonic_timestamps,
3424 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003425 } else {
3426 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3427 expected_oldest_remote_monotonic_timestamps);
3428 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3429 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003430 EXPECT_EQ(
3431 oldest_logger_remote_unreliable_monotonic_timestamps,
3432 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3433 EXPECT_EQ(
3434 oldest_logger_local_unreliable_monotonic_timestamps,
3435 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003436 }
3437 break;
3438 default:
3439 FAIL();
3440 break;
3441 }
3442
3443 switch (log_header->message().parts_index()) {
3444 case 0:
3445 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3446 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3447 break;
3448 case 1:
3449 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3450 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3451 break;
3452 default:
3453 FAIL();
3454 break;
3455 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003456 }
3457
3458 continue;
3459 }
3460 EXPECT_EQ(
3461 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3462 monotonic_clock::max_time.time_since_epoch().count());
3463 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3464 monotonic_clock::max_time.time_since_epoch().count());
3465 EXPECT_EQ(log_header->message()
3466 .oldest_remote_unreliable_monotonic_timestamps()
3467 ->Get(0),
3468 monotonic_clock::max_time.time_since_epoch().count());
3469 EXPECT_EQ(log_header->message()
3470 .oldest_local_unreliable_monotonic_timestamps()
3471 ->Get(0),
3472 monotonic_clock::max_time.time_since_epoch().count());
3473
3474 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3475 monotonic_clock::time_point(chrono::nanoseconds(
3476 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3477 1)));
3478 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3479 monotonic_clock::time_point(chrono::nanoseconds(
3480 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3481 const monotonic_clock::time_point
3482 oldest_remote_unreliable_monotonic_timestamps =
3483 monotonic_clock::time_point(chrono::nanoseconds(
3484 log_header->message()
3485 .oldest_remote_unreliable_monotonic_timestamps()
3486 ->Get(1)));
3487 const monotonic_clock::time_point
3488 oldest_local_unreliable_monotonic_timestamps =
3489 monotonic_clock::time_point(chrono::nanoseconds(
3490 log_header->message()
3491 .oldest_local_unreliable_monotonic_timestamps()
3492 ->Get(1)));
3493 switch (log_header->message().parts_index()) {
3494 case 0:
3495 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3496 monotonic_clock::max_time);
3497 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3498 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3499 monotonic_clock::max_time);
3500 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3501 monotonic_clock::max_time);
3502 break;
3503 default:
3504 FAIL();
3505 break;
3506 }
3507 }
3508
Austin Schuh01f3b392022-01-25 20:03:09 -08003509 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003510 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003511 } else {
3512 EXPECT_EQ(timestamp_file_count, 4u);
3513 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003514
Austin Schuhe2373e22022-01-21 12:25:17 -08003515 // Confirm that we can actually sort the resulting log and read it.
3516 {
3517 LogReader reader(SortParts(filenames));
3518
3519 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3520 log_reader_factory.set_send_delay(chrono::microseconds(0));
3521
3522 // This sends out the fetched messages and advances time to the start of
3523 // the log file.
3524 reader.Register(&log_reader_factory);
3525
3526 log_reader_factory.Run();
3527
3528 reader.Deregister();
3529 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003530}
3531
Austin Schuhc9049732020-12-21 22:27:15 -08003532// Tests that we properly handle one direction of message_bridge being
3533// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003534TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003535 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003536 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003537 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003538
3539 time_converter_.AddMonotonic(
3540 {chrono::milliseconds(10000),
3541 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003542 {
3543 LoggerState pi1_logger = MakeLogger(pi1_);
3544
3545 event_loop_factory_.RunFor(chrono::milliseconds(95));
3546
3547 StartLogger(&pi1_logger);
3548
3549 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3550 }
3551
3552 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3553 // to confirm the right thing happened.
3554 ConfirmReadable(pi1_single_direction_logfiles_);
3555}
3556
3557// Tests that we properly handle one direction of message_bridge being
3558// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003559TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003560 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003561 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003562 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003563
3564 time_converter_.AddMonotonic(
3565 {chrono::milliseconds(10000),
3566 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3567 {
3568 LoggerState pi1_logger = MakeLogger(pi1_);
3569
3570 event_loop_factory_.RunFor(chrono::milliseconds(95));
3571
3572 StartLogger(&pi1_logger);
3573
3574 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3575 }
3576
3577 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3578 // to confirm the right thing happened.
3579 ConfirmReadable(pi1_single_direction_logfiles_);
3580}
3581
Austin Schuhe9f00232021-09-16 18:04:23 -07003582// Tests that we explode if someone passes in a part file twice with a better
3583// error than an out of order error.
3584TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3585 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003586 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003587 {
3588 LoggerState pi1_logger = MakeLogger(pi1_);
3589
3590 event_loop_factory_.RunFor(chrono::milliseconds(95));
3591
3592 StartLogger(&pi1_logger);
3593
3594 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3595 }
3596
3597 std::vector<std::string> duplicates;
3598 for (const std::string &f : pi1_single_direction_logfiles_) {
3599 duplicates.emplace_back(f);
3600 duplicates.emplace_back(f);
3601 }
3602 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3603}
3604
Austin Schuh87dd3832021-01-01 23:07:31 -08003605// Tests that we properly handle a dead node. Do this by just disconnecting it
3606// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003607TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003608 pi1_->Disconnect(pi2_->node());
3609 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003610 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003611 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003612 {
3613 LoggerState pi1_logger = MakeLogger(pi1_);
3614
3615 event_loop_factory_.RunFor(chrono::milliseconds(95));
3616
3617 StartLogger(&pi1_logger);
3618
3619 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3620 }
3621
3622 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3623 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003624 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003625}
3626
Austin Schuhcdd90272021-03-15 12:46:16 -07003627constexpr std::string_view kCombinedConfigSha1(
Brian Silvermandae15a12022-07-23 12:55:20 -07003628 "bcc66bc13a90a4a268649744e244129c5d024f5abd67587dcfbd7158d8abfc44");
Austin Schuhcdd90272021-03-15 12:46:16 -07003629constexpr std::string_view kSplitConfigSha1(
Brian Silvermandae15a12022-07-23 12:55:20 -07003630 "d97e998164a6f1bf078aad77ef127329728ac9198a13a5ab8d5f30d84a932662");
Austin Schuhcdd90272021-03-15 12:46:16 -07003631
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003632INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003633 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003634 ::testing::Combine(::testing::Values(
3635 ConfigParams{
3636 "multinode_pingpong_combined_config.json", true,
3637 kCombinedConfigSha1},
3638 ConfigParams{"multinode_pingpong_split_config.json",
3639 false, kSplitConfigSha1}),
3640 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003641
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003642INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003643 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003644 ::testing::Combine(::testing::Values(
3645 ConfigParams{
3646 "multinode_pingpong_combined_config.json", true,
3647 kCombinedConfigSha1},
3648 ConfigParams{"multinode_pingpong_split_config.json",
3649 false, kSplitConfigSha1}),
3650 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003651
Austin Schuh5b728b72021-06-16 14:57:15 -07003652// Tests that we can relog with a different config. This makes most sense when
3653// you are trying to edit a log and want to use channel renaming + the original
3654// config in the new log.
3655TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3656 time_converter_.StartEqual();
3657 {
3658 LoggerState pi1_logger = MakeLogger(pi1_);
3659 LoggerState pi2_logger = MakeLogger(pi2_);
3660
3661 event_loop_factory_.RunFor(chrono::milliseconds(95));
3662
3663 StartLogger(&pi1_logger);
3664 StartLogger(&pi2_logger);
3665
3666 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3667 }
3668
3669 LogReader reader(SortParts(logfiles_));
3670 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3671
3672 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3673 log_reader_factory.set_send_delay(chrono::microseconds(0));
3674
3675 // This sends out the fetched messages and advances time to the start of the
3676 // log file.
3677 reader.Register(&log_reader_factory);
3678
3679 const Node *pi1 =
3680 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3681 const Node *pi2 =
3682 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3683
3684 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3685 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3686 LOG(INFO) << "now pi1 "
3687 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3688 LOG(INFO) << "now pi2 "
3689 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3690
3691 EXPECT_THAT(reader.LoggedNodes(),
3692 ::testing::ElementsAre(
3693 configuration::GetNode(reader.logged_configuration(), pi1),
3694 configuration::GetNode(reader.logged_configuration(), pi2)));
3695
3696 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3697
3698 // And confirm we can re-create a log again, while checking the contents.
3699 std::vector<std::string> log_files;
3700 {
3701 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003702 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003703 &log_reader_factory, reader.logged_configuration());
3704 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003705 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003706 &log_reader_factory, reader.logged_configuration());
3707
Austin Schuh3e20c692021-11-16 20:43:16 -08003708 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3709 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003710
3711 log_reader_factory.Run();
3712
3713 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3714 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3715 }
3716 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3717 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3718 }
3719 }
3720
3721 reader.Deregister();
3722
3723 // And verify that we can run the LogReader over the relogged files without
3724 // hitting any fatal errors.
3725 {
3726 LogReader relogged_reader(SortParts(log_files));
3727 relogged_reader.Register();
3728
3729 relogged_reader.event_loop_factory()->Run();
3730 }
3731}
Austin Schuha04efed2021-01-24 18:04:20 -08003732
Austin Schuh3e20c692021-11-16 20:43:16 -08003733// Tests that we properly replay a log where the start time for a node is before
3734// any data on the node. This can happen if the logger starts before data is
3735// published. While the scenario below is a bit convoluted, we have seen logs
3736// like this generated out in the wild.
3737TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3738 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3739 aos::configuration::ReadConfig(ArtifactPath(
3740 "aos/events/logging/multinode_pingpong_split3_config.json"));
3741 message_bridge::TestingTimeConverter time_converter(
3742 configuration::NodesCount(&config.message()));
3743 SimulatedEventLoopFactory event_loop_factory(&config.message());
3744 event_loop_factory.SetTimeConverter(&time_converter);
3745 NodeEventLoopFactory *const pi1 =
3746 event_loop_factory.GetNodeEventLoopFactory("pi1");
3747 const size_t pi1_index = configuration::GetNodeIndex(
3748 event_loop_factory.configuration(), pi1->node());
3749 NodeEventLoopFactory *const pi2 =
3750 event_loop_factory.GetNodeEventLoopFactory("pi2");
3751 const size_t pi2_index = configuration::GetNodeIndex(
3752 event_loop_factory.configuration(), pi2->node());
3753 NodeEventLoopFactory *const pi3 =
3754 event_loop_factory.GetNodeEventLoopFactory("pi3");
3755 const size_t pi3_index = configuration::GetNodeIndex(
3756 event_loop_factory.configuration(), pi3->node());
3757
3758 const std::string kLogfile1_1 =
3759 aos::testing::TestTmpDir() + "/multi_logfile1/";
3760 const std::string kLogfile2_1 =
3761 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3762 const std::string kLogfile2_2 =
3763 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3764 const std::string kLogfile3_1 =
3765 aos::testing::TestTmpDir() + "/multi_logfile3/";
3766 util::UnlinkRecursive(kLogfile1_1);
3767 util::UnlinkRecursive(kLogfile2_1);
3768 util::UnlinkRecursive(kLogfile2_2);
3769 util::UnlinkRecursive(kLogfile3_1);
3770 const UUID pi1_boot0 = UUID::Random();
3771 const UUID pi2_boot0 = UUID::Random();
3772 const UUID pi2_boot1 = UUID::Random();
3773 const UUID pi3_boot0 = UUID::Random();
3774 {
3775 CHECK_EQ(pi1_index, 0u);
3776 CHECK_EQ(pi2_index, 1u);
3777 CHECK_EQ(pi3_index, 2u);
3778
3779 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3780 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3781 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3782 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3783
3784 time_converter.AddNextTimestamp(
3785 distributed_clock::epoch(),
3786 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3787 BootTimestamp::epoch()});
3788 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3789 time_converter.AddNextTimestamp(
3790 distributed_clock::epoch() + reboot_time,
3791 {BootTimestamp::epoch() + reboot_time,
3792 BootTimestamp{
3793 .boot = 1,
3794 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3795 BootTimestamp::epoch() + reboot_time});
3796 }
3797
3798 // Make everything perfectly quiet.
3799 event_loop_factory.SkipTimingReport();
3800 event_loop_factory.DisableStatistics();
3801
3802 std::vector<std::string> filenames;
3803 {
3804 LoggerState pi1_logger = LoggerState::MakeLogger(
3805 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3806 LoggerState pi3_logger = LoggerState::MakeLogger(
3807 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3808 {
3809 // And now start the logger.
3810 LoggerState pi2_logger = LoggerState::MakeLogger(
3811 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3812
3813 event_loop_factory.RunFor(chrono::milliseconds(1000));
3814
3815 pi1_logger.StartLogger(kLogfile1_1);
3816 pi3_logger.StartLogger(kLogfile3_1);
3817 pi2_logger.StartLogger(kLogfile2_1);
3818
3819 event_loop_factory.RunFor(chrono::milliseconds(10000));
3820
3821 // Now that we've got a start time in the past, turn on data.
3822 event_loop_factory.EnableStatistics();
3823 std::unique_ptr<aos::EventLoop> ping_event_loop =
3824 pi1->MakeEventLoop("ping");
3825 Ping ping(ping_event_loop.get());
3826
3827 pi2->AlwaysStart<Pong>("pong");
3828
3829 event_loop_factory.RunFor(chrono::milliseconds(3000));
3830
3831 pi2_logger.AppendAllFilenames(&filenames);
3832
3833 // Stop logging on pi2 before rebooting and completely shut off all
3834 // messages on pi2.
3835 pi2->DisableStatistics();
3836 pi1->Disconnect(pi2->node());
3837 pi2->Disconnect(pi1->node());
3838 }
3839 event_loop_factory.RunFor(chrono::milliseconds(7000));
3840 // pi2 now reboots.
3841 {
3842 event_loop_factory.RunFor(chrono::milliseconds(1000));
3843
3844 // Start logging again on pi2 after it is up.
3845 LoggerState pi2_logger = LoggerState::MakeLogger(
3846 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3847 pi2_logger.StartLogger(kLogfile2_2);
3848
3849 event_loop_factory.RunFor(chrono::milliseconds(10000));
3850 // And, now that we have a start time in the log, turn data back on.
3851 pi2->EnableStatistics();
3852 pi1->Connect(pi2->node());
3853 pi2->Connect(pi1->node());
3854
3855 pi2->AlwaysStart<Pong>("pong");
3856 std::unique_ptr<aos::EventLoop> ping_event_loop =
3857 pi1->MakeEventLoop("ping");
3858 Ping ping(ping_event_loop.get());
3859
3860 event_loop_factory.RunFor(chrono::milliseconds(3000));
3861
3862 pi2_logger.AppendAllFilenames(&filenames);
3863 }
3864
3865 pi1_logger.AppendAllFilenames(&filenames);
3866 pi3_logger.AppendAllFilenames(&filenames);
3867 }
3868
3869 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3870 // to confirm the right thing happened.
3871 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003872 auto result = ConfirmReadable(filenames);
3873 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3874 chrono::seconds(1)));
3875 EXPECT_THAT(result[0].second,
3876 ::testing::ElementsAre(realtime_clock::epoch() +
3877 chrono::microseconds(34990350)));
3878
3879 EXPECT_THAT(result[1].first,
3880 ::testing::ElementsAre(
3881 realtime_clock::epoch() + chrono::seconds(1),
3882 realtime_clock::epoch() + chrono::microseconds(3323000)));
3883 EXPECT_THAT(result[1].second,
3884 ::testing::ElementsAre(
3885 realtime_clock::epoch() + chrono::microseconds(13990200),
3886 realtime_clock::epoch() + chrono::microseconds(16313200)));
3887
3888 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3889 chrono::seconds(1)));
3890 EXPECT_THAT(result[2].second,
3891 ::testing::ElementsAre(realtime_clock::epoch() +
3892 chrono::microseconds(34900150)));
Austin Schuh3e20c692021-11-16 20:43:16 -08003893}
3894
Austin Schuh5dd22842021-11-17 16:09:39 -08003895// Tests that local data before remote data after reboot is properly replayed.
3896// We only trigger a reboot in the timestamp interpolation function when solving
3897// the timestamp problem when we actually have a point in the function. This
3898// originally only happened when a point passes the noncausal filter. At the
3899// start of time for the second boot, if we aren't careful, we will have
3900// messages which need to be published at times before the boot. This happens
3901// when a local message is in the log before a forwarded message, so there is no
3902// point in the interpolation function. This delays the reboot. So, we need to
3903// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08003904TEST(MultinodeRebootLoggerTest,
3905 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08003906 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3907 aos::configuration::ReadConfig(ArtifactPath(
3908 "aos/events/logging/multinode_pingpong_split3_config.json"));
3909 message_bridge::TestingTimeConverter time_converter(
3910 configuration::NodesCount(&config.message()));
3911 SimulatedEventLoopFactory event_loop_factory(&config.message());
3912 event_loop_factory.SetTimeConverter(&time_converter);
3913 NodeEventLoopFactory *const pi1 =
3914 event_loop_factory.GetNodeEventLoopFactory("pi1");
3915 const size_t pi1_index = configuration::GetNodeIndex(
3916 event_loop_factory.configuration(), pi1->node());
3917 NodeEventLoopFactory *const pi2 =
3918 event_loop_factory.GetNodeEventLoopFactory("pi2");
3919 const size_t pi2_index = configuration::GetNodeIndex(
3920 event_loop_factory.configuration(), pi2->node());
3921 NodeEventLoopFactory *const pi3 =
3922 event_loop_factory.GetNodeEventLoopFactory("pi3");
3923 const size_t pi3_index = configuration::GetNodeIndex(
3924 event_loop_factory.configuration(), pi3->node());
3925
3926 const std::string kLogfile1_1 =
3927 aos::testing::TestTmpDir() + "/multi_logfile1/";
3928 const std::string kLogfile2_1 =
3929 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3930 const std::string kLogfile2_2 =
3931 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3932 const std::string kLogfile3_1 =
3933 aos::testing::TestTmpDir() + "/multi_logfile3/";
3934 util::UnlinkRecursive(kLogfile1_1);
3935 util::UnlinkRecursive(kLogfile2_1);
3936 util::UnlinkRecursive(kLogfile2_2);
3937 util::UnlinkRecursive(kLogfile3_1);
3938 const UUID pi1_boot0 = UUID::Random();
3939 const UUID pi2_boot0 = UUID::Random();
3940 const UUID pi2_boot1 = UUID::Random();
3941 const UUID pi3_boot0 = UUID::Random();
3942 {
3943 CHECK_EQ(pi1_index, 0u);
3944 CHECK_EQ(pi2_index, 1u);
3945 CHECK_EQ(pi3_index, 2u);
3946
3947 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3948 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3949 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3950 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3951
3952 time_converter.AddNextTimestamp(
3953 distributed_clock::epoch(),
3954 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3955 BootTimestamp::epoch()});
3956 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3957 time_converter.AddNextTimestamp(
3958 distributed_clock::epoch() + reboot_time,
3959 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003960 BootTimestamp{.boot = 1,
3961 .time = monotonic_clock::epoch() + reboot_time +
3962 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08003963 BootTimestamp::epoch() + reboot_time});
3964 }
3965
3966 std::vector<std::string> filenames;
3967 {
3968 LoggerState pi1_logger = LoggerState::MakeLogger(
3969 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3970 LoggerState pi3_logger = LoggerState::MakeLogger(
3971 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3972 {
3973 // And now start the logger.
3974 LoggerState pi2_logger = LoggerState::MakeLogger(
3975 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3976
3977 pi1_logger.StartLogger(kLogfile1_1);
3978 pi3_logger.StartLogger(kLogfile3_1);
3979 pi2_logger.StartLogger(kLogfile2_1);
3980
3981 event_loop_factory.RunFor(chrono::milliseconds(1005));
3982
3983 // Now that we've got a start time in the past, turn on data.
3984 std::unique_ptr<aos::EventLoop> ping_event_loop =
3985 pi1->MakeEventLoop("ping");
3986 Ping ping(ping_event_loop.get());
3987
3988 pi2->AlwaysStart<Pong>("pong");
3989
3990 event_loop_factory.RunFor(chrono::milliseconds(3000));
3991
3992 pi2_logger.AppendAllFilenames(&filenames);
3993
3994 // Disable any remote messages on pi2.
3995 pi1->Disconnect(pi2->node());
3996 pi2->Disconnect(pi1->node());
3997 }
3998 event_loop_factory.RunFor(chrono::milliseconds(995));
3999 // pi2 now reboots at 5 seconds.
4000 {
4001 event_loop_factory.RunFor(chrono::milliseconds(1000));
4002
4003 // Make local stuff happen before we start logging and connect the remote.
4004 pi2->AlwaysStart<Pong>("pong");
4005 std::unique_ptr<aos::EventLoop> ping_event_loop =
4006 pi1->MakeEventLoop("ping");
4007 Ping ping(ping_event_loop.get());
4008 event_loop_factory.RunFor(chrono::milliseconds(1005));
4009
4010 // Start logging again on pi2 after it is up.
4011 LoggerState pi2_logger = LoggerState::MakeLogger(
4012 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4013 pi2_logger.StartLogger(kLogfile2_2);
4014
4015 // And allow remote messages now that we have some local ones.
4016 pi1->Connect(pi2->node());
4017 pi2->Connect(pi1->node());
4018
4019 event_loop_factory.RunFor(chrono::milliseconds(1000));
4020
4021 event_loop_factory.RunFor(chrono::milliseconds(3000));
4022
4023 pi2_logger.AppendAllFilenames(&filenames);
4024 }
4025
4026 pi1_logger.AppendAllFilenames(&filenames);
4027 pi3_logger.AppendAllFilenames(&filenames);
4028 }
4029
4030 // Confirm that we can parse the result. LogReader has enough internal CHECKs
4031 // to confirm the right thing happened.
4032 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08004033 auto result = ConfirmReadable(filenames);
4034
4035 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4036 EXPECT_THAT(result[0].second,
4037 ::testing::ElementsAre(realtime_clock::epoch() +
4038 chrono::microseconds(11000350)));
4039
4040 EXPECT_THAT(result[1].first,
4041 ::testing::ElementsAre(
4042 realtime_clock::epoch(),
4043 realtime_clock::epoch() + chrono::microseconds(107005000)));
4044 EXPECT_THAT(result[1].second,
4045 ::testing::ElementsAre(
4046 realtime_clock::epoch() + chrono::microseconds(4000150),
4047 realtime_clock::epoch() + chrono::microseconds(111000200)));
4048
4049 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4050 EXPECT_THAT(result[2].second,
4051 ::testing::ElementsAre(realtime_clock::epoch() +
4052 chrono::microseconds(11000150)));
4053
4054 auto start_stop_result = ConfirmReadable(
4055 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4056 realtime_clock::epoch() + chrono::milliseconds(3000));
4057
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004058 EXPECT_THAT(
4059 start_stop_result[0].first,
4060 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4061 EXPECT_THAT(
4062 start_stop_result[0].second,
4063 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4064 EXPECT_THAT(
4065 start_stop_result[1].first,
4066 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4067 EXPECT_THAT(
4068 start_stop_result[1].second,
4069 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4070 EXPECT_THAT(
4071 start_stop_result[2].first,
4072 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4073 EXPECT_THAT(
4074 start_stop_result[2].second,
4075 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
Austin Schuh5dd22842021-11-17 16:09:39 -08004076}
4077
Austin Schuhe33c08d2022-02-03 18:15:21 -08004078// Tests that setting the start and stop flags across a reboot works as
4079// expected.
4080TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
4081 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4082 aos::configuration::ReadConfig(ArtifactPath(
4083 "aos/events/logging/multinode_pingpong_split3_config.json"));
4084 message_bridge::TestingTimeConverter time_converter(
4085 configuration::NodesCount(&config.message()));
4086 SimulatedEventLoopFactory event_loop_factory(&config.message());
4087 event_loop_factory.SetTimeConverter(&time_converter);
4088 NodeEventLoopFactory *const pi1 =
4089 event_loop_factory.GetNodeEventLoopFactory("pi1");
4090 const size_t pi1_index = configuration::GetNodeIndex(
4091 event_loop_factory.configuration(), pi1->node());
4092 NodeEventLoopFactory *const pi2 =
4093 event_loop_factory.GetNodeEventLoopFactory("pi2");
4094 const size_t pi2_index = configuration::GetNodeIndex(
4095 event_loop_factory.configuration(), pi2->node());
4096 NodeEventLoopFactory *const pi3 =
4097 event_loop_factory.GetNodeEventLoopFactory("pi3");
4098 const size_t pi3_index = configuration::GetNodeIndex(
4099 event_loop_factory.configuration(), pi3->node());
4100
4101 const std::string kLogfile1_1 =
4102 aos::testing::TestTmpDir() + "/multi_logfile1/";
4103 const std::string kLogfile2_1 =
4104 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4105 const std::string kLogfile2_2 =
4106 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4107 const std::string kLogfile3_1 =
4108 aos::testing::TestTmpDir() + "/multi_logfile3/";
4109 util::UnlinkRecursive(kLogfile1_1);
4110 util::UnlinkRecursive(kLogfile2_1);
4111 util::UnlinkRecursive(kLogfile2_2);
4112 util::UnlinkRecursive(kLogfile3_1);
4113 {
4114 CHECK_EQ(pi1_index, 0u);
4115 CHECK_EQ(pi2_index, 1u);
4116 CHECK_EQ(pi3_index, 2u);
4117
4118 time_converter.AddNextTimestamp(
4119 distributed_clock::epoch(),
4120 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4121 BootTimestamp::epoch()});
4122 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4123 time_converter.AddNextTimestamp(
4124 distributed_clock::epoch() + reboot_time,
4125 {BootTimestamp::epoch() + reboot_time,
4126 BootTimestamp{.boot = 1,
4127 .time = monotonic_clock::epoch() + reboot_time},
4128 BootTimestamp::epoch() + reboot_time});
4129 }
4130
4131 std::vector<std::string> filenames;
4132 {
4133 LoggerState pi1_logger = LoggerState::MakeLogger(
4134 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4135 LoggerState pi3_logger = LoggerState::MakeLogger(
4136 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4137 {
4138 // And now start the logger.
4139 LoggerState pi2_logger = LoggerState::MakeLogger(
4140 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4141
4142 pi1_logger.StartLogger(kLogfile1_1);
4143 pi3_logger.StartLogger(kLogfile3_1);
4144 pi2_logger.StartLogger(kLogfile2_1);
4145
4146 event_loop_factory.RunFor(chrono::milliseconds(1005));
4147
4148 // Now that we've got a start time in the past, turn on data.
4149 std::unique_ptr<aos::EventLoop> ping_event_loop =
4150 pi1->MakeEventLoop("ping");
4151 Ping ping(ping_event_loop.get());
4152
4153 pi2->AlwaysStart<Pong>("pong");
4154
4155 event_loop_factory.RunFor(chrono::milliseconds(3000));
4156
4157 pi2_logger.AppendAllFilenames(&filenames);
4158 }
4159 event_loop_factory.RunFor(chrono::milliseconds(995));
4160 // pi2 now reboots at 5 seconds.
4161 {
4162 event_loop_factory.RunFor(chrono::milliseconds(1000));
4163
4164 // Make local stuff happen before we start logging and connect the remote.
4165 pi2->AlwaysStart<Pong>("pong");
4166 std::unique_ptr<aos::EventLoop> ping_event_loop =
4167 pi1->MakeEventLoop("ping");
4168 Ping ping(ping_event_loop.get());
4169 event_loop_factory.RunFor(chrono::milliseconds(5));
4170
4171 // Start logging again on pi2 after it is up.
4172 LoggerState pi2_logger = LoggerState::MakeLogger(
4173 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4174 pi2_logger.StartLogger(kLogfile2_2);
4175
4176 event_loop_factory.RunFor(chrono::milliseconds(5000));
4177
4178 pi2_logger.AppendAllFilenames(&filenames);
4179 }
4180
4181 pi1_logger.AppendAllFilenames(&filenames);
4182 pi3_logger.AppendAllFilenames(&filenames);
4183 }
4184
4185 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4186 auto result = ConfirmReadable(filenames);
4187
4188 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4189 EXPECT_THAT(result[0].second,
4190 ::testing::ElementsAre(realtime_clock::epoch() +
4191 chrono::microseconds(11000350)));
4192
4193 EXPECT_THAT(result[1].first,
4194 ::testing::ElementsAre(
4195 realtime_clock::epoch(),
4196 realtime_clock::epoch() + chrono::microseconds(6005000)));
4197 EXPECT_THAT(result[1].second,
4198 ::testing::ElementsAre(
4199 realtime_clock::epoch() + chrono::microseconds(4900150),
4200 realtime_clock::epoch() + chrono::microseconds(11000200)));
4201
4202 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4203 EXPECT_THAT(result[2].second,
4204 ::testing::ElementsAre(realtime_clock::epoch() +
4205 chrono::microseconds(11000150)));
4206
4207 // Confirm we observed the correct start and stop times. We should see the
4208 // reboot here.
4209 auto start_stop_result = ConfirmReadable(
4210 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4211 realtime_clock::epoch() + chrono::milliseconds(8000));
4212
4213 EXPECT_THAT(
4214 start_stop_result[0].first,
4215 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4216 EXPECT_THAT(
4217 start_stop_result[0].second,
4218 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4219 EXPECT_THAT(start_stop_result[1].first,
4220 ::testing::ElementsAre(
4221 realtime_clock::epoch() + chrono::seconds(2),
4222 realtime_clock::epoch() + chrono::microseconds(6005000)));
4223 EXPECT_THAT(start_stop_result[1].second,
4224 ::testing::ElementsAre(
4225 realtime_clock::epoch() + chrono::microseconds(4900150),
4226 realtime_clock::epoch() + chrono::seconds(8)));
4227 EXPECT_THAT(
4228 start_stop_result[2].first,
4229 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4230 EXPECT_THAT(
4231 start_stop_result[2].second,
4232 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4233}
Austin Schuh5dd22842021-11-17 16:09:39 -08004234
Austin Schuh5c770fa2022-03-11 06:57:22 -08004235// Tests that we properly handle one direction being down.
4236TEST(MissingDirectionTest, OneDirection) {
4237 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4238 aos::configuration::ReadConfig(ArtifactPath(
4239 "aos/events/logging/multinode_pingpong_split4_config.json"));
4240 message_bridge::TestingTimeConverter time_converter(
4241 configuration::NodesCount(&config.message()));
4242 SimulatedEventLoopFactory event_loop_factory(&config.message());
4243 event_loop_factory.SetTimeConverter(&time_converter);
4244
4245 NodeEventLoopFactory *const pi1 =
4246 event_loop_factory.GetNodeEventLoopFactory("pi1");
4247 const size_t pi1_index = configuration::GetNodeIndex(
4248 event_loop_factory.configuration(), pi1->node());
4249 NodeEventLoopFactory *const pi2 =
4250 event_loop_factory.GetNodeEventLoopFactory("pi2");
4251 const size_t pi2_index = configuration::GetNodeIndex(
4252 event_loop_factory.configuration(), pi2->node());
4253 std::vector<std::string> filenames;
4254
4255 {
4256 CHECK_EQ(pi1_index, 0u);
4257 CHECK_EQ(pi2_index, 1u);
4258
4259 time_converter.AddNextTimestamp(
4260 distributed_clock::epoch(),
4261 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4262
4263 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4264 time_converter.AddNextTimestamp(
4265 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004266 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuh5c770fa2022-03-11 06:57:22 -08004267 BootTimestamp::epoch() + reboot_time});
4268 }
4269
4270 const std::string kLogfile2_1 =
4271 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4272 const std::string kLogfile1_1 =
4273 aos::testing::TestTmpDir() + "/multi_logfile1.1/";
4274 util::UnlinkRecursive(kLogfile2_1);
4275 util::UnlinkRecursive(kLogfile1_1);
4276
4277 pi2->Disconnect(pi1->node());
4278
4279 pi1->AlwaysStart<Ping>("ping");
4280 pi2->AlwaysStart<Pong>("pong");
4281
4282 {
4283 LoggerState pi2_logger = LoggerState::MakeLogger(
4284 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4285
4286 event_loop_factory.RunFor(chrono::milliseconds(95));
4287
4288 pi2_logger.StartLogger(kLogfile2_1);
4289
4290 event_loop_factory.RunFor(chrono::milliseconds(6000));
4291
4292 pi2->Connect(pi1->node());
4293
4294 LoggerState pi1_logger = LoggerState::MakeLogger(
4295 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4296 pi1_logger.StartLogger(kLogfile1_1);
4297
4298 event_loop_factory.RunFor(chrono::milliseconds(5000));
4299 pi1_logger.AppendAllFilenames(&filenames);
4300 pi2_logger.AppendAllFilenames(&filenames);
4301 }
4302
4303 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4304 ConfirmReadable(filenames);
4305}
4306
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004307// Tests that we properly handle only one direction ever existing after a
4308// reboot.
4309TEST(MissingDirectionTest, OneDirectionAfterReboot) {
4310 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4311 aos::configuration::ReadConfig(ArtifactPath(
4312 "aos/events/logging/multinode_pingpong_split4_config.json"));
4313 message_bridge::TestingTimeConverter time_converter(
4314 configuration::NodesCount(&config.message()));
4315 SimulatedEventLoopFactory event_loop_factory(&config.message());
4316 event_loop_factory.SetTimeConverter(&time_converter);
4317
4318 NodeEventLoopFactory *const pi1 =
4319 event_loop_factory.GetNodeEventLoopFactory("pi1");
4320 const size_t pi1_index = configuration::GetNodeIndex(
4321 event_loop_factory.configuration(), pi1->node());
4322 NodeEventLoopFactory *const pi2 =
4323 event_loop_factory.GetNodeEventLoopFactory("pi2");
4324 const size_t pi2_index = configuration::GetNodeIndex(
4325 event_loop_factory.configuration(), pi2->node());
4326 std::vector<std::string> filenames;
4327
4328 {
4329 CHECK_EQ(pi1_index, 0u);
4330 CHECK_EQ(pi2_index, 1u);
4331
4332 time_converter.AddNextTimestamp(
4333 distributed_clock::epoch(),
4334 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4335
4336 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4337 time_converter.AddNextTimestamp(
4338 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004339 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004340 BootTimestamp::epoch() + reboot_time});
4341 }
4342
4343 const std::string kLogfile2_1 =
4344 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4345 util::UnlinkRecursive(kLogfile2_1);
4346
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004347 pi1->AlwaysStart<Ping>("ping");
4348
4349 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4350 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4351 // second boot.
4352 {
4353 LoggerState pi2_logger = LoggerState::MakeLogger(
4354 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4355
4356 event_loop_factory.RunFor(chrono::milliseconds(95));
4357
4358 pi2_logger.StartLogger(kLogfile2_1);
4359
4360 event_loop_factory.RunFor(chrono::milliseconds(4000));
4361
4362 pi2->Disconnect(pi1->node());
4363
4364 event_loop_factory.RunFor(chrono::milliseconds(1000));
4365 pi1->AlwaysStart<Ping>("ping");
4366
4367 event_loop_factory.RunFor(chrono::milliseconds(5000));
4368 pi2_logger.AppendAllFilenames(&filenames);
4369 }
4370
4371 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4372 ConfirmReadable(filenames);
4373}
4374
4375// Tests that we properly handle only one direction ever existing after a reboot
4376// with only reliable data.
4377TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
4378 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4379 aos::configuration::ReadConfig(ArtifactPath(
4380 "aos/events/logging/multinode_pingpong_split4_reliable_config.json"));
4381 message_bridge::TestingTimeConverter time_converter(
4382 configuration::NodesCount(&config.message()));
4383 SimulatedEventLoopFactory event_loop_factory(&config.message());
4384 event_loop_factory.SetTimeConverter(&time_converter);
4385
4386 NodeEventLoopFactory *const pi1 =
4387 event_loop_factory.GetNodeEventLoopFactory("pi1");
4388 const size_t pi1_index = configuration::GetNodeIndex(
4389 event_loop_factory.configuration(), pi1->node());
4390 NodeEventLoopFactory *const pi2 =
4391 event_loop_factory.GetNodeEventLoopFactory("pi2");
4392 const size_t pi2_index = configuration::GetNodeIndex(
4393 event_loop_factory.configuration(), pi2->node());
4394 std::vector<std::string> filenames;
4395
4396 {
4397 CHECK_EQ(pi1_index, 0u);
4398 CHECK_EQ(pi2_index, 1u);
4399
4400 time_converter.AddNextTimestamp(
4401 distributed_clock::epoch(),
4402 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4403
4404 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4405 time_converter.AddNextTimestamp(
4406 distributed_clock::epoch() + reboot_time,
4407 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4408 BootTimestamp::epoch() + reboot_time});
4409 }
4410
4411 const std::string kLogfile2_1 =
4412 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4413 util::UnlinkRecursive(kLogfile2_1);
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004414
4415 pi1->AlwaysStart<Ping>("ping");
4416
4417 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4418 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4419 // second boot.
4420 {
4421 LoggerState pi2_logger = LoggerState::MakeLogger(
4422 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4423
4424 event_loop_factory.RunFor(chrono::milliseconds(95));
4425
4426 pi2_logger.StartLogger(kLogfile2_1);
4427
4428 event_loop_factory.RunFor(chrono::milliseconds(4000));
4429
4430 pi2->Disconnect(pi1->node());
4431
4432 event_loop_factory.RunFor(chrono::milliseconds(1000));
4433 pi1->AlwaysStart<Ping>("ping");
4434
4435 event_loop_factory.RunFor(chrono::milliseconds(5000));
4436 pi2_logger.AppendAllFilenames(&filenames);
4437 }
4438
4439 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4440 ConfirmReadable(filenames);
4441}
4442
Austin Schuhefba96d2022-06-24 13:22:18 -07004443// Tests that we properly handle what used to be a time violation in one
4444// direction. This can occur when one direction goes down after sending some
4445// data, but the other keeps working. The down direction ends up resolving to a
4446// straight line in the noncausal filter, where the direction which is still up
4447// can cross that line. Really, time progressed along just fine but we assumed
4448// that the offset was a line when it could have deviated by up to 1ms/second.
4449TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4450 std::vector<std::string> filenames;
4451
4452 CHECK_EQ(pi1_index_, 0u);
4453 CHECK_EQ(pi2_index_, 1u);
4454
4455 time_converter_.AddNextTimestamp(
4456 distributed_clock::epoch(),
4457 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4458
4459 const chrono::nanoseconds before_disconnect_duration =
4460 time_converter_.AddMonotonic(
4461 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4462
4463 const chrono::nanoseconds test_duration =
4464 time_converter_.AddMonotonic(
4465 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4466 time_converter_.AddMonotonic(
4467 {chrono::milliseconds(10000),
4468 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4469 time_converter_.AddMonotonic(
4470 {chrono::milliseconds(10000),
4471 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4472
4473 const std::string kLogfile =
4474 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4475 util::UnlinkRecursive(kLogfile);
4476
4477 {
4478 LoggerState pi2_logger = MakeLogger(pi2_);
4479 pi2_logger.StartLogger(kLogfile);
4480 event_loop_factory_.RunFor(before_disconnect_duration);
4481
4482 pi2_->Disconnect(pi1_->node());
4483
4484 event_loop_factory_.RunFor(test_duration);
4485 pi2_->Connect(pi1_->node());
4486
4487 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4488 pi2_logger.AppendAllFilenames(&filenames);
4489 }
4490
4491 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4492 ConfirmReadable(filenames);
4493}
4494
Austin Schuhe309d2a2019-11-29 13:25:21 -08004495} // namespace testing
4496} // namespace logger
4497} // namespace aos