Closed Bug 1687061 Opened 5 years ago Closed 5 years ago

Intermittent browser/components/preferences/tests/browser_searchRestoreDefaults.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Categories

(Firefox :: Settings UI, defect, P5)

Product:
Firefox
Component:
Settings UI
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=326852977&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VKqGwwoYSteFs4hylPAnug/runs/0/artifacts/public/logs/live_backing.log

[task 2021-01-15T20:06:23.910Z] 20:06:23     INFO - TEST-START | browser/components/preferences/tests/browser_searchRestoreDefaults.js
[task 2021-01-15T20:11:31.161Z] 20:11:31     INFO - TEST-INFO | started process screentopng
[task 2021-01-15T20:11:31.895Z] 20:11:31     INFO - TEST-INFO | screentopng: exit 0
[task 2021-01-15T20:11:31.904Z] 20:11:31     INFO - Buffered messages logged at 20:06:23
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Entering test bound test_restore_functionality
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:06:27
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have disabled the restore default search engines button on open - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:06:28
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have hidden the engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have enabled the restore default search engines button - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:06:29
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have re-enabled the disabled engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have disabled the restore default search engines button after use - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:06:30
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Leaving test bound test_restore_functionality
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Entering test bound test_restoreEnabledOnOpenWithEngineHidden
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:06:35
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have enabled the restore default search engines button on open - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:06:36
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have re-enabled the disabled engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | Should have disabled the restore default search engines button after use - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Leaving test bound test_restoreEnabledOnOpenWithEngineHidden
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Entering test bound test_removeOutOfOrder
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:06:45
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The restore-defaults button is disabled initially - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:10:57
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The remove-engine button is disabled because a local shortcut is selected - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The restore-defaults button is enabled after removing an engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:11:07
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The remove-engine button is disabled because a local shortcut is selected - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The restore-defaults button is enabled after removing an engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:11:12
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The restore-defaults button is enabled after removing an engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:11:17
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The restore-defaults button is enabled after removing an engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:11:22
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The restore-defaults button is enabled after removing an engine - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The remove-engine button is disabled because only one engine remains - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:11:29
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | The restore-defaults button is disabled after restoring defaults - true == true - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchRestoreDefaults.js | All engines are restored - 9 == 9 - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages logged at 20:11:30
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Leaving test bound test_removeOutOfOrder
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - Buffered messages finished
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-UNEXPECTED-FAIL | browser/components/preferences/tests/browser_searchRestoreDefaults.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - GECKO(1545) | MEMORY STAT | vsize 130552213MB | residentFast 4256MB
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-OK | browser/components/preferences/tests/browser_searchRestoreDefaults.js | took 307227ms
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - checking window state
[task 2021-01-15T20:11:31.905Z] 20:11:31     INFO - TEST-START | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js
[task 2021-01-15T20:15:43.711Z] 20:15:43     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Buffered messages logged at 20:11:31
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Entering test bound openWithSearchSuggestionsShownFirst
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Buffered messages logged at 20:11:32
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js | Pref should be cleared initially - "" == "" - 
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Buffered messages logged at 20:11:37
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js | Checkbox should be checked - true == true - 
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js | Pref should now be set to show history first - "general:5,suggestion:Infinity" == "general:5,suggestion:Infinity" - 
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - TEST-PASS | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js | Checkbox should become checked after clearing pref - true == true - 
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Buffered messages logged at 20:11:38
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Leaving test bound openWithSearchSuggestionsShownFirst
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Entering test bound openWithHistoryShownFirst
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - Buffered messages finished
[task 2021-01-15T20:15:43.719Z] 20:15:43     INFO - TEST-UNEXPECTED-FAIL | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js | Test timed out - 
[task 2021-01-15T20:15:46.507Z] 20:15:46     INFO - GECKO(1545) | MEMORY STAT | vsize 130552222MB | residentFast 4322MB
[task 2021-01-15T20:15:46.596Z] 20:15:46     INFO - TEST-OK | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js | took 254863ms
[task 2021-01-15T20:15:46.787Z] 20:15:46     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-15T20:15:46.789Z] 20:15:46     INFO - TEST-UNEXPECTED-FAIL | browser/components/preferences/tests/browser_searchShowSuggestionsFirst.js | Found a tab after previous test timed out: about:preferences#search - 
[task 2021-01-15T20:15:58.398Z] 20:15:58     INFO - checking window state
[task 2021-01-15T20:17:03.488Z] 20:17:03     INFO - TEST-START | browser/components/preferences/tests/browser_search_no_results_change_category.js
[task 2021-01-15T20:23:14.430Z] 20:23:14     INFO - Buffered messages logged at 20:17:03
[task 2021-01-15T20:23:15.407Z] 20:23:14     INFO - Entering test bound 
[task 2021-01-15T20:23:16.791Z] 20:23:14     INFO - Leaving test bound 
[task 2021-01-15T20:23:18.041Z] 20:23:16     INFO - Entering test bound 
[task 2021-01-15T20:23:18.889Z] 20:23:17     INFO - Buffered messages finished
[task 2021-01-15T20:23:19.679Z] 20:23:19    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/preferences/tests/browser_search_no_results_change_category.js | application timed out after 370 seconds with no output
[task 2021-01-15T20:23:21.291Z] 20:23:19    ERROR - Force-terminating active process(es).
[task 2021-01-15T20:23:22.188Z] 20:23:19     INFO - Determining child pids from psutil...
[task 2021-01-15T20:23:24.182Z] 20:23:21     INFO - [1614, 1639, 1702, 1734, 1774, 1811]
[task 2021-01-15T20:23:25.650Z] 20:23:25     INFO - ==> process 1545 launched child process 1560
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - ==> process 1545 launched child process 1614
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - ==> process 1545 launched child process 1639
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - ==> process 1545 launched child process 1702
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - ==> process 1545 launched child process 1734
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - ==> process 1545 launched child process 1774
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - ==> process 1545 launched child process 1811
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - Found child pids: set([1702, 1734, 1639, 1774, 1811, 1614, 1560])
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - Failed to get child procs
[task 2021-01-15T20:23:25.676Z] 20:23:25     INFO - Killing process: 1702```

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=330799422&repo=autoland&lineNumber=2723

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

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