// 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 #include "base/compiler_specific.h" #include "base/string_util.h" #include "base/format_macros.h" #include "chrome/browser/browser_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::Entry::Entry(uint32 order, net::NetLog::EventType type, const base::TimeTicks& time, net::NetLog::Source source, net::NetLog::EventPhase phase, net::NetLog::EventParameters* params) : order(order), type(type), time(time), source(source), phase(phase), params(params) { } PassiveLogCollector::Entry::~Entry() {} PassiveLogCollector::SourceInfo::SourceInfo() : source_id(net::NetLog::Source::kInvalidId), num_entries_truncated(0), reference_count(0), is_alive(true) { } PassiveLogCollector::SourceInfo::~SourceInfo() {} //---------------------------------------------------------------------------- // 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(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( entry.params.get())->url().possibly_invalid_spec(); case net::NetLog::TYPE_SOCKET_STREAM_CONNECT: return static_cast( 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( 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( 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(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(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; } }