Bug 214688 – REGRESSION (r264690): [ iOS wk2 ] editing/selection/shift-click-includes-existing-selection.html is a flaky failure

• Component: New Bugs
• Status: RESOLVED FIXED

[Karl Rackler]

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."
 | "
 "

[Radar WebKit Bug Importer]

<rdar://problem/65993683>

[Karl Rackler]

I have marked these tests as failing while this issue is investigated.
https://trac.webkit.org/changeset/264765/webkit

[Wenson Hsieh]

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.

[Wenson Hsieh]

Created attachment 405171 [details]
Data collection

[Wenson Hsieh]

Created attachment 405172 [details]
Data collection

[Wenson Hsieh]

Created attachment 405175 [details]
Data collection (2)

[Wenson Hsieh]

Created attachment 405176 [details]
Data collection (3)

[Wenson Hsieh]

Created attachment 405177 [details]
Data collection (4)

[Wenson Hsieh]

Created attachment 405178 [details]
Data collection (5)

[Wenson Hsieh]

Created attachment 405179 [details]
Data collection (6)

[Wenson Hsieh]

Created attachment 405180 [details]
Data collection (7)

[Wenson Hsieh]

Created attachment 405181 [details]
Data collection (8)

[Wenson Hsieh]

Created attachment 405182 [details]
Data collection (9)

[Wenson Hsieh]

Created attachment 405183 [details]
Data collection (10)

[Wenson Hsieh]

Created attachment 405184 [details]
Data collection (11)

[Wenson Hsieh]

Created attachment 405192 [details]
Speculative fix?

[Darin Adler]

Comment on attachment 405192 [details]
Speculative fix?

If it works, consider it reviewed.

[Wenson Hsieh]

(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 :/

[EWS]

Committed r264868: <https://trac.webkit.org/changeset/264868>

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

[Wenson Hsieh]

(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.

[Wenson Hsieh]

Reopening.

[Wenson Hsieh]

Created attachment 405218 [details]
Test another theory

[EWS]

Committed r264882: <https://trac.webkit.org/changeset/264882>

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

[Wenson Hsieh]

(Reopening, because the last patch just adds logging).

[Wenson Hsieh]

Created attachment 405231 [details]
Speculative fix #2

[EWS]

Committed r264890: <https://trac.webkit.org/changeset/264890>

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

[Wenson Hsieh]

(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

[Wenson Hsieh]

Created attachment 405234 [details]
Test yet another theory

[Wenson Hsieh]

Created attachment 405235 [details]
Test yet another theory

[EWS]

Committed r264892: <https://trac.webkit.org/changeset/264892>

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

[Wenson Hsieh]

(Reopening, because the last patch just added logging)

[Wenson Hsieh]

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.

[Wenson Hsieh]

Created attachment 405246 [details]
Test yet another theory

[EWS]

Committed r264896: <https://trac.webkit.org/changeset/264896>

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

[Wenson Hsieh]

(Reopening, because the last patch just added logging)

[Wenson Hsieh]

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.

[Wenson Hsieh]

Created attachment 405254 [details]
Speculative fix #3

[Wenson Hsieh]

Comment on attachment 405254 [details]
Speculative fix #3

Thanks for the review!

Hopefully, this’ll fix it for good.

[EWS]

Committed r264907: <https://trac.webkit.org/changeset/264907>

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