file_net_log_observer.cc

// Copyright 2016 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "net/log/file_net_log_observer.h"

#include <limits>
#include <memory>
#include <queue>
#include <set>
#include <string>
#include <utility>
#include <vector>

#include "base/bind.h"
#include "base/files/file_util.h"
#include "base/json/json_writer.h"
#include "base/logging.h"
#include "base/strings/string_number_conversions.h"
#include "base/synchronization/lock.h"
#include "base/threading/thread.h"
#include "base/values.h"
#include "net/log/net_log_capture_mode.h"
#include "net/log/net_log_entry.h"
#include "net/log/net_log_util.h"
#include "net/url_request/url_request_context.h"

namespace {

// Number of events that can build up in |write_queue_| before file thread
// is triggered to drain the queue.
const int kNumWriteQueueEvents = 15;

}  // namespace

namespace net {

// Used to store events to be written to file.
using EventQueue = std::queue<std::unique_ptr<std::string>>;

// WriteQueue receives events from FileNetLogObserver on the main thread and
// holds them in a queue until they are drained from the queue and written to
// file on the file thread.
//
// WriteQueue contains the resources shared between the main thread and the
// file thread. |lock_| must be acquired to read or write to |queue_| and
// |memory_|.
//
// WriteQueue is refcounted and should be destroyed once all events on the
// file thread have finished executing.
class FileNetLogObserver::WriteQueue
    : public base::RefCountedThreadSafe<WriteQueue> {
 public:
  // |memory_max| indicates the maximum amount of memory that the virtual write
  // queue can use. If |memory_| exceeds |memory_max_|, the |queue_| of events
  // is overwritten.
  explicit WriteQueue(size_t memory_max);

  // Adds |event| to |queue_|. Also manages the size of |memory_|; if it
  // exceeds |memory_max_|, then old events are dropped from |queue_| without
  // being written to file.
  //
  // Returns the number of events in the |queue_|.
  size_t AddEntryToQueue(std::unique_ptr<std::string> event);

  // Swaps |queue_| with |local_queue|. |local_queue| should be empty, so that
  // |queue_| is emptied. Resets |memory_| to 0.
  void SwapQueue(EventQueue* local_queue);

 private:
  friend class base::RefCountedThreadSafe<WriteQueue>;

  ~WriteQueue();

  // Queue of events to be written shared between main thread and file thread.
  // Main thread adds events to the queue and the file thread drains them and
  // writes the events to file.
  //
  // |lock_| must be acquired to read or write to this.
  EventQueue queue_;

  // Tracks how much memory is being used by the virtual write queue.
  // Incremented in AddEntryToQueue() when events are added to the
  // buffer, and decremented when SwapQueue() is called and the file thread's
  // local queue is swapped with the shared write queue.
  //
  // |lock_| must be acquired to read or write to this.
  size_t memory_;

  // Indicates the maximum amount of memory that the |queue_| is allowed to
  // use.
  const size_t memory_max_;

  // Protects access to |queue_| and |memory_|.
  //
  // A lock is necessary because |queue_| and |memory_| are shared between the
  // file thread and the main thread. NetLog's lock protects OnAddEntry(),
  // which calls AddEntryToQueue(), but it does not protect access to the
  // observer's member variables. Thus, a race condition exists if a thread is
  // calling OnAddEntry() at the same time that the file thread is accessing
  // |memory_| and |queue_| to write events to file. The |queue_| and |memory_|
  // counter are necessary to bound the amount of memory that is used for the
  // queue in the event that the file thread lags significantly behind the main
  // thread in writing events to file.
  base::Lock lock_;

  DISALLOW_COPY_AND_ASSIGN(WriteQueue);
};

// FileWriter is an interface describing an object that drains events from a
// WriteQueue and writes them to disk.
class FileNetLogObserver::FileWriter {
 public:
  virtual ~FileWriter();

  // Writes |constants_value| to disk and opens the events array (closed in
  // Stop()).
  virtual void Initialize(std::unique_ptr<base::Value> constants_value) = 0;

  // Closes the events array opened in Initialize() and writes |tab_info| to
  // disk. If |tab_info| cannot be converted to proper JSON, then it
  // is ignored.
  virtual void Stop(std::unique_ptr<base::Value> tab_info) = 0;

  // Drains |queue_| from WriteQueue into a local file queue and writes the
  // events in the queue to disk.
  virtual void Flush(scoped_refptr<WriteQueue> write_queue) = 0;

  // Deletes all netlog files. It is not valid to call any method of
  // FileNetLogObserver after DeleteAllFiles().
  virtual void DeleteAllFiles() = 0;
};

// This implementation of FileWriter is used when the observer is in bounded
// mode.
// BoundedFileWriter can be constructed on any thread, and afterwards is only
// accessed on the file thread.
class FileNetLogObserver::BoundedFileWriter
    : public FileNetLogObserver::FileWriter {
 public:
  BoundedFileWriter(const base::FilePath& directory,
                    size_t max_file_size,
                    size_t total_num_files,
                    scoped_refptr<base::SingleThreadTaskRunner> task_runner);

  ~BoundedFileWriter() override;

  // FileNetLogObserver::FileWriter implementation
  void Initialize(std::unique_ptr<base::Value> constants_value) override;
  void Stop(std::unique_ptr<base::Value> tab_info) override;
  void Flush(scoped_refptr<WriteQueue> write_queue) override;
  void DeleteAllFiles() override;

 private:
  // Increments |current_file_idx_|, and handles the clearing and openining of
  // the new current file. Also sets |event_files_[current_file_idx_]| to point
  // to the new current file.
  void IncrementCurrentFile();

  // Each ScopedFILE points to a netlog event file with the file name
  // "event_file_<index>.json".
  std::vector<base::ScopedFILE> event_files_;

  // The directory where the netlog files are created.
  const base::FilePath directory_;

  // Indicates the total number of netlog event files, which does not include
  // the constants file (constants.json), or closing file (end_netlog.json).
  const size_t total_num_files_;

  // Indicates the index of the file in |event_files_| currently being written
  // into.
  size_t current_file_idx_;

  // Indicates the maximum size of each individual netlogging file, excluding
  // the constant file.
  const size_t max_file_size_;

  // Task runner from the file thread.
  const scoped_refptr<base::SingleThreadTaskRunner> task_runner_;

  DISALLOW_COPY_AND_ASSIGN(BoundedFileWriter);
};

// This implementation of FileWriter is used when the observer is in unbounded
// mode.
// UnboundedFileWriter can be constructed on any thread, and afterwards is only
// accessed on the file thread.
class FileNetLogObserver::UnboundedFileWriter
    : public FileNetLogObserver::FileWriter {
 public:
  UnboundedFileWriter(const base::FilePath& path,
                      scoped_refptr<base::SingleThreadTaskRunner> task_runner);

  ~UnboundedFileWriter() override;

  // FileNetLogObserver::FileWriter implementation
  void Initialize(std::unique_ptr<base::Value> constants_value) override;
  void Stop(std::unique_ptr<base::Value> tab_info) override;
  void Flush(scoped_refptr<WriteQueue> write_queue) override;
  void DeleteAllFiles() override;

 private:
  base::FilePath file_path_;
  base::ScopedFILE file_;

  // Is set to true after the first event is written to the log file.
  bool first_event_written_;

  // Task runner from the file thread.
  const scoped_refptr<base::SingleThreadTaskRunner> task_runner_;

  DISALLOW_COPY_AND_ASSIGN(UnboundedFileWriter);
};

FileNetLogObserver::FileNetLogObserver(
    scoped_refptr<base::SingleThreadTaskRunner> file_task_runner)
    : file_task_runner_(file_task_runner) {}

FileNetLogObserver::~FileNetLogObserver() {
  if (net_log()) {
    // StopObserving was not called.
    file_task_runner_->PostTask(
        FROM_HERE, base::Bind(&FileNetLogObserver::FileWriter::DeleteAllFiles,
                              base::Unretained(file_writer_)));
    net_log()->DeprecatedRemoveObserver(this);
  }

  file_task_runner_->DeleteSoon(FROM_HERE, file_writer_);
}

void FileNetLogObserver::StartObservingBounded(
    NetLog* net_log,
    NetLogCaptureMode capture_mode,
    const base::FilePath& directory,
    std::unique_ptr<base::Value> constants,
    URLRequestContext* url_request_context,
    size_t max_total_size,
    size_t total_num_files) {
  DCHECK_GT(total_num_files, 0u);

  file_writer_ =
      new BoundedFileWriter(directory, max_total_size / total_num_files,
                            total_num_files, file_task_runner_);

  // The |file_writer_| uses a soft limit to write events to file that allows
  // the size of the file to exceed the limit, but the |write_queue_| uses a
  // hard limit which the size of the |queue_| cannot exceed. Thus, the
  // |file_writer_| may write more events to file than can be contained by the
  // |write_queue_| if they have the same size limit. The maximum size of the
  // |write_queue_| is doubled to allow the |queue_| to hold enough events for
  // the |file_writer_| to fill all files. As long as all events have sizes <=
  // the size of an individual event file, the discrepancy between the hard
  // limit and the soft limit will not cause an issue.
  // TODO(dconnol): Handle the case when the |write_queue_| still doesn't
  // contain enough events to fill all files, because of very large events
  // relative to file size.
  write_queue_ = new WriteQueue(max_total_size * 2);

  StartObservingHelper(net_log, capture_mode, std::move(constants),
                       url_request_context);
}

void FileNetLogObserver::StartObservingUnbounded(
    NetLog* net_log,
    NetLogCaptureMode capture_mode,
    const base::FilePath& filepath,
    std::unique_ptr<base::Value> constants,
    URLRequestContext* url_request_context) {
  file_writer_ = new UnboundedFileWriter(filepath, file_task_runner_);

  write_queue_ = new WriteQueue(std::numeric_limits<size_t>::max());

  StartObservingHelper(net_log, capture_mode, std::move(constants),
                       url_request_context);
}

void FileNetLogObserver::StartObservingHelper(
    NetLog* net_log,
    NetLogCaptureMode capture_mode,
    std::unique_ptr<base::Value> constants,
    URLRequestContext* url_request_context) {
  if (!constants)
    constants = GetNetConstants();
  file_task_runner_->PostTask(
      FROM_HERE,
      base::Bind(&FileNetLogObserver::FileWriter::Initialize,
                 base::Unretained(file_writer_), base::Passed(&constants)));

  if (url_request_context) {
    DCHECK(url_request_context->CalledOnValidThread());
    std::set<URLRequestContext*> contexts;
    contexts.insert(url_request_context);
    CreateNetLogEntriesForActiveObjects(contexts, this);
  }

  net_log->DeprecatedAddObserver(this, capture_mode);
}

void FileNetLogObserver::StopObserving(URLRequestContext* url_request_context,
                                       const base::Closure& callback) {
  file_task_runner_->PostTask(
      FROM_HERE, base::Bind(&FileNetLogObserver::FileWriter::Flush,
                            base::Unretained(file_writer_), write_queue_));

  file_task_runner_->PostTaskAndReply(
      FROM_HERE,
      base::Bind(
          &FileNetLogObserver::FileWriter::Stop, base::Unretained(file_writer_),
          base::Passed(url_request_context ? GetNetInfo(url_request_context,
                                                        NET_INFO_ALL_SOURCES)
                                           : nullptr)),
      callback);

  net_log()->DeprecatedRemoveObserver(this);
}

void FileNetLogObserver::OnAddEntry(const NetLogEntry& entry) {
  std::unique_ptr<std::string> json(new std::string);

  // If |entry| cannot be converted to proper JSON, ignore it.
  if (!base::JSONWriter::Write(*entry.ToValue(), json.get()))
    return;

  size_t queue_size = write_queue_->AddEntryToQueue(std::move(json));

  // If events build up in |write_queue_|, trigger the file thread to drain
  // the queue. Because only 1 item is added to the queue at a time, if
  // queue_size > kNumWriteQueueEvents a task has already been posted, or will
  // be posted.
  if (queue_size == kNumWriteQueueEvents) {
    file_task_runner_->PostTask(
        FROM_HERE, base::Bind(&FileNetLogObserver::FileWriter::Flush,
                              base::Unretained(file_writer_), write_queue_));
  }
}

FileNetLogObserver::WriteQueue::WriteQueue(size_t memory_max)
    : memory_(0), memory_max_(memory_max) {}

size_t FileNetLogObserver::WriteQueue::AddEntryToQueue(
    std::unique_ptr<std::string> event) {
  base::AutoLock lock(lock_);

  memory_ += event->size();
  queue_.push(std::move(event));

  while (memory_ > memory_max_ && !queue_.empty()) {
    // Delete oldest events in the queue.
    DCHECK(queue_.front());
    memory_ -= queue_.front()->size();
    queue_.pop();
  }

  return queue_.size();
}
void FileNetLogObserver::WriteQueue::SwapQueue(EventQueue* local_queue) {
  DCHECK(local_queue->empty());
  base::AutoLock lock(lock_);
  queue_.swap(*local_queue);
  memory_ = 0;
}

FileNetLogObserver::WriteQueue::~WriteQueue() {}

FileNetLogObserver::FileWriter::~FileWriter() {}

FileNetLogObserver::BoundedFileWriter::BoundedFileWriter(
    const base::FilePath& directory,
    size_t max_file_size,
    size_t total_num_files,
    scoped_refptr<base::SingleThreadTaskRunner> task_runner)
    : directory_(directory),
      total_num_files_(total_num_files),
      current_file_idx_(0),
      max_file_size_(max_file_size),
      task_runner_(task_runner) {
  event_files_.resize(total_num_files_);
}

FileNetLogObserver::BoundedFileWriter::~BoundedFileWriter() {}

void FileNetLogObserver::BoundedFileWriter::Initialize(
    std::unique_ptr<base::Value> constants_value) {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  event_files_[current_file_idx_] = base::ScopedFILE(
      base::OpenFile(directory_.AppendASCII("event_file_0.json"), "w"));

  base::ScopedFILE constants_file(
      base::OpenFile(directory_.AppendASCII("constants.json"), "w"));

  // Print constants to file and open events array.
  std::string json;

  // It should always be possible to convert constants to JSON.
  if (!base::JSONWriter::Write(*constants_value, &json))
    DCHECK(false);
  fprintf(constants_file.get(), "{\"constants\":%s,\n\"events\": [\n",
          json.c_str());
}

void FileNetLogObserver::BoundedFileWriter::Stop(
    std::unique_ptr<base::Value> tab_info) {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  base::ScopedFILE closing_file(
      base::OpenFile(directory_.AppendASCII("end_netlog.json"), "w"));

  std::string json;
  if (tab_info)
    base::JSONWriter::Write(*tab_info, &json);

  fprintf(closing_file.get(), "]%s}\n",
          json.empty() ? "" : (",\"tabInfo\": " + json + "\n").c_str());

  // Flush all fprintfs to disk so that files can be safely accessed on
  // callback.
  event_files_.clear();
}

void FileNetLogObserver::BoundedFileWriter::IncrementCurrentFile() {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  current_file_idx_++;
  current_file_idx_ %= total_num_files_;
  event_files_[current_file_idx_].reset();
  event_files_[current_file_idx_] = base::ScopedFILE(base::OpenFile(
      directory_.AppendASCII("event_file_" +
                             base::SizeTToString(current_file_idx_) + ".json"),
      "w"));
}

void FileNetLogObserver::BoundedFileWriter::Flush(
    scoped_refptr<FileNetLogObserver::WriteQueue> write_queue) {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  EventQueue local_file_queue;
  write_queue->SwapQueue(&local_file_queue);

  std::string to_print;
  size_t file_size = ftell(event_files_[current_file_idx_].get());
  size_t memory_freed = 0;

  while (!local_file_queue.empty()) {
    if (file_size >= max_file_size_) {
      // The current file is full. Start a new current file.
      IncrementCurrentFile();
      file_size = 0;
    }
    fprintf(event_files_[current_file_idx_].get(), "%s,\n",
            local_file_queue.front().get()->c_str());
    file_size += local_file_queue.front()->size();
    memory_freed += local_file_queue.front()->size();
    local_file_queue.pop();
  }
}

void FileNetLogObserver::BoundedFileWriter::DeleteAllFiles() {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  // Reset |event_files_| to release all file handles so base::DeleteFile can
  // safely access files.
  event_files_.clear();

  base::DeleteFile(directory_.AppendASCII("constants.json"), false);
  base::DeleteFile(directory_.AppendASCII("end_netlog.json"), false);
  for (size_t i = 0; i < total_num_files_; i++) {
    base::DeleteFile(directory_.AppendASCII("event_file_" +
                                            base::SizeTToString(i) + ".json"),
                     false);
  }
}

FileNetLogObserver::UnboundedFileWriter::UnboundedFileWriter(
    const base::FilePath& path,
    scoped_refptr<base::SingleThreadTaskRunner> task_runner)
    : file_path_(path), task_runner_(task_runner) {}

FileNetLogObserver::UnboundedFileWriter::~UnboundedFileWriter() {}

void FileNetLogObserver::UnboundedFileWriter::Initialize(
    std::unique_ptr<base::Value> constants_value) {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  file_.reset(base::OpenFile(file_path_, "w"));
  first_event_written_ = false;

  // Print constants to file and open events array.
  std::string json;

  // It should always be possible to convert constants to JSON.
  if (!base::JSONWriter::Write(*constants_value, &json))
    DCHECK(false);
  fprintf(file_.get(), "{\"constants\":%s,\n\"events\": [\n", json.c_str());
}

void FileNetLogObserver::UnboundedFileWriter::Stop(
    std::unique_ptr<base::Value> tab_info) {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  std::string json;
  if (tab_info)
    base::JSONWriter::Write(*tab_info, &json);

  fprintf(file_.get(), "]%s}\n",
          json.empty() ? "" : (",\n\"tabInfo\": " + json + "\n").c_str());

  // Flush all fprintfs to disk so that the file can be safely accessed on
  // callback.
  file_.reset();
}

void FileNetLogObserver::UnboundedFileWriter::Flush(
    scoped_refptr<FileNetLogObserver::WriteQueue> write_queue) {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  EventQueue local_file_queue;
  write_queue->SwapQueue(&local_file_queue);

  while (!local_file_queue.empty()) {
    if (first_event_written_) {
      fputs(",\n", file_.get());
    } else {
      first_event_written_ = true;
    }
    fputs(local_file_queue.front()->c_str(), file_.get());
    local_file_queue.pop();
  }
}

void FileNetLogObserver::UnboundedFileWriter::DeleteAllFiles() {
  DCHECK(task_runner_->RunsTasksOnCurrentThread());

  // Reset |file_| to release the file handle so base::DeleteFile can
  // safely access it.
  file_.reset();
  base::DeleteFile(file_path_, false);
}

}  // namespace net