Bug 180547 – Message Handlers fail to call despite message being sent

• Component: Page Loading
• Status: NEW

[Josh Hrach]

Created attachment 328731 [details]
Simple project demoing issue

Scenario: We have two AJAX calls that we are making within a web view. Each call has a callback that is called when the call is complete. As they are async calls, we wait for the callback to trigger a message before we reload the web view. 

When run in the iOS 11 simulator with Xcode 9, we get consistent behavior. AJAX Call 1 is sent, Call 1's callback is called and the message is handled. Call 2 is sent, same. This can be done ad infinitum with no issues.

On device, however, the behavior is different. After a certain number of calls (this varies between tests), eventually the callback fails to be handled by the device. Server logs show that the callback is indeed sent. The following is an example of what happens:
* Call 1 is sent
* Call 1's callback is called, app receives message
* Call 2 is sent
* Call 2's callback is called, app receives message
* Call 1 is sent
* No callback is detected
* Call 2 is sent
* Call 2's callback message is received
* Call 1's callback message is received

It seems that, after a certain number of messages, messages fail to come through promptly and appear stuck until another AJAX call/message is sent/received. This behavior was also seen when using WKHTTPCookieStore.getAllCookies(). A breakpoint set within the getAllCookies() closure was not hit until after several messages were received. I had expected this function to return me cookies right away, but instead something seemed to lock up the web view.

Enclosed is a sample project. Expected usage: Tap Set. Wait for Alert. Dismiss alert. Tap Clear. Wait for Alert. Dismiss alert. Repeat.
Simulator results: You should have no problem with the above sequence.
On device: After several attempts (my testing has shown it happening after as little as 2 calls or as many as 20), tapping one of the buttons will not trigger a callback message and alert. Console logs show that evaluateJavaScript's completion handler is called, but no message is received, despite server logs saying that they are sent. Eventually, tapping either button to continue testing will show multiple messages being retrieved at the same time.

Testing environment: Xcode 9.2
Device: iPhone X, iOS 11.2

[Radar WebKit Bug Importer]

<rdar://problem/35923752>

[Josh Hrach]

Issue still happening on iOS 11.3.

Additionally, when clearing data, I'm getting some internal logging.

Here's how I'm deleting data:

===
let group = DispatchGroup()
group.enter()
WKWebsiteDataStore.default().fetchDataRecords(ofTypes: WKWebsiteDataStore.allWebsiteDataTypes()) { records in
       let companyRecords = records.filter({$0.displayName.contains("<companyNameHere>")})
       companyRecords.forEach { record in
           group.enter()
           WKWebsiteDataStore.default().removeData(ofTypes: record.dataTypes, for: [record], completionHandler: { group.leave() })
           print("[Webview] Record \(record) deleted")
       }
       group.leave()
       group.notify(queue: .main, execute: {
           print("Cookie records deleted.")
           self.callback(forSet: false)
       })
}
```

After deleting the single record found, I'm seeing this in console:

2018-04-27 10:42:12.552588-0700 WebKitScriptHandlerTest[4122:2151546] [logging] BUG IN CLIENT OF libsqlite3.dylib: database integrity compromised by API violation: vnode unlinked while in use: /private/var/mobile/Containers/Data/Application/3C1BBDA4-5994-41AE-B8B4-84B6BC6B6835/Library/WebKit/WebsiteData/LocalStorage/https_www.<company>.com_0.localstorage
2018-04-27 10:42:12.552701-0700 WebKitScriptHandlerTest[4122:2151546] [logging] invalidated open fd: 6 (0x11)
2018-04-27 10:42:12.553066-0700 WebKitScriptHandlerTest[4122:2151546] [logging] BUG IN CLIENT OF libsqlite3.dylib: database integrity compromised by API violation: vnode unlinked while in use: /private/var/mobile/Containers/Data/Application/3C1BBDA4-5994-41AE-B8B4-84B6BC6B6835/Library/WebKit/WebsiteData/LocalStorage/https_www.<company>.com_0.localstorage-wal
2018-04-27 10:42:12.553133-0700 WebKitScriptHandlerTest[4122:2151546] [logging] invalidated open fd: 7 (0x11)
2018-04-27 10:42:12.553644-0700 WebKitScriptHandlerTest[4122:2151546] [logging] BUG IN CLIENT OF libsqlite3.dylib: database integrity compromised by API violation: vnode unlinked while in use: /private/var/mobile/Containers/Data/Application/3C1BBDA4-5994-41AE-B8B4-84B6BC6B6835/Library/WebKit/WebsiteData/LocalStorage/https_www.<company>.com_0.localstorage-shm
2018-04-27 10:42:12.553707-0700 WebKitScriptHandlerTest[4122:2151546] [logging] invalidated open fd: 8 (0x11)

[Josh Hrach]

Created attachment 341878 [details]
Updated sample project. Included 2 examples. Readme file explains the issue.

[Josh Hrach]

Issue persists in iOS 11.4.

Also want to note that the WKWebView instance is not being added as a subview. It isn't intended to be displayed but rather to exist in the background to handle network activity.

[Chris Dumez]

(In reply to Josh Hrach from comment #4)
> Issue persists in iOS 11.4.
> 
> Also want to note that the WKWebView instance is not being added as a
> subview. It isn't intended to be displayed but rather to exist in the
> background to handle network activity.

The processes on a WKWebView which is not visible get suspended on iOS for power reasons.

[Josh Hrach]

Does it matter how visible the web view is? This was created as a way to manage working with our web services while operating natively in the app.

If I create a new window for the web view but don't make it a key window, will this still get suspended?

[Chris Dumez]

(In reply to Josh Hrach from comment #6)
> Does it matter how visible the web view is? This was created as a way to
> manage working with our web services while operating natively in the app.
> 
> If I create a new window for the web view but don't make it a key window,
> will this still get suspended?

The view needs to be in the view hierarchy and at least partly visible on screen in order for its child processes to not get suspended on iOS.

[Josh Hrach]

So if I create a web view of 1x1 point size (I assume 0x0 would be considered hidden), then it would be enough to keep it in process so long as it is on top of other views?

[Chris Dumez]

(In reply to Josh Hrach from comment #8)
> So if I create a web view of 1x1 point size (I assume 0x0 would be
> considered hidden), then it would be enough to keep it in process so long as
> it is on top of other views?

I would imagine so, try it out.

[Josh Hrach]

I'll try that.

Meanwhile, is there any reason why, despite this behavior, the following completion handlers don't get called consistently:

webView.configuration.websiteDataStore.httpCookieStore.setCookie(_:completionHandler:)

WKWebsiteDataStore.default().fetchDataRecords(ofTypes:completionHandler:)

I would assume that managing data should work reliably despite a web view not being visible. I'm guessing the intention is for all of this to happen before navigating to the initial URL when presenting a WKWebView but after it's added to the view hierarchy?

[Geoffrey Garen]

> Meanwhile, is there any reason why, despite this behavior, the following
> completion handlers don't get called consistently:
> 
> webView.configuration.websiteDataStore.httpCookieStore.setCookie(_:
> completionHandler:)
> 
> WKWebsiteDataStore.default().fetchDataRecords(ofTypes:completionHandler:)

That sounds like a (separate) bug.

[Brady Eidson]

(In reply to Geoffrey Garen from comment #11)
> > Meanwhile, is there any reason why, despite this behavior, the following
> > completion handlers don't get called consistently:
> > 
> > webView.configuration.websiteDataStore.httpCookieStore.setCookie(_:
> > completionHandler:)
> > 
> > WKWebsiteDataStore.default().fetchDataRecords(ofTypes:completionHandler:)
> 
> That sounds like a (separate) bug.

Actually, both of those calls do require IPC to the web process, so if the web process is suspended because the view is offscreen that would explain this behavior.

But, for the website data store calls, we should be able to fix that by temporarily unsuspending the web process.

[Chris Dumez]

(In reply to Brady Eidson from comment #12)
> (In reply to Geoffrey Garen from comment #11)
> > > Meanwhile, is there any reason why, despite this behavior, the following
> > > completion handlers don't get called consistently:
> > > 
> > > webView.configuration.websiteDataStore.httpCookieStore.setCookie(_:
> > > completionHandler:)
> > > 
> > > WKWebsiteDataStore.default().fetchDataRecords(ofTypes:completionHandler:)
> > 
> > That sounds like a (separate) bug.
> 
> Actually, both of those calls do require IPC to the web process, so if the
> web process is suspended because the view is offscreen that would explain
> this behavior.
> 
> But, for the website data store calls, we should be able to fix that by
> temporarily unsuspending the web process.

I do not believe this is an issue for fetchWebsiteData() takes a background activity so ensure that the child process stays alive until we get the data back.

However, looking at httpCookieStore.setCookie(), I do not see it take background activity, which indeed seems wrong. WebCookieManagerProxy should probably be updated to take background assertions during the execution of the callbacks.