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()
<rdar://problem/93140932>
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
Created attachment 459195 [details] Crash Log
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*)
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)
`resources/subframe.html` is missing in the WPT repo too. Rob, is this on purpose?
*** Bug 240670 has been marked as a duplicate of this bug. ***
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.
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.
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.
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.
Created attachment 460513 [details] Patch
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 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.
I'm also not thrilled about all these raw pointers being stored everywhere.
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].