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;
+
+class TraceNetLogObserverTest : public testing::Test {
+ public:
+  virtual void SetUp() OVERRIDE {
+    TraceLog::DeleteForTesting();
+    TraceLog* tracelog = TraceLog::GetInstance();
+    ASSERT_TRUE(tracelog);
+    ASSERT_FALSE(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 Trace bug is fixed.
+    TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop();
+  }
+
+  virtual void TearDown() OVERRIDE {
+    EXPECT_FALSE(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.get());
+    ASSERT_TRUE(trace_value->GetAsList(&trace_events));
+    trace_events_.Swap(trace_events);
+  }
+
+  void EnableTraceLog() {
+    TraceLog::GetInstance()->SetEnabled(
+        base::debug::CategoryFilter("*"),
+        TraceLog::RECORDING_MODE,
+        base::debug::TraceOptions());
+  }
+
+  void DisableTraceLog() {

[mmenke, 2014/08/22 18:28:14]

Optional:  May want to make this and EnableTraceLog static, since they don't
affect anything else.

[xunjieli, 2014/08/22 19:04:40]

Done.

+    TraceLog::GetInstance()->SetDisabled();
+  }
+
+  void EndTraceAndFlush() {
+    TraceLog::GetInstance()->SetDisabled();
+    TraceLog::GetInstance()->Flush(
+        Bind(&TraceNetLogObserverTest::OnTraceDataCollected,
+        base::Unretained(this)));
+  }
+
+  void ResetTraceNetLogObserver(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) {
+    // Scan all items
+    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) {
+          pos = i;
+          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_;
+};
+
+const size_t npos = size_t(-1);

[mmenke, 2014/08/22 18:28:14]

I don't think we need this - if FindTraceEntry returns NULL, then it's not set. 
Don't need to check the new value.  If it shouldn't return NULL, then can just
assert it's non-NULL before looking at pos.

[xunjieli, 2014/08/22 19:04:40]

Done.

+
+TEST_F(TraceNetLogObserverTest, TracingNotEnabled) {
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+
+  EndTraceAndFlush();
+  trace_net_log_observer()->StopWatchForTraceStart();
+
+  size_t pos = npos;
+  const base::DictionaryValue* item = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos);
+  EXPECT_FALSE(item);
+  EXPECT_EQ(npos, pos);
+}
+
+TEST_F(TraceNetLogObserverTest, TraceEventCaptured) {
+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  EXPECT_EQ(0u, entries.size());
+
+  trace_net_log_observer()->WatchForTraceStart(net_log());
+  EnableTraceLog();
+  net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+
+  net_log()->GetEntries(&entries);
+  ASSERT_EQ(2u, entries.size());
+
+  EndTraceAndFlush();
+  trace_net_log_observer()->StopWatchForTraceStart();
+
+  size_t pos1, pos2 = npos;

[mmenke, 2014/08/22 18:28:14]

Per Google style guide, use one line per variable.  i.e.

size_t pos1 = ...;
size_t pos2 = ...;
...

[xunjieli, 2014/08/22 19:04:40]

Done.

+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  EXPECT_TRUE(pos1 < pos2);
+
+  std::string item1_phase, item2_phase;
+  EXPECT_TRUE(item1 && item1->GetString("ph", &item1_phase));
+  EXPECT_TRUE(item2 && item2->GetString("ph", &item2_phase));
+  EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NET_LOG_INSTANT), item1_phase);
+  EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NET_LOG_INSTANT), item2_phase);
+
+  std::string item1_id, item2_id;
+  EXPECT_TRUE(item1->GetString("id", &item1_id) &&
+              item2->GetString("id", &item2_id));
+  std::string item1_expected_id =
+      base::StringPrintf("0x%d", entries[0].source.id);
+  std::string item2_expected_id =
+      base::StringPrintf("0x%d", entries[1].source.id);
+  EXPECT_EQ(item1_expected_id, item1_id);
+  EXPECT_EQ(item2_expected_id, item2_id);
+  EXPECT_NE(item1_id, item2_id);
+
+  std::string item1_source_type, item2_source_type;
+  EXPECT_TRUE(item1->GetString("args.source_type", &item1_source_type));
+  EXPECT_TRUE(item2->GetString("args.source_type", &item2_source_type));
+
+  EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
+            item1_source_type);
+  EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type),
+            item2_source_type);
+
+  std::string item1_category, item2_category;
+  EXPECT_TRUE(item1->GetString("cat", &item1_category));
+  EXPECT_TRUE(item2->GetString("cat", &item2_category));
+
+  EXPECT_EQ("netlog", item1_category);
+  EXPECT_EQ("netlog", item2_category);
+
+  EXPECT_EQ(1u, FindTraceEntries(NetLog::TYPE_CANCELLED).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();
+
+  size_t pos1, pos2, pos3 = npos;
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, pos3);
+  EXPECT_TRUE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_TRUE(item3);
+  EXPECT_TRUE(pos2 == npos && pos1 < pos3);

[mmenke, 2014/08/22 18:28:14]

Should use EXPECT_EQ and EXPECT_LT.  They provide more useful output on test
failures.  In general, should never use a top-level && in EXPECT or DCHECK
lines, should split them in two for just that reason.

[xunjieli, 2014/08/22 19:04:39]

Done. Thanks!

+
+  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();
+  ResetTraceNetLogObserver(NULL);
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+  net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
+
+  EndTraceAndFlush();
+
+  size_t pos1, pos2, pos3 = npos;
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, pos3);
+  EXPECT_TRUE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+  EXPECT_TRUE(pos1 != npos && pos2 == npos && pos3 == npos);
+
+  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();
+  ResetTraceNetLogObserver(NULL);
+  net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+  net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
+
+  EndTraceAndFlush();
+
+  size_t pos1, pos2, pos3 = npos;
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, pos3);
+  EXPECT_FALSE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+  EXPECT_TRUE(pos1 == npos && pos2 == npos && pos3 == npos);
+}
+
+TEST_F(TraceNetLogObserverTest, CreateObserverAfterTracingStarts) {
+  ResetTraceNetLogObserver(NULL);
+  EnableTraceLog();
+  ResetTraceNetLogObserver(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();
+
+  size_t pos1, pos2, pos3 = npos;
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  const base::DictionaryValue* item3 = FindTraceEntry(
+      NetLog::TYPE_URL_REQUEST_START_JOB, pos3);
+  EXPECT_FALSE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+  EXPECT_TRUE(pos1 == npos && pos2 == npos && pos3 == npos);
+}
+
+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();
+
+  size_t pos1, pos2 = npos;
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  EXPECT_TRUE(pos1 < pos2);

[mmenke, 2014/08/22 18:28:14]

EXPECT_LE

[xunjieli, 2014/08/22 19:04:40]

Done.

+
+  std::string item1_params, 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