blob: c5b1768a09aa3f10d0510307acc5c00559e50fd2 [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 Schuh11717692022-10-16 17:11:28 -070087 const ::std::string logfile = base_name + "_data.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));
Austin Schuh11717692022-10-16 17:11:28 -0700103 logger.StartLoggingOnRun(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");
Austin Schuh11717692022-10-16 17:11:28 -0700151 const ::std::string logfile1 = base_name1 + "_data.part0.bfbs";
Brian Silverman1f345222020-09-24 21:14:48 -0700152 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");
Austin Schuh11717692022-10-16 17:11:28 -0700155 const ::std::string logfile2 = base_name2 + "_data.part0.bfbs";
Brian Silverman1f345222020-09-24 21:14:48 -0700156 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));
Austin Schuh11717692022-10-16 17:11:28 -0700171 logger_event_loop->OnRun(
172 [base_name1, base_name2, &logger_event_loop, &logger]() {
173 logger.StartLogging(std::make_unique<MultiNodeLogNamer>(
174 base_name1, logger_event_loop->configuration(),
175 logger_event_loop.get(), logger_event_loop->node()));
176 EXPECT_DEATH(logger.StartLogging(std::make_unique<MultiNodeLogNamer>(
177 base_name2, logger_event_loop->configuration(),
178 logger_event_loop.get(), logger_event_loop->node())),
179 "Already logging");
180 });
Brian Silverman1f345222020-09-24 21:14:48 -0700181 event_loop_factory_.RunFor(chrono::milliseconds(20000));
182 }
183}
184
James Kuszmaul94ca5132022-07-19 09:11:08 -0700185// Tests that we die if the replayer attempts to send on a logged channel.
186TEST_F(LoggerDeathTest, DieOnDuplicateReplayChannels) {
187 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
188 aos::configuration::ReadConfig(
189 ArtifactPath("aos/events/pingpong_config.json"));
190 SimulatedEventLoopFactory event_loop_factory(&config.message());
191 const ::std::string tmpdir = aos::testing::TestTmpDir();
192 const ::std::string base_name = tmpdir + "/logfile";
193 const ::std::string config_file =
194 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh11717692022-10-16 17:11:28 -0700195 const ::std::string logfile = base_name + "_data.part0.bfbs";
James Kuszmaul94ca5132022-07-19 09:11:08 -0700196 // Remove the log file.
197 unlink(config_file.c_str());
198 unlink(logfile.c_str());
199
200 LOG(INFO) << "Logging data to " << logfile;
201
202 {
203 std::unique_ptr<EventLoop> logger_event_loop =
204 event_loop_factory.MakeEventLoop("logger");
205
206 Logger logger(logger_event_loop.get());
207 logger.set_separate_config(false);
208 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh11717692022-10-16 17:11:28 -0700209 logger.StartLoggingOnRun(base_name);
James Kuszmaul94ca5132022-07-19 09:11:08 -0700210
211 event_loop_factory.RunFor(chrono::seconds(2));
212 }
213
214 LogReader reader(logfile);
215
216 reader.Register();
217
218 std::unique_ptr<EventLoop> test_event_loop =
219 reader.event_loop_factory()->MakeEventLoop("log_reader");
220
221 EXPECT_DEATH(test_event_loop->MakeSender<examples::Ping>("/test"),
222 "exclusive channel.*examples.Ping");
223}
224
Brian Silverman1f345222020-09-24 21:14:48 -0700225// Tests calling StopLogging twice.
226TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800227 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700228 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800229 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700230 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700231 const ::std::string logfile = base_name + ".part0.bfbs";
232 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800233 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700234 unlink(logfile.c_str());
235
236 LOG(INFO) << "Logging data to " << logfile;
237
238 {
239 std::unique_ptr<EventLoop> logger_event_loop =
240 event_loop_factory_.MakeEventLoop("logger");
241
242 event_loop_factory_.RunFor(chrono::milliseconds(95));
243
244 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800245 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700246 logger.set_polling_period(std::chrono::milliseconds(100));
247 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuh11717692022-10-16 17:11:28 -0700248 logger.StartLogging(std::make_unique<MultiNodeLogNamer>(
249 base_name, logger_event_loop->configuration(),
250 logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700251 logger.StopLogging(aos::monotonic_clock::min_time);
252 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
253 "Not logging right now");
254 });
255 event_loop_factory_.RunFor(chrono::milliseconds(20000));
256 }
257}
258
259// Tests that we can startup twice.
260TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800261 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700262 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800263 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700264 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Austin Schuh11717692022-10-16 17:11:28 -0700265 const ::std::string logfile1 = base_name1 + "_data.part0.bfbs";
Brian Silverman1f345222020-09-24 21:14:48 -0700266 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800267 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700268 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Austin Schuh11717692022-10-16 17:11:28 -0700269 const ::std::string logfile2 = base_name2 + "_data.part0.bfbs";
Brian Silverman1f345222020-09-24 21:14:48 -0700270 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800271 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700272 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800273 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700274
275 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
276
277 {
278 std::unique_ptr<EventLoop> logger_event_loop =
279 event_loop_factory_.MakeEventLoop("logger");
280
281 event_loop_factory_.RunFor(chrono::milliseconds(95));
282
283 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800284 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700285 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh11717692022-10-16 17:11:28 -0700286 logger.StartLogging(std::make_unique<MultiNodeLogNamer>(
287 base_name1, logger_event_loop->configuration(), logger_event_loop.get(),
288 logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700289 event_loop_factory_.RunFor(chrono::milliseconds(10000));
290 logger.StopLogging(logger_event_loop->monotonic_now());
291 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh11717692022-10-16 17:11:28 -0700292 logger.StartLogging(std::make_unique<MultiNodeLogNamer>(
293 base_name2, logger_event_loop->configuration(), logger_event_loop.get(),
294 logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700295 event_loop_factory_.RunFor(chrono::milliseconds(10000));
296 }
297
298 for (const auto &logfile :
299 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
300 SCOPED_TRACE(std::get<0>(logfile));
301 LogReader reader(std::get<0>(logfile));
302 reader.Register();
303
Austin Schuh07676622021-01-21 18:59:17 -0800304 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700305
306 std::unique_ptr<EventLoop> test_event_loop =
307 reader.event_loop_factory()->MakeEventLoop("log_reader");
308
309 int ping_count = std::get<1>(logfile);
310 int pong_count = std::get<1>(logfile);
311
312 // Confirm that the ping and pong counts both match, and the value also
313 // matches.
314 test_event_loop->MakeWatcher("/test",
315 [&ping_count](const examples::Ping &ping) {
316 EXPECT_EQ(ping.value(), ping_count + 1);
317 ++ping_count;
318 });
319 test_event_loop->MakeWatcher(
320 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
321 EXPECT_EQ(pong.value(), pong_count + 1);
322 ++pong_count;
323 EXPECT_EQ(ping_count, pong_count);
324 });
325
326 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
327 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
328 }
329}
330
Austin Schuhfa895892020-01-07 20:07:41 -0800331// Tests that we can read and write rotated log files.
332TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800333 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700334 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800335 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700336 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh11717692022-10-16 17:11:28 -0700337 const ::std::string logfile0 = base_name + "_data.part0.bfbs";
338 const ::std::string logfile1 = base_name + "_data.part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800339 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800340 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800341 unlink(logfile0.c_str());
342 unlink(logfile1.c_str());
343
344 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
345
346 {
Austin Schuhfa895892020-01-07 20:07:41 -0800347 std::unique_ptr<EventLoop> logger_event_loop =
348 event_loop_factory_.MakeEventLoop("logger");
349
350 event_loop_factory_.RunFor(chrono::milliseconds(95));
351
Brian Silverman1f345222020-09-24 21:14:48 -0700352 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800353 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700354 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh11717692022-10-16 17:11:28 -0700355 logger.StartLoggingOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800356 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700357 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800358 event_loop_factory_.RunFor(chrono::milliseconds(10000));
359 }
360
Austin Schuh64fab802020-09-09 22:47:47 -0700361 {
362 // Confirm that the UUIDs match for both the parts and the logger, and the
363 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800364 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700365 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800366 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700367 }
368
Brian Silvermanae7c0332020-09-30 16:58:23 -0700369 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
370 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700371 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
372 log_header[1].message().parts_uuid()->string_view());
373
374 EXPECT_EQ(log_header[0].message().parts_index(), 0);
375 EXPECT_EQ(log_header[1].message().parts_index(), 1);
376 }
377
Austin Schuhfa895892020-01-07 20:07:41 -0800378 // Even though it doesn't make any difference here, exercise the logic for
379 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800380 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800381
382 // Confirm that we can remap logged channels to point to new buses.
383 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
384
385 // This sends out the fetched messages and advances time to the start of the
386 // log file.
387 reader.Register();
388
Austin Schuh07676622021-01-21 18:59:17 -0800389 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800390
391 std::unique_ptr<EventLoop> test_event_loop =
392 reader.event_loop_factory()->MakeEventLoop("log_reader");
393
394 int ping_count = 10;
395 int pong_count = 10;
396
397 // Confirm that the ping value matches in the remapped channel location.
398 test_event_loop->MakeWatcher("/original/test",
399 [&ping_count](const examples::Ping &ping) {
400 EXPECT_EQ(ping.value(), ping_count + 1);
401 ++ping_count;
402 });
403 // Confirm that the ping and pong counts both match, and the value also
404 // matches.
405 test_event_loop->MakeWatcher(
406 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
407 EXPECT_EQ(pong.value(), pong_count + 1);
408 ++pong_count;
409 EXPECT_EQ(ping_count, pong_count);
410 });
411
412 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
413 EXPECT_EQ(ping_count, 2010);
414}
415
Austin Schuh4c4e0092019-12-22 16:18:03 -0800416// Tests that a large number of messages per second doesn't overwhelm writev.
417TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800418 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700419 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800420 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700421 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700422 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800423 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800424 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800425 unlink(logfile.c_str());
426
427 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700428 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800429
430 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800431 std::unique_ptr<EventLoop> logger_event_loop =
432 event_loop_factory_.MakeEventLoop("logger");
433
434 std::unique_ptr<EventLoop> ping_spammer_event_loop =
435 event_loop_factory_.MakeEventLoop("ping_spammer");
436 aos::Sender<examples::Ping> ping_sender =
437 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
438
439 aos::TimerHandler *timer_handler =
440 ping_spammer_event_loop->AddTimer([&ping_sender]() {
441 aos::Sender<examples::Ping>::Builder builder =
442 ping_sender.MakeBuilder();
443 examples::Ping::Builder ping_builder =
444 builder.MakeBuilder<examples::Ping>();
Austin Schuhbfe6c572022-01-27 20:48:20 -0800445 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800446 });
447
448 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
449 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
450 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
451 chrono::microseconds(50));
452 });
453
Brian Silverman1f345222020-09-24 21:14:48 -0700454 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800455 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700456 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh11717692022-10-16 17:11:28 -0700457 logger.StartLoggingOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800458
459 event_loop_factory_.RunFor(chrono::milliseconds(1000));
460 }
461}
462
James Kuszmaul890c2492022-04-06 14:59:31 -0700463// Tests that we can read a logfile that has channels which were sent too fast.
464TEST(SingleNodeLoggerNoFixtureTest, ReadTooFast) {
465 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
466 aos::configuration::ReadConfig(
467 ArtifactPath("aos/events/pingpong_config.json"));
468 SimulatedEventLoopFactory event_loop_factory(&config.message());
469 const ::std::string tmpdir = aos::testing::TestTmpDir();
470 const ::std::string base_name = tmpdir + "/logfile";
471 const ::std::string config_file =
472 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh11717692022-10-16 17:11:28 -0700473 const ::std::string logfile = base_name + "_data.part0.bfbs";
James Kuszmaul890c2492022-04-06 14:59:31 -0700474 // Remove the log file.
475 unlink(config_file.c_str());
476 unlink(logfile.c_str());
477
478 LOG(INFO) << "Logging data to " << logfile;
479
480 int sent_messages = 0;
481
482 {
483 std::unique_ptr<EventLoop> logger_event_loop =
484 event_loop_factory.MakeEventLoop("logger");
485
486 std::unique_ptr<EventLoop> ping_spammer_event_loop =
487 event_loop_factory.GetNodeEventLoopFactory(nullptr)->MakeEventLoop(
488 "ping_spammer", {NodeEventLoopFactory::CheckSentTooFast::kNo,
James Kuszmaul94ca5132022-07-19 09:11:08 -0700489 NodeEventLoopFactory::ExclusiveSenders::kNo,
490 {}});
James Kuszmaul890c2492022-04-06 14:59:31 -0700491 aos::Sender<examples::Ping> ping_sender =
492 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
493
494 aos::TimerHandler *timer_handler =
495 ping_spammer_event_loop->AddTimer([&ping_sender, &sent_messages]() {
496 aos::Sender<examples::Ping>::Builder builder =
497 ping_sender.MakeBuilder();
498 examples::Ping::Builder ping_builder =
499 builder.MakeBuilder<examples::Ping>();
500 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
501 ++sent_messages;
502 });
503
504 constexpr std::chrono::microseconds kSendPeriod{10};
505 const int max_legal_messages =
506 ping_sender.channel()->frequency() *
507 event_loop_factory.configuration()->channel_storage_duration() /
508 1000000000;
509
510 ping_spammer_event_loop->OnRun(
511 [&ping_spammer_event_loop, kSendPeriod, timer_handler]() {
512 timer_handler->Setup(
513 ping_spammer_event_loop->monotonic_now() + kSendPeriod / 2,
514 kSendPeriod);
515 });
516
517 Logger logger(logger_event_loop.get());
518 logger.set_separate_config(false);
519 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh11717692022-10-16 17:11:28 -0700520 logger.StartLoggingOnRun(base_name);
James Kuszmaul890c2492022-04-06 14:59:31 -0700521
522 event_loop_factory.RunFor(kSendPeriod * max_legal_messages * 2);
523 }
524
525 LogReader reader(logfile);
526
527 reader.Register();
528
529 std::unique_ptr<EventLoop> test_event_loop =
530 reader.event_loop_factory()->MakeEventLoop("log_reader");
531
532 int replay_count = 0;
533
534 test_event_loop->MakeWatcher(
535 "/test", [&replay_count](const examples::Ping &) { ++replay_count; });
536
537 reader.event_loop_factory()->Run();
538 EXPECT_EQ(replay_count, sent_messages);
539}
540
James Kuszmauldd0a5042021-10-28 23:38:04 -0700541struct CompressionParams {
542 std::string_view extension;
543 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
544};
545
546std::ostream &operator<<(std::ostream &ostream,
547 const CompressionParams &params) {
548 ostream << "\"" << params.extension << "\"";
549 return ostream;
550}
551
552std::vector<CompressionParams> SupportedCompressionAlgorithms() {
553 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
554 {SnappyDecoder::kExtension,
555 []() { return std::make_unique<SnappyEncoder>(); }},
556#ifdef LZMA
557 {LzmaDecoder::kExtension,
558 []() { return std::make_unique<LzmaEncoder>(3); }}
559#endif // LZMA
560 };
561}
562
Austin Schuh61e973f2021-02-21 21:43:56 -0800563// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700564struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800565 // The config file to use.
566 std::string config;
567 // If true, the RemoteMessage channel should be shared between all the remote
568 // channels. If false, there will be 1 RemoteMessage channel per remote
569 // channel.
570 bool shared;
571 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700572 std::string_view sha256;
James Kuszmaul53da7f32022-09-11 11:11:55 -0700573 // sha256 of the relogged config
574 std::string_view relogged_sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800575};
Austin Schuh315b96b2020-12-11 21:21:12 -0800576
James Kuszmauldd0a5042021-10-28 23:38:04 -0700577std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
578 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
James Kuszmaul53da7f32022-09-11 11:11:55 -0700579 << ", sha256: \"" << params.sha256 << "\", relogged_sha256: \""
580 << params.relogged_sha256 << "\"}";
James Kuszmauldd0a5042021-10-28 23:38:04 -0700581 return ostream;
582}
583
Austin Schuh3e20c692021-11-16 20:43:16 -0800584struct LoggerState {
585 static LoggerState MakeLogger(NodeEventLoopFactory *node,
586 SimulatedEventLoopFactory *factory,
587 CompressionParams params,
588 const Configuration *configuration = nullptr) {
589 if (configuration == nullptr) {
590 configuration = factory->configuration();
591 }
592 return {node->MakeEventLoop("logger"),
593 {},
594 configuration,
595 configuration::GetNode(configuration, node->node()),
596 nullptr,
597 params};
598 }
599
600 void StartLogger(std::string logfile_base) {
601 CHECK(!logfile_base.empty());
602
603 logger = std::make_unique<Logger>(event_loop.get(), configuration);
604 logger->set_polling_period(std::chrono::milliseconds(100));
605 logger->set_name(
606 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
Austin Schuhfa712682022-05-11 16:43:42 -0700607 logger->set_logger_sha1(
608 absl::StrCat("logger_sha1_", event_loop->node()->name()->str()));
609 logger->set_logger_version(
610 absl::StrCat("logger_version_", event_loop->node()->name()->str()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800611 event_loop->OnRun([this, logfile_base]() {
612 std::unique_ptr<MultiNodeLogNamer> namer =
613 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
614 event_loop.get(), node);
615 namer->set_extension(params.extension);
616 namer->set_encoder_factory(params.encoder_factory);
617 log_namer = namer.get();
618
619 logger->StartLogging(std::move(namer));
620 });
621 }
622
623 std::unique_ptr<EventLoop> event_loop;
624 std::unique_ptr<Logger> logger;
625 const Configuration *configuration;
626 const Node *node;
627 MultiNodeLogNamer *log_namer;
628 CompressionParams params;
629
630 void AppendAllFilenames(std::vector<std::string> *filenames) {
631 for (const std::string &file : log_namer->all_filenames()) {
632 const std::string_view separator =
633 log_namer->base_name().back() == '/' ? "" : "_";
634 filenames->emplace_back(
635 absl::StrCat(log_namer->base_name(), separator, file));
636 }
637 }
638
639 ~LoggerState() {
640 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800641 std::vector<std::string> filenames;
642 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800643 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800644 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800645 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800646 auto x = ReadHeader(file);
647 if (x) {
648 VLOG(1) << aos::FlatbufferToJson(x.value());
649 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800650 }
651 }
652 }
653};
654
Austin Schuhe33c08d2022-02-03 18:15:21 -0800655std::vector<std::pair<std::vector<realtime_clock::time_point>,
656 std::vector<realtime_clock::time_point>>>
657ConfirmReadable(
658 const std::vector<std::string> &files,
659 realtime_clock::time_point start_time = realtime_clock::min_time,
660 realtime_clock::time_point end_time = realtime_clock::max_time) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800661 {
662 LogReader reader(SortParts(files));
663
664 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
665 reader.Register(&log_reader_factory);
666
667 log_reader_factory.Run();
668
669 reader.Deregister();
670 }
671 {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800672 std::vector<std::pair<std::vector<realtime_clock::time_point>,
673 std::vector<realtime_clock::time_point>>>
674 result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800675 LogReader reader(SortParts(files));
676
Austin Schuhe33c08d2022-02-03 18:15:21 -0800677 reader.SetStartTime(start_time);
678 reader.SetEndTime(end_time);
679
Austin Schuh3e20c692021-11-16 20:43:16 -0800680 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
681 reader.RegisterWithoutStarting(&log_reader_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -0800682 result.resize(
683 configuration::NodesCount(log_reader_factory.configuration()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800684 if (configuration::MultiNode(log_reader_factory.configuration())) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800685 size_t i = 0;
Austin Schuh3e20c692021-11-16 20:43:16 -0800686 for (const aos::Node *node :
687 *log_reader_factory.configuration()->nodes()) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800688 LOG(INFO) << "Registering start";
689 reader.OnStart(node, [node, &log_reader_factory, &result,
690 node_index = i]() {
Austin Schuh3e20c692021-11-16 20:43:16 -0800691 LOG(INFO) << "Starting " << node->name()->string_view();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800692 result[node_index].first.push_back(
693 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
Austin Schuh3e20c692021-11-16 20:43:16 -0800694 });
Austin Schuhe33c08d2022-02-03 18:15:21 -0800695 reader.OnEnd(node, [node, &log_reader_factory, &result,
696 node_index = i]() {
697 LOG(INFO) << "Ending " << node->name()->string_view();
698 result[node_index].second.push_back(
699 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
700 });
701 ++i;
Austin Schuh3e20c692021-11-16 20:43:16 -0800702 }
Austin Schuhe33c08d2022-02-03 18:15:21 -0800703 } else {
704 reader.OnStart([&log_reader_factory, &result]() {
705 LOG(INFO) << "Starting";
706 result[0].first.push_back(
707 log_reader_factory.GetNodeEventLoopFactory(nullptr)
708 ->realtime_now());
709 });
710 reader.OnEnd([&log_reader_factory, &result]() {
711 LOG(INFO) << "Ending";
712 result[0].second.push_back(
713 log_reader_factory.GetNodeEventLoopFactory(nullptr)
714 ->realtime_now());
715 });
Austin Schuh3e20c692021-11-16 20:43:16 -0800716 }
717
718 log_reader_factory.Run();
719
720 reader.Deregister();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800721
722 for (auto x : result) {
723 for (auto y : x.first) {
724 VLOG(1) << "Start " << y;
725 }
726 for (auto y : x.second) {
727 VLOG(1) << "End " << y;
728 }
729 }
730 return result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800731 }
732}
733
James Kuszmauldd0a5042021-10-28 23:38:04 -0700734class MultinodeLoggerTest : public ::testing::TestWithParam<
735 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800736 public:
737 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700738 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
739 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800740 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800741 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700742 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800743 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700744 event_loop_factory_.configuration(), pi1_->node())),
745 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800746 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700747 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800748 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800749 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
750 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800751 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800752 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800753 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700754 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700755 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800756 event_loop_factory_.SetTimeConverter(&time_converter_);
757
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700758 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700759 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700760 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800761 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700762 }
763
James Kuszmaul53da7f32022-09-11 11:11:55 -0700764 for (const auto &file : MakeLogFiles(tmp_dir_ + "/relogged1",
765 tmp_dir_ + "/relogged2", 3, 3, true)) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800766 unlink(file.c_str());
767 }
768
Austin Schuh268586b2021-03-31 22:24:39 -0700769 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800770 unlink(file.c_str());
771 }
772
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700773 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
774 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700775
776 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
777 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700778 }
779
James Kuszmauldd0a5042021-10-28 23:38:04 -0700780 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800781
782 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700783 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800784 size_t pi1_data_count = 3,
James Kuszmaul53da7f32022-09-11 11:11:55 -0700785 size_t pi2_data_count = 3,
786 bool relogged_config = false) {
787 std::string_view sha256 = relogged_config
788 ? std::get<0>(GetParam()).relogged_sha256
789 : std::get<0>(GetParam()).sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800790 std::vector<std::string> result;
James Kuszmaul53da7f32022-09-11 11:11:55 -0700791 result.emplace_back(absl::StrCat(logfile_base1, "_", sha256, Extension()));
792 result.emplace_back(absl::StrCat(logfile_base2, "_", sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700793 for (size_t i = 0; i < pi1_data_count; ++i) {
794 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700795 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700796 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800797 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700798 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800799 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700800 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700801 for (size_t i = 0; i < pi2_data_count; ++i) {
802 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700803 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700804 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700805 result.emplace_back(logfile_base2 +
806 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
807 Extension());
808 result.emplace_back(logfile_base2 +
809 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
810 Extension());
811 result.emplace_back(logfile_base1 +
812 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
813 Extension());
814 result.emplace_back(logfile_base1 +
815 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
816 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800817 if (shared()) {
818 result.emplace_back(logfile_base1 +
819 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700820 "aos.message_bridge.RemoteMessage.part0" +
821 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800822 result.emplace_back(logfile_base1 +
823 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700824 "aos.message_bridge.RemoteMessage.part1" +
825 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800826 result.emplace_back(logfile_base1 +
827 "_timestamps/pi1/aos/remote_timestamps/pi2/"
828 "aos.message_bridge.RemoteMessage.part2" +
829 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800830 result.emplace_back(logfile_base2 +
831 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700832 "aos.message_bridge.RemoteMessage.part0" +
833 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800834 result.emplace_back(logfile_base2 +
835 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700836 "aos.message_bridge.RemoteMessage.part1" +
837 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800838 } else {
839 result.emplace_back(logfile_base1 +
840 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
841 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700842 "aos.message_bridge.RemoteMessage.part0" +
843 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800844 result.emplace_back(logfile_base1 +
845 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
846 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700847 "aos.message_bridge.RemoteMessage.part1" +
848 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800849 result.emplace_back(logfile_base2 +
850 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
851 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700852 "aos.message_bridge.RemoteMessage.part0" +
853 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800854 result.emplace_back(logfile_base2 +
855 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
856 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700857 "aos.message_bridge.RemoteMessage.part1" +
858 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800859 result.emplace_back(logfile_base1 +
860 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
861 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700862 "aos.message_bridge.RemoteMessage.part0" +
863 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800864 result.emplace_back(logfile_base1 +
865 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
866 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700867 "aos.message_bridge.RemoteMessage.part1" +
868 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800869 }
870
871 return result;
872 }
873
874 std::vector<std::string> MakePi1RebootLogfiles() {
875 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700876 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
877 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
878 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800879 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
880 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800881 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700882 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800883 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700884 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800885 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700886 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700887 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700888 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
889 result.emplace_back(logfile_base1_ +
890 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
891 Extension());
892 result.emplace_back(logfile_base1_ +
893 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
894 Extension());
895 result.emplace_back(logfile_base1_ +
896 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
897 Extension());
898 result.emplace_back(logfile_base1_ +
899 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
900 Extension());
901 result.emplace_back(absl::StrCat(
902 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800903 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800904 for (size_t i = 0; i < 6; ++i) {
905 result.emplace_back(
906 absl::StrCat(logfile_base1_,
907 "_timestamps/pi1/aos/remote_timestamps/pi2/"
908 "aos.message_bridge.RemoteMessage.part",
909 i, Extension()));
910 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800911 } else {
912 result.emplace_back(logfile_base1_ +
913 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
914 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700915 "aos.message_bridge.RemoteMessage.part0" +
916 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800917 result.emplace_back(logfile_base1_ +
918 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
919 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700920 "aos.message_bridge.RemoteMessage.part1" +
921 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800922 result.emplace_back(logfile_base1_ +
923 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
924 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700925 "aos.message_bridge.RemoteMessage.part2" +
926 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700927 result.emplace_back(logfile_base1_ +
928 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
929 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700930 "aos.message_bridge.RemoteMessage.part3" +
931 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800932
933 result.emplace_back(logfile_base1_ +
934 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
935 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700936 "aos.message_bridge.RemoteMessage.part0" +
937 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800938 result.emplace_back(logfile_base1_ +
939 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
940 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700941 "aos.message_bridge.RemoteMessage.part1" +
942 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800943 result.emplace_back(logfile_base1_ +
944 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
945 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700946 "aos.message_bridge.RemoteMessage.part2" +
947 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700948 result.emplace_back(logfile_base1_ +
949 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
950 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700951 "aos.message_bridge.RemoteMessage.part3" +
952 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800953 }
954 return result;
955 }
956
957 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
958 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700959 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
960 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
961 result.emplace_back(logfile_base1_ +
962 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
963 Extension());
964 result.emplace_back(absl::StrCat(
965 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700966 return result;
967 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800968
Austin Schuh510dc622021-08-06 18:47:30 -0700969 std::vector<std::string> MakePi1DeadNodeLogfiles() {
970 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700971 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
972 result.emplace_back(absl::StrCat(
973 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800974 return result;
975 }
976
977 std::vector<std::vector<std::string>> StructureLogFiles() {
978 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800979 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
980 std::vector<std::string>{logfiles_[5], logfiles_[6]},
981 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800982 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800983 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800984
Austin Schuhbfe6c572022-01-27 20:48:20 -0800985 if (shared()) {
986 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
987 logfiles_[16]});
988 result.emplace_back(
989 std::vector<std::string>{logfiles_[17], logfiles_[18]});
990 } else {
991 result.emplace_back(
992 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800993 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700994 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800995 result.emplace_back(
996 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800997 }
998
999 return result;
1000 }
1001
James Kuszmauldd0a5042021-10-28 23:38:04 -07001002 std::string Extension() {
1003 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
1004 }
1005
Austin Schuh58646e22021-08-23 23:51:46 -07001006 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -07001007 SimulatedEventLoopFactory *factory = nullptr,
1008 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001009 if (factory == nullptr) {
1010 factory = &event_loop_factory_;
1011 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001012 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
1013 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001014 }
1015
James Kuszmauldd0a5042021-10-28 23:38:04 -07001016 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001017 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -08001018 if (logger->event_loop->node()->name()->string_view() == "pi1") {
1019 logfile_base = logfile_base1_;
1020 } else {
1021 logfile_base = logfile_base2_;
1022 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001023 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001024 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001025 }
Austin Schuh15649d62019-12-28 16:36:38 -08001026
Austin Schuh3bd4c402020-11-06 18:19:06 -08001027 void VerifyParts(const std::vector<LogFile> &sorted_parts,
1028 const std::vector<std::string> &corrupted_parts = {}) {
1029 EXPECT_EQ(sorted_parts.size(), 2u);
1030
1031 // Count up the number of UUIDs and make sure they are what we expect as a
1032 // sanity check.
1033 std::set<std::string> log_event_uuids;
1034 std::set<std::string> parts_uuids;
1035 std::set<std::string> both_uuids;
1036
1037 size_t missing_rt_count = 0;
1038
1039 std::vector<std::string> logger_nodes;
1040 for (const LogFile &log_file : sorted_parts) {
1041 EXPECT_FALSE(log_file.log_event_uuid.empty());
1042 log_event_uuids.insert(log_file.log_event_uuid);
1043 logger_nodes.emplace_back(log_file.logger_node);
1044 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -08001045 EXPECT_TRUE(log_file.config);
1046 EXPECT_EQ(log_file.name,
1047 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuhfa712682022-05-11 16:43:42 -07001048 EXPECT_EQ(log_file.logger_sha1,
1049 absl::StrCat("logger_sha1_", log_file.logger_node));
1050 EXPECT_EQ(log_file.logger_version,
1051 absl::StrCat("logger_version_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -08001052
1053 for (const LogParts &part : log_file.parts) {
1054 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
1055 << ": " << part;
1056 missing_rt_count +=
1057 part.realtime_start_time == aos::realtime_clock::min_time;
1058
1059 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
1060 log_event_uuids.end());
1061 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -08001062 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001063 parts_uuids.insert(part.parts_uuid);
1064 both_uuids.insert(part.parts_uuid);
1065 }
1066 }
1067
Austin Schuh61e973f2021-02-21 21:43:56 -08001068 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
1069 // start time on remote nodes because we don't know it and would be
1070 // guessing. And the log reader can actually do a better job. The number
1071 // depends on if we have the remote timestamps split across 2 files, or just
1072 // across 1, depending on if we are using a split or combined timestamp
1073 // channel config.
1074 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001075
1076 EXPECT_EQ(log_event_uuids.size(), 2u);
1077 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
1078 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
1079
1080 // Test that each list of parts is in order. Don't worry about the ordering
1081 // between part file lists though.
1082 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -08001083 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -08001084 ::testing::UnorderedElementsAreArray(structured_logfiles_));
1085
1086 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
1087
1088 EXPECT_NE(sorted_parts[0].realtime_start_time,
1089 aos::realtime_clock::min_time);
1090 EXPECT_NE(sorted_parts[1].realtime_start_time,
1091 aos::realtime_clock::min_time);
1092
1093 EXPECT_NE(sorted_parts[0].monotonic_start_time,
1094 aos::monotonic_clock::min_time);
1095 EXPECT_NE(sorted_parts[1].monotonic_start_time,
1096 aos::monotonic_clock::min_time);
1097
1098 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
1099 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
1100 }
1101
1102 void AddExtension(std::string_view extension) {
1103 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
1104 [extension](const std::string &in) {
1105 return absl::StrCat(in, extension);
1106 });
1107
1108 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
1109 structured_logfiles_.begin(),
1110 [extension](std::vector<std::string> in) {
1111 std::transform(in.begin(), in.end(), in.begin(),
1112 [extension](const std::string &in_str) {
1113 return absl::StrCat(in_str, extension);
1114 });
1115 return in;
1116 });
1117 }
1118
Austin Schuh15649d62019-12-28 16:36:38 -08001119 // Config and factory.
1120 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001121 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -08001122 SimulatedEventLoopFactory event_loop_factory_;
1123
Austin Schuh58646e22021-08-23 23:51:46 -07001124 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001125 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -07001126 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001127 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001128
1129 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -08001130 std::string logfile_base1_;
1131 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -08001132 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001133 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -08001134 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001135
1136 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -08001137};
1138
Austin Schuh391e3172020-09-01 22:48:18 -07001139// Counts the number of messages on a channel. Returns (channel name, channel
1140// type, count) for every message matching matcher()
1141std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -08001142 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001143 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -08001144 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -08001145 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -08001146
Austin Schuh6f3babe2020-01-26 20:34:50 -08001147 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001148 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -08001149 if (!msg) {
1150 break;
1151 }
1152
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001153 if (matcher(msg.get())) {
1154 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001155 }
1156 }
1157
Austin Schuh391e3172020-09-01 22:48:18 -07001158 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001159 int channel = 0;
1160 for (size_t i = 0; i < counts.size(); ++i) {
1161 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -08001162 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -07001163 result.push_back(std::make_tuple(channel->name()->str(),
1164 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -08001165 }
1166 ++channel;
1167 }
1168
1169 return result;
1170}
1171
1172// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001173std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -08001174 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -07001175 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001176 return CountChannelsMatching(
1177 config, filename, [](const UnpackedMessageHeader *msg) {
1178 if (msg->span.data() != nullptr) {
1179 CHECK(!msg->monotonic_remote_time.has_value());
1180 CHECK(!msg->realtime_remote_time.has_value());
1181 CHECK(!msg->remote_queue_index.has_value());
1182 return true;
1183 }
1184 return false;
1185 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001186}
1187
1188// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001189std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001190 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001191 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001192 return CountChannelsMatching(
1193 config, filename, [](const UnpackedMessageHeader *msg) {
1194 if (msg->span.data() == nullptr) {
1195 CHECK(msg->monotonic_remote_time.has_value());
1196 CHECK(msg->realtime_remote_time.has_value());
1197 CHECK(msg->remote_queue_index.has_value());
1198 return true;
1199 }
1200 return false;
1201 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001202}
1203
Austin Schuhcde938c2020-02-02 17:30:07 -08001204// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001205TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001206 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001207 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001208
Austin Schuh15649d62019-12-28 16:36:38 -08001209 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001210 LoggerState pi1_logger = MakeLogger(pi1_);
1211 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001212
1213 event_loop_factory_.RunFor(chrono::milliseconds(95));
1214
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001215 StartLogger(&pi1_logger);
1216 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001217
Austin Schuh15649d62019-12-28 16:36:38 -08001218 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001219 pi1_logger.AppendAllFilenames(&actual_filenames);
1220 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001221 }
1222
Austin Schuhbfe6c572022-01-27 20:48:20 -08001223 ASSERT_THAT(actual_filenames,
1224 ::testing::UnorderedElementsAreArray(logfiles_));
1225
Austin Schuh6f3babe2020-01-26 20:34:50 -08001226 {
Austin Schuh64fab802020-09-09 22:47:47 -07001227 std::set<std::string> logfile_uuids;
1228 std::set<std::string> parts_uuids;
1229 // Confirm that we have the expected number of UUIDs for both the logfile
1230 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001231 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001232 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001233 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001234 if (!log_header.back().message().has_configuration()) {
1235 logfile_uuids.insert(
1236 log_header.back().message().log_event_uuid()->str());
1237 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1238 }
Austin Schuh64fab802020-09-09 22:47:47 -07001239 }
Austin Schuh15649d62019-12-28 16:36:38 -08001240
Austin Schuh64fab802020-09-09 22:47:47 -07001241 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001242 if (shared()) {
1243 EXPECT_EQ(parts_uuids.size(), 7u);
1244 } else {
1245 EXPECT_EQ(parts_uuids.size(), 8u);
1246 }
Austin Schuh64fab802020-09-09 22:47:47 -07001247
1248 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001249 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001250 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001251 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1252
Austin Schuh64fab802020-09-09 22:47:47 -07001253 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001254 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001255
Austin Schuhe46492f2021-07-31 19:49:41 -07001256 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001257 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1258 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1259
1260 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1261 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1262
Austin Schuhe46492f2021-07-31 19:49:41 -07001263 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1264 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001265
1266 if (shared()) {
1267 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1268 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001269 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001270
1271 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1272 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1273 } else {
1274 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1275 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1276
1277 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1278 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1279
1280 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1281 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001282 }
Austin Schuh64fab802020-09-09 22:47:47 -07001283
1284 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001285 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001286 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001287 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1288
1289 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1290 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1291
1292 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1293 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1294 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1295
Austin Schuh64fab802020-09-09 22:47:47 -07001296 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1297 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001298
Austin Schuh61e973f2021-02-21 21:43:56 -08001299 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1300 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001301
1302 if (shared()) {
1303 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1304 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1305 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1306
1307 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1308 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1309 } else {
1310 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1311 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1312
Austin Schuhe46492f2021-07-31 19:49:41 -07001313 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1314 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001315
1316 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1317 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001318 }
Austin Schuh64fab802020-09-09 22:47:47 -07001319 }
1320
Austin Schuh8c399962020-12-25 21:51:45 -08001321 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001322 {
Austin Schuh391e3172020-09-01 22:48:18 -07001323 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001324 std::shared_ptr<const aos::Configuration> config =
1325 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001326
Austin Schuh6f3babe2020-01-26 20:34:50 -08001327 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001328 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1329 UnorderedElementsAre(
1330 std::make_tuple("/pi1/aos",
1331 "aos.message_bridge.ServerStatistics", 1),
1332 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001333 << " : " << logfiles_[2];
James Kuszmaul53da7f32022-09-11 11:11:55 -07001334 {
1335 std::vector<std::tuple<std::string, std::string, int>> channel_counts = {
1336 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1337 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1338 1)};
1339 if (!std::get<0>(GetParam()).shared) {
1340 channel_counts.push_back(
1341 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1342 "aos-message_bridge-Timestamp",
1343 "aos.message_bridge.RemoteMessage", 1));
1344 }
1345 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
1346 ::testing::UnorderedElementsAreArray(channel_counts))
1347 << " : " << logfiles_[3];
1348 }
1349 {
1350 std::vector<std::tuple<std::string, std::string, int>> channel_counts = {
1351 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
1352 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
1353 20),
1354 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1355 199),
1356 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
1357 std::make_tuple("/test", "aos.examples.Ping", 2000)};
1358 if (!std::get<0>(GetParam()).shared) {
1359 channel_counts.push_back(
1360 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1361 "aos-message_bridge-Timestamp",
1362 "aos.message_bridge.RemoteMessage", 199));
1363 }
1364 EXPECT_THAT(CountChannelsData(config, logfiles_[4]),
1365 ::testing::UnorderedElementsAreArray(channel_counts))
1366 << " : " << logfiles_[4];
1367 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001368 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001369 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1370 UnorderedElementsAre())
1371 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001372 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001373 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001374 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001375 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001376 EXPECT_THAT(
1377 CountChannelsTimestamp(config, logfiles_[4]),
1378 UnorderedElementsAre(
1379 std::make_tuple("/test", "aos.examples.Pong", 2000),
1380 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1381 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001382
1383 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001384 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001385 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001386 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001387 << " : " << logfiles_[5];
1388 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001389 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001390 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001391 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001392
Austin Schuh6f3babe2020-01-26 20:34:50 -08001393 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001394 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1395 UnorderedElementsAre())
1396 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001397 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1398 UnorderedElementsAre())
1399 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001400
1401 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001402 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001403 UnorderedElementsAre(std::make_tuple(
1404 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001405 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001406 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001407 CountChannelsData(config, logfiles_[8]),
1408 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1409 << " : " << logfiles_[8];
1410 EXPECT_THAT(
1411 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001412 UnorderedElementsAre(
1413 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001414 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001415 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001416 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1417 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001418 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001419 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1420 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001421 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001422 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001423 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001424 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001425 EXPECT_THAT(
1426 CountChannelsTimestamp(config, logfiles_[8]),
1427 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1428 << " : " << logfiles_[8];
1429 EXPECT_THAT(
1430 CountChannelsTimestamp(config, logfiles_[9]),
1431 UnorderedElementsAre(
1432 std::make_tuple("/test", "aos.examples.Ping", 2000),
1433 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1434 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001435
1436 // And then test that the remotely logged timestamp data files only have
1437 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001438 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1439 UnorderedElementsAre())
1440 << " : " << logfiles_[10];
1441 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1442 UnorderedElementsAre())
1443 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001444 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1445 UnorderedElementsAre())
1446 << " : " << logfiles_[12];
1447 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1448 UnorderedElementsAre())
1449 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001450
Austin Schuh8c399962020-12-25 21:51:45 -08001451 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001452 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001453 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001454 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001455 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001456 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001457 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001458 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001459
Austin Schuh61e973f2021-02-21 21:43:56 -08001460 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001461 UnorderedElementsAre(std::make_tuple(
1462 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001463 << " : " << logfiles_[12];
1464 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001465 UnorderedElementsAre(std::make_tuple(
1466 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001467 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001468
1469 // Timestamps from pi2 on pi1, and the other way.
1470 if (shared()) {
1471 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1472 UnorderedElementsAre())
1473 << " : " << logfiles_[14];
1474 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1475 UnorderedElementsAre())
1476 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001477 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001478 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001479 << " : " << logfiles_[16];
1480 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001481 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001482 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001483 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1484 UnorderedElementsAre())
1485 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001486
Austin Schuhbfe6c572022-01-27 20:48:20 -08001487 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1488 UnorderedElementsAre(
1489 std::make_tuple("/test", "aos.examples.Ping", 1)))
1490 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001491 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001492 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001493 UnorderedElementsAre(
1494 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001495 std::make_tuple("/test", "aos.examples.Ping", 90)))
1496 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001497 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001498 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001499 UnorderedElementsAre(
1500 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1501 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001502 << " : " << logfiles_[16];
1503 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001504 UnorderedElementsAre(std::make_tuple(
1505 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1506 << " : " << logfiles_[17];
1507 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1508 UnorderedElementsAre(std::make_tuple(
1509 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1510 << " : " << logfiles_[18];
1511 } else {
1512 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1513 UnorderedElementsAre())
1514 << " : " << logfiles_[14];
1515 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1516 UnorderedElementsAre())
1517 << " : " << logfiles_[15];
1518 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1519 UnorderedElementsAre())
1520 << " : " << logfiles_[16];
1521 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1522 UnorderedElementsAre())
1523 << " : " << logfiles_[17];
1524 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1525 UnorderedElementsAre())
1526 << " : " << logfiles_[18];
1527 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1528 UnorderedElementsAre())
1529 << " : " << logfiles_[19];
1530
1531 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1532 UnorderedElementsAre(std::make_tuple(
1533 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1534 << " : " << logfiles_[14];
1535 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1536 UnorderedElementsAre(std::make_tuple(
1537 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1538 << " : " << logfiles_[15];
1539 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1540 UnorderedElementsAre(std::make_tuple(
1541 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1542 << " : " << logfiles_[16];
1543 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1544 UnorderedElementsAre(std::make_tuple(
1545 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1546 << " : " << logfiles_[17];
1547 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1548 UnorderedElementsAre(
1549 std::make_tuple("/test", "aos.examples.Ping", 91)))
1550 << " : " << logfiles_[18];
1551 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001552 UnorderedElementsAre(
1553 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001554 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001555 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001556 }
1557
Austin Schuh8c399962020-12-25 21:51:45 -08001558 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001559
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001560 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001561 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001562
1563 // This sends out the fetched messages and advances time to the start of the
1564 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001565 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001566
Austin Schuhac0771c2020-01-07 18:36:30 -08001567 const Node *pi1 =
1568 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001569 const Node *pi2 =
1570 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001571
Austin Schuh2f8fd752020-09-01 22:38:28 -07001572 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1573 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1574 LOG(INFO) << "now pi1 "
1575 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1576 LOG(INFO) << "now pi2 "
1577 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1578
Austin Schuh07676622021-01-21 18:59:17 -08001579 EXPECT_THAT(reader.LoggedNodes(),
1580 ::testing::ElementsAre(
1581 configuration::GetNode(reader.logged_configuration(), pi1),
1582 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001583
1584 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001585
Austin Schuh6f3babe2020-01-26 20:34:50 -08001586 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001587 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001588 std::unique_ptr<EventLoop> pi2_event_loop =
1589 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001590
Austin Schuh6f3babe2020-01-26 20:34:50 -08001591 int pi1_ping_count = 10;
1592 int pi2_ping_count = 10;
1593 int pi1_pong_count = 10;
1594 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001595
1596 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001597 pi1_event_loop->MakeWatcher(
1598 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001599 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001600 << pi1_event_loop->context().monotonic_remote_time << " -> "
1601 << pi1_event_loop->context().monotonic_event_time;
1602 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1603 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1604 pi1_ping_count * chrono::milliseconds(10) +
1605 monotonic_clock::epoch());
1606 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1607 pi1_ping_count * chrono::milliseconds(10) +
1608 realtime_clock::epoch());
1609 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1610 pi1_event_loop->context().monotonic_event_time);
1611 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1612 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001613
Austin Schuh6f3babe2020-01-26 20:34:50 -08001614 ++pi1_ping_count;
1615 });
1616 pi2_event_loop->MakeWatcher(
1617 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001618 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001619 << pi2_event_loop->context().monotonic_remote_time << " -> "
1620 << pi2_event_loop->context().monotonic_event_time;
1621 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1622
1623 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1624 pi2_ping_count * chrono::milliseconds(10) +
1625 monotonic_clock::epoch());
1626 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1627 pi2_ping_count * chrono::milliseconds(10) +
1628 realtime_clock::epoch());
1629 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1630 chrono::microseconds(150),
1631 pi2_event_loop->context().monotonic_event_time);
1632 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1633 chrono::microseconds(150),
1634 pi2_event_loop->context().realtime_event_time);
1635 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001636 });
1637
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001638 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001639 // Confirm that the ping and pong counts both match, and the value also
1640 // matches.
1641 pi1_event_loop->MakeWatcher(
1642 "/test", [&pi1_event_loop, &pi1_ping_count,
1643 &pi1_pong_count](const examples::Pong &pong) {
1644 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1645 << pi1_event_loop->context().monotonic_remote_time << " -> "
1646 << pi1_event_loop->context().monotonic_event_time;
1647
1648 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1649 pi1_pong_count + kQueueIndexOffset);
1650 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1651 chrono::microseconds(200) +
1652 pi1_pong_count * chrono::milliseconds(10) +
1653 monotonic_clock::epoch());
1654 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1655 chrono::microseconds(200) +
1656 pi1_pong_count * chrono::milliseconds(10) +
1657 realtime_clock::epoch());
1658
1659 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1660 chrono::microseconds(150),
1661 pi1_event_loop->context().monotonic_event_time);
1662 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1663 chrono::microseconds(150),
1664 pi1_event_loop->context().realtime_event_time);
1665
1666 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1667 ++pi1_pong_count;
1668 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1669 });
1670 pi2_event_loop->MakeWatcher(
1671 "/test", [&pi2_event_loop, &pi2_ping_count,
1672 &pi2_pong_count](const examples::Pong &pong) {
1673 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1674 << pi2_event_loop->context().monotonic_remote_time << " -> "
1675 << pi2_event_loop->context().monotonic_event_time;
1676
1677 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001678 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001679
1680 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1681 chrono::microseconds(200) +
1682 pi2_pong_count * chrono::milliseconds(10) +
1683 monotonic_clock::epoch());
1684 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1685 chrono::microseconds(200) +
1686 pi2_pong_count * chrono::milliseconds(10) +
1687 realtime_clock::epoch());
1688
1689 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1690 pi2_event_loop->context().monotonic_event_time);
1691 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1692 pi2_event_loop->context().realtime_event_time);
1693
1694 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1695 ++pi2_pong_count;
1696 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1697 });
1698
1699 log_reader_factory.Run();
1700 EXPECT_EQ(pi1_ping_count, 2010);
1701 EXPECT_EQ(pi2_ping_count, 2010);
1702 EXPECT_EQ(pi1_pong_count, 2010);
1703 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001704
1705 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001706}
1707
James Kuszmaul46d82582020-05-09 19:50:09 -07001708typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1709
1710// Test that if we feed the replay with a mismatched node list that we die on
1711// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001712TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001713 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001714 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001715 LoggerState pi1_logger = MakeLogger(pi1_);
1716 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001717
1718 event_loop_factory_.RunFor(chrono::milliseconds(95));
1719
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001720 StartLogger(&pi1_logger);
1721 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001722
James Kuszmaul46d82582020-05-09 19:50:09 -07001723 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1724 }
1725
1726 // Test that, if we add an additional node to the replay config that the
1727 // logger complains about the mismatch in number of nodes.
1728 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1729 configuration::MergeWithConfig(&config_.message(), R"({
1730 "nodes": [
1731 {
1732 "name": "extra-node"
1733 }
1734 ]
1735 }
1736 )");
1737
Austin Schuh287d43d2020-12-04 20:19:33 -08001738 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1739 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001740 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001741}
1742
Austin Schuhcde938c2020-02-02 17:30:07 -08001743// Tests that we can read log files where they don't start at the same monotonic
1744// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001745TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001746 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001747 std::vector<std::string> actual_filenames;
1748
Austin Schuhcde938c2020-02-02 17:30:07 -08001749 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001750 LoggerState pi1_logger = MakeLogger(pi1_);
1751 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001752
1753 event_loop_factory_.RunFor(chrono::milliseconds(95));
1754
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001755 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001756
1757 event_loop_factory_.RunFor(chrono::milliseconds(200));
1758
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001759 StartLogger(&pi2_logger);
1760
Austin Schuhcde938c2020-02-02 17:30:07 -08001761 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001762 pi1_logger.AppendAllFilenames(&actual_filenames);
1763 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001764 }
1765
Austin Schuhe46492f2021-07-31 19:49:41 -07001766 // Since we delay starting pi2, it already knows about all the timestamps so
1767 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001768 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001769
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001770 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001771 log_reader_factory.set_send_delay(chrono::microseconds(0));
1772
1773 // This sends out the fetched messages and advances time to the start of the
1774 // log file.
1775 reader.Register(&log_reader_factory);
1776
1777 const Node *pi1 =
1778 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1779 const Node *pi2 =
1780 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1781
Austin Schuh07676622021-01-21 18:59:17 -08001782 EXPECT_THAT(reader.LoggedNodes(),
1783 ::testing::ElementsAre(
1784 configuration::GetNode(reader.logged_configuration(), pi1),
1785 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001786
1787 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1788
1789 std::unique_ptr<EventLoop> pi1_event_loop =
1790 log_reader_factory.MakeEventLoop("test", pi1);
1791 std::unique_ptr<EventLoop> pi2_event_loop =
1792 log_reader_factory.MakeEventLoop("test", pi2);
1793
1794 int pi1_ping_count = 30;
1795 int pi2_ping_count = 30;
1796 int pi1_pong_count = 30;
1797 int pi2_pong_count = 30;
1798
1799 // Confirm that the ping value matches.
1800 pi1_event_loop->MakeWatcher(
1801 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1802 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1803 << pi1_event_loop->context().monotonic_remote_time << " -> "
1804 << pi1_event_loop->context().monotonic_event_time;
1805 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1806
1807 ++pi1_ping_count;
1808 });
1809 pi2_event_loop->MakeWatcher(
1810 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1811 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1812 << pi2_event_loop->context().monotonic_remote_time << " -> "
1813 << pi2_event_loop->context().monotonic_event_time;
1814 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1815
1816 ++pi2_ping_count;
1817 });
1818
1819 // Confirm that the ping and pong counts both match, and the value also
1820 // matches.
1821 pi1_event_loop->MakeWatcher(
1822 "/test", [&pi1_event_loop, &pi1_ping_count,
1823 &pi1_pong_count](const examples::Pong &pong) {
1824 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1825 << pi1_event_loop->context().monotonic_remote_time << " -> "
1826 << pi1_event_loop->context().monotonic_event_time;
1827
1828 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1829 ++pi1_pong_count;
1830 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1831 });
1832 pi2_event_loop->MakeWatcher(
1833 "/test", [&pi2_event_loop, &pi2_ping_count,
1834 &pi2_pong_count](const examples::Pong &pong) {
1835 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1836 << pi2_event_loop->context().monotonic_remote_time << " -> "
1837 << pi2_event_loop->context().monotonic_event_time;
1838
1839 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1840 ++pi2_pong_count;
1841 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1842 });
1843
1844 log_reader_factory.Run();
1845 EXPECT_EQ(pi1_ping_count, 2030);
1846 EXPECT_EQ(pi2_ping_count, 2030);
1847 EXPECT_EQ(pi1_pong_count, 2030);
1848 EXPECT_EQ(pi2_pong_count, 2030);
1849
1850 reader.Deregister();
1851}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001852
Austin Schuh8bd96322020-02-13 21:18:22 -08001853// Tests that we can read log files where the monotonic clocks drift and don't
1854// match correctly. While we are here, also test that different ending times
1855// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001856TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001857 // TODO(austin): Negate...
1858 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1859
Austin Schuh66168842021-08-17 19:42:21 -07001860 time_converter_.AddMonotonic(
1861 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001862 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1863 // skew to be 200 uS/s
1864 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1865 {chrono::milliseconds(95),
1866 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1867 // Run another 200 ms to have one logger start first.
1868 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1869 {chrono::milliseconds(200), chrono::milliseconds(200)});
1870 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1871 // go far enough to cause problems if this isn't accounted for.
1872 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1873 {chrono::milliseconds(20000),
1874 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1875 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1876 {chrono::milliseconds(40000),
1877 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1878 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1879 {chrono::milliseconds(400), chrono::milliseconds(400)});
1880
Austin Schuhcde938c2020-02-02 17:30:07 -08001881 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001882 LoggerState pi2_logger = MakeLogger(pi2_);
1883
Austin Schuh58646e22021-08-23 23:51:46 -07001884 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1885 << pi2_->realtime_now() << " distributed "
1886 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001887
Austin Schuh58646e22021-08-23 23:51:46 -07001888 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1889 << pi2_->realtime_now() << " distributed "
1890 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001891
Austin Schuh87dd3832021-01-01 23:07:31 -08001892 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001893
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001894 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001895
Austin Schuh87dd3832021-01-01 23:07:31 -08001896 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001897
Austin Schuh8bd96322020-02-13 21:18:22 -08001898 {
1899 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001900 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001901
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001902 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001903 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001904
Austin Schuh87dd3832021-01-01 23:07:31 -08001905 // Make sure we slewed time far enough so that the difference is greater
1906 // than the network delay. This confirms that if we sort incorrectly, it
1907 // would show in the results.
1908 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001909 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001910 -event_loop_factory_.send_delay() -
1911 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001912
Austin Schuh87dd3832021-01-01 23:07:31 -08001913 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001914
Austin Schuh87dd3832021-01-01 23:07:31 -08001915 // And now check that we went far enough the other way to make sure we
1916 // cover both problems.
1917 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001918 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001919 event_loop_factory_.send_delay() +
1920 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001921 }
1922
1923 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001924 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001925 }
1926
Austin Schuh72211ae2021-08-05 14:02:30 -07001927 LogReader reader(
1928 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001929
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001930 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001931 log_reader_factory.set_send_delay(chrono::microseconds(0));
1932
Austin Schuhcde938c2020-02-02 17:30:07 -08001933 const Node *pi1 =
1934 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1935 const Node *pi2 =
1936 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1937
Austin Schuh2f8fd752020-09-01 22:38:28 -07001938 // This sends out the fetched messages and advances time to the start of the
1939 // log file.
1940 reader.Register(&log_reader_factory);
1941
1942 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1943 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1944 LOG(INFO) << "now pi1 "
1945 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1946 LOG(INFO) << "now pi2 "
1947 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1948
Austin Schuhcde938c2020-02-02 17:30:07 -08001949 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001950 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1951 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001952 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1953 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001954 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1955 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001956 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1957
Austin Schuh07676622021-01-21 18:59:17 -08001958 EXPECT_THAT(reader.LoggedNodes(),
1959 ::testing::ElementsAre(
1960 configuration::GetNode(reader.logged_configuration(), pi1),
1961 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001962
1963 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1964
1965 std::unique_ptr<EventLoop> pi1_event_loop =
1966 log_reader_factory.MakeEventLoop("test", pi1);
1967 std::unique_ptr<EventLoop> pi2_event_loop =
1968 log_reader_factory.MakeEventLoop("test", pi2);
1969
1970 int pi1_ping_count = 30;
1971 int pi2_ping_count = 30;
1972 int pi1_pong_count = 30;
1973 int pi2_pong_count = 30;
1974
1975 // Confirm that the ping value matches.
1976 pi1_event_loop->MakeWatcher(
1977 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1978 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1979 << pi1_event_loop->context().monotonic_remote_time << " -> "
1980 << pi1_event_loop->context().monotonic_event_time;
1981 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1982
1983 ++pi1_ping_count;
1984 });
1985 pi2_event_loop->MakeWatcher(
1986 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1987 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1988 << pi2_event_loop->context().monotonic_remote_time << " -> "
1989 << pi2_event_loop->context().monotonic_event_time;
1990 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1991
1992 ++pi2_ping_count;
1993 });
1994
1995 // Confirm that the ping and pong counts both match, and the value also
1996 // matches.
1997 pi1_event_loop->MakeWatcher(
1998 "/test", [&pi1_event_loop, &pi1_ping_count,
1999 &pi1_pong_count](const examples::Pong &pong) {
2000 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
2001 << pi1_event_loop->context().monotonic_remote_time << " -> "
2002 << pi1_event_loop->context().monotonic_event_time;
2003
2004 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
2005 ++pi1_pong_count;
2006 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
2007 });
2008 pi2_event_loop->MakeWatcher(
2009 "/test", [&pi2_event_loop, &pi2_ping_count,
2010 &pi2_pong_count](const examples::Pong &pong) {
2011 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
2012 << pi2_event_loop->context().monotonic_remote_time << " -> "
2013 << pi2_event_loop->context().monotonic_event_time;
2014
2015 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
2016 ++pi2_pong_count;
2017 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
2018 });
2019
2020 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08002021 EXPECT_EQ(pi1_ping_count, 6030);
2022 EXPECT_EQ(pi2_ping_count, 6030);
2023 EXPECT_EQ(pi1_pong_count, 6030);
2024 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08002025
2026 reader.Deregister();
2027}
2028
Austin Schuh5212cad2020-09-09 23:12:09 -07002029// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002030TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002031 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07002032 // Make a bunch of parts.
2033 {
2034 LoggerState pi1_logger = MakeLogger(pi1_);
2035 LoggerState pi2_logger = MakeLogger(pi2_);
2036
2037 event_loop_factory_.RunFor(chrono::milliseconds(95));
2038
2039 StartLogger(&pi1_logger);
2040 StartLogger(&pi2_logger);
2041
2042 event_loop_factory_.RunFor(chrono::milliseconds(2000));
2043 }
2044
Austin Schuh11d43732020-09-21 17:28:30 -07002045 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002046 VerifyParts(sorted_parts);
2047}
Austin Schuh11d43732020-09-21 17:28:30 -07002048
Austin Schuh3bd4c402020-11-06 18:19:06 -08002049// Tests that we can sort a bunch of parts with an empty part. We should ignore
2050// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08002051TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002052 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002053 // Make a bunch of parts.
2054 {
2055 LoggerState pi1_logger = MakeLogger(pi1_);
2056 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07002057
Austin Schuh3bd4c402020-11-06 18:19:06 -08002058 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07002059
Austin Schuh3bd4c402020-11-06 18:19:06 -08002060 StartLogger(&pi1_logger);
2061 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07002062
Austin Schuh3bd4c402020-11-06 18:19:06 -08002063 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07002064 }
2065
Austin Schuh3bd4c402020-11-06 18:19:06 -08002066 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07002067 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07002068
Austin Schuh3bd4c402020-11-06 18:19:06 -08002069 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
2070 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07002071
Austin Schuh3bd4c402020-11-06 18:19:06 -08002072 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2073 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07002074}
2075
James Kuszmauldd0a5042021-10-28 23:38:04 -07002076// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08002077// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002078TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002079 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002080 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002081 // Make a bunch of parts.
2082 {
2083 LoggerState pi1_logger = MakeLogger(pi1_);
2084 LoggerState pi2_logger = MakeLogger(pi2_);
2085
2086 event_loop_factory_.RunFor(chrono::milliseconds(95));
2087
James Kuszmauldd0a5042021-10-28 23:38:04 -07002088 StartLogger(&pi1_logger);
2089 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002090
2091 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002092
2093 pi1_logger.AppendAllFilenames(&actual_filenames);
2094 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002095 }
2096
Austin Schuhbfe6c572022-01-27 20:48:20 -08002097 ASSERT_THAT(actual_filenames,
2098 ::testing::UnorderedElementsAreArray(logfiles_));
2099
Austin Schuh3bd4c402020-11-06 18:19:06 -08002100 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002101 // For snappy, needs to have enough data to be >1 chunk of compressed data so
2102 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08002103 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08002104 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002105
2106 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08002107 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08002108 compressed_contents.substr(0, compressed_contents.size() - 100));
2109
2110 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2111 VerifyParts(sorted_parts);
2112}
Austin Schuh3bd4c402020-11-06 18:19:06 -08002113
Austin Schuh01b4c352020-09-21 23:09:39 -07002114// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08002115TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002116 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07002117 {
2118 LoggerState pi1_logger = MakeLogger(pi1_);
2119 LoggerState pi2_logger = MakeLogger(pi2_);
2120
2121 event_loop_factory_.RunFor(chrono::milliseconds(95));
2122
2123 StartLogger(&pi1_logger);
2124 StartLogger(&pi2_logger);
2125
2126 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2127 }
2128
Austin Schuh287d43d2020-12-04 20:19:33 -08002129 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07002130
2131 // Remap just on pi1.
2132 reader.RemapLoggedChannel<aos::timing::Report>(
2133 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
2134
2135 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2136 log_reader_factory.set_send_delay(chrono::microseconds(0));
2137
Austin Schuh1c227352021-09-17 12:53:54 -07002138 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
James Kuszmaul53da7f32022-09-11 11:11:55 -07002139 // Note: An extra channel gets remapped automatically due to a timestamp
2140 // channel being LOCAL_LOGGER'd.
2141 ASSERT_EQ(remapped_channels.size(), std::get<0>(GetParam()).shared ? 1u : 2u);
Austin Schuh1c227352021-09-17 12:53:54 -07002142 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
2143 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
James Kuszmaul53da7f32022-09-11 11:11:55 -07002144 if (!std::get<0>(GetParam()).shared) {
2145 EXPECT_EQ(remapped_channels[1]->name()->string_view(),
2146 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
2147 "aos-message_bridge-Timestamp");
2148 EXPECT_EQ(remapped_channels[1]->type()->string_view(),
2149 "aos.message_bridge.RemoteMessage");
2150 }
Austin Schuh1c227352021-09-17 12:53:54 -07002151
Austin Schuh01b4c352020-09-21 23:09:39 -07002152 reader.Register(&log_reader_factory);
2153
2154 const Node *pi1 =
2155 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2156 const Node *pi2 =
2157 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2158
2159 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2160 // else should have moved.
2161 std::unique_ptr<EventLoop> pi1_event_loop =
2162 log_reader_factory.MakeEventLoop("test", pi1);
2163 pi1_event_loop->SkipTimingReport();
2164 std::unique_ptr<EventLoop> full_pi1_event_loop =
2165 log_reader_factory.MakeEventLoop("test", pi1);
2166 full_pi1_event_loop->SkipTimingReport();
2167 std::unique_ptr<EventLoop> pi2_event_loop =
2168 log_reader_factory.MakeEventLoop("test", pi2);
2169 pi2_event_loop->SkipTimingReport();
2170
2171 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
2172 "/aos");
2173 MessageCounter<aos::timing::Report> full_pi1_timing_report(
2174 full_pi1_event_loop.get(), "/pi1/aos");
2175 MessageCounter<aos::timing::Report> pi1_original_timing_report(
2176 pi1_event_loop.get(), "/original/aos");
2177 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
2178 full_pi1_event_loop.get(), "/original/pi1/aos");
2179 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
2180 "/aos");
2181
2182 log_reader_factory.Run();
2183
2184 EXPECT_EQ(pi1_timing_report.count(), 0u);
2185 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
2186 EXPECT_NE(pi1_original_timing_report.count(), 0u);
2187 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
2188 EXPECT_NE(pi2_timing_report.count(), 0u);
2189
2190 reader.Deregister();
2191}
2192
Austin Schuh006a9f52021-04-07 16:24:18 -07002193// Tests that we can remap a forwarded channel as well.
2194TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
2195 time_converter_.StartEqual();
2196 {
2197 LoggerState pi1_logger = MakeLogger(pi1_);
2198 LoggerState pi2_logger = MakeLogger(pi2_);
2199
2200 event_loop_factory_.RunFor(chrono::milliseconds(95));
2201
2202 StartLogger(&pi1_logger);
2203 StartLogger(&pi2_logger);
2204
2205 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2206 }
2207
2208 LogReader reader(SortParts(logfiles_));
2209
2210 reader.RemapLoggedChannel<examples::Ping>("/test");
2211
2212 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2213 log_reader_factory.set_send_delay(chrono::microseconds(0));
2214
2215 reader.Register(&log_reader_factory);
2216
2217 const Node *pi1 =
2218 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2219 const Node *pi2 =
2220 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2221
2222 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2223 // else should have moved.
2224 std::unique_ptr<EventLoop> pi1_event_loop =
2225 log_reader_factory.MakeEventLoop("test", pi1);
2226 pi1_event_loop->SkipTimingReport();
2227 std::unique_ptr<EventLoop> full_pi1_event_loop =
2228 log_reader_factory.MakeEventLoop("test", pi1);
2229 full_pi1_event_loop->SkipTimingReport();
2230 std::unique_ptr<EventLoop> pi2_event_loop =
2231 log_reader_factory.MakeEventLoop("test", pi2);
2232 pi2_event_loop->SkipTimingReport();
2233
2234 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2235 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2236 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2237 "/original/test");
2238 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2239 "/original/test");
2240
2241 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2242 pi1_original_ping_timestamp;
2243 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2244 pi1_ping_timestamp;
2245 if (!shared()) {
2246 pi1_original_ping_timestamp =
2247 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2248 pi1_event_loop.get(),
2249 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2250 pi1_ping_timestamp =
2251 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2252 pi1_event_loop.get(),
2253 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2254 }
2255
2256 log_reader_factory.Run();
2257
2258 EXPECT_EQ(pi1_ping.count(), 0u);
2259 EXPECT_EQ(pi2_ping.count(), 0u);
2260 EXPECT_NE(pi1_original_ping.count(), 0u);
2261 EXPECT_NE(pi2_original_ping.count(), 0u);
2262 if (!shared()) {
2263 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2264 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2265 }
2266
2267 reader.Deregister();
2268}
2269
James Kuszmaul09632422022-05-25 15:56:19 -07002270// Tests that we observe all the same events in log replay (for a given node)
2271// whether we just register an event loop for that node or if we register a full
2272// event loop factory.
2273TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
2274 time_converter_.StartEqual();
2275 constexpr chrono::milliseconds kStartupDelay(95);
2276 {
2277 LoggerState pi1_logger = MakeLogger(pi1_);
2278 LoggerState pi2_logger = MakeLogger(pi2_);
2279
2280 event_loop_factory_.RunFor(kStartupDelay);
2281
2282 StartLogger(&pi1_logger);
2283 StartLogger(&pi2_logger);
2284
2285 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2286 }
2287
2288 LogReader full_reader(SortParts(logfiles_));
2289 LogReader single_node_reader(SortParts(logfiles_));
2290
2291 SimulatedEventLoopFactory full_factory(full_reader.configuration());
2292 SimulatedEventLoopFactory single_node_factory(
2293 single_node_reader.configuration());
James Kuszmaul94ca5132022-07-19 09:11:08 -07002294 single_node_factory.SkipTimingReport();
2295 single_node_factory.DisableStatistics();
James Kuszmaul09632422022-05-25 15:56:19 -07002296 std::unique_ptr<EventLoop> replay_event_loop =
2297 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
2298 "log_reader");
2299
2300 full_reader.Register(&full_factory);
2301 single_node_reader.Register(replay_event_loop.get());
James Kuszmaul09632422022-05-25 15:56:19 -07002302
2303 const Node *full_pi1 =
2304 configuration::GetNode(full_factory.configuration(), "pi1");
2305
2306 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2307 // else should have moved.
2308 std::unique_ptr<EventLoop> full_event_loop =
2309 full_factory.MakeEventLoop("test", full_pi1);
2310 full_event_loop->SkipTimingReport();
2311 full_event_loop->SkipAosLog();
2312 // maps are indexed on channel index.
2313 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
2314 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
2315 observed_messages;
2316 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
2317 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
2318 ++ii) {
2319 const Channel *channel =
2320 full_event_loop->configuration()->channels()->Get(ii);
2321 // We currently don't support replaying remote timestamp channels in
James Kuszmaul53da7f32022-09-11 11:11:55 -07002322 // realtime replay (unless the remote timestamp channel was not NOT_LOGGED,
2323 // in which case it gets auto-remapped and replayed on a /original channel).
James Kuszmaul09632422022-05-25 15:56:19 -07002324 if (channel->name()->string_view().find("remote_timestamp") !=
James Kuszmaul53da7f32022-09-11 11:11:55 -07002325 std::string_view::npos &&
2326 channel->name()->string_view().find("/original") ==
2327 std::string_view::npos) {
James Kuszmaul09632422022-05-25 15:56:19 -07002328 continue;
2329 }
2330 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
2331 observed_messages[ii] = {};
2332 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
2333 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
2334 if (fetchers[ii]->Fetch()) {
2335 observed_messages[ii].push_back(std::make_pair(
2336 fetchers[ii]->context().monotonic_event_time, true));
2337 }
2338 });
2339 full_event_loop->MakeRawNoArgWatcher(
2340 channel, [ii, &observed_messages](const Context &context) {
2341 observed_messages[ii].push_back(
2342 std::make_pair(context.monotonic_event_time, false));
2343 });
2344 }
2345 }
2346
2347 full_factory.Run();
2348 fetchers.clear();
2349 full_reader.Deregister();
2350
2351 const Node *single_node_pi1 =
2352 configuration::GetNode(single_node_factory.configuration(), "pi1");
2353 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
2354
2355 std::unique_ptr<EventLoop> single_node_event_loop =
2356 single_node_factory.MakeEventLoop("test", single_node_pi1);
2357 single_node_event_loop->SkipTimingReport();
2358 single_node_event_loop->SkipAosLog();
2359 for (size_t ii = 0;
2360 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
2361 const Channel *channel =
2362 single_node_event_loop->configuration()->channels()->Get(ii);
2363 single_node_factory.DisableForwarding(channel);
2364 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
2365 single_node_fetchers[ii] =
2366 single_node_event_loop->MakeRawFetcher(channel);
2367 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
2368 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
2369 << "Single EventLoop replay doesn't support pre-loading fetchers. "
2370 << configuration::StrippedChannelToString(channel);
2371 });
2372 single_node_event_loop->MakeRawNoArgWatcher(
2373 channel, [ii, &observed_messages, channel,
2374 kStartupDelay](const Context &context) {
2375 if (observed_messages[ii].empty()) {
2376 FAIL() << "Observed extra message at "
2377 << context.monotonic_event_time << " on "
2378 << configuration::StrippedChannelToString(channel);
2379 return;
2380 }
2381 const std::pair<monotonic_clock::time_point, bool> &message =
2382 observed_messages[ii].front();
2383 if (message.second) {
2384 EXPECT_LE(message.first,
2385 context.monotonic_event_time + kStartupDelay)
2386 << "Mismatched message times " << context.monotonic_event_time
2387 << " and " << message.first << " on "
2388 << configuration::StrippedChannelToString(channel);
2389 } else {
2390 EXPECT_EQ(message.first,
2391 context.monotonic_event_time + kStartupDelay)
2392 << "Mismatched message times " << context.monotonic_event_time
2393 << " and " << message.first << " on "
2394 << configuration::StrippedChannelToString(channel);
2395 }
2396 observed_messages[ii].erase(observed_messages[ii].begin());
2397 });
2398 }
2399 }
2400
2401 single_node_factory.Run();
2402
2403 single_node_fetchers.clear();
2404
2405 single_node_reader.Deregister();
2406
2407 for (const auto &pair : observed_messages) {
2408 EXPECT_TRUE(pair.second.empty())
2409 << "Missed " << pair.second.size() << " messages on "
2410 << configuration::StrippedChannelToString(
2411 single_node_event_loop->configuration()->channels()->Get(
2412 pair.first));
2413 }
2414}
2415
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002416// Tests that we properly recreate forwarded timestamps when replaying a log.
2417// This should be enough that we can then re-run the logger and get a valid log
2418// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002419TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002420 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002421 {
2422 LoggerState pi1_logger = MakeLogger(pi1_);
2423 LoggerState pi2_logger = MakeLogger(pi2_);
2424
2425 event_loop_factory_.RunFor(chrono::milliseconds(95));
2426
2427 StartLogger(&pi1_logger);
2428 StartLogger(&pi2_logger);
2429
2430 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2431 }
2432
Austin Schuh287d43d2020-12-04 20:19:33 -08002433 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002434
2435 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2436 log_reader_factory.set_send_delay(chrono::microseconds(0));
2437
2438 // This sends out the fetched messages and advances time to the start of the
2439 // log file.
2440 reader.Register(&log_reader_factory);
2441
2442 const Node *pi1 =
2443 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2444 const Node *pi2 =
2445 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2446
2447 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2448 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2449 LOG(INFO) << "now pi1 "
2450 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2451 LOG(INFO) << "now pi2 "
2452 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2453
Austin Schuh07676622021-01-21 18:59:17 -08002454 EXPECT_THAT(reader.LoggedNodes(),
2455 ::testing::ElementsAre(
2456 configuration::GetNode(reader.logged_configuration(), pi1),
2457 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002458
2459 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2460
2461 std::unique_ptr<EventLoop> pi1_event_loop =
2462 log_reader_factory.MakeEventLoop("test", pi1);
2463 std::unique_ptr<EventLoop> pi2_event_loop =
2464 log_reader_factory.MakeEventLoop("test", pi2);
2465
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002466 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2467 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2468 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2469 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2470
2471 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2472 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2473 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2474 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2475
2476 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2477 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2478 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2479 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2480
2481 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2482 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2483 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2484 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2485
2486 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2487 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2488 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2489 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2490
2491 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2492 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2493 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2494 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2495
Austin Schuh969cd602021-01-03 00:09:45 -08002496 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002497 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002498
Austin Schuh61e973f2021-02-21 21:43:56 -08002499 for (std::pair<int, std::string> channel :
2500 shared()
2501 ? std::vector<
2502 std::pair<int, std::string>>{{-1,
2503 "/aos/remote_timestamps/pi2"}}
2504 : std::vector<std::pair<int, std::string>>{
2505 {pi1_timestamp_channel,
2506 "/aos/remote_timestamps/pi2/pi1/aos/"
2507 "aos-message_bridge-Timestamp"},
2508 {ping_timestamp_channel,
2509 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2510 pi1_event_loop->MakeWatcher(
2511 channel.second,
2512 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2513 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2514 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2515 &ping_on_pi2_fetcher, network_delay, send_delay,
2516 channel_index = channel.first](const RemoteMessage &header) {
2517 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2518 chrono::nanoseconds(header.monotonic_sent_time()));
2519 const aos::realtime_clock::time_point header_realtime_sent_time(
2520 chrono::nanoseconds(header.realtime_sent_time()));
2521 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2522 chrono::nanoseconds(header.monotonic_remote_time()));
2523 const aos::realtime_clock::time_point header_realtime_remote_time(
2524 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002525
Austin Schuh61e973f2021-02-21 21:43:56 -08002526 if (channel_index != -1) {
2527 ASSERT_EQ(channel_index, header.channel_index());
2528 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002529
Austin Schuh61e973f2021-02-21 21:43:56 -08002530 const Context *pi1_context = nullptr;
2531 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002532
Austin Schuh61e973f2021-02-21 21:43:56 -08002533 if (header.channel_index() == pi1_timestamp_channel) {
2534 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2535 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2536 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2537 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2538 } else if (header.channel_index() == ping_timestamp_channel) {
2539 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2540 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2541 pi1_context = &ping_on_pi1_fetcher.context();
2542 pi2_context = &ping_on_pi2_fetcher.context();
2543 } else {
2544 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2545 << configuration::CleanedChannelToString(
2546 pi1_event_loop->configuration()->channels()->Get(
2547 header.channel_index()));
2548 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002549
Austin Schuh61e973f2021-02-21 21:43:56 -08002550 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002551 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2552 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002553
Austin Schuh61e973f2021-02-21 21:43:56 -08002554 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2555 EXPECT_EQ(pi2_context->remote_queue_index,
2556 header.remote_queue_index());
2557 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002558
Austin Schuh61e973f2021-02-21 21:43:56 -08002559 EXPECT_EQ(pi2_context->monotonic_event_time,
2560 header_monotonic_sent_time);
2561 EXPECT_EQ(pi2_context->realtime_event_time,
2562 header_realtime_sent_time);
2563 EXPECT_EQ(pi2_context->realtime_remote_time,
2564 header_realtime_remote_time);
2565 EXPECT_EQ(pi2_context->monotonic_remote_time,
2566 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002567
Austin Schuh61e973f2021-02-21 21:43:56 -08002568 EXPECT_EQ(pi1_context->realtime_event_time,
2569 header_realtime_remote_time);
2570 EXPECT_EQ(pi1_context->monotonic_event_time,
2571 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002572
Austin Schuh61e973f2021-02-21 21:43:56 -08002573 // Time estimation isn't perfect, but we know the clocks were
2574 // identical when logged, so we know when this should have come back.
2575 // Confirm we got it when we expected.
2576 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2577 pi1_context->monotonic_event_time + 2 * network_delay +
2578 send_delay);
2579 });
2580 }
2581 for (std::pair<int, std::string> channel :
2582 shared()
2583 ? std::vector<
2584 std::pair<int, std::string>>{{-1,
2585 "/aos/remote_timestamps/pi1"}}
2586 : std::vector<std::pair<int, std::string>>{
2587 {pi2_timestamp_channel,
2588 "/aos/remote_timestamps/pi1/pi2/aos/"
2589 "aos-message_bridge-Timestamp"}}) {
2590 pi2_event_loop->MakeWatcher(
2591 channel.second,
2592 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2593 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2594 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2595 &pong_on_pi1_fetcher, network_delay, send_delay,
2596 channel_index = channel.first](const RemoteMessage &header) {
2597 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2598 chrono::nanoseconds(header.monotonic_sent_time()));
2599 const aos::realtime_clock::time_point header_realtime_sent_time(
2600 chrono::nanoseconds(header.realtime_sent_time()));
2601 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2602 chrono::nanoseconds(header.monotonic_remote_time()));
2603 const aos::realtime_clock::time_point header_realtime_remote_time(
2604 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002605
Austin Schuh61e973f2021-02-21 21:43:56 -08002606 if (channel_index != -1) {
2607 ASSERT_EQ(channel_index, header.channel_index());
2608 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002609
Austin Schuh61e973f2021-02-21 21:43:56 -08002610 const Context *pi2_context = nullptr;
2611 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002612
Austin Schuh61e973f2021-02-21 21:43:56 -08002613 if (header.channel_index() == pi2_timestamp_channel) {
2614 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2615 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2616 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2617 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2618 } else if (header.channel_index() == pong_timestamp_channel) {
2619 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2620 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2621 pi2_context = &pong_on_pi2_fetcher.context();
2622 pi1_context = &pong_on_pi1_fetcher.context();
2623 } else {
2624 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2625 << configuration::CleanedChannelToString(
2626 pi2_event_loop->configuration()->channels()->Get(
2627 header.channel_index()));
2628 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002629
Austin Schuh61e973f2021-02-21 21:43:56 -08002630 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002631 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2632 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002633
Austin Schuh61e973f2021-02-21 21:43:56 -08002634 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2635 EXPECT_EQ(pi1_context->remote_queue_index,
2636 header.remote_queue_index());
2637 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002638
Austin Schuh61e973f2021-02-21 21:43:56 -08002639 EXPECT_EQ(pi1_context->monotonic_event_time,
2640 header_monotonic_sent_time);
2641 EXPECT_EQ(pi1_context->realtime_event_time,
2642 header_realtime_sent_time);
2643 EXPECT_EQ(pi1_context->realtime_remote_time,
2644 header_realtime_remote_time);
2645 EXPECT_EQ(pi1_context->monotonic_remote_time,
2646 header_monotonic_remote_time);
2647
2648 EXPECT_EQ(pi2_context->realtime_event_time,
2649 header_realtime_remote_time);
2650 EXPECT_EQ(pi2_context->monotonic_event_time,
2651 header_monotonic_remote_time);
2652
2653 // Time estimation isn't perfect, but we know the clocks were
2654 // identical when logged, so we know when this should have come back.
2655 // Confirm we got it when we expected.
2656 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2657 pi2_context->monotonic_event_time + 2 * network_delay +
2658 send_delay);
2659 });
2660 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002661
2662 // And confirm we can re-create a log again, while checking the contents.
2663 {
2664 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002665 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002666 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002667 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002668
Austin Schuh25b46712021-01-03 00:04:38 -08002669 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2670 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002671
2672 log_reader_factory.Run();
2673 }
2674
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002675 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002676
2677 // And verify that we can run the LogReader over the relogged files without
2678 // hitting any fatal errors.
2679 {
James Kuszmaul53da7f32022-09-11 11:11:55 -07002680 LogReader relogged_reader(SortParts(MakeLogFiles(
2681 tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2", 3, 3, true)));
2682 relogged_reader.Register();
2683
2684 relogged_reader.event_loop_factory()->Run();
2685 }
2686 // And confirm that we can read the logged file using the reader's
2687 // configuration.
2688 {
2689 LogReader relogged_reader(
2690 SortParts(MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2",
2691 3, 3, true)),
2692 reader.configuration());
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002693 relogged_reader.Register();
2694
2695 relogged_reader.event_loop_factory()->Run();
2696 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002697}
2698
Austin Schuh315b96b2020-12-11 21:21:12 -08002699// Tests that we properly populate and extract the logger_start time by setting
2700// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002701TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002702 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002703 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002704 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002705 {
2706 LoggerState pi1_logger = MakeLogger(pi1_);
2707 LoggerState pi2_logger = MakeLogger(pi2_);
2708
Austin Schuh315b96b2020-12-11 21:21:12 -08002709 StartLogger(&pi1_logger);
2710 StartLogger(&pi2_logger);
2711
2712 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002713
2714 pi1_logger.AppendAllFilenames(&actual_filenames);
2715 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002716 }
2717
Austin Schuhf5f99f32022-02-07 20:05:37 -08002718 ASSERT_THAT(actual_filenames,
2719 ::testing::UnorderedElementsAreArray(logfiles_));
2720
Austin Schuh315b96b2020-12-11 21:21:12 -08002721 for (const LogFile &log_file : SortParts(logfiles_)) {
2722 for (const LogParts &log_part : log_file.parts) {
2723 if (log_part.node == log_file.logger_node) {
2724 EXPECT_EQ(log_part.logger_monotonic_start_time,
2725 aos::monotonic_clock::min_time);
2726 EXPECT_EQ(log_part.logger_realtime_start_time,
2727 aos::realtime_clock::min_time);
2728 } else {
2729 const chrono::seconds offset = log_file.logger_node == "pi1"
2730 ? -chrono::seconds(1000)
2731 : chrono::seconds(1000);
2732 EXPECT_EQ(log_part.logger_monotonic_start_time,
2733 log_part.monotonic_start_time + offset);
2734 EXPECT_EQ(log_part.logger_realtime_start_time,
2735 log_file.realtime_start_time +
2736 (log_part.logger_monotonic_start_time -
2737 log_file.monotonic_start_time));
2738 }
2739 }
2740 }
2741}
2742
Austin Schuh6bb8a822021-03-31 23:04:39 -07002743// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002744TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002745 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2746 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002747 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002748 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002749 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2750 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2751 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2752 LoggerState pi1_logger = MakeLogger(pi1_);
2753 LoggerState pi2_logger = MakeLogger(pi2_);
2754
2755 StartLogger(&pi1_logger);
2756 StartLogger(&pi2_logger);
2757
2758 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2759 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2760 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2761 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2762 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2763 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2764 for (auto &file : logfiles_) {
2765 struct stat s;
2766 EXPECT_EQ(0, stat(file.c_str(), &s));
2767 }
2768}
2769
2770// Test that renaming the file base dies.
2771TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2772 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002773 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002774 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002775 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2776 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2777 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2778 LoggerState pi1_logger = MakeLogger(pi1_);
2779 StartLogger(&pi1_logger);
2780 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2781 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2782 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2783 "Rename of file base from");
2784}
2785
Austin Schuh8bd96322020-02-13 21:18:22 -08002786// TODO(austin): We can write a test which recreates a logfile and confirms that
2787// we get it back. That is the ultimate test.
2788
Austin Schuh315b96b2020-12-11 21:21:12 -08002789// Tests that we properly recreate forwarded timestamps when replaying a log.
2790// This should be enough that we can then re-run the logger and get a valid log
2791// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002792TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002793 std::vector<std::string> actual_filenames;
2794
Austin Schuh58646e22021-08-23 23:51:46 -07002795 const UUID pi1_boot0 = UUID::Random();
2796 const UUID pi2_boot0 = UUID::Random();
2797 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002798 {
Austin Schuh58646e22021-08-23 23:51:46 -07002799 CHECK_EQ(pi1_index_, 0u);
2800 CHECK_EQ(pi2_index_, 1u);
2801
2802 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2803 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2804 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2805
2806 time_converter_.AddNextTimestamp(
2807 distributed_clock::epoch(),
2808 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2809 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2810 time_converter_.AddNextTimestamp(
2811 distributed_clock::epoch() + reboot_time,
2812 {BootTimestamp::epoch() + reboot_time,
2813 BootTimestamp{
2814 .boot = 1,
2815 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2816 }
2817
2818 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002819 LoggerState pi1_logger = MakeLogger(pi1_);
2820
2821 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002822 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2823 pi1_boot0);
2824 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2825 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002826
2827 StartLogger(&pi1_logger);
2828
2829 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2830
Austin Schuh58646e22021-08-23 23:51:46 -07002831 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002832
2833 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002834 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2835 pi1_boot0);
2836 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2837 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002838
2839 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002840 }
2841
Austin Schuhbfe6c572022-01-27 20:48:20 -08002842 std::sort(actual_filenames.begin(), actual_filenames.end());
2843 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2844 ASSERT_THAT(actual_filenames,
2845 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2846
Austin Schuh72211ae2021-08-05 14:02:30 -07002847 // Confirm that our new oldest timestamps properly update as we reboot and
2848 // rotate.
2849 for (const std::string &file : pi1_reboot_logfiles_) {
2850 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2851 ReadHeader(file);
2852 CHECK(log_header);
2853 if (log_header->message().has_configuration()) {
2854 continue;
2855 }
2856
Austin Schuh58646e22021-08-23 23:51:46 -07002857 const monotonic_clock::time_point monotonic_start_time =
2858 monotonic_clock::time_point(
2859 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2860 const UUID source_node_boot_uuid = UUID::FromString(
2861 log_header->message().source_node_boot_uuid()->string_view());
2862
Austin Schuh72211ae2021-08-05 14:02:30 -07002863 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002864 // The remote message channel should rotate later and have more parts.
2865 // This only is true on the log files with shared remote messages.
2866 //
2867 // TODO(austin): I'm not the most thrilled with this test pattern... It
2868 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002869 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2870 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002871 switch (log_header->message().parts_index()) {
2872 case 0:
2873 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2874 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2875 break;
2876 case 1:
2877 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2878 ASSERT_EQ(monotonic_start_time,
2879 monotonic_clock::epoch() + chrono::seconds(1));
2880 break;
2881 case 2:
2882 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2883 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2884 break;
2885 case 3:
2886 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2887 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2888 chrono::nanoseconds(2322999462))
2889 << " on " << file;
2890 break;
2891 default:
2892 FAIL();
2893 break;
2894 }
2895 } else {
2896 switch (log_header->message().parts_index()) {
2897 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002898 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002899 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2900 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2901 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002902 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002903 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2904 ASSERT_EQ(monotonic_start_time,
2905 monotonic_clock::epoch() + chrono::seconds(1));
2906 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002907 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002908 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002909 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2910 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2911 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002912 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002913 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2914 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2915 chrono::nanoseconds(2322999462))
2916 << " on " << file;
2917 break;
2918 default:
2919 FAIL();
2920 break;
2921 }
Austin Schuh58646e22021-08-23 23:51:46 -07002922 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002923 continue;
2924 }
2925 SCOPED_TRACE(file);
2926 SCOPED_TRACE(aos::FlatbufferToJson(
2927 *log_header, {.multi_line = true, .max_vector_size = 100}));
2928 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2929 ASSERT_EQ(
2930 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2931 EXPECT_EQ(
2932 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2933 monotonic_clock::max_time.time_since_epoch().count());
2934 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2935 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2936 2u);
2937 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2938 monotonic_clock::max_time.time_since_epoch().count());
2939 ASSERT_TRUE(log_header->message()
2940 .has_oldest_remote_unreliable_monotonic_timestamps());
2941 ASSERT_EQ(log_header->message()
2942 .oldest_remote_unreliable_monotonic_timestamps()
2943 ->size(),
2944 2u);
2945 EXPECT_EQ(log_header->message()
2946 .oldest_remote_unreliable_monotonic_timestamps()
2947 ->Get(0),
2948 monotonic_clock::max_time.time_since_epoch().count());
2949 ASSERT_TRUE(log_header->message()
2950 .has_oldest_local_unreliable_monotonic_timestamps());
2951 ASSERT_EQ(log_header->message()
2952 .oldest_local_unreliable_monotonic_timestamps()
2953 ->size(),
2954 2u);
2955 EXPECT_EQ(log_header->message()
2956 .oldest_local_unreliable_monotonic_timestamps()
2957 ->Get(0),
2958 monotonic_clock::max_time.time_since_epoch().count());
2959
2960 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2961 monotonic_clock::time_point(chrono::nanoseconds(
2962 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2963 1)));
2964 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2965 monotonic_clock::time_point(chrono::nanoseconds(
2966 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2967 const monotonic_clock::time_point
2968 oldest_remote_unreliable_monotonic_timestamps =
2969 monotonic_clock::time_point(chrono::nanoseconds(
2970 log_header->message()
2971 .oldest_remote_unreliable_monotonic_timestamps()
2972 ->Get(1)));
2973 const monotonic_clock::time_point
2974 oldest_local_unreliable_monotonic_timestamps =
2975 monotonic_clock::time_point(chrono::nanoseconds(
2976 log_header->message()
2977 .oldest_local_unreliable_monotonic_timestamps()
2978 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002979 const monotonic_clock::time_point
2980 oldest_remote_reliable_monotonic_timestamps =
2981 monotonic_clock::time_point(chrono::nanoseconds(
2982 log_header->message()
2983 .oldest_remote_reliable_monotonic_timestamps()
2984 ->Get(1)));
2985 const monotonic_clock::time_point
2986 oldest_local_reliable_monotonic_timestamps =
2987 monotonic_clock::time_point(chrono::nanoseconds(
2988 log_header->message()
2989 .oldest_local_reliable_monotonic_timestamps()
2990 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002991 const monotonic_clock::time_point
2992 oldest_logger_remote_unreliable_monotonic_timestamps =
2993 monotonic_clock::time_point(chrono::nanoseconds(
2994 log_header->message()
2995 .oldest_logger_remote_unreliable_monotonic_timestamps()
2996 ->Get(0)));
2997 const monotonic_clock::time_point
2998 oldest_logger_local_unreliable_monotonic_timestamps =
2999 monotonic_clock::time_point(chrono::nanoseconds(
3000 log_header->message()
3001 .oldest_logger_local_unreliable_monotonic_timestamps()
3002 ->Get(0)));
3003 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3004 monotonic_clock::max_time);
3005 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3006 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003007 switch (log_header->message().parts_index()) {
3008 case 0:
3009 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3010 monotonic_clock::max_time);
3011 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3012 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3013 monotonic_clock::max_time);
3014 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3015 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08003016 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3017 monotonic_clock::max_time);
3018 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3019 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003020 break;
3021 case 1:
3022 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3023 monotonic_clock::time_point(chrono::microseconds(90200)));
3024 EXPECT_EQ(oldest_local_monotonic_timestamps,
3025 monotonic_clock::time_point(chrono::microseconds(90350)));
3026 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3027 monotonic_clock::time_point(chrono::microseconds(90200)));
3028 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3029 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003030 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3031 monotonic_clock::max_time);
3032 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3033 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003034 break;
3035 case 2:
3036 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003037 monotonic_clock::time_point(chrono::microseconds(90200)))
3038 << file;
3039 EXPECT_EQ(oldest_local_monotonic_timestamps,
3040 monotonic_clock::time_point(chrono::microseconds(90350)))
3041 << file;
3042 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3043 monotonic_clock::time_point(chrono::microseconds(90200)))
3044 << file;
3045 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3046 monotonic_clock::time_point(chrono::microseconds(90350)))
3047 << file;
3048 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3049 monotonic_clock::time_point(chrono::microseconds(100000)))
3050 << file;
3051 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3052 monotonic_clock::time_point(chrono::microseconds(100150)))
3053 << file;
3054 break;
3055 case 3:
3056 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003057 monotonic_clock::time_point(chrono::milliseconds(1323) +
3058 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003059 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003060 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003061 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003062 monotonic_clock::time_point(chrono::milliseconds(1323) +
3063 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003064 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3065 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003066 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3067 monotonic_clock::max_time)
3068 << file;
3069 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3070 monotonic_clock::max_time)
3071 << file;
3072 break;
3073 case 4:
3074 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3075 monotonic_clock::time_point(chrono::milliseconds(1323) +
3076 chrono::microseconds(200)));
3077 EXPECT_EQ(oldest_local_monotonic_timestamps,
3078 monotonic_clock::time_point(chrono::microseconds(10100350)));
3079 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3080 monotonic_clock::time_point(chrono::milliseconds(1323) +
3081 chrono::microseconds(200)));
3082 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3083 monotonic_clock::time_point(chrono::microseconds(10100350)));
3084 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3085 monotonic_clock::time_point(chrono::microseconds(1423000)))
3086 << file;
3087 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3088 monotonic_clock::time_point(chrono::microseconds(10200150)))
3089 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07003090 break;
3091 default:
3092 FAIL();
3093 break;
3094 }
3095 }
3096
Austin Schuh315b96b2020-12-11 21:21:12 -08003097 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07003098 {
3099 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08003100
Austin Schuh58646e22021-08-23 23:51:46 -07003101 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3102 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08003103
Austin Schuh58646e22021-08-23 23:51:46 -07003104 // This sends out the fetched messages and advances time to the start of
3105 // the log file.
3106 reader.Register(&log_reader_factory);
3107
3108 log_reader_factory.Run();
3109
3110 reader.Deregister();
3111 }
Austin Schuh315b96b2020-12-11 21:21:12 -08003112}
3113
Austin Schuh5e14d842022-01-21 12:02:15 -08003114// Tests that we can sort a log which only has timestamps from the remote
3115// because the local message_bridge_client failed to connect.
3116TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
3117 const UUID pi1_boot0 = UUID::Random();
3118 const UUID pi2_boot0 = UUID::Random();
3119 const UUID pi2_boot1 = UUID::Random();
3120 {
3121 CHECK_EQ(pi1_index_, 0u);
3122 CHECK_EQ(pi2_index_, 1u);
3123
3124 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
3125 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
3126 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
3127
3128 time_converter_.AddNextTimestamp(
3129 distributed_clock::epoch(),
3130 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3131 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
3132 time_converter_.AddNextTimestamp(
3133 distributed_clock::epoch() + reboot_time,
3134 {BootTimestamp::epoch() + reboot_time,
3135 BootTimestamp{
3136 .boot = 1,
3137 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
3138 }
3139 pi2_->Disconnect(pi1_->node());
3140
3141 std::vector<std::string> filenames;
3142 {
3143 LoggerState pi1_logger = MakeLogger(pi1_);
3144
3145 event_loop_factory_.RunFor(chrono::milliseconds(95));
3146 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3147 pi1_boot0);
3148 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3149 pi2_boot0);
3150
3151 StartLogger(&pi1_logger);
3152
3153 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3154
3155 VLOG(1) << "Reboot now!";
3156
3157 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3158 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3159 pi1_boot0);
3160 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3161 pi2_boot1);
3162 pi1_logger.AppendAllFilenames(&filenames);
3163 }
3164
Austin Schuhbfe6c572022-01-27 20:48:20 -08003165 std::sort(filenames.begin(), filenames.end());
3166
Austin Schuh5e14d842022-01-21 12:02:15 -08003167 // Confirm that our new oldest timestamps properly update as we reboot and
3168 // rotate.
3169 size_t timestamp_file_count = 0;
3170 for (const std::string &file : filenames) {
3171 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
3172 ReadHeader(file);
3173 CHECK(log_header);
3174
3175 if (log_header->message().has_configuration()) {
3176 continue;
3177 }
3178
3179 const monotonic_clock::time_point monotonic_start_time =
3180 monotonic_clock::time_point(
3181 chrono::nanoseconds(log_header->message().monotonic_start_time()));
3182 const UUID source_node_boot_uuid = UUID::FromString(
3183 log_header->message().source_node_boot_uuid()->string_view());
3184
3185 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
3186 ASSERT_EQ(
3187 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
3188 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
3189 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
3190 2u);
3191 ASSERT_TRUE(log_header->message()
3192 .has_oldest_remote_unreliable_monotonic_timestamps());
3193 ASSERT_EQ(log_header->message()
3194 .oldest_remote_unreliable_monotonic_timestamps()
3195 ->size(),
3196 2u);
3197 ASSERT_TRUE(log_header->message()
3198 .has_oldest_local_unreliable_monotonic_timestamps());
3199 ASSERT_EQ(log_header->message()
3200 .oldest_local_unreliable_monotonic_timestamps()
3201 ->size(),
3202 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003203 ASSERT_TRUE(log_header->message()
3204 .has_oldest_remote_reliable_monotonic_timestamps());
3205 ASSERT_EQ(log_header->message()
3206 .oldest_remote_reliable_monotonic_timestamps()
3207 ->size(),
3208 2u);
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003209 ASSERT_TRUE(
3210 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
Austin Schuhf5f99f32022-02-07 20:05:37 -08003211 ASSERT_EQ(log_header->message()
3212 .oldest_local_reliable_monotonic_timestamps()
3213 ->size(),
3214 2u);
3215
3216 ASSERT_TRUE(
3217 log_header->message()
3218 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
3219 ASSERT_EQ(log_header->message()
3220 .oldest_logger_remote_unreliable_monotonic_timestamps()
3221 ->size(),
3222 2u);
3223 ASSERT_TRUE(log_header->message()
3224 .has_oldest_logger_local_unreliable_monotonic_timestamps());
3225 ASSERT_EQ(log_header->message()
3226 .oldest_logger_local_unreliable_monotonic_timestamps()
3227 ->size(),
3228 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08003229
3230 if (log_header->message().node()->name()->string_view() != "pi1") {
3231 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
3232 std::string::npos);
3233
3234 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
3235 ReadNthMessage(file, 0);
3236 CHECK(msg);
3237
3238 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
3239 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
3240
3241 const monotonic_clock::time_point
3242 expected_oldest_local_monotonic_timestamps(
3243 chrono::nanoseconds(msg->message().monotonic_sent_time()));
3244 const monotonic_clock::time_point
3245 expected_oldest_remote_monotonic_timestamps(
3246 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003247 const monotonic_clock::time_point
3248 expected_oldest_timestamp_monotonic_timestamps(
3249 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08003250
3251 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
3252 monotonic_clock::min_time);
3253 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
3254 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003255 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
3256 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08003257
3258 ++timestamp_file_count;
3259 // Since the log file is from the perspective of the other node,
3260 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3261 monotonic_clock::time_point(chrono::nanoseconds(
3262 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3263 0)));
3264 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3265 monotonic_clock::time_point(chrono::nanoseconds(
3266 log_header->message().oldest_local_monotonic_timestamps()->Get(
3267 0)));
3268 const monotonic_clock::time_point
3269 oldest_remote_unreliable_monotonic_timestamps =
3270 monotonic_clock::time_point(chrono::nanoseconds(
3271 log_header->message()
3272 .oldest_remote_unreliable_monotonic_timestamps()
3273 ->Get(0)));
3274 const monotonic_clock::time_point
3275 oldest_local_unreliable_monotonic_timestamps =
3276 monotonic_clock::time_point(chrono::nanoseconds(
3277 log_header->message()
3278 .oldest_local_unreliable_monotonic_timestamps()
3279 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003280 const monotonic_clock::time_point
3281 oldest_remote_reliable_monotonic_timestamps =
3282 monotonic_clock::time_point(chrono::nanoseconds(
3283 log_header->message()
3284 .oldest_remote_reliable_monotonic_timestamps()
3285 ->Get(0)));
3286 const monotonic_clock::time_point
3287 oldest_local_reliable_monotonic_timestamps =
3288 monotonic_clock::time_point(chrono::nanoseconds(
3289 log_header->message()
3290 .oldest_local_reliable_monotonic_timestamps()
3291 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003292 const monotonic_clock::time_point
3293 oldest_logger_remote_unreliable_monotonic_timestamps =
3294 monotonic_clock::time_point(chrono::nanoseconds(
3295 log_header->message()
3296 .oldest_logger_remote_unreliable_monotonic_timestamps()
3297 ->Get(1)));
3298 const monotonic_clock::time_point
3299 oldest_logger_local_unreliable_monotonic_timestamps =
3300 monotonic_clock::time_point(chrono::nanoseconds(
3301 log_header->message()
3302 .oldest_logger_local_unreliable_monotonic_timestamps()
3303 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08003304
Austin Schuh01f3b392022-01-25 20:03:09 -08003305 const Channel *channel =
3306 event_loop_factory_.configuration()->channels()->Get(
3307 msg->message().channel_index());
3308 const Connection *connection = configuration::ConnectionToNode(
3309 channel, configuration::GetNode(
3310 event_loop_factory_.configuration(),
3311 log_header->message().node()->name()->string_view()));
3312
3313 const bool reliable = connection->time_to_live() == 0;
3314
Austin Schuhf5f99f32022-02-07 20:05:37 -08003315 SCOPED_TRACE(file);
3316 SCOPED_TRACE(aos::FlatbufferToJson(
3317 *log_header, {.multi_line = true, .max_vector_size = 100}));
3318
Austin Schuh01f3b392022-01-25 20:03:09 -08003319 if (shared()) {
3320 // Confirm that the oldest timestamps match what we expect. Based on
3321 // what we are doing, we know that the oldest time is the first
3322 // message's time.
3323 //
3324 // This makes the test robust to both the split and combined config
3325 // tests.
3326 switch (log_header->message().parts_index()) {
3327 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08003328 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3329 expected_oldest_remote_monotonic_timestamps);
3330 EXPECT_EQ(oldest_local_monotonic_timestamps,
3331 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003332 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003333 expected_oldest_local_monotonic_timestamps)
3334 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003335 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003336 expected_oldest_timestamp_monotonic_timestamps)
3337 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003338
Austin Schuh01f3b392022-01-25 20:03:09 -08003339 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003340 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3341 expected_oldest_remote_monotonic_timestamps);
3342 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3343 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08003344 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3345 monotonic_clock::max_time);
3346 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3347 monotonic_clock::max_time);
3348 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003349 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3350 monotonic_clock::max_time);
3351 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3352 monotonic_clock::max_time);
3353 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3354 expected_oldest_remote_monotonic_timestamps);
3355 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3356 expected_oldest_local_monotonic_timestamps);
3357 }
3358 break;
3359 case 1:
3360 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3361 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3362 EXPECT_EQ(oldest_local_monotonic_timestamps,
3363 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003364 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3365 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3366 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3367 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003368 if (reliable) {
3369 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3370 expected_oldest_remote_monotonic_timestamps);
3371 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3372 expected_oldest_local_monotonic_timestamps);
3373 EXPECT_EQ(
3374 oldest_remote_unreliable_monotonic_timestamps,
3375 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3376 EXPECT_EQ(
3377 oldest_local_unreliable_monotonic_timestamps,
3378 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3379 } else {
3380 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3381 monotonic_clock::max_time);
3382 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3383 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003384 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3385 expected_oldest_remote_monotonic_timestamps);
3386 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3387 expected_oldest_local_monotonic_timestamps);
3388 }
3389 break;
3390 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003391 EXPECT_EQ(
3392 oldest_remote_monotonic_timestamps,
3393 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3394 EXPECT_EQ(
3395 oldest_local_monotonic_timestamps,
3396 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003397 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003398 expected_oldest_local_monotonic_timestamps)
3399 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003400 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003401 expected_oldest_timestamp_monotonic_timestamps)
3402 << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003403 if (reliable) {
3404 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3405 expected_oldest_remote_monotonic_timestamps);
3406 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3407 expected_oldest_local_monotonic_timestamps);
3408 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3409 monotonic_clock::max_time);
3410 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3411 monotonic_clock::max_time);
3412 } else {
3413 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3414 monotonic_clock::max_time);
3415 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3416 monotonic_clock::max_time);
3417 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3418 expected_oldest_remote_monotonic_timestamps);
3419 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3420 expected_oldest_local_monotonic_timestamps);
3421 }
3422 break;
3423
3424 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003425 EXPECT_EQ(
3426 oldest_remote_monotonic_timestamps,
3427 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3428 EXPECT_EQ(
3429 oldest_local_monotonic_timestamps,
3430 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3431 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3432 expected_oldest_remote_monotonic_timestamps);
3433 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3434 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003435 EXPECT_EQ(
3436 oldest_logger_remote_unreliable_monotonic_timestamps,
3437 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3438 EXPECT_EQ(
3439 oldest_logger_local_unreliable_monotonic_timestamps,
3440 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003441 break;
3442 default:
3443 FAIL();
3444 break;
3445 }
3446
3447 switch (log_header->message().parts_index()) {
3448 case 0:
3449 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3450 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3451 break;
3452 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003453 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003454 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3455 break;
3456 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003457 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3458 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3459 break;
3460 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003461 if (shared()) {
3462 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3463 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003464 break;
3465 }
3466 [[fallthrough]];
3467 default:
3468 FAIL();
3469 break;
3470 }
3471 } else {
3472 switch (log_header->message().parts_index()) {
3473 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003474 if (reliable) {
3475 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3476 monotonic_clock::max_time);
3477 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3478 monotonic_clock::max_time);
3479 EXPECT_EQ(
3480 oldest_logger_remote_unreliable_monotonic_timestamps,
3481 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3482 << file;
3483 EXPECT_EQ(
3484 oldest_logger_local_unreliable_monotonic_timestamps,
3485 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3486 << file;
3487 } else {
3488 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3489 expected_oldest_remote_monotonic_timestamps);
3490 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3491 expected_oldest_local_monotonic_timestamps);
3492 EXPECT_EQ(
3493 oldest_logger_remote_unreliable_monotonic_timestamps,
3494 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3495 << file;
3496 EXPECT_EQ(
3497 oldest_logger_local_unreliable_monotonic_timestamps,
3498 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3499 << file;
3500 }
3501 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003502 case 1:
3503 if (reliable) {
3504 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3505 monotonic_clock::max_time);
3506 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3507 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003508 EXPECT_EQ(
3509 oldest_logger_remote_unreliable_monotonic_timestamps,
3510 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3511 EXPECT_EQ(
3512 oldest_logger_local_unreliable_monotonic_timestamps,
3513 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003514 } else {
3515 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3516 expected_oldest_remote_monotonic_timestamps);
3517 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3518 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003519 EXPECT_EQ(
3520 oldest_logger_remote_unreliable_monotonic_timestamps,
3521 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3522 EXPECT_EQ(
3523 oldest_logger_local_unreliable_monotonic_timestamps,
3524 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003525 }
3526 break;
3527 default:
3528 FAIL();
3529 break;
3530 }
3531
3532 switch (log_header->message().parts_index()) {
3533 case 0:
3534 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3535 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3536 break;
3537 case 1:
3538 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3539 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3540 break;
3541 default:
3542 FAIL();
3543 break;
3544 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003545 }
3546
3547 continue;
3548 }
3549 EXPECT_EQ(
3550 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3551 monotonic_clock::max_time.time_since_epoch().count());
3552 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3553 monotonic_clock::max_time.time_since_epoch().count());
3554 EXPECT_EQ(log_header->message()
3555 .oldest_remote_unreliable_monotonic_timestamps()
3556 ->Get(0),
3557 monotonic_clock::max_time.time_since_epoch().count());
3558 EXPECT_EQ(log_header->message()
3559 .oldest_local_unreliable_monotonic_timestamps()
3560 ->Get(0),
3561 monotonic_clock::max_time.time_since_epoch().count());
3562
3563 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3564 monotonic_clock::time_point(chrono::nanoseconds(
3565 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3566 1)));
3567 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3568 monotonic_clock::time_point(chrono::nanoseconds(
3569 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3570 const monotonic_clock::time_point
3571 oldest_remote_unreliable_monotonic_timestamps =
3572 monotonic_clock::time_point(chrono::nanoseconds(
3573 log_header->message()
3574 .oldest_remote_unreliable_monotonic_timestamps()
3575 ->Get(1)));
3576 const monotonic_clock::time_point
3577 oldest_local_unreliable_monotonic_timestamps =
3578 monotonic_clock::time_point(chrono::nanoseconds(
3579 log_header->message()
3580 .oldest_local_unreliable_monotonic_timestamps()
3581 ->Get(1)));
3582 switch (log_header->message().parts_index()) {
3583 case 0:
3584 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3585 monotonic_clock::max_time);
3586 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3587 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3588 monotonic_clock::max_time);
3589 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3590 monotonic_clock::max_time);
3591 break;
3592 default:
3593 FAIL();
3594 break;
3595 }
3596 }
3597
Austin Schuh01f3b392022-01-25 20:03:09 -08003598 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003599 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003600 } else {
3601 EXPECT_EQ(timestamp_file_count, 4u);
3602 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003603
Austin Schuhe2373e22022-01-21 12:25:17 -08003604 // Confirm that we can actually sort the resulting log and read it.
3605 {
3606 LogReader reader(SortParts(filenames));
3607
3608 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3609 log_reader_factory.set_send_delay(chrono::microseconds(0));
3610
3611 // This sends out the fetched messages and advances time to the start of
3612 // the log file.
3613 reader.Register(&log_reader_factory);
3614
3615 log_reader_factory.Run();
3616
3617 reader.Deregister();
3618 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003619}
3620
Austin Schuhc9049732020-12-21 22:27:15 -08003621// Tests that we properly handle one direction of message_bridge being
3622// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003623TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003624 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003625 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003626 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003627
3628 time_converter_.AddMonotonic(
3629 {chrono::milliseconds(10000),
3630 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003631 {
3632 LoggerState pi1_logger = MakeLogger(pi1_);
3633
3634 event_loop_factory_.RunFor(chrono::milliseconds(95));
3635
3636 StartLogger(&pi1_logger);
3637
3638 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3639 }
3640
3641 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3642 // to confirm the right thing happened.
3643 ConfirmReadable(pi1_single_direction_logfiles_);
3644}
3645
3646// Tests that we properly handle one direction of message_bridge being
3647// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003648TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003649 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003650 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003651 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003652
3653 time_converter_.AddMonotonic(
3654 {chrono::milliseconds(10000),
3655 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3656 {
3657 LoggerState pi1_logger = MakeLogger(pi1_);
3658
3659 event_loop_factory_.RunFor(chrono::milliseconds(95));
3660
3661 StartLogger(&pi1_logger);
3662
3663 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3664 }
3665
3666 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3667 // to confirm the right thing happened.
3668 ConfirmReadable(pi1_single_direction_logfiles_);
3669}
3670
Austin Schuhe9f00232021-09-16 18:04:23 -07003671// Tests that we explode if someone passes in a part file twice with a better
3672// error than an out of order error.
3673TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3674 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003675 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003676 {
3677 LoggerState pi1_logger = MakeLogger(pi1_);
3678
3679 event_loop_factory_.RunFor(chrono::milliseconds(95));
3680
3681 StartLogger(&pi1_logger);
3682
3683 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3684 }
3685
3686 std::vector<std::string> duplicates;
3687 for (const std::string &f : pi1_single_direction_logfiles_) {
3688 duplicates.emplace_back(f);
3689 duplicates.emplace_back(f);
3690 }
3691 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3692}
3693
Austin Schuh22cf7862022-09-19 19:09:42 -07003694// Tests that we explode if someone loses a part out of the middle of a log.
3695TEST_P(MultinodeLoggerTest, MissingPartsFromMiddle) {
3696 time_converter_.AddMonotonic(
3697 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3698 {
3699 LoggerState pi1_logger = MakeLogger(pi1_);
3700
3701 event_loop_factory_.RunFor(chrono::milliseconds(95));
3702
3703
3704 StartLogger(&pi1_logger);
3705 aos::monotonic_clock::time_point last_rotation_time =
3706 pi1_logger.event_loop->monotonic_now();
3707 pi1_logger.logger->set_on_logged_period([&] {
3708 const auto now = pi1_logger.event_loop->monotonic_now();
3709 if (now > last_rotation_time + std::chrono::seconds(5)) {
3710 pi1_logger.logger->Rotate();
3711 last_rotation_time = now;
3712 }
3713 });
3714
3715 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3716 }
3717
3718 std::vector<std::string> missing_parts;
3719
3720 missing_parts.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
3721 missing_parts.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
3722 missing_parts.emplace_back(absl::StrCat(
3723 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
3724
3725 EXPECT_DEATH({ SortParts(missing_parts); },
3726 "Broken log, missing part files between");
3727}
3728
Austin Schuh87dd3832021-01-01 23:07:31 -08003729// Tests that we properly handle a dead node. Do this by just disconnecting it
3730// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003731TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003732 pi1_->Disconnect(pi2_->node());
3733 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003734 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003735 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003736 {
3737 LoggerState pi1_logger = MakeLogger(pi1_);
3738
3739 event_loop_factory_.RunFor(chrono::milliseconds(95));
3740
3741 StartLogger(&pi1_logger);
3742
3743 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3744 }
3745
3746 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3747 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003748 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003749}
3750
Austin Schuhcdd90272021-03-15 12:46:16 -07003751constexpr std::string_view kCombinedConfigSha1(
Austin Schuh13ec0722022-09-26 18:12:16 -07003752 "c10ca3c1efa7924d48859000b6671eadc007b6373c81d07138a385dfdbb33d69");
Austin Schuhcdd90272021-03-15 12:46:16 -07003753constexpr std::string_view kSplitConfigSha1(
Austin Schuh13ec0722022-09-26 18:12:16 -07003754 "f8df4ee52e137025dac96303f8d38a5324fd819d1c22ff018754dd56c3ca64e8");
James Kuszmaul53da7f32022-09-11 11:11:55 -07003755constexpr std::string_view kReloggedSplitConfigSha1(
Austin Schuh13ec0722022-09-26 18:12:16 -07003756 "3154b2a9f9819d676d40c689a6c2967c2c64152c2845673b78d0c1cdc368d3ec");
Austin Schuhcdd90272021-03-15 12:46:16 -07003757
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003758INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003759 All, MultinodeLoggerTest,
James Kuszmaul53da7f32022-09-11 11:11:55 -07003760 ::testing::Combine(
3761 ::testing::Values(
3762 ConfigParams{"multinode_pingpong_combined_config.json", true,
3763 kCombinedConfigSha1, kCombinedConfigSha1},
3764 ConfigParams{"multinode_pingpong_split_config.json", false,
3765 kSplitConfigSha1, kReloggedSplitConfigSha1}),
3766 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003767
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003768INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003769 All, MultinodeLoggerDeathTest,
James Kuszmaul53da7f32022-09-11 11:11:55 -07003770 ::testing::Combine(
3771 ::testing::Values(
3772 ConfigParams{"multinode_pingpong_combined_config.json", true,
3773 kCombinedConfigSha1, kCombinedConfigSha1},
3774 ConfigParams{"multinode_pingpong_split_config.json", false,
3775 kSplitConfigSha1, kReloggedSplitConfigSha1}),
3776 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003777
Austin Schuh5b728b72021-06-16 14:57:15 -07003778// Tests that we can relog with a different config. This makes most sense when
3779// you are trying to edit a log and want to use channel renaming + the original
3780// config in the new log.
3781TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3782 time_converter_.StartEqual();
3783 {
3784 LoggerState pi1_logger = MakeLogger(pi1_);
3785 LoggerState pi2_logger = MakeLogger(pi2_);
3786
3787 event_loop_factory_.RunFor(chrono::milliseconds(95));
3788
3789 StartLogger(&pi1_logger);
3790 StartLogger(&pi2_logger);
3791
3792 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3793 }
3794
3795 LogReader reader(SortParts(logfiles_));
3796 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3797
3798 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3799 log_reader_factory.set_send_delay(chrono::microseconds(0));
3800
3801 // This sends out the fetched messages and advances time to the start of the
3802 // log file.
3803 reader.Register(&log_reader_factory);
3804
3805 const Node *pi1 =
3806 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3807 const Node *pi2 =
3808 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3809
3810 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3811 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3812 LOG(INFO) << "now pi1 "
3813 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3814 LOG(INFO) << "now pi2 "
3815 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3816
3817 EXPECT_THAT(reader.LoggedNodes(),
3818 ::testing::ElementsAre(
3819 configuration::GetNode(reader.logged_configuration(), pi1),
3820 configuration::GetNode(reader.logged_configuration(), pi2)));
3821
3822 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3823
3824 // And confirm we can re-create a log again, while checking the contents.
3825 std::vector<std::string> log_files;
3826 {
3827 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003828 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003829 &log_reader_factory, reader.logged_configuration());
3830 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003831 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003832 &log_reader_factory, reader.logged_configuration());
3833
Austin Schuh3e20c692021-11-16 20:43:16 -08003834 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3835 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003836
3837 log_reader_factory.Run();
3838
3839 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3840 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3841 }
3842 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3843 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3844 }
3845 }
3846
3847 reader.Deregister();
3848
3849 // And verify that we can run the LogReader over the relogged files without
3850 // hitting any fatal errors.
3851 {
3852 LogReader relogged_reader(SortParts(log_files));
3853 relogged_reader.Register();
3854
3855 relogged_reader.event_loop_factory()->Run();
3856 }
3857}
Austin Schuha04efed2021-01-24 18:04:20 -08003858
Austin Schuh3e20c692021-11-16 20:43:16 -08003859// Tests that we properly replay a log where the start time for a node is before
3860// any data on the node. This can happen if the logger starts before data is
3861// published. While the scenario below is a bit convoluted, we have seen logs
3862// like this generated out in the wild.
3863TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3864 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3865 aos::configuration::ReadConfig(ArtifactPath(
3866 "aos/events/logging/multinode_pingpong_split3_config.json"));
3867 message_bridge::TestingTimeConverter time_converter(
3868 configuration::NodesCount(&config.message()));
3869 SimulatedEventLoopFactory event_loop_factory(&config.message());
3870 event_loop_factory.SetTimeConverter(&time_converter);
3871 NodeEventLoopFactory *const pi1 =
3872 event_loop_factory.GetNodeEventLoopFactory("pi1");
3873 const size_t pi1_index = configuration::GetNodeIndex(
3874 event_loop_factory.configuration(), pi1->node());
3875 NodeEventLoopFactory *const pi2 =
3876 event_loop_factory.GetNodeEventLoopFactory("pi2");
3877 const size_t pi2_index = configuration::GetNodeIndex(
3878 event_loop_factory.configuration(), pi2->node());
3879 NodeEventLoopFactory *const pi3 =
3880 event_loop_factory.GetNodeEventLoopFactory("pi3");
3881 const size_t pi3_index = configuration::GetNodeIndex(
3882 event_loop_factory.configuration(), pi3->node());
3883
3884 const std::string kLogfile1_1 =
3885 aos::testing::TestTmpDir() + "/multi_logfile1/";
3886 const std::string kLogfile2_1 =
3887 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3888 const std::string kLogfile2_2 =
3889 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3890 const std::string kLogfile3_1 =
3891 aos::testing::TestTmpDir() + "/multi_logfile3/";
3892 util::UnlinkRecursive(kLogfile1_1);
3893 util::UnlinkRecursive(kLogfile2_1);
3894 util::UnlinkRecursive(kLogfile2_2);
3895 util::UnlinkRecursive(kLogfile3_1);
3896 const UUID pi1_boot0 = UUID::Random();
3897 const UUID pi2_boot0 = UUID::Random();
3898 const UUID pi2_boot1 = UUID::Random();
3899 const UUID pi3_boot0 = UUID::Random();
3900 {
3901 CHECK_EQ(pi1_index, 0u);
3902 CHECK_EQ(pi2_index, 1u);
3903 CHECK_EQ(pi3_index, 2u);
3904
3905 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3906 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3907 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3908 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3909
3910 time_converter.AddNextTimestamp(
3911 distributed_clock::epoch(),
3912 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3913 BootTimestamp::epoch()});
3914 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3915 time_converter.AddNextTimestamp(
3916 distributed_clock::epoch() + reboot_time,
3917 {BootTimestamp::epoch() + reboot_time,
3918 BootTimestamp{
3919 .boot = 1,
3920 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3921 BootTimestamp::epoch() + reboot_time});
3922 }
3923
3924 // Make everything perfectly quiet.
3925 event_loop_factory.SkipTimingReport();
3926 event_loop_factory.DisableStatistics();
3927
3928 std::vector<std::string> filenames;
3929 {
3930 LoggerState pi1_logger = LoggerState::MakeLogger(
3931 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3932 LoggerState pi3_logger = LoggerState::MakeLogger(
3933 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3934 {
3935 // And now start the logger.
3936 LoggerState pi2_logger = LoggerState::MakeLogger(
3937 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3938
3939 event_loop_factory.RunFor(chrono::milliseconds(1000));
3940
3941 pi1_logger.StartLogger(kLogfile1_1);
3942 pi3_logger.StartLogger(kLogfile3_1);
3943 pi2_logger.StartLogger(kLogfile2_1);
3944
3945 event_loop_factory.RunFor(chrono::milliseconds(10000));
3946
3947 // Now that we've got a start time in the past, turn on data.
3948 event_loop_factory.EnableStatistics();
3949 std::unique_ptr<aos::EventLoop> ping_event_loop =
3950 pi1->MakeEventLoop("ping");
3951 Ping ping(ping_event_loop.get());
3952
3953 pi2->AlwaysStart<Pong>("pong");
3954
3955 event_loop_factory.RunFor(chrono::milliseconds(3000));
3956
3957 pi2_logger.AppendAllFilenames(&filenames);
3958
3959 // Stop logging on pi2 before rebooting and completely shut off all
3960 // messages on pi2.
3961 pi2->DisableStatistics();
3962 pi1->Disconnect(pi2->node());
3963 pi2->Disconnect(pi1->node());
3964 }
3965 event_loop_factory.RunFor(chrono::milliseconds(7000));
3966 // pi2 now reboots.
3967 {
3968 event_loop_factory.RunFor(chrono::milliseconds(1000));
3969
3970 // Start logging again on pi2 after it is up.
3971 LoggerState pi2_logger = LoggerState::MakeLogger(
3972 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3973 pi2_logger.StartLogger(kLogfile2_2);
3974
3975 event_loop_factory.RunFor(chrono::milliseconds(10000));
3976 // And, now that we have a start time in the log, turn data back on.
3977 pi2->EnableStatistics();
3978 pi1->Connect(pi2->node());
3979 pi2->Connect(pi1->node());
3980
3981 pi2->AlwaysStart<Pong>("pong");
3982 std::unique_ptr<aos::EventLoop> ping_event_loop =
3983 pi1->MakeEventLoop("ping");
3984 Ping ping(ping_event_loop.get());
3985
3986 event_loop_factory.RunFor(chrono::milliseconds(3000));
3987
3988 pi2_logger.AppendAllFilenames(&filenames);
3989 }
3990
3991 pi1_logger.AppendAllFilenames(&filenames);
3992 pi3_logger.AppendAllFilenames(&filenames);
3993 }
3994
3995 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3996 // to confirm the right thing happened.
3997 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003998 auto result = ConfirmReadable(filenames);
3999 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
4000 chrono::seconds(1)));
4001 EXPECT_THAT(result[0].second,
4002 ::testing::ElementsAre(realtime_clock::epoch() +
4003 chrono::microseconds(34990350)));
4004
4005 EXPECT_THAT(result[1].first,
4006 ::testing::ElementsAre(
4007 realtime_clock::epoch() + chrono::seconds(1),
4008 realtime_clock::epoch() + chrono::microseconds(3323000)));
4009 EXPECT_THAT(result[1].second,
4010 ::testing::ElementsAre(
4011 realtime_clock::epoch() + chrono::microseconds(13990200),
4012 realtime_clock::epoch() + chrono::microseconds(16313200)));
4013
4014 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
4015 chrono::seconds(1)));
4016 EXPECT_THAT(result[2].second,
4017 ::testing::ElementsAre(realtime_clock::epoch() +
4018 chrono::microseconds(34900150)));
Austin Schuh3e20c692021-11-16 20:43:16 -08004019}
4020
Austin Schuh5dd22842021-11-17 16:09:39 -08004021// Tests that local data before remote data after reboot is properly replayed.
4022// We only trigger a reboot in the timestamp interpolation function when solving
4023// the timestamp problem when we actually have a point in the function. This
4024// originally only happened when a point passes the noncausal filter. At the
4025// start of time for the second boot, if we aren't careful, we will have
4026// messages which need to be published at times before the boot. This happens
4027// when a local message is in the log before a forwarded message, so there is no
4028// point in the interpolation function. This delays the reboot. So, we need to
4029// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08004030TEST(MultinodeRebootLoggerTest,
4031 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08004032 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4033 aos::configuration::ReadConfig(ArtifactPath(
4034 "aos/events/logging/multinode_pingpong_split3_config.json"));
4035 message_bridge::TestingTimeConverter time_converter(
4036 configuration::NodesCount(&config.message()));
4037 SimulatedEventLoopFactory event_loop_factory(&config.message());
4038 event_loop_factory.SetTimeConverter(&time_converter);
4039 NodeEventLoopFactory *const pi1 =
4040 event_loop_factory.GetNodeEventLoopFactory("pi1");
4041 const size_t pi1_index = configuration::GetNodeIndex(
4042 event_loop_factory.configuration(), pi1->node());
4043 NodeEventLoopFactory *const pi2 =
4044 event_loop_factory.GetNodeEventLoopFactory("pi2");
4045 const size_t pi2_index = configuration::GetNodeIndex(
4046 event_loop_factory.configuration(), pi2->node());
4047 NodeEventLoopFactory *const pi3 =
4048 event_loop_factory.GetNodeEventLoopFactory("pi3");
4049 const size_t pi3_index = configuration::GetNodeIndex(
4050 event_loop_factory.configuration(), pi3->node());
4051
4052 const std::string kLogfile1_1 =
4053 aos::testing::TestTmpDir() + "/multi_logfile1/";
4054 const std::string kLogfile2_1 =
4055 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4056 const std::string kLogfile2_2 =
4057 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4058 const std::string kLogfile3_1 =
4059 aos::testing::TestTmpDir() + "/multi_logfile3/";
4060 util::UnlinkRecursive(kLogfile1_1);
4061 util::UnlinkRecursive(kLogfile2_1);
4062 util::UnlinkRecursive(kLogfile2_2);
4063 util::UnlinkRecursive(kLogfile3_1);
4064 const UUID pi1_boot0 = UUID::Random();
4065 const UUID pi2_boot0 = UUID::Random();
4066 const UUID pi2_boot1 = UUID::Random();
4067 const UUID pi3_boot0 = UUID::Random();
4068 {
4069 CHECK_EQ(pi1_index, 0u);
4070 CHECK_EQ(pi2_index, 1u);
4071 CHECK_EQ(pi3_index, 2u);
4072
4073 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
4074 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
4075 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
4076 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
4077
4078 time_converter.AddNextTimestamp(
4079 distributed_clock::epoch(),
4080 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4081 BootTimestamp::epoch()});
4082 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4083 time_converter.AddNextTimestamp(
4084 distributed_clock::epoch() + reboot_time,
4085 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08004086 BootTimestamp{.boot = 1,
4087 .time = monotonic_clock::epoch() + reboot_time +
4088 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08004089 BootTimestamp::epoch() + reboot_time});
4090 }
4091
4092 std::vector<std::string> filenames;
4093 {
4094 LoggerState pi1_logger = LoggerState::MakeLogger(
4095 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4096 LoggerState pi3_logger = LoggerState::MakeLogger(
4097 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4098 {
4099 // And now start the logger.
4100 LoggerState pi2_logger = LoggerState::MakeLogger(
4101 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4102
4103 pi1_logger.StartLogger(kLogfile1_1);
4104 pi3_logger.StartLogger(kLogfile3_1);
4105 pi2_logger.StartLogger(kLogfile2_1);
4106
4107 event_loop_factory.RunFor(chrono::milliseconds(1005));
4108
4109 // Now that we've got a start time in the past, turn on data.
4110 std::unique_ptr<aos::EventLoop> ping_event_loop =
4111 pi1->MakeEventLoop("ping");
4112 Ping ping(ping_event_loop.get());
4113
4114 pi2->AlwaysStart<Pong>("pong");
4115
4116 event_loop_factory.RunFor(chrono::milliseconds(3000));
4117
4118 pi2_logger.AppendAllFilenames(&filenames);
4119
4120 // Disable any remote messages on pi2.
4121 pi1->Disconnect(pi2->node());
4122 pi2->Disconnect(pi1->node());
4123 }
4124 event_loop_factory.RunFor(chrono::milliseconds(995));
4125 // pi2 now reboots at 5 seconds.
4126 {
4127 event_loop_factory.RunFor(chrono::milliseconds(1000));
4128
4129 // Make local stuff happen before we start logging and connect the remote.
4130 pi2->AlwaysStart<Pong>("pong");
4131 std::unique_ptr<aos::EventLoop> ping_event_loop =
4132 pi1->MakeEventLoop("ping");
4133 Ping ping(ping_event_loop.get());
4134 event_loop_factory.RunFor(chrono::milliseconds(1005));
4135
4136 // Start logging again on pi2 after it is up.
4137 LoggerState pi2_logger = LoggerState::MakeLogger(
4138 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4139 pi2_logger.StartLogger(kLogfile2_2);
4140
4141 // And allow remote messages now that we have some local ones.
4142 pi1->Connect(pi2->node());
4143 pi2->Connect(pi1->node());
4144
4145 event_loop_factory.RunFor(chrono::milliseconds(1000));
4146
4147 event_loop_factory.RunFor(chrono::milliseconds(3000));
4148
4149 pi2_logger.AppendAllFilenames(&filenames);
4150 }
4151
4152 pi1_logger.AppendAllFilenames(&filenames);
4153 pi3_logger.AppendAllFilenames(&filenames);
4154 }
4155
4156 // Confirm that we can parse the result. LogReader has enough internal CHECKs
4157 // to confirm the right thing happened.
4158 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08004159 auto result = ConfirmReadable(filenames);
4160
4161 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4162 EXPECT_THAT(result[0].second,
4163 ::testing::ElementsAre(realtime_clock::epoch() +
4164 chrono::microseconds(11000350)));
4165
4166 EXPECT_THAT(result[1].first,
4167 ::testing::ElementsAre(
4168 realtime_clock::epoch(),
4169 realtime_clock::epoch() + chrono::microseconds(107005000)));
4170 EXPECT_THAT(result[1].second,
4171 ::testing::ElementsAre(
4172 realtime_clock::epoch() + chrono::microseconds(4000150),
4173 realtime_clock::epoch() + chrono::microseconds(111000200)));
4174
4175 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4176 EXPECT_THAT(result[2].second,
4177 ::testing::ElementsAre(realtime_clock::epoch() +
4178 chrono::microseconds(11000150)));
4179
4180 auto start_stop_result = ConfirmReadable(
4181 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4182 realtime_clock::epoch() + chrono::milliseconds(3000));
4183
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004184 EXPECT_THAT(
4185 start_stop_result[0].first,
4186 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4187 EXPECT_THAT(
4188 start_stop_result[0].second,
4189 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4190 EXPECT_THAT(
4191 start_stop_result[1].first,
4192 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4193 EXPECT_THAT(
4194 start_stop_result[1].second,
4195 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4196 EXPECT_THAT(
4197 start_stop_result[2].first,
4198 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4199 EXPECT_THAT(
4200 start_stop_result[2].second,
4201 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
Austin Schuh5dd22842021-11-17 16:09:39 -08004202}
4203
Austin Schuhe33c08d2022-02-03 18:15:21 -08004204// Tests that setting the start and stop flags across a reboot works as
4205// expected.
4206TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
4207 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4208 aos::configuration::ReadConfig(ArtifactPath(
4209 "aos/events/logging/multinode_pingpong_split3_config.json"));
4210 message_bridge::TestingTimeConverter time_converter(
4211 configuration::NodesCount(&config.message()));
4212 SimulatedEventLoopFactory event_loop_factory(&config.message());
4213 event_loop_factory.SetTimeConverter(&time_converter);
4214 NodeEventLoopFactory *const pi1 =
4215 event_loop_factory.GetNodeEventLoopFactory("pi1");
4216 const size_t pi1_index = configuration::GetNodeIndex(
4217 event_loop_factory.configuration(), pi1->node());
4218 NodeEventLoopFactory *const pi2 =
4219 event_loop_factory.GetNodeEventLoopFactory("pi2");
4220 const size_t pi2_index = configuration::GetNodeIndex(
4221 event_loop_factory.configuration(), pi2->node());
4222 NodeEventLoopFactory *const pi3 =
4223 event_loop_factory.GetNodeEventLoopFactory("pi3");
4224 const size_t pi3_index = configuration::GetNodeIndex(
4225 event_loop_factory.configuration(), pi3->node());
4226
4227 const std::string kLogfile1_1 =
4228 aos::testing::TestTmpDir() + "/multi_logfile1/";
4229 const std::string kLogfile2_1 =
4230 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4231 const std::string kLogfile2_2 =
4232 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4233 const std::string kLogfile3_1 =
4234 aos::testing::TestTmpDir() + "/multi_logfile3/";
4235 util::UnlinkRecursive(kLogfile1_1);
4236 util::UnlinkRecursive(kLogfile2_1);
4237 util::UnlinkRecursive(kLogfile2_2);
4238 util::UnlinkRecursive(kLogfile3_1);
4239 {
4240 CHECK_EQ(pi1_index, 0u);
4241 CHECK_EQ(pi2_index, 1u);
4242 CHECK_EQ(pi3_index, 2u);
4243
4244 time_converter.AddNextTimestamp(
4245 distributed_clock::epoch(),
4246 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4247 BootTimestamp::epoch()});
4248 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4249 time_converter.AddNextTimestamp(
4250 distributed_clock::epoch() + reboot_time,
4251 {BootTimestamp::epoch() + reboot_time,
4252 BootTimestamp{.boot = 1,
4253 .time = monotonic_clock::epoch() + reboot_time},
4254 BootTimestamp::epoch() + reboot_time});
4255 }
4256
4257 std::vector<std::string> filenames;
4258 {
4259 LoggerState pi1_logger = LoggerState::MakeLogger(
4260 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4261 LoggerState pi3_logger = LoggerState::MakeLogger(
4262 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4263 {
4264 // And now start the logger.
4265 LoggerState pi2_logger = LoggerState::MakeLogger(
4266 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4267
4268 pi1_logger.StartLogger(kLogfile1_1);
4269 pi3_logger.StartLogger(kLogfile3_1);
4270 pi2_logger.StartLogger(kLogfile2_1);
4271
4272 event_loop_factory.RunFor(chrono::milliseconds(1005));
4273
4274 // Now that we've got a start time in the past, turn on data.
4275 std::unique_ptr<aos::EventLoop> ping_event_loop =
4276 pi1->MakeEventLoop("ping");
4277 Ping ping(ping_event_loop.get());
4278
4279 pi2->AlwaysStart<Pong>("pong");
4280
4281 event_loop_factory.RunFor(chrono::milliseconds(3000));
4282
4283 pi2_logger.AppendAllFilenames(&filenames);
4284 }
4285 event_loop_factory.RunFor(chrono::milliseconds(995));
4286 // pi2 now reboots at 5 seconds.
4287 {
4288 event_loop_factory.RunFor(chrono::milliseconds(1000));
4289
4290 // Make local stuff happen before we start logging and connect the remote.
4291 pi2->AlwaysStart<Pong>("pong");
4292 std::unique_ptr<aos::EventLoop> ping_event_loop =
4293 pi1->MakeEventLoop("ping");
4294 Ping ping(ping_event_loop.get());
4295 event_loop_factory.RunFor(chrono::milliseconds(5));
4296
4297 // Start logging again on pi2 after it is up.
4298 LoggerState pi2_logger = LoggerState::MakeLogger(
4299 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4300 pi2_logger.StartLogger(kLogfile2_2);
4301
4302 event_loop_factory.RunFor(chrono::milliseconds(5000));
4303
4304 pi2_logger.AppendAllFilenames(&filenames);
4305 }
4306
4307 pi1_logger.AppendAllFilenames(&filenames);
4308 pi3_logger.AppendAllFilenames(&filenames);
4309 }
4310
4311 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4312 auto result = ConfirmReadable(filenames);
4313
4314 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4315 EXPECT_THAT(result[0].second,
4316 ::testing::ElementsAre(realtime_clock::epoch() +
4317 chrono::microseconds(11000350)));
4318
4319 EXPECT_THAT(result[1].first,
4320 ::testing::ElementsAre(
4321 realtime_clock::epoch(),
4322 realtime_clock::epoch() + chrono::microseconds(6005000)));
4323 EXPECT_THAT(result[1].second,
4324 ::testing::ElementsAre(
4325 realtime_clock::epoch() + chrono::microseconds(4900150),
4326 realtime_clock::epoch() + chrono::microseconds(11000200)));
4327
4328 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4329 EXPECT_THAT(result[2].second,
4330 ::testing::ElementsAre(realtime_clock::epoch() +
4331 chrono::microseconds(11000150)));
4332
4333 // Confirm we observed the correct start and stop times. We should see the
4334 // reboot here.
4335 auto start_stop_result = ConfirmReadable(
4336 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4337 realtime_clock::epoch() + chrono::milliseconds(8000));
4338
4339 EXPECT_THAT(
4340 start_stop_result[0].first,
4341 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4342 EXPECT_THAT(
4343 start_stop_result[0].second,
4344 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4345 EXPECT_THAT(start_stop_result[1].first,
4346 ::testing::ElementsAre(
4347 realtime_clock::epoch() + chrono::seconds(2),
4348 realtime_clock::epoch() + chrono::microseconds(6005000)));
4349 EXPECT_THAT(start_stop_result[1].second,
4350 ::testing::ElementsAre(
4351 realtime_clock::epoch() + chrono::microseconds(4900150),
4352 realtime_clock::epoch() + chrono::seconds(8)));
4353 EXPECT_THAT(
4354 start_stop_result[2].first,
4355 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4356 EXPECT_THAT(
4357 start_stop_result[2].second,
4358 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4359}
Austin Schuh5dd22842021-11-17 16:09:39 -08004360
Austin Schuh5c770fa2022-03-11 06:57:22 -08004361// Tests that we properly handle one direction being down.
4362TEST(MissingDirectionTest, OneDirection) {
4363 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4364 aos::configuration::ReadConfig(ArtifactPath(
4365 "aos/events/logging/multinode_pingpong_split4_config.json"));
4366 message_bridge::TestingTimeConverter time_converter(
4367 configuration::NodesCount(&config.message()));
4368 SimulatedEventLoopFactory event_loop_factory(&config.message());
4369 event_loop_factory.SetTimeConverter(&time_converter);
4370
4371 NodeEventLoopFactory *const pi1 =
4372 event_loop_factory.GetNodeEventLoopFactory("pi1");
4373 const size_t pi1_index = configuration::GetNodeIndex(
4374 event_loop_factory.configuration(), pi1->node());
4375 NodeEventLoopFactory *const pi2 =
4376 event_loop_factory.GetNodeEventLoopFactory("pi2");
4377 const size_t pi2_index = configuration::GetNodeIndex(
4378 event_loop_factory.configuration(), pi2->node());
4379 std::vector<std::string> filenames;
4380
4381 {
4382 CHECK_EQ(pi1_index, 0u);
4383 CHECK_EQ(pi2_index, 1u);
4384
4385 time_converter.AddNextTimestamp(
4386 distributed_clock::epoch(),
4387 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4388
4389 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4390 time_converter.AddNextTimestamp(
4391 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004392 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuh5c770fa2022-03-11 06:57:22 -08004393 BootTimestamp::epoch() + reboot_time});
4394 }
4395
4396 const std::string kLogfile2_1 =
4397 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4398 const std::string kLogfile1_1 =
4399 aos::testing::TestTmpDir() + "/multi_logfile1.1/";
4400 util::UnlinkRecursive(kLogfile2_1);
4401 util::UnlinkRecursive(kLogfile1_1);
4402
4403 pi2->Disconnect(pi1->node());
4404
4405 pi1->AlwaysStart<Ping>("ping");
4406 pi2->AlwaysStart<Pong>("pong");
4407
4408 {
4409 LoggerState pi2_logger = LoggerState::MakeLogger(
4410 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4411
4412 event_loop_factory.RunFor(chrono::milliseconds(95));
4413
4414 pi2_logger.StartLogger(kLogfile2_1);
4415
4416 event_loop_factory.RunFor(chrono::milliseconds(6000));
4417
4418 pi2->Connect(pi1->node());
4419
4420 LoggerState pi1_logger = LoggerState::MakeLogger(
4421 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4422 pi1_logger.StartLogger(kLogfile1_1);
4423
4424 event_loop_factory.RunFor(chrono::milliseconds(5000));
4425 pi1_logger.AppendAllFilenames(&filenames);
4426 pi2_logger.AppendAllFilenames(&filenames);
4427 }
4428
4429 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4430 ConfirmReadable(filenames);
4431}
4432
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004433// Tests that we properly handle only one direction ever existing after a
4434// reboot.
4435TEST(MissingDirectionTest, OneDirectionAfterReboot) {
4436 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4437 aos::configuration::ReadConfig(ArtifactPath(
4438 "aos/events/logging/multinode_pingpong_split4_config.json"));
4439 message_bridge::TestingTimeConverter time_converter(
4440 configuration::NodesCount(&config.message()));
4441 SimulatedEventLoopFactory event_loop_factory(&config.message());
4442 event_loop_factory.SetTimeConverter(&time_converter);
4443
4444 NodeEventLoopFactory *const pi1 =
4445 event_loop_factory.GetNodeEventLoopFactory("pi1");
4446 const size_t pi1_index = configuration::GetNodeIndex(
4447 event_loop_factory.configuration(), pi1->node());
4448 NodeEventLoopFactory *const pi2 =
4449 event_loop_factory.GetNodeEventLoopFactory("pi2");
4450 const size_t pi2_index = configuration::GetNodeIndex(
4451 event_loop_factory.configuration(), pi2->node());
4452 std::vector<std::string> filenames;
4453
4454 {
4455 CHECK_EQ(pi1_index, 0u);
4456 CHECK_EQ(pi2_index, 1u);
4457
4458 time_converter.AddNextTimestamp(
4459 distributed_clock::epoch(),
4460 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4461
4462 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4463 time_converter.AddNextTimestamp(
4464 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004465 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004466 BootTimestamp::epoch() + reboot_time});
4467 }
4468
4469 const std::string kLogfile2_1 =
4470 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4471 util::UnlinkRecursive(kLogfile2_1);
4472
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004473 pi1->AlwaysStart<Ping>("ping");
4474
4475 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4476 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4477 // second boot.
4478 {
4479 LoggerState pi2_logger = LoggerState::MakeLogger(
4480 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4481
4482 event_loop_factory.RunFor(chrono::milliseconds(95));
4483
4484 pi2_logger.StartLogger(kLogfile2_1);
4485
4486 event_loop_factory.RunFor(chrono::milliseconds(4000));
4487
4488 pi2->Disconnect(pi1->node());
4489
4490 event_loop_factory.RunFor(chrono::milliseconds(1000));
4491 pi1->AlwaysStart<Ping>("ping");
4492
4493 event_loop_factory.RunFor(chrono::milliseconds(5000));
4494 pi2_logger.AppendAllFilenames(&filenames);
4495 }
4496
4497 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4498 ConfirmReadable(filenames);
4499}
4500
4501// Tests that we properly handle only one direction ever existing after a reboot
4502// with only reliable data.
4503TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
4504 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4505 aos::configuration::ReadConfig(ArtifactPath(
4506 "aos/events/logging/multinode_pingpong_split4_reliable_config.json"));
4507 message_bridge::TestingTimeConverter time_converter(
4508 configuration::NodesCount(&config.message()));
4509 SimulatedEventLoopFactory event_loop_factory(&config.message());
4510 event_loop_factory.SetTimeConverter(&time_converter);
4511
4512 NodeEventLoopFactory *const pi1 =
4513 event_loop_factory.GetNodeEventLoopFactory("pi1");
4514 const size_t pi1_index = configuration::GetNodeIndex(
4515 event_loop_factory.configuration(), pi1->node());
4516 NodeEventLoopFactory *const pi2 =
4517 event_loop_factory.GetNodeEventLoopFactory("pi2");
4518 const size_t pi2_index = configuration::GetNodeIndex(
4519 event_loop_factory.configuration(), pi2->node());
4520 std::vector<std::string> filenames;
4521
4522 {
4523 CHECK_EQ(pi1_index, 0u);
4524 CHECK_EQ(pi2_index, 1u);
4525
4526 time_converter.AddNextTimestamp(
4527 distributed_clock::epoch(),
4528 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4529
4530 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4531 time_converter.AddNextTimestamp(
4532 distributed_clock::epoch() + reboot_time,
4533 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4534 BootTimestamp::epoch() + reboot_time});
4535 }
4536
4537 const std::string kLogfile2_1 =
4538 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4539 util::UnlinkRecursive(kLogfile2_1);
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004540
4541 pi1->AlwaysStart<Ping>("ping");
4542
4543 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4544 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4545 // second boot.
4546 {
4547 LoggerState pi2_logger = LoggerState::MakeLogger(
4548 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4549
4550 event_loop_factory.RunFor(chrono::milliseconds(95));
4551
4552 pi2_logger.StartLogger(kLogfile2_1);
4553
4554 event_loop_factory.RunFor(chrono::milliseconds(4000));
4555
4556 pi2->Disconnect(pi1->node());
4557
4558 event_loop_factory.RunFor(chrono::milliseconds(1000));
4559 pi1->AlwaysStart<Ping>("ping");
4560
4561 event_loop_factory.RunFor(chrono::milliseconds(5000));
4562 pi2_logger.AppendAllFilenames(&filenames);
4563 }
4564
4565 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4566 ConfirmReadable(filenames);
4567}
4568
Austin Schuhefba96d2022-06-24 13:22:18 -07004569// Tests that we properly handle what used to be a time violation in one
4570// direction. This can occur when one direction goes down after sending some
4571// data, but the other keeps working. The down direction ends up resolving to a
4572// straight line in the noncausal filter, where the direction which is still up
4573// can cross that line. Really, time progressed along just fine but we assumed
4574// that the offset was a line when it could have deviated by up to 1ms/second.
4575TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4576 std::vector<std::string> filenames;
4577
4578 CHECK_EQ(pi1_index_, 0u);
4579 CHECK_EQ(pi2_index_, 1u);
4580
4581 time_converter_.AddNextTimestamp(
4582 distributed_clock::epoch(),
4583 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4584
4585 const chrono::nanoseconds before_disconnect_duration =
4586 time_converter_.AddMonotonic(
4587 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4588
4589 const chrono::nanoseconds test_duration =
4590 time_converter_.AddMonotonic(
4591 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4592 time_converter_.AddMonotonic(
4593 {chrono::milliseconds(10000),
4594 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4595 time_converter_.AddMonotonic(
4596 {chrono::milliseconds(10000),
4597 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4598
4599 const std::string kLogfile =
4600 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4601 util::UnlinkRecursive(kLogfile);
4602
4603 {
4604 LoggerState pi2_logger = MakeLogger(pi2_);
4605 pi2_logger.StartLogger(kLogfile);
4606 event_loop_factory_.RunFor(before_disconnect_duration);
4607
4608 pi2_->Disconnect(pi1_->node());
4609
4610 event_loop_factory_.RunFor(test_duration);
4611 pi2_->Connect(pi1_->node());
4612
4613 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4614 pi2_logger.AppendAllFilenames(&filenames);
4615 }
4616
4617 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4618 ConfirmReadable(filenames);
4619}
4620
James Kuszmaul86e86c32022-07-21 17:39:47 -07004621// Tests that we can replay a logfile that has timestamps such that at least one
4622// node's epoch is at a positive distributed_clock (and thus will have to be
4623// booted after the other node(s)).
4624TEST_P(MultinodeLoggerTest, StartOneNodeBeforeOther) {
4625 std::vector<std::string> filenames;
4626
4627 CHECK_EQ(pi1_index_, 0u);
4628 CHECK_EQ(pi2_index_, 1u);
4629
4630 time_converter_.AddNextTimestamp(
4631 distributed_clock::epoch(),
4632 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4633
4634 const chrono::nanoseconds before_reboot_duration = chrono::milliseconds(1000);
4635 time_converter_.RebootAt(
4636 0, distributed_clock::time_point(before_reboot_duration));
4637
4638 const chrono::nanoseconds test_duration = time_converter_.AddMonotonic(
4639 {chrono::milliseconds(10000), chrono::milliseconds(10000)});
4640
4641 const std::string kLogfile =
4642 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4643 util::UnlinkRecursive(kLogfile);
4644
4645 pi2_->Disconnect(pi1_->node());
4646 pi1_->Disconnect(pi2_->node());
4647
4648 {
4649 LoggerState pi2_logger = MakeLogger(pi2_);
4650
4651 pi2_logger.StartLogger(kLogfile);
4652 event_loop_factory_.RunFor(before_reboot_duration);
4653
4654 pi2_->Connect(pi1_->node());
4655 pi1_->Connect(pi2_->node());
4656
4657 event_loop_factory_.RunFor(test_duration);
4658
4659 pi2_logger.AppendAllFilenames(&filenames);
4660 }
4661
4662 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4663 ConfirmReadable(filenames);
4664
4665 {
4666 LogReader reader(sorted_parts);
4667 SimulatedEventLoopFactory replay_factory(reader.configuration());
4668 reader.RegisterWithoutStarting(&replay_factory);
4669
4670 NodeEventLoopFactory *const replay_node =
4671 reader.event_loop_factory()->GetNodeEventLoopFactory("pi1");
4672
4673 std::unique_ptr<EventLoop> test_event_loop =
4674 replay_node->MakeEventLoop("test_reader");
4675 replay_node->OnStartup([replay_node]() {
4676 // Check that we didn't boot until at least t=0.
4677 CHECK_LE(monotonic_clock::epoch(), replay_node->monotonic_now());
4678 });
4679 test_event_loop->OnRun([&test_event_loop]() {
4680 // Check that we didn't boot until at least t=0.
4681 EXPECT_LE(monotonic_clock::epoch(), test_event_loop->monotonic_now());
4682 });
4683 reader.event_loop_factory()->Run();
4684 reader.Deregister();
4685 }
4686}
4687
Austin Schuh79b21d62022-08-16 13:54:49 -07004688// Tests that when we have a loop without all the logs at all points in time, we
4689// can sort it properly.
Austin Schuheb595a62022-08-26 19:24:32 -07004690TEST(MultinodeLoggerLoopTest, Loop) {
Austin Schuh79b21d62022-08-16 13:54:49 -07004691 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4692 aos::configuration::ReadConfig(ArtifactPath(
4693 "aos/events/logging/multinode_pingpong_triangle_split_config.json"));
4694 message_bridge::TestingTimeConverter time_converter(
4695 configuration::NodesCount(&config.message()));
4696 SimulatedEventLoopFactory event_loop_factory(&config.message());
4697 event_loop_factory.SetTimeConverter(&time_converter);
4698
4699 NodeEventLoopFactory *const pi1 =
4700 event_loop_factory.GetNodeEventLoopFactory("pi1");
4701 NodeEventLoopFactory *const pi2 =
4702 event_loop_factory.GetNodeEventLoopFactory("pi2");
4703 NodeEventLoopFactory *const pi3 =
4704 event_loop_factory.GetNodeEventLoopFactory("pi3");
4705
4706 const std::string kLogfile1_1 =
4707 aos::testing::TestTmpDir() + "/multi_logfile1/";
4708 const std::string kLogfile2_1 =
4709 aos::testing::TestTmpDir() + "/multi_logfile2/";
4710 const std::string kLogfile3_1 =
4711 aos::testing::TestTmpDir() + "/multi_logfile3/";
4712 util::UnlinkRecursive(kLogfile1_1);
4713 util::UnlinkRecursive(kLogfile2_1);
4714 util::UnlinkRecursive(kLogfile3_1);
4715
4716 {
4717 // Make pi1 boot before everything else.
4718 time_converter.AddNextTimestamp(
4719 distributed_clock::epoch(),
4720 {BootTimestamp::epoch(),
4721 BootTimestamp::epoch() - chrono::milliseconds(100),
4722 BootTimestamp::epoch() - chrono::milliseconds(300)});
4723 }
4724
4725 // We want to setup a situation such that 2 of the 3 legs of the loop are very
4726 // confident about time being X, and the third leg is pulling the average off
4727 // to one side.
4728 //
4729 // It's easiest to visualize this in timestamp_plotter.
4730
4731 std::vector<std::string> filenames;
4732 {
4733 // Have pi1 send out a reliable message at startup. This sets up a long
4734 // forwarding time message at the start to bias time.
4735 std::unique_ptr<EventLoop> pi1_event_loop = pi1->MakeEventLoop("ping");
4736 {
4737 aos::Sender<examples::Ping> ping_sender =
4738 pi1_event_loop->MakeSender<examples::Ping>("/reliable");
4739
4740 aos::Sender<examples::Ping>::Builder builder = ping_sender.MakeBuilder();
4741 examples::Ping::Builder ping_builder =
4742 builder.MakeBuilder<examples::Ping>();
4743 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
4744 }
4745
4746 // Wait a while so there's enough data to let the worst case be rather off.
4747 event_loop_factory.RunFor(chrono::seconds(1000));
4748
4749 // Now start a receiving node first. This sets up 2 tight bounds between 2
4750 // of the nodes.
4751 LoggerState pi2_logger = LoggerState::MakeLogger(
4752 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4753 pi2_logger.StartLogger(kLogfile2_1);
4754
4755 event_loop_factory.RunFor(chrono::seconds(100));
4756
4757 // And now start the third leg.
4758 LoggerState pi3_logger = LoggerState::MakeLogger(
4759 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4760 pi3_logger.StartLogger(kLogfile3_1);
4761
4762 LoggerState pi1_logger = LoggerState::MakeLogger(
4763 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4764 pi1_logger.StartLogger(kLogfile1_1);
4765
4766 event_loop_factory.RunFor(chrono::seconds(100));
4767
4768 pi1_logger.AppendAllFilenames(&filenames);
4769 pi2_logger.AppendAllFilenames(&filenames);
4770 pi3_logger.AppendAllFilenames(&filenames);
4771 }
4772
4773 // Make sure we can read this.
4774 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4775 auto result = ConfirmReadable(filenames);
4776}
4777
Austin Schuhe309d2a2019-11-29 13:25:21 -08004778} // namespace testing
4779} // namespace logger
4780} // namespace aos