blob: d6ad8fe9e0a3aacec133437cc2e39b7eacd1465c [file] [log] [blame]
Austin Schuhb06f03b2021-02-17 22:00:37 -08001#include "aos/events/logging/log_reader.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08002
Austin Schuh6bb8a822021-03-31 23:04:39 -07003#include <sys/stat.h>
4
Austin Schuh315b96b2020-12-11 21:21:12 -08005#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08006#include "aos/events/event_loop.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08007#include "aos/events/logging/log_writer.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));
171 logger_event_loop->OnRun(
172 [base_name1, base_name2, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700175 EXPECT_DEATH(logger.StartLogging(std::make_unique<LocalLogNamer>(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 base_name2, logger_event_loop.get(),
177 logger_event_loop->node())),
Brian Silverman1f345222020-09-24 21:14:48 -0700178 "Already logging");
179 });
180 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>();
401 CHECK(builder.Send(ping_builder.Finish()));
402 });
403
404 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
405 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
406 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
407 chrono::microseconds(50));
408 });
409
Brian Silverman1f345222020-09-24 21:14:48 -0700410 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800411 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700412 logger.set_polling_period(std::chrono::milliseconds(100));
413 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800414
415 event_loop_factory_.RunFor(chrono::milliseconds(1000));
416 }
417}
418
Austin Schuh61e973f2021-02-21 21:43:56 -0800419// Parameters to run all the tests with.
420struct Param {
421 // The config file to use.
422 std::string config;
423 // If true, the RemoteMessage channel should be shared between all the remote
424 // channels. If false, there will be 1 RemoteMessage channel per remote
425 // channel.
426 bool shared;
427 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700428 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800429};
Austin Schuh315b96b2020-12-11 21:21:12 -0800430
Austin Schuh61e973f2021-02-21 21:43:56 -0800431class MultinodeLoggerTest : public ::testing::TestWithParam<struct Param> {
Austin Schuh15649d62019-12-28 16:36:38 -0800432 public:
433 MultinodeLoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -0700434 : config_(aos::configuration::ReadConfig(ArtifactPath(
435 absl::StrCat("aos/events/logging/", GetParam().config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800436 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800437 event_loop_factory_(&config_.message()),
Austin Schuhcde938c2020-02-02 17:30:07 -0800438 pi1_(
439 configuration::GetNode(event_loop_factory_.configuration(), "pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800440 pi1_index_(configuration::GetNodeIndex(
441 event_loop_factory_.configuration(), pi1_)),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700442 pi2_(
443 configuration::GetNode(event_loop_factory_.configuration(), "pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800444 pi2_index_(configuration::GetNodeIndex(
445 event_loop_factory_.configuration(), pi2_)),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800446 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800447 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
448 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800449 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800450 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800451 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
452 structured_logfiles_(StructureLogFiles()),
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700453 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping", pi1_)),
454 ping_(ping_event_loop_.get()),
455 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong", pi2_)),
456 pong_(pong_event_loop_.get()) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800457 LOG(INFO) << "Config " << GetParam().config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800458 event_loop_factory_.SetTimeConverter(&time_converter_);
459
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700460 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700461 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700462 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800463 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700464 }
465
Austin Schuh268586b2021-03-31 22:24:39 -0700466 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800467 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800468 unlink(file.c_str());
469 }
470
Austin Schuh268586b2021-03-31 22:24:39 -0700471 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800472 unlink(file.c_str());
473 }
474
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700475 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
476 << " and " << logfiles_[2];
477 }
478
Austin Schuh61e973f2021-02-21 21:43:56 -0800479 bool shared() const { return GetParam().shared; }
480
481 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700482 std::string logfile_base2,
483 size_t pi1_data_count = 2,
484 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800485 std::vector<std::string> result;
486 result.emplace_back(
487 absl::StrCat(logfile_base1, "_", GetParam().sha256, ".bfbs"));
488 result.emplace_back(
489 absl::StrCat(logfile_base2, "_", GetParam().sha256, ".bfbs"));
Austin Schuhe46492f2021-07-31 19:49:41 -0700490 for (size_t i = 0; i < pi1_data_count; ++i) {
491 result.emplace_back(
492 absl::StrCat(logfile_base1, "_pi1_data.part", i, ".bfbs"));
493 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800494 result.emplace_back(logfile_base1 +
495 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
496 result.emplace_back(logfile_base1 +
497 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700498 for (size_t i = 0; i < pi2_data_count; ++i) {
499 result.emplace_back(
500 absl::StrCat(logfile_base2, "_pi2_data.part", i, ".bfbs"));
501 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800502 result.emplace_back(
503 logfile_base2 +
504 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0.bfbs");
505 result.emplace_back(
506 logfile_base2 +
507 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1.bfbs");
508 result.emplace_back(
509 logfile_base1 +
510 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
511 result.emplace_back(
512 logfile_base1 +
513 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
514 if (shared()) {
515 result.emplace_back(logfile_base1 +
516 "_timestamps/pi1/aos/remote_timestamps/pi2/"
517 "aos.message_bridge.RemoteMessage.part0.bfbs");
518 result.emplace_back(logfile_base1 +
519 "_timestamps/pi1/aos/remote_timestamps/pi2/"
520 "aos.message_bridge.RemoteMessage.part1.bfbs");
521 result.emplace_back(logfile_base2 +
522 "_timestamps/pi2/aos/remote_timestamps/pi1/"
523 "aos.message_bridge.RemoteMessage.part0.bfbs");
524 result.emplace_back(logfile_base2 +
525 "_timestamps/pi2/aos/remote_timestamps/pi1/"
526 "aos.message_bridge.RemoteMessage.part1.bfbs");
527 } else {
528 result.emplace_back(logfile_base1 +
529 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
530 "aos-message_bridge-Timestamp/"
531 "aos.message_bridge.RemoteMessage.part0.bfbs");
532 result.emplace_back(logfile_base1 +
533 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
534 "aos-message_bridge-Timestamp/"
535 "aos.message_bridge.RemoteMessage.part1.bfbs");
536 result.emplace_back(logfile_base2 +
537 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
538 "aos-message_bridge-Timestamp/"
539 "aos.message_bridge.RemoteMessage.part0.bfbs");
540 result.emplace_back(logfile_base2 +
541 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
542 "aos-message_bridge-Timestamp/"
543 "aos.message_bridge.RemoteMessage.part1.bfbs");
544 result.emplace_back(logfile_base1 +
545 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
546 "aos-examples-Ping/"
547 "aos.message_bridge.RemoteMessage.part0.bfbs");
548 result.emplace_back(logfile_base1 +
549 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
550 "aos-examples-Ping/"
551 "aos.message_bridge.RemoteMessage.part1.bfbs");
552 }
553
554 return result;
555 }
556
557 std::vector<std::string> MakePi1RebootLogfiles() {
558 std::vector<std::string> result;
559 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuhe46492f2021-07-31 19:49:41 -0700560 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
561 result.emplace_back(logfile_base1_ + "_pi1_data.part2.bfbs");
Austin Schuh72211ae2021-08-05 14:02:30 -0700562 result.emplace_back(logfile_base1_ + "_pi1_data.part3.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800563 result.emplace_back(logfile_base1_ +
564 "_pi2_data/test/aos.examples.Pong.part0.bfbs");
565 result.emplace_back(logfile_base1_ +
566 "_pi2_data/test/aos.examples.Pong.part1.bfbs");
567 result.emplace_back(logfile_base1_ +
568 "_pi2_data/test/aos.examples.Pong.part2.bfbs");
569 result.emplace_back(
570 logfile_base1_ +
571 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
572 result.emplace_back(
573 logfile_base1_ +
574 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1.bfbs");
575 result.emplace_back(
576 logfile_base1_ +
577 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2.bfbs");
578 result.emplace_back(
579 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
580 if (shared()) {
581 result.emplace_back(logfile_base1_ +
582 "_timestamps/pi1/aos/remote_timestamps/pi2/"
583 "aos.message_bridge.RemoteMessage.part0.bfbs");
584 result.emplace_back(logfile_base1_ +
585 "_timestamps/pi1/aos/remote_timestamps/pi2/"
586 "aos.message_bridge.RemoteMessage.part1.bfbs");
587 result.emplace_back(logfile_base1_ +
588 "_timestamps/pi1/aos/remote_timestamps/pi2/"
589 "aos.message_bridge.RemoteMessage.part2.bfbs");
590 } else {
591 result.emplace_back(logfile_base1_ +
592 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
593 "aos-message_bridge-Timestamp/"
594 "aos.message_bridge.RemoteMessage.part0.bfbs");
595 result.emplace_back(logfile_base1_ +
596 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
597 "aos-message_bridge-Timestamp/"
598 "aos.message_bridge.RemoteMessage.part1.bfbs");
599 result.emplace_back(logfile_base1_ +
600 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
601 "aos-message_bridge-Timestamp/"
602 "aos.message_bridge.RemoteMessage.part2.bfbs");
603
604 result.emplace_back(logfile_base1_ +
605 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
606 "aos-examples-Ping/"
607 "aos.message_bridge.RemoteMessage.part0.bfbs");
608 result.emplace_back(logfile_base1_ +
609 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
610 "aos-examples-Ping/"
611 "aos.message_bridge.RemoteMessage.part1.bfbs");
612 result.emplace_back(logfile_base1_ +
613 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
614 "aos-examples-Ping/"
615 "aos.message_bridge.RemoteMessage.part2.bfbs");
616 }
617 return result;
618 }
619
620 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
621 std::vector<std::string> result;
622 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
Austin Schuh510dc622021-08-06 18:47:30 -0700623 result.emplace_back(logfile_base1_ + "_pi1_data.part1.bfbs");
Austin Schuh61e973f2021-02-21 21:43:56 -0800624 result.emplace_back(
625 logfile_base1_ +
626 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0.bfbs");
627 result.emplace_back(
628 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh510dc622021-08-06 18:47:30 -0700629 return result;
630 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800631
Austin Schuh510dc622021-08-06 18:47:30 -0700632 std::vector<std::string> MakePi1DeadNodeLogfiles() {
633 std::vector<std::string> result;
634 result.emplace_back(logfile_base1_ + "_pi1_data.part0.bfbs");
635 result.emplace_back(
636 absl::StrCat(logfile_base1_, "_", GetParam().sha256, ".bfbs"));
Austin Schuh61e973f2021-02-21 21:43:56 -0800637 return result;
638 }
639
640 std::vector<std::vector<std::string>> StructureLogFiles() {
641 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700642 std::vector<std::string>{logfiles_[2], logfiles_[3]},
643 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800644 std::vector<std::string>{logfiles_[6], logfiles_[7]},
645 std::vector<std::string>{logfiles_[8], logfiles_[9]},
646 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700647 std::vector<std::string>{logfiles_[12], logfiles_[13]},
648 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800649
650 if (!shared()) {
651 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700652 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800653 }
654
655 return result;
656 }
657
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700658 struct LoggerState {
659 std::unique_ptr<EventLoop> event_loop;
660 std::unique_ptr<Logger> logger;
Austin Schuh5b728b72021-06-16 14:57:15 -0700661 const Configuration *configuration;
662 const Node *node;
663 MultiNodeLogNamer *log_namer;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700664 };
665
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700666 LoggerState MakeLogger(const Node *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700667 SimulatedEventLoopFactory *factory = nullptr,
668 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700669 if (factory == nullptr) {
670 factory = &event_loop_factory_;
671 }
Austin Schuh5b728b72021-06-16 14:57:15 -0700672 if (configuration == nullptr) {
673 configuration = factory->configuration();
674 }
675 return {
676 factory->MakeEventLoop(
677 "logger", configuration::GetNode(factory->configuration(), node)),
678 {},
679 configuration,
680 node,
681 nullptr};
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700682 }
683
Austin Schuh3bd4c402020-11-06 18:19:06 -0800684 void StartLogger(LoggerState *logger, std::string logfile_base = "",
685 bool compress = false) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700686 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800687 if (logger->event_loop->node()->name()->string_view() == "pi1") {
688 logfile_base = logfile_base1_;
689 } else {
690 logfile_base = logfile_base2_;
691 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700692 }
693
Austin Schuh5b728b72021-06-16 14:57:15 -0700694 logger->logger = std::make_unique<Logger>(logger->event_loop.get(),
695 logger->configuration);
Brian Silverman1f345222020-09-24 21:14:48 -0700696 logger->logger->set_polling_period(std::chrono::milliseconds(100));
Austin Schuh0ca51f32020-12-25 21:51:45 -0800697 logger->logger->set_name(absl::StrCat(
698 "name_prefix_", logger->event_loop->node()->name()->str()));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800699 logger->event_loop->OnRun([logger, logfile_base, compress]() {
700 std::unique_ptr<MultiNodeLogNamer> namer =
Austin Schuh5b728b72021-06-16 14:57:15 -0700701 std::make_unique<MultiNodeLogNamer>(
702 logfile_base, logger->configuration, logger->event_loop.get(),
703 logger->node);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800704 if (compress) {
705#ifdef LZMA
706 namer->set_extension(".xz");
707 namer->set_encoder_factory(
708 []() { return std::make_unique<aos::logger::LzmaEncoder>(3); });
709#else
710 LOG(FATAL) << "Compression unsupported";
711#endif
712 }
Austin Schuh5b728b72021-06-16 14:57:15 -0700713 logger->log_namer = namer.get();
Austin Schuh3bd4c402020-11-06 18:19:06 -0800714
715 logger->logger->StartLogging(std::move(namer));
Brian Silverman1f345222020-09-24 21:14:48 -0700716 });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700717 }
Austin Schuh15649d62019-12-28 16:36:38 -0800718
Austin Schuh3bd4c402020-11-06 18:19:06 -0800719 void VerifyParts(const std::vector<LogFile> &sorted_parts,
720 const std::vector<std::string> &corrupted_parts = {}) {
721 EXPECT_EQ(sorted_parts.size(), 2u);
722
723 // Count up the number of UUIDs and make sure they are what we expect as a
724 // sanity check.
725 std::set<std::string> log_event_uuids;
726 std::set<std::string> parts_uuids;
727 std::set<std::string> both_uuids;
728
729 size_t missing_rt_count = 0;
730
731 std::vector<std::string> logger_nodes;
732 for (const LogFile &log_file : sorted_parts) {
733 EXPECT_FALSE(log_file.log_event_uuid.empty());
734 log_event_uuids.insert(log_file.log_event_uuid);
735 logger_nodes.emplace_back(log_file.logger_node);
736 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800737 EXPECT_TRUE(log_file.config);
738 EXPECT_EQ(log_file.name,
739 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800740
741 for (const LogParts &part : log_file.parts) {
742 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
743 << ": " << part;
744 missing_rt_count +=
745 part.realtime_start_time == aos::realtime_clock::min_time;
746
747 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
748 log_event_uuids.end());
749 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800750 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800751 parts_uuids.insert(part.parts_uuid);
752 both_uuids.insert(part.parts_uuid);
753 }
754 }
755
Austin Schuh61e973f2021-02-21 21:43:56 -0800756 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
757 // start time on remote nodes because we don't know it and would be
758 // guessing. And the log reader can actually do a better job. The number
759 // depends on if we have the remote timestamps split across 2 files, or just
760 // across 1, depending on if we are using a split or combined timestamp
761 // channel config.
762 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800763
764 EXPECT_EQ(log_event_uuids.size(), 2u);
765 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
766 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
767
768 // Test that each list of parts is in order. Don't worry about the ordering
769 // between part file lists though.
770 // (inner vectors all need to be in order, but outer one doesn't matter).
771 EXPECT_THAT(ToLogReaderVector(sorted_parts),
772 ::testing::UnorderedElementsAreArray(structured_logfiles_));
773
774 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
775
776 EXPECT_NE(sorted_parts[0].realtime_start_time,
777 aos::realtime_clock::min_time);
778 EXPECT_NE(sorted_parts[1].realtime_start_time,
779 aos::realtime_clock::min_time);
780
781 EXPECT_NE(sorted_parts[0].monotonic_start_time,
782 aos::monotonic_clock::min_time);
783 EXPECT_NE(sorted_parts[1].monotonic_start_time,
784 aos::monotonic_clock::min_time);
785
786 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
787 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
788 }
789
Austin Schuhc9049732020-12-21 22:27:15 -0800790 void ConfirmReadable(const std::vector<std::string> &files) {
791 LogReader reader(SortParts(files));
792
793 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
794 reader.Register(&log_reader_factory);
795
796 log_reader_factory.Run();
797
798 reader.Deregister();
799 }
800
Austin Schuh3bd4c402020-11-06 18:19:06 -0800801 void AddExtension(std::string_view extension) {
802 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
803 [extension](const std::string &in) {
804 return absl::StrCat(in, extension);
805 });
806
807 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
808 structured_logfiles_.begin(),
809 [extension](std::vector<std::string> in) {
810 std::transform(in.begin(), in.end(), in.begin(),
811 [extension](const std::string &in_str) {
812 return absl::StrCat(in_str, extension);
813 });
814 return in;
815 });
816 }
817
Austin Schuh15649d62019-12-28 16:36:38 -0800818 // Config and factory.
819 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800820 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800821 SimulatedEventLoopFactory event_loop_factory_;
822
Austin Schuh87dd3832021-01-01 23:07:31 -0800823 const Node *const pi1_;
824 const size_t pi1_index_;
825 const Node *const pi2_;
826 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700827
828 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800829 std::string logfile_base1_;
830 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800831 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700832 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800833 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700834
835 std::vector<std::vector<std::string>> structured_logfiles_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700836
837 std::unique_ptr<EventLoop> ping_event_loop_;
838 Ping ping_;
839 std::unique_ptr<EventLoop> pong_event_loop_;
840 Pong pong_;
Austin Schuh15649d62019-12-28 16:36:38 -0800841};
842
Austin Schuh391e3172020-09-01 22:48:18 -0700843// Counts the number of messages on a channel. Returns (channel name, channel
844// type, count) for every message matching matcher()
845std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800846 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800847 std::function<bool(const MessageHeader *)> matcher) {
848 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800849 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800850
Austin Schuh6f3babe2020-01-26 20:34:50 -0800851 while (true) {
Austin Schuhadd6eb32020-11-09 21:24:26 -0800852 std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
Austin Schuh6f3babe2020-01-26 20:34:50 -0800853 message_reader.ReadMessage();
854 if (!msg) {
855 break;
856 }
857
858 if (matcher(&msg.value().message())) {
859 counts[msg.value().message().channel_index()]++;
860 }
861 }
862
Austin Schuh391e3172020-09-01 22:48:18 -0700863 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800864 int channel = 0;
865 for (size_t i = 0; i < counts.size(); ++i) {
866 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800867 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700868 result.push_back(std::make_tuple(channel->name()->str(),
869 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800870 }
871 ++channel;
872 }
873
874 return result;
875}
876
877// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700878std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800879 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700880 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800881 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800882 if (msg->has_data()) {
883 CHECK(!msg->has_monotonic_remote_time());
884 CHECK(!msg->has_realtime_remote_time());
885 CHECK(!msg->has_remote_queue_index());
886 return true;
887 }
888 return false;
889 });
890}
891
892// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700893std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -0800894 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -0800895 std::string_view filename) {
Austin Schuh8c399962020-12-25 21:51:45 -0800896 return CountChannelsMatching(config, filename, [](const MessageHeader *msg) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800897 if (!msg->has_data()) {
898 CHECK(msg->has_monotonic_remote_time());
899 CHECK(msg->has_realtime_remote_time());
900 CHECK(msg->has_remote_queue_index());
901 return true;
902 }
903 return false;
904 });
905}
906
Austin Schuhcde938c2020-02-02 17:30:07 -0800907// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -0800908TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -0800909 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -0800910 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700911 LoggerState pi1_logger = MakeLogger(pi1_);
912 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -0800913
914 event_loop_factory_.RunFor(chrono::milliseconds(95));
915
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700916 StartLogger(&pi1_logger);
917 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -0800918
Austin Schuh15649d62019-12-28 16:36:38 -0800919 event_loop_factory_.RunFor(chrono::milliseconds(20000));
920 }
921
Austin Schuh6f3babe2020-01-26 20:34:50 -0800922 {
Austin Schuh64fab802020-09-09 22:47:47 -0700923 std::set<std::string> logfile_uuids;
924 std::set<std::string> parts_uuids;
925 // Confirm that we have the expected number of UUIDs for both the logfile
926 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800927 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700928 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800929 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -0800930 if (!log_header.back().message().has_configuration()) {
931 logfile_uuids.insert(
932 log_header.back().message().log_event_uuid()->str());
933 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
934 }
Austin Schuh64fab802020-09-09 22:47:47 -0700935 }
Austin Schuh15649d62019-12-28 16:36:38 -0800936
Austin Schuh64fab802020-09-09 22:47:47 -0700937 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -0800938 if (shared()) {
939 EXPECT_EQ(parts_uuids.size(), 7u);
940 } else {
941 EXPECT_EQ(parts_uuids.size(), 8u);
942 }
Austin Schuh64fab802020-09-09 22:47:47 -0700943
944 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -0800945 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -0700946 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700947 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
948 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700949 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
950 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
951 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
952 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -0700953 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
954 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -0700955 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
956 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
957 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
958 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -0800959 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700960 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
961 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -0800962 }
Austin Schuh64fab802020-09-09 22:47:47 -0700963
964 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -0800965 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -0700966 EXPECT_EQ(log_header[3].message().parts_index(), 1);
967 EXPECT_EQ(log_header[4].message().parts_index(), 0);
968 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -0700969 EXPECT_EQ(log_header[6].message().parts_index(), 0);
970 EXPECT_EQ(log_header[7].message().parts_index(), 1);
971 EXPECT_EQ(log_header[8].message().parts_index(), 0);
972 EXPECT_EQ(log_header[9].message().parts_index(), 1);
973 EXPECT_EQ(log_header[10].message().parts_index(), 0);
974 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800975 EXPECT_EQ(log_header[12].message().parts_index(), 0);
976 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -0700977 EXPECT_EQ(log_header[14].message().parts_index(), 0);
978 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800979 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700980 EXPECT_EQ(log_header[16].message().parts_index(), 0);
981 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -0800982 }
Austin Schuh64fab802020-09-09 22:47:47 -0700983 }
984
Austin Schuh8c399962020-12-25 21:51:45 -0800985 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -0700986 {
Austin Schuh391e3172020-09-01 22:48:18 -0700987 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -0800988 std::shared_ptr<const aos::Configuration> config =
989 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -0700990
Austin Schuh6f3babe2020-01-26 20:34:50 -0800991 // Timing reports, pings
Austin Schuh2f8fd752020-09-01 22:38:28 -0700992 EXPECT_THAT(
Austin Schuh61e973f2021-02-21 21:43:56 -0800993 CountChannelsData(config, logfiles_[2]),
Austin Schuh2f8fd752020-09-01 22:38:28 -0700994 UnorderedElementsAre(
Austin Schuhe46492f2021-07-31 19:49:41 -0700995 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
996 1),
997 std::make_tuple("/test", "aos.examples.Ping", 1)))
998 << " : " << logfiles_[2];
999 EXPECT_THAT(
1000 CountChannelsData(config, logfiles_[3]),
1001 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -07001002 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001003 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001004 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001005 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1006 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001007 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001008 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1009 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001010 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001011 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1012 UnorderedElementsAre())
1013 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001014 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001015 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001016 UnorderedElementsAre(
1017 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001018 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001019 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001020
1021 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001022 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001023 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001024 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001025 << " : " << logfiles_[4];
1026 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001027 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001028 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001029 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001030
Austin Schuh6f3babe2020-01-26 20:34:50 -08001031 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001032 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001033 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001034 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001035 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1036 UnorderedElementsAre())
1037 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001038
1039 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001040 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1041 UnorderedElementsAre(std::make_tuple(
1042 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1043 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001044 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001045 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001046 UnorderedElementsAre(
1047 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001048 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001049 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001050 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1051 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001052 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001053 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001054 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001055 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001056 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1057 UnorderedElementsAre())
1058 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001059 EXPECT_THAT(
1060 CountChannelsTimestamp(config, logfiles_[7]),
1061 UnorderedElementsAre(
1062 std::make_tuple("/test", "aos.examples.Ping", 2001),
1063 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001064 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001065
1066 // And then test that the remotely logged timestamp data files only have
1067 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001068 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1069 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001070 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001071 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1072 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001073 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001074 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1075 UnorderedElementsAre())
1076 << " : " << logfiles_[10];
1077 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1078 UnorderedElementsAre())
1079 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001080
Austin Schuh8c399962020-12-25 21:51:45 -08001081 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001082 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001083 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001084 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001085 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001086 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001087 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001088 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001089
Austin Schuh8c399962020-12-25 21:51:45 -08001090 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001091 UnorderedElementsAre(std::make_tuple(
1092 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001093 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001094 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001095 UnorderedElementsAre(std::make_tuple(
1096 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001097 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001098
1099 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001100 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1101 UnorderedElementsAre())
1102 << " : " << logfiles_[12];
1103 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1104 UnorderedElementsAre())
1105 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001106 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1107 UnorderedElementsAre())
1108 << " : " << logfiles_[14];
1109 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1110 UnorderedElementsAre())
1111 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001112 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001113 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001114 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001115 << " : " << logfiles_[16];
1116 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001117 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001118 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001119 }
1120
1121 if (shared()) {
1122 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001123 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001124 UnorderedElementsAre(
1125 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1126 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001127 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001128 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001129 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001130 UnorderedElementsAre(
1131 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1132 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001133 << " : " << logfiles_[13];
1134 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001135 UnorderedElementsAre(std::make_tuple(
1136 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001137 << " : " << logfiles_[14];
1138 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001139 UnorderedElementsAre(std::make_tuple(
1140 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1141 << " : " << logfiles_[15];
1142 } else {
1143 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1144 UnorderedElementsAre(std::make_tuple(
1145 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1146 << " : " << logfiles_[12];
1147 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1148 UnorderedElementsAre(std::make_tuple(
1149 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1150 << " : " << logfiles_[13];
1151 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1152 UnorderedElementsAre(std::make_tuple(
1153 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1154 << " : " << logfiles_[14];
1155 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1156 UnorderedElementsAre(std::make_tuple(
1157 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1158 << " : " << logfiles_[15];
1159 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1160 UnorderedElementsAre(
1161 std::make_tuple("/test", "aos.examples.Ping", 91)))
1162 << " : " << logfiles_[16];
1163 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001164 UnorderedElementsAre(
1165 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001166 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001167 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001168 }
1169
Austin Schuh8c399962020-12-25 21:51:45 -08001170 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001171
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001172 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001173 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001174
1175 // This sends out the fetched messages and advances time to the start of the
1176 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001177 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001178
Austin Schuhac0771c2020-01-07 18:36:30 -08001179 const Node *pi1 =
1180 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001181 const Node *pi2 =
1182 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001183
Austin Schuh2f8fd752020-09-01 22:38:28 -07001184 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1185 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1186 LOG(INFO) << "now pi1 "
1187 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1188 LOG(INFO) << "now pi2 "
1189 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1190
Austin Schuh07676622021-01-21 18:59:17 -08001191 EXPECT_THAT(reader.LoggedNodes(),
1192 ::testing::ElementsAre(
1193 configuration::GetNode(reader.logged_configuration(), pi1),
1194 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001195
1196 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001197
Austin Schuh6f3babe2020-01-26 20:34:50 -08001198 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001199 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001200 std::unique_ptr<EventLoop> pi2_event_loop =
1201 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001202
Austin Schuh6f3babe2020-01-26 20:34:50 -08001203 int pi1_ping_count = 10;
1204 int pi2_ping_count = 10;
1205 int pi1_pong_count = 10;
1206 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001207
1208 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001209 pi1_event_loop->MakeWatcher(
1210 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001211 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001212 << pi1_event_loop->context().monotonic_remote_time << " -> "
1213 << pi1_event_loop->context().monotonic_event_time;
1214 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1215 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1216 pi1_ping_count * chrono::milliseconds(10) +
1217 monotonic_clock::epoch());
1218 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1219 pi1_ping_count * chrono::milliseconds(10) +
1220 realtime_clock::epoch());
1221 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1222 pi1_event_loop->context().monotonic_event_time);
1223 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1224 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001225
Austin Schuh6f3babe2020-01-26 20:34:50 -08001226 ++pi1_ping_count;
1227 });
1228 pi2_event_loop->MakeWatcher(
1229 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001230 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001231 << pi2_event_loop->context().monotonic_remote_time << " -> "
1232 << pi2_event_loop->context().monotonic_event_time;
1233 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1234
1235 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1236 pi2_ping_count * chrono::milliseconds(10) +
1237 monotonic_clock::epoch());
1238 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1239 pi2_ping_count * chrono::milliseconds(10) +
1240 realtime_clock::epoch());
1241 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1242 chrono::microseconds(150),
1243 pi2_event_loop->context().monotonic_event_time);
1244 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1245 chrono::microseconds(150),
1246 pi2_event_loop->context().realtime_event_time);
1247 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001248 });
1249
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001250 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001251 // Confirm that the ping and pong counts both match, and the value also
1252 // matches.
1253 pi1_event_loop->MakeWatcher(
1254 "/test", [&pi1_event_loop, &pi1_ping_count,
1255 &pi1_pong_count](const examples::Pong &pong) {
1256 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1257 << pi1_event_loop->context().monotonic_remote_time << " -> "
1258 << pi1_event_loop->context().monotonic_event_time;
1259
1260 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1261 pi1_pong_count + kQueueIndexOffset);
1262 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1263 chrono::microseconds(200) +
1264 pi1_pong_count * chrono::milliseconds(10) +
1265 monotonic_clock::epoch());
1266 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1267 chrono::microseconds(200) +
1268 pi1_pong_count * chrono::milliseconds(10) +
1269 realtime_clock::epoch());
1270
1271 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1272 chrono::microseconds(150),
1273 pi1_event_loop->context().monotonic_event_time);
1274 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1275 chrono::microseconds(150),
1276 pi1_event_loop->context().realtime_event_time);
1277
1278 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1279 ++pi1_pong_count;
1280 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1281 });
1282 pi2_event_loop->MakeWatcher(
1283 "/test", [&pi2_event_loop, &pi2_ping_count,
1284 &pi2_pong_count](const examples::Pong &pong) {
1285 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1286 << pi2_event_loop->context().monotonic_remote_time << " -> "
1287 << pi2_event_loop->context().monotonic_event_time;
1288
1289 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001290 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001291
1292 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1293 chrono::microseconds(200) +
1294 pi2_pong_count * chrono::milliseconds(10) +
1295 monotonic_clock::epoch());
1296 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1297 chrono::microseconds(200) +
1298 pi2_pong_count * chrono::milliseconds(10) +
1299 realtime_clock::epoch());
1300
1301 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1302 pi2_event_loop->context().monotonic_event_time);
1303 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1304 pi2_event_loop->context().realtime_event_time);
1305
1306 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1307 ++pi2_pong_count;
1308 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1309 });
1310
1311 log_reader_factory.Run();
1312 EXPECT_EQ(pi1_ping_count, 2010);
1313 EXPECT_EQ(pi2_ping_count, 2010);
1314 EXPECT_EQ(pi1_pong_count, 2010);
1315 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001316
1317 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001318}
1319
James Kuszmaul46d82582020-05-09 19:50:09 -07001320typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1321
1322// Test that if we feed the replay with a mismatched node list that we die on
1323// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001324TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001325 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001326 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001327 LoggerState pi1_logger = MakeLogger(pi1_);
1328 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001329
1330 event_loop_factory_.RunFor(chrono::milliseconds(95));
1331
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001332 StartLogger(&pi1_logger);
1333 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001334
James Kuszmaul46d82582020-05-09 19:50:09 -07001335 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1336 }
1337
1338 // Test that, if we add an additional node to the replay config that the
1339 // logger complains about the mismatch in number of nodes.
1340 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1341 configuration::MergeWithConfig(&config_.message(), R"({
1342 "nodes": [
1343 {
1344 "name": "extra-node"
1345 }
1346 ]
1347 }
1348 )");
1349
Austin Schuh287d43d2020-12-04 20:19:33 -08001350 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1351 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001352 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001353}
1354
Austin Schuhcde938c2020-02-02 17:30:07 -08001355// Tests that we can read log files where they don't start at the same monotonic
1356// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001357TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001358 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001359 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001360 LoggerState pi1_logger = MakeLogger(pi1_);
1361 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001362
1363 event_loop_factory_.RunFor(chrono::milliseconds(95));
1364
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001365 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001366
1367 event_loop_factory_.RunFor(chrono::milliseconds(200));
1368
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001369 StartLogger(&pi2_logger);
1370
Austin Schuhcde938c2020-02-02 17:30:07 -08001371 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1372 }
1373
Austin Schuhe46492f2021-07-31 19:49:41 -07001374 // Since we delay starting pi2, it already knows about all the timestamps so
1375 // we don't end up with extra parts.
1376 LogReader reader(
1377 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001378
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001379 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001380 log_reader_factory.set_send_delay(chrono::microseconds(0));
1381
1382 // This sends out the fetched messages and advances time to the start of the
1383 // log file.
1384 reader.Register(&log_reader_factory);
1385
1386 const Node *pi1 =
1387 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1388 const Node *pi2 =
1389 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1390
Austin Schuh07676622021-01-21 18:59:17 -08001391 EXPECT_THAT(reader.LoggedNodes(),
1392 ::testing::ElementsAre(
1393 configuration::GetNode(reader.logged_configuration(), pi1),
1394 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001395
1396 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1397
1398 std::unique_ptr<EventLoop> pi1_event_loop =
1399 log_reader_factory.MakeEventLoop("test", pi1);
1400 std::unique_ptr<EventLoop> pi2_event_loop =
1401 log_reader_factory.MakeEventLoop("test", pi2);
1402
1403 int pi1_ping_count = 30;
1404 int pi2_ping_count = 30;
1405 int pi1_pong_count = 30;
1406 int pi2_pong_count = 30;
1407
1408 // Confirm that the ping value matches.
1409 pi1_event_loop->MakeWatcher(
1410 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1411 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1412 << pi1_event_loop->context().monotonic_remote_time << " -> "
1413 << pi1_event_loop->context().monotonic_event_time;
1414 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1415
1416 ++pi1_ping_count;
1417 });
1418 pi2_event_loop->MakeWatcher(
1419 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1420 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1421 << pi2_event_loop->context().monotonic_remote_time << " -> "
1422 << pi2_event_loop->context().monotonic_event_time;
1423 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1424
1425 ++pi2_ping_count;
1426 });
1427
1428 // Confirm that the ping and pong counts both match, and the value also
1429 // matches.
1430 pi1_event_loop->MakeWatcher(
1431 "/test", [&pi1_event_loop, &pi1_ping_count,
1432 &pi1_pong_count](const examples::Pong &pong) {
1433 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1434 << pi1_event_loop->context().monotonic_remote_time << " -> "
1435 << pi1_event_loop->context().monotonic_event_time;
1436
1437 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1438 ++pi1_pong_count;
1439 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1440 });
1441 pi2_event_loop->MakeWatcher(
1442 "/test", [&pi2_event_loop, &pi2_ping_count,
1443 &pi2_pong_count](const examples::Pong &pong) {
1444 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1445 << pi2_event_loop->context().monotonic_remote_time << " -> "
1446 << pi2_event_loop->context().monotonic_event_time;
1447
1448 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1449 ++pi2_pong_count;
1450 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1451 });
1452
1453 log_reader_factory.Run();
1454 EXPECT_EQ(pi1_ping_count, 2030);
1455 EXPECT_EQ(pi2_ping_count, 2030);
1456 EXPECT_EQ(pi1_pong_count, 2030);
1457 EXPECT_EQ(pi2_pong_count, 2030);
1458
1459 reader.Deregister();
1460}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001461
Austin Schuh8bd96322020-02-13 21:18:22 -08001462// Tests that we can read log files where the monotonic clocks drift and don't
1463// match correctly. While we are here, also test that different ending times
1464// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001465TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001466 // TODO(austin): Negate...
1467 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1468
1469 time_converter_.AddMonotonic({monotonic_clock::epoch(),
1470 monotonic_clock::epoch() + initial_pi2_offset});
1471 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1472 // skew to be 200 uS/s
1473 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1474 {chrono::milliseconds(95),
1475 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1476 // Run another 200 ms to have one logger start first.
1477 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1478 {chrono::milliseconds(200), chrono::milliseconds(200)});
1479 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1480 // go far enough to cause problems if this isn't accounted for.
1481 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1482 {chrono::milliseconds(20000),
1483 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1484 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1485 {chrono::milliseconds(40000),
1486 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1487 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1488 {chrono::milliseconds(400), chrono::milliseconds(400)});
1489
Austin Schuhcde938c2020-02-02 17:30:07 -08001490 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001491 LoggerState pi2_logger = MakeLogger(pi2_);
1492
Austin Schuh87dd3832021-01-01 23:07:31 -08001493 NodeEventLoopFactory *pi1 =
1494 event_loop_factory_.GetNodeEventLoopFactory(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001495 NodeEventLoopFactory *pi2 =
1496 event_loop_factory_.GetNodeEventLoopFactory(pi2_);
1497 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1498 << pi2->realtime_now() << " distributed "
1499 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001500
Austin Schuh8bd96322020-02-13 21:18:22 -08001501 LOG(INFO) << "pi2 times: " << pi2->monotonic_now() << " "
1502 << pi2->realtime_now() << " distributed "
1503 << pi2->ToDistributedClock(pi2->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001504
Austin Schuh87dd3832021-01-01 23:07:31 -08001505 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001506
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001507 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001508
Austin Schuh87dd3832021-01-01 23:07:31 -08001509 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001510
Austin Schuh8bd96322020-02-13 21:18:22 -08001511 {
1512 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001513 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001514
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001515 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001516 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001517
Austin Schuh87dd3832021-01-01 23:07:31 -08001518 // Make sure we slewed time far enough so that the difference is greater
1519 // than the network delay. This confirms that if we sort incorrectly, it
1520 // would show in the results.
1521 EXPECT_LT(
1522 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1523 -event_loop_factory_.send_delay() -
1524 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001525
Austin Schuh87dd3832021-01-01 23:07:31 -08001526 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001527
Austin Schuh87dd3832021-01-01 23:07:31 -08001528 // And now check that we went far enough the other way to make sure we
1529 // cover both problems.
1530 EXPECT_GT(
1531 (pi2->monotonic_now() - pi1->monotonic_now()) - initial_pi2_offset,
1532 event_loop_factory_.send_delay() +
1533 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001534 }
1535
1536 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001537 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001538 }
1539
Austin Schuh72211ae2021-08-05 14:02:30 -07001540 LogReader reader(
1541 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001542
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001543 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001544 log_reader_factory.set_send_delay(chrono::microseconds(0));
1545
Austin Schuhcde938c2020-02-02 17:30:07 -08001546 const Node *pi1 =
1547 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1548 const Node *pi2 =
1549 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1550
Austin Schuh2f8fd752020-09-01 22:38:28 -07001551 // This sends out the fetched messages and advances time to the start of the
1552 // log file.
1553 reader.Register(&log_reader_factory);
1554
1555 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1556 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1557 LOG(INFO) << "now pi1 "
1558 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1559 LOG(INFO) << "now pi2 "
1560 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1561
Austin Schuhcde938c2020-02-02 17:30:07 -08001562 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001563 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1564 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001565 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1566 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001567 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1568 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001569 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1570
Austin Schuh07676622021-01-21 18:59:17 -08001571 EXPECT_THAT(reader.LoggedNodes(),
1572 ::testing::ElementsAre(
1573 configuration::GetNode(reader.logged_configuration(), pi1),
1574 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001575
1576 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1577
1578 std::unique_ptr<EventLoop> pi1_event_loop =
1579 log_reader_factory.MakeEventLoop("test", pi1);
1580 std::unique_ptr<EventLoop> pi2_event_loop =
1581 log_reader_factory.MakeEventLoop("test", pi2);
1582
1583 int pi1_ping_count = 30;
1584 int pi2_ping_count = 30;
1585 int pi1_pong_count = 30;
1586 int pi2_pong_count = 30;
1587
1588 // Confirm that the ping value matches.
1589 pi1_event_loop->MakeWatcher(
1590 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1591 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1592 << pi1_event_loop->context().monotonic_remote_time << " -> "
1593 << pi1_event_loop->context().monotonic_event_time;
1594 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1595
1596 ++pi1_ping_count;
1597 });
1598 pi2_event_loop->MakeWatcher(
1599 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1600 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1601 << pi2_event_loop->context().monotonic_remote_time << " -> "
1602 << pi2_event_loop->context().monotonic_event_time;
1603 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1604
1605 ++pi2_ping_count;
1606 });
1607
1608 // Confirm that the ping and pong counts both match, and the value also
1609 // matches.
1610 pi1_event_loop->MakeWatcher(
1611 "/test", [&pi1_event_loop, &pi1_ping_count,
1612 &pi1_pong_count](const examples::Pong &pong) {
1613 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1614 << pi1_event_loop->context().monotonic_remote_time << " -> "
1615 << pi1_event_loop->context().monotonic_event_time;
1616
1617 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1618 ++pi1_pong_count;
1619 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1620 });
1621 pi2_event_loop->MakeWatcher(
1622 "/test", [&pi2_event_loop, &pi2_ping_count,
1623 &pi2_pong_count](const examples::Pong &pong) {
1624 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1625 << pi2_event_loop->context().monotonic_remote_time << " -> "
1626 << pi2_event_loop->context().monotonic_event_time;
1627
1628 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1629 ++pi2_pong_count;
1630 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1631 });
1632
1633 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001634 EXPECT_EQ(pi1_ping_count, 6030);
1635 EXPECT_EQ(pi2_ping_count, 6030);
1636 EXPECT_EQ(pi1_pong_count, 6030);
1637 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001638
1639 reader.Deregister();
1640}
1641
Austin Schuh5212cad2020-09-09 23:12:09 -07001642// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001643TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001644 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001645 // Make a bunch of parts.
1646 {
1647 LoggerState pi1_logger = MakeLogger(pi1_);
1648 LoggerState pi2_logger = MakeLogger(pi2_);
1649
1650 event_loop_factory_.RunFor(chrono::milliseconds(95));
1651
1652 StartLogger(&pi1_logger);
1653 StartLogger(&pi2_logger);
1654
1655 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1656 }
1657
Austin Schuh11d43732020-09-21 17:28:30 -07001658 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001659 VerifyParts(sorted_parts);
1660}
Austin Schuh11d43732020-09-21 17:28:30 -07001661
Austin Schuh3bd4c402020-11-06 18:19:06 -08001662// Tests that we can sort a bunch of parts with an empty part. We should ignore
1663// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001664TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001665 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001666 // Make a bunch of parts.
1667 {
1668 LoggerState pi1_logger = MakeLogger(pi1_);
1669 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001670
Austin Schuh3bd4c402020-11-06 18:19:06 -08001671 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001672
Austin Schuh3bd4c402020-11-06 18:19:06 -08001673 StartLogger(&pi1_logger);
1674 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001675
Austin Schuh3bd4c402020-11-06 18:19:06 -08001676 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001677 }
1678
Austin Schuh3bd4c402020-11-06 18:19:06 -08001679 // TODO(austin): Should we flip out if the file can't open?
1680 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs");
Austin Schuh11d43732020-09-21 17:28:30 -07001681
Austin Schuh3bd4c402020-11-06 18:19:06 -08001682 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1683 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001684
Austin Schuh3bd4c402020-11-06 18:19:06 -08001685 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1686 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001687}
1688
Austin Schuh3bd4c402020-11-06 18:19:06 -08001689#ifdef LZMA
1690// Tests that we can sort a bunch of parts with an empty .xz file in there. The
1691// empty file should be ignored.
Austin Schuh61e973f2021-02-21 21:43:56 -08001692TEST_P(MultinodeLoggerTest, SortEmptyCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001693 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001694 // Make a bunch of parts.
1695 {
1696 LoggerState pi1_logger = MakeLogger(pi1_);
1697 LoggerState pi2_logger = MakeLogger(pi2_);
1698
1699 event_loop_factory_.RunFor(chrono::milliseconds(95));
1700
1701 StartLogger(&pi1_logger, "", true);
1702 StartLogger(&pi2_logger, "", true);
1703
1704 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1705 }
1706
1707 // TODO(austin): Should we flip out if the file can't open?
1708 const std::string kEmptyFile("foobarinvalidfiledoesnotexist.bfbs.xz");
1709
1710 AddExtension(".xz");
1711
1712 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1713 logfiles_.emplace_back(kEmptyFile);
1714
1715 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1716 VerifyParts(sorted_parts, {kEmptyFile});
1717}
1718
1719// Tests that we can sort a bunch of parts with the end missing off a compressed
1720// file. We should use the part we can read.
Austin Schuh61e973f2021-02-21 21:43:56 -08001721TEST_P(MultinodeLoggerTest, SortTruncatedCompressedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001722 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001723 // Make a bunch of parts.
1724 {
1725 LoggerState pi1_logger = MakeLogger(pi1_);
1726 LoggerState pi2_logger = MakeLogger(pi2_);
1727
1728 event_loop_factory_.RunFor(chrono::milliseconds(95));
1729
1730 StartLogger(&pi1_logger, "", true);
1731 StartLogger(&pi2_logger, "", true);
1732
1733 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1734 }
1735
1736 // Append everything with .xz.
1737 AddExtension(".xz");
1738
1739 // Strip off the end of one of the files. Pick one with a lot of data.
1740 ::std::string compressed_contents =
Austin Schuh61e973f2021-02-21 21:43:56 -08001741 aos::util::ReadFileToStringOrDie(logfiles_[2]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001742
1743 aos::util::WriteStringToFileOrDie(
Austin Schuh61e973f2021-02-21 21:43:56 -08001744 logfiles_[2],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001745 compressed_contents.substr(0, compressed_contents.size() - 100));
1746
1747 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1748 VerifyParts(sorted_parts);
1749}
1750#endif
1751
Austin Schuh01b4c352020-09-21 23:09:39 -07001752// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001753TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001754 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001755 {
1756 LoggerState pi1_logger = MakeLogger(pi1_);
1757 LoggerState pi2_logger = MakeLogger(pi2_);
1758
1759 event_loop_factory_.RunFor(chrono::milliseconds(95));
1760
1761 StartLogger(&pi1_logger);
1762 StartLogger(&pi2_logger);
1763
1764 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1765 }
1766
Austin Schuh287d43d2020-12-04 20:19:33 -08001767 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001768
1769 // Remap just on pi1.
1770 reader.RemapLoggedChannel<aos::timing::Report>(
1771 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1772
1773 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1774 log_reader_factory.set_send_delay(chrono::microseconds(0));
1775
1776 reader.Register(&log_reader_factory);
1777
1778 const Node *pi1 =
1779 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1780 const Node *pi2 =
1781 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1782
1783 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1784 // else should have moved.
1785 std::unique_ptr<EventLoop> pi1_event_loop =
1786 log_reader_factory.MakeEventLoop("test", pi1);
1787 pi1_event_loop->SkipTimingReport();
1788 std::unique_ptr<EventLoop> full_pi1_event_loop =
1789 log_reader_factory.MakeEventLoop("test", pi1);
1790 full_pi1_event_loop->SkipTimingReport();
1791 std::unique_ptr<EventLoop> pi2_event_loop =
1792 log_reader_factory.MakeEventLoop("test", pi2);
1793 pi2_event_loop->SkipTimingReport();
1794
1795 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1796 "/aos");
1797 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1798 full_pi1_event_loop.get(), "/pi1/aos");
1799 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1800 pi1_event_loop.get(), "/original/aos");
1801 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1802 full_pi1_event_loop.get(), "/original/pi1/aos");
1803 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1804 "/aos");
1805
1806 log_reader_factory.Run();
1807
1808 EXPECT_EQ(pi1_timing_report.count(), 0u);
1809 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1810 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1811 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1812 EXPECT_NE(pi2_timing_report.count(), 0u);
1813
1814 reader.Deregister();
1815}
1816
Austin Schuh006a9f52021-04-07 16:24:18 -07001817// Tests that we can remap a forwarded channel as well.
1818TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1819 time_converter_.StartEqual();
1820 {
1821 LoggerState pi1_logger = MakeLogger(pi1_);
1822 LoggerState pi2_logger = MakeLogger(pi2_);
1823
1824 event_loop_factory_.RunFor(chrono::milliseconds(95));
1825
1826 StartLogger(&pi1_logger);
1827 StartLogger(&pi2_logger);
1828
1829 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1830 }
1831
1832 LogReader reader(SortParts(logfiles_));
1833
1834 reader.RemapLoggedChannel<examples::Ping>("/test");
1835
1836 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1837 log_reader_factory.set_send_delay(chrono::microseconds(0));
1838
1839 reader.Register(&log_reader_factory);
1840
1841 const Node *pi1 =
1842 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1843 const Node *pi2 =
1844 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1845
1846 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1847 // else should have moved.
1848 std::unique_ptr<EventLoop> pi1_event_loop =
1849 log_reader_factory.MakeEventLoop("test", pi1);
1850 pi1_event_loop->SkipTimingReport();
1851 std::unique_ptr<EventLoop> full_pi1_event_loop =
1852 log_reader_factory.MakeEventLoop("test", pi1);
1853 full_pi1_event_loop->SkipTimingReport();
1854 std::unique_ptr<EventLoop> pi2_event_loop =
1855 log_reader_factory.MakeEventLoop("test", pi2);
1856 pi2_event_loop->SkipTimingReport();
1857
1858 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1859 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1860 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1861 "/original/test");
1862 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1863 "/original/test");
1864
1865 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1866 pi1_original_ping_timestamp;
1867 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1868 pi1_ping_timestamp;
1869 if (!shared()) {
1870 pi1_original_ping_timestamp =
1871 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1872 pi1_event_loop.get(),
1873 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1874 pi1_ping_timestamp =
1875 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1876 pi1_event_loop.get(),
1877 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1878 }
1879
1880 log_reader_factory.Run();
1881
1882 EXPECT_EQ(pi1_ping.count(), 0u);
1883 EXPECT_EQ(pi2_ping.count(), 0u);
1884 EXPECT_NE(pi1_original_ping.count(), 0u);
1885 EXPECT_NE(pi2_original_ping.count(), 0u);
1886 if (!shared()) {
1887 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1888 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1889 }
1890
1891 reader.Deregister();
1892}
1893
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001894// Tests that we properly recreate forwarded timestamps when replaying a log.
1895// This should be enough that we can then re-run the logger and get a valid log
1896// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001897TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001898 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001899 {
1900 LoggerState pi1_logger = MakeLogger(pi1_);
1901 LoggerState pi2_logger = MakeLogger(pi2_);
1902
1903 event_loop_factory_.RunFor(chrono::milliseconds(95));
1904
1905 StartLogger(&pi1_logger);
1906 StartLogger(&pi2_logger);
1907
1908 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1909 }
1910
Austin Schuh287d43d2020-12-04 20:19:33 -08001911 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001912
1913 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1914 log_reader_factory.set_send_delay(chrono::microseconds(0));
1915
1916 // This sends out the fetched messages and advances time to the start of the
1917 // log file.
1918 reader.Register(&log_reader_factory);
1919
1920 const Node *pi1 =
1921 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1922 const Node *pi2 =
1923 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1924
1925 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1926 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1927 LOG(INFO) << "now pi1 "
1928 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1929 LOG(INFO) << "now pi2 "
1930 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1931
Austin Schuh07676622021-01-21 18:59:17 -08001932 EXPECT_THAT(reader.LoggedNodes(),
1933 ::testing::ElementsAre(
1934 configuration::GetNode(reader.logged_configuration(), pi1),
1935 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001936
1937 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1938
1939 std::unique_ptr<EventLoop> pi1_event_loop =
1940 log_reader_factory.MakeEventLoop("test", pi1);
1941 std::unique_ptr<EventLoop> pi2_event_loop =
1942 log_reader_factory.MakeEventLoop("test", pi2);
1943
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001944 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
1945 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1946 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
1947 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
1948
1949 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
1950 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
1951 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
1952 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
1953
1954 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
1955 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1956 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
1957 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
1958
1959 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
1960 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
1961 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
1962 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
1963
1964 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
1965 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
1966 const size_t ping_timestamp_channel = configuration::ChannelIndex(
1967 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
1968
1969 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
1970 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
1971 const size_t pong_timestamp_channel = configuration::ChannelIndex(
1972 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
1973
Austin Schuh969cd602021-01-03 00:09:45 -08001974 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08001975 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08001976
Austin Schuh61e973f2021-02-21 21:43:56 -08001977 for (std::pair<int, std::string> channel :
1978 shared()
1979 ? std::vector<
1980 std::pair<int, std::string>>{{-1,
1981 "/aos/remote_timestamps/pi2"}}
1982 : std::vector<std::pair<int, std::string>>{
1983 {pi1_timestamp_channel,
1984 "/aos/remote_timestamps/pi2/pi1/aos/"
1985 "aos-message_bridge-Timestamp"},
1986 {ping_timestamp_channel,
1987 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
1988 pi1_event_loop->MakeWatcher(
1989 channel.second,
1990 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
1991 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
1992 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
1993 &ping_on_pi2_fetcher, network_delay, send_delay,
1994 channel_index = channel.first](const RemoteMessage &header) {
1995 const aos::monotonic_clock::time_point header_monotonic_sent_time(
1996 chrono::nanoseconds(header.monotonic_sent_time()));
1997 const aos::realtime_clock::time_point header_realtime_sent_time(
1998 chrono::nanoseconds(header.realtime_sent_time()));
1999 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2000 chrono::nanoseconds(header.monotonic_remote_time()));
2001 const aos::realtime_clock::time_point header_realtime_remote_time(
2002 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002003
Austin Schuh61e973f2021-02-21 21:43:56 -08002004 if (channel_index != -1) {
2005 ASSERT_EQ(channel_index, header.channel_index());
2006 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002007
Austin Schuh61e973f2021-02-21 21:43:56 -08002008 const Context *pi1_context = nullptr;
2009 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002010
Austin Schuh61e973f2021-02-21 21:43:56 -08002011 if (header.channel_index() == pi1_timestamp_channel) {
2012 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2013 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2014 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2015 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2016 } else if (header.channel_index() == ping_timestamp_channel) {
2017 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2018 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2019 pi1_context = &ping_on_pi1_fetcher.context();
2020 pi2_context = &ping_on_pi2_fetcher.context();
2021 } else {
2022 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2023 << configuration::CleanedChannelToString(
2024 pi1_event_loop->configuration()->channels()->Get(
2025 header.channel_index()));
2026 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002027
Austin Schuh61e973f2021-02-21 21:43:56 -08002028 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002029 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2030 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002031
Austin Schuh61e973f2021-02-21 21:43:56 -08002032 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2033 EXPECT_EQ(pi2_context->remote_queue_index,
2034 header.remote_queue_index());
2035 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002036
Austin Schuh61e973f2021-02-21 21:43:56 -08002037 EXPECT_EQ(pi2_context->monotonic_event_time,
2038 header_monotonic_sent_time);
2039 EXPECT_EQ(pi2_context->realtime_event_time,
2040 header_realtime_sent_time);
2041 EXPECT_EQ(pi2_context->realtime_remote_time,
2042 header_realtime_remote_time);
2043 EXPECT_EQ(pi2_context->monotonic_remote_time,
2044 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002045
Austin Schuh61e973f2021-02-21 21:43:56 -08002046 EXPECT_EQ(pi1_context->realtime_event_time,
2047 header_realtime_remote_time);
2048 EXPECT_EQ(pi1_context->monotonic_event_time,
2049 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002050
Austin Schuh61e973f2021-02-21 21:43:56 -08002051 // Time estimation isn't perfect, but we know the clocks were
2052 // identical when logged, so we know when this should have come back.
2053 // Confirm we got it when we expected.
2054 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2055 pi1_context->monotonic_event_time + 2 * network_delay +
2056 send_delay);
2057 });
2058 }
2059 for (std::pair<int, std::string> channel :
2060 shared()
2061 ? std::vector<
2062 std::pair<int, std::string>>{{-1,
2063 "/aos/remote_timestamps/pi1"}}
2064 : std::vector<std::pair<int, std::string>>{
2065 {pi2_timestamp_channel,
2066 "/aos/remote_timestamps/pi1/pi2/aos/"
2067 "aos-message_bridge-Timestamp"}}) {
2068 pi2_event_loop->MakeWatcher(
2069 channel.second,
2070 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2071 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2072 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2073 &pong_on_pi1_fetcher, network_delay, send_delay,
2074 channel_index = channel.first](const RemoteMessage &header) {
2075 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2076 chrono::nanoseconds(header.monotonic_sent_time()));
2077 const aos::realtime_clock::time_point header_realtime_sent_time(
2078 chrono::nanoseconds(header.realtime_sent_time()));
2079 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2080 chrono::nanoseconds(header.monotonic_remote_time()));
2081 const aos::realtime_clock::time_point header_realtime_remote_time(
2082 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002083
Austin Schuh61e973f2021-02-21 21:43:56 -08002084 if (channel_index != -1) {
2085 ASSERT_EQ(channel_index, header.channel_index());
2086 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002087
Austin Schuh61e973f2021-02-21 21:43:56 -08002088 const Context *pi2_context = nullptr;
2089 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002090
Austin Schuh61e973f2021-02-21 21:43:56 -08002091 if (header.channel_index() == pi2_timestamp_channel) {
2092 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2093 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2094 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2095 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2096 } else if (header.channel_index() == pong_timestamp_channel) {
2097 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2098 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2099 pi2_context = &pong_on_pi2_fetcher.context();
2100 pi1_context = &pong_on_pi1_fetcher.context();
2101 } else {
2102 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2103 << configuration::CleanedChannelToString(
2104 pi2_event_loop->configuration()->channels()->Get(
2105 header.channel_index()));
2106 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002107
Austin Schuh61e973f2021-02-21 21:43:56 -08002108 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002109 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2110 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002111
Austin Schuh61e973f2021-02-21 21:43:56 -08002112 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2113 EXPECT_EQ(pi1_context->remote_queue_index,
2114 header.remote_queue_index());
2115 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002116
Austin Schuh61e973f2021-02-21 21:43:56 -08002117 EXPECT_EQ(pi1_context->monotonic_event_time,
2118 header_monotonic_sent_time);
2119 EXPECT_EQ(pi1_context->realtime_event_time,
2120 header_realtime_sent_time);
2121 EXPECT_EQ(pi1_context->realtime_remote_time,
2122 header_realtime_remote_time);
2123 EXPECT_EQ(pi1_context->monotonic_remote_time,
2124 header_monotonic_remote_time);
2125
2126 EXPECT_EQ(pi2_context->realtime_event_time,
2127 header_realtime_remote_time);
2128 EXPECT_EQ(pi2_context->monotonic_event_time,
2129 header_monotonic_remote_time);
2130
2131 // Time estimation isn't perfect, but we know the clocks were
2132 // identical when logged, so we know when this should have come back.
2133 // Confirm we got it when we expected.
2134 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2135 pi2_context->monotonic_event_time + 2 * network_delay +
2136 send_delay);
2137 });
2138 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002139
2140 // And confirm we can re-create a log again, while checking the contents.
2141 {
2142 LoggerState pi1_logger = MakeLogger(
2143 configuration::GetNode(log_reader_factory.configuration(), pi1_),
2144 &log_reader_factory);
2145 LoggerState pi2_logger = MakeLogger(
2146 configuration::GetNode(log_reader_factory.configuration(), pi2_),
2147 &log_reader_factory);
2148
Austin Schuh25b46712021-01-03 00:04:38 -08002149 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2150 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002151
2152 log_reader_factory.Run();
2153 }
2154
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002155 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002156
2157 // And verify that we can run the LogReader over the relogged files without
2158 // hitting any fatal errors.
2159 {
2160 LogReader relogged_reader(SortParts(
2161 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2162 relogged_reader.Register();
2163
2164 relogged_reader.event_loop_factory()->Run();
2165 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002166}
2167
Austin Schuh315b96b2020-12-11 21:21:12 -08002168// Tests that we properly populate and extract the logger_start time by setting
2169// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002170TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002171 time_converter_.AddMonotonic(
2172 {monotonic_clock::epoch(),
2173 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002174 {
2175 LoggerState pi1_logger = MakeLogger(pi1_);
2176 LoggerState pi2_logger = MakeLogger(pi2_);
2177
Austin Schuh315b96b2020-12-11 21:21:12 -08002178 StartLogger(&pi1_logger);
2179 StartLogger(&pi2_logger);
2180
2181 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2182 }
2183
2184 for (const LogFile &log_file : SortParts(logfiles_)) {
2185 for (const LogParts &log_part : log_file.parts) {
2186 if (log_part.node == log_file.logger_node) {
2187 EXPECT_EQ(log_part.logger_monotonic_start_time,
2188 aos::monotonic_clock::min_time);
2189 EXPECT_EQ(log_part.logger_realtime_start_time,
2190 aos::realtime_clock::min_time);
2191 } else {
2192 const chrono::seconds offset = log_file.logger_node == "pi1"
2193 ? -chrono::seconds(1000)
2194 : chrono::seconds(1000);
2195 EXPECT_EQ(log_part.logger_monotonic_start_time,
2196 log_part.monotonic_start_time + offset);
2197 EXPECT_EQ(log_part.logger_realtime_start_time,
2198 log_file.realtime_start_time +
2199 (log_part.logger_monotonic_start_time -
2200 log_file.monotonic_start_time));
2201 }
2202 }
2203 }
2204}
2205
Austin Schuh6bb8a822021-03-31 23:04:39 -07002206// Test that renaming the base, renames the folder.
2207TEST_F(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002208 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2209 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002210 time_converter_.AddMonotonic(
2211 {monotonic_clock::epoch(),
2212 monotonic_clock::epoch() + chrono::seconds(1000)});
2213 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2214 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2215 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2216 LoggerState pi1_logger = MakeLogger(pi1_);
2217 LoggerState pi2_logger = MakeLogger(pi2_);
2218
2219 StartLogger(&pi1_logger);
2220 StartLogger(&pi2_logger);
2221
2222 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2223 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2224 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2225 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2226 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2227 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2228 for (auto &file : logfiles_) {
2229 struct stat s;
2230 EXPECT_EQ(0, stat(file.c_str(), &s));
2231 }
2232}
2233
2234// Test that renaming the file base dies.
2235TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2236 time_converter_.AddMonotonic(
2237 {monotonic_clock::epoch(),
2238 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002239 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002240 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2241 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2242 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2243 LoggerState pi1_logger = MakeLogger(pi1_);
2244 StartLogger(&pi1_logger);
2245 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2246 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2247 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2248 "Rename of file base from");
2249}
2250
Austin Schuh8bd96322020-02-13 21:18:22 -08002251// TODO(austin): We can write a test which recreates a logfile and confirms that
2252// we get it back. That is the ultimate test.
2253
Austin Schuh315b96b2020-12-11 21:21:12 -08002254// Tests that we properly recreate forwarded timestamps when replaying a log.
2255// This should be enough that we can then re-run the logger and get a valid log
2256// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08002257TEST_P(MultinodeLoggerDeathTest, RemoteReboot) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002258 time_converter_.StartEqual();
Austin Schuh315b96b2020-12-11 21:21:12 -08002259 std::string pi2_boot1;
2260 std::string pi2_boot2;
2261 {
2262 pi2_boot1 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2263 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002264 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002265 LoggerState pi1_logger = MakeLogger(pi1_);
2266
2267 event_loop_factory_.RunFor(chrono::milliseconds(95));
2268
2269 StartLogger(&pi1_logger);
2270
2271 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2272
2273 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Reboot();
2274
2275 pi2_boot2 = event_loop_factory_.GetNodeEventLoopFactory(pi2_)
2276 ->boot_uuid()
Austin Schuh5e2bfb82021-03-13 22:46:55 -08002277 .ToString();
Austin Schuh315b96b2020-12-11 21:21:12 -08002278
2279 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2280 }
2281
Austin Schuh72211ae2021-08-05 14:02:30 -07002282 // Confirm that our new oldest timestamps properly update as we reboot and
2283 // rotate.
2284 for (const std::string &file : pi1_reboot_logfiles_) {
2285 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2286 ReadHeader(file);
2287 CHECK(log_header);
2288 if (log_header->message().has_configuration()) {
2289 continue;
2290 }
2291
2292 if (log_header->message().node()->name()->string_view() != "pi1") {
2293 continue;
2294 }
2295 SCOPED_TRACE(file);
2296 SCOPED_TRACE(aos::FlatbufferToJson(
2297 *log_header, {.multi_line = true, .max_vector_size = 100}));
2298 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2299 ASSERT_EQ(
2300 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2301 EXPECT_EQ(
2302 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2303 monotonic_clock::max_time.time_since_epoch().count());
2304 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2305 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2306 2u);
2307 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2308 monotonic_clock::max_time.time_since_epoch().count());
2309 ASSERT_TRUE(log_header->message()
2310 .has_oldest_remote_unreliable_monotonic_timestamps());
2311 ASSERT_EQ(log_header->message()
2312 .oldest_remote_unreliable_monotonic_timestamps()
2313 ->size(),
2314 2u);
2315 EXPECT_EQ(log_header->message()
2316 .oldest_remote_unreliable_monotonic_timestamps()
2317 ->Get(0),
2318 monotonic_clock::max_time.time_since_epoch().count());
2319 ASSERT_TRUE(log_header->message()
2320 .has_oldest_local_unreliable_monotonic_timestamps());
2321 ASSERT_EQ(log_header->message()
2322 .oldest_local_unreliable_monotonic_timestamps()
2323 ->size(),
2324 2u);
2325 EXPECT_EQ(log_header->message()
2326 .oldest_local_unreliable_monotonic_timestamps()
2327 ->Get(0),
2328 monotonic_clock::max_time.time_since_epoch().count());
2329
2330 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2331 monotonic_clock::time_point(chrono::nanoseconds(
2332 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2333 1)));
2334 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2335 monotonic_clock::time_point(chrono::nanoseconds(
2336 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2337 const monotonic_clock::time_point
2338 oldest_remote_unreliable_monotonic_timestamps =
2339 monotonic_clock::time_point(chrono::nanoseconds(
2340 log_header->message()
2341 .oldest_remote_unreliable_monotonic_timestamps()
2342 ->Get(1)));
2343 const monotonic_clock::time_point
2344 oldest_local_unreliable_monotonic_timestamps =
2345 monotonic_clock::time_point(chrono::nanoseconds(
2346 log_header->message()
2347 .oldest_local_unreliable_monotonic_timestamps()
2348 ->Get(1)));
2349 switch (log_header->message().parts_index()) {
2350 case 0:
2351 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2352 monotonic_clock::max_time);
2353 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2354 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2355 monotonic_clock::max_time);
2356 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2357 monotonic_clock::max_time);
2358 break;
2359 case 1:
2360 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2361 monotonic_clock::time_point(chrono::microseconds(90200)));
2362 EXPECT_EQ(oldest_local_monotonic_timestamps,
2363 monotonic_clock::time_point(chrono::microseconds(90350)));
2364 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2365 monotonic_clock::time_point(chrono::microseconds(90200)));
2366 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2367 monotonic_clock::time_point(chrono::microseconds(90350)));
2368 break;
2369 case 2:
2370 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2371 monotonic_clock::time_point(chrono::microseconds(10100000)));
2372 EXPECT_EQ(oldest_local_monotonic_timestamps,
2373 monotonic_clock::time_point(chrono::microseconds(10100150)));
2374 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2375 monotonic_clock::max_time);
2376 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2377 monotonic_clock::max_time);
2378 break;
2379 case 3:
2380 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2381 monotonic_clock::time_point(chrono::microseconds(10100000)));
2382 EXPECT_EQ(oldest_local_monotonic_timestamps,
2383 monotonic_clock::time_point(chrono::microseconds(10100150)));
2384 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2385 monotonic_clock::time_point(chrono::microseconds(10100200)));
2386 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2387 monotonic_clock::time_point(chrono::microseconds(10100350)));
2388 break;
2389 default:
2390 FAIL();
2391 break;
2392 }
2393 }
2394
Austin Schuh315b96b2020-12-11 21:21:12 -08002395 // Confirm that we refuse to replay logs with missing boot uuids.
2396 EXPECT_DEATH(
2397 {
2398 LogReader reader(SortParts(pi1_reboot_logfiles_));
2399
2400 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2401 log_reader_factory.set_send_delay(chrono::microseconds(0));
2402
2403 // This sends out the fetched messages and advances time to the start of
2404 // the log file.
2405 reader.Register(&log_reader_factory);
2406 },
2407 absl::StrFormat("(%s|%s).*(%s|%s).*Found parts from different boots",
2408 pi2_boot1, pi2_boot2, pi2_boot2, pi2_boot1));
2409}
2410
Austin Schuhc9049732020-12-21 22:27:15 -08002411// Tests that we properly handle one direction of message_bridge being
2412// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002413TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002414 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002415 time_converter_.AddMonotonic(
2416 {monotonic_clock::epoch(),
2417 monotonic_clock::epoch() + chrono::seconds(1000)});
2418
2419 time_converter_.AddMonotonic(
2420 {chrono::milliseconds(10000),
2421 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002422 {
2423 LoggerState pi1_logger = MakeLogger(pi1_);
2424
2425 event_loop_factory_.RunFor(chrono::milliseconds(95));
2426
2427 StartLogger(&pi1_logger);
2428
2429 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2430 }
2431
2432 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2433 // to confirm the right thing happened.
2434 ConfirmReadable(pi1_single_direction_logfiles_);
2435}
2436
2437// Tests that we properly handle one direction of message_bridge being
2438// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002439TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuhc9049732020-12-21 22:27:15 -08002440 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
Austin Schuh87dd3832021-01-01 23:07:31 -08002441 time_converter_.AddMonotonic(
2442 {monotonic_clock::epoch(),
2443 monotonic_clock::epoch() + chrono::seconds(500)});
2444
2445 time_converter_.AddMonotonic(
2446 {chrono::milliseconds(10000),
2447 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2448 {
2449 LoggerState pi1_logger = MakeLogger(pi1_);
2450
2451 event_loop_factory_.RunFor(chrono::milliseconds(95));
2452
2453 StartLogger(&pi1_logger);
2454
2455 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2456 }
2457
2458 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2459 // to confirm the right thing happened.
2460 ConfirmReadable(pi1_single_direction_logfiles_);
2461}
2462
2463// Tests that we properly handle a dead node. Do this by just disconnecting it
2464// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002465TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002466 event_loop_factory_.GetNodeEventLoopFactory(pi1_)->Disconnect(pi2_);
2467 event_loop_factory_.GetNodeEventLoopFactory(pi2_)->Disconnect(pi1_);
2468 time_converter_.AddMonotonic(
2469 {monotonic_clock::epoch(),
2470 monotonic_clock::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002471 {
2472 LoggerState pi1_logger = MakeLogger(pi1_);
2473
2474 event_loop_factory_.RunFor(chrono::milliseconds(95));
2475
2476 StartLogger(&pi1_logger);
2477
2478 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2479 }
2480
2481 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2482 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002483 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002484}
2485
Austin Schuhcdd90272021-03-15 12:46:16 -07002486constexpr std::string_view kCombinedConfigSha1(
milind945708b2021-07-03 13:30:15 -07002487 "4503751edc96327493562f0376f0d6daac172927c0fd64d04ce5d67505186c0b");
Austin Schuhcdd90272021-03-15 12:46:16 -07002488constexpr std::string_view kSplitConfigSha1(
milind945708b2021-07-03 13:30:15 -07002489 "918a748432c5e70a971dfd8934968378bed04ab61cf2efcd35b7f6224053c247");
Austin Schuhcdd90272021-03-15 12:46:16 -07002490
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002491INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002492 All, MultinodeLoggerTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002493 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2494 kCombinedConfigSha1},
2495 Param{"multinode_pingpong_split_config.json", false,
2496 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002497
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002498INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002499 All, MultinodeLoggerDeathTest,
Austin Schuhcdd90272021-03-15 12:46:16 -07002500 ::testing::Values(Param{"multinode_pingpong_combined_config.json", true,
2501 kCombinedConfigSha1},
2502 Param{"multinode_pingpong_split_config.json", false,
2503 kSplitConfigSha1}));
Austin Schuh61e973f2021-02-21 21:43:56 -08002504
Austin Schuh5b728b72021-06-16 14:57:15 -07002505// Tests that we can relog with a different config. This makes most sense when
2506// you are trying to edit a log and want to use channel renaming + the original
2507// config in the new log.
2508TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
2509 time_converter_.StartEqual();
2510 {
2511 LoggerState pi1_logger = MakeLogger(pi1_);
2512 LoggerState pi2_logger = MakeLogger(pi2_);
2513
2514 event_loop_factory_.RunFor(chrono::milliseconds(95));
2515
2516 StartLogger(&pi1_logger);
2517 StartLogger(&pi2_logger);
2518
2519 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2520 }
2521
2522 LogReader reader(SortParts(logfiles_));
2523 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
2524
2525 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2526 log_reader_factory.set_send_delay(chrono::microseconds(0));
2527
2528 // This sends out the fetched messages and advances time to the start of the
2529 // log file.
2530 reader.Register(&log_reader_factory);
2531
2532 const Node *pi1 =
2533 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2534 const Node *pi2 =
2535 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2536
2537 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2538 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2539 LOG(INFO) << "now pi1 "
2540 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2541 LOG(INFO) << "now pi2 "
2542 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2543
2544 EXPECT_THAT(reader.LoggedNodes(),
2545 ::testing::ElementsAre(
2546 configuration::GetNode(reader.logged_configuration(), pi1),
2547 configuration::GetNode(reader.logged_configuration(), pi2)));
2548
2549 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2550
2551 // And confirm we can re-create a log again, while checking the contents.
2552 std::vector<std::string> log_files;
2553 {
2554 LoggerState pi1_logger =
2555 MakeLogger(configuration::GetNode(reader.logged_configuration(), pi1_),
2556 &log_reader_factory, reader.logged_configuration());
2557 LoggerState pi2_logger =
2558 MakeLogger(configuration::GetNode(reader.logged_configuration(), pi2_),
2559 &log_reader_factory, reader.logged_configuration());
2560
2561 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2562 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
2563
2564 log_reader_factory.Run();
2565
2566 for (auto &x : pi1_logger.log_namer->all_filenames()) {
2567 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
2568 }
2569 for (auto &x : pi2_logger.log_namer->all_filenames()) {
2570 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
2571 }
2572 }
2573
2574 reader.Deregister();
2575
2576 // And verify that we can run the LogReader over the relogged files without
2577 // hitting any fatal errors.
2578 {
2579 LogReader relogged_reader(SortParts(log_files));
2580 relogged_reader.Register();
2581
2582 relogged_reader.event_loop_factory()->Run();
2583 }
2584}
Austin Schuha04efed2021-01-24 18:04:20 -08002585
Austin Schuhe309d2a2019-11-29 13:25:21 -08002586} // namespace testing
2587} // namespace logger
2588} // namespace aos