1334842 - Intermittent browser/base/content/test/general/browser_temporary_permissions.js | {"state":0,"scope":"{SitePermissions.SCOPE_PERSISTENT}"} deepEqual {"state":2,"scope":"{SitePermissions.SCOPE_TEMPORARY}"} - JS frame :: chrome://mochitests/content/browser/

Reporter

Description

•

8 years ago

treeherder

Filed by: philringnalda [at] gmail.com

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

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

Comment hidden (Intermittent Failures Robot)

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

Repository breakdown:
* autoland: 5
* mozilla-inbound: 1

Platform breakdown:
* linux32: 4
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-01-30&endday=2017-02-05&tree=all

Comment hidden (Intermittent Failures Robot)

19 failures in 833 pushes (0.023 failures/push) were associated with this bug in the last 7 days.  
Repository breakdown:
* autoland: 9
* mozilla-inbound: 7
* try: 1
* mozilla-central: 1
* graphics: 1

Platform breakdown:
* linux32: 17
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-02-13&endday=2017-02-19&tree=all

Comment hidden (Intermittent Failures Robot)

16 failures in 812 pushes (0.02 failures/push) were associated with this bug in the last 7 days.  
Repository breakdown:
* autoland: 7
* mozilla-inbound: 4
* graphics: 4
* mozilla-aurora: 1

Platform breakdown:
* linux32: 15
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-02-20&endday=2017-02-26&tree=all

Comment hidden (Intermittent Failures Robot)

25 failures in 783 pushes (0.032 failures/push) were associated with this bug in the last 7 days.  
Repository breakdown:
* autoland: 11
* mozilla-inbound: 8
* try: 3
* graphics: 2
* mozilla-aurora: 1

Platform breakdown:
* linux32: 25

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-02-27&endday=2017-03-05&tree=all

Comment hidden (Intermittent Failures Robot)

37 failures in 790 pushes (0.047 failures/push) were associated with this bug in the last 7 days. 

This is the #47 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* mozilla-inbound: 10
* mozilla-central: 9
* try: 8
* graphics: 5
* autoland: 4
* oak: 1

Platform breakdown:
* linux32: 28
* linux64: 9

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-03-06&endday=2017-03-12&tree=all

Comment hidden (Intermittent Failures Robot)

20 failures in 777 pushes (0.026 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 10
* mozilla-inbound: 6
* try: 1
* mozilla-central: 1
* mozilla-aurora: 1
* graphics: 1

Platform breakdown:
* linux32: 18
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-03-13&endday=2017-03-19&tree=all

Joel Maher ( :jmaher ) (UTC -8)

Comment 7

•

8 years ago

2 weeks ago this had 37 failures and a few days last week were not very active, but looking at the last week from today, we are right back at the 30+ mark.  This has been trending up for the last few weeks (since about Feb 15th).

the failures are primarily linux debug e10s!

here is a screenshot from a recent linux32 debug failure:
https://public-artifacts.taskcluster.net/cTiZpyxXTcyo_HB594YvnQ/0/public/test_info//mozilla-test-fail-screenshot_rKQJgL.png

and the related log file:
https://public-artifacts.taskcluster.net/cTiZpyxXTcyo_HB594YvnQ/0/public/logs/live_backing.log

and this is a clip from the log ^:
[task 2017-03-21T12:37:07.394391Z] 12:37:07     INFO - TEST-INFO | started process screentopng
[task 2017-03-21T12:37:09.430708Z] 12:37:09     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-21T12:37:09.435734Z] 12:37:09     INFO - Buffered messages logged at 12:36:42
[task 2017-03-21T12:37:09.438892Z] 12:37:09     INFO - Entering test bound testTempPermissionChangeEvents
[task 2017-03-21T12:37:09.441849Z] 12:37:09     INFO - Buffered messages logged at 12:36:57
[task 2017-03-21T12:37:09.446931Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | {"state":2,"scope":"{SitePermissions.SCOPE_TEMPORARY}"} deepEqual {"state":2,"scope":"{SitePermissions.SCOPE_TEMPORARY}"} - 
[task 2017-03-21T12:37:09.453300Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | geo anchor should be visible - 16 != 0 - 
[task 2017-03-21T12:37:09.461464Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | geo anchor should not be visible - 0 == 0 - 
[task 2017-03-21T12:37:09.463958Z] 12:37:09     INFO - Buffered messages logged at 12:36:58
[task 2017-03-21T12:37:09.466577Z] 12:37:09     INFO - Leaving test bound testTempPermissionChangeEvents
[task 2017-03-21T12:37:09.469800Z] 12:37:09     INFO - Entering test bound testTempPermissionRequestAfterExpiry
[task 2017-03-21T12:37:09.476143Z] 12:37:09     INFO - Buffered messages logged at 12:37:01
[task 2017-03-21T12:37:09.479462Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | {"state":2,"scope":"{SitePermissions.SCOPE_TEMPORARY}"} deepEqual {"state":2,"scope":"{SitePermissions.SCOPE_TEMPORARY}"} - 
[task 2017-03-21T12:37:09.481861Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | blocked permission icon is shown - 
[task 2017-03-21T12:37:09.486602Z] 12:37:09     INFO - Buffered messages logged at 12:37:02
[task 2017-03-21T12:37:09.490064Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | {"state":0,"scope":"{SitePermissions.SCOPE_PERSISTENT}"} deepEqual {"state":0,"scope":"{SitePermissions.SCOPE_PERSISTENT}"} - 
[task 2017-03-21T12:37:09.492280Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | blocked permission icon is not shown - 
[task 2017-03-21T12:37:09.494734Z] 12:37:09     INFO - Buffered messages logged at 12:37:03
[task 2017-03-21T12:37:09.496694Z] 12:37:09     INFO - Leaving test bound testTempPermissionRequestAfterExpiry
[task 2017-03-21T12:37:09.501054Z] 12:37:09     INFO - Entering test bound testTempPermissionSubframes
[task 2017-03-21T12:37:09.503087Z] 12:37:09     INFO - Buffered messages logged at 12:37:06
[task 2017-03-21T12:37:09.505070Z] 12:37:09     INFO - TEST-PASS | browser/base/content/test/general/browser_temporary_permissions.js | "example.org" != "example.com" - 
[task 2017-03-21T12:37:09.507018Z] 12:37:09     INFO - Buffered messages finished
[task 2017-03-21T12:37:09.509800Z] 12:37:09     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_temporary_permissions.js | {"state":0,"scope":"{SitePermissions.SCOPE_PERSISTENT}"} deepEqual {"state":2,"scope":"{SitePermissions.SCOPE_TEMPORARY}"} - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_temporary_permissions.js :: testTempPermissionSubframes/< :: line 121
[task 2017-03-21T12:37:09.512455Z] 12:37:09     INFO - Stack trace:
[task 2017-03-21T12:37:09.514388Z] 12:37:09     INFO -     chrome://mochitests/content/browser/browser/base/content/test/general/browser_temporary_permissions.js:testTempPermissionSubframes/<:121
[task 2017-03-21T12:37:09.516921Z] 12:37:09     INFO -     testTempPermissionSubframes@chrome://mochitests/content/browser/browser/base/content/test/general/browser_temporary_permissions.js:96:9
[task 2017-03-21T12:37:09.518835Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-21T12:37:09.521467Z] 12:37:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-21T12:37:09.523421Z] 12:37:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-21T12:37:09.525355Z] 12:37:09     INFO -     Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-21T12:37:09.527370Z] 12:37:09     INFO -     TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-21T12:37:09.530409Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-21T12:37:09.532176Z] 12:37:09     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-21T12:37:09.534202Z] 12:37:09     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-21T12:37:09.536875Z] 12:37:09     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-21T12:37:09.538649Z] 12:37:09     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-21T12:37:09.541849Z] 12:37:09     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-21T12:37:09.543648Z] 12:37:09     INFO -     promise callback*completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:698:7
[task 2017-03-21T12:37:09.545386Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:324:15
[task 2017-03-21T12:37:09.547439Z] 12:37:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-21T12:37:09.552836Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-21T12:37:09.555444Z] 12:37:09     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-21T12:37:09.557389Z] 12:37:09     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-21T12:37:09.559334Z] 12:37:09     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-21T12:37:09.561115Z] 12:37:09     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-21T12:37:09.563419Z] 12:37:09     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-21T12:37:09.565568Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:324:15
[task 2017-03-21T12:37:09.568692Z] 12:37:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-21T12:37:09.570573Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-21T12:37:09.572340Z] 12:37:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-21T12:37:09.574021Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-21T12:37:09.586963Z] 12:37:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-21T12:37:09.589658Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-21T12:37:09.591794Z] 12:37:09     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-21T12:37:09.595676Z] 12:37:09     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-21T12:37:09.597737Z] 12:37:09     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-21T12:37:09.599505Z] 12:37:09     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-21T12:37:09.601342Z] 12:37:09     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-21T12:37:09.604897Z] 12:37:09     INFO -     setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:672:12
[task 2017-03-21T12:37:09.606817Z] 12:37:09     INFO -     testTempPermissionRequestAfterExpiry/</<@chrome://mochitests/content/browser/browser/base/content/test/general/browser_temporary_permissions.js:64:30
[task 2017-03-21T12:37:09.608891Z] 12:37:09     INFO -     Promise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:390:5
[task 2017-03-21T12:37:09.611037Z] 12:37:09     INFO -     testTempPermissionRequestAfterExpiry/<@chrome://mochitests/content/browser/browser/base/content/test/general/browser_temporary_permissions.js:64:11
[task 2017-03-21T12:37:09.613852Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-21T12:37:09.615542Z] 12:37:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-21T12:37:09.617536Z] 12:37:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-21T12:37:09.622515Z] 12:37:09     INFO -     Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-21T12:37:09.624241Z] 12:37:09     INFO -     TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-21T12:37:09.625955Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-21T12:37:09.627813Z] 12:37:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-21T12:37:09.629838Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-21T12:37:09.632982Z] 12:37:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-21T12:37:09.634826Z] 12:37:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-21T12:37:09.639098Z] 12:37:09     INFO -     testTempPermissionRequestAfterExpiry@chrome://mochitests/content/browser/browser/base/content/test/general/browser_temporary_permissions.js:51:9
[task 2017-03-21T12:37:09.640836Z] 12:37:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-21T12:37:09.642737Z] 12:37:09     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-21T12:37:09.647096Z] 12:37:09     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-21T12:37:09.651715Z] 12:37:09     INFO - Leaving test bound testTempPermissionSubframes
[task 2017-03-21T12:37:09.967446Z] 12:37:09     INFO - GECKO(1289) | MEMORY STAT | vsize 1285MB | residentFast 346MB | heapAllocated 132MB
[task 2017-03-21T12:37:09.975305Z] 12:37:09     INFO - TEST-OK | browser/base/content/test/general/browser_temporary_permissions.js | took 27597ms


it appears we are failing on the last check of the test:
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/general/browser_temporary_permissions.js#121


:johann, I see you are the author of this test, any ideas why this might be happening on linux debug e10s frequently?

Flags: needinfo?(jhofmann)

Whiteboard: [stockwell needswork]

Johann Hofmann [:johannh]

Assignee

Comment 8

•

8 years ago

Yes, I've been watching this for some time, but didn't really prioritize it because it didn't seem too frequent. It's likely a timing issue since the screenshot shows the correct state but we probably assert a tiny bit too early (which is strange).

I'll try to get it soon. Marking for triage for now.

Component: General → Site Identity and Permission Panels

Flags: needinfo?(jhofmann)

Whiteboard: [stockwell needswork] → [stockwell needswork] [fxprivacy] [triage]

Comment hidden (Intermittent Failures Robot)

33 failures in 898 pushes (0.037 failures/push) were associated with this bug in the last 7 days. 

This is the #43 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 12
* mozilla-inbound: 9
* try: 4
* graphics: 4
* mozilla-central: 2
* oak: 1
* mozilla-aurora: 1

Platform breakdown:
* linux32: 26
* linux64: 7

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-03-20&endday=2017-03-26&tree=all

Johann Hofmann [:johannh]

Assignee

Updated

•

8 years ago

Assignee: nobody → jhofmann

Status: NEW → ASSIGNED

Priority: -- → P1

Whiteboard: [stockwell needswork] [fxprivacy] [triage] → [stockwell needswork] [fxprivacy]

Johann Hofmann [:johannh]

Assignee

Comment 10

•

8 years ago

https://treeherder.mozilla.org/#/jobs?repo=try&revision=03a1917c2a9614a27d5b444e148bafaa4d23f871

Johann Hofmann [:johannh]

Assignee

Comment 11

•

8 years ago

https://treeherder.mozilla.org/#/jobs?repo=try&revision=dece482b62d59aa828d529f2cf22bd58d3270e58

Comment hidden (mozreview-request)

This intermittent was likely occurring because we set the expiry timeout
for temporary permissions to a really low value in the previous test.
The failing test was only failing on slow machines, leading me to believe
that the time between setting and checking was larger than the 500ms timeout
defined in the previous test. Thus, the permission was reset on checking it.
The expiry pref was set using pushPrefEnv, which restores prefs only after
the entire test was run. To just eradicate this category of problems in
the future I moved the test that manipulates the expiry into its own file.

Review commit: https://reviewboard.mozilla.org/r/125032/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/125032/

Johann Hofmann [:johannh]

Assignee

Updated

•

8 years ago

Attachment #8852893 - Flags: review?(nhnt11)

(inactive) Nihanth Subramanya [:nhnt11]

Comment 13

•

8 years ago

mozreview-review

Comment on attachment 8852893 [details]
Bug 1334842 - Fix intermittent browser_temporary_permissions.js.

https://reviewboard.mozilla.org/r/125032/#review127884

Attachment #8852893 - Flags: review?(nhnt11) → review+

Pulsebot

Comment 14

•

8 years ago

Pushed by jhofmann@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bb2b3077d339
Fix intermittent browser_temporary_permissions.js. r=Nihanth

Carsten Book [:Tomcat]

Comment 15

•

8 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/bb2b3077d339

Status: ASSIGNED → RESOLVED

Closed: 8 years ago

status-firefox55: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → Firefox 55

Ryan VanderMeulen [:RyanVM]

Updated

•

8 years ago

status-firefox52: --- → unaffected

status-firefox53: --- → affected

status-firefox54: --- → affected

status-firefox-esr52: --- → unaffected

Ryan VanderMeulen [:RyanVM]

Comment 16

•

8 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-aurora/rev/2e3854301739

status-firefox54: affected → fixed

Flags: in-testsuite+

Whiteboard: [stockwell needswork] [fxprivacy] → [stockwell fixed][fxprivacy]

Ryan VanderMeulen [:RyanVM]

Comment 17

•

8 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-beta/rev/98bf63856a7b

status-firefox53: affected → fixed

Comment hidden (Intermittent Failures Robot)

34 failures in 845 pushes (0.04 failures/push) were associated with this bug in the last 7 days.   

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 14
* mozilla-inbound: 10
* mozilla-central: 4
* graphics: 3
* try: 2
* mozilla-beta: 1

Platform breakdown:
* linux32: 24
* linux64: 10

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1334842&startday=2017-03-27&endday=2017-04-02&tree=all