From 06650c582f9cfcf3869c490f3dc1ca224d6c9963 Mon Sep 17 00:00:00 2001 From: "eroman@chromium.org" Date: Thu, 3 Jun 2010 00:49:17 +0000 Subject: Rework the logging for sockets/connectjobs. In particular, make it work better when using backup jobs / late binding (the display was very confused before because of how these asynchronous events would nest). Also changed the paradigm for how PassiveLogCollector preserves these async associations -- this fixes how it replays the events to net-internals. (Before we would collapse the event streams into the SOURCE_URL_REQUEST which lost some hiearchy.. now I keep the separate streams). Some of the particular changes to the event streams: * ConnectJobs now create their own source stream internally. * Sockets are now bounded by +SOCKET_ALIVE / -SOCKET_ALIVE events (removed the one-off SOCKET_DONE event). * The socket log streams contains +SOCKET_IN_USE / -SOCKET_IN_USE event blocks to show which URLRequest was controlling it at various points in time (this makes it much easier to understand which read/writes belonged to a particular network transaction when a socket gets re-used). * ConnectJobs are bounded by +SOCKET_POOL_CONNECT_JOB / - SOCKET_POOL_CONNECT_JOB events. * ConnectJobs log the net error they failed with. * Removed the SOCKET_BACKUP_TIMER_EXTENDED event. Review URL: http://codereview.chromium.org/2363003 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@48797 0039d316-1c4b-4281-b951-d872f2087c98 --- chrome/browser/dom_ui/net_internals_ui.cc | 3 +- chrome/browser/net/chrome_url_request_context.cc | 3 + chrome/browser/net/connection_tester.cc | 3 +- chrome/browser/net/passive_log_collector.cc | 549 ++++------- chrome/browser/net/passive_log_collector.h | 179 ++-- .../browser/net/passive_log_collector_unittest.cc | 1020 ++++---------------- chrome/service/net/service_url_request_context.cc | 3 +- chrome_frame/test/test_server_test.cc | 3 +- net/base/net_log.cc | 11 + net/base/net_log.h | 21 +- net/base/net_log_event_type_list.h | 58 +- net/base/net_log_source_type_list.h | 16 +- net/http/http_cache.cc | 4 +- net/http/http_cache.h | 3 + net/http/http_network_layer.cc | 15 +- net/http/http_network_layer.h | 8 +- net/http/http_network_layer_unittest.cc | 6 +- net/http/http_network_session.cc | 20 +- net/http/http_network_session.h | 4 +- net/http/http_network_transaction_unittest.cc | 9 +- net/proxy/proxy_script_fetcher_unittest.cc | 2 +- net/socket/client_socket_handle.cc | 10 + net/socket/client_socket_handle.h | 5 + net/socket/client_socket_pool_base.cc | 93 +- net/socket/client_socket_pool_base.h | 23 +- net/socket/client_socket_pool_base_unittest.cc | 85 +- net/socket/socks_client_socket_pool.cc | 18 +- net/socket/socks_client_socket_pool.h | 17 +- net/socket/socks_client_socket_pool_unittest.cc | 4 +- net/socket/ssl_client_socket_unittest.cc | 6 +- net/socket/tcp_client_socket_libevent.cc | 3 +- net/socket/tcp_client_socket_pool.cc | 18 +- net/socket/tcp_client_socket_pool.h | 15 +- net/socket/tcp_client_socket_pool_unittest.cc | 4 +- net/socket/tcp_client_socket_unittest.cc | 7 +- net/socket/tcp_client_socket_win.cc | 3 +- net/spdy/spdy_network_transaction_unittest.cc | 3 +- net/spdy/spdy_session_unittest.cc | 1 + net/spdy/spdy_stream_unittest.cc | 3 +- net/tools/fetch/fetch_client.cc | 4 +- net/url_request/url_request_unittest.h | 3 +- .../tools/test_shell/test_shell_request_context.cc | 2 +- 42 files changed, 821 insertions(+), 1446 deletions(-) diff --git a/chrome/browser/dom_ui/net_internals_ui.cc b/chrome/browser/dom_ui/net_internals_ui.cc index 0ea96a4..44345ff 100644 --- a/chrome/browser/dom_ui/net_internals_ui.cc +++ b/chrome/browser/dom_ui/net_internals_ui.cc @@ -581,8 +581,7 @@ void NetInternalsMessageHandler::IOThreadImpl::OnRendererReady( { DictionaryValue* dict = new DictionaryValue(); - int i = 0; -#define SOURCE_TYPE(label) dict->SetInteger(ASCIIToWide(# label), i++); +#define SOURCE_TYPE(label, value) dict->SetInteger(ASCIIToWide(# label), value); #include "net/base/net_log_source_type_list.h" #undef SOURCE_TYPE diff --git a/chrome/browser/net/chrome_url_request_context.cc b/chrome/browser/net/chrome_url_request_context.cc index e75921e..ed36a1c 100644 --- a/chrome/browser/net/chrome_url_request_context.cc +++ b/chrome/browser/net/chrome_url_request_context.cc @@ -256,6 +256,7 @@ ChromeURLRequestContext* FactoryForOriginal::Create() { context->proxy_service(), context->ssl_config_service(), context->http_auth_handler_factory(), + io_thread()->globals()->net_log.get(), backend); if (command_line.HasSwitch(switches::kDisableByteRangeSupport)) @@ -379,6 +380,7 @@ ChromeURLRequestContext* FactoryForOffTheRecord::Create() { context->proxy_service(), context->ssl_config_service(), context->http_auth_handler_factory(), + io_thread()->globals()->net_log.get(), backend); context->set_cookie_store(new net::CookieMonster(NULL, cookie_monster_delegate_)); @@ -474,6 +476,7 @@ ChromeURLRequestContext* FactoryForMedia::Create() { main_context->proxy_service(), main_context->ssl_config_service(), main_context->http_auth_handler_factory(), + io_thread()->globals()->net_log.get(), backend); } diff --git a/chrome/browser/net/connection_tester.cc b/chrome/browser/net/connection_tester.cc index 430874a..6e72380 100644 --- a/chrome/browser/net/connection_tester.cc +++ b/chrome/browser/net/connection_tester.cc @@ -58,7 +58,8 @@ class ExperimentURLRequestContext : public URLRequestContext { net::HttpNetworkLayer::CreateFactory(NULL, host_resolver_, proxy_service_, ssl_config_service_, - http_auth_handler_factory_), + http_auth_handler_factory_, + NULL), net::HttpCache::DefaultBackend::InMemory(0)); // In-memory cookie store. cookie_store_ = new net::CookieMonster(NULL, NULL); diff --git a/chrome/browser/net/passive_log_collector.cc b/chrome/browser/net/passive_log_collector.cc index c506f25..4c3e4973 100644 --- a/chrome/browser/net/passive_log_collector.cc +++ b/chrome/browser/net/passive_log_collector.cc @@ -6,6 +6,7 @@ #include +#include "base/compiler_specific.h" #include "base/string_util.h" #include "base/format_macros.h" #include "chrome/browser/chrome_thread.h" @@ -13,16 +14,10 @@ namespace { -const size_t kMaxNumEntriesPerLog = 50; -const size_t kMaxConnectJobGraveyardSize = 3; -const size_t kMaxRequestGraveyardSize = 25; -const size_t kMaxLiveRequests = 200; +// TODO(eroman): Do something with the truncation count. -// Sort function on source ID. -bool OrderBySourceID(const PassiveLogCollector::RequestInfo& a, - const PassiveLogCollector::RequestInfo& b) { - return a.source_id < b.source_id; -} +const size_t kMaxNumEntriesPerLog = 30; +const size_t kMaxRequestsPerTracker = 200; void AddEntryToRequestInfo(const PassiveLogCollector::Entry& entry, PassiveLogCollector::RequestInfo* out_info) { @@ -35,45 +30,12 @@ void AddEntryToRequestInfo(const PassiveLogCollector::Entry& entry, } } -void AppendToRequestInfo(const PassiveLogCollector::RequestInfo& info, - PassiveLogCollector::RequestInfo* out_info) { - for (size_t i = 0; i < info.entries.size(); ++i) - AddEntryToRequestInfo(info.entries[i], out_info); -} - -// Appends all of the logged events in |input| to |out|. -void AppendAllEntriesFromRequests( - const PassiveLogCollector::RequestInfoList& input, - PassiveLogCollector::EntryList* out) { - for (size_t i = 0; i < input.size(); ++i) { - const PassiveLogCollector::EntryList& entries = input[i].entries; - out->insert(out->end(), entries.begin(), entries.end()); - } -} - // Comparator to sort entries by their |order| property, ascending. bool SortByOrderComparator(const PassiveLogCollector::Entry& a, const PassiveLogCollector::Entry& b) { return a.order < b.order; } -void SetSubordinateSource(PassiveLogCollector::RequestInfo* info, - const PassiveLogCollector::Entry& entry) { - info->subordinate_source.id = static_cast( - entry.params.get())->value(); - switch (entry.type) { - case net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID: - info->subordinate_source.type = net::NetLog::SOURCE_CONNECT_JOB; - break; - case net::NetLog::TYPE_SOCKET_POOL_SOCKET_ID: - info->subordinate_source.type = net::NetLog::SOURCE_SOCKET; - break; - default: - NOTREACHED(); - break; - } -} - } // namespace //---------------------------------------------------------------------------- @@ -81,9 +43,24 @@ void SetSubordinateSource(PassiveLogCollector::RequestInfo* info, //---------------------------------------------------------------------------- PassiveLogCollector::PassiveLogCollector() - : url_request_tracker_(&connect_job_tracker_, &socket_tracker_), - socket_stream_tracker_(&connect_job_tracker_, &socket_tracker_), + : 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_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_; + + // 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() { @@ -98,32 +75,22 @@ void PassiveLogCollector::OnAddEntry( // Package the parameters into a single struct for convenience. Entry entry(num_events_seen_++, type, time, source, phase, params); - switch (entry.source.type) { - case net::NetLog::SOURCE_URL_REQUEST: - url_request_tracker_.OnAddEntry(entry); - break; - case net::NetLog::SOURCE_SOCKET_STREAM: - socket_stream_tracker_.OnAddEntry(entry); - break; - case net::NetLog::SOURCE_CONNECT_JOB: - connect_job_tracker_.OnAddEntry(entry); - break; - case net::NetLog::SOURCE_SOCKET: - socket_tracker_.OnAddEntry(entry); - break; - case net::NetLog::SOURCE_INIT_PROXY_RESOLVER: - init_proxy_resolver_tracker_.OnAddEntry(entry); - break; - default: - // Drop all other logged events. - break; - } + RequestTrackerBase* tracker = GetTrackerForSourceType(entry.source.type); + if (tracker) + tracker->OnAddEntry(entry); +} + +PassiveLogCollector::RequestTrackerBase* +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() { - connect_job_tracker_.Clear(); - url_request_tracker_.Clear(); - socket_stream_tracker_.Clear(); + for (size_t i = 0; i < arraysize(trackers_); ++i) + trackers_[i]->Clear(); } void PassiveLogCollector::GetAllCapturedEvents(EntryList* out) const { @@ -131,13 +98,8 @@ void PassiveLogCollector::GetAllCapturedEvents(EntryList* out) const { // Append all of the captured entries held by the various trackers to // |out|. - socket_stream_tracker_.AppendAllEntries(out); - url_request_tracker_.AppendAllEntries(out); - spdy_session_tracker_.AppendAllEntries(out); - - const EntryList& proxy_entries = - init_proxy_resolver_tracker_.entries(); - out->insert(out->end(), proxy_entries.begin(), proxy_entries.end()); + 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); @@ -169,124 +131,166 @@ std::string PassiveLogCollector::RequestInfo::GetURL() const { //---------------------------------------------------------------------------- PassiveLogCollector::RequestTrackerBase::RequestTrackerBase( - size_t max_graveyard_size) - : max_graveyard_size_(max_graveyard_size), - next_graveyard_index_(0) { + size_t max_graveyard_size, PassiveLogCollector* parent) + : max_graveyard_size_(max_graveyard_size), parent_(parent) { } +PassiveLogCollector::RequestTrackerBase::~RequestTrackerBase() {} + void PassiveLogCollector::RequestTrackerBase::OnAddEntry(const Entry& entry) { - RequestInfo& info = live_requests_[entry.source.id]; + RequestInfo& info = requests_[entry.source.id]; info.source_id = entry.source.id; // In case this is a new entry. Action result = DoAddEntry(entry, &info); - switch (result) { - case ACTION_MOVE_TO_GRAVEYARD: - InsertIntoGraveyard(info); - // (fall-through) - case ACTION_DELETE: - RemoveFromLiveRequests(entry.source.id); - break; - default: - break; + 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: + DeleteRequestInfo(info.source_id); + break; + default: + NOTREACHED(); + break; + } + } } - if (live_requests_.size() > kMaxLiveRequests) { + if (requests_.size() > kMaxRequestsPerTracker) { // This is a safety net in case something went wrong, to avoid continually // growing memory. LOG(WARNING) << "The passive log data has grown larger " "than expected, resetting"; - live_requests_.clear(); + Clear(); } } -PassiveLogCollector::RequestInfoList -PassiveLogCollector::RequestTrackerBase::GetLiveRequests() const { - RequestInfoList list; +void PassiveLogCollector::RequestTrackerBase::DeleteRequestInfo( + uint32 source_id) { + SourceIDToInfoMap::iterator it = requests_.find(source_id); + DCHECK(it != requests_.end()); + // The request should not be in the deletion queue. + DCHECK(std::find(deletion_queue_.begin(), deletion_queue_.end(), + source_id) == deletion_queue_.end()); + ReleaseAllReferencesToDependencies(&(it->second)); + requests_.erase(it); +} + +void PassiveLogCollector::RequestTrackerBase::Clear() { + deletion_queue_.clear(); - // Copy all of the live requests into the vector. - for (SourceIDToInfoMap::const_iterator it = live_requests_.begin(); - it != live_requests_.end(); + // Release all references held to dependent sources. + for (SourceIDToInfoMap::iterator it = requests_.begin(); + it != requests_.end(); ++it) { - list.push_back(it->second); - // We pass the copy (made by the list insert), so changes made in - // OnLiveRequest are only seen by our caller. - OnLiveRequest(&list.back()); - std::sort(list.back().entries.begin(), list.back().entries.end(), - SortByOrderComparator); + ReleaseAllReferencesToDependencies(&(it->second)); } - - std::sort(list.begin(), list.end(), OrderBySourceID); - return list; + requests_.clear(); } -void PassiveLogCollector::RequestTrackerBase::ClearRecentlyDeceased() { - next_graveyard_index_ = 0; - graveyard_.clear(); +void PassiveLogCollector::RequestTrackerBase::AppendAllEntries( + EntryList* out) const { + // Append all of the entries for each of the sources. + for (SourceIDToInfoMap::const_iterator it = requests_.begin(); + it != requests_.end(); + ++it) { + const RequestInfo& info = it->second; + out->insert(out->end(), info.entries.begin(), info.entries.end()); + } } -// Returns a list of recently completed Requests. -PassiveLogCollector::RequestInfoList -PassiveLogCollector::RequestTrackerBase::GetRecentlyDeceased() const { - RequestInfoList list; - - // Copy the items from |graveyard_| (our circular queue of recently - // deceased request infos) into a vector, ordered from oldest to newest. - for (size_t i = 0; i < graveyard_.size(); ++i) { - size_t index = (next_graveyard_index_ + i) % graveyard_.size(); - list.push_back(graveyard_[index]); +void PassiveLogCollector::RequestTrackerBase::AddToDeletionQueue( + uint32 source_id) { + DCHECK(requests_.find(source_id) != requests_.end()); + DCHECK(!requests_.find(source_id)->second.is_alive); + DCHECK_GE(requests_.find(source_id)->second.reference_count, 0); + DCHECK_LE(deletion_queue_.size(), max_graveyard_size_); + + deletion_queue_.push_back(source_id); + + // After the deletion queue has reached its maximum size, start + // deleting requests in FIFO order. + if (deletion_queue_.size() > max_graveyard_size_) { + uint32 oldest = deletion_queue_.front(); + deletion_queue_.pop_front(); + DeleteRequestInfo(oldest); } - return list; } -PassiveLogCollector::RequestInfo* -PassiveLogCollector::RequestTrackerBase::GetRequestInfo(uint32 source_id) { - // Look for it in the live requests first. - SourceIDToInfoMap::iterator it = live_requests_.find(source_id); - if (it != live_requests_.end()) - return &(it->second); - - // Otherwise, scan through the graveyard to find an entry for |source_id|. - for (size_t i = 0; i < graveyard_.size(); ++i) { - if (graveyard_[i].source_id == source_id) { - return &graveyard_[i]; +void PassiveLogCollector::RequestTrackerBase::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 + // RequestTrackerBase::Clear() was previously called this can happen. + // TODO(eroman): Add a unit-test that exercises this case. + SourceIDToInfoMap::iterator it = requests_.find(source_id); + if (it == requests_.end()) + return; + + RequestInfo& info = it->second; + DCHECK_GE(info.reference_count, 0); + DCHECK_GE(info.reference_count + offset, 0); + info.reference_count += offset; + + 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 request, go ahead + // and delete it right away. + DeleteRequestInfo(source_id); } } - return NULL; } -void PassiveLogCollector::RequestTrackerBase::RemoveFromLiveRequests( - uint32 source_id) { - // Remove from |live_requests_|. - SourceIDToInfoMap::iterator it = live_requests_.find(source_id); - // TODO(eroman): Shouldn't have this 'if', is it actually really necessary? - if (it != live_requests_.end()) - live_requests_.erase(it); -} +void PassiveLogCollector::RequestTrackerBase::AddReferenceToSourceDependency( + const net::NetLog::Source& source, RequestInfo* info) { + // Find the tracker which should be holding |source|. + DCHECK(parent_); + RequestTrackerBase* tracker = + parent_->GetTrackerForSourceType(source.type); + DCHECK(tracker); -void PassiveLogCollector::RequestTrackerBase::Clear() { - ClearRecentlyDeceased(); - live_requests_.clear(); -} + // Tell the owning tracker to increment the reference count of |source|. + tracker->AdjustReferenceCountForSource(1, source.id); -void PassiveLogCollector::RequestTrackerBase::AppendAllEntries( - EntryList* out) const { - AppendAllEntriesFromRequests(GetLiveRequests(), out); - AppendAllEntriesFromRequests(GetRecentlyDeceased(), out); + // Make a note to release this reference once |info| is destroyed. + info->dependencies.push_back(source); } -void PassiveLogCollector::RequestTrackerBase::InsertIntoGraveyard( - const RequestInfo& info) { - // Enforce a bound on the graveyard size, by treating it as a - // circular buffer. - if (graveyard_.size() < max_graveyard_size_) { - // Still growing to maximum capacity. - DCHECK_EQ(next_graveyard_index_, graveyard_.size()); - graveyard_.push_back(info); - } else { - // At maximum capacity, overwite the oldest entry. - graveyard_[next_graveyard_index_] = info; +void +PassiveLogCollector::RequestTrackerBase::ReleaseAllReferencesToDependencies( + RequestInfo* info) { + // Release all references |info| was holding to dependent 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_); + RequestTrackerBase* tracker = + parent_->GetTrackerForSourceType(source.type); + DCHECK(tracker); + + // Tell the owning tracker to decrement the reference count of |source|. + tracker->AdjustReferenceCountForSource(-1, source.id); } - next_graveyard_index_ = (next_graveyard_index_ + 1) % max_graveyard_size_; + + info->dependencies.clear(); } //---------------------------------------------------------------------------- @@ -295,8 +299,9 @@ void PassiveLogCollector::RequestTrackerBase::InsertIntoGraveyard( const size_t PassiveLogCollector::ConnectJobTracker::kMaxGraveyardSize = 15; -PassiveLogCollector::ConnectJobTracker::ConnectJobTracker() - : RequestTrackerBase(kMaxGraveyardSize) { +PassiveLogCollector::ConnectJobTracker::ConnectJobTracker( + PassiveLogCollector* parent) + : RequestTrackerBase(kMaxGraveyardSize, parent) { } PassiveLogCollector::RequestTrackerBase::Action @@ -304,8 +309,10 @@ PassiveLogCollector::ConnectJobTracker::DoAddEntry(const Entry& entry, RequestInfo* out_info) { AddEntryToRequestInfo(entry, out_info); - if (entry.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID) { - SetSubordinateSource(out_info, entry); + 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 request to the graveyard. @@ -317,29 +324,6 @@ PassiveLogCollector::ConnectJobTracker::DoAddEntry(const Entry& entry, return ACTION_NONE; } -void PassiveLogCollector::ConnectJobTracker::AppendLogEntries( - RequestInfo* out_info, uint32 connect_id) { - RequestInfo* connect_info = GetRequestInfo(connect_id); - if (!connect_info) { - net::NetLogStringParameter* text = new net::NetLogStringParameter( - "todo", StringPrintf("Used ConnectJob id=%u", connect_id)); - Entry new_entry(0, net::NetLog::TYPE_TODO_STRING, base::TimeTicks(), - net::NetLog::Source(net::NetLog::SOURCE_CONNECT_JOB, - connect_id), - net::NetLog::PHASE_NONE, text); - AddEntryToRequestInfo(new_entry, out_info); - return; - } - - AppendToRequestInfo(*connect_info, out_info); - std::sort(out_info->entries.begin(), out_info->entries.end(), - &SortByOrderComparator); - out_info->num_entries_truncated += connect_info->num_entries_truncated; - - if (connect_info->subordinate_source.is_valid()) - AppendLogEntries(out_info, connect_info->subordinate_source.id); -} - //---------------------------------------------------------------------------- // SocketTracker //---------------------------------------------------------------------------- @@ -347,87 +331,28 @@ void PassiveLogCollector::ConnectJobTracker::AppendLogEntries( const size_t PassiveLogCollector::SocketTracker::kMaxGraveyardSize = 15; PassiveLogCollector::SocketTracker::SocketTracker() - : RequestTrackerBase(kMaxGraveyardSize) { + : RequestTrackerBase(kMaxGraveyardSize, NULL) { } PassiveLogCollector::RequestTrackerBase::Action PassiveLogCollector::SocketTracker::DoAddEntry(const Entry& entry, RequestInfo* out_info) { - int int_arg; - switch (entry.type) { - case net::NetLog::TYPE_SOCKET_BYTES_SENT: - int_arg = static_cast( - entry.params.get())->value(); - out_info->total_bytes_transmitted += int_arg; - out_info->bytes_transmitted += int_arg; - out_info->last_tx_rx_time = entry.time; - out_info->last_tx_rx_position = entry.order; - break; - case net::NetLog::TYPE_SOCKET_BYTES_RECEIVED: - int_arg = static_cast( - entry.params.get())->value(); - out_info->total_bytes_received += int_arg; - out_info->bytes_received += int_arg; - out_info->last_tx_rx_time = entry.time; - out_info->last_tx_rx_position = entry.order; - break; - case net::NetLog::TYPE_TCP_SOCKET_DONE: - return ACTION_MOVE_TO_GRAVEYARD; - default: - AddEntryToRequestInfo(entry, out_info); - break; + // 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; } - return ACTION_NONE; -} -void PassiveLogCollector::SocketTracker::AppendLogEntries( - RequestInfo* out_info, uint32 socket_id, bool clear) { - RequestInfo* socket_info = GetRequestInfo(socket_id); - if (!socket_info) { - net::NetLogStringParameter* text = new net::NetLogStringParameter( - "todo", StringPrintf("Used Socket id=%u.", socket_id)); - Entry new_entry(0, net::NetLog::TYPE_TODO_STRING, base::TimeTicks(), - net::NetLog::Source(net::NetLog::SOURCE_SOCKET, socket_id), - net::NetLog::PHASE_NONE, text); - AddEntryToRequestInfo(new_entry, out_info); - return; - } + AddEntryToRequestInfo(entry, out_info); - AppendToRequestInfo(*socket_info, out_info); - out_info->num_entries_truncated += socket_info->num_entries_truncated; - - // Synthesize a log entry for bytes sent and received. - if (socket_info->bytes_transmitted > 0 || socket_info->bytes_received > 0) { - net::NetLogStringParameter* text = new net::NetLogStringParameter( - "stats", - StringPrintf("Tx/Rx: %"PRIu64"/%"PRIu64" [%"PRIu64"/%"PRIu64 - " total on socket] (Bytes)", - socket_info->bytes_transmitted, - socket_info->bytes_received, - socket_info->total_bytes_transmitted, - socket_info->total_bytes_received)); - Entry new_entry(socket_info->last_tx_rx_position, - net::NetLog::TYPE_TODO_STRING, - socket_info->last_tx_rx_time, - net::NetLog::Source(net::NetLog::SOURCE_SOCKET, socket_id), - net::NetLog::PHASE_NONE, - text); - AddEntryToRequestInfo(new_entry, out_info); + if (entry.type == net::NetLog::TYPE_SOCKET_ALIVE && + entry.phase == net::NetLog::PHASE_END) { + return ACTION_MOVE_TO_GRAVEYARD; } - std::sort(out_info->entries.begin(), out_info->entries.end(), - &SortByOrderComparator); - if (clear) - ClearInfo(socket_info); -} - -void PassiveLogCollector::SocketTracker::ClearInfo(RequestInfo* info) { - info->entries.clear(); - info->num_entries_truncated = 0; - info->bytes_transmitted = 0; - info->bytes_received = 0; - info->last_tx_rx_position = 0; - info->last_tx_rx_time = base::TimeTicks(); + return ACTION_NONE; } //---------------------------------------------------------------------------- @@ -436,59 +361,18 @@ void PassiveLogCollector::SocketTracker::ClearInfo(RequestInfo* info) { const size_t PassiveLogCollector::RequestTracker::kMaxGraveyardSize = 25; -PassiveLogCollector::RequestTracker::RequestTracker( - ConnectJobTracker* connect_job_tracker, SocketTracker* socket_tracker) - : RequestTrackerBase(kMaxGraveyardSize), - connect_job_tracker_(connect_job_tracker), - socket_tracker_(socket_tracker) { +PassiveLogCollector::RequestTracker::RequestTracker(PassiveLogCollector* parent) + : RequestTrackerBase(kMaxGraveyardSize, parent) { } PassiveLogCollector::RequestTrackerBase::Action PassiveLogCollector::RequestTracker::DoAddEntry(const Entry& entry, RequestInfo* out_info) { - // We expect up to three events with IDs. - // - Begin SOCKET_POOL_CONNECT_JOB_ID: Means a ConnectJob was created for - // this request. Including it for now, but the resulting socket may be - // used for a different request. - // - End SOCKET_POOL_CONNECT_JOB_ID: The named ConnectJob completed and - // this request will be getting the socket from that request. - // - SOCKET_POOL_SOCKET_ID: The given socket will be used for this request. - // - // The action to take when seeing these events depends on the current - // content of the |subordinate_source| field: - // |subordinate_source| is invalid (fresh state). - // - Begin SOCKET_POOL_CONNECT_JOB_ID: Set |subordinate_source|. - // - End SOCKET_POOL_CONNECT_JOB_ID: Integrate the named ConnectJob ID. - // - SOCKET_POOL_SOCKET_ID: Set |subordinate_source|. - // |subordinate_source| is a ConnectJob: - // - Begin SOCKET_POOL_CONNECT_JOB_ID: Set |subordinate_source|. - // - End SOCKET_POOL_CONNECT_JOB_ID: Integrate the named ConnectJob ID and - // clear the |subordinate_source|. - // - SOCKET_POOL_SOCKET_ID: Set |subordinate_source|. (The request was - // assigned a new idle socket, after starting a ConnectJob.) - // |subordinate_source| is a Socket: - // First, integrate the subordinate socket source, then: - // - Begin SOCKET_POOL_CONNECT_JOB_ID: Set |subordinate_source|. - // (Connection restarted with a new ConnectJob.) - // - End SOCKET_POOL_CONNECT_JOB_ID: Integrate the named ConnectJob ID and - // clear the |subordinate_source|. (Connection restarted with a late bound - // ConnectJob.) - // - SOCKET_POOL_SOCKET_ID: Set |subordinate_source|. (Connection - // restarted and got an idle socket.) - if (entry.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID || - entry.type == net::NetLog::TYPE_SOCKET_POOL_SOCKET_ID) { - - if (out_info->subordinate_source.is_valid() && - out_info->subordinate_source.type == net::NetLog::SOURCE_SOCKET) - IntegrateSubordinateSource(out_info, true); - - SetSubordinateSource(out_info, entry); - - if (entry.phase == net::NetLog::PHASE_END && - entry.type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID) { - IntegrateSubordinateSource(out_info, true); - out_info->subordinate_source.id = net::NetLog::Source::kInvalidId; - } + 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); } AddEntryToRequestInfo(entry, out_info); @@ -496,7 +380,6 @@ PassiveLogCollector::RequestTracker::DoAddEntry(const Entry& entry, // If the request has ended, move it to the graveyard. if (entry.type == net::NetLog::TYPE_REQUEST_ALIVE && entry.phase == net::NetLog::PHASE_END) { - IntegrateSubordinateSource(out_info, true); if (StartsWithASCII(out_info->GetURL(), "chrome://", false)) { // Avoid sending "chrome://" requests to the graveyard, since it just // adds to clutter. @@ -508,53 +391,27 @@ PassiveLogCollector::RequestTracker::DoAddEntry(const Entry& entry, return ACTION_NONE; } -void PassiveLogCollector::RequestTracker::IntegrateSubordinateSource( - RequestInfo* info, bool clear_entries) const { - if (!info->subordinate_source.is_valid()) - return; - - uint32 subordinate_id = info->subordinate_source.id; - switch (info->subordinate_source.type) { - case net::NetLog::SOURCE_CONNECT_JOB: - connect_job_tracker_->AppendLogEntries(info, subordinate_id); - break; - case net::NetLog::SOURCE_SOCKET: - socket_tracker_->AppendLogEntries(info, subordinate_id, clear_entries); - break; - default: - NOTREACHED(); - break; - } -} - //---------------------------------------------------------------------------- // InitProxyResolverTracker //---------------------------------------------------------------------------- -PassiveLogCollector::InitProxyResolverTracker::InitProxyResolverTracker() {} +const size_t PassiveLogCollector::InitProxyResolverTracker::kMaxGraveyardSize = + 3; -void PassiveLogCollector::InitProxyResolverTracker::OnAddEntry( - const Entry& entry) { +PassiveLogCollector::InitProxyResolverTracker::InitProxyResolverTracker() + : RequestTrackerBase(kMaxGraveyardSize, NULL) { +} + +PassiveLogCollector::RequestTrackerBase::Action +PassiveLogCollector::InitProxyResolverTracker::DoAddEntry( + const Entry& entry, RequestInfo* out_info) { + AddEntryToRequestInfo(entry, out_info); if (entry.type == net::NetLog::TYPE_INIT_PROXY_RESOLVER && - entry.phase == net::NetLog::PHASE_BEGIN) { - // If this is the start of a new InitProxyResolver, overwrite the old data. - entries_.clear(); - entries_.push_back(entry); + entry.phase == net::NetLog::PHASE_END) { + return ACTION_MOVE_TO_GRAVEYARD; } else { - // Otherwise append it to the log for the latest InitProxyResolver. - if (!entries_.empty() && entries_[0].source.id != entry.source.id) { - // If this entry doesn't match what we think was the latest - // InitProxyResolver, drop it. (This shouldn't happen, but we will guard - // against it). - return; - } - entries_.push_back(entry); + return ACTION_NONE; } - - // Safety net: INIT_PROXY_RESOLVER shouldn't generate many messages, but in - // case something goes wrong, avoid exploding the memory usage. - if (entries_.size() > kMaxNumEntriesPerLog) - entries_.clear(); } //---------------------------------------------------------------------------- @@ -564,17 +421,17 @@ void PassiveLogCollector::InitProxyResolverTracker::OnAddEntry( const size_t PassiveLogCollector::SpdySessionTracker::kMaxGraveyardSize = 10; PassiveLogCollector::SpdySessionTracker::SpdySessionTracker() - : RequestTrackerBase(kMaxGraveyardSize) { + : RequestTrackerBase(kMaxGraveyardSize, NULL) { } PassiveLogCollector::RequestTrackerBase::Action PassiveLogCollector::SpdySessionTracker::DoAddEntry(const Entry& entry, RequestInfo* out_info) { + AddEntryToRequestInfo(entry, out_info); if (entry.type == net::NetLog::TYPE_SPDY_SESSION && entry.phase == net::NetLog::PHASE_END) { return ACTION_MOVE_TO_GRAVEYARD; } else { - AddEntryToRequestInfo(entry, out_info); return ACTION_NONE; } } diff --git a/chrome/browser/net/passive_log_collector.h b/chrome/browser/net/passive_log_collector.h index 2c59b67..a514428 100644 --- a/chrome/browser/net/passive_log_collector.h +++ b/chrome/browser/net/passive_log_collector.h @@ -5,6 +5,7 @@ #ifndef CHROME_BROWSER_NET_PASSIVE_LOG_COLLECTOR_H_ #define CHROME_BROWSER_NET_PASSIVE_LOG_COLLECTOR_H_ +#include #include #include @@ -15,6 +16,21 @@ #include "chrome/browser/net/chrome_net_log.h" #include "net/base/net_log.h" +// PassiveLogCollector watches the NetLog event stream, and saves the network +// event for recent requests, in a circular buffer. +// +// This is done so that when a network problem is encountered (performance +// problem, or error), about:net-internals can be opened shortly after the +// problem and it will contain a trace for the problem request. +// +// (This is in contrast to the "active logging" which captures every single +// network event, but requires capturing to have been enabled *prior* to +// encountering the problem. Active capturing is enabled as long as +// about:net-internals is open). +// +// The data captured by PassiveLogCollector is grouped by NetLog::Source, into +// a RequestInfo structure. These in turn are grouped by NetLog::SourceType, and +// owned by a RequestTrackerBase instance for the specific source type. class PassiveLogCollector : public ChromeNetLog::Observer { public: // This structure encapsulates all of the parameters of a captured event, @@ -40,16 +56,13 @@ class PassiveLogCollector : public ChromeNetLog::Observer { }; typedef std::vector EntryList; + typedef std::vector SourceDependencyList; + // TODO(eroman): Rename to SourceInfo. struct RequestInfo { RequestInfo() : source_id(net::NetLog::Source::kInvalidId), - num_entries_truncated(0), - total_bytes_transmitted(0), - total_bytes_received(0), - bytes_transmitted(0), - bytes_received(0), - last_tx_rx_position(0) {} + num_entries_truncated(0), reference_count(0), is_alive(true) {} // Returns the URL that corresponds with this source. This is // only meaningful for certain source types (URL_REQUEST, SOCKET_STREAM). @@ -59,15 +72,21 @@ class PassiveLogCollector : public ChromeNetLog::Observer { uint32 source_id; EntryList entries; size_t num_entries_truncated; - net::NetLog::Source subordinate_source; - - // Only used in SocketTracker. - uint64 total_bytes_transmitted; - uint64 total_bytes_received; - uint64 bytes_transmitted; - uint64 bytes_received; - uint32 last_tx_rx_position; // The |order| of the last Tx or Rx entry. - base::TimeTicks last_tx_rx_time; // The |time| of the last Tx or Rx entry. + + // List of other sources which contain information relevant to this + // request (for example, a url request might depend on the log items + // for a connect job and for a socket that were bound to it.) + SourceDependencyList dependencies; + + // Holds the count of how many other sources have added this as a + // dependent source. When it is 0, it means noone has referenced it so it + // can be deleted normally. + int reference_count; + + // |is_alive| is set to false once the request has been added to the + // tracker's graveyard (it may still be kept around due to a non-zero + // reference_count, but it is still considered "dead"). + bool is_alive; }; typedef std::vector RequestInfoList; @@ -76,19 +95,32 @@ class PassiveLogCollector : public ChromeNetLog::Observer { // URLRequests/SocketStreams/ConnectJobs. class RequestTrackerBase { public: - explicit RequestTrackerBase(size_t max_graveyard_size); + RequestTrackerBase(size_t max_graveyard_size, PassiveLogCollector* parent); - void OnAddEntry(const Entry& entry); + virtual ~RequestTrackerBase(); - RequestInfoList GetLiveRequests() const; - void ClearRecentlyDeceased(); - RequestInfoList GetRecentlyDeceased() const; + void OnAddEntry(const Entry& entry); + // Clears all the passively logged data from this tracker. void Clear(); // Appends all the captured entries to |out|. The ordering is undefined. void AppendAllEntries(EntryList* out) const; +#ifdef UNIT_TEST + // Helper used to inspect the current state by unit-tests. + // Retuns a copy of the requests held by the tracker. + RequestInfoList GetAllDeadOrAliveRequests(bool is_alive) const { + RequestInfoList result; + for (SourceIDToInfoMap::const_iterator it = requests_.begin(); + it != requests_.end(); ++it) { + if (it->second.is_alive == is_alive) + result.push_back(it->second); + } + return result; + } +#endif + protected: enum Action { ACTION_NONE, @@ -96,29 +128,45 @@ class PassiveLogCollector : public ChromeNetLog::Observer { ACTION_MOVE_TO_GRAVEYARD, }; - // Finds a request, either in the live entries or the graveyard and returns - // it. - RequestInfo* GetRequestInfo(uint32 id); - - // When GetLiveRequests() is called, RequestTrackerBase calls this method - // for each entry after adding it to the list which will be returned - // to the caller. - virtual void OnLiveRequest(RequestInfo* info) const {} + // Makes |info| hold a reference to |source|. This way |source| will be + // kept alive at least as long as |info|. + void AddReferenceToSourceDependency(const net::NetLog::Source& source, + RequestInfo* info); private: typedef base::hash_map SourceIDToInfoMap; + typedef std::deque DeletionQueue; // Updates |out_info| with the information from |entry|. Returns an action // to perform for this map entry on completion. virtual Action DoAddEntry(const Entry& entry, RequestInfo* out_info) = 0; - void RemoveFromLiveRequests(uint32 source_id); - void InsertIntoGraveyard(const RequestInfo& info); + // Removes |source_id| from |requests_|. This also releases any references + // to dependencies held by this source. + void DeleteRequestInfo(uint32 source_id); + + // Adds |source_id| to the FIFO queue (graveyard) for deletion. + void AddToDeletionQueue(uint32 source_id); + + // Adds/Releases a reference from the source with ID |source_id|. + // Use |offset=-1| to do a release, and |offset=1| for an addref. + void AdjustReferenceCountForSource(int offset, uint32 source_id); + + // Releases all the references to sources held by |info|. + void ReleaseAllReferencesToDependencies(RequestInfo* info); + + // This map contains all of the requests being tracked by this tracker. + // (It includes both the "live" requests, and the "dead" ones.) + SourceIDToInfoMap requests_; - SourceIDToInfoMap live_requests_; size_t max_graveyard_size_; - size_t next_graveyard_index_; - RequestInfoList graveyard_; + + // FIFO queue for entries in |requests_| that are no longer alive, and + // can be deleted. This buffer is also called "graveyard" elsewhere. We + // queue requests for deletion so they can persist a bit longer. + DeletionQueue deletion_queue_; + + PassiveLogCollector* parent_; DISALLOW_COPY_AND_ASSIGN(RequestTrackerBase); }; @@ -128,9 +176,7 @@ class PassiveLogCollector : public ChromeNetLog::Observer { public: static const size_t kMaxGraveyardSize; - ConnectJobTracker(); - - void AppendLogEntries(RequestInfo* out_info, uint32 connect_id); + explicit ConnectJobTracker(PassiveLogCollector* parent); protected: virtual Action DoAddEntry(const Entry& entry, RequestInfo* out_info); @@ -145,14 +191,10 @@ class PassiveLogCollector : public ChromeNetLog::Observer { SocketTracker(); - void AppendLogEntries(RequestInfo* out_info, uint32 socket_id, bool clear); - protected: virtual Action DoAddEntry(const Entry& entry, RequestInfo* out_info); private: - void ClearInfo(RequestInfo* info); - DISALLOW_COPY_AND_ASSIGN(SocketTracker); }; @@ -161,39 +203,27 @@ class PassiveLogCollector : public ChromeNetLog::Observer { public: static const size_t kMaxGraveyardSize; - RequestTracker(ConnectJobTracker* connect_job_tracker, - SocketTracker* socket_tracker); - - void IntegrateSubordinateSource(RequestInfo* info, - bool clear_entries) const; + explicit RequestTracker(PassiveLogCollector* parent); protected: virtual Action DoAddEntry(const Entry& entry, RequestInfo* out_info); - virtual void OnLiveRequest(RequestInfo* info) const { - IntegrateSubordinateSource(info, false); - } - private: - ConnectJobTracker* connect_job_tracker_; - SocketTracker* socket_tracker_; - DISALLOW_COPY_AND_ASSIGN(RequestTracker); }; - // Tracks the log entries for the last seen SOURCE_INIT_PROXY_RESOLVER. - class InitProxyResolverTracker { + // Specialization of RequestTrackerBase for handling + // SOURCE_INIT_PROXY_RESOLVER. + class InitProxyResolverTracker : public RequestTrackerBase { public: - InitProxyResolverTracker(); + static const size_t kMaxGraveyardSize; - void OnAddEntry(const Entry& entry); + InitProxyResolverTracker(); - const EntryList& entries() const { - return entries_; - } + protected: + virtual Action DoAddEntry(const Entry& entry, RequestInfo* out_info); private: - EntryList entries_; DISALLOW_COPY_AND_ASSIGN(InitProxyResolverTracker); }; @@ -221,32 +251,20 @@ class PassiveLogCollector : public ChromeNetLog::Observer { net::NetLog::EventPhase phase, net::NetLog::EventParameters* params); + // Returns the tracker to use for sources of type |source_type|, or NULL. + RequestTrackerBase* GetTrackerForSourceType( + net::NetLog::SourceType source_type); + // Clears all of the passively logged data. void Clear(); - RequestTracker* url_request_tracker() { - return &url_request_tracker_; - } - - RequestTracker* socket_stream_tracker() { - return &socket_stream_tracker_; - } - - InitProxyResolverTracker* init_proxy_resolver_tracker() { - return &init_proxy_resolver_tracker_; - } - - SpdySessionTracker* spdy_session_tracker() { - return &spdy_session_tracker_; - } - // Fills |out| with the full list of events that have been passively // captured. The list is ordered by capture time. void GetAllCapturedEvents(EntryList* out) const; private: - FRIEND_TEST_ALL_PREFIXES(PassiveLogCollectorTest, LostConnectJob); - FRIEND_TEST_ALL_PREFIXES(PassiveLogCollectorTest, LostSocket); + FRIEND_TEST_ALL_PREFIXES(PassiveLogCollectorTest, + HoldReferenceToDependentSource); ConnectJobTracker connect_job_tracker_; SocketTracker socket_tracker_; @@ -255,6 +273,11 @@ class PassiveLogCollector : public ChromeNetLog::Observer { InitProxyResolverTracker init_proxy_resolver_tracker_; SpdySessionTracker spdy_session_tracker_; + // This array maps each NetLog::SourceType to one of the tracker instances + // defined above. Use of this array avoid duplicating the list of trackers + // elsewhere. + RequestTrackerBase* trackers_[net::NetLog::SOURCE_COUNT]; + // The count of how many events have flowed through this log. Used to set the // "order" field on captured events. uint32 num_events_seen_; diff --git a/chrome/browser/net/passive_log_collector_unittest.cc b/chrome/browser/net/passive_log_collector_unittest.cc index 41209404..3e0894c 100644 --- a/chrome/browser/net/passive_log_collector_unittest.cc +++ b/chrome/browser/net/passive_log_collector_unittest.cc @@ -14,6 +14,7 @@ namespace { typedef PassiveLogCollector::RequestTracker RequestTracker; typedef PassiveLogCollector::RequestInfoList RequestInfoList; +typedef PassiveLogCollector::SocketTracker SocketTracker; using net::NetLog; const NetLog::SourceType kSourceType = NetLog::SOURCE_NONE; @@ -65,14 +66,33 @@ std::string GetStringParam(const PassiveLogCollector::Entry& entry) { entry.params.get())->value(); } +bool OrderBySourceID(const PassiveLogCollector::RequestInfo& a, + const PassiveLogCollector::RequestInfo& b) { + return a.source_id < b.source_id; +} + +RequestInfoList GetLiveRequests( + const PassiveLogCollector::RequestTrackerBase& tracker) { + RequestInfoList result = tracker.GetAllDeadOrAliveRequests(true); + std::sort(result.begin(), result.end(), &OrderBySourceID); + return result; +} + +RequestInfoList GetDeadRequests( + const PassiveLogCollector::RequestTrackerBase& tracker) { + RequestInfoList result = tracker.GetAllDeadOrAliveRequests(false); + std::sort(result.begin(), result.end(), &OrderBySourceID); + return result; +} + static const int kMaxNumLoadLogEntries = 1; } // namespace TEST(RequestTrackerTest, BasicBounded) { - RequestTracker tracker(NULL, NULL); - EXPECT_EQ(0u, tracker.GetLiveRequests().size()); - EXPECT_EQ(0u, tracker.GetRecentlyDeceased().size()); + RequestTracker tracker(NULL); + EXPECT_EQ(0u, GetLiveRequests(tracker).size()); + EXPECT_EQ(0u, GetDeadRequests(tracker).size()); tracker.OnAddEntry(MakeStartLogEntry(1)); tracker.OnAddEntry(MakeStartLogEntry(2)); @@ -80,7 +100,7 @@ TEST(RequestTrackerTest, BasicBounded) { tracker.OnAddEntry(MakeStartLogEntry(4)); tracker.OnAddEntry(MakeStartLogEntry(5)); - RequestInfoList live_reqs = tracker.GetLiveRequests(); + RequestInfoList live_reqs = GetLiveRequests(tracker); ASSERT_EQ(5u, live_reqs.size()); EXPECT_EQ("http://req1/", live_reqs[0].GetURL()); @@ -93,9 +113,9 @@ TEST(RequestTrackerTest, BasicBounded) { tracker.OnAddEntry(MakeEndLogEntry(5)); tracker.OnAddEntry(MakeEndLogEntry(3)); - ASSERT_EQ(3u, tracker.GetRecentlyDeceased().size()); + ASSERT_EQ(3u, GetDeadRequests(tracker).size()); - live_reqs = tracker.GetLiveRequests(); + live_reqs = GetLiveRequests(tracker); ASSERT_EQ(2u, live_reqs.size()); EXPECT_EQ("http://req2/", live_reqs[0].GetURL()); @@ -103,9 +123,9 @@ TEST(RequestTrackerTest, BasicBounded) { } TEST(RequestTrackerTest, GraveyardBounded) { - RequestTracker tracker(NULL, NULL); - EXPECT_EQ(0u, tracker.GetLiveRequests().size()); - EXPECT_EQ(0u, tracker.GetRecentlyDeceased().size()); + RequestTracker tracker(NULL); + EXPECT_EQ(0u, GetLiveRequests(tracker).size()); + EXPECT_EQ(0u, GetDeadRequests(tracker).size()); // Add twice as many requests as will fit in the graveyard. for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize * 2; ++i) { @@ -113,9 +133,11 @@ TEST(RequestTrackerTest, GraveyardBounded) { tracker.OnAddEntry(MakeEndLogEntry(i)); } + EXPECT_EQ(0u, GetLiveRequests(tracker).size()); + // Check that only the last |kMaxGraveyardSize| requests are in-memory. - RequestInfoList recent_reqs = tracker.GetRecentlyDeceased(); + RequestInfoList recent_reqs = GetDeadRequests(tracker); ASSERT_EQ(RequestTracker::kMaxGraveyardSize, recent_reqs.size()); @@ -129,7 +151,7 @@ TEST(RequestTrackerTest, GraveyardBounded) { // Check that we exclude "chrome://" URLs from being saved into the recent // requests list (graveyard). TEST(RequestTrackerTest, GraveyardIsFiltered) { - RequestTracker tracker(NULL, NULL); + RequestTracker tracker(NULL); // This will be excluded. std::string url1 = "chrome://dontcare/"; @@ -146,824 +168,15 @@ TEST(RequestTrackerTest, GraveyardIsFiltered) { tracker.OnAddEntry(MakeStartLogEntryWithURL(3, url3)); tracker.OnAddEntry(MakeEndLogEntry(3)); - ASSERT_EQ(2u, tracker.GetRecentlyDeceased().size()); - EXPECT_EQ(url2, tracker.GetRecentlyDeceased()[0].GetURL()); - EXPECT_EQ(url3, tracker.GetRecentlyDeceased()[1].GetURL()); -} - -TEST(PassiveLogCollectorTest, BasicConnectJobAssociation) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - AddStartURLRequestEntries(&log, 20); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(10u, requests[0].source_id); - EXPECT_EQ(2u, requests[0].entries.size()); - EXPECT_EQ(20u, requests[1].source_id); - EXPECT_EQ(2u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 21)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(4u, requests[0].entries.size()); - EXPECT_EQ(5u, requests[1].entries.size()); - - AddEndURLRequestEntries(&log, 10); - AddEndURLRequestEntries(&log, 20); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(2u, requests.size()); - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); -} - -TEST(PassiveLogCollectorTest, BasicSocketAssociation) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - AddStartURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_END, NULL); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 21)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 21)); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(6u, requests[0].entries.size()); - EXPECT_EQ(7u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 25)); - - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(8u, requests[0].entries.size()); - EXPECT_EQ(10u, requests[1].entries.size()); - - AddEndURLRequestEntries(&log, 10); - AddEndURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(2u, requests.size()); - EXPECT_EQ(9u, requests[0].entries.size()); - EXPECT_EQ(11u, requests[1].entries.size()); -} - -TEST(PassiveLogCollectorTest, IdleSocketAssociation) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - AddStartURLRequestEntries(&log, 20); - log.OnAddEntry(NetLog::TYPE_INIT_PROXY_RESOLVER , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(2u, requests[0].entries.size()); - EXPECT_EQ(3u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 25)); - - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(4u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); - - AddEndURLRequestEntries(&log, 10); - AddEndURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(2u, requests.size()); - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(7u, requests[1].entries.size()); -} - -TEST(PassiveLogCollectorTest, IdleAssociateAfterConnectJobStarted) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - AddStartURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_END, NULL); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 21)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 25)); - - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); - - AddEndURLRequestEntries(&log, 10); - AddEndURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(2u, requests.size()); - EXPECT_EQ(6u, requests[0].entries.size()); - EXPECT_EQ(7u, requests[1].entries.size()); -} - -TEST(PassiveLogCollectorTest, LateBindDifferentConnectJob) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - AddStartURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_END, NULL); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 21)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_END, NULL); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 31), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 31), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 31), - NetLog::PHASE_END, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 31), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 21)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 31)); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(7u, requests[0].entries.size()); - EXPECT_EQ(8u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 25)); - - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(9u, requests[0].entries.size()); - EXPECT_EQ(11u, requests[1].entries.size()); - - AddEndURLRequestEntries(&log, 10); - AddEndURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(2u, requests.size()); - EXPECT_EQ(10u, requests[0].entries.size()); - EXPECT_EQ(12u, requests[1].entries.size()); -} - -TEST(PassiveLogCollectorTest, LateBindPendingConnectJob) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - AddStartURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_END, NULL); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 21), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(2u, requests[0].entries.size()); - EXPECT_EQ(2u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 21)); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 25)); - - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(2u, requests.size()); - - EXPECT_EQ(7u, requests[0].entries.size()); - EXPECT_EQ(9u, requests[1].entries.size()); - - AddEndURLRequestEntries(&log, 10); - AddEndURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 25), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(2u, requests.size()); - EXPECT_EQ(8u, requests[0].entries.size()); - EXPECT_EQ(10u, requests[1].entries.size()); -} - -TEST(PassiveLogCollectorTest, ReconnectToIdleSocket) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - - // Initial socket. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(4u, requests[0].entries.size()); - - // Reconnect. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 17)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 17), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(6u, requests[0].entries.size()); - - AddEndURLRequestEntries(&log, 10); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(7u, requests[0].entries.size()); -} - -TEST(PassiveLogCollectorTest, ReconnectToLateBoundSocket) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - - // Initial socket. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(4u, requests[0].entries.size()); - - // Now reconnect. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(6u, requests[0].entries.size()); - - // But we get late bound to an idle socket. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 17)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 17), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(7u, requests[0].entries.size()); - - AddEndURLRequestEntries(&log, 10); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(8u, requests[0].entries.size()); -} - -TEST(PassiveLogCollectorTest, ReconnectToLateBoundConnectJob) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - - // Initial socket. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(4u, requests[0].entries.size()); - - // Now reconnect. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(6u, requests[0].entries.size()); - - // But we get late bound to a different ConnectJob. - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 12), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 12), - NetLog::PHASE_END, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 12)); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(8u, requests[0].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 17)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 17), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(10u, requests[0].entries.size()); - - AddEndURLRequestEntries(&log, 10); - - log.OnAddEntry(NetLog::TYPE_TCP_SOCKET_DONE , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(11u, requests[0].entries.size()); -} - -TEST(PassiveLogCollectorTest, LostConnectJob) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_BEGIN, new net::NetLogIntegerParameter("x", 11)); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_NONE, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_CONNECT_JOB, 11), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(6u, requests[0].entries.size()); - - log.connect_job_tracker_.Clear(); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 11)); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(5u, requests[0].entries.size()); -} - -TEST(PassiveLogCollectorTest, LostSocket) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_END, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_BEGIN, NULL); - log.OnAddEntry(NetLog::TYPE_SSL_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_END, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(7u, requests[0].entries.size()); - - log.socket_tracker_.Clear(); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(4u, requests[0].entries.size()); -} - -TEST(PassiveLogCollectorTest, AccumulateRxTxData) { - PassiveLogCollector log; - - RequestInfoList requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - - AddStartURLRequestEntries(&log, 10); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 10), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(4u, requests[0].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_BYTES_SENT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 1)); - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(NetLog::TYPE_TODO_STRING, requests[0].entries[4].type); - EXPECT_EQ("Tx/Rx: 1/0 [1/0 total on socket] (Bytes)", - GetStringParam(requests[0].entries[4])); - - log.OnAddEntry(NetLog::TYPE_SOCKET_BYTES_RECEIVED , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 2)); - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(NetLog::TYPE_TODO_STRING, requests[0].entries[4].type); - EXPECT_EQ("Tx/Rx: 1/2 [1/2 total on socket] (Bytes)", - GetStringParam(requests[0].entries[4])); - - AddEndURLRequestEntries(&log, 10); - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(6u, requests[0].entries.size()); - EXPECT_EQ(NetLog::TYPE_TODO_STRING, requests[0].entries[4].type); - EXPECT_EQ("Tx/Rx: 1/2 [1/2 total on socket] (Bytes)", - GetStringParam(requests[0].entries[4])); - - AddStartURLRequestEntries(&log, 20); - - log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_SOCKET_ID , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_URL_REQUEST, 20), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 15)); - log.OnAddEntry(NetLog::TYPE_SOCKS_CONNECT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_NONE, NULL); - - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(4u, requests[0].entries.size()); - - log.OnAddEntry(NetLog::TYPE_SOCKET_BYTES_SENT , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 4)); - log.OnAddEntry(NetLog::TYPE_SOCKET_BYTES_RECEIVED , base::TimeTicks(), - NetLog::Source(NetLog::SOURCE_SOCKET, 15), - NetLog::PHASE_END, new net::NetLogIntegerParameter("x", 8)); - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(1u, requests.size()); - EXPECT_EQ(5u, requests[0].entries.size()); - EXPECT_EQ(NetLog::TYPE_TODO_STRING, requests[0].entries[4].type); - EXPECT_EQ("Tx/Rx: 4/8 [5/10 total on socket] (Bytes)", - GetStringParam(requests[0].entries[4])); - - AddEndURLRequestEntries(&log, 20); - requests = log.url_request_tracker()->GetLiveRequests(); - EXPECT_EQ(0u, requests.size()); - requests = log.url_request_tracker()->GetRecentlyDeceased(); - EXPECT_EQ(2u, requests.size()); - EXPECT_EQ(6u, requests[0].entries.size()); - EXPECT_EQ(6u, requests[1].entries.size()); + ASSERT_EQ(2u, GetDeadRequests(tracker).size()); + EXPECT_EQ(url2, GetDeadRequests(tracker)[0].GetURL()); + EXPECT_EQ(url3, GetDeadRequests(tracker)[1].GetURL()); } TEST(SpdySessionTracker, MovesToGraveyard) { PassiveLogCollector::SpdySessionTracker tracker; - EXPECT_EQ(0u, tracker.GetLiveRequests().size()); - EXPECT_EQ(0u, tracker.GetRecentlyDeceased().size()); + EXPECT_EQ(0u, GetLiveRequests(tracker).size()); + EXPECT_EQ(0u, GetDeadRequests(tracker).size()); PassiveLogCollector::Entry begin( 0u, @@ -974,8 +187,8 @@ TEST(SpdySessionTracker, MovesToGraveyard) { NULL); tracker.OnAddEntry(begin); - EXPECT_EQ(1u, tracker.GetLiveRequests().size()); - EXPECT_EQ(0u, tracker.GetRecentlyDeceased().size()); + EXPECT_EQ(1u, GetLiveRequests(tracker).size()); + EXPECT_EQ(0u, GetDeadRequests(tracker).size()); PassiveLogCollector::Entry end( 0u, @@ -986,6 +199,155 @@ TEST(SpdySessionTracker, MovesToGraveyard) { NULL); tracker.OnAddEntry(end); - EXPECT_EQ(0u, tracker.GetLiveRequests().size()); - EXPECT_EQ(1u, tracker.GetRecentlyDeceased().size()); + EXPECT_EQ(0u, GetLiveRequests(tracker).size()); + EXPECT_EQ(1u, GetDeadRequests(tracker).size()); +} + +// Test that when a SOURCE_SOCKET is connected to a SOURCE_URL_REQUEST +// (via the TYPE_SOCKET_POOL_BOUND_TO_SOCKET event), it holds a reference +// to the SOURCE_SOCKET preventing it from getting deleted as long as the +// SOURCE_URL_REQUEST is still around. +TEST(PassiveLogCollectorTest, HoldReferenceToDependentSource) { + PassiveLogCollector log; + + EXPECT_EQ(0u, GetLiveRequests(log.url_request_tracker_).size()); + EXPECT_EQ(0u, GetLiveRequests(log.socket_tracker_).size()); + + uint32 next_id = 0; + NetLog::Source socket_source(NetLog::SOURCE_SOCKET, next_id++); + NetLog::Source url_request_source(NetLog::SOURCE_URL_REQUEST, next_id++); + + // Start a SOURCE_SOCKET. + log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE, + base::TimeTicks(), + socket_source, + NetLog::PHASE_BEGIN, + NULL); + + EXPECT_EQ(0u, GetLiveRequests(log.url_request_tracker_).size()); + EXPECT_EQ(1u, GetLiveRequests(log.socket_tracker_).size()); + + // Start a SOURCE_URL_REQUEST. + log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE, + base::TimeTicks(), + url_request_source, + NetLog::PHASE_BEGIN, + NULL); + + // Check that there is no association between the SOURCE_URL_REQUEST and the + // SOURCE_SOCKET yet. + ASSERT_EQ(1u, GetLiveRequests(log.url_request_tracker_).size()); + { + PassiveLogCollector::RequestInfo info = + GetLiveRequests(log.url_request_tracker_)[0]; + EXPECT_EQ(0, info.reference_count); + EXPECT_EQ(0u, info.dependencies.size()); + } + ASSERT_EQ(1u, GetLiveRequests(log.socket_tracker_).size()); + { + PassiveLogCollector::RequestInfo info = + GetLiveRequests(log.socket_tracker_)[0]; + EXPECT_EQ(0, info.reference_count); + EXPECT_EQ(0u, info.dependencies.size()); + } + + // Associate the SOURCE_SOCKET with the SOURCE_URL_REQUEST. + log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET, + base::TimeTicks(), + url_request_source, + NetLog::PHASE_NONE, + new net::NetLogSourceParameter("x", socket_source)); + + // Check that an associate was made -- the SOURCE_URL_REQUEST should have + // added a reference to the SOURCE_SOCKET. + ASSERT_EQ(1u, GetLiveRequests(log.url_request_tracker_).size()); + { + PassiveLogCollector::RequestInfo info = + GetLiveRequests(log.url_request_tracker_)[0]; + EXPECT_EQ(0, info.reference_count); + EXPECT_EQ(1u, info.dependencies.size()); + EXPECT_EQ(socket_source.id, info.dependencies[0].id); + } + ASSERT_EQ(1u, GetLiveRequests(log.socket_tracker_).size()); + { + PassiveLogCollector::RequestInfo info = + GetLiveRequests(log.socket_tracker_)[0]; + EXPECT_EQ(1, info.reference_count); + EXPECT_EQ(0u, info.dependencies.size()); + } + + // Now end both |source_socket| and |source_url_request|. This sends them + // to deletion queue, and they will be deleted once space runs out. + + log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE, + base::TimeTicks(), + url_request_source, + NetLog::PHASE_END, + NULL); + + log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE, + base::TimeTicks(), + socket_source, + NetLog::PHASE_END, + NULL); + + // Verify that both sources are in fact dead, and that |source_url_request| + // still holds a reference to |source_socket|. + ASSERT_EQ(0u, GetLiveRequests(log.url_request_tracker_).size()); + ASSERT_EQ(1u, GetDeadRequests(log.url_request_tracker_).size()); + { + PassiveLogCollector::RequestInfo info = + GetDeadRequests(log.url_request_tracker_)[0]; + EXPECT_EQ(0, info.reference_count); + EXPECT_EQ(1u, info.dependencies.size()); + EXPECT_EQ(socket_source.id, info.dependencies[0].id); + } + EXPECT_EQ(0u, GetLiveRequests(log.socket_tracker_).size()); + ASSERT_EQ(1u, GetDeadRequests(log.socket_tracker_).size()); + { + PassiveLogCollector::RequestInfo info = + GetDeadRequests(log.socket_tracker_)[0]; + EXPECT_EQ(1, info.reference_count); + EXPECT_EQ(0u, info.dependencies.size()); + } + + // Cycle through a bunch of SOURCE_SOCKET -- if it were not referenced, this + // loop will have deleted it. + for (size_t i = 0; i < SocketTracker::kMaxGraveyardSize; ++i) { + log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE, + base::TimeTicks(), + NetLog::Source(NetLog::SOURCE_SOCKET, next_id++), + NetLog::PHASE_END, + NULL); + } + + EXPECT_EQ(0u, GetLiveRequests(log.socket_tracker_).size()); + ASSERT_EQ(SocketTracker::kMaxGraveyardSize + 1, + GetDeadRequests(log.socket_tracker_).size()); + { + PassiveLogCollector::RequestInfo info = + GetDeadRequests(log.socket_tracker_)[0]; + EXPECT_EQ(socket_source.id, info.source_id); + EXPECT_EQ(1, info.reference_count); + EXPECT_EQ(0u, info.dependencies.size()); + } + + // Cycle through a bunch of SOURCE_URL_REQUEST -- this will cause + // |source_url_request| to be freed, which in turn should release the final + // reference to |source_socket| cause it to be freed as well. + for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize; ++i) { + log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE, + base::TimeTicks(), + NetLog::Source(NetLog::SOURCE_URL_REQUEST, next_id++), + NetLog::PHASE_END, + NULL); + } + + EXPECT_EQ(0u, GetLiveRequests(log.url_request_tracker_).size()); + EXPECT_EQ(RequestTracker::kMaxGraveyardSize, + GetDeadRequests(log.url_request_tracker_).size()); + + EXPECT_EQ(0u, GetLiveRequests(log.socket_tracker_).size()); + EXPECT_EQ(SocketTracker::kMaxGraveyardSize, + GetDeadRequests(log.socket_tracker_).size()); } diff --git a/chrome/service/net/service_url_request_context.cc b/chrome/service/net/service_url_request_context.cc index 9a1716e..572ccb8 100644 --- a/chrome/service/net/service_url_request_context.cc +++ b/chrome/service/net/service_url_request_context.cc @@ -39,7 +39,8 @@ ServiceURLRequestContext::ServiceURLRequestContext() { net::HttpNetworkLayer::CreateFactory(NULL, host_resolver_, proxy_service_, ssl_config_service_, - http_auth_handler_factory_), + http_auth_handler_factory_, + NULL /*net_log*/), net::HttpCache::DefaultBackend::InMemory(0)); // In-memory cookie store. cookie_store_ = new net::CookieMonster(NULL, NULL); diff --git a/chrome_frame/test/test_server_test.cc b/chrome_frame/test/test_server_test.cc index 9376e0d..4ea7c1b 100644 --- a/chrome_frame/test/test_server_test.cc +++ b/chrome_frame/test/test_server_test.cc @@ -70,7 +70,8 @@ class URLRequestTestContext : public URLRequestContext { net::HttpNetworkLayer::CreateFactory(NULL, host_resolver_, proxy_service_, ssl_config_service_, - http_auth_handler_factory_), + http_auth_handler_factory_, + NULL), net::HttpCache::DefaultBackend::InMemory(0)); // In-memory cookie store. cookie_store_ = new net::CookieMonster(NULL, NULL); diff --git a/net/base/net_log.cc b/net/base/net_log.cc index 02b6bbd..ace4a53 100644 --- a/net/base/net_log.cc +++ b/net/base/net_log.cc @@ -97,4 +97,15 @@ Value* NetLogStringParameter::ToValue() const { return dict; } +Value* NetLogSourceParameter::ToValue() const { + DictionaryValue* dict = new DictionaryValue(); + + DictionaryValue* source_dict = new DictionaryValue(); + source_dict->SetInteger(L"type", static_cast(value_.type)); + source_dict->SetInteger(L"id", static_cast(value_.id)); + + dict->Set(ASCIIToWide(name_), source_dict); + return dict; +} + } // namespace net diff --git a/net/base/net_log.h b/net/base/net_log.h index 619b57b..a9d24f8 100644 --- a/net/base/net_log.h +++ b/net/base/net_log.h @@ -53,7 +53,7 @@ class NetLog { // The "source" identifies the entity that generated the log message. enum SourceType { -#define SOURCE_TYPE(label) SOURCE_ ## label, +#define SOURCE_TYPE(label, value) SOURCE_ ## label = value, #include "net/base/net_log_source_type_list.h" #undef SOURCE_TYPE }; @@ -206,6 +206,25 @@ class NetLogIntegerParameter : public NetLog::EventParameters { const int value_; }; +// NetLogSourceParameter is a subclass of EventParameters that encapsulates a +// single NetLog::Source parameter. +class NetLogSourceParameter : public NetLog::EventParameters { + public: + // |name| must be a string literal. + NetLogSourceParameter(const char* name, const NetLog::Source& value) + : name_(name), value_(value) {} + + const NetLog::Source& value() const { + return value_; + } + + virtual Value* ToValue() const; + + private: + const char* name_; + const NetLog::Source value_; +}; + } // namespace net #endif // NET_BASE_NET_LOG_H_ diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h index 531a019..709a130 100644 --- a/net/base/net_log_event_type_list.h +++ b/net/base/net_log_event_type_list.h @@ -13,12 +13,7 @@ // log context around it.) EVENT_TYPE(CANCELLED) -// TODO(eroman): remove the remaining consumers of this. -EVENT_TYPE(TODO_STRING) - // Marks the creation/destruction of a request (URLRequest or SocketStream). -// In the begin phase of this event, the message will contain a string which -// is the URL. EVENT_TYPE(REQUEST_ALIVE) // ------------------------------------------------------------------------ @@ -154,8 +149,18 @@ EVENT_TYPE(TCP_CONNECT) // } EVENT_TYPE(TCP_CONNECT_ATTEMPT) -// Marks the destruction of a TCP socket. -EVENT_TYPE(TCP_SOCKET_DONE) +// Marks the begin/end of a socket (TCP/SOCKS/SSL). +EVENT_TYPE(SOCKET_ALIVE) + +// This event is logged to the socket stream whenever the socket is +// acquired/released via a ClientSocketHandle. +// +// The BEGIN phase contains the following parameters: +// +// { +// "source_dependency": +// } +EVENT_TYPE(SOCKET_IN_USE) // The start/end of a SOCKS connect(). EVENT_TYPE(SOCKS_CONNECT) @@ -228,6 +233,23 @@ EVENT_TYPE(SOCKET_BYTES_RECEIVED) // The start/end of a ConnectJob. EVENT_TYPE(SOCKET_POOL_CONNECT_JOB) +// The start/end of the ConnectJob::Connect(). +// +// The BEGIN phase has these parameters: +// +// { +// "group_name": +// } +EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_CONNECT) + +// This event is logged whenever the ConnectJob gets a new socket +// association. The event parameters point to that socket: +// +// { +// "source_dependency": +// } +EVENT_TYPE(CONNECT_JOB_SET_SOCKET) + // Whether the connect job timed out. EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_TIMED_OUT) @@ -262,25 +284,23 @@ EVENT_TYPE(TCP_CLIENT_SOCKET_POOL_REQUESTED_SOCKET) // A backup socket is created due to slow connect EVENT_TYPE(SOCKET_BACKUP_CREATED) -// A backup socket is created due to slow connect -EVENT_TYPE(SOCKET_BACKUP_TIMER_EXTENDED) - -// Identifies the NetLog::Source() for a ConnectJob. The begin event -// is sent to the request that triggered the ConnectJob, the end event -// is sent to the request that received the connected socket. Because of -// late binding, they may not be the same. Therefore the ID for the -// ConnectJob NetLog is sent in both events. The event parameters are: +// This event is sent when a connect job is eventually bound to a request +// (because of late binding and socket backup jobs, we don't assign the job to +// a request until it has completed). +// +// The event parameters are: // { -// "source_id": +// "source_dependency": // } -EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_ID) +EVENT_TYPE(SOCKET_POOL_BOUND_TO_CONNECT_JOB) // Identifies the NetLog::Source() for the Socket assigned to the pending // request. The event parameters are: // { -// "source_id": +// "source_dependency": // } -EVENT_TYPE(SOCKET_POOL_SOCKET_ID) +EVENT_TYPE(SOCKET_POOL_BOUND_TO_SOCKET) // ------------------------------------------------------------------------ // URLRequest diff --git a/net/base/net_log_source_type_list.h b/net/base/net_log_source_type_list.h index 9d29826..6664c2d 100644 --- a/net/base/net_log_source_type_list.h +++ b/net/base/net_log_source_type_list.h @@ -5,11 +5,13 @@ // NOTE: No header guards are used, since this file is intended to be expanded // directly within a block where the SOURCE_TYPE macro is defined. -SOURCE_TYPE(NONE) -SOURCE_TYPE(URL_REQUEST) -SOURCE_TYPE(SOCKET_STREAM) -SOURCE_TYPE(INIT_PROXY_RESOLVER) -SOURCE_TYPE(CONNECT_JOB) -SOURCE_TYPE(SOCKET) -SOURCE_TYPE(SPDY_SESSION) +SOURCE_TYPE(NONE, -1) +SOURCE_TYPE(URL_REQUEST, 0) +SOURCE_TYPE(SOCKET_STREAM, 1) +SOURCE_TYPE(INIT_PROXY_RESOLVER, 2) +SOURCE_TYPE(CONNECT_JOB, 3) +SOURCE_TYPE(SOCKET, 4) +SOURCE_TYPE(SPDY_SESSION, 5) + +SOURCE_TYPE(COUNT, 6) // Always keep this as the last entry. diff --git a/net/http/http_cache.cc b/net/http/http_cache.cc index 964d1b9..bffd97a 100644 --- a/net/http/http_cache.cc +++ b/net/http/http_cache.cc @@ -236,6 +236,7 @@ HttpCache::HttpCache(NetworkChangeNotifier* network_change_notifier, HostResolver* host_resolver, ProxyService* proxy_service, SSLConfigService* ssl_config_service, HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log, BackendFactory* backend_factory) : backend_factory_(backend_factory), temp_backend_(NULL), @@ -243,7 +244,8 @@ HttpCache::HttpCache(NetworkChangeNotifier* network_change_notifier, mode_(NORMAL), network_layer_(HttpNetworkLayer::CreateFactory( network_change_notifier, host_resolver, proxy_service, - ssl_config_service, http_auth_handler_factory)), + ssl_config_service, http_auth_handler_factory, + net_log)), ALLOW_THIS_IN_INITIALIZER_LIST(task_factory_(this)), enable_range_support_(true) { } diff --git a/net/http/http_cache.h b/net/http/http_cache.h index a55763b..79c2134 100644 --- a/net/http/http_cache.h +++ b/net/http/http_cache.h @@ -16,6 +16,7 @@ #include #include +#include #include "base/basictypes.h" #include "base/file_path.h" @@ -43,6 +44,7 @@ class HttpNetworkSession; struct HttpRequestInfo; class HttpResponseInfo; class IOBuffer; +class NetLog; class NetworkChangeNotifier; class ProxyService; class SSLConfigService; @@ -114,6 +116,7 @@ class HttpCache : public HttpTransactionFactory, HostResolver* host_resolver, ProxyService* proxy_service, SSLConfigService* ssl_config_service, HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log, BackendFactory* backend_factory); // The disk cache is initialized lazily (by CreateTransaction) in this case. diff --git a/net/http/http_network_layer.cc b/net/http/http_network_layer.cc index 87422d4..f661fde 100644 --- a/net/http/http_network_layer.cc +++ b/net/http/http_network_layer.cc @@ -25,13 +25,15 @@ HttpTransactionFactory* HttpNetworkLayer::CreateFactory( HostResolver* host_resolver, ProxyService* proxy_service, SSLConfigService* ssl_config_service, - HttpAuthHandlerFactory* http_auth_handler_factory) { + HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log) { DCHECK(proxy_service); return new HttpNetworkLayer(ClientSocketFactory::GetDefaultFactory(), network_change_notifier, host_resolver, proxy_service, ssl_config_service, - http_auth_handler_factory); + http_auth_handler_factory, + net_log); } // static @@ -51,7 +53,8 @@ HttpNetworkLayer::HttpNetworkLayer( HostResolver* host_resolver, ProxyService* proxy_service, SSLConfigService* ssl_config_service, - HttpAuthHandlerFactory* http_auth_handler_factory) + HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log) : socket_factory_(socket_factory), network_change_notifier_(network_change_notifier), host_resolver_(host_resolver), @@ -60,6 +63,7 @@ HttpNetworkLayer::HttpNetworkLayer( session_(NULL), spdy_session_pool_(NULL), http_auth_handler_factory_(http_auth_handler_factory), + net_log_(net_log), suspended_(false) { DCHECK(proxy_service_); DCHECK(ssl_config_service_.get()); @@ -72,6 +76,7 @@ HttpNetworkLayer::HttpNetworkLayer(HttpNetworkSession* session) session_(session), spdy_session_pool_(session->spdy_session_pool()), http_auth_handler_factory_(NULL), + net_log_(NULL), suspended_(false) { DCHECK(session_.get()); } @@ -108,13 +113,15 @@ HttpNetworkSession* HttpNetworkLayer::GetSession() { session_ = new HttpNetworkSession( network_change_notifier_, host_resolver_, proxy_service_, socket_factory_, ssl_config_service_, spdy_pool, - http_auth_handler_factory_); + http_auth_handler_factory_, + net_log_); // These were just temps for lazy-initializing HttpNetworkSession. network_change_notifier_ = NULL; host_resolver_ = NULL; proxy_service_ = NULL; socket_factory_ = NULL; http_auth_handler_factory_ = NULL; + net_log_ = NULL; } return session_; } diff --git a/net/http/http_network_layer.h b/net/http/http_network_layer.h index 2d4130d..a045798 100644 --- a/net/http/http_network_layer.h +++ b/net/http/http_network_layer.h @@ -17,6 +17,7 @@ class ClientSocketFactory; class HostResolver; class HttpAuthHandlerFactory; class HttpNetworkSession; +class NetLog; class NetworkChangeNotifier; class ProxyInfo; class ProxyService; @@ -31,7 +32,8 @@ class HttpNetworkLayer : public HttpTransactionFactory { NetworkChangeNotifier* network_change_notifier, HostResolver* host_resolver, ProxyService* proxy_service, SSLConfigService* ssl_config_service, - HttpAuthHandlerFactory* http_auth_handler_factory); + HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log); // Construct a HttpNetworkLayer with an existing HttpNetworkSession which // contains a valid ProxyService. explicit HttpNetworkLayer(HttpNetworkSession* session); @@ -44,7 +46,8 @@ class HttpNetworkLayer : public HttpTransactionFactory { HostResolver* host_resolver, ProxyService* proxy_service, SSLConfigService* ssl_config_service, - HttpAuthHandlerFactory* http_auth_handler_factory); + HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log); // Create a transaction factory that instantiate a network layer over an // existing network session. Network session contains some valuable // information (e.g. authentication data) that we want to share across @@ -85,6 +88,7 @@ class HttpNetworkLayer : public HttpTransactionFactory { scoped_refptr spdy_session_pool_; HttpAuthHandlerFactory* http_auth_handler_factory_; + NetLog* net_log_; bool suspended_; static bool force_spdy_; diff --git a/net/http/http_network_layer_unittest.cc b/net/http/http_network_layer_unittest.cc index 697fe98..780ab68 100644 --- a/net/http/http_network_layer_unittest.cc +++ b/net/http/http_network_layer_unittest.cc @@ -18,7 +18,7 @@ class HttpNetworkLayerTest : public PlatformTest { TEST_F(HttpNetworkLayerTest, CreateAndDestroy) { net::HttpNetworkLayer factory( NULL, NULL, new net::MockHostResolver, net::ProxyService::CreateNull(), - new net::SSLConfigServiceDefaults, NULL); + new net::SSLConfigServiceDefaults, NULL, NULL); scoped_ptr trans; int rv = factory.CreateTransaction(&trans); @@ -29,7 +29,7 @@ TEST_F(HttpNetworkLayerTest, CreateAndDestroy) { TEST_F(HttpNetworkLayerTest, Suspend) { net::HttpNetworkLayer factory( NULL, NULL, new net::MockHostResolver, net::ProxyService::CreateNull(), - new net::SSLConfigServiceDefaults, NULL); + new net::SSLConfigServiceDefaults, NULL, NULL); scoped_ptr trans; int rv = factory.CreateTransaction(&trans); @@ -71,7 +71,7 @@ TEST_F(HttpNetworkLayerTest, GET) { new net::MockHostResolver, net::ProxyService::CreateNull(), new net::SSLConfigServiceDefaults, - NULL); + NULL, NULL); TestCompletionCallback callback; diff --git a/net/http/http_network_session.cc b/net/http/http_network_session.cc index dddb223..4301a76 100644 --- a/net/http/http_network_session.cc +++ b/net/http/http_network_session.cc @@ -42,7 +42,8 @@ HttpNetworkSession::HttpNetworkSession( ClientSocketFactory* client_socket_factory, SSLConfigService* ssl_config_service, SpdySessionPool* spdy_session_pool, - HttpAuthHandlerFactory* http_auth_handler_factory) + HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log) : network_change_notifier_(network_change_notifier), // TODO(vandebo) when we've completely converted to pools, the base TCP // pool name should get changed to TCP instead of Transport. @@ -53,13 +54,15 @@ HttpNetworkSession::HttpNetworkSession( socks_pool_histograms_(new ClientSocketPoolHistograms("SOCK")), tcp_socket_pool_(new TCPClientSocketPool( g_max_sockets, g_max_sockets_per_group, tcp_pool_histograms_, - host_resolver, client_socket_factory, network_change_notifier_)), + host_resolver, client_socket_factory, network_change_notifier_, + net_log)), socket_factory_(client_socket_factory), host_resolver_(host_resolver), proxy_service_(proxy_service), ssl_config_service_(ssl_config_service), spdy_session_pool_(spdy_session_pool), - http_auth_handler_factory_(http_auth_handler_factory) { + http_auth_handler_factory_(http_auth_handler_factory), + net_log_(net_log) { DCHECK(proxy_service); DCHECK(ssl_config_service); } @@ -81,7 +84,8 @@ HttpNetworkSession::GetSocketPoolForHTTPProxy(const HostPortPair& http_proxy) { new TCPClientSocketPool( g_max_sockets_per_proxy_server, g_max_sockets_per_group, http_proxy_pool_histograms_, host_resolver_, socket_factory_, - network_change_notifier_))); + network_change_notifier_, + net_log_))); return ret.first->second; } @@ -104,8 +108,9 @@ HttpNetworkSession::GetSocketPoolForSOCKSProxy( g_max_sockets_per_group, tcp_for_socks_pool_histograms_, host_resolver_, socket_factory_, - network_change_notifier_), - network_change_notifier_))); + network_change_notifier_, + net_log_), + network_change_notifier_, net_log_))); return ret.first->second; } @@ -144,7 +149,8 @@ void HttpNetworkSession::ReplaceTCPSocketPool() { tcp_pool_histograms_, host_resolver_, socket_factory_, - network_change_notifier_); + network_change_notifier_, + net_log_); } } // namespace net diff --git a/net/http/http_network_session.h b/net/http/http_network_session.h index 5495c4b..64d302d 100644 --- a/net/http/http_network_session.h +++ b/net/http/http_network_session.h @@ -38,7 +38,8 @@ class HttpNetworkSession : public base::RefCounted { ClientSocketFactory* client_socket_factory, SSLConfigService* ssl_config_service, SpdySessionPool* spdy_session_pool, - HttpAuthHandlerFactory* http_auth_handler_factory); + HttpAuthHandlerFactory* http_auth_handler_factory, + NetLog* net_log); HttpAuthCache* auth_cache() { return &auth_cache_; } SSLClientAuthCache* ssl_client_auth_cache() { @@ -123,6 +124,7 @@ class HttpNetworkSession : public base::RefCounted { scoped_refptr ssl_config_service_; scoped_refptr spdy_session_pool_; HttpAuthHandlerFactory* http_auth_handler_factory_; + NetLog* net_log_; SpdySettingsStorage spdy_settings_; }; diff --git a/net/http/http_network_transaction_unittest.cc b/net/http/http_network_transaction_unittest.cc index 79d176f..f0c111a 100644 --- a/net/http/http_network_transaction_unittest.cc +++ b/net/http/http_network_transaction_unittest.cc @@ -114,7 +114,8 @@ HttpNetworkSession* CreateSession(SessionDependencies* session_deps) { &session_deps->socket_factory, session_deps->ssl_config_service, session_deps->spdy_session_pool, - session_deps->http_auth_handler_factory.get()); + session_deps->http_auth_handler_factory.get(), + NULL); } class HttpNetworkTransactionTest : public PlatformTest { @@ -237,9 +238,9 @@ std::string MockGetHostName() { template class CaptureGroupNameSocketPool : public EmulatedClientSocketPool { public: - CaptureGroupNameSocketPool(HttpNetworkSession* session) + explicit CaptureGroupNameSocketPool(HttpNetworkSession* session) : EmulatedClientSocketPool(0, 0, NULL, session->host_resolver(), NULL, - NULL) {} + NULL, NULL) {} const std::string last_group_name_received() const { return last_group_name_; } @@ -5589,7 +5590,7 @@ TEST_F(HttpNetworkTransactionTest, ResolveCanonicalName) { class TLSDecompressionFailureSocketDataProvider : public SocketDataProvider { public: - TLSDecompressionFailureSocketDataProvider(bool fail_all) + explicit TLSDecompressionFailureSocketDataProvider(bool fail_all) : fail_all_(fail_all) { } diff --git a/net/proxy/proxy_script_fetcher_unittest.cc b/net/proxy/proxy_script_fetcher_unittest.cc index 3a1f707..5d147b1 100644 --- a/net/proxy/proxy_script_fetcher_unittest.cc +++ b/net/proxy/proxy_script_fetcher_unittest.cc @@ -40,7 +40,7 @@ class RequestContext : public URLRequestContext { new net::HttpCache( net::HttpNetworkLayer::CreateFactory( NULL, host_resolver_, proxy_service_, ssl_config_service_, - NULL), + NULL, NULL), net::HttpCache::DefaultBackend::InMemory(0)); } diff --git a/net/socket/client_socket_handle.cc b/net/socket/client_socket_handle.cc index 5964239..4f61a68 100644 --- a/net/socket/client_socket_handle.cc +++ b/net/socket/client_socket_handle.cc @@ -33,6 +33,7 @@ void ClientSocketHandle::ResetInternal(bool cancel) { if (socket_.get()) { // Because of http://crbug.com/37810 we may not have a pool, but have // just a raw socket. + socket_->NetLog().EndEvent(NetLog::TYPE_SOCKET_IN_USE, NULL); if (pool_) // If we've still got a socket, release it back to the ClientSocketPool so // it can be deleted or reused. @@ -92,6 +93,15 @@ void ClientSocketHandle::HandleInitCompletion(int result) { NOTREACHED(); break; } + + // Broadcast that the socket has been acquired. + // TODO(eroman): This logging is not complete, in particular set_socket() and + // release() socket. It ends up working though, since those methods are being + // used to layer sockets (and the destination sources are the same). + DCHECK(socket_.get()); + socket_->NetLog().BeginEvent( + NetLog::TYPE_SOCKET_IN_USE, + new NetLogSourceParameter("source_dependency", requesting_source_)); } } // namespace net diff --git a/net/socket/client_socket_handle.h b/net/socket/client_socket_handle.h index f750c7b..4b36e58 100644 --- a/net/socket/client_socket_handle.h +++ b/net/socket/client_socket_handle.h @@ -14,6 +14,7 @@ #include "net/base/completion_callback.h" #include "net/base/load_states.h" #include "net/base/net_errors.h" +#include "net/base/net_log.h" #include "net/base/request_priority.h" #include "net/socket/client_socket.h" #include "net/socket/client_socket_pool.h" @@ -144,6 +145,8 @@ class ClientSocketHandle { base::TimeTicks init_time_; base::TimeDelta setup_time_; + NetLog::Source requesting_source_; + DISALLOW_COPY_AND_ASSIGN(ClientSocketHandle); }; @@ -155,6 +158,8 @@ int ClientSocketHandle::Init(const std::string& group_name, CompletionCallback* callback, const scoped_refptr& pool, const BoundNetLog& net_log) { + requesting_source_ = net_log.source(); + CHECK(!group_name.empty()); // Note that this will result in a link error if the SocketParams has not been // registered for the PoolType via REGISTER_SOCKET_PARAMS_FOR_POOL (defined in diff --git a/net/socket/client_socket_pool_base.cc b/net/socket/client_socket_pool_base.cc index 99011be..ddaa430 100644 --- a/net/socket/client_socket_pool_base.cc +++ b/net/socket/client_socket_pool_base.cc @@ -42,42 +42,46 @@ ConnectJob::ConnectJob(const std::string& group_name, idle_(true) { DCHECK(!group_name.empty()); DCHECK(delegate); + net_log.BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL); } ConnectJob::~ConnectJob() { - if (delegate_ && !idle_) { - // If the delegate was not NULLed, then NotifyDelegateOfCompletion has - // not been called yet. If we've started then we are cancelling. - net_log_.AddEvent(NetLog::TYPE_CANCELLED, NULL); - net_log_.EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL); - } + net_log().EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL); } int ConnectJob::Connect() { if (timeout_duration_ != base::TimeDelta()) timer_.Start(timeout_duration_, this, &ConnectJob::OnTimeout); - net_log_.BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, - new NetLogStringParameter("group_name", group_name_)); idle_ = false; + LogConnectStart(); + int rv = ConnectInternal(); if (rv != ERR_IO_PENDING) { + LogConnectCompletion(rv); delegate_ = NULL; - net_log_.EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL); } return rv; } +void ConnectJob::set_socket(ClientSocket* socket) { + if (socket) { + net_log().AddEvent(NetLog::TYPE_CONNECT_JOB_SET_SOCKET, + new NetLogSourceParameter("source_dependency", + socket->NetLog().source())); + } + socket_.reset(socket); +} + void ConnectJob::NotifyDelegateOfCompletion(int rv) { // The delegate will delete |this|. Delegate *delegate = delegate_; delegate_ = NULL; - net_log_.EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL); - + LogConnectCompletion(rv); delegate->OnConnectJobComplete(rv, this); } @@ -86,6 +90,18 @@ void ConnectJob::ResetTimer(base::TimeDelta remaining_time) { timer_.Start(remaining_time, this, &ConnectJob::OnTimeout); } +void ConnectJob::LogConnectStart() { + net_log().BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT, + new NetLogStringParameter("group_name", group_name_)); +} + +void ConnectJob::LogConnectCompletion(int net_error) { + scoped_refptr params; + if (net_error != OK) + params = new NetLogIntegerParameter("net_error", net_error); + net_log().EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT, params); +} + void ConnectJob::OnTimeout() { // Make sure the socket is NULL before calling into |delegate|. set_socket(NULL); @@ -236,21 +252,12 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal( } // We couldn't find a socket to reuse, so allocate and connect a new one. - BoundNetLog job_net_log = BoundNetLog::Make( - request->net_log().net_log(), NetLog::SOURCE_CONNECT_JOB); - request->net_log().BeginEvent( - NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID, - new NetLogIntegerParameter("source_id", job_net_log.source().id)); - scoped_ptr connect_job( - connect_job_factory_->NewConnectJob(group_name, *request, this, - job_net_log)); + connect_job_factory_->NewConnectJob(group_name, *request, this)); int rv = connect_job->Connect(); if (rv == OK) { - request->net_log().EndEvent( - NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID, - new NetLogIntegerParameter("source_id", job_net_log.source().id)); + LogBoundConnectJobToRequest(connect_job->net_log().source(), request); HandOutSocket(connect_job->ReleaseSocket(), false /* not reused */, handle, base::TimeDelta(), &group, request->net_log()); } else if (rv == ERR_IO_PENDING) { @@ -260,8 +267,7 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal( if (group.IsEmpty() && !group.backup_job && backup_jobs_enabled_) { group.backup_job = connect_job_factory_->NewConnectJob(group_name, *request, - this, - job_net_log); + this); StartBackupSocketTimer(group_name); } @@ -270,9 +276,7 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal( ConnectJob* job = connect_job.release(); group.jobs.insert(job); } else { - request->net_log().EndEvent( - NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID, - new NetLogIntegerParameter("source_id", job_net_log.source().id)); + LogBoundConnectJobToRequest(connect_job->net_log().source(), request); if (group.IsEmpty()) group_map_.erase(group_name); } @@ -280,6 +284,14 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal( return rv; } +// static +void ClientSocketPoolBaseHelper::LogBoundConnectJobToRequest( + const NetLog::Source& connect_job_source, const Request* request) { + request->net_log().AddEvent( + NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB, + new NetLogSourceParameter("source_dependency", connect_job_source)); +} + void ClientSocketPoolBaseHelper::StartBackupSocketTimer( const std::string& group_name) { CHECK(ContainsKey(group_map_, group_name)); @@ -312,8 +324,6 @@ void ClientSocketPoolBaseHelper::OnBackupSocketTimerFired( if (ReachedMaxSocketsLimit() || !group.HasAvailableSocketSlot(max_sockets_per_group_) || (*group.jobs.begin())->GetLoadState() == LOAD_STATE_RESOLVING_HOST) { - group.backup_job->net_log().AddEvent( - NetLog::TYPE_SOCKET_BACKUP_TIMER_EXTENDED, NULL); StartBackupSocketTimer(group_name); return; } @@ -583,13 +593,11 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete( if (!group.pending_requests.empty()) { scoped_ptr r(RemoveRequestFromQueue( group.pending_requests.begin(), &group.pending_requests)); - r->net_log().EndEvent( - NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID, - new NetLogIntegerParameter("source_id", job_log.source().id)); - r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL); + LogBoundConnectJobToRequest(job_log.source(), r.get()); HandOutSocket( socket.release(), false /* unused socket */, r->handle(), base::TimeDelta(), &group, r->net_log()); + r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL); r->callback()->Run(result); } else { AddIdleSocket(socket.release(), false /* unused socket */, &group); @@ -600,10 +608,9 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete( if (!group.pending_requests.empty()) { scoped_ptr r(RemoveRequestFromQueue( group.pending_requests.begin(), &group.pending_requests)); - r->net_log().EndEvent( - NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID, - new NetLogIntegerParameter("source_id", job_log.source().id)); - r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL); + LogBoundConnectJobToRequest(job_log.source(), r.get()); + r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, + new NetLogIntegerParameter("net_error", result)); r->callback()->Run(result); } MaybeOnAvailableSocketSlot(group_name); @@ -667,7 +674,11 @@ void ClientSocketPoolBaseHelper::ProcessPendingRequest( if (rv != ERR_IO_PENDING) { scoped_ptr r(RemoveRequestFromQueue( group->pending_requests.begin(), &group->pending_requests)); - r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL); + + scoped_refptr params; + if (rv != OK) + params = new NetLogIntegerParameter("net_error", rv); + r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, params); r->callback()->Run(rv); if (rv != OK) { // |group| may be invalid after the callback, we need to search @@ -696,9 +707,9 @@ void ClientSocketPoolBaseHelper::HandOutSocket( "idle_ms", static_cast(idle_time.InMilliseconds()))); } - net_log.AddEvent(NetLog::TYPE_SOCKET_POOL_SOCKET_ID, - new NetLogIntegerParameter( - "source_id", socket->NetLog().source().id)); + net_log.AddEvent(NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET, + new NetLogSourceParameter( + "source_dependency", socket->NetLog().source())); handed_out_socket_count_++; group->active_socket_count++; diff --git a/net/socket/client_socket_pool_base.h b/net/socket/client_socket_pool_base.h index db408a2..470c120 100644 --- a/net/socket/client_socket_pool_base.h +++ b/net/socket/client_socket_pool_base.h @@ -91,7 +91,7 @@ class ConnectJob { virtual LoadState GetLoadState() const = 0; protected: - void set_socket(ClientSocket* socket) { socket_.reset(socket); } + void set_socket(ClientSocket* socket); ClientSocket* socket() { return socket_.get(); } void NotifyDelegateOfCompletion(int rv); void ResetTimer(base::TimeDelta remainingTime); @@ -99,6 +99,9 @@ class ConnectJob { private: virtual int ConnectInternal() = 0; + void LogConnectStart(); + void LogConnectCompletion(int net_error); + // Alerts the delegate that the ConnectJob has timed out. void OnTimeout(); @@ -158,8 +161,7 @@ class ClientSocketPoolBaseHelper virtual ConnectJob* NewConnectJob( const std::string& group_name, const Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const = 0; + ConnectJob::Delegate* delegate) const = 0; virtual base::TimeDelta ConnectionTimeout() const = 0; @@ -231,7 +233,7 @@ class ClientSocketPoolBaseHelper return connect_job_factory_->ConnectionTimeout(); } - void enable_backup_jobs() { backup_jobs_enabled_ = true; }; + void enable_backup_jobs() { backup_jobs_enabled_ = true; } private: friend class base::RefCounted; @@ -387,6 +389,9 @@ class ClientSocketPoolBaseHelper int RequestSocketInternal(const std::string& group_name, const Request* request); + static void LogBoundConnectJobToRequest( + const NetLog::Source& connect_job_source, const Request* request); + // Set a timer to create a backup socket if it takes too long to create one. void StartBackupSocketTimer(const std::string& group_name); @@ -486,8 +491,7 @@ class ClientSocketPoolBase { virtual ConnectJob* NewConnectJob( const std::string& group_name, const Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const = 0; + ConnectJob::Delegate* delegate) const = 0; virtual base::TimeDelta ConnectionTimeout() const = 0; @@ -580,7 +584,7 @@ class ClientSocketPoolBase { return histograms_; } - void enable_backup_jobs() { helper_->enable_backup_jobs(); }; + void enable_backup_jobs() { helper_->enable_backup_jobs(); } private: // This adaptor class exists to bridge the @@ -602,11 +606,10 @@ class ClientSocketPoolBase { virtual ConnectJob* NewConnectJob( const std::string& group_name, const internal::ClientSocketPoolBaseHelper::Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const { + ConnectJob::Delegate* delegate) const { const Request* casted_request = static_cast(&request); return connect_job_factory_->NewConnectJob( - group_name, *casted_request, delegate, net_log); + group_name, *casted_request, delegate); } virtual base::TimeDelta ConnectionTimeout() const { diff --git a/net/socket/client_socket_pool_base_unittest.cc b/net/socket/client_socket_pool_base_unittest.cc index b33da2e..bf0f96e 100644 --- a/net/socket/client_socket_pool_base_unittest.cc +++ b/net/socket/client_socket_pool_base_unittest.cc @@ -46,8 +46,8 @@ class MockClientSocket : public ClientSocket { IOBuffer* /* buf */, int /* len */, CompletionCallback* /* callback */) { return ERR_UNEXPECTED; } - virtual bool SetReceiveBufferSize(int32 size) { return true; }; - virtual bool SetSendBufferSize(int32 size) { return true; }; + virtual bool SetReceiveBufferSize(int32 size) { return true; } + virtual bool SetSendBufferSize(int32 size) { return true; } // ClientSocket methods: @@ -122,8 +122,9 @@ class TestConnectJob : public ConnectJob { base::TimeDelta timeout_duration, ConnectJob::Delegate* delegate, MockClientSocketFactory* client_socket_factory, - const BoundNetLog& net_log) - : ConnectJob(group_name, timeout_duration, delegate, net_log), + NetLog* net_log) + : ConnectJob(group_name, timeout_duration, delegate, + BoundNetLog::Make(net_log, NetLog::SOURCE_CONNECT_JOB)), job_type_(job_type), client_socket_factory_(client_socket_factory), method_factory_(ALLOW_THIS_IN_INITIALIZER_LIST(this)), @@ -255,15 +256,14 @@ class TestConnectJobFactory virtual ConnectJob* NewConnectJob( const std::string& group_name, const TestClientSocketPoolBase::Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const { + ConnectJob::Delegate* delegate) const { return new TestConnectJob(job_type_, group_name, request, timeout_duration_, delegate, client_socket_factory_, - net_log); + NULL); } virtual base::TimeDelta ConnectionTimeout() const { @@ -484,14 +484,14 @@ TEST_F(ClientSocketPoolBaseTest, ConnectJob_NoTimeoutOnSynchronousCompletion) { base::TimeDelta::FromMicroseconds(1), &delegate, &client_socket_factory_, - BoundNetLog())); + NULL)); EXPECT_EQ(OK, job->Connect()); } TEST_F(ClientSocketPoolBaseTest, ConnectJob_TimedOut) { TestConnectJobDelegate delegate; ClientSocketHandle ignored; - CapturingBoundNetLog log(CapturingNetLog::kUnbounded); + CapturingNetLog log(CapturingNetLog::kUnbounded); TestClientSocketPoolBase::Request request( &ignored, NULL, kDefaultPriority, NULL, BoundNetLog()); @@ -503,19 +503,26 @@ TEST_F(ClientSocketPoolBaseTest, ConnectJob_TimedOut) { base::TimeDelta::FromMicroseconds(1), &delegate, &client_socket_factory_, - log.bound()); + &log); ASSERT_EQ(ERR_IO_PENDING, job->Connect()); PlatformThread::Sleep(1); EXPECT_EQ(ERR_TIMED_OUT, delegate.WaitForResult()); - EXPECT_EQ(3u, log.entries().size()); + EXPECT_EQ(6u, log.entries().size()); EXPECT_TRUE(LogContainsBeginEvent( log.entries(), 0, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); + EXPECT_TRUE(LogContainsBeginEvent( + log.entries(), 1, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT)); + EXPECT_TRUE(LogContainsEvent( + log.entries(), 2, NetLog::TYPE_CONNECT_JOB_SET_SOCKET, + NetLog::PHASE_NONE)); EXPECT_TRUE(LogContainsEvent( - log.entries(), 1, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT, + log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT, NetLog::PHASE_NONE)); EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); + log.entries(), 4, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT)); + EXPECT_TRUE(LogContainsEndEvent( + log.entries(), 5, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); } TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) { @@ -531,22 +538,17 @@ TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) { EXPECT_TRUE(handle.socket()); handle.Reset(); - EXPECT_EQ(7u, log.entries().size()); + EXPECT_EQ(4u, log.entries().size()); EXPECT_TRUE(LogContainsBeginEvent( log.entries(), 0, NetLog::TYPE_SOCKET_POOL)); - EXPECT_TRUE(LogContainsBeginEvent( - log.entries(), 1, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID)); - EXPECT_TRUE(LogContainsBeginEvent( - log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); - EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); - EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 4, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID)); EXPECT_TRUE(LogContainsEvent( - log.entries(), 5, NetLog::TYPE_SOCKET_POOL_SOCKET_ID, + log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB, + NetLog::PHASE_NONE)); + EXPECT_TRUE(LogContainsEvent( + log.entries(), 2, NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET, NetLog::PHASE_NONE)); EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 6, NetLog::TYPE_SOCKET_POOL)); + log.entries(), 3, NetLog::TYPE_SOCKET_POOL)); } TEST_F(ClientSocketPoolBaseTest, InitConnectionFailure) { @@ -560,14 +562,14 @@ TEST_F(ClientSocketPoolBaseTest, InitConnectionFailure) { InitHandle(req.handle(), "a", kDefaultPriority, &req, pool_, log.bound())); - EXPECT_EQ(6u, log.entries().size()); + EXPECT_EQ(3u, log.entries().size()); EXPECT_TRUE(LogContainsBeginEvent( log.entries(), 0, NetLog::TYPE_SOCKET_POOL)); - EXPECT_TRUE(LogContainsBeginEvent( - log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); + EXPECT_TRUE(LogContainsEvent( + log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB, + NetLog::PHASE_NONE)); EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); - EXPECT_TRUE(LogContainsEndEvent(log.entries(), 5, NetLog::TYPE_SOCKET_POOL)); + log.entries(), 2, NetLog::TYPE_SOCKET_POOL)); } TEST_F(ClientSocketPoolBaseTest, TotalLimit) { @@ -1205,15 +1207,17 @@ TEST_F(ClientSocketPoolBaseTest, BasicAsynchronous) { EXPECT_TRUE(req.handle()->socket()); req.handle()->Reset(); - EXPECT_EQ(7u, log.entries().size()); + EXPECT_EQ(4u, log.entries().size()); EXPECT_TRUE(LogContainsBeginEvent( log.entries(), 0, NetLog::TYPE_SOCKET_POOL)); - EXPECT_TRUE(LogContainsBeginEvent( - log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); - EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); + EXPECT_TRUE(LogContainsEvent( + log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB, + NetLog::PHASE_NONE)); + EXPECT_TRUE(LogContainsEvent( + log.entries(), 2, NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET, + NetLog::PHASE_NONE)); EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 5, NetLog::TYPE_SOCKET_POOL)); + log.entries(), 3, NetLog::TYPE_SOCKET_POOL)); } TEST_F(ClientSocketPoolBaseTest, @@ -1229,15 +1233,14 @@ TEST_F(ClientSocketPoolBaseTest, EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", req.handle())); EXPECT_EQ(ERR_CONNECTION_FAILED, req.WaitForResult()); - EXPECT_EQ(6u, log.entries().size()); + EXPECT_EQ(3u, log.entries().size()); EXPECT_TRUE(LogContainsBeginEvent( log.entries(), 0, NetLog::TYPE_SOCKET_POOL)); - EXPECT_TRUE(LogContainsBeginEvent( - log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); - EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB)); + EXPECT_TRUE(LogContainsEvent( + log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB, + NetLog::PHASE_NONE)); EXPECT_TRUE(LogContainsEndEvent( - log.entries(), 5, NetLog::TYPE_SOCKET_POOL)); + log.entries(), 2, NetLog::TYPE_SOCKET_POOL)); } TEST_F(ClientSocketPoolBaseTest, TwoRequestsCancelOne) { diff --git a/net/socket/socks_client_socket_pool.cc b/net/socket/socks_client_socket_pool.cc index 452ce25..4c446ab 100644 --- a/net/socket/socks_client_socket_pool.cc +++ b/net/socket/socks_client_socket_pool.cc @@ -26,13 +26,15 @@ SOCKSConnectJob::SOCKSConnectJob( const scoped_refptr& tcp_pool, const scoped_refptr& host_resolver, Delegate* delegate, - const BoundNetLog& net_log) - : ConnectJob(group_name, timeout_duration, delegate, net_log), + NetLog* net_log) + : ConnectJob(group_name, timeout_duration, delegate, + BoundNetLog::Make(net_log, NetLog::SOURCE_CONNECT_JOB)), socks_params_(socks_params), tcp_pool_(tcp_pool), resolver_(host_resolver), ALLOW_THIS_IN_INITIALIZER_LIST( - callback_(this, &SOCKSConnectJob::OnIOComplete)) {} + callback_(this, &SOCKSConnectJob::OnIOComplete)) { +} SOCKSConnectJob::~SOCKSConnectJob() { // We don't worry about cancelling the tcp socket since the destructor in @@ -144,10 +146,9 @@ int SOCKSConnectJob::DoSOCKSConnectComplete(int result) { ConnectJob* SOCKSClientSocketPool::SOCKSConnectJobFactory::NewConnectJob( const std::string& group_name, const PoolBase::Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const { + ConnectJob::Delegate* delegate) const { return new SOCKSConnectJob(group_name, request.params(), ConnectionTimeout(), - tcp_pool_, host_resolver_, delegate, net_log); + tcp_pool_, host_resolver_, delegate, net_log_); } base::TimeDelta @@ -162,11 +163,12 @@ SOCKSClientSocketPool::SOCKSClientSocketPool( const scoped_refptr& histograms, const scoped_refptr& host_resolver, const scoped_refptr& tcp_pool, - NetworkChangeNotifier* network_change_notifier) + NetworkChangeNotifier* network_change_notifier, + NetLog* net_log) : base_(max_sockets, max_sockets_per_group, histograms, base::TimeDelta::FromSeconds(kUnusedIdleSocketTimeout), base::TimeDelta::FromSeconds(kUsedIdleSocketTimeout), - new SOCKSConnectJobFactory(tcp_pool, host_resolver), + new SOCKSConnectJobFactory(tcp_pool, host_resolver, net_log), network_change_notifier) {} SOCKSClientSocketPool::~SOCKSClientSocketPool() {} diff --git a/net/socket/socks_client_socket_pool.h b/net/socket/socks_client_socket_pool.h index ea162245..bd975ba 100644 --- a/net/socket/socks_client_socket_pool.h +++ b/net/socket/socks_client_socket_pool.h @@ -41,7 +41,7 @@ class SOCKSSocketParams { const TCPSocketParams& tcp_params() const { return tcp_params_; } const HostResolver::RequestInfo& destination() const { return destination_; } - bool is_socks_v5() const { return socks_v5_; }; + bool is_socks_v5() const { return socks_v5_; } private: // The tcp connection must point toward the proxy server. @@ -61,7 +61,7 @@ class SOCKSConnectJob : public ConnectJob { const scoped_refptr& tcp_pool, const scoped_refptr &host_resolver, Delegate* delegate, - const BoundNetLog& net_log); + NetLog* net_log); virtual ~SOCKSConnectJob(); // ConnectJob methods. @@ -111,7 +111,8 @@ class SOCKSClientSocketPool : public ClientSocketPool { const scoped_refptr& histograms, const scoped_refptr& host_resolver, const scoped_refptr& tcp_pool, - NetworkChangeNotifier* network_change_notifier); + NetworkChangeNotifier* network_change_notifier, + NetLog* net_log); // ClientSocketPool methods: virtual int RequestSocket(const std::string& group_name, @@ -155,9 +156,11 @@ class SOCKSClientSocketPool : public ClientSocketPool { class SOCKSConnectJobFactory : public PoolBase::ConnectJobFactory { public: SOCKSConnectJobFactory(const scoped_refptr& tcp_pool, - HostResolver* host_resolver) + HostResolver* host_resolver, + NetLog* net_log) : tcp_pool_(tcp_pool), - host_resolver_(host_resolver) {} + host_resolver_(host_resolver), + net_log_(net_log) {} virtual ~SOCKSConnectJobFactory() {} @@ -165,14 +168,14 @@ class SOCKSClientSocketPool : public ClientSocketPool { virtual ConnectJob* NewConnectJob( const std::string& group_name, const PoolBase::Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const; + ConnectJob::Delegate* delegate) const; virtual base::TimeDelta ConnectionTimeout() const; private: const scoped_refptr tcp_pool_; const scoped_refptr host_resolver_; + NetLog* net_log_; DISALLOW_COPY_AND_ASSIGN(SOCKSConnectJobFactory); }; diff --git a/net/socket/socks_client_socket_pool_unittest.cc b/net/socket/socks_client_socket_pool_unittest.cc index 27cb027..33bc146 100644 --- a/net/socket/socks_client_socket_pool_unittest.cc +++ b/net/socket/socks_client_socket_pool_unittest.cc @@ -87,7 +87,7 @@ class MockTCPClientSocketPool : public TCPClientSocketPool { ClientSocketFactory* socket_factory, NetworkChangeNotifier* network_change_notifier) : TCPClientSocketPool(max_sockets, max_sockets_per_group, histograms, - NULL, NULL, network_change_notifier), + NULL, NULL, network_change_notifier, NULL), client_socket_factory_(socket_factory), release_count_(0), cancel_count_(0) {} @@ -180,7 +180,7 @@ class SOCKSClientSocketPoolTest : public ClientSocketPoolTest { socks_histograms_(new ClientSocketPoolHistograms("SOCKSUnitTest")), pool_(new SOCKSClientSocketPool( kMaxSockets, kMaxSocketsPerGroup, socks_histograms_, NULL, - tcp_socket_pool_, &socks_notifier_)) { + tcp_socket_pool_, &socks_notifier_, NULL)) { } int StartRequest(const std::string& group_name, RequestPriority priority) { diff --git a/net/socket/ssl_client_socket_unittest.cc b/net/socket/ssl_client_socket_unittest.cc index 415cb83..7eec8fa 100644 --- a/net/socket/ssl_client_socket_unittest.cc +++ b/net/socket/ssl_client_socket_unittest.cc @@ -84,7 +84,7 @@ TEST_F(SSLClientSocketTest, Connect) { rv = sock->Connect(&callback); EXPECT_TRUE(net::LogContainsBeginEvent( - log.entries(), 4, net::NetLog::TYPE_SSL_CONNECT)); + log.entries(), 5, net::NetLog::TYPE_SSL_CONNECT)); if (rv != net::OK) { ASSERT_EQ(net::ERR_IO_PENDING, rv); EXPECT_FALSE(sock->IsConnected()); @@ -128,7 +128,7 @@ TEST_F(SSLClientSocketTest, ConnectExpired) { rv = sock->Connect(&callback); EXPECT_TRUE(net::LogContainsBeginEvent( - log.entries(), 4, net::NetLog::TYPE_SSL_CONNECT)); + log.entries(), 5, net::NetLog::TYPE_SSL_CONNECT)); if (rv != net::OK) { ASSERT_EQ(net::ERR_IO_PENDING, rv); EXPECT_FALSE(sock->IsConnected()); @@ -174,7 +174,7 @@ TEST_F(SSLClientSocketTest, ConnectMismatched) { rv = sock->Connect(&callback); EXPECT_TRUE(net::LogContainsBeginEvent( - log.entries(), 4, net::NetLog::TYPE_SSL_CONNECT)); + log.entries(), 5, net::NetLog::TYPE_SSL_CONNECT)); if (rv != net::ERR_CERT_COMMON_NAME_INVALID) { ASSERT_EQ(net::ERR_IO_PENDING, rv); EXPECT_FALSE(sock->IsConnected()); diff --git a/net/socket/tcp_client_socket_libevent.cc b/net/socket/tcp_client_socket_libevent.cc index 93f2333..81c3ccd 100644 --- a/net/socket/tcp_client_socket_libevent.cc +++ b/net/socket/tcp_client_socket_libevent.cc @@ -110,11 +110,12 @@ TCPClientSocketLibevent::TCPClientSocketLibevent(const AddressList& addresses, next_connect_state_(CONNECT_STATE_NONE), connect_os_error_(0), net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) { + net_log_.BeginEvent(NetLog::TYPE_SOCKET_ALIVE, NULL); } TCPClientSocketLibevent::~TCPClientSocketLibevent() { Disconnect(); - net_log_.AddEvent(NetLog::TYPE_TCP_SOCKET_DONE, NULL); + net_log_.EndEvent(NetLog::TYPE_SOCKET_ALIVE, NULL); } int TCPClientSocketLibevent::Connect(CompletionCallback* callback) { diff --git a/net/socket/tcp_client_socket_pool.cc b/net/socket/tcp_client_socket_pool.cc index 833b36e..0f2c079 100644 --- a/net/socket/tcp_client_socket_pool.cc +++ b/net/socket/tcp_client_socket_pool.cc @@ -29,7 +29,7 @@ namespace net { // timeout. Even worse, the per-connect timeout threshold varies greatly // between systems (anywhere from 20 seconds to 190 seconds). // See comment #12 at http://crbug.com/23364 for specifics. -static const int kTCPConnectJobTimeoutInSeconds = 240; // 4 minutes. +static const int kTCPConnectJobTimeoutInSeconds = 240; // 4 minutes. TCPConnectJob::TCPConnectJob( const std::string& group_name, @@ -38,8 +38,9 @@ TCPConnectJob::TCPConnectJob( ClientSocketFactory* client_socket_factory, HostResolver* host_resolver, Delegate* delegate, - const BoundNetLog& net_log) - : ConnectJob(group_name, timeout_duration, delegate, net_log), + NetLog* net_log) + : ConnectJob(group_name, timeout_duration, delegate, + BoundNetLog::Make(net_log, NetLog::SOURCE_CONNECT_JOB)), params_(params), client_socket_factory_(client_socket_factory), ALLOW_THIS_IN_INITIALIZER_LIST( @@ -160,11 +161,10 @@ int TCPConnectJob::DoTCPConnectComplete(int result) { ConnectJob* TCPClientSocketPool::TCPConnectJobFactory::NewConnectJob( const std::string& group_name, const PoolBase::Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const { + ConnectJob::Delegate* delegate) const { return new TCPConnectJob(group_name, request.params(), ConnectionTimeout(), client_socket_factory_, host_resolver_, delegate, - net_log); + net_log_); } base::TimeDelta @@ -178,11 +178,13 @@ TCPClientSocketPool::TCPClientSocketPool( const scoped_refptr& histograms, HostResolver* host_resolver, ClientSocketFactory* client_socket_factory, - NetworkChangeNotifier* network_change_notifier) + NetworkChangeNotifier* network_change_notifier, + NetLog* net_log) : base_(max_sockets, max_sockets_per_group, histograms, base::TimeDelta::FromSeconds(kUnusedIdleSocketTimeout), base::TimeDelta::FromSeconds(kUsedIdleSocketTimeout), - new TCPConnectJobFactory(client_socket_factory, host_resolver), + new TCPConnectJobFactory(client_socket_factory, + host_resolver, net_log), network_change_notifier) { base_.enable_backup_jobs(); } diff --git a/net/socket/tcp_client_socket_pool.h b/net/socket/tcp_client_socket_pool.h index 355bd2a..ea2ef70 100644 --- a/net/socket/tcp_client_socket_pool.h +++ b/net/socket/tcp_client_socket_pool.h @@ -64,7 +64,7 @@ class TCPConnectJob : public ConnectJob { ClientSocketFactory* client_socket_factory, HostResolver* host_resolver, Delegate* delegate, - const BoundNetLog& net_log); + NetLog* net_log); virtual ~TCPConnectJob(); // ConnectJob methods. @@ -118,7 +118,8 @@ class TCPClientSocketPool : public ClientSocketPool { const scoped_refptr& histograms, HostResolver* host_resolver, ClientSocketFactory* client_socket_factory, - NetworkChangeNotifier* network_change_notifier); + NetworkChangeNotifier* network_change_notifier, + NetLog* net_log); // ClientSocketPool methods: @@ -164,9 +165,11 @@ class TCPClientSocketPool : public ClientSocketPool { : public PoolBase::ConnectJobFactory { public: TCPConnectJobFactory(ClientSocketFactory* client_socket_factory, - HostResolver* host_resolver) + HostResolver* host_resolver, + NetLog* net_log) : client_socket_factory_(client_socket_factory), - host_resolver_(host_resolver) {} + host_resolver_(host_resolver), + net_log_(net_log) {} virtual ~TCPConnectJobFactory() {} @@ -175,14 +178,14 @@ class TCPClientSocketPool : public ClientSocketPool { virtual ConnectJob* NewConnectJob( const std::string& group_name, const PoolBase::Request& request, - ConnectJob::Delegate* delegate, - const BoundNetLog& net_log) const; + ConnectJob::Delegate* delegate) const; virtual base::TimeDelta ConnectionTimeout() const; private: ClientSocketFactory* const client_socket_factory_; const scoped_refptr host_resolver_; + NetLog* net_log_; DISALLOW_COPY_AND_ASSIGN(TCPConnectJobFactory); }; diff --git a/net/socket/tcp_client_socket_pool_unittest.cc b/net/socket/tcp_client_socket_pool_unittest.cc index e0dc09f..25e7fdd 100644 --- a/net/socket/tcp_client_socket_pool_unittest.cc +++ b/net/socket/tcp_client_socket_pool_unittest.cc @@ -272,7 +272,8 @@ class TCPClientSocketPoolTest : public ClientSocketPoolTest { histograms_, host_resolver_, &client_socket_factory_, - ¬ifier_)) { + ¬ifier_, + NULL)) { } int StartRequest(const std::string& group_name, RequestPriority priority) { @@ -746,6 +747,7 @@ TEST_F(TCPClientSocketPoolTest, BackupSocketConnect) { histograms_, host_resolver_, &client_socket_factory_, + NULL, NULL); } } diff --git a/net/socket/tcp_client_socket_unittest.cc b/net/socket/tcp_client_socket_unittest.cc index 0c16010..a2b584a 100644 --- a/net/socket/tcp_client_socket_unittest.cc +++ b/net/socket/tcp_client_socket_unittest.cc @@ -102,12 +102,11 @@ TEST_F(TCPClientSocketTest, Connect) { int rv = sock_->Connect(&callback); EXPECT_TRUE(net::LogContainsBeginEvent( - net_log_.entries(), 0, net::NetLog::TYPE_TCP_CONNECT)); + net_log_.entries(), 0, net::NetLog::TYPE_SOCKET_ALIVE)); + EXPECT_TRUE(net::LogContainsBeginEvent( + net_log_.entries(), 1, net::NetLog::TYPE_TCP_CONNECT)); if (rv != OK) { ASSERT_EQ(rv, ERR_IO_PENDING); - EXPECT_FALSE(net::LogContainsEndEvent( - net_log_.entries(), -1, net::NetLog::TYPE_TCP_CONNECT)); - rv = callback.WaitForResult(); EXPECT_EQ(rv, OK); } diff --git a/net/socket/tcp_client_socket_win.cc b/net/socket/tcp_client_socket_win.cc index c663992..b25d07f 100644 --- a/net/socket/tcp_client_socket_win.cc +++ b/net/socket/tcp_client_socket_win.cc @@ -267,12 +267,13 @@ TCPClientSocketWin::TCPClientSocketWin(const AddressList& addresses, next_connect_state_(CONNECT_STATE_NONE), connect_os_error_(0), net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) { + net_log_.BeginEvent(NetLog::TYPE_SOCKET_ALIVE, NULL); EnsureWinsockInit(); } TCPClientSocketWin::~TCPClientSocketWin() { Disconnect(); - net_log_.AddEvent(NetLog::TYPE_TCP_SOCKET_DONE, NULL); + net_log_.EndEvent(NetLog::TYPE_SOCKET_ALIVE, NULL); } int TCPClientSocketWin::Connect(CompletionCallback* callback) { diff --git a/net/spdy/spdy_network_transaction_unittest.cc b/net/spdy/spdy_network_transaction_unittest.cc index add273b..e8278a5 100644 --- a/net/spdy/spdy_network_transaction_unittest.cc +++ b/net/spdy/spdy_network_transaction_unittest.cc @@ -87,7 +87,8 @@ HttpNetworkSession* CreateSession(SessionDependencies* session_deps) { &session_deps->socket_factory, session_deps->ssl_config_service, session_deps->spdy_session_pool, - session_deps->http_auth_handler_factory.get()); + session_deps->http_auth_handler_factory.get(), + NULL); } // Chop a frame into an array of MockWrites. diff --git a/net/spdy/spdy_session_unittest.cc b/net/spdy/spdy_session_unittest.cc index ab7b12c..d022232 100644 --- a/net/spdy/spdy_session_unittest.cc +++ b/net/spdy/spdy_session_unittest.cc @@ -55,6 +55,7 @@ HttpNetworkSession* CreateSession(SessionDependencies* session_deps) { &session_deps->socket_factory, session_deps->ssl_config_service, session_deps->spdy_session_pool, + NULL, NULL); } diff --git a/net/spdy/spdy_stream_unittest.cc b/net/spdy/spdy_stream_unittest.cc index 3da9da73..84db904 100644 --- a/net/spdy/spdy_stream_unittest.cc +++ b/net/spdy/spdy_stream_unittest.cc @@ -78,7 +78,8 @@ HttpNetworkSession* CreateSession(SessionDependencies* session_deps) { &session_deps->socket_factory, session_deps->ssl_config_service, session_deps->spdy_session_pool, - session_deps->http_auth_handler_factory.get()); + session_deps->http_auth_handler_factory.get(), + NULL); } class SpdyStreamTest : public testing::Test { diff --git a/net/tools/fetch/fetch_client.cc b/net/tools/fetch/fetch_client.cc index 5da7756..f939c2d 100644 --- a/net/tools/fetch/fetch_client.cc +++ b/net/tools/fetch/fetch_client.cc @@ -146,11 +146,13 @@ int main(int argc, char**argv) { factory = new net::HttpCache(NULL, host_resolver, proxy_service, ssl_config_service, http_auth_handler_factory.get(), + NULL, net::HttpCache::DefaultBackend::InMemory(0)); } else { factory = new net::HttpNetworkLayer( net::ClientSocketFactory::GetDefaultFactory(), NULL, host_resolver, - proxy_service, ssl_config_service, http_auth_handler_factory.get()); + proxy_service, ssl_config_service, http_auth_handler_factory.get(), + NULL); } { diff --git a/net/url_request/url_request_unittest.h b/net/url_request/url_request_unittest.h index 6f41e93..3546832 100644 --- a/net/url_request/url_request_unittest.h +++ b/net/url_request/url_request_unittest.h @@ -165,7 +165,8 @@ class TestURLRequestContext : public URLRequestContext { net::HttpNetworkLayer::CreateFactory(NULL, host_resolver_, proxy_service_, ssl_config_service_, - http_auth_handler_factory_), + http_auth_handler_factory_, + NULL), net::HttpCache::DefaultBackend::InMemory(0)); // In-memory cookie store. cookie_store_ = new net::CookieMonster(NULL, NULL); diff --git a/webkit/tools/test_shell/test_shell_request_context.cc b/webkit/tools/test_shell/test_shell_request_context.cc index a53e349..4c98f28 100644 --- a/webkit/tools/test_shell/test_shell_request_context.cc +++ b/webkit/tools/test_shell/test_shell_request_context.cc @@ -89,7 +89,7 @@ void TestShellRequestContext::Init( net::HttpCache* cache = new net::HttpCache(NULL, host_resolver_, proxy_service_, ssl_config_service_, http_auth_handler_factory_, - backend); + NULL, backend); cache->set_mode(cache_mode); http_transaction_factory_ = cache; -- cgit v1.1