1739008 - Intermittent Mn/en-US | marionette_driver.errors.SessionNotCreatedException: TimeoutError: TimedPromise timed out after 300000 ms

Status: RESOLVED FIXED

(Testing :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_execute_js_exception
[task 2021-11-02T19:38:34.919Z] 19:38:34     INFO -  1635881914919	Marionette	DEBUG	Accepted connection 350 from 127.0.0.1:44086
[task 2021-11-02T19:38:34.920Z] 19:38:34     INFO -  1635881914920	Marionette	DEBUG	Closed connection 349
[task 2021-11-02T19:38:34.924Z] 19:38:34     INFO -  1635881914924	Marionette	DEBUG	350 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-11-02T19:38:44.084Z] 19:38:44     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-11-02T19:38:44.111Z] 19:38:44     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-11-02T19:38:59.117Z] 19:38:59     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-11-02T19:38:59.142Z] 19:38:59     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-11-02T19:43:34.933Z] 19:43:34     INFO -  1635882214932	Marionette	DEBUG	350 <- [1,1,{"error":"session not created","message":"TimeoutError: TimedPromise timed out after 300000 ms","stacktrace":"WebDriverE ... r@chrome://remote/content/shared/webdriver/Errors.jsm:450:5\nbail@chrome://remote/content/marionette/sync.js:230:19\n"},null]
[task 2021-11-02T19:43:34.938Z] 19:43:34     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_execute_js_exception | marionette_driver.errors.SessionNotCreatedException: TimeoutError: TimedPromise timed out after 300000 ms
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO - stacktrace:
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO - 	WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:181:5
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO - 	TimeoutError@chrome://remote/content/shared/webdriver/Errors.jsm:450:5
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO - 	bail@chrome://remote/content/marionette/sync.js:230:19
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO - Traceback (most recent call last):
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 183, in run
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO -     self.setUp()
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py", line 18, in setUp
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO -     super(TestExecuteAsyncContent, self).setUp()
[task 2021-11-02T19:43:34.939Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 405, in setUp
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -     super(MarionetteTestCase, self).setUp()
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 308, in setUp
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -     self.marionette.start_session()
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -     return func(*args, **kwargs)
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1187, in start_session
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -     resp = self._send_message("WebDriver:NewSession", capabilities)
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -     return func(*args, **kwargs)
[task 2021-11-02T19:43:34.940Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 630, in _send_message
[task 2021-11-02T19:43:34.941Z] 19:43:34     INFO -     self._handle_error(err)
[task 2021-11-02T19:43:34.941Z] 19:43:34     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 652, in _handle_error
[task 2021-11-02T19:43:34.941Z] 19:43:34     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2021-11-02T19:43:34.941Z] 19:43:34     INFO - TEST-INFO took 300018ms
[task 2021-11-02T19:43:34.941Z] 19:43:34     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_execute_no_return

Comment 1

[Sandor Molnar]

@whimbo, could you take a look at these failures
started to fail after bug 1736323 landed.

Comment 2

[Julian Descottes [:jdescottes]]

Will take a look today

Comment 3

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Please also check if bug 1739066 and bug 1739074 It's uncommon to see new Marionette failures which have been observed several times for a day.

Comment 4

[Henrik Skupin (:whimboo) [⌚️UTC+1] (away 07/18 - 08/05)]

Yes, those seem to be also related.

Comment 5

[Release mgmt bot [:suhaib / :marco/ :calixte]]

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

Comment 6

[Julian Descottes [:jdescottes]]

Started adding some logs, as expected we timeout before waitForNavigationCompleted in newSession. Meaning we get a webprogresslistener with isLoading set to true, but we never actually get the navigation events.

Comment 7

[Julian Descottes [:jdescottes]]

It's not that surprising because the pattern we use is racy by nature.

     if (browsingContext.webProgress.isLoadingDocument) {
        await navigate.waitForNavigationCompleted(this, () => {}, {
          loadEventExpected: true,
          unknownState: true,
        });
      }

In the parent process we detect that we have a load, but then we will communicate to the content process in order to add load listeners. So before the listeners can be added, the navigation might complete and we might never receive any load event.

Either we need to fully monitor the load from the parent process, or we need to be a bit more careful in navigate.js in case we pass unknownState to true. I think we should check the state of the document (or of the webprogresslistener?) in the content process before expecting a load event.

Comment 8

[Intermittent Failures Robot]

15 failures in 589 pushes (0.025 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 2
• autoland: 13

Platform and build breakdown:

• linux1804-64-qr: 9
  • debug: 5
  • opt: 4
• macosx1015-64-shippable-qr: 1
  • opt: 1
• linux1804-64-asan-qr: 2
  • opt: 2
• linux1804-64-shippable-qr: 1
  • opt: 1
• windows10-64-2004-asan-qr: 2
  • opt: 2

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

Comment 14

[Henrik Skupin (:whimboo) [⌚️UTC+1] (away 07/18 - 08/05)]

I discussed the topic with Julian yesterday and he will try out some options. If we cannot find the right solution until afternoon today I will go ahead and request a backout of bug 1736323 given that this new hang in WebDriver:NewSession is way more severe.

Comment 15

[Julian Descottes [:jdescottes]]

Attachment: Bug 1739008 - [marionette] Monitor navigation using the webprogresslistener for NewSession

Comment 16

[Intermittent Failures Robot]

23 failures in 643 pushes (0.036 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 12
• mozilla-central: 4
• try: 7

Platform and build breakdown:

• linux1804-64-qr: 7
  • opt: 5
  • debug: 2
• macosx1015-64-qr: 2
  • debug: 2
• windows10-64-2004-asan-qr: 4
  • opt: 4
• macosx1015-64-devedition-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 5
  • opt: 5
• windows10-64-shippable-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1
• linux1804-64-asan-qr: 2
  • opt: 2

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

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/78d6ea95a82f
[marionette] Monitor navigation using the webprogresslistener for NewSession r=webdriver-reviewers,whimboo

Comment 18

[Cristian Tuns]

Backed out for causing android wpt failures.

• Backout link
• Push with failures
• Failure Log

Comment 19

[Intermittent Failures Robot]

68 failures in 3030 pushes (0.022 failures/push) were associated with this bug in the last 7 days.

This is the #12 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: 42
• mozilla-central: 16
• try: 10

Platform and build breakdown:

• linux1804-64-qr: 30
  • debug: 18
  • opt: 12
• windows10-64-2004-asan-qr: 11
  • opt: 11
• macosx1015-64-shippable-qr: 9
  • opt: 9
• linux1804-64-asan-qr: 8
  • opt: 8
• linux1804-64-shippable-qr: 2
  • opt: 2
• macosx1015-64-qr: 5
  • debug: 4
  • opt: 1
• macosx1015-64-devedition-qr: 1
  • opt: 1
• windows10-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=1739008&startday=2021-11-01&endday=2021-11-07&tree=all

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ff1b3692fe81
[marionette] Monitor navigation using the webprogresslistener for NewSession r=webdriver-reviewers,whimboo

Comment 21

[Julian Descottes [:jdescottes]]

Renewing my need-info: will have to uplift this and Bug 1736323 to beta. Uplifting patches from both bugs will allow to reuse the same patches as the ones used against central. Let's wait to see if the current patch sticks.

Comment 22

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/ff1b3692fe81

Comment 23

[Julian Descottes [:jdescottes]]

Comment on attachment 9249223 [details]
Bug 1739008 - [marionette] Monitor navigation using the webprogresslistener for NewSession

Beta/Release Uplift Approval Request

• User impact if declined: Users of marionette/geckodriver (eg selenium webdriver users) are exposed to a race condition that can lead to sessions created too early, and therefore making their scripts fail. Hitting this race condition became much more frequent after Bug 1735500 landed in Firefox 95.

We fixed it over Bug 1736323 and Bug 1739008 (this bug), which only landed in 96. We should uplift both patches to 95 to avoid issues due to Bug 1735500.

• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: Bug 1736323
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): Low risk as it only affects marionette users and is changing the logic to create new sessions in order to wait for a load in case we are creating a session when a document is not loaded.
  The new session logic is extensively tested and relied upon in many tests and test suites.
• String changes made/needed:

Comment 24

[Pascal Chevrel:pascalc (PTO until August 22)]

Comment on attachment 9249223 [details]
Bug 1739008 - [marionette] Monitor navigation using the webprogresslistener for NewSession

Approved for 95 beta 5, thanks.

Comment 25

[Pascal Chevrel:pascalc (PTO until August 22)]

https://hg.mozilla.org/releases/mozilla-beta/rev/7cb8324e9f4d

Comment 26

[Intermittent Failures Robot]

6 failures in 2723 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 4
• try: 2

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1
• linux1804-64-qr: 1
  • debug: 1
• windows10-64-2004-asan-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1739008&startday=2021-11-08&endday=2021-11-14&tree=all

Comment 27

[Ryan VanderMeulen [:RyanVM]]

Can we get a rebased patch for ESR now that the regressing patch was uplifted there?

Comment 28

[Henrik Skupin (:whimboo) [⌚️UTC+1] (away 07/18 - 08/05)]

I'm not sure if we need an uplift here. It regressed because of a feature (bug 1735500) that landed for Firefox 95. My try build hasn't shown any failing tests for MacOS on esr91.

Comment 29

[Ryan VanderMeulen [:RyanVM]]

Couple instances today post-uplift:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-02-24&endday=2022-03-03&tree=mozilla-esr91&bug=1739008

Comment 30

[Henrik Skupin (:whimboo) [⌚️UTC+1] (away 07/18 - 08/05)]

Interesting. Julian, would you be able to provide a backport patch for esr91?

Comment 31

[Julian Descottes [:jdescottes]]

Let's see how this goes on try: https://treeherder.mozilla.org/jobs?repo=try&revision=1250341fb5106d114e2f8c99507b39c9f7475ec9

Comment 32

[Julian Descottes [:jdescottes]]

Attachment: bug_1739008_esr91_backport.patch

[Approval Request Comment]
If this is not a sec:{high,crit} bug, please state case for ESR consideration: This fixes a regression from Bug 1736323 which was just uplifted to ESR91
User impact if declined: user impact should be relatively low, this issue mostly leads to intermittent failures and pollutes our CI
Fix Landed on Version: 95 (landed in 96 but was uplifted)
Risk to taking this patch (and alternatives if risky): Low, same comment as for the beta uplift: Only affects marionette users and is changing the logic to create new sessions in order to wait for a load in case we are creating a session when a document is not loaded. The new session logic is extensively tested and relied upon in many tests and test suites.

See https://wiki.mozilla.org/Release_Management/ESR_Landing_Process for more info.

Comment 33

[Henrik Skupin (:whimboo) [⌚️UTC+1] (away 07/18 - 08/05)]

(In reply to Julian Descottes [:jdescottes] from comment #31)

Let's see how this goes on try: https://treeherder.mozilla.org/jobs?repo=try&revision=1250341fb5106d114e2f8c99507b39c9f7475ec9

Note that you triggered the wdspec jobs for MacOS only. But the two failures that we got are from Linux. So you may want to extend to maybe all desktop platforms.

Comment 34

[Intermittent Failures Robot]

7 failures in 3063 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr91: 7

Platform and build breakdown:

• linux1804-64-qr: 6
  • debug: 6
• windows10-64-2004-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1739008&startday=2022-02-28&endday=2022-03-06&tree=all

Comment 35

[Julian Descottes [:jdescottes]]

triggered some additional jobs, but feel free to add more

Comment 36

[Henrik Skupin (:whimboo) [⌚️UTC+1] (away 07/18 - 08/05)]

All the triggered tests are passing. So I'm fine with the following commit to get uplifted to esr91:
https://hg.mozilla.org/try/rev/e15b4708e41b39258862912dcbc8cd94d72ba028

Ryan can you help us with the uplift?

Comment 37

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9266494 [details]
bug_1739008_esr91_backport.patch

Approved for esr91, thanks.

Comment 38

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr91/rev/73ffb44db5c6