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 {

[mmenke, 2014/08/27 19:03:15]

Can we just make these into the constructor and destructor?

[xunjieli, 2014/09/02 16:37:33]

Done.

+    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());

[mmenke, 2014/08/27 19:03:15]

This is redundant with the one above (minor nit:  I suggest not using the get
when checking if a scoped_ptr is non-NULL - we support not using it, so seems
like that should be the preferred style).

[xunjieli, 2014/09/02 16:37:34]

Done. I see. Thanks!

+    ASSERT_TRUE(trace_value->GetAsList(&trace_events));
+    trace_events_.Swap(trace_events);
+  }
+
+  static void EnableTraceLog() {
+    TraceLog::GetInstance()->SetEnabled(
+        base::debug::CategoryFilter("*"),

[mmenke, 2014/08/27 19:03:15]

Could we just filter on "netlog", and then know the exact positions of items in
the log, rather than having to search for them?

[xunjieli, 2014/09/02 16:37:33]

Done. 

+        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 ResetTraceNetLogObserver(TraceNetLogObserver* trace_net_log_observer) {

[mmenke, 2014/08/27 19:03:14]

nit:  More common to call methods that do this "set_trace_net_log_observer" (And
inline them, though you're already doing that here, anyways)

[xunjieli, 2014/09/02 16:37:33]

Done.

+    trace_net_log_observer_.reset(trace_net_log_observer);
+  }
+
+  const base::DictionaryValue* FindTraceEntry(NetLog::EventType event_type,
+                                              size_t& pos) {

[mmenke, 2014/08/27 19:03:15]

Passing in non-const references violates the style guide.  Should pass it as a
size_t*.

[xunjieli, 2014/09/02 16:37:34]

Done. Got it. Thanks!

+    // Scan all items

[mmenke, 2014/08/27 19:03:15]

nit:  Comments should be sentences, and end with periods.

[xunjieli, 2014/09/02 16:37:34]

Acknowledged. I changed the category filter, as you suggested. So I removed this
loop. Thanks!

+    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_;

[mmenke, 2014/08/27 19:03:15]

nit:  I don't think this need to be a scoped_ptr.

[xunjieli, 2014/09/02 16:37:33]

But there is a DISALLOW_COPY_AND_ASSIGN(CapturingNetLog), so I can't do net_log_
= new CapturingNetLog, right?

On 2014/08/27 19:03:15, mmenke wrote:

+  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();
+
+  size_t pos;
+  const base::DictionaryValue* item = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos);
+  EXPECT_FALSE(item);
+}
+
+TEST_F(TraceNetLogObserverTest, TraceEventCaptured) {

[mmenke, 2014/08/27 19:03:15]

Should have an event with PHASE_BEGIN and PHASE_END in this test, as well as an
instant / PHASE_NONE event.

[xunjieli, 2014/09/02 16:37:33]

Done. Thanks!

+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  EXPECT_EQ(0u, entries.size());

[mmenke, 2014/08/27 19:03:15]

Just FYI, entries.empty() is generally preferred for this kind of check, as it
may perform better for large vectors.  For tests, performance doesn't matter,
and the EXPECT_EQ gives us better output on failure, so this is fine as-is.

[xunjieli, 2014/09/02 16:37:33]

Done. I see. Thanks!

+
+  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;
+  size_t pos2;
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  EXPECT_LT(pos1, pos2);
+
+  std::string item1_phase, item2_phase;

[mmenke, 2014/08/27 19:03:15]

These should be declared on separate lines.

[xunjieli, 2014/09/02 16:37:33]

Done. Sorry, I missed this one. Thanks!

+  EXPECT_TRUE(item1 && item1->GetString("ph", &item1_phase));
+  EXPECT_TRUE(item2 && item2->GetString("ph", &item2_phase));

[mmenke, 2014/08/27 19:03:15]

Should just asserting on item1 / item2 when you try to get them.  If they're
NULL, we'll crash a couple lines down, anyways, and most of the rest of the test
is meaningless, anyways.

[xunjieli, 2014/09/02 16:37:33]

Done.

+  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;
+  std::string item2_id;
+  EXPECT_TRUE(item1->GetString("id", &item1_id) &&
+              item2->GetString("id", &item2_id));

[mmenke, 2014/08/27 19:03:14]

nit:  Should have two separate EXPECTs, so if one fails, it's clear which one.

[xunjieli, 2014/09/02 16:37:34]

Done.

+  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;
+  std::string 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;
+  std::string 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);

[mmenke, 2014/08/27 19:03:14]

Suggest making a utility function to clean up this test.  Something like:

struct TraceEntryInfo {
  std::string foo;
  ...
};

TraceEntryInfo GetTranceEntryInfoFromValue(Value* blah) { ... }

Could handle failure a couple ways - just an EXPECT and early return, or
returning a scoped_ptr and just returning an empty one on failure, or could
return a bool and take a TraceEntryInfo* as a parameter.  Sure there are other
options, any of which is fine.

[xunjieli, 2014/09/02 16:37:34]

Done. Thanks!

+
+  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;
+  size_t pos2;
+  size_t pos3;
+  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_LT(pos1, pos3);
+
+  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);

[mmenke, 2014/08/27 19:03:14]

nit:  Don't think we need the final entry.

[xunjieli, 2014/09/02 16:37:33]

Done.

+
+  EndTraceAndFlush();
+
+  size_t pos1;
+  size_t pos2;
+  size_t pos3;
+  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_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;
+  size_t pos2;
+  size_t pos3;
+  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);
+}
+
+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;
+  size_t pos2;
+  size_t pos3;
+  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);
+}
+
+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;
+  size_t pos2;
+  const base::DictionaryValue* item1 = FindTraceEntry(
+      NetLog::TYPE_CANCELLED, pos1);
+  const base::DictionaryValue* item2 = FindTraceEntry(
+      NetLog::TYPE_REQUEST_ALIVE, pos2);
+  EXPECT_LT(pos1, pos2);
+
+  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