Closed Bug 1678131 Opened 5 years ago Closed 5 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | application timed out after 370 seconds with no output

Categories

(Toolkit :: Safe Browsing, defect, P5)

Product:
Toolkit
Component:
Safe Browsing
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2020-11-18T18:39:26.706Z] 18:39:26     INFO - TEST-START | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js
[task 2020-11-18T18:39:36.343Z] 18:39:36     INFO - GECKO(5100) | [CodeCoverage] Requested flush for 7452.
[task 2020-11-18T18:39:38.109Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] flush completed.
[task 2020-11-18T18:39:38.423Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] JS flush completed.
[task 2020-11-18T18:39:38.423Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] Requested flush for 6564.
[task 2020-11-18T18:39:38.423Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] Requested flush for 5564.
[task 2020-11-18T18:39:38.423Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] Requested flush for 2912.
[task 2020-11-18T18:39:38.423Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] Requested flush for 8888.
[task 2020-11-18T18:39:38.423Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] Requested flush for 640.
[task 2020-11-18T18:39:38.424Z] 18:39:38     INFO - GECKO(5100) | [CodeCoverage] Requested flush for 10852.
[task 2020-11-18T18:39:43.411Z] 18:39:43     INFO - GECKO(5100) | [CodeCoverage] flush completed.
[task 2020-11-18T18:39:43.430Z] 18:39:43     INFO - GECKO(5100) | [CodeCoverage] JS flush completed.
[task 2020-11-18T18:39:48.018Z] 18:39:48     INFO - GECKO(5100) | [CodeCoverage] flush completed.
[task 2020-11-18T18:39:48.043Z] 18:39:48     INFO - GECKO(5100) | [CodeCoverage] JS flush completed.
[task 2020-11-18T18:39:52.853Z] 18:39:52     INFO - GECKO(5100) | [CodeCoverage] flush completed.
[task 2020-11-18T18:39:52.871Z] 18:39:52     INFO - GECKO(5100) | [CodeCoverage] JS flush completed.
[task 2020-11-18T18:39:57.458Z] 18:39:57     INFO - GECKO(5100) | [CodeCoverage] flush completed.
[task 2020-11-18T18:39:57.503Z] 18:39:57     INFO - GECKO(5100) | [CodeCoverage] JS flush completed.
[task 2020-11-18T18:40:02.171Z] 18:40:02     INFO - GECKO(5100) | [CodeCoverage] flush completed.
[task 2020-11-18T18:40:02.190Z] 18:40:02     INFO - GECKO(5100) | [CodeCoverage] JS flush completed.
[task 2020-11-18T18:40:07.188Z] 18:40:07     INFO - GECKO(5100) | [CodeCoverage] flush completed.
[task 2020-11-18T18:40:07.188Z] 18:40:07     INFO - GECKO(5100) | [CodeCoverage] JS flush completed.
[task 2020-11-18T18:40:07.327Z] 18:40:07     INFO - GECKO(5100) | JavaScript error: resource://testing-common/PerTestCoverageUtils.jsm, line 61: Error: [Exception... "Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [nsIFile.moveTo]"  nsresult: "0x8052000e (NS_ERROR_FILE_IS_LOCKED)"  location: "JS frame :: resource://testing-common/PerTestCoverageUtils.jsm :: moveDirectoryContents :: line 76"  data: no]
[task 2020-11-18T18:45:24.141Z] 18:45:24     INFO - GECKO(5100) | 1605725124137	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
[task 2020-11-18T18:51:34.153Z] 18:51:34     INFO - Buffered messages logged at 18:39:26
[task 2020-11-18T18:51:34.154Z] 18:51:34     INFO - Entering test bound checkFlashBlockLists
[task 2020-11-18T18:51:34.154Z] 18:51:34     INFO - RUNNING TEST: Unknown domain (Ask to Activate, Flashblock on)
[task 2020-11-18T18:51:34.154Z] 18:51:34     INFO - Buffered messages logged at 18:39:27
[task 2020-11-18T18:51:34.155Z] 18:51:34     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/toolkit/components/url-classifier/tests/browser/flash_block_frame.html" line: 0}]
[task 2020-11-18T18:51:34.155Z] 18:51:34     INFO - Console message: [JavaScript Error: "Unknown Collection "main/partitioning-exempt-urls"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 160}]
[task 2020-11-18T18:51:34.155Z] 18:51:34     INFO - UnknownCollectionError@resource://services-settings/RemoteSettingsClient.jsm:160:5
[task 2020-11-18T18:51:34.156Z] 18:51:34     INFO - sync@resource://services-settings/RemoteSettingsClient.jsm:470:13
[task 2020-11-18T18:51:34.156Z] 18:51:34     INFO - 
[task 2020-11-18T18:51:34.156Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Page's classification should match expected - 
[task 2020-11-18T18:51:34.157Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin should have the correct fallback type - 
[task 2020-11-18T18:51:34.157Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin should have the correct activation - 
[task 2020-11-18T18:51:34.157Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin should have the correct 'plugin running' state - 
[task 2020-11-18T18:51:34.157Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin's existance in navigator.plugins should match expected - 

[task 2020-11-18T18:51:34.203Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Page's classification should match expected - 
[task 2020-11-18T18:51:34.203Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin should have the correct fallback type - 
[task 2020-11-18T18:51:34.203Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin should have the correct activation - 
[task 2020-11-18T18:51:34.203Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin should have the correct 'plugin running' state - 
[task 2020-11-18T18:51:34.203Z] 18:51:34     INFO - TEST-PASS | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | Plugin's existance in navigator.plugins should match expected - 
[task 2020-11-18T18:51:34.203Z] 18:51:34     INFO - Leaving test bound checkFlashBlockLists
[task 2020-11-18T18:51:34.203Z] 18:51:34     INFO - Buffered messages logged at 18:40:07
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - Console message: [JavaScript Error: "Error: [Exception... "Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [nsIFile.moveTo]"  nsresult: "0x8052000e (NS_ERROR_FILE_IS_LOCKED)"  location: "JS frame :: resource://testing-common/PerTestCoverageUtils.jsm :: moveDirectoryContents :: line 76"  data: no]" {file: "resource://testing-common/PerTestCoverageUtils.jsm" line: 61}]
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - Buffered messages logged at 18:45:24
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - Console message: [JavaScript Error: "1605725124137	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4015:25
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - 
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - Buffered messages finished
[task 2020-11-18T18:51:34.204Z] 18:51:34    ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/components/url-classifier/tests/browser/browser_flashblock_on_with_ask_to_activate.js | application timed out after 370 seconds with no output
[task 2020-11-18T18:51:34.204Z] 18:51:34    ERROR - Force-terminating active process(es).
[task 2020-11-18T18:51:34.204Z] 18:51:34     INFO - Determining child pids from psutil...
[task 2020-11-18T18:51:34.205Z] 18:51:34     INFO - [7452]
[task 2020-11-18T18:51:34.205Z] 18:51:34     INFO - ==> process 7452 launched child process 6184 ("Z:\task_1605722783\build\application\firefox\firefox.exe" -contentproc --channel="7452.0.704290920\1306896007" -parentBuildID 20201118160535 -prefsHandle 2228 -prefMapHandle 2220 -prefsLen 1 -prefMapSize 243838 -appdir "Z:\task_1605722783\build\application\firefox\browser" - 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 2296 gpu)
[task 2020-11-18T18:51:34.205Z] 18:51:34     INFO - ==> process 7452 launched child process 6564 ("Z:\task_1605722783\build\application\firefox\firefox.exe" -contentproc --channel="7452.6.1318641360\687006113" -childID 1 -isForBrowser -prefsHandle 2884 -prefMapHandle 2880 -prefsLen 1684 -prefMapSize 243838 -parentBuildID 20201118160535 -appdir "Z:\task_1605722783\build\application\firefox\browser" - 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 2896 tab)
[task 2020-11-18T18:51:34.205Z] 18:51:34     INFO - ==> process 7452 launched child process 5564 ("Z:\task_1605722783\build\application\firefox\firefox.exe" -contentproc --channel="7452.13.169937421\163353838" -childID 2 -isForBrowser -prefsHandle 5580 -prefMapHandle 5576 -prefsLen 2159 -prefMapSize 243838 -parentBuildID 20201118160535 -appdir "Z:\task_1605722783\build\application\firefox\browser" - 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 5588 tab)
[task 2020-11-18T18:51:34.205Z] 18:51:34     INFO - ==> process 7452 launched child process 2912 ("Z:\task_1605722783\build\application\firefox\firefox.exe" -contentproc --channel="7452.20.508524996\488080177" -childID 3 -isForBrowser -prefsHandle 5624 -prefMapHandle 5640 -prefsLen 2199 -prefMapSize 243838 -parentBuildID 20201118160535 -appdir "Z:\task_1605722783\build\application\firefox\browser" - 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 5608 tab)
[task 2020-11-18T18:51:34.206Z] 18:51:34     INFO - ==> process 7452 launched child process 8888 ("Z:\task_1605722783\build\application\firefox\firefox.exe" -contentproc --channel="7452.27.1343546558\1240066714" -childID 4 -isForBrowser -prefsHandle 4560 -prefMapHandle 5136 -prefsLen 10811 -prefMapSize 243838 -parentBuildID 20201118160535 -appdir "Z:\task_1605722783\build\application\firefox\browser" - 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 1000 tab)
[task 2020-11-18T18:51:34.206Z] 18:51:34     INFO - ==> process 7452 launched child process 640 ("Z:\task_1605722783\build\application\firefox\firefox.exe" -contentproc --channel="7452.34.408644554\1337535685" -childID 5 -isForBrowser -prefsHandle 4684 -prefMapHandle 5192 -prefsLen 11773 -prefMapSize 243838 -parentBuildID 20201118160535 -appdir "Z:\task_1605722783\build\application\firefox\browser" - 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 1980 tab)
[task 2020-11-18T18:51:34.206Z] 18:51:34     INFO - ==> process 7452 launched child process 10852 ("Z:\task_1605722783\build\application\firefox\firefox.exe" -contentproc --channel="7452.41.362573109\1993769079" -childID 6 -isForBrowser -prefsHandle 4996 -prefMapHandle 2668 -prefsLen 14961 -prefMapSize 243838 -parentBuildID 20201118160535 -appdir "Z:\task_1605722783\build\application\firefox\browser" - 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 4660 tab)
[task 2020-11-18T18:51:34.206Z] 18:51:34     INFO - ==> process 7452 launched child process 11196 ("Z:\task_1605722783\build\application\firefox\plugin-container.exe" --channel="7452.48.1004295526\155036805" "c:\users\task_1605722783\appdata\local\temp\tmpehbdtm.mozrunner\plugins\npswftest.dll" -appdir "Z:\task_1605722783\build\application\firefox\browser" 168A860E158F7484 7452 "\\.\pipe\gecko-crash-server-pipe.7452" 15928 plugin)
[task 2020-11-18T18:51:34.206Z] 18:51:34     INFO - Found child pids: set([2912, 640, 6564, 6184, 7452, 11196, 8888, 10852, 5564])
[task 2020-11-18T18:51:34.206Z] 18:51:34     INFO - Failed to get child procs
[task 2020-11-18T18:51:34.206Z] 18:51:34     INFO - Killing process: 2912
[task 2020-11-18T18:51:34.207Z] 18:51:34     INFO - TEST-INFO | started process screenshot
[task 2020-11-18T18:51:34.266Z] 18:51:34     INFO - TEST-INFO | screenshot: exit 0
[task 2020-11-18T18:51:34.266Z] 18:51:34     INFO - mozcrash Writing a dump to c:\users\task_1605722783\appdata\local\temp\tmpehbdtm.mozrunner\minidumps\2f414847-240f-4d78-83de-ce7a893314ec.dmp for [2912]
[task 2020-11-18T18:51:34.369Z] 18:51:34     INFO - Killing process: 640
[task 2020-11-18T18:51:34.369Z] 18:51:34     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-18T18:51:34.369Z] 18:51:34     INFO - mozcrash Writing a dump to c:\users\task_1605722783\appdata\local\temp\tmpehbdtm.mozrunner\minidumps\befa6766-fb03-4cd3-8478-867e4f3a7285.dmp for [640]
[task 2020-11-18T18:51:34.448Z] 18:51:34     INFO - Killing process: 6564
[task 2020-11-18T18:51:34.448Z] 18:51:34     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-18T18:51:34.448Z] 18:51:34     INFO - mozcrash Writing a dump to c:\users\task_1605722783\appdata\local\temp\tmpehbdtm.mozrunner\minidumps\a251f212-d0db-4c02-8994-a803398001a9.dmp for [6564]
[task 2020-11-18T18:51:34.533Z] 18:51:34     INFO - Killing process: 6184
[task 2020-11-18T18:51:34.533Z] 18:51:34     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-18T18:51:34.533Z] 18:51:34     INFO - mozcrash Writing a dump to c:\users\task_1605722783\appdata\local\temp\tmpehbdtm.mozrunner\minidumps\a0a387a9-5857-43ba-a522-39fde3b2998d.dmp for [6184]
[task 2020-11-18T18:51:34.663Z] 18:51:34     INFO - Killing process: 7452
[task 2020-11-18T18:51:34.663Z] 18:51:34     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-18T18:51:34.663Z] 18:51:34     INFO - mozcrash Writing a dump to c:\users\task_1605722783\appdata\local\temp\tmpehbdtm.mozrunner\minidumps\af207d91-e59a-4e4d-8806-405f647e56c3.dmp for [7452]
[task 2020-11-18T18:51:34.862Z] 18:51:34     INFO - Killing process: 11196
[task 2020-11-18T18:51:34.862Z] 18:51:34     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-18T18:51:34.862Z] 18:51:34     INFO - mozcrash Writing a dump to c:\users\task_1605722783\appdata\local\temp\tmpehbdtm.mozrunner\minidumps\76efd347-6699-465c-b746-240d985733ea.dmp for [11196]
[task 2020-11-18T18:51:34.862Z] 18:51:34  WARNING - mozcrash unable to get handle for pid 11196: 87
[task 2020-11-18T18:51:34.862Z] 18:51:34  WARNING - mozcrash kill_pid(): unable to get handle for pid 11196: 87```

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
You need to log in before you can comment on or make changes to this bug.