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 291038 4a7ab6d8c379fe1e700d61c306c21c687176e48a
parent 291037 4c3f6045b2812c4c8dd1f8521ff0adee1186e50a
child 291039 77b78203d8b153d16708b6488f30f131bbe8c8f0
push id19656
push usergwagner@mozilla.com
push dateMon, 04 Apr 2016 13:43:23 +0000
treeherderb2g-inbound@e99061fde28a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmcmanus
bugs1260407
milestone48.0a1
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;