blob: f13b2151d939b05b1dfbc5ef38974bf1cadc2356 [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);
Austin Schuh572924a2021-07-30 22:32:12 -0700135 CHECK(header_written_) << ": Attempting to write message before header to "
136 << writer->filename();
Austin Schuh510dc622021-08-06 18:47:30 -0700137 CHECK(writer);
Austin Schuh572924a2021-07-30 22:32:12 -0700138 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) {
296 oldest_remote_monotonic_timestamps[i] =
297 state[i].oldest_remote_monotonic_timestamp.time_since_epoch().count();
298 oldest_local_monotonic_timestamps[i] =
299 state[i].oldest_local_monotonic_timestamp.time_since_epoch().count();
300 oldest_remote_unreliable_monotonic_timestamps[i] =
301 state[i]
302 .oldest_remote_unreliable_monotonic_timestamp.time_since_epoch()
303 .count();
304 oldest_local_unreliable_monotonic_timestamps[i] =
305 state[i]
306 .oldest_local_unreliable_monotonic_timestamp.time_since_epoch()
307 .count();
308 }
309
Austin Schuh73340842021-07-30 22:32:06 -0700310 aos::logger::LogFileHeader::Builder log_file_header_builder(fbb);
311
312 log_file_header_builder.add_name(name_offset);
313
314 // Only add the node if we are running in a multinode configuration.
315 if (!logger_node_offset.IsNull()) {
316 log_file_header_builder.add_node(node_offset);
317 log_file_header_builder.add_logger_node(logger_node_offset);
318 }
319
320 if (!configuration_offset.IsNull()) {
321 log_file_header_builder.add_configuration(configuration_offset);
322 }
323 log_file_header_builder.add_max_out_of_order_duration(
324 header_.message().max_out_of_order_duration());
325
Austin Schuh58646e22021-08-23 23:51:46 -0700326 NodeState *node_state = GetNodeState(node_index, source_node_boot_uuid);
Austin Schuh73340842021-07-30 22:32:06 -0700327 log_file_header_builder.add_monotonic_start_time(
328 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700329 node_state->monotonic_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700330 .count());
331 if (source_node == node_) {
332 log_file_header_builder.add_realtime_start_time(
333 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700334 node_state->realtime_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700335 .count());
336 } else {
337 // Fill out the legacy start times. Since these were implemented to never
338 // change on reboot, they aren't very helpful in tracking what happened.
339 log_file_header_builder.add_logger_monotonic_start_time(
340 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700341 node_state->logger_monotonic_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700342 .count());
343 log_file_header_builder.add_logger_realtime_start_time(
344 std::chrono::duration_cast<std::chrono::nanoseconds>(
Austin Schuh58646e22021-08-23 23:51:46 -0700345 node_state->logger_realtime_start_time.time_since_epoch())
Austin Schuh73340842021-07-30 22:32:06 -0700346 .count());
347 }
348
349 // TODO(austin): Add more useful times. When was this part started? What do
350 // we know about both the logger and remote then?
351
352 log_file_header_builder.add_log_event_uuid(log_event_uuid_offset);
353 log_file_header_builder.add_logger_instance_uuid(logger_instance_uuid_offset);
354 if (!log_start_uuid_offset.IsNull()) {
355 log_file_header_builder.add_log_start_uuid(log_start_uuid_offset);
356 }
357 log_file_header_builder.add_logger_node_boot_uuid(
358 logger_node_boot_uuid_offset);
359 log_file_header_builder.add_source_node_boot_uuid(
360 source_node_boot_uuid_offset);
361
362 log_file_header_builder.add_parts_uuid(parts_uuid_offset);
363 log_file_header_builder.add_parts_index(parts_index);
364
365 if (!config_sha256_offset.IsNull()) {
366 log_file_header_builder.add_configuration_sha256(config_sha256_offset);
367 }
368
Austin Schuhe46492f2021-07-31 19:49:41 -0700369 log_file_header_builder.add_boot_uuids(boot_uuids_offset);
Austin Schuha499cea2021-07-31 19:49:53 -0700370 log_file_header_builder.add_logger_part_monotonic_start_time(
371 std::chrono::duration_cast<std::chrono::nanoseconds>(
372 event_loop_->monotonic_now().time_since_epoch())
373 .count());
374 log_file_header_builder.add_logger_part_realtime_start_time(
375 std::chrono::duration_cast<std::chrono::nanoseconds>(
376 event_loop_->realtime_now().time_since_epoch())
377 .count());
Austin Schuh72211ae2021-08-05 14:02:30 -0700378 log_file_header_builder.add_oldest_remote_monotonic_timestamps(
379 oldest_remote_monotonic_timestamps_offset);
380 log_file_header_builder.add_oldest_local_monotonic_timestamps(
381 oldest_local_monotonic_timestamps_offset);
382 log_file_header_builder.add_oldest_remote_unreliable_monotonic_timestamps(
383 oldest_remote_unreliable_monotonic_timestamps_offset);
384 log_file_header_builder.add_oldest_local_unreliable_monotonic_timestamps(
385 oldest_local_unreliable_monotonic_timestamps_offset);
Austin Schuh73340842021-07-30 22:32:06 -0700386 fbb.FinishSizePrefixed(log_file_header_builder.Finish());
387 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> result(
388 fbb.Release());
389
390 CHECK(result.Verify()) << ": Built a corrupted header.";
391
392 return result;
Austin Schuhcb5601b2020-09-10 15:29:59 -0700393}
394
Austin Schuhb8bca732021-07-30 22:32:00 -0700395NewDataWriter *LocalLogNamer::MakeWriter(const Channel *channel) {
Austin Schuhdf576472020-10-19 09:39:37 -0700396 CHECK(configuration::ChannelIsSendableOnNode(channel, node()))
397 << ": " << configuration::CleanedChannelToString(channel);
Austin Schuhb8bca732021-07-30 22:32:00 -0700398 return &data_writer_;
Austin Schuhcb5601b2020-09-10 15:29:59 -0700399}
400
Austin Schuh73340842021-07-30 22:32:06 -0700401void LocalLogNamer::Rotate(const Node *node) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700402 CHECK(node == this->node());
Austin Schuhb8bca732021-07-30 22:32:00 -0700403 data_writer_.Rotate();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700404}
Austin Schuh8c399962020-12-25 21:51:45 -0800405
406void LocalLogNamer::WriteConfiguration(
407 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
408 std::string_view config_sha256) {
409 const std::string filename = absl::StrCat(base_name_, config_sha256, ".bfbs");
410
411 std::unique_ptr<DetachedBufferWriter> writer =
412 std::make_unique<DetachedBufferWriter>(
413 filename, std::make_unique<aos::logger::DummyEncoder>());
414 writer->QueueSizedFlatbuffer(header->Release());
415}
416
Austin Schuhb8bca732021-07-30 22:32:00 -0700417NewDataWriter *LocalLogNamer::MakeTimestampWriter(const Channel *channel) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700418 CHECK(configuration::ChannelIsReadableOnNode(channel, node_))
419 << ": Message is not delivered to this node.";
420 CHECK(node_ != nullptr) << ": Can't log timestamps in a single node world";
421 CHECK(configuration::ConnectionDeliveryTimeIsLoggedOnNode(channel, node_,
422 node_))
423 << ": Delivery times aren't logged for this channel on this node.";
Austin Schuhb8bca732021-07-30 22:32:00 -0700424 return &data_writer_;
Austin Schuhcb5601b2020-09-10 15:29:59 -0700425}
426
Austin Schuhb8bca732021-07-30 22:32:00 -0700427NewDataWriter *LocalLogNamer::MakeForwardedTimestampWriter(
Austin Schuhcb5601b2020-09-10 15:29:59 -0700428 const Channel * /*channel*/, const Node * /*node*/) {
429 LOG(FATAL) << "Can't log forwarded timestamps in a singe log file.";
430 return nullptr;
431}
Austin Schuhcb5601b2020-09-10 15:29:59 -0700432MultiNodeLogNamer::MultiNodeLogNamer(std::string_view base_name,
Austin Schuha499cea2021-07-31 19:49:53 -0700433 EventLoop *event_loop)
Austin Schuh5b728b72021-06-16 14:57:15 -0700434 : MultiNodeLogNamer(base_name, event_loop->configuration(), event_loop,
435 event_loop->node()) {}
436
437MultiNodeLogNamer::MultiNodeLogNamer(std::string_view base_name,
438 const Configuration *configuration,
439 EventLoop *event_loop, const Node *node)
440 : LogNamer(configuration, event_loop, node),
441 base_name_(base_name),
442 old_base_name_() {}
Austin Schuhcb5601b2020-09-10 15:29:59 -0700443
Brian Silverman48deab12020-09-30 18:39:28 -0700444MultiNodeLogNamer::~MultiNodeLogNamer() {
445 if (!ran_out_of_space_) {
446 // This handles renaming temporary files etc.
447 Close();
448 }
449}
450
Austin Schuh572924a2021-07-30 22:32:12 -0700451void MultiNodeLogNamer::Rotate(const Node *node) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700452 if (node == this->node()) {
Austin Schuhb8bca732021-07-30 22:32:00 -0700453 if (data_writer_) {
Austin Schuh572924a2021-07-30 22:32:12 -0700454 data_writer_->Rotate();
Brian Silvermancb805822020-10-06 17:43:35 -0700455 }
Austin Schuhcb5601b2020-09-10 15:29:59 -0700456 } else {
Austin Schuhb8bca732021-07-30 22:32:00 -0700457 for (std::pair<const Channel *const, NewDataWriter> &data_writer :
Austin Schuhcb5601b2020-09-10 15:29:59 -0700458 data_writers_) {
Austin Schuh572924a2021-07-30 22:32:12 -0700459 if (node == data_writer.second.node()) {
460 data_writer.second.Rotate();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700461 }
462 }
463 }
464}
465
Austin Schuh8c399962020-12-25 21:51:45 -0800466void MultiNodeLogNamer::WriteConfiguration(
467 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> *header,
468 std::string_view config_sha256) {
469 if (ran_out_of_space_) {
470 return;
471 }
472
473 const std::string_view separator = base_name_.back() == '/' ? "" : "_";
474 const std::string filename = absl::StrCat(
475 base_name_, separator, config_sha256, ".bfbs", extension_, temp_suffix_);
476
477 std::unique_ptr<DetachedBufferWriter> writer =
478 std::make_unique<DetachedBufferWriter>(filename, encoder_factory_());
479
480 writer->QueueSizedFlatbuffer(header->Release());
481
482 if (!writer->ran_out_of_space()) {
Austin Schuh5b728b72021-06-16 14:57:15 -0700483 all_filenames_.emplace_back(
484 absl::StrCat(config_sha256, ".bfbs", extension_));
Austin Schuh8c399962020-12-25 21:51:45 -0800485 }
486 CloseWriter(&writer);
487}
488
Austin Schuhb8bca732021-07-30 22:32:00 -0700489NewDataWriter *MultiNodeLogNamer::MakeWriter(const Channel *channel) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700490 // See if we can read the data on this node at all.
491 const bool is_readable =
492 configuration::ChannelIsReadableOnNode(channel, this->node());
493 if (!is_readable) {
494 return nullptr;
495 }
496
497 // Then, see if we are supposed to log the data here.
498 const bool log_message =
499 configuration::ChannelMessageIsLoggedOnNode(channel, this->node());
500
501 if (!log_message) {
502 return nullptr;
503 }
504
505 // Now, sort out if this is data generated on this node, or not. It is
506 // generated if it is sendable on this node.
507 if (configuration::ChannelIsSendableOnNode(channel, this->node())) {
Austin Schuhb8bca732021-07-30 22:32:00 -0700508 if (!data_writer_) {
Brian Silvermancb805822020-10-06 17:43:35 -0700509 OpenDataWriter();
510 }
Austin Schuhb8bca732021-07-30 22:32:00 -0700511 return data_writer_.get();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700512 }
513
514 // Ok, we have data that is being forwarded to us that we are supposed to
515 // log. It needs to be logged with send timestamps, but be sorted enough
516 // to be able to be processed.
517 CHECK(data_writers_.find(channel) == data_writers_.end());
518
519 // Track that this node is being logged.
520 const Node *source_node = configuration::GetNode(
521 configuration_, channel->source_node()->string_view());
522
523 if (std::find(nodes_.begin(), nodes_.end(), source_node) == nodes_.end()) {
524 nodes_.emplace_back(source_node);
525 }
526
Austin Schuh572924a2021-07-30 22:32:12 -0700527 NewDataWriter data_writer(this, source_node,
528 [this, channel](NewDataWriter *data_writer) {
529 OpenWriter(channel, data_writer);
530 },
531 [this](NewDataWriter *data_writer) {
532 CloseWriter(&data_writer->writer);
533 });
Austin Schuhb8bca732021-07-30 22:32:00 -0700534 return &(
535 data_writers_.emplace(channel, std::move(data_writer)).first->second);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700536}
537
Austin Schuhb8bca732021-07-30 22:32:00 -0700538NewDataWriter *MultiNodeLogNamer::MakeForwardedTimestampWriter(
Austin Schuhcb5601b2020-09-10 15:29:59 -0700539 const Channel *channel, const Node *node) {
540 // See if we can read the data on this node at all.
541 const bool is_readable =
542 configuration::ChannelIsReadableOnNode(channel, this->node());
543 CHECK(is_readable) << ": " << configuration::CleanedChannelToString(channel);
544
545 CHECK(data_writers_.find(channel) == data_writers_.end());
546
547 if (std::find(nodes_.begin(), nodes_.end(), node) == nodes_.end()) {
548 nodes_.emplace_back(node);
549 }
550
Austin Schuh5b728b72021-06-16 14:57:15 -0700551 NewDataWriter data_writer(this, configuration::GetNode(configuration_, node),
Austin Schuh572924a2021-07-30 22:32:12 -0700552 [this, channel](NewDataWriter *data_writer) {
553 OpenForwardedTimestampWriter(channel,
554 data_writer);
555 },
556 [this](NewDataWriter *data_writer) {
557 CloseWriter(&data_writer->writer);
558 });
Austin Schuhb8bca732021-07-30 22:32:00 -0700559 return &(
560 data_writers_.emplace(channel, std::move(data_writer)).first->second);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700561}
562
Austin Schuhb8bca732021-07-30 22:32:00 -0700563NewDataWriter *MultiNodeLogNamer::MakeTimestampWriter(const Channel *channel) {
Brian Silverman0465fcf2020-09-24 00:29:18 -0700564 bool log_delivery_times = false;
565 if (this->node() != nullptr) {
566 log_delivery_times = configuration::ConnectionDeliveryTimeIsLoggedOnNode(
567 channel, this->node(), this->node());
568 }
Austin Schuhcb5601b2020-09-10 15:29:59 -0700569 if (!log_delivery_times) {
570 return nullptr;
571 }
572
Austin Schuhb8bca732021-07-30 22:32:00 -0700573 if (!data_writer_) {
Brian Silvermancb805822020-10-06 17:43:35 -0700574 OpenDataWriter();
575 }
Austin Schuhb8bca732021-07-30 22:32:00 -0700576 return data_writer_.get();
Austin Schuhcb5601b2020-09-10 15:29:59 -0700577}
578
Brian Silverman0465fcf2020-09-24 00:29:18 -0700579void MultiNodeLogNamer::Close() {
Austin Schuhb8bca732021-07-30 22:32:00 -0700580 data_writers_.clear();
581 data_writer_.reset();
Brian Silvermancb805822020-10-06 17:43:35 -0700582}
583
584void MultiNodeLogNamer::ResetStatistics() {
Austin Schuhb8bca732021-07-30 22:32:00 -0700585 for (std::pair<const Channel *const, NewDataWriter> &data_writer :
Brian Silvermancb805822020-10-06 17:43:35 -0700586 data_writers_) {
Austin Schuhad0cfc32020-12-21 12:34:26 -0800587 if (!data_writer.second.writer) continue;
Brian Silvermancb805822020-10-06 17:43:35 -0700588 data_writer.second.writer->ResetStatistics();
Brian Silverman0465fcf2020-09-24 00:29:18 -0700589 }
Austin Schuhb8bca732021-07-30 22:32:00 -0700590 if (data_writer_) {
591 data_writer_->writer->ResetStatistics();
Brian Silvermancb805822020-10-06 17:43:35 -0700592 }
593 max_write_time_ = std::chrono::nanoseconds::zero();
594 max_write_time_bytes_ = -1;
595 max_write_time_messages_ = -1;
596 total_write_time_ = std::chrono::nanoseconds::zero();
597 total_write_count_ = 0;
598 total_write_messages_ = 0;
599 total_write_bytes_ = 0;
Brian Silverman0465fcf2020-09-24 00:29:18 -0700600}
601
Austin Schuhb8bca732021-07-30 22:32:00 -0700602void MultiNodeLogNamer::OpenForwardedTimestampWriter(
603 const Channel *channel, NewDataWriter *data_writer) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700604 std::string filename =
Austin Schuhe715eae2020-10-10 15:39:30 -0700605 absl::StrCat("timestamps", channel->name()->string_view(), "/",
Brian Silvermana621f522020-09-30 16:52:43 -0700606 channel->type()->string_view(), ".part",
Austin Schuh572924a2021-07-30 22:32:12 -0700607 data_writer->parts_index(), ".bfbs", extension_);
Brian Silverman0465fcf2020-09-24 00:29:18 -0700608 CreateBufferWriter(filename, &data_writer->writer);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700609}
610
611void MultiNodeLogNamer::OpenWriter(const Channel *channel,
Austin Schuhb8bca732021-07-30 22:32:00 -0700612 NewDataWriter *data_writer) {
Austin Schuhcb5601b2020-09-10 15:29:59 -0700613 const std::string filename = absl::StrCat(
Austin Schuhe715eae2020-10-10 15:39:30 -0700614 CHECK_NOTNULL(channel->source_node())->string_view(), "_data",
Brian Silvermana621f522020-09-30 16:52:43 -0700615 channel->name()->string_view(), "/", channel->type()->string_view(),
Austin Schuh572924a2021-07-30 22:32:12 -0700616 ".part", data_writer->parts_index(), ".bfbs", extension_);
Brian Silverman0465fcf2020-09-24 00:29:18 -0700617 CreateBufferWriter(filename, &data_writer->writer);
Austin Schuhcb5601b2020-09-10 15:29:59 -0700618}
619
Brian Silvermana621f522020-09-30 16:52:43 -0700620void MultiNodeLogNamer::OpenDataWriter() {
Austin Schuhb8bca732021-07-30 22:32:00 -0700621 if (!data_writer_) {
622 data_writer_ = std::make_unique<NewDataWriter>(
Austin Schuh572924a2021-07-30 22:32:12 -0700623 this, node_,
Austin Schuhb8bca732021-07-30 22:32:00 -0700624 [this](NewDataWriter *writer) {
625 std::string name;
626 if (node() != nullptr) {
627 name = absl::StrCat(name, node()->name()->string_view(), "_");
628 }
Austin Schuh572924a2021-07-30 22:32:12 -0700629 absl::StrAppend(&name, "data.part", writer->parts_index(), ".bfbs",
Austin Schuhb8bca732021-07-30 22:32:00 -0700630 extension_);
631 CreateBufferWriter(name, &writer->writer);
632 },
633 [this](NewDataWriter *data_writer) {
634 CloseWriter(&data_writer->writer);
635 });
Brian Silverman7af8c902020-09-29 16:14:04 -0700636 }
Austin Schuhcb5601b2020-09-10 15:29:59 -0700637}
638
Brian Silverman0465fcf2020-09-24 00:29:18 -0700639void MultiNodeLogNamer::CreateBufferWriter(
Brian Silvermana621f522020-09-30 16:52:43 -0700640 std::string_view path, std::unique_ptr<DetachedBufferWriter> *destination) {
Brian Silverman0465fcf2020-09-24 00:29:18 -0700641 if (ran_out_of_space_) {
642 // Refuse to open any new files, which might skip data. Any existing files
643 // are in the same folder, which means they're on the same filesystem, which
644 // means they're probably going to run out of space and get stuck too.
Austin Schuha426f1f2021-03-31 22:27:41 -0700645 if (!destination->get()) {
646 // But avoid leaving a nullptr writer if we're out of space when
647 // attempting to open the first file.
648 *destination = std::make_unique<DetachedBufferWriter>(
649 DetachedBufferWriter::already_out_of_space_t());
650 }
Brian Silverman0465fcf2020-09-24 00:29:18 -0700651 return;
652 }
Austin Schuhe715eae2020-10-10 15:39:30 -0700653 const std::string_view separator = base_name_.back() == '/' ? "" : "_";
654 const std::string filename =
655 absl::StrCat(base_name_, separator, path, temp_suffix_);
Brian Silverman0465fcf2020-09-24 00:29:18 -0700656 if (!destination->get()) {
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700657 if (ran_out_of_space_) {
658 *destination = std::make_unique<DetachedBufferWriter>(
659 DetachedBufferWriter::already_out_of_space_t());
660 return;
661 }
Brian Silvermancb805822020-10-06 17:43:35 -0700662 *destination =
663 std::make_unique<DetachedBufferWriter>(filename, encoder_factory_());
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700664 if (!destination->get()->ran_out_of_space()) {
665 all_filenames_.emplace_back(path);
666 }
Brian Silverman0465fcf2020-09-24 00:29:18 -0700667 return;
668 }
Brian Silvermancb805822020-10-06 17:43:35 -0700669
670 CloseWriter(destination);
671 if (ran_out_of_space_) {
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700672 *destination->get() =
673 DetachedBufferWriter(DetachedBufferWriter::already_out_of_space_t());
Brian Silverman0465fcf2020-09-24 00:29:18 -0700674 return;
675 }
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700676
Brian Silvermancb805822020-10-06 17:43:35 -0700677 *destination->get() = DetachedBufferWriter(filename, encoder_factory_());
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700678 if (!destination->get()->ran_out_of_space()) {
679 all_filenames_.emplace_back(path);
680 }
Brian Silverman0465fcf2020-09-24 00:29:18 -0700681}
682
Brian Silverman48deab12020-09-30 18:39:28 -0700683void MultiNodeLogNamer::RenameTempFile(DetachedBufferWriter *destination) {
684 if (temp_suffix_.empty()) {
685 return;
686 }
Austin Schuh6bb8a822021-03-31 23:04:39 -0700687 std::string current_filename = std::string(destination->filename());
Brian Silverman48deab12020-09-30 18:39:28 -0700688 CHECK(current_filename.size() > temp_suffix_.size());
Austin Schuh6bb8a822021-03-31 23:04:39 -0700689 std::string final_filename =
Brian Silverman48deab12020-09-30 18:39:28 -0700690 current_filename.substr(0, current_filename.size() - temp_suffix_.size());
Austin Schuh6bb8a822021-03-31 23:04:39 -0700691 int result = rename(current_filename.c_str(), final_filename.c_str());
692
693 // When changing the base name, we rename the log folder while there active
694 // buffer writers. Therefore, the name of that active buffer may still refer
695 // to the old file location rather than the new one. This minimized changes to
696 // existing code.
697 if (result != 0 && errno != ENOSPC && !old_base_name_.empty()) {
698 auto offset = current_filename.find(old_base_name_);
699 if (offset != std::string::npos) {
700 current_filename.replace(offset, old_base_name_.length(), base_name_);
701 }
702 offset = final_filename.find(old_base_name_);
703 if (offset != std::string::npos) {
704 final_filename.replace(offset, old_base_name_.length(), base_name_);
705 }
706 result = rename(current_filename.c_str(), final_filename.c_str());
707 }
708
Brian Silverman48deab12020-09-30 18:39:28 -0700709 if (result != 0) {
710 if (errno == ENOSPC) {
711 ran_out_of_space_ = true;
712 return;
713 } else {
714 PLOG(FATAL) << "Renaming " << current_filename << " to " << final_filename
715 << " failed";
716 }
Austin Schuh6bb8a822021-03-31 23:04:39 -0700717 } else {
718 VLOG(1) << "Renamed " << current_filename << " -> " << final_filename;
Brian Silverman48deab12020-09-30 18:39:28 -0700719 }
720}
721
Brian Silvermancb805822020-10-06 17:43:35 -0700722void MultiNodeLogNamer::CloseWriter(
723 std::unique_ptr<DetachedBufferWriter> *writer_pointer) {
724 DetachedBufferWriter *const writer = writer_pointer->get();
725 if (!writer) {
726 return;
727 }
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700728 const bool was_open = writer->is_open();
Brian Silvermancb805822020-10-06 17:43:35 -0700729 writer->Close();
730
731 if (writer->max_write_time() > max_write_time_) {
732 max_write_time_ = writer->max_write_time();
733 max_write_time_bytes_ = writer->max_write_time_bytes();
734 max_write_time_messages_ = writer->max_write_time_messages();
735 }
736 total_write_time_ += writer->total_write_time();
737 total_write_count_ += writer->total_write_count();
738 total_write_messages_ += writer->total_write_messages();
739 total_write_bytes_ += writer->total_write_bytes();
740
741 if (writer->ran_out_of_space()) {
742 ran_out_of_space_ = true;
743 writer->acknowledge_out_of_space();
744 }
Brian Silvermana9f2ec92020-10-06 18:00:53 -0700745 if (was_open) {
746 RenameTempFile(writer);
747 } else {
748 CHECK(access(std::string(writer->filename()).c_str(), F_OK) == -1)
749 << ": File should not exist: " << writer->filename();
750 }
Brian Silvermancb805822020-10-06 17:43:35 -0700751}
752
Austin Schuhcb5601b2020-09-10 15:29:59 -0700753} // namespace logger
754} // namespace aos