Bug 175030 - API test URLSchemeHandler.Exceptions is Exiting out early on macOS Debug.
Summary: API test URLSchemeHandler.Exceptions is Exiting out early on macOS Debug.
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: New Bugs (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Brady Eidson
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2017-08-01 09:39 PDT by Matt Lewis
Modified: 2021-04-29 10:34 PDT (History)
4 users (show)

See Also:


Attachments
URLSchemeHandler crash (62.29 KB, text/plain)
2017-08-01 10:31 PDT, Matt Lewis
no flags Details
Patch (3.02 KB, patch)
2017-08-01 11:34 PDT, Brady Eidson
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Matt Lewis 2017-08-01 09:39:28 PDT
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
Comment 1 Brady Eidson 2017-08-01 09:45:45 PDT
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.
Comment 2 Brady Eidson 2017-08-01 09:47:42 PDT
(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.
Comment 3 Brady Eidson 2017-08-01 10:19:34 PDT
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?
Comment 4 Matt Lewis 2017-08-01 10:31:27 PDT
Created attachment 316870 [details]
URLSchemeHandler crash

I found the crash log for the API test.
Comment 5 Brady Eidson 2017-08-01 10:55:16 PDT
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.
Comment 6 Brady Eidson 2017-08-01 10:57:52 PDT
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)
Comment 7 Brady Eidson 2017-08-01 11:25:49 PDT
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.
Comment 8 Brady Eidson 2017-08-01 11:34:08 PDT
Created attachment 316875 [details]
Patch
Comment 9 WebKit Commit Bot 2017-08-01 12:04:02 PDT
Comment on attachment 316875 [details]
Patch

Clearing flags on attachment: 316875

Committed r220107: <http://trac.webkit.org/changeset/220107>
Comment 10 WebKit Commit Bot 2017-08-01 12:04:03 PDT
All reviewed patches have been landed.  Closing bug.
Comment 11 Radar WebKit Bug Importer 2017-08-01 12:05:08 PDT
<rdar://problem/33659179>