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_buffer.h"
  18 #include "base/trace_event/trace_event.h"
  19 #include "base/trace_event/trace_event_impl.h"
  20 #include "base/values.h"
  21 #include "net/log/net_log.h"
  22 #include "net/log/test_net_log.h"
  23 #include "net/log/test_net_log_entry.h"
  24 #include "testing/gtest/include/gtest/gtest.h"
  25
  26 using base::trace_event::TraceLog;
  27
  28 namespace net {
  29
  30 namespace {
  31
  32 // TraceLog category for NetLog events.
  33 const char kNetLogTracingCategory[] = "netlog";
  34
  35 struct TraceEntryInfo {
  36   std::string category;
  37   std::string id;
  38   std::string phase;
  39   std::string name;
  40   std::string source_type;
  41 };
  42
  43 TraceEntryInfo GetTraceEntryInfoFromValue(const base::DictionaryValue& value) {
  44   TraceEntryInfo info;
  45   EXPECT_TRUE(value.GetString("cat", &info.category));
  46   EXPECT_TRUE(value.GetString("id", &info.id));
  47   EXPECT_TRUE(value.GetString("ph", &info.phase));
  48   EXPECT_TRUE(value.GetString("name", &info.name));
  49   EXPECT_TRUE(value.GetString("args.source_type", &info.source_type));
  50
  51   return info;
  52 }
  53
  54 class TraceNetLogObserverTest : public testing::Test {
  55  public:
  56   TraceNetLogObserverTest() {
  57     TraceLog* tracelog = TraceLog::GetInstance();
  58     DCHECK(tracelog);
  59     DCHECK(!tracelog->IsEnabled());
  60     trace_buffer_.SetOutputCallback(json_output_.GetCallback());
  61     trace_net_log_observer_.reset(new TraceNetLogObserver());
  62     trace_events_.reset(new base::ListValue());
  63   }
  64
  65   ~TraceNetLogObserverTest() override {
  66     DCHECK(!TraceLog::GetInstance()->IsEnabled());
  67   }
  68
  69   void OnTraceDataCollected(
  70       base::RunLoop* run_loop,
  71       const scoped_refptr<base::RefCountedString>& events_str,
  72       bool has_more_events) {
  73     DCHECK(trace_events_->empty());
  74     trace_buffer_.Start();
  75     trace_buffer_.AddFragment(events_str->data());
  76     trace_buffer_.Finish();
  77
  78     scoped_ptr<base::Value> trace_value;
  79     trace_value.reset(base::JSONReader::DeprecatedRead(
  80         json_output_.json_output,
  81         base::JSON_PARSE_RFC | base::JSON_DETACHABLE_CHILDREN));
  82
  83     ASSERT_TRUE(trace_value) << json_output_.json_output;
  84     base::ListValue* trace_events = NULL;
  85     ASSERT_TRUE(trace_value->GetAsList(&trace_events));
  86
  87     trace_events_ = FilterNetLogTraceEvents(*trace_events);
  88
  89     if (!has_more_events)
  90       run_loop->Quit();
  91   }
  92
  93   static void EnableTraceLog() {
  94     TraceLog::GetInstance()->SetEnabled(
  95         base::trace_event::TraceConfig(kNetLogTracingCategory, ""),
  96         TraceLog::RECORDING_MODE);
  97   }
  98
  99   void EndTraceAndFlush() {
 100     base::RunLoop run_loop;
 101     TraceLog::GetInstance()->SetDisabled();
 102     TraceLog::GetInstance()->Flush(
 103         base::Bind(&TraceNetLogObserverTest::OnTraceDataCollected,
 104                    base::Unretained(this), 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 { return trace_events_.get(); }
 135
 136   TestNetLog* net_log() { return &net_log_; }
 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::trace_event::TraceResultBuffer trace_buffer_;
 145   base::trace_event::TraceResultBuffer::SimpleOutput json_output_;
 146   TestNetLog 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   TestNetLogEntry::List 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(kNetLogTracingCategory, 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(kNetLogTracingCategory, 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(kNetLogTracingCategory, 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   TestNetLogEntry::List 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(kNetLogTracingCategory, 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(kNetLogTracingCategory, 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   TestNetLogEntry::List 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(kNetLogTracingCategory, 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   TestNetLogEntry::List 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   TestNetLogEntry::List 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   TestNetLogEntry::List 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(kNetLogTracingCategory, 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(kNetLogTracingCategory, 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