add logging coverage for cookie eviction and db operations. b=401998, r+sr=mconnor, a=beltzner

netwerk/cookie/src/nsCookieService.cpp

@@ -204,7 +204,11 @@ struct nsEnumerationData
 static PRLogModuleInfo *sCookieLog = PR_NewLogModule("cookie");
 
 #define COOKIE_LOGFAILURE(a, b, c, d)    LogFailure(a, b, c, d)
-#define COOKIE_LOGSUCCESS(a, b, c, d) LogSuccess(a, b, c, d)
+#define COOKIE_LOGSUCCESS(a, b, c, d, e) LogSuccess(a, b, c, d, e)
+#define COOKIE_LOGEVICTED(a)             LogEvicted(a)
+#define COOKIE_LOGSTRING(lvl, fmt) \
+  PR_LOG(sCookieLog, lvl, fmt);    \
+  PR_LOG(sCookieLog, lvl, ("\n"))
 
 static void
 LogFailure(PRBool aSetCookie, nsIURI *aHostURI, const char *aCookieString, const char *aReason)
@@ -234,22 +238,8 @@ LogFailure(PRBool aSetCookie, nsIURI *aHostURI, const char *aCookieString, const
 }
 
 static void
-LogSuccess(PRBool aSetCookie, nsIURI *aHostURI, const char *aCookieString, nsCookie *aCookie)
+LogCookie(nsCookie *aCookie)
 {
-  // if logging isn't enabled, return now to save cycles
-  if (!PR_LOG_TEST(sCookieLog, PR_LOG_DEBUG)) {
-    return;
-  }
-
-  nsCAutoString spec;
-  if (aHostURI)
-    aHostURI->GetAsciiSpec(spec);
-
-  PR_LOG(sCookieLog, PR_LOG_DEBUG,
-    ("===== %s =====\n", aSetCookie ? "COOKIE ACCEPTED" : "COOKIE SENT"));
-  PR_LOG(sCookieLog, PR_LOG_DEBUG,("request URL: %s\n", spec.get()));
-  PR_LOG(sCookieLog, PR_LOG_DEBUG,("cookie string: %s\n", aCookieString));
-
   PRExplodedTime explodedTime;
   PR_ExplodeTime(PR_Now(), PR_GMTParameters, &explodedTime);
   char timeString[40];
@@ -257,7 +247,7 @@ LogSuccess(PRBool aSetCookie, nsIURI *aHostURI, const char *aCookieString, nsCoo
 
   PR_LOG(sCookieLog, PR_LOG_DEBUG,("current time: %s", timeString));
 
-  if (aSetCookie) {
+  if (aCookie) {
     PR_LOG(sCookieLog, PR_LOG_DEBUG,("----------------\n"));
     PR_LOG(sCookieLog, PR_LOG_DEBUG,("name: %s\n", aCookie->Name().get()));
     PR_LOG(sCookieLog, PR_LOG_DEBUG,("value: %s\n", aCookie->Value().get()));
@@ -277,6 +267,44 @@ LogSuccess(PRBool aSetCookie, nsIURI *aHostURI, const char *aCookieString, nsCoo
     PR_LOG(sCookieLog, PR_LOG_DEBUG,("is secure: %s\n", aCookie->IsSecure() ? "true" : "false"));
     PR_LOG(sCookieLog, PR_LOG_DEBUG,("is httpOnly: %s\n", aCookie->IsHttpOnly() ? "true" : "false"));
   }
+}
+
+static void
+LogSuccess(PRBool aSetCookie, nsIURI *aHostURI, const char *aCookieString, nsCookie *aCookie, PRBool aReplacing)
+{
+  // if logging isn't enabled, return now to save cycles
+  if (!PR_LOG_TEST(sCookieLog, PR_LOG_DEBUG)) {
+    return;
+  }
+
+  nsCAutoString spec;
+  if (aHostURI)
+    aHostURI->GetAsciiSpec(spec);
+
+  PR_LOG(sCookieLog, PR_LOG_DEBUG,
+    ("===== %s =====\n", aSetCookie ? "COOKIE ACCEPTED" : "COOKIE SENT"));
+  PR_LOG(sCookieLog, PR_LOG_DEBUG,("request URL: %s\n", spec.get()));
+  PR_LOG(sCookieLog, PR_LOG_DEBUG,("cookie string: %s\n", aCookieString));
+  if (aSetCookie)
+    PR_LOG(sCookieLog, PR_LOG_DEBUG,("replaces existing cookie: %s\n", aReplacing ? "true" : "false"));
+
+  LogCookie(aCookie);
+
+  PR_LOG(sCookieLog, PR_LOG_DEBUG,("\n"));
+}
+
+static void
+LogEvicted(nsCookie *aCookie)
+{
+  // if logging isn't enabled, return now to save cycles
+  if (!PR_LOG_TEST(sCookieLog, PR_LOG_DEBUG)) {
+    return;
+  }
+
+  PR_LOG(sCookieLog, PR_LOG_DEBUG,("===== COOKIE EVICTED =====\n"));
+
+  LogCookie(aCookie);
+
   PR_LOG(sCookieLog, PR_LOG_DEBUG,("\n"));
 }
 
@@ -288,14 +316,16 @@ LogFailure(PRBool aSetCookie, nsIURI *aHostURI, const nsAFlatCString &aCookieStr
 }
 
 static inline void
-LogSuccess(PRBool aSetCookie, nsIURI *aHostURI, const nsAFlatCString &aCookieString, nsCookie *aCookie)
+LogSuccess(PRBool aSetCookie, nsIURI *aHostURI, const nsAFlatCString &aCookieString, nsCookie *aCookie, PRBool aReplacing)
 {
-  LogSuccess(aSetCookie, aHostURI, aCookieString.get(), aCookie);
+  LogSuccess(aSetCookie, aHostURI, aCookieString.get(), aCookie, aReplacing);
 }
 
 #else
 #define COOKIE_LOGFAILURE(a, b, c, d)    /* nothing */
-#define COOKIE_LOGSUCCESS(a, b, c, d) /* nothing */
+#define COOKIE_LOGSUCCESS(a, b, c, d, e) /* nothing */
+#define COOKIE_LOGEVICTED(a)             /* nothing */
+#define COOKIE_LOGSTRING(a, b)           /* nothing */
 #endif
 
 /******************************************************************************
@@ -401,7 +431,9 @@ nsCookieService::Init()
 
   // ignore failure here, since it's non-fatal (we can run fine without
   // persistent storage - e.g. if there's no profile)
-  InitDB();
+  nsresult rv = InitDB();
+  if (NS_FAILED(rv))
+    COOKIE_LOGSTRING(PR_LOG_WARNING, ("Init(): InitDB() gave error %x", rv));
 
   mObserverService = do_GetService("@mozilla.org/observer-service;1");
   if (mObserverService) {
@@ -890,6 +922,8 @@ nsCookieService::Read()
       delete newCookie;
   }
 
+  COOKIE_LOGSTRING(PR_LOG_DEBUG, ("Read(): %ld cookies read", mCookieCount));
+
   return NS_OK;
 }
 
@@ -1029,6 +1063,8 @@ nsCookieService::ImportCookies()
   // we're done importing - delete the old cookie file
   cookieFile->Remove(PR_FALSE);
 
+  COOKIE_LOGSTRING(PR_LOG_DEBUG, ("ImportCookies(): %ld cookies imported", mCookieCount));
+
   return NS_OK;
 }
 
@@ -1180,7 +1216,7 @@ nsCookieService::GetCookieInternal(nsIURI      *aHostURI,
   // it's wasteful to alloc a new string; but we have no other choice, until we
   // fix the callers to use nsACStrings.
   if (!cookieData.IsEmpty()) {
-    COOKIE_LOGSUCCESS(GET_COOKIE, aHostURI, cookieData, nsnull);
+    COOKIE_LOGSUCCESS(GET_COOKIE, aHostURI, cookieData, nsnull, nsnull);
     *aCookie = ToNewCString(cookieData);
   }
 }
@@ -1356,16 +1392,18 @@ nsCookieService::AddInternal(nsCookie   *aCookie,
     }
 
     // if we deleted an old cookie, notify consumers
-    if (oldCookie)
+    if (oldCookie) {
+      COOKIE_LOGEVICTED(oldCookie);
       NotifyChanged(oldCookie, NS_LITERAL_STRING("deleted").get());
     }
+  }
 
   // add the cookie to head of list
   AddCookieToList(aCookie);
   NotifyChanged(aCookie, foundCookie ? NS_LITERAL_STRING("changed").get()
                                      : NS_LITERAL_STRING("added").get());
 
-  COOKIE_LOGSUCCESS(SET_COOKIE, aHostURI, aCookieHeader, aCookie);
+  COOKIE_LOGSUCCESS(SET_COOKIE, aHostURI, aCookieHeader, aCookie, foundCookie != nsnull);
 }
 
 /******************************************************************************
@@ -2013,7 +2051,9 @@ removeExpiredCallback(nsCookieEntry *aEntry,
 void
 nsCookieService::RemoveExpiredCookies(PRInt64 aCurrentTime)
 {
+  PRUint32 initialCookieCount = mCookieCount;
   mHostTable.EnumerateEntries(removeExpiredCallback, &aCurrentTime);
+  COOKIE_LOGSTRING(PR_LOG_DEBUG, ("RemoveExpiredCookies(): %ld purged; %ld remain", initialCookieCount - mCookieCount, mCookieCount));
 }
 
 // find whether a given cookie has been previously set. this is provided by the
@@ -2109,11 +2149,14 @@ nsCookieService::RemoveCookieFromList(nsListIter &aIter)
     mozStorageStatementScoper scoper(mStmtDelete);
 
     nsresult rv = mStmtDelete->BindInt64Parameter(0, aIter.current->CreationID());
-    NS_WARN_IF_FALSE(NS_SUCCEEDED(rv), "binding parameter failed");
     if (NS_SUCCEEDED(rv)) {
       PRBool hasResult;
       rv = mStmtDelete->ExecuteStep(&hasResult);
-      NS_WARN_IF_FALSE(NS_SUCCEEDED(rv), "db remove failed!");
+    }
+
+    if (NS_FAILED(rv)) {
+      NS_WARNING("db remove failed!");
+      COOKIE_LOGSTRING(PR_LOG_WARNING, ("RemoveCookieFromList(): removing from db gave error %x", rv));
     }
   }
 
@@ -2192,11 +2235,15 @@ nsCookieService::AddCookieToList(nsCookie *aCookie, PRBool aWriteToDB)
     mozStorageStatementScoper scoper(mStmtInsert);
 
     nsresult rv = bindCookieParameters(mStmtInsert, aCookie);
-    NS_ENSURE_SUCCESS(rv, PR_TRUE);
+    if (NS_SUCCEEDED(rv)) {
-
       PRBool hasResult;
       rv = mStmtInsert->ExecuteStep(&hasResult);
-    NS_WARN_IF_FALSE(NS_SUCCEEDED(rv), "db insert failed!");
+    }
+
+    if (NS_FAILED(rv)) {
+      NS_WARNING("db insert failed!");
+      COOKIE_LOGSTRING(PR_LOG_WARNING, ("AddCookieToList(): adding to db gave error %x", rv));
+    }
   }
 
   return PR_TRUE;