Filed by: archaeopteryx [at] coole-files.de https://treeherder.mozilla.org/logviewer.html#?job_id=142108991&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/RhxWTJ_kRR2RXHpbbWWJoQ/runs/0/artifacts/public/test_info/mochitest-devtools-chrome-chunked_errorsummary.log 05:46:09 INFO - TEST-START | devtools/client/performance/test/browser_timeline-waterfall-workers.js 05:46:09 INFO - TEST-SKIP | devtools/client/performance/test/browser_timeline-waterfall-workers.js | took 0ms 05:46:09 INFO - Running manifest: devtools\client\debugger\new\test\mochitest\browser.ini 05:46:09 INFO - Z:\task_1509773846\build\tests\bin\pk12util.exe: PKCS12 IMPORT SUCCESSFUL 05:46:09 INFO - MochitestServer : launching [u'Z:\\task_1509773846\\build\\tests\\bin\\xpcshell.exe', '-g', 'Z:\\task_1509773846\\build\\application\\firefox', '-v', '170', '-f', 'Z:\\task_1509773846\\build\\tests\\bin\\components\\httpd.js', '-e', "const _PROFILE_PATH = 'c:\\\\users\\\\genericworker\\\\appdata\\\\local\\\\temp\\\\tmpxtl83a.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', 'Z:\\task_1509773846\\build\\tests\\mochitest\\server.js'] 05:46:09 INFO - runtests.py | Server pid: 7068 05:46:09 INFO - runtests.py | Websocket server pid: 8724 05:46:09 INFO - runtests.py | SSL tunnel pid: 7308 05:46:10 INFO - runtests.py | Running with e10s: True 05:46:10 INFO - runtests.py | Running tests: start. 05:46:10 INFO - Application command: Z:\task_1509773846\build\application\firefox\firefox.exe -marionette -foreground -profile c:\users\genericworker\appdata\local\temp\tmpxtl83a.mozrunner 05:46:10 INFO - runtests.py | Application pid: 6256 05:46:10 INFO - TEST-INFO | started process GECKO(6256) 05:46:10 INFO - GECKO(6256) | 1509774370676 Marionette DEBUG Received observer notification "profile-after-change" 05:46:10 INFO - GECKO(6256) | 1509774370793 Marionette DEBUG Received observer notification "command-line-startup" 05:46:10 INFO - GECKO(6256) | 1509774370793 Marionette INFO Enabled via --marionette 05:46:11 INFO - GECKO(6256) | 1509774371746 Marionette DEBUG Received observer notification "sessionstore-windows-restored" 05:46:12 INFO - GECKO(6256) | 1509774372064 Marionette DEBUG New connections are accepted 05:46:12 INFO - GECKO(6256) | 1509774372064 Marionette INFO Listening on port 2828 05:52:22 INFO - Buffered messages finished 05:52:22 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output

I added some logging in https://treeherder.mozilla.org/#/jobs?repo=try&revision=6737b2be84e9b7cd23fcb1dcf4586abab865498a and reproduced the timeouts. In the timeout cases, it looks to me like start_session() completes very quickly -- maybe even before the server has started?? I wonder if it is actually connecting to something (what?) or if it is just failing but not noticing that it's failing. I then added more logging and pushed to try, but then couldn't reproduce any time outs on startup -- just as jmaher reported in https://bugzilla.mozilla.org/show_bug.cgi?id=1397201#c79.

Maybe related to https://bugzilla.mozilla.org/show_bug.cgi?id=1282638#c54??

Go ahead and successfully get that bug suggested for both 330 second failures on beta/release/esr52 and for 370 second failures on the trunk, and only *then* mark this as a duplicate of it.

There are 73 failures related to this bug in the last 7 days. We can see this occurring on Windows 10, OSX, Linux 64 and Windows 7 (opt, pgo and debug). :whimboo any updates on this? 09:55:30 INFO - Calling ['C:\\slave\\test\\build\\venv\\Scripts\\python', '-u', 'C:\\slave\\test\\build\\tests\\reftest\\runreftest.py', '--appname=C:\\slave\\test\\build\\application\\firefox\\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/Bq3iCutpRqyt6w1eZve9WQ/artifacts/public/build/target.crashreporter-symbols.zip', '--log-raw=C:\\slave\\test\\build\\blobber_upload_dir\\reftest_raw.log', '--log-errorsummary=C:\\slave\\test\\build\\blobber_upload_dir\\reftest_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--log-raw=-', '--suite=reftest', '--', 'tests/reftest/tests/layout/reftests/reftest.list'] with output_timeout 1000 09:55:31 INFO - REFTEST INFO | Running with e10s: True 09:55:31 INFO - REFTEST INFO | Application command: C:\slave\test\build\application\firefox\firefox.exe -marionette -profile c:\users\cltbld\appdata\local\temp\tmp9br3ex.mozrunner 10:01:41 ERROR - REFTEST ERROR | reftest | application timed out after 370 seconds with no output 10:01:41 ERROR - REFTEST ERROR | Force-terminating active process(es). 10:01:41 INFO - REFTEST TEST-INFO | started process screenshot 10:01:41 INFO - REFTEST TEST-INFO | screenshot: exit 0 10:01:41 INFO - TEST-INFO | crashinject: exit 0 10:01:42 ERROR - TEST-UNEXPECTED-FAIL | reftest | application terminated with exit code 1 10:01:42 INFO - REFTEST INFO | Downloading symbols from: https://queue.taskcluster.net/v1/task/Bq3iCutpRqyt6w1eZve9WQ/artifacts/public/build/target.crashreporter-symbols.zip 10:01:48 INFO - REFTEST INFO | Copy/paste: C:\slave\test\build\win32-minidump_stackwalk.exe c:\users\cltbld\appdata\local\temp\tmp9br3ex.mozrunner\minidumps\b53c3a0f-9d59-44f4-a529-321d52056490.dmp c:\users\cltbld\appdata\local\temp\tmplrafuh 10:01:53 INFO - REFTEST INFO | Saved minidump as C:\slave\test\build\blobber_upload_dir\b53c3a0f-9d59-44f4-a529-321d52056490.dmp 10:01:53 INFO - REFTEST INFO | Saved app info as C:\slave\test\build\blobber_upload_dir\b53c3a0f-9d59-44f4-a529-321d52056490.extra 10:01:53 INFO - REFTEST PROCESS-CRASH | reftest | application crashed [@ CrashingThread(void *)] 10:01:53 INFO - Crash dump filename: c:\users\cltbld\appdata\local\temp\tmp9br3ex.mozrunner\minidumps\b53c3a0f-9d59-44f4-a529-321d52056490.dmp 10:01:53 INFO - Operating system: Windows NT 10:01:53 INFO - 10.0.15063 10:01:53 INFO - CPU: amd64 10:01:53 INFO - family 6 model 30 stepping 5 10:01:53 INFO - 8 CPUs 10:01:53 INFO - 10:01:53 INFO - GPU: UNKNOWN 10:01:53 INFO - 10:01:53 INFO - Crash reason: EXCEPTION_ACCESS_VIOLATION_WRITE 10:01:53 INFO - Crash address: 0x0 10:01:53 INFO - Process uptime: 371 seconds 10:01:53 INFO - 10:01:53 INFO - Thread 29 (crashed) 10:01:53 INFO - 0 crashinjectdll.dll!CrashingThread(void *) [crashinjectdll.cpp:389bd78cf79d : 17 + 0x0] 10:01:53 INFO - rax = 0x00007ffbc5c01000 rdx = 0x00007ffbc5c01000 10:01:53 INFO - rcx = 0x0000000000000000 rbx = 0x0000000000000000 10:01:53 INFO - rsi = 0x0000000000000000 rdi = 0x0000000000000000 10:01:53 INFO - rbp = 0x0000000000000000 rsp = 0x0000009a24dffcc8 10:01:53 INFO - r8 = 0x0000000000000000 r9 = 0x0000000000000000 10:01:53 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000246 10:01:53 INFO - r12 = 0x0000000000000000 r13 = 0x0000000000000000 10:01:53 INFO - r14 = 0x0000000000000000 r15 = 0x0000000000000000 10:01:53 INFO - rip = 0x00007ffbc5c01000 10:01:53 INFO - Found by: given as instruction pointer in context 10:01:53 INFO - 1 kernel32.dll!LdrpLoadResourceFromAlternativeModule + 0x27c 10:01:53 INFO - rsp = 0x0000009a24dffcd0 rip = 0x00007ffbc86d2774 10:01:53 INFO - Found by: stack scanning

I checked some of the screenshots and found the following: Mac OS with a system notification present and in the foreground: https://public-artifacts.taskcluster.net/bPC-phMtQp-XV3W97WGDhw/0/public/test_info/mozilla-test-fail-screenshot_xGwbMf.png Here a Windows case when Marionette installed the Mochikit extension, but then Firefox seems to hang, and doesn't correctly load the Mochitest window: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=144259262&lineNumber=6238 https://public-artifacts.taskcluster.net/f6p4HQJGQsCBeockIpEjRw/0/public/test_info/mozilla-test-fail-screenshot_bgwyes.png Here a job on Linux, which also shows that Marionette has been finished installing the addons but then we seem to hang with maybe the local webserver not being ready? The invalid cert message is strange: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=143862071&lineNumber=9519 https://public-artifacts.taskcluster.net/EdJZ9Ei4SYuQV4XQdCXmtA/0/public/test_info//mozilla-test-fail-screenshot_KPLPcM.png Windows again, with a command shell window in-front (I thought this was fixed): https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=143629526&lineNumber=1754 https://public-artifacts.taskcluster.net/fVHbhN6MRKiQgPymuZCUlQ/0/public/test_info/mozilla-test-fail-screenshot_uuieaw.png Geoff, it would be good if you could take over some of the work now. I will still try to get logging enabled for Marionette client, but I doubt that this client is the problem here.

OK - I'll try to look into this early next week, including following up on your excellent screenshots.

The Mac notification has been there for multiple versions of OS X, we've filed multiple bugs about it, multiple times discovered that it wasn't causing any of the problems we blamed on it, and multiple times discovered that none of the things people say will allow for automating getting rid of it actually will get rid of it.

Btw. what happens when mochitests are getting started, and Firefox gets moved to the background? Some tests do need explicit focus set to Firefox, and print a message to the console. Is this just a print or a logging statement? I wonder if this could cause a hang we do not see in the logs.

There were several hangs reported here on Nov 16 for Windows test-verify. Those were triggered by bug 1396620, which was backed out; on re-landing, there were no test-verify failures.

There were also several hangs in Windows 10 ccov tests, a new platform. Those tests are hidden now - tier 3 - so let's ignore those too.

I've made some progress on bug 1419121, which I thought might be related, but as it turns out probably isn't very important to this bug. The majority of recent failures here are Windows 10 mochitests, with perhaps a bias toward pgo builds. They seem consistent in that logs typically end with 'Received observer notification "profile-after-change"' before the timeout. The parent process is alive at the time of the timeout, and crash reports are produced. Screenshots typically do not show the browser. All of that seems consistent with a browser hang early in startup. The location of the hang is not apparent to me from the crash reports. I typically see threads running MessagePumpForNonMainThreads and helper threads and native Windows code, and most threads just waiting. Still investigating...

https://treeherder.mozilla.org/#/jobs?repo=try&revision=b2ba28de727cfbe53c51b254dacd489cb2dd0fd2 reproduces the hang on Windows 10 pgo and appears to confirm a hang early in startup, somewhere in https://dxr.mozilla.org/mozilla-central/rev/c2248f85346939d3e0b01f57276c440ccb2d16a1/toolkit/xre/nsXREDirProvider.cpp#1022-1073 Trying to narrow it down further...

Now narrowed down to https://dxr.mozilla.org/mozilla-central/rev/38f49346a200cc25492236c7b3c536fc835fe031/toolkit/xre/nsXREDirProvider.cpp#1024-1025

(In reply to Geoff Brown [:gbrown] from comment #19) > Now narrowed down to > > https://dxr.mozilla.org/mozilla-central/rev/ > 38f49346a200cc25492236c7b3c536fc835fe031/toolkit/xre/nsXREDirProvider. > cpp#1024-1025 Does it hang? I wonder for which component registered under "profile-after-change" that is happening. Looks like we have to add some log statements to: https://dxr.mozilla.org/mozilla-central/source/xpcom/components/nsCategoryManager.cpp#757

It does hang, at least for 370 seconds. https://treeherder.mozilla.org/#/jobs?repo=try&revision=53d0f4bc5311160f45bf9bf4fd9fa061263fb9ca narrows it down just a little more, to https://dxr.mozilla.org/mozilla-central/rev/574f4f58fe09dd590ea892406e237318c31705b4/xpcom/components/nsCategoryManager.cpp#784-817 I assume one of the profile-after-change observers is hanging, but I cannot reproduce the hang once I add logging to the loop (and that wouldn't be very helpful anyway -- still wouldn't know which observer is to blame). A better crash report would be very useful...why are they so consistently unhelpful?

Shouldn't we better find someone who has knowledge in that area? Dave, do you know who could help us in investigating this hang/crash during start-up? I would have suggested Benjamin but he is no longer with us. Thanks.

Help would be great! https://treeherder.mozilla.org/#/jobs?repo=try&revision=cdf7b1aecc826f41e45e25fb9b249fa5d5df8906 demonstrates what I have found so far. On Windows 10/pgo, there is an intermittent hang during startup. XRE_mainRun() calls mDirProvider.DoStartup() https://hg.mozilla.org/try/rev/5e8a028c3373c8d8c8af2b98923c1cb636610eb9#l1.14 which calls NS_CreateServicesFromCategory() https://hg.mozilla.org/try/rev/5e8a028c3373c8d8c8af2b98923c1cb636610eb9#l2.16 which enumerates and notifies observers of 'profile-after-change' https://hg.mozilla.org/try/rev/5e8a028c3373c8d8c8af2b98923c1cb636610eb9#l3.14 There are other calls to NS_CreateServicesFromCategory(), so on a successful run this logging produces something like 21:45:46 INFO - GECKO(5920) | ZZZ NS_CreateServicesFromCategory starts loop 21:45:46 INFO - GECKO(5920) | ZZZ NS_CreateServicesFromCategory starts loop 21:45:46 INFO - GECKO(5920) | ZZZ XRE_mainRun calls mDirProvider.DoStartup 21:45:46 INFO - GECKO(5920) | ZZZ NS_CreateServicesFromCategory starts loop 21:45:46 INFO - GECKO(5920) | ZZZ DoStartup calls NS_CreateServicesFromCategory 21:45:46 INFO - GECKO(5920) | ZZZ NS_CreateServicesFromCategory starts loop 21:45:46 INFO - GECKO(5920) | 1512423946889 Marionette DEBUG Received observer notification "profile-after-change" 21:45:47 INFO - GECKO(5920) | ZZZ NS_CreateServicesFromCategory done 21:45:47 INFO - GECKO(5920) | ZZZ mDirProvider.DoStartup done Intermittently, there is a hang and we get: https://treeherder.mozilla.org/logviewer.html#?job_id=149681058&repo=try&lineNumber=11692 22:43:24 INFO - GECKO(6604) | ZZZ NS_CreateServicesFromCategory starts loop 22:43:25 INFO - GECKO(6604) | ZZZ NS_CreateServicesFromCategory starts loop 22:43:25 INFO - GECKO(6604) | ZZZ XRE_mainRun calls mDirProvider.DoStartup 22:43:25 INFO - GECKO(6604) | ZZZ NS_CreateServicesFromCategory starts loop 22:43:25 INFO - GECKO(6604) | ZZZ DoStartup calls NS_CreateServicesFromCategory 22:43:25 INFO - GECKO(6604) | ZZZ NS_CreateServicesFromCategory starts loop 22:43:25 INFO - GECKO(6604) | 1512427405433 Marionette DEBUG Received observer notification "profile-after-change" 22:46:25 INFO - runtests.py | Waiting for browser... 22:49:35 INFO - Buffered messages finished 22:49:35 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output If I add additional logging within the observer loop, I can no longer reproduce the hang. Curiously, I never see XRE_mainRun or DoStartup or NS_CreateServicesFromCategory in the crash report. This is a startup hang, but I think the hang is after the crash reporter is initialized. These are pgo builds -- that probably doesn't help.

Florian, can you help with this startup-related issue?

This bug has failed 36 times in the last 7 days on Windows 10-64, Linux64 and OS X 10.10 on asan, pgo and debug build types. Here is a recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=153056867 And here is part of the log: WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output 00:38:10 INFO - 1141 ERROR Force-terminating active process(es). 00:38:10 INFO - Determining child pids from psutil... 00:38:10 INFO - [] 00:38:10 INFO - Found child pids: set([]) 00:38:10 INFO - Killing process: 600 00:38:10 INFO - TEST-INFO | started process screenshot 00:38:10 INFO - TEST-INFO | screenshot: exit 0 00:38:10 INFO - mozcrash kill_pid(): wait failed (-1) terminating pid 600: error 5 00:38:10 INFO - psutil found pid 600 dead 00:38:10 INFO - TEST-INFO | Main app process: exit 1 00:38:10 INFO - Buffered messages finished 00:38:10 ERROR - 1142 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1 00:38:10 INFO - runtests.py | Application ran for: 0:06:10.602000 00:38:10 INFO - zombiecheck | Reading PID log: c:\users\genericworker\appdata\local\temp\tmp4pdowzpidlog 00:38:10 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/KgFDiTGcTb2MD86V9ZQtqw/artifacts/public/build/target.crashreporter-symbols.zip 00:38:13 INFO - mozcrash Copy/paste: Z:\task_1513901523\build\win32-minidump_stackwalk.exe c:\users\genericworker\appdata\local\temp\tmpq0ik1j.mozrunner\minidumps\f1c8369b-a44c-4d8d-a21a-e6d41cd3490e.dmp c:\users\genericworker\appdata\local\temp\tmpvlr48b 00:38:24 INFO - mozcrash Saved minidump as Z:\task_1513901523\build\blobber_upload_dir\f1c8369b-a44c-4d8d-a21a-e6d41cd3490e.dmp 00:38:24 WARNING - PROCESS-CRASH | automation.py | application crashed [None] 00:38:24 INFO - Crash dump filename: c:\users\genericworker\appdata\local\temp\tmpq0ik1j.mozrunner\minidumps\f1c8369b-a44c-4d8d-a21a-e6d41cd3490e.dmp 00:38:24 INFO - Operating system: Windows NT 00:38:24 INFO - 10.0.15063 00:38:24 INFO - CPU: amd64 00:38:24 INFO - family 6 model 63 stepping 2 00:38:24 INFO - 8 CPUs 00:38:24 INFO - GPU: UNKNOWN 00:38:24 INFO - No crash 00:38:24 INFO - Process uptime: 371 seconds 00:38:24 INFO - Thread 0 Hi :gbrown, can you please take a look at this bug?

I'm waiting for Florian. This may take a while to sort out.

On 2018-01-11 there was a spike of failures in Windows test-verify reported here. Those are likely a separate, non-recurring problem that should probably be ignored for now.

These failures have been very infrequent for the last 2 weeks. I don't know why. Similar failures continue in reftests in bug 1418575.

Temporary spike on Feb 2 was Windows test-verify of js\\xpconnect\\tests\\mochitest\\test_bug790732.html (triggered by bug 1435138).

Lower frequency failures continue here, perhaps from multiple causes. I no longer see any of the Windows screenshot oddities that were previously noted. I expect bug 1437420 to reduce failure frequency by about 30% more. I would still like to hear from :florian regarding investigation of the possible intermittent browser startup hang. Changing to [stockwell infra] to reflect that this bug may indicate multiple on-going issues.

(In reply to Geoff Brown [:gbrown] from comment #43) > I would still like to hear from :florian regarding investigation of the > possible intermittent browser startup hang. Which kind of investigation do you expect from me here? From looking at the failures in comment 42, most have a JS error like: 15:32:55 INFO - GECKO(3416) | JavaScript error: http://mochi.test:8888/tests/js/xpconnect/tests/mochitest?autorun=1&closeWhenDone=1&consoleLevel=INFO&runUntilFailure=1&repeat=10&testname=tests/js\xpconnect\tests\mochitest\test_bug790732.html&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Cgenericworker%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true, line 11: SyntaxError: malformed hexadecimal character escape sequence Then there are a few isolate odd ones, like https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=160828169&lineNumber=57455 that has "Assertion failure: aVsyncTimestamp <= TimeStamp::Now(), at z:/build/build/src/layout/base/nsRefreshDriver.cpp:680"

"malformed hexadecimal character escape sequence" should be handled by bug 1437420. The aVsyncTimestamp assertion is interesting. There are also cases like https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=161236315&lineNumber=12171 02:39:15 INFO - Application command: Z:\task_1518142850\build\application\firefox\firefox.exe -marionette -foreground -profile c:\users\genericworker\appdata\local\temp\tmpdymd4w.mozrunner 02:39:15 INFO - runtests.py | Application pid: 5076 02:39:15 INFO - TEST-INFO | started process GECKO(5076) 02:39:15 INFO - GECKO(5076) | 1518143955773 Marionette DEBUG Received observer notification profile-after-change 02:42:15 INFO - runtests.py | Waiting for browser... 02:45:25 INFO - Buffered messages finished 02:45:25 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output Marionette would normally report next: GECKO(6080) | 1518349905300 Marionette DEBUG Received observer notification command-line-startup but there's no sign of that in these cases. If command-line-startup is not received, I'd expect marionette to not start, and no tests will run. It would be great if we could determine why firefox startup seems to hang like this.

(In reply to Geoff Brown [:gbrown] from comment #45) > There are also cases like > > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > inbound&job_id=161236315&lineNumber=12171 This contains a crash dump, which I don't know how to read. Who could help to understand it? xul.dll!profiler_suspend_and_sample_thread at https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=161236315&lineNumber=13199 makes me wonder if the profiler is somehow enabled, and if so how we could access the captured profile.

Florian, this is not a crash. After the test failure as covered by this bug mozprocess killed the process: > Killing process: 5076 The crash info also mentions 'No Crash'. So this is a hang between: 02:39:15 INFO - Application command: Z:\task_1518142850\build\application\firefox\firefox.exe -marionette -foreground -profile c:\users\genericworker\appdata\local\temp\tmpdymd4w.mozrunner 02:39:15 INFO - runtests.py | Application pid: 5076 02:39:15 INFO - TEST-INFO | started process GECKO(5076) 02:39:15 INFO - GECKO(5076) | 1518143955773 Marionette DEBUG Received observer notification profile-after-change ..... [1] 02:42:15 INFO - runtests.py | Waiting for browser... 02:45:25 INFO - Buffered messages finished 02:45:25 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output 02:45:25 INFO - 911 ERROR Force-terminating active process(es). [1] Here nothing happened and the -marionette argument is not handled.

(In reply to Henrik Skupin (:whimboo) from comment #47) > Florian, this is not a crash. The process gets killed and we have a crash dump. I would like to understand what the main thread was doing at the time we killed the process, and don't know how to get that information from the crash dump.

(In reply to Florian Quèze [:florian] from comment #46) > (In reply to Geoff Brown [:gbrown] from comment #45) > > > There are also cases like > > > > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > > inbound&job_id=161236315&lineNumber=12171 > > This contains a crash dump, which I don't know how to read. Who could help > to understand it? :ted knows a lot about how crash dumps are generated, crash dump format, etc. :mconley comes to mind as someone who's done a lot of crash debugging. Perhaps needinfo one of them?

I talked to Ted on IRC and he mentioned to me mozcrash.kill_and_get_minidump(): https://dxr.mozilla.org/mozilla-central/rev/27fd083ed7ee5782e52a5eaf0286c5ffa8b35a9e/testing/mozbase/mozcrash/mozcrash/mozcrash.py#512 Maybe we should use that method instead of mozprocess' kill(SIGKILL) in case of detected application hangs and timeouts? In that case we should get at least a better stack.

Please skip my last comment. We already do that. So the stack we see here shows what was going on at that time. Ted suggested to load the minidump as attached as artifact into the debugger and to get more details: https://queue.taskcluster.net/v1/task/Mt-3rb_sST270x1rN7P-Qw/runs/0/artifacts/public/test_info/8a7e9064-b5dc-4108-82e4-b704d7c64012.dmp

I managed to open this crash dump with Visual Studio, here is the stack I got: [External Code] xul.dll!mozilla::widget::GfxInfo::Init() Line 393 C++ > xul.dll!mozilla::widget::GfxInfoConstructor(nsISupports * aOuter, const nsID & aIID, void * * aResult) Line 152 C++ xul.dll!nsComponentManagerImpl::CreateInstance(const nsID & aClass, nsISupports * aDelegate, const nsID & aIID, void * * aResult) Line 1003 C++ xul.dll!nsComponentManagerImpl::GetService(const nsID & aClass, const nsID & aIID, void * * aResult) Line 1247 C++ xul.dll!nsJSCID::GetService(JS::Handle<JS::Value> iidval, JSContext * cx, unsigned char optionalArgc, JS::MutableHandle<JS::Value> retval) Line 702 C++ [External Code] xul.dll!XPC_WN_CallMethod(JSContext * cx, unsigned int argc, JS::Value * vp) Line 929 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 473 C++ xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 3096 C++ xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 423 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 495 C++ xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 3096 C++ xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 423 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 495 C++ xul.dll!JS_CallFunctionValue(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> fval, const JS::HandleValueArray & args, JS::MutableHandle<JS::Value> rval) Line 2978 C++ xul.dll!nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS * wrapper, unsigned short methodIndex, const XPTMethodDescriptor * info_, nsXPTCMiniVariant * nativeParams) Line 1307 C++ xul.dll!nsXPCWrappedJS::CallMethod(unsigned short methodIndex, const XPTMethodDescriptor * info, nsXPTCMiniVariant * params) Line 616 C++ xul.dll!PrepareAndDispatch(nsXPTCStubBase * self, unsigned int methodIndex, unsigned __int64 * args, unsigned __int64 * gprData, double * fprData) Line 174 C++ [External Code] xul.dll!NS_CreateServicesFromCategory(const char * aCategory, nsISupports * aOrigin, const char * aObserverTopic, const char16_t *) Line 816 C++ xul.dll!nsXREDirProvider::DoStartup() Line 1035 C++ xul.dll!XREMain::XRE_mainRun() Line 4512 C++ xul.dll!XREMain::XRE_main(int argc, char * * argv, const mozilla::BootstrapConfig & aConfig) Line 4808 C++ xul.dll!XRE_main(int argc, char * * argv, const mozilla::BootstrapConfig & aConfig) Line 4901 C++ GfxInfo::Init() Line 393 looks like https://searchfox.org/mozilla-central/rev/74b7ffee403c7ffd05b8b476c411cbf11d134eb9/widget/windows/GfxInfo.cpp#393 HDEVINFO devinfo = SetupDiGetClassDevsW(nullptr, mDeviceID[0].get(), nullptr, DIGCF_PRESENT | DIGCF_PROFILE | DIGCF_ALLCLASSES);

Milan, are we aware of such a hang in GfxInfo::Init() during startup of Firefox?

There's a good chance I don't know what I'm talking about here, but, it looks like mDeviceID[0] is being used as a "PnP device instance ID" and https://msdn.microsoft.com/en-us/library/windows/hardware/ff551069(v=vs.85).aspx says When specifying a PnP device instance ID, DIGCF_DEVICEINTERFACE must be set in the Flags parameter. :milan - should DIGCF_DEVICEINTERFACE be added to the SetupDiGetClassDevsW() call?

The documentation could certainly be suggesting that, so if it takes away the intermittent hang, I'd r+ it. Geoff, want to to a try push with a bunch of repeats and see if the hang goes away?

Unfortunately, adding DIGCF_DEVICEINTERFACE seems to cause some new failures: https://treeherder.mozilla.org/#/jobs?repo=try&revision=699ca312a40c81bbc6d0a939d57696c43df3791e

:gbrown, is this what I"m experiencing with bug 1427969?

(In reply to Edmund Wong (:ewong) from comment #58) > :gbrown, is this what I"m experiencing with bug 1427969? You are getting the same "application timed out" message obviously, which really just means the harness has not seen any test output for a long time -- either the browser is hung or a test is hung. There are lots of ways to hang. Note that most of the specific issues identified so far in this bug - bug 1437420, bug 1419191, and comment 54 - only happen on Windows. We are also seeing hangs on Linux, which mostly haven't been investigated yet.

As it looks like the landed patch on bug 1441869 helped a lot. I don't see failing tests anymore for normal test jobs. But the QuantumRender jobs still have the problem: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=165175543&lineNumber=1753 Maybe we also have to update some Rust code for that GFX initialization?

The only rust call to SetupDiGetClassDevs* that I can find is https://dxr.mozilla.org/mozilla-central/rev/714a94df1a99b933a4eef2149819d2af319a1ed5/dom/webauthn/u2f-hid-rs/src/windows/winapi.rs#78-85 and that looks correct to me.

:florian -- The crash report that you obtained from Visual Studio (comment 52) was quite helpful - thanks! Could you do the same thing for a few of the most recent failures, like https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=165307692 https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=165230332 https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=165175543 ?

Geoff, I checked some of the latest reports and each of those jobs do not show an active Firefox window in the failing screenshot at all, but only a command shell with a Notepad command for visual effects. https://taskcluster-artifacts.net/O-UKxZLIQ0WEVgHnsJc4Gg/0/public/test_info/mozilla-test-fail-screenshot_xzyfty.png So whether we do no longer create a Firefox window anymore due to the changes on bug 1441869, or we fail somewhere else now and leave a zombie process behind?

(In reply to Geoff Brown [:gbrown] from comment #63) > https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=165307692 ntdll.dll!NtWaitForAlertByThreadId() Unknown ntdll.dll!RtlpWaitOnAddressWithTimeout() Unknown ntdll.dll!RtlpWaitOnCriticalSection() Unknown ntdll.dll!RtlpEnterCriticalSectionContended() Unknown ntdll.dll!RtlEnterCriticalSection() Unknown ucrtbase.dll!__acrt_update_thread_locale_data() Unknown ucrtbase.dll!_LocaleUpdate::_LocaleUpdate(struct __crt_locale_pointers * const) Unknown ucrtbase.dll!__crt_stdio_output::write_multiple_characters<class __crt_stdio_output::stream_output_adapter<wchar_t>,char>(class __crt_stdio_output::stream_output_adapter<wchar_t> const &,char,int,int * const) Unknown ucrtbase.dll!__stdio_common_vfwscanf() Unknown ucrtbase.dll!__stdio_common_vfprintf() Unknown xul.dll!fprintf(_iobuf * const _Stream, const char * const _Format, ...) Line 840 C > xul.dll!CVRPathRegistry_Public::BLoadFromFile() Line 223 C++ xul.dll!CVRPathRegistry_Public::GetPaths(std::basic_string<char,std::char_traits<char>,std::allocator<char> > * psRuntimePath, std::basic_string<char,std::char_traits<char>,std::allocator<char> > * psConfigPath, std::basic_string<char,std::char_traits<char>,std::allocator<char> > * psLogPath, const char * pchConfigPathOverride, const char * pchLogPathOverride, std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > > * pvecExternalDrivers) Line 337 C++ xul.dll!vr::VR_IsRuntimeInstalled() Line 213 C++ xul.dll!mozilla::gfx::VRSystemManagerOpenVR::Create() Line 609 C++ xul.dll!mozilla::gfx::VRManager::VRManager() Line 90 C++ xul.dll!mozilla::gfx::VRManager::ManagerInit() Line 51 C++ xul.dll!gfxPlatform::gfxPlatform() Line 530 C++ xul.dll!gfxWindowsPlatform::gfxWindowsPlatform() Line 310 C++ xul.dll!gfxPlatform::Init() Line 745 C++ xul.dll!gfxPlatform::GetPlatform() Line 538 C++ xul.dll!nsRefreshDriver::ChooseTimer() Line 1141 C++ xul.dll!nsRefreshDriver::EnsureTimerStarted(nsRefreshDriver::EnsureTimerStartedFlags aFlags) Line 1378 C++ xul.dll!nsIPresShell::DoObserveStyleFlushes() Line 9387 C++ xul.dll!nsPresContext::MediaFeatureValuesChanged(const mozilla::MediaFeatureChange & aChange) Line 303 C++ xul.dll!mozilla::PresShell::ResizeReflowIgnoreOverride(int aWidth, int aHeight, int aOldWidth, int aOldHeight, nsIPresShell::ResizeReflowOptions aOptions) Line 1942 C++ xul.dll!mozilla::PresShell::ResizeReflow(int aWidth, int aHeight, int aOldWidth, int aOldHeight, nsIPresShell::ResizeReflowOptions aOptions) Line 1919 C++ xul.dll!nsViewManager::DoSetWindowDimensions(int aWidth, int aHeight) Line 193 C++ xul.dll!nsViewManager::SetWindowDimensions(int aWidth, int aHeight, bool aDelayResize) Line 228 C++ xul.dll!nsDocumentViewer::SetBoundsWithFlags(const mozilla::gfx::IntRectTyped<mozilla::gfx::UnknownUnits> & aBounds, unsigned int aFlags) Line 2071 C++ xul.dll!nsDocShell::SetPositionAndSize(int aX, int aY, int aWidth, int aHeight, unsigned int aFlags) Line 5673 C++ xul.dll!nsWebShellWindow::WindowResized(nsIWidget * aWidget, int aWidth, int aHeight) Line 305 C++ xul.dll!nsWebShellWindow::WidgetListenerDelegate::WindowResized(nsIWidget * aWidget, int aWidth, int aHeight) Line 808 C++ xul.dll!nsWindow::OnResize(mozilla::gfx::IntRectTyped<mozilla::gfx::UnknownUnits> & aWindowRect) Line 7262 C++ xul.dll!nsWindow::OnWindowPosChanged(tagWINDOWPOS * wp) Line 6805 C++ xul.dll!nsWindow::ProcessMessage(unsigned int msg, unsigned __int64 & wParam, __int64 & lParam, __int64 * aRetValue) Line 6022 C++ xul.dll!nsWindow::WindowProcInternal(HWND__ * hWnd, unsigned int msg, unsigned __int64 wParam, __int64 lParam) Line 5015 C++ xul.dll!CallWindowProcCrashProtected(__int64(*)(HWND__ *, unsigned int, unsigned __int64, __int64) aWndProc, HWND__ * aHWnd, unsigned int aMsg, unsigned __int64 aWParam, __int64 aLParam) Line 32 C++ xul.dll!nsWindow::WindowProc(HWND__ * hWnd, unsigned int msg, unsigned __int64 wParam, __int64 lParam) Line 4968 C++ user32.dll!UserCallWinProcCheckWow() Unknown user32.dll!DispatchClientMessage() Unknown user32.dll!__fnINLPWINDOWPOS() Unknown ntdll.dll!KiUserCallbackDispatcherContinue() Unknown win32u.dll!NtUserSetWindowPos() Unknown xul.dll!nsWindow::Resize(double aWidth, double aHeight, bool aRepaint) Line 1904 C++ xul.dll!nsXULWindow::SetSize(int aCX, int aCY, bool aRepaint) Line 585 C++ xul.dll!nsXULWindow::SizeShellToWithLimit(int aDesiredWidth, int aDesiredHeight, int shellItemWidth, int shellItemHeight) Line 2294 C++ xul.dll!nsXULWindow::SizeShellTo(nsIDocShellTreeItem * aShellItem, int aCX, int aCY) Line 1882 C++ xul.dll!nsXULWindow::SetRootShellSize(int aWidth, int aHeight) Line 1862 C++ xul.dll!nsWindowWatcher::SizeOpenedWindow(nsIDocShellTreeOwner * aTreeOwner, mozIDOMWindowProxy * aParent, bool aIsCallerChrome, const SizeSpec & aSizeSpec, const mozilla::Maybe<float> & aOpenerFullZoom) Line 2491 C++ xul.dll!nsWindowWatcher::OpenWindowInternal(mozIDOMWindowProxy * aParent, const char * aUrl, const char * aName, const char * aFeatures, bool aCalledFromJS, bool aDialog, bool aNavigate, nsIArray * aArgv, bool aIsPopupSpam, bool aForceNoOpener, nsIDocShellLoadInfo * aLoadInfo, mozIDOMWindowProxy * * aResult) Line 1249 C++ xul.dll!nsWindowWatcher::OpenWindow(mozIDOMWindowProxy * aParent, const char * aUrl, const char * aName, const char * aFeatures, nsISupports * aArguments, mozIDOMWindowProxy * * aResult) Line 354 C++ xul.dll!XPTC__InvokebyIndex() Unknown xul.dll!XPCWrappedNative::CallMethod(XPCCallContext & ccx, XPCWrappedNative::CallMode mode) Line 1234 C++ xul.dll!XPC_WN_CallMethod(JSContext * cx, unsigned int argc, JS::Value * vp) Line 929 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 467 C++ xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 3085 C++ xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 417 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 489 C++ xul.dll!js::Call(JSContext * cx, JS::Handle<JS::Value> fval, JS::Handle<JS::Value> thisv, const js::AnyInvokeArgs & args, JS::MutableHandle<JS::Value> rval) Line 535 C++ xul.dll!JS_CallFunctionValue(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> fval, const JS::HandleValueArray & args, JS::MutableHandle<JS::Value> rval) Line 2969 C++ xul.dll!nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS * wrapper, unsigned short methodIndex, const nsXPTMethodInfo * info, nsXPTCMiniVariant * nativeParams) Line 1308 C++ xul.dll!nsXPCWrappedJS::CallMethod(unsigned short methodIndex, const nsXPTMethodInfo * info, nsXPTCMiniVariant * params) Line 615 C++ xul.dll!PrepareAndDispatch(nsXPTCStubBase * self, unsigned int methodIndex, unsigned __int64 * args, unsigned __int64 * gprData, double * fprData) Line 174 C++ xul.dll!SharedStub() Unknown xul.dll!NS_CreateServicesFromCategory(const char * aCategory, nsISupports * aOrigin, const char * aObserverTopic, const char16_t * aObserverData) Line 812 C++ xul.dll!nsXREDirProvider::DoStartup() Line 1025 C++ xul.dll!XREMain::XRE_mainRun() Line 4518 C++ xul.dll!XREMain::XRE_main(int argc, char * * argv, const mozilla::BootstrapConfig & aConfig) Line 4814 C++ xul.dll!XRE_main(int argc, char * * argv, const mozilla::BootstrapConfig & aConfig) Line 4906 C++ firefox.exe!do_main(int argc, char * * argv, char * * envp) Line 232 C++ firefox.exe!NS_internal_main(int argc, char * * argv, char * * envp) Line 306 C++ firefox.exe!wmain(int argc, wchar_t * * argv) Line 132 C++ firefox.exe!__scrt_common_main_seh() Line 283 C++ kernel32.dll!BaseThreadInitThunk() Unknown ntdll.dll!RtlUserThreadStart() Unknown

(In reply to Geoff Brown [:gbrown] from comment #63) > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > inbound&job_id=165230332 > https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=165175543 These 2 other failures have the exact same stack as the first one (comment 66).

(In reply to Florian Quèze [:florian] from comment #66) > (In reply to Geoff Brown [:gbrown] from comment #63) > > > https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=165307692 > > xul.dll!fprintf(_iobuf * const _Stream, const char * const _Format, ...) > Line 840 C > > xul.dll!CVRPathRegistry_Public::BLoadFromFile() Line 223 C++ This is https://searchfox.org/mozilla-central/rev/d2b4b40901c15614fad2fa34718eea428774306e/gfx/vr/openvr/src/vrpathregistry_public.cpp#223 See bug 1373279.

(In reply to Florian Quèze [:florian] from comment #68) > This is > https://searchfox.org/mozilla-central/rev/ > d2b4b40901c15614fad2fa34718eea428774306e/gfx/vr/openvr/src/ > vrpathregistry_public.cpp#223 This line is: VRLog( "Unable to read VR Path Registry from %s\n", sRegPath.c_str() );

https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=165897117&lineNumber=5110 (most recent failure in the link from comment 64) has this stack: > ntdll.dll!NtProtectVirtualMemory() Unknown ntdll.dll!LdrpChangeMrdataProtection() Unknown ntdll.dll!LdrProtectMrdata() Unknown ntdll.dll!RtlInsertInvertedFunctionTable() Unknown ntdll.dll!LdrpProcessMappedModule() Unknown ntdll.dll!LdrpMapDllWithSectionHandle() Unknown ntdll.dll!LdrpMapDllNtFileName() Unknown ntdll.dll!LdrpMapDllSearchPath() Unknown ntdll.dll!LdrpProcessWork() Unknown ntdll.dll!LdrpLoadDllInternal() Unknown ntdll.dll!LdrpLoadForwardedDll() Unknown ntdll.dll!LdrpGetDelayloadExportDll() Unknown ntdll.dll!LdrpHandleProtectedDelayload() Unknown ntdll.dll!LdrResolveDelayLoadedAPI() Unknown setupapi.dll!__delayLoadHelper2() Unknown setupapi.dll!__tailMerge_DEVOBJ_dll() Unknown setupapi.dll!SetupDiCreateDeviceInfoListExW() Unknown setupapi.dll!SetupDiGetClassDevsExW() Unknown setupapi.dll!SetupDiGetClassDevsW() Unknown xul.dll!mozilla::widget::GfxInfo::Init() Line 394 C++ xul.dll!mozilla::widget::GfxInfoConstructor(nsISupports * aOuter, const nsID & aIID, void * * aResult) Line 152 C++ xul.dll!nsComponentManagerImpl::CreateInstance(const nsID & aClass, nsISupports * aDelegate, const nsID & aIID, void * * aResult) Line 1003 C++ xul.dll!nsComponentManagerImpl::GetService(const nsID & aClass, const nsID & aIID, void * * aResult) Line 1247 C++ xul.dll!nsJSCID::GetService(JS::Handle<JS::Value> iidval, JSContext * cx, unsigned char optionalArgc, JS::MutableHandle<JS::Value> retval) Line 691 C++ xul.dll!XPTC__InvokebyIndex() Line 99 Unknown xul.dll!XPCWrappedNative::CallMethod(XPCCallContext & ccx, XPCWrappedNative::CallMode) Line 1234 C++ xul.dll!XPC_WN_CallMethod(JSContext * cx, unsigned int argc, JS::Value * vp) Line 929 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 467 C++ xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 3085 C++ xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 417 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 489 C++ xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 3085 C++ xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 417 C++ xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 489 C++ xul.dll!JS_CallFunctionValue(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> fval, const JS::HandleValueArray & args, JS::MutableHandle<JS::Value> rval) Line 2969 C++ xul.dll!nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS * wrapper, unsigned short methodIndex, const nsXPTMethodInfo * info, nsXPTCMiniVariant * nativeParams) Line 1308 C++ xul.dll!nsXPCWrappedJS::CallMethod(unsigned short methodIndex, const nsXPTMethodInfo * info, nsXPTCMiniVariant * params) Line 615 C++ xul.dll!PrepareAndDispatch(nsXPTCStubBase * self, unsigned int methodIndex, unsigned __int64 * args, unsigned __int64 * gprData, double * fprData) Line 174 C++ xul.dll!SharedStub() Line 61 Unknown xul.dll!NS_CreateServicesFromCategory(const char * aCategory, nsISupports * aOrigin, const char * aObserverTopic, const char16_t *) Line 816 C++ xul.dll!nsXREDirProvider::DoStartup() Line 1025 C++ xul.dll!XREMain::XRE_mainRun() Line 4518 C++ xul.dll!XREMain::XRE_main(int argc, char * * argv, const mozilla::BootstrapConfig & aConfig) Line 4814 C++ xul.dll!mozilla::BootstrapImpl::XRE_main(int argc, char * * argv, const mozilla::BootstrapConfig & aConfig) Line 49 C++ firefox.exe!NS_internal_main(int argc, char * * argv, char * * envp) Line 304 C++ firefox.exe!wmain(int argc, wchar_t * * argv) Line 132 C++ firefox.exe!__scrt_common_main_seh() Line 283 C++ kernel32.dll!BaseThreadInitThunk() Unknown ntdll.dll!RtlUserThreadStart() Unknown This is worryingly similar to the stack in comment 52.

https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=165893200&lineNumber=2057 is the same as comment 70.

There have been 58 failures in the last 7 days Summary: TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output (hang on start) Fails on -windows10-64 opt/pgo/debug amounting to 50 out of 58 failures as follows: -31 on windows10-64 PGO -17 on windows10-64 OPT -2 on windows10-64 DEBUG -windows10-64-nightly OPT - 2 failures -windows10-64-qr OPT - 3 failures -windows7-32-nightly OPT - 3 failures Here is a recent log life and a snippet with the failure: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=167830234&lineNumber=4729 00:44:17 INFO - Application command: Z:\task_1520987284\build\application\firefox\firefox.exe -marionette -foreground -profile c:\users\genericworker\appdata\local\temp\tmpxlb8z_.mozrunner 00:44:17 INFO - runtests.py | Application pid: 6860 00:44:17 INFO - TEST-INFO | started process GECKO(6860) 00:44:17 INFO - GECKO(6860) | 1520988257528 Marionette DEBUG Received observer notification profile-after-change 00:47:17 INFO - runtests.py | Waiting for browser... 00:50:27 INFO - Buffered messages finished 00:50:27 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output 00:50:27 INFO - 752 ERROR Force-terminating active process(es). 00:50:27 INFO - Determining child pids from psutil... 00:50:27 INFO - [] 00:50:27 INFO - Found child pids: set([]) 00:50:27 INFO - Killing process: 6860 00:50:27 INFO - TEST-INFO | started process screenshot 00:50:27 INFO - TEST-INFO | screenshot: exit 0 00:50:27 INFO - mozcrash kill_pid(): wait failed (-1) terminating pid 6860: error 5 00:50:27 INFO - psutil found pid 6860 dead 00:50:27 INFO - TEST-INFO | Main app process: exit 1 00:50:27 INFO - Buffered messages finished 00:50:27 ERROR - 753 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1 00:50:27 INFO - runtests.py | Application ran for: 0:06:10.614000 00:50:27 INFO - zombiecheck | Reading PID log: c:\users\genericworker\appdata\local\temp\tmpkswgr0pidlog 00:50:27 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/D3QPLiWRSsuSQuOxVCfe_g/artifacts/public/build/target.crashreporter-symbols.zip 00:50:30 INFO - mozcrash Copy/paste: Z:\task_1520987284\build\win32-minidump_stackwalk.exe c:\users\genericworker\appdata\local\temp\tmpxlb8z_.mozrunner\minidumps\6bacc407-1bca-44cd-9dbe-b16a905e8598.dmp c:\users\genericworker\appdata\local\temp\tmp9pckdd 00:50:36 INFO - mozcrash Saved minidump as Z:\task_1520987284\build\blobber_upload_dir\6bacc407-1bca-44cd-9dbe-b16a905e8598.dmp 00:50:36 WARNING - PROCESS-CRASH | automation.py | application crashed [None] 00:50:36 INFO - Crash dump filename: c:\users\genericworker\appdata\local\temp\tmpxlb8z_.mozrunner\minidumps\6bacc407-1bca-44cd-9dbe-b16a905e8598.dmp

this appears to be windows only- is it possibly that we need to wait a bit longer between cycling the browser? I have been investigating some reftest issues on startup with the new taskcluster worker and noticed that adding a time.sleep(10) after shutting down the browser seems to resolve almost all my issues. In fact most of the failures in bug 1444642 are the same thing as this bug- I assume the root cause is the OS doing cleanup or not releasing a file handle until some other OS level operations are done.

Maybe this is due to bug 1438009? At least I know that there is a race condition right now on Windows in reporting the exit code of the browser.

Thanks Joel. I've pushed a sleep() patch to try to see if it helps. Meanwhile, let's keep in mind that we have multiple confirmed causes of these hangs, including bug 1373279 (I just commented there), more cases of SetupDiGetClassDevsW (I need to follow-up) and bug 1440719 (waiting on needinfos).

(In reply to Geoff Brown [:gbrown] from comment #60) > (In reply to Edmund Wong (:ewong) from comment #58) > > :gbrown, is this what I"m experiencing with bug 1427969? > > You are getting the same "application timed out" message obviously, which > really just means the harness has not seen any test output for a long time > -- either the browser is hung or a test is hung. There are lots of ways to > hang. Note that most of the specific issues identified so far in this bug - > bug 1437420, bug 1419191, and comment 54 - only happen on Windows. We are > also seeing hangs on Linux, which mostly haven't been investigated yet. This is a part of the log from a seamonkey linux debug mochitest: GECKO(11732) | --DOMWINDOW == 14 (0xe06e7800) [pid = 11732] [serial = 14] [outer = (nil)] [url = about:blank] GECKO(11732) | --DOMWINDOW == 13 (0xdd52b800) [pid = 11732] [serial = 10] [outer = (nil)] [url = about:blank] GECKO(11732) | --DOMWINDOW == 12 (0xe627d800) [pid = 11732] [serial = 2] [outer = (nil)] [url = about:blank] [11707, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004002: file /builds/slave/c-cen-t-lnx-dbg/build/mozilla/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 680 runtests.py | Waiting for browser... Buffered messages finished TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output 0 ERROR Force-terminating active process(es). Determining child pids from psutil... [] Found child pids: set([]) Killing process: 11732 Failed to retrieve MOZ_UPLOAD_DIR env var psutil found pid 11732 dead runtests.py | Failed to get app exit code - running/crashed? TEST-INFO | Main app process: exit 0 runtests.py | Application ran for: 0:06:25.944597 zombiecheck | Reading PID log: /tmp/tmpk9YuVWpidlog mozcrash Copy/paste: /builds/slave/test/tools/breakpad/linux/minidump_stackwalk /tmp/tmpiXbfRY.mozrunner/minidumps/0282b304-a7b8-cc35-0d86-7b0de34acf62.dmp /builds/slave/test/build/symbols mozcrash Saved minidump as /builds/slave/test/minidumps/0282b304-a7b8-cc35-0d86-7b0de34acf62.dmp mozcrash Saved app info as /builds/slave/test/minidumps/0282b304-a7b8-cc35-0d86-7b0de34acf62.extra PROCESS-CRASH | Main app process exited normally | application crashed [@ linux-gate.so + 0x430] Crash dump filename: /tmp/tmpiXbfRY.mozrunner/minidumps/0282b304-a7b8-cc35-0d86-7b0de34acf62.dmp Operating system: Linux 0.0.0 Linux 2.6.32-220.7.1.el6.x86_64 #1 SMP Wed Mar 7 00:52:02 GMT 2012 x86_64 CPU: x86 GenuineIntel family 6 model 42 stepping 7 4 CPUs Crash reason: SIGABRT Crash address: 0x2da1 Thread 0 (crashed) 0 linux-gate.so + 0x430 eip = 0x00565430 esp = 0xffec3db4 ebp = 0xffec3dd8 ebx = 0xe5eb6420 esi = 0x00000000 edi = 0x0029bff4 eax = 0xfffffffc ecx = 0x00000003 edx = 0xffffffff efl = 0x00000296 Found by: given as instruction pointer in context 1 libglib-2.0.so.0.3400.3 + 0x53dba eip = 0x079a5dbb esp = 0xffec3de0 ebp = 0xffec3df8 Found by: previous frame's frame pointer 2 libxul.so + 0x25be5d7 eip = 0xf3d3b5d8 esp = 0xffec3e00 ebp = 0xffec3e38 Found by: previous frame's frame pointer 3 libglib-2.0.so.0.3400.3 + 0x462bb eip = 0x079982bc esp = 0xffec3e40 ebp = 0xffec3e98 Found by: previous frame's frame pointer 4 libglib-2.0.so.0.3400.3 + 0x463b2 eip = 0x079983b3 esp = 0xffec3ea0 ebp = 0xffec3ec8 Found by: previous frame's frame pointer 5 libxul.so + 0x25bc5cf eip = 0xf3d395d0 esp = 0xffec3ed0 ebp = 0xffec3ee8 Found by: previous frame's frame pointer 6 libxul.so + 0x258d56d eip = 0xf3d0a56e esp = 0xffec3ef0 ebp = 0xffec3f18 Found by: previous frame's frame pointer 7 libxul.so + 0x2590f8c eip = 0xf3d0df8d esp = 0xffec3f20 ebp = 0xffec3f58 Found by: previous frame's frame pointer 8 libxul.so + 0x81acb4 eip = 0xf1f97cb5 esp = 0xffec3f60 ebp = 0xffec44a8 Found by: previous frame's frame pointer 9 libxul.so + 0x820c88 eip = 0xf1f9dc89 esp = 0xffec44b0 ebp = 0xffec44e8 Found by: previous frame's frame pointer 10 libxul.so + 0xc13eee eip = 0xf2390eef esp = 0xffec44f0 ebp = 0xffec4538 Found by: previous frame's frame pointer 11 libxul.so + 0xbe6bb1 eip = 0xf2363bb2 esp = 0xffec4540 ebp = 0xffec4568 Found by: previous frame's frame pointer 12 libxul.so + 0xbe6bd8 eip = 0xf2363bd9 esp = 0xffec4570 ebp = 0xffec4598 Found by: previous frame's frame pointer 13 libxul.so + 0x258c242 eip = 0xf3d09243 esp = 0xffec45a0 ebp = 0xffec45c8 Found by: previous frame's frame pointer 14 libxul.so + 0x34c7673 eip = 0xf4c44674 esp = 0xffec45d0 ebp = 0xffec45e8 Found by: previous frame's frame pointer 15 libxul.so + 0x3561458 eip = 0xf4cde459 esp = 0xffec45f0 ebp = 0xffec4718 Found by: previous frame's frame pointer 16 libxul.so + 0x3561c00 eip = 0xf4cdec01 esp = 0xffec4720 ebp = 0xffec4788 Found by: previous frame's frame pointer 17 libxul.so + 0x3561f72 eip = 0xf4cdef73 esp = 0xffec4790 ebp = 0xffec48e8 Found by: previous frame's frame pointer 18 seamonkey-bin + 0x543c eip = 0x0804d43d esp = 0xffec48f0 ebp = 0xffec5928 Found by: previous frame's frame pointer 19 seamonkey-bin + 0x4d55 eip = 0x0804cd56 esp = 0xffec5930 ebp = 0xffec5978 Found by: previous frame's frame pointer 20 libc-2.12.so + 0x16ce5 eip = 0x00126ce6 esp = 0xffec5980 ebp = 0xffec5a08 Found by: previous frame's frame pointer 21 seamonkey-bin + 0x503c eip = 0x0804d03d esp = 0xffec5a10 ebp = 0x00000000 Found by: previous frame's frame pointer 22 seamonkey-bin + 0x4ca7 eip = 0x0804cca8 esp = 0xffec5a14 ebp = 0x00000000 Found by: stack scanning 23 seamonkey-bin + 0x27d9f eip = 0x0806fda0 esp = 0xffec5a20 ebp = 0x00000000 Found by: stack scanning 24 seamonkey-bin + 0x27d8f eip = 0x0806fd90 esp = 0xffec5a24 ebp = 0x00000000 Found by: stack scanning 25 ld-2.12.so + 0xf25f eip = 0x006c0260 esp = 0xffec5a28 ebp = 0x00000000 Found by: stack scanning I'm just super confused with the "PROCESS-CRASH" then "Main app process exited normally" then "application crashed". Might someone be able to clarify if bug 1427969 is an application hang issue or a process crash issue? or is it a log that shows two different bugs? Any clarifications appreciated.

(In reply to Edmund Wong (:ewong) from comment #79) > This is a part of the log from a seamonkey linux debug mochitest: > runtests.py | Waiting for browser... > Buffered messages finished > TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 > seconds with no output > 0 ERROR Force-terminating active process(es). > Killing process: 11732 > runtests.py | Failed to get app exit code - running/crashed? > TEST-INFO | Main app process: exit 0 > Crash reason: SIGABRT > Might someone be able to clarify if bug 1427969 is an application hang issue > or > a process crash issue? or is it a log that shows two different bugs? > > Any clarifications appreciated. I quoted only the parts of your log that are relevant to answer your question. It shows a timeout and then killing the process to force generating a crash dump. It's a hang issue, not a crash.

(In reply to Geoff Brown [:gbrown] from comment #78) > Thanks Joel. I've pushed a sleep() patch to try to see if it helps. Comparing: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1aec580486b41835e15e46eba69200d1d54a98d2 https://treeherder.mozilla.org/#/jobs?repo=try&revision=aabdb4e412306f72b8ef5b8e695ffc83923d1082 I see no improvement with the sleep(). I understand Joel did his own test and found a possible minor improvement. Let's continue to pursue existing leads: > Meanwhile, let's keep in mind that we have multiple confirmed causes of > these hangs, including bug 1373279 (I just commented there), more cases of > SetupDiGetClassDevsW (I need to follow-up) and bug 1440719 (waiting on > needinfos).

There have been 168 failures in the last week. It fails almost exclusively on windows10-64 / opt & pgo, with for 4 failures also for windows10-64-nightly / opt. Log file and snippet with the failure: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=170954514&lineNumber=4551 02:51:40 INFO - TEST-INFO | started process GECKO(5992) 02:51:40 INFO - GECKO(5992) | 1522291900840 Marionette DEBUG Received observer notification profile-after-change 02:54:40 INFO - runtests.py | Waiting for browser... 02:57:50 INFO - Buffered messages finished 02:57:50 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output 02:57:50 INFO - 508 ERROR Force-terminating active process(es). 02:57:50 INFO - Determining child pids from psutil... 02:57:50 INFO - [] 02:57:50 INFO - Found child pids: set([]) 02:57:50 INFO - Killing process: 5992 02:57:50 INFO - TEST-INFO | started process screenshot 02:57:50 INFO - TEST-INFO | screenshot: exit 0 02:57:51 INFO - mozcrash kill_pid(): wait failed (-1) terminating pid 5992: error 5 02:57:51 INFO - psutil found pid 5992 dead 02:57:51 INFO - TEST-INFO | Main app process: exit 1 02:57:51 INFO - Buffered messages finished 02:57:51 ERROR - 509 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1 02:57:51 INFO - runtests.py | Application ran for: 0:06:10.740000 02:57:51 INFO - zombiecheck | Reading PID log: c:\users\genericworker\appdata\local\temp\tmplkiurupidlog 02:57:51 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/EFbKvJ_DQOm8uQRowPpyEw/artifacts/public/build/target.crashreporter-symbols.zip 02:57:54 INFO - mozcrash Copy/paste: Z:\task_1522289749\build\win32-minidump_stackwalk.exe c:\users\genericworker\appdata\local\temp\tmpg8tsmh.mozrunner\minidumps\5d4c02bb-abfe-4133-8a4e-18895b2e0fc8.dmp c:\users\genericworker\appdata\local\temp\tmpmm9ug6 02:58:01 INFO - mozcrash Saved minidump as Z:\task_1522289749\build\blobber_upload_dir\5d4c02bb-abfe-4133-8a4e-18895b2e0fc8.dmp 02:58:01 WARNING - PROCESS-CRASH | automation.py | application crashed [None] Waiting for updates on: 1373279

(In reply to Geoff Brown [:gbrown] from comment #81) > Let's continue to pursue existing leads: > > > Meanwhile, let's keep in mind that we have multiple confirmed causes of > > these hangs, including bug 1373279 (I just commented there), more cases of > > SetupDiGetClassDevsW (I need to follow-up) and bug 1440719 (waiting on > > needinfos). Bug 1440719 was resolved last night. I'll be watching to see how much of a difference it makes. Still waiting for bug 1373279. I have started but still need to investigate more cases of SetupDiGetClassDevsW.

(In reply to Geoff Brown [:gbrown] from comment #90) > Bug 1440719 was resolved last night. I'll be watching to see how much of a > difference it makes. That didn't make a big difference. :( Watching for any effects from the Windows update now: https://groups.google.com/forum/#!topic/mozilla.tools.taskcluster/UHeTl1ZMEy8 Still waiting for bug 1373279. I have started but still need to investigate more cases of SetupDiGetClassDevsW.

We should check later today if the switch to generic worker on Windows (see bug 1399401) had an impact here.

Henrik, I haven't seen any more occurrences since the upgrade in bug 1399401, so things are looking good at the moment. The last one I saw was https://treeherder.mozilla.org/logviewer.html#?job_id=171656558&repo=mozilla-inbound&lineNumber=1635 which is still from generic-worker 8.3.0.

Pete, I hope you are talking about the overlapping windows in the screenshots? I agree that is no longer present. Great! I still see failures after the upgrade, maybe even at the same rate. (Still hopeful bug 1373279 will make a big difference.) https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=172128314&lineNumber=7702

(In reply to Geoff Brown [:gbrown] from comment #98) > I still see failures after the upgrade, maybe even at the same rate. (Still > hopeful bug 1373279 will make a big difference.) > > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > central&job_id=172128314&lineNumber=7702 This job still has a command window open, but no Firefox window is visible. Also sadly no Windows taskbar. Pete, do you really think that the problem is fixed?

(In reply to Henrik Skupin (:whimboo) from comment #99) > (In reply to Geoff Brown [:gbrown] from comment #98) > > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=172128314&lineNumber=7702 > > This job still has a command window open, but no Firefox window is visible. > Also sadly no Windows taskbar. Pete, do you really think that the problem is > fixed? We have code to explicitly remove the Windows taskbar which was requested in bug 1373178: Windows 10: https://github.com/mozilla-releng/OpenCloudConfig/blob/902d24ab34314b314ec98a18512cfc12ed4fcfa0/userdata/Configuration/GenericWorker/task-user-init-win10.cmd#L14-L16 Windows 7: https://github.com/mozilla-releng/OpenCloudConfig/blob/902d24ab34314b314ec98a18512cfc12ed4fcfa0/userdata/Configuration/GenericWorker/task-user-init-win7.cmd#L14-L24 Can you clarify if this is no longer required?

Note, probably the test harnesses should take care of removing taskbar, or showing it, to get this logic out of OpenCloudConfig and into gecko. It doesn't require special privileges - the steps can be run as the task user itself.

I would argue that the test harnesses should not be modifying the OS config- it should fail if the config isn't acceptable (like screen resolution, etc.) For all of the history we have assumed the machine would be setup properly and crafted our tests to work in that environment- just having a better list of what custom modifications we require goes a long way towards making our tests better.

(In reply to Pete Moore [:pmoore][:pete] from comment #100) > We have code to explicitly remove the Windows taskbar which was requested in > bug 1373178: Interesting. I nearly forgot about this bug. So if hiding the taskbar stops the notifications from popping up, it's clearly a must have for I would surely say all test suites which interact with the UI of Firefox/Thunderbird/etc. I can second that open notifications irritate tests which require focus of the Firefox window. Pete, but what about the command window, which I'm actually more interested in here?

OF reports from the last 3 weeks only show Windows 10 64bit as being affected by this hang. (In reply to Henrik Skupin (:whimboo) from comment #103) > Interesting. I nearly forgot about this bug. So if hiding the taskbar stops > the notifications from popping up, it's clearly a must have for I would > surely say all test suites which interact with the UI of > Firefox/Thunderbird/etc. I can second that open notifications irritate tests > which require focus of the Firefox window. So how would that look like if you actually want to use a one-click loaner? Is the taskbar hidden/disabled in those cases too? If yes, how could someone enable it? Shouldn't it be better to find and disable all notifications which could cause such a focus issue instead? I really miss the taskbar for inspecting per test job screenshot which tasks are currently running on that machine.

if you hover the mouse pointer over the lower edge of the screen, the task bar should pop up. the task bar isn't disabled it's just set to "auto hide". on a loaner, you can also reverse the registry setting which was used to enable auto hide. - Win 7: HKCU:SOFTWARE\Microsoft\Windows\CurrentVersion\Explorer\StuckRects2 - Win 10: HKCU:SOFTWARE\Microsoft\Windows\CurrentVersion\Explorer\StuckRects3

Ok, that sounds better, but do you also have a reply to the second part of the comment?

if you mean "Shouldn't it be better to find and disable all notifications which could cause such a focus issue instead?" then the answer is probably yes. but there are probably quite an infinite number of notifications that could pop up and steal focus. disabling them will depend on what they are and what triggered them. when we receive bugs about specific notification popups, we do generally implement some mechanism to disable them. usually a registry setting or some configuration change. if the registry setting or configuration to disable a pop-up is user specific (eg: HKEY_CURRENT_USER), then it should be disabled in tree rather than in OCC. note that the mechanism to disable the task bar is also in-tree: https://dxr.mozilla.org/mozilla-central/rev/cb2bb4a7c1c39a017aa8c24c30b62a5f48922677/testing/mozharness/configs/unittests/win_taskcluster_unittest.py#278-287

an example of disabling specific pop-ups: https://dxr.mozilla.org/mozilla-central/rev/cb2bb4a7c1c39a017aa8c24c30b62a5f48922677/testing/mozharness/configs/unittests/win_taskcluster_unittest.py#258-267

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #102) > I would argue that the test harnesses should not be modifying the OS config- > it should fail if the config isn't acceptable (like screen resolution, etc.) > For all of the history we have assumed the machine would be setup properly > and crafted our tests to work in that environment- just having a better list > of what custom modifications we require goes a long way towards making our > tests better. Joel, Luckily for us in this case, it turns out that hiding the task bar doesn't require any system setup, it is a just a user-specific change that requires no special privileges and can be run as the task user during task execution. This makes it a great candidate for the test harness, and it looks like from Rob's comment 110 that this is already the case. One issue with that though that might bite us - on Windows 7 I experienced that the HKCU:SOFTWARE\Microsoft\Windows\CurrentVersion\Explorer\StuckRects2 key didn't exist at all, so I couldn't just amend it, I actually needed to create it[1] with a bunch of default values. On Windows 10, we can just take the existing value, and flip some bits. In any case, this logic should probably be moved in-tree like we have for win10, and individual tests should be able to decide if they want to hide the task bar or not. Henrik, are you able to RDP onto a task to see the focus issue firsthand to get an idea what might be stealing focus etc? I haven't quite understood how the focus issue might relate to a hidden task bar. --- [1] https://github.com/mozilla-releng/OpenCloudConfig/blob/dbd82051b22f3cd336153d257f5509bf838652d0/userdata/Configuration/GenericWorker/task-user-init-win7.cmd#L19

I doubt that this related to focus given that there is not a Firefox window open at all since we have the new generic worker. The only thing I want to know what this command window is: https://taskcluster-artifacts.net/Ft5Tp50aTKu1tqdRT1uY1w/0/public/test_info/mozilla-test-fail-screenshot_jzic_2.png

are we able to realistically set these registry values from a restricted user? One difference is mozharness vs testharness- possibly we need to ensure that mozharness does more of the os setup/config in addition to downloading builds/artifacts and setting up the virtualenv.

(In reply to Henrik Skupin (:whimboo) from comment #112) > I doubt that this related to focus given that there is not a Firefox window > open at all since we have the new generic worker. The only thing I want to > know what this command window is: > > https://taskcluster-artifacts.net/Ft5Tp50aTKu1tqdRT1uY1w/0/public/test_info/ > mozilla-test-fail-screenshot_jzic_2.png Henrik, if you can get the test to keep running (so the cmd window doesn't get closed), you should be able to discover what process created that window with the Process Explorer / Process Monitor or similar tools we have on the workers. See https://wiki.mozilla.org/ReleaseEngineering/How_To/Self_Provision_a_TaskCluster_Windows_Instance#For_generic-worker_10.5.0_onwards for getting a loaner.

(In reply to Pete Moore [:pmoore][:pete] from comment #114) > Henrik, if you can get the test to keep running (so the cmd window doesn't > get closed), you should be able to discover what process created that window > with the Process Explorer / Process Monitor or similar tools we have on the > workers. The only command window I see while the tests are running is the one which seems to get used by the harness, and is open all the time while the tests are running. Could we make it happen that this window is minimized? Pete, once the tests have finished, how can I start the tests again? The docs are missing that and I don't want to create a new one click loaner all the time.

Geoff, I don't see that we have browser log output available during startup which might help us to better investigate the problem. So something I would consider is to enable the tracing logs for Marionette, which means that only the very first run will show the output but no test afterward. Given that the hang happens during the first start, this seems to be a good trade off. Shall we enable it?

(In reply to Henrik Skupin (:whimboo) from comment #120) > Given that > the hang happens during the first start, this seems to be a good trade off. > Shall we enable it? Are you saying this about a specific failure log? I just looked at a few failure logs and it seems the hang is during startup when restarting the browser for another folder of tests, after having already ran a random number of tests from other folders.

You are correct, sorry. In that case we will have it indeed for each and every start of Firefox when Marionette is enabled. But we can stop the trace log right after the extension gets installed. Maybe we could just trigger a try build with that and hope we run into such a situation.

I'm confused: Haven't we already enabled Marionette trace logs, at least for mochitests? https://treeherder.mozilla.org/logviewer.html#?job_id=175000549&repo=mozilla-inbound&lineNumber=1902-1916 10:24:50 INFO - Application command: Z:\task_1524390763\build\application\firefox\firefox.exe -marionette -foreground -profile c:\users\task_1524390763\appdata\local\temp\tmpqpvsc8.mozrunner 10:24:50 INFO - runtests.py | Application pid: 2960 10:24:50 INFO - TEST-INFO | started process GECKO(2960) 10:24:51 INFO - GECKO(2960) | 1524392691355 Marionette DEBUG Received observer notification profile-after-change 10:24:51 INFO - GECKO(2960) | 1524392691471 Marionette DEBUG Received observer notification command-line-startup 10:24:51 INFO - GECKO(2960) | 1524392691471 Marionette DEBUG Received observer notification nsPref:changed 10:24:52 INFO - GECKO(2960) | 1524392692403 Marionette DEBUG Received observer notification sessionstore-windows-restored 10:24:52 INFO - GECKO(2960) | 1524392692632 Marionette DEBUG New connections are accepted 10:24:52 INFO - GECKO(2960) | 1524392692633 Marionette INFO Listening on port 2828 10:24:52 INFO - GECKO(2960) | 1524392692695 Marionette DEBUG Accepted connection 0 from 127.0.0.1:49991 10:24:52 INFO - GECKO(2960) | 1524392692708 Marionette DEBUG Closed connection 0 10:24:52 INFO - GECKO(2960) | 1524392692709 Marionette DEBUG Accepted connection 1 from 127.0.0.1:49992 10:24:52 INFO - GECKO(2960) | 1524392692732 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] 10:24:52 INFO - GECKO(2960) | 1524392692759 Marionette DEBUG Register listener.js for window 4294967297 10:24:52 INFO - GECKO(2960) | 1524392692768 Marionette TRACE 1 <- [1,1,null,{"sessionId":"0e264648-1daf-45bb-a01b-c32af3d5625e","capabilities":{"browserName":"firefox","browserVersion":"61.0a ... 4390763\\AppData\\Local\\Temp\\tmpqpvsc8.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] We don't see that output for the 370 second timeout case because Marionette is inactive, waiting for the browser to start - right? If there is more logging that can be enabled, I'd do that on try, at least initially: It should not be too hard to reproduce this on try. I'm waiting for / hoping for action on bug 1373279.

(In reply to Henrik Skupin (:whimboo) from comment #117) > (In reply to Pete Moore [:pmoore][:pete] from comment #114) > > Henrik, if you can get the test to keep running (so the cmd window doesn't > > get closed), you should be able to discover what process created that window > > with the Process Explorer / Process Monitor or similar tools we have on the > > workers. > > The only command window I see while the tests are running is the one which > seems to get used by the harness, and is open all the time while the tests > are running. Could we make it happen that this window is minimized? > > Pete, once the tests have finished, how can I start the tests again? The > docs are missing that and I don't want to create a new one click loaner all > the time. There is a script for each command in the task payload. They are named like this: Z:\task_XXXXXXX\command_000000_wrapper.bat Z:\task_XXXXXXX\command_000001_wrapper.bat Z:\task_XXXXXXX\command_000002_wrapper.bat .... You should just be able to run them. Sorry for delayed reply!

Note: I've also updated the docs: https://wiki.mozilla.org/ReleaseEngineering/How_To/Self_Provision_a_TaskCluster_Windows_Instance#Rerunning_tasks_after_they_have_completed

(In reply to Geoff Brown [:gbrown] from comment #124) > I'm confused: Haven't we already enabled Marionette trace logs, at least for > mochitests? Oh, the problem might be then that we don't see anything because Marionette isn't handling the Firefox instance but the mochitest runner is doing that. I'm not sure where the difference actually is and what exactly enables the tracing output in the former case before Marionette is enabled. Andreas, what do I miss? > We don't see that output for the 370 second timeout case because Marionette > is inactive, waiting for the browser to start - right? In parts of the cases we fail before Marionette gets enabled. In others we fail later most likely in the mochitest extension which should start the tests but fails somehow. > I'm waiting for / hoping for action on bug 1373279. Not sure if that will help given that we see this warning in a lot of places also for passing tests. But who knows...

Hm, maybe this is `browser.dom.window.dump.enabled` which is missing in this case? Or does the Firefox log output goes somewhere else.

(In reply to Henrik Skupin (:whimboo) from comment #128) > (In reply to Geoff Brown [:gbrown] from comment #124) > > I'm confused: Haven't we already enabled Marionette trace logs, at least for > > mochitests? > > Oh, the problem might be then that we don't see anything because Marionette > isn't handling the Firefox instance but the mochitest runner is doing that. > I'm not sure where the difference actually is and what exactly enables the > tracing output in the former case before Marionette is enabled. Andreas, > what do I miss? I’m confused too. The log pasted in https://bugzilla.mozilla.org/show_bug.cgi?id=1414495#c124 appears to contain trace-level logging entries?

testing locally on win10, I ran into a similar problem- here I found we didn't cleanup properly (I assume ssltunnel was a zombie process as I couldn't remove that file from my objdir nor did I see it in task manager). Could it be that when taskcluster hits a timeout (aborted task) we don't cleanup everything properly. I see the failures here are win10 and mochitest specific- could we somehow determine which jobs ran previously? could we enforce a reboot on a device when taskcluster aborts a task?

Joel, sorry, I'm not sure I understand what happened to you locally: Was it a 370 second no output timeout? Did it happen on browser startup? Was "runtests.py | Waiting for browser..." logged immediately before the timeout? I checked several recent logs and found the associated system-info.logs show they were freshly rebooted. Of course, there are multiple browser starts in each task, and many (but not all) of the failures in this bug happen on the 2nd or later browser start, so there is a possibility of an interaction with processes launched previously...but I have no evidence for that.

Time for a new summary: This bug tracks intermittent test failures in which the test harness times out after 370 seconds waiting for firefox to start. In recent months, the great majority of known failures are on Windows 10 opt and pgo on various flavors of mochitest. Instead of seeing: 19:20:31 INFO - TEST-INFO | started process GECKO(672) 19:20:31 INFO - GECKO(672) | 1525288831693 Marionette DEBUG Received observer notification profile-after-change 19:20:31 INFO - GECKO(672) | 1525288831788 Marionette DEBUG Received observer notification command-line-startup 19:20:31 INFO - GECKO(672) | 1525288831788 Marionette DEBUG Received observer notification nsPref:changed 19:20:32 INFO - GECKO(672) | 1525288832579 Marionette DEBUG Received observer notification sessionstore-windows-restored ... The failure logs have: 19:20:41 INFO - TEST-INFO | started process GECKO(4768) 19:20:42 INFO - GECKO(4768) | 1525288842452 Marionette DEBUG Received observer notification profile-after-change 19:23:42 INFO - runtests.py | Waiting for browser... 19:26:52 INFO - Buffered messages finished 19:26:52 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output Note that Marionette does not receive command-line-startup, so never completes its startup. Not receiving command-line-startup is consistent with a hang early in gecko startup. Screenshots taken at the time of the timeout show only a cmd.exe window -- no firefox window -- possibly consistent with a startup hang prior to window initialization. After the timeout, the harness kills the browser and almost always collects a minidump, but the logged crash report is nonsensical. However, loading the minidump in Visual Studio produces a sensible stack, as seen in comments like comment 66. Comments 66 to 69 suggest a hang in CVRPathRegistry_Public::BLoadFromFile: we hope that bug 1373279 will address that, but there's been no recent activity there. Comments 70 and 71 suggest a hang in SetupDiGetClassDevsW; that should also be investigated further. Want to help? There are lots of failure logs here, each with an associated .dmp file. Please load some .dmp files in Visual Studio and document the stacks found: Is it in BLoadFromFile? SetupDiGetClassDevsW? Somewhere else??

Something I want to note here... Even those failures exist for a long time we ONLY see them for builds on any development branch but never on beta, release, or esr. So I wonder if a feature which is only enabled in Nightly causes us to fail here. It would be good to know which feature can affect the Firefox startup process, and given our former analysis this might be a GFX related feature? Milan, mind telling us which GFX features are only enabled by default for Nightly on Windows 10?

Some possibilities: We build (but not enable) WebRender. Perhaps the presence of the WebRender code, and maybe some parts that are still run? We do some checkerboarding telemetry by default. We restart the GPU process a few extra times, if it crashes or fails.

(In reply to Milan Sreckovic [:milan] (needinfo for best results) from comment #144) > Some possibilities: > We build (but not enable) WebRender. Perhaps the presence of the WebRender > code, and maybe some parts that are still run? I would say it's unlikely that building webrender would cause this sort of startup hang. But it should be easy enough to check, we can do a try push with --enable-webrender=false in the mozconfig and see if the problem still occurs. > We do some checkerboarding telemetry by default. The telemetry is recorded on all channels, but there is some extra recording of state that happens on Nightly. However that should only come into play after APZ is initialized, which in turn should only be after the gfx startup is done. The recording can be disabled by setting apz.record_checkerboarding to false. > We restart the GPU process a few extra times, if it crashes or fails. Of the three options this seems the most plausible to me, but I don't have any concrete idea of why GPU process restarting might trigger the hang. Again though, it should be easy enough to check as we just need to change the value of the layers.gpu-process.max_restarts pref - it's 1 on release but set to 3 in all.js inside an ifdef for NIGHTLY. I would suggest doing a try push with all three of these changes and retrigger to see if we still have the problem. If the problem is resolved we can bisect the changes to see which one is causing it and go from there. Otherwise we'll have to look elsewhere.

(In reply to Henrik Skupin (:whimboo) from comment #143) > Something I want to note here... Even those failures exist for a long time > we ONLY see them for builds on any development branch but never on beta, > release, or esr. Another factor to consider: We don't seem to run mochitests on "Windows 10 x64 opt" or "Windows 10 x64 pgo" on beta/release/esr ... only on "Windows 10 x64 Nightly opt".

Btw the fix for "Unable to read VR Path Registry ..." didn't had an effect here.

I am disappointed that startup hangs continue with about the same frequency after the fix for bug 1373279. However, there is good news: in about 30% of the cases, we are now getting a more sensible stack reported in the crash report -- bug 1461353.

Over the last 7 days there are 127 failures. These happen on windows10-64, windows10-64-nightly Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=179573601&repo=autoland&lineNumber=5350 00:28:15 INFO - runtests.py | Waiting for browser... 00:31:26 INFO - Buffered messages finished 00:31:26 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output 00:31:26 INFO - 572 ERROR Force-terminating active process(es). 00:31:26 INFO - Determining child pids from psutil... 00:31:26 INFO - [] 00:31:26 INFO - Found child pids: set([]) 00:31:26 INFO - Killing process: 6404 00:31:26 INFO - TEST-INFO | started process screenshot 00:31:26 INFO - TEST-INFO | screenshot: exit 0 00:31:26 INFO - mozcrash kill_pid(): wait failed (-1) terminating pid 6404: error 5 00:31:26 INFO - psutil found pid 6404 dead 00:31:26 INFO - TEST-INFO | Main app process: exit 1 00:31:26 INFO - Buffered messages finished 00:31:26 ERROR - 573 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1 00:31:26 INFO - runtests.py | Application ran for: 0:06:10.768000 00:31:26 INFO - zombiecheck | Reading PID log: c:\users\task_1526947977\appdata\local\temp\tmp1k35cwpidlog 00:31:26 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/IBjTCj0cRS2e_mboBfcWeg/artifacts/public/build/target.crashreporter-symbols.zip 00:31:30 INFO - mozcrash Copy/paste: Z:\task_1526947977\build\win32-minidump_stackwalk.exe c:\users\task_1526947977\appdata\local\temp\tmpipgryd.mozrunner\minidumps\ecfcc165-a3ff-4e79-9dbf-40f49d88879c.dmp c:\users\task_1526947977\appdata\local\temp\tmpcejvwg 00:31:35 INFO - mozcrash Saved minidump as Z:\task_1526947977\build\blobber_upload_dir\ecfcc165-a3ff-4e79-9dbf-40f49d88879c.dmp 00:31:35 WARNING - PROCESS-CRASH | automation.py | application crashed [None]

See comment 139, comment 154.

Update: There have been 44 failures in the last week. All the failures occur on the windows10-64 platform on all the build types except debug. Recent log file: https://treeherder.mozilla.org/logviewer.html#?job_id=181826361&repo=autoland&lineNumber=5208

one random theory worth considering. While working on cleaning up test-verify, I noticed many failures. before: https://treeherder.mozilla.org/#/jobs?repo=try&revision=25f98606954d6a785becca862c2d056abea8e8b7&filter-searchStr=windows%20x64%20test-verify%20opt after skip-if=verify on many tests: https://treeherder.mozilla.org/#/jobs?repo=try&revision=183e10a5f6103373ae2d098e0a4e24add9413e86&filter-searchStr=windows%20x64%20test-verify%20opt what I noticed is we are running ~2000 jobs on each of the pushes. the before has many more of these startup failures than the after. Some initial questions about this problem in general: 1) are the timeouts on the first time we launch the browser or a secondary one (could we analyze many of the failures on integration branches) 2) is it possible that certain tests are affecting the state of the browser/OS which causes the startup failure on subsequent launches 3) not sure how to do this programatically- possibly some simply log parsing trick we could use?

(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #178) > 1) are the timeouts on the first time we launch the browser or a secondary > one (could we analyze many of the failures on integration branches) Both: The normal (not test-verify) failures reported here are often on a secondary launch of the browser, but it is not hard to find cases where the startup hang occurs on the very first start of the browser: https://treeherder.mozilla.org/logviewer.html#?job_id=183091128&repo=autoland&lineNumber=1177

(In reply to Geoff Brown [:gbrown] from comment #154) > I am disappointed that startup hangs continue with about the same frequency > after the fix for bug 1373279. However, there is good news: in about 30% of > the cases, we are now getting a more sensible stack reported in the crash > report -- bug 1461353. Crash reports consistent with bug 1461353 continue and may be the most frequent failure mode: https://treeherder.mozilla.org/logviewer.html#?job_id=183053190&repo=mozilla-inbound&lineNumber=1822 https://treeherder.mozilla.org/logviewer.html#?job_id=183012047&repo=mozilla-inbound&lineNumber=12237 https://treeherder.mozilla.org/logviewer.html#?job_id=183003540&repo=autoland&lineNumber=2298

Recent discussion in bug 1461353 suggests the Windows 10 hangs are related to the BackgroundHangMonitor. Comparing https://treeherder.mozilla.org/#/jobs?repo=try&revision=6fbd7b2164e560948314fcc7cdd0b37d2925ddb1 https://treeherder.mozilla.org/#/jobs?repo=try&revision=255a4bf742be01631249345592fa5a8de9367de5 seems to confirm this: I cannot reproduce the startup hang when the BackgroundHangMonitor is disabled. It's great to see progress in bug 1461353 -- waiting to see how that works out...

Geoff, lately I see lots of those hangs also reported on Linux. That happens here on this bug directly, but also for Marionette restart tests. Maybe something changed for Linux in the last weeks?

Update: In the last 7 days, there have been 157 failures. Occurrences per platform and build type: - 122 failures on windows10-64 / pgo, opt - 26 failures on linux64 / asan, opt, pgo, debug - 4 failures on linux32 / opt, debug - 2 failures on windows10-64-qr / opt - 2 failures on windows10-64-nightly / opt - 1 failure on linux64-qr / debug Here is a recent relevant log file and a snippet with the failure: https://treeherder.mozilla.org/logviewer.html#?job_id=186098012&repo=autoland&lineNumber=3466 101:42:57 INFO - runtests.py | Server pid: 8032 01:42:57 INFO - runtests.py | Websocket server pid: 2584 01:42:57 INFO - runtests.py | websocket/process bridge pid: 6196 01:42:57 INFO - runtests.py | SSL tunnel pid: 5576 01:42:57 INFO - runtests.py | Running with e10s: True 01:42:57 INFO - runtests.py | Running tests: start. 01:42:57 INFO - Application command: Z:\task_1530580643\build\application\firefox\firefox.exe -marionette -foreground -profile c:\users\task_1530580643\appdata\local\temp\tmpr9km34.mozrunner 01:42:57 INFO - runtests.py | Application pid: 7268 01:42:57 INFO - TEST-INFO | started process GECKO(7268) 01:42:58 INFO - GECKO(7268) | 1530582178454 Marionette DEBUG Received observer notification profile-after-change 01:45:58 INFO - runtests.py | Waiting for browser... 01:49:08 INFO - Buffered messages finished 01:49:08 WARNING - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output 01:49:08 INFO - 961 ERROR Force-terminating active process(es). 01:49:08 INFO - Determining child pids from psutil... 01:49:08 INFO - [] 01:49:08 INFO - Found child pids: set([]) 01:49:08 INFO - Killing process: 7268 01:49:08 INFO - TEST-INFO | started process screenshot 01:49:08 INFO - TEST-INFO | screenshot: exit 0 01:49:08 INFO - mozcrash kill_pid(): wait failed (-1) terminating pid 7268: error 5 01:49:08 INFO - psutil found pid 7268 dead 01:49:08 INFO - TEST-INFO | Main app process: exit 1 01:49:08 INFO - Buffered messages finished 01:49:08 ERROR - 962 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1 01:49:08 INFO - runtests.py | Application ran for: 0:06:10.819000e