Bug 1164518 - Better logging of completions. r?gcp draft
authorFrancois Marier <francois@mozilla.com>
Wed, 02 Mar 2016 14:54:59 -0800
changeset 336249 fa106540989ac239884f8fc0ff2a6f1310aea01b
parent 336168 c59c022943f6a7e79f6002e11fc9f56cb836f5dd
child 336250 f510f63b93af675aa5fe16da201328bad2d97b4d
push id12024
push userfmarier@mozilla.com
push dateWed, 02 Mar 2016 23:56:55 +0000
reviewersgcp
bugs1164518
milestone47.0a1
Bug 1164518 - Better logging of completions. r?gcp MozReview-Commit-ID: JqhDC9GzB8l
netwerk/base/nsChannelClassifier.cpp
toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
toolkit/components/url-classifier/nsUrlClassifierHashCompleter.js
--- a/netwerk/base/nsChannelClassifier.cpp
+++ b/netwerk/base/nsChannelClassifier.cpp
@@ -380,16 +380,27 @@ nsChannelClassifier::MarkEntryClassified
     // Should only be called in the parent process.
     MOZ_ASSERT(XRE_IsParentProcess());
 
     // Don't cache tracking classifications because we support allowlisting.
     if (status == NS_ERROR_TRACKING_URI || mIsAllowListed) {
         return;
     }
 
+    if (LOG_ENABLED()) {
+      nsAutoCString errorName;
+      mozilla::GetErrorName(status, errorName);
+      nsCOMPtr<nsIURI> uri;
+      mChannel->GetURI(getter_AddRefs(uri));
+      nsAutoCString spec;
+      uri->GetAsciiSpec(spec);
+      LOG(("nsChannelClassifier::MarkEntryClassified[%s] %s",
+           errorName.get(), spec.get()));
+    }
+
     nsCOMPtr<nsICachingChannel> cachingChannel = do_QueryInterface(mChannel);
     if (!cachingChannel) {
         return;
     }
 
     nsCOMPtr<nsISupports> cacheToken;
     cachingChannel->GetCacheToken(getter_AddRefs(cacheToken));
     if (!cacheToken) {
--- a/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
+++ b/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
@@ -858,16 +858,18 @@ nsUrlClassifierLookupCallback::LookupCom
                result.mTableName.get()));
         } else {
           NS_WARNING("Partial match in a table without a valid completer, ignoring partial match.");
         }
       }
     }
   }
 
+  LOG(("nsUrlClassifierLookupCallback::LookupComplete [%p] "
+       "%u pending completions", this, mPendingCompletions));
   if (mPendingCompletions == 0) {
     // All results were complete, we're ready!
     HandleResults();
   }
 
   return NS_OK;
 }
 
@@ -928,18 +930,24 @@ nsUrlClassifierLookupCallback::Completio
   return NS_OK;
 }
 
 nsresult
 nsUrlClassifierLookupCallback::HandleResults()
 {
   if (!mResults) {
     // No results, this URI is clean.
+    LOG(("nsUrlClassifierLookupCallback::HandleResults [%p, no results]", this));
     return mCallback->HandleEvent(NS_LITERAL_CSTRING(""));
   }
+  MOZ_ASSERT(mPendingCompletions == 0, "HandleResults() should never be "
+             "called while there are pending completions");
+
+  LOG(("nsUrlClassifierLookupCallback::HandleResults [%p, %u results]",
+       this, mResults->Length()));
 
   nsTArray<nsCString> tables;
   // Build a stringified list of result tables.
   for (uint32_t i = 0; i < mResults->Length(); i++) {
     LookupResult& result = mResults->ElementAt(i);
 
     // Leave out results that weren't confirmed, as their existence on
     // the list can't be verified.  Also leave out randomly-generated
@@ -947,17 +955,18 @@ nsUrlClassifierLookupCallback::HandleRes
     if (!result.Confirmed()) {
       LOG(("Skipping result from table %s (not confirmed)", result.mTableName.get()));
       continue;
     } else if (result.mNoise) {
       LOG(("Skipping result from table %s (noise)", result.mTableName.get()));
       continue;
     }
 
-    LOG(("Confirmed result from table %s", result.mTableName.get()));
+    LOG(("Confirmed result %X from table %s",
+         result.hash.prefix.ToUint32(), result.mTableName.get()));
 
     if (tables.IndexOf(result.mTableName) == nsTArray<nsCString>::NoIndex) {
       tables.AppendElement(result.mTableName);
     }
   }
 
   // Some parts of this gethash request generated no hits at all.
   // Prefixes must have been removed from the database since our last update.
--- a/toolkit/components/url-classifier/nsUrlClassifierHashCompleter.js
+++ b/toolkit/components/url-classifier/nsUrlClassifierHashCompleter.js
@@ -537,23 +537,23 @@ HashCompleterRequest.prototype = {
     if (Components.isSuccessCode(aStatusCode)) {
       let channel = aRequest.QueryInterface(Ci.nsIHttpChannel);
       let success = channel.requestSucceeded;
       httpStatus = channel.responseStatus;
       if (!success) {
         aStatusCode = Cr.NS_ERROR_ABORT;
       }
     }
-    log('Received a ' + httpStatus + ' status code from the gethash server.');
+    let success = Components.isSuccessCode(aStatusCode);
+    log('Received a ' + httpStatus + ' status code from the gethash server (success=' + success + ').');
 
     let histogram =
       Services.telemetry.getHistogramById("URLCLASSIFIER_COMPLETE_REMOTE_STATUS");
     histogram.add(httpStatusToBucket(httpStatus));
 
-    let success = Components.isSuccessCode(aStatusCode);
     // Notify the RequestBackoff once a response is received.
     this._completer.finishRequest(this.gethashUrl, httpStatus);
 
     if (success) {
       try {
         this.handleResponse();
       }
       catch (err) {