blob: 6d828c9b76c51f78dbec8f41fb99c56ae357afa0 [file] [log] [blame]
Austin Schuh6bb8a822021-03-31 23:04:39 -07001#include <sys/stat.h>
2
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07005#include "aos/events/logging/log_reader.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08006#include "aos/events/logging/log_writer.h"
milind1f1dca32021-07-03 13:50:07 -07007#include "aos/events/logging/snappy_encoder.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
milind1f1dca32021-07-03 13:50:07 -0700171 logger_event_loop->OnRun([base_name1, base_name2, &logger_event_loop,
172 &logger]() {
173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
175 EXPECT_DEATH(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 logger.StartLogging(std::make_unique<LocalLogNamer>(
milind1f1dca32021-07-03 13:50:07 -0700177 base_name2, logger_event_loop.get(), logger_event_loop->node())),
178 "Already logging");
179 });
Brian Silverman1f345222020-09-24 21:14:48 -0700180 event_loop_factory_.RunFor(chrono::milliseconds(20000));
181 }
182}
183
184// Tests calling StopLogging twice.
185TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800186 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700187 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800188 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700189 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700190 const ::std::string logfile = base_name + ".part0.bfbs";
191 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800192 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700193 unlink(logfile.c_str());
194
195 LOG(INFO) << "Logging data to " << logfile;
196
197 {
198 std::unique_ptr<EventLoop> logger_event_loop =
199 event_loop_factory_.MakeEventLoop("logger");
200
201 event_loop_factory_.RunFor(chrono::milliseconds(95));
202
203 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800204 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700205 logger.set_polling_period(std::chrono::milliseconds(100));
206 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700207 logger.StartLogging(std::make_unique<LocalLogNamer>(
208 base_name, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700209 logger.StopLogging(aos::monotonic_clock::min_time);
210 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
211 "Not logging right now");
212 });
213 event_loop_factory_.RunFor(chrono::milliseconds(20000));
214 }
215}
216
217// Tests that we can startup twice.
218TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800219 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700220 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800221 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700222 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700223 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
224 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800225 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700226 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700227 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
228 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800229 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700230 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800231 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700232
233 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
234
235 {
236 std::unique_ptr<EventLoop> logger_event_loop =
237 event_loop_factory_.MakeEventLoop("logger");
238
239 event_loop_factory_.RunFor(chrono::milliseconds(95));
240
241 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800242 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700243 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh5b728b72021-06-16 14:57:15 -0700244 logger.StartLogging(std::make_unique<LocalLogNamer>(
245 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700246 event_loop_factory_.RunFor(chrono::milliseconds(10000));
247 logger.StopLogging(logger_event_loop->monotonic_now());
248 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh5b728b72021-06-16 14:57:15 -0700249 logger.StartLogging(std::make_unique<LocalLogNamer>(
250 base_name2, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700251 event_loop_factory_.RunFor(chrono::milliseconds(10000));
252 }
253
254 for (const auto &logfile :
255 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
256 SCOPED_TRACE(std::get<0>(logfile));
257 LogReader reader(std::get<0>(logfile));
258 reader.Register();
259
Austin Schuh07676622021-01-21 18:59:17 -0800260 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700261
262 std::unique_ptr<EventLoop> test_event_loop =
263 reader.event_loop_factory()->MakeEventLoop("log_reader");
264
265 int ping_count = std::get<1>(logfile);
266 int pong_count = std::get<1>(logfile);
267
268 // Confirm that the ping and pong counts both match, and the value also
269 // matches.
270 test_event_loop->MakeWatcher("/test",
271 [&ping_count](const examples::Ping &ping) {
272 EXPECT_EQ(ping.value(), ping_count + 1);
273 ++ping_count;
274 });
275 test_event_loop->MakeWatcher(
276 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
277 EXPECT_EQ(pong.value(), pong_count + 1);
278 ++pong_count;
279 EXPECT_EQ(ping_count, pong_count);
280 });
281
282 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
283 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
284 }
285}
286
Austin Schuhfa895892020-01-07 20:07:41 -0800287// Tests that we can read and write rotated log files.
288TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800289 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700290 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800291 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700292 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700293 const ::std::string logfile0 = base_name + ".part0.bfbs";
294 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800295 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800296 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800297 unlink(logfile0.c_str());
298 unlink(logfile1.c_str());
299
300 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
301
302 {
Austin Schuhfa895892020-01-07 20:07:41 -0800303 std::unique_ptr<EventLoop> logger_event_loop =
304 event_loop_factory_.MakeEventLoop("logger");
305
306 event_loop_factory_.RunFor(chrono::milliseconds(95));
307
Brian Silverman1f345222020-09-24 21:14:48 -0700308 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800309 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700310 logger.set_polling_period(std::chrono::milliseconds(100));
311 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800312 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700313 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800314 event_loop_factory_.RunFor(chrono::milliseconds(10000));
315 }
316
Austin Schuh64fab802020-09-09 22:47:47 -0700317 {
318 // Confirm that the UUIDs match for both the parts and the logger, and the
319 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800320 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700321 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800322 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700323 }
324
Brian Silvermanae7c0332020-09-30 16:58:23 -0700325 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
326 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700327 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
328 log_header[1].message().parts_uuid()->string_view());
329
330 EXPECT_EQ(log_header[0].message().parts_index(), 0);
331 EXPECT_EQ(log_header[1].message().parts_index(), 1);
332 }
333
Austin Schuhfa895892020-01-07 20:07:41 -0800334 // Even though it doesn't make any difference here, exercise the logic for
335 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800336 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800337
338 // Confirm that we can remap logged channels to point to new buses.
339 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
340
341 // This sends out the fetched messages and advances time to the start of the
342 // log file.
343 reader.Register();
344
Austin Schuh07676622021-01-21 18:59:17 -0800345 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800346
347 std::unique_ptr<EventLoop> test_event_loop =
348 reader.event_loop_factory()->MakeEventLoop("log_reader");
349
350 int ping_count = 10;
351 int pong_count = 10;
352
353 // Confirm that the ping value matches in the remapped channel location.
354 test_event_loop->MakeWatcher("/original/test",
355 [&ping_count](const examples::Ping &ping) {
356 EXPECT_EQ(ping.value(), ping_count + 1);
357 ++ping_count;
358 });
359 // Confirm that the ping and pong counts both match, and the value also
360 // matches.
361 test_event_loop->MakeWatcher(
362 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
363 EXPECT_EQ(pong.value(), pong_count + 1);
364 ++pong_count;
365 EXPECT_EQ(ping_count, pong_count);
366 });
367
368 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
369 EXPECT_EQ(ping_count, 2010);
370}
371
Austin Schuh4c4e0092019-12-22 16:18:03 -0800372// Tests that a large number of messages per second doesn't overwhelm writev.
373TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800374 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700375 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800376 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700377 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700378 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800379 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800380 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800381 unlink(logfile.c_str());
382
383 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700384 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800385
386 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800387 std::unique_ptr<EventLoop> logger_event_loop =
388 event_loop_factory_.MakeEventLoop("logger");
389
390 std::unique_ptr<EventLoop> ping_spammer_event_loop =
391 event_loop_factory_.MakeEventLoop("ping_spammer");
392 aos::Sender<examples::Ping> ping_sender =
393 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
394
395 aos::TimerHandler *timer_handler =
396 ping_spammer_event_loop->AddTimer([&ping_sender]() {
397 aos::Sender<examples::Ping>::Builder builder =
398 ping_sender.MakeBuilder();
399 examples::Ping::Builder ping_builder =
400 builder.MakeBuilder<examples::Ping>();
Austin Schuhbfe6c572022-01-27 20:48:20 -0800401 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800402 });
403
404 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
405 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
406 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
407 chrono::microseconds(50));
408 });
409
Brian Silverman1f345222020-09-24 21:14:48 -0700410 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800411 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700412 logger.set_polling_period(std::chrono::milliseconds(100));
413 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800414
415 event_loop_factory_.RunFor(chrono::milliseconds(1000));
416 }
417}
418
James Kuszmaul890c2492022-04-06 14:59:31 -0700419// Tests that we can read a logfile that has channels which were sent too fast.
420TEST(SingleNodeLoggerNoFixtureTest, ReadTooFast) {
421 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
422 aos::configuration::ReadConfig(
423 ArtifactPath("aos/events/pingpong_config.json"));
424 SimulatedEventLoopFactory event_loop_factory(&config.message());
425 const ::std::string tmpdir = aos::testing::TestTmpDir();
426 const ::std::string base_name = tmpdir + "/logfile";
427 const ::std::string config_file =
428 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
429 const ::std::string logfile = base_name + ".part0.bfbs";
430 // Remove the log file.
431 unlink(config_file.c_str());
432 unlink(logfile.c_str());
433
434 LOG(INFO) << "Logging data to " << logfile;
435
436 int sent_messages = 0;
437
438 {
439 std::unique_ptr<EventLoop> logger_event_loop =
440 event_loop_factory.MakeEventLoop("logger");
441
442 std::unique_ptr<EventLoop> ping_spammer_event_loop =
443 event_loop_factory.GetNodeEventLoopFactory(nullptr)->MakeEventLoop(
444 "ping_spammer", {NodeEventLoopFactory::CheckSentTooFast::kNo,
445 NodeEventLoopFactory::ExclusiveSenders::kNo});
446 aos::Sender<examples::Ping> ping_sender =
447 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
448
449 aos::TimerHandler *timer_handler =
450 ping_spammer_event_loop->AddTimer([&ping_sender, &sent_messages]() {
451 aos::Sender<examples::Ping>::Builder builder =
452 ping_sender.MakeBuilder();
453 examples::Ping::Builder ping_builder =
454 builder.MakeBuilder<examples::Ping>();
455 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
456 ++sent_messages;
457 });
458
459 constexpr std::chrono::microseconds kSendPeriod{10};
460 const int max_legal_messages =
461 ping_sender.channel()->frequency() *
462 event_loop_factory.configuration()->channel_storage_duration() /
463 1000000000;
464
465 ping_spammer_event_loop->OnRun(
466 [&ping_spammer_event_loop, kSendPeriod, timer_handler]() {
467 timer_handler->Setup(
468 ping_spammer_event_loop->monotonic_now() + kSendPeriod / 2,
469 kSendPeriod);
470 });
471
472 Logger logger(logger_event_loop.get());
473 logger.set_separate_config(false);
474 logger.set_polling_period(std::chrono::milliseconds(100));
475 logger.StartLoggingLocalNamerOnRun(base_name);
476
477 event_loop_factory.RunFor(kSendPeriod * max_legal_messages * 2);
478 }
479
480 LogReader reader(logfile);
481
482 reader.Register();
483
484 std::unique_ptr<EventLoop> test_event_loop =
485 reader.event_loop_factory()->MakeEventLoop("log_reader");
486
487 int replay_count = 0;
488
489 test_event_loop->MakeWatcher(
490 "/test", [&replay_count](const examples::Ping &) { ++replay_count; });
491
492 reader.event_loop_factory()->Run();
493 EXPECT_EQ(replay_count, sent_messages);
494}
495
James Kuszmauldd0a5042021-10-28 23:38:04 -0700496struct CompressionParams {
497 std::string_view extension;
498 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
499};
500
501std::ostream &operator<<(std::ostream &ostream,
502 const CompressionParams &params) {
503 ostream << "\"" << params.extension << "\"";
504 return ostream;
505}
506
507std::vector<CompressionParams> SupportedCompressionAlgorithms() {
508 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
509 {SnappyDecoder::kExtension,
510 []() { return std::make_unique<SnappyEncoder>(); }},
511#ifdef LZMA
512 {LzmaDecoder::kExtension,
513 []() { return std::make_unique<LzmaEncoder>(3); }}
514#endif // LZMA
515 };
516}
517
Austin Schuh61e973f2021-02-21 21:43:56 -0800518// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700519struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800520 // The config file to use.
521 std::string config;
522 // If true, the RemoteMessage channel should be shared between all the remote
523 // channels. If false, there will be 1 RemoteMessage channel per remote
524 // channel.
525 bool shared;
526 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700527 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800528};
Austin Schuh315b96b2020-12-11 21:21:12 -0800529
James Kuszmauldd0a5042021-10-28 23:38:04 -0700530std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
531 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
532 << ", sha256: \"" << params.sha256 << "\"}";
533 return ostream;
534}
535
Austin Schuh3e20c692021-11-16 20:43:16 -0800536struct LoggerState {
537 static LoggerState MakeLogger(NodeEventLoopFactory *node,
538 SimulatedEventLoopFactory *factory,
539 CompressionParams params,
540 const Configuration *configuration = nullptr) {
541 if (configuration == nullptr) {
542 configuration = factory->configuration();
543 }
544 return {node->MakeEventLoop("logger"),
545 {},
546 configuration,
547 configuration::GetNode(configuration, node->node()),
548 nullptr,
549 params};
550 }
551
552 void StartLogger(std::string logfile_base) {
553 CHECK(!logfile_base.empty());
554
555 logger = std::make_unique<Logger>(event_loop.get(), configuration);
556 logger->set_polling_period(std::chrono::milliseconds(100));
557 logger->set_name(
558 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
559 event_loop->OnRun([this, logfile_base]() {
560 std::unique_ptr<MultiNodeLogNamer> namer =
561 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
562 event_loop.get(), node);
563 namer->set_extension(params.extension);
564 namer->set_encoder_factory(params.encoder_factory);
565 log_namer = namer.get();
566
567 logger->StartLogging(std::move(namer));
568 });
569 }
570
571 std::unique_ptr<EventLoop> event_loop;
572 std::unique_ptr<Logger> logger;
573 const Configuration *configuration;
574 const Node *node;
575 MultiNodeLogNamer *log_namer;
576 CompressionParams params;
577
578 void AppendAllFilenames(std::vector<std::string> *filenames) {
579 for (const std::string &file : log_namer->all_filenames()) {
580 const std::string_view separator =
581 log_namer->base_name().back() == '/' ? "" : "_";
582 filenames->emplace_back(
583 absl::StrCat(log_namer->base_name(), separator, file));
584 }
585 }
586
587 ~LoggerState() {
588 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800589 std::vector<std::string> filenames;
590 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800591 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800592 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800593 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800594 auto x = ReadHeader(file);
595 if (x) {
596 VLOG(1) << aos::FlatbufferToJson(x.value());
597 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800598 }
599 }
600 }
601};
602
Austin Schuhe33c08d2022-02-03 18:15:21 -0800603std::vector<std::pair<std::vector<realtime_clock::time_point>,
604 std::vector<realtime_clock::time_point>>>
605ConfirmReadable(
606 const std::vector<std::string> &files,
607 realtime_clock::time_point start_time = realtime_clock::min_time,
608 realtime_clock::time_point end_time = realtime_clock::max_time) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800609 {
610 LogReader reader(SortParts(files));
611
612 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
613 reader.Register(&log_reader_factory);
614
615 log_reader_factory.Run();
616
617 reader.Deregister();
618 }
619 {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800620 std::vector<std::pair<std::vector<realtime_clock::time_point>,
621 std::vector<realtime_clock::time_point>>>
622 result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800623 LogReader reader(SortParts(files));
624
Austin Schuhe33c08d2022-02-03 18:15:21 -0800625 reader.SetStartTime(start_time);
626 reader.SetEndTime(end_time);
627
Austin Schuh3e20c692021-11-16 20:43:16 -0800628 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
629 reader.RegisterWithoutStarting(&log_reader_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -0800630 result.resize(
631 configuration::NodesCount(log_reader_factory.configuration()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800632 if (configuration::MultiNode(log_reader_factory.configuration())) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800633 size_t i = 0;
Austin Schuh3e20c692021-11-16 20:43:16 -0800634 for (const aos::Node *node :
635 *log_reader_factory.configuration()->nodes()) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800636 LOG(INFO) << "Registering start";
637 reader.OnStart(node, [node, &log_reader_factory, &result,
638 node_index = i]() {
Austin Schuh3e20c692021-11-16 20:43:16 -0800639 LOG(INFO) << "Starting " << node->name()->string_view();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800640 result[node_index].first.push_back(
641 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
Austin Schuh3e20c692021-11-16 20:43:16 -0800642 });
Austin Schuhe33c08d2022-02-03 18:15:21 -0800643 reader.OnEnd(node, [node, &log_reader_factory, &result,
644 node_index = i]() {
645 LOG(INFO) << "Ending " << node->name()->string_view();
646 result[node_index].second.push_back(
647 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
648 });
649 ++i;
Austin Schuh3e20c692021-11-16 20:43:16 -0800650 }
Austin Schuhe33c08d2022-02-03 18:15:21 -0800651 } else {
652 reader.OnStart([&log_reader_factory, &result]() {
653 LOG(INFO) << "Starting";
654 result[0].first.push_back(
655 log_reader_factory.GetNodeEventLoopFactory(nullptr)
656 ->realtime_now());
657 });
658 reader.OnEnd([&log_reader_factory, &result]() {
659 LOG(INFO) << "Ending";
660 result[0].second.push_back(
661 log_reader_factory.GetNodeEventLoopFactory(nullptr)
662 ->realtime_now());
663 });
Austin Schuh3e20c692021-11-16 20:43:16 -0800664 }
665
666 log_reader_factory.Run();
667
668 reader.Deregister();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800669
670 for (auto x : result) {
671 for (auto y : x.first) {
672 VLOG(1) << "Start " << y;
673 }
674 for (auto y : x.second) {
675 VLOG(1) << "End " << y;
676 }
677 }
678 return result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800679 }
680}
681
James Kuszmauldd0a5042021-10-28 23:38:04 -0700682class MultinodeLoggerTest : public ::testing::TestWithParam<
683 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800684 public:
685 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700686 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
687 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800688 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800689 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700690 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800691 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700692 event_loop_factory_.configuration(), pi1_->node())),
693 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800694 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700695 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800696 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800697 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
698 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800699 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800700 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800701 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700702 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700703 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800704 event_loop_factory_.SetTimeConverter(&time_converter_);
705
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700706 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700707 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700708 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800709 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700710 }
711
Austin Schuh268586b2021-03-31 22:24:39 -0700712 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800713 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800714 unlink(file.c_str());
715 }
716
Austin Schuh268586b2021-03-31 22:24:39 -0700717 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800718 unlink(file.c_str());
719 }
720
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700721 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
722 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700723
724 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
725 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700726 }
727
James Kuszmauldd0a5042021-10-28 23:38:04 -0700728 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800729
730 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700731 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800732 size_t pi1_data_count = 3,
733 size_t pi2_data_count = 3) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800734 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700735 result.emplace_back(absl::StrCat(
736 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
737 result.emplace_back(absl::StrCat(
738 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700739 for (size_t i = 0; i < pi1_data_count; ++i) {
740 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700741 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700742 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800743 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700744 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800745 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700746 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700747 for (size_t i = 0; i < pi2_data_count; ++i) {
748 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700749 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700750 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700751 result.emplace_back(logfile_base2 +
752 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
753 Extension());
754 result.emplace_back(logfile_base2 +
755 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
756 Extension());
757 result.emplace_back(logfile_base1 +
758 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
759 Extension());
760 result.emplace_back(logfile_base1 +
761 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
762 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800763 if (shared()) {
764 result.emplace_back(logfile_base1 +
765 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700766 "aos.message_bridge.RemoteMessage.part0" +
767 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800768 result.emplace_back(logfile_base1 +
769 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700770 "aos.message_bridge.RemoteMessage.part1" +
771 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800772 result.emplace_back(logfile_base1 +
773 "_timestamps/pi1/aos/remote_timestamps/pi2/"
774 "aos.message_bridge.RemoteMessage.part2" +
775 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800776 result.emplace_back(logfile_base2 +
777 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700778 "aos.message_bridge.RemoteMessage.part0" +
779 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800780 result.emplace_back(logfile_base2 +
781 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700782 "aos.message_bridge.RemoteMessage.part1" +
783 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800784 } else {
785 result.emplace_back(logfile_base1 +
786 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
787 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700788 "aos.message_bridge.RemoteMessage.part0" +
789 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800790 result.emplace_back(logfile_base1 +
791 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
792 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700793 "aos.message_bridge.RemoteMessage.part1" +
794 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800795 result.emplace_back(logfile_base2 +
796 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
797 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700798 "aos.message_bridge.RemoteMessage.part0" +
799 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800800 result.emplace_back(logfile_base2 +
801 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
802 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700803 "aos.message_bridge.RemoteMessage.part1" +
804 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800805 result.emplace_back(logfile_base1 +
806 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
807 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700808 "aos.message_bridge.RemoteMessage.part0" +
809 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800810 result.emplace_back(logfile_base1 +
811 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
812 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700813 "aos.message_bridge.RemoteMessage.part1" +
814 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800815 }
816
817 return result;
818 }
819
820 std::vector<std::string> MakePi1RebootLogfiles() {
821 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700822 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
823 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
824 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800825 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
826 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800827 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700828 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800829 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700830 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800831 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700832 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700833 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700834 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
835 result.emplace_back(logfile_base1_ +
836 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
837 Extension());
838 result.emplace_back(logfile_base1_ +
839 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
840 Extension());
841 result.emplace_back(logfile_base1_ +
842 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
843 Extension());
844 result.emplace_back(logfile_base1_ +
845 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
846 Extension());
847 result.emplace_back(absl::StrCat(
848 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800849 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800850 for (size_t i = 0; i < 6; ++i) {
851 result.emplace_back(
852 absl::StrCat(logfile_base1_,
853 "_timestamps/pi1/aos/remote_timestamps/pi2/"
854 "aos.message_bridge.RemoteMessage.part",
855 i, Extension()));
856 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800857 } else {
858 result.emplace_back(logfile_base1_ +
859 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
860 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700861 "aos.message_bridge.RemoteMessage.part0" +
862 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800863 result.emplace_back(logfile_base1_ +
864 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
865 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700866 "aos.message_bridge.RemoteMessage.part1" +
867 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800868 result.emplace_back(logfile_base1_ +
869 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
870 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700871 "aos.message_bridge.RemoteMessage.part2" +
872 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700873 result.emplace_back(logfile_base1_ +
874 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
875 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700876 "aos.message_bridge.RemoteMessage.part3" +
877 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800878
879 result.emplace_back(logfile_base1_ +
880 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
881 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700882 "aos.message_bridge.RemoteMessage.part0" +
883 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800884 result.emplace_back(logfile_base1_ +
885 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
886 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700887 "aos.message_bridge.RemoteMessage.part1" +
888 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800889 result.emplace_back(logfile_base1_ +
890 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
891 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700892 "aos.message_bridge.RemoteMessage.part2" +
893 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700894 result.emplace_back(logfile_base1_ +
895 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
896 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700897 "aos.message_bridge.RemoteMessage.part3" +
898 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800899 }
900 return result;
901 }
902
903 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
904 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700905 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
906 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
907 result.emplace_back(logfile_base1_ +
908 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
909 Extension());
910 result.emplace_back(absl::StrCat(
911 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700912 return result;
913 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800914
Austin Schuh510dc622021-08-06 18:47:30 -0700915 std::vector<std::string> MakePi1DeadNodeLogfiles() {
916 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700917 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
918 result.emplace_back(absl::StrCat(
919 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800920 return result;
921 }
922
923 std::vector<std::vector<std::string>> StructureLogFiles() {
924 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800925 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
926 std::vector<std::string>{logfiles_[5], logfiles_[6]},
927 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800928 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800929 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800930
Austin Schuhbfe6c572022-01-27 20:48:20 -0800931 if (shared()) {
932 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
933 logfiles_[16]});
934 result.emplace_back(
935 std::vector<std::string>{logfiles_[17], logfiles_[18]});
936 } else {
937 result.emplace_back(
938 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800939 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700940 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800941 result.emplace_back(
942 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800943 }
944
945 return result;
946 }
947
James Kuszmauldd0a5042021-10-28 23:38:04 -0700948 std::string Extension() {
949 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
950 }
951
Austin Schuh58646e22021-08-23 23:51:46 -0700952 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700953 SimulatedEventLoopFactory *factory = nullptr,
954 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700955 if (factory == nullptr) {
956 factory = &event_loop_factory_;
957 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800958 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
959 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700960 }
961
James Kuszmauldd0a5042021-10-28 23:38:04 -0700962 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700963 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800964 if (logger->event_loop->node()->name()->string_view() == "pi1") {
965 logfile_base = logfile_base1_;
966 } else {
967 logfile_base = logfile_base2_;
968 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700969 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800970 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700971 }
Austin Schuh15649d62019-12-28 16:36:38 -0800972
Austin Schuh3bd4c402020-11-06 18:19:06 -0800973 void VerifyParts(const std::vector<LogFile> &sorted_parts,
974 const std::vector<std::string> &corrupted_parts = {}) {
975 EXPECT_EQ(sorted_parts.size(), 2u);
976
977 // Count up the number of UUIDs and make sure they are what we expect as a
978 // sanity check.
979 std::set<std::string> log_event_uuids;
980 std::set<std::string> parts_uuids;
981 std::set<std::string> both_uuids;
982
983 size_t missing_rt_count = 0;
984
985 std::vector<std::string> logger_nodes;
986 for (const LogFile &log_file : sorted_parts) {
987 EXPECT_FALSE(log_file.log_event_uuid.empty());
988 log_event_uuids.insert(log_file.log_event_uuid);
989 logger_nodes.emplace_back(log_file.logger_node);
990 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800991 EXPECT_TRUE(log_file.config);
992 EXPECT_EQ(log_file.name,
993 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800994
995 for (const LogParts &part : log_file.parts) {
996 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
997 << ": " << part;
998 missing_rt_count +=
999 part.realtime_start_time == aos::realtime_clock::min_time;
1000
1001 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
1002 log_event_uuids.end());
1003 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -08001004 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001005 parts_uuids.insert(part.parts_uuid);
1006 both_uuids.insert(part.parts_uuid);
1007 }
1008 }
1009
Austin Schuh61e973f2021-02-21 21:43:56 -08001010 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
1011 // start time on remote nodes because we don't know it and would be
1012 // guessing. And the log reader can actually do a better job. The number
1013 // depends on if we have the remote timestamps split across 2 files, or just
1014 // across 1, depending on if we are using a split or combined timestamp
1015 // channel config.
1016 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001017
1018 EXPECT_EQ(log_event_uuids.size(), 2u);
1019 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
1020 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
1021
1022 // Test that each list of parts is in order. Don't worry about the ordering
1023 // between part file lists though.
1024 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -08001025 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -08001026 ::testing::UnorderedElementsAreArray(structured_logfiles_));
1027
1028 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
1029
1030 EXPECT_NE(sorted_parts[0].realtime_start_time,
1031 aos::realtime_clock::min_time);
1032 EXPECT_NE(sorted_parts[1].realtime_start_time,
1033 aos::realtime_clock::min_time);
1034
1035 EXPECT_NE(sorted_parts[0].monotonic_start_time,
1036 aos::monotonic_clock::min_time);
1037 EXPECT_NE(sorted_parts[1].monotonic_start_time,
1038 aos::monotonic_clock::min_time);
1039
1040 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
1041 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
1042 }
1043
1044 void AddExtension(std::string_view extension) {
1045 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
1046 [extension](const std::string &in) {
1047 return absl::StrCat(in, extension);
1048 });
1049
1050 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
1051 structured_logfiles_.begin(),
1052 [extension](std::vector<std::string> in) {
1053 std::transform(in.begin(), in.end(), in.begin(),
1054 [extension](const std::string &in_str) {
1055 return absl::StrCat(in_str, extension);
1056 });
1057 return in;
1058 });
1059 }
1060
Austin Schuh15649d62019-12-28 16:36:38 -08001061 // Config and factory.
1062 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001063 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -08001064 SimulatedEventLoopFactory event_loop_factory_;
1065
Austin Schuh58646e22021-08-23 23:51:46 -07001066 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001067 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -07001068 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001069 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001070
1071 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -08001072 std::string logfile_base1_;
1073 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -08001074 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001075 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -08001076 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001077
1078 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -08001079};
1080
Austin Schuh391e3172020-09-01 22:48:18 -07001081// Counts the number of messages on a channel. Returns (channel name, channel
1082// type, count) for every message matching matcher()
1083std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -08001084 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001085 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -08001086 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -08001087 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -08001088
Austin Schuh6f3babe2020-01-26 20:34:50 -08001089 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001090 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -08001091 if (!msg) {
1092 break;
1093 }
1094
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001095 if (matcher(msg.get())) {
1096 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001097 }
1098 }
1099
Austin Schuh391e3172020-09-01 22:48:18 -07001100 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001101 int channel = 0;
1102 for (size_t i = 0; i < counts.size(); ++i) {
1103 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -08001104 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -07001105 result.push_back(std::make_tuple(channel->name()->str(),
1106 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -08001107 }
1108 ++channel;
1109 }
1110
1111 return result;
1112}
1113
1114// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001115std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -08001116 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -07001117 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001118 return CountChannelsMatching(
1119 config, filename, [](const UnpackedMessageHeader *msg) {
1120 if (msg->span.data() != nullptr) {
1121 CHECK(!msg->monotonic_remote_time.has_value());
1122 CHECK(!msg->realtime_remote_time.has_value());
1123 CHECK(!msg->remote_queue_index.has_value());
1124 return true;
1125 }
1126 return false;
1127 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001128}
1129
1130// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001131std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001132 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001133 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001134 return CountChannelsMatching(
1135 config, filename, [](const UnpackedMessageHeader *msg) {
1136 if (msg->span.data() == nullptr) {
1137 CHECK(msg->monotonic_remote_time.has_value());
1138 CHECK(msg->realtime_remote_time.has_value());
1139 CHECK(msg->remote_queue_index.has_value());
1140 return true;
1141 }
1142 return false;
1143 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001144}
1145
Austin Schuhcde938c2020-02-02 17:30:07 -08001146// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001147TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001148 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001149 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001150
Austin Schuh15649d62019-12-28 16:36:38 -08001151 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001152 LoggerState pi1_logger = MakeLogger(pi1_);
1153 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001154
1155 event_loop_factory_.RunFor(chrono::milliseconds(95));
1156
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001157 StartLogger(&pi1_logger);
1158 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001159
Austin Schuh15649d62019-12-28 16:36:38 -08001160 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001161 pi1_logger.AppendAllFilenames(&actual_filenames);
1162 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001163 }
1164
Austin Schuhbfe6c572022-01-27 20:48:20 -08001165 ASSERT_THAT(actual_filenames,
1166 ::testing::UnorderedElementsAreArray(logfiles_));
1167
Austin Schuh6f3babe2020-01-26 20:34:50 -08001168 {
Austin Schuh64fab802020-09-09 22:47:47 -07001169 std::set<std::string> logfile_uuids;
1170 std::set<std::string> parts_uuids;
1171 // Confirm that we have the expected number of UUIDs for both the logfile
1172 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001173 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001174 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001175 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001176 if (!log_header.back().message().has_configuration()) {
1177 logfile_uuids.insert(
1178 log_header.back().message().log_event_uuid()->str());
1179 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1180 }
Austin Schuh64fab802020-09-09 22:47:47 -07001181 }
Austin Schuh15649d62019-12-28 16:36:38 -08001182
Austin Schuh64fab802020-09-09 22:47:47 -07001183 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001184 if (shared()) {
1185 EXPECT_EQ(parts_uuids.size(), 7u);
1186 } else {
1187 EXPECT_EQ(parts_uuids.size(), 8u);
1188 }
Austin Schuh64fab802020-09-09 22:47:47 -07001189
1190 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001191 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001192 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001193 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1194
Austin Schuh64fab802020-09-09 22:47:47 -07001195 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001196 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001197
Austin Schuhe46492f2021-07-31 19:49:41 -07001198 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001199 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1200 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1201
1202 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1203 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1204
Austin Schuhe46492f2021-07-31 19:49:41 -07001205 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1206 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001207
1208 if (shared()) {
1209 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1210 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001211 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001212
1213 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1214 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1215 } else {
1216 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1217 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1218
1219 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1220 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1221
1222 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1223 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001224 }
Austin Schuh64fab802020-09-09 22:47:47 -07001225
1226 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001227 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001228 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001229 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1230
1231 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1232 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1233
1234 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1235 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1236 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1237
Austin Schuh64fab802020-09-09 22:47:47 -07001238 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1239 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001240
Austin Schuh61e973f2021-02-21 21:43:56 -08001241 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1242 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001243
1244 if (shared()) {
1245 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1246 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1247 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1248
1249 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1250 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1251 } else {
1252 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1253 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1254
Austin Schuhe46492f2021-07-31 19:49:41 -07001255 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1256 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001257
1258 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1259 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001260 }
Austin Schuh64fab802020-09-09 22:47:47 -07001261 }
1262
Austin Schuh8c399962020-12-25 21:51:45 -08001263 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001264 {
Austin Schuh391e3172020-09-01 22:48:18 -07001265 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001266 std::shared_ptr<const aos::Configuration> config =
1267 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001268
Austin Schuh6f3babe2020-01-26 20:34:50 -08001269 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001270 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1271 UnorderedElementsAre(
1272 std::make_tuple("/pi1/aos",
1273 "aos.message_bridge.ServerStatistics", 1),
1274 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001275 << " : " << logfiles_[2];
1276 EXPECT_THAT(
1277 CountChannelsData(config, logfiles_[3]),
1278 UnorderedElementsAre(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001279 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1280 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1281 1)))
1282 << " : " << logfiles_[3];
1283 EXPECT_THAT(
1284 CountChannelsData(config, logfiles_[4]),
1285 UnorderedElementsAre(
1286 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001287 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001288 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001289 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
Austin Schuhbfe6c572022-01-27 20:48:20 -08001290 199),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001291 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001292 std::make_tuple("/test", "aos.examples.Ping", 2000)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001293 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001294 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001295 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1296 UnorderedElementsAre())
1297 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001298 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001299 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001300 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001301 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001302 EXPECT_THAT(
1303 CountChannelsTimestamp(config, logfiles_[4]),
1304 UnorderedElementsAre(
1305 std::make_tuple("/test", "aos.examples.Pong", 2000),
1306 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1307 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001308
1309 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001310 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001311 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001312 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001313 << " : " << logfiles_[5];
1314 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001315 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001316 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001317 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001318
Austin Schuh6f3babe2020-01-26 20:34:50 -08001319 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001320 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1321 UnorderedElementsAre())
1322 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001323 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1324 UnorderedElementsAre())
1325 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001326
1327 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001328 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001329 UnorderedElementsAre(std::make_tuple(
1330 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001331 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001332 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001333 CountChannelsData(config, logfiles_[8]),
1334 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1335 << " : " << logfiles_[8];
1336 EXPECT_THAT(
1337 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001338 UnorderedElementsAre(
1339 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001340 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001341 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001342 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1343 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001344 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001345 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1346 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001347 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001348 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001349 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001350 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001351 EXPECT_THAT(
1352 CountChannelsTimestamp(config, logfiles_[8]),
1353 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1354 << " : " << logfiles_[8];
1355 EXPECT_THAT(
1356 CountChannelsTimestamp(config, logfiles_[9]),
1357 UnorderedElementsAre(
1358 std::make_tuple("/test", "aos.examples.Ping", 2000),
1359 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1360 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001361
1362 // And then test that the remotely logged timestamp data files only have
1363 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001364 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1365 UnorderedElementsAre())
1366 << " : " << logfiles_[10];
1367 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1368 UnorderedElementsAre())
1369 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001370 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1371 UnorderedElementsAre())
1372 << " : " << logfiles_[12];
1373 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1374 UnorderedElementsAre())
1375 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001376
Austin Schuh8c399962020-12-25 21:51:45 -08001377 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001378 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001379 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001380 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001381 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001382 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001383 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001384 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001385
Austin Schuh61e973f2021-02-21 21:43:56 -08001386 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001387 UnorderedElementsAre(std::make_tuple(
1388 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001389 << " : " << logfiles_[12];
1390 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001391 UnorderedElementsAre(std::make_tuple(
1392 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001393 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001394
1395 // Timestamps from pi2 on pi1, and the other way.
1396 if (shared()) {
1397 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1398 UnorderedElementsAre())
1399 << " : " << logfiles_[14];
1400 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1401 UnorderedElementsAre())
1402 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001403 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001404 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001405 << " : " << logfiles_[16];
1406 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001407 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001408 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001409 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1410 UnorderedElementsAre())
1411 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001412
Austin Schuhbfe6c572022-01-27 20:48:20 -08001413 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1414 UnorderedElementsAre(
1415 std::make_tuple("/test", "aos.examples.Ping", 1)))
1416 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001417 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001418 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001419 UnorderedElementsAre(
1420 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001421 std::make_tuple("/test", "aos.examples.Ping", 90)))
1422 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001423 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001424 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001425 UnorderedElementsAre(
1426 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1427 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001428 << " : " << logfiles_[16];
1429 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001430 UnorderedElementsAre(std::make_tuple(
1431 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1432 << " : " << logfiles_[17];
1433 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1434 UnorderedElementsAre(std::make_tuple(
1435 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1436 << " : " << logfiles_[18];
1437 } else {
1438 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1439 UnorderedElementsAre())
1440 << " : " << logfiles_[14];
1441 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1442 UnorderedElementsAre())
1443 << " : " << logfiles_[15];
1444 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1445 UnorderedElementsAre())
1446 << " : " << logfiles_[16];
1447 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1448 UnorderedElementsAre())
1449 << " : " << logfiles_[17];
1450 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1451 UnorderedElementsAre())
1452 << " : " << logfiles_[18];
1453 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1454 UnorderedElementsAre())
1455 << " : " << logfiles_[19];
1456
1457 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1458 UnorderedElementsAre(std::make_tuple(
1459 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1460 << " : " << logfiles_[14];
1461 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1462 UnorderedElementsAre(std::make_tuple(
1463 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1464 << " : " << logfiles_[15];
1465 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1466 UnorderedElementsAre(std::make_tuple(
1467 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1468 << " : " << logfiles_[16];
1469 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1470 UnorderedElementsAre(std::make_tuple(
1471 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1472 << " : " << logfiles_[17];
1473 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1474 UnorderedElementsAre(
1475 std::make_tuple("/test", "aos.examples.Ping", 91)))
1476 << " : " << logfiles_[18];
1477 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001478 UnorderedElementsAre(
1479 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001480 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001481 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001482 }
1483
Austin Schuh8c399962020-12-25 21:51:45 -08001484 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001485
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001486 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001487 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001488
1489 // This sends out the fetched messages and advances time to the start of the
1490 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001491 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001492
Austin Schuhac0771c2020-01-07 18:36:30 -08001493 const Node *pi1 =
1494 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001495 const Node *pi2 =
1496 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001497
Austin Schuh2f8fd752020-09-01 22:38:28 -07001498 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1499 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1500 LOG(INFO) << "now pi1 "
1501 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1502 LOG(INFO) << "now pi2 "
1503 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1504
Austin Schuh07676622021-01-21 18:59:17 -08001505 EXPECT_THAT(reader.LoggedNodes(),
1506 ::testing::ElementsAre(
1507 configuration::GetNode(reader.logged_configuration(), pi1),
1508 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001509
1510 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001511
Austin Schuh6f3babe2020-01-26 20:34:50 -08001512 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001513 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001514 std::unique_ptr<EventLoop> pi2_event_loop =
1515 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001516
Austin Schuh6f3babe2020-01-26 20:34:50 -08001517 int pi1_ping_count = 10;
1518 int pi2_ping_count = 10;
1519 int pi1_pong_count = 10;
1520 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001521
1522 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001523 pi1_event_loop->MakeWatcher(
1524 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001525 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001526 << pi1_event_loop->context().monotonic_remote_time << " -> "
1527 << pi1_event_loop->context().monotonic_event_time;
1528 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1529 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1530 pi1_ping_count * chrono::milliseconds(10) +
1531 monotonic_clock::epoch());
1532 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1533 pi1_ping_count * chrono::milliseconds(10) +
1534 realtime_clock::epoch());
1535 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1536 pi1_event_loop->context().monotonic_event_time);
1537 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1538 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001539
Austin Schuh6f3babe2020-01-26 20:34:50 -08001540 ++pi1_ping_count;
1541 });
1542 pi2_event_loop->MakeWatcher(
1543 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001544 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001545 << pi2_event_loop->context().monotonic_remote_time << " -> "
1546 << pi2_event_loop->context().monotonic_event_time;
1547 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1548
1549 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1550 pi2_ping_count * chrono::milliseconds(10) +
1551 monotonic_clock::epoch());
1552 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1553 pi2_ping_count * chrono::milliseconds(10) +
1554 realtime_clock::epoch());
1555 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1556 chrono::microseconds(150),
1557 pi2_event_loop->context().monotonic_event_time);
1558 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1559 chrono::microseconds(150),
1560 pi2_event_loop->context().realtime_event_time);
1561 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001562 });
1563
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001564 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001565 // Confirm that the ping and pong counts both match, and the value also
1566 // matches.
1567 pi1_event_loop->MakeWatcher(
1568 "/test", [&pi1_event_loop, &pi1_ping_count,
1569 &pi1_pong_count](const examples::Pong &pong) {
1570 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1571 << pi1_event_loop->context().monotonic_remote_time << " -> "
1572 << pi1_event_loop->context().monotonic_event_time;
1573
1574 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1575 pi1_pong_count + kQueueIndexOffset);
1576 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1577 chrono::microseconds(200) +
1578 pi1_pong_count * chrono::milliseconds(10) +
1579 monotonic_clock::epoch());
1580 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1581 chrono::microseconds(200) +
1582 pi1_pong_count * chrono::milliseconds(10) +
1583 realtime_clock::epoch());
1584
1585 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1586 chrono::microseconds(150),
1587 pi1_event_loop->context().monotonic_event_time);
1588 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1589 chrono::microseconds(150),
1590 pi1_event_loop->context().realtime_event_time);
1591
1592 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1593 ++pi1_pong_count;
1594 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1595 });
1596 pi2_event_loop->MakeWatcher(
1597 "/test", [&pi2_event_loop, &pi2_ping_count,
1598 &pi2_pong_count](const examples::Pong &pong) {
1599 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1600 << pi2_event_loop->context().monotonic_remote_time << " -> "
1601 << pi2_event_loop->context().monotonic_event_time;
1602
1603 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001604 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001605
1606 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1607 chrono::microseconds(200) +
1608 pi2_pong_count * chrono::milliseconds(10) +
1609 monotonic_clock::epoch());
1610 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1611 chrono::microseconds(200) +
1612 pi2_pong_count * chrono::milliseconds(10) +
1613 realtime_clock::epoch());
1614
1615 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1616 pi2_event_loop->context().monotonic_event_time);
1617 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1618 pi2_event_loop->context().realtime_event_time);
1619
1620 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1621 ++pi2_pong_count;
1622 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1623 });
1624
1625 log_reader_factory.Run();
1626 EXPECT_EQ(pi1_ping_count, 2010);
1627 EXPECT_EQ(pi2_ping_count, 2010);
1628 EXPECT_EQ(pi1_pong_count, 2010);
1629 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001630
1631 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001632}
1633
James Kuszmaul46d82582020-05-09 19:50:09 -07001634typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1635
1636// Test that if we feed the replay with a mismatched node list that we die on
1637// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001638TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001639 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001640 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001641 LoggerState pi1_logger = MakeLogger(pi1_);
1642 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001643
1644 event_loop_factory_.RunFor(chrono::milliseconds(95));
1645
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001646 StartLogger(&pi1_logger);
1647 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001648
James Kuszmaul46d82582020-05-09 19:50:09 -07001649 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1650 }
1651
1652 // Test that, if we add an additional node to the replay config that the
1653 // logger complains about the mismatch in number of nodes.
1654 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1655 configuration::MergeWithConfig(&config_.message(), R"({
1656 "nodes": [
1657 {
1658 "name": "extra-node"
1659 }
1660 ]
1661 }
1662 )");
1663
Austin Schuh287d43d2020-12-04 20:19:33 -08001664 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1665 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001666 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001667}
1668
Austin Schuhcde938c2020-02-02 17:30:07 -08001669// Tests that we can read log files where they don't start at the same monotonic
1670// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001671TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001672 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001673 std::vector<std::string> actual_filenames;
1674
Austin Schuhcde938c2020-02-02 17:30:07 -08001675 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001676 LoggerState pi1_logger = MakeLogger(pi1_);
1677 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001678
1679 event_loop_factory_.RunFor(chrono::milliseconds(95));
1680
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001681 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001682
1683 event_loop_factory_.RunFor(chrono::milliseconds(200));
1684
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001685 StartLogger(&pi2_logger);
1686
Austin Schuhcde938c2020-02-02 17:30:07 -08001687 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001688 pi1_logger.AppendAllFilenames(&actual_filenames);
1689 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001690 }
1691
Austin Schuhe46492f2021-07-31 19:49:41 -07001692 // Since we delay starting pi2, it already knows about all the timestamps so
1693 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001694 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001695
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001696 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001697 log_reader_factory.set_send_delay(chrono::microseconds(0));
1698
1699 // This sends out the fetched messages and advances time to the start of the
1700 // log file.
1701 reader.Register(&log_reader_factory);
1702
1703 const Node *pi1 =
1704 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1705 const Node *pi2 =
1706 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1707
Austin Schuh07676622021-01-21 18:59:17 -08001708 EXPECT_THAT(reader.LoggedNodes(),
1709 ::testing::ElementsAre(
1710 configuration::GetNode(reader.logged_configuration(), pi1),
1711 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001712
1713 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1714
1715 std::unique_ptr<EventLoop> pi1_event_loop =
1716 log_reader_factory.MakeEventLoop("test", pi1);
1717 std::unique_ptr<EventLoop> pi2_event_loop =
1718 log_reader_factory.MakeEventLoop("test", pi2);
1719
1720 int pi1_ping_count = 30;
1721 int pi2_ping_count = 30;
1722 int pi1_pong_count = 30;
1723 int pi2_pong_count = 30;
1724
1725 // Confirm that the ping value matches.
1726 pi1_event_loop->MakeWatcher(
1727 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1728 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1729 << pi1_event_loop->context().monotonic_remote_time << " -> "
1730 << pi1_event_loop->context().monotonic_event_time;
1731 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1732
1733 ++pi1_ping_count;
1734 });
1735 pi2_event_loop->MakeWatcher(
1736 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1737 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1738 << pi2_event_loop->context().monotonic_remote_time << " -> "
1739 << pi2_event_loop->context().monotonic_event_time;
1740 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1741
1742 ++pi2_ping_count;
1743 });
1744
1745 // Confirm that the ping and pong counts both match, and the value also
1746 // matches.
1747 pi1_event_loop->MakeWatcher(
1748 "/test", [&pi1_event_loop, &pi1_ping_count,
1749 &pi1_pong_count](const examples::Pong &pong) {
1750 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1751 << pi1_event_loop->context().monotonic_remote_time << " -> "
1752 << pi1_event_loop->context().monotonic_event_time;
1753
1754 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1755 ++pi1_pong_count;
1756 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1757 });
1758 pi2_event_loop->MakeWatcher(
1759 "/test", [&pi2_event_loop, &pi2_ping_count,
1760 &pi2_pong_count](const examples::Pong &pong) {
1761 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1762 << pi2_event_loop->context().monotonic_remote_time << " -> "
1763 << pi2_event_loop->context().monotonic_event_time;
1764
1765 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1766 ++pi2_pong_count;
1767 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1768 });
1769
1770 log_reader_factory.Run();
1771 EXPECT_EQ(pi1_ping_count, 2030);
1772 EXPECT_EQ(pi2_ping_count, 2030);
1773 EXPECT_EQ(pi1_pong_count, 2030);
1774 EXPECT_EQ(pi2_pong_count, 2030);
1775
1776 reader.Deregister();
1777}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001778
Austin Schuh8bd96322020-02-13 21:18:22 -08001779// Tests that we can read log files where the monotonic clocks drift and don't
1780// match correctly. While we are here, also test that different ending times
1781// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001782TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001783 // TODO(austin): Negate...
1784 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1785
Austin Schuh66168842021-08-17 19:42:21 -07001786 time_converter_.AddMonotonic(
1787 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001788 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1789 // skew to be 200 uS/s
1790 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1791 {chrono::milliseconds(95),
1792 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1793 // Run another 200 ms to have one logger start first.
1794 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1795 {chrono::milliseconds(200), chrono::milliseconds(200)});
1796 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1797 // go far enough to cause problems if this isn't accounted for.
1798 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1799 {chrono::milliseconds(20000),
1800 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1801 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1802 {chrono::milliseconds(40000),
1803 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1804 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1805 {chrono::milliseconds(400), chrono::milliseconds(400)});
1806
Austin Schuhcde938c2020-02-02 17:30:07 -08001807 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001808 LoggerState pi2_logger = MakeLogger(pi2_);
1809
Austin Schuh58646e22021-08-23 23:51:46 -07001810 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1811 << pi2_->realtime_now() << " distributed "
1812 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001813
Austin Schuh58646e22021-08-23 23:51:46 -07001814 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1815 << pi2_->realtime_now() << " distributed "
1816 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001817
Austin Schuh87dd3832021-01-01 23:07:31 -08001818 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001819
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001820 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001821
Austin Schuh87dd3832021-01-01 23:07:31 -08001822 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001823
Austin Schuh8bd96322020-02-13 21:18:22 -08001824 {
1825 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001826 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001827
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001828 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001829 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001830
Austin Schuh87dd3832021-01-01 23:07:31 -08001831 // Make sure we slewed time far enough so that the difference is greater
1832 // than the network delay. This confirms that if we sort incorrectly, it
1833 // would show in the results.
1834 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001835 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001836 -event_loop_factory_.send_delay() -
1837 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001838
Austin Schuh87dd3832021-01-01 23:07:31 -08001839 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001840
Austin Schuh87dd3832021-01-01 23:07:31 -08001841 // And now check that we went far enough the other way to make sure we
1842 // cover both problems.
1843 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001844 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001845 event_loop_factory_.send_delay() +
1846 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001847 }
1848
1849 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001850 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001851 }
1852
Austin Schuh72211ae2021-08-05 14:02:30 -07001853 LogReader reader(
1854 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001855
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001856 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001857 log_reader_factory.set_send_delay(chrono::microseconds(0));
1858
Austin Schuhcde938c2020-02-02 17:30:07 -08001859 const Node *pi1 =
1860 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1861 const Node *pi2 =
1862 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1863
Austin Schuh2f8fd752020-09-01 22:38:28 -07001864 // This sends out the fetched messages and advances time to the start of the
1865 // log file.
1866 reader.Register(&log_reader_factory);
1867
1868 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1869 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1870 LOG(INFO) << "now pi1 "
1871 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1872 LOG(INFO) << "now pi2 "
1873 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1874
Austin Schuhcde938c2020-02-02 17:30:07 -08001875 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001876 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1877 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001878 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1879 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001880 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1881 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001882 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1883
Austin Schuh07676622021-01-21 18:59:17 -08001884 EXPECT_THAT(reader.LoggedNodes(),
1885 ::testing::ElementsAre(
1886 configuration::GetNode(reader.logged_configuration(), pi1),
1887 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001888
1889 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1890
1891 std::unique_ptr<EventLoop> pi1_event_loop =
1892 log_reader_factory.MakeEventLoop("test", pi1);
1893 std::unique_ptr<EventLoop> pi2_event_loop =
1894 log_reader_factory.MakeEventLoop("test", pi2);
1895
1896 int pi1_ping_count = 30;
1897 int pi2_ping_count = 30;
1898 int pi1_pong_count = 30;
1899 int pi2_pong_count = 30;
1900
1901 // Confirm that the ping value matches.
1902 pi1_event_loop->MakeWatcher(
1903 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1904 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1905 << pi1_event_loop->context().monotonic_remote_time << " -> "
1906 << pi1_event_loop->context().monotonic_event_time;
1907 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1908
1909 ++pi1_ping_count;
1910 });
1911 pi2_event_loop->MakeWatcher(
1912 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1913 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1914 << pi2_event_loop->context().monotonic_remote_time << " -> "
1915 << pi2_event_loop->context().monotonic_event_time;
1916 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1917
1918 ++pi2_ping_count;
1919 });
1920
1921 // Confirm that the ping and pong counts both match, and the value also
1922 // matches.
1923 pi1_event_loop->MakeWatcher(
1924 "/test", [&pi1_event_loop, &pi1_ping_count,
1925 &pi1_pong_count](const examples::Pong &pong) {
1926 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1927 << pi1_event_loop->context().monotonic_remote_time << " -> "
1928 << pi1_event_loop->context().monotonic_event_time;
1929
1930 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1931 ++pi1_pong_count;
1932 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1933 });
1934 pi2_event_loop->MakeWatcher(
1935 "/test", [&pi2_event_loop, &pi2_ping_count,
1936 &pi2_pong_count](const examples::Pong &pong) {
1937 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1938 << pi2_event_loop->context().monotonic_remote_time << " -> "
1939 << pi2_event_loop->context().monotonic_event_time;
1940
1941 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1942 ++pi2_pong_count;
1943 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1944 });
1945
1946 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001947 EXPECT_EQ(pi1_ping_count, 6030);
1948 EXPECT_EQ(pi2_ping_count, 6030);
1949 EXPECT_EQ(pi1_pong_count, 6030);
1950 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001951
1952 reader.Deregister();
1953}
1954
Austin Schuh5212cad2020-09-09 23:12:09 -07001955// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001956TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001957 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001958 // Make a bunch of parts.
1959 {
1960 LoggerState pi1_logger = MakeLogger(pi1_);
1961 LoggerState pi2_logger = MakeLogger(pi2_);
1962
1963 event_loop_factory_.RunFor(chrono::milliseconds(95));
1964
1965 StartLogger(&pi1_logger);
1966 StartLogger(&pi2_logger);
1967
1968 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1969 }
1970
Austin Schuh11d43732020-09-21 17:28:30 -07001971 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001972 VerifyParts(sorted_parts);
1973}
Austin Schuh11d43732020-09-21 17:28:30 -07001974
Austin Schuh3bd4c402020-11-06 18:19:06 -08001975// Tests that we can sort a bunch of parts with an empty part. We should ignore
1976// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001977TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001978 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001979 // Make a bunch of parts.
1980 {
1981 LoggerState pi1_logger = MakeLogger(pi1_);
1982 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001983
Austin Schuh3bd4c402020-11-06 18:19:06 -08001984 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001985
Austin Schuh3bd4c402020-11-06 18:19:06 -08001986 StartLogger(&pi1_logger);
1987 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001988
Austin Schuh3bd4c402020-11-06 18:19:06 -08001989 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001990 }
1991
Austin Schuh3bd4c402020-11-06 18:19:06 -08001992 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001993 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001994
Austin Schuh3bd4c402020-11-06 18:19:06 -08001995 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1996 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001997
Austin Schuh3bd4c402020-11-06 18:19:06 -08001998 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1999 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07002000}
2001
James Kuszmauldd0a5042021-10-28 23:38:04 -07002002// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08002003// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002004TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002005 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002006 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002007 // Make a bunch of parts.
2008 {
2009 LoggerState pi1_logger = MakeLogger(pi1_);
2010 LoggerState pi2_logger = MakeLogger(pi2_);
2011
2012 event_loop_factory_.RunFor(chrono::milliseconds(95));
2013
James Kuszmauldd0a5042021-10-28 23:38:04 -07002014 StartLogger(&pi1_logger);
2015 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002016
2017 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002018
2019 pi1_logger.AppendAllFilenames(&actual_filenames);
2020 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002021 }
2022
Austin Schuhbfe6c572022-01-27 20:48:20 -08002023 ASSERT_THAT(actual_filenames,
2024 ::testing::UnorderedElementsAreArray(logfiles_));
2025
Austin Schuh3bd4c402020-11-06 18:19:06 -08002026 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002027 // For snappy, needs to have enough data to be >1 chunk of compressed data so
2028 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08002029 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08002030 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002031
2032 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08002033 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08002034 compressed_contents.substr(0, compressed_contents.size() - 100));
2035
2036 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2037 VerifyParts(sorted_parts);
2038}
Austin Schuh3bd4c402020-11-06 18:19:06 -08002039
Austin Schuh01b4c352020-09-21 23:09:39 -07002040// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08002041TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002042 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07002043 {
2044 LoggerState pi1_logger = MakeLogger(pi1_);
2045 LoggerState pi2_logger = MakeLogger(pi2_);
2046
2047 event_loop_factory_.RunFor(chrono::milliseconds(95));
2048
2049 StartLogger(&pi1_logger);
2050 StartLogger(&pi2_logger);
2051
2052 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2053 }
2054
Austin Schuh287d43d2020-12-04 20:19:33 -08002055 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07002056
2057 // Remap just on pi1.
2058 reader.RemapLoggedChannel<aos::timing::Report>(
2059 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
2060
2061 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2062 log_reader_factory.set_send_delay(chrono::microseconds(0));
2063
Austin Schuh1c227352021-09-17 12:53:54 -07002064 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
2065 ASSERT_EQ(remapped_channels.size(), 1u);
2066 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
2067 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
2068
Austin Schuh01b4c352020-09-21 23:09:39 -07002069 reader.Register(&log_reader_factory);
2070
2071 const Node *pi1 =
2072 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2073 const Node *pi2 =
2074 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2075
2076 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2077 // else should have moved.
2078 std::unique_ptr<EventLoop> pi1_event_loop =
2079 log_reader_factory.MakeEventLoop("test", pi1);
2080 pi1_event_loop->SkipTimingReport();
2081 std::unique_ptr<EventLoop> full_pi1_event_loop =
2082 log_reader_factory.MakeEventLoop("test", pi1);
2083 full_pi1_event_loop->SkipTimingReport();
2084 std::unique_ptr<EventLoop> pi2_event_loop =
2085 log_reader_factory.MakeEventLoop("test", pi2);
2086 pi2_event_loop->SkipTimingReport();
2087
2088 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
2089 "/aos");
2090 MessageCounter<aos::timing::Report> full_pi1_timing_report(
2091 full_pi1_event_loop.get(), "/pi1/aos");
2092 MessageCounter<aos::timing::Report> pi1_original_timing_report(
2093 pi1_event_loop.get(), "/original/aos");
2094 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
2095 full_pi1_event_loop.get(), "/original/pi1/aos");
2096 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
2097 "/aos");
2098
2099 log_reader_factory.Run();
2100
2101 EXPECT_EQ(pi1_timing_report.count(), 0u);
2102 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
2103 EXPECT_NE(pi1_original_timing_report.count(), 0u);
2104 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
2105 EXPECT_NE(pi2_timing_report.count(), 0u);
2106
2107 reader.Deregister();
2108}
2109
Austin Schuh006a9f52021-04-07 16:24:18 -07002110// Tests that we can remap a forwarded channel as well.
2111TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
2112 time_converter_.StartEqual();
2113 {
2114 LoggerState pi1_logger = MakeLogger(pi1_);
2115 LoggerState pi2_logger = MakeLogger(pi2_);
2116
2117 event_loop_factory_.RunFor(chrono::milliseconds(95));
2118
2119 StartLogger(&pi1_logger);
2120 StartLogger(&pi2_logger);
2121
2122 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2123 }
2124
2125 LogReader reader(SortParts(logfiles_));
2126
2127 reader.RemapLoggedChannel<examples::Ping>("/test");
2128
2129 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2130 log_reader_factory.set_send_delay(chrono::microseconds(0));
2131
2132 reader.Register(&log_reader_factory);
2133
2134 const Node *pi1 =
2135 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2136 const Node *pi2 =
2137 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2138
2139 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2140 // else should have moved.
2141 std::unique_ptr<EventLoop> pi1_event_loop =
2142 log_reader_factory.MakeEventLoop("test", pi1);
2143 pi1_event_loop->SkipTimingReport();
2144 std::unique_ptr<EventLoop> full_pi1_event_loop =
2145 log_reader_factory.MakeEventLoop("test", pi1);
2146 full_pi1_event_loop->SkipTimingReport();
2147 std::unique_ptr<EventLoop> pi2_event_loop =
2148 log_reader_factory.MakeEventLoop("test", pi2);
2149 pi2_event_loop->SkipTimingReport();
2150
2151 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2152 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2153 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2154 "/original/test");
2155 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2156 "/original/test");
2157
2158 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2159 pi1_original_ping_timestamp;
2160 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2161 pi1_ping_timestamp;
2162 if (!shared()) {
2163 pi1_original_ping_timestamp =
2164 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2165 pi1_event_loop.get(),
2166 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2167 pi1_ping_timestamp =
2168 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2169 pi1_event_loop.get(),
2170 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2171 }
2172
2173 log_reader_factory.Run();
2174
2175 EXPECT_EQ(pi1_ping.count(), 0u);
2176 EXPECT_EQ(pi2_ping.count(), 0u);
2177 EXPECT_NE(pi1_original_ping.count(), 0u);
2178 EXPECT_NE(pi2_original_ping.count(), 0u);
2179 if (!shared()) {
2180 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2181 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2182 }
2183
2184 reader.Deregister();
2185}
2186
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002187// Tests that we properly recreate forwarded timestamps when replaying a log.
2188// This should be enough that we can then re-run the logger and get a valid log
2189// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002190TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002191 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002192 {
2193 LoggerState pi1_logger = MakeLogger(pi1_);
2194 LoggerState pi2_logger = MakeLogger(pi2_);
2195
2196 event_loop_factory_.RunFor(chrono::milliseconds(95));
2197
2198 StartLogger(&pi1_logger);
2199 StartLogger(&pi2_logger);
2200
2201 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2202 }
2203
Austin Schuh287d43d2020-12-04 20:19:33 -08002204 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002205
2206 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2207 log_reader_factory.set_send_delay(chrono::microseconds(0));
2208
2209 // This sends out the fetched messages and advances time to the start of the
2210 // log file.
2211 reader.Register(&log_reader_factory);
2212
2213 const Node *pi1 =
2214 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2215 const Node *pi2 =
2216 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2217
2218 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2219 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2220 LOG(INFO) << "now pi1 "
2221 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2222 LOG(INFO) << "now pi2 "
2223 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2224
Austin Schuh07676622021-01-21 18:59:17 -08002225 EXPECT_THAT(reader.LoggedNodes(),
2226 ::testing::ElementsAre(
2227 configuration::GetNode(reader.logged_configuration(), pi1),
2228 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002229
2230 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2231
2232 std::unique_ptr<EventLoop> pi1_event_loop =
2233 log_reader_factory.MakeEventLoop("test", pi1);
2234 std::unique_ptr<EventLoop> pi2_event_loop =
2235 log_reader_factory.MakeEventLoop("test", pi2);
2236
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002237 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2238 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2239 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2240 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2241
2242 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2243 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2244 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2245 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2246
2247 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2248 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2249 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2250 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2251
2252 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2253 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2254 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2255 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2256
2257 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2258 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2259 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2260 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2261
2262 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2263 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2264 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2265 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2266
Austin Schuh969cd602021-01-03 00:09:45 -08002267 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002268 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002269
Austin Schuh61e973f2021-02-21 21:43:56 -08002270 for (std::pair<int, std::string> channel :
2271 shared()
2272 ? std::vector<
2273 std::pair<int, std::string>>{{-1,
2274 "/aos/remote_timestamps/pi2"}}
2275 : std::vector<std::pair<int, std::string>>{
2276 {pi1_timestamp_channel,
2277 "/aos/remote_timestamps/pi2/pi1/aos/"
2278 "aos-message_bridge-Timestamp"},
2279 {ping_timestamp_channel,
2280 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2281 pi1_event_loop->MakeWatcher(
2282 channel.second,
2283 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2284 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2285 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2286 &ping_on_pi2_fetcher, network_delay, send_delay,
2287 channel_index = channel.first](const RemoteMessage &header) {
2288 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2289 chrono::nanoseconds(header.monotonic_sent_time()));
2290 const aos::realtime_clock::time_point header_realtime_sent_time(
2291 chrono::nanoseconds(header.realtime_sent_time()));
2292 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2293 chrono::nanoseconds(header.monotonic_remote_time()));
2294 const aos::realtime_clock::time_point header_realtime_remote_time(
2295 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002296
Austin Schuh61e973f2021-02-21 21:43:56 -08002297 if (channel_index != -1) {
2298 ASSERT_EQ(channel_index, header.channel_index());
2299 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002300
Austin Schuh61e973f2021-02-21 21:43:56 -08002301 const Context *pi1_context = nullptr;
2302 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002303
Austin Schuh61e973f2021-02-21 21:43:56 -08002304 if (header.channel_index() == pi1_timestamp_channel) {
2305 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2306 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2307 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2308 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2309 } else if (header.channel_index() == ping_timestamp_channel) {
2310 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2311 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2312 pi1_context = &ping_on_pi1_fetcher.context();
2313 pi2_context = &ping_on_pi2_fetcher.context();
2314 } else {
2315 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2316 << configuration::CleanedChannelToString(
2317 pi1_event_loop->configuration()->channels()->Get(
2318 header.channel_index()));
2319 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002320
Austin Schuh61e973f2021-02-21 21:43:56 -08002321 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002322 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2323 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002324
Austin Schuh61e973f2021-02-21 21:43:56 -08002325 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2326 EXPECT_EQ(pi2_context->remote_queue_index,
2327 header.remote_queue_index());
2328 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002329
Austin Schuh61e973f2021-02-21 21:43:56 -08002330 EXPECT_EQ(pi2_context->monotonic_event_time,
2331 header_monotonic_sent_time);
2332 EXPECT_EQ(pi2_context->realtime_event_time,
2333 header_realtime_sent_time);
2334 EXPECT_EQ(pi2_context->realtime_remote_time,
2335 header_realtime_remote_time);
2336 EXPECT_EQ(pi2_context->monotonic_remote_time,
2337 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002338
Austin Schuh61e973f2021-02-21 21:43:56 -08002339 EXPECT_EQ(pi1_context->realtime_event_time,
2340 header_realtime_remote_time);
2341 EXPECT_EQ(pi1_context->monotonic_event_time,
2342 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002343
Austin Schuh61e973f2021-02-21 21:43:56 -08002344 // Time estimation isn't perfect, but we know the clocks were
2345 // identical when logged, so we know when this should have come back.
2346 // Confirm we got it when we expected.
2347 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2348 pi1_context->monotonic_event_time + 2 * network_delay +
2349 send_delay);
2350 });
2351 }
2352 for (std::pair<int, std::string> channel :
2353 shared()
2354 ? std::vector<
2355 std::pair<int, std::string>>{{-1,
2356 "/aos/remote_timestamps/pi1"}}
2357 : std::vector<std::pair<int, std::string>>{
2358 {pi2_timestamp_channel,
2359 "/aos/remote_timestamps/pi1/pi2/aos/"
2360 "aos-message_bridge-Timestamp"}}) {
2361 pi2_event_loop->MakeWatcher(
2362 channel.second,
2363 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2364 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2365 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2366 &pong_on_pi1_fetcher, network_delay, send_delay,
2367 channel_index = channel.first](const RemoteMessage &header) {
2368 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2369 chrono::nanoseconds(header.monotonic_sent_time()));
2370 const aos::realtime_clock::time_point header_realtime_sent_time(
2371 chrono::nanoseconds(header.realtime_sent_time()));
2372 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2373 chrono::nanoseconds(header.monotonic_remote_time()));
2374 const aos::realtime_clock::time_point header_realtime_remote_time(
2375 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002376
Austin Schuh61e973f2021-02-21 21:43:56 -08002377 if (channel_index != -1) {
2378 ASSERT_EQ(channel_index, header.channel_index());
2379 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002380
Austin Schuh61e973f2021-02-21 21:43:56 -08002381 const Context *pi2_context = nullptr;
2382 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002383
Austin Schuh61e973f2021-02-21 21:43:56 -08002384 if (header.channel_index() == pi2_timestamp_channel) {
2385 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2386 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2387 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2388 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2389 } else if (header.channel_index() == pong_timestamp_channel) {
2390 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2391 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2392 pi2_context = &pong_on_pi2_fetcher.context();
2393 pi1_context = &pong_on_pi1_fetcher.context();
2394 } else {
2395 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2396 << configuration::CleanedChannelToString(
2397 pi2_event_loop->configuration()->channels()->Get(
2398 header.channel_index()));
2399 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002400
Austin Schuh61e973f2021-02-21 21:43:56 -08002401 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002402 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2403 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002404
Austin Schuh61e973f2021-02-21 21:43:56 -08002405 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2406 EXPECT_EQ(pi1_context->remote_queue_index,
2407 header.remote_queue_index());
2408 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002409
Austin Schuh61e973f2021-02-21 21:43:56 -08002410 EXPECT_EQ(pi1_context->monotonic_event_time,
2411 header_monotonic_sent_time);
2412 EXPECT_EQ(pi1_context->realtime_event_time,
2413 header_realtime_sent_time);
2414 EXPECT_EQ(pi1_context->realtime_remote_time,
2415 header_realtime_remote_time);
2416 EXPECT_EQ(pi1_context->monotonic_remote_time,
2417 header_monotonic_remote_time);
2418
2419 EXPECT_EQ(pi2_context->realtime_event_time,
2420 header_realtime_remote_time);
2421 EXPECT_EQ(pi2_context->monotonic_event_time,
2422 header_monotonic_remote_time);
2423
2424 // Time estimation isn't perfect, but we know the clocks were
2425 // identical when logged, so we know when this should have come back.
2426 // Confirm we got it when we expected.
2427 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2428 pi2_context->monotonic_event_time + 2 * network_delay +
2429 send_delay);
2430 });
2431 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002432
2433 // And confirm we can re-create a log again, while checking the contents.
2434 {
2435 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002436 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002437 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002438 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002439
Austin Schuh25b46712021-01-03 00:04:38 -08002440 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2441 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002442
2443 log_reader_factory.Run();
2444 }
2445
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002446 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002447
2448 // And verify that we can run the LogReader over the relogged files without
2449 // hitting any fatal errors.
2450 {
2451 LogReader relogged_reader(SortParts(
2452 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2453 relogged_reader.Register();
2454
2455 relogged_reader.event_loop_factory()->Run();
2456 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002457}
2458
Austin Schuh315b96b2020-12-11 21:21:12 -08002459// Tests that we properly populate and extract the logger_start time by setting
2460// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002461TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002462 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002463 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002464 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002465 {
2466 LoggerState pi1_logger = MakeLogger(pi1_);
2467 LoggerState pi2_logger = MakeLogger(pi2_);
2468
Austin Schuh315b96b2020-12-11 21:21:12 -08002469 StartLogger(&pi1_logger);
2470 StartLogger(&pi2_logger);
2471
2472 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002473
2474 pi1_logger.AppendAllFilenames(&actual_filenames);
2475 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002476 }
2477
Austin Schuhf5f99f32022-02-07 20:05:37 -08002478 ASSERT_THAT(actual_filenames,
2479 ::testing::UnorderedElementsAreArray(logfiles_));
2480
Austin Schuh315b96b2020-12-11 21:21:12 -08002481 for (const LogFile &log_file : SortParts(logfiles_)) {
2482 for (const LogParts &log_part : log_file.parts) {
2483 if (log_part.node == log_file.logger_node) {
2484 EXPECT_EQ(log_part.logger_monotonic_start_time,
2485 aos::monotonic_clock::min_time);
2486 EXPECT_EQ(log_part.logger_realtime_start_time,
2487 aos::realtime_clock::min_time);
2488 } else {
2489 const chrono::seconds offset = log_file.logger_node == "pi1"
2490 ? -chrono::seconds(1000)
2491 : chrono::seconds(1000);
2492 EXPECT_EQ(log_part.logger_monotonic_start_time,
2493 log_part.monotonic_start_time + offset);
2494 EXPECT_EQ(log_part.logger_realtime_start_time,
2495 log_file.realtime_start_time +
2496 (log_part.logger_monotonic_start_time -
2497 log_file.monotonic_start_time));
2498 }
2499 }
2500 }
2501}
2502
Austin Schuh6bb8a822021-03-31 23:04:39 -07002503// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002504TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002505 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2506 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002507 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002508 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002509 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2510 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2511 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2512 LoggerState pi1_logger = MakeLogger(pi1_);
2513 LoggerState pi2_logger = MakeLogger(pi2_);
2514
2515 StartLogger(&pi1_logger);
2516 StartLogger(&pi2_logger);
2517
2518 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2519 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2520 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2521 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2522 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2523 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2524 for (auto &file : logfiles_) {
2525 struct stat s;
2526 EXPECT_EQ(0, stat(file.c_str(), &s));
2527 }
2528}
2529
2530// Test that renaming the file base dies.
2531TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2532 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002533 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002534 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002535 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2536 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2537 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2538 LoggerState pi1_logger = MakeLogger(pi1_);
2539 StartLogger(&pi1_logger);
2540 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2541 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2542 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2543 "Rename of file base from");
2544}
2545
Austin Schuh8bd96322020-02-13 21:18:22 -08002546// TODO(austin): We can write a test which recreates a logfile and confirms that
2547// we get it back. That is the ultimate test.
2548
Austin Schuh315b96b2020-12-11 21:21:12 -08002549// Tests that we properly recreate forwarded timestamps when replaying a log.
2550// This should be enough that we can then re-run the logger and get a valid log
2551// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002552TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002553 std::vector<std::string> actual_filenames;
2554
Austin Schuh58646e22021-08-23 23:51:46 -07002555 const UUID pi1_boot0 = UUID::Random();
2556 const UUID pi2_boot0 = UUID::Random();
2557 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002558 {
Austin Schuh58646e22021-08-23 23:51:46 -07002559 CHECK_EQ(pi1_index_, 0u);
2560 CHECK_EQ(pi2_index_, 1u);
2561
2562 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2563 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2564 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2565
2566 time_converter_.AddNextTimestamp(
2567 distributed_clock::epoch(),
2568 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2569 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2570 time_converter_.AddNextTimestamp(
2571 distributed_clock::epoch() + reboot_time,
2572 {BootTimestamp::epoch() + reboot_time,
2573 BootTimestamp{
2574 .boot = 1,
2575 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2576 }
2577
2578 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002579 LoggerState pi1_logger = MakeLogger(pi1_);
2580
2581 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002582 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2583 pi1_boot0);
2584 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2585 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002586
2587 StartLogger(&pi1_logger);
2588
2589 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2590
Austin Schuh58646e22021-08-23 23:51:46 -07002591 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002592
2593 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002594 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2595 pi1_boot0);
2596 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2597 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002598
2599 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002600 }
2601
Austin Schuhbfe6c572022-01-27 20:48:20 -08002602 std::sort(actual_filenames.begin(), actual_filenames.end());
2603 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2604 ASSERT_THAT(actual_filenames,
2605 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2606
Austin Schuh72211ae2021-08-05 14:02:30 -07002607 // Confirm that our new oldest timestamps properly update as we reboot and
2608 // rotate.
2609 for (const std::string &file : pi1_reboot_logfiles_) {
2610 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2611 ReadHeader(file);
2612 CHECK(log_header);
2613 if (log_header->message().has_configuration()) {
2614 continue;
2615 }
2616
Austin Schuh58646e22021-08-23 23:51:46 -07002617 const monotonic_clock::time_point monotonic_start_time =
2618 monotonic_clock::time_point(
2619 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2620 const UUID source_node_boot_uuid = UUID::FromString(
2621 log_header->message().source_node_boot_uuid()->string_view());
2622
Austin Schuh72211ae2021-08-05 14:02:30 -07002623 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002624 // The remote message channel should rotate later and have more parts.
2625 // This only is true on the log files with shared remote messages.
2626 //
2627 // TODO(austin): I'm not the most thrilled with this test pattern... It
2628 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002629 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2630 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002631 switch (log_header->message().parts_index()) {
2632 case 0:
2633 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2634 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2635 break;
2636 case 1:
2637 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2638 ASSERT_EQ(monotonic_start_time,
2639 monotonic_clock::epoch() + chrono::seconds(1));
2640 break;
2641 case 2:
2642 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2643 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2644 break;
2645 case 3:
2646 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2647 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2648 chrono::nanoseconds(2322999462))
2649 << " on " << file;
2650 break;
2651 default:
2652 FAIL();
2653 break;
2654 }
2655 } else {
2656 switch (log_header->message().parts_index()) {
2657 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002658 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002659 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2660 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2661 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002662 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002663 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2664 ASSERT_EQ(monotonic_start_time,
2665 monotonic_clock::epoch() + chrono::seconds(1));
2666 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002667 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002668 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002669 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2670 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2671 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002672 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002673 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2674 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2675 chrono::nanoseconds(2322999462))
2676 << " on " << file;
2677 break;
2678 default:
2679 FAIL();
2680 break;
2681 }
Austin Schuh58646e22021-08-23 23:51:46 -07002682 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002683 continue;
2684 }
2685 SCOPED_TRACE(file);
2686 SCOPED_TRACE(aos::FlatbufferToJson(
2687 *log_header, {.multi_line = true, .max_vector_size = 100}));
2688 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2689 ASSERT_EQ(
2690 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2691 EXPECT_EQ(
2692 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2693 monotonic_clock::max_time.time_since_epoch().count());
2694 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2695 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2696 2u);
2697 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2698 monotonic_clock::max_time.time_since_epoch().count());
2699 ASSERT_TRUE(log_header->message()
2700 .has_oldest_remote_unreliable_monotonic_timestamps());
2701 ASSERT_EQ(log_header->message()
2702 .oldest_remote_unreliable_monotonic_timestamps()
2703 ->size(),
2704 2u);
2705 EXPECT_EQ(log_header->message()
2706 .oldest_remote_unreliable_monotonic_timestamps()
2707 ->Get(0),
2708 monotonic_clock::max_time.time_since_epoch().count());
2709 ASSERT_TRUE(log_header->message()
2710 .has_oldest_local_unreliable_monotonic_timestamps());
2711 ASSERT_EQ(log_header->message()
2712 .oldest_local_unreliable_monotonic_timestamps()
2713 ->size(),
2714 2u);
2715 EXPECT_EQ(log_header->message()
2716 .oldest_local_unreliable_monotonic_timestamps()
2717 ->Get(0),
2718 monotonic_clock::max_time.time_since_epoch().count());
2719
2720 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2721 monotonic_clock::time_point(chrono::nanoseconds(
2722 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2723 1)));
2724 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2725 monotonic_clock::time_point(chrono::nanoseconds(
2726 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2727 const monotonic_clock::time_point
2728 oldest_remote_unreliable_monotonic_timestamps =
2729 monotonic_clock::time_point(chrono::nanoseconds(
2730 log_header->message()
2731 .oldest_remote_unreliable_monotonic_timestamps()
2732 ->Get(1)));
2733 const monotonic_clock::time_point
2734 oldest_local_unreliable_monotonic_timestamps =
2735 monotonic_clock::time_point(chrono::nanoseconds(
2736 log_header->message()
2737 .oldest_local_unreliable_monotonic_timestamps()
2738 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002739 const monotonic_clock::time_point
2740 oldest_remote_reliable_monotonic_timestamps =
2741 monotonic_clock::time_point(chrono::nanoseconds(
2742 log_header->message()
2743 .oldest_remote_reliable_monotonic_timestamps()
2744 ->Get(1)));
2745 const monotonic_clock::time_point
2746 oldest_local_reliable_monotonic_timestamps =
2747 monotonic_clock::time_point(chrono::nanoseconds(
2748 log_header->message()
2749 .oldest_local_reliable_monotonic_timestamps()
2750 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002751 const monotonic_clock::time_point
2752 oldest_logger_remote_unreliable_monotonic_timestamps =
2753 monotonic_clock::time_point(chrono::nanoseconds(
2754 log_header->message()
2755 .oldest_logger_remote_unreliable_monotonic_timestamps()
2756 ->Get(0)));
2757 const monotonic_clock::time_point
2758 oldest_logger_local_unreliable_monotonic_timestamps =
2759 monotonic_clock::time_point(chrono::nanoseconds(
2760 log_header->message()
2761 .oldest_logger_local_unreliable_monotonic_timestamps()
2762 ->Get(0)));
2763 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2764 monotonic_clock::max_time);
2765 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2766 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002767 switch (log_header->message().parts_index()) {
2768 case 0:
2769 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2770 monotonic_clock::max_time);
2771 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2772 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2773 monotonic_clock::max_time);
2774 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2775 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002776 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2777 monotonic_clock::max_time);
2778 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2779 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002780 break;
2781 case 1:
2782 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2783 monotonic_clock::time_point(chrono::microseconds(90200)));
2784 EXPECT_EQ(oldest_local_monotonic_timestamps,
2785 monotonic_clock::time_point(chrono::microseconds(90350)));
2786 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2787 monotonic_clock::time_point(chrono::microseconds(90200)));
2788 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2789 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002790 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2791 monotonic_clock::max_time);
2792 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2793 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002794 break;
2795 case 2:
2796 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08002797 monotonic_clock::time_point(chrono::microseconds(90200)))
2798 << file;
2799 EXPECT_EQ(oldest_local_monotonic_timestamps,
2800 monotonic_clock::time_point(chrono::microseconds(90350)))
2801 << file;
2802 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2803 monotonic_clock::time_point(chrono::microseconds(90200)))
2804 << file;
2805 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2806 monotonic_clock::time_point(chrono::microseconds(90350)))
2807 << file;
2808 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2809 monotonic_clock::time_point(chrono::microseconds(100000)))
2810 << file;
2811 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2812 monotonic_clock::time_point(chrono::microseconds(100150)))
2813 << file;
2814 break;
2815 case 3:
2816 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002817 monotonic_clock::time_point(chrono::milliseconds(1323) +
2818 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002819 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002820 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002821 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002822 monotonic_clock::time_point(chrono::milliseconds(1323) +
2823 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002824 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2825 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002826 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2827 monotonic_clock::max_time)
2828 << file;
2829 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2830 monotonic_clock::max_time)
2831 << file;
2832 break;
2833 case 4:
2834 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2835 monotonic_clock::time_point(chrono::milliseconds(1323) +
2836 chrono::microseconds(200)));
2837 EXPECT_EQ(oldest_local_monotonic_timestamps,
2838 monotonic_clock::time_point(chrono::microseconds(10100350)));
2839 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2840 monotonic_clock::time_point(chrono::milliseconds(1323) +
2841 chrono::microseconds(200)));
2842 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2843 monotonic_clock::time_point(chrono::microseconds(10100350)));
2844 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2845 monotonic_clock::time_point(chrono::microseconds(1423000)))
2846 << file;
2847 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2848 monotonic_clock::time_point(chrono::microseconds(10200150)))
2849 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07002850 break;
2851 default:
2852 FAIL();
2853 break;
2854 }
2855 }
2856
Austin Schuh315b96b2020-12-11 21:21:12 -08002857 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002858 {
2859 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002860
Austin Schuh58646e22021-08-23 23:51:46 -07002861 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2862 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002863
Austin Schuh58646e22021-08-23 23:51:46 -07002864 // This sends out the fetched messages and advances time to the start of
2865 // the log file.
2866 reader.Register(&log_reader_factory);
2867
2868 log_reader_factory.Run();
2869
2870 reader.Deregister();
2871 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002872}
2873
Austin Schuh5e14d842022-01-21 12:02:15 -08002874// Tests that we can sort a log which only has timestamps from the remote
2875// because the local message_bridge_client failed to connect.
2876TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
2877 const UUID pi1_boot0 = UUID::Random();
2878 const UUID pi2_boot0 = UUID::Random();
2879 const UUID pi2_boot1 = UUID::Random();
2880 {
2881 CHECK_EQ(pi1_index_, 0u);
2882 CHECK_EQ(pi2_index_, 1u);
2883
2884 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2885 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2886 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2887
2888 time_converter_.AddNextTimestamp(
2889 distributed_clock::epoch(),
2890 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2891 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2892 time_converter_.AddNextTimestamp(
2893 distributed_clock::epoch() + reboot_time,
2894 {BootTimestamp::epoch() + reboot_time,
2895 BootTimestamp{
2896 .boot = 1,
2897 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2898 }
2899 pi2_->Disconnect(pi1_->node());
2900
2901 std::vector<std::string> filenames;
2902 {
2903 LoggerState pi1_logger = MakeLogger(pi1_);
2904
2905 event_loop_factory_.RunFor(chrono::milliseconds(95));
2906 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2907 pi1_boot0);
2908 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2909 pi2_boot0);
2910
2911 StartLogger(&pi1_logger);
2912
2913 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2914
2915 VLOG(1) << "Reboot now!";
2916
2917 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2918 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2919 pi1_boot0);
2920 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2921 pi2_boot1);
2922 pi1_logger.AppendAllFilenames(&filenames);
2923 }
2924
Austin Schuhbfe6c572022-01-27 20:48:20 -08002925 std::sort(filenames.begin(), filenames.end());
2926
Austin Schuh5e14d842022-01-21 12:02:15 -08002927 // Confirm that our new oldest timestamps properly update as we reboot and
2928 // rotate.
2929 size_t timestamp_file_count = 0;
2930 for (const std::string &file : filenames) {
2931 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2932 ReadHeader(file);
2933 CHECK(log_header);
2934
2935 if (log_header->message().has_configuration()) {
2936 continue;
2937 }
2938
2939 const monotonic_clock::time_point monotonic_start_time =
2940 monotonic_clock::time_point(
2941 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2942 const UUID source_node_boot_uuid = UUID::FromString(
2943 log_header->message().source_node_boot_uuid()->string_view());
2944
2945 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2946 ASSERT_EQ(
2947 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2948 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2949 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2950 2u);
2951 ASSERT_TRUE(log_header->message()
2952 .has_oldest_remote_unreliable_monotonic_timestamps());
2953 ASSERT_EQ(log_header->message()
2954 .oldest_remote_unreliable_monotonic_timestamps()
2955 ->size(),
2956 2u);
2957 ASSERT_TRUE(log_header->message()
2958 .has_oldest_local_unreliable_monotonic_timestamps());
2959 ASSERT_EQ(log_header->message()
2960 .oldest_local_unreliable_monotonic_timestamps()
2961 ->size(),
2962 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08002963 ASSERT_TRUE(log_header->message()
2964 .has_oldest_remote_reliable_monotonic_timestamps());
2965 ASSERT_EQ(log_header->message()
2966 .oldest_remote_reliable_monotonic_timestamps()
2967 ->size(),
2968 2u);
2969 ASSERT_TRUE(log_header->message()
2970 .has_oldest_local_reliable_monotonic_timestamps());
2971 ASSERT_EQ(log_header->message()
2972 .oldest_local_reliable_monotonic_timestamps()
2973 ->size(),
2974 2u);
2975
2976 ASSERT_TRUE(
2977 log_header->message()
2978 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
2979 ASSERT_EQ(log_header->message()
2980 .oldest_logger_remote_unreliable_monotonic_timestamps()
2981 ->size(),
2982 2u);
2983 ASSERT_TRUE(log_header->message()
2984 .has_oldest_logger_local_unreliable_monotonic_timestamps());
2985 ASSERT_EQ(log_header->message()
2986 .oldest_logger_local_unreliable_monotonic_timestamps()
2987 ->size(),
2988 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08002989
2990 if (log_header->message().node()->name()->string_view() != "pi1") {
2991 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
2992 std::string::npos);
2993
2994 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2995 ReadNthMessage(file, 0);
2996 CHECK(msg);
2997
2998 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2999 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
3000
3001 const monotonic_clock::time_point
3002 expected_oldest_local_monotonic_timestamps(
3003 chrono::nanoseconds(msg->message().monotonic_sent_time()));
3004 const monotonic_clock::time_point
3005 expected_oldest_remote_monotonic_timestamps(
3006 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003007 const monotonic_clock::time_point
3008 expected_oldest_timestamp_monotonic_timestamps(
3009 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08003010
3011 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
3012 monotonic_clock::min_time);
3013 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
3014 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003015 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
3016 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08003017
3018 ++timestamp_file_count;
3019 // Since the log file is from the perspective of the other node,
3020 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3021 monotonic_clock::time_point(chrono::nanoseconds(
3022 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3023 0)));
3024 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3025 monotonic_clock::time_point(chrono::nanoseconds(
3026 log_header->message().oldest_local_monotonic_timestamps()->Get(
3027 0)));
3028 const monotonic_clock::time_point
3029 oldest_remote_unreliable_monotonic_timestamps =
3030 monotonic_clock::time_point(chrono::nanoseconds(
3031 log_header->message()
3032 .oldest_remote_unreliable_monotonic_timestamps()
3033 ->Get(0)));
3034 const monotonic_clock::time_point
3035 oldest_local_unreliable_monotonic_timestamps =
3036 monotonic_clock::time_point(chrono::nanoseconds(
3037 log_header->message()
3038 .oldest_local_unreliable_monotonic_timestamps()
3039 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003040 const monotonic_clock::time_point
3041 oldest_remote_reliable_monotonic_timestamps =
3042 monotonic_clock::time_point(chrono::nanoseconds(
3043 log_header->message()
3044 .oldest_remote_reliable_monotonic_timestamps()
3045 ->Get(0)));
3046 const monotonic_clock::time_point
3047 oldest_local_reliable_monotonic_timestamps =
3048 monotonic_clock::time_point(chrono::nanoseconds(
3049 log_header->message()
3050 .oldest_local_reliable_monotonic_timestamps()
3051 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003052 const monotonic_clock::time_point
3053 oldest_logger_remote_unreliable_monotonic_timestamps =
3054 monotonic_clock::time_point(chrono::nanoseconds(
3055 log_header->message()
3056 .oldest_logger_remote_unreliable_monotonic_timestamps()
3057 ->Get(1)));
3058 const monotonic_clock::time_point
3059 oldest_logger_local_unreliable_monotonic_timestamps =
3060 monotonic_clock::time_point(chrono::nanoseconds(
3061 log_header->message()
3062 .oldest_logger_local_unreliable_monotonic_timestamps()
3063 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08003064
Austin Schuh01f3b392022-01-25 20:03:09 -08003065 const Channel *channel =
3066 event_loop_factory_.configuration()->channels()->Get(
3067 msg->message().channel_index());
3068 const Connection *connection = configuration::ConnectionToNode(
3069 channel, configuration::GetNode(
3070 event_loop_factory_.configuration(),
3071 log_header->message().node()->name()->string_view()));
3072
3073 const bool reliable = connection->time_to_live() == 0;
3074
Austin Schuhf5f99f32022-02-07 20:05:37 -08003075 SCOPED_TRACE(file);
3076 SCOPED_TRACE(aos::FlatbufferToJson(
3077 *log_header, {.multi_line = true, .max_vector_size = 100}));
3078
Austin Schuh01f3b392022-01-25 20:03:09 -08003079 if (shared()) {
3080 // Confirm that the oldest timestamps match what we expect. Based on
3081 // what we are doing, we know that the oldest time is the first
3082 // message's time.
3083 //
3084 // This makes the test robust to both the split and combined config
3085 // tests.
3086 switch (log_header->message().parts_index()) {
3087 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08003088 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3089 expected_oldest_remote_monotonic_timestamps);
3090 EXPECT_EQ(oldest_local_monotonic_timestamps,
3091 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003092 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3093 expected_oldest_local_monotonic_timestamps) << file;
3094 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3095 expected_oldest_timestamp_monotonic_timestamps) << file;
3096
Austin Schuh01f3b392022-01-25 20:03:09 -08003097 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003098 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3099 expected_oldest_remote_monotonic_timestamps);
3100 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3101 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08003102 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3103 monotonic_clock::max_time);
3104 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3105 monotonic_clock::max_time);
3106 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003107 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3108 monotonic_clock::max_time);
3109 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3110 monotonic_clock::max_time);
3111 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3112 expected_oldest_remote_monotonic_timestamps);
3113 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3114 expected_oldest_local_monotonic_timestamps);
3115 }
3116 break;
3117 case 1:
3118 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3119 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3120 EXPECT_EQ(oldest_local_monotonic_timestamps,
3121 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003122 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3123 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3124 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3125 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003126 if (reliable) {
3127 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3128 expected_oldest_remote_monotonic_timestamps);
3129 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3130 expected_oldest_local_monotonic_timestamps);
3131 EXPECT_EQ(
3132 oldest_remote_unreliable_monotonic_timestamps,
3133 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3134 EXPECT_EQ(
3135 oldest_local_unreliable_monotonic_timestamps,
3136 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3137 } else {
3138 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3139 monotonic_clock::max_time);
3140 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3141 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003142 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3143 expected_oldest_remote_monotonic_timestamps);
3144 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3145 expected_oldest_local_monotonic_timestamps);
3146 }
3147 break;
3148 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003149 EXPECT_EQ(
3150 oldest_remote_monotonic_timestamps,
3151 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3152 EXPECT_EQ(
3153 oldest_local_monotonic_timestamps,
3154 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003155 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3156 expected_oldest_local_monotonic_timestamps) << file;
3157 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3158 expected_oldest_timestamp_monotonic_timestamps) << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003159 if (reliable) {
3160 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3161 expected_oldest_remote_monotonic_timestamps);
3162 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3163 expected_oldest_local_monotonic_timestamps);
3164 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3165 monotonic_clock::max_time);
3166 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3167 monotonic_clock::max_time);
3168 } else {
3169 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3170 monotonic_clock::max_time);
3171 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3172 monotonic_clock::max_time);
3173 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3174 expected_oldest_remote_monotonic_timestamps);
3175 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3176 expected_oldest_local_monotonic_timestamps);
3177 }
3178 break;
3179
3180 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003181 EXPECT_EQ(
3182 oldest_remote_monotonic_timestamps,
3183 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3184 EXPECT_EQ(
3185 oldest_local_monotonic_timestamps,
3186 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3187 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3188 expected_oldest_remote_monotonic_timestamps);
3189 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3190 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003191 EXPECT_EQ(
3192 oldest_logger_remote_unreliable_monotonic_timestamps,
3193 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3194 EXPECT_EQ(
3195 oldest_logger_local_unreliable_monotonic_timestamps,
3196 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003197 break;
3198 default:
3199 FAIL();
3200 break;
3201 }
3202
3203 switch (log_header->message().parts_index()) {
3204 case 0:
3205 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3206 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3207 break;
3208 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003209 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003210 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3211 break;
3212 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003213 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3214 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3215 break;
3216 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003217 if (shared()) {
3218 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3219 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003220 break;
3221 }
3222 [[fallthrough]];
3223 default:
3224 FAIL();
3225 break;
3226 }
3227 } else {
3228 switch (log_header->message().parts_index()) {
3229 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003230 if (reliable) {
3231 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3232 monotonic_clock::max_time);
3233 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3234 monotonic_clock::max_time);
3235 EXPECT_EQ(
3236 oldest_logger_remote_unreliable_monotonic_timestamps,
3237 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3238 << file;
3239 EXPECT_EQ(
3240 oldest_logger_local_unreliable_monotonic_timestamps,
3241 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3242 << file;
3243 } else {
3244 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3245 expected_oldest_remote_monotonic_timestamps);
3246 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3247 expected_oldest_local_monotonic_timestamps);
3248 EXPECT_EQ(
3249 oldest_logger_remote_unreliable_monotonic_timestamps,
3250 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3251 << file;
3252 EXPECT_EQ(
3253 oldest_logger_local_unreliable_monotonic_timestamps,
3254 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3255 << file;
3256 }
3257 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003258 case 1:
3259 if (reliable) {
3260 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3261 monotonic_clock::max_time);
3262 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3263 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003264 EXPECT_EQ(
3265 oldest_logger_remote_unreliable_monotonic_timestamps,
3266 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3267 EXPECT_EQ(
3268 oldest_logger_local_unreliable_monotonic_timestamps,
3269 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003270 } else {
3271 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3272 expected_oldest_remote_monotonic_timestamps);
3273 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3274 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003275 EXPECT_EQ(
3276 oldest_logger_remote_unreliable_monotonic_timestamps,
3277 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3278 EXPECT_EQ(
3279 oldest_logger_local_unreliable_monotonic_timestamps,
3280 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003281 }
3282 break;
3283 default:
3284 FAIL();
3285 break;
3286 }
3287
3288 switch (log_header->message().parts_index()) {
3289 case 0:
3290 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3291 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3292 break;
3293 case 1:
3294 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3295 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3296 break;
3297 default:
3298 FAIL();
3299 break;
3300 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003301 }
3302
3303 continue;
3304 }
3305 EXPECT_EQ(
3306 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3307 monotonic_clock::max_time.time_since_epoch().count());
3308 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3309 monotonic_clock::max_time.time_since_epoch().count());
3310 EXPECT_EQ(log_header->message()
3311 .oldest_remote_unreliable_monotonic_timestamps()
3312 ->Get(0),
3313 monotonic_clock::max_time.time_since_epoch().count());
3314 EXPECT_EQ(log_header->message()
3315 .oldest_local_unreliable_monotonic_timestamps()
3316 ->Get(0),
3317 monotonic_clock::max_time.time_since_epoch().count());
3318
3319 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3320 monotonic_clock::time_point(chrono::nanoseconds(
3321 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3322 1)));
3323 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3324 monotonic_clock::time_point(chrono::nanoseconds(
3325 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3326 const monotonic_clock::time_point
3327 oldest_remote_unreliable_monotonic_timestamps =
3328 monotonic_clock::time_point(chrono::nanoseconds(
3329 log_header->message()
3330 .oldest_remote_unreliable_monotonic_timestamps()
3331 ->Get(1)));
3332 const monotonic_clock::time_point
3333 oldest_local_unreliable_monotonic_timestamps =
3334 monotonic_clock::time_point(chrono::nanoseconds(
3335 log_header->message()
3336 .oldest_local_unreliable_monotonic_timestamps()
3337 ->Get(1)));
3338 switch (log_header->message().parts_index()) {
3339 case 0:
3340 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3341 monotonic_clock::max_time);
3342 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3343 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3344 monotonic_clock::max_time);
3345 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3346 monotonic_clock::max_time);
3347 break;
3348 default:
3349 FAIL();
3350 break;
3351 }
3352 }
3353
Austin Schuh01f3b392022-01-25 20:03:09 -08003354 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003355 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003356 } else {
3357 EXPECT_EQ(timestamp_file_count, 4u);
3358 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003359
Austin Schuhe2373e22022-01-21 12:25:17 -08003360 // Confirm that we can actually sort the resulting log and read it.
3361 {
3362 LogReader reader(SortParts(filenames));
3363
3364 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3365 log_reader_factory.set_send_delay(chrono::microseconds(0));
3366
3367 // This sends out the fetched messages and advances time to the start of
3368 // the log file.
3369 reader.Register(&log_reader_factory);
3370
3371 log_reader_factory.Run();
3372
3373 reader.Deregister();
3374 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003375}
3376
Austin Schuhc9049732020-12-21 22:27:15 -08003377// Tests that we properly handle one direction of message_bridge being
3378// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003379TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003380 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003381 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003382 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003383
3384 time_converter_.AddMonotonic(
3385 {chrono::milliseconds(10000),
3386 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003387 {
3388 LoggerState pi1_logger = MakeLogger(pi1_);
3389
3390 event_loop_factory_.RunFor(chrono::milliseconds(95));
3391
3392 StartLogger(&pi1_logger);
3393
3394 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3395 }
3396
3397 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3398 // to confirm the right thing happened.
3399 ConfirmReadable(pi1_single_direction_logfiles_);
3400}
3401
3402// Tests that we properly handle one direction of message_bridge being
3403// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003404TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003405 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003406 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003407 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003408
3409 time_converter_.AddMonotonic(
3410 {chrono::milliseconds(10000),
3411 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3412 {
3413 LoggerState pi1_logger = MakeLogger(pi1_);
3414
3415 event_loop_factory_.RunFor(chrono::milliseconds(95));
3416
3417 StartLogger(&pi1_logger);
3418
3419 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3420 }
3421
3422 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3423 // to confirm the right thing happened.
3424 ConfirmReadable(pi1_single_direction_logfiles_);
3425}
3426
Austin Schuhe9f00232021-09-16 18:04:23 -07003427// Tests that we explode if someone passes in a part file twice with a better
3428// error than an out of order error.
3429TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3430 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003431 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003432 {
3433 LoggerState pi1_logger = MakeLogger(pi1_);
3434
3435 event_loop_factory_.RunFor(chrono::milliseconds(95));
3436
3437 StartLogger(&pi1_logger);
3438
3439 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3440 }
3441
3442 std::vector<std::string> duplicates;
3443 for (const std::string &f : pi1_single_direction_logfiles_) {
3444 duplicates.emplace_back(f);
3445 duplicates.emplace_back(f);
3446 }
3447 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3448}
3449
Austin Schuh87dd3832021-01-01 23:07:31 -08003450// Tests that we properly handle a dead node. Do this by just disconnecting it
3451// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003452TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003453 pi1_->Disconnect(pi2_->node());
3454 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003455 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003456 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003457 {
3458 LoggerState pi1_logger = MakeLogger(pi1_);
3459
3460 event_loop_factory_.RunFor(chrono::milliseconds(95));
3461
3462 StartLogger(&pi1_logger);
3463
3464 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3465 }
3466
3467 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3468 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003469 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003470}
3471
Austin Schuhcdd90272021-03-15 12:46:16 -07003472constexpr std::string_view kCombinedConfigSha1(
James Kuszmaul78514332022-04-06 15:08:34 -07003473 "ad71114d104afea6cc400f3a968bb69e394681183fd42655d4efcdc8f4cd8911");
Austin Schuhcdd90272021-03-15 12:46:16 -07003474constexpr std::string_view kSplitConfigSha1(
James Kuszmaul78514332022-04-06 15:08:34 -07003475 "cdd60ecc4423ef2450bf67bed059f2f28f0e8ff6819b94a2194d825a6b15fe91");
Austin Schuhcdd90272021-03-15 12:46:16 -07003476
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003477INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003478 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003479 ::testing::Combine(::testing::Values(
3480 ConfigParams{
3481 "multinode_pingpong_combined_config.json", true,
3482 kCombinedConfigSha1},
3483 ConfigParams{"multinode_pingpong_split_config.json",
3484 false, kSplitConfigSha1}),
3485 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003486
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003487INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003488 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003489 ::testing::Combine(::testing::Values(
3490 ConfigParams{
3491 "multinode_pingpong_combined_config.json", true,
3492 kCombinedConfigSha1},
3493 ConfigParams{"multinode_pingpong_split_config.json",
3494 false, kSplitConfigSha1}),
3495 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003496
Austin Schuh5b728b72021-06-16 14:57:15 -07003497// Tests that we can relog with a different config. This makes most sense when
3498// you are trying to edit a log and want to use channel renaming + the original
3499// config in the new log.
3500TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3501 time_converter_.StartEqual();
3502 {
3503 LoggerState pi1_logger = MakeLogger(pi1_);
3504 LoggerState pi2_logger = MakeLogger(pi2_);
3505
3506 event_loop_factory_.RunFor(chrono::milliseconds(95));
3507
3508 StartLogger(&pi1_logger);
3509 StartLogger(&pi2_logger);
3510
3511 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3512 }
3513
3514 LogReader reader(SortParts(logfiles_));
3515 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3516
3517 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3518 log_reader_factory.set_send_delay(chrono::microseconds(0));
3519
3520 // This sends out the fetched messages and advances time to the start of the
3521 // log file.
3522 reader.Register(&log_reader_factory);
3523
3524 const Node *pi1 =
3525 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3526 const Node *pi2 =
3527 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3528
3529 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3530 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3531 LOG(INFO) << "now pi1 "
3532 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3533 LOG(INFO) << "now pi2 "
3534 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3535
3536 EXPECT_THAT(reader.LoggedNodes(),
3537 ::testing::ElementsAre(
3538 configuration::GetNode(reader.logged_configuration(), pi1),
3539 configuration::GetNode(reader.logged_configuration(), pi2)));
3540
3541 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3542
3543 // And confirm we can re-create a log again, while checking the contents.
3544 std::vector<std::string> log_files;
3545 {
3546 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003547 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003548 &log_reader_factory, reader.logged_configuration());
3549 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003550 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003551 &log_reader_factory, reader.logged_configuration());
3552
Austin Schuh3e20c692021-11-16 20:43:16 -08003553 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3554 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003555
3556 log_reader_factory.Run();
3557
3558 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3559 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3560 }
3561 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3562 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3563 }
3564 }
3565
3566 reader.Deregister();
3567
3568 // And verify that we can run the LogReader over the relogged files without
3569 // hitting any fatal errors.
3570 {
3571 LogReader relogged_reader(SortParts(log_files));
3572 relogged_reader.Register();
3573
3574 relogged_reader.event_loop_factory()->Run();
3575 }
3576}
Austin Schuha04efed2021-01-24 18:04:20 -08003577
Austin Schuh3e20c692021-11-16 20:43:16 -08003578// Tests that we properly replay a log where the start time for a node is before
3579// any data on the node. This can happen if the logger starts before data is
3580// published. While the scenario below is a bit convoluted, we have seen logs
3581// like this generated out in the wild.
3582TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3583 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3584 aos::configuration::ReadConfig(ArtifactPath(
3585 "aos/events/logging/multinode_pingpong_split3_config.json"));
3586 message_bridge::TestingTimeConverter time_converter(
3587 configuration::NodesCount(&config.message()));
3588 SimulatedEventLoopFactory event_loop_factory(&config.message());
3589 event_loop_factory.SetTimeConverter(&time_converter);
3590 NodeEventLoopFactory *const pi1 =
3591 event_loop_factory.GetNodeEventLoopFactory("pi1");
3592 const size_t pi1_index = configuration::GetNodeIndex(
3593 event_loop_factory.configuration(), pi1->node());
3594 NodeEventLoopFactory *const pi2 =
3595 event_loop_factory.GetNodeEventLoopFactory("pi2");
3596 const size_t pi2_index = configuration::GetNodeIndex(
3597 event_loop_factory.configuration(), pi2->node());
3598 NodeEventLoopFactory *const pi3 =
3599 event_loop_factory.GetNodeEventLoopFactory("pi3");
3600 const size_t pi3_index = configuration::GetNodeIndex(
3601 event_loop_factory.configuration(), pi3->node());
3602
3603 const std::string kLogfile1_1 =
3604 aos::testing::TestTmpDir() + "/multi_logfile1/";
3605 const std::string kLogfile2_1 =
3606 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3607 const std::string kLogfile2_2 =
3608 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3609 const std::string kLogfile3_1 =
3610 aos::testing::TestTmpDir() + "/multi_logfile3/";
3611 util::UnlinkRecursive(kLogfile1_1);
3612 util::UnlinkRecursive(kLogfile2_1);
3613 util::UnlinkRecursive(kLogfile2_2);
3614 util::UnlinkRecursive(kLogfile3_1);
3615 const UUID pi1_boot0 = UUID::Random();
3616 const UUID pi2_boot0 = UUID::Random();
3617 const UUID pi2_boot1 = UUID::Random();
3618 const UUID pi3_boot0 = UUID::Random();
3619 {
3620 CHECK_EQ(pi1_index, 0u);
3621 CHECK_EQ(pi2_index, 1u);
3622 CHECK_EQ(pi3_index, 2u);
3623
3624 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3625 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3626 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3627 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3628
3629 time_converter.AddNextTimestamp(
3630 distributed_clock::epoch(),
3631 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3632 BootTimestamp::epoch()});
3633 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3634 time_converter.AddNextTimestamp(
3635 distributed_clock::epoch() + reboot_time,
3636 {BootTimestamp::epoch() + reboot_time,
3637 BootTimestamp{
3638 .boot = 1,
3639 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3640 BootTimestamp::epoch() + reboot_time});
3641 }
3642
3643 // Make everything perfectly quiet.
3644 event_loop_factory.SkipTimingReport();
3645 event_loop_factory.DisableStatistics();
3646
3647 std::vector<std::string> filenames;
3648 {
3649 LoggerState pi1_logger = LoggerState::MakeLogger(
3650 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3651 LoggerState pi3_logger = LoggerState::MakeLogger(
3652 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3653 {
3654 // And now start the logger.
3655 LoggerState pi2_logger = LoggerState::MakeLogger(
3656 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3657
3658 event_loop_factory.RunFor(chrono::milliseconds(1000));
3659
3660 pi1_logger.StartLogger(kLogfile1_1);
3661 pi3_logger.StartLogger(kLogfile3_1);
3662 pi2_logger.StartLogger(kLogfile2_1);
3663
3664 event_loop_factory.RunFor(chrono::milliseconds(10000));
3665
3666 // Now that we've got a start time in the past, turn on data.
3667 event_loop_factory.EnableStatistics();
3668 std::unique_ptr<aos::EventLoop> ping_event_loop =
3669 pi1->MakeEventLoop("ping");
3670 Ping ping(ping_event_loop.get());
3671
3672 pi2->AlwaysStart<Pong>("pong");
3673
3674 event_loop_factory.RunFor(chrono::milliseconds(3000));
3675
3676 pi2_logger.AppendAllFilenames(&filenames);
3677
3678 // Stop logging on pi2 before rebooting and completely shut off all
3679 // messages on pi2.
3680 pi2->DisableStatistics();
3681 pi1->Disconnect(pi2->node());
3682 pi2->Disconnect(pi1->node());
3683 }
3684 event_loop_factory.RunFor(chrono::milliseconds(7000));
3685 // pi2 now reboots.
3686 {
3687 event_loop_factory.RunFor(chrono::milliseconds(1000));
3688
3689 // Start logging again on pi2 after it is up.
3690 LoggerState pi2_logger = LoggerState::MakeLogger(
3691 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3692 pi2_logger.StartLogger(kLogfile2_2);
3693
3694 event_loop_factory.RunFor(chrono::milliseconds(10000));
3695 // And, now that we have a start time in the log, turn data back on.
3696 pi2->EnableStatistics();
3697 pi1->Connect(pi2->node());
3698 pi2->Connect(pi1->node());
3699
3700 pi2->AlwaysStart<Pong>("pong");
3701 std::unique_ptr<aos::EventLoop> ping_event_loop =
3702 pi1->MakeEventLoop("ping");
3703 Ping ping(ping_event_loop.get());
3704
3705 event_loop_factory.RunFor(chrono::milliseconds(3000));
3706
3707 pi2_logger.AppendAllFilenames(&filenames);
3708 }
3709
3710 pi1_logger.AppendAllFilenames(&filenames);
3711 pi3_logger.AppendAllFilenames(&filenames);
3712 }
3713
3714 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3715 // to confirm the right thing happened.
3716 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003717 auto result = ConfirmReadable(filenames);
3718 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3719 chrono::seconds(1)));
3720 EXPECT_THAT(result[0].second,
3721 ::testing::ElementsAre(realtime_clock::epoch() +
3722 chrono::microseconds(34990350)));
3723
3724 EXPECT_THAT(result[1].first,
3725 ::testing::ElementsAre(
3726 realtime_clock::epoch() + chrono::seconds(1),
3727 realtime_clock::epoch() + chrono::microseconds(3323000)));
3728 EXPECT_THAT(result[1].second,
3729 ::testing::ElementsAre(
3730 realtime_clock::epoch() + chrono::microseconds(13990200),
3731 realtime_clock::epoch() + chrono::microseconds(16313200)));
3732
3733 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3734 chrono::seconds(1)));
3735 EXPECT_THAT(result[2].second,
3736 ::testing::ElementsAre(realtime_clock::epoch() +
3737 chrono::microseconds(34900150)));
Austin Schuh3e20c692021-11-16 20:43:16 -08003738}
3739
Austin Schuh5dd22842021-11-17 16:09:39 -08003740// Tests that local data before remote data after reboot is properly replayed.
3741// We only trigger a reboot in the timestamp interpolation function when solving
3742// the timestamp problem when we actually have a point in the function. This
3743// originally only happened when a point passes the noncausal filter. At the
3744// start of time for the second boot, if we aren't careful, we will have
3745// messages which need to be published at times before the boot. This happens
3746// when a local message is in the log before a forwarded message, so there is no
3747// point in the interpolation function. This delays the reboot. So, we need to
3748// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08003749TEST(MultinodeRebootLoggerTest,
3750 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08003751 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3752 aos::configuration::ReadConfig(ArtifactPath(
3753 "aos/events/logging/multinode_pingpong_split3_config.json"));
3754 message_bridge::TestingTimeConverter time_converter(
3755 configuration::NodesCount(&config.message()));
3756 SimulatedEventLoopFactory event_loop_factory(&config.message());
3757 event_loop_factory.SetTimeConverter(&time_converter);
3758 NodeEventLoopFactory *const pi1 =
3759 event_loop_factory.GetNodeEventLoopFactory("pi1");
3760 const size_t pi1_index = configuration::GetNodeIndex(
3761 event_loop_factory.configuration(), pi1->node());
3762 NodeEventLoopFactory *const pi2 =
3763 event_loop_factory.GetNodeEventLoopFactory("pi2");
3764 const size_t pi2_index = configuration::GetNodeIndex(
3765 event_loop_factory.configuration(), pi2->node());
3766 NodeEventLoopFactory *const pi3 =
3767 event_loop_factory.GetNodeEventLoopFactory("pi3");
3768 const size_t pi3_index = configuration::GetNodeIndex(
3769 event_loop_factory.configuration(), pi3->node());
3770
3771 const std::string kLogfile1_1 =
3772 aos::testing::TestTmpDir() + "/multi_logfile1/";
3773 const std::string kLogfile2_1 =
3774 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3775 const std::string kLogfile2_2 =
3776 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3777 const std::string kLogfile3_1 =
3778 aos::testing::TestTmpDir() + "/multi_logfile3/";
3779 util::UnlinkRecursive(kLogfile1_1);
3780 util::UnlinkRecursive(kLogfile2_1);
3781 util::UnlinkRecursive(kLogfile2_2);
3782 util::UnlinkRecursive(kLogfile3_1);
3783 const UUID pi1_boot0 = UUID::Random();
3784 const UUID pi2_boot0 = UUID::Random();
3785 const UUID pi2_boot1 = UUID::Random();
3786 const UUID pi3_boot0 = UUID::Random();
3787 {
3788 CHECK_EQ(pi1_index, 0u);
3789 CHECK_EQ(pi2_index, 1u);
3790 CHECK_EQ(pi3_index, 2u);
3791
3792 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3793 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3794 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3795 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3796
3797 time_converter.AddNextTimestamp(
3798 distributed_clock::epoch(),
3799 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3800 BootTimestamp::epoch()});
3801 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3802 time_converter.AddNextTimestamp(
3803 distributed_clock::epoch() + reboot_time,
3804 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003805 BootTimestamp{.boot = 1,
3806 .time = monotonic_clock::epoch() + reboot_time +
3807 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08003808 BootTimestamp::epoch() + reboot_time});
3809 }
3810
3811 std::vector<std::string> filenames;
3812 {
3813 LoggerState pi1_logger = LoggerState::MakeLogger(
3814 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3815 LoggerState pi3_logger = LoggerState::MakeLogger(
3816 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3817 {
3818 // And now start the logger.
3819 LoggerState pi2_logger = LoggerState::MakeLogger(
3820 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3821
3822 pi1_logger.StartLogger(kLogfile1_1);
3823 pi3_logger.StartLogger(kLogfile3_1);
3824 pi2_logger.StartLogger(kLogfile2_1);
3825
3826 event_loop_factory.RunFor(chrono::milliseconds(1005));
3827
3828 // Now that we've got a start time in the past, turn on data.
3829 std::unique_ptr<aos::EventLoop> ping_event_loop =
3830 pi1->MakeEventLoop("ping");
3831 Ping ping(ping_event_loop.get());
3832
3833 pi2->AlwaysStart<Pong>("pong");
3834
3835 event_loop_factory.RunFor(chrono::milliseconds(3000));
3836
3837 pi2_logger.AppendAllFilenames(&filenames);
3838
3839 // Disable any remote messages on pi2.
3840 pi1->Disconnect(pi2->node());
3841 pi2->Disconnect(pi1->node());
3842 }
3843 event_loop_factory.RunFor(chrono::milliseconds(995));
3844 // pi2 now reboots at 5 seconds.
3845 {
3846 event_loop_factory.RunFor(chrono::milliseconds(1000));
3847
3848 // Make local stuff happen before we start logging and connect the remote.
3849 pi2->AlwaysStart<Pong>("pong");
3850 std::unique_ptr<aos::EventLoop> ping_event_loop =
3851 pi1->MakeEventLoop("ping");
3852 Ping ping(ping_event_loop.get());
3853 event_loop_factory.RunFor(chrono::milliseconds(1005));
3854
3855 // Start logging again on pi2 after it is up.
3856 LoggerState pi2_logger = LoggerState::MakeLogger(
3857 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3858 pi2_logger.StartLogger(kLogfile2_2);
3859
3860 // And allow remote messages now that we have some local ones.
3861 pi1->Connect(pi2->node());
3862 pi2->Connect(pi1->node());
3863
3864 event_loop_factory.RunFor(chrono::milliseconds(1000));
3865
3866 event_loop_factory.RunFor(chrono::milliseconds(3000));
3867
3868 pi2_logger.AppendAllFilenames(&filenames);
3869 }
3870
3871 pi1_logger.AppendAllFilenames(&filenames);
3872 pi3_logger.AppendAllFilenames(&filenames);
3873 }
3874
3875 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3876 // to confirm the right thing happened.
3877 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003878 auto result = ConfirmReadable(filenames);
3879
3880 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
3881 EXPECT_THAT(result[0].second,
3882 ::testing::ElementsAre(realtime_clock::epoch() +
3883 chrono::microseconds(11000350)));
3884
3885 EXPECT_THAT(result[1].first,
3886 ::testing::ElementsAre(
3887 realtime_clock::epoch(),
3888 realtime_clock::epoch() + chrono::microseconds(107005000)));
3889 EXPECT_THAT(result[1].second,
3890 ::testing::ElementsAre(
3891 realtime_clock::epoch() + chrono::microseconds(4000150),
3892 realtime_clock::epoch() + chrono::microseconds(111000200)));
3893
3894 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
3895 EXPECT_THAT(result[2].second,
3896 ::testing::ElementsAre(realtime_clock::epoch() +
3897 chrono::microseconds(11000150)));
3898
3899 auto start_stop_result = ConfirmReadable(
3900 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
3901 realtime_clock::epoch() + chrono::milliseconds(3000));
3902
3903 EXPECT_THAT(start_stop_result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3904 chrono::seconds(2)));
3905 EXPECT_THAT(start_stop_result[0].second, ::testing::ElementsAre(realtime_clock::epoch() +
3906 chrono::seconds(3)));
3907 EXPECT_THAT(start_stop_result[1].first, ::testing::ElementsAre(realtime_clock::epoch() +
3908 chrono::seconds(2)));
3909 EXPECT_THAT(start_stop_result[1].second, ::testing::ElementsAre(realtime_clock::epoch() +
3910 chrono::seconds(3)));
3911 EXPECT_THAT(start_stop_result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3912 chrono::seconds(2)));
3913 EXPECT_THAT(start_stop_result[2].second, ::testing::ElementsAre(realtime_clock::epoch() +
3914 chrono::seconds(3)));
Austin Schuh5dd22842021-11-17 16:09:39 -08003915}
3916
Austin Schuhe33c08d2022-02-03 18:15:21 -08003917// Tests that setting the start and stop flags across a reboot works as
3918// expected.
3919TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
3920 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3921 aos::configuration::ReadConfig(ArtifactPath(
3922 "aos/events/logging/multinode_pingpong_split3_config.json"));
3923 message_bridge::TestingTimeConverter time_converter(
3924 configuration::NodesCount(&config.message()));
3925 SimulatedEventLoopFactory event_loop_factory(&config.message());
3926 event_loop_factory.SetTimeConverter(&time_converter);
3927 NodeEventLoopFactory *const pi1 =
3928 event_loop_factory.GetNodeEventLoopFactory("pi1");
3929 const size_t pi1_index = configuration::GetNodeIndex(
3930 event_loop_factory.configuration(), pi1->node());
3931 NodeEventLoopFactory *const pi2 =
3932 event_loop_factory.GetNodeEventLoopFactory("pi2");
3933 const size_t pi2_index = configuration::GetNodeIndex(
3934 event_loop_factory.configuration(), pi2->node());
3935 NodeEventLoopFactory *const pi3 =
3936 event_loop_factory.GetNodeEventLoopFactory("pi3");
3937 const size_t pi3_index = configuration::GetNodeIndex(
3938 event_loop_factory.configuration(), pi3->node());
3939
3940 const std::string kLogfile1_1 =
3941 aos::testing::TestTmpDir() + "/multi_logfile1/";
3942 const std::string kLogfile2_1 =
3943 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3944 const std::string kLogfile2_2 =
3945 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3946 const std::string kLogfile3_1 =
3947 aos::testing::TestTmpDir() + "/multi_logfile3/";
3948 util::UnlinkRecursive(kLogfile1_1);
3949 util::UnlinkRecursive(kLogfile2_1);
3950 util::UnlinkRecursive(kLogfile2_2);
3951 util::UnlinkRecursive(kLogfile3_1);
3952 {
3953 CHECK_EQ(pi1_index, 0u);
3954 CHECK_EQ(pi2_index, 1u);
3955 CHECK_EQ(pi3_index, 2u);
3956
3957 time_converter.AddNextTimestamp(
3958 distributed_clock::epoch(),
3959 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3960 BootTimestamp::epoch()});
3961 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3962 time_converter.AddNextTimestamp(
3963 distributed_clock::epoch() + reboot_time,
3964 {BootTimestamp::epoch() + reboot_time,
3965 BootTimestamp{.boot = 1,
3966 .time = monotonic_clock::epoch() + reboot_time},
3967 BootTimestamp::epoch() + reboot_time});
3968 }
3969
3970 std::vector<std::string> filenames;
3971 {
3972 LoggerState pi1_logger = LoggerState::MakeLogger(
3973 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3974 LoggerState pi3_logger = LoggerState::MakeLogger(
3975 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3976 {
3977 // And now start the logger.
3978 LoggerState pi2_logger = LoggerState::MakeLogger(
3979 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3980
3981 pi1_logger.StartLogger(kLogfile1_1);
3982 pi3_logger.StartLogger(kLogfile3_1);
3983 pi2_logger.StartLogger(kLogfile2_1);
3984
3985 event_loop_factory.RunFor(chrono::milliseconds(1005));
3986
3987 // Now that we've got a start time in the past, turn on data.
3988 std::unique_ptr<aos::EventLoop> ping_event_loop =
3989 pi1->MakeEventLoop("ping");
3990 Ping ping(ping_event_loop.get());
3991
3992 pi2->AlwaysStart<Pong>("pong");
3993
3994 event_loop_factory.RunFor(chrono::milliseconds(3000));
3995
3996 pi2_logger.AppendAllFilenames(&filenames);
3997 }
3998 event_loop_factory.RunFor(chrono::milliseconds(995));
3999 // pi2 now reboots at 5 seconds.
4000 {
4001 event_loop_factory.RunFor(chrono::milliseconds(1000));
4002
4003 // Make local stuff happen before we start logging and connect the remote.
4004 pi2->AlwaysStart<Pong>("pong");
4005 std::unique_ptr<aos::EventLoop> ping_event_loop =
4006 pi1->MakeEventLoop("ping");
4007 Ping ping(ping_event_loop.get());
4008 event_loop_factory.RunFor(chrono::milliseconds(5));
4009
4010 // Start logging again on pi2 after it is up.
4011 LoggerState pi2_logger = LoggerState::MakeLogger(
4012 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4013 pi2_logger.StartLogger(kLogfile2_2);
4014
4015 event_loop_factory.RunFor(chrono::milliseconds(5000));
4016
4017 pi2_logger.AppendAllFilenames(&filenames);
4018 }
4019
4020 pi1_logger.AppendAllFilenames(&filenames);
4021 pi3_logger.AppendAllFilenames(&filenames);
4022 }
4023
4024 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4025 auto result = ConfirmReadable(filenames);
4026
4027 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4028 EXPECT_THAT(result[0].second,
4029 ::testing::ElementsAre(realtime_clock::epoch() +
4030 chrono::microseconds(11000350)));
4031
4032 EXPECT_THAT(result[1].first,
4033 ::testing::ElementsAre(
4034 realtime_clock::epoch(),
4035 realtime_clock::epoch() + chrono::microseconds(6005000)));
4036 EXPECT_THAT(result[1].second,
4037 ::testing::ElementsAre(
4038 realtime_clock::epoch() + chrono::microseconds(4900150),
4039 realtime_clock::epoch() + chrono::microseconds(11000200)));
4040
4041 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4042 EXPECT_THAT(result[2].second,
4043 ::testing::ElementsAre(realtime_clock::epoch() +
4044 chrono::microseconds(11000150)));
4045
4046 // Confirm we observed the correct start and stop times. We should see the
4047 // reboot here.
4048 auto start_stop_result = ConfirmReadable(
4049 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4050 realtime_clock::epoch() + chrono::milliseconds(8000));
4051
4052 EXPECT_THAT(
4053 start_stop_result[0].first,
4054 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4055 EXPECT_THAT(
4056 start_stop_result[0].second,
4057 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4058 EXPECT_THAT(start_stop_result[1].first,
4059 ::testing::ElementsAre(
4060 realtime_clock::epoch() + chrono::seconds(2),
4061 realtime_clock::epoch() + chrono::microseconds(6005000)));
4062 EXPECT_THAT(start_stop_result[1].second,
4063 ::testing::ElementsAre(
4064 realtime_clock::epoch() + chrono::microseconds(4900150),
4065 realtime_clock::epoch() + chrono::seconds(8)));
4066 EXPECT_THAT(
4067 start_stop_result[2].first,
4068 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4069 EXPECT_THAT(
4070 start_stop_result[2].second,
4071 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4072}
Austin Schuh5dd22842021-11-17 16:09:39 -08004073
Austin Schuh5c770fa2022-03-11 06:57:22 -08004074// Tests that we properly handle one direction being down.
4075TEST(MissingDirectionTest, OneDirection) {
4076 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4077 aos::configuration::ReadConfig(ArtifactPath(
4078 "aos/events/logging/multinode_pingpong_split4_config.json"));
4079 message_bridge::TestingTimeConverter time_converter(
4080 configuration::NodesCount(&config.message()));
4081 SimulatedEventLoopFactory event_loop_factory(&config.message());
4082 event_loop_factory.SetTimeConverter(&time_converter);
4083
4084 NodeEventLoopFactory *const pi1 =
4085 event_loop_factory.GetNodeEventLoopFactory("pi1");
4086 const size_t pi1_index = configuration::GetNodeIndex(
4087 event_loop_factory.configuration(), pi1->node());
4088 NodeEventLoopFactory *const pi2 =
4089 event_loop_factory.GetNodeEventLoopFactory("pi2");
4090 const size_t pi2_index = configuration::GetNodeIndex(
4091 event_loop_factory.configuration(), pi2->node());
4092 std::vector<std::string> filenames;
4093
4094 {
4095 CHECK_EQ(pi1_index, 0u);
4096 CHECK_EQ(pi2_index, 1u);
4097
4098 time_converter.AddNextTimestamp(
4099 distributed_clock::epoch(),
4100 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4101
4102 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4103 time_converter.AddNextTimestamp(
4104 distributed_clock::epoch() + reboot_time,
4105 {BootTimestamp{.boot = 1,
4106 .time = monotonic_clock::epoch()},
4107 BootTimestamp::epoch() + reboot_time});
4108 }
4109
4110 const std::string kLogfile2_1 =
4111 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4112 const std::string kLogfile1_1 =
4113 aos::testing::TestTmpDir() + "/multi_logfile1.1/";
4114 util::UnlinkRecursive(kLogfile2_1);
4115 util::UnlinkRecursive(kLogfile1_1);
4116
4117 pi2->Disconnect(pi1->node());
4118
4119 pi1->AlwaysStart<Ping>("ping");
4120 pi2->AlwaysStart<Pong>("pong");
4121
4122 {
4123 LoggerState pi2_logger = LoggerState::MakeLogger(
4124 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4125
4126 event_loop_factory.RunFor(chrono::milliseconds(95));
4127
4128 pi2_logger.StartLogger(kLogfile2_1);
4129
4130 event_loop_factory.RunFor(chrono::milliseconds(6000));
4131
4132 pi2->Connect(pi1->node());
4133
4134 LoggerState pi1_logger = LoggerState::MakeLogger(
4135 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4136 pi1_logger.StartLogger(kLogfile1_1);
4137
4138 event_loop_factory.RunFor(chrono::milliseconds(5000));
4139 pi1_logger.AppendAllFilenames(&filenames);
4140 pi2_logger.AppendAllFilenames(&filenames);
4141 }
4142
4143 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4144 ConfirmReadable(filenames);
4145}
4146
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004147// Tests that we properly handle only one direction ever existing after a
4148// reboot.
4149TEST(MissingDirectionTest, OneDirectionAfterReboot) {
4150 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4151 aos::configuration::ReadConfig(ArtifactPath(
4152 "aos/events/logging/multinode_pingpong_split4_config.json"));
4153 message_bridge::TestingTimeConverter time_converter(
4154 configuration::NodesCount(&config.message()));
4155 SimulatedEventLoopFactory event_loop_factory(&config.message());
4156 event_loop_factory.SetTimeConverter(&time_converter);
4157
4158 NodeEventLoopFactory *const pi1 =
4159 event_loop_factory.GetNodeEventLoopFactory("pi1");
4160 const size_t pi1_index = configuration::GetNodeIndex(
4161 event_loop_factory.configuration(), pi1->node());
4162 NodeEventLoopFactory *const pi2 =
4163 event_loop_factory.GetNodeEventLoopFactory("pi2");
4164 const size_t pi2_index = configuration::GetNodeIndex(
4165 event_loop_factory.configuration(), pi2->node());
4166 std::vector<std::string> filenames;
4167
4168 {
4169 CHECK_EQ(pi1_index, 0u);
4170 CHECK_EQ(pi2_index, 1u);
4171
4172 time_converter.AddNextTimestamp(
4173 distributed_clock::epoch(),
4174 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4175
4176 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4177 time_converter.AddNextTimestamp(
4178 distributed_clock::epoch() + reboot_time,
4179 {BootTimestamp{.boot = 1,
4180 .time = monotonic_clock::epoch()},
4181 BootTimestamp::epoch() + reboot_time});
4182 }
4183
4184 const std::string kLogfile2_1 =
4185 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4186 util::UnlinkRecursive(kLogfile2_1);
4187
4188
4189 pi1->AlwaysStart<Ping>("ping");
4190
4191 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4192 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4193 // second boot.
4194 {
4195 LoggerState pi2_logger = LoggerState::MakeLogger(
4196 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4197
4198 event_loop_factory.RunFor(chrono::milliseconds(95));
4199
4200 pi2_logger.StartLogger(kLogfile2_1);
4201
4202 event_loop_factory.RunFor(chrono::milliseconds(4000));
4203
4204 pi2->Disconnect(pi1->node());
4205
4206 event_loop_factory.RunFor(chrono::milliseconds(1000));
4207 pi1->AlwaysStart<Ping>("ping");
4208
4209 event_loop_factory.RunFor(chrono::milliseconds(5000));
4210 pi2_logger.AppendAllFilenames(&filenames);
4211 }
4212
4213 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4214 ConfirmReadable(filenames);
4215}
4216
Austin Schuhe309d2a2019-11-29 13:25:21 -08004217} // namespace testing
4218} // namespace logger
4219} // namespace aos