1 // Copyright 2013 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/net_log.h"
6
7 #include "base/memory/raw_ptr.h"
8 #include "base/synchronization/waitable_event.h"
9 #include "base/test/task_environment.h"
10 #include "base/threading/simple_thread.h"
11 #include "base/values.h"
12 #include "net/log/net_log_event_type.h"
13 #include "net/log/net_log_source_type.h"
14 #include "net/log/net_log_with_source.h"
15 #include "net/log/test_net_log.h"
16 #include "net/log/test_net_log_util.h"
17 #include "testing/gtest/include/gtest/gtest.h"
18
19 namespace net {
20
21 namespace {
22
23 const int kThreads = 10;
24 const int kEvents = 100;
25
CaptureModeToInt(NetLogCaptureMode capture_mode)26 int CaptureModeToInt(NetLogCaptureMode capture_mode) {
27 return static_cast<int>(capture_mode);
28 }
29
CaptureModeToValue(NetLogCaptureMode capture_mode)30 base::Value CaptureModeToValue(NetLogCaptureMode capture_mode) {
31 return base::Value(CaptureModeToInt(capture_mode));
32 }
33
NetCaptureModeParams(NetLogCaptureMode capture_mode)34 base::Value::Dict NetCaptureModeParams(NetLogCaptureMode capture_mode) {
35 base::Value::Dict dict;
36 dict.Set("capture_mode", CaptureModeToValue(capture_mode));
37 return dict;
38 }
39
TEST(NetLogTest,BasicGlobalEvents)40 TEST(NetLogTest, BasicGlobalEvents) {
41 base::test::TaskEnvironment task_environment{
42 base::test::TaskEnvironment::TimeSource::MOCK_TIME};
43 RecordingNetLogObserver net_log_observer;
44 auto entries = net_log_observer.GetEntries();
45 EXPECT_EQ(0u, entries.size());
46
47 task_environment.FastForwardBy(base::Seconds(1234));
48 base::TimeTicks ticks0 = base::TimeTicks::Now();
49
50 NetLog::Get()->AddGlobalEntry(NetLogEventType::CANCELLED);
51
52 task_environment.FastForwardBy(base::Seconds(5678));
53 base::TimeTicks ticks1 = base::TimeTicks::Now();
54 EXPECT_LE(ticks0, ticks1);
55
56 NetLog::Get()->AddGlobalEntry(NetLogEventType::FAILED);
57
58 task_environment.FastForwardBy(base::Seconds(91011));
59 EXPECT_LE(ticks1, base::TimeTicks::Now());
60
61 entries = net_log_observer.GetEntries();
62 ASSERT_EQ(2u, entries.size());
63
64 EXPECT_EQ(NetLogEventType::CANCELLED, entries[0].type);
65 EXPECT_EQ(NetLogSourceType::NONE, entries[0].source.type);
66 EXPECT_NE(NetLogSource::kInvalidId, entries[0].source.id);
67 EXPECT_EQ(ticks0, entries[0].source.start_time);
68 EXPECT_EQ(NetLogEventPhase::NONE, entries[0].phase);
69 EXPECT_EQ(ticks0, entries[0].time);
70 EXPECT_FALSE(entries[0].HasParams());
71
72 EXPECT_EQ(NetLogEventType::FAILED, entries[1].type);
73 EXPECT_EQ(NetLogSourceType::NONE, entries[1].source.type);
74 EXPECT_NE(NetLogSource::kInvalidId, entries[1].source.id);
75 EXPECT_LT(entries[0].source.id, entries[1].source.id);
76 EXPECT_EQ(ticks1, entries[1].source.start_time);
77 EXPECT_EQ(NetLogEventPhase::NONE, entries[1].phase);
78 EXPECT_EQ(ticks1, entries[1].time);
79 EXPECT_FALSE(entries[1].HasParams());
80 }
81
TEST(NetLogTest,BasicEventsWithSource)82 TEST(NetLogTest, BasicEventsWithSource) {
83 base::test::TaskEnvironment task_environment{
84 base::test::TaskEnvironment::TimeSource::MOCK_TIME};
85 RecordingNetLogObserver net_log_observer;
86 auto entries = net_log_observer.GetEntries();
87 EXPECT_EQ(0u, entries.size());
88
89 task_environment.FastForwardBy(base::Seconds(9876));
90 base::TimeTicks source0_start_ticks = base::TimeTicks::Now();
91
92 NetLogWithSource source0 =
93 NetLogWithSource::Make(NetLogSourceType::URL_REQUEST);
94 task_environment.FastForwardBy(base::Seconds(1));
95 base::TimeTicks source0_event0_ticks = base::TimeTicks::Now();
96 source0.BeginEvent(NetLogEventType::REQUEST_ALIVE);
97
98 task_environment.FastForwardBy(base::Seconds(5432));
99 base::TimeTicks source1_start_ticks = base::TimeTicks::Now();
100
101 NetLogWithSource source1 = NetLogWithSource::Make(NetLogSourceType::SOCKET);
102 task_environment.FastForwardBy(base::Seconds(1));
103 base::TimeTicks source1_event0_ticks = base::TimeTicks::Now();
104 source1.BeginEvent(NetLogEventType::SOCKET_ALIVE);
105 task_environment.FastForwardBy(base::Seconds(10));
106 base::TimeTicks source1_event1_ticks = base::TimeTicks::Now();
107 source1.EndEvent(NetLogEventType::SOCKET_ALIVE);
108
109 task_environment.FastForwardBy(base::Seconds(1));
110 base::TimeTicks source0_event1_ticks = base::TimeTicks::Now();
111 source0.EndEvent(NetLogEventType::REQUEST_ALIVE);
112
113 task_environment.FastForwardBy(base::Seconds(123));
114
115 entries = net_log_observer.GetEntries();
116 ASSERT_EQ(4u, entries.size());
117
118 EXPECT_EQ(NetLogEventType::REQUEST_ALIVE, entries[0].type);
119 EXPECT_EQ(NetLogSourceType::URL_REQUEST, entries[0].source.type);
120 EXPECT_NE(NetLogSource::kInvalidId, entries[0].source.id);
121 EXPECT_EQ(source0_start_ticks, entries[0].source.start_time);
122 EXPECT_EQ(NetLogEventPhase::BEGIN, entries[0].phase);
123 EXPECT_EQ(source0_event0_ticks, entries[0].time);
124 EXPECT_FALSE(entries[0].HasParams());
125
126 EXPECT_EQ(NetLogEventType::SOCKET_ALIVE, entries[1].type);
127 EXPECT_EQ(NetLogSourceType::SOCKET, entries[1].source.type);
128 EXPECT_NE(NetLogSource::kInvalidId, entries[1].source.id);
129 EXPECT_LT(entries[0].source.id, entries[1].source.id);
130 EXPECT_EQ(source1_start_ticks, entries[1].source.start_time);
131 EXPECT_EQ(NetLogEventPhase::BEGIN, entries[1].phase);
132 EXPECT_EQ(source1_event0_ticks, entries[1].time);
133 EXPECT_FALSE(entries[1].HasParams());
134
135 EXPECT_EQ(NetLogEventType::SOCKET_ALIVE, entries[2].type);
136 EXPECT_EQ(NetLogSourceType::SOCKET, entries[2].source.type);
137 EXPECT_EQ(entries[1].source.id, entries[2].source.id);
138 EXPECT_EQ(source1_start_ticks, entries[2].source.start_time);
139 EXPECT_EQ(NetLogEventPhase::END, entries[2].phase);
140 EXPECT_EQ(source1_event1_ticks, entries[2].time);
141 EXPECT_FALSE(entries[2].HasParams());
142
143 EXPECT_EQ(NetLogEventType::REQUEST_ALIVE, entries[3].type);
144 EXPECT_EQ(NetLogSourceType::URL_REQUEST, entries[3].source.type);
145 EXPECT_EQ(entries[0].source.id, entries[3].source.id);
146 EXPECT_EQ(source0_start_ticks, entries[3].source.start_time);
147 EXPECT_EQ(NetLogEventPhase::END, entries[3].phase);
148 EXPECT_EQ(source0_event1_ticks, entries[3].time);
149 EXPECT_FALSE(entries[3].HasParams());
150 }
151
152 // Check that the correct CaptureMode is sent to NetLog Value callbacks.
TEST(NetLogTest,CaptureModes)153 TEST(NetLogTest, CaptureModes) {
154 NetLogCaptureMode kModes[] = {
155 NetLogCaptureMode::kDefault,
156 NetLogCaptureMode::kIncludeSensitive,
157 NetLogCaptureMode::kEverything,
158 };
159
160 RecordingNetLogObserver net_log_observer;
161
162 for (NetLogCaptureMode mode : kModes) {
163 net_log_observer.SetObserverCaptureMode(mode);
164
165 NetLog::Get()->AddGlobalEntry(NetLogEventType::SOCKET_ALIVE,
166 [&](NetLogCaptureMode capture_mode) {
167 return NetCaptureModeParams(capture_mode);
168 });
169
170 auto entries = net_log_observer.GetEntries();
171
172 ASSERT_EQ(1u, entries.size());
173 EXPECT_EQ(NetLogEventType::SOCKET_ALIVE, entries[0].type);
174 EXPECT_EQ(NetLogSourceType::NONE, entries[0].source.type);
175 EXPECT_NE(NetLogSource::kInvalidId, entries[0].source.id);
176 EXPECT_GE(base::TimeTicks::Now(), entries[0].source.start_time);
177 EXPECT_EQ(NetLogEventPhase::NONE, entries[0].phase);
178 EXPECT_GE(base::TimeTicks::Now(), entries[0].time);
179
180 ASSERT_EQ(CaptureModeToInt(mode),
181 GetIntegerValueFromParams(entries[0], "capture_mode"));
182
183 net_log_observer.Clear();
184 }
185 }
186
187 class CountingObserver : public NetLog::ThreadSafeObserver {
188 public:
189 CountingObserver() = default;
190
~CountingObserver()191 ~CountingObserver() override {
192 if (net_log())
193 net_log()->RemoveObserver(this);
194 }
195
OnAddEntry(const NetLogEntry & entry)196 void OnAddEntry(const NetLogEntry& entry) override { ++count_; }
197
count() const198 int count() const { return count_; }
199
200 private:
201 int count_ = 0;
202 };
203
204 class LoggingObserver : public NetLog::ThreadSafeObserver {
205 public:
206 LoggingObserver() = default;
207
~LoggingObserver()208 ~LoggingObserver() override {
209 if (net_log())
210 net_log()->RemoveObserver(this);
211 }
212
OnAddEntry(const NetLogEntry & entry)213 void OnAddEntry(const NetLogEntry& entry) override {
214 // TODO(https://crbug.com/1418110): This should be updated to be a
215 // base::Value::Dict instead of a std::unique_ptr.
216 std::unique_ptr<base::Value::Dict> dict =
217 std::make_unique<base::Value::Dict>(entry.ToDict());
218 ASSERT_TRUE(dict);
219 values_.push_back(std::move(dict));
220 }
221
GetNumValues() const222 size_t GetNumValues() const { return values_.size(); }
GetDict(size_t index) const223 base::Value::Dict* GetDict(size_t index) const {
224 return values_[index].get();
225 }
226
227 private:
228 std::vector<std::unique_ptr<base::Value::Dict>> values_;
229 };
230
AddEvent(NetLog * net_log)231 void AddEvent(NetLog* net_log) {
232 net_log->AddGlobalEntry(NetLogEventType::CANCELLED,
233 [&](NetLogCaptureMode capture_mode) {
234 return NetCaptureModeParams(capture_mode);
235 });
236 }
237
238 // A thread that waits until an event has been signalled before calling
239 // RunTestThread.
240 class NetLogTestThread : public base::SimpleThread {
241 public:
NetLogTestThread()242 NetLogTestThread() : base::SimpleThread("NetLogTest") {}
243
244 NetLogTestThread(const NetLogTestThread&) = delete;
245 NetLogTestThread& operator=(const NetLogTestThread&) = delete;
246
247 // We'll wait for |start_event| to be triggered before calling a subclass's
248 // subclass's RunTestThread() function.
Init(NetLog * net_log,base::WaitableEvent * start_event)249 void Init(NetLog* net_log, base::WaitableEvent* start_event) {
250 start_event_ = start_event;
251 net_log_ = net_log;
252 }
253
Run()254 void Run() override {
255 start_event_->Wait();
256 RunTestThread();
257 }
258
259 // Subclasses must override this with the code they want to run on their
260 // thread.
261 virtual void RunTestThread() = 0;
262
263 protected:
264 raw_ptr<NetLog> net_log_ = nullptr;
265
266 private:
267 // Only triggered once all threads have been created, to make it less likely
268 // each thread completes before the next one starts.
269 raw_ptr<base::WaitableEvent> start_event_ = nullptr;
270 };
271
272 // A thread that adds a bunch of events to the NetLog.
273 class AddEventsTestThread : public NetLogTestThread {
274 public:
275 AddEventsTestThread() = default;
276
277 AddEventsTestThread(const AddEventsTestThread&) = delete;
278 AddEventsTestThread& operator=(const AddEventsTestThread&) = delete;
279
280 ~AddEventsTestThread() override = default;
281
282 private:
RunTestThread()283 void RunTestThread() override {
284 for (int i = 0; i < kEvents; ++i)
285 AddEvent(net_log_);
286 }
287 };
288
289 // A thread that adds and removes an observer from the NetLog repeatedly.
290 class AddRemoveObserverTestThread : public NetLogTestThread {
291 public:
292 AddRemoveObserverTestThread() = default;
293
294 AddRemoveObserverTestThread(const AddRemoveObserverTestThread&) = delete;
295 AddRemoveObserverTestThread& operator=(const AddRemoveObserverTestThread&) =
296 delete;
297
~AddRemoveObserverTestThread()298 ~AddRemoveObserverTestThread() override { EXPECT_TRUE(!observer_.net_log()); }
299
300 private:
RunTestThread()301 void RunTestThread() override {
302 for (int i = 0; i < kEvents; ++i) {
303 ASSERT_FALSE(observer_.net_log());
304
305 net_log_->AddObserver(&observer_, NetLogCaptureMode::kIncludeSensitive);
306 ASSERT_EQ(net_log_, observer_.net_log());
307 ASSERT_EQ(NetLogCaptureMode::kIncludeSensitive, observer_.capture_mode());
308
309 net_log_->RemoveObserver(&observer_);
310 ASSERT_TRUE(!observer_.net_log());
311 }
312 }
313
314 CountingObserver observer_;
315 };
316
317 // Creates |kThreads| threads of type |ThreadType| and then runs them all
318 // to completion.
319 template <class ThreadType>
RunTestThreads(NetLog * net_log)320 void RunTestThreads(NetLog* net_log) {
321 // Must outlive `threads`.
322 base::WaitableEvent start_event(
323 base::WaitableEvent::ResetPolicy::MANUAL,
324 base::WaitableEvent::InitialState::NOT_SIGNALED);
325
326 ThreadType threads[kThreads];
327 for (size_t i = 0; i < std::size(threads); ++i) {
328 threads[i].Init(net_log, &start_event);
329 threads[i].Start();
330 }
331
332 start_event.Signal();
333
334 for (size_t i = 0; i < std::size(threads); ++i)
335 threads[i].Join();
336 }
337
338 // Makes sure that events on multiple threads are dispatched to all observers.
TEST(NetLogTest,NetLogEventThreads)339 TEST(NetLogTest, NetLogEventThreads) {
340 // Attach some observers. They'll safely detach themselves on destruction.
341 CountingObserver observers[3];
342 for (auto& observer : observers) {
343 NetLog::Get()->AddObserver(&observer, NetLogCaptureMode::kEverything);
344 }
345
346 // Run a bunch of threads to completion, each of which will emit events to
347 // |net_log|.
348 RunTestThreads<AddEventsTestThread>(NetLog::Get());
349
350 // Check that each observer saw the emitted events.
351 const int kTotalEvents = kThreads * kEvents;
352 for (const auto& observer : observers)
353 EXPECT_EQ(kTotalEvents, observer.count());
354 }
355
356 // Test adding and removing a single observer.
TEST(NetLogTest,NetLogAddRemoveObserver)357 TEST(NetLogTest, NetLogAddRemoveObserver) {
358 CountingObserver observer;
359
360 AddEvent(NetLog::Get());
361 EXPECT_EQ(0, observer.count());
362 EXPECT_EQ(nullptr, observer.net_log());
363 EXPECT_FALSE(NetLog::Get()->IsCapturing());
364
365 // Add the observer and add an event.
366 NetLog::Get()->AddObserver(&observer, NetLogCaptureMode::kIncludeSensitive);
367 EXPECT_TRUE(NetLog::Get()->IsCapturing());
368 EXPECT_EQ(NetLog::Get(), observer.net_log());
369 EXPECT_EQ(NetLogCaptureMode::kIncludeSensitive, observer.capture_mode());
370 EXPECT_TRUE(NetLog::Get()->IsCapturing());
371
372 AddEvent(NetLog::Get());
373 EXPECT_EQ(1, observer.count());
374
375 AddEvent(NetLog::Get());
376 EXPECT_EQ(2, observer.count());
377
378 // Remove observer and add an event.
379 NetLog::Get()->RemoveObserver(&observer);
380 EXPECT_EQ(nullptr, observer.net_log());
381 EXPECT_FALSE(NetLog::Get()->IsCapturing());
382
383 AddEvent(NetLog::Get());
384 EXPECT_EQ(2, observer.count());
385
386 // Add the observer a final time, this time with a different capture mdoe, and
387 // add an event.
388 NetLog::Get()->AddObserver(&observer, NetLogCaptureMode::kEverything);
389 EXPECT_EQ(NetLog::Get(), observer.net_log());
390 EXPECT_EQ(NetLogCaptureMode::kEverything, observer.capture_mode());
391 EXPECT_TRUE(NetLog::Get()->IsCapturing());
392
393 AddEvent(NetLog::Get());
394 EXPECT_EQ(3, observer.count());
395 }
396
397 // Test adding and removing two observers at different log levels.
TEST(NetLogTest,NetLogTwoObservers)398 TEST(NetLogTest, NetLogTwoObservers) {
399 LoggingObserver observer[2];
400
401 // Add first observer.
402 NetLog::Get()->AddObserver(&observer[0],
403 NetLogCaptureMode::kIncludeSensitive);
404 EXPECT_EQ(NetLog::Get(), observer[0].net_log());
405 EXPECT_EQ(nullptr, observer[1].net_log());
406 EXPECT_EQ(NetLogCaptureMode::kIncludeSensitive, observer[0].capture_mode());
407 EXPECT_TRUE(NetLog::Get()->IsCapturing());
408
409 // Add second observer observer.
410 NetLog::Get()->AddObserver(&observer[1], NetLogCaptureMode::kEverything);
411 EXPECT_EQ(NetLog::Get(), observer[0].net_log());
412 EXPECT_EQ(NetLog::Get(), observer[1].net_log());
413 EXPECT_EQ(NetLogCaptureMode::kIncludeSensitive, observer[0].capture_mode());
414 EXPECT_EQ(NetLogCaptureMode::kEverything, observer[1].capture_mode());
415 EXPECT_TRUE(NetLog::Get()->IsCapturing());
416
417 // Add event and make sure both observers receive it at their respective log
418 // levels.
419 std::optional<int> param;
420 AddEvent(NetLog::Get());
421 ASSERT_EQ(1U, observer[0].GetNumValues());
422 param = observer[0].GetDict(0)->FindDict("params")->FindInt("capture_mode");
423 ASSERT_TRUE(param);
424 EXPECT_EQ(CaptureModeToInt(observer[0].capture_mode()), param.value());
425 ASSERT_EQ(1U, observer[1].GetNumValues());
426 param = observer[1].GetDict(0)->FindDict("params")->FindInt("capture_mode");
427 ASSERT_TRUE(param);
428 EXPECT_EQ(CaptureModeToInt(observer[1].capture_mode()), param.value());
429
430 // Remove second observer.
431 NetLog::Get()->RemoveObserver(&observer[1]);
432 EXPECT_EQ(NetLog::Get(), observer[0].net_log());
433 EXPECT_EQ(nullptr, observer[1].net_log());
434 EXPECT_EQ(NetLogCaptureMode::kIncludeSensitive, observer[0].capture_mode());
435 EXPECT_TRUE(NetLog::Get()->IsCapturing());
436
437 // Add event and make sure only second observer gets it.
438 AddEvent(NetLog::Get());
439 EXPECT_EQ(2U, observer[0].GetNumValues());
440 EXPECT_EQ(1U, observer[1].GetNumValues());
441
442 // Remove first observer.
443 NetLog::Get()->RemoveObserver(&observer[0]);
444 EXPECT_EQ(nullptr, observer[0].net_log());
445 EXPECT_EQ(nullptr, observer[1].net_log());
446 EXPECT_FALSE(NetLog::Get()->IsCapturing());
447
448 // Add event and make sure neither observer gets it.
449 AddEvent(NetLog::Get());
450 EXPECT_EQ(2U, observer[0].GetNumValues());
451 EXPECT_EQ(1U, observer[1].GetNumValues());
452 }
453
454 // Makes sure that adding and removing observers simultaneously on different
455 // threads works.
TEST(NetLogTest,NetLogAddRemoveObserverThreads)456 TEST(NetLogTest, NetLogAddRemoveObserverThreads) {
457 // Run a bunch of threads to completion, each of which will repeatedly add
458 // and remove an observer, and set its logging level.
459 RunTestThreads<AddRemoveObserverTestThread>(NetLog::Get());
460 }
461
462 // Tests that serializing a NetLogEntry with empty parameters omits a value for
463 // "params".
TEST(NetLogTest,NetLogEntryToValueEmptyParams)464 TEST(NetLogTest, NetLogEntryToValueEmptyParams) {
465 // NetLogEntry with no params.
466 NetLogEntry entry1(NetLogEventType::REQUEST_ALIVE, NetLogSource(),
467 NetLogEventPhase::BEGIN, base::TimeTicks(),
468 base::Value::Dict());
469
470 ASSERT_TRUE(entry1.params.empty());
471 ASSERT_FALSE(entry1.ToDict().Find("params"));
472 }
473
474 } // namespace
475
476 } // namespace net
477