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