aos: Fix `--force_timestamp_loading` for single-node logs
We're currently seeing a bunch of segfaults in log-reading code.
This is happening because the timestamp loading code
performs some checks against a list of source nodes. This list was
only populated for multi-node logs.
The fix here is to populate the list (with zeroes) even for
single-node logs. That lets the code proceed happily.
Before this patch I got the following crash for the new test:
$ bazel test --config=strict_ubsan @aos//aos/events/logging:logfile_utils_test -c opt
...
[ RUN ] SingleNodeTimestampMapperTest.QueueTimestampsForSingleNodes
external/llvm_k8/include/c++/v1/vector:1548:12: runtime error: reference binding to null pointer of type 'const value_type' (aka 'const unsigned long')
#0 0x7f404ba4197e (/data/phil_cache/bazel/_bazel_philipp/d441cd67cd5f527804d5d757edac2e45/execroot/shasta/bazel-out/k8-opt-ubsan/bin/external/aos/aos/events/logging/../../../../../_solib_k8/libexternal_Saos_Saos_Sevents_Slogging_Sliblogfile_Uutils.so+0x24197e) (BuildId: 64e54686062e7b4cd33e15bb59eb809a)
References: PRO-26639
Change-Id: I5a28f09af4f77da9b9aa2f36030394bd6d7e2e77
Signed-off-by: James Kuszmaul <james.kuszmaul@bluerivertech.com>
diff --git a/aos/events/logging/logfile_utils_test.cc b/aos/events/logging/logfile_utils_test.cc
index 0c1cafd..4ceca20 100644
--- a/aos/events/logging/logfile_utils_test.cc
+++ b/aos/events/logging/logfile_utils_test.cc
@@ -326,11 +326,44 @@
return fbb2.Release();
}
+// Allows for some customization of a SortingElementTest.
+enum class SortingElementConfig {
+ // Create a single node configuration.
+ kSingleNode,
+ // Create a multi-node configuration.
+ kMultiNode,
+};
+
+template <SortingElementConfig sorting_element_config =
+ SortingElementConfig::kMultiNode>
class SortingElementTest : public ::testing::Test {
public:
SortingElementTest()
: config_(JsonToFlatbuffer<Configuration>(
- R"({
+ sorting_element_config == SortingElementConfig::kSingleNode ?
+ R"({
+ "channels": [
+ {
+ "name": "/a",
+ "type": "aos.logger.testing.TestMessage"
+ },
+ {
+ "name": "/b",
+ "type": "aos.logger.testing.TestMessage"
+ },
+ {
+ "name": "/c",
+ "type": "aos.logger.testing.TestMessage"
+ },
+ {
+ "name": "/d",
+ "type": "aos.logger.testing.TestMessage"
+ }
+ ]
+}
+)"
+ :
+ R"({
"channels": [
{
"name": "/a",
@@ -379,7 +412,31 @@
]
}
)")),
- config0_(MakeHeader(config_, R"({
+ config0_(MakeHeader(
+ config_, sorting_element_config == SortingElementConfig::kSingleNode
+ ?
+ R"({
+ /* 100ms */
+ "max_out_of_order_duration": 100000000,
+ "node": {
+ "name": "pi1"
+ },
+ "logger_node": {
+ "name": "pi1"
+ },
+ "monotonic_start_time": 1000000,
+ "realtime_start_time": 1000000000000,
+ "log_event_uuid": "30ef1283-81d7-4004-8c36-1c162dbcb2b2",
+ "source_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
+ "logger_node_boot_uuid": "1d782c63-b3c7-466e-bea9-a01308b43333",
+ "boot_uuids": [
+ "1d782c63-b3c7-466e-bea9-a01308b43333",
+ ],
+ "parts_uuid": "2a05d725-5d5c-4c0b-af42-88de2f3c3876",
+ "parts_index": 0
+})"
+ :
+ R"({
/* 100ms */
"max_out_of_order_duration": 100000000,
"node": {
@@ -593,10 +650,13 @@
std::vector<uint32_t> queue_index_;
};
-using MessageSorterTest = SortingElementTest;
+using MessageSorterTest = SortingElementTest<SortingElementConfig::kMultiNode>;
using MessageSorterDeathTest = MessageSorterTest;
-using PartsMergerTest = SortingElementTest;
-using TimestampMapperTest = SortingElementTest;
+using PartsMergerTest = SortingElementTest<SortingElementConfig::kMultiNode>;
+using TimestampMapperTest =
+ SortingElementTest<SortingElementConfig::kMultiNode>;
+using SingleNodeTimestampMapperTest =
+ SortingElementTest<SortingElementConfig::kSingleNode>;
// Tests that we can pull messages out of a log sorted in order.
TEST_F(MessageSorterTest, Pull) {
@@ -2065,7 +2125,44 @@
}
}
-class BootMergerTest : public SortingElementTest {
+// Validates that we can read timestamps on startup even for single-node logs.
+TEST_F(SingleNodeTimestampMapperTest, QueueTimestampsForSingleNodes) {
+ const aos::monotonic_clock::time_point e = monotonic_clock::epoch();
+ {
+ TestDetachedBufferWriter writer0(logfile0_);
+ writer0.QueueSpan(config0_.span());
+
+ writer0.WriteSizedFlatbuffer(
+ MakeLogMessage(e + chrono::milliseconds(1000), 0, 0x005));
+ writer0.WriteSizedFlatbuffer(
+ MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x006));
+ writer0.WriteSizedFlatbuffer(
+ MakeLogMessage(e + chrono::milliseconds(2000), 0, 0x007));
+ writer0.WriteSizedFlatbuffer(
+ MakeLogMessage(e + chrono::milliseconds(3000), 0, 0x008));
+ }
+
+ const std::vector<LogFile> parts = SortParts({logfile0_});
+ LogFilesContainer log_files(parts);
+
+ ASSERT_EQ(parts[0].logger_node, "pi1");
+
+ size_t mapper0_count = 0;
+ TimestampMapper mapper0("pi1", log_files,
+ TimestampQueueStrategy::kQueueTimestampsAtStartup);
+ mapper0.set_timestamp_callback(
+ [&](TimestampedMessage *) { ++mapper0_count; });
+ mapper0.QueueTimestamps();
+
+ for (int i = 0; i < 4; ++i) {
+ ASSERT_TRUE(mapper0.Front() != nullptr);
+ mapper0.PopFront();
+ }
+ EXPECT_TRUE(mapper0.Front() == nullptr);
+ EXPECT_EQ(mapper0_count, 4u);
+}
+
+class BootMergerTest : public SortingElementTest<> {
public:
BootMergerTest()
: SortingElementTest(),
@@ -2204,7 +2301,7 @@
EXPECT_EQ(output[3].timestamp.time, e + chrono::milliseconds(200));
}
-class RebootTimestampMapperTest : public SortingElementTest {
+class RebootTimestampMapperTest : public SortingElementTest<> {
public:
RebootTimestampMapperTest()
: SortingElementTest(),
@@ -2730,7 +2827,7 @@
}
}
-class SortingDeathTest : public SortingElementTest {
+class SortingDeathTest : public SortingElementTest<> {
public:
SortingDeathTest()
: SortingElementTest(),