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..f7309ad0f2e3b4d1fa04678d3a7497f69f4ff093
--- /dev/null
+++ b/net/base/trace_net_log_observer_unittest.cc
@@ -0,0 +1,320 @@
+// 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 "base/debug/trace_event.h"
+

[mmenke, 2014/08/21 15:35:40]

nit:  Remove blank line.

[xunjieli, 2014/08/22 17:20:10]

Done.

+#include "base/json/json_reader.h"
+#include "base/values.h"
+#include "testing/gtest/include/gtest/gtest.h"

[mmenke, 2014/08/21 15:35:41]

Should include NetLog and TraceLog headers (They're redundant with
trace_net_log_observer.h, but we tend to be fairly cautious with unit test
files).

[xunjieli, 2014/08/22 17:20:11]

Done.

+
+namespace net {
+
+namespace {
+
+using namespace base;

[xunjieli, 2014/08/20 22:00:43]

I think this "using namespace" directive is not recommended. How can I avoid
doing "base::debug::" all the time?

[mmenke, 2014/08/21 15:35:40]

It's not too common in net/, but you can use individual classes (e.g. "using
base::debug::TraceLog"), just can't use entire namespaces.

[xunjieli, 2014/08/22 17:20:11]

Done. Thanks!

+
+// A net log that logs all events by default.
+class MyTestNetLog : public net::NetLog {
+ public:
+  MyTestNetLog() {
+    SetBaseLogLevel(LOG_ALL);

[mmenke, 2014/08/21 15:35:40]

This class shouldn't be needed - the NetLog should automatically adjust its
level when the observer is attached.

[xunjieli, 2014/08/22 17:20:11]

Done. Thanks!

+  }
+  virtual ~MyTestNetLog() {}
+};
+
+class TraceNetLogObserverTest : public testing::Test {
+ public:
+  void OnTraceDataCollected(
+      const scoped_refptr<RefCountedString>& events_str,

[mmenke, 2014/08/21 15:35:40]

Should include base/memory/ref_counted.h, and ref_counted_memory.h.

[xunjieli, 2014/08/22 17:20:11]

Done.

+      bool has_more_events);

[mmenke, 2014/08/21 15:35:41]

nit:  Should inline all functions, to be consistent.

[xunjieli, 2014/08/22 17:20:10]

Done.

+  void Clear() {

[mmenke, 2014/08/21 15:35:41]

nit:  Blank line before clear.

[xunjieli, 2014/08/22 17:20:10]

Done.

+    trace_parsed_.Clear();
+    json_output_.json_output.clear();
+  }
+
+  void EnableTraceLog() {
+    debug::TraceLog::GetInstance()->SetEnabled(
+    debug::CategoryFilter("*"),
+    debug::TraceLog::RECORDING_MODE,
+    debug::TraceOptions());
+  }
+
+  void DisableTraceLog() {
+    debug::TraceLog::GetInstance()->SetDisabled();
+  }
+
+  void EndTraceAndFlush() {
+    debug::TraceLog::GetInstance()->SetDisabled();
+    debug::TraceLog::GetInstance()->Flush(
+        Bind(&TraceNetLogObserverTest::OnTraceDataCollected,
+        Unretained(this)));
+  }
+
+  virtual void SetUp() OVERRIDE {

[mmenke, 2014/08/21 15:35:40]

nit:  Suggest putting SetUp and TearDown first.

[xunjieli, 2014/08/22 17:20:10]

Done. Thanks!

+    debug::TraceLog::DeleteForTesting();
+    debug::TraceLog* tracelog = debug::TraceLog::GetInstance();
+    ASSERT_TRUE(tracelog);
+    ASSERT_FALSE(tracelog->IsEnabled());
+    trace_buffer_.SetOutputCallback(json_output_.GetCallback());
+    net_log_.reset(new MyTestNetLog);
+    trace_net_log_observer_.reset(new TraceNetLogObserver());
+    // TODO(xunjieli): not sure whether this is okay.
+    debug::TraceLog::GetInstance()->SetCurrentThreadBlocksMessageLoop();
+  }
+
+  virtual void TearDown() OVERRIDE {
+    if (debug::TraceLog::GetInstance())

[mmenke, 2014/08/21 15:35:41]

Is this conditional needed?  Looks like it always exists on shutdown, currently.

[xunjieli, 2014/08/22 17:20:11]

Done. Right, I think it is not needed. Thanks!

+      EXPECT_FALSE(debug::TraceLog::GetInstance()->IsEnabled());
+    debug::TraceLog::DeleteForTesting();
+  }
+
+  ListValue trace_parsed_;

[mmenke, 2014/08/21 15:35:41]

These should be private, with accessors as needed.  Google style guide
technically does not allow public variables in classes, even in tests (Though a
lot of tests violate that rule).

[xunjieli, 2014/08/22 17:20:11]

Done. Got it. Thanks!

+  debug::TraceResultBuffer trace_buffer_;
+  debug::TraceResultBuffer::SimpleOutput json_output_;
+  scoped_ptr<NetLog> net_log_;
+  scoped_ptr<TraceNetLogObserver> trace_net_log_observer_;

[mmenke, 2014/08/21 15:35:40]

Should include the scoped_ptr header.

[xunjieli, 2014/08/22 17:20:10]

Done.

+};
+
+
+void TraceNetLogObserverTest::OnTraceDataCollected(
+    const scoped_refptr<RefCountedString>& events_str,
+    bool has_more_events) {
+  json_output_.json_output.clear();

[mmenke, 2014/08/21 15:35:40]

DCHECK(trace_parsed_.empty());?

(DCHECK instead of assert because DCHECKs in tests are sometiems indicate a bug
in the test / test fixture, as opposed to a bug in the code being tested)

Also should include base/logging.h for DCHECK.

[xunjieli, 2014/08/22 17:20:11]

Done. Thanks!

+  trace_buffer_.Start();
+  trace_buffer_.AddFragment(events_str->data());
+  trace_buffer_.Finish();
+
+  scoped_ptr<Value> root;

[mmenke, 2014/08/21 15:35:41]

trace_value, maybe?

[xunjieli, 2014/08/22 17:20:11]

Done.

+  root.reset(JSONReader::Read(json_output_.json_output,
+                              JSON_PARSE_RFC | JSON_DETACHABLE_CHILDREN));
+
+  if (!root.get()) {
+    LOG(ERROR) << json_output_.json_output;
+  }

[mmenke, 2014/08/21 15:35:41]

This can be replaced with:

ASSERT_TRUE(root) << json_output_.json_output;

(And get rid of the ASSERT_TRUE(root.get()) below)

[xunjieli, 2014/08/22 17:20:11]

Done. Thanks! That's convenient!

+
+  ListValue* root_list = NULL;
+  ASSERT_TRUE(root.get());
+  ASSERT_TRUE(root->GetAsList(&root_list));
+
+  while (root_list->GetSize()) {

[mmenke, 2014/08/21 15:35:41]

Rather than copying, this can be replaced with:

trace_parsed_.swap(root_list);

[mmenke, 2014/08/21 15:35:42]

suggest renaming root_list to trace_events and trace_parsed_ to trace_events_
(Or use trace_event_list for both), which I think are a little clearer.

[xunjieli, 2014/08/22 17:20:11]

Done. Thanks!

+    scoped_ptr<Value> item;
+    root_list->Remove(0, &item);
+    trace_parsed_.Append(item.release());
+  }
+}
+
+bool IsStringInDict(const char* string_to_match, const DictionaryValue* dict) {
+  for (DictionaryValue::Iterator it(*dict); !it.IsAtEnd(); it.Advance()) {
+    if (it.key().find(string_to_match) != std::string::npos)
+      return true;
+
+    std::string value_str;

[mmenke, 2014/08/21 15:35:40]

Should include <string>

[xunjieli, 2014/08/22 17:20:10]

Done.

+    it.value().GetAsString(&value_str);
+    if (value_str.find(string_to_match) != std::string::npos)
+      return true;
+  }
+
+  // Recurse to test arguments
+  const DictionaryValue* args_dict = NULL;
+  dict->GetDictionary("args", &args_dict);
+  if (args_dict)
+    return IsStringInDict(string_to_match, args_dict);

[mmenke, 2014/08/21 15:35:41]

This seems much too broad.  Surely we know just where the object is we're
looking for?  If it's a key, a value, or in "args" in some specific place.

[xunjieli, 2014/08/22 17:20:10]

Done. You are right! Thanks!

+
+  return false;
+}
+
+const DictionaryValue* FindTraceEntry(
+    const ListValue& trace_parsed,

[mmenke, 2014/08/21 15:35:41]

Since this is a member of the class, don't need to take it as an argument.

[xunjieli, 2014/08/22 17:20:11]

Done.

+    const char* string_to_match) {

[mmenke, 2014/08/21 15:35:41]

Maybe call this event_type, and just take raw NetLog event types, and convert
them to strings in this function as well?

[xunjieli, 2014/08/22 17:20:10]

Done. That's smart. Thank you!

+  // Scan all items
+  size_t trace_parsed_count = trace_parsed.GetSize();
+  for (size_t i = 0; i < trace_parsed_count; i++) {
+    const Value* value = NULL;
+    trace_parsed.Get(i, &value);
+    if (!value || value->GetType() != Value::TYPE_DICTIONARY)
+      continue;
+    const DictionaryValue* dict = static_cast<const DictionaryValue*>(value);

[mmenke, 2014/08/21 15:35:41]

Should get rid of the type check, and use value->GetAsDictionary(&dict) (Which
returns false on failure)

[xunjieli, 2014/08/22 17:20:10]

Done.

+
+    if (IsStringInDict(string_to_match, dict))

[mmenke, 2014/08/21 15:35:41]

Again, it seems like we should know exactly where the thing we're looking for
it.

[xunjieli, 2014/08/22 17:20:11]

Done.

+      return dict;
+  }
+  return NULL;
+}
+
+}  // namespace

[mmenke, 2014/08/21 15:35:42]

Can just extend the anonymous namespace to the end of the file.

[xunjieli, 2014/08/22 17:20:10]

Done.

+
+TEST_F(TraceNetLogObserverTest, TracingNotEnabled) {
+  trace_net_log_observer_->WatchForTraceStart(net_log_.get());
+  net_log_->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+
+  EndTraceAndFlush();
+
+  trace_net_log_observer_->StopWatchForTraceStart();
+  const DictionaryValue* item = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE));
+  EXPECT_FALSE(item);
+}
+
+
+TEST_F(TraceNetLogObserverTest, TraceEventCaptured) {
+  trace_net_log_observer_->WatchForTraceStart(net_log_.get());
+  EnableTraceLog();
+  net_log_->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+
+  EndTraceAndFlush();
+
+  const DictionaryValue* item = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_CANCELLED));
+  EXPECT_TRUE(item);

[mmenke, 2014/08/21 15:35:40]

Also, maybe log a second event, and make sure order is preserved?

[mmenke, 2014/08/21 15:35:40]

Also, should check other values as well - make sure that EVENT_PHASE is logged
correctly, make sure source IDs end up where they should be.

[mmenke, 2014/08/21 15:35:41]

Should we make sure there's only one such event?

[xunjieli, 2014/08/22 17:20:10]

Done.

[xunjieli, 2014/08/22 17:20:11]

Done.

[xunjieli, 2014/08/22 17:20:11]

Done.

+}
+
+TEST_F(TraceNetLogObserverTest, EnableAndDisableTracing) {
+  trace_net_log_observer_->WatchForTraceStart(net_log_.get());
+  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();
+
+  const DictionaryValue* item1 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_CANCELLED));
+  const DictionaryValue* item2 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE));
+  const DictionaryValue* item3 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB));
+  EXPECT_TRUE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_TRUE(item3);
+}
+
+TEST_F(TraceNetLogObserverTest, DestroyObserverWhileTracing) {
+  trace_net_log_observer_->WatchForTraceStart(net_log_.get());
+  EnableTraceLog();
+  net_log_->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  trace_net_log_observer_->StopWatchForTraceStart();
+  trace_net_log_observer_.reset(NULL);

[xunjieli, 2014/08/20 22:00:43]

Matt, if I just reset the observer scope_ptr, the program will crash, unless I
StopWatchForTraceStart() first. Can this be considered "destroy safely"?

[mmenke, 2014/08/21 15:35:41]

Yes, this is just what you should be doing.

[xunjieli, 2014/08/22 17:20:11]

Done. Thanks!

+  net_log_->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+  net_log_->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
+
+  EndTraceAndFlush();
+
+  const DictionaryValue* item1 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_CANCELLED));
+  const DictionaryValue* item2 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE));
+  const DictionaryValue* item3 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB));
+  EXPECT_TRUE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+}
+
+TEST_F(TraceNetLogObserverTest, DestroyObserverWhileNotTracing) {
+  trace_net_log_observer_->WatchForTraceStart(net_log_.get());
+  net_log_->AddGlobalEntry(NetLog::TYPE_CANCELLED);
+  trace_net_log_observer_->StopWatchForTraceStart();
+  trace_net_log_observer_.reset(NULL);
+  net_log_->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
+  net_log_->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
+
+  EndTraceAndFlush();
+
+  const DictionaryValue* item1 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_CANCELLED));
+  const DictionaryValue* item2 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE));
+  const DictionaryValue* item3 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB));
+  EXPECT_FALSE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+}
+/**
+TEST_F(TraceNetLogObserverTest, CreateObserverAfterTracingStarts) {
+  trace_net_log_observer_.reset(NULL);
+  EnableTraceLog();
+  trace_net_log_observer_.reset(new TraceNetLogObserver());

[xunjieli, 2014/08/20 22:00:43]

If we start the observer after Tracing is enabled, this does not trigger
OnTraceLogEnabled() in the observer. Line 271's EXPECT_TRUE will fail. 

You mentioned that in this case, we should try to fix the behavior. I looked
into this, but I am not sure how to fix it. Do you have any suggestion?

[mmenke, 2014/08/21 15:35:41]

This is probably expected behavior.  I suggest just making sure we don't crash
when tracing stops in this case, and not worry about anything else.

[xunjieli, 2014/08/22 17:20:10]

I see. Thanks!
On 2014/08/21 15:35:41, mmenke wrote:

+  trace_net_log_observer_->WatchForTraceStart(net_log_.get());
+  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 DictionaryValue* item1 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_CANCELLED));
+  const DictionaryValue* item2 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE));
+  const DictionaryValue* item3 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB));
+  EXPECT_TRUE(item1);
+  EXPECT_FALSE(item2);
+  EXPECT_FALSE(item3);
+} **/
+
+TEST_F(TraceNetLogObserverTest, EventsWithAndWithoutParameters) {
+  trace_net_log_observer_->WatchForTraceStart(net_log_.get());
+  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();
+
+  const DictionaryValue* item1 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_CANCELLED));
+  EXPECT_TRUE(item1);
+  const DictionaryValue* item1_args = NULL;
+  item1->GetDictionary("args", &item1_args);
+  EXPECT_TRUE(item1_args);
+  const DictionaryValue* item1_value = NULL;
+  item1_args->GetDictionary("value", &item1_value);
+  EXPECT_TRUE(item1_value);
+  const DictionaryValue* item1_params = NULL;
+  item1_value->GetDictionary("params", &item1_params);
+  EXPECT_TRUE(item1_params);
+  std::string actual_value;
+  item1_params->GetString("foo", &actual_value);
+  EXPECT_EQ("bar", actual_value);

[mmenke, 2014/08/21 15:35:41]

Dictionaries support recursion, I believe, so this can just be replaced with:

ASSERT_TRUE(item->GetString("args.value.params.foo", &actual_value));
ASSERT_EQ("bar", actual_value);

[xunjieli, 2014/08/22 17:20:11]

Done. Thanks for letting me know!

+
+  const DictionaryValue* item2 = FindTraceEntry(
+      trace_parsed_,
+      NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE));
+  EXPECT_TRUE(item2);
+  const DictionaryValue* item2_args = NULL;
+  item2->GetDictionary("args", &item2_args);
+  EXPECT_TRUE(item2_args);
+  const DictionaryValue* item2_value = NULL;
+  item2_args->GetDictionary("value", &item2_value);
+  EXPECT_TRUE(item2_value);
+  const DictionaryValue* item2_params = NULL;
+  item2_value->GetDictionary("params", &item2_params);
+  EXPECT_FALSE(item2_params);
+}

[mmenke, 2014/08/21 15:35:40]

nit:  Blank line before ending a namespace.

[xunjieli, 2014/08/22 17:20:12]

Done.

+}  // namespace net