Closed Bug 1807868 Opened 1 year ago Closed 13 days ago

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

Categories

(Remote Protocol :: Marionette, defect, P5)

defect
Points:
3

Tracking

(firefox-esr115 unaffected, firefox123 unaffected, firefox124 unaffected, firefox125 fixed)

RESOLVED FIXED
125 Branch
Tracking Status
firefox-esr115 --- unaffected
firefox123 --- unaffected
firefox124 --- unaffected
firefox125 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

(Regression)

Details

(Keywords: assertion, intermittent-failure, regression, Whiteboard: [webdriver:m10], [wptsync upstream])

Attachments

(2 files)

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

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.

Depends on: 1798655
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago3 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 months ago1 month ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

@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?

Flags: needinfo?(hskupin)

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

Depends on: 1879260
Flags: needinfo?(hskupin)
Summary: Intermittent /webdriver/tests/new_window/new_tab.py | test_focus_content - AssertionError: assert 'false' == 'true' → Intermittent /webdriver/tests/classic/new_window/new_tab.py | test_focus_content - AssertionError: assert 'false' == 'true'

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

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

No longer depends on: 1879260
Keywords: regression
Regressed by: 1877469

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

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.

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

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.

Assignee: nobody → hskupin

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.

Assignee: hskupin → nobody
Flags: needinfo?(mconley)
Assignee: nobody → hskupin
Status: REOPENED → ASSIGNED
Whiteboard: [webdriver:m10]
Points: --- → 3
Pushed by hskupin@mozilla.com:
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
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/45121 for changes under testing/web-platform/tests
Whiteboard: [webdriver:m10] → [webdriver:m10], [wptsync upstream]
Status: ASSIGNED → RESOLVED
Closed: 1 month ago13 days ago
Resolution: --- → FIXED
Target Milestone: --- → 125 Branch
Upstream PR merged by moz-wptsync-bot
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: