1407205 - Intermittent Windows10 TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 330 seconds with no output

Status: RESOLVED DUPLICATE of bug 1397201

(Testing :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

https://treeherder.mozilla.org/logviewer.html#?job_id=135889670&repo=autoland

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

08:18:04     INFO -  TEST-START | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_websocket.js
08:18:04     INFO -  TEST-SKIP | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_websocket.js | took 1ms
08:18:04     INFO -  TEST-START | devtools/client/webide/test/browser_tabs.js
08:18:04     INFO -  TEST-SKIP | devtools/client/webide/test/browser_tabs.js | took 0ms
08:18:04     INFO -  Running manifest: devtools\client\debugger\test\mochitest\browser2.ini
08:18:04     INFO -  Z:\task_1507622899\build\tests\bin\pk12util.exe: PKCS12 IMPORT SUCCESSFUL
08:18:04     INFO -  MochitestServer : launching [u'Z:\\task_1507622899\\build\\tests\\bin\\xpcshell.exe', '-g', 'Z:\\task_1507622899\\build\\application\\firefox', '-v', '170', '-f', 'Z:\\task_1507622899\\build\\tests\\bin\\components\\httpd.js', '-e', "const _PROFILE_PATH = 'c:\\\\users\\\\genericworker\\\\appdata\\\\local\\\\temp\\\\tmps1rmbl.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', 'Z:\\task_1507622899\\build\\tests\\mochitest\\server.js']
08:18:04     INFO -  runtests.py | Server pid: 12636
08:18:04     INFO -  runtests.py | Websocket server pid: 10232
08:18:04     INFO -  runtests.py | SSL tunnel pid: 14556
08:18:05     INFO -  runtests.py | Running with e10s: True
08:18:05     INFO -  runtests.py | Running tests: start.
08:18:05     INFO -  Application command: Z:\task_1507622899\build\application\firefox\firefox.exe -marionette -foreground -profile c:\users\genericworker\appdata\local\temp\tmps1rmbl.mozrunner
08:18:05     INFO -  runtests.py | Application pid: 11536
08:18:05     INFO -  TEST-INFO | started process GECKO(11536)
08:18:05     INFO -  GECKO(11536) | 1507623485706	Marionette	INFO	Enabled via --marionette
08:18:07     INFO -  GECKO(11536) | 1507623487012	Marionette	INFO	Listening on port 2828
08:23:37     INFO -  Buffered messages finished
08:23:37  WARNING -  TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 330 seconds with no output
08:23:37     INFO -  0 ERROR Force-terminating active process(es).
08:23:37     INFO -  Determining child pids from psutil
08:23:37     INFO -  Found child pids: [2016, 16116, 6484]
08:23:37     INFO -  Killing process: 2016
08:23:37     INFO -  TEST-INFO | started process screenshot
08:23:37     INFO -  TEST-INFO | screenshot: exit 0
08:23:37     INFO -  mozcrash Using Z:\task_1507622899\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\genericworker\appdata\local\temp\tmps1rmbl.mozrunner\minidumps\4751a4f2-010a-4e78-8c56-63ba6fc55b3e.dmp for [2016]
08:23:37     INFO -  Killing process: 16116
08:23:37     INFO -  Not taking screenshot here: see the one that was previously logged
08:23:37     INFO -  mozcrash Using Z:\task_1507622899\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\genericworker\appdata\local\temp\tmps1rmbl.mozrunner\minidumps\cd4d413c-26ec-443a-9fc6-a6593188d201.dmp for [16116]
08:23:37     INFO -  Killing process: 6484
08:23:37     INFO -  Not taking screenshot here: see the one that was previously logged
08:23:37     INFO -  mozcrash Using Z:\task_1507622899\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\genericworker\appdata\local\temp\tmps1rmbl.mozrunner\minidumps\3609768c-b925-47b3-954a-f490ee2728d3.dmp for [6484]
08:23:37     INFO -  psutil found pid 16116 dead
08:23:37     INFO -  psutil found pid 2016 dead
08:23:37     INFO -  psutil found pid 6484 dead
08:23:37     INFO -  Killing process: 11536
08:23:37     INFO -  Not taking screenshot here: see the one that was previously logged
08:23:37     INFO -  mozcrash Using Z:\task_1507622899\build\tests\bin\minidumpwriter.exe to write a dump to c:\users\genericworker\appdata\local\temp\tmps1rmbl.mozrunner\minidumps\d2f3bc85-6975-40d3-b63c-7f7b26076075.dmp for [11536]
08:24:05     INFO -  TEST-INFO | Main app process: exit 1
08:24:05     INFO -  Buffered messages finished
08:24:05    ERROR -  1 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1
08:24:05     INFO -  runtests.py | Application ran for: 0:06:00.062000
08:24:05     INFO -  zombiecheck | Reading PID log: c:\users\genericworker\appdata\local\temp\tmpsrtnnqpidlog
08:24:05     INFO -  ==> process 11536 launched child process 16116 ("Z:\task_1507622899\build\application\firefox\firefox.exe" -contentproc --channel="11536.0.1895124898\1145898429" -greomni "Z:\task_1507622899\build\application\firefox\omni.ja" -appomni "Z:\task_1507622899\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1507622899\build\application\firefox\browser"  "C:\Users\GenericWorker\AppData\LocalLow\Mozilla\Temp-{85414bb3-6e36-49e4-b1b8-827227a07b3e}" 11536 "\\.\pipe\gecko-crash-server-pipe.11536" gpu)
08:24:05     INFO -  ==> process 11536 launched child process 6484 ("Z:\task_1507622899\build\application\firefox\firefox.exe" -contentproc --channel="11536.3.2025966079\623696783" -childID 1 -isForBrowser -intPrefs 5:50|6:-1|29:1000|35:0|36:5|37:0|46:128|47:10000|52:0|54:400|55:1|56:0|57:0|62:0|63:120|64:120|99:2|100:1|115:0|125:0|127:0|138:10000|150:-1|155:128|156:10000|157:0|163:24|164:32768|166:0|167:0|175:2|179:1048576|180:100|181:5000|183:600|185:1|194:4|198:0|207:60000| -boolPrefs 1:0|2:0|4:1|27:1|28:1|31:1|34:1|38:1|39:0|40:0|41:0|44:1|45:1|48:1|49:1|50:0|51:0|53:0|58:1|59:1|60:1|61:1|65:1|66:1|67:0|68:1|69:1|70:1|71:1|74:0|75:0|78:1|79:1|83:1|84:1|85:1|86:0|87:0|89:0|90:0|91:1|92:1|93:1|96:1|98:1|101:1|102:0|109:0|114:0|117:1|120:1|122:1|126:0|129:1|130:1|132:1|133:1|139:0|140:0|141:1|143:0|149:0|151:1|152:0|153:1|154:1|161:0|162:0|165:1|168:0|170:1|172:1|173:0|178:0|182:1|187:0|188:0|189:0|190:1|191:0|192:1|193:1|196:0|199:1|200:0|201:1|202:1|203:0|204:1|205:1|206:1|208:0|209:0|211:1|219:1|220:1|221:0|222:0|223:0| -stringPrefs "3:7;default|97:0;|142:4;0.01|159:332; ����!==> process 11536 launched child process 2016 ("Z:\task_1507622899\build\application\firefox\firefox.exe" -contentproc --channel="11536.13.1118661382\1773867787" -childID 2 -isForBrowser -intPrefs 5:50|6:-1|29:1000|35:0|36:5|37:0|46:128|47:10000|52:0|54:400|55:1|56:0|57:0|62:0|63:120|64:120|99:2|100:1|115:0|125:0|127:0|138:10000|150:-1|155:128|156:10000|157:0|163:24|164:32768|166:0|167:0|175:2|179:1048576|180:100|181:5000|183:600|185:1|194:4|198:0|207:60000| -boolPrefs 1:0|2:0|4:1|27:1|28:1|31:1|34:1|38:1|39:0|40:0|41:0|44:1|45:1|48:1|49:1|50:0|51:0|53:0|58:1|59:1|60:1|61:1|65:1|66:1|67:0|68:1|69:1|70:1|71:1|74:0|75:0|78:1|79:1|83:1|84:1|85:1|86:0|87:0|89:0|90:0|91:1|92:1|93:1|96:1|98:1|101:1|102:0|109:0|114:0|117:1|120:1|122:1|126:0|129:1|130:1|132:1|133:1|139:0|140:0|141:1|143:0|149:0|151:1|152:0|153:1|154:1|161:0|162:0|165:1|168:0|170:1|172:1|173:0|178:0|182:1|187:0|188:0|189:0|190:1|191:0|192:1|193:1|196:0|199:1|200:0|201:1|202:1|203:0|204:1|205:1|206:1|208:0|209:0|211:1|219:1|220:1|221:0|222:0|223:0| -stringPrefs "3:7;default|97:0;|142:4;0.01|159:332; ����!==> process 11536 launched child process 1544 ("Z:\task_1507622899\build\application\firefox\firefox.exe" -contentproc --channel="11536.20.968535912\1878736698" -greomni "Z:\task_1507622899\build\application\firefox\omni.ja" -appomni "Z:\task_1507622899\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1507622899\build\application\firefox\browser"  "C:\Users\GenericWorker\AppData\LocalLow\Mozilla\Temp-{85414bb3-6e36-49e4-b1b8-827227a07b3e}" 11536 "\\.\pipe\gecko-crash-server-pipe.11536" gpu)
08:24:05     INFO -  zombiecheck | Checking for orphan process with PID: 16116
08:24:05     INFO -  zombiecheck | Checking for orphan process with PID: 6484
08:24:05     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/e17WMBVtT06mDZAMRpzZ0w/artifacts/public/build/target.crashreporter-symbols.zip
08:24:08     INFO -  mozcrash Copy/paste: Z:\task_1507622899\build\win32-minidump_stackwalk.exe c:\users\genericworker\appdata\local\temp\tmps1rmbl.mozrunner\minidumps\3609768c-b925-47b3-954a-f490ee2728d3.dmp c:\users\genericworker\appdata\local\temp\tmp20sb31
08:24:13     INFO -  mozcrash Saved minidump as Z:\task_1507622899\build\blobber_upload_dir\3609768c-b925-47b3-954a-f490ee2728d3.dmp
08:24:13  WARNING -  PROCESS-CRASH | automation.py | application crashed [None]
08:24:13     INFO -  Crash dump filename: c:\users\genericworker\appdata\local\temp\tmps1rmbl.mozrunner\minidumps\3609768c-b925-47b3-954a-f490ee2728d3.dmp
08:24:13     INFO -  Operating system: Windows NT
08:24:13     INFO -                    10.0.15063
08:24:13     INFO -  CPU: amd64
08:24:13     INFO -       family 6 model 63 stepping 2
08:24:13     INFO -       8 CPUs
08:24:13     INFO -  GPU: UNKNOWN
08:24:13     INFO -  No crash
08:24:13     INFO -  Process uptime: 332 seconds
08:24:13     INFO -  Thread 0
08:24:13     INFO -   0  ntdll.dll!NtWaitForMultipleObjects + 0x14
08:24:13     INFO -      rax = 0x0000000000000001   rdx = 0x00000230003e9780
08:24:13     INFO -      rcx = 0x00007ff99fbb23a8   rbx = 0x0000000000000001
08:24:13     INFO -      rsi = 0x0000000000000001   rdi = 0x0000000000000001
08:24:13     INFO -      rbp = 0x0000023000830740   rsp = 0x0000004948dfe9e8
08:24:13     INFO -       r8 = 0x00007ff99fa4878c    r9 = 0x0000000000000000
08:24:13     INFO -      r10 = 0x0000000000000001   r11 = 0x00000230003e97c0
08:24:13     INFO -      r12 = 0x00000000ffffffff   r13 = 0x0000004948dfed30
08:24:13     INFO -      r14 = 0x0000000000000000   r15 = 0x0000000000000000
08:24:13     INFO -      rip = 0x00007ff9d9155f04
08:24:13     INFO -      Found by: given as instruction pointer in context
08:24:13     INFO -   1  KERNELBASE.dll!SbCleanupTrace + 0x18
08:24:13     INFO -      rbx = 0x0000000000000001   rbp = 0x0000023000830740
08:24:13     INFO -      rsp = 0x0000004948dfe9f0   r12 = 0x00000000ffffffff
08:24:13     INFO -      r13 = 0x0000004948dfed30   r14 = 0x0000000000000000
08:24:13     INFO -      r15 = 0x0000000000000000   rip = 0x00007ff9d60edd20
08:24:13     INFO -      Found by: call frame info
08:24:13     INFO -  Thread 1
08:24:13     INFO -   0  ntdll.dll!NtRemoveIoCompletion + 0x14
08:24:13     INFO -      rax = 0x000000000000bf64   rdx = 0x000000000000c1a4
08:24:13     INFO -      rcx = 0x0000000000bf0322   rbx = 0x0000004948fff490
08:24:13     INFO -      rsi = 0x0000000000000000   rdi = 0x0000004948fff4c0
08:24:13     INFO -      rbp = 0x0000004948fff4d0   rsp = 0x0000004948fff3e8
08:24:13     INFO -       r8 = 0x0000000000000000    r9 = 0x000002300034e980
08:24:13     INFO -      r10 = 0x00007ff99fa2bf28   r11 = 0x00000230003f7000
08:24:13     INFO -      r12 = 0x0000000000000000   r13 = 0x0000000000000000
08:24:13     INFO -      r14 = 0x00000000ffffffff   r15 = 0x0000000000000000
08:24:13     INFO -      rip = 0x00007ff9d91554d4
08:24:13     INFO -      Found by: given as instruction pointer in context
08:24:13     INFO -   1  KERNELBASE.dll!LdrResGetRCConfig + 0x3ff
08:24:13     INFO -      rbx = 0x0000004948fff490   rbp = 0x0000004948fff4d0
08:24:13     INFO -      rsp = 0x0000004948fff3f0   r12 = 0x0000000000000000
08:24:13     INFO -      r13 = 0x0000000000000000   r14 = 0x00000000ffffffff
08:24:13     INFO -      r15 = 0x0000000000000000   rip = 0x00007ff9d60f9aff
08:24:13     INFO -      Found by: call frame info

Comment 1

[Intermittent Failures Robot]

31 failures in 171 pushes (0.181 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 15
* autoland: 12
* mozilla-beta: 4

Platform breakdown:
* windows10-64-stylo-disabled: 17
* windows10-64: 13
* windows10-64-devedition: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407205&startday=2017-10-10&endday=2017-10-10&tree=all

Comment 2

[Intermittent Failures Robot]

72 failures in 188 pushes (0.383 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 24
* mozilla-beta: 19
* autoland: 12
* mozilla-inbound: 10
* try: 7

Platform breakdown:
* windows10-64: 34
* windows10-64-stylo-disabled: 26
* windows10-64-nightly: 8
* windows10-64-devedition: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407205&startday=2017-10-11&endday=2017-10-11&tree=all

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

here is another one where we have tons of new failures :(

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

we never start the tests, possibly this is marionette causing more problems?

if we timeout with 330 seconds, that should be long enough for marionette- maybe this is something else.  Any ideas on what else to collect to debug this?

BTW, this has 90+ failures in the last 2 days.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Why a new bug? This basically is bug 1397201.

Comment 6

[Intermittent Failures Robot]

16 failures in 182 pushes (0.088 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 12
* mozilla-inbound: 3
* try: 1

Platform breakdown:
* windows10-64: 13
* windows10-64-stylo-disabled: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407205&startday=2017-10-12&endday=2017-10-12&tree=all

Comment 7

[Intermittent Failures Robot]

141 failures in 947 pushes (0.149 failures/push) were associated with this bug in the last 7 days. 

This is the #6 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: 43
* mozilla-inbound: 32
* mozilla-central: 25
* mozilla-beta: 23
* try: 18

Platform breakdown:
* windows10-64: 76
* windows10-64-stylo-disabled: 51
* windows10-64-nightly: 9
* windows10-64-devedition: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407205&startday=2017-10-09&endday=2017-10-15&tree=all