Bug 207916 – Add logging to help diagnose redirect issue

• Component: WebCore Misc.
• Status: RESOLVED FIXED

[Keith Rollin]

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.

[Radar WebKit Bug Importer]

<rdar://problem/59567875>

[Keith Rollin]

Created attachment 391100 [details]
Patch

[Keith Rollin]

bump.

[Simon Fraser (smfr)]

Comment on attachment 391100 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=391100&action=review

> Source/WebCore/loader/PolicyChecker.cpp:56
> +#define RELEASE_LOG_ALWAYS(fmt, ...) RELEASE_LOG(Loading, "%p - PolicyChecker::" fmt, this, ##__VA_ARGS__)

Don't we normally use RELEASE_LOG_IF_ALLOWED?

> Source/WebCore/loader/PolicyChecker.cpp:133
> +        RELEASE_LOG_ALWAYS("checkNavigationPolicy: continuing because empty URL");

These all need to log some context (pageID, processIdentifier or something).

[Keith Rollin]

(In reply to Simon Fraser (smfr) from comment #4)
> Comment on attachment 391100 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=391100&action=review
> 
> > Source/WebCore/loader/PolicyChecker.cpp:56
> > +#define RELEASE_LOG_ALWAYS(fmt, ...) RELEASE_LOG(Loading, "%p - PolicyChecker::" fmt, this, ##__VA_ARGS__)
> 
> Don't we normally use RELEASE_LOG_IF_ALLOWED?

If possible. The policy for whether or not to perform logging is based on private browsing, which is based on the Session. I don't know if one is available here, but I'll double-check.

> 
> > Source/WebCore/loader/PolicyChecker.cpp:133
> > +        RELEASE_LOG_ALWAYS("checkNavigationPolicy: continuing because empty URL");
> 
> These all need to log some context (pageID, processIdentifier or something).

That information is usually applied in the RELEASE_LOG_ALWAYS macro, so you wouldn't see it at the call site. That said, I don't see any additional information in the macro. I'll see if there's anything appropriate.

[Keith Rollin]

There's no SessionID immediately available to the Policy checking. It doesn't have one as a member, and none is passed in as a parameter anywhere.

Similarly, there is no pageID or frameID information anywhere.

Indirectly, the PolicyChecker has a Frame reference. But this class doesn't have a SessionID or frameID, either.

ProcessID is standard as part of all logging.

In light of all this, can you think of anything else you'd like to see added to the logging?

[Simon Fraser (smfr)]

(In reply to Keith Rollin from comment #6)
> There's no SessionID immediately available to the Policy checking. It
> doesn't have one as a member, and none is passed in as a parameter anywhere.
> 
> Similarly, there is no pageID or frameID information anywhere.
> 
> Indirectly, the PolicyChecker has a Frame reference. But this class doesn't
> have a SessionID or frameID, either.
> 
> ProcessID is standard as part of all logging.
> 
> In light of all this, can you think of anything else you'd like to see added
> to the logging?

Can you get the FrameIdentifier via the FrameLoaderClient?

I'm not sure why FrameIdentifier doesn't live on Frame.

Do resource loads have some kind of identifier we can log?

[Keith Rollin]

(In reply to Simon Fraser (smfr) from comment #7)
> 
> Can you get the FrameIdentifier via the FrameLoaderClient?

I see pageID and frameID in FrameLoaderClient. I'll toss those in. Chris points out that the Frame has a Page reference, which will have a SessionID, so I can add that, too.

> Do resource loads have some kind of identifier we can log?

They do, but I don't think we have any in the context of PolicyChecker calls.

[Keith Rollin]

PolicyChecker logging now looks like:

2020-02-25 16:41:54.252851-0800 0x158edc5  Default     0x0                  35354  0    com.apple.WebKit.WebContent.Development: (WebCore) [com.apple.WebKit:Loading] 0x609c76bd0 - [pageID=19, frameID=3] PolicyChecker::checkNavigationPolicy: continuing because this policyAction from dispatchDecidePolicyForNavigationAction is Use
...
2020-02-25 16:41:56.238576-0800 0x158ed55  Default     0x0                  35352  0    com.apple.WebKit.WebContent.Development: (WebCore) [com.apple.WebKit:Loading] 0x6c1c96d20 - [pageID=10, frameID=3] PolicyChecker::checkNavigationPolicy: stopping because policyAction from dispatchDecidePolicyForNavigationAction is StopAllLoads

[Keith Rollin]

Created attachment 391703 [details]
Patch

[Chris Dumez]

Comment on attachment 391703 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=391703&action=review

r=me with fixes

> Source/WebCore/ChangeLog:15
> +        Reviewed by NOBODY (OOPS!).

This comes *before* the description.

> Source/WebKit/ChangeLog:15
> +        Reviewed by NOBODY (OOPS!).

Ditto.

> Source/WebCore/loader/PolicyChecker.cpp:136
> +        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: continuing because empty URL");

or because it is the same as last request.

> Source/WebCore/loader/PolicyChecker.cpp:155
> +            RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because the content filter told us not to");

This should say that we are not continuing *with substitute data*, to indicate clearly that we are in the substitute data code path.

> Source/WebCore/loader/PolicyChecker.cpp:188
> +        RELEASE_LOG_IF_ALLOWED("checkNavigationPolicy: ignoring because mumble-content-filter-unblock-handler-mumble");

because ContentFilterUnblockHandler can handle the request

> Source/WebCore/loader/ResourceLoader.cpp:397
> +            RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load reached terminal state");

... after calling assignIdentifierToInitialRequest()

> Source/WebCore/loader/SubresourceLoader.cpp:192
> +        RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because request is invalid");

*new* request

> Source/WebCore/loader/SubresourceLoader.cpp:206
> +                RELEASE_LOG_IF_ALLOWED("willSendRequestInternal: resource load canceled because request is NULL (1)");

*new* request is null

> Source/WebKit/WebProcess/WebCoreSupport/WebFrameLoaderClient.cpp:817
> +        WEBFRAMELOADERCLIENT_RELEASE_LOG(Network, "dispatchDecidePolicyForResponse: continuing because the url string is empty");

s/empty/null

[Keith Rollin]

Created attachment 391763 [details]
Patch

[WebKit Commit Bot]

Comment on attachment 391763 [details]
Patch

Clearing flags on attachment: 391763

Committed r257505: <https://trac.webkit.org/changeset/257505>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.