Closed Bug 1099370 Opened 11 years ago Closed 11 years ago

Intermittent browser_widget.js | application crashed [@ mozalloc_abort(char const*)] after FATAL ERROR: AsyncShutdown timeout in ShutdownLeaks: Wait for cleanup to be finished before checking for leaks Conditions: [{"name":"DevTools: Wait until toolbox...

Categories

(DevTools :: Inspector, defect)

Product:
DevTools
Component:
Inspector
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox36 unaffected, firefox37 fixed, firefox38 fixed, firefox-esr31 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 38
Tracking Flags:
Tracking Status
firefox36 --- unaffected
firefox37 --- fixed
firefox38 --- fixed
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: sjakthol)

References

Details

(Keywords: crash, intermittent-failure)

Attachments

(2 files)

bug1099370-fix-canvasdebugger-teardown v1.patch
1.20 KB, patch
vporof
: review+
Details | Diff | Splinter Review
debugger-automatic-cleanup-after-test.patch
7.38 KB, patch
ejpbruel
: review+
Details | Diff | Splinter Review
11:04:09 INFO - 3279 INFO TEST-START | chrome://mochitests/content/browser/browser/devtools/webide/test/browser_widget.js 11:04:10 INFO - 3280 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webide/test/browser_widget.js | Found WebIDE button 11:04:10 INFO - 3281 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webide/test/browser_widget.js | WebIDE button uninstalled 11:04:10 INFO - 3282 INFO Closing WebIDE 11:04:10 INFO - 3283 INFO Console message: [JavaScript Error: "not well-formed" {file: "file:///builds/slave/test/build/tests/mochitest/chrome/browser/devtools/webide/test/addons/simulators.json" line: 1 column: 1 source: "{"}] 11:04:10 INFO - 3284 INFO WebIDE closed 11:04:11 INFO - 3285 INFO TEST-OK | chrome://mochitests/content/browser/browser/devtools/webide/test/browser_widget.js | took 1332ms 11:04:21 INFO - WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"DevTools: Wait until toolbox is destroyed","state":"(none)","filename":"resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js","lineNumber":1660,"stack":["resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:Toolbox.prototype.destroy/leakCheckObserver:1660","chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest</<:548","chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/maybeRunTests/<:683","null:null:0"]}] Barrier: ShutdownLeaks: Wait for cleanup to be finished before checking for leaks 11:05:12 INFO - FATAL ERROR: AsyncShutdown timeout in ShutdownLeaks: Wait for cleanup to be finished before checking for leaks Conditions: [{"name":"DevTools: Wait until toolbox is destroyed","state":"(none)","filename":"resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js","lineNumber":1660,"stack":["resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:Toolbox.prototype.destroy/leakCheckObserver:1660","chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest</<:548","chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/maybeRunTests/<:683","null:null:0"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources. 11:05:12 INFO - [Parent 1806] ###!!! ABORT: file resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js, line 1660 11:05:12 INFO - [Parent 1806] ###!!! ABORT: file resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js, line 1660 11:05:13 INFO - TEST-INFO | Main app process: killed by SIGSEGV 11:05:13 INFO - 3286 INFO checking window state 11:05:13 INFO - 3287 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/webide/test/browser_widget.js | application terminated with exit code 11 11:05:13 INFO - runtests.py | Application ran for: 0:36:00.869964 11:05:13 INFO - zombiecheck | Reading PID log: /tmp/tmpOxqJLNpidlog 11:05:13 INFO - ==> process 1806 launched child process 1846 11:05:13 INFO - zombiecheck | Checking for orphan process with PID: 1846 11:05:13 INFO - mozcrash Downloading symbols from: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/fx-team-linux/1415987176/firefox-36.0a1.en-US.linux-i686.crashreporter-symbols.zip 11:05:39 INFO - mozcrash Saved minidump as /builds/slave/test/build/blobber_upload_dir/5a45c836-50fc-e333-09a84154-05d656f2.dmp 11:05:39 INFO - mozcrash Saved app info as /builds/slave/test/build/blobber_upload_dir/5a45c836-50fc-e333-09a84154-05d656f2.extra 11:05:39 WARNING - PROCESS-CRASH | chrome://mochitests/content/browser/browser/devtools/webide/test/browser_widget.js | application crashed [@ mozalloc_abort(char const*)] 11:05:39 INFO - Crash dump filename: /tmp/tmpSkYDwW.mozrunner/minidumps/5a45c836-50fc-e333-09a84154-05d656f2.dmp 11:05:39 INFO - Operating system: Linux 11:05:39 INFO - 0.0.0 Linux 3.2.0-23-generic-pae #36-Ubuntu SMP Tue Apr 10 22:19:09 UTC 2012 i686 11:05:39 INFO - CPU: x86 11:05:39 INFO - GenuineIntel family 6 model 44 stepping 2 11:05:39 INFO - 1 CPU 11:05:39 INFO - Crash reason: SIGSEGV 11:05:39 INFO - Crash address: 0x0 11:05:39 INFO - Thread 0 (crashed) 11:05:39 INFO - 0 libmozalloc.so!mozalloc_abort(char const*) [mozalloc_abort.cpp:91b67b9a26bb : 37 + 0x0] 11:05:39 INFO - eip = 0xb730d8a9 esp = 0xbf9e3730 ebp = 0xbf9e3748 ebx = 0xb73105c0 11:05:39 INFO - esi = 0xb75f9d9c edi = 0xbf9e3788 eax = 0x0000000a ecx = 0xffffffff 11:05:39 INFO - edx = 0xb75fa8ac efl = 0x00210282 11:05:39 INFO - Found by: given as instruction pointer in context 11:05:39 INFO - 1 libxul.so!NS_DebugBreak [nsDebugImpl.cpp:91b67b9a26bb : 469 + 0xe] 11:05:39 INFO - eip = 0xb367453a esp = 0xbf9e3750 ebp = 0xbf9e3b98 ebx = 0xb6e58804 11:05:39 INFO - esi = 0xbf9e3770 edi = 0xbf9e3788 11:05:39 INFO - Found by: call frame info 11:05:39 INFO - 2 libxul.so!nsDebugImpl::Abort(char const*, int) [nsDebugImpl.cpp:91b67b9a26bb : 150 + 0xd] 11:05:39 INFO - eip = 0xb36745af esp = 0xbf9e3ba0 ebp = 0xbf9e3bc8 ebx = 0xb6e58804 11:05:39 INFO - esi = 0xbf9e3d10 edi = 0xbf9e3cb8 11:05:39 INFO - Found by: call frame info 11:05:39 INFO - 3 libxul.so!NS_InvokeByIndex + 0x2f 11:05:39 INFO - eip = 0xb36ba628 esp = 0xbf9e3bd0 ebp = 0xbf9e3bf8 ebx = 0xb6e58804 11:05:39 INFO - esi = 0xbf9e3d10 edi = 0xbf9e3cb8 11:05:39 INFO - Found by: call frame info 11:05:39 INFO - 4 libxul.so!XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:91b67b9a26bb : 2395 + 0x15] 11:05:39 INFO - eip = 0xb3a458dc esp = 0xbf9e3c00 ebp = 0xbf9e3da8 11:05:39 INFO - Found by: previous frame's frame pointer 11:05:39 INFO - 5 libxul.so!XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [XPCWrappedNativeJSOps.cpp:91b67b9a26bb : 1244 + 0x9] 11:05:39 INFO - eip = 0xb3a47ddc esp = 0xbf9e3db0 ebp = 0xbf9e3e78 ebx = 0xb6e58804 11:05:39 INFO - esi = 0xb7260aa0 edi = 0xbf9e3e04 11:05:39 INFO - Found by: call frame info 11:05:39 INFO - 6 libxul.so!js::Invoke(JSContext*, JS::CallArgs, js::MaybeConstruct) [jscntxtinlines.h:91b67b9a26bb : 231 + 0x1b] 11:05:39 INFO - eip = 0xb5313c53 esp = 0xbf9e3e80 ebp = 0xbf9e4118 ebx = 0xb6e58804 11:05:39 INFO - esi = 0xb7260aa0 edi = 0xbf9e3ec8 11:05:39 INFO - Found by: call frame info
This test does not open a toolbox, so maybe a previous test is bleeding into it?
Paul, that doesn't look good. Can you dispatch someone to look at it?
Flags: needinfo?(paul)
Bug 1053463 seems related with view._elementStyle.rules errors. I believe this is really a Style Inspector error. browser_widget just happens to be the last test in the DevTools browser suite at the moment.
Component: Developer Tools: WebIDE → Developer Tools: Style Editor
Flags: needinfo?(paul)
See Also: → 1053463
Component: Developer Tools: Style Editor → Developer Tools: Inspector
Patrick, any guess what the issue is here? I believe you've done some recent Inspector test improvements, so thought you might have an idea. Ignore the WebIDE test name, it just happens to be the last test of the suite.
My understanding so far is that it sometimes takes longer for the toolbox to close, and that makes the whole thing crash because of the blocker code we added to the toolbox destroy function in bug 1060840. I don't exactly know what this does, but it looks like it prevents the tab from closing until the toolbox is fully destroy (to avoid leaks). But in doing this, it just waits for some reasonable amount of time, and declares the thing dead if it takes longer to complete. Here is the relevant code: http://mxr.mozilla.org/mozilla-central/source/toolkit/components/asyncshutdown/AsyncShutdown.jsm#760 Tim, you worked on bug 1060840, can you confirm my understanding of things so far? Do you agree with me that this shutdown crash can simply be caused by the toolbox taking more time than usual (maybe the machine is slower)?
Flags: needinfo?(pbrosset) → needinfo?(ttaubert)
Bug 1060840 just makes the shutdown leak detector wait until all tabs/toolboxes have been closed. Otherwise it would report those as leaked not knowing that they're still alive. If we see a shutdown crash then it seems like they're just never destroyed. AsyncShutdown stops waiting after 60s and just kills the process. Looks like for some reason the toolbox is never destroyed.
Flags: needinfo?(ttaubert)
(In reply to Tim Taubert [:ttaubert] (away Dec 19th, back Jan 5th) from comment #119) > Bug 1060840 just makes the shutdown leak detector wait until all > tabs/toolboxes have been closed. Otherwise it would report those as leaked > not knowing that they're still alive. If we see a shutdown crash then it > seems like they're just never destroyed. AsyncShutdown stops waiting after > 60s and just kills the process. Looks like for some reason the toolbox is > never destroyed. Or maybe the toolbox takes a whole lot of time to get destroyed. 60s really seems like an awful lot of time, but what if the machine is running very slow? Anyway, I've looked at the logs, there are plenty of exceptions in there and uncaught promise rejections, but it's hard to relate any of this to the toolbox not being able to close. I've also run a small script on the log that calculates the time between 2 lines, and I didn't find anything that was taking more than 60s. There's a couple of occurrences of stuff that take about 20seconds, but they were not about closing the toolbox anyway. So basically, I can't reproduce, I don't know where it comes from, and I don't know where to look :) Yay, best type of bug! Tim, one more question: is it right to assume that this error message is just displayed here because that's the end of the testsuite, but really, any test in the suite could have caused it, right? It seems pretty obvious that browser_widget.js isn't to blame here because it doesn't even open the toolbox, but I just want to make sure.
Flags: needinfo?(ttaubert)
(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #124) > Tim, one more question: is it right to assume that this error message is > just displayed here because that's the end of the testsuite, but really, any > test in the suite could have caused it, right? > It seems pretty obvious that browser_widget.js isn't to blame here because > it doesn't even open the toolbox, but I just want to make sure. Yeah, exactly. Some test running before will have opened a toolbox but never destroyed it properly. It probably wouldn't be too hard to add some debug output to find out which of the tests creates a toolbox and never destroys it. From there on you could dig deeper and try to find the actual cause, unfortunately try is your best bet to reproduce as it seems.
Flags: needinfo?(ttaubert)
> Or maybe the toolbox takes a whole lot of time to get destroyed. 60s really seems like an awful lot of time, but what if the machine is running very slow? In that case, crashing will be a mercy for the user. A shutdown that takes more than 60 seconds is clearly unacceptable, even on a slow machine.
I noticed when running canvasdebugger tests that they hang and the AsyncShutdown warning is printed to terminal. After a bit of bisection I was able to narrow the cause down to browser_canvas-frontend-open.js which would hang the shutdown IF another browser_canvas-frontend-* test was also executed. For example, I can reproduce the AsyncShutdown hang with following command: ./mach mochitest-devtools --e10s browser/devtools/canvasdebugger/test/browser_canvas-frontend-call-stack-03.js browser/devtools/canvasdebugger/test/browser_canvas-frontend-open.js I don't know if canvasdebugger is solely responsible for these intermittent failures but it sure seems to contribute to the result.
(In reply to Sami Jaktholm from comment #143) > I noticed when running canvasdebugger tests that they hang and the > AsyncShutdown warning is printed to terminal. After a bit of bisection I was > able to narrow the cause down to browser_canvas-frontend-open.js which would > hang the shutdown IF another browser_canvas-frontend-* test was also > executed. > > For example, I can reproduce the AsyncShutdown hang with following command: > ./mach mochitest-devtools --e10s > browser/devtools/canvasdebugger/test/browser_canvas-frontend-call-stack-03. > js browser/devtools/canvasdebugger/test/browser_canvas-frontend-open.js > > I don't know if canvasdebugger is solely responsible for these intermittent > failures but it sure seems to contribute to the result. Thanks Sami for finding this out. It sure does seem like it contributes to this bug. Victor, here's a slight change the canvasdebugger test teardown function that makes sure the toolbox is destroyed before closing the tab which seems to avoid the hang.
Attachment #8540601 - Flags: review?(vporof)
Comment on attachment 8540601 [details] [diff] [review] bug1099370-fix-canvasdebugger-teardown v1.patch Review of attachment 8540601 [details] [diff] [review]: ----------------------------------------------------------------- LGTM
Attachment #8540601 - Flags: review?(vporof) → review+
Thanks Victor. Let's check this in and keep the bug open in case this wasn't the only cause for the toolbox destroy hang.
Keywords: leave-open
If a debugger test times out, this problem seems to be triggered (see below). Here's a patch should fix that case. It modifies the cleanup function in head.js to a) destroy all toolboxes and wait for them to be destroyed b) close all extra tabs to avoid leaks It also removes calls to removeTab(gBrowser.selectedTab) from some tests that called that in their own cleanup functions. Now that the tabs are destroyed in the global cleanup function those calls would remove last tab and close the browser in the middle of the test suite. Try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=2c183694d706 ---- When a timeout occurs test harness will execute the cleanup function registered in debugger/test/head.js [1] which destroys the debugger server. Next the harness will remove leaked tabs. The open tab will be closed and the toolbox starts to destroy itself. At this point I kind of lost track of what's happening. The client destroyer sequence seems to hang in TabTarget._client.close(cleanupAndResolve)[2] which is waiting for the transport to be closed. When the cleanup function called DebuggerServer.destroy it closed the transport on the server side. The transport is apparently being closed from both ends at the same time (though I have no idea how e10s fits into this mix) which seem to cause the closure callback [3] to be never executed. Thus the destroyer promise does not resolve and the leak check barrier is never removed. I think this could occur even without a timeout. If a test destroys the tab but doesn't wait for the toolbox to be destroyed before finishing it could trigger similar chain of events so this might also help to reduce the general frequency of this bug. [1] https://hg.mozilla.org/mozilla-central/annotate/369a8f14ccf8/browser/devtools/debugger/test/head.js#l46 [2] https://hg.mozilla.org/mozilla-central/annotate/369a8f14ccf8/browser/devtools/framework/target.js#l591 [3] https://hg.mozilla.org/mozilla-central/annotate/369a8f14ccf8/browser/devtools/framework/target.js#l577
Attachment #8550719 - Flags: review?(vporof)
Comment on attachment 8550719 [details] [diff] [review] debugger-automatic-cleanup-after-test.patch Review of attachment 8550719 [details] [diff] [review]: ----------------------------------------------------------------- I think ejpbruel should review this instead
Attachment #8550719 - Flags: review?(vporof)
Attachment #8550719 - Flags: review?(ejpbruel)
This is on my radar for tomorrow. Sorry it took so long.
Comment on attachment 8550719 [details] [diff] [review] debugger-automatic-cleanup-after-test.patch Review of attachment 8550719 [details] [diff] [review]: ----------------------------------------------------------------- Patch looks good to me
Attachment #8550719 - Flags: review?(ejpbruel) → review+
Keywords: checkin-needed
Comment 232 seems like a false positive, since it's not the DevTools test suite. So far, no more occurrences since the last patch.
Ryan, the new hits after the last patch are only on Aurora (or they aren't actually the DevTools suite). Would it help you for us to uplift the fix to Aurora?
Flags: needinfo?(ryanvm)
Yes please! It can land a=test-only whenever.
Flags: needinfo?(ryanvm)
Assignee: nobody → sjakthol
status-firefox36: --- → unaffected
status-firefox37: --- → affected
status-firefox38: --- → fixed
status-firefox-esr31: --- → unaffected
Target Milestone: --- → Firefox 38
Marking FIXED, as there have not been new hits (for the DevTools suite) on fx-team / m-c in the last week.
Status: NEW → RESOLVED
Closed: 11 years ago
Keywords: leave-open
Resolution: --- → FIXED
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: