OLD | NEW |
| (Empty) |
1 // Copyright 2014 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 "net/base/trace_net_log_observer.h" | |
6 | |
7 #include <string> | |
8 #include <vector> | |
9 | |
10 #include "base/json/json_reader.h" | |
11 #include "base/logging.h" | |
12 #include "base/memory/ref_counted.h" | |
13 #include "base/memory/ref_counted_memory.h" | |
14 #include "base/memory/scoped_ptr.h" | |
15 #include "base/run_loop.h" | |
16 #include "base/strings/stringprintf.h" | |
17 #include "base/trace_event/trace_event.h" | |
18 #include "base/trace_event/trace_event_impl.h" | |
19 #include "base/values.h" | |
20 #include "net/base/capturing_net_log.h" | |
21 #include "net/base/net_log.h" | |
22 #include "testing/gtest/include/gtest/gtest.h" | |
23 | |
24 using base::trace_event::TraceLog; | |
25 | |
26 namespace net { | |
27 | |
28 namespace { | |
29 | |
30 // TraceLog category for NetLog events. | |
31 const char kNetLogTracingCategory[] = TRACE_DISABLED_BY_DEFAULT("netlog"); | |
32 | |
33 struct TraceEntryInfo { | |
34 std::string category; | |
35 std::string id; | |
36 std::string phase; | |
37 std::string name; | |
38 std::string source_type; | |
39 }; | |
40 | |
41 TraceEntryInfo GetTraceEntryInfoFromValue(const base::DictionaryValue& value) { | |
42 TraceEntryInfo info; | |
43 EXPECT_TRUE(value.GetString("cat", &info.category)); | |
44 EXPECT_TRUE(value.GetString("id", &info.id)); | |
45 EXPECT_TRUE(value.GetString("ph", &info.phase)); | |
46 EXPECT_TRUE(value.GetString("name", &info.name)); | |
47 EXPECT_TRUE(value.GetString("args.source_type", &info.source_type)); | |
48 | |
49 return info; | |
50 } | |
51 | |
52 class TraceNetLogObserverTest : public testing::Test { | |
53 public: | |
54 TraceNetLogObserverTest() { | |
55 TraceLog* tracelog = TraceLog::GetInstance(); | |
56 DCHECK(tracelog); | |
57 DCHECK(!tracelog->IsEnabled()); | |
58 trace_buffer_.SetOutputCallback(json_output_.GetCallback()); | |
59 trace_net_log_observer_.reset(new TraceNetLogObserver()); | |
60 trace_events_.reset(new base::ListValue()); | |
61 } | |
62 | |
63 ~TraceNetLogObserverTest() override { | |
64 DCHECK(!TraceLog::GetInstance()->IsEnabled()); | |
65 } | |
66 | |
67 void OnTraceDataCollected( | |
68 base::RunLoop* run_loop, | |
69 const scoped_refptr<base::RefCountedString>& events_str, | |
70 bool has_more_events) { | |
71 DCHECK(trace_events_->empty()); | |
72 trace_buffer_.Start(); | |
73 trace_buffer_.AddFragment(events_str->data()); | |
74 trace_buffer_.Finish(); | |
75 | |
76 scoped_ptr<base::Value> trace_value; | |
77 trace_value.reset(base::JSONReader::Read( | |
78 json_output_.json_output, | |
79 base::JSON_PARSE_RFC | base::JSON_DETACHABLE_CHILDREN)); | |
80 | |
81 ASSERT_TRUE(trace_value) << json_output_.json_output; | |
82 base::ListValue* trace_events = NULL; | |
83 ASSERT_TRUE(trace_value->GetAsList(&trace_events)); | |
84 | |
85 trace_events_ = FilterNetLogTraceEvents(*trace_events); | |
86 | |
87 if (!has_more_events) | |
88 run_loop->Quit(); | |
89 } | |
90 | |
91 static void EnableTraceLog() { | |
92 TraceLog::GetInstance()->SetEnabled( | |
93 base::trace_event::CategoryFilter(kNetLogTracingCategory), | |
94 TraceLog::RECORDING_MODE, | |
95 base::trace_event::TraceOptions()); | |
96 } | |
97 | |
98 void EndTraceAndFlush() { | |
99 base::RunLoop run_loop; | |
100 TraceLog::GetInstance()->SetDisabled(); | |
101 TraceLog::GetInstance()->Flush( | |
102 base::Bind(&TraceNetLogObserverTest::OnTraceDataCollected, | |
103 base::Unretained(this), | |
104 base::Unretained(&run_loop))); | |
105 run_loop.Run(); | |
106 } | |
107 | |
108 void set_trace_net_log_observer(TraceNetLogObserver* trace_net_log_observer) { | |
109 trace_net_log_observer_.reset(trace_net_log_observer); | |
110 } | |
111 | |
112 static scoped_ptr<base::ListValue> FilterNetLogTraceEvents( | |
113 const base::ListValue& trace_events) { | |
114 scoped_ptr<base::ListValue> filtered_trace_events(new base::ListValue()); | |
115 for (size_t i = 0; i < trace_events.GetSize(); i++) { | |
116 const base::DictionaryValue* dict = NULL; | |
117 if (!trace_events.GetDictionary(i, &dict)) { | |
118 ADD_FAILURE() << "Unexpected non-dictionary event in trace_events"; | |
119 continue; | |
120 } | |
121 std::string category; | |
122 if (!dict->GetString("cat", &category)) { | |
123 ADD_FAILURE() | |
124 << "Unexpected item without a category field in trace_events"; | |
125 continue; | |
126 } | |
127 if (category != kNetLogTracingCategory) | |
128 continue; | |
129 filtered_trace_events->Append(dict->DeepCopy()); | |
130 } | |
131 return filtered_trace_events.Pass(); | |
132 } | |
133 | |
134 base::ListValue* trace_events() const { | |
135 return trace_events_.get(); | |
136 } | |
137 | |
138 CapturingNetLog* net_log() { | |
139 return &net_log_; | |
140 } | |
141 | |
142 TraceNetLogObserver* trace_net_log_observer() const { | |
143 return trace_net_log_observer_.get(); | |
144 } | |
145 | |
146 private: | |
147 scoped_ptr<base::ListValue> trace_events_; | |
148 base::trace_event::TraceResultBuffer trace_buffer_; | |
149 base::trace_event::TraceResultBuffer::SimpleOutput json_output_; | |
150 CapturingNetLog net_log_; | |
151 scoped_ptr<TraceNetLogObserver> trace_net_log_observer_; | |
152 }; | |
153 | |
154 TEST_F(TraceNetLogObserverTest, TracingNotEnabled) { | |
155 trace_net_log_observer()->WatchForTraceStart(net_log()); | |
156 net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE); | |
157 | |
158 EndTraceAndFlush(); | |
159 trace_net_log_observer()->StopWatchForTraceStart(); | |
160 | |
161 EXPECT_EQ(0u, trace_events()->GetSize()); | |
162 } | |
163 | |
164 TEST_F(TraceNetLogObserverTest, TraceEventCaptured) { | |
165 CapturingNetLog::CapturedEntryList entries; | |
166 net_log()->GetEntries(&entries); | |
167 EXPECT_TRUE(entries.empty()); | |
168 | |
169 trace_net_log_observer()->WatchForTraceStart(net_log()); | |
170 EnableTraceLog(); | |
171 BoundNetLog bound_net_log = | |
172 BoundNetLog::Make(net_log(), net::NetLog::SOURCE_NONE); | |
173 net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED); | |
174 bound_net_log.BeginEvent(NetLog::TYPE_URL_REQUEST_START_JOB); | |
175 bound_net_log.EndEvent(NetLog::TYPE_REQUEST_ALIVE); | |
176 | |
177 net_log()->GetEntries(&entries); | |
178 EXPECT_EQ(3u, entries.size()); | |
179 EndTraceAndFlush(); | |
180 trace_net_log_observer()->StopWatchForTraceStart(); | |
181 EXPECT_EQ(3u, trace_events()->GetSize()); | |
182 const base::DictionaryValue* item1 = NULL; | |
183 ASSERT_TRUE(trace_events()->GetDictionary(0, &item1)); | |
184 const base::DictionaryValue* item2 = NULL; | |
185 ASSERT_TRUE(trace_events()->GetDictionary(1, &item2)); | |
186 const base::DictionaryValue* item3 = NULL; | |
187 ASSERT_TRUE(trace_events()->GetDictionary(2, &item3)); | |
188 | |
189 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1); | |
190 TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2); | |
191 TraceEntryInfo actual_item3 = GetTraceEntryInfoFromValue(*item3); | |
192 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category); | |
193 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id); | |
194 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT), | |
195 actual_item1.phase); | |
196 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED), | |
197 actual_item1.name); | |
198 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type), | |
199 actual_item1.source_type); | |
200 | |
201 EXPECT_EQ(kNetLogTracingCategory, actual_item2.category); | |
202 EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id); | |
203 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN), | |
204 actual_item2.phase); | |
205 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB), | |
206 actual_item2.name); | |
207 EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type), | |
208 actual_item2.source_type); | |
209 | |
210 EXPECT_EQ(kNetLogTracingCategory, actual_item3.category); | |
211 EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item3.id); | |
212 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_END), | |
213 actual_item3.phase); | |
214 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE), | |
215 actual_item3.name); | |
216 EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type), | |
217 actual_item3.source_type); | |
218 } | |
219 | |
220 TEST_F(TraceNetLogObserverTest, EnableAndDisableTracing) { | |
221 trace_net_log_observer()->WatchForTraceStart(net_log()); | |
222 EnableTraceLog(); | |
223 net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED); | |
224 TraceLog::GetInstance()->SetDisabled(); | |
225 net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE); | |
226 EnableTraceLog(); | |
227 net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB); | |
228 | |
229 EndTraceAndFlush(); | |
230 trace_net_log_observer()->StopWatchForTraceStart(); | |
231 | |
232 CapturingNetLog::CapturedEntryList entries; | |
233 net_log()->GetEntries(&entries); | |
234 EXPECT_EQ(3u, entries.size()); | |
235 EXPECT_EQ(2u, trace_events()->GetSize()); | |
236 const base::DictionaryValue* item1 = NULL; | |
237 ASSERT_TRUE(trace_events()->GetDictionary(0, &item1)); | |
238 const base::DictionaryValue* item2 = NULL; | |
239 ASSERT_TRUE(trace_events()->GetDictionary(1, &item2)); | |
240 | |
241 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1); | |
242 TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2); | |
243 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category); | |
244 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id); | |
245 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT), | |
246 actual_item1.phase); | |
247 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED), | |
248 actual_item1.name); | |
249 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type), | |
250 actual_item1.source_type); | |
251 | |
252 EXPECT_EQ(kNetLogTracingCategory, actual_item2.category); | |
253 EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item2.id); | |
254 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT), | |
255 actual_item2.phase); | |
256 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB), | |
257 actual_item2.name); | |
258 EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type), | |
259 actual_item2.source_type); | |
260 } | |
261 | |
262 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileTracing) { | |
263 trace_net_log_observer()->WatchForTraceStart(net_log()); | |
264 EnableTraceLog(); | |
265 net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED); | |
266 trace_net_log_observer()->StopWatchForTraceStart(); | |
267 set_trace_net_log_observer(NULL); | |
268 net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE); | |
269 | |
270 EndTraceAndFlush(); | |
271 | |
272 CapturingNetLog::CapturedEntryList entries; | |
273 net_log()->GetEntries(&entries); | |
274 EXPECT_EQ(2u, entries.size()); | |
275 EXPECT_EQ(1u, trace_events()->GetSize()); | |
276 | |
277 const base::DictionaryValue* item1 = NULL; | |
278 ASSERT_TRUE(trace_events()->GetDictionary(0, &item1)); | |
279 | |
280 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1); | |
281 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category); | |
282 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id); | |
283 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT), | |
284 actual_item1.phase); | |
285 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED), | |
286 actual_item1.name); | |
287 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type), | |
288 actual_item1.source_type); | |
289 } | |
290 | |
291 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileNotTracing) { | |
292 trace_net_log_observer()->WatchForTraceStart(net_log()); | |
293 net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED); | |
294 trace_net_log_observer()->StopWatchForTraceStart(); | |
295 set_trace_net_log_observer(NULL); | |
296 net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE); | |
297 net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB); | |
298 | |
299 EndTraceAndFlush(); | |
300 | |
301 CapturingNetLog::CapturedEntryList entries; | |
302 net_log()->GetEntries(&entries); | |
303 EXPECT_EQ(3u, entries.size()); | |
304 EXPECT_EQ(0u, trace_events()->GetSize()); | |
305 } | |
306 | |
307 TEST_F(TraceNetLogObserverTest, CreateObserverAfterTracingStarts) { | |
308 set_trace_net_log_observer(NULL); | |
309 EnableTraceLog(); | |
310 set_trace_net_log_observer(new TraceNetLogObserver()); | |
311 trace_net_log_observer()->WatchForTraceStart(net_log()); | |
312 net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED); | |
313 trace_net_log_observer()->StopWatchForTraceStart(); | |
314 net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE); | |
315 net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB); | |
316 | |
317 EndTraceAndFlush(); | |
318 | |
319 CapturingNetLog::CapturedEntryList entries; | |
320 net_log()->GetEntries(&entries); | |
321 EXPECT_EQ(3u, entries.size()); | |
322 EXPECT_EQ(0u, trace_events()->GetSize()); | |
323 } | |
324 | |
325 TEST_F(TraceNetLogObserverTest, EventsWithAndWithoutParameters) { | |
326 trace_net_log_observer()->WatchForTraceStart(net_log()); | |
327 EnableTraceLog(); | |
328 NetLog::ParametersCallback net_log_callback; | |
329 std::string param = "bar"; | |
330 net_log_callback = NetLog::StringCallback("foo", ¶m); | |
331 | |
332 net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED, net_log_callback); | |
333 net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE); | |
334 | |
335 EndTraceAndFlush(); | |
336 trace_net_log_observer()->StopWatchForTraceStart(); | |
337 | |
338 CapturingNetLog::CapturedEntryList entries; | |
339 net_log()->GetEntries(&entries); | |
340 EXPECT_EQ(2u, entries.size()); | |
341 EXPECT_EQ(2u, trace_events()->GetSize()); | |
342 const base::DictionaryValue* item1 = NULL; | |
343 ASSERT_TRUE(trace_events()->GetDictionary(0, &item1)); | |
344 const base::DictionaryValue* item2 = NULL; | |
345 ASSERT_TRUE(trace_events()->GetDictionary(1, &item2)); | |
346 | |
347 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1); | |
348 TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2); | |
349 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category); | |
350 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id); | |
351 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT), | |
352 actual_item1.phase); | |
353 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED), | |
354 actual_item1.name); | |
355 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type), | |
356 actual_item1.source_type); | |
357 | |
358 EXPECT_EQ(kNetLogTracingCategory, actual_item2.category); | |
359 EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id); | |
360 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT), | |
361 actual_item2.phase); | |
362 EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE), | |
363 actual_item2.name); | |
364 EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type), | |
365 actual_item2.source_type); | |
366 | |
367 std::string item1_params; | |
368 std::string item2_params; | |
369 EXPECT_TRUE(item1->GetString("args.params.foo", &item1_params)); | |
370 EXPECT_EQ("bar", item1_params); | |
371 | |
372 EXPECT_TRUE(item2->GetString("args.params", &item2_params)); | |
373 EXPECT_TRUE(item2_params.empty()); | |
374 } | |
375 | |
376 } // namespace | |
377 | |
378 } // namespace net | |
OLD | NEW |