Bug 1461534 - Improve logging for the channel classifier. r?dimi draft
authorFrancois Marier <francois@mozilla.com>
Mon, 09 Jul 2018 09:42:31 -0700
changeset 815673 f3cf7f44e9620b20b67e1faca16500a78d7f2222
parent 814338 6e63e6b7f19b585859c36b74954a4961001dd106
push id115603
push userfmarier@mozilla.com
push dateMon, 09 Jul 2018 17:21:00 +0000
reviewersdimi
bugs1461534
milestone63.0a1
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
netwerk/base/nsChannelClassifier.cpp
--- a/netwerk/base/nsChannelClassifier.cpp
+++ b/netwerk/base/nsChannelClassifier.cpp
@@ -47,25 +47,28 @@
 namespace mozilla {
 namespace net {
 
 //
 // MOZ_LOG=nsChannelClassifier:5
 //
 static LazyLogModule gChannelClassifierLog("nsChannelClassifier");
 
-
 #undef LOG
-#define LOG(args)     MOZ_LOG(gChannelClassifierLog, LogLevel::Debug, args)
-#define LOG_ENABLED() MOZ_LOG_TEST(gChannelClassifierLog, LogLevel::Debug)
+#define LOG(args) MOZ_LOG(gChannelClassifierLog, LogLevel::Info, args)
+#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 {
 
 /**
  * It is not recommended to read from Preference everytime a channel is
  * connected.
  * That is not fast and we should cache preference values and reuse them
@@ -230,39 +233,48 @@ LowerPriorityHelper(nsIChannel* aChannel
 
       cos->AddClassFlags(nsIClassOfService::Throttleable);
     }
   }
 
   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);
     }
   }
 }
 
 NS_IMPL_ISUPPORTS(nsChannelClassifier,
                   nsIURIClassifierCallback,
                   nsIObserver)
 
 nsChannelClassifier::nsChannelClassifier(nsIChannel *aChannel)
   : mIsAllowListed(false),
     mSuspendedChannel(false),
     mChannel(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
 nsChannelClassifier::ShouldEnableTrackingProtection()
 {
   if (mTrackingProtectionEnabled) {
     return mTrackingProtectionEnabled.value();
   }
@@ -362,19 +374,21 @@ nsChannelClassifier::ShouldEnableTrackin
     // from being detected as third-party.
     bool isThirdPartyChannel = true;
     bool isThirdPartyWindow = true;
     thirdPartyUtil->IsThirdPartyURI(chanURI, topWinURI, &isThirdPartyWindow);
     thirdPartyUtil->IsThirdPartyChannel(aChannel, nullptr, &isThirdPartyChannel);
     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;
     }
 
     if (AddonMayLoad(aChannel, chanURI)) {
         return NS_OK;
     }
 
@@ -410,18 +424,22 @@ nsChannelClassifier::ShouldEnableTrackin
         do_GetService(NS_PERMISSIONMANAGER_CONTRACTID, &rv);
     NS_ENSURE_SUCCESS(rv, rv);
 
     uint32_t permissions = nsIPermissionManager::UNKNOWN_ACTION;
     rv = permMgr->TestPermission(topWinURI, "trackingprotection", &permissions);
     NS_ENSURE_SUCCESS(rv, rv);
 
     if (permissions == nsIPermissionManager::ALLOW_ACTION) {
-      LOG(("nsChannelClassifier[%p]: Allowlisting channel[%p] for %s", this,
-           aChannel, escaped.get()));
+      if (LOG_ENABLED()) {
+        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 {
       *result = true;
     }
 
     // In Private Browsing Mode we also check against an in-memory list.
     if (NS_UsePrivateBrowsing(aChannel)) {
@@ -430,32 +448,39 @@ nsChannelClassifier::ShouldEnableTrackin
       NS_ENSURE_SUCCESS(rv, rv);
 
       bool exists = false;
       rv = pbmtpWhitelist->ExistsInAllowList(topWinURI, &exists);
       NS_ENSURE_SUCCESS(rv, rv);
 
       if (exists) {
         mIsAllowListed = true;
-        LOG(("nsChannelClassifier[%p]: Allowlisting channel[%p] in PBM for %s",
-             this, aChannel, escaped.get()));
+        if (LOG_ENABLED()) {
+          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;
     }
 
     // Tracking protection will be enabled so return without updating
     // the security state. If any channels are subsequently cancelled
     // (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,
-             chanURI->GetSpecOrDefault().get(),
-             topWinURI->GetSpecOrDefault().get()));
+             "channel[%p] with uri %s for toplevel window uri %s", this,
+             aChannel, chanSpec.get(), topWinSpec.get()));
       }
       return NS_OK;
     }
 
     // Tracking protection will be disabled so update the security state
     // of the document and fire a secure change event. If we can't get the
     // window for the channel, then the shield won't show up so we can't send
     // an event to the securityUI anyway.
@@ -619,19 +644,20 @@ nsChannelClassifier::StartInternal()
     nsCOMPtr<nsIPrincipal> principal;
     rv = securityManager->GetChannelURIPrincipal(mChannel, getter_AddRefs(principal));
     NS_ENSURE_SUCCESS(rv, rv);
 
     bool expectCallback;
     if (LOG_ENABLED()) {
       nsCOMPtr<nsIURI> principalURI;
       principal->GetURI(getter_AddRefs(principalURI));
-      LOG(("nsChannelClassifier[%p]: Classifying principal %s on channel with "
-           "uri %s", this, principalURI->GetSpecOrDefault().get(),
-           uri->GetSpecOrDefault().get()));
+      nsCString spec = principalURI->GetSpecOrDefault();
+      spec.Truncate(std::min(spec.Length(), sMaxSpecLength));
+      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
     rv = uriClassifier->Classify(principal, nullptr,
                                  false,
                                  this, &expectCallback);
     if (NS_FAILED(rv)) {
         return rv;
@@ -640,22 +666,22 @@ nsChannelClassifier::StartInternal()
     if (expectCallback) {
         // Suspend the channel, it will be resumed when we get the classifier
         // callback.
         rv = mChannel->Suspend();
         if (NS_FAILED(rv)) {
             // 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));
         return NS_ERROR_FAILURE;
     }
 
     // Add an observer for shutdown
     AddShutdownObserver();
@@ -701,16 +727,17 @@ nsChannelClassifier::MarkEntryClassified
 
     if (LOG_ENABLED()) {
       nsAutoCString errorName;
       GetErrorName(status, errorName);
       nsCOMPtr<nsIURI> uri;
       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()));
     }
 
     nsCOMPtr<nsICachingChannel> cachingChannel = do_QueryInterface(mChannel);
     if (!cachingChannel) {
         return;
     }
@@ -938,32 +965,42 @@ TrackingURICallback::OnClassifyComplete(
 
   nsresult status = aLists.IsEmpty() ? NS_ERROR_TRACKING_URI : NS_OK;
   return OnWhitelistResult(status);
 }
 
 nsresult
 TrackingURICallback::OnBlacklistResult(nsresult aErrorCode)
 {
-  LOG(("TrackingURICallback[%p]::OnBlacklistResult aErrorCode=0x%" PRIx32,
-       mChannelClassifier.get(), static_cast<uint32_t>(aErrorCode)));
+  LOG_DEBUG(("TrackingURICallback[%p]::OnBlacklistResult aErrorCode=0x%" PRIx32,
+             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;
   }
 
   if (LOG_ENABLED()) {
     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(),
-         uri->GetSpecOrDefault().get()));
+         mChannelClassifier.get(), channel.get(), spec.get()));
   }
 
   nsCOMPtr<nsIURI> whitelistURI = mChannelClassifier->CreateWhiteListURI();
 
   // If IsTrackerWhitelisted has failed, it means the uri is not in whitelist.
   if (NS_FAILED(mChannelClassifier->IsTrackerWhitelisted(whitelistURI, this))) {
     LOG(("TrackingURICallback[%p]:OnBlacklistResult "
          "IsTrackerWhitelisted has failed.",
@@ -976,48 +1013,59 @@ TrackingURICallback::OnBlacklistResult(n
   }
 
   return NS_OK;
 }
 
 nsresult
 TrackingURICallback::OnWhitelistResult(nsresult aErrorCode)
 {
-  LOG(("TrackingURICallback[%p]::OnWhitelistResult aErrorCode=0x%" PRIx32,
-       mChannelClassifier.get(), static_cast<uint32_t>(aErrorCode)));
+  LOG_DEBUG(("TrackingURICallback[%p]::OnWhitelistResult aErrorCode=0x%" PRIx32,
+             mChannelClassifier.get(), static_cast<uint32_t>(aErrorCode)));
 
   if (NS_SUCCEEDED(aErrorCode)) {
-    LOG(("TrackingURICallback[%p]::OnWhitelistResult tracker found "
-         "in whitelist so we won't block it", mChannelClassifier.get()));
+    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]::OnWhitelistResult uri %s found "
+           "in whitelist so we won't block it", mChannelClassifier.get(),
+           spec.get()));
+    }
     mChannelCallback();
     return NS_OK;
   }
 
   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]::OnWhitelistResult "
-         "channel [%p] uri=%s, is not in whitelist",
-         mChannelClassifier.get(), channel.get(),
-         uri->GetSpecOrDefault().get()));
+         "channel[%p] uri=%s, should not be whitelisted",
+         mChannelClassifier.get(), channel.get(), spec.get()));
   }
 
   OnTrackerFound(aErrorCode);
   mChannelCallback();
   return NS_OK;
 }
 
 void
 TrackingURICallback::OnTrackerFound(nsresult aErrorCode)
 {
   nsCOMPtr<nsIChannel> channel = mChannelClassifier->GetChannel();
   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());
 
     // Even with TP disabled, we still want to show the user that there
     // are unblocked trackers on the site, so notify the UI that we loaded
     // tracking content. UI code can treat this notification differently
     // depending on whether TP is enabled or disabled.
@@ -1062,18 +1110,18 @@ nsChannelClassifier::CreateWhiteListURI(
   // Craft a whitelist URL like "toplevel.page/?resource=third.party.domain"
   nsAutoCString pageHostname, resourceDomain;
   rv = topWinURI->GetHost(pageHostname);
   NS_ENSURE_SUCCESS(rv, nullptr);
   rv = chanPrincipal->GetBaseDomain(resourceDomain);
   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",
-       this, whitelistEntry.get()));
+  LOG(("nsChannelClassifier[%p]: Looking for %s in the whitelist (channel=%p)",
+       this, whitelistEntry.get(), mChannel.get()));
 
   nsCOMPtr<nsIURI> whitelistURI;
   rv = NS_NewURI(getter_AddRefs(whitelistURI), whitelistEntry);
 
   return NS_SUCCEEDED(rv) ? whitelistURI.forget() : nullptr;
 }
 
 nsresult
@@ -1137,48 +1185,50 @@ nsChannelClassifier::OnClassifyComplete(
                                         const nsACString& aFullHash)
 {
   // Should only be called in the parent process.
   MOZ_ASSERT(XRE_IsParentProcess());
   MOZ_ASSERT(aErrorCode != NS_ERROR_TRACKING_URI);
 
   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()));
     }
     MarkEntryClassified(aErrorCode);
 
     if (NS_FAILED(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.
       // Do update the security state of the document and fire a security
       // change event.
       SetBlockedContent(mChannel, aErrorCode, aList, aProvider, aFullHash);
 
       if (aErrorCode == NS_ERROR_MALWARE_URI ||
           aErrorCode == NS_ERROR_PHISHING_URI ||
           aErrorCode == NS_ERROR_UNWANTED_URI ||
           aErrorCode == NS_ERROR_HARMFUL_URI) {
         SendThreatHitReport(mChannel, aProvider, aList, aFullHash);
       }
 
       mChannel->Cancel(aErrorCode);
     }
-    LOG(("nsChannelClassifier[%p]: resuming channel %p from "
-         "OnClassifyComplete", this, mChannel.get()));
+    LOG_DEBUG(("nsChannelClassifier[%p]: resuming channel[%p] from "
+               "OnClassifyComplete", this, mChannel.get()));
     mChannel->Resume();
   }
 
   mChannel = nullptr;
   RemoveShutdownObserver();
 
   return NS_OK;
 }
@@ -1206,26 +1256,30 @@ nsChannelClassifier::CheckIsTrackerWithL
   rv = mChannel->GetURI(getter_AddRefs(uri));
   if (NS_FAILED(rv) || !uri) {
     return rv;
   }
 
   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;
   }
 
   nsCOMPtr<nsIURIClassifierCallback> callback =
     new TrackingURICallback(this, std::move(aCallback));
 
-  LOG(("nsChannelClassifier[%p]:CheckIsTrackerWithLocalTable for uri=%s\n",
-       this, uri->GetSpecOrDefault().get()));
+  if (LOG_ENABLED()) {
+    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);
 }
 
 already_AddRefed<nsIChannel>
 nsChannelClassifier::GetChannel()
 {