Server push cancellation: add NetLogs to track cache lookup transaction

net/http/http_cache_lookup_manager.cc

Index: net/http/http_cache_lookup_manager.cc
diff --git a/net/http/http_cache_lookup_manager.cc b/net/http/http_cache_lookup_manager.cc
index d4d8a2e023e2de5a99a0a548d4a3187959a0c7b7..8c86ab455227e00d73685c4bb35560d88e78a261 100644
--- a/net/http/http_cache_lookup_manager.cc
+++ b/net/http/http_cache_lookup_manager.cc
@@ -5,65 +5,109 @@
 #include "net/http/http_cache_lookup_manager.h"
 
 #include "base/memory/ptr_util.h"
+#include "base/values.h"
 #include "net/base/load_flags.h"
 
 namespace net {
 
+// Returns parameters associated with the start of a server push lookup
+// transaction.
+std::unique_ptr<base::Value> NetLogPushLookupTransactionCallback(
+    const NetLogSource& source,

[Ryan Hamilton, 2017/02/07 15:22:58]

nit: this should be net_log

[Zhongyi Shi, 2017/02/07 19:08:22]

Done.

+    std::string push_url,
+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  if (source.IsValid())

[Ryan Hamilton, 2017/02/07 15:22:58]

Under what circumstances will this not be valid?

[Zhongyi Shi, 2017/02/07 19:08:22]

Done.

I thought the tests would have the invalid id, looking at the source of
NetLogSource, I'm wrong. A NetLogSource constructed implicitly should always has
an valid id.

+    source.AddToEventParameters(dict.get());
+  dict->SetString("push_url", push_url);
+  return std::move(dict);
+}
+
+std::unique_ptr<base::Value> NetLogServerPushLookupCompleteCallback(
+    bool found_in_cache,
+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  dict->SetBoolean("found_in_cache", found_in_cache);
+  return std::move(dict);
+}
+
 HttpCacheLookupManager::LookupTransaction::LookupTransaction(
-    std::unique_ptr<ServerPushHelper> server_push_helper)
+    std::unique_ptr<ServerPushHelper> server_push_helper,
+    NetLog* net_log)
     : push_helper_(std::move(server_push_helper)),
       request_(new HttpRequestInfo()),
-      transaction_(nullptr) {}
+      transaction_(nullptr),
+      net_log_(
+          NetLogWithSource::Make(net_log,
+                                 NetLogSourceType::PUSH_LOOKUP_TRANSACTION)) {}
 
-HttpCacheLookupManager::LookupTransaction::~LookupTransaction() {}
+HttpCacheLookupManager::LookupTransaction::~LookupTransaction() {
+  net_log_.EndEvent(NetLogEventType::PUSH_LOOKUP_TRANSACTION);
+}
 
 int HttpCacheLookupManager::LookupTransaction::StartLookup(
     HttpCache* cache,
     const CompletionCallback& callback,
-    const NetLogWithSource& net_log) {
+    const NetLogWithSource& source) {
+  net_log_.BeginEvent(
+      NetLogEventType::PUSH_LOOKUP_TRANSACTION,
+      base::Bind(&NetLogPushLookupTransactionCallback, source.source(),
+                 push_helper_->GetURL().spec()));
+
   request_->url = push_helper_->GetURL();
   request_->method = "GET";
   request_->load_flags = LOAD_ONLY_FROM_CACHE | LOAD_SKIP_CACHE_VALIDATION;
   cache->CreateTransaction(DEFAULT_PRIORITY, &transaction_);
-  return transaction_->Start(request_.get(), callback, net_log);
+  return transaction_->Start(request_.get(), callback, net_log_);
 }
 
-void HttpCacheLookupManager::LookupTransaction::CancelPush() {
+void HttpCacheLookupManager::LookupTransaction::OnLookupComplete(
+    bool found_in_cache) {
+  net_log_.AddEvent(
+      NetLogEventType::SERVER_PUSH_LOOKUP_COMPLETE,

[Ryan Hamilton, 2017/02/07 15:22:58]

nit: This is called SERVER_PUSH_... and the other is just PUSH_... It'd be best
to be consistent.

[Zhongyi Shi, 2017/02/07 19:08:21]

Done.

+      base::Bind(&NetLogServerPushLookupCompleteCallback, found_in_cache));
+  if (!found_in_cache)
+    return;
+
   DCHECK(push_helper_.get());
   push_helper_->Cancel();
 }
 
 HttpCacheLookupManager::HttpCacheLookupManager(HttpCache* http_cache,
-                                               const NetLogWithSource& net_log)
+                                               NetLog* net_log)
     : net_log_(net_log), http_cache_(http_cache), weak_factory_(this) {}
 
 HttpCacheLookupManager::~HttpCacheLookupManager() {}
 
 void HttpCacheLookupManager::OnPush(
-    std::unique_ptr<ServerPushHelper> push_helper) {
+    std::unique_ptr<ServerPushHelper> push_helper,
+    const NetLogWithSource& net_log) {
   GURL pushed_url = push_helper->GetURL();
 
   // There's a pending lookup transaction sent over already.
   if (base::ContainsKey(lookup_transactions_, pushed_url))
     return;
 
-  auto lookup = base::MakeUnique<LookupTransaction>(std::move(push_helper));
+  auto lookup =
+      base::MakeUnique<LookupTransaction>(std::move(push_helper), net_log_);
 
   int rv = lookup->StartLookup(
       http_cache_, base::Bind(&HttpCacheLookupManager::OnLookupComplete,
                               weak_factory_.GetWeakPtr(), pushed_url),
-      net_log_);
+      net_log);
 
-  if (rv == ERR_IO_PENDING)
+  if (rv == ERR_IO_PENDING) {
     lookup_transactions_[pushed_url] = std::move(lookup);
+  } else {
+    lookup->OnLookupComplete(false);

[Ryan Hamilton, 2017/02/07 15:22:58]

I would have thought this would be OnLookupComplete(rv == OK);

Or perhaps this is guaranteed to not return OK synchronously so then
  DCHECK_NE(OK, rv);
  OnLookupComplete(false);
?

[Zhongyi Shi, 2017/02/07 19:08:22]

Done.

An synchronous return should imply that the cache index doesn't have the entry.
Either way should be fine, but the first one sounds more safe. 

+  }
 }
 
 void HttpCacheLookupManager::OnLookupComplete(const GURL& url, int rv) {
   auto it = lookup_transactions_.find(url);
   DCHECK(it != lookup_transactions_.end());
 
-  if (rv == OK)
-    it->second->CancelPush();
+  it->second->OnLookupComplete(rv == OK);
 
   lookup_transactions_.erase(it);
 }