#[markdown(off)]
Filed by: opoprus [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=237077743&repo=mozilla-central

https://queue.taskcluster.net/v1/task/YHuzGeBuTKC8PZtcnoJnWA/runs/0/artifacts/public/logs/live_backing.log

02:40:30 INFO - TEST-START | /webdriver/tests/back/back.py
02:40:31 INFO - STDOUT: ============================= test session starts =============================
02:40:31 INFO - STDOUT: platform win32 -- Python 2.7.15, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- Z:\task_1553910095\build\venv\Scripts\python.exe
02:40:31 INFO - STDOUT: rootdir: Z:\task_1553910095\build, inifile:
02:40:31 INFO - STDOUT: collecting ...
02:40:31 INFO - STDOUT: collected 7 items
02:40:31 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/back/back.py::test_null_response_value
02:40:31 INFO - PID 10356 | 1553913631304 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"binary": "Z:\\task_1553910095\\build\\application\\firefox\\firefox.exe", "prefs": {"network.dns.localDomains": "www1.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www1.web-platform.test,www.www2.not-web-platform.test,www2.www2.not-web-platform.test,xn--lve-6lad.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.not-web-platform.test,not-web-platform.test,www1.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.web-platform.test,www2.not-web-platform.test,www1.not-web-platform.test,www1.www1.web-platform.test,www2.xn--lve-6lad.web-platform.test,www1.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.not-web-platform.test,www2.www1.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.not-web-platform.test,xn--lve-6lad.www.web-platform.test,www.www.web-platform.test,www1.xn--lve-6lad.web-platform.test,xn--lve-6lad.www2.web-platform.test,www.www2.web-platform.test,www2.www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.not-web-platform.test,www1.www.web-platform.test,www.xn--lve-6lad.web-platform.test,www.www.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.web-platform.test,xn--lve-6lad.www1.not-web-platform.test,www1.www1.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.not-web-platform.test,www2.www2.web-platform.test,xn--lve-6lad.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.web-platform.test,xn--lve-6lad.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www2.xn--lve-6lad.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.web-platform.test,www1.xn--lve-6lad.not-web-platform.test,www1.web-platform.test,www.www1.web-platform.test,www2.web-platform.test,www.xn--lve-6lad.not-web-platform.test,www.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.not-web-platform.test,www2.www1.web-platform.test,www.www1.not-web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test"}}}}}
02:40:31 INFO - PID 10356 | 1553913631309 mozrunner::runner INFO Running command: "Z:\\task_1553910095\\build\\application\\firefox\\firefox.exe" "-marionette" "-foreground" "-no-remote" "-profile" "C:\\Users\\task_1553910095\\AppData\\Local\\Temp\\rust_mozprofile.BWbEMKQubRSz"
02:40:31 INFO - PID 10356 | 1553913631317 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:2828
02:40:31 INFO - PID 10356 | 1553913631931 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
02:40:31 INFO - PID 10356 | 1553913631932 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
02:40:31 INFO - PID 10356 | 1553913631932 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
02:40:32 INFO - PID 10356 | 1553913632098 Marionette TRACE Received observer notification profile-after-change
02:40:32 INFO - PID 10356 | 1553913632177 Marionette TRACE Received observer notification toplevel-window-ready
02:40:32 INFO - PID 10356 | 1553913632242 Marionette TRACE Received observer notification command-line-startup
02:40:32 INFO - PID 10356 | 1553913632242 Marionette TRACE Received observer notification nsPref:changed
02:40:32 INFO - PID 10356 | 1553913632242 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
02:41:00 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK
02:41:00 INFO - TEST-INFO took 30032ms
02:41:00 INFO - Closing logging queue
02:41:00 INFO - queue closed
02:41:00 INFO - Starting runner
02:41:01 INFO - PID 1692 | 1553913661058 webdriver::httpapi DEBUG Creating routes
02:41:01 INFO - PID 1692 | 1553913661067 geckodriver DEBUG Listening on 127.0.0.1:4444
02:41:01 INFO - WebDriver HTTP server listening at http://127.0.0.1:4444/

There was no marionette-startup-requested observer notification, which means it depends on bug 1382162.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

New occurrence; https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=279014545&repo=mozilla-central&lineNumber=5647

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

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293063000&repo=mozilla-central&lineNumber=1852

All the recent classified failures were against Fission related test jobs. So bug 1625413 has been created for.

This is actually caused by a 30s long start-up delay of Firefox before the first window gets opened.

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=295243112&repo=mozilla-central&lineNumber=1105-1131

[task 2020-03-29T11:39:08.833Z] 11:39:08     INFO - PID 757 | DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase OS.File: Waiting for clients before profileBeforeChange
[task 2020-03-29T11:39:08.854Z] 11:39:08     INFO - PID 757 | DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2020-03-29T11:39:29.929Z] 11:39:29     INFO - PID 757 | DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2020-03-29T11:39:29.937Z] 11:39:29     INFO - PID 757 | 1585481969933	Marionette	TRACE	Marionette enabled
[task 2020-03-29T11:39:30.059Z] 11:39:30     INFO - PID 757 | 1585481970056	Marionette	TRACE	Received observer notification toplevel-window-ready

Florian, does the above information help you so we can get a specific bug filed? I wonder what's happening between the TelemetryController and EnvironmentAddonBuilder entries. Note that this problem only happened for the very first run of Firefox for this test job. I assume a lot of other Wd spec tests are affected by that too.

Given that it's on Ubuntu 18.04, it's very likely to be the same problem as what we see in bug 1624868 where we get blocked on a system library (dbus) when we make our first window visible.

Ok, i found the problem here. This is only happening for the first startup of Firefox when running Marionette on Ubuntu 18.04, and it's all caused by building-up the not yet populated font cache.

With bug 1822466 more tests have been added and now the test runs more often into a timeout due to the additional restarts. I'm going to fix that on bug 1839123.

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

The removal of the acceptInsecureCerts capability requirement which causes lesser restarts of Firefox helped:

Before:

[task 2023-06-20T04:29:47.679Z] 04:29:47     INFO - TEST-START | /webdriver/tests/classic/back/back.py
[..]
[task 2023-06-20T04:31:07.683Z] 04:31:07     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/classic/back/back.py | expected OK
[task 2023-06-20T04:31:07.684Z] 04:31:07     INFO - TEST-INFO took 80004ms

After:

[task 2023-06-21T04:40:04.552Z] 04:40:04     INFO - TEST-START | /webdriver/tests/classic/back/back.py
[..]
[task 2023-06-21T04:40:40.144Z] 04:40:40     INFO - TEST-OK | /webdriver/tests/classic/back/back.py | took 35591ms

As it can be seen we no longer run into a timeout for TSAN builds after 80s but roughly take only half the time now. I expect that the intermittent failures for this bug will drop drastically.

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