Closed Bug 1661591 Opened 4 years ago Closed 3 years ago

Intermittent /webdriver/tests/get_title/get.py | test_after_modification - AssertionError: assert 'Initial' == 'Updated'

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Type:
defect

Tracking

(Fission Milestone:Future, firefox-esr78 unaffected, firefox81 unaffected, firefox82 wontfix, firefox84 wontfix, firefox85 wontfix, firefox86 wontfix, firefox88 wontfix, firefox89 wontfix, firefox90 fixed)

Status:
RESOLVED FIXED
Milestone:
90 Branch
Project Flags:
Fission Milestone Future
Tracking Flags:
Tracking Status
firefox-esr78 --- unaffected
firefox81 --- unaffected
firefox82 --- wontfix
firefox84 --- wontfix
firefox85 --- wontfix
firefox86 --- wontfix
firefox88 --- wontfix
firefox89 --- wontfix
firefox90 --- fixed

People

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

References

(Regression)

Details

(Keywords: assertion, intermittent-failure, regression, Whiteboard: [marionette-fission-reserve])

Attachments

(1 file)

Bug 1661591 - [marionette] Inform the main thread when command in child actor has been completed.
48 bytes, text/x-phabricator-request
Details | Review

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=314218815&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/cYZ_BRZdS7-CdOLQSWHsZQ/runs/0/artifacts/public/logs/live_backing.log

[task 2020-08-27T21:54:33.951Z] 21:54:33 INFO - TEST-PASS | /webdriver/tests/get_title/get.py | test_without_title
[task 2020-08-27T21:54:33.952Z] 21:54:33 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/get_title/get.py | test_after_modification - AssertionError: assert 'Initial' == 'Updated'
[task 2020-08-27T21:54:33.952Z] 21:54:33 INFO - session = <Session e4f783bb-f87a-4412-88f2-383ab86506c0>
[task 2020-08-27T21:54:33.952Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.952Z] 21:54:33 INFO - def test_after_modification(session):
[task 2020-08-27T21:54:33.952Z] 21:54:33 INFO - session.url = inline("<title>Initial</title><h2>Hello</h2>")
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO - session.execute_script("document.title = 'Updated'")
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO - result = get_title(session)
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO - > assert_success(result, "Updated")
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO - result = <Responsetatus=200 body={"value": "Initial"}>
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO - session = <Session e4f783bb-f87a-4412-88f2-383ab86506c0>
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.953Z] 21:54:33 INFO - tests/web-platform/tests/webdriver/tests/get_title/get.py:44:
[task 2020-08-27T21:54:33.954Z] 21:54:33 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2020-08-27T21:54:33.954Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.954Z] 21:54:33 INFO - response = <Responsetatus=200 body={"value": "Initial"}>, value = 'Updated'
[task 2020-08-27T21:54:33.954Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.954Z] 21:54:33 INFO - def assert_success(response, value=None):
[task 2020-08-27T21:54:33.954Z] 21:54:33 INFO - """
[task 2020-08-27T21:54:33.955Z] 21:54:33 INFO - Verify that the provided webdriver.Response instance described
[task 2020-08-27T21:54:33.955Z] 21:54:33 INFO - a valid success response as defined by dfn-send-a-response and
[task 2020-08-27T21:54:33.955Z] 21:54:33 INFO - the provided response value.
[task 2020-08-27T21:54:33.955Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.955Z] 21:54:33 INFO - :param response: webdriver.Response instance.
[task 2020-08-27T21:54:33.955Z] 21:54:33 INFO - :param value: Expected value of the response body, if any.
[task 2020-08-27T21:54:33.955Z] 21:54:33 INFO - """
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - assert response.status == 200, str(response.error)
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - if value is not None:
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - > assert response.body["value"] == value
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - E AssertionError: assert 'Initial' == 'Updated'
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - E - Initial
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - E + Updated
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - response = <Responsetatus=200 body={"value": "Initial"}>
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - value = 'Updated'
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO -
[task 2020-08-27T21:54:33.956Z] 21:54:33 INFO - tests/web-platform/tests/webdriver/tests/support/asserts.py:72: AssertionError

Due to the low numbers of failures this looks like a race condition. With the content script setting document.title directly, the currentWindowGlobal of that browsing context, doesn't have that value set:

[task 2020-08-27T21:54:33.774Z] 21:54:33     INFO - PID 6230 | 1598565273770	Marionette	DEBUG	0 -> [0,81,"WebDriver:ExecuteScript",{"args":[],"script":"document.title = 'Updated'"}]
[task 2020-08-27T21:54:33.781Z] 21:54:33     INFO - PID 6230 | 1598565273774	Marionette	DEBUG	0 <- [1,81,null,{"value":null}]
[task 2020-08-27T21:54:33.781Z] 21:54:33     INFO - PID 6230 | 1598565273774	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-08-27T21:54:33.781Z] 21:54:33     INFO - PID 6230 | 1598565273775	webdriver::server	DEBUG	-> GET /session/e4f783bb-f87a-4412-88f2-383ab86506c0/title
[task 2020-08-27T21:54:33.781Z] 21:54:33     INFO - PID 6230 | 1598565273775	Marionette	DEBUG	0 -> [0,82,"WebDriver:GetTitle",{}]
[task 2020-08-27T21:54:33.781Z] 21:54:33     INFO - PID 6230 | 1598565273775	Marionette	DEBUG	0 <- [1,82,null,{"value":"Initial"}]
[task 2020-08-27T21:54:33.782Z] 21:54:33     INFO - PID 6230 | 1598565273776	webdriver::server	DEBUG	<- 200 OK {"value":"Initial"}

Might be a side-effect from the landing of bug 1660426.

status-firefox81: --- → unaffected
status-firefox82: --- → affected
Keywords: regression
Regressed by: 1660426
Blocks: marionette-fission
Whiteboard: [marionette-fission-mvp]

Tracking marionette-fission-mvp bugs for Fission Beta milestone (M7).

Fission Milestone: --- → M7

This failure stopped happening on November 6th. If there are no more failures on Monday next week we can get this bug closed.

Whiteboard: [marionette-fission-mvp] → [marionette-fission-reserve]
Depends on: 1685454

With the patch on bug 1685454 this should be fixed now. Please reopen if it's not the case.

Assignee: nobody → hskupin
status-firefox82: affected → wontfix
status-firefox86: --- → fixed
Target Milestone: --- → 86 Branch
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=326373649&repo=autoland&lineNumber=57041

Status: RESOLVED → REOPENED
status-firefox86: fixed → affected
Resolution: FIXED → ---
Target Milestone: 86 Branch → ---

Ok, so there is clearly a race between setting the title of the web page via WebDriver:ExecuteScript and retrieving the title afterward. Here in short the code as run:

[task 2021-01-11T15:28:54.603Z] 15:28:54     INFO - STDOUT:         session.execute_script("document.title = 'Updated'")
[task 2021-01-11T15:28:54.603Z] 15:28:54     INFO - STDOUT:         result = get_title(session)

While the execute script command gets executed within the JSWindowActor child and directly sets the title of the document, retrieving the title is implemented via browsingContext.currentWindowGlobal.documentTitle

Nika, I assume this is a race within the syncing code for the parent and child process. Is that a known platform issue?

Assignee: hskupin → nobody
Blocks: 1669172
Status: REOPENED → NEW
Flags: needinfo?(nika)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #26)

Nika, I assume this is a race within the syncing code for the parent and child process. Is that a known platform issue?

When the content process detects that the title of a document may have changed, it calls NotifyPossibleTitleChange here: https://searchfox.org/mozilla-central/rev/31ddf859c57e812878a5f817e4097efb06de4d97/dom/base/Document.cpp#8686. This then dispatches an event to the event queue which actually calls SendUpdateDocumentTitle and updates the title in the parent process after the event loop is allowed to spin once: https://searchfox.org/mozilla-central/rev/31ddf859c57e812878a5f817e4097efb06de4d97/dom/base/Document.cpp#8729

I believe that this is partially done to avoid spamming the window with title updates and expensive computations during a synchronous block of code which is constantly updating the title, as basically all code which relies on this information in the parent process doesn't care about having the absolute most-up-to-date version of the data, as it's just used for display etc.

I'm guessing it's this dispatch which is causing you issues.

Flags: needinfo?(nika)

Would it then help if the code in the parent process that forwards the execute script call to the child process spins the event loop once? Or could other events be waiting to get processed? If that would be the case I assume that we would have to go through the JSWindowActor pair and directly retrieve the web page title via the child actor.

Flags: needinfo?(nika)

Does this marionette-fission-reserve bug need to block shipping Fission MVP?

Fission Milestone: M7 → ?

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] (away 01/15 - 01/31) from comment #28)

Would it then help if the code in the parent process that forwards the execute script call to the child process spins the event loop once? Or could other events be waiting to get processed?

Spinning the event loop in the parent process won't help at all, as we're talking about IPC here, and there is no shared event loop. If you really really need to have the most up-to-date title information at all times, and can't afford for it to be slightly out of date, then you'll probably need to bounce to the content process to check the current value there, as the parent process is seeing a slightly delayed mirror of content process state.

Another potential option would be to have all calls to execute script in the content process perform an await new Promise(resolve => Services.tm.dispatchToMainThread(resolve)) (or equivalent) before they send a reply saying that the script execution has completed. This will give the content process time to process async follow-up tasks before the reply is sent.

Flags: needinfo?(nika)

For now, I am assuming marionette-fission-reserve bugs don't need to block shipping Fission MVP.

Fission Milestone: ? → Future
No longer blocks: 1669172

(In reply to Nika Layzell [:nika] (ni? for response) from comment #32)

Another potential option would be to have all calls to execute script in the content process perform an await new Promise(resolve => Services.tm.dispatchToMainThread(resolve)) (or equivalent) before they send a reply saying that the script execution has completed. This will give the content process time to process async follow-up tasks before the reply is sent.

This is a good idea. I'll have a look.

Please note that the tests aren't longer failing because they have multiple statuses now:

https://searchfox.org/mozilla-central/rev/6e630edb09c3ab06d0103665b16c9ea7dce782c5/testing/web-platform/meta/webdriver/tests/get_title/get.py.ini#6-12

Inform the main thread of the content process when the
command of the child command actor that causes the DOM
to change has been completed. It allows it to process
async follow-up tasks before the actual reply is sent
to the parent command actor.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/94a871824a5d
[marionette] Inform the main thread when command in child actor has been completed. r=marionette-reviewers,webdriver-reviewers,jdescottes

https://hg.mozilla.org/mozilla-central/rev/94a871824a5d

Status: ASSIGNED → RESOLVED
Closed: 3 years ago → 3 years ago
status-firefox90: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 90 Branch
Regressions: 1712682
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: