Bug 1260407 - added logging for proxy/pac to aid debugging, r=mcmanus
authorDaniel Stenberg <daniel@haxx.se>
Tue, 29 Mar 2016 05:23:00 +0200
changeset 290861 4a7ab6d8c379fe1e700d61c306c21c687176e48a
parent 290860 4c3f6045b2812c4c8dd1f8521ff0adee1186e50a
child 290862 77b78203d8b153d16708b6488f30f131bbe8c8f0
push id74397
push usercbook@mozilla.com
push dateWed, 30 Mar 2016 06:58:47 +0000
treeherdermozilla-inbound@4a7ab6d8c379 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmcmanus
bugs1260407
milestone48.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 1260407 - added logging for proxy/pac to aid debugging, r=mcmanus
netwerk/base/nsPACMan.cpp
netwerk/base/nsProtocolProxyService.cpp
--- a/netwerk/base/nsPACMan.cpp
+++ b/netwerk/base/nsPACMan.cpp
@@ -356,18 +356,21 @@ nsPACMan::AsyncGetProxyForURI(nsIURI *ur
                               bool mainThreadResponse)
 {
   MOZ_ASSERT(NS_IsMainThread(), "wrong thread");
   if (mShutdown)
     return NS_ERROR_NOT_AVAILABLE;
 
   // Maybe Reload PAC
   if (!mPACURISpec.IsEmpty() && !mScheduledReload.IsNull() &&
-      TimeStamp::Now() > mScheduledReload)
+      TimeStamp::Now() > mScheduledReload) {
+    LOG(("nsPACMan::AsyncGetProxyForURI reload as scheduled\n"));
+
     LoadPACFromURI(EmptyCString());
+  }
 
   RefPtr<PendingPACQuery> query =
     new PendingPACQuery(this, uri, appId, isInIsolatedMozBrowser, callback,
                         mainThreadResponse);
 
   if (IsPACURI(uri)) {
     // deal with this directly instead of queueing it
     query->Complete(NS_OK, EmptyCString());
@@ -399,16 +402,17 @@ nsPACMan::LoadPACFromURI(const nsCString
 {
   NS_ENSURE_STATE(!mShutdown);
   NS_ENSURE_ARG(!spec.IsEmpty() || !mPACURISpec.IsEmpty());
 
   nsCOMPtr<nsIStreamLoader> loader =
       do_CreateInstance(NS_STREAMLOADER_CONTRACTID);
   NS_ENSURE_STATE(loader);
 
+  LOG(("nsPACMan::LoadPACFromURI %s\n", spec.get()));
   // Since we might get called from nsProtocolProxyService::Init, we need to
   // post an event back to the main thread before we try to use the IO service.
   //
   // But, we need to flag ourselves as loading, so that we queue up any PAC
   // queries the enter between now and when we actually load the PAC file.
 
   if (!mLoadPending) {
     nsCOMPtr<nsIRunnable> event =
@@ -501,16 +505,19 @@ nsPACMan::OnLoadFailure()
   }
 
   int32_t interval = minInterval << mLoadFailureCount++;  // seconds
   if (!interval || interval > maxInterval)
     interval = maxInterval;
 
   mScheduledReload = TimeStamp::Now() + TimeDuration::FromSeconds(interval);
 
+  LOG(("OnLoadFailure: retry in %d seconds (%d fails)\n",
+       interval, mLoadFailureCount));
+
   // while we wait for the retry queued members should try direct
   // even if that means fast failure.
   PostCancelPendingQ(NS_ERROR_NOT_AVAILABLE);
 }
 
 void
 nsPACMan::CancelExistingLoad()
 {
@@ -598,36 +605,39 @@ nsPACMan::ProcessPending()
   nsAutoCString PACURI;
 
   // first we need to consider the system proxy changing the pac url
   if (mSystemProxySettings &&
       NS_SUCCEEDED(mSystemProxySettings->GetPACURI(PACURI)) &&
       !PACURI.IsEmpty() &&
       !PACURI.Equals(mPACURISpec)) {
     query->UseAlternatePACFile(PACURI);
+    LOG(("Use PAC from system settings: %s\n", PACURI.get()));
     completed = true;
   }
 
   // now try the system proxy settings for this particular url if
   // PAC was not specified
   if (!completed && mSystemProxySettings && PACURI.IsEmpty() &&
       NS_SUCCEEDED(mSystemProxySettings->
                    GetProxyForURI(query->mSpec, query->mScheme,
                                   query->mHost, query->mPort,
                                   pacString))) {
+    LOG(("Use proxy from system settings: %s\n", pacString.get()));
     query->Complete(NS_OK, pacString);
     completed = true;
   }
 
   // the systemproxysettings didn't complete the resolution. try via PAC
   if (!completed) {
     nsresult status = mPAC.GetProxyForURI(query->mSpec, query->mHost,
                                           query->mAppId, query->mAppOrigin,
                                           query->mIsInIsolatedMozBrowser,
                                           pacString);
+    LOG(("Use proxy from PAC: %s\n", pacString.get()));
     query->Complete(status, pacString);
   }
 
   mInProgress = false;
   return true;
 }
 
 NS_IMPL_ISUPPORTS(nsPACMan, nsIStreamLoaderObserver,
@@ -641,20 +651,23 @@ nsPACMan::OnStreamComplete(nsIStreamLoad
                            const uint8_t *data)
 {
   MOZ_ASSERT(NS_IsMainThread(), "wrong thread");
   if (mLoader != loader) {
     // If this happens, then it means that LoadPACFromURI was called more
     // than once before the initial call completed.  In this case, status
     // should be NS_ERROR_ABORT, and if so, then we know that we can and
     // should delay any processing.
+    LOG(("OnStreamComplete: called more than once\n"));
     if (status == NS_ERROR_ABORT)
       return NS_OK;
   }
 
+  LOG(("OnStreamComplete: entry\n"));
+
   if (NS_SUCCEEDED(status) && HttpRequestSucceeded(loader)) {
     // Get the URI spec used to load this PAC script.
     nsAutoCString pacURI;
     {
       nsCOMPtr<nsIRequest> request;
       loader->GetRequest(getter_AddRefs(request));
       nsCOMPtr<nsIChannel> channel = do_QueryInterface(request);
       if (channel) {
@@ -676,22 +689,25 @@ nsPACMan::OnStreamComplete(nsIStreamLoad
     // that is where it will be used.
 
     RefPtr<ExecutePACThreadAction> pending =
       new ExecutePACThreadAction(this);
     pending->SetupPAC(text, dataLen, pacURI);
     if (mPACThread)
       mPACThread->Dispatch(pending, nsIEventTarget::DISPATCH_NORMAL);
 
+    LOG(("OnStreamComplete: process the PAC contents\n"));
+
     // Even if the PAC file could not be parsed, we did succeed in loading the
     // data for it.
     mLoadFailureCount = 0;
   } else {
     // We were unable to load the PAC file (presumably because of a network
     // failure).  Try again a little later.
+    LOG(("OnStreamComplete: unable to load PAC, retry later\n"));
     OnLoadFailure();
   }
 
   if (NS_SUCCEEDED(status))
     PostProcessPendingQ();
   else
     PostCancelPendingQ(status);
 
--- a/netwerk/base/nsProtocolProxyService.cpp
+++ b/netwerk/base/nsProtocolProxyService.cpp
@@ -211,22 +211,26 @@ private:
         // In the cancelation case, we may still have another PLEvent in
         // the queue that wants to call DoCallback.  No need to wait for
         // it, just run the callback now.
         DoCallback();
     }
 
     void DoCallback()
     {
+        bool pacAvailable = true;
         if (mStatus == NS_ERROR_NOT_AVAILABLE && !mProxyInfo) {
             // If the PAC service is not avail (e.g. failed pac load
             // or shutdown) then we will be going direct. Make that
             // mapping now so that any filters are still applied.
             mPACString = NS_LITERAL_CSTRING("DIRECT;");
             mStatus = NS_OK;
+
+            LOG(("pac not available, use DIRECT\n"));
+            pacAvailable = false;
         }
 
         // Generate proxy info from the PAC string if appropriate
         if (NS_SUCCEEDED(mStatus) && !mProxyInfo && !mPACString.IsEmpty()) {
             mPPS->ProcessPACString(mPACString, mResolveFlags,
                                    getter_AddRefs(mProxyInfo));
             nsCOMPtr<nsIURI> proxyURI;
             GetProxyURI(mChannel, getter_AddRefs(proxyURI));
@@ -234,17 +238,20 @@ private:
             // Now apply proxy filters
             nsProtocolInfo info;
             mStatus = mPPS->GetProtocolInfo(proxyURI, &info);
             if (NS_SUCCEEDED(mStatus))
                 mPPS->ApplyFilters(mChannel, info, mProxyInfo);
             else
                 mProxyInfo = nullptr;
 
-            LOG(("pac thread callback %s\n", mPACString.get()));
+            if(pacAvailable) {
+                // if !pacAvailable, it was already logged above
+                LOG(("pac thread callback %s\n", mPACString.get()));
+            }
             if (NS_SUCCEEDED(mStatus))
                 mPPS->MaybeDisableDNSPrefetch(mProxyInfo);
             mCallback->OnProxyAvailable(this, mChannel, mProxyInfo, mStatus);
         }
         else if (NS_SUCCEEDED(mStatus) && !mPACURL.IsEmpty()) {
             LOG(("pac thread callback indicates new pac file load\n"));
 
             nsCOMPtr<nsIURI> proxyURI;