Bug 175030 – API test URLSchemeHandler.Exceptions is Exiting out early on macOS Debug.

• Component: New Bugs
• Status: RESOLVED FIXED

[Matt Lewis]

URLSchemeHandler.Exceptions is closing out unexpectedly consistently on El Capitan Debug bot WK1 and WK2. It is flaky on Sierra WK2 Debug and Flaky on Sierra Debug both on WK2 and WK1.

The error given is:
UNEXPECTEDLY EXITED URLSchemeHandler.Exceptions
2017-08-01 00:36:00.514 TestWebKitAPI[29562:699404] -[NSError init] called; this results in an invalid NSError instance. It will raise an exception in a future release. Please call errorWithDomain:code:userInfo: or initWithDomain:code:userInfo:. This message shown only once.

Build and results:
https://build.webkit.org/builders/Apple%20El%20Capitan%20Debug%20WK2%20%28Tests%29/builds/2343
https://build.webkit.org/builders/Apple%20El%20Capitan%20Debug%20WK2%20%28Tests%29/builds/2343/steps/run-api-tests/logs/stdio

I was able to reproduce the error code locally but not the unexpected exit on El Capitan.

I used run-api-tests -v URLSchemeHandler

[Brady Eidson]

The logged error message is not relevant here - The crash is!

I started with a clean install of El Capitan, a ToT WebKit debug build, and also could not reproduce.

Really going to need the crash log here.

[Brady Eidson]

(In reply to Matt Lewis from comment #0)
> URLSchemeHandler.Exceptions is closing out unexpectedly consistently on El
> Capitan Debug bot WK1 and WK2. It is flaky on Sierra WK2 Debug and Flaky on
> Sierra Debug both on WK2 and WK1.

Note that the "WK1"ness or "WK2"ness of the bot is irrelevant for API tests. All API tests are run in all test-webkit-api configurations.

[Brady Eidson]

From one of the log files on the bots:

UNEXPECTEDLY EXITED URLSchemeHandler.Exceptions
2017-08-01 09:12:57.598 TestWebKitAPI[61333:1470342] -[NSError init] called; this results in an invalid NSError instance. It will raise an exception in a future release. Please call errorWithDomain:code:userInfo: or initWithDomain:code:userInfo:. This message shown only once.
PASS URLSchemeHandler.Leaks1
PASS URLSchemeHandler.Leaks2
ERROR: WebLoaderStrategy::networkProcessCrashed: failing all pending resource loaders
/Volumes/Data/slave/elcapitan-debug/build/Source/WebKit/WebProcess/Network/WebLoaderStrategy.cpp(343) : void WebKit::WebLoaderStrategy::networkProcessCrashed()
ERROR: WebLoaderStrategy::networkProcessCrashed: failing all pending resource loaders
/Volumes/Data/slave/elcapitan-debug/build/Source/WebKit/WebProcess/Network/WebLoaderStrategy.cpp(343) : void WebKit::WebLoaderStrategy::networkProcessCrashed()

This suggests the possibility that the Networking process crashed which is what caused the test in question to bail.

Have a log for that, maybe?

[Matt Lewis]

Created attachment 316870 [details]
URLSchemeHandler crash

I found the crash log for the API test.

[Brady Eidson]

Great! A huge help.

---

Application Specific Information:
objc_msgSend() selector name: didFinish
...
Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0   libobjc.A.dylib               	0x00007fff97f944dd objc_msgSend + 29
1   com.apple.WebKit              	0x0000000110b1e5bf WebKit::WebURLSchemeHandlerCocoa::platformStartTask(WebKit::WebPageProxy&, WebKit::WebURLSchemeTask&) + 383 (WebURLSchemeHandlerCocoa.mm:56)
2   com.apple.WebKit              	0x0000000110b17f55 WebKit::WebURLSchemeHandler::startTask(WebKit::WebPageProxy&, unsigned long long, WebCore::ResourceRequest const&) + 517 (WebURLSchemeHandler.cpp:61)
3   com.apple.WebKit              	0x00000001108b51a0 WebKit::WebPageProxy::startURLSchemeTask(unsigned long long, unsigned long long, WebCore::ResourceRequest const&) + 256 (WebPageProxy.cpp:6937)
4   com.apple.WebKit              	0x0000000110972e69 void IPC::callMemberFunctionImpl<WebKit::WebPageProxy, void (WebKit::WebPageProxy::*)(unsigned long long, unsigned long long, WebCore::ResourceRequest const&), std::__1::tuple<unsigned long long, unsigned long long, WebCore::ResourceRequest>, 0ul, 1ul, 2ul>(WebKit::WebPageProxy*, void (WebKit::WebPageProxy::*)(unsigned long long, unsigned long long, WebCore::ResourceRequest const&), std::__1::tuple<unsigned long long, unsigned long long, WebCore::ResourceRequest>&&, std::__1::integer_sequence<unsigned long, 0ul, 1ul, 2ul>) + 265 (HandleMessage.h:41)

---

WebKit is starting a WKURLSchemeTask, calling back to TestWebKitAPI.
TestWebKitAPI is trying to finish that task (sending "didFinish:" to it), but the task is invalid already.

I don't yet see how this might happen, but I know what to look for now.

[Brady Eidson]

And looking at this test, it's also unclear why this would be 100% on ElCap, flakey on Sierra, but engineers haven't repro'ed locally)

[Brady Eidson]

With a whole bunch of logging built in, I can start to reproduce it. Timing related somehow.

The command sequence in question is:
checkCallSequence({Command::Response, Command::Finish, Command::Data}, ShouldRaiseException::Yes);

When Finish is called, the task is dealloc'ed.

So the call to didReceiveData: is on a dealloc'ed task.

Easy fix coming.

[Brady Eidson]

Created attachment 316875 [details]
Patch

[WebKit Commit Bot]

Comment on attachment 316875 [details]
Patch

Clearing flags on attachment: 316875

Committed r220107: <http://trac.webkit.org/changeset/220107>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Radar WebKit Bug Importer]

<rdar://problem/33659179>