Update log file header size when rotating
This was being masked before by data and timestamps being put in the
same file. Data was always bigger than the header size, so we never had
an issue.
Now, when we do a rotation, update the header size before rotating.
Change-Id: I81d7372ee8bda935d1f4f2a28c5e79fa0c225d06
Signed-off-by: James Kuszmaul <james.kuszmaul@bluerivertech.com>
diff --git a/aos/events/logging/BUILD b/aos/events/logging/BUILD
index 3bed5c4..d4c361f 100644
--- a/aos/events/logging/BUILD
+++ b/aos/events/logging/BUILD
@@ -725,6 +725,21 @@
deps = ["//aos/events:aos_config"],
)
+aos_config(
+ name = "multinode_pingpong_pi3_pingpong_config",
+ src = "multinode_pingpong_pi3_pingpong.json",
+ flatbuffers = [
+ "//aos/events:ping_fbs",
+ "//aos/events:pong_fbs",
+ "//aos/network:message_bridge_client_fbs",
+ "//aos/network:message_bridge_server_fbs",
+ "//aos/network:remote_message_fbs",
+ "//aos/network:timestamp_fbs",
+ ],
+ target_compatible_with = ["@platforms//os:linux"],
+ deps = ["//aos/events:aos_config"],
+)
+
cc_test(
name = "realtime_replay_test",
srcs = ["realtime_replay_test.cc"],
@@ -769,6 +784,7 @@
}),
data = [
":multinode_pingpong_combined_config",
+ ":multinode_pingpong_pi3_pingpong_config",
":multinode_pingpong_reboot_ooo_config",
":multinode_pingpong_split3_config",
":multinode_pingpong_split4_config",
diff --git a/aos/events/logging/log_namer.cc b/aos/events/logging/log_namer.cc
index 679d364..edfcc83 100644
--- a/aos/events/logging/log_namer.cc
+++ b/aos/events/logging/log_namer.cc
@@ -58,9 +58,17 @@
if (header_written_) {
VLOG(1) << "Rotated " << name();
++parts_index_;
+
+ aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> header =
+ MakeHeader();
+
+ if (header.span().size() > max_message_size_) {
+ max_message_size_ = header.span().size();
+ }
+
reopen_(this);
header_written_ = false;
- QueueHeader(MakeHeader());
+ QueueHeader(std::move(header));
}
}
@@ -307,6 +315,7 @@
CHECK(writer);
CHECK(header_written_) << ": Attempting to write message before header to "
<< writer->name();
+ CHECK_LE(coppier->size(), max_message_size_);
writer->CopyMessage(coppier, now);
}
@@ -353,6 +362,7 @@
CHECK(writer);
DataEncoder::SpanCopier coppier(header.span());
+ CHECK_LE(coppier.size(), max_message_size_);
writer->CopyMessage(&coppier, aos::monotonic_clock::now());
header_written_ = true;
monotonic_start_time_ = log_namer_->monotonic_start_time(
diff --git a/aos/events/logging/multinode_logger_test.cc b/aos/events/logging/multinode_logger_test.cc
index 48f1b8b..64abfe7 100644
--- a/aos/events/logging/multinode_logger_test.cc
+++ b/aos/events/logging/multinode_logger_test.cc
@@ -4374,6 +4374,98 @@
auto result = ConfirmReadable(filenames);
}
+// Class to spam Pong messages blindly.
+class PongSender {
+ public:
+ PongSender(EventLoop *loop, std::string_view channel_name)
+ : sender_(loop->MakeSender<examples::Pong>(channel_name)) {
+ loop->AddPhasedLoop(
+ [this](int) {
+ aos::Sender<examples::Pong>::Builder builder = sender_.MakeBuilder();
+ examples::Pong::Builder pong_builder =
+ builder.MakeBuilder<examples::Pong>();
+ CHECK_EQ(builder.Send(pong_builder.Finish()), RawSender::Error::kOk);
+ },
+ chrono::milliseconds(10));
+ }
+
+ private:
+ aos::Sender<examples::Pong> sender_;
+};
+
+// Tests that we log correctly as nodes connect slowly.
+TEST(MultinodeLoggerLoopTest, StaggeredConnect) {
+ aos::FlatbufferDetachedBuffer<aos::Configuration> config =
+ aos::configuration::ReadConfig(ArtifactPath(
+ "aos/events/logging/multinode_pingpong_pi3_pingpong_config.json"));
+ message_bridge::TestingTimeConverter time_converter(
+ configuration::NodesCount(&config.message()));
+ SimulatedEventLoopFactory event_loop_factory(&config.message());
+ event_loop_factory.SetTimeConverter(&time_converter);
+
+ time_converter.StartEqual();
+
+ const std::string kLogfile1_1 =
+ aos::testing::TestTmpDir() + "/multi_logfile1/";
+ util::UnlinkRecursive(kLogfile1_1);
+
+ NodeEventLoopFactory *const pi1 =
+ event_loop_factory.GetNodeEventLoopFactory("pi1");
+ NodeEventLoopFactory *const pi2 =
+ event_loop_factory.GetNodeEventLoopFactory("pi2");
+ NodeEventLoopFactory *const pi3 =
+ event_loop_factory.GetNodeEventLoopFactory("pi3");
+
+ // What we want is for pi2 to send a message at t=1000 on the first channel
+ // (/atest1 pong), and t=1 on the second channel (/atest3 pong). That'll make
+ // the max out of order duration be large.
+ //
+ // Then, we disconnect, and only send messages on a third channel
+ // (/atest2 pong). The order is key, they need to sort in this order in the
+ // config so we observe them in the order which grows the
+ // max_out_of_order_duration.
+
+ pi1->Disconnect(pi2->node());
+ pi2->Disconnect(pi1->node());
+
+ pi1->Disconnect(pi3->node());
+ pi3->Disconnect(pi1->node());
+
+ std::vector<std::string> filenames;
+ pi2->AlwaysStart<PongSender>("pongsender", "/test2");
+ pi3->AlwaysStart<PongSender>("pongsender", "/test3");
+
+ event_loop_factory.RunFor(chrono::seconds(10));
+
+ {
+ // Now start a receiving node first. This sets up 2 tight bounds between
+ // 2 of the nodes.
+ LoggerState pi1_logger = MakeLoggerState(
+ pi1, &event_loop_factory, SupportedCompressionAlgorithms()[0]);
+ pi1_logger.StartLogger(kLogfile1_1);
+
+ event_loop_factory.RunFor(chrono::seconds(10));
+
+ // Now, reconnect, and everything should recover.
+ pi1->Connect(pi2->node());
+ pi2->Connect(pi1->node());
+
+ event_loop_factory.RunFor(chrono::seconds(10));
+
+ pi1->Connect(pi3->node());
+ pi3->Connect(pi1->node());
+
+ event_loop_factory.RunFor(chrono::seconds(10));
+
+ pi1_logger.AppendAllFilenames(&filenames);
+ }
+
+ // Make sure we can read this.
+ const std::vector<LogFile> sorted_parts = SortParts(filenames);
+ EXPECT_TRUE(AllPartsMatchOutOfOrderDuration(sorted_parts));
+ auto result = ConfirmReadable(filenames);
+}
+
} // namespace testing
} // namespace logger
} // namespace aos
diff --git a/aos/events/logging/multinode_pingpong_pi3_pingpong.json b/aos/events/logging/multinode_pingpong_pi3_pingpong.json
new file mode 100644
index 0000000..336b328
--- /dev/null
+++ b/aos/events/logging/multinode_pingpong_pi3_pingpong.json
@@ -0,0 +1,312 @@
+{
+ "channels": [
+ {
+ "name": "/pi1/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi1",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/pi2/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi2",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/pi3/aos",
+ "type": "aos.logging.LogMessageFbs",
+ "source_node": "pi3",
+ "frequency": 200,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ /* Logged on pi1 locally */
+ {
+ "name": "/pi1/aos",
+ "type": "aos.timing.Report",
+ "source_node": "pi1",
+ "frequency": 50,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/pi2/aos",
+ "type": "aos.timing.Report",
+ "source_node": "pi2",
+ "frequency": 50,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/pi3/aos",
+ "type": "aos.timing.Report",
+ "source_node": "pi3",
+ "frequency": 50,
+ "num_senders": 20,
+ "max_size": 2048
+ },
+ {
+ "name": "/pi1/aos",
+ "type": "aos.message_bridge.ServerStatistics",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi1"
+ },
+ {
+ "name": "/pi2/aos",
+ "type": "aos.message_bridge.ServerStatistics",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi2"
+ },
+ {
+ "name": "/pi3/aos",
+ "type": "aos.message_bridge.ServerStatistics",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi3"
+ },
+ {
+ "name": "/pi1/aos",
+ "type": "aos.logging.DynamicLogCommand",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi1"
+ },
+ {
+ "name": "/pi2/aos",
+ "type": "aos.logging.DynamicLogCommand",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi2"
+ },
+ {
+ "name": "/pi3/aos",
+ "type": "aos.logging.DynamicLogCommand",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi3"
+ },
+ {
+ "name": "/pi1/aos",
+ "type": "aos.message_bridge.ClientStatistics",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi1"
+ },
+ {
+ "name": "/pi2/aos",
+ "type": "aos.message_bridge.ClientStatistics",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi2"
+ },
+ {
+ "name": "/pi3/aos",
+ "type": "aos.message_bridge.ClientStatistics",
+ "logger": "LOCAL_LOGGER",
+ "source_node": "pi3"
+ },
+ {
+ "name": "/pi1/aos",
+ "type": "aos.message_bridge.Timestamp",
+ "logger": "LOCAL_AND_REMOTE_LOGGER",
+ "logger_nodes": ["pi2"],
+ "source_node": "pi1",
+ "destination_nodes": [
+ {
+ "name": "pi2",
+ "timestamp_logger": "LOCAL_AND_REMOTE_LOGGER",
+ "timestamp_logger_nodes": ["pi1"]
+ },
+ {
+ "name": "pi3",
+ "timestamp_logger": "LOCAL_AND_REMOTE_LOGGER",
+ "timestamp_logger_nodes": ["pi1"]
+ }
+ ]
+ },
+ {
+ "name": "/pi2/aos",
+ "type": "aos.message_bridge.Timestamp",
+ "logger": "LOCAL_AND_REMOTE_LOGGER",
+ "logger_nodes": ["pi1"],
+ "source_node": "pi2",
+ "destination_nodes": [
+ {
+ "name": "pi1",
+ "timestamp_logger": "LOCAL_AND_REMOTE_LOGGER",
+ "timestamp_logger_nodes": ["pi2"]
+ }
+ ]
+ },
+ {
+ "name": "/pi3/aos",
+ "type": "aos.message_bridge.Timestamp",
+ "logger": "LOCAL_AND_REMOTE_LOGGER",
+ "logger_nodes": ["pi1"],
+ "source_node": "pi3",
+ "destination_nodes": [
+ {
+ "name": "pi1",
+ "timestamp_logger": "LOCAL_AND_REMOTE_LOGGER",
+ "timestamp_logger_nodes": ["pi3"]
+ }
+ ]
+ },
+ {
+ "name": "/pi1/aos/remote_timestamps/pi2/pi1/aos/aos-message_bridge-Timestamp",
+ "type": "aos.message_bridge.RemoteMessage",
+ "logger": "NOT_LOGGED",
+ "num_senders": 2,
+ "source_node": "pi1"
+ },
+ {
+ "name": "/pi1/aos/remote_timestamps/pi3/pi1/aos/aos-message_bridge-Timestamp",
+ "type": "aos.message_bridge.RemoteMessage",
+ "logger": "NOT_LOGGED",
+ "num_senders": 2,
+ "source_node": "pi1"
+ },
+ {
+ "name": "/pi2/aos/remote_timestamps/pi1/pi2/aos/aos-message_bridge-Timestamp",
+ "type": "aos.message_bridge.RemoteMessage",
+ "logger": "NOT_LOGGED",
+ "num_senders": 2,
+ "source_node": "pi2"
+ },
+ {
+ "name": "/pi3/aos/remote_timestamps/pi1/pi3/aos/aos-message_bridge-Timestamp",
+ "type": "aos.message_bridge.RemoteMessage",
+ "logger": "NOT_LOGGED",
+ "num_senders": 2,
+ "source_node": "pi3"
+ },
+ {
+ "name": "/pi1/aos/remote_timestamps/pi2/test2/aos-examples-Ping",
+ "type": "aos.message_bridge.RemoteMessage",
+ "logger": "NOT_LOGGED",
+ "num_senders": 2,
+ "source_node": "pi1",
+ "frequency": 150
+ },
+ {
+ "name": "/pi1/aos/remote_timestamps/pi3/test3/aos-examples-Ping",
+ "type": "aos.message_bridge.RemoteMessage",
+ "logger": "NOT_LOGGED",
+ "num_senders": 2,
+ "source_node": "pi1",
+ "frequency": 150
+ },
+ /* Forwarded to pi2 */
+ {
+ "name": "/test2",
+ "type": "aos.examples.Ping",
+ "source_node": "pi1",
+ "destination_nodes": [
+ {
+ "name": "pi2",
+ "priority": 1,
+ "timestamp_logger": "LOCAL_AND_REMOTE_LOGGER",
+ "timestamp_logger_nodes": [
+ "pi1"
+ ],
+ "time_to_live": 5000000
+ }
+ ],
+ "frequency": 150
+ },
+ {
+ "name": "/test2",
+ "type": "aos.examples.Pong",
+ "source_node": "pi2",
+ "logger": "LOCAL_AND_REMOTE_LOGGER",
+ "logger_nodes": ["pi1"],
+ "destination_nodes": [
+ {
+ "name": "pi1",
+ "priority": 1,
+ "timestamp_logger": "LOCAL_LOGGER",
+ "time_to_live": 5000000
+ }
+ ],
+ "frequency": 150
+ },
+ /* Forwarded to pi3 */
+ {
+ "name": "/test3",
+ "type": "aos.examples.Ping",
+ "source_node": "pi1",
+ "destination_nodes": [
+ {
+ "name": "pi3",
+ "priority": 1,
+ "timestamp_logger": "LOCAL_AND_REMOTE_LOGGER",
+ "timestamp_logger_nodes": [
+ "pi1"
+ ],
+ "time_to_live": 5000000
+ }
+ ],
+ "frequency": 150
+ },
+ {
+ "name": "/test3",
+ "type": "aos.examples.Pong",
+ "source_node": "pi3",
+ "logger": "LOCAL_AND_REMOTE_LOGGER",
+ "logger_nodes": ["pi1"],
+ "destination_nodes": [
+ {
+ "name": "pi1",
+ "priority": 1,
+ "timestamp_logger": "LOCAL_LOGGER",
+ "time_to_live": 5000000
+ }
+ ],
+ "frequency": 150
+ }
+ ],
+ "maps": [
+ {
+ "match": {
+ "name": "/aos*",
+ "source_node": "pi1"
+ },
+ "rename": {
+ "name": "/pi1/aos"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos*",
+ "source_node": "pi2"
+ },
+ "rename": {
+ "name": "/pi2/aos"
+ }
+ },
+ {
+ "match": {
+ "name": "/aos*",
+ "source_node": "pi3"
+ },
+ "rename": {
+ "name": "/pi3/aos"
+ }
+ }
+ ],
+ "nodes": [
+ {
+ "name": "pi1",
+ "hostname": "raspberrypi",
+ "port": 9971
+ },
+ {
+ "name": "pi2",
+ "hostname": "raspberrypi2",
+ "port": 9971
+ },
+ {
+ "name": "pi3",
+ "hostname": "raspberrypi3",
+ "port": 9971
+ }
+ ]
+}