Bug 1203347 - Increase Safe Browsing debug logging around downloads. r=gcp
authorFrancois Marier <francois@mozilla.com>
Mon, 14 Sep 2015 18:03:48 -0700
changeset 295102 4915faf3ff5b564b05c401a041b3d2efba01aca0
parent 295101 1248bbef83a4b036a5daea80b56aab5a5bf882f8
child 295103 095bcf27e08100415ccda86a341633a49d46905a
push id5245
push userraliiev@mozilla.com
push dateThu, 29 Oct 2015 11:30:51 +0000
treeherdermozilla-beta@dac831dc1bd0 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgcp
bugs1203347
milestone43.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1203347 - Increase Safe Browsing debug logging around downloads. r=gcp
toolkit/components/url-classifier/ProtocolParser.cpp
toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
--- a/toolkit/components/url-classifier/ProtocolParser.cpp
+++ b/toolkit/components/url-classifier/ProtocolParser.cpp
@@ -7,20 +7,19 @@
 #include "LookupCache.h"
 #include "nsNetCID.h"
 #include "mozilla/Logging.h"
 #include "prnetdb.h"
 #include "prprf.h"
 
 #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 {
 
 // Updates will fail if fed chunks larger than this
 const uint32_t MAX_CHUNK_SIZE = (1024 * 1024);
 // Updates will fail if the total number of tocuhed chunks is larger than this
 const uint32_t MAX_CHUNK_RANGE = 1000000;
@@ -72,16 +71,20 @@ ProtocolParser::ProtocolParser()
 ProtocolParser::~ProtocolParser()
 {
   CleanupUpdates();
 }
 
 nsresult
 ProtocolParser::Init(nsICryptoHash* aHasher)
 {
+  if (!gUrlClassifierProtocolParserLog) {
+    gUrlClassifierProtocolParserLog =
+      PR_NewLogModule("UrlClassifierProtocolParser");
+  }
   mCryptoHash = aHasher;
   return NS_OK;
 }
 
 void
 ProtocolParser::SetCurrentTable(const nsACString& aTable)
 {
   mTableUpdate = GetTableUpdate(aTable);
@@ -117,24 +120,24 @@ ProtocolParser::AppendStream(const nsACS
 nsresult
 ProtocolParser::ProcessControl(bool* aDone)
 {
   nsresult rv;
 
   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")) {
       mResetRequested = true;
     } else if (StringBeginsWith(line, NS_LITERAL_CSTRING("u:"))) {
       rv = ProcessForward(line);
       NS_ENSURE_SUCCESS(rv, rv);
     } else if (StringBeginsWith(line, NS_LITERAL_CSTRING("a:")) ||
@@ -204,37 +207,39 @@ ProtocolParser::ProcessChunkControl(cons
   mChunkState.Clear();
 
   if (PR_sscanf(aLine.get(),
                 "%c:%d:%d:%d",
                 &command,
                 &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;
   }
 
   if (!(mChunkState.hashSize == PREFIX_SIZE || mChunkState.hashSize == COMPLETE_SIZE)) {
     NS_WARNING("Invalid hash size specified in update.");
     return NS_ERROR_FAILURE;
   }
 
   if (StringEndsWith(mTableUpdate->TableName(),
                      NS_LITERAL_CSTRING("-shavar")) ||
       StringEndsWith(mTableUpdate->TableName(),
                      NS_LITERAL_CSTRING("-simple"))) {
     // Accommodate test tables ending in -simple for now.
     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;
   switch (mChunkState.type) {
     case CHUNK_ADD:
       rv = mTableUpdate->NewAddChunk(mChunkState.num);
       if (NS_FAILED(rv)) {
         return rv;
@@ -303,17 +308,17 @@ ProtocolParser::ProcessChunk(bool* aDone
   // Pull the chunk out of the pending stream data.
   nsAutoCString chunk;
   chunk.Assign(Substring(mPending, 0, mChunkState.length));
   mPending.Cut(0, mChunkState.length);
 
   *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);
   }
   if (StringEndsWith(mTableUpdate->TableName(),
              NS_LITERAL_CSTRING("-digest256"))) {
     return ProcessDigestChunk(chunk);
   }
@@ -410,17 +415,17 @@ ProtocolParser::ProcessShaChunk(const ns
     } else if (mChunkState.type == CHUNK_ADD && mChunkState.hashSize == COMPLETE_SIZE) {
       rv = ProcessHostAddComplete(numEntries, aChunk, &start);
     } else if (mChunkState.type == CHUNK_SUB && mChunkState.hashSize == PREFIX_SIZE) {
       rv = ProcessHostSub(domain, numEntries, aChunk, &start);
     } else if (mChunkState.type == CHUNK_SUB && mChunkState.hashSize == COMPLETE_SIZE) {
       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;
     }
     NS_ENSURE_SUCCESS(rv, rv);
   }
 
   return NS_OK;
--- a/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
+++ b/toolkit/components/url-classifier/nsUrlClassifierDBService.cpp
@@ -28,16 +28,17 @@
 #include "nsTArray.h"
 #include "nsNetCID.h"
 #include "nsThreadUtils.h"
 #include "nsXPCOMStrings.h"
 #include "nsProxyRelease.h"
 #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"
 #include "mozilla/Telemetry.h"
 #include "mozilla/Logging.h"
 #include "prprf.h"
 #include "prnetdb.h"
 #include "Entries.h"
@@ -511,16 +512,18 @@ nsUrlClassifierDBServiceWorker::FinishSt
       const ProtocolParser::ForwardedUpdate &forward = forwards[i];
       mUpdateObserver->UpdateUrlRequested(forward.url, forward.table);
     }
     // Hold on to any TableUpdate objects that were created by the
     // parser.
     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);
 
   if (NS_SUCCEEDED(mUpdateStatus)) {
     if (mProtocolParser->ResetRequested()) {
       mClassifier->Reset();
    }
@@ -535,25 +538,33 @@ NS_IMETHODIMP
 nsUrlClassifierDBServiceWorker::FinishUpdate()
 {
   if (gShuttingDownThread)
     return NS_ERROR_NOT_INITIALIZED;
   NS_ENSURE_STATE(mUpdateObserver);
 
   if (NS_SUCCEEDED(mUpdateStatus)) {
     mUpdateStatus = ApplyUpdate();
+  } else {
+    LOG(("nsUrlClassifierDBServiceWorker::FinishUpdate() Not running "
+         "ApplyUpdate() since the update has already failed."));
   }
 
   mMissCache.Clear();
 
   if (NS_SUCCEEDED(mUpdateStatus)) {
     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
      * longer than normal because our update failed
     */
     mClassifier->MarkSpoiled(mUpdateTables);
   }
   mUpdateObserver = nullptr;