Bug 240325

Summary:

REGRESSION (r293933): [ iOS Debug ][ macOS Debug wk2 ] ASSERTION FAILED: m_requestCount > -1

Product:

WebKit

Reporter:

Karl Rackler <rackler>

Component:

Page Loading

Assignee:

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:

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

Karl Rackler

Reported 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()

Attachments
Crash Log (27.17 KB, text/plain) 2022-05-11 18:05 PDT, Karl Rackler	no flags	Details
Patch (6.06 KB, patch) 2022-06-27 22:25 PDT, Alex Christensen	no flags	Details Formatted Diff Diff
View All Add attachment proposed patch, testcase, etc.

Radar WebKit Bug Importer

Comment 1 2022-05-11 17:54:23 PDT

<rdar://problem/93140932>

Karl Rackler

Comment 2 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

Karl Rackler

Comment 3 2022-05-11 18:05:22 PDT

Created attachment 459195 [details] Crash Log

Simon Fraser (smfr)

Comment 4 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*)

Simon Fraser (smfr)

Comment 5 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)

Simon Fraser (smfr)

Comment 6 2022-05-16 17:05:01 PDT

`resources/subframe.html` is missing in the WPT repo too. Rob, is this on purpose?

Ryan Haddad

Comment 7 2022-05-25 14:13:21 PDT

*** Bug 240670 has been marked as a duplicate of this bug. ***

Rob Buis

Comment 8 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.

Simon Fraser (smfr)

Comment 9 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.

Simon Fraser (smfr)

Comment 10 2022-06-13 20:55:26 PDT

Simon Fraser (smfr)

Comment 11 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.

Alex Christensen

Comment 12 2022-06-27 22:25:28 PDT

Created attachment 460513 [details] Patch

Antti Koivisto

Comment 13 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.

Alex Christensen

Comment 14 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.

Alex Christensen

Comment 15 2022-06-28 10:50:29 PDT

I'm also not thrilled about all these raw pointers being stored everywhere.

EWS

Comment 16 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].

Note You need to log in before you can comment on or make changes to this bug.