Bug 1461534 - Improve logging for the channel classifier. r=dimi

This patch reduces the level of noise in MOZ_LOG messages by:

- splitting log messages into Warning, Info, and Debug levels
- truncating long URIs down to the first 128 bytes
- not mentioning suspended channels on NS_OK results

It also introduces new log messages for the outcome of a
match against the blacklist:

- dropping the channel priority (tracking annotations)
- cancelling the channel (tracking protection)
- no match (i.e. not a tracker)

MozReview-Commit-ID: wSQChJkMKv

--HG--
extra : rebase_source : 620c0b8f7094fa001d2389c99cbee6d547627fd9

netwerk/base/nsChannelClassifier.cpp

@@ -52,15 +52,18 @@ namespace net {
 //
 static LazyLogModule gChannelClassifierLog("nsChannelClassifier");
 
-
 #undef LOG
-#define LOG(args)     MOZ_LOG(gChannelClassifierLog, LogLevel::Debug, args)
+#define LOG(args) MOZ_LOG(gChannelClassifierLog, LogLevel::Info, args)
-#define LOG_ENABLED() MOZ_LOG_TEST(gChannelClassifierLog, LogLevel::Debug)
+#define LOG_DEBUG(args) MOZ_LOG(gChannelClassifierLog, LogLevel::Debug, args)
+#define LOG_WARN(args) MOZ_LOG(gChannelClassifierLog, LogLevel::Warning, args)
+#define LOG_ENABLED() MOZ_LOG_TEST(gChannelClassifierLog, LogLevel::Info)
 
 #define URLCLASSIFIER_SKIP_HOSTNAMES       "urlclassifier.skipHostnames"
 #define URLCLASSIFIER_TRACKING_WHITELIST   "urlclassifier.trackingWhitelistTable"
 #define URLCLASSIFIER_TRACKING_TABLE       "urlclassifier.trackingTable"
 
+static const nsCString::size_type sMaxSpecLength = 128;
+
 // Put CachedPrefs in anonymous namespace to avoid any collision from outside of
 // this file.
 namespace {
@@ -235,6 +238,15 @@ LowerPriorityHelper(nsIChannel* aChannel)
   if (!isBlockingResource) {
     nsCOMPtr<nsISupportsPriority> p = do_QueryInterface(aChannel);
     if (p) {
+      if (LOG_ENABLED()) {
+        nsCOMPtr<nsIURI> uri;
+        aChannel->GetURI(getter_AddRefs(uri));
+        nsAutoCString spec;
+        uri->GetAsciiSpec(spec);
+        spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
+        LOG(("Setting PRIORITY_LOWEST for channel[%p] (%s)",
+             aChannel, spec.get()));
+      }
       p->SetPriority(nsISupportsPriority::PRIORITY_LOWEST);
     }
   }
@@ -251,13 +263,13 @@ nsChannelClassifier::nsChannelClassifier(nsIChannel *aChannel)
     mTrackingProtectionEnabled(Nothing()),
     mTrackingAnnotationEnabled(Nothing())
 {
-  LOG(("nsChannelClassifier::nsChannelClassifier %p", this));
+  LOG_DEBUG(("nsChannelClassifier::nsChannelClassifier %p", this));
   MOZ_ASSERT(mChannel);
 }
 
 nsChannelClassifier::~nsChannelClassifier()
 {
-  LOG(("nsChannelClassifier::~nsChannelClassifier %p", this));
+  LOG_DEBUG(("nsChannelClassifier::~nsChannelClassifier %p", this));
 }
 
 bool
@@ -367,9 +379,11 @@ nsChannelClassifier::ShouldEnableTrackingProtectionInternal(
     if (!isThirdPartyWindow || !isThirdPartyChannel) {
       *result = false;
       if (LOG_ENABLED()) {
+        nsCString spec = chanURI->GetSpecOrDefault();
+        spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
         LOG(("nsChannelClassifier[%p]: Skipping tracking protection checks "
              "for first party or top-level load channel[%p] with uri %s",
-             this, aChannel, chanURI->GetSpecOrDefault().get()));
+             this, aChannel, spec.get()));
       }
       return NS_OK;
     }
@@ -415,8 +429,12 @@ nsChannelClassifier::ShouldEnableTrackingProtectionInternal(
     NS_ENSURE_SUCCESS(rv, rv);
 
     if (permissions == nsIPermissionManager::ALLOW_ACTION) {
-      LOG(("nsChannelClassifier[%p]: Allowlisting channel[%p] for %s", this,
+      if (LOG_ENABLED()) {
-           aChannel, escaped.get()));
+        nsCString chanSpec = chanURI->GetSpecOrDefault();
+        chanSpec.Truncate(std::min(chanSpec.Length(), sMaxSpecLength));
+        LOG(("nsChannelClassifier[%p]: User override on channel[%p] (%s) for %s",
+             this, aChannel, chanSpec.get(), escaped.get()));
+      }
       mIsAllowListed = true;
       *result = false;
     } else {
@@ -435,8 +453,12 @@ nsChannelClassifier::ShouldEnableTrackingProtectionInternal(
 
       if (exists) {
         mIsAllowListed = true;
-        LOG(("nsChannelClassifier[%p]: Allowlisting channel[%p] in PBM for %s",
+        if (LOG_ENABLED()) {
-             this, aChannel, escaped.get()));
+          nsCString chanSpec = chanURI->GetSpecOrDefault();
+          chanSpec.Truncate(std::min(chanSpec.Length(), sMaxSpecLength));
+          LOG(("nsChannelClassifier[%p]: User override (PBM) on channel[%p] (%s) for %s",
+               this, aChannel, chanSpec.get(), escaped.get()));
+        }
       }
 
       *result = !exists;
@@ -447,10 +469,13 @@ nsChannelClassifier::ShouldEnableTrackingProtectionInternal(
     // (page elements blocked) the state will be then updated.
     if (*result) {
       if (LOG_ENABLED()) {
+        nsCString chanSpec = chanURI->GetSpecOrDefault();
+        chanSpec.Truncate(std::min(chanSpec.Length(), sMaxSpecLength));
+        nsCString topWinSpec = topWinURI->GetSpecOrDefault();
+        topWinSpec.Truncate(std::min(topWinSpec.Length(), sMaxSpecLength));
         LOG(("nsChannelClassifier[%p]: Enabling tracking protection checks on "
-             "channel[%p] with uri %s for toplevel window %s", this, aChannel,
+             "channel[%p] with uri %s for toplevel window uri %s", this,
-             chanURI->GetSpecOrDefault().get(),
+             aChannel, chanSpec.get(), topWinSpec.get()));
-             topWinURI->GetSpecOrDefault().get()));
       }
       return NS_OK;
     }
@@ -624,9 +649,10 @@ nsChannelClassifier::StartInternal()
     if (LOG_ENABLED()) {
       nsCOMPtr<nsIURI> principalURI;
       principal->GetURI(getter_AddRefs(principalURI));
-      LOG(("nsChannelClassifier[%p]: Classifying principal %s on channel with "
+      nsCString spec = principalURI->GetSpecOrDefault();
-           "uri %s", this, principalURI->GetSpecOrDefault().get(),
+      spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
-           uri->GetSpecOrDefault().get()));
+      LOG(("nsChannelClassifier[%p]: Classifying principal %s on channel[%p]",
+           this, spec.get(), mChannel.get()));
     }
     // The classify is running in parent process, no need to give a valid event
     // target
@@ -645,12 +671,12 @@ nsChannelClassifier::StartInternal()
             // Some channels (including nsJSChannel) fail on Suspend.  This
             // shouldn't be fatal, but will prevent malware from being
             // blocked on these channels.
-            LOG(("nsChannelClassifier[%p]: Couldn't suspend channel", this));
+            LOG_WARN(("nsChannelClassifier[%p]: Couldn't suspend channel", this));
             return rv;
         }
 
         mSuspendedChannel = true;
-        LOG(("nsChannelClassifier[%p]: suspended channel %p",
+        LOG_DEBUG(("nsChannelClassifier[%p]: suspended channel %p",
              this, mChannel.get()));
     } else {
         LOG(("nsChannelClassifier[%p]: not expecting callback", this));
@@ -706,6 +732,7 @@ nsChannelClassifier::MarkEntryClassified(nsresult status)
       mChannel->GetURI(getter_AddRefs(uri));
       nsAutoCString spec;
       uri->GetAsciiSpec(spec);
+      spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
       LOG(("nsChannelClassifier::MarkEntryClassified[%s] %s",
            errorName.get(), spec.get()));
     }
@@ -943,10 +970,19 @@ TrackingURICallback::OnClassifyComplete(nsresult aErrorCode,
 nsresult
 TrackingURICallback::OnBlacklistResult(nsresult aErrorCode)
 {
-  LOG(("TrackingURICallback[%p]::OnBlacklistResult aErrorCode=0x%" PRIx32,
+  LOG_DEBUG(("TrackingURICallback[%p]::OnBlacklistResult aErrorCode=0x%" PRIx32,
-       mChannelClassifier.get(), static_cast<uint32_t>(aErrorCode)));
+             mChannelClassifier.get(), static_cast<uint32_t>(aErrorCode)));
 
   if (NS_SUCCEEDED(aErrorCode)) {
+    if (LOG_ENABLED()) {
+      nsCOMPtr<nsIChannel> channel = mChannelClassifier->GetChannel();
+      nsCOMPtr<nsIURI> uri;
+      channel->GetURI(getter_AddRefs(uri));
+      nsCString spec = uri->GetSpecOrDefault();
+      spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
+      LOG(("TrackingURICallback[%p]::OnBlacklistResult uri %s not found "
+           "in blacklist", mChannelClassifier.get(), spec.get()));
+    }
     mChannelCallback();
     return NS_OK;
   }
@@ -955,10 +991,11 @@ TrackingURICallback::OnBlacklistResult(nsresult aErrorCode)
     nsCOMPtr<nsIChannel> channel = mChannelClassifier->GetChannel();
     nsCOMPtr<nsIURI> uri;
     channel->GetURI(getter_AddRefs(uri));
-    LOG(("TrackingURICallback[%p]::OnBlacklistResult channel [%p] "
+    nsCString spec = uri->GetSpecOrDefault();
+    spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
+    LOG(("TrackingURICallback[%p]::OnBlacklistResult channel[%p] "
          "uri=%s, is in blacklist. Start checking whitelist.",
-         mChannelClassifier.get(), channel.get(),
+         mChannelClassifier.get(), channel.get(), spec.get()));
-         uri->GetSpecOrDefault().get()));
   }
 
   nsCOMPtr<nsIURI> whitelistURI = mChannelClassifier->CreateWhiteListURI();
@@ -981,12 +1018,20 @@ TrackingURICallback::OnBlacklistResult(nsresult aErrorCode)
 nsresult
 TrackingURICallback::OnWhitelistResult(nsresult aErrorCode)
 {
-  LOG(("TrackingURICallback[%p]::OnWhitelistResult aErrorCode=0x%" PRIx32,
+  LOG_DEBUG(("TrackingURICallback[%p]::OnWhitelistResult aErrorCode=0x%" PRIx32,
-       mChannelClassifier.get(), static_cast<uint32_t>(aErrorCode)));
+             mChannelClassifier.get(), static_cast<uint32_t>(aErrorCode)));
 
   if (NS_SUCCEEDED(aErrorCode)) {
-    LOG(("TrackingURICallback[%p]::OnWhitelistResult tracker found "
+    if (LOG_ENABLED()) {
-         "in whitelist so we won't block it", mChannelClassifier.get()));
+      nsCOMPtr<nsIChannel> channel = mChannelClassifier->GetChannel();
+      nsCOMPtr<nsIURI> uri;
+      channel->GetURI(getter_AddRefs(uri));
+      nsCString spec = uri->GetSpecOrDefault();
+      spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
+      LOG(("TrackingURICallback[%p]::OnWhitelistResult uri %s found "
+           "in whitelist so we won't block it", mChannelClassifier.get(),
+           spec.get()));
+    }
     mChannelCallback();
     return NS_OK;
   }
@@ -995,10 +1040,11 @@ TrackingURICallback::OnWhitelistResult(nsresult aErrorCode)
     nsCOMPtr<nsIChannel> channel = mChannelClassifier->GetChannel();
     nsCOMPtr<nsIURI> uri;
     channel->GetURI(getter_AddRefs(uri));
+    nsCString spec = uri->GetSpecOrDefault();
+    spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
     LOG(("TrackingURICallback[%p]::OnWhitelistResult "
-         "channel [%p] uri=%s, is not in whitelist",
+         "channel[%p] uri=%s, should not be whitelisted",
-         mChannelClassifier.get(), channel.get(),
+         mChannelClassifier.get(), channel.get(), spec.get()));
-         uri->GetSpecOrDefault().get()));
   }
 
   OnTrackerFound(aErrorCode);
@@ -1013,6 +1059,8 @@ TrackingURICallback::OnTrackerFound(nsresult aErrorCode)
   if (mChannelClassifier->ShouldEnableTrackingProtection()) {
     mChannelClassifier->SetBlockedContent(channel, aErrorCode,
                                           mList, mProvider, mFullHash);
+    LOG(("TrackingURICallback[%p]::OnTrackerFound, cancelling channel[%p]",
+         mChannelClassifier.get(), channel.get()));
     channel->Cancel(aErrorCode);
   } else {
     MOZ_ASSERT(mChannelClassifier->ShouldEnableTrackingAnnotation());
@@ -1067,8 +1115,8 @@ nsChannelClassifier::CreateWhiteListURI() const
   NS_ENSURE_SUCCESS(rv, nullptr);
   nsAutoCString whitelistEntry = NS_LITERAL_CSTRING("http://") +
     pageHostname + NS_LITERAL_CSTRING("/?resource=") + resourceDomain;
-  LOG(("nsChannelClassifier[%p]: Looking for %s in the whitelist",
+  LOG(("nsChannelClassifier[%p]: Looking for %s in the whitelist (channel=%p)",
-       this, whitelistEntry.get()));
+       this, whitelistEntry.get(), mChannel.get()));
 
   nsCOMPtr<nsIURI> whitelistURI;
   rv = NS_NewURI(getter_AddRefs(whitelistURI), whitelistEntry);
@@ -1142,7 +1190,7 @@ nsChannelClassifier::OnClassifyComplete(nsresult aErrorCode,
 
   if (mSuspendedChannel) {
     nsAutoCString errorName;
-    if (LOG_ENABLED()) {
+    if (LOG_ENABLED() && NS_FAILED(aErrorCode)) {
       GetErrorName(aErrorCode, errorName);
       LOG(("nsChannelClassifier[%p]:OnClassifyComplete %s (suspended channel)",
            this, errorName.get()));
@@ -1153,9 +1201,11 @@ nsChannelClassifier::OnClassifyComplete(nsresult aErrorCode,
       if (LOG_ENABLED()) {
         nsCOMPtr<nsIURI> uri;
         mChannel->GetURI(getter_AddRefs(uri));
+        nsCString spec = uri->GetSpecOrDefault();
+        spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
         LOG(("nsChannelClassifier[%p]: cancelling channel %p for %s "
              "with error code %s", this, mChannel.get(),
-              uri->GetSpecOrDefault().get(), errorName.get()));
+              spec.get(), errorName.get()));
       }
 
       // Channel will be cancelled (page element blocked) due to Safe Browsing.
@@ -1172,8 +1222,8 @@ nsChannelClassifier::OnClassifyComplete(nsresult aErrorCode,
 
       mChannel->Cancel(aErrorCode);
     }
-    LOG(("nsChannelClassifier[%p]: resuming channel %p from "
+    LOG_DEBUG(("nsChannelClassifier[%p]: resuming channel[%p] from "
-         "OnClassifyComplete", this, mChannel.get()));
+               "OnClassifyComplete", this, mChannel.get()));
     mChannel->Resume();
   }
 
@@ -1211,7 +1261,7 @@ nsChannelClassifier::CheckIsTrackerWithLocalTable(std::function<void()>&& aCallb
   nsCString trackingBlacklist =
     CachedPrefs::GetInstance()->GetTrackingBlackList();
   if (trackingBlacklist.IsEmpty()) {
-    LOG(("nsChannelClassifier[%p]:CheckIsTrackerWithLocalTable blacklist is empty",
+    LOG_WARN(("nsChannelClassifier[%p]: CheckIsTrackerWithLocalTable blacklist is empty",
          this));
     return NS_ERROR_FAILURE;
   }
@@ -1219,8 +1269,12 @@ nsChannelClassifier::CheckIsTrackerWithLocalTable(std::function<void()>&& aCallb
   nsCOMPtr<nsIURIClassifierCallback> callback =
     new TrackingURICallback(this, std::move(aCallback));
 
-  LOG(("nsChannelClassifier[%p]:CheckIsTrackerWithLocalTable for uri=%s\n",
+  if (LOG_ENABLED()) {
-       this, uri->GetSpecOrDefault().get()));
+    nsCString spec = uri->GetSpecOrDefault();
+    spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
+    LOG(("nsChannelClassifier[%p]: Checking blacklist for uri=%s\n",
+         this, spec.get()));
+  }
   return uriClassifier->AsyncClassifyLocalWithTables(uri,
                                                      trackingBlacklist,
                                                      callback);