Closed Bug 1334842 Opened 3 years ago Closed 3 years ago

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/

Categories

(Firefox :: Site Identity, defect, P1)

defect

Tracking

()

RESOLVED FIXED
Firefox 55
Tracking Status
firefox52 --- unaffected
firefox-esr52 --- unaffected
firefox53 --- fixed
firefox54 --- fixed
firefox55 --- fixed

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed][fxprivacy])

Attachments

(1 file)

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]
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]
Assignee: nobody → jhofmann
Status: NEW → ASSIGNED
Priority: -- → P1
Whiteboard: [stockwell needswork] [fxprivacy] [triage] → [stockwell needswork] [fxprivacy]
Attachment #8852893 - Flags: review?(nhnt11)
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+
Pushed by jhofmann@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bb2b3077d339
Fix intermittent browser_temporary_permissions.js. r=Nihanth
https://hg.mozilla.org/mozilla-central/rev/bb2b3077d339
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
https://hg.mozilla.org/releases/mozilla-aurora/rev/2e3854301739
Flags: in-testsuite+
Whiteboard: [stockwell needswork] [fxprivacy] → [stockwell fixed][fxprivacy]
You need to log in before you can comment on or make changes to this bug.