1 // Copyright 2016 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "net/log/file_net_log_observer.h"
6
7 #include <algorithm>
8 #include <memory>
9 #include <string>
10 #include <utility>
11
12 #include "base/bind.h"
13 #include "base/containers/queue.h"
14 #include "base/files/file.h"
15 #include "base/files/file_util.h"
16 #include "base/json/json_writer.h"
17 #include "base/logging.h"
18 #include "base/memory/ptr_util.h"
19 #include "base/numerics/clamped_math.h"
20 #include "base/sequenced_task_runner.h"
21 #include "base/strings/string_number_conversions.h"
22 #include "base/synchronization/lock.h"
23 #include "base/task/post_task.h"
24 #include "base/task/thread_pool.h"
25 #include "base/values.h"
26 #include "net/log/net_log_capture_mode.h"
27 #include "net/log/net_log_entry.h"
28 #include "net/log/net_log_util.h"
29 #include "net/url_request/url_request_context.h"
30
31 namespace {
32
33 // Number of events that can build up in |write_queue_| before a task is posted
34 // to the file task runner to flush them to disk.
35 const int kNumWriteQueueEvents = 15;
36
37 // TODO(eroman): Should use something other than 10 for number of files?
38 const int kDefaultNumFiles = 10;
39
CreateFileTaskRunner()40 scoped_refptr<base::SequencedTaskRunner> CreateFileTaskRunner() {
41 // The tasks posted to this sequenced task runner do synchronous File I/O for
42 // the purposes of writing NetLog files.
43 //
44 // These intentionally block shutdown to ensure the log file has finished
45 // being written.
46 return base::ThreadPool::CreateSequencedTaskRunner(
47 {base::MayBlock(), base::TaskPriority::USER_VISIBLE,
48 base::TaskShutdownBehavior::BLOCK_SHUTDOWN});
49 }
50
51 // Truncates a file, also reseting the seek position.
TruncateFile(base::File * file)52 void TruncateFile(base::File* file) {
53 if (!file->IsValid())
54 return;
55 file->Seek(base::File::FROM_BEGIN, 0);
56 file->SetLength(0);
57 }
58
59 // Opens |path| in write mode.
OpenFileForWrite(const base::FilePath & path)60 base::File OpenFileForWrite(const base::FilePath& path) {
61 base::File result(path,
62 base::File::FLAG_CREATE_ALWAYS | base::File::FLAG_WRITE);
63 LOG_IF(ERROR, !result.IsValid()) << "Failed opening: " << path.value();
64 return result;
65 }
66
67 // Helper that writes data to a file. |file->IsValid()| may be false,
68 // in which case nothing will be written. Returns the number of bytes
69 // successfully written (may be less than input data in case of errors).
WriteToFile(base::File * file,base::StringPiece data1,base::StringPiece data2=base::StringPiece (),base::StringPiece data3=base::StringPiece ())70 size_t WriteToFile(base::File* file,
71 base::StringPiece data1,
72 base::StringPiece data2 = base::StringPiece(),
73 base::StringPiece data3 = base::StringPiece()) {
74 size_t bytes_written = 0;
75
76 if (file->IsValid()) {
77 // Append each of data1, data2 and data3.
78 if (!data1.empty())
79 bytes_written +=
80 std::max(0, file->WriteAtCurrentPos(data1.data(), data1.size()));
81 if (!data2.empty())
82 bytes_written +=
83 std::max(0, file->WriteAtCurrentPos(data2.data(), data2.size()));
84 if (!data3.empty())
85 bytes_written +=
86 std::max(0, file->WriteAtCurrentPos(data3.data(), data3.size()));
87 }
88
89 return bytes_written;
90 }
91
92 // Copies all of the data at |source_path| and appends it to |destination_file|,
93 // then deletes |source_path|.
AppendToFileThenDelete(const base::FilePath & source_path,base::File * destination_file,char * read_buffer,size_t read_buffer_size)94 void AppendToFileThenDelete(const base::FilePath& source_path,
95 base::File* destination_file,
96 char* read_buffer,
97 size_t read_buffer_size) {
98 base::ScopedFILE source_file(base::OpenFile(source_path, "rb"));
99 if (!source_file)
100 return;
101
102 // Read |source_path|'s contents in chunks of read_buffer_size and append
103 // to |destination_file|.
104 size_t num_bytes_read;
105 while ((num_bytes_read =
106 fread(read_buffer, 1, read_buffer_size, source_file.get())) > 0) {
107 WriteToFile(destination_file,
108 base::StringPiece(read_buffer, num_bytes_read));
109 }
110
111 // Now that it has been copied, delete the source file.
112 source_file.reset();
113 base::DeleteFile(source_path);
114 }
115
SiblingInprogressDirectory(const base::FilePath & log_path)116 base::FilePath SiblingInprogressDirectory(const base::FilePath& log_path) {
117 return log_path.AddExtension(FILE_PATH_LITERAL(".inprogress"));
118 }
119
120 } // namespace
121
122 namespace net {
123
124 // Used to store events to be written to file.
125 using EventQueue = base::queue<std::unique_ptr<std::string>>;
126
127 // WriteQueue receives events from FileNetLogObserver on the main thread and
128 // holds them in a queue until they are drained from the queue and written to
129 // file on the file task runner.
130 //
131 // WriteQueue contains the resources shared between the main thread and the
132 // file task runner. |lock_| must be acquired to read or write to |queue_| and
133 // |memory_|.
134 //
135 // WriteQueue is refcounted and should be destroyed once all events on the
136 // file task runner have finished executing.
137 class FileNetLogObserver::WriteQueue
138 : public base::RefCountedThreadSafe<WriteQueue> {
139 public:
140 // |memory_max| indicates the maximum amount of memory that the virtual write
141 // queue can use. If |memory_| exceeds |memory_max_|, the |queue_| of events
142 // is overwritten.
143 explicit WriteQueue(uint64_t memory_max);
144
145 // Adds |event| to |queue_|. Also manages the size of |memory_|; if it
146 // exceeds |memory_max_|, then old events are dropped from |queue_| without
147 // being written to file.
148 //
149 // Returns the number of events in the |queue_|.
150 size_t AddEntryToQueue(std::unique_ptr<std::string> event);
151
152 // Swaps |queue_| with |local_queue|. |local_queue| should be empty, so that
153 // |queue_| is emptied. Resets |memory_| to 0.
154 void SwapQueue(EventQueue* local_queue);
155
156 private:
157 friend class base::RefCountedThreadSafe<WriteQueue>;
158
159 ~WriteQueue();
160
161 // Queue of events to be written, shared between main thread and file task
162 // runner. Main thread adds events to the queue and the file task runner
163 // drains them and writes the events to file.
164 //
165 // |lock_| must be acquired to read or write to this.
166 EventQueue queue_;
167
168 // Tracks how much memory is being used by the virtual write queue.
169 // Incremented in AddEntryToQueue() when events are added to the
170 // buffer, and decremented when SwapQueue() is called and the file task
171 // runner's local queue is swapped with the shared write queue.
172 //
173 // |lock_| must be acquired to read or write to this.
174 uint64_t memory_;
175
176 // Indicates the maximum amount of memory that the |queue_| is allowed to
177 // use.
178 const uint64_t memory_max_;
179
180 // Protects access to |queue_| and |memory_|.
181 //
182 // A lock is necessary because |queue_| and |memory_| are shared between the
183 // file task runner and the main thread. NetLog's lock protects OnAddEntry(),
184 // which calls AddEntryToQueue(), but it does not protect access to the
185 // observer's member variables. Thus, a race condition exists if a thread is
186 // calling OnAddEntry() at the same time that the file task runner is
187 // accessing |memory_| and |queue_| to write events to file. The |queue_| and
188 // |memory_| counter are necessary to bound the amount of memory that is used
189 // for the queue in the event that the file task runner lags significantly
190 // behind the main thread in writing events to file.
191 base::Lock lock_;
192
193 DISALLOW_COPY_AND_ASSIGN(WriteQueue);
194 };
195
196 // FileWriter is responsible for draining events from a WriteQueue and writing
197 // them to disk. FileWriter can be constructed on any thread, and
198 // afterwards is only accessed on the file task runner.
199 class FileNetLogObserver::FileWriter {
200 public:
201 // If max_event_file_size == kNoLimit, then no limit is enforced.
202 FileWriter(const base::FilePath& log_path,
203 const base::FilePath& inprogress_dir_path,
204 base::Optional<base::File> pre_existing_log_file,
205 uint64_t max_event_file_size,
206 size_t total_num_event_files,
207 scoped_refptr<base::SequencedTaskRunner> task_runner);
208
209 ~FileWriter();
210
211 // Writes |constants_value| to disk and opens the events array (closed in
212 // Stop()).
213 void Initialize(std::unique_ptr<base::Value> constants_value);
214
215 // Closes the events array opened in Initialize() and writes |polled_data| to
216 // disk. If |polled_data| cannot be converted to proper JSON, then it
217 // is ignored.
218 void Stop(std::unique_ptr<base::Value> polled_data);
219
220 // Drains |queue_| from WriteQueue into a local file queue and writes the
221 // events in the queue to disk.
222 void Flush(scoped_refptr<WriteQueue> write_queue);
223
224 // Deletes all netlog files. It is not valid to call any method of
225 // FileNetLogObserver after DeleteAllFiles().
226 void DeleteAllFiles();
227
228 void FlushThenStop(scoped_refptr<WriteQueue> write_queue,
229 std::unique_ptr<base::Value> polled_data);
230
231 private:
232 // Returns true if there is no file size bound to enforce.
233 //
234 // When operating in unbounded mode, the implementation is optimized to stream
235 // writes to a single file, rather than chunking them across temporary event
236 // files.
237 bool IsUnbounded() const;
238 bool IsBounded() const;
239
240 // Increments |current_event_file_number_|, and updates all state relating to
241 // the current event file (open file handle, num bytes written, current file
242 // number).
243 void IncrementCurrentEventFile();
244
245 // Returns the path to the event file having |index|. This looks like
246 // "LOGDIR/event_file_<index>.json".
247 base::FilePath GetEventFilePath(size_t index) const;
248
249 // Gets the file path where constants are saved at the start of
250 // logging. This looks like "LOGDIR/constants.json".
251 base::FilePath GetConstantsFilePath() const;
252
253 // Gets the file path where the final data is written at the end of logging.
254 // This looks like "LOGDIR/end_netlog.json".
255 base::FilePath GetClosingFilePath() const;
256
257 // Returns the corresponding index for |file_number|. File "numbers" are a
258 // monotonically increasing identifier that start at 1 (a value of zero means
259 // it is uninitialized), whereas the file "index" is a bounded value that
260 // wraps and identifies the file path to use.
261 //
262 // Keeping track of the current number rather than index makes it a bit easier
263 // to assemble a file at the end, since it is unambiguous which paths have
264 // been used/re-used.
265 size_t FileNumberToIndex(size_t file_number) const;
266
267 // Writes |constants_value| to a file.
268 static void WriteConstantsToFile(std::unique_ptr<base::Value> constants_value,
269 base::File* file);
270
271 // Writes |polled_data| to a file.
272 static void WritePolledDataToFile(std::unique_ptr<base::Value> polled_data,
273 base::File* file);
274
275 // If any events were written (wrote_event_bytes_), rewinds |file| by 2 bytes
276 // in order to overwrite the trailing ",\n" that was written by the last event
277 // line.
278 void RewindIfWroteEventBytes(base::File* file) const;
279
280 // Concatenates all the log files to assemble the final
281 // |final_log_file_|. This single "stitched" file is what other
282 // log ingesting tools expect.
283 void StitchFinalLogFile();
284
285 // Creates the .inprogress directory used by bounded mode.
286 void CreateInprogressDirectory();
287
288 // The file the final netlog is written to. In bounded mode this is mostly
289 // written to once logging is stopped, whereas in unbounded mode events will
290 // be directly written to it.
291 base::File final_log_file_;
292
293 // If non-empty, this is the path to |final_log_file_| created and owned
294 // by FileWriter itself (rather than passed in to Create*PreExisting
295 // methods of FileNetLogObserver).
296 const base::FilePath final_log_path_;
297
298 // Path to a (temporary) directory where files are written in bounded mode.
299 // When logging is stopped these files are stitched together and written
300 // to the final log path.
301 const base::FilePath inprogress_dir_path_;
302
303 // Holds the numbered events file where data is currently being written to.
304 // The file path of this file is GetEventFilePath(current_event_file_number_).
305 // The file may be !IsValid() if an error previously occurred opening the
306 // file, or logging has been stopped.
307 base::File current_event_file_;
308 uint64_t current_event_file_size_;
309
310 // Indicates the total number of netlog event files allowed.
311 // (The files GetConstantsFilePath() and GetClosingFilePath() do
312 // not count against the total.)
313 const size_t total_num_event_files_;
314
315 // Counter for the events file currently being written into. See
316 // FileNumberToIndex() for an explanation of what "number" vs "index" mean.
317 size_t current_event_file_number_;
318
319 // Indicates the maximum size of each individual events file. May be kNoLimit
320 // to indicate that it can grow arbitrarily large.
321 const uint64_t max_event_file_size_;
322
323 // Whether any bytes were written for events. This is used to properly format
324 // JSON (events list shouldn't end with a comma).
325 bool wrote_event_bytes_;
326
327 // Task runner for doing file operations.
328 const scoped_refptr<base::SequencedTaskRunner> task_runner_;
329
330 DISALLOW_COPY_AND_ASSIGN(FileWriter);
331 };
332
CreateBounded(const base::FilePath & log_path,uint64_t max_total_size,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value> constants)333 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateBounded(
334 const base::FilePath& log_path,
335 uint64_t max_total_size,
336 NetLogCaptureMode capture_mode,
337 std::unique_ptr<base::Value> constants) {
338 return CreateInternal(log_path, SiblingInprogressDirectory(log_path),
339 base::nullopt, max_total_size, kDefaultNumFiles,
340 capture_mode, std::move(constants));
341 }
342
CreateUnbounded(const base::FilePath & log_path,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value> constants)343 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateUnbounded(
344 const base::FilePath& log_path,
345 NetLogCaptureMode capture_mode,
346 std::unique_ptr<base::Value> constants) {
347 return CreateInternal(log_path, base::FilePath(), base::nullopt, kNoLimit,
348 kDefaultNumFiles, capture_mode, std::move(constants));
349 }
350
351 std::unique_ptr<FileNetLogObserver>
CreateBoundedPreExisting(const base::FilePath & inprogress_dir_path,base::File output_file,uint64_t max_total_size,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value> constants)352 FileNetLogObserver::CreateBoundedPreExisting(
353 const base::FilePath& inprogress_dir_path,
354 base::File output_file,
355 uint64_t max_total_size,
356 NetLogCaptureMode capture_mode,
357 std::unique_ptr<base::Value> constants) {
358 return CreateInternal(base::FilePath(), inprogress_dir_path,
359 base::make_optional<base::File>(std::move(output_file)),
360 max_total_size, kDefaultNumFiles, capture_mode,
361 std::move(constants));
362 }
363
364 std::unique_ptr<FileNetLogObserver>
CreateUnboundedPreExisting(base::File output_file,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value> constants)365 FileNetLogObserver::CreateUnboundedPreExisting(
366 base::File output_file,
367 NetLogCaptureMode capture_mode,
368 std::unique_ptr<base::Value> constants) {
369 return CreateInternal(base::FilePath(), base::FilePath(),
370 base::make_optional<base::File>(std::move(output_file)),
371 kNoLimit, kDefaultNumFiles, capture_mode,
372 std::move(constants));
373 }
374
~FileNetLogObserver()375 FileNetLogObserver::~FileNetLogObserver() {
376 if (net_log()) {
377 // StopObserving was not called.
378 net_log()->RemoveObserver(this);
379 file_task_runner_->PostTask(
380 FROM_HERE,
381 base::BindOnce(&FileNetLogObserver::FileWriter::DeleteAllFiles,
382 base::Unretained(file_writer_.get())));
383 }
384 file_task_runner_->DeleteSoon(FROM_HERE, file_writer_.release());
385 }
386
StartObserving(NetLog * net_log)387 void FileNetLogObserver::StartObserving(NetLog* net_log) {
388 net_log->AddObserver(this, capture_mode_);
389 }
390
StopObserving(std::unique_ptr<base::Value> polled_data,base::OnceClosure optional_callback)391 void FileNetLogObserver::StopObserving(std::unique_ptr<base::Value> polled_data,
392 base::OnceClosure optional_callback) {
393 net_log()->RemoveObserver(this);
394
395 base::OnceClosure bound_flush_then_stop =
396 base::BindOnce(&FileNetLogObserver::FileWriter::FlushThenStop,
397 base::Unretained(file_writer_.get()), write_queue_,
398 std::move(polled_data));
399
400 // Note that PostTaskAndReply() requires a non-null closure.
401 if (!optional_callback.is_null()) {
402 file_task_runner_->PostTaskAndReply(FROM_HERE,
403 std::move(bound_flush_then_stop),
404 std::move(optional_callback));
405 } else {
406 file_task_runner_->PostTask(FROM_HERE, std::move(bound_flush_then_stop));
407 }
408 }
409
OnAddEntry(const NetLogEntry & entry)410 void FileNetLogObserver::OnAddEntry(const NetLogEntry& entry) {
411 std::unique_ptr<std::string> json(new std::string);
412
413 *json = SerializeNetLogValueToJson(entry.ToValue());
414
415 size_t queue_size = write_queue_->AddEntryToQueue(std::move(json));
416
417 // If events build up in |write_queue_|, trigger the file task runner to drain
418 // the queue. Because only 1 item is added to the queue at a time, if
419 // queue_size > kNumWriteQueueEvents a task has already been posted, or will
420 // be posted.
421 if (queue_size == kNumWriteQueueEvents) {
422 file_task_runner_->PostTask(
423 FROM_HERE,
424 base::BindOnce(&FileNetLogObserver::FileWriter::Flush,
425 base::Unretained(file_writer_.get()), write_queue_));
426 }
427 }
428
CreateBoundedForTests(const base::FilePath & log_path,uint64_t max_total_size,size_t total_num_event_files,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value> constants)429 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateBoundedForTests(
430 const base::FilePath& log_path,
431 uint64_t max_total_size,
432 size_t total_num_event_files,
433 NetLogCaptureMode capture_mode,
434 std::unique_ptr<base::Value> constants) {
435 return CreateInternal(log_path, SiblingInprogressDirectory(log_path),
436 base::nullopt, max_total_size, total_num_event_files,
437 capture_mode, std::move(constants));
438 }
439
CreateInternal(const base::FilePath & log_path,const base::FilePath & inprogress_dir_path,base::Optional<base::File> pre_existing_log_file,uint64_t max_total_size,size_t total_num_event_files,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value> constants)440 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateInternal(
441 const base::FilePath& log_path,
442 const base::FilePath& inprogress_dir_path,
443 base::Optional<base::File> pre_existing_log_file,
444 uint64_t max_total_size,
445 size_t total_num_event_files,
446 NetLogCaptureMode capture_mode,
447 std::unique_ptr<base::Value> constants) {
448 DCHECK_GT(total_num_event_files, 0u);
449
450 scoped_refptr<base::SequencedTaskRunner> file_task_runner =
451 CreateFileTaskRunner();
452
453 const uint64_t max_event_file_size =
454 max_total_size == kNoLimit ? kNoLimit
455 : max_total_size / total_num_event_files;
456
457 // The FileWriter uses a soft limit to write events to file that allows
458 // the size of the file to exceed the limit, but the WriteQueue uses a hard
459 // limit which the size of |WriteQueue::queue_| cannot exceed. Thus, the
460 // FileWriter may write more events to file than can be contained by
461 // the WriteQueue if they have the same size limit. The maximum size of the
462 // WriteQueue is doubled to allow |WriteQueue::queue_| to hold enough events
463 // for the FileWriter to fill all files. As long as all events have
464 // sizes <= the size of an individual event file, the discrepancy between the
465 // hard limit and the soft limit will not cause an issue.
466 // TODO(dconnol): Handle the case when the WriteQueue still doesn't
467 // contain enough events to fill all files, because of very large events
468 // relative to file size.
469 std::unique_ptr<FileWriter> file_writer(new FileWriter(
470 log_path, inprogress_dir_path, std::move(pre_existing_log_file),
471 max_event_file_size, total_num_event_files, file_task_runner));
472
473 uint64_t write_queue_memory_max =
474 base::MakeClampedNum<uint64_t>(max_total_size) * 2;
475
476 return base::WrapUnique(new FileNetLogObserver(
477 file_task_runner, std::move(file_writer),
478 base::WrapRefCounted(new WriteQueue(write_queue_memory_max)),
479 capture_mode, std::move(constants)));
480 }
481
FileNetLogObserver(scoped_refptr<base::SequencedTaskRunner> file_task_runner,std::unique_ptr<FileWriter> file_writer,scoped_refptr<WriteQueue> write_queue,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value> constants)482 FileNetLogObserver::FileNetLogObserver(
483 scoped_refptr<base::SequencedTaskRunner> file_task_runner,
484 std::unique_ptr<FileWriter> file_writer,
485 scoped_refptr<WriteQueue> write_queue,
486 NetLogCaptureMode capture_mode,
487 std::unique_ptr<base::Value> constants)
488 : file_task_runner_(std::move(file_task_runner)),
489 write_queue_(std::move(write_queue)),
490 file_writer_(std::move(file_writer)),
491 capture_mode_(capture_mode) {
492 if (!constants)
493 constants = base::Value::ToUniquePtrValue(GetNetConstants());
494
495 DCHECK(!constants->FindKey("logCaptureMode"));
496 constants->SetStringKey("logCaptureMode", CaptureModeToString(capture_mode));
497 file_task_runner_->PostTask(
498 FROM_HERE, base::BindOnce(&FileNetLogObserver::FileWriter::Initialize,
499 base::Unretained(file_writer_.get()),
500 std::move(constants)));
501 }
502
CaptureModeToString(NetLogCaptureMode mode)503 std::string FileNetLogObserver::CaptureModeToString(NetLogCaptureMode mode) {
504 switch (mode) {
505 case NetLogCaptureMode::kDefault:
506 return "Default";
507 case NetLogCaptureMode::kIncludeSensitive:
508 return "IncludeSensitive";
509 case NetLogCaptureMode::kEverything:
510 return "Everything";
511 }
512 NOTREACHED();
513 return "UNKNOWN";
514 }
515
WriteQueue(uint64_t memory_max)516 FileNetLogObserver::WriteQueue::WriteQueue(uint64_t memory_max)
517 : memory_(0), memory_max_(memory_max) {}
518
AddEntryToQueue(std::unique_ptr<std::string> event)519 size_t FileNetLogObserver::WriteQueue::AddEntryToQueue(
520 std::unique_ptr<std::string> event) {
521 base::AutoLock lock(lock_);
522
523 memory_ += event->size();
524 queue_.push(std::move(event));
525
526 while (memory_ > memory_max_ && !queue_.empty()) {
527 // Delete oldest events in the queue.
528 DCHECK(queue_.front());
529 memory_ -= queue_.front()->size();
530 queue_.pop();
531 }
532
533 return queue_.size();
534 }
535
SwapQueue(EventQueue * local_queue)536 void FileNetLogObserver::WriteQueue::SwapQueue(EventQueue* local_queue) {
537 DCHECK(local_queue->empty());
538 base::AutoLock lock(lock_);
539 queue_.swap(*local_queue);
540 memory_ = 0;
541 }
542
543 FileNetLogObserver::WriteQueue::~WriteQueue() = default;
544
FileWriter(const base::FilePath & log_path,const base::FilePath & inprogress_dir_path,base::Optional<base::File> pre_existing_log_file,uint64_t max_event_file_size,size_t total_num_event_files,scoped_refptr<base::SequencedTaskRunner> task_runner)545 FileNetLogObserver::FileWriter::FileWriter(
546 const base::FilePath& log_path,
547 const base::FilePath& inprogress_dir_path,
548 base::Optional<base::File> pre_existing_log_file,
549 uint64_t max_event_file_size,
550 size_t total_num_event_files,
551 scoped_refptr<base::SequencedTaskRunner> task_runner)
552 : final_log_path_(log_path),
553 inprogress_dir_path_(inprogress_dir_path),
554 total_num_event_files_(total_num_event_files),
555 current_event_file_number_(0),
556 max_event_file_size_(max_event_file_size),
557 wrote_event_bytes_(false),
558 task_runner_(std::move(task_runner)) {
559 DCHECK_EQ(pre_existing_log_file.has_value(), log_path.empty());
560 DCHECK_EQ(IsBounded(), !inprogress_dir_path.empty());
561
562 if (pre_existing_log_file.has_value()) {
563 // pre_existing_log_file.IsValid() being false is fine.
564 final_log_file_ = std::move(pre_existing_log_file.value());
565 }
566 }
567
568 FileNetLogObserver::FileWriter::~FileWriter() = default;
569
Initialize(std::unique_ptr<base::Value> constants_value)570 void FileNetLogObserver::FileWriter::Initialize(
571 std::unique_ptr<base::Value> constants_value) {
572 DCHECK(task_runner_->RunsTasksInCurrentSequence());
573
574 // Open the final log file, and keep it open for the duration of logging (even
575 // in bounded mode).
576 if (!final_log_path_.empty())
577 final_log_file_ = OpenFileForWrite(final_log_path_);
578 else
579 TruncateFile(&final_log_file_);
580
581 if (IsBounded()) {
582 CreateInprogressDirectory();
583 base::File constants_file = OpenFileForWrite(GetConstantsFilePath());
584 WriteConstantsToFile(std::move(constants_value), &constants_file);
585 } else {
586 WriteConstantsToFile(std::move(constants_value), &final_log_file_);
587 }
588 }
589
Stop(std::unique_ptr<base::Value> polled_data)590 void FileNetLogObserver::FileWriter::Stop(
591 std::unique_ptr<base::Value> polled_data) {
592 DCHECK(task_runner_->RunsTasksInCurrentSequence());
593
594 // Write out the polled data.
595 if (IsBounded()) {
596 base::File closing_file = OpenFileForWrite(GetClosingFilePath());
597 WritePolledDataToFile(std::move(polled_data), &closing_file);
598 } else {
599 RewindIfWroteEventBytes(&final_log_file_);
600 WritePolledDataToFile(std::move(polled_data), &final_log_file_);
601 }
602
603 // If operating in bounded mode, the events were written to separate files
604 // within |inprogress_dir_path_|. Assemble them into the final destination
605 // file.
606 if (IsBounded())
607 StitchFinalLogFile();
608
609 // Ensure the final log file has been flushed.
610 final_log_file_.Close();
611 }
612
Flush(scoped_refptr<FileNetLogObserver::WriteQueue> write_queue)613 void FileNetLogObserver::FileWriter::Flush(
614 scoped_refptr<FileNetLogObserver::WriteQueue> write_queue) {
615 DCHECK(task_runner_->RunsTasksInCurrentSequence());
616
617 EventQueue local_file_queue;
618 write_queue->SwapQueue(&local_file_queue);
619
620 while (!local_file_queue.empty()) {
621 base::File* output_file;
622
623 // If in bounded mode, output events to the current event file. Otherwise
624 // output events to the final log path.
625 if (IsBounded()) {
626 if (current_event_file_number_ == 0 ||
627 current_event_file_size_ >= max_event_file_size_) {
628 IncrementCurrentEventFile();
629 }
630 output_file = ¤t_event_file_;
631 } else {
632 output_file = &final_log_file_;
633 }
634
635 size_t bytes_written =
636 WriteToFile(output_file, *local_file_queue.front(), ",\n");
637
638 wrote_event_bytes_ |= bytes_written > 0;
639
640 // Keep track of the filesize for current event file when in bounded mode.
641 if (IsBounded())
642 current_event_file_size_ += bytes_written;
643
644 local_file_queue.pop();
645 }
646 }
647
DeleteAllFiles()648 void FileNetLogObserver::FileWriter::DeleteAllFiles() {
649 DCHECK(task_runner_->RunsTasksInCurrentSequence());
650
651 final_log_file_.Close();
652
653 if (IsBounded()) {
654 current_event_file_.Close();
655 base::DeletePathRecursively(inprogress_dir_path_);
656 }
657
658 // Only delete |final_log_file_| if it was created internally.
659 // (If it was provided as a base::File by the caller, don't try to delete it).
660 if (!final_log_path_.empty())
661 base::DeleteFile(final_log_path_);
662 }
663
FlushThenStop(scoped_refptr<FileNetLogObserver::WriteQueue> write_queue,std::unique_ptr<base::Value> polled_data)664 void FileNetLogObserver::FileWriter::FlushThenStop(
665 scoped_refptr<FileNetLogObserver::WriteQueue> write_queue,
666 std::unique_ptr<base::Value> polled_data) {
667 Flush(write_queue);
668 Stop(std::move(polled_data));
669 }
670
IsUnbounded() const671 bool FileNetLogObserver::FileWriter::IsUnbounded() const {
672 return max_event_file_size_ == kNoLimit;
673 }
674
IsBounded() const675 bool FileNetLogObserver::FileWriter::IsBounded() const {
676 return !IsUnbounded();
677 }
678
IncrementCurrentEventFile()679 void FileNetLogObserver::FileWriter::IncrementCurrentEventFile() {
680 DCHECK(task_runner_->RunsTasksInCurrentSequence());
681 DCHECK(IsBounded());
682
683 current_event_file_number_++;
684 current_event_file_ = OpenFileForWrite(
685 GetEventFilePath(FileNumberToIndex(current_event_file_number_)));
686 current_event_file_size_ = 0;
687 }
688
GetEventFilePath(size_t index) const689 base::FilePath FileNetLogObserver::FileWriter::GetEventFilePath(
690 size_t index) const {
691 DCHECK_LT(index, total_num_event_files_);
692 DCHECK(IsBounded());
693 return inprogress_dir_path_.AppendASCII(
694 "event_file_" + base::NumberToString(index) + ".json");
695 }
696
GetConstantsFilePath() const697 base::FilePath FileNetLogObserver::FileWriter::GetConstantsFilePath() const {
698 return inprogress_dir_path_.AppendASCII("constants.json");
699 }
700
GetClosingFilePath() const701 base::FilePath FileNetLogObserver::FileWriter::GetClosingFilePath() const {
702 return inprogress_dir_path_.AppendASCII("end_netlog.json");
703 }
704
FileNumberToIndex(size_t file_number) const705 size_t FileNetLogObserver::FileWriter::FileNumberToIndex(
706 size_t file_number) const {
707 DCHECK_GT(file_number, 0u);
708 // Note that "file numbers" start at 1 not 0.
709 return (file_number - 1) % total_num_event_files_;
710 }
711
WriteConstantsToFile(std::unique_ptr<base::Value> constants_value,base::File * file)712 void FileNetLogObserver::FileWriter::WriteConstantsToFile(
713 std::unique_ptr<base::Value> constants_value,
714 base::File* file) {
715 // Print constants to file and open events array.
716 std::string json = SerializeNetLogValueToJson(*constants_value);
717 WriteToFile(file, "{\"constants\":", json, ",\n\"events\": [\n");
718 }
719
WritePolledDataToFile(std::unique_ptr<base::Value> polled_data,base::File * file)720 void FileNetLogObserver::FileWriter::WritePolledDataToFile(
721 std::unique_ptr<base::Value> polled_data,
722 base::File* file) {
723 // Close the events array.
724 WriteToFile(file, "]");
725
726 // Write the polled data (if any).
727 if (polled_data) {
728 std::string polled_data_json;
729 base::JSONWriter::Write(*polled_data, &polled_data_json);
730 if (!polled_data_json.empty())
731 WriteToFile(file, ",\n\"polledData\": ", polled_data_json, "\n");
732 }
733
734 // Close the log.
735 WriteToFile(file, "}\n");
736 }
737
RewindIfWroteEventBytes(base::File * file) const738 void FileNetLogObserver::FileWriter::RewindIfWroteEventBytes(
739 base::File* file) const {
740 if (file->IsValid() && wrote_event_bytes_) {
741 // To be valid JSON the events array should not end with a comma. If events
742 // were written though, they will have been terminated with "\n," so strip
743 // it before closing the events array.
744 file->Seek(base::File::FROM_END, -2);
745 }
746 }
747
StitchFinalLogFile()748 void FileNetLogObserver::FileWriter::StitchFinalLogFile() {
749 // Make sure all the events files are flushed (as will read them next).
750 current_event_file_.Close();
751
752 // Allocate a 64K buffer used for reading the files. At most kReadBufferSize
753 // bytes will be in memory at a time.
754 const size_t kReadBufferSize = 1 << 16; // 64KiB
755 std::unique_ptr<char[]> read_buffer(new char[kReadBufferSize]);
756
757 if (final_log_file_.IsValid()) {
758 // Truncate the final log file.
759 TruncateFile(&final_log_file_);
760
761 // Append the constants file.
762 AppendToFileThenDelete(GetConstantsFilePath(), &final_log_file_,
763 read_buffer.get(), kReadBufferSize);
764
765 // Iterate over the events files, from oldest to most recent, and append
766 // them to the final destination. Note that "file numbers" start at 1 not 0.
767 size_t end_filenumber = current_event_file_number_ + 1;
768 size_t begin_filenumber =
769 current_event_file_number_ <= total_num_event_files_
770 ? 1
771 : end_filenumber - total_num_event_files_;
772 for (size_t filenumber = begin_filenumber; filenumber < end_filenumber;
773 ++filenumber) {
774 AppendToFileThenDelete(GetEventFilePath(FileNumberToIndex(filenumber)),
775 &final_log_file_, read_buffer.get(),
776 kReadBufferSize);
777 }
778
779 // Account for the final event line ending in a ",\n". Strip it to form
780 // valid JSON.
781 RewindIfWroteEventBytes(&final_log_file_);
782
783 // Append the polled data.
784 AppendToFileThenDelete(GetClosingFilePath(), &final_log_file_,
785 read_buffer.get(), kReadBufferSize);
786 }
787
788 // Delete the inprogress directory (and anything that may still be left inside
789 // it).
790 base::DeletePathRecursively(inprogress_dir_path_);
791 }
792
CreateInprogressDirectory()793 void FileNetLogObserver::FileWriter::CreateInprogressDirectory() {
794 DCHECK(IsBounded());
795
796 // If an output file couldn't be created, either creation of intermediate
797 // files will also fail (if they're in a sibling directory), or are they are
798 // hidden somewhere the user would be unlikely to find them, so there is
799 // little reason to progress.
800 if (!final_log_file_.IsValid())
801 return;
802
803 if (!base::CreateDirectory(inprogress_dir_path_)) {
804 LOG(WARNING) << "Failed creating directory: "
805 << inprogress_dir_path_.value();
806 return;
807 }
808
809 // It is OK if the path is wrong due to encoding - this is really just a
810 // convenience display for the user in understanding what the file means.
811 std::string in_progress_path = inprogress_dir_path_.AsUTF8Unsafe();
812
813 // Since |final_log_file_| will not be written to until the very end, leave
814 // some data in it explaining that the real data is currently in the
815 // .inprogress directory. This ordinarily won't be visible (overwritten when
816 // stopping) however if logging does not end gracefully the comments are
817 // useful for recovery.
818 WriteToFile(
819 &final_log_file_, "Logging is in progress writing data to:\n ",
820 in_progress_path,
821 "\n\n"
822 "That data will be stitched into a single file (this one) once logging\n"
823 "has stopped.\n"
824 "\n"
825 "If logging was interrupted, you can stitch a NetLog file out of the\n"
826 ".inprogress directory manually using:\n"
827 "\n"
828 "https://chromium.googlesource.com/chromium/src/+/master/net/tools/"
829 "stitch_net_log_files.py\n");
830 }
831
SerializeNetLogValueToJson(const base::Value & value)832 std::string SerializeNetLogValueToJson(const base::Value& value) {
833 // Omit trailing ".0" when printing a DOUBLE that is representable as a 64-bit
834 // integer. This makes the values returned by NetLogNumberValue() look more
835 // pleasant (for representing integers between 32 and 53 bits large).
836 int options = base::JSONWriter::OPTIONS_OMIT_DOUBLE_TYPE_PRESERVATION;
837
838 std::string json;
839 bool ok = base::JSONWriter::WriteWithOptions(value, options, &json);
840
841 // Serialization shouldn't fail. However it can if a consumer has passed a
842 // parameter of type BINARY, since JSON serialization can't handle that.
843 DCHECK(ok);
844
845 return json;
846 }
847
848 } // namespace net
849