browser/net/passive_log_collector.cc

// Copyright (c) 2010 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 "chrome/browser/net/passive_log_collector.h"

#include <algorithm>

#include "base/compiler_specific.h"
#include "base/string_util.h"
#include "base/format_macros.h"
#include "chrome/browser/chrome_thread.h"
#include "net/url_request/url_request_netlog_params.h"

namespace {

// TODO(eroman): Do something with the truncation count.

const size_t kMaxNumEntriesPerLog = 30;

void AddEntryToSourceInfo(const PassiveLogCollector::Entry& entry,
                          PassiveLogCollector::SourceInfo* out_info) {
  // Start dropping new entries when the log has gotten too big.
  if (out_info->entries.size() + 1 <= kMaxNumEntriesPerLog) {
    out_info->entries.push_back(entry);
  } else {
    out_info->num_entries_truncated += 1;
    out_info->entries[kMaxNumEntriesPerLog - 1] = entry;
  }
}

// Comparator to sort entries by their |order| property, ascending.
bool SortByOrderComparator(const PassiveLogCollector::Entry& a,
                           const PassiveLogCollector::Entry& b) {
  return a.order < b.order;
}

}  // namespace

//----------------------------------------------------------------------------
// PassiveLogCollector
//----------------------------------------------------------------------------

PassiveLogCollector::PassiveLogCollector()
    : Observer(net::NetLog::LOG_BASIC),
      ALLOW_THIS_IN_INITIALIZER_LIST(connect_job_tracker_(this)),
      ALLOW_THIS_IN_INITIALIZER_LIST(url_request_tracker_(this)),
      ALLOW_THIS_IN_INITIALIZER_LIST(socket_stream_tracker_(this)),
      num_events_seen_(0) {

  // Define the mapping between source types and the tracker objects.
  memset(&trackers_[0], 0, sizeof(trackers_));
  trackers_[net::NetLog::SOURCE_NONE] = &global_source_tracker_;
  trackers_[net::NetLog::SOURCE_URL_REQUEST] = &url_request_tracker_;
  trackers_[net::NetLog::SOURCE_SOCKET_STREAM] = &socket_stream_tracker_;
  trackers_[net::NetLog::SOURCE_CONNECT_JOB] = &connect_job_tracker_;
  trackers_[net::NetLog::SOURCE_SOCKET] = &socket_tracker_;
  trackers_[net::NetLog::SOURCE_INIT_PROXY_RESOLVER] =
      &init_proxy_resolver_tracker_;
  trackers_[net::NetLog::SOURCE_SPDY_SESSION] = &spdy_session_tracker_;
  trackers_[net::NetLog::SOURCE_HOST_RESOLVER_IMPL_REQUEST] =
      &dns_request_tracker_;
  trackers_[net::NetLog::SOURCE_HOST_RESOLVER_IMPL_JOB] = &dns_job_tracker_;
  // Make sure our mapping is up-to-date.
  for (size_t i = 0; i < arraysize(trackers_); ++i)
    DCHECK(trackers_[i]) << "Unhandled SourceType: " << i;
}

PassiveLogCollector::~PassiveLogCollector() {
}

void PassiveLogCollector::OnAddEntry(
    net::NetLog::EventType type,
    const base::TimeTicks& time,
    const net::NetLog::Source& source,
    net::NetLog::EventPhase phase,
    net::NetLog::EventParameters* params) {
  // Package the parameters into a single struct for convenience.
  Entry entry(num_events_seen_++, type, time, source, phase, params);

  SourceTrackerInterface* tracker = GetTrackerForSourceType(entry.source.type);
  if (tracker)
    tracker->OnAddEntry(entry);
}

PassiveLogCollector::SourceTrackerInterface*
PassiveLogCollector::GetTrackerForSourceType(
    net::NetLog::SourceType source_type) {
  DCHECK_LE(source_type, static_cast<int>(arraysize(trackers_)));
  DCHECK_GE(source_type, 0);
  return trackers_[source_type];
}

void PassiveLogCollector::Clear() {
  for (size_t i = 0; i < arraysize(trackers_); ++i)
    trackers_[i]->Clear();
}

void PassiveLogCollector::GetAllCapturedEvents(EntryList* out) const {
  out->clear();

  // Append all of the captured entries held by the various trackers to
  // |out|.
  for (size_t i = 0; i < arraysize(trackers_); ++i)
    trackers_[i]->AppendAllEntries(out);

  // Now sort the list of entries by their insertion time (ascending).
  std::sort(out->begin(), out->end(), &SortByOrderComparator);
}

std::string PassiveLogCollector::SourceInfo::GetURL() const {
  // Note: we look at the first *two* entries, since the outer REQUEST_ALIVE
  // doesn't actually contain any data.
  for (size_t i = 0; i < 2 && i < entries.size(); ++i) {
    const PassiveLogCollector::Entry& entry = entries[i];
    if (entry.phase == net::NetLog::PHASE_BEGIN && entry.params) {
      switch (entry.type) {
        case net::NetLog::TYPE_URL_REQUEST_START_JOB:
          return static_cast<URLRequestStartEventParameters*>(
              entry.params.get())->url().possibly_invalid_spec();
        case net::NetLog::TYPE_SOCKET_STREAM_CONNECT:
          return static_cast<net::NetLogStringParameter*>(
              entry.params.get())->value();
        default:
          break;
      }
    }
  }
  return std::string();
}

//----------------------------------------------------------------------------
// GlobalSourceTracker
//----------------------------------------------------------------------------

PassiveLogCollector::GlobalSourceTracker::GlobalSourceTracker() {}
PassiveLogCollector::GlobalSourceTracker::~GlobalSourceTracker() {}

void PassiveLogCollector::GlobalSourceTracker::OnAddEntry(const Entry& entry) {
  const size_t kMaxEntries = 30u;
  entries_.push_back(entry);
  if (entries_.size() > kMaxEntries)
    entries_.pop_front();
}

void PassiveLogCollector::GlobalSourceTracker::Clear() {
  entries_.clear();
}

void PassiveLogCollector::GlobalSourceTracker::AppendAllEntries(
    EntryList* out) const {
  out->insert(out->end(), entries_.begin(), entries_.end());
}

//----------------------------------------------------------------------------
// SourceTracker
//----------------------------------------------------------------------------

PassiveLogCollector::SourceTracker::SourceTracker(
    size_t max_num_sources,
    size_t max_graveyard_size,
    PassiveLogCollector* parent)
    : max_num_sources_(max_num_sources),
      max_graveyard_size_(max_graveyard_size),
      parent_(parent) {
}

PassiveLogCollector::SourceTracker::~SourceTracker() {}

void PassiveLogCollector::SourceTracker::OnAddEntry(const Entry& entry) {
  // Lookup or insert a new entry into the bounded map.
  SourceIDToInfoMap::iterator it = sources_.find(entry.source.id);
  if (it == sources_.end()) {
    if (sources_.size() >= max_num_sources_) {
      LOG(WARNING) << "The passive log data has grown larger "
                      "than expected, resetting";
      Clear();
    }
    it = sources_.insert(
        SourceIDToInfoMap::value_type(entry.source.id, SourceInfo())).first;
    it->second.source_id = entry.source.id;
  }

  SourceInfo& info = it->second;
  Action result = DoAddEntry(entry, &info);

  if (result != ACTION_NONE) {
    // We are either queuing it for deletion, or deleting it immediately.
    // If someone else holds a reference to this source, defer the deletion
    // until all the references are released.
    info.is_alive = false;
    if (info.reference_count == 0) {
      switch (result) {
        case ACTION_MOVE_TO_GRAVEYARD:
          AddToDeletionQueue(info.source_id);
          break;
        case ACTION_DELETE:
          DeleteSourceInfo(info.source_id);
          break;
        default:
          NOTREACHED();
          break;
      }
    }
  }
}

void PassiveLogCollector::SourceTracker::DeleteSourceInfo(
    uint32 source_id) {
  SourceIDToInfoMap::iterator it = sources_.find(source_id);
  if (it == sources_.end()) {
    // TODO(eroman): Is this happening? And if so, why. Remove this
    //               once the cause is understood.
    LOG(WARNING) << "Tried to delete info for nonexistent source";
    return;
  }
  // The source should not be in the deletion queue.
  DCHECK(std::find(deletion_queue_.begin(), deletion_queue_.end(),
                   source_id) == deletion_queue_.end());
  ReleaseAllReferencesToDependencies(&(it->second));
  sources_.erase(it);
}

void PassiveLogCollector::SourceTracker::Clear() {
  deletion_queue_.clear();

  // Release all references held to dependent sources.
  for (SourceIDToInfoMap::iterator it = sources_.begin();
       it != sources_.end();
       ++it) {
    ReleaseAllReferencesToDependencies(&(it->second));
  }
  sources_.clear();
}

void PassiveLogCollector::SourceTracker::AppendAllEntries(
    EntryList* out) const {
  // Append all of the entries for each of the sources.
  for (SourceIDToInfoMap::const_iterator it = sources_.begin();
       it != sources_.end();
       ++it) {
    const SourceInfo& info = it->second;
    out->insert(out->end(), info.entries.begin(), info.entries.end());
  }
}

void PassiveLogCollector::SourceTracker::AddToDeletionQueue(
    uint32 source_id) {
  DCHECK(sources_.find(source_id) != sources_.end());
  DCHECK(!sources_.find(source_id)->second.is_alive);
  DCHECK_GE(sources_.find(source_id)->second.reference_count, 0);
  DCHECK_LE(deletion_queue_.size(), max_graveyard_size_);

  DCHECK(std::find(deletion_queue_.begin(), deletion_queue_.end(),
                   source_id) == deletion_queue_.end());
  deletion_queue_.push_back(source_id);

  // After the deletion queue has reached its maximum size, start
  // deleting sources in FIFO order.
  if (deletion_queue_.size() > max_graveyard_size_) {
    uint32 oldest = deletion_queue_.front();
    deletion_queue_.pop_front();
    DeleteSourceInfo(oldest);
  }
}

void PassiveLogCollector::SourceTracker::AdjustReferenceCountForSource(
    int offset, uint32 source_id) {
  DCHECK(offset == -1 || offset == 1) << "invalid offset: " << offset;

  // In general it is invalid to call AdjustReferenceCountForSource() on
  // source that doesn't exist. However, it is possible that if
  // SourceTracker::Clear() was previously called this can happen.
  SourceIDToInfoMap::iterator it = sources_.find(source_id);
  if (it == sources_.end()) {
    LOG(WARNING) << "Released a reference to nonexistent source.";
    return;
  }

  SourceInfo& info = it->second;
  DCHECK_GE(info.reference_count, 0);
  info.reference_count += offset;

  if (info.reference_count < 0) {
    // In general this shouldn't happen, however it is possible to reach this
    // state if SourceTracker::Clear() was called earlier.
    LOG(WARNING) << "Released unmatched reference count.";
    info.reference_count = 0;
  }

  if (!info.is_alive) {
    if (info.reference_count == 1 && offset == 1) {
      // If we just added a reference to a dead source that had no references,
      // it must have been in the deletion queue, so remove it from the queue.
      DeletionQueue::iterator it =
          std::remove(deletion_queue_.begin(), deletion_queue_.end(),
                      source_id);
      DCHECK(it != deletion_queue_.end());
      deletion_queue_.erase(it);
    } else if (info.reference_count == 0) {
      // If we just released the final reference to a dead source, go ahead
      // and delete it right away.
      DeleteSourceInfo(source_id);
    }
  }
}

void PassiveLogCollector::SourceTracker::AddReferenceToSourceDependency(
    const net::NetLog::Source& source, SourceInfo* info) {
  // Find the tracker which should be holding |source|.
  DCHECK(parent_);
  DCHECK_NE(source.type, net::NetLog::SOURCE_NONE);
  SourceTracker* tracker = static_cast<SourceTracker*>(
      parent_->GetTrackerForSourceType(source.type));
  DCHECK(tracker);

  // Tell the owning tracker to increment the reference count of |source|.
  tracker->AdjustReferenceCountForSource(1, source.id);

  // Make a note to release this reference once |info| is destroyed.
  info->dependencies.push_back(source);
}

void
PassiveLogCollector::SourceTracker::ReleaseAllReferencesToDependencies(
    SourceInfo* info) {
  // Release all references |info| was holding to other sources.
  for (SourceDependencyList::const_iterator it = info->dependencies.begin();
       it != info->dependencies.end(); ++it) {
    const net::NetLog::Source& source = *it;

    // Find the tracker which should be holding |source|.
    DCHECK(parent_);
    DCHECK_NE(source.type, net::NetLog::SOURCE_NONE);
    SourceTracker* tracker = static_cast<SourceTracker*>(
        parent_->GetTrackerForSourceType(source.type));
    DCHECK(tracker);

    // Tell the owning tracker to decrement the reference count of |source|.
    tracker->AdjustReferenceCountForSource(-1, source.id);
  }

  info->dependencies.clear();
}

//----------------------------------------------------------------------------
// ConnectJobTracker
//----------------------------------------------------------------------------

const size_t PassiveLogCollector::ConnectJobTracker::kMaxNumSources = 100;
const size_t PassiveLogCollector::ConnectJobTracker::kMaxGraveyardSize = 15;

PassiveLogCollector::ConnectJobTracker::ConnectJobTracker(
    PassiveLogCollector* parent)
    : SourceTracker(kMaxNumSources, kMaxGraveyardSize, parent) {
}

PassiveLogCollector::SourceTracker::Action
PassiveLogCollector::ConnectJobTracker::DoAddEntry(const Entry& entry,
                                                   SourceInfo* out_info) {
  AddEntryToSourceInfo(entry, out_info);

  if (entry.type == net::NetLog::TYPE_CONNECT_JOB_SET_SOCKET) {
    const net::NetLog::Source& source_dependency =
        static_cast<net::NetLogSourceParameter*>(entry.params.get())->value();
    AddReferenceToSourceDependency(source_dependency, out_info);
  }

  // If this is the end of the connect job, move the source to the graveyard.
  if (entry.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB &&
      entry.phase == net::NetLog::PHASE_END) {
    return ACTION_MOVE_TO_GRAVEYARD;
  }

  return ACTION_NONE;
}

//----------------------------------------------------------------------------
// SocketTracker
//----------------------------------------------------------------------------

const size_t PassiveLogCollector::SocketTracker::kMaxNumSources = 200;
const size_t PassiveLogCollector::SocketTracker::kMaxGraveyardSize = 15;

PassiveLogCollector::SocketTracker::SocketTracker()
    : SourceTracker(kMaxNumSources, kMaxGraveyardSize, NULL) {
}

PassiveLogCollector::SourceTracker::Action
PassiveLogCollector::SocketTracker::DoAddEntry(const Entry& entry,
                                               SourceInfo* out_info) {
  // TODO(eroman): aggregate the byte counts once truncation starts to happen,
  //               to summarize transaction read/writes for each SOCKET_IN_USE
  //               section.
  if (entry.type == net::NetLog::TYPE_SOCKET_BYTES_SENT ||
      entry.type == net::NetLog::TYPE_SOCKET_BYTES_RECEIVED) {
    return ACTION_NONE;
  }

  AddEntryToSourceInfo(entry, out_info);

  if (entry.type == net::NetLog::TYPE_SOCKET_ALIVE &&
      entry.phase == net::NetLog::PHASE_END) {
    return ACTION_MOVE_TO_GRAVEYARD;
  }

  return ACTION_NONE;
}

//----------------------------------------------------------------------------
// RequestTracker
//----------------------------------------------------------------------------

const size_t PassiveLogCollector::RequestTracker::kMaxNumSources = 100;
const size_t PassiveLogCollector::RequestTracker::kMaxGraveyardSize = 25;

PassiveLogCollector::RequestTracker::RequestTracker(PassiveLogCollector* parent)
    : SourceTracker(kMaxNumSources, kMaxGraveyardSize, parent) {
}

PassiveLogCollector::SourceTracker::Action
PassiveLogCollector::RequestTracker::DoAddEntry(const Entry& entry,
                                                SourceInfo* out_info) {
  if (entry.type == net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB ||
      entry.type == net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET) {
    const net::NetLog::Source& source_dependency =
        static_cast<net::NetLogSourceParameter*>(entry.params.get())->value();
    AddReferenceToSourceDependency(source_dependency, out_info);
  }

  AddEntryToSourceInfo(entry, out_info);

  // If the request has ended, move it to the graveyard.
  if (entry.type == net::NetLog::TYPE_REQUEST_ALIVE &&
      entry.phase == net::NetLog::PHASE_END) {
    if (StartsWithASCII(out_info->GetURL(), "chrome://", false)) {
      // Avoid sending "chrome://" requests to the graveyard, since it just
      // adds to clutter.
      return ACTION_DELETE;
    }
    return ACTION_MOVE_TO_GRAVEYARD;
  }

  return ACTION_NONE;
}

//----------------------------------------------------------------------------
// InitProxyResolverTracker
//----------------------------------------------------------------------------

const size_t PassiveLogCollector::InitProxyResolverTracker::kMaxNumSources = 20;
const size_t PassiveLogCollector::InitProxyResolverTracker::kMaxGraveyardSize =
    3;

PassiveLogCollector::InitProxyResolverTracker::InitProxyResolverTracker()
    : SourceTracker(kMaxNumSources, kMaxGraveyardSize, NULL) {
}

PassiveLogCollector::SourceTracker::Action
PassiveLogCollector::InitProxyResolverTracker::DoAddEntry(
    const Entry& entry, SourceInfo* out_info) {
  AddEntryToSourceInfo(entry, out_info);
  if (entry.type == net::NetLog::TYPE_INIT_PROXY_RESOLVER &&
      entry.phase == net::NetLog::PHASE_END) {
    return ACTION_MOVE_TO_GRAVEYARD;
  } else {
    return ACTION_NONE;
  }
}

//----------------------------------------------------------------------------
// SpdySessionTracker
//----------------------------------------------------------------------------

const size_t PassiveLogCollector::SpdySessionTracker::kMaxNumSources = 50;
const size_t PassiveLogCollector::SpdySessionTracker::kMaxGraveyardSize = 10;

PassiveLogCollector::SpdySessionTracker::SpdySessionTracker()
    : SourceTracker(kMaxNumSources, kMaxGraveyardSize, NULL) {
}

PassiveLogCollector::SourceTracker::Action
PassiveLogCollector::SpdySessionTracker::DoAddEntry(const Entry& entry,
                                                    SourceInfo* out_info) {
  AddEntryToSourceInfo(entry, out_info);
  if (entry.type == net::NetLog::TYPE_SPDY_SESSION &&
      entry.phase == net::NetLog::PHASE_END) {
    return ACTION_MOVE_TO_GRAVEYARD;
  } else {
    return ACTION_NONE;
  }
}

//----------------------------------------------------------------------------
// DNSRequestTracker
//----------------------------------------------------------------------------

const size_t PassiveLogCollector::DNSRequestTracker::kMaxNumSources = 200;
const size_t PassiveLogCollector::DNSRequestTracker::kMaxGraveyardSize = 20;

PassiveLogCollector::DNSRequestTracker::DNSRequestTracker()
    : SourceTracker(kMaxNumSources, kMaxGraveyardSize, NULL) {
}

PassiveLogCollector::SourceTracker::Action
PassiveLogCollector::DNSRequestTracker::DoAddEntry(const Entry& entry,
                                                   SourceInfo* out_info) {
  AddEntryToSourceInfo(entry, out_info);
  if (entry.type == net::NetLog::TYPE_HOST_RESOLVER_IMPL_REQUEST &&
      entry.phase == net::NetLog::PHASE_END) {
    return ACTION_MOVE_TO_GRAVEYARD;
  } else {
    return ACTION_NONE;
  }
}

//----------------------------------------------------------------------------
// DNSJobTracker
//----------------------------------------------------------------------------

const size_t PassiveLogCollector::DNSJobTracker::kMaxNumSources = 100;
const size_t PassiveLogCollector::DNSJobTracker::kMaxGraveyardSize = 15;

PassiveLogCollector::DNSJobTracker::DNSJobTracker()
    : SourceTracker(kMaxNumSources, kMaxGraveyardSize, NULL) {
}

PassiveLogCollector::SourceTracker::Action
PassiveLogCollector::DNSJobTracker::DoAddEntry(const Entry& entry,
                                               SourceInfo* out_info) {
  AddEntryToSourceInfo(entry, out_info);
  if (entry.type == net::NetLog::TYPE_HOST_RESOLVER_IMPL_JOB &&
      entry.phase == net::NetLog::PHASE_END) {
    return ACTION_MOVE_TO_GRAVEYARD;
  } else {
    return ACTION_NONE;
  }
}