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/log/trace_net_log_observer.h"
6
7 #include <memory>
8 #include <string>
9 #include <vector>
10
11 #include "base/bind.h"
12 #include "base/check.h"
13 #include "base/json/json_reader.h"
14 #include "base/memory/ptr_util.h"
15 #include "base/memory/ref_counted.h"
16 #include "base/memory/ref_counted_memory.h"
17 #include "base/run_loop.h"
18 #include "base/strings/stringprintf.h"
19 #include "base/test/task_environment.h"
20 #include "base/trace_event/trace_buffer.h"
21 #include "base/trace_event/trace_event.h"
22 #include "base/trace_event/trace_event_impl.h"
23 #include "base/values.h"
24 #include "net/log/net_log_event_type.h"
25 #include "net/log/net_log_source_type.h"
26 #include "net/log/net_log_with_source.h"
27 #include "net/log/test_net_log.h"
28 #include "net/test/test_with_task_environment.h"
29 #include "testing/gtest/include/gtest/gtest.h"
30
31 using base::trace_event::TraceLog;
32
33 namespace net {
34
35 namespace {
36
37 // TraceLog category for NetLog events.
38 const char kNetLogTracingCategory[] = "netlog";
39
40 struct TraceEntryInfo {
41 std::string category;
42 std::string id;
43 std::string phase;
44 std::string name;
45 std::string source_type;
46 };
47
GetTraceEntryInfoFromValue(const base::Value & value)48 TraceEntryInfo GetTraceEntryInfoFromValue(const base::Value& value) {
49 TraceEntryInfo info;
50 if (const std::string* cat = value.FindStringKey("cat")) {
51 info.category = *cat;
52 } else {
53 ADD_FAILURE() << "Missing 'cat'";
54 }
55 if (const std::string* id = value.FindStringKey("id")) {
56 info.id = *id;
57 } else {
58 ADD_FAILURE() << "Missing 'id'";
59 }
60 if (const std::string* ph = value.FindStringKey("ph")) {
61 info.phase = *ph;
62 } else {
63 ADD_FAILURE() << "Missing 'ph'";
64 }
65 if (const std::string* name = value.FindStringKey("name")) {
66 info.name = *name;
67 } else {
68 ADD_FAILURE() << "Missing 'name'";
69 }
70 if (const std::string* type = value.FindStringPath("args.source_type")) {
71 info.source_type = *type;
72 } else {
73 ADD_FAILURE() << "Missing 'args.source_type'";
74 }
75
76 return info;
77 }
78
EnableTraceLog(base::StringPiece category)79 void EnableTraceLog(base::StringPiece category) {
80 TraceLog::GetInstance()->SetEnabled(
81 base::trace_event::TraceConfig(category, ""), TraceLog::RECORDING_MODE);
82 // AsyncEnabledStateObserver will receive enabled notification one message
83 // loop iteration later.
84 base::RunLoop().RunUntilIdle();
85 }
86
DisableTraceLog()87 void DisableTraceLog() {
88 TraceLog::GetInstance()->SetDisabled();
89 // AsyncEnabledStateObserver will receive disabled notification one message
90 // loop iteration later.
91 base::RunLoop().RunUntilIdle();
92 }
93
EnableTraceLogWithNetLog()94 void EnableTraceLogWithNetLog() {
95 EnableTraceLog(kNetLogTracingCategory);
96 }
97
EnableTraceLogWithoutNetLog()98 void EnableTraceLogWithoutNetLog() {
99 std::string disabled_netlog_category =
100 std::string("-") + kNetLogTracingCategory;
101 EnableTraceLog(disabled_netlog_category);
102 }
103
104 class TraceNetLogObserverTest : public TestWithTaskEnvironment {
105 public:
TraceNetLogObserverTest()106 TraceNetLogObserverTest() {
107 TraceLog* tracelog = TraceLog::GetInstance();
108 DCHECK(tracelog);
109 DCHECK(!tracelog->IsEnabled());
110 trace_buffer_.SetOutputCallback(json_output_.GetCallback());
111 trace_net_log_observer_.reset(new TraceNetLogObserver());
112 trace_events_.reset(new base::ListValue());
113 }
114
~TraceNetLogObserverTest()115 ~TraceNetLogObserverTest() override {
116 DCHECK(!TraceLog::GetInstance()->IsEnabled());
117 }
118
OnTraceDataCollected(base::RunLoop * run_loop,const scoped_refptr<base::RefCountedString> & events_str,bool has_more_events)119 void OnTraceDataCollected(
120 base::RunLoop* run_loop,
121 const scoped_refptr<base::RefCountedString>& events_str,
122 bool has_more_events) {
123 DCHECK(trace_events_->empty());
124 trace_buffer_.Start();
125 trace_buffer_.AddFragment(events_str->data());
126 trace_buffer_.Finish();
127
128 std::unique_ptr<base::Value> trace_value;
129 trace_value = base::JSONReader::ReadDeprecated(json_output_.json_output,
130 base::JSON_PARSE_RFC);
131
132 ASSERT_TRUE(trace_value) << json_output_.json_output;
133 base::ListValue* trace_events = nullptr;
134 ASSERT_TRUE(trace_value->GetAsList(&trace_events));
135
136 trace_events_ = FilterNetLogTraceEvents(*trace_events);
137
138 if (!has_more_events)
139 run_loop->Quit();
140 }
141
EndTraceAndFlush()142 void EndTraceAndFlush() {
143 DisableTraceLog();
144 base::RunLoop run_loop;
145 TraceLog::GetInstance()->Flush(base::BindRepeating(
146 &TraceNetLogObserverTest::OnTraceDataCollected, base::Unretained(this),
147 base::Unretained(&run_loop)));
148 run_loop.Run();
149 }
150
set_trace_net_log_observer(TraceNetLogObserver * trace_net_log_observer)151 void set_trace_net_log_observer(TraceNetLogObserver* trace_net_log_observer) {
152 trace_net_log_observer_.reset(trace_net_log_observer);
153 }
154
FilterNetLogTraceEvents(const base::ListValue & trace_events)155 static std::unique_ptr<base::ListValue> FilterNetLogTraceEvents(
156 const base::ListValue& trace_events) {
157 std::unique_ptr<base::ListValue> filtered_trace_events(
158 new base::ListValue());
159 for (size_t i = 0; i < trace_events.GetSize(); i++) {
160 const base::Value* dict = &trace_events.GetList()[i];
161 if (!dict->is_dict()) {
162 ADD_FAILURE() << "Unexpected non-dictionary event in trace_events";
163 continue;
164 }
165 const std::string* category = dict->FindStringPath("cat");
166 if (!category) {
167 ADD_FAILURE()
168 << "Unexpected item without a category field in trace_events";
169 continue;
170 }
171 if (*category != kNetLogTracingCategory)
172 continue;
173 filtered_trace_events->Append(dict->CreateDeepCopy());
174 }
175 return filtered_trace_events;
176 }
177
trace_events() const178 base::ListValue* trace_events() const { return trace_events_.get(); }
179
net_log()180 RecordingTestNetLog* net_log() { return &net_log_; }
181
trace_net_log_observer() const182 TraceNetLogObserver* trace_net_log_observer() const {
183 return trace_net_log_observer_.get();
184 }
185
186 private:
187 std::unique_ptr<base::ListValue> trace_events_;
188 base::trace_event::TraceResultBuffer trace_buffer_;
189 base::trace_event::TraceResultBuffer::SimpleOutput json_output_;
190 RecordingTestNetLog net_log_;
191 std::unique_ptr<TraceNetLogObserver> trace_net_log_observer_;
192 };
193
TEST_F(TraceNetLogObserverTest,TracingNotEnabled)194 TEST_F(TraceNetLogObserverTest, TracingNotEnabled) {
195 trace_net_log_observer()->WatchForTraceStart(net_log());
196 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
197
198 EndTraceAndFlush();
199 trace_net_log_observer()->StopWatchForTraceStart();
200
201 EXPECT_EQ(0u, trace_events()->GetSize());
202 }
203
204 // This test will result in a deadlock if EnabledStateObserver instead
205 // of AsyncEnabledStateObserver is used. Regression test for crbug.com/760817.
TEST_F(TraceNetLogObserverTest,TracingDisabledDuringOnAddEntry)206 TEST_F(TraceNetLogObserverTest, TracingDisabledDuringOnAddEntry) {
207 trace_net_log_observer()->WatchForTraceStart(net_log());
208 TraceLog* trace_log = TraceLog::GetInstance();
209 trace_log->SetTraceBufferForTesting(base::WrapUnique(
210 base::trace_event::TraceBuffer::CreateTraceBufferVectorOfSize(1)));
211 EnableTraceLogWithNetLog();
212 // TraceLog will disable itself when an event makes the TraceBuffer full.
213 while (!trace_log->BufferIsFull()) {
214 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
215 }
216
217 base::RunLoop().RunUntilIdle();
218 ASSERT_FALSE(trace_log->IsEnabled());
219 ASSERT_FALSE(trace_net_log_observer()->net_log());
220 trace_net_log_observer()->StopWatchForTraceStart();
221 // Flush now so that TraceLog's buffer is empty in the next test.
222 EndTraceAndFlush();
223 }
224
TEST_F(TraceNetLogObserverTest,TraceEventCaptured)225 TEST_F(TraceNetLogObserverTest, TraceEventCaptured) {
226 auto entries = net_log()->GetEntries();
227 EXPECT_TRUE(entries.empty());
228
229 trace_net_log_observer()->WatchForTraceStart(net_log());
230 EnableTraceLogWithNetLog();
231 NetLogWithSource net_log_with_source =
232 NetLogWithSource::Make(net_log(), net::NetLogSourceType::NONE);
233 net_log()->AddGlobalEntry(NetLogEventType::CANCELLED);
234 net_log_with_source.BeginEvent(NetLogEventType::URL_REQUEST_START_JOB);
235 net_log_with_source.EndEvent(NetLogEventType::REQUEST_ALIVE);
236
237 entries = net_log()->GetEntries();
238 EXPECT_EQ(3u, entries.size());
239 EndTraceAndFlush();
240 trace_net_log_observer()->StopWatchForTraceStart();
241 EXPECT_EQ(3u, trace_events()->GetSize());
242 const base::Value* item1 = &trace_events()->GetList()[0];
243 ASSERT_TRUE(item1->is_dict());
244 const base::Value* item2 = &trace_events()->GetList()[1];
245 ;
246 ASSERT_TRUE(item2->is_dict());
247 const base::Value* item3 = &trace_events()->GetList()[2];
248 ;
249 ASSERT_TRUE(item3->is_dict());
250
251 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
252 TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
253 TraceEntryInfo actual_item3 = GetTraceEntryInfoFromValue(*item3);
254 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
255 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
256 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
257 actual_item1.phase);
258 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::CANCELLED),
259 actual_item1.name);
260 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
261 actual_item1.source_type);
262
263 EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
264 EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id);
265 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN),
266 actual_item2.phase);
267 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::URL_REQUEST_START_JOB),
268 actual_item2.name);
269 EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type),
270 actual_item2.source_type);
271
272 EXPECT_EQ(kNetLogTracingCategory, actual_item3.category);
273 EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item3.id);
274 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_END),
275 actual_item3.phase);
276 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::REQUEST_ALIVE),
277 actual_item3.name);
278 EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type),
279 actual_item3.source_type);
280 }
281
TEST_F(TraceNetLogObserverTest,EnableAndDisableTracing)282 TEST_F(TraceNetLogObserverTest, EnableAndDisableTracing) {
283 trace_net_log_observer()->WatchForTraceStart(net_log());
284 EnableTraceLogWithNetLog();
285 net_log()->AddGlobalEntry(NetLogEventType::CANCELLED);
286 DisableTraceLog();
287 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
288 EnableTraceLogWithNetLog();
289 net_log()->AddGlobalEntry(NetLogEventType::URL_REQUEST_START_JOB);
290
291 EndTraceAndFlush();
292 trace_net_log_observer()->StopWatchForTraceStart();
293
294 auto entries = net_log()->GetEntries();
295 EXPECT_EQ(3u, entries.size());
296 EXPECT_EQ(2u, trace_events()->GetSize());
297 const base::Value* item1 = &trace_events()->GetList()[0];
298 ASSERT_TRUE(item1->is_dict());
299 const base::Value* item2 = &trace_events()->GetList()[1];
300 ASSERT_TRUE(item2->is_dict());
301
302 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
303 TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
304 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
305 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
306 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
307 actual_item1.phase);
308 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::CANCELLED),
309 actual_item1.name);
310 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
311 actual_item1.source_type);
312
313 EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
314 EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item2.id);
315 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
316 actual_item2.phase);
317 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::URL_REQUEST_START_JOB),
318 actual_item2.name);
319 EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type),
320 actual_item2.source_type);
321 }
322
TEST_F(TraceNetLogObserverTest,DestroyObserverWhileTracing)323 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileTracing) {
324 trace_net_log_observer()->WatchForTraceStart(net_log());
325 EnableTraceLogWithNetLog();
326 net_log()->AddGlobalEntry(NetLogEventType::CANCELLED);
327 trace_net_log_observer()->StopWatchForTraceStart();
328 set_trace_net_log_observer(nullptr);
329 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
330
331 EndTraceAndFlush();
332
333 auto entries = net_log()->GetEntries();
334 EXPECT_EQ(2u, entries.size());
335 EXPECT_EQ(1u, trace_events()->GetSize());
336
337 const base::Value* item1 = &trace_events()->GetList()[0];
338 ASSERT_TRUE(item1->is_dict());
339
340 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
341 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
342 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
343 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
344 actual_item1.phase);
345 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::CANCELLED),
346 actual_item1.name);
347 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
348 actual_item1.source_type);
349 }
350
TEST_F(TraceNetLogObserverTest,DestroyObserverWhileNotTracing)351 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileNotTracing) {
352 trace_net_log_observer()->WatchForTraceStart(net_log());
353 net_log()->AddGlobalEntry(NetLogEventType::CANCELLED);
354 trace_net_log_observer()->StopWatchForTraceStart();
355 set_trace_net_log_observer(nullptr);
356 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
357 net_log()->AddGlobalEntry(NetLogEventType::URL_REQUEST_START_JOB);
358
359 EndTraceAndFlush();
360
361 auto entries = net_log()->GetEntries();
362 EXPECT_EQ(3u, entries.size());
363 EXPECT_EQ(0u, trace_events()->GetSize());
364 }
365
TEST_F(TraceNetLogObserverTest,CreateObserverAfterTracingStarts)366 TEST_F(TraceNetLogObserverTest, CreateObserverAfterTracingStarts) {
367 set_trace_net_log_observer(nullptr);
368 EnableTraceLogWithNetLog();
369 set_trace_net_log_observer(new TraceNetLogObserver());
370 trace_net_log_observer()->WatchForTraceStart(net_log());
371 net_log()->AddGlobalEntry(NetLogEventType::CANCELLED);
372 trace_net_log_observer()->StopWatchForTraceStart();
373 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
374 net_log()->AddGlobalEntry(NetLogEventType::URL_REQUEST_START_JOB);
375
376 EndTraceAndFlush();
377
378 auto entries = net_log()->GetEntries();
379 EXPECT_EQ(3u, entries.size());
380 EXPECT_EQ(1u, trace_events()->GetSize());
381 }
382
TEST_F(TraceNetLogObserverTest,CreateObserverAfterTracingStartsDisabledCategory)383 TEST_F(TraceNetLogObserverTest,
384 CreateObserverAfterTracingStartsDisabledCategory) {
385 set_trace_net_log_observer(nullptr);
386
387 EnableTraceLogWithoutNetLog();
388
389 set_trace_net_log_observer(new TraceNetLogObserver());
390 trace_net_log_observer()->WatchForTraceStart(net_log());
391 net_log()->AddGlobalEntry(NetLogEventType::CANCELLED);
392 trace_net_log_observer()->StopWatchForTraceStart();
393 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
394 net_log()->AddGlobalEntry(NetLogEventType::URL_REQUEST_START_JOB);
395
396 EndTraceAndFlush();
397
398 auto entries = net_log()->GetEntries();
399 EXPECT_EQ(3u, entries.size());
400 EXPECT_EQ(0u, trace_events()->GetSize());
401 }
402
TEST_F(TraceNetLogObserverTest,EventsWithAndWithoutParameters)403 TEST_F(TraceNetLogObserverTest, EventsWithAndWithoutParameters) {
404 trace_net_log_observer()->WatchForTraceStart(net_log());
405 EnableTraceLogWithNetLog();
406
407 net_log()->AddGlobalEntryWithStringParams(NetLogEventType::CANCELLED, "foo",
408 "bar");
409 net_log()->AddGlobalEntry(NetLogEventType::REQUEST_ALIVE);
410
411 EndTraceAndFlush();
412 trace_net_log_observer()->StopWatchForTraceStart();
413
414 auto entries = net_log()->GetEntries();
415 EXPECT_EQ(2u, entries.size());
416 EXPECT_EQ(2u, trace_events()->GetSize());
417 const base::Value* item1 = &trace_events()->GetList()[0];
418 ASSERT_TRUE(item1->is_dict());
419 const base::Value* item2 = &trace_events()->GetList()[1];
420 ASSERT_TRUE(item2->is_dict());
421
422 TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
423 TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
424 EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
425 EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
426 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
427 actual_item1.phase);
428 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::CANCELLED),
429 actual_item1.name);
430 EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
431 actual_item1.source_type);
432
433 EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
434 EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id);
435 EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
436 actual_item2.phase);
437 EXPECT_EQ(NetLog::EventTypeToString(NetLogEventType::REQUEST_ALIVE),
438 actual_item2.name);
439 EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type),
440 actual_item2.source_type);
441
442 const std::string* item1_params = item1->FindStringPath("args.params.foo");
443 ASSERT_TRUE(item1_params);
444 EXPECT_EQ("bar", *item1_params);
445
446 const base::Value* item2_params = item2->FindDictPath("args.params");
447 ASSERT_TRUE(item2_params);
448 EXPECT_TRUE(item2_params->DictEmpty());
449 }
450
TEST(TraceNetLogObserverCategoryTest,DisabledCategory)451 TEST(TraceNetLogObserverCategoryTest, DisabledCategory) {
452 base::test::TaskEnvironment task_environment;
453 TraceNetLogObserver observer;
454 TestNetLog net_log;
455 observer.WatchForTraceStart(&net_log);
456
457 EXPECT_FALSE(net_log.IsCapturing());
458
459 EnableTraceLogWithoutNetLog();
460
461 EXPECT_FALSE(net_log.IsCapturing());
462 observer.StopWatchForTraceStart();
463 EXPECT_FALSE(net_log.IsCapturing());
464
465 DisableTraceLog();
466 }
467
TEST(TraceNetLogObserverCategoryTest,EnabledCategory)468 TEST(TraceNetLogObserverCategoryTest, EnabledCategory) {
469 base::test::TaskEnvironment task_environment;
470 TraceNetLogObserver observer;
471 TestNetLog net_log;
472 observer.WatchForTraceStart(&net_log);
473
474 EXPECT_FALSE(net_log.IsCapturing());
475
476 EnableTraceLogWithNetLog();
477
478 EXPECT_TRUE(net_log.IsCapturing());
479 observer.StopWatchForTraceStart();
480 EXPECT_FALSE(net_log.IsCapturing());
481
482 DisableTraceLog();
483 }
484
485 } // namespace
486
487 } // namespace net
488