blob: 1c67312f803b2b83f1b6802a593d4381c21bdd9f [file] [log] [blame]
Austin Schuhc243b422020-10-11 15:35:08 -07001#include "aos/events/logging/logfile_utils.h"
2
Austin Schuhe243aaf2020-10-11 15:46:02 -07003#include <chrono>
4#include <string>
Austin Schuhc243b422020-10-11 15:35:08 -07005
Austin Schuhc41603c2020-10-11 16:17:37 -07006#include "aos/events/logging/logfile_sorting.h"
Austin Schuhc243b422020-10-11 15:35:08 -07007#include "aos/events/logging/test_message_generated.h"
Austin Schuh4b5c22a2020-11-30 22:58:43 -08008#include "aos/flatbuffer_merge.h"
Austin Schuhe243aaf2020-10-11 15:46:02 -07009#include "aos/flatbuffers.h"
Austin Schuhc243b422020-10-11 15:35:08 -070010#include "aos/json_to_flatbuffer.h"
11#include "aos/testing/tmpdir.h"
Austin Schuhe243aaf2020-10-11 15:46:02 -070012#include "gtest/gtest.h"
Austin Schuhc243b422020-10-11 15:35:08 -070013
14namespace aos {
15namespace logger {
16namespace testing {
Austin Schuhe243aaf2020-10-11 15:46:02 -070017namespace chrono = std::chrono;
Austin Schuhc243b422020-10-11 15:35:08 -070018
Austin Schuhe243aaf2020-10-11 15:46:02 -070019// Creates a size prefixed flatbuffer from json.
Austin Schuhc243b422020-10-11 15:35:08 -070020template <typename T>
21SizePrefixedFlatbufferDetachedBuffer<T> JsonToSizedFlatbuffer(
22 const std::string_view data) {
23 flatbuffers::FlatBufferBuilder fbb;
24 fbb.ForceDefaults(true);
25 fbb.FinishSizePrefixed(JsonToFlatbuffer<T>(data, &fbb));
26 return fbb.Release();
27}
28
Austin Schuhe243aaf2020-10-11 15:46:02 -070029// Tests that we can write and read 2 flatbuffers to file.
Austin Schuhc243b422020-10-11 15:35:08 -070030TEST(SpanReaderTest, ReadWrite) {
31 const std::string logfile = aos::testing::TestTmpDir() + "/log.bfbs";
32 unlink(logfile.c_str());
33
34 const aos::SizePrefixedFlatbufferDetachedBuffer<TestMessage> m1 =
Austin Schuh4b5c22a2020-11-30 22:58:43 -080035 JsonToSizedFlatbuffer<TestMessage>(R"({ "value": 1 })");
Austin Schuhc243b422020-10-11 15:35:08 -070036 const aos::SizePrefixedFlatbufferDetachedBuffer<TestMessage> m2 =
Austin Schuh4b5c22a2020-11-30 22:58:43 -080037 JsonToSizedFlatbuffer<TestMessage>(R"({ "value": 2 })");
Austin Schuhc243b422020-10-11 15:35:08 -070038
39 {
40 DetachedBufferWriter writer(logfile, std::make_unique<DummyEncoder>());
Austin Schuhadd6eb32020-11-09 21:24:26 -080041 writer.QueueSpan(m1.span());
42 writer.QueueSpan(m2.span());
Austin Schuhc243b422020-10-11 15:35:08 -070043 }
44
45 SpanReader reader(logfile);
46
47 EXPECT_EQ(reader.filename(), logfile);
Austin Schuhcf5f6442021-07-06 10:43:28 -070048 EXPECT_EQ(reader.PeekMessage(), m1.span());
49 EXPECT_EQ(reader.PeekMessage(), m1.span());
Austin Schuhadd6eb32020-11-09 21:24:26 -080050 EXPECT_EQ(reader.ReadMessage(), m1.span());
51 EXPECT_EQ(reader.ReadMessage(), m2.span());
Austin Schuhcf5f6442021-07-06 10:43:28 -070052 EXPECT_EQ(reader.PeekMessage(), absl::Span<const uint8_t>());
Austin Schuhc243b422020-10-11 15:35:08 -070053 EXPECT_EQ(reader.ReadMessage(), absl::Span<const uint8_t>());
54}
55
Austin Schuhe243aaf2020-10-11 15:46:02 -070056// Tests that we can actually parse the resulting messages at a basic level
57// through MessageReader.
58TEST(MessageReaderTest, ReadWrite) {
59 const std::string logfile = aos::testing::TestTmpDir() + "/log.bfbs";
60 unlink(logfile.c_str());
61
62 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config =
63 JsonToSizedFlatbuffer<LogFileHeader>(
64 R"({ "max_out_of_order_duration": 100000000 })");
65 const aos::SizePrefixedFlatbufferDetachedBuffer<MessageHeader> m1 =
66 JsonToSizedFlatbuffer<MessageHeader>(
67 R"({ "channel_index": 0, "monotonic_sent_time": 1 })");
68 const aos::SizePrefixedFlatbufferDetachedBuffer<MessageHeader> m2 =
69 JsonToSizedFlatbuffer<MessageHeader>(
70 R"({ "channel_index": 0, "monotonic_sent_time": 2 })");
71
72 {
73 DetachedBufferWriter writer(logfile, std::make_unique<DummyEncoder>());
Austin Schuhadd6eb32020-11-09 21:24:26 -080074 writer.QueueSpan(config.span());
75 writer.QueueSpan(m1.span());
76 writer.QueueSpan(m2.span());
Austin Schuhe243aaf2020-10-11 15:46:02 -070077 }
78
79 MessageReader reader(logfile);
80
81 EXPECT_EQ(reader.filename(), logfile);
82
83 EXPECT_EQ(
84 reader.max_out_of_order_duration(),
85 std::chrono::nanoseconds(config.message().max_out_of_order_duration()));
86 EXPECT_EQ(reader.newest_timestamp(), monotonic_clock::min_time);
87 EXPECT_TRUE(reader.ReadMessage());
88 EXPECT_EQ(reader.newest_timestamp(),
89 monotonic_clock::time_point(chrono::nanoseconds(1)));
90 EXPECT_TRUE(reader.ReadMessage());
91 EXPECT_EQ(reader.newest_timestamp(),
92 monotonic_clock::time_point(chrono::nanoseconds(2)));
93 EXPECT_FALSE(reader.ReadMessage());
94}
95
Austin Schuh32f68492020-11-08 21:45:51 -080096// Tests that we explode when messages are too far out of order.
97TEST(PartsMessageReaderDeathTest, TooFarOutOfOrder) {
98 const std::string logfile0 = aos::testing::TestTmpDir() + "/log0.bfbs";
99 unlink(logfile0.c_str());
100
101 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config0 =
102 JsonToSizedFlatbuffer<LogFileHeader>(
103 R"({
104 "max_out_of_order_duration": 100000000,
Austin Schuh0ca51f32020-12-25 21:51:45 -0800105 "configuration": {},
Austin Schuh32f68492020-11-08 21:45:51 -0800106 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
107 "parts_uuid": "2a05d725-5d5c-4c0b-af42-88de2f3c3876",
108 "parts_index": 0
109})");
110
111 const aos::SizePrefixedFlatbufferDetachedBuffer<MessageHeader> m1 =
112 JsonToSizedFlatbuffer<MessageHeader>(
113 R"({ "channel_index": 0, "monotonic_sent_time": 100000000 })");
114 const aos::SizePrefixedFlatbufferDetachedBuffer<MessageHeader> m2 =
115 JsonToSizedFlatbuffer<MessageHeader>(
116 R"({ "channel_index": 0, "monotonic_sent_time": 0 })");
117 const aos::SizePrefixedFlatbufferDetachedBuffer<MessageHeader> m3 =
118 JsonToSizedFlatbuffer<MessageHeader>(
119 R"({ "channel_index": 0, "monotonic_sent_time": -1 })");
120
121 {
122 DetachedBufferWriter writer(logfile0, std::make_unique<DummyEncoder>());
Austin Schuhadd6eb32020-11-09 21:24:26 -0800123 writer.QueueSpan(config0.span());
124 writer.QueueSpan(m1.span());
125 writer.QueueSpan(m2.span());
126 writer.QueueSpan(m3.span());
Austin Schuh32f68492020-11-08 21:45:51 -0800127 }
128
129 const std::vector<LogFile> parts = SortParts({logfile0});
130
131 PartsMessageReader reader(parts[0].parts[0]);
132
133 EXPECT_TRUE(reader.ReadMessage());
134 EXPECT_TRUE(reader.ReadMessage());
135 EXPECT_DEATH({ reader.ReadMessage(); }, "-0.000000001sec vs. 0.000000000sec");
136}
137
Austin Schuhc41603c2020-10-11 16:17:37 -0700138// Tests that we can transparently re-assemble part files with a
139// PartsMessageReader.
140TEST(PartsMessageReaderTest, ReadWrite) {
141 const std::string logfile0 = aos::testing::TestTmpDir() + "/log0.bfbs";
142 const std::string logfile1 = aos::testing::TestTmpDir() + "/log1.bfbs";
143 unlink(logfile0.c_str());
144 unlink(logfile1.c_str());
145
146 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config0 =
147 JsonToSizedFlatbuffer<LogFileHeader>(
148 R"({
149 "max_out_of_order_duration": 100000000,
Austin Schuh0ca51f32020-12-25 21:51:45 -0800150 "configuration": {},
Austin Schuhc41603c2020-10-11 16:17:37 -0700151 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
152 "parts_uuid": "2a05d725-5d5c-4c0b-af42-88de2f3c3876",
153 "parts_index": 0
154})");
155 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config1 =
156 JsonToSizedFlatbuffer<LogFileHeader>(
157 R"({
158 "max_out_of_order_duration": 200000000,
159 "monotonic_start_time": 0,
160 "realtime_start_time": 0,
Austin Schuh0ca51f32020-12-25 21:51:45 -0800161 "configuration": {},
Austin Schuhc41603c2020-10-11 16:17:37 -0700162 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
163 "parts_uuid": "2a05d725-5d5c-4c0b-af42-88de2f3c3876",
164 "parts_index": 1
165})");
166
167 const aos::SizePrefixedFlatbufferDetachedBuffer<MessageHeader> m1 =
168 JsonToSizedFlatbuffer<MessageHeader>(
169 R"({ "channel_index": 0, "monotonic_sent_time": 1 })");
170 const aos::SizePrefixedFlatbufferDetachedBuffer<MessageHeader> m2 =
171 JsonToSizedFlatbuffer<MessageHeader>(
172 R"({ "channel_index": 0, "monotonic_sent_time": 2 })");
173
174 {
175 DetachedBufferWriter writer(logfile0, std::make_unique<DummyEncoder>());
Austin Schuhadd6eb32020-11-09 21:24:26 -0800176 writer.QueueSpan(config0.span());
177 writer.QueueSpan(m1.span());
Austin Schuhc41603c2020-10-11 16:17:37 -0700178 }
179 {
180 DetachedBufferWriter writer(logfile1, std::make_unique<DummyEncoder>());
Austin Schuhadd6eb32020-11-09 21:24:26 -0800181 writer.QueueSpan(config1.span());
182 writer.QueueSpan(m2.span());
Austin Schuhc41603c2020-10-11 16:17:37 -0700183 }
184
185 const std::vector<LogFile> parts = SortParts({logfile0, logfile1});
186
187 PartsMessageReader reader(parts[0].parts[0]);
188
189 EXPECT_EQ(reader.filename(), logfile0);
190
191 // Confirm that the timestamps track, and the filename also updates.
192 // Read the first message.
193 EXPECT_EQ(reader.newest_timestamp(), monotonic_clock::min_time);
194 EXPECT_EQ(
195 reader.max_out_of_order_duration(),
196 std::chrono::nanoseconds(config0.message().max_out_of_order_duration()));
197 EXPECT_TRUE(reader.ReadMessage());
198 EXPECT_EQ(reader.filename(), logfile0);
199 EXPECT_EQ(reader.newest_timestamp(),
200 monotonic_clock::time_point(chrono::nanoseconds(1)));
201 EXPECT_EQ(
202 reader.max_out_of_order_duration(),
203 std::chrono::nanoseconds(config0.message().max_out_of_order_duration()));
204
205 // Read the second message.
206 EXPECT_TRUE(reader.ReadMessage());
207 EXPECT_EQ(reader.filename(), logfile1);
208 EXPECT_EQ(reader.newest_timestamp(),
209 monotonic_clock::time_point(chrono::nanoseconds(2)));
210 EXPECT_EQ(
211 reader.max_out_of_order_duration(),
212 std::chrono::nanoseconds(config1.message().max_out_of_order_duration()));
213
214 // And then confirm that reading again returns no message.
215 EXPECT_FALSE(reader.ReadMessage());
216 EXPECT_EQ(reader.filename(), logfile1);
217 EXPECT_EQ(
218 reader.max_out_of_order_duration(),
219 std::chrono::nanoseconds(config1.message().max_out_of_order_duration()));
Austin Schuh32f68492020-11-08 21:45:51 -0800220 EXPECT_EQ(reader.newest_timestamp(), monotonic_clock::max_time);
Austin Schuhc41603c2020-10-11 16:17:37 -0700221}
Austin Schuh32f68492020-11-08 21:45:51 -0800222
Austin Schuh1be0ce42020-11-29 22:43:26 -0800223// Tests that Message's operator < works as expected.
224TEST(MessageTest, Sorting) {
225 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
226
227 Message m1{.channel_index = 0,
Austin Schuh58646e22021-08-23 23:51:46 -0700228 .queue_index = BootQueueIndex{.boot = 0, .index = 0u},
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700229 .timestamp =
230 BootTimestamp{.boot = 0, .time = e + chrono::milliseconds(1)},
Austin Schuh48507722021-07-17 17:29:24 -0700231 .monotonic_remote_boot = 0xffffff,
232 .monotonic_timestamp_boot = 0xffffff,
Austin Schuh1be0ce42020-11-29 22:43:26 -0800233 .data = SizePrefixedFlatbufferVector<MessageHeader>::Empty()};
234 Message m2{.channel_index = 0,
Austin Schuh58646e22021-08-23 23:51:46 -0700235 .queue_index = BootQueueIndex{.boot = 0, .index = 0u},
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700236 .timestamp =
237 BootTimestamp{.boot = 0, .time = e + chrono::milliseconds(2)},
Austin Schuh48507722021-07-17 17:29:24 -0700238 .monotonic_remote_boot = 0xffffff,
239 .monotonic_timestamp_boot = 0xffffff,
Austin Schuh1be0ce42020-11-29 22:43:26 -0800240 .data = SizePrefixedFlatbufferVector<MessageHeader>::Empty()};
241
242 EXPECT_LT(m1, m2);
243 EXPECT_GE(m2, m1);
244
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700245 m1.timestamp.time = e;
246 m2.timestamp.time = e;
Austin Schuh1be0ce42020-11-29 22:43:26 -0800247
248 m1.channel_index = 1;
249 m2.channel_index = 2;
250
251 EXPECT_LT(m1, m2);
252 EXPECT_GE(m2, m1);
253
254 m1.channel_index = 0;
255 m2.channel_index = 0;
Austin Schuh58646e22021-08-23 23:51:46 -0700256 m1.queue_index.index = 0u;
257 m2.queue_index.index = 1u;
Austin Schuh1be0ce42020-11-29 22:43:26 -0800258
259 EXPECT_LT(m1, m2);
260 EXPECT_GE(m2, m1);
261}
262
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800263aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> MakeHeader(
264 const aos::FlatbufferDetachedBuffer<Configuration> &config,
265 const std::string_view json) {
266 flatbuffers::FlatBufferBuilder fbb;
Austin Schuh1034a832021-03-31 21:53:26 -0700267 fbb.ForceDefaults(true);
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800268 flatbuffers::Offset<Configuration> config_offset =
269 aos::CopyFlatBuffer(config, &fbb);
270 LogFileHeader::Builder header_builder(fbb);
271 header_builder.add_configuration(config_offset);
272 fbb.Finish(header_builder.Finish());
273 aos::FlatbufferDetachedBuffer<LogFileHeader> config_header(fbb.Release());
274
275 aos::FlatbufferDetachedBuffer<LogFileHeader> header_updates(
276 JsonToFlatbuffer<LogFileHeader>(json));
277 CHECK(header_updates.Verify());
278 flatbuffers::FlatBufferBuilder fbb2;
Austin Schuh1034a832021-03-31 21:53:26 -0700279 fbb2.ForceDefaults(true);
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800280 fbb2.FinishSizePrefixed(
281 aos::MergeFlatBuffers(config_header, header_updates, &fbb2));
282 return fbb2.Release();
283}
284
285class SortingElementTest : public ::testing::Test {
286 public:
287 SortingElementTest()
288 : config_(JsonToFlatbuffer<Configuration>(
289 R"({
290 "channels": [
291 {
292 "name": "/a",
293 "type": "aos.logger.testing.TestMessage",
294 "source_node": "pi1",
295 "destination_nodes": [
296 {
297 "name": "pi2"
298 },
299 {
300 "name": "pi3"
301 }
302 ]
303 },
304 {
305 "name": "/b",
306 "type": "aos.logger.testing.TestMessage",
307 "source_node": "pi1"
308 },
309 {
310 "name": "/c",
311 "type": "aos.logger.testing.TestMessage",
312 "source_node": "pi1"
Austin Schuh48507722021-07-17 17:29:24 -0700313 },
314 {
315 "name": "/d",
316 "type": "aos.logger.testing.TestMessage",
317 "source_node": "pi2",
318 "destination_nodes": [
319 {
320 "name": "pi1"
321 }
322 ]
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800323 }
324 ],
325 "nodes": [
326 {
327 "name": "pi1"
328 },
329 {
330 "name": "pi2"
331 },
332 {
333 "name": "pi3"
334 }
335 ]
336}
337)")),
338 config0_(MakeHeader(config_, R"({
339 /* 100ms */
340 "max_out_of_order_duration": 100000000,
341 "node": {
342 "name": "pi1"
343 },
344 "logger_node": {
345 "name": "pi1"
346 },
Austin Schuhd2f96102020-12-01 20:27:29 -0800347 "monotonic_start_time": 1000000,
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800348 "realtime_start_time": 1000000000000,
349 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
Austin Schuh48507722021-07-17 17:29:24 -0700350 "source_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
351 "logger_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
352 "boot_uuids": [
353 "1d782c63-b3c7-466e-bea9-a01308b43333",
354 "",
355 ""
356 ],
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800357 "parts_uuid": "2a05d725-5d5c-4c0b-af42-88de2f3c3876",
358 "parts_index": 0
359})")),
360 config1_(MakeHeader(config_,
361 R"({
362 /* 100ms */
363 "max_out_of_order_duration": 100000000,
364 "node": {
365 "name": "pi1"
366 },
367 "logger_node": {
368 "name": "pi1"
369 },
Austin Schuhd2f96102020-12-01 20:27:29 -0800370 "monotonic_start_time": 1000000,
371 "realtime_start_time": 1000000000000,
372 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
Austin Schuh48507722021-07-17 17:29:24 -0700373 "source_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
374 "logger_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
375 "boot_uuids": [
376 "1d782c63-b3c7-466e-bea9-a01308b43333",
377 "",
378 ""
379 ],
Austin Schuhd2f96102020-12-01 20:27:29 -0800380 "parts_uuid": "bafe9f8e-7dea-4bd9-95f5-3d8390e49208",
381 "parts_index": 0
382})")),
383 config2_(MakeHeader(config_,
384 R"({
385 /* 100ms */
386 "max_out_of_order_duration": 100000000,
387 "node": {
388 "name": "pi2"
389 },
390 "logger_node": {
391 "name": "pi2"
392 },
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800393 "monotonic_start_time": 0,
394 "realtime_start_time": 1000000000000,
Austin Schuh48507722021-07-17 17:29:24 -0700395 "source_node_boot_uuid": "6f4269ec-547f-4a1a-8281-37aca7fe5dc2",
396 "logger_node_boot_uuid": "6f4269ec-547f-4a1a-8281-37aca7fe5dc2",
397 "boot_uuids": [
398 "",
399 "6f4269ec-547f-4a1a-8281-37aca7fe5dc2",
400 ""
401 ],
Austin Schuhd2f96102020-12-01 20:27:29 -0800402 "log_event_uuid": "cb89a1ce-c4b6-4747-a647-051f09ac888c",
403 "parts_uuid": "e6bff6c6-757f-4675-90d8-3bfb642870e6",
404 "parts_index": 0
405})")),
406 config3_(MakeHeader(config_,
407 R"({
408 /* 100ms */
409 "max_out_of_order_duration": 100000000,
410 "node": {
411 "name": "pi1"
412 },
413 "logger_node": {
414 "name": "pi1"
415 },
416 "monotonic_start_time": 2000000,
417 "realtime_start_time": 1000000000,
418 "log_event_uuid": "cb26b86a-473e-4f74-8403-50eb92ed60ad",
Austin Schuh48507722021-07-17 17:29:24 -0700419 "source_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
420 "logger_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
421 "boot_uuids": [
422 "1d782c63-b3c7-466e-bea9-a01308b43333",
423 "",
424 ""
425 ],
Austin Schuhd2f96102020-12-01 20:27:29 -0800426 "parts_uuid": "1f098701-949f-4392-81f9-be463e2d7bd4",
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800427 "parts_index": 0
Austin Schuh8bf1e632021-01-02 22:41:04 -0800428})")),
429 config4_(MakeHeader(config_,
430 R"({
431 /* 100ms */
432 "max_out_of_order_duration": 100000000,
433 "node": {
434 "name": "pi2"
435 },
436 "logger_node": {
437 "name": "pi1"
438 },
439 "monotonic_start_time": 2000000,
440 "realtime_start_time": 1000000000,
441 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
442 "parts_uuid": "4e560a47-e2a6-4ce3-a925-490bebc947c5",
Austin Schuh48507722021-07-17 17:29:24 -0700443 "source_node_boot_uuid": "6f4269ec-547f-4a1a-8281-37aca7fe5dc2",
444 "logger_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
445 "boot_uuids": [
446 "1d782c63-b3c7-466e-bea9-a01308b43333",
447 "6f4269ec-547f-4a1a-8281-37aca7fe5dc2",
448 ""
449 ],
Austin Schuh8bf1e632021-01-02 22:41:04 -0800450 "parts_index": 0
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800451})")) {
452 unlink(logfile0_.c_str());
453 unlink(logfile1_.c_str());
Austin Schuhd2f96102020-12-01 20:27:29 -0800454 unlink(logfile2_.c_str());
Austin Schuh48507722021-07-17 17:29:24 -0700455 unlink(logfile3_.c_str());
Austin Schuh921b2562021-07-31 19:37:03 -0700456 queue_index_.resize(config_.message().channels()->size());
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800457 }
458
459 protected:
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800460 flatbuffers::DetachedBuffer MakeLogMessage(
461 const aos::monotonic_clock::time_point monotonic_now, int channel_index,
462 int value) {
463 flatbuffers::FlatBufferBuilder message_fbb;
464 message_fbb.ForceDefaults(true);
465 TestMessage::Builder test_message_builder(message_fbb);
466 test_message_builder.add_value(value);
467 message_fbb.Finish(test_message_builder.Finish());
468
469 aos::Context context;
470 context.monotonic_event_time = monotonic_now;
471 context.realtime_event_time = aos::realtime_clock::epoch() +
472 chrono::seconds(1000) +
473 monotonic_now.time_since_epoch();
Austin Schuh921b2562021-07-31 19:37:03 -0700474 CHECK_LT(static_cast<size_t>(channel_index), queue_index_.size());
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800475 context.queue_index = queue_index_[channel_index];
476 context.size = message_fbb.GetSize();
477 context.data = message_fbb.GetBufferPointer();
478
479 ++queue_index_[channel_index];
480
481 flatbuffers::FlatBufferBuilder fbb;
482 fbb.FinishSizePrefixed(
483 PackMessage(&fbb, context, channel_index, LogType::kLogMessage));
484
485 return fbb.Release();
486 }
487
488 flatbuffers::DetachedBuffer MakeTimestampMessage(
489 const aos::monotonic_clock::time_point sender_monotonic_now,
Austin Schuh8bf1e632021-01-02 22:41:04 -0800490 int channel_index, chrono::nanoseconds receiver_monotonic_offset,
491 monotonic_clock::time_point monotonic_timestamp_time =
492 monotonic_clock::min_time) {
493 const monotonic_clock::time_point monotonic_sent_time =
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800494 sender_monotonic_now + receiver_monotonic_offset;
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800495
496 flatbuffers::FlatBufferBuilder fbb;
Austin Schuh8bf1e632021-01-02 22:41:04 -0800497 fbb.ForceDefaults(true);
498
499 logger::MessageHeader::Builder message_header_builder(fbb);
500
501 message_header_builder.add_channel_index(channel_index);
502
503 message_header_builder.add_queue_index(queue_index_[channel_index] - 1 +
504 100);
505 message_header_builder.add_monotonic_sent_time(
506 monotonic_sent_time.time_since_epoch().count());
507 message_header_builder.add_realtime_sent_time(
508 (aos::realtime_clock::epoch() + chrono::seconds(1000) +
509 monotonic_sent_time.time_since_epoch())
510 .time_since_epoch()
511 .count());
512
513 message_header_builder.add_monotonic_remote_time(
514 sender_monotonic_now.time_since_epoch().count());
515 message_header_builder.add_realtime_remote_time(
516 (aos::realtime_clock::epoch() + chrono::seconds(1000) +
517 sender_monotonic_now.time_since_epoch())
518 .time_since_epoch()
519 .count());
520 message_header_builder.add_remote_queue_index(queue_index_[channel_index] -
521 1);
522
523 if (monotonic_timestamp_time != monotonic_clock::min_time) {
524 message_header_builder.add_monotonic_timestamp_time(
525 monotonic_timestamp_time.time_since_epoch().count());
526 }
527
528 fbb.FinishSizePrefixed(message_header_builder.Finish());
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800529 LOG(INFO) << aos::FlatbufferToJson(
530 aos::SizePrefixedFlatbufferSpan<MessageHeader>(
531 absl::Span<uint8_t>(fbb.GetBufferPointer(), fbb.GetSize())));
532
533 return fbb.Release();
534 }
535
536 const std::string logfile0_ = aos::testing::TestTmpDir() + "/log0.bfbs";
537 const std::string logfile1_ = aos::testing::TestTmpDir() + "/log1.bfbs";
Austin Schuhd2f96102020-12-01 20:27:29 -0800538 const std::string logfile2_ = aos::testing::TestTmpDir() + "/log2.bfbs";
Austin Schuh48507722021-07-17 17:29:24 -0700539 const std::string logfile3_ = aos::testing::TestTmpDir() + "/log3.bfbs";
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800540
541 const aos::FlatbufferDetachedBuffer<Configuration> config_;
542 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config0_;
543 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config1_;
Austin Schuhd2f96102020-12-01 20:27:29 -0800544 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config2_;
545 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config3_;
Austin Schuh8bf1e632021-01-02 22:41:04 -0800546 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> config4_;
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800547
548 std::vector<uint32_t> queue_index_;
549};
550
551using LogPartsSorterTest = SortingElementTest;
552using LogPartsSorterDeathTest = LogPartsSorterTest;
Austin Schuh8f52ed52020-11-30 23:12:39 -0800553using NodeMergerTest = SortingElementTest;
Austin Schuhd2f96102020-12-01 20:27:29 -0800554using TimestampMapperTest = SortingElementTest;
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800555
556// Tests that we can pull messages out of a log sorted in order.
557TEST_F(LogPartsSorterTest, Pull) {
558 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
559 {
560 DetachedBufferWriter writer(logfile0_, std::make_unique<DummyEncoder>());
561 writer.QueueSpan(config0_.span());
562 writer.QueueSizedFlatbuffer(
563 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
564 writer.QueueSizedFlatbuffer(
565 MakeLogMessage(e + chrono::milliseconds(1000), 1, 0x105));
566 writer.QueueSizedFlatbuffer(
567 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
568 writer.QueueSizedFlatbuffer(
569 MakeLogMessage(e + chrono::milliseconds(1901), 1, 0x107));
570 }
571
572 const std::vector<LogFile> parts = SortParts({logfile0_});
573
574 LogPartsSorter parts_sorter(parts[0].parts[0]);
575
576 // Confirm we aren't sorted until any time until the message is popped.
577 // Peeking shouldn't change the sorted until time.
578 EXPECT_EQ(parts_sorter.sorted_until(), monotonic_clock::min_time);
579
580 std::deque<Message> output;
581
582 ASSERT_TRUE(parts_sorter.Front() != nullptr);
583 output.emplace_back(std::move(*parts_sorter.Front()));
584 parts_sorter.PopFront();
585 EXPECT_EQ(parts_sorter.sorted_until(), e + chrono::milliseconds(1900));
586
587 ASSERT_TRUE(parts_sorter.Front() != nullptr);
588 output.emplace_back(std::move(*parts_sorter.Front()));
589 parts_sorter.PopFront();
590 EXPECT_EQ(parts_sorter.sorted_until(), e + chrono::milliseconds(1900));
591
592 ASSERT_TRUE(parts_sorter.Front() != nullptr);
593 output.emplace_back(std::move(*parts_sorter.Front()));
594 parts_sorter.PopFront();
595 EXPECT_EQ(parts_sorter.sorted_until(), monotonic_clock::max_time);
596
597 ASSERT_TRUE(parts_sorter.Front() != nullptr);
598 output.emplace_back(std::move(*parts_sorter.Front()));
599 parts_sorter.PopFront();
600 EXPECT_EQ(parts_sorter.sorted_until(), monotonic_clock::max_time);
601
602 ASSERT_TRUE(parts_sorter.Front() == nullptr);
603
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700604 EXPECT_EQ(output[0].timestamp.boot, 0);
605 EXPECT_EQ(output[0].timestamp.time, e + chrono::milliseconds(1000));
606 EXPECT_EQ(output[1].timestamp.boot, 0);
607 EXPECT_EQ(output[1].timestamp.time, e + chrono::milliseconds(1000));
608 EXPECT_EQ(output[2].timestamp.boot, 0);
609 EXPECT_EQ(output[2].timestamp.time, e + chrono::milliseconds(1901));
610 EXPECT_EQ(output[3].timestamp.boot, 0);
611 EXPECT_EQ(output[3].timestamp.time, e + chrono::milliseconds(2000));
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800612}
613
Austin Schuhb000de62020-12-03 22:00:40 -0800614// Tests that we can pull messages out of a log sorted in order.
615TEST_F(LogPartsSorterTest, WayBeforeStart) {
616 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
617 {
618 DetachedBufferWriter writer(logfile0_, std::make_unique<DummyEncoder>());
619 writer.QueueSpan(config0_.span());
620 writer.QueueSizedFlatbuffer(
621 MakeLogMessage(e - chrono::milliseconds(500), 0, 0x005));
622 writer.QueueSizedFlatbuffer(
623 MakeLogMessage(e - chrono::milliseconds(10), 2, 0x005));
624 writer.QueueSizedFlatbuffer(
625 MakeLogMessage(e - chrono::milliseconds(1000), 1, 0x105));
626 writer.QueueSizedFlatbuffer(
627 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
628 writer.QueueSizedFlatbuffer(
629 MakeLogMessage(e + chrono::milliseconds(1901), 1, 0x107));
630 }
631
632 const std::vector<LogFile> parts = SortParts({logfile0_});
633
634 LogPartsSorter parts_sorter(parts[0].parts[0]);
635
636 // Confirm we aren't sorted until any time until the message is popped.
637 // Peeking shouldn't change the sorted until time.
638 EXPECT_EQ(parts_sorter.sorted_until(), monotonic_clock::min_time);
639
640 std::deque<Message> output;
641
642 for (monotonic_clock::time_point t :
643 {e + chrono::milliseconds(1900), e + chrono::milliseconds(1900),
644 e + chrono::milliseconds(1900), monotonic_clock::max_time,
645 monotonic_clock::max_time}) {
646 ASSERT_TRUE(parts_sorter.Front() != nullptr);
647 output.emplace_back(std::move(*parts_sorter.Front()));
648 parts_sorter.PopFront();
649 EXPECT_EQ(parts_sorter.sorted_until(), t);
650 }
651
652 ASSERT_TRUE(parts_sorter.Front() == nullptr);
653
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700654 EXPECT_EQ(output[0].timestamp.boot, 0u);
655 EXPECT_EQ(output[0].timestamp.time, e - chrono::milliseconds(1000));
656 EXPECT_EQ(output[1].timestamp.boot, 0u);
657 EXPECT_EQ(output[1].timestamp.time, e - chrono::milliseconds(500));
658 EXPECT_EQ(output[2].timestamp.boot, 0u);
659 EXPECT_EQ(output[2].timestamp.time, e - chrono::milliseconds(10));
660 EXPECT_EQ(output[3].timestamp.boot, 0u);
661 EXPECT_EQ(output[3].timestamp.time, e + chrono::milliseconds(1901));
662 EXPECT_EQ(output[4].timestamp.boot, 0u);
663 EXPECT_EQ(output[4].timestamp.time, e + chrono::milliseconds(2000));
Austin Schuhb000de62020-12-03 22:00:40 -0800664}
665
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800666// Tests that messages too far out of order trigger death.
667TEST_F(LogPartsSorterDeathTest, Pull) {
668 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
669 {
670 DetachedBufferWriter writer(logfile0_, std::make_unique<DummyEncoder>());
671 writer.QueueSpan(config0_.span());
672 writer.QueueSizedFlatbuffer(
673 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
674 writer.QueueSizedFlatbuffer(
675 MakeLogMessage(e + chrono::milliseconds(1000), 1, 0x105));
676 writer.QueueSizedFlatbuffer(
677 MakeLogMessage(e + chrono::milliseconds(2001), 0, 0x006));
678 // The following message is too far out of order and will trigger the CHECK.
679 writer.QueueSizedFlatbuffer(
680 MakeLogMessage(e + chrono::milliseconds(1900), 1, 0x107));
681 }
682
683 const std::vector<LogFile> parts = SortParts({logfile0_});
684
685 LogPartsSorter parts_sorter(parts[0].parts[0]);
686
687 // Confirm we aren't sorted until any time until the message is popped.
688 // Peeking shouldn't change the sorted until time.
689 EXPECT_EQ(parts_sorter.sorted_until(), monotonic_clock::min_time);
690 std::deque<Message> output;
691
692 ASSERT_TRUE(parts_sorter.Front() != nullptr);
693 parts_sorter.PopFront();
694 ASSERT_TRUE(parts_sorter.Front() != nullptr);
695 ASSERT_TRUE(parts_sorter.Front() != nullptr);
696 parts_sorter.PopFront();
697
Austin Schuh58646e22021-08-23 23:51:46 -0700698 EXPECT_DEATH({ parts_sorter.Front(); },
699 "Max out of order of 100000000ns exceeded.");
Austin Schuh4b5c22a2020-11-30 22:58:43 -0800700}
701
Austin Schuh8f52ed52020-11-30 23:12:39 -0800702// Tests that we can merge data from 2 separate files, including duplicate data.
703TEST_F(NodeMergerTest, TwoFileMerger) {
704 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
705 {
706 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
707 writer0.QueueSpan(config0_.span());
708 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
709 writer1.QueueSpan(config1_.span());
710
711 writer0.QueueSizedFlatbuffer(
712 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
713 writer1.QueueSizedFlatbuffer(
714 MakeLogMessage(e + chrono::milliseconds(1001), 1, 0x105));
715
716 writer0.QueueSizedFlatbuffer(
717 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
718 writer1.QueueSizedFlatbuffer(
719 MakeLogMessage(e + chrono::milliseconds(1002), 1, 0x106));
720
721 // Make a duplicate!
722 SizePrefixedFlatbufferDetachedBuffer<MessageHeader> msg(
723 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
724 writer0.QueueSpan(msg.span());
725 writer1.QueueSpan(msg.span());
726
727 writer1.QueueSizedFlatbuffer(
728 MakeLogMessage(e + chrono::milliseconds(3002), 1, 0x107));
729 }
730
731 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
Austin Schuhd2f96102020-12-01 20:27:29 -0800732 ASSERT_EQ(parts.size(), 1u);
Austin Schuh8f52ed52020-11-30 23:12:39 -0800733
Austin Schuhd2f96102020-12-01 20:27:29 -0800734 NodeMerger merger(FilterPartsForNode(parts, "pi1"));
Austin Schuh8f52ed52020-11-30 23:12:39 -0800735
736 EXPECT_EQ(merger.sorted_until(), monotonic_clock::min_time);
737
738 std::deque<Message> output;
739
740 EXPECT_EQ(merger.sorted_until(), monotonic_clock::min_time);
741 ASSERT_TRUE(merger.Front() != nullptr);
742 EXPECT_EQ(merger.sorted_until(), e + chrono::milliseconds(1900));
743
744 output.emplace_back(std::move(*merger.Front()));
745 merger.PopFront();
746 EXPECT_EQ(merger.sorted_until(), e + chrono::milliseconds(1900));
747
748 ASSERT_TRUE(merger.Front() != nullptr);
749 output.emplace_back(std::move(*merger.Front()));
750 merger.PopFront();
751 EXPECT_EQ(merger.sorted_until(), e + chrono::milliseconds(2900));
752
753 ASSERT_TRUE(merger.Front() != nullptr);
754 output.emplace_back(std::move(*merger.Front()));
755 merger.PopFront();
756 EXPECT_EQ(merger.sorted_until(), e + chrono::milliseconds(2900));
757
758 ASSERT_TRUE(merger.Front() != nullptr);
759 output.emplace_back(std::move(*merger.Front()));
760 merger.PopFront();
761 EXPECT_EQ(merger.sorted_until(), e + chrono::milliseconds(2900));
762
763 ASSERT_TRUE(merger.Front() != nullptr);
764 output.emplace_back(std::move(*merger.Front()));
765 merger.PopFront();
766 EXPECT_EQ(merger.sorted_until(), monotonic_clock::max_time);
767
768 ASSERT_TRUE(merger.Front() != nullptr);
769 output.emplace_back(std::move(*merger.Front()));
770 merger.PopFront();
771 EXPECT_EQ(merger.sorted_until(), monotonic_clock::max_time);
772
773 ASSERT_TRUE(merger.Front() == nullptr);
774
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700775 EXPECT_EQ(output[0].timestamp.boot, 0u);
776 EXPECT_EQ(output[0].timestamp.time, e + chrono::milliseconds(1000));
777 EXPECT_EQ(output[1].timestamp.boot, 0u);
778 EXPECT_EQ(output[1].timestamp.time, e + chrono::milliseconds(1001));
779 EXPECT_EQ(output[2].timestamp.boot, 0u);
780 EXPECT_EQ(output[2].timestamp.time, e + chrono::milliseconds(1002));
781 EXPECT_EQ(output[3].timestamp.boot, 0u);
782 EXPECT_EQ(output[3].timestamp.time, e + chrono::milliseconds(2000));
783 EXPECT_EQ(output[4].timestamp.boot, 0u);
784 EXPECT_EQ(output[4].timestamp.time, e + chrono::milliseconds(3000));
785 EXPECT_EQ(output[5].timestamp.boot, 0u);
786 EXPECT_EQ(output[5].timestamp.time, e + chrono::milliseconds(3002));
Austin Schuh8f52ed52020-11-30 23:12:39 -0800787}
788
Austin Schuh8bf1e632021-01-02 22:41:04 -0800789// Tests that we can merge timestamps with various combinations of
790// monotonic_timestamp_time.
791TEST_F(NodeMergerTest, TwoFileTimestampMerger) {
792 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
793 {
794 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
795 writer0.QueueSpan(config0_.span());
796 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
797 writer1.QueueSpan(config1_.span());
798
799 // Neither has it.
800 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005);
801 writer0.QueueSizedFlatbuffer(MakeTimestampMessage(
802 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
803 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
804 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
805
806 // First only has it.
807 MakeLogMessage(e + chrono::milliseconds(1001), 0, 0x006);
808 writer0.QueueSizedFlatbuffer(MakeTimestampMessage(
809 e + chrono::milliseconds(1001), 0, chrono::seconds(100),
810 e + chrono::nanoseconds(971)));
811 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
812 e + chrono::milliseconds(1001), 0, chrono::seconds(100)));
813
814 // Second only has it.
815 MakeLogMessage(e + chrono::milliseconds(1002), 0, 0x007);
816 writer0.QueueSizedFlatbuffer(MakeTimestampMessage(
817 e + chrono::milliseconds(1002), 0, chrono::seconds(100)));
818 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
819 e + chrono::milliseconds(1002), 0, chrono::seconds(100),
820 e + chrono::nanoseconds(972)));
821
822 // Both have it.
823 MakeLogMessage(e + chrono::milliseconds(1003), 0, 0x008);
824 writer0.QueueSizedFlatbuffer(MakeTimestampMessage(
825 e + chrono::milliseconds(1003), 0, chrono::seconds(100),
826 e + chrono::nanoseconds(973)));
827 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
828 e + chrono::milliseconds(1003), 0, chrono::seconds(100),
829 e + chrono::nanoseconds(973)));
830 }
831
832 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
833 ASSERT_EQ(parts.size(), 1u);
834
835 NodeMerger merger(FilterPartsForNode(parts, "pi1"));
836
837 EXPECT_EQ(merger.sorted_until(), monotonic_clock::min_time);
838
839 std::deque<Message> output;
840
841 for (int i = 0; i < 4; ++i) {
842 ASSERT_TRUE(merger.Front() != nullptr);
843 output.emplace_back(std::move(*merger.Front()));
844 merger.PopFront();
845 }
846 ASSERT_TRUE(merger.Front() == nullptr);
847
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700848 EXPECT_EQ(output[0].timestamp.boot, 0u);
849 EXPECT_EQ(output[0].timestamp.time, e + chrono::milliseconds(101000));
Austin Schuh8bf1e632021-01-02 22:41:04 -0800850 EXPECT_FALSE(output[0].data.message().has_monotonic_timestamp_time());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700851
852 EXPECT_EQ(output[1].timestamp.boot, 0u);
853 EXPECT_EQ(output[1].timestamp.time, e + chrono::milliseconds(101001));
Austin Schuh8bf1e632021-01-02 22:41:04 -0800854 EXPECT_TRUE(output[1].data.message().has_monotonic_timestamp_time());
855 EXPECT_EQ(output[1].data.message().monotonic_timestamp_time(), 971);
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700856
857 EXPECT_EQ(output[2].timestamp.boot, 0u);
858 EXPECT_EQ(output[2].timestamp.time, e + chrono::milliseconds(101002));
Austin Schuh8bf1e632021-01-02 22:41:04 -0800859 EXPECT_TRUE(output[2].data.message().has_monotonic_timestamp_time());
860 EXPECT_EQ(output[2].data.message().monotonic_timestamp_time(), 972);
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700861
862 EXPECT_EQ(output[3].timestamp.boot, 0u);
863 EXPECT_EQ(output[3].timestamp.time, e + chrono::milliseconds(101003));
Austin Schuh8bf1e632021-01-02 22:41:04 -0800864 EXPECT_TRUE(output[3].data.message().has_monotonic_timestamp_time());
865 EXPECT_EQ(output[3].data.message().monotonic_timestamp_time(), 973);
866}
867
Austin Schuhd2f96102020-12-01 20:27:29 -0800868// Tests that we can match timestamps on delivered messages.
869TEST_F(TimestampMapperTest, ReadNode0First) {
870 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
871 {
872 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
873 writer0.QueueSpan(config0_.span());
874 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
875 writer1.QueueSpan(config2_.span());
876
877 writer0.QueueSizedFlatbuffer(
878 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
879 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
880 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
881
882 writer0.QueueSizedFlatbuffer(
883 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
884 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
885 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
886
887 writer0.QueueSizedFlatbuffer(
888 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
889 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
890 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
891 }
892
893 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
894
895 ASSERT_EQ(parts[0].logger_node, "pi1");
896 ASSERT_EQ(parts[1].logger_node, "pi2");
897
Austin Schuh79b30942021-01-24 22:32:21 -0800898 size_t mapper0_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -0800899 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -0800900 mapper0.set_timestamp_callback(
901 [&](TimestampedMessage *) { ++mapper0_count; });
902 size_t mapper1_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -0800903 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -0800904 mapper1.set_timestamp_callback(
905 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuhd2f96102020-12-01 20:27:29 -0800906
907 mapper0.AddPeer(&mapper1);
908 mapper1.AddPeer(&mapper0);
909
910 {
911 std::deque<TimestampedMessage> output0;
912
Austin Schuh79b30942021-01-24 22:32:21 -0800913 EXPECT_EQ(mapper0_count, 0u);
914 EXPECT_EQ(mapper1_count, 0u);
Austin Schuhd2f96102020-12-01 20:27:29 -0800915 ASSERT_TRUE(mapper0.Front() != nullptr);
Austin Schuh79b30942021-01-24 22:32:21 -0800916 EXPECT_EQ(mapper0_count, 1u);
917 EXPECT_EQ(mapper1_count, 0u);
Austin Schuhd2f96102020-12-01 20:27:29 -0800918 output0.emplace_back(std::move(*mapper0.Front()));
919 mapper0.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -0700920 EXPECT_TRUE(mapper0.started());
Austin Schuh79b30942021-01-24 22:32:21 -0800921 EXPECT_EQ(mapper0_count, 1u);
922 EXPECT_EQ(mapper1_count, 0u);
Austin Schuhd2f96102020-12-01 20:27:29 -0800923
924 ASSERT_TRUE(mapper0.Front() != nullptr);
Austin Schuh79b30942021-01-24 22:32:21 -0800925 EXPECT_EQ(mapper0_count, 2u);
926 EXPECT_EQ(mapper1_count, 0u);
Austin Schuhd2f96102020-12-01 20:27:29 -0800927 output0.emplace_back(std::move(*mapper0.Front()));
928 mapper0.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -0700929 EXPECT_TRUE(mapper0.started());
Austin Schuhd2f96102020-12-01 20:27:29 -0800930
931 ASSERT_TRUE(mapper0.Front() != nullptr);
932 output0.emplace_back(std::move(*mapper0.Front()));
933 mapper0.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -0700934 EXPECT_TRUE(mapper0.started());
Austin Schuhd2f96102020-12-01 20:27:29 -0800935
Austin Schuh79b30942021-01-24 22:32:21 -0800936 EXPECT_EQ(mapper0_count, 3u);
937 EXPECT_EQ(mapper1_count, 0u);
938
Austin Schuhd2f96102020-12-01 20:27:29 -0800939 ASSERT_TRUE(mapper0.Front() == nullptr);
940
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700941 EXPECT_EQ(output0[0].monotonic_event_time.boot, 0u);
942 EXPECT_EQ(output0[0].monotonic_event_time.time,
943 e + chrono::milliseconds(1000));
Austin Schuhd2f96102020-12-01 20:27:29 -0800944 EXPECT_TRUE(output0[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700945
946 EXPECT_EQ(output0[1].monotonic_event_time.boot, 0u);
947 EXPECT_EQ(output0[1].monotonic_event_time.time,
948 e + chrono::milliseconds(2000));
Austin Schuhd2f96102020-12-01 20:27:29 -0800949 EXPECT_TRUE(output0[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700950
951 EXPECT_EQ(output0[2].monotonic_event_time.boot, 0u);
952 EXPECT_EQ(output0[2].monotonic_event_time.time,
953 e + chrono::milliseconds(3000));
Austin Schuhd2f96102020-12-01 20:27:29 -0800954 EXPECT_TRUE(output0[2].data.Verify());
955 }
956
957 {
958 SCOPED_TRACE("Trying node1 now");
959 std::deque<TimestampedMessage> output1;
960
Austin Schuh79b30942021-01-24 22:32:21 -0800961 EXPECT_EQ(mapper0_count, 3u);
962 EXPECT_EQ(mapper1_count, 0u);
963
Austin Schuhd2f96102020-12-01 20:27:29 -0800964 ASSERT_TRUE(mapper1.Front() != nullptr);
Austin Schuh79b30942021-01-24 22:32:21 -0800965 EXPECT_EQ(mapper0_count, 3u);
966 EXPECT_EQ(mapper1_count, 1u);
Austin Schuhd2f96102020-12-01 20:27:29 -0800967 output1.emplace_back(std::move(*mapper1.Front()));
968 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -0700969 EXPECT_TRUE(mapper1.started());
Austin Schuh79b30942021-01-24 22:32:21 -0800970 EXPECT_EQ(mapper0_count, 3u);
971 EXPECT_EQ(mapper1_count, 1u);
Austin Schuhd2f96102020-12-01 20:27:29 -0800972
973 ASSERT_TRUE(mapper1.Front() != nullptr);
Austin Schuh79b30942021-01-24 22:32:21 -0800974 EXPECT_EQ(mapper0_count, 3u);
975 EXPECT_EQ(mapper1_count, 2u);
Austin Schuhd2f96102020-12-01 20:27:29 -0800976 output1.emplace_back(std::move(*mapper1.Front()));
977 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -0700978 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -0800979
980 ASSERT_TRUE(mapper1.Front() != nullptr);
981 output1.emplace_back(std::move(*mapper1.Front()));
982 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -0700983 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -0800984
Austin Schuh79b30942021-01-24 22:32:21 -0800985 EXPECT_EQ(mapper0_count, 3u);
986 EXPECT_EQ(mapper1_count, 3u);
987
Austin Schuhd2f96102020-12-01 20:27:29 -0800988 ASSERT_TRUE(mapper1.Front() == nullptr);
989
Austin Schuh79b30942021-01-24 22:32:21 -0800990 EXPECT_EQ(mapper0_count, 3u);
991 EXPECT_EQ(mapper1_count, 3u);
992
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700993 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
994 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -0800995 e + chrono::seconds(100) + chrono::milliseconds(1000));
996 EXPECT_TRUE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -0700997
998 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
999 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001000 e + chrono::seconds(100) + chrono::milliseconds(2000));
1001 EXPECT_TRUE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001002
1003 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1004 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001005 e + chrono::seconds(100) + chrono::milliseconds(3000));
1006 EXPECT_TRUE(output1[2].data.Verify());
1007 }
1008}
1009
Austin Schuh8bf1e632021-01-02 22:41:04 -08001010// Tests that a MessageHeader with monotonic_timestamp_time set gets properly
1011// returned.
1012TEST_F(TimestampMapperTest, MessageWithTimestampTime) {
1013 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1014 {
1015 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1016 writer0.QueueSpan(config0_.span());
1017 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1018 writer1.QueueSpan(config4_.span());
1019
1020 writer0.QueueSizedFlatbuffer(
1021 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
1022 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1023 e + chrono::milliseconds(1000), 0, chrono::seconds(100),
1024 e + chrono::nanoseconds(971)));
1025
1026 writer0.QueueSizedFlatbuffer(
1027 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
1028 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1029 e + chrono::milliseconds(2000), 0, chrono::seconds(100),
1030 e + chrono::nanoseconds(5458)));
1031
1032 writer0.QueueSizedFlatbuffer(
1033 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
1034 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1035 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1036 }
1037
1038 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1039
1040 for (const auto &p : parts) {
1041 LOG(INFO) << p;
1042 }
1043
1044 ASSERT_EQ(parts.size(), 1u);
1045
Austin Schuh79b30942021-01-24 22:32:21 -08001046 size_t mapper0_count = 0;
Austin Schuh8bf1e632021-01-02 22:41:04 -08001047 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -08001048 mapper0.set_timestamp_callback(
1049 [&](TimestampedMessage *) { ++mapper0_count; });
1050 size_t mapper1_count = 0;
Austin Schuh8bf1e632021-01-02 22:41:04 -08001051 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -08001052 mapper1.set_timestamp_callback(
1053 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuh8bf1e632021-01-02 22:41:04 -08001054
1055 mapper0.AddPeer(&mapper1);
1056 mapper1.AddPeer(&mapper0);
1057
1058 {
1059 std::deque<TimestampedMessage> output0;
1060
1061 for (int i = 0; i < 3; ++i) {
1062 ASSERT_TRUE(mapper0.Front() != nullptr) << ": " << i;
1063 output0.emplace_back(std::move(*mapper0.Front()));
1064 mapper0.PopFront();
1065 }
1066
1067 ASSERT_TRUE(mapper0.Front() == nullptr);
1068
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001069 EXPECT_EQ(output0[0].monotonic_event_time.boot, 0u);
1070 EXPECT_EQ(output0[0].monotonic_event_time.time,
1071 e + chrono::milliseconds(1000));
1072 EXPECT_EQ(output0[0].monotonic_timestamp_time.boot, 0u);
1073 EXPECT_EQ(output0[0].monotonic_timestamp_time.time,
1074 monotonic_clock::min_time);
Austin Schuh8bf1e632021-01-02 22:41:04 -08001075 EXPECT_TRUE(output0[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001076
1077 EXPECT_EQ(output0[1].monotonic_event_time.boot, 0u);
1078 EXPECT_EQ(output0[1].monotonic_event_time.time,
1079 e + chrono::milliseconds(2000));
1080 EXPECT_EQ(output0[1].monotonic_timestamp_time.boot, 0u);
1081 EXPECT_EQ(output0[1].monotonic_timestamp_time.time,
1082 monotonic_clock::min_time);
Austin Schuh8bf1e632021-01-02 22:41:04 -08001083 EXPECT_TRUE(output0[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001084
1085 EXPECT_EQ(output0[2].monotonic_event_time.boot, 0u);
1086 EXPECT_EQ(output0[2].monotonic_event_time.time,
1087 e + chrono::milliseconds(3000));
1088 EXPECT_EQ(output0[2].monotonic_timestamp_time.boot, 0u);
1089 EXPECT_EQ(output0[2].monotonic_timestamp_time.time,
1090 monotonic_clock::min_time);
Austin Schuh8bf1e632021-01-02 22:41:04 -08001091 EXPECT_TRUE(output0[2].data.Verify());
1092 }
1093
1094 {
1095 SCOPED_TRACE("Trying node1 now");
1096 std::deque<TimestampedMessage> output1;
1097
1098 for (int i = 0; i < 3; ++i) {
1099 ASSERT_TRUE(mapper1.Front() != nullptr);
1100 output1.emplace_back(std::move(*mapper1.Front()));
1101 mapper1.PopFront();
1102 }
1103
1104 ASSERT_TRUE(mapper1.Front() == nullptr);
1105
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001106 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1107 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuh8bf1e632021-01-02 22:41:04 -08001108 e + chrono::seconds(100) + chrono::milliseconds(1000));
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001109 EXPECT_EQ(output1[0].monotonic_timestamp_time.boot, 0u);
1110 EXPECT_EQ(output1[0].monotonic_timestamp_time.time,
Austin Schuh8bf1e632021-01-02 22:41:04 -08001111 e + chrono::nanoseconds(971));
1112 EXPECT_TRUE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001113
1114 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1115 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuh8bf1e632021-01-02 22:41:04 -08001116 e + chrono::seconds(100) + chrono::milliseconds(2000));
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001117 EXPECT_EQ(output1[1].monotonic_timestamp_time.boot, 0u);
1118 EXPECT_EQ(output1[1].monotonic_timestamp_time.time,
Austin Schuh8bf1e632021-01-02 22:41:04 -08001119 e + chrono::nanoseconds(5458));
1120 EXPECT_TRUE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001121
1122 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1123 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuh8bf1e632021-01-02 22:41:04 -08001124 e + chrono::seconds(100) + chrono::milliseconds(3000));
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001125 EXPECT_EQ(output1[2].monotonic_timestamp_time.boot, 0u);
1126 EXPECT_EQ(output1[2].monotonic_timestamp_time.time,
1127 monotonic_clock::min_time);
Austin Schuh8bf1e632021-01-02 22:41:04 -08001128 EXPECT_TRUE(output1[2].data.Verify());
1129 }
Austin Schuh79b30942021-01-24 22:32:21 -08001130
1131 EXPECT_EQ(mapper0_count, 3u);
1132 EXPECT_EQ(mapper1_count, 3u);
Austin Schuh8bf1e632021-01-02 22:41:04 -08001133}
1134
Austin Schuhd2f96102020-12-01 20:27:29 -08001135// Tests that we can match timestamps on delivered messages. By doing this in
1136// the reverse order, the second node needs to queue data up from the first node
1137// to find the matching timestamp.
1138TEST_F(TimestampMapperTest, ReadNode1First) {
1139 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1140 {
1141 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1142 writer0.QueueSpan(config0_.span());
1143 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1144 writer1.QueueSpan(config2_.span());
1145
1146 writer0.QueueSizedFlatbuffer(
1147 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
1148 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1149 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1150
1151 writer0.QueueSizedFlatbuffer(
1152 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
1153 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1154 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
1155
1156 writer0.QueueSizedFlatbuffer(
1157 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
1158 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1159 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1160 }
1161
1162 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1163
1164 ASSERT_EQ(parts[0].logger_node, "pi1");
1165 ASSERT_EQ(parts[1].logger_node, "pi2");
1166
Austin Schuh79b30942021-01-24 22:32:21 -08001167 size_t mapper0_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001168 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -08001169 mapper0.set_timestamp_callback(
1170 [&](TimestampedMessage *) { ++mapper0_count; });
1171 size_t mapper1_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001172 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -08001173 mapper1.set_timestamp_callback(
1174 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuhd2f96102020-12-01 20:27:29 -08001175
1176 mapper0.AddPeer(&mapper1);
1177 mapper1.AddPeer(&mapper0);
1178
1179 {
1180 SCOPED_TRACE("Trying node1 now");
1181 std::deque<TimestampedMessage> output1;
1182
1183 ASSERT_TRUE(mapper1.Front() != nullptr);
1184 output1.emplace_back(std::move(*mapper1.Front()));
1185 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001186 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001187
1188 ASSERT_TRUE(mapper1.Front() != nullptr);
1189 output1.emplace_back(std::move(*mapper1.Front()));
1190 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001191 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001192
1193 ASSERT_TRUE(mapper1.Front() != nullptr);
1194 output1.emplace_back(std::move(*mapper1.Front()));
1195 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001196 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001197
1198 ASSERT_TRUE(mapper1.Front() == nullptr);
1199
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001200 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1201 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001202 e + chrono::seconds(100) + chrono::milliseconds(1000));
1203 EXPECT_TRUE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001204
1205 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1206 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001207 e + chrono::seconds(100) + chrono::milliseconds(2000));
1208 EXPECT_TRUE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001209
1210 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1211 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001212 e + chrono::seconds(100) + chrono::milliseconds(3000));
1213 EXPECT_TRUE(output1[2].data.Verify());
1214 }
1215
1216 {
1217 std::deque<TimestampedMessage> output0;
1218
1219 ASSERT_TRUE(mapper0.Front() != nullptr);
1220 output0.emplace_back(std::move(*mapper0.Front()));
1221 mapper0.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001222 EXPECT_TRUE(mapper0.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001223
1224 ASSERT_TRUE(mapper0.Front() != nullptr);
1225 output0.emplace_back(std::move(*mapper0.Front()));
1226 mapper0.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001227 EXPECT_TRUE(mapper0.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001228
1229 ASSERT_TRUE(mapper0.Front() != nullptr);
1230 output0.emplace_back(std::move(*mapper0.Front()));
1231 mapper0.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001232 EXPECT_TRUE(mapper0.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001233
1234 ASSERT_TRUE(mapper0.Front() == nullptr);
1235
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001236 EXPECT_EQ(output0[0].monotonic_event_time.boot, 0u);
1237 EXPECT_EQ(output0[0].monotonic_event_time.time,
1238 e + chrono::milliseconds(1000));
Austin Schuhd2f96102020-12-01 20:27:29 -08001239 EXPECT_TRUE(output0[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001240
1241 EXPECT_EQ(output0[1].monotonic_event_time.boot, 0u);
1242 EXPECT_EQ(output0[1].monotonic_event_time.time,
1243 e + chrono::milliseconds(2000));
Austin Schuhd2f96102020-12-01 20:27:29 -08001244 EXPECT_TRUE(output0[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001245
1246 EXPECT_EQ(output0[2].monotonic_event_time.boot, 0u);
1247 EXPECT_EQ(output0[2].monotonic_event_time.time,
1248 e + chrono::milliseconds(3000));
Austin Schuhd2f96102020-12-01 20:27:29 -08001249 EXPECT_TRUE(output0[2].data.Verify());
1250 }
Austin Schuh79b30942021-01-24 22:32:21 -08001251
1252 EXPECT_EQ(mapper0_count, 3u);
1253 EXPECT_EQ(mapper1_count, 3u);
Austin Schuhd2f96102020-12-01 20:27:29 -08001254}
1255
1256// Tests that we return just the timestamps if we couldn't find the data and the
1257// missing data was at the beginning of the file.
1258TEST_F(TimestampMapperTest, ReadMissingDataBefore) {
1259 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1260 {
1261 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1262 writer0.QueueSpan(config0_.span());
1263 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1264 writer1.QueueSpan(config2_.span());
1265
1266 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005);
1267 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1268 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1269
1270 writer0.QueueSizedFlatbuffer(
1271 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
1272 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1273 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
1274
1275 writer0.QueueSizedFlatbuffer(
1276 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
1277 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1278 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1279 }
1280
1281 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1282
1283 ASSERT_EQ(parts[0].logger_node, "pi1");
1284 ASSERT_EQ(parts[1].logger_node, "pi2");
1285
Austin Schuh79b30942021-01-24 22:32:21 -08001286 size_t mapper0_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001287 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -08001288 mapper0.set_timestamp_callback(
1289 [&](TimestampedMessage *) { ++mapper0_count; });
1290 size_t mapper1_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001291 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -08001292 mapper1.set_timestamp_callback(
1293 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuhd2f96102020-12-01 20:27:29 -08001294
1295 mapper0.AddPeer(&mapper1);
1296 mapper1.AddPeer(&mapper0);
1297
1298 {
1299 SCOPED_TRACE("Trying node1 now");
1300 std::deque<TimestampedMessage> output1;
1301
1302 ASSERT_TRUE(mapper1.Front() != nullptr);
1303 output1.emplace_back(std::move(*mapper1.Front()));
1304 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001305 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001306
1307 ASSERT_TRUE(mapper1.Front() != nullptr);
1308 output1.emplace_back(std::move(*mapper1.Front()));
1309 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001310 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001311
1312 ASSERT_TRUE(mapper1.Front() != nullptr);
1313 output1.emplace_back(std::move(*mapper1.Front()));
1314 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001315 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001316
1317 ASSERT_TRUE(mapper1.Front() == nullptr);
1318
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001319 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1320 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001321 e + chrono::seconds(100) + chrono::milliseconds(1000));
1322 EXPECT_FALSE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001323
1324 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1325 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001326 e + chrono::seconds(100) + chrono::milliseconds(2000));
1327 EXPECT_TRUE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001328
1329 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1330 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001331 e + chrono::seconds(100) + chrono::milliseconds(3000));
1332 EXPECT_TRUE(output1[2].data.Verify());
1333 }
Austin Schuh79b30942021-01-24 22:32:21 -08001334
1335 EXPECT_EQ(mapper0_count, 0u);
1336 EXPECT_EQ(mapper1_count, 3u);
Austin Schuhd2f96102020-12-01 20:27:29 -08001337}
1338
1339// Tests that we return just the timestamps if we couldn't find the data and the
1340// missing data was at the end of the file.
1341TEST_F(TimestampMapperTest, ReadMissingDataAfter) {
1342 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1343 {
1344 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1345 writer0.QueueSpan(config0_.span());
1346 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1347 writer1.QueueSpan(config2_.span());
1348
1349 writer0.QueueSizedFlatbuffer(
1350 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
1351 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1352 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1353
1354 writer0.QueueSizedFlatbuffer(
1355 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
1356 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1357 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
1358
1359 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007);
1360 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1361 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1362 }
1363
1364 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1365
1366 ASSERT_EQ(parts[0].logger_node, "pi1");
1367 ASSERT_EQ(parts[1].logger_node, "pi2");
1368
Austin Schuh79b30942021-01-24 22:32:21 -08001369 size_t mapper0_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001370 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -08001371 mapper0.set_timestamp_callback(
1372 [&](TimestampedMessage *) { ++mapper0_count; });
1373 size_t mapper1_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001374 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -08001375 mapper1.set_timestamp_callback(
1376 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuhd2f96102020-12-01 20:27:29 -08001377
1378 mapper0.AddPeer(&mapper1);
1379 mapper1.AddPeer(&mapper0);
1380
1381 {
1382 SCOPED_TRACE("Trying node1 now");
1383 std::deque<TimestampedMessage> output1;
1384
1385 ASSERT_TRUE(mapper1.Front() != nullptr);
1386 output1.emplace_back(std::move(*mapper1.Front()));
1387 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001388 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001389
1390 ASSERT_TRUE(mapper1.Front() != nullptr);
1391 output1.emplace_back(std::move(*mapper1.Front()));
1392 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001393 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001394
1395 ASSERT_TRUE(mapper1.Front() != nullptr);
1396 output1.emplace_back(std::move(*mapper1.Front()));
1397 mapper1.PopFront();
Austin Schuh24bf4972021-06-29 22:09:08 -07001398 EXPECT_TRUE(mapper1.started());
Austin Schuhd2f96102020-12-01 20:27:29 -08001399
1400 ASSERT_TRUE(mapper1.Front() == nullptr);
1401
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001402 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1403 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001404 e + chrono::seconds(100) + chrono::milliseconds(1000));
1405 EXPECT_TRUE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001406
1407 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1408 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001409 e + chrono::seconds(100) + chrono::milliseconds(2000));
1410 EXPECT_TRUE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001411
1412 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1413 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001414 e + chrono::seconds(100) + chrono::milliseconds(3000));
1415 EXPECT_FALSE(output1[2].data.Verify());
1416 }
Austin Schuh79b30942021-01-24 22:32:21 -08001417
1418 EXPECT_EQ(mapper0_count, 0u);
1419 EXPECT_EQ(mapper1_count, 3u);
Austin Schuhd2f96102020-12-01 20:27:29 -08001420}
1421
Austin Schuh993ccb52020-12-12 15:59:32 -08001422// Tests that we handle a message which failed to forward or be logged.
1423TEST_F(TimestampMapperTest, ReadMissingDataMiddle) {
1424 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1425 {
1426 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1427 writer0.QueueSpan(config0_.span());
1428 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1429 writer1.QueueSpan(config2_.span());
1430
1431 writer0.QueueSizedFlatbuffer(
1432 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
1433 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1434 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1435
1436 // Create both the timestamp and message, but don't log them, simulating a
1437 // forwarding drop.
1438 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006);
1439 MakeTimestampMessage(e + chrono::milliseconds(2000), 0,
1440 chrono::seconds(100));
1441
1442 writer0.QueueSizedFlatbuffer(
1443 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
1444 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1445 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1446 }
1447
1448 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1449
1450 ASSERT_EQ(parts[0].logger_node, "pi1");
1451 ASSERT_EQ(parts[1].logger_node, "pi2");
1452
Austin Schuh79b30942021-01-24 22:32:21 -08001453 size_t mapper0_count = 0;
Austin Schuh993ccb52020-12-12 15:59:32 -08001454 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -08001455 mapper0.set_timestamp_callback(
1456 [&](TimestampedMessage *) { ++mapper0_count; });
1457 size_t mapper1_count = 0;
Austin Schuh993ccb52020-12-12 15:59:32 -08001458 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -08001459 mapper1.set_timestamp_callback(
1460 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuh993ccb52020-12-12 15:59:32 -08001461
1462 mapper0.AddPeer(&mapper1);
1463 mapper1.AddPeer(&mapper0);
1464
1465 {
1466 std::deque<TimestampedMessage> output1;
1467
1468 ASSERT_TRUE(mapper1.Front() != nullptr);
1469 output1.emplace_back(std::move(*mapper1.Front()));
1470 mapper1.PopFront();
1471
1472 ASSERT_TRUE(mapper1.Front() != nullptr);
1473 output1.emplace_back(std::move(*mapper1.Front()));
1474
1475 ASSERT_FALSE(mapper1.Front() == nullptr);
1476
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001477 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1478 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuh993ccb52020-12-12 15:59:32 -08001479 e + chrono::seconds(100) + chrono::milliseconds(1000));
1480 EXPECT_TRUE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001481
1482 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1483 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuh993ccb52020-12-12 15:59:32 -08001484 e + chrono::seconds(100) + chrono::milliseconds(3000));
1485 EXPECT_TRUE(output1[1].data.Verify());
1486 }
Austin Schuh79b30942021-01-24 22:32:21 -08001487
1488 EXPECT_EQ(mapper0_count, 0u);
1489 EXPECT_EQ(mapper1_count, 2u);
Austin Schuh993ccb52020-12-12 15:59:32 -08001490}
1491
Austin Schuhd2f96102020-12-01 20:27:29 -08001492// Tests that we properly sort log files with duplicate timestamps.
1493TEST_F(TimestampMapperTest, ReadSameTimestamp) {
1494 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1495 {
1496 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1497 writer0.QueueSpan(config0_.span());
1498 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1499 writer1.QueueSpan(config2_.span());
1500
1501 writer0.QueueSizedFlatbuffer(
1502 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
1503 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1504 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1505
1506 writer0.QueueSizedFlatbuffer(
1507 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
1508 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1509 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
1510
1511 writer0.QueueSizedFlatbuffer(
1512 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x007));
1513 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1514 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
1515
1516 writer0.QueueSizedFlatbuffer(
1517 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x008));
1518 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1519 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1520 }
1521
1522 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1523
1524 ASSERT_EQ(parts[0].logger_node, "pi1");
1525 ASSERT_EQ(parts[1].logger_node, "pi2");
1526
Austin Schuh79b30942021-01-24 22:32:21 -08001527 size_t mapper0_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001528 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -08001529 mapper0.set_timestamp_callback(
1530 [&](TimestampedMessage *) { ++mapper0_count; });
1531 size_t mapper1_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001532 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -08001533 mapper1.set_timestamp_callback(
1534 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuhd2f96102020-12-01 20:27:29 -08001535
1536 mapper0.AddPeer(&mapper1);
1537 mapper1.AddPeer(&mapper0);
1538
1539 {
1540 SCOPED_TRACE("Trying node1 now");
1541 std::deque<TimestampedMessage> output1;
1542
1543 for (int i = 0; i < 4; ++i) {
1544 ASSERT_TRUE(mapper1.Front() != nullptr);
1545 output1.emplace_back(std::move(*mapper1.Front()));
1546 mapper1.PopFront();
1547 }
1548 ASSERT_TRUE(mapper1.Front() == nullptr);
1549
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001550 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1551 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001552 e + chrono::seconds(100) + chrono::milliseconds(1000));
1553 EXPECT_TRUE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001554
1555 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1556 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001557 e + chrono::seconds(100) + chrono::milliseconds(2000));
1558 EXPECT_TRUE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001559
1560 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1561 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001562 e + chrono::seconds(100) + chrono::milliseconds(2000));
1563 EXPECT_TRUE(output1[2].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001564
1565 EXPECT_EQ(output1[3].monotonic_event_time.boot, 0u);
1566 EXPECT_EQ(output1[3].monotonic_event_time.time,
Austin Schuhd2f96102020-12-01 20:27:29 -08001567 e + chrono::seconds(100) + chrono::milliseconds(3000));
1568 EXPECT_TRUE(output1[3].data.Verify());
1569 }
Austin Schuh79b30942021-01-24 22:32:21 -08001570
1571 EXPECT_EQ(mapper0_count, 0u);
1572 EXPECT_EQ(mapper1_count, 4u);
Austin Schuhd2f96102020-12-01 20:27:29 -08001573}
1574
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001575// Tests that we properly produce a valid start time.
Austin Schuhd2f96102020-12-01 20:27:29 -08001576TEST_F(TimestampMapperTest, StartTime) {
1577 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1578 {
1579 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1580 writer0.QueueSpan(config0_.span());
1581 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1582 writer1.QueueSpan(config1_.span());
1583 DetachedBufferWriter writer2(logfile2_, std::make_unique<DummyEncoder>());
1584 writer2.QueueSpan(config3_.span());
1585 }
1586
1587 const std::vector<LogFile> parts =
1588 SortParts({logfile0_, logfile1_, logfile2_});
1589
Austin Schuh79b30942021-01-24 22:32:21 -08001590 size_t mapper0_count = 0;
Austin Schuhd2f96102020-12-01 20:27:29 -08001591 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
Austin Schuh79b30942021-01-24 22:32:21 -08001592 mapper0.set_timestamp_callback(
1593 [&](TimestampedMessage *) { ++mapper0_count; });
Austin Schuhd2f96102020-12-01 20:27:29 -08001594
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001595 EXPECT_EQ(mapper0.monotonic_start_time(0), e + chrono::milliseconds(1));
1596 EXPECT_EQ(mapper0.realtime_start_time(0),
Austin Schuhd2f96102020-12-01 20:27:29 -08001597 realtime_clock::time_point(chrono::seconds(1000)));
Austin Schuh79b30942021-01-24 22:32:21 -08001598 EXPECT_EQ(mapper0_count, 0u);
Austin Schuhd2f96102020-12-01 20:27:29 -08001599}
1600
Austin Schuhfecf1d82020-12-19 16:57:28 -08001601// Tests that when a peer isn't registered, we treat that as if there was no
1602// data available.
1603TEST_F(TimestampMapperTest, NoPeer) {
1604 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1605 {
1606 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1607 writer0.QueueSpan(config0_.span());
1608 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1609 writer1.QueueSpan(config2_.span());
1610
1611 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005);
1612 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1613 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1614
1615 writer0.QueueSizedFlatbuffer(
1616 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
1617 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1618 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
1619
1620 writer0.QueueSizedFlatbuffer(
1621 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
1622 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1623 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1624 }
1625
1626 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1627
1628 ASSERT_EQ(parts[0].logger_node, "pi1");
1629 ASSERT_EQ(parts[1].logger_node, "pi2");
1630
Austin Schuh79b30942021-01-24 22:32:21 -08001631 size_t mapper1_count = 0;
Austin Schuhfecf1d82020-12-19 16:57:28 -08001632 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
Austin Schuh79b30942021-01-24 22:32:21 -08001633 mapper1.set_timestamp_callback(
1634 [&](TimestampedMessage *) { ++mapper1_count; });
Austin Schuhfecf1d82020-12-19 16:57:28 -08001635
1636 {
1637 std::deque<TimestampedMessage> output1;
1638
1639 ASSERT_TRUE(mapper1.Front() != nullptr);
1640 output1.emplace_back(std::move(*mapper1.Front()));
1641 mapper1.PopFront();
1642 ASSERT_TRUE(mapper1.Front() != nullptr);
1643 output1.emplace_back(std::move(*mapper1.Front()));
1644 mapper1.PopFront();
1645 ASSERT_TRUE(mapper1.Front() != nullptr);
1646 output1.emplace_back(std::move(*mapper1.Front()));
1647 mapper1.PopFront();
1648 ASSERT_TRUE(mapper1.Front() == nullptr);
1649
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001650 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1651 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuhfecf1d82020-12-19 16:57:28 -08001652 e + chrono::seconds(100) + chrono::milliseconds(1000));
1653 EXPECT_FALSE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001654
1655 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1656 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuhfecf1d82020-12-19 16:57:28 -08001657 e + chrono::seconds(100) + chrono::milliseconds(2000));
1658 EXPECT_FALSE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001659
1660 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1661 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuhfecf1d82020-12-19 16:57:28 -08001662 e + chrono::seconds(100) + chrono::milliseconds(3000));
1663 EXPECT_FALSE(output1[2].data.Verify());
1664 }
Austin Schuh79b30942021-01-24 22:32:21 -08001665 EXPECT_EQ(mapper1_count, 3u);
1666}
1667
1668// Tests that we can queue messages and call the timestamp callback for both
1669// nodes.
1670TEST_F(TimestampMapperTest, QueueUntilNode0) {
1671 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1672 {
1673 DetachedBufferWriter writer0(logfile0_, std::make_unique<DummyEncoder>());
1674 writer0.QueueSpan(config0_.span());
1675 DetachedBufferWriter writer1(logfile1_, std::make_unique<DummyEncoder>());
1676 writer1.QueueSpan(config2_.span());
1677
1678 writer0.QueueSizedFlatbuffer(
1679 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
1680 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1681 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1682
1683 writer0.QueueSizedFlatbuffer(
1684 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x006));
1685 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1686 e + chrono::milliseconds(1000), 0, chrono::seconds(100)));
1687
1688 writer0.QueueSizedFlatbuffer(
1689 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x007));
1690 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1691 e + chrono::milliseconds(2000), 0, chrono::seconds(100)));
1692
1693 writer0.QueueSizedFlatbuffer(
1694 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x008));
1695 writer1.QueueSizedFlatbuffer(MakeTimestampMessage(
1696 e + chrono::milliseconds(3000), 0, chrono::seconds(100)));
1697 }
1698
1699 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1700
1701 ASSERT_EQ(parts[0].logger_node, "pi1");
1702 ASSERT_EQ(parts[1].logger_node, "pi2");
1703
1704 size_t mapper0_count = 0;
1705 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
1706 mapper0.set_timestamp_callback(
1707 [&](TimestampedMessage *) { ++mapper0_count; });
1708 size_t mapper1_count = 0;
1709 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
1710 mapper1.set_timestamp_callback(
1711 [&](TimestampedMessage *) { ++mapper1_count; });
1712
1713 mapper0.AddPeer(&mapper1);
1714 mapper1.AddPeer(&mapper0);
1715
1716 {
1717 std::deque<TimestampedMessage> output0;
1718
1719 EXPECT_EQ(mapper0_count, 0u);
1720 EXPECT_EQ(mapper1_count, 0u);
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001721 mapper0.QueueUntil(
1722 BootTimestamp{.boot = 0, .time = e + chrono::milliseconds(1000)});
Austin Schuh79b30942021-01-24 22:32:21 -08001723 EXPECT_EQ(mapper0_count, 3u);
1724 EXPECT_EQ(mapper1_count, 0u);
1725
1726 ASSERT_TRUE(mapper0.Front() != nullptr);
1727 EXPECT_EQ(mapper0_count, 3u);
1728 EXPECT_EQ(mapper1_count, 0u);
1729
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001730 mapper0.QueueUntil(
1731 BootTimestamp{.boot = 0, .time = e + chrono::milliseconds(1500)});
Austin Schuh79b30942021-01-24 22:32:21 -08001732 EXPECT_EQ(mapper0_count, 3u);
1733 EXPECT_EQ(mapper1_count, 0u);
1734
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001735 mapper0.QueueUntil(
1736 BootTimestamp{.boot = 0, .time = e + chrono::milliseconds(2500)});
Austin Schuh79b30942021-01-24 22:32:21 -08001737 EXPECT_EQ(mapper0_count, 4u);
1738 EXPECT_EQ(mapper1_count, 0u);
1739
1740 output0.emplace_back(std::move(*mapper0.Front()));
1741 mapper0.PopFront();
1742 output0.emplace_back(std::move(*mapper0.Front()));
1743 mapper0.PopFront();
1744 output0.emplace_back(std::move(*mapper0.Front()));
1745 mapper0.PopFront();
1746 output0.emplace_back(std::move(*mapper0.Front()));
1747 mapper0.PopFront();
1748
1749 EXPECT_EQ(mapper0_count, 4u);
1750 EXPECT_EQ(mapper1_count, 0u);
1751
1752 ASSERT_TRUE(mapper0.Front() == nullptr);
1753
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001754 EXPECT_EQ(output0[0].monotonic_event_time.boot, 0u);
1755 EXPECT_EQ(output0[0].monotonic_event_time.time,
1756 e + chrono::milliseconds(1000));
Austin Schuh79b30942021-01-24 22:32:21 -08001757 EXPECT_TRUE(output0[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001758
1759 EXPECT_EQ(output0[1].monotonic_event_time.boot, 0u);
1760 EXPECT_EQ(output0[1].monotonic_event_time.time,
1761 e + chrono::milliseconds(1000));
Austin Schuh79b30942021-01-24 22:32:21 -08001762 EXPECT_TRUE(output0[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001763
1764 EXPECT_EQ(output0[2].monotonic_event_time.boot, 0u);
1765 EXPECT_EQ(output0[2].monotonic_event_time.time,
1766 e + chrono::milliseconds(2000));
Austin Schuh79b30942021-01-24 22:32:21 -08001767 EXPECT_TRUE(output0[2].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001768
1769 EXPECT_EQ(output0[3].monotonic_event_time.boot, 0u);
1770 EXPECT_EQ(output0[3].monotonic_event_time.time,
1771 e + chrono::milliseconds(3000));
Austin Schuh79b30942021-01-24 22:32:21 -08001772 EXPECT_TRUE(output0[3].data.Verify());
1773 }
1774
1775 {
1776 SCOPED_TRACE("Trying node1 now");
1777 std::deque<TimestampedMessage> output1;
1778
1779 EXPECT_EQ(mapper0_count, 4u);
1780 EXPECT_EQ(mapper1_count, 0u);
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001781 mapper1.QueueUntil(BootTimestamp{
1782 .boot = 0,
1783 .time = e + chrono::seconds(100) + chrono::milliseconds(1000)});
Austin Schuh79b30942021-01-24 22:32:21 -08001784 EXPECT_EQ(mapper0_count, 4u);
1785 EXPECT_EQ(mapper1_count, 3u);
1786
1787 ASSERT_TRUE(mapper1.Front() != nullptr);
1788 EXPECT_EQ(mapper0_count, 4u);
1789 EXPECT_EQ(mapper1_count, 3u);
1790
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001791 mapper1.QueueUntil(BootTimestamp{
1792 .boot = 0,
1793 .time = e + chrono::seconds(100) + chrono::milliseconds(1500)});
Austin Schuh79b30942021-01-24 22:32:21 -08001794 EXPECT_EQ(mapper0_count, 4u);
1795 EXPECT_EQ(mapper1_count, 3u);
1796
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001797 mapper1.QueueUntil(BootTimestamp{
1798 .boot = 0,
1799 .time = e + chrono::seconds(100) + chrono::milliseconds(2500)});
Austin Schuh79b30942021-01-24 22:32:21 -08001800 EXPECT_EQ(mapper0_count, 4u);
1801 EXPECT_EQ(mapper1_count, 4u);
1802
1803 ASSERT_TRUE(mapper1.Front() != nullptr);
1804 EXPECT_EQ(mapper0_count, 4u);
1805 EXPECT_EQ(mapper1_count, 4u);
1806
1807 output1.emplace_back(std::move(*mapper1.Front()));
1808 mapper1.PopFront();
1809 ASSERT_TRUE(mapper1.Front() != nullptr);
1810 output1.emplace_back(std::move(*mapper1.Front()));
1811 mapper1.PopFront();
1812 ASSERT_TRUE(mapper1.Front() != nullptr);
1813 output1.emplace_back(std::move(*mapper1.Front()));
1814 mapper1.PopFront();
1815 ASSERT_TRUE(mapper1.Front() != nullptr);
1816 output1.emplace_back(std::move(*mapper1.Front()));
1817 mapper1.PopFront();
1818
1819 EXPECT_EQ(mapper0_count, 4u);
1820 EXPECT_EQ(mapper1_count, 4u);
1821
1822 ASSERT_TRUE(mapper1.Front() == nullptr);
1823
1824 EXPECT_EQ(mapper0_count, 4u);
1825 EXPECT_EQ(mapper1_count, 4u);
1826
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001827 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
1828 EXPECT_EQ(output1[0].monotonic_event_time.time,
Austin Schuh79b30942021-01-24 22:32:21 -08001829 e + chrono::seconds(100) + chrono::milliseconds(1000));
1830 EXPECT_TRUE(output1[0].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001831
1832 EXPECT_EQ(output1[1].monotonic_event_time.boot, 0u);
1833 EXPECT_EQ(output1[1].monotonic_event_time.time,
Austin Schuh79b30942021-01-24 22:32:21 -08001834 e + chrono::seconds(100) + chrono::milliseconds(1000));
1835 EXPECT_TRUE(output1[1].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001836
1837 EXPECT_EQ(output1[2].monotonic_event_time.boot, 0u);
1838 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuh79b30942021-01-24 22:32:21 -08001839 e + chrono::seconds(100) + chrono::milliseconds(2000));
1840 EXPECT_TRUE(output1[2].data.Verify());
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001841
1842 EXPECT_EQ(output1[3].monotonic_event_time.boot, 0u);
1843 EXPECT_EQ(output1[3].monotonic_event_time.time,
Austin Schuh79b30942021-01-24 22:32:21 -08001844 e + chrono::seconds(100) + chrono::milliseconds(3000));
1845 EXPECT_TRUE(output1[3].data.Verify());
1846 }
Austin Schuhfecf1d82020-12-19 16:57:28 -08001847}
1848
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001849class BootMergerTest : public SortingElementTest {
1850 public:
1851 BootMergerTest()
1852 : SortingElementTest(),
1853 boot0_(MakeHeader(config_, R"({
Austin Schuh8bee6882021-06-28 21:03:28 -07001854 /* 100ms */
1855 "max_out_of_order_duration": 100000000,
1856 "node": {
1857 "name": "pi2"
1858 },
1859 "logger_node": {
1860 "name": "pi1"
1861 },
1862 "monotonic_start_time": 1000000,
1863 "realtime_start_time": 1000000000000,
1864 "logger_monotonic_start_time": 1000000,
1865 "logger_realtime_start_time": 1000000000000,
1866 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
1867 "parts_uuid": "1a9e5ca2-31b2-475b-8282-88f6d1ce5109",
1868 "parts_index": 0,
1869 "logger_instance_uuid": "1c3142ad-10a5-408d-a760-b63b73d3b904",
1870 "logger_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
Austin Schuh48507722021-07-17 17:29:24 -07001871 "source_node_boot_uuid": "6ba4f28d-21a2-4d7f-83f4-ee365cf86464",
1872 "boot_uuids": [
1873 "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
1874 "6ba4f28d-21a2-4d7f-83f4-ee365cf86464",
1875 ""
1876 ]
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001877})")),
1878 boot1_(MakeHeader(config_, R"({
Austin Schuh8bee6882021-06-28 21:03:28 -07001879 /* 100ms */
1880 "max_out_of_order_duration": 100000000,
1881 "node": {
1882 "name": "pi2"
1883 },
1884 "logger_node": {
1885 "name": "pi1"
1886 },
1887 "monotonic_start_time": 1000000,
1888 "realtime_start_time": 1000000000000,
1889 "logger_monotonic_start_time": 1000000,
1890 "logger_realtime_start_time": 1000000000000,
1891 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
1892 "parts_uuid": "2a05d725-5d5c-4c0b-af42-88de2f3c3876",
1893 "parts_index": 1,
1894 "logger_instance_uuid": "1c3142ad-10a5-408d-a760-b63b73d3b904",
1895 "logger_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
Austin Schuh48507722021-07-17 17:29:24 -07001896 "source_node_boot_uuid": "b728d27a-9181-4eac-bfc1-5d09b80469d2",
1897 "boot_uuids": [
1898 "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
1899 "b728d27a-9181-4eac-bfc1-5d09b80469d2",
1900 ""
1901 ]
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001902})")) {}
Austin Schuh8bee6882021-06-28 21:03:28 -07001903
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001904 protected:
1905 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> boot0_;
1906 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> boot1_;
1907};
1908
1909// This tests that we can properly sort a multi-node log file which has the old
1910// (and buggy) timestamps in the header, and the non-resetting parts_index.
1911// These make it so we can just bairly figure out what happened first and what
1912// happened second, but not in a way that is robust to multiple nodes rebooting.
1913TEST_F(BootMergerTest, OldReboot) {
Austin Schuh8bee6882021-06-28 21:03:28 -07001914 {
1915 DetachedBufferWriter writer(logfile0_, std::make_unique<DummyEncoder>());
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001916 writer.QueueSpan(boot0_.span());
Austin Schuh8bee6882021-06-28 21:03:28 -07001917 }
1918 {
1919 DetachedBufferWriter writer(logfile1_, std::make_unique<DummyEncoder>());
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001920 writer.QueueSpan(boot1_.span());
Austin Schuh8bee6882021-06-28 21:03:28 -07001921 }
1922
1923 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1924
1925 ASSERT_EQ(parts.size(), 1u);
1926 ASSERT_EQ(parts[0].parts.size(), 2u);
1927
1928 EXPECT_EQ(parts[0].parts[0].boot_count, 0);
1929 EXPECT_EQ(parts[0].parts[0].source_boot_uuid,
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001930 boot0_.message().source_node_boot_uuid()->string_view());
Austin Schuh8bee6882021-06-28 21:03:28 -07001931
1932 EXPECT_EQ(parts[0].parts[1].boot_count, 1);
1933 EXPECT_EQ(parts[0].parts[1].source_boot_uuid,
Austin Schuhf16ef6a2021-06-30 21:48:17 -07001934 boot1_.message().source_node_boot_uuid()->string_view());
1935}
1936
1937// This tests that we can produce messages ordered across a reboot.
1938TEST_F(BootMergerTest, SortAcrossReboot) {
1939 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
1940 {
1941 DetachedBufferWriter writer(logfile0_, std::make_unique<DummyEncoder>());
1942 writer.QueueSpan(boot0_.span());
1943 writer.QueueSizedFlatbuffer(
1944 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
1945 writer.QueueSizedFlatbuffer(
1946 MakeLogMessage(e + chrono::milliseconds(2000), 1, 0x105));
1947 }
1948 {
1949 DetachedBufferWriter writer(logfile1_, std::make_unique<DummyEncoder>());
1950 writer.QueueSpan(boot1_.span());
1951 writer.QueueSizedFlatbuffer(
1952 MakeLogMessage(e + chrono::milliseconds(100), 0, 0x006));
1953 writer.QueueSizedFlatbuffer(
1954 MakeLogMessage(e + chrono::milliseconds(200), 1, 0x106));
1955 }
1956
1957 const std::vector<LogFile> parts = SortParts({logfile0_, logfile1_});
1958 ASSERT_EQ(parts.size(), 1u);
1959 ASSERT_EQ(parts[0].parts.size(), 2u);
1960
1961 BootMerger merger(FilterPartsForNode(parts, "pi2"));
1962
1963 EXPECT_EQ(merger.node(), 1u);
1964
1965 std::vector<Message> output;
1966 for (int i = 0; i < 4; ++i) {
1967 ASSERT_TRUE(merger.Front() != nullptr);
1968 output.emplace_back(std::move(*merger.Front()));
1969 merger.PopFront();
1970 }
1971
1972 ASSERT_TRUE(merger.Front() == nullptr);
1973
Austin Schuh2dc8c7d2021-07-01 17:41:28 -07001974 EXPECT_EQ(output[0].timestamp.boot, 0u);
1975 EXPECT_EQ(output[0].timestamp.time, e + chrono::milliseconds(1000));
1976 EXPECT_EQ(output[1].timestamp.boot, 0u);
1977 EXPECT_EQ(output[1].timestamp.time, e + chrono::milliseconds(2000));
1978
1979 EXPECT_EQ(output[2].timestamp.boot, 1u);
1980 EXPECT_EQ(output[2].timestamp.time, e + chrono::milliseconds(100));
1981 EXPECT_EQ(output[3].timestamp.boot, 1u);
1982 EXPECT_EQ(output[3].timestamp.time, e + chrono::milliseconds(200));
Austin Schuh8bee6882021-06-28 21:03:28 -07001983}
1984
Austin Schuh48507722021-07-17 17:29:24 -07001985class RebootTimestampMapperTest : public SortingElementTest {
1986 public:
1987 RebootTimestampMapperTest()
1988 : SortingElementTest(),
1989 boot0a_(MakeHeader(config_, R"({
1990 /* 100ms */
1991 "max_out_of_order_duration": 100000000,
1992 "node": {
1993 "name": "pi1"
1994 },
1995 "logger_node": {
1996 "name": "pi1"
1997 },
1998 "monotonic_start_time": 1000000,
1999 "realtime_start_time": 1000000000000,
2000 "logger_monotonic_start_time": 1000000,
2001 "logger_realtime_start_time": 1000000000000,
2002 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
2003 "parts_uuid": "ee4f5a98-77d0-4e01-af2f-bbb29e098ede",
2004 "parts_index": 0,
2005 "logger_instance_uuid": "1c3142ad-10a5-408d-a760-b63b73d3b904",
2006 "logger_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2007 "source_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2008 "boot_uuids": [
2009 "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2010 "6ba4f28d-21a2-4d7f-83f4-ee365cf86464",
2011 ""
2012 ]
2013})")),
2014 boot0b_(MakeHeader(config_, R"({
2015 /* 100ms */
2016 "max_out_of_order_duration": 100000000,
2017 "node": {
2018 "name": "pi1"
2019 },
2020 "logger_node": {
2021 "name": "pi1"
2022 },
2023 "monotonic_start_time": 1000000,
2024 "realtime_start_time": 1000000000000,
2025 "logger_monotonic_start_time": 1000000,
2026 "logger_realtime_start_time": 1000000000000,
2027 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
2028 "parts_uuid": "ee4f5a98-77d0-4e01-af2f-bbb29e098ede",
2029 "parts_index": 1,
2030 "logger_instance_uuid": "1c3142ad-10a5-408d-a760-b63b73d3b904",
2031 "logger_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2032 "source_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2033 "boot_uuids": [
2034 "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2035 "b728d27a-9181-4eac-bfc1-5d09b80469d2",
2036 ""
2037 ]
2038})")),
2039 boot1a_(MakeHeader(config_, R"({
2040 /* 100ms */
2041 "max_out_of_order_duration": 100000000,
2042 "node": {
2043 "name": "pi2"
2044 },
2045 "logger_node": {
2046 "name": "pi1"
2047 },
2048 "monotonic_start_time": 1000000,
2049 "realtime_start_time": 1000000000000,
2050 "logger_monotonic_start_time": 1000000,
2051 "logger_realtime_start_time": 1000000000000,
2052 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
2053 "parts_uuid": "f6ab0cdc-a654-456d-bfd9-2bbc09098edf",
2054 "parts_index": 0,
2055 "logger_instance_uuid": "1c3142ad-10a5-408d-a760-b63b73d3b904",
2056 "logger_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2057 "source_node_boot_uuid": "6ba4f28d-21a2-4d7f-83f4-ee365cf86464",
2058 "boot_uuids": [
2059 "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2060 "6ba4f28d-21a2-4d7f-83f4-ee365cf86464",
2061 ""
2062 ]
2063})")),
2064 boot1b_(MakeHeader(config_, R"({
2065 /* 100ms */
2066 "max_out_of_order_duration": 100000000,
2067 "node": {
2068 "name": "pi2"
2069 },
2070 "logger_node": {
2071 "name": "pi1"
2072 },
2073 "monotonic_start_time": 1000000,
2074 "realtime_start_time": 1000000000000,
2075 "logger_monotonic_start_time": 1000000,
2076 "logger_realtime_start_time": 1000000000000,
2077 "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
2078 "parts_uuid": "3a9d0445-f520-43ca-93f5-e2cc7f54d40a",
2079 "parts_index": 1,
2080 "logger_instance_uuid": "1c3142ad-10a5-408d-a760-b63b73d3b904",
2081 "logger_node_boot_uuid": "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2082 "source_node_boot_uuid": "b728d27a-9181-4eac-bfc1-5d09b80469d2",
2083 "boot_uuids": [
2084 "a570df8b-5cc2-4dbe-89bd-286f9ddd02b7",
2085 "b728d27a-9181-4eac-bfc1-5d09b80469d2",
2086 ""
2087 ]
2088})")) {}
2089
2090 protected:
2091 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> boot0a_;
2092 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> boot0b_;
2093 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> boot1a_;
2094 const aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> boot1b_;
2095};
2096
Austin Schuh48507722021-07-17 17:29:24 -07002097// Tests that we can match timestamps on delivered messages in the presence of
2098// reboots on the node receiving timestamps.
2099TEST_F(RebootTimestampMapperTest, ReadNode0First) {
2100 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
2101 {
2102 DetachedBufferWriter writer0a(logfile0_, std::make_unique<DummyEncoder>());
2103 writer0a.QueueSpan(boot0a_.span());
2104 DetachedBufferWriter writer0b(logfile1_, std::make_unique<DummyEncoder>());
2105 writer0b.QueueSpan(boot0b_.span());
2106 DetachedBufferWriter writer1a(logfile2_, std::make_unique<DummyEncoder>());
2107 writer1a.QueueSpan(boot1a_.span());
2108 DetachedBufferWriter writer1b(logfile3_, std::make_unique<DummyEncoder>());
2109 writer1b.QueueSpan(boot1b_.span());
2110
2111 writer0a.QueueSizedFlatbuffer(
2112 MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
2113 writer1a.QueueSizedFlatbuffer(MakeTimestampMessage(
2114 e + chrono::milliseconds(1000), 0, chrono::seconds(100),
2115 e + chrono::milliseconds(1001)));
2116
Austin Schuh58646e22021-08-23 23:51:46 -07002117 writer1b.QueueSizedFlatbuffer(MakeTimestampMessage(
2118 e + chrono::milliseconds(1000), 0, chrono::seconds(21),
2119 e + chrono::milliseconds(2001)));
2120
Austin Schuh48507722021-07-17 17:29:24 -07002121 writer0b.QueueSizedFlatbuffer(
2122 MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
2123 writer1b.QueueSizedFlatbuffer(MakeTimestampMessage(
2124 e + chrono::milliseconds(2000), 0, chrono::seconds(20),
2125 e + chrono::milliseconds(2001)));
2126
2127 writer0b.QueueSizedFlatbuffer(
2128 MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x007));
2129 writer1b.QueueSizedFlatbuffer(MakeTimestampMessage(
2130 e + chrono::milliseconds(3000), 0, chrono::seconds(20),
2131 e + chrono::milliseconds(3001)));
2132 }
2133
Austin Schuh58646e22021-08-23 23:51:46 -07002134 const std::vector<LogFile> parts =
2135 SortParts({logfile0_, logfile1_, logfile2_, logfile3_});
Austin Schuh48507722021-07-17 17:29:24 -07002136
2137 for (const auto &x : parts) {
2138 LOG(INFO) << x;
2139 }
2140 ASSERT_EQ(parts.size(), 1u);
2141 ASSERT_EQ(parts[0].logger_node, "pi1");
2142
2143 size_t mapper0_count = 0;
2144 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
2145 mapper0.set_timestamp_callback(
2146 [&](TimestampedMessage *) { ++mapper0_count; });
2147 size_t mapper1_count = 0;
2148 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
2149 mapper1.set_timestamp_callback(
2150 [&](TimestampedMessage *) { ++mapper1_count; });
2151
2152 mapper0.AddPeer(&mapper1);
2153 mapper1.AddPeer(&mapper0);
2154
2155 {
2156 std::deque<TimestampedMessage> output0;
2157
2158 EXPECT_EQ(mapper0_count, 0u);
2159 EXPECT_EQ(mapper1_count, 0u);
2160 ASSERT_TRUE(mapper0.Front() != nullptr);
2161 EXPECT_EQ(mapper0_count, 1u);
2162 EXPECT_EQ(mapper1_count, 0u);
2163 output0.emplace_back(std::move(*mapper0.Front()));
2164 mapper0.PopFront();
2165 EXPECT_TRUE(mapper0.started());
2166 EXPECT_EQ(mapper0_count, 1u);
2167 EXPECT_EQ(mapper1_count, 0u);
2168
2169 ASSERT_TRUE(mapper0.Front() != nullptr);
2170 EXPECT_EQ(mapper0_count, 2u);
2171 EXPECT_EQ(mapper1_count, 0u);
2172 output0.emplace_back(std::move(*mapper0.Front()));
2173 mapper0.PopFront();
2174 EXPECT_TRUE(mapper0.started());
2175
2176 ASSERT_TRUE(mapper0.Front() != nullptr);
2177 output0.emplace_back(std::move(*mapper0.Front()));
2178 mapper0.PopFront();
2179 EXPECT_TRUE(mapper0.started());
2180
2181 EXPECT_EQ(mapper0_count, 3u);
2182 EXPECT_EQ(mapper1_count, 0u);
2183
2184 ASSERT_TRUE(mapper0.Front() == nullptr);
2185
2186 LOG(INFO) << output0[0];
2187 LOG(INFO) << output0[1];
2188 LOG(INFO) << output0[2];
2189
2190 EXPECT_EQ(output0[0].monotonic_event_time.boot, 0u);
2191 EXPECT_EQ(output0[0].monotonic_event_time.time,
2192 e + chrono::milliseconds(1000));
Austin Schuh58646e22021-08-23 23:51:46 -07002193 EXPECT_EQ(output0[0].queue_index,
2194 (BootQueueIndex{.boot = 0u, .index = 0u}));
Austin Schuh48507722021-07-17 17:29:24 -07002195 EXPECT_EQ(output0[0].monotonic_remote_time, BootTimestamp::min_time());
2196 EXPECT_EQ(output0[0].monotonic_timestamp_time, BootTimestamp::min_time());
2197 EXPECT_TRUE(output0[0].data.Verify());
2198
2199 EXPECT_EQ(output0[1].monotonic_event_time.boot, 0u);
2200 EXPECT_EQ(output0[1].monotonic_event_time.time,
2201 e + chrono::milliseconds(2000));
Austin Schuh58646e22021-08-23 23:51:46 -07002202 EXPECT_EQ(output0[1].queue_index,
2203 (BootQueueIndex{.boot = 0u, .index = 1u}));
Austin Schuh48507722021-07-17 17:29:24 -07002204 EXPECT_EQ(output0[1].monotonic_remote_time, BootTimestamp::min_time());
2205 EXPECT_EQ(output0[1].monotonic_timestamp_time, BootTimestamp::min_time());
2206 EXPECT_TRUE(output0[1].data.Verify());
2207
2208 EXPECT_EQ(output0[2].monotonic_event_time.boot, 0u);
2209 EXPECT_EQ(output0[2].monotonic_event_time.time,
2210 e + chrono::milliseconds(3000));
Austin Schuh58646e22021-08-23 23:51:46 -07002211 EXPECT_EQ(output0[2].queue_index,
2212 (BootQueueIndex{.boot = 0u, .index = 2u}));
Austin Schuh48507722021-07-17 17:29:24 -07002213 EXPECT_EQ(output0[2].monotonic_remote_time, BootTimestamp::min_time());
2214 EXPECT_EQ(output0[2].monotonic_timestamp_time, BootTimestamp::min_time());
2215 EXPECT_TRUE(output0[2].data.Verify());
2216 }
2217
2218 {
2219 SCOPED_TRACE("Trying node1 now");
2220 std::deque<TimestampedMessage> output1;
2221
2222 EXPECT_EQ(mapper0_count, 3u);
2223 EXPECT_EQ(mapper1_count, 0u);
2224
2225 ASSERT_TRUE(mapper1.Front() != nullptr);
2226 EXPECT_EQ(mapper0_count, 3u);
2227 EXPECT_EQ(mapper1_count, 1u);
2228 output1.emplace_back(std::move(*mapper1.Front()));
2229 mapper1.PopFront();
2230 EXPECT_TRUE(mapper1.started());
2231 EXPECT_EQ(mapper0_count, 3u);
2232 EXPECT_EQ(mapper1_count, 1u);
2233
2234 ASSERT_TRUE(mapper1.Front() != nullptr);
2235 EXPECT_EQ(mapper0_count, 3u);
2236 EXPECT_EQ(mapper1_count, 2u);
2237 output1.emplace_back(std::move(*mapper1.Front()));
2238 mapper1.PopFront();
2239 EXPECT_TRUE(mapper1.started());
2240
2241 ASSERT_TRUE(mapper1.Front() != nullptr);
2242 output1.emplace_back(std::move(*mapper1.Front()));
2243 mapper1.PopFront();
2244 EXPECT_TRUE(mapper1.started());
2245
Austin Schuh58646e22021-08-23 23:51:46 -07002246 ASSERT_TRUE(mapper1.Front() != nullptr);
2247 output1.emplace_back(std::move(*mapper1.Front()));
2248 mapper1.PopFront();
2249 EXPECT_TRUE(mapper1.started());
2250
Austin Schuh48507722021-07-17 17:29:24 -07002251 EXPECT_EQ(mapper0_count, 3u);
Austin Schuh58646e22021-08-23 23:51:46 -07002252 EXPECT_EQ(mapper1_count, 4u);
Austin Schuh48507722021-07-17 17:29:24 -07002253
2254 ASSERT_TRUE(mapper1.Front() == nullptr);
2255
2256 EXPECT_EQ(mapper0_count, 3u);
Austin Schuh58646e22021-08-23 23:51:46 -07002257 EXPECT_EQ(mapper1_count, 4u);
Austin Schuh48507722021-07-17 17:29:24 -07002258
2259 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
2260 EXPECT_EQ(output1[0].monotonic_event_time.time,
2261 e + chrono::seconds(100) + chrono::milliseconds(1000));
2262 EXPECT_EQ(output1[0].monotonic_remote_time.boot, 0u);
2263 EXPECT_EQ(output1[0].monotonic_remote_time.time,
2264 e + chrono::milliseconds(1000));
Austin Schuh58646e22021-08-23 23:51:46 -07002265 EXPECT_EQ(output1[0].remote_queue_index,
2266 (BootQueueIndex{.boot = 0u, .index = 0u}));
Austin Schuh48507722021-07-17 17:29:24 -07002267 EXPECT_EQ(output1[0].monotonic_timestamp_time.boot, 0u);
2268 EXPECT_EQ(output1[0].monotonic_timestamp_time.time,
2269 e + chrono::milliseconds(1001));
2270 EXPECT_TRUE(output1[0].data.Verify());
2271
2272 EXPECT_EQ(output1[1].monotonic_event_time.boot, 1u);
2273 EXPECT_EQ(output1[1].monotonic_event_time.time,
2274 e + chrono::seconds(20) + chrono::milliseconds(2000));
Austin Schuh58646e22021-08-23 23:51:46 -07002275 EXPECT_EQ(output1[1].remote_queue_index,
2276 (BootQueueIndex{.boot = 0u, .index = 0u}));
Austin Schuh48507722021-07-17 17:29:24 -07002277 EXPECT_EQ(output1[1].monotonic_remote_time.boot, 0u);
2278 EXPECT_EQ(output1[1].monotonic_remote_time.time,
Austin Schuh58646e22021-08-23 23:51:46 -07002279 e + chrono::milliseconds(1000));
Austin Schuh48507722021-07-17 17:29:24 -07002280 EXPECT_EQ(output1[1].monotonic_timestamp_time.boot, 0u);
2281 EXPECT_EQ(output1[1].monotonic_timestamp_time.time,
2282 e + chrono::milliseconds(2001));
2283 EXPECT_TRUE(output1[1].data.Verify());
2284
2285 EXPECT_EQ(output1[2].monotonic_event_time.boot, 1u);
2286 EXPECT_EQ(output1[2].monotonic_event_time.time,
Austin Schuh58646e22021-08-23 23:51:46 -07002287 e + chrono::seconds(20) + chrono::milliseconds(2000));
Austin Schuh48507722021-07-17 17:29:24 -07002288 EXPECT_EQ(output1[2].monotonic_remote_time.boot, 0u);
2289 EXPECT_EQ(output1[2].monotonic_remote_time.time,
Austin Schuh58646e22021-08-23 23:51:46 -07002290 e + chrono::milliseconds(2000));
2291 EXPECT_EQ(output1[2].remote_queue_index,
2292 (BootQueueIndex{.boot = 0u, .index = 1u}));
Austin Schuh48507722021-07-17 17:29:24 -07002293 EXPECT_EQ(output1[2].monotonic_timestamp_time.boot, 0u);
2294 EXPECT_EQ(output1[2].monotonic_timestamp_time.time,
Austin Schuh58646e22021-08-23 23:51:46 -07002295 e + chrono::milliseconds(2001));
Austin Schuh48507722021-07-17 17:29:24 -07002296 EXPECT_TRUE(output1[2].data.Verify());
2297
Austin Schuh58646e22021-08-23 23:51:46 -07002298 EXPECT_EQ(output1[3].monotonic_event_time.boot, 1u);
2299 EXPECT_EQ(output1[3].monotonic_event_time.time,
2300 e + chrono::seconds(20) + chrono::milliseconds(3000));
2301 EXPECT_EQ(output1[3].monotonic_remote_time.boot, 0u);
2302 EXPECT_EQ(output1[3].monotonic_remote_time.time,
2303 e + chrono::milliseconds(3000));
2304 EXPECT_EQ(output1[3].remote_queue_index,
2305 (BootQueueIndex{.boot = 0u, .index = 2u}));
2306 EXPECT_EQ(output1[3].monotonic_timestamp_time.boot, 0u);
2307 EXPECT_EQ(output1[3].monotonic_timestamp_time.time,
2308 e + chrono::milliseconds(3001));
2309 EXPECT_TRUE(output1[3].data.Verify());
2310
Austin Schuh48507722021-07-17 17:29:24 -07002311 LOG(INFO) << output1[0];
2312 LOG(INFO) << output1[1];
2313 LOG(INFO) << output1[2];
Austin Schuh58646e22021-08-23 23:51:46 -07002314 LOG(INFO) << output1[3];
Austin Schuh48507722021-07-17 17:29:24 -07002315 }
2316}
2317
2318TEST_F(RebootTimestampMapperTest, Node2Reboot) {
2319 const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
2320 {
2321 DetachedBufferWriter writer0a(logfile0_, std::make_unique<DummyEncoder>());
2322 writer0a.QueueSpan(boot0a_.span());
2323 DetachedBufferWriter writer0b(logfile1_, std::make_unique<DummyEncoder>());
2324 writer0b.QueueSpan(boot0b_.span());
2325 DetachedBufferWriter writer1a(logfile2_, std::make_unique<DummyEncoder>());
2326 writer1a.QueueSpan(boot1a_.span());
2327 DetachedBufferWriter writer1b(logfile3_, std::make_unique<DummyEncoder>());
2328 writer1b.QueueSpan(boot1b_.span());
2329
2330 writer1a.QueueSizedFlatbuffer(MakeLogMessage(
2331 e + chrono::seconds(100) + chrono::milliseconds(1000), 3, 0x005));
2332 writer0a.QueueSizedFlatbuffer(MakeTimestampMessage(
2333 e + chrono::seconds(100) + chrono::milliseconds(1000), 3,
2334 chrono::seconds(-100),
2335 e + chrono::seconds(100) + chrono::milliseconds(1001)));
2336
2337 writer1b.QueueSizedFlatbuffer(MakeLogMessage(
2338 e + chrono::seconds(20) + chrono::milliseconds(2000), 3, 0x006));
2339 writer0b.QueueSizedFlatbuffer(MakeTimestampMessage(
2340 e + chrono::seconds(20) + chrono::milliseconds(2000), 3,
2341 chrono::seconds(-20),
2342 e + chrono::seconds(20) + chrono::milliseconds(2001)));
2343
2344 writer1b.QueueSizedFlatbuffer(MakeLogMessage(
2345 e + chrono::seconds(20) + chrono::milliseconds(3000), 3, 0x007));
2346 writer0b.QueueSizedFlatbuffer(MakeTimestampMessage(
2347 e + chrono::seconds(20) + chrono::milliseconds(3000), 3,
2348 chrono::seconds(-20),
2349 e + chrono::seconds(20) + chrono::milliseconds(3001)));
2350 }
2351
2352 const std::vector<LogFile> parts =
2353 SortParts({logfile0_, logfile1_, logfile2_, logfile3_});
2354
2355 for (const auto &x : parts) {
2356 LOG(INFO) << x;
2357 }
2358 ASSERT_EQ(parts.size(), 1u);
2359 ASSERT_EQ(parts[0].logger_node, "pi1");
2360
2361 size_t mapper0_count = 0;
2362 TimestampMapper mapper0(FilterPartsForNode(parts, "pi1"));
2363 mapper0.set_timestamp_callback(
2364 [&](TimestampedMessage *) { ++mapper0_count; });
2365 size_t mapper1_count = 0;
2366 TimestampMapper mapper1(FilterPartsForNode(parts, "pi2"));
2367 mapper1.set_timestamp_callback(
2368 [&](TimestampedMessage *) { ++mapper1_count; });
2369
2370 mapper0.AddPeer(&mapper1);
2371 mapper1.AddPeer(&mapper0);
2372
2373 {
2374 std::deque<TimestampedMessage> output0;
2375
2376 EXPECT_EQ(mapper0_count, 0u);
2377 EXPECT_EQ(mapper1_count, 0u);
2378 ASSERT_TRUE(mapper0.Front() != nullptr);
2379 EXPECT_EQ(mapper0_count, 1u);
2380 EXPECT_EQ(mapper1_count, 0u);
2381 output0.emplace_back(std::move(*mapper0.Front()));
2382 mapper0.PopFront();
2383 EXPECT_TRUE(mapper0.started());
2384 EXPECT_EQ(mapper0_count, 1u);
2385 EXPECT_EQ(mapper1_count, 0u);
2386
2387 ASSERT_TRUE(mapper0.Front() != nullptr);
2388 EXPECT_EQ(mapper0_count, 2u);
2389 EXPECT_EQ(mapper1_count, 0u);
2390 output0.emplace_back(std::move(*mapper0.Front()));
2391 mapper0.PopFront();
2392 EXPECT_TRUE(mapper0.started());
2393
2394 ASSERT_TRUE(mapper0.Front() != nullptr);
2395 output0.emplace_back(std::move(*mapper0.Front()));
2396 mapper0.PopFront();
2397 EXPECT_TRUE(mapper0.started());
2398
2399 EXPECT_EQ(mapper0_count, 3u);
2400 EXPECT_EQ(mapper1_count, 0u);
2401
2402 ASSERT_TRUE(mapper0.Front() == nullptr);
2403
2404 LOG(INFO) << output0[0];
2405 LOG(INFO) << output0[1];
2406 LOG(INFO) << output0[2];
2407
2408 EXPECT_EQ(output0[0].monotonic_event_time.boot, 0u);
2409 EXPECT_EQ(output0[0].monotonic_event_time.time,
2410 e + chrono::milliseconds(1000));
2411 EXPECT_EQ(output0[0].monotonic_remote_time.boot, 0u);
2412 EXPECT_EQ(output0[0].monotonic_remote_time.time,
2413 e + chrono::seconds(100) + chrono::milliseconds(1000));
2414 EXPECT_EQ(output0[0].monotonic_timestamp_time.boot, 0u);
2415 EXPECT_EQ(output0[0].monotonic_timestamp_time.time,
2416 e + chrono::seconds(100) + chrono::milliseconds(1001));
2417 EXPECT_TRUE(output0[0].data.Verify());
2418
2419 EXPECT_EQ(output0[1].monotonic_event_time.boot, 0u);
2420 EXPECT_EQ(output0[1].monotonic_event_time.time,
2421 e + chrono::milliseconds(2000));
2422 EXPECT_EQ(output0[1].monotonic_remote_time.boot, 1u);
2423 EXPECT_EQ(output0[1].monotonic_remote_time.time,
2424 e + chrono::seconds(20) + chrono::milliseconds(2000));
2425 EXPECT_EQ(output0[1].monotonic_timestamp_time.boot, 0u);
2426 EXPECT_EQ(output0[1].monotonic_timestamp_time.time,
2427 e + chrono::seconds(20) + chrono::milliseconds(2001));
2428 EXPECT_TRUE(output0[1].data.Verify());
2429
2430 EXPECT_EQ(output0[2].monotonic_event_time.boot, 0u);
2431 EXPECT_EQ(output0[2].monotonic_event_time.time,
2432 e + chrono::milliseconds(3000));
2433 EXPECT_EQ(output0[2].monotonic_remote_time.boot, 1u);
2434 EXPECT_EQ(output0[2].monotonic_remote_time.time,
2435 e + chrono::seconds(20) + chrono::milliseconds(3000));
2436 EXPECT_EQ(output0[2].monotonic_timestamp_time.boot, 0u);
2437 EXPECT_EQ(output0[2].monotonic_timestamp_time.time,
2438 e + chrono::seconds(20) + chrono::milliseconds(3001));
2439 EXPECT_TRUE(output0[2].data.Verify());
2440 }
2441
2442 {
2443 SCOPED_TRACE("Trying node1 now");
2444 std::deque<TimestampedMessage> output1;
2445
2446 EXPECT_EQ(mapper0_count, 3u);
2447 EXPECT_EQ(mapper1_count, 0u);
2448
2449 ASSERT_TRUE(mapper1.Front() != nullptr);
2450 EXPECT_EQ(mapper0_count, 3u);
2451 EXPECT_EQ(mapper1_count, 1u);
2452 output1.emplace_back(std::move(*mapper1.Front()));
2453 mapper1.PopFront();
2454 EXPECT_TRUE(mapper1.started());
2455 EXPECT_EQ(mapper0_count, 3u);
2456 EXPECT_EQ(mapper1_count, 1u);
2457
2458 ASSERT_TRUE(mapper1.Front() != nullptr);
2459 EXPECT_EQ(mapper0_count, 3u);
2460 EXPECT_EQ(mapper1_count, 2u);
2461 output1.emplace_back(std::move(*mapper1.Front()));
2462 mapper1.PopFront();
2463 EXPECT_TRUE(mapper1.started());
2464
2465 ASSERT_TRUE(mapper1.Front() != nullptr);
2466 output1.emplace_back(std::move(*mapper1.Front()));
2467 mapper1.PopFront();
2468 EXPECT_TRUE(mapper1.started());
2469
2470 EXPECT_EQ(mapper0_count, 3u);
2471 EXPECT_EQ(mapper1_count, 3u);
2472
2473 ASSERT_TRUE(mapper1.Front() == nullptr);
2474
2475 EXPECT_EQ(mapper0_count, 3u);
2476 EXPECT_EQ(mapper1_count, 3u);
2477
2478 EXPECT_EQ(output1[0].monotonic_event_time.boot, 0u);
2479 EXPECT_EQ(output1[0].monotonic_event_time.time,
2480 e + chrono::seconds(100) + chrono::milliseconds(1000));
2481 EXPECT_EQ(output1[0].monotonic_remote_time, BootTimestamp::min_time());
2482 EXPECT_EQ(output1[0].monotonic_timestamp_time, BootTimestamp::min_time());
2483 EXPECT_TRUE(output1[0].data.Verify());
2484
2485 EXPECT_EQ(output1[1].monotonic_event_time.boot, 1u);
2486 EXPECT_EQ(output1[1].monotonic_event_time.time,
2487 e + chrono::seconds(20) + chrono::milliseconds(2000));
2488 EXPECT_EQ(output1[1].monotonic_remote_time, BootTimestamp::min_time());
2489 EXPECT_EQ(output1[1].monotonic_timestamp_time, BootTimestamp::min_time());
2490 EXPECT_TRUE(output1[1].data.Verify());
2491
2492 EXPECT_EQ(output1[2].monotonic_event_time.boot, 1u);
2493 EXPECT_EQ(output1[2].monotonic_event_time.time,
2494 e + chrono::seconds(20) + chrono::milliseconds(3000));
2495 EXPECT_EQ(output1[2].monotonic_remote_time, BootTimestamp::min_time());
2496 EXPECT_EQ(output1[2].monotonic_timestamp_time, BootTimestamp::min_time());
2497 EXPECT_TRUE(output1[2].data.Verify());
2498
2499 LOG(INFO) << output1[0];
2500 LOG(INFO) << output1[1];
2501 LOG(INFO) << output1[2];
2502 }
2503}
2504
Austin Schuhc243b422020-10-11 15:35:08 -07002505} // namespace testing
2506} // namespace logger
2507} // namespace aos