1544687 - Intermittent TEST-UNEXPECTED-TIMEOUT | browser/components/shell/test/test_headless_screenshot.html | application timed out after 370 seconds with no output

Status: RESOLVED INCOMPLETE

(Firefox :: Shell Integration, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: opoprus [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=240556913&repo=mozilla-central

https://queue.taskcluster.net/v1/task/fAGyS65iS9KSKh5kIWrjVw/runs/0/artifacts/public/logs/live_backing.log

06:55:27 INFO - TEST-START | browser/components/shell/test/test_headless_screenshot.html
06:55:28 INFO - GECKO(7264) | *** You are running in headless mode.
06:55:28 INFO - GECKO(7264) | >>> 1555397728743 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
06:55:28 INFO - GECKO(7264) | >>> 1555397728744 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
06:55:28 INFO - GECKO(7264) | 1555397728744 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
06:55:28 INFO - GECKO(7264) | >>> 1555397728915 Marionette TRACE Received observer notification profile-after-change
06:55:28 INFO - GECKO(7264) | >>>
06:55:28 INFO - GECKO(7264) | >>> 1555397728968 Marionette TRACE Received observer notification command-line-startup
06:55:28 INFO - GECKO(7264) | >>>
06:55:29 INFO - GECKO(7264) | >>> Screenshot saved to: C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
06:55:29 INFO - GECKO(7264) | >>>
06:55:29 INFO - GECKO(7264) | JavaScript error: resource://gre/modules/AutoCompletePopup.jsm, line 112: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]
06:55:30 INFO - GECKO(7264) | >>> 1555397730629 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
06:55:30 INFO - GECKO(7264) | >>> 1555397730630 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
06:55:30 INFO - GECKO(7264) | 1555397730630 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
06:55:30 INFO - GECKO(7264) | >>> 1555397730799 Marionette TRACE Received observer notification profile-after-change
06:55:30 INFO - GECKO(7264) | >>>
06:55:30 INFO - GECKO(7264) | >>> [
06:55:30 INFO - GECKO(7264) | >>> GFX1-]: VendorIDMismatch V 0x5143 0x4d4f4351
06:55:30 INFO - GECKO(7264) | >>> 1555397730880 Marionette TRACE Received observer notification command-line-startup
06:55:30 INFO - GECKO(7264) | >>>
06:55:31 INFO - GECKO(7264) | >>> Screenshot saved to: C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
06:55:31 INFO - GECKO(7264) | >>>
06:55:31 INFO - GECKO(7264) | JavaScript error: resource://gre/modules/AutoCompletePopup.jsm, line 112: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]
06:55:32 INFO - GECKO(7264) | *** You are running in headless mode.
06:55:32 INFO - GECKO(7264) | >>> 1555397732614 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
06:55:32 INFO - GECKO(7264) | >>> 1555397732615 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
06:55:32 INFO - GECKO(7264) | 1555397732615 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
06:55:32 INFO - GECKO(7264) | >>> 1555397732784 Marionette TRACE Received observer notification profile-after-change
06:55:32 INFO - GECKO(7264) | >>>
06:55:32 INFO - GECKO(7264) | >>> 1555397732840 Marionette TRACE Received observer notification command-line-startup
06:55:32 INFO - GECKO(7264) | >>>
06:55:33 INFO - GECKO(7264) | >>> Screenshot saved to: C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
06:55:33 INFO - GECKO(7264) | >>>
06:55:33 INFO - GECKO(7264) | JavaScript error: resource://gre/modules/AutoCompletePopup.jsm, line 112: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]
06:55:33 INFO - GECKO(7264) | JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 400: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close
06:55:34 INFO - GECKO(7264) | >>> 1555397734480 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
06:55:34 INFO - GECKO(7264) | >>> 1555397734481 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
06:55:34 INFO - GECKO(7264) | 1555397734481 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
06:55:34 INFO - GECKO(7264) | >>> 1555397734651 Marionette TRACE Received observer notification profile-after-change
06:55:34 INFO - GECKO(7264) | >>>
06:55:34 INFO - GECKO(7264) | >>> [
06:55:34 INFO - GECKO(7264) | >>> GFX1-]: VendorIDMismatch V 0x5143 0x4d4f4351
06:55:34 INFO - GECKO(7264) | >>> 1555397734724 Marionette TRACE Received observer notification command-line-startup
06:55:34 INFO - GECKO(7264) | >>>
06:55:35 INFO - GECKO(7264) | >>> Screenshot saved to: C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
06:55:35 INFO - GECKO(7264) | >>>
06:55:35 INFO - GECKO(7264) | JavaScript error: resource://gre/modules/AutoCompletePopup.jsm, line 112: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]
06:55:35 INFO - GECKO(7264) | JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 400: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close
06:55:35 INFO - GECKO(7264) | *** You are running in headless mode.
06:55:36 INFO - GECKO(7264) | >>> 1555397736377 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
06:55:36 INFO - GECKO(7264) | >>> 1555397736378 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
06:55:36 INFO - GECKO(7264) | 1555397736378 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
06:55:36 INFO - GECKO(7264) | >>> 1555397736546 Marionette TRACE Received observer notification profile-after-change
06:55:36 INFO - GECKO(7264) | >>>
06:55:36 INFO - GECKO(7264) | >>> 1555397736600 Marionette TRACE Received observer notification command-line-startup
06:55:36 INFO - GECKO(7264) | >>>
07:01:46 INFO - Buffered messages logged at 06:55:29
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Firefox process should exit with code 0
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | A screenshot should be saved as C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
07:01:46 INFO - Buffered messages logged at 06:55:30
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Screenshot should not be an empty file
07:01:46 INFO - Buffered messages logged at 06:55:31
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Firefox process should exit with code 0
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | A screenshot should be saved as C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Screenshot should not be an empty file
07:01:46 INFO - Buffered messages logged at 06:55:33
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Firefox process should exit with code 0
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | A screenshot should be saved as C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Screenshot should not be an empty file
07:01:46 INFO - Buffered messages logged at 06:55:35
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Firefox process should exit with code 0
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | A screenshot should be saved as C:\Users\TESTDR~1\AppData\Local\Temp\headless_test_screenshot.png
07:01:46 INFO - TEST-PASS | browser/components/shell/test/test_headless_screenshot.html | Screenshot should not be an empty file
07:01:46 INFO - Buffered messages finished
07:01:46 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/shell/test/test_headless_screenshot.html | application timed out after 370 seconds with no output
07:01:46 ERROR - Force-terminating active process(es).
07:01:46 INFO - Determining child pids from psutil...
07:01:46 INFO - [8028]
07:01:46 INFO - Found child pids: set([8028])
07:01:46 INFO - Killing process: 8028
07:01:46 INFO - TEST-INFO | started process screenshot
07:01:47 INFO - TEST-INFO | screenshot: exit 0
07:01:47 INFO - Can't trigger Breakpad, just killing process
07:01:47 INFO - psutil found pid 8028 dead
07:01:47 INFO - psutil found pid 9648 dead
07:01:47 INFO - psutil found pid 8028 dead
07:01:47 INFO - Killing process: 7264
07:01:47 INFO - Not taking screenshot here: see the one that was previously logged
07:01:47 INFO - Can't trigger Breakpad, just killing process
07:01:47 INFO - Error: Failed to kill process 7264: psutil.NoSuchProcess no process found with pid 7264
07:01:47 INFO - psutil found pid 7264 dead
07:01:47 INFO - TEST-INFO | Main app process: exit f
07:01:47 INFO - Buffered messages finished
07:01:47 ERROR - TEST-UNEXPECTED-FAIL | browser/components/shell/test/test_headless_screenshot.html | application terminated with exit code 15
07:01:47 INFO - runtests.py | Application ran for: 0:06:25.052000
07:01:47 INFO - zombiecheck | Reading PID log: c:\users\testdr~1\appdata\local\temp\tmpuhtml4pidlog
07:01:47 INFO - Stopping web server
07:01:47 INFO - Stopping web socket server
07:01:47 INFO - Stopping ssltunnel
07:01:47 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
07:01:47 INFO - runtests.py | Running tests: end.
07:01:47 INFO - Buffered messages finished
07:01:47 INFO - Running manifest: caps\tests\mochitest\chrome.ini
07:01:47 INFO - C:\tasks\task_1555396544\build\tests\bin\pk12util.exe: PKCS12 IMPORT SUCCESSFUL
07:01:47 INFO - Increasing default timeout to 240.0 seconds
07:01:47 INFO - MochitestServer : launching [u'C:\\tasks\\task_1555396544\\build\\tests\\bin\\xpcshell.exe', '-g', 'C:\\tasks\\task_1555396544\\build\\application\\firefox', '-f', 'C:\\tasks\\task_1555396544\\build\\tests\\bin\\components\\httpd.js', '-e', "const _PROFILE_PATH = 'c:\\\\users\\\\testdr~1\\\\appdata\\\\local\\\\temp\\\\tmptewlj9.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', 'C:\\tasks\\task_1555396544\\build\\tests\\mochitest\\server.js']
07:01:47 INFO - runtests.py | Server pid: 9008
07:01:47 INFO - runtests.py | Websocket server pid: 8620
07:01:47 INFO - runtests.py | SSL tunnel pid: 6756
07:01:48 INFO - runtests.py | Running with scheme: http
07:01:48 INFO - runtests.py | Running with e10s: False
07:01:48 INFO - runtests.py | Running with serviceworker_e10s: False
07:01:48 INFO - runtests.py | Running with socketprocess_e10s: False
07:01:48 INFO - runtests.py | Running tests: start.
07:01:48 INFO -
07:01:48 INFO - Application command: C:\tasks\task_1555396544\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile c:\users\testdr~1\appdata\local\temp\tmptewlj9.mozrunner
07:01:48 INFO - runtests.py | Application pid: 1456
07:01:48 INFO - TEST-INFO | started process GECKO(1456)
07:01:48 INFO - GECKO(1456) | C:\Users\testdroid\AppData\Local\Temp\tmptewlj9.mozrunner\user.js:223: prefs parse error: unexpected character
07:01:49 INFO - GECKO(1456) | 1555398109204 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
07:01:49 INFO - GECKO(1456) | 1555398109204 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
07:01:49 INFO - GECKO(1456) | 1555398109204 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
07:01:49 INFO - GECKO(1456) | 1555398109384 Marionette TRACE Received observer notification profile-after-change
07:01:49 INFO - GECKO(1456) | [GFX1-]: VendorIDMismatch V 0x5143 0x4d4f4351
07:01:49 INFO - GECKO(1456) | 1555398109444 Marionette TRACE Received observer notification toplevel-window-ready
07:01:49 INFO - GECKO(1456) | 1555398109483 Marionette TRACE Received observer notification command-line-startup
07:01:49 INFO - GECKO(1456) | 1555398109484 Marionette TRACE Received observer notification nsPref:changed
07:01:49 INFO - GECKO(1456) | 1555398109484 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
07:01:49 INFO - GECKO(1456) | 1555398109652 Marionette TRACE Received observer notification toplevel-window-ready
07:01:50 INFO - GECKO(1456) | JavaScript warning: chrome://global/content/bindings/tabbox.xml, line 162: Array.forEach is deprecated; use Array.prototype.forEach instead
07:01:50 INFO - GECKO(1456) | JavaScript warning: chrome://browser/content/browser-ctrlTab.js, line 568: Array.filter is deprecated; use Array.prototype.filter instead
07:01:52 INFO - GECKO(1456) | 1555398112066 Marionette TRACE Received observer notification marionette-startup-requested
07:01:52 INFO - GECKO(1456) | 1555398112068 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
07:01:52 INFO - GECKO(1456) | 1555398112221 Marionette TRACE All scripts recorded.
07:01:52 INFO - GECKO(1456) | 1555398112299 Marionette INFO Listening on port 2828
07:01:52 INFO - GECKO(1456) | 1555398112299 Marionette DEBUG Remote service is active
07:01:52 INFO - GECKO(1456) | 1555398112567 Marionette DEBUG Accepted connection 0 from 127.0.0.1:50132
07:01:52 INFO - GECKO(1456) | 1555398112665 Marionette DEBUG Closed connection 0
07:01:52 INFO - GECKO(1456) | 1555398112667 Marionette DEBUG Accepted connection 1 from 127.0.0.1:50134
07:01:52 INFO - GECKO(1456) | 1555398112767 Marionette DEBUG Accepted connection 2 from 127.0.0.1:50135
07:01:52 INFO - GECKO(1456) | 1555398112772 Marionette DEBUG Closed connection 2
07:01:52 INFO - GECKO(1456) | 1555398112774 Marionette DEBUG Closed connection 1
07:01:52 INFO - GECKO(1456) | 1555398112776 Marionette DEBUG Accepted connection 3 from 127.0.0.1:50136
07:01:52 INFO - GECKO(1456) | 1555398112785 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
07:01:52 INFO - GECKO(1456) | 1555398112806 Marionette TRACE [22] Frame script loaded
07:01:52 INFO - GECKO(1456) | 1555398112808 Marionette TRACE [22] Frame script registered
07:01:52 INFO - GECKO(1456) | 1555398112810 Marionette TRACE [34] Frame script loaded
07:01:52 INFO - GECKO(1456) | 1555398112811 Marionette TRACE [34] Frame script registered
07:01:52 INFO - GECKO(1456) | 1555398112823 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"20e7f609-b477-4382-a973-94175c73edb7","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... p\\tmptewlj9.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
07:01:52 INFO - GECKO(1456) | 1555398112864 Marionette DEBUG 3 -> [0,2,"Addon:Install",{"path":"c:\\users\\testdr~1\\appdata\\local\\temp\\tmps21afk.zip","temporary":false}]
07:01:52 INFO - GECKO(1456) | 1555398112932 Marionette DEBUG 3 <- [1,2,null,{"value":"[e-mail]"}]
07:01:53 INFO - GECKO(1456) | 1555398113011 Marionette DEBUG 3 -> [0,3,"Addon:Install",{"path":"c:\\users\\testdr~1\\appdata\\local\\temp\\tmpktm8hg.zip","temporary":false}]
07:01:53 INFO - GECKO(1456) | 1555398113055 Marionette DEBUG 3 <- [1,3,null,{"value":"[e-mail]"}]
07:01:53 INFO - GECKO(1456) | 1555398113060 Marionette DEBUG 3 -> [0,4,"Marionette:GetContext",{}]
07:01:53 INFO - GECKO(1456) | 1555398113060 Marionette DEBUG 3 <- [1,4,null,{"value":"content"}]
07:01:53 INFO - GECKO(1456) | 1555398113063 Marionette DEBUG 3 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
07:01:53 INFO - GECKO(1456) | 1555398113063 Marionette DEBUG 3 <- [1,5,null,{"value":null}]
07:01:53 INFO - GECKO(1456) | 1555398113068 Marionette DEBUG 3 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... r":"chrome"}],"filename":"C:\\tasks\\task_1555396544\\build\\tests\\mochitest\\runtests.py","sandbox":"default","line":1750}]
07:01:53 INFO - GECKO(1456) | 1555398113100 Marionette DEBUG 3 <- [1,6,null,{"value":null}]
07:01:53 INFO - GECKO(1456) | 1555398113133 Marionette DEBUG 3 -> [0,7,"Marionette:SetContext",{"value":"content"}]
07:01:53 INFO - GECKO(1456) | 1555398113134 Marionette DEBUG 3 <- [1,7,null,{"value":null}]
07:01:53 INFO - GECKO(1456) | 1555398113197 Marionette DEBUG 3 -> [0,8,"WebDriver:DeleteSession",{}]
07:01:53 INFO - GECKO(1456) | 1555398113199 Marionette DEBUG 3 <- [1,8,null,{"value":null}]
07:01:53 INFO - runtests.py | Waiting for browser...
07:01:53 INFO - GECKO(1456) | 1555398113230 Marionette DEBUG Closed connection 3
07:01:53 INFO - SimpleTest START

Comment 1

[Intermittent Failures Robot]

3 failures in 2673 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• windows10-aarch64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1544687&startday=2019-04-15&endday=2019-04-21&tree=all

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Raul Gurzau (:RaulG)]

New failure https://treeherder.mozilla.org/logviewer.html#?job_id=247134549&repo=mozilla-central

Comment 4

[Intermittent Failures Robot]

1 failures in 4658 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1544687&startday=2019-05-13&endday=2019-05-19&tree=all

Comment 5

[Intermittent Failures Robot]

1 failures in 4730 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1544687&startday=2019-05-20&endday=2019-05-26&tree=all

Comment 6

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup