passive_log_collector_unittest.cc revision c407dc5cd9bdc5668497f21b26b09d988ab439de 
1// Copyright (c) 2010 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "chrome/browser/net/passive_log_collector.h"
6
7#include "base/compiler_specific.h"
8#include "base/format_macros.h"
9#include "base/string_util.h"
10#include "net/url_request/url_request_netlog_params.h"
11#include "testing/gtest/include/gtest/gtest.h"
12
13namespace {
14
15typedef PassiveLogCollector::RequestTracker RequestTracker;
16typedef PassiveLogCollector::SourceInfoList SourceInfoList;
17typedef PassiveLogCollector::SocketTracker SocketTracker;
18using net::NetLog;
19
20const NetLog::SourceType kSourceType = NetLog::SOURCE_NONE;
21
22PassiveLogCollector::Entry MakeStartLogEntryWithURL(int source_id,
23                                                    const std::string& url) {
24  return PassiveLogCollector::Entry(
25      0,
26      NetLog::TYPE_URL_REQUEST_START_JOB,
27      base::TimeTicks(),
28      NetLog::Source(kSourceType, source_id),
29      NetLog::PHASE_BEGIN,
30      new URLRequestStartEventParameters(GURL(url), "GET", 0, net::LOW));
31}
32
33PassiveLogCollector::Entry MakeStartLogEntry(int source_id) {
34  return MakeStartLogEntryWithURL(source_id,
35                                  StringPrintf("http://req%d", source_id));
36}
37
38PassiveLogCollector::Entry MakeEndLogEntry(int source_id) {
39  return PassiveLogCollector::Entry(
40      0,
41      NetLog::TYPE_REQUEST_ALIVE,
42      base::TimeTicks(),
43      NetLog::Source(kSourceType, source_id),
44      NetLog::PHASE_END,
45      NULL);
46}
47
48void AddStartURLRequestEntries(PassiveLogCollector* collector, uint32 id) {
49  collector->OnAddEntry(NetLog::TYPE_REQUEST_ALIVE, base::TimeTicks(),
50                        NetLog::Source(NetLog::SOURCE_URL_REQUEST, id),
51                        NetLog::PHASE_BEGIN, NULL);
52  collector->OnAddEntry(NetLog::TYPE_URL_REQUEST_START_JOB, base::TimeTicks(),
53                        NetLog::Source(NetLog::SOURCE_URL_REQUEST, id),
54                        NetLog::PHASE_BEGIN, new URLRequestStartEventParameters(
55                            GURL(StringPrintf("http://req%d", id)), "GET", 0,
56                            net::LOW));
57}
58
59void AddEndURLRequestEntries(PassiveLogCollector* collector, uint32 id) {
60  collector->OnAddEntry(NetLog::TYPE_REQUEST_ALIVE, base::TimeTicks(),
61                        NetLog::Source(NetLog::SOURCE_URL_REQUEST, id),
62                        NetLog::PHASE_END, NULL);
63}
64
65std::string GetStringParam(const PassiveLogCollector::Entry& entry) {
66  return static_cast<net::NetLogStringParameter*>(
67      entry.params.get())->value();
68}
69
70bool OrderBySourceID(const PassiveLogCollector::SourceInfo& a,
71                     const PassiveLogCollector::SourceInfo& b) {
72  return a.source_id < b.source_id;
73}
74
75SourceInfoList GetLiveSources(
76    const PassiveLogCollector::SourceTracker& tracker) {
77  SourceInfoList result = tracker.GetAllDeadOrAliveSources(true);
78  std::sort(result.begin(), result.end(), &OrderBySourceID);
79  return result;
80}
81
82SourceInfoList GetDeadSources(
83    const PassiveLogCollector::SourceTracker& tracker) {
84  SourceInfoList result = tracker.GetAllDeadOrAliveSources(false);
85  std::sort(result.begin(), result.end(), &OrderBySourceID);
86  return result;
87}
88
89static const int kMaxNumLoadLogEntries = 1;
90
91}  // namespace
92
93// Test that once the tracker contains a total maximum amount of data
94// (graveyard + live requests), it resets itself to avoid growing unbounded.
95TEST(RequestTrackerTest, DropsAfterMaximumSize) {
96  RequestTracker tracker(NULL);
97
98  // Fill the source tracker with as many sources as it can hold.
99  for (size_t i = 0; i < RequestTracker::kMaxNumSources; ++i)
100    tracker.OnAddEntry(MakeStartLogEntry(i));
101
102  EXPECT_EQ(RequestTracker::kMaxNumSources, GetLiveSources(tracker).size());
103
104  // Add 1 more -- this should cause it to exceed its expected peak, and
105  // therefore reset all of its data.
106  tracker.OnAddEntry(
107      MakeStartLogEntry(1 + RequestTracker::kMaxNumSources));
108
109  EXPECT_EQ(1u, GetLiveSources(tracker).size());
110}
111
112TEST(RequestTrackerTest, BasicBounded) {
113  RequestTracker tracker(NULL);
114  EXPECT_EQ(0u, GetLiveSources(tracker).size());
115  EXPECT_EQ(0u, GetDeadSources(tracker).size());
116
117  tracker.OnAddEntry(MakeStartLogEntry(1));
118  tracker.OnAddEntry(MakeStartLogEntry(2));
119  tracker.OnAddEntry(MakeStartLogEntry(3));
120  tracker.OnAddEntry(MakeStartLogEntry(4));
121  tracker.OnAddEntry(MakeStartLogEntry(5));
122
123  SourceInfoList live_reqs = GetLiveSources(tracker);
124
125  ASSERT_EQ(5u, live_reqs.size());
126  EXPECT_EQ("http://req1/", live_reqs[0].GetURL());
127  EXPECT_EQ("http://req2/", live_reqs[1].GetURL());
128  EXPECT_EQ("http://req3/", live_reqs[2].GetURL());
129  EXPECT_EQ("http://req4/", live_reqs[3].GetURL());
130  EXPECT_EQ("http://req5/", live_reqs[4].GetURL());
131
132  tracker.OnAddEntry(MakeEndLogEntry(1));
133  tracker.OnAddEntry(MakeEndLogEntry(5));
134  tracker.OnAddEntry(MakeEndLogEntry(3));
135
136  ASSERT_EQ(3u, GetDeadSources(tracker).size());
137
138  live_reqs = GetLiveSources(tracker);
139
140  ASSERT_EQ(2u, live_reqs.size());
141  EXPECT_EQ("http://req2/", live_reqs[0].GetURL());
142  EXPECT_EQ("http://req4/", live_reqs[1].GetURL());
143}
144
145TEST(RequestTrackerTest, GraveyardBounded) {
146  RequestTracker tracker(NULL);
147  EXPECT_EQ(0u, GetLiveSources(tracker).size());
148  EXPECT_EQ(0u, GetDeadSources(tracker).size());
149
150  // Add twice as many requests as will fit in the graveyard.
151  for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize * 2; ++i) {
152    tracker.OnAddEntry(MakeStartLogEntry(i));
153    tracker.OnAddEntry(MakeEndLogEntry(i));
154  }
155
156  EXPECT_EQ(0u, GetLiveSources(tracker).size());
157
158  // Check that only the last |kMaxGraveyardSize| requests are in-memory.
159
160  SourceInfoList recent = GetDeadSources(tracker);
161
162  ASSERT_EQ(RequestTracker::kMaxGraveyardSize, recent.size());
163
164  for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize; ++i) {
165    size_t req_number = i + RequestTracker::kMaxGraveyardSize;
166    std::string url = StringPrintf("http://req%" PRIuS "/", req_number);
167    EXPECT_EQ(url, recent[i].GetURL());
168  }
169}
170
171// Check that we exclude "chrome://" URLs from being saved into the recent
172// requests list (graveyard).
173TEST(RequestTrackerTest, GraveyardIsFiltered) {
174  RequestTracker tracker(NULL);
175
176  // This will be excluded.
177  std::string url1 = "chrome://dontcare/";
178  tracker.OnAddEntry(MakeStartLogEntryWithURL(1, url1));
179  tracker.OnAddEntry(MakeEndLogEntry(1));
180
181  // This will be be added to graveyard.
182  std::string url2 = "chrome2://dontcare/";
183  tracker.OnAddEntry(MakeStartLogEntryWithURL(2, url2));
184  tracker.OnAddEntry(MakeEndLogEntry(2));
185
186  // This will be be added to graveyard.
187  std::string url3 = "http://foo/";
188  tracker.OnAddEntry(MakeStartLogEntryWithURL(3, url3));
189  tracker.OnAddEntry(MakeEndLogEntry(3));
190
191  ASSERT_EQ(2u, GetDeadSources(tracker).size());
192  EXPECT_EQ(url2, GetDeadSources(tracker)[0].GetURL());
193  EXPECT_EQ(url3, GetDeadSources(tracker)[1].GetURL());
194}
195
196TEST(SpdySessionTracker, MovesToGraveyard) {
197  PassiveLogCollector::SpdySessionTracker tracker;
198  EXPECT_EQ(0u, GetLiveSources(tracker).size());
199  EXPECT_EQ(0u, GetDeadSources(tracker).size());
200
201  PassiveLogCollector::Entry begin(
202      0u,
203      NetLog::TYPE_SPDY_SESSION,
204      base::TimeTicks(),
205      NetLog::Source(NetLog::SOURCE_SPDY_SESSION, 1),
206      NetLog::PHASE_BEGIN,
207      NULL);
208
209  tracker.OnAddEntry(begin);
210  EXPECT_EQ(1u, GetLiveSources(tracker).size());
211  EXPECT_EQ(0u, GetDeadSources(tracker).size());
212
213  PassiveLogCollector::Entry end(
214      0u,
215      NetLog::TYPE_SPDY_SESSION,
216      base::TimeTicks(),
217      NetLog::Source(NetLog::SOURCE_SPDY_SESSION, 1),
218      NetLog::PHASE_END,
219      NULL);
220
221  tracker.OnAddEntry(end);
222  EXPECT_EQ(0u, GetLiveSources(tracker).size());
223  EXPECT_EQ(1u, GetDeadSources(tracker).size());
224}
225
226// Test that when a SOURCE_SOCKET is connected to a SOURCE_URL_REQUEST
227// (via the TYPE_SOCKET_POOL_BOUND_TO_SOCKET event), it holds a reference
228// to the SOURCE_SOCKET preventing it from getting deleted as long as the
229// SOURCE_URL_REQUEST is still around.
230TEST(PassiveLogCollectorTest, HoldReferenceToDependentSource) {
231  PassiveLogCollector log;
232
233  EXPECT_EQ(0u, GetLiveSources(log.url_request_tracker_).size());
234  EXPECT_EQ(0u, GetLiveSources(log.socket_tracker_).size());
235
236  uint32 next_id = 0;
237  NetLog::Source socket_source(NetLog::SOURCE_SOCKET, next_id++);
238  NetLog::Source url_request_source(NetLog::SOURCE_URL_REQUEST, next_id++);
239
240  // Start a SOURCE_SOCKET.
241  log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE,
242                 base::TimeTicks(),
243                 socket_source,
244                 NetLog::PHASE_BEGIN,
245                 NULL);
246
247  EXPECT_EQ(0u, GetLiveSources(log.url_request_tracker_).size());
248  EXPECT_EQ(1u, GetLiveSources(log.socket_tracker_).size());
249
250  // Start a SOURCE_URL_REQUEST.
251  log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE,
252                 base::TimeTicks(),
253                 url_request_source,
254                 NetLog::PHASE_BEGIN,
255                 NULL);
256
257  // Check that there is no association between the SOURCE_URL_REQUEST and the
258  // SOURCE_SOCKET yet.
259  ASSERT_EQ(1u, GetLiveSources(log.url_request_tracker_).size());
260  {
261    PassiveLogCollector::SourceInfo info =
262        GetLiveSources(log.url_request_tracker_)[0];
263    EXPECT_EQ(0, info.reference_count);
264    EXPECT_EQ(0u, info.dependencies.size());
265  }
266  ASSERT_EQ(1u, GetLiveSources(log.socket_tracker_).size());
267  {
268    PassiveLogCollector::SourceInfo info =
269        GetLiveSources(log.socket_tracker_)[0];
270    EXPECT_EQ(0, info.reference_count);
271    EXPECT_EQ(0u, info.dependencies.size());
272  }
273
274  // Associate the SOURCE_SOCKET with the SOURCE_URL_REQUEST.
275  log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
276                 base::TimeTicks(),
277                 url_request_source,
278                 NetLog::PHASE_NONE,
279                 new net::NetLogSourceParameter("x", socket_source));
280
281  // Check that an associate was made -- the SOURCE_URL_REQUEST should have
282  // added a reference to the SOURCE_SOCKET.
283  ASSERT_EQ(1u, GetLiveSources(log.url_request_tracker_).size());
284  {
285    PassiveLogCollector::SourceInfo info =
286        GetLiveSources(log.url_request_tracker_)[0];
287    EXPECT_EQ(0, info.reference_count);
288    EXPECT_EQ(1u, info.dependencies.size());
289    EXPECT_EQ(socket_source.id, info.dependencies[0].id);
290  }
291  ASSERT_EQ(1u, GetLiveSources(log.socket_tracker_).size());
292  {
293    PassiveLogCollector::SourceInfo info =
294        GetLiveSources(log.socket_tracker_)[0];
295    EXPECT_EQ(1, info.reference_count);
296    EXPECT_EQ(0u, info.dependencies.size());
297  }
298
299  // Now end both |source_socket| and |source_url_request|. This sends them
300  // to deletion queue, and they will be deleted once space runs out.
301
302  log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE,
303                 base::TimeTicks(),
304                 url_request_source,
305                 NetLog::PHASE_END,
306                 NULL);
307
308  log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE,
309                 base::TimeTicks(),
310                 socket_source,
311                 NetLog::PHASE_END,
312                 NULL);
313
314  // Verify that both sources are in fact dead, and that |source_url_request|
315  // still holds a reference to |source_socket|.
316  ASSERT_EQ(0u, GetLiveSources(log.url_request_tracker_).size());
317  ASSERT_EQ(1u, GetDeadSources(log.url_request_tracker_).size());
318  {
319    PassiveLogCollector::SourceInfo info =
320        GetDeadSources(log.url_request_tracker_)[0];
321    EXPECT_EQ(0, info.reference_count);
322    EXPECT_EQ(1u, info.dependencies.size());
323    EXPECT_EQ(socket_source.id, info.dependencies[0].id);
324  }
325  EXPECT_EQ(0u, GetLiveSources(log.socket_tracker_).size());
326  ASSERT_EQ(1u, GetDeadSources(log.socket_tracker_).size());
327  {
328    PassiveLogCollector::SourceInfo info =
329        GetDeadSources(log.socket_tracker_)[0];
330    EXPECT_EQ(1, info.reference_count);
331    EXPECT_EQ(0u, info.dependencies.size());
332  }
333
334  // Cycle through a bunch of SOURCE_SOCKET -- if it were not referenced, this
335  // loop will have deleted it.
336  for (size_t i = 0; i < SocketTracker::kMaxGraveyardSize; ++i) {
337      log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE,
338                     base::TimeTicks(),
339                     NetLog::Source(NetLog::SOURCE_SOCKET, next_id++),
340                     NetLog::PHASE_END,
341                     NULL);
342  }
343
344  EXPECT_EQ(0u, GetLiveSources(log.socket_tracker_).size());
345  ASSERT_EQ(SocketTracker::kMaxGraveyardSize + 1,
346            GetDeadSources(log.socket_tracker_).size());
347  {
348    PassiveLogCollector::SourceInfo info =
349        GetDeadSources(log.socket_tracker_)[0];
350    EXPECT_EQ(socket_source.id, info.source_id);
351    EXPECT_EQ(1, info.reference_count);
352    EXPECT_EQ(0u, info.dependencies.size());
353  }
354
355  // Cycle through a bunch of SOURCE_URL_REQUEST -- this will cause
356  // |source_url_request| to be freed, which in turn should release the final
357  // reference to |source_socket| cause it to be freed as well.
358  for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize; ++i) {
359    log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE,
360                   base::TimeTicks(),
361                   NetLog::Source(NetLog::SOURCE_URL_REQUEST, next_id++),
362                   NetLog::PHASE_END,
363                   NULL);
364  }
365
366  EXPECT_EQ(0u, GetLiveSources(log.url_request_tracker_).size());
367  EXPECT_EQ(RequestTracker::kMaxGraveyardSize,
368            GetDeadSources(log.url_request_tracker_).size());
369
370  EXPECT_EQ(0u, GetLiveSources(log.socket_tracker_).size());
371  EXPECT_EQ(SocketTracker::kMaxGraveyardSize,
372            GetDeadSources(log.socket_tracker_).size());
373}
374
375// Have a URL_REQUEST hold a reference to a SOCKET. Then cause the SOCKET to
376// get evicted (by exceeding maximum sources limit). Now the URL_REQUEST is
377// referencing a non-existant SOCKET. Lastly, evict the URL_REQUEST so it
378// tries to drop all of its references. Make sure that in releasing its
379// non-existant reference it doesn't trip any DCHECKs.
380TEST(PassiveLogCollectorTest, HoldReferenceToDeletedSource) {
381  PassiveLogCollector log;
382
383  EXPECT_EQ(0u, GetLiveSources(log.url_request_tracker_).size());
384  EXPECT_EQ(0u, GetLiveSources(log.socket_tracker_).size());
385
386  uint32 next_id = 0;
387  NetLog::Source socket_source(NetLog::SOURCE_SOCKET, next_id++);
388  NetLog::Source url_request_source(NetLog::SOURCE_URL_REQUEST, next_id++);
389
390  // Start a SOURCE_SOCKET.
391  log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE,
392                 base::TimeTicks(),
393                 socket_source,
394                 NetLog::PHASE_BEGIN,
395                 NULL);
396
397  EXPECT_EQ(0u, GetLiveSources(log.url_request_tracker_).size());
398  EXPECT_EQ(1u, GetLiveSources(log.socket_tracker_).size());
399
400  // Start a SOURCE_URL_REQUEST.
401  log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE,
402                 base::TimeTicks(),
403                 url_request_source,
404                 NetLog::PHASE_BEGIN,
405                 NULL);
406
407  // Associate the SOURCE_SOCKET with the SOURCE_URL_REQUEST.
408  log.OnAddEntry(NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
409                 base::TimeTicks(),
410                 url_request_source,
411                 NetLog::PHASE_NONE,
412                 new net::NetLogSourceParameter("x", socket_source));
413
414  // Check that an associate was made -- the SOURCE_URL_REQUEST should have
415  // added a reference to the SOURCE_SOCKET.
416  ASSERT_EQ(1u, GetLiveSources(log.url_request_tracker_).size());
417  {
418    PassiveLogCollector::SourceInfo info =
419        GetLiveSources(log.url_request_tracker_)[0];
420    EXPECT_EQ(0, info.reference_count);
421    EXPECT_EQ(1u, info.dependencies.size());
422    EXPECT_EQ(socket_source.id, info.dependencies[0].id);
423  }
424  ASSERT_EQ(1u, GetLiveSources(log.socket_tracker_).size());
425  {
426    PassiveLogCollector::SourceInfo info =
427        GetLiveSources(log.socket_tracker_)[0];
428    EXPECT_EQ(1, info.reference_count);
429    EXPECT_EQ(0u, info.dependencies.size());
430  }
431
432  // Add lots of sources to the socket tracker. This is just enough to cause
433  // the tracker to reach its peak, and reset all of its data as a safeguard.
434  for (size_t i = 0; i < SocketTracker::kMaxNumSources; ++i) {
435    log.OnAddEntry(NetLog::TYPE_SOCKET_ALIVE,
436                   base::TimeTicks(),
437                   NetLog::Source(NetLog::SOURCE_SOCKET, next_id++),
438                   NetLog::PHASE_BEGIN,
439                   NULL);
440  }
441  ASSERT_EQ(1u, GetLiveSources(log.socket_tracker_).size());
442
443  // End the original request. Then saturate the graveyard with enough other
444  // requests to cause it to be deleted. Once that source is deleted, it will
445  // try to give up its reference to the SOCKET. However that socket_id no
446  // longer exists -- should not DCHECK().
447  log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE,
448                 base::TimeTicks(),
449                 url_request_source,
450                 NetLog::PHASE_END,
451                 NULL);
452  for (size_t i = 0; i < RequestTracker::kMaxGraveyardSize; ++i) {
453    log.OnAddEntry(NetLog::TYPE_REQUEST_ALIVE,
454                   base::TimeTicks(),
455                   NetLog::Source(NetLog::SOURCE_URL_REQUEST, next_id++),
456                   NetLog::PHASE_END,
457                   NULL);
458  }
459  EXPECT_EQ(RequestTracker::kMaxGraveyardSize,
460            GetDeadSources(log.url_request_tracker_).size());
461}
462
463