Bug 1203347 - Increase Safe Browsing debug logging around downloads. r=gcp

toolkit/components/url-classifier/ProtocolParser.cpp

@@ -12,10 +12,9 @@
 
 #include "nsUrlClassifierUtils.h"
 
-// NSPR_LOG_MODULES=UrlClassifierDbService:5
-extern PRLogModuleInfo *gUrlClassifierDbServiceLog;
-#define LOG(args) MOZ_LOG(gUrlClassifierDbServiceLog, mozilla::LogLevel::Debug, args)
-#define LOG_ENABLED() MOZ_LOG_TEST(gUrlClassifierDbServiceLog, mozilla::LogLevel::Debug)
+// NSPR_LOG_MODULES=UrlClassifierProtocolParser:5
+PRLogModuleInfo *gUrlClassifierProtocolParserLog = nullptr;
+#define PARSER_LOG(args) MOZ_LOG(gUrlClassifierProtocolParserLog, mozilla::LogLevel::Debug, args)
 
 namespace mozilla {
 namespace safebrowsing {
@@ -77,6 +76,10 @@ ProtocolParser::~ProtocolParser()
 nsresult
 ProtocolParser::Init(nsICryptoHash* aHasher)
 {
+  if (!gUrlClassifierProtocolParserLog) {
+    gUrlClassifierProtocolParserLog =
+      PR_NewLogModule("UrlClassifierProtocolParser");
+  }
   mCryptoHash = aHasher;
   return NS_OK;
 }
@@ -122,14 +125,14 @@ ProtocolParser::ProcessControl(bool* aDone)
   nsAutoCString line;
   *aDone = true;
   while (NextLine(line)) {
-    //LOG(("Processing %s\n", line.get()));
+    PARSER_LOG(("Processing %s\n", line.get()));
 
     if (StringBeginsWith(line, NS_LITERAL_CSTRING("i:"))) {
       // Set the table name from the table header line.
       SetCurrentTable(Substring(line, 2));
     } else if (StringBeginsWith(line, NS_LITERAL_CSTRING("n:"))) {
       if (PR_sscanf(line.get(), "n:%d", &mUpdateWait) != 1) {
-        LOG(("Error parsing n: '%s' (%d)", line.get(), mUpdateWait));
+        PARSER_LOG(("Error parsing n: '%s' (%d)", line.get(), mUpdateWait));
         mUpdateWait = 0;
       }
     } else if (line.EqualsLiteral("r:pleasereset")) {
@@ -209,10 +212,12 @@ ProtocolParser::ProcessChunkControl(const nsCString& aLine)
                 &mChunkState.num, &mChunkState.hashSize, &mChunkState.length)
       != 4)
   {
+    NS_WARNING(("PR_sscanf failed"));
     return NS_ERROR_FAILURE;
   }
 
   if (mChunkState.length > MAX_CHUNK_SIZE) {
+    NS_WARNING("Invalid length specified in update.");
     return NS_ERROR_FAILURE;
   }
 
@@ -229,7 +234,7 @@ ProtocolParser::ProcessChunkControl(const nsCString& aLine)
     mChunkState.type = (command == 'a') ? CHUNK_ADD : CHUNK_SUB;
   } else if (StringEndsWith(mTableUpdate->TableName(),
     NS_LITERAL_CSTRING("-digest256"))) {
-    LOG(("Processing digest256 data"));
+    PARSER_LOG(("Processing digest256 data"));
     mChunkState.type = (command == 'a') ? CHUNK_ADD_DIGEST : CHUNK_SUB_DIGEST;
   }
   nsresult rv;
@@ -308,7 +313,7 @@ ProtocolParser::ProcessChunk(bool* aDone)
   *aDone = false;
   mState = PROTOCOL_STATE_CONTROL;
 
-  //LOG(("Handling a %d-byte chunk", chunk.Length()));
+  PARSER_LOG(("Handling a %d-byte chunk", chunk.Length()));
   if (StringEndsWith(mTableUpdate->TableName(),
                      NS_LITERAL_CSTRING("-shavar"))) {
     return ProcessShaChunk(chunk);
@@ -415,7 +420,7 @@ ProtocolParser::ProcessShaChunk(const nsACString& aChunk)
       rv = ProcessHostSubComplete(numEntries, aChunk, &start);
     } else {
       NS_WARNING("Unexpected chunk type/hash size!");
-      LOG(("Got an unexpected chunk type/hash size: %s:%d",
+      PARSER_LOG(("Got an unexpected chunk type/hash size: %s:%d",
            mChunkState.type == CHUNK_ADD ? "add" : "sub",
            mChunkState.hashSize));
       return NS_ERROR_FAILURE;

toolkit/components/url-classifier/nsUrlClassifierDBService.cpp

@@ -33,6 +33,7 @@
 #include "nsString.h"
 #include "mozilla/Atomics.h"
 #include "mozilla/DebugOnly.h"
+#include "mozilla/ErrorNames.h"
 #include "mozilla/Mutex.h"
 #include "mozilla/Preferences.h"
 #include "mozilla/TimeStamp.h"
@@ -516,6 +517,8 @@ nsUrlClassifierDBServiceWorker::FinishStream()
     mTableUpdates.AppendElements(mProtocolParser->GetTableUpdates());
     mProtocolParser->ForgetTableUpdates();
   } else {
+    LOG(("nsUrlClassifierDBService::FinishStream Failed to parse the stream "
+         "using mProtocolParser."));
     mUpdateStatus = mProtocolParser->Status();
   }
   mUpdateObserver->StreamFinished(mProtocolParser->Status(), 0);
@@ -540,6 +543,9 @@ nsUrlClassifierDBServiceWorker::FinishUpdate()
 
   if (NS_SUCCEEDED(mUpdateStatus)) {
     mUpdateStatus = ApplyUpdate();
+  } else {
+    LOG(("nsUrlClassifierDBServiceWorker::FinishUpdate() Not running "
+         "ApplyUpdate() since the update has already failed."));
   }
 
   mMissCache.Clear();
@@ -548,7 +554,12 @@ nsUrlClassifierDBServiceWorker::FinishUpdate()
     LOG(("Notifying success: %d", mUpdateWait));
     mUpdateObserver->UpdateSuccess(mUpdateWait);
   } else {
-    LOG(("Notifying error: %d", mUpdateStatus));
+    if (LOG_ENABLED()) {
+      nsAutoCString errorName;
+      mozilla::GetErrorName(mUpdateStatus, errorName);
+      LOG(("Notifying error: %s (%d)", errorName.get(), mUpdateStatus));
+    }
+
     mUpdateObserver->UpdateError(mUpdateStatus);
     /*
      * mark the tables as spoiled, we don't want to block hosts