blob: 1383aeda49dbe00058b6c2c301384b530f707fe8 [file] [log] [blame]
Austin Schuhcb5601b2020-09-10 15:29:59 -07001#include "aos/events/logging/log_namer.h"
2
3#include <functional>
4#include <map>
5#include <memory>
6#include <string_view>
7#include <vector>
8
9#include "absl/strings/str_cat.h"
10#include "aos/events/logging/logfile_utils.h"
11#include "aos/events/logging/logger_generated.h"
Austin Schuh73340842021-07-30 22:32:06 -070012#include "aos/flatbuffer_merge.h"
Austin Schuh4385b142021-03-14 21:31:13 -070013#include "aos/uuid.h"
Austin Schuhcb5601b2020-09-10 15:29:59 -070014#include "flatbuffers/flatbuffers.h"
15#include "glog/logging.h"
16
17namespace aos {
18namespace logger {
19
Austin Schuh572924a2021-07-30 22:32:12 -070020NewDataWriter::NewDataWriter(LogNamer *log_namer, const Node *node,
21 std::function<void(NewDataWriter *)> reopen,
22 std::function<void(NewDataWriter *)> close)
23 : node_(node),
24 node_index_(configuration::GetNodeIndex(log_namer->configuration_, node)),
25 log_namer_(log_namer),
26 reopen_(std::move(reopen)),
27 close_(std::move(close)) {
Austin Schuh72211ae2021-08-05 14:02:30 -070028 state_.resize(configuration::NodesCount(log_namer->configuration_));
29 CHECK_LT(node_index_, state_.size());
Austin Schuh572924a2021-07-30 22:32:12 -070030}
31
32NewDataWriter::~NewDataWriter() {
33 if (writer) {
34 Close();
35 }
36}
37
38void NewDataWriter::Rotate() {
Austin Schuhe46492f2021-07-31 19:49:41 -070039 // No need to rotate if nothing has been written.
40 if (header_written_) {
Austin Schuh58646e22021-08-23 23:51:46 -070041 VLOG(1) << "Rotated " << filename();
Austin Schuhe46492f2021-07-31 19:49:41 -070042 ++parts_index_;
43 reopen_(this);
44 header_written_ = false;
45 QueueHeader(MakeHeader());
46 }
Austin Schuh572924a2021-07-30 22:32:12 -070047}
48
49void NewDataWriter::Reboot() {
50 parts_uuid_ = UUID::Random();
51 ++parts_index_;
52 reopen_(this);
53 header_written_ = false;
54}
55
Austin Schuh72211ae2021-08-05 14:02:30 -070056void NewDataWriter::UpdateRemote(
57 const size_t remote_node_index, const UUID &remote_node_boot_uuid,
58 const monotonic_clock::time_point monotonic_remote_time,
59 const monotonic_clock::time_point monotonic_event_time,
60 const bool reliable) {
Austin Schuh58646e22021-08-23 23:51:46 -070061 // Trigger rotation if anything in the header changes.
Austin Schuh72211ae2021-08-05 14:02:30 -070062 bool rotate = false;
63 CHECK_LT(remote_node_index, state_.size());
64 State &state = state_[remote_node_index];
Austin Schuh58646e22021-08-23 23:51:46 -070065
66 // Did the remote boot UUID change?
Austin Schuh72211ae2021-08-05 14:02:30 -070067 if (state.boot_uuid != remote_node_boot_uuid) {
Austin Schuhe46492f2021-07-31 19:49:41 -070068 VLOG(1) << filename() << " Remote " << remote_node_index << " updated to "
Austin Schuh72211ae2021-08-05 14:02:30 -070069 << remote_node_boot_uuid << " from " << state.boot_uuid;
70 state.boot_uuid = remote_node_boot_uuid;
71 state.oldest_remote_monotonic_timestamp = monotonic_clock::max_time;
72 state.oldest_local_monotonic_timestamp = monotonic_clock::max_time;
73 state.oldest_remote_unreliable_monotonic_timestamp =
74 monotonic_clock::max_time;
75 state.oldest_local_unreliable_monotonic_timestamp =
76 monotonic_clock::max_time;
77 rotate = true;
78 }
79
Austin Schuh58646e22021-08-23 23:51:46 -070080
81 // Did the unreliable timestamps change?
Austin Schuh72211ae2021-08-05 14:02:30 -070082 if (!reliable) {
83 if (state.oldest_remote_unreliable_monotonic_timestamp >
84 monotonic_remote_time) {
Austin Schuh58646e22021-08-23 23:51:46 -070085 VLOG(1) << filename() << " Remote " << remote_node_index
86 << " oldest_remote_unreliable_monotonic_timestamp updated from "
87 << state.oldest_remote_unreliable_monotonic_timestamp << " to "
88 << monotonic_remote_time;
Austin Schuh72211ae2021-08-05 14:02:30 -070089 state.oldest_remote_unreliable_monotonic_timestamp =
90 monotonic_remote_time;
91 state.oldest_local_unreliable_monotonic_timestamp = monotonic_event_time;
92 rotate = true;
93 }
94 }
95
Austin Schuh58646e22021-08-23 23:51:46 -070096 // Did any of the timestamps change?
Austin Schuh72211ae2021-08-05 14:02:30 -070097 if (state.oldest_remote_monotonic_timestamp > monotonic_remote_time) {
Austin Schuh58646e22021-08-23 23:51:46 -070098 VLOG(1) << filename() << " Remote " << remote_node_index
99 << " oldest_remote_monotonic_timestamp updated from "
100 << state.oldest_remote_monotonic_timestamp << " to "
101 << monotonic_remote_time;
Austin Schuh72211ae2021-08-05 14:02:30 -0700102 state.oldest_remote_monotonic_timestamp = monotonic_remote_time;
103 state.oldest_local_monotonic_timestamp = monotonic_event_time;
104 rotate = true;
105 }
106
107 if (rotate) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700108 Rotate();
109 }
110}
111
112void NewDataWriter::QueueMessage(flatbuffers::FlatBufferBuilder *fbb,
113 const UUID &source_node_boot_uuid,
114 aos::monotonic_clock::time_point now) {
Austin Schuh58646e22021-08-23 23:51:46 -0700115 // Trigger a reboot if we detect the boot UUID change.
Austin Schuh72211ae2021-08-05 14:02:30 -0700116 if (state_[node_index_].boot_uuid != source_node_boot_uuid) {
117 state_[node_index_].boot_uuid = source_node_boot_uuid;
Austin Schuh572924a2021-07-30 22:32:12 -0700118 if (header_written_) {
119 Reboot();
120 }
121
Austin Schuhe46492f2021-07-31 19:49:41 -0700122 QueueHeader(MakeHeader());
Austin Schuh572924a2021-07-30 22:32:12 -0700123 }
Austin Schuh58646e22021-08-23 23:51:46 -0700124
125 // If the start time has changed for this node, trigger a rotation.
126 if (log_namer_->monotonic_start_time(node_index_, source_node_boot_uuid) !=
127 monotonic_start_time_) {
128 CHECK(header_written_);
129 Rotate();
130 }
131
132 CHECK_EQ(log_namer_->monotonic_start_time(node_index_, source_node_boot_uuid),
133 monotonic_start_time_);
Austin Schuh72211ae2021-08-05 14:02:30 -0700134 CHECK_EQ(state_[node_index_].boot_uuid, source_node_boot_uuid);
milind-ua50344f2021-08-25 18:22:20 -0700135 CHECK(writer);
Austin Schuh572924a2021-07-30 22:32:12 -0700136 CHECK(header_written_) << ": Attempting to write message before header to "
137 << writer->filename();
138 writer->QueueSizedFlatbuffer(fbb, now);
139}
140
Austin Schuhe46492f2021-07-31 19:49:41 -0700141aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader>
142NewDataWriter::MakeHeader() {
143 const size_t logger_node_index = log_namer_->logger_node_index();
144 const UUID &logger_node_boot_uuid = log_namer_->logger_node_boot_uuid();
Austin Schuh72211ae2021-08-05 14:02:30 -0700145 if (state_[logger_node_index].boot_uuid == UUID::Zero()) {
Austin Schuhe46492f2021-07-31 19:49:41 -0700146 VLOG(1) << filename() << " Logger node is " << logger_node_index
147 << " and uuid is " << logger_node_boot_uuid;
Austin Schuh72211ae2021-08-05 14:02:30 -0700148 state_[logger_node_index].boot_uuid = logger_node_boot_uuid;
Austin Schuhe46492f2021-07-31 19:49:41 -0700149 } else {
Austin Schuh72211ae2021-08-05 14:02:30 -0700150 CHECK_EQ(state_[logger_node_index].boot_uuid, logger_node_boot_uuid);
Austin Schuhe46492f2021-07-31 19:49:41 -0700151 }
Austin Schuh72211ae2021-08-05 14:02:30 -0700152 return log_namer_->MakeHeader(node_index_, state_, parts_uuid(),
Austin Schuhe46492f2021-07-31 19:49:41 -0700153 parts_index_);
154}
155
Austin Schuh572924a2021-07-30 22:32:12 -0700156void NewDataWriter::QueueHeader(
157 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> &&header) {
158 CHECK(!header_written_) << ": Attempting to write duplicate header to "
159 << writer->filename();
160 CHECK(header.message().has_source_node_boot_uuid());
Austin Schuh72211ae2021-08-05 14:02:30 -0700161 CHECK_EQ(state_[node_index_].boot_uuid,
Austin Schuhe46492f2021-07-31 19:49:41 -0700162 UUID::FromString(header.message().source_node_boot_uuid()));
Austin Schuh510dc622021-08-06 18:47:30 -0700163 if (!writer) {
164 reopen_(this);
165 }
166
Austin Schuh58646e22021-08-23 23:51:46 -0700167 VLOG(1) << "Writing to " << filename() << " "
168 << aos::FlatbufferToJson(
169 header, {.multi_line = false, .max_vector_size = 100});
170
Austin Schuh572924a2021-07-30 22:32:12 -0700171 // TODO(austin): This triggers a dummy allocation that we don't need as part
172 // of releasing. Can we skip it?
Austin Schuh510dc622021-08-06 18:47:30 -0700173 CHECK(writer);
Austin Schuh572924a2021-07-30 22:32:12 -0700174 writer->QueueSizedFlatbuffer(header.Release());
175 header_written_ = true;
Austin Schuh58646e22021-08-23 23:51:46 -0700176 monotonic_start_time_ = log_namer_->monotonic_start_time(
177 node_index_, state_[node_index_].boot_uuid);
Austin Schuh572924a2021-07-30 22:32:12 -0700178}
179
180void NewDataWriter::Close() {
181 CHECK(writer);
182 close_(this);
183 writer.reset();
184 header_written_ = false;
185}
186
Austin Schuh58646e22021-08-23 23:51:46 -0700187LogNamer::NodeState *LogNamer::GetNodeState(size_t node_index,
188 const UUID &boot_uuid) {
189 auto it = node_states_.find(std::make_pair(node_index, boot_uuid));
190 if (it == node_states_.end()) {
191 it =
192 node_states_.emplace(std::make_pair(node_index, boot_uuid), NodeState())
193 .first;
194 }
195 return &it->second;
196}
197
Austin Schuh73340842021-07-30 22:32:06 -0700198aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> LogNamer::MakeHeader(
Austin Schuh72211ae2021-08-05 14:02:30 -0700199 size_t node_index, const std::vector<NewDataWriter::State> &state,
Austin Schuh58646e22021-08-23 23:51:46 -0700200 const UUID &parts_uuid, int parts_index) {
Austin Schuh72211ae2021-08-05 14:02:30 -0700201 const UUID &source_node_boot_uuid = state[node_index].boot_uuid;
Austin Schuh73340842021-07-30 22:32:06 -0700202 const Node *const source_node =
203 configuration::GetNode(configuration_, node_index);
Austin Schuh72211ae2021-08-05 14:02:30 -0700204 CHECK_EQ(LogFileHeader::MiniReflectTypeTable()->num_elems, 24u);
Austin Schuh73340842021-07-30 22:32:06 -0700205 flatbuffers::FlatBufferBuilder fbb;
206 fbb.ForceDefaults(true);
207
208 flatbuffers::Offset<flatbuffers::String> config_sha256_offset;
209 flatbuffers::Offset<aos::Configuration> configuration_offset;
210 if (header_.message().has_configuration()) {
211 CHECK(!header_.message().has_configuration_sha256());
212 configuration_offset =
213 CopyFlatBuffer(header_.message().configuration(), &fbb);
214 } else {
215 CHECK(!header_.message().has_configuration());
216 CHECK(header_.message().has_configuration_sha256());
217 config_sha256_offset = fbb.CreateString(
218 header_.message().configuration_sha256()->string_view());
219 }
220
221 CHECK(header_.message().has_name());
222 const flatbuffers::Offset<flatbuffers::String> name_offset =
223 fbb.CreateString(header_.message().name()->string_view());
224
225 CHECK(header_.message().has_log_event_uuid());
226 const flatbuffers::Offset<flatbuffers::String> log_event_uuid_offset =
227 fbb.CreateString(header_.message().log_event_uuid()->string_view());
228
229 CHECK(header_.message().has_logger_instance_uuid());
230 const flatbuffers::Offset<flatbuffers::String> logger_instance_uuid_offset =
231 fbb.CreateString(header_.message().logger_instance_uuid()->string_view());
232
233 flatbuffers::Offset<flatbuffers::String> log_start_uuid_offset;
234 if (header_.message().has_log_start_uuid()) {
235 log_start_uuid_offset =
236 fbb.CreateString(header_.message().log_start_uuid()->string_view());
237 }
238
239 CHECK(header_.message().has_logger_node_boot_uuid());
240 const flatbuffers::Offset<flatbuffers::String> logger_node_boot_uuid_offset =
241 fbb.CreateString(
242 header_.message().logger_node_boot_uuid()->string_view());
243
244 CHECK_NE(source_node_boot_uuid, UUID::Zero());
245 const flatbuffers::Offset<flatbuffers::String> source_node_boot_uuid_offset =
246 source_node_boot_uuid.PackString(&fbb);
247
248 const flatbuffers::Offset<flatbuffers::String> parts_uuid_offset =
249 parts_uuid.PackString(&fbb);
250
251 flatbuffers::Offset<Node> node_offset;
252 flatbuffers::Offset<Node> logger_node_offset;
253
254 if (configuration::MultiNode(configuration_)) {
255 node_offset = RecursiveCopyFlatBuffer(source_node, &fbb);
256 logger_node_offset = RecursiveCopyFlatBuffer(node_, &fbb);
257 }
258
Austin Schuhe46492f2021-07-31 19:49:41 -0700259 std::vector<flatbuffers::Offset<flatbuffers::String>> boot_uuid_offsets;
Austin Schuh72211ae2021-08-05 14:02:30 -0700260 boot_uuid_offsets.reserve(state.size());
261 for (const NewDataWriter::State &state : state) {
262 if (state.boot_uuid != UUID::Zero()) {
263 boot_uuid_offsets.emplace_back(state.boot_uuid.PackString(&fbb));
Austin Schuhe46492f2021-07-31 19:49:41 -0700264 } else {
265 boot_uuid_offsets.emplace_back(fbb.CreateString(""));
266 }
267 }
268
269 flatbuffers::Offset<
270 flatbuffers::Vector<flatbuffers::Offset<flatbuffers::String>>>
271 boot_uuids_offset = fbb.CreateVector(boot_uuid_offsets);
272
Austin Schuh72211ae2021-08-05 14:02:30 -0700273 int64_t *oldest_remote_monotonic_timestamps;
274 flatbuffers::Offset<flatbuffers::Vector<int64_t>>
275 oldest_remote_monotonic_timestamps_offset = fbb.CreateUninitializedVector(
276 state.size(), &oldest_remote_monotonic_timestamps);
277
278 int64_t *oldest_local_monotonic_timestamps;
279 flatbuffers::Offset<flatbuffers::Vector<int64_t>>
280 oldest_local_monotonic_timestamps_offset = fbb.CreateUninitializedVector(
281 state.size(), &oldest_local_monotonic_timestamps);
282
283 int64_t *oldest_remote_unreliable_monotonic_timestamps;
284 flatbuffers::Offset<flatbuffers::Vector<int64_t>>
285 oldest_remote_unreliable_monotonic_timestamps_offset =
286 fbb.CreateUninitializedVector(
287 state.size(), &oldest_remote_unreliable_monotonic_timestamps);
288
289 int64_t *oldest_local_unreliable_monotonic_timestamps;
290 flatbuffers::Offset<flatbuffers::Vector<int64_t>>
291 oldest_local_unreliable_monotonic_timestamps_offset =
292 fbb.CreateUninitializedVector(
293 state.size(), &oldest_local_unreliable_monotonic_timestamps);
294
295 for (size_t i = 0; i < state.size(); ++i) {
Austin Schuh5ae8f4a2021-09-11 19:09:50 -0700296 if (state[i].boot_uuid == UUID::Zero()) {
297 CHECK_EQ(state[i].oldest_remote_monotonic_timestamp,
298 monotonic_clock::max_time);
299 CHECK_EQ(state[i].oldest_local_monotonic_timestamp,
300 monotonic_clock::max_time);
301 CHECK_EQ(state[i].oldest_remote_unreliable_monotonic_timestamp,
302 monotonic_clock::max_time);
303 CHECK_EQ(state[i].oldest_local_unreliable_monotonic_timestamp,
304 monotonic_clock::max_time);
305 }
306
Austin Schuh72211ae2021-08-05 14:02:30 -0700307 oldest_remote_monotonic_timestamps[i] =
308 state[i].oldest_remote_monotonic_timestamp.time_since_epoch().count();
309 oldest_local_monotonic_timestamps[i] =
310 state[i].oldest_local_monotonic_timestamp.time_since_epoch().count();
311 oldest_remote_unreliable_monotonic_timestamps[i] =
312 state[i]
313 .oldest_remote_unreliable_monotonic_timestamp.time_since_epoch()
314 .count();
315 oldest_local_unreliable_monotonic_timestamps[i] =
316 state[i]
317 .oldest_local_unreliable_monotonic_timestamp.time_since_epoch()
318 .count();
319 }
320
Austin Schuh73340842021-07-30 22:32:06 -0700321 aos::logger::LogFileHeader::Builder log_file_header_builder(fbb);
322
323 log_file_header_builder.add_name(name_offset);
324
325 // Only add the node if we are running in a multinode configuration.
326 if (!logger_node_offset.IsNull()) {
327 log_file_header_builder.add_node(node_offset);
328 log_file_header_builder.add_logger_node(logger_node_offset);
329 }
330
331 if (!configuration_offset.IsNull()) {
332 log_file_header_builder.add_configuration(configuration_offset);
333 }
334 log_file_header_builder.add_max_out_of_order_duration(
335 header_.message().max_out_of_order_duration());
336
Austin Schuh58646e22021-08-23 23:51:46 -0700337 NodeState *node_state = GetNodeState(node_index, source_node_boot_uuid);
Austin Schuh73340842021-07-30 22:32:06 -0700338 log_file_header_builder.add_monotonic_start_time(
339 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700340 node_state->monotonic_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700341 .count());
342 if (source_node == node_) {
343 log_file_header_builder.add_realtime_start_time(
344 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700345 node_state->realtime_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700346 .count());
347 } else {
348 // Fill out the legacy start times. Since these were implemented to never
349 // change on reboot, they aren't very helpful in tracking what happened.
350 log_file_header_builder.add_logger_monotonic_start_time(
351 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700352 node_state->logger_monotonic_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700353 .count());
354 log_file_header_builder.add_logger_realtime_start_time(
355 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700356 node_state->logger_realtime_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700357 .count());
358 }
359
360 // TODO(austin): Add more useful times. When was this part started? What do
361 // we know about both the logger and remote then?
362
363 log_file_header_builder.add_log_event_uuid(log_event_uuid_offset);
364 log_file_header_builder.add_logger_instance_uuid(logger_instance_uuid_offset);
365 if (!log_start_uuid_offset.IsNull()) {
366 log_file_header_builder.add_log_start_uuid(log_start_uuid_offset);
367 }
368 log_file_header_builder.add_logger_node_boot_uuid(
369 logger_node_boot_uuid_offset);
370 log_file_header_builder.add_source_node_boot_uuid(
371 source_node_boot_uuid_offset);
372
373 log_file_header_builder.add_parts_uuid(parts_uuid_offset);
374 log_file_header_builder.add_parts_index(parts_index);
375
376 if (!config_sha256_offset.IsNull()) {
377 log_file_header_builder.add_configuration_sha256(config_sha256_offset);
378 }
379
Austin Schuhe46492f2021-07-31 19:49:41 -0700380 log_file_header_builder.add_boot_uuids(boot_uuids_offset);
Austin Schuha499cea2021-07-31 19:49:53 -0700381 log_file_header_builder.add_logger_part_monotonic_start_time(
382 std::chrono::duration_cast<std::chrono::nanoseconds>(
383 event_loop_->monotonic_now().time_since_epoch())
384 .count());
385 log_file_header_builder.add_logger_part_realtime_start_time(
386 std::chrono::duration_cast<std::chrono::nanoseconds>(
387 event_loop_->realtime_now().time_since_epoch())
388 .count());
Austin Schuh72211ae2021-08-05 14:02:30 -0700389 log_file_header_builder.add_oldest_remote_monotonic_timestamps(
390 oldest_remote_monotonic_timestamps_offset);
391 log_file_header_builder.add_oldest_local_monotonic_timestamps(
392 oldest_local_monotonic_timestamps_offset);
393 log_file_header_builder.add_oldest_remote_unreliable_monotonic_timestamps(
394 oldest_remote_unreliable_monotonic_timestamps_offset);
395 log_file_header_builder.add_oldest_local_unreliable_monotonic_timestamps(
396 oldest_local_unreliable_monotonic_timestamps_offset);
Austin Schuh73340842021-07-30 22:32:06 -0700397 fbb.FinishSizePrefixed(log_file_header_builder.Finish());
398 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> result(
399 fbb.Release());
400
401 CHECK(result.Verify()) << ": Built a corrupted header.";
402
403 return result;
Austin Schuhcb5601b2020-09-10 15:29:59 -0700404}
405
Austin Schuhb8bca732021-07-30 22:32:00 -0700406NewDataWriter *LocalLogNamer::MakeWriter(const Channel *channel) {
Austin Schuhdf576472020-10-19 09:39:37 -0700407 CHECK(configuration::ChannelIsSendableOnNode(channel, node()))
408 << ": " << configuration::CleanedChannelToString(channel);
Austin Schuhb8bca732021-07-30 22:32:00 -0700409 return &data_writer_;
Austin Schuhcb5601b2020-09-10 15:29:59 -0700410}
411
Austin Schuh73340842021-07-30 22:32:06 -0700412void LocalLogNamer::Rotate(const Node *node) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700413 CHECK(node == this->node());
Austin Schuhb8bca732021-07-30 22:32:00 -0700414 data_writer_.Rotate();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700415}
Austin Schuh8c399962020-12-25 21:51:45 -0800416
417void LocalLogNamer::WriteConfiguration(
418 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
419 std::string_view config_sha256) {
420 const std::string filename = absl::StrCat(base_name_, config_sha256, ".bfbs");
421
422 std::unique_ptr<DetachedBufferWriter> writer =
423 std::make_unique<DetachedBufferWriter>(
424 filename, std::make_unique<aos::logger::DummyEncoder>());
425 writer->QueueSizedFlatbuffer(header->Release());
426}
427
Austin Schuhb8bca732021-07-30 22:32:00 -0700428NewDataWriter *LocalLogNamer::MakeTimestampWriter(const Channel *channel) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700429 CHECK(configuration::ChannelIsReadableOnNode(channel, node_))
430 << ": Message is not delivered to this node.";
431 CHECK(node_ != nullptr) << ": Can't log timestamps in a single node world";
432 CHECK(configuration::ConnectionDeliveryTimeIsLoggedOnNode(channel, node_,
433 node_))
434 << ": Delivery times aren't logged for this channel on this node.";
Austin Schuhb8bca732021-07-30 22:32:00 -0700435 return &data_writer_;
Austin Schuhcb5601b2020-09-10 15:29:59 -0700436}
437
Austin Schuhb8bca732021-07-30 22:32:00 -0700438NewDataWriter *LocalLogNamer::MakeForwardedTimestampWriter(
Austin Schuhcb5601b2020-09-10 15:29:59 -0700439 const Channel * /*channel*/, const Node * /*node*/) {
440 LOG(FATAL) << "Can't log forwarded timestamps in a singe log file.";
441 return nullptr;
442}
Austin Schuhcb5601b2020-09-10 15:29:59 -0700443MultiNodeLogNamer::MultiNodeLogNamer(std::string_view base_name,
Austin Schuha499cea2021-07-31 19:49:53 -0700444 EventLoop *event_loop)
Austin Schuh5b728b72021-06-16 14:57:15 -0700445 : MultiNodeLogNamer(base_name, event_loop->configuration(), event_loop,
446 event_loop->node()) {}
447
448MultiNodeLogNamer::MultiNodeLogNamer(std::string_view base_name,
449 const Configuration *configuration,
450 EventLoop *event_loop, const Node *node)
451 : LogNamer(configuration, event_loop, node),
452 base_name_(base_name),
453 old_base_name_() {}
Austin Schuhcb5601b2020-09-10 15:29:59 -0700454
Brian Silverman48deab12020-09-30 18:39:28 -0700455MultiNodeLogNamer::~MultiNodeLogNamer() {
456 if (!ran_out_of_space_) {
457 // This handles renaming temporary files etc.
458 Close();
459 }
460}
461
Austin Schuh572924a2021-07-30 22:32:12 -0700462void MultiNodeLogNamer::Rotate(const Node *node) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700463 if (node == this->node()) {
Austin Schuhb8bca732021-07-30 22:32:00 -0700464 if (data_writer_) {
Austin Schuh572924a2021-07-30 22:32:12 -0700465 data_writer_->Rotate();
Brian Silvermancb805822020-10-06 17:43:35 -0700466 }
Austin Schuhcb5601b2020-09-10 15:29:59 -0700467 } else {
Austin Schuhb8bca732021-07-30 22:32:00 -0700468 for (std::pair<const Channel *const, NewDataWriter> &data_writer :
Austin Schuhcb5601b2020-09-10 15:29:59 -0700469 data_writers_) {
Austin Schuh572924a2021-07-30 22:32:12 -0700470 if (node == data_writer.second.node()) {
471 data_writer.second.Rotate();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700472 }
473 }
474 }
475}
476
Austin Schuh8c399962020-12-25 21:51:45 -0800477void MultiNodeLogNamer::WriteConfiguration(
478 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
479 std::string_view config_sha256) {
480 if (ran_out_of_space_) {
481 return;
482 }
483
484 const std::string_view separator = base_name_.back() == '/' ? "" : "_";
485 const std::string filename = absl::StrCat(
486 base_name_, separator, config_sha256, ".bfbs", extension_, temp_suffix_);
487
488 std::unique_ptr<DetachedBufferWriter> writer =
489 std::make_unique<DetachedBufferWriter>(filename, encoder_factory_());
490
491 writer->QueueSizedFlatbuffer(header->Release());
492
493 if (!writer->ran_out_of_space()) {
Austin Schuh5b728b72021-06-16 14:57:15 -0700494 all_filenames_.emplace_back(
495 absl::StrCat(config_sha256, ".bfbs", extension_));
Austin Schuh8c399962020-12-25 21:51:45 -0800496 }
497 CloseWriter(&writer);
498}
499
Austin Schuhb8bca732021-07-30 22:32:00 -0700500NewDataWriter *MultiNodeLogNamer::MakeWriter(const Channel *channel) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700501 // See if we can read the data on this node at all.
502 const bool is_readable =
503 configuration::ChannelIsReadableOnNode(channel, this->node());
504 if (!is_readable) {
505 return nullptr;
506 }
507
508 // Then, see if we are supposed to log the data here.
509 const bool log_message =
510 configuration::ChannelMessageIsLoggedOnNode(channel, this->node());
511
512 if (!log_message) {
513 return nullptr;
514 }
515
516 // Now, sort out if this is data generated on this node, or not. It is
517 // generated if it is sendable on this node.
518 if (configuration::ChannelIsSendableOnNode(channel, this->node())) {
Austin Schuhb8bca732021-07-30 22:32:00 -0700519 if (!data_writer_) {
Brian Silvermancb805822020-10-06 17:43:35 -0700520 OpenDataWriter();
521 }
Austin Schuhb8bca732021-07-30 22:32:00 -0700522 return data_writer_.get();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700523 }
524
525 // Ok, we have data that is being forwarded to us that we are supposed to
526 // log. It needs to be logged with send timestamps, but be sorted enough
527 // to be able to be processed.
528 CHECK(data_writers_.find(channel) == data_writers_.end());
529
530 // Track that this node is being logged.
531 const Node *source_node = configuration::GetNode(
532 configuration_, channel->source_node()->string_view());
533
534 if (std::find(nodes_.begin(), nodes_.end(), source_node) == nodes_.end()) {
535 nodes_.emplace_back(source_node);
536 }
537
Austin Schuh572924a2021-07-30 22:32:12 -0700538 NewDataWriter data_writer(this, source_node,
539 [this, channel](NewDataWriter *data_writer) {
540 OpenWriter(channel, data_writer);
541 },
542 [this](NewDataWriter *data_writer) {
543 CloseWriter(&data_writer->writer);
544 });
Austin Schuhb8bca732021-07-30 22:32:00 -0700545 return &(
546 data_writers_.emplace(channel, std::move(data_writer)).first->second);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700547}
548
Austin Schuhb8bca732021-07-30 22:32:00 -0700549NewDataWriter *MultiNodeLogNamer::MakeForwardedTimestampWriter(
Austin Schuhcb5601b2020-09-10 15:29:59 -0700550 const Channel *channel, const Node *node) {
551 // See if we can read the data on this node at all.
552 const bool is_readable =
553 configuration::ChannelIsReadableOnNode(channel, this->node());
554 CHECK(is_readable) << ": " << configuration::CleanedChannelToString(channel);
555
556 CHECK(data_writers_.find(channel) == data_writers_.end());
557
558 if (std::find(nodes_.begin(), nodes_.end(), node) == nodes_.end()) {
559 nodes_.emplace_back(node);
560 }
561
Austin Schuh5b728b72021-06-16 14:57:15 -0700562 NewDataWriter data_writer(this, configuration::GetNode(configuration_, node),
Austin Schuh572924a2021-07-30 22:32:12 -0700563 [this, channel](NewDataWriter *data_writer) {
564 OpenForwardedTimestampWriter(channel,
565 data_writer);
566 },
567 [this](NewDataWriter *data_writer) {
568 CloseWriter(&data_writer->writer);
569 });
Austin Schuhb8bca732021-07-30 22:32:00 -0700570 return &(
571 data_writers_.emplace(channel, std::move(data_writer)).first->second);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700572}
573
Austin Schuhb8bca732021-07-30 22:32:00 -0700574NewDataWriter *MultiNodeLogNamer::MakeTimestampWriter(const Channel *channel) {
Brian Silverman0465fcf2020-09-24 00:29:18 -0700575 bool log_delivery_times = false;
576 if (this->node() != nullptr) {
577 log_delivery_times = configuration::ConnectionDeliveryTimeIsLoggedOnNode(
578 channel, this->node(), this->node());
579 }
Austin Schuhcb5601b2020-09-10 15:29:59 -0700580 if (!log_delivery_times) {
581 return nullptr;
582 }
583
Austin Schuhb8bca732021-07-30 22:32:00 -0700584 if (!data_writer_) {
Brian Silvermancb805822020-10-06 17:43:35 -0700585 OpenDataWriter();
586 }
Austin Schuhb8bca732021-07-30 22:32:00 -0700587 return data_writer_.get();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700588}
589
Brian Silverman0465fcf2020-09-24 00:29:18 -0700590void MultiNodeLogNamer::Close() {
Austin Schuhb8bca732021-07-30 22:32:00 -0700591 data_writers_.clear();
592 data_writer_.reset();
Brian Silvermancb805822020-10-06 17:43:35 -0700593}
594
595void MultiNodeLogNamer::ResetStatistics() {
Austin Schuhb8bca732021-07-30 22:32:00 -0700596 for (std::pair<const Channel *const, NewDataWriter> &data_writer :
Brian Silvermancb805822020-10-06 17:43:35 -0700597 data_writers_) {
Austin Schuhad0cfc32020-12-21 12:34:26 -0800598 if (!data_writer.second.writer) continue;
Brian Silvermancb805822020-10-06 17:43:35 -0700599 data_writer.second.writer->ResetStatistics();
Brian Silverman0465fcf2020-09-24 00:29:18 -0700600 }
Austin Schuhb8bca732021-07-30 22:32:00 -0700601 if (data_writer_) {
602 data_writer_->writer->ResetStatistics();
Brian Silvermancb805822020-10-06 17:43:35 -0700603 }
604 max_write_time_ = std::chrono::nanoseconds::zero();
605 max_write_time_bytes_ = -1;
606 max_write_time_messages_ = -1;
607 total_write_time_ = std::chrono::nanoseconds::zero();
608 total_write_count_ = 0;
609 total_write_messages_ = 0;
610 total_write_bytes_ = 0;
Brian Silverman0465fcf2020-09-24 00:29:18 -0700611}
612
Austin Schuhb8bca732021-07-30 22:32:00 -0700613void MultiNodeLogNamer::OpenForwardedTimestampWriter(
614 const Channel *channel, NewDataWriter *data_writer) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700615 std::string filename =
Austin Schuhe715eae2020-10-10 15:39:30 -0700616 absl::StrCat("timestamps", channel->name()->string_view(), "/",
Brian Silvermana621f522020-09-30 16:52:43 -0700617 channel->type()->string_view(), ".part",
Austin Schuh572924a2021-07-30 22:32:12 -0700618 data_writer->parts_index(), ".bfbs", extension_);
Brian Silverman0465fcf2020-09-24 00:29:18 -0700619 CreateBufferWriter(filename, &data_writer->writer);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700620}
621
622void MultiNodeLogNamer::OpenWriter(const Channel *channel,
Austin Schuhb8bca732021-07-30 22:32:00 -0700623 NewDataWriter *data_writer) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700624 const std::string filename = absl::StrCat(
Austin Schuhe715eae2020-10-10 15:39:30 -0700625 CHECK_NOTNULL(channel->source_node())->string_view(), "_data",
Brian Silvermana621f522020-09-30 16:52:43 -0700626 channel->name()->string_view(), "/", channel->type()->string_view(),
Austin Schuh572924a2021-07-30 22:32:12 -0700627 ".part", data_writer->parts_index(), ".bfbs", extension_);
Brian Silverman0465fcf2020-09-24 00:29:18 -0700628 CreateBufferWriter(filename, &data_writer->writer);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700629}
630
Brian Silvermana621f522020-09-30 16:52:43 -0700631void MultiNodeLogNamer::OpenDataWriter() {
Austin Schuhb8bca732021-07-30 22:32:00 -0700632 if (!data_writer_) {
633 data_writer_ = std::make_unique<NewDataWriter>(
Austin Schuh572924a2021-07-30 22:32:12 -0700634 this, node_,
Austin Schuhb8bca732021-07-30 22:32:00 -0700635 [this](NewDataWriter *writer) {
636 std::string name;
637 if (node() != nullptr) {
638 name = absl::StrCat(name, node()->name()->string_view(), "_");
639 }
Austin Schuh572924a2021-07-30 22:32:12 -0700640 absl::StrAppend(&name, "data.part", writer->parts_index(), ".bfbs",
Austin Schuhb8bca732021-07-30 22:32:00 -0700641 extension_);
642 CreateBufferWriter(name, &writer->writer);
643 },
644 [this](NewDataWriter *data_writer) {
645 CloseWriter(&data_writer->writer);
646 });
Brian Silverman7af8c902020-09-29 16:14:04 -0700647 }
Austin Schuhcb5601b2020-09-10 15:29:59 -0700648}
649
Brian Silverman0465fcf2020-09-24 00:29:18 -0700650void MultiNodeLogNamer::CreateBufferWriter(
Brian Silvermana621f522020-09-30 16:52:43 -0700651 std::string_view path, std::unique_ptr<DetachedBufferWriter> *destination) {
Brian Silverman0465fcf2020-09-24 00:29:18 -0700652 if (ran_out_of_space_) {
653 // Refuse to open any new files, which might skip data. Any existing files
654 // are in the same folder, which means they're on the same filesystem, which
655 // means they're probably going to run out of space and get stuck too.
Austin Schuha426f1f2021-03-31 22:27:41 -0700656 if (!destination->get()) {
657 // But avoid leaving a nullptr writer if we're out of space when
658 // attempting to open the first file.
659 *destination = std::make_unique<DetachedBufferWriter>(
660 DetachedBufferWriter::already_out_of_space_t());
661 }
Brian Silverman0465fcf2020-09-24 00:29:18 -0700662 return;
663 }
Austin Schuhe715eae2020-10-10 15:39:30 -0700664 const std::string_view separator = base_name_.back() == '/' ? "" : "_";
665 const std::string filename =
666 absl::StrCat(base_name_, separator, path, temp_suffix_);
Brian Silverman0465fcf2020-09-24 00:29:18 -0700667 if (!destination->get()) {
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700668 if (ran_out_of_space_) {
669 *destination = std::make_unique<DetachedBufferWriter>(
670 DetachedBufferWriter::already_out_of_space_t());
671 return;
672 }
Brian Silvermancb805822020-10-06 17:43:35 -0700673 *destination =
674 std::make_unique<DetachedBufferWriter>(filename, encoder_factory_());
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700675 if (!destination->get()->ran_out_of_space()) {
676 all_filenames_.emplace_back(path);
677 }
Brian Silverman0465fcf2020-09-24 00:29:18 -0700678 return;
679 }
Brian Silvermancb805822020-10-06 17:43:35 -0700680
681 CloseWriter(destination);
682 if (ran_out_of_space_) {
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700683 *destination->get() =
684 DetachedBufferWriter(DetachedBufferWriter::already_out_of_space_t());
Brian Silverman0465fcf2020-09-24 00:29:18 -0700685 return;
686 }
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700687
Brian Silvermancb805822020-10-06 17:43:35 -0700688 *destination->get() = DetachedBufferWriter(filename, encoder_factory_());
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700689 if (!destination->get()->ran_out_of_space()) {
690 all_filenames_.emplace_back(path);
691 }
Brian Silverman0465fcf2020-09-24 00:29:18 -0700692}
693
Brian Silverman48deab12020-09-30 18:39:28 -0700694void MultiNodeLogNamer::RenameTempFile(DetachedBufferWriter *destination) {
695 if (temp_suffix_.empty()) {
696 return;
697 }
Austin Schuh6bb8a822021-03-31 23:04:39 -0700698 std::string current_filename = std::string(destination->filename());
Brian Silverman48deab12020-09-30 18:39:28 -0700699 CHECK(current_filename.size() > temp_suffix_.size());
Austin Schuh6bb8a822021-03-31 23:04:39 -0700700 std::string final_filename =
Brian Silverman48deab12020-09-30 18:39:28 -0700701 current_filename.substr(0, current_filename.size() - temp_suffix_.size());
Austin Schuh6bb8a822021-03-31 23:04:39 -0700702 int result = rename(current_filename.c_str(), final_filename.c_str());
703
704 // When changing the base name, we rename the log folder while there active
705 // buffer writers. Therefore, the name of that active buffer may still refer
706 // to the old file location rather than the new one. This minimized changes to
707 // existing code.
708 if (result != 0 && errno != ENOSPC && !old_base_name_.empty()) {
709 auto offset = current_filename.find(old_base_name_);
710 if (offset != std::string::npos) {
711 current_filename.replace(offset, old_base_name_.length(), base_name_);
712 }
713 offset = final_filename.find(old_base_name_);
714 if (offset != std::string::npos) {
715 final_filename.replace(offset, old_base_name_.length(), base_name_);
716 }
717 result = rename(current_filename.c_str(), final_filename.c_str());
718 }
719
Brian Silverman48deab12020-09-30 18:39:28 -0700720 if (result != 0) {
721 if (errno == ENOSPC) {
722 ran_out_of_space_ = true;
723 return;
724 } else {
725 PLOG(FATAL) << "Renaming " << current_filename << " to " << final_filename
726 << " failed";
727 }
Austin Schuh6bb8a822021-03-31 23:04:39 -0700728 } else {
729 VLOG(1) << "Renamed " << current_filename << " -> " << final_filename;
Brian Silverman48deab12020-09-30 18:39:28 -0700730 }
731}
732
Brian Silvermancb805822020-10-06 17:43:35 -0700733void MultiNodeLogNamer::CloseWriter(
734 std::unique_ptr<DetachedBufferWriter> *writer_pointer) {
735 DetachedBufferWriter *const writer = writer_pointer->get();
736 if (!writer) {
737 return;
738 }
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700739 const bool was_open = writer->is_open();
Brian Silvermancb805822020-10-06 17:43:35 -0700740 writer->Close();
741
742 if (writer->max_write_time() > max_write_time_) {
743 max_write_time_ = writer->max_write_time();
744 max_write_time_bytes_ = writer->max_write_time_bytes();
745 max_write_time_messages_ = writer->max_write_time_messages();
746 }
747 total_write_time_ += writer->total_write_time();
748 total_write_count_ += writer->total_write_count();
749 total_write_messages_ += writer->total_write_messages();
750 total_write_bytes_ += writer->total_write_bytes();
751
752 if (writer->ran_out_of_space()) {
753 ran_out_of_space_ = true;
754 writer->acknowledge_out_of_space();
755 }
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700756 if (was_open) {
757 RenameTempFile(writer);
758 } else {
759 CHECK(access(std::string(writer->filename()).c_str(), F_OK) == -1)
760 << ": File should not exist: " << writer->filename();
761 }
Brian Silvermancb805822020-10-06 17:43:35 -0700762}
763
Austin Schuhcb5601b2020-09-10 15:29:59 -0700764} // namespace logger
765} // namespace aos