blob: cdf080b2f273ede7ddb14d7cef8f305724a262ee [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;
Austin Schuh48d10d62022-10-16 22:19:23 -0700543 std::function<std::unique_ptr<DataEncoder>(size_t max_message_size)>
544 encoder_factory;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700545};
546
547std::ostream &operator<<(std::ostream &ostream,
548 const CompressionParams &params) {
549 ostream << "\"" << params.extension << "\"";
550 return ostream;
551}
552
553std::vector<CompressionParams> SupportedCompressionAlgorithms() {
Austin Schuh48d10d62022-10-16 22:19:23 -0700554 return {{"",
555 [](size_t max_message_size) {
556 return std::make_unique<DummyEncoder>(max_message_size);
557 }},
James Kuszmauldd0a5042021-10-28 23:38:04 -0700558 {SnappyDecoder::kExtension,
Austin Schuh48d10d62022-10-16 22:19:23 -0700559 [](size_t max_message_size) {
Austin Schuh8bdfc492023-02-11 12:53:13 -0800560 return std::make_unique<SnappyEncoder>(max_message_size, 32768);
Austin Schuh48d10d62022-10-16 22:19:23 -0700561 }},
James Kuszmauldd0a5042021-10-28 23:38:04 -0700562#ifdef LZMA
563 {LzmaDecoder::kExtension,
Austin Schuh48d10d62022-10-16 22:19:23 -0700564 [](size_t max_message_size) {
565 return std::make_unique<LzmaEncoder>(max_message_size, 3);
566 }}
James Kuszmauldd0a5042021-10-28 23:38:04 -0700567#endif // LZMA
568 };
569}
570
Austin Schuh61e973f2021-02-21 21:43:56 -0800571// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700572struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800573 // The config file to use.
574 std::string config;
575 // If true, the RemoteMessage channel should be shared between all the remote
576 // channels. If false, there will be 1 RemoteMessage channel per remote
577 // channel.
578 bool shared;
579 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700580 std::string_view sha256;
James Kuszmaul53da7f32022-09-11 11:11:55 -0700581 // sha256 of the relogged config
582 std::string_view relogged_sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800583};
Austin Schuh315b96b2020-12-11 21:21:12 -0800584
James Kuszmauldd0a5042021-10-28 23:38:04 -0700585std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
586 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
James Kuszmaul53da7f32022-09-11 11:11:55 -0700587 << ", sha256: \"" << params.sha256 << "\", relogged_sha256: \""
588 << params.relogged_sha256 << "\"}";
James Kuszmauldd0a5042021-10-28 23:38:04 -0700589 return ostream;
590}
591
Austin Schuh3e20c692021-11-16 20:43:16 -0800592struct LoggerState {
593 static LoggerState MakeLogger(NodeEventLoopFactory *node,
594 SimulatedEventLoopFactory *factory,
595 CompressionParams params,
596 const Configuration *configuration = nullptr) {
597 if (configuration == nullptr) {
598 configuration = factory->configuration();
599 }
600 return {node->MakeEventLoop("logger"),
601 {},
602 configuration,
603 configuration::GetNode(configuration, node->node()),
604 nullptr,
605 params};
606 }
607
608 void StartLogger(std::string logfile_base) {
609 CHECK(!logfile_base.empty());
610
611 logger = std::make_unique<Logger>(event_loop.get(), configuration);
612 logger->set_polling_period(std::chrono::milliseconds(100));
613 logger->set_name(
614 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
Austin Schuhfa712682022-05-11 16:43:42 -0700615 logger->set_logger_sha1(
616 absl::StrCat("logger_sha1_", event_loop->node()->name()->str()));
617 logger->set_logger_version(
618 absl::StrCat("logger_version_", event_loop->node()->name()->str()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800619 event_loop->OnRun([this, logfile_base]() {
620 std::unique_ptr<MultiNodeLogNamer> namer =
621 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
622 event_loop.get(), node);
623 namer->set_extension(params.extension);
624 namer->set_encoder_factory(params.encoder_factory);
625 log_namer = namer.get();
626
627 logger->StartLogging(std::move(namer));
628 });
629 }
630
631 std::unique_ptr<EventLoop> event_loop;
632 std::unique_ptr<Logger> logger;
633 const Configuration *configuration;
634 const Node *node;
635 MultiNodeLogNamer *log_namer;
636 CompressionParams params;
637
638 void AppendAllFilenames(std::vector<std::string> *filenames) {
639 for (const std::string &file : log_namer->all_filenames()) {
640 const std::string_view separator =
641 log_namer->base_name().back() == '/' ? "" : "_";
642 filenames->emplace_back(
643 absl::StrCat(log_namer->base_name(), separator, file));
644 }
645 }
646
647 ~LoggerState() {
648 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800649 std::vector<std::string> filenames;
650 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800651 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800652 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800653 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800654 auto x = ReadHeader(file);
655 if (x) {
656 VLOG(1) << aos::FlatbufferToJson(x.value());
657 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800658 }
659 }
660 }
661};
662
Austin Schuhe33c08d2022-02-03 18:15:21 -0800663std::vector<std::pair<std::vector<realtime_clock::time_point>,
664 std::vector<realtime_clock::time_point>>>
665ConfirmReadable(
666 const std::vector<std::string> &files,
667 realtime_clock::time_point start_time = realtime_clock::min_time,
668 realtime_clock::time_point end_time = realtime_clock::max_time) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800669 {
670 LogReader reader(SortParts(files));
671
672 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
673 reader.Register(&log_reader_factory);
674
675 log_reader_factory.Run();
676
677 reader.Deregister();
678 }
679 {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800680 std::vector<std::pair<std::vector<realtime_clock::time_point>,
681 std::vector<realtime_clock::time_point>>>
682 result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800683 LogReader reader(SortParts(files));
684
Austin Schuhe33c08d2022-02-03 18:15:21 -0800685 reader.SetStartTime(start_time);
686 reader.SetEndTime(end_time);
687
Austin Schuh3e20c692021-11-16 20:43:16 -0800688 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
689 reader.RegisterWithoutStarting(&log_reader_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -0800690 result.resize(
691 configuration::NodesCount(log_reader_factory.configuration()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800692 if (configuration::MultiNode(log_reader_factory.configuration())) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800693 size_t i = 0;
Austin Schuh3e20c692021-11-16 20:43:16 -0800694 for (const aos::Node *node :
695 *log_reader_factory.configuration()->nodes()) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800696 LOG(INFO) << "Registering start";
697 reader.OnStart(node, [node, &log_reader_factory, &result,
698 node_index = i]() {
Austin Schuh3e20c692021-11-16 20:43:16 -0800699 LOG(INFO) << "Starting " << node->name()->string_view();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800700 result[node_index].first.push_back(
701 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
Austin Schuh3e20c692021-11-16 20:43:16 -0800702 });
Austin Schuhe33c08d2022-02-03 18:15:21 -0800703 reader.OnEnd(node, [node, &log_reader_factory, &result,
704 node_index = i]() {
705 LOG(INFO) << "Ending " << node->name()->string_view();
706 result[node_index].second.push_back(
707 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
708 });
709 ++i;
Austin Schuh3e20c692021-11-16 20:43:16 -0800710 }
Austin Schuhe33c08d2022-02-03 18:15:21 -0800711 } else {
712 reader.OnStart([&log_reader_factory, &result]() {
713 LOG(INFO) << "Starting";
714 result[0].first.push_back(
715 log_reader_factory.GetNodeEventLoopFactory(nullptr)
716 ->realtime_now());
717 });
718 reader.OnEnd([&log_reader_factory, &result]() {
719 LOG(INFO) << "Ending";
720 result[0].second.push_back(
721 log_reader_factory.GetNodeEventLoopFactory(nullptr)
722 ->realtime_now());
723 });
Austin Schuh3e20c692021-11-16 20:43:16 -0800724 }
725
726 log_reader_factory.Run();
727
728 reader.Deregister();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800729
730 for (auto x : result) {
731 for (auto y : x.first) {
732 VLOG(1) << "Start " << y;
733 }
734 for (auto y : x.second) {
735 VLOG(1) << "End " << y;
736 }
737 }
738 return result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800739 }
740}
741
James Kuszmauldd0a5042021-10-28 23:38:04 -0700742class MultinodeLoggerTest : public ::testing::TestWithParam<
743 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800744 public:
745 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700746 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
747 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800748 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800749 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700750 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800751 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700752 event_loop_factory_.configuration(), pi1_->node())),
753 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800754 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700755 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800756 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800757 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
758 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800759 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800760 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800761 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700762 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700763 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800764 event_loop_factory_.SetTimeConverter(&time_converter_);
765
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700766 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700767 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700768 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800769 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700770 }
771
James Kuszmaul53da7f32022-09-11 11:11:55 -0700772 for (const auto &file : MakeLogFiles(tmp_dir_ + "/relogged1",
773 tmp_dir_ + "/relogged2", 3, 3, true)) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800774 unlink(file.c_str());
775 }
776
Austin Schuh268586b2021-03-31 22:24:39 -0700777 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800778 unlink(file.c_str());
779 }
780
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700781 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
782 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700783
784 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
785 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700786 }
787
James Kuszmauldd0a5042021-10-28 23:38:04 -0700788 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800789
790 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700791 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800792 size_t pi1_data_count = 3,
James Kuszmaul53da7f32022-09-11 11:11:55 -0700793 size_t pi2_data_count = 3,
794 bool relogged_config = false) {
795 std::string_view sha256 = relogged_config
796 ? std::get<0>(GetParam()).relogged_sha256
797 : std::get<0>(GetParam()).sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800798 std::vector<std::string> result;
James Kuszmaul53da7f32022-09-11 11:11:55 -0700799 result.emplace_back(absl::StrCat(logfile_base1, "_", sha256, Extension()));
800 result.emplace_back(absl::StrCat(logfile_base2, "_", sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700801 for (size_t i = 0; i < pi1_data_count; ++i) {
802 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700803 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700804 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800805 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700806 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800807 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700808 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700809 for (size_t i = 0; i < pi2_data_count; ++i) {
810 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700811 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700812 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700813 result.emplace_back(logfile_base2 +
814 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
815 Extension());
816 result.emplace_back(logfile_base2 +
817 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
818 Extension());
819 result.emplace_back(logfile_base1 +
820 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
821 Extension());
822 result.emplace_back(logfile_base1 +
823 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
824 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800825 if (shared()) {
826 result.emplace_back(logfile_base1 +
827 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700828 "aos.message_bridge.RemoteMessage.part0" +
829 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800830 result.emplace_back(logfile_base1 +
831 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700832 "aos.message_bridge.RemoteMessage.part1" +
833 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800834 result.emplace_back(logfile_base1 +
835 "_timestamps/pi1/aos/remote_timestamps/pi2/"
836 "aos.message_bridge.RemoteMessage.part2" +
837 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800838 result.emplace_back(logfile_base2 +
839 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700840 "aos.message_bridge.RemoteMessage.part0" +
841 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800842 result.emplace_back(logfile_base2 +
843 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700844 "aos.message_bridge.RemoteMessage.part1" +
845 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800846 } else {
847 result.emplace_back(logfile_base1 +
848 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
849 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700850 "aos.message_bridge.RemoteMessage.part0" +
851 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800852 result.emplace_back(logfile_base1 +
853 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
854 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700855 "aos.message_bridge.RemoteMessage.part1" +
856 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800857 result.emplace_back(logfile_base2 +
858 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
859 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700860 "aos.message_bridge.RemoteMessage.part0" +
861 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800862 result.emplace_back(logfile_base2 +
863 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
864 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700865 "aos.message_bridge.RemoteMessage.part1" +
866 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800867 result.emplace_back(logfile_base1 +
868 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
869 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700870 "aos.message_bridge.RemoteMessage.part0" +
871 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800872 result.emplace_back(logfile_base1 +
873 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
874 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700875 "aos.message_bridge.RemoteMessage.part1" +
876 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800877 }
878
879 return result;
880 }
881
882 std::vector<std::string> MakePi1RebootLogfiles() {
883 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700884 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
885 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
886 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800887 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
888 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800889 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700890 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800891 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700892 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800893 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700894 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700895 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700896 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
897 result.emplace_back(logfile_base1_ +
898 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
899 Extension());
900 result.emplace_back(logfile_base1_ +
901 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
902 Extension());
903 result.emplace_back(logfile_base1_ +
904 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
905 Extension());
906 result.emplace_back(logfile_base1_ +
907 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
908 Extension());
909 result.emplace_back(absl::StrCat(
910 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800911 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800912 for (size_t i = 0; i < 6; ++i) {
913 result.emplace_back(
914 absl::StrCat(logfile_base1_,
915 "_timestamps/pi1/aos/remote_timestamps/pi2/"
916 "aos.message_bridge.RemoteMessage.part",
917 i, Extension()));
918 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800919 } else {
920 result.emplace_back(logfile_base1_ +
921 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
922 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700923 "aos.message_bridge.RemoteMessage.part0" +
924 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800925 result.emplace_back(logfile_base1_ +
926 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
927 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700928 "aos.message_bridge.RemoteMessage.part1" +
929 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800930 result.emplace_back(logfile_base1_ +
931 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
932 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700933 "aos.message_bridge.RemoteMessage.part2" +
934 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700935 result.emplace_back(logfile_base1_ +
936 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
937 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700938 "aos.message_bridge.RemoteMessage.part3" +
939 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800940
941 result.emplace_back(logfile_base1_ +
942 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
943 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700944 "aos.message_bridge.RemoteMessage.part0" +
945 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800946 result.emplace_back(logfile_base1_ +
947 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
948 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700949 "aos.message_bridge.RemoteMessage.part1" +
950 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800951 result.emplace_back(logfile_base1_ +
952 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
953 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700954 "aos.message_bridge.RemoteMessage.part2" +
955 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700956 result.emplace_back(logfile_base1_ +
957 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
958 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700959 "aos.message_bridge.RemoteMessage.part3" +
960 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800961 }
962 return result;
963 }
964
965 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
966 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700967 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
968 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
969 result.emplace_back(logfile_base1_ +
970 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
971 Extension());
972 result.emplace_back(absl::StrCat(
973 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700974 return result;
975 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800976
Austin Schuh510dc622021-08-06 18:47:30 -0700977 std::vector<std::string> MakePi1DeadNodeLogfiles() {
978 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700979 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
980 result.emplace_back(absl::StrCat(
981 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800982 return result;
983 }
984
985 std::vector<std::vector<std::string>> StructureLogFiles() {
986 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800987 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
988 std::vector<std::string>{logfiles_[5], logfiles_[6]},
989 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800990 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800991 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800992
Austin Schuhbfe6c572022-01-27 20:48:20 -0800993 if (shared()) {
994 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
995 logfiles_[16]});
996 result.emplace_back(
997 std::vector<std::string>{logfiles_[17], logfiles_[18]});
998 } else {
999 result.emplace_back(
1000 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -08001001 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -07001002 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -08001003 result.emplace_back(
1004 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -08001005 }
1006
1007 return result;
1008 }
1009
James Kuszmauldd0a5042021-10-28 23:38:04 -07001010 std::string Extension() {
1011 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
1012 }
1013
Austin Schuh58646e22021-08-23 23:51:46 -07001014 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -07001015 SimulatedEventLoopFactory *factory = nullptr,
1016 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001017 if (factory == nullptr) {
1018 factory = &event_loop_factory_;
1019 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001020 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
1021 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001022 }
1023
James Kuszmauldd0a5042021-10-28 23:38:04 -07001024 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001025 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -08001026 if (logger->event_loop->node()->name()->string_view() == "pi1") {
1027 logfile_base = logfile_base1_;
1028 } else {
1029 logfile_base = logfile_base2_;
1030 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001031 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001032 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001033 }
Austin Schuh15649d62019-12-28 16:36:38 -08001034
Austin Schuh3bd4c402020-11-06 18:19:06 -08001035 void VerifyParts(const std::vector<LogFile> &sorted_parts,
1036 const std::vector<std::string> &corrupted_parts = {}) {
1037 EXPECT_EQ(sorted_parts.size(), 2u);
1038
1039 // Count up the number of UUIDs and make sure they are what we expect as a
1040 // sanity check.
1041 std::set<std::string> log_event_uuids;
1042 std::set<std::string> parts_uuids;
1043 std::set<std::string> both_uuids;
1044
1045 size_t missing_rt_count = 0;
1046
1047 std::vector<std::string> logger_nodes;
1048 for (const LogFile &log_file : sorted_parts) {
1049 EXPECT_FALSE(log_file.log_event_uuid.empty());
1050 log_event_uuids.insert(log_file.log_event_uuid);
1051 logger_nodes.emplace_back(log_file.logger_node);
1052 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -08001053 EXPECT_TRUE(log_file.config);
1054 EXPECT_EQ(log_file.name,
1055 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuhfa712682022-05-11 16:43:42 -07001056 EXPECT_EQ(log_file.logger_sha1,
1057 absl::StrCat("logger_sha1_", log_file.logger_node));
1058 EXPECT_EQ(log_file.logger_version,
1059 absl::StrCat("logger_version_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -08001060
1061 for (const LogParts &part : log_file.parts) {
1062 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
1063 << ": " << part;
1064 missing_rt_count +=
1065 part.realtime_start_time == aos::realtime_clock::min_time;
1066
1067 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
1068 log_event_uuids.end());
1069 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -08001070 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001071 parts_uuids.insert(part.parts_uuid);
1072 both_uuids.insert(part.parts_uuid);
1073 }
1074 }
1075
Austin Schuh61e973f2021-02-21 21:43:56 -08001076 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
1077 // start time on remote nodes because we don't know it and would be
1078 // guessing. And the log reader can actually do a better job. The number
1079 // depends on if we have the remote timestamps split across 2 files, or just
1080 // across 1, depending on if we are using a split or combined timestamp
1081 // channel config.
1082 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001083
1084 EXPECT_EQ(log_event_uuids.size(), 2u);
1085 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
1086 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
1087
1088 // Test that each list of parts is in order. Don't worry about the ordering
1089 // between part file lists though.
1090 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -08001091 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -08001092 ::testing::UnorderedElementsAreArray(structured_logfiles_));
1093
1094 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
1095
1096 EXPECT_NE(sorted_parts[0].realtime_start_time,
1097 aos::realtime_clock::min_time);
1098 EXPECT_NE(sorted_parts[1].realtime_start_time,
1099 aos::realtime_clock::min_time);
1100
1101 EXPECT_NE(sorted_parts[0].monotonic_start_time,
1102 aos::monotonic_clock::min_time);
1103 EXPECT_NE(sorted_parts[1].monotonic_start_time,
1104 aos::monotonic_clock::min_time);
1105
1106 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
1107 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
1108 }
1109
1110 void AddExtension(std::string_view extension) {
1111 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
1112 [extension](const std::string &in) {
1113 return absl::StrCat(in, extension);
1114 });
1115
1116 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
1117 structured_logfiles_.begin(),
1118 [extension](std::vector<std::string> in) {
1119 std::transform(in.begin(), in.end(), in.begin(),
1120 [extension](const std::string &in_str) {
1121 return absl::StrCat(in_str, extension);
1122 });
1123 return in;
1124 });
1125 }
1126
Austin Schuh15649d62019-12-28 16:36:38 -08001127 // Config and factory.
1128 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001129 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -08001130 SimulatedEventLoopFactory event_loop_factory_;
1131
Austin Schuh58646e22021-08-23 23:51:46 -07001132 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001133 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -07001134 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001135 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001136
1137 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -08001138 std::string logfile_base1_;
1139 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -08001140 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001141 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -08001142 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001143
1144 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -08001145};
1146
Austin Schuh391e3172020-09-01 22:48:18 -07001147// Counts the number of messages on a channel. Returns (channel name, channel
1148// type, count) for every message matching matcher()
1149std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -08001150 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001151 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -08001152 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -08001153 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -08001154
Austin Schuh6f3babe2020-01-26 20:34:50 -08001155 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001156 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -08001157 if (!msg) {
1158 break;
1159 }
1160
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001161 if (matcher(msg.get())) {
1162 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001163 }
1164 }
1165
Austin Schuh391e3172020-09-01 22:48:18 -07001166 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001167 int channel = 0;
1168 for (size_t i = 0; i < counts.size(); ++i) {
1169 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -08001170 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -07001171 result.push_back(std::make_tuple(channel->name()->str(),
1172 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -08001173 }
1174 ++channel;
1175 }
1176
1177 return result;
1178}
1179
1180// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001181std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -08001182 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -07001183 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001184 return CountChannelsMatching(
1185 config, filename, [](const UnpackedMessageHeader *msg) {
1186 if (msg->span.data() != nullptr) {
1187 CHECK(!msg->monotonic_remote_time.has_value());
1188 CHECK(!msg->realtime_remote_time.has_value());
1189 CHECK(!msg->remote_queue_index.has_value());
1190 return true;
1191 }
1192 return false;
1193 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001194}
1195
1196// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001197std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001198 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001199 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001200 return CountChannelsMatching(
1201 config, filename, [](const UnpackedMessageHeader *msg) {
1202 if (msg->span.data() == nullptr) {
1203 CHECK(msg->monotonic_remote_time.has_value());
1204 CHECK(msg->realtime_remote_time.has_value());
1205 CHECK(msg->remote_queue_index.has_value());
1206 return true;
1207 }
1208 return false;
1209 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001210}
1211
Austin Schuhcde938c2020-02-02 17:30:07 -08001212// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001213TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001214 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001215 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001216
Austin Schuh15649d62019-12-28 16:36:38 -08001217 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001218 LoggerState pi1_logger = MakeLogger(pi1_);
1219 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001220
1221 event_loop_factory_.RunFor(chrono::milliseconds(95));
1222
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001223 StartLogger(&pi1_logger);
1224 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001225
Austin Schuh15649d62019-12-28 16:36:38 -08001226 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001227 pi1_logger.AppendAllFilenames(&actual_filenames);
1228 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001229 }
1230
Austin Schuhbfe6c572022-01-27 20:48:20 -08001231 ASSERT_THAT(actual_filenames,
1232 ::testing::UnorderedElementsAreArray(logfiles_));
1233
Austin Schuh6f3babe2020-01-26 20:34:50 -08001234 {
Austin Schuh64fab802020-09-09 22:47:47 -07001235 std::set<std::string> logfile_uuids;
1236 std::set<std::string> parts_uuids;
1237 // Confirm that we have the expected number of UUIDs for both the logfile
1238 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001239 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001240 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001241 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001242 if (!log_header.back().message().has_configuration()) {
1243 logfile_uuids.insert(
1244 log_header.back().message().log_event_uuid()->str());
1245 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1246 }
Austin Schuh64fab802020-09-09 22:47:47 -07001247 }
Austin Schuh15649d62019-12-28 16:36:38 -08001248
Austin Schuh64fab802020-09-09 22:47:47 -07001249 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001250 if (shared()) {
1251 EXPECT_EQ(parts_uuids.size(), 7u);
1252 } else {
1253 EXPECT_EQ(parts_uuids.size(), 8u);
1254 }
Austin Schuh64fab802020-09-09 22:47:47 -07001255
1256 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001257 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001258 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001259 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1260
Austin Schuh64fab802020-09-09 22:47:47 -07001261 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001262 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001263
Austin Schuhe46492f2021-07-31 19:49:41 -07001264 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001265 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1266 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1267
1268 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1269 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1270
Austin Schuhe46492f2021-07-31 19:49:41 -07001271 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1272 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001273
1274 if (shared()) {
1275 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1276 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001277 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001278
1279 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1280 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1281 } else {
1282 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1283 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1284
1285 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1286 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1287
1288 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1289 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001290 }
Austin Schuh64fab802020-09-09 22:47:47 -07001291
1292 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001293 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001294 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001295 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1296
1297 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1298 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1299
1300 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1301 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1302 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1303
Austin Schuh64fab802020-09-09 22:47:47 -07001304 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1305 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001306
Austin Schuh61e973f2021-02-21 21:43:56 -08001307 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1308 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001309
1310 if (shared()) {
1311 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1312 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1313 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1314
1315 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1316 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1317 } else {
1318 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1319 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1320
Austin Schuhe46492f2021-07-31 19:49:41 -07001321 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1322 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001323
1324 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1325 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001326 }
Austin Schuh64fab802020-09-09 22:47:47 -07001327 }
1328
Austin Schuh8c399962020-12-25 21:51:45 -08001329 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001330 {
Austin Schuh391e3172020-09-01 22:48:18 -07001331 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001332 std::shared_ptr<const aos::Configuration> config =
1333 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001334
Austin Schuh6f3babe2020-01-26 20:34:50 -08001335 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001336 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1337 UnorderedElementsAre(
1338 std::make_tuple("/pi1/aos",
1339 "aos.message_bridge.ServerStatistics", 1),
1340 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001341 << " : " << logfiles_[2];
James Kuszmaul53da7f32022-09-11 11:11:55 -07001342 {
1343 std::vector<std::tuple<std::string, std::string, int>> channel_counts = {
1344 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1345 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1346 1)};
1347 if (!std::get<0>(GetParam()).shared) {
1348 channel_counts.push_back(
1349 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1350 "aos-message_bridge-Timestamp",
1351 "aos.message_bridge.RemoteMessage", 1));
1352 }
1353 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
1354 ::testing::UnorderedElementsAreArray(channel_counts))
1355 << " : " << logfiles_[3];
1356 }
1357 {
1358 std::vector<std::tuple<std::string, std::string, int>> channel_counts = {
1359 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
1360 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
1361 20),
1362 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1363 199),
1364 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
1365 std::make_tuple("/test", "aos.examples.Ping", 2000)};
1366 if (!std::get<0>(GetParam()).shared) {
1367 channel_counts.push_back(
1368 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1369 "aos-message_bridge-Timestamp",
1370 "aos.message_bridge.RemoteMessage", 199));
1371 }
1372 EXPECT_THAT(CountChannelsData(config, logfiles_[4]),
1373 ::testing::UnorderedElementsAreArray(channel_counts))
1374 << " : " << logfiles_[4];
1375 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001376 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001377 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1378 UnorderedElementsAre())
1379 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001380 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001381 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001382 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001383 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001384 EXPECT_THAT(
1385 CountChannelsTimestamp(config, logfiles_[4]),
1386 UnorderedElementsAre(
1387 std::make_tuple("/test", "aos.examples.Pong", 2000),
1388 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1389 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001390
1391 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001392 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001393 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001394 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001395 << " : " << logfiles_[5];
1396 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001397 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001398 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001399 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001400
Austin Schuh6f3babe2020-01-26 20:34:50 -08001401 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001402 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1403 UnorderedElementsAre())
1404 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001405 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1406 UnorderedElementsAre())
1407 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001408
1409 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001410 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001411 UnorderedElementsAre(std::make_tuple(
1412 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001413 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001414 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001415 CountChannelsData(config, logfiles_[8]),
1416 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1417 << " : " << logfiles_[8];
1418 EXPECT_THAT(
1419 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001420 UnorderedElementsAre(
1421 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001422 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001423 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001424 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1425 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001426 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001427 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1428 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001429 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001430 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001431 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001432 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001433 EXPECT_THAT(
1434 CountChannelsTimestamp(config, logfiles_[8]),
1435 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1436 << " : " << logfiles_[8];
1437 EXPECT_THAT(
1438 CountChannelsTimestamp(config, logfiles_[9]),
1439 UnorderedElementsAre(
1440 std::make_tuple("/test", "aos.examples.Ping", 2000),
1441 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1442 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001443
1444 // And then test that the remotely logged timestamp data files only have
1445 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001446 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1447 UnorderedElementsAre())
1448 << " : " << logfiles_[10];
1449 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1450 UnorderedElementsAre())
1451 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001452 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1453 UnorderedElementsAre())
1454 << " : " << logfiles_[12];
1455 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1456 UnorderedElementsAre())
1457 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001458
Austin Schuh8c399962020-12-25 21:51:45 -08001459 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001460 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001461 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001462 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001463 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001464 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001465 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001466 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001467
Austin Schuh61e973f2021-02-21 21:43:56 -08001468 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001469 UnorderedElementsAre(std::make_tuple(
1470 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001471 << " : " << logfiles_[12];
1472 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001473 UnorderedElementsAre(std::make_tuple(
1474 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001475 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001476
1477 // Timestamps from pi2 on pi1, and the other way.
1478 if (shared()) {
1479 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1480 UnorderedElementsAre())
1481 << " : " << logfiles_[14];
1482 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1483 UnorderedElementsAre())
1484 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001485 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001486 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001487 << " : " << logfiles_[16];
1488 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001489 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001490 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001491 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1492 UnorderedElementsAre())
1493 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001494
Austin Schuhbfe6c572022-01-27 20:48:20 -08001495 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1496 UnorderedElementsAre(
1497 std::make_tuple("/test", "aos.examples.Ping", 1)))
1498 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001499 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001500 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001501 UnorderedElementsAre(
1502 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001503 std::make_tuple("/test", "aos.examples.Ping", 90)))
1504 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001505 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001506 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001507 UnorderedElementsAre(
1508 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1509 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001510 << " : " << logfiles_[16];
1511 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001512 UnorderedElementsAre(std::make_tuple(
1513 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1514 << " : " << logfiles_[17];
1515 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1516 UnorderedElementsAre(std::make_tuple(
1517 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1518 << " : " << logfiles_[18];
1519 } else {
1520 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1521 UnorderedElementsAre())
1522 << " : " << logfiles_[14];
1523 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1524 UnorderedElementsAre())
1525 << " : " << logfiles_[15];
1526 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1527 UnorderedElementsAre())
1528 << " : " << logfiles_[16];
1529 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1530 UnorderedElementsAre())
1531 << " : " << logfiles_[17];
1532 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1533 UnorderedElementsAre())
1534 << " : " << logfiles_[18];
1535 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1536 UnorderedElementsAre())
1537 << " : " << logfiles_[19];
1538
1539 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1540 UnorderedElementsAre(std::make_tuple(
1541 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1542 << " : " << logfiles_[14];
1543 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1544 UnorderedElementsAre(std::make_tuple(
1545 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1546 << " : " << logfiles_[15];
1547 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1548 UnorderedElementsAre(std::make_tuple(
1549 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1550 << " : " << logfiles_[16];
1551 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1552 UnorderedElementsAre(std::make_tuple(
1553 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1554 << " : " << logfiles_[17];
1555 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1556 UnorderedElementsAre(
1557 std::make_tuple("/test", "aos.examples.Ping", 91)))
1558 << " : " << logfiles_[18];
1559 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001560 UnorderedElementsAre(
1561 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001562 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001563 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001564 }
1565
Austin Schuh8c399962020-12-25 21:51:45 -08001566 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001567
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001568 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001569 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001570
1571 // This sends out the fetched messages and advances time to the start of the
1572 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001573 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001574
Austin Schuhac0771c2020-01-07 18:36:30 -08001575 const Node *pi1 =
1576 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001577 const Node *pi2 =
1578 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001579
Austin Schuh2f8fd752020-09-01 22:38:28 -07001580 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1581 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1582 LOG(INFO) << "now pi1 "
1583 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1584 LOG(INFO) << "now pi2 "
1585 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1586
Austin Schuh07676622021-01-21 18:59:17 -08001587 EXPECT_THAT(reader.LoggedNodes(),
1588 ::testing::ElementsAre(
1589 configuration::GetNode(reader.logged_configuration(), pi1),
1590 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001591
1592 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001593
Austin Schuh6f3babe2020-01-26 20:34:50 -08001594 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001595 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001596 std::unique_ptr<EventLoop> pi2_event_loop =
1597 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001598
Austin Schuh6f3babe2020-01-26 20:34:50 -08001599 int pi1_ping_count = 10;
1600 int pi2_ping_count = 10;
1601 int pi1_pong_count = 10;
1602 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001603
1604 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001605 pi1_event_loop->MakeWatcher(
1606 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001607 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001608 << pi1_event_loop->context().monotonic_remote_time << " -> "
1609 << pi1_event_loop->context().monotonic_event_time;
1610 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1611 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1612 pi1_ping_count * chrono::milliseconds(10) +
1613 monotonic_clock::epoch());
1614 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1615 pi1_ping_count * chrono::milliseconds(10) +
1616 realtime_clock::epoch());
1617 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1618 pi1_event_loop->context().monotonic_event_time);
1619 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1620 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001621
Austin Schuh6f3babe2020-01-26 20:34:50 -08001622 ++pi1_ping_count;
1623 });
1624 pi2_event_loop->MakeWatcher(
1625 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001626 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001627 << pi2_event_loop->context().monotonic_remote_time << " -> "
1628 << pi2_event_loop->context().monotonic_event_time;
1629 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1630
1631 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1632 pi2_ping_count * chrono::milliseconds(10) +
1633 monotonic_clock::epoch());
1634 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1635 pi2_ping_count * chrono::milliseconds(10) +
1636 realtime_clock::epoch());
1637 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1638 chrono::microseconds(150),
1639 pi2_event_loop->context().monotonic_event_time);
1640 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1641 chrono::microseconds(150),
1642 pi2_event_loop->context().realtime_event_time);
1643 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001644 });
1645
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001646 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001647 // Confirm that the ping and pong counts both match, and the value also
1648 // matches.
1649 pi1_event_loop->MakeWatcher(
1650 "/test", [&pi1_event_loop, &pi1_ping_count,
1651 &pi1_pong_count](const examples::Pong &pong) {
1652 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1653 << pi1_event_loop->context().monotonic_remote_time << " -> "
1654 << pi1_event_loop->context().monotonic_event_time;
1655
1656 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1657 pi1_pong_count + kQueueIndexOffset);
1658 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1659 chrono::microseconds(200) +
1660 pi1_pong_count * chrono::milliseconds(10) +
1661 monotonic_clock::epoch());
1662 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1663 chrono::microseconds(200) +
1664 pi1_pong_count * chrono::milliseconds(10) +
1665 realtime_clock::epoch());
1666
1667 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1668 chrono::microseconds(150),
1669 pi1_event_loop->context().monotonic_event_time);
1670 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1671 chrono::microseconds(150),
1672 pi1_event_loop->context().realtime_event_time);
1673
1674 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1675 ++pi1_pong_count;
1676 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1677 });
1678 pi2_event_loop->MakeWatcher(
1679 "/test", [&pi2_event_loop, &pi2_ping_count,
1680 &pi2_pong_count](const examples::Pong &pong) {
1681 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1682 << pi2_event_loop->context().monotonic_remote_time << " -> "
1683 << pi2_event_loop->context().monotonic_event_time;
1684
1685 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001686 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001687
1688 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1689 chrono::microseconds(200) +
1690 pi2_pong_count * chrono::milliseconds(10) +
1691 monotonic_clock::epoch());
1692 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1693 chrono::microseconds(200) +
1694 pi2_pong_count * chrono::milliseconds(10) +
1695 realtime_clock::epoch());
1696
1697 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1698 pi2_event_loop->context().monotonic_event_time);
1699 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1700 pi2_event_loop->context().realtime_event_time);
1701
1702 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1703 ++pi2_pong_count;
1704 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1705 });
1706
1707 log_reader_factory.Run();
1708 EXPECT_EQ(pi1_ping_count, 2010);
1709 EXPECT_EQ(pi2_ping_count, 2010);
1710 EXPECT_EQ(pi1_pong_count, 2010);
1711 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001712
1713 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001714}
1715
James Kuszmaul46d82582020-05-09 19:50:09 -07001716typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1717
1718// Test that if we feed the replay with a mismatched node list that we die on
1719// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001720TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001721 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001722 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001723 LoggerState pi1_logger = MakeLogger(pi1_);
1724 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001725
1726 event_loop_factory_.RunFor(chrono::milliseconds(95));
1727
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001728 StartLogger(&pi1_logger);
1729 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001730
James Kuszmaul46d82582020-05-09 19:50:09 -07001731 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1732 }
1733
1734 // Test that, if we add an additional node to the replay config that the
1735 // logger complains about the mismatch in number of nodes.
1736 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1737 configuration::MergeWithConfig(&config_.message(), R"({
1738 "nodes": [
1739 {
1740 "name": "extra-node"
1741 }
1742 ]
1743 }
1744 )");
1745
Austin Schuh287d43d2020-12-04 20:19:33 -08001746 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1747 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001748 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001749}
1750
Austin Schuhcde938c2020-02-02 17:30:07 -08001751// Tests that we can read log files where they don't start at the same monotonic
1752// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001753TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001754 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001755 std::vector<std::string> actual_filenames;
1756
Austin Schuhcde938c2020-02-02 17:30:07 -08001757 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001758 LoggerState pi1_logger = MakeLogger(pi1_);
1759 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001760
1761 event_loop_factory_.RunFor(chrono::milliseconds(95));
1762
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001763 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001764
1765 event_loop_factory_.RunFor(chrono::milliseconds(200));
1766
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001767 StartLogger(&pi2_logger);
1768
Austin Schuhcde938c2020-02-02 17:30:07 -08001769 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001770 pi1_logger.AppendAllFilenames(&actual_filenames);
1771 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001772 }
1773
Austin Schuhe46492f2021-07-31 19:49:41 -07001774 // Since we delay starting pi2, it already knows about all the timestamps so
1775 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001776 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001777
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001778 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001779 log_reader_factory.set_send_delay(chrono::microseconds(0));
1780
1781 // This sends out the fetched messages and advances time to the start of the
1782 // log file.
1783 reader.Register(&log_reader_factory);
1784
1785 const Node *pi1 =
1786 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1787 const Node *pi2 =
1788 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1789
Austin Schuh07676622021-01-21 18:59:17 -08001790 EXPECT_THAT(reader.LoggedNodes(),
1791 ::testing::ElementsAre(
1792 configuration::GetNode(reader.logged_configuration(), pi1),
1793 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001794
1795 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1796
1797 std::unique_ptr<EventLoop> pi1_event_loop =
1798 log_reader_factory.MakeEventLoop("test", pi1);
1799 std::unique_ptr<EventLoop> pi2_event_loop =
1800 log_reader_factory.MakeEventLoop("test", pi2);
1801
1802 int pi1_ping_count = 30;
1803 int pi2_ping_count = 30;
1804 int pi1_pong_count = 30;
1805 int pi2_pong_count = 30;
1806
1807 // Confirm that the ping value matches.
1808 pi1_event_loop->MakeWatcher(
1809 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1810 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1811 << pi1_event_loop->context().monotonic_remote_time << " -> "
1812 << pi1_event_loop->context().monotonic_event_time;
1813 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1814
1815 ++pi1_ping_count;
1816 });
1817 pi2_event_loop->MakeWatcher(
1818 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1819 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1820 << pi2_event_loop->context().monotonic_remote_time << " -> "
1821 << pi2_event_loop->context().monotonic_event_time;
1822 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1823
1824 ++pi2_ping_count;
1825 });
1826
1827 // Confirm that the ping and pong counts both match, and the value also
1828 // matches.
1829 pi1_event_loop->MakeWatcher(
1830 "/test", [&pi1_event_loop, &pi1_ping_count,
1831 &pi1_pong_count](const examples::Pong &pong) {
1832 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1833 << pi1_event_loop->context().monotonic_remote_time << " -> "
1834 << pi1_event_loop->context().monotonic_event_time;
1835
1836 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1837 ++pi1_pong_count;
1838 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1839 });
1840 pi2_event_loop->MakeWatcher(
1841 "/test", [&pi2_event_loop, &pi2_ping_count,
1842 &pi2_pong_count](const examples::Pong &pong) {
1843 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1844 << pi2_event_loop->context().monotonic_remote_time << " -> "
1845 << pi2_event_loop->context().monotonic_event_time;
1846
1847 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1848 ++pi2_pong_count;
1849 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1850 });
1851
1852 log_reader_factory.Run();
1853 EXPECT_EQ(pi1_ping_count, 2030);
1854 EXPECT_EQ(pi2_ping_count, 2030);
1855 EXPECT_EQ(pi1_pong_count, 2030);
1856 EXPECT_EQ(pi2_pong_count, 2030);
1857
1858 reader.Deregister();
1859}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001860
Austin Schuh8bd96322020-02-13 21:18:22 -08001861// Tests that we can read log files where the monotonic clocks drift and don't
1862// match correctly. While we are here, also test that different ending times
1863// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001864TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001865 // TODO(austin): Negate...
1866 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1867
Austin Schuh66168842021-08-17 19:42:21 -07001868 time_converter_.AddMonotonic(
1869 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001870 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1871 // skew to be 200 uS/s
1872 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1873 {chrono::milliseconds(95),
1874 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1875 // Run another 200 ms to have one logger start first.
1876 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1877 {chrono::milliseconds(200), chrono::milliseconds(200)});
1878 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1879 // go far enough to cause problems if this isn't accounted for.
1880 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1881 {chrono::milliseconds(20000),
1882 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1883 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1884 {chrono::milliseconds(40000),
1885 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1886 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1887 {chrono::milliseconds(400), chrono::milliseconds(400)});
1888
Austin Schuhcde938c2020-02-02 17:30:07 -08001889 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001890 LoggerState pi2_logger = MakeLogger(pi2_);
1891
Austin Schuh58646e22021-08-23 23:51:46 -07001892 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1893 << pi2_->realtime_now() << " distributed "
1894 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001895
Austin Schuh58646e22021-08-23 23:51:46 -07001896 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1897 << pi2_->realtime_now() << " distributed "
1898 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001899
Austin Schuh87dd3832021-01-01 23:07:31 -08001900 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001901
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001902 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001903
Austin Schuh87dd3832021-01-01 23:07:31 -08001904 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001905
Austin Schuh8bd96322020-02-13 21:18:22 -08001906 {
1907 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001908 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001909
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001910 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001911 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001912
Austin Schuh87dd3832021-01-01 23:07:31 -08001913 // Make sure we slewed time far enough so that the difference is greater
1914 // than the network delay. This confirms that if we sort incorrectly, it
1915 // would show in the results.
1916 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001917 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001918 -event_loop_factory_.send_delay() -
1919 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001920
Austin Schuh87dd3832021-01-01 23:07:31 -08001921 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001922
Austin Schuh87dd3832021-01-01 23:07:31 -08001923 // And now check that we went far enough the other way to make sure we
1924 // cover both problems.
1925 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001926 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001927 event_loop_factory_.send_delay() +
1928 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001929 }
1930
1931 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001932 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001933 }
1934
Austin Schuh72211ae2021-08-05 14:02:30 -07001935 LogReader reader(
1936 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001937
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001938 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001939 log_reader_factory.set_send_delay(chrono::microseconds(0));
1940
Austin Schuhcde938c2020-02-02 17:30:07 -08001941 const Node *pi1 =
1942 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1943 const Node *pi2 =
1944 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1945
Austin Schuh2f8fd752020-09-01 22:38:28 -07001946 // This sends out the fetched messages and advances time to the start of the
1947 // log file.
1948 reader.Register(&log_reader_factory);
1949
1950 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1951 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1952 LOG(INFO) << "now pi1 "
1953 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1954 LOG(INFO) << "now pi2 "
1955 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1956
Austin Schuhcde938c2020-02-02 17:30:07 -08001957 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001958 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1959 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001960 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1961 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001962 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1963 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001964 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1965
Austin Schuh07676622021-01-21 18:59:17 -08001966 EXPECT_THAT(reader.LoggedNodes(),
1967 ::testing::ElementsAre(
1968 configuration::GetNode(reader.logged_configuration(), pi1),
1969 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001970
1971 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1972
1973 std::unique_ptr<EventLoop> pi1_event_loop =
1974 log_reader_factory.MakeEventLoop("test", pi1);
1975 std::unique_ptr<EventLoop> pi2_event_loop =
1976 log_reader_factory.MakeEventLoop("test", pi2);
1977
1978 int pi1_ping_count = 30;
1979 int pi2_ping_count = 30;
1980 int pi1_pong_count = 30;
1981 int pi2_pong_count = 30;
1982
1983 // Confirm that the ping value matches.
1984 pi1_event_loop->MakeWatcher(
1985 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1986 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1987 << pi1_event_loop->context().monotonic_remote_time << " -> "
1988 << pi1_event_loop->context().monotonic_event_time;
1989 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1990
1991 ++pi1_ping_count;
1992 });
1993 pi2_event_loop->MakeWatcher(
1994 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1995 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1996 << pi2_event_loop->context().monotonic_remote_time << " -> "
1997 << pi2_event_loop->context().monotonic_event_time;
1998 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1999
2000 ++pi2_ping_count;
2001 });
2002
2003 // Confirm that the ping and pong counts both match, and the value also
2004 // matches.
2005 pi1_event_loop->MakeWatcher(
2006 "/test", [&pi1_event_loop, &pi1_ping_count,
2007 &pi1_pong_count](const examples::Pong &pong) {
2008 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
2009 << pi1_event_loop->context().monotonic_remote_time << " -> "
2010 << pi1_event_loop->context().monotonic_event_time;
2011
2012 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
2013 ++pi1_pong_count;
2014 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
2015 });
2016 pi2_event_loop->MakeWatcher(
2017 "/test", [&pi2_event_loop, &pi2_ping_count,
2018 &pi2_pong_count](const examples::Pong &pong) {
2019 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
2020 << pi2_event_loop->context().monotonic_remote_time << " -> "
2021 << pi2_event_loop->context().monotonic_event_time;
2022
2023 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
2024 ++pi2_pong_count;
2025 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
2026 });
2027
2028 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08002029 EXPECT_EQ(pi1_ping_count, 6030);
2030 EXPECT_EQ(pi2_ping_count, 6030);
2031 EXPECT_EQ(pi1_pong_count, 6030);
2032 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08002033
2034 reader.Deregister();
2035}
2036
Austin Schuh5212cad2020-09-09 23:12:09 -07002037// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002038TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002039 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07002040 // Make a bunch of parts.
2041 {
2042 LoggerState pi1_logger = MakeLogger(pi1_);
2043 LoggerState pi2_logger = MakeLogger(pi2_);
2044
2045 event_loop_factory_.RunFor(chrono::milliseconds(95));
2046
2047 StartLogger(&pi1_logger);
2048 StartLogger(&pi2_logger);
2049
2050 event_loop_factory_.RunFor(chrono::milliseconds(2000));
2051 }
2052
Austin Schuh11d43732020-09-21 17:28:30 -07002053 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002054 VerifyParts(sorted_parts);
2055}
Austin Schuh11d43732020-09-21 17:28:30 -07002056
Austin Schuh3bd4c402020-11-06 18:19:06 -08002057// Tests that we can sort a bunch of parts with an empty part. We should ignore
2058// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08002059TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002060 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002061 // Make a bunch of parts.
2062 {
2063 LoggerState pi1_logger = MakeLogger(pi1_);
2064 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07002065
Austin Schuh3bd4c402020-11-06 18:19:06 -08002066 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07002067
Austin Schuh3bd4c402020-11-06 18:19:06 -08002068 StartLogger(&pi1_logger);
2069 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07002070
Austin Schuh3bd4c402020-11-06 18:19:06 -08002071 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07002072 }
2073
Austin Schuh3bd4c402020-11-06 18:19:06 -08002074 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07002075 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07002076
Austin Schuh3bd4c402020-11-06 18:19:06 -08002077 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
2078 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07002079
Austin Schuh3bd4c402020-11-06 18:19:06 -08002080 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2081 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07002082}
2083
James Kuszmauldd0a5042021-10-28 23:38:04 -07002084// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08002085// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002086TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002087 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002088 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002089 // Make a bunch of parts.
2090 {
2091 LoggerState pi1_logger = MakeLogger(pi1_);
2092 LoggerState pi2_logger = MakeLogger(pi2_);
2093
2094 event_loop_factory_.RunFor(chrono::milliseconds(95));
2095
James Kuszmauldd0a5042021-10-28 23:38:04 -07002096 StartLogger(&pi1_logger);
2097 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002098
2099 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002100
2101 pi1_logger.AppendAllFilenames(&actual_filenames);
2102 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002103 }
2104
Austin Schuhbfe6c572022-01-27 20:48:20 -08002105 ASSERT_THAT(actual_filenames,
2106 ::testing::UnorderedElementsAreArray(logfiles_));
2107
Austin Schuh3bd4c402020-11-06 18:19:06 -08002108 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002109 // For snappy, needs to have enough data to be >1 chunk of compressed data so
2110 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08002111 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08002112 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002113
2114 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08002115 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08002116 compressed_contents.substr(0, compressed_contents.size() - 100));
2117
2118 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2119 VerifyParts(sorted_parts);
2120}
Austin Schuh3bd4c402020-11-06 18:19:06 -08002121
Austin Schuh01b4c352020-09-21 23:09:39 -07002122// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08002123TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002124 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07002125 {
2126 LoggerState pi1_logger = MakeLogger(pi1_);
2127 LoggerState pi2_logger = MakeLogger(pi2_);
2128
2129 event_loop_factory_.RunFor(chrono::milliseconds(95));
2130
2131 StartLogger(&pi1_logger);
2132 StartLogger(&pi2_logger);
2133
2134 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2135 }
2136
Austin Schuh287d43d2020-12-04 20:19:33 -08002137 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07002138
2139 // Remap just on pi1.
2140 reader.RemapLoggedChannel<aos::timing::Report>(
2141 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
2142
2143 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2144 log_reader_factory.set_send_delay(chrono::microseconds(0));
2145
Austin Schuh1c227352021-09-17 12:53:54 -07002146 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
James Kuszmaul53da7f32022-09-11 11:11:55 -07002147 // Note: An extra channel gets remapped automatically due to a timestamp
2148 // channel being LOCAL_LOGGER'd.
2149 ASSERT_EQ(remapped_channels.size(), std::get<0>(GetParam()).shared ? 1u : 2u);
Austin Schuh1c227352021-09-17 12:53:54 -07002150 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
2151 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
James Kuszmaul53da7f32022-09-11 11:11:55 -07002152 if (!std::get<0>(GetParam()).shared) {
2153 EXPECT_EQ(remapped_channels[1]->name()->string_view(),
2154 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
2155 "aos-message_bridge-Timestamp");
2156 EXPECT_EQ(remapped_channels[1]->type()->string_view(),
2157 "aos.message_bridge.RemoteMessage");
2158 }
Austin Schuh1c227352021-09-17 12:53:54 -07002159
Austin Schuh01b4c352020-09-21 23:09:39 -07002160 reader.Register(&log_reader_factory);
2161
2162 const Node *pi1 =
2163 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2164 const Node *pi2 =
2165 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2166
2167 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2168 // else should have moved.
2169 std::unique_ptr<EventLoop> pi1_event_loop =
2170 log_reader_factory.MakeEventLoop("test", pi1);
2171 pi1_event_loop->SkipTimingReport();
2172 std::unique_ptr<EventLoop> full_pi1_event_loop =
2173 log_reader_factory.MakeEventLoop("test", pi1);
2174 full_pi1_event_loop->SkipTimingReport();
2175 std::unique_ptr<EventLoop> pi2_event_loop =
2176 log_reader_factory.MakeEventLoop("test", pi2);
2177 pi2_event_loop->SkipTimingReport();
2178
2179 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
2180 "/aos");
2181 MessageCounter<aos::timing::Report> full_pi1_timing_report(
2182 full_pi1_event_loop.get(), "/pi1/aos");
2183 MessageCounter<aos::timing::Report> pi1_original_timing_report(
2184 pi1_event_loop.get(), "/original/aos");
2185 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
2186 full_pi1_event_loop.get(), "/original/pi1/aos");
2187 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
2188 "/aos");
2189
2190 log_reader_factory.Run();
2191
2192 EXPECT_EQ(pi1_timing_report.count(), 0u);
2193 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
2194 EXPECT_NE(pi1_original_timing_report.count(), 0u);
2195 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
2196 EXPECT_NE(pi2_timing_report.count(), 0u);
2197
2198 reader.Deregister();
2199}
2200
Austin Schuh006a9f52021-04-07 16:24:18 -07002201// Tests that we can remap a forwarded channel as well.
2202TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
2203 time_converter_.StartEqual();
2204 {
2205 LoggerState pi1_logger = MakeLogger(pi1_);
2206 LoggerState pi2_logger = MakeLogger(pi2_);
2207
2208 event_loop_factory_.RunFor(chrono::milliseconds(95));
2209
2210 StartLogger(&pi1_logger);
2211 StartLogger(&pi2_logger);
2212
2213 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2214 }
2215
2216 LogReader reader(SortParts(logfiles_));
2217
2218 reader.RemapLoggedChannel<examples::Ping>("/test");
2219
2220 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2221 log_reader_factory.set_send_delay(chrono::microseconds(0));
2222
2223 reader.Register(&log_reader_factory);
2224
2225 const Node *pi1 =
2226 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2227 const Node *pi2 =
2228 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2229
2230 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2231 // else should have moved.
2232 std::unique_ptr<EventLoop> pi1_event_loop =
2233 log_reader_factory.MakeEventLoop("test", pi1);
2234 pi1_event_loop->SkipTimingReport();
2235 std::unique_ptr<EventLoop> full_pi1_event_loop =
2236 log_reader_factory.MakeEventLoop("test", pi1);
2237 full_pi1_event_loop->SkipTimingReport();
2238 std::unique_ptr<EventLoop> pi2_event_loop =
2239 log_reader_factory.MakeEventLoop("test", pi2);
2240 pi2_event_loop->SkipTimingReport();
2241
2242 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2243 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2244 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2245 "/original/test");
2246 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2247 "/original/test");
2248
2249 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2250 pi1_original_ping_timestamp;
2251 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2252 pi1_ping_timestamp;
2253 if (!shared()) {
2254 pi1_original_ping_timestamp =
2255 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2256 pi1_event_loop.get(),
2257 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2258 pi1_ping_timestamp =
2259 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2260 pi1_event_loop.get(),
2261 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2262 }
2263
2264 log_reader_factory.Run();
2265
2266 EXPECT_EQ(pi1_ping.count(), 0u);
2267 EXPECT_EQ(pi2_ping.count(), 0u);
2268 EXPECT_NE(pi1_original_ping.count(), 0u);
2269 EXPECT_NE(pi2_original_ping.count(), 0u);
2270 if (!shared()) {
2271 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2272 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2273 }
2274
2275 reader.Deregister();
2276}
2277
James Kuszmaul09632422022-05-25 15:56:19 -07002278// Tests that we observe all the same events in log replay (for a given node)
2279// whether we just register an event loop for that node or if we register a full
2280// event loop factory.
2281TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
2282 time_converter_.StartEqual();
2283 constexpr chrono::milliseconds kStartupDelay(95);
2284 {
2285 LoggerState pi1_logger = MakeLogger(pi1_);
2286 LoggerState pi2_logger = MakeLogger(pi2_);
2287
2288 event_loop_factory_.RunFor(kStartupDelay);
2289
2290 StartLogger(&pi1_logger);
2291 StartLogger(&pi2_logger);
2292
2293 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2294 }
2295
2296 LogReader full_reader(SortParts(logfiles_));
2297 LogReader single_node_reader(SortParts(logfiles_));
2298
2299 SimulatedEventLoopFactory full_factory(full_reader.configuration());
2300 SimulatedEventLoopFactory single_node_factory(
2301 single_node_reader.configuration());
James Kuszmaul94ca5132022-07-19 09:11:08 -07002302 single_node_factory.SkipTimingReport();
2303 single_node_factory.DisableStatistics();
James Kuszmaul09632422022-05-25 15:56:19 -07002304 std::unique_ptr<EventLoop> replay_event_loop =
2305 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
2306 "log_reader");
2307
2308 full_reader.Register(&full_factory);
2309 single_node_reader.Register(replay_event_loop.get());
James Kuszmaul09632422022-05-25 15:56:19 -07002310
2311 const Node *full_pi1 =
2312 configuration::GetNode(full_factory.configuration(), "pi1");
2313
2314 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2315 // else should have moved.
2316 std::unique_ptr<EventLoop> full_event_loop =
2317 full_factory.MakeEventLoop("test", full_pi1);
2318 full_event_loop->SkipTimingReport();
2319 full_event_loop->SkipAosLog();
2320 // maps are indexed on channel index.
2321 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
2322 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
2323 observed_messages;
2324 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
2325 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
2326 ++ii) {
2327 const Channel *channel =
2328 full_event_loop->configuration()->channels()->Get(ii);
2329 // We currently don't support replaying remote timestamp channels in
James Kuszmaul53da7f32022-09-11 11:11:55 -07002330 // realtime replay (unless the remote timestamp channel was not NOT_LOGGED,
2331 // in which case it gets auto-remapped and replayed on a /original channel).
James Kuszmaul09632422022-05-25 15:56:19 -07002332 if (channel->name()->string_view().find("remote_timestamp") !=
James Kuszmaul53da7f32022-09-11 11:11:55 -07002333 std::string_view::npos &&
2334 channel->name()->string_view().find("/original") ==
2335 std::string_view::npos) {
James Kuszmaul09632422022-05-25 15:56:19 -07002336 continue;
2337 }
2338 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
2339 observed_messages[ii] = {};
2340 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
2341 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
2342 if (fetchers[ii]->Fetch()) {
2343 observed_messages[ii].push_back(std::make_pair(
2344 fetchers[ii]->context().monotonic_event_time, true));
2345 }
2346 });
2347 full_event_loop->MakeRawNoArgWatcher(
2348 channel, [ii, &observed_messages](const Context &context) {
2349 observed_messages[ii].push_back(
2350 std::make_pair(context.monotonic_event_time, false));
2351 });
2352 }
2353 }
2354
2355 full_factory.Run();
2356 fetchers.clear();
2357 full_reader.Deregister();
2358
2359 const Node *single_node_pi1 =
2360 configuration::GetNode(single_node_factory.configuration(), "pi1");
2361 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
2362
2363 std::unique_ptr<EventLoop> single_node_event_loop =
2364 single_node_factory.MakeEventLoop("test", single_node_pi1);
2365 single_node_event_loop->SkipTimingReport();
2366 single_node_event_loop->SkipAosLog();
2367 for (size_t ii = 0;
2368 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
2369 const Channel *channel =
2370 single_node_event_loop->configuration()->channels()->Get(ii);
2371 single_node_factory.DisableForwarding(channel);
2372 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
2373 single_node_fetchers[ii] =
2374 single_node_event_loop->MakeRawFetcher(channel);
2375 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
2376 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
2377 << "Single EventLoop replay doesn't support pre-loading fetchers. "
2378 << configuration::StrippedChannelToString(channel);
2379 });
2380 single_node_event_loop->MakeRawNoArgWatcher(
2381 channel, [ii, &observed_messages, channel,
2382 kStartupDelay](const Context &context) {
2383 if (observed_messages[ii].empty()) {
2384 FAIL() << "Observed extra message at "
2385 << context.monotonic_event_time << " on "
2386 << configuration::StrippedChannelToString(channel);
2387 return;
2388 }
2389 const std::pair<monotonic_clock::time_point, bool> &message =
2390 observed_messages[ii].front();
2391 if (message.second) {
2392 EXPECT_LE(message.first,
2393 context.monotonic_event_time + kStartupDelay)
2394 << "Mismatched message times " << context.monotonic_event_time
2395 << " and " << message.first << " on "
2396 << configuration::StrippedChannelToString(channel);
2397 } else {
2398 EXPECT_EQ(message.first,
2399 context.monotonic_event_time + kStartupDelay)
2400 << "Mismatched message times " << context.monotonic_event_time
2401 << " and " << message.first << " on "
2402 << configuration::StrippedChannelToString(channel);
2403 }
2404 observed_messages[ii].erase(observed_messages[ii].begin());
2405 });
2406 }
2407 }
2408
2409 single_node_factory.Run();
2410
2411 single_node_fetchers.clear();
2412
2413 single_node_reader.Deregister();
2414
2415 for (const auto &pair : observed_messages) {
2416 EXPECT_TRUE(pair.second.empty())
2417 << "Missed " << pair.second.size() << " messages on "
2418 << configuration::StrippedChannelToString(
2419 single_node_event_loop->configuration()->channels()->Get(
2420 pair.first));
2421 }
2422}
2423
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002424// Tests that we properly recreate forwarded timestamps when replaying a log.
2425// This should be enough that we can then re-run the logger and get a valid log
2426// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002427TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002428 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002429 {
2430 LoggerState pi1_logger = MakeLogger(pi1_);
2431 LoggerState pi2_logger = MakeLogger(pi2_);
2432
2433 event_loop_factory_.RunFor(chrono::milliseconds(95));
2434
2435 StartLogger(&pi1_logger);
2436 StartLogger(&pi2_logger);
2437
2438 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2439 }
2440
Austin Schuh287d43d2020-12-04 20:19:33 -08002441 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002442
2443 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2444 log_reader_factory.set_send_delay(chrono::microseconds(0));
2445
2446 // This sends out the fetched messages and advances time to the start of the
2447 // log file.
2448 reader.Register(&log_reader_factory);
2449
2450 const Node *pi1 =
2451 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2452 const Node *pi2 =
2453 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2454
2455 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2456 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2457 LOG(INFO) << "now pi1 "
2458 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2459 LOG(INFO) << "now pi2 "
2460 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2461
Austin Schuh07676622021-01-21 18:59:17 -08002462 EXPECT_THAT(reader.LoggedNodes(),
2463 ::testing::ElementsAre(
2464 configuration::GetNode(reader.logged_configuration(), pi1),
2465 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002466
2467 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2468
2469 std::unique_ptr<EventLoop> pi1_event_loop =
2470 log_reader_factory.MakeEventLoop("test", pi1);
2471 std::unique_ptr<EventLoop> pi2_event_loop =
2472 log_reader_factory.MakeEventLoop("test", pi2);
2473
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002474 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2475 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2476 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2477 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2478
2479 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2480 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2481 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2482 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2483
2484 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2485 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2486 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2487 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2488
2489 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2490 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2491 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2492 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2493
2494 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2495 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2496 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2497 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2498
2499 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2500 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2501 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2502 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2503
Austin Schuh969cd602021-01-03 00:09:45 -08002504 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002505 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002506
Austin Schuh61e973f2021-02-21 21:43:56 -08002507 for (std::pair<int, std::string> channel :
2508 shared()
2509 ? std::vector<
2510 std::pair<int, std::string>>{{-1,
2511 "/aos/remote_timestamps/pi2"}}
2512 : std::vector<std::pair<int, std::string>>{
2513 {pi1_timestamp_channel,
2514 "/aos/remote_timestamps/pi2/pi1/aos/"
2515 "aos-message_bridge-Timestamp"},
2516 {ping_timestamp_channel,
2517 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2518 pi1_event_loop->MakeWatcher(
2519 channel.second,
2520 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2521 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2522 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2523 &ping_on_pi2_fetcher, network_delay, send_delay,
2524 channel_index = channel.first](const RemoteMessage &header) {
2525 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2526 chrono::nanoseconds(header.monotonic_sent_time()));
2527 const aos::realtime_clock::time_point header_realtime_sent_time(
2528 chrono::nanoseconds(header.realtime_sent_time()));
2529 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2530 chrono::nanoseconds(header.monotonic_remote_time()));
2531 const aos::realtime_clock::time_point header_realtime_remote_time(
2532 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002533
Austin Schuh61e973f2021-02-21 21:43:56 -08002534 if (channel_index != -1) {
2535 ASSERT_EQ(channel_index, header.channel_index());
2536 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002537
Austin Schuh61e973f2021-02-21 21:43:56 -08002538 const Context *pi1_context = nullptr;
2539 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002540
Austin Schuh61e973f2021-02-21 21:43:56 -08002541 if (header.channel_index() == pi1_timestamp_channel) {
2542 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2543 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2544 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2545 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2546 } else if (header.channel_index() == ping_timestamp_channel) {
2547 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2548 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2549 pi1_context = &ping_on_pi1_fetcher.context();
2550 pi2_context = &ping_on_pi2_fetcher.context();
2551 } else {
2552 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2553 << configuration::CleanedChannelToString(
2554 pi1_event_loop->configuration()->channels()->Get(
2555 header.channel_index()));
2556 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002557
Austin Schuh61e973f2021-02-21 21:43:56 -08002558 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002559 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2560 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002561
Austin Schuh61e973f2021-02-21 21:43:56 -08002562 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2563 EXPECT_EQ(pi2_context->remote_queue_index,
2564 header.remote_queue_index());
2565 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002566
Austin Schuh61e973f2021-02-21 21:43:56 -08002567 EXPECT_EQ(pi2_context->monotonic_event_time,
2568 header_monotonic_sent_time);
2569 EXPECT_EQ(pi2_context->realtime_event_time,
2570 header_realtime_sent_time);
2571 EXPECT_EQ(pi2_context->realtime_remote_time,
2572 header_realtime_remote_time);
2573 EXPECT_EQ(pi2_context->monotonic_remote_time,
2574 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002575
Austin Schuh61e973f2021-02-21 21:43:56 -08002576 EXPECT_EQ(pi1_context->realtime_event_time,
2577 header_realtime_remote_time);
2578 EXPECT_EQ(pi1_context->monotonic_event_time,
2579 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002580
Austin Schuh61e973f2021-02-21 21:43:56 -08002581 // Time estimation isn't perfect, but we know the clocks were
2582 // identical when logged, so we know when this should have come back.
2583 // Confirm we got it when we expected.
2584 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2585 pi1_context->monotonic_event_time + 2 * network_delay +
2586 send_delay);
2587 });
2588 }
2589 for (std::pair<int, std::string> channel :
2590 shared()
2591 ? std::vector<
2592 std::pair<int, std::string>>{{-1,
2593 "/aos/remote_timestamps/pi1"}}
2594 : std::vector<std::pair<int, std::string>>{
2595 {pi2_timestamp_channel,
2596 "/aos/remote_timestamps/pi1/pi2/aos/"
2597 "aos-message_bridge-Timestamp"}}) {
2598 pi2_event_loop->MakeWatcher(
2599 channel.second,
2600 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2601 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2602 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2603 &pong_on_pi1_fetcher, network_delay, send_delay,
2604 channel_index = channel.first](const RemoteMessage &header) {
2605 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2606 chrono::nanoseconds(header.monotonic_sent_time()));
2607 const aos::realtime_clock::time_point header_realtime_sent_time(
2608 chrono::nanoseconds(header.realtime_sent_time()));
2609 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2610 chrono::nanoseconds(header.monotonic_remote_time()));
2611 const aos::realtime_clock::time_point header_realtime_remote_time(
2612 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002613
Austin Schuh61e973f2021-02-21 21:43:56 -08002614 if (channel_index != -1) {
2615 ASSERT_EQ(channel_index, header.channel_index());
2616 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002617
Austin Schuh61e973f2021-02-21 21:43:56 -08002618 const Context *pi2_context = nullptr;
2619 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002620
Austin Schuh61e973f2021-02-21 21:43:56 -08002621 if (header.channel_index() == pi2_timestamp_channel) {
2622 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2623 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2624 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2625 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2626 } else if (header.channel_index() == pong_timestamp_channel) {
2627 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2628 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2629 pi2_context = &pong_on_pi2_fetcher.context();
2630 pi1_context = &pong_on_pi1_fetcher.context();
2631 } else {
2632 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2633 << configuration::CleanedChannelToString(
2634 pi2_event_loop->configuration()->channels()->Get(
2635 header.channel_index()));
2636 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002637
Austin Schuh61e973f2021-02-21 21:43:56 -08002638 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002639 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2640 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002641
Austin Schuh61e973f2021-02-21 21:43:56 -08002642 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2643 EXPECT_EQ(pi1_context->remote_queue_index,
2644 header.remote_queue_index());
2645 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002646
Austin Schuh61e973f2021-02-21 21:43:56 -08002647 EXPECT_EQ(pi1_context->monotonic_event_time,
2648 header_monotonic_sent_time);
2649 EXPECT_EQ(pi1_context->realtime_event_time,
2650 header_realtime_sent_time);
2651 EXPECT_EQ(pi1_context->realtime_remote_time,
2652 header_realtime_remote_time);
2653 EXPECT_EQ(pi1_context->monotonic_remote_time,
2654 header_monotonic_remote_time);
2655
2656 EXPECT_EQ(pi2_context->realtime_event_time,
2657 header_realtime_remote_time);
2658 EXPECT_EQ(pi2_context->monotonic_event_time,
2659 header_monotonic_remote_time);
2660
2661 // Time estimation isn't perfect, but we know the clocks were
2662 // identical when logged, so we know when this should have come back.
2663 // Confirm we got it when we expected.
2664 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2665 pi2_context->monotonic_event_time + 2 * network_delay +
2666 send_delay);
2667 });
2668 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002669
2670 // And confirm we can re-create a log again, while checking the contents.
2671 {
2672 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002673 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002674 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002675 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002676
Austin Schuh25b46712021-01-03 00:04:38 -08002677 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2678 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002679
2680 log_reader_factory.Run();
2681 }
2682
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002683 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002684
2685 // And verify that we can run the LogReader over the relogged files without
2686 // hitting any fatal errors.
2687 {
James Kuszmaul53da7f32022-09-11 11:11:55 -07002688 LogReader relogged_reader(SortParts(MakeLogFiles(
2689 tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2", 3, 3, true)));
2690 relogged_reader.Register();
2691
2692 relogged_reader.event_loop_factory()->Run();
2693 }
2694 // And confirm that we can read the logged file using the reader's
2695 // configuration.
2696 {
2697 LogReader relogged_reader(
2698 SortParts(MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2",
2699 3, 3, true)),
2700 reader.configuration());
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002701 relogged_reader.Register();
2702
2703 relogged_reader.event_loop_factory()->Run();
2704 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002705}
2706
Austin Schuh315b96b2020-12-11 21:21:12 -08002707// Tests that we properly populate and extract the logger_start time by setting
2708// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002709TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002710 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002711 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002712 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002713 {
2714 LoggerState pi1_logger = MakeLogger(pi1_);
2715 LoggerState pi2_logger = MakeLogger(pi2_);
2716
Austin Schuh315b96b2020-12-11 21:21:12 -08002717 StartLogger(&pi1_logger);
2718 StartLogger(&pi2_logger);
2719
2720 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002721
2722 pi1_logger.AppendAllFilenames(&actual_filenames);
2723 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002724 }
2725
Austin Schuhf5f99f32022-02-07 20:05:37 -08002726 ASSERT_THAT(actual_filenames,
2727 ::testing::UnorderedElementsAreArray(logfiles_));
2728
Austin Schuh315b96b2020-12-11 21:21:12 -08002729 for (const LogFile &log_file : SortParts(logfiles_)) {
2730 for (const LogParts &log_part : log_file.parts) {
2731 if (log_part.node == log_file.logger_node) {
2732 EXPECT_EQ(log_part.logger_monotonic_start_time,
2733 aos::monotonic_clock::min_time);
2734 EXPECT_EQ(log_part.logger_realtime_start_time,
2735 aos::realtime_clock::min_time);
2736 } else {
2737 const chrono::seconds offset = log_file.logger_node == "pi1"
2738 ? -chrono::seconds(1000)
2739 : chrono::seconds(1000);
2740 EXPECT_EQ(log_part.logger_monotonic_start_time,
2741 log_part.monotonic_start_time + offset);
2742 EXPECT_EQ(log_part.logger_realtime_start_time,
2743 log_file.realtime_start_time +
2744 (log_part.logger_monotonic_start_time -
2745 log_file.monotonic_start_time));
2746 }
2747 }
2748 }
2749}
2750
Austin Schuh6bb8a822021-03-31 23:04:39 -07002751// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002752TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002753 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2754 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002755 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002756 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002757 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2758 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2759 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2760 LoggerState pi1_logger = MakeLogger(pi1_);
2761 LoggerState pi2_logger = MakeLogger(pi2_);
2762
2763 StartLogger(&pi1_logger);
2764 StartLogger(&pi2_logger);
2765
2766 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2767 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2768 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2769 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2770 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2771 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2772 for (auto &file : logfiles_) {
2773 struct stat s;
2774 EXPECT_EQ(0, stat(file.c_str(), &s));
2775 }
2776}
2777
2778// Test that renaming the file base dies.
2779TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2780 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002781 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002782 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002783 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2784 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2785 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2786 LoggerState pi1_logger = MakeLogger(pi1_);
2787 StartLogger(&pi1_logger);
2788 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2789 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2790 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2791 "Rename of file base from");
2792}
2793
Austin Schuh8bd96322020-02-13 21:18:22 -08002794// TODO(austin): We can write a test which recreates a logfile and confirms that
2795// we get it back. That is the ultimate test.
2796
Austin Schuh315b96b2020-12-11 21:21:12 -08002797// Tests that we properly recreate forwarded timestamps when replaying a log.
2798// This should be enough that we can then re-run the logger and get a valid log
2799// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002800TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002801 std::vector<std::string> actual_filenames;
2802
Austin Schuh58646e22021-08-23 23:51:46 -07002803 const UUID pi1_boot0 = UUID::Random();
2804 const UUID pi2_boot0 = UUID::Random();
2805 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002806 {
Austin Schuh58646e22021-08-23 23:51:46 -07002807 CHECK_EQ(pi1_index_, 0u);
2808 CHECK_EQ(pi2_index_, 1u);
2809
2810 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2811 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2812 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2813
2814 time_converter_.AddNextTimestamp(
2815 distributed_clock::epoch(),
2816 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2817 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2818 time_converter_.AddNextTimestamp(
2819 distributed_clock::epoch() + reboot_time,
2820 {BootTimestamp::epoch() + reboot_time,
2821 BootTimestamp{
2822 .boot = 1,
2823 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2824 }
2825
2826 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002827 LoggerState pi1_logger = MakeLogger(pi1_);
2828
2829 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002830 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2831 pi1_boot0);
2832 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2833 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002834
2835 StartLogger(&pi1_logger);
2836
2837 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2838
Austin Schuh58646e22021-08-23 23:51:46 -07002839 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002840
2841 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002842 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2843 pi1_boot0);
2844 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2845 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002846
2847 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002848 }
2849
Austin Schuhbfe6c572022-01-27 20:48:20 -08002850 std::sort(actual_filenames.begin(), actual_filenames.end());
2851 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2852 ASSERT_THAT(actual_filenames,
2853 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2854
Austin Schuh72211ae2021-08-05 14:02:30 -07002855 // Confirm that our new oldest timestamps properly update as we reboot and
2856 // rotate.
2857 for (const std::string &file : pi1_reboot_logfiles_) {
2858 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2859 ReadHeader(file);
2860 CHECK(log_header);
2861 if (log_header->message().has_configuration()) {
2862 continue;
2863 }
2864
Austin Schuh58646e22021-08-23 23:51:46 -07002865 const monotonic_clock::time_point monotonic_start_time =
2866 monotonic_clock::time_point(
2867 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2868 const UUID source_node_boot_uuid = UUID::FromString(
2869 log_header->message().source_node_boot_uuid()->string_view());
2870
Austin Schuh72211ae2021-08-05 14:02:30 -07002871 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002872 // The remote message channel should rotate later and have more parts.
2873 // This only is true on the log files with shared remote messages.
2874 //
2875 // TODO(austin): I'm not the most thrilled with this test pattern... It
2876 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002877 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2878 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002879 switch (log_header->message().parts_index()) {
2880 case 0:
2881 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2882 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2883 break;
2884 case 1:
2885 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2886 ASSERT_EQ(monotonic_start_time,
2887 monotonic_clock::epoch() + chrono::seconds(1));
2888 break;
2889 case 2:
2890 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2891 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2892 break;
2893 case 3:
2894 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2895 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2896 chrono::nanoseconds(2322999462))
2897 << " on " << file;
2898 break;
2899 default:
2900 FAIL();
2901 break;
2902 }
2903 } else {
2904 switch (log_header->message().parts_index()) {
2905 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002906 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002907 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2908 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2909 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002910 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002911 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2912 ASSERT_EQ(monotonic_start_time,
2913 monotonic_clock::epoch() + chrono::seconds(1));
2914 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002915 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002916 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002917 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2918 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2919 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002920 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002921 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2922 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2923 chrono::nanoseconds(2322999462))
2924 << " on " << file;
2925 break;
2926 default:
2927 FAIL();
2928 break;
2929 }
Austin Schuh58646e22021-08-23 23:51:46 -07002930 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002931 continue;
2932 }
2933 SCOPED_TRACE(file);
2934 SCOPED_TRACE(aos::FlatbufferToJson(
2935 *log_header, {.multi_line = true, .max_vector_size = 100}));
2936 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2937 ASSERT_EQ(
2938 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2939 EXPECT_EQ(
2940 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2941 monotonic_clock::max_time.time_since_epoch().count());
2942 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2943 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2944 2u);
2945 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2946 monotonic_clock::max_time.time_since_epoch().count());
2947 ASSERT_TRUE(log_header->message()
2948 .has_oldest_remote_unreliable_monotonic_timestamps());
2949 ASSERT_EQ(log_header->message()
2950 .oldest_remote_unreliable_monotonic_timestamps()
2951 ->size(),
2952 2u);
2953 EXPECT_EQ(log_header->message()
2954 .oldest_remote_unreliable_monotonic_timestamps()
2955 ->Get(0),
2956 monotonic_clock::max_time.time_since_epoch().count());
2957 ASSERT_TRUE(log_header->message()
2958 .has_oldest_local_unreliable_monotonic_timestamps());
2959 ASSERT_EQ(log_header->message()
2960 .oldest_local_unreliable_monotonic_timestamps()
2961 ->size(),
2962 2u);
2963 EXPECT_EQ(log_header->message()
2964 .oldest_local_unreliable_monotonic_timestamps()
2965 ->Get(0),
2966 monotonic_clock::max_time.time_since_epoch().count());
2967
2968 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2969 monotonic_clock::time_point(chrono::nanoseconds(
2970 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2971 1)));
2972 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2973 monotonic_clock::time_point(chrono::nanoseconds(
2974 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2975 const monotonic_clock::time_point
2976 oldest_remote_unreliable_monotonic_timestamps =
2977 monotonic_clock::time_point(chrono::nanoseconds(
2978 log_header->message()
2979 .oldest_remote_unreliable_monotonic_timestamps()
2980 ->Get(1)));
2981 const monotonic_clock::time_point
2982 oldest_local_unreliable_monotonic_timestamps =
2983 monotonic_clock::time_point(chrono::nanoseconds(
2984 log_header->message()
2985 .oldest_local_unreliable_monotonic_timestamps()
2986 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002987 const monotonic_clock::time_point
2988 oldest_remote_reliable_monotonic_timestamps =
2989 monotonic_clock::time_point(chrono::nanoseconds(
2990 log_header->message()
2991 .oldest_remote_reliable_monotonic_timestamps()
2992 ->Get(1)));
2993 const monotonic_clock::time_point
2994 oldest_local_reliable_monotonic_timestamps =
2995 monotonic_clock::time_point(chrono::nanoseconds(
2996 log_header->message()
2997 .oldest_local_reliable_monotonic_timestamps()
2998 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002999 const monotonic_clock::time_point
3000 oldest_logger_remote_unreliable_monotonic_timestamps =
3001 monotonic_clock::time_point(chrono::nanoseconds(
3002 log_header->message()
3003 .oldest_logger_remote_unreliable_monotonic_timestamps()
3004 ->Get(0)));
3005 const monotonic_clock::time_point
3006 oldest_logger_local_unreliable_monotonic_timestamps =
3007 monotonic_clock::time_point(chrono::nanoseconds(
3008 log_header->message()
3009 .oldest_logger_local_unreliable_monotonic_timestamps()
3010 ->Get(0)));
3011 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3012 monotonic_clock::max_time);
3013 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3014 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003015 switch (log_header->message().parts_index()) {
3016 case 0:
3017 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3018 monotonic_clock::max_time);
3019 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3020 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3021 monotonic_clock::max_time);
3022 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3023 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08003024 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3025 monotonic_clock::max_time);
3026 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3027 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003028 break;
3029 case 1:
3030 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3031 monotonic_clock::time_point(chrono::microseconds(90200)));
3032 EXPECT_EQ(oldest_local_monotonic_timestamps,
3033 monotonic_clock::time_point(chrono::microseconds(90350)));
3034 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3035 monotonic_clock::time_point(chrono::microseconds(90200)));
3036 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3037 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003038 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3039 monotonic_clock::max_time);
3040 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3041 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003042 break;
3043 case 2:
3044 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003045 monotonic_clock::time_point(chrono::microseconds(90200)))
3046 << file;
3047 EXPECT_EQ(oldest_local_monotonic_timestamps,
3048 monotonic_clock::time_point(chrono::microseconds(90350)))
3049 << file;
3050 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3051 monotonic_clock::time_point(chrono::microseconds(90200)))
3052 << file;
3053 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3054 monotonic_clock::time_point(chrono::microseconds(90350)))
3055 << file;
3056 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3057 monotonic_clock::time_point(chrono::microseconds(100000)))
3058 << file;
3059 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3060 monotonic_clock::time_point(chrono::microseconds(100150)))
3061 << file;
3062 break;
3063 case 3:
3064 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003065 monotonic_clock::time_point(chrono::milliseconds(1323) +
3066 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003067 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003068 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003069 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003070 monotonic_clock::time_point(chrono::milliseconds(1323) +
3071 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003072 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3073 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003074 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3075 monotonic_clock::max_time)
3076 << file;
3077 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3078 monotonic_clock::max_time)
3079 << file;
3080 break;
3081 case 4:
3082 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3083 monotonic_clock::time_point(chrono::milliseconds(1323) +
3084 chrono::microseconds(200)));
3085 EXPECT_EQ(oldest_local_monotonic_timestamps,
3086 monotonic_clock::time_point(chrono::microseconds(10100350)));
3087 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3088 monotonic_clock::time_point(chrono::milliseconds(1323) +
3089 chrono::microseconds(200)));
3090 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3091 monotonic_clock::time_point(chrono::microseconds(10100350)));
3092 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3093 monotonic_clock::time_point(chrono::microseconds(1423000)))
3094 << file;
3095 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3096 monotonic_clock::time_point(chrono::microseconds(10200150)))
3097 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07003098 break;
3099 default:
3100 FAIL();
3101 break;
3102 }
3103 }
3104
Austin Schuh315b96b2020-12-11 21:21:12 -08003105 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07003106 {
3107 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08003108
Austin Schuh58646e22021-08-23 23:51:46 -07003109 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3110 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08003111
Austin Schuh58646e22021-08-23 23:51:46 -07003112 // This sends out the fetched messages and advances time to the start of
3113 // the log file.
3114 reader.Register(&log_reader_factory);
3115
3116 log_reader_factory.Run();
3117
3118 reader.Deregister();
3119 }
Austin Schuh315b96b2020-12-11 21:21:12 -08003120}
3121
Austin Schuh5e14d842022-01-21 12:02:15 -08003122// Tests that we can sort a log which only has timestamps from the remote
3123// because the local message_bridge_client failed to connect.
3124TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
3125 const UUID pi1_boot0 = UUID::Random();
3126 const UUID pi2_boot0 = UUID::Random();
3127 const UUID pi2_boot1 = UUID::Random();
3128 {
3129 CHECK_EQ(pi1_index_, 0u);
3130 CHECK_EQ(pi2_index_, 1u);
3131
3132 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
3133 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
3134 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
3135
3136 time_converter_.AddNextTimestamp(
3137 distributed_clock::epoch(),
3138 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3139 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
3140 time_converter_.AddNextTimestamp(
3141 distributed_clock::epoch() + reboot_time,
3142 {BootTimestamp::epoch() + reboot_time,
3143 BootTimestamp{
3144 .boot = 1,
3145 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
3146 }
3147 pi2_->Disconnect(pi1_->node());
3148
3149 std::vector<std::string> filenames;
3150 {
3151 LoggerState pi1_logger = MakeLogger(pi1_);
3152
3153 event_loop_factory_.RunFor(chrono::milliseconds(95));
3154 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3155 pi1_boot0);
3156 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3157 pi2_boot0);
3158
3159 StartLogger(&pi1_logger);
3160
3161 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3162
3163 VLOG(1) << "Reboot now!";
3164
3165 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3166 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3167 pi1_boot0);
3168 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3169 pi2_boot1);
3170 pi1_logger.AppendAllFilenames(&filenames);
3171 }
3172
Austin Schuhbfe6c572022-01-27 20:48:20 -08003173 std::sort(filenames.begin(), filenames.end());
3174
Austin Schuh5e14d842022-01-21 12:02:15 -08003175 // Confirm that our new oldest timestamps properly update as we reboot and
3176 // rotate.
3177 size_t timestamp_file_count = 0;
3178 for (const std::string &file : filenames) {
3179 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
3180 ReadHeader(file);
3181 CHECK(log_header);
3182
3183 if (log_header->message().has_configuration()) {
3184 continue;
3185 }
3186
3187 const monotonic_clock::time_point monotonic_start_time =
3188 monotonic_clock::time_point(
3189 chrono::nanoseconds(log_header->message().monotonic_start_time()));
3190 const UUID source_node_boot_uuid = UUID::FromString(
3191 log_header->message().source_node_boot_uuid()->string_view());
3192
3193 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
3194 ASSERT_EQ(
3195 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
3196 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
3197 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
3198 2u);
3199 ASSERT_TRUE(log_header->message()
3200 .has_oldest_remote_unreliable_monotonic_timestamps());
3201 ASSERT_EQ(log_header->message()
3202 .oldest_remote_unreliable_monotonic_timestamps()
3203 ->size(),
3204 2u);
3205 ASSERT_TRUE(log_header->message()
3206 .has_oldest_local_unreliable_monotonic_timestamps());
3207 ASSERT_EQ(log_header->message()
3208 .oldest_local_unreliable_monotonic_timestamps()
3209 ->size(),
3210 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003211 ASSERT_TRUE(log_header->message()
3212 .has_oldest_remote_reliable_monotonic_timestamps());
3213 ASSERT_EQ(log_header->message()
3214 .oldest_remote_reliable_monotonic_timestamps()
3215 ->size(),
3216 2u);
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003217 ASSERT_TRUE(
3218 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
Austin Schuhf5f99f32022-02-07 20:05:37 -08003219 ASSERT_EQ(log_header->message()
3220 .oldest_local_reliable_monotonic_timestamps()
3221 ->size(),
3222 2u);
3223
3224 ASSERT_TRUE(
3225 log_header->message()
3226 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
3227 ASSERT_EQ(log_header->message()
3228 .oldest_logger_remote_unreliable_monotonic_timestamps()
3229 ->size(),
3230 2u);
3231 ASSERT_TRUE(log_header->message()
3232 .has_oldest_logger_local_unreliable_monotonic_timestamps());
3233 ASSERT_EQ(log_header->message()
3234 .oldest_logger_local_unreliable_monotonic_timestamps()
3235 ->size(),
3236 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08003237
3238 if (log_header->message().node()->name()->string_view() != "pi1") {
3239 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
3240 std::string::npos);
3241
3242 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
3243 ReadNthMessage(file, 0);
3244 CHECK(msg);
3245
3246 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
3247 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
3248
3249 const monotonic_clock::time_point
3250 expected_oldest_local_monotonic_timestamps(
3251 chrono::nanoseconds(msg->message().monotonic_sent_time()));
3252 const monotonic_clock::time_point
3253 expected_oldest_remote_monotonic_timestamps(
3254 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003255 const monotonic_clock::time_point
3256 expected_oldest_timestamp_monotonic_timestamps(
3257 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08003258
3259 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
3260 monotonic_clock::min_time);
3261 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
3262 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003263 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
3264 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08003265
3266 ++timestamp_file_count;
3267 // Since the log file is from the perspective of the other node,
3268 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3269 monotonic_clock::time_point(chrono::nanoseconds(
3270 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3271 0)));
3272 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3273 monotonic_clock::time_point(chrono::nanoseconds(
3274 log_header->message().oldest_local_monotonic_timestamps()->Get(
3275 0)));
3276 const monotonic_clock::time_point
3277 oldest_remote_unreliable_monotonic_timestamps =
3278 monotonic_clock::time_point(chrono::nanoseconds(
3279 log_header->message()
3280 .oldest_remote_unreliable_monotonic_timestamps()
3281 ->Get(0)));
3282 const monotonic_clock::time_point
3283 oldest_local_unreliable_monotonic_timestamps =
3284 monotonic_clock::time_point(chrono::nanoseconds(
3285 log_header->message()
3286 .oldest_local_unreliable_monotonic_timestamps()
3287 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003288 const monotonic_clock::time_point
3289 oldest_remote_reliable_monotonic_timestamps =
3290 monotonic_clock::time_point(chrono::nanoseconds(
3291 log_header->message()
3292 .oldest_remote_reliable_monotonic_timestamps()
3293 ->Get(0)));
3294 const monotonic_clock::time_point
3295 oldest_local_reliable_monotonic_timestamps =
3296 monotonic_clock::time_point(chrono::nanoseconds(
3297 log_header->message()
3298 .oldest_local_reliable_monotonic_timestamps()
3299 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003300 const monotonic_clock::time_point
3301 oldest_logger_remote_unreliable_monotonic_timestamps =
3302 monotonic_clock::time_point(chrono::nanoseconds(
3303 log_header->message()
3304 .oldest_logger_remote_unreliable_monotonic_timestamps()
3305 ->Get(1)));
3306 const monotonic_clock::time_point
3307 oldest_logger_local_unreliable_monotonic_timestamps =
3308 monotonic_clock::time_point(chrono::nanoseconds(
3309 log_header->message()
3310 .oldest_logger_local_unreliable_monotonic_timestamps()
3311 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08003312
Austin Schuh01f3b392022-01-25 20:03:09 -08003313 const Channel *channel =
3314 event_loop_factory_.configuration()->channels()->Get(
3315 msg->message().channel_index());
3316 const Connection *connection = configuration::ConnectionToNode(
3317 channel, configuration::GetNode(
3318 event_loop_factory_.configuration(),
3319 log_header->message().node()->name()->string_view()));
3320
3321 const bool reliable = connection->time_to_live() == 0;
3322
Austin Schuhf5f99f32022-02-07 20:05:37 -08003323 SCOPED_TRACE(file);
3324 SCOPED_TRACE(aos::FlatbufferToJson(
3325 *log_header, {.multi_line = true, .max_vector_size = 100}));
3326
Austin Schuh01f3b392022-01-25 20:03:09 -08003327 if (shared()) {
3328 // Confirm that the oldest timestamps match what we expect. Based on
3329 // what we are doing, we know that the oldest time is the first
3330 // message's time.
3331 //
3332 // This makes the test robust to both the split and combined config
3333 // tests.
3334 switch (log_header->message().parts_index()) {
3335 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08003336 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3337 expected_oldest_remote_monotonic_timestamps);
3338 EXPECT_EQ(oldest_local_monotonic_timestamps,
3339 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003340 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003341 expected_oldest_local_monotonic_timestamps)
3342 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003343 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003344 expected_oldest_timestamp_monotonic_timestamps)
3345 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003346
Austin Schuh01f3b392022-01-25 20:03:09 -08003347 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003348 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3349 expected_oldest_remote_monotonic_timestamps);
3350 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3351 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08003352 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3353 monotonic_clock::max_time);
3354 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3355 monotonic_clock::max_time);
3356 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003357 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3358 monotonic_clock::max_time);
3359 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3360 monotonic_clock::max_time);
3361 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3362 expected_oldest_remote_monotonic_timestamps);
3363 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3364 expected_oldest_local_monotonic_timestamps);
3365 }
3366 break;
3367 case 1:
3368 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3369 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3370 EXPECT_EQ(oldest_local_monotonic_timestamps,
3371 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003372 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3373 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3374 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3375 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003376 if (reliable) {
3377 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3378 expected_oldest_remote_monotonic_timestamps);
3379 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3380 expected_oldest_local_monotonic_timestamps);
3381 EXPECT_EQ(
3382 oldest_remote_unreliable_monotonic_timestamps,
3383 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3384 EXPECT_EQ(
3385 oldest_local_unreliable_monotonic_timestamps,
3386 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3387 } else {
3388 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3389 monotonic_clock::max_time);
3390 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3391 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003392 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3393 expected_oldest_remote_monotonic_timestamps);
3394 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3395 expected_oldest_local_monotonic_timestamps);
3396 }
3397 break;
3398 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003399 EXPECT_EQ(
3400 oldest_remote_monotonic_timestamps,
3401 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3402 EXPECT_EQ(
3403 oldest_local_monotonic_timestamps,
3404 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003405 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003406 expected_oldest_local_monotonic_timestamps)
3407 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003408 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003409 expected_oldest_timestamp_monotonic_timestamps)
3410 << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003411 if (reliable) {
3412 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3413 expected_oldest_remote_monotonic_timestamps);
3414 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3415 expected_oldest_local_monotonic_timestamps);
3416 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3417 monotonic_clock::max_time);
3418 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3419 monotonic_clock::max_time);
3420 } else {
3421 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3422 monotonic_clock::max_time);
3423 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3424 monotonic_clock::max_time);
3425 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3426 expected_oldest_remote_monotonic_timestamps);
3427 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3428 expected_oldest_local_monotonic_timestamps);
3429 }
3430 break;
3431
3432 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003433 EXPECT_EQ(
3434 oldest_remote_monotonic_timestamps,
3435 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3436 EXPECT_EQ(
3437 oldest_local_monotonic_timestamps,
3438 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3439 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3440 expected_oldest_remote_monotonic_timestamps);
3441 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3442 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003443 EXPECT_EQ(
3444 oldest_logger_remote_unreliable_monotonic_timestamps,
3445 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3446 EXPECT_EQ(
3447 oldest_logger_local_unreliable_monotonic_timestamps,
3448 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003449 break;
3450 default:
3451 FAIL();
3452 break;
3453 }
3454
3455 switch (log_header->message().parts_index()) {
3456 case 0:
3457 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3458 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3459 break;
3460 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003461 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003462 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3463 break;
3464 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003465 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3466 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3467 break;
3468 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003469 if (shared()) {
3470 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3471 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003472 break;
3473 }
3474 [[fallthrough]];
3475 default:
3476 FAIL();
3477 break;
3478 }
3479 } else {
3480 switch (log_header->message().parts_index()) {
3481 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003482 if (reliable) {
3483 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3484 monotonic_clock::max_time);
3485 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3486 monotonic_clock::max_time);
3487 EXPECT_EQ(
3488 oldest_logger_remote_unreliable_monotonic_timestamps,
3489 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3490 << file;
3491 EXPECT_EQ(
3492 oldest_logger_local_unreliable_monotonic_timestamps,
3493 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3494 << file;
3495 } else {
3496 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3497 expected_oldest_remote_monotonic_timestamps);
3498 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3499 expected_oldest_local_monotonic_timestamps);
3500 EXPECT_EQ(
3501 oldest_logger_remote_unreliable_monotonic_timestamps,
3502 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3503 << file;
3504 EXPECT_EQ(
3505 oldest_logger_local_unreliable_monotonic_timestamps,
3506 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3507 << file;
3508 }
3509 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003510 case 1:
3511 if (reliable) {
3512 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3513 monotonic_clock::max_time);
3514 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3515 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003516 EXPECT_EQ(
3517 oldest_logger_remote_unreliable_monotonic_timestamps,
3518 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3519 EXPECT_EQ(
3520 oldest_logger_local_unreliable_monotonic_timestamps,
3521 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003522 } else {
3523 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3524 expected_oldest_remote_monotonic_timestamps);
3525 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3526 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003527 EXPECT_EQ(
3528 oldest_logger_remote_unreliable_monotonic_timestamps,
3529 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3530 EXPECT_EQ(
3531 oldest_logger_local_unreliable_monotonic_timestamps,
3532 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003533 }
3534 break;
3535 default:
3536 FAIL();
3537 break;
3538 }
3539
3540 switch (log_header->message().parts_index()) {
3541 case 0:
3542 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3543 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3544 break;
3545 case 1:
3546 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3547 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3548 break;
3549 default:
3550 FAIL();
3551 break;
3552 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003553 }
3554
3555 continue;
3556 }
3557 EXPECT_EQ(
3558 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3559 monotonic_clock::max_time.time_since_epoch().count());
3560 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3561 monotonic_clock::max_time.time_since_epoch().count());
3562 EXPECT_EQ(log_header->message()
3563 .oldest_remote_unreliable_monotonic_timestamps()
3564 ->Get(0),
3565 monotonic_clock::max_time.time_since_epoch().count());
3566 EXPECT_EQ(log_header->message()
3567 .oldest_local_unreliable_monotonic_timestamps()
3568 ->Get(0),
3569 monotonic_clock::max_time.time_since_epoch().count());
3570
3571 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3572 monotonic_clock::time_point(chrono::nanoseconds(
3573 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3574 1)));
3575 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3576 monotonic_clock::time_point(chrono::nanoseconds(
3577 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3578 const monotonic_clock::time_point
3579 oldest_remote_unreliable_monotonic_timestamps =
3580 monotonic_clock::time_point(chrono::nanoseconds(
3581 log_header->message()
3582 .oldest_remote_unreliable_monotonic_timestamps()
3583 ->Get(1)));
3584 const monotonic_clock::time_point
3585 oldest_local_unreliable_monotonic_timestamps =
3586 monotonic_clock::time_point(chrono::nanoseconds(
3587 log_header->message()
3588 .oldest_local_unreliable_monotonic_timestamps()
3589 ->Get(1)));
3590 switch (log_header->message().parts_index()) {
3591 case 0:
3592 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3593 monotonic_clock::max_time);
3594 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3595 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3596 monotonic_clock::max_time);
3597 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3598 monotonic_clock::max_time);
3599 break;
3600 default:
3601 FAIL();
3602 break;
3603 }
3604 }
3605
Austin Schuh01f3b392022-01-25 20:03:09 -08003606 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003607 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003608 } else {
3609 EXPECT_EQ(timestamp_file_count, 4u);
3610 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003611
Austin Schuhe2373e22022-01-21 12:25:17 -08003612 // Confirm that we can actually sort the resulting log and read it.
3613 {
3614 LogReader reader(SortParts(filenames));
3615
3616 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3617 log_reader_factory.set_send_delay(chrono::microseconds(0));
3618
3619 // This sends out the fetched messages and advances time to the start of
3620 // the log file.
3621 reader.Register(&log_reader_factory);
3622
3623 log_reader_factory.Run();
3624
3625 reader.Deregister();
3626 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003627}
3628
Austin Schuhc9049732020-12-21 22:27:15 -08003629// Tests that we properly handle one direction of message_bridge being
3630// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003631TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003632 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003633 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003634 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003635
3636 time_converter_.AddMonotonic(
3637 {chrono::milliseconds(10000),
3638 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003639 {
3640 LoggerState pi1_logger = MakeLogger(pi1_);
3641
3642 event_loop_factory_.RunFor(chrono::milliseconds(95));
3643
3644 StartLogger(&pi1_logger);
3645
3646 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3647 }
3648
3649 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3650 // to confirm the right thing happened.
3651 ConfirmReadable(pi1_single_direction_logfiles_);
3652}
3653
3654// Tests that we properly handle one direction of message_bridge being
3655// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003656TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003657 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003658 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003659 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003660
3661 time_converter_.AddMonotonic(
3662 {chrono::milliseconds(10000),
3663 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3664 {
3665 LoggerState pi1_logger = MakeLogger(pi1_);
3666
3667 event_loop_factory_.RunFor(chrono::milliseconds(95));
3668
3669 StartLogger(&pi1_logger);
3670
3671 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3672 }
3673
3674 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3675 // to confirm the right thing happened.
3676 ConfirmReadable(pi1_single_direction_logfiles_);
3677}
3678
Austin Schuhe9f00232021-09-16 18:04:23 -07003679// Tests that we explode if someone passes in a part file twice with a better
3680// error than an out of order error.
3681TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3682 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003683 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003684 {
3685 LoggerState pi1_logger = MakeLogger(pi1_);
3686
3687 event_loop_factory_.RunFor(chrono::milliseconds(95));
3688
3689 StartLogger(&pi1_logger);
3690
3691 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3692 }
3693
3694 std::vector<std::string> duplicates;
3695 for (const std::string &f : pi1_single_direction_logfiles_) {
3696 duplicates.emplace_back(f);
3697 duplicates.emplace_back(f);
3698 }
3699 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3700}
3701
Austin Schuh22cf7862022-09-19 19:09:42 -07003702// Tests that we explode if someone loses a part out of the middle of a log.
3703TEST_P(MultinodeLoggerTest, MissingPartsFromMiddle) {
3704 time_converter_.AddMonotonic(
3705 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3706 {
3707 LoggerState pi1_logger = MakeLogger(pi1_);
3708
3709 event_loop_factory_.RunFor(chrono::milliseconds(95));
3710
Austin Schuh22cf7862022-09-19 19:09:42 -07003711 StartLogger(&pi1_logger);
3712 aos::monotonic_clock::time_point last_rotation_time =
3713 pi1_logger.event_loop->monotonic_now();
3714 pi1_logger.logger->set_on_logged_period([&] {
3715 const auto now = pi1_logger.event_loop->monotonic_now();
3716 if (now > last_rotation_time + std::chrono::seconds(5)) {
3717 pi1_logger.logger->Rotate();
3718 last_rotation_time = now;
3719 }
3720 });
3721
3722 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3723 }
3724
3725 std::vector<std::string> missing_parts;
3726
3727 missing_parts.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
3728 missing_parts.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
3729 missing_parts.emplace_back(absl::StrCat(
3730 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
3731
3732 EXPECT_DEATH({ SortParts(missing_parts); },
3733 "Broken log, missing part files between");
3734}
3735
Austin Schuh87dd3832021-01-01 23:07:31 -08003736// Tests that we properly handle a dead node. Do this by just disconnecting it
3737// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003738TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003739 pi1_->Disconnect(pi2_->node());
3740 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003741 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003742 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003743 {
3744 LoggerState pi1_logger = MakeLogger(pi1_);
3745
3746 event_loop_factory_.RunFor(chrono::milliseconds(95));
3747
3748 StartLogger(&pi1_logger);
3749
3750 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3751 }
3752
3753 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3754 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003755 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003756}
3757
Austin Schuhcdd90272021-03-15 12:46:16 -07003758constexpr std::string_view kCombinedConfigSha1(
James Kuszmaul65541cb2022-11-08 14:53:47 -08003759 "5d73fe35bacaa59d24f8f0c1a806fe10b783b0fcc80809ee30a9db824e82538b");
Austin Schuhcdd90272021-03-15 12:46:16 -07003760constexpr std::string_view kSplitConfigSha1(
James Kuszmaul65541cb2022-11-08 14:53:47 -08003761 "f25e8f6f90d61f41c41517e652300566228b077e44cd86f1af2af4a9bed31ad4");
James Kuszmaul53da7f32022-09-11 11:11:55 -07003762constexpr std::string_view kReloggedSplitConfigSha1(
James Kuszmaul65541cb2022-11-08 14:53:47 -08003763 "f1fabd629bdf8735c3d81bc791d7a454e8e636951c26cba6426545cbc97f911f");
Austin Schuhcdd90272021-03-15 12:46:16 -07003764
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003765INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003766 All, MultinodeLoggerTest,
James Kuszmaul53da7f32022-09-11 11:11:55 -07003767 ::testing::Combine(
3768 ::testing::Values(
3769 ConfigParams{"multinode_pingpong_combined_config.json", true,
3770 kCombinedConfigSha1, kCombinedConfigSha1},
3771 ConfigParams{"multinode_pingpong_split_config.json", false,
3772 kSplitConfigSha1, kReloggedSplitConfigSha1}),
3773 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003774
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003775INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003776 All, MultinodeLoggerDeathTest,
James Kuszmaul53da7f32022-09-11 11:11:55 -07003777 ::testing::Combine(
3778 ::testing::Values(
3779 ConfigParams{"multinode_pingpong_combined_config.json", true,
3780 kCombinedConfigSha1, kCombinedConfigSha1},
3781 ConfigParams{"multinode_pingpong_split_config.json", false,
3782 kSplitConfigSha1, kReloggedSplitConfigSha1}),
3783 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003784
Austin Schuh5b728b72021-06-16 14:57:15 -07003785// Tests that we can relog with a different config. This makes most sense when
3786// you are trying to edit a log and want to use channel renaming + the original
3787// config in the new log.
3788TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3789 time_converter_.StartEqual();
3790 {
3791 LoggerState pi1_logger = MakeLogger(pi1_);
3792 LoggerState pi2_logger = MakeLogger(pi2_);
3793
3794 event_loop_factory_.RunFor(chrono::milliseconds(95));
3795
3796 StartLogger(&pi1_logger);
3797 StartLogger(&pi2_logger);
3798
3799 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3800 }
3801
3802 LogReader reader(SortParts(logfiles_));
3803 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3804
3805 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3806 log_reader_factory.set_send_delay(chrono::microseconds(0));
3807
3808 // This sends out the fetched messages and advances time to the start of the
3809 // log file.
3810 reader.Register(&log_reader_factory);
3811
3812 const Node *pi1 =
3813 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3814 const Node *pi2 =
3815 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3816
3817 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3818 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3819 LOG(INFO) << "now pi1 "
3820 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3821 LOG(INFO) << "now pi2 "
3822 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3823
3824 EXPECT_THAT(reader.LoggedNodes(),
3825 ::testing::ElementsAre(
3826 configuration::GetNode(reader.logged_configuration(), pi1),
3827 configuration::GetNode(reader.logged_configuration(), pi2)));
3828
3829 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3830
3831 // And confirm we can re-create a log again, while checking the contents.
3832 std::vector<std::string> log_files;
3833 {
3834 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003835 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003836 &log_reader_factory, reader.logged_configuration());
3837 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003838 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003839 &log_reader_factory, reader.logged_configuration());
3840
Austin Schuh3e20c692021-11-16 20:43:16 -08003841 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3842 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003843
3844 log_reader_factory.Run();
3845
3846 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3847 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3848 }
3849 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3850 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3851 }
3852 }
3853
3854 reader.Deregister();
3855
3856 // And verify that we can run the LogReader over the relogged files without
3857 // hitting any fatal errors.
3858 {
3859 LogReader relogged_reader(SortParts(log_files));
3860 relogged_reader.Register();
3861
3862 relogged_reader.event_loop_factory()->Run();
3863 }
3864}
Austin Schuha04efed2021-01-24 18:04:20 -08003865
Austin Schuh3e20c692021-11-16 20:43:16 -08003866// Tests that we properly replay a log where the start time for a node is before
3867// any data on the node. This can happen if the logger starts before data is
3868// published. While the scenario below is a bit convoluted, we have seen logs
3869// like this generated out in the wild.
3870TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3871 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3872 aos::configuration::ReadConfig(ArtifactPath(
3873 "aos/events/logging/multinode_pingpong_split3_config.json"));
3874 message_bridge::TestingTimeConverter time_converter(
3875 configuration::NodesCount(&config.message()));
3876 SimulatedEventLoopFactory event_loop_factory(&config.message());
3877 event_loop_factory.SetTimeConverter(&time_converter);
3878 NodeEventLoopFactory *const pi1 =
3879 event_loop_factory.GetNodeEventLoopFactory("pi1");
3880 const size_t pi1_index = configuration::GetNodeIndex(
3881 event_loop_factory.configuration(), pi1->node());
3882 NodeEventLoopFactory *const pi2 =
3883 event_loop_factory.GetNodeEventLoopFactory("pi2");
3884 const size_t pi2_index = configuration::GetNodeIndex(
3885 event_loop_factory.configuration(), pi2->node());
3886 NodeEventLoopFactory *const pi3 =
3887 event_loop_factory.GetNodeEventLoopFactory("pi3");
3888 const size_t pi3_index = configuration::GetNodeIndex(
3889 event_loop_factory.configuration(), pi3->node());
3890
3891 const std::string kLogfile1_1 =
3892 aos::testing::TestTmpDir() + "/multi_logfile1/";
3893 const std::string kLogfile2_1 =
3894 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3895 const std::string kLogfile2_2 =
3896 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3897 const std::string kLogfile3_1 =
3898 aos::testing::TestTmpDir() + "/multi_logfile3/";
3899 util::UnlinkRecursive(kLogfile1_1);
3900 util::UnlinkRecursive(kLogfile2_1);
3901 util::UnlinkRecursive(kLogfile2_2);
3902 util::UnlinkRecursive(kLogfile3_1);
3903 const UUID pi1_boot0 = UUID::Random();
3904 const UUID pi2_boot0 = UUID::Random();
3905 const UUID pi2_boot1 = UUID::Random();
3906 const UUID pi3_boot0 = UUID::Random();
3907 {
3908 CHECK_EQ(pi1_index, 0u);
3909 CHECK_EQ(pi2_index, 1u);
3910 CHECK_EQ(pi3_index, 2u);
3911
3912 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3913 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3914 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3915 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3916
3917 time_converter.AddNextTimestamp(
3918 distributed_clock::epoch(),
3919 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3920 BootTimestamp::epoch()});
3921 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3922 time_converter.AddNextTimestamp(
3923 distributed_clock::epoch() + reboot_time,
3924 {BootTimestamp::epoch() + reboot_time,
3925 BootTimestamp{
3926 .boot = 1,
3927 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3928 BootTimestamp::epoch() + reboot_time});
3929 }
3930
3931 // Make everything perfectly quiet.
3932 event_loop_factory.SkipTimingReport();
3933 event_loop_factory.DisableStatistics();
3934
3935 std::vector<std::string> filenames;
3936 {
3937 LoggerState pi1_logger = LoggerState::MakeLogger(
3938 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3939 LoggerState pi3_logger = LoggerState::MakeLogger(
3940 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3941 {
3942 // And now start the logger.
3943 LoggerState pi2_logger = LoggerState::MakeLogger(
3944 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3945
3946 event_loop_factory.RunFor(chrono::milliseconds(1000));
3947
3948 pi1_logger.StartLogger(kLogfile1_1);
3949 pi3_logger.StartLogger(kLogfile3_1);
3950 pi2_logger.StartLogger(kLogfile2_1);
3951
3952 event_loop_factory.RunFor(chrono::milliseconds(10000));
3953
3954 // Now that we've got a start time in the past, turn on data.
3955 event_loop_factory.EnableStatistics();
3956 std::unique_ptr<aos::EventLoop> ping_event_loop =
3957 pi1->MakeEventLoop("ping");
3958 Ping ping(ping_event_loop.get());
3959
3960 pi2->AlwaysStart<Pong>("pong");
3961
3962 event_loop_factory.RunFor(chrono::milliseconds(3000));
3963
3964 pi2_logger.AppendAllFilenames(&filenames);
3965
3966 // Stop logging on pi2 before rebooting and completely shut off all
3967 // messages on pi2.
3968 pi2->DisableStatistics();
3969 pi1->Disconnect(pi2->node());
3970 pi2->Disconnect(pi1->node());
3971 }
3972 event_loop_factory.RunFor(chrono::milliseconds(7000));
3973 // pi2 now reboots.
3974 {
3975 event_loop_factory.RunFor(chrono::milliseconds(1000));
3976
3977 // Start logging again on pi2 after it is up.
3978 LoggerState pi2_logger = LoggerState::MakeLogger(
3979 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3980 pi2_logger.StartLogger(kLogfile2_2);
3981
3982 event_loop_factory.RunFor(chrono::milliseconds(10000));
3983 // And, now that we have a start time in the log, turn data back on.
3984 pi2->EnableStatistics();
3985 pi1->Connect(pi2->node());
3986 pi2->Connect(pi1->node());
3987
3988 pi2->AlwaysStart<Pong>("pong");
3989 std::unique_ptr<aos::EventLoop> ping_event_loop =
3990 pi1->MakeEventLoop("ping");
3991 Ping ping(ping_event_loop.get());
3992
3993 event_loop_factory.RunFor(chrono::milliseconds(3000));
3994
3995 pi2_logger.AppendAllFilenames(&filenames);
3996 }
3997
3998 pi1_logger.AppendAllFilenames(&filenames);
3999 pi3_logger.AppendAllFilenames(&filenames);
4000 }
4001
4002 // Confirm that we can parse the result. LogReader has enough internal CHECKs
4003 // to confirm the right thing happened.
4004 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08004005 auto result = ConfirmReadable(filenames);
4006 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
4007 chrono::seconds(1)));
4008 EXPECT_THAT(result[0].second,
4009 ::testing::ElementsAre(realtime_clock::epoch() +
4010 chrono::microseconds(34990350)));
4011
4012 EXPECT_THAT(result[1].first,
4013 ::testing::ElementsAre(
4014 realtime_clock::epoch() + chrono::seconds(1),
4015 realtime_clock::epoch() + chrono::microseconds(3323000)));
4016 EXPECT_THAT(result[1].second,
4017 ::testing::ElementsAre(
4018 realtime_clock::epoch() + chrono::microseconds(13990200),
4019 realtime_clock::epoch() + chrono::microseconds(16313200)));
4020
4021 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
4022 chrono::seconds(1)));
4023 EXPECT_THAT(result[2].second,
4024 ::testing::ElementsAre(realtime_clock::epoch() +
4025 chrono::microseconds(34900150)));
Austin Schuh3e20c692021-11-16 20:43:16 -08004026}
4027
Austin Schuh5dd22842021-11-17 16:09:39 -08004028// Tests that local data before remote data after reboot is properly replayed.
4029// We only trigger a reboot in the timestamp interpolation function when solving
4030// the timestamp problem when we actually have a point in the function. This
4031// originally only happened when a point passes the noncausal filter. At the
4032// start of time for the second boot, if we aren't careful, we will have
4033// messages which need to be published at times before the boot. This happens
4034// when a local message is in the log before a forwarded message, so there is no
4035// point in the interpolation function. This delays the reboot. So, we need to
4036// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08004037TEST(MultinodeRebootLoggerTest,
4038 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08004039 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4040 aos::configuration::ReadConfig(ArtifactPath(
4041 "aos/events/logging/multinode_pingpong_split3_config.json"));
4042 message_bridge::TestingTimeConverter time_converter(
4043 configuration::NodesCount(&config.message()));
4044 SimulatedEventLoopFactory event_loop_factory(&config.message());
4045 event_loop_factory.SetTimeConverter(&time_converter);
4046 NodeEventLoopFactory *const pi1 =
4047 event_loop_factory.GetNodeEventLoopFactory("pi1");
4048 const size_t pi1_index = configuration::GetNodeIndex(
4049 event_loop_factory.configuration(), pi1->node());
4050 NodeEventLoopFactory *const pi2 =
4051 event_loop_factory.GetNodeEventLoopFactory("pi2");
4052 const size_t pi2_index = configuration::GetNodeIndex(
4053 event_loop_factory.configuration(), pi2->node());
4054 NodeEventLoopFactory *const pi3 =
4055 event_loop_factory.GetNodeEventLoopFactory("pi3");
4056 const size_t pi3_index = configuration::GetNodeIndex(
4057 event_loop_factory.configuration(), pi3->node());
4058
4059 const std::string kLogfile1_1 =
4060 aos::testing::TestTmpDir() + "/multi_logfile1/";
4061 const std::string kLogfile2_1 =
4062 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4063 const std::string kLogfile2_2 =
4064 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4065 const std::string kLogfile3_1 =
4066 aos::testing::TestTmpDir() + "/multi_logfile3/";
4067 util::UnlinkRecursive(kLogfile1_1);
4068 util::UnlinkRecursive(kLogfile2_1);
4069 util::UnlinkRecursive(kLogfile2_2);
4070 util::UnlinkRecursive(kLogfile3_1);
4071 const UUID pi1_boot0 = UUID::Random();
4072 const UUID pi2_boot0 = UUID::Random();
4073 const UUID pi2_boot1 = UUID::Random();
4074 const UUID pi3_boot0 = UUID::Random();
4075 {
4076 CHECK_EQ(pi1_index, 0u);
4077 CHECK_EQ(pi2_index, 1u);
4078 CHECK_EQ(pi3_index, 2u);
4079
4080 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
4081 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
4082 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
4083 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
4084
4085 time_converter.AddNextTimestamp(
4086 distributed_clock::epoch(),
4087 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4088 BootTimestamp::epoch()});
4089 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4090 time_converter.AddNextTimestamp(
4091 distributed_clock::epoch() + reboot_time,
4092 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08004093 BootTimestamp{.boot = 1,
4094 .time = monotonic_clock::epoch() + reboot_time +
4095 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08004096 BootTimestamp::epoch() + reboot_time});
4097 }
4098
4099 std::vector<std::string> filenames;
4100 {
4101 LoggerState pi1_logger = LoggerState::MakeLogger(
4102 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4103 LoggerState pi3_logger = LoggerState::MakeLogger(
4104 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4105 {
4106 // And now start the logger.
4107 LoggerState pi2_logger = LoggerState::MakeLogger(
4108 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4109
4110 pi1_logger.StartLogger(kLogfile1_1);
4111 pi3_logger.StartLogger(kLogfile3_1);
4112 pi2_logger.StartLogger(kLogfile2_1);
4113
4114 event_loop_factory.RunFor(chrono::milliseconds(1005));
4115
4116 // Now that we've got a start time in the past, turn on data.
4117 std::unique_ptr<aos::EventLoop> ping_event_loop =
4118 pi1->MakeEventLoop("ping");
4119 Ping ping(ping_event_loop.get());
4120
4121 pi2->AlwaysStart<Pong>("pong");
4122
4123 event_loop_factory.RunFor(chrono::milliseconds(3000));
4124
4125 pi2_logger.AppendAllFilenames(&filenames);
4126
4127 // Disable any remote messages on pi2.
4128 pi1->Disconnect(pi2->node());
4129 pi2->Disconnect(pi1->node());
4130 }
4131 event_loop_factory.RunFor(chrono::milliseconds(995));
4132 // pi2 now reboots at 5 seconds.
4133 {
4134 event_loop_factory.RunFor(chrono::milliseconds(1000));
4135
4136 // Make local stuff happen before we start logging and connect the remote.
4137 pi2->AlwaysStart<Pong>("pong");
4138 std::unique_ptr<aos::EventLoop> ping_event_loop =
4139 pi1->MakeEventLoop("ping");
4140 Ping ping(ping_event_loop.get());
4141 event_loop_factory.RunFor(chrono::milliseconds(1005));
4142
4143 // Start logging again on pi2 after it is up.
4144 LoggerState pi2_logger = LoggerState::MakeLogger(
4145 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4146 pi2_logger.StartLogger(kLogfile2_2);
4147
4148 // And allow remote messages now that we have some local ones.
4149 pi1->Connect(pi2->node());
4150 pi2->Connect(pi1->node());
4151
4152 event_loop_factory.RunFor(chrono::milliseconds(1000));
4153
4154 event_loop_factory.RunFor(chrono::milliseconds(3000));
4155
4156 pi2_logger.AppendAllFilenames(&filenames);
4157 }
4158
4159 pi1_logger.AppendAllFilenames(&filenames);
4160 pi3_logger.AppendAllFilenames(&filenames);
4161 }
4162
4163 // Confirm that we can parse the result. LogReader has enough internal CHECKs
4164 // to confirm the right thing happened.
4165 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08004166 auto result = ConfirmReadable(filenames);
4167
4168 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4169 EXPECT_THAT(result[0].second,
4170 ::testing::ElementsAre(realtime_clock::epoch() +
4171 chrono::microseconds(11000350)));
4172
4173 EXPECT_THAT(result[1].first,
4174 ::testing::ElementsAre(
4175 realtime_clock::epoch(),
4176 realtime_clock::epoch() + chrono::microseconds(107005000)));
4177 EXPECT_THAT(result[1].second,
4178 ::testing::ElementsAre(
4179 realtime_clock::epoch() + chrono::microseconds(4000150),
4180 realtime_clock::epoch() + chrono::microseconds(111000200)));
4181
4182 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4183 EXPECT_THAT(result[2].second,
4184 ::testing::ElementsAre(realtime_clock::epoch() +
4185 chrono::microseconds(11000150)));
4186
4187 auto start_stop_result = ConfirmReadable(
4188 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4189 realtime_clock::epoch() + chrono::milliseconds(3000));
4190
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004191 EXPECT_THAT(
4192 start_stop_result[0].first,
4193 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4194 EXPECT_THAT(
4195 start_stop_result[0].second,
4196 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4197 EXPECT_THAT(
4198 start_stop_result[1].first,
4199 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4200 EXPECT_THAT(
4201 start_stop_result[1].second,
4202 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4203 EXPECT_THAT(
4204 start_stop_result[2].first,
4205 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4206 EXPECT_THAT(
4207 start_stop_result[2].second,
4208 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
Austin Schuh5dd22842021-11-17 16:09:39 -08004209}
4210
Austin Schuhe33c08d2022-02-03 18:15:21 -08004211// Tests that setting the start and stop flags across a reboot works as
4212// expected.
4213TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
4214 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4215 aos::configuration::ReadConfig(ArtifactPath(
4216 "aos/events/logging/multinode_pingpong_split3_config.json"));
4217 message_bridge::TestingTimeConverter time_converter(
4218 configuration::NodesCount(&config.message()));
4219 SimulatedEventLoopFactory event_loop_factory(&config.message());
4220 event_loop_factory.SetTimeConverter(&time_converter);
4221 NodeEventLoopFactory *const pi1 =
4222 event_loop_factory.GetNodeEventLoopFactory("pi1");
4223 const size_t pi1_index = configuration::GetNodeIndex(
4224 event_loop_factory.configuration(), pi1->node());
4225 NodeEventLoopFactory *const pi2 =
4226 event_loop_factory.GetNodeEventLoopFactory("pi2");
4227 const size_t pi2_index = configuration::GetNodeIndex(
4228 event_loop_factory.configuration(), pi2->node());
4229 NodeEventLoopFactory *const pi3 =
4230 event_loop_factory.GetNodeEventLoopFactory("pi3");
4231 const size_t pi3_index = configuration::GetNodeIndex(
4232 event_loop_factory.configuration(), pi3->node());
4233
4234 const std::string kLogfile1_1 =
4235 aos::testing::TestTmpDir() + "/multi_logfile1/";
4236 const std::string kLogfile2_1 =
4237 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4238 const std::string kLogfile2_2 =
4239 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4240 const std::string kLogfile3_1 =
4241 aos::testing::TestTmpDir() + "/multi_logfile3/";
4242 util::UnlinkRecursive(kLogfile1_1);
4243 util::UnlinkRecursive(kLogfile2_1);
4244 util::UnlinkRecursive(kLogfile2_2);
4245 util::UnlinkRecursive(kLogfile3_1);
4246 {
4247 CHECK_EQ(pi1_index, 0u);
4248 CHECK_EQ(pi2_index, 1u);
4249 CHECK_EQ(pi3_index, 2u);
4250
4251 time_converter.AddNextTimestamp(
4252 distributed_clock::epoch(),
4253 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4254 BootTimestamp::epoch()});
4255 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4256 time_converter.AddNextTimestamp(
4257 distributed_clock::epoch() + reboot_time,
4258 {BootTimestamp::epoch() + reboot_time,
4259 BootTimestamp{.boot = 1,
4260 .time = monotonic_clock::epoch() + reboot_time},
4261 BootTimestamp::epoch() + reboot_time});
4262 }
4263
4264 std::vector<std::string> filenames;
4265 {
4266 LoggerState pi1_logger = LoggerState::MakeLogger(
4267 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4268 LoggerState pi3_logger = LoggerState::MakeLogger(
4269 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4270 {
4271 // And now start the logger.
4272 LoggerState pi2_logger = LoggerState::MakeLogger(
4273 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4274
4275 pi1_logger.StartLogger(kLogfile1_1);
4276 pi3_logger.StartLogger(kLogfile3_1);
4277 pi2_logger.StartLogger(kLogfile2_1);
4278
4279 event_loop_factory.RunFor(chrono::milliseconds(1005));
4280
4281 // Now that we've got a start time in the past, turn on data.
4282 std::unique_ptr<aos::EventLoop> ping_event_loop =
4283 pi1->MakeEventLoop("ping");
4284 Ping ping(ping_event_loop.get());
4285
4286 pi2->AlwaysStart<Pong>("pong");
4287
4288 event_loop_factory.RunFor(chrono::milliseconds(3000));
4289
4290 pi2_logger.AppendAllFilenames(&filenames);
4291 }
4292 event_loop_factory.RunFor(chrono::milliseconds(995));
4293 // pi2 now reboots at 5 seconds.
4294 {
4295 event_loop_factory.RunFor(chrono::milliseconds(1000));
4296
4297 // Make local stuff happen before we start logging and connect the remote.
4298 pi2->AlwaysStart<Pong>("pong");
4299 std::unique_ptr<aos::EventLoop> ping_event_loop =
4300 pi1->MakeEventLoop("ping");
4301 Ping ping(ping_event_loop.get());
4302 event_loop_factory.RunFor(chrono::milliseconds(5));
4303
4304 // Start logging again on pi2 after it is up.
4305 LoggerState pi2_logger = LoggerState::MakeLogger(
4306 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4307 pi2_logger.StartLogger(kLogfile2_2);
4308
4309 event_loop_factory.RunFor(chrono::milliseconds(5000));
4310
4311 pi2_logger.AppendAllFilenames(&filenames);
4312 }
4313
4314 pi1_logger.AppendAllFilenames(&filenames);
4315 pi3_logger.AppendAllFilenames(&filenames);
4316 }
4317
4318 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4319 auto result = ConfirmReadable(filenames);
4320
4321 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4322 EXPECT_THAT(result[0].second,
4323 ::testing::ElementsAre(realtime_clock::epoch() +
4324 chrono::microseconds(11000350)));
4325
4326 EXPECT_THAT(result[1].first,
4327 ::testing::ElementsAre(
4328 realtime_clock::epoch(),
4329 realtime_clock::epoch() + chrono::microseconds(6005000)));
4330 EXPECT_THAT(result[1].second,
4331 ::testing::ElementsAre(
4332 realtime_clock::epoch() + chrono::microseconds(4900150),
4333 realtime_clock::epoch() + chrono::microseconds(11000200)));
4334
4335 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4336 EXPECT_THAT(result[2].second,
4337 ::testing::ElementsAre(realtime_clock::epoch() +
4338 chrono::microseconds(11000150)));
4339
4340 // Confirm we observed the correct start and stop times. We should see the
4341 // reboot here.
4342 auto start_stop_result = ConfirmReadable(
4343 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4344 realtime_clock::epoch() + chrono::milliseconds(8000));
4345
4346 EXPECT_THAT(
4347 start_stop_result[0].first,
4348 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4349 EXPECT_THAT(
4350 start_stop_result[0].second,
4351 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4352 EXPECT_THAT(start_stop_result[1].first,
4353 ::testing::ElementsAre(
4354 realtime_clock::epoch() + chrono::seconds(2),
4355 realtime_clock::epoch() + chrono::microseconds(6005000)));
4356 EXPECT_THAT(start_stop_result[1].second,
4357 ::testing::ElementsAre(
4358 realtime_clock::epoch() + chrono::microseconds(4900150),
4359 realtime_clock::epoch() + chrono::seconds(8)));
4360 EXPECT_THAT(
4361 start_stop_result[2].first,
4362 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4363 EXPECT_THAT(
4364 start_stop_result[2].second,
4365 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4366}
Austin Schuh5dd22842021-11-17 16:09:39 -08004367
Austin Schuh5c770fa2022-03-11 06:57:22 -08004368// Tests that we properly handle one direction being down.
4369TEST(MissingDirectionTest, OneDirection) {
4370 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4371 aos::configuration::ReadConfig(ArtifactPath(
4372 "aos/events/logging/multinode_pingpong_split4_config.json"));
4373 message_bridge::TestingTimeConverter time_converter(
4374 configuration::NodesCount(&config.message()));
4375 SimulatedEventLoopFactory event_loop_factory(&config.message());
4376 event_loop_factory.SetTimeConverter(&time_converter);
4377
4378 NodeEventLoopFactory *const pi1 =
4379 event_loop_factory.GetNodeEventLoopFactory("pi1");
4380 const size_t pi1_index = configuration::GetNodeIndex(
4381 event_loop_factory.configuration(), pi1->node());
4382 NodeEventLoopFactory *const pi2 =
4383 event_loop_factory.GetNodeEventLoopFactory("pi2");
4384 const size_t pi2_index = configuration::GetNodeIndex(
4385 event_loop_factory.configuration(), pi2->node());
4386 std::vector<std::string> filenames;
4387
4388 {
4389 CHECK_EQ(pi1_index, 0u);
4390 CHECK_EQ(pi2_index, 1u);
4391
4392 time_converter.AddNextTimestamp(
4393 distributed_clock::epoch(),
4394 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4395
4396 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4397 time_converter.AddNextTimestamp(
4398 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004399 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuh5c770fa2022-03-11 06:57:22 -08004400 BootTimestamp::epoch() + reboot_time});
4401 }
4402
4403 const std::string kLogfile2_1 =
4404 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4405 const std::string kLogfile1_1 =
4406 aos::testing::TestTmpDir() + "/multi_logfile1.1/";
4407 util::UnlinkRecursive(kLogfile2_1);
4408 util::UnlinkRecursive(kLogfile1_1);
4409
4410 pi2->Disconnect(pi1->node());
4411
4412 pi1->AlwaysStart<Ping>("ping");
4413 pi2->AlwaysStart<Pong>("pong");
4414
4415 {
4416 LoggerState pi2_logger = LoggerState::MakeLogger(
4417 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4418
4419 event_loop_factory.RunFor(chrono::milliseconds(95));
4420
4421 pi2_logger.StartLogger(kLogfile2_1);
4422
4423 event_loop_factory.RunFor(chrono::milliseconds(6000));
4424
4425 pi2->Connect(pi1->node());
4426
4427 LoggerState pi1_logger = LoggerState::MakeLogger(
4428 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4429 pi1_logger.StartLogger(kLogfile1_1);
4430
4431 event_loop_factory.RunFor(chrono::milliseconds(5000));
4432 pi1_logger.AppendAllFilenames(&filenames);
4433 pi2_logger.AppendAllFilenames(&filenames);
4434 }
4435
4436 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4437 ConfirmReadable(filenames);
4438}
4439
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004440// Tests that we properly handle only one direction ever existing after a
4441// reboot.
4442TEST(MissingDirectionTest, OneDirectionAfterReboot) {
4443 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4444 aos::configuration::ReadConfig(ArtifactPath(
4445 "aos/events/logging/multinode_pingpong_split4_config.json"));
4446 message_bridge::TestingTimeConverter time_converter(
4447 configuration::NodesCount(&config.message()));
4448 SimulatedEventLoopFactory event_loop_factory(&config.message());
4449 event_loop_factory.SetTimeConverter(&time_converter);
4450
4451 NodeEventLoopFactory *const pi1 =
4452 event_loop_factory.GetNodeEventLoopFactory("pi1");
4453 const size_t pi1_index = configuration::GetNodeIndex(
4454 event_loop_factory.configuration(), pi1->node());
4455 NodeEventLoopFactory *const pi2 =
4456 event_loop_factory.GetNodeEventLoopFactory("pi2");
4457 const size_t pi2_index = configuration::GetNodeIndex(
4458 event_loop_factory.configuration(), pi2->node());
4459 std::vector<std::string> filenames;
4460
4461 {
4462 CHECK_EQ(pi1_index, 0u);
4463 CHECK_EQ(pi2_index, 1u);
4464
4465 time_converter.AddNextTimestamp(
4466 distributed_clock::epoch(),
4467 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4468
4469 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4470 time_converter.AddNextTimestamp(
4471 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004472 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004473 BootTimestamp::epoch() + reboot_time});
4474 }
4475
4476 const std::string kLogfile2_1 =
4477 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4478 util::UnlinkRecursive(kLogfile2_1);
4479
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004480 pi1->AlwaysStart<Ping>("ping");
4481
4482 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4483 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4484 // second boot.
4485 {
4486 LoggerState pi2_logger = LoggerState::MakeLogger(
4487 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4488
4489 event_loop_factory.RunFor(chrono::milliseconds(95));
4490
4491 pi2_logger.StartLogger(kLogfile2_1);
4492
4493 event_loop_factory.RunFor(chrono::milliseconds(4000));
4494
4495 pi2->Disconnect(pi1->node());
4496
4497 event_loop_factory.RunFor(chrono::milliseconds(1000));
4498 pi1->AlwaysStart<Ping>("ping");
4499
4500 event_loop_factory.RunFor(chrono::milliseconds(5000));
4501 pi2_logger.AppendAllFilenames(&filenames);
4502 }
4503
4504 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4505 ConfirmReadable(filenames);
4506}
4507
4508// Tests that we properly handle only one direction ever existing after a reboot
4509// with only reliable data.
4510TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
4511 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4512 aos::configuration::ReadConfig(ArtifactPath(
4513 "aos/events/logging/multinode_pingpong_split4_reliable_config.json"));
4514 message_bridge::TestingTimeConverter time_converter(
4515 configuration::NodesCount(&config.message()));
4516 SimulatedEventLoopFactory event_loop_factory(&config.message());
4517 event_loop_factory.SetTimeConverter(&time_converter);
4518
4519 NodeEventLoopFactory *const pi1 =
4520 event_loop_factory.GetNodeEventLoopFactory("pi1");
4521 const size_t pi1_index = configuration::GetNodeIndex(
4522 event_loop_factory.configuration(), pi1->node());
4523 NodeEventLoopFactory *const pi2 =
4524 event_loop_factory.GetNodeEventLoopFactory("pi2");
4525 const size_t pi2_index = configuration::GetNodeIndex(
4526 event_loop_factory.configuration(), pi2->node());
4527 std::vector<std::string> filenames;
4528
4529 {
4530 CHECK_EQ(pi1_index, 0u);
4531 CHECK_EQ(pi2_index, 1u);
4532
4533 time_converter.AddNextTimestamp(
4534 distributed_clock::epoch(),
4535 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4536
4537 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4538 time_converter.AddNextTimestamp(
4539 distributed_clock::epoch() + reboot_time,
4540 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4541 BootTimestamp::epoch() + reboot_time});
4542 }
4543
4544 const std::string kLogfile2_1 =
4545 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4546 util::UnlinkRecursive(kLogfile2_1);
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004547
4548 pi1->AlwaysStart<Ping>("ping");
4549
4550 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4551 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4552 // second boot.
4553 {
4554 LoggerState pi2_logger = LoggerState::MakeLogger(
4555 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4556
4557 event_loop_factory.RunFor(chrono::milliseconds(95));
4558
4559 pi2_logger.StartLogger(kLogfile2_1);
4560
4561 event_loop_factory.RunFor(chrono::milliseconds(4000));
4562
4563 pi2->Disconnect(pi1->node());
4564
4565 event_loop_factory.RunFor(chrono::milliseconds(1000));
4566 pi1->AlwaysStart<Ping>("ping");
4567
4568 event_loop_factory.RunFor(chrono::milliseconds(5000));
4569 pi2_logger.AppendAllFilenames(&filenames);
4570 }
4571
4572 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4573 ConfirmReadable(filenames);
4574}
4575
Austin Schuhefba96d2022-06-24 13:22:18 -07004576// Tests that we properly handle what used to be a time violation in one
4577// direction. This can occur when one direction goes down after sending some
4578// data, but the other keeps working. The down direction ends up resolving to a
4579// straight line in the noncausal filter, where the direction which is still up
4580// can cross that line. Really, time progressed along just fine but we assumed
4581// that the offset was a line when it could have deviated by up to 1ms/second.
4582TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4583 std::vector<std::string> filenames;
4584
4585 CHECK_EQ(pi1_index_, 0u);
4586 CHECK_EQ(pi2_index_, 1u);
4587
4588 time_converter_.AddNextTimestamp(
4589 distributed_clock::epoch(),
4590 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4591
4592 const chrono::nanoseconds before_disconnect_duration =
4593 time_converter_.AddMonotonic(
4594 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4595
4596 const chrono::nanoseconds test_duration =
4597 time_converter_.AddMonotonic(
4598 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4599 time_converter_.AddMonotonic(
4600 {chrono::milliseconds(10000),
4601 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4602 time_converter_.AddMonotonic(
4603 {chrono::milliseconds(10000),
4604 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4605
4606 const std::string kLogfile =
4607 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4608 util::UnlinkRecursive(kLogfile);
4609
4610 {
4611 LoggerState pi2_logger = MakeLogger(pi2_);
4612 pi2_logger.StartLogger(kLogfile);
4613 event_loop_factory_.RunFor(before_disconnect_duration);
4614
4615 pi2_->Disconnect(pi1_->node());
4616
4617 event_loop_factory_.RunFor(test_duration);
4618 pi2_->Connect(pi1_->node());
4619
4620 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4621 pi2_logger.AppendAllFilenames(&filenames);
4622 }
4623
4624 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4625 ConfirmReadable(filenames);
4626}
4627
James Kuszmaul86e86c32022-07-21 17:39:47 -07004628// Tests that we can replay a logfile that has timestamps such that at least one
4629// node's epoch is at a positive distributed_clock (and thus will have to be
4630// booted after the other node(s)).
4631TEST_P(MultinodeLoggerTest, StartOneNodeBeforeOther) {
4632 std::vector<std::string> filenames;
4633
4634 CHECK_EQ(pi1_index_, 0u);
4635 CHECK_EQ(pi2_index_, 1u);
4636
4637 time_converter_.AddNextTimestamp(
4638 distributed_clock::epoch(),
4639 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4640
4641 const chrono::nanoseconds before_reboot_duration = chrono::milliseconds(1000);
4642 time_converter_.RebootAt(
4643 0, distributed_clock::time_point(before_reboot_duration));
4644
4645 const chrono::nanoseconds test_duration = time_converter_.AddMonotonic(
4646 {chrono::milliseconds(10000), chrono::milliseconds(10000)});
4647
4648 const std::string kLogfile =
4649 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4650 util::UnlinkRecursive(kLogfile);
4651
4652 pi2_->Disconnect(pi1_->node());
4653 pi1_->Disconnect(pi2_->node());
4654
4655 {
4656 LoggerState pi2_logger = MakeLogger(pi2_);
4657
4658 pi2_logger.StartLogger(kLogfile);
4659 event_loop_factory_.RunFor(before_reboot_duration);
4660
4661 pi2_->Connect(pi1_->node());
4662 pi1_->Connect(pi2_->node());
4663
4664 event_loop_factory_.RunFor(test_duration);
4665
4666 pi2_logger.AppendAllFilenames(&filenames);
4667 }
4668
4669 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4670 ConfirmReadable(filenames);
4671
4672 {
4673 LogReader reader(sorted_parts);
4674 SimulatedEventLoopFactory replay_factory(reader.configuration());
4675 reader.RegisterWithoutStarting(&replay_factory);
4676
4677 NodeEventLoopFactory *const replay_node =
4678 reader.event_loop_factory()->GetNodeEventLoopFactory("pi1");
4679
4680 std::unique_ptr<EventLoop> test_event_loop =
4681 replay_node->MakeEventLoop("test_reader");
4682 replay_node->OnStartup([replay_node]() {
4683 // Check that we didn't boot until at least t=0.
4684 CHECK_LE(monotonic_clock::epoch(), replay_node->monotonic_now());
4685 });
4686 test_event_loop->OnRun([&test_event_loop]() {
4687 // Check that we didn't boot until at least t=0.
4688 EXPECT_LE(monotonic_clock::epoch(), test_event_loop->monotonic_now());
4689 });
4690 reader.event_loop_factory()->Run();
4691 reader.Deregister();
4692 }
4693}
4694
Austin Schuh79b21d62022-08-16 13:54:49 -07004695// Tests that when we have a loop without all the logs at all points in time, we
4696// can sort it properly.
Austin Schuheb595a62022-08-26 19:24:32 -07004697TEST(MultinodeLoggerLoopTest, Loop) {
Austin Schuh79b21d62022-08-16 13:54:49 -07004698 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4699 aos::configuration::ReadConfig(ArtifactPath(
4700 "aos/events/logging/multinode_pingpong_triangle_split_config.json"));
4701 message_bridge::TestingTimeConverter time_converter(
4702 configuration::NodesCount(&config.message()));
4703 SimulatedEventLoopFactory event_loop_factory(&config.message());
4704 event_loop_factory.SetTimeConverter(&time_converter);
4705
4706 NodeEventLoopFactory *const pi1 =
4707 event_loop_factory.GetNodeEventLoopFactory("pi1");
4708 NodeEventLoopFactory *const pi2 =
4709 event_loop_factory.GetNodeEventLoopFactory("pi2");
4710 NodeEventLoopFactory *const pi3 =
4711 event_loop_factory.GetNodeEventLoopFactory("pi3");
4712
4713 const std::string kLogfile1_1 =
4714 aos::testing::TestTmpDir() + "/multi_logfile1/";
4715 const std::string kLogfile2_1 =
4716 aos::testing::TestTmpDir() + "/multi_logfile2/";
4717 const std::string kLogfile3_1 =
4718 aos::testing::TestTmpDir() + "/multi_logfile3/";
4719 util::UnlinkRecursive(kLogfile1_1);
4720 util::UnlinkRecursive(kLogfile2_1);
4721 util::UnlinkRecursive(kLogfile3_1);
4722
4723 {
4724 // Make pi1 boot before everything else.
4725 time_converter.AddNextTimestamp(
4726 distributed_clock::epoch(),
4727 {BootTimestamp::epoch(),
4728 BootTimestamp::epoch() - chrono::milliseconds(100),
4729 BootTimestamp::epoch() - chrono::milliseconds(300)});
4730 }
4731
4732 // We want to setup a situation such that 2 of the 3 legs of the loop are very
4733 // confident about time being X, and the third leg is pulling the average off
4734 // to one side.
4735 //
4736 // It's easiest to visualize this in timestamp_plotter.
4737
4738 std::vector<std::string> filenames;
4739 {
4740 // Have pi1 send out a reliable message at startup. This sets up a long
4741 // forwarding time message at the start to bias time.
4742 std::unique_ptr<EventLoop> pi1_event_loop = pi1->MakeEventLoop("ping");
4743 {
4744 aos::Sender<examples::Ping> ping_sender =
4745 pi1_event_loop->MakeSender<examples::Ping>("/reliable");
4746
4747 aos::Sender<examples::Ping>::Builder builder = ping_sender.MakeBuilder();
4748 examples::Ping::Builder ping_builder =
4749 builder.MakeBuilder<examples::Ping>();
4750 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
4751 }
4752
4753 // Wait a while so there's enough data to let the worst case be rather off.
4754 event_loop_factory.RunFor(chrono::seconds(1000));
4755
4756 // Now start a receiving node first. This sets up 2 tight bounds between 2
4757 // of the nodes.
4758 LoggerState pi2_logger = LoggerState::MakeLogger(
4759 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4760 pi2_logger.StartLogger(kLogfile2_1);
4761
4762 event_loop_factory.RunFor(chrono::seconds(100));
4763
4764 // And now start the third leg.
4765 LoggerState pi3_logger = LoggerState::MakeLogger(
4766 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4767 pi3_logger.StartLogger(kLogfile3_1);
4768
4769 LoggerState pi1_logger = LoggerState::MakeLogger(
4770 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4771 pi1_logger.StartLogger(kLogfile1_1);
4772
4773 event_loop_factory.RunFor(chrono::seconds(100));
4774
4775 pi1_logger.AppendAllFilenames(&filenames);
4776 pi2_logger.AppendAllFilenames(&filenames);
4777 pi3_logger.AppendAllFilenames(&filenames);
4778 }
4779
4780 // Make sure we can read this.
4781 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4782 auto result = ConfirmReadable(filenames);
4783}
4784
Austin Schuhe309d2a2019-11-29 13:25:21 -08004785} // namespace testing
4786} // namespace logger
4787} // namespace aos