Bug 214688 - REGRESSION (r264690): [ iOS wk2 ] editing/selection/shift-click-includes-existing-selection.html is a flaky failure
Summary: REGRESSION (r264690): [ iOS wk2 ] editing/selection/shift-click-includes-exis...
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: Wenson Hsieh
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2020-07-23 08:42 PDT by Karl Rackler
Modified: 2020-07-26 12:25 PDT (History)
7 users (show)

See Also:


Attachments
Data collection (1.57 MB, patch)
2020-07-24 13:47 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (589.78 KB, patch)
2020-07-24 13:56 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (2) (2.85 MB, patch)
2020-07-24 14:32 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (3) (2.85 MB, patch)
2020-07-24 14:33 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (4) (2.85 MB, patch)
2020-07-24 14:33 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (5) (2.85 MB, patch)
2020-07-24 14:34 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (6) (2.85 MB, patch)
2020-07-24 14:35 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (7) (2.85 MB, patch)
2020-07-24 14:36 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (8) (2.85 MB, patch)
2020-07-24 14:36 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (9) (2.85 MB, patch)
2020-07-24 14:36 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (10) (2.85 MB, patch)
2020-07-24 14:37 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Data collection (11) (2.85 MB, patch)
2020-07-24 14:38 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Speculative fix? (1.97 KB, patch)
2020-07-24 15:42 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Test another theory (6.32 KB, patch)
2020-07-24 20:11 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Speculative fix #2 (3.95 KB, patch)
2020-07-25 12:29 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Test yet another theory (8.25 KB, patch)
2020-07-25 16:33 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Test yet another theory (13.01 KB, patch)
2020-07-25 16:41 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Test yet another theory (14.16 KB, patch)
2020-07-26 00:26 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff
Speculative fix #3 (24.43 KB, patch)
2020-07-26 11:18 PDT, Wenson Hsieh
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Karl Rackler 2020-07-23 08:42:39 PDT
Description:
editing/selection/shift-click-includes-existing-selection.html

This appears to have started after https://trac.webkit.org/changeset/264690/webkit .

History:
https://results.webkit.org/?suite=layout-tests&test=editing%2Fselection%2Fshift-click-includes-existing-selection.html&platform=ios&flavor=wk2&style=release&limit=50000

Diff:
--- /Volumes/Data/slave/ipados-simulator-13-release-tests-wk2/build/layout-test-results/editing/selection/shift-click-includes-existing-selection-expected.txt
+++ /Volumes/Data/slave/ipados-simulator-13-release-tests-wk2/build/layout-test-results/editing/selection/shift-click-includes-existing-selection-actual.txt
@@ -24,13 +24,13 @@
 |   "The quick brown fox jumped over the "
 |   <span>
 |     id="start"
-|     "<#selection-anchor>lazy dog."
+|     "lazy dog."
 | "
     "
 | <p>
 |   <span>
 |     id="end"
-|     "T<#selection-focus>"
+|     "<#selection-caret>T"
 |   "he quick brown fox jumped over the lazy dog."
 | "
 "
Comment 1 Radar WebKit Bug Importer 2020-07-23 08:43:16 PDT
<rdar://problem/65993683>
Comment 2 Karl Rackler 2020-07-23 08:50:36 PDT
I have marked these tests as failing while this issue is investigated.
https://trac.webkit.org/changeset/264765/webkit
Comment 3 Wenson Hsieh 2020-07-24 09:04:26 PDT
I haven’t been able to reproduce the text diff result at all locally, but I am observing a flaky timeout locally when running the test back-to-back for many iterations.
Comment 4 Wenson Hsieh 2020-07-24 13:47:07 PDT Comment hidden (obsolete)
Comment 5 Wenson Hsieh 2020-07-24 13:56:52 PDT Comment hidden (obsolete)
Comment 6 Wenson Hsieh 2020-07-24 14:32:23 PDT
Created attachment 405175 [details]
Data collection (2)
Comment 7 Wenson Hsieh 2020-07-24 14:33:03 PDT
Created attachment 405176 [details]
Data collection (3)
Comment 8 Wenson Hsieh 2020-07-24 14:33:47 PDT
Created attachment 405177 [details]
Data collection (4)
Comment 9 Wenson Hsieh 2020-07-24 14:34:33 PDT
Created attachment 405178 [details]
Data collection (5)
Comment 10 Wenson Hsieh 2020-07-24 14:35:52 PDT
Created attachment 405179 [details]
Data collection (6)
Comment 11 Wenson Hsieh 2020-07-24 14:36:34 PDT
Created attachment 405180 [details]
Data collection (7)
Comment 12 Wenson Hsieh 2020-07-24 14:36:44 PDT
Created attachment 405181 [details]
Data collection (8)
Comment 13 Wenson Hsieh 2020-07-24 14:36:54 PDT
Created attachment 405182 [details]
Data collection (9)
Comment 14 Wenson Hsieh 2020-07-24 14:37:03 PDT
Created attachment 405183 [details]
Data collection (10)
Comment 15 Wenson Hsieh 2020-07-24 14:38:19 PDT
Created attachment 405184 [details]
Data collection (11)
Comment 16 Wenson Hsieh 2020-07-24 15:42:10 PDT
Created attachment 405192 [details]
Speculative fix?
Comment 17 Darin Adler 2020-07-24 15:52:43 PDT
Comment on attachment 405192 [details]
Speculative fix?

If it works, consider it reviewed.
Comment 18 Wenson Hsieh 2020-07-24 15:57:58 PDT
(In reply to Darin Adler from comment #17)
> Comment on attachment 405192 [details]
> Speculative fix?
> 
> If it works, consider it reviewed.

Thanks for taking a look!

Unfortunately, this is speculative at best, as it seems EWS is also unable to reproduce this failure. I’ve also been unable to reproduce it locally, both when running the test for 1000s of iterations in isolation, and when running all the tests in the same directory for 100s of iterations.

However, I *have* been able to reproduce a flaky timeout locally, whose root cause is described in this fix. I’m really hoping that this timeout I’ve observed locally is (somehow) the same issue as what the post-commit bots are seeing (both internal and non-internal), and that this fix will address what Karl and the other bot-watchers observed :/
Comment 19 EWS 2020-07-24 16:18:25 PDT
Committed r264868: <https://trac.webkit.org/changeset/264868>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 405192 [details].
Comment 20 Wenson Hsieh 2020-07-24 19:18:45 PDT
(In reply to Wenson Hsieh from comment #18)
> (In reply to Darin Adler from comment #17)
> > Comment on attachment 405192 [details]
> > Speculative fix?
> > 
> > If it works, consider it reviewed.
> 
> Thanks for taking a look!
> 
> Unfortunately, this is speculative at best, as it seems EWS is also unable
> to reproduce this failure. I’ve also been unable to reproduce it locally,
> both when running the test for 1000s of iterations in isolation, and when
> running all the tests in the same directory for 100s of iterations.
> 
> However, I *have* been able to reproduce a flaky timeout locally, whose root
> cause is described in this fix. I’m really hoping that this timeout I’ve
> observed locally is (somehow) the same issue as what the post-commit bots
> are seeing (both internal and non-internal), and that this fix will address
> what Karl and the other bot-watchers observed :/

<https://build.webkit.org/builders/Apple%20iOS%2013%20Simulator%20Release%20WK2%20%28Tests%29/builds/5859/steps/layout-test/logs/stdio> shows a text diff, so I don’t think this speculative fix worked (though, it is needed anyways in order to fix the rare timeout for this test).

It’s very unfortunate that the above EWS runs ran the test 9000 times with 0 failures. I think the only way to proceed is to check in temporary debug logging for post-commit automation to run, until we can gather enough information for a second speculative fix.
Comment 21 Wenson Hsieh 2020-07-24 19:19:16 PDT
Reopening.
Comment 22 Wenson Hsieh 2020-07-24 20:11:07 PDT
Created attachment 405218 [details]
Test another theory
Comment 23 EWS 2020-07-24 20:52:52 PDT
Committed r264882: <https://trac.webkit.org/changeset/264882>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 405218 [details].
Comment 24 Wenson Hsieh 2020-07-24 20:53:38 PDT
(Reopening, because the last patch just adds logging).
Comment 25 Wenson Hsieh 2020-07-25 12:29:35 PDT
Created attachment 405231 [details]
Speculative fix #2
Comment 26 EWS 2020-07-25 13:02:28 PDT
Committed r264890: <https://trac.webkit.org/changeset/264890>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 405231 [details].
Comment 27 Wenson Hsieh 2020-07-25 15:46:46 PDT
(In reply to EWS from comment #26)
> Committed r264890: <https://trac.webkit.org/changeset/264890>
> 
> All reviewed patches have been landed. Closing bug and clearing flags on
> attachment 405231 [details].

Still not enough to fix this :(

From https://build.webkit.org/builders/Apple%20iPadOS%2013%20Simulator%20Release%20WK2%20%28Tests%29/builds/4109/steps/layout-test/logs/stdio...

> 14:57:30.770 78653 worker/9 editing/selection/shift-click-includes-existing-selection.html output stderr lines:
> 14:57:30.770 78653   Synthesizing modifier keydown events.
> 14:57:30.770 78653   Synthesizing tap.
> 14:57:30.771 78653   -[WKContentView(WKInteraction) _singleTapIdentified:] - modifier flags: 0x00
> 14:57:30.771 78653   -[WKContentView(WKInteraction) _singleTapRecognized:] - modifier flags: 0x00
> 14:57:30.771 78653   Committing potential tap with modifiers: 0x00
> 14:57:30.771 78653   Handling synthetic click at (16, 223) with modifiers: 0x00
> 14:57:30.771 78653   Synthesizing modifier keyup events.
> 14:57:31.269 78653 "ruby -I /Volumes/Data/slave/ipados-simulator-13-release-tests-wk2/build/Websites/bugs.webkit.org/PrettyPatch /Volumes/Data/slave/ipados-simulator-13-release-tests-wk2/build/Websites/bugs.webkit.org/PrettyPatch/prettify.rb /Volumes/Data/slave/ipados-simulator-13-release-tests-wk2/build/layout-test-results/editing/selection/shift-click-includes-existing-selection-diff.txt" took 0.50s
> 14:57:31.272 78653 worker/9 editing/selection/shift-click-includes-existing-selection.html failed:
> 14:57:31.272 78653 worker/9  text diff
Comment 28 Wenson Hsieh 2020-07-25 16:33:08 PDT Comment hidden (obsolete)
Comment 29 Wenson Hsieh 2020-07-25 16:41:12 PDT
Created attachment 405235 [details]
Test yet another theory
Comment 30 EWS 2020-07-25 17:39:50 PDT
Committed r264892: <https://trac.webkit.org/changeset/264892>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 405235 [details].
Comment 31 Wenson Hsieh 2020-07-25 17:50:46 PDT
(Reopening, because the last patch just added logging)
Comment 32 Wenson Hsieh 2020-07-25 19:51:44 PDT
Example of a pass (from https://build.webkit.org/builders/Apple%20iOS%2013%20Simulator%20Debug%20WK2%20%28Tests%29/builds/4858/steps/layout-test/logs/stdio):

> 18:12:26.062 14700 worker/8 editing/selection/shift-click-includes-existing-selection.html output stderr lines:
> 18:12:26.062 14700   Synthesizing modifier keydown events.
> 18:12:26.062 14700   Synthesizing tap.
> 18:12:26.062 14700   (Before): keyboard 0x6000038903c0 has modifier state: 0x00
> 18:12:26.062 14700   (After): keyboard 0x6000038903c0 has modifier state: 0x20000
> 18:12:26.062 14700   -[WKContentView(WKInteraction) _singleTapIdentified:] - modifier flags: 0x20000
> 18:12:26.062 14700   -[WKContentView(WKInteraction) _singleTapRecognized:] - modifier flags: 0x20000
> 18:12:26.062 14700   Committing potential tap with modifiers: 0x01
> 18:12:26.062 14700   Synthesizing modifier keyup events.
> 18:12:26.062 14700   Handling synthetic click at (16, 307) with modifiers: 0x01
> 18:12:26.063 14700   (Before): keyboard 0x6000038903c0 has modifier state: 0x20000
> 18:12:26.063 14700   (After): keyboard 0x6000038903c0 has modifier state: 0x00

Example of a text diff failure (from: https://build.webkit.org/builders/Apple%20iOS%2013%20Simulator%20Release%20WK2%20%28Tests%29/builds/5870/steps/layout-test/logs/stdio):

> 18:10:48.267 87902 worker/0 editing/selection/shift-click-includes-existing-selection.html output stderr lines:
> 18:10:48.267 87902   Synthesizing modifier keydown events.
> 18:10:48.267 87902   Synthesizing tap.
> 18:10:48.267 87902   (Before): keyboard 0x600002008500 has modifier state: 0x00
> 18:10:48.267 87902   (After): keyboard 0x60000201c460 has modifier state: 0x00
> 18:10:48.267 87902   -[WKContentView(WKInteraction) _singleTapIdentified:] - modifier flags: 0x00
> 18:10:48.267 87902   -[WKContentView(WKInteraction) _singleTapRecognized:] - modifier flags: 0x00
> 18:10:48.268 87902   Committing potential tap with modifiers: 0x00
> 18:10:48.268 87902   Handling synthetic click at (16, 307) with modifiers: 0x00
> 18:10:48.268 87902   Synthesizing modifier keyup events.
> 18:10:48.268 87902   (Before): keyboard 0x60000201c460 has modifier state: 0x00
> 18:10:48.268 87902   (After): keyboard 0x60000201c460 has modifier state: 0x00
> 18:10:48.723 87902 "ruby -I /Volumes/Data/slave/ios-simulator-13-release-tests-wk2/build/Websites/bugs.webkit.org/PrettyPatch /Volumes/Data/slave/ios-simulator-13-release-tests-wk2/build/Websites/bugs.webkit.org/PrettyPatch/prettify.rb /Volumes/Data/slave/ios-simulator-13-release-tests-wk2/build/layout-test-results/editing/selection/shift-click-includes-existing-selection-diff.txt" took 0.45s
> 18:10:48.725 87902 worker/0 editing/selection/shift-click-includes-existing-selection.html failed:
> 18:10:48.725 87902 worker/0  text diff

It’s possible that the smoking gun is the fact that the UIApplication’s GSKeyboardRef changes while (or perhaps, as a result of) dispatching the modifier keydown:

In the failure case,
18:10:48.267 87902   (Before): keyboard 0x600002008500 has modifier state: 0x00
18:10:48.267 87902   (After): keyboard 0x60000201c460 has modifier state: 0x00

Versus this, in the success case:
18:12:26.062 14700   (Before): keyboard 0x6000038903c0 has modifier state: 0x00
18:12:26.062 14700   (After): keyboard 0x6000038903c0 has modifier state: 0x20000

Needs more GraphicsServices spelunking (and more datapoints) to see whether this is the culprit.
Comment 33 Wenson Hsieh 2020-07-26 00:26:27 PDT
Created attachment 405246 [details]
Test yet another theory
Comment 34 EWS 2020-07-26 01:17:36 PDT
Committed r264896: <https://trac.webkit.org/changeset/264896>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 405246 [details].
Comment 35 Wenson Hsieh 2020-07-26 09:42:19 PDT
(Reopening, because the last patch just added logging)
Comment 36 Wenson Hsieh 2020-07-26 10:19:38 PDT
From https://build.webkit.org/builders/Apple%20iOS%2013%20Simulator%20Release%20WK2%20%28Tests%29/builds/5875/steps/layout-test/logs/stdio (with the logging added in r264896):

> 09:06:26.094 84334 worker/4 editing/selection/shift-click-includes-existing-selection.html output stderr lines:
> 09:06:26.094 84334   Synthesizing modifier keydown events.
> 09:06:26.094 84334   Synthesizing tap.
> 09:06:26.094 84334   (Before): keyboard 0x60000089c320 has modifier state: 0x00; layout:Hebrew; type: 0
> 09:06:26.094 84334   (After): keyboard 0x600000894320 has modifier state: 0x00; layout:US; type: 0
> 09:06:26.094 84334   -[WKContentView(WKInteraction) _singleTapIdentified:] - modifier flags: 0x00
> 09:06:26.094 84334   -[WKContentView(WKInteraction) _singleTapRecognized:] - modifier flags: 0x00
> 09:06:26.094 84334   Committing potential tap with modifiers: 0x00
> 09:06:26.094 84334   Handling synthetic click at (16, 307) with modifiers: 0x00
> 09:06:26.094 84334   Synthesizing modifier keyup events.
> 09:06:26.095 84334   (Before): keyboard 0x600000894320 has modifier state: 0x00; layout:US; type: 0
> 09:06:26.095 84334   (After): keyboard 0x600000894320 has modifier state: 0x00; layout:US; type: 0

The Hebrew => US keyboard change that happens in the middle of handling the keydown certainly seems suspect.
Comment 37 Wenson Hsieh 2020-07-26 11:18:50 PDT
Created attachment 405254 [details]
Speculative fix #3
Comment 38 Wenson Hsieh 2020-07-26 12:18:37 PDT
Comment on attachment 405254 [details]
Speculative fix #3

Thanks for the review!

Hopefully, this’ll fix it for good.
Comment 39 EWS 2020-07-26 12:25:33 PDT
Committed r264907: <https://trac.webkit.org/changeset/264907>

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