Diff
Modified: trunk/Source/WebCore/ChangeLog (257504 => 257505)
--- trunk/Source/WebCore/ChangeLog 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebCore/ChangeLog 2020-02-26 21:12:54 UTC (rev 257505)
@@ -1,3 +1,45 @@
+2020-02-26 Keith Rollin <[email protected]>
+
+ 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 <[email protected]>
Clean up HitTestLocation.h
Modified: trunk/Source/WebCore/loader/PolicyChecker.cpp (257504 => 257505)
--- trunk/Source/WebCore/loader/PolicyChecker.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebCore/loader/PolicyChecker.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -53,6 +53,11 @@
#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 @@
// 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 @@
#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 @@
// 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 @@
#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 @@
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 @@
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 @@
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 @@
}
} // namespace WebCore
+
+#undef IS_ALLOWED
+#undef PAGE_ID
+#undef FRAME_ID
+#undef RELEASE_LOG_IF_ALLOWED
Modified: trunk/Source/WebCore/loader/ResourceLoader.cpp (257504 => 257505)
--- trunk/Source/WebCore/loader/ResourceLoader.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebCore/loader/ResourceLoader.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -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 @@
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 @@
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 @@
#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 @@
#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 @@
loadDataURL();
}
}
+
+ RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: calling completion handler");
completionHandler(WTFMove(request));
}
@@ -539,7 +542,7 @@
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::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 @@
{
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::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());
}
Modified: trunk/Source/WebCore/loader/SubresourceLoader.cpp (257504 => 257505)
--- trunk/Source/WebCore/loader/SubresourceLoader.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebCore/loader/SubresourceLoader.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -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 @@
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 @@
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,8 +201,13 @@
}
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())
@@ -208,6 +214,7 @@
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));
}
@@ -214,6 +221,8 @@
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 @@
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 @@
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 @@
}
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 @@
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 @@
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 @@
#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 @@
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 @@
// 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::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 @@
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 @@
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::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::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
Modified: trunk/Source/WebCore/loader/cache/CachedRawResource.cpp (257504 => 257505)
--- trunk/Source/WebCore/loader/cache/CachedRawResource.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebCore/loader/cache/CachedRawResource.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -30,6 +30,7 @@
#include "CachedResourceClientWalker.h"
#include "CachedResourceLoader.h"
#include "HTTPHeaderNames.h"
+#include "Logging.h"
#include "SharedBuffer.h"
#include "SubresourceLoader.h"
#include <wtf/CompletionHandler.h>
@@ -36,6 +37,8 @@
#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 @@
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 {
Modified: trunk/Source/WebCore/loader/cache/CachedResource.cpp (257504 => 257505)
--- trunk/Source/WebCore/loader/cache/CachedResource.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebCore/loader/cache/CachedResource.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -61,7 +61,10 @@
#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 @@
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));
}
Modified: trunk/Source/WebCore/loader/cache/CachedResourceLoader.cpp (257504 => 257505)
--- trunk/Source/WebCore/loader/cache/CachedResourceLoader.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebCore/loader/cache/CachedResourceLoader.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -540,7 +540,8 @@
{
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 @@
// 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;
}
Modified: trunk/Source/WebKit/ChangeLog (257504 => 257505)
--- trunk/Source/WebKit/ChangeLog 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebKit/ChangeLog 2020-02-26 21:12:54 UTC (rev 257505)
@@ -1,3 +1,24 @@
+2020-02-26 Keith Rollin <[email protected]>
+
+ 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 <[email protected]>
Make sure a client cannot cause a whole DOM tree to get leaked by simply holding on to a WKBundleNodeHandle
Modified: trunk/Source/WebKit/WebProcess/Network/WebResourceLoader.cpp (257504 => 257505)
--- trunk/Source/WebKit/WebProcess/Network/WebResourceLoader.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebKit/WebProcess/Network/WebResourceLoader.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -114,6 +114,7 @@
return;
}
+ RELEASE_LOG_IF_ALLOWED("willSendRequest: returning ContinueWillSendRequest");
send(Messages::NetworkResourceLoader::ContinueWillSendRequest(request, m_coreLoader->isAllowedToAskUserForCredentials()));
});
}
Modified: trunk/Source/WebKit/WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp (257504 => 257505)
--- trunk/Source/WebKit/WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp 2020-02-26 21:10:53 UTC (rev 257504)
+++ trunk/Source/WebKit/WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp 2020-02-26 21:12:54 UTC (rev 257505)
@@ -808,11 +808,13 @@
{
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 @@
// 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 @@
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,
