Add data reduction proxy debug info to net-internals#bandwidth

components/data_reduction_proxy/core/common/data_reduction_proxy_event_store.cc

Index: components/data_reduction_proxy/core/common/data_reduction_proxy_event_store.cc
diff --git a/components/data_reduction_proxy/core/common/data_reduction_proxy_event_store.cc b/components/data_reduction_proxy/core/common/data_reduction_proxy_event_store.cc
index 3e164a67a1b547690c340039ed6139b151922fc4..8a3d9bd7b2419404e1498bdd51050d76c1ad1dd5 100644
--- a/components/data_reduction_proxy/core/common/data_reduction_proxy_event_store.cc
+++ b/components/data_reduction_proxy/core/common/data_reduction_proxy_event_store.cc
@@ -32,10 +32,11 @@ scoped_ptr<base::Value> BuildDataReductionProxyEvent(
   return entry_value;
 }
 
-std::string GetExpirationTicks(int bypass_seconds) {
+int64 GetExpirationTicks(int bypass_seconds) {
   base::TimeTicks ticks_now = base::TimeTicks::Now();
-  return net::NetLog::TickCountToString(
-      ticks_now + base::TimeDelta::FromSeconds(bypass_seconds));
+  base::TimeTicks expiration_ticks = ticks_now +
+      base::TimeDelta::FromSeconds(bypass_seconds);
+  return (expiration_ticks - base::TimeTicks()).InMilliseconds();
 }
 
 // The following callbacks create a base::Value which contains information
@@ -67,30 +68,30 @@ base::Value* DisableDataReductionProxyCallback(
 
 base::Value* UrlBypassActionCallback(const std::string& action,
                                      const GURL& url,
-                                     const base::TimeDelta& bypass_duration,
+                                     int bypass_seconds,
+                                     int64 expiration_ticks,
                                      net::NetLog::LogLevel /* log_level */) {
   base::DictionaryValue* dict = new base::DictionaryValue();
-  int bypass_seconds = bypass_duration.InSeconds();
   dict->SetString("action", action);
   dict->SetString("url", url.spec());
   dict->SetString("bypass_duration_seconds",
                   base::Int64ToString(bypass_seconds));
-  dict->SetString("expiration", GetExpirationTicks(bypass_seconds));
+  dict->SetString("expiration", base::Int64ToString(expiration_ticks));
   return dict;
 }
 
 base::Value* UrlBypassTypeCallback(
     data_reduction_proxy::DataReductionProxyBypassType bypass_type,
     const GURL& url,
-    const base::TimeDelta& bypass_duration,
+    int bypass_seconds,
+    int64 expiration_ticks,
     net::NetLog::LogLevel /* log_level */) {
   base::DictionaryValue* dict = new base::DictionaryValue();
-  int bypass_seconds = bypass_duration.InSeconds();
   dict->SetInteger("bypass_type", bypass_type);
   dict->SetString("url", url.spec());
   dict->SetString("bypass_duration_seconds",
                   base::Int64ToString(bypass_seconds));
-  dict->SetString("expiration", GetExpirationTicks(bypass_seconds));
+  dict->SetString("expiration", base::Int64ToString(expiration_ticks));
   return dict;
 }
 
@@ -100,8 +101,9 @@ namespace data_reduction_proxy {
 
 DataReductionProxyEventStore::DataReductionProxyEventStore(
     const scoped_refptr<base::SingleThreadTaskRunner>& network_task_runner)
-    : network_task_runner_(network_task_runner) {
-}
+    : network_task_runner_(network_task_runner),
+      canary_state_(CANARY_UNKNOWN),
+      expiration_ticks_(0) { }
 
 DataReductionProxyEventStore::~DataReductionProxyEventStore() {
   STLDeleteElements(&stored_events_);
@@ -119,18 +121,20 @@ void DataReductionProxyEventStore::AddProxyEnabledEvent(
       base::Bind(&EnableDataReductionProxyCallback, primary_restricted,
                  fallback_restricted, primary_origin, fallback_origin,
                  ssl_origin);
-  PostGlobalNetLogEvent(net_log,
-                        net::NetLog::TYPE_DATA_REDUCTION_PROXY_ENABLED,
-                        parameters_callback);
+  PostEnabledEvent(net_log,
+                   net::NetLog::TYPE_DATA_REDUCTION_PROXY_ENABLED,
+                   true,
+                   parameters_callback);
 }
 
 void DataReductionProxyEventStore::AddProxyDisabledEvent(
     net::NetLog* net_log) {
   const net::NetLog::ParametersCallback& parameters_callback =
       base::Bind(&DisableDataReductionProxyCallback);
-  PostGlobalNetLogEvent(net_log,
-                        net::NetLog::TYPE_DATA_REDUCTION_PROXY_ENABLED,
-                        parameters_callback);
+  PostEnabledEvent(net_log,
+                   net::NetLog::TYPE_DATA_REDUCTION_PROXY_ENABLED,
+                   false,
+                   parameters_callback);
 }
 
 void DataReductionProxyEventStore::AddBypassActionEvent(
@@ -138,12 +142,17 @@ void DataReductionProxyEventStore::AddBypassActionEvent(
     const std::string& bypass_action,
     const GURL& url,
     const base::TimeDelta& bypass_duration) {
+  int bypass_seconds = bypass_duration.InSeconds();
+  int64 expiration_ticks = GetExpirationTicks(bypass_seconds);
   const net::NetLog::ParametersCallback& parameters_callback =
-      base::Bind(&UrlBypassActionCallback, bypass_action, url, bypass_duration);
-  PostBoundNetLogEvent(net_log,
-                       net::NetLog::TYPE_DATA_REDUCTION_PROXY_BYPASS_REQUESTED,
-                       net::NetLog::PHASE_NONE,
-                       parameters_callback);
+      base::Bind(&UrlBypassActionCallback, bypass_action, url, bypass_seconds,
+                 expiration_ticks);
+  PostBoundNetLogBypassEvent(
+      net_log,
+      net::NetLog::TYPE_DATA_REDUCTION_PROXY_BYPASS_REQUESTED,
+      net::NetLog::PHASE_NONE,
+      expiration_ticks,
+      parameters_callback);
 }
 
 void DataReductionProxyEventStore::AddBypassTypeEvent(
@@ -151,12 +160,17 @@ void DataReductionProxyEventStore::AddBypassTypeEvent(
     DataReductionProxyBypassType bypass_type,
     const GURL& url,
     const base::TimeDelta& bypass_duration) {
+  int bypass_seconds = bypass_duration.InSeconds();
+  int64 expiration_ticks = GetExpirationTicks(bypass_seconds);
   const net::NetLog::ParametersCallback& parameters_callback =
-      base::Bind(&UrlBypassTypeCallback, bypass_type, url, bypass_duration);
-  PostBoundNetLogEvent(net_log,
-                       net::NetLog::TYPE_DATA_REDUCTION_PROXY_BYPASS_REQUESTED,
-                       net::NetLog::PHASE_NONE,
-                       parameters_callback);
+      base::Bind(&UrlBypassTypeCallback, bypass_type, url, bypass_seconds,
+                 expiration_ticks);
+  PostBoundNetLogBypassEvent(
+      net_log,
+      net::NetLog::TYPE_DATA_REDUCTION_PROXY_BYPASS_REQUESTED,
+      net::NetLog::PHASE_NONE,
+      expiration_ticks,
+      parameters_callback);
 }
 
 void DataReductionProxyEventStore::BeginCanaryRequest(
@@ -165,10 +179,12 @@ void DataReductionProxyEventStore::BeginCanaryRequest(
   // This callback must be invoked synchronously
   const net::NetLog::ParametersCallback& parameters_callback =
       net::NetLog::StringCallback("url", &url.spec());
-  PostBoundNetLogEvent(net_log,
-                       net::NetLog::TYPE_DATA_REDUCTION_PROXY_CANARY_REQUEST,
-                       net::NetLog::PHASE_BEGIN,
-                       parameters_callback);
+  PostBoundNetLogCanaryEvent(
+      net_log,
+      net::NetLog::TYPE_DATA_REDUCTION_PROXY_CANARY_REQUEST,
+      net::NetLog::PHASE_BEGIN,
+      CANARY_PENDING,
+      parameters_callback);
 }
 
 void DataReductionProxyEventStore::EndCanaryRequest(
@@ -176,48 +192,119 @@ void DataReductionProxyEventStore::EndCanaryRequest(
     int net_error) {
   const net::NetLog::ParametersCallback& parameters_callback =
       net::NetLog::IntegerCallback("net_error", net_error);
-  PostBoundNetLogEvent(net_log,
-                       net::NetLog::TYPE_DATA_REDUCTION_PROXY_CANARY_REQUEST,
-                       net::NetLog::PHASE_END,
-                       parameters_callback);
+  PostBoundNetLogCanaryEvent(
+      net_log,
+      net::NetLog::TYPE_DATA_REDUCTION_PROXY_CANARY_REQUEST,
+      net::NetLog::PHASE_END,
+      net_error == 0 ? CANARY_SUCCESS : CANARY_FAILED,
+      parameters_callback);
 }
 
-void DataReductionProxyEventStore::PostGlobalNetLogEvent(
+void DataReductionProxyEventStore::PostEnabledEvent(
     net::NetLog* net_log,
     net::NetLog::EventType type,
+    bool enabled,
     const net::NetLog::ParametersCallback& callback) {
   scoped_ptr<base::Value> event = BuildDataReductionProxyEvent(
       type, net::NetLog::Source(), net::NetLog::PHASE_NONE, callback);
   if (event.get()) {
     network_task_runner_->PostTask(
         FROM_HERE,
-        base::Bind(&DataReductionProxyEventStore::AddEventOnIOThread,
+        base::Bind(&DataReductionProxyEventStore::AddEnabledEventOnIOThread,
                    base::Unretained(this),
-                   base::Passed(&event)));
+                   base::Passed(&event),
+                   enabled));
   }
 
   if (net_log)
     net_log->AddGlobalEntry(type, callback);
 }
 
-void DataReductionProxyEventStore::PostBoundNetLogEvent(
+void DataReductionProxyEventStore::PostBoundNetLogBypassEvent(
     const net::BoundNetLog& net_log,
     net::NetLog::EventType type,
     net::NetLog::EventPhase phase,
+    int64 expiration_ticks,
     const net::NetLog::ParametersCallback& callback) {
   scoped_ptr<base::Value> event = BuildDataReductionProxyEvent(
       type, net_log.source(), phase, callback);
   if (event.get()) {
     network_task_runner_->PostTask(
         FROM_HERE,
-        base::Bind(&DataReductionProxyEventStore::AddEventOnIOThread,
-                   base::Unretained(this),
-                   base::Passed(&event)));
+        base::Bind(
+            &DataReductionProxyEventStore::AddAndSetLastBypassEventOnIOThread,
+            base::Unretained(this),
+            base::Passed(&event),
+            expiration_ticks));
   }
 
   net_log.AddEntry(type, phase, callback);
 }
 
+void DataReductionProxyEventStore::PostBoundNetLogCanaryEvent(
+    const net::BoundNetLog& net_log,
+    net::NetLog::EventType type,
+    net::NetLog::EventPhase phase,
+    DataReductionProxyCanaryState state,
+    const net::NetLog::ParametersCallback& callback) {
+  scoped_ptr<base::Value> event = BuildDataReductionProxyEvent(

[bengr, 2014/12/02 23:55:32]

Move BuildData... down with the next line.

[jeremyim, 2014/12/03 08:10:37]

Done.

+      type, net_log.source(), phase, callback);
+  if (event.get()) {
+    network_task_runner_->PostTask(
+        FROM_HERE,
+        base::Bind(
+            &DataReductionProxyEventStore::AddEventAndCanaryStateOnIOThread,
+            base::Unretained(this),
+            base::Passed(&event),
+            state));
+  }
+
+  net_log.AddEntry(type, phase, callback);
+}
+
+void DataReductionProxyEventStore::AddStoredEvents (
+    base::DictionaryValue* data_reduction_proxy_values) const {
+  DCHECK(network_task_runner_->BelongsToCurrentThread());
+
+  switch (canary_state_) {
+    case CANARY_PENDING:
+      data_reduction_proxy_values->SetString("canary", "Pending");
+      break;
+    case CANARY_SUCCESS:
+      data_reduction_proxy_values->SetString("canary", "Success");
+      break;
+    case CANARY_FAILED:
+      data_reduction_proxy_values->SetString("canary", "Failed");
+      break;
+    default:
+      break;

[bengr, 2014/12/02 23:55:32]

Should this be explicit that it is NOTREACHED?

[jeremyim, 2014/12/03 08:10:37]

Done.

+  }
+
+  base::Value* last_bypass_event = last_bypass_event_.get();
+  if (last_bypass_event != nullptr) {
+    int cur_time_ticks_ms =
+        (base::TimeTicks::Now() - base::TimeTicks()).InMilliseconds();

[bengr, 2014/12/02 23:55:32]

This is a little strange. I don't know if base::TimeTicks() is guaranteed to be
anything in particular.

[jeremyim, 2014/12/03 08:10:37]

base::TimeTicks() is time(0); this construct is used in net_log_util.cc

+    if (expiration_ticks_ > cur_time_ticks_ms) {

[bengr, 2014/12/02 23:55:32]

current_time_ticks_milliseconds or current_time_ticks_ms.

[jeremyim, 2014/12/03 08:10:37]

Done.

+      data_reduction_proxy_values->Set("last_bypass",
+                                       last_bypass_event->DeepCopy());
+    }
+  }
+
+  base::Value* current_configuration = current_configuration_.get();
+  if (current_configuration != nullptr) {
+    data_reduction_proxy_values->Set("proxy_config",
+                                     current_configuration->DeepCopy());
+  }
+
+  base::ListValue* eventsList = new base::ListValue();
+  for (size_t i = 0; i < stored_events_.size(); i++) {
+    base::Value* event = stored_events_[i];
+    eventsList->Append(event->DeepCopy());
+  }
+
+  data_reduction_proxy_values->Set("events", eventsList);
+}
+
 void DataReductionProxyEventStore::AddEventOnIOThread(
     scoped_ptr<base::Value> entry) {
   DCHECK(network_task_runner_->BelongsToCurrentThread());
@@ -230,4 +317,32 @@ void DataReductionProxyEventStore::AddEventOnIOThread(
   stored_events_.push_back(entry.release());
 }
 
+void DataReductionProxyEventStore::AddEnabledEventOnIOThread(
+    scoped_ptr<base::Value> entry,
+    bool enabled) {
+  DCHECK(network_task_runner_->BelongsToCurrentThread());
+  if (enabled)
+    current_configuration_.reset(entry->DeepCopy());
+  else
+    current_configuration_.reset();
+  AddEventOnIOThread(entry.Pass());
+}
+
+void DataReductionProxyEventStore::AddEventAndCanaryStateOnIOThread(
+    scoped_ptr<base::Value> entry,
+    DataReductionProxyCanaryState state) {
+  DCHECK(network_task_runner_->BelongsToCurrentThread());
+  canary_state_ = state;
+  AddEventOnIOThread(entry.Pass());
+}
+
+void DataReductionProxyEventStore::AddAndSetLastBypassEventOnIOThread(
+    scoped_ptr<base::Value> entry,
+    int64 expiration_ticks) {
+  DCHECK(network_task_runner_->BelongsToCurrentThread());
+  last_bypass_event_.reset(entry->DeepCopy());
+  expiration_ticks_ = expiration_ticks;
+  AddEventOnIOThread(entry.Pass());
+}
+
 }  // namespace data_reduction_proxy