blob: 1732549e5b01b360053c24d0236adfc3d24789f3 [file] [log] [blame]
Austin Schuh6bb8a822021-03-31 23:04:39 -07001#include <sys/stat.h>
2
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07005#include "aos/events/logging/log_reader.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08006#include "aos/events/logging/log_writer.h"
milind1f1dca32021-07-03 13:50:07 -07007#include "aos/events/logging/snappy_encoder.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
milind1f1dca32021-07-03 13:50:07 -0700171 logger_event_loop->OnRun([base_name1, base_name2, &logger_event_loop,
172 &logger]() {
173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
175 EXPECT_DEATH(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 logger.StartLogging(std::make_unique<LocalLogNamer>(
milind1f1dca32021-07-03 13:50:07 -0700177 base_name2, logger_event_loop.get(), logger_event_loop->node())),
178 "Already logging");
179 });
Brian Silverman1f345222020-09-24 21:14:48 -0700180 event_loop_factory_.RunFor(chrono::milliseconds(20000));
181 }
182}
183
184// Tests calling StopLogging twice.
185TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800186 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700187 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800188 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700189 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700190 const ::std::string logfile = base_name + ".part0.bfbs";
191 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800192 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700193 unlink(logfile.c_str());
194
195 LOG(INFO) << "Logging data to " << logfile;
196
197 {
198 std::unique_ptr<EventLoop> logger_event_loop =
199 event_loop_factory_.MakeEventLoop("logger");
200
201 event_loop_factory_.RunFor(chrono::milliseconds(95));
202
203 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800204 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700205 logger.set_polling_period(std::chrono::milliseconds(100));
206 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700207 logger.StartLogging(std::make_unique<LocalLogNamer>(
208 base_name, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700209 logger.StopLogging(aos::monotonic_clock::min_time);
210 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
211 "Not logging right now");
212 });
213 event_loop_factory_.RunFor(chrono::milliseconds(20000));
214 }
215}
216
217// Tests that we can startup twice.
218TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800219 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700220 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800221 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700222 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700223 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
224 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800225 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700226 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700227 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
228 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800229 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700230 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800231 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700232
233 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
234
235 {
236 std::unique_ptr<EventLoop> logger_event_loop =
237 event_loop_factory_.MakeEventLoop("logger");
238
239 event_loop_factory_.RunFor(chrono::milliseconds(95));
240
241 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800242 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700243 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh5b728b72021-06-16 14:57:15 -0700244 logger.StartLogging(std::make_unique<LocalLogNamer>(
245 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700246 event_loop_factory_.RunFor(chrono::milliseconds(10000));
247 logger.StopLogging(logger_event_loop->monotonic_now());
248 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh5b728b72021-06-16 14:57:15 -0700249 logger.StartLogging(std::make_unique<LocalLogNamer>(
250 base_name2, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700251 event_loop_factory_.RunFor(chrono::milliseconds(10000));
252 }
253
254 for (const auto &logfile :
255 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
256 SCOPED_TRACE(std::get<0>(logfile));
257 LogReader reader(std::get<0>(logfile));
258 reader.Register();
259
Austin Schuh07676622021-01-21 18:59:17 -0800260 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700261
262 std::unique_ptr<EventLoop> test_event_loop =
263 reader.event_loop_factory()->MakeEventLoop("log_reader");
264
265 int ping_count = std::get<1>(logfile);
266 int pong_count = std::get<1>(logfile);
267
268 // Confirm that the ping and pong counts both match, and the value also
269 // matches.
270 test_event_loop->MakeWatcher("/test",
271 [&ping_count](const examples::Ping &ping) {
272 EXPECT_EQ(ping.value(), ping_count + 1);
273 ++ping_count;
274 });
275 test_event_loop->MakeWatcher(
276 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
277 EXPECT_EQ(pong.value(), pong_count + 1);
278 ++pong_count;
279 EXPECT_EQ(ping_count, pong_count);
280 });
281
282 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
283 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
284 }
285}
286
Austin Schuhfa895892020-01-07 20:07:41 -0800287// Tests that we can read and write rotated log files.
288TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800289 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700290 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800291 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700292 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700293 const ::std::string logfile0 = base_name + ".part0.bfbs";
294 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800295 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800296 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800297 unlink(logfile0.c_str());
298 unlink(logfile1.c_str());
299
300 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
301
302 {
Austin Schuhfa895892020-01-07 20:07:41 -0800303 std::unique_ptr<EventLoop> logger_event_loop =
304 event_loop_factory_.MakeEventLoop("logger");
305
306 event_loop_factory_.RunFor(chrono::milliseconds(95));
307
Brian Silverman1f345222020-09-24 21:14:48 -0700308 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800309 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700310 logger.set_polling_period(std::chrono::milliseconds(100));
311 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800312 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700313 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800314 event_loop_factory_.RunFor(chrono::milliseconds(10000));
315 }
316
Austin Schuh64fab802020-09-09 22:47:47 -0700317 {
318 // Confirm that the UUIDs match for both the parts and the logger, and the
319 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800320 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700321 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800322 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700323 }
324
Brian Silvermanae7c0332020-09-30 16:58:23 -0700325 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
326 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700327 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
328 log_header[1].message().parts_uuid()->string_view());
329
330 EXPECT_EQ(log_header[0].message().parts_index(), 0);
331 EXPECT_EQ(log_header[1].message().parts_index(), 1);
332 }
333
Austin Schuhfa895892020-01-07 20:07:41 -0800334 // Even though it doesn't make any difference here, exercise the logic for
335 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800336 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800337
338 // Confirm that we can remap logged channels to point to new buses.
339 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
340
341 // This sends out the fetched messages and advances time to the start of the
342 // log file.
343 reader.Register();
344
Austin Schuh07676622021-01-21 18:59:17 -0800345 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800346
347 std::unique_ptr<EventLoop> test_event_loop =
348 reader.event_loop_factory()->MakeEventLoop("log_reader");
349
350 int ping_count = 10;
351 int pong_count = 10;
352
353 // Confirm that the ping value matches in the remapped channel location.
354 test_event_loop->MakeWatcher("/original/test",
355 [&ping_count](const examples::Ping &ping) {
356 EXPECT_EQ(ping.value(), ping_count + 1);
357 ++ping_count;
358 });
359 // Confirm that the ping and pong counts both match, and the value also
360 // matches.
361 test_event_loop->MakeWatcher(
362 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
363 EXPECT_EQ(pong.value(), pong_count + 1);
364 ++pong_count;
365 EXPECT_EQ(ping_count, pong_count);
366 });
367
368 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
369 EXPECT_EQ(ping_count, 2010);
370}
371
Austin Schuh4c4e0092019-12-22 16:18:03 -0800372// Tests that a large number of messages per second doesn't overwhelm writev.
373TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800374 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700375 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800376 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700377 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700378 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800379 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800380 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800381 unlink(logfile.c_str());
382
383 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700384 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800385
386 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800387 std::unique_ptr<EventLoop> logger_event_loop =
388 event_loop_factory_.MakeEventLoop("logger");
389
390 std::unique_ptr<EventLoop> ping_spammer_event_loop =
391 event_loop_factory_.MakeEventLoop("ping_spammer");
392 aos::Sender<examples::Ping> ping_sender =
393 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
394
395 aos::TimerHandler *timer_handler =
396 ping_spammer_event_loop->AddTimer([&ping_sender]() {
397 aos::Sender<examples::Ping>::Builder builder =
398 ping_sender.MakeBuilder();
399 examples::Ping::Builder ping_builder =
400 builder.MakeBuilder<examples::Ping>();
Austin Schuhbfe6c572022-01-27 20:48:20 -0800401 CHECK_EQ(builder.Send(ping_builder.Finish()), RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800402 });
403
404 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
405 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
406 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
407 chrono::microseconds(50));
408 });
409
Brian Silverman1f345222020-09-24 21:14:48 -0700410 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800411 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700412 logger.set_polling_period(std::chrono::milliseconds(100));
413 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800414
415 event_loop_factory_.RunFor(chrono::milliseconds(1000));
416 }
417}
418
James Kuszmauldd0a5042021-10-28 23:38:04 -0700419struct CompressionParams {
420 std::string_view extension;
421 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
422};
423
424std::ostream &operator<<(std::ostream &ostream,
425 const CompressionParams &params) {
426 ostream << "\"" << params.extension << "\"";
427 return ostream;
428}
429
430std::vector<CompressionParams> SupportedCompressionAlgorithms() {
431 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
432 {SnappyDecoder::kExtension,
433 []() { return std::make_unique<SnappyEncoder>(); }},
434#ifdef LZMA
435 {LzmaDecoder::kExtension,
436 []() { return std::make_unique<LzmaEncoder>(3); }}
437#endif // LZMA
438 };
439}
440
Austin Schuh61e973f2021-02-21 21:43:56 -0800441// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700442struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800443 // The config file to use.
444 std::string config;
445 // If true, the RemoteMessage channel should be shared between all the remote
446 // channels. If false, there will be 1 RemoteMessage channel per remote
447 // channel.
448 bool shared;
449 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700450 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800451};
Austin Schuh315b96b2020-12-11 21:21:12 -0800452
James Kuszmauldd0a5042021-10-28 23:38:04 -0700453std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
454 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
455 << ", sha256: \"" << params.sha256 << "\"}";
456 return ostream;
457}
458
Austin Schuh3e20c692021-11-16 20:43:16 -0800459struct LoggerState {
460 static LoggerState MakeLogger(NodeEventLoopFactory *node,
461 SimulatedEventLoopFactory *factory,
462 CompressionParams params,
463 const Configuration *configuration = nullptr) {
464 if (configuration == nullptr) {
465 configuration = factory->configuration();
466 }
467 return {node->MakeEventLoop("logger"),
468 {},
469 configuration,
470 configuration::GetNode(configuration, node->node()),
471 nullptr,
472 params};
473 }
474
475 void StartLogger(std::string logfile_base) {
476 CHECK(!logfile_base.empty());
477
478 logger = std::make_unique<Logger>(event_loop.get(), configuration);
479 logger->set_polling_period(std::chrono::milliseconds(100));
480 logger->set_name(
481 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
482 event_loop->OnRun([this, logfile_base]() {
483 std::unique_ptr<MultiNodeLogNamer> namer =
484 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
485 event_loop.get(), node);
486 namer->set_extension(params.extension);
487 namer->set_encoder_factory(params.encoder_factory);
488 log_namer = namer.get();
489
490 logger->StartLogging(std::move(namer));
491 });
492 }
493
494 std::unique_ptr<EventLoop> event_loop;
495 std::unique_ptr<Logger> logger;
496 const Configuration *configuration;
497 const Node *node;
498 MultiNodeLogNamer *log_namer;
499 CompressionParams params;
500
501 void AppendAllFilenames(std::vector<std::string> *filenames) {
502 for (const std::string &file : log_namer->all_filenames()) {
503 const std::string_view separator =
504 log_namer->base_name().back() == '/' ? "" : "_";
505 filenames->emplace_back(
506 absl::StrCat(log_namer->base_name(), separator, file));
507 }
508 }
509
510 ~LoggerState() {
511 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800512 std::vector<std::string> filenames;
513 AppendAllFilenames(&filenames);
Austin Schuhbfe6c572022-01-27 20:48:20 -0800514 std::sort(filenames.begin(), filenames.end());
Austin Schuh01f3b392022-01-25 20:03:09 -0800515 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800516 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800517 auto x = ReadHeader(file);
518 if (x) {
519 VLOG(1) << aos::FlatbufferToJson(x.value());
520 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800521 }
522 }
523 }
524};
525
526void ConfirmReadable(const std::vector<std::string> &files) {
527 {
528 LogReader reader(SortParts(files));
529
530 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
531 reader.Register(&log_reader_factory);
532
533 log_reader_factory.Run();
534
535 reader.Deregister();
536 }
537 {
538 LogReader reader(SortParts(files));
539
540 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
541 reader.RegisterWithoutStarting(&log_reader_factory);
542 if (configuration::MultiNode(log_reader_factory.configuration())) {
543 for (const aos::Node *node :
544 *log_reader_factory.configuration()->nodes()) {
545 reader.OnStart(node, [node]() {
546 LOG(INFO) << "Starting " << node->name()->string_view();
547 });
548 }
549 }
550
551 log_reader_factory.Run();
552
553 reader.Deregister();
554 }
555}
556
James Kuszmauldd0a5042021-10-28 23:38:04 -0700557class MultinodeLoggerTest : public ::testing::TestWithParam<
558 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800559 public:
560 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700561 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
562 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800563 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800564 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700565 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800566 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700567 event_loop_factory_.configuration(), pi1_->node())),
568 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800569 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700570 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800571 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800572 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
573 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800574 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800575 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800576 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700577 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700578 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800579 event_loop_factory_.SetTimeConverter(&time_converter_);
580
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700581 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700582 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700583 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800584 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700585 }
586
Austin Schuh268586b2021-03-31 22:24:39 -0700587 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800588 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800589 unlink(file.c_str());
590 }
591
Austin Schuh268586b2021-03-31 22:24:39 -0700592 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800593 unlink(file.c_str());
594 }
595
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700596 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
597 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700598
599 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
600 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700601 }
602
James Kuszmauldd0a5042021-10-28 23:38:04 -0700603 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800604
605 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700606 std::string logfile_base2,
Austin Schuhbfe6c572022-01-27 20:48:20 -0800607 size_t pi1_data_count = 3,
608 size_t pi2_data_count = 3) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800609 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700610 result.emplace_back(absl::StrCat(
611 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
612 result.emplace_back(absl::StrCat(
613 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700614 for (size_t i = 0; i < pi1_data_count; ++i) {
615 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700616 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700617 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800618 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700619 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800620 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700621 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700622 for (size_t i = 0; i < pi2_data_count; ++i) {
623 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700624 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700625 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700626 result.emplace_back(logfile_base2 +
627 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
628 Extension());
629 result.emplace_back(logfile_base2 +
630 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
631 Extension());
632 result.emplace_back(logfile_base1 +
633 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
634 Extension());
635 result.emplace_back(logfile_base1 +
636 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
637 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800638 if (shared()) {
639 result.emplace_back(logfile_base1 +
640 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700641 "aos.message_bridge.RemoteMessage.part0" +
642 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800643 result.emplace_back(logfile_base1 +
644 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700645 "aos.message_bridge.RemoteMessage.part1" +
646 Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800647 result.emplace_back(logfile_base1 +
648 "_timestamps/pi1/aos/remote_timestamps/pi2/"
649 "aos.message_bridge.RemoteMessage.part2" +
650 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800651 result.emplace_back(logfile_base2 +
652 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700653 "aos.message_bridge.RemoteMessage.part0" +
654 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800655 result.emplace_back(logfile_base2 +
656 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700657 "aos.message_bridge.RemoteMessage.part1" +
658 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800659 } else {
660 result.emplace_back(logfile_base1 +
661 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
662 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700663 "aos.message_bridge.RemoteMessage.part0" +
664 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800665 result.emplace_back(logfile_base1 +
666 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
667 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700668 "aos.message_bridge.RemoteMessage.part1" +
669 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800670 result.emplace_back(logfile_base2 +
671 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
672 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700673 "aos.message_bridge.RemoteMessage.part0" +
674 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800675 result.emplace_back(logfile_base2 +
676 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
677 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700678 "aos.message_bridge.RemoteMessage.part1" +
679 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800680 result.emplace_back(logfile_base1 +
681 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
682 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700683 "aos.message_bridge.RemoteMessage.part0" +
684 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800685 result.emplace_back(logfile_base1 +
686 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
687 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700688 "aos.message_bridge.RemoteMessage.part1" +
689 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800690 }
691
692 return result;
693 }
694
695 std::vector<std::string> MakePi1RebootLogfiles() {
696 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700697 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
698 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
699 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuhbfe6c572022-01-27 20:48:20 -0800700 result.emplace_back(logfile_base1_ + "_pi1_data.part3" + Extension());
701 result.emplace_back(logfile_base1_ + "_pi1_data.part4" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800702 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700703 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800704 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700705 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800706 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700707 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700708 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700709 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
710 result.emplace_back(logfile_base1_ +
711 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
712 Extension());
713 result.emplace_back(logfile_base1_ +
714 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
715 Extension());
716 result.emplace_back(logfile_base1_ +
717 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
718 Extension());
719 result.emplace_back(logfile_base1_ +
720 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
721 Extension());
722 result.emplace_back(absl::StrCat(
723 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800724 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -0800725 for (size_t i = 0; i < 6; ++i) {
726 result.emplace_back(
727 absl::StrCat(logfile_base1_,
728 "_timestamps/pi1/aos/remote_timestamps/pi2/"
729 "aos.message_bridge.RemoteMessage.part",
730 i, Extension()));
731 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800732 } else {
733 result.emplace_back(logfile_base1_ +
734 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
735 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700736 "aos.message_bridge.RemoteMessage.part0" +
737 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800738 result.emplace_back(logfile_base1_ +
739 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
740 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700741 "aos.message_bridge.RemoteMessage.part1" +
742 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800743 result.emplace_back(logfile_base1_ +
744 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
745 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700746 "aos.message_bridge.RemoteMessage.part2" +
747 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700748 result.emplace_back(logfile_base1_ +
749 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
750 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700751 "aos.message_bridge.RemoteMessage.part3" +
752 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800753
754 result.emplace_back(logfile_base1_ +
755 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
756 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700757 "aos.message_bridge.RemoteMessage.part0" +
758 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800759 result.emplace_back(logfile_base1_ +
760 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
761 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700762 "aos.message_bridge.RemoteMessage.part1" +
763 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800764 result.emplace_back(logfile_base1_ +
765 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
766 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700767 "aos.message_bridge.RemoteMessage.part2" +
768 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700769 result.emplace_back(logfile_base1_ +
770 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
771 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700772 "aos.message_bridge.RemoteMessage.part3" +
773 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800774 }
775 return result;
776 }
777
778 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
779 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700780 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
781 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
782 result.emplace_back(logfile_base1_ +
783 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
784 Extension());
785 result.emplace_back(absl::StrCat(
786 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700787 return result;
788 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800789
Austin Schuh510dc622021-08-06 18:47:30 -0700790 std::vector<std::string> MakePi1DeadNodeLogfiles() {
791 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700792 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
793 result.emplace_back(absl::StrCat(
794 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800795 return result;
796 }
797
798 std::vector<std::vector<std::string>> StructureLogFiles() {
799 std::vector<std::vector<std::string>> result{
Austin Schuhbfe6c572022-01-27 20:48:20 -0800800 std::vector<std::string>{logfiles_[2], logfiles_[3], logfiles_[4]},
801 std::vector<std::string>{logfiles_[5], logfiles_[6]},
802 std::vector<std::string>{logfiles_[7], logfiles_[8], logfiles_[9]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800803 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhbfe6c572022-01-27 20:48:20 -0800804 std::vector<std::string>{logfiles_[12], logfiles_[13]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800805
Austin Schuhbfe6c572022-01-27 20:48:20 -0800806 if (shared()) {
807 result.emplace_back(std::vector<std::string>{logfiles_[14], logfiles_[15],
808 logfiles_[16]});
809 result.emplace_back(
810 std::vector<std::string>{logfiles_[17], logfiles_[18]});
811 } else {
812 result.emplace_back(
813 std::vector<std::string>{logfiles_[14], logfiles_[15]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800814 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700815 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuhbfe6c572022-01-27 20:48:20 -0800816 result.emplace_back(
817 std::vector<std::string>{logfiles_[18], logfiles_[19]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800818 }
819
820 return result;
821 }
822
James Kuszmauldd0a5042021-10-28 23:38:04 -0700823 std::string Extension() {
824 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
825 }
826
Austin Schuh58646e22021-08-23 23:51:46 -0700827 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700828 SimulatedEventLoopFactory *factory = nullptr,
829 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700830 if (factory == nullptr) {
831 factory = &event_loop_factory_;
832 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800833 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
834 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700835 }
836
James Kuszmauldd0a5042021-10-28 23:38:04 -0700837 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700838 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800839 if (logger->event_loop->node()->name()->string_view() == "pi1") {
840 logfile_base = logfile_base1_;
841 } else {
842 logfile_base = logfile_base2_;
843 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700844 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800845 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700846 }
Austin Schuh15649d62019-12-28 16:36:38 -0800847
Austin Schuh3bd4c402020-11-06 18:19:06 -0800848 void VerifyParts(const std::vector<LogFile> &sorted_parts,
849 const std::vector<std::string> &corrupted_parts = {}) {
850 EXPECT_EQ(sorted_parts.size(), 2u);
851
852 // Count up the number of UUIDs and make sure they are what we expect as a
853 // sanity check.
854 std::set<std::string> log_event_uuids;
855 std::set<std::string> parts_uuids;
856 std::set<std::string> both_uuids;
857
858 size_t missing_rt_count = 0;
859
860 std::vector<std::string> logger_nodes;
861 for (const LogFile &log_file : sorted_parts) {
862 EXPECT_FALSE(log_file.log_event_uuid.empty());
863 log_event_uuids.insert(log_file.log_event_uuid);
864 logger_nodes.emplace_back(log_file.logger_node);
865 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800866 EXPECT_TRUE(log_file.config);
867 EXPECT_EQ(log_file.name,
868 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800869
870 for (const LogParts &part : log_file.parts) {
871 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
872 << ": " << part;
873 missing_rt_count +=
874 part.realtime_start_time == aos::realtime_clock::min_time;
875
876 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
877 log_event_uuids.end());
878 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800879 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800880 parts_uuids.insert(part.parts_uuid);
881 both_uuids.insert(part.parts_uuid);
882 }
883 }
884
Austin Schuh61e973f2021-02-21 21:43:56 -0800885 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
886 // start time on remote nodes because we don't know it and would be
887 // guessing. And the log reader can actually do a better job. The number
888 // depends on if we have the remote timestamps split across 2 files, or just
889 // across 1, depending on if we are using a split or combined timestamp
890 // channel config.
891 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800892
893 EXPECT_EQ(log_event_uuids.size(), 2u);
894 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
895 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
896
897 // Test that each list of parts is in order. Don't worry about the ordering
898 // between part file lists though.
899 // (inner vectors all need to be in order, but outer one doesn't matter).
Austin Schuhbfe6c572022-01-27 20:48:20 -0800900 ASSERT_THAT(ToLogReaderVector(sorted_parts),
Austin Schuh3bd4c402020-11-06 18:19:06 -0800901 ::testing::UnorderedElementsAreArray(structured_logfiles_));
902
903 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
904
905 EXPECT_NE(sorted_parts[0].realtime_start_time,
906 aos::realtime_clock::min_time);
907 EXPECT_NE(sorted_parts[1].realtime_start_time,
908 aos::realtime_clock::min_time);
909
910 EXPECT_NE(sorted_parts[0].monotonic_start_time,
911 aos::monotonic_clock::min_time);
912 EXPECT_NE(sorted_parts[1].monotonic_start_time,
913 aos::monotonic_clock::min_time);
914
915 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
916 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
917 }
918
919 void AddExtension(std::string_view extension) {
920 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
921 [extension](const std::string &in) {
922 return absl::StrCat(in, extension);
923 });
924
925 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
926 structured_logfiles_.begin(),
927 [extension](std::vector<std::string> in) {
928 std::transform(in.begin(), in.end(), in.begin(),
929 [extension](const std::string &in_str) {
930 return absl::StrCat(in_str, extension);
931 });
932 return in;
933 });
934 }
935
Austin Schuh15649d62019-12-28 16:36:38 -0800936 // Config and factory.
937 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800938 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800939 SimulatedEventLoopFactory event_loop_factory_;
940
Austin Schuh58646e22021-08-23 23:51:46 -0700941 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800942 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700943 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800944 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700945
946 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800947 std::string logfile_base1_;
948 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800949 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700950 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800951 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700952
953 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800954};
955
Austin Schuh391e3172020-09-01 22:48:18 -0700956// Counts the number of messages on a channel. Returns (channel name, channel
957// type, count) for every message matching matcher()
958std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800959 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700960 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800961 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800962 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800963
Austin Schuh6f3babe2020-01-26 20:34:50 -0800964 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700965 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800966 if (!msg) {
967 break;
968 }
969
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700970 if (matcher(msg.get())) {
971 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800972 }
973 }
974
Austin Schuh391e3172020-09-01 22:48:18 -0700975 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800976 int channel = 0;
977 for (size_t i = 0; i < counts.size(); ++i) {
978 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800979 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700980 result.push_back(std::make_tuple(channel->name()->str(),
981 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800982 }
983 ++channel;
984 }
985
986 return result;
987}
988
989// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700990std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800991 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700992 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700993 return CountChannelsMatching(
994 config, filename, [](const UnpackedMessageHeader *msg) {
995 if (msg->span.data() != nullptr) {
996 CHECK(!msg->monotonic_remote_time.has_value());
997 CHECK(!msg->realtime_remote_time.has_value());
998 CHECK(!msg->remote_queue_index.has_value());
999 return true;
1000 }
1001 return false;
1002 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001003}
1004
1005// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001006std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001007 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001008 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001009 return CountChannelsMatching(
1010 config, filename, [](const UnpackedMessageHeader *msg) {
1011 if (msg->span.data() == nullptr) {
1012 CHECK(msg->monotonic_remote_time.has_value());
1013 CHECK(msg->realtime_remote_time.has_value());
1014 CHECK(msg->remote_queue_index.has_value());
1015 return true;
1016 }
1017 return false;
1018 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001019}
1020
Austin Schuhcde938c2020-02-02 17:30:07 -08001021// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001022TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001023 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001024 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001025
Austin Schuh15649d62019-12-28 16:36:38 -08001026 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001027 LoggerState pi1_logger = MakeLogger(pi1_);
1028 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001029
1030 event_loop_factory_.RunFor(chrono::milliseconds(95));
1031
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001032 StartLogger(&pi1_logger);
1033 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001034
Austin Schuh15649d62019-12-28 16:36:38 -08001035 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001036 pi1_logger.AppendAllFilenames(&actual_filenames);
1037 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh15649d62019-12-28 16:36:38 -08001038 }
1039
Austin Schuhbfe6c572022-01-27 20:48:20 -08001040 ASSERT_THAT(actual_filenames,
1041 ::testing::UnorderedElementsAreArray(logfiles_));
1042
Austin Schuh6f3babe2020-01-26 20:34:50 -08001043 {
Austin Schuh64fab802020-09-09 22:47:47 -07001044 std::set<std::string> logfile_uuids;
1045 std::set<std::string> parts_uuids;
1046 // Confirm that we have the expected number of UUIDs for both the logfile
1047 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001048 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001049 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001050 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001051 if (!log_header.back().message().has_configuration()) {
1052 logfile_uuids.insert(
1053 log_header.back().message().log_event_uuid()->str());
1054 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1055 }
Austin Schuh64fab802020-09-09 22:47:47 -07001056 }
Austin Schuh15649d62019-12-28 16:36:38 -08001057
Austin Schuh64fab802020-09-09 22:47:47 -07001058 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001059 if (shared()) {
1060 EXPECT_EQ(parts_uuids.size(), 7u);
1061 } else {
1062 EXPECT_EQ(parts_uuids.size(), 8u);
1063 }
Austin Schuh64fab802020-09-09 22:47:47 -07001064
1065 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001066 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001067 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001068 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi1");
1069
Austin Schuh64fab802020-09-09 22:47:47 -07001070 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001071 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001072
Austin Schuhe46492f2021-07-31 19:49:41 -07001073 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001074 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi2");
1075 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi2");
1076
1077 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi1");
1078 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi1");
1079
Austin Schuhe46492f2021-07-31 19:49:41 -07001080 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1081 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001082
1083 if (shared()) {
1084 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1085 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001086 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
Austin Schuhbfe6c572022-01-27 20:48:20 -08001087
1088 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1089 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi1");
1090 } else {
1091 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi2");
1092 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi2");
1093
1094 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi1");
1095 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi1");
1096
1097 EXPECT_EQ(log_header[18].message().node()->name()->string_view(), "pi2");
1098 EXPECT_EQ(log_header[19].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001099 }
Austin Schuh64fab802020-09-09 22:47:47 -07001100
1101 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001102 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001103 EXPECT_EQ(log_header[3].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001104 EXPECT_EQ(log_header[4].message().parts_index(), 2);
1105
1106 EXPECT_EQ(log_header[5].message().parts_index(), 0);
1107 EXPECT_EQ(log_header[6].message().parts_index(), 1);
1108
1109 EXPECT_EQ(log_header[7].message().parts_index(), 0);
1110 EXPECT_EQ(log_header[8].message().parts_index(), 1);
1111 EXPECT_EQ(log_header[9].message().parts_index(), 2);
1112
Austin Schuh64fab802020-09-09 22:47:47 -07001113 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1114 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001115
Austin Schuh61e973f2021-02-21 21:43:56 -08001116 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1117 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001118
1119 if (shared()) {
1120 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1121 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1122 EXPECT_EQ(log_header[16].message().parts_index(), 2);
1123
1124 EXPECT_EQ(log_header[17].message().parts_index(), 0);
1125 EXPECT_EQ(log_header[18].message().parts_index(), 1);
1126 } else {
1127 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1128 EXPECT_EQ(log_header[15].message().parts_index(), 1);
1129
Austin Schuhe46492f2021-07-31 19:49:41 -07001130 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1131 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08001132
1133 EXPECT_EQ(log_header[18].message().parts_index(), 0);
1134 EXPECT_EQ(log_header[19].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001135 }
Austin Schuh64fab802020-09-09 22:47:47 -07001136 }
1137
Austin Schuh8c399962020-12-25 21:51:45 -08001138 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001139 {
Austin Schuh391e3172020-09-01 22:48:18 -07001140 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001141 std::shared_ptr<const aos::Configuration> config =
1142 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001143
Austin Schuh6f3babe2020-01-26 20:34:50 -08001144 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001145 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1146 UnorderedElementsAre(
1147 std::make_tuple("/pi1/aos",
1148 "aos.message_bridge.ServerStatistics", 1),
1149 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001150 << " : " << logfiles_[2];
1151 EXPECT_THAT(
1152 CountChannelsData(config, logfiles_[3]),
1153 UnorderedElementsAre(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001154 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 1),
1155 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1156 1)))
1157 << " : " << logfiles_[3];
1158 EXPECT_THAT(
1159 CountChannelsData(config, logfiles_[4]),
1160 UnorderedElementsAre(
1161 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 199),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001162 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001163 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001164 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
Austin Schuhbfe6c572022-01-27 20:48:20 -08001165 199),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001166 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001167 std::make_tuple("/test", "aos.examples.Ping", 2000)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001168 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001169 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001170 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1171 UnorderedElementsAre())
1172 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001173 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001174 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001175 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001176 << " : " << logfiles_[3];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001177 EXPECT_THAT(
1178 CountChannelsTimestamp(config, logfiles_[4]),
1179 UnorderedElementsAre(
1180 std::make_tuple("/test", "aos.examples.Pong", 2000),
1181 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
1182 << " : " << logfiles_[4];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001183
1184 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001185 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001186 CountChannelsData(config, logfiles_[5]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001187 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001188 << " : " << logfiles_[5];
1189 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001190 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001191 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001192 << " : " << logfiles_[6];
Austin Schuh391e3172020-09-01 22:48:18 -07001193
Austin Schuh6f3babe2020-01-26 20:34:50 -08001194 // No timestamps
Austin Schuhe46492f2021-07-31 19:49:41 -07001195 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1196 UnorderedElementsAre())
1197 << " : " << logfiles_[5];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001198 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1199 UnorderedElementsAre())
1200 << " : " << logfiles_[6];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001201
1202 // Timing reports and pongs.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001203 EXPECT_THAT(CountChannelsData(config, logfiles_[7]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001204 UnorderedElementsAre(std::make_tuple(
1205 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001206 << " : " << logfiles_[7];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001207 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001208 CountChannelsData(config, logfiles_[8]),
1209 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 1)))
1210 << " : " << logfiles_[8];
1211 EXPECT_THAT(
1212 CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001213 UnorderedElementsAre(
1214 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001215 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001216 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001217 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1218 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001219 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001220 std::make_tuple("/test", "aos.examples.Pong", 2000)))
1221 << " : " << logfiles_[9];
Austin Schuh61e973f2021-02-21 21:43:56 -08001222 // And ping timestamps.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001223 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[7]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001224 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001225 << " : " << logfiles_[7];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001226 EXPECT_THAT(
1227 CountChannelsTimestamp(config, logfiles_[8]),
1228 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Ping", 1)))
1229 << " : " << logfiles_[8];
1230 EXPECT_THAT(
1231 CountChannelsTimestamp(config, logfiles_[9]),
1232 UnorderedElementsAre(
1233 std::make_tuple("/test", "aos.examples.Ping", 2000),
1234 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
1235 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001236
1237 // And then test that the remotely logged timestamp data files only have
1238 // timestamps in them.
Austin Schuhe46492f2021-07-31 19:49:41 -07001239 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1240 UnorderedElementsAre())
1241 << " : " << logfiles_[10];
1242 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1243 UnorderedElementsAre())
1244 << " : " << logfiles_[11];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001245 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1246 UnorderedElementsAre())
1247 << " : " << logfiles_[12];
1248 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1249 UnorderedElementsAre())
1250 << " : " << logfiles_[13];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001251
Austin Schuh8c399962020-12-25 21:51:45 -08001252 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001253 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001254 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001255 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001256 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001257 UnorderedElementsAre(std::make_tuple(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001258 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001259 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001260
Austin Schuh61e973f2021-02-21 21:43:56 -08001261 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001262 UnorderedElementsAre(std::make_tuple(
1263 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001264 << " : " << logfiles_[12];
1265 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001266 UnorderedElementsAre(std::make_tuple(
1267 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001268 << " : " << logfiles_[13];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001269
1270 // Timestamps from pi2 on pi1, and the other way.
1271 if (shared()) {
1272 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1273 UnorderedElementsAre())
1274 << " : " << logfiles_[14];
1275 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1276 UnorderedElementsAre())
1277 << " : " << logfiles_[15];
Austin Schuhe46492f2021-07-31 19:49:41 -07001278 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001279 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001280 << " : " << logfiles_[16];
1281 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001282 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001283 << " : " << logfiles_[17];
Austin Schuhbfe6c572022-01-27 20:48:20 -08001284 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1285 UnorderedElementsAre())
1286 << " : " << logfiles_[18];
Austin Schuh61e973f2021-02-21 21:43:56 -08001287
Austin Schuhbfe6c572022-01-27 20:48:20 -08001288 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1289 UnorderedElementsAre(
1290 std::make_tuple("/test", "aos.examples.Ping", 1)))
1291 << " : " << logfiles_[14];
Austin Schuh61e973f2021-02-21 21:43:56 -08001292 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001293 CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001294 UnorderedElementsAre(
1295 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001296 std::make_tuple("/test", "aos.examples.Ping", 90)))
1297 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001298 EXPECT_THAT(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001299 CountChannelsTimestamp(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001300 UnorderedElementsAre(
1301 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1302 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001303 << " : " << logfiles_[16];
1304 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuhbfe6c572022-01-27 20:48:20 -08001305 UnorderedElementsAre(std::make_tuple(
1306 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1307 << " : " << logfiles_[17];
1308 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1309 UnorderedElementsAre(std::make_tuple(
1310 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1311 << " : " << logfiles_[18];
1312 } else {
1313 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1314 UnorderedElementsAre())
1315 << " : " << logfiles_[14];
1316 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1317 UnorderedElementsAre())
1318 << " : " << logfiles_[15];
1319 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
1320 UnorderedElementsAre())
1321 << " : " << logfiles_[16];
1322 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
1323 UnorderedElementsAre())
1324 << " : " << logfiles_[17];
1325 EXPECT_THAT(CountChannelsData(config, logfiles_[18]),
1326 UnorderedElementsAre())
1327 << " : " << logfiles_[18];
1328 EXPECT_THAT(CountChannelsData(config, logfiles_[19]),
1329 UnorderedElementsAre())
1330 << " : " << logfiles_[19];
1331
1332 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1333 UnorderedElementsAre(std::make_tuple(
1334 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1335 << " : " << logfiles_[14];
1336 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1337 UnorderedElementsAre(std::make_tuple(
1338 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1339 << " : " << logfiles_[15];
1340 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1341 UnorderedElementsAre(std::make_tuple(
1342 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1343 << " : " << logfiles_[16];
1344 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
1345 UnorderedElementsAre(std::make_tuple(
1346 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1347 << " : " << logfiles_[17];
1348 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[18]),
1349 UnorderedElementsAre(
1350 std::make_tuple("/test", "aos.examples.Ping", 91)))
1351 << " : " << logfiles_[18];
1352 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[19]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001353 UnorderedElementsAre(
1354 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhbfe6c572022-01-27 20:48:20 -08001355 << " : " << logfiles_[19];
Austin Schuh61e973f2021-02-21 21:43:56 -08001356 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001357 }
1358
Austin Schuh8c399962020-12-25 21:51:45 -08001359 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001360
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001361 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001362 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001363
1364 // This sends out the fetched messages and advances time to the start of the
1365 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001366 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001367
Austin Schuhac0771c2020-01-07 18:36:30 -08001368 const Node *pi1 =
1369 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001370 const Node *pi2 =
1371 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001372
Austin Schuh2f8fd752020-09-01 22:38:28 -07001373 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1374 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1375 LOG(INFO) << "now pi1 "
1376 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1377 LOG(INFO) << "now pi2 "
1378 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1379
Austin Schuh07676622021-01-21 18:59:17 -08001380 EXPECT_THAT(reader.LoggedNodes(),
1381 ::testing::ElementsAre(
1382 configuration::GetNode(reader.logged_configuration(), pi1),
1383 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001384
1385 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001386
Austin Schuh6f3babe2020-01-26 20:34:50 -08001387 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001388 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001389 std::unique_ptr<EventLoop> pi2_event_loop =
1390 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001391
Austin Schuh6f3babe2020-01-26 20:34:50 -08001392 int pi1_ping_count = 10;
1393 int pi2_ping_count = 10;
1394 int pi1_pong_count = 10;
1395 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001396
1397 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001398 pi1_event_loop->MakeWatcher(
1399 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001400 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001401 << pi1_event_loop->context().monotonic_remote_time << " -> "
1402 << pi1_event_loop->context().monotonic_event_time;
1403 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1404 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1405 pi1_ping_count * chrono::milliseconds(10) +
1406 monotonic_clock::epoch());
1407 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1408 pi1_ping_count * chrono::milliseconds(10) +
1409 realtime_clock::epoch());
1410 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1411 pi1_event_loop->context().monotonic_event_time);
1412 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1413 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001414
Austin Schuh6f3babe2020-01-26 20:34:50 -08001415 ++pi1_ping_count;
1416 });
1417 pi2_event_loop->MakeWatcher(
1418 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001419 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001420 << pi2_event_loop->context().monotonic_remote_time << " -> "
1421 << pi2_event_loop->context().monotonic_event_time;
1422 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1423
1424 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1425 pi2_ping_count * chrono::milliseconds(10) +
1426 monotonic_clock::epoch());
1427 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1428 pi2_ping_count * chrono::milliseconds(10) +
1429 realtime_clock::epoch());
1430 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1431 chrono::microseconds(150),
1432 pi2_event_loop->context().monotonic_event_time);
1433 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1434 chrono::microseconds(150),
1435 pi2_event_loop->context().realtime_event_time);
1436 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001437 });
1438
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001439 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001440 // Confirm that the ping and pong counts both match, and the value also
1441 // matches.
1442 pi1_event_loop->MakeWatcher(
1443 "/test", [&pi1_event_loop, &pi1_ping_count,
1444 &pi1_pong_count](const examples::Pong &pong) {
1445 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1446 << pi1_event_loop->context().monotonic_remote_time << " -> "
1447 << pi1_event_loop->context().monotonic_event_time;
1448
1449 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1450 pi1_pong_count + kQueueIndexOffset);
1451 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1452 chrono::microseconds(200) +
1453 pi1_pong_count * chrono::milliseconds(10) +
1454 monotonic_clock::epoch());
1455 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1456 chrono::microseconds(200) +
1457 pi1_pong_count * chrono::milliseconds(10) +
1458 realtime_clock::epoch());
1459
1460 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1461 chrono::microseconds(150),
1462 pi1_event_loop->context().monotonic_event_time);
1463 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1464 chrono::microseconds(150),
1465 pi1_event_loop->context().realtime_event_time);
1466
1467 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1468 ++pi1_pong_count;
1469 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1470 });
1471 pi2_event_loop->MakeWatcher(
1472 "/test", [&pi2_event_loop, &pi2_ping_count,
1473 &pi2_pong_count](const examples::Pong &pong) {
1474 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1475 << pi2_event_loop->context().monotonic_remote_time << " -> "
1476 << pi2_event_loop->context().monotonic_event_time;
1477
1478 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001479 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001480
1481 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1482 chrono::microseconds(200) +
1483 pi2_pong_count * chrono::milliseconds(10) +
1484 monotonic_clock::epoch());
1485 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1486 chrono::microseconds(200) +
1487 pi2_pong_count * chrono::milliseconds(10) +
1488 realtime_clock::epoch());
1489
1490 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1491 pi2_event_loop->context().monotonic_event_time);
1492 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1493 pi2_event_loop->context().realtime_event_time);
1494
1495 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1496 ++pi2_pong_count;
1497 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1498 });
1499
1500 log_reader_factory.Run();
1501 EXPECT_EQ(pi1_ping_count, 2010);
1502 EXPECT_EQ(pi2_ping_count, 2010);
1503 EXPECT_EQ(pi1_pong_count, 2010);
1504 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001505
1506 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001507}
1508
James Kuszmaul46d82582020-05-09 19:50:09 -07001509typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1510
1511// Test that if we feed the replay with a mismatched node list that we die on
1512// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001513TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001514 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001515 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001516 LoggerState pi1_logger = MakeLogger(pi1_);
1517 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001518
1519 event_loop_factory_.RunFor(chrono::milliseconds(95));
1520
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001521 StartLogger(&pi1_logger);
1522 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001523
James Kuszmaul46d82582020-05-09 19:50:09 -07001524 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1525 }
1526
1527 // Test that, if we add an additional node to the replay config that the
1528 // logger complains about the mismatch in number of nodes.
1529 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1530 configuration::MergeWithConfig(&config_.message(), R"({
1531 "nodes": [
1532 {
1533 "name": "extra-node"
1534 }
1535 ]
1536 }
1537 )");
1538
Austin Schuh287d43d2020-12-04 20:19:33 -08001539 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1540 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001541 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001542}
1543
Austin Schuhcde938c2020-02-02 17:30:07 -08001544// Tests that we can read log files where they don't start at the same monotonic
1545// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001546TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001547 time_converter_.StartEqual();
Austin Schuhbfe6c572022-01-27 20:48:20 -08001548 std::vector<std::string> actual_filenames;
1549
Austin Schuhcde938c2020-02-02 17:30:07 -08001550 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001551 LoggerState pi1_logger = MakeLogger(pi1_);
1552 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001553
1554 event_loop_factory_.RunFor(chrono::milliseconds(95));
1555
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001556 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001557
1558 event_loop_factory_.RunFor(chrono::milliseconds(200));
1559
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001560 StartLogger(&pi2_logger);
1561
Austin Schuhcde938c2020-02-02 17:30:07 -08001562 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001563 pi1_logger.AppendAllFilenames(&actual_filenames);
1564 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuhcde938c2020-02-02 17:30:07 -08001565 }
1566
Austin Schuhe46492f2021-07-31 19:49:41 -07001567 // Since we delay starting pi2, it already knows about all the timestamps so
1568 // we don't end up with extra parts.
Austin Schuhbfe6c572022-01-27 20:48:20 -08001569 LogReader reader(SortParts(actual_filenames));
Austin Schuhcde938c2020-02-02 17:30:07 -08001570
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001571 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001572 log_reader_factory.set_send_delay(chrono::microseconds(0));
1573
1574 // This sends out the fetched messages and advances time to the start of the
1575 // log file.
1576 reader.Register(&log_reader_factory);
1577
1578 const Node *pi1 =
1579 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1580 const Node *pi2 =
1581 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1582
Austin Schuh07676622021-01-21 18:59:17 -08001583 EXPECT_THAT(reader.LoggedNodes(),
1584 ::testing::ElementsAre(
1585 configuration::GetNode(reader.logged_configuration(), pi1),
1586 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001587
1588 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1589
1590 std::unique_ptr<EventLoop> pi1_event_loop =
1591 log_reader_factory.MakeEventLoop("test", pi1);
1592 std::unique_ptr<EventLoop> pi2_event_loop =
1593 log_reader_factory.MakeEventLoop("test", pi2);
1594
1595 int pi1_ping_count = 30;
1596 int pi2_ping_count = 30;
1597 int pi1_pong_count = 30;
1598 int pi2_pong_count = 30;
1599
1600 // Confirm that the ping value matches.
1601 pi1_event_loop->MakeWatcher(
1602 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1603 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1604 << pi1_event_loop->context().monotonic_remote_time << " -> "
1605 << pi1_event_loop->context().monotonic_event_time;
1606 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1607
1608 ++pi1_ping_count;
1609 });
1610 pi2_event_loop->MakeWatcher(
1611 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1612 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1613 << pi2_event_loop->context().monotonic_remote_time << " -> "
1614 << pi2_event_loop->context().monotonic_event_time;
1615 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1616
1617 ++pi2_ping_count;
1618 });
1619
1620 // Confirm that the ping and pong counts both match, and the value also
1621 // matches.
1622 pi1_event_loop->MakeWatcher(
1623 "/test", [&pi1_event_loop, &pi1_ping_count,
1624 &pi1_pong_count](const examples::Pong &pong) {
1625 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1626 << pi1_event_loop->context().monotonic_remote_time << " -> "
1627 << pi1_event_loop->context().monotonic_event_time;
1628
1629 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1630 ++pi1_pong_count;
1631 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1632 });
1633 pi2_event_loop->MakeWatcher(
1634 "/test", [&pi2_event_loop, &pi2_ping_count,
1635 &pi2_pong_count](const examples::Pong &pong) {
1636 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1637 << pi2_event_loop->context().monotonic_remote_time << " -> "
1638 << pi2_event_loop->context().monotonic_event_time;
1639
1640 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1641 ++pi2_pong_count;
1642 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1643 });
1644
1645 log_reader_factory.Run();
1646 EXPECT_EQ(pi1_ping_count, 2030);
1647 EXPECT_EQ(pi2_ping_count, 2030);
1648 EXPECT_EQ(pi1_pong_count, 2030);
1649 EXPECT_EQ(pi2_pong_count, 2030);
1650
1651 reader.Deregister();
1652}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001653
Austin Schuh8bd96322020-02-13 21:18:22 -08001654// Tests that we can read log files where the monotonic clocks drift and don't
1655// match correctly. While we are here, also test that different ending times
1656// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001657TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001658 // TODO(austin): Negate...
1659 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1660
Austin Schuh66168842021-08-17 19:42:21 -07001661 time_converter_.AddMonotonic(
1662 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001663 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1664 // skew to be 200 uS/s
1665 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1666 {chrono::milliseconds(95),
1667 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1668 // Run another 200 ms to have one logger start first.
1669 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1670 {chrono::milliseconds(200), chrono::milliseconds(200)});
1671 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1672 // go far enough to cause problems if this isn't accounted for.
1673 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1674 {chrono::milliseconds(20000),
1675 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1676 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1677 {chrono::milliseconds(40000),
1678 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1679 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1680 {chrono::milliseconds(400), chrono::milliseconds(400)});
1681
Austin Schuhcde938c2020-02-02 17:30:07 -08001682 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001683 LoggerState pi2_logger = MakeLogger(pi2_);
1684
Austin Schuh58646e22021-08-23 23:51:46 -07001685 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1686 << pi2_->realtime_now() << " distributed "
1687 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001688
Austin Schuh58646e22021-08-23 23:51:46 -07001689 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1690 << pi2_->realtime_now() << " distributed "
1691 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001692
Austin Schuh87dd3832021-01-01 23:07:31 -08001693 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001694
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001695 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001696
Austin Schuh87dd3832021-01-01 23:07:31 -08001697 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001698
Austin Schuh8bd96322020-02-13 21:18:22 -08001699 {
1700 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001701 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001702
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001703 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001704 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001705
Austin Schuh87dd3832021-01-01 23:07:31 -08001706 // Make sure we slewed time far enough so that the difference is greater
1707 // than the network delay. This confirms that if we sort incorrectly, it
1708 // would show in the results.
1709 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001710 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001711 -event_loop_factory_.send_delay() -
1712 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001713
Austin Schuh87dd3832021-01-01 23:07:31 -08001714 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001715
Austin Schuh87dd3832021-01-01 23:07:31 -08001716 // And now check that we went far enough the other way to make sure we
1717 // cover both problems.
1718 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001719 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001720 event_loop_factory_.send_delay() +
1721 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001722 }
1723
1724 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001725 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001726 }
1727
Austin Schuh72211ae2021-08-05 14:02:30 -07001728 LogReader reader(
1729 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001730
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001731 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001732 log_reader_factory.set_send_delay(chrono::microseconds(0));
1733
Austin Schuhcde938c2020-02-02 17:30:07 -08001734 const Node *pi1 =
1735 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1736 const Node *pi2 =
1737 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1738
Austin Schuh2f8fd752020-09-01 22:38:28 -07001739 // This sends out the fetched messages and advances time to the start of the
1740 // log file.
1741 reader.Register(&log_reader_factory);
1742
1743 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1744 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1745 LOG(INFO) << "now pi1 "
1746 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1747 LOG(INFO) << "now pi2 "
1748 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1749
Austin Schuhcde938c2020-02-02 17:30:07 -08001750 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001751 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1752 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001753 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1754 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001755 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1756 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001757 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1758
Austin Schuh07676622021-01-21 18:59:17 -08001759 EXPECT_THAT(reader.LoggedNodes(),
1760 ::testing::ElementsAre(
1761 configuration::GetNode(reader.logged_configuration(), pi1),
1762 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001763
1764 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1765
1766 std::unique_ptr<EventLoop> pi1_event_loop =
1767 log_reader_factory.MakeEventLoop("test", pi1);
1768 std::unique_ptr<EventLoop> pi2_event_loop =
1769 log_reader_factory.MakeEventLoop("test", pi2);
1770
1771 int pi1_ping_count = 30;
1772 int pi2_ping_count = 30;
1773 int pi1_pong_count = 30;
1774 int pi2_pong_count = 30;
1775
1776 // Confirm that the ping value matches.
1777 pi1_event_loop->MakeWatcher(
1778 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1779 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1780 << pi1_event_loop->context().monotonic_remote_time << " -> "
1781 << pi1_event_loop->context().monotonic_event_time;
1782 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1783
1784 ++pi1_ping_count;
1785 });
1786 pi2_event_loop->MakeWatcher(
1787 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1788 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1789 << pi2_event_loop->context().monotonic_remote_time << " -> "
1790 << pi2_event_loop->context().monotonic_event_time;
1791 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1792
1793 ++pi2_ping_count;
1794 });
1795
1796 // Confirm that the ping and pong counts both match, and the value also
1797 // matches.
1798 pi1_event_loop->MakeWatcher(
1799 "/test", [&pi1_event_loop, &pi1_ping_count,
1800 &pi1_pong_count](const examples::Pong &pong) {
1801 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1802 << pi1_event_loop->context().monotonic_remote_time << " -> "
1803 << pi1_event_loop->context().monotonic_event_time;
1804
1805 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1806 ++pi1_pong_count;
1807 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1808 });
1809 pi2_event_loop->MakeWatcher(
1810 "/test", [&pi2_event_loop, &pi2_ping_count,
1811 &pi2_pong_count](const examples::Pong &pong) {
1812 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1813 << pi2_event_loop->context().monotonic_remote_time << " -> "
1814 << pi2_event_loop->context().monotonic_event_time;
1815
1816 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1817 ++pi2_pong_count;
1818 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1819 });
1820
1821 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001822 EXPECT_EQ(pi1_ping_count, 6030);
1823 EXPECT_EQ(pi2_ping_count, 6030);
1824 EXPECT_EQ(pi1_pong_count, 6030);
1825 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001826
1827 reader.Deregister();
1828}
1829
Austin Schuh5212cad2020-09-09 23:12:09 -07001830// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001831TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001832 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001833 // Make a bunch of parts.
1834 {
1835 LoggerState pi1_logger = MakeLogger(pi1_);
1836 LoggerState pi2_logger = MakeLogger(pi2_);
1837
1838 event_loop_factory_.RunFor(chrono::milliseconds(95));
1839
1840 StartLogger(&pi1_logger);
1841 StartLogger(&pi2_logger);
1842
1843 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1844 }
1845
Austin Schuh11d43732020-09-21 17:28:30 -07001846 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001847 VerifyParts(sorted_parts);
1848}
Austin Schuh11d43732020-09-21 17:28:30 -07001849
Austin Schuh3bd4c402020-11-06 18:19:06 -08001850// Tests that we can sort a bunch of parts with an empty part. We should ignore
1851// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001852TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001853 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001854 // Make a bunch of parts.
1855 {
1856 LoggerState pi1_logger = MakeLogger(pi1_);
1857 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001858
Austin Schuh3bd4c402020-11-06 18:19:06 -08001859 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001860
Austin Schuh3bd4c402020-11-06 18:19:06 -08001861 StartLogger(&pi1_logger);
1862 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001863
Austin Schuh3bd4c402020-11-06 18:19:06 -08001864 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001865 }
1866
Austin Schuh3bd4c402020-11-06 18:19:06 -08001867 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001868 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001869
Austin Schuh3bd4c402020-11-06 18:19:06 -08001870 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1871 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001872
Austin Schuh3bd4c402020-11-06 18:19:06 -08001873 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1874 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001875}
1876
James Kuszmauldd0a5042021-10-28 23:38:04 -07001877// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08001878// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001879TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08001880 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08001881 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001882 // Make a bunch of parts.
1883 {
1884 LoggerState pi1_logger = MakeLogger(pi1_);
1885 LoggerState pi2_logger = MakeLogger(pi2_);
1886
1887 event_loop_factory_.RunFor(chrono::milliseconds(95));
1888
James Kuszmauldd0a5042021-10-28 23:38:04 -07001889 StartLogger(&pi1_logger);
1890 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001891
1892 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08001893
1894 pi1_logger.AppendAllFilenames(&actual_filenames);
1895 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001896 }
1897
Austin Schuhbfe6c572022-01-27 20:48:20 -08001898 ASSERT_THAT(actual_filenames,
1899 ::testing::UnorderedElementsAreArray(logfiles_));
1900
Austin Schuh3bd4c402020-11-06 18:19:06 -08001901 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001902 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1903 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08001904 ::std::string compressed_contents =
Austin Schuhbfe6c572022-01-27 20:48:20 -08001905 aos::util::ReadFileToStringOrDie(logfiles_[4]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001906
1907 aos::util::WriteStringToFileOrDie(
Austin Schuhbfe6c572022-01-27 20:48:20 -08001908 logfiles_[4],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001909 compressed_contents.substr(0, compressed_contents.size() - 100));
1910
1911 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1912 VerifyParts(sorted_parts);
1913}
Austin Schuh3bd4c402020-11-06 18:19:06 -08001914
Austin Schuh01b4c352020-09-21 23:09:39 -07001915// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001916TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001917 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001918 {
1919 LoggerState pi1_logger = MakeLogger(pi1_);
1920 LoggerState pi2_logger = MakeLogger(pi2_);
1921
1922 event_loop_factory_.RunFor(chrono::milliseconds(95));
1923
1924 StartLogger(&pi1_logger);
1925 StartLogger(&pi2_logger);
1926
1927 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1928 }
1929
Austin Schuh287d43d2020-12-04 20:19:33 -08001930 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001931
1932 // Remap just on pi1.
1933 reader.RemapLoggedChannel<aos::timing::Report>(
1934 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1935
1936 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1937 log_reader_factory.set_send_delay(chrono::microseconds(0));
1938
Austin Schuh1c227352021-09-17 12:53:54 -07001939 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1940 ASSERT_EQ(remapped_channels.size(), 1u);
1941 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1942 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1943
Austin Schuh01b4c352020-09-21 23:09:39 -07001944 reader.Register(&log_reader_factory);
1945
1946 const Node *pi1 =
1947 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1948 const Node *pi2 =
1949 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1950
1951 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1952 // else should have moved.
1953 std::unique_ptr<EventLoop> pi1_event_loop =
1954 log_reader_factory.MakeEventLoop("test", pi1);
1955 pi1_event_loop->SkipTimingReport();
1956 std::unique_ptr<EventLoop> full_pi1_event_loop =
1957 log_reader_factory.MakeEventLoop("test", pi1);
1958 full_pi1_event_loop->SkipTimingReport();
1959 std::unique_ptr<EventLoop> pi2_event_loop =
1960 log_reader_factory.MakeEventLoop("test", pi2);
1961 pi2_event_loop->SkipTimingReport();
1962
1963 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1964 "/aos");
1965 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1966 full_pi1_event_loop.get(), "/pi1/aos");
1967 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1968 pi1_event_loop.get(), "/original/aos");
1969 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1970 full_pi1_event_loop.get(), "/original/pi1/aos");
1971 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1972 "/aos");
1973
1974 log_reader_factory.Run();
1975
1976 EXPECT_EQ(pi1_timing_report.count(), 0u);
1977 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1978 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1979 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1980 EXPECT_NE(pi2_timing_report.count(), 0u);
1981
1982 reader.Deregister();
1983}
1984
Austin Schuh006a9f52021-04-07 16:24:18 -07001985// Tests that we can remap a forwarded channel as well.
1986TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1987 time_converter_.StartEqual();
1988 {
1989 LoggerState pi1_logger = MakeLogger(pi1_);
1990 LoggerState pi2_logger = MakeLogger(pi2_);
1991
1992 event_loop_factory_.RunFor(chrono::milliseconds(95));
1993
1994 StartLogger(&pi1_logger);
1995 StartLogger(&pi2_logger);
1996
1997 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1998 }
1999
2000 LogReader reader(SortParts(logfiles_));
2001
2002 reader.RemapLoggedChannel<examples::Ping>("/test");
2003
2004 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2005 log_reader_factory.set_send_delay(chrono::microseconds(0));
2006
2007 reader.Register(&log_reader_factory);
2008
2009 const Node *pi1 =
2010 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2011 const Node *pi2 =
2012 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2013
2014 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
2015 // else should have moved.
2016 std::unique_ptr<EventLoop> pi1_event_loop =
2017 log_reader_factory.MakeEventLoop("test", pi1);
2018 pi1_event_loop->SkipTimingReport();
2019 std::unique_ptr<EventLoop> full_pi1_event_loop =
2020 log_reader_factory.MakeEventLoop("test", pi1);
2021 full_pi1_event_loop->SkipTimingReport();
2022 std::unique_ptr<EventLoop> pi2_event_loop =
2023 log_reader_factory.MakeEventLoop("test", pi2);
2024 pi2_event_loop->SkipTimingReport();
2025
2026 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
2027 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
2028 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
2029 "/original/test");
2030 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
2031 "/original/test");
2032
2033 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2034 pi1_original_ping_timestamp;
2035 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
2036 pi1_ping_timestamp;
2037 if (!shared()) {
2038 pi1_original_ping_timestamp =
2039 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2040 pi1_event_loop.get(),
2041 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
2042 pi1_ping_timestamp =
2043 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
2044 pi1_event_loop.get(),
2045 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
2046 }
2047
2048 log_reader_factory.Run();
2049
2050 EXPECT_EQ(pi1_ping.count(), 0u);
2051 EXPECT_EQ(pi2_ping.count(), 0u);
2052 EXPECT_NE(pi1_original_ping.count(), 0u);
2053 EXPECT_NE(pi2_original_ping.count(), 0u);
2054 if (!shared()) {
2055 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
2056 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
2057 }
2058
2059 reader.Deregister();
2060}
2061
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002062// Tests that we properly recreate forwarded timestamps when replaying a log.
2063// This should be enough that we can then re-run the logger and get a valid log
2064// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002065TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002066 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002067 {
2068 LoggerState pi1_logger = MakeLogger(pi1_);
2069 LoggerState pi2_logger = MakeLogger(pi2_);
2070
2071 event_loop_factory_.RunFor(chrono::milliseconds(95));
2072
2073 StartLogger(&pi1_logger);
2074 StartLogger(&pi2_logger);
2075
2076 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2077 }
2078
Austin Schuh287d43d2020-12-04 20:19:33 -08002079 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002080
2081 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2082 log_reader_factory.set_send_delay(chrono::microseconds(0));
2083
2084 // This sends out the fetched messages and advances time to the start of the
2085 // log file.
2086 reader.Register(&log_reader_factory);
2087
2088 const Node *pi1 =
2089 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2090 const Node *pi2 =
2091 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2092
2093 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2094 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2095 LOG(INFO) << "now pi1 "
2096 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2097 LOG(INFO) << "now pi2 "
2098 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2099
Austin Schuh07676622021-01-21 18:59:17 -08002100 EXPECT_THAT(reader.LoggedNodes(),
2101 ::testing::ElementsAre(
2102 configuration::GetNode(reader.logged_configuration(), pi1),
2103 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002104
2105 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2106
2107 std::unique_ptr<EventLoop> pi1_event_loop =
2108 log_reader_factory.MakeEventLoop("test", pi1);
2109 std::unique_ptr<EventLoop> pi2_event_loop =
2110 log_reader_factory.MakeEventLoop("test", pi2);
2111
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002112 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2113 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2114 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2115 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2116
2117 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2118 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2119 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2120 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2121
2122 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2123 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2124 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2125 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2126
2127 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2128 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2129 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2130 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2131
2132 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2133 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2134 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2135 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2136
2137 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2138 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2139 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2140 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2141
Austin Schuh969cd602021-01-03 00:09:45 -08002142 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002143 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002144
Austin Schuh61e973f2021-02-21 21:43:56 -08002145 for (std::pair<int, std::string> channel :
2146 shared()
2147 ? std::vector<
2148 std::pair<int, std::string>>{{-1,
2149 "/aos/remote_timestamps/pi2"}}
2150 : std::vector<std::pair<int, std::string>>{
2151 {pi1_timestamp_channel,
2152 "/aos/remote_timestamps/pi2/pi1/aos/"
2153 "aos-message_bridge-Timestamp"},
2154 {ping_timestamp_channel,
2155 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2156 pi1_event_loop->MakeWatcher(
2157 channel.second,
2158 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2159 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2160 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2161 &ping_on_pi2_fetcher, network_delay, send_delay,
2162 channel_index = channel.first](const RemoteMessage &header) {
2163 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2164 chrono::nanoseconds(header.monotonic_sent_time()));
2165 const aos::realtime_clock::time_point header_realtime_sent_time(
2166 chrono::nanoseconds(header.realtime_sent_time()));
2167 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2168 chrono::nanoseconds(header.monotonic_remote_time()));
2169 const aos::realtime_clock::time_point header_realtime_remote_time(
2170 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002171
Austin Schuh61e973f2021-02-21 21:43:56 -08002172 if (channel_index != -1) {
2173 ASSERT_EQ(channel_index, header.channel_index());
2174 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002175
Austin Schuh61e973f2021-02-21 21:43:56 -08002176 const Context *pi1_context = nullptr;
2177 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002178
Austin Schuh61e973f2021-02-21 21:43:56 -08002179 if (header.channel_index() == pi1_timestamp_channel) {
2180 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2181 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2182 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2183 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2184 } else if (header.channel_index() == ping_timestamp_channel) {
2185 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2186 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2187 pi1_context = &ping_on_pi1_fetcher.context();
2188 pi2_context = &ping_on_pi2_fetcher.context();
2189 } else {
2190 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2191 << configuration::CleanedChannelToString(
2192 pi1_event_loop->configuration()->channels()->Get(
2193 header.channel_index()));
2194 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002195
Austin Schuh61e973f2021-02-21 21:43:56 -08002196 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002197 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2198 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002199
Austin Schuh61e973f2021-02-21 21:43:56 -08002200 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2201 EXPECT_EQ(pi2_context->remote_queue_index,
2202 header.remote_queue_index());
2203 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002204
Austin Schuh61e973f2021-02-21 21:43:56 -08002205 EXPECT_EQ(pi2_context->monotonic_event_time,
2206 header_monotonic_sent_time);
2207 EXPECT_EQ(pi2_context->realtime_event_time,
2208 header_realtime_sent_time);
2209 EXPECT_EQ(pi2_context->realtime_remote_time,
2210 header_realtime_remote_time);
2211 EXPECT_EQ(pi2_context->monotonic_remote_time,
2212 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002213
Austin Schuh61e973f2021-02-21 21:43:56 -08002214 EXPECT_EQ(pi1_context->realtime_event_time,
2215 header_realtime_remote_time);
2216 EXPECT_EQ(pi1_context->monotonic_event_time,
2217 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002218
Austin Schuh61e973f2021-02-21 21:43:56 -08002219 // Time estimation isn't perfect, but we know the clocks were
2220 // identical when logged, so we know when this should have come back.
2221 // Confirm we got it when we expected.
2222 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2223 pi1_context->monotonic_event_time + 2 * network_delay +
2224 send_delay);
2225 });
2226 }
2227 for (std::pair<int, std::string> channel :
2228 shared()
2229 ? std::vector<
2230 std::pair<int, std::string>>{{-1,
2231 "/aos/remote_timestamps/pi1"}}
2232 : std::vector<std::pair<int, std::string>>{
2233 {pi2_timestamp_channel,
2234 "/aos/remote_timestamps/pi1/pi2/aos/"
2235 "aos-message_bridge-Timestamp"}}) {
2236 pi2_event_loop->MakeWatcher(
2237 channel.second,
2238 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2239 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2240 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2241 &pong_on_pi1_fetcher, network_delay, send_delay,
2242 channel_index = channel.first](const RemoteMessage &header) {
2243 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2244 chrono::nanoseconds(header.monotonic_sent_time()));
2245 const aos::realtime_clock::time_point header_realtime_sent_time(
2246 chrono::nanoseconds(header.realtime_sent_time()));
2247 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2248 chrono::nanoseconds(header.monotonic_remote_time()));
2249 const aos::realtime_clock::time_point header_realtime_remote_time(
2250 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002251
Austin Schuh61e973f2021-02-21 21:43:56 -08002252 if (channel_index != -1) {
2253 ASSERT_EQ(channel_index, header.channel_index());
2254 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002255
Austin Schuh61e973f2021-02-21 21:43:56 -08002256 const Context *pi2_context = nullptr;
2257 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002258
Austin Schuh61e973f2021-02-21 21:43:56 -08002259 if (header.channel_index() == pi2_timestamp_channel) {
2260 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2261 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2262 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2263 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2264 } else if (header.channel_index() == pong_timestamp_channel) {
2265 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2266 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2267 pi2_context = &pong_on_pi2_fetcher.context();
2268 pi1_context = &pong_on_pi1_fetcher.context();
2269 } else {
2270 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2271 << configuration::CleanedChannelToString(
2272 pi2_event_loop->configuration()->channels()->Get(
2273 header.channel_index()));
2274 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002275
Austin Schuh61e973f2021-02-21 21:43:56 -08002276 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002277 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2278 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002279
Austin Schuh61e973f2021-02-21 21:43:56 -08002280 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2281 EXPECT_EQ(pi1_context->remote_queue_index,
2282 header.remote_queue_index());
2283 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002284
Austin Schuh61e973f2021-02-21 21:43:56 -08002285 EXPECT_EQ(pi1_context->monotonic_event_time,
2286 header_monotonic_sent_time);
2287 EXPECT_EQ(pi1_context->realtime_event_time,
2288 header_realtime_sent_time);
2289 EXPECT_EQ(pi1_context->realtime_remote_time,
2290 header_realtime_remote_time);
2291 EXPECT_EQ(pi1_context->monotonic_remote_time,
2292 header_monotonic_remote_time);
2293
2294 EXPECT_EQ(pi2_context->realtime_event_time,
2295 header_realtime_remote_time);
2296 EXPECT_EQ(pi2_context->monotonic_event_time,
2297 header_monotonic_remote_time);
2298
2299 // Time estimation isn't perfect, but we know the clocks were
2300 // identical when logged, so we know when this should have come back.
2301 // Confirm we got it when we expected.
2302 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2303 pi2_context->monotonic_event_time + 2 * network_delay +
2304 send_delay);
2305 });
2306 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002307
2308 // And confirm we can re-create a log again, while checking the contents.
2309 {
2310 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002311 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002312 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002313 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002314
Austin Schuh25b46712021-01-03 00:04:38 -08002315 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2316 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002317
2318 log_reader_factory.Run();
2319 }
2320
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002321 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002322
2323 // And verify that we can run the LogReader over the relogged files without
2324 // hitting any fatal errors.
2325 {
2326 LogReader relogged_reader(SortParts(
2327 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2328 relogged_reader.Register();
2329
2330 relogged_reader.event_loop_factory()->Run();
2331 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002332}
2333
Austin Schuh315b96b2020-12-11 21:21:12 -08002334// Tests that we properly populate and extract the logger_start time by setting
2335// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002336TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuhf5f99f32022-02-07 20:05:37 -08002337 std::vector<std::string> actual_filenames;
Austin Schuh87dd3832021-01-01 23:07:31 -08002338 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002339 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002340 {
2341 LoggerState pi1_logger = MakeLogger(pi1_);
2342 LoggerState pi2_logger = MakeLogger(pi2_);
2343
Austin Schuh315b96b2020-12-11 21:21:12 -08002344 StartLogger(&pi1_logger);
2345 StartLogger(&pi2_logger);
2346
2347 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002348
2349 pi1_logger.AppendAllFilenames(&actual_filenames);
2350 pi2_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002351 }
2352
Austin Schuhf5f99f32022-02-07 20:05:37 -08002353 ASSERT_THAT(actual_filenames,
2354 ::testing::UnorderedElementsAreArray(logfiles_));
2355
Austin Schuh315b96b2020-12-11 21:21:12 -08002356 for (const LogFile &log_file : SortParts(logfiles_)) {
2357 for (const LogParts &log_part : log_file.parts) {
2358 if (log_part.node == log_file.logger_node) {
2359 EXPECT_EQ(log_part.logger_monotonic_start_time,
2360 aos::monotonic_clock::min_time);
2361 EXPECT_EQ(log_part.logger_realtime_start_time,
2362 aos::realtime_clock::min_time);
2363 } else {
2364 const chrono::seconds offset = log_file.logger_node == "pi1"
2365 ? -chrono::seconds(1000)
2366 : chrono::seconds(1000);
2367 EXPECT_EQ(log_part.logger_monotonic_start_time,
2368 log_part.monotonic_start_time + offset);
2369 EXPECT_EQ(log_part.logger_realtime_start_time,
2370 log_file.realtime_start_time +
2371 (log_part.logger_monotonic_start_time -
2372 log_file.monotonic_start_time));
2373 }
2374 }
2375 }
2376}
2377
Austin Schuh6bb8a822021-03-31 23:04:39 -07002378// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002379TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002380 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2381 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002382 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002383 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002384 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2385 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2386 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2387 LoggerState pi1_logger = MakeLogger(pi1_);
2388 LoggerState pi2_logger = MakeLogger(pi2_);
2389
2390 StartLogger(&pi1_logger);
2391 StartLogger(&pi2_logger);
2392
2393 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2394 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2395 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2396 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2397 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2398 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2399 for (auto &file : logfiles_) {
2400 struct stat s;
2401 EXPECT_EQ(0, stat(file.c_str(), &s));
2402 }
2403}
2404
2405// Test that renaming the file base dies.
2406TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2407 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002408 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002409 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002410 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2411 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2412 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2413 LoggerState pi1_logger = MakeLogger(pi1_);
2414 StartLogger(&pi1_logger);
2415 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2416 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2417 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2418 "Rename of file base from");
2419}
2420
Austin Schuh8bd96322020-02-13 21:18:22 -08002421// TODO(austin): We can write a test which recreates a logfile and confirms that
2422// we get it back. That is the ultimate test.
2423
Austin Schuh315b96b2020-12-11 21:21:12 -08002424// Tests that we properly recreate forwarded timestamps when replaying a log.
2425// This should be enough that we can then re-run the logger and get a valid log
2426// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002427TEST_P(MultinodeLoggerTest, RemoteReboot) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002428 std::vector<std::string> actual_filenames;
2429
Austin Schuh58646e22021-08-23 23:51:46 -07002430 const UUID pi1_boot0 = UUID::Random();
2431 const UUID pi2_boot0 = UUID::Random();
2432 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002433 {
Austin Schuh58646e22021-08-23 23:51:46 -07002434 CHECK_EQ(pi1_index_, 0u);
2435 CHECK_EQ(pi2_index_, 1u);
2436
2437 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2438 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2439 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2440
2441 time_converter_.AddNextTimestamp(
2442 distributed_clock::epoch(),
2443 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2444 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2445 time_converter_.AddNextTimestamp(
2446 distributed_clock::epoch() + reboot_time,
2447 {BootTimestamp::epoch() + reboot_time,
2448 BootTimestamp{
2449 .boot = 1,
2450 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2451 }
2452
2453 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002454 LoggerState pi1_logger = MakeLogger(pi1_);
2455
2456 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002457 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2458 pi1_boot0);
2459 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2460 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002461
2462 StartLogger(&pi1_logger);
2463
2464 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2465
Austin Schuh58646e22021-08-23 23:51:46 -07002466 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002467
2468 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002469 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2470 pi1_boot0);
2471 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2472 pi2_boot1);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002473
2474 pi1_logger.AppendAllFilenames(&actual_filenames);
Austin Schuh315b96b2020-12-11 21:21:12 -08002475 }
2476
Austin Schuhbfe6c572022-01-27 20:48:20 -08002477 std::sort(actual_filenames.begin(), actual_filenames.end());
2478 std::sort(pi1_reboot_logfiles_.begin(), pi1_reboot_logfiles_.end());
2479 ASSERT_THAT(actual_filenames,
2480 ::testing::UnorderedElementsAreArray(pi1_reboot_logfiles_));
2481
Austin Schuh72211ae2021-08-05 14:02:30 -07002482 // Confirm that our new oldest timestamps properly update as we reboot and
2483 // rotate.
2484 for (const std::string &file : pi1_reboot_logfiles_) {
2485 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2486 ReadHeader(file);
2487 CHECK(log_header);
2488 if (log_header->message().has_configuration()) {
2489 continue;
2490 }
2491
Austin Schuh58646e22021-08-23 23:51:46 -07002492 const monotonic_clock::time_point monotonic_start_time =
2493 monotonic_clock::time_point(
2494 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2495 const UUID source_node_boot_uuid = UUID::FromString(
2496 log_header->message().source_node_boot_uuid()->string_view());
2497
Austin Schuh72211ae2021-08-05 14:02:30 -07002498 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002499 // The remote message channel should rotate later and have more parts.
2500 // This only is true on the log files with shared remote messages.
2501 //
2502 // TODO(austin): I'm not the most thrilled with this test pattern... It
2503 // feels brittle in a different way.
Austin Schuhbfe6c572022-01-27 20:48:20 -08002504 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos ||
2505 !shared()) {
Austin Schuh01f3b392022-01-25 20:03:09 -08002506 switch (log_header->message().parts_index()) {
2507 case 0:
2508 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2509 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2510 break;
2511 case 1:
2512 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2513 ASSERT_EQ(monotonic_start_time,
2514 monotonic_clock::epoch() + chrono::seconds(1));
2515 break;
2516 case 2:
2517 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2518 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2519 break;
2520 case 3:
2521 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2522 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2523 chrono::nanoseconds(2322999462))
2524 << " on " << file;
2525 break;
2526 default:
2527 FAIL();
2528 break;
2529 }
2530 } else {
2531 switch (log_header->message().parts_index()) {
2532 case 0:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002533 case 1:
Austin Schuh01f3b392022-01-25 20:03:09 -08002534 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2535 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2536 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002537 case 2:
Austin Schuh01f3b392022-01-25 20:03:09 -08002538 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2539 ASSERT_EQ(monotonic_start_time,
2540 monotonic_clock::epoch() + chrono::seconds(1));
2541 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08002542 case 3:
Austin Schuhbfe6c572022-01-27 20:48:20 -08002543 case 4:
Austin Schuh01f3b392022-01-25 20:03:09 -08002544 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2545 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2546 break;
Austin Schuhbfe6c572022-01-27 20:48:20 -08002547 case 5:
Austin Schuh01f3b392022-01-25 20:03:09 -08002548 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2549 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2550 chrono::nanoseconds(2322999462))
2551 << " on " << file;
2552 break;
2553 default:
2554 FAIL();
2555 break;
2556 }
Austin Schuh58646e22021-08-23 23:51:46 -07002557 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002558 continue;
2559 }
2560 SCOPED_TRACE(file);
2561 SCOPED_TRACE(aos::FlatbufferToJson(
2562 *log_header, {.multi_line = true, .max_vector_size = 100}));
2563 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2564 ASSERT_EQ(
2565 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2566 EXPECT_EQ(
2567 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2568 monotonic_clock::max_time.time_since_epoch().count());
2569 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2570 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2571 2u);
2572 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2573 monotonic_clock::max_time.time_since_epoch().count());
2574 ASSERT_TRUE(log_header->message()
2575 .has_oldest_remote_unreliable_monotonic_timestamps());
2576 ASSERT_EQ(log_header->message()
2577 .oldest_remote_unreliable_monotonic_timestamps()
2578 ->size(),
2579 2u);
2580 EXPECT_EQ(log_header->message()
2581 .oldest_remote_unreliable_monotonic_timestamps()
2582 ->Get(0),
2583 monotonic_clock::max_time.time_since_epoch().count());
2584 ASSERT_TRUE(log_header->message()
2585 .has_oldest_local_unreliable_monotonic_timestamps());
2586 ASSERT_EQ(log_header->message()
2587 .oldest_local_unreliable_monotonic_timestamps()
2588 ->size(),
2589 2u);
2590 EXPECT_EQ(log_header->message()
2591 .oldest_local_unreliable_monotonic_timestamps()
2592 ->Get(0),
2593 monotonic_clock::max_time.time_since_epoch().count());
2594
2595 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2596 monotonic_clock::time_point(chrono::nanoseconds(
2597 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2598 1)));
2599 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2600 monotonic_clock::time_point(chrono::nanoseconds(
2601 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2602 const monotonic_clock::time_point
2603 oldest_remote_unreliable_monotonic_timestamps =
2604 monotonic_clock::time_point(chrono::nanoseconds(
2605 log_header->message()
2606 .oldest_remote_unreliable_monotonic_timestamps()
2607 ->Get(1)));
2608 const monotonic_clock::time_point
2609 oldest_local_unreliable_monotonic_timestamps =
2610 monotonic_clock::time_point(chrono::nanoseconds(
2611 log_header->message()
2612 .oldest_local_unreliable_monotonic_timestamps()
2613 ->Get(1)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002614 const monotonic_clock::time_point
2615 oldest_remote_reliable_monotonic_timestamps =
2616 monotonic_clock::time_point(chrono::nanoseconds(
2617 log_header->message()
2618 .oldest_remote_reliable_monotonic_timestamps()
2619 ->Get(1)));
2620 const monotonic_clock::time_point
2621 oldest_local_reliable_monotonic_timestamps =
2622 monotonic_clock::time_point(chrono::nanoseconds(
2623 log_header->message()
2624 .oldest_local_reliable_monotonic_timestamps()
2625 ->Get(1)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002626 const monotonic_clock::time_point
2627 oldest_logger_remote_unreliable_monotonic_timestamps =
2628 monotonic_clock::time_point(chrono::nanoseconds(
2629 log_header->message()
2630 .oldest_logger_remote_unreliable_monotonic_timestamps()
2631 ->Get(0)));
2632 const monotonic_clock::time_point
2633 oldest_logger_local_unreliable_monotonic_timestamps =
2634 monotonic_clock::time_point(chrono::nanoseconds(
2635 log_header->message()
2636 .oldest_logger_local_unreliable_monotonic_timestamps()
2637 ->Get(0)));
2638 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2639 monotonic_clock::max_time);
2640 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2641 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002642 switch (log_header->message().parts_index()) {
2643 case 0:
2644 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2645 monotonic_clock::max_time);
2646 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2647 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2648 monotonic_clock::max_time);
2649 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2650 monotonic_clock::max_time);
Austin Schuhbfe6c572022-01-27 20:48:20 -08002651 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2652 monotonic_clock::max_time);
2653 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2654 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002655 break;
2656 case 1:
2657 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2658 monotonic_clock::time_point(chrono::microseconds(90200)));
2659 EXPECT_EQ(oldest_local_monotonic_timestamps,
2660 monotonic_clock::time_point(chrono::microseconds(90350)));
2661 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2662 monotonic_clock::time_point(chrono::microseconds(90200)));
2663 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2664 monotonic_clock::time_point(chrono::microseconds(90350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002665 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2666 monotonic_clock::max_time);
2667 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2668 monotonic_clock::max_time);
Austin Schuh72211ae2021-08-05 14:02:30 -07002669 break;
2670 case 2:
2671 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuhbfe6c572022-01-27 20:48:20 -08002672 monotonic_clock::time_point(chrono::microseconds(90200)))
2673 << file;
2674 EXPECT_EQ(oldest_local_monotonic_timestamps,
2675 monotonic_clock::time_point(chrono::microseconds(90350)))
2676 << file;
2677 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2678 monotonic_clock::time_point(chrono::microseconds(90200)))
2679 << file;
2680 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2681 monotonic_clock::time_point(chrono::microseconds(90350)))
2682 << file;
2683 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2684 monotonic_clock::time_point(chrono::microseconds(100000)))
2685 << file;
2686 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2687 monotonic_clock::time_point(chrono::microseconds(100150)))
2688 << file;
2689 break;
2690 case 3:
2691 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002692 monotonic_clock::time_point(chrono::milliseconds(1323) +
2693 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002694 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002695 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002696 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002697 monotonic_clock::time_point(chrono::milliseconds(1323) +
2698 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002699 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2700 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002701 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2702 monotonic_clock::max_time)
2703 << file;
2704 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2705 monotonic_clock::max_time)
2706 << file;
2707 break;
2708 case 4:
2709 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2710 monotonic_clock::time_point(chrono::milliseconds(1323) +
2711 chrono::microseconds(200)));
2712 EXPECT_EQ(oldest_local_monotonic_timestamps,
2713 monotonic_clock::time_point(chrono::microseconds(10100350)));
2714 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2715 monotonic_clock::time_point(chrono::milliseconds(1323) +
2716 chrono::microseconds(200)));
2717 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2718 monotonic_clock::time_point(chrono::microseconds(10100350)));
2719 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2720 monotonic_clock::time_point(chrono::microseconds(1423000)))
2721 << file;
2722 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2723 monotonic_clock::time_point(chrono::microseconds(10200150)))
2724 << file;
Austin Schuh72211ae2021-08-05 14:02:30 -07002725 break;
2726 default:
2727 FAIL();
2728 break;
2729 }
2730 }
2731
Austin Schuh315b96b2020-12-11 21:21:12 -08002732 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002733 {
2734 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002735
Austin Schuh58646e22021-08-23 23:51:46 -07002736 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2737 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002738
Austin Schuh58646e22021-08-23 23:51:46 -07002739 // This sends out the fetched messages and advances time to the start of
2740 // the log file.
2741 reader.Register(&log_reader_factory);
2742
2743 log_reader_factory.Run();
2744
2745 reader.Deregister();
2746 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002747}
2748
Austin Schuh5e14d842022-01-21 12:02:15 -08002749// Tests that we can sort a log which only has timestamps from the remote
2750// because the local message_bridge_client failed to connect.
2751TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
2752 const UUID pi1_boot0 = UUID::Random();
2753 const UUID pi2_boot0 = UUID::Random();
2754 const UUID pi2_boot1 = UUID::Random();
2755 {
2756 CHECK_EQ(pi1_index_, 0u);
2757 CHECK_EQ(pi2_index_, 1u);
2758
2759 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2760 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2761 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2762
2763 time_converter_.AddNextTimestamp(
2764 distributed_clock::epoch(),
2765 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2766 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2767 time_converter_.AddNextTimestamp(
2768 distributed_clock::epoch() + reboot_time,
2769 {BootTimestamp::epoch() + reboot_time,
2770 BootTimestamp{
2771 .boot = 1,
2772 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2773 }
2774 pi2_->Disconnect(pi1_->node());
2775
2776 std::vector<std::string> filenames;
2777 {
2778 LoggerState pi1_logger = MakeLogger(pi1_);
2779
2780 event_loop_factory_.RunFor(chrono::milliseconds(95));
2781 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2782 pi1_boot0);
2783 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2784 pi2_boot0);
2785
2786 StartLogger(&pi1_logger);
2787
2788 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2789
2790 VLOG(1) << "Reboot now!";
2791
2792 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2793 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2794 pi1_boot0);
2795 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2796 pi2_boot1);
2797 pi1_logger.AppendAllFilenames(&filenames);
2798 }
2799
Austin Schuhbfe6c572022-01-27 20:48:20 -08002800 std::sort(filenames.begin(), filenames.end());
2801
Austin Schuh5e14d842022-01-21 12:02:15 -08002802 // Confirm that our new oldest timestamps properly update as we reboot and
2803 // rotate.
2804 size_t timestamp_file_count = 0;
2805 for (const std::string &file : filenames) {
2806 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2807 ReadHeader(file);
2808 CHECK(log_header);
2809
2810 if (log_header->message().has_configuration()) {
2811 continue;
2812 }
2813
2814 const monotonic_clock::time_point monotonic_start_time =
2815 monotonic_clock::time_point(
2816 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2817 const UUID source_node_boot_uuid = UUID::FromString(
2818 log_header->message().source_node_boot_uuid()->string_view());
2819
2820 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2821 ASSERT_EQ(
2822 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2823 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2824 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2825 2u);
2826 ASSERT_TRUE(log_header->message()
2827 .has_oldest_remote_unreliable_monotonic_timestamps());
2828 ASSERT_EQ(log_header->message()
2829 .oldest_remote_unreliable_monotonic_timestamps()
2830 ->size(),
2831 2u);
2832 ASSERT_TRUE(log_header->message()
2833 .has_oldest_local_unreliable_monotonic_timestamps());
2834 ASSERT_EQ(log_header->message()
2835 .oldest_local_unreliable_monotonic_timestamps()
2836 ->size(),
2837 2u);
Austin Schuhf5f99f32022-02-07 20:05:37 -08002838 ASSERT_TRUE(log_header->message()
2839 .has_oldest_remote_reliable_monotonic_timestamps());
2840 ASSERT_EQ(log_header->message()
2841 .oldest_remote_reliable_monotonic_timestamps()
2842 ->size(),
2843 2u);
2844 ASSERT_TRUE(log_header->message()
2845 .has_oldest_local_reliable_monotonic_timestamps());
2846 ASSERT_EQ(log_header->message()
2847 .oldest_local_reliable_monotonic_timestamps()
2848 ->size(),
2849 2u);
2850
2851 ASSERT_TRUE(
2852 log_header->message()
2853 .has_oldest_logger_remote_unreliable_monotonic_timestamps());
2854 ASSERT_EQ(log_header->message()
2855 .oldest_logger_remote_unreliable_monotonic_timestamps()
2856 ->size(),
2857 2u);
2858 ASSERT_TRUE(log_header->message()
2859 .has_oldest_logger_local_unreliable_monotonic_timestamps());
2860 ASSERT_EQ(log_header->message()
2861 .oldest_logger_local_unreliable_monotonic_timestamps()
2862 ->size(),
2863 2u);
Austin Schuh5e14d842022-01-21 12:02:15 -08002864
2865 if (log_header->message().node()->name()->string_view() != "pi1") {
2866 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
2867 std::string::npos);
2868
2869 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2870 ReadNthMessage(file, 0);
2871 CHECK(msg);
2872
2873 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2874 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2875
2876 const monotonic_clock::time_point
2877 expected_oldest_local_monotonic_timestamps(
2878 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2879 const monotonic_clock::time_point
2880 expected_oldest_remote_monotonic_timestamps(
2881 chrono::nanoseconds(msg->message().monotonic_remote_time()));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002882 const monotonic_clock::time_point
2883 expected_oldest_timestamp_monotonic_timestamps(
2884 chrono::nanoseconds(msg->message().monotonic_timestamp_time()));
Austin Schuh5e14d842022-01-21 12:02:15 -08002885
2886 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2887 monotonic_clock::min_time);
2888 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2889 monotonic_clock::min_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08002890 EXPECT_NE(expected_oldest_timestamp_monotonic_timestamps,
2891 monotonic_clock::min_time);
Austin Schuh5e14d842022-01-21 12:02:15 -08002892
2893 ++timestamp_file_count;
2894 // Since the log file is from the perspective of the other node,
2895 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2896 monotonic_clock::time_point(chrono::nanoseconds(
2897 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2898 0)));
2899 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2900 monotonic_clock::time_point(chrono::nanoseconds(
2901 log_header->message().oldest_local_monotonic_timestamps()->Get(
2902 0)));
2903 const monotonic_clock::time_point
2904 oldest_remote_unreliable_monotonic_timestamps =
2905 monotonic_clock::time_point(chrono::nanoseconds(
2906 log_header->message()
2907 .oldest_remote_unreliable_monotonic_timestamps()
2908 ->Get(0)));
2909 const monotonic_clock::time_point
2910 oldest_local_unreliable_monotonic_timestamps =
2911 monotonic_clock::time_point(chrono::nanoseconds(
2912 log_header->message()
2913 .oldest_local_unreliable_monotonic_timestamps()
2914 ->Get(0)));
Austin Schuhbfe6c572022-01-27 20:48:20 -08002915 const monotonic_clock::time_point
2916 oldest_remote_reliable_monotonic_timestamps =
2917 monotonic_clock::time_point(chrono::nanoseconds(
2918 log_header->message()
2919 .oldest_remote_reliable_monotonic_timestamps()
2920 ->Get(0)));
2921 const monotonic_clock::time_point
2922 oldest_local_reliable_monotonic_timestamps =
2923 monotonic_clock::time_point(chrono::nanoseconds(
2924 log_header->message()
2925 .oldest_local_reliable_monotonic_timestamps()
2926 ->Get(0)));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002927 const monotonic_clock::time_point
2928 oldest_logger_remote_unreliable_monotonic_timestamps =
2929 monotonic_clock::time_point(chrono::nanoseconds(
2930 log_header->message()
2931 .oldest_logger_remote_unreliable_monotonic_timestamps()
2932 ->Get(1)));
2933 const monotonic_clock::time_point
2934 oldest_logger_local_unreliable_monotonic_timestamps =
2935 monotonic_clock::time_point(chrono::nanoseconds(
2936 log_header->message()
2937 .oldest_logger_local_unreliable_monotonic_timestamps()
2938 ->Get(1)));
Austin Schuh5e14d842022-01-21 12:02:15 -08002939
Austin Schuh01f3b392022-01-25 20:03:09 -08002940 const Channel *channel =
2941 event_loop_factory_.configuration()->channels()->Get(
2942 msg->message().channel_index());
2943 const Connection *connection = configuration::ConnectionToNode(
2944 channel, configuration::GetNode(
2945 event_loop_factory_.configuration(),
2946 log_header->message().node()->name()->string_view()));
2947
2948 const bool reliable = connection->time_to_live() == 0;
2949
Austin Schuhf5f99f32022-02-07 20:05:37 -08002950 SCOPED_TRACE(file);
2951 SCOPED_TRACE(aos::FlatbufferToJson(
2952 *log_header, {.multi_line = true, .max_vector_size = 100}));
2953
Austin Schuh01f3b392022-01-25 20:03:09 -08002954 if (shared()) {
2955 // Confirm that the oldest timestamps match what we expect. Based on
2956 // what we are doing, we know that the oldest time is the first
2957 // message's time.
2958 //
2959 // This makes the test robust to both the split and combined config
2960 // tests.
2961 switch (log_header->message().parts_index()) {
2962 case 0:
Austin Schuh01f3b392022-01-25 20:03:09 -08002963 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2964 expected_oldest_remote_monotonic_timestamps);
2965 EXPECT_EQ(oldest_local_monotonic_timestamps,
2966 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08002967 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2968 expected_oldest_local_monotonic_timestamps) << file;
2969 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
2970 expected_oldest_timestamp_monotonic_timestamps) << file;
2971
Austin Schuh01f3b392022-01-25 20:03:09 -08002972 if (reliable) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08002973 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
2974 expected_oldest_remote_monotonic_timestamps);
2975 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
2976 expected_oldest_local_monotonic_timestamps);
Austin Schuh01f3b392022-01-25 20:03:09 -08002977 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2978 monotonic_clock::max_time);
2979 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2980 monotonic_clock::max_time);
2981 } else {
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);
2986 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2987 expected_oldest_remote_monotonic_timestamps);
2988 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2989 expected_oldest_local_monotonic_timestamps);
2990 }
2991 break;
2992 case 1:
2993 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2994 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
2995 EXPECT_EQ(oldest_local_monotonic_timestamps,
2996 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08002997 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
2998 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
2999 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3000 monotonic_clock::epoch() + chrono::nanoseconds(90250000));
Austin Schuhbfe6c572022-01-27 20:48:20 -08003001 if (reliable) {
3002 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3003 expected_oldest_remote_monotonic_timestamps);
3004 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3005 expected_oldest_local_monotonic_timestamps);
3006 EXPECT_EQ(
3007 oldest_remote_unreliable_monotonic_timestamps,
3008 monotonic_clock::epoch() + chrono::nanoseconds(90000000));
3009 EXPECT_EQ(
3010 oldest_local_unreliable_monotonic_timestamps,
3011 monotonic_clock::epoch() + chrono::nanoseconds(90150000));
3012 } else {
3013 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3014 monotonic_clock::max_time);
3015 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3016 monotonic_clock::max_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003017 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3018 expected_oldest_remote_monotonic_timestamps);
3019 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3020 expected_oldest_local_monotonic_timestamps);
3021 }
3022 break;
3023 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003024 EXPECT_EQ(
3025 oldest_remote_monotonic_timestamps,
3026 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3027 EXPECT_EQ(
3028 oldest_local_monotonic_timestamps,
3029 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
Austin Schuhf5f99f32022-02-07 20:05:37 -08003030 EXPECT_EQ(oldest_logger_remote_unreliable_monotonic_timestamps,
3031 expected_oldest_local_monotonic_timestamps) << file;
3032 EXPECT_EQ(oldest_logger_local_unreliable_monotonic_timestamps,
3033 expected_oldest_timestamp_monotonic_timestamps) << file;
Austin Schuhbfe6c572022-01-27 20:48:20 -08003034 if (reliable) {
3035 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3036 expected_oldest_remote_monotonic_timestamps);
3037 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3038 expected_oldest_local_monotonic_timestamps);
3039 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3040 monotonic_clock::max_time);
3041 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3042 monotonic_clock::max_time);
3043 } else {
3044 EXPECT_EQ(oldest_remote_reliable_monotonic_timestamps,
3045 monotonic_clock::max_time);
3046 EXPECT_EQ(oldest_local_reliable_monotonic_timestamps,
3047 monotonic_clock::max_time);
3048 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3049 expected_oldest_remote_monotonic_timestamps);
3050 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3051 expected_oldest_local_monotonic_timestamps);
3052 }
3053 break;
3054
3055 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003056 EXPECT_EQ(
3057 oldest_remote_monotonic_timestamps,
3058 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
3059 EXPECT_EQ(
3060 oldest_local_monotonic_timestamps,
3061 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3062 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3063 expected_oldest_remote_monotonic_timestamps);
3064 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3065 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003066 EXPECT_EQ(
3067 oldest_logger_remote_unreliable_monotonic_timestamps,
3068 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3069 EXPECT_EQ(
3070 oldest_logger_local_unreliable_monotonic_timestamps,
3071 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003072 break;
3073 default:
3074 FAIL();
3075 break;
3076 }
3077
3078 switch (log_header->message().parts_index()) {
3079 case 0:
3080 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3081 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3082 break;
3083 case 1:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003084 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
Austin Schuh01f3b392022-01-25 20:03:09 -08003085 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3086 break;
3087 case 2:
Austin Schuhbfe6c572022-01-27 20:48:20 -08003088 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3089 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3090 break;
3091 case 3:
Austin Schuh01f3b392022-01-25 20:03:09 -08003092 if (shared()) {
3093 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3094 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
Austin Schuh01f3b392022-01-25 20:03:09 -08003095 break;
3096 }
3097 [[fallthrough]];
3098 default:
3099 FAIL();
3100 break;
3101 }
3102 } else {
3103 switch (log_header->message().parts_index()) {
3104 case 0:
Austin Schuhf5f99f32022-02-07 20:05:37 -08003105 if (reliable) {
3106 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3107 monotonic_clock::max_time);
3108 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3109 monotonic_clock::max_time);
3110 EXPECT_EQ(
3111 oldest_logger_remote_unreliable_monotonic_timestamps,
3112 monotonic_clock::epoch() + chrono::nanoseconds(100150000))
3113 << file;
3114 EXPECT_EQ(
3115 oldest_logger_local_unreliable_monotonic_timestamps,
3116 monotonic_clock::epoch() + chrono::nanoseconds(100250000))
3117 << file;
3118 } else {
3119 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3120 expected_oldest_remote_monotonic_timestamps);
3121 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3122 expected_oldest_local_monotonic_timestamps);
3123 EXPECT_EQ(
3124 oldest_logger_remote_unreliable_monotonic_timestamps,
3125 monotonic_clock::epoch() + chrono::nanoseconds(90150000))
3126 << file;
3127 EXPECT_EQ(
3128 oldest_logger_local_unreliable_monotonic_timestamps,
3129 monotonic_clock::epoch() + chrono::nanoseconds(90250000))
3130 << file;
3131 }
3132 break;
Austin Schuh01f3b392022-01-25 20:03:09 -08003133 case 1:
3134 if (reliable) {
3135 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3136 monotonic_clock::max_time);
3137 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3138 monotonic_clock::max_time);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003139 EXPECT_EQ(
3140 oldest_logger_remote_unreliable_monotonic_timestamps,
3141 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
3142 EXPECT_EQ(
3143 oldest_logger_local_unreliable_monotonic_timestamps,
3144 monotonic_clock::epoch() + chrono::nanoseconds(10100200000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003145 } else {
3146 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3147 expected_oldest_remote_monotonic_timestamps);
3148 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3149 expected_oldest_local_monotonic_timestamps);
Austin Schuhf5f99f32022-02-07 20:05:37 -08003150 EXPECT_EQ(
3151 oldest_logger_remote_unreliable_monotonic_timestamps,
3152 monotonic_clock::epoch() + chrono::nanoseconds(1323150000));
3153 EXPECT_EQ(
3154 oldest_logger_local_unreliable_monotonic_timestamps,
3155 monotonic_clock::epoch() + chrono::nanoseconds(10100250000));
Austin Schuh01f3b392022-01-25 20:03:09 -08003156 }
3157 break;
3158 default:
3159 FAIL();
3160 break;
3161 }
3162
3163 switch (log_header->message().parts_index()) {
3164 case 0:
3165 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
3166 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3167 break;
3168 case 1:
3169 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
3170 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
3171 break;
3172 default:
3173 FAIL();
3174 break;
3175 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003176 }
3177
3178 continue;
3179 }
3180 EXPECT_EQ(
3181 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
3182 monotonic_clock::max_time.time_since_epoch().count());
3183 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
3184 monotonic_clock::max_time.time_since_epoch().count());
3185 EXPECT_EQ(log_header->message()
3186 .oldest_remote_unreliable_monotonic_timestamps()
3187 ->Get(0),
3188 monotonic_clock::max_time.time_since_epoch().count());
3189 EXPECT_EQ(log_header->message()
3190 .oldest_local_unreliable_monotonic_timestamps()
3191 ->Get(0),
3192 monotonic_clock::max_time.time_since_epoch().count());
3193
3194 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
3195 monotonic_clock::time_point(chrono::nanoseconds(
3196 log_header->message().oldest_remote_monotonic_timestamps()->Get(
3197 1)));
3198 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
3199 monotonic_clock::time_point(chrono::nanoseconds(
3200 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
3201 const monotonic_clock::time_point
3202 oldest_remote_unreliable_monotonic_timestamps =
3203 monotonic_clock::time_point(chrono::nanoseconds(
3204 log_header->message()
3205 .oldest_remote_unreliable_monotonic_timestamps()
3206 ->Get(1)));
3207 const monotonic_clock::time_point
3208 oldest_local_unreliable_monotonic_timestamps =
3209 monotonic_clock::time_point(chrono::nanoseconds(
3210 log_header->message()
3211 .oldest_local_unreliable_monotonic_timestamps()
3212 ->Get(1)));
3213 switch (log_header->message().parts_index()) {
3214 case 0:
3215 EXPECT_EQ(oldest_remote_monotonic_timestamps,
3216 monotonic_clock::max_time);
3217 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
3218 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
3219 monotonic_clock::max_time);
3220 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
3221 monotonic_clock::max_time);
3222 break;
3223 default:
3224 FAIL();
3225 break;
3226 }
3227 }
3228
Austin Schuh01f3b392022-01-25 20:03:09 -08003229 if (shared()) {
Austin Schuhbfe6c572022-01-27 20:48:20 -08003230 EXPECT_EQ(timestamp_file_count, 4u);
Austin Schuh01f3b392022-01-25 20:03:09 -08003231 } else {
3232 EXPECT_EQ(timestamp_file_count, 4u);
3233 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003234
Austin Schuhe2373e22022-01-21 12:25:17 -08003235 // Confirm that we can actually sort the resulting log and read it.
3236 {
3237 LogReader reader(SortParts(filenames));
3238
3239 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3240 log_reader_factory.set_send_delay(chrono::microseconds(0));
3241
3242 // This sends out the fetched messages and advances time to the start of
3243 // the log file.
3244 reader.Register(&log_reader_factory);
3245
3246 log_reader_factory.Run();
3247
3248 reader.Deregister();
3249 }
Austin Schuh5e14d842022-01-21 12:02:15 -08003250}
3251
Austin Schuhc9049732020-12-21 22:27:15 -08003252// Tests that we properly handle one direction of message_bridge being
3253// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003254TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003255 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003256 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003257 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003258
3259 time_converter_.AddMonotonic(
3260 {chrono::milliseconds(10000),
3261 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08003262 {
3263 LoggerState pi1_logger = MakeLogger(pi1_);
3264
3265 event_loop_factory_.RunFor(chrono::milliseconds(95));
3266
3267 StartLogger(&pi1_logger);
3268
3269 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3270 }
3271
3272 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3273 // to confirm the right thing happened.
3274 ConfirmReadable(pi1_single_direction_logfiles_);
3275}
3276
3277// Tests that we properly handle one direction of message_bridge being
3278// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08003279TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07003280 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003281 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003282 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08003283
3284 time_converter_.AddMonotonic(
3285 {chrono::milliseconds(10000),
3286 chrono::milliseconds(10000) + chrono::milliseconds(1)});
3287 {
3288 LoggerState pi1_logger = MakeLogger(pi1_);
3289
3290 event_loop_factory_.RunFor(chrono::milliseconds(95));
3291
3292 StartLogger(&pi1_logger);
3293
3294 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3295 }
3296
3297 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3298 // to confirm the right thing happened.
3299 ConfirmReadable(pi1_single_direction_logfiles_);
3300}
3301
Austin Schuhe9f00232021-09-16 18:04:23 -07003302// Tests that we explode if someone passes in a part file twice with a better
3303// error than an out of order error.
3304TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
3305 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003306 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07003307 {
3308 LoggerState pi1_logger = MakeLogger(pi1_);
3309
3310 event_loop_factory_.RunFor(chrono::milliseconds(95));
3311
3312 StartLogger(&pi1_logger);
3313
3314 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3315 }
3316
3317 std::vector<std::string> duplicates;
3318 for (const std::string &f : pi1_single_direction_logfiles_) {
3319 duplicates.emplace_back(f);
3320 duplicates.emplace_back(f);
3321 }
3322 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
3323}
3324
Austin Schuh87dd3832021-01-01 23:07:31 -08003325// Tests that we properly handle a dead node. Do this by just disconnecting it
3326// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08003327TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07003328 pi1_->Disconnect(pi2_->node());
3329 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08003330 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08003331 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08003332 {
3333 LoggerState pi1_logger = MakeLogger(pi1_);
3334
3335 event_loop_factory_.RunFor(chrono::milliseconds(95));
3336
3337 StartLogger(&pi1_logger);
3338
3339 event_loop_factory_.RunFor(chrono::milliseconds(10000));
3340 }
3341
3342 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3343 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07003344 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08003345}
3346
Austin Schuhcdd90272021-03-15 12:46:16 -07003347constexpr std::string_view kCombinedConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08003348 "b8114cd99e9c606b7517d8f478bf16513aef550f23f317720667314cb261f689");
Austin Schuhcdd90272021-03-15 12:46:16 -07003349constexpr std::string_view kSplitConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08003350 "60943d0a46afa6028c8ae276e7b4900b35892f1f53b1818056e7d04463709c5b");
Austin Schuhcdd90272021-03-15 12:46:16 -07003351
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003352INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003353 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003354 ::testing::Combine(::testing::Values(
3355 ConfigParams{
3356 "multinode_pingpong_combined_config.json", true,
3357 kCombinedConfigSha1},
3358 ConfigParams{"multinode_pingpong_split_config.json",
3359 false, kSplitConfigSha1}),
3360 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003361
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07003362INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08003363 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07003364 ::testing::Combine(::testing::Values(
3365 ConfigParams{
3366 "multinode_pingpong_combined_config.json", true,
3367 kCombinedConfigSha1},
3368 ConfigParams{"multinode_pingpong_split_config.json",
3369 false, kSplitConfigSha1}),
3370 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08003371
Austin Schuh5b728b72021-06-16 14:57:15 -07003372// Tests that we can relog with a different config. This makes most sense when
3373// you are trying to edit a log and want to use channel renaming + the original
3374// config in the new log.
3375TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3376 time_converter_.StartEqual();
3377 {
3378 LoggerState pi1_logger = MakeLogger(pi1_);
3379 LoggerState pi2_logger = MakeLogger(pi2_);
3380
3381 event_loop_factory_.RunFor(chrono::milliseconds(95));
3382
3383 StartLogger(&pi1_logger);
3384 StartLogger(&pi2_logger);
3385
3386 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3387 }
3388
3389 LogReader reader(SortParts(logfiles_));
3390 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3391
3392 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3393 log_reader_factory.set_send_delay(chrono::microseconds(0));
3394
3395 // This sends out the fetched messages and advances time to the start of the
3396 // log file.
3397 reader.Register(&log_reader_factory);
3398
3399 const Node *pi1 =
3400 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3401 const Node *pi2 =
3402 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3403
3404 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3405 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3406 LOG(INFO) << "now pi1 "
3407 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3408 LOG(INFO) << "now pi2 "
3409 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3410
3411 EXPECT_THAT(reader.LoggedNodes(),
3412 ::testing::ElementsAre(
3413 configuration::GetNode(reader.logged_configuration(), pi1),
3414 configuration::GetNode(reader.logged_configuration(), pi2)));
3415
3416 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3417
3418 // And confirm we can re-create a log again, while checking the contents.
3419 std::vector<std::string> log_files;
3420 {
3421 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003422 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003423 &log_reader_factory, reader.logged_configuration());
3424 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003425 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003426 &log_reader_factory, reader.logged_configuration());
3427
Austin Schuh3e20c692021-11-16 20:43:16 -08003428 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3429 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003430
3431 log_reader_factory.Run();
3432
3433 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3434 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3435 }
3436 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3437 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3438 }
3439 }
3440
3441 reader.Deregister();
3442
3443 // And verify that we can run the LogReader over the relogged files without
3444 // hitting any fatal errors.
3445 {
3446 LogReader relogged_reader(SortParts(log_files));
3447 relogged_reader.Register();
3448
3449 relogged_reader.event_loop_factory()->Run();
3450 }
3451}
Austin Schuha04efed2021-01-24 18:04:20 -08003452
Austin Schuh3e20c692021-11-16 20:43:16 -08003453// Tests that we properly replay a log where the start time for a node is before
3454// any data on the node. This can happen if the logger starts before data is
3455// published. While the scenario below is a bit convoluted, we have seen logs
3456// like this generated out in the wild.
3457TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3458 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3459 aos::configuration::ReadConfig(ArtifactPath(
3460 "aos/events/logging/multinode_pingpong_split3_config.json"));
3461 message_bridge::TestingTimeConverter time_converter(
3462 configuration::NodesCount(&config.message()));
3463 SimulatedEventLoopFactory event_loop_factory(&config.message());
3464 event_loop_factory.SetTimeConverter(&time_converter);
3465 NodeEventLoopFactory *const pi1 =
3466 event_loop_factory.GetNodeEventLoopFactory("pi1");
3467 const size_t pi1_index = configuration::GetNodeIndex(
3468 event_loop_factory.configuration(), pi1->node());
3469 NodeEventLoopFactory *const pi2 =
3470 event_loop_factory.GetNodeEventLoopFactory("pi2");
3471 const size_t pi2_index = configuration::GetNodeIndex(
3472 event_loop_factory.configuration(), pi2->node());
3473 NodeEventLoopFactory *const pi3 =
3474 event_loop_factory.GetNodeEventLoopFactory("pi3");
3475 const size_t pi3_index = configuration::GetNodeIndex(
3476 event_loop_factory.configuration(), pi3->node());
3477
3478 const std::string kLogfile1_1 =
3479 aos::testing::TestTmpDir() + "/multi_logfile1/";
3480 const std::string kLogfile2_1 =
3481 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3482 const std::string kLogfile2_2 =
3483 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3484 const std::string kLogfile3_1 =
3485 aos::testing::TestTmpDir() + "/multi_logfile3/";
3486 util::UnlinkRecursive(kLogfile1_1);
3487 util::UnlinkRecursive(kLogfile2_1);
3488 util::UnlinkRecursive(kLogfile2_2);
3489 util::UnlinkRecursive(kLogfile3_1);
3490 const UUID pi1_boot0 = UUID::Random();
3491 const UUID pi2_boot0 = UUID::Random();
3492 const UUID pi2_boot1 = UUID::Random();
3493 const UUID pi3_boot0 = UUID::Random();
3494 {
3495 CHECK_EQ(pi1_index, 0u);
3496 CHECK_EQ(pi2_index, 1u);
3497 CHECK_EQ(pi3_index, 2u);
3498
3499 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3500 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3501 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3502 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3503
3504 time_converter.AddNextTimestamp(
3505 distributed_clock::epoch(),
3506 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3507 BootTimestamp::epoch()});
3508 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3509 time_converter.AddNextTimestamp(
3510 distributed_clock::epoch() + reboot_time,
3511 {BootTimestamp::epoch() + reboot_time,
3512 BootTimestamp{
3513 .boot = 1,
3514 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3515 BootTimestamp::epoch() + reboot_time});
3516 }
3517
3518 // Make everything perfectly quiet.
3519 event_loop_factory.SkipTimingReport();
3520 event_loop_factory.DisableStatistics();
3521
3522 std::vector<std::string> filenames;
3523 {
3524 LoggerState pi1_logger = LoggerState::MakeLogger(
3525 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3526 LoggerState pi3_logger = LoggerState::MakeLogger(
3527 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3528 {
3529 // And now start the logger.
3530 LoggerState pi2_logger = LoggerState::MakeLogger(
3531 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3532
3533 event_loop_factory.RunFor(chrono::milliseconds(1000));
3534
3535 pi1_logger.StartLogger(kLogfile1_1);
3536 pi3_logger.StartLogger(kLogfile3_1);
3537 pi2_logger.StartLogger(kLogfile2_1);
3538
3539 event_loop_factory.RunFor(chrono::milliseconds(10000));
3540
3541 // Now that we've got a start time in the past, turn on data.
3542 event_loop_factory.EnableStatistics();
3543 std::unique_ptr<aos::EventLoop> ping_event_loop =
3544 pi1->MakeEventLoop("ping");
3545 Ping ping(ping_event_loop.get());
3546
3547 pi2->AlwaysStart<Pong>("pong");
3548
3549 event_loop_factory.RunFor(chrono::milliseconds(3000));
3550
3551 pi2_logger.AppendAllFilenames(&filenames);
3552
3553 // Stop logging on pi2 before rebooting and completely shut off all
3554 // messages on pi2.
3555 pi2->DisableStatistics();
3556 pi1->Disconnect(pi2->node());
3557 pi2->Disconnect(pi1->node());
3558 }
3559 event_loop_factory.RunFor(chrono::milliseconds(7000));
3560 // pi2 now reboots.
3561 {
3562 event_loop_factory.RunFor(chrono::milliseconds(1000));
3563
3564 // Start logging again on pi2 after it is up.
3565 LoggerState pi2_logger = LoggerState::MakeLogger(
3566 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3567 pi2_logger.StartLogger(kLogfile2_2);
3568
3569 event_loop_factory.RunFor(chrono::milliseconds(10000));
3570 // And, now that we have a start time in the log, turn data back on.
3571 pi2->EnableStatistics();
3572 pi1->Connect(pi2->node());
3573 pi2->Connect(pi1->node());
3574
3575 pi2->AlwaysStart<Pong>("pong");
3576 std::unique_ptr<aos::EventLoop> ping_event_loop =
3577 pi1->MakeEventLoop("ping");
3578 Ping ping(ping_event_loop.get());
3579
3580 event_loop_factory.RunFor(chrono::milliseconds(3000));
3581
3582 pi2_logger.AppendAllFilenames(&filenames);
3583 }
3584
3585 pi1_logger.AppendAllFilenames(&filenames);
3586 pi3_logger.AppendAllFilenames(&filenames);
3587 }
3588
3589 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3590 // to confirm the right thing happened.
3591 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3592 ConfirmReadable(filenames);
3593}
3594
Austin Schuh5dd22842021-11-17 16:09:39 -08003595// Tests that local data before remote data after reboot is properly replayed.
3596// We only trigger a reboot in the timestamp interpolation function when solving
3597// the timestamp problem when we actually have a point in the function. This
3598// originally only happened when a point passes the noncausal filter. At the
3599// start of time for the second boot, if we aren't careful, we will have
3600// messages which need to be published at times before the boot. This happens
3601// when a local message is in the log before a forwarded message, so there is no
3602// point in the interpolation function. This delays the reboot. So, we need to
3603// recreate that situation and make sure it doesn't come back.
Austin Schuhbfe6c572022-01-27 20:48:20 -08003604TEST(MultinodeRebootLoggerTest,
3605 LocalMessageBeforeRemoteBeforeStartAfterReboot) {
Austin Schuh5dd22842021-11-17 16:09:39 -08003606 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3607 aos::configuration::ReadConfig(ArtifactPath(
3608 "aos/events/logging/multinode_pingpong_split3_config.json"));
3609 message_bridge::TestingTimeConverter time_converter(
3610 configuration::NodesCount(&config.message()));
3611 SimulatedEventLoopFactory event_loop_factory(&config.message());
3612 event_loop_factory.SetTimeConverter(&time_converter);
3613 NodeEventLoopFactory *const pi1 =
3614 event_loop_factory.GetNodeEventLoopFactory("pi1");
3615 const size_t pi1_index = configuration::GetNodeIndex(
3616 event_loop_factory.configuration(), pi1->node());
3617 NodeEventLoopFactory *const pi2 =
3618 event_loop_factory.GetNodeEventLoopFactory("pi2");
3619 const size_t pi2_index = configuration::GetNodeIndex(
3620 event_loop_factory.configuration(), pi2->node());
3621 NodeEventLoopFactory *const pi3 =
3622 event_loop_factory.GetNodeEventLoopFactory("pi3");
3623 const size_t pi3_index = configuration::GetNodeIndex(
3624 event_loop_factory.configuration(), pi3->node());
3625
3626 const std::string kLogfile1_1 =
3627 aos::testing::TestTmpDir() + "/multi_logfile1/";
3628 const std::string kLogfile2_1 =
3629 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3630 const std::string kLogfile2_2 =
3631 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3632 const std::string kLogfile3_1 =
3633 aos::testing::TestTmpDir() + "/multi_logfile3/";
3634 util::UnlinkRecursive(kLogfile1_1);
3635 util::UnlinkRecursive(kLogfile2_1);
3636 util::UnlinkRecursive(kLogfile2_2);
3637 util::UnlinkRecursive(kLogfile3_1);
3638 const UUID pi1_boot0 = UUID::Random();
3639 const UUID pi2_boot0 = UUID::Random();
3640 const UUID pi2_boot1 = UUID::Random();
3641 const UUID pi3_boot0 = UUID::Random();
3642 {
3643 CHECK_EQ(pi1_index, 0u);
3644 CHECK_EQ(pi2_index, 1u);
3645 CHECK_EQ(pi3_index, 2u);
3646
3647 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3648 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3649 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3650 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3651
3652 time_converter.AddNextTimestamp(
3653 distributed_clock::epoch(),
3654 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3655 BootTimestamp::epoch()});
3656 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3657 time_converter.AddNextTimestamp(
3658 distributed_clock::epoch() + reboot_time,
3659 {BootTimestamp::epoch() + reboot_time,
Austin Schuhbfe6c572022-01-27 20:48:20 -08003660 BootTimestamp{.boot = 1,
3661 .time = monotonic_clock::epoch() + reboot_time +
3662 chrono::seconds(100)},
Austin Schuh5dd22842021-11-17 16:09:39 -08003663 BootTimestamp::epoch() + reboot_time});
3664 }
3665
3666 std::vector<std::string> filenames;
3667 {
3668 LoggerState pi1_logger = LoggerState::MakeLogger(
3669 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3670 LoggerState pi3_logger = LoggerState::MakeLogger(
3671 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3672 {
3673 // And now start the logger.
3674 LoggerState pi2_logger = LoggerState::MakeLogger(
3675 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3676
3677 pi1_logger.StartLogger(kLogfile1_1);
3678 pi3_logger.StartLogger(kLogfile3_1);
3679 pi2_logger.StartLogger(kLogfile2_1);
3680
3681 event_loop_factory.RunFor(chrono::milliseconds(1005));
3682
3683 // Now that we've got a start time in the past, turn on data.
3684 std::unique_ptr<aos::EventLoop> ping_event_loop =
3685 pi1->MakeEventLoop("ping");
3686 Ping ping(ping_event_loop.get());
3687
3688 pi2->AlwaysStart<Pong>("pong");
3689
3690 event_loop_factory.RunFor(chrono::milliseconds(3000));
3691
3692 pi2_logger.AppendAllFilenames(&filenames);
3693
3694 // Disable any remote messages on pi2.
3695 pi1->Disconnect(pi2->node());
3696 pi2->Disconnect(pi1->node());
3697 }
3698 event_loop_factory.RunFor(chrono::milliseconds(995));
3699 // pi2 now reboots at 5 seconds.
3700 {
3701 event_loop_factory.RunFor(chrono::milliseconds(1000));
3702
3703 // Make local stuff happen before we start logging and connect the remote.
3704 pi2->AlwaysStart<Pong>("pong");
3705 std::unique_ptr<aos::EventLoop> ping_event_loop =
3706 pi1->MakeEventLoop("ping");
3707 Ping ping(ping_event_loop.get());
3708 event_loop_factory.RunFor(chrono::milliseconds(1005));
3709
3710 // Start logging again on pi2 after it is up.
3711 LoggerState pi2_logger = LoggerState::MakeLogger(
3712 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3713 pi2_logger.StartLogger(kLogfile2_2);
3714
3715 // And allow remote messages now that we have some local ones.
3716 pi1->Connect(pi2->node());
3717 pi2->Connect(pi1->node());
3718
3719 event_loop_factory.RunFor(chrono::milliseconds(1000));
3720
3721 event_loop_factory.RunFor(chrono::milliseconds(3000));
3722
3723 pi2_logger.AppendAllFilenames(&filenames);
3724 }
3725
3726 pi1_logger.AppendAllFilenames(&filenames);
3727 pi3_logger.AppendAllFilenames(&filenames);
3728 }
3729
3730 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3731 // to confirm the right thing happened.
3732 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3733 ConfirmReadable(filenames);
3734}
3735
3736
Austin Schuhe309d2a2019-11-29 13:25:21 -08003737} // namespace testing
3738} // namespace logger
3739} // namespace aos