blob: 081d3c42d197198d91cbbef9d0928b56fc01a56f [file] [log] [blame]
Austin Schuh6bb8a822021-03-31 23:04:39 -07001#include <sys/stat.h>
2
Austin Schuh315b96b2020-12-11 21:21:12 -08003#include "absl/strings/str_format.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08004#include "aos/events/event_loop.h"
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07005#include "aos/events/logging/log_reader.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -08006#include "aos/events/logging/log_writer.h"
milind1f1dca32021-07-03 13:50:07 -07007#include "aos/events/logging/snappy_encoder.h"
Austin Schuh01b4c352020-09-21 23:09:39 -07008#include "aos/events/message_counter.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -08009#include "aos/events/ping_lib.h"
10#include "aos/events/pong_lib.h"
11#include "aos/events/simulated_event_loop.h"
Austin Schuh0de30f32020-12-06 12:44:28 -080012#include "aos/network/remote_message_generated.h"
Austin Schuh87dd3832021-01-01 23:07:31 -080013#include "aos/network/testing_time_converter.h"
Austin Schuh8d7e0bb2020-10-02 17:57:00 -070014#include "aos/network/timestamp_generated.h"
Austin Schuh373f1762021-06-02 21:07:09 -070015#include "aos/testing/path.h"
Austin Schuhc243b422020-10-11 15:35:08 -070016#include "aos/testing/tmpdir.h"
Austin Schuh2f8fd752020-09-01 22:38:28 -070017#include "aos/util/file.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080018#include "glog/logging.h"
Austin Schuh6f3babe2020-01-26 20:34:50 -080019#include "gmock/gmock.h"
Austin Schuhe309d2a2019-11-29 13:25:21 -080020#include "gtest/gtest.h"
21
Austin Schuh3bd4c402020-11-06 18:19:06 -080022#ifdef LZMA
23#include "aos/events/logging/lzma_encoder.h"
24#endif
25
Austin Schuhe309d2a2019-11-29 13:25:21 -080026namespace aos {
27namespace logger {
28namespace testing {
29
Austin Schuh373f1762021-06-02 21:07:09 -070030using aos::testing::ArtifactPath;
31
Austin Schuhe309d2a2019-11-29 13:25:21 -080032namespace chrono = std::chrono;
Austin Schuh0de30f32020-12-06 12:44:28 -080033using aos::message_bridge::RemoteMessage;
Austin Schuh01b4c352020-09-21 23:09:39 -070034using aos::testing::MessageCounter;
Austin Schuhe309d2a2019-11-29 13:25:21 -080035
Austin Schuhee4713b2021-03-21 19:25:17 -070036constexpr std::string_view kSingleConfigSha256(
Austin Schuhb8bca732021-07-30 22:32:00 -070037 "bbe1b563139273b23a5405eebc2f2740cefcda5f96681acd0a84b8ff9ab93ea4");
Austin Schuh8c399962020-12-25 21:51:45 -080038
Austin Schuhb06f03b2021-02-17 22:00:37 -080039std::vector<std::vector<std::string>> ToLogReaderVector(
40 const std::vector<LogFile> &log_files) {
41 std::vector<std::vector<std::string>> result;
42 for (const LogFile &log_file : log_files) {
43 for (const LogParts &log_parts : log_file.parts) {
44 std::vector<std::string> parts;
45 for (const std::string &part : log_parts.parts) {
46 parts.emplace_back(part);
47 }
48 result.emplace_back(std::move(parts));
49 }
50 }
51 return result;
52}
53
Austin Schuhe309d2a2019-11-29 13:25:21 -080054class LoggerTest : public ::testing::Test {
55 public:
56 LoggerTest()
Austin Schuh373f1762021-06-02 21:07:09 -070057 : config_(aos::configuration::ReadConfig(
58 ArtifactPath("aos/events/pingpong_config.json"))),
Austin Schuhe309d2a2019-11-29 13:25:21 -080059 event_loop_factory_(&config_.message()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080060 ping_event_loop_(event_loop_factory_.MakeEventLoop("ping")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080061 ping_(ping_event_loop_.get()),
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080062 pong_event_loop_(event_loop_factory_.MakeEventLoop("pong")),
Austin Schuhe309d2a2019-11-29 13:25:21 -080063 pong_(pong_event_loop_.get()) {}
64
65 // Config and factory.
66 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
67 SimulatedEventLoopFactory event_loop_factory_;
68
69 // Event loop and app for Ping
70 std::unique_ptr<EventLoop> ping_event_loop_;
71 Ping ping_;
72
73 // Event loop and app for Pong
74 std::unique_ptr<EventLoop> pong_event_loop_;
75 Pong pong_;
76};
77
Brian Silverman1f345222020-09-24 21:14:48 -070078using LoggerDeathTest = LoggerTest;
79
Austin Schuhe309d2a2019-11-29 13:25:21 -080080// Tests that we can startup at all. This confirms that the channels are all in
81// the config.
82TEST_F(LoggerTest, Starts) {
Austin Schuhc243b422020-10-11 15:35:08 -070083 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -070084 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -080085 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -070086 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -070087 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuhe309d2a2019-11-29 13:25:21 -080088 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -080089 unlink(config.c_str());
Austin Schuhe309d2a2019-11-29 13:25:21 -080090 unlink(logfile.c_str());
91
92 LOG(INFO) << "Logging data to " << logfile;
93
94 {
Austin Schuhe309d2a2019-11-29 13:25:21 -080095 std::unique_ptr<EventLoop> logger_event_loop =
Austin Schuh5f1cc5c2019-12-01 18:01:11 -080096 event_loop_factory_.MakeEventLoop("logger");
Austin Schuhe309d2a2019-11-29 13:25:21 -080097
98 event_loop_factory_.RunFor(chrono::milliseconds(95));
99
Brian Silverman1f345222020-09-24 21:14:48 -0700100 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800101 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700102 logger.set_polling_period(std::chrono::milliseconds(100));
103 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800104 event_loop_factory_.RunFor(chrono::milliseconds(20000));
105 }
106
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800107 // Even though it doesn't make any difference here, exercise the logic for
108 // passing in a separate config.
109 LogReader reader(logfile, &config_.message());
Austin Schuhe309d2a2019-11-29 13:25:21 -0800110
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800111 // Confirm that we can remap logged channels to point to new buses.
112 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800113
Austin Schuh15649d62019-12-28 16:36:38 -0800114 // This sends out the fetched messages and advances time to the start of the
115 // log file.
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800116 reader.Register();
Austin Schuhe309d2a2019-11-29 13:25:21 -0800117
Austin Schuh07676622021-01-21 18:59:17 -0800118 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800119
Austin Schuhe309d2a2019-11-29 13:25:21 -0800120 std::unique_ptr<EventLoop> test_event_loop =
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800121 reader.event_loop_factory()->MakeEventLoop("log_reader");
Austin Schuhe309d2a2019-11-29 13:25:21 -0800122
123 int ping_count = 10;
124 int pong_count = 10;
125
James Kuszmaulc7bbb3e2020-01-03 20:01:00 -0800126 // Confirm that the ping value matches in the remapped channel location.
127 test_event_loop->MakeWatcher("/original/test",
Austin Schuhe309d2a2019-11-29 13:25:21 -0800128 [&ping_count](const examples::Ping &ping) {
129 EXPECT_EQ(ping.value(), ping_count + 1);
130 ++ping_count;
131 });
132 // Confirm that the ping and pong counts both match, and the value also
133 // matches.
134 test_event_loop->MakeWatcher(
135 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
136 EXPECT_EQ(pong.value(), pong_count + 1);
137 ++pong_count;
138 EXPECT_EQ(ping_count, pong_count);
139 });
140
James Kuszmaul84ff3e52020-01-03 19:48:53 -0800141 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
Austin Schuhe309d2a2019-11-29 13:25:21 -0800142 EXPECT_EQ(ping_count, 2010);
Austin Schuhe309d2a2019-11-29 13:25:21 -0800143}
144
Brian Silverman1f345222020-09-24 21:14:48 -0700145// Tests calling StartLogging twice.
146TEST_F(LoggerDeathTest, ExtraStart) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800147 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700148 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800149 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700150 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700151 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
152 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800153 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700154 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700155 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
156 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800157 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700158 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800159 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700160
161 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
162
163 {
164 std::unique_ptr<EventLoop> logger_event_loop =
165 event_loop_factory_.MakeEventLoop("logger");
166
167 event_loop_factory_.RunFor(chrono::milliseconds(95));
168
169 Logger logger(logger_event_loop.get());
170 logger.set_polling_period(std::chrono::milliseconds(100));
milind1f1dca32021-07-03 13:50:07 -0700171 logger_event_loop->OnRun([base_name1, base_name2, &logger_event_loop,
172 &logger]() {
173 logger.StartLogging(std::make_unique<LocalLogNamer>(
174 base_name1, logger_event_loop.get(), logger_event_loop->node()));
175 EXPECT_DEATH(
Austin Schuh5b728b72021-06-16 14:57:15 -0700176 logger.StartLogging(std::make_unique<LocalLogNamer>(
milind1f1dca32021-07-03 13:50:07 -0700177 base_name2, logger_event_loop.get(), logger_event_loop->node())),
178 "Already logging");
179 });
Brian Silverman1f345222020-09-24 21:14:48 -0700180 event_loop_factory_.RunFor(chrono::milliseconds(20000));
181 }
182}
183
184// Tests calling StopLogging twice.
185TEST_F(LoggerDeathTest, ExtraStop) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800186 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700187 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800188 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700189 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700190 const ::std::string logfile = base_name + ".part0.bfbs";
191 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800192 unlink(config.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700193 unlink(logfile.c_str());
194
195 LOG(INFO) << "Logging data to " << logfile;
196
197 {
198 std::unique_ptr<EventLoop> logger_event_loop =
199 event_loop_factory_.MakeEventLoop("logger");
200
201 event_loop_factory_.RunFor(chrono::milliseconds(95));
202
203 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800204 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700205 logger.set_polling_period(std::chrono::milliseconds(100));
206 logger_event_loop->OnRun([base_name, &logger_event_loop, &logger]() {
Austin Schuh5b728b72021-06-16 14:57:15 -0700207 logger.StartLogging(std::make_unique<LocalLogNamer>(
208 base_name, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700209 logger.StopLogging(aos::monotonic_clock::min_time);
210 EXPECT_DEATH(logger.StopLogging(aos::monotonic_clock::min_time),
211 "Not logging right now");
212 });
213 event_loop_factory_.RunFor(chrono::milliseconds(20000));
214 }
215}
216
217// Tests that we can startup twice.
218TEST_F(LoggerTest, StartsTwice) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800219 const ::std::string tmpdir = aos::testing::TestTmpDir();
Brian Silverman1f345222020-09-24 21:14:48 -0700220 const ::std::string base_name1 = tmpdir + "/logfile1";
Austin Schuh25b46712021-01-03 00:04:38 -0800221 const ::std::string config1 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700222 absl::StrCat(base_name1, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700223 const ::std::string logfile1 = base_name1 + ".part0.bfbs";
224 const ::std::string base_name2 = tmpdir + "/logfile2";
Austin Schuh25b46712021-01-03 00:04:38 -0800225 const ::std::string config2 =
Austin Schuhee4713b2021-03-21 19:25:17 -0700226 absl::StrCat(base_name2, kSingleConfigSha256, ".bfbs");
Brian Silverman1f345222020-09-24 21:14:48 -0700227 const ::std::string logfile2 = base_name2 + ".part0.bfbs";
228 unlink(logfile1.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800229 unlink(config1.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700230 unlink(logfile2.c_str());
Austin Schuh25b46712021-01-03 00:04:38 -0800231 unlink(config2.c_str());
Brian Silverman1f345222020-09-24 21:14:48 -0700232
233 LOG(INFO) << "Logging data to " << logfile1 << " then " << logfile2;
234
235 {
236 std::unique_ptr<EventLoop> logger_event_loop =
237 event_loop_factory_.MakeEventLoop("logger");
238
239 event_loop_factory_.RunFor(chrono::milliseconds(95));
240
241 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800242 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700243 logger.set_polling_period(std::chrono::milliseconds(100));
Austin Schuh5b728b72021-06-16 14:57:15 -0700244 logger.StartLogging(std::make_unique<LocalLogNamer>(
245 base_name1, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700246 event_loop_factory_.RunFor(chrono::milliseconds(10000));
247 logger.StopLogging(logger_event_loop->monotonic_now());
248 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh5b728b72021-06-16 14:57:15 -0700249 logger.StartLogging(std::make_unique<LocalLogNamer>(
250 base_name2, logger_event_loop.get(), logger_event_loop->node()));
Brian Silverman1f345222020-09-24 21:14:48 -0700251 event_loop_factory_.RunFor(chrono::milliseconds(10000));
252 }
253
254 for (const auto &logfile :
255 {std::make_tuple(logfile1, 10), std::make_tuple(logfile2, 2010)}) {
256 SCOPED_TRACE(std::get<0>(logfile));
257 LogReader reader(std::get<0>(logfile));
258 reader.Register();
259
Austin Schuh07676622021-01-21 18:59:17 -0800260 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Brian Silverman1f345222020-09-24 21:14:48 -0700261
262 std::unique_ptr<EventLoop> test_event_loop =
263 reader.event_loop_factory()->MakeEventLoop("log_reader");
264
265 int ping_count = std::get<1>(logfile);
266 int pong_count = std::get<1>(logfile);
267
268 // Confirm that the ping and pong counts both match, and the value also
269 // matches.
270 test_event_loop->MakeWatcher("/test",
271 [&ping_count](const examples::Ping &ping) {
272 EXPECT_EQ(ping.value(), ping_count + 1);
273 ++ping_count;
274 });
275 test_event_loop->MakeWatcher(
276 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
277 EXPECT_EQ(pong.value(), pong_count + 1);
278 ++pong_count;
279 EXPECT_EQ(ping_count, pong_count);
280 });
281
282 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
283 EXPECT_EQ(ping_count, std::get<1>(logfile) + 1000);
284 }
285}
286
Austin Schuhfa895892020-01-07 20:07:41 -0800287// Tests that we can read and write rotated log files.
288TEST_F(LoggerTest, RotatedLogFile) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800289 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700290 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800291 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700292 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700293 const ::std::string logfile0 = base_name + ".part0.bfbs";
294 const ::std::string logfile1 = base_name + ".part1.bfbs";
Austin Schuhfa895892020-01-07 20:07:41 -0800295 // Remove it.
Austin Schuh25b46712021-01-03 00:04:38 -0800296 unlink(config.c_str());
Austin Schuhfa895892020-01-07 20:07:41 -0800297 unlink(logfile0.c_str());
298 unlink(logfile1.c_str());
299
300 LOG(INFO) << "Logging data to " << logfile0 << " and " << logfile1;
301
302 {
Austin Schuhfa895892020-01-07 20:07:41 -0800303 std::unique_ptr<EventLoop> logger_event_loop =
304 event_loop_factory_.MakeEventLoop("logger");
305
306 event_loop_factory_.RunFor(chrono::milliseconds(95));
307
Brian Silverman1f345222020-09-24 21:14:48 -0700308 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800309 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700310 logger.set_polling_period(std::chrono::milliseconds(100));
311 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuhfa895892020-01-07 20:07:41 -0800312 event_loop_factory_.RunFor(chrono::milliseconds(10000));
Austin Schuh2f8fd752020-09-01 22:38:28 -0700313 logger.Rotate();
Austin Schuhfa895892020-01-07 20:07:41 -0800314 event_loop_factory_.RunFor(chrono::milliseconds(10000));
315 }
316
Austin Schuh64fab802020-09-09 22:47:47 -0700317 {
318 // Confirm that the UUIDs match for both the parts and the logger, and the
319 // parts_index increments.
Austin Schuhadd6eb32020-11-09 21:24:26 -0800320 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -0700321 for (std::string_view f : {logfile0, logfile1}) {
Austin Schuh3bd4c402020-11-06 18:19:06 -0800322 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh64fab802020-09-09 22:47:47 -0700323 }
324
Brian Silvermanae7c0332020-09-30 16:58:23 -0700325 EXPECT_EQ(log_header[0].message().log_event_uuid()->string_view(),
326 log_header[1].message().log_event_uuid()->string_view());
Austin Schuh64fab802020-09-09 22:47:47 -0700327 EXPECT_EQ(log_header[0].message().parts_uuid()->string_view(),
328 log_header[1].message().parts_uuid()->string_view());
329
330 EXPECT_EQ(log_header[0].message().parts_index(), 0);
331 EXPECT_EQ(log_header[1].message().parts_index(), 1);
332 }
333
Austin Schuhfa895892020-01-07 20:07:41 -0800334 // Even though it doesn't make any difference here, exercise the logic for
335 // passing in a separate config.
Austin Schuh287d43d2020-12-04 20:19:33 -0800336 LogReader reader(SortParts({logfile0, logfile1}), &config_.message());
Austin Schuhfa895892020-01-07 20:07:41 -0800337
338 // Confirm that we can remap logged channels to point to new buses.
339 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
340
341 // This sends out the fetched messages and advances time to the start of the
342 // log file.
343 reader.Register();
344
Austin Schuh07676622021-01-21 18:59:17 -0800345 EXPECT_THAT(reader.LoggedNodes(), ::testing::ElementsAre(nullptr));
Austin Schuhfa895892020-01-07 20:07:41 -0800346
347 std::unique_ptr<EventLoop> test_event_loop =
348 reader.event_loop_factory()->MakeEventLoop("log_reader");
349
350 int ping_count = 10;
351 int pong_count = 10;
352
353 // Confirm that the ping value matches in the remapped channel location.
354 test_event_loop->MakeWatcher("/original/test",
355 [&ping_count](const examples::Ping &ping) {
356 EXPECT_EQ(ping.value(), ping_count + 1);
357 ++ping_count;
358 });
359 // Confirm that the ping and pong counts both match, and the value also
360 // matches.
361 test_event_loop->MakeWatcher(
362 "/test", [&pong_count, &ping_count](const examples::Pong &pong) {
363 EXPECT_EQ(pong.value(), pong_count + 1);
364 ++pong_count;
365 EXPECT_EQ(ping_count, pong_count);
366 });
367
368 reader.event_loop_factory()->RunFor(std::chrono::seconds(100));
369 EXPECT_EQ(ping_count, 2010);
370}
371
Austin Schuh4c4e0092019-12-22 16:18:03 -0800372// Tests that a large number of messages per second doesn't overwhelm writev.
373TEST_F(LoggerTest, ManyMessages) {
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800374 const ::std::string tmpdir = aos::testing::TestTmpDir();
Austin Schuh2f8fd752020-09-01 22:38:28 -0700375 const ::std::string base_name = tmpdir + "/logfile";
Austin Schuh25b46712021-01-03 00:04:38 -0800376 const ::std::string config =
Austin Schuhee4713b2021-03-21 19:25:17 -0700377 absl::StrCat(base_name, kSingleConfigSha256, ".bfbs");
Austin Schuh2f8fd752020-09-01 22:38:28 -0700378 const ::std::string logfile = base_name + ".part0.bfbs";
Austin Schuh4c4e0092019-12-22 16:18:03 -0800379 // Remove the log file.
Austin Schuh25b46712021-01-03 00:04:38 -0800380 unlink(config.c_str());
Austin Schuh4c4e0092019-12-22 16:18:03 -0800381 unlink(logfile.c_str());
382
383 LOG(INFO) << "Logging data to " << logfile;
Austin Schuh4c3b9702020-08-30 11:34:55 -0700384 ping_.set_quiet(true);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800385
386 {
Austin Schuh4c4e0092019-12-22 16:18:03 -0800387 std::unique_ptr<EventLoop> logger_event_loop =
388 event_loop_factory_.MakeEventLoop("logger");
389
390 std::unique_ptr<EventLoop> ping_spammer_event_loop =
391 event_loop_factory_.MakeEventLoop("ping_spammer");
392 aos::Sender<examples::Ping> ping_sender =
393 ping_spammer_event_loop->MakeSender<examples::Ping>("/test");
394
395 aos::TimerHandler *timer_handler =
396 ping_spammer_event_loop->AddTimer([&ping_sender]() {
397 aos::Sender<examples::Ping>::Builder builder =
398 ping_sender.MakeBuilder();
399 examples::Ping::Builder ping_builder =
400 builder.MakeBuilder<examples::Ping>();
milind1f1dca32021-07-03 13:50:07 -0700401 CHECK_EQ(builder.Send(ping_builder.Finish()),
402 RawSender::Error::kOk);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800403 });
404
405 // 100 ms / 0.05 ms -> 2000 messages. Should be enough to crash it.
406 ping_spammer_event_loop->OnRun([&ping_spammer_event_loop, timer_handler]() {
407 timer_handler->Setup(ping_spammer_event_loop->monotonic_now(),
408 chrono::microseconds(50));
409 });
410
Brian Silverman1f345222020-09-24 21:14:48 -0700411 Logger logger(logger_event_loop.get());
Austin Schuh8c399962020-12-25 21:51:45 -0800412 logger.set_separate_config(false);
Brian Silverman1f345222020-09-24 21:14:48 -0700413 logger.set_polling_period(std::chrono::milliseconds(100));
414 logger.StartLoggingLocalNamerOnRun(base_name);
Austin Schuh4c4e0092019-12-22 16:18:03 -0800415
416 event_loop_factory_.RunFor(chrono::milliseconds(1000));
417 }
418}
419
James Kuszmauldd0a5042021-10-28 23:38:04 -0700420struct CompressionParams {
421 std::string_view extension;
422 std::function<std::unique_ptr<DetachedBufferEncoder>()> encoder_factory;
423};
424
425std::ostream &operator<<(std::ostream &ostream,
426 const CompressionParams &params) {
427 ostream << "\"" << params.extension << "\"";
428 return ostream;
429}
430
431std::vector<CompressionParams> SupportedCompressionAlgorithms() {
432 return {{"", []() { return std::make_unique<DummyEncoder>(); }},
433 {SnappyDecoder::kExtension,
434 []() { return std::make_unique<SnappyEncoder>(); }},
435#ifdef LZMA
436 {LzmaDecoder::kExtension,
437 []() { return std::make_unique<LzmaEncoder>(3); }}
438#endif // LZMA
439 };
440}
441
Austin Schuh61e973f2021-02-21 21:43:56 -0800442// Parameters to run all the tests with.
James Kuszmauldd0a5042021-10-28 23:38:04 -0700443struct ConfigParams {
Austin Schuh61e973f2021-02-21 21:43:56 -0800444 // The config file to use.
445 std::string config;
446 // If true, the RemoteMessage channel should be shared between all the remote
447 // channels. If false, there will be 1 RemoteMessage channel per remote
448 // channel.
449 bool shared;
450 // sha256 of the config.
Austin Schuhcdd90272021-03-15 12:46:16 -0700451 std::string_view sha256;
Austin Schuh61e973f2021-02-21 21:43:56 -0800452};
Austin Schuh315b96b2020-12-11 21:21:12 -0800453
James Kuszmauldd0a5042021-10-28 23:38:04 -0700454std::ostream &operator<<(std::ostream &ostream, const ConfigParams &params) {
455 ostream << "{config: \"" << params.config << "\", shared: " << params.shared
456 << ", sha256: \"" << params.sha256 << "\"}";
457 return ostream;
458}
459
Austin Schuh3e20c692021-11-16 20:43:16 -0800460struct LoggerState {
461 static LoggerState MakeLogger(NodeEventLoopFactory *node,
462 SimulatedEventLoopFactory *factory,
463 CompressionParams params,
464 const Configuration *configuration = nullptr) {
465 if (configuration == nullptr) {
466 configuration = factory->configuration();
467 }
468 return {node->MakeEventLoop("logger"),
469 {},
470 configuration,
471 configuration::GetNode(configuration, node->node()),
472 nullptr,
473 params};
474 }
475
476 void StartLogger(std::string logfile_base) {
477 CHECK(!logfile_base.empty());
478
479 logger = std::make_unique<Logger>(event_loop.get(), configuration);
480 logger->set_polling_period(std::chrono::milliseconds(100));
481 logger->set_name(
482 absl::StrCat("name_prefix_", event_loop->node()->name()->str()));
483 event_loop->OnRun([this, logfile_base]() {
484 std::unique_ptr<MultiNodeLogNamer> namer =
485 std::make_unique<MultiNodeLogNamer>(logfile_base, configuration,
486 event_loop.get(), node);
487 namer->set_extension(params.extension);
488 namer->set_encoder_factory(params.encoder_factory);
489 log_namer = namer.get();
490
491 logger->StartLogging(std::move(namer));
492 });
493 }
494
495 std::unique_ptr<EventLoop> event_loop;
496 std::unique_ptr<Logger> logger;
497 const Configuration *configuration;
498 const Node *node;
499 MultiNodeLogNamer *log_namer;
500 CompressionParams params;
501
502 void AppendAllFilenames(std::vector<std::string> *filenames) {
503 for (const std::string &file : log_namer->all_filenames()) {
504 const std::string_view separator =
505 log_namer->base_name().back() == '/' ? "" : "_";
506 filenames->emplace_back(
507 absl::StrCat(log_namer->base_name(), separator, file));
508 }
509 }
510
511 ~LoggerState() {
512 if (logger) {
Austin Schuh01f3b392022-01-25 20:03:09 -0800513 std::vector<std::string> filenames;
514 AppendAllFilenames(&filenames);
515 for (const std::string &file : filenames) {
Austin Schuh3e20c692021-11-16 20:43:16 -0800516 LOG(INFO) << "Wrote to " << file;
Austin Schuh01f3b392022-01-25 20:03:09 -0800517 auto x = ReadHeader(file);
518 if (x) {
519 VLOG(1) << aos::FlatbufferToJson(x.value());
520 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800521 }
522 }
523 }
524};
525
526void ConfirmReadable(const std::vector<std::string> &files) {
527 {
528 LogReader reader(SortParts(files));
529
530 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
531 reader.Register(&log_reader_factory);
532
533 log_reader_factory.Run();
534
535 reader.Deregister();
536 }
537 {
538 LogReader reader(SortParts(files));
539
540 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
541 reader.RegisterWithoutStarting(&log_reader_factory);
542 if (configuration::MultiNode(log_reader_factory.configuration())) {
543 for (const aos::Node *node :
544 *log_reader_factory.configuration()->nodes()) {
545 reader.OnStart(node, [node]() {
546 LOG(INFO) << "Starting " << node->name()->string_view();
547 });
548 }
549 }
550
551 log_reader_factory.Run();
552
553 reader.Deregister();
554 }
555}
556
James Kuszmauldd0a5042021-10-28 23:38:04 -0700557class MultinodeLoggerTest : public ::testing::TestWithParam<
558 std::tuple<ConfigParams, CompressionParams>> {
Austin Schuh15649d62019-12-28 16:36:38 -0800559 public:
560 MultinodeLoggerTest()
James Kuszmauldd0a5042021-10-28 23:38:04 -0700561 : config_(aos::configuration::ReadConfig(ArtifactPath(absl::StrCat(
562 "aos/events/logging/", std::get<0>(GetParam()).config)))),
Austin Schuh87dd3832021-01-01 23:07:31 -0800563 time_converter_(configuration::NodesCount(&config_.message())),
Austin Schuhac0771c2020-01-07 18:36:30 -0800564 event_loop_factory_(&config_.message()),
Austin Schuh58646e22021-08-23 23:51:46 -0700565 pi1_(event_loop_factory_.GetNodeEventLoopFactory("pi1")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800566 pi1_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700567 event_loop_factory_.configuration(), pi1_->node())),
568 pi2_(event_loop_factory_.GetNodeEventLoopFactory("pi2")),
Austin Schuh87dd3832021-01-01 23:07:31 -0800569 pi2_index_(configuration::GetNodeIndex(
Austin Schuh58646e22021-08-23 23:51:46 -0700570 event_loop_factory_.configuration(), pi2_->node())),
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800571 tmp_dir_(aos::testing::TestTmpDir()),
Austin Schuh8c399962020-12-25 21:51:45 -0800572 logfile_base1_(tmp_dir_ + "/multi_logfile1"),
573 logfile_base2_(tmp_dir_ + "/multi_logfile2"),
Austin Schuh61e973f2021-02-21 21:43:56 -0800574 pi1_reboot_logfiles_(MakePi1RebootLogfiles()),
Austin Schuh8c399962020-12-25 21:51:45 -0800575 logfiles_(MakeLogFiles(logfile_base1_, logfile_base2_)),
Austin Schuh61e973f2021-02-21 21:43:56 -0800576 pi1_single_direction_logfiles_(MakePi1SingleDirectionLogfiles()),
Austin Schuh58646e22021-08-23 23:51:46 -0700577 structured_logfiles_(StructureLogFiles()) {
James Kuszmauldd0a5042021-10-28 23:38:04 -0700578 LOG(INFO) << "Config " << std::get<0>(GetParam()).config;
Austin Schuh87dd3832021-01-01 23:07:31 -0800579 event_loop_factory_.SetTimeConverter(&time_converter_);
580
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700581 // Go through and remove the logfiles if they already exist.
Austin Schuh268586b2021-03-31 22:24:39 -0700582 for (const auto &file : logfiles_) {
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700583 unlink(file.c_str());
Austin Schuhc6f8f1b2020-12-02 23:23:39 -0800584 unlink((file + ".xz").c_str());
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700585 }
586
Austin Schuh268586b2021-03-31 22:24:39 -0700587 for (const auto &file :
Austin Schuh25b46712021-01-03 00:04:38 -0800588 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800589 unlink(file.c_str());
590 }
591
Austin Schuh268586b2021-03-31 22:24:39 -0700592 for (const auto &file : pi1_reboot_logfiles_) {
Austin Schuh315b96b2020-12-11 21:21:12 -0800593 unlink(file.c_str());
594 }
595
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700596 LOG(INFO) << "Logging data to " << logfiles_[0] << ", " << logfiles_[1]
597 << " and " << logfiles_[2];
Austin Schuh58646e22021-08-23 23:51:46 -0700598
599 pi1_->OnStartup([this]() { pi1_->AlwaysStart<Ping>("ping"); });
600 pi2_->OnStartup([this]() { pi2_->AlwaysStart<Pong>("pong"); });
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700601 }
602
James Kuszmauldd0a5042021-10-28 23:38:04 -0700603 bool shared() const { return std::get<0>(GetParam()).shared; }
Austin Schuh61e973f2021-02-21 21:43:56 -0800604
605 std::vector<std::string> MakeLogFiles(std::string logfile_base1,
Austin Schuhe46492f2021-07-31 19:49:41 -0700606 std::string logfile_base2,
607 size_t pi1_data_count = 2,
608 size_t pi2_data_count = 2) {
Austin Schuh61e973f2021-02-21 21:43:56 -0800609 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700610 result.emplace_back(absl::StrCat(
611 logfile_base1, "_", std::get<0>(GetParam()).sha256, Extension()));
612 result.emplace_back(absl::StrCat(
613 logfile_base2, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700614 for (size_t i = 0; i < pi1_data_count; ++i) {
615 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700616 absl::StrCat(logfile_base1, "_pi1_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700617 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800618 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700619 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800620 result.emplace_back(logfile_base1 +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700621 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuhe46492f2021-07-31 19:49:41 -0700622 for (size_t i = 0; i < pi2_data_count; ++i) {
623 result.emplace_back(
James Kuszmauldd0a5042021-10-28 23:38:04 -0700624 absl::StrCat(logfile_base2, "_pi2_data.part", i, Extension()));
Austin Schuhe46492f2021-07-31 19:49:41 -0700625 }
James Kuszmauldd0a5042021-10-28 23:38:04 -0700626 result.emplace_back(logfile_base2 +
627 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part0" +
628 Extension());
629 result.emplace_back(logfile_base2 +
630 "_pi1_data/pi1/aos/aos.message_bridge.Timestamp.part1" +
631 Extension());
632 result.emplace_back(logfile_base1 +
633 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
634 Extension());
635 result.emplace_back(logfile_base1 +
636 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
637 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800638 if (shared()) {
639 result.emplace_back(logfile_base1 +
640 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700641 "aos.message_bridge.RemoteMessage.part0" +
642 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800643 result.emplace_back(logfile_base1 +
644 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700645 "aos.message_bridge.RemoteMessage.part1" +
646 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800647 result.emplace_back(logfile_base2 +
648 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700649 "aos.message_bridge.RemoteMessage.part0" +
650 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800651 result.emplace_back(logfile_base2 +
652 "_timestamps/pi2/aos/remote_timestamps/pi1/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700653 "aos.message_bridge.RemoteMessage.part1" +
654 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800655 } else {
656 result.emplace_back(logfile_base1 +
657 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
658 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700659 "aos.message_bridge.RemoteMessage.part0" +
660 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800661 result.emplace_back(logfile_base1 +
662 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
663 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700664 "aos.message_bridge.RemoteMessage.part1" +
665 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800666 result.emplace_back(logfile_base2 +
667 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
668 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700669 "aos.message_bridge.RemoteMessage.part0" +
670 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800671 result.emplace_back(logfile_base2 +
672 "_timestamps/pi2/aos/remote_timestamps/pi1/pi2/aos/"
673 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700674 "aos.message_bridge.RemoteMessage.part1" +
675 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800676 result.emplace_back(logfile_base1 +
677 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
678 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700679 "aos.message_bridge.RemoteMessage.part0" +
680 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800681 result.emplace_back(logfile_base1 +
682 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
683 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700684 "aos.message_bridge.RemoteMessage.part1" +
685 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800686 }
687
688 return result;
689 }
690
691 std::vector<std::string> MakePi1RebootLogfiles() {
692 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700693 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
694 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
695 result.emplace_back(logfile_base1_ + "_pi1_data.part2" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800696 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700697 "_pi2_data/test/aos.examples.Pong.part0" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800698 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700699 "_pi2_data/test/aos.examples.Pong.part1" + Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800700 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700701 "_pi2_data/test/aos.examples.Pong.part2" + Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700702 result.emplace_back(logfile_base1_ +
James Kuszmauldd0a5042021-10-28 23:38:04 -0700703 "_pi2_data/test/aos.examples.Pong.part3" + Extension());
704 result.emplace_back(logfile_base1_ +
705 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
706 Extension());
707 result.emplace_back(logfile_base1_ +
708 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part1" +
709 Extension());
710 result.emplace_back(logfile_base1_ +
711 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part2" +
712 Extension());
713 result.emplace_back(logfile_base1_ +
714 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part3" +
715 Extension());
716 result.emplace_back(absl::StrCat(
717 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800718 if (shared()) {
719 result.emplace_back(logfile_base1_ +
720 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700721 "aos.message_bridge.RemoteMessage.part0" +
722 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800723 result.emplace_back(logfile_base1_ +
724 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700725 "aos.message_bridge.RemoteMessage.part1" +
726 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800727 result.emplace_back(logfile_base1_ +
728 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700729 "aos.message_bridge.RemoteMessage.part2" +
730 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700731 result.emplace_back(logfile_base1_ +
732 "_timestamps/pi1/aos/remote_timestamps/pi2/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700733 "aos.message_bridge.RemoteMessage.part3" +
734 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800735 } else {
736 result.emplace_back(logfile_base1_ +
737 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
738 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700739 "aos.message_bridge.RemoteMessage.part0" +
740 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800741 result.emplace_back(logfile_base1_ +
742 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
743 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700744 "aos.message_bridge.RemoteMessage.part1" +
745 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800746 result.emplace_back(logfile_base1_ +
747 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
748 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700749 "aos.message_bridge.RemoteMessage.part2" +
750 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700751 result.emplace_back(logfile_base1_ +
752 "_timestamps/pi1/aos/remote_timestamps/pi2/pi1/aos/"
753 "aos-message_bridge-Timestamp/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700754 "aos.message_bridge.RemoteMessage.part3" +
755 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800756
757 result.emplace_back(logfile_base1_ +
758 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
759 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700760 "aos.message_bridge.RemoteMessage.part0" +
761 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800762 result.emplace_back(logfile_base1_ +
763 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
764 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700765 "aos.message_bridge.RemoteMessage.part1" +
766 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800767 result.emplace_back(logfile_base1_ +
768 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
769 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700770 "aos.message_bridge.RemoteMessage.part2" +
771 Extension());
Austin Schuh58646e22021-08-23 23:51:46 -0700772 result.emplace_back(logfile_base1_ +
773 "_timestamps/pi1/aos/remote_timestamps/pi2/test/"
774 "aos-examples-Ping/"
James Kuszmauldd0a5042021-10-28 23:38:04 -0700775 "aos.message_bridge.RemoteMessage.part3" +
776 Extension());
Austin Schuh61e973f2021-02-21 21:43:56 -0800777 }
778 return result;
779 }
780
781 std::vector<std::string> MakePi1SingleDirectionLogfiles() {
782 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700783 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
784 result.emplace_back(logfile_base1_ + "_pi1_data.part1" + Extension());
785 result.emplace_back(logfile_base1_ +
786 "_pi2_data/pi2/aos/aos.message_bridge.Timestamp.part0" +
787 Extension());
788 result.emplace_back(absl::StrCat(
789 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh510dc622021-08-06 18:47:30 -0700790 return result;
791 }
Austin Schuh61e973f2021-02-21 21:43:56 -0800792
Austin Schuh510dc622021-08-06 18:47:30 -0700793 std::vector<std::string> MakePi1DeadNodeLogfiles() {
794 std::vector<std::string> result;
James Kuszmauldd0a5042021-10-28 23:38:04 -0700795 result.emplace_back(logfile_base1_ + "_pi1_data.part0" + Extension());
796 result.emplace_back(absl::StrCat(
797 logfile_base1_, "_", std::get<0>(GetParam()).sha256, Extension()));
Austin Schuh61e973f2021-02-21 21:43:56 -0800798 return result;
799 }
800
801 std::vector<std::vector<std::string>> StructureLogFiles() {
802 std::vector<std::vector<std::string>> result{
Austin Schuhe46492f2021-07-31 19:49:41 -0700803 std::vector<std::string>{logfiles_[2], logfiles_[3]},
804 std::vector<std::string>{logfiles_[4], logfiles_[5]},
Austin Schuh61e973f2021-02-21 21:43:56 -0800805 std::vector<std::string>{logfiles_[6], logfiles_[7]},
806 std::vector<std::string>{logfiles_[8], logfiles_[9]},
807 std::vector<std::string>{logfiles_[10], logfiles_[11]},
Austin Schuhe46492f2021-07-31 19:49:41 -0700808 std::vector<std::string>{logfiles_[12], logfiles_[13]},
809 std::vector<std::string>{logfiles_[14], logfiles_[15]}};
Austin Schuh61e973f2021-02-21 21:43:56 -0800810
811 if (!shared()) {
812 result.emplace_back(
Austin Schuhe46492f2021-07-31 19:49:41 -0700813 std::vector<std::string>{logfiles_[16], logfiles_[17]});
Austin Schuh61e973f2021-02-21 21:43:56 -0800814 }
815
816 return result;
817 }
818
James Kuszmauldd0a5042021-10-28 23:38:04 -0700819 std::string Extension() {
820 return absl::StrCat(".bfbs", std::get<1>(GetParam()).extension);
821 }
822
Austin Schuh58646e22021-08-23 23:51:46 -0700823 LoggerState MakeLogger(NodeEventLoopFactory *node,
Austin Schuh5b728b72021-06-16 14:57:15 -0700824 SimulatedEventLoopFactory *factory = nullptr,
825 const Configuration *configuration = nullptr) {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700826 if (factory == nullptr) {
827 factory = &event_loop_factory_;
828 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800829 return LoggerState::MakeLogger(node, factory, std::get<1>(GetParam()),
830 configuration);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700831 }
832
James Kuszmauldd0a5042021-10-28 23:38:04 -0700833 void StartLogger(LoggerState *logger, std::string logfile_base = "") {
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700834 if (logfile_base.empty()) {
Austin Schuh8c399962020-12-25 21:51:45 -0800835 if (logger->event_loop->node()->name()->string_view() == "pi1") {
836 logfile_base = logfile_base1_;
837 } else {
838 logfile_base = logfile_base2_;
839 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -0700840 }
Austin Schuh3e20c692021-11-16 20:43:16 -0800841 logger->StartLogger(logfile_base);
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700842 }
Austin Schuh15649d62019-12-28 16:36:38 -0800843
Austin Schuh3bd4c402020-11-06 18:19:06 -0800844 void VerifyParts(const std::vector<LogFile> &sorted_parts,
845 const std::vector<std::string> &corrupted_parts = {}) {
846 EXPECT_EQ(sorted_parts.size(), 2u);
847
848 // Count up the number of UUIDs and make sure they are what we expect as a
849 // sanity check.
850 std::set<std::string> log_event_uuids;
851 std::set<std::string> parts_uuids;
852 std::set<std::string> both_uuids;
853
854 size_t missing_rt_count = 0;
855
856 std::vector<std::string> logger_nodes;
857 for (const LogFile &log_file : sorted_parts) {
858 EXPECT_FALSE(log_file.log_event_uuid.empty());
859 log_event_uuids.insert(log_file.log_event_uuid);
860 logger_nodes.emplace_back(log_file.logger_node);
861 both_uuids.insert(log_file.log_event_uuid);
Austin Schuh0ca51f32020-12-25 21:51:45 -0800862 EXPECT_TRUE(log_file.config);
863 EXPECT_EQ(log_file.name,
864 absl::StrCat("name_prefix_", log_file.logger_node));
Austin Schuh3bd4c402020-11-06 18:19:06 -0800865
866 for (const LogParts &part : log_file.parts) {
867 EXPECT_NE(part.monotonic_start_time, aos::monotonic_clock::min_time)
868 << ": " << part;
869 missing_rt_count +=
870 part.realtime_start_time == aos::realtime_clock::min_time;
871
872 EXPECT_TRUE(log_event_uuids.find(part.log_event_uuid) !=
873 log_event_uuids.end());
874 EXPECT_NE(part.node, "");
Austin Schuh0ca51f32020-12-25 21:51:45 -0800875 EXPECT_TRUE(log_file.config);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800876 parts_uuids.insert(part.parts_uuid);
877 both_uuids.insert(part.parts_uuid);
878 }
879 }
880
Austin Schuh61e973f2021-02-21 21:43:56 -0800881 // We won't have RT timestamps for 5 or 6 log files. We don't log the RT
882 // start time on remote nodes because we don't know it and would be
883 // guessing. And the log reader can actually do a better job. The number
884 // depends on if we have the remote timestamps split across 2 files, or just
885 // across 1, depending on if we are using a split or combined timestamp
886 // channel config.
887 EXPECT_EQ(missing_rt_count, shared() ? 5u : 6u);
Austin Schuh3bd4c402020-11-06 18:19:06 -0800888
889 EXPECT_EQ(log_event_uuids.size(), 2u);
890 EXPECT_EQ(parts_uuids.size(), ToLogReaderVector(sorted_parts).size());
891 EXPECT_EQ(log_event_uuids.size() + parts_uuids.size(), both_uuids.size());
892
893 // Test that each list of parts is in order. Don't worry about the ordering
894 // between part file lists though.
895 // (inner vectors all need to be in order, but outer one doesn't matter).
896 EXPECT_THAT(ToLogReaderVector(sorted_parts),
897 ::testing::UnorderedElementsAreArray(structured_logfiles_));
898
899 EXPECT_THAT(logger_nodes, ::testing::UnorderedElementsAre("pi1", "pi2"));
900
901 EXPECT_NE(sorted_parts[0].realtime_start_time,
902 aos::realtime_clock::min_time);
903 EXPECT_NE(sorted_parts[1].realtime_start_time,
904 aos::realtime_clock::min_time);
905
906 EXPECT_NE(sorted_parts[0].monotonic_start_time,
907 aos::monotonic_clock::min_time);
908 EXPECT_NE(sorted_parts[1].monotonic_start_time,
909 aos::monotonic_clock::min_time);
910
911 EXPECT_THAT(sorted_parts[0].corrupted, ::testing::Eq(corrupted_parts));
912 EXPECT_THAT(sorted_parts[1].corrupted, ::testing::Eq(corrupted_parts));
913 }
914
915 void AddExtension(std::string_view extension) {
916 std::transform(logfiles_.begin(), logfiles_.end(), logfiles_.begin(),
917 [extension](const std::string &in) {
918 return absl::StrCat(in, extension);
919 });
920
921 std::transform(structured_logfiles_.begin(), structured_logfiles_.end(),
922 structured_logfiles_.begin(),
923 [extension](std::vector<std::string> in) {
924 std::transform(in.begin(), in.end(), in.begin(),
925 [extension](const std::string &in_str) {
926 return absl::StrCat(in_str, extension);
927 });
928 return in;
929 });
930 }
931
Austin Schuh15649d62019-12-28 16:36:38 -0800932 // Config and factory.
933 aos::FlatbufferDetachedBuffer<aos::Configuration> config_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800934 message_bridge::TestingTimeConverter time_converter_;
Austin Schuh15649d62019-12-28 16:36:38 -0800935 SimulatedEventLoopFactory event_loop_factory_;
936
Austin Schuh58646e22021-08-23 23:51:46 -0700937 NodeEventLoopFactory *const pi1_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800938 const size_t pi1_index_;
Austin Schuh58646e22021-08-23 23:51:46 -0700939 NodeEventLoopFactory *const pi2_;
Austin Schuh87dd3832021-01-01 23:07:31 -0800940 const size_t pi2_index_;
James Kuszmaulbb28ef22020-05-09 22:30:38 -0700941
942 std::string tmp_dir_;
Austin Schuh8c399962020-12-25 21:51:45 -0800943 std::string logfile_base1_;
944 std::string logfile_base2_;
Austin Schuh315b96b2020-12-11 21:21:12 -0800945 std::vector<std::string> pi1_reboot_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700946 std::vector<std::string> logfiles_;
Austin Schuhc9049732020-12-21 22:27:15 -0800947 std::vector<std::string> pi1_single_direction_logfiles_;
Austin Schuh2f8fd752020-09-01 22:38:28 -0700948
949 std::vector<std::vector<std::string>> structured_logfiles_;
Austin Schuh15649d62019-12-28 16:36:38 -0800950};
951
Austin Schuh391e3172020-09-01 22:48:18 -0700952// Counts the number of messages on a channel. Returns (channel name, channel
953// type, count) for every message matching matcher()
954std::vector<std::tuple<std::string, std::string, int>> CountChannelsMatching(
Austin Schuh25b46712021-01-03 00:04:38 -0800955 std::shared_ptr<const aos::Configuration> config, std::string_view filename,
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700956 std::function<bool(const UnpackedMessageHeader *)> matcher) {
Austin Schuh6f3babe2020-01-26 20:34:50 -0800957 MessageReader message_reader(filename);
Austin Schuh8c399962020-12-25 21:51:45 -0800958 std::vector<int> counts(config->channels()->size(), 0);
Austin Schuh15649d62019-12-28 16:36:38 -0800959
Austin Schuh6f3babe2020-01-26 20:34:50 -0800960 while (true) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700961 std::shared_ptr<UnpackedMessageHeader> msg = message_reader.ReadMessage();
Austin Schuh6f3babe2020-01-26 20:34:50 -0800962 if (!msg) {
963 break;
964 }
965
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700966 if (matcher(msg.get())) {
967 counts[msg->channel_index]++;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800968 }
969 }
970
Austin Schuh391e3172020-09-01 22:48:18 -0700971 std::vector<std::tuple<std::string, std::string, int>> result;
Austin Schuh6f3babe2020-01-26 20:34:50 -0800972 int channel = 0;
973 for (size_t i = 0; i < counts.size(); ++i) {
974 if (counts[i] != 0) {
Austin Schuh8c399962020-12-25 21:51:45 -0800975 const Channel *channel = config->channels()->Get(i);
Austin Schuh391e3172020-09-01 22:48:18 -0700976 result.push_back(std::make_tuple(channel->name()->str(),
977 channel->type()->str(), counts[i]));
Austin Schuh6f3babe2020-01-26 20:34:50 -0800978 }
979 ++channel;
980 }
981
982 return result;
983}
984
985// Counts the number of messages (channel, count) for all data messages.
Austin Schuh391e3172020-09-01 22:48:18 -0700986std::vector<std::tuple<std::string, std::string, int>> CountChannelsData(
Austin Schuh8c399962020-12-25 21:51:45 -0800987 std::shared_ptr<const aos::Configuration> config,
Austin Schuh391e3172020-09-01 22:48:18 -0700988 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -0700989 return CountChannelsMatching(
990 config, filename, [](const UnpackedMessageHeader *msg) {
991 if (msg->span.data() != nullptr) {
992 CHECK(!msg->monotonic_remote_time.has_value());
993 CHECK(!msg->realtime_remote_time.has_value());
994 CHECK(!msg->remote_queue_index.has_value());
995 return true;
996 }
997 return false;
998 });
Austin Schuh6f3babe2020-01-26 20:34:50 -0800999}
1000
1001// Counts the number of messages (channel, count) for all timestamp messages.
Austin Schuh391e3172020-09-01 22:48:18 -07001002std::vector<std::tuple<std::string, std::string, int>> CountChannelsTimestamp(
Austin Schuh8c399962020-12-25 21:51:45 -08001003 std::shared_ptr<const aos::Configuration> config,
Austin Schuh6f3babe2020-01-26 20:34:50 -08001004 std::string_view filename) {
Tyler Chatowb7c6eba2021-07-28 14:43:23 -07001005 return CountChannelsMatching(
1006 config, filename, [](const UnpackedMessageHeader *msg) {
1007 if (msg->span.data() == nullptr) {
1008 CHECK(msg->monotonic_remote_time.has_value());
1009 CHECK(msg->realtime_remote_time.has_value());
1010 CHECK(msg->remote_queue_index.has_value());
1011 return true;
1012 }
1013 return false;
1014 });
Austin Schuh6f3babe2020-01-26 20:34:50 -08001015}
1016
Austin Schuhcde938c2020-02-02 17:30:07 -08001017// Tests that we can write and read simple multi-node log files.
Austin Schuh61e973f2021-02-21 21:43:56 -08001018TEST_P(MultinodeLoggerTest, SimpleMultiNode) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001019 time_converter_.StartEqual();
Austin Schuh15649d62019-12-28 16:36:38 -08001020 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001021 LoggerState pi1_logger = MakeLogger(pi1_);
1022 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh15649d62019-12-28 16:36:38 -08001023
1024 event_loop_factory_.RunFor(chrono::milliseconds(95));
1025
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001026 StartLogger(&pi1_logger);
1027 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001028
Austin Schuh15649d62019-12-28 16:36:38 -08001029 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1030 }
1031
Austin Schuh6f3babe2020-01-26 20:34:50 -08001032 {
Austin Schuh64fab802020-09-09 22:47:47 -07001033 std::set<std::string> logfile_uuids;
1034 std::set<std::string> parts_uuids;
1035 // Confirm that we have the expected number of UUIDs for both the logfile
1036 // UUIDs and parts UUIDs.
Austin Schuhadd6eb32020-11-09 21:24:26 -08001037 std::vector<SizePrefixedFlatbufferVector<LogFileHeader>> log_header;
Austin Schuh64fab802020-09-09 22:47:47 -07001038 for (std::string_view f : logfiles_) {
Austin Schuh3bd4c402020-11-06 18:19:06 -08001039 log_header.emplace_back(ReadHeader(f).value());
Austin Schuh8c399962020-12-25 21:51:45 -08001040 if (!log_header.back().message().has_configuration()) {
1041 logfile_uuids.insert(
1042 log_header.back().message().log_event_uuid()->str());
1043 parts_uuids.insert(log_header.back().message().parts_uuid()->str());
1044 }
Austin Schuh64fab802020-09-09 22:47:47 -07001045 }
Austin Schuh15649d62019-12-28 16:36:38 -08001046
Austin Schuh64fab802020-09-09 22:47:47 -07001047 EXPECT_EQ(logfile_uuids.size(), 2u);
Austin Schuh61e973f2021-02-21 21:43:56 -08001048 if (shared()) {
1049 EXPECT_EQ(parts_uuids.size(), 7u);
1050 } else {
1051 EXPECT_EQ(parts_uuids.size(), 8u);
1052 }
Austin Schuh64fab802020-09-09 22:47:47 -07001053
1054 // And confirm everything is on the correct node.
Austin Schuh61e973f2021-02-21 21:43:56 -08001055 EXPECT_EQ(log_header[2].message().node()->name()->string_view(), "pi1");
Austin Schuhe46492f2021-07-31 19:49:41 -07001056 EXPECT_EQ(log_header[3].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001057 EXPECT_EQ(log_header[4].message().node()->name()->string_view(), "pi2");
1058 EXPECT_EQ(log_header[5].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001059 EXPECT_EQ(log_header[6].message().node()->name()->string_view(), "pi2");
1060 EXPECT_EQ(log_header[7].message().node()->name()->string_view(), "pi2");
1061 EXPECT_EQ(log_header[8].message().node()->name()->string_view(), "pi1");
1062 EXPECT_EQ(log_header[9].message().node()->name()->string_view(), "pi1");
Austin Schuh64fab802020-09-09 22:47:47 -07001063 EXPECT_EQ(log_header[10].message().node()->name()->string_view(), "pi2");
1064 EXPECT_EQ(log_header[11].message().node()->name()->string_view(), "pi2");
Austin Schuhe46492f2021-07-31 19:49:41 -07001065 EXPECT_EQ(log_header[12].message().node()->name()->string_view(), "pi2");
1066 EXPECT_EQ(log_header[13].message().node()->name()->string_view(), "pi2");
1067 EXPECT_EQ(log_header[14].message().node()->name()->string_view(), "pi1");
1068 EXPECT_EQ(log_header[15].message().node()->name()->string_view(), "pi1");
Austin Schuh61e973f2021-02-21 21:43:56 -08001069 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001070 EXPECT_EQ(log_header[16].message().node()->name()->string_view(), "pi2");
1071 EXPECT_EQ(log_header[17].message().node()->name()->string_view(), "pi2");
Austin Schuh61e973f2021-02-21 21:43:56 -08001072 }
Austin Schuh64fab802020-09-09 22:47:47 -07001073
1074 // And the parts index matches.
Austin Schuh61e973f2021-02-21 21:43:56 -08001075 EXPECT_EQ(log_header[2].message().parts_index(), 0);
Austin Schuhe46492f2021-07-31 19:49:41 -07001076 EXPECT_EQ(log_header[3].message().parts_index(), 1);
1077 EXPECT_EQ(log_header[4].message().parts_index(), 0);
1078 EXPECT_EQ(log_header[5].message().parts_index(), 1);
Austin Schuh64fab802020-09-09 22:47:47 -07001079 EXPECT_EQ(log_header[6].message().parts_index(), 0);
1080 EXPECT_EQ(log_header[7].message().parts_index(), 1);
1081 EXPECT_EQ(log_header[8].message().parts_index(), 0);
1082 EXPECT_EQ(log_header[9].message().parts_index(), 1);
1083 EXPECT_EQ(log_header[10].message().parts_index(), 0);
1084 EXPECT_EQ(log_header[11].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001085 EXPECT_EQ(log_header[12].message().parts_index(), 0);
1086 EXPECT_EQ(log_header[13].message().parts_index(), 1);
Austin Schuhe46492f2021-07-31 19:49:41 -07001087 EXPECT_EQ(log_header[14].message().parts_index(), 0);
1088 EXPECT_EQ(log_header[15].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001089 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001090 EXPECT_EQ(log_header[16].message().parts_index(), 0);
1091 EXPECT_EQ(log_header[17].message().parts_index(), 1);
Austin Schuh61e973f2021-02-21 21:43:56 -08001092 }
Austin Schuh64fab802020-09-09 22:47:47 -07001093 }
1094
Austin Schuh8c399962020-12-25 21:51:45 -08001095 const std::vector<LogFile> sorted_log_files = SortParts(logfiles_);
Austin Schuh64fab802020-09-09 22:47:47 -07001096 {
Austin Schuh391e3172020-09-01 22:48:18 -07001097 using ::testing::UnorderedElementsAre;
Austin Schuh8c399962020-12-25 21:51:45 -08001098 std::shared_ptr<const aos::Configuration> config =
1099 sorted_log_files[0].config;
Austin Schuh391e3172020-09-01 22:48:18 -07001100
Austin Schuh6f3babe2020-01-26 20:34:50 -08001101 // Timing reports, pings
Austin Schuh3e20c692021-11-16 20:43:16 -08001102 EXPECT_THAT(CountChannelsData(config, logfiles_[2]),
1103 UnorderedElementsAre(
1104 std::make_tuple("/pi1/aos",
1105 "aos.message_bridge.ServerStatistics", 1),
1106 std::make_tuple("/test", "aos.examples.Ping", 1)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001107 << " : " << logfiles_[2];
1108 EXPECT_THAT(
1109 CountChannelsData(config, logfiles_[3]),
1110 UnorderedElementsAre(
Austin Schuh2f8fd752020-09-01 22:38:28 -07001111 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001112 std::make_tuple("/pi1/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001113 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001114 std::make_tuple("/pi1/aos", "aos.message_bridge.ClientStatistics",
1115 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001116 std::make_tuple("/pi1/aos", "aos.timing.Report", 40),
Austin Schuhe46492f2021-07-31 19:49:41 -07001117 std::make_tuple("/test", "aos.examples.Ping", 2000)))
1118 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001119 // Timestamps for pong
Austin Schuhe46492f2021-07-31 19:49:41 -07001120 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[2]),
1121 UnorderedElementsAre())
1122 << " : " << logfiles_[2];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001123 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001124 CountChannelsTimestamp(config, logfiles_[3]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001125 UnorderedElementsAre(
1126 std::make_tuple("/test", "aos.examples.Pong", 2001),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001127 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001128 << " : " << logfiles_[3];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001129
1130 // Pong data.
Austin Schuh20ac95d2020-12-05 17:24:19 -08001131 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001132 CountChannelsData(config, logfiles_[4]),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001133 UnorderedElementsAre(std::make_tuple("/test", "aos.examples.Pong", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001134 << " : " << logfiles_[4];
1135 EXPECT_THAT(CountChannelsData(config, logfiles_[5]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001136 UnorderedElementsAre(
Austin Schuh20ac95d2020-12-05 17:24:19 -08001137 std::make_tuple("/test", "aos.examples.Pong", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001138 << " : " << logfiles_[5];
Austin Schuh391e3172020-09-01 22:48:18 -07001139
Austin Schuh6f3babe2020-01-26 20:34:50 -08001140 // No timestamps
Austin Schuh61e973f2021-02-21 21:43:56 -08001141 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[4]),
Austin Schuh25b46712021-01-03 00:04:38 -08001142 UnorderedElementsAre())
Austin Schuh61e973f2021-02-21 21:43:56 -08001143 << " : " << logfiles_[4];
Austin Schuhe46492f2021-07-31 19:49:41 -07001144 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[5]),
1145 UnorderedElementsAre())
1146 << " : " << logfiles_[5];
Austin Schuh6f3babe2020-01-26 20:34:50 -08001147
1148 // Timing reports and pongs.
Austin Schuhe46492f2021-07-31 19:49:41 -07001149 EXPECT_THAT(CountChannelsData(config, logfiles_[6]),
1150 UnorderedElementsAre(std::make_tuple(
1151 "/pi2/aos", "aos.message_bridge.ServerStatistics", 1)))
1152 << " : " << logfiles_[6];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001153 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001154 CountChannelsData(config, logfiles_[7]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001155 UnorderedElementsAre(
1156 std::make_tuple("/pi2/aos", "aos.message_bridge.Timestamp", 200),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001157 std::make_tuple("/pi2/aos", "aos.message_bridge.ServerStatistics",
Austin Schuhe46492f2021-07-31 19:49:41 -07001158 20),
James Kuszmaul4f106fb2021-01-05 20:53:02 -08001159 std::make_tuple("/pi2/aos", "aos.message_bridge.ClientStatistics",
1160 200),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001161 std::make_tuple("/pi2/aos", "aos.timing.Report", 40),
Austin Schuh20ac95d2020-12-05 17:24:19 -08001162 std::make_tuple("/test", "aos.examples.Pong", 2001)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001163 << " : " << logfiles_[7];
Austin Schuh61e973f2021-02-21 21:43:56 -08001164 // And ping timestamps.
Austin Schuh61e973f2021-02-21 21:43:56 -08001165 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[6]),
1166 UnorderedElementsAre())
1167 << " : " << logfiles_[6];
Austin Schuhe46492f2021-07-31 19:49:41 -07001168 EXPECT_THAT(
1169 CountChannelsTimestamp(config, logfiles_[7]),
1170 UnorderedElementsAre(
1171 std::make_tuple("/test", "aos.examples.Ping", 2001),
1172 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 200)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001173 << " : " << logfiles_[7];
Austin Schuhe46492f2021-07-31 19:49:41 -07001174
1175 // And then test that the remotely logged timestamp data files only have
1176 // timestamps in them.
Austin Schuh25b46712021-01-03 00:04:38 -08001177 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[8]),
1178 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001179 << " : " << logfiles_[8];
Austin Schuh25b46712021-01-03 00:04:38 -08001180 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[9]),
1181 UnorderedElementsAre())
Austin Schuh20ac95d2020-12-05 17:24:19 -08001182 << " : " << logfiles_[9];
Austin Schuhe46492f2021-07-31 19:49:41 -07001183 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[10]),
1184 UnorderedElementsAre())
1185 << " : " << logfiles_[10];
1186 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[11]),
1187 UnorderedElementsAre())
1188 << " : " << logfiles_[11];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001189
Austin Schuh8c399962020-12-25 21:51:45 -08001190 EXPECT_THAT(CountChannelsData(config, logfiles_[8]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001191 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001192 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001193 << " : " << logfiles_[8];
Austin Schuh8c399962020-12-25 21:51:45 -08001194 EXPECT_THAT(CountChannelsData(config, logfiles_[9]),
Austin Schuh2f8fd752020-09-01 22:38:28 -07001195 UnorderedElementsAre(std::make_tuple(
Austin Schuhe46492f2021-07-31 19:49:41 -07001196 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001197 << " : " << logfiles_[9];
Austin Schuh2f8fd752020-09-01 22:38:28 -07001198
Austin Schuh8c399962020-12-25 21:51:45 -08001199 EXPECT_THAT(CountChannelsData(config, logfiles_[10]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001200 UnorderedElementsAre(std::make_tuple(
1201 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001202 << " : " << logfiles_[10];
Austin Schuh8c399962020-12-25 21:51:45 -08001203 EXPECT_THAT(CountChannelsData(config, logfiles_[11]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001204 UnorderedElementsAre(std::make_tuple(
1205 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
Austin Schuh20ac95d2020-12-05 17:24:19 -08001206 << " : " << logfiles_[11];
Austin Schuhe46492f2021-07-31 19:49:41 -07001207
1208 // Timestamps from pi2 on pi1, and the other way.
Austin Schuh61e973f2021-02-21 21:43:56 -08001209 EXPECT_THAT(CountChannelsData(config, logfiles_[12]),
1210 UnorderedElementsAre())
1211 << " : " << logfiles_[12];
1212 EXPECT_THAT(CountChannelsData(config, logfiles_[13]),
1213 UnorderedElementsAre())
1214 << " : " << logfiles_[13];
Austin Schuhe46492f2021-07-31 19:49:41 -07001215 EXPECT_THAT(CountChannelsData(config, logfiles_[14]),
1216 UnorderedElementsAre())
1217 << " : " << logfiles_[14];
1218 EXPECT_THAT(CountChannelsData(config, logfiles_[15]),
1219 UnorderedElementsAre())
1220 << " : " << logfiles_[15];
Austin Schuh61e973f2021-02-21 21:43:56 -08001221 if (!shared()) {
Austin Schuhe46492f2021-07-31 19:49:41 -07001222 EXPECT_THAT(CountChannelsData(config, logfiles_[16]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001223 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001224 << " : " << logfiles_[16];
1225 EXPECT_THAT(CountChannelsData(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001226 UnorderedElementsAre())
Austin Schuhe46492f2021-07-31 19:49:41 -07001227 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001228 }
1229
1230 if (shared()) {
1231 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001232 CountChannelsTimestamp(config, logfiles_[12]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001233 UnorderedElementsAre(
1234 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 9),
1235 std::make_tuple("/test", "aos.examples.Ping", 91)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001236 << " : " << logfiles_[12];
Austin Schuh61e973f2021-02-21 21:43:56 -08001237 EXPECT_THAT(
Austin Schuhe46492f2021-07-31 19:49:41 -07001238 CountChannelsTimestamp(config, logfiles_[13]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001239 UnorderedElementsAre(
1240 std::make_tuple("/pi1/aos", "aos.message_bridge.Timestamp", 191),
1241 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001242 << " : " << logfiles_[13];
1243 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001244 UnorderedElementsAre(std::make_tuple(
1245 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
Austin Schuh61e973f2021-02-21 21:43:56 -08001246 << " : " << logfiles_[14];
1247 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
Austin Schuhe46492f2021-07-31 19:49:41 -07001248 UnorderedElementsAre(std::make_tuple(
1249 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1250 << " : " << logfiles_[15];
1251 } else {
1252 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[12]),
1253 UnorderedElementsAre(std::make_tuple(
1254 "/pi1/aos", "aos.message_bridge.Timestamp", 9)))
1255 << " : " << logfiles_[12];
1256 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[13]),
1257 UnorderedElementsAre(std::make_tuple(
1258 "/pi1/aos", "aos.message_bridge.Timestamp", 191)))
1259 << " : " << logfiles_[13];
1260 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[14]),
1261 UnorderedElementsAre(std::make_tuple(
1262 "/pi2/aos", "aos.message_bridge.Timestamp", 9)))
1263 << " : " << logfiles_[14];
1264 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[15]),
1265 UnorderedElementsAre(std::make_tuple(
1266 "/pi2/aos", "aos.message_bridge.Timestamp", 191)))
1267 << " : " << logfiles_[15];
1268 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[16]),
1269 UnorderedElementsAre(
1270 std::make_tuple("/test", "aos.examples.Ping", 91)))
1271 << " : " << logfiles_[16];
1272 EXPECT_THAT(CountChannelsTimestamp(config, logfiles_[17]),
Austin Schuh61e973f2021-02-21 21:43:56 -08001273 UnorderedElementsAre(
1274 std::make_tuple("/test", "aos.examples.Ping", 1910)))
Austin Schuhe46492f2021-07-31 19:49:41 -07001275 << " : " << logfiles_[17];
Austin Schuh61e973f2021-02-21 21:43:56 -08001276 }
Austin Schuh6f3babe2020-01-26 20:34:50 -08001277 }
1278
Austin Schuh8c399962020-12-25 21:51:45 -08001279 LogReader reader(sorted_log_files);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001280
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001281 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuh6331ef92020-01-07 18:28:09 -08001282 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001283
1284 // This sends out the fetched messages and advances time to the start of the
1285 // log file.
Austin Schuh6331ef92020-01-07 18:28:09 -08001286 reader.Register(&log_reader_factory);
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001287
Austin Schuhac0771c2020-01-07 18:36:30 -08001288 const Node *pi1 =
1289 configuration::GetNode(log_reader_factory.configuration(), "pi1");
Austin Schuh6f3babe2020-01-26 20:34:50 -08001290 const Node *pi2 =
1291 configuration::GetNode(log_reader_factory.configuration(), "pi2");
Austin Schuhac0771c2020-01-07 18:36:30 -08001292
Austin Schuh2f8fd752020-09-01 22:38:28 -07001293 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1294 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1295 LOG(INFO) << "now pi1 "
1296 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1297 LOG(INFO) << "now pi2 "
1298 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1299
Austin Schuh07676622021-01-21 18:59:17 -08001300 EXPECT_THAT(reader.LoggedNodes(),
1301 ::testing::ElementsAre(
1302 configuration::GetNode(reader.logged_configuration(), pi1),
1303 configuration::GetNode(reader.logged_configuration(), pi2)));
James Kuszmaul84ff3e52020-01-03 19:48:53 -08001304
1305 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
Austin Schuh15649d62019-12-28 16:36:38 -08001306
Austin Schuh6f3babe2020-01-26 20:34:50 -08001307 std::unique_ptr<EventLoop> pi1_event_loop =
Austin Schuhac0771c2020-01-07 18:36:30 -08001308 log_reader_factory.MakeEventLoop("test", pi1);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001309 std::unique_ptr<EventLoop> pi2_event_loop =
1310 log_reader_factory.MakeEventLoop("test", pi2);
Austin Schuh15649d62019-12-28 16:36:38 -08001311
Austin Schuh6f3babe2020-01-26 20:34:50 -08001312 int pi1_ping_count = 10;
1313 int pi2_ping_count = 10;
1314 int pi1_pong_count = 10;
1315 int pi2_pong_count = 10;
Austin Schuh15649d62019-12-28 16:36:38 -08001316
1317 // Confirm that the ping value matches.
Austin Schuh6f3babe2020-01-26 20:34:50 -08001318 pi1_event_loop->MakeWatcher(
1319 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001320 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001321 << pi1_event_loop->context().monotonic_remote_time << " -> "
1322 << pi1_event_loop->context().monotonic_event_time;
1323 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1324 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1325 pi1_ping_count * chrono::milliseconds(10) +
1326 monotonic_clock::epoch());
1327 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1328 pi1_ping_count * chrono::milliseconds(10) +
1329 realtime_clock::epoch());
1330 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1331 pi1_event_loop->context().monotonic_event_time);
1332 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1333 pi1_event_loop->context().realtime_event_time);
Austin Schuh15649d62019-12-28 16:36:38 -08001334
Austin Schuh6f3babe2020-01-26 20:34:50 -08001335 ++pi1_ping_count;
1336 });
1337 pi2_event_loop->MakeWatcher(
1338 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
Austin Schuh2f8fd752020-09-01 22:38:28 -07001339 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping) << " at "
Austin Schuh6f3babe2020-01-26 20:34:50 -08001340 << pi2_event_loop->context().monotonic_remote_time << " -> "
1341 << pi2_event_loop->context().monotonic_event_time;
1342 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1343
1344 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1345 pi2_ping_count * chrono::milliseconds(10) +
1346 monotonic_clock::epoch());
1347 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1348 pi2_ping_count * chrono::milliseconds(10) +
1349 realtime_clock::epoch());
1350 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time +
1351 chrono::microseconds(150),
1352 pi2_event_loop->context().monotonic_event_time);
1353 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time +
1354 chrono::microseconds(150),
1355 pi2_event_loop->context().realtime_event_time);
1356 ++pi2_ping_count;
Austin Schuh15649d62019-12-28 16:36:38 -08001357 });
1358
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001359 constexpr ssize_t kQueueIndexOffset = -9;
Austin Schuh6f3babe2020-01-26 20:34:50 -08001360 // Confirm that the ping and pong counts both match, and the value also
1361 // matches.
1362 pi1_event_loop->MakeWatcher(
1363 "/test", [&pi1_event_loop, &pi1_ping_count,
1364 &pi1_pong_count](const examples::Pong &pong) {
1365 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1366 << pi1_event_loop->context().monotonic_remote_time << " -> "
1367 << pi1_event_loop->context().monotonic_event_time;
1368
1369 EXPECT_EQ(pi1_event_loop->context().remote_queue_index,
1370 pi1_pong_count + kQueueIndexOffset);
1371 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time,
1372 chrono::microseconds(200) +
1373 pi1_pong_count * chrono::milliseconds(10) +
1374 monotonic_clock::epoch());
1375 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time,
1376 chrono::microseconds(200) +
1377 pi1_pong_count * chrono::milliseconds(10) +
1378 realtime_clock::epoch());
1379
1380 EXPECT_EQ(pi1_event_loop->context().monotonic_remote_time +
1381 chrono::microseconds(150),
1382 pi1_event_loop->context().monotonic_event_time);
1383 EXPECT_EQ(pi1_event_loop->context().realtime_remote_time +
1384 chrono::microseconds(150),
1385 pi1_event_loop->context().realtime_event_time);
1386
1387 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1388 ++pi1_pong_count;
1389 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1390 });
1391 pi2_event_loop->MakeWatcher(
1392 "/test", [&pi2_event_loop, &pi2_ping_count,
1393 &pi2_pong_count](const examples::Pong &pong) {
1394 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1395 << pi2_event_loop->context().monotonic_remote_time << " -> "
1396 << pi2_event_loop->context().monotonic_event_time;
1397
1398 EXPECT_EQ(pi2_event_loop->context().remote_queue_index,
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001399 pi2_pong_count + kQueueIndexOffset);
Austin Schuh6f3babe2020-01-26 20:34:50 -08001400
1401 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1402 chrono::microseconds(200) +
1403 pi2_pong_count * chrono::milliseconds(10) +
1404 monotonic_clock::epoch());
1405 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1406 chrono::microseconds(200) +
1407 pi2_pong_count * chrono::milliseconds(10) +
1408 realtime_clock::epoch());
1409
1410 EXPECT_EQ(pi2_event_loop->context().monotonic_remote_time,
1411 pi2_event_loop->context().monotonic_event_time);
1412 EXPECT_EQ(pi2_event_loop->context().realtime_remote_time,
1413 pi2_event_loop->context().realtime_event_time);
1414
1415 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1416 ++pi2_pong_count;
1417 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1418 });
1419
1420 log_reader_factory.Run();
1421 EXPECT_EQ(pi1_ping_count, 2010);
1422 EXPECT_EQ(pi2_ping_count, 2010);
1423 EXPECT_EQ(pi1_pong_count, 2010);
1424 EXPECT_EQ(pi2_pong_count, 2010);
Austin Schuh6331ef92020-01-07 18:28:09 -08001425
1426 reader.Deregister();
Austin Schuh15649d62019-12-28 16:36:38 -08001427}
1428
James Kuszmaul46d82582020-05-09 19:50:09 -07001429typedef MultinodeLoggerTest MultinodeLoggerDeathTest;
1430
1431// Test that if we feed the replay with a mismatched node list that we die on
1432// the LogReader constructor.
Austin Schuh61e973f2021-02-21 21:43:56 -08001433TEST_P(MultinodeLoggerDeathTest, MultiNodeBadReplayConfig) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001434 time_converter_.StartEqual();
James Kuszmaul46d82582020-05-09 19:50:09 -07001435 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001436 LoggerState pi1_logger = MakeLogger(pi1_);
1437 LoggerState pi2_logger = MakeLogger(pi2_);
James Kuszmaul46d82582020-05-09 19:50:09 -07001438
1439 event_loop_factory_.RunFor(chrono::milliseconds(95));
1440
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001441 StartLogger(&pi1_logger);
1442 StartLogger(&pi2_logger);
James Kuszmaul46d82582020-05-09 19:50:09 -07001443
James Kuszmaul46d82582020-05-09 19:50:09 -07001444 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1445 }
1446
1447 // Test that, if we add an additional node to the replay config that the
1448 // logger complains about the mismatch in number of nodes.
1449 FlatbufferDetachedBuffer<Configuration> extra_nodes_config =
1450 configuration::MergeWithConfig(&config_.message(), R"({
1451 "nodes": [
1452 {
1453 "name": "extra-node"
1454 }
1455 ]
1456 }
1457 )");
1458
Austin Schuh287d43d2020-12-04 20:19:33 -08001459 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1460 EXPECT_DEATH(LogReader(sorted_parts, &extra_nodes_config.message()),
James Kuszmaul46d82582020-05-09 19:50:09 -07001461 "Log file and replay config need to have matching nodes lists.");
James Kuszmaul46d82582020-05-09 19:50:09 -07001462}
1463
Austin Schuhcde938c2020-02-02 17:30:07 -08001464// Tests that we can read log files where they don't start at the same monotonic
1465// time.
Austin Schuh61e973f2021-02-21 21:43:56 -08001466TEST_P(MultinodeLoggerTest, StaggeredStart) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001467 time_converter_.StartEqual();
Austin Schuhcde938c2020-02-02 17:30:07 -08001468 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001469 LoggerState pi1_logger = MakeLogger(pi1_);
1470 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuhcde938c2020-02-02 17:30:07 -08001471
1472 event_loop_factory_.RunFor(chrono::milliseconds(95));
1473
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001474 StartLogger(&pi1_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001475
1476 event_loop_factory_.RunFor(chrono::milliseconds(200));
1477
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001478 StartLogger(&pi2_logger);
1479
Austin Schuhcde938c2020-02-02 17:30:07 -08001480 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1481 }
1482
Austin Schuhe46492f2021-07-31 19:49:41 -07001483 // Since we delay starting pi2, it already knows about all the timestamps so
1484 // we don't end up with extra parts.
1485 LogReader reader(
1486 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 2, 1)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001487
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001488 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001489 log_reader_factory.set_send_delay(chrono::microseconds(0));
1490
1491 // This sends out the fetched messages and advances time to the start of the
1492 // log file.
1493 reader.Register(&log_reader_factory);
1494
1495 const Node *pi1 =
1496 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1497 const Node *pi2 =
1498 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1499
Austin Schuh07676622021-01-21 18:59:17 -08001500 EXPECT_THAT(reader.LoggedNodes(),
1501 ::testing::ElementsAre(
1502 configuration::GetNode(reader.logged_configuration(), pi1),
1503 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001504
1505 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1506
1507 std::unique_ptr<EventLoop> pi1_event_loop =
1508 log_reader_factory.MakeEventLoop("test", pi1);
1509 std::unique_ptr<EventLoop> pi2_event_loop =
1510 log_reader_factory.MakeEventLoop("test", pi2);
1511
1512 int pi1_ping_count = 30;
1513 int pi2_ping_count = 30;
1514 int pi1_pong_count = 30;
1515 int pi2_pong_count = 30;
1516
1517 // Confirm that the ping value matches.
1518 pi1_event_loop->MakeWatcher(
1519 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1520 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1521 << pi1_event_loop->context().monotonic_remote_time << " -> "
1522 << pi1_event_loop->context().monotonic_event_time;
1523 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1524
1525 ++pi1_ping_count;
1526 });
1527 pi2_event_loop->MakeWatcher(
1528 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1529 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1530 << pi2_event_loop->context().monotonic_remote_time << " -> "
1531 << pi2_event_loop->context().monotonic_event_time;
1532 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1533
1534 ++pi2_ping_count;
1535 });
1536
1537 // Confirm that the ping and pong counts both match, and the value also
1538 // matches.
1539 pi1_event_loop->MakeWatcher(
1540 "/test", [&pi1_event_loop, &pi1_ping_count,
1541 &pi1_pong_count](const examples::Pong &pong) {
1542 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1543 << pi1_event_loop->context().monotonic_remote_time << " -> "
1544 << pi1_event_loop->context().monotonic_event_time;
1545
1546 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1547 ++pi1_pong_count;
1548 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1549 });
1550 pi2_event_loop->MakeWatcher(
1551 "/test", [&pi2_event_loop, &pi2_ping_count,
1552 &pi2_pong_count](const examples::Pong &pong) {
1553 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1554 << pi2_event_loop->context().monotonic_remote_time << " -> "
1555 << pi2_event_loop->context().monotonic_event_time;
1556
1557 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1558 ++pi2_pong_count;
1559 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1560 });
1561
1562 log_reader_factory.Run();
1563 EXPECT_EQ(pi1_ping_count, 2030);
1564 EXPECT_EQ(pi2_ping_count, 2030);
1565 EXPECT_EQ(pi1_pong_count, 2030);
1566 EXPECT_EQ(pi2_pong_count, 2030);
1567
1568 reader.Deregister();
1569}
Austin Schuh6f3babe2020-01-26 20:34:50 -08001570
Austin Schuh8bd96322020-02-13 21:18:22 -08001571// Tests that we can read log files where the monotonic clocks drift and don't
1572// match correctly. While we are here, also test that different ending times
1573// also is readable.
Austin Schuh61e973f2021-02-21 21:43:56 -08001574TEST_P(MultinodeLoggerTest, MismatchedClocks) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001575 // TODO(austin): Negate...
1576 const chrono::nanoseconds initial_pi2_offset = chrono::seconds(1000);
1577
Austin Schuh66168842021-08-17 19:42:21 -07001578 time_converter_.AddMonotonic(
1579 {BootTimestamp::epoch(), BootTimestamp::epoch() + initial_pi2_offset});
Austin Schuh87dd3832021-01-01 23:07:31 -08001580 // Wait for 95 ms, (~0.1 seconds - 1/2 of the ping/pong period), and set the
1581 // skew to be 200 uS/s
1582 const chrono::nanoseconds startup_sleep1 = time_converter_.AddMonotonic(
1583 {chrono::milliseconds(95),
1584 chrono::milliseconds(95) - chrono::nanoseconds(200) * 95});
1585 // Run another 200 ms to have one logger start first.
1586 const chrono::nanoseconds startup_sleep2 = time_converter_.AddMonotonic(
1587 {chrono::milliseconds(200), chrono::milliseconds(200)});
1588 // Slew one way then the other at the same 200 uS/S slew rate. Make sure we
1589 // go far enough to cause problems if this isn't accounted for.
1590 const chrono::nanoseconds logger_run1 = time_converter_.AddMonotonic(
1591 {chrono::milliseconds(20000),
1592 chrono::milliseconds(20000) - chrono::nanoseconds(200) * 20000});
1593 const chrono::nanoseconds logger_run2 = time_converter_.AddMonotonic(
1594 {chrono::milliseconds(40000),
1595 chrono::milliseconds(40000) + chrono::nanoseconds(200) * 40000});
1596 const chrono::nanoseconds logger_run3 = time_converter_.AddMonotonic(
1597 {chrono::milliseconds(400), chrono::milliseconds(400)});
1598
Austin Schuhcde938c2020-02-02 17:30:07 -08001599 {
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001600 LoggerState pi2_logger = MakeLogger(pi2_);
1601
Austin Schuh58646e22021-08-23 23:51:46 -07001602 LOG(INFO) << "pi2 times: " << pi2_->monotonic_now() << " "
1603 << pi2_->realtime_now() << " distributed "
1604 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001605
Austin Schuh58646e22021-08-23 23:51:46 -07001606 LOG(INFO) << "pi2_ times: " << pi2_->monotonic_now() << " "
1607 << pi2_->realtime_now() << " distributed "
1608 << pi2_->ToDistributedClock(pi2_->monotonic_now());
Austin Schuhcde938c2020-02-02 17:30:07 -08001609
Austin Schuh87dd3832021-01-01 23:07:31 -08001610 event_loop_factory_.RunFor(startup_sleep1);
Austin Schuhcde938c2020-02-02 17:30:07 -08001611
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001612 StartLogger(&pi2_logger);
Austin Schuhcde938c2020-02-02 17:30:07 -08001613
Austin Schuh87dd3832021-01-01 23:07:31 -08001614 event_loop_factory_.RunFor(startup_sleep2);
Austin Schuhcde938c2020-02-02 17:30:07 -08001615
Austin Schuh8bd96322020-02-13 21:18:22 -08001616 {
1617 // Run pi1's logger for only part of the time.
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001618 LoggerState pi1_logger = MakeLogger(pi1_);
Austin Schuh8bd96322020-02-13 21:18:22 -08001619
James Kuszmaulbb28ef22020-05-09 22:30:38 -07001620 StartLogger(&pi1_logger);
Austin Schuh87dd3832021-01-01 23:07:31 -08001621 event_loop_factory_.RunFor(logger_run1);
Austin Schuh8bd96322020-02-13 21:18:22 -08001622
Austin Schuh87dd3832021-01-01 23:07:31 -08001623 // Make sure we slewed time far enough so that the difference is greater
1624 // than the network delay. This confirms that if we sort incorrectly, it
1625 // would show in the results.
1626 EXPECT_LT(
Austin Schuh58646e22021-08-23 23:51:46 -07001627 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001628 -event_loop_factory_.send_delay() -
1629 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001630
Austin Schuh87dd3832021-01-01 23:07:31 -08001631 event_loop_factory_.RunFor(logger_run2);
Austin Schuh8bd96322020-02-13 21:18:22 -08001632
Austin Schuh87dd3832021-01-01 23:07:31 -08001633 // And now check that we went far enough the other way to make sure we
1634 // cover both problems.
1635 EXPECT_GT(
Austin Schuh58646e22021-08-23 23:51:46 -07001636 (pi2_->monotonic_now() - pi1_->monotonic_now()) - initial_pi2_offset,
Austin Schuh87dd3832021-01-01 23:07:31 -08001637 event_loop_factory_.send_delay() +
1638 event_loop_factory_.network_delay());
Austin Schuh8bd96322020-02-13 21:18:22 -08001639 }
1640
1641 // And log a bit more on pi2.
Austin Schuh87dd3832021-01-01 23:07:31 -08001642 event_loop_factory_.RunFor(logger_run3);
Austin Schuhcde938c2020-02-02 17:30:07 -08001643 }
1644
Austin Schuh72211ae2021-08-05 14:02:30 -07001645 LogReader reader(
1646 SortParts(MakeLogFiles(logfile_base1_, logfile_base2_, 3, 2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001647
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001648 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
Austin Schuhcde938c2020-02-02 17:30:07 -08001649 log_reader_factory.set_send_delay(chrono::microseconds(0));
1650
Austin Schuhcde938c2020-02-02 17:30:07 -08001651 const Node *pi1 =
1652 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1653 const Node *pi2 =
1654 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1655
Austin Schuh2f8fd752020-09-01 22:38:28 -07001656 // This sends out the fetched messages and advances time to the start of the
1657 // log file.
1658 reader.Register(&log_reader_factory);
1659
1660 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
1661 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
1662 LOG(INFO) << "now pi1 "
1663 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
1664 LOG(INFO) << "now pi2 "
1665 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
1666
Austin Schuhcde938c2020-02-02 17:30:07 -08001667 LOG(INFO) << "Done registering (pi1) "
Austin Schuh391e3172020-09-01 22:48:18 -07001668 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now()
1669 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001670 << log_reader_factory.GetNodeEventLoopFactory(pi1)->realtime_now();
1671 LOG(INFO) << "Done registering (pi2) "
Austin Schuh391e3172020-09-01 22:48:18 -07001672 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now()
1673 << " "
Austin Schuhcde938c2020-02-02 17:30:07 -08001674 << log_reader_factory.GetNodeEventLoopFactory(pi2)->realtime_now();
1675
Austin Schuh07676622021-01-21 18:59:17 -08001676 EXPECT_THAT(reader.LoggedNodes(),
1677 ::testing::ElementsAre(
1678 configuration::GetNode(reader.logged_configuration(), pi1),
1679 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuhcde938c2020-02-02 17:30:07 -08001680
1681 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
1682
1683 std::unique_ptr<EventLoop> pi1_event_loop =
1684 log_reader_factory.MakeEventLoop("test", pi1);
1685 std::unique_ptr<EventLoop> pi2_event_loop =
1686 log_reader_factory.MakeEventLoop("test", pi2);
1687
1688 int pi1_ping_count = 30;
1689 int pi2_ping_count = 30;
1690 int pi1_pong_count = 30;
1691 int pi2_pong_count = 30;
1692
1693 // Confirm that the ping value matches.
1694 pi1_event_loop->MakeWatcher(
1695 "/test", [&pi1_ping_count, &pi1_event_loop](const examples::Ping &ping) {
1696 VLOG(1) << "Pi1 ping " << FlatbufferToJson(&ping)
1697 << pi1_event_loop->context().monotonic_remote_time << " -> "
1698 << pi1_event_loop->context().monotonic_event_time;
1699 EXPECT_EQ(ping.value(), pi1_ping_count + 1);
1700
1701 ++pi1_ping_count;
1702 });
1703 pi2_event_loop->MakeWatcher(
1704 "/test", [&pi2_ping_count, &pi2_event_loop](const examples::Ping &ping) {
1705 VLOG(1) << "Pi2 ping " << FlatbufferToJson(&ping)
1706 << pi2_event_loop->context().monotonic_remote_time << " -> "
1707 << pi2_event_loop->context().monotonic_event_time;
1708 EXPECT_EQ(ping.value(), pi2_ping_count + 1);
1709
1710 ++pi2_ping_count;
1711 });
1712
1713 // Confirm that the ping and pong counts both match, and the value also
1714 // matches.
1715 pi1_event_loop->MakeWatcher(
1716 "/test", [&pi1_event_loop, &pi1_ping_count,
1717 &pi1_pong_count](const examples::Pong &pong) {
1718 VLOG(1) << "Pi1 pong " << FlatbufferToJson(&pong) << " at "
1719 << pi1_event_loop->context().monotonic_remote_time << " -> "
1720 << pi1_event_loop->context().monotonic_event_time;
1721
1722 EXPECT_EQ(pong.value(), pi1_pong_count + 1);
1723 ++pi1_pong_count;
1724 EXPECT_EQ(pi1_ping_count, pi1_pong_count);
1725 });
1726 pi2_event_loop->MakeWatcher(
1727 "/test", [&pi2_event_loop, &pi2_ping_count,
1728 &pi2_pong_count](const examples::Pong &pong) {
1729 VLOG(1) << "Pi2 pong " << FlatbufferToJson(&pong) << " at "
1730 << pi2_event_loop->context().monotonic_remote_time << " -> "
1731 << pi2_event_loop->context().monotonic_event_time;
1732
1733 EXPECT_EQ(pong.value(), pi2_pong_count + 1);
1734 ++pi2_pong_count;
1735 EXPECT_EQ(pi2_ping_count, pi2_pong_count);
1736 });
1737
1738 log_reader_factory.Run();
Austin Schuh8bd96322020-02-13 21:18:22 -08001739 EXPECT_EQ(pi1_ping_count, 6030);
1740 EXPECT_EQ(pi2_ping_count, 6030);
1741 EXPECT_EQ(pi1_pong_count, 6030);
1742 EXPECT_EQ(pi2_pong_count, 6030);
Austin Schuhcde938c2020-02-02 17:30:07 -08001743
1744 reader.Deregister();
1745}
1746
Austin Schuh5212cad2020-09-09 23:12:09 -07001747// Tests that we can sort a bunch of parts into the pre-determined sorted parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08001748TEST_P(MultinodeLoggerTest, SortParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001749 time_converter_.StartEqual();
Austin Schuh5212cad2020-09-09 23:12:09 -07001750 // Make a bunch of parts.
1751 {
1752 LoggerState pi1_logger = MakeLogger(pi1_);
1753 LoggerState pi2_logger = MakeLogger(pi2_);
1754
1755 event_loop_factory_.RunFor(chrono::milliseconds(95));
1756
1757 StartLogger(&pi1_logger);
1758 StartLogger(&pi2_logger);
1759
1760 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1761 }
1762
Austin Schuh11d43732020-09-21 17:28:30 -07001763 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001764 VerifyParts(sorted_parts);
1765}
Austin Schuh11d43732020-09-21 17:28:30 -07001766
Austin Schuh3bd4c402020-11-06 18:19:06 -08001767// Tests that we can sort a bunch of parts with an empty part. We should ignore
1768// it and remove it from the sorted list.
Austin Schuh61e973f2021-02-21 21:43:56 -08001769TEST_P(MultinodeLoggerTest, SortEmptyParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001770 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001771 // Make a bunch of parts.
1772 {
1773 LoggerState pi1_logger = MakeLogger(pi1_);
1774 LoggerState pi2_logger = MakeLogger(pi2_);
Austin Schuh11d43732020-09-21 17:28:30 -07001775
Austin Schuh3bd4c402020-11-06 18:19:06 -08001776 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh11d43732020-09-21 17:28:30 -07001777
Austin Schuh3bd4c402020-11-06 18:19:06 -08001778 StartLogger(&pi1_logger);
1779 StartLogger(&pi2_logger);
Austin Schuh11d43732020-09-21 17:28:30 -07001780
Austin Schuh3bd4c402020-11-06 18:19:06 -08001781 event_loop_factory_.RunFor(chrono::milliseconds(2000));
Austin Schuh11d43732020-09-21 17:28:30 -07001782 }
1783
Austin Schuh3bd4c402020-11-06 18:19:06 -08001784 // TODO(austin): Should we flip out if the file can't open?
James Kuszmauldd0a5042021-10-28 23:38:04 -07001785 const std::string kEmptyFile("foobarinvalidfiledoesnotexist" + Extension());
Austin Schuh11d43732020-09-21 17:28:30 -07001786
Austin Schuh3bd4c402020-11-06 18:19:06 -08001787 aos::util::WriteStringToFileOrDie(kEmptyFile, "");
1788 logfiles_.emplace_back(kEmptyFile);
Austin Schuh5212cad2020-09-09 23:12:09 -07001789
Austin Schuh3bd4c402020-11-06 18:19:06 -08001790 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1791 VerifyParts(sorted_parts, {kEmptyFile});
Austin Schuh5212cad2020-09-09 23:12:09 -07001792}
1793
James Kuszmauldd0a5042021-10-28 23:38:04 -07001794// Tests that we can sort a bunch of parts with the end missing off a
Austin Schuh3bd4c402020-11-06 18:19:06 -08001795// file. We should use the part we can read.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001796TEST_P(MultinodeLoggerTest, SortTruncatedParts) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001797 time_converter_.StartEqual();
Austin Schuh3bd4c402020-11-06 18:19:06 -08001798 // Make a bunch of parts.
1799 {
1800 LoggerState pi1_logger = MakeLogger(pi1_);
1801 LoggerState pi2_logger = MakeLogger(pi2_);
1802
1803 event_loop_factory_.RunFor(chrono::milliseconds(95));
1804
James Kuszmauldd0a5042021-10-28 23:38:04 -07001805 StartLogger(&pi1_logger);
1806 StartLogger(&pi2_logger);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001807
1808 event_loop_factory_.RunFor(chrono::milliseconds(2000));
1809 }
1810
Austin Schuh3bd4c402020-11-06 18:19:06 -08001811 // Strip off the end of one of the files. Pick one with a lot of data.
James Kuszmauldd0a5042021-10-28 23:38:04 -07001812 // For snappy, needs to have enough data to be >1 chunk of compressed data so
1813 // that we don't corrupt the entire log part.
Austin Schuh3bd4c402020-11-06 18:19:06 -08001814 ::std::string compressed_contents =
James Kuszmauldd0a5042021-10-28 23:38:04 -07001815 aos::util::ReadFileToStringOrDie(logfiles_[3]);
Austin Schuh3bd4c402020-11-06 18:19:06 -08001816
1817 aos::util::WriteStringToFileOrDie(
James Kuszmauldd0a5042021-10-28 23:38:04 -07001818 logfiles_[3],
Austin Schuh3bd4c402020-11-06 18:19:06 -08001819 compressed_contents.substr(0, compressed_contents.size() - 100));
1820
1821 const std::vector<LogFile> sorted_parts = SortParts(logfiles_);
1822 VerifyParts(sorted_parts);
1823}
Austin Schuh3bd4c402020-11-06 18:19:06 -08001824
Austin Schuh01b4c352020-09-21 23:09:39 -07001825// Tests that if we remap a remapped channel, it shows up correctly.
Austin Schuh61e973f2021-02-21 21:43:56 -08001826TEST_P(MultinodeLoggerTest, RemapLoggedChannel) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001827 time_converter_.StartEqual();
Austin Schuh01b4c352020-09-21 23:09:39 -07001828 {
1829 LoggerState pi1_logger = MakeLogger(pi1_);
1830 LoggerState pi2_logger = MakeLogger(pi2_);
1831
1832 event_loop_factory_.RunFor(chrono::milliseconds(95));
1833
1834 StartLogger(&pi1_logger);
1835 StartLogger(&pi2_logger);
1836
1837 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1838 }
1839
Austin Schuh287d43d2020-12-04 20:19:33 -08001840 LogReader reader(SortParts(logfiles_));
Austin Schuh01b4c352020-09-21 23:09:39 -07001841
1842 // Remap just on pi1.
1843 reader.RemapLoggedChannel<aos::timing::Report>(
1844 "/aos", configuration::GetNode(reader.configuration(), "pi1"));
1845
1846 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1847 log_reader_factory.set_send_delay(chrono::microseconds(0));
1848
Austin Schuh1c227352021-09-17 12:53:54 -07001849 std::vector<const Channel *> remapped_channels = reader.RemappedChannels();
1850 ASSERT_EQ(remapped_channels.size(), 1u);
1851 EXPECT_EQ(remapped_channels[0]->name()->string_view(), "/original/pi1/aos");
1852 EXPECT_EQ(remapped_channels[0]->type()->string_view(), "aos.timing.Report");
1853
Austin Schuh01b4c352020-09-21 23:09:39 -07001854 reader.Register(&log_reader_factory);
1855
1856 const Node *pi1 =
1857 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1858 const Node *pi2 =
1859 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1860
1861 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1862 // else should have moved.
1863 std::unique_ptr<EventLoop> pi1_event_loop =
1864 log_reader_factory.MakeEventLoop("test", pi1);
1865 pi1_event_loop->SkipTimingReport();
1866 std::unique_ptr<EventLoop> full_pi1_event_loop =
1867 log_reader_factory.MakeEventLoop("test", pi1);
1868 full_pi1_event_loop->SkipTimingReport();
1869 std::unique_ptr<EventLoop> pi2_event_loop =
1870 log_reader_factory.MakeEventLoop("test", pi2);
1871 pi2_event_loop->SkipTimingReport();
1872
1873 MessageCounter<aos::timing::Report> pi1_timing_report(pi1_event_loop.get(),
1874 "/aos");
1875 MessageCounter<aos::timing::Report> full_pi1_timing_report(
1876 full_pi1_event_loop.get(), "/pi1/aos");
1877 MessageCounter<aos::timing::Report> pi1_original_timing_report(
1878 pi1_event_loop.get(), "/original/aos");
1879 MessageCounter<aos::timing::Report> full_pi1_original_timing_report(
1880 full_pi1_event_loop.get(), "/original/pi1/aos");
1881 MessageCounter<aos::timing::Report> pi2_timing_report(pi2_event_loop.get(),
1882 "/aos");
1883
1884 log_reader_factory.Run();
1885
1886 EXPECT_EQ(pi1_timing_report.count(), 0u);
1887 EXPECT_EQ(full_pi1_timing_report.count(), 0u);
1888 EXPECT_NE(pi1_original_timing_report.count(), 0u);
1889 EXPECT_NE(full_pi1_original_timing_report.count(), 0u);
1890 EXPECT_NE(pi2_timing_report.count(), 0u);
1891
1892 reader.Deregister();
1893}
1894
Austin Schuh006a9f52021-04-07 16:24:18 -07001895// Tests that we can remap a forwarded channel as well.
1896TEST_P(MultinodeLoggerTest, RemapForwardedLoggedChannel) {
1897 time_converter_.StartEqual();
1898 {
1899 LoggerState pi1_logger = MakeLogger(pi1_);
1900 LoggerState pi2_logger = MakeLogger(pi2_);
1901
1902 event_loop_factory_.RunFor(chrono::milliseconds(95));
1903
1904 StartLogger(&pi1_logger);
1905 StartLogger(&pi2_logger);
1906
1907 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1908 }
1909
1910 LogReader reader(SortParts(logfiles_));
1911
1912 reader.RemapLoggedChannel<examples::Ping>("/test");
1913
1914 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1915 log_reader_factory.set_send_delay(chrono::microseconds(0));
1916
1917 reader.Register(&log_reader_factory);
1918
1919 const Node *pi1 =
1920 configuration::GetNode(log_reader_factory.configuration(), "pi1");
1921 const Node *pi2 =
1922 configuration::GetNode(log_reader_factory.configuration(), "pi2");
1923
1924 // Confirm we can read the data on the remapped channel, just for pi1. Nothing
1925 // else should have moved.
1926 std::unique_ptr<EventLoop> pi1_event_loop =
1927 log_reader_factory.MakeEventLoop("test", pi1);
1928 pi1_event_loop->SkipTimingReport();
1929 std::unique_ptr<EventLoop> full_pi1_event_loop =
1930 log_reader_factory.MakeEventLoop("test", pi1);
1931 full_pi1_event_loop->SkipTimingReport();
1932 std::unique_ptr<EventLoop> pi2_event_loop =
1933 log_reader_factory.MakeEventLoop("test", pi2);
1934 pi2_event_loop->SkipTimingReport();
1935
1936 MessageCounter<examples::Ping> pi1_ping(pi1_event_loop.get(), "/test");
1937 MessageCounter<examples::Ping> pi2_ping(pi2_event_loop.get(), "/test");
1938 MessageCounter<examples::Ping> pi1_original_ping(pi1_event_loop.get(),
1939 "/original/test");
1940 MessageCounter<examples::Ping> pi2_original_ping(pi2_event_loop.get(),
1941 "/original/test");
1942
1943 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1944 pi1_original_ping_timestamp;
1945 std::unique_ptr<MessageCounter<message_bridge::RemoteMessage>>
1946 pi1_ping_timestamp;
1947 if (!shared()) {
1948 pi1_original_ping_timestamp =
1949 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1950 pi1_event_loop.get(),
1951 "/pi1/aos/remote_timestamps/pi2/original/test/aos-examples-Ping");
1952 pi1_ping_timestamp =
1953 std::make_unique<MessageCounter<message_bridge::RemoteMessage>>(
1954 pi1_event_loop.get(),
1955 "/pi1/aos/remote_timestamps/pi2/test/aos-examples-Ping");
1956 }
1957
1958 log_reader_factory.Run();
1959
1960 EXPECT_EQ(pi1_ping.count(), 0u);
1961 EXPECT_EQ(pi2_ping.count(), 0u);
1962 EXPECT_NE(pi1_original_ping.count(), 0u);
1963 EXPECT_NE(pi2_original_ping.count(), 0u);
1964 if (!shared()) {
1965 EXPECT_NE(pi1_original_ping_timestamp->count(), 0u);
1966 EXPECT_EQ(pi1_ping_timestamp->count(), 0u);
1967 }
1968
1969 reader.Deregister();
1970}
1971
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001972// Tests that we properly recreate forwarded timestamps when replaying a log.
1973// This should be enough that we can then re-run the logger and get a valid log
1974// back.
Austin Schuh61e973f2021-02-21 21:43:56 -08001975TEST_P(MultinodeLoggerTest, MessageHeader) {
Austin Schuh87dd3832021-01-01 23:07:31 -08001976 time_converter_.StartEqual();
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001977 {
1978 LoggerState pi1_logger = MakeLogger(pi1_);
1979 LoggerState pi2_logger = MakeLogger(pi2_);
1980
1981 event_loop_factory_.RunFor(chrono::milliseconds(95));
1982
1983 StartLogger(&pi1_logger);
1984 StartLogger(&pi2_logger);
1985
1986 event_loop_factory_.RunFor(chrono::milliseconds(20000));
1987 }
1988
Austin Schuh287d43d2020-12-04 20:19:33 -08001989 LogReader reader(SortParts(logfiles_));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07001990
1991 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
1992 log_reader_factory.set_send_delay(chrono::microseconds(0));
1993
1994 // This sends out the fetched messages and advances time to the start of the
1995 // log file.
1996 reader.Register(&log_reader_factory);
1997
1998 const Node *pi1 =
1999 configuration::GetNode(log_reader_factory.configuration(), "pi1");
2000 const Node *pi2 =
2001 configuration::GetNode(log_reader_factory.configuration(), "pi2");
2002
2003 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
2004 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
2005 LOG(INFO) << "now pi1 "
2006 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
2007 LOG(INFO) << "now pi2 "
2008 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
2009
Austin Schuh07676622021-01-21 18:59:17 -08002010 EXPECT_THAT(reader.LoggedNodes(),
2011 ::testing::ElementsAre(
2012 configuration::GetNode(reader.logged_configuration(), pi1),
2013 configuration::GetNode(reader.logged_configuration(), pi2)));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002014
2015 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
2016
2017 std::unique_ptr<EventLoop> pi1_event_loop =
2018 log_reader_factory.MakeEventLoop("test", pi1);
2019 std::unique_ptr<EventLoop> pi2_event_loop =
2020 log_reader_factory.MakeEventLoop("test", pi2);
2021
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002022 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi1_fetcher =
2023 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2024 aos::Fetcher<message_bridge::Timestamp> pi1_timestamp_on_pi2_fetcher =
2025 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi1/aos");
2026
2027 aos::Fetcher<examples::Ping> ping_on_pi1_fetcher =
2028 pi1_event_loop->MakeFetcher<examples::Ping>("/test");
2029 aos::Fetcher<examples::Ping> ping_on_pi2_fetcher =
2030 pi2_event_loop->MakeFetcher<examples::Ping>("/test");
2031
2032 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi2_fetcher =
2033 pi2_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2034 aos::Fetcher<message_bridge::Timestamp> pi2_timestamp_on_pi1_fetcher =
2035 pi1_event_loop->MakeFetcher<message_bridge::Timestamp>("/pi2/aos");
2036
2037 aos::Fetcher<examples::Pong> pong_on_pi2_fetcher =
2038 pi2_event_loop->MakeFetcher<examples::Pong>("/test");
2039 aos::Fetcher<examples::Pong> pong_on_pi1_fetcher =
2040 pi1_event_loop->MakeFetcher<examples::Pong>("/test");
2041
2042 const size_t pi1_timestamp_channel = configuration::ChannelIndex(
2043 pi1_event_loop->configuration(), pi1_timestamp_on_pi1_fetcher.channel());
2044 const size_t ping_timestamp_channel = configuration::ChannelIndex(
2045 pi2_event_loop->configuration(), ping_on_pi2_fetcher.channel());
2046
2047 const size_t pi2_timestamp_channel = configuration::ChannelIndex(
2048 pi2_event_loop->configuration(), pi2_timestamp_on_pi2_fetcher.channel());
2049 const size_t pong_timestamp_channel = configuration::ChannelIndex(
2050 pi1_event_loop->configuration(), pong_on_pi1_fetcher.channel());
2051
Austin Schuh969cd602021-01-03 00:09:45 -08002052 const chrono::nanoseconds network_delay = event_loop_factory_.network_delay();
Austin Schuh816e5d62021-01-05 23:42:20 -08002053 const chrono::nanoseconds send_delay = event_loop_factory_.send_delay();
Austin Schuh969cd602021-01-03 00:09:45 -08002054
Austin Schuh61e973f2021-02-21 21:43:56 -08002055 for (std::pair<int, std::string> channel :
2056 shared()
2057 ? std::vector<
2058 std::pair<int, std::string>>{{-1,
2059 "/aos/remote_timestamps/pi2"}}
2060 : std::vector<std::pair<int, std::string>>{
2061 {pi1_timestamp_channel,
2062 "/aos/remote_timestamps/pi2/pi1/aos/"
2063 "aos-message_bridge-Timestamp"},
2064 {ping_timestamp_channel,
2065 "/aos/remote_timestamps/pi2/test/aos-examples-Ping"}}) {
2066 pi1_event_loop->MakeWatcher(
2067 channel.second,
2068 [&pi1_event_loop, &pi2_event_loop, pi1_timestamp_channel,
2069 ping_timestamp_channel, &pi1_timestamp_on_pi1_fetcher,
2070 &pi1_timestamp_on_pi2_fetcher, &ping_on_pi1_fetcher,
2071 &ping_on_pi2_fetcher, network_delay, send_delay,
2072 channel_index = channel.first](const RemoteMessage &header) {
2073 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2074 chrono::nanoseconds(header.monotonic_sent_time()));
2075 const aos::realtime_clock::time_point header_realtime_sent_time(
2076 chrono::nanoseconds(header.realtime_sent_time()));
2077 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2078 chrono::nanoseconds(header.monotonic_remote_time()));
2079 const aos::realtime_clock::time_point header_realtime_remote_time(
2080 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002081
Austin Schuh61e973f2021-02-21 21:43:56 -08002082 if (channel_index != -1) {
2083 ASSERT_EQ(channel_index, header.channel_index());
2084 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002085
Austin Schuh61e973f2021-02-21 21:43:56 -08002086 const Context *pi1_context = nullptr;
2087 const Context *pi2_context = nullptr;
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002088
Austin Schuh61e973f2021-02-21 21:43:56 -08002089 if (header.channel_index() == pi1_timestamp_channel) {
2090 ASSERT_TRUE(pi1_timestamp_on_pi1_fetcher.FetchNext());
2091 ASSERT_TRUE(pi1_timestamp_on_pi2_fetcher.FetchNext());
2092 pi1_context = &pi1_timestamp_on_pi1_fetcher.context();
2093 pi2_context = &pi1_timestamp_on_pi2_fetcher.context();
2094 } else if (header.channel_index() == ping_timestamp_channel) {
2095 ASSERT_TRUE(ping_on_pi1_fetcher.FetchNext());
2096 ASSERT_TRUE(ping_on_pi2_fetcher.FetchNext());
2097 pi1_context = &ping_on_pi1_fetcher.context();
2098 pi2_context = &ping_on_pi2_fetcher.context();
2099 } else {
2100 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2101 << configuration::CleanedChannelToString(
2102 pi1_event_loop->configuration()->channels()->Get(
2103 header.channel_index()));
2104 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002105
Austin Schuh61e973f2021-02-21 21:43:56 -08002106 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002107 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2108 pi2_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002109
Austin Schuh61e973f2021-02-21 21:43:56 -08002110 EXPECT_EQ(pi1_context->queue_index, header.remote_queue_index());
2111 EXPECT_EQ(pi2_context->remote_queue_index,
2112 header.remote_queue_index());
2113 EXPECT_EQ(pi2_context->queue_index, header.queue_index());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002114
Austin Schuh61e973f2021-02-21 21:43:56 -08002115 EXPECT_EQ(pi2_context->monotonic_event_time,
2116 header_monotonic_sent_time);
2117 EXPECT_EQ(pi2_context->realtime_event_time,
2118 header_realtime_sent_time);
2119 EXPECT_EQ(pi2_context->realtime_remote_time,
2120 header_realtime_remote_time);
2121 EXPECT_EQ(pi2_context->monotonic_remote_time,
2122 header_monotonic_remote_time);
Austin Schuh969cd602021-01-03 00:09:45 -08002123
Austin Schuh61e973f2021-02-21 21:43:56 -08002124 EXPECT_EQ(pi1_context->realtime_event_time,
2125 header_realtime_remote_time);
2126 EXPECT_EQ(pi1_context->monotonic_event_time,
2127 header_monotonic_remote_time);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002128
Austin Schuh61e973f2021-02-21 21:43:56 -08002129 // Time estimation isn't perfect, but we know the clocks were
2130 // identical when logged, so we know when this should have come back.
2131 // Confirm we got it when we expected.
2132 EXPECT_EQ(pi1_event_loop->context().monotonic_event_time,
2133 pi1_context->monotonic_event_time + 2 * network_delay +
2134 send_delay);
2135 });
2136 }
2137 for (std::pair<int, std::string> channel :
2138 shared()
2139 ? std::vector<
2140 std::pair<int, std::string>>{{-1,
2141 "/aos/remote_timestamps/pi1"}}
2142 : std::vector<std::pair<int, std::string>>{
2143 {pi2_timestamp_channel,
2144 "/aos/remote_timestamps/pi1/pi2/aos/"
2145 "aos-message_bridge-Timestamp"}}) {
2146 pi2_event_loop->MakeWatcher(
2147 channel.second,
2148 [&pi2_event_loop, &pi1_event_loop, pi2_timestamp_channel,
2149 pong_timestamp_channel, &pi2_timestamp_on_pi2_fetcher,
2150 &pi2_timestamp_on_pi1_fetcher, &pong_on_pi2_fetcher,
2151 &pong_on_pi1_fetcher, network_delay, send_delay,
2152 channel_index = channel.first](const RemoteMessage &header) {
2153 const aos::monotonic_clock::time_point header_monotonic_sent_time(
2154 chrono::nanoseconds(header.monotonic_sent_time()));
2155 const aos::realtime_clock::time_point header_realtime_sent_time(
2156 chrono::nanoseconds(header.realtime_sent_time()));
2157 const aos::monotonic_clock::time_point header_monotonic_remote_time(
2158 chrono::nanoseconds(header.monotonic_remote_time()));
2159 const aos::realtime_clock::time_point header_realtime_remote_time(
2160 chrono::nanoseconds(header.realtime_remote_time()));
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002161
Austin Schuh61e973f2021-02-21 21:43:56 -08002162 if (channel_index != -1) {
2163 ASSERT_EQ(channel_index, header.channel_index());
2164 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002165
Austin Schuh61e973f2021-02-21 21:43:56 -08002166 const Context *pi2_context = nullptr;
2167 const Context *pi1_context = nullptr;
Austin Schuh315b96b2020-12-11 21:21:12 -08002168
Austin Schuh61e973f2021-02-21 21:43:56 -08002169 if (header.channel_index() == pi2_timestamp_channel) {
2170 ASSERT_TRUE(pi2_timestamp_on_pi2_fetcher.FetchNext());
2171 ASSERT_TRUE(pi2_timestamp_on_pi1_fetcher.FetchNext());
2172 pi2_context = &pi2_timestamp_on_pi2_fetcher.context();
2173 pi1_context = &pi2_timestamp_on_pi1_fetcher.context();
2174 } else if (header.channel_index() == pong_timestamp_channel) {
2175 ASSERT_TRUE(pong_on_pi2_fetcher.FetchNext());
2176 ASSERT_TRUE(pong_on_pi1_fetcher.FetchNext());
2177 pi2_context = &pong_on_pi2_fetcher.context();
2178 pi1_context = &pong_on_pi1_fetcher.context();
2179 } else {
2180 LOG(FATAL) << "Unknown channel " << FlatbufferToJson(&header) << " "
2181 << configuration::CleanedChannelToString(
2182 pi2_event_loop->configuration()->channels()->Get(
2183 header.channel_index()));
2184 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002185
Austin Schuh61e973f2021-02-21 21:43:56 -08002186 ASSERT_TRUE(header.has_boot_uuid());
Austin Schuhcdd90272021-03-15 12:46:16 -07002187 EXPECT_EQ(UUID::FromVector(header.boot_uuid()),
2188 pi1_event_loop->boot_uuid());
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002189
Austin Schuh61e973f2021-02-21 21:43:56 -08002190 EXPECT_EQ(pi2_context->queue_index, header.remote_queue_index());
2191 EXPECT_EQ(pi1_context->remote_queue_index,
2192 header.remote_queue_index());
2193 EXPECT_EQ(pi1_context->queue_index, header.queue_index());
Austin Schuh969cd602021-01-03 00:09:45 -08002194
Austin Schuh61e973f2021-02-21 21:43:56 -08002195 EXPECT_EQ(pi1_context->monotonic_event_time,
2196 header_monotonic_sent_time);
2197 EXPECT_EQ(pi1_context->realtime_event_time,
2198 header_realtime_sent_time);
2199 EXPECT_EQ(pi1_context->realtime_remote_time,
2200 header_realtime_remote_time);
2201 EXPECT_EQ(pi1_context->monotonic_remote_time,
2202 header_monotonic_remote_time);
2203
2204 EXPECT_EQ(pi2_context->realtime_event_time,
2205 header_realtime_remote_time);
2206 EXPECT_EQ(pi2_context->monotonic_event_time,
2207 header_monotonic_remote_time);
2208
2209 // Time estimation isn't perfect, but we know the clocks were
2210 // identical when logged, so we know when this should have come back.
2211 // Confirm we got it when we expected.
2212 EXPECT_EQ(pi2_event_loop->context().monotonic_event_time,
2213 pi2_context->monotonic_event_time + 2 * network_delay +
2214 send_delay);
2215 });
2216 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002217
2218 // And confirm we can re-create a log again, while checking the contents.
2219 {
2220 LoggerState pi1_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002221 log_reader_factory.GetNodeEventLoopFactory("pi1"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002222 LoggerState pi2_logger = MakeLogger(
Austin Schuh58646e22021-08-23 23:51:46 -07002223 log_reader_factory.GetNodeEventLoopFactory("pi2"), &log_reader_factory);
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002224
Austin Schuh25b46712021-01-03 00:04:38 -08002225 StartLogger(&pi1_logger, tmp_dir_ + "/relogged1");
2226 StartLogger(&pi2_logger, tmp_dir_ + "/relogged2");
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002227
2228 log_reader_factory.Run();
2229 }
2230
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002231 reader.Deregister();
James Kuszmaul4f106fb2021-01-05 20:53:02 -08002232
2233 // And verify that we can run the LogReader over the relogged files without
2234 // hitting any fatal errors.
2235 {
2236 LogReader relogged_reader(SortParts(
2237 MakeLogFiles(tmp_dir_ + "/relogged1", tmp_dir_ + "/relogged2")));
2238 relogged_reader.Register();
2239
2240 relogged_reader.event_loop_factory()->Run();
2241 }
Austin Schuh8d7e0bb2020-10-02 17:57:00 -07002242}
2243
Austin Schuh315b96b2020-12-11 21:21:12 -08002244// Tests that we properly populate and extract the logger_start time by setting
2245// up a clock difference between 2 nodes and looking at the resulting parts.
Austin Schuh61e973f2021-02-21 21:43:56 -08002246TEST_P(MultinodeLoggerTest, LoggerStartTime) {
Austin Schuh87dd3832021-01-01 23:07:31 -08002247 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002248 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh315b96b2020-12-11 21:21:12 -08002249 {
2250 LoggerState pi1_logger = MakeLogger(pi1_);
2251 LoggerState pi2_logger = MakeLogger(pi2_);
2252
Austin Schuh315b96b2020-12-11 21:21:12 -08002253 StartLogger(&pi1_logger);
2254 StartLogger(&pi2_logger);
2255
2256 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2257 }
2258
2259 for (const LogFile &log_file : SortParts(logfiles_)) {
2260 for (const LogParts &log_part : log_file.parts) {
2261 if (log_part.node == log_file.logger_node) {
2262 EXPECT_EQ(log_part.logger_monotonic_start_time,
2263 aos::monotonic_clock::min_time);
2264 EXPECT_EQ(log_part.logger_realtime_start_time,
2265 aos::realtime_clock::min_time);
2266 } else {
2267 const chrono::seconds offset = log_file.logger_node == "pi1"
2268 ? -chrono::seconds(1000)
2269 : chrono::seconds(1000);
2270 EXPECT_EQ(log_part.logger_monotonic_start_time,
2271 log_part.monotonic_start_time + offset);
2272 EXPECT_EQ(log_part.logger_realtime_start_time,
2273 log_file.realtime_start_time +
2274 (log_part.logger_monotonic_start_time -
2275 log_file.monotonic_start_time));
2276 }
2277 }
2278 }
2279}
2280
Austin Schuh6bb8a822021-03-31 23:04:39 -07002281// Test that renaming the base, renames the folder.
Austin Schuh9f2a74b2021-12-08 12:10:50 -08002282TEST_P(MultinodeLoggerTest, LoggerRenameFolder) {
Austin Schuh9733ae52021-07-30 18:25:52 -07002283 util::UnlinkRecursive(tmp_dir_ + "/renamefolder");
2284 util::UnlinkRecursive(tmp_dir_ + "/new-good");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002285 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002286 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh6bb8a822021-03-31 23:04:39 -07002287 logfile_base1_ = tmp_dir_ + "/renamefolder/multi_logfile1";
2288 logfile_base2_ = tmp_dir_ + "/renamefolder/multi_logfile2";
2289 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2290 LoggerState pi1_logger = MakeLogger(pi1_);
2291 LoggerState pi2_logger = MakeLogger(pi2_);
2292
2293 StartLogger(&pi1_logger);
2294 StartLogger(&pi2_logger);
2295
2296 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2297 logfile_base1_ = tmp_dir_ + "/new-good/multi_logfile1";
2298 logfile_base2_ = tmp_dir_ + "/new-good/multi_logfile2";
2299 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2300 ASSERT_TRUE(pi1_logger.logger->RenameLogBase(logfile_base1_));
2301 ASSERT_TRUE(pi2_logger.logger->RenameLogBase(logfile_base2_));
2302 for (auto &file : logfiles_) {
2303 struct stat s;
2304 EXPECT_EQ(0, stat(file.c_str(), &s));
2305 }
2306}
2307
2308// Test that renaming the file base dies.
2309TEST_P(MultinodeLoggerDeathTest, LoggerRenameFile) {
2310 time_converter_.AddMonotonic(
Austin Schuh58646e22021-08-23 23:51:46 -07002311 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh9733ae52021-07-30 18:25:52 -07002312 util::UnlinkRecursive(tmp_dir_ + "/renamefile");
Austin Schuh6bb8a822021-03-31 23:04:39 -07002313 logfile_base1_ = tmp_dir_ + "/renamefile/multi_logfile1";
2314 logfile_base2_ = tmp_dir_ + "/renamefile/multi_logfile2";
2315 logfiles_ = MakeLogFiles(logfile_base1_, logfile_base2_);
2316 LoggerState pi1_logger = MakeLogger(pi1_);
2317 StartLogger(&pi1_logger);
2318 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2319 logfile_base1_ = tmp_dir_ + "/new-renamefile/new_multi_logfile1";
2320 EXPECT_DEATH({ pi1_logger.logger->RenameLogBase(logfile_base1_); },
2321 "Rename of file base from");
2322}
2323
Austin Schuh8bd96322020-02-13 21:18:22 -08002324// TODO(austin): We can write a test which recreates a logfile and confirms that
2325// we get it back. That is the ultimate test.
2326
Austin Schuh315b96b2020-12-11 21:21:12 -08002327// Tests that we properly recreate forwarded timestamps when replaying a log.
2328// This should be enough that we can then re-run the logger and get a valid log
2329// back.
Austin Schuh58646e22021-08-23 23:51:46 -07002330TEST_P(MultinodeLoggerTest, RemoteReboot) {
2331 const UUID pi1_boot0 = UUID::Random();
2332 const UUID pi2_boot0 = UUID::Random();
2333 const UUID pi2_boot1 = UUID::Random();
Austin Schuh315b96b2020-12-11 21:21:12 -08002334 {
Austin Schuh58646e22021-08-23 23:51:46 -07002335 CHECK_EQ(pi1_index_, 0u);
2336 CHECK_EQ(pi2_index_, 1u);
2337
2338 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2339 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2340 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2341
2342 time_converter_.AddNextTimestamp(
2343 distributed_clock::epoch(),
2344 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2345 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2346 time_converter_.AddNextTimestamp(
2347 distributed_clock::epoch() + reboot_time,
2348 {BootTimestamp::epoch() + reboot_time,
2349 BootTimestamp{
2350 .boot = 1,
2351 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2352 }
2353
2354 {
Austin Schuh315b96b2020-12-11 21:21:12 -08002355 LoggerState pi1_logger = MakeLogger(pi1_);
2356
2357 event_loop_factory_.RunFor(chrono::milliseconds(95));
Austin Schuh58646e22021-08-23 23:51:46 -07002358 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2359 pi1_boot0);
2360 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2361 pi2_boot0);
Austin Schuh315b96b2020-12-11 21:21:12 -08002362
2363 StartLogger(&pi1_logger);
2364
2365 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2366
Austin Schuh58646e22021-08-23 23:51:46 -07002367 VLOG(1) << "Reboot now!";
Austin Schuh315b96b2020-12-11 21:21:12 -08002368
2369 event_loop_factory_.RunFor(chrono::milliseconds(20000));
Austin Schuh58646e22021-08-23 23:51:46 -07002370 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2371 pi1_boot0);
2372 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2373 pi2_boot1);
Austin Schuh315b96b2020-12-11 21:21:12 -08002374 }
2375
Austin Schuh72211ae2021-08-05 14:02:30 -07002376 // Confirm that our new oldest timestamps properly update as we reboot and
2377 // rotate.
2378 for (const std::string &file : pi1_reboot_logfiles_) {
2379 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2380 ReadHeader(file);
2381 CHECK(log_header);
2382 if (log_header->message().has_configuration()) {
2383 continue;
2384 }
2385
Austin Schuh58646e22021-08-23 23:51:46 -07002386 const monotonic_clock::time_point monotonic_start_time =
2387 monotonic_clock::time_point(
2388 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2389 const UUID source_node_boot_uuid = UUID::FromString(
2390 log_header->message().source_node_boot_uuid()->string_view());
2391
Austin Schuh72211ae2021-08-05 14:02:30 -07002392 if (log_header->message().node()->name()->string_view() != "pi1") {
Austin Schuh01f3b392022-01-25 20:03:09 -08002393 // The remote message channel should rotate later and have more parts.
2394 // This only is true on the log files with shared remote messages.
2395 //
2396 // TODO(austin): I'm not the most thrilled with this test pattern... It
2397 // feels brittle in a different way.
2398 if (file.find("aos.message_bridge.RemoteMessage") == std::string::npos || !shared()) {
2399 switch (log_header->message().parts_index()) {
2400 case 0:
2401 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2402 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2403 break;
2404 case 1:
2405 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2406 ASSERT_EQ(monotonic_start_time,
2407 monotonic_clock::epoch() + chrono::seconds(1));
2408 break;
2409 case 2:
2410 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2411 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2412 break;
2413 case 3:
2414 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2415 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2416 chrono::nanoseconds(2322999462))
2417 << " on " << file;
2418 break;
2419 default:
2420 FAIL();
2421 break;
2422 }
2423 } else {
2424 switch (log_header->message().parts_index()) {
2425 case 0:
2426 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2427 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2428 break;
2429 case 1:
2430 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2431 ASSERT_EQ(monotonic_start_time,
2432 monotonic_clock::epoch() + chrono::seconds(1));
2433 break;
2434 case 2:
2435 case 3:
2436 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2437 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time) << file;
2438 break;
2439 case 4:
2440 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2441 ASSERT_EQ(monotonic_start_time, monotonic_clock::epoch() +
2442 chrono::nanoseconds(2322999462))
2443 << " on " << file;
2444 break;
2445 default:
2446 FAIL();
2447 break;
2448 }
Austin Schuh58646e22021-08-23 23:51:46 -07002449 }
Austin Schuh72211ae2021-08-05 14:02:30 -07002450 continue;
2451 }
2452 SCOPED_TRACE(file);
2453 SCOPED_TRACE(aos::FlatbufferToJson(
2454 *log_header, {.multi_line = true, .max_vector_size = 100}));
2455 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2456 ASSERT_EQ(
2457 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2458 EXPECT_EQ(
2459 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2460 monotonic_clock::max_time.time_since_epoch().count());
2461 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2462 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2463 2u);
2464 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2465 monotonic_clock::max_time.time_since_epoch().count());
2466 ASSERT_TRUE(log_header->message()
2467 .has_oldest_remote_unreliable_monotonic_timestamps());
2468 ASSERT_EQ(log_header->message()
2469 .oldest_remote_unreliable_monotonic_timestamps()
2470 ->size(),
2471 2u);
2472 EXPECT_EQ(log_header->message()
2473 .oldest_remote_unreliable_monotonic_timestamps()
2474 ->Get(0),
2475 monotonic_clock::max_time.time_since_epoch().count());
2476 ASSERT_TRUE(log_header->message()
2477 .has_oldest_local_unreliable_monotonic_timestamps());
2478 ASSERT_EQ(log_header->message()
2479 .oldest_local_unreliable_monotonic_timestamps()
2480 ->size(),
2481 2u);
2482 EXPECT_EQ(log_header->message()
2483 .oldest_local_unreliable_monotonic_timestamps()
2484 ->Get(0),
2485 monotonic_clock::max_time.time_since_epoch().count());
2486
2487 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2488 monotonic_clock::time_point(chrono::nanoseconds(
2489 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2490 1)));
2491 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2492 monotonic_clock::time_point(chrono::nanoseconds(
2493 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2494 const monotonic_clock::time_point
2495 oldest_remote_unreliable_monotonic_timestamps =
2496 monotonic_clock::time_point(chrono::nanoseconds(
2497 log_header->message()
2498 .oldest_remote_unreliable_monotonic_timestamps()
2499 ->Get(1)));
2500 const monotonic_clock::time_point
2501 oldest_local_unreliable_monotonic_timestamps =
2502 monotonic_clock::time_point(chrono::nanoseconds(
2503 log_header->message()
2504 .oldest_local_unreliable_monotonic_timestamps()
2505 ->Get(1)));
2506 switch (log_header->message().parts_index()) {
2507 case 0:
2508 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2509 monotonic_clock::max_time);
2510 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2511 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2512 monotonic_clock::max_time);
2513 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2514 monotonic_clock::max_time);
2515 break;
2516 case 1:
2517 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2518 monotonic_clock::time_point(chrono::microseconds(90200)));
2519 EXPECT_EQ(oldest_local_monotonic_timestamps,
2520 monotonic_clock::time_point(chrono::microseconds(90350)));
2521 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2522 monotonic_clock::time_point(chrono::microseconds(90200)));
2523 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2524 monotonic_clock::time_point(chrono::microseconds(90350)));
2525 break;
2526 case 2:
2527 EXPECT_EQ(oldest_remote_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002528 monotonic_clock::time_point(chrono::milliseconds(1323) +
2529 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002530 EXPECT_EQ(oldest_local_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002531 monotonic_clock::time_point(chrono::microseconds(10100350)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002532 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
Austin Schuh58646e22021-08-23 23:51:46 -07002533 monotonic_clock::time_point(chrono::milliseconds(1323) +
2534 chrono::microseconds(200)));
Austin Schuh72211ae2021-08-05 14:02:30 -07002535 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2536 monotonic_clock::time_point(chrono::microseconds(10100350)));
2537 break;
2538 default:
2539 FAIL();
2540 break;
2541 }
2542 }
2543
Austin Schuh315b96b2020-12-11 21:21:12 -08002544 // Confirm that we refuse to replay logs with missing boot uuids.
Austin Schuh58646e22021-08-23 23:51:46 -07002545 {
2546 LogReader reader(SortParts(pi1_reboot_logfiles_));
Austin Schuh315b96b2020-12-11 21:21:12 -08002547
Austin Schuh58646e22021-08-23 23:51:46 -07002548 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2549 log_reader_factory.set_send_delay(chrono::microseconds(0));
Austin Schuh315b96b2020-12-11 21:21:12 -08002550
Austin Schuh58646e22021-08-23 23:51:46 -07002551 // This sends out the fetched messages and advances time to the start of
2552 // the log file.
2553 reader.Register(&log_reader_factory);
2554
2555 log_reader_factory.Run();
2556
2557 reader.Deregister();
2558 }
Austin Schuh315b96b2020-12-11 21:21:12 -08002559}
2560
Austin Schuh5e14d842022-01-21 12:02:15 -08002561// Tests that we can sort a log which only has timestamps from the remote
2562// because the local message_bridge_client failed to connect.
2563TEST_P(MultinodeLoggerTest, RemoteRebootOnlyTimestamps) {
2564 const UUID pi1_boot0 = UUID::Random();
2565 const UUID pi2_boot0 = UUID::Random();
2566 const UUID pi2_boot1 = UUID::Random();
2567 {
2568 CHECK_EQ(pi1_index_, 0u);
2569 CHECK_EQ(pi2_index_, 1u);
2570
2571 time_converter_.set_boot_uuid(pi1_index_, 0, pi1_boot0);
2572 time_converter_.set_boot_uuid(pi2_index_, 0, pi2_boot0);
2573 time_converter_.set_boot_uuid(pi2_index_, 1, pi2_boot1);
2574
2575 time_converter_.AddNextTimestamp(
2576 distributed_clock::epoch(),
2577 {BootTimestamp::epoch(), BootTimestamp::epoch()});
2578 const chrono::nanoseconds reboot_time = chrono::milliseconds(10100);
2579 time_converter_.AddNextTimestamp(
2580 distributed_clock::epoch() + reboot_time,
2581 {BootTimestamp::epoch() + reboot_time,
2582 BootTimestamp{
2583 .boot = 1,
2584 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)}});
2585 }
2586 pi2_->Disconnect(pi1_->node());
2587
2588 std::vector<std::string> filenames;
2589 {
2590 LoggerState pi1_logger = MakeLogger(pi1_);
2591
2592 event_loop_factory_.RunFor(chrono::milliseconds(95));
2593 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2594 pi1_boot0);
2595 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2596 pi2_boot0);
2597
2598 StartLogger(&pi1_logger);
2599
2600 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2601
2602 VLOG(1) << "Reboot now!";
2603
2604 event_loop_factory_.RunFor(chrono::milliseconds(20000));
2605 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi1")->boot_uuid(),
2606 pi1_boot0);
2607 EXPECT_EQ(event_loop_factory_.GetNodeEventLoopFactory("pi2")->boot_uuid(),
2608 pi2_boot1);
2609 pi1_logger.AppendAllFilenames(&filenames);
2610 }
2611
2612 // Confirm that our new oldest timestamps properly update as we reboot and
2613 // rotate.
2614 size_t timestamp_file_count = 0;
2615 for (const std::string &file : filenames) {
2616 std::optional<SizePrefixedFlatbufferVector<LogFileHeader>> log_header =
2617 ReadHeader(file);
2618 CHECK(log_header);
2619
2620 if (log_header->message().has_configuration()) {
2621 continue;
2622 }
2623
2624 const monotonic_clock::time_point monotonic_start_time =
2625 monotonic_clock::time_point(
2626 chrono::nanoseconds(log_header->message().monotonic_start_time()));
2627 const UUID source_node_boot_uuid = UUID::FromString(
2628 log_header->message().source_node_boot_uuid()->string_view());
2629
2630 ASSERT_TRUE(log_header->message().has_oldest_remote_monotonic_timestamps());
2631 ASSERT_EQ(
2632 log_header->message().oldest_remote_monotonic_timestamps()->size(), 2u);
2633 ASSERT_TRUE(log_header->message().has_oldest_local_monotonic_timestamps());
2634 ASSERT_EQ(log_header->message().oldest_local_monotonic_timestamps()->size(),
2635 2u);
2636 ASSERT_TRUE(log_header->message()
2637 .has_oldest_remote_unreliable_monotonic_timestamps());
2638 ASSERT_EQ(log_header->message()
2639 .oldest_remote_unreliable_monotonic_timestamps()
2640 ->size(),
2641 2u);
2642 ASSERT_TRUE(log_header->message()
2643 .has_oldest_local_unreliable_monotonic_timestamps());
2644 ASSERT_EQ(log_header->message()
2645 .oldest_local_unreliable_monotonic_timestamps()
2646 ->size(),
2647 2u);
2648
2649 if (log_header->message().node()->name()->string_view() != "pi1") {
2650 ASSERT_TRUE(file.find("aos.message_bridge.RemoteMessage") !=
2651 std::string::npos);
2652
2653 const std::optional<SizePrefixedFlatbufferVector<MessageHeader>> msg =
2654 ReadNthMessage(file, 0);
2655 CHECK(msg);
2656
2657 EXPECT_TRUE(msg->message().has_monotonic_sent_time());
2658 EXPECT_TRUE(msg->message().has_monotonic_remote_time());
2659
2660 const monotonic_clock::time_point
2661 expected_oldest_local_monotonic_timestamps(
2662 chrono::nanoseconds(msg->message().monotonic_sent_time()));
2663 const monotonic_clock::time_point
2664 expected_oldest_remote_monotonic_timestamps(
2665 chrono::nanoseconds(msg->message().monotonic_remote_time()));
2666
2667 EXPECT_NE(expected_oldest_local_monotonic_timestamps,
2668 monotonic_clock::min_time);
2669 EXPECT_NE(expected_oldest_remote_monotonic_timestamps,
2670 monotonic_clock::min_time);
2671
2672 ++timestamp_file_count;
2673 // Since the log file is from the perspective of the other node,
2674 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2675 monotonic_clock::time_point(chrono::nanoseconds(
2676 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2677 0)));
2678 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2679 monotonic_clock::time_point(chrono::nanoseconds(
2680 log_header->message().oldest_local_monotonic_timestamps()->Get(
2681 0)));
2682 const monotonic_clock::time_point
2683 oldest_remote_unreliable_monotonic_timestamps =
2684 monotonic_clock::time_point(chrono::nanoseconds(
2685 log_header->message()
2686 .oldest_remote_unreliable_monotonic_timestamps()
2687 ->Get(0)));
2688 const monotonic_clock::time_point
2689 oldest_local_unreliable_monotonic_timestamps =
2690 monotonic_clock::time_point(chrono::nanoseconds(
2691 log_header->message()
2692 .oldest_local_unreliable_monotonic_timestamps()
2693 ->Get(0)));
Austin Schuh5e14d842022-01-21 12:02:15 -08002694
Austin Schuh01f3b392022-01-25 20:03:09 -08002695 const Channel *channel =
2696 event_loop_factory_.configuration()->channels()->Get(
2697 msg->message().channel_index());
2698 const Connection *connection = configuration::ConnectionToNode(
2699 channel, configuration::GetNode(
2700 event_loop_factory_.configuration(),
2701 log_header->message().node()->name()->string_view()));
2702
2703 const bool reliable = connection->time_to_live() == 0;
2704
2705 if (shared()) {
2706 // Confirm that the oldest timestamps match what we expect. Based on
2707 // what we are doing, we know that the oldest time is the first
2708 // message's time.
2709 //
2710 // This makes the test robust to both the split and combined config
2711 // tests.
2712 switch (log_header->message().parts_index()) {
2713 case 0:
2714 case 1:
2715 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2716 expected_oldest_remote_monotonic_timestamps);
2717 EXPECT_EQ(oldest_local_monotonic_timestamps,
2718 expected_oldest_local_monotonic_timestamps);
2719 if (reliable) {
2720 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2721 monotonic_clock::max_time);
2722 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2723 monotonic_clock::max_time);
2724 } else {
2725 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2726 expected_oldest_remote_monotonic_timestamps);
2727 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2728 expected_oldest_local_monotonic_timestamps);
2729 }
2730 break;
2731 case 2:
2732 LOG(INFO) << "Shared";
2733 EXPECT_EQ(
2734 oldest_remote_monotonic_timestamps,
2735 monotonic_clock::epoch() + chrono::nanoseconds(10000000000));
2736 EXPECT_EQ(
2737 oldest_local_monotonic_timestamps,
2738 monotonic_clock::epoch() + chrono::nanoseconds(1323100000));
2739 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2740 expected_oldest_remote_monotonic_timestamps);
2741 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2742 expected_oldest_local_monotonic_timestamps);
2743 break;
2744 default:
2745 FAIL();
2746 break;
2747 }
2748
2749 switch (log_header->message().parts_index()) {
2750 case 0:
2751 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2752 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2753 break;
2754 case 1:
2755 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2756 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2757 break;
2758 case 2:
2759 if (shared()) {
2760 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2761 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2762 LOG(INFO) << "Shared";
2763 break;
2764 }
2765 [[fallthrough]];
2766 default:
2767 FAIL();
2768 break;
2769 }
2770 } else {
2771 switch (log_header->message().parts_index()) {
2772 case 0:
2773 case 1:
2774 if (reliable) {
2775 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2776 monotonic_clock::max_time);
2777 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2778 monotonic_clock::max_time);
2779 } else {
2780 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2781 expected_oldest_remote_monotonic_timestamps);
2782 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2783 expected_oldest_local_monotonic_timestamps);
2784 }
2785 break;
2786 default:
2787 FAIL();
2788 break;
2789 }
2790
2791 switch (log_header->message().parts_index()) {
2792 case 0:
2793 EXPECT_EQ(source_node_boot_uuid, pi2_boot0);
2794 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2795 break;
2796 case 1:
2797 EXPECT_EQ(source_node_boot_uuid, pi2_boot1);
2798 EXPECT_EQ(monotonic_start_time, monotonic_clock::min_time);
2799 break;
2800 default:
2801 FAIL();
2802 break;
2803 }
Austin Schuh5e14d842022-01-21 12:02:15 -08002804 }
2805
2806 continue;
2807 }
2808 EXPECT_EQ(
2809 log_header->message().oldest_remote_monotonic_timestamps()->Get(0),
2810 monotonic_clock::max_time.time_since_epoch().count());
2811 EXPECT_EQ(log_header->message().oldest_local_monotonic_timestamps()->Get(0),
2812 monotonic_clock::max_time.time_since_epoch().count());
2813 EXPECT_EQ(log_header->message()
2814 .oldest_remote_unreliable_monotonic_timestamps()
2815 ->Get(0),
2816 monotonic_clock::max_time.time_since_epoch().count());
2817 EXPECT_EQ(log_header->message()
2818 .oldest_local_unreliable_monotonic_timestamps()
2819 ->Get(0),
2820 monotonic_clock::max_time.time_since_epoch().count());
2821
2822 const monotonic_clock::time_point oldest_remote_monotonic_timestamps =
2823 monotonic_clock::time_point(chrono::nanoseconds(
2824 log_header->message().oldest_remote_monotonic_timestamps()->Get(
2825 1)));
2826 const monotonic_clock::time_point oldest_local_monotonic_timestamps =
2827 monotonic_clock::time_point(chrono::nanoseconds(
2828 log_header->message().oldest_local_monotonic_timestamps()->Get(1)));
2829 const monotonic_clock::time_point
2830 oldest_remote_unreliable_monotonic_timestamps =
2831 monotonic_clock::time_point(chrono::nanoseconds(
2832 log_header->message()
2833 .oldest_remote_unreliable_monotonic_timestamps()
2834 ->Get(1)));
2835 const monotonic_clock::time_point
2836 oldest_local_unreliable_monotonic_timestamps =
2837 monotonic_clock::time_point(chrono::nanoseconds(
2838 log_header->message()
2839 .oldest_local_unreliable_monotonic_timestamps()
2840 ->Get(1)));
2841 switch (log_header->message().parts_index()) {
2842 case 0:
2843 EXPECT_EQ(oldest_remote_monotonic_timestamps,
2844 monotonic_clock::max_time);
2845 EXPECT_EQ(oldest_local_monotonic_timestamps, monotonic_clock::max_time);
2846 EXPECT_EQ(oldest_remote_unreliable_monotonic_timestamps,
2847 monotonic_clock::max_time);
2848 EXPECT_EQ(oldest_local_unreliable_monotonic_timestamps,
2849 monotonic_clock::max_time);
2850 break;
2851 default:
2852 FAIL();
2853 break;
2854 }
2855 }
2856
Austin Schuh01f3b392022-01-25 20:03:09 -08002857 if (shared()) {
2858 EXPECT_EQ(timestamp_file_count, 3u);
2859 } else {
2860 EXPECT_EQ(timestamp_file_count, 4u);
2861 }
Austin Schuh5e14d842022-01-21 12:02:15 -08002862
Austin Schuhe2373e22022-01-21 12:25:17 -08002863 // Confirm that we can actually sort the resulting log and read it.
2864 {
2865 LogReader reader(SortParts(filenames));
2866
2867 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
2868 log_reader_factory.set_send_delay(chrono::microseconds(0));
2869
2870 // This sends out the fetched messages and advances time to the start of
2871 // the log file.
2872 reader.Register(&log_reader_factory);
2873
2874 log_reader_factory.Run();
2875
2876 reader.Deregister();
2877 }
Austin Schuh5e14d842022-01-21 12:02:15 -08002878}
2879
Austin Schuhc9049732020-12-21 22:27:15 -08002880// Tests that we properly handle one direction of message_bridge being
2881// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002882TEST_P(MultinodeLoggerTest, OneDirectionWithNegativeSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002883 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002884 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002885 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002886
2887 time_converter_.AddMonotonic(
2888 {chrono::milliseconds(10000),
2889 chrono::milliseconds(10000) - chrono::milliseconds(1)});
Austin Schuhc9049732020-12-21 22:27:15 -08002890 {
2891 LoggerState pi1_logger = MakeLogger(pi1_);
2892
2893 event_loop_factory_.RunFor(chrono::milliseconds(95));
2894
2895 StartLogger(&pi1_logger);
2896
2897 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2898 }
2899
2900 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2901 // to confirm the right thing happened.
2902 ConfirmReadable(pi1_single_direction_logfiles_);
2903}
2904
2905// Tests that we properly handle one direction of message_bridge being
2906// unavailable.
Austin Schuh61e973f2021-02-21 21:43:56 -08002907TEST_P(MultinodeLoggerTest, OneDirectionWithPositiveSlope) {
Austin Schuh58646e22021-08-23 23:51:46 -07002908 pi1_->Disconnect(pi2_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002909 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002910 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(500)});
Austin Schuh87dd3832021-01-01 23:07:31 -08002911
2912 time_converter_.AddMonotonic(
2913 {chrono::milliseconds(10000),
2914 chrono::milliseconds(10000) + chrono::milliseconds(1)});
2915 {
2916 LoggerState pi1_logger = MakeLogger(pi1_);
2917
2918 event_loop_factory_.RunFor(chrono::milliseconds(95));
2919
2920 StartLogger(&pi1_logger);
2921
2922 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2923 }
2924
2925 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2926 // to confirm the right thing happened.
2927 ConfirmReadable(pi1_single_direction_logfiles_);
2928}
2929
Austin Schuhe9f00232021-09-16 18:04:23 -07002930// Tests that we explode if someone passes in a part file twice with a better
2931// error than an out of order error.
2932TEST_P(MultinodeLoggerTest, DuplicateLogFiles) {
2933 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002934 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhe9f00232021-09-16 18:04:23 -07002935 {
2936 LoggerState pi1_logger = MakeLogger(pi1_);
2937
2938 event_loop_factory_.RunFor(chrono::milliseconds(95));
2939
2940 StartLogger(&pi1_logger);
2941
2942 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2943 }
2944
2945 std::vector<std::string> duplicates;
2946 for (const std::string &f : pi1_single_direction_logfiles_) {
2947 duplicates.emplace_back(f);
2948 duplicates.emplace_back(f);
2949 }
2950 EXPECT_DEATH({ SortParts(duplicates); }, "Found duplicate parts in");
2951}
2952
Austin Schuh87dd3832021-01-01 23:07:31 -08002953// Tests that we properly handle a dead node. Do this by just disconnecting it
2954// and only using one nodes of logs.
Austin Schuh61e973f2021-02-21 21:43:56 -08002955TEST_P(MultinodeLoggerTest, DeadNode) {
Austin Schuh58646e22021-08-23 23:51:46 -07002956 pi1_->Disconnect(pi2_->node());
2957 pi2_->Disconnect(pi1_->node());
Austin Schuh87dd3832021-01-01 23:07:31 -08002958 time_converter_.AddMonotonic(
Austin Schuh3e20c692021-11-16 20:43:16 -08002959 {BootTimestamp::epoch(), BootTimestamp::epoch() + chrono::seconds(1000)});
Austin Schuhc9049732020-12-21 22:27:15 -08002960 {
2961 LoggerState pi1_logger = MakeLogger(pi1_);
2962
2963 event_loop_factory_.RunFor(chrono::milliseconds(95));
2964
2965 StartLogger(&pi1_logger);
2966
2967 event_loop_factory_.RunFor(chrono::milliseconds(10000));
2968 }
2969
2970 // Confirm that we can parse the result. LogReader has enough internal CHECKs
2971 // to confirm the right thing happened.
Austin Schuh510dc622021-08-06 18:47:30 -07002972 ConfirmReadable(MakePi1DeadNodeLogfiles());
Austin Schuhc9049732020-12-21 22:27:15 -08002973}
2974
Austin Schuhcdd90272021-03-15 12:46:16 -07002975constexpr std::string_view kCombinedConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08002976 "b8114cd99e9c606b7517d8f478bf16513aef550f23f317720667314cb261f689");
Austin Schuhcdd90272021-03-15 12:46:16 -07002977constexpr std::string_view kSplitConfigSha1(
James Kuszmaule7c7e582022-01-07 18:50:01 -08002978 "60943d0a46afa6028c8ae276e7b4900b35892f1f53b1818056e7d04463709c5b");
Austin Schuhcdd90272021-03-15 12:46:16 -07002979
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002980INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002981 All, MultinodeLoggerTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002982 ::testing::Combine(::testing::Values(
2983 ConfigParams{
2984 "multinode_pingpong_combined_config.json", true,
2985 kCombinedConfigSha1},
2986 ConfigParams{"multinode_pingpong_split_config.json",
2987 false, kSplitConfigSha1}),
2988 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002989
James Kuszmaulf4bf9fe2021-05-10 22:58:24 -07002990INSTANTIATE_TEST_SUITE_P(
Austin Schuh61e973f2021-02-21 21:43:56 -08002991 All, MultinodeLoggerDeathTest,
James Kuszmauldd0a5042021-10-28 23:38:04 -07002992 ::testing::Combine(::testing::Values(
2993 ConfigParams{
2994 "multinode_pingpong_combined_config.json", true,
2995 kCombinedConfigSha1},
2996 ConfigParams{"multinode_pingpong_split_config.json",
2997 false, kSplitConfigSha1}),
2998 ::testing::ValuesIn(SupportedCompressionAlgorithms())));
Austin Schuh61e973f2021-02-21 21:43:56 -08002999
Austin Schuh5b728b72021-06-16 14:57:15 -07003000// Tests that we can relog with a different config. This makes most sense when
3001// you are trying to edit a log and want to use channel renaming + the original
3002// config in the new log.
3003TEST_P(MultinodeLoggerTest, LogDifferentConfig) {
3004 time_converter_.StartEqual();
3005 {
3006 LoggerState pi1_logger = MakeLogger(pi1_);
3007 LoggerState pi2_logger = MakeLogger(pi2_);
3008
3009 event_loop_factory_.RunFor(chrono::milliseconds(95));
3010
3011 StartLogger(&pi1_logger);
3012 StartLogger(&pi2_logger);
3013
3014 event_loop_factory_.RunFor(chrono::milliseconds(20000));
3015 }
3016
3017 LogReader reader(SortParts(logfiles_));
3018 reader.RemapLoggedChannel<aos::examples::Ping>("/test", "/original");
3019
3020 SimulatedEventLoopFactory log_reader_factory(reader.configuration());
3021 log_reader_factory.set_send_delay(chrono::microseconds(0));
3022
3023 // This sends out the fetched messages and advances time to the start of the
3024 // log file.
3025 reader.Register(&log_reader_factory);
3026
3027 const Node *pi1 =
3028 configuration::GetNode(log_reader_factory.configuration(), "pi1");
3029 const Node *pi2 =
3030 configuration::GetNode(log_reader_factory.configuration(), "pi2");
3031
3032 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi1) << " pi1";
3033 LOG(INFO) << "Start time " << reader.monotonic_start_time(pi2) << " pi2";
3034 LOG(INFO) << "now pi1 "
3035 << log_reader_factory.GetNodeEventLoopFactory(pi1)->monotonic_now();
3036 LOG(INFO) << "now pi2 "
3037 << log_reader_factory.GetNodeEventLoopFactory(pi2)->monotonic_now();
3038
3039 EXPECT_THAT(reader.LoggedNodes(),
3040 ::testing::ElementsAre(
3041 configuration::GetNode(reader.logged_configuration(), pi1),
3042 configuration::GetNode(reader.logged_configuration(), pi2)));
3043
3044 reader.event_loop_factory()->set_send_delay(chrono::microseconds(0));
3045
3046 // And confirm we can re-create a log again, while checking the contents.
3047 std::vector<std::string> log_files;
3048 {
3049 LoggerState pi1_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003050 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi1"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003051 &log_reader_factory, reader.logged_configuration());
3052 LoggerState pi2_logger =
Austin Schuh58646e22021-08-23 23:51:46 -07003053 MakeLogger(log_reader_factory.GetNodeEventLoopFactory("pi2"),
Austin Schuh5b728b72021-06-16 14:57:15 -07003054 &log_reader_factory, reader.logged_configuration());
3055
Austin Schuh3e20c692021-11-16 20:43:16 -08003056 pi1_logger.StartLogger(tmp_dir_ + "/relogged1");
3057 pi2_logger.StartLogger(tmp_dir_ + "/relogged2");
Austin Schuh5b728b72021-06-16 14:57:15 -07003058
3059 log_reader_factory.Run();
3060
3061 for (auto &x : pi1_logger.log_namer->all_filenames()) {
3062 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged1_", x));
3063 }
3064 for (auto &x : pi2_logger.log_namer->all_filenames()) {
3065 log_files.emplace_back(absl::StrCat(tmp_dir_, "/relogged2_", x));
3066 }
3067 }
3068
3069 reader.Deregister();
3070
3071 // And verify that we can run the LogReader over the relogged files without
3072 // hitting any fatal errors.
3073 {
3074 LogReader relogged_reader(SortParts(log_files));
3075 relogged_reader.Register();
3076
3077 relogged_reader.event_loop_factory()->Run();
3078 }
3079}
Austin Schuha04efed2021-01-24 18:04:20 -08003080
Austin Schuh3e20c692021-11-16 20:43:16 -08003081// Tests that we properly replay a log where the start time for a node is before
3082// any data on the node. This can happen if the logger starts before data is
3083// published. While the scenario below is a bit convoluted, we have seen logs
3084// like this generated out in the wild.
3085TEST(MultinodeRebootLoggerTest, StartTimeBeforeData) {
3086 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3087 aos::configuration::ReadConfig(ArtifactPath(
3088 "aos/events/logging/multinode_pingpong_split3_config.json"));
3089 message_bridge::TestingTimeConverter time_converter(
3090 configuration::NodesCount(&config.message()));
3091 SimulatedEventLoopFactory event_loop_factory(&config.message());
3092 event_loop_factory.SetTimeConverter(&time_converter);
3093 NodeEventLoopFactory *const pi1 =
3094 event_loop_factory.GetNodeEventLoopFactory("pi1");
3095 const size_t pi1_index = configuration::GetNodeIndex(
3096 event_loop_factory.configuration(), pi1->node());
3097 NodeEventLoopFactory *const pi2 =
3098 event_loop_factory.GetNodeEventLoopFactory("pi2");
3099 const size_t pi2_index = configuration::GetNodeIndex(
3100 event_loop_factory.configuration(), pi2->node());
3101 NodeEventLoopFactory *const pi3 =
3102 event_loop_factory.GetNodeEventLoopFactory("pi3");
3103 const size_t pi3_index = configuration::GetNodeIndex(
3104 event_loop_factory.configuration(), pi3->node());
3105
3106 const std::string kLogfile1_1 =
3107 aos::testing::TestTmpDir() + "/multi_logfile1/";
3108 const std::string kLogfile2_1 =
3109 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3110 const std::string kLogfile2_2 =
3111 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3112 const std::string kLogfile3_1 =
3113 aos::testing::TestTmpDir() + "/multi_logfile3/";
3114 util::UnlinkRecursive(kLogfile1_1);
3115 util::UnlinkRecursive(kLogfile2_1);
3116 util::UnlinkRecursive(kLogfile2_2);
3117 util::UnlinkRecursive(kLogfile3_1);
3118 const UUID pi1_boot0 = UUID::Random();
3119 const UUID pi2_boot0 = UUID::Random();
3120 const UUID pi2_boot1 = UUID::Random();
3121 const UUID pi3_boot0 = UUID::Random();
3122 {
3123 CHECK_EQ(pi1_index, 0u);
3124 CHECK_EQ(pi2_index, 1u);
3125 CHECK_EQ(pi3_index, 2u);
3126
3127 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3128 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3129 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3130 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3131
3132 time_converter.AddNextTimestamp(
3133 distributed_clock::epoch(),
3134 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3135 BootTimestamp::epoch()});
3136 const chrono::nanoseconds reboot_time = chrono::milliseconds(20000);
3137 time_converter.AddNextTimestamp(
3138 distributed_clock::epoch() + reboot_time,
3139 {BootTimestamp::epoch() + reboot_time,
3140 BootTimestamp{
3141 .boot = 1,
3142 .time = monotonic_clock::epoch() + chrono::milliseconds(1323)},
3143 BootTimestamp::epoch() + reboot_time});
3144 }
3145
3146 // Make everything perfectly quiet.
3147 event_loop_factory.SkipTimingReport();
3148 event_loop_factory.DisableStatistics();
3149
3150 std::vector<std::string> filenames;
3151 {
3152 LoggerState pi1_logger = LoggerState::MakeLogger(
3153 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3154 LoggerState pi3_logger = LoggerState::MakeLogger(
3155 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3156 {
3157 // And now start the logger.
3158 LoggerState pi2_logger = LoggerState::MakeLogger(
3159 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3160
3161 event_loop_factory.RunFor(chrono::milliseconds(1000));
3162
3163 pi1_logger.StartLogger(kLogfile1_1);
3164 pi3_logger.StartLogger(kLogfile3_1);
3165 pi2_logger.StartLogger(kLogfile2_1);
3166
3167 event_loop_factory.RunFor(chrono::milliseconds(10000));
3168
3169 // Now that we've got a start time in the past, turn on data.
3170 event_loop_factory.EnableStatistics();
3171 std::unique_ptr<aos::EventLoop> ping_event_loop =
3172 pi1->MakeEventLoop("ping");
3173 Ping ping(ping_event_loop.get());
3174
3175 pi2->AlwaysStart<Pong>("pong");
3176
3177 event_loop_factory.RunFor(chrono::milliseconds(3000));
3178
3179 pi2_logger.AppendAllFilenames(&filenames);
3180
3181 // Stop logging on pi2 before rebooting and completely shut off all
3182 // messages on pi2.
3183 pi2->DisableStatistics();
3184 pi1->Disconnect(pi2->node());
3185 pi2->Disconnect(pi1->node());
3186 }
3187 event_loop_factory.RunFor(chrono::milliseconds(7000));
3188 // pi2 now reboots.
3189 {
3190 event_loop_factory.RunFor(chrono::milliseconds(1000));
3191
3192 // Start logging again on pi2 after it is up.
3193 LoggerState pi2_logger = LoggerState::MakeLogger(
3194 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3195 pi2_logger.StartLogger(kLogfile2_2);
3196
3197 event_loop_factory.RunFor(chrono::milliseconds(10000));
3198 // And, now that we have a start time in the log, turn data back on.
3199 pi2->EnableStatistics();
3200 pi1->Connect(pi2->node());
3201 pi2->Connect(pi1->node());
3202
3203 pi2->AlwaysStart<Pong>("pong");
3204 std::unique_ptr<aos::EventLoop> ping_event_loop =
3205 pi1->MakeEventLoop("ping");
3206 Ping ping(ping_event_loop.get());
3207
3208 event_loop_factory.RunFor(chrono::milliseconds(3000));
3209
3210 pi2_logger.AppendAllFilenames(&filenames);
3211 }
3212
3213 pi1_logger.AppendAllFilenames(&filenames);
3214 pi3_logger.AppendAllFilenames(&filenames);
3215 }
3216
3217 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3218 // to confirm the right thing happened.
3219 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3220 ConfirmReadable(filenames);
3221}
3222
Austin Schuh5dd22842021-11-17 16:09:39 -08003223// Tests that local data before remote data after reboot is properly replayed.
3224// We only trigger a reboot in the timestamp interpolation function when solving
3225// the timestamp problem when we actually have a point in the function. This
3226// originally only happened when a point passes the noncausal filter. At the
3227// start of time for the second boot, if we aren't careful, we will have
3228// messages which need to be published at times before the boot. This happens
3229// when a local message is in the log before a forwarded message, so there is no
3230// point in the interpolation function. This delays the reboot. So, we need to
3231// recreate that situation and make sure it doesn't come back.
3232TEST(MultinodeRebootLoggerTest, LocalMessageBeforeRemoteBeforeStartAfterReboot) {
3233 aos::FlatbufferDetachedBuffer<aos::Configuration> config =
3234 aos::configuration::ReadConfig(ArtifactPath(
3235 "aos/events/logging/multinode_pingpong_split3_config.json"));
3236 message_bridge::TestingTimeConverter time_converter(
3237 configuration::NodesCount(&config.message()));
3238 SimulatedEventLoopFactory event_loop_factory(&config.message());
3239 event_loop_factory.SetTimeConverter(&time_converter);
3240 NodeEventLoopFactory *const pi1 =
3241 event_loop_factory.GetNodeEventLoopFactory("pi1");
3242 const size_t pi1_index = configuration::GetNodeIndex(
3243 event_loop_factory.configuration(), pi1->node());
3244 NodeEventLoopFactory *const pi2 =
3245 event_loop_factory.GetNodeEventLoopFactory("pi2");
3246 const size_t pi2_index = configuration::GetNodeIndex(
3247 event_loop_factory.configuration(), pi2->node());
3248 NodeEventLoopFactory *const pi3 =
3249 event_loop_factory.GetNodeEventLoopFactory("pi3");
3250 const size_t pi3_index = configuration::GetNodeIndex(
3251 event_loop_factory.configuration(), pi3->node());
3252
3253 const std::string kLogfile1_1 =
3254 aos::testing::TestTmpDir() + "/multi_logfile1/";
3255 const std::string kLogfile2_1 =
3256 aos::testing::TestTmpDir() + "/multi_logfile2.1/";
3257 const std::string kLogfile2_2 =
3258 aos::testing::TestTmpDir() + "/multi_logfile2.2/";
3259 const std::string kLogfile3_1 =
3260 aos::testing::TestTmpDir() + "/multi_logfile3/";
3261 util::UnlinkRecursive(kLogfile1_1);
3262 util::UnlinkRecursive(kLogfile2_1);
3263 util::UnlinkRecursive(kLogfile2_2);
3264 util::UnlinkRecursive(kLogfile3_1);
3265 const UUID pi1_boot0 = UUID::Random();
3266 const UUID pi2_boot0 = UUID::Random();
3267 const UUID pi2_boot1 = UUID::Random();
3268 const UUID pi3_boot0 = UUID::Random();
3269 {
3270 CHECK_EQ(pi1_index, 0u);
3271 CHECK_EQ(pi2_index, 1u);
3272 CHECK_EQ(pi3_index, 2u);
3273
3274 time_converter.set_boot_uuid(pi1_index, 0, pi1_boot0);
3275 time_converter.set_boot_uuid(pi2_index, 0, pi2_boot0);
3276 time_converter.set_boot_uuid(pi2_index, 1, pi2_boot1);
3277 time_converter.set_boot_uuid(pi3_index, 0, pi3_boot0);
3278
3279 time_converter.AddNextTimestamp(
3280 distributed_clock::epoch(),
3281 {BootTimestamp::epoch(), BootTimestamp::epoch(),
3282 BootTimestamp::epoch()});
3283 const chrono::nanoseconds reboot_time = chrono::milliseconds(5000);
3284 time_converter.AddNextTimestamp(
3285 distributed_clock::epoch() + reboot_time,
3286 {BootTimestamp::epoch() + reboot_time,
3287 BootTimestamp{
3288 .boot = 1,
3289 .time = monotonic_clock::epoch() + reboot_time + chrono::seconds(100)},
3290 BootTimestamp::epoch() + reboot_time});
3291 }
3292
3293 std::vector<std::string> filenames;
3294 {
3295 LoggerState pi1_logger = LoggerState::MakeLogger(
3296 pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3297 LoggerState pi3_logger = LoggerState::MakeLogger(
3298 pi3, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3299 {
3300 // And now start the logger.
3301 LoggerState pi2_logger = LoggerState::MakeLogger(
3302 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3303
3304 pi1_logger.StartLogger(kLogfile1_1);
3305 pi3_logger.StartLogger(kLogfile3_1);
3306 pi2_logger.StartLogger(kLogfile2_1);
3307
3308 event_loop_factory.RunFor(chrono::milliseconds(1005));
3309
3310 // Now that we've got a start time in the past, turn on data.
3311 std::unique_ptr<aos::EventLoop> ping_event_loop =
3312 pi1->MakeEventLoop("ping");
3313 Ping ping(ping_event_loop.get());
3314
3315 pi2->AlwaysStart<Pong>("pong");
3316
3317 event_loop_factory.RunFor(chrono::milliseconds(3000));
3318
3319 pi2_logger.AppendAllFilenames(&filenames);
3320
3321 // Disable any remote messages on pi2.
3322 pi1->Disconnect(pi2->node());
3323 pi2->Disconnect(pi1->node());
3324 }
3325 event_loop_factory.RunFor(chrono::milliseconds(995));
3326 // pi2 now reboots at 5 seconds.
3327 {
3328 event_loop_factory.RunFor(chrono::milliseconds(1000));
3329
3330 // Make local stuff happen before we start logging and connect the remote.
3331 pi2->AlwaysStart<Pong>("pong");
3332 std::unique_ptr<aos::EventLoop> ping_event_loop =
3333 pi1->MakeEventLoop("ping");
3334 Ping ping(ping_event_loop.get());
3335 event_loop_factory.RunFor(chrono::milliseconds(1005));
3336
3337 // Start logging again on pi2 after it is up.
3338 LoggerState pi2_logger = LoggerState::MakeLogger(
3339 pi2, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
3340 pi2_logger.StartLogger(kLogfile2_2);
3341
3342 // And allow remote messages now that we have some local ones.
3343 pi1->Connect(pi2->node());
3344 pi2->Connect(pi1->node());
3345
3346 event_loop_factory.RunFor(chrono::milliseconds(1000));
3347
3348 event_loop_factory.RunFor(chrono::milliseconds(3000));
3349
3350 pi2_logger.AppendAllFilenames(&filenames);
3351 }
3352
3353 pi1_logger.AppendAllFilenames(&filenames);
3354 pi3_logger.AppendAllFilenames(&filenames);
3355 }
3356
3357 // Confirm that we can parse the result. LogReader has enough internal CHECKs
3358 // to confirm the right thing happened.
3359 const std::vector<LogFile> sorted_parts = SortParts(filenames);
3360 ConfirmReadable(filenames);
3361}
3362
3363
Austin Schuhe309d2a2019-11-29 13:25:21 -08003364} // namespace testing
3365} // namespace logger
3366} // namespace aos