Bug 240325

Summary: REGRESSION (r293933): [ iOS Debug ][ macOS Debug wk2 ] ASSERTION FAILED: m_requestCount > -1
Product: WebKit Reporter: Karl Rackler <rackler>
Component: Page LoadingAssignee: Alex Christensen <achristensen>
Status: RESOLVED FIXED    
Severity: Normal CC: achristensen, beidson, cdumez, ews-watchlist, japhet, koivisto, rbuis, simon.fraser, webkit-bot-watchers-bugzilla, webkit-bug-importer
Priority: P2 Keywords: InRadar
Version: WebKit Nightly Build   
Hardware: Unspecified   
OS: Unspecified   
See Also: https://bugs.webkit.org/show_bug.cgi?id=240670
https://bugs.webkit.org/show_bug.cgi?id=241676
Attachments:
Description Flags
Crash Log
none
Patch none

Description Karl Rackler 2022-05-11 17:53:51 PDT
Description:
REGRESSION (r293931): [ iOS Debug ][ macOS Debug wk2 ] imported/w3c/web-platform-tests/html/semantics/embedded-content/the-img-element/image-loading-lazy-move-into-script-disabled-iframe.html is a flaky crash
imported/w3c/web-platform-tests/html/semantics/embedded-content/the-img-element/image-loading-lazy-move-into-script-disabled-iframe.html

The first failure that I saw on the dashboard was 5/6/2022 at r293933.  r293931 modified ContentFilterUnblockHandlerCocoa, so that possibly introduced the flakiness crash. 

History:
https://results.webkit.org/?platform=ios&platform=mac&style=debug&limit=50000&suite=layout-tests&test=imported%2Fw3c%2Fweb-platform-tests%2Fhtml%2Fsemantics%2Fembedded-content%2Fthe-img-element%2Fimage-loading-lazy-move-into-script-disabled-iframe.html

Crash Log: 
ERROR: Unhandled web process message 'WebPage_UpdateCurrentModifierState' (destination: 747 pid: 9332)
/Volumes/Data/worker/Apple-iOS-15-Simulator-Debug-Build/build/Source/WebKit/WebProcess/WebProcess.cpp(952) : virtual void WebKit::WebProcess::didReceiveMessage(IPC::Connection &, IPC::Decoder &)
ERROR: Unhandled web process message 'WebPage_HardwareKeyboardAvailabilityChanged' (destination: 747 pid: 9332)
/Volumes/Data/worker/Apple-iOS-15-Simulator-Debug-Build/build/Source/WebKit/WebProcess/WebProcess.cpp(952) : virtual void WebKit::WebProcess::didReceiveMessage(IPC::Connection &, IPC::Decoder &)
ASSERTION FAILED: m_requestCount > -1
./loader/cache/CachedResourceLoader.cpp(1514) : void WebCore::CachedResourceLoader::decrementRequestCount(const WebCore::CachedResource &)
1   0x215079b09 WTFCrash
2   0x23dd05d4b WTFCrashWithInfo(int, char const*, char const*, int)
3   0x2421e165d WebCore::CachedResourceLoader::decrementRequestCount(WebCore::CachedResource const&)
4   0x24214379c WebCore::SubresourceLoader::RequestCountTracker::~RequestCountTracker()
5   0x2421437c5 WebCore::SubresourceLoader::RequestCountTracker::~RequestCountTracker()
Comment 1 Radar WebKit Bug Importer 2022-05-11 17:54:23 PDT
<rdar://problem/93140932>
Comment 2 Karl Rackler 2022-05-11 18:02:57 PDT
REPRODUCTION STEPS
I can reproduce this on r293933, but am unable to reproduce it on r293931 or earlier.

Command: 
[ iOS Debug ]
run-webkit-tests --root 293951-debug --ios-simulator --debug --exit-after-n-failures 1 --exit-after-n-crashes-or-timeouts 1 --iterations 50 --no-retry imported/w3c/web-platform-tests/html/semantics/embedded-content/the-img-element/image-loading-lazy-move-into-script-disabled-iframe.html

[ macOS Debug wk2 ]
run-webkit-tests --debug --root 293933-debug --exit-after-n-failures 1 --exit-after-n-crashes-or-timeouts 1 --iterations 50 -f --no-retry imported/w3c/web-platform-tests/html/semantics/embedded-content/the-img-element/image-loading-lazy-move-into-script-disabled-iframe.html

Result:  
[ iOS Debug ]
Regressions: Unexpected crashes (1)
  imported/w3c/web-platform-tests/html/semantics/embedded-content/the-img-element/image-loading-lazy-move-into-script-disabled-iframe.html [ Crash ]

[ macOS Debug wk2 ]
Regressions: Unexpected crashes (1)
  imported/w3c/web-platform-tests/html/semantics/embedded-content/the-img-element/image-loading-lazy-move-into-script-disabled-iframe.html [ Crash ]

Crash Log: 
https://build.webkit.org/results/Apple-Monterey-Debug-WK2-Tests/250468%40main%20(4625)/imported/w3c/web-platform-tests/html/semantics/embedded-content/the-img-element/image-loading-lazy-move-into-script-disabled-iframe-crash-log.txt
Comment 3 Karl Rackler 2022-05-11 18:05:22 PDT
Created attachment 459195 [details]
Crash Log
Comment 4 Simon Fraser (smfr) 2022-05-12 15:03:30 PDT
Full stack:

read
0  com.apple.JavaScriptCore   	       0x54bf8642e    WTFCrash
1  com.apple.WebCore          	       0x4fb065e08    WTFCrashWithInfo(int, char const*, char const*, int)
2  com.apple.WebCore          	       0x4ff6207da    WebCore::CachedResourceLoader::decrementRequestCount(WebCore::CachedResource const&)
3  com.apple.WebCore          	       0x4ff584a3a    WebCore::SubresourceLoader::RequestCountTracker::~RequestCountTracker()
4  com.apple.WebCore          	       0x4ff584a62    WebCore::SubresourceLoader::RequestCountTracker::~RequestCountTracker()
5  com.apple.WebCore          	       0x4ff597664    std::__1::__optional_destruct_base<WebCore::SubresourceLoader::RequestCountTracker, false>::reset()
6  com.apple.WebCore          	       0x4ff58c236    std::__1::optional<WebCore::SubresourceLoader::RequestCountTracker>::operator=(std::__1::nullopt_t)
7  com.apple.WebCore          	       0x4ff58b690    WebCore::SubresourceLoader::notifyDone(WebCore::LoadCompletionType)
8  com.apple.WebCore          	       0x4ff587b60    WebCore::SubresourceLoader::didFinishLoading(WebCore::NetworkLoadMetrics const&)
9  com.apple.WebKit           	       0x526617b10    WebKit::WebResourceLoader::didFinishResourceLoad(WebCore::NetworkLoadMetrics const&)
10  com.apple.WebKit           	       0x526f57354    void IPC::callMemberFunctionImpl<WebKit::WebResourceLoader, void (WebKit::WebResourceLoader::*)(WebCore::NetworkLoadMetrics const&), std::__1::tuple<WebCore::NetworkLoadMetrics>, 0ul>(WebKit::WebResourceLoader*, void (WebKit::WebResourceLoader::*)(WebCore::NetworkLoadMetrics const&), std::__1::tuple<WebCore::NetworkLoadMetrics>&&, std::__1::integer_sequence<unsigned long, 0ul>)
11  com.apple.WebKit           	       0x526f5723a    void IPC::callMemberFunction<WebKit::WebResourceLoader, void (WebKit::WebResourceLoader::*)(WebCore::NetworkLoadMetrics const&), std::__1::tuple<WebCore::NetworkLoadMetrics>, std::__1::integer_sequence<unsigned long, 0ul> >(std::__1::tuple<WebCore::NetworkLoadMetrics>&&, WebKit::WebResourceLoader*, void (WebKit::WebResourceLoader::*)(WebCore::NetworkLoadMetrics const&))
12  com.apple.WebKit           	       0x526f4c134    void IPC::handleMessage<Messages::WebResourceLoader::DidFinishResourceLoad, WebKit::WebResourceLoader, void (WebKit::WebResourceLoader::*)(WebCore::NetworkLoadMetrics const&)>(IPC::Connection&, IPC::Decoder&, WebKit::WebResourceLoader*, void (WebKit::WebResourceLoader::*)(WebCore::NetworkLoadMetrics const&))
13  com.apple.WebKit           	       0x526f4b83c    WebKit::WebResourceLoader::didReceiveWebResourceLoaderMessage(IPC::Connection&, IPC::Decoder&)
14  com.apple.WebKit           	       0x5266098cc    WebKit::NetworkProcessConnection::didReceiveMessage(IPC::Connection&, IPC::Decoder&)
15  com.apple.WebKit           	       0x5256ccf52    IPC::Connection::dispatchMessage(IPC::Decoder&)
16  com.apple.WebKit           	       0x5256cd612    IPC::Connection::dispatchMessage(std::__1::unique_ptr<IPC::Decoder, std::__1::default_delete<IPC::Decoder> >)
17  com.apple.WebKit           	       0x5256cdc1a    IPC::Connection::dispatchOneIncomingMessage()
18  com.apple.WebKit           	       0x5256eeb52    IPC::Connection::enqueueIncomingMessage(std::__1::unique_ptr<IPC::Decoder, std::__1::default_delete<IPC::Decoder> >)::$_15::operator()()
19  com.apple.WebKit           	       0x5256eea66    WTF::Detail::CallableWrapper<IPC::Connection::enqueueIncomingMessage(std::__1::unique_ptr<IPC::Decoder, std::__1::default_delete<IPC::Decoder> >)::$_15, void>::call()
20  com.apple.JavaScriptCore   	       0x54bfb58f0    WTF::Function<void ()>::operator()() const
21  com.apple.JavaScriptCore   	       0x54c050c3c    WTF::RunLoop::performWork()
22  com.apple.JavaScriptCore   	       0x54c05569c    WTF::RunLoop::performWork(void*)
Comment 5 Simon Fraser (smfr) 2022-05-16 17:03:08 PDT
This test fails for me with:
[Error] Failed to load resource: the server responded with a status of 404 (Not Found) (subframe.html, line 0)
Comment 6 Simon Fraser (smfr) 2022-05-16 17:05:01 PDT
`resources/subframe.html` is missing in the WPT repo too. Rob, is this on purpose?
Comment 7 Ryan Haddad 2022-05-25 14:13:21 PDT
*** Bug 240670 has been marked as a duplicate of this bug. ***
Comment 8 Rob Buis 2022-06-13 09:54:33 PDT
I looked into this last week. I am pretty sure the request counting of the image in resources/image-loading-lazy-in-viewport.html is spread across two documents (one for each subframe in the test). So the decrement is on something that was never incremented, hence the assert.
I was playing with some code in ImageLoader::elementDidMoveToNewDocument, but it was hard to detect the case and then do something about it. I hope to have another look this week.
Comment 9 Simon Fraser (smfr) 2022-06-13 20:30:16 PDT
Good:
20:26:18.075 98874 worker/13    RequestCountTracker: loader 0x154179820 resource 0x154089c00 http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.9175318621737235-1655177151179
20:26:18.075 98874 worker/13   CachedResourceLoader 0x154179820 incrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.9175318621737235-1655177151179 ignore: 1
20:26:18.075 98874 worker/13   ~RequestCountTracker: loader 0x154179820 resource 0x154089c00 http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.9175318621737235-1655177151179
20:26:18.075 98874 worker/13   CachedResourceLoader 0x154179820 decrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.9175318621737235-1655177151179 ignore: 1

Bad:
20:27:56.323 99057 worker/9    RequestCountTracker: loader 0x414085820 resource 0x414089c00 http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.45203600444193737-1655177240308
20:27:56.323 99057 worker/9   CachedResourceLoader 0x414085820 incrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.45203600444193737-1655177240308 ignore: 1
20:27:56.323 99057 worker/9   CachedResourceLoader 0x414085da0 incrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.45203600444193737-1655177240308 ignore: 0
20:27:56.324 99057 worker/9   ~RequestCountTracker: loader 0x414085820 resource 0x414089c00 http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.45203600444193737-1655177240308
20:27:56.324 99057 worker/9   CachedResourceLoader 0x414085820 decrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.45203600444193737-1655177240308 ignore: 0
20:27:56.324 99057 worker/9   CachedResourceLoader 0x414085820 decrementRequestCount: bad request count for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.45203600444193737-1655177240308

So it's the ignoreForRequestCount() that's different.
Comment 10 Simon Fraser (smfr) 2022-06-13 20:55:26 PDT
Looks like an interaction with preloading:

20:41:48.278 491 worker/0   ImageLoader::updateFromElement: request http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911 - setting ignore to true for lazy loading
20:41:48.278 491 worker/0    RequestCountTracker: loader 0x4d40840c0 resource 0x4d4088e80 http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911
20:41:48.278 491 worker/0   CachedResourceLoader 0x4d40840c0 incrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911 ignore: 1
20:41:48.278 491 worker/0   CachedResourceLoader 0x4d4084640 requestResource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911 - setting ignore to false for preload
20:41:48.278 491 worker/0   CachedResourceLoader 0x4d4084640 incrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911 ignore: 0
20:41:48.279 491 worker/0   ~RequestCountTracker: loader 0x4d40840c0 resource 0x4d4088e80 http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911
20:41:48.279 491 worker/0   CachedResourceLoader 0x4d40840c0 decrementRequestCount for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911 ignore: 0
20:41:48.279 491 worker/0   CachedResourceLoader 0x4d40840c0 decrementRequestCount: bad request count for resource http://localhost:8800/html/semantics/embedded-content/the-img-element/resources/image.png?image-loading-lazy-in-viewport-0.26373450708710056-1655178032911

Looks like we have two separate CachedResourceLoader for the same CachedResource (weird). Preloading toggles m_ignoreForRequestCount on the CachedResource, which causes an extra decrement of m_requestCount on one of the CachedResourceLoaders.
Comment 11 Simon Fraser (smfr) 2022-06-13 21:20:30 PDT
The two CachedResourceLoaders are in different frames, but they reference the same CachedResource. I'm not sure how resource.ignoreForRequestCount() is supposed to work in this case; seems like it's easy for CachedResourceLoader::m_requestCount to get out of whack.
Comment 12 Alex Christensen 2022-06-27 22:25:28 PDT
Created attachment 460513 [details]
Patch
Comment 13 Antti Koivisto 2022-06-28 09:41:51 PDT
Comment on attachment 460513 [details]
Patch

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

> Source/WebCore/loader/cache/CachedResourceLoader.cpp:1078
> +        subresourceLoader->clearRequestCountTracker();
>          resource->setIgnoreForRequestCount(false);
> -        incrementRequestCount(*resource);
> +        subresourceLoader->resetRequestCountTracker(*this, *resource);

I feel there is a less confusing factoring for this that involves not making a request count tracker at all when you are ignoring request counts.
Comment 14 Alex Christensen 2022-06-28 10:46:17 PDT
Comment on attachment 460513 [details]
Patch

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

>> Source/WebCore/loader/cache/CachedResourceLoader.cpp:1078
>> +        subresourceLoader->resetRequestCountTracker(*this, *resource);
> 
> I feel there is a less confusing factoring for this that involves not making a request count tracker at all when you are ignoring request counts.

This removes an asymmetric increment call and is an improvement, but you're right, I think there's room for future improvement.
Comment 15 Alex Christensen 2022-06-28 10:50:29 PDT
I'm also not thrilled about all these raw pointers being stored everywhere.
Comment 16 EWS 2022-06-28 11:27:53 PDT
Committed 251917@main (d48c70af7924): <https://commits.webkit.org/251917@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 460513 [details].