Intermittent browser/base/content/test/permissions/browser_autoplay_blocked.js | Test timed out -

REOPENED
Assigned to

Status

()

defect
P5
normal
REOPENED
3 months ago
Yesterday

People

(Reporter: intermittent-bug-filer, Assigned: daleharvey)

Tracking

({intermittent-failure, regression})

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [stockwell unknown])

Attachments

(2 attachments)

Reporter

Description

3 months ago
treeherder

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

https://treeherder.mozilla.org/logviewer.html#?job_id=235770448&repo=autoland

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

00:24:52 INFO - TEST-START | accessible/tests/browser/states/browser_test_visibility.js
00:24:52 INFO - GECKO(2632) | MEMORY STAT | vsize 2103093MB | vsizeMaxContiguous 65154397MB | residentFast 274MB | heapAllocated 131MB
00:24:52 INFO - TEST-OK | accessible/tests/browser/states/browser_test_visibility.js | took 762ms

00:25:44 INFO - TEST-PASS | browser/base/content/test/permissions/browser_autoplay_blocked.js | Blocked icon is hidden -
00:25:44 INFO - Leaving test bound testChangingBlockingSettingDuringNavigation
00:25:44 INFO - Entering test bound testSlowLoadingPage
00:25:44 INFO - Console message: [JavaScript Warning: "Autoplay is only allowed when approved by the user, the site is activated by the user, or media is muted." {file: "https://example.com/browser/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs" line: 0}]
00:25:44 INFO - Buffered messages finished
00:25:44 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Test timed out -
00:25:44 INFO - GECKO(8100) | MEMORY STAT | vsize 2103098MB | vsizeMaxContiguous 65651462MB | residentFast 234MB | heapAllocated 81MB
00:25:44 INFO - TEST-OK | browser/base/content/test/permissions/browser_autoplay_blocked.js | took 45056ms
00:25:44 INFO - Not taking screenshot here: see the one that was previously logged
00:25:44 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: https://example.com/browser/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs#foo -
00:25:44 INFO - Not taking screenshot here: see the one that was previously logged
00:25:44 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: about:home -
00:25:44 INFO - checking window state

Appeared when bug 1534219 landed.

Comment hidden (Intermittent Failures Robot)
Component: Preferences → Site Identity and Permission Panels

There are 23 total failures in the last 7 days, on linux32, linux64, osx-10-10, windows10 and windows7-32 all build types.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=236298532&repo=autoland&lineNumber=1870

[task 2019-03-27T05:26:55.243Z] 05:26:55 INFO - TEST-PASS | browser/base/content/test/permissions/browser_autoplay_blocked.js | Blocked icon is hidden -
[task 2019-03-27T05:26:55.245Z] 05:26:55 INFO - Leaving test bound testChangingBlockingSettingDuringNavigation
[task 2019-03-27T05:26:55.247Z] 05:26:55 INFO - Entering test bound testSlowLoadingPage
[task 2019-03-27T05:26:55.249Z] 05:26:55 INFO - Console message: [JavaScript Warning: "Autoplay is only allowed when approved by the user, the site is activated by the user, or media is muted." {file: "https://example.com/browser/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs" line: 0}]
[task 2019-03-27T05:26:55.250Z] 05:26:55 INFO - Buffered messages finished
[task 2019-03-27T05:26:55.252Z] 05:26:55 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Test timed out -
[task 2019-03-27T05:26:55.254Z] 05:26:55 INFO - GECKO(1849) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2019-03-27T05:26:55.254Z] 05:26:55 INFO - GECKO(1849) | MEMORY STAT | vsize 2164MB | residentFast 294MB | heapAllocated 109MB
[task 2019-03-27T05:26:55.256Z] 05:26:55 INFO - TEST-OK | browser/base/content/test/permissions/browser_autoplay_blocked.js | took 45027ms
[task 2019-03-27T05:26:55.257Z] 05:26:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-03-27T05:26:55.258Z] 05:26:55 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: https://example.com/browser/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs#foo -
[task 2019-03-27T05:26:55.260Z] 05:26:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-03-27T05:26:55.261Z] 05:26:55 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: about:home -
[task 2019-03-27T05:26:55.262Z] 05:26:55 INFO - checking window state

Dale, please take a look.

Flags: needinfo?(dharvey)
Whiteboard: [stockwell needswork:owner]
Comment hidden (Intermittent Failures Robot)

Update:
There have been 35 failures within the last 7 days:

  • 7 failures on Linux shippable opt
  • 4 failures on Linux x64 CCov debug
  • 2 failures on Linux x64 shippable opt
  • 14 failures on OS X 10.10 shippable opt
  • 1 failure on Windows 10 x64 opt
  • 3 failures on Windows 10 x64 Shippable opt
  • 1 failure on Windows 7 opt
  • 2 failures on Windows 7 Shippable opt
Comment hidden (Intermittent Failures Robot)
Assignee

Comment 8

2 months ago

So I cant get this to fail for me, under --verify or whatever

However these changes seem like they may make the test more stable

Flags: needinfo?(dharvey)

Comment 9

2 months ago
Pushed by dharvey@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d2dfbfc9da12
Dont depend on event for icon shown condition. r=johannh

Comment 10

2 months ago
bugherder
Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 68
Assignee: nobody → dharvey

This is still happening.

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=239984420&repo=mozilla-central&lineNumber=3029

[task 2019-04-12T18:01:02.485Z] 18:01:02 INFO - TEST-PASS | browser/base/content/test/permissions/browser_autoplay_blocked.js | Blocked icon is hidden -
[task 2019-04-12T18:01:02.486Z] 18:01:02 INFO - Leaving test bound testChangingBlockingSettingDuringNavigation
[task 2019-04-12T18:01:02.487Z] 18:01:02 INFO - Entering test bound testSlowLoadingPage
[task 2019-04-12T18:01:02.487Z] 18:01:02 INFO - Console message: [JavaScript Warning: "Autoplay is only allowed when approved by the user, the site is activated by the user, or media is muted." {file: "https://example.com/browser/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs" line: 0}]
[task 2019-04-12T18:01:02.488Z] 18:01:02 INFO - Console message: [JavaScript Error: "RemoteWebProgress failed to call onStatusChange: [Exception... "JavaScript component does not have a method named: "onStatusChange"'JavaScript component does not have a method named: "onStatusChange"' when calling method: [nsIWebProgressListener::onStatusChange]" nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)" location: "JS frame :: resource://gre/modules/RemoteWebProgress.jsm :: _callProgressListeners :: line 103" data: no]
[task 2019-04-12T18:01:02.489Z] 18:01:02 INFO - " {file: "resource://gre/modules/RemoteWebProgress.jsm" line: 105}]
[task 2019-04-12T18:01:02.489Z] 18:01:02 INFO - _callProgressListeners@resource://gre/modules/RemoteWebProgress.jsm:105:14
[task 2019-04-12T18:01:02.490Z] 18:01:02 INFO - onStatusChange@resource://gre/modules/RemoteWebProgress.jsm:135:10
[task 2019-04-12T18:01:02.490Z] 18:01:02 INFO -
[task 2019-04-12T18:01:02.490Z] 18:01:02 INFO - Buffered messages finished
[task 2019-04-12T18:01:02.491Z] 18:01:02 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Test timed out -
[task 2019-04-12T18:01:02.492Z] 18:01:02 INFO - GECKO(2657) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2019-04-12T18:01:02.493Z] 18:01:02 INFO - GECKO(2657) | MEMORY STAT | vsize 798MB | residentFast 283MB | heapAllocated 95MB
[task 2019-04-12T18:01:02.493Z] 18:01:02 INFO - TEST-OK | browser/base/content/test/permissions/browser_autoplay_blocked.js | took 45047ms
[task 2019-04-12T18:01:02.494Z] 18:01:02 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-04-12T18:01:02.494Z] 18:01:02 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: https://example.com/browser/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs#foo -
[task 2019-04-12T18:01:02.495Z] 18:01:02 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-04-12T18:01:02.495Z] 18:01:02 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: about:home -
[task 2019-04-12T18:01:02.496Z] 18:01:02 INFO - checking window state

Status: RESOLVED → REOPENED
Flags: needinfo?(dharvey)
Resolution: FIXED → ---
Duplicate of this bug: 1544086
Comment hidden (Intermittent Failures Robot)
Assignee

Comment 14

2 months ago

ok will take another shot

Flags: needinfo?(dharvey)
Comment hidden (Intermittent Failures Robot)

Comment 16

2 months ago

There are 30 total failures in the las 7 days on multiple platforms. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-17&endday=2019-04-24&tree=trunk&bug=1538602

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242187539&repo=autoland&lineNumber=1319

00:07:04 INFO - TEST-START | browser/base/content/test/permissions/browser_autoplay_blocked.js
00:07:49 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Test timed out -
00:07:49 INFO - GECKO(823) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
00:07:49 INFO - GECKO(823) | MEMORY STAT | vsize 5424MB | residentFast 328MB | heapAllocated 94MB
00:07:49 INFO - TEST-OK | browser/base/content/test/permissions/browser_autoplay_blocked.js | took 45018ms
00:07:49 INFO - Not taking screenshot here: see the one that was previously logged
00:07:49 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: https://example.com/browser/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs#foo -
00:07:49 INFO - Not taking screenshot here: see the one that was previously logged
00:07:49 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_autoplay_blocked.js | Found a tab after previous test timed out: about:home -
00:07:49 INFO - checking window state

Comment hidden (Intermittent Failures Robot)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork]
Comment hidden (Intermittent Failures Robot)

There are 26 failures in the last 7 days, across windows, linux and mac platforms: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-28&endday=2019-05-05&tree=trunk&bug=1538602

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244191821&repo=autoland&lineNumber=1560

Dale, do you have any updates on this? Thank you.

Flags: needinfo?(dharvey)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Assignee

Comment 24

Last month

So not sure this is the cause of the failure since I get it on passing tests runs as well, but probably worth checking whats up, I am seeing

12:03:16 INFO - Console message: [JavaScript Error: "RemoteWebProgress failed to call onStateChange: [Exception... "JavaScript component does not have a method named: "onStateChange"'JavaScript component does not have a method named: "onStateChange"' when calling method: [nsIWebProgressListener::onStateChange]" nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)" location: "JS frame :: resource://gre/modules/RemoteWebProgress.jsm :: _callProgressListeners :: line 103" data: no]
12:03:16 INFO - " {file: "resource://gre/modules/RemoteWebProgress.jsm" line: 105}]

During these test runs, even ones that are passing locally, https://treeherder.mozilla.org/logviewer.html#?job_id=248181536&repo=mozilla-central is an example, these never used to happen when I was working on these tests in the first place

Barret I seen that you touched a lot of the RemoteWebProgress stuff recently, do you know what causes this / how to get rid of these errors. Cheers

https://searchfox.org/mozilla-central/source/browser/modules/SitePermissions.jsm#172 is the caller here

Flags: needinfo?(dharvey) → needinfo?(brennie)

Hi :daleharvey

That example calls browser.addProgressListener with only onLocationChangeDefined. nsIWebProgress::AddProgressListener takes second argument which indicates what events it wants to be notified on. It should pass (Ci.nsIWebProgress.NOTIFY_LOCATION](https://searchfox.org/mozilla-central/source/uriloader/base/nsIWebProgress.idl#94) as the second argument.

Hitting these errors won't cause anything to fail. They are handled gracefully.

Flags: needinfo?(brennie)
Comment hidden (Intermittent Failures Robot)

Comment 28

24 days ago
Pushed by dharvey@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/566166b6edfb
Improve logging during block autoplay tests. r=johannh

Comment 29

24 days ago
bugherder
Status: REOPENED → RESOLVED
Closed: 2 months ago24 days ago
Resolution: --- → FIXED
Status: RESOLVED → REOPENED
Flags: needinfo?(dharvey)
Resolution: FIXED → ---
Target Milestone: Firefox 68 → ---
Comment hidden (Intermittent Failures Robot)
Assignee

Comment 32

22 days ago

Yeh hoping the last commit would fix this was quite optimistic, it was mostly to help debugging. However narrowed down the issue now, https://searchfox.org/mozilla-central/source/browser/base/content/test/permissions/browser_autoplay_blocked_slow.sjs will very occasionally just never finish loading, the 'load' event never fires in content and the screenshot shows the throbber permanently.

So now just to figure out why or how to work around that

Flags: needinfo?(dharvey)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.