Open Bug 1868846 Opened 2 years ago Updated 1 day ago

Intermittent TV automation.py | application timed out after 740.0 seconds with no output | single tracking bug

Categories

(Testing :: General, defect, P5)

defect

Tracking

(firefox-esr115 unaffected, firefox120 unaffected, firefox121 unaffected, firefox122 affected, firefox123 affected)

Tracking Status
firefox-esr115 --- unaffected
firefox120 --- unaffected
firefox121 --- unaffected
firefox122 --- affected
firefox123 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, regression, test-verify-fail)

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=439220639&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/d0J9AcHnRbSdfQM668_kHg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/d0J9AcHnRbSdfQM668_kHg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2023-12-07T16:25:54.545Z] 16:25:54     INFO - TEST-START | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_capture_form_removal.js
[task 2023-12-07T16:25:58.631Z] 16:25:58     INFO - GECKO(6245) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2023-12-07T16:25:58.634Z] 16:25:58     INFO - GECKO(6245) | MEMORY STAT | vsize 11517MB | residentFast 465MB | heapAllocated 249MB
[task 2023-12-07T16:25:58.634Z] 16:25:58     INFO - TEST-OK | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_capture_form_removal.js | took 4088ms
[task 2023-12-07T16:25:58.706Z] 16:25:58     INFO - checking window state
[task 2023-12-07T16:25:58.798Z] 16:25:58     INFO - GECKO(6245) | Completed ShutdownLeaks collections in process 6245
[task 2023-12-07T16:25:58.798Z] 16:25:58     INFO - TEST-START | Shutdown
[task 2023-12-07T16:25:58.798Z] 16:25:58     INFO - Browser Chrome Test Summary
[task 2023-12-07T16:25:58.798Z] 16:25:58     INFO - Passed:  7
[task 2023-12-07T16:25:58.798Z] 16:25:58     INFO - Failed:  0
[task 2023-12-07T16:25:58.798Z] 16:25:58     INFO - Todo:    0
[task 2023-12-07T16:25:58.798Z] 16:25:58     INFO - Mode:    e10s
[task 2023-12-07T16:25:58.799Z] 16:25:58     INFO - *** End BrowserChrome Test Results ***
[task 2023-12-07T16:25:58.836Z] 16:25:58     INFO - GECKO(6245) | Exiting due to channel error.
[task 2023-12-07T16:25:58.836Z] 16:25:58     INFO - GECKO(6245) | Exiting due to channel error.
[task 2023-12-07T16:25:58.837Z] 16:25:58     INFO - GECKO(6245) | Exiting due to channel error.
[task 2023-12-07T16:25:58.837Z] 16:25:58     INFO - GECKO(6245) | Exiting due to channel error.
[task 2023-12-07T16:25:58.837Z] 16:25:58     INFO - GECKO(6245) | Exiting due to channel error.
[task 2023-12-07T16:25:58.838Z] 16:25:58     INFO - GECKO(6245) | Exiting due to channel error.
[task 2023-12-07T16:25:58.838Z] 16:25:58     INFO - GECKO(6245) | Exiting due to channel error.
[task 2023-12-07T16:25:58.899Z] 16:25:58     INFO - TEST-INFO | Main app process: exit 0
[task 2023-12-07T16:25:58.899Z] 16:25:58     INFO - runtests.py | Application ran for: 0:08:50.843136
[task 2023-12-07T16:25:58.899Z] 16:25:58     INFO - zombiecheck | Reading PID log: /tmp/tmph4e3lft_pidlog
<...>
[task 2023-12-07T16:25:59.373Z] 16:25:59     INFO - runtests.py | Running tests: start.
[task 2023-12-07T16:25:59.374Z] 16:25:59     INFO - 
[task 2023-12-07T16:25:59.402Z] 16:25:59     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpc_pn2b7y.mozrunner
[task 2023-12-07T16:25:59.412Z] 16:25:59     INFO - runtests.py | Application pid: 6687
[task 2023-12-07T16:25:59.413Z] 16:25:59     INFO - TEST-INFO | started process GECKO(6687)
[task 2023-12-07T16:25:59.440Z] 16:25:59     INFO - GECKO(6687) | *** You are running in chaos test mode. See ChaosMode.h. ***
[task 2023-12-07T16:26:00.396Z] 16:26:00     INFO - GECKO(6687) | ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-12-07T16:26:00.429Z] 16:26:00     INFO - GECKO(6687) | 1701966360428	Marionette	INFO	Marionette enabled
[task 2023-12-07T16:26:00.432Z] 16:26:00     INFO - GECKO(6687) | 1701966360431	Marionette	TRACE	Received observer notification final-ui-startup
[task 2023-12-07T16:26:00.489Z] 16:26:00     INFO - GECKO(6687) | console.error: "Warning: unrecognized command line flag" "-foreground"
[task 2023-12-07T16:26:00.498Z] 16:26:00     INFO - GECKO(6687) | ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-12-07T16:26:00.531Z] 16:26:00     INFO - GECKO(6687) | 1701966360530	RemoteAgent	WARN	PollPromise timed out after 5000 ms
[task 2023-12-07T16:26:00.537Z] 16:26:00     INFO - GECKO(6687) | 1701966360536	Marionette	INFO	Listening on port 2828
[task 2023-12-07T16:26:00.540Z] 16:26:00     INFO - GECKO(6687) | 1701966360539	Marionette	DEBUG	Marionette is listening
[task 2023-12-07T16:26:00.584Z] 16:26:00     INFO - GECKO(6687) | 1701966360582	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:59156
[task 2023-12-07T16:26:00.657Z] 16:26:00     INFO - GECKO(6687) | 1701966360655	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:59160
[task 2023-12-07T16:26:00.665Z] 16:26:00     INFO - GECKO(6687) | 1701966360664	Marionette	DEBUG	Closed connection 0
[task 2023-12-07T16:26:01.032Z] 16:26:01     INFO - GECKO(6687) | 1701966361031	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-12-07T16:26:01.038Z] 16:26:01     INFO - GECKO(6687) | 1701966361037	Marionette	DEBUG	Waiting for initial application window
[task 2023-12-07T16:26:05.972Z] 16:26:05     INFO - GECKO(6687) | console.error: ({})
[task 2023-12-07T16:26:09.868Z] 16:26:09     INFO - GECKO(6687) | 1701966369867	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2023-12-07T16:26:09.917Z] 16:26:09     INFO - GECKO(6687) | 1701966369915	RemoteAgent	TRACE	[9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=5000 waitForExplicitStart=false
[task 2023-12-07T16:26:09.919Z] 16:26:09     INFO - GECKO(6687) | 1701966369918	RemoteAgent	TRACE	[9] ProgressListener Setting unload timer (5000ms)
[task 2023-12-07T16:26:09.922Z] 16:26:09     INFO - GECKO(6687) | 1701966369921	RemoteAgent	TRACE	[9] Document already finished loading: about:blank
[task 2023-12-07T16:26:09.927Z] 16:26:09     INFO - GECKO(6687) | 1701966369923	RemoteAgent	TRACE	[9] ProgressListener Stop: has error=false
[task 2023-12-07T16:26:09.960Z] 16:26:09     INFO - GECKO(6687) | 1701966369957	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"4ff0fab7-7b0d-4fac-8703-0d9eb6cb7308","capabilities":{"browserName":"firefox","browserVersion":"122.0a1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20231207152911","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":6687,"moz:profile":"/tmp/tmpc_pn2b7y.mozrunner","moz:shutdownTimeout":60000,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-12-07T16:26:10.009Z] 16:26:10     INFO - GECKO(6687) | 1701966370008	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/tmp/tmpupss0eod.zip","temporary":false}]
[task 2023-12-07T16:26:11.408Z] 16:26:11     INFO - GECKO(6687) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-12-07T16:26:11.410Z] 16:26:11     INFO - GECKO(6687) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-12-07T16:26:11.415Z] 16:26:11     INFO - GECKO(6687) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-12-07T16:26:11.436Z] 16:26:11     INFO - GECKO(6687) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-12-07T16:26:11.438Z] 16:26:11     INFO - GECKO(6687) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-12-07T16:26:11.441Z] 16:26:11     INFO - GECKO(6687) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-12-07T16:26:11.443Z] 16:26:11     INFO - GECKO(6687) | 1701966371442	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2023-12-07T16:26:11.446Z] 16:26:11     INFO - GECKO(6687) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-12-07T16:26:11.547Z] 16:26:11     INFO - GECKO(6687) | 1701966371544	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpke7ftsx6.zip","temporary":false}]
[task 2023-12-07T16:32:11.553Z] 16:32:11     INFO - runtests.py | Waiting for browser...
[task 2023-12-07T16:33:57.150Z] 16:33:57     INFO - GECKO(6687) | 1701966837149	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2023-12-07T16:33:57.182Z] 16:33:57     INFO - GECKO(6687) | 1701966837181	Marionette	DEBUG	Closed connection 1
[task 2023-12-07T16:46:17.196Z] 16:46:17     INFO - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 740 seconds with no output
[task 2023-12-07T16:46:17.196Z] 16:46:17     INFO - TEST-INFO 
[task 2023-12-07T16:46:17.196Z] 16:46:17     INFO - Buffered messages finished
[task 2023-12-07T16:46:17.196Z] 16:46:17  WARNING - Force-terminating active process(es).
[task 2023-12-07T16:46:17.196Z] 16:46:17     INFO - Determining child pids from psutil...
[task 2023-12-07T16:46:17.206Z] 16:46:17     INFO - [6765, 6798, 6836, 6862, 6864, 6865, 6898]

Hi Janika! Can you please take a look at this? The reason for the need info and marking Bug 1865876 as the culprit, is that I saw the last test start before the timeout TEST-START | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_capture_form_removal.js which is added in that bug.
Thank you!

Hi Geoff! Can you also take a look at this please?
Thank you!

There seems to be a hang here:

[task 2023-12-07T16:26:11.547Z] 16:26:11     INFO - GECKO(6687) | 1701966371544	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpke7ftsx6.zip","temporary":false}]
[task 2023-12-07T16:32:11.553Z] 16:32:11     INFO - runtests.py | Waiting for browser...
[task 2023-12-07T16:33:57.150Z] 16:33:57     INFO - GECKO(6687) | 1701966837149	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2023-12-07T16:33:57.182Z] 16:33:57     INFO - GECKO(6687) | 1701966837181	Marionette	DEBUG	Closed connection 1
[task 2023-12-07T16:46:17.196Z] 16:46:17     INFO - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 740 seconds with no output
[task 2023-12-07T16:46:17.196Z] 16:46:17     INFO - TEST-INFO 
[task 2023-12-07T16:46:17.196Z] 16:46:17     INFO - Buffered messages finished
Flags: needinfo?(gbrown)
Flags: needinfo?(jneuberger)

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

Sorry - not sure how I can help with this.

Flags: needinfo?(gbrown)

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

Flags: needinfo?(jneuberger)

AFAICT, this is a general issue with TV on Wayland.

Flags: needinfo?(ahal)
No longer regressed by: 1865876
Flags: needinfo?(ahal)
Component: Applications: MozharnessCore → General
Product: Release Engineering → Testing

Hi Joel , could you take a look at this failure? It's racking 59 failures this week
Thanks.

Recent failure log -> https://treeherder.mozilla.org/logviewer?job_id=508869737&repo=autoland&lineNumber=4900

Flags: needinfo?(jmaher)

this is macosx 14.70/debug only. I suspect this is similar to what we see for webdriver tests in bug 1960740.

I would rather revisit this after bug 1960740 is resolved. If this is still a problem or we want to do something faster, I am happy to not schedule test-verify on macosx/debug.

Flags: needinfo?(jmaher)
See Also: → 1960740

Well, for recent failures at least I can see the following log entries:
https://treeherder.mozilla.org/logviewer?job_id=509217630&repo=autoland&lineNumber=15451-15453

task 2025-05-20T11:55:51.579Z] 11:55:51     INFO - GECKO(2633) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/8h/42m81v7x53xc8ycgyw2nl0vw0000jb/T/tmphcvisqvp.mozrunner/runtests_leaks_tab_pid2641.log
[task 2025-05-20T11:55:51.787Z] 11:55:51     INFO - GECKO(2633) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2025-05-20T11:55:51.788Z] 11:55:51     INFO - GECKO(2633) | [Child 2641, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:476
[task 2025-05-20T12:07:51.164Z] 12:07:51     INFO - runtests.py | Waiting for browser...

If there is a problem with chrome://branding/locale/brand.properties it most likely is a broken build? I have seen things like that only when updating a local checkout and failing to build before starting Firefox. Here we clearly hang and also cannot get a connection to Marionette to install the mochijar and specialpowers addons.

Note that this line is only printed in debug builds and as per list only those builds are failing here. IMHO this is a different issue than bug 1960740.

Gijs, do you have an idea/

Flags: needinfo?(gijskruitbosch+bugs)

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

Well, for recent failures at least I can see the following log entries:
https://treeherder.mozilla.org/logviewer?job_id=509217630&repo=autoland&lineNumber=15451-15453

task 2025-05-20T11:55:51.579Z] 11:55:51     INFO - GECKO(2633) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/8h/42m81v7x53xc8ycgyw2nl0vw0000jb/T/tmphcvisqvp.mozrunner/runtests_leaks_tab_pid2641.log
[task 2025-05-20T11:55:51.787Z] 11:55:51     INFO - GECKO(2633) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2025-05-20T11:55:51.788Z] 11:55:51     INFO - GECKO(2633) | [Child 2641, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:476
[task 2025-05-20T12:07:51.164Z] 12:07:51     INFO - runtests.py | Waiting for browser...

Gijs, do you have an idea/

The screenshot from this is super weird. Joel, are we expecting raritan hardware connected to our thing? Can we dismiss this prompt? Is this issue specific to particular (virtual) machines?

If there is a problem with chrome://branding/locale/brand.properties it most likely is a broken build? I have seen things like that only when updating a local checkout and failing to build before starting Firefox. Here we clearly hang and also cannot get a connection to Marionette to install the mochijar and specialpowers addons.

Note that this line is only printed in debug builds and as per list only those builds are failing here. IMHO this is a different issue than bug 1960740.

I don't understand what "as per list" means. Do other, working debug build tests report this same error? Have you tried downloading the artifacts that are being run and do they run locally? Any evidence that things are getting lost when moving content out of dmgs and such?

Flags: needinfo?(jmaher)
Flags: needinfo?(hskupin)
Flags: needinfo?(gijskruitbosch+bugs)

These lines in the log about not killing things are also weird: https://treeherder.mozilla.org/logviewer?job_id=509217630&repo=autoland&lineNumber=15385-15390

thanks for pointing that out :gijs, the raritan is what we use for pdu/kvm, but we need to dismiss this dialog properly and it shouldn't be popping up in general, maybe setup had some issues.

:rcurran, can you look at the kvm setup and ensure all "devices" are properly setup on the 14.7.5 machines (per screenshot)?

Flags: needinfo?(jmaher) → needinfo?(rcurran)

(In reply to :Gijs (he/him) from comment #39)

I don't understand what "as per list" means. Do other, working debug build tests report this same error? Have you tried downloading the artifacts that are being run and do they run locally? Any evidence that things are getting lost when moving content out of dmgs and such?

I meant the intermittent failures list. Sorry when it was not that clear.

These kind of hang also happens when this Raritan dialog is not open. It looks like Firefox doesn't open any window, and the last notification that we receive in Marionette is final-ui-startup.

I now downloaded such a DMG and run it locally after installing with mozinstall. I didn't observe an issue.

Flags: needinfo?(hskupin)

Note that those failures started on May 13th. Joel and Ryan, was it the time when we started to upgrade from 14.7.1 to 14.7.5?

We started that rollout on May 6th, completed it on May 8th, re-puppetized the workers on May 9th (so that the gw config would update reflecting the correct OS version), and updated Safari on May 12th.

Flags: needinfo?(rcurran)

Recent failures still have the same dialog popping up: https://firefoxci.taskcluster-artifacts.net/AzpAHKtFTfutFuIRkXmsGw/0/public/test_info/mozilla-test-fail-screenshot_d9ufdv9p.png

Renewing this needinfo for that bit in case it is interfering with Firefox in some way:

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

thanks for pointing that out :gijs, the raritan is what we use for pdu/kvm, but we need to dismiss this dialog properly and it shouldn't be popping up in general, maybe setup had some issues.

:rcurran, can you look at the kvm setup and ensure all "devices" are properly setup on the 14.7.5 machines (per screenshot)?

Flags: needinfo?(rcurran)

(In reply to :Gijs (he/him) from comment #50)

Recent failures still have the same dialog popping up: https://firefoxci.taskcluster-artifacts.net/AzpAHKtFTfutFuIRkXmsGw/0/public/test_info/mozilla-test-fail-screenshot_d9ufdv9p.png

Note that not all of these failures actually show this dialog, but still a lot of notifications for firefox and xyz: https://firefoxci.taskcluster-artifacts.net/DHVZwPDCTK6TOaxzY87T2Q/0/public/test_info/mozilla-test-fail-screenshot_r3ig06b1.png.

But there is probably some other factor which is causing this issue.

:Gijs Is the needinfo a request to suppress the kvm keyboard prompt? Or something else? Thank you

Flags: needinfo?(rcurran)

(In reply to Ryan Curran from comment #53)

:Gijs Is the needinfo a request to suppress the kvm keyboard prompt? Or something else? Thank you

Yes - I quoted comment #41 where my read of Joel's comment was that hopefully we could get rid of the dialog. Even if it isn't itself interfering with the test, as long as it's there other people with intermittent failures will probably wonder about whether it is a cause (and/or may occlude what the actual app is doing), so it seems better to make sure it's not present.

Flags: needinfo?(rcurran)

(In reply to :Gijs (he/him) from comment #55)

(In reply to Ryan Curran from comment #53)

:Gijs Is the needinfo a request to suppress the kvm keyboard prompt? Or something else? Thank you

Yes - I quoted comment #41 where my read of Joel's comment was that hopefully we could get rid of the dialog. Even if it isn't itself interfering with the test, as long as it's there other people with intermittent failures will probably wonder about whether it is a cause (and/or may occlude what the actual app is doing), so it seems better to make sure it's not present.

Thank you. I have created a work item for this issue https://mozilla-hub.atlassian.net/browse/RELOPS-1601

Flags: needinfo?(rcurran)
Whiteboard: [stockwell disable-recommended]

Note that I was able to see the exact problem locally on my MBP. I filed bug 1997841 with a Gecko profile attached. Lets hope it's useful and we can figure out why it's happening. this is a high frequent failure - whereby the underlying reason in the mochitest harness is the same as bug 1414495.

Depends on: 1997841
See Also: → 1414495

As it looks like the infra changes as pushed to macOS workers on bug 2004631 has fixed the timeouts completely for that platform. Lets revisit later this week if we can close this bug now given that only macOS was affected by it over the last 30 days.

Depends on: 2004631
No longer depends on: 1812622

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

As it looks like the infra changes as pushed to macOS workers on bug 2004631 has fixed the timeouts completely for that platform. Lets revisit later this week if we can close this bug now given that only macOS was affected by it over the last 30 days.

Actually macOS machines need to be provisioned again. The whole process will take a bit longer. So no improvements will be seen immediately.

With the fix on bug 2004631 most of the failures are gone now.

But what I wonder why we are waiting twice that long (740s) on macOS instead of the 360s on other platforms. I'm asking because this bug is basically all the same as bug 1414495, which is about Waiting for browser....

From the logs it looks like that only verify mode is actually affected and I can see those lines:

[task 2026-01-06T01:21:12.194+00:00] 01:21:12     INFO - Increasing default timeout to 90 seconds (asan or debug)
[task 2026-01-06T01:21:12.194+00:00] 01:21:12     INFO - Increasing default timeout to 180 seconds (MOZ_CHAOSMODE)

But still there is a factor of 4 still missing which might get applied at some other point and that is not listed anywhere in the logs.

Andrew, do you have an idea where this could be done and especially why we need that? I don't see an actual reason for it.

Flags: needinfo?(ahal)

Sorry, I'm not sure. There could be some logic in one of the transforms under taskcluster/gecko_taskgraph/transforms/test (try grepping for max-run-time), or sometimes test manifests can increase the timeoutfactor as well, e.g:
https://searchfox.org/firefox-main/source/browser/components/backup/tests/xpcshell/xpcshell.toml#35

Flags: needinfo?(ahal)

(In reply to Andrew Halberstadt [:ahal] from comment #91)

Sorry, I'm not sure. There could be some logic in one of the transforms under taskcluster/gecko_taskgraph/transforms/test (try grepping for max-run-time), or sometimes test manifests can increase the timeoutfactor as well, e.g:
https://searchfox.org/firefox-main/source/browser/components/backup/tests/xpcshell/xpcshell.toml#35

But that should as well be reflected in the log output as shown above. When I query the log viewer for Increasing default timeout nothing is listed which would explain an increase of the default timeout. The maximum is still set to 180s like for this job:

https://treeherder.mozilla.org/logviewer?job_id=542468879&repo=autoland&lineNumber=14584

If we silently applying other multiplicators we should as well log that and not doing it silently.

Summary: Intermittent TV automation.py | application timed out after 740 seconds with no output → Intermittent TV automation.py | application timed out after 740.0 seconds with no output | single tracking bug

It looks like that the increase of this failure on macOS might be related to the Keyboard Setup Assistent dialog which pops-up for all the affected tests.

But not sure if that is actually the real underlying reason why the Firefox window doesn't open at all.

@Ryan are you aware of this dialog? Is that something new or do you already have a bug for it?

Flags: needinfo?(rcurran)

hi :whimboo

we landed a change with a potential fix for this about a month ago. are the keyboard prompts still showing up since then?

thank you

Flags: needinfo?(rcurran) → needinfo?(hskupin)

thank you. i have a new approach im going to test https://github.com/mozilla-platform-ops/ronin_puppet/pull/1141

merged the pr. the change should land on all the mac14/15 workers in an hour or so. keep me posted :whimboo if you still see the issue after that time. thanks

Flags: needinfo?(rcurran)

Great! Let it bake some days given that sometimes new failures appear days after. I'll check back on Monday with the regular triage work if the situation has been improved, and if that keyboard dialog was the reason for the failures at all.

(In reply to Ryan Curran from comment #107)

merged the pr. the change should land on all the mac14/15 workers in an hour or so. keep me posted :whimboo if you still see the issue after that time. thanks

Since the patch landed on all the workers I haven't seen this dialog in a screenshot anymore. Thanks Ryan!

Nevertheless this bug is still not done given that the Firefox window doesn't come up correctly. Marionette is blocked as well with waiting for the initial application window. Maybe some more details logging could help to identify the underlying problem. But lets wait until more failures happen.

You need to log in before you can comment on or make changes to this bug.