Closed Bug 1580683 Opened 5 years ago Closed 5 years ago

Debian 10 - TEST-UNEXPECTED-TIMEOUT | toolkit/components/passwordmgr/test/browser/browser_basicAuth_rateLimit.js | application timed out after 370 seconds with no output

Categories

(Toolkit :: Password Manager, defect, P5)

Product:
Toolkit
Component:
Password Manager
Type:
defect

Tracking

()

Status:
RESOLVED INVALID

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: regression)

Filed by: egao [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=266072366&repo=try
Full log: https://queue.taskcluster.net/v1/task/AkhUiqJPQjSmnin42wICBQ/runs/0/artifacts/public/logs/live_backing.log

Platform: debian 10
Suite: mochitest-browser-chrome
Chunk: 6

Context:
[task 2019-09-11T08:29:49.720Z] 08:29:49 INFO - TEST-START | toolkit/components/passwordmgr/test/browser/browser_basicAuth_rateLimit.js
[task 2019-09-11T08:29:50.085Z] 08:29:50 INFO - GECKO(11345) | JavaScript error: resource://specialpowers/SpecialPowersParent.jsm, line 605: TypeError: this.manager.rootFrameLoader is null
[task 2019-09-11T08:29:50.086Z] 08:29:50 INFO - GECKO(11345) | JavaScript error: resource://gre/modules/Prompter.jsm, line 452: NS_ERROR_UNEXPECTED:
[task 2019-09-11T08:40:55.426Z] 08:40:55 INFO - Buffered messages logged at 08:29:49
[task 2019-09-11T08:40:55.426Z] 08:40:55 INFO - Entering test bound common_initialize
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - Leaving test bound common_initialize
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - Entering test bound test
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - Buffered messages logged at 08:29:50
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - must wait for load
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - must wait for focus
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - Console message: [JavaScript Error: "TypeError: this.manager.rootFrameLoader is null" {file: "resource://specialpowers/SpecialPowersParent.jsm" line: 605}]
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - Console message: [JavaScript Error: "NS_ERROR_UNEXPECTED: " {file: "resource://gre/modules/Prompter.jsm" line: 452}]
[task 2019-09-11T08:40:55.427Z] 08:40:55 INFO - Buffered messages logged at 08:34:45
[task 2019-09-11T08:40:55.428Z] 08:40:55 INFO - Console message: [JavaScript Error: "getScreenshot(https://example.com/browser/toolkit/components/passwordmgr/test/browser/form_basic.html) failed: TypeError: NetworkError when attempting to fetch resource." {file: "resource://activity-stream/lib/Screenshots.jsm" line: 59}]
[task 2019-09-11T08:40:55.428Z] 08:40:55 INFO - getScreenshotForURL@resource://activity-stream/lib/Screenshots.jsm:59:10
[task 2019-09-11T08:40:55.429Z] 08:40:55 INFO - asyncmaybeCacheScreenshot@resource://activity-stream/lib/Screenshots.jsm:112:37
[task 2019-09-11T08:40:55.430Z] 08:40:55 INFO - _fetchScreenshot@resource://activity-stream/lib/TopSitesFeed.jsm:527:23
[task 2019-09-11T08:40:55.431Z] 08:40:55 INFO - _fetchIcon@resource://activity-stream/lib/TopSitesFeed.jsm:515:16
[task 2019-09-11T08:40:55.432Z] 08:40:55 INFO - getLinksWithDefaults@resource://activity-stream/lib/TopSitesFeed.jsm:408:16
[task 2019-09-11T08:40:55.433Z] 08:40:55 INFO - asyncrefresh@resource://activity-stream/lib/TopSitesFeed.jsm:431:30
[task 2019-09-11T08:40:55.433Z] 08:40:55 INFO - onAction@resource://activity-stream/lib/TopSitesFeed.jsm:771:14
[task 2019-09-11T08:40:55.434Z] 08:40:55 INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:63:17
[task 2019-09-11T08:40:55.442Z] 08:40:55 INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:39:54
[task 2019-09-11T08:40:55.443Z] 08:40:55 INFO - init/this.intervalId<@resource://activity-stream/lib/SystemTickFeed.jsm:27:24
[task 2019-09-11T08:40:55.444Z] 08:40:55 INFO - notify@resource://gre/modules/Timer.jsm:62:17
[task 2019-09-11T08:40:55.445Z] 08:40:55 INFO - openModalWindow@resource://gre/modules/Prompter.jsm:452:15
[task 2019-09-11T08:40:55.445Z] 08:40:55 INFO - openPrompt@resource://gre/modules/Prompter.jsm:688:20
[task 2019-09-11T08:40:55.446Z] 08:40:55 INFO - nsIPrompt_promptUsernameAndPassword@resource://gre/modules/Prompter.jsm:904:10
[task 2019-09-11T08:40:55.447Z] 08:40:55 INFO - promptAuth@resource://gre/modules/Prompter.jsm:1030:17
[task 2019-09-11T08:40:55.448Z] 08:40:55 INFO - promptAuth@resource://gre/modules/Prompter.jsm:145:14
[task 2019-09-11T08:40:55.449Z] 08:40:55 INFO - promptAuth@resource://gre/modules/LoginManagerPrompter.jsm:762:28
[task 2019-09-11T08:40:55.450Z] 08:40:55 INFO - run@resource://gre/modules/LoginManagerPrompter.jsm:196:27
[task 2019-09-11T08:40:55.450Z] 08:40:55 INFO -
[task 2019-09-11T08:40:55.451Z] 08:40:55 INFO - Buffered messages finished
[task 2019-09-11T08:40:55.452Z] 08:40:55 ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/components/passwordmgr/test/browser/browser_basicAuth_rateLimit.js | application timed out after 370 seconds with no output
[task 2019-09-11T08:40:55.452Z] 08:40:55 ERROR - Force-terminating active process(es).
[task 2019-09-11T08:40:55.452Z] 08:40:55 INFO - Determining child pids from psutil...
[task 2019-09-11T08:40:55.452Z] 08:40:55 INFO - [11399, 11481, 11515, 11548, 11555, 11604, 11611, 11412, 11665, 11692]
[task 2019-09-11T08:40:55.452Z] 08:40:55 INFO - ==> process 11345 launched child process 11365
[task 2019-09-11T08:40:55.452Z] 08:40:55 INFO - ==> process 11345 launched child process 11399
[task 2019-09-11T08:40:55.452Z] 08:40:55 INFO - ==> process 11345 launched child process 11412
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11481
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11515
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11548
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11555
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11604
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11611
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11665
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - ==> process 11345 launched child process 11692
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - Found child pids: set([11412, 11555, 11365, 11399, 11692, 11665, 11604, 11481, 11611, 11515, 11548])
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - Failed to get child procs
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - Killing process: 11412
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - Killing process: 11555
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.453Z] 08:40:55 INFO - Killing process: 11365
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Can't trigger Breakpad, process no longer exists
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11399
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11692
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11665
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11604
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11481
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11611
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11515
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11548
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Killing process: 11345
[task 2019-09-11T08:40:55.454Z] 08:40:55 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-11T08:40:55.591Z] 08:40:55 INFO - psutil found pid 11345 dead

:MattN - this test began failing on linux platforms when the test image was switched from Ubuntu 16.04 to Debian 10 under the ongoing work to update our linux test environment. I see the previous bug filed against this test, bug 1524898 was closed without any work.

Would you be able to pass on the ni for this bug to someone that may be able to offer guidance on next steps?

To test changes against the Debian 10 image, please use ./mach try fuzzy --debian-buster flag when pushing to try.

Flags: needinfo?(MattN+bmo)
Flags: needinfo?(MattN+bmo) → needinfo?(jhofmann)

As with the other Debian tests I don't really have the capacity to prioritize this right now. I'll add it to the list.

Flags: needinfo?(jhofmann)

Closing this bug as debian10 work has been halted and focus redirected to ubuntu1804, and that platform does not observe this failure.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.