trace_net_log_observer_unittest.cc 17 KB

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