Filed by: aiakab [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=164587615&repo=autoland https://queue.taskcluster.net/v1/task/J1E7Ld6yRkyiJP1o3Ks-0g/runs/0/artifacts/public/logs/live_backing.log https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/J1E7Ld6yRkyiJP1o3Ks-0g/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

Since this bug was created, 5 days ago, there have been 30 failures. Starting with 2nd March we have an increase: https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1441580 The failures are on windows10-64 and windows10-64-ccov platform. Affected build types: debug and opt. An example of a recent log file: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=165835047&lineNumber=1776 And the relevant part of the log: 11:40:31 INFO - --DOMWINDOW == 4 (00000124F5006400) [pid = 3416] [serial = 1] [outer = 0000000000000000] [url = chrome://gfxsanity/content/sanitytest.html] 11:40:34 INFO - --DOMWINDOW == 3 (00000124F528D800) [pid = 3416] [serial = 3] [outer = 0000000000000000] [url = chrome://gfxsanity/content/sanitytest.html] 11:40:36 INFO - --DOMWINDOW == 2 (000002178D136800) [pid = 4092] [serial = 2] [outer = 0000000000000000] [url = about:blank] 11:41:33 INFO - --DOMWINDOW == 2 (00000124F507C000) [pid = 3416] [serial = 5] [outer = 0000000000000000] [url = about:blank] 11:47:43 INFO - REFTEST ERROR | None | application timed out after 370 seconds with no output 11:47:43 INFO - REFTEST ERROR | Force-terminating active process(es). 11:47:43 INFO - REFTEST TEST-INFO | started process screenshot 11:47:45 INFO - REFTEST TEST-INFO | screenshot: exit 0 11:47:45 INFO - TEST-INFO | crashinject: exit 0 11:47:46 WARNING - TEST-UNEXPECTED-FAIL | None | application terminated with exit code 1 11:47:46 INFO - REFTEST INFO | Copy/paste: Z:\task_1520163497\build\win32-minidump_stackwalk.exe c:\users\genericworker\appdata\local\temp\tmpnkgmhq.mozrunner\minidumps\aac2d0b6-624f-4b8c-bb2a-5f6a37d76edf.dmp Z:\task_1520163497\build\symbols 11:47:56 INFO - REFTEST INFO | Saved minidump as Z:\task_1520163497\build\blobber_upload_dir\aac2d0b6-624f-4b8c-bb2a-5f6a37d76edf.dmp 11:47:56 INFO - REFTEST INFO | Saved app info as Z:\task_1520163497\build\blobber_upload_dir\aac2d0b6-624f-4b8c-bb2a-5f6a37d76edf.extra 11:47:56 ERROR - REFTEST PROCESS-CRASH | pid: None | application crashed [@ CrashingThread(void *)] 11:47:56 INFO - Crash dump filename: c:\users\genericworker\appdata\local\temp\tmpnkgmhq.mozrunner\minidumps\aac2d0b6-624f-4b8c-bb2a-5f6a37d76edf.dmp 11:47:56 INFO - Operating system: Windows NT 11:47:56 INFO - 10.0.15063 11:47:56 INFO - CPU: amd64 11:47:56 INFO - family 6 model 63 stepping 2 11:47:56 INFO - 8 CPUs 11:47:56 INFO - GPU: UNKNOWN 11:47:56 INFO - Crash reason: EXCEPTION_ACCESS_VIOLATION_WRITE 11:47:56 INFO - Crash address: 0x0 11:47:56 INFO - Process uptime: 458 seconds 11:47:56 INFO - Thread 53 (crashed) 11:47:56 INFO - 0 crashinjectdll.dll!CrashingThread(void *) [crashinjectdll.cpp:21f7f94a2c18dc8010ac2f300a36cc4ddd16081c : 17 + 0x0] 11:47:56 INFO - rax = 0x00007fffc3991000 rdx = 0x00007fffc3991000 11:47:56 INFO - rcx = 0x0000000000000000 rbx = 0x0000000000000000 11:47:56 INFO - rsi = 0x00007fffc3991000 rdi = 0x00007fffcae9fab0 11:47:56 INFO - rbp = 0x0000000000000000 rsp = 0x0000002f03dff8a8 11:47:56 INFO - r8 = 0x0000000000000000 r9 = 0x0000000000000000 11:47:56 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000246 11:47:56 INFO - r12 = 0x0000000000000000 r13 = 0x0000000000000000 11:47:56 INFO - r14 = 0x0000000000000000 r15 = 0x0000000000000000 11:47:56 INFO - rip = 0x00007fffc3991018 11:47:56 INFO - Found by: given as instruction pointer in context 11:47:56 INFO - 1 kernel32.dll!LdrpLoadResourceFromAlternativeModule + 0x27c 11:47:56 INFO - rsp = 0x0000002f03dff8b0 rip = 0x00007fffe9782774 11:47:56 INFO - Found by: stack scanning :ahal could you please take a look?

Failure classification for this issue specifies: Logs not fully parsed, please wait However, the logs are parsed: https://treeherder.mozilla.org/logviewer.html#?job_id=165741192&repo=autoland&lineNumber=1638 https://taskcluster-artifacts.net/YIpGfHBmQEyFJPuC2N9cVg/0/public/logs/live_backing.log

:gbrown, do you think this is related to the other reftest startup timeout issues?

Most of the recent jsreftest failures here appear to be browser startup hangs, with logs similar to those seen in bug 1414495 (for mochitest) and bug 1418575 (for reftests, but recently closed since we stopped getting failures reported there -- maybe because they shifted here?). So they are related in that way. In terms of root cause, it's harder to say, since we've found several causes of browser startup hangs, none of which leaves a clear signature. It is possibly worth noting that I see "Unable to read VR Path Registry" in a lot of these logs; see https://bugzilla.mozilla.org/show_bug.cgi?id=1414495#c68.

Please note that in a lot or maybe even all cases we have again multiple processes of Firefox running as it looks like: https://taskcluster-artifacts.net/b6BKzNgaRVunvlp8FtIWEA/0/public/test_info/mozilla-test-fail-screenshot_ux4v9o.png

Those all look like content crashes. Geoff, I assume we need bug 1440719 first before you want to add the crash environment variable for reftests too? (In reply to Geoff Brown [:gbrown] from comment #5) > Most of the recent jsreftest failures here appear to be browser startup > hangs, with logs similar to those seen in bug 1414495 (for mochitest) and Actually Marionette is initialized and installed the required extensions. The hang as I think caused by a content crash happens afterward. Having the env variable set we might get better information where it crashes.

Yes, bug 1440719 will set MOZ_CRASHREPORTER_SHUTDOWN for mochitests and reftests; browser-chrome mochitest might be handled in a separate bug. I hope to work on that more this week. How can you tell these are content crashes?

There are lots of pipe errors from the ipc component which from experience with content crashes in Marionette tests could indicate that there are content crashes happening. https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=167201353&lineNumber=1708-1715 Given that the harness hangs the reftest tab should have been crashed. Sadly it's not visible because the command window overlays Firefox: https://taskcluster-artifacts.net/AwGg84RrQvGEC7eI9yLY8A/0/public/test_info/mozilla-test-fail-screenshot_tur6yn.png

This was filed around when reftest run-by-manifest was landed. If there was a previously existing startup crash/hang, then it would make sense that it is now a lot more frequent (since we start Firefox N times per job instead of 1). So my guess is this could be a previously existing issue that is now magnified by run-by-manifest. Interestingly, it looks like all jobs in orange factor are either crashtest or jsreftest jobs. I wonder if there are configuration differences that could explain this.

win10 reftests run on buildbot (ix hardware + buildbot worker), crashtest and jsreftest are on VM machines and use a taskcluster worker.

There are 34 failures in the past 7 days. Platforms: - windows10-64 opt, debug and pgo - windows10-64-ccov debug - android-4-3-armv7-api16 debug Recent log failure: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=170601870&lineNumber=1635 Relevant part of the log: 16:51:16 INFO - REFTEST ERROR | None | application timed out after 370 seconds with no output 16:51:16 INFO - REFTEST ERROR | Force-terminating active process(es). 16:51:16 INFO - REFTEST TEST-INFO | started process screenshot 16:51:16 INFO - REFTEST TEST-INFO | screenshot: exit 0 16:51:16 INFO - TEST-INFO | crashinject: exit 0 17:07:56 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['Z:\\task_1522168990\\build\\venv\\Scripts\\python', '-u', 'Z:\\task_1522168990\\build\\tests\\reftest\\runreftest.py', '--total-chunks', '2', '--this-chunk', '1', '--appname=Z:\\task_1522168990\\build\\application\\firefox\\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/JtWmTP07Rwy2zJwexL6gZA/artifacts/public/build/target.crashreporter-symbols.zip', '--log-raw=Z:\\task_1522168990\\build\\blobber_upload_dir\\jsreftest_raw.log', '--log-errorsummary=Z:\\task_1522168990\\build\\blobber_upload_dir\\jsreftest_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--extra-profile-file=tests/jsreftest/tests/user.js', '--suite=jstestbrowser', '--', 'tests/jsreftest/tests/jstests.list'] [taskcluster 2018-03-27T17:43:13.169Z] Exit Code: 0 [taskcluster 2018-03-27T17:43:13.169Z] User Time: 15.625ms [taskcluster 2018-03-27T17:43:13.169Z] Kernel Time: 0s [taskcluster 2018-03-27T17:43:13.169Z] Wall Time: 59m57.205979s [taskcluster 2018-03-27T17:43:13.169Z] Peak Memory: 5918720 [taskcluster 2018-03-27T17:43:13.169Z] Result: IDLENESS_LIMIT_EXCEEDED [taskcluster 2018-03-27T17:43:13.169Z] === Task Finished === [taskcluster 2018-03-27T17:43:13.169Z] Task Duration: 59m57.210049s :ahal Can you please take a look here?

Reftest analyzer: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/egyAGMj3Sj2oLpbY06-1NQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

Most of these likely have a common cause with bug 1414495, although the subsequent mozprocess timeout and the lack of crash report is odd and unfortunate.

I filed bug 1449576 to figure out why were not getting crash stacks on timeout anymore. I'll poke into that a bit to see if I can figure out why. I don't have any ideas for this bug though :/

In each of the cases the Firefox window is still in the background and a command line window is pushed to foreground. I know that for a couple of tests we wait until the Firefox window has focus. So maybe this hits us here? https://queue.taskcluster.net/v1/task/I3ADGO9cToyq9fNgHCNI2g/runs/0/artifacts/public/test_info/mozilla-test-fail-screenshot_l5vwzt.png Pete or Rob, can we run the Notepad command in a minimized command line window?

Yes. The command to create the cmd window is created by the generic worker install command so a patch to gw to add a /B (background process) flag should mean that the cmd window won't show up in the test UI. I'll let Pete weigh in because I suspect this is already patched on the 10.x gw installs which are due to roll out any day now.

Thanks Rob. Yes indeed, we have a major Windows upgrade going on today - let's see if this is still needed after the upgrade. Details: https://groups.google.com/forum/#!topic/mozilla.tools.taskcluster/UHeTl1ZMEy8

(In reply to Henrik Skupin (:whimboo) from comment #20) > In each of the cases the Firefox window is still in the background and a > command line window is pushed to foreground. I know that for a couple of > tests we wait until the Firefox window has focus. So maybe this hits us here? I think it may make sense that the Firefox window is not displayed: The hangs we have identified from crash reports in bug 1414495 are fairly early in Firefox startup -- perhaps before we have tried to display a window?

No, the Firefox windows are visible but hidden by the command window. So there is no way to see what is actually been displayed. See the screenshot from comment 20.

Something interesting happened here on a ccov job: https://treeherder.mozilla.org/logviewer.html#?job_id=172327879&repo=mozilla-central&lineNumber=1795 Why are all those applications and windows open which cause Firefox to be in the background, and maybe the harness to hang? https://queue.taskcluster.net/v1/task/T9kkWXaDRkaH8SrF6XlTug/runs/0/artifacts/public/test_info/mozilla-test-fail-screenshot_nqpwq6.png Good news is at least that since we are on the new generic worker the amount of failures has been drastically dropped. So I assume that the problem here was the shown command window which executed the Notepad command.

this screenshot appears to be from a hardware instance (T-W1064-MS-021). on hardware the generic worker version is still 8. hardware was not included in the upgrade to 10. i suspect someone was on the instance doing some debugging work because the event viewer shown in the screenshot is unlikely to have been opened by something in automation. much more likely to be a human being doing some debug work.

Greg, can you please check comment 26 and comment 27? Did you operate on that machine while it was running the ccov tests?

I am pretty sure neither Greg or Marco have had a loaner, this could have been stuck around since setting up the hardware, or maybe there was an odd bit of hardware someone from relops was looking into. The standard method for putting a loaner back into production is at the very least to reboot it, I thought it was to reimage the machine. I agree that this looks fully resolved with the new worker- I imagine there will always be an odd case where the specific hardware machine is quirky or there is human error intervening.

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #29) > been stuck around since setting up the hardware, or maybe there was an odd > bit of hardware someone from relops was looking into. The standard method > for putting a loaner back into production is at the very least to reboot it, > I thought it was to reimage the machine. Should someone check that machine to be sure that all is back to normal? I doubt it will be re-imaged automatically, or does it? > I agree that this looks fully resolved with the new worker- I imagine there > will always be an odd case where the specific hardware machine is quirky or > there is human error intervening. Ok, then lets close this bug as fixed by the generic worker upgrade. Thanks a ton Pete! \o/

Please note that I can perfectly replicate this problem with a Unicode character in the profile string. See the following try push: https://treeherder.mozilla.org/logviewer.html#?job_id=172807698&repo=try&lineNumber=1824 It hangs in the same line as usual (directly after Marionette installed the extensions): > [task 2018-04-10T05:47:41.148Z] 05:47:41 INFO - 1523339261141 Marionette TRACE 1 <- [1,2,null,{"value":"reftest@mozilla.org"}] > [task 2018-04-10T05:47:41.399Z] 05:47:41 INFO - 1523339261393 Marionette TRACE 1 -> [0,3,"deleteSession",{}] > [task 2018-04-10T05:47:41.400Z] 05:47:41 INFO - 1523339261395 Marionette TRACE 1 <- [1,3,null,{}] > [task 2018-04-10T05:47:41.416Z] 05:47:41 INFO - 1523339261412 Marionette DEBUG Closed connection 1 > [task 2018-04-10T05:53:51.729Z] 05:53:51 ERROR - REFTEST ERROR | None | application timed out after 370 seconds with no output I will track this separately via bug 918097 because that's a new feature which might break certain code in reftest. But it may be related.

Well, I think that we should reopen for now given that I found some cases which are not only related to Unicode characters in the profile path, but wrong Promise handling which cause a hang in reftests. I will file as separate bug in a moment.

Geoff, I have another case (from yesterday) for you here: https://treeherder.mozilla.org/logviewer.html#?job_id=172985412&repo=autoland&lineNumber=7372-7374 As the screenshot shows there is a problem with loading XPCOM: https://taskcluster-artifacts.net/AiJoPQdSRqakMIHuhLUSLQ/0/public/test_info/mozilla-test-fail-screenshot_n1mdgg.png Looks like the reftest harness waits forever and always assumes that Marionette will install the reftest extension, and executes the tests. Maybe we can catch this with another kind of timeout?

Thanks - I haven't seen that screenshot before. I think the 370 s no-output application timeout is appropriate. I'm not sure what else we can do in the harness. I suppose GetBootstrap() failed here: https://dxr.mozilla.org/mozilla-central/rev/0528a414c2a86dad0623779abde5301d37337934/browser/app/nsBrowserApp.cpp#243-247 And it looks like that Output() call pops up a message box in Windows/debug builds: https://dxr.mozilla.org/mozilla-central/rev/0528a414c2a86dad0623779abde5301d37337934/browser/app/nsBrowserApp.cpp#120-127 Maybe using a message box here is not a good idea? In the log I also notice: 23:39:32 INFO - [Parent 4988, Main Thread] WARNING: NS_ENSURE_TRUE(mHiddenWindow) failed: file z:/build/build/src/xpfe/appshell/nsAppShellService.cpp, line 805 23:39:32 INFO - JavaScript error: jar:file:///C:/Users/task_1523403112/build/application/firefox/browser/omni.ja!/components/nsBrowserGlue.js, line 1019: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAppShellService.hiddenDOMWindow] 23:39:32 INFO - [Parent 4988, StreamTrans #26] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 428 23:40:17 INFO - Hit MOZ_CRASH(Shutdown hanging before starting.) at z:/build/build/src/toolkit/components/terminator/nsTerminator.cpp:206 23:40:17 INFO - #01: PR_NativeRunThread [nsprpub/pr/src/threads/combined/pruthr.c:406] 23:40:17 INFO - #02: static unsigned int pr_root(void *) [nsprpub/pr/src/md/windows/w95thred.c:138] 23:40:17 INFO - #03: ucrtbase.dll + 0x20369 23:40:17 INFO - #04: KERNEL32.DLL + 0x12774 23:40:17 INFO - #05: ntdll.dll + 0x70d61 23:40:20 INFO - [GPU 6368, Main Thread] WARNING: Shutting down GPU process early due to a crash!: file z:/build/build/src/gfx/ipc/GPUParent.cpp, line 466 ...but I do not know what went wrong first.

(In reply to Geoff Brown [:gbrown] from comment #34) > 23:39:32 INFO - [Parent 4988, Main Thread] WARNING: > NS_ENSURE_TRUE(mHiddenWindow) failed: file > z:/build/build/src/xpfe/appshell/nsAppShellService.cpp, line 805 > 23:39:32 INFO - JavaScript error: > jar:file:///C:/Users/task_1523403112/build/application/firefox/browser/omni. > ja!/components/nsBrowserGlue.js, line 1019: NS_ERROR_FAILURE: Component > returned failure code: 0x80004005 (NS_ERROR_FAILURE) > [nsIAppShellService.hiddenDOMWindow] So we report first that something maybe went wrong in creating the hidden window, and then we fail with a JavaScript failure in Media Telemetry code trying to access the hidden window: https://dxr.mozilla.org/mozilla-central/rev/cfe6399e142c71966ef58a16cfd52c0b46dc6b1e/browser/components/nsBrowserGlue.js#1018-1021 I would say that we should file a separate bug for that, or get at least some info from Felipe first who implemented this code in bug 1397232. Also shouldn't Telemetry be disabled for reftests? Why are we running into this code? > 23:39:32 INFO - [Parent 4988, StreamTrans #26] WARNING: > 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, > line 428 > 23:40:17 INFO - Hit MOZ_CRASH(Shutdown hanging before starting.) at > z:/build/build/src/toolkit/components/terminator/nsTerminator.cpp:206 I wonder why we hang here, and do not see a shutdown of the process. Is that the messagebox which is blocking it? For automation this doesn't look ideal. Jim, could you help us here? Also see comment 33 and comment 34. Thanks.

(In reply to OrangeFactor Robot from comment #36) > * windows10-64-qr: 1 I cannot find anything for that listed in the intermittent failures list. Maybe it was mis-starred and got fixed. > * linux32: 1 Interesting here is that it takes about 4:30 minutes until this instance of Firefox (debug) has been started: https://treeherder.mozilla.org/logviewer.html#?job_id=173652170&repo=autoland&lineNumber=1766-1802

(In reply to Henrik Skupin (:whimboo) from comment #37) > (In reply to OrangeFactor Robot from comment #36) > > * windows10-64-qr: 1 > > I cannot find anything for that listed in the intermittent failures list. > Maybe it was mis-starred and got fixed. When and if we find miss-classified failures we usually correct them, so that's likely the case here.

(In reply to Geoff Brown [:gbrown] from comment #34) > Thanks - I haven't seen that screenshot before. > > I think the 370 s no-output application timeout is appropriate. I'm not sure > what else we can do in the harness. > > I suppose GetBootstrap() failed here: > > https://dxr.mozilla.org/mozilla-central/rev/ > 0528a414c2a86dad0623779abde5301d37337934/browser/app/nsBrowserApp.cpp#243-247 > > And it looks like that Output() call pops up a message box in Windows/debug > builds: > > https://dxr.mozilla.org/mozilla-central/rev/ > 0528a414c2a86dad0623779abde5301d37337934/browser/app/nsBrowserApp.cpp#120-127 > > Maybe using a message box here is not a good idea? > > > In the log I also notice: > > 23:39:32 INFO - [Parent 4988, Main Thread] WARNING: > NS_ENSURE_TRUE(mHiddenWindow) failed: file > z:/build/build/src/xpfe/appshell/nsAppShellService.cpp, line 805 > 23:39:32 INFO - JavaScript error: > jar:file:///C:/Users/task_1523403112/build/application/firefox/browser/omni. > ja!/components/nsBrowserGlue.js, line 1019: NS_ERROR_FAILURE: Component > returned failure code: 0x80004005 (NS_ERROR_FAILURE) > [nsIAppShellService.hiddenDOMWindow] > 23:39:32 INFO - [Parent 4988, StreamTrans #26] WARNING: > 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, > line 428 > 23:40:17 INFO - Hit MOZ_CRASH(Shutdown hanging before starting.) at > z:/build/build/src/toolkit/components/terminator/nsTerminator.cpp:206 > 23:40:17 INFO - #01: PR_NativeRunThread > [nsprpub/pr/src/threads/combined/pruthr.c:406] > 23:40:17 INFO - #02: static unsigned int pr_root(void *) > [nsprpub/pr/src/md/windows/w95thred.c:138] > 23:40:17 INFO - #03: ucrtbase.dll + 0x20369 > 23:40:17 INFO - #04: KERNEL32.DLL + 0x12774 > 23:40:17 INFO - #05: ntdll.dll + 0x70d61 > 23:40:20 INFO - [GPU 6368, Main Thread] WARNING: Shutting down GPU > process early due to a crash!: file > z:/build/build/src/gfx/ipc/GPUParent.cpp, line 466 > > ...but I do not know what went wrong first. I don't see how any of this can happen with an XPCOM lib that failed to load. These issues are usually related to flawed installs or corrupt binaries.