Bug 1485099 - Add some logging to the AntiTracking component for the saving and reading of storage access permissions; r=smaug
authorEhsan Akhgari <ehsan@mozilla.com>
Tue, 21 Aug 2018 14:28:49 -0400
changeset 480972 f9417ef4b9568f7edf1fc6854b38ef75a13db086
parent 480971 c9a06dacc095cc7c9968eef179b36174d57c0260
child 480973 9b2e26f618a443989ab88e724ecc52d160bd093d
push id232
push userfmarier@mozilla.com
push dateWed, 05 Sep 2018 20:45:54 +0000
reviewerssmaug
bugs1485099
milestone63.0a1
Bug 1485099 - Add some logging to the AntiTracking component for the saving and reading of storage access permissions; r=smaug
toolkit/components/antitracking/AntiTrackingCommon.cpp
--- a/toolkit/components/antitracking/AntiTrackingCommon.cpp
+++ b/toolkit/components/antitracking/AntiTrackingCommon.cpp
@@ -4,16 +4,17 @@
  * License, v. 2.0. If a copy of the MPL was not distributed with this file,
  * You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "AntiTrackingCommon.h"
 
 #include "mozilla/dom/ContentChild.h"
 #include "mozilla/ipc/MessageChannel.h"
 #include "mozilla/AbstractThread.h"
+#include "mozilla/Logging.h"
 #include "mozilla/StaticPrefs.h"
 #include "mozIThirdPartyUtil.h"
 #include "nsContentUtils.h"
 #include "nsGlobalWindowInner.h"
 #include "nsICookiePermission.h"
 #include "nsICookieService.h"
 #include "nsIPermissionManager.h"
 #include "nsIPrincipal.h"
@@ -22,16 +23,32 @@
 #include "nsScriptSecurityManager.h"
 #include "prtime.h"
 
 #define ANTITRACKING_PERM_KEY "3rdPartyStorage"
 
 using namespace mozilla;
 using mozilla::dom::ContentChild;
 
+static LazyLogModule gAntiTrackingLog("AntiTracking");
+
+#define LOG(format) MOZ_LOG(gAntiTrackingLog, mozilla::LogLevel::Debug, format)
+
+#define LOG_SPEC(format, uri)                                                 \
+  PR_BEGIN_MACRO                                                              \
+    if (MOZ_LOG_TEST(gAntiTrackingLog, mozilla::LogLevel::Debug)) {           \
+      nsAutoCString _specStr(NS_LITERAL_CSTRING("(null)"));                   \
+      if (uri) {                                                              \
+        _specStr = uri->GetSpecOrDefault();                                   \
+      }                                                                       \
+      const char* _spec = _specStr.get();                                     \
+      LOG(format);                                                            \
+    }                                                                         \
+  PR_END_MACRO
+
 namespace {
 
 bool
 GetParentPrincipalAndTrackingOrigin(nsGlobalWindowInner* a3rdPartyTrackingWindow,
                                     nsIPrincipal** aTopLevelStoragePrincipal,
                                     nsACString& aTrackingOrigin)
 {
   MOZ_ASSERT(nsContentUtils::IsTrackingResourceWindow(a3rdPartyTrackingWindow));
@@ -114,62 +131,79 @@ CookiesBehavior(nsIPrincipal* aPrincipal
 } // anonymous
 
 /* static */ RefPtr<AntiTrackingCommon::StorageAccessGrantPromise>
 AntiTrackingCommon::AddFirstPartyStorageAccessGrantedFor(const nsAString& aOrigin,
                                                          nsPIDOMWindowInner* aParentWindow)
 {
   MOZ_ASSERT(aParentWindow);
 
+  LOG(("Adding a first-party storage exception for %s...",
+       NS_ConvertUTF16toUTF8(aOrigin).get()));
+
   if (StaticPrefs::network_cookie_cookieBehavior() !=
         nsICookieService::BEHAVIOR_REJECT_TRACKER) {
+    LOG(("Disabled by network.cookie.cookieBehavior pref (%d), bailing out early",
+         StaticPrefs::network_cookie_cookieBehavior()));
     return StorageAccessGrantPromise::CreateAndResolve(true, __func__);
   }
 
   nsCOMPtr<nsIPrincipal> topLevelStoragePrincipal;
   nsAutoCString trackingOrigin;
 
   nsGlobalWindowInner* parentWindow = nsGlobalWindowInner::Cast(aParentWindow);
   nsGlobalWindowOuter* outerParentWindow =
     nsGlobalWindowOuter::Cast(parentWindow->GetOuterWindow());
   if (NS_WARN_IF(!outerParentWindow)) {
+    LOG(("No outer window found for our parent window, bailing out early"));
     return StorageAccessGrantPromise::CreateAndReject(false, __func__);
   }
 
+  LOG(("The current resource is %s-party",
+       outerParentWindow->IsTopLevelWindow() ? "first" : "third"));
+
   // We are a first party resource.
   if (outerParentWindow->IsTopLevelWindow()) {
     CopyUTF16toUTF8(aOrigin, trackingOrigin);
     topLevelStoragePrincipal = parentWindow->GetPrincipal();
     if (NS_WARN_IF(!topLevelStoragePrincipal)) {
+      LOG(("Top-level storage area principal not found, bailing out early"));
       return StorageAccessGrantPromise::CreateAndReject(false, __func__);
     }
 
   // We are a 3rd party source.
   } else if (!GetParentPrincipalAndTrackingOrigin(parentWindow,
                                                   getter_AddRefs(topLevelStoragePrincipal),
                                                   trackingOrigin)) {
+    LOG(("Error while computing the parent principal and tracking origin, bailing out early"));
     return StorageAccessGrantPromise::CreateAndReject(false, __func__);
   }
 
   NS_ConvertUTF16toUTF8 grantedOrigin(aOrigin);
 
   if (XRE_IsParentProcess()) {
+    LOG(("Saving the permission: trackingOrigin=%s, grantedOrigin=%s",
+         trackingOrigin.get(), grantedOrigin.get()));
+
     RefPtr<StorageAccessGrantPromise::Private> p = new StorageAccessGrantPromise::Private(__func__);
     SaveFirstPartyStorageAccessGrantedForOriginOnParentProcess(topLevelStoragePrincipal,
                                                                trackingOrigin,
                                                                grantedOrigin,
                                                                [p] (bool success) {
                                                                  p->Resolve(success, __func__);
                                                                });
     return p;
   }
 
   ContentChild* cc = ContentChild::GetSingleton();
   MOZ_ASSERT(cc);
 
+  LOG(("Asking the parent process to save the permission for us: trackingOrigin=%s, grantedOrigin=%s",
+       trackingOrigin.get(), grantedOrigin.get()));
+
   // This is not really secure, because here we have the content process sending
   // the request of storing a permission.
   RefPtr<StorageAccessGrantPromise::Private> p = new StorageAccessGrantPromise::Private(__func__);
   cc->SendFirstPartyStorageAccessGrantedForOrigin(IPC::Principal(topLevelStoragePrincipal),
                                                   trackingOrigin,
                                                   grantedOrigin)
     ->Then(GetCurrentThreadSerialEventTarget(), __func__,
            [p] (bool success) {
@@ -183,271 +217,346 @@ AntiTrackingCommon::AddFirstPartyStorage
 /* static */ void
 AntiTrackingCommon::SaveFirstPartyStorageAccessGrantedForOriginOnParentProcess(nsIPrincipal* aParentPrincipal,
                                                                                const nsCString& aTrackingOrigin,
                                                                                const nsCString& aGrantedOrigin,
                                                                                FirstPartyStorageAccessGrantedForOriginResolver&& aResolver)
 {
   MOZ_ASSERT(XRE_IsParentProcess());
 
+  nsCOMPtr<nsIURI> parentPrincipalURI;
+  Unused << aParentPrincipal->GetURI(getter_AddRefs(parentPrincipalURI));
+  LOG_SPEC(("Saving a first-party storage permission on %s for trackingOrigin=%s grantedOrigin=%s",
+            _spec, aTrackingOrigin.get(), aGrantedOrigin.get()), parentPrincipalURI);
+
   if (NS_WARN_IF(!aParentPrincipal)) {
     // The child process is sending something wrong. Let's ignore it.
+    LOG(("aParentPrincipal is null, bailing out early"));
     aResolver(false);
     return;
   }
 
   nsCOMPtr<nsIPermissionManager> pm = services::GetPermissionManager();
   if (NS_WARN_IF(!pm)) {
+    LOG(("Permission manager is null, bailing out early"));
     aResolver(false);
     return;
   }
 
   // Remember that this pref is stored in seconds!
   uint32_t expirationTime =
     StaticPrefs::privacy_restrict3rdpartystorage_expiration() * 1000;
   int64_t when = (PR_Now() / PR_USEC_PER_MSEC) + expirationTime;
 
   nsAutoCString type;
   CreatePermissionKey(aTrackingOrigin, aGrantedOrigin, type);
 
+  LOG(("Computed permission key: %s, expiry: %d, proceeding to save in the permission manager",
+       type.get(), expirationTime));
+
   nsresult rv = pm->AddFromPrincipal(aParentPrincipal, type.get(),
                                      nsIPermissionManager::ALLOW_ACTION,
                                      nsIPermissionManager::EXPIRE_TIME, when);
   Unused << NS_WARN_IF(NS_FAILED(rv));
   aResolver(NS_SUCCEEDED(rv));
+
+  LOG(("Result: %s", NS_SUCCEEDED(rv) ? "success" : "failure"));
 }
 
 bool
 AntiTrackingCommon::IsFirstPartyStorageAccessGrantedFor(nsPIDOMWindowInner* aWindow,
                                                         nsIURI* aURI)
 {
   MOZ_ASSERT(aWindow);
   MOZ_ASSERT(aURI);
 
+  LOG_SPEC(("Computing whether window %p has access to URI %s", aWindow, _spec), aURI);
+
   nsGlobalWindowInner* innerWindow = nsGlobalWindowInner::Cast(aWindow);
   nsIPrincipal* toplevelPrincipal = innerWindow->GetTopLevelPrincipal();
   if (!toplevelPrincipal) {
     // We are already the top-level principal. Let's use the window's principal.
+    LOG(("Our inner window lacks a top-level principal, use the window's principal instead"));
     toplevelPrincipal = innerWindow->GetPrincipal();
   }
 
   if (!toplevelPrincipal) {
     // This should not be possible, right?
+    LOG(("No top-level principal, this shouldn't be happening! Bail out early"));
     return false;
   }
 
   nsCookieAccess access = CheckCookiePermissionForPrincipal(toplevelPrincipal);
   if (access != nsICookiePermission::ACCESS_DEFAULT) {
+    LOG(("CheckCookiePermissionForPrincipal() returned a non-default access code (%d), returning %s",
+         int(access), access != nsICookiePermission::ACCESS_DENY ?
+                        "success" : "failure"));
     return access != nsICookiePermission::ACCESS_DENY;
   }
 
   int32_t behavior = CookiesBehavior(toplevelPrincipal);
   if (behavior == nsICookieService::BEHAVIOR_ACCEPT) {
+    LOG(("The cookie behavior pref mandates accepting all cookies!"));
     return true;
   }
 
   if (behavior == nsICookieService::BEHAVIOR_REJECT) {
+    LOG(("The cookie behavior pref mandates rejecting all cookies!"));
     return false;
   }
 
   // Let's check if this is a 3rd party context.
   if (!nsContentUtils::IsThirdPartyWindowOrChannel(aWindow, nullptr, aURI)) {
+    LOG(("Our window isn't a third-party window"));
     return true;
   }
 
   if (behavior == nsICookieService::BEHAVIOR_REJECT_FOREIGN ||
       behavior == nsICookieService::BEHAVIOR_LIMIT_FOREIGN) {
     // XXX For non-cookie forms of storage, we handle BEHAVIOR_LIMIT_FOREIGN by
     // simply rejecting the request to use the storage. In the future, if we
     // change the meaning of BEHAVIOR_LIMIT_FOREIGN to be one which makes sense
     // for non-cookie storage types, this may change.
+    LOG(("Nothing more to do due to the behavior code %d", int(behavior)));
     return false;
   }
 
   MOZ_ASSERT(behavior == nsICookieService::BEHAVIOR_REJECT_TRACKER);
   if (!nsContentUtils::IsTrackingResourceWindow(aWindow)) {
+    LOG(("Our window isn't a tracking window"));
     return true;
   }
 
   nsCOMPtr<nsIPrincipal> parentPrincipal;
   nsAutoCString trackingOrigin;
   if (!GetParentPrincipalAndTrackingOrigin(nsGlobalWindowInner::Cast(aWindow),
                                            getter_AddRefs(parentPrincipal),
                                            trackingOrigin)) {
+    LOG(("Failed to obtain the parent principal and the tracking origin"));
     return false;
   }
 
   nsAutoString origin;
   nsresult rv = nsContentUtils::GetUTFOrigin(aURI, origin);
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG_SPEC(("Failed to compute the origin from %s", _spec), aURI);
     return false;
   }
 
   nsAutoCString type;
   CreatePermissionKey(trackingOrigin, NS_ConvertUTF16toUTF8(origin), type);
 
   nsCOMPtr<nsIPermissionManager> pm = services::GetPermissionManager();
   if (NS_WARN_IF(!pm)) {
+    LOG(("Failed to obtain the permission manager"));
     return false;
   }
 
   uint32_t result = 0;
   rv = pm->TestPermissionFromPrincipal(parentPrincipal, type.get(), &result);
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG(("Failed to test the permission"));
     return false;
   }
 
+  nsCOMPtr<nsIURI> parentPrincipalURI;
+  Unused << parentPrincipal->GetURI(getter_AddRefs(parentPrincipalURI));
+  LOG_SPEC(("Testing permission type %s for %s resulted in %d (%s)",
+            type.get(), _spec, int(result),
+            result == nsIPermissionManager::ALLOW_ACTION ?
+              "success" : "failure"), parentPrincipalURI);
+
   return result == nsIPermissionManager::ALLOW_ACTION;
 }
 
 bool
 AntiTrackingCommon::IsFirstPartyStorageAccessGrantedFor(nsIHttpChannel* aChannel,
                                                         nsIURI* aURI)
 {
   MOZ_ASSERT(aURI);
   MOZ_ASSERT(aChannel);
 
+  nsCOMPtr<nsIURI> channelURI;
+  Unused << aChannel->GetURI(getter_AddRefs(channelURI));
+  LOG_SPEC(("Computing whether channel %p has access to URI %s", aChannel, _spec),
+           channelURI);
+
   nsCOMPtr<nsILoadInfo> loadInfo = aChannel->GetLoadInfo();
   if (!loadInfo) {
+    LOG(("No loadInfo, bail out early"));
     return true;
   }
 
   // We need to find the correct principal to check the cookie permission. For
   // third-party contexts, we want to check if the top-level window has a custom
   // cookie permission.
   nsIPrincipal* toplevelPrincipal = loadInfo->TopLevelPrincipal();
 
   // If this is already the top-level window, we should use the loading
   // principal.
   if (!toplevelPrincipal) {
+    LOG(("Our loadInfo lacks a top-level principal, use the loadInfo's loading principal instead"));
     toplevelPrincipal = loadInfo->LoadingPrincipal();
   }
 
   nsCOMPtr<nsIPrincipal> channelPrincipal;
   nsIScriptSecurityManager* ssm = nsScriptSecurityManager::GetScriptSecurityManager();
   nsresult rv = ssm->GetChannelResultPrincipal(aChannel,
                                                getter_AddRefs(channelPrincipal));
 
   // If we don't have a loading principal and this is a document channel, we are
   // a top-level window!
   if (!toplevelPrincipal) {
+    LOG(("We don't have a loading principal, let's see if this is a document channel"
+         " that belongs to a top-level window"));
     bool isDocument = false;
     nsresult rv2 = aChannel->GetIsMainDocumentChannel(&isDocument);
     if (NS_SUCCEEDED(rv) && NS_SUCCEEDED(rv2) && isDocument) {
       toplevelPrincipal = channelPrincipal;
+      LOG(("Yes, we guessed right!"));
+    } else {
+      LOG(("No, we guessed wrong!"));
     }
   }
 
   // Let's use the triggering principal then.
   if (!toplevelPrincipal) {
+    LOG(("Our loadInfo lacks a top-level principal, use the loadInfo's triggering principal instead"));
     toplevelPrincipal = loadInfo->TriggeringPrincipal();
   }
 
   if (NS_WARN_IF(!toplevelPrincipal)) {
+    LOG(("No top-level principal! Bail out early"));
     return false;
   }
 
   nsCookieAccess access = CheckCookiePermissionForPrincipal(toplevelPrincipal);
   if (access != nsICookiePermission::ACCESS_DEFAULT) {
+    LOG(("CheckCookiePermissionForPrincipal() returned a non-default access code (%d), returning %s",
+         int(access), access != nsICookiePermission::ACCESS_DENY ?
+                        "success" : "failure"));
     return access != nsICookiePermission::ACCESS_DENY;
   }
 
   if (NS_WARN_IF(NS_FAILED(rv) || !channelPrincipal)) {
+    LOG(("No channel principal, bail out early"));
     return false;
   }
 
   int32_t behavior = CookiesBehavior(channelPrincipal);
   if (behavior == nsICookieService::BEHAVIOR_ACCEPT) {
+    LOG(("The cookie behavior pref mandates accepting all cookies!"));
     return true;
   }
 
   if (behavior == nsICookieService::BEHAVIOR_REJECT) {
+    LOG(("The cookie behavior pref mandates rejecting all cookies!"));
     return false;
   }
 
   nsCOMPtr<mozIThirdPartyUtil> thirdPartyUtil = services::GetThirdPartyUtil();
   if (!thirdPartyUtil) {
+    LOG(("No thirdPartyUtil, bail out early"));
     return true;
   }
 
   bool thirdParty = false;
   Unused << thirdPartyUtil->IsThirdPartyChannel(aChannel,
                                                 nullptr,
                                                 &thirdParty);
   // Grant if it's not a 3rd party.
   if (!thirdParty) {
+    LOG(("Our channel isn't a third-party channel"));
     return true;
   }
 
   if (behavior == nsICookieService::BEHAVIOR_REJECT_FOREIGN ||
       behavior == nsICookieService::BEHAVIOR_LIMIT_FOREIGN) {
     // XXX For non-cookie forms of storage, we handle BEHAVIOR_LIMIT_FOREIGN by
     // simply rejecting the request to use the storage. In the future, if we
     // change the meaning of BEHAVIOR_LIMIT_FOREIGN to be one which makes sense
     // for non-cookie storage types, this may change.
+    LOG(("Nothing more to do due to the behavior code %d", int(behavior)));
     return false;
   }
 
   MOZ_ASSERT(behavior == nsICookieService::BEHAVIOR_REJECT_TRACKER);
 
   nsIPrincipal* parentPrincipal = loadInfo->TopLevelStorageAreaPrincipal();
   if (!parentPrincipal) {
+    LOG(("No top-level storage area principal at hand"));
+
     // parentPrincipal can be null if the parent window is not the top-level
     // window.
     if (loadInfo->TopLevelPrincipal()) {
+      LOG(("Parent window is the top-level window, bail out early"));
       return false;
     }
 
     parentPrincipal = loadInfo->TriggeringPrincipal();
     if (NS_WARN_IF(!parentPrincipal)) {
+      LOG(("No triggering principal, this shouldn't be happening! Bail out early"));
       // Why we are here?!?
       return true;
     }
   }
 
   // Not a tracker.
   if (!aChannel->GetIsTrackingResource()) {
+    LOG(("Our channel isn't a tracking channel"));
     return true;
   }
 
   // Let's see if we have to grant the access for this particular channel.
 
   nsCOMPtr<nsIURI> trackingURI;
   rv = aChannel->GetURI(getter_AddRefs(trackingURI));
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG(("Failed to get the channel URI"));
     return true;
   }
 
   nsAutoString trackingOrigin;
   rv = nsContentUtils::GetUTFOrigin(trackingURI, trackingOrigin);
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG_SPEC(("Failed to compute the origin from %s", _spec), trackingURI);
     return false;
   }
 
   nsAutoString origin;
   rv = nsContentUtils::GetUTFOrigin(aURI, origin);
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG_SPEC(("Failed to compute the origin from %s", _spec), aURI);
     return false;
   }
 
   nsAutoCString type;
   CreatePermissionKey(NS_ConvertUTF16toUTF8(trackingOrigin),
                       NS_ConvertUTF16toUTF8(origin), type);
 
   nsCOMPtr<nsIPermissionManager> pm = services::GetPermissionManager();
   if (NS_WARN_IF(!pm)) {
+    LOG(("Failed to obtain the permission manager"));
     return false;
   }
 
   uint32_t result = 0;
   rv = pm->TestPermissionFromPrincipal(parentPrincipal, type.get(), &result);
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG(("Failed to test the permission"));
     return false;
   }
 
+  nsCOMPtr<nsIURI> parentPrincipalURI;
+  Unused << parentPrincipal->GetURI(getter_AddRefs(parentPrincipalURI));
+  LOG_SPEC(("Testing permission type %s for %s resulted in %d (%s)",
+            type.get(), _spec, int(result),
+            result == nsIPermissionManager::ALLOW_ACTION ?
+              "success" : "failure"), parentPrincipalURI);
+
   return result == nsIPermissionManager::ALLOW_ACTION;
 }
 
 bool
 AntiTrackingCommon::IsFirstPartyStorageAccessGrantedFor(nsIPrincipal* aPrincipal)
 {
   MOZ_ASSERT(aPrincipal);
 
@@ -463,53 +572,73 @@ AntiTrackingCommon::IsFirstPartyStorageA
 /* static */ bool
 AntiTrackingCommon::MaybeIsFirstPartyStorageAccessGrantedFor(nsPIDOMWindowInner* aFirstPartyWindow,
                                                              nsIURI* aURI)
 {
   MOZ_ASSERT(aFirstPartyWindow);
   MOZ_ASSERT(!nsContentUtils::IsTrackingResourceWindow(aFirstPartyWindow));
   MOZ_ASSERT(aURI);
 
+  LOG_SPEC(("Computing a best guess as to whether window %p has access to URI %s",
+            aFirstPartyWindow, _spec), aURI);
+
   if (StaticPrefs::network_cookie_cookieBehavior() !=
         nsICookieService::BEHAVIOR_REJECT_TRACKER) {
+    LOG(("Disabled by the pref (%d), bail out early",
+         StaticPrefs::network_cookie_cookieBehavior()));
     return true;
   }
 
   if (!nsContentUtils::IsThirdPartyWindowOrChannel(aFirstPartyWindow,
                                                    nullptr, aURI)) {
+    LOG(("Our window isn't a third-party window"));
     return true;
   }
 
   nsCOMPtr<nsIPrincipal> parentPrincipal =
     nsGlobalWindowInner::Cast(aFirstPartyWindow)->GetPrincipal();
   if (NS_WARN_IF(!parentPrincipal)) {
+    LOG(("Failed to get the first party window's principal"));
     return false;
   }
 
   nsCookieAccess access = CheckCookiePermissionForPrincipal(parentPrincipal);
   if (access != nsICookiePermission::ACCESS_DEFAULT) {
+    LOG(("CheckCookiePermissionForPrincipal() returned a non-default access code (%d), returning %s",
+         int(access), access != nsICookiePermission::ACCESS_DENY ?
+                        "success" : "failure"));
     return access != nsICookiePermission::ACCESS_DENY;
   }
 
   nsAutoString origin;
   nsresult rv = nsContentUtils::GetUTFOrigin(aURI, origin);
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG_SPEC(("Failed to compute the origin from %s", _spec), aURI);
     return false;
   }
 
   NS_ConvertUTF16toUTF8 utf8Origin(origin);
 
   nsAutoCString type;
   CreatePermissionKey(utf8Origin, utf8Origin, type);
 
   nsCOMPtr<nsIPermissionManager> pm = services::GetPermissionManager();
   if (NS_WARN_IF(!pm)) {
+    LOG(("Failed to obtain the permission manager"));
     return false;
   }
 
   uint32_t result = 0;
   rv = pm->TestPermissionFromPrincipal(parentPrincipal, type.get(), &result);
   if (NS_WARN_IF(NS_FAILED(rv))) {
+    LOG(("Failed to test the permission"));
     return false;
   }
 
+  nsCOMPtr<nsIURI> parentPrincipalURI;
+  Unused << parentPrincipal->GetURI(getter_AddRefs(parentPrincipalURI));
+  LOG_SPEC(("Testing permission type %s for %s resulted in %d (%s)",
+            type.get(), _spec, int(result),
+            result == nsIPermissionManager::ALLOW_ACTION ?
+              "success" : "failure"), parentPrincipalURI);
+
   return result == nsIPermissionManager::ALLOW_ACTION;
 }