1807868 - Intermittent /webdriver/tests/classic/new_window/new_tab.py | test_focus_content - AssertionError: assert 'false' == 'true'

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=400926980&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/I5WAS7vLSHmej3S73lQJkQ/runs/0/artifacts/public/logs/live_backing.log

---

INFO - TEST-PASS | /webdriver/tests/new_window/new_tab.py | test_sets_no_opener 
[task 2022-12-28T23:03:22.940Z] 23:03:22     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/new_window/new_tab.py | test_focus_content - AssertionError: assert 'false' == 'true'
[task 2022-12-28T23:03:22.940Z] 23:03:22     INFO - session = <Session edcaa7e8-4b29-4a85-95a1-6ec4c247d4eb>
[task 2022-12-28T23:03:22.940Z] 23:03:22     INFO - inline = <function inline.<locals>.inline at 0x7fdac805bae8>
[task 2022-12-28T23:03:22.940Z] 23:03:22     INFO - 
[task 2022-12-28T23:03:22.940Z] 23:03:22     INFO -     def test_focus_content(session, inline):
[task 2022-12-28T23:03:22.940Z] 23:03:22     INFO -         response = new_window(session, type_hint="tab")
[task 2022-12-28T23:03:22.941Z] 23:03:22     INFO -         value = assert_success(response)
[task 2022-12-28T23:03:22.941Z] 23:03:22     INFO -         assert value["type"] == "tab"
[task 2022-12-28T23:03:22.941Z] 23:03:22     INFO -     
[task 2022-12-28T23:03:22.941Z] 23:03:22     INFO -         session.window_handle = value["handle"]
[task 2022-12-28T23:03:22.941Z] 23:03:22     INFO -     
[task 2022-12-28T23:03:22.941Z] 23:03:22     INFO -         session.url = inline("""
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -             <span contenteditable="true"> abc </span>
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -             <script>
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                 const selection = getSelection();
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                 window.onload = async() => {
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                     const initial = document.querySelector("span");
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                     initial.focus();
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                     initial.setAttribute(
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                         "_focused",
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                         selection.anchorNode == initial.firstChild
[task 2022-12-28T23:03:22.942Z] 23:03:22     INFO -                     );
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO -                 }
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO -             </script>
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO -         """)
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO -     
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO -         elem = session.find.css("span", all=False)
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO - >       assert elem.attribute("_focused") == "true"
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO - E       AssertionError: assert 'false' == 'true'
[task 2022-12-28T23:03:22.943Z] 23:03:22     INFO - E         - true
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - E         + false
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - 
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - elem       = <Element 7dc31b70-9491-4a01-bad5-d4fdf79aeab4>
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - inline     = <function inline.<locals>.inline at 0x7fdac805bae8>
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - response   = <[ValueError('Sign not allowed in string format specifier',) raised in repr()] Response object at 0x7fdac82c9ef0>
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - session    = <Session edcaa7e8-4b29-4a85-95a1-6ec4c247d4eb>
INFO - value      = {'handle': '11d7b29d-6402-4e3d-9048-b2228668b040', 'type': 'tab'}
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - 
[task 2022-12-28T23:03:22.944Z] 23:03:22     INFO - tests/web-platform/tests/webdriver/tests/new_window/new_tab.py:89: AssertionError
[task 2022-12-28T23:03:22.945Z] 23:03:22     INFO - TEST-OK | /webdriver/tests/new_window/new_tab.py | took 10430ms

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This kind of failure should have basically fixed with my patch on bug 1798655. But maybe only calling this.contentBrowser?.focus(); doesn't seem to be enough and especially for slow builds it might take some time to actually set the focus to the given tab's browser.

It happened once so far for a ccov build. Lets observe for now.

Comment 2

[Intermittent Failures Robot]

1 failures in 1328 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2022-12-26&endday=2023-01-01&tree=all

Comment 3

[Intermittent Failures Robot]

1 failures in 2607 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-01-02&endday=2023-01-08&tree=all

Comment 4

[Intermittent Failures Robot]

1 failures in 3717 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-01-16&endday=2023-01-22&tree=all

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 6

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.

Comment 7

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=421310469&repo=mozilla-central

Comment 8

[Intermittent Failures Robot]

1 failures in 3594 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-06-26&endday=2023-07-02&tree=all

Comment 9

[Intermittent Failures Robot]

2 failures in 3309 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1
• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-07-10&endday=2023-07-16&tree=all

Comment 10

[Intermittent Failures Robot]

1 failures in 3341 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-08-07&endday=2023-08-13&tree=all

Comment 11

[Intermittent Failures Robot]

1 failures in 2218 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-08-21&endday=2023-08-27&tree=all

Comment 12

[Intermittent Failures Robot]

1 failures in 3337 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-09-11&endday=2023-09-17&tree=all

Comment 13

[Intermittent Failures Robot]

1 failures in 3764 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-10-09&endday=2023-10-15&tree=all

Comment 14

[Intermittent Failures Robot]

1 failures in 4108 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-11-27&endday=2023-12-03&tree=all

Comment 15

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Comment 16

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=441814817&repo=mozilla-central

Comment 17

[Intermittent Failures Robot]

1 failures in 1162 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2023-12-25&endday=2023-12-31&tree=all

Comment 18

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Comment 19

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=447151039&repo=mozilla-central

Comment 20

[Intermittent Failures Robot]

1 failures in 3125 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2024-02-12&endday=2024-02-18&tree=all

Comment 21

[Sandor Molnar[:smolnar]]

@Henrik, these WD failures have started since Bug 1877469 has landed here and it shows a high frequency rate. (12 failures since yesterday
Could you take a look?

Comment 22

[Intermittent Failures Robot]

18 failures in 142 pushes (0.127 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 9
• mozilla-central: 8
• try: 1

Platform and build breakdown:

• linux1804-64-qr: 5
  • debug: 3
  • opt: 2
• linux1804-64-shippable-qr: 2
  • opt: 2
• windows11-32-2009-qr: 2
  • opt: 2
• linux1804-64-asan-qr: 4
  • opt: 4
• windows11-64-2009-shippable-qr: 3
  • opt: 3
• windows11-64-2009-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2024-03-09&endday=2024-03-09&tree=all

Comment 23

[Intermittent Failures Robot]

29 failures in 4198 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 14
• mozilla-central: 14
• try: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 10
  • opt: 10
• linux1804-64-qr: 6
  • debug: 4
  • opt: 2
• windows11-32-2009-qr: 2
  • opt: 2
• linux1804-64-shippable-qr: 4
  • opt: 4
• windows11-64-2009-shippable-qr: 3
  • opt: 3
• windows11-64-2009-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1
• linux1804-64-ccov-qr: 1
  • opt: 1
• windows11-32-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2024-03-04&endday=2024-03-10&tree=all

Comment 24

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Sandor Molnar[:smolnar] from comment #21)

@Henrik, these WD failures have started since Bug 1877469 has landed here and it shows a high frequency rate. (12 failures since yesterday
Could you take a look?

Interesting. It shouldn't cause an issue with WebDriver classic (Marionette) because the patch was only intended for WebDriver BiDi (Remote Agent). But it looks like that there might have been a side-effect. I'll use bug 1879260 to implement the correct waiting for Marionette as well, which should then fix this intermittent failure.

Comment 25

[Intermittent Failures Robot]

15 failures in 767 pushes (0.02 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 9
• mozilla-central: 2
• try: 4

Platform and build breakdown:

• windows11-64-2009-qr: 2
  • opt: 2
• linux1804-64-ccov-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1
• windows11-64-2009-shippable-qr: 1
  • opt: 1
• linux1804-64-asan-qr: 6
  • opt: 6
• linux1804-64-qr: 3
  • debug: 2
  • opt: 1
• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2024-03-11&endday=2024-03-11&tree=all

Comment 26

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The test actually sets the _focused attribute on the element within a callback for onload. Surprisingly this callback is defined as async whereby no async code is run. Not sure if that makes a difference but lets see if removing that keyword makes it better.

Here a try build with the async keyword in place but wrapping the assertion in a try/finally to further wait until the attribute is set:
https://treeherder.mozilla.org/jobs?repo=try&revision=31cde9c39dbe7eb21278f45a8b4e07c54849918e

Another try build like the above but with async removed:
https://treeherder.mozilla.org/jobs?repo=try&revision=e35495961a33cbfd8e313c8f7351e3de7bb349b5

Comment 27

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The test is most likely flaky. As such I cannot see how a fix for bug 1879260 can help here.

Comment 28

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1877469

Comment 29

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So the problematic test here is the following:
https://searchfox.org/mozilla-central/rev/f9157a03835653cd3ece8d2dc713a782b7e4374e/testing/web-platform/tests/webdriver/tests/classic/new_window/new_tab.py#66-89

We create a new tab, switch to it and then focus the contenteditable span element within the onload callback. In some cases the selection's anchorNode isn't equal to the span element first child.

This all happens since we set the preference browser.tabs.remote.unloadDelayMs to 0 for the Remote Agent protocols (including Marionette).

Mike could it be that in some cases the content browser doesn't have the focus yet when the onload code is run in the new tab? Might the async tab switcher code have some side-effects for the tab just switched to? I'm not able to reproduce at all locally on different platforms and build types so I'm asking in case you have something in mind. Thanks.

Comment 30

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1877469

Comment 31

[Intermittent Failures Robot]

21 failures in 738 pushes (0.028 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 15
• mozilla-central: 2
• try: 4

Platform and build breakdown:

• linux1804-64-asan-qr: 5
  • opt: 5
• macosx1015-64-qr: 1
  • opt: 1
• windows11-32-2009-qr: 3
  • opt: 3
• windows11-64-2009-qr: 3
  • opt: 3
• windows11-64-2009-shippable-qr: 1
  • opt: 1
• windows11-32-2009-shippable-qr: 1
  • opt: 1
• linux1804-64-devedition-qr: 1
  • opt: 1
• linux1804-64-qr: 4
  • debug: 1
  • opt: 3
• linux1804-64-shippable-qr: 1
  • opt: 1
• linux1804-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2024-03-12&endday=2024-03-12&tree=all

Comment 32

[Henrik Skupin [:whimboo][⌚️UTC+2]]

It's indeed related to the value of the preference browser.tabs.remote.unloadDelayMs. While150ms still works fine and doesn't show the problem, I can see a failure on my Windows Surface after a couple of test repetitions when using 125. Note that I haven't bisected the value further for now. Maybe that might ring a bell?

As next step I would check the JS code that we are using what's actually different in case of a failure.

Comment 33

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Bug 1807868 - [wdspec] Fix /webdriver/tests/classic/new_window/new_tab.py | test_focus_content.

Depends on D163946

Comment 34

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Bug 1807868 - [marionette] Unload previously selected tab immediately.

Depends on D204698

Comment 35

[Henrik Skupin [:whimboo][⌚️UTC+2]]

As discussed with Olli we should wait for the selectionchange event to be fired to be sure that we actually have a valid selection. With the immediate visibilitystate update now we might end-up in a race now.

The patches as attached work fine on my local machine now.

Comment 36

[Intermittent Failures Robot]

16 failures in 761 pushes (0.021 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 8
• mozilla-central: 6
• try: 2

Platform and build breakdown:

• windows11-64-2009-qr: 2
  • opt: 2
• linux1804-64-shippable-qr: 2
  • opt: 2
• macosx1015-64-qr: 2
  • debug: 1
  • opt: 1
• linux1804-64-asan-qr: 3
  • opt: 3
• linux1804-64-qr: 4
  • debug: 2
  • opt: 2
• windows11-64-2009-shippable-qr: 1
  • opt: 1
• windows11-32-2009-shippable-qr: 1
  • opt: 1
• linux1804-64-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2024-03-14&endday=2024-03-14&tree=all

Comment 37

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e16d9cb7c4a9
[wdspec] Fix /webdriver/tests/classic/new_window/new_tab.py | test_focus_content. r=webdriver-reviewers,jdescottes
https://hg.mozilla.org/integration/autoland/rev/4f052355c8a2
[marionette] Unload previously selected tab immediately. r=webdriver-reviewers,jdescottes

Comment 38

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/45121 for changes under testing/web-platform/tests

Comment 39

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/e16d9cb7c4a9
https://hg.mozilla.org/mozilla-central/rev/4f052355c8a2

Comment 40

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR merged by moz-wptsync-bot

Comment 41

[Intermittent Failures Robot]

72 failures in 3849 pushes (0.019 failures/push) were associated with this bug in the last 7 days.

This is the #5 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 46
• mozilla-central: 11
• try: 15

Platform and build breakdown:

• windows11-64-2009-qr: 9
  • opt: 9
• linux1804-64-ccov-qr: 2
  • opt: 2
• linux1804-64-qr: 13
  • debug: 5
  • opt: 8
• linux1804-64-asan-qr: 18
  • opt: 18
• linux1804-64-shippable-qr: 7
  • opt: 7
• windows11-64-2009-shippable-qr: 4
  • opt: 4
• windows11-32-2009-qr: 8
  • opt: 8
• macosx1015-64-qr: 5
  • opt: 4
  • debug: 1
• windows11-32-2009-shippable-qr: 2
  • opt: 2
• linux1804-64-devedition-qr: 3
  • opt: 3
• windows11-64-2009-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1807868&startday=2024-03-11&endday=2024-03-17&tree=all