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..b48be1a07fe68af04a2335d19cb05664a96bc47a 100644
--- a/net/http/http_cache_lookup_manager.cc
+++ b/net/http/http_cache_lookup_manager.cc
@@ -5,65 +5,105 @@
 #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,
+    const ServerPushDelegate::ServerPushHelper* push_helper,
+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  net_log.AddToEventParameters(dict.get());
+  dict->SetString("push_url", push_helper->GetURL().spec());

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

[optional] Consider using |possibly_invalid_spec()| instead of |spec()|.

The difference is what happens should GetURL() return an invalid URL.

[Zhongyi Shi, 2017/02/11 02:21:10]

Done.

+  return std::move(dict);
+}
+
+std::unique_ptr<base::Value> NetLogServerPushLookupCompleteCallback(

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

[optional] You can remove this function and use
NetLog::BoolCallback("found_in_cache", found_in_cache) in its place.

[Zhongyi Shi, 2017/02/11 02:21:10]

Done.

+    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::SERVER_PUSH_LOOKUP_TRANSACTION)) {}
 
 HttpCacheLookupManager::LookupTransaction::~LookupTransaction() {}
 
 int HttpCacheLookupManager::LookupTransaction::StartLookup(
     HttpCache* cache,
     const CompletionCallback& callback,
-    const NetLogWithSource& net_log) {
+    const NetLogWithSource& source_net_log) {
+  net_log_.BeginEvent(NetLogEventType::SERVER_PUSH_LOOKUP_TRANSACTION,
+                      base::Bind(&NetLogPushLookupTransactionCallback,
+                                 source_net_log.source(), push_helper_.get()));
+
   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() {
-  DCHECK(push_helper_.get());
-  push_helper_->Cancel();
+void HttpCacheLookupManager::LookupTransaction::OnLookupComplete(
+    bool found_in_cache) {
+  net_log_.AddEvent(
+      NetLogEventType::SERVER_PUSH_LOOKUP_COMPLETE,

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

Seems like we can remove this event, and instead put the |found_in_cache|
parameter as part of the event logged below. WDYT?

Otherwise we are always logging two events here.

It is fairly common to attach parameters to the start/end events, see for
instance:

https://cs.chromium.org/chromium/src/net/log/net_log_event_type_list.h?type=c...

(searching for "net_error" in that file will reveal several others)

[Zhongyi Shi, 2017/02/11 02:21:10]

Thanks for the pointer, this greatly simplified the log events.

+      base::Bind(&NetLogServerPushLookupCompleteCallback, found_in_cache));
+  if (found_in_cache) {
+    DCHECK(push_helper_.get());
+    push_helper_->Cancel();
+  }
+  net_log_.EndEvent(NetLogEventType::SERVER_PUSH_LOOKUP_TRANSACTION);
 }
 
 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& source_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/10 23:57:47]

[optional] It is also common practice to add a breadcrumb in the opposite
direction too -- which in this case would mean emitting an event to the session
that called OnPush() telling it the NetLogSource of the created
LookupTransaction.

If I understood one of your previous responses, your plan is to add this in a
follow-up CL?

[Zhongyi Shi, 2017/02/11 02:21:10]

Yup, I did plan to add this in a follow-up CL after the finch turns on this
feature. 

 
   int rv = lookup->StartLookup(
       http_cache_, base::Bind(&HttpCacheLookupManager::OnLookupComplete,
                               weak_factory_.GetWeakPtr(), pushed_url),
-      net_log_);
+      source_net_log);
 
-  if (rv == ERR_IO_PENDING)
+  if (rv == ERR_IO_PENDING) {
     lookup_transactions_[pushed_url] = std::move(lookup);
+  } else {
+    lookup->OnLookupComplete(rv == OK);

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

[optional] Have you considered making the parameter to OnLookupComplete() be an
error code rather than a boolean? Given all the callsites are interpreting
completion in the same way (rv == OK) that may remove some duplication, and also
allow logging the raw value of |rv| in the log (which may be handy in case it
has some unexpected error value).

[Zhongyi Shi, 2017/02/11 02:21:10]

Done.

+  }
 }
 
 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);
 }