net_log_unittest.cc 16 KB

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