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