1924507 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/classic/new_session/unhandled_prompt_behavior.py | single tracking bug

Status: REOPENED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

Comment 1

[Intermittent Failures Robot]

27 failures in 4579 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

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

Platform and build breakdown:

• macosx1015-64-qr: 16
  • opt: 16
• macosx1015-64-shippable-qr: 11
  • opt: 11

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

Comment 2

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

This specific test timeout only happening on MacOS started around October 13th and then manifested on October 15th by producing around 5 failures per day for shippable builds. Checking the logs shows that we have a delay in starting Firefox which means that the final-ui-startup notification is sent out delayed with ~2s. In working cases the notification is received after at maximum 2.5s but now its between 4-6s for jobs timing out.

We didn't change this test nor any behavior in Remote Agent (Marionette). So I wonder if there was any change for MacOS specific recently which might have caused some slowness in startup. Stephen do you maybe have an idea? Thanks.

Comment 3

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

As it looks like the issue goes back even further and we have a huge difference in the test duration between different Wd4 jobs on MacOS for opt/shippable builds. These Treeherder jobs, which are next to each other show that.

While one has 129s the older one has 163s.

Overall the tests are running more on their limit these days which means some other factor came in as well. But that is hard to figure out.

Joel, any idea where this huge difference can originate from? Are the Mac workers shared as well between different jobs which may cause slowness of Firefox?

Comment 4

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

Locally I the tests take 80s on MacOS, and on wpt.fyi the tests on 60s only on Linux.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

yes the mac workers are shared with all unittests and perftests, not builders and signers though. Nothing has changed with our task -> pools for a long time. We did force cleaning up these directories (September 24-26):

/opt/worker/downloads
/Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/

if for some reason these tests were depending on data in those directories between tasks, then I could see that being affected.

I have noticed that failing tasks have:

[task 2024-10-22T12:54:06.429Z] 12:54:06     INFO - PID 3551 | 1729601646428	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:06.429Z] 12:54:06     INFO - PID 3551 | 1729601646428	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:06.556Z] 12:54:06     INFO - PID 3551 | 1729601646555	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:06.556Z] 12:54:06     INFO - PID 3551 | 1729601646555	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:06.791Z] 12:54:06     INFO - PID 3551 | 1729601646791	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:06.792Z] 12:54:06     INFO - PID 3551 | 1729601646791	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.025Z] 12:54:07     INFO - PID 3551 | 1729601647025	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.026Z] 12:54:07     INFO - PID 3551 | 1729601647025	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.256Z] 12:54:07     INFO - PID 3551 | 1729601647255	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.256Z] 12:54:07     INFO - PID 3551 | 1729601647255	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.495Z] 12:54:07     INFO - PID 3551 | 1729601647495	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.496Z] 12:54:07     INFO - PID 3551 | 1729601647495	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.731Z] 12:54:07     INFO - PID 3551 | 1729601647731	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.732Z] 12:54:07     INFO - PID 3551 | 1729601647731	geckodriver::marionette	TRACE	Retrying in 100ms

it is probably likely that these messages exist and only are printed out when we have a failure- so we only see these messages on the failed (timedout) tasks.

for macosx, I went back on m-c to oct 10th, and osx/shippable was taking in the range of 130-165 seconds. I did a handful of retriggers and most of the tasks failed, in fact some passing ones finished faster; I think this is intermittent- but it could be machine dependent. I did notice that headless was a lot faster, even today.

retriggering off the tip of m-c, I see ranges of 146-182s on the retriggers (180+ for original jobs). Not as many retriggers timed out on the tip, but the overall runtimes seemed longer.

Comment 6

[Intermittent Failures Robot]

13 failures in 4456 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 3
• mozilla-central: 5
• autoland: 5

Platform and build breakdown:

• macosx1015-64-qr: 8
  • opt: 8
• macosx1015-64-shippable-qr: 5
  • opt: 5

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

Comment 7

[Intermittent Failures Robot]

13 failures in 4456 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 3
• mozilla-central: 5
• autoland: 5

Platform and build breakdown:

• macosx1015-64-qr: 8
  • opt: 8
• macosx1015-64-shippable-qr: 5
  • opt: 5

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

Comment 8

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

(In reply to Joel Maher ( :jmaher ) (UTC -8) from comment #5)

yes the mac workers are shared with all unittests and perftests, not builders and signers though. Nothing has changed with our task -> pools for a long time. We did force cleaning up these directories (September 24-26):

Ok, so it could happen that some other test job runs in parallel and claiming too much resources so that due to limited resources on our side it takes longer for Firefox to startup.

if for some reason these tests were depending on data in those directories between tasks, then I could see that being affected.

No, we do not have any dependency. It is just that Firefox takes longer as expected to startup.

I have noticed that failing tasks have:

[task 2024-10-22T12:54:06.429Z] 12:54:06     INFO - PID 3551 | 1729601646428	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:06.429Z] 12:54:06     INFO - PID 3551 | 1729601646428	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:06.556Z] 12:54:06     INFO - PID 3551 | 1729601646555	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:06.556Z] 12:54:06     INFO - PID 3551 | 1729601646555	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:06.791Z] 12:54:06     INFO - PID 3551 | 1729601646791	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:06.792Z] 12:54:06     INFO - PID 3551 | 1729601646791	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.025Z] 12:54:07     INFO - PID 3551 | 1729601647025	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.026Z] 12:54:07     INFO - PID 3551 | 1729601647025	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.256Z] 12:54:07     INFO - PID 3551 | 1729601647255	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.256Z] 12:54:07     INFO - PID 3551 | 1729601647255	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.495Z] 12:54:07     INFO - PID 3551 | 1729601647495	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.496Z] 12:54:07     INFO - PID 3551 | 1729601647495	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-10-22T12:54:07.731Z] 12:54:07     INFO - PID 3551 | 1729601647731	geckodriver::browser	TRACE	Failed to open /var/folders/p4/_gm58y794639164h1xnkpyyw000014/T/tmpqvlzhgva.mozrunner/MarionetteActivePort
[task 2024-10-22T12:54:07.732Z] 12:54:07     INFO - PID 3551 | 1729601647731	geckodriver::marionette	TRACE	Retrying in 100ms

it is probably likely that these messages exist and only are printed out when we have a failure- so we only see these messages on the failed (timedout) tasks.

No, these messages are added in all the cases and not only for failing tasks. It just means that geckodriver tries to read the Marionette port of the started Firefox process but it isn't ready yet. But the amount of entries of these lines indeed demonstrates a startup delay.

for macosx, I went back on m-c to oct 10th, and osx/shippable was taking in the range of 130-165 seconds. I did a handful of retriggers and most of the tasks failed, in fact some passing ones finished faster; I think this is intermittent- but it could be machine dependent. I did notice that headless was a lot faster, even today.

Maybe this means that anything to graphic related initialization could be involved and especially in a shared worker environment causes longer delays for startup?

Markus, do you have an idea?

Comment 9

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

Because other tests are affected as well, I moved the needinfo request over to bug 1927416.

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• mozilla-central: 3

Platform and build breakdown:

• macosx1015-64-qr: 2
  • opt: 2
• macosx1015-64-shippable-qr: 2
  • opt: 2
• linux1804-64-ccov-qr: 1
  • opt: 1

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

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1
• linux1804-64-ccov-qr: 1
  • opt: 1

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

Comment 12

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=487363245&repo=try

Comment 13

[Intermittent Failures Robot]

Summary

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug: 1

Table

	1proc	fis	fis-hv	fis-hv-s	fis-s	headless	http2	http3	mda-gpu-s	no_variant	nofis	nofis-aab	nofis-s	nofis-ship	nofis-ship-s	nofis-spi	nofis-swr	nofis-swr-s	nogpu	nogpu-s	s	spi	spi-nw	spi-nw-s	swr	wmfme	xorig	xorig-s
android-em-7-0-x86_64-qr/debug										1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1924507&startday=2024-12-16&endday=2024-12-22&tree=all

Comment 14

[Intermittent Failures Robot]

Summary

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1

Table

	no_variant
android-em-7-0-x86_64-qr/debug-isolated-process	1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1924507&startday=2024-12-30&endday=2025-01-05&tree=all

Comment 15

[Intermittent Failures Robot]

Summary

1 failures in 3682 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

Table

	headless
linux1804-64-ccov-qr/opt	1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1924507&startday=2025-01-06&endday=2025-01-12&tree=all

Comment 16

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

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

Comment 17

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=493406902&repo=autoland

Comment 18

[Intermittent Failures Robot]

Summary

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

Repository breakdown:

• mozilla-beta: 1
• mozilla-central: 1
• mozilla-esr128: 1
• autoland: 2

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • opt: 1
• linux1804-64-ccov-qr: 1
  • opt: 1
• linux1804-64-qr: 1
  • opt: 1
• macosx1470-64: 2
  • opt: 2

Table

	headless	no_variant
android-em-7-0-x86_64-qr--/opt		1
linux1804-64-ccov-qr--/opt	1
linux1804-64-qr--/opt		1
macosx1470-64--/opt		2

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1924507&startday=2025-02-03&endday=2025-02-09&tree=all

Comment 19

[Intermittent Failures Robot]

Summary

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

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

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

Table

	headless
linux1804-64-ccov-qr--/opt	2

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1924507&startday=2025-02-10&endday=2025-02-16&tree=all