Add logging to help diagnose redirect issue
authorkrollin@apple.com <krollin@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 26 Feb 2020 21:12:54 +0000 (21:12 +0000)
committerkrollin@apple.com <krollin@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 26 Feb 2020 21:12:54 +0000 (21:12 +0000)
https://bugs.webkit.org/show_bug.cgi?id=207916
<rdar://problem/59567875>

Reviewed by Chris Dumez.

We're seeing an issue where communication between the WebContent
process and the Network process seems to come to a stop between
NetworkResourceLoader::continueWillSendRedirectedRequest and
NetworkResourceLoader::continueWillSendRequest. We do see a
WebResourceLoader::willSendRequest log line between those two
NetworkResourceLoader logging lines, but nothing else. Add a bunch of
logging in this area to help determine what's happening.

Source/WebCore:

No new tests -- no new or changed functionality.

* loader/PolicyChecker.cpp:
(WebCore::PolicyChecker::checkNavigationPolicy):
* loader/ResourceLoader.cpp:
(WebCore::ResourceLoader::loadDataURL):
(WebCore::ResourceLoader::willSendRequestInternal):
(WebCore::ResourceLoader::didFinishLoading):
(WebCore::ResourceLoader::didFail):
(WebCore::ResourceLoader::willSendRequestAsync):
(WebCore::ResourceLoader::wasBlocked):
(WebCore::ResourceLoader::cannotShowURL):
* loader/SubresourceLoader.cpp:
(WebCore::SubresourceLoader::init):
(WebCore::SubresourceLoader::willSendRequestInternal):
(WebCore::SubresourceLoader::didReceiveResponse):
(WebCore::SubresourceLoader::didFinishLoading):
(WebCore::SubresourceLoader::didFail):
(WebCore::SubresourceLoader::willCancel):
* loader/cache/CachedRawResource.cpp:
(WebCore::CachedRawResource::redirectReceived):
* loader/cache/CachedResource.cpp:
(WebCore::CachedResource::redirectReceived):
* loader/cache/CachedResourceLoader.cpp:
(WebCore::CachedResourceLoader::canRequestAfterRedirection const):

Source/WebKit:

* WebProcess/Network/WebResourceLoader.cpp:
(WebKit::WebResourceLoader::willSendRequest):
* WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp:
(WebKit::WebFrameLoaderClient::dispatchDecidePolicyForResponse):

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@257505 268f45cc-cd09-0410-ab3c-d52691b4dbfc

Source/WebCore/ChangeLog
Source/WebCore/loader/PolicyChecker.cpp
Source/WebCore/loader/ResourceLoader.cpp
Source/WebCore/loader/SubresourceLoader.cpp
Source/WebCore/loader/cache/CachedRawResource.cpp
Source/WebCore/loader/cache/CachedResource.cpp
Source/WebCore/loader/cache/CachedResourceLoader.cpp
Source/WebKit/ChangeLog
Source/WebKit/WebProcess/Network/WebResourceLoader.cpp
Source/WebKit/WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp

index 7a8381b..3dfc738 100644 (file)
@@ -1,3 +1,45 @@
+2020-02-26  Keith Rollin  <krollin@apple.com>
+
+        Add logging to help diagnose redirect issue
+        https://bugs.webkit.org/show_bug.cgi?id=207916
+        <rdar://problem/59567875>
+
+        Reviewed by Chris Dumez.
+
+        We're seeing an issue where communication between the WebContent
+        process and the Network process seems to come to a stop between
+        NetworkResourceLoader::continueWillSendRedirectedRequest and
+        NetworkResourceLoader::continueWillSendRequest. We do see a
+        WebResourceLoader::willSendRequest log line between those two
+        NetworkResourceLoader logging lines, but nothing else. Add a bunch of
+        logging in this area to help determine what's happening.
+
+        No new tests -- no new or changed functionality.
+
+        * loader/PolicyChecker.cpp:
+        (WebCore::PolicyChecker::checkNavigationPolicy):
+        * loader/ResourceLoader.cpp:
+        (WebCore::ResourceLoader::loadDataURL):
+        (WebCore::ResourceLoader::willSendRequestInternal):
+        (WebCore::ResourceLoader::didFinishLoading):
+        (WebCore::ResourceLoader::didFail):
+        (WebCore::ResourceLoader::willSendRequestAsync):
+        (WebCore::ResourceLoader::wasBlocked):
+        (WebCore::ResourceLoader::cannotShowURL):
+        * loader/SubresourceLoader.cpp:
+        (WebCore::SubresourceLoader::init):
+        (WebCore::SubresourceLoader::willSendRequestInternal):
+        (WebCore::SubresourceLoader::didReceiveResponse):
+        (WebCore::SubresourceLoader::didFinishLoading):
+        (WebCore::SubresourceLoader::didFail):
+        (WebCore::SubresourceLoader::willCancel):
+        * loader/cache/CachedRawResource.cpp:
+        (WebCore::CachedRawResource::redirectReceived):
+        * loader/cache/CachedResource.cpp:
+        (WebCore::CachedResource::redirectReceived):
+        * loader/cache/CachedResourceLoader.cpp:
+        (WebCore::CachedResourceLoader::canRequestAfterRedirection const):
+
 2020-02-26  Daniel Bates  <dabates@apple.com>
 
         Clean up HitTestLocation.h
index 7a6b573..bf08686 100644 (file)
 #include "QuickLook.h"
 #endif
 
+#define IS_ALLOWED (m_frame.page() ? m_frame.page()->sessionID().isAlwaysOnLoggingAllowed() : false)
+#define PAGE_ID (m_frame.loader().client().pageID().valueOr(PageIdentifier()).toUInt64())
+#define FRAME_ID (m_frame.loader().client().frameID().valueOr(FrameIdentifier()).toUInt64())
+#define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(IS_ALLOWED, Loading, "%p - [pageID=%" PRIu64 ", frameID=%" PRIu64 "] PolicyChecker::" fmt, this, PAGE_ID, FRAME_ID, ##__VA_ARGS__)
+
 namespace WebCore {
 
 static bool isAllowedByContentSecurityPolicy(const URL& url, const Element* ownerElement, bool didReceiveRedirectResponse)
@@ -128,6 +133,10 @@ void PolicyChecker::checkNavigationPolicy(ResourceRequest&& request, const Resou
     // Don't ask more than once for the same request or if we are loading an empty URL.
     // This avoids confusion on the part of the client.
     if (equalIgnoringHeaderFields(request, loader->lastCheckedRequest()) || (!request.isNull() && request.url().isEmpty())) {
+        if (!request.isNull() && request.url().isEmpty())
+            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because the URL is empty");
+        else
+            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because the URL is the same as the last request");
         function(ResourceRequest(request), { }, NavigationPolicyDecision::ContinueLoad);
         loader->setLastCheckedRequest(WTFMove(request));
         return;
@@ -143,6 +152,11 @@ void PolicyChecker::checkNavigationPolicy(ResourceRequest&& request, const Resou
 #endif
         if (isBackForwardLoadType(m_loadType))
             m_loadType = FrameLoadType::Reload;
+        if (shouldContinue)
+            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because we have valid substitute data");
+        else
+            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: not continuing with substitute data because the content filter told us not to");
+
         function(WTFMove(request), { }, shouldContinue ? NavigationPolicyDecision::ContinueLoad : NavigationPolicyDecision::IgnoreLoad);
         return;
     }
@@ -153,6 +167,7 @@ void PolicyChecker::checkNavigationPolicy(ResourceRequest&& request, const Resou
             // reveal that the frame was blocked. This way, it looks like any other cross-origin page load.
             m_frame.ownerElement()->dispatchEvent(Event::create(eventNames().loadEvent, Event::CanBubble::No, Event::IsCancelable::No));
         }
+        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because disallowed by content security policy");
         function(WTFMove(request), { }, NavigationPolicyDecision::IgnoreLoad);
         return;
     }
@@ -161,8 +176,10 @@ void PolicyChecker::checkNavigationPolicy(ResourceRequest&& request, const Resou
 
 #if USE(QUICK_LOOK)
     // Always allow QuickLook-generated URLs based on the protocol scheme.
-    if (!request.isNull() && isQuickLookPreviewURL(request.url()))
+    if (!request.isNull() && isQuickLookPreviewURL(request.url())) {
+        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because quicklook-generated URL");
         return function(WTFMove(request), makeWeakPtr(formState.get()), NavigationPolicyDecision::ContinueLoad);
+    }
 #endif
 
 #if ENABLE(CONTENT_FILTERING)
@@ -172,6 +189,7 @@ void PolicyChecker::checkNavigationPolicy(ResourceRequest&& request, const Resou
             if (unblocked)
                 frame->loader().reload();
         });
+        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because ContentFilterUnblockHandler can handle the request");
         return function({ }, nullptr, NavigationPolicyDecision::IgnoreLoad);
     }
     m_contentFilterUnblockHandler = { };
@@ -186,9 +204,11 @@ void PolicyChecker::checkNavigationPolicy(ResourceRequest&& request, const Resou
     m_delegateIsDecidingNavigationPolicy = true;
     String suggestedFilename = action.downloadAttribute().isEmpty() ? nullAtom() : action.downloadAttribute();
     FramePolicyFunction decisionHandler = [this, function = WTFMove(function), request = ResourceRequest(request), formState = WTFMove(formState), suggestedFilename = WTFMove(suggestedFilename),
-         blobURLLifetimeExtension = WTFMove(blobURLLifetimeExtension), requestIdentifier] (PolicyAction policyAction, PolicyCheckIdentifier responseIdentifier) mutable {
-        if (!responseIdentifier.isValidFor(requestIdentifier))
+         blobURLLifetimeExtension = WTFMove(blobURLLifetimeExtension), requestIdentifier, isInitialEmptyDocumentLoad] (PolicyAction policyAction, PolicyCheckIdentifier responseIdentifier) mutable {
+        if (!responseIdentifier.isValidFor(requestIdentifier)) {
+            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because response is not valid for request");
             return function({ }, nullptr, NavigationPolicyDecision::IgnoreLoad);
+        }
 
         m_delegateIsDecidingNavigationPolicy = false;
 
@@ -198,15 +218,22 @@ void PolicyChecker::checkNavigationPolicy(ResourceRequest&& request, const Resou
             m_frame.loader().client().startDownload(request, suggestedFilename);
             FALLTHROUGH;
         case PolicyAction::Ignore:
+            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because policyAction from dispatchDecidePolicyForNavigationAction is Ignore");
             return function({ }, nullptr, NavigationPolicyDecision::IgnoreLoad);
         case PolicyAction::StopAllLoads:
+            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: stopping because policyAction from dispatchDecidePolicyForNavigationAction is StopAllLoads");
             function({ }, nullptr, NavigationPolicyDecision::StopAllLoads);
             return;
         case PolicyAction::Use:
             if (!m_frame.loader().client().canHandleRequest(request)) {
                 handleUnimplementablePolicy(m_frame.loader().client().cannotShowURLError(request));
+                RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because frame loader client can't handle the request");
                 return function({ }, { }, NavigationPolicyDecision::IgnoreLoad);
             }
+            if (isInitialEmptyDocumentLoad)
+                RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because this is an initial empty document");
+            else
+                RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because this policyAction from dispatchDecidePolicyForNavigationAction is Use");
             return function(WTFMove(request), makeWeakPtr(formState.get()), NavigationPolicyDecision::ContinueLoad);
         }
         ASSERT_NOT_REACHED();
@@ -275,3 +302,8 @@ void PolicyChecker::handleUnimplementablePolicy(const ResourceError& error)
 }
 
 } // namespace WebCore
+
+#undef IS_ALLOWED
+#undef PAGE_ID
+#undef FRAME_ID
+#undef RELEASE_LOG_IF_ALLOWED
index 7321700..a357275 100644 (file)
@@ -64,7 +64,7 @@
 #endif
 
 #undef RELEASE_LOG_IF_ALLOWED
-#define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), Network, "%p - ResourceLoader::" fmt, this, ##__VA_ARGS__)
+#define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), Network, "%p - [frame=%p, frameLoader=%p, resourceID=%lu] ResourceLoader::" fmt, this, frame(), frameLoader(), identifier(), ##__VA_ARGS__)
 
 namespace WebCore {
 
@@ -272,7 +272,7 @@ void ResourceLoader::loadDataURL()
         if (this->reachedTerminalState())
             return;
         if (!decodeResult) {
-            RELEASE_LOG_IF_ALLOWED("loadDataURL: decoding of data failed (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_IF_ALLOWED("loadDataURL: decoding of data failed");
             protectedThis->didFail(ResourceError(errorDomainWebKitInternal, 0, url, "Data URL decoding failed"));
             return;
         }
@@ -371,7 +371,7 @@ void ResourceLoader::willSendRequestInternal(ResourceRequest&& request, const Re
             bool blockedLoad = results.summary.blockedLoad;
             ContentExtensions::applyResultsToRequest(WTFMove(results), page, request);
             if (blockedLoad) {
-                RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because of content blocker (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because of content blocker");
                 didFail(blockedByContentBlockerError());
                 completionHandler({ });
                 return;
@@ -381,7 +381,7 @@ void ResourceLoader::willSendRequestInternal(ResourceRequest&& request, const Re
 #endif
 
     if (request.isNull()) {
-        RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because of empty request (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+        RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because of empty request");
         didFail(cannotShowURLError());
         completionHandler({ });
         return;
@@ -394,6 +394,7 @@ void ResourceLoader::willSendRequestInternal(ResourceRequest&& request, const Re
 #if PLATFORM(IOS_FAMILY)
         // If this ResourceLoader was stopped as a result of assignIdentifierToInitialRequest, bail out
         if (m_reachedTerminalState) {
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load reached terminal state after calling assignIdentifierToInitialRequest()");
             completionHandler(WTFMove(request));
             return;
         }
@@ -429,6 +430,8 @@ void ResourceLoader::willSendRequestInternal(ResourceRequest&& request, const Re
             loadDataURL();
         }
     }
+
+    RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: calling completion handler");
     completionHandler(WTFMove(request));
 }
 
@@ -539,7 +542,7 @@ void ResourceLoader::didReceiveDataOrBuffer(const char* data, unsigned length, R
 
 void ResourceLoader::didFinishLoading(const NetworkLoadMetrics& networkLoadMetrics)
 {
-    RELEASE_LOG_IF_ALLOWED("didFinishLoading: (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+    RELEASE_LOG_IF_ALLOWED("didFinishLoading:");
 
     didFinishLoadingOnePart(networkLoadMetrics);
 
@@ -567,7 +570,7 @@ void ResourceLoader::didFinishLoadingOnePart(const NetworkLoadMetrics& networkLo
 
 void ResourceLoader::didFail(const ResourceError& error)
 {
-    RELEASE_LOG_IF_ALLOWED("didFail: (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+    RELEASE_LOG_IF_ALLOWED("didFail:");
 
     if (wasCancelled())
         return;
@@ -669,7 +672,7 @@ void ResourceLoader::willSendRequestAsync(ResourceHandle* handle, ResourceReques
 {
     RefPtr<ResourceHandle> protectedHandle(handle);
     if (documentLoader()->applicationCacheHost().maybeLoadFallbackForRedirect(this, request, redirectResponse)) {
-        RELEASE_LOG_IF_ALLOWED("willSendRequestAsync: exiting early because maybeLoadFallbackForRedirect returned false (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+        RELEASE_LOG_IF_ALLOWED("willSendRequestAsync: exiting early because maybeLoadFallbackForRedirect returned false");
         completionHandler(WTFMove(request));
         return;
     }
@@ -715,13 +718,13 @@ void ResourceLoader::didFail(ResourceHandle*, const ResourceError& error)
 
 void ResourceLoader::wasBlocked(ResourceHandle*)
 {
-    RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of content blocker (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+    RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of content blocker");
     didFail(blockedError());
 }
 
 void ResourceLoader::cannotShowURL(ResourceHandle*)
 {
-    RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of invalid URL (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+    RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of invalid URL");
     didFail(cannotShowURLError());
 }
 
index 4a0ca3e..0600ff3 100644 (file)
@@ -70,8 +70,8 @@
 
 #undef RELEASE_LOG_IF_ALLOWED
 #undef RELEASE_LOG_ERROR_IF_ALLOWED
-#define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), ResourceLoading, "%p - SubresourceLoader::" fmt, this, ##__VA_ARGS__)
-#define RELEASE_LOG_ERROR_IF_ALLOWED(fmt, ...) RELEASE_LOG_ERROR_IF(isAlwaysOnLoggingAllowed(), ResourceLoading, "%p - SubresourceLoader::" fmt, this, ##__VA_ARGS__)
+#define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), ResourceLoading, "%p - [frame=%p, frameLoader=%p, resourceID=%lu] SubresourceLoader::" fmt, this, frame(), frameLoader(), identifier(), ##__VA_ARGS__)
+#define RELEASE_LOG_ERROR_IF_ALLOWED(fmt, ...) RELEASE_LOG_ERROR_IF(isAlwaysOnLoggingAllowed(), ResourceLoading, "%p - [frame=%p, frameLoader=%p, resourceID=%lu] SubresourceLoader::" fmt, this, frame(), frameLoader(), identifier(), ##__VA_ARGS__)
 
 namespace WebCore {
 
@@ -166,7 +166,7 @@ void SubresourceLoader::init(ResourceRequest&& request, CompletionHandler<void(b
             return completionHandler(false);
         if (!m_documentLoader) {
             ASSERT_NOT_REACHED();
-            RELEASE_LOG_ERROR(ResourceLoading, "SubresourceLoader::init: resource load canceled because document loader is null (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_ERROR_IF_ALLOWED("init: resource load canceled because document loader is null");
             return completionHandler(false);
         }
         ASSERT(!reachedTerminalState());
@@ -189,6 +189,7 @@ void SubresourceLoader::willSendRequestInternal(ResourceRequest&& newRequest, co
     Ref<SubresourceLoader> protectedThis(*this);
 
     if (!newRequest.url().isValid()) {
+        RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because new request is invalid");
         cancel(cannotShowURLError());
         return completionHandler(WTFMove(newRequest));
     }
@@ -200,20 +201,28 @@ void SubresourceLoader::willSendRequestInternal(ResourceRequest&& newRequest, co
     }
 
     auto continueWillSendRequest = [this, protectedThis = makeRef(*this), redirectResponse] (CompletionHandler<void(ResourceRequest&&)>&& completionHandler, ResourceRequest&& newRequest) mutable {
-        if (newRequest.isNull() || reachedTerminalState())
+        if (newRequest.isNull() || reachedTerminalState()) {
+            if (newRequest.isNull())
+                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because new request is NULL (1)");
+            else
+                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because reached terminal state");
             return completionHandler(WTFMove(newRequest));
+        }
 
         ResourceLoader::willSendRequestInternal(WTFMove(newRequest), redirectResponse, [this, protectedThis = WTFMove(protectedThis), completionHandler = WTFMove(completionHandler), redirectResponse] (ResourceRequest&& request) mutable {
             if (reachedTerminalState())
                 return completionHandler(WTFMove(request));
 
             if (request.isNull()) {
+                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because request is NULL (2)");
                 cancel();
                 return completionHandler(WTFMove(request));
             }
 
             if (m_resource->type() == CachedResource::Type::MainResource && !redirectResponse.isNull())
                 m_documentLoader->willContinueMainResourceLoadAfterRedirect(request);
+
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load finished; calling completion handler");
             completionHandler(WTFMove(request));
         });
     };
@@ -227,7 +236,7 @@ void SubresourceLoader::willSendRequestInternal(ResourceRequest&& newRequest, co
                 if (m_frame && m_frame->document())
                     m_frame->document()->addConsoleMessage(MessageSource::Security, MessageLevel::Error, error.localizedDescription());
 
-                RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because not allowed to follow a redirect (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because not allowed to follow a redirect");
 
                 cancel(error);
                 return completionHandler(WTFMove(newRequest));
@@ -238,17 +247,17 @@ void SubresourceLoader::willSendRequestInternal(ResourceRequest&& newRequest, co
             opaqueRedirectedResponse.setTainting(ResourceResponse::Tainting::Opaqueredirect);
             m_resource->responseReceived(opaqueRedirectedResponse);
             if (reachedTerminalState()) {
-                RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: reached terminal state (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: reached terminal state");
                 return completionHandler(WTFMove(newRequest));
             }
 
-            RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load completed (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load completed");
 
             NetworkLoadMetrics emptyMetrics;
             didFinishLoading(emptyMetrics);
             return completionHandler(WTFMove(newRequest));
         } else if (m_redirectCount++ >= options().maxRedirectCount) {
-            RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because too many redirects (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because too many redirects");
             cancel(ResourceError(String(), 0, request().url(), "Too many redirections"_s, ResourceError::Type::General));
             return completionHandler(WTFMove(newRequest));
         }
@@ -265,7 +274,7 @@ void SubresourceLoader::willSendRequestInternal(ResourceRequest&& newRequest, co
         }
 
         if (!m_documentLoader->cachedResourceLoader().updateRequestAfterRedirection(m_resource->type(), newRequest, options())) {
-            RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because something about updateRequestAfterRedirection (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because CachedResourceLoader::updateRequestAfterRedirection (really CachedResourceLoader::canRequestAfterRedirection) said no");
             cancel();
             return completionHandler(WTFMove(newRequest));
         }
@@ -275,23 +284,25 @@ void SubresourceLoader::willSendRequestInternal(ResourceRequest&& newRequest, co
             String errorMessage = "Cross-origin redirection to " + newRequest.url().string() + " denied by Cross-Origin Resource Sharing policy: " + errorDescription;
             if (m_frame && m_frame->document())
                 m_frame->document()->addConsoleMessage(MessageSource::Security, MessageLevel::Error, errorMessage);
-            RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because crosss-origin redirection denied by CORS policy (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because crosss-origin redirection denied by CORS policy");
             cancel(ResourceError(String(), 0, request().url(), errorMessage, ResourceError::Type::AccessControl));
             return completionHandler(WTFMove(newRequest));
         }
 
         if (m_resource->isImage() && m_documentLoader->cachedResourceLoader().shouldDeferImageLoad(newRequest.url())) {
-            RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because it's an image that should be defered (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because it's an image that should be defered");
             cancel();
             return completionHandler(WTFMove(newRequest));
         }
         m_loadTiming.addRedirect(redirectResponse.url(), newRequest.url());
-        m_resource->redirectReceived(WTFMove(newRequest), redirectResponse, [completionHandler = WTFMove(completionHandler), continueWillSendRequest = WTFMove(continueWillSendRequest)] (ResourceRequest&& request) mutable {
+        m_resource->redirectReceived(WTFMove(newRequest), redirectResponse, [this, protectedThis = WTFMove(protectedThis), completionHandler = WTFMove(completionHandler), continueWillSendRequest = WTFMove(continueWillSendRequest)] (ResourceRequest&& request) mutable {
+            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource done notifying clients");
             continueWillSendRequest(WTFMove(completionHandler), WTFMove(request));
         });
         return;
     }
 
+    RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: redirect response is NULL");
     continueWillSendRequest(WTFMove(completionHandler), WTFMove(newRequest));
 }
 
@@ -351,7 +362,7 @@ void SubresourceLoader::didReceiveResponse(const ResourceResponse& response, Com
     if (response.source() == ResourceResponse::Source::ServiceWorker && response.url() != request().url()) {
         auto& loader = m_documentLoader->cachedResourceLoader();
         if (!loader.allowedByContentSecurityPolicy(m_resource->type(), response.url(), options(), ContentSecurityPolicy::RedirectResponseReceived::Yes)) {
-            RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because not allowed by content policy (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+            RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because not allowed by content policy");
             cancel(ResourceError({ }, 0, response.url(), { }, ResourceError::Type::General));
             return;
         }
@@ -359,7 +370,7 @@ void SubresourceLoader::didReceiveResponse(const ResourceResponse& response, Com
 #endif
 
     if (auto error = validateRangeRequestedFlag(request(), response)) {
-        RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because receiving a range requested response for a non-range request (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+        RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because receiving a range requested response for a non-range request");
         cancel(WTFMove(*error));
         return;
     }
@@ -402,7 +413,7 @@ void SubresourceLoader::didReceiveResponse(const ResourceResponse& response, Com
     if (!checkResponseCrossOriginAccessControl(response, errorDescription)) {
         if (m_frame && m_frame->document())
             m_frame->document()->addConsoleMessage(MessageSource::Security, MessageLevel::Error, errorDescription);
-        RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because of cross origin access control (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+        RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because of cross origin access control");
         cancel(ResourceError(String(), 0, request().url(), errorDescription, ResourceError::Type::AccessControl));
         return;
     }
@@ -442,7 +453,7 @@ void SubresourceLoader::didReceiveResponse(const ResourceResponse& response, Com
             // We don't count multiParts in a CachedResourceLoader's request count
             m_requestCountTracker = WTF::nullopt;
             if (!m_resource->isImage()) {
-                RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because something about a multi-part non-image (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+                RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because something about a multi-part non-image");
                 cancel();
                 return;
             }
@@ -661,7 +672,7 @@ void SubresourceLoader::updateReferrerPolicy(const String& referrerPolicyValue)
 
 void SubresourceLoader::didFinishLoading(const NetworkLoadMetrics& networkLoadMetrics)
 {
-    RELEASE_LOG_IF_ALLOWED("didFinishLoading: (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+    RELEASE_LOG_IF_ALLOWED("didFinishLoading:");
 
 #if USE(QUICK_LOOK)
     if (auto previewLoader = m_previewLoader.get()) {
@@ -707,7 +718,7 @@ void SubresourceLoader::didFinishLoading(const NetworkLoadMetrics& networkLoadMe
     m_resource->finishLoading(resourceData());
 
     if (wasCancelled()) {
-        RELEASE_LOG_IF_ALLOWED("didFinishLoading: was canceled (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+        RELEASE_LOG_IF_ALLOWED("didFinishLoading: was canceled");
         return;
     }
 
@@ -717,7 +728,7 @@ void SubresourceLoader::didFinishLoading(const NetworkLoadMetrics& networkLoadMe
     notifyDone(LoadCompletionType::Finish);
 
     if (reachedTerminalState()) {
-        RELEASE_LOG_IF_ALLOWED("didFinishLoading: reached terminal state (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
+        RELEASE_LOG_IF_ALLOWED("didFinishLoading: reached terminal state");
         return;
     }
     releaseResources();
@@ -725,7 +736,7 @@ void SubresourceLoader::didFinishLoading(const NetworkLoadMetrics& networkLoadMe
 
 void SubresourceLoader::didFail(const ResourceError& error)
 {
-    RELEASE_LOG_IF_ALLOWED("didFail: (frame = %p, frameLoader = %p, resourceID = %lu, type = %d, code = %d)", frame(), frameLoader(), identifier(), static_cast<int>(error.type()), error.errorCode());
+    RELEASE_LOG_IF_ALLOWED("didFail: (type = %d, code = %d)", static_cast<int>(error.type()), error.errorCode());
 
 #if USE(QUICK_LOOK)
     if (auto previewLoader = m_previewLoader.get())
@@ -763,7 +774,7 @@ void SubresourceLoader::didFail(const ResourceError& error)
 
 void SubresourceLoader::willCancel(const ResourceError& error)
 {
-    RELEASE_LOG_IF_ALLOWED("willCancel: (frame = %p, frameLoader = %p, resourceID = %lu, type = %d, code = %d)", frame(), frameLoader(), identifier(), static_cast<int>(error.type()), error.errorCode());
+    RELEASE_LOG_IF_ALLOWED("willCancel: (type = %d, code = %d)", static_cast<int>(error.type()), error.errorCode());
 
 #if PLATFORM(IOS_FAMILY)
     // Since we defer initialization to scheduling time on iOS but
index e7dc633..00a7f23 100644 (file)
 #include "CachedResourceClientWalker.h"
 #include "CachedResourceLoader.h"
 #include "HTTPHeaderNames.h"
+#include "Logging.h"
 #include "SharedBuffer.h"
 #include "SubresourceLoader.h"
 #include <wtf/CompletionHandler.h>
 #include <wtf/SetForScope.h>
 #include <wtf/text/StringView.h>
 
+#define RELEASE_LOG_ALWAYS(fmt, ...) RELEASE_LOG(Network, "%p - CachedRawResource::" fmt, this, ##__VA_ARGS__)
+
 namespace WebCore {
 
 CachedRawResource::CachedRawResource(CachedResourceRequest&& request, Type type, const PAL::SessionID& sessionID, const CookieJar* cookieJar)
@@ -204,6 +207,7 @@ static void iterateClients(CachedResourceClientWalker<CachedRawResourceClient>&&
 
 void CachedRawResource::redirectReceived(ResourceRequest&& request, const ResourceResponse& response, CompletionHandler<void(ResourceRequest&&)>&& completionHandler)
 {
+    RELEASE_LOG_ALWAYS("redirectReceived:");
     if (response.isNull())
         CachedResource::redirectReceived(WTFMove(request), response, WTFMove(completionHandler));
     else {
index 5de7083..6f157a0 100644 (file)
 #include "QuickLook.h"
 #endif
 
+#undef RELEASE_LOG_IF_ALLOWED
+#undef RELEASE_LOG_ALWAYS
 #define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(cachedResourceLoader.isAlwaysOnLoggingAllowed(), Network, "%p - CachedResource::" fmt, this, ##__VA_ARGS__)
+#define RELEASE_LOG_ALWAYS(fmt, ...) RELEASE_LOG(Network, "%p - CachedResource::" fmt, this, ##__VA_ARGS__)
 
 namespace WebCore {
 
@@ -485,11 +488,12 @@ Seconds CachedResource::freshnessLifetime(const ResourceResponse& response) cons
 
 void CachedResource::redirectReceived(ResourceRequest&& request, const ResourceResponse& response, CompletionHandler<void(ResourceRequest&&)>&& completionHandler)
 {
+    RELEASE_LOG_ALWAYS("redirectReceived:");
+
     m_requestedFromNetworkingLayer = true;
-    if (response.isNull())
-        return completionHandler(WTFMove(request));
+    if (!response.isNull())
+        updateRedirectChainStatus(m_redirectChainCacheStatus, response);
 
-    updateRedirectChainStatus(m_redirectChainCacheStatus, response);
     completionHandler(WTFMove(request));
 }
 
index 3f2f727..f162c85 100644 (file)
@@ -540,7 +540,8 @@ bool CachedResourceLoader::canRequestAfterRedirection(CachedResource::Type type,
 {
     if (document() && !document()->securityOrigin().canDisplay(url)) {
         FrameLoader::reportLocalLoadFailed(frame(), url.stringCenterEllipsizedToLength());
-        LOG(ResourceLoading, "CachedResourceLoader::requestResource URL was not allowed by SecurityOrigin::canDisplay");
+        LOG(ResourceLoading, "CachedResourceLoader::canRequestAfterRedirection URL was not allowed by SecurityOrigin::canDisplay");
+        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed by SecurityOrigin::canDisplay");
         return false;
     }
 
@@ -548,17 +549,22 @@ bool CachedResourceLoader::canRequestAfterRedirection(CachedResource::Type type,
     // But we currently allow at least data URLs to be loaded.
 
     if (options.mode == FetchOptions::Mode::SameOrigin && !m_document->securityOrigin().canRequest(url)) {
+        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed by SecurityOrigin::canRequest");
         printAccessDeniedMessage(url);
         return false;
     }
 
-    if (!allowedByContentSecurityPolicy(type, url, options, ContentSecurityPolicy::RedirectResponseReceived::Yes))
+    if (!allowedByContentSecurityPolicy(type, url, options, ContentSecurityPolicy::RedirectResponseReceived::Yes)) {
+        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed by content policy");
         return false;
+    }
 
     // Last of all, check for insecure content. We do this last so that when folks block insecure content with a CSP policy, they don't get a warning.
     // They'll still get a warning in the console about CSP blocking the load.
-    if (!checkInsecureContent(type, url))
+    if (!checkInsecureContent(type, url)) {
+        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed because content is insecure");
         return false;
+    }
 
     return true;
 }
index d136868..7ec70d6 100644 (file)
@@ -1,3 +1,24 @@
+2020-02-26  Keith Rollin  <krollin@apple.com>
+
+        Add logging to help diagnose redirect issue
+        https://bugs.webkit.org/show_bug.cgi?id=207916
+        <rdar://problem/59567875>
+
+        Reviewed by Chris Dumez.
+
+        We're seeing an issue where communication between the WebContent
+        process and the Network process seems to come to a stop between
+        NetworkResourceLoader::continueWillSendRedirectedRequest and
+        NetworkResourceLoader::continueWillSendRequest. We do see a
+        WebResourceLoader::willSendRequest log line between those two
+        NetworkResourceLoader logging lines, but nothing else. Add a bunch of
+        logging in this area to help determine what's happening.
+
+        * WebProcess/Network/WebResourceLoader.cpp:
+        (WebKit::WebResourceLoader::willSendRequest):
+        * WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp:
+        (WebKit::WebFrameLoaderClient::dispatchDecidePolicyForResponse):
+
 2020-02-26  Chris Dumez  <cdumez@apple.com>
 
         Make sure a client cannot cause a whole DOM tree to get leaked by simply holding on to a WKBundleNodeHandle
index 09d7987..ebd856f 100644 (file)
@@ -114,6 +114,7 @@ void WebResourceLoader::willSendRequest(ResourceRequest&& proposedRequest, IPC::
             return;
         }
 
+        RELEASE_LOG_IF_ALLOWED("willSendRequest: returning ContinueWillSendRequest");
         send(Messages::NetworkResourceLoader::ContinueWillSendRequest(request, m_coreLoader->isAllowedToAskUserForCredentials()));
     });
 }
index 98b15b8..7aa28ec 100644 (file)
@@ -808,11 +808,13 @@ void WebFrameLoaderClient::dispatchDecidePolicyForResponse(const ResourceRespons
 {
     WebPage* webPage = m_frame ? m_frame->page() : nullptr;
     if (!webPage) {
+        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: ignoring because there's no web page");
         function(PolicyAction::Ignore, identifier);
         return;
     }
 
     if (!request.url().string()) {
+        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: continuing because the url string is null");
         function(PolicyAction::Use, identifier);
         return;
     }
@@ -822,6 +824,7 @@ void WebFrameLoaderClient::dispatchDecidePolicyForResponse(const ResourceRespons
     // Notify the bundle client.
     WKBundlePagePolicyAction policy = webPage->injectedBundlePolicyClient().decidePolicyForResponse(webPage, m_frame, response, request, userData);
     if (policy == WKBundlePagePolicyActionUse) {
+        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: continuing because injected bundle says so");
         function(PolicyAction::Use, identifier);
         return;
     }
@@ -835,8 +838,10 @@ void WebFrameLoaderClient::dispatchDecidePolicyForResponse(const ResourceRespons
     Ref<WebFrame> protector(*m_frame);
     uint64_t listenerID = m_frame->setUpPolicyListener(identifier, WTFMove(function), WebFrame::ForNavigationAction::No);
     if (!webPage->send(Messages::WebPageProxy::DecidePolicyForResponse(m_frame->frameID(), SecurityOriginData::fromFrame(coreFrame), identifier, navigationID, response, request,
-        canShowResponse, downloadAttribute, listenerID, UserData(WebProcess::singleton().transformObjectsToHandles(userData.get()).get()))))
+        canShowResponse, downloadAttribute, listenerID, UserData(WebProcess::singleton().transformObjectsToHandles(userData.get()).get())))) {
+        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: ignoring because WebPageProxy::DecidePolicyForResponse failed");
         m_frame->didReceivePolicyDecision(listenerID, PolicyDecision { identifier, NavigatingToAppBoundDomain::No, PolicyAction::Ignore, 0, { }, { } });
+    }
 }
 
 void WebFrameLoaderClient::dispatchDecidePolicyForNewWindowAction(const NavigationAction& navigationAction, const ResourceRequest& request,