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