net/base/trace_net_log_observer_unittest.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "net/base/trace_net_log_observer.h"
   6
   7 #include <string>
   8 #include <vector>
   9
  10 #include "base/json/json_reader.h"
  11 #include "base/logging.h"
  12 #include "base/memory/ref_counted.h"
  13 #include "base/memory/ref_counted_memory.h"
  14 #include "base/memory/scoped_ptr.h"
  15 #include "base/run_loop.h"
  16 #include "base/strings/stringprintf.h"
  17 #include "base/trace_event/trace_event.h"
  18 #include "base/trace_event/trace_event_impl.h"
  19 #include "base/values.h"
  20 #include "net/base/capturing_net_log.h"
  21 #include "net/base/net_log.h"
  22 #include "testing/gtest/include/gtest/gtest.h"
  23
  24 using base::trace_event::TraceLog;
  25
  26 namespace net {
  27
  28 namespace {
  29
  30 // TraceLog category for NetLog events.
  31 const char kNetLogTracingCategory[] = "netlog";
  32
  33 struct TraceEntryInfo {
  34   std::string category;
  35   std::string id;
  36   std::string phase;
  37   std::string name;
  38   std::string source_type;
  39 };
  40
  41 TraceEntryInfo GetTraceEntryInfoFromValue(const base::DictionaryValue& value) {
  42   TraceEntryInfo info;
  43   EXPECT_TRUE(value.GetString("cat", &info.category));
  44   EXPECT_TRUE(value.GetString("id", &info.id));
  45   EXPECT_TRUE(value.GetString("ph", &info.phase));
  46   EXPECT_TRUE(value.GetString("name", &info.name));
  47   EXPECT_TRUE(value.GetString("args.source_type", &info.source_type));
  48
  49   return info;
  50 }
  51
  52 class TraceNetLogObserverTest : public testing::Test {
  53  public:
  54   TraceNetLogObserverTest() {
  55     TraceLog* tracelog = TraceLog::GetInstance();
  56     DCHECK(tracelog);
  57     DCHECK(!tracelog->IsEnabled());
  58     trace_buffer_.SetOutputCallback(json_output_.GetCallback());
  59     trace_net_log_observer_.reset(new TraceNetLogObserver());
  60     trace_events_.reset(new base::ListValue());
  61   }
  62
  63   ~TraceNetLogObserverTest() override {
  64     DCHECK(!TraceLog::GetInstance()->IsEnabled());
  65   }
  66
  67   void OnTraceDataCollected(
  68       base::RunLoop* run_loop,
  69       const scoped_refptr<base::RefCountedString>& events_str,
  70       bool has_more_events) {
  71     DCHECK(trace_events_->empty());
  72     trace_buffer_.Start();
  73     trace_buffer_.AddFragment(events_str->data());
  74     trace_buffer_.Finish();
  75
  76     scoped_ptr<base::Value> trace_value;
  77     trace_value.reset(base::JSONReader::Read(
  78         json_output_.json_output,
  79         base::JSON_PARSE_RFC | base::JSON_DETACHABLE_CHILDREN));
  80
  81     ASSERT_TRUE(trace_value) << json_output_.json_output;
  82     base::ListValue* trace_events = NULL;
  83     ASSERT_TRUE(trace_value->GetAsList(&trace_events));
  84
  85     trace_events_ = FilterNetLogTraceEvents(*trace_events);
  86
  87     if (!has_more_events)
  88       run_loop->Quit();
  89   }
  90
  91   static void EnableTraceLog() {
  92     TraceLog::GetInstance()->SetEnabled(
  93         base::trace_event::CategoryFilter(kNetLogTracingCategory),
  94         TraceLog::RECORDING_MODE,
  95         base::trace_event::TraceOptions());
  96   }
  97
  98   void EndTraceAndFlush() {
  99     base::RunLoop run_loop;
 100     TraceLog::GetInstance()->SetDisabled();
 101     TraceLog::GetInstance()->Flush(
 102         base::Bind(&TraceNetLogObserverTest::OnTraceDataCollected,
 103                    base::Unretained(this),
 104                    base::Unretained(&run_loop)));
 105     run_loop.Run();
 106   }
 107
 108   void set_trace_net_log_observer(TraceNetLogObserver* trace_net_log_observer) {
 109     trace_net_log_observer_.reset(trace_net_log_observer);
 110   }
 111
 112   static scoped_ptr<base::ListValue> FilterNetLogTraceEvents(
 113       const base::ListValue& trace_events) {
 114     scoped_ptr<base::ListValue> filtered_trace_events(new base::ListValue());
 115     for (size_t i = 0; i < trace_events.GetSize(); i++) {
 116       const base::DictionaryValue* dict = NULL;
 117       if (!trace_events.GetDictionary(i, &dict)) {
 118         ADD_FAILURE() << "Unexpected non-dictionary event in trace_events";
 119         continue;
 120       }
 121       std::string category;
 122       if (!dict->GetString("cat", &category)) {
 123         ADD_FAILURE()
 124             << "Unexpected item without a category field in trace_events";
 125         continue;
 126       }
 127       if (category != kNetLogTracingCategory)
 128         continue;
 129       filtered_trace_events->Append(dict->DeepCopy());
 130     }
 131     return filtered_trace_events.Pass();
 132   }
 133
 134   base::ListValue* trace_events() const {
 135     return trace_events_.get();
 136   }
 137
 138   CapturingNetLog* net_log() {
 139     return &net_log_;
 140   }
 141
 142   TraceNetLogObserver* trace_net_log_observer() const {
 143     return trace_net_log_observer_.get();
 144   }
 145
 146  private:
 147   scoped_ptr<base::ListValue> trace_events_;
 148   base::trace_event::TraceResultBuffer trace_buffer_;
 149   base::trace_event::TraceResultBuffer::SimpleOutput json_output_;
 150   CapturingNetLog net_log_;
 151   scoped_ptr<TraceNetLogObserver> trace_net_log_observer_;
 152 };
 153
 154 TEST_F(TraceNetLogObserverTest, TracingNotEnabled) {
 155   trace_net_log_observer()->WatchForTraceStart(net_log());
 156   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 157
 158   EndTraceAndFlush();
 159   trace_net_log_observer()->StopWatchForTraceStart();
 160
 161   EXPECT_EQ(0u, trace_events()->GetSize());
 162 }
 163
 164 TEST_F(TraceNetLogObserverTest, TraceEventCaptured) {
 165   CapturingNetLog::CapturedEntryList entries;
 166   net_log()->GetEntries(&entries);
 167   EXPECT_TRUE(entries.empty());
 168
 169   trace_net_log_observer()->WatchForTraceStart(net_log());
 170   EnableTraceLog();
 171   BoundNetLog bound_net_log =
 172       BoundNetLog::Make(net_log(), net::NetLog::SOURCE_NONE);
 173   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 174   bound_net_log.BeginEvent(NetLog::TYPE_URL_REQUEST_START_JOB);
 175   bound_net_log.EndEvent(NetLog::TYPE_REQUEST_ALIVE);
 176
 177   net_log()->GetEntries(&entries);
 178   EXPECT_EQ(3u, entries.size());
 179   EndTraceAndFlush();
 180   trace_net_log_observer()->StopWatchForTraceStart();
 181   EXPECT_EQ(3u, trace_events()->GetSize());
 182   const base::DictionaryValue* item1 = NULL;
 183   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 184   const base::DictionaryValue* item2 = NULL;
 185   ASSERT_TRUE(trace_events()->GetDictionary(1, &item2));
 186   const base::DictionaryValue* item3 = NULL;
 187   ASSERT_TRUE(trace_events()->GetDictionary(2, &item3));
 188
 189   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 190   TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
 191   TraceEntryInfo actual_item3 = GetTraceEntryInfoFromValue(*item3);
 192   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 193   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 194   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 195             actual_item1.phase);
 196   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 197             actual_item1.name);
 198   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 199             actual_item1.source_type);
 200
 201   EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
 202   EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id);
 203   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN),
 204             actual_item2.phase);
 205   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB),
 206             actual_item2.name);
 207   EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type),
 208             actual_item2.source_type);
 209
 210   EXPECT_EQ(kNetLogTracingCategory, actual_item3.category);
 211   EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item3.id);
 212   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_END),
 213             actual_item3.phase);
 214   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE),
 215             actual_item3.name);
 216   EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type),
 217             actual_item3.source_type);
 218 }
 219
 220 TEST_F(TraceNetLogObserverTest, EnableAndDisableTracing) {
 221   trace_net_log_observer()->WatchForTraceStart(net_log());
 222   EnableTraceLog();
 223   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 224   TraceLog::GetInstance()->SetDisabled();
 225   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 226   EnableTraceLog();
 227   net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
 228
 229   EndTraceAndFlush();
 230   trace_net_log_observer()->StopWatchForTraceStart();
 231
 232   CapturingNetLog::CapturedEntryList entries;
 233   net_log()->GetEntries(&entries);
 234   EXPECT_EQ(3u, entries.size());
 235   EXPECT_EQ(2u, trace_events()->GetSize());
 236   const base::DictionaryValue* item1 = NULL;
 237   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 238   const base::DictionaryValue* item2 = NULL;
 239   ASSERT_TRUE(trace_events()->GetDictionary(1, &item2));
 240
 241   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 242   TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
 243   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 244   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 245   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 246             actual_item1.phase);
 247   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 248             actual_item1.name);
 249   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 250             actual_item1.source_type);
 251
 252   EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
 253   EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item2.id);
 254   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 255             actual_item2.phase);
 256   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB),
 257             actual_item2.name);
 258   EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type),
 259             actual_item2.source_type);
 260 }
 261
 262 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileTracing) {
 263   trace_net_log_observer()->WatchForTraceStart(net_log());
 264   EnableTraceLog();
 265   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 266   trace_net_log_observer()->StopWatchForTraceStart();
 267   set_trace_net_log_observer(NULL);
 268   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 269
 270   EndTraceAndFlush();
 271
 272   CapturingNetLog::CapturedEntryList entries;
 273   net_log()->GetEntries(&entries);
 274   EXPECT_EQ(2u, entries.size());
 275   EXPECT_EQ(1u, trace_events()->GetSize());
 276
 277   const base::DictionaryValue* item1 = NULL;
 278   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 279
 280   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 281   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 282   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 283   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 284             actual_item1.phase);
 285   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 286             actual_item1.name);
 287   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 288             actual_item1.source_type);
 289 }
 290
 291 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileNotTracing) {
 292   trace_net_log_observer()->WatchForTraceStart(net_log());
 293   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 294   trace_net_log_observer()->StopWatchForTraceStart();
 295   set_trace_net_log_observer(NULL);
 296   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 297   net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
 298
 299   EndTraceAndFlush();
 300
 301   CapturingNetLog::CapturedEntryList entries;
 302   net_log()->GetEntries(&entries);
 303   EXPECT_EQ(3u, entries.size());
 304   EXPECT_EQ(0u, trace_events()->GetSize());
 305 }
 306
 307 TEST_F(TraceNetLogObserverTest, CreateObserverAfterTracingStarts) {
 308   set_trace_net_log_observer(NULL);
 309   EnableTraceLog();
 310   set_trace_net_log_observer(new TraceNetLogObserver());
 311   trace_net_log_observer()->WatchForTraceStart(net_log());
 312   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 313   trace_net_log_observer()->StopWatchForTraceStart();
 314   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 315   net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
 316
 317   EndTraceAndFlush();
 318
 319   CapturingNetLog::CapturedEntryList entries;
 320   net_log()->GetEntries(&entries);
 321   EXPECT_EQ(3u, entries.size());
 322   EXPECT_EQ(0u, trace_events()->GetSize());
 323 }
 324
 325 TEST_F(TraceNetLogObserverTest, EventsWithAndWithoutParameters) {
 326   trace_net_log_observer()->WatchForTraceStart(net_log());
 327   EnableTraceLog();
 328   NetLog::ParametersCallback net_log_callback;
 329   std::string param = "bar";
 330   net_log_callback = NetLog::StringCallback("foo", &param);
 331
 332   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED, net_log_callback);
 333   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 334
 335   EndTraceAndFlush();
 336   trace_net_log_observer()->StopWatchForTraceStart();
 337
 338   CapturingNetLog::CapturedEntryList entries;
 339   net_log()->GetEntries(&entries);
 340   EXPECT_EQ(2u, entries.size());
 341   EXPECT_EQ(2u, trace_events()->GetSize());
 342   const base::DictionaryValue* item1 = NULL;
 343   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 344   const base::DictionaryValue* item2 = NULL;
 345   ASSERT_TRUE(trace_events()->GetDictionary(1, &item2));
 346
 347   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 348   TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
 349   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 350   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 351   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 352             actual_item1.phase);
 353   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 354             actual_item1.name);
 355   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 356             actual_item1.source_type);
 357
 358   EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
 359   EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id);
 360   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 361             actual_item2.phase);
 362   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE),
 363             actual_item2.name);
 364   EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type),
 365             actual_item2.source_type);
 366
 367   std::string item1_params;
 368   std::string item2_params;
 369   EXPECT_TRUE(item1->GetString("args.params.foo", &item1_params));
 370   EXPECT_EQ("bar", item1_params);
 371
 372   EXPECT_TRUE(item2->GetString("args.params", &item2_params));
 373   EXPECT_TRUE(item2_params.empty());
 374 }
 375
 376 }  // namespace
 377
 378 }  // namespace net