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.
<rdar://problem/59567875>
Created attachment 391100 [details] Patch
bump.
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).
(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.
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?
(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?
(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.
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
Created attachment 391703 [details] Patch
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
Created attachment 391763 [details] Patch
Comment on attachment 391763 [details] Patch Clearing flags on attachment: 391763 Committed r257505: <https://trac.webkit.org/changeset/257505>
All reviewed patches have been landed. Closing bug.