blob: 62648f1a6a2151a39de9e8ba4fdfce56e85c20aa [file] [log] [blame]
Austin Schuh6bb8a822021-03-31 23:04:39 -07001#include <sys/stat.h>
2
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07005#include "aos/events/logging/log_reader.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08006#include "aos/events/logging/log_writer.h"
milind1f1dca32021-07-03 13:50:07 -07007#include "aos/events/logging/snappy_encoder.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
milind1f1dca32021-07-03 13:50:07 -0700171 logger_event_loop->OnRun([base_name1, base_name2, &logger_event_loop,
172 &logger]() {
173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
175 EXPECT_DEATH(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 logger.StartLogging(std::make_unique<LocalLogNamer>(
milind1f1dca32021-07-03 13:50:07 -0700177 base_name2, logger_event_loop.get(), logger_event_loop->node())),
178 "Already logging");
179 });
Brian Silverman1f345222020-09-24 21:14:48 -0700180 event_loop_factory_.RunFor(chrono::milliseconds(20000));
181 }
182}
183
James Kuszmaul94ca5132022-07-19 09:11:08 -0700184// Tests that we die if the replayer attempts to send on a logged channel.
185TEST_F(LoggerDeathTest, DieOnDuplicateReplayChannels) {
186 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
187 aos::configuration::ReadConfig(
188 ArtifactPath("aos/events/pingpong_config.json"));
189 SimulatedEventLoopFactory event_loop_factory(&config.message());
190 const ::std::string tmpdir = aos::testing::TestTmpDir();
191 const ::std::string base_name = tmpdir + "/logfile";
192 const ::std::string config_file =
193 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
194 const ::std::string logfile = base_name + ".part0.bfbs";
195 // Remove the log file.
196 unlink(config_file.c_str());
197 unlink(logfile.c_str());
198
199 LOG(INFO) << "Logging data to " << logfile;
200
201 {
202 std::unique_ptr<EventLoop> logger_event_loop =
203 event_loop_factory.MakeEventLoop("logger");
204
205 Logger logger(logger_event_loop.get());
206 logger.set_separate_config(false);
207 logger.set_polling_period(std::chrono::milliseconds(100));
208 logger.StartLoggingLocalNamerOnRun(base_name);
209
210 event_loop_factory.RunFor(chrono::seconds(2));
211 }
212
213 LogReader reader(logfile);
214
215 reader.Register();
216
217 std::unique_ptr<EventLoop> test_event_loop =
218 reader.event_loop_factory()->MakeEventLoop("log_reader");
219
220 EXPECT_DEATH(test_event_loop->MakeSender<examples::Ping>("/test"),
221 "exclusive channel.*examples.Ping");
222}
223
Brian Silverman1f345222020-09-24 21:14:48 -0700224// Tests calling StopLogging twice.
225TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800226 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700227 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800228 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700229 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700230 const ::std::string logfile = base_name + ".part0.bfbs";
231 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800232 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700233 unlink(logfile.c_str());
234
235 LOG(INFO) << "Logging data to " << logfile;
236
237 {
238 std::unique_ptr<EventLoop> logger_event_loop =
239 event_loop_factory_.MakeEventLoop("logger");
240
241 event_loop_factory_.RunFor(chrono::milliseconds(95));
242
243 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800244 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700245 logger.set_polling_period(std::chrono::milliseconds(100));
246 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700247 logger.StartLogging(std::make_unique<LocalLogNamer>(
248 base_name, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700249 logger.StopLogging(aos::monotonic_clock::min_time);
250 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
251 "Not logging right now");
252 });
253 event_loop_factory_.RunFor(chrono::milliseconds(20000));
254 }
255}
256
257// Tests that we can startup twice.
258TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800259 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700260 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800261 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700262 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700263 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
264 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800265 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700266 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700267 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
268 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800269 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700270 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800271 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700272
273 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
274
275 {
276 std::unique_ptr<EventLoop> logger_event_loop =
277 event_loop_factory_.MakeEventLoop("logger");
278
279 event_loop_factory_.RunFor(chrono::milliseconds(95));
280
281 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800282 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700283 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh5b728b72021-06-16 14:57:15 -0700284 logger.StartLogging(std::make_unique<LocalLogNamer>(
285 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700286 event_loop_factory_.RunFor(chrono::milliseconds(10000));
287 logger.StopLogging(logger_event_loop->monotonic_now());
288 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh5b728b72021-06-16 14:57:15 -0700289 logger.StartLogging(std::make_unique<LocalLogNamer>(
290 base_name2, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700291 event_loop_factory_.RunFor(chrono::milliseconds(10000));
292 }
293
294 for (const auto &logfile :
295 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
296 SCOPED_TRACE(std::get<0>(logfile));
297 LogReader reader(std::get<0>(logfile));
298 reader.Register();
299
Austin Schuh07676622021-01-21 18:59:17 -0800300 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700301
302 std::unique_ptr<EventLoop> test_event_loop =
303 reader.event_loop_factory()->MakeEventLoop("log_reader");
304
305 int ping_count = std::get<1>(logfile);
306 int pong_count = std::get<1>(logfile);
307
308 // Confirm that the ping and pong counts both match, and the value also
309 // matches.
310 test_event_loop->MakeWatcher("/test",
311 [&ping_count](const examples::Ping &ping) {
312 EXPECT_EQ(ping.value(), ping_count + 1);
313 ++ping_count;
314 });
315 test_event_loop->MakeWatcher(
316 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
317 EXPECT_EQ(pong.value(), pong_count + 1);
318 ++pong_count;
319 EXPECT_EQ(ping_count, pong_count);
320 });
321
322 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
323 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
324 }
325}
326
Austin Schuhfa895892020-01-07 20:07:41 -0800327// Tests that we can read and write rotated log files.
328TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800329 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700330 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800331 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700332 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700333 const ::std::string logfile0 = base_name + ".part0.bfbs";
334 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800335 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800336 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800337 unlink(logfile0.c_str());
338 unlink(logfile1.c_str());
339
340 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
341
342 {
Austin Schuhfa895892020-01-07 20:07:41 -0800343 std::unique_ptr<EventLoop> logger_event_loop =
344 event_loop_factory_.MakeEventLoop("logger");
345
346 event_loop_factory_.RunFor(chrono::milliseconds(95));
347
Brian Silverman1f345222020-09-24 21:14:48 -0700348 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800349 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700350 logger.set_polling_period(std::chrono::milliseconds(100));
351 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800352 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700353 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800354 event_loop_factory_.RunFor(chrono::milliseconds(10000));
355 }
356
Austin Schuh64fab802020-09-09 22:47:47 -0700357 {
358 // Confirm that the UUIDs match for both the parts and the logger, and the
359 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800360 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700361 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800362 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700363 }
364
Brian Silvermanae7c0332020-09-30 16:58:23 -0700365 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
366 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700367 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
368 log_header[1].message().parts_uuid()->string_view());
369
370 EXPECT_EQ(log_header[0].message().parts_index(), 0);
371 EXPECT_EQ(log_header[1].message().parts_index(), 1);
372 }
373
Austin Schuhfa895892020-01-07 20:07:41 -0800374 // Even though it doesn't make any difference here, exercise the logic for
375 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800376 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800377
378 // Confirm that we can remap logged channels to point to new buses.
379 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
380
381 // This sends out the fetched messages and advances time to the start of the
382 // log file.
383 reader.Register();
384
Austin Schuh07676622021-01-21 18:59:17 -0800385 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800386
387 std::unique_ptr<EventLoop> test_event_loop =
388 reader.event_loop_factory()->MakeEventLoop("log_reader");
389
390 int ping_count = 10;
391 int pong_count = 10;
392
393 // Confirm that the ping value matches in the remapped channel location.
394 test_event_loop->MakeWatcher("/original/test",
395 [&ping_count](const examples::Ping &ping) {
396 EXPECT_EQ(ping.value(), ping_count + 1);
397 ++ping_count;
398 });
399 // Confirm that the ping and pong counts both match, and the value also
400 // matches.
401 test_event_loop->MakeWatcher(
402 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
403 EXPECT_EQ(pong.value(), pong_count + 1);
404 ++pong_count;
405 EXPECT_EQ(ping_count, pong_count);
406 });
407
408 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
409 EXPECT_EQ(ping_count, 2010);
410}
411
Austin Schuh4c4e0092019-12-22 16:18:03 -0800412// Tests that a large number of messages per second doesn't overwhelm writev.
413TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800414 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700415 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800416 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700417 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700418 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800419 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800420 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800421 unlink(logfile.c_str());
422
423 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700424 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800425
426 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800427 std::unique_ptr<EventLoop> logger_event_loop =
428 event_loop_factory_.MakeEventLoop("logger");
429
430 std::unique_ptr<EventLoop> ping_spammer_event_loop =
431 event_loop_factory_.MakeEventLoop("ping_spammer");
432 aos::Sender<examples::Ping> ping_sender =
433 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
434
435 aos::TimerHandler *timer_handler =
436 ping_spammer_event_loop->AddTimer([&ping_sender]() {
437 aos::Sender<examples::Ping>::Builder builder =
438 ping_sender.MakeBuilder();
439 examples::Ping::Builder ping_builder =
440 builder.MakeBuilder<examples::Ping>();
Austin Schuhbfe6c572022-01-27 20:48:20 -0800441 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800442 });
443
444 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
445 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
446 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
447 chrono::microseconds(50));
448 });
449
Brian Silverman1f345222020-09-24 21:14:48 -0700450 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800451 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700452 logger.set_polling_period(std::chrono::milliseconds(100));
453 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800454
455 event_loop_factory_.RunFor(chrono::milliseconds(1000));
456 }
457}
458
James Kuszmaul890c2492022-04-06 14:59:31 -0700459// Tests that we can read a logfile that has channels which were sent too fast.
460TEST(SingleNodeLoggerNoFixtureTest, ReadTooFast) {
461 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
462 aos::configuration::ReadConfig(
463 ArtifactPath("aos/events/pingpong_config.json"));
464 SimulatedEventLoopFactory event_loop_factory(&config.message());
465 const ::std::string tmpdir = aos::testing::TestTmpDir();
466 const ::std::string base_name = tmpdir + "/logfile";
467 const ::std::string config_file =
468 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
469 const ::std::string logfile = base_name + ".part0.bfbs";
470 // Remove the log file.
471 unlink(config_file.c_str());
472 unlink(logfile.c_str());
473
474 LOG(INFO) << "Logging data to " << logfile;
475
476 int sent_messages = 0;
477
478 {
479 std::unique_ptr<EventLoop> logger_event_loop =
480 event_loop_factory.MakeEventLoop("logger");
481
482 std::unique_ptr<EventLoop> ping_spammer_event_loop =
483 event_loop_factory.GetNodeEventLoopFactory(nullptr)->MakeEventLoop(
484 "ping_spammer", {NodeEventLoopFactory::CheckSentTooFast::kNo,
James Kuszmaul94ca5132022-07-19 09:11:08 -0700485 NodeEventLoopFactory::ExclusiveSenders::kNo,
486 {}});
James Kuszmaul890c2492022-04-06 14:59:31 -0700487 aos::Sender<examples::Ping> ping_sender =
488 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
489
490 aos::TimerHandler *timer_handler =
491 ping_spammer_event_loop->AddTimer([&ping_sender, &sent_messages]() {
492 aos::Sender<examples::Ping>::Builder builder =
493 ping_sender.MakeBuilder();
494 examples::Ping::Builder ping_builder =
495 builder.MakeBuilder<examples::Ping>();
496 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
497 ++sent_messages;
498 });
499
500 constexpr std::chrono::microseconds kSendPeriod{10};
501 const int max_legal_messages =
502 ping_sender.channel()->frequency() *
503 event_loop_factory.configuration()->channel_storage_duration() /
504 1000000000;
505
506 ping_spammer_event_loop->OnRun(
507 [&ping_spammer_event_loop, kSendPeriod, timer_handler]() {
508 timer_handler->Setup(
509 ping_spammer_event_loop->monotonic_now() + kSendPeriod / 2,
510 kSendPeriod);
511 });
512
513 Logger logger(logger_event_loop.get());
514 logger.set_separate_config(false);
515 logger.set_polling_period(std::chrono::milliseconds(100));
516 logger.StartLoggingLocalNamerOnRun(base_name);
517
518 event_loop_factory.RunFor(kSendPeriod * max_legal_messages * 2);
519 }
520
521 LogReader reader(logfile);
522
523 reader.Register();
524
525 std::unique_ptr<EventLoop> test_event_loop =
526 reader.event_loop_factory()->MakeEventLoop("log_reader");
527
528 int replay_count = 0;
529
530 test_event_loop->MakeWatcher(
531 "/test", [&replay_count](const examples::Ping &) { ++replay_count; });
532
533 reader.event_loop_factory()->Run();
534 EXPECT_EQ(replay_count, sent_messages);
535}
536
James Kuszmauldd0a5042021-10-28 23:38:04 -0700537struct CompressionParams {
538 std::string_view extension;
539 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
540};
541
542std::ostream &operator<<(std::ostream &ostream,
543 const CompressionParams &params) {
544 ostream << "\"" << params.extension << "\"";
545 return ostream;
546}
547
548std::vector<CompressionParams> SupportedCompressionAlgorithms() {
549 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
550 {SnappyDecoder::kExtension,
551 []() { return std::make_unique<SnappyEncoder>(); }},
552#ifdef LZMA
553 {LzmaDecoder::kExtension,
554 []() { return std::make_unique<LzmaEncoder>(3); }}
555#endif // LZMA
556 };
557}
558
Austin Schuh61e973f2021-02-21 21:43:56 -0800559// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700560struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800561 // The config file to use.
562 std::string config;
563 // If true, the RemoteMessage channel should be shared between all the remote
564 // channels. If false, there will be 1 RemoteMessage channel per remote
565 // channel.
566 bool shared;
567 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700568 std::string_view sha256;
James Kuszmaul53da7f32022-09-11 11:11:55 -0700569 // sha256 of the relogged config
570 std::string_view relogged_sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800571};
Austin Schuh315b96b2020-12-11 21:21:12 -0800572
James Kuszmauldd0a5042021-10-28 23:38:04 -0700573std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
574 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
James Kuszmaul53da7f32022-09-11 11:11:55 -0700575 << ", sha256: \"" << params.sha256 << "\", relogged_sha256: \""
576 << params.relogged_sha256 << "\"}";
James Kuszmauldd0a5042021-10-28 23:38:04 -0700577 return ostream;
578}
579
Austin Schuh3e20c692021-11-16 20:43:16 -0800580struct LoggerState {
581 static LoggerState MakeLogger(NodeEventLoopFactory *node,
582 SimulatedEventLoopFactory *factory,
583 CompressionParams params,
584 const Configuration *configuration = nullptr) {
585 if (configuration == nullptr) {
586 configuration = factory->configuration();
587 }
588 return {node->MakeEventLoop("logger"),
589 {},
590 configuration,
591 configuration::GetNode(configuration, node->node()),
592 nullptr,
593 params};
594 }
595
596 void StartLogger(std::string logfile_base) {
597 CHECK(!logfile_base.empty());
598
599 logger = std::make_unique<Logger>(event_loop.get(), configuration);
600 logger->set_polling_period(std::chrono::milliseconds(100));
601 logger->set_name(
602 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
Austin Schuhfa712682022-05-11 16:43:42 -0700603 logger->set_logger_sha1(
604 absl::StrCat("logger_sha1_", event_loop->node()->name()->str()));
605 logger->set_logger_version(
606 absl::StrCat("logger_version_", event_loop->node()->name()->str()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800607 event_loop->OnRun([this, logfile_base]() {
608 std::unique_ptr<MultiNodeLogNamer> namer =
609 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
610 event_loop.get(), node);
611 namer->set_extension(params.extension);
612 namer->set_encoder_factory(params.encoder_factory);
613 log_namer = namer.get();
614
615 logger->StartLogging(std::move(namer));
616 });
617 }
618
619 std::unique_ptr<EventLoop> event_loop;
620 std::unique_ptr<Logger> logger;
621 const Configuration *configuration;
622 const Node *node;
623 MultiNodeLogNamer *log_namer;
624 CompressionParams params;
625
626 void AppendAllFilenames(std::vector<std::string> *filenames) {
627 for (const std::string &file : log_namer->all_filenames()) {
628 const std::string_view separator =
629 log_namer->base_name().back() == '/' ? "" : "_";
630 filenames->emplace_back(
631 absl::StrCat(log_namer->base_name(), separator, file));
632 }
633 }
634
635 ~LoggerState() {
636 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800637 std::vector<std::string> filenames;
638 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800639 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800640 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800641 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800642 auto x = ReadHeader(file);
643 if (x) {
644 VLOG(1) << aos::FlatbufferToJson(x.value());
645 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800646 }
647 }
648 }
649};
650
Austin Schuhe33c08d2022-02-03 18:15:21 -0800651std::vector<std::pair<std::vector<realtime_clock::time_point>,
652 std::vector<realtime_clock::time_point>>>
653ConfirmReadable(
654 const std::vector<std::string> &files,
655 realtime_clock::time_point start_time = realtime_clock::min_time,
656 realtime_clock::time_point end_time = realtime_clock::max_time) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800657 {
658 LogReader reader(SortParts(files));
659
660 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
661 reader.Register(&log_reader_factory);
662
663 log_reader_factory.Run();
664
665 reader.Deregister();
666 }
667 {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800668 std::vector<std::pair<std::vector<realtime_clock::time_point>,
669 std::vector<realtime_clock::time_point>>>
670 result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800671 LogReader reader(SortParts(files));
672
Austin Schuhe33c08d2022-02-03 18:15:21 -0800673 reader.SetStartTime(start_time);
674 reader.SetEndTime(end_time);
675
Austin Schuh3e20c692021-11-16 20:43:16 -0800676 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
677 reader.RegisterWithoutStarting(&log_reader_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -0800678 result.resize(
679 configuration::NodesCount(log_reader_factory.configuration()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800680 if (configuration::MultiNode(log_reader_factory.configuration())) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800681 size_t i = 0;
Austin Schuh3e20c692021-11-16 20:43:16 -0800682 for (const aos::Node *node :
683 *log_reader_factory.configuration()->nodes()) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800684 LOG(INFO) << "Registering start";
685 reader.OnStart(node, [node, &log_reader_factory, &result,
686 node_index = i]() {
Austin Schuh3e20c692021-11-16 20:43:16 -0800687 LOG(INFO) << "Starting " << node->name()->string_view();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800688 result[node_index].first.push_back(
689 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
Austin Schuh3e20c692021-11-16 20:43:16 -0800690 });
Austin Schuhe33c08d2022-02-03 18:15:21 -0800691 reader.OnEnd(node, [node, &log_reader_factory, &result,
692 node_index = i]() {
693 LOG(INFO) << "Ending " << node->name()->string_view();
694 result[node_index].second.push_back(
695 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
696 });
697 ++i;
Austin Schuh3e20c692021-11-16 20:43:16 -0800698 }
Austin Schuhe33c08d2022-02-03 18:15:21 -0800699 } else {
700 reader.OnStart([&log_reader_factory, &result]() {
701 LOG(INFO) << "Starting";
702 result[0].first.push_back(
703 log_reader_factory.GetNodeEventLoopFactory(nullptr)
704 ->realtime_now());
705 });
706 reader.OnEnd([&log_reader_factory, &result]() {
707 LOG(INFO) << "Ending";
708 result[0].second.push_back(
709 log_reader_factory.GetNodeEventLoopFactory(nullptr)
710 ->realtime_now());
711 });
Austin Schuh3e20c692021-11-16 20:43:16 -0800712 }
713
714 log_reader_factory.Run();
715
716 reader.Deregister();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800717
718 for (auto x : result) {
719 for (auto y : x.first) {
720 VLOG(1) << "Start " << y;
721 }
722 for (auto y : x.second) {
723 VLOG(1) << "End " << y;
724 }
725 }
726 return result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800727 }
728}
729
James Kuszmauldd0a5042021-10-28 23:38:04 -0700730class MultinodeLoggerTest : public ::testing::TestWithParam<
731 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800732 public:
733 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700734 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
735 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800736 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800737 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700738 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800739 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700740 event_loop_factory_.configuration(), pi1_->node())),
741 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800742 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700743 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800744 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800745 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
746 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800747 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800748 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800749 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700750 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700751 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800752 event_loop_factory_.SetTimeConverter(&time_converter_);
753
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700754 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700755 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700756 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800757 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700758 }
759
James Kuszmaul53da7f32022-09-11 11:11:55 -0700760 for (const auto &file : MakeLogFiles(tmp_dir_ + "/relogged1",
761 tmp_dir_ + "/relogged2", 3, 3, true)) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800762 unlink(file.c_str());
763 }
764
Austin Schuh268586b2021-03-31 22:24:39 -0700765 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800766 unlink(file.c_str());
767 }
768
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700769 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
770 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700771
772 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
773 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700774 }
775
James Kuszmauldd0a5042021-10-28 23:38:04 -0700776 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800777
778 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700779 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800780 size_t pi1_data_count = 3,
James Kuszmaul53da7f32022-09-11 11:11:55 -0700781 size_t pi2_data_count = 3,
782 bool relogged_config = false) {
783 std::string_view sha256 = relogged_config
784 ? std::get<0>(GetParam()).relogged_sha256
785 : std::get<0>(GetParam()).sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800786 std::vector<std::string> result;
James Kuszmaul53da7f32022-09-11 11:11:55 -0700787 result.emplace_back(absl::StrCat(logfile_base1, "_", sha256, Extension()));
788 result.emplace_back(absl::StrCat(logfile_base2, "_", sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700789 for (size_t i = 0; i < pi1_data_count; ++i) {
790 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700791 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700792 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800793 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700794 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800795 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700796 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700797 for (size_t i = 0; i < pi2_data_count; ++i) {
798 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700799 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700800 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700801 result.emplace_back(logfile_base2 +
802 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
803 Extension());
804 result.emplace_back(logfile_base2 +
805 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
806 Extension());
807 result.emplace_back(logfile_base1 +
808 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
809 Extension());
810 result.emplace_back(logfile_base1 +
811 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
812 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800813 if (shared()) {
814 result.emplace_back(logfile_base1 +
815 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700816 "aos.message_bridge.RemoteMessage.part0" +
817 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800818 result.emplace_back(logfile_base1 +
819 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700820 "aos.message_bridge.RemoteMessage.part1" +
821 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800822 result.emplace_back(logfile_base1 +
823 "_timestamps/pi1/aos/remote_timestamps/pi2/"
824 "aos.message_bridge.RemoteMessage.part2" +
825 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800826 result.emplace_back(logfile_base2 +
827 "_timestamps/pi2/aos/remote_timestamps/pi1/"
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_base2 +
831 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700832 "aos.message_bridge.RemoteMessage.part1" +
833 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800834 } else {
835 result.emplace_back(logfile_base1 +
836 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
837 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700838 "aos.message_bridge.RemoteMessage.part0" +
839 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800840 result.emplace_back(logfile_base1 +
841 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
842 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700843 "aos.message_bridge.RemoteMessage.part1" +
844 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800845 result.emplace_back(logfile_base2 +
846 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
847 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700848 "aos.message_bridge.RemoteMessage.part0" +
849 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800850 result.emplace_back(logfile_base2 +
851 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
852 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700853 "aos.message_bridge.RemoteMessage.part1" +
854 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800855 result.emplace_back(logfile_base1 +
856 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
857 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700858 "aos.message_bridge.RemoteMessage.part0" +
859 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800860 result.emplace_back(logfile_base1 +
861 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
862 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700863 "aos.message_bridge.RemoteMessage.part1" +
864 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800865 }
866
867 return result;
868 }
869
870 std::vector<std::string> MakePi1RebootLogfiles() {
871 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700872 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
873 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
874 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800875 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
876 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800877 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700878 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800879 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700880 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800881 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700882 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700883 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700884 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
885 result.emplace_back(logfile_base1_ +
886 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
887 Extension());
888 result.emplace_back(logfile_base1_ +
889 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
890 Extension());
891 result.emplace_back(logfile_base1_ +
892 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
893 Extension());
894 result.emplace_back(logfile_base1_ +
895 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
896 Extension());
897 result.emplace_back(absl::StrCat(
898 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800899 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800900 for (size_t i = 0; i < 6; ++i) {
901 result.emplace_back(
902 absl::StrCat(logfile_base1_,
903 "_timestamps/pi1/aos/remote_timestamps/pi2/"
904 "aos.message_bridge.RemoteMessage.part",
905 i, Extension()));
906 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800907 } else {
908 result.emplace_back(logfile_base1_ +
909 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
910 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700911 "aos.message_bridge.RemoteMessage.part0" +
912 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800913 result.emplace_back(logfile_base1_ +
914 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
915 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700916 "aos.message_bridge.RemoteMessage.part1" +
917 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800918 result.emplace_back(logfile_base1_ +
919 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
920 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700921 "aos.message_bridge.RemoteMessage.part2" +
922 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700923 result.emplace_back(logfile_base1_ +
924 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
925 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700926 "aos.message_bridge.RemoteMessage.part3" +
927 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800928
929 result.emplace_back(logfile_base1_ +
930 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
931 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700932 "aos.message_bridge.RemoteMessage.part0" +
933 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800934 result.emplace_back(logfile_base1_ +
935 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
936 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700937 "aos.message_bridge.RemoteMessage.part1" +
938 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800939 result.emplace_back(logfile_base1_ +
940 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
941 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700942 "aos.message_bridge.RemoteMessage.part2" +
943 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700944 result.emplace_back(logfile_base1_ +
945 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
946 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700947 "aos.message_bridge.RemoteMessage.part3" +
948 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800949 }
950 return result;
951 }
952
953 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
954 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700955 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
956 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
957 result.emplace_back(logfile_base1_ +
958 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
959 Extension());
960 result.emplace_back(absl::StrCat(
961 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700962 return result;
963 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800964
Austin Schuh510dc622021-08-06 18:47:30 -0700965 std::vector<std::string> MakePi1DeadNodeLogfiles() {
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(absl::StrCat(
969 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800970 return result;
971 }
972
973 std::vector<std::vector<std::string>> StructureLogFiles() {
974 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800975 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
976 std::vector<std::string>{logfiles_[5], logfiles_[6]},
977 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800978 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800979 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800980
Austin Schuhbfe6c572022-01-27 20:48:20 -0800981 if (shared()) {
982 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
983 logfiles_[16]});
984 result.emplace_back(
985 std::vector<std::string>{logfiles_[17], logfiles_[18]});
986 } else {
987 result.emplace_back(
988 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800989 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700990 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800991 result.emplace_back(
992 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800993 }
994
995 return result;
996 }
997
James Kuszmauldd0a5042021-10-28 23:38:04 -0700998 std::string Extension() {
999 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
1000 }
1001
Austin Schuh58646e22021-08-23 23:51:46 -07001002 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -07001003 SimulatedEventLoopFactory *factory = nullptr,
1004 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001005 if (factory == nullptr) {
1006 factory = &event_loop_factory_;
1007 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001008 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
1009 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001010 }
1011
James Kuszmauldd0a5042021-10-28 23:38:04 -07001012 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001013 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -08001014 if (logger->event_loop->node()->name()->string_view() == "pi1") {
1015 logfile_base = logfile_base1_;
1016 } else {
1017 logfile_base = logfile_base2_;
1018 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001019 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001020 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001021 }
Austin Schuh15649d62019-12-28 16:36:38 -08001022
Austin Schuh3bd4c402020-11-06 18:19:06 -08001023 void VerifyParts(const std::vector<LogFile> &sorted_parts,
1024 const std::vector<std::string> &corrupted_parts = {}) {
1025 EXPECT_EQ(sorted_parts.size(), 2u);
1026
1027 // Count up the number of UUIDs and make sure they are what we expect as a
1028 // sanity check.
1029 std::set<std::string> log_event_uuids;
1030 std::set<std::string> parts_uuids;
1031 std::set<std::string> both_uuids;
1032
1033 size_t missing_rt_count = 0;
1034
1035 std::vector<std::string> logger_nodes;
1036 for (const LogFile &log_file : sorted_parts) {
1037 EXPECT_FALSE(log_file.log_event_uuid.empty());
1038 log_event_uuids.insert(log_file.log_event_uuid);
1039 logger_nodes.emplace_back(log_file.logger_node);
1040 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -08001041 EXPECT_TRUE(log_file.config);
1042 EXPECT_EQ(log_file.name,
1043 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuhfa712682022-05-11 16:43:42 -07001044 EXPECT_EQ(log_file.logger_sha1,
1045 absl::StrCat("logger_sha1_", log_file.logger_node));
1046 EXPECT_EQ(log_file.logger_version,
1047 absl::StrCat("logger_version_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -08001048
1049 for (const LogParts &part : log_file.parts) {
1050 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
1051 << ": " << part;
1052 missing_rt_count +=
1053 part.realtime_start_time == aos::realtime_clock::min_time;
1054
1055 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
1056 log_event_uuids.end());
1057 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -08001058 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001059 parts_uuids.insert(part.parts_uuid);
1060 both_uuids.insert(part.parts_uuid);
1061 }
1062 }
1063
Austin Schuh61e973f2021-02-21 21:43:56 -08001064 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
1065 // start time on remote nodes because we don't know it and would be
1066 // guessing. And the log reader can actually do a better job. The number
1067 // depends on if we have the remote timestamps split across 2 files, or just
1068 // across 1, depending on if we are using a split or combined timestamp
1069 // channel config.
1070 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001071
1072 EXPECT_EQ(log_event_uuids.size(), 2u);
1073 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
1074 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
1075
1076 // Test that each list of parts is in order. Don't worry about the ordering
1077 // between part file lists though.
1078 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -08001079 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -08001080 ::testing::UnorderedElementsAreArray(structured_logfiles_));
1081
1082 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
1083
1084 EXPECT_NE(sorted_parts[0].realtime_start_time,
1085 aos::realtime_clock::min_time);
1086 EXPECT_NE(sorted_parts[1].realtime_start_time,
1087 aos::realtime_clock::min_time);
1088
1089 EXPECT_NE(sorted_parts[0].monotonic_start_time,
1090 aos::monotonic_clock::min_time);
1091 EXPECT_NE(sorted_parts[1].monotonic_start_time,
1092 aos::monotonic_clock::min_time);
1093
1094 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
1095 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
1096 }
1097
1098 void AddExtension(std::string_view extension) {
1099 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
1100 [extension](const std::string &in) {
1101 return absl::StrCat(in, extension);
1102 });
1103
1104 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
1105 structured_logfiles_.begin(),
1106 [extension](std::vector<std::string> in) {
1107 std::transform(in.begin(), in.end(), in.begin(),
1108 [extension](const std::string &in_str) {
1109 return absl::StrCat(in_str, extension);
1110 });
1111 return in;
1112 });
1113 }
1114
Austin Schuh15649d62019-12-28 16:36:38 -08001115 // Config and factory.
1116 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001117 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -08001118 SimulatedEventLoopFactory event_loop_factory_;
1119
Austin Schuh58646e22021-08-23 23:51:46 -07001120 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001121 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -07001122 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001123 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001124
1125 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -08001126 std::string logfile_base1_;
1127 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -08001128 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001129 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -08001130 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001131
1132 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -08001133};
1134
Austin Schuh391e3172020-09-01 22:48:18 -07001135// Counts the number of messages on a channel. Returns (channel name, channel
1136// type, count) for every message matching matcher()
1137std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -08001138 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001139 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -08001140 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -08001141 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -08001142
Austin Schuh6f3babe2020-01-26 20:34:50 -08001143 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001144 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -08001145 if (!msg) {
1146 break;
1147 }
1148
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001149 if (matcher(msg.get())) {
1150 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001151 }
1152 }
1153
Austin Schuh391e3172020-09-01 22:48:18 -07001154 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001155 int channel = 0;
1156 for (size_t i = 0; i < counts.size(); ++i) {
1157 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -08001158 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -07001159 result.push_back(std::make_tuple(channel->name()->str(),
1160 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -08001161 }
1162 ++channel;
1163 }
1164
1165 return result;
1166}
1167
1168// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001169std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -08001170 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -07001171 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001172 return CountChannelsMatching(
1173 config, filename, [](const UnpackedMessageHeader *msg) {
1174 if (msg->span.data() != nullptr) {
1175 CHECK(!msg->monotonic_remote_time.has_value());
1176 CHECK(!msg->realtime_remote_time.has_value());
1177 CHECK(!msg->remote_queue_index.has_value());
1178 return true;
1179 }
1180 return false;
1181 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001182}
1183
1184// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001185std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001186 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001187 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001188 return CountChannelsMatching(
1189 config, filename, [](const UnpackedMessageHeader *msg) {
1190 if (msg->span.data() == nullptr) {
1191 CHECK(msg->monotonic_remote_time.has_value());
1192 CHECK(msg->realtime_remote_time.has_value());
1193 CHECK(msg->remote_queue_index.has_value());
1194 return true;
1195 }
1196 return false;
1197 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001198}
1199
Austin Schuhcde938c2020-02-02 17:30:07 -08001200// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001201TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001202 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001203 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001204
Austin Schuh15649d62019-12-28 16:36:38 -08001205 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001206 LoggerState pi1_logger = MakeLogger(pi1_);
1207 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001208
1209 event_loop_factory_.RunFor(chrono::milliseconds(95));
1210
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001211 StartLogger(&pi1_logger);
1212 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001213
Austin Schuh15649d62019-12-28 16:36:38 -08001214 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001215 pi1_logger.AppendAllFilenames(&actual_filenames);
1216 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001217 }
1218
Austin Schuhbfe6c572022-01-27 20:48:20 -08001219 ASSERT_THAT(actual_filenames,
1220 ::testing::UnorderedElementsAreArray(logfiles_));
1221
Austin Schuh6f3babe2020-01-26 20:34:50 -08001222 {
Austin Schuh64fab802020-09-09 22:47:47 -07001223 std::set<std::string> logfile_uuids;
1224 std::set<std::string> parts_uuids;
1225 // Confirm that we have the expected number of UUIDs for both the logfile
1226 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001227 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001228 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001229 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001230 if (!log_header.back().message().has_configuration()) {
1231 logfile_uuids.insert(
1232 log_header.back().message().log_event_uuid()->str());
1233 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1234 }
Austin Schuh64fab802020-09-09 22:47:47 -07001235 }
Austin Schuh15649d62019-12-28 16:36:38 -08001236
Austin Schuh64fab802020-09-09 22:47:47 -07001237 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001238 if (shared()) {
1239 EXPECT_EQ(parts_uuids.size(), 7u);
1240 } else {
1241 EXPECT_EQ(parts_uuids.size(), 8u);
1242 }
Austin Schuh64fab802020-09-09 22:47:47 -07001243
1244 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001245 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001246 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001247 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1248
Austin Schuh64fab802020-09-09 22:47:47 -07001249 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001250 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001251
Austin Schuhe46492f2021-07-31 19:49:41 -07001252 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001253 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1254 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1255
1256 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1257 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1258
Austin Schuhe46492f2021-07-31 19:49:41 -07001259 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1260 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001261
1262 if (shared()) {
1263 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1264 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001265 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001266
1267 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1268 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1269 } else {
1270 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1271 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1272
1273 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1274 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1275
1276 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1277 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001278 }
Austin Schuh64fab802020-09-09 22:47:47 -07001279
1280 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001281 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001282 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001283 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1284
1285 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1286 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1287
1288 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1289 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1290 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1291
Austin Schuh64fab802020-09-09 22:47:47 -07001292 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1293 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001294
Austin Schuh61e973f2021-02-21 21:43:56 -08001295 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1296 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001297
1298 if (shared()) {
1299 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1300 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1301 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1302
1303 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1304 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1305 } else {
1306 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1307 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1308
Austin Schuhe46492f2021-07-31 19:49:41 -07001309 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1310 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001311
1312 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1313 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001314 }
Austin Schuh64fab802020-09-09 22:47:47 -07001315 }
1316
Austin Schuh8c399962020-12-25 21:51:45 -08001317 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001318 {
Austin Schuh391e3172020-09-01 22:48:18 -07001319 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001320 std::shared_ptr<const aos::Configuration> config =
1321 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001322
Austin Schuh6f3babe2020-01-26 20:34:50 -08001323 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001324 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1325 UnorderedElementsAre(
1326 std::make_tuple("/pi1/aos",
1327 "aos.message_bridge.ServerStatistics", 1),
1328 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001329 << " : " << logfiles_[2];
James Kuszmaul53da7f32022-09-11 11:11:55 -07001330 {
1331 std::vector<std::tuple<std::string, std::string, int>> channel_counts = {
1332 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1333 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1334 1)};
1335 if (!std::get<0>(GetParam()).shared) {
1336 channel_counts.push_back(
1337 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1338 "aos-message_bridge-Timestamp",
1339 "aos.message_bridge.RemoteMessage", 1));
1340 }
1341 EXPECT_THAT(CountChannelsData(config, logfiles_[3]),
1342 ::testing::UnorderedElementsAreArray(channel_counts))
1343 << " : " << logfiles_[3];
1344 }
1345 {
1346 std::vector<std::tuple<std::string, std::string, int>> channel_counts = {
1347 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
1348 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
1349 20),
1350 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1351 199),
1352 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
1353 std::make_tuple("/test", "aos.examples.Ping", 2000)};
1354 if (!std::get<0>(GetParam()).shared) {
1355 channel_counts.push_back(
1356 std::make_tuple("/pi1/aos/remote_timestamps/pi2/pi1/aos/"
1357 "aos-message_bridge-Timestamp",
1358 "aos.message_bridge.RemoteMessage", 199));
1359 }
1360 EXPECT_THAT(CountChannelsData(config, logfiles_[4]),
1361 ::testing::UnorderedElementsAreArray(channel_counts))
1362 << " : " << logfiles_[4];
1363 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001364 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001365 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1366 UnorderedElementsAre())
1367 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001368 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001369 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001370 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001371 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001372 EXPECT_THAT(
1373 CountChannelsTimestamp(config, logfiles_[4]),
1374 UnorderedElementsAre(
1375 std::make_tuple("/test", "aos.examples.Pong", 2000),
1376 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1377 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001378
1379 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001380 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001381 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001382 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001383 << " : " << logfiles_[5];
1384 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001385 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001386 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001387 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001388
Austin Schuh6f3babe2020-01-26 20:34:50 -08001389 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001390 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1391 UnorderedElementsAre())
1392 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001393 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1394 UnorderedElementsAre())
1395 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001396
1397 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001398 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001399 UnorderedElementsAre(std::make_tuple(
1400 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001401 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001402 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001403 CountChannelsData(config, logfiles_[8]),
1404 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1405 << " : " << logfiles_[8];
1406 EXPECT_THAT(
1407 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001408 UnorderedElementsAre(
1409 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001410 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001411 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001412 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1413 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001414 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001415 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1416 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001417 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001418 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001419 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001420 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001421 EXPECT_THAT(
1422 CountChannelsTimestamp(config, logfiles_[8]),
1423 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1424 << " : " << logfiles_[8];
1425 EXPECT_THAT(
1426 CountChannelsTimestamp(config, logfiles_[9]),
1427 UnorderedElementsAre(
1428 std::make_tuple("/test", "aos.examples.Ping", 2000),
1429 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1430 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001431
1432 // And then test that the remotely logged timestamp data files only have
1433 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001434 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1435 UnorderedElementsAre())
1436 << " : " << logfiles_[10];
1437 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1438 UnorderedElementsAre())
1439 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001440 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1441 UnorderedElementsAre())
1442 << " : " << logfiles_[12];
1443 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1444 UnorderedElementsAre())
1445 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001446
Austin Schuh8c399962020-12-25 21:51:45 -08001447 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001448 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001449 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001450 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001451 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001452 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001453 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001454 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001455
Austin Schuh61e973f2021-02-21 21:43:56 -08001456 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001457 UnorderedElementsAre(std::make_tuple(
1458 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001459 << " : " << logfiles_[12];
1460 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001461 UnorderedElementsAre(std::make_tuple(
1462 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001463 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001464
1465 // Timestamps from pi2 on pi1, and the other way.
1466 if (shared()) {
1467 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1468 UnorderedElementsAre())
1469 << " : " << logfiles_[14];
1470 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1471 UnorderedElementsAre())
1472 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001473 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001474 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001475 << " : " << logfiles_[16];
1476 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001477 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001478 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001479 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1480 UnorderedElementsAre())
1481 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001482
Austin Schuhbfe6c572022-01-27 20:48:20 -08001483 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1484 UnorderedElementsAre(
1485 std::make_tuple("/test", "aos.examples.Ping", 1)))
1486 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001487 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001488 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001489 UnorderedElementsAre(
1490 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001491 std::make_tuple("/test", "aos.examples.Ping", 90)))
1492 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001493 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001494 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001495 UnorderedElementsAre(
1496 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1497 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001498 << " : " << logfiles_[16];
1499 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001500 UnorderedElementsAre(std::make_tuple(
1501 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1502 << " : " << logfiles_[17];
1503 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1504 UnorderedElementsAre(std::make_tuple(
1505 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1506 << " : " << logfiles_[18];
1507 } else {
1508 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1509 UnorderedElementsAre())
1510 << " : " << logfiles_[14];
1511 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1512 UnorderedElementsAre())
1513 << " : " << logfiles_[15];
1514 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1515 UnorderedElementsAre())
1516 << " : " << logfiles_[16];
1517 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1518 UnorderedElementsAre())
1519 << " : " << logfiles_[17];
1520 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1521 UnorderedElementsAre())
1522 << " : " << logfiles_[18];
1523 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1524 UnorderedElementsAre())
1525 << " : " << logfiles_[19];
1526
1527 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1528 UnorderedElementsAre(std::make_tuple(
1529 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1530 << " : " << logfiles_[14];
1531 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1532 UnorderedElementsAre(std::make_tuple(
1533 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1534 << " : " << logfiles_[15];
1535 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1536 UnorderedElementsAre(std::make_tuple(
1537 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1538 << " : " << logfiles_[16];
1539 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1540 UnorderedElementsAre(std::make_tuple(
1541 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1542 << " : " << logfiles_[17];
1543 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1544 UnorderedElementsAre(
1545 std::make_tuple("/test", "aos.examples.Ping", 91)))
1546 << " : " << logfiles_[18];
1547 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001548 UnorderedElementsAre(
1549 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001550 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001551 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001552 }
1553
Austin Schuh8c399962020-12-25 21:51:45 -08001554 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001555
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001556 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001557 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001558
1559 // This sends out the fetched messages and advances time to the start of the
1560 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001561 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001562
Austin Schuhac0771c2020-01-07 18:36:30 -08001563 const Node *pi1 =
1564 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001565 const Node *pi2 =
1566 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001567
Austin Schuh2f8fd752020-09-01 22:38:28 -07001568 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1569 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1570 LOG(INFO) << "now pi1 "
1571 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1572 LOG(INFO) << "now pi2 "
1573 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1574
Austin Schuh07676622021-01-21 18:59:17 -08001575 EXPECT_THAT(reader.LoggedNodes(),
1576 ::testing::ElementsAre(
1577 configuration::GetNode(reader.logged_configuration(), pi1),
1578 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001579
1580 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001581
Austin Schuh6f3babe2020-01-26 20:34:50 -08001582 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001583 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001584 std::unique_ptr<EventLoop> pi2_event_loop =
1585 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001586
Austin Schuh6f3babe2020-01-26 20:34:50 -08001587 int pi1_ping_count = 10;
1588 int pi2_ping_count = 10;
1589 int pi1_pong_count = 10;
1590 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001591
1592 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001593 pi1_event_loop->MakeWatcher(
1594 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001595 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001596 << pi1_event_loop->context().monotonic_remote_time << " -> "
1597 << pi1_event_loop->context().monotonic_event_time;
1598 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1599 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1600 pi1_ping_count * chrono::milliseconds(10) +
1601 monotonic_clock::epoch());
1602 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1603 pi1_ping_count * chrono::milliseconds(10) +
1604 realtime_clock::epoch());
1605 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1606 pi1_event_loop->context().monotonic_event_time);
1607 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1608 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001609
Austin Schuh6f3babe2020-01-26 20:34:50 -08001610 ++pi1_ping_count;
1611 });
1612 pi2_event_loop->MakeWatcher(
1613 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001614 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001615 << pi2_event_loop->context().monotonic_remote_time << " -> "
1616 << pi2_event_loop->context().monotonic_event_time;
1617 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1618
1619 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1620 pi2_ping_count * chrono::milliseconds(10) +
1621 monotonic_clock::epoch());
1622 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1623 pi2_ping_count * chrono::milliseconds(10) +
1624 realtime_clock::epoch());
1625 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1626 chrono::microseconds(150),
1627 pi2_event_loop->context().monotonic_event_time);
1628 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1629 chrono::microseconds(150),
1630 pi2_event_loop->context().realtime_event_time);
1631 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001632 });
1633
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001634 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001635 // Confirm that the ping and pong counts both match, and the value also
1636 // matches.
1637 pi1_event_loop->MakeWatcher(
1638 "/test", [&pi1_event_loop, &pi1_ping_count,
1639 &pi1_pong_count](const examples::Pong &pong) {
1640 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1641 << pi1_event_loop->context().monotonic_remote_time << " -> "
1642 << pi1_event_loop->context().monotonic_event_time;
1643
1644 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1645 pi1_pong_count + kQueueIndexOffset);
1646 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1647 chrono::microseconds(200) +
1648 pi1_pong_count * chrono::milliseconds(10) +
1649 monotonic_clock::epoch());
1650 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1651 chrono::microseconds(200) +
1652 pi1_pong_count * chrono::milliseconds(10) +
1653 realtime_clock::epoch());
1654
1655 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1656 chrono::microseconds(150),
1657 pi1_event_loop->context().monotonic_event_time);
1658 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1659 chrono::microseconds(150),
1660 pi1_event_loop->context().realtime_event_time);
1661
1662 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1663 ++pi1_pong_count;
1664 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1665 });
1666 pi2_event_loop->MakeWatcher(
1667 "/test", [&pi2_event_loop, &pi2_ping_count,
1668 &pi2_pong_count](const examples::Pong &pong) {
1669 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1670 << pi2_event_loop->context().monotonic_remote_time << " -> "
1671 << pi2_event_loop->context().monotonic_event_time;
1672
1673 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001674 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001675
1676 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1677 chrono::microseconds(200) +
1678 pi2_pong_count * chrono::milliseconds(10) +
1679 monotonic_clock::epoch());
1680 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1681 chrono::microseconds(200) +
1682 pi2_pong_count * chrono::milliseconds(10) +
1683 realtime_clock::epoch());
1684
1685 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1686 pi2_event_loop->context().monotonic_event_time);
1687 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1688 pi2_event_loop->context().realtime_event_time);
1689
1690 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1691 ++pi2_pong_count;
1692 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1693 });
1694
1695 log_reader_factory.Run();
1696 EXPECT_EQ(pi1_ping_count, 2010);
1697 EXPECT_EQ(pi2_ping_count, 2010);
1698 EXPECT_EQ(pi1_pong_count, 2010);
1699 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001700
1701 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001702}
1703
James Kuszmaul46d82582020-05-09 19:50:09 -07001704typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1705
1706// Test that if we feed the replay with a mismatched node list that we die on
1707// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001708TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001709 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001710 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001711 LoggerState pi1_logger = MakeLogger(pi1_);
1712 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001713
1714 event_loop_factory_.RunFor(chrono::milliseconds(95));
1715
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001716 StartLogger(&pi1_logger);
1717 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001718
James Kuszmaul46d82582020-05-09 19:50:09 -07001719 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1720 }
1721
1722 // Test that, if we add an additional node to the replay config that the
1723 // logger complains about the mismatch in number of nodes.
1724 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1725 configuration::MergeWithConfig(&config_.message(), R"({
1726 "nodes": [
1727 {
1728 "name": "extra-node"
1729 }
1730 ]
1731 }
1732 )");
1733
Austin Schuh287d43d2020-12-04 20:19:33 -08001734 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1735 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001736 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001737}
1738
Austin Schuhcde938c2020-02-02 17:30:07 -08001739// Tests that we can read log files where they don't start at the same monotonic
1740// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001741TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001742 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001743 std::vector<std::string> actual_filenames;
1744
Austin Schuhcde938c2020-02-02 17:30:07 -08001745 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001746 LoggerState pi1_logger = MakeLogger(pi1_);
1747 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001748
1749 event_loop_factory_.RunFor(chrono::milliseconds(95));
1750
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001751 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001752
1753 event_loop_factory_.RunFor(chrono::milliseconds(200));
1754
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001755 StartLogger(&pi2_logger);
1756
Austin Schuhcde938c2020-02-02 17:30:07 -08001757 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001758 pi1_logger.AppendAllFilenames(&actual_filenames);
1759 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001760 }
1761
Austin Schuhe46492f2021-07-31 19:49:41 -07001762 // Since we delay starting pi2, it already knows about all the timestamps so
1763 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001764 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001765
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001766 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001767 log_reader_factory.set_send_delay(chrono::microseconds(0));
1768
1769 // This sends out the fetched messages and advances time to the start of the
1770 // log file.
1771 reader.Register(&log_reader_factory);
1772
1773 const Node *pi1 =
1774 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1775 const Node *pi2 =
1776 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1777
Austin Schuh07676622021-01-21 18:59:17 -08001778 EXPECT_THAT(reader.LoggedNodes(),
1779 ::testing::ElementsAre(
1780 configuration::GetNode(reader.logged_configuration(), pi1),
1781 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001782
1783 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1784
1785 std::unique_ptr<EventLoop> pi1_event_loop =
1786 log_reader_factory.MakeEventLoop("test", pi1);
1787 std::unique_ptr<EventLoop> pi2_event_loop =
1788 log_reader_factory.MakeEventLoop("test", pi2);
1789
1790 int pi1_ping_count = 30;
1791 int pi2_ping_count = 30;
1792 int pi1_pong_count = 30;
1793 int pi2_pong_count = 30;
1794
1795 // Confirm that the ping value matches.
1796 pi1_event_loop->MakeWatcher(
1797 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1798 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1799 << pi1_event_loop->context().monotonic_remote_time << " -> "
1800 << pi1_event_loop->context().monotonic_event_time;
1801 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1802
1803 ++pi1_ping_count;
1804 });
1805 pi2_event_loop->MakeWatcher(
1806 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1807 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1808 << pi2_event_loop->context().monotonic_remote_time << " -> "
1809 << pi2_event_loop->context().monotonic_event_time;
1810 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1811
1812 ++pi2_ping_count;
1813 });
1814
1815 // Confirm that the ping and pong counts both match, and the value also
1816 // matches.
1817 pi1_event_loop->MakeWatcher(
1818 "/test", [&pi1_event_loop, &pi1_ping_count,
1819 &pi1_pong_count](const examples::Pong &pong) {
1820 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1821 << pi1_event_loop->context().monotonic_remote_time << " -> "
1822 << pi1_event_loop->context().monotonic_event_time;
1823
1824 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1825 ++pi1_pong_count;
1826 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1827 });
1828 pi2_event_loop->MakeWatcher(
1829 "/test", [&pi2_event_loop, &pi2_ping_count,
1830 &pi2_pong_count](const examples::Pong &pong) {
1831 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1832 << pi2_event_loop->context().monotonic_remote_time << " -> "
1833 << pi2_event_loop->context().monotonic_event_time;
1834
1835 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1836 ++pi2_pong_count;
1837 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1838 });
1839
1840 log_reader_factory.Run();
1841 EXPECT_EQ(pi1_ping_count, 2030);
1842 EXPECT_EQ(pi2_ping_count, 2030);
1843 EXPECT_EQ(pi1_pong_count, 2030);
1844 EXPECT_EQ(pi2_pong_count, 2030);
1845
1846 reader.Deregister();
1847}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001848
Austin Schuh8bd96322020-02-13 21:18:22 -08001849// Tests that we can read log files where the monotonic clocks drift and don't
1850// match correctly. While we are here, also test that different ending times
1851// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001852TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001853 // TODO(austin): Negate...
1854 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1855
Austin Schuh66168842021-08-17 19:42:21 -07001856 time_converter_.AddMonotonic(
1857 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001858 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1859 // skew to be 200 uS/s
1860 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1861 {chrono::milliseconds(95),
1862 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1863 // Run another 200 ms to have one logger start first.
1864 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1865 {chrono::milliseconds(200), chrono::milliseconds(200)});
1866 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1867 // go far enough to cause problems if this isn't accounted for.
1868 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1869 {chrono::milliseconds(20000),
1870 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1871 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1872 {chrono::milliseconds(40000),
1873 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1874 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1875 {chrono::milliseconds(400), chrono::milliseconds(400)});
1876
Austin Schuhcde938c2020-02-02 17:30:07 -08001877 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001878 LoggerState pi2_logger = MakeLogger(pi2_);
1879
Austin Schuh58646e22021-08-23 23:51:46 -07001880 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1881 << pi2_->realtime_now() << " distributed "
1882 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001883
Austin Schuh58646e22021-08-23 23:51:46 -07001884 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1885 << pi2_->realtime_now() << " distributed "
1886 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001887
Austin Schuh87dd3832021-01-01 23:07:31 -08001888 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001889
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001890 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001891
Austin Schuh87dd3832021-01-01 23:07:31 -08001892 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001893
Austin Schuh8bd96322020-02-13 21:18:22 -08001894 {
1895 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001896 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001897
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001898 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001899 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001900
Austin Schuh87dd3832021-01-01 23:07:31 -08001901 // Make sure we slewed time far enough so that the difference is greater
1902 // than the network delay. This confirms that if we sort incorrectly, it
1903 // would show in the results.
1904 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001905 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001906 -event_loop_factory_.send_delay() -
1907 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001908
Austin Schuh87dd3832021-01-01 23:07:31 -08001909 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001910
Austin Schuh87dd3832021-01-01 23:07:31 -08001911 // And now check that we went far enough the other way to make sure we
1912 // cover both problems.
1913 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001914 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001915 event_loop_factory_.send_delay() +
1916 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001917 }
1918
1919 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001920 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001921 }
1922
Austin Schuh72211ae2021-08-05 14:02:30 -07001923 LogReader reader(
1924 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001925
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001926 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001927 log_reader_factory.set_send_delay(chrono::microseconds(0));
1928
Austin Schuhcde938c2020-02-02 17:30:07 -08001929 const Node *pi1 =
1930 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1931 const Node *pi2 =
1932 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1933
Austin Schuh2f8fd752020-09-01 22:38:28 -07001934 // This sends out the fetched messages and advances time to the start of the
1935 // log file.
1936 reader.Register(&log_reader_factory);
1937
1938 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1939 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1940 LOG(INFO) << "now pi1 "
1941 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1942 LOG(INFO) << "now pi2 "
1943 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1944
Austin Schuhcde938c2020-02-02 17:30:07 -08001945 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001946 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1947 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001948 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1949 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001950 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1951 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001952 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1953
Austin Schuh07676622021-01-21 18:59:17 -08001954 EXPECT_THAT(reader.LoggedNodes(),
1955 ::testing::ElementsAre(
1956 configuration::GetNode(reader.logged_configuration(), pi1),
1957 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001958
1959 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1960
1961 std::unique_ptr<EventLoop> pi1_event_loop =
1962 log_reader_factory.MakeEventLoop("test", pi1);
1963 std::unique_ptr<EventLoop> pi2_event_loop =
1964 log_reader_factory.MakeEventLoop("test", pi2);
1965
1966 int pi1_ping_count = 30;
1967 int pi2_ping_count = 30;
1968 int pi1_pong_count = 30;
1969 int pi2_pong_count = 30;
1970
1971 // Confirm that the ping value matches.
1972 pi1_event_loop->MakeWatcher(
1973 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1974 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1975 << pi1_event_loop->context().monotonic_remote_time << " -> "
1976 << pi1_event_loop->context().monotonic_event_time;
1977 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1978
1979 ++pi1_ping_count;
1980 });
1981 pi2_event_loop->MakeWatcher(
1982 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1983 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1984 << pi2_event_loop->context().monotonic_remote_time << " -> "
1985 << pi2_event_loop->context().monotonic_event_time;
1986 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1987
1988 ++pi2_ping_count;
1989 });
1990
1991 // Confirm that the ping and pong counts both match, and the value also
1992 // matches.
1993 pi1_event_loop->MakeWatcher(
1994 "/test", [&pi1_event_loop, &pi1_ping_count,
1995 &pi1_pong_count](const examples::Pong &pong) {
1996 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1997 << pi1_event_loop->context().monotonic_remote_time << " -> "
1998 << pi1_event_loop->context().monotonic_event_time;
1999
2000 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
2001 ++pi1_pong_count;
2002 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
2003 });
2004 pi2_event_loop->MakeWatcher(
2005 "/test", [&pi2_event_loop, &pi2_ping_count,
2006 &pi2_pong_count](const examples::Pong &pong) {
2007 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
2008 << pi2_event_loop->context().monotonic_remote_time << " -> "
2009 << pi2_event_loop->context().monotonic_event_time;
2010
2011 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
2012 ++pi2_pong_count;
2013 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
2014 });
2015
2016 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08002017 EXPECT_EQ(pi1_ping_count, 6030);
2018 EXPECT_EQ(pi2_ping_count, 6030);
2019 EXPECT_EQ(pi1_pong_count, 6030);
2020 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08002021
2022 reader.Deregister();
2023}
2024
Austin Schuh5212cad2020-09-09 23:12:09 -07002025// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002026TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002027 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07002028 // Make a bunch of parts.
2029 {
2030 LoggerState pi1_logger = MakeLogger(pi1_);
2031 LoggerState pi2_logger = MakeLogger(pi2_);
2032
2033 event_loop_factory_.RunFor(chrono::milliseconds(95));
2034
2035 StartLogger(&pi1_logger);
2036 StartLogger(&pi2_logger);
2037
2038 event_loop_factory_.RunFor(chrono::milliseconds(2000));
2039 }
2040
Austin Schuh11d43732020-09-21 17:28:30 -07002041 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002042 VerifyParts(sorted_parts);
2043}
Austin Schuh11d43732020-09-21 17:28:30 -07002044
Austin Schuh3bd4c402020-11-06 18:19:06 -08002045// Tests that we can sort a bunch of parts with an empty part. We should ignore
2046// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08002047TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002048 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002049 // Make a bunch of parts.
2050 {
2051 LoggerState pi1_logger = MakeLogger(pi1_);
2052 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07002053
Austin Schuh3bd4c402020-11-06 18:19:06 -08002054 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07002055
Austin Schuh3bd4c402020-11-06 18:19:06 -08002056 StartLogger(&pi1_logger);
2057 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07002058
Austin Schuh3bd4c402020-11-06 18:19:06 -08002059 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07002060 }
2061
Austin Schuh3bd4c402020-11-06 18:19:06 -08002062 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07002063 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07002064
Austin Schuh3bd4c402020-11-06 18:19:06 -08002065 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
2066 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07002067
Austin Schuh3bd4c402020-11-06 18:19:06 -08002068 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2069 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07002070}
2071
James Kuszmauldd0a5042021-10-28 23:38:04 -07002072// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08002073// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002074TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002075 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002076 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002077 // Make a bunch of parts.
2078 {
2079 LoggerState pi1_logger = MakeLogger(pi1_);
2080 LoggerState pi2_logger = MakeLogger(pi2_);
2081
2082 event_loop_factory_.RunFor(chrono::milliseconds(95));
2083
James Kuszmauldd0a5042021-10-28 23:38:04 -07002084 StartLogger(&pi1_logger);
2085 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002086
2087 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002088
2089 pi1_logger.AppendAllFilenames(&actual_filenames);
2090 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002091 }
2092
Austin Schuhbfe6c572022-01-27 20:48:20 -08002093 ASSERT_THAT(actual_filenames,
2094 ::testing::UnorderedElementsAreArray(logfiles_));
2095
Austin Schuh3bd4c402020-11-06 18:19:06 -08002096 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002097 // For snappy, needs to have enough data to be >1 chunk of compressed data so
2098 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08002099 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08002100 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002101
2102 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08002103 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08002104 compressed_contents.substr(0, compressed_contents.size() - 100));
2105
2106 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2107 VerifyParts(sorted_parts);
2108}
Austin Schuh3bd4c402020-11-06 18:19:06 -08002109
Austin Schuh01b4c352020-09-21 23:09:39 -07002110// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08002111TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002112 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07002113 {
2114 LoggerState pi1_logger = MakeLogger(pi1_);
2115 LoggerState pi2_logger = MakeLogger(pi2_);
2116
2117 event_loop_factory_.RunFor(chrono::milliseconds(95));
2118
2119 StartLogger(&pi1_logger);
2120 StartLogger(&pi2_logger);
2121
2122 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2123 }
2124
Austin Schuh287d43d2020-12-04 20:19:33 -08002125 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07002126
2127 // Remap just on pi1.
2128 reader.RemapLoggedChannel<aos::timing::Report>(
2129 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
2130
2131 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2132 log_reader_factory.set_send_delay(chrono::microseconds(0));
2133
Austin Schuh1c227352021-09-17 12:53:54 -07002134 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
James Kuszmaul53da7f32022-09-11 11:11:55 -07002135 // Note: An extra channel gets remapped automatically due to a timestamp
2136 // channel being LOCAL_LOGGER'd.
2137 ASSERT_EQ(remapped_channels.size(), std::get<0>(GetParam()).shared ? 1u : 2u);
Austin Schuh1c227352021-09-17 12:53:54 -07002138 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
2139 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
James Kuszmaul53da7f32022-09-11 11:11:55 -07002140 if (!std::get<0>(GetParam()).shared) {
2141 EXPECT_EQ(remapped_channels[1]->name()->string_view(),
2142 "/original/pi1/aos/remote_timestamps/pi2/pi1/aos/"
2143 "aos-message_bridge-Timestamp");
2144 EXPECT_EQ(remapped_channels[1]->type()->string_view(),
2145 "aos.message_bridge.RemoteMessage");
2146 }
Austin Schuh1c227352021-09-17 12:53:54 -07002147
Austin Schuh01b4c352020-09-21 23:09:39 -07002148 reader.Register(&log_reader_factory);
2149
2150 const Node *pi1 =
2151 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2152 const Node *pi2 =
2153 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2154
2155 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2156 // else should have moved.
2157 std::unique_ptr<EventLoop> pi1_event_loop =
2158 log_reader_factory.MakeEventLoop("test", pi1);
2159 pi1_event_loop->SkipTimingReport();
2160 std::unique_ptr<EventLoop> full_pi1_event_loop =
2161 log_reader_factory.MakeEventLoop("test", pi1);
2162 full_pi1_event_loop->SkipTimingReport();
2163 std::unique_ptr<EventLoop> pi2_event_loop =
2164 log_reader_factory.MakeEventLoop("test", pi2);
2165 pi2_event_loop->SkipTimingReport();
2166
2167 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
2168 "/aos");
2169 MessageCounter<aos::timing::Report> full_pi1_timing_report(
2170 full_pi1_event_loop.get(), "/pi1/aos");
2171 MessageCounter<aos::timing::Report> pi1_original_timing_report(
2172 pi1_event_loop.get(), "/original/aos");
2173 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
2174 full_pi1_event_loop.get(), "/original/pi1/aos");
2175 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
2176 "/aos");
2177
2178 log_reader_factory.Run();
2179
2180 EXPECT_EQ(pi1_timing_report.count(), 0u);
2181 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
2182 EXPECT_NE(pi1_original_timing_report.count(), 0u);
2183 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
2184 EXPECT_NE(pi2_timing_report.count(), 0u);
2185
2186 reader.Deregister();
2187}
2188
Austin Schuh006a9f52021-04-07 16:24:18 -07002189// Tests that we can remap a forwarded channel as well.
2190TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
2191 time_converter_.StartEqual();
2192 {
2193 LoggerState pi1_logger = MakeLogger(pi1_);
2194 LoggerState pi2_logger = MakeLogger(pi2_);
2195
2196 event_loop_factory_.RunFor(chrono::milliseconds(95));
2197
2198 StartLogger(&pi1_logger);
2199 StartLogger(&pi2_logger);
2200
2201 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2202 }
2203
2204 LogReader reader(SortParts(logfiles_));
2205
2206 reader.RemapLoggedChannel<examples::Ping>("/test");
2207
2208 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2209 log_reader_factory.set_send_delay(chrono::microseconds(0));
2210
2211 reader.Register(&log_reader_factory);
2212
2213 const Node *pi1 =
2214 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2215 const Node *pi2 =
2216 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2217
2218 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2219 // else should have moved.
2220 std::unique_ptr<EventLoop> pi1_event_loop =
2221 log_reader_factory.MakeEventLoop("test", pi1);
2222 pi1_event_loop->SkipTimingReport();
2223 std::unique_ptr<EventLoop> full_pi1_event_loop =
2224 log_reader_factory.MakeEventLoop("test", pi1);
2225 full_pi1_event_loop->SkipTimingReport();
2226 std::unique_ptr<EventLoop> pi2_event_loop =
2227 log_reader_factory.MakeEventLoop("test", pi2);
2228 pi2_event_loop->SkipTimingReport();
2229
2230 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2231 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2232 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2233 "/original/test");
2234 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2235 "/original/test");
2236
2237 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2238 pi1_original_ping_timestamp;
2239 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2240 pi1_ping_timestamp;
2241 if (!shared()) {
2242 pi1_original_ping_timestamp =
2243 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2244 pi1_event_loop.get(),
2245 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2246 pi1_ping_timestamp =
2247 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2248 pi1_event_loop.get(),
2249 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2250 }
2251
2252 log_reader_factory.Run();
2253
2254 EXPECT_EQ(pi1_ping.count(), 0u);
2255 EXPECT_EQ(pi2_ping.count(), 0u);
2256 EXPECT_NE(pi1_original_ping.count(), 0u);
2257 EXPECT_NE(pi2_original_ping.count(), 0u);
2258 if (!shared()) {
2259 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2260 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2261 }
2262
2263 reader.Deregister();
2264}
2265
James Kuszmaul09632422022-05-25 15:56:19 -07002266// Tests that we observe all the same events in log replay (for a given node)
2267// whether we just register an event loop for that node or if we register a full
2268// event loop factory.
2269TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
2270 time_converter_.StartEqual();
2271 constexpr chrono::milliseconds kStartupDelay(95);
2272 {
2273 LoggerState pi1_logger = MakeLogger(pi1_);
2274 LoggerState pi2_logger = MakeLogger(pi2_);
2275
2276 event_loop_factory_.RunFor(kStartupDelay);
2277
2278 StartLogger(&pi1_logger);
2279 StartLogger(&pi2_logger);
2280
2281 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2282 }
2283
2284 LogReader full_reader(SortParts(logfiles_));
2285 LogReader single_node_reader(SortParts(logfiles_));
2286
2287 SimulatedEventLoopFactory full_factory(full_reader.configuration());
2288 SimulatedEventLoopFactory single_node_factory(
2289 single_node_reader.configuration());
James Kuszmaul94ca5132022-07-19 09:11:08 -07002290 single_node_factory.SkipTimingReport();
2291 single_node_factory.DisableStatistics();
James Kuszmaul09632422022-05-25 15:56:19 -07002292 std::unique_ptr<EventLoop> replay_event_loop =
2293 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
2294 "log_reader");
2295
2296 full_reader.Register(&full_factory);
2297 single_node_reader.Register(replay_event_loop.get());
James Kuszmaul09632422022-05-25 15:56:19 -07002298
2299 const Node *full_pi1 =
2300 configuration::GetNode(full_factory.configuration(), "pi1");
2301
2302 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2303 // else should have moved.
2304 std::unique_ptr<EventLoop> full_event_loop =
2305 full_factory.MakeEventLoop("test", full_pi1);
2306 full_event_loop->SkipTimingReport();
2307 full_event_loop->SkipAosLog();
2308 // maps are indexed on channel index.
2309 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
2310 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
2311 observed_messages;
2312 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
2313 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
2314 ++ii) {
2315 const Channel *channel =
2316 full_event_loop->configuration()->channels()->Get(ii);
2317 // We currently don't support replaying remote timestamp channels in
James Kuszmaul53da7f32022-09-11 11:11:55 -07002318 // realtime replay (unless the remote timestamp channel was not NOT_LOGGED,
2319 // in which case it gets auto-remapped and replayed on a /original channel).
James Kuszmaul09632422022-05-25 15:56:19 -07002320 if (channel->name()->string_view().find("remote_timestamp") !=
James Kuszmaul53da7f32022-09-11 11:11:55 -07002321 std::string_view::npos &&
2322 channel->name()->string_view().find("/original") ==
2323 std::string_view::npos) {
James Kuszmaul09632422022-05-25 15:56:19 -07002324 continue;
2325 }
2326 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
2327 observed_messages[ii] = {};
2328 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
2329 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
2330 if (fetchers[ii]->Fetch()) {
2331 observed_messages[ii].push_back(std::make_pair(
2332 fetchers[ii]->context().monotonic_event_time, true));
2333 }
2334 });
2335 full_event_loop->MakeRawNoArgWatcher(
2336 channel, [ii, &observed_messages](const Context &context) {
2337 observed_messages[ii].push_back(
2338 std::make_pair(context.monotonic_event_time, false));
2339 });
2340 }
2341 }
2342
2343 full_factory.Run();
2344 fetchers.clear();
2345 full_reader.Deregister();
2346
2347 const Node *single_node_pi1 =
2348 configuration::GetNode(single_node_factory.configuration(), "pi1");
2349 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
2350
2351 std::unique_ptr<EventLoop> single_node_event_loop =
2352 single_node_factory.MakeEventLoop("test", single_node_pi1);
2353 single_node_event_loop->SkipTimingReport();
2354 single_node_event_loop->SkipAosLog();
2355 for (size_t ii = 0;
2356 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
2357 const Channel *channel =
2358 single_node_event_loop->configuration()->channels()->Get(ii);
2359 single_node_factory.DisableForwarding(channel);
2360 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
2361 single_node_fetchers[ii] =
2362 single_node_event_loop->MakeRawFetcher(channel);
2363 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
2364 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
2365 << "Single EventLoop replay doesn't support pre-loading fetchers. "
2366 << configuration::StrippedChannelToString(channel);
2367 });
2368 single_node_event_loop->MakeRawNoArgWatcher(
2369 channel, [ii, &observed_messages, channel,
2370 kStartupDelay](const Context &context) {
2371 if (observed_messages[ii].empty()) {
2372 FAIL() << "Observed extra message at "
2373 << context.monotonic_event_time << " on "
2374 << configuration::StrippedChannelToString(channel);
2375 return;
2376 }
2377 const std::pair<monotonic_clock::time_point, bool> &message =
2378 observed_messages[ii].front();
2379 if (message.second) {
2380 EXPECT_LE(message.first,
2381 context.monotonic_event_time + kStartupDelay)
2382 << "Mismatched message times " << context.monotonic_event_time
2383 << " and " << message.first << " on "
2384 << configuration::StrippedChannelToString(channel);
2385 } else {
2386 EXPECT_EQ(message.first,
2387 context.monotonic_event_time + kStartupDelay)
2388 << "Mismatched message times " << context.monotonic_event_time
2389 << " and " << message.first << " on "
2390 << configuration::StrippedChannelToString(channel);
2391 }
2392 observed_messages[ii].erase(observed_messages[ii].begin());
2393 });
2394 }
2395 }
2396
2397 single_node_factory.Run();
2398
2399 single_node_fetchers.clear();
2400
2401 single_node_reader.Deregister();
2402
2403 for (const auto &pair : observed_messages) {
2404 EXPECT_TRUE(pair.second.empty())
2405 << "Missed " << pair.second.size() << " messages on "
2406 << configuration::StrippedChannelToString(
2407 single_node_event_loop->configuration()->channels()->Get(
2408 pair.first));
2409 }
2410}
2411
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002412// Tests that we properly recreate forwarded timestamps when replaying a log.
2413// This should be enough that we can then re-run the logger and get a valid log
2414// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002415TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002416 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002417 {
2418 LoggerState pi1_logger = MakeLogger(pi1_);
2419 LoggerState pi2_logger = MakeLogger(pi2_);
2420
2421 event_loop_factory_.RunFor(chrono::milliseconds(95));
2422
2423 StartLogger(&pi1_logger);
2424 StartLogger(&pi2_logger);
2425
2426 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2427 }
2428
Austin Schuh287d43d2020-12-04 20:19:33 -08002429 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002430
2431 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2432 log_reader_factory.set_send_delay(chrono::microseconds(0));
2433
2434 // This sends out the fetched messages and advances time to the start of the
2435 // log file.
2436 reader.Register(&log_reader_factory);
2437
2438 const Node *pi1 =
2439 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2440 const Node *pi2 =
2441 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2442
2443 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2444 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2445 LOG(INFO) << "now pi1 "
2446 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2447 LOG(INFO) << "now pi2 "
2448 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2449
Austin Schuh07676622021-01-21 18:59:17 -08002450 EXPECT_THAT(reader.LoggedNodes(),
2451 ::testing::ElementsAre(
2452 configuration::GetNode(reader.logged_configuration(), pi1),
2453 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002454
2455 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2456
2457 std::unique_ptr<EventLoop> pi1_event_loop =
2458 log_reader_factory.MakeEventLoop("test", pi1);
2459 std::unique_ptr<EventLoop> pi2_event_loop =
2460 log_reader_factory.MakeEventLoop("test", pi2);
2461
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002462 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2463 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2464 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2465 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2466
2467 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2468 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2469 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2470 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2471
2472 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2473 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2474 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2475 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2476
2477 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2478 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2479 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2480 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2481
2482 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2483 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2484 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2485 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2486
2487 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2488 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2489 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2490 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2491
Austin Schuh969cd602021-01-03 00:09:45 -08002492 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002493 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002494
Austin Schuh61e973f2021-02-21 21:43:56 -08002495 for (std::pair<int, std::string> channel :
2496 shared()
2497 ? std::vector<
2498 std::pair<int, std::string>>{{-1,
2499 "/aos/remote_timestamps/pi2"}}
2500 : std::vector<std::pair<int, std::string>>{
2501 {pi1_timestamp_channel,
2502 "/aos/remote_timestamps/pi2/pi1/aos/"
2503 "aos-message_bridge-Timestamp"},
2504 {ping_timestamp_channel,
2505 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2506 pi1_event_loop->MakeWatcher(
2507 channel.second,
2508 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2509 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2510 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2511 &ping_on_pi2_fetcher, network_delay, send_delay,
2512 channel_index = channel.first](const RemoteMessage &header) {
2513 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2514 chrono::nanoseconds(header.monotonic_sent_time()));
2515 const aos::realtime_clock::time_point header_realtime_sent_time(
2516 chrono::nanoseconds(header.realtime_sent_time()));
2517 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2518 chrono::nanoseconds(header.monotonic_remote_time()));
2519 const aos::realtime_clock::time_point header_realtime_remote_time(
2520 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002521
Austin Schuh61e973f2021-02-21 21:43:56 -08002522 if (channel_index != -1) {
2523 ASSERT_EQ(channel_index, header.channel_index());
2524 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002525
Austin Schuh61e973f2021-02-21 21:43:56 -08002526 const Context *pi1_context = nullptr;
2527 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002528
Austin Schuh61e973f2021-02-21 21:43:56 -08002529 if (header.channel_index() == pi1_timestamp_channel) {
2530 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2531 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2532 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2533 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2534 } else if (header.channel_index() == ping_timestamp_channel) {
2535 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2536 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2537 pi1_context = &ping_on_pi1_fetcher.context();
2538 pi2_context = &ping_on_pi2_fetcher.context();
2539 } else {
2540 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2541 << configuration::CleanedChannelToString(
2542 pi1_event_loop->configuration()->channels()->Get(
2543 header.channel_index()));
2544 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002545
Austin Schuh61e973f2021-02-21 21:43:56 -08002546 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002547 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2548 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002549
Austin Schuh61e973f2021-02-21 21:43:56 -08002550 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2551 EXPECT_EQ(pi2_context->remote_queue_index,
2552 header.remote_queue_index());
2553 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002554
Austin Schuh61e973f2021-02-21 21:43:56 -08002555 EXPECT_EQ(pi2_context->monotonic_event_time,
2556 header_monotonic_sent_time);
2557 EXPECT_EQ(pi2_context->realtime_event_time,
2558 header_realtime_sent_time);
2559 EXPECT_EQ(pi2_context->realtime_remote_time,
2560 header_realtime_remote_time);
2561 EXPECT_EQ(pi2_context->monotonic_remote_time,
2562 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002563
Austin Schuh61e973f2021-02-21 21:43:56 -08002564 EXPECT_EQ(pi1_context->realtime_event_time,
2565 header_realtime_remote_time);
2566 EXPECT_EQ(pi1_context->monotonic_event_time,
2567 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002568
Austin Schuh61e973f2021-02-21 21:43:56 -08002569 // Time estimation isn't perfect, but we know the clocks were
2570 // identical when logged, so we know when this should have come back.
2571 // Confirm we got it when we expected.
2572 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2573 pi1_context->monotonic_event_time + 2 * network_delay +
2574 send_delay);
2575 });
2576 }
2577 for (std::pair<int, std::string> channel :
2578 shared()
2579 ? std::vector<
2580 std::pair<int, std::string>>{{-1,
2581 "/aos/remote_timestamps/pi1"}}
2582 : std::vector<std::pair<int, std::string>>{
2583 {pi2_timestamp_channel,
2584 "/aos/remote_timestamps/pi1/pi2/aos/"
2585 "aos-message_bridge-Timestamp"}}) {
2586 pi2_event_loop->MakeWatcher(
2587 channel.second,
2588 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2589 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2590 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2591 &pong_on_pi1_fetcher, network_delay, send_delay,
2592 channel_index = channel.first](const RemoteMessage &header) {
2593 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2594 chrono::nanoseconds(header.monotonic_sent_time()));
2595 const aos::realtime_clock::time_point header_realtime_sent_time(
2596 chrono::nanoseconds(header.realtime_sent_time()));
2597 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2598 chrono::nanoseconds(header.monotonic_remote_time()));
2599 const aos::realtime_clock::time_point header_realtime_remote_time(
2600 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002601
Austin Schuh61e973f2021-02-21 21:43:56 -08002602 if (channel_index != -1) {
2603 ASSERT_EQ(channel_index, header.channel_index());
2604 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002605
Austin Schuh61e973f2021-02-21 21:43:56 -08002606 const Context *pi2_context = nullptr;
2607 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002608
Austin Schuh61e973f2021-02-21 21:43:56 -08002609 if (header.channel_index() == pi2_timestamp_channel) {
2610 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2611 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2612 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2613 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2614 } else if (header.channel_index() == pong_timestamp_channel) {
2615 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2616 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2617 pi2_context = &pong_on_pi2_fetcher.context();
2618 pi1_context = &pong_on_pi1_fetcher.context();
2619 } else {
2620 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2621 << configuration::CleanedChannelToString(
2622 pi2_event_loop->configuration()->channels()->Get(
2623 header.channel_index()));
2624 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002625
Austin Schuh61e973f2021-02-21 21:43:56 -08002626 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002627 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2628 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002629
Austin Schuh61e973f2021-02-21 21:43:56 -08002630 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2631 EXPECT_EQ(pi1_context->remote_queue_index,
2632 header.remote_queue_index());
2633 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002634
Austin Schuh61e973f2021-02-21 21:43:56 -08002635 EXPECT_EQ(pi1_context->monotonic_event_time,
2636 header_monotonic_sent_time);
2637 EXPECT_EQ(pi1_context->realtime_event_time,
2638 header_realtime_sent_time);
2639 EXPECT_EQ(pi1_context->realtime_remote_time,
2640 header_realtime_remote_time);
2641 EXPECT_EQ(pi1_context->monotonic_remote_time,
2642 header_monotonic_remote_time);
2643
2644 EXPECT_EQ(pi2_context->realtime_event_time,
2645 header_realtime_remote_time);
2646 EXPECT_EQ(pi2_context->monotonic_event_time,
2647 header_monotonic_remote_time);
2648
2649 // Time estimation isn't perfect, but we know the clocks were
2650 // identical when logged, so we know when this should have come back.
2651 // Confirm we got it when we expected.
2652 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2653 pi2_context->monotonic_event_time + 2 * network_delay +
2654 send_delay);
2655 });
2656 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002657
2658 // And confirm we can re-create a log again, while checking the contents.
2659 {
2660 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002661 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002662 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002663 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002664
Austin Schuh25b46712021-01-03 00:04:38 -08002665 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2666 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002667
2668 log_reader_factory.Run();
2669 }
2670
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002671 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002672
2673 // And verify that we can run the LogReader over the relogged files without
2674 // hitting any fatal errors.
2675 {
James Kuszmaul53da7f32022-09-11 11:11:55 -07002676 LogReader relogged_reader(SortParts(MakeLogFiles(
2677 tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2", 3, 3, true)));
2678 relogged_reader.Register();
2679
2680 relogged_reader.event_loop_factory()->Run();
2681 }
2682 // And confirm that we can read the logged file using the reader's
2683 // configuration.
2684 {
2685 LogReader relogged_reader(
2686 SortParts(MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2",
2687 3, 3, true)),
2688 reader.configuration());
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002689 relogged_reader.Register();
2690
2691 relogged_reader.event_loop_factory()->Run();
2692 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002693}
2694
Austin Schuh315b96b2020-12-11 21:21:12 -08002695// Tests that we properly populate and extract the logger_start time by setting
2696// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002697TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002698 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002699 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002700 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002701 {
2702 LoggerState pi1_logger = MakeLogger(pi1_);
2703 LoggerState pi2_logger = MakeLogger(pi2_);
2704
Austin Schuh315b96b2020-12-11 21:21:12 -08002705 StartLogger(&pi1_logger);
2706 StartLogger(&pi2_logger);
2707
2708 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002709
2710 pi1_logger.AppendAllFilenames(&actual_filenames);
2711 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002712 }
2713
Austin Schuhf5f99f32022-02-07 20:05:37 -08002714 ASSERT_THAT(actual_filenames,
2715 ::testing::UnorderedElementsAreArray(logfiles_));
2716
Austin Schuh315b96b2020-12-11 21:21:12 -08002717 for (const LogFile &log_file : SortParts(logfiles_)) {
2718 for (const LogParts &log_part : log_file.parts) {
2719 if (log_part.node == log_file.logger_node) {
2720 EXPECT_EQ(log_part.logger_monotonic_start_time,
2721 aos::monotonic_clock::min_time);
2722 EXPECT_EQ(log_part.logger_realtime_start_time,
2723 aos::realtime_clock::min_time);
2724 } else {
2725 const chrono::seconds offset = log_file.logger_node == "pi1"
2726 ? -chrono::seconds(1000)
2727 : chrono::seconds(1000);
2728 EXPECT_EQ(log_part.logger_monotonic_start_time,
2729 log_part.monotonic_start_time + offset);
2730 EXPECT_EQ(log_part.logger_realtime_start_time,
2731 log_file.realtime_start_time +
2732 (log_part.logger_monotonic_start_time -
2733 log_file.monotonic_start_time));
2734 }
2735 }
2736 }
2737}
2738
Austin Schuh6bb8a822021-03-31 23:04:39 -07002739// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002740TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002741 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2742 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002743 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002744 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002745 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2746 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2747 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2748 LoggerState pi1_logger = MakeLogger(pi1_);
2749 LoggerState pi2_logger = MakeLogger(pi2_);
2750
2751 StartLogger(&pi1_logger);
2752 StartLogger(&pi2_logger);
2753
2754 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2755 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2756 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2757 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2758 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2759 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2760 for (auto &file : logfiles_) {
2761 struct stat s;
2762 EXPECT_EQ(0, stat(file.c_str(), &s));
2763 }
2764}
2765
2766// Test that renaming the file base dies.
2767TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2768 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002769 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002770 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002771 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2772 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2773 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2774 LoggerState pi1_logger = MakeLogger(pi1_);
2775 StartLogger(&pi1_logger);
2776 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2777 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2778 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2779 "Rename of file base from");
2780}
2781
Austin Schuh8bd96322020-02-13 21:18:22 -08002782// TODO(austin): We can write a test which recreates a logfile and confirms that
2783// we get it back. That is the ultimate test.
2784
Austin Schuh315b96b2020-12-11 21:21:12 -08002785// Tests that we properly recreate forwarded timestamps when replaying a log.
2786// This should be enough that we can then re-run the logger and get a valid log
2787// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002788TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002789 std::vector<std::string> actual_filenames;
2790
Austin Schuh58646e22021-08-23 23:51:46 -07002791 const UUID pi1_boot0 = UUID::Random();
2792 const UUID pi2_boot0 = UUID::Random();
2793 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002794 {
Austin Schuh58646e22021-08-23 23:51:46 -07002795 CHECK_EQ(pi1_index_, 0u);
2796 CHECK_EQ(pi2_index_, 1u);
2797
2798 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2799 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2800 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2801
2802 time_converter_.AddNextTimestamp(
2803 distributed_clock::epoch(),
2804 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2805 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2806 time_converter_.AddNextTimestamp(
2807 distributed_clock::epoch() + reboot_time,
2808 {BootTimestamp::epoch() + reboot_time,
2809 BootTimestamp{
2810 .boot = 1,
2811 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2812 }
2813
2814 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002815 LoggerState pi1_logger = MakeLogger(pi1_);
2816
2817 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002818 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2819 pi1_boot0);
2820 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2821 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002822
2823 StartLogger(&pi1_logger);
2824
2825 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2826
Austin Schuh58646e22021-08-23 23:51:46 -07002827 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002828
2829 event_loop_factory_.RunFor(chrono::milliseconds(20000));
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_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002834
2835 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002836 }
2837
Austin Schuhbfe6c572022-01-27 20:48:20 -08002838 std::sort(actual_filenames.begin(), actual_filenames.end());
2839 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2840 ASSERT_THAT(actual_filenames,
2841 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2842
Austin Schuh72211ae2021-08-05 14:02:30 -07002843 // Confirm that our new oldest timestamps properly update as we reboot and
2844 // rotate.
2845 for (const std::string &file : pi1_reboot_logfiles_) {
2846 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2847 ReadHeader(file);
2848 CHECK(log_header);
2849 if (log_header->message().has_configuration()) {
2850 continue;
2851 }
2852
Austin Schuh58646e22021-08-23 23:51:46 -07002853 const monotonic_clock::time_point monotonic_start_time =
2854 monotonic_clock::time_point(
2855 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2856 const UUID source_node_boot_uuid = UUID::FromString(
2857 log_header->message().source_node_boot_uuid()->string_view());
2858
Austin Schuh72211ae2021-08-05 14:02:30 -07002859 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002860 // The remote message channel should rotate later and have more parts.
2861 // This only is true on the log files with shared remote messages.
2862 //
2863 // TODO(austin): I'm not the most thrilled with this test pattern... It
2864 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002865 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2866 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002867 switch (log_header->message().parts_index()) {
2868 case 0:
2869 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2870 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2871 break;
2872 case 1:
2873 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2874 ASSERT_EQ(monotonic_start_time,
2875 monotonic_clock::epoch() + chrono::seconds(1));
2876 break;
2877 case 2:
2878 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2879 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2880 break;
2881 case 3:
2882 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2883 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2884 chrono::nanoseconds(2322999462))
2885 << " on " << file;
2886 break;
2887 default:
2888 FAIL();
2889 break;
2890 }
2891 } else {
2892 switch (log_header->message().parts_index()) {
2893 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002894 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002895 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2896 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2897 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002898 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002899 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2900 ASSERT_EQ(monotonic_start_time,
2901 monotonic_clock::epoch() + chrono::seconds(1));
2902 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002903 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002904 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002905 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2906 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2907 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002908 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002909 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2910 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2911 chrono::nanoseconds(2322999462))
2912 << " on " << file;
2913 break;
2914 default:
2915 FAIL();
2916 break;
2917 }
Austin Schuh58646e22021-08-23 23:51:46 -07002918 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002919 continue;
2920 }
2921 SCOPED_TRACE(file);
2922 SCOPED_TRACE(aos::FlatbufferToJson(
2923 *log_header, {.multi_line = true, .max_vector_size = 100}));
2924 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2925 ASSERT_EQ(
2926 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2927 EXPECT_EQ(
2928 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2929 monotonic_clock::max_time.time_since_epoch().count());
2930 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2931 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2932 2u);
2933 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2934 monotonic_clock::max_time.time_since_epoch().count());
2935 ASSERT_TRUE(log_header->message()
2936 .has_oldest_remote_unreliable_monotonic_timestamps());
2937 ASSERT_EQ(log_header->message()
2938 .oldest_remote_unreliable_monotonic_timestamps()
2939 ->size(),
2940 2u);
2941 EXPECT_EQ(log_header->message()
2942 .oldest_remote_unreliable_monotonic_timestamps()
2943 ->Get(0),
2944 monotonic_clock::max_time.time_since_epoch().count());
2945 ASSERT_TRUE(log_header->message()
2946 .has_oldest_local_unreliable_monotonic_timestamps());
2947 ASSERT_EQ(log_header->message()
2948 .oldest_local_unreliable_monotonic_timestamps()
2949 ->size(),
2950 2u);
2951 EXPECT_EQ(log_header->message()
2952 .oldest_local_unreliable_monotonic_timestamps()
2953 ->Get(0),
2954 monotonic_clock::max_time.time_since_epoch().count());
2955
2956 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2957 monotonic_clock::time_point(chrono::nanoseconds(
2958 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2959 1)));
2960 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2961 monotonic_clock::time_point(chrono::nanoseconds(
2962 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2963 const monotonic_clock::time_point
2964 oldest_remote_unreliable_monotonic_timestamps =
2965 monotonic_clock::time_point(chrono::nanoseconds(
2966 log_header->message()
2967 .oldest_remote_unreliable_monotonic_timestamps()
2968 ->Get(1)));
2969 const monotonic_clock::time_point
2970 oldest_local_unreliable_monotonic_timestamps =
2971 monotonic_clock::time_point(chrono::nanoseconds(
2972 log_header->message()
2973 .oldest_local_unreliable_monotonic_timestamps()
2974 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002975 const monotonic_clock::time_point
2976 oldest_remote_reliable_monotonic_timestamps =
2977 monotonic_clock::time_point(chrono::nanoseconds(
2978 log_header->message()
2979 .oldest_remote_reliable_monotonic_timestamps()
2980 ->Get(1)));
2981 const monotonic_clock::time_point
2982 oldest_local_reliable_monotonic_timestamps =
2983 monotonic_clock::time_point(chrono::nanoseconds(
2984 log_header->message()
2985 .oldest_local_reliable_monotonic_timestamps()
2986 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002987 const monotonic_clock::time_point
2988 oldest_logger_remote_unreliable_monotonic_timestamps =
2989 monotonic_clock::time_point(chrono::nanoseconds(
2990 log_header->message()
2991 .oldest_logger_remote_unreliable_monotonic_timestamps()
2992 ->Get(0)));
2993 const monotonic_clock::time_point
2994 oldest_logger_local_unreliable_monotonic_timestamps =
2995 monotonic_clock::time_point(chrono::nanoseconds(
2996 log_header->message()
2997 .oldest_logger_local_unreliable_monotonic_timestamps()
2998 ->Get(0)));
2999 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3000 monotonic_clock::max_time);
3001 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3002 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003003 switch (log_header->message().parts_index()) {
3004 case 0:
3005 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3006 monotonic_clock::max_time);
3007 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3008 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3009 monotonic_clock::max_time);
3010 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3011 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08003012 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3013 monotonic_clock::max_time);
3014 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3015 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003016 break;
3017 case 1:
3018 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3019 monotonic_clock::time_point(chrono::microseconds(90200)));
3020 EXPECT_EQ(oldest_local_monotonic_timestamps,
3021 monotonic_clock::time_point(chrono::microseconds(90350)));
3022 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3023 monotonic_clock::time_point(chrono::microseconds(90200)));
3024 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3025 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003026 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3027 monotonic_clock::max_time);
3028 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3029 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07003030 break;
3031 case 2:
3032 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003033 monotonic_clock::time_point(chrono::microseconds(90200)))
3034 << file;
3035 EXPECT_EQ(oldest_local_monotonic_timestamps,
3036 monotonic_clock::time_point(chrono::microseconds(90350)))
3037 << file;
3038 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3039 monotonic_clock::time_point(chrono::microseconds(90200)))
3040 << file;
3041 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3042 monotonic_clock::time_point(chrono::microseconds(90350)))
3043 << file;
3044 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3045 monotonic_clock::time_point(chrono::microseconds(100000)))
3046 << file;
3047 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3048 monotonic_clock::time_point(chrono::microseconds(100150)))
3049 << file;
3050 break;
3051 case 3:
3052 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003053 monotonic_clock::time_point(chrono::milliseconds(1323) +
3054 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003055 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003056 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003057 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003058 monotonic_clock::time_point(chrono::milliseconds(1323) +
3059 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003060 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3061 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003062 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3063 monotonic_clock::max_time)
3064 << file;
3065 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3066 monotonic_clock::max_time)
3067 << file;
3068 break;
3069 case 4:
3070 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3071 monotonic_clock::time_point(chrono::milliseconds(1323) +
3072 chrono::microseconds(200)));
3073 EXPECT_EQ(oldest_local_monotonic_timestamps,
3074 monotonic_clock::time_point(chrono::microseconds(10100350)));
3075 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3076 monotonic_clock::time_point(chrono::milliseconds(1323) +
3077 chrono::microseconds(200)));
3078 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3079 monotonic_clock::time_point(chrono::microseconds(10100350)));
3080 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3081 monotonic_clock::time_point(chrono::microseconds(1423000)))
3082 << file;
3083 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3084 monotonic_clock::time_point(chrono::microseconds(10200150)))
3085 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07003086 break;
3087 default:
3088 FAIL();
3089 break;
3090 }
3091 }
3092
Austin Schuh315b96b2020-12-11 21:21:12 -08003093 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07003094 {
3095 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08003096
Austin Schuh58646e22021-08-23 23:51:46 -07003097 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3098 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08003099
Austin Schuh58646e22021-08-23 23:51:46 -07003100 // This sends out the fetched messages and advances time to the start of
3101 // the log file.
3102 reader.Register(&log_reader_factory);
3103
3104 log_reader_factory.Run();
3105
3106 reader.Deregister();
3107 }
Austin Schuh315b96b2020-12-11 21:21:12 -08003108}
3109
Austin Schuh5e14d842022-01-21 12:02:15 -08003110// Tests that we can sort a log which only has timestamps from the remote
3111// because the local message_bridge_client failed to connect.
3112TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
3113 const UUID pi1_boot0 = UUID::Random();
3114 const UUID pi2_boot0 = UUID::Random();
3115 const UUID pi2_boot1 = UUID::Random();
3116 {
3117 CHECK_EQ(pi1_index_, 0u);
3118 CHECK_EQ(pi2_index_, 1u);
3119
3120 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
3121 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
3122 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
3123
3124 time_converter_.AddNextTimestamp(
3125 distributed_clock::epoch(),
3126 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3127 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
3128 time_converter_.AddNextTimestamp(
3129 distributed_clock::epoch() + reboot_time,
3130 {BootTimestamp::epoch() + reboot_time,
3131 BootTimestamp{
3132 .boot = 1,
3133 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
3134 }
3135 pi2_->Disconnect(pi1_->node());
3136
3137 std::vector<std::string> filenames;
3138 {
3139 LoggerState pi1_logger = MakeLogger(pi1_);
3140
3141 event_loop_factory_.RunFor(chrono::milliseconds(95));
3142 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3143 pi1_boot0);
3144 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3145 pi2_boot0);
3146
3147 StartLogger(&pi1_logger);
3148
3149 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3150
3151 VLOG(1) << "Reboot now!";
3152
3153 event_loop_factory_.RunFor(chrono::milliseconds(20000));
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_boot1);
3158 pi1_logger.AppendAllFilenames(&filenames);
3159 }
3160
Austin Schuhbfe6c572022-01-27 20:48:20 -08003161 std::sort(filenames.begin(), filenames.end());
3162
Austin Schuh5e14d842022-01-21 12:02:15 -08003163 // Confirm that our new oldest timestamps properly update as we reboot and
3164 // rotate.
3165 size_t timestamp_file_count = 0;
3166 for (const std::string &file : filenames) {
3167 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
3168 ReadHeader(file);
3169 CHECK(log_header);
3170
3171 if (log_header->message().has_configuration()) {
3172 continue;
3173 }
3174
3175 const monotonic_clock::time_point monotonic_start_time =
3176 monotonic_clock::time_point(
3177 chrono::nanoseconds(log_header->message().monotonic_start_time()));
3178 const UUID source_node_boot_uuid = UUID::FromString(
3179 log_header->message().source_node_boot_uuid()->string_view());
3180
3181 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
3182 ASSERT_EQ(
3183 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
3184 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
3185 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
3186 2u);
3187 ASSERT_TRUE(log_header->message()
3188 .has_oldest_remote_unreliable_monotonic_timestamps());
3189 ASSERT_EQ(log_header->message()
3190 .oldest_remote_unreliable_monotonic_timestamps()
3191 ->size(),
3192 2u);
3193 ASSERT_TRUE(log_header->message()
3194 .has_oldest_local_unreliable_monotonic_timestamps());
3195 ASSERT_EQ(log_header->message()
3196 .oldest_local_unreliable_monotonic_timestamps()
3197 ->size(),
3198 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003199 ASSERT_TRUE(log_header->message()
3200 .has_oldest_remote_reliable_monotonic_timestamps());
3201 ASSERT_EQ(log_header->message()
3202 .oldest_remote_reliable_monotonic_timestamps()
3203 ->size(),
3204 2u);
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003205 ASSERT_TRUE(
3206 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
Austin Schuhf5f99f32022-02-07 20:05:37 -08003207 ASSERT_EQ(log_header->message()
3208 .oldest_local_reliable_monotonic_timestamps()
3209 ->size(),
3210 2u);
3211
3212 ASSERT_TRUE(
3213 log_header->message()
3214 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
3215 ASSERT_EQ(log_header->message()
3216 .oldest_logger_remote_unreliable_monotonic_timestamps()
3217 ->size(),
3218 2u);
3219 ASSERT_TRUE(log_header->message()
3220 .has_oldest_logger_local_unreliable_monotonic_timestamps());
3221 ASSERT_EQ(log_header->message()
3222 .oldest_logger_local_unreliable_monotonic_timestamps()
3223 ->size(),
3224 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08003225
3226 if (log_header->message().node()->name()->string_view() != "pi1") {
3227 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
3228 std::string::npos);
3229
3230 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
3231 ReadNthMessage(file, 0);
3232 CHECK(msg);
3233
3234 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
3235 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
3236
3237 const monotonic_clock::time_point
3238 expected_oldest_local_monotonic_timestamps(
3239 chrono::nanoseconds(msg->message().monotonic_sent_time()));
3240 const monotonic_clock::time_point
3241 expected_oldest_remote_monotonic_timestamps(
3242 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003243 const monotonic_clock::time_point
3244 expected_oldest_timestamp_monotonic_timestamps(
3245 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08003246
3247 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
3248 monotonic_clock::min_time);
3249 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
3250 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003251 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
3252 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08003253
3254 ++timestamp_file_count;
3255 // Since the log file is from the perspective of the other node,
3256 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3257 monotonic_clock::time_point(chrono::nanoseconds(
3258 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3259 0)));
3260 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3261 monotonic_clock::time_point(chrono::nanoseconds(
3262 log_header->message().oldest_local_monotonic_timestamps()->Get(
3263 0)));
3264 const monotonic_clock::time_point
3265 oldest_remote_unreliable_monotonic_timestamps =
3266 monotonic_clock::time_point(chrono::nanoseconds(
3267 log_header->message()
3268 .oldest_remote_unreliable_monotonic_timestamps()
3269 ->Get(0)));
3270 const monotonic_clock::time_point
3271 oldest_local_unreliable_monotonic_timestamps =
3272 monotonic_clock::time_point(chrono::nanoseconds(
3273 log_header->message()
3274 .oldest_local_unreliable_monotonic_timestamps()
3275 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003276 const monotonic_clock::time_point
3277 oldest_remote_reliable_monotonic_timestamps =
3278 monotonic_clock::time_point(chrono::nanoseconds(
3279 log_header->message()
3280 .oldest_remote_reliable_monotonic_timestamps()
3281 ->Get(0)));
3282 const monotonic_clock::time_point
3283 oldest_local_reliable_monotonic_timestamps =
3284 monotonic_clock::time_point(chrono::nanoseconds(
3285 log_header->message()
3286 .oldest_local_reliable_monotonic_timestamps()
3287 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003288 const monotonic_clock::time_point
3289 oldest_logger_remote_unreliable_monotonic_timestamps =
3290 monotonic_clock::time_point(chrono::nanoseconds(
3291 log_header->message()
3292 .oldest_logger_remote_unreliable_monotonic_timestamps()
3293 ->Get(1)));
3294 const monotonic_clock::time_point
3295 oldest_logger_local_unreliable_monotonic_timestamps =
3296 monotonic_clock::time_point(chrono::nanoseconds(
3297 log_header->message()
3298 .oldest_logger_local_unreliable_monotonic_timestamps()
3299 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08003300
Austin Schuh01f3b392022-01-25 20:03:09 -08003301 const Channel *channel =
3302 event_loop_factory_.configuration()->channels()->Get(
3303 msg->message().channel_index());
3304 const Connection *connection = configuration::ConnectionToNode(
3305 channel, configuration::GetNode(
3306 event_loop_factory_.configuration(),
3307 log_header->message().node()->name()->string_view()));
3308
3309 const bool reliable = connection->time_to_live() == 0;
3310
Austin Schuhf5f99f32022-02-07 20:05:37 -08003311 SCOPED_TRACE(file);
3312 SCOPED_TRACE(aos::FlatbufferToJson(
3313 *log_header, {.multi_line = true, .max_vector_size = 100}));
3314
Austin Schuh01f3b392022-01-25 20:03:09 -08003315 if (shared()) {
3316 // Confirm that the oldest timestamps match what we expect. Based on
3317 // what we are doing, we know that the oldest time is the first
3318 // message's time.
3319 //
3320 // This makes the test robust to both the split and combined config
3321 // tests.
3322 switch (log_header->message().parts_index()) {
3323 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08003324 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3325 expected_oldest_remote_monotonic_timestamps);
3326 EXPECT_EQ(oldest_local_monotonic_timestamps,
3327 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003328 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003329 expected_oldest_local_monotonic_timestamps)
3330 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003331 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003332 expected_oldest_timestamp_monotonic_timestamps)
3333 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003334
Austin Schuh01f3b392022-01-25 20:03:09 -08003335 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003336 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3337 expected_oldest_remote_monotonic_timestamps);
3338 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3339 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08003340 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3341 monotonic_clock::max_time);
3342 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3343 monotonic_clock::max_time);
3344 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003345 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3346 monotonic_clock::max_time);
3347 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3348 monotonic_clock::max_time);
3349 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3350 expected_oldest_remote_monotonic_timestamps);
3351 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3352 expected_oldest_local_monotonic_timestamps);
3353 }
3354 break;
3355 case 1:
3356 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3357 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3358 EXPECT_EQ(oldest_local_monotonic_timestamps,
3359 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003360 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3361 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3362 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3363 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003364 if (reliable) {
3365 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3366 expected_oldest_remote_monotonic_timestamps);
3367 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3368 expected_oldest_local_monotonic_timestamps);
3369 EXPECT_EQ(
3370 oldest_remote_unreliable_monotonic_timestamps,
3371 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3372 EXPECT_EQ(
3373 oldest_local_unreliable_monotonic_timestamps,
3374 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3375 } else {
3376 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3377 monotonic_clock::max_time);
3378 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3379 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003380 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3381 expected_oldest_remote_monotonic_timestamps);
3382 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3383 expected_oldest_local_monotonic_timestamps);
3384 }
3385 break;
3386 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003387 EXPECT_EQ(
3388 oldest_remote_monotonic_timestamps,
3389 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3390 EXPECT_EQ(
3391 oldest_local_monotonic_timestamps,
3392 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003393 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003394 expected_oldest_local_monotonic_timestamps)
3395 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003396 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003397 expected_oldest_timestamp_monotonic_timestamps)
3398 << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003399 if (reliable) {
3400 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3401 expected_oldest_remote_monotonic_timestamps);
3402 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3403 expected_oldest_local_monotonic_timestamps);
3404 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3405 monotonic_clock::max_time);
3406 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3407 monotonic_clock::max_time);
3408 } else {
3409 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3410 monotonic_clock::max_time);
3411 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3412 monotonic_clock::max_time);
3413 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3414 expected_oldest_remote_monotonic_timestamps);
3415 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3416 expected_oldest_local_monotonic_timestamps);
3417 }
3418 break;
3419
3420 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003421 EXPECT_EQ(
3422 oldest_remote_monotonic_timestamps,
3423 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3424 EXPECT_EQ(
3425 oldest_local_monotonic_timestamps,
3426 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3427 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3428 expected_oldest_remote_monotonic_timestamps);
3429 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3430 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003431 EXPECT_EQ(
3432 oldest_logger_remote_unreliable_monotonic_timestamps,
3433 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3434 EXPECT_EQ(
3435 oldest_logger_local_unreliable_monotonic_timestamps,
3436 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003437 break;
3438 default:
3439 FAIL();
3440 break;
3441 }
3442
3443 switch (log_header->message().parts_index()) {
3444 case 0:
3445 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3446 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3447 break;
3448 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003449 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003450 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3451 break;
3452 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003453 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3454 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3455 break;
3456 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003457 if (shared()) {
3458 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3459 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003460 break;
3461 }
3462 [[fallthrough]];
3463 default:
3464 FAIL();
3465 break;
3466 }
3467 } else {
3468 switch (log_header->message().parts_index()) {
3469 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003470 if (reliable) {
3471 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3472 monotonic_clock::max_time);
3473 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3474 monotonic_clock::max_time);
3475 EXPECT_EQ(
3476 oldest_logger_remote_unreliable_monotonic_timestamps,
3477 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3478 << file;
3479 EXPECT_EQ(
3480 oldest_logger_local_unreliable_monotonic_timestamps,
3481 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3482 << file;
3483 } else {
3484 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3485 expected_oldest_remote_monotonic_timestamps);
3486 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3487 expected_oldest_local_monotonic_timestamps);
3488 EXPECT_EQ(
3489 oldest_logger_remote_unreliable_monotonic_timestamps,
3490 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3491 << file;
3492 EXPECT_EQ(
3493 oldest_logger_local_unreliable_monotonic_timestamps,
3494 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3495 << file;
3496 }
3497 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003498 case 1:
3499 if (reliable) {
3500 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3501 monotonic_clock::max_time);
3502 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3503 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003504 EXPECT_EQ(
3505 oldest_logger_remote_unreliable_monotonic_timestamps,
3506 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3507 EXPECT_EQ(
3508 oldest_logger_local_unreliable_monotonic_timestamps,
3509 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003510 } else {
3511 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3512 expected_oldest_remote_monotonic_timestamps);
3513 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3514 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003515 EXPECT_EQ(
3516 oldest_logger_remote_unreliable_monotonic_timestamps,
3517 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3518 EXPECT_EQ(
3519 oldest_logger_local_unreliable_monotonic_timestamps,
3520 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003521 }
3522 break;
3523 default:
3524 FAIL();
3525 break;
3526 }
3527
3528 switch (log_header->message().parts_index()) {
3529 case 0:
3530 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3531 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3532 break;
3533 case 1:
3534 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3535 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3536 break;
3537 default:
3538 FAIL();
3539 break;
3540 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003541 }
3542
3543 continue;
3544 }
3545 EXPECT_EQ(
3546 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3547 monotonic_clock::max_time.time_since_epoch().count());
3548 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3549 monotonic_clock::max_time.time_since_epoch().count());
3550 EXPECT_EQ(log_header->message()
3551 .oldest_remote_unreliable_monotonic_timestamps()
3552 ->Get(0),
3553 monotonic_clock::max_time.time_since_epoch().count());
3554 EXPECT_EQ(log_header->message()
3555 .oldest_local_unreliable_monotonic_timestamps()
3556 ->Get(0),
3557 monotonic_clock::max_time.time_since_epoch().count());
3558
3559 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3560 monotonic_clock::time_point(chrono::nanoseconds(
3561 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3562 1)));
3563 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3564 monotonic_clock::time_point(chrono::nanoseconds(
3565 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3566 const monotonic_clock::time_point
3567 oldest_remote_unreliable_monotonic_timestamps =
3568 monotonic_clock::time_point(chrono::nanoseconds(
3569 log_header->message()
3570 .oldest_remote_unreliable_monotonic_timestamps()
3571 ->Get(1)));
3572 const monotonic_clock::time_point
3573 oldest_local_unreliable_monotonic_timestamps =
3574 monotonic_clock::time_point(chrono::nanoseconds(
3575 log_header->message()
3576 .oldest_local_unreliable_monotonic_timestamps()
3577 ->Get(1)));
3578 switch (log_header->message().parts_index()) {
3579 case 0:
3580 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3581 monotonic_clock::max_time);
3582 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3583 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3584 monotonic_clock::max_time);
3585 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3586 monotonic_clock::max_time);
3587 break;
3588 default:
3589 FAIL();
3590 break;
3591 }
3592 }
3593
Austin Schuh01f3b392022-01-25 20:03:09 -08003594 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003595 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003596 } else {
3597 EXPECT_EQ(timestamp_file_count, 4u);
3598 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003599
Austin Schuhe2373e22022-01-21 12:25:17 -08003600 // Confirm that we can actually sort the resulting log and read it.
3601 {
3602 LogReader reader(SortParts(filenames));
3603
3604 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3605 log_reader_factory.set_send_delay(chrono::microseconds(0));
3606
3607 // This sends out the fetched messages and advances time to the start of
3608 // the log file.
3609 reader.Register(&log_reader_factory);
3610
3611 log_reader_factory.Run();
3612
3613 reader.Deregister();
3614 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003615}
3616
Austin Schuhc9049732020-12-21 22:27:15 -08003617// Tests that we properly handle one direction of message_bridge being
3618// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003619TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003620 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003621 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003622 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003623
3624 time_converter_.AddMonotonic(
3625 {chrono::milliseconds(10000),
3626 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003627 {
3628 LoggerState pi1_logger = MakeLogger(pi1_);
3629
3630 event_loop_factory_.RunFor(chrono::milliseconds(95));
3631
3632 StartLogger(&pi1_logger);
3633
3634 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3635 }
3636
3637 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3638 // to confirm the right thing happened.
3639 ConfirmReadable(pi1_single_direction_logfiles_);
3640}
3641
3642// Tests that we properly handle one direction of message_bridge being
3643// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003644TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003645 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003646 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003647 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003648
3649 time_converter_.AddMonotonic(
3650 {chrono::milliseconds(10000),
3651 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3652 {
3653 LoggerState pi1_logger = MakeLogger(pi1_);
3654
3655 event_loop_factory_.RunFor(chrono::milliseconds(95));
3656
3657 StartLogger(&pi1_logger);
3658
3659 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3660 }
3661
3662 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3663 // to confirm the right thing happened.
3664 ConfirmReadable(pi1_single_direction_logfiles_);
3665}
3666
Austin Schuhe9f00232021-09-16 18:04:23 -07003667// Tests that we explode if someone passes in a part file twice with a better
3668// error than an out of order error.
3669TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3670 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003671 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003672 {
3673 LoggerState pi1_logger = MakeLogger(pi1_);
3674
3675 event_loop_factory_.RunFor(chrono::milliseconds(95));
3676
3677 StartLogger(&pi1_logger);
3678
3679 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3680 }
3681
3682 std::vector<std::string> duplicates;
3683 for (const std::string &f : pi1_single_direction_logfiles_) {
3684 duplicates.emplace_back(f);
3685 duplicates.emplace_back(f);
3686 }
3687 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3688}
3689
Austin Schuh22cf7862022-09-19 19:09:42 -07003690// Tests that we explode if someone loses a part out of the middle of a log.
3691TEST_P(MultinodeLoggerTest, MissingPartsFromMiddle) {
3692 time_converter_.AddMonotonic(
3693 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
3694 {
3695 LoggerState pi1_logger = MakeLogger(pi1_);
3696
3697 event_loop_factory_.RunFor(chrono::milliseconds(95));
3698
3699
3700 StartLogger(&pi1_logger);
3701 aos::monotonic_clock::time_point last_rotation_time =
3702 pi1_logger.event_loop->monotonic_now();
3703 pi1_logger.logger->set_on_logged_period([&] {
3704 const auto now = pi1_logger.event_loop->monotonic_now();
3705 if (now > last_rotation_time + std::chrono::seconds(5)) {
3706 pi1_logger.logger->Rotate();
3707 last_rotation_time = now;
3708 }
3709 });
3710
3711 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3712 }
3713
3714 std::vector<std::string> missing_parts;
3715
3716 missing_parts.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
3717 missing_parts.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
3718 missing_parts.emplace_back(absl::StrCat(
3719 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
3720
3721 EXPECT_DEATH({ SortParts(missing_parts); },
3722 "Broken log, missing part files between");
3723}
3724
Austin Schuh87dd3832021-01-01 23:07:31 -08003725// Tests that we properly handle a dead node. Do this by just disconnecting it
3726// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003727TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003728 pi1_->Disconnect(pi2_->node());
3729 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003730 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003731 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003732 {
3733 LoggerState pi1_logger = MakeLogger(pi1_);
3734
3735 event_loop_factory_.RunFor(chrono::milliseconds(95));
3736
3737 StartLogger(&pi1_logger);
3738
3739 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3740 }
3741
3742 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3743 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003744 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003745}
3746
Austin Schuhcdd90272021-03-15 12:46:16 -07003747constexpr std::string_view kCombinedConfigSha1(
Austin Schuh13ec0722022-09-26 18:12:16 -07003748 "c10ca3c1efa7924d48859000b6671eadc007b6373c81d07138a385dfdbb33d69");
Austin Schuhcdd90272021-03-15 12:46:16 -07003749constexpr std::string_view kSplitConfigSha1(
Austin Schuh13ec0722022-09-26 18:12:16 -07003750 "f8df4ee52e137025dac96303f8d38a5324fd819d1c22ff018754dd56c3ca64e8");
James Kuszmaul53da7f32022-09-11 11:11:55 -07003751constexpr std::string_view kReloggedSplitConfigSha1(
Austin Schuh13ec0722022-09-26 18:12:16 -07003752 "3154b2a9f9819d676d40c689a6c2967c2c64152c2845673b78d0c1cdc368d3ec");
Austin Schuhcdd90272021-03-15 12:46:16 -07003753
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003754INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003755 All, MultinodeLoggerTest,
James Kuszmaul53da7f32022-09-11 11:11:55 -07003756 ::testing::Combine(
3757 ::testing::Values(
3758 ConfigParams{"multinode_pingpong_combined_config.json", true,
3759 kCombinedConfigSha1, kCombinedConfigSha1},
3760 ConfigParams{"multinode_pingpong_split_config.json", false,
3761 kSplitConfigSha1, kReloggedSplitConfigSha1}),
3762 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003763
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003764INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003765 All, MultinodeLoggerDeathTest,
James Kuszmaul53da7f32022-09-11 11:11:55 -07003766 ::testing::Combine(
3767 ::testing::Values(
3768 ConfigParams{"multinode_pingpong_combined_config.json", true,
3769 kCombinedConfigSha1, kCombinedConfigSha1},
3770 ConfigParams{"multinode_pingpong_split_config.json", false,
3771 kSplitConfigSha1, kReloggedSplitConfigSha1}),
3772 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003773
Austin Schuh5b728b72021-06-16 14:57:15 -07003774// Tests that we can relog with a different config. This makes most sense when
3775// you are trying to edit a log and want to use channel renaming + the original
3776// config in the new log.
3777TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3778 time_converter_.StartEqual();
3779 {
3780 LoggerState pi1_logger = MakeLogger(pi1_);
3781 LoggerState pi2_logger = MakeLogger(pi2_);
3782
3783 event_loop_factory_.RunFor(chrono::milliseconds(95));
3784
3785 StartLogger(&pi1_logger);
3786 StartLogger(&pi2_logger);
3787
3788 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3789 }
3790
3791 LogReader reader(SortParts(logfiles_));
3792 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3793
3794 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3795 log_reader_factory.set_send_delay(chrono::microseconds(0));
3796
3797 // This sends out the fetched messages and advances time to the start of the
3798 // log file.
3799 reader.Register(&log_reader_factory);
3800
3801 const Node *pi1 =
3802 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3803 const Node *pi2 =
3804 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3805
3806 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3807 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3808 LOG(INFO) << "now pi1 "
3809 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3810 LOG(INFO) << "now pi2 "
3811 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3812
3813 EXPECT_THAT(reader.LoggedNodes(),
3814 ::testing::ElementsAre(
3815 configuration::GetNode(reader.logged_configuration(), pi1),
3816 configuration::GetNode(reader.logged_configuration(), pi2)));
3817
3818 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3819
3820 // And confirm we can re-create a log again, while checking the contents.
3821 std::vector<std::string> log_files;
3822 {
3823 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003824 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003825 &log_reader_factory, reader.logged_configuration());
3826 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003827 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003828 &log_reader_factory, reader.logged_configuration());
3829
Austin Schuh3e20c692021-11-16 20:43:16 -08003830 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3831 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003832
3833 log_reader_factory.Run();
3834
3835 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3836 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3837 }
3838 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3839 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3840 }
3841 }
3842
3843 reader.Deregister();
3844
3845 // And verify that we can run the LogReader over the relogged files without
3846 // hitting any fatal errors.
3847 {
3848 LogReader relogged_reader(SortParts(log_files));
3849 relogged_reader.Register();
3850
3851 relogged_reader.event_loop_factory()->Run();
3852 }
3853}
Austin Schuha04efed2021-01-24 18:04:20 -08003854
Austin Schuh3e20c692021-11-16 20:43:16 -08003855// Tests that we properly replay a log where the start time for a node is before
3856// any data on the node. This can happen if the logger starts before data is
3857// published. While the scenario below is a bit convoluted, we have seen logs
3858// like this generated out in the wild.
3859TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3860 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3861 aos::configuration::ReadConfig(ArtifactPath(
3862 "aos/events/logging/multinode_pingpong_split3_config.json"));
3863 message_bridge::TestingTimeConverter time_converter(
3864 configuration::NodesCount(&config.message()));
3865 SimulatedEventLoopFactory event_loop_factory(&config.message());
3866 event_loop_factory.SetTimeConverter(&time_converter);
3867 NodeEventLoopFactory *const pi1 =
3868 event_loop_factory.GetNodeEventLoopFactory("pi1");
3869 const size_t pi1_index = configuration::GetNodeIndex(
3870 event_loop_factory.configuration(), pi1->node());
3871 NodeEventLoopFactory *const pi2 =
3872 event_loop_factory.GetNodeEventLoopFactory("pi2");
3873 const size_t pi2_index = configuration::GetNodeIndex(
3874 event_loop_factory.configuration(), pi2->node());
3875 NodeEventLoopFactory *const pi3 =
3876 event_loop_factory.GetNodeEventLoopFactory("pi3");
3877 const size_t pi3_index = configuration::GetNodeIndex(
3878 event_loop_factory.configuration(), pi3->node());
3879
3880 const std::string kLogfile1_1 =
3881 aos::testing::TestTmpDir() + "/multi_logfile1/";
3882 const std::string kLogfile2_1 =
3883 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3884 const std::string kLogfile2_2 =
3885 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3886 const std::string kLogfile3_1 =
3887 aos::testing::TestTmpDir() + "/multi_logfile3/";
3888 util::UnlinkRecursive(kLogfile1_1);
3889 util::UnlinkRecursive(kLogfile2_1);
3890 util::UnlinkRecursive(kLogfile2_2);
3891 util::UnlinkRecursive(kLogfile3_1);
3892 const UUID pi1_boot0 = UUID::Random();
3893 const UUID pi2_boot0 = UUID::Random();
3894 const UUID pi2_boot1 = UUID::Random();
3895 const UUID pi3_boot0 = UUID::Random();
3896 {
3897 CHECK_EQ(pi1_index, 0u);
3898 CHECK_EQ(pi2_index, 1u);
3899 CHECK_EQ(pi3_index, 2u);
3900
3901 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3902 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3903 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3904 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3905
3906 time_converter.AddNextTimestamp(
3907 distributed_clock::epoch(),
3908 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3909 BootTimestamp::epoch()});
3910 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3911 time_converter.AddNextTimestamp(
3912 distributed_clock::epoch() + reboot_time,
3913 {BootTimestamp::epoch() + reboot_time,
3914 BootTimestamp{
3915 .boot = 1,
3916 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3917 BootTimestamp::epoch() + reboot_time});
3918 }
3919
3920 // Make everything perfectly quiet.
3921 event_loop_factory.SkipTimingReport();
3922 event_loop_factory.DisableStatistics();
3923
3924 std::vector<std::string> filenames;
3925 {
3926 LoggerState pi1_logger = LoggerState::MakeLogger(
3927 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3928 LoggerState pi3_logger = LoggerState::MakeLogger(
3929 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3930 {
3931 // And now start the logger.
3932 LoggerState pi2_logger = LoggerState::MakeLogger(
3933 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3934
3935 event_loop_factory.RunFor(chrono::milliseconds(1000));
3936
3937 pi1_logger.StartLogger(kLogfile1_1);
3938 pi3_logger.StartLogger(kLogfile3_1);
3939 pi2_logger.StartLogger(kLogfile2_1);
3940
3941 event_loop_factory.RunFor(chrono::milliseconds(10000));
3942
3943 // Now that we've got a start time in the past, turn on data.
3944 event_loop_factory.EnableStatistics();
3945 std::unique_ptr<aos::EventLoop> ping_event_loop =
3946 pi1->MakeEventLoop("ping");
3947 Ping ping(ping_event_loop.get());
3948
3949 pi2->AlwaysStart<Pong>("pong");
3950
3951 event_loop_factory.RunFor(chrono::milliseconds(3000));
3952
3953 pi2_logger.AppendAllFilenames(&filenames);
3954
3955 // Stop logging on pi2 before rebooting and completely shut off all
3956 // messages on pi2.
3957 pi2->DisableStatistics();
3958 pi1->Disconnect(pi2->node());
3959 pi2->Disconnect(pi1->node());
3960 }
3961 event_loop_factory.RunFor(chrono::milliseconds(7000));
3962 // pi2 now reboots.
3963 {
3964 event_loop_factory.RunFor(chrono::milliseconds(1000));
3965
3966 // Start logging again on pi2 after it is up.
3967 LoggerState pi2_logger = LoggerState::MakeLogger(
3968 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3969 pi2_logger.StartLogger(kLogfile2_2);
3970
3971 event_loop_factory.RunFor(chrono::milliseconds(10000));
3972 // And, now that we have a start time in the log, turn data back on.
3973 pi2->EnableStatistics();
3974 pi1->Connect(pi2->node());
3975 pi2->Connect(pi1->node());
3976
3977 pi2->AlwaysStart<Pong>("pong");
3978 std::unique_ptr<aos::EventLoop> ping_event_loop =
3979 pi1->MakeEventLoop("ping");
3980 Ping ping(ping_event_loop.get());
3981
3982 event_loop_factory.RunFor(chrono::milliseconds(3000));
3983
3984 pi2_logger.AppendAllFilenames(&filenames);
3985 }
3986
3987 pi1_logger.AppendAllFilenames(&filenames);
3988 pi3_logger.AppendAllFilenames(&filenames);
3989 }
3990
3991 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3992 // to confirm the right thing happened.
3993 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003994 auto result = ConfirmReadable(filenames);
3995 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3996 chrono::seconds(1)));
3997 EXPECT_THAT(result[0].second,
3998 ::testing::ElementsAre(realtime_clock::epoch() +
3999 chrono::microseconds(34990350)));
4000
4001 EXPECT_THAT(result[1].first,
4002 ::testing::ElementsAre(
4003 realtime_clock::epoch() + chrono::seconds(1),
4004 realtime_clock::epoch() + chrono::microseconds(3323000)));
4005 EXPECT_THAT(result[1].second,
4006 ::testing::ElementsAre(
4007 realtime_clock::epoch() + chrono::microseconds(13990200),
4008 realtime_clock::epoch() + chrono::microseconds(16313200)));
4009
4010 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
4011 chrono::seconds(1)));
4012 EXPECT_THAT(result[2].second,
4013 ::testing::ElementsAre(realtime_clock::epoch() +
4014 chrono::microseconds(34900150)));
Austin Schuh3e20c692021-11-16 20:43:16 -08004015}
4016
Austin Schuh5dd22842021-11-17 16:09:39 -08004017// Tests that local data before remote data after reboot is properly replayed.
4018// We only trigger a reboot in the timestamp interpolation function when solving
4019// the timestamp problem when we actually have a point in the function. This
4020// originally only happened when a point passes the noncausal filter. At the
4021// start of time for the second boot, if we aren't careful, we will have
4022// messages which need to be published at times before the boot. This happens
4023// when a local message is in the log before a forwarded message, so there is no
4024// point in the interpolation function. This delays the reboot. So, we need to
4025// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08004026TEST(MultinodeRebootLoggerTest,
4027 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08004028 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4029 aos::configuration::ReadConfig(ArtifactPath(
4030 "aos/events/logging/multinode_pingpong_split3_config.json"));
4031 message_bridge::TestingTimeConverter time_converter(
4032 configuration::NodesCount(&config.message()));
4033 SimulatedEventLoopFactory event_loop_factory(&config.message());
4034 event_loop_factory.SetTimeConverter(&time_converter);
4035 NodeEventLoopFactory *const pi1 =
4036 event_loop_factory.GetNodeEventLoopFactory("pi1");
4037 const size_t pi1_index = configuration::GetNodeIndex(
4038 event_loop_factory.configuration(), pi1->node());
4039 NodeEventLoopFactory *const pi2 =
4040 event_loop_factory.GetNodeEventLoopFactory("pi2");
4041 const size_t pi2_index = configuration::GetNodeIndex(
4042 event_loop_factory.configuration(), pi2->node());
4043 NodeEventLoopFactory *const pi3 =
4044 event_loop_factory.GetNodeEventLoopFactory("pi3");
4045 const size_t pi3_index = configuration::GetNodeIndex(
4046 event_loop_factory.configuration(), pi3->node());
4047
4048 const std::string kLogfile1_1 =
4049 aos::testing::TestTmpDir() + "/multi_logfile1/";
4050 const std::string kLogfile2_1 =
4051 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4052 const std::string kLogfile2_2 =
4053 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4054 const std::string kLogfile3_1 =
4055 aos::testing::TestTmpDir() + "/multi_logfile3/";
4056 util::UnlinkRecursive(kLogfile1_1);
4057 util::UnlinkRecursive(kLogfile2_1);
4058 util::UnlinkRecursive(kLogfile2_2);
4059 util::UnlinkRecursive(kLogfile3_1);
4060 const UUID pi1_boot0 = UUID::Random();
4061 const UUID pi2_boot0 = UUID::Random();
4062 const UUID pi2_boot1 = UUID::Random();
4063 const UUID pi3_boot0 = UUID::Random();
4064 {
4065 CHECK_EQ(pi1_index, 0u);
4066 CHECK_EQ(pi2_index, 1u);
4067 CHECK_EQ(pi3_index, 2u);
4068
4069 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
4070 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
4071 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
4072 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
4073
4074 time_converter.AddNextTimestamp(
4075 distributed_clock::epoch(),
4076 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4077 BootTimestamp::epoch()});
4078 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4079 time_converter.AddNextTimestamp(
4080 distributed_clock::epoch() + reboot_time,
4081 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08004082 BootTimestamp{.boot = 1,
4083 .time = monotonic_clock::epoch() + reboot_time +
4084 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08004085 BootTimestamp::epoch() + reboot_time});
4086 }
4087
4088 std::vector<std::string> filenames;
4089 {
4090 LoggerState pi1_logger = LoggerState::MakeLogger(
4091 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4092 LoggerState pi3_logger = LoggerState::MakeLogger(
4093 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4094 {
4095 // And now start the logger.
4096 LoggerState pi2_logger = LoggerState::MakeLogger(
4097 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4098
4099 pi1_logger.StartLogger(kLogfile1_1);
4100 pi3_logger.StartLogger(kLogfile3_1);
4101 pi2_logger.StartLogger(kLogfile2_1);
4102
4103 event_loop_factory.RunFor(chrono::milliseconds(1005));
4104
4105 // Now that we've got a start time in the past, turn on data.
4106 std::unique_ptr<aos::EventLoop> ping_event_loop =
4107 pi1->MakeEventLoop("ping");
4108 Ping ping(ping_event_loop.get());
4109
4110 pi2->AlwaysStart<Pong>("pong");
4111
4112 event_loop_factory.RunFor(chrono::milliseconds(3000));
4113
4114 pi2_logger.AppendAllFilenames(&filenames);
4115
4116 // Disable any remote messages on pi2.
4117 pi1->Disconnect(pi2->node());
4118 pi2->Disconnect(pi1->node());
4119 }
4120 event_loop_factory.RunFor(chrono::milliseconds(995));
4121 // pi2 now reboots at 5 seconds.
4122 {
4123 event_loop_factory.RunFor(chrono::milliseconds(1000));
4124
4125 // Make local stuff happen before we start logging and connect the remote.
4126 pi2->AlwaysStart<Pong>("pong");
4127 std::unique_ptr<aos::EventLoop> ping_event_loop =
4128 pi1->MakeEventLoop("ping");
4129 Ping ping(ping_event_loop.get());
4130 event_loop_factory.RunFor(chrono::milliseconds(1005));
4131
4132 // Start logging again on pi2 after it is up.
4133 LoggerState pi2_logger = LoggerState::MakeLogger(
4134 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4135 pi2_logger.StartLogger(kLogfile2_2);
4136
4137 // And allow remote messages now that we have some local ones.
4138 pi1->Connect(pi2->node());
4139 pi2->Connect(pi1->node());
4140
4141 event_loop_factory.RunFor(chrono::milliseconds(1000));
4142
4143 event_loop_factory.RunFor(chrono::milliseconds(3000));
4144
4145 pi2_logger.AppendAllFilenames(&filenames);
4146 }
4147
4148 pi1_logger.AppendAllFilenames(&filenames);
4149 pi3_logger.AppendAllFilenames(&filenames);
4150 }
4151
4152 // Confirm that we can parse the result. LogReader has enough internal CHECKs
4153 // to confirm the right thing happened.
4154 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08004155 auto result = ConfirmReadable(filenames);
4156
4157 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4158 EXPECT_THAT(result[0].second,
4159 ::testing::ElementsAre(realtime_clock::epoch() +
4160 chrono::microseconds(11000350)));
4161
4162 EXPECT_THAT(result[1].first,
4163 ::testing::ElementsAre(
4164 realtime_clock::epoch(),
4165 realtime_clock::epoch() + chrono::microseconds(107005000)));
4166 EXPECT_THAT(result[1].second,
4167 ::testing::ElementsAre(
4168 realtime_clock::epoch() + chrono::microseconds(4000150),
4169 realtime_clock::epoch() + chrono::microseconds(111000200)));
4170
4171 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4172 EXPECT_THAT(result[2].second,
4173 ::testing::ElementsAre(realtime_clock::epoch() +
4174 chrono::microseconds(11000150)));
4175
4176 auto start_stop_result = ConfirmReadable(
4177 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4178 realtime_clock::epoch() + chrono::milliseconds(3000));
4179
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004180 EXPECT_THAT(
4181 start_stop_result[0].first,
4182 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4183 EXPECT_THAT(
4184 start_stop_result[0].second,
4185 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4186 EXPECT_THAT(
4187 start_stop_result[1].first,
4188 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4189 EXPECT_THAT(
4190 start_stop_result[1].second,
4191 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4192 EXPECT_THAT(
4193 start_stop_result[2].first,
4194 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4195 EXPECT_THAT(
4196 start_stop_result[2].second,
4197 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
Austin Schuh5dd22842021-11-17 16:09:39 -08004198}
4199
Austin Schuhe33c08d2022-02-03 18:15:21 -08004200// Tests that setting the start and stop flags across a reboot works as
4201// expected.
4202TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
4203 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4204 aos::configuration::ReadConfig(ArtifactPath(
4205 "aos/events/logging/multinode_pingpong_split3_config.json"));
4206 message_bridge::TestingTimeConverter time_converter(
4207 configuration::NodesCount(&config.message()));
4208 SimulatedEventLoopFactory event_loop_factory(&config.message());
4209 event_loop_factory.SetTimeConverter(&time_converter);
4210 NodeEventLoopFactory *const pi1 =
4211 event_loop_factory.GetNodeEventLoopFactory("pi1");
4212 const size_t pi1_index = configuration::GetNodeIndex(
4213 event_loop_factory.configuration(), pi1->node());
4214 NodeEventLoopFactory *const pi2 =
4215 event_loop_factory.GetNodeEventLoopFactory("pi2");
4216 const size_t pi2_index = configuration::GetNodeIndex(
4217 event_loop_factory.configuration(), pi2->node());
4218 NodeEventLoopFactory *const pi3 =
4219 event_loop_factory.GetNodeEventLoopFactory("pi3");
4220 const size_t pi3_index = configuration::GetNodeIndex(
4221 event_loop_factory.configuration(), pi3->node());
4222
4223 const std::string kLogfile1_1 =
4224 aos::testing::TestTmpDir() + "/multi_logfile1/";
4225 const std::string kLogfile2_1 =
4226 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4227 const std::string kLogfile2_2 =
4228 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4229 const std::string kLogfile3_1 =
4230 aos::testing::TestTmpDir() + "/multi_logfile3/";
4231 util::UnlinkRecursive(kLogfile1_1);
4232 util::UnlinkRecursive(kLogfile2_1);
4233 util::UnlinkRecursive(kLogfile2_2);
4234 util::UnlinkRecursive(kLogfile3_1);
4235 {
4236 CHECK_EQ(pi1_index, 0u);
4237 CHECK_EQ(pi2_index, 1u);
4238 CHECK_EQ(pi3_index, 2u);
4239
4240 time_converter.AddNextTimestamp(
4241 distributed_clock::epoch(),
4242 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4243 BootTimestamp::epoch()});
4244 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4245 time_converter.AddNextTimestamp(
4246 distributed_clock::epoch() + reboot_time,
4247 {BootTimestamp::epoch() + reboot_time,
4248 BootTimestamp{.boot = 1,
4249 .time = monotonic_clock::epoch() + reboot_time},
4250 BootTimestamp::epoch() + reboot_time});
4251 }
4252
4253 std::vector<std::string> filenames;
4254 {
4255 LoggerState pi1_logger = LoggerState::MakeLogger(
4256 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4257 LoggerState pi3_logger = LoggerState::MakeLogger(
4258 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4259 {
4260 // And now start the logger.
4261 LoggerState pi2_logger = LoggerState::MakeLogger(
4262 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4263
4264 pi1_logger.StartLogger(kLogfile1_1);
4265 pi3_logger.StartLogger(kLogfile3_1);
4266 pi2_logger.StartLogger(kLogfile2_1);
4267
4268 event_loop_factory.RunFor(chrono::milliseconds(1005));
4269
4270 // Now that we've got a start time in the past, turn on data.
4271 std::unique_ptr<aos::EventLoop> ping_event_loop =
4272 pi1->MakeEventLoop("ping");
4273 Ping ping(ping_event_loop.get());
4274
4275 pi2->AlwaysStart<Pong>("pong");
4276
4277 event_loop_factory.RunFor(chrono::milliseconds(3000));
4278
4279 pi2_logger.AppendAllFilenames(&filenames);
4280 }
4281 event_loop_factory.RunFor(chrono::milliseconds(995));
4282 // pi2 now reboots at 5 seconds.
4283 {
4284 event_loop_factory.RunFor(chrono::milliseconds(1000));
4285
4286 // Make local stuff happen before we start logging and connect the remote.
4287 pi2->AlwaysStart<Pong>("pong");
4288 std::unique_ptr<aos::EventLoop> ping_event_loop =
4289 pi1->MakeEventLoop("ping");
4290 Ping ping(ping_event_loop.get());
4291 event_loop_factory.RunFor(chrono::milliseconds(5));
4292
4293 // Start logging again on pi2 after it is up.
4294 LoggerState pi2_logger = LoggerState::MakeLogger(
4295 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4296 pi2_logger.StartLogger(kLogfile2_2);
4297
4298 event_loop_factory.RunFor(chrono::milliseconds(5000));
4299
4300 pi2_logger.AppendAllFilenames(&filenames);
4301 }
4302
4303 pi1_logger.AppendAllFilenames(&filenames);
4304 pi3_logger.AppendAllFilenames(&filenames);
4305 }
4306
4307 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4308 auto result = ConfirmReadable(filenames);
4309
4310 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4311 EXPECT_THAT(result[0].second,
4312 ::testing::ElementsAre(realtime_clock::epoch() +
4313 chrono::microseconds(11000350)));
4314
4315 EXPECT_THAT(result[1].first,
4316 ::testing::ElementsAre(
4317 realtime_clock::epoch(),
4318 realtime_clock::epoch() + chrono::microseconds(6005000)));
4319 EXPECT_THAT(result[1].second,
4320 ::testing::ElementsAre(
4321 realtime_clock::epoch() + chrono::microseconds(4900150),
4322 realtime_clock::epoch() + chrono::microseconds(11000200)));
4323
4324 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4325 EXPECT_THAT(result[2].second,
4326 ::testing::ElementsAre(realtime_clock::epoch() +
4327 chrono::microseconds(11000150)));
4328
4329 // Confirm we observed the correct start and stop times. We should see the
4330 // reboot here.
4331 auto start_stop_result = ConfirmReadable(
4332 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4333 realtime_clock::epoch() + chrono::milliseconds(8000));
4334
4335 EXPECT_THAT(
4336 start_stop_result[0].first,
4337 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4338 EXPECT_THAT(
4339 start_stop_result[0].second,
4340 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4341 EXPECT_THAT(start_stop_result[1].first,
4342 ::testing::ElementsAre(
4343 realtime_clock::epoch() + chrono::seconds(2),
4344 realtime_clock::epoch() + chrono::microseconds(6005000)));
4345 EXPECT_THAT(start_stop_result[1].second,
4346 ::testing::ElementsAre(
4347 realtime_clock::epoch() + chrono::microseconds(4900150),
4348 realtime_clock::epoch() + chrono::seconds(8)));
4349 EXPECT_THAT(
4350 start_stop_result[2].first,
4351 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4352 EXPECT_THAT(
4353 start_stop_result[2].second,
4354 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4355}
Austin Schuh5dd22842021-11-17 16:09:39 -08004356
Austin Schuh5c770fa2022-03-11 06:57:22 -08004357// Tests that we properly handle one direction being down.
4358TEST(MissingDirectionTest, OneDirection) {
4359 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4360 aos::configuration::ReadConfig(ArtifactPath(
4361 "aos/events/logging/multinode_pingpong_split4_config.json"));
4362 message_bridge::TestingTimeConverter time_converter(
4363 configuration::NodesCount(&config.message()));
4364 SimulatedEventLoopFactory event_loop_factory(&config.message());
4365 event_loop_factory.SetTimeConverter(&time_converter);
4366
4367 NodeEventLoopFactory *const pi1 =
4368 event_loop_factory.GetNodeEventLoopFactory("pi1");
4369 const size_t pi1_index = configuration::GetNodeIndex(
4370 event_loop_factory.configuration(), pi1->node());
4371 NodeEventLoopFactory *const pi2 =
4372 event_loop_factory.GetNodeEventLoopFactory("pi2");
4373 const size_t pi2_index = configuration::GetNodeIndex(
4374 event_loop_factory.configuration(), pi2->node());
4375 std::vector<std::string> filenames;
4376
4377 {
4378 CHECK_EQ(pi1_index, 0u);
4379 CHECK_EQ(pi2_index, 1u);
4380
4381 time_converter.AddNextTimestamp(
4382 distributed_clock::epoch(),
4383 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4384
4385 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4386 time_converter.AddNextTimestamp(
4387 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004388 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuh5c770fa2022-03-11 06:57:22 -08004389 BootTimestamp::epoch() + reboot_time});
4390 }
4391
4392 const std::string kLogfile2_1 =
4393 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4394 const std::string kLogfile1_1 =
4395 aos::testing::TestTmpDir() + "/multi_logfile1.1/";
4396 util::UnlinkRecursive(kLogfile2_1);
4397 util::UnlinkRecursive(kLogfile1_1);
4398
4399 pi2->Disconnect(pi1->node());
4400
4401 pi1->AlwaysStart<Ping>("ping");
4402 pi2->AlwaysStart<Pong>("pong");
4403
4404 {
4405 LoggerState pi2_logger = LoggerState::MakeLogger(
4406 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4407
4408 event_loop_factory.RunFor(chrono::milliseconds(95));
4409
4410 pi2_logger.StartLogger(kLogfile2_1);
4411
4412 event_loop_factory.RunFor(chrono::milliseconds(6000));
4413
4414 pi2->Connect(pi1->node());
4415
4416 LoggerState pi1_logger = LoggerState::MakeLogger(
4417 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4418 pi1_logger.StartLogger(kLogfile1_1);
4419
4420 event_loop_factory.RunFor(chrono::milliseconds(5000));
4421 pi1_logger.AppendAllFilenames(&filenames);
4422 pi2_logger.AppendAllFilenames(&filenames);
4423 }
4424
4425 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4426 ConfirmReadable(filenames);
4427}
4428
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004429// Tests that we properly handle only one direction ever existing after a
4430// reboot.
4431TEST(MissingDirectionTest, OneDirectionAfterReboot) {
4432 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4433 aos::configuration::ReadConfig(ArtifactPath(
4434 "aos/events/logging/multinode_pingpong_split4_config.json"));
4435 message_bridge::TestingTimeConverter time_converter(
4436 configuration::NodesCount(&config.message()));
4437 SimulatedEventLoopFactory event_loop_factory(&config.message());
4438 event_loop_factory.SetTimeConverter(&time_converter);
4439
4440 NodeEventLoopFactory *const pi1 =
4441 event_loop_factory.GetNodeEventLoopFactory("pi1");
4442 const size_t pi1_index = configuration::GetNodeIndex(
4443 event_loop_factory.configuration(), pi1->node());
4444 NodeEventLoopFactory *const pi2 =
4445 event_loop_factory.GetNodeEventLoopFactory("pi2");
4446 const size_t pi2_index = configuration::GetNodeIndex(
4447 event_loop_factory.configuration(), pi2->node());
4448 std::vector<std::string> filenames;
4449
4450 {
4451 CHECK_EQ(pi1_index, 0u);
4452 CHECK_EQ(pi2_index, 1u);
4453
4454 time_converter.AddNextTimestamp(
4455 distributed_clock::epoch(),
4456 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4457
4458 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4459 time_converter.AddNextTimestamp(
4460 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004461 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004462 BootTimestamp::epoch() + reboot_time});
4463 }
4464
4465 const std::string kLogfile2_1 =
4466 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4467 util::UnlinkRecursive(kLogfile2_1);
4468
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004469 pi1->AlwaysStart<Ping>("ping");
4470
4471 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4472 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4473 // second boot.
4474 {
4475 LoggerState pi2_logger = LoggerState::MakeLogger(
4476 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4477
4478 event_loop_factory.RunFor(chrono::milliseconds(95));
4479
4480 pi2_logger.StartLogger(kLogfile2_1);
4481
4482 event_loop_factory.RunFor(chrono::milliseconds(4000));
4483
4484 pi2->Disconnect(pi1->node());
4485
4486 event_loop_factory.RunFor(chrono::milliseconds(1000));
4487 pi1->AlwaysStart<Ping>("ping");
4488
4489 event_loop_factory.RunFor(chrono::milliseconds(5000));
4490 pi2_logger.AppendAllFilenames(&filenames);
4491 }
4492
4493 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4494 ConfirmReadable(filenames);
4495}
4496
4497// Tests that we properly handle only one direction ever existing after a reboot
4498// with only reliable data.
4499TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
4500 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4501 aos::configuration::ReadConfig(ArtifactPath(
4502 "aos/events/logging/multinode_pingpong_split4_reliable_config.json"));
4503 message_bridge::TestingTimeConverter time_converter(
4504 configuration::NodesCount(&config.message()));
4505 SimulatedEventLoopFactory event_loop_factory(&config.message());
4506 event_loop_factory.SetTimeConverter(&time_converter);
4507
4508 NodeEventLoopFactory *const pi1 =
4509 event_loop_factory.GetNodeEventLoopFactory("pi1");
4510 const size_t pi1_index = configuration::GetNodeIndex(
4511 event_loop_factory.configuration(), pi1->node());
4512 NodeEventLoopFactory *const pi2 =
4513 event_loop_factory.GetNodeEventLoopFactory("pi2");
4514 const size_t pi2_index = configuration::GetNodeIndex(
4515 event_loop_factory.configuration(), pi2->node());
4516 std::vector<std::string> filenames;
4517
4518 {
4519 CHECK_EQ(pi1_index, 0u);
4520 CHECK_EQ(pi2_index, 1u);
4521
4522 time_converter.AddNextTimestamp(
4523 distributed_clock::epoch(),
4524 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4525
4526 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4527 time_converter.AddNextTimestamp(
4528 distributed_clock::epoch() + reboot_time,
4529 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4530 BootTimestamp::epoch() + reboot_time});
4531 }
4532
4533 const std::string kLogfile2_1 =
4534 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4535 util::UnlinkRecursive(kLogfile2_1);
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004536
4537 pi1->AlwaysStart<Ping>("ping");
4538
4539 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4540 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4541 // second boot.
4542 {
4543 LoggerState pi2_logger = LoggerState::MakeLogger(
4544 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4545
4546 event_loop_factory.RunFor(chrono::milliseconds(95));
4547
4548 pi2_logger.StartLogger(kLogfile2_1);
4549
4550 event_loop_factory.RunFor(chrono::milliseconds(4000));
4551
4552 pi2->Disconnect(pi1->node());
4553
4554 event_loop_factory.RunFor(chrono::milliseconds(1000));
4555 pi1->AlwaysStart<Ping>("ping");
4556
4557 event_loop_factory.RunFor(chrono::milliseconds(5000));
4558 pi2_logger.AppendAllFilenames(&filenames);
4559 }
4560
4561 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4562 ConfirmReadable(filenames);
4563}
4564
Austin Schuhefba96d2022-06-24 13:22:18 -07004565// Tests that we properly handle what used to be a time violation in one
4566// direction. This can occur when one direction goes down after sending some
4567// data, but the other keeps working. The down direction ends up resolving to a
4568// straight line in the noncausal filter, where the direction which is still up
4569// can cross that line. Really, time progressed along just fine but we assumed
4570// that the offset was a line when it could have deviated by up to 1ms/second.
4571TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4572 std::vector<std::string> filenames;
4573
4574 CHECK_EQ(pi1_index_, 0u);
4575 CHECK_EQ(pi2_index_, 1u);
4576
4577 time_converter_.AddNextTimestamp(
4578 distributed_clock::epoch(),
4579 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4580
4581 const chrono::nanoseconds before_disconnect_duration =
4582 time_converter_.AddMonotonic(
4583 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4584
4585 const chrono::nanoseconds test_duration =
4586 time_converter_.AddMonotonic(
4587 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4588 time_converter_.AddMonotonic(
4589 {chrono::milliseconds(10000),
4590 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4591 time_converter_.AddMonotonic(
4592 {chrono::milliseconds(10000),
4593 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4594
4595 const std::string kLogfile =
4596 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4597 util::UnlinkRecursive(kLogfile);
4598
4599 {
4600 LoggerState pi2_logger = MakeLogger(pi2_);
4601 pi2_logger.StartLogger(kLogfile);
4602 event_loop_factory_.RunFor(before_disconnect_duration);
4603
4604 pi2_->Disconnect(pi1_->node());
4605
4606 event_loop_factory_.RunFor(test_duration);
4607 pi2_->Connect(pi1_->node());
4608
4609 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4610 pi2_logger.AppendAllFilenames(&filenames);
4611 }
4612
4613 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4614 ConfirmReadable(filenames);
4615}
4616
James Kuszmaul86e86c32022-07-21 17:39:47 -07004617// Tests that we can replay a logfile that has timestamps such that at least one
4618// node's epoch is at a positive distributed_clock (and thus will have to be
4619// booted after the other node(s)).
4620TEST_P(MultinodeLoggerTest, StartOneNodeBeforeOther) {
4621 std::vector<std::string> filenames;
4622
4623 CHECK_EQ(pi1_index_, 0u);
4624 CHECK_EQ(pi2_index_, 1u);
4625
4626 time_converter_.AddNextTimestamp(
4627 distributed_clock::epoch(),
4628 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4629
4630 const chrono::nanoseconds before_reboot_duration = chrono::milliseconds(1000);
4631 time_converter_.RebootAt(
4632 0, distributed_clock::time_point(before_reboot_duration));
4633
4634 const chrono::nanoseconds test_duration = time_converter_.AddMonotonic(
4635 {chrono::milliseconds(10000), chrono::milliseconds(10000)});
4636
4637 const std::string kLogfile =
4638 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4639 util::UnlinkRecursive(kLogfile);
4640
4641 pi2_->Disconnect(pi1_->node());
4642 pi1_->Disconnect(pi2_->node());
4643
4644 {
4645 LoggerState pi2_logger = MakeLogger(pi2_);
4646
4647 pi2_logger.StartLogger(kLogfile);
4648 event_loop_factory_.RunFor(before_reboot_duration);
4649
4650 pi2_->Connect(pi1_->node());
4651 pi1_->Connect(pi2_->node());
4652
4653 event_loop_factory_.RunFor(test_duration);
4654
4655 pi2_logger.AppendAllFilenames(&filenames);
4656 }
4657
4658 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4659 ConfirmReadable(filenames);
4660
4661 {
4662 LogReader reader(sorted_parts);
4663 SimulatedEventLoopFactory replay_factory(reader.configuration());
4664 reader.RegisterWithoutStarting(&replay_factory);
4665
4666 NodeEventLoopFactory *const replay_node =
4667 reader.event_loop_factory()->GetNodeEventLoopFactory("pi1");
4668
4669 std::unique_ptr<EventLoop> test_event_loop =
4670 replay_node->MakeEventLoop("test_reader");
4671 replay_node->OnStartup([replay_node]() {
4672 // Check that we didn't boot until at least t=0.
4673 CHECK_LE(monotonic_clock::epoch(), replay_node->monotonic_now());
4674 });
4675 test_event_loop->OnRun([&test_event_loop]() {
4676 // Check that we didn't boot until at least t=0.
4677 EXPECT_LE(monotonic_clock::epoch(), test_event_loop->monotonic_now());
4678 });
4679 reader.event_loop_factory()->Run();
4680 reader.Deregister();
4681 }
4682}
4683
Austin Schuh79b21d62022-08-16 13:54:49 -07004684// Tests that when we have a loop without all the logs at all points in time, we
4685// can sort it properly.
Austin Schuheb595a62022-08-26 19:24:32 -07004686TEST(MultinodeLoggerLoopTest, Loop) {
Austin Schuh79b21d62022-08-16 13:54:49 -07004687 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4688 aos::configuration::ReadConfig(ArtifactPath(
4689 "aos/events/logging/multinode_pingpong_triangle_split_config.json"));
4690 message_bridge::TestingTimeConverter time_converter(
4691 configuration::NodesCount(&config.message()));
4692 SimulatedEventLoopFactory event_loop_factory(&config.message());
4693 event_loop_factory.SetTimeConverter(&time_converter);
4694
4695 NodeEventLoopFactory *const pi1 =
4696 event_loop_factory.GetNodeEventLoopFactory("pi1");
4697 NodeEventLoopFactory *const pi2 =
4698 event_loop_factory.GetNodeEventLoopFactory("pi2");
4699 NodeEventLoopFactory *const pi3 =
4700 event_loop_factory.GetNodeEventLoopFactory("pi3");
4701
4702 const std::string kLogfile1_1 =
4703 aos::testing::TestTmpDir() + "/multi_logfile1/";
4704 const std::string kLogfile2_1 =
4705 aos::testing::TestTmpDir() + "/multi_logfile2/";
4706 const std::string kLogfile3_1 =
4707 aos::testing::TestTmpDir() + "/multi_logfile3/";
4708 util::UnlinkRecursive(kLogfile1_1);
4709 util::UnlinkRecursive(kLogfile2_1);
4710 util::UnlinkRecursive(kLogfile3_1);
4711
4712 {
4713 // Make pi1 boot before everything else.
4714 time_converter.AddNextTimestamp(
4715 distributed_clock::epoch(),
4716 {BootTimestamp::epoch(),
4717 BootTimestamp::epoch() - chrono::milliseconds(100),
4718 BootTimestamp::epoch() - chrono::milliseconds(300)});
4719 }
4720
4721 // We want to setup a situation such that 2 of the 3 legs of the loop are very
4722 // confident about time being X, and the third leg is pulling the average off
4723 // to one side.
4724 //
4725 // It's easiest to visualize this in timestamp_plotter.
4726
4727 std::vector<std::string> filenames;
4728 {
4729 // Have pi1 send out a reliable message at startup. This sets up a long
4730 // forwarding time message at the start to bias time.
4731 std::unique_ptr<EventLoop> pi1_event_loop = pi1->MakeEventLoop("ping");
4732 {
4733 aos::Sender<examples::Ping> ping_sender =
4734 pi1_event_loop->MakeSender<examples::Ping>("/reliable");
4735
4736 aos::Sender<examples::Ping>::Builder builder = ping_sender.MakeBuilder();
4737 examples::Ping::Builder ping_builder =
4738 builder.MakeBuilder<examples::Ping>();
4739 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
4740 }
4741
4742 // Wait a while so there's enough data to let the worst case be rather off.
4743 event_loop_factory.RunFor(chrono::seconds(1000));
4744
4745 // Now start a receiving node first. This sets up 2 tight bounds between 2
4746 // of the nodes.
4747 LoggerState pi2_logger = LoggerState::MakeLogger(
4748 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4749 pi2_logger.StartLogger(kLogfile2_1);
4750
4751 event_loop_factory.RunFor(chrono::seconds(100));
4752
4753 // And now start the third leg.
4754 LoggerState pi3_logger = LoggerState::MakeLogger(
4755 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4756 pi3_logger.StartLogger(kLogfile3_1);
4757
4758 LoggerState pi1_logger = LoggerState::MakeLogger(
4759 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4760 pi1_logger.StartLogger(kLogfile1_1);
4761
4762 event_loop_factory.RunFor(chrono::seconds(100));
4763
4764 pi1_logger.AppendAllFilenames(&filenames);
4765 pi2_logger.AppendAllFilenames(&filenames);
4766 pi3_logger.AppendAllFilenames(&filenames);
4767 }
4768
4769 // Make sure we can read this.
4770 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4771 auto result = ConfirmReadable(filenames);
4772}
4773
Austin Schuhe309d2a2019-11-29 13:25:21 -08004774} // namespace testing
4775} // namespace logger
4776} // namespace aos