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/capturing_net_log.h"
  21 #include "net/log/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, base::trace_event::TraceOptions());
  95   }
  96
  97   void EndTraceAndFlush() {
  98     base::RunLoop run_loop;
  99     TraceLog::GetInstance()->SetDisabled();
 100     TraceLog::GetInstance()->Flush(
 101         base::Bind(&TraceNetLogObserverTest::OnTraceDataCollected,
 102                    base::Unretained(this), base::Unretained(&run_loop)));
 103     run_loop.Run();
 104   }
 105
 106   void set_trace_net_log_observer(TraceNetLogObserver* trace_net_log_observer) {
 107     trace_net_log_observer_.reset(trace_net_log_observer);
 108   }
 109
 110   static scoped_ptr<base::ListValue> FilterNetLogTraceEvents(
 111       const base::ListValue& trace_events) {
 112     scoped_ptr<base::ListValue> filtered_trace_events(new base::ListValue());
 113     for (size_t i = 0; i < trace_events.GetSize(); i++) {
 114       const base::DictionaryValue* dict = NULL;
 115       if (!trace_events.GetDictionary(i, &dict)) {
 116         ADD_FAILURE() << "Unexpected non-dictionary event in trace_events";
 117         continue;
 118       }
 119       std::string category;
 120       if (!dict->GetString("cat", &category)) {
 121         ADD_FAILURE()
 122             << "Unexpected item without a category field in trace_events";
 123         continue;
 124       }
 125       if (category != kNetLogTracingCategory)
 126         continue;
 127       filtered_trace_events->Append(dict->DeepCopy());
 128     }
 129     return filtered_trace_events.Pass();
 130   }
 131
 132   base::ListValue* trace_events() const { return trace_events_.get(); }
 133
 134   CapturingNetLog* net_log() { return &net_log_; }
 135
 136   TraceNetLogObserver* trace_net_log_observer() const {
 137     return trace_net_log_observer_.get();
 138   }
 139
 140  private:
 141   scoped_ptr<base::ListValue> trace_events_;
 142   base::trace_event::TraceResultBuffer trace_buffer_;
 143   base::trace_event::TraceResultBuffer::SimpleOutput json_output_;
 144   CapturingNetLog net_log_;
 145   scoped_ptr<TraceNetLogObserver> trace_net_log_observer_;
 146 };
 147
 148 TEST_F(TraceNetLogObserverTest, TracingNotEnabled) {
 149   trace_net_log_observer()->WatchForTraceStart(net_log());
 150   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 151
 152   EndTraceAndFlush();
 153   trace_net_log_observer()->StopWatchForTraceStart();
 154
 155   EXPECT_EQ(0u, trace_events()->GetSize());
 156 }
 157
 158 TEST_F(TraceNetLogObserverTest, TraceEventCaptured) {
 159   CapturingNetLog::CapturedEntryList entries;
 160   net_log()->GetEntries(&entries);
 161   EXPECT_TRUE(entries.empty());
 162
 163   trace_net_log_observer()->WatchForTraceStart(net_log());
 164   EnableTraceLog();
 165   BoundNetLog bound_net_log =
 166       BoundNetLog::Make(net_log(), net::NetLog::SOURCE_NONE);
 167   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 168   bound_net_log.BeginEvent(NetLog::TYPE_URL_REQUEST_START_JOB);
 169   bound_net_log.EndEvent(NetLog::TYPE_REQUEST_ALIVE);
 170
 171   net_log()->GetEntries(&entries);
 172   EXPECT_EQ(3u, entries.size());
 173   EndTraceAndFlush();
 174   trace_net_log_observer()->StopWatchForTraceStart();
 175   EXPECT_EQ(3u, trace_events()->GetSize());
 176   const base::DictionaryValue* item1 = NULL;
 177   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 178   const base::DictionaryValue* item2 = NULL;
 179   ASSERT_TRUE(trace_events()->GetDictionary(1, &item2));
 180   const base::DictionaryValue* item3 = NULL;
 181   ASSERT_TRUE(trace_events()->GetDictionary(2, &item3));
 182
 183   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 184   TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
 185   TraceEntryInfo actual_item3 = GetTraceEntryInfoFromValue(*item3);
 186   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 187   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 188   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 189             actual_item1.phase);
 190   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 191             actual_item1.name);
 192   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 193             actual_item1.source_type);
 194
 195   EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
 196   EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id);
 197   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN),
 198             actual_item2.phase);
 199   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB),
 200             actual_item2.name);
 201   EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type),
 202             actual_item2.source_type);
 203
 204   EXPECT_EQ(kNetLogTracingCategory, actual_item3.category);
 205   EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item3.id);
 206   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_END),
 207             actual_item3.phase);
 208   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE),
 209             actual_item3.name);
 210   EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type),
 211             actual_item3.source_type);
 212 }
 213
 214 TEST_F(TraceNetLogObserverTest, EnableAndDisableTracing) {
 215   trace_net_log_observer()->WatchForTraceStart(net_log());
 216   EnableTraceLog();
 217   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 218   TraceLog::GetInstance()->SetDisabled();
 219   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 220   EnableTraceLog();
 221   net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
 222
 223   EndTraceAndFlush();
 224   trace_net_log_observer()->StopWatchForTraceStart();
 225
 226   CapturingNetLog::CapturedEntryList entries;
 227   net_log()->GetEntries(&entries);
 228   EXPECT_EQ(3u, entries.size());
 229   EXPECT_EQ(2u, trace_events()->GetSize());
 230   const base::DictionaryValue* item1 = NULL;
 231   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 232   const base::DictionaryValue* item2 = NULL;
 233   ASSERT_TRUE(trace_events()->GetDictionary(1, &item2));
 234
 235   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 236   TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
 237   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 238   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 239   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 240             actual_item1.phase);
 241   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 242             actual_item1.name);
 243   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 244             actual_item1.source_type);
 245
 246   EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
 247   EXPECT_EQ(base::StringPrintf("0x%d", entries[2].source.id), actual_item2.id);
 248   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 249             actual_item2.phase);
 250   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_URL_REQUEST_START_JOB),
 251             actual_item2.name);
 252   EXPECT_EQ(NetLog::SourceTypeToString(entries[2].source.type),
 253             actual_item2.source_type);
 254 }
 255
 256 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileTracing) {
 257   trace_net_log_observer()->WatchForTraceStart(net_log());
 258   EnableTraceLog();
 259   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 260   trace_net_log_observer()->StopWatchForTraceStart();
 261   set_trace_net_log_observer(NULL);
 262   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 263
 264   EndTraceAndFlush();
 265
 266   CapturingNetLog::CapturedEntryList entries;
 267   net_log()->GetEntries(&entries);
 268   EXPECT_EQ(2u, entries.size());
 269   EXPECT_EQ(1u, trace_events()->GetSize());
 270
 271   const base::DictionaryValue* item1 = NULL;
 272   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 273
 274   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 275   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 276   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 277   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 278             actual_item1.phase);
 279   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 280             actual_item1.name);
 281   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 282             actual_item1.source_type);
 283 }
 284
 285 TEST_F(TraceNetLogObserverTest, DestroyObserverWhileNotTracing) {
 286   trace_net_log_observer()->WatchForTraceStart(net_log());
 287   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 288   trace_net_log_observer()->StopWatchForTraceStart();
 289   set_trace_net_log_observer(NULL);
 290   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 291   net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
 292
 293   EndTraceAndFlush();
 294
 295   CapturingNetLog::CapturedEntryList entries;
 296   net_log()->GetEntries(&entries);
 297   EXPECT_EQ(3u, entries.size());
 298   EXPECT_EQ(0u, trace_events()->GetSize());
 299 }
 300
 301 TEST_F(TraceNetLogObserverTest, CreateObserverAfterTracingStarts) {
 302   set_trace_net_log_observer(NULL);
 303   EnableTraceLog();
 304   set_trace_net_log_observer(new TraceNetLogObserver());
 305   trace_net_log_observer()->WatchForTraceStart(net_log());
 306   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED);
 307   trace_net_log_observer()->StopWatchForTraceStart();
 308   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 309   net_log()->AddGlobalEntry(NetLog::TYPE_URL_REQUEST_START_JOB);
 310
 311   EndTraceAndFlush();
 312
 313   CapturingNetLog::CapturedEntryList entries;
 314   net_log()->GetEntries(&entries);
 315   EXPECT_EQ(3u, entries.size());
 316   EXPECT_EQ(0u, trace_events()->GetSize());
 317 }
 318
 319 TEST_F(TraceNetLogObserverTest, EventsWithAndWithoutParameters) {
 320   trace_net_log_observer()->WatchForTraceStart(net_log());
 321   EnableTraceLog();
 322   NetLog::ParametersCallback net_log_callback;
 323   std::string param = "bar";
 324   net_log_callback = NetLog::StringCallback("foo", &param);
 325
 326   net_log()->AddGlobalEntry(NetLog::TYPE_CANCELLED, net_log_callback);
 327   net_log()->AddGlobalEntry(NetLog::TYPE_REQUEST_ALIVE);
 328
 329   EndTraceAndFlush();
 330   trace_net_log_observer()->StopWatchForTraceStart();
 331
 332   CapturingNetLog::CapturedEntryList entries;
 333   net_log()->GetEntries(&entries);
 334   EXPECT_EQ(2u, entries.size());
 335   EXPECT_EQ(2u, trace_events()->GetSize());
 336   const base::DictionaryValue* item1 = NULL;
 337   ASSERT_TRUE(trace_events()->GetDictionary(0, &item1));
 338   const base::DictionaryValue* item2 = NULL;
 339   ASSERT_TRUE(trace_events()->GetDictionary(1, &item2));
 340
 341   TraceEntryInfo actual_item1 = GetTraceEntryInfoFromValue(*item1);
 342   TraceEntryInfo actual_item2 = GetTraceEntryInfoFromValue(*item2);
 343   EXPECT_EQ(kNetLogTracingCategory, actual_item1.category);
 344   EXPECT_EQ(base::StringPrintf("0x%d", entries[0].source.id), actual_item1.id);
 345   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 346             actual_item1.phase);
 347   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_CANCELLED),
 348             actual_item1.name);
 349   EXPECT_EQ(NetLog::SourceTypeToString(entries[0].source.type),
 350             actual_item1.source_type);
 351
 352   EXPECT_EQ(kNetLogTracingCategory, actual_item2.category);
 353   EXPECT_EQ(base::StringPrintf("0x%d", entries[1].source.id), actual_item2.id);
 354   EXPECT_EQ(std::string(1, TRACE_EVENT_PHASE_NESTABLE_ASYNC_INSTANT),
 355             actual_item2.phase);
 356   EXPECT_EQ(NetLog::EventTypeToString(NetLog::TYPE_REQUEST_ALIVE),
 357             actual_item2.name);
 358   EXPECT_EQ(NetLog::SourceTypeToString(entries[1].source.type),
 359             actual_item2.source_type);
 360
 361   std::string item1_params;
 362   std::string item2_params;
 363   EXPECT_TRUE(item1->GetString("args.params.foo", &item1_params));
 364   EXPECT_EQ("bar", item1_params);
 365
 366   EXPECT_TRUE(item2->GetString("args.params", &item2_params));
 367   EXPECT_TRUE(item2_params.empty());
 368 }
 369
 370 }  // namespace
 371
 372 }  // namespace net