1540367 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK

Status: RESOLVED INCOMPLETE

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

#[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 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
02:40:31 INFO - PID 10356 | 1553913631932 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
02:40:31 INFO - PID 10356 | 1553913631932 [e-mail] WARN Loading extension '[e-mail]': 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/

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2019-03-25&endday=2019-03-31&tree=all

Comment 2

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

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

Comment 3

[Firefox Bug Husbandry Bot]

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

Comment 4

[Razvan Maries]

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2019-12-02&endday=2019-12-08&tree=all

Comment 6

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

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

Comment 7

[Alexandru Michis [:malexandru]]

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

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 6

Platform breakdown:

• linux1804-64-qr: 5
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-03-09&endday=2020-03-15&tree=all

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 7
• try: 2

Platform breakdown:

• linux1804-64-qr: 9

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 10

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

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

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 7

Platform breakdown:

• linux1804-64-qr: 6
• linux1804-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 12

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

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.

Comment 13

[Florian Quèze [:florian]]

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.

Comment 14

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 3
• mozilla-central: 1

Platform breakdown:

• linux1804-64-qr: 3
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 6
• try: 1
• autoland: 1

Platform breakdown:

• linux1804-64-qr: 7
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1
• autoland: 1
• mozilla-central: 6

Platform breakdown:

• linux1804-64-qr: 7
• macosx1014-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 17

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

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.

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• linux1804-64-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-04-27&endday=2020-05-03&tree=all

Comment 19

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 4

Platform breakdown:

• linux1804-64-shippable-qr: 1
• linux1804-64-qr: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1540367&startday=2020-05-18&endday=2020-05-24&tree=all

Comment 21

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.

Comment 22

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-03-27&endday=2023-04-02&tree=all

Comment 23

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

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.

Comment 24

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

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

Comment 25

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

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.

Comment 26

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4
• mozilla-central: 2
• try: 2

Platform and build breakdown:

• linux1804-64-tsan-qr: 6
  • opt: 6
• windows11-64-2009-qr: 1
  • opt: 1
• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-06-19&endday=2023-06-25&tree=all

Comment 27

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

• windows11-64-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-06-26&endday=2023-07-02&tree=all

Comment 28

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

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

Comment 29

[Intermittent Failures Robot]

1 failures in 2956 pushes (0.0 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: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-07-03&endday=2023-07-09&tree=all

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1
• mozilla-esr102: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-07-10&endday=2023-07-16&tree=all

Comment 31

[Intermittent Failures Robot]

1 failures in 3276 pushes (0.0 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: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-07-31&endday=2023-08-06&tree=all

Comment 32

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

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

Comment 33

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=428873903&repo=mozilla-central

Comment 34

[Intermittent Failures Robot]

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-09-11&endday=2023-09-17&tree=all

Comment 35

[Intermittent Failures Robot]

1 failures in 4018 pushes (0.0 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-shippable-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-10-02&endday=2023-10-08&tree=all

Comment 36

[Intermittent Failures Robot]

1 failures in 3484 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-shippable-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1540367&startday=2023-10-16&endday=2023-10-22&tree=all

Comment 37

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

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