blob: e558422706007f39fc22ae816170079f9bd475f8 [file] [log] [blame]
Austin Schuh6bb8a822021-03-31 23:04:39 -07001#include <sys/stat.h>
2
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07005#include "aos/events/logging/log_reader.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08006#include "aos/events/logging/log_writer.h"
milind1f1dca32021-07-03 13:50:07 -07007#include "aos/events/logging/snappy_encoder.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
milind1f1dca32021-07-03 13:50:07 -0700171 logger_event_loop->OnRun([base_name1, base_name2, &logger_event_loop,
172 &logger]() {
173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
175 EXPECT_DEATH(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 logger.StartLogging(std::make_unique<LocalLogNamer>(
milind1f1dca32021-07-03 13:50:07 -0700177 base_name2, logger_event_loop.get(), logger_event_loop->node())),
178 "Already logging");
179 });
Brian Silverman1f345222020-09-24 21:14:48 -0700180 event_loop_factory_.RunFor(chrono::milliseconds(20000));
181 }
182}
183
184// Tests calling StopLogging twice.
185TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800186 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700187 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800188 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700189 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700190 const ::std::string logfile = base_name + ".part0.bfbs";
191 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800192 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700193 unlink(logfile.c_str());
194
195 LOG(INFO) << "Logging data to " << logfile;
196
197 {
198 std::unique_ptr<EventLoop> logger_event_loop =
199 event_loop_factory_.MakeEventLoop("logger");
200
201 event_loop_factory_.RunFor(chrono::milliseconds(95));
202
203 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800204 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700205 logger.set_polling_period(std::chrono::milliseconds(100));
206 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700207 logger.StartLogging(std::make_unique<LocalLogNamer>(
208 base_name, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700209 logger.StopLogging(aos::monotonic_clock::min_time);
210 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
211 "Not logging right now");
212 });
213 event_loop_factory_.RunFor(chrono::milliseconds(20000));
214 }
215}
216
217// Tests that we can startup twice.
218TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800219 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700220 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800221 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700222 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700223 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
224 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800225 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700226 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700227 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
228 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800229 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700230 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800231 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700232
233 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
234
235 {
236 std::unique_ptr<EventLoop> logger_event_loop =
237 event_loop_factory_.MakeEventLoop("logger");
238
239 event_loop_factory_.RunFor(chrono::milliseconds(95));
240
241 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800242 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700243 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh5b728b72021-06-16 14:57:15 -0700244 logger.StartLogging(std::make_unique<LocalLogNamer>(
245 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700246 event_loop_factory_.RunFor(chrono::milliseconds(10000));
247 logger.StopLogging(logger_event_loop->monotonic_now());
248 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh5b728b72021-06-16 14:57:15 -0700249 logger.StartLogging(std::make_unique<LocalLogNamer>(
250 base_name2, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700251 event_loop_factory_.RunFor(chrono::milliseconds(10000));
252 }
253
254 for (const auto &logfile :
255 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
256 SCOPED_TRACE(std::get<0>(logfile));
257 LogReader reader(std::get<0>(logfile));
258 reader.Register();
259
Austin Schuh07676622021-01-21 18:59:17 -0800260 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700261
262 std::unique_ptr<EventLoop> test_event_loop =
263 reader.event_loop_factory()->MakeEventLoop("log_reader");
264
265 int ping_count = std::get<1>(logfile);
266 int pong_count = std::get<1>(logfile);
267
268 // Confirm that the ping and pong counts both match, and the value also
269 // matches.
270 test_event_loop->MakeWatcher("/test",
271 [&ping_count](const examples::Ping &ping) {
272 EXPECT_EQ(ping.value(), ping_count + 1);
273 ++ping_count;
274 });
275 test_event_loop->MakeWatcher(
276 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
277 EXPECT_EQ(pong.value(), pong_count + 1);
278 ++pong_count;
279 EXPECT_EQ(ping_count, pong_count);
280 });
281
282 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
283 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
284 }
285}
286
Austin Schuhfa895892020-01-07 20:07:41 -0800287// Tests that we can read and write rotated log files.
288TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800289 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700290 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800291 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700292 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700293 const ::std::string logfile0 = base_name + ".part0.bfbs";
294 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800295 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800296 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800297 unlink(logfile0.c_str());
298 unlink(logfile1.c_str());
299
300 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
301
302 {
Austin Schuhfa895892020-01-07 20:07:41 -0800303 std::unique_ptr<EventLoop> logger_event_loop =
304 event_loop_factory_.MakeEventLoop("logger");
305
306 event_loop_factory_.RunFor(chrono::milliseconds(95));
307
Brian Silverman1f345222020-09-24 21:14:48 -0700308 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800309 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700310 logger.set_polling_period(std::chrono::milliseconds(100));
311 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800312 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700313 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800314 event_loop_factory_.RunFor(chrono::milliseconds(10000));
315 }
316
Austin Schuh64fab802020-09-09 22:47:47 -0700317 {
318 // Confirm that the UUIDs match for both the parts and the logger, and the
319 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800320 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700321 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800322 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700323 }
324
Brian Silvermanae7c0332020-09-30 16:58:23 -0700325 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
326 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700327 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
328 log_header[1].message().parts_uuid()->string_view());
329
330 EXPECT_EQ(log_header[0].message().parts_index(), 0);
331 EXPECT_EQ(log_header[1].message().parts_index(), 1);
332 }
333
Austin Schuhfa895892020-01-07 20:07:41 -0800334 // Even though it doesn't make any difference here, exercise the logic for
335 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800336 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800337
338 // Confirm that we can remap logged channels to point to new buses.
339 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
340
341 // This sends out the fetched messages and advances time to the start of the
342 // log file.
343 reader.Register();
344
Austin Schuh07676622021-01-21 18:59:17 -0800345 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800346
347 std::unique_ptr<EventLoop> test_event_loop =
348 reader.event_loop_factory()->MakeEventLoop("log_reader");
349
350 int ping_count = 10;
351 int pong_count = 10;
352
353 // Confirm that the ping value matches in the remapped channel location.
354 test_event_loop->MakeWatcher("/original/test",
355 [&ping_count](const examples::Ping &ping) {
356 EXPECT_EQ(ping.value(), ping_count + 1);
357 ++ping_count;
358 });
359 // Confirm that the ping and pong counts both match, and the value also
360 // matches.
361 test_event_loop->MakeWatcher(
362 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
363 EXPECT_EQ(pong.value(), pong_count + 1);
364 ++pong_count;
365 EXPECT_EQ(ping_count, pong_count);
366 });
367
368 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
369 EXPECT_EQ(ping_count, 2010);
370}
371
Austin Schuh4c4e0092019-12-22 16:18:03 -0800372// Tests that a large number of messages per second doesn't overwhelm writev.
373TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800374 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700375 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800376 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700377 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700378 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800379 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800380 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800381 unlink(logfile.c_str());
382
383 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700384 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800385
386 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800387 std::unique_ptr<EventLoop> logger_event_loop =
388 event_loop_factory_.MakeEventLoop("logger");
389
390 std::unique_ptr<EventLoop> ping_spammer_event_loop =
391 event_loop_factory_.MakeEventLoop("ping_spammer");
392 aos::Sender<examples::Ping> ping_sender =
393 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
394
395 aos::TimerHandler *timer_handler =
396 ping_spammer_event_loop->AddTimer([&ping_sender]() {
397 aos::Sender<examples::Ping>::Builder builder =
398 ping_sender.MakeBuilder();
399 examples::Ping::Builder ping_builder =
400 builder.MakeBuilder<examples::Ping>();
Austin Schuhbfe6c572022-01-27 20:48:20 -0800401 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800402 });
403
404 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
405 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
406 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
407 chrono::microseconds(50));
408 });
409
Brian Silverman1f345222020-09-24 21:14:48 -0700410 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800411 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700412 logger.set_polling_period(std::chrono::milliseconds(100));
413 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800414
415 event_loop_factory_.RunFor(chrono::milliseconds(1000));
416 }
417}
418
James Kuszmauldd0a5042021-10-28 23:38:04 -0700419struct CompressionParams {
420 std::string_view extension;
421 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
422};
423
424std::ostream &operator<<(std::ostream &ostream,
425 const CompressionParams &params) {
426 ostream << "\"" << params.extension << "\"";
427 return ostream;
428}
429
430std::vector<CompressionParams> SupportedCompressionAlgorithms() {
431 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
432 {SnappyDecoder::kExtension,
433 []() { return std::make_unique<SnappyEncoder>(); }},
434#ifdef LZMA
435 {LzmaDecoder::kExtension,
436 []() { return std::make_unique<LzmaEncoder>(3); }}
437#endif // LZMA
438 };
439}
440
Austin Schuh61e973f2021-02-21 21:43:56 -0800441// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700442struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800443 // The config file to use.
444 std::string config;
445 // If true, the RemoteMessage channel should be shared between all the remote
446 // channels. If false, there will be 1 RemoteMessage channel per remote
447 // channel.
448 bool shared;
449 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700450 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800451};
Austin Schuh315b96b2020-12-11 21:21:12 -0800452
James Kuszmauldd0a5042021-10-28 23:38:04 -0700453std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
454 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
455 << ", sha256: \"" << params.sha256 << "\"}";
456 return ostream;
457}
458
Austin Schuh3e20c692021-11-16 20:43:16 -0800459struct LoggerState {
460 static LoggerState MakeLogger(NodeEventLoopFactory *node,
461 SimulatedEventLoopFactory *factory,
462 CompressionParams params,
463 const Configuration *configuration = nullptr) {
464 if (configuration == nullptr) {
465 configuration = factory->configuration();
466 }
467 return {node->MakeEventLoop("logger"),
468 {},
469 configuration,
470 configuration::GetNode(configuration, node->node()),
471 nullptr,
472 params};
473 }
474
475 void StartLogger(std::string logfile_base) {
476 CHECK(!logfile_base.empty());
477
478 logger = std::make_unique<Logger>(event_loop.get(), configuration);
479 logger->set_polling_period(std::chrono::milliseconds(100));
480 logger->set_name(
481 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
482 event_loop->OnRun([this, logfile_base]() {
483 std::unique_ptr<MultiNodeLogNamer> namer =
484 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
485 event_loop.get(), node);
486 namer->set_extension(params.extension);
487 namer->set_encoder_factory(params.encoder_factory);
488 log_namer = namer.get();
489
490 logger->StartLogging(std::move(namer));
491 });
492 }
493
494 std::unique_ptr<EventLoop> event_loop;
495 std::unique_ptr<Logger> logger;
496 const Configuration *configuration;
497 const Node *node;
498 MultiNodeLogNamer *log_namer;
499 CompressionParams params;
500
501 void AppendAllFilenames(std::vector<std::string> *filenames) {
502 for (const std::string &file : log_namer->all_filenames()) {
503 const std::string_view separator =
504 log_namer->base_name().back() == '/' ? "" : "_";
505 filenames->emplace_back(
506 absl::StrCat(log_namer->base_name(), separator, file));
507 }
508 }
509
510 ~LoggerState() {
511 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800512 std::vector<std::string> filenames;
513 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800514 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800515 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800516 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800517 auto x = ReadHeader(file);
518 if (x) {
519 VLOG(1) << aos::FlatbufferToJson(x.value());
520 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800521 }
522 }
523 }
524};
525
526void ConfirmReadable(const std::vector<std::string> &files) {
527 {
528 LogReader reader(SortParts(files));
529
530 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
531 reader.Register(&log_reader_factory);
532
533 log_reader_factory.Run();
534
535 reader.Deregister();
536 }
537 {
538 LogReader reader(SortParts(files));
539
540 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
541 reader.RegisterWithoutStarting(&log_reader_factory);
542 if (configuration::MultiNode(log_reader_factory.configuration())) {
543 for (const aos::Node *node :
544 *log_reader_factory.configuration()->nodes()) {
545 reader.OnStart(node, [node]() {
546 LOG(INFO) << "Starting " << node->name()->string_view();
547 });
548 }
549 }
550
551 log_reader_factory.Run();
552
553 reader.Deregister();
554 }
555}
556
James Kuszmauldd0a5042021-10-28 23:38:04 -0700557class MultinodeLoggerTest : public ::testing::TestWithParam<
558 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800559 public:
560 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700561 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
562 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800563 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800564 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700565 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800566 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700567 event_loop_factory_.configuration(), pi1_->node())),
568 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800569 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700570 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800571 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800572 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
573 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800574 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800575 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800576 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700577 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700578 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800579 event_loop_factory_.SetTimeConverter(&time_converter_);
580
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700581 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700582 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700583 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800584 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700585 }
586
Austin Schuh268586b2021-03-31 22:24:39 -0700587 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800588 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800589 unlink(file.c_str());
590 }
591
Austin Schuh268586b2021-03-31 22:24:39 -0700592 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800593 unlink(file.c_str());
594 }
595
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700596 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
597 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700598
599 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
600 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700601 }
602
James Kuszmauldd0a5042021-10-28 23:38:04 -0700603 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800604
605 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700606 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800607 size_t pi1_data_count = 3,
608 size_t pi2_data_count = 3) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800609 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700610 result.emplace_back(absl::StrCat(
611 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
612 result.emplace_back(absl::StrCat(
613 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700614 for (size_t i = 0; i < pi1_data_count; ++i) {
615 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700616 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700617 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800618 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700619 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800620 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700621 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700622 for (size_t i = 0; i < pi2_data_count; ++i) {
623 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700624 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700625 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700626 result.emplace_back(logfile_base2 +
627 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
628 Extension());
629 result.emplace_back(logfile_base2 +
630 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
631 Extension());
632 result.emplace_back(logfile_base1 +
633 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
634 Extension());
635 result.emplace_back(logfile_base1 +
636 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
637 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800638 if (shared()) {
639 result.emplace_back(logfile_base1 +
640 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700641 "aos.message_bridge.RemoteMessage.part0" +
642 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800643 result.emplace_back(logfile_base1 +
644 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700645 "aos.message_bridge.RemoteMessage.part1" +
646 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800647 result.emplace_back(logfile_base1 +
648 "_timestamps/pi1/aos/remote_timestamps/pi2/"
649 "aos.message_bridge.RemoteMessage.part2" +
650 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800651 result.emplace_back(logfile_base2 +
652 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700653 "aos.message_bridge.RemoteMessage.part0" +
654 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800655 result.emplace_back(logfile_base2 +
656 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700657 "aos.message_bridge.RemoteMessage.part1" +
658 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800659 } else {
660 result.emplace_back(logfile_base1 +
661 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
662 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700663 "aos.message_bridge.RemoteMessage.part0" +
664 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800665 result.emplace_back(logfile_base1 +
666 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
667 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700668 "aos.message_bridge.RemoteMessage.part1" +
669 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800670 result.emplace_back(logfile_base2 +
671 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
672 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700673 "aos.message_bridge.RemoteMessage.part0" +
674 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800675 result.emplace_back(logfile_base2 +
676 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
677 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700678 "aos.message_bridge.RemoteMessage.part1" +
679 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800680 result.emplace_back(logfile_base1 +
681 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
682 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700683 "aos.message_bridge.RemoteMessage.part0" +
684 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800685 result.emplace_back(logfile_base1 +
686 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
687 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700688 "aos.message_bridge.RemoteMessage.part1" +
689 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800690 }
691
692 return result;
693 }
694
695 std::vector<std::string> MakePi1RebootLogfiles() {
696 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700697 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
698 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
699 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800700 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
701 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800702 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700703 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800704 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700705 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800706 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700707 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700708 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700709 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
710 result.emplace_back(logfile_base1_ +
711 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
712 Extension());
713 result.emplace_back(logfile_base1_ +
714 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
715 Extension());
716 result.emplace_back(logfile_base1_ +
717 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
718 Extension());
719 result.emplace_back(logfile_base1_ +
720 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
721 Extension());
722 result.emplace_back(absl::StrCat(
723 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800724 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800725 for (size_t i = 0; i < 6; ++i) {
726 result.emplace_back(
727 absl::StrCat(logfile_base1_,
728 "_timestamps/pi1/aos/remote_timestamps/pi2/"
729 "aos.message_bridge.RemoteMessage.part",
730 i, Extension()));
731 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800732 } else {
733 result.emplace_back(logfile_base1_ +
734 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
735 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700736 "aos.message_bridge.RemoteMessage.part0" +
737 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800738 result.emplace_back(logfile_base1_ +
739 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
740 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700741 "aos.message_bridge.RemoteMessage.part1" +
742 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800743 result.emplace_back(logfile_base1_ +
744 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
745 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700746 "aos.message_bridge.RemoteMessage.part2" +
747 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700748 result.emplace_back(logfile_base1_ +
749 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
750 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700751 "aos.message_bridge.RemoteMessage.part3" +
752 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800753
754 result.emplace_back(logfile_base1_ +
755 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
756 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700757 "aos.message_bridge.RemoteMessage.part0" +
758 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800759 result.emplace_back(logfile_base1_ +
760 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
761 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700762 "aos.message_bridge.RemoteMessage.part1" +
763 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800764 result.emplace_back(logfile_base1_ +
765 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
766 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700767 "aos.message_bridge.RemoteMessage.part2" +
768 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700769 result.emplace_back(logfile_base1_ +
770 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
771 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700772 "aos.message_bridge.RemoteMessage.part3" +
773 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800774 }
775 return result;
776 }
777
778 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
779 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700780 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
781 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
782 result.emplace_back(logfile_base1_ +
783 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
784 Extension());
785 result.emplace_back(absl::StrCat(
786 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700787 return result;
788 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800789
Austin Schuh510dc622021-08-06 18:47:30 -0700790 std::vector<std::string> MakePi1DeadNodeLogfiles() {
791 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700792 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
793 result.emplace_back(absl::StrCat(
794 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800795 return result;
796 }
797
798 std::vector<std::vector<std::string>> StructureLogFiles() {
799 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800800 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
801 std::vector<std::string>{logfiles_[5], logfiles_[6]},
802 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800803 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800804 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800805
Austin Schuhbfe6c572022-01-27 20:48:20 -0800806 if (shared()) {
807 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
808 logfiles_[16]});
809 result.emplace_back(
810 std::vector<std::string>{logfiles_[17], logfiles_[18]});
811 } else {
812 result.emplace_back(
813 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800814 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700815 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800816 result.emplace_back(
817 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800818 }
819
820 return result;
821 }
822
James Kuszmauldd0a5042021-10-28 23:38:04 -0700823 std::string Extension() {
824 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
825 }
826
Austin Schuh58646e22021-08-23 23:51:46 -0700827 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700828 SimulatedEventLoopFactory *factory = nullptr,
829 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700830 if (factory == nullptr) {
831 factory = &event_loop_factory_;
832 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800833 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
834 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700835 }
836
James Kuszmauldd0a5042021-10-28 23:38:04 -0700837 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700838 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800839 if (logger->event_loop->node()->name()->string_view() == "pi1") {
840 logfile_base = logfile_base1_;
841 } else {
842 logfile_base = logfile_base2_;
843 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700844 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800845 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700846 }
Austin Schuh15649d62019-12-28 16:36:38 -0800847
Austin Schuh3bd4c402020-11-06 18:19:06 -0800848 void VerifyParts(const std::vector<LogFile> &sorted_parts,
849 const std::vector<std::string> &corrupted_parts = {}) {
850 EXPECT_EQ(sorted_parts.size(), 2u);
851
852 // Count up the number of UUIDs and make sure they are what we expect as a
853 // sanity check.
854 std::set<std::string> log_event_uuids;
855 std::set<std::string> parts_uuids;
856 std::set<std::string> both_uuids;
857
858 size_t missing_rt_count = 0;
859
860 std::vector<std::string> logger_nodes;
861 for (const LogFile &log_file : sorted_parts) {
862 EXPECT_FALSE(log_file.log_event_uuid.empty());
863 log_event_uuids.insert(log_file.log_event_uuid);
864 logger_nodes.emplace_back(log_file.logger_node);
865 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800866 EXPECT_TRUE(log_file.config);
867 EXPECT_EQ(log_file.name,
868 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800869
870 for (const LogParts &part : log_file.parts) {
871 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
872 << ": " << part;
873 missing_rt_count +=
874 part.realtime_start_time == aos::realtime_clock::min_time;
875
876 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
877 log_event_uuids.end());
878 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800879 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800880 parts_uuids.insert(part.parts_uuid);
881 both_uuids.insert(part.parts_uuid);
882 }
883 }
884
Austin Schuh61e973f2021-02-21 21:43:56 -0800885 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
886 // start time on remote nodes because we don't know it and would be
887 // guessing. And the log reader can actually do a better job. The number
888 // depends on if we have the remote timestamps split across 2 files, or just
889 // across 1, depending on if we are using a split or combined timestamp
890 // channel config.
891 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800892
893 EXPECT_EQ(log_event_uuids.size(), 2u);
894 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
895 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
896
897 // Test that each list of parts is in order. Don't worry about the ordering
898 // between part file lists though.
899 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -0800900 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -0800901 ::testing::UnorderedElementsAreArray(structured_logfiles_));
902
903 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
904
905 EXPECT_NE(sorted_parts[0].realtime_start_time,
906 aos::realtime_clock::min_time);
907 EXPECT_NE(sorted_parts[1].realtime_start_time,
908 aos::realtime_clock::min_time);
909
910 EXPECT_NE(sorted_parts[0].monotonic_start_time,
911 aos::monotonic_clock::min_time);
912 EXPECT_NE(sorted_parts[1].monotonic_start_time,
913 aos::monotonic_clock::min_time);
914
915 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
916 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
917 }
918
919 void AddExtension(std::string_view extension) {
920 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
921 [extension](const std::string &in) {
922 return absl::StrCat(in, extension);
923 });
924
925 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
926 structured_logfiles_.begin(),
927 [extension](std::vector<std::string> in) {
928 std::transform(in.begin(), in.end(), in.begin(),
929 [extension](const std::string &in_str) {
930 return absl::StrCat(in_str, extension);
931 });
932 return in;
933 });
934 }
935
Austin Schuh15649d62019-12-28 16:36:38 -0800936 // Config and factory.
937 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800938 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800939 SimulatedEventLoopFactory event_loop_factory_;
940
Austin Schuh58646e22021-08-23 23:51:46 -0700941 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800942 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700943 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800944 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700945
946 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800947 std::string logfile_base1_;
948 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800949 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700950 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800951 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700952
953 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800954};
955
Austin Schuh391e3172020-09-01 22:48:18 -0700956// Counts the number of messages on a channel. Returns (channel name, channel
957// type, count) for every message matching matcher()
958std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800959 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700960 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800961 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800962 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800963
Austin Schuh6f3babe2020-01-26 20:34:50 -0800964 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700965 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800966 if (!msg) {
967 break;
968 }
969
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700970 if (matcher(msg.get())) {
971 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800972 }
973 }
974
Austin Schuh391e3172020-09-01 22:48:18 -0700975 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800976 int channel = 0;
977 for (size_t i = 0; i < counts.size(); ++i) {
978 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800979 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700980 result.push_back(std::make_tuple(channel->name()->str(),
981 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800982 }
983 ++channel;
984 }
985
986 return result;
987}
988
989// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700990std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800991 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700992 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700993 return CountChannelsMatching(
994 config, filename, [](const UnpackedMessageHeader *msg) {
995 if (msg->span.data() != nullptr) {
996 CHECK(!msg->monotonic_remote_time.has_value());
997 CHECK(!msg->realtime_remote_time.has_value());
998 CHECK(!msg->remote_queue_index.has_value());
999 return true;
1000 }
1001 return false;
1002 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001003}
1004
1005// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001006std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001007 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001008 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001009 return CountChannelsMatching(
1010 config, filename, [](const UnpackedMessageHeader *msg) {
1011 if (msg->span.data() == nullptr) {
1012 CHECK(msg->monotonic_remote_time.has_value());
1013 CHECK(msg->realtime_remote_time.has_value());
1014 CHECK(msg->remote_queue_index.has_value());
1015 return true;
1016 }
1017 return false;
1018 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001019}
1020
Austin Schuhcde938c2020-02-02 17:30:07 -08001021// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001022TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001023 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001024 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001025
Austin Schuh15649d62019-12-28 16:36:38 -08001026 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001027 LoggerState pi1_logger = MakeLogger(pi1_);
1028 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001029
1030 event_loop_factory_.RunFor(chrono::milliseconds(95));
1031
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001032 StartLogger(&pi1_logger);
1033 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001034
Austin Schuh15649d62019-12-28 16:36:38 -08001035 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001036 pi1_logger.AppendAllFilenames(&actual_filenames);
1037 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001038 }
1039
Austin Schuhbfe6c572022-01-27 20:48:20 -08001040 ASSERT_THAT(actual_filenames,
1041 ::testing::UnorderedElementsAreArray(logfiles_));
1042
Austin Schuh6f3babe2020-01-26 20:34:50 -08001043 {
Austin Schuh64fab802020-09-09 22:47:47 -07001044 std::set<std::string> logfile_uuids;
1045 std::set<std::string> parts_uuids;
1046 // Confirm that we have the expected number of UUIDs for both the logfile
1047 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001048 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001049 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001050 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001051 if (!log_header.back().message().has_configuration()) {
1052 logfile_uuids.insert(
1053 log_header.back().message().log_event_uuid()->str());
1054 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1055 }
Austin Schuh64fab802020-09-09 22:47:47 -07001056 }
Austin Schuh15649d62019-12-28 16:36:38 -08001057
Austin Schuh64fab802020-09-09 22:47:47 -07001058 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001059 if (shared()) {
1060 EXPECT_EQ(parts_uuids.size(), 7u);
1061 } else {
1062 EXPECT_EQ(parts_uuids.size(), 8u);
1063 }
Austin Schuh64fab802020-09-09 22:47:47 -07001064
1065 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001066 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001067 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001068 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1069
Austin Schuh64fab802020-09-09 22:47:47 -07001070 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001071 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001072
Austin Schuhe46492f2021-07-31 19:49:41 -07001073 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001074 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1075 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1076
1077 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1078 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1079
Austin Schuhe46492f2021-07-31 19:49:41 -07001080 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1081 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001082
1083 if (shared()) {
1084 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1085 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001086 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001087
1088 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1089 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1090 } else {
1091 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1092 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1093
1094 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1095 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1096
1097 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1098 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001099 }
Austin Schuh64fab802020-09-09 22:47:47 -07001100
1101 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001102 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001103 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001104 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1105
1106 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1107 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1108
1109 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1110 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1111 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1112
Austin Schuh64fab802020-09-09 22:47:47 -07001113 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1114 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001115
Austin Schuh61e973f2021-02-21 21:43:56 -08001116 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1117 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001118
1119 if (shared()) {
1120 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1121 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1122 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1123
1124 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1125 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1126 } else {
1127 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1128 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1129
Austin Schuhe46492f2021-07-31 19:49:41 -07001130 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1131 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001132
1133 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1134 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001135 }
Austin Schuh64fab802020-09-09 22:47:47 -07001136 }
1137
Austin Schuh8c399962020-12-25 21:51:45 -08001138 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001139 {
Austin Schuh391e3172020-09-01 22:48:18 -07001140 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001141 std::shared_ptr<const aos::Configuration> config =
1142 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001143
Austin Schuh6f3babe2020-01-26 20:34:50 -08001144 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001145 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1146 UnorderedElementsAre(
1147 std::make_tuple("/pi1/aos",
1148 "aos.message_bridge.ServerStatistics", 1),
1149 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001150 << " : " << logfiles_[2];
1151 EXPECT_THAT(
1152 CountChannelsData(config, logfiles_[3]),
1153 UnorderedElementsAre(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001154 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1155 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1156 1)))
1157 << " : " << logfiles_[3];
1158 EXPECT_THAT(
1159 CountChannelsData(config, logfiles_[4]),
1160 UnorderedElementsAre(
1161 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001162 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001163 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001164 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
Austin Schuhbfe6c572022-01-27 20:48:20 -08001165 199),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001166 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001167 std::make_tuple("/test", "aos.examples.Ping", 2000)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001168 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001169 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001170 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1171 UnorderedElementsAre())
1172 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001173 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001174 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001175 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001176 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001177 EXPECT_THAT(
1178 CountChannelsTimestamp(config, logfiles_[4]),
1179 UnorderedElementsAre(
1180 std::make_tuple("/test", "aos.examples.Pong", 2000),
1181 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1182 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001183
1184 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001185 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001186 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001187 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001188 << " : " << logfiles_[5];
1189 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001190 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001191 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001192 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001193
Austin Schuh6f3babe2020-01-26 20:34:50 -08001194 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001195 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1196 UnorderedElementsAre())
1197 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001198 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1199 UnorderedElementsAre())
1200 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001201
1202 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001203 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001204 UnorderedElementsAre(std::make_tuple(
1205 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001206 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001207 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001208 CountChannelsData(config, logfiles_[8]),
1209 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1210 << " : " << logfiles_[8];
1211 EXPECT_THAT(
1212 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001213 UnorderedElementsAre(
1214 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001215 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001216 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001217 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1218 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001219 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001220 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1221 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001222 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001223 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001224 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001225 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001226 EXPECT_THAT(
1227 CountChannelsTimestamp(config, logfiles_[8]),
1228 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1229 << " : " << logfiles_[8];
1230 EXPECT_THAT(
1231 CountChannelsTimestamp(config, logfiles_[9]),
1232 UnorderedElementsAre(
1233 std::make_tuple("/test", "aos.examples.Ping", 2000),
1234 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1235 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001236
1237 // And then test that the remotely logged timestamp data files only have
1238 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001239 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1240 UnorderedElementsAre())
1241 << " : " << logfiles_[10];
1242 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1243 UnorderedElementsAre())
1244 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001245 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1246 UnorderedElementsAre())
1247 << " : " << logfiles_[12];
1248 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1249 UnorderedElementsAre())
1250 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001251
Austin Schuh8c399962020-12-25 21:51:45 -08001252 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001253 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001254 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001255 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001256 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001257 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001258 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001259 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001260
Austin Schuh61e973f2021-02-21 21:43:56 -08001261 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001262 UnorderedElementsAre(std::make_tuple(
1263 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001264 << " : " << logfiles_[12];
1265 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001266 UnorderedElementsAre(std::make_tuple(
1267 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001268 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001269
1270 // Timestamps from pi2 on pi1, and the other way.
1271 if (shared()) {
1272 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1273 UnorderedElementsAre())
1274 << " : " << logfiles_[14];
1275 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1276 UnorderedElementsAre())
1277 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001278 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001279 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001280 << " : " << logfiles_[16];
1281 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001282 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001283 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001284 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1285 UnorderedElementsAre())
1286 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001287
Austin Schuhbfe6c572022-01-27 20:48:20 -08001288 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1289 UnorderedElementsAre(
1290 std::make_tuple("/test", "aos.examples.Ping", 1)))
1291 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001292 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001293 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001294 UnorderedElementsAre(
1295 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001296 std::make_tuple("/test", "aos.examples.Ping", 90)))
1297 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001298 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001299 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001300 UnorderedElementsAre(
1301 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1302 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001303 << " : " << logfiles_[16];
1304 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001305 UnorderedElementsAre(std::make_tuple(
1306 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1307 << " : " << logfiles_[17];
1308 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1309 UnorderedElementsAre(std::make_tuple(
1310 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1311 << " : " << logfiles_[18];
1312 } else {
1313 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1314 UnorderedElementsAre())
1315 << " : " << logfiles_[14];
1316 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1317 UnorderedElementsAre())
1318 << " : " << logfiles_[15];
1319 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1320 UnorderedElementsAre())
1321 << " : " << logfiles_[16];
1322 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1323 UnorderedElementsAre())
1324 << " : " << logfiles_[17];
1325 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1326 UnorderedElementsAre())
1327 << " : " << logfiles_[18];
1328 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1329 UnorderedElementsAre())
1330 << " : " << logfiles_[19];
1331
1332 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1333 UnorderedElementsAre(std::make_tuple(
1334 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1335 << " : " << logfiles_[14];
1336 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1337 UnorderedElementsAre(std::make_tuple(
1338 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1339 << " : " << logfiles_[15];
1340 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1341 UnorderedElementsAre(std::make_tuple(
1342 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1343 << " : " << logfiles_[16];
1344 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1345 UnorderedElementsAre(std::make_tuple(
1346 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1347 << " : " << logfiles_[17];
1348 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1349 UnorderedElementsAre(
1350 std::make_tuple("/test", "aos.examples.Ping", 91)))
1351 << " : " << logfiles_[18];
1352 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001353 UnorderedElementsAre(
1354 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001355 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001356 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001357 }
1358
Austin Schuh8c399962020-12-25 21:51:45 -08001359 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001360
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001361 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001362 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001363
1364 // This sends out the fetched messages and advances time to the start of the
1365 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001366 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001367
Austin Schuhac0771c2020-01-07 18:36:30 -08001368 const Node *pi1 =
1369 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001370 const Node *pi2 =
1371 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001372
Austin Schuh2f8fd752020-09-01 22:38:28 -07001373 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1374 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1375 LOG(INFO) << "now pi1 "
1376 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1377 LOG(INFO) << "now pi2 "
1378 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1379
Austin Schuh07676622021-01-21 18:59:17 -08001380 EXPECT_THAT(reader.LoggedNodes(),
1381 ::testing::ElementsAre(
1382 configuration::GetNode(reader.logged_configuration(), pi1),
1383 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001384
1385 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001386
Austin Schuh6f3babe2020-01-26 20:34:50 -08001387 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001388 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001389 std::unique_ptr<EventLoop> pi2_event_loop =
1390 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001391
Austin Schuh6f3babe2020-01-26 20:34:50 -08001392 int pi1_ping_count = 10;
1393 int pi2_ping_count = 10;
1394 int pi1_pong_count = 10;
1395 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001396
1397 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001398 pi1_event_loop->MakeWatcher(
1399 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001400 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001401 << pi1_event_loop->context().monotonic_remote_time << " -> "
1402 << pi1_event_loop->context().monotonic_event_time;
1403 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1404 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1405 pi1_ping_count * chrono::milliseconds(10) +
1406 monotonic_clock::epoch());
1407 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1408 pi1_ping_count * chrono::milliseconds(10) +
1409 realtime_clock::epoch());
1410 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1411 pi1_event_loop->context().monotonic_event_time);
1412 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1413 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001414
Austin Schuh6f3babe2020-01-26 20:34:50 -08001415 ++pi1_ping_count;
1416 });
1417 pi2_event_loop->MakeWatcher(
1418 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001419 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001420 << pi2_event_loop->context().monotonic_remote_time << " -> "
1421 << pi2_event_loop->context().monotonic_event_time;
1422 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1423
1424 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1425 pi2_ping_count * chrono::milliseconds(10) +
1426 monotonic_clock::epoch());
1427 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1428 pi2_ping_count * chrono::milliseconds(10) +
1429 realtime_clock::epoch());
1430 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1431 chrono::microseconds(150),
1432 pi2_event_loop->context().monotonic_event_time);
1433 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1434 chrono::microseconds(150),
1435 pi2_event_loop->context().realtime_event_time);
1436 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001437 });
1438
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001439 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001440 // Confirm that the ping and pong counts both match, and the value also
1441 // matches.
1442 pi1_event_loop->MakeWatcher(
1443 "/test", [&pi1_event_loop, &pi1_ping_count,
1444 &pi1_pong_count](const examples::Pong &pong) {
1445 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1446 << pi1_event_loop->context().monotonic_remote_time << " -> "
1447 << pi1_event_loop->context().monotonic_event_time;
1448
1449 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1450 pi1_pong_count + kQueueIndexOffset);
1451 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1452 chrono::microseconds(200) +
1453 pi1_pong_count * chrono::milliseconds(10) +
1454 monotonic_clock::epoch());
1455 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1456 chrono::microseconds(200) +
1457 pi1_pong_count * chrono::milliseconds(10) +
1458 realtime_clock::epoch());
1459
1460 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1461 chrono::microseconds(150),
1462 pi1_event_loop->context().monotonic_event_time);
1463 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1464 chrono::microseconds(150),
1465 pi1_event_loop->context().realtime_event_time);
1466
1467 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1468 ++pi1_pong_count;
1469 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1470 });
1471 pi2_event_loop->MakeWatcher(
1472 "/test", [&pi2_event_loop, &pi2_ping_count,
1473 &pi2_pong_count](const examples::Pong &pong) {
1474 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1475 << pi2_event_loop->context().monotonic_remote_time << " -> "
1476 << pi2_event_loop->context().monotonic_event_time;
1477
1478 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001479 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001480
1481 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1482 chrono::microseconds(200) +
1483 pi2_pong_count * chrono::milliseconds(10) +
1484 monotonic_clock::epoch());
1485 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1486 chrono::microseconds(200) +
1487 pi2_pong_count * chrono::milliseconds(10) +
1488 realtime_clock::epoch());
1489
1490 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1491 pi2_event_loop->context().monotonic_event_time);
1492 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1493 pi2_event_loop->context().realtime_event_time);
1494
1495 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1496 ++pi2_pong_count;
1497 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1498 });
1499
1500 log_reader_factory.Run();
1501 EXPECT_EQ(pi1_ping_count, 2010);
1502 EXPECT_EQ(pi2_ping_count, 2010);
1503 EXPECT_EQ(pi1_pong_count, 2010);
1504 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001505
1506 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001507}
1508
James Kuszmaul46d82582020-05-09 19:50:09 -07001509typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1510
1511// Test that if we feed the replay with a mismatched node list that we die on
1512// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001513TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001514 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001515 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001516 LoggerState pi1_logger = MakeLogger(pi1_);
1517 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001518
1519 event_loop_factory_.RunFor(chrono::milliseconds(95));
1520
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001521 StartLogger(&pi1_logger);
1522 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001523
James Kuszmaul46d82582020-05-09 19:50:09 -07001524 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1525 }
1526
1527 // Test that, if we add an additional node to the replay config that the
1528 // logger complains about the mismatch in number of nodes.
1529 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1530 configuration::MergeWithConfig(&config_.message(), R"({
1531 "nodes": [
1532 {
1533 "name": "extra-node"
1534 }
1535 ]
1536 }
1537 )");
1538
Austin Schuh287d43d2020-12-04 20:19:33 -08001539 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1540 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001541 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001542}
1543
Austin Schuhcde938c2020-02-02 17:30:07 -08001544// Tests that we can read log files where they don't start at the same monotonic
1545// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001546TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001547 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001548 std::vector<std::string> actual_filenames;
1549
Austin Schuhcde938c2020-02-02 17:30:07 -08001550 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001551 LoggerState pi1_logger = MakeLogger(pi1_);
1552 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001553
1554 event_loop_factory_.RunFor(chrono::milliseconds(95));
1555
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001556 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001557
1558 event_loop_factory_.RunFor(chrono::milliseconds(200));
1559
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001560 StartLogger(&pi2_logger);
1561
Austin Schuhcde938c2020-02-02 17:30:07 -08001562 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001563 pi1_logger.AppendAllFilenames(&actual_filenames);
1564 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001565 }
1566
Austin Schuhe46492f2021-07-31 19:49:41 -07001567 // Since we delay starting pi2, it already knows about all the timestamps so
1568 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001569 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001570
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001571 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001572 log_reader_factory.set_send_delay(chrono::microseconds(0));
1573
1574 // This sends out the fetched messages and advances time to the start of the
1575 // log file.
1576 reader.Register(&log_reader_factory);
1577
1578 const Node *pi1 =
1579 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1580 const Node *pi2 =
1581 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1582
Austin Schuh07676622021-01-21 18:59:17 -08001583 EXPECT_THAT(reader.LoggedNodes(),
1584 ::testing::ElementsAre(
1585 configuration::GetNode(reader.logged_configuration(), pi1),
1586 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001587
1588 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1589
1590 std::unique_ptr<EventLoop> pi1_event_loop =
1591 log_reader_factory.MakeEventLoop("test", pi1);
1592 std::unique_ptr<EventLoop> pi2_event_loop =
1593 log_reader_factory.MakeEventLoop("test", pi2);
1594
1595 int pi1_ping_count = 30;
1596 int pi2_ping_count = 30;
1597 int pi1_pong_count = 30;
1598 int pi2_pong_count = 30;
1599
1600 // Confirm that the ping value matches.
1601 pi1_event_loop->MakeWatcher(
1602 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1603 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1604 << pi1_event_loop->context().monotonic_remote_time << " -> "
1605 << pi1_event_loop->context().monotonic_event_time;
1606 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1607
1608 ++pi1_ping_count;
1609 });
1610 pi2_event_loop->MakeWatcher(
1611 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1612 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1613 << pi2_event_loop->context().monotonic_remote_time << " -> "
1614 << pi2_event_loop->context().monotonic_event_time;
1615 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1616
1617 ++pi2_ping_count;
1618 });
1619
1620 // Confirm that the ping and pong counts both match, and the value also
1621 // matches.
1622 pi1_event_loop->MakeWatcher(
1623 "/test", [&pi1_event_loop, &pi1_ping_count,
1624 &pi1_pong_count](const examples::Pong &pong) {
1625 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1626 << pi1_event_loop->context().monotonic_remote_time << " -> "
1627 << pi1_event_loop->context().monotonic_event_time;
1628
1629 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1630 ++pi1_pong_count;
1631 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1632 });
1633 pi2_event_loop->MakeWatcher(
1634 "/test", [&pi2_event_loop, &pi2_ping_count,
1635 &pi2_pong_count](const examples::Pong &pong) {
1636 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1637 << pi2_event_loop->context().monotonic_remote_time << " -> "
1638 << pi2_event_loop->context().monotonic_event_time;
1639
1640 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1641 ++pi2_pong_count;
1642 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1643 });
1644
1645 log_reader_factory.Run();
1646 EXPECT_EQ(pi1_ping_count, 2030);
1647 EXPECT_EQ(pi2_ping_count, 2030);
1648 EXPECT_EQ(pi1_pong_count, 2030);
1649 EXPECT_EQ(pi2_pong_count, 2030);
1650
1651 reader.Deregister();
1652}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001653
Austin Schuh8bd96322020-02-13 21:18:22 -08001654// Tests that we can read log files where the monotonic clocks drift and don't
1655// match correctly. While we are here, also test that different ending times
1656// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001657TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001658 // TODO(austin): Negate...
1659 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1660
Austin Schuh66168842021-08-17 19:42:21 -07001661 time_converter_.AddMonotonic(
1662 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001663 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1664 // skew to be 200 uS/s
1665 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1666 {chrono::milliseconds(95),
1667 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1668 // Run another 200 ms to have one logger start first.
1669 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1670 {chrono::milliseconds(200), chrono::milliseconds(200)});
1671 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1672 // go far enough to cause problems if this isn't accounted for.
1673 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1674 {chrono::milliseconds(20000),
1675 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1676 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1677 {chrono::milliseconds(40000),
1678 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1679 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1680 {chrono::milliseconds(400), chrono::milliseconds(400)});
1681
Austin Schuhcde938c2020-02-02 17:30:07 -08001682 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001683 LoggerState pi2_logger = MakeLogger(pi2_);
1684
Austin Schuh58646e22021-08-23 23:51:46 -07001685 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1686 << pi2_->realtime_now() << " distributed "
1687 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001688
Austin Schuh58646e22021-08-23 23:51:46 -07001689 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1690 << pi2_->realtime_now() << " distributed "
1691 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001692
Austin Schuh87dd3832021-01-01 23:07:31 -08001693 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001694
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001695 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001696
Austin Schuh87dd3832021-01-01 23:07:31 -08001697 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001698
Austin Schuh8bd96322020-02-13 21:18:22 -08001699 {
1700 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001701 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001702
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001703 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001704 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001705
Austin Schuh87dd3832021-01-01 23:07:31 -08001706 // Make sure we slewed time far enough so that the difference is greater
1707 // than the network delay. This confirms that if we sort incorrectly, it
1708 // would show in the results.
1709 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001710 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001711 -event_loop_factory_.send_delay() -
1712 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001713
Austin Schuh87dd3832021-01-01 23:07:31 -08001714 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001715
Austin Schuh87dd3832021-01-01 23:07:31 -08001716 // And now check that we went far enough the other way to make sure we
1717 // cover both problems.
1718 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001719 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001720 event_loop_factory_.send_delay() +
1721 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001722 }
1723
1724 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001725 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001726 }
1727
Austin Schuh72211ae2021-08-05 14:02:30 -07001728 LogReader reader(
1729 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001730
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001731 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001732 log_reader_factory.set_send_delay(chrono::microseconds(0));
1733
Austin Schuhcde938c2020-02-02 17:30:07 -08001734 const Node *pi1 =
1735 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1736 const Node *pi2 =
1737 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1738
Austin Schuh2f8fd752020-09-01 22:38:28 -07001739 // This sends out the fetched messages and advances time to the start of the
1740 // log file.
1741 reader.Register(&log_reader_factory);
1742
1743 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1744 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1745 LOG(INFO) << "now pi1 "
1746 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1747 LOG(INFO) << "now pi2 "
1748 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1749
Austin Schuhcde938c2020-02-02 17:30:07 -08001750 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001751 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1752 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001753 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1754 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001755 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1756 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001757 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1758
Austin Schuh07676622021-01-21 18:59:17 -08001759 EXPECT_THAT(reader.LoggedNodes(),
1760 ::testing::ElementsAre(
1761 configuration::GetNode(reader.logged_configuration(), pi1),
1762 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001763
1764 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1765
1766 std::unique_ptr<EventLoop> pi1_event_loop =
1767 log_reader_factory.MakeEventLoop("test", pi1);
1768 std::unique_ptr<EventLoop> pi2_event_loop =
1769 log_reader_factory.MakeEventLoop("test", pi2);
1770
1771 int pi1_ping_count = 30;
1772 int pi2_ping_count = 30;
1773 int pi1_pong_count = 30;
1774 int pi2_pong_count = 30;
1775
1776 // Confirm that the ping value matches.
1777 pi1_event_loop->MakeWatcher(
1778 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1779 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1780 << pi1_event_loop->context().monotonic_remote_time << " -> "
1781 << pi1_event_loop->context().monotonic_event_time;
1782 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1783
1784 ++pi1_ping_count;
1785 });
1786 pi2_event_loop->MakeWatcher(
1787 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1788 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1789 << pi2_event_loop->context().monotonic_remote_time << " -> "
1790 << pi2_event_loop->context().monotonic_event_time;
1791 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1792
1793 ++pi2_ping_count;
1794 });
1795
1796 // Confirm that the ping and pong counts both match, and the value also
1797 // matches.
1798 pi1_event_loop->MakeWatcher(
1799 "/test", [&pi1_event_loop, &pi1_ping_count,
1800 &pi1_pong_count](const examples::Pong &pong) {
1801 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1802 << pi1_event_loop->context().monotonic_remote_time << " -> "
1803 << pi1_event_loop->context().monotonic_event_time;
1804
1805 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1806 ++pi1_pong_count;
1807 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1808 });
1809 pi2_event_loop->MakeWatcher(
1810 "/test", [&pi2_event_loop, &pi2_ping_count,
1811 &pi2_pong_count](const examples::Pong &pong) {
1812 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1813 << pi2_event_loop->context().monotonic_remote_time << " -> "
1814 << pi2_event_loop->context().monotonic_event_time;
1815
1816 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1817 ++pi2_pong_count;
1818 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1819 });
1820
1821 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001822 EXPECT_EQ(pi1_ping_count, 6030);
1823 EXPECT_EQ(pi2_ping_count, 6030);
1824 EXPECT_EQ(pi1_pong_count, 6030);
1825 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001826
1827 reader.Deregister();
1828}
1829
Austin Schuh5212cad2020-09-09 23:12:09 -07001830// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001831TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001832 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001833 // Make a bunch of parts.
1834 {
1835 LoggerState pi1_logger = MakeLogger(pi1_);
1836 LoggerState pi2_logger = MakeLogger(pi2_);
1837
1838 event_loop_factory_.RunFor(chrono::milliseconds(95));
1839
1840 StartLogger(&pi1_logger);
1841 StartLogger(&pi2_logger);
1842
1843 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1844 }
1845
Austin Schuh11d43732020-09-21 17:28:30 -07001846 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001847 VerifyParts(sorted_parts);
1848}
Austin Schuh11d43732020-09-21 17:28:30 -07001849
Austin Schuh3bd4c402020-11-06 18:19:06 -08001850// Tests that we can sort a bunch of parts with an empty part. We should ignore
1851// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001852TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001853 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001854 // Make a bunch of parts.
1855 {
1856 LoggerState pi1_logger = MakeLogger(pi1_);
1857 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001858
Austin Schuh3bd4c402020-11-06 18:19:06 -08001859 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001860
Austin Schuh3bd4c402020-11-06 18:19:06 -08001861 StartLogger(&pi1_logger);
1862 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001863
Austin Schuh3bd4c402020-11-06 18:19:06 -08001864 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001865 }
1866
Austin Schuh3bd4c402020-11-06 18:19:06 -08001867 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001868 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001869
Austin Schuh3bd4c402020-11-06 18:19:06 -08001870 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1871 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001872
Austin Schuh3bd4c402020-11-06 18:19:06 -08001873 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1874 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001875}
1876
James Kuszmauldd0a5042021-10-28 23:38:04 -07001877// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08001878// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001879TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001880 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001881 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001882 // Make a bunch of parts.
1883 {
1884 LoggerState pi1_logger = MakeLogger(pi1_);
1885 LoggerState pi2_logger = MakeLogger(pi2_);
1886
1887 event_loop_factory_.RunFor(chrono::milliseconds(95));
1888
James Kuszmauldd0a5042021-10-28 23:38:04 -07001889 StartLogger(&pi1_logger);
1890 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001891
1892 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001893
1894 pi1_logger.AppendAllFilenames(&actual_filenames);
1895 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001896 }
1897
Austin Schuhbfe6c572022-01-27 20:48:20 -08001898 ASSERT_THAT(actual_filenames,
1899 ::testing::UnorderedElementsAreArray(logfiles_));
1900
Austin Schuh3bd4c402020-11-06 18:19:06 -08001901 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001902 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1903 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08001904 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08001905 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001906
1907 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001908 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001909 compressed_contents.substr(0, compressed_contents.size() - 100));
1910
1911 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1912 VerifyParts(sorted_parts);
1913}
Austin Schuh3bd4c402020-11-06 18:19:06 -08001914
Austin Schuh01b4c352020-09-21 23:09:39 -07001915// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001916TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001917 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001918 {
1919 LoggerState pi1_logger = MakeLogger(pi1_);
1920 LoggerState pi2_logger = MakeLogger(pi2_);
1921
1922 event_loop_factory_.RunFor(chrono::milliseconds(95));
1923
1924 StartLogger(&pi1_logger);
1925 StartLogger(&pi2_logger);
1926
1927 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1928 }
1929
Austin Schuh287d43d2020-12-04 20:19:33 -08001930 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001931
1932 // Remap just on pi1.
1933 reader.RemapLoggedChannel<aos::timing::Report>(
1934 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1935
1936 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1937 log_reader_factory.set_send_delay(chrono::microseconds(0));
1938
Austin Schuh1c227352021-09-17 12:53:54 -07001939 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1940 ASSERT_EQ(remapped_channels.size(), 1u);
1941 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1942 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1943
Austin Schuh01b4c352020-09-21 23:09:39 -07001944 reader.Register(&log_reader_factory);
1945
1946 const Node *pi1 =
1947 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1948 const Node *pi2 =
1949 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1950
1951 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1952 // else should have moved.
1953 std::unique_ptr<EventLoop> pi1_event_loop =
1954 log_reader_factory.MakeEventLoop("test", pi1);
1955 pi1_event_loop->SkipTimingReport();
1956 std::unique_ptr<EventLoop> full_pi1_event_loop =
1957 log_reader_factory.MakeEventLoop("test", pi1);
1958 full_pi1_event_loop->SkipTimingReport();
1959 std::unique_ptr<EventLoop> pi2_event_loop =
1960 log_reader_factory.MakeEventLoop("test", pi2);
1961 pi2_event_loop->SkipTimingReport();
1962
1963 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1964 "/aos");
1965 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1966 full_pi1_event_loop.get(), "/pi1/aos");
1967 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1968 pi1_event_loop.get(), "/original/aos");
1969 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1970 full_pi1_event_loop.get(), "/original/pi1/aos");
1971 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1972 "/aos");
1973
1974 log_reader_factory.Run();
1975
1976 EXPECT_EQ(pi1_timing_report.count(), 0u);
1977 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1978 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1979 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1980 EXPECT_NE(pi2_timing_report.count(), 0u);
1981
1982 reader.Deregister();
1983}
1984
Austin Schuh006a9f52021-04-07 16:24:18 -07001985// Tests that we can remap a forwarded channel as well.
1986TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1987 time_converter_.StartEqual();
1988 {
1989 LoggerState pi1_logger = MakeLogger(pi1_);
1990 LoggerState pi2_logger = MakeLogger(pi2_);
1991
1992 event_loop_factory_.RunFor(chrono::milliseconds(95));
1993
1994 StartLogger(&pi1_logger);
1995 StartLogger(&pi2_logger);
1996
1997 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1998 }
1999
2000 LogReader reader(SortParts(logfiles_));
2001
2002 reader.RemapLoggedChannel<examples::Ping>("/test");
2003
2004 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2005 log_reader_factory.set_send_delay(chrono::microseconds(0));
2006
2007 reader.Register(&log_reader_factory);
2008
2009 const Node *pi1 =
2010 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2011 const Node *pi2 =
2012 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2013
2014 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2015 // else should have moved.
2016 std::unique_ptr<EventLoop> pi1_event_loop =
2017 log_reader_factory.MakeEventLoop("test", pi1);
2018 pi1_event_loop->SkipTimingReport();
2019 std::unique_ptr<EventLoop> full_pi1_event_loop =
2020 log_reader_factory.MakeEventLoop("test", pi1);
2021 full_pi1_event_loop->SkipTimingReport();
2022 std::unique_ptr<EventLoop> pi2_event_loop =
2023 log_reader_factory.MakeEventLoop("test", pi2);
2024 pi2_event_loop->SkipTimingReport();
2025
2026 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2027 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2028 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2029 "/original/test");
2030 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2031 "/original/test");
2032
2033 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2034 pi1_original_ping_timestamp;
2035 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2036 pi1_ping_timestamp;
2037 if (!shared()) {
2038 pi1_original_ping_timestamp =
2039 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2040 pi1_event_loop.get(),
2041 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2042 pi1_ping_timestamp =
2043 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2044 pi1_event_loop.get(),
2045 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2046 }
2047
2048 log_reader_factory.Run();
2049
2050 EXPECT_EQ(pi1_ping.count(), 0u);
2051 EXPECT_EQ(pi2_ping.count(), 0u);
2052 EXPECT_NE(pi1_original_ping.count(), 0u);
2053 EXPECT_NE(pi2_original_ping.count(), 0u);
2054 if (!shared()) {
2055 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2056 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2057 }
2058
2059 reader.Deregister();
2060}
2061
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002062// Tests that we properly recreate forwarded timestamps when replaying a log.
2063// This should be enough that we can then re-run the logger and get a valid log
2064// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002065TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002066 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002067 {
2068 LoggerState pi1_logger = MakeLogger(pi1_);
2069 LoggerState pi2_logger = MakeLogger(pi2_);
2070
2071 event_loop_factory_.RunFor(chrono::milliseconds(95));
2072
2073 StartLogger(&pi1_logger);
2074 StartLogger(&pi2_logger);
2075
2076 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2077 }
2078
Austin Schuh287d43d2020-12-04 20:19:33 -08002079 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002080
2081 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2082 log_reader_factory.set_send_delay(chrono::microseconds(0));
2083
2084 // This sends out the fetched messages and advances time to the start of the
2085 // log file.
2086 reader.Register(&log_reader_factory);
2087
2088 const Node *pi1 =
2089 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2090 const Node *pi2 =
2091 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2092
2093 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2094 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2095 LOG(INFO) << "now pi1 "
2096 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2097 LOG(INFO) << "now pi2 "
2098 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2099
Austin Schuh07676622021-01-21 18:59:17 -08002100 EXPECT_THAT(reader.LoggedNodes(),
2101 ::testing::ElementsAre(
2102 configuration::GetNode(reader.logged_configuration(), pi1),
2103 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002104
2105 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2106
2107 std::unique_ptr<EventLoop> pi1_event_loop =
2108 log_reader_factory.MakeEventLoop("test", pi1);
2109 std::unique_ptr<EventLoop> pi2_event_loop =
2110 log_reader_factory.MakeEventLoop("test", pi2);
2111
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002112 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2113 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2114 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2115 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2116
2117 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2118 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2119 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2120 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2121
2122 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2123 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2124 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2125 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2126
2127 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2128 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2129 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2130 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2131
2132 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2133 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2134 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2135 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2136
2137 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2138 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2139 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2140 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2141
Austin Schuh969cd602021-01-03 00:09:45 -08002142 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002143 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002144
Austin Schuh61e973f2021-02-21 21:43:56 -08002145 for (std::pair<int, std::string> channel :
2146 shared()
2147 ? std::vector<
2148 std::pair<int, std::string>>{{-1,
2149 "/aos/remote_timestamps/pi2"}}
2150 : std::vector<std::pair<int, std::string>>{
2151 {pi1_timestamp_channel,
2152 "/aos/remote_timestamps/pi2/pi1/aos/"
2153 "aos-message_bridge-Timestamp"},
2154 {ping_timestamp_channel,
2155 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2156 pi1_event_loop->MakeWatcher(
2157 channel.second,
2158 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2159 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2160 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2161 &ping_on_pi2_fetcher, network_delay, send_delay,
2162 channel_index = channel.first](const RemoteMessage &header) {
2163 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2164 chrono::nanoseconds(header.monotonic_sent_time()));
2165 const aos::realtime_clock::time_point header_realtime_sent_time(
2166 chrono::nanoseconds(header.realtime_sent_time()));
2167 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2168 chrono::nanoseconds(header.monotonic_remote_time()));
2169 const aos::realtime_clock::time_point header_realtime_remote_time(
2170 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002171
Austin Schuh61e973f2021-02-21 21:43:56 -08002172 if (channel_index != -1) {
2173 ASSERT_EQ(channel_index, header.channel_index());
2174 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002175
Austin Schuh61e973f2021-02-21 21:43:56 -08002176 const Context *pi1_context = nullptr;
2177 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002178
Austin Schuh61e973f2021-02-21 21:43:56 -08002179 if (header.channel_index() == pi1_timestamp_channel) {
2180 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2181 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2182 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2183 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2184 } else if (header.channel_index() == ping_timestamp_channel) {
2185 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2186 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2187 pi1_context = &ping_on_pi1_fetcher.context();
2188 pi2_context = &ping_on_pi2_fetcher.context();
2189 } else {
2190 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2191 << configuration::CleanedChannelToString(
2192 pi1_event_loop->configuration()->channels()->Get(
2193 header.channel_index()));
2194 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002195
Austin Schuh61e973f2021-02-21 21:43:56 -08002196 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002197 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2198 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002199
Austin Schuh61e973f2021-02-21 21:43:56 -08002200 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2201 EXPECT_EQ(pi2_context->remote_queue_index,
2202 header.remote_queue_index());
2203 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002204
Austin Schuh61e973f2021-02-21 21:43:56 -08002205 EXPECT_EQ(pi2_context->monotonic_event_time,
2206 header_monotonic_sent_time);
2207 EXPECT_EQ(pi2_context->realtime_event_time,
2208 header_realtime_sent_time);
2209 EXPECT_EQ(pi2_context->realtime_remote_time,
2210 header_realtime_remote_time);
2211 EXPECT_EQ(pi2_context->monotonic_remote_time,
2212 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002213
Austin Schuh61e973f2021-02-21 21:43:56 -08002214 EXPECT_EQ(pi1_context->realtime_event_time,
2215 header_realtime_remote_time);
2216 EXPECT_EQ(pi1_context->monotonic_event_time,
2217 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002218
Austin Schuh61e973f2021-02-21 21:43:56 -08002219 // Time estimation isn't perfect, but we know the clocks were
2220 // identical when logged, so we know when this should have come back.
2221 // Confirm we got it when we expected.
2222 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2223 pi1_context->monotonic_event_time + 2 * network_delay +
2224 send_delay);
2225 });
2226 }
2227 for (std::pair<int, std::string> channel :
2228 shared()
2229 ? std::vector<
2230 std::pair<int, std::string>>{{-1,
2231 "/aos/remote_timestamps/pi1"}}
2232 : std::vector<std::pair<int, std::string>>{
2233 {pi2_timestamp_channel,
2234 "/aos/remote_timestamps/pi1/pi2/aos/"
2235 "aos-message_bridge-Timestamp"}}) {
2236 pi2_event_loop->MakeWatcher(
2237 channel.second,
2238 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2239 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2240 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2241 &pong_on_pi1_fetcher, network_delay, send_delay,
2242 channel_index = channel.first](const RemoteMessage &header) {
2243 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2244 chrono::nanoseconds(header.monotonic_sent_time()));
2245 const aos::realtime_clock::time_point header_realtime_sent_time(
2246 chrono::nanoseconds(header.realtime_sent_time()));
2247 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2248 chrono::nanoseconds(header.monotonic_remote_time()));
2249 const aos::realtime_clock::time_point header_realtime_remote_time(
2250 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002251
Austin Schuh61e973f2021-02-21 21:43:56 -08002252 if (channel_index != -1) {
2253 ASSERT_EQ(channel_index, header.channel_index());
2254 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002255
Austin Schuh61e973f2021-02-21 21:43:56 -08002256 const Context *pi2_context = nullptr;
2257 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002258
Austin Schuh61e973f2021-02-21 21:43:56 -08002259 if (header.channel_index() == pi2_timestamp_channel) {
2260 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2261 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2262 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2263 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2264 } else if (header.channel_index() == pong_timestamp_channel) {
2265 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2266 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2267 pi2_context = &pong_on_pi2_fetcher.context();
2268 pi1_context = &pong_on_pi1_fetcher.context();
2269 } else {
2270 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2271 << configuration::CleanedChannelToString(
2272 pi2_event_loop->configuration()->channels()->Get(
2273 header.channel_index()));
2274 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002275
Austin Schuh61e973f2021-02-21 21:43:56 -08002276 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002277 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2278 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002279
Austin Schuh61e973f2021-02-21 21:43:56 -08002280 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2281 EXPECT_EQ(pi1_context->remote_queue_index,
2282 header.remote_queue_index());
2283 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002284
Austin Schuh61e973f2021-02-21 21:43:56 -08002285 EXPECT_EQ(pi1_context->monotonic_event_time,
2286 header_monotonic_sent_time);
2287 EXPECT_EQ(pi1_context->realtime_event_time,
2288 header_realtime_sent_time);
2289 EXPECT_EQ(pi1_context->realtime_remote_time,
2290 header_realtime_remote_time);
2291 EXPECT_EQ(pi1_context->monotonic_remote_time,
2292 header_monotonic_remote_time);
2293
2294 EXPECT_EQ(pi2_context->realtime_event_time,
2295 header_realtime_remote_time);
2296 EXPECT_EQ(pi2_context->monotonic_event_time,
2297 header_monotonic_remote_time);
2298
2299 // Time estimation isn't perfect, but we know the clocks were
2300 // identical when logged, so we know when this should have come back.
2301 // Confirm we got it when we expected.
2302 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2303 pi2_context->monotonic_event_time + 2 * network_delay +
2304 send_delay);
2305 });
2306 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002307
2308 // And confirm we can re-create a log again, while checking the contents.
2309 {
2310 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002311 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002312 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002313 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002314
Austin Schuh25b46712021-01-03 00:04:38 -08002315 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2316 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002317
2318 log_reader_factory.Run();
2319 }
2320
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002321 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002322
2323 // And verify that we can run the LogReader over the relogged files without
2324 // hitting any fatal errors.
2325 {
2326 LogReader relogged_reader(SortParts(
2327 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2328 relogged_reader.Register();
2329
2330 relogged_reader.event_loop_factory()->Run();
2331 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002332}
2333
Austin Schuh315b96b2020-12-11 21:21:12 -08002334// Tests that we properly populate and extract the logger_start time by setting
2335// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002336TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002337 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002338 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002339 {
2340 LoggerState pi1_logger = MakeLogger(pi1_);
2341 LoggerState pi2_logger = MakeLogger(pi2_);
2342
Austin Schuh315b96b2020-12-11 21:21:12 -08002343 StartLogger(&pi1_logger);
2344 StartLogger(&pi2_logger);
2345
2346 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2347 }
2348
2349 for (const LogFile &log_file : SortParts(logfiles_)) {
2350 for (const LogParts &log_part : log_file.parts) {
2351 if (log_part.node == log_file.logger_node) {
2352 EXPECT_EQ(log_part.logger_monotonic_start_time,
2353 aos::monotonic_clock::min_time);
2354 EXPECT_EQ(log_part.logger_realtime_start_time,
2355 aos::realtime_clock::min_time);
2356 } else {
2357 const chrono::seconds offset = log_file.logger_node == "pi1"
2358 ? -chrono::seconds(1000)
2359 : chrono::seconds(1000);
2360 EXPECT_EQ(log_part.logger_monotonic_start_time,
2361 log_part.monotonic_start_time + offset);
2362 EXPECT_EQ(log_part.logger_realtime_start_time,
2363 log_file.realtime_start_time +
2364 (log_part.logger_monotonic_start_time -
2365 log_file.monotonic_start_time));
2366 }
2367 }
2368 }
2369}
2370
Austin Schuh6bb8a822021-03-31 23:04:39 -07002371// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002372TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002373 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2374 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002375 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002376 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002377 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2378 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2379 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2380 LoggerState pi1_logger = MakeLogger(pi1_);
2381 LoggerState pi2_logger = MakeLogger(pi2_);
2382
2383 StartLogger(&pi1_logger);
2384 StartLogger(&pi2_logger);
2385
2386 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2387 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2388 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2389 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2390 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2391 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2392 for (auto &file : logfiles_) {
2393 struct stat s;
2394 EXPECT_EQ(0, stat(file.c_str(), &s));
2395 }
2396}
2397
2398// Test that renaming the file base dies.
2399TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2400 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002401 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002402 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002403 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2404 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2405 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2406 LoggerState pi1_logger = MakeLogger(pi1_);
2407 StartLogger(&pi1_logger);
2408 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2409 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2410 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2411 "Rename of file base from");
2412}
2413
Austin Schuh8bd96322020-02-13 21:18:22 -08002414// TODO(austin): We can write a test which recreates a logfile and confirms that
2415// we get it back. That is the ultimate test.
2416
Austin Schuh315b96b2020-12-11 21:21:12 -08002417// Tests that we properly recreate forwarded timestamps when replaying a log.
2418// This should be enough that we can then re-run the logger and get a valid log
2419// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002420TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002421 std::vector<std::string> actual_filenames;
2422
Austin Schuh58646e22021-08-23 23:51:46 -07002423 const UUID pi1_boot0 = UUID::Random();
2424 const UUID pi2_boot0 = UUID::Random();
2425 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002426 {
Austin Schuh58646e22021-08-23 23:51:46 -07002427 CHECK_EQ(pi1_index_, 0u);
2428 CHECK_EQ(pi2_index_, 1u);
2429
2430 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2431 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2432 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2433
2434 time_converter_.AddNextTimestamp(
2435 distributed_clock::epoch(),
2436 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2437 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2438 time_converter_.AddNextTimestamp(
2439 distributed_clock::epoch() + reboot_time,
2440 {BootTimestamp::epoch() + reboot_time,
2441 BootTimestamp{
2442 .boot = 1,
2443 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2444 }
2445
2446 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002447 LoggerState pi1_logger = MakeLogger(pi1_);
2448
2449 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002450 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2451 pi1_boot0);
2452 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2453 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002454
2455 StartLogger(&pi1_logger);
2456
2457 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2458
Austin Schuh58646e22021-08-23 23:51:46 -07002459 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002460
2461 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002462 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2463 pi1_boot0);
2464 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2465 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002466
2467 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002468 }
2469
Austin Schuhbfe6c572022-01-27 20:48:20 -08002470 std::sort(actual_filenames.begin(), actual_filenames.end());
2471 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2472 ASSERT_THAT(actual_filenames,
2473 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2474
Austin Schuh72211ae2021-08-05 14:02:30 -07002475 // Confirm that our new oldest timestamps properly update as we reboot and
2476 // rotate.
2477 for (const std::string &file : pi1_reboot_logfiles_) {
2478 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2479 ReadHeader(file);
2480 CHECK(log_header);
2481 if (log_header->message().has_configuration()) {
2482 continue;
2483 }
2484
Austin Schuh58646e22021-08-23 23:51:46 -07002485 const monotonic_clock::time_point monotonic_start_time =
2486 monotonic_clock::time_point(
2487 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2488 const UUID source_node_boot_uuid = UUID::FromString(
2489 log_header->message().source_node_boot_uuid()->string_view());
2490
Austin Schuh72211ae2021-08-05 14:02:30 -07002491 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002492 // The remote message channel should rotate later and have more parts.
2493 // This only is true on the log files with shared remote messages.
2494 //
2495 // TODO(austin): I'm not the most thrilled with this test pattern... It
2496 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002497 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2498 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002499 switch (log_header->message().parts_index()) {
2500 case 0:
2501 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2502 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2503 break;
2504 case 1:
2505 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2506 ASSERT_EQ(monotonic_start_time,
2507 monotonic_clock::epoch() + chrono::seconds(1));
2508 break;
2509 case 2:
2510 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2511 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2512 break;
2513 case 3:
2514 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2515 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2516 chrono::nanoseconds(2322999462))
2517 << " on " << file;
2518 break;
2519 default:
2520 FAIL();
2521 break;
2522 }
2523 } else {
2524 switch (log_header->message().parts_index()) {
2525 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002526 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002527 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2528 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2529 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002530 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002531 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2532 ASSERT_EQ(monotonic_start_time,
2533 monotonic_clock::epoch() + chrono::seconds(1));
2534 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002535 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002536 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002537 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2538 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2539 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002540 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002541 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2542 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2543 chrono::nanoseconds(2322999462))
2544 << " on " << file;
2545 break;
2546 default:
2547 FAIL();
2548 break;
2549 }
Austin Schuh58646e22021-08-23 23:51:46 -07002550 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002551 continue;
2552 }
2553 SCOPED_TRACE(file);
2554 SCOPED_TRACE(aos::FlatbufferToJson(
2555 *log_header, {.multi_line = true, .max_vector_size = 100}));
2556 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2557 ASSERT_EQ(
2558 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2559 EXPECT_EQ(
2560 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2561 monotonic_clock::max_time.time_since_epoch().count());
2562 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2563 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2564 2u);
2565 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2566 monotonic_clock::max_time.time_since_epoch().count());
2567 ASSERT_TRUE(log_header->message()
2568 .has_oldest_remote_unreliable_monotonic_timestamps());
2569 ASSERT_EQ(log_header->message()
2570 .oldest_remote_unreliable_monotonic_timestamps()
2571 ->size(),
2572 2u);
2573 EXPECT_EQ(log_header->message()
2574 .oldest_remote_unreliable_monotonic_timestamps()
2575 ->Get(0),
2576 monotonic_clock::max_time.time_since_epoch().count());
2577 ASSERT_TRUE(log_header->message()
2578 .has_oldest_local_unreliable_monotonic_timestamps());
2579 ASSERT_EQ(log_header->message()
2580 .oldest_local_unreliable_monotonic_timestamps()
2581 ->size(),
2582 2u);
2583 EXPECT_EQ(log_header->message()
2584 .oldest_local_unreliable_monotonic_timestamps()
2585 ->Get(0),
2586 monotonic_clock::max_time.time_since_epoch().count());
2587
2588 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2589 monotonic_clock::time_point(chrono::nanoseconds(
2590 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2591 1)));
2592 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2593 monotonic_clock::time_point(chrono::nanoseconds(
2594 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2595 const monotonic_clock::time_point
2596 oldest_remote_unreliable_monotonic_timestamps =
2597 monotonic_clock::time_point(chrono::nanoseconds(
2598 log_header->message()
2599 .oldest_remote_unreliable_monotonic_timestamps()
2600 ->Get(1)));
2601 const monotonic_clock::time_point
2602 oldest_local_unreliable_monotonic_timestamps =
2603 monotonic_clock::time_point(chrono::nanoseconds(
2604 log_header->message()
2605 .oldest_local_unreliable_monotonic_timestamps()
2606 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002607 const monotonic_clock::time_point
2608 oldest_remote_reliable_monotonic_timestamps =
2609 monotonic_clock::time_point(chrono::nanoseconds(
2610 log_header->message()
2611 .oldest_remote_reliable_monotonic_timestamps()
2612 ->Get(1)));
2613 const monotonic_clock::time_point
2614 oldest_local_reliable_monotonic_timestamps =
2615 monotonic_clock::time_point(chrono::nanoseconds(
2616 log_header->message()
2617 .oldest_local_reliable_monotonic_timestamps()
2618 ->Get(1)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002619 switch (log_header->message().parts_index()) {
2620 case 0:
2621 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2622 monotonic_clock::max_time);
2623 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2624 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2625 monotonic_clock::max_time);
2626 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2627 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002628 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2629 monotonic_clock::max_time);
2630 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2631 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002632 break;
2633 case 1:
2634 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2635 monotonic_clock::time_point(chrono::microseconds(90200)));
2636 EXPECT_EQ(oldest_local_monotonic_timestamps,
2637 monotonic_clock::time_point(chrono::microseconds(90350)));
2638 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2639 monotonic_clock::time_point(chrono::microseconds(90200)));
2640 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2641 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002642 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2643 monotonic_clock::max_time);
2644 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2645 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002646 break;
2647 case 2:
2648 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08002649 monotonic_clock::time_point(chrono::microseconds(90200)))
2650 << file;
2651 EXPECT_EQ(oldest_local_monotonic_timestamps,
2652 monotonic_clock::time_point(chrono::microseconds(90350)))
2653 << file;
2654 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2655 monotonic_clock::time_point(chrono::microseconds(90200)))
2656 << file;
2657 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2658 monotonic_clock::time_point(chrono::microseconds(90350)))
2659 << file;
2660 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2661 monotonic_clock::time_point(chrono::microseconds(100000)))
2662 << file;
2663 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2664 monotonic_clock::time_point(chrono::microseconds(100150)))
2665 << file;
2666 break;
2667 case 3:
2668 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002669 monotonic_clock::time_point(chrono::milliseconds(1323) +
2670 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002671 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002672 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002673 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002674 monotonic_clock::time_point(chrono::milliseconds(1323) +
2675 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002676 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2677 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002678 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2679 monotonic_clock::max_time)
2680 << file;
2681 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2682 monotonic_clock::max_time)
2683 << file;
2684 break;
2685 case 4:
2686 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2687 monotonic_clock::time_point(chrono::milliseconds(1323) +
2688 chrono::microseconds(200)));
2689 EXPECT_EQ(oldest_local_monotonic_timestamps,
2690 monotonic_clock::time_point(chrono::microseconds(10100350)));
2691 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2692 monotonic_clock::time_point(chrono::milliseconds(1323) +
2693 chrono::microseconds(200)));
2694 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2695 monotonic_clock::time_point(chrono::microseconds(10100350)));
2696 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2697 monotonic_clock::time_point(chrono::microseconds(1423000)))
2698 << file;
2699 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2700 monotonic_clock::time_point(chrono::microseconds(10200150)))
2701 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07002702 break;
2703 default:
2704 FAIL();
2705 break;
2706 }
2707 }
2708
Austin Schuh315b96b2020-12-11 21:21:12 -08002709 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002710 {
2711 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002712
Austin Schuh58646e22021-08-23 23:51:46 -07002713 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2714 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002715
Austin Schuh58646e22021-08-23 23:51:46 -07002716 // This sends out the fetched messages and advances time to the start of
2717 // the log file.
2718 reader.Register(&log_reader_factory);
2719
2720 log_reader_factory.Run();
2721
2722 reader.Deregister();
2723 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002724}
2725
Austin Schuh5e14d842022-01-21 12:02:15 -08002726// Tests that we can sort a log which only has timestamps from the remote
2727// because the local message_bridge_client failed to connect.
2728TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
2729 const UUID pi1_boot0 = UUID::Random();
2730 const UUID pi2_boot0 = UUID::Random();
2731 const UUID pi2_boot1 = UUID::Random();
2732 {
2733 CHECK_EQ(pi1_index_, 0u);
2734 CHECK_EQ(pi2_index_, 1u);
2735
2736 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2737 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2738 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2739
2740 time_converter_.AddNextTimestamp(
2741 distributed_clock::epoch(),
2742 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2743 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2744 time_converter_.AddNextTimestamp(
2745 distributed_clock::epoch() + reboot_time,
2746 {BootTimestamp::epoch() + reboot_time,
2747 BootTimestamp{
2748 .boot = 1,
2749 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2750 }
2751 pi2_->Disconnect(pi1_->node());
2752
2753 std::vector<std::string> filenames;
2754 {
2755 LoggerState pi1_logger = MakeLogger(pi1_);
2756
2757 event_loop_factory_.RunFor(chrono::milliseconds(95));
2758 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2759 pi1_boot0);
2760 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2761 pi2_boot0);
2762
2763 StartLogger(&pi1_logger);
2764
2765 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2766
2767 VLOG(1) << "Reboot now!";
2768
2769 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2770 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2771 pi1_boot0);
2772 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2773 pi2_boot1);
2774 pi1_logger.AppendAllFilenames(&filenames);
2775 }
2776
Austin Schuhbfe6c572022-01-27 20:48:20 -08002777 std::sort(filenames.begin(), filenames.end());
2778
Austin Schuh5e14d842022-01-21 12:02:15 -08002779 // Confirm that our new oldest timestamps properly update as we reboot and
2780 // rotate.
2781 size_t timestamp_file_count = 0;
2782 for (const std::string &file : filenames) {
2783 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2784 ReadHeader(file);
2785 CHECK(log_header);
2786
2787 if (log_header->message().has_configuration()) {
2788 continue;
2789 }
2790
2791 const monotonic_clock::time_point monotonic_start_time =
2792 monotonic_clock::time_point(
2793 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2794 const UUID source_node_boot_uuid = UUID::FromString(
2795 log_header->message().source_node_boot_uuid()->string_view());
2796
2797 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2798 ASSERT_EQ(
2799 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2800 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2801 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2802 2u);
2803 ASSERT_TRUE(log_header->message()
2804 .has_oldest_remote_unreliable_monotonic_timestamps());
2805 ASSERT_EQ(log_header->message()
2806 .oldest_remote_unreliable_monotonic_timestamps()
2807 ->size(),
2808 2u);
2809 ASSERT_TRUE(log_header->message()
2810 .has_oldest_local_unreliable_monotonic_timestamps());
2811 ASSERT_EQ(log_header->message()
2812 .oldest_local_unreliable_monotonic_timestamps()
2813 ->size(),
2814 2u);
2815
2816 if (log_header->message().node()->name()->string_view() != "pi1") {
2817 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
2818 std::string::npos);
2819
2820 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2821 ReadNthMessage(file, 0);
2822 CHECK(msg);
2823
2824 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2825 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2826
2827 const monotonic_clock::time_point
2828 expected_oldest_local_monotonic_timestamps(
2829 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2830 const monotonic_clock::time_point
2831 expected_oldest_remote_monotonic_timestamps(
2832 chrono::nanoseconds(msg->message().monotonic_remote_time()));
2833
2834 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2835 monotonic_clock::min_time);
2836 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2837 monotonic_clock::min_time);
2838
2839 ++timestamp_file_count;
2840 // Since the log file is from the perspective of the other node,
2841 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2842 monotonic_clock::time_point(chrono::nanoseconds(
2843 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2844 0)));
2845 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2846 monotonic_clock::time_point(chrono::nanoseconds(
2847 log_header->message().oldest_local_monotonic_timestamps()->Get(
2848 0)));
2849 const monotonic_clock::time_point
2850 oldest_remote_unreliable_monotonic_timestamps =
2851 monotonic_clock::time_point(chrono::nanoseconds(
2852 log_header->message()
2853 .oldest_remote_unreliable_monotonic_timestamps()
2854 ->Get(0)));
2855 const monotonic_clock::time_point
2856 oldest_local_unreliable_monotonic_timestamps =
2857 monotonic_clock::time_point(chrono::nanoseconds(
2858 log_header->message()
2859 .oldest_local_unreliable_monotonic_timestamps()
2860 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002861 const monotonic_clock::time_point
2862 oldest_remote_reliable_monotonic_timestamps =
2863 monotonic_clock::time_point(chrono::nanoseconds(
2864 log_header->message()
2865 .oldest_remote_reliable_monotonic_timestamps()
2866 ->Get(0)));
2867 const monotonic_clock::time_point
2868 oldest_local_reliable_monotonic_timestamps =
2869 monotonic_clock::time_point(chrono::nanoseconds(
2870 log_header->message()
2871 .oldest_local_reliable_monotonic_timestamps()
2872 ->Get(0)));
Austin Schuh5e14d842022-01-21 12:02:15 -08002873
Austin Schuh01f3b392022-01-25 20:03:09 -08002874 const Channel *channel =
2875 event_loop_factory_.configuration()->channels()->Get(
2876 msg->message().channel_index());
2877 const Connection *connection = configuration::ConnectionToNode(
2878 channel, configuration::GetNode(
2879 event_loop_factory_.configuration(),
2880 log_header->message().node()->name()->string_view()));
2881
2882 const bool reliable = connection->time_to_live() == 0;
2883
2884 if (shared()) {
2885 // Confirm that the oldest timestamps match what we expect. Based on
2886 // what we are doing, we know that the oldest time is the first
2887 // message's time.
2888 //
2889 // This makes the test robust to both the split and combined config
2890 // tests.
2891 switch (log_header->message().parts_index()) {
2892 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08002893 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2894 expected_oldest_remote_monotonic_timestamps);
2895 EXPECT_EQ(oldest_local_monotonic_timestamps,
2896 expected_oldest_local_monotonic_timestamps);
2897 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002898 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2899 expected_oldest_remote_monotonic_timestamps);
2900 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2901 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08002902 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2903 monotonic_clock::max_time);
2904 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2905 monotonic_clock::max_time);
2906 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002907 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2908 monotonic_clock::max_time);
2909 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2910 monotonic_clock::max_time);
2911 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2912 expected_oldest_remote_monotonic_timestamps);
2913 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2914 expected_oldest_local_monotonic_timestamps);
2915 }
2916 break;
2917 case 1:
2918 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2919 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2920 EXPECT_EQ(oldest_local_monotonic_timestamps,
2921 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2922 if (reliable) {
2923 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2924 expected_oldest_remote_monotonic_timestamps);
2925 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2926 expected_oldest_local_monotonic_timestamps);
2927 EXPECT_EQ(
2928 oldest_remote_unreliable_monotonic_timestamps,
2929 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2930 EXPECT_EQ(
2931 oldest_local_unreliable_monotonic_timestamps,
2932 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2933 } else {
2934 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2935 monotonic_clock::max_time);
2936 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2937 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08002938 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2939 expected_oldest_remote_monotonic_timestamps);
2940 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2941 expected_oldest_local_monotonic_timestamps);
2942 }
2943 break;
2944 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002945 EXPECT_EQ(
2946 oldest_remote_monotonic_timestamps,
2947 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2948 EXPECT_EQ(
2949 oldest_local_monotonic_timestamps,
2950 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2951 if (reliable) {
2952 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2953 expected_oldest_remote_monotonic_timestamps);
2954 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2955 expected_oldest_local_monotonic_timestamps);
2956 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2957 monotonic_clock::max_time);
2958 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2959 monotonic_clock::max_time);
2960 } else {
2961 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2962 monotonic_clock::max_time);
2963 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2964 monotonic_clock::max_time);
2965 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2966 expected_oldest_remote_monotonic_timestamps);
2967 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2968 expected_oldest_local_monotonic_timestamps);
2969 }
2970 break;
2971
2972 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08002973 LOG(INFO) << "Shared";
2974 EXPECT_EQ(
2975 oldest_remote_monotonic_timestamps,
2976 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2977 EXPECT_EQ(
2978 oldest_local_monotonic_timestamps,
2979 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2980 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2981 expected_oldest_remote_monotonic_timestamps);
2982 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2983 expected_oldest_local_monotonic_timestamps);
2984 break;
2985 default:
2986 FAIL();
2987 break;
2988 }
2989
2990 switch (log_header->message().parts_index()) {
2991 case 0:
2992 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2993 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2994 break;
2995 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002996 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08002997 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2998 break;
2999 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003000 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3001 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3002 break;
3003 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003004 if (shared()) {
3005 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3006 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3007 LOG(INFO) << "Shared";
3008 break;
3009 }
3010 [[fallthrough]];
3011 default:
3012 FAIL();
3013 break;
3014 }
3015 } else {
3016 switch (log_header->message().parts_index()) {
3017 case 0:
3018 case 1:
3019 if (reliable) {
3020 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3021 monotonic_clock::max_time);
3022 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3023 monotonic_clock::max_time);
3024 } else {
3025 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3026 expected_oldest_remote_monotonic_timestamps);
3027 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3028 expected_oldest_local_monotonic_timestamps);
3029 }
3030 break;
3031 default:
3032 FAIL();
3033 break;
3034 }
3035
3036 switch (log_header->message().parts_index()) {
3037 case 0:
3038 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3039 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3040 break;
3041 case 1:
3042 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3043 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3044 break;
3045 default:
3046 FAIL();
3047 break;
3048 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003049 }
3050
3051 continue;
3052 }
3053 EXPECT_EQ(
3054 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3055 monotonic_clock::max_time.time_since_epoch().count());
3056 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3057 monotonic_clock::max_time.time_since_epoch().count());
3058 EXPECT_EQ(log_header->message()
3059 .oldest_remote_unreliable_monotonic_timestamps()
3060 ->Get(0),
3061 monotonic_clock::max_time.time_since_epoch().count());
3062 EXPECT_EQ(log_header->message()
3063 .oldest_local_unreliable_monotonic_timestamps()
3064 ->Get(0),
3065 monotonic_clock::max_time.time_since_epoch().count());
3066
3067 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3068 monotonic_clock::time_point(chrono::nanoseconds(
3069 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3070 1)));
3071 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3072 monotonic_clock::time_point(chrono::nanoseconds(
3073 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3074 const monotonic_clock::time_point
3075 oldest_remote_unreliable_monotonic_timestamps =
3076 monotonic_clock::time_point(chrono::nanoseconds(
3077 log_header->message()
3078 .oldest_remote_unreliable_monotonic_timestamps()
3079 ->Get(1)));
3080 const monotonic_clock::time_point
3081 oldest_local_unreliable_monotonic_timestamps =
3082 monotonic_clock::time_point(chrono::nanoseconds(
3083 log_header->message()
3084 .oldest_local_unreliable_monotonic_timestamps()
3085 ->Get(1)));
3086 switch (log_header->message().parts_index()) {
3087 case 0:
3088 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3089 monotonic_clock::max_time);
3090 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3091 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3092 monotonic_clock::max_time);
3093 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3094 monotonic_clock::max_time);
3095 break;
3096 default:
3097 FAIL();
3098 break;
3099 }
3100 }
3101
Austin Schuh01f3b392022-01-25 20:03:09 -08003102 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003103 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003104 } else {
3105 EXPECT_EQ(timestamp_file_count, 4u);
3106 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003107
Austin Schuhe2373e22022-01-21 12:25:17 -08003108 // Confirm that we can actually sort the resulting log and read it.
3109 {
3110 LogReader reader(SortParts(filenames));
3111
3112 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3113 log_reader_factory.set_send_delay(chrono::microseconds(0));
3114
3115 // This sends out the fetched messages and advances time to the start of
3116 // the log file.
3117 reader.Register(&log_reader_factory);
3118
3119 log_reader_factory.Run();
3120
3121 reader.Deregister();
3122 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003123}
3124
Austin Schuhc9049732020-12-21 22:27:15 -08003125// Tests that we properly handle one direction of message_bridge being
3126// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003127TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003128 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003129 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003130 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003131
3132 time_converter_.AddMonotonic(
3133 {chrono::milliseconds(10000),
3134 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003135 {
3136 LoggerState pi1_logger = MakeLogger(pi1_);
3137
3138 event_loop_factory_.RunFor(chrono::milliseconds(95));
3139
3140 StartLogger(&pi1_logger);
3141
3142 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3143 }
3144
3145 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3146 // to confirm the right thing happened.
3147 ConfirmReadable(pi1_single_direction_logfiles_);
3148}
3149
3150// Tests that we properly handle one direction of message_bridge being
3151// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003152TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003153 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003154 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003155 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003156
3157 time_converter_.AddMonotonic(
3158 {chrono::milliseconds(10000),
3159 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3160 {
3161 LoggerState pi1_logger = MakeLogger(pi1_);
3162
3163 event_loop_factory_.RunFor(chrono::milliseconds(95));
3164
3165 StartLogger(&pi1_logger);
3166
3167 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3168 }
3169
3170 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3171 // to confirm the right thing happened.
3172 ConfirmReadable(pi1_single_direction_logfiles_);
3173}
3174
Austin Schuhe9f00232021-09-16 18:04:23 -07003175// Tests that we explode if someone passes in a part file twice with a better
3176// error than an out of order error.
3177TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3178 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003179 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003180 {
3181 LoggerState pi1_logger = MakeLogger(pi1_);
3182
3183 event_loop_factory_.RunFor(chrono::milliseconds(95));
3184
3185 StartLogger(&pi1_logger);
3186
3187 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3188 }
3189
3190 std::vector<std::string> duplicates;
3191 for (const std::string &f : pi1_single_direction_logfiles_) {
3192 duplicates.emplace_back(f);
3193 duplicates.emplace_back(f);
3194 }
3195 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3196}
3197
Austin Schuh87dd3832021-01-01 23:07:31 -08003198// Tests that we properly handle a dead node. Do this by just disconnecting it
3199// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003200TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003201 pi1_->Disconnect(pi2_->node());
3202 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003203 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003204 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003205 {
3206 LoggerState pi1_logger = MakeLogger(pi1_);
3207
3208 event_loop_factory_.RunFor(chrono::milliseconds(95));
3209
3210 StartLogger(&pi1_logger);
3211
3212 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3213 }
3214
3215 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3216 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003217 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003218}
3219
Austin Schuhcdd90272021-03-15 12:46:16 -07003220constexpr std::string_view kCombinedConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08003221 "b8114cd99e9c606b7517d8f478bf16513aef550f23f317720667314cb261f689");
Austin Schuhcdd90272021-03-15 12:46:16 -07003222constexpr std::string_view kSplitConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08003223 "60943d0a46afa6028c8ae276e7b4900b35892f1f53b1818056e7d04463709c5b");
Austin Schuhcdd90272021-03-15 12:46:16 -07003224
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003225INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003226 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003227 ::testing::Combine(::testing::Values(
3228 ConfigParams{
3229 "multinode_pingpong_combined_config.json", true,
3230 kCombinedConfigSha1},
3231 ConfigParams{"multinode_pingpong_split_config.json",
3232 false, kSplitConfigSha1}),
3233 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003234
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003235INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003236 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003237 ::testing::Combine(::testing::Values(
3238 ConfigParams{
3239 "multinode_pingpong_combined_config.json", true,
3240 kCombinedConfigSha1},
3241 ConfigParams{"multinode_pingpong_split_config.json",
3242 false, kSplitConfigSha1}),
3243 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003244
Austin Schuh5b728b72021-06-16 14:57:15 -07003245// Tests that we can relog with a different config. This makes most sense when
3246// you are trying to edit a log and want to use channel renaming + the original
3247// config in the new log.
3248TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3249 time_converter_.StartEqual();
3250 {
3251 LoggerState pi1_logger = MakeLogger(pi1_);
3252 LoggerState pi2_logger = MakeLogger(pi2_);
3253
3254 event_loop_factory_.RunFor(chrono::milliseconds(95));
3255
3256 StartLogger(&pi1_logger);
3257 StartLogger(&pi2_logger);
3258
3259 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3260 }
3261
3262 LogReader reader(SortParts(logfiles_));
3263 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3264
3265 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3266 log_reader_factory.set_send_delay(chrono::microseconds(0));
3267
3268 // This sends out the fetched messages and advances time to the start of the
3269 // log file.
3270 reader.Register(&log_reader_factory);
3271
3272 const Node *pi1 =
3273 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3274 const Node *pi2 =
3275 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3276
3277 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3278 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3279 LOG(INFO) << "now pi1 "
3280 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3281 LOG(INFO) << "now pi2 "
3282 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3283
3284 EXPECT_THAT(reader.LoggedNodes(),
3285 ::testing::ElementsAre(
3286 configuration::GetNode(reader.logged_configuration(), pi1),
3287 configuration::GetNode(reader.logged_configuration(), pi2)));
3288
3289 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3290
3291 // And confirm we can re-create a log again, while checking the contents.
3292 std::vector<std::string> log_files;
3293 {
3294 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003295 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003296 &log_reader_factory, reader.logged_configuration());
3297 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003298 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003299 &log_reader_factory, reader.logged_configuration());
3300
Austin Schuh3e20c692021-11-16 20:43:16 -08003301 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3302 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003303
3304 log_reader_factory.Run();
3305
3306 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3307 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3308 }
3309 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3310 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3311 }
3312 }
3313
3314 reader.Deregister();
3315
3316 // And verify that we can run the LogReader over the relogged files without
3317 // hitting any fatal errors.
3318 {
3319 LogReader relogged_reader(SortParts(log_files));
3320 relogged_reader.Register();
3321
3322 relogged_reader.event_loop_factory()->Run();
3323 }
3324}
Austin Schuha04efed2021-01-24 18:04:20 -08003325
Austin Schuh3e20c692021-11-16 20:43:16 -08003326// Tests that we properly replay a log where the start time for a node is before
3327// any data on the node. This can happen if the logger starts before data is
3328// published. While the scenario below is a bit convoluted, we have seen logs
3329// like this generated out in the wild.
3330TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3331 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3332 aos::configuration::ReadConfig(ArtifactPath(
3333 "aos/events/logging/multinode_pingpong_split3_config.json"));
3334 message_bridge::TestingTimeConverter time_converter(
3335 configuration::NodesCount(&config.message()));
3336 SimulatedEventLoopFactory event_loop_factory(&config.message());
3337 event_loop_factory.SetTimeConverter(&time_converter);
3338 NodeEventLoopFactory *const pi1 =
3339 event_loop_factory.GetNodeEventLoopFactory("pi1");
3340 const size_t pi1_index = configuration::GetNodeIndex(
3341 event_loop_factory.configuration(), pi1->node());
3342 NodeEventLoopFactory *const pi2 =
3343 event_loop_factory.GetNodeEventLoopFactory("pi2");
3344 const size_t pi2_index = configuration::GetNodeIndex(
3345 event_loop_factory.configuration(), pi2->node());
3346 NodeEventLoopFactory *const pi3 =
3347 event_loop_factory.GetNodeEventLoopFactory("pi3");
3348 const size_t pi3_index = configuration::GetNodeIndex(
3349 event_loop_factory.configuration(), pi3->node());
3350
3351 const std::string kLogfile1_1 =
3352 aos::testing::TestTmpDir() + "/multi_logfile1/";
3353 const std::string kLogfile2_1 =
3354 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3355 const std::string kLogfile2_2 =
3356 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3357 const std::string kLogfile3_1 =
3358 aos::testing::TestTmpDir() + "/multi_logfile3/";
3359 util::UnlinkRecursive(kLogfile1_1);
3360 util::UnlinkRecursive(kLogfile2_1);
3361 util::UnlinkRecursive(kLogfile2_2);
3362 util::UnlinkRecursive(kLogfile3_1);
3363 const UUID pi1_boot0 = UUID::Random();
3364 const UUID pi2_boot0 = UUID::Random();
3365 const UUID pi2_boot1 = UUID::Random();
3366 const UUID pi3_boot0 = UUID::Random();
3367 {
3368 CHECK_EQ(pi1_index, 0u);
3369 CHECK_EQ(pi2_index, 1u);
3370 CHECK_EQ(pi3_index, 2u);
3371
3372 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3373 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3374 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3375 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3376
3377 time_converter.AddNextTimestamp(
3378 distributed_clock::epoch(),
3379 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3380 BootTimestamp::epoch()});
3381 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3382 time_converter.AddNextTimestamp(
3383 distributed_clock::epoch() + reboot_time,
3384 {BootTimestamp::epoch() + reboot_time,
3385 BootTimestamp{
3386 .boot = 1,
3387 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3388 BootTimestamp::epoch() + reboot_time});
3389 }
3390
3391 // Make everything perfectly quiet.
3392 event_loop_factory.SkipTimingReport();
3393 event_loop_factory.DisableStatistics();
3394
3395 std::vector<std::string> filenames;
3396 {
3397 LoggerState pi1_logger = LoggerState::MakeLogger(
3398 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3399 LoggerState pi3_logger = LoggerState::MakeLogger(
3400 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3401 {
3402 // And now start the logger.
3403 LoggerState pi2_logger = LoggerState::MakeLogger(
3404 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3405
3406 event_loop_factory.RunFor(chrono::milliseconds(1000));
3407
3408 pi1_logger.StartLogger(kLogfile1_1);
3409 pi3_logger.StartLogger(kLogfile3_1);
3410 pi2_logger.StartLogger(kLogfile2_1);
3411
3412 event_loop_factory.RunFor(chrono::milliseconds(10000));
3413
3414 // Now that we've got a start time in the past, turn on data.
3415 event_loop_factory.EnableStatistics();
3416 std::unique_ptr<aos::EventLoop> ping_event_loop =
3417 pi1->MakeEventLoop("ping");
3418 Ping ping(ping_event_loop.get());
3419
3420 pi2->AlwaysStart<Pong>("pong");
3421
3422 event_loop_factory.RunFor(chrono::milliseconds(3000));
3423
3424 pi2_logger.AppendAllFilenames(&filenames);
3425
3426 // Stop logging on pi2 before rebooting and completely shut off all
3427 // messages on pi2.
3428 pi2->DisableStatistics();
3429 pi1->Disconnect(pi2->node());
3430 pi2->Disconnect(pi1->node());
3431 }
3432 event_loop_factory.RunFor(chrono::milliseconds(7000));
3433 // pi2 now reboots.
3434 {
3435 event_loop_factory.RunFor(chrono::milliseconds(1000));
3436
3437 // Start logging again on pi2 after it is up.
3438 LoggerState pi2_logger = LoggerState::MakeLogger(
3439 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3440 pi2_logger.StartLogger(kLogfile2_2);
3441
3442 event_loop_factory.RunFor(chrono::milliseconds(10000));
3443 // And, now that we have a start time in the log, turn data back on.
3444 pi2->EnableStatistics();
3445 pi1->Connect(pi2->node());
3446 pi2->Connect(pi1->node());
3447
3448 pi2->AlwaysStart<Pong>("pong");
3449 std::unique_ptr<aos::EventLoop> ping_event_loop =
3450 pi1->MakeEventLoop("ping");
3451 Ping ping(ping_event_loop.get());
3452
3453 event_loop_factory.RunFor(chrono::milliseconds(3000));
3454
3455 pi2_logger.AppendAllFilenames(&filenames);
3456 }
3457
3458 pi1_logger.AppendAllFilenames(&filenames);
3459 pi3_logger.AppendAllFilenames(&filenames);
3460 }
3461
3462 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3463 // to confirm the right thing happened.
3464 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3465 ConfirmReadable(filenames);
3466}
3467
Austin Schuh5dd22842021-11-17 16:09:39 -08003468// Tests that local data before remote data after reboot is properly replayed.
3469// We only trigger a reboot in the timestamp interpolation function when solving
3470// the timestamp problem when we actually have a point in the function. This
3471// originally only happened when a point passes the noncausal filter. At the
3472// start of time for the second boot, if we aren't careful, we will have
3473// messages which need to be published at times before the boot. This happens
3474// when a local message is in the log before a forwarded message, so there is no
3475// point in the interpolation function. This delays the reboot. So, we need to
3476// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08003477TEST(MultinodeRebootLoggerTest,
3478 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08003479 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3480 aos::configuration::ReadConfig(ArtifactPath(
3481 "aos/events/logging/multinode_pingpong_split3_config.json"));
3482 message_bridge::TestingTimeConverter time_converter(
3483 configuration::NodesCount(&config.message()));
3484 SimulatedEventLoopFactory event_loop_factory(&config.message());
3485 event_loop_factory.SetTimeConverter(&time_converter);
3486 NodeEventLoopFactory *const pi1 =
3487 event_loop_factory.GetNodeEventLoopFactory("pi1");
3488 const size_t pi1_index = configuration::GetNodeIndex(
3489 event_loop_factory.configuration(), pi1->node());
3490 NodeEventLoopFactory *const pi2 =
3491 event_loop_factory.GetNodeEventLoopFactory("pi2");
3492 const size_t pi2_index = configuration::GetNodeIndex(
3493 event_loop_factory.configuration(), pi2->node());
3494 NodeEventLoopFactory *const pi3 =
3495 event_loop_factory.GetNodeEventLoopFactory("pi3");
3496 const size_t pi3_index = configuration::GetNodeIndex(
3497 event_loop_factory.configuration(), pi3->node());
3498
3499 const std::string kLogfile1_1 =
3500 aos::testing::TestTmpDir() + "/multi_logfile1/";
3501 const std::string kLogfile2_1 =
3502 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3503 const std::string kLogfile2_2 =
3504 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3505 const std::string kLogfile3_1 =
3506 aos::testing::TestTmpDir() + "/multi_logfile3/";
3507 util::UnlinkRecursive(kLogfile1_1);
3508 util::UnlinkRecursive(kLogfile2_1);
3509 util::UnlinkRecursive(kLogfile2_2);
3510 util::UnlinkRecursive(kLogfile3_1);
3511 const UUID pi1_boot0 = UUID::Random();
3512 const UUID pi2_boot0 = UUID::Random();
3513 const UUID pi2_boot1 = UUID::Random();
3514 const UUID pi3_boot0 = UUID::Random();
3515 {
3516 CHECK_EQ(pi1_index, 0u);
3517 CHECK_EQ(pi2_index, 1u);
3518 CHECK_EQ(pi3_index, 2u);
3519
3520 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3521 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3522 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3523 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3524
3525 time_converter.AddNextTimestamp(
3526 distributed_clock::epoch(),
3527 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3528 BootTimestamp::epoch()});
3529 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3530 time_converter.AddNextTimestamp(
3531 distributed_clock::epoch() + reboot_time,
3532 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003533 BootTimestamp{.boot = 1,
3534 .time = monotonic_clock::epoch() + reboot_time +
3535 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08003536 BootTimestamp::epoch() + reboot_time});
3537 }
3538
3539 std::vector<std::string> filenames;
3540 {
3541 LoggerState pi1_logger = LoggerState::MakeLogger(
3542 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3543 LoggerState pi3_logger = LoggerState::MakeLogger(
3544 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3545 {
3546 // And now start the logger.
3547 LoggerState pi2_logger = LoggerState::MakeLogger(
3548 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3549
3550 pi1_logger.StartLogger(kLogfile1_1);
3551 pi3_logger.StartLogger(kLogfile3_1);
3552 pi2_logger.StartLogger(kLogfile2_1);
3553
3554 event_loop_factory.RunFor(chrono::milliseconds(1005));
3555
3556 // Now that we've got a start time in the past, turn on data.
3557 std::unique_ptr<aos::EventLoop> ping_event_loop =
3558 pi1->MakeEventLoop("ping");
3559 Ping ping(ping_event_loop.get());
3560
3561 pi2->AlwaysStart<Pong>("pong");
3562
3563 event_loop_factory.RunFor(chrono::milliseconds(3000));
3564
3565 pi2_logger.AppendAllFilenames(&filenames);
3566
3567 // Disable any remote messages on pi2.
3568 pi1->Disconnect(pi2->node());
3569 pi2->Disconnect(pi1->node());
3570 }
3571 event_loop_factory.RunFor(chrono::milliseconds(995));
3572 // pi2 now reboots at 5 seconds.
3573 {
3574 event_loop_factory.RunFor(chrono::milliseconds(1000));
3575
3576 // Make local stuff happen before we start logging and connect the remote.
3577 pi2->AlwaysStart<Pong>("pong");
3578 std::unique_ptr<aos::EventLoop> ping_event_loop =
3579 pi1->MakeEventLoop("ping");
3580 Ping ping(ping_event_loop.get());
3581 event_loop_factory.RunFor(chrono::milliseconds(1005));
3582
3583 // Start logging again on pi2 after it is up.
3584 LoggerState pi2_logger = LoggerState::MakeLogger(
3585 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3586 pi2_logger.StartLogger(kLogfile2_2);
3587
3588 // And allow remote messages now that we have some local ones.
3589 pi1->Connect(pi2->node());
3590 pi2->Connect(pi1->node());
3591
3592 event_loop_factory.RunFor(chrono::milliseconds(1000));
3593
3594 event_loop_factory.RunFor(chrono::milliseconds(3000));
3595
3596 pi2_logger.AppendAllFilenames(&filenames);
3597 }
3598
3599 pi1_logger.AppendAllFilenames(&filenames);
3600 pi3_logger.AppendAllFilenames(&filenames);
3601 }
3602
3603 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3604 // to confirm the right thing happened.
3605 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3606 ConfirmReadable(filenames);
3607}
3608
3609
Austin Schuhe309d2a2019-11-29 13:25:21 -08003610} // namespace testing
3611} // namespace logger
3612} // namespace aos