1444642 - Intermittent TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output (hang on shutdown)

Status: RESOLVED DUPLICATE of bug 1414495

(Testing :: Mochitest, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=167181335&repo=try

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

[task 2018-03-10T13:23:59.213Z] 13:23:59     INFO - TEST-START | dom/media/test/test_video_dimensions.html
[task 2018-03-10T13:24:00.474Z] 13:24:00     INFO - GECKO(1573) | MEMORY STAT | vsize 20975447MB | residentFast 992MB
[task 2018-03-10T13:24:00.491Z] 13:24:00     INFO - TEST-OK | dom/media/test/test_video_dimensions.html | took 1278ms
[task 2018-03-10T13:24:00.569Z] 13:24:00     INFO - TEST-START | Shutdown
[task 2018-03-10T13:24:00.569Z] 13:24:00     INFO - Passed:  8063
[task 2018-03-10T13:24:00.571Z] 13:24:00     INFO - Failed:  0
[task 2018-03-10T13:24:00.572Z] 13:24:00     INFO - Todo:    46
[task 2018-03-10T13:24:00.573Z] 13:24:00     INFO - Mode:    e10s
[task 2018-03-10T13:24:00.574Z] 13:24:00     INFO - Slowest: 110960ms - /tests/dom/media/test/test_playback.html
[task 2018-03-10T13:24:00.581Z] 13:24:00     INFO - SimpleTest FINISHED
[task 2018-03-10T13:24:00.582Z] 13:24:00     INFO - TEST-INFO | Ran 1 Loops
[task 2018-03-10T13:24:00.583Z] 13:24:00     INFO - SimpleTest FINISHED
[task 2018-03-10T13:24:00.948Z] 13:24:00     INFO - GECKO(1573) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2018-03-10T13:24:01.066Z] 13:24:01     INFO - GECKO(1573) | 1520688241052	addons.xpi	ERROR	XPI_verifySignature: Error: Attempt to use XPI database when it is not initialized
[task 2018-03-10T13:24:01.492Z] 13:24:01     INFO - GECKO(1573) | 1520688241486	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-03-10T13:24:01.493Z] 13:24:01     INFO - GECKO(1573) | 1520688241486	Marionette	DEBUG	New connections will no longer be accepted
[task 2018-03-10T13:24:01.954Z] 13:24:01     INFO - GECKO(1573) | -----------------------------------------------------
[task 2018-03-10T13:24:01.954Z] 13:24:01     INFO - GECKO(1573) | Suppressions used:
[task 2018-03-10T13:24:01.954Z] 13:24:01     INFO - GECKO(1573) |   count      bytes template
[task 2018-03-10T13:24:01.955Z] 13:24:01     INFO - GECKO(1573) |     661      21088 nsComponentManagerImpl
[task 2018-03-10T13:24:01.955Z] 13:24:01     INFO - GECKO(1573) |       3        576 mozJSComponentLoader::LoadModule
[task 2018-03-10T13:24:01.955Z] 13:24:01     INFO - GECKO(1573) |       2        288 libfontconfig.so
[task 2018-03-10T13:24:01.955Z] 13:24:01     INFO - GECKO(1573) | -----------------------------------------------------
[task 2018-03-10T13:24:04.224Z] 13:24:04     INFO - GECKO(1573) | -----------------------------------------------------
[task 2018-03-10T13:24:04.224Z] 13:24:04     INFO - GECKO(1573) | Suppressions used:
[task 2018-03-10T13:24:04.226Z] 13:24:04     INFO - GECKO(1573) |   count      bytes template
[task 2018-03-10T13:24:04.227Z] 13:24:04     INFO - GECKO(1573) |     661      21088 nsComponentManagerImpl
[task 2018-03-10T13:24:04.228Z] 13:24:04     INFO - GECKO(1573) |       8       1536 mozJSComponentLoader::LoadModule
[task 2018-03-10T13:24:04.229Z] 13:24:04     INFO - GECKO(1573) |     611      17713 libfontconfig.so
[task 2018-03-10T13:24:04.230Z] 13:24:04     INFO - GECKO(1573) |       1         29 libglib-2.0.so
[task 2018-03-10T13:24:04.231Z] 13:24:04     INFO - GECKO(1573) | -----------------------------------------------------
[task 2018-03-10T13:24:05.514Z] 13:24:05     INFO - GECKO(1573) | -----------------------------------------------------
[task 2018-03-10T13:24:05.514Z] 13:24:05     INFO - GECKO(1573) | Suppressions used:
[task 2018-03-10T13:24:05.515Z] 13:24:05     INFO - GECKO(1573) |   count      bytes template
[task 2018-03-10T13:24:05.516Z] 13:24:05     INFO - GECKO(1573) |     673      21456 nsComponentManagerImpl
[task 2018-03-10T13:24:05.517Z] 13:24:05     INFO - GECKO(1573) |      45       8640 mozJSComponentLoader::LoadModule
[task 2018-03-10T13:24:05.518Z] 13:24:05     INFO - GECKO(1573) |     611      17509 libfontconfig.so
[task 2018-03-10T13:24:05.519Z] 13:24:05     INFO - GECKO(1573) |       4        176 _PR_Getfd
[task 2018-03-10T13:24:05.519Z] 13:24:05     INFO - GECKO(1573) |       1         29 libglib-2.0.so
[task 2018-03-10T13:24:05.520Z] 13:24:05     INFO - GECKO(1573) | -----------------------------------------------------
[task 2018-03-10T13:24:05.710Z] 13:24:05     INFO - TEST-INFO | Main app process: exit 0
[task 2018-03-10T13:24:05.711Z] 13:24:05     INFO - runtests.py | Application ran for: 0:12:37.019457
[task 2018-03-10T13:24:05.714Z] 13:24:05     INFO - zombiecheck | Reading PID log: /tmp/tmpd03Qb3pidlog
[task 2018-03-10T13:24:05.714Z] 13:24:05     INFO - ==> process 1573 launched child process 1592
[task 2018-03-10T13:24:05.715Z] 13:24:05     INFO - ==> process 1573 launched child process 1624
[task 2018-03-10T13:24:05.715Z] 13:24:05     INFO - ==> process 1573 launched child process 1651
[task 2018-03-10T13:24:05.716Z] 13:24:05     INFO - zombiecheck | Checking for orphan process with PID: 1592
[task 2018-03-10T13:24:05.717Z] 13:24:05     INFO - zombiecheck | Checking for orphan process with PID: 1624
[task 2018-03-10T13:24:05.719Z] 13:24:05     INFO - zombiecheck | Checking for orphan process with PID: 1651
[task 2018-03-10T13:24:05.720Z] 13:24:05     INFO - runtests.py | Running with e10s: True
[task 2018-03-10T13:24:05.721Z] 13:24:05     INFO - runtests.py | Running tests: start.
[task 2018-03-10T13:24:05.722Z] 13:24:05     INFO - 
[task 2018-03-10T13:24:05.732Z] 13:24:05     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmp73Ntv5.mozrunner
[task 2018-03-10T13:24:05.749Z] 13:24:05     INFO - runtests.py | Application pid: 4200
[task 2018-03-10T13:24:05.749Z] 13:24:05     INFO - TEST-INFO | started process GECKO(4200)
[task 2018-03-10T13:27:05.844Z] 13:27:05     INFO - runtests.py | Waiting for browser...
[task 2018-03-10T13:30:15.755Z] 13:30:15     INFO - Buffered messages finished
[task 2018-03-10T13:30:15.757Z] 13:30:15    ERROR - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output

Comment 1

[Intermittent Failures Robot]

4 failures in 747 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2
* try: 1
* mozilla-central: 1

Platform breakdown:
* windows10-64: 3
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1444642&startday=2018-03-05&endday=2018-03-11&tree=all

Comment 2

[Stefan Hindli [:stefan_hindli]]

Over the last 7 days this bug has 31 failures, most of these happen on windows10-64 but there are some occurrences on OS X 10.10, windows10-64-nightly and windows10-64-qr.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=168129124&lineNumber=6266

Here is a relevant part of that log: 

03:53:43  WARNING -  TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output
03:53:43     INFO -  860 ERROR Force-terminating active process(es).
03:53:43     INFO -  Determining child pids from psutil...
03:53:43     INFO -  []
03:53:43     INFO -  Found child pids: set([])
03:53:43     INFO -  Killing process: 7872
03:53:43     INFO -  TEST-INFO | started process screenshot
03:53:43     INFO -  TEST-INFO | screenshot: exit 0
03:53:43     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 7872: error 5
03:53:43     INFO -  psutil found pid 7872 dead
03:53:43     INFO -  TEST-INFO | Main app process: exit 1
03:53:43     INFO -  Buffered messages finished
03:53:43    ERROR -  861 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1
03:53:43     INFO -  runtests.py | Application ran for: 0:06:10.762000
03:53:43     INFO -  zombiecheck | Reading PID log: c:\users\genericworker\appdata\local\temp\tmpamyik9pidlog
03:53:43     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/diJ5SFXDTU2NCvOJX2JB9A/artifacts/public/build/target.crashreporter-symbols.zip
03:53:47     INFO -  mozcrash Copy/paste: Z:\task_1521084768\build\win32-minidump_stackwalk.exe c:\users\genericworker\appdata\local\temp\tmpoifoot.mozrunner\minidumps\63d46565-76da-46e7-8e6e-cbccd63d487e.dmp c:\users\genericworker\appdata\local\temp\tmpt35vzl
03:53:53     INFO -  mozcrash Saved minidump as Z:\task_1521084768\build\blobber_upload_dir\63d46565-76da-46e7-8e6e-cbccd63d487e.dmp
03:53:53  WARNING -  PROCESS-CRASH | automation.py | application crashed [None]

Comment 3

[Nils Ohlmeier [:drno]]

Chris, can I ask you to take a quick look to figure how urgent this is and who would be a good person to investigate?

Comment 4

[Intermittent Failures Robot]

15 failures in 46 pushes (0.326 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 6
* mozilla-central: 5
* mozilla-inbound: 4

Platform breakdown:
* windows10-64: 12
* windows10-64-nightly: 1
* osx-10-10: 1
* linux64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1444642&startday=2018-03-17&endday=2018-03-17&tree=all

Comment 5

[Intermittent Failures Robot]

79 failures in 814 pushes (0.097 failures/push) were associated with this bug in the last 7 days. 

This is the #13 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 30
* mozilla-inbound: 21
* mozilla-central: 18
* try: 10

Platform breakdown:
* windows10-64: 70
* osx-10-10: 4
* windows10-64-nightly: 3
* windows10-64-qr: 1
* linux64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1444642&startday=2018-03-12&endday=2018-03-18&tree=all

Comment 6

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Seems to be a duplicate of bug 1414495.

Comment 7

[Intermittent Failures Robot]

19 failures in 149 pushes (0.128 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* try: 10
* mozilla-inbound: 8
* autoland: 1

Platform breakdown:
* windows10-64: 19

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1444642&startday=2018-03-20&endday=2018-03-20&tree=all

Comment 8

[Intermittent Failures Robot]

19 failures in 822 pushes (0.023 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 11
* mozilla-inbound: 7
* autoland: 1

Platform breakdown:
* windows10-64: 19

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1444642&startday=2018-03-20&endday=2018-03-26&tree=trunk