From ef41c4971f292955f46fbb42cf60e4f0d414f469 Mon Sep 17 00:00:00 2001
From: Francois Marier <francois@mozilla.com>
Date: Mon, 14 Sep 2015 18:03:48 -0700
Subject: [PATCH] Bug 1203347 - Increase Safe Browsing debug logging around
 downloads. r=gcp

---
 .../url-classifier/ProtocolParser.cpp         | 23 +++++++++++--------
 .../nsUrlClassifierDBService.cpp              | 13 ++++++++++-
 2 files changed, 26 insertions(+), 10 deletions(-)

diff --git a/toolkit/components/url-classifier/ProtocolParser.cpp b/toolkit/components/url-classifier/ProtocolParser.cpp
index f85554f7ae11..d58e2b56715d 100644
--- a/toolkit/components/url-classifier/ProtocolParser.cpp
+++ b/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;
diff --git a/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp b/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
index 5f7e3544b8ae..2abd3af8dec6 100644
--- a/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
+++ b/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