blob: 65c68f47b793bd276fad1ff5ee8ed8cbde998c06 [file] [log] [blame]
Austin Schuhb06f03b2021-02-17 22:00:37 -08001#ifndef AOS_EVENTS_LOGGING_LOG_WRITER_H_
2#define AOS_EVENTS_LOGGING_LOG_WRITER_H_
3
4#include <chrono>
5#include <string_view>
6#include <vector>
7
8#include "aos/events/event_loop.h"
9#include "aos/events/logging/log_namer.h"
10#include "aos/events/logging/logfile_utils.h"
11#include "aos/events/logging/logger_generated.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -080012#include "aos/events/simulated_event_loop.h"
13#include "aos/network/message_bridge_server_generated.h"
14#include "aos/network/remote_message_generated.h"
15#include "aos/time/time.h"
Austin Schuh4385b142021-03-14 21:31:13 -070016#include "aos/uuid.h"
Austin Schuhb06f03b2021-02-17 22:00:37 -080017#include "flatbuffers/flatbuffers.h"
18
19namespace aos {
20namespace logger {
21
22// Logs all channels available in the event loop to disk every 100 ms.
23// Start by logging one message per channel to capture any state and
24// configuration that is sent rately on a channel and would affect execution.
25class Logger {
26 public:
27 // Constructs a logger.
28 // event_loop: The event loop used to read the messages.
29 // configuration: When provided, this is the configuration to log, and the
30 // configuration to use for the channel list to log. If not provided,
31 // this becomes the configuration from the event loop.
32 // should_log: When provided, a filter for channels to log. If not provided,
33 // all available channels are logged.
34 Logger(EventLoop *event_loop)
35 : Logger(event_loop, event_loop->configuration()) {}
36 Logger(EventLoop *event_loop, const Configuration *configuration)
37 : Logger(event_loop, configuration,
38 [](const Channel *) { return true; }) {}
39 Logger(EventLoop *event_loop, const Configuration *configuration,
40 std::function<bool(const Channel *)> should_log);
41 ~Logger();
42
43 // Overrides the name in the log file header.
44 void set_name(std::string_view name) { name_ = name; }
45
Austin Schuhfa712682022-05-11 16:43:42 -070046 void set_logger_sha1(std::string_view sha1) { logger_sha1_ = sha1; }
47 void set_logger_version(std::string_view version) {
48 logger_version_ = version;
49 }
50
Austin Schuhb06f03b2021-02-17 22:00:37 -080051 // Sets the callback to run after each period of data is logged. Defaults to
52 // doing nothing.
53 //
54 // This callback may safely do things like call Rotate().
55 void set_on_logged_period(std::function<void()> on_logged_period) {
56 on_logged_period_ = std::move(on_logged_period);
57 }
58
59 void set_separate_config(bool separate_config) {
60 separate_config_ = separate_config;
61 }
62
63 // Sets the period between polling the data. Defaults to 100ms.
64 //
65 // Changing this while a set of files is being written may result in
66 // unreadable files.
67 void set_polling_period(std::chrono::nanoseconds polling_period) {
68 polling_period_ = polling_period;
69 }
Austin Schuh29cf4e52021-03-31 22:51:35 -070070 std::chrono::nanoseconds polling_period() const { return polling_period_; }
Austin Schuhb06f03b2021-02-17 22:00:37 -080071
Austin Schuh34f9e482021-03-31 22:54:18 -070072 std::optional<UUID> log_start_uuid() const { return log_start_uuid_; }
Austin Schuhb06f03b2021-02-17 22:00:37 -080073 UUID logger_instance_uuid() const { return logger_instance_uuid_; }
74
75 // The maximum time for a single fetch which returned a message, or 0 if none
76 // of those have happened.
77 std::chrono::nanoseconds max_message_fetch_time() const {
78 return max_message_fetch_time_;
79 }
80 // The channel for that longest fetch which returned a message, or -1 if none
81 // of those have happened.
82 int max_message_fetch_time_channel() const {
83 return max_message_fetch_time_channel_;
84 }
85 // The size of the message returned by that longest fetch, or -1 if none of
86 // those have happened.
87 int max_message_fetch_time_size() const {
88 return max_message_fetch_time_size_;
89 }
90 // The total time spent fetching messages.
91 std::chrono::nanoseconds total_message_fetch_time() const {
92 return total_message_fetch_time_;
93 }
94 // The total number of fetch calls which returned messages.
95 int total_message_fetch_count() const { return total_message_fetch_count_; }
96 // The total number of bytes fetched.
97 int64_t total_message_fetch_bytes() const {
98 return total_message_fetch_bytes_;
99 }
100
101 // The total time spent in fetches which did not return a message.
102 std::chrono::nanoseconds total_nop_fetch_time() const {
103 return total_nop_fetch_time_;
104 }
105 // The total number of fetches which did not return a message.
106 int total_nop_fetch_count() const { return total_nop_fetch_count_; }
107
108 // The maximum time for a single copy, or 0 if none of those have happened.
109 std::chrono::nanoseconds max_copy_time() const { return max_copy_time_; }
110 // The channel for that longest copy, or -1 if none of those have happened.
111 int max_copy_time_channel() const { return max_copy_time_channel_; }
112 // The size of the message for that longest copy, or -1 if none of those have
113 // happened.
114 int max_copy_time_size() const { return max_copy_time_size_; }
115 // The total time spent copying messages.
116 std::chrono::nanoseconds total_copy_time() const { return total_copy_time_; }
117 // The total number of messages copied.
118 int total_copy_count() const { return total_copy_count_; }
119 // The total number of bytes copied.
120 int64_t total_copy_bytes() const { return total_copy_bytes_; }
121
122 void ResetStatisics();
123
124 // Rotates the log file(s), triggering new part files to be written for each
125 // log file.
126 void Rotate();
127
128 // Starts logging to files with the given naming scheme.
129 //
130 // log_start_uuid may be used to tie this log event to other log events across
131 // multiple nodes. The default (empty string) indicates there isn't one
132 // available.
133 void StartLogging(std::unique_ptr<LogNamer> log_namer,
Austin Schuh34f9e482021-03-31 22:54:18 -0700134 std::optional<UUID> log_start_uuid = std::nullopt);
Austin Schuhb06f03b2021-02-17 22:00:37 -0800135
Brian Smartt03c00da2022-02-24 10:25:00 -0800136 // Restart logging using a new naming scheme. Intended for log rotation.
137 // Returns a unique_ptr to the prior log_namer instance.
Austin Schuh60e77942022-05-16 17:48:24 -0700138 std::unique_ptr<LogNamer> RestartLogging(
139 std::unique_ptr<LogNamer> log_namer,
140 std::optional<UUID> log_start_uuid = std::nullopt);
Brian Smartt03c00da2022-02-24 10:25:00 -0800141
Austin Schuhb06f03b2021-02-17 22:00:37 -0800142 // Stops logging. Ensures any messages through end_time make it into the log.
143 //
144 // If you want to stop ASAP, pass min_time to avoid reading any more messages.
145 //
146 // Returns the LogNamer in case the caller wants to do anything else with it
147 // before destroying it.
148 std::unique_ptr<LogNamer> StopLogging(
149 aos::monotonic_clock::time_point end_time);
150
151 // Returns whether a log is currently being written.
152 bool is_started() const { return static_cast<bool>(log_namer_); }
153
Alexei Strots01395492023-03-20 13:59:56 -0700154 // Shortcut to call StartLogging with a MultiNodeFilesLogNamer when event
Austin Schuh5b6b3bc2021-03-31 22:55:06 -0700155 // processing starts.
156 void StartLoggingOnRun(std::string base_name) {
157 event_loop_->OnRun([this, base_name]() {
Alexei Strots01395492023-03-20 13:59:56 -0700158 StartLogging(std::make_unique<MultiNodeFilesLogNamer>(
Austin Schuh5b728b72021-06-16 14:57:15 -0700159 base_name, configuration_, event_loop_, node_));
Austin Schuh5b6b3bc2021-03-31 22:55:06 -0700160 });
161 }
162
Austin Schuhb06f03b2021-02-17 22:00:37 -0800163 private:
164 // Structure to track both a fetcher, and if the data fetched has been
165 // written. We may want to delay writing data to disk so that we don't let
166 // data get too far out of order when written to disk so we can avoid making
167 // it too hard to sort when reading.
168 struct FetcherStruct {
169 std::unique_ptr<RawFetcher> fetcher;
170 bool written = false;
171
172 // Channel index to log to.
173 int channel_index = -1;
174 const Channel *channel = nullptr;
175 const Node *timestamp_node = nullptr;
176
177 LogType log_type = LogType::kLogMessage;
178
179 // We fill out the metadata at construction, but the actual writers have to
180 // be updated each time we start logging. To avoid duplicating the complex
181 // logic determining whether each writer should be initialized, we just
182 // stash the answer in separate member variables.
183 bool wants_writer = false;
Austin Schuhb8bca732021-07-30 22:32:00 -0700184 NewDataWriter *writer = nullptr;
Austin Schuhb06f03b2021-02-17 22:00:37 -0800185 bool wants_timestamp_writer = false;
Austin Schuhb8bca732021-07-30 22:32:00 -0700186 NewDataWriter *timestamp_writer = nullptr;
Austin Schuhb06f03b2021-02-17 22:00:37 -0800187 bool wants_contents_writer = false;
Austin Schuhb8bca732021-07-30 22:32:00 -0700188 NewDataWriter *contents_writer = nullptr;
Austin Schuhb06f03b2021-02-17 22:00:37 -0800189
190 // Node which this data is from, or -1 if it is unknown.
191 int data_node_index = -1;
192 // Node that this timestamp is for, or -1 if it is known.
193 int timestamp_node_index = -1;
194 // Node that the contents this contents_writer will log are from.
195 int contents_node_index = -1;
Austin Schuh72211ae2021-08-05 14:02:30 -0700196
197 // If true, this message is being sent over a reliable channel.
198 bool reliable_forwarding = false;
Austin Schuh01f3b392022-01-25 20:03:09 -0800199
200 // One of the following will be populated. If channel_reliable_contents is
201 // non zero size, it contains a mapping from the event loop channel (not the
202 // logged channel) to a bool telling us if that particular channel is
203 // reliable.
204 //
205 // If channel_reliable_contents is empty, reliable_contents will contain the
206 // same info for all contents logged here. This is the predominant case for
207 // split timestamp channels (the prefered approach).
208 bool reliable_contents = false;
209 std::vector<bool> channel_reliable_contents;
Austin Schuhb06f03b2021-02-17 22:00:37 -0800210 };
211
212 // Vector mapping from the channel index from the event loop to the logged
213 // channel index.
214 std::vector<int> event_loop_to_logged_channel_index_;
215
Brian Smartt03c00da2022-02-24 10:25:00 -0800216 // Start/Restart write configuration into LogNamer space.
Austin Schuh60e77942022-05-16 17:48:24 -0700217 std::string WriteConfiguration(LogNamer *log_namer);
Brian Smartt03c00da2022-02-24 10:25:00 -0800218
Austin Schuh41f8df92022-04-15 11:45:52 -0700219 void WriteHeader(aos::monotonic_clock::time_point monotonic_start_time =
220 aos::monotonic_clock::min_time,
221 aos::realtime_clock::time_point realtime_start_time =
222 aos::realtime_clock::min_time);
Austin Schuhb06f03b2021-02-17 22:00:37 -0800223
Austin Schuh73340842021-07-30 22:32:06 -0700224 // Makes a template header for all the follower nodes.
Austin Schuhb06f03b2021-02-17 22:00:37 -0800225 aos::SizePrefixedFlatbufferDetachedBuffer<LogFileHeader> MakeHeader(
Austin Schuh73340842021-07-30 22:32:06 -0700226 std::string_view config_sha256);
Austin Schuhb06f03b2021-02-17 22:00:37 -0800227
Austin Schuhb06f03b2021-02-17 22:00:37 -0800228 bool MaybeUpdateTimestamp(
229 const Node *node, int node_index,
230 aos::monotonic_clock::time_point monotonic_start_time,
231 aos::realtime_clock::time_point realtime_start_time);
232
Austin Schuh30586902021-03-30 22:54:08 -0700233 void DoLogData(const monotonic_clock::time_point end_time,
234 bool run_on_logged);
Austin Schuhb06f03b2021-02-17 22:00:37 -0800235
236 void WriteMissingTimestamps();
237
Brian Smartt03c00da2022-02-24 10:25:00 -0800238 void WriteData(NewDataWriter *writer, const FetcherStruct &f);
Austin Schuh60e77942022-05-16 17:48:24 -0700239 void WriteTimestamps(NewDataWriter *timestamps_writer,
240 const FetcherStruct &f);
Brian Smartt03c00da2022-02-24 10:25:00 -0800241 void WriteContent(NewDataWriter *contents_writer, const FetcherStruct &f);
242
243 void WriteFetchedRecord(FetcherStruct &f);
244
Austin Schuh855f8932021-03-19 22:01:32 -0700245 // Fetches from each channel until all the data is logged. This is dangerous
246 // because it lets you log for more than 1 period. All calls need to verify
247 // that t isn't greater than 1 period in the future.
Austin Schuh08dba8f2023-05-01 08:29:30 -0700248 //
249 // Returns true if there is at least one message written, and also returns the
250 // timestamp of the newest record that any fetcher is pointing to, or min_time
251 // if there are no messages published on any logged channels.
252 std::pair<bool, monotonic_clock::time_point> LogUntil(
253 monotonic_clock::time_point t);
Austin Schuhb06f03b2021-02-17 22:00:37 -0800254
255 void RecordFetchResult(aos::monotonic_clock::time_point start,
256 aos::monotonic_clock::time_point end, bool got_new,
257 FetcherStruct *fetcher);
258
259 void RecordCreateMessageTime(aos::monotonic_clock::time_point start,
260 aos::monotonic_clock::time_point end,
Brian Smartt03c00da2022-02-24 10:25:00 -0800261 const FetcherStruct &fetcher);
Austin Schuhb06f03b2021-02-17 22:00:37 -0800262
Austin Schuhb06f03b2021-02-17 22:00:37 -0800263 EventLoop *const event_loop_;
264 // The configuration to place at the top of the log file.
265 const Configuration *const configuration_;
266
Austin Schuh5b728b72021-06-16 14:57:15 -0700267 // The node that is writing the log.
268 // For most cases, this is the same node as the node that is reading the
269 // messages. However, in some cases, these two nodes may be different. i.e. if
270 // one node reading and modifying the messages, and another node is listening
271 // and saving those messages to another log.
272 //
273 // node_ is a pointer to the writing node, and that node is guaranteed to be
274 // in configuration_ which is the configuration being written to the top of
275 // the log file.
276 const Node *const node_;
277 // The node_index_ is the index of the node in configuration_.
278 const size_t node_index_;
279
Austin Schuhb06f03b2021-02-17 22:00:37 -0800280 UUID log_event_uuid_ = UUID::Zero();
281 const UUID logger_instance_uuid_ = UUID::Random();
282 std::unique_ptr<LogNamer> log_namer_;
283 // Empty indicates there isn't one.
Austin Schuh34f9e482021-03-31 22:54:18 -0700284 std::optional<UUID> log_start_uuid_;
Austin Schuhb06f03b2021-02-17 22:00:37 -0800285
286 // Name to save in the log file. Defaults to hostname.
287 std::string name_;
Austin Schuhfa712682022-05-11 16:43:42 -0700288 std::string logger_sha1_;
289 std::string logger_version_;
Austin Schuhb06f03b2021-02-17 22:00:37 -0800290
291 std::function<void()> on_logged_period_ = []() {};
292
293 std::chrono::nanoseconds max_message_fetch_time_ =
294 std::chrono::nanoseconds::zero();
295 int max_message_fetch_time_channel_ = -1;
296 int max_message_fetch_time_size_ = -1;
297 std::chrono::nanoseconds total_message_fetch_time_ =
298 std::chrono::nanoseconds::zero();
299 int total_message_fetch_count_ = 0;
300 int64_t total_message_fetch_bytes_ = 0;
301
302 std::chrono::nanoseconds total_nop_fetch_time_ =
303 std::chrono::nanoseconds::zero();
304 int total_nop_fetch_count_ = 0;
305
306 std::chrono::nanoseconds max_copy_time_ = std::chrono::nanoseconds::zero();
307 int max_copy_time_channel_ = -1;
308 int max_copy_time_size_ = -1;
309 std::chrono::nanoseconds total_copy_time_ = std::chrono::nanoseconds::zero();
310 int total_copy_count_ = 0;
311 int64_t total_copy_bytes_ = 0;
312
313 std::vector<FetcherStruct> fetchers_;
314 TimerHandler *timer_handler_;
315
316 // Period to poll the channels.
317 std::chrono::nanoseconds polling_period_ = std::chrono::milliseconds(100);
318
319 // Last time that data was written for all channels to disk.
320 monotonic_clock::time_point last_synchronized_time_;
321
Austin Schuhb06f03b2021-02-17 22:00:37 -0800322 // If true, write the message header into a separate file.
323 bool separate_config_ = true;
324
325 // Fetcher for all the statistics from all the nodes.
326 aos::Fetcher<message_bridge::ServerStatistics> server_statistics_fetcher_;
Austin Schuhb06f03b2021-02-17 22:00:37 -0800327};
328
329} // namespace logger
330} // namespace aos
331
332#endif // AOS_EVENTS_LOGGING_LOG_WRITER_H_