blob: 35474c71060b5f4af800ca31416b4ff613433d84 [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;
Austin Schuh61e973f2021-02-21 21:43:56 -0800569};
Austin Schuh315b96b2020-12-11 21:21:12 -0800570
James Kuszmauldd0a5042021-10-28 23:38:04 -0700571std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
572 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
573 << ", sha256: \"" << params.sha256 << "\"}";
574 return ostream;
575}
576
Austin Schuh3e20c692021-11-16 20:43:16 -0800577struct LoggerState {
578 static LoggerState MakeLogger(NodeEventLoopFactory *node,
579 SimulatedEventLoopFactory *factory,
580 CompressionParams params,
581 const Configuration *configuration = nullptr) {
582 if (configuration == nullptr) {
583 configuration = factory->configuration();
584 }
585 return {node->MakeEventLoop("logger"),
586 {},
587 configuration,
588 configuration::GetNode(configuration, node->node()),
589 nullptr,
590 params};
591 }
592
593 void StartLogger(std::string logfile_base) {
594 CHECK(!logfile_base.empty());
595
596 logger = std::make_unique<Logger>(event_loop.get(), configuration);
597 logger->set_polling_period(std::chrono::milliseconds(100));
598 logger->set_name(
599 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
Austin Schuhfa712682022-05-11 16:43:42 -0700600 logger->set_logger_sha1(
601 absl::StrCat("logger_sha1_", event_loop->node()->name()->str()));
602 logger->set_logger_version(
603 absl::StrCat("logger_version_", event_loop->node()->name()->str()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800604 event_loop->OnRun([this, logfile_base]() {
605 std::unique_ptr<MultiNodeLogNamer> namer =
606 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
607 event_loop.get(), node);
608 namer->set_extension(params.extension);
609 namer->set_encoder_factory(params.encoder_factory);
610 log_namer = namer.get();
611
612 logger->StartLogging(std::move(namer));
613 });
614 }
615
616 std::unique_ptr<EventLoop> event_loop;
617 std::unique_ptr<Logger> logger;
618 const Configuration *configuration;
619 const Node *node;
620 MultiNodeLogNamer *log_namer;
621 CompressionParams params;
622
623 void AppendAllFilenames(std::vector<std::string> *filenames) {
624 for (const std::string &file : log_namer->all_filenames()) {
625 const std::string_view separator =
626 log_namer->base_name().back() == '/' ? "" : "_";
627 filenames->emplace_back(
628 absl::StrCat(log_namer->base_name(), separator, file));
629 }
630 }
631
632 ~LoggerState() {
633 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800634 std::vector<std::string> filenames;
635 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800636 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800637 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800638 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800639 auto x = ReadHeader(file);
640 if (x) {
641 VLOG(1) << aos::FlatbufferToJson(x.value());
642 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800643 }
644 }
645 }
646};
647
Austin Schuhe33c08d2022-02-03 18:15:21 -0800648std::vector<std::pair<std::vector<realtime_clock::time_point>,
649 std::vector<realtime_clock::time_point>>>
650ConfirmReadable(
651 const std::vector<std::string> &files,
652 realtime_clock::time_point start_time = realtime_clock::min_time,
653 realtime_clock::time_point end_time = realtime_clock::max_time) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800654 {
655 LogReader reader(SortParts(files));
656
657 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
658 reader.Register(&log_reader_factory);
659
660 log_reader_factory.Run();
661
662 reader.Deregister();
663 }
664 {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800665 std::vector<std::pair<std::vector<realtime_clock::time_point>,
666 std::vector<realtime_clock::time_point>>>
667 result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800668 LogReader reader(SortParts(files));
669
Austin Schuhe33c08d2022-02-03 18:15:21 -0800670 reader.SetStartTime(start_time);
671 reader.SetEndTime(end_time);
672
Austin Schuh3e20c692021-11-16 20:43:16 -0800673 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
674 reader.RegisterWithoutStarting(&log_reader_factory);
Austin Schuhe33c08d2022-02-03 18:15:21 -0800675 result.resize(
676 configuration::NodesCount(log_reader_factory.configuration()));
Austin Schuh3e20c692021-11-16 20:43:16 -0800677 if (configuration::MultiNode(log_reader_factory.configuration())) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800678 size_t i = 0;
Austin Schuh3e20c692021-11-16 20:43:16 -0800679 for (const aos::Node *node :
680 *log_reader_factory.configuration()->nodes()) {
Austin Schuhe33c08d2022-02-03 18:15:21 -0800681 LOG(INFO) << "Registering start";
682 reader.OnStart(node, [node, &log_reader_factory, &result,
683 node_index = i]() {
Austin Schuh3e20c692021-11-16 20:43:16 -0800684 LOG(INFO) << "Starting " << node->name()->string_view();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800685 result[node_index].first.push_back(
686 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
Austin Schuh3e20c692021-11-16 20:43:16 -0800687 });
Austin Schuhe33c08d2022-02-03 18:15:21 -0800688 reader.OnEnd(node, [node, &log_reader_factory, &result,
689 node_index = i]() {
690 LOG(INFO) << "Ending " << node->name()->string_view();
691 result[node_index].second.push_back(
692 log_reader_factory.GetNodeEventLoopFactory(node)->realtime_now());
693 });
694 ++i;
Austin Schuh3e20c692021-11-16 20:43:16 -0800695 }
Austin Schuhe33c08d2022-02-03 18:15:21 -0800696 } else {
697 reader.OnStart([&log_reader_factory, &result]() {
698 LOG(INFO) << "Starting";
699 result[0].first.push_back(
700 log_reader_factory.GetNodeEventLoopFactory(nullptr)
701 ->realtime_now());
702 });
703 reader.OnEnd([&log_reader_factory, &result]() {
704 LOG(INFO) << "Ending";
705 result[0].second.push_back(
706 log_reader_factory.GetNodeEventLoopFactory(nullptr)
707 ->realtime_now());
708 });
Austin Schuh3e20c692021-11-16 20:43:16 -0800709 }
710
711 log_reader_factory.Run();
712
713 reader.Deregister();
Austin Schuhe33c08d2022-02-03 18:15:21 -0800714
715 for (auto x : result) {
716 for (auto y : x.first) {
717 VLOG(1) << "Start " << y;
718 }
719 for (auto y : x.second) {
720 VLOG(1) << "End " << y;
721 }
722 }
723 return result;
Austin Schuh3e20c692021-11-16 20:43:16 -0800724 }
725}
726
James Kuszmauldd0a5042021-10-28 23:38:04 -0700727class MultinodeLoggerTest : public ::testing::TestWithParam<
728 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800729 public:
730 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700731 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
732 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800733 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800734 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700735 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800736 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700737 event_loop_factory_.configuration(), pi1_->node())),
738 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800739 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700740 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800741 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800742 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
743 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800744 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800745 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800746 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700747 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700748 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800749 event_loop_factory_.SetTimeConverter(&time_converter_);
750
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700751 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700752 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700753 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800754 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700755 }
756
Austin Schuh268586b2021-03-31 22:24:39 -0700757 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800758 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800759 unlink(file.c_str());
760 }
761
Austin Schuh268586b2021-03-31 22:24:39 -0700762 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800763 unlink(file.c_str());
764 }
765
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700766 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
767 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700768
769 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
770 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700771 }
772
James Kuszmauldd0a5042021-10-28 23:38:04 -0700773 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800774
775 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700776 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800777 size_t pi1_data_count = 3,
778 size_t pi2_data_count = 3) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800779 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700780 result.emplace_back(absl::StrCat(
781 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
782 result.emplace_back(absl::StrCat(
783 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700784 for (size_t i = 0; i < pi1_data_count; ++i) {
785 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700786 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700787 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800788 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700789 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800790 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700791 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700792 for (size_t i = 0; i < pi2_data_count; ++i) {
793 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700794 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700795 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700796 result.emplace_back(logfile_base2 +
797 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
798 Extension());
799 result.emplace_back(logfile_base2 +
800 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
801 Extension());
802 result.emplace_back(logfile_base1 +
803 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
804 Extension());
805 result.emplace_back(logfile_base1 +
806 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
807 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800808 if (shared()) {
809 result.emplace_back(logfile_base1 +
810 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700811 "aos.message_bridge.RemoteMessage.part0" +
812 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800813 result.emplace_back(logfile_base1 +
814 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700815 "aos.message_bridge.RemoteMessage.part1" +
816 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800817 result.emplace_back(logfile_base1 +
818 "_timestamps/pi1/aos/remote_timestamps/pi2/"
819 "aos.message_bridge.RemoteMessage.part2" +
820 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800821 result.emplace_back(logfile_base2 +
822 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700823 "aos.message_bridge.RemoteMessage.part0" +
824 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800825 result.emplace_back(logfile_base2 +
826 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700827 "aos.message_bridge.RemoteMessage.part1" +
828 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800829 } else {
830 result.emplace_back(logfile_base1 +
831 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
832 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700833 "aos.message_bridge.RemoteMessage.part0" +
834 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800835 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.part1" +
839 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800840 result.emplace_back(logfile_base2 +
841 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
842 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700843 "aos.message_bridge.RemoteMessage.part0" +
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.part1" +
849 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800850 result.emplace_back(logfile_base1 +
851 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
852 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700853 "aos.message_bridge.RemoteMessage.part0" +
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.part1" +
859 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800860 }
861
862 return result;
863 }
864
865 std::vector<std::string> MakePi1RebootLogfiles() {
866 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700867 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
868 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
869 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800870 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
871 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800872 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700873 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800874 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700875 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800876 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700877 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700878 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700879 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
880 result.emplace_back(logfile_base1_ +
881 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
882 Extension());
883 result.emplace_back(logfile_base1_ +
884 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
885 Extension());
886 result.emplace_back(logfile_base1_ +
887 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
888 Extension());
889 result.emplace_back(logfile_base1_ +
890 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
891 Extension());
892 result.emplace_back(absl::StrCat(
893 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800894 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800895 for (size_t i = 0; i < 6; ++i) {
896 result.emplace_back(
897 absl::StrCat(logfile_base1_,
898 "_timestamps/pi1/aos/remote_timestamps/pi2/"
899 "aos.message_bridge.RemoteMessage.part",
900 i, Extension()));
901 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800902 } else {
903 result.emplace_back(logfile_base1_ +
904 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
905 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700906 "aos.message_bridge.RemoteMessage.part0" +
907 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800908 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.part1" +
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.part2" +
917 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700918 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.part3" +
922 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800923
924 result.emplace_back(logfile_base1_ +
925 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
926 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700927 "aos.message_bridge.RemoteMessage.part0" +
928 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800929 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.part1" +
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.part2" +
938 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700939 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.part3" +
943 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800944 }
945 return result;
946 }
947
948 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
949 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700950 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
951 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
952 result.emplace_back(logfile_base1_ +
953 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
954 Extension());
955 result.emplace_back(absl::StrCat(
956 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700957 return result;
958 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800959
Austin Schuh510dc622021-08-06 18:47:30 -0700960 std::vector<std::string> MakePi1DeadNodeLogfiles() {
961 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700962 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
963 result.emplace_back(absl::StrCat(
964 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800965 return result;
966 }
967
968 std::vector<std::vector<std::string>> StructureLogFiles() {
969 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800970 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
971 std::vector<std::string>{logfiles_[5], logfiles_[6]},
972 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800973 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800974 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800975
Austin Schuhbfe6c572022-01-27 20:48:20 -0800976 if (shared()) {
977 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
978 logfiles_[16]});
979 result.emplace_back(
980 std::vector<std::string>{logfiles_[17], logfiles_[18]});
981 } else {
982 result.emplace_back(
983 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800984 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700985 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800986 result.emplace_back(
987 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800988 }
989
990 return result;
991 }
992
James Kuszmauldd0a5042021-10-28 23:38:04 -0700993 std::string Extension() {
994 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
995 }
996
Austin Schuh58646e22021-08-23 23:51:46 -0700997 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700998 SimulatedEventLoopFactory *factory = nullptr,
999 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001000 if (factory == nullptr) {
1001 factory = &event_loop_factory_;
1002 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001003 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
1004 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001005 }
1006
James Kuszmauldd0a5042021-10-28 23:38:04 -07001007 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001008 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -08001009 if (logger->event_loop->node()->name()->string_view() == "pi1") {
1010 logfile_base = logfile_base1_;
1011 } else {
1012 logfile_base = logfile_base2_;
1013 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001014 }
Austin Schuh3e20c692021-11-16 20:43:16 -08001015 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001016 }
Austin Schuh15649d62019-12-28 16:36:38 -08001017
Austin Schuh3bd4c402020-11-06 18:19:06 -08001018 void VerifyParts(const std::vector<LogFile> &sorted_parts,
1019 const std::vector<std::string> &corrupted_parts = {}) {
1020 EXPECT_EQ(sorted_parts.size(), 2u);
1021
1022 // Count up the number of UUIDs and make sure they are what we expect as a
1023 // sanity check.
1024 std::set<std::string> log_event_uuids;
1025 std::set<std::string> parts_uuids;
1026 std::set<std::string> both_uuids;
1027
1028 size_t missing_rt_count = 0;
1029
1030 std::vector<std::string> logger_nodes;
1031 for (const LogFile &log_file : sorted_parts) {
1032 EXPECT_FALSE(log_file.log_event_uuid.empty());
1033 log_event_uuids.insert(log_file.log_event_uuid);
1034 logger_nodes.emplace_back(log_file.logger_node);
1035 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -08001036 EXPECT_TRUE(log_file.config);
1037 EXPECT_EQ(log_file.name,
1038 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuhfa712682022-05-11 16:43:42 -07001039 EXPECT_EQ(log_file.logger_sha1,
1040 absl::StrCat("logger_sha1_", log_file.logger_node));
1041 EXPECT_EQ(log_file.logger_version,
1042 absl::StrCat("logger_version_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -08001043
1044 for (const LogParts &part : log_file.parts) {
1045 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
1046 << ": " << part;
1047 missing_rt_count +=
1048 part.realtime_start_time == aos::realtime_clock::min_time;
1049
1050 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
1051 log_event_uuids.end());
1052 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -08001053 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001054 parts_uuids.insert(part.parts_uuid);
1055 both_uuids.insert(part.parts_uuid);
1056 }
1057 }
1058
Austin Schuh61e973f2021-02-21 21:43:56 -08001059 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
1060 // start time on remote nodes because we don't know it and would be
1061 // guessing. And the log reader can actually do a better job. The number
1062 // depends on if we have the remote timestamps split across 2 files, or just
1063 // across 1, depending on if we are using a split or combined timestamp
1064 // channel config.
1065 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001066
1067 EXPECT_EQ(log_event_uuids.size(), 2u);
1068 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
1069 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
1070
1071 // Test that each list of parts is in order. Don't worry about the ordering
1072 // between part file lists though.
1073 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -08001074 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -08001075 ::testing::UnorderedElementsAreArray(structured_logfiles_));
1076
1077 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
1078
1079 EXPECT_NE(sorted_parts[0].realtime_start_time,
1080 aos::realtime_clock::min_time);
1081 EXPECT_NE(sorted_parts[1].realtime_start_time,
1082 aos::realtime_clock::min_time);
1083
1084 EXPECT_NE(sorted_parts[0].monotonic_start_time,
1085 aos::monotonic_clock::min_time);
1086 EXPECT_NE(sorted_parts[1].monotonic_start_time,
1087 aos::monotonic_clock::min_time);
1088
1089 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
1090 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
1091 }
1092
1093 void AddExtension(std::string_view extension) {
1094 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
1095 [extension](const std::string &in) {
1096 return absl::StrCat(in, extension);
1097 });
1098
1099 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
1100 structured_logfiles_.begin(),
1101 [extension](std::vector<std::string> in) {
1102 std::transform(in.begin(), in.end(), in.begin(),
1103 [extension](const std::string &in_str) {
1104 return absl::StrCat(in_str, extension);
1105 });
1106 return in;
1107 });
1108 }
1109
Austin Schuh15649d62019-12-28 16:36:38 -08001110 // Config and factory.
1111 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001112 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -08001113 SimulatedEventLoopFactory event_loop_factory_;
1114
Austin Schuh58646e22021-08-23 23:51:46 -07001115 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001116 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -07001117 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -08001118 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001119
1120 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -08001121 std::string logfile_base1_;
1122 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -08001123 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001124 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -08001125 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -07001126
1127 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -08001128};
1129
Austin Schuh391e3172020-09-01 22:48:18 -07001130// Counts the number of messages on a channel. Returns (channel name, channel
1131// type, count) for every message matching matcher()
1132std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -08001133 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001134 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -08001135 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -08001136 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -08001137
Austin Schuh6f3babe2020-01-26 20:34:50 -08001138 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001139 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -08001140 if (!msg) {
1141 break;
1142 }
1143
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001144 if (matcher(msg.get())) {
1145 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001146 }
1147 }
1148
Austin Schuh391e3172020-09-01 22:48:18 -07001149 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001150 int channel = 0;
1151 for (size_t i = 0; i < counts.size(); ++i) {
1152 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -08001153 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -07001154 result.push_back(std::make_tuple(channel->name()->str(),
1155 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -08001156 }
1157 ++channel;
1158 }
1159
1160 return result;
1161}
1162
1163// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001164std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -08001165 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -07001166 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001167 return CountChannelsMatching(
1168 config, filename, [](const UnpackedMessageHeader *msg) {
1169 if (msg->span.data() != nullptr) {
1170 CHECK(!msg->monotonic_remote_time.has_value());
1171 CHECK(!msg->realtime_remote_time.has_value());
1172 CHECK(!msg->remote_queue_index.has_value());
1173 return true;
1174 }
1175 return false;
1176 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001177}
1178
1179// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001180std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001181 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001182 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001183 return CountChannelsMatching(
1184 config, filename, [](const UnpackedMessageHeader *msg) {
1185 if (msg->span.data() == nullptr) {
1186 CHECK(msg->monotonic_remote_time.has_value());
1187 CHECK(msg->realtime_remote_time.has_value());
1188 CHECK(msg->remote_queue_index.has_value());
1189 return true;
1190 }
1191 return false;
1192 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001193}
1194
Austin Schuhcde938c2020-02-02 17:30:07 -08001195// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001196TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001197 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001198 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001199
Austin Schuh15649d62019-12-28 16:36:38 -08001200 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001201 LoggerState pi1_logger = MakeLogger(pi1_);
1202 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001203
1204 event_loop_factory_.RunFor(chrono::milliseconds(95));
1205
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001206 StartLogger(&pi1_logger);
1207 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001208
Austin Schuh15649d62019-12-28 16:36:38 -08001209 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001210 pi1_logger.AppendAllFilenames(&actual_filenames);
1211 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001212 }
1213
Austin Schuhbfe6c572022-01-27 20:48:20 -08001214 ASSERT_THAT(actual_filenames,
1215 ::testing::UnorderedElementsAreArray(logfiles_));
1216
Austin Schuh6f3babe2020-01-26 20:34:50 -08001217 {
Austin Schuh64fab802020-09-09 22:47:47 -07001218 std::set<std::string> logfile_uuids;
1219 std::set<std::string> parts_uuids;
1220 // Confirm that we have the expected number of UUIDs for both the logfile
1221 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001222 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001223 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001224 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001225 if (!log_header.back().message().has_configuration()) {
1226 logfile_uuids.insert(
1227 log_header.back().message().log_event_uuid()->str());
1228 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1229 }
Austin Schuh64fab802020-09-09 22:47:47 -07001230 }
Austin Schuh15649d62019-12-28 16:36:38 -08001231
Austin Schuh64fab802020-09-09 22:47:47 -07001232 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001233 if (shared()) {
1234 EXPECT_EQ(parts_uuids.size(), 7u);
1235 } else {
1236 EXPECT_EQ(parts_uuids.size(), 8u);
1237 }
Austin Schuh64fab802020-09-09 22:47:47 -07001238
1239 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001240 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001241 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001242 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1243
Austin Schuh64fab802020-09-09 22:47:47 -07001244 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001245 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001246
Austin Schuhe46492f2021-07-31 19:49:41 -07001247 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001248 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1249 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1250
1251 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1252 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1253
Austin Schuhe46492f2021-07-31 19:49:41 -07001254 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1255 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001256
1257 if (shared()) {
1258 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1259 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001260 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001261
1262 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1263 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1264 } else {
1265 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1266 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1267
1268 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1269 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1270
1271 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1272 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001273 }
Austin Schuh64fab802020-09-09 22:47:47 -07001274
1275 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001276 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001277 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001278 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1279
1280 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1281 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1282
1283 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1284 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1285 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1286
Austin Schuh64fab802020-09-09 22:47:47 -07001287 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1288 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001289
Austin Schuh61e973f2021-02-21 21:43:56 -08001290 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1291 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001292
1293 if (shared()) {
1294 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1295 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1296 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1297
1298 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1299 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1300 } else {
1301 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1302 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1303
Austin Schuhe46492f2021-07-31 19:49:41 -07001304 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1305 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001306
1307 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1308 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001309 }
Austin Schuh64fab802020-09-09 22:47:47 -07001310 }
1311
Austin Schuh8c399962020-12-25 21:51:45 -08001312 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001313 {
Austin Schuh391e3172020-09-01 22:48:18 -07001314 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001315 std::shared_ptr<const aos::Configuration> config =
1316 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001317
Austin Schuh6f3babe2020-01-26 20:34:50 -08001318 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001319 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1320 UnorderedElementsAre(
1321 std::make_tuple("/pi1/aos",
1322 "aos.message_bridge.ServerStatistics", 1),
1323 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001324 << " : " << logfiles_[2];
1325 EXPECT_THAT(
1326 CountChannelsData(config, logfiles_[3]),
1327 UnorderedElementsAre(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001328 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1329 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1330 1)))
1331 << " : " << logfiles_[3];
1332 EXPECT_THAT(
1333 CountChannelsData(config, logfiles_[4]),
1334 UnorderedElementsAre(
1335 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001336 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001337 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001338 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
Austin Schuhbfe6c572022-01-27 20:48:20 -08001339 199),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001340 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001341 std::make_tuple("/test", "aos.examples.Ping", 2000)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001342 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001343 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001344 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1345 UnorderedElementsAre())
1346 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001347 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001348 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001349 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001350 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001351 EXPECT_THAT(
1352 CountChannelsTimestamp(config, logfiles_[4]),
1353 UnorderedElementsAre(
1354 std::make_tuple("/test", "aos.examples.Pong", 2000),
1355 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1356 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001357
1358 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001359 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001360 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001361 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001362 << " : " << logfiles_[5];
1363 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001364 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001365 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001366 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001367
Austin Schuh6f3babe2020-01-26 20:34:50 -08001368 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001369 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1370 UnorderedElementsAre())
1371 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001372 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1373 UnorderedElementsAre())
1374 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001375
1376 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001377 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001378 UnorderedElementsAre(std::make_tuple(
1379 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001380 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001381 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001382 CountChannelsData(config, logfiles_[8]),
1383 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1384 << " : " << logfiles_[8];
1385 EXPECT_THAT(
1386 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001387 UnorderedElementsAre(
1388 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001389 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001390 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001391 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1392 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001393 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001394 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1395 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001396 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001397 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001398 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001399 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001400 EXPECT_THAT(
1401 CountChannelsTimestamp(config, logfiles_[8]),
1402 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1403 << " : " << logfiles_[8];
1404 EXPECT_THAT(
1405 CountChannelsTimestamp(config, logfiles_[9]),
1406 UnorderedElementsAre(
1407 std::make_tuple("/test", "aos.examples.Ping", 2000),
1408 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1409 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001410
1411 // And then test that the remotely logged timestamp data files only have
1412 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001413 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1414 UnorderedElementsAre())
1415 << " : " << logfiles_[10];
1416 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1417 UnorderedElementsAre())
1418 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001419 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1420 UnorderedElementsAre())
1421 << " : " << logfiles_[12];
1422 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1423 UnorderedElementsAre())
1424 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001425
Austin Schuh8c399962020-12-25 21:51:45 -08001426 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001427 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001428 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001429 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001430 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001431 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001432 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001433 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001434
Austin Schuh61e973f2021-02-21 21:43:56 -08001435 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001436 UnorderedElementsAre(std::make_tuple(
1437 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001438 << " : " << logfiles_[12];
1439 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001440 UnorderedElementsAre(std::make_tuple(
1441 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001442 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001443
1444 // Timestamps from pi2 on pi1, and the other way.
1445 if (shared()) {
1446 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1447 UnorderedElementsAre())
1448 << " : " << logfiles_[14];
1449 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1450 UnorderedElementsAre())
1451 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001452 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001453 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001454 << " : " << logfiles_[16];
1455 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001456 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001457 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001458 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1459 UnorderedElementsAre())
1460 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001461
Austin Schuhbfe6c572022-01-27 20:48:20 -08001462 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1463 UnorderedElementsAre(
1464 std::make_tuple("/test", "aos.examples.Ping", 1)))
1465 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001466 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001467 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001468 UnorderedElementsAre(
1469 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001470 std::make_tuple("/test", "aos.examples.Ping", 90)))
1471 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001472 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001473 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001474 UnorderedElementsAre(
1475 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1476 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001477 << " : " << logfiles_[16];
1478 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001479 UnorderedElementsAre(std::make_tuple(
1480 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1481 << " : " << logfiles_[17];
1482 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1483 UnorderedElementsAre(std::make_tuple(
1484 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1485 << " : " << logfiles_[18];
1486 } else {
1487 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1488 UnorderedElementsAre())
1489 << " : " << logfiles_[14];
1490 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1491 UnorderedElementsAre())
1492 << " : " << logfiles_[15];
1493 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1494 UnorderedElementsAre())
1495 << " : " << logfiles_[16];
1496 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1497 UnorderedElementsAre())
1498 << " : " << logfiles_[17];
1499 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1500 UnorderedElementsAre())
1501 << " : " << logfiles_[18];
1502 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1503 UnorderedElementsAre())
1504 << " : " << logfiles_[19];
1505
1506 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1507 UnorderedElementsAre(std::make_tuple(
1508 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1509 << " : " << logfiles_[14];
1510 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1511 UnorderedElementsAre(std::make_tuple(
1512 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1513 << " : " << logfiles_[15];
1514 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1515 UnorderedElementsAre(std::make_tuple(
1516 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1517 << " : " << logfiles_[16];
1518 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1519 UnorderedElementsAre(std::make_tuple(
1520 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1521 << " : " << logfiles_[17];
1522 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1523 UnorderedElementsAre(
1524 std::make_tuple("/test", "aos.examples.Ping", 91)))
1525 << " : " << logfiles_[18];
1526 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001527 UnorderedElementsAre(
1528 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001529 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001530 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001531 }
1532
Austin Schuh8c399962020-12-25 21:51:45 -08001533 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001534
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001535 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001536 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001537
1538 // This sends out the fetched messages and advances time to the start of the
1539 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001540 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001541
Austin Schuhac0771c2020-01-07 18:36:30 -08001542 const Node *pi1 =
1543 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001544 const Node *pi2 =
1545 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001546
Austin Schuh2f8fd752020-09-01 22:38:28 -07001547 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1548 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1549 LOG(INFO) << "now pi1 "
1550 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1551 LOG(INFO) << "now pi2 "
1552 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1553
Austin Schuh07676622021-01-21 18:59:17 -08001554 EXPECT_THAT(reader.LoggedNodes(),
1555 ::testing::ElementsAre(
1556 configuration::GetNode(reader.logged_configuration(), pi1),
1557 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001558
1559 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001560
Austin Schuh6f3babe2020-01-26 20:34:50 -08001561 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001562 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001563 std::unique_ptr<EventLoop> pi2_event_loop =
1564 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001565
Austin Schuh6f3babe2020-01-26 20:34:50 -08001566 int pi1_ping_count = 10;
1567 int pi2_ping_count = 10;
1568 int pi1_pong_count = 10;
1569 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001570
1571 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001572 pi1_event_loop->MakeWatcher(
1573 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001574 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001575 << pi1_event_loop->context().monotonic_remote_time << " -> "
1576 << pi1_event_loop->context().monotonic_event_time;
1577 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1578 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1579 pi1_ping_count * chrono::milliseconds(10) +
1580 monotonic_clock::epoch());
1581 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1582 pi1_ping_count * chrono::milliseconds(10) +
1583 realtime_clock::epoch());
1584 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1585 pi1_event_loop->context().monotonic_event_time);
1586 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1587 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001588
Austin Schuh6f3babe2020-01-26 20:34:50 -08001589 ++pi1_ping_count;
1590 });
1591 pi2_event_loop->MakeWatcher(
1592 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001593 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001594 << pi2_event_loop->context().monotonic_remote_time << " -> "
1595 << pi2_event_loop->context().monotonic_event_time;
1596 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1597
1598 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1599 pi2_ping_count * chrono::milliseconds(10) +
1600 monotonic_clock::epoch());
1601 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1602 pi2_ping_count * chrono::milliseconds(10) +
1603 realtime_clock::epoch());
1604 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1605 chrono::microseconds(150),
1606 pi2_event_loop->context().monotonic_event_time);
1607 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1608 chrono::microseconds(150),
1609 pi2_event_loop->context().realtime_event_time);
1610 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001611 });
1612
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001613 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001614 // Confirm that the ping and pong counts both match, and the value also
1615 // matches.
1616 pi1_event_loop->MakeWatcher(
1617 "/test", [&pi1_event_loop, &pi1_ping_count,
1618 &pi1_pong_count](const examples::Pong &pong) {
1619 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1620 << pi1_event_loop->context().monotonic_remote_time << " -> "
1621 << pi1_event_loop->context().monotonic_event_time;
1622
1623 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1624 pi1_pong_count + kQueueIndexOffset);
1625 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1626 chrono::microseconds(200) +
1627 pi1_pong_count * chrono::milliseconds(10) +
1628 monotonic_clock::epoch());
1629 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1630 chrono::microseconds(200) +
1631 pi1_pong_count * chrono::milliseconds(10) +
1632 realtime_clock::epoch());
1633
1634 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1635 chrono::microseconds(150),
1636 pi1_event_loop->context().monotonic_event_time);
1637 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1638 chrono::microseconds(150),
1639 pi1_event_loop->context().realtime_event_time);
1640
1641 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1642 ++pi1_pong_count;
1643 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1644 });
1645 pi2_event_loop->MakeWatcher(
1646 "/test", [&pi2_event_loop, &pi2_ping_count,
1647 &pi2_pong_count](const examples::Pong &pong) {
1648 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1649 << pi2_event_loop->context().monotonic_remote_time << " -> "
1650 << pi2_event_loop->context().monotonic_event_time;
1651
1652 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001653 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001654
1655 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1656 chrono::microseconds(200) +
1657 pi2_pong_count * chrono::milliseconds(10) +
1658 monotonic_clock::epoch());
1659 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1660 chrono::microseconds(200) +
1661 pi2_pong_count * chrono::milliseconds(10) +
1662 realtime_clock::epoch());
1663
1664 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1665 pi2_event_loop->context().monotonic_event_time);
1666 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1667 pi2_event_loop->context().realtime_event_time);
1668
1669 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1670 ++pi2_pong_count;
1671 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1672 });
1673
1674 log_reader_factory.Run();
1675 EXPECT_EQ(pi1_ping_count, 2010);
1676 EXPECT_EQ(pi2_ping_count, 2010);
1677 EXPECT_EQ(pi1_pong_count, 2010);
1678 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001679
1680 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001681}
1682
James Kuszmaul46d82582020-05-09 19:50:09 -07001683typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1684
1685// Test that if we feed the replay with a mismatched node list that we die on
1686// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001687TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001688 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001689 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001690 LoggerState pi1_logger = MakeLogger(pi1_);
1691 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001692
1693 event_loop_factory_.RunFor(chrono::milliseconds(95));
1694
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001695 StartLogger(&pi1_logger);
1696 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001697
James Kuszmaul46d82582020-05-09 19:50:09 -07001698 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1699 }
1700
1701 // Test that, if we add an additional node to the replay config that the
1702 // logger complains about the mismatch in number of nodes.
1703 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1704 configuration::MergeWithConfig(&config_.message(), R"({
1705 "nodes": [
1706 {
1707 "name": "extra-node"
1708 }
1709 ]
1710 }
1711 )");
1712
Austin Schuh287d43d2020-12-04 20:19:33 -08001713 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1714 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001715 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001716}
1717
Austin Schuhcde938c2020-02-02 17:30:07 -08001718// Tests that we can read log files where they don't start at the same monotonic
1719// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001720TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001721 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001722 std::vector<std::string> actual_filenames;
1723
Austin Schuhcde938c2020-02-02 17:30:07 -08001724 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001725 LoggerState pi1_logger = MakeLogger(pi1_);
1726 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001727
1728 event_loop_factory_.RunFor(chrono::milliseconds(95));
1729
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001730 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001731
1732 event_loop_factory_.RunFor(chrono::milliseconds(200));
1733
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001734 StartLogger(&pi2_logger);
1735
Austin Schuhcde938c2020-02-02 17:30:07 -08001736 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001737 pi1_logger.AppendAllFilenames(&actual_filenames);
1738 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001739 }
1740
Austin Schuhe46492f2021-07-31 19:49:41 -07001741 // Since we delay starting pi2, it already knows about all the timestamps so
1742 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001743 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001744
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001745 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001746 log_reader_factory.set_send_delay(chrono::microseconds(0));
1747
1748 // This sends out the fetched messages and advances time to the start of the
1749 // log file.
1750 reader.Register(&log_reader_factory);
1751
1752 const Node *pi1 =
1753 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1754 const Node *pi2 =
1755 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1756
Austin Schuh07676622021-01-21 18:59:17 -08001757 EXPECT_THAT(reader.LoggedNodes(),
1758 ::testing::ElementsAre(
1759 configuration::GetNode(reader.logged_configuration(), pi1),
1760 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001761
1762 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1763
1764 std::unique_ptr<EventLoop> pi1_event_loop =
1765 log_reader_factory.MakeEventLoop("test", pi1);
1766 std::unique_ptr<EventLoop> pi2_event_loop =
1767 log_reader_factory.MakeEventLoop("test", pi2);
1768
1769 int pi1_ping_count = 30;
1770 int pi2_ping_count = 30;
1771 int pi1_pong_count = 30;
1772 int pi2_pong_count = 30;
1773
1774 // Confirm that the ping value matches.
1775 pi1_event_loop->MakeWatcher(
1776 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1777 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1778 << pi1_event_loop->context().monotonic_remote_time << " -> "
1779 << pi1_event_loop->context().monotonic_event_time;
1780 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1781
1782 ++pi1_ping_count;
1783 });
1784 pi2_event_loop->MakeWatcher(
1785 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1786 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1787 << pi2_event_loop->context().monotonic_remote_time << " -> "
1788 << pi2_event_loop->context().monotonic_event_time;
1789 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1790
1791 ++pi2_ping_count;
1792 });
1793
1794 // Confirm that the ping and pong counts both match, and the value also
1795 // matches.
1796 pi1_event_loop->MakeWatcher(
1797 "/test", [&pi1_event_loop, &pi1_ping_count,
1798 &pi1_pong_count](const examples::Pong &pong) {
1799 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1800 << pi1_event_loop->context().monotonic_remote_time << " -> "
1801 << pi1_event_loop->context().monotonic_event_time;
1802
1803 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1804 ++pi1_pong_count;
1805 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1806 });
1807 pi2_event_loop->MakeWatcher(
1808 "/test", [&pi2_event_loop, &pi2_ping_count,
1809 &pi2_pong_count](const examples::Pong &pong) {
1810 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1811 << pi2_event_loop->context().monotonic_remote_time << " -> "
1812 << pi2_event_loop->context().monotonic_event_time;
1813
1814 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1815 ++pi2_pong_count;
1816 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1817 });
1818
1819 log_reader_factory.Run();
1820 EXPECT_EQ(pi1_ping_count, 2030);
1821 EXPECT_EQ(pi2_ping_count, 2030);
1822 EXPECT_EQ(pi1_pong_count, 2030);
1823 EXPECT_EQ(pi2_pong_count, 2030);
1824
1825 reader.Deregister();
1826}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001827
Austin Schuh8bd96322020-02-13 21:18:22 -08001828// Tests that we can read log files where the monotonic clocks drift and don't
1829// match correctly. While we are here, also test that different ending times
1830// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001831TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001832 // TODO(austin): Negate...
1833 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1834
Austin Schuh66168842021-08-17 19:42:21 -07001835 time_converter_.AddMonotonic(
1836 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001837 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1838 // skew to be 200 uS/s
1839 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1840 {chrono::milliseconds(95),
1841 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1842 // Run another 200 ms to have one logger start first.
1843 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1844 {chrono::milliseconds(200), chrono::milliseconds(200)});
1845 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1846 // go far enough to cause problems if this isn't accounted for.
1847 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1848 {chrono::milliseconds(20000),
1849 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1850 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1851 {chrono::milliseconds(40000),
1852 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1853 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1854 {chrono::milliseconds(400), chrono::milliseconds(400)});
1855
Austin Schuhcde938c2020-02-02 17:30:07 -08001856 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001857 LoggerState pi2_logger = MakeLogger(pi2_);
1858
Austin Schuh58646e22021-08-23 23:51:46 -07001859 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1860 << pi2_->realtime_now() << " distributed "
1861 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001862
Austin Schuh58646e22021-08-23 23:51:46 -07001863 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1864 << pi2_->realtime_now() << " distributed "
1865 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001866
Austin Schuh87dd3832021-01-01 23:07:31 -08001867 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001868
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001869 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001870
Austin Schuh87dd3832021-01-01 23:07:31 -08001871 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001872
Austin Schuh8bd96322020-02-13 21:18:22 -08001873 {
1874 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001875 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001876
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001877 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001878 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001879
Austin Schuh87dd3832021-01-01 23:07:31 -08001880 // Make sure we slewed time far enough so that the difference is greater
1881 // than the network delay. This confirms that if we sort incorrectly, it
1882 // would show in the results.
1883 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001884 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001885 -event_loop_factory_.send_delay() -
1886 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001887
Austin Schuh87dd3832021-01-01 23:07:31 -08001888 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001889
Austin Schuh87dd3832021-01-01 23:07:31 -08001890 // And now check that we went far enough the other way to make sure we
1891 // cover both problems.
1892 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001893 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001894 event_loop_factory_.send_delay() +
1895 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001896 }
1897
1898 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001899 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001900 }
1901
Austin Schuh72211ae2021-08-05 14:02:30 -07001902 LogReader reader(
1903 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001904
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001905 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001906 log_reader_factory.set_send_delay(chrono::microseconds(0));
1907
Austin Schuhcde938c2020-02-02 17:30:07 -08001908 const Node *pi1 =
1909 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1910 const Node *pi2 =
1911 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1912
Austin Schuh2f8fd752020-09-01 22:38:28 -07001913 // This sends out the fetched messages and advances time to the start of the
1914 // log file.
1915 reader.Register(&log_reader_factory);
1916
1917 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1918 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1919 LOG(INFO) << "now pi1 "
1920 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1921 LOG(INFO) << "now pi2 "
1922 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1923
Austin Schuhcde938c2020-02-02 17:30:07 -08001924 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001925 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1926 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001927 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1928 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001929 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1930 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001931 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1932
Austin Schuh07676622021-01-21 18:59:17 -08001933 EXPECT_THAT(reader.LoggedNodes(),
1934 ::testing::ElementsAre(
1935 configuration::GetNode(reader.logged_configuration(), pi1),
1936 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001937
1938 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1939
1940 std::unique_ptr<EventLoop> pi1_event_loop =
1941 log_reader_factory.MakeEventLoop("test", pi1);
1942 std::unique_ptr<EventLoop> pi2_event_loop =
1943 log_reader_factory.MakeEventLoop("test", pi2);
1944
1945 int pi1_ping_count = 30;
1946 int pi2_ping_count = 30;
1947 int pi1_pong_count = 30;
1948 int pi2_pong_count = 30;
1949
1950 // Confirm that the ping value matches.
1951 pi1_event_loop->MakeWatcher(
1952 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1953 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1954 << pi1_event_loop->context().monotonic_remote_time << " -> "
1955 << pi1_event_loop->context().monotonic_event_time;
1956 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1957
1958 ++pi1_ping_count;
1959 });
1960 pi2_event_loop->MakeWatcher(
1961 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1962 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1963 << pi2_event_loop->context().monotonic_remote_time << " -> "
1964 << pi2_event_loop->context().monotonic_event_time;
1965 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1966
1967 ++pi2_ping_count;
1968 });
1969
1970 // Confirm that the ping and pong counts both match, and the value also
1971 // matches.
1972 pi1_event_loop->MakeWatcher(
1973 "/test", [&pi1_event_loop, &pi1_ping_count,
1974 &pi1_pong_count](const examples::Pong &pong) {
1975 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1976 << pi1_event_loop->context().monotonic_remote_time << " -> "
1977 << pi1_event_loop->context().monotonic_event_time;
1978
1979 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1980 ++pi1_pong_count;
1981 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1982 });
1983 pi2_event_loop->MakeWatcher(
1984 "/test", [&pi2_event_loop, &pi2_ping_count,
1985 &pi2_pong_count](const examples::Pong &pong) {
1986 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1987 << pi2_event_loop->context().monotonic_remote_time << " -> "
1988 << pi2_event_loop->context().monotonic_event_time;
1989
1990 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1991 ++pi2_pong_count;
1992 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1993 });
1994
1995 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001996 EXPECT_EQ(pi1_ping_count, 6030);
1997 EXPECT_EQ(pi2_ping_count, 6030);
1998 EXPECT_EQ(pi1_pong_count, 6030);
1999 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08002000
2001 reader.Deregister();
2002}
2003
Austin Schuh5212cad2020-09-09 23:12:09 -07002004// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002005TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002006 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07002007 // Make a bunch of parts.
2008 {
2009 LoggerState pi1_logger = MakeLogger(pi1_);
2010 LoggerState pi2_logger = MakeLogger(pi2_);
2011
2012 event_loop_factory_.RunFor(chrono::milliseconds(95));
2013
2014 StartLogger(&pi1_logger);
2015 StartLogger(&pi2_logger);
2016
2017 event_loop_factory_.RunFor(chrono::milliseconds(2000));
2018 }
2019
Austin Schuh11d43732020-09-21 17:28:30 -07002020 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002021 VerifyParts(sorted_parts);
2022}
Austin Schuh11d43732020-09-21 17:28:30 -07002023
Austin Schuh3bd4c402020-11-06 18:19:06 -08002024// Tests that we can sort a bunch of parts with an empty part. We should ignore
2025// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08002026TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002027 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002028 // Make a bunch of parts.
2029 {
2030 LoggerState pi1_logger = MakeLogger(pi1_);
2031 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07002032
Austin Schuh3bd4c402020-11-06 18:19:06 -08002033 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07002034
Austin Schuh3bd4c402020-11-06 18:19:06 -08002035 StartLogger(&pi1_logger);
2036 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07002037
Austin Schuh3bd4c402020-11-06 18:19:06 -08002038 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07002039 }
2040
Austin Schuh3bd4c402020-11-06 18:19:06 -08002041 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07002042 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07002043
Austin Schuh3bd4c402020-11-06 18:19:06 -08002044 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
2045 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07002046
Austin Schuh3bd4c402020-11-06 18:19:06 -08002047 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2048 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07002049}
2050
James Kuszmauldd0a5042021-10-28 23:38:04 -07002051// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08002052// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002053TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002054 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002055 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08002056 // Make a bunch of parts.
2057 {
2058 LoggerState pi1_logger = MakeLogger(pi1_);
2059 LoggerState pi2_logger = MakeLogger(pi2_);
2060
2061 event_loop_factory_.RunFor(chrono::milliseconds(95));
2062
James Kuszmauldd0a5042021-10-28 23:38:04 -07002063 StartLogger(&pi1_logger);
2064 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002065
2066 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002067
2068 pi1_logger.AppendAllFilenames(&actual_filenames);
2069 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002070 }
2071
Austin Schuhbfe6c572022-01-27 20:48:20 -08002072 ASSERT_THAT(actual_filenames,
2073 ::testing::UnorderedElementsAreArray(logfiles_));
2074
Austin Schuh3bd4c402020-11-06 18:19:06 -08002075 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07002076 // For snappy, needs to have enough data to be >1 chunk of compressed data so
2077 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08002078 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08002079 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08002080
2081 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08002082 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08002083 compressed_contents.substr(0, compressed_contents.size() - 100));
2084
2085 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
2086 VerifyParts(sorted_parts);
2087}
Austin Schuh3bd4c402020-11-06 18:19:06 -08002088
Austin Schuh01b4c352020-09-21 23:09:39 -07002089// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08002090TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002091 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07002092 {
2093 LoggerState pi1_logger = MakeLogger(pi1_);
2094 LoggerState pi2_logger = MakeLogger(pi2_);
2095
2096 event_loop_factory_.RunFor(chrono::milliseconds(95));
2097
2098 StartLogger(&pi1_logger);
2099 StartLogger(&pi2_logger);
2100
2101 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2102 }
2103
Austin Schuh287d43d2020-12-04 20:19:33 -08002104 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07002105
2106 // Remap just on pi1.
2107 reader.RemapLoggedChannel<aos::timing::Report>(
2108 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
2109
2110 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2111 log_reader_factory.set_send_delay(chrono::microseconds(0));
2112
Austin Schuh1c227352021-09-17 12:53:54 -07002113 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
2114 ASSERT_EQ(remapped_channels.size(), 1u);
2115 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
2116 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
2117
Austin Schuh01b4c352020-09-21 23:09:39 -07002118 reader.Register(&log_reader_factory);
2119
2120 const Node *pi1 =
2121 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2122 const Node *pi2 =
2123 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2124
2125 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2126 // else should have moved.
2127 std::unique_ptr<EventLoop> pi1_event_loop =
2128 log_reader_factory.MakeEventLoop("test", pi1);
2129 pi1_event_loop->SkipTimingReport();
2130 std::unique_ptr<EventLoop> full_pi1_event_loop =
2131 log_reader_factory.MakeEventLoop("test", pi1);
2132 full_pi1_event_loop->SkipTimingReport();
2133 std::unique_ptr<EventLoop> pi2_event_loop =
2134 log_reader_factory.MakeEventLoop("test", pi2);
2135 pi2_event_loop->SkipTimingReport();
2136
2137 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
2138 "/aos");
2139 MessageCounter<aos::timing::Report> full_pi1_timing_report(
2140 full_pi1_event_loop.get(), "/pi1/aos");
2141 MessageCounter<aos::timing::Report> pi1_original_timing_report(
2142 pi1_event_loop.get(), "/original/aos");
2143 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
2144 full_pi1_event_loop.get(), "/original/pi1/aos");
2145 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
2146 "/aos");
2147
2148 log_reader_factory.Run();
2149
2150 EXPECT_EQ(pi1_timing_report.count(), 0u);
2151 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
2152 EXPECT_NE(pi1_original_timing_report.count(), 0u);
2153 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
2154 EXPECT_NE(pi2_timing_report.count(), 0u);
2155
2156 reader.Deregister();
2157}
2158
Austin Schuh006a9f52021-04-07 16:24:18 -07002159// Tests that we can remap a forwarded channel as well.
2160TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
2161 time_converter_.StartEqual();
2162 {
2163 LoggerState pi1_logger = MakeLogger(pi1_);
2164 LoggerState pi2_logger = MakeLogger(pi2_);
2165
2166 event_loop_factory_.RunFor(chrono::milliseconds(95));
2167
2168 StartLogger(&pi1_logger);
2169 StartLogger(&pi2_logger);
2170
2171 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2172 }
2173
2174 LogReader reader(SortParts(logfiles_));
2175
2176 reader.RemapLoggedChannel<examples::Ping>("/test");
2177
2178 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2179 log_reader_factory.set_send_delay(chrono::microseconds(0));
2180
2181 reader.Register(&log_reader_factory);
2182
2183 const Node *pi1 =
2184 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2185 const Node *pi2 =
2186 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2187
2188 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2189 // else should have moved.
2190 std::unique_ptr<EventLoop> pi1_event_loop =
2191 log_reader_factory.MakeEventLoop("test", pi1);
2192 pi1_event_loop->SkipTimingReport();
2193 std::unique_ptr<EventLoop> full_pi1_event_loop =
2194 log_reader_factory.MakeEventLoop("test", pi1);
2195 full_pi1_event_loop->SkipTimingReport();
2196 std::unique_ptr<EventLoop> pi2_event_loop =
2197 log_reader_factory.MakeEventLoop("test", pi2);
2198 pi2_event_loop->SkipTimingReport();
2199
2200 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2201 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2202 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2203 "/original/test");
2204 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2205 "/original/test");
2206
2207 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2208 pi1_original_ping_timestamp;
2209 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2210 pi1_ping_timestamp;
2211 if (!shared()) {
2212 pi1_original_ping_timestamp =
2213 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2214 pi1_event_loop.get(),
2215 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2216 pi1_ping_timestamp =
2217 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2218 pi1_event_loop.get(),
2219 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2220 }
2221
2222 log_reader_factory.Run();
2223
2224 EXPECT_EQ(pi1_ping.count(), 0u);
2225 EXPECT_EQ(pi2_ping.count(), 0u);
2226 EXPECT_NE(pi1_original_ping.count(), 0u);
2227 EXPECT_NE(pi2_original_ping.count(), 0u);
2228 if (!shared()) {
2229 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2230 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2231 }
2232
2233 reader.Deregister();
2234}
2235
James Kuszmaul09632422022-05-25 15:56:19 -07002236// Tests that we observe all the same events in log replay (for a given node)
2237// whether we just register an event loop for that node or if we register a full
2238// event loop factory.
2239TEST_P(MultinodeLoggerTest, SingleNodeReplay) {
2240 time_converter_.StartEqual();
2241 constexpr chrono::milliseconds kStartupDelay(95);
2242 {
2243 LoggerState pi1_logger = MakeLogger(pi1_);
2244 LoggerState pi2_logger = MakeLogger(pi2_);
2245
2246 event_loop_factory_.RunFor(kStartupDelay);
2247
2248 StartLogger(&pi1_logger);
2249 StartLogger(&pi2_logger);
2250
2251 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2252 }
2253
2254 LogReader full_reader(SortParts(logfiles_));
2255 LogReader single_node_reader(SortParts(logfiles_));
2256
2257 SimulatedEventLoopFactory full_factory(full_reader.configuration());
2258 SimulatedEventLoopFactory single_node_factory(
2259 single_node_reader.configuration());
James Kuszmaul94ca5132022-07-19 09:11:08 -07002260 single_node_factory.SkipTimingReport();
2261 single_node_factory.DisableStatistics();
James Kuszmaul09632422022-05-25 15:56:19 -07002262 std::unique_ptr<EventLoop> replay_event_loop =
2263 single_node_factory.GetNodeEventLoopFactory("pi1")->MakeEventLoop(
2264 "log_reader");
2265
2266 full_reader.Register(&full_factory);
2267 single_node_reader.Register(replay_event_loop.get());
James Kuszmaul09632422022-05-25 15:56:19 -07002268
2269 const Node *full_pi1 =
2270 configuration::GetNode(full_factory.configuration(), "pi1");
2271
2272 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2273 // else should have moved.
2274 std::unique_ptr<EventLoop> full_event_loop =
2275 full_factory.MakeEventLoop("test", full_pi1);
2276 full_event_loop->SkipTimingReport();
2277 full_event_loop->SkipAosLog();
2278 // maps are indexed on channel index.
2279 // observed_messages: {channel_index: [(message_sent_time, was_fetched),...]}
2280 std::map<size_t, std::vector<std::pair<monotonic_clock::time_point, bool>>>
2281 observed_messages;
2282 std::map<size_t, std::unique_ptr<RawFetcher>> fetchers;
2283 for (size_t ii = 0; ii < full_event_loop->configuration()->channels()->size();
2284 ++ii) {
2285 const Channel *channel =
2286 full_event_loop->configuration()->channels()->Get(ii);
2287 // We currently don't support replaying remote timestamp channels in
2288 // realtime replay.
2289 if (channel->name()->string_view().find("remote_timestamp") !=
2290 std::string_view::npos) {
2291 continue;
2292 }
2293 if (configuration::ChannelIsReadableOnNode(channel, full_pi1)) {
2294 observed_messages[ii] = {};
2295 fetchers[ii] = full_event_loop->MakeRawFetcher(channel);
2296 full_event_loop->OnRun([ii, &observed_messages, &fetchers]() {
2297 if (fetchers[ii]->Fetch()) {
2298 observed_messages[ii].push_back(std::make_pair(
2299 fetchers[ii]->context().monotonic_event_time, true));
2300 }
2301 });
2302 full_event_loop->MakeRawNoArgWatcher(
2303 channel, [ii, &observed_messages](const Context &context) {
2304 observed_messages[ii].push_back(
2305 std::make_pair(context.monotonic_event_time, false));
2306 });
2307 }
2308 }
2309
2310 full_factory.Run();
2311 fetchers.clear();
2312 full_reader.Deregister();
2313
2314 const Node *single_node_pi1 =
2315 configuration::GetNode(single_node_factory.configuration(), "pi1");
2316 std::map<size_t, std::unique_ptr<RawFetcher>> single_node_fetchers;
2317
2318 std::unique_ptr<EventLoop> single_node_event_loop =
2319 single_node_factory.MakeEventLoop("test", single_node_pi1);
2320 single_node_event_loop->SkipTimingReport();
2321 single_node_event_loop->SkipAosLog();
2322 for (size_t ii = 0;
2323 ii < single_node_event_loop->configuration()->channels()->size(); ++ii) {
2324 const Channel *channel =
2325 single_node_event_loop->configuration()->channels()->Get(ii);
2326 single_node_factory.DisableForwarding(channel);
2327 if (configuration::ChannelIsReadableOnNode(channel, single_node_pi1)) {
2328 single_node_fetchers[ii] =
2329 single_node_event_loop->MakeRawFetcher(channel);
2330 single_node_event_loop->OnRun([channel, ii, &single_node_fetchers]() {
2331 EXPECT_FALSE(single_node_fetchers[ii]->Fetch())
2332 << "Single EventLoop replay doesn't support pre-loading fetchers. "
2333 << configuration::StrippedChannelToString(channel);
2334 });
2335 single_node_event_loop->MakeRawNoArgWatcher(
2336 channel, [ii, &observed_messages, channel,
2337 kStartupDelay](const Context &context) {
2338 if (observed_messages[ii].empty()) {
2339 FAIL() << "Observed extra message at "
2340 << context.monotonic_event_time << " on "
2341 << configuration::StrippedChannelToString(channel);
2342 return;
2343 }
2344 const std::pair<monotonic_clock::time_point, bool> &message =
2345 observed_messages[ii].front();
2346 if (message.second) {
2347 EXPECT_LE(message.first,
2348 context.monotonic_event_time + kStartupDelay)
2349 << "Mismatched message times " << context.monotonic_event_time
2350 << " and " << message.first << " on "
2351 << configuration::StrippedChannelToString(channel);
2352 } else {
2353 EXPECT_EQ(message.first,
2354 context.monotonic_event_time + kStartupDelay)
2355 << "Mismatched message times " << context.monotonic_event_time
2356 << " and " << message.first << " on "
2357 << configuration::StrippedChannelToString(channel);
2358 }
2359 observed_messages[ii].erase(observed_messages[ii].begin());
2360 });
2361 }
2362 }
2363
2364 single_node_factory.Run();
2365
2366 single_node_fetchers.clear();
2367
2368 single_node_reader.Deregister();
2369
2370 for (const auto &pair : observed_messages) {
2371 EXPECT_TRUE(pair.second.empty())
2372 << "Missed " << pair.second.size() << " messages on "
2373 << configuration::StrippedChannelToString(
2374 single_node_event_loop->configuration()->channels()->Get(
2375 pair.first));
2376 }
2377}
2378
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002379// Tests that we properly recreate forwarded timestamps when replaying a log.
2380// This should be enough that we can then re-run the logger and get a valid log
2381// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002382TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002383 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002384 {
2385 LoggerState pi1_logger = MakeLogger(pi1_);
2386 LoggerState pi2_logger = MakeLogger(pi2_);
2387
2388 event_loop_factory_.RunFor(chrono::milliseconds(95));
2389
2390 StartLogger(&pi1_logger);
2391 StartLogger(&pi2_logger);
2392
2393 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2394 }
2395
Austin Schuh287d43d2020-12-04 20:19:33 -08002396 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002397
2398 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2399 log_reader_factory.set_send_delay(chrono::microseconds(0));
2400
2401 // This sends out the fetched messages and advances time to the start of the
2402 // log file.
2403 reader.Register(&log_reader_factory);
2404
2405 const Node *pi1 =
2406 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2407 const Node *pi2 =
2408 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2409
2410 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2411 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2412 LOG(INFO) << "now pi1 "
2413 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2414 LOG(INFO) << "now pi2 "
2415 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2416
Austin Schuh07676622021-01-21 18:59:17 -08002417 EXPECT_THAT(reader.LoggedNodes(),
2418 ::testing::ElementsAre(
2419 configuration::GetNode(reader.logged_configuration(), pi1),
2420 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002421
2422 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2423
2424 std::unique_ptr<EventLoop> pi1_event_loop =
2425 log_reader_factory.MakeEventLoop("test", pi1);
2426 std::unique_ptr<EventLoop> pi2_event_loop =
2427 log_reader_factory.MakeEventLoop("test", pi2);
2428
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002429 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2430 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2431 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2432 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2433
2434 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2435 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2436 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2437 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2438
2439 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2440 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2441 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2442 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2443
2444 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2445 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2446 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2447 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2448
2449 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2450 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2451 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2452 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2453
2454 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2455 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2456 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2457 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2458
Austin Schuh969cd602021-01-03 00:09:45 -08002459 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002460 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002461
Austin Schuh61e973f2021-02-21 21:43:56 -08002462 for (std::pair<int, std::string> channel :
2463 shared()
2464 ? std::vector<
2465 std::pair<int, std::string>>{{-1,
2466 "/aos/remote_timestamps/pi2"}}
2467 : std::vector<std::pair<int, std::string>>{
2468 {pi1_timestamp_channel,
2469 "/aos/remote_timestamps/pi2/pi1/aos/"
2470 "aos-message_bridge-Timestamp"},
2471 {ping_timestamp_channel,
2472 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2473 pi1_event_loop->MakeWatcher(
2474 channel.second,
2475 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2476 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2477 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2478 &ping_on_pi2_fetcher, network_delay, send_delay,
2479 channel_index = channel.first](const RemoteMessage &header) {
2480 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2481 chrono::nanoseconds(header.monotonic_sent_time()));
2482 const aos::realtime_clock::time_point header_realtime_sent_time(
2483 chrono::nanoseconds(header.realtime_sent_time()));
2484 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2485 chrono::nanoseconds(header.monotonic_remote_time()));
2486 const aos::realtime_clock::time_point header_realtime_remote_time(
2487 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002488
Austin Schuh61e973f2021-02-21 21:43:56 -08002489 if (channel_index != -1) {
2490 ASSERT_EQ(channel_index, header.channel_index());
2491 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002492
Austin Schuh61e973f2021-02-21 21:43:56 -08002493 const Context *pi1_context = nullptr;
2494 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002495
Austin Schuh61e973f2021-02-21 21:43:56 -08002496 if (header.channel_index() == pi1_timestamp_channel) {
2497 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2498 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2499 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2500 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2501 } else if (header.channel_index() == ping_timestamp_channel) {
2502 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2503 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2504 pi1_context = &ping_on_pi1_fetcher.context();
2505 pi2_context = &ping_on_pi2_fetcher.context();
2506 } else {
2507 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2508 << configuration::CleanedChannelToString(
2509 pi1_event_loop->configuration()->channels()->Get(
2510 header.channel_index()));
2511 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002512
Austin Schuh61e973f2021-02-21 21:43:56 -08002513 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002514 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2515 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002516
Austin Schuh61e973f2021-02-21 21:43:56 -08002517 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2518 EXPECT_EQ(pi2_context->remote_queue_index,
2519 header.remote_queue_index());
2520 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002521
Austin Schuh61e973f2021-02-21 21:43:56 -08002522 EXPECT_EQ(pi2_context->monotonic_event_time,
2523 header_monotonic_sent_time);
2524 EXPECT_EQ(pi2_context->realtime_event_time,
2525 header_realtime_sent_time);
2526 EXPECT_EQ(pi2_context->realtime_remote_time,
2527 header_realtime_remote_time);
2528 EXPECT_EQ(pi2_context->monotonic_remote_time,
2529 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002530
Austin Schuh61e973f2021-02-21 21:43:56 -08002531 EXPECT_EQ(pi1_context->realtime_event_time,
2532 header_realtime_remote_time);
2533 EXPECT_EQ(pi1_context->monotonic_event_time,
2534 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002535
Austin Schuh61e973f2021-02-21 21:43:56 -08002536 // Time estimation isn't perfect, but we know the clocks were
2537 // identical when logged, so we know when this should have come back.
2538 // Confirm we got it when we expected.
2539 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2540 pi1_context->monotonic_event_time + 2 * network_delay +
2541 send_delay);
2542 });
2543 }
2544 for (std::pair<int, std::string> channel :
2545 shared()
2546 ? std::vector<
2547 std::pair<int, std::string>>{{-1,
2548 "/aos/remote_timestamps/pi1"}}
2549 : std::vector<std::pair<int, std::string>>{
2550 {pi2_timestamp_channel,
2551 "/aos/remote_timestamps/pi1/pi2/aos/"
2552 "aos-message_bridge-Timestamp"}}) {
2553 pi2_event_loop->MakeWatcher(
2554 channel.second,
2555 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2556 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2557 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2558 &pong_on_pi1_fetcher, network_delay, send_delay,
2559 channel_index = channel.first](const RemoteMessage &header) {
2560 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2561 chrono::nanoseconds(header.monotonic_sent_time()));
2562 const aos::realtime_clock::time_point header_realtime_sent_time(
2563 chrono::nanoseconds(header.realtime_sent_time()));
2564 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2565 chrono::nanoseconds(header.monotonic_remote_time()));
2566 const aos::realtime_clock::time_point header_realtime_remote_time(
2567 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002568
Austin Schuh61e973f2021-02-21 21:43:56 -08002569 if (channel_index != -1) {
2570 ASSERT_EQ(channel_index, header.channel_index());
2571 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002572
Austin Schuh61e973f2021-02-21 21:43:56 -08002573 const Context *pi2_context = nullptr;
2574 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002575
Austin Schuh61e973f2021-02-21 21:43:56 -08002576 if (header.channel_index() == pi2_timestamp_channel) {
2577 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2578 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2579 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2580 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2581 } else if (header.channel_index() == pong_timestamp_channel) {
2582 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2583 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2584 pi2_context = &pong_on_pi2_fetcher.context();
2585 pi1_context = &pong_on_pi1_fetcher.context();
2586 } else {
2587 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2588 << configuration::CleanedChannelToString(
2589 pi2_event_loop->configuration()->channels()->Get(
2590 header.channel_index()));
2591 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002592
Austin Schuh61e973f2021-02-21 21:43:56 -08002593 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002594 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2595 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002596
Austin Schuh61e973f2021-02-21 21:43:56 -08002597 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2598 EXPECT_EQ(pi1_context->remote_queue_index,
2599 header.remote_queue_index());
2600 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002601
Austin Schuh61e973f2021-02-21 21:43:56 -08002602 EXPECT_EQ(pi1_context->monotonic_event_time,
2603 header_monotonic_sent_time);
2604 EXPECT_EQ(pi1_context->realtime_event_time,
2605 header_realtime_sent_time);
2606 EXPECT_EQ(pi1_context->realtime_remote_time,
2607 header_realtime_remote_time);
2608 EXPECT_EQ(pi1_context->monotonic_remote_time,
2609 header_monotonic_remote_time);
2610
2611 EXPECT_EQ(pi2_context->realtime_event_time,
2612 header_realtime_remote_time);
2613 EXPECT_EQ(pi2_context->monotonic_event_time,
2614 header_monotonic_remote_time);
2615
2616 // Time estimation isn't perfect, but we know the clocks were
2617 // identical when logged, so we know when this should have come back.
2618 // Confirm we got it when we expected.
2619 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2620 pi2_context->monotonic_event_time + 2 * network_delay +
2621 send_delay);
2622 });
2623 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002624
2625 // And confirm we can re-create a log again, while checking the contents.
2626 {
2627 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002628 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002629 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002630 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002631
Austin Schuh25b46712021-01-03 00:04:38 -08002632 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2633 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002634
2635 log_reader_factory.Run();
2636 }
2637
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002638 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002639
2640 // And verify that we can run the LogReader over the relogged files without
2641 // hitting any fatal errors.
2642 {
2643 LogReader relogged_reader(SortParts(
2644 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2645 relogged_reader.Register();
2646
2647 relogged_reader.event_loop_factory()->Run();
2648 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002649}
2650
Austin Schuh315b96b2020-12-11 21:21:12 -08002651// Tests that we properly populate and extract the logger_start time by setting
2652// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002653TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002654 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002655 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002656 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002657 {
2658 LoggerState pi1_logger = MakeLogger(pi1_);
2659 LoggerState pi2_logger = MakeLogger(pi2_);
2660
Austin Schuh315b96b2020-12-11 21:21:12 -08002661 StartLogger(&pi1_logger);
2662 StartLogger(&pi2_logger);
2663
2664 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002665
2666 pi1_logger.AppendAllFilenames(&actual_filenames);
2667 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002668 }
2669
Austin Schuhf5f99f32022-02-07 20:05:37 -08002670 ASSERT_THAT(actual_filenames,
2671 ::testing::UnorderedElementsAreArray(logfiles_));
2672
Austin Schuh315b96b2020-12-11 21:21:12 -08002673 for (const LogFile &log_file : SortParts(logfiles_)) {
2674 for (const LogParts &log_part : log_file.parts) {
2675 if (log_part.node == log_file.logger_node) {
2676 EXPECT_EQ(log_part.logger_monotonic_start_time,
2677 aos::monotonic_clock::min_time);
2678 EXPECT_EQ(log_part.logger_realtime_start_time,
2679 aos::realtime_clock::min_time);
2680 } else {
2681 const chrono::seconds offset = log_file.logger_node == "pi1"
2682 ? -chrono::seconds(1000)
2683 : chrono::seconds(1000);
2684 EXPECT_EQ(log_part.logger_monotonic_start_time,
2685 log_part.monotonic_start_time + offset);
2686 EXPECT_EQ(log_part.logger_realtime_start_time,
2687 log_file.realtime_start_time +
2688 (log_part.logger_monotonic_start_time -
2689 log_file.monotonic_start_time));
2690 }
2691 }
2692 }
2693}
2694
Austin Schuh6bb8a822021-03-31 23:04:39 -07002695// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002696TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002697 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2698 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002699 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002700 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002701 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2702 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2703 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2704 LoggerState pi1_logger = MakeLogger(pi1_);
2705 LoggerState pi2_logger = MakeLogger(pi2_);
2706
2707 StartLogger(&pi1_logger);
2708 StartLogger(&pi2_logger);
2709
2710 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2711 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2712 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2713 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2714 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2715 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2716 for (auto &file : logfiles_) {
2717 struct stat s;
2718 EXPECT_EQ(0, stat(file.c_str(), &s));
2719 }
2720}
2721
2722// Test that renaming the file base dies.
2723TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2724 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002725 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002726 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002727 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2728 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2729 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2730 LoggerState pi1_logger = MakeLogger(pi1_);
2731 StartLogger(&pi1_logger);
2732 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2733 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2734 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2735 "Rename of file base from");
2736}
2737
Austin Schuh8bd96322020-02-13 21:18:22 -08002738// TODO(austin): We can write a test which recreates a logfile and confirms that
2739// we get it back. That is the ultimate test.
2740
Austin Schuh315b96b2020-12-11 21:21:12 -08002741// Tests that we properly recreate forwarded timestamps when replaying a log.
2742// This should be enough that we can then re-run the logger and get a valid log
2743// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002744TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002745 std::vector<std::string> actual_filenames;
2746
Austin Schuh58646e22021-08-23 23:51:46 -07002747 const UUID pi1_boot0 = UUID::Random();
2748 const UUID pi2_boot0 = UUID::Random();
2749 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002750 {
Austin Schuh58646e22021-08-23 23:51:46 -07002751 CHECK_EQ(pi1_index_, 0u);
2752 CHECK_EQ(pi2_index_, 1u);
2753
2754 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2755 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2756 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2757
2758 time_converter_.AddNextTimestamp(
2759 distributed_clock::epoch(),
2760 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2761 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2762 time_converter_.AddNextTimestamp(
2763 distributed_clock::epoch() + reboot_time,
2764 {BootTimestamp::epoch() + reboot_time,
2765 BootTimestamp{
2766 .boot = 1,
2767 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2768 }
2769
2770 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002771 LoggerState pi1_logger = MakeLogger(pi1_);
2772
2773 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002774 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2775 pi1_boot0);
2776 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2777 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002778
2779 StartLogger(&pi1_logger);
2780
2781 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2782
Austin Schuh58646e22021-08-23 23:51:46 -07002783 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002784
2785 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002786 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2787 pi1_boot0);
2788 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2789 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002790
2791 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002792 }
2793
Austin Schuhbfe6c572022-01-27 20:48:20 -08002794 std::sort(actual_filenames.begin(), actual_filenames.end());
2795 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2796 ASSERT_THAT(actual_filenames,
2797 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2798
Austin Schuh72211ae2021-08-05 14:02:30 -07002799 // Confirm that our new oldest timestamps properly update as we reboot and
2800 // rotate.
2801 for (const std::string &file : pi1_reboot_logfiles_) {
2802 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2803 ReadHeader(file);
2804 CHECK(log_header);
2805 if (log_header->message().has_configuration()) {
2806 continue;
2807 }
2808
Austin Schuh58646e22021-08-23 23:51:46 -07002809 const monotonic_clock::time_point monotonic_start_time =
2810 monotonic_clock::time_point(
2811 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2812 const UUID source_node_boot_uuid = UUID::FromString(
2813 log_header->message().source_node_boot_uuid()->string_view());
2814
Austin Schuh72211ae2021-08-05 14:02:30 -07002815 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002816 // The remote message channel should rotate later and have more parts.
2817 // This only is true on the log files with shared remote messages.
2818 //
2819 // TODO(austin): I'm not the most thrilled with this test pattern... It
2820 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002821 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2822 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002823 switch (log_header->message().parts_index()) {
2824 case 0:
2825 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2826 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2827 break;
2828 case 1:
2829 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2830 ASSERT_EQ(monotonic_start_time,
2831 monotonic_clock::epoch() + chrono::seconds(1));
2832 break;
2833 case 2:
2834 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2835 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2836 break;
2837 case 3:
2838 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2839 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2840 chrono::nanoseconds(2322999462))
2841 << " on " << file;
2842 break;
2843 default:
2844 FAIL();
2845 break;
2846 }
2847 } else {
2848 switch (log_header->message().parts_index()) {
2849 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002850 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002851 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2852 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2853 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002854 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002855 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2856 ASSERT_EQ(monotonic_start_time,
2857 monotonic_clock::epoch() + chrono::seconds(1));
2858 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002859 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002860 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002861 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2862 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2863 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002864 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002865 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2866 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2867 chrono::nanoseconds(2322999462))
2868 << " on " << file;
2869 break;
2870 default:
2871 FAIL();
2872 break;
2873 }
Austin Schuh58646e22021-08-23 23:51:46 -07002874 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002875 continue;
2876 }
2877 SCOPED_TRACE(file);
2878 SCOPED_TRACE(aos::FlatbufferToJson(
2879 *log_header, {.multi_line = true, .max_vector_size = 100}));
2880 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2881 ASSERT_EQ(
2882 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2883 EXPECT_EQ(
2884 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2885 monotonic_clock::max_time.time_since_epoch().count());
2886 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2887 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2888 2u);
2889 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2890 monotonic_clock::max_time.time_since_epoch().count());
2891 ASSERT_TRUE(log_header->message()
2892 .has_oldest_remote_unreliable_monotonic_timestamps());
2893 ASSERT_EQ(log_header->message()
2894 .oldest_remote_unreliable_monotonic_timestamps()
2895 ->size(),
2896 2u);
2897 EXPECT_EQ(log_header->message()
2898 .oldest_remote_unreliable_monotonic_timestamps()
2899 ->Get(0),
2900 monotonic_clock::max_time.time_since_epoch().count());
2901 ASSERT_TRUE(log_header->message()
2902 .has_oldest_local_unreliable_monotonic_timestamps());
2903 ASSERT_EQ(log_header->message()
2904 .oldest_local_unreliable_monotonic_timestamps()
2905 ->size(),
2906 2u);
2907 EXPECT_EQ(log_header->message()
2908 .oldest_local_unreliable_monotonic_timestamps()
2909 ->Get(0),
2910 monotonic_clock::max_time.time_since_epoch().count());
2911
2912 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2913 monotonic_clock::time_point(chrono::nanoseconds(
2914 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2915 1)));
2916 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2917 monotonic_clock::time_point(chrono::nanoseconds(
2918 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2919 const monotonic_clock::time_point
2920 oldest_remote_unreliable_monotonic_timestamps =
2921 monotonic_clock::time_point(chrono::nanoseconds(
2922 log_header->message()
2923 .oldest_remote_unreliable_monotonic_timestamps()
2924 ->Get(1)));
2925 const monotonic_clock::time_point
2926 oldest_local_unreliable_monotonic_timestamps =
2927 monotonic_clock::time_point(chrono::nanoseconds(
2928 log_header->message()
2929 .oldest_local_unreliable_monotonic_timestamps()
2930 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002931 const monotonic_clock::time_point
2932 oldest_remote_reliable_monotonic_timestamps =
2933 monotonic_clock::time_point(chrono::nanoseconds(
2934 log_header->message()
2935 .oldest_remote_reliable_monotonic_timestamps()
2936 ->Get(1)));
2937 const monotonic_clock::time_point
2938 oldest_local_reliable_monotonic_timestamps =
2939 monotonic_clock::time_point(chrono::nanoseconds(
2940 log_header->message()
2941 .oldest_local_reliable_monotonic_timestamps()
2942 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002943 const monotonic_clock::time_point
2944 oldest_logger_remote_unreliable_monotonic_timestamps =
2945 monotonic_clock::time_point(chrono::nanoseconds(
2946 log_header->message()
2947 .oldest_logger_remote_unreliable_monotonic_timestamps()
2948 ->Get(0)));
2949 const monotonic_clock::time_point
2950 oldest_logger_local_unreliable_monotonic_timestamps =
2951 monotonic_clock::time_point(chrono::nanoseconds(
2952 log_header->message()
2953 .oldest_logger_local_unreliable_monotonic_timestamps()
2954 ->Get(0)));
2955 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2956 monotonic_clock::max_time);
2957 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2958 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002959 switch (log_header->message().parts_index()) {
2960 case 0:
2961 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2962 monotonic_clock::max_time);
2963 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2964 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2965 monotonic_clock::max_time);
2966 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2967 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002968 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2969 monotonic_clock::max_time);
2970 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2971 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002972 break;
2973 case 1:
2974 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2975 monotonic_clock::time_point(chrono::microseconds(90200)));
2976 EXPECT_EQ(oldest_local_monotonic_timestamps,
2977 monotonic_clock::time_point(chrono::microseconds(90350)));
2978 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2979 monotonic_clock::time_point(chrono::microseconds(90200)));
2980 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2981 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002982 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2983 monotonic_clock::max_time);
2984 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2985 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002986 break;
2987 case 2:
2988 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08002989 monotonic_clock::time_point(chrono::microseconds(90200)))
2990 << file;
2991 EXPECT_EQ(oldest_local_monotonic_timestamps,
2992 monotonic_clock::time_point(chrono::microseconds(90350)))
2993 << file;
2994 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2995 monotonic_clock::time_point(chrono::microseconds(90200)))
2996 << file;
2997 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2998 monotonic_clock::time_point(chrono::microseconds(90350)))
2999 << file;
3000 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3001 monotonic_clock::time_point(chrono::microseconds(100000)))
3002 << file;
3003 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3004 monotonic_clock::time_point(chrono::microseconds(100150)))
3005 << file;
3006 break;
3007 case 3:
3008 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003009 monotonic_clock::time_point(chrono::milliseconds(1323) +
3010 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003011 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003012 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003013 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07003014 monotonic_clock::time_point(chrono::milliseconds(1323) +
3015 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07003016 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3017 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003018 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3019 monotonic_clock::max_time)
3020 << file;
3021 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3022 monotonic_clock::max_time)
3023 << file;
3024 break;
3025 case 4:
3026 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3027 monotonic_clock::time_point(chrono::milliseconds(1323) +
3028 chrono::microseconds(200)));
3029 EXPECT_EQ(oldest_local_monotonic_timestamps,
3030 monotonic_clock::time_point(chrono::microseconds(10100350)));
3031 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3032 monotonic_clock::time_point(chrono::milliseconds(1323) +
3033 chrono::microseconds(200)));
3034 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3035 monotonic_clock::time_point(chrono::microseconds(10100350)));
3036 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3037 monotonic_clock::time_point(chrono::microseconds(1423000)))
3038 << file;
3039 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3040 monotonic_clock::time_point(chrono::microseconds(10200150)))
3041 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07003042 break;
3043 default:
3044 FAIL();
3045 break;
3046 }
3047 }
3048
Austin Schuh315b96b2020-12-11 21:21:12 -08003049 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07003050 {
3051 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08003052
Austin Schuh58646e22021-08-23 23:51:46 -07003053 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3054 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08003055
Austin Schuh58646e22021-08-23 23:51:46 -07003056 // This sends out the fetched messages and advances time to the start of
3057 // the log file.
3058 reader.Register(&log_reader_factory);
3059
3060 log_reader_factory.Run();
3061
3062 reader.Deregister();
3063 }
Austin Schuh315b96b2020-12-11 21:21:12 -08003064}
3065
Austin Schuh5e14d842022-01-21 12:02:15 -08003066// Tests that we can sort a log which only has timestamps from the remote
3067// because the local message_bridge_client failed to connect.
3068TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
3069 const UUID pi1_boot0 = UUID::Random();
3070 const UUID pi2_boot0 = UUID::Random();
3071 const UUID pi2_boot1 = UUID::Random();
3072 {
3073 CHECK_EQ(pi1_index_, 0u);
3074 CHECK_EQ(pi2_index_, 1u);
3075
3076 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
3077 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
3078 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
3079
3080 time_converter_.AddNextTimestamp(
3081 distributed_clock::epoch(),
3082 {BootTimestamp::epoch(), BootTimestamp::epoch()});
3083 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
3084 time_converter_.AddNextTimestamp(
3085 distributed_clock::epoch() + reboot_time,
3086 {BootTimestamp::epoch() + reboot_time,
3087 BootTimestamp{
3088 .boot = 1,
3089 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
3090 }
3091 pi2_->Disconnect(pi1_->node());
3092
3093 std::vector<std::string> filenames;
3094 {
3095 LoggerState pi1_logger = MakeLogger(pi1_);
3096
3097 event_loop_factory_.RunFor(chrono::milliseconds(95));
3098 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3099 pi1_boot0);
3100 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3101 pi2_boot0);
3102
3103 StartLogger(&pi1_logger);
3104
3105 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3106
3107 VLOG(1) << "Reboot now!";
3108
3109 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3110 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
3111 pi1_boot0);
3112 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
3113 pi2_boot1);
3114 pi1_logger.AppendAllFilenames(&filenames);
3115 }
3116
Austin Schuhbfe6c572022-01-27 20:48:20 -08003117 std::sort(filenames.begin(), filenames.end());
3118
Austin Schuh5e14d842022-01-21 12:02:15 -08003119 // Confirm that our new oldest timestamps properly update as we reboot and
3120 // rotate.
3121 size_t timestamp_file_count = 0;
3122 for (const std::string &file : filenames) {
3123 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
3124 ReadHeader(file);
3125 CHECK(log_header);
3126
3127 if (log_header->message().has_configuration()) {
3128 continue;
3129 }
3130
3131 const monotonic_clock::time_point monotonic_start_time =
3132 monotonic_clock::time_point(
3133 chrono::nanoseconds(log_header->message().monotonic_start_time()));
3134 const UUID source_node_boot_uuid = UUID::FromString(
3135 log_header->message().source_node_boot_uuid()->string_view());
3136
3137 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
3138 ASSERT_EQ(
3139 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
3140 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
3141 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
3142 2u);
3143 ASSERT_TRUE(log_header->message()
3144 .has_oldest_remote_unreliable_monotonic_timestamps());
3145 ASSERT_EQ(log_header->message()
3146 .oldest_remote_unreliable_monotonic_timestamps()
3147 ->size(),
3148 2u);
3149 ASSERT_TRUE(log_header->message()
3150 .has_oldest_local_unreliable_monotonic_timestamps());
3151 ASSERT_EQ(log_header->message()
3152 .oldest_local_unreliable_monotonic_timestamps()
3153 ->size(),
3154 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003155 ASSERT_TRUE(log_header->message()
3156 .has_oldest_remote_reliable_monotonic_timestamps());
3157 ASSERT_EQ(log_header->message()
3158 .oldest_remote_reliable_monotonic_timestamps()
3159 ->size(),
3160 2u);
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003161 ASSERT_TRUE(
3162 log_header->message().has_oldest_local_reliable_monotonic_timestamps());
Austin Schuhf5f99f32022-02-07 20:05:37 -08003163 ASSERT_EQ(log_header->message()
3164 .oldest_local_reliable_monotonic_timestamps()
3165 ->size(),
3166 2u);
3167
3168 ASSERT_TRUE(
3169 log_header->message()
3170 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
3171 ASSERT_EQ(log_header->message()
3172 .oldest_logger_remote_unreliable_monotonic_timestamps()
3173 ->size(),
3174 2u);
3175 ASSERT_TRUE(log_header->message()
3176 .has_oldest_logger_local_unreliable_monotonic_timestamps());
3177 ASSERT_EQ(log_header->message()
3178 .oldest_logger_local_unreliable_monotonic_timestamps()
3179 ->size(),
3180 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08003181
3182 if (log_header->message().node()->name()->string_view() != "pi1") {
3183 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
3184 std::string::npos);
3185
3186 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
3187 ReadNthMessage(file, 0);
3188 CHECK(msg);
3189
3190 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
3191 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
3192
3193 const monotonic_clock::time_point
3194 expected_oldest_local_monotonic_timestamps(
3195 chrono::nanoseconds(msg->message().monotonic_sent_time()));
3196 const monotonic_clock::time_point
3197 expected_oldest_remote_monotonic_timestamps(
3198 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003199 const monotonic_clock::time_point
3200 expected_oldest_timestamp_monotonic_timestamps(
3201 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08003202
3203 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
3204 monotonic_clock::min_time);
3205 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
3206 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003207 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
3208 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08003209
3210 ++timestamp_file_count;
3211 // Since the log file is from the perspective of the other node,
3212 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3213 monotonic_clock::time_point(chrono::nanoseconds(
3214 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3215 0)));
3216 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3217 monotonic_clock::time_point(chrono::nanoseconds(
3218 log_header->message().oldest_local_monotonic_timestamps()->Get(
3219 0)));
3220 const monotonic_clock::time_point
3221 oldest_remote_unreliable_monotonic_timestamps =
3222 monotonic_clock::time_point(chrono::nanoseconds(
3223 log_header->message()
3224 .oldest_remote_unreliable_monotonic_timestamps()
3225 ->Get(0)));
3226 const monotonic_clock::time_point
3227 oldest_local_unreliable_monotonic_timestamps =
3228 monotonic_clock::time_point(chrono::nanoseconds(
3229 log_header->message()
3230 .oldest_local_unreliable_monotonic_timestamps()
3231 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003232 const monotonic_clock::time_point
3233 oldest_remote_reliable_monotonic_timestamps =
3234 monotonic_clock::time_point(chrono::nanoseconds(
3235 log_header->message()
3236 .oldest_remote_reliable_monotonic_timestamps()
3237 ->Get(0)));
3238 const monotonic_clock::time_point
3239 oldest_local_reliable_monotonic_timestamps =
3240 monotonic_clock::time_point(chrono::nanoseconds(
3241 log_header->message()
3242 .oldest_local_reliable_monotonic_timestamps()
3243 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003244 const monotonic_clock::time_point
3245 oldest_logger_remote_unreliable_monotonic_timestamps =
3246 monotonic_clock::time_point(chrono::nanoseconds(
3247 log_header->message()
3248 .oldest_logger_remote_unreliable_monotonic_timestamps()
3249 ->Get(1)));
3250 const monotonic_clock::time_point
3251 oldest_logger_local_unreliable_monotonic_timestamps =
3252 monotonic_clock::time_point(chrono::nanoseconds(
3253 log_header->message()
3254 .oldest_logger_local_unreliable_monotonic_timestamps()
3255 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08003256
Austin Schuh01f3b392022-01-25 20:03:09 -08003257 const Channel *channel =
3258 event_loop_factory_.configuration()->channels()->Get(
3259 msg->message().channel_index());
3260 const Connection *connection = configuration::ConnectionToNode(
3261 channel, configuration::GetNode(
3262 event_loop_factory_.configuration(),
3263 log_header->message().node()->name()->string_view()));
3264
3265 const bool reliable = connection->time_to_live() == 0;
3266
Austin Schuhf5f99f32022-02-07 20:05:37 -08003267 SCOPED_TRACE(file);
3268 SCOPED_TRACE(aos::FlatbufferToJson(
3269 *log_header, {.multi_line = true, .max_vector_size = 100}));
3270
Austin Schuh01f3b392022-01-25 20:03:09 -08003271 if (shared()) {
3272 // Confirm that the oldest timestamps match what we expect. Based on
3273 // what we are doing, we know that the oldest time is the first
3274 // message's time.
3275 //
3276 // This makes the test robust to both the split and combined config
3277 // tests.
3278 switch (log_header->message().parts_index()) {
3279 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08003280 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3281 expected_oldest_remote_monotonic_timestamps);
3282 EXPECT_EQ(oldest_local_monotonic_timestamps,
3283 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003284 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003285 expected_oldest_local_monotonic_timestamps)
3286 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003287 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003288 expected_oldest_timestamp_monotonic_timestamps)
3289 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003290
Austin Schuh01f3b392022-01-25 20:03:09 -08003291 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003292 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3293 expected_oldest_remote_monotonic_timestamps);
3294 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3295 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08003296 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3297 monotonic_clock::max_time);
3298 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3299 monotonic_clock::max_time);
3300 } else {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003301 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3302 monotonic_clock::max_time);
3303 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3304 monotonic_clock::max_time);
3305 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3306 expected_oldest_remote_monotonic_timestamps);
3307 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3308 expected_oldest_local_monotonic_timestamps);
3309 }
3310 break;
3311 case 1:
3312 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3313 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3314 EXPECT_EQ(oldest_local_monotonic_timestamps,
3315 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003316 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3317 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3318 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3319 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003320 if (reliable) {
3321 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3322 expected_oldest_remote_monotonic_timestamps);
3323 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3324 expected_oldest_local_monotonic_timestamps);
3325 EXPECT_EQ(
3326 oldest_remote_unreliable_monotonic_timestamps,
3327 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3328 EXPECT_EQ(
3329 oldest_local_unreliable_monotonic_timestamps,
3330 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3331 } else {
3332 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3333 monotonic_clock::max_time);
3334 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3335 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003336 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3337 expected_oldest_remote_monotonic_timestamps);
3338 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3339 expected_oldest_local_monotonic_timestamps);
3340 }
3341 break;
3342 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003343 EXPECT_EQ(
3344 oldest_remote_monotonic_timestamps,
3345 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3346 EXPECT_EQ(
3347 oldest_local_monotonic_timestamps,
3348 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003349 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003350 expected_oldest_local_monotonic_timestamps)
3351 << file;
Austin Schuhf5f99f32022-02-07 20:05:37 -08003352 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07003353 expected_oldest_timestamp_monotonic_timestamps)
3354 << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003355 if (reliable) {
3356 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3357 expected_oldest_remote_monotonic_timestamps);
3358 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3359 expected_oldest_local_monotonic_timestamps);
3360 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3361 monotonic_clock::max_time);
3362 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3363 monotonic_clock::max_time);
3364 } else {
3365 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3366 monotonic_clock::max_time);
3367 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3368 monotonic_clock::max_time);
3369 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3370 expected_oldest_remote_monotonic_timestamps);
3371 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3372 expected_oldest_local_monotonic_timestamps);
3373 }
3374 break;
3375
3376 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003377 EXPECT_EQ(
3378 oldest_remote_monotonic_timestamps,
3379 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3380 EXPECT_EQ(
3381 oldest_local_monotonic_timestamps,
3382 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3383 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3384 expected_oldest_remote_monotonic_timestamps);
3385 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3386 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003387 EXPECT_EQ(
3388 oldest_logger_remote_unreliable_monotonic_timestamps,
3389 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3390 EXPECT_EQ(
3391 oldest_logger_local_unreliable_monotonic_timestamps,
3392 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003393 break;
3394 default:
3395 FAIL();
3396 break;
3397 }
3398
3399 switch (log_header->message().parts_index()) {
3400 case 0:
3401 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3402 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3403 break;
3404 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003405 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003406 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3407 break;
3408 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003409 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3410 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3411 break;
3412 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003413 if (shared()) {
3414 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3415 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003416 break;
3417 }
3418 [[fallthrough]];
3419 default:
3420 FAIL();
3421 break;
3422 }
3423 } else {
3424 switch (log_header->message().parts_index()) {
3425 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003426 if (reliable) {
3427 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3428 monotonic_clock::max_time);
3429 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3430 monotonic_clock::max_time);
3431 EXPECT_EQ(
3432 oldest_logger_remote_unreliable_monotonic_timestamps,
3433 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3434 << file;
3435 EXPECT_EQ(
3436 oldest_logger_local_unreliable_monotonic_timestamps,
3437 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3438 << file;
3439 } else {
3440 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3441 expected_oldest_remote_monotonic_timestamps);
3442 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3443 expected_oldest_local_monotonic_timestamps);
3444 EXPECT_EQ(
3445 oldest_logger_remote_unreliable_monotonic_timestamps,
3446 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3447 << file;
3448 EXPECT_EQ(
3449 oldest_logger_local_unreliable_monotonic_timestamps,
3450 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3451 << file;
3452 }
3453 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003454 case 1:
3455 if (reliable) {
3456 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3457 monotonic_clock::max_time);
3458 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3459 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003460 EXPECT_EQ(
3461 oldest_logger_remote_unreliable_monotonic_timestamps,
3462 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3463 EXPECT_EQ(
3464 oldest_logger_local_unreliable_monotonic_timestamps,
3465 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003466 } else {
3467 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3468 expected_oldest_remote_monotonic_timestamps);
3469 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3470 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003471 EXPECT_EQ(
3472 oldest_logger_remote_unreliable_monotonic_timestamps,
3473 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3474 EXPECT_EQ(
3475 oldest_logger_local_unreliable_monotonic_timestamps,
3476 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003477 }
3478 break;
3479 default:
3480 FAIL();
3481 break;
3482 }
3483
3484 switch (log_header->message().parts_index()) {
3485 case 0:
3486 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3487 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3488 break;
3489 case 1:
3490 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3491 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3492 break;
3493 default:
3494 FAIL();
3495 break;
3496 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003497 }
3498
3499 continue;
3500 }
3501 EXPECT_EQ(
3502 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3503 monotonic_clock::max_time.time_since_epoch().count());
3504 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3505 monotonic_clock::max_time.time_since_epoch().count());
3506 EXPECT_EQ(log_header->message()
3507 .oldest_remote_unreliable_monotonic_timestamps()
3508 ->Get(0),
3509 monotonic_clock::max_time.time_since_epoch().count());
3510 EXPECT_EQ(log_header->message()
3511 .oldest_local_unreliable_monotonic_timestamps()
3512 ->Get(0),
3513 monotonic_clock::max_time.time_since_epoch().count());
3514
3515 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3516 monotonic_clock::time_point(chrono::nanoseconds(
3517 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3518 1)));
3519 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3520 monotonic_clock::time_point(chrono::nanoseconds(
3521 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3522 const monotonic_clock::time_point
3523 oldest_remote_unreliable_monotonic_timestamps =
3524 monotonic_clock::time_point(chrono::nanoseconds(
3525 log_header->message()
3526 .oldest_remote_unreliable_monotonic_timestamps()
3527 ->Get(1)));
3528 const monotonic_clock::time_point
3529 oldest_local_unreliable_monotonic_timestamps =
3530 monotonic_clock::time_point(chrono::nanoseconds(
3531 log_header->message()
3532 .oldest_local_unreliable_monotonic_timestamps()
3533 ->Get(1)));
3534 switch (log_header->message().parts_index()) {
3535 case 0:
3536 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3537 monotonic_clock::max_time);
3538 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3539 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3540 monotonic_clock::max_time);
3541 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3542 monotonic_clock::max_time);
3543 break;
3544 default:
3545 FAIL();
3546 break;
3547 }
3548 }
3549
Austin Schuh01f3b392022-01-25 20:03:09 -08003550 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003551 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003552 } else {
3553 EXPECT_EQ(timestamp_file_count, 4u);
3554 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003555
Austin Schuhe2373e22022-01-21 12:25:17 -08003556 // Confirm that we can actually sort the resulting log and read it.
3557 {
3558 LogReader reader(SortParts(filenames));
3559
3560 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3561 log_reader_factory.set_send_delay(chrono::microseconds(0));
3562
3563 // This sends out the fetched messages and advances time to the start of
3564 // the log file.
3565 reader.Register(&log_reader_factory);
3566
3567 log_reader_factory.Run();
3568
3569 reader.Deregister();
3570 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003571}
3572
Austin Schuhc9049732020-12-21 22:27:15 -08003573// Tests that we properly handle one direction of message_bridge being
3574// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003575TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003576 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003577 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003578 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003579
3580 time_converter_.AddMonotonic(
3581 {chrono::milliseconds(10000),
3582 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003583 {
3584 LoggerState pi1_logger = MakeLogger(pi1_);
3585
3586 event_loop_factory_.RunFor(chrono::milliseconds(95));
3587
3588 StartLogger(&pi1_logger);
3589
3590 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3591 }
3592
3593 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3594 // to confirm the right thing happened.
3595 ConfirmReadable(pi1_single_direction_logfiles_);
3596}
3597
3598// Tests that we properly handle one direction of message_bridge being
3599// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003600TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003601 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003602 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003603 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003604
3605 time_converter_.AddMonotonic(
3606 {chrono::milliseconds(10000),
3607 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3608 {
3609 LoggerState pi1_logger = MakeLogger(pi1_);
3610
3611 event_loop_factory_.RunFor(chrono::milliseconds(95));
3612
3613 StartLogger(&pi1_logger);
3614
3615 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3616 }
3617
3618 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3619 // to confirm the right thing happened.
3620 ConfirmReadable(pi1_single_direction_logfiles_);
3621}
3622
Austin Schuhe9f00232021-09-16 18:04:23 -07003623// Tests that we explode if someone passes in a part file twice with a better
3624// error than an out of order error.
3625TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3626 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003627 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003628 {
3629 LoggerState pi1_logger = MakeLogger(pi1_);
3630
3631 event_loop_factory_.RunFor(chrono::milliseconds(95));
3632
3633 StartLogger(&pi1_logger);
3634
3635 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3636 }
3637
3638 std::vector<std::string> duplicates;
3639 for (const std::string &f : pi1_single_direction_logfiles_) {
3640 duplicates.emplace_back(f);
3641 duplicates.emplace_back(f);
3642 }
3643 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3644}
3645
Austin Schuh87dd3832021-01-01 23:07:31 -08003646// Tests that we properly handle a dead node. Do this by just disconnecting it
3647// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003648TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003649 pi1_->Disconnect(pi2_->node());
3650 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003651 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003652 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003653 {
3654 LoggerState pi1_logger = MakeLogger(pi1_);
3655
3656 event_loop_factory_.RunFor(chrono::milliseconds(95));
3657
3658 StartLogger(&pi1_logger);
3659
3660 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3661 }
3662
3663 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3664 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003665 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003666}
3667
Austin Schuhcdd90272021-03-15 12:46:16 -07003668constexpr std::string_view kCombinedConfigSha1(
Brian Silvermandae15a12022-07-23 12:55:20 -07003669 "bcc66bc13a90a4a268649744e244129c5d024f5abd67587dcfbd7158d8abfc44");
Austin Schuhcdd90272021-03-15 12:46:16 -07003670constexpr std::string_view kSplitConfigSha1(
Brian Silvermandae15a12022-07-23 12:55:20 -07003671 "d97e998164a6f1bf078aad77ef127329728ac9198a13a5ab8d5f30d84a932662");
Austin Schuhcdd90272021-03-15 12:46:16 -07003672
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003673INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003674 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003675 ::testing::Combine(::testing::Values(
3676 ConfigParams{
3677 "multinode_pingpong_combined_config.json", true,
3678 kCombinedConfigSha1},
3679 ConfigParams{"multinode_pingpong_split_config.json",
3680 false, kSplitConfigSha1}),
3681 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003682
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003683INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003684 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003685 ::testing::Combine(::testing::Values(
3686 ConfigParams{
3687 "multinode_pingpong_combined_config.json", true,
3688 kCombinedConfigSha1},
3689 ConfigParams{"multinode_pingpong_split_config.json",
3690 false, kSplitConfigSha1}),
3691 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003692
Austin Schuh5b728b72021-06-16 14:57:15 -07003693// Tests that we can relog with a different config. This makes most sense when
3694// you are trying to edit a log and want to use channel renaming + the original
3695// config in the new log.
3696TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3697 time_converter_.StartEqual();
3698 {
3699 LoggerState pi1_logger = MakeLogger(pi1_);
3700 LoggerState pi2_logger = MakeLogger(pi2_);
3701
3702 event_loop_factory_.RunFor(chrono::milliseconds(95));
3703
3704 StartLogger(&pi1_logger);
3705 StartLogger(&pi2_logger);
3706
3707 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3708 }
3709
3710 LogReader reader(SortParts(logfiles_));
3711 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3712
3713 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3714 log_reader_factory.set_send_delay(chrono::microseconds(0));
3715
3716 // This sends out the fetched messages and advances time to the start of the
3717 // log file.
3718 reader.Register(&log_reader_factory);
3719
3720 const Node *pi1 =
3721 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3722 const Node *pi2 =
3723 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3724
3725 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3726 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3727 LOG(INFO) << "now pi1 "
3728 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3729 LOG(INFO) << "now pi2 "
3730 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3731
3732 EXPECT_THAT(reader.LoggedNodes(),
3733 ::testing::ElementsAre(
3734 configuration::GetNode(reader.logged_configuration(), pi1),
3735 configuration::GetNode(reader.logged_configuration(), pi2)));
3736
3737 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3738
3739 // And confirm we can re-create a log again, while checking the contents.
3740 std::vector<std::string> log_files;
3741 {
3742 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003743 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003744 &log_reader_factory, reader.logged_configuration());
3745 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003746 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003747 &log_reader_factory, reader.logged_configuration());
3748
Austin Schuh3e20c692021-11-16 20:43:16 -08003749 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3750 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003751
3752 log_reader_factory.Run();
3753
3754 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3755 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3756 }
3757 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3758 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3759 }
3760 }
3761
3762 reader.Deregister();
3763
3764 // And verify that we can run the LogReader over the relogged files without
3765 // hitting any fatal errors.
3766 {
3767 LogReader relogged_reader(SortParts(log_files));
3768 relogged_reader.Register();
3769
3770 relogged_reader.event_loop_factory()->Run();
3771 }
3772}
Austin Schuha04efed2021-01-24 18:04:20 -08003773
Austin Schuh3e20c692021-11-16 20:43:16 -08003774// Tests that we properly replay a log where the start time for a node is before
3775// any data on the node. This can happen if the logger starts before data is
3776// published. While the scenario below is a bit convoluted, we have seen logs
3777// like this generated out in the wild.
3778TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3779 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3780 aos::configuration::ReadConfig(ArtifactPath(
3781 "aos/events/logging/multinode_pingpong_split3_config.json"));
3782 message_bridge::TestingTimeConverter time_converter(
3783 configuration::NodesCount(&config.message()));
3784 SimulatedEventLoopFactory event_loop_factory(&config.message());
3785 event_loop_factory.SetTimeConverter(&time_converter);
3786 NodeEventLoopFactory *const pi1 =
3787 event_loop_factory.GetNodeEventLoopFactory("pi1");
3788 const size_t pi1_index = configuration::GetNodeIndex(
3789 event_loop_factory.configuration(), pi1->node());
3790 NodeEventLoopFactory *const pi2 =
3791 event_loop_factory.GetNodeEventLoopFactory("pi2");
3792 const size_t pi2_index = configuration::GetNodeIndex(
3793 event_loop_factory.configuration(), pi2->node());
3794 NodeEventLoopFactory *const pi3 =
3795 event_loop_factory.GetNodeEventLoopFactory("pi3");
3796 const size_t pi3_index = configuration::GetNodeIndex(
3797 event_loop_factory.configuration(), pi3->node());
3798
3799 const std::string kLogfile1_1 =
3800 aos::testing::TestTmpDir() + "/multi_logfile1/";
3801 const std::string kLogfile2_1 =
3802 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3803 const std::string kLogfile2_2 =
3804 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3805 const std::string kLogfile3_1 =
3806 aos::testing::TestTmpDir() + "/multi_logfile3/";
3807 util::UnlinkRecursive(kLogfile1_1);
3808 util::UnlinkRecursive(kLogfile2_1);
3809 util::UnlinkRecursive(kLogfile2_2);
3810 util::UnlinkRecursive(kLogfile3_1);
3811 const UUID pi1_boot0 = UUID::Random();
3812 const UUID pi2_boot0 = UUID::Random();
3813 const UUID pi2_boot1 = UUID::Random();
3814 const UUID pi3_boot0 = UUID::Random();
3815 {
3816 CHECK_EQ(pi1_index, 0u);
3817 CHECK_EQ(pi2_index, 1u);
3818 CHECK_EQ(pi3_index, 2u);
3819
3820 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3821 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3822 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3823 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3824
3825 time_converter.AddNextTimestamp(
3826 distributed_clock::epoch(),
3827 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3828 BootTimestamp::epoch()});
3829 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3830 time_converter.AddNextTimestamp(
3831 distributed_clock::epoch() + reboot_time,
3832 {BootTimestamp::epoch() + reboot_time,
3833 BootTimestamp{
3834 .boot = 1,
3835 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3836 BootTimestamp::epoch() + reboot_time});
3837 }
3838
3839 // Make everything perfectly quiet.
3840 event_loop_factory.SkipTimingReport();
3841 event_loop_factory.DisableStatistics();
3842
3843 std::vector<std::string> filenames;
3844 {
3845 LoggerState pi1_logger = LoggerState::MakeLogger(
3846 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3847 LoggerState pi3_logger = LoggerState::MakeLogger(
3848 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3849 {
3850 // And now start the logger.
3851 LoggerState pi2_logger = LoggerState::MakeLogger(
3852 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3853
3854 event_loop_factory.RunFor(chrono::milliseconds(1000));
3855
3856 pi1_logger.StartLogger(kLogfile1_1);
3857 pi3_logger.StartLogger(kLogfile3_1);
3858 pi2_logger.StartLogger(kLogfile2_1);
3859
3860 event_loop_factory.RunFor(chrono::milliseconds(10000));
3861
3862 // Now that we've got a start time in the past, turn on data.
3863 event_loop_factory.EnableStatistics();
3864 std::unique_ptr<aos::EventLoop> ping_event_loop =
3865 pi1->MakeEventLoop("ping");
3866 Ping ping(ping_event_loop.get());
3867
3868 pi2->AlwaysStart<Pong>("pong");
3869
3870 event_loop_factory.RunFor(chrono::milliseconds(3000));
3871
3872 pi2_logger.AppendAllFilenames(&filenames);
3873
3874 // Stop logging on pi2 before rebooting and completely shut off all
3875 // messages on pi2.
3876 pi2->DisableStatistics();
3877 pi1->Disconnect(pi2->node());
3878 pi2->Disconnect(pi1->node());
3879 }
3880 event_loop_factory.RunFor(chrono::milliseconds(7000));
3881 // pi2 now reboots.
3882 {
3883 event_loop_factory.RunFor(chrono::milliseconds(1000));
3884
3885 // Start logging again on pi2 after it is up.
3886 LoggerState pi2_logger = LoggerState::MakeLogger(
3887 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3888 pi2_logger.StartLogger(kLogfile2_2);
3889
3890 event_loop_factory.RunFor(chrono::milliseconds(10000));
3891 // And, now that we have a start time in the log, turn data back on.
3892 pi2->EnableStatistics();
3893 pi1->Connect(pi2->node());
3894 pi2->Connect(pi1->node());
3895
3896 pi2->AlwaysStart<Pong>("pong");
3897 std::unique_ptr<aos::EventLoop> ping_event_loop =
3898 pi1->MakeEventLoop("ping");
3899 Ping ping(ping_event_loop.get());
3900
3901 event_loop_factory.RunFor(chrono::milliseconds(3000));
3902
3903 pi2_logger.AppendAllFilenames(&filenames);
3904 }
3905
3906 pi1_logger.AppendAllFilenames(&filenames);
3907 pi3_logger.AppendAllFilenames(&filenames);
3908 }
3909
3910 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3911 // to confirm the right thing happened.
3912 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08003913 auto result = ConfirmReadable(filenames);
3914 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch() +
3915 chrono::seconds(1)));
3916 EXPECT_THAT(result[0].second,
3917 ::testing::ElementsAre(realtime_clock::epoch() +
3918 chrono::microseconds(34990350)));
3919
3920 EXPECT_THAT(result[1].first,
3921 ::testing::ElementsAre(
3922 realtime_clock::epoch() + chrono::seconds(1),
3923 realtime_clock::epoch() + chrono::microseconds(3323000)));
3924 EXPECT_THAT(result[1].second,
3925 ::testing::ElementsAre(
3926 realtime_clock::epoch() + chrono::microseconds(13990200),
3927 realtime_clock::epoch() + chrono::microseconds(16313200)));
3928
3929 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch() +
3930 chrono::seconds(1)));
3931 EXPECT_THAT(result[2].second,
3932 ::testing::ElementsAre(realtime_clock::epoch() +
3933 chrono::microseconds(34900150)));
Austin Schuh3e20c692021-11-16 20:43:16 -08003934}
3935
Austin Schuh5dd22842021-11-17 16:09:39 -08003936// Tests that local data before remote data after reboot is properly replayed.
3937// We only trigger a reboot in the timestamp interpolation function when solving
3938// the timestamp problem when we actually have a point in the function. This
3939// originally only happened when a point passes the noncausal filter. At the
3940// start of time for the second boot, if we aren't careful, we will have
3941// messages which need to be published at times before the boot. This happens
3942// when a local message is in the log before a forwarded message, so there is no
3943// point in the interpolation function. This delays the reboot. So, we need to
3944// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08003945TEST(MultinodeRebootLoggerTest,
3946 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08003947 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3948 aos::configuration::ReadConfig(ArtifactPath(
3949 "aos/events/logging/multinode_pingpong_split3_config.json"));
3950 message_bridge::TestingTimeConverter time_converter(
3951 configuration::NodesCount(&config.message()));
3952 SimulatedEventLoopFactory event_loop_factory(&config.message());
3953 event_loop_factory.SetTimeConverter(&time_converter);
3954 NodeEventLoopFactory *const pi1 =
3955 event_loop_factory.GetNodeEventLoopFactory("pi1");
3956 const size_t pi1_index = configuration::GetNodeIndex(
3957 event_loop_factory.configuration(), pi1->node());
3958 NodeEventLoopFactory *const pi2 =
3959 event_loop_factory.GetNodeEventLoopFactory("pi2");
3960 const size_t pi2_index = configuration::GetNodeIndex(
3961 event_loop_factory.configuration(), pi2->node());
3962 NodeEventLoopFactory *const pi3 =
3963 event_loop_factory.GetNodeEventLoopFactory("pi3");
3964 const size_t pi3_index = configuration::GetNodeIndex(
3965 event_loop_factory.configuration(), pi3->node());
3966
3967 const std::string kLogfile1_1 =
3968 aos::testing::TestTmpDir() + "/multi_logfile1/";
3969 const std::string kLogfile2_1 =
3970 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3971 const std::string kLogfile2_2 =
3972 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3973 const std::string kLogfile3_1 =
3974 aos::testing::TestTmpDir() + "/multi_logfile3/";
3975 util::UnlinkRecursive(kLogfile1_1);
3976 util::UnlinkRecursive(kLogfile2_1);
3977 util::UnlinkRecursive(kLogfile2_2);
3978 util::UnlinkRecursive(kLogfile3_1);
3979 const UUID pi1_boot0 = UUID::Random();
3980 const UUID pi2_boot0 = UUID::Random();
3981 const UUID pi2_boot1 = UUID::Random();
3982 const UUID pi3_boot0 = UUID::Random();
3983 {
3984 CHECK_EQ(pi1_index, 0u);
3985 CHECK_EQ(pi2_index, 1u);
3986 CHECK_EQ(pi3_index, 2u);
3987
3988 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3989 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3990 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3991 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3992
3993 time_converter.AddNextTimestamp(
3994 distributed_clock::epoch(),
3995 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3996 BootTimestamp::epoch()});
3997 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3998 time_converter.AddNextTimestamp(
3999 distributed_clock::epoch() + reboot_time,
4000 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08004001 BootTimestamp{.boot = 1,
4002 .time = monotonic_clock::epoch() + reboot_time +
4003 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08004004 BootTimestamp::epoch() + reboot_time});
4005 }
4006
4007 std::vector<std::string> filenames;
4008 {
4009 LoggerState pi1_logger = LoggerState::MakeLogger(
4010 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4011 LoggerState pi3_logger = LoggerState::MakeLogger(
4012 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4013 {
4014 // And now start the logger.
4015 LoggerState pi2_logger = LoggerState::MakeLogger(
4016 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4017
4018 pi1_logger.StartLogger(kLogfile1_1);
4019 pi3_logger.StartLogger(kLogfile3_1);
4020 pi2_logger.StartLogger(kLogfile2_1);
4021
4022 event_loop_factory.RunFor(chrono::milliseconds(1005));
4023
4024 // Now that we've got a start time in the past, turn on data.
4025 std::unique_ptr<aos::EventLoop> ping_event_loop =
4026 pi1->MakeEventLoop("ping");
4027 Ping ping(ping_event_loop.get());
4028
4029 pi2->AlwaysStart<Pong>("pong");
4030
4031 event_loop_factory.RunFor(chrono::milliseconds(3000));
4032
4033 pi2_logger.AppendAllFilenames(&filenames);
4034
4035 // Disable any remote messages on pi2.
4036 pi1->Disconnect(pi2->node());
4037 pi2->Disconnect(pi1->node());
4038 }
4039 event_loop_factory.RunFor(chrono::milliseconds(995));
4040 // pi2 now reboots at 5 seconds.
4041 {
4042 event_loop_factory.RunFor(chrono::milliseconds(1000));
4043
4044 // Make local stuff happen before we start logging and connect the remote.
4045 pi2->AlwaysStart<Pong>("pong");
4046 std::unique_ptr<aos::EventLoop> ping_event_loop =
4047 pi1->MakeEventLoop("ping");
4048 Ping ping(ping_event_loop.get());
4049 event_loop_factory.RunFor(chrono::milliseconds(1005));
4050
4051 // Start logging again on pi2 after it is up.
4052 LoggerState pi2_logger = LoggerState::MakeLogger(
4053 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4054 pi2_logger.StartLogger(kLogfile2_2);
4055
4056 // And allow remote messages now that we have some local ones.
4057 pi1->Connect(pi2->node());
4058 pi2->Connect(pi1->node());
4059
4060 event_loop_factory.RunFor(chrono::milliseconds(1000));
4061
4062 event_loop_factory.RunFor(chrono::milliseconds(3000));
4063
4064 pi2_logger.AppendAllFilenames(&filenames);
4065 }
4066
4067 pi1_logger.AppendAllFilenames(&filenames);
4068 pi3_logger.AppendAllFilenames(&filenames);
4069 }
4070
4071 // Confirm that we can parse the result. LogReader has enough internal CHECKs
4072 // to confirm the right thing happened.
4073 const std::vector<LogFile> sorted_parts = SortParts(filenames);
Austin Schuhe33c08d2022-02-03 18:15:21 -08004074 auto result = ConfirmReadable(filenames);
4075
4076 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4077 EXPECT_THAT(result[0].second,
4078 ::testing::ElementsAre(realtime_clock::epoch() +
4079 chrono::microseconds(11000350)));
4080
4081 EXPECT_THAT(result[1].first,
4082 ::testing::ElementsAre(
4083 realtime_clock::epoch(),
4084 realtime_clock::epoch() + chrono::microseconds(107005000)));
4085 EXPECT_THAT(result[1].second,
4086 ::testing::ElementsAre(
4087 realtime_clock::epoch() + chrono::microseconds(4000150),
4088 realtime_clock::epoch() + chrono::microseconds(111000200)));
4089
4090 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4091 EXPECT_THAT(result[2].second,
4092 ::testing::ElementsAre(realtime_clock::epoch() +
4093 chrono::microseconds(11000150)));
4094
4095 auto start_stop_result = ConfirmReadable(
4096 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4097 realtime_clock::epoch() + chrono::milliseconds(3000));
4098
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004099 EXPECT_THAT(
4100 start_stop_result[0].first,
4101 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4102 EXPECT_THAT(
4103 start_stop_result[0].second,
4104 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4105 EXPECT_THAT(
4106 start_stop_result[1].first,
4107 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4108 EXPECT_THAT(
4109 start_stop_result[1].second,
4110 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
4111 EXPECT_THAT(
4112 start_stop_result[2].first,
4113 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4114 EXPECT_THAT(
4115 start_stop_result[2].second,
4116 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(3)));
Austin Schuh5dd22842021-11-17 16:09:39 -08004117}
4118
Austin Schuhe33c08d2022-02-03 18:15:21 -08004119// Tests that setting the start and stop flags across a reboot works as
4120// expected.
4121TEST(MultinodeRebootLoggerTest, RebootStartStopTimes) {
4122 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4123 aos::configuration::ReadConfig(ArtifactPath(
4124 "aos/events/logging/multinode_pingpong_split3_config.json"));
4125 message_bridge::TestingTimeConverter time_converter(
4126 configuration::NodesCount(&config.message()));
4127 SimulatedEventLoopFactory event_loop_factory(&config.message());
4128 event_loop_factory.SetTimeConverter(&time_converter);
4129 NodeEventLoopFactory *const pi1 =
4130 event_loop_factory.GetNodeEventLoopFactory("pi1");
4131 const size_t pi1_index = configuration::GetNodeIndex(
4132 event_loop_factory.configuration(), pi1->node());
4133 NodeEventLoopFactory *const pi2 =
4134 event_loop_factory.GetNodeEventLoopFactory("pi2");
4135 const size_t pi2_index = configuration::GetNodeIndex(
4136 event_loop_factory.configuration(), pi2->node());
4137 NodeEventLoopFactory *const pi3 =
4138 event_loop_factory.GetNodeEventLoopFactory("pi3");
4139 const size_t pi3_index = configuration::GetNodeIndex(
4140 event_loop_factory.configuration(), pi3->node());
4141
4142 const std::string kLogfile1_1 =
4143 aos::testing::TestTmpDir() + "/multi_logfile1/";
4144 const std::string kLogfile2_1 =
4145 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4146 const std::string kLogfile2_2 =
4147 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
4148 const std::string kLogfile3_1 =
4149 aos::testing::TestTmpDir() + "/multi_logfile3/";
4150 util::UnlinkRecursive(kLogfile1_1);
4151 util::UnlinkRecursive(kLogfile2_1);
4152 util::UnlinkRecursive(kLogfile2_2);
4153 util::UnlinkRecursive(kLogfile3_1);
4154 {
4155 CHECK_EQ(pi1_index, 0u);
4156 CHECK_EQ(pi2_index, 1u);
4157 CHECK_EQ(pi3_index, 2u);
4158
4159 time_converter.AddNextTimestamp(
4160 distributed_clock::epoch(),
4161 {BootTimestamp::epoch(), BootTimestamp::epoch(),
4162 BootTimestamp::epoch()});
4163 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4164 time_converter.AddNextTimestamp(
4165 distributed_clock::epoch() + reboot_time,
4166 {BootTimestamp::epoch() + reboot_time,
4167 BootTimestamp{.boot = 1,
4168 .time = monotonic_clock::epoch() + reboot_time},
4169 BootTimestamp::epoch() + reboot_time});
4170 }
4171
4172 std::vector<std::string> filenames;
4173 {
4174 LoggerState pi1_logger = LoggerState::MakeLogger(
4175 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4176 LoggerState pi3_logger = LoggerState::MakeLogger(
4177 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4178 {
4179 // And now start the logger.
4180 LoggerState pi2_logger = LoggerState::MakeLogger(
4181 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4182
4183 pi1_logger.StartLogger(kLogfile1_1);
4184 pi3_logger.StartLogger(kLogfile3_1);
4185 pi2_logger.StartLogger(kLogfile2_1);
4186
4187 event_loop_factory.RunFor(chrono::milliseconds(1005));
4188
4189 // Now that we've got a start time in the past, turn on data.
4190 std::unique_ptr<aos::EventLoop> ping_event_loop =
4191 pi1->MakeEventLoop("ping");
4192 Ping ping(ping_event_loop.get());
4193
4194 pi2->AlwaysStart<Pong>("pong");
4195
4196 event_loop_factory.RunFor(chrono::milliseconds(3000));
4197
4198 pi2_logger.AppendAllFilenames(&filenames);
4199 }
4200 event_loop_factory.RunFor(chrono::milliseconds(995));
4201 // pi2 now reboots at 5 seconds.
4202 {
4203 event_loop_factory.RunFor(chrono::milliseconds(1000));
4204
4205 // Make local stuff happen before we start logging and connect the remote.
4206 pi2->AlwaysStart<Pong>("pong");
4207 std::unique_ptr<aos::EventLoop> ping_event_loop =
4208 pi1->MakeEventLoop("ping");
4209 Ping ping(ping_event_loop.get());
4210 event_loop_factory.RunFor(chrono::milliseconds(5));
4211
4212 // Start logging again on pi2 after it is up.
4213 LoggerState pi2_logger = LoggerState::MakeLogger(
4214 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4215 pi2_logger.StartLogger(kLogfile2_2);
4216
4217 event_loop_factory.RunFor(chrono::milliseconds(5000));
4218
4219 pi2_logger.AppendAllFilenames(&filenames);
4220 }
4221
4222 pi1_logger.AppendAllFilenames(&filenames);
4223 pi3_logger.AppendAllFilenames(&filenames);
4224 }
4225
4226 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4227 auto result = ConfirmReadable(filenames);
4228
4229 EXPECT_THAT(result[0].first, ::testing::ElementsAre(realtime_clock::epoch()));
4230 EXPECT_THAT(result[0].second,
4231 ::testing::ElementsAre(realtime_clock::epoch() +
4232 chrono::microseconds(11000350)));
4233
4234 EXPECT_THAT(result[1].first,
4235 ::testing::ElementsAre(
4236 realtime_clock::epoch(),
4237 realtime_clock::epoch() + chrono::microseconds(6005000)));
4238 EXPECT_THAT(result[1].second,
4239 ::testing::ElementsAre(
4240 realtime_clock::epoch() + chrono::microseconds(4900150),
4241 realtime_clock::epoch() + chrono::microseconds(11000200)));
4242
4243 EXPECT_THAT(result[2].first, ::testing::ElementsAre(realtime_clock::epoch()));
4244 EXPECT_THAT(result[2].second,
4245 ::testing::ElementsAre(realtime_clock::epoch() +
4246 chrono::microseconds(11000150)));
4247
4248 // Confirm we observed the correct start and stop times. We should see the
4249 // reboot here.
4250 auto start_stop_result = ConfirmReadable(
4251 filenames, realtime_clock::epoch() + chrono::milliseconds(2000),
4252 realtime_clock::epoch() + chrono::milliseconds(8000));
4253
4254 EXPECT_THAT(
4255 start_stop_result[0].first,
4256 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4257 EXPECT_THAT(
4258 start_stop_result[0].second,
4259 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4260 EXPECT_THAT(start_stop_result[1].first,
4261 ::testing::ElementsAre(
4262 realtime_clock::epoch() + chrono::seconds(2),
4263 realtime_clock::epoch() + chrono::microseconds(6005000)));
4264 EXPECT_THAT(start_stop_result[1].second,
4265 ::testing::ElementsAre(
4266 realtime_clock::epoch() + chrono::microseconds(4900150),
4267 realtime_clock::epoch() + chrono::seconds(8)));
4268 EXPECT_THAT(
4269 start_stop_result[2].first,
4270 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(2)));
4271 EXPECT_THAT(
4272 start_stop_result[2].second,
4273 ::testing::ElementsAre(realtime_clock::epoch() + chrono::seconds(8)));
4274}
Austin Schuh5dd22842021-11-17 16:09:39 -08004275
Austin Schuh5c770fa2022-03-11 06:57:22 -08004276// Tests that we properly handle one direction being down.
4277TEST(MissingDirectionTest, OneDirection) {
4278 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4279 aos::configuration::ReadConfig(ArtifactPath(
4280 "aos/events/logging/multinode_pingpong_split4_config.json"));
4281 message_bridge::TestingTimeConverter time_converter(
4282 configuration::NodesCount(&config.message()));
4283 SimulatedEventLoopFactory event_loop_factory(&config.message());
4284 event_loop_factory.SetTimeConverter(&time_converter);
4285
4286 NodeEventLoopFactory *const pi1 =
4287 event_loop_factory.GetNodeEventLoopFactory("pi1");
4288 const size_t pi1_index = configuration::GetNodeIndex(
4289 event_loop_factory.configuration(), pi1->node());
4290 NodeEventLoopFactory *const pi2 =
4291 event_loop_factory.GetNodeEventLoopFactory("pi2");
4292 const size_t pi2_index = configuration::GetNodeIndex(
4293 event_loop_factory.configuration(), pi2->node());
4294 std::vector<std::string> filenames;
4295
4296 {
4297 CHECK_EQ(pi1_index, 0u);
4298 CHECK_EQ(pi2_index, 1u);
4299
4300 time_converter.AddNextTimestamp(
4301 distributed_clock::epoch(),
4302 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4303
4304 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4305 time_converter.AddNextTimestamp(
4306 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004307 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuh5c770fa2022-03-11 06:57:22 -08004308 BootTimestamp::epoch() + reboot_time});
4309 }
4310
4311 const std::string kLogfile2_1 =
4312 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4313 const std::string kLogfile1_1 =
4314 aos::testing::TestTmpDir() + "/multi_logfile1.1/";
4315 util::UnlinkRecursive(kLogfile2_1);
4316 util::UnlinkRecursive(kLogfile1_1);
4317
4318 pi2->Disconnect(pi1->node());
4319
4320 pi1->AlwaysStart<Ping>("ping");
4321 pi2->AlwaysStart<Pong>("pong");
4322
4323 {
4324 LoggerState pi2_logger = LoggerState::MakeLogger(
4325 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4326
4327 event_loop_factory.RunFor(chrono::milliseconds(95));
4328
4329 pi2_logger.StartLogger(kLogfile2_1);
4330
4331 event_loop_factory.RunFor(chrono::milliseconds(6000));
4332
4333 pi2->Connect(pi1->node());
4334
4335 LoggerState pi1_logger = LoggerState::MakeLogger(
4336 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4337 pi1_logger.StartLogger(kLogfile1_1);
4338
4339 event_loop_factory.RunFor(chrono::milliseconds(5000));
4340 pi1_logger.AppendAllFilenames(&filenames);
4341 pi2_logger.AppendAllFilenames(&filenames);
4342 }
4343
4344 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4345 ConfirmReadable(filenames);
4346}
4347
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004348// Tests that we properly handle only one direction ever existing after a
4349// reboot.
4350TEST(MissingDirectionTest, OneDirectionAfterReboot) {
4351 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4352 aos::configuration::ReadConfig(ArtifactPath(
4353 "aos/events/logging/multinode_pingpong_split4_config.json"));
4354 message_bridge::TestingTimeConverter time_converter(
4355 configuration::NodesCount(&config.message()));
4356 SimulatedEventLoopFactory event_loop_factory(&config.message());
4357 event_loop_factory.SetTimeConverter(&time_converter);
4358
4359 NodeEventLoopFactory *const pi1 =
4360 event_loop_factory.GetNodeEventLoopFactory("pi1");
4361 const size_t pi1_index = configuration::GetNodeIndex(
4362 event_loop_factory.configuration(), pi1->node());
4363 NodeEventLoopFactory *const pi2 =
4364 event_loop_factory.GetNodeEventLoopFactory("pi2");
4365 const size_t pi2_index = configuration::GetNodeIndex(
4366 event_loop_factory.configuration(), pi2->node());
4367 std::vector<std::string> filenames;
4368
4369 {
4370 CHECK_EQ(pi1_index, 0u);
4371 CHECK_EQ(pi2_index, 1u);
4372
4373 time_converter.AddNextTimestamp(
4374 distributed_clock::epoch(),
4375 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4376
4377 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4378 time_converter.AddNextTimestamp(
4379 distributed_clock::epoch() + reboot_time,
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004380 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004381 BootTimestamp::epoch() + reboot_time});
4382 }
4383
4384 const std::string kLogfile2_1 =
4385 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4386 util::UnlinkRecursive(kLogfile2_1);
4387
Austin Schuh4b8b45b2022-04-13 17:05:44 -07004388 pi1->AlwaysStart<Ping>("ping");
4389
4390 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4391 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4392 // second boot.
4393 {
4394 LoggerState pi2_logger = LoggerState::MakeLogger(
4395 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4396
4397 event_loop_factory.RunFor(chrono::milliseconds(95));
4398
4399 pi2_logger.StartLogger(kLogfile2_1);
4400
4401 event_loop_factory.RunFor(chrono::milliseconds(4000));
4402
4403 pi2->Disconnect(pi1->node());
4404
4405 event_loop_factory.RunFor(chrono::milliseconds(1000));
4406 pi1->AlwaysStart<Ping>("ping");
4407
4408 event_loop_factory.RunFor(chrono::milliseconds(5000));
4409 pi2_logger.AppendAllFilenames(&filenames);
4410 }
4411
4412 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4413 ConfirmReadable(filenames);
4414}
4415
4416// Tests that we properly handle only one direction ever existing after a reboot
4417// with only reliable data.
4418TEST(MissingDirectionTest, OneDirectionAfterRebootReliable) {
4419 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
4420 aos::configuration::ReadConfig(ArtifactPath(
4421 "aos/events/logging/multinode_pingpong_split4_reliable_config.json"));
4422 message_bridge::TestingTimeConverter time_converter(
4423 configuration::NodesCount(&config.message()));
4424 SimulatedEventLoopFactory event_loop_factory(&config.message());
4425 event_loop_factory.SetTimeConverter(&time_converter);
4426
4427 NodeEventLoopFactory *const pi1 =
4428 event_loop_factory.GetNodeEventLoopFactory("pi1");
4429 const size_t pi1_index = configuration::GetNodeIndex(
4430 event_loop_factory.configuration(), pi1->node());
4431 NodeEventLoopFactory *const pi2 =
4432 event_loop_factory.GetNodeEventLoopFactory("pi2");
4433 const size_t pi2_index = configuration::GetNodeIndex(
4434 event_loop_factory.configuration(), pi2->node());
4435 std::vector<std::string> filenames;
4436
4437 {
4438 CHECK_EQ(pi1_index, 0u);
4439 CHECK_EQ(pi2_index, 1u);
4440
4441 time_converter.AddNextTimestamp(
4442 distributed_clock::epoch(),
4443 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4444
4445 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
4446 time_converter.AddNextTimestamp(
4447 distributed_clock::epoch() + reboot_time,
4448 {BootTimestamp{.boot = 1, .time = monotonic_clock::epoch()},
4449 BootTimestamp::epoch() + reboot_time});
4450 }
4451
4452 const std::string kLogfile2_1 =
4453 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4454 util::UnlinkRecursive(kLogfile2_1);
Austin Schuhc1ee1b62022-03-22 17:09:52 -07004455
4456 pi1->AlwaysStart<Ping>("ping");
4457
4458 // Pi1 sends to pi2. Reboot pi1, but don't let pi2 connect to pi1. This
4459 // makes it such that we will only get timestamps from pi1 -> pi2 on the
4460 // second boot.
4461 {
4462 LoggerState pi2_logger = LoggerState::MakeLogger(
4463 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
4464
4465 event_loop_factory.RunFor(chrono::milliseconds(95));
4466
4467 pi2_logger.StartLogger(kLogfile2_1);
4468
4469 event_loop_factory.RunFor(chrono::milliseconds(4000));
4470
4471 pi2->Disconnect(pi1->node());
4472
4473 event_loop_factory.RunFor(chrono::milliseconds(1000));
4474 pi1->AlwaysStart<Ping>("ping");
4475
4476 event_loop_factory.RunFor(chrono::milliseconds(5000));
4477 pi2_logger.AppendAllFilenames(&filenames);
4478 }
4479
4480 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4481 ConfirmReadable(filenames);
4482}
4483
Austin Schuhefba96d2022-06-24 13:22:18 -07004484// Tests that we properly handle what used to be a time violation in one
4485// direction. This can occur when one direction goes down after sending some
4486// data, but the other keeps working. The down direction ends up resolving to a
4487// straight line in the noncausal filter, where the direction which is still up
4488// can cross that line. Really, time progressed along just fine but we assumed
4489// that the offset was a line when it could have deviated by up to 1ms/second.
4490TEST_P(MultinodeLoggerTest, OneDirectionTimeDrift) {
4491 std::vector<std::string> filenames;
4492
4493 CHECK_EQ(pi1_index_, 0u);
4494 CHECK_EQ(pi2_index_, 1u);
4495
4496 time_converter_.AddNextTimestamp(
4497 distributed_clock::epoch(),
4498 {BootTimestamp::epoch(), BootTimestamp::epoch()});
4499
4500 const chrono::nanoseconds before_disconnect_duration =
4501 time_converter_.AddMonotonic(
4502 {chrono::milliseconds(1000), chrono::milliseconds(1000)});
4503
4504 const chrono::nanoseconds test_duration =
4505 time_converter_.AddMonotonic(
4506 {chrono::milliseconds(1000), chrono::milliseconds(1000)}) +
4507 time_converter_.AddMonotonic(
4508 {chrono::milliseconds(10000),
4509 chrono::milliseconds(10000) - chrono::milliseconds(5)}) +
4510 time_converter_.AddMonotonic(
4511 {chrono::milliseconds(10000),
4512 chrono::milliseconds(10000) + chrono::milliseconds(5)});
4513
4514 const std::string kLogfile =
4515 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
4516 util::UnlinkRecursive(kLogfile);
4517
4518 {
4519 LoggerState pi2_logger = MakeLogger(pi2_);
4520 pi2_logger.StartLogger(kLogfile);
4521 event_loop_factory_.RunFor(before_disconnect_duration);
4522
4523 pi2_->Disconnect(pi1_->node());
4524
4525 event_loop_factory_.RunFor(test_duration);
4526 pi2_->Connect(pi1_->node());
4527
4528 event_loop_factory_.RunFor(chrono::milliseconds(5000));
4529 pi2_logger.AppendAllFilenames(&filenames);
4530 }
4531
4532 const std::vector<LogFile> sorted_parts = SortParts(filenames);
4533 ConfirmReadable(filenames);
4534}
4535
Austin Schuhe309d2a2019-11-29 13:25:21 -08004536} // namespace testing
4537} // namespace logger
4538} // namespace aos