Bug 212281

Summary: REGRESSION (r261812): editing/async-clipboard/clipboard-item-get-type-basic.html is flaky
Product: WebKit Reporter: Jason Lawrence <Lawrence.j>
Component: HTML EditingAssignee: Wenson Hsieh <wenson_hsieh>
Status: RESOLVED FIXED    
Severity: Normal CC: ap, bdakin, benjamin, cdumez, cmarcelo, esprehn+autocc, ews-watchlist, kangil.han, megan_gardner, thorton, webkit-bot-watchers-bugzilla, webkit-bug-importer, wenson_hsieh
Priority: P2 Keywords: InRadar
Version: WebKit Nightly Build   
Hardware: iPhone / iPad   
OS: iOS 13   
Attachments:
Description Flags
Repro attempt #1
none
Repro attempt #2
none
Repro attempt #3
none
Repro attempt #4
none
Repro attempt #5
none
Repro attempt #6
none
Repro attempt #7 (more logging)
none
Repro attempt #8 (and force EWS to fail)
none
Repro attempt #9
none
Repro attempt #10
none
Repro attempt #11
none
Repro attempt #12
none
Patch
none
Patch for EWS none

Description Jason Lawrence 2020-05-22 14:48:06 PDT
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
Comment 1 Radar WebKit Bug Importer 2020-05-22 14:48:35 PDT
<rdar://problem/63554912>
Comment 2 Jason Lawrence 2020-05-22 14:57:34 PDT
I have marked this test as flaky failing while this issue is investigated.
https://trac.webkit.org/changeset/262078/webkit
Comment 3 Jason Lawrence 2020-05-22 15:55:16 PDT
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.
Comment 4 Alexey Proskuryakov 2020-05-25 14:37:42 PDT
r261812 is the only editing change in this range, and a very timing sensitive one.
Comment 5 Wenson Hsieh 2020-05-26 09:42:58 PDT
I’m unable to reproduce this locally. I ran for 600 iterations several times at full parallelization (10 test runners on my machine).
Comment 6 Wenson Hsieh 2020-05-26 10:36:23 PDT Comment hidden (obsolete)
Comment 7 Wenson Hsieh 2020-05-26 10:37:10 PDT Comment hidden (obsolete)
Comment 8 Wenson Hsieh 2020-05-26 10:37:42 PDT Comment hidden (obsolete)
Comment 9 Wenson Hsieh 2020-05-26 10:38:28 PDT Comment hidden (obsolete)
Comment 10 Wenson Hsieh 2020-05-26 10:39:09 PDT Comment hidden (obsolete)
Comment 11 Wenson Hsieh 2020-05-27 10:01:27 PDT Comment hidden (obsolete)
Comment 12 Wenson Hsieh 2020-05-27 10:27:37 PDT Comment hidden (obsolete)
Comment 13 Wenson Hsieh 2020-05-27 11:19:56 PDT Comment hidden (obsolete)
Comment 14 Wenson Hsieh 2020-05-27 15:00:54 PDT Comment hidden (obsolete)
Comment 15 Wenson Hsieh 2020-05-28 11:19:12 PDT Comment hidden (obsolete)
Comment 16 Wenson Hsieh 2020-05-28 12:57:12 PDT Comment hidden (obsolete)
Comment 17 Wenson Hsieh 2020-05-28 14:16:14 PDT
(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!)
Comment 18 Wenson Hsieh 2020-05-28 16:37:27 PDT Comment hidden (obsolete)
Comment 19 Wenson Hsieh 2020-05-28 21:01:46 PDT
(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...
Comment 20 Wenson Hsieh 2020-05-28 22:12:50 PDT Comment hidden (obsolete)
Comment 21 Wenson Hsieh 2020-05-28 22:41:09 PDT
Created attachment 400551 [details]
Patch for EWS
Comment 22 EWS 2020-05-29 00:27:08 PDT
Committed r262283: <https://trac.webkit.org/changeset/262283>

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