Use NESTABLE_ASYNC APIs to get NetLog data into Tracing

net/base/trace_net_log_observer_unittest.cc

Index: net/base/trace_net_log_observer_unittest.cc
diff --git a/net/base/trace_net_log_observer_unittest.cc b/net/base/trace_net_log_observer_unittest.cc
new file mode 100644
index 0000000000000000000000000000000000000000..b0e7bbaf53bee117b2fc2e4f32f081a64b7f467d
--- /dev/null
+++ b/net/base/trace_net_log_observer_unittest.cc
@@ -0,0 +1,360 @@
+// 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;

[mmenke, 2014/09/02 21:28:59]

nit:  Using directives are usually put outside namespaces.

[xunjieli, 2014/09/02 23:57:17]

Done. Thanks!

+
+struct TraceEntryInfo {
+  std::string category;
+  std::string id;
+  std::string phase;
+  std::string source_type;
+};
+
+TraceEntryInfo GetTraceEntryInfoFromValue(const base::DictionaryValue *value) {

[mmenke, 2014/09/02 21:28:59]

nit:  Asterisk goes before the space.

Actually, though, since the input is const and can't be NULL, passing by
reference is preferred.

[xunjieli, 2014/09/02 23:57:17]

Done. Thanks! I will keep that in mind.

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

[mmenke, 2014/09/02 21:28:59]

nit:

TraceEntryInfo info;
value->GetString("cat", &info.category);
...
return info;

Is a little simpler.

[xunjieli, 2014/09/02 23:57:17]

Done. I see! Thanks!

+}
+
+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) {

[mmenke, 2014/09/02 21:28:59]

nit:  Find -> Get

[xunjieli, 2014/09/02 23:57:17]

Done.

+    std::string type(NetLog::EventTypeToString(event_type));
+    const base::Value* value = NULL;
+    trace_events_.Get(pos, &value);

[mmenke, 2014/09/02 21:28:59]

Can use GetDictionary to save a step.

[xunjieli, 2014/09/02 23:57:17]

Done. Thanks!

+    if (value) {
+      const base::DictionaryValue* dict = NULL;
+      if (value->GetAsDictionary(&dict)) {
+        std::string actual_type;
+        if (dict->GetString("name", &actual_type)) {

[mmenke, 2014/09/02 21:28:59]

I think we don't expose enough on failure - it could be the entry is missing, or
it could be it has the wrong type.  Suggest removing the type from this
function, and make GetTraceEntryInfoFromValue get it as well.

Then this function becomes basically a call to trace_events_.GetDictionary(), so
you may as well just get rid of it, and inline the code, adding an accessor for
trace_events_.

[xunjieli, 2014/09/02 23:57:17]

This is a good point. 
But Trace adds metadata events, no matter what category we are watching.
Therefore, the total number of trace entries does not correspond to the number
of NetLog calls. trace_events can have a metadata event happen in between two
netlog events, so we can't know for sure at which position in the list is a
netlog event. 

Eg.
[{"args":{"params":"","source_type":"NONE"},"cat":"netlog","id":"0x2","name":"CANCELLED","ph":"z","pid":15991,"tid":15991,"ts":35531447013.0,"tts":820024},{"args":{"params":"","source_type":"NONE"},"cat":"netlog","id":"0x1","name":"URL_REQUEST_START_JOB","ph":"x","pid":15991,"tid":15991,"ts":35531447071.0,"tts":820078},{"args":{"params":"","source_type":"NONE"},"cat":"netlog","id":"0x1","name":"REQUEST_ALIVE","ph":"y","pid":15991,"tid":15991,"ts":35531447088.0,"tts":820094},{"args":{"number":40},"cat":"__metadata","name":"num_cpus","ph":"M","pid":15991,"tid":0,"ts":0}]


On 2014/09/02 21:28:59, mmenke wrote:

[mmenke, 2014/09/03 00:07:23]

Thanks, I didn't realize that!

Weird...  I wonder if this is a bug in base::debug::CategoryFilter, since we're
only asking for netlog events.  My suggestion is to filter out non-"cat: netlog"
events in OnTraceDataCollected.  Then we should know exactly what the objects
look like.

Sound reasonable?

On 2014/09/02 23:57:17, xunjieli1 wrote:

+          if (actual_type == type) {
+            return dict;
+          }
+        }
+      }
+    }
+    return NULL;
+  }
+
+  std::vector<const base::DictionaryValue*> FindTraceEntries(

[mmenke, 2014/09/02 21:28:59]

This function adds fuzziness into tests that I don't think we need - we can
check the exact values instead.  First entry should be TYPE_GOAT_NOT_FOUND
event, second should be a TYPE_GOAT_OVERFLOW, etc.

[xunjieli, 2014/09/02 23:57:17]

Acknowledged. Ideally, we should be able to do this. But due to this metadata
events, we can't know for sure at which position in the list a Netlog entry is.

+      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/09/02 21:28:59]

That's certainly true, but I don't see any reason you need to explicitly invoke
the constructor yourself.  It'll be called on construction of the test fixture
itself, and it doesn't look like that will cause any issues.  Am I missing
something?

[xunjieli, 2014/09/02 23:57:17]

Done. I see! Didn't know it is automatically constructed for me. That's
convenient! thanks!

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

[mmenke, 2014/09/02 21:28:59]

This will return clearer failures if you just use sets of 4 EXPECT_EQ entries
here - will give the line number, so you know which items has the mismatch, and
the real/expected values.  Not lovely, but can really help diagnose failures on
the bots.

[xunjieli, 2014/09/02 23:57:17]

Done.

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

[mmenke, 2014/09/02 21:28:59]

If you just check the total number of trace entries under the call to
StopWatchForTraceStart, these are redundant.  Same goes for the other tests

[xunjieli, 2014/09/02 23:57:17]

Acknowledged. Given the metadata events limitation, is there a better way to do
this?

+}
+
+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