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"
+
+using base::debug::TraceLog;
+
+namespace net {
+
+namespace {
+
+struct TraceEntryInfo {
+  std::string category;
+  std::string id;
+  std::string phase;
+  std::string name;
+  std::string source_type;
+};
+
+TraceEntryInfo GetTraceEntryInfoFromValue(const base::DictionaryValue& value) {
+  TraceEntryInfo info;
+  value.GetString("cat", &info.category);
+  value.GetString("id", &info.id);
+  value.GetString("ph", &info.phase);
+  value.GetString("name", &info.name);
+  value.GetString("args.source_type", &info.source_type);
+
+  return info;
+}
+
+class TraceNetLogObserverTest : public testing::Test {
+ public:
+  TraceNetLogObserverTest() {
+    TraceLog::DeleteForTesting();
+    TraceLog* tracelog = TraceLog::GetInstance();
+    DCHECK(tracelog);
+    DCHECK(!tracelog->IsEnabled());
+    trace_buffer_.SetOutputCallback(json_output_.GetCallback());
+    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));
+    base::ListValue* filtered_events = FilterNetLogTraceEvents(trace_events);

[mmenke, 2014/09/03 19:12:11]

BUG:  You're leaking |filtered_events| here.

[xunjieli, 2014/09/08 14:08:41]

Done. Thanks!

+    trace_events_.Swap(filtered_events);

[mmenke, 2014/09/03 19:12:11]

Think it makes sense to just switch trace_events_ to a scoped_ptr now, and set
it to filtered_events, instead of swapping it.  This didn't work because because
of the GetAsList call, but now makes life simpler.

[xunjieli, 2014/09/08 14:08:41]

Done.

+  }
+
+  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);
+  }
+
+  base::ListValue* FilterNetLogTraceEvents(base::ListValue* trace_events) {

[mmenke, 2014/09/03 19:12:11]

Should make this:

static scoped_ptr<base::ListValue> FilterNetLogTraceEvents(const
base::ListValue& trace_events)

* static because it doesn't access any member variables.
* scoped_ptr to make ownership semantics clear, and to prevent leaks.
* const base::ListValue& to make it clear the argument can't be NULL (And is not
modified).

[xunjieli, 2014/09/08 14:08:41]

Done. Thanks for the detailed explanation! I will keep this in mind.

+    base::ListValue* filtered_trace_events = new base::ListValue();

[mmenke, 2014/09/03 19:12:11]

Should make this a scoped_ptr as well, and return it with .Pass()

[xunjieli, 2014/09/08 14:08:41]

Done.

+    for (size_t i = 0; i < trace_events->GetSize(); i++) {
+      const base::DictionaryValue* dict = NULL;
+      if (!trace_events->GetDictionary(i, &dict))

[mmenke, 2014/09/03 19:12:11]

completely optional:  Since this isn't expected, may want to add an
ADD_FAILURE() here.  Main reason is if we somehow end up adding
non-dictionaries, and the test fails as a result, failures here will hint at the
problem.  Also indicates to people reading the test it shouldn't happen.

Failures here would have to be failures of the tracing code, so it's not really
necessary.

Same goes for the dict->GetString("cat", ...) call.

[xunjieli, 2014/09/08 14:08:41]

Done.

+        continue;
+      std::string category;
+      if (dict->GetString("cat", &category)) {

[mmenke, 2014/09/03 19:12:11]

nit:  Early abort is preferred, in general, as it reduces nesting, which makes
code a little more readable, in general.  Some cases it can make code less clear
or more regression prone, but I don't think this is one of those cases.

So just:

if (!dict->GetString("cat", &category)))
  continue;
// Flipping this one isn't really necessary, but is more consistent.
if (category != "netlog")
  continue;
filtered_trace_events->Append(dict->DeepCopy());

[xunjieli, 2014/09/08 14:08:41]

Done.

+        if (category == "netlog")
+          filtered_trace_events->Append(dict->DeepCopy());
+      }
+    }
+    return filtered_trace_events;
+  }
+
+  const base::ListValue& trace_events() const {
+    return trace_events_;
+  }
+
+  CapturingNetLog* net_log() {
+    return &net_log_;
+  }
+
+  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_;
+  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();
+
+  EXPECT_EQ(0u, trace_events().GetSize());
+}
+
+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();
+
+  ASSERT_EQ(3u, trace_events().GetSize());
+  const base::DictionaryValue* item1 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(0, &item1));
+  const base::DictionaryValue* item2 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(1, &item2));
+  const base::DictionaryValue* item3 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(2, &item3));

[mmenke, 2014/09/03 19:12:11]

These should all be asserts.

[xunjieli, 2014/09/08 14:08:41]

Done.

+
+  TraceEntryInfo expected_item1 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[0].source.id),
+      std::string(1, TRACE_EVENT_PHASE_ASYNC_NESTABLE_INSTANT),
+      NetLog::EventTypeToString(entries[0].type),
+      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_ASYNC_NESTABLE_BEGIN),
+      NetLog::EventTypeToString(entries[1].type),
+      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_ASYNC_NESTABLE_END),
+      NetLog::EventTypeToString(entries[2].type),
+      NetLog::SourceTypeToString(entries[2].source.type)};

[mmenke, 2014/09/03 19:12:11]

Don't think these get you a whole lot - suggest just inline these values before.
 This goes for other tests, too.

[xunjieli, 2014/09/08 14:08:41]

Partially done. I inlined event types, since those are made explicit in these
tests. I left source id and source type. Is that okay?

+
+  TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
+  TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
+  TraceEntryInfo actual_item3 = GetTraceEntryInfoFromValue(*item3);
+  EXPECT_EQ(expected_item1.category, actual_item1.category);
+  EXPECT_EQ(expected_item1.id, actual_item1.id);
+  EXPECT_EQ(expected_item1.phase, actual_item1.phase);
+  EXPECT_EQ(expected_item1.source_type, actual_item1.source_type);

[mmenke, 2014/09/03 19:12:11]

Should check the names here, too.  This goes for other tests, too.

[xunjieli, 2014/09/08 14:08:41]

Done. Sorry!

+
+  EXPECT_EQ(expected_item2.category, actual_item2.category);
+  EXPECT_EQ(expected_item2.id, actual_item2.id);
+  EXPECT_EQ(expected_item2.phase, actual_item2.phase);
+  EXPECT_EQ(expected_item2.source_type, actual_item2.source_type);
+
+  EXPECT_EQ(expected_item3.category, actual_item3.category);
+  EXPECT_EQ(expected_item3.id, actual_item3.id);
+  EXPECT_EQ(expected_item3.phase, actual_item3.phase);
+  EXPECT_EQ(expected_item3.source_type, actual_item3.source_type);
+}
+
+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();
+
+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  ASSERT_EQ(3u, entries.size());
+  ASSERT_EQ(2u, trace_events().GetSize());
+  const base::DictionaryValue* item1 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(0, &item1));
+  const base::DictionaryValue* item2 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(1, &item2));
+
+  TraceEntryInfo expected_item1 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[0].source.id),
+      std::string(1, TRACE_EVENT_PHASE_ASYNC_NESTABLE_INSTANT),
+      NetLog::EventTypeToString(entries[0].type),
+      NetLog::SourceTypeToString(entries[0].source.type)};
+  TraceEntryInfo expected_item2 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[2].source.id),
+      std::string(1, TRACE_EVENT_PHASE_ASYNC_NESTABLE_INSTANT),
+      NetLog::EventTypeToString(entries[2].type),
+      NetLog::SourceTypeToString(entries[2].source.type)};
+
+  TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
+  TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
+  EXPECT_EQ(expected_item1.category, actual_item1.category);
+  EXPECT_EQ(expected_item1.id, actual_item1.id);
+  EXPECT_EQ(expected_item1.phase, actual_item1.phase);
+  EXPECT_EQ(expected_item1.source_type, actual_item1.source_type);
+
+  EXPECT_EQ(expected_item2.category, actual_item2.category);
+  EXPECT_EQ(expected_item2.id, actual_item2.id);
+  EXPECT_EQ(expected_item2.phase, actual_item2.phase);
+  EXPECT_EQ(expected_item2.source_type, actual_item2.source_type);
+}
+
+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();
+
+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  ASSERT_EQ(2u, entries.size());
+  ASSERT_EQ(1u, trace_events().GetSize());
+
+  const base::DictionaryValue* item1 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(0, &item1));
+
+  TraceEntryInfo expected_item1 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[0].source.id),
+      std::string(1, TRACE_EVENT_PHASE_ASYNC_NESTABLE_INSTANT),
+      NetLog::EventTypeToString(entries[0].type),
+      NetLog::SourceTypeToString(entries[0].source.type)};
+
+  TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
+  EXPECT_EQ(expected_item1.category, actual_item1.category);
+  EXPECT_EQ(expected_item1.id, actual_item1.id);
+  EXPECT_EQ(expected_item1.phase, actual_item1.phase);
+  EXPECT_EQ(expected_item1.source_type, actual_item1.source_type);
+}
+
+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();
+
+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  ASSERT_EQ(3u, entries.size());
+  ASSERT_EQ(0u, trace_events().GetSize());
+}
+
+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();
+
+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  ASSERT_EQ(3u, entries.size());
+  ASSERT_EQ(0u, trace_events().GetSize());
+}
+
+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();
+
+  CapturingNetLog::CapturedEntryList entries;
+  net_log()->GetEntries(&entries);
+  ASSERT_EQ(2u, entries.size());
+  ASSERT_EQ(2u, trace_events().GetSize());
+  const base::DictionaryValue* item1 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(0, &item1));
+  const base::DictionaryValue* item2 = NULL;
+  EXPECT_TRUE(trace_events().GetDictionary(1, &item2));
+
+  TraceEntryInfo expected_item1 = TraceEntryInfo{
+      "netlog",
+      base::StringPrintf("0x%d", entries[0].source.id),
+      std::string(1, TRACE_EVENT_PHASE_ASYNC_NESTABLE_INSTANT),
+      NetLog::EventTypeToString(entries[0].type),
+      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_ASYNC_NESTABLE_INSTANT),
+      NetLog::EventTypeToString(entries[1].type),
+      NetLog::SourceTypeToString(entries[1].source.type)};
+
+  TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
+  TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
+  EXPECT_EQ(expected_item1.category, actual_item1.category);
+  EXPECT_EQ(expected_item1.id, actual_item1.id);
+  EXPECT_EQ(expected_item1.phase, actual_item1.phase);
+  EXPECT_EQ(expected_item1.source_type, actual_item1.source_type);
+
+  EXPECT_EQ(expected_item2.category, actual_item2.category);
+  EXPECT_EQ(expected_item2.id, actual_item2.id);
+  EXPECT_EQ(expected_item2.phase, actual_item2.phase);
+  EXPECT_EQ(expected_item2.source_type, actual_item2.source_type);
+
+  std::string item1_params;
+  std::string item2_params;
+  EXPECT_TRUE(item1->GetString("args.params.foo", &item1_params));
+  EXPECT_EQ("bar", item1_params);
+
+  EXPECT_TRUE(item2->GetString("args.params", &item2_params));
+  EXPECT_TRUE(item2_params.empty());
+}
+
+}  // namespace
+
+}  // namespace net