• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 // Copyright 2016 The Chromium Authors
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/containers/queue.h"
13 #include "base/files/file.h"
14 #include "base/files/file_util.h"
15 #include "base/functional/bind.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/strings/string_number_conversions.h"
21 #include "base/synchronization/lock.h"
22 #include "base/task/sequenced_task_runner.h"
23 #include "base/task/thread_pool.h"
24 #include "base/values.h"
25 #include "net/log/net_log_capture_mode.h"
26 #include "net/log/net_log_entry.h"
27 #include "net/log/net_log_util.h"
28 #include "net/url_request/url_request_context.h"
29 
30 namespace {
31 
32 // Number of events that can build up in |write_queue_| before a task is posted
33 // to the file task runner to flush them to disk.
34 const int kNumWriteQueueEvents = 15;
35 
36 // TODO(eroman): Should use something other than 10 for number of files?
37 const int kDefaultNumFiles = 10;
38 
CreateFileTaskRunner()39 scoped_refptr<base::SequencedTaskRunner> CreateFileTaskRunner() {
40   // The tasks posted to this sequenced task runner do synchronous File I/O for
41   // the purposes of writing NetLog files.
42   //
43   // These intentionally block shutdown to ensure the log file has finished
44   // being written.
45   return base::ThreadPool::CreateSequencedTaskRunner(
46       {base::MayBlock(), base::TaskPriority::USER_VISIBLE,
47        base::TaskShutdownBehavior::BLOCK_SHUTDOWN});
48 }
49 
50 // Truncates a file, also reseting the seek position.
TruncateFile(base::File * file)51 void TruncateFile(base::File* file) {
52   if (!file->IsValid())
53     return;
54   file->Seek(base::File::FROM_BEGIN, 0);
55   file->SetLength(0);
56 }
57 
58 // Opens |path| in write mode.
OpenFileForWrite(const base::FilePath & path)59 base::File OpenFileForWrite(const base::FilePath& path) {
60   base::File result(path,
61                     base::File::FLAG_CREATE_ALWAYS | base::File::FLAG_WRITE);
62   LOG_IF(ERROR, !result.IsValid()) << "Failed opening: " << path.value();
63   return result;
64 }
65 
66 // Helper that writes data to a file. |file->IsValid()| may be false,
67 // in which case nothing will be written. Returns the number of bytes
68 // 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 ())69 size_t WriteToFile(base::File* file,
70                    base::StringPiece data1,
71                    base::StringPiece data2 = base::StringPiece(),
72                    base::StringPiece data3 = base::StringPiece()) {
73   size_t bytes_written = 0;
74 
75   if (file->IsValid()) {
76     // Append each of data1, data2 and data3.
77     if (!data1.empty())
78       bytes_written +=
79           std::max(0, file->WriteAtCurrentPos(data1.data(), data1.size()));
80     if (!data2.empty())
81       bytes_written +=
82           std::max(0, file->WriteAtCurrentPos(data2.data(), data2.size()));
83     if (!data3.empty())
84       bytes_written +=
85           std::max(0, file->WriteAtCurrentPos(data3.data(), data3.size()));
86   }
87 
88   return bytes_written;
89 }
90 
91 // Copies all of the data at |source_path| and appends it to |destination_file|,
92 // then deletes |source_path|.
AppendToFileThenDelete(const base::FilePath & source_path,base::File * destination_file,char * read_buffer,size_t read_buffer_size)93 void AppendToFileThenDelete(const base::FilePath& source_path,
94                             base::File* destination_file,
95                             char* read_buffer,
96                             size_t read_buffer_size) {
97   base::ScopedFILE source_file(base::OpenFile(source_path, "rb"));
98   if (!source_file)
99     return;
100 
101   // Read |source_path|'s contents in chunks of read_buffer_size and append
102   // to |destination_file|.
103   size_t num_bytes_read;
104   while ((num_bytes_read =
105               fread(read_buffer, 1, read_buffer_size, source_file.get())) > 0) {
106     WriteToFile(destination_file,
107                 base::StringPiece(read_buffer, num_bytes_read));
108   }
109 
110   // Now that it has been copied, delete the source file.
111   source_file.reset();
112   base::DeleteFile(source_path);
113 }
114 
SiblingInprogressDirectory(const base::FilePath & log_path)115 base::FilePath SiblingInprogressDirectory(const base::FilePath& log_path) {
116   return log_path.AddExtension(FILE_PATH_LITERAL(".inprogress"));
117 }
118 
119 }  // namespace
120 
121 namespace net {
122 
123 // Used to store events to be written to file.
124 using EventQueue = base::queue<std::unique_ptr<std::string>>;
125 
126 // WriteQueue receives events from FileNetLogObserver on the main thread and
127 // holds them in a queue until they are drained from the queue and written to
128 // file on the file task runner.
129 //
130 // WriteQueue contains the resources shared between the main thread and the
131 // file task runner. |lock_| must be acquired to read or write to |queue_| and
132 // |memory_|.
133 //
134 // WriteQueue is refcounted and should be destroyed once all events on the
135 // file task runner have finished executing.
136 class FileNetLogObserver::WriteQueue
137     : public base::RefCountedThreadSafe<WriteQueue> {
138  public:
139   // |memory_max| indicates the maximum amount of memory that the virtual write
140   // queue can use. If |memory_| exceeds |memory_max_|, the |queue_| of events
141   // is overwritten.
142   explicit WriteQueue(uint64_t memory_max);
143 
144   WriteQueue(const WriteQueue&) = delete;
145   WriteQueue& operator=(const WriteQueue&) = delete;
146 
147   // Adds |event| to |queue_|. Also manages the size of |memory_|; if it
148   // exceeds |memory_max_|, then old events are dropped from |queue_| without
149   // being written to file.
150   //
151   // Returns the number of events in the |queue_|.
152   size_t AddEntryToQueue(std::unique_ptr<std::string> event);
153 
154   // Swaps |queue_| with |local_queue|. |local_queue| should be empty, so that
155   // |queue_| is emptied. Resets |memory_| to 0.
156   void SwapQueue(EventQueue* local_queue);
157 
158  private:
159   friend class base::RefCountedThreadSafe<WriteQueue>;
160 
161   ~WriteQueue();
162 
163   // Queue of events to be written, shared between main thread and file task
164   // runner. Main thread adds events to the queue and the file task runner
165   // drains them and writes the events to file.
166   //
167   // |lock_| must be acquired to read or write to this.
168   EventQueue queue_;
169 
170   // Tracks how much memory is being used by the virtual write queue.
171   // Incremented in AddEntryToQueue() when events are added to the
172   // buffer, and decremented when SwapQueue() is called and the file task
173   // runner's local queue is swapped with the shared write queue.
174   //
175   // |lock_| must be acquired to read or write to this.
176   uint64_t memory_ = 0;
177 
178   // Indicates the maximum amount of memory that the |queue_| is allowed to
179   // use.
180   const uint64_t memory_max_;
181 
182   // Protects access to |queue_| and |memory_|.
183   //
184   // A lock is necessary because |queue_| and |memory_| are shared between the
185   // file task runner and the main thread. NetLog's lock protects OnAddEntry(),
186   // which calls AddEntryToQueue(), but it does not protect access to the
187   // observer's member variables. Thus, a race condition exists if a thread is
188   // calling OnAddEntry() at the same time that the file task runner is
189   // accessing |memory_| and |queue_| to write events to file. The |queue_| and
190   // |memory_| counter are necessary to bound the amount of memory that is used
191   // for the queue in the event that the file task runner lags significantly
192   // behind the main thread in writing events to file.
193   base::Lock lock_;
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              absl::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(const FileWriter&) = delete;
210   FileWriter& operator=(const FileWriter&) = delete;
211 
212   ~FileWriter();
213 
214   // Writes |constants_value| to disk and opens the events array (closed in
215   // Stop()).
216   void Initialize(std::unique_ptr<base::Value::Dict> constants_value);
217 
218   // Closes the events array opened in Initialize() and writes |polled_data| to
219   // disk. If |polled_data| cannot be converted to proper JSON, then it
220   // is ignored.
221   void Stop(std::unique_ptr<base::Value> polled_data);
222 
223   // Drains |queue_| from WriteQueue into a local file queue and writes the
224   // events in the queue to disk.
225   void Flush(scoped_refptr<WriteQueue> write_queue);
226 
227   // Deletes all netlog files. It is not valid to call any method of
228   // FileNetLogObserver after DeleteAllFiles().
229   void DeleteAllFiles();
230 
231   void FlushThenStop(scoped_refptr<WriteQueue> write_queue,
232                      std::unique_ptr<base::Value> polled_data);
233 
234  private:
235   // Returns true if there is no file size bound to enforce.
236   //
237   // When operating in unbounded mode, the implementation is optimized to stream
238   // writes to a single file, rather than chunking them across temporary event
239   // files.
240   bool IsUnbounded() const;
241   bool IsBounded() const;
242 
243   // Increments |current_event_file_number_|, and updates all state relating to
244   // the current event file (open file handle, num bytes written, current file
245   // number).
246   void IncrementCurrentEventFile();
247 
248   // Returns the path to the event file having |index|. This looks like
249   // "LOGDIR/event_file_<index>.json".
250   base::FilePath GetEventFilePath(size_t index) const;
251 
252   // Gets the file path where constants are saved at the start of
253   // logging. This looks like "LOGDIR/constants.json".
254   base::FilePath GetConstantsFilePath() const;
255 
256   // Gets the file path where the final data is written at the end of logging.
257   // This looks like "LOGDIR/end_netlog.json".
258   base::FilePath GetClosingFilePath() const;
259 
260   // Returns the corresponding index for |file_number|. File "numbers" are a
261   // monotonically increasing identifier that start at 1 (a value of zero means
262   // it is uninitialized), whereas the file "index" is a bounded value that
263   // wraps and identifies the file path to use.
264   //
265   // Keeping track of the current number rather than index makes it a bit easier
266   // to assemble a file at the end, since it is unambiguous which paths have
267   // been used/re-used.
268   size_t FileNumberToIndex(size_t file_number) const;
269 
270   // Writes |constants_value| to a file.
271   static void WriteConstantsToFile(
272       std::unique_ptr<base::Value::Dict> constants_value,
273       base::File* file);
274 
275   // Writes |polled_data| to a file.
276   static void WritePolledDataToFile(std::unique_ptr<base::Value> polled_data,
277                                     base::File* file);
278 
279   // If any events were written (wrote_event_bytes_), rewinds |file| by 2 bytes
280   // in order to overwrite the trailing ",\n" that was written by the last event
281   // line.
282   void RewindIfWroteEventBytes(base::File* file) const;
283 
284   // Concatenates all the log files to assemble the final
285   // |final_log_file_|. This single "stitched" file is what other
286   // log ingesting tools expect.
287   void StitchFinalLogFile();
288 
289   // Creates the .inprogress directory used by bounded mode.
290   void CreateInprogressDirectory();
291 
292   // The file the final netlog is written to. In bounded mode this is mostly
293   // written to once logging is stopped, whereas in unbounded mode events will
294   // be directly written to it.
295   base::File final_log_file_;
296 
297   // If non-empty, this is the path to |final_log_file_| created and owned
298   // by FileWriter itself (rather than passed in to Create*PreExisting
299   // methods of FileNetLogObserver).
300   const base::FilePath final_log_path_;
301 
302   // Path to a (temporary) directory where files are written in bounded mode.
303   // When logging is stopped these files are stitched together and written
304   // to the final log path.
305   const base::FilePath inprogress_dir_path_;
306 
307   // Holds the numbered events file where data is currently being written to.
308   // The file path of this file is GetEventFilePath(current_event_file_number_).
309   // The file may be !IsValid() if an error previously occurred opening the
310   // file, or logging has been stopped.
311   base::File current_event_file_;
312   uint64_t current_event_file_size_;
313 
314   // Indicates the total number of netlog event files allowed.
315   // (The files GetConstantsFilePath() and GetClosingFilePath() do
316   // not count against the total.)
317   const size_t total_num_event_files_;
318 
319   // Counter for the events file currently being written into. See
320   // FileNumberToIndex() for an explanation of what "number" vs "index" mean.
321   size_t current_event_file_number_ = 0;
322 
323   // Indicates the maximum size of each individual events file. May be kNoLimit
324   // to indicate that it can grow arbitrarily large.
325   const uint64_t max_event_file_size_;
326 
327   // Whether any bytes were written for events. This is used to properly format
328   // JSON (events list shouldn't end with a comma).
329   bool wrote_event_bytes_ = false;
330 
331   // Task runner for doing file operations.
332   const scoped_refptr<base::SequencedTaskRunner> task_runner_;
333 };
334 
CreateBounded(const base::FilePath & log_path,uint64_t max_total_size,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value::Dict> constants)335 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateBounded(
336     const base::FilePath& log_path,
337     uint64_t max_total_size,
338     NetLogCaptureMode capture_mode,
339     std::unique_ptr<base::Value::Dict> constants) {
340   return CreateInternal(log_path, SiblingInprogressDirectory(log_path),
341                         absl::nullopt, max_total_size, kDefaultNumFiles,
342                         capture_mode, std::move(constants));
343 }
344 
CreateUnbounded(const base::FilePath & log_path,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value::Dict> constants)345 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateUnbounded(
346     const base::FilePath& log_path,
347     NetLogCaptureMode capture_mode,
348     std::unique_ptr<base::Value::Dict> constants) {
349   return CreateInternal(log_path, base::FilePath(), absl::nullopt, kNoLimit,
350                         kDefaultNumFiles, capture_mode, std::move(constants));
351 }
352 
353 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::Dict> constants)354 FileNetLogObserver::CreateBoundedPreExisting(
355     const base::FilePath& inprogress_dir_path,
356     base::File output_file,
357     uint64_t max_total_size,
358     NetLogCaptureMode capture_mode,
359     std::unique_ptr<base::Value::Dict> constants) {
360   return CreateInternal(base::FilePath(), inprogress_dir_path,
361                         absl::make_optional<base::File>(std::move(output_file)),
362                         max_total_size, kDefaultNumFiles, capture_mode,
363                         std::move(constants));
364 }
365 
366 std::unique_ptr<FileNetLogObserver>
CreateUnboundedPreExisting(base::File output_file,NetLogCaptureMode capture_mode,std::unique_ptr<base::Value::Dict> constants)367 FileNetLogObserver::CreateUnboundedPreExisting(
368     base::File output_file,
369     NetLogCaptureMode capture_mode,
370     std::unique_ptr<base::Value::Dict> constants) {
371   return CreateInternal(base::FilePath(), base::FilePath(),
372                         absl::make_optional<base::File>(std::move(output_file)),
373                         kNoLimit, kDefaultNumFiles, capture_mode,
374                         std::move(constants));
375 }
376 
~FileNetLogObserver()377 FileNetLogObserver::~FileNetLogObserver() {
378   if (net_log()) {
379     // StopObserving was not called.
380     net_log()->RemoveObserver(this);
381     file_task_runner_->PostTask(
382         FROM_HERE,
383         base::BindOnce(&FileNetLogObserver::FileWriter::DeleteAllFiles,
384                        base::Unretained(file_writer_.get())));
385   }
386   file_task_runner_->DeleteSoon(FROM_HERE, file_writer_.release());
387 }
388 
StartObserving(NetLog * net_log)389 void FileNetLogObserver::StartObserving(NetLog* net_log) {
390   net_log->AddObserver(this, capture_mode_);
391 }
392 
StopObserving(std::unique_ptr<base::Value> polled_data,base::OnceClosure optional_callback)393 void FileNetLogObserver::StopObserving(std::unique_ptr<base::Value> polled_data,
394                                        base::OnceClosure optional_callback) {
395   net_log()->RemoveObserver(this);
396 
397   base::OnceClosure bound_flush_then_stop =
398       base::BindOnce(&FileNetLogObserver::FileWriter::FlushThenStop,
399                      base::Unretained(file_writer_.get()), write_queue_,
400                      std::move(polled_data));
401 
402   // Note that PostTaskAndReply() requires a non-null closure.
403   if (!optional_callback.is_null()) {
404     file_task_runner_->PostTaskAndReply(FROM_HERE,
405                                         std::move(bound_flush_then_stop),
406                                         std::move(optional_callback));
407   } else {
408     file_task_runner_->PostTask(FROM_HERE, std::move(bound_flush_then_stop));
409   }
410 }
411 
OnAddEntry(const NetLogEntry & entry)412 void FileNetLogObserver::OnAddEntry(const NetLogEntry& entry) {
413   auto json = std::make_unique<std::string>();
414 
415   *json = SerializeNetLogValueToJson(entry.ToDict());
416 
417   size_t queue_size = write_queue_->AddEntryToQueue(std::move(json));
418 
419   // If events build up in |write_queue_|, trigger the file task runner to drain
420   // the queue. Because only 1 item is added to the queue at a time, if
421   // queue_size > kNumWriteQueueEvents a task has already been posted, or will
422   // be posted.
423   if (queue_size == kNumWriteQueueEvents) {
424     file_task_runner_->PostTask(
425         FROM_HERE,
426         base::BindOnce(&FileNetLogObserver::FileWriter::Flush,
427                        base::Unretained(file_writer_.get()), write_queue_));
428   }
429 }
430 
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::Dict> constants)431 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateBoundedForTests(
432     const base::FilePath& log_path,
433     uint64_t max_total_size,
434     size_t total_num_event_files,
435     NetLogCaptureMode capture_mode,
436     std::unique_ptr<base::Value::Dict> constants) {
437   return CreateInternal(log_path, SiblingInprogressDirectory(log_path),
438                         absl::nullopt, max_total_size, total_num_event_files,
439                         capture_mode, std::move(constants));
440 }
441 
CreateInternal(const base::FilePath & log_path,const base::FilePath & inprogress_dir_path,absl::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::Dict> constants)442 std::unique_ptr<FileNetLogObserver> FileNetLogObserver::CreateInternal(
443     const base::FilePath& log_path,
444     const base::FilePath& inprogress_dir_path,
445     absl::optional<base::File> pre_existing_log_file,
446     uint64_t max_total_size,
447     size_t total_num_event_files,
448     NetLogCaptureMode capture_mode,
449     std::unique_ptr<base::Value::Dict> constants) {
450   DCHECK_GT(total_num_event_files, 0u);
451 
452   scoped_refptr<base::SequencedTaskRunner> file_task_runner =
453       CreateFileTaskRunner();
454 
455   const uint64_t max_event_file_size =
456       max_total_size == kNoLimit ? kNoLimit
457                                  : max_total_size / total_num_event_files;
458 
459   // The FileWriter uses a soft limit to write events to file that allows
460   // the size of the file to exceed the limit, but the WriteQueue uses a hard
461   // limit which the size of |WriteQueue::queue_| cannot exceed. Thus, the
462   // FileWriter may write more events to file than can be contained by
463   // the WriteQueue if they have the same size limit. The maximum size of the
464   // WriteQueue is doubled to allow |WriteQueue::queue_| to hold enough events
465   // for the FileWriter to fill all files. As long as all events have
466   // sizes <= the size of an individual event file, the discrepancy between the
467   // hard limit and the soft limit will not cause an issue.
468   // TODO(dconnol): Handle the case when the WriteQueue  still doesn't
469   // contain enough events to fill all files, because of very large events
470   // relative to file size.
471   auto file_writer = std::make_unique<FileWriter>(
472       log_path, inprogress_dir_path, std::move(pre_existing_log_file),
473       max_event_file_size, total_num_event_files, file_task_runner);
474 
475   uint64_t write_queue_memory_max =
476       base::MakeClampedNum<uint64_t>(max_total_size) * 2;
477 
478   return base::WrapUnique(new FileNetLogObserver(
479       file_task_runner, std::move(file_writer),
480       base::MakeRefCounted<WriteQueue>(write_queue_memory_max), capture_mode,
481       std::move(constants)));
482 }
483 
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::Dict> constants)484 FileNetLogObserver::FileNetLogObserver(
485     scoped_refptr<base::SequencedTaskRunner> file_task_runner,
486     std::unique_ptr<FileWriter> file_writer,
487     scoped_refptr<WriteQueue> write_queue,
488     NetLogCaptureMode capture_mode,
489     std::unique_ptr<base::Value::Dict> constants)
490     : file_task_runner_(std::move(file_task_runner)),
491       write_queue_(std::move(write_queue)),
492       file_writer_(std::move(file_writer)),
493       capture_mode_(capture_mode) {
494   if (!constants)
495     constants = std::make_unique<base::Value::Dict>(GetNetConstants());
496 
497   DCHECK(!constants->Find("logCaptureMode"));
498   constants->Set("logCaptureMode", CaptureModeToString(capture_mode));
499   file_task_runner_->PostTask(
500       FROM_HERE, base::BindOnce(&FileNetLogObserver::FileWriter::Initialize,
501                                 base::Unretained(file_writer_.get()),
502                                 std::move(constants)));
503 }
504 
CaptureModeToString(NetLogCaptureMode mode)505 std::string FileNetLogObserver::CaptureModeToString(NetLogCaptureMode mode) {
506   switch (mode) {
507     case NetLogCaptureMode::kDefault:
508       return "Default";
509     case NetLogCaptureMode::kIncludeSensitive:
510       return "IncludeSensitive";
511     case NetLogCaptureMode::kEverything:
512       return "Everything";
513   }
514   NOTREACHED();
515   return "UNKNOWN";
516 }
517 
WriteQueue(uint64_t memory_max)518 FileNetLogObserver::WriteQueue::WriteQueue(uint64_t memory_max)
519     : memory_max_(memory_max) {}
520 
AddEntryToQueue(std::unique_ptr<std::string> event)521 size_t FileNetLogObserver::WriteQueue::AddEntryToQueue(
522     std::unique_ptr<std::string> event) {
523   base::AutoLock lock(lock_);
524 
525   memory_ += event->size();
526   queue_.push(std::move(event));
527 
528   while (memory_ > memory_max_ && !queue_.empty()) {
529     // Delete oldest events in the queue.
530     DCHECK(queue_.front());
531     memory_ -= queue_.front()->size();
532     queue_.pop();
533   }
534 
535   return queue_.size();
536 }
537 
SwapQueue(EventQueue * local_queue)538 void FileNetLogObserver::WriteQueue::SwapQueue(EventQueue* local_queue) {
539   DCHECK(local_queue->empty());
540   base::AutoLock lock(lock_);
541   queue_.swap(*local_queue);
542   memory_ = 0;
543 }
544 
545 FileNetLogObserver::WriteQueue::~WriteQueue() = default;
546 
FileWriter(const base::FilePath & log_path,const base::FilePath & inprogress_dir_path,absl::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)547 FileNetLogObserver::FileWriter::FileWriter(
548     const base::FilePath& log_path,
549     const base::FilePath& inprogress_dir_path,
550     absl::optional<base::File> pre_existing_log_file,
551     uint64_t max_event_file_size,
552     size_t total_num_event_files,
553     scoped_refptr<base::SequencedTaskRunner> task_runner)
554     : final_log_path_(log_path),
555       inprogress_dir_path_(inprogress_dir_path),
556       total_num_event_files_(total_num_event_files),
557       max_event_file_size_(max_event_file_size),
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::Dict> constants_value)570 void FileNetLogObserver::FileWriter::Initialize(
571     std::unique_ptr<base::Value::Dict> 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 = &current_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::Dict> constants_value,base::File * file)712 void FileNetLogObserver::FileWriter::WriteConstantsToFile(
713     std::unique_ptr<base::Value::Dict> 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   auto read_buffer = std::make_unique<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/+/main/net/tools/"
829       "stitch_net_log_files.py\n");
830 }
831 
SerializeNetLogValueToJson(const base::ValueView & value)832 std::string SerializeNetLogValueToJson(const base::ValueView& 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