Use NESTABLE_ASYNC APIs to get NetLog data into Tracing

net/base/trace_net_log_observer_unittest.cc

+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "net/base/trace_net_log_observer.h"
+
+#include <string>
+#include <vector>
+
+#include "base/debug/trace_event.h"
+#include "base/debug/trace_event_impl.h"
+#include "base/json/json_reader.h"
+#include "base/logging.h"
+#include "base/memory/ref_counted.h"
+#include "base/memory/ref_counted_memory.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/strings/stringprintf.h"
+#include "base/values.h"
+#include "net/base/capturing_net_log.h"
+#include "net/base/net_log.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace net {
+
+namespace {
+
+using base::debug::TraceLog;
+
+struct TraceEntryInfo {
+  std::string category;
+  std::string id;
+  std::string phase;
+  std::string source_type;
+};
+
+TraceEntryInfo GetTraceEntryInfoFromValue(const base::DictionaryValue *value) {
+  std::string category;
+  std::string id;
+  std::string phase;
+  std::string source_type;
+  value->GetString("cat", &category);
+  value->GetString("id", &id);
+  value->GetString("ph", &phase);
+  value->GetString("args.source_type", &source_type);
+
+  return TraceEntryInfo{category, id, phase, source_type};
+}
+
+bool TraceEntryInfoEqual(const TraceEntryInfo& a, const TraceEntryInfo& b) {
+  return a.category == b.category &&
+         a.id == b.id &&
+         a.phase == b.phase &&
+         a.source_type == b.source_type;
+}
+
+class TraceNetLogObserverTest : public testing::Test {
+ public:
+  TraceNetLogObserverTest() {
+    TraceLog::DeleteForTesting();
+    TraceLog* tracelog = TraceLog::GetInstance();
+    DCHECK(tracelog);
+    DCHECK(!tracelog->IsEnabled());
+    trace_buffer_.SetOutputCallback(json_output_.GetCallback());
+    net_log_.reset(new CapturingNetLog);
+    trace_net_log_observer_.reset(new TraceNetLogObserver());
+    // TODO(xunjieli): Remove this once the Trace bug (397022) is fixed.
+    TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop();
+  }
+
+  virtual ~TraceNetLogObserverTest() {
+    DCHECK(!TraceLog::GetInstance()->IsEnabled());
+    TraceLog::DeleteForTesting();
+  }
+
+  void OnTraceDataCollected(
+      const scoped_refptr<base::RefCountedString>& events_str,
+      bool has_more_events) {
+    DCHECK(trace_events_.empty());
+    trace_buffer_.Start();
+    trace_buffer_.AddFragment(events_str->data());
+    trace_buffer_.Finish();
+
+    scoped_ptr<base::Value> trace_value;
+    trace_value.reset(base::JSONReader::Read(
+        json_output_.json_output,
+        base::JSON_PARSE_RFC | base::JSON_DETACHABLE_CHILDREN));
+
+    ASSERT_TRUE(trace_value) << json_output_.json_output;
+    base::ListValue* trace_events = NULL;
+    ASSERT_TRUE(trace_value);
+    ASSERT_TRUE(trace_value->GetAsList(&trace_events));
+    trace_events_.Swap(trace_events);
+  }
+
+  static void EnableTraceLog() {
+    TraceLog::GetInstance()->SetEnabled(
+        base::debug::CategoryFilter("netlog"),
+        TraceLog::RECORDING_MODE,
+        base::debug::TraceOptions());
+  }
+
+  static void DisableTraceLog() {
+    TraceLog::GetInstance()->SetDisabled();
+  }
+
+  void EndTraceAndFlush() {
+    TraceLog::GetInstance()->SetDisabled();
+    TraceLog::GetInstance()->Flush(
+        Bind(&TraceNetLogObserverTest::OnTraceDataCollected,
+        base::Unretained(this)));
+  }
+
+  void set_trace_net_log_observer(TraceNetLogObserver* trace_net_log_observer) {
+    trace_net_log_observer_.reset(trace_net_log_observer);
+  }
+
+  const base::DictionaryValue* FindTraceEntry(NetLog::EventType event_type,
+                                              size_t pos) {
+    std::string type(NetLog::EventTypeToString(event_type));
+    const base::Value* value = NULL;
+    trace_events_.Get(pos, &value);
+    if (value) {
+      const base::DictionaryValue* dict = NULL;
+      if (value->GetAsDictionary(&dict)) {
+        std::string actual_type;
+        if (dict->GetString("name", &actual_type)) {
+          if (actual_type == type) {
+            return dict;
+          }
+        }
+      }
+    }
+    return NULL;
+  }
+
+  std::vector<const base::DictionaryValue*> FindTraceEntries(
+      NetLog::EventType event_type) {
+    std::vector<const base::DictionaryValue*> hits;
+    std::string type(NetLog::EventTypeToString(event_type));
+    size_t trace_events_count = trace_events_.GetSize();
+    for (size_t i = 0; i < trace_events_count; i++) {
+      const base::Value* value = NULL;
+      trace_events_.Get(i, &value);
+      const base::DictionaryValue* dict = NULL;
+      if (!value->GetAsDictionary(&dict))
+        continue;
+      std::string actual_type;
+      if (dict->GetString("name", &actual_type)) {
+        if (actual_type == type)
+          hits.push_back(dict);
+      }
+    }
+    return hits;
+  }
+
+  CapturingNetLog* net_log() const {
+    return net_log_.get();
+  }
+
+  TraceNetLogObserver* trace_net_log_observer() const {
+    return trace_net_log_observer_.get();
+  }
+
+ private:
+  base::ListValue trace_events_;
+  base::debug::TraceResultBuffer trace_buffer_;
+  base::debug::TraceResultBuffer::SimpleOutput json_output_;
+  scoped_ptr<CapturingNetLog> net_log_;
+  scoped_ptr<TraceNetLogObserver> trace_net_log_observer_;
+};
+
+TEST_F(TraceNetLogObserverTest, TracingNotEnabled) {
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+
+  EndTraceAndFlush();
+  trace_net_log_observer()->StopWatchForTraceStart();
+
+  const base::DictionaryValue* item = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, 0);
+  EXPECT_FALSE(item);
+}
+
+TEST_F(TraceNetLogObserverTest, TraceEventCaptured) {
+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  EXPECT_TRUE(entries.empty());
+
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  EnableTraceLog();
+  BoundNetLog bound_net_log = BoundNetLog::Make(net_log(),
+                                                net::NetLog::SOURCE_NONE);
+  net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  bound_net_log.BeginEvent(NetLog::TYPE_URL_REQUEST_START_JOB);
+  bound_net_log.EndEvent(NetLog::TYPE_REQUEST_ALIVE);
+
+  net_log()->GetEntries(&entries);
+  ASSERT_EQ(3u, entries.size());
+
+  EndTraceAndFlush();
+  trace_net_log_observer()->StopWatchForTraceStart();
+
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, 0);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, 1);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, 2);
+
+  TraceEntryInfo expected_item1 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[0].source.id),
+      std::string(1, TRACE_EVENT_PHASE_NET_LOG_INSTANT),
+      NetLog::SourceTypeToString(entries[0].source.type)};
+  TraceEntryInfo expected_item2 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[1].source.id),
+      std::string(1, TRACE_EVENT_PHASE_NET_LOG_BEGIN),
+      NetLog::SourceTypeToString(entries[1].source.type)};
+  TraceEntryInfo expected_item3 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[2].source.id),
+      std::string(1, TRACE_EVENT_PHASE_NET_LOG_END),
+      NetLog::SourceTypeToString(entries[2].source.type)};
+
+  EXPECT_TRUE(TraceEntryInfoEqual(expected_item1,
+                                  GetTraceEntryInfoFromValue(item1)));
+  EXPECT_TRUE(TraceEntryInfoEqual(expected_item2,
+                                  GetTraceEntryInfoFromValue(item2)));
+  EXPECT_TRUE(TraceEntryInfoEqual(expected_item3,
+                                  GetTraceEntryInfoFromValue(item3)));
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_CANCELLED).size());
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_URL_REQUEST_START_JOB).size());
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_REQUEST_ALIVE).size());
+}
+
+TEST_F(TraceNetLogObserverTest, EnableAndDisableTracing) {
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  EnableTraceLog();
+  net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  DisableTraceLog();
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+  EnableTraceLog();
+  net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
+
+  EndTraceAndFlush();
+  trace_net_log_observer()->StopWatchForTraceStart();
+
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, 0);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, 1);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, 2);
+  EXPECT_TRUE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_TRUE(item3);
+
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_CANCELLED).size());
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_URL_REQUEST_START_JOB).size());
+}
+
+TEST_F(TraceNetLogObserverTest, DestroyObserverWhileTracing) {
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  EnableTraceLog();
+  net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  trace_net_log_observer()->StopWatchForTraceStart();
+  set_trace_net_log_observer(NULL);
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+
+  EndTraceAndFlush();
+
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, 0);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, 1);
+  EXPECT_TRUE(item1);
+  EXPECT_FALSE(item2);
+
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_CANCELLED).size());
+}
+
+TEST_F(TraceNetLogObserverTest, DestroyObserverWhileNotTracing) {
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  trace_net_log_observer()->StopWatchForTraceStart();
+  set_trace_net_log_observer(NULL);
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+  net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
+
+  EndTraceAndFlush();
+
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, 0);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, 1);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, 2);
+  EXPECT_FALSE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+}
+
+TEST_F(TraceNetLogObserverTest, CreateObserverAfterTracingStarts) {
+  set_trace_net_log_observer(NULL);
+  EnableTraceLog();
+  set_trace_net_log_observer(new TraceNetLogObserver());
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  trace_net_log_observer()->StopWatchForTraceStart();
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+  net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
+
+  EndTraceAndFlush();
+
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, 0);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, 1);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, 2);
+  EXPECT_FALSE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+}
+
+TEST_F(TraceNetLogObserverTest, EventsWithAndWithoutParameters) {
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  EnableTraceLog();
+  NetLog::ParametersCallback net_log_callback;
+  std::string param = "bar";
+  net_log_callback = NetLog::StringCallback("foo",
+                                            &param);
+
+  net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED, net_log_callback);
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+
+  EndTraceAndFlush();
+  trace_net_log_observer()->StopWatchForTraceStart();
+
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, 0);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, 1);
+
+  std::string item1_params;
+  std::string item2_params;
+  EXPECT_TRUE(item1 && item1->GetString("args.params.foo", &item1_params));
+  EXPECT_EQ("bar", item1_params);
+
+  EXPECT_TRUE(item2 && item2->GetString("args.params", &item2_params));
+  EXPECT_TRUE(item2_params.empty());
+
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_CANCELLED).size());
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_REQUEST_ALIVE).size());
+}
+
+}  // namespace
+
+}  // namespace net