Open Bug 1304273 Opened 3 years ago Updated 11 days ago

Intermittent browser/base/content/test/general/browser_offlineQuotaNotification.js | Test timed out -

Categories

(Firefox :: General, defect, P5)

defect

Tracking

()

Tracking Status
firefox52 --- disabled
firefox-esr52 --- disabled
firefox53 --- disabled
firefox54 --- disabled

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(2 files)

this is hitting our threshold of 30 failures/week (given recent data)- I am starting to look into this.  On Feb 2nd, this started up, I have done a lot of retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=linux%20opt%20browser-chrome-2&tochange=4e2d67e6ce3e81bc357e7c7992b35a2a9ccd9f49&fromchange=58967ce933159d16ac5825830782d670ce105d0e&selectedJob=73989810

the test finishes typically in <5 seconds, especially on linux32/64 opt/pgo where this is failing.  this is not failing in e10s mode.

this is the error we get:
TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_offlineQuotaNotification.js | A promise chain failed to handle a rejection: - at chrome://mochitests/content/browser/browser/base/content/test/general/browser_offlineQuotaNotification.js:69 - TypeError: PopupNotifications.panel.firstElementChild is null


and from the same log[0] we get this full output:
[task 2017-02-02T19:34:39.169204Z] 19:34:39     INFO - TEST-START | browser/base/content/test/general/browser_offlineQuotaNotification.js
[task 2017-02-02T19:34:40.320998Z] 19:34:40     INFO - *************************
[task 2017-02-02T19:34:40.324912Z] 19:34:40     INFO - A coding exception was thrown in a Promise resolution callback.
[task 2017-02-02T19:34:40.325301Z] 19:34:40     INFO - See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
[task 2017-02-02T19:34:40.328031Z] 19:34:40     INFO - Full message: TypeError: PopupNotifications.panel.firstElementChild is null
[task 2017-02-02T19:34:40.336567Z] 19:34:40     INFO - Full stack: test/</<@chrome://mochitests/content/browser/browser/base/content/test/general/browser_offlineQuotaNotification.js:69:7
[task 2017-02-02T19:34:40.338163Z] 19:34:40     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-02-02T19:34:40.340044Z] 19:34:40     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-02-02T19:34:40.342385Z] 19:34:40     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-02-02T19:34:40.345035Z] 19:34:40     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-02-02T19:34:40.345425Z] 19:34:40     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-02-02T19:34:40.348984Z] 19:34:40     INFO - receiveMessage@resource://testing-common/ContentTask.jsm:113:9
[task 2017-02-02T19:34:40.350973Z] 19:34:40     INFO - *************************
[task 2017-02-02T19:34:47.100854Z] 19:34:47     INFO - TEST-INFO | started process screentopng
[task 2017-02-02T19:34:47.993024Z] 19:34:47     INFO - TEST-INFO | screentopng: exit 0
[task 2017-02-02T19:34:47.996736Z] 19:34:47     INFO - Buffered messages logged at 19:34:40
[task 2017-02-02T19:34:47.998495Z] 19:34:47     INFO - Loaded page, adding onCached handler
[task 2017-02-02T19:34:48.002018Z] 19:34:48     INFO - Console message: Offline cache update done, URL=http://mochi.test:8888/browser/browser/base/content/test/general/offlineQuotaNotification.cacheManifest
[task 2017-02-02T19:34:48.004106Z] 19:34:48     INFO - TEST-PASS | browser/base/content/test/general/browser_offlineQuotaNotification.js | have offline-app-usage notification - 
[task 2017-02-02T19:34:48.006060Z] 19:34:48     INFO - Buffered messages finished
[task 2017-02-02T19:34:48.008544Z] 19:34:48     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_offlineQuotaNotification.js | A promise chain failed to handle a rejection:  - at chrome://mochitests/content/browser/browser/base/content/test/general/browser_offlineQuotaNotification.js:69 - TypeError: PopupNotifications.panel.firstElementChild is null
[task 2017-02-02T19:34:48.010770Z] 19:34:48     INFO - Stack trace:
[task 2017-02-02T19:34:48.012999Z] 19:34:48     INFO - test/</<@chrome://mochitests/content/browser/browser/base/content/test/general/browser_offlineQuotaNotification.js:69:7
[task 2017-02-02T19:34:48.016334Z] 19:34:48     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-02-02T19:34:48.020103Z] 19:34:48     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-02-02T19:34:48.022158Z] 19:34:48     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-02-02T19:34:48.024027Z] 19:34:48     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-02-02T19:34:48.025904Z] 19:34:48     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-02-02T19:34:48.027681Z] 19:34:48     INFO - receiveMessage@resource://testing-common/ContentTask.jsm:113:9
[task 2017-02-02T19:35:09.150492Z] 19:35:09     INFO - Console message: [JavaScript Error: "1486064109090	Toolkit.Telemetry	ERROR	TelemetrySend::_doPing - error making request to https://127.0.0.1:8888/telemetry-dummy//submit/telemetry/6b46a1d1-91fb-45f3-ba64-88b213b59a67/main/Firefox/54.0a1/default/20170202190229?v=4: timeout" {file: "resource://gre/modules/Log.jsm" line: 748}]
[task 2017-02-02T19:35:09.151235Z] 19:35:09     INFO - App_append@resource://gre/modules/Log.jsm:748:9
[task 2017-02-02T19:35:09.154182Z] 19:35:09     INFO - log@resource://gre/modules/Log.jsm:386:7
[task 2017-02-02T19:35:09.155719Z] 19:35:09     INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:501:44
[task 2017-02-02T19:35:09.157622Z] 19:35:09     INFO - error@resource://gre/modules/Log.jsm:394:5
[task 2017-02-02T19:35:09.160481Z] 19:35:09     INFO - errorhandler@resource://gre/modules/TelemetrySend.jsm:951:7
[task 2017-02-02T19:35:09.160829Z] 19:35:09     INFO - EventHandlerNonNull*_doPing@resource://gre/modules/TelemetrySend.jsm:955:5
[task 2017-02-02T19:35:09.161138Z] 19:35:09     INFO - sendPings/p<@resource://gre/modules/TelemetrySend.jsm:784:17
[task 2017-02-02T19:35:09.161379Z] 19:35:09     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-02-02T19:35:09.164385Z] 19:35:09     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-02-02T19:35:09.166401Z] 19:35:09     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-02-02T19:35:09.168561Z] 19:35:09     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-02-02T19:35:09.170683Z] 19:35:09     INFO - sendPings@resource://gre/modules/TelemetrySend.jsm:782:15
[task 2017-02-02T19:35:09.172814Z] 19:35:09     INFO - SendScheduler._doSendTask<@resource://gre/modules/TelemetrySend.jsm:460:13
[task 2017-02-02T19:35:09.175148Z] 19:35:09     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-02-02T19:35:09.176997Z] 19:35:09     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-02-02T19:35:09.179003Z] 19:35:09     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-02-02T19:35:09.183205Z] 19:35:09     INFO - triggerSendingPings@resource://gre/modules/TelemetrySend.jsm:385:24
[task 2017-02-02T19:35:09.185156Z] 19:35:09     INFO - submitPing@resource://gre/modules/TelemetrySend.jsm:720:5
[task 2017-02-02T19:35:09.186961Z] 19:35:09     INFO - submitPing@resource://gre/modules/TelemetrySend.jsm:209:12
[task 2017-02-02T19:35:09.189041Z] 19:35:09     INFO - Impl._submitPingLogic<@resource://gre/modules/TelemetryController.jsm:476:12
[task 2017-02-02T19:35:09.190923Z] 19:35:09     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-02-02T19:35:09.192645Z] 19:35:09     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-02-02T19:35:09.195226Z] 19:35:09     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-02-02T19:35:09.197039Z] 19:35:09     INFO - send@resource://gre/modules/TelemetryController.jsm:520:19
[task 2017-02-02T19:35:09.198950Z] 19:35:09     INFO - submitExternalPing@resource://gre/modules/TelemetryController.jsm:206:12
[task 2017-02-02T19:35:09.200965Z] 19:35:09     INFO - _onEnvironmentChange@resource://gre/modules/TelemetrySession.jsm:2082:5
[task 2017-02-02T19:35:09.203032Z] 19:35:09     INFO - delayedInit/this._delayedInitTask</<@resource://gre/modules/TelemetrySession.jsm:1543:52
[task 2017-02-02T19:35:09.205433Z] 19:35:09     INFO - _onEnvironmentChange@resource://gre/modules/TelemetryEnvironment.jsm:1455:9
[task 2017-02-02T19:35:09.207387Z] 19:35:09     INFO - _checkForChanges/this._pendingTask<@resource://gre/modules/TelemetryEnvironment.jsm:492:11
[task 2017-02-02T19:35:09.209608Z] 19:35:09     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-02-02T19:35:09.213550Z] 19:35:09     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-02-02T19:35:09.215475Z] 19:35:09     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-02-02T19:35:09.217400Z] 19:35:09     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-02-02T19:35:09.219181Z] 19:35:09     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-02-02T19:35:09.221023Z] 19:35:09     INFO - get _worker/worker.onmessage@resource://gre/modules/PromiseWorker.jsm:231:9
[task 2017-02-02T19:35:09.224707Z] 19:35:09     INFO - EventHandlerNonNull*get _worker@resource://gre/modules/PromiseWorker.jsm:217:5
[task 2017-02-02T19:35:09.226600Z] 19:35:09     INFO - postMessage@resource://gre/modules/PromiseWorker.jsm:291:9
[task 2017-02-02T19:35:09.228328Z] 19:35:09     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-02-02T19:35:09.230455Z] 19:35:09     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-02-02T19:35:09.232345Z] 19:35:09     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-02-02T19:35:09.234174Z] 19:35:09     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-02-02T19:35:09.236247Z] 19:35:09     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-02-02T19:35:09.241158Z] 19:35:09     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-02-02T19:35:09.243062Z] 19:35:09     INFO - observe@resource://gre/modules/AddonManager.jsm:2857:17
[task 2017-02-02T19:35:09.244815Z] 19:35:09     INFO - reply@resource://app/modules/ExtensionsUI.jsm:131:9
[task 2017-02-02T19:35:09.246666Z] 19:35:09     INFO - promise callback*observe@resource://app/modules/ExtensionsUI.jsm:140:9
[task 2017-02-02T19:35:09.248452Z] 19:35:09     INFO - setupPromptHandler/install.promptHandler/<@resource://gre/modules/AddonManager.jsm:2868:9
[task 2017-02-02T19:35:09.250490Z] 19:35:09     INFO - Promise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:390:5
[task 2017-02-02T19:35:09.252331Z] 19:35:09     INFO - setupPromptHandler/install.promptHandler@resource://gre/modules/AddonManager.jsm:2827:37
[task 2017-02-02T19:35:09.258171Z] 19:35:09     INFO - checkPrompt/<@resource://gre/modules/addons/XPIProvider.jsm:5632:17
[task 2017-02-02T19:35:09.260256Z] 19:35:09     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-02-02T19:35:09.262128Z] 19:35:09     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-02-02T19:35:09.263848Z] 19:35:09     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-02-02T19:35:09.265614Z] 19:35:09     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-02-02T19:35:09.267433Z] 19:35:09     INFO - checkPrompt@resource://gre/modules/addons/XPIProvider.jsm:5623:5
[task 2017-02-02T19:35:09.269151Z] 19:35:09     INFO - install@resource://gre/modules/addons/XPIProvider.jsm:5354:7
[task 2017-02-02T19:35:09.271142Z] 19:35:09     INFO - install@resource://gre/modules/addons/XPIProvider.jsm:6130:7
[task 2017-02-02T19:35:09.272934Z] 19:35:09     INFO - downloadCompleted/<@resource://gre/modules/addons/XPIProvider.jsm:6446:9
[task 2017-02-02T19:35:09.274766Z] 19:35:09     INFO - makeSafe/<@resource://gre/modules/addons/XPIProvider.jsm -> resource://gre/modules/addons/XPIProviderUtils.js:172:17
[task 2017-02-02T19:35:09.276580Z] 19:35:09     INFO - getRepositoryAddon@resource://gre/modules/addons/XPIProvider.jsm -> resource://gre/modules/addons/XPIProviderUtils.js:153:5
[task 2017-02-02T19:35:09.278595Z] 19:35:09     INFO - getAddon/<@resource://gre/modules/addons/XPIProvider.jsm -> resource://gre/modules/addons/XPIProviderUtils.js:1069:9
[task 2017-02-02T19:35:09.280807Z] 19:35:09     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-02-02T19:35:09.284388Z] 19:35:09     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-02-02T19:35:09.286428Z] 19:35:09     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-02-02T19:35:09.290408Z] 19:35:09     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-02-02T19:35:09.292738Z] 19:35:09     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-02-02T19:35:09.294571Z] 19:35:09     INFO - openSignedAppFileFinished@resource://gre/modules/addons/XPIProvider.jsm:1819:9
[task 2017-02-02T19:35:09.296255Z] 19:35:09     INFO - 
[task 2017-02-02T19:36:09.275682Z] 19:36:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-02-02T19:36:09.279996Z] 19:36:09     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_offlineQuotaNotification.js | Test timed out - 
[task 2017-02-02T19:36:09.413046Z] 19:36:09     INFO - MEMORY STAT | vsize 986MB | residentFast 272MB | heapAllocated 113MB
[task 2017-02-02T19:36:09.415917Z] 19:36:09     INFO - TEST-OK | browser/base/content/test/general/browser_offlineQuotaNotification.js | took 90244ms

there isn't much here to help figure out the root cause.  I do wonder about this message in there:
Full message: TypeError: PopupNotifications.panel.firstElementChild is null

this fails here in the code:
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/general/browser_offlineQuotaNotification.js?q=path%3Abrowser_offlineQuotaNotification.js&redirect_type=single#69


here is a screenshot from the failure:
https://public-artifacts.taskcluster.net/AQzCDlD_ShCPeXzYcQrV9w/0/public/test_info//mozilla-test-fail-screenshot_lqgr3H.png

:jaws, I see you did a lot of changes to this test over time, could you take a look at it or help find someone to look at it?





[0] https://public-artifacts.taskcluster.net/AQzCDlD_ShCPeXzYcQrV9w/0/public/logs/live_backing.log
Flags: needinfo?(jaws)
checking in here :jaws, it has been a week since I pinged you, can we get this bug fixed this week, or shoul we consider disabling it until there are resources to work on this?
I need to figure out why it is randomly failing on e10s with the rewrite, and might not be able to come back to this for a few days. I attached my WIP here in case anyone wants to complete this. Leaving NI on to remind me to come back.
:jaws, checking back in here, it has been 10 days since last communication, have you had a chance to get back to this bug?  should we disable this test on linux && !debug, until you have more time to work on it?
Yeah, we should disable on linux && !debug. Sorry for not getting back to it sooner.
Flags: needinfo?(jaws)
Keywords: leave-open
Whiteboard: [stockwell disabled]
Attachment #8841018 - Flags: review?(gbrown) → review+
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/7222bd7c4a20
Intermittent browser/base/content/test/general/browser_offlineQuotaNotification.js. disabled on linux opt/pgo. r=gbrown
Priority: -- → P5
You need to log in before you can comment on or make changes to this bug.