// Copyright (c) 2010 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. #include "chrome/browser/net/passive_log_collector.h" #include "base/compiler_specific.h" #include "base/format_macros.h" #include "base/string_util.h" #include "net/url_request/url_request_netlog_params.h" #include "testing/gtest/include/gtest/gtest.h" namespace { typedef PassiveLogCollector::RequestTracker RequestTracker; typedef PassiveLogCollector::SourceInfoList SourceInfoList; typedef PassiveLogCollector::SocketTracker SocketTracker; typedef PassiveLogCollector::HttpStreamJobTracker HttpStreamJobTracker; using net::NetLog; const NetLog::SourceType kSourceType = NetLog::SOURCE_NONE; ChromeNetLog::Entry MakeStartLogEntryWithURL(int source_id, const std::string& url) { return ChromeNetLog::Entry( 0, NetLog::TYPE_URL_REQUEST_START_JOB, base::TimeTicks(), NetLog::Source(kSourceType, source_id), NetLog::PHASE_BEGIN, new net::URLRequestStartEventParameters(GURL(url), "GET", 0, net::LOW)); } ChromeNetLog::Entry MakeStartLogEntry(int source_id) { return MakeStartLogEntryWithURL(source_id, StringPrintf("http://req%d", source_id)); } ChromeNetLog::Entry MakeEndLogEntry(int source_id) { return ChromeNetLog::Entry( 0, NetLog::TYPE_REQUEST_ALIVE, base::TimeTicks(), NetLog::Source(kSourceType, source_id), NetLog::PHASE_END, NULL); } bool OrderBySourceID(const PassiveLogCollector::SourceInfo& a, const PassiveLogCollector::SourceInfo& b) { return a.source_id < b.source_id; } SourceInfoList GetLiveSources( const PassiveLogCollector::SourceTracker& tracker) { SourceInfoList result = tracker.GetAllDeadOrAliveSources(true); std::sort(result.begin(), result.end(), &OrderBySourceID); return result; } SourceInfoList GetDeadSources( const PassiveLogCollector::SourceTracker& tracker) { SourceInfoList result = tracker.GetAllDeadOrAliveSources(false); std::sort(result.begin(), result.end(), &OrderBySourceID); return result; } static const int kMaxNumLoadLogEntries = 1; } // namespace // Test that once the tracker contains a total maximum amount of data // (graveyard + live requests), it resets itself to avoid growing unbounded. TEST(RequestTrackerTest, DropsAfterMaximumSize) { RequestTracker tracker(NULL); // Fill the source tracker with as many sources as it can hold. for (size_t i = 0; i < RequestTracker::kMaxNumSources; ++i) tracker.OnAddEntry(MakeStartLogEntry(i)); EXPECT_EQ(RequestTracker::kMaxNumSources, GetLiveSources(tracker).size()); // Add 1 more -- this should cause it to exceed its expected peak, and // therefore reset all of its data. tracker.OnAddEntry( MakeStartLogEntry(1 + RequestTracker::kMaxNumSources)); EXPECT_EQ(1u, GetLiveSources(tracker).size()); } TEST(RequestTrackerTest, BasicBounded) { RequestTracker tracker(NULL); EXPECT_EQ(0u, GetLiveSources(tracker).size()); EXPECT_EQ(0u, GetDeadSources(tracker).size()); tracker.OnAddEntry(MakeStartLogEntry(1)); tracker.OnAddEntry(MakeStartLogEntry(2)); tracker.OnAddEntry(MakeStartLogEntry(3)); tracker.OnAddEntry(MakeStartLogEntry(4)); tracker.OnAddEntry(MakeStartLogEntry(5)); SourceInfoList live_reqs = GetLiveSources(tracker); ASSERT_EQ(5u, live_reqs.size()); EXPECT_EQ("http://req1/", live_reqs[0].GetURL()); EXPECT_EQ("http://req2/", live_reqs[1].GetURL()); EXPECT_EQ("http://req3/", live_reqs[2].GetURL()); EXPECT_EQ("http://req4/", live_reqs[3].GetURL()); EXPECT_EQ("http://req5/", live_reqs[4].GetURL()); tracker.OnAddEntry(MakeEndLogEntry(1)); tracker.OnAddEntry(MakeEndLogEntry(5)); tracker.OnAddEntry(MakeEndLogEntry(3)); ASSERT_EQ(3u, GetDeadSources(tracker).size()); live_reqs = GetLiveSources(tracker); ASSERT_EQ(2u, live_reqs.size()); EXPECT_EQ("http://req2/", live_reqs[0].GetURL()); EXPECT_EQ("http://req4/", live_reqs[1].GetURL()); } TEST(RequestTrackerTest, GraveyardBounded) { RequestTracker tracker(NULL); EXPECT_EQ(0u, GetLiveSources(tracker).size()); EXPECT_EQ(0u, GetDeadSources(tracker).size()); // Add twice as many requests as will fit in the graveyard. for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize * 2; ++i) { tracker.OnAddEntry(MakeStartLogEntry(i)); tracker.OnAddEntry(MakeEndLogEntry(i)); } EXPECT_EQ(0u, GetLiveSources(tracker).size()); // Check that only the last |kMaxGraveyardSize| requests are in-memory. SourceInfoList recent = GetDeadSources(tracker); ASSERT_EQ(RequestTracker::kMaxGraveyardSize, recent.size()); for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize; ++i) { size_t req_number = i + RequestTracker::kMaxGraveyardSize; std::string url = StringPrintf("http://req%" PRIuS "/", req_number); EXPECT_EQ(url, recent[i].GetURL()); } } // Check that we exclude "chrome://" URLs from being saved into the recent // requests list (graveyard). TEST(RequestTrackerTest, GraveyardIsFiltered) { RequestTracker tracker(NULL); // This will be excluded. std::string url1 = "chrome://dontcare/"; tracker.OnAddEntry(MakeStartLogEntryWithURL(1, url1)); tracker.OnAddEntry(MakeEndLogEntry(1)); // This will be be added to graveyard. std::string url2 = "chrome2://dontcare/"; tracker.OnAddEntry(MakeStartLogEntryWithURL(2, url2)); tracker.OnAddEntry(MakeEndLogEntry(2)); // This will be be added to graveyard. std::string url3 = "http://foo/"; tracker.OnAddEntry(MakeStartLogEntryWithURL(3, url3)); tracker.OnAddEntry(MakeEndLogEntry(3)); ASSERT_EQ(2u, GetDeadSources(tracker).size()); EXPECT_EQ(url2, GetDeadSources(tracker)[0].GetURL()); EXPECT_EQ(url3, GetDeadSources(tracker)[1].GetURL()); } TEST(SpdySessionTracker, MovesToGraveyard) { PassiveLogCollector::SpdySessionTracker tracker; EXPECT_EQ(0u, GetLiveSources(tracker).size()); EXPECT_EQ(0u, GetDeadSources(tracker).size()); ChromeNetLog::Entry begin( 0u, NetLog::TYPE_SPDY_SESSION, base::TimeTicks(), NetLog::Source(NetLog::SOURCE_SPDY_SESSION, 1), NetLog::PHASE_BEGIN, NULL); tracker.OnAddEntry(begin); EXPECT_EQ(1u, GetLiveSources(tracker).size()); EXPECT_EQ(0u, GetDeadSources(tracker).size()); ChromeNetLog::Entry end( 0u, NetLog::TYPE_SPDY_SESSION, base::TimeTicks(), NetLog::Source(NetLog::SOURCE_SPDY_SESSION, 1), NetLog::PHASE_END, NULL); tracker.OnAddEntry(end); EXPECT_EQ(0u, GetLiveSources(tracker).size()); EXPECT_EQ(1u, GetDeadSources(tracker).size()); } // Test that when a SOURCE_HTTP_STREAM_JOB is connected to a SOURCE_URL_REQUEST // (via the TYPE_HTTP_STREAM_REQUEST_BOUND_TO_JOB event), it holds a reference // to the SOURCE_HTTP_STREAM_JOB preventing it from getting deleted as long as // the SOURCE_URL_REQUEST is still around. TEST(PassiveLogCollectorTest, HoldReferenceToDependentSource) { PassiveLogCollector log; EXPECT_EQ(0u, GetLiveSources(log.url_request_tracker_).size()); EXPECT_EQ(0u, GetLiveSources(log.http_stream_job_tracker_).size()); uint32 next_id = 0; NetLog::Source stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, next_id++); NetLog::Source url_request_source(NetLog::SOURCE_URL_REQUEST, next_id++); // Start a SOURCE_HTTP_STREAM_JOB. log.OnAddEntry(NetLog::TYPE_HTTP_STREAM_JOB, base::TimeTicks(), stream_job_source, NetLog::PHASE_BEGIN, NULL); EXPECT_EQ(0u, GetLiveSources(log.url_request_tracker_).size()); EXPECT_EQ(1u, GetLiveSources(log.http_stream_job_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_HTTP_STREAM_JOB yet. ASSERT_EQ(1u, GetLiveSources(log.url_request_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetLiveSources(log.url_request_tracker_)[0]; EXPECT_EQ(0, info.reference_count); EXPECT_EQ(0u, info.dependencies.size()); } ASSERT_EQ(1u, GetLiveSources(log.http_stream_job_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetLiveSources(log.http_stream_job_tracker_)[0]; EXPECT_EQ(0, info.reference_count); EXPECT_EQ(0u, info.dependencies.size()); } // Associate the SOURCE_HTTP_STREAM_JOB with the SOURCE_URL_REQUEST. log.OnAddEntry(NetLog::TYPE_HTTP_STREAM_REQUEST_BOUND_TO_JOB, base::TimeTicks(), url_request_source, NetLog::PHASE_NONE, new net::NetLogSourceParameter("x", stream_job_source)); // Check that an associate was made -- the SOURCE_URL_REQUEST should have // added a reference to the SOURCE_HTTP_STREAM_JOB. ASSERT_EQ(1u, GetLiveSources(log.url_request_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetLiveSources(log.url_request_tracker_)[0]; EXPECT_EQ(0, info.reference_count); EXPECT_EQ(1u, info.dependencies.size()); EXPECT_EQ(stream_job_source.id, info.dependencies[0].id); } ASSERT_EQ(1u, GetLiveSources(log.http_stream_job_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetLiveSources(log.http_stream_job_tracker_)[0]; EXPECT_EQ(1, info.reference_count); EXPECT_EQ(0u, info.dependencies.size()); } // Now end both |stream_job_source| and |url_request_source|. 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_HTTP_STREAM_JOB, base::TimeTicks(), stream_job_source, NetLog::PHASE_END, NULL); // Verify that both sources are in fact dead, and that |url_request_source| // still holds a reference to |stream_job_source|. ASSERT_EQ(0u, GetLiveSources(log.url_request_tracker_).size()); ASSERT_EQ(1u, GetDeadSources(log.url_request_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetDeadSources(log.url_request_tracker_)[0]; EXPECT_EQ(0, info.reference_count); EXPECT_EQ(1u, info.dependencies.size()); EXPECT_EQ(stream_job_source.id, info.dependencies[0].id); } EXPECT_EQ(0u, GetLiveSources(log.http_stream_job_tracker_).size()); ASSERT_EQ(1u, GetDeadSources(log.http_stream_job_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetDeadSources(log.http_stream_job_tracker_)[0]; EXPECT_EQ(1, info.reference_count); EXPECT_EQ(0u, info.dependencies.size()); } // Cycle through a bunch of SOURCE_HTTP_STREAM_JOB -- if it were not // referenced, this loop will have deleted it. for (size_t i = 0; i < HttpStreamJobTracker::kMaxGraveyardSize; ++i) { log.OnAddEntry(NetLog::TYPE_HTTP_STREAM_JOB, base::TimeTicks(), NetLog::Source(NetLog::SOURCE_HTTP_STREAM_JOB, next_id++), NetLog::PHASE_END, NULL); } EXPECT_EQ(0u, GetLiveSources(log.http_stream_job_tracker_).size()); ASSERT_EQ(HttpStreamJobTracker::kMaxGraveyardSize + 1, GetDeadSources(log.http_stream_job_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetDeadSources(log.http_stream_job_tracker_)[0]; EXPECT_EQ(stream_job_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 // |url_request_source| to be freed, which in turn should release the final // reference to |stream_job_source| 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, GetLiveSources(log.url_request_tracker_).size()); EXPECT_EQ(RequestTracker::kMaxGraveyardSize, GetDeadSources(log.url_request_tracker_).size()); EXPECT_EQ(0u, GetLiveSources(log.http_stream_job_tracker_).size()); EXPECT_EQ(HttpStreamJobTracker::kMaxGraveyardSize, GetDeadSources(log.http_stream_job_tracker_).size()); } // Have a HTTP_STREAM_JOB hold a reference to a SOCKET. Then cause the SOCKET to // get evicted (by exceeding maximum sources limit). Now the HTTP_STREAM_JOB is // referencing a non-existant SOCKET. Lastly, evict the HTTP_STREAM_JOB so it // tries to drop all of its references. Make sure that in releasing its // non-existant reference it doesn't trip any DCHECKs. TEST(PassiveLogCollectorTest, HoldReferenceToDeletedSource) { PassiveLogCollector log; EXPECT_EQ(0u, GetLiveSources(log.http_stream_job_tracker_).size()); EXPECT_EQ(0u, GetLiveSources(log.socket_tracker_).size()); uint32 next_id = 0; NetLog::Source socket_source(NetLog::SOURCE_SOCKET, next_id++); NetLog::Source stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, next_id++); // Start a SOURCE_SOCKET. log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE, base::TimeTicks(), socket_source, NetLog::PHASE_BEGIN, NULL); EXPECT_EQ(0u, GetLiveSources(log.http_stream_job_tracker_).size()); EXPECT_EQ(1u, GetLiveSources(log.socket_tracker_).size()); // Start a SOURCE_HTTP_STREAM_JOB. log.OnAddEntry(NetLog::TYPE_HTTP_STREAM_JOB, base::TimeTicks(), stream_job_source, NetLog::PHASE_BEGIN, NULL); // Associate the SOURCE_SOCKET with the SOURCE_HTTP_STREAM_JOB. log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET, base::TimeTicks(), stream_job_source, NetLog::PHASE_NONE, new net::NetLogSourceParameter("x", socket_source)); // Check that an associate was made -- the SOURCE_HTTP_STREAM_JOB should have // added a reference to the SOURCE_SOCKET. ASSERT_EQ(1u, GetLiveSources(log.http_stream_job_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetLiveSources(log.http_stream_job_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, GetLiveSources(log.socket_tracker_).size()); { PassiveLogCollector::SourceInfo info = GetLiveSources(log.socket_tracker_)[0]; EXPECT_EQ(1, info.reference_count); EXPECT_EQ(0u, info.dependencies.size()); } // Add lots of sources to the socket tracker. This is just enough to cause // the tracker to reach its peak, and reset all of its data as a safeguard. for (size_t i = 0; i < SocketTracker::kMaxNumSources; ++i) { log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE, base::TimeTicks(), NetLog::Source(NetLog::SOURCE_SOCKET, next_id++), NetLog::PHASE_BEGIN, NULL); } ASSERT_EQ(1u, GetLiveSources(log.socket_tracker_).size()); // End the original request. Then saturate the graveyard with enough other // requests to cause it to be deleted. Once that source is deleted, it will // try to give up its reference to the SOCKET. However that socket_id no // longer exists -- should not DCHECK(). log.OnAddEntry(NetLog::TYPE_HTTP_STREAM_JOB, base::TimeTicks(), stream_job_source, NetLog::PHASE_END, NULL); for (size_t i = 0; i < HttpStreamJobTracker::kMaxGraveyardSize; ++i) { log.OnAddEntry(NetLog::TYPE_HTTP_STREAM_JOB, base::TimeTicks(), NetLog::Source(NetLog::SOURCE_HTTP_STREAM_JOB, next_id++), NetLog::PHASE_END, NULL); } EXPECT_EQ(HttpStreamJobTracker::kMaxGraveyardSize, GetDeadSources(log.http_stream_job_tracker_).size()); } // Regression test for http://crbug.com/58847 TEST(PassiveLogCollectorTest, ReleaseDependencyToUnreferencedSource) { PassiveLogCollector log; // If these constants are weird, the test won't be testing the right thing. EXPECT_LT(PassiveLogCollector::HttpStreamJobTracker::kMaxGraveyardSize, PassiveLogCollector::HttpStreamJobTracker::kMaxNumSources); // Add a "reference" to a non-existant source (sourceID=1263 does not exist). scoped_refptr<net::NetLog::EventParameters> params = new net::NetLogSourceParameter( "source_dependency", net::NetLog::Source(net::NetLog::SOURCE_SOCKET, 1263)); log.OnAddEntry(net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET, base::TimeTicks(), net::NetLog::Source(net::NetLog::SOURCE_HTTP_STREAM_JOB, 1706), net::NetLog::PHASE_NONE, params); // At this point source 1706 has noted 1263 as a dependency. However the // reference count for 1263 was not adjusted since it doesn't actually exist. // Move source 1706 to the graveyard. log.OnAddEntry(net::NetLog::TYPE_HTTP_STREAM_JOB, base::TimeTicks(), net::NetLog::Source(net::NetLog::SOURCE_HTTP_STREAM_JOB, 1706), net::NetLog::PHASE_END, NULL); // Now create a source entry for 1263, such that it is unreferenced and // waiting to be garbage collected. log.OnAddEntry(net::NetLog::TYPE_SOCKET_ALIVE, base::TimeTicks(), net::NetLog::Source(net::NetLog::SOURCE_SOCKET, 1263), net::NetLog::PHASE_END, NULL); // Add kMaxGraveyardSize unreferenced HTTP_STREAM_JOBS, so the circular // buffer containing source 1706. After adding kMaxGraveyardSize - 1 the // buffer will be full. Now when we add one more more source it will now evict // the oldest item, which is 1706. In doing so, 1706 will try to release the // reference it *thinks* it has on 1263. However 1263 has a reference count // of 0 and is already in a graveyard. for (size_t i = 0; i < PassiveLogCollector::HttpStreamJobTracker::kMaxGraveyardSize; ++i) { log.OnAddEntry(net::NetLog::TYPE_HTTP_STREAM_JOB, base::TimeTicks(), net::NetLog::Source(net::NetLog::SOURCE_HTTP_STREAM_JOB, i), net::NetLog::PHASE_END, NULL); } // To pass, this should simply not have DCHECK-ed above. }