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..0576816566ae77ff5111deee0f770bad4d1241ee 100644
--- a/net/http/http_cache_lookup_manager.cc
+++ b/net/http/http_cache_lookup_manager.cc
@@ -5,65 +5,108 @@
 #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& net_log,
+    std::string push_url,

[eroman, 2017/02/07 22:33:42]

Can you reduce the copying of |push_url| ?

Minimally you can change this to |const std::string&|, however that still does
one unnecessary copy (internal for the callback state).

Zero-copy solutions are (from worst to best)

  (a) Change the parameter type to base::StringPiece -- works, but can become a
UAF if push_helper_->GetURL().spec() were to return a temporary.

  (b) Use base::ConstRef() when binding the callback -- works, but if caller
forgets to add ConstRef() it does a copy

  (c) Change the parameter type to |const std::string*| -- harder to mis-use,
but kind of ugly...

  (d) Change the parameter type to |const ServerPushHelper*|


I suggest option (d)

[Zhongyi Shi, 2017/02/08 00:40:53]

Done.

+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  net_log.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(

[eroman, 2017/02/07 22:33:42]

Instead of creating a new source for this LookupTransaction, what if we output a
BEGIN event during StartLookup  (to the provided net_log), and then a
corresponding END event in OnLookupComplete.

Is there a need to de-couple the LookupTransaction to an independent NetLog
stream?

[Zhongyi Shi, 2017/02/08 00:40:53]

SERVER_PUSH_LOOKUP_TRANSACTION is something similar to a DISK_CACHE_ENTRY. We do
need to provide a NetLogWithSource when run the cache transaction per
https://cs.chromium.org/chromium/src/net/http/http_transaction.h?l=71. It might
be possible that we could create a new source for the HttpCacheLookupManager or
reuse the caller's net log who calls HttpCacheLookupManager::OnPush. 

The HttpCacheLookupManager creates a LookupTransaction every time
HttpCacheLookupManager::OnPush is invoked. It's possible to have a few lookup
transactions pending at the same time, logged in the same net log since server
push cancellation lookup only requires read lock on the cache. This will make it
hard to track a single server push lookup transaction status.

The QuicChromiumClientSession/SpdySession calls HttpCacheLookupManager::OnPush,
it could call OnPush multiple times while having the previous lookup not
returned. I do plan to add some logging linked to the
SERVER_PUSH_LOOKUP_TRANSACTION net_log though(in follow up CLs). 

That's why I decide to have a new source for LookupTransaction, it should be
more straightforward to track the cache lookup results, quite similar to
DISK_CACHE_DISK_CACHE_ENTRY.

Does that make sense? This is the minimal effort to add some basic net log to
verify server push cancellation works, I'll need to come back to add more
granular NetLogs when server push is finally turning on.

[eroman, 2017/02/10 23:57:47]

Sure, that makes sense then!

+          net_log,
+          NetLogSourceType::SERVER_PUSH_LOOKUP_TRANSACTION)) {}
 
-HttpCacheLookupManager::LookupTransaction::~LookupTransaction() {}
+HttpCacheLookupManager::LookupTransaction::~LookupTransaction() {
+  net_log_.EndEvent(NetLogEventType::SERVER_PUSH_LOOKUP_TRANSACTION);

[eroman, 2017/02/07 22:33:42]

What is the meaning for SERVER_PUSH_LOOKUP_TRANSACTION  begin vs end?

Normally if we have an EndEvent() in the destructor, it is to match a
BeginEvent() that took place in the constructor, however that is not the case
here, where the corresponding BeginEvent is part of StartLookup().

Should the Begin/End instead by done by StartLookup vs OnLookupComplete?  (and
if there is a way to cancel, may have multiple paths to mark the "end")

[Zhongyi Shi, 2017/02/08 00:40:53]

Done.

Agreed that it's better to match the Begin/End event. I guess it's better to
have the event logged in StartLookup since that method will be passed in a net
log from the source and we could 
extract source dependency. 

+}
 
 int HttpCacheLookupManager::LookupTransaction::StartLookup(
     HttpCache* cache,
     const CompletionCallback& callback,
     const NetLogWithSource& net_log) {
+  net_log_.BeginEvent(
+      NetLogEventType::SERVER_PUSH_LOOKUP_TRANSACTION,
+      base::Bind(&NetLogPushLookupTransactionCallback, net_log.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,
+      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_);

[eroman, 2017/02/07 22:33:42]

[optional] I found it a bit confusing that here (and in
LookupTransaction::StartLookup) there is a |net_log_| member variable as well as
a |net_log| argument, however they are different things. I suggest picking a
different name for the argument that explains how its role is different.

[Zhongyi Shi, 2017/02/08 00:40:53]

Done.

 
   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(rv == OK);
+  }
 }
 
 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);
 }