Changeset 257505 in webkit


Ignore:
Timestamp:
Feb 26, 2020 1:12:54 PM (4 years ago)
Author:
Keith Rollin
Message:

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.

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):

Location:
trunk/Source
Files:
10 edited

Legend:

Unmodified
Added
Removed

  • trunk/Source/WebCore/ChangeLog

    r257502 r257505  
     12020-02-26  Keith Rollin  <krollin@apple.com>
     2
     3        Add logging to help diagnose redirect issue
     4        https://bugs.webkit.org/show_bug.cgi?id=207916
     5        <rdar://problem/59567875>
     6
     7        Reviewed by Chris Dumez.
     8
     9        We're seeing an issue where communication between the WebContent
     10        process and the Network process seems to come to a stop between
     11        NetworkResourceLoader::continueWillSendRedirectedRequest and
     12        NetworkResourceLoader::continueWillSendRequest. We do see a
     13        WebResourceLoader::willSendRequest log line between those two
     14        NetworkResourceLoader logging lines, but nothing else. Add a bunch of
     15        logging in this area to help determine what's happening.
     16
     17        No new tests -- no new or changed functionality.
     18
     19        * loader/PolicyChecker.cpp:
     20        (WebCore::PolicyChecker::checkNavigationPolicy):
     21        * loader/ResourceLoader.cpp:
     22        (WebCore::ResourceLoader::loadDataURL):
     23        (WebCore::ResourceLoader::willSendRequestInternal):
     24        (WebCore::ResourceLoader::didFinishLoading):
     25        (WebCore::ResourceLoader::didFail):
     26        (WebCore::ResourceLoader::willSendRequestAsync):
     27        (WebCore::ResourceLoader::wasBlocked):
     28        (WebCore::ResourceLoader::cannotShowURL):
     29        * loader/SubresourceLoader.cpp:
     30        (WebCore::SubresourceLoader::init):
     31        (WebCore::SubresourceLoader::willSendRequestInternal):
     32        (WebCore::SubresourceLoader::didReceiveResponse):
     33        (WebCore::SubresourceLoader::didFinishLoading):
     34        (WebCore::SubresourceLoader::didFail):
     35        (WebCore::SubresourceLoader::willCancel):
     36        * loader/cache/CachedRawResource.cpp:
     37        (WebCore::CachedRawResource::redirectReceived):
     38        * loader/cache/CachedResource.cpp:
     39        (WebCore::CachedResource::redirectReceived):
     40        * loader/cache/CachedResourceLoader.cpp:
     41        (WebCore::CachedResourceLoader::canRequestAfterRedirection const):
     42
    1432020-02-26  Daniel Bates  <dabates@apple.com>
    244

  • trunk/Source/WebCore/loader/PolicyChecker.cpp

    r254930 r257505  
    5454#endif
    5555
     56#define IS_ALLOWED (m_frame.page() ? m_frame.page()->sessionID().isAlwaysOnLoggingAllowed() : false)
     57#define PAGE_ID (m_frame.loader().client().pageID().valueOr(PageIdentifier()).toUInt64())
     58#define FRAME_ID (m_frame.loader().client().frameID().valueOr(FrameIdentifier()).toUInt64())
     59#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__)
     60
    5661namespace WebCore {
    5762
    … …  
    129134    // This avoids confusion on the part of the client.
    130135    if (equalIgnoringHeaderFields(request, loader->lastCheckedRequest()) || (!request.isNull() && request.url().isEmpty())) {
     136        if (!request.isNull() && request.url().isEmpty())
     137            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because the URL is empty");
     138        else
     139            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because the URL is the same as the last request");
    131140        function(ResourceRequest(request), { }, NavigationPolicyDecision::ContinueLoad);
    132141        loader->setLastCheckedRequest(WTFMove(request));
    … …  
    144153        if (isBackForwardLoadType(m_loadType))
    145154            m_loadType = FrameLoadType::Reload;
     155        if (shouldContinue)
     156            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because we have valid substitute data");
     157        else
     158            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: not continuing with substitute data because the content filter told us not to");
     159
    146160        function(WTFMove(request), { }, shouldContinue ? NavigationPolicyDecision::ContinueLoad : NavigationPolicyDecision::IgnoreLoad);
    147161        return;
    … …  
    154168            m_frame.ownerElement()->dispatchEvent(Event::create(eventNames().loadEvent, Event::CanBubble::No, Event::IsCancelable::No));
    155169        }
     170        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because disallowed by content security policy");
    156171        function(WTFMove(request), { }, NavigationPolicyDecision::IgnoreLoad);
    157172        return;
    … …  
    162177#if USE(QUICK_LOOK)
    163178    // Always allow QuickLook-generated URLs based on the protocol scheme.
    164     if (!request.isNull() && isQuickLookPreviewURL(request.url()))
     179    if (!request.isNull() && isQuickLookPreviewURL(request.url())) {
     180        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because quicklook-generated URL");
    165181        return function(WTFMove(request), makeWeakPtr(formState.get()), NavigationPolicyDecision::ContinueLoad);
     182    }
    166183#endif
    167184
    … …  
    173190                frame->loader().reload();
    174191        });
     192        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because ContentFilterUnblockHandler can handle the request");
    175193        return function({ }, nullptr, NavigationPolicyDecision::IgnoreLoad);
    176194    }
    … …  
    187205    String suggestedFilename = action.downloadAttribute().isEmpty() ? nullAtom() : action.downloadAttribute();
    188206    FramePolicyFunction decisionHandler = [this, function = WTFMove(function), request = ResourceRequest(request), formState = WTFMove(formState), suggestedFilename = WTFMove(suggestedFilename),
    189          blobURLLifetimeExtension = WTFMove(blobURLLifetimeExtension), requestIdentifier] (PolicyAction policyAction, PolicyCheckIdentifier responseIdentifier) mutable {
    190         if (!responseIdentifier.isValidFor(requestIdentifier))
     207         blobURLLifetimeExtension = WTFMove(blobURLLifetimeExtension), requestIdentifier, isInitialEmptyDocumentLoad] (PolicyAction policyAction, PolicyCheckIdentifier responseIdentifier) mutable {
     208        if (!responseIdentifier.isValidFor(requestIdentifier)) {
     209            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because response is not valid for request");
    191210            return function({ }, nullptr, NavigationPolicyDecision::IgnoreLoad);
     211        }
    192212
    193213        m_delegateIsDecidingNavigationPolicy = false;
    … …  
    199219            FALLTHROUGH;
    200220        case PolicyAction::Ignore:
     221            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because policyAction from dispatchDecidePolicyForNavigationAction is Ignore");
    201222            return function({ }, nullptr, NavigationPolicyDecision::IgnoreLoad);
    202223        case PolicyAction::StopAllLoads:
     224            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: stopping because policyAction from dispatchDecidePolicyForNavigationAction is StopAllLoads");
    203225            function({ }, nullptr, NavigationPolicyDecision::StopAllLoads);
    204226            return;
    … …  
    206228            if (!m_frame.loader().client().canHandleRequest(request)) {
    207229                handleUnimplementablePolicy(m_frame.loader().client().cannotShowURLError(request));
     230                RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because frame loader client can't handle the request");
    208231                return function({ }, { }, NavigationPolicyDecision::IgnoreLoad);
    209232            }
     233            if (isInitialEmptyDocumentLoad)
     234                RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because this is an initial empty document");
     235            else
     236                RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because this policyAction from dispatchDecidePolicyForNavigationAction is Use");
    210237            return function(WTFMove(request), makeWeakPtr(formState.get()), NavigationPolicyDecision::ContinueLoad);
    211238        }
    … …  
    276303
    277304} // namespace WebCore
     305
     306#undef IS_ALLOWED
     307#undef PAGE_ID
     308#undef FRAME_ID
     309#undef RELEASE_LOG_IF_ALLOWED

  • trunk/Source/WebCore/loader/ResourceLoader.cpp

    r256583 r257505  
    6565
    6666#undef RELEASE_LOG_IF_ALLOWED
    67 #define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), Network, "%p - ResourceLoader::" fmt, this, ##__VA_ARGS__)
     67#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__)
    6868
    6969namespace WebCore {
    … …  
    273273            return;
    274274        if (!decodeResult) {
    275             RELEASE_LOG_IF_ALLOWED("loadDataURL: decoding of data failed (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     275            RELEASE_LOG_IF_ALLOWED("loadDataURL: decoding of data failed");
    276276            protectedThis->didFail(ResourceError(errorDomainWebKitInternal, 0, url, "Data URL decoding failed"));
    277277            return;
    … …  
    372372            ContentExtensions::applyResultsToRequest(WTFMove(results), page, request);
    373373            if (blockedLoad) {
    374                 RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because of content blocker (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     374                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because of content blocker");
    375375                didFail(blockedByContentBlockerError());
    376376                completionHandler({ });
    … …  
    382382
    383383    if (request.isNull()) {
    384         RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because of empty request (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     384        RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because of empty request");
    385385        didFail(cannotShowURLError());
    386386        completionHandler({ });
    … …  
    395395        // If this ResourceLoader was stopped as a result of assignIdentifierToInitialRequest, bail out
    396396        if (m_reachedTerminalState) {
     397            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load reached terminal state after calling assignIdentifierToInitialRequest()");
    397398            completionHandler(WTFMove(request));
    398399            return;
    … …  
    430431        }
    431432    }
     433
     434    RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: calling completion handler");
    432435    completionHandler(WTFMove(request));
    433436}
    … …  
    540543void ResourceLoader::didFinishLoading(const NetworkLoadMetrics& networkLoadMetrics)
    541544{
    542     RELEASE_LOG_IF_ALLOWED("didFinishLoading: (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     545    RELEASE_LOG_IF_ALLOWED("didFinishLoading:");
    543546
    544547    didFinishLoadingOnePart(networkLoadMetrics);
    … …  
    568571void ResourceLoader::didFail(const ResourceError& error)
    569572{
    570     RELEASE_LOG_IF_ALLOWED("didFail: (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     573    RELEASE_LOG_IF_ALLOWED("didFail:");
    571574
    572575    if (wasCancelled())
    … …  
    670673    RefPtr<ResourceHandle> protectedHandle(handle);
    671674    if (documentLoader()->applicationCacheHost().maybeLoadFallbackForRedirect(this, request, redirectResponse)) {
    672         RELEASE_LOG_IF_ALLOWED("willSendRequestAsync: exiting early because maybeLoadFallbackForRedirect returned false (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     675        RELEASE_LOG_IF_ALLOWED("willSendRequestAsync: exiting early because maybeLoadFallbackForRedirect returned false");
    673676        completionHandler(WTFMove(request));
    674677        return;
    … …  
    716719void ResourceLoader::wasBlocked(ResourceHandle*)
    717720{
    718     RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of content blocker (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     721    RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of content blocker");
    719722    didFail(blockedError());
    720723}
    … …  
    722725void ResourceLoader::cannotShowURL(ResourceHandle*)
    723726{
    724     RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of invalid URL (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     727    RELEASE_LOG_IF_ALLOWED("wasBlocked: resource load canceled because of invalid URL");
    725728    didFail(cannotShowURLError());
    726729}

  • trunk/Source/WebCore/loader/SubresourceLoader.cpp

    r256632 r257505  
    7171#undef RELEASE_LOG_IF_ALLOWED
    7272#undef RELEASE_LOG_ERROR_IF_ALLOWED
    73 #define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), ResourceLoading, "%p - SubresourceLoader::" fmt, this, ##__VA_ARGS__)
    74 #define RELEASE_LOG_ERROR_IF_ALLOWED(fmt, ...) RELEASE_LOG_ERROR_IF(isAlwaysOnLoggingAllowed(), ResourceLoading, "%p - SubresourceLoader::" fmt, this, ##__VA_ARGS__)
     73#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__)
     74#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__)
    7575
    7676namespace WebCore {
    … …  
    167167        if (!m_documentLoader) {
    168168            ASSERT_NOT_REACHED();
    169             RELEASE_LOG_ERROR(ResourceLoading, "SubresourceLoader::init: resource load canceled because document loader is null (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     169            RELEASE_LOG_ERROR_IF_ALLOWED("init: resource load canceled because document loader is null");
    170170            return completionHandler(false);
    171171        }
    … …  
    190190
    191191    if (!newRequest.url().isValid()) {
     192        RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because new request is invalid");
    192193        cancel(cannotShowURLError());
    193194        return completionHandler(WTFMove(newRequest));
    … …  
    201202
    202203    auto continueWillSendRequest = [this, protectedThis = makeRef(*this), redirectResponse] (CompletionHandler<void(ResourceRequest&&)>&& completionHandler, ResourceRequest&& newRequest) mutable {
    203         if (newRequest.isNull() || reachedTerminalState())
     204        if (newRequest.isNull() || reachedTerminalState()) {
     205            if (newRequest.isNull())
     206                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because new request is NULL (1)");
     207            else
     208                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because reached terminal state");
    204209            return completionHandler(WTFMove(newRequest));
     210        }
    205211
    206212        ResourceLoader::willSendRequestInternal(WTFMove(newRequest), redirectResponse, [this, protectedThis = WTFMove(protectedThis), completionHandler = WTFMove(completionHandler), redirectResponse] (ResourceRequest&& request) mutable {
    … …  
    209215
    210216            if (request.isNull()) {
     217                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because request is NULL (2)");
    211218                cancel();
    212219                return completionHandler(WTFMove(request));
    … …  
    215222            if (m_resource->type() == CachedResource::Type::MainResource && !redirectResponse.isNull())
    216223                m_documentLoader->willContinueMainResourceLoadAfterRedirect(request);
     224
     225            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load finished; calling completion handler");
    217226            completionHandler(WTFMove(request));
    218227        });
    … …  
    228237                    m_frame->document()->addConsoleMessage(MessageSource::Security, MessageLevel::Error, error.localizedDescription());
    229238
    230                 RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because not allowed to follow a redirect (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     239                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because not allowed to follow a redirect");
    231240
    232241                cancel(error);
    … …  
    239248            m_resource->responseReceived(opaqueRedirectedResponse);
    240249            if (reachedTerminalState()) {
    241                 RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: reached terminal state (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     250                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: reached terminal state");
    242251                return completionHandler(WTFMove(newRequest));
    243252            }
    244253
    245             RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load completed (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     254            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load completed");
    246255
    247256            NetworkLoadMetrics emptyMetrics;
    … …  
    249258            return completionHandler(WTFMove(newRequest));
    250259        } else if (m_redirectCount++ >= options().maxRedirectCount) {
    251             RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because too many redirects (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     260            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because too many redirects");
    252261            cancel(ResourceError(String(), 0, request().url(), "Too many redirections"_s, ResourceError::Type::General));
    253262            return completionHandler(WTFMove(newRequest));
    … …  
    266275
    267276        if (!m_documentLoader->cachedResourceLoader().updateRequestAfterRedirection(m_resource->type(), newRequest, options())) {
    268             RELEASE_LOG_IF_ALLOWED("willSendRequestinternal: resource load canceled because something about updateRequestAfterRedirection (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     277            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because CachedResourceLoader::updateRequestAfterRedirection (really CachedResourceLoader::canRequestAfterRedirection) said no");
    269278            cancel();
    270279            return completionHandler(WTFMove(newRequest));
    … …  
    276285            if (m_frame && m_frame->document())
    277286                m_frame->document()->addConsoleMessage(MessageSource::Security, MessageLevel::Error, errorMessage);
    278             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());
     287            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because crosss-origin redirection denied by CORS policy");
    279288            cancel(ResourceError(String(), 0, request().url(), errorMessage, ResourceError::Type::AccessControl));
    280289            return completionHandler(WTFMove(newRequest));
    … …  
    282291
    283292        if (m_resource->isImage() && m_documentLoader->cachedResourceLoader().shouldDeferImageLoad(newRequest.url())) {
    284             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());
     293            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because it's an image that should be defered");
    285294            cancel();
    286295            return completionHandler(WTFMove(newRequest));
    287296        }
    288297        m_loadTiming.addRedirect(redirectResponse.url(), newRequest.url());
    289         m_resource->redirectReceived(WTFMove(newRequest), redirectResponse, [completionHandler = WTFMove(completionHandler), continueWillSendRequest = WTFMove(continueWillSendRequest)] (ResourceRequest&& request) mutable {
     298        m_resource->redirectReceived(WTFMove(newRequest), redirectResponse, [this, protectedThis = WTFMove(protectedThis), completionHandler = WTFMove(completionHandler), continueWillSendRequest = WTFMove(continueWillSendRequest)] (ResourceRequest&& request) mutable {
     299            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource done notifying clients");
    290300            continueWillSendRequest(WTFMove(completionHandler), WTFMove(request));
    291301        });
    … …  
    293303    }
    294304
     305    RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: redirect response is NULL");
    295306    continueWillSendRequest(WTFMove(completionHandler), WTFMove(newRequest));
    296307}
    … …  
    352363        auto& loader = m_documentLoader->cachedResourceLoader();
    353364        if (!loader.allowedByContentSecurityPolicy(m_resource->type(), response.url(), options(), ContentSecurityPolicy::RedirectResponseReceived::Yes)) {
    354             RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because not allowed by content policy (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     365            RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because not allowed by content policy");
    355366            cancel(ResourceError({ }, 0, response.url(), { }, ResourceError::Type::General));
    356367            return;
    … …  
    360371
    361372    if (auto error = validateRangeRequestedFlag(request(), response)) {
    362         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());
     373        RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because receiving a range requested response for a non-range request");
    363374        cancel(WTFMove(*error));
    364375        return;
    … …  
    403414        if (m_frame && m_frame->document())
    404415            m_frame->document()->addConsoleMessage(MessageSource::Security, MessageLevel::Error, errorDescription);
    405         RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because of cross origin access control (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     416        RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because of cross origin access control");
    406417        cancel(ResourceError(String(), 0, request().url(), errorDescription, ResourceError::Type::AccessControl));
    407418        return;
    … …  
    443454            m_requestCountTracker = WTF::nullopt;
    444455            if (!m_resource->isImage()) {
    445                 RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because something about a multi-part non-image (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     456                RELEASE_LOG_IF_ALLOWED("didReceiveResponse: canceling load because something about a multi-part non-image");
    446457                cancel();
    447458                return;
    … …  
    662673void SubresourceLoader::didFinishLoading(const NetworkLoadMetrics& networkLoadMetrics)
    663674{
    664     RELEASE_LOG_IF_ALLOWED("didFinishLoading: (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     675    RELEASE_LOG_IF_ALLOWED("didFinishLoading:");
    665676
    666677#if USE(QUICK_LOOK)
    … …  
    708719
    709720    if (wasCancelled()) {
    710         RELEASE_LOG_IF_ALLOWED("didFinishLoading: was canceled (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     721        RELEASE_LOG_IF_ALLOWED("didFinishLoading: was canceled");
    711722        return;
    712723    }
    … …  
    718729
    719730    if (reachedTerminalState()) {
    720         RELEASE_LOG_IF_ALLOWED("didFinishLoading: reached terminal state (frame = %p, frameLoader = %p, resourceID = %lu)", frame(), frameLoader(), identifier());
     731        RELEASE_LOG_IF_ALLOWED("didFinishLoading: reached terminal state");
    721732        return;
    722733    }
    … …  
    726737void SubresourceLoader::didFail(const ResourceError& error)
    727738{
    728     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());
     739    RELEASE_LOG_IF_ALLOWED("didFail: (type = %d, code = %d)", static_cast<int>(error.type()), error.errorCode());
    729740
    730741#if USE(QUICK_LOOK)
    … …  
    764775void SubresourceLoader::willCancel(const ResourceError& error)
    765776{
    766     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());
     777    RELEASE_LOG_IF_ALLOWED("willCancel: (type = %d, code = %d)", static_cast<int>(error.type()), error.errorCode());
    767778
    768779#if PLATFORM(IOS_FAMILY)

  • trunk/Source/WebCore/loader/cache/CachedRawResource.cpp

    r251105 r257505  
    3131#include "CachedResourceLoader.h"
    3232#include "HTTPHeaderNames.h"
     33#include "Logging.h"
    3334#include "SharedBuffer.h"
    3435#include "SubresourceLoader.h"
    … …  
    3637#include <wtf/SetForScope.h>
    3738#include <wtf/text/StringView.h>
     39
     40#define RELEASE_LOG_ALWAYS(fmt, ...) RELEASE_LOG(Network, "%p - CachedRawResource::" fmt, this, ##__VA_ARGS__)
    3841
    3942namespace WebCore {
    … …  
    205208void CachedRawResource::redirectReceived(ResourceRequest&& request, const ResourceResponse& response, CompletionHandler<void(ResourceRequest&&)>&& completionHandler)
    206209{
     210    RELEASE_LOG_ALWAYS("redirectReceived:");
    207211    if (response.isNull())
    208212        CachedResource::redirectReceived(WTFMove(request), response, WTFMove(completionHandler));

  • trunk/Source/WebCore/loader/cache/CachedResource.cpp

    r257206 r257505  
    6262#endif
    6363
     64#undef RELEASE_LOG_IF_ALLOWED
     65#undef RELEASE_LOG_ALWAYS
    6466#define RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(cachedResourceLoader.isAlwaysOnLoggingAllowed(), Network, "%p - CachedResource::" fmt, this, ##__VA_ARGS__)
     67#define RELEASE_LOG_ALWAYS(fmt, ...) RELEASE_LOG(Network, "%p - CachedResource::" fmt, this, ##__VA_ARGS__)
    6568
    6669namespace WebCore {
    … …  
    486489void CachedResource::redirectReceived(ResourceRequest&& request, const ResourceResponse& response, CompletionHandler<void(ResourceRequest&&)>&& completionHandler)
    487490{
     491    RELEASE_LOG_ALWAYS("redirectReceived:");
     492
    488493    m_requestedFromNetworkingLayer = true;
    489     if (response.isNull())
    490         return completionHandler(WTFMove(request));
    491 
    492     updateRedirectChainStatus(m_redirectChainCacheStatus, response);
     494    if (!response.isNull())
     495        updateRedirectChainStatus(m_redirectChainCacheStatus, response);
     496
    493497    completionHandler(WTFMove(request));
    494498}

  • trunk/Source/WebCore/loader/cache/CachedResourceLoader.cpp

    r256786 r257505  
    541541    if (document() && !document()->securityOrigin().canDisplay(url)) {
    542542        FrameLoader::reportLocalLoadFailed(frame(), url.stringCenterEllipsizedToLength());
    543         LOG(ResourceLoading, "CachedResourceLoader::requestResource URL was not allowed by SecurityOrigin::canDisplay");
     543        LOG(ResourceLoading, "CachedResourceLoader::canRequestAfterRedirection URL was not allowed by SecurityOrigin::canDisplay");
     544        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed by SecurityOrigin::canDisplay");
    544545        return false;
    545546    }
    … …  
    549550
    550551    if (options.mode == FetchOptions::Mode::SameOrigin && !m_document->securityOrigin().canRequest(url)) {
     552        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed by SecurityOrigin::canRequest");
    551553        printAccessDeniedMessage(url);
    552554        return false;
    553555    }
    554556
    555     if (!allowedByContentSecurityPolicy(type, url, options, ContentSecurityPolicy::RedirectResponseReceived::Yes))
    556         return false;
     557    if (!allowedByContentSecurityPolicy(type, url, options, ContentSecurityPolicy::RedirectResponseReceived::Yes)) {
     558        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed by content policy");
     559        return false;
     560    }
    557561
    558562    // 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.
    559563    // They'll still get a warning in the console about CSP blocking the load.
    560     if (!checkInsecureContent(type, url))
    561         return false;
     564    if (!checkInsecureContent(type, url)) {
     565        RELEASE_LOG_IF_ALLOWED("canRequestAfterRedirection: URL was not allowed because content is insecure");
     566        return false;
     567    }
    562568
    563569    return true;

  • trunk/Source/WebKit/ChangeLog

    r257503 r257505  
     12020-02-26  Keith Rollin  <krollin@apple.com>
     2
     3        Add logging to help diagnose redirect issue
     4        https://bugs.webkit.org/show_bug.cgi?id=207916
     5        <rdar://problem/59567875>
     6
     7        Reviewed by Chris Dumez.
     8
     9        We're seeing an issue where communication between the WebContent
     10        process and the Network process seems to come to a stop between
     11        NetworkResourceLoader::continueWillSendRedirectedRequest and
     12        NetworkResourceLoader::continueWillSendRequest. We do see a
     13        WebResourceLoader::willSendRequest log line between those two
     14        NetworkResourceLoader logging lines, but nothing else. Add a bunch of
     15        logging in this area to help determine what's happening.
     16
     17        * WebProcess/Network/WebResourceLoader.cpp:
     18        (WebKit::WebResourceLoader::willSendRequest):
     19        * WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp:
     20        (WebKit::WebFrameLoaderClient::dispatchDecidePolicyForResponse):
     21
    1222020-02-26  Chris Dumez  <cdumez@apple.com>
    223

  • trunk/Source/WebKit/WebProcess/Network/WebResourceLoader.cpp

    r254087 r257505  
    115115        }
    116116
     117        RELEASE_LOG_IF_ALLOWED("willSendRequest: returning ContinueWillSendRequest");
    117118        send(Messages::NetworkResourceLoader::ContinueWillSendRequest(request, m_coreLoader->isAllowedToAskUserForCredentials()));
    118119    });

  • trunk/Source/WebKit/WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp

    r257185 r257505  
    809809    WebPage* webPage = m_frame ? m_frame->page() : nullptr;
    810810    if (!webPage) {
     811        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: ignoring because there's no web page");
    811812        function(PolicyAction::Ignore, identifier);
    812813        return;
    … …  
    814815
    815816    if (!request.url().string()) {
     817        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: continuing because the url string is null");
    816818        function(PolicyAction::Use, identifier);
    817819        return;
    … …  
    823825    WKBundlePagePolicyAction policy = webPage->injectedBundlePolicyClient().decidePolicyForResponse(webPage, m_frame, response, request, userData);
    824826    if (policy == WKBundlePagePolicyActionUse) {
     827        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: continuing because injected bundle says so");
    825828        function(PolicyAction::Use, identifier);
    826829        return;
    … …  
    836839    uint64_t listenerID = m_frame->setUpPolicyListener(identifier, WTFMove(function), WebFrame::ForNavigationAction::No);
    837840    if (!webPage->send(Messages::WebPageProxy::DecidePolicyForResponse(m_frame->frameID(), SecurityOriginData::fromFrame(coreFrame), identifier, navigationID, response, request,
    838         canShowResponse, downloadAttribute, listenerID, UserData(WebProcess::singleton().transformObjectsToHandles(userData.get()).get()))))
     841        canShowResponse, downloadAttribute, listenerID, UserData(WebProcess::singleton().transformObjectsToHandles(userData.get()).get())))) {
     842        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: ignoring because WebPageProxy::DecidePolicyForResponse failed");
    839843        m_frame->didReceivePolicyDecision(listenerID, PolicyDecision { identifier, NavigatingToAppBoundDomain::No, PolicyAction::Ignore, 0, { }, { } });
     844    }
    840845}
    841846
Note: See TracChangeset for help on using the changeset viewer.