blob: 97b293ae49a11ec8dd69e99f2d00a41857537d76 [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>();
milind1f1dca32021-07-03 13:50:07 -0700401 CHECK_EQ(builder.Send(ping_builder.Finish()),
402 RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800403 });
404
405 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
406 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
407 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
408 chrono::microseconds(50));
409 });
410
Brian Silverman1f345222020-09-24 21:14:48 -0700411 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800412 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700413 logger.set_polling_period(std::chrono::milliseconds(100));
414 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800415
416 event_loop_factory_.RunFor(chrono::milliseconds(1000));
417 }
418}
419
James Kuszmauldd0a5042021-10-28 23:38:04 -0700420struct CompressionParams {
421 std::string_view extension;
422 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
423};
424
425std::ostream &operator<<(std::ostream &ostream,
426 const CompressionParams &params) {
427 ostream << "\"" << params.extension << "\"";
428 return ostream;
429}
430
431std::vector<CompressionParams> SupportedCompressionAlgorithms() {
432 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
433 {SnappyDecoder::kExtension,
434 []() { return std::make_unique<SnappyEncoder>(); }},
435#ifdef LZMA
436 {LzmaDecoder::kExtension,
437 []() { return std::make_unique<LzmaEncoder>(3); }}
438#endif // LZMA
439 };
440}
441
Austin Schuh61e973f2021-02-21 21:43:56 -0800442// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700443struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800444 // The config file to use.
445 std::string config;
446 // If true, the RemoteMessage channel should be shared between all the remote
447 // channels. If false, there will be 1 RemoteMessage channel per remote
448 // channel.
449 bool shared;
450 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700451 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800452};
Austin Schuh315b96b2020-12-11 21:21:12 -0800453
James Kuszmauldd0a5042021-10-28 23:38:04 -0700454std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
455 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
456 << ", sha256: \"" << params.sha256 << "\"}";
457 return ostream;
458}
459
Austin Schuh3e20c692021-11-16 20:43:16 -0800460struct LoggerState {
461 static LoggerState MakeLogger(NodeEventLoopFactory *node,
462 SimulatedEventLoopFactory *factory,
463 CompressionParams params,
464 const Configuration *configuration = nullptr) {
465 if (configuration == nullptr) {
466 configuration = factory->configuration();
467 }
468 return {node->MakeEventLoop("logger"),
469 {},
470 configuration,
471 configuration::GetNode(configuration, node->node()),
472 nullptr,
473 params};
474 }
475
476 void StartLogger(std::string logfile_base) {
477 CHECK(!logfile_base.empty());
478
479 logger = std::make_unique<Logger>(event_loop.get(), configuration);
480 logger->set_polling_period(std::chrono::milliseconds(100));
481 logger->set_name(
482 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
483 event_loop->OnRun([this, logfile_base]() {
484 std::unique_ptr<MultiNodeLogNamer> namer =
485 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
486 event_loop.get(), node);
487 namer->set_extension(params.extension);
488 namer->set_encoder_factory(params.encoder_factory);
489 log_namer = namer.get();
490
491 logger->StartLogging(std::move(namer));
492 });
493 }
494
495 std::unique_ptr<EventLoop> event_loop;
496 std::unique_ptr<Logger> logger;
497 const Configuration *configuration;
498 const Node *node;
499 MultiNodeLogNamer *log_namer;
500 CompressionParams params;
501
502 void AppendAllFilenames(std::vector<std::string> *filenames) {
503 for (const std::string &file : log_namer->all_filenames()) {
504 const std::string_view separator =
505 log_namer->base_name().back() == '/' ? "" : "_";
506 filenames->emplace_back(
507 absl::StrCat(log_namer->base_name(), separator, file));
508 }
509 }
510
511 ~LoggerState() {
512 if (logger) {
513 for (const std::string &file : log_namer->all_filenames()) {
514 LOG(INFO) << "Wrote to " << file;
515 }
516 }
517 }
518};
519
520void ConfirmReadable(const std::vector<std::string> &files) {
521 {
522 LogReader reader(SortParts(files));
523
524 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
525 reader.Register(&log_reader_factory);
526
527 log_reader_factory.Run();
528
529 reader.Deregister();
530 }
531 {
532 LogReader reader(SortParts(files));
533
534 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
535 reader.RegisterWithoutStarting(&log_reader_factory);
536 if (configuration::MultiNode(log_reader_factory.configuration())) {
537 for (const aos::Node *node :
538 *log_reader_factory.configuration()->nodes()) {
539 reader.OnStart(node, [node]() {
540 LOG(INFO) << "Starting " << node->name()->string_view();
541 });
542 }
543 }
544
545 log_reader_factory.Run();
546
547 reader.Deregister();
548 }
549}
550
James Kuszmauldd0a5042021-10-28 23:38:04 -0700551class MultinodeLoggerTest : public ::testing::TestWithParam<
552 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800553 public:
554 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700555 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
556 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800557 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800558 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700559 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800560 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700561 event_loop_factory_.configuration(), pi1_->node())),
562 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800563 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700564 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800565 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800566 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
567 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800568 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800569 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800570 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700571 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700572 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800573 event_loop_factory_.SetTimeConverter(&time_converter_);
574
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700575 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700576 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700577 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800578 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700579 }
580
Austin Schuh268586b2021-03-31 22:24:39 -0700581 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800582 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800583 unlink(file.c_str());
584 }
585
Austin Schuh268586b2021-03-31 22:24:39 -0700586 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800587 unlink(file.c_str());
588 }
589
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700590 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
591 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700592
593 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
594 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700595 }
596
James Kuszmauldd0a5042021-10-28 23:38:04 -0700597 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800598
599 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700600 std::string logfile_base2,
601 size_t pi1_data_count = 2,
602 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800603 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700604 result.emplace_back(absl::StrCat(
605 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
606 result.emplace_back(absl::StrCat(
607 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700608 for (size_t i = 0; i < pi1_data_count; ++i) {
609 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700610 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700611 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800612 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700613 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800614 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700615 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700616 for (size_t i = 0; i < pi2_data_count; ++i) {
617 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700618 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700619 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700620 result.emplace_back(logfile_base2 +
621 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
622 Extension());
623 result.emplace_back(logfile_base2 +
624 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
625 Extension());
626 result.emplace_back(logfile_base1 +
627 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
628 Extension());
629 result.emplace_back(logfile_base1 +
630 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
631 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800632 if (shared()) {
633 result.emplace_back(logfile_base1 +
634 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700635 "aos.message_bridge.RemoteMessage.part0" +
636 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800637 result.emplace_back(logfile_base1 +
638 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700639 "aos.message_bridge.RemoteMessage.part1" +
640 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800641 result.emplace_back(logfile_base2 +
642 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700643 "aos.message_bridge.RemoteMessage.part0" +
644 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800645 result.emplace_back(logfile_base2 +
646 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700647 "aos.message_bridge.RemoteMessage.part1" +
648 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800649 } else {
650 result.emplace_back(logfile_base1 +
651 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
652 "aos-message_bridge-Timestamp/"
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_base1 +
656 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
657 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700658 "aos.message_bridge.RemoteMessage.part1" +
659 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800660 result.emplace_back(logfile_base2 +
661 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/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_base2 +
666 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/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_base1 +
671 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
672 "aos-examples-Ping/"
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_base1 +
676 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
677 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700678 "aos.message_bridge.RemoteMessage.part1" +
679 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800680 }
681
682 return result;
683 }
684
685 std::vector<std::string> MakePi1RebootLogfiles() {
686 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700687 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
688 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
689 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800690 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700691 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800692 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700693 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800694 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700695 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700696 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700697 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
698 result.emplace_back(logfile_base1_ +
699 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
700 Extension());
701 result.emplace_back(logfile_base1_ +
702 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
703 Extension());
704 result.emplace_back(logfile_base1_ +
705 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
706 Extension());
707 result.emplace_back(logfile_base1_ +
708 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
709 Extension());
710 result.emplace_back(absl::StrCat(
711 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800712 if (shared()) {
713 result.emplace_back(logfile_base1_ +
714 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700715 "aos.message_bridge.RemoteMessage.part0" +
716 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800717 result.emplace_back(logfile_base1_ +
718 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700719 "aos.message_bridge.RemoteMessage.part1" +
720 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800721 result.emplace_back(logfile_base1_ +
722 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700723 "aos.message_bridge.RemoteMessage.part2" +
724 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700725 result.emplace_back(logfile_base1_ +
726 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700727 "aos.message_bridge.RemoteMessage.part3" +
728 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800729 } else {
730 result.emplace_back(logfile_base1_ +
731 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
732 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700733 "aos.message_bridge.RemoteMessage.part0" +
734 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800735 result.emplace_back(logfile_base1_ +
736 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
737 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700738 "aos.message_bridge.RemoteMessage.part1" +
739 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800740 result.emplace_back(logfile_base1_ +
741 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
742 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700743 "aos.message_bridge.RemoteMessage.part2" +
744 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700745 result.emplace_back(logfile_base1_ +
746 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
747 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700748 "aos.message_bridge.RemoteMessage.part3" +
749 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800750
751 result.emplace_back(logfile_base1_ +
752 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
753 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700754 "aos.message_bridge.RemoteMessage.part0" +
755 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800756 result.emplace_back(logfile_base1_ +
757 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
758 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700759 "aos.message_bridge.RemoteMessage.part1" +
760 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800761 result.emplace_back(logfile_base1_ +
762 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
763 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700764 "aos.message_bridge.RemoteMessage.part2" +
765 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700766 result.emplace_back(logfile_base1_ +
767 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
768 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700769 "aos.message_bridge.RemoteMessage.part3" +
770 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800771 }
772 return result;
773 }
774
775 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
776 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700777 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
778 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
779 result.emplace_back(logfile_base1_ +
780 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
781 Extension());
782 result.emplace_back(absl::StrCat(
783 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700784 return result;
785 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800786
Austin Schuh510dc622021-08-06 18:47:30 -0700787 std::vector<std::string> MakePi1DeadNodeLogfiles() {
788 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700789 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
790 result.emplace_back(absl::StrCat(
791 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800792 return result;
793 }
794
795 std::vector<std::vector<std::string>> StructureLogFiles() {
796 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700797 std::vector<std::string>{logfiles_[2], logfiles_[3]},
798 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800799 std::vector<std::string>{logfiles_[6], logfiles_[7]},
800 std::vector<std::string>{logfiles_[8], logfiles_[9]},
801 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700802 std::vector<std::string>{logfiles_[12], logfiles_[13]},
803 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800804
805 if (!shared()) {
806 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700807 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800808 }
809
810 return result;
811 }
812
James Kuszmauldd0a5042021-10-28 23:38:04 -0700813 std::string Extension() {
814 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
815 }
816
Austin Schuh58646e22021-08-23 23:51:46 -0700817 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700818 SimulatedEventLoopFactory *factory = nullptr,
819 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700820 if (factory == nullptr) {
821 factory = &event_loop_factory_;
822 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800823 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
824 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700825 }
826
James Kuszmauldd0a5042021-10-28 23:38:04 -0700827 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700828 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800829 if (logger->event_loop->node()->name()->string_view() == "pi1") {
830 logfile_base = logfile_base1_;
831 } else {
832 logfile_base = logfile_base2_;
833 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700834 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800835 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700836 }
Austin Schuh15649d62019-12-28 16:36:38 -0800837
Austin Schuh3bd4c402020-11-06 18:19:06 -0800838 void VerifyParts(const std::vector<LogFile> &sorted_parts,
839 const std::vector<std::string> &corrupted_parts = {}) {
840 EXPECT_EQ(sorted_parts.size(), 2u);
841
842 // Count up the number of UUIDs and make sure they are what we expect as a
843 // sanity check.
844 std::set<std::string> log_event_uuids;
845 std::set<std::string> parts_uuids;
846 std::set<std::string> both_uuids;
847
848 size_t missing_rt_count = 0;
849
850 std::vector<std::string> logger_nodes;
851 for (const LogFile &log_file : sorted_parts) {
852 EXPECT_FALSE(log_file.log_event_uuid.empty());
853 log_event_uuids.insert(log_file.log_event_uuid);
854 logger_nodes.emplace_back(log_file.logger_node);
855 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800856 EXPECT_TRUE(log_file.config);
857 EXPECT_EQ(log_file.name,
858 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800859
860 for (const LogParts &part : log_file.parts) {
861 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
862 << ": " << part;
863 missing_rt_count +=
864 part.realtime_start_time == aos::realtime_clock::min_time;
865
866 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
867 log_event_uuids.end());
868 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800869 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800870 parts_uuids.insert(part.parts_uuid);
871 both_uuids.insert(part.parts_uuid);
872 }
873 }
874
Austin Schuh61e973f2021-02-21 21:43:56 -0800875 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
876 // start time on remote nodes because we don't know it and would be
877 // guessing. And the log reader can actually do a better job. The number
878 // depends on if we have the remote timestamps split across 2 files, or just
879 // across 1, depending on if we are using a split or combined timestamp
880 // channel config.
881 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800882
883 EXPECT_EQ(log_event_uuids.size(), 2u);
884 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
885 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
886
887 // Test that each list of parts is in order. Don't worry about the ordering
888 // between part file lists though.
889 // (inner vectors all need to be in order, but outer one doesn't matter).
890 EXPECT_THAT(ToLogReaderVector(sorted_parts),
891 ::testing::UnorderedElementsAreArray(structured_logfiles_));
892
893 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
894
895 EXPECT_NE(sorted_parts[0].realtime_start_time,
896 aos::realtime_clock::min_time);
897 EXPECT_NE(sorted_parts[1].realtime_start_time,
898 aos::realtime_clock::min_time);
899
900 EXPECT_NE(sorted_parts[0].monotonic_start_time,
901 aos::monotonic_clock::min_time);
902 EXPECT_NE(sorted_parts[1].monotonic_start_time,
903 aos::monotonic_clock::min_time);
904
905 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
906 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
907 }
908
909 void AddExtension(std::string_view extension) {
910 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
911 [extension](const std::string &in) {
912 return absl::StrCat(in, extension);
913 });
914
915 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
916 structured_logfiles_.begin(),
917 [extension](std::vector<std::string> in) {
918 std::transform(in.begin(), in.end(), in.begin(),
919 [extension](const std::string &in_str) {
920 return absl::StrCat(in_str, extension);
921 });
922 return in;
923 });
924 }
925
Austin Schuh15649d62019-12-28 16:36:38 -0800926 // Config and factory.
927 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800928 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800929 SimulatedEventLoopFactory event_loop_factory_;
930
Austin Schuh58646e22021-08-23 23:51:46 -0700931 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800932 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700933 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800934 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700935
936 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800937 std::string logfile_base1_;
938 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800939 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700940 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800941 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700942
943 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800944};
945
Austin Schuh391e3172020-09-01 22:48:18 -0700946// Counts the number of messages on a channel. Returns (channel name, channel
947// type, count) for every message matching matcher()
948std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800949 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700950 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800951 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800952 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800953
Austin Schuh6f3babe2020-01-26 20:34:50 -0800954 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700955 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800956 if (!msg) {
957 break;
958 }
959
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700960 if (matcher(msg.get())) {
961 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800962 }
963 }
964
Austin Schuh391e3172020-09-01 22:48:18 -0700965 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800966 int channel = 0;
967 for (size_t i = 0; i < counts.size(); ++i) {
968 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800969 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700970 result.push_back(std::make_tuple(channel->name()->str(),
971 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800972 }
973 ++channel;
974 }
975
976 return result;
977}
978
979// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700980std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800981 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700982 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700983 return CountChannelsMatching(
984 config, filename, [](const UnpackedMessageHeader *msg) {
985 if (msg->span.data() != nullptr) {
986 CHECK(!msg->monotonic_remote_time.has_value());
987 CHECK(!msg->realtime_remote_time.has_value());
988 CHECK(!msg->remote_queue_index.has_value());
989 return true;
990 }
991 return false;
992 });
Austin Schuh6f3babe2020-01-26 20:34:50 -0800993}
994
995// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700996std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800997 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800998 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700999 return CountChannelsMatching(
1000 config, filename, [](const UnpackedMessageHeader *msg) {
1001 if (msg->span.data() == nullptr) {
1002 CHECK(msg->monotonic_remote_time.has_value());
1003 CHECK(msg->realtime_remote_time.has_value());
1004 CHECK(msg->remote_queue_index.has_value());
1005 return true;
1006 }
1007 return false;
1008 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001009}
1010
Austin Schuhcde938c2020-02-02 17:30:07 -08001011// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001012TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001013 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -08001014 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001015 LoggerState pi1_logger = MakeLogger(pi1_);
1016 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001017
1018 event_loop_factory_.RunFor(chrono::milliseconds(95));
1019
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001020 StartLogger(&pi1_logger);
1021 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001022
Austin Schuh15649d62019-12-28 16:36:38 -08001023 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1024 }
1025
Austin Schuh6f3babe2020-01-26 20:34:50 -08001026 {
Austin Schuh64fab802020-09-09 22:47:47 -07001027 std::set<std::string> logfile_uuids;
1028 std::set<std::string> parts_uuids;
1029 // Confirm that we have the expected number of UUIDs for both the logfile
1030 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001031 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001032 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001033 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001034 if (!log_header.back().message().has_configuration()) {
1035 logfile_uuids.insert(
1036 log_header.back().message().log_event_uuid()->str());
1037 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1038 }
Austin Schuh64fab802020-09-09 22:47:47 -07001039 }
Austin Schuh15649d62019-12-28 16:36:38 -08001040
Austin Schuh64fab802020-09-09 22:47:47 -07001041 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001042 if (shared()) {
1043 EXPECT_EQ(parts_uuids.size(), 7u);
1044 } else {
1045 EXPECT_EQ(parts_uuids.size(), 8u);
1046 }
Austin Schuh64fab802020-09-09 22:47:47 -07001047
1048 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001049 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001050 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001051 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
1052 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001053 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
1054 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
1055 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
1056 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001057 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
1058 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001059 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1060 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
1061 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
1062 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -08001063 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001064 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
1065 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001066 }
Austin Schuh64fab802020-09-09 22:47:47 -07001067
1068 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001069 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001070 EXPECT_EQ(log_header[3].message().parts_index(), 1);
1071 EXPECT_EQ(log_header[4].message().parts_index(), 0);
1072 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -07001073 EXPECT_EQ(log_header[6].message().parts_index(), 0);
1074 EXPECT_EQ(log_header[7].message().parts_index(), 1);
1075 EXPECT_EQ(log_header[8].message().parts_index(), 0);
1076 EXPECT_EQ(log_header[9].message().parts_index(), 1);
1077 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1078 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001079 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1080 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -07001081 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1082 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001083 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001084 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1085 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001086 }
Austin Schuh64fab802020-09-09 22:47:47 -07001087 }
1088
Austin Schuh8c399962020-12-25 21:51:45 -08001089 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001090 {
Austin Schuh391e3172020-09-01 22:48:18 -07001091 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001092 std::shared_ptr<const aos::Configuration> config =
1093 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001094
Austin Schuh6f3babe2020-01-26 20:34:50 -08001095 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001096 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1097 UnorderedElementsAre(
1098 std::make_tuple("/pi1/aos",
1099 "aos.message_bridge.ServerStatistics", 1),
1100 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001101 << " : " << logfiles_[2];
1102 EXPECT_THAT(
1103 CountChannelsData(config, logfiles_[3]),
1104 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -07001105 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001106 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001107 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001108 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1109 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001110 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001111 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1112 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001113 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001114 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1115 UnorderedElementsAre())
1116 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001117 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001118 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001119 UnorderedElementsAre(
1120 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001121 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001122 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001123
1124 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001125 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001126 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001127 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001128 << " : " << logfiles_[4];
1129 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001130 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001131 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001132 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001133
Austin Schuh6f3babe2020-01-26 20:34:50 -08001134 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001135 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001136 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001137 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001138 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1139 UnorderedElementsAre())
1140 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001141
1142 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001143 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1144 UnorderedElementsAre(std::make_tuple(
1145 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1146 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001147 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001148 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001149 UnorderedElementsAre(
1150 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001151 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001152 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001153 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1154 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001155 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001156 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001157 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001158 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001159 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1160 UnorderedElementsAre())
1161 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001162 EXPECT_THAT(
1163 CountChannelsTimestamp(config, logfiles_[7]),
1164 UnorderedElementsAre(
1165 std::make_tuple("/test", "aos.examples.Ping", 2001),
1166 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001167 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001168
1169 // And then test that the remotely logged timestamp data files only have
1170 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001171 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1172 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001173 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001174 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1175 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001176 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001177 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1178 UnorderedElementsAre())
1179 << " : " << logfiles_[10];
1180 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1181 UnorderedElementsAre())
1182 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001183
Austin Schuh8c399962020-12-25 21:51:45 -08001184 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001185 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001186 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001187 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001188 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001189 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001190 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001191 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001192
Austin Schuh8c399962020-12-25 21:51:45 -08001193 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001194 UnorderedElementsAre(std::make_tuple(
1195 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001196 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001197 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001198 UnorderedElementsAre(std::make_tuple(
1199 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001200 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001201
1202 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001203 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1204 UnorderedElementsAre())
1205 << " : " << logfiles_[12];
1206 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1207 UnorderedElementsAre())
1208 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001209 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1210 UnorderedElementsAre())
1211 << " : " << logfiles_[14];
1212 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1213 UnorderedElementsAre())
1214 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001215 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001216 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001217 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001218 << " : " << logfiles_[16];
1219 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001220 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001221 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001222 }
1223
1224 if (shared()) {
1225 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001226 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001227 UnorderedElementsAre(
1228 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1229 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001230 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001231 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001232 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001233 UnorderedElementsAre(
1234 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1235 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001236 << " : " << logfiles_[13];
1237 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001238 UnorderedElementsAre(std::make_tuple(
1239 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001240 << " : " << logfiles_[14];
1241 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001242 UnorderedElementsAre(std::make_tuple(
1243 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1244 << " : " << logfiles_[15];
1245 } else {
1246 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1247 UnorderedElementsAre(std::make_tuple(
1248 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1249 << " : " << logfiles_[12];
1250 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1251 UnorderedElementsAre(std::make_tuple(
1252 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1253 << " : " << logfiles_[13];
1254 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1255 UnorderedElementsAre(std::make_tuple(
1256 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1257 << " : " << logfiles_[14];
1258 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1259 UnorderedElementsAre(std::make_tuple(
1260 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1261 << " : " << logfiles_[15];
1262 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1263 UnorderedElementsAre(
1264 std::make_tuple("/test", "aos.examples.Ping", 91)))
1265 << " : " << logfiles_[16];
1266 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001267 UnorderedElementsAre(
1268 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001269 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001270 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001271 }
1272
Austin Schuh8c399962020-12-25 21:51:45 -08001273 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001274
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001275 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001276 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001277
1278 // This sends out the fetched messages and advances time to the start of the
1279 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001280 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001281
Austin Schuhac0771c2020-01-07 18:36:30 -08001282 const Node *pi1 =
1283 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001284 const Node *pi2 =
1285 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001286
Austin Schuh2f8fd752020-09-01 22:38:28 -07001287 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1288 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1289 LOG(INFO) << "now pi1 "
1290 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1291 LOG(INFO) << "now pi2 "
1292 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1293
Austin Schuh07676622021-01-21 18:59:17 -08001294 EXPECT_THAT(reader.LoggedNodes(),
1295 ::testing::ElementsAre(
1296 configuration::GetNode(reader.logged_configuration(), pi1),
1297 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001298
1299 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001300
Austin Schuh6f3babe2020-01-26 20:34:50 -08001301 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001302 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001303 std::unique_ptr<EventLoop> pi2_event_loop =
1304 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001305
Austin Schuh6f3babe2020-01-26 20:34:50 -08001306 int pi1_ping_count = 10;
1307 int pi2_ping_count = 10;
1308 int pi1_pong_count = 10;
1309 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001310
1311 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001312 pi1_event_loop->MakeWatcher(
1313 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001314 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001315 << pi1_event_loop->context().monotonic_remote_time << " -> "
1316 << pi1_event_loop->context().monotonic_event_time;
1317 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1318 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1319 pi1_ping_count * chrono::milliseconds(10) +
1320 monotonic_clock::epoch());
1321 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1322 pi1_ping_count * chrono::milliseconds(10) +
1323 realtime_clock::epoch());
1324 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1325 pi1_event_loop->context().monotonic_event_time);
1326 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1327 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001328
Austin Schuh6f3babe2020-01-26 20:34:50 -08001329 ++pi1_ping_count;
1330 });
1331 pi2_event_loop->MakeWatcher(
1332 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001333 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001334 << pi2_event_loop->context().monotonic_remote_time << " -> "
1335 << pi2_event_loop->context().monotonic_event_time;
1336 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1337
1338 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1339 pi2_ping_count * chrono::milliseconds(10) +
1340 monotonic_clock::epoch());
1341 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1342 pi2_ping_count * chrono::milliseconds(10) +
1343 realtime_clock::epoch());
1344 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1345 chrono::microseconds(150),
1346 pi2_event_loop->context().monotonic_event_time);
1347 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1348 chrono::microseconds(150),
1349 pi2_event_loop->context().realtime_event_time);
1350 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001351 });
1352
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001353 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001354 // Confirm that the ping and pong counts both match, and the value also
1355 // matches.
1356 pi1_event_loop->MakeWatcher(
1357 "/test", [&pi1_event_loop, &pi1_ping_count,
1358 &pi1_pong_count](const examples::Pong &pong) {
1359 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1360 << pi1_event_loop->context().monotonic_remote_time << " -> "
1361 << pi1_event_loop->context().monotonic_event_time;
1362
1363 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1364 pi1_pong_count + kQueueIndexOffset);
1365 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1366 chrono::microseconds(200) +
1367 pi1_pong_count * chrono::milliseconds(10) +
1368 monotonic_clock::epoch());
1369 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1370 chrono::microseconds(200) +
1371 pi1_pong_count * chrono::milliseconds(10) +
1372 realtime_clock::epoch());
1373
1374 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1375 chrono::microseconds(150),
1376 pi1_event_loop->context().monotonic_event_time);
1377 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1378 chrono::microseconds(150),
1379 pi1_event_loop->context().realtime_event_time);
1380
1381 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1382 ++pi1_pong_count;
1383 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1384 });
1385 pi2_event_loop->MakeWatcher(
1386 "/test", [&pi2_event_loop, &pi2_ping_count,
1387 &pi2_pong_count](const examples::Pong &pong) {
1388 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1389 << pi2_event_loop->context().monotonic_remote_time << " -> "
1390 << pi2_event_loop->context().monotonic_event_time;
1391
1392 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001393 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001394
1395 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1396 chrono::microseconds(200) +
1397 pi2_pong_count * chrono::milliseconds(10) +
1398 monotonic_clock::epoch());
1399 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1400 chrono::microseconds(200) +
1401 pi2_pong_count * chrono::milliseconds(10) +
1402 realtime_clock::epoch());
1403
1404 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1405 pi2_event_loop->context().monotonic_event_time);
1406 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1407 pi2_event_loop->context().realtime_event_time);
1408
1409 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1410 ++pi2_pong_count;
1411 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1412 });
1413
1414 log_reader_factory.Run();
1415 EXPECT_EQ(pi1_ping_count, 2010);
1416 EXPECT_EQ(pi2_ping_count, 2010);
1417 EXPECT_EQ(pi1_pong_count, 2010);
1418 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001419
1420 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001421}
1422
James Kuszmaul46d82582020-05-09 19:50:09 -07001423typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1424
1425// Test that if we feed the replay with a mismatched node list that we die on
1426// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001427TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001428 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001429 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001430 LoggerState pi1_logger = MakeLogger(pi1_);
1431 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001432
1433 event_loop_factory_.RunFor(chrono::milliseconds(95));
1434
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001435 StartLogger(&pi1_logger);
1436 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001437
James Kuszmaul46d82582020-05-09 19:50:09 -07001438 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1439 }
1440
1441 // Test that, if we add an additional node to the replay config that the
1442 // logger complains about the mismatch in number of nodes.
1443 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1444 configuration::MergeWithConfig(&config_.message(), R"({
1445 "nodes": [
1446 {
1447 "name": "extra-node"
1448 }
1449 ]
1450 }
1451 )");
1452
Austin Schuh287d43d2020-12-04 20:19:33 -08001453 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1454 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001455 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001456}
1457
Austin Schuhcde938c2020-02-02 17:30:07 -08001458// Tests that we can read log files where they don't start at the same monotonic
1459// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001460TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001461 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001462 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001463 LoggerState pi1_logger = MakeLogger(pi1_);
1464 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001465
1466 event_loop_factory_.RunFor(chrono::milliseconds(95));
1467
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001468 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001469
1470 event_loop_factory_.RunFor(chrono::milliseconds(200));
1471
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001472 StartLogger(&pi2_logger);
1473
Austin Schuhcde938c2020-02-02 17:30:07 -08001474 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1475 }
1476
Austin Schuhe46492f2021-07-31 19:49:41 -07001477 // Since we delay starting pi2, it already knows about all the timestamps so
1478 // we don't end up with extra parts.
1479 LogReader reader(
1480 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001481
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001482 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001483 log_reader_factory.set_send_delay(chrono::microseconds(0));
1484
1485 // This sends out the fetched messages and advances time to the start of the
1486 // log file.
1487 reader.Register(&log_reader_factory);
1488
1489 const Node *pi1 =
1490 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1491 const Node *pi2 =
1492 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1493
Austin Schuh07676622021-01-21 18:59:17 -08001494 EXPECT_THAT(reader.LoggedNodes(),
1495 ::testing::ElementsAre(
1496 configuration::GetNode(reader.logged_configuration(), pi1),
1497 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001498
1499 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1500
1501 std::unique_ptr<EventLoop> pi1_event_loop =
1502 log_reader_factory.MakeEventLoop("test", pi1);
1503 std::unique_ptr<EventLoop> pi2_event_loop =
1504 log_reader_factory.MakeEventLoop("test", pi2);
1505
1506 int pi1_ping_count = 30;
1507 int pi2_ping_count = 30;
1508 int pi1_pong_count = 30;
1509 int pi2_pong_count = 30;
1510
1511 // Confirm that the ping value matches.
1512 pi1_event_loop->MakeWatcher(
1513 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1514 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1515 << pi1_event_loop->context().monotonic_remote_time << " -> "
1516 << pi1_event_loop->context().monotonic_event_time;
1517 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1518
1519 ++pi1_ping_count;
1520 });
1521 pi2_event_loop->MakeWatcher(
1522 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1523 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1524 << pi2_event_loop->context().monotonic_remote_time << " -> "
1525 << pi2_event_loop->context().monotonic_event_time;
1526 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1527
1528 ++pi2_ping_count;
1529 });
1530
1531 // Confirm that the ping and pong counts both match, and the value also
1532 // matches.
1533 pi1_event_loop->MakeWatcher(
1534 "/test", [&pi1_event_loop, &pi1_ping_count,
1535 &pi1_pong_count](const examples::Pong &pong) {
1536 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1537 << pi1_event_loop->context().monotonic_remote_time << " -> "
1538 << pi1_event_loop->context().monotonic_event_time;
1539
1540 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1541 ++pi1_pong_count;
1542 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1543 });
1544 pi2_event_loop->MakeWatcher(
1545 "/test", [&pi2_event_loop, &pi2_ping_count,
1546 &pi2_pong_count](const examples::Pong &pong) {
1547 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1548 << pi2_event_loop->context().monotonic_remote_time << " -> "
1549 << pi2_event_loop->context().monotonic_event_time;
1550
1551 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1552 ++pi2_pong_count;
1553 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1554 });
1555
1556 log_reader_factory.Run();
1557 EXPECT_EQ(pi1_ping_count, 2030);
1558 EXPECT_EQ(pi2_ping_count, 2030);
1559 EXPECT_EQ(pi1_pong_count, 2030);
1560 EXPECT_EQ(pi2_pong_count, 2030);
1561
1562 reader.Deregister();
1563}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001564
Austin Schuh8bd96322020-02-13 21:18:22 -08001565// Tests that we can read log files where the monotonic clocks drift and don't
1566// match correctly. While we are here, also test that different ending times
1567// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001568TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001569 // TODO(austin): Negate...
1570 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1571
Austin Schuh66168842021-08-17 19:42:21 -07001572 time_converter_.AddMonotonic(
1573 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001574 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1575 // skew to be 200 uS/s
1576 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1577 {chrono::milliseconds(95),
1578 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1579 // Run another 200 ms to have one logger start first.
1580 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1581 {chrono::milliseconds(200), chrono::milliseconds(200)});
1582 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1583 // go far enough to cause problems if this isn't accounted for.
1584 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1585 {chrono::milliseconds(20000),
1586 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1587 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1588 {chrono::milliseconds(40000),
1589 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1590 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1591 {chrono::milliseconds(400), chrono::milliseconds(400)});
1592
Austin Schuhcde938c2020-02-02 17:30:07 -08001593 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001594 LoggerState pi2_logger = MakeLogger(pi2_);
1595
Austin Schuh58646e22021-08-23 23:51:46 -07001596 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1597 << pi2_->realtime_now() << " distributed "
1598 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001599
Austin Schuh58646e22021-08-23 23:51:46 -07001600 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1601 << pi2_->realtime_now() << " distributed "
1602 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001603
Austin Schuh87dd3832021-01-01 23:07:31 -08001604 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001605
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001606 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001607
Austin Schuh87dd3832021-01-01 23:07:31 -08001608 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001609
Austin Schuh8bd96322020-02-13 21:18:22 -08001610 {
1611 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001612 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001613
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001614 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001615 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001616
Austin Schuh87dd3832021-01-01 23:07:31 -08001617 // Make sure we slewed time far enough so that the difference is greater
1618 // than the network delay. This confirms that if we sort incorrectly, it
1619 // would show in the results.
1620 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001621 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001622 -event_loop_factory_.send_delay() -
1623 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001624
Austin Schuh87dd3832021-01-01 23:07:31 -08001625 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001626
Austin Schuh87dd3832021-01-01 23:07:31 -08001627 // And now check that we went far enough the other way to make sure we
1628 // cover both problems.
1629 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001630 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001631 event_loop_factory_.send_delay() +
1632 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001633 }
1634
1635 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001636 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001637 }
1638
Austin Schuh72211ae2021-08-05 14:02:30 -07001639 LogReader reader(
1640 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001641
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001642 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001643 log_reader_factory.set_send_delay(chrono::microseconds(0));
1644
Austin Schuhcde938c2020-02-02 17:30:07 -08001645 const Node *pi1 =
1646 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1647 const Node *pi2 =
1648 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1649
Austin Schuh2f8fd752020-09-01 22:38:28 -07001650 // This sends out the fetched messages and advances time to the start of the
1651 // log file.
1652 reader.Register(&log_reader_factory);
1653
1654 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1655 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1656 LOG(INFO) << "now pi1 "
1657 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1658 LOG(INFO) << "now pi2 "
1659 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1660
Austin Schuhcde938c2020-02-02 17:30:07 -08001661 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001662 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1663 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001664 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1665 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001666 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1667 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001668 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1669
Austin Schuh07676622021-01-21 18:59:17 -08001670 EXPECT_THAT(reader.LoggedNodes(),
1671 ::testing::ElementsAre(
1672 configuration::GetNode(reader.logged_configuration(), pi1),
1673 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001674
1675 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1676
1677 std::unique_ptr<EventLoop> pi1_event_loop =
1678 log_reader_factory.MakeEventLoop("test", pi1);
1679 std::unique_ptr<EventLoop> pi2_event_loop =
1680 log_reader_factory.MakeEventLoop("test", pi2);
1681
1682 int pi1_ping_count = 30;
1683 int pi2_ping_count = 30;
1684 int pi1_pong_count = 30;
1685 int pi2_pong_count = 30;
1686
1687 // Confirm that the ping value matches.
1688 pi1_event_loop->MakeWatcher(
1689 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1690 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1691 << pi1_event_loop->context().monotonic_remote_time << " -> "
1692 << pi1_event_loop->context().monotonic_event_time;
1693 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1694
1695 ++pi1_ping_count;
1696 });
1697 pi2_event_loop->MakeWatcher(
1698 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1699 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1700 << pi2_event_loop->context().monotonic_remote_time << " -> "
1701 << pi2_event_loop->context().monotonic_event_time;
1702 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1703
1704 ++pi2_ping_count;
1705 });
1706
1707 // Confirm that the ping and pong counts both match, and the value also
1708 // matches.
1709 pi1_event_loop->MakeWatcher(
1710 "/test", [&pi1_event_loop, &pi1_ping_count,
1711 &pi1_pong_count](const examples::Pong &pong) {
1712 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1713 << pi1_event_loop->context().monotonic_remote_time << " -> "
1714 << pi1_event_loop->context().monotonic_event_time;
1715
1716 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1717 ++pi1_pong_count;
1718 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1719 });
1720 pi2_event_loop->MakeWatcher(
1721 "/test", [&pi2_event_loop, &pi2_ping_count,
1722 &pi2_pong_count](const examples::Pong &pong) {
1723 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1724 << pi2_event_loop->context().monotonic_remote_time << " -> "
1725 << pi2_event_loop->context().monotonic_event_time;
1726
1727 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1728 ++pi2_pong_count;
1729 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1730 });
1731
1732 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001733 EXPECT_EQ(pi1_ping_count, 6030);
1734 EXPECT_EQ(pi2_ping_count, 6030);
1735 EXPECT_EQ(pi1_pong_count, 6030);
1736 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001737
1738 reader.Deregister();
1739}
1740
Austin Schuh5212cad2020-09-09 23:12:09 -07001741// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001742TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001743 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001744 // Make a bunch of parts.
1745 {
1746 LoggerState pi1_logger = MakeLogger(pi1_);
1747 LoggerState pi2_logger = MakeLogger(pi2_);
1748
1749 event_loop_factory_.RunFor(chrono::milliseconds(95));
1750
1751 StartLogger(&pi1_logger);
1752 StartLogger(&pi2_logger);
1753
1754 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1755 }
1756
Austin Schuh11d43732020-09-21 17:28:30 -07001757 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001758 VerifyParts(sorted_parts);
1759}
Austin Schuh11d43732020-09-21 17:28:30 -07001760
Austin Schuh3bd4c402020-11-06 18:19:06 -08001761// Tests that we can sort a bunch of parts with an empty part. We should ignore
1762// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001763TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001764 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001765 // Make a bunch of parts.
1766 {
1767 LoggerState pi1_logger = MakeLogger(pi1_);
1768 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001769
Austin Schuh3bd4c402020-11-06 18:19:06 -08001770 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001771
Austin Schuh3bd4c402020-11-06 18:19:06 -08001772 StartLogger(&pi1_logger);
1773 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001774
Austin Schuh3bd4c402020-11-06 18:19:06 -08001775 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001776 }
1777
Austin Schuh3bd4c402020-11-06 18:19:06 -08001778 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001779 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001780
Austin Schuh3bd4c402020-11-06 18:19:06 -08001781 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1782 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001783
Austin Schuh3bd4c402020-11-06 18:19:06 -08001784 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1785 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001786}
1787
James Kuszmauldd0a5042021-10-28 23:38:04 -07001788// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08001789// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001790TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001791 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001792 // Make a bunch of parts.
1793 {
1794 LoggerState pi1_logger = MakeLogger(pi1_);
1795 LoggerState pi2_logger = MakeLogger(pi2_);
1796
1797 event_loop_factory_.RunFor(chrono::milliseconds(95));
1798
James Kuszmauldd0a5042021-10-28 23:38:04 -07001799 StartLogger(&pi1_logger);
1800 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001801
1802 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1803 }
1804
Austin Schuh3bd4c402020-11-06 18:19:06 -08001805 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001806 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1807 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08001808 ::std::string compressed_contents =
James Kuszmauldd0a5042021-10-28 23:38:04 -07001809 aos::util::ReadFileToStringOrDie(logfiles_[3]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001810
1811 aos::util::WriteStringToFileOrDie(
James Kuszmauldd0a5042021-10-28 23:38:04 -07001812 logfiles_[3],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001813 compressed_contents.substr(0, compressed_contents.size() - 100));
1814
1815 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1816 VerifyParts(sorted_parts);
1817}
Austin Schuh3bd4c402020-11-06 18:19:06 -08001818
Austin Schuh01b4c352020-09-21 23:09:39 -07001819// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001820TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001821 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001822 {
1823 LoggerState pi1_logger = MakeLogger(pi1_);
1824 LoggerState pi2_logger = MakeLogger(pi2_);
1825
1826 event_loop_factory_.RunFor(chrono::milliseconds(95));
1827
1828 StartLogger(&pi1_logger);
1829 StartLogger(&pi2_logger);
1830
1831 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1832 }
1833
Austin Schuh287d43d2020-12-04 20:19:33 -08001834 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001835
1836 // Remap just on pi1.
1837 reader.RemapLoggedChannel<aos::timing::Report>(
1838 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1839
1840 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1841 log_reader_factory.set_send_delay(chrono::microseconds(0));
1842
Austin Schuh1c227352021-09-17 12:53:54 -07001843 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1844 ASSERT_EQ(remapped_channels.size(), 1u);
1845 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1846 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1847
Austin Schuh01b4c352020-09-21 23:09:39 -07001848 reader.Register(&log_reader_factory);
1849
1850 const Node *pi1 =
1851 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1852 const Node *pi2 =
1853 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1854
1855 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1856 // else should have moved.
1857 std::unique_ptr<EventLoop> pi1_event_loop =
1858 log_reader_factory.MakeEventLoop("test", pi1);
1859 pi1_event_loop->SkipTimingReport();
1860 std::unique_ptr<EventLoop> full_pi1_event_loop =
1861 log_reader_factory.MakeEventLoop("test", pi1);
1862 full_pi1_event_loop->SkipTimingReport();
1863 std::unique_ptr<EventLoop> pi2_event_loop =
1864 log_reader_factory.MakeEventLoop("test", pi2);
1865 pi2_event_loop->SkipTimingReport();
1866
1867 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1868 "/aos");
1869 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1870 full_pi1_event_loop.get(), "/pi1/aos");
1871 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1872 pi1_event_loop.get(), "/original/aos");
1873 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1874 full_pi1_event_loop.get(), "/original/pi1/aos");
1875 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1876 "/aos");
1877
1878 log_reader_factory.Run();
1879
1880 EXPECT_EQ(pi1_timing_report.count(), 0u);
1881 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1882 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1883 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1884 EXPECT_NE(pi2_timing_report.count(), 0u);
1885
1886 reader.Deregister();
1887}
1888
Austin Schuh006a9f52021-04-07 16:24:18 -07001889// Tests that we can remap a forwarded channel as well.
1890TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1891 time_converter_.StartEqual();
1892 {
1893 LoggerState pi1_logger = MakeLogger(pi1_);
1894 LoggerState pi2_logger = MakeLogger(pi2_);
1895
1896 event_loop_factory_.RunFor(chrono::milliseconds(95));
1897
1898 StartLogger(&pi1_logger);
1899 StartLogger(&pi2_logger);
1900
1901 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1902 }
1903
1904 LogReader reader(SortParts(logfiles_));
1905
1906 reader.RemapLoggedChannel<examples::Ping>("/test");
1907
1908 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1909 log_reader_factory.set_send_delay(chrono::microseconds(0));
1910
1911 reader.Register(&log_reader_factory);
1912
1913 const Node *pi1 =
1914 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1915 const Node *pi2 =
1916 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1917
1918 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1919 // else should have moved.
1920 std::unique_ptr<EventLoop> pi1_event_loop =
1921 log_reader_factory.MakeEventLoop("test", pi1);
1922 pi1_event_loop->SkipTimingReport();
1923 std::unique_ptr<EventLoop> full_pi1_event_loop =
1924 log_reader_factory.MakeEventLoop("test", pi1);
1925 full_pi1_event_loop->SkipTimingReport();
1926 std::unique_ptr<EventLoop> pi2_event_loop =
1927 log_reader_factory.MakeEventLoop("test", pi2);
1928 pi2_event_loop->SkipTimingReport();
1929
1930 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1931 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1932 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1933 "/original/test");
1934 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1935 "/original/test");
1936
1937 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1938 pi1_original_ping_timestamp;
1939 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1940 pi1_ping_timestamp;
1941 if (!shared()) {
1942 pi1_original_ping_timestamp =
1943 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1944 pi1_event_loop.get(),
1945 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1946 pi1_ping_timestamp =
1947 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1948 pi1_event_loop.get(),
1949 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1950 }
1951
1952 log_reader_factory.Run();
1953
1954 EXPECT_EQ(pi1_ping.count(), 0u);
1955 EXPECT_EQ(pi2_ping.count(), 0u);
1956 EXPECT_NE(pi1_original_ping.count(), 0u);
1957 EXPECT_NE(pi2_original_ping.count(), 0u);
1958 if (!shared()) {
1959 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1960 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1961 }
1962
1963 reader.Deregister();
1964}
1965
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001966// Tests that we properly recreate forwarded timestamps when replaying a log.
1967// This should be enough that we can then re-run the logger and get a valid log
1968// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001969TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001970 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001971 {
1972 LoggerState pi1_logger = MakeLogger(pi1_);
1973 LoggerState pi2_logger = MakeLogger(pi2_);
1974
1975 event_loop_factory_.RunFor(chrono::milliseconds(95));
1976
1977 StartLogger(&pi1_logger);
1978 StartLogger(&pi2_logger);
1979
1980 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1981 }
1982
Austin Schuh287d43d2020-12-04 20:19:33 -08001983 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001984
1985 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1986 log_reader_factory.set_send_delay(chrono::microseconds(0));
1987
1988 // This sends out the fetched messages and advances time to the start of the
1989 // log file.
1990 reader.Register(&log_reader_factory);
1991
1992 const Node *pi1 =
1993 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1994 const Node *pi2 =
1995 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1996
1997 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1998 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1999 LOG(INFO) << "now pi1 "
2000 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2001 LOG(INFO) << "now pi2 "
2002 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2003
Austin Schuh07676622021-01-21 18:59:17 -08002004 EXPECT_THAT(reader.LoggedNodes(),
2005 ::testing::ElementsAre(
2006 configuration::GetNode(reader.logged_configuration(), pi1),
2007 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002008
2009 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2010
2011 std::unique_ptr<EventLoop> pi1_event_loop =
2012 log_reader_factory.MakeEventLoop("test", pi1);
2013 std::unique_ptr<EventLoop> pi2_event_loop =
2014 log_reader_factory.MakeEventLoop("test", pi2);
2015
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002016 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2017 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2018 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2019 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2020
2021 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2022 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2023 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2024 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2025
2026 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2027 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2028 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2029 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2030
2031 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2032 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2033 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2034 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2035
2036 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2037 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2038 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2039 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2040
2041 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2042 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2043 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2044 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2045
Austin Schuh969cd602021-01-03 00:09:45 -08002046 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002047 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002048
Austin Schuh61e973f2021-02-21 21:43:56 -08002049 for (std::pair<int, std::string> channel :
2050 shared()
2051 ? std::vector<
2052 std::pair<int, std::string>>{{-1,
2053 "/aos/remote_timestamps/pi2"}}
2054 : std::vector<std::pair<int, std::string>>{
2055 {pi1_timestamp_channel,
2056 "/aos/remote_timestamps/pi2/pi1/aos/"
2057 "aos-message_bridge-Timestamp"},
2058 {ping_timestamp_channel,
2059 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2060 pi1_event_loop->MakeWatcher(
2061 channel.second,
2062 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2063 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2064 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2065 &ping_on_pi2_fetcher, network_delay, send_delay,
2066 channel_index = channel.first](const RemoteMessage &header) {
2067 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2068 chrono::nanoseconds(header.monotonic_sent_time()));
2069 const aos::realtime_clock::time_point header_realtime_sent_time(
2070 chrono::nanoseconds(header.realtime_sent_time()));
2071 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2072 chrono::nanoseconds(header.monotonic_remote_time()));
2073 const aos::realtime_clock::time_point header_realtime_remote_time(
2074 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002075
Austin Schuh61e973f2021-02-21 21:43:56 -08002076 if (channel_index != -1) {
2077 ASSERT_EQ(channel_index, header.channel_index());
2078 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002079
Austin Schuh61e973f2021-02-21 21:43:56 -08002080 const Context *pi1_context = nullptr;
2081 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002082
Austin Schuh61e973f2021-02-21 21:43:56 -08002083 if (header.channel_index() == pi1_timestamp_channel) {
2084 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2085 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2086 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2087 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2088 } else if (header.channel_index() == ping_timestamp_channel) {
2089 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2090 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2091 pi1_context = &ping_on_pi1_fetcher.context();
2092 pi2_context = &ping_on_pi2_fetcher.context();
2093 } else {
2094 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2095 << configuration::CleanedChannelToString(
2096 pi1_event_loop->configuration()->channels()->Get(
2097 header.channel_index()));
2098 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002099
Austin Schuh61e973f2021-02-21 21:43:56 -08002100 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002101 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2102 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002103
Austin Schuh61e973f2021-02-21 21:43:56 -08002104 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2105 EXPECT_EQ(pi2_context->remote_queue_index,
2106 header.remote_queue_index());
2107 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002108
Austin Schuh61e973f2021-02-21 21:43:56 -08002109 EXPECT_EQ(pi2_context->monotonic_event_time,
2110 header_monotonic_sent_time);
2111 EXPECT_EQ(pi2_context->realtime_event_time,
2112 header_realtime_sent_time);
2113 EXPECT_EQ(pi2_context->realtime_remote_time,
2114 header_realtime_remote_time);
2115 EXPECT_EQ(pi2_context->monotonic_remote_time,
2116 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002117
Austin Schuh61e973f2021-02-21 21:43:56 -08002118 EXPECT_EQ(pi1_context->realtime_event_time,
2119 header_realtime_remote_time);
2120 EXPECT_EQ(pi1_context->monotonic_event_time,
2121 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002122
Austin Schuh61e973f2021-02-21 21:43:56 -08002123 // Time estimation isn't perfect, but we know the clocks were
2124 // identical when logged, so we know when this should have come back.
2125 // Confirm we got it when we expected.
2126 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2127 pi1_context->monotonic_event_time + 2 * network_delay +
2128 send_delay);
2129 });
2130 }
2131 for (std::pair<int, std::string> channel :
2132 shared()
2133 ? std::vector<
2134 std::pair<int, std::string>>{{-1,
2135 "/aos/remote_timestamps/pi1"}}
2136 : std::vector<std::pair<int, std::string>>{
2137 {pi2_timestamp_channel,
2138 "/aos/remote_timestamps/pi1/pi2/aos/"
2139 "aos-message_bridge-Timestamp"}}) {
2140 pi2_event_loop->MakeWatcher(
2141 channel.second,
2142 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2143 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2144 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2145 &pong_on_pi1_fetcher, network_delay, send_delay,
2146 channel_index = channel.first](const RemoteMessage &header) {
2147 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2148 chrono::nanoseconds(header.monotonic_sent_time()));
2149 const aos::realtime_clock::time_point header_realtime_sent_time(
2150 chrono::nanoseconds(header.realtime_sent_time()));
2151 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2152 chrono::nanoseconds(header.monotonic_remote_time()));
2153 const aos::realtime_clock::time_point header_realtime_remote_time(
2154 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002155
Austin Schuh61e973f2021-02-21 21:43:56 -08002156 if (channel_index != -1) {
2157 ASSERT_EQ(channel_index, header.channel_index());
2158 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002159
Austin Schuh61e973f2021-02-21 21:43:56 -08002160 const Context *pi2_context = nullptr;
2161 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002162
Austin Schuh61e973f2021-02-21 21:43:56 -08002163 if (header.channel_index() == pi2_timestamp_channel) {
2164 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2165 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2166 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2167 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2168 } else if (header.channel_index() == pong_timestamp_channel) {
2169 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2170 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2171 pi2_context = &pong_on_pi2_fetcher.context();
2172 pi1_context = &pong_on_pi1_fetcher.context();
2173 } else {
2174 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2175 << configuration::CleanedChannelToString(
2176 pi2_event_loop->configuration()->channels()->Get(
2177 header.channel_index()));
2178 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002179
Austin Schuh61e973f2021-02-21 21:43:56 -08002180 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002181 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2182 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002183
Austin Schuh61e973f2021-02-21 21:43:56 -08002184 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2185 EXPECT_EQ(pi1_context->remote_queue_index,
2186 header.remote_queue_index());
2187 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002188
Austin Schuh61e973f2021-02-21 21:43:56 -08002189 EXPECT_EQ(pi1_context->monotonic_event_time,
2190 header_monotonic_sent_time);
2191 EXPECT_EQ(pi1_context->realtime_event_time,
2192 header_realtime_sent_time);
2193 EXPECT_EQ(pi1_context->realtime_remote_time,
2194 header_realtime_remote_time);
2195 EXPECT_EQ(pi1_context->monotonic_remote_time,
2196 header_monotonic_remote_time);
2197
2198 EXPECT_EQ(pi2_context->realtime_event_time,
2199 header_realtime_remote_time);
2200 EXPECT_EQ(pi2_context->monotonic_event_time,
2201 header_monotonic_remote_time);
2202
2203 // Time estimation isn't perfect, but we know the clocks were
2204 // identical when logged, so we know when this should have come back.
2205 // Confirm we got it when we expected.
2206 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2207 pi2_context->monotonic_event_time + 2 * network_delay +
2208 send_delay);
2209 });
2210 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002211
2212 // And confirm we can re-create a log again, while checking the contents.
2213 {
2214 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002215 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002216 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002217 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002218
Austin Schuh25b46712021-01-03 00:04:38 -08002219 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2220 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002221
2222 log_reader_factory.Run();
2223 }
2224
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002225 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002226
2227 // And verify that we can run the LogReader over the relogged files without
2228 // hitting any fatal errors.
2229 {
2230 LogReader relogged_reader(SortParts(
2231 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2232 relogged_reader.Register();
2233
2234 relogged_reader.event_loop_factory()->Run();
2235 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002236}
2237
Austin Schuh315b96b2020-12-11 21:21:12 -08002238// Tests that we properly populate and extract the logger_start time by setting
2239// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002240TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002241 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002242 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002243 {
2244 LoggerState pi1_logger = MakeLogger(pi1_);
2245 LoggerState pi2_logger = MakeLogger(pi2_);
2246
Austin Schuh315b96b2020-12-11 21:21:12 -08002247 StartLogger(&pi1_logger);
2248 StartLogger(&pi2_logger);
2249
2250 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2251 }
2252
2253 for (const LogFile &log_file : SortParts(logfiles_)) {
2254 for (const LogParts &log_part : log_file.parts) {
2255 if (log_part.node == log_file.logger_node) {
2256 EXPECT_EQ(log_part.logger_monotonic_start_time,
2257 aos::monotonic_clock::min_time);
2258 EXPECT_EQ(log_part.logger_realtime_start_time,
2259 aos::realtime_clock::min_time);
2260 } else {
2261 const chrono::seconds offset = log_file.logger_node == "pi1"
2262 ? -chrono::seconds(1000)
2263 : chrono::seconds(1000);
2264 EXPECT_EQ(log_part.logger_monotonic_start_time,
2265 log_part.monotonic_start_time + offset);
2266 EXPECT_EQ(log_part.logger_realtime_start_time,
2267 log_file.realtime_start_time +
2268 (log_part.logger_monotonic_start_time -
2269 log_file.monotonic_start_time));
2270 }
2271 }
2272 }
2273}
2274
Austin Schuh6bb8a822021-03-31 23:04:39 -07002275// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002276TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002277 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2278 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002279 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002280 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002281 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2282 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2283 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2284 LoggerState pi1_logger = MakeLogger(pi1_);
2285 LoggerState pi2_logger = MakeLogger(pi2_);
2286
2287 StartLogger(&pi1_logger);
2288 StartLogger(&pi2_logger);
2289
2290 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2291 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2292 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2293 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2294 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2295 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2296 for (auto &file : logfiles_) {
2297 struct stat s;
2298 EXPECT_EQ(0, stat(file.c_str(), &s));
2299 }
2300}
2301
2302// Test that renaming the file base dies.
2303TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2304 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002305 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002306 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002307 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2308 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2309 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2310 LoggerState pi1_logger = MakeLogger(pi1_);
2311 StartLogger(&pi1_logger);
2312 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2313 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2314 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2315 "Rename of file base from");
2316}
2317
Austin Schuh8bd96322020-02-13 21:18:22 -08002318// TODO(austin): We can write a test which recreates a logfile and confirms that
2319// we get it back. That is the ultimate test.
2320
Austin Schuh315b96b2020-12-11 21:21:12 -08002321// Tests that we properly recreate forwarded timestamps when replaying a log.
2322// This should be enough that we can then re-run the logger and get a valid log
2323// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002324TEST_P(MultinodeLoggerTest, RemoteReboot) {
2325 const UUID pi1_boot0 = UUID::Random();
2326 const UUID pi2_boot0 = UUID::Random();
2327 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002328 {
Austin Schuh58646e22021-08-23 23:51:46 -07002329 CHECK_EQ(pi1_index_, 0u);
2330 CHECK_EQ(pi2_index_, 1u);
2331
2332 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2333 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2334 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2335
2336 time_converter_.AddNextTimestamp(
2337 distributed_clock::epoch(),
2338 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2339 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2340 time_converter_.AddNextTimestamp(
2341 distributed_clock::epoch() + reboot_time,
2342 {BootTimestamp::epoch() + reboot_time,
2343 BootTimestamp{
2344 .boot = 1,
2345 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2346 }
2347
2348 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002349 LoggerState pi1_logger = MakeLogger(pi1_);
2350
2351 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002352 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2353 pi1_boot0);
2354 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2355 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002356
2357 StartLogger(&pi1_logger);
2358
2359 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2360
Austin Schuh58646e22021-08-23 23:51:46 -07002361 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002362
2363 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002364 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2365 pi1_boot0);
2366 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2367 pi2_boot1);
Austin Schuh315b96b2020-12-11 21:21:12 -08002368 }
2369
Austin Schuh72211ae2021-08-05 14:02:30 -07002370 // Confirm that our new oldest timestamps properly update as we reboot and
2371 // rotate.
2372 for (const std::string &file : pi1_reboot_logfiles_) {
2373 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2374 ReadHeader(file);
2375 CHECK(log_header);
2376 if (log_header->message().has_configuration()) {
2377 continue;
2378 }
2379
Austin Schuh58646e22021-08-23 23:51:46 -07002380 const monotonic_clock::time_point monotonic_start_time =
2381 monotonic_clock::time_point(
2382 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2383 const UUID source_node_boot_uuid = UUID::FromString(
2384 log_header->message().source_node_boot_uuid()->string_view());
2385
Austin Schuh72211ae2021-08-05 14:02:30 -07002386 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh58646e22021-08-23 23:51:46 -07002387 switch (log_header->message().parts_index()) {
2388 case 0:
2389 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2390 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2391 break;
2392 case 1:
2393 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2394 ASSERT_EQ(monotonic_start_time,
2395 monotonic_clock::epoch() + chrono::seconds(1));
2396 break;
2397 case 2:
2398 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2399 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2400 break;
2401 case 3:
2402 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2403 ASSERT_EQ(monotonic_start_time,
2404 monotonic_clock::epoch() + chrono::nanoseconds(2322999462));
2405 break;
2406 default:
2407 FAIL();
2408 break;
2409 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002410 continue;
2411 }
2412 SCOPED_TRACE(file);
2413 SCOPED_TRACE(aos::FlatbufferToJson(
2414 *log_header, {.multi_line = true, .max_vector_size = 100}));
2415 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2416 ASSERT_EQ(
2417 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2418 EXPECT_EQ(
2419 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2420 monotonic_clock::max_time.time_since_epoch().count());
2421 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2422 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2423 2u);
2424 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2425 monotonic_clock::max_time.time_since_epoch().count());
2426 ASSERT_TRUE(log_header->message()
2427 .has_oldest_remote_unreliable_monotonic_timestamps());
2428 ASSERT_EQ(log_header->message()
2429 .oldest_remote_unreliable_monotonic_timestamps()
2430 ->size(),
2431 2u);
2432 EXPECT_EQ(log_header->message()
2433 .oldest_remote_unreliable_monotonic_timestamps()
2434 ->Get(0),
2435 monotonic_clock::max_time.time_since_epoch().count());
2436 ASSERT_TRUE(log_header->message()
2437 .has_oldest_local_unreliable_monotonic_timestamps());
2438 ASSERT_EQ(log_header->message()
2439 .oldest_local_unreliable_monotonic_timestamps()
2440 ->size(),
2441 2u);
2442 EXPECT_EQ(log_header->message()
2443 .oldest_local_unreliable_monotonic_timestamps()
2444 ->Get(0),
2445 monotonic_clock::max_time.time_since_epoch().count());
2446
2447 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2448 monotonic_clock::time_point(chrono::nanoseconds(
2449 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2450 1)));
2451 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2452 monotonic_clock::time_point(chrono::nanoseconds(
2453 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2454 const monotonic_clock::time_point
2455 oldest_remote_unreliable_monotonic_timestamps =
2456 monotonic_clock::time_point(chrono::nanoseconds(
2457 log_header->message()
2458 .oldest_remote_unreliable_monotonic_timestamps()
2459 ->Get(1)));
2460 const monotonic_clock::time_point
2461 oldest_local_unreliable_monotonic_timestamps =
2462 monotonic_clock::time_point(chrono::nanoseconds(
2463 log_header->message()
2464 .oldest_local_unreliable_monotonic_timestamps()
2465 ->Get(1)));
2466 switch (log_header->message().parts_index()) {
2467 case 0:
2468 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2469 monotonic_clock::max_time);
2470 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2471 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2472 monotonic_clock::max_time);
2473 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2474 monotonic_clock::max_time);
2475 break;
2476 case 1:
2477 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2478 monotonic_clock::time_point(chrono::microseconds(90200)));
2479 EXPECT_EQ(oldest_local_monotonic_timestamps,
2480 monotonic_clock::time_point(chrono::microseconds(90350)));
2481 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2482 monotonic_clock::time_point(chrono::microseconds(90200)));
2483 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2484 monotonic_clock::time_point(chrono::microseconds(90350)));
2485 break;
2486 case 2:
2487 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002488 monotonic_clock::time_point(chrono::milliseconds(1323) +
2489 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002490 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002491 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002492 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002493 monotonic_clock::time_point(chrono::milliseconds(1323) +
2494 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002495 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2496 monotonic_clock::time_point(chrono::microseconds(10100350)));
2497 break;
2498 default:
2499 FAIL();
2500 break;
2501 }
2502 }
2503
Austin Schuh315b96b2020-12-11 21:21:12 -08002504 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002505 {
2506 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002507
Austin Schuh58646e22021-08-23 23:51:46 -07002508 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2509 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002510
Austin Schuh58646e22021-08-23 23:51:46 -07002511 // This sends out the fetched messages and advances time to the start of
2512 // the log file.
2513 reader.Register(&log_reader_factory);
2514
2515 log_reader_factory.Run();
2516
2517 reader.Deregister();
2518 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002519}
2520
Austin Schuhc9049732020-12-21 22:27:15 -08002521// Tests that we properly handle one direction of message_bridge being
2522// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002523TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002524 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002525 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002526 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002527
2528 time_converter_.AddMonotonic(
2529 {chrono::milliseconds(10000),
2530 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002531 {
2532 LoggerState pi1_logger = MakeLogger(pi1_);
2533
2534 event_loop_factory_.RunFor(chrono::milliseconds(95));
2535
2536 StartLogger(&pi1_logger);
2537
2538 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2539 }
2540
2541 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2542 // to confirm the right thing happened.
2543 ConfirmReadable(pi1_single_direction_logfiles_);
2544}
2545
2546// Tests that we properly handle one direction of message_bridge being
2547// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002548TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002549 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002550 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002551 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002552
2553 time_converter_.AddMonotonic(
2554 {chrono::milliseconds(10000),
2555 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2556 {
2557 LoggerState pi1_logger = MakeLogger(pi1_);
2558
2559 event_loop_factory_.RunFor(chrono::milliseconds(95));
2560
2561 StartLogger(&pi1_logger);
2562
2563 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2564 }
2565
2566 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2567 // to confirm the right thing happened.
2568 ConfirmReadable(pi1_single_direction_logfiles_);
2569}
2570
Austin Schuhe9f00232021-09-16 18:04:23 -07002571// Tests that we explode if someone passes in a part file twice with a better
2572// error than an out of order error.
2573TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2574 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002575 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07002576 {
2577 LoggerState pi1_logger = MakeLogger(pi1_);
2578
2579 event_loop_factory_.RunFor(chrono::milliseconds(95));
2580
2581 StartLogger(&pi1_logger);
2582
2583 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2584 }
2585
2586 std::vector<std::string> duplicates;
2587 for (const std::string &f : pi1_single_direction_logfiles_) {
2588 duplicates.emplace_back(f);
2589 duplicates.emplace_back(f);
2590 }
2591 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
2592}
2593
Austin Schuh87dd3832021-01-01 23:07:31 -08002594// Tests that we properly handle a dead node. Do this by just disconnecting it
2595// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002596TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07002597 pi1_->Disconnect(pi2_->node());
2598 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002599 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002600 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002601 {
2602 LoggerState pi1_logger = MakeLogger(pi1_);
2603
2604 event_loop_factory_.RunFor(chrono::milliseconds(95));
2605
2606 StartLogger(&pi1_logger);
2607
2608 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2609 }
2610
2611 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2612 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002613 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002614}
2615
Austin Schuhcdd90272021-03-15 12:46:16 -07002616constexpr std::string_view kCombinedConfigSha1(
milind1f1dca32021-07-03 13:50:07 -07002617 "644a3ab079c3ddfb1ef866483cfca9ec015c4142202169081138f72664ffd589");
Austin Schuhcdd90272021-03-15 12:46:16 -07002618constexpr std::string_view kSplitConfigSha1(
milind1f1dca32021-07-03 13:50:07 -07002619 "20bb9f6ee89519c4bd49986f0afe497d61c71b29d846f2c51f51727c9ef37415");
Austin Schuhcdd90272021-03-15 12:46:16 -07002620
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002621INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002622 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002623 ::testing::Combine(::testing::Values(
2624 ConfigParams{
2625 "multinode_pingpong_combined_config.json", true,
2626 kCombinedConfigSha1},
2627 ConfigParams{"multinode_pingpong_split_config.json",
2628 false, kSplitConfigSha1}),
2629 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002630
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002631INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002632 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002633 ::testing::Combine(::testing::Values(
2634 ConfigParams{
2635 "multinode_pingpong_combined_config.json", true,
2636 kCombinedConfigSha1},
2637 ConfigParams{"multinode_pingpong_split_config.json",
2638 false, kSplitConfigSha1}),
2639 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002640
Austin Schuh5b728b72021-06-16 14:57:15 -07002641// Tests that we can relog with a different config. This makes most sense when
2642// you are trying to edit a log and want to use channel renaming + the original
2643// config in the new log.
2644TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
2645 time_converter_.StartEqual();
2646 {
2647 LoggerState pi1_logger = MakeLogger(pi1_);
2648 LoggerState pi2_logger = MakeLogger(pi2_);
2649
2650 event_loop_factory_.RunFor(chrono::milliseconds(95));
2651
2652 StartLogger(&pi1_logger);
2653 StartLogger(&pi2_logger);
2654
2655 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2656 }
2657
2658 LogReader reader(SortParts(logfiles_));
2659 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
2660
2661 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2662 log_reader_factory.set_send_delay(chrono::microseconds(0));
2663
2664 // This sends out the fetched messages and advances time to the start of the
2665 // log file.
2666 reader.Register(&log_reader_factory);
2667
2668 const Node *pi1 =
2669 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2670 const Node *pi2 =
2671 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2672
2673 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2674 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2675 LOG(INFO) << "now pi1 "
2676 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2677 LOG(INFO) << "now pi2 "
2678 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2679
2680 EXPECT_THAT(reader.LoggedNodes(),
2681 ::testing::ElementsAre(
2682 configuration::GetNode(reader.logged_configuration(), pi1),
2683 configuration::GetNode(reader.logged_configuration(), pi2)));
2684
2685 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2686
2687 // And confirm we can re-create a log again, while checking the contents.
2688 std::vector<std::string> log_files;
2689 {
2690 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002691 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002692 &log_reader_factory, reader.logged_configuration());
2693 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07002694 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07002695 &log_reader_factory, reader.logged_configuration());
2696
Austin Schuh3e20c692021-11-16 20:43:16 -08002697 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
2698 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07002699
2700 log_reader_factory.Run();
2701
2702 for (auto &x : pi1_logger.log_namer->all_filenames()) {
2703 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
2704 }
2705 for (auto &x : pi2_logger.log_namer->all_filenames()) {
2706 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
2707 }
2708 }
2709
2710 reader.Deregister();
2711
2712 // And verify that we can run the LogReader over the relogged files without
2713 // hitting any fatal errors.
2714 {
2715 LogReader relogged_reader(SortParts(log_files));
2716 relogged_reader.Register();
2717
2718 relogged_reader.event_loop_factory()->Run();
2719 }
2720}
Austin Schuha04efed2021-01-24 18:04:20 -08002721
Austin Schuh3e20c692021-11-16 20:43:16 -08002722// Tests that we properly replay a log where the start time for a node is before
2723// any data on the node. This can happen if the logger starts before data is
2724// published. While the scenario below is a bit convoluted, we have seen logs
2725// like this generated out in the wild.
2726TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
2727 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
2728 aos::configuration::ReadConfig(ArtifactPath(
2729 "aos/events/logging/multinode_pingpong_split3_config.json"));
2730 message_bridge::TestingTimeConverter time_converter(
2731 configuration::NodesCount(&config.message()));
2732 SimulatedEventLoopFactory event_loop_factory(&config.message());
2733 event_loop_factory.SetTimeConverter(&time_converter);
2734 NodeEventLoopFactory *const pi1 =
2735 event_loop_factory.GetNodeEventLoopFactory("pi1");
2736 const size_t pi1_index = configuration::GetNodeIndex(
2737 event_loop_factory.configuration(), pi1->node());
2738 NodeEventLoopFactory *const pi2 =
2739 event_loop_factory.GetNodeEventLoopFactory("pi2");
2740 const size_t pi2_index = configuration::GetNodeIndex(
2741 event_loop_factory.configuration(), pi2->node());
2742 NodeEventLoopFactory *const pi3 =
2743 event_loop_factory.GetNodeEventLoopFactory("pi3");
2744 const size_t pi3_index = configuration::GetNodeIndex(
2745 event_loop_factory.configuration(), pi3->node());
2746
2747 const std::string kLogfile1_1 =
2748 aos::testing::TestTmpDir() + "/multi_logfile1/";
2749 const std::string kLogfile2_1 =
2750 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
2751 const std::string kLogfile2_2 =
2752 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
2753 const std::string kLogfile3_1 =
2754 aos::testing::TestTmpDir() + "/multi_logfile3/";
2755 util::UnlinkRecursive(kLogfile1_1);
2756 util::UnlinkRecursive(kLogfile2_1);
2757 util::UnlinkRecursive(kLogfile2_2);
2758 util::UnlinkRecursive(kLogfile3_1);
2759 const UUID pi1_boot0 = UUID::Random();
2760 const UUID pi2_boot0 = UUID::Random();
2761 const UUID pi2_boot1 = UUID::Random();
2762 const UUID pi3_boot0 = UUID::Random();
2763 {
2764 CHECK_EQ(pi1_index, 0u);
2765 CHECK_EQ(pi2_index, 1u);
2766 CHECK_EQ(pi3_index, 2u);
2767
2768 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
2769 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
2770 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
2771 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
2772
2773 time_converter.AddNextTimestamp(
2774 distributed_clock::epoch(),
2775 {BootTimestamp::epoch(), BootTimestamp::epoch(),
2776 BootTimestamp::epoch()});
2777 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
2778 time_converter.AddNextTimestamp(
2779 distributed_clock::epoch() + reboot_time,
2780 {BootTimestamp::epoch() + reboot_time,
2781 BootTimestamp{
2782 .boot = 1,
2783 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
2784 BootTimestamp::epoch() + reboot_time});
2785 }
2786
2787 // Make everything perfectly quiet.
2788 event_loop_factory.SkipTimingReport();
2789 event_loop_factory.DisableStatistics();
2790
2791 std::vector<std::string> filenames;
2792 {
2793 LoggerState pi1_logger = LoggerState::MakeLogger(
2794 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2795 LoggerState pi3_logger = LoggerState::MakeLogger(
2796 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2797 {
2798 // And now start the logger.
2799 LoggerState pi2_logger = LoggerState::MakeLogger(
2800 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2801
2802 event_loop_factory.RunFor(chrono::milliseconds(1000));
2803
2804 pi1_logger.StartLogger(kLogfile1_1);
2805 pi3_logger.StartLogger(kLogfile3_1);
2806 pi2_logger.StartLogger(kLogfile2_1);
2807
2808 event_loop_factory.RunFor(chrono::milliseconds(10000));
2809
2810 // Now that we've got a start time in the past, turn on data.
2811 event_loop_factory.EnableStatistics();
2812 std::unique_ptr<aos::EventLoop> ping_event_loop =
2813 pi1->MakeEventLoop("ping");
2814 Ping ping(ping_event_loop.get());
2815
2816 pi2->AlwaysStart<Pong>("pong");
2817
2818 event_loop_factory.RunFor(chrono::milliseconds(3000));
2819
2820 pi2_logger.AppendAllFilenames(&filenames);
2821
2822 // Stop logging on pi2 before rebooting and completely shut off all
2823 // messages on pi2.
2824 pi2->DisableStatistics();
2825 pi1->Disconnect(pi2->node());
2826 pi2->Disconnect(pi1->node());
2827 }
2828 event_loop_factory.RunFor(chrono::milliseconds(7000));
2829 // pi2 now reboots.
2830 {
2831 event_loop_factory.RunFor(chrono::milliseconds(1000));
2832
2833 // Start logging again on pi2 after it is up.
2834 LoggerState pi2_logger = LoggerState::MakeLogger(
2835 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2836 pi2_logger.StartLogger(kLogfile2_2);
2837
2838 event_loop_factory.RunFor(chrono::milliseconds(10000));
2839 // And, now that we have a start time in the log, turn data back on.
2840 pi2->EnableStatistics();
2841 pi1->Connect(pi2->node());
2842 pi2->Connect(pi1->node());
2843
2844 pi2->AlwaysStart<Pong>("pong");
2845 std::unique_ptr<aos::EventLoop> ping_event_loop =
2846 pi1->MakeEventLoop("ping");
2847 Ping ping(ping_event_loop.get());
2848
2849 event_loop_factory.RunFor(chrono::milliseconds(3000));
2850
2851 pi2_logger.AppendAllFilenames(&filenames);
2852 }
2853
2854 pi1_logger.AppendAllFilenames(&filenames);
2855 pi3_logger.AppendAllFilenames(&filenames);
2856 }
2857
2858 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2859 // to confirm the right thing happened.
2860 const std::vector<LogFile> sorted_parts = SortParts(filenames);
2861 ConfirmReadable(filenames);
2862}
2863
Austin Schuh5dd22842021-11-17 16:09:39 -08002864// Tests that local data before remote data after reboot is properly replayed.
2865// We only trigger a reboot in the timestamp interpolation function when solving
2866// the timestamp problem when we actually have a point in the function. This
2867// originally only happened when a point passes the noncausal filter. At the
2868// start of time for the second boot, if we aren't careful, we will have
2869// messages which need to be published at times before the boot. This happens
2870// when a local message is in the log before a forwarded message, so there is no
2871// point in the interpolation function. This delays the reboot. So, we need to
2872// recreate that situation and make sure it doesn't come back.
2873TEST(MultinodeRebootLoggerTest, LocalMessageBeforeRemoteBeforeStartAfterReboot) {
2874 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
2875 aos::configuration::ReadConfig(ArtifactPath(
2876 "aos/events/logging/multinode_pingpong_split3_config.json"));
2877 message_bridge::TestingTimeConverter time_converter(
2878 configuration::NodesCount(&config.message()));
2879 SimulatedEventLoopFactory event_loop_factory(&config.message());
2880 event_loop_factory.SetTimeConverter(&time_converter);
2881 NodeEventLoopFactory *const pi1 =
2882 event_loop_factory.GetNodeEventLoopFactory("pi1");
2883 const size_t pi1_index = configuration::GetNodeIndex(
2884 event_loop_factory.configuration(), pi1->node());
2885 NodeEventLoopFactory *const pi2 =
2886 event_loop_factory.GetNodeEventLoopFactory("pi2");
2887 const size_t pi2_index = configuration::GetNodeIndex(
2888 event_loop_factory.configuration(), pi2->node());
2889 NodeEventLoopFactory *const pi3 =
2890 event_loop_factory.GetNodeEventLoopFactory("pi3");
2891 const size_t pi3_index = configuration::GetNodeIndex(
2892 event_loop_factory.configuration(), pi3->node());
2893
2894 const std::string kLogfile1_1 =
2895 aos::testing::TestTmpDir() + "/multi_logfile1/";
2896 const std::string kLogfile2_1 =
2897 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
2898 const std::string kLogfile2_2 =
2899 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
2900 const std::string kLogfile3_1 =
2901 aos::testing::TestTmpDir() + "/multi_logfile3/";
2902 util::UnlinkRecursive(kLogfile1_1);
2903 util::UnlinkRecursive(kLogfile2_1);
2904 util::UnlinkRecursive(kLogfile2_2);
2905 util::UnlinkRecursive(kLogfile3_1);
2906 const UUID pi1_boot0 = UUID::Random();
2907 const UUID pi2_boot0 = UUID::Random();
2908 const UUID pi2_boot1 = UUID::Random();
2909 const UUID pi3_boot0 = UUID::Random();
2910 {
2911 CHECK_EQ(pi1_index, 0u);
2912 CHECK_EQ(pi2_index, 1u);
2913 CHECK_EQ(pi3_index, 2u);
2914
2915 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
2916 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
2917 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
2918 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
2919
2920 time_converter.AddNextTimestamp(
2921 distributed_clock::epoch(),
2922 {BootTimestamp::epoch(), BootTimestamp::epoch(),
2923 BootTimestamp::epoch()});
2924 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
2925 time_converter.AddNextTimestamp(
2926 distributed_clock::epoch() + reboot_time,
2927 {BootTimestamp::epoch() + reboot_time,
2928 BootTimestamp{
2929 .boot = 1,
2930 .time = monotonic_clock::epoch() + reboot_time + chrono::seconds(100)},
2931 BootTimestamp::epoch() + reboot_time});
2932 }
2933
2934 std::vector<std::string> filenames;
2935 {
2936 LoggerState pi1_logger = LoggerState::MakeLogger(
2937 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2938 LoggerState pi3_logger = LoggerState::MakeLogger(
2939 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2940 {
2941 // And now start the logger.
2942 LoggerState pi2_logger = LoggerState::MakeLogger(
2943 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2944
2945 pi1_logger.StartLogger(kLogfile1_1);
2946 pi3_logger.StartLogger(kLogfile3_1);
2947 pi2_logger.StartLogger(kLogfile2_1);
2948
2949 event_loop_factory.RunFor(chrono::milliseconds(1005));
2950
2951 // Now that we've got a start time in the past, turn on data.
2952 std::unique_ptr<aos::EventLoop> ping_event_loop =
2953 pi1->MakeEventLoop("ping");
2954 Ping ping(ping_event_loop.get());
2955
2956 pi2->AlwaysStart<Pong>("pong");
2957
2958 event_loop_factory.RunFor(chrono::milliseconds(3000));
2959
2960 pi2_logger.AppendAllFilenames(&filenames);
2961
2962 // Disable any remote messages on pi2.
2963 pi1->Disconnect(pi2->node());
2964 pi2->Disconnect(pi1->node());
2965 }
2966 event_loop_factory.RunFor(chrono::milliseconds(995));
2967 // pi2 now reboots at 5 seconds.
2968 {
2969 event_loop_factory.RunFor(chrono::milliseconds(1000));
2970
2971 // Make local stuff happen before we start logging and connect the remote.
2972 pi2->AlwaysStart<Pong>("pong");
2973 std::unique_ptr<aos::EventLoop> ping_event_loop =
2974 pi1->MakeEventLoop("ping");
2975 Ping ping(ping_event_loop.get());
2976 event_loop_factory.RunFor(chrono::milliseconds(1005));
2977
2978 // Start logging again on pi2 after it is up.
2979 LoggerState pi2_logger = LoggerState::MakeLogger(
2980 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
2981 pi2_logger.StartLogger(kLogfile2_2);
2982
2983 // And allow remote messages now that we have some local ones.
2984 pi1->Connect(pi2->node());
2985 pi2->Connect(pi1->node());
2986
2987 event_loop_factory.RunFor(chrono::milliseconds(1000));
2988
2989 event_loop_factory.RunFor(chrono::milliseconds(3000));
2990
2991 pi2_logger.AppendAllFilenames(&filenames);
2992 }
2993
2994 pi1_logger.AppendAllFilenames(&filenames);
2995 pi3_logger.AppendAllFilenames(&filenames);
2996 }
2997
2998 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2999 // to confirm the right thing happened.
3000 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3001 ConfirmReadable(filenames);
3002}
3003
3004
Austin Schuhe309d2a2019-11-29 13:25:21 -08003005} // namespace testing
3006} // namespace logger
3007} // namespace aos