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