Bug 212281 – REGRESSION (r261812): editing/async-clipboard/clipboard-item-get-type-basic.html is flaky

• Status: RESOLVED
• Resolution: FIXED
• Component: HTML Editing

[Jason Lawrence]

editing/async-clipboard/clipboard-item-get-type-basic.html

Description:
This test is flaky failing on iOS wk2 release. It was passing consistently until 5/19/2020. 

History:
https://results.webkit.org/?suite=layout-tests&test=editing%2Fasync-clipboard%2Fclipboard-item-get-type-basic.html&platform=ios&limit=50000&style=release

Diff:
--- /Volumes/Data/slave/ios-simulator-13-release-tests-wk2/build/layout-test-results/editing/async-clipboard/clipboard-item-get-type-basic-expected.txt
+++ /Volumes/Data/slave/ios-simulator-13-release-tests-wk2/build/layout-test-results/editing/async-clipboard/clipboard-item-get-type-basic-actual.txt
@@ -2,12 +2,9 @@
 
 On success, you will see a series of "PASS" messages, followed by "TEST COMPLETE".
 
-PASS items.length is 1
-PASS item.types.length is 3
-PASS text is "Apple, Inc."
-PASS url is "https://www.apple.com/"
-PASS doc.querySelector('a').href is "https://www.apple.com/"
+FAIL Caught unexpected exception: NotAllowedError
 PASS successfullyParsed is true
+Some tests failed.
 
 TEST COMPLETE

[Radar WebKit Bug Importer]

<rdar://problem/63554912>

[Jason Lawrence]

I have marked this test as flaky failing while this issue is investigated.
https://trac.webkit.org/changeset/262078/webkit

[Jason Lawrence]

I am able to reproduce this issue on 261815 using the command below, but I cannot reproduce it on 261811.

run-webkit-tests --ios-simulator --device-type iPhone SE --iterations 99 --exit-after-n-failures 3 --force editing/async-clipboard/clipboard-item-get-type-basic.html

r261815:
[27/99] editing/async-clipboard/clipboard-item-get-type-basic.html failed unexpectedly (text diff)
[41/99] editing/async-clipboard/clipboard-item-get-type-basic.html failed unexpectedly (text diff)
[47/99] editing/async-clipboard/clipboard-item-get-type-basic.html failed unexpectedly (text diff)
Exiting early after 3 failures. 47 tests run.


44 tests ran as expected, 3 didn't (52 didn't run):

r261811:
All 99 tests ran as expected.

[Alexey Proskuryakov]

r261812 is the only editing change in this range, and a very timing sensitive one.

[Wenson Hsieh]

I’m unable to reproduce this locally. I ran for 600 iterations several times at full parallelization (10 test runners on my machine).

[Wenson Hsieh]

Created attachment 400259 [details]
Repro attempt #1

[Wenson Hsieh]

Created attachment 400260 [details]
Repro attempt #2

[Wenson Hsieh]

Created attachment 400261 [details]
Repro attempt #3

[Wenson Hsieh]

Created attachment 400262 [details]
Repro attempt #4

[Wenson Hsieh]

Created attachment 400263 [details]
Repro attempt #5

[Wenson Hsieh]

Created attachment 400344 [details]
Repro attempt #6

[Wenson Hsieh]

Created attachment 400348 [details]
Repro attempt #7 (more logging)

[Wenson Hsieh]

Created attachment 400354 [details]
Repro attempt #8 (and force EWS to fail)

[Wenson Hsieh]

Created attachment 400385 [details]
Repro attempt #9

[Wenson Hsieh]

Created attachment 400486 [details]
Repro attempt #10

[Wenson Hsieh]

Created attachment 400497 [details]
Repro attempt #11

[Wenson Hsieh]

(In reply to Wenson Hsieh from comment #16)
> Created attachment 400497 [details]
> Repro attempt #11

I think I’ve finally found a smoking gun...!

13:46:36.213 17986   <WK>: Has active session? no
13:46:36.213 17986   <WK>: - changeCountAtStart 12
13:46:36.213 17986   <WK>: - m_activeSession->changeCount 0
13:46:36.213 17986   <WK>: void WebKit::WebPasteboardProxy::allPasteboardItemInfo(IPC::Connection &, const WTF::String &, int64_t, CompletionHandler<void (Optional<Vector<WebCore::PasteboardItemInfo> > &&)> &&)
13:46:36.213 17986   <WK>: BAILING BECAUSE CHANGE COUNTS DIFFER (12, 14)
13:46:36.213 17986   <WK>: Got pasteboard item info? no
13:46:36.213 17986   <WK>: Number of items: 0
13:46:36.271 17986 "ruby --version" took 0.06s
13:46:37.716 17986 "ruby -I /Volumes/Data/worker/iOS-13-Simulator-WK2-Tests-EWS/build/Websites/bugs.webkit.org/PrettyPatch /Volumes/Data/worker/iOS-13-Simulator-WK2-Tests-EWS/build/Websites/bugs.webkit.org/PrettyPatch/prettify.rb /Volumes/Data/worker/iOS-13-Simulator-WK2-Tests-EWS/build/layout-test-results/editing/async-clipboard/clipboard-item-get-type-basic-1-diff.txt" took 1.44s
13:46:37.722 16182 [4601/46006] editing/async-clipboard/clipboard-item-get-type-basic-1.html failed unexpectedly (text diff)

We’re bailing in PlatformPasteboard::allPasteboardItemInfo because the change count has been bumped beneath us. Need to drill further to figure out what’s causing the change count to increment (twice, even!)

[Wenson Hsieh]

Created attachment 400523 [details]
Repro attempt #12

[Wenson Hsieh]

(In reply to Wenson Hsieh from comment #18)
> Created attachment 400523 [details]
> Repro attempt #12

<WK>: Committed load: <blank>
<WK>: Committed load: </Volumes/Data/worker/iOS-13-Simulator-WK2-Tests-EWS/build/LayoutTests/editing/async-clipboard/clipboard-item-get-type-basic-8.html>
<WK>: Waiting for autocorrection context...
<WK>: void WebKit::WebPasteboardProxy::getPasteboardChangeCount(const WTF::String &, CompletionHandler<void (int64_t)> &&) => 32
<WK>: Writing custom data.
<WK>: void WebKit::WebPasteboardProxy::writeCustomData(IPC::Connection &, const Vector<WebCore::PasteboardCustomData> &, const WTF::String &, CompletionHandler<void (int64_t)> &&)
<WK>: int64_t WebCore::PlatformPasteboard::write(const Vector<WebCore::PasteboardCustomData> &)
<WK>: -[WKContentView(WKInteraction) _pasteboardChanged]
<WK>: 0   WebKit                              0x00000001078ec54a -[WKContentView(WKInteraction) _pasteboardChanged] + 104
<WK>: 1   CoreFoundation                      0x000000010962ed0c __CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__ + 12
<WK>: 2   CoreFoundation                      0x000000010962e185 _CFXRegistrationPost1 + 421
<WK>: 3   CoreFoundation                      0x000000010962def1 ___CFXNotificationPost_block_invoke + 193
<WK>: 4   CoreFoundation                      0x000000010972b2d3 -[_CFXNotificationRegistrar find:object:observer:enumerator:] + 1795
<WK>: 5   CoreFoundation                      0x000000010962d846 _CFXNotificationPost + 950
<WK>: 6   Foundation                          0x0000000108ce2e2b -[NSNotificationCenter postNotificationName:object:userInfo:] + 59
<WK>: 7   UIKitCore                           0x000000011797a6ca _sendPasteboardChangedNotification + 90
<WK>: 8   UIKitCore                           0x000000011797a553 -[_UIConcretePasteboard _saveItemCollection:] + 192
<WK>: 9   UIKitCore                           0x0000000117981552 -[_UIConcretePasteboard _setItemsAndSave:options:coerceStringsToURLs:] + 1539
<WK>: 10  UIKitCore                           0x000000011797cbf1 -[_UIConcretePasteboard setItemProviders:localOnly:expirationDate:] + 590
<WK>: 11  WebCore                             0x000000010b67cda2 _ZN7WebCoreL25registerItemsToPasteboardEP7NSArrayIP35WebItemProviderRegistrationInfoListEPU29objcproto18AbstractPasteboard11objc_object + 402

…

<WK>: 
<WK>: ...done waiting!
<WK>: void WebKit::WebPasteboardProxy::getPasteboardChangeCount(const WTF::String &, CompletionHandler<void (int64_t)> &&) => 33
<WK>: -[WKContentView(WKInteraction) supportsImagePaste] => NO
<WK>: 0   WebKit                              0x00000001078ec6b0 -[WKContentView(WKInteraction) supportsImagePaste] + 148
<WK>: 1   UIKitCore                           0x000000011786009e -[UIKeyboardImpl delegateSupportsImagePaste] + 444
<WK>: 2   UIKitCore                           0x000000011785fe00 -[UIKeyboardImpl updateDelegatePasteSupport] + 274
<WK>: 3   UIKitCore                           0x000000011785fbfc -[UIKeyboardImpl didSetDelegate] + 222

…

<WK>: 
<WK>: void WebKit::WebPasteboardProxy::getPasteboardChangeCount(const WTF::String &, CompletionHandler<void (int64_t)> &&) => 35
<WK>: Requesting DOM paste access...
<WK>: ...passed.
<WK>: 
<WK>: Has active session? no
<WK>: - changeCountAtStart 35
<WK>: - m_activeSession->changeCount 0
<WK>: void WebKit::WebPasteboardProxy::allPasteboardItemInfo(IPC::Connection &, const WTF::String &, int64_t, CompletionHandler<void (Optional<Vector<WebCore::PasteboardItemInfo> > &&)> &&)
<WK>: BAILING BECAUSE CHANGE COUNTS DIFFER (33, 35)
<WK>: Got pasteboard item info? no
<WK>: Number of items: 0

It seems like what’s happening is that code in UIKit (-[UIKeyboardImpl delegateSupportsImagePaste]) that was added in support of Memojis in the software keyboard kicks in after we focus an element, pins a temporary PNG image to the pasteboard, clears the pinned PNG image, and finally restores the contents of the pasteboard to what it was before pinning. This causes the changeCount of the pasteboard to be incremented twice, which interferes with WebKit’s logic (in both the web and UI processes) that prevents the page from accessing the clipboard if the changeCount has changed underneath us.

Coincidentally, this seems to have been fixed after a recent UIKit change, <rdar://problem/60891825>. That explains why iOS bots running shipping software are hitting this...

[Wenson Hsieh]

Created attachment 400548 [details]
Patch

[Wenson Hsieh]

Created attachment 400551 [details]
Patch for EWS

[EWS]

Committed r262283: <https://trac.webkit.org/changeset/262283>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 400551 [details].