Closed
Bug 1256008
Opened 8 years ago
Closed 5 years ago
Intermittent automation.py | application crashed [@ mozilla::dom::AutoJSAPI::InitInternal(JSObject*, JSContext*, bool)] (Assertion failure: !JS_IsExceptionPending(aCx), at dom/base/ScriptSettings.cpp:337)
Categories
(Core :: DOM: Core & HTML, defect, P5)
Tracking
()
RESOLVED
WORKSFORME
Tracking | Status | |
---|---|---|
firefox48 | --- | affected |
People
(Reporter: RyanVM, Unassigned)
References
Details
(Keywords: assertion, crash, intermittent-failure)
Attachments
(1 file)
3.56 KB,
patch
|
khuey
:
review+
|
Details | Diff | Splinter Review |
https://treeherder.mozilla.org/logviewer.html#?job_id=7977749&repo=fx-team 03:38:16 INFO - TEST-START | jetpack-package/addon-sdk/source/test/test-content-script.js.test Events Overload 03:38:16 INFO - ++DOCSHELL 0x119d88000 == 17 [pid = 2193] [id = 33] 03:38:16 INFO - ++DOMWINDOW == 53 (0x12f57f000) [pid = 2193] [serial = 82] [outer = 0x0] 03:38:16 INFO - ++DOMWINDOW == 54 (0x141e57000) [pid = 2193] [serial = 83] [outer = 0x12f57f000] 03:38:16 INFO - ++DOMWINDOW == 55 (0x142ef1400) [pid = 2193] [serial = 84] [outer = 0x12f57f000] 03:38:16 INFO - TEST-PASS | jetpack-package/addon-sdk/source/test/test-content-script.js.test Events Overload | correct URL loaded 03:38:16 INFO - Assertion failure: !JS_IsExceptionPending(aCx), at /builds/slave/fx-team-m64-d-0000000000000000/build/src/dom/base/ScriptSettings.cpp:337 03:38:45 INFO - #01: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) [js/xpconnect/src/XPCWrappedJSClass.cpp:985] 03:38:45 INFO - #02: PrepareAndDispatch [xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_darwin.cpp:122] 03:38:45 INFO - TEST-INFO | Main app process: exit 1 03:38:45 WARNING - TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1 03:38:45 INFO - runtests.py | Application ran for: 0:01:20.774786 03:38:45 INFO - zombiecheck | Reading PID log: /var/folders/pq/9wq8k9b96lz0dzpzk0df56pw00000w/T/tmpwYxnFspidlog 03:38:45 INFO - mozcrash Copy/paste: /builds/slave/test/build/macosx64-minidump_stackwalk /var/folders/pq/9wq8k9b96lz0dzpzk0df56pw00000w/T/tmpjodQ84.mozrunner/minidumps/04034B56-6F8B-40AA-AEA8-E3503547EA67.dmp /builds/slave/test/build/symbols 03:38:56 INFO - mozcrash Saved minidump as /builds/slave/test/build/blobber_upload_dir/04034B56-6F8B-40AA-AEA8-E3503547EA67.dmp 03:38:56 INFO - mozcrash Saved app info as /builds/slave/test/build/blobber_upload_dir/04034B56-6F8B-40AA-AEA8-E3503547EA67.extra 03:38:56 WARNING - PROCESS-CRASH | automation.py | application crashed [@ mozilla::dom::AutoJSAPI::InitInternal(JSObject*, JSContext*, bool)] 03:38:56 INFO - Crash dump filename: /var/folders/pq/9wq8k9b96lz0dzpzk0df56pw00000w/T/tmpjodQ84.mozrunner/minidumps/04034B56-6F8B-40AA-AEA8-E3503547EA67.dmp 03:38:56 INFO - Operating system: Mac OS X 03:38:56 INFO - 10.10.5 14F27 03:38:56 INFO - CPU: amd64 03:38:56 INFO - family 6 model 69 stepping 1 03:38:56 INFO - 4 CPUs 03:38:56 INFO - Crash reason: EXC_BAD_ACCESS / KERN_INVALID_ADDRESS 03:38:56 INFO - Crash address: 0x0 03:38:56 INFO - Process uptime: 52 seconds 03:38:56 INFO - Thread 0 (crashed) 03:38:56 INFO - 0 XUL!mozilla::dom::AutoJSAPI::InitInternal(JSObject*, JSContext*, bool) [ScriptSettings.cpp:17c26f120827 : 337 + 0x0] 03:38:56 INFO - rax = 0x0000000000000000 rdx = 0x00007fff78f641f8 03:38:56 INFO - rcx = 0x0000000000000000 rbx = 0x00007fff78f64c50 03:38:56 INFO - rsi = 0x0000d6000000d600 rdi = 0x0000000105d3b46d 03:38:56 INFO - rbp = 0x00007fff5fbf49f0 rsp = 0x00007fff5fbf49a0 03:38:56 INFO - r8 = 0x00007fff5fbf4950 r9 = 0x00007fff7894d300 03:38:56 INFO - r10 = 0x0000000000000001 r11 = 0x0000000000000040 03:38:56 INFO - r12 = 0x0000000000000000 r13 = 0x00000001253674c0 03:38:56 INFO - r14 = 0x0000000000000001 r15 = 0x000000010ba1d000 03:38:56 INFO - rip = 0x00000001022665b7 03:38:56 INFO - Found by: given as instruction pointer in context 03:38:56 INFO - 1 XUL!mozilla::dom::AutoEntryScript::AutoEntryScript(nsIGlobalObject*, char const*, bool, JSContext*) [ScriptSettings.cpp:17c26f120827 : 584 + 0xf] 03:38:56 INFO - rbx = 0x00007fff5fbf4dc8 rbp = 0x00007fff5fbf4a30 03:38:56 INFO - rsp = 0x00007fff5fbf4a00 r12 = 0x0000000000000000 03:38:56 INFO - r13 = 0x0000000128141be0 r14 = 0x0000000105c916f3 03:38:56 INFO - r15 = 0x0000000000000001 rip = 0x00000001022670ef 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 2 XUL!nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) [XPCWrappedJSClass.cpp:17c26f120827 : 983 + 0x21] 03:38:56 INFO - rbx = 0x00007fff5fbf4dc8 rbp = 0x00007fff5fbf4ed0 03:38:56 INFO - rsp = 0x00007fff5fbf4a40 r12 = 0x000000010bba2878 03:38:56 INFO - r13 = 0x0000000000000003 r14 = 0x1e0073a4add1a234 03:38:56 INFO - r15 = 0x0000000128171500 rip = 0x0000000101b40889 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 3 XUL!PrepareAndDispatch [xptcstubs_x86_64_darwin.cpp:17c26f120827 : 122 + 0xc] 03:38:56 INFO - rbx = 0x00007fff5fbf4f20 rbp = 0x00007fff5fbf4fd0 03:38:56 INFO - rsp = 0x00007fff5fbf4ee0 r12 = 0x00000001281773e0 03:38:56 INFO - r13 = 0x0000000000000003 r14 = 0x0000000000000004 03:38:56 INFO - r15 = 0x1e0073a4add1a234 rip = 0x000000010119ba81 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 4 XUL!SharedStub + 0x5b 03:38:56 INFO - rbx = 0x0000000000000000 rbp = 0x00007fff5fbf5050 03:38:56 INFO - rsp = 0x00007fff5fbf4fe0 r12 = 0x000000011b882be0 03:38:56 INFO - r13 = 0x000000012f741c10 r14 = 0x0000000000000000 03:38:56 INFO - r15 = 0x0000000105d1f725 rip = 0x000000010119a79b 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 5 XUL!nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [nsObserverList.cpp:17c26f120827 : 113 + 0xf] 03:38:56 INFO - rbp = 0x00007fff5fbf5090 rsp = 0x00007fff5fbf5060 03:38:56 INFO - rip = 0x000000010112c4eb 03:38:56 INFO - Found by: previous frame's frame pointer 03:38:56 INFO - 6 XUL!nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [nsObserverService.cpp:17c26f120827 : 303 + 0x11] 03:38:56 INFO - rbx = 0x0000000100310a88 rbp = 0x00007fff5fbf50c0 03:38:56 INFO - rsp = 0x00007fff5fbf50a0 r12 = 0x0000000105d1f725 03:38:56 INFO - r13 = 0x0000000000000019 r14 = 0x0000000000000000 03:38:56 INFO - r15 = 0x000000012f741c10 rip = 0x000000010112de06 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 7 XUL!nsFrameMessageManager::Close() [nsFrameMessageManager.cpp:17c26f120827 : 1367 + 0x12] 03:38:56 INFO - rbx = 0x000000012f741c10 rbp = 0x00007fff5fbf50f0 03:38:56 INFO - rsp = 0x00007fff5fbf50d0 r12 = 0x00000001003f7000 03:38:56 INFO - r13 = 0x0000000000000019 r14 = 0x0000000000000001 03:38:56 INFO - r15 = 0x000000011cbde7f8 rip = 0x0000000102169334 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 8 XUL!nsFrameMessageManager::Disconnect(bool) [nsFrameMessageManager.cpp:17c26f120827 : 1380 + 0x5] 03:38:56 INFO - rbx = 0x000000012f741c10 rbp = 0x00007fff5fbf5120 03:38:56 INFO - rsp = 0x00007fff5fbf5100 r12 = 0x00000001003f7000 03:38:56 INFO - r13 = 0x0000000000000019 r14 = 0x0000000000000001 03:38:56 INFO - r15 = 0x000000011cbde7f8 rip = 0x0000000102163656 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 9 XUL!nsGlobalChromeWindow::DisconnectAndClearGroupMessageManagers() [nsGlobalWindow.h:17c26f120827 : 1922 + 0xe] 03:38:56 INFO - rbx = 0x00007fff5fbf5130 rbp = 0x00007fff5fbf5170 03:38:56 INFO - rsp = 0x00007fff5fbf5130 r12 = 0x00000001003f7000 03:38:56 INFO - r13 = 0x0000000000000019 r14 = 0x000000012da3abd8 03:38:56 INFO - r15 = 0x000000011cbde7f8 rip = 0x00000001021b0c6f 03:38:56 INFO - Found by: call frame info 03:38:56 INFO - 10 XUL!nsGlobalChromeWindow::cycleCollection::Unlink(void*) [nsGlobalWindow.cpp:17c26f120827 : 13118 + 0x8] 03:38:56 INFO - rbx = 0x000000012da3a800 rbp = 0x00007fff5fbf51a0 03:38:56 INFO - rsp = 0x00007fff5fbf5180 r12 = 0x00000001003f7000 03:38:56 INFO - r13 = 0x0000000000000019 r14 = 0x000000012da3abd0 03:38:56 INFO - r15 = 0x000000011cbde7f8 rip = 0x00000001021a9fdf 03:38:56 INFO - Found by: call frame info
Flags: needinfo?(bzbarsky)
Comment 1•8 years ago
|
||
We added this basic-sanity assertion in bug 1112920. Looks like someone is not clearing/reporting exceptions when they should... I'll see if I can reproduce this in rr on Monday; if I can that will tell us who the someone is. Note that there is a good chance that landing bug 1255817 will just fix this anyway.
Blocks: 1112920
Comment 2•8 years ago
|
||
I ran this for over 24 hours under rr in a loop.. until the test harness failed due to a timeout. Never hit this issue. :(
Flags: needinfo?(bzbarsky)
Can we log what the exception is somewhere?
Comment 4•8 years ago
|
||
That should be doable. I'll see if I can write up something.
Comment 5•8 years ago
|
||
Attachment #8730878 -
Flags: review?(khuey)
Comment on attachment 8730878 [details] [diff] [review] Maybe like so? Review of attachment 8730878 [details] [diff] [review]: ----------------------------------------------------------------- Yuck :)
Attachment #8730878 -
Flags: review?(khuey) → review+
Updated•8 years ago
|
Keywords: leave-open
Comment 8•8 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/f87cc2d2312c
Comment 9•8 years ago
|
||
It looks like this is still happening sometimes. It happened twice in the last week.
03:02:09 INFO - #01: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) [js/xpconnect/src/XPCWrappedJSClass.cpp:982] 03:02:09 INFO - #02: PrepareAndDispatch [xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_darwin.cpp:122] https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=24956426
Oh, and 03:01:39 INFO - PREEXISTING EXCEPTION OBJECT: 'NS_ERROR_FILE_NOT_FOUND: Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIChannel.open]' 03:01:39 INFO - resource://gre/modules/commonjs/toolkit/loader.js:181 03:01:39 INFO - readURI@resource://gre/modules/commonjs/toolkit/loader.js:181:16 03:01:39 INFO - loadAsFile@resource://gre/modules/commonjs/toolkit/loader.js:485:5 03:01:39 INFO - nodeResolve@resource://gre/modules/commonjs/toolkit/loader.js:444:23 03:01:39 INFO - @resource://gre/modules/commonjs/toolkit/loader.js:836:25 03:01:39 INFO - getRequirements@resource://gre/modules/commonjs/toolkit/loader.js:718:23 03:01:39 INFO - _require@resource://gre/modules/commonjs/toolkit/loader.js:611:32 03:01:39 INFO - require@resource://gre/modules/commonjs/toolkit/loader.js:607:12 03:01:39 INFO - @resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/private-browsing/utils.js:14:24 03:01:39 INFO - evaluate@resource://gre/modules/commonjs/toolkit/loader.js:279:19 03:01:39 INFO - load@resource://gre/modules/commonjs/toolkit/loader.js:331:5 03:01:39 INFO - _require@resource://gre/modules/commonjs/toolkit/loader.js:653:16 03:01:39 INFO - require@resource://gre/modules/commonjs/toolkit/loader.js:607:12 03:01:39 INFO - @resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/content/worker.js:16:23 03:01:39 INFO - evaluate@resource://gre/modules/commonjs/toolkit/loader.js:279:19 03:01:39 INFO - load@resource://gre/modules/commonjs/toolkit/loader.js:331:5 03:01:39 INFO - _require@resource://gre/modules/commonjs/toolkit/loader.js:653:16 03:01:39 INFO - require@resource://gre/modules/commonjs/toolkit/loader.js:607:12 03:01:39 INFO - createWorker@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jetpack-package-tests/jetpack-package/addon-sdk/source/test/test-content-script.js:69:16 03:01:39 INFO - createProxyTest/</onDOMReady/helper.createWorker@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jetpack-package-tests/jetpack-package/addon-sdk/source/test/test-content-script.js:52:18 03:01:39 INFO - exports["test Collections 2"]<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jetpack-package-tests/jetpack-package/addon-sdk/source/test/test-content-script.js:530:3 03:01:39 INFO - onDOMReady@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jetpack-package-tests/jetpack-package/addon-sdk/source/test/test-content-script.js:62:7 03:01:39 INFO - EventListener.handleEvent*EventTargetInterposition.methods.addEventListener@resource://gre/modules/RemoteAddonsParent.jsm:626:5 03:01:39 INFO - AddonInterpositionService.prototype.interposeProperty/desc.value@resource://gre/components/multiprocessShims.js:160:52 03:01:39 INFO - createProxyTest/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jetpack-package-tests/jetpack-package/addon-sdk/source/test/test-content-script.js:31:5 03:01:39 INFO - @resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/test.js:67:13 03:01:39 INFO - start@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/deprecated/unit-test.js:576:7 03:01:39 INFO - startMany/runNextTest/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/deprecated/unit-test.js:538:11 03:01:39 INFO - promise callback*runNextTest@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/deprecated/unit-test.js:532:14 03:01:39 INFO - start/this.onDone@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/deprecated/unit-test.js:563:7 03:01:39 INFO - done/</<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/deprecated/unit-test.js:389:31 03:01:39 INFO - notify@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/timers.js:40:9
Comment 12•8 years ago
|
||
So that's showing an exception thrown from this code in readURI: 181 let stream = NetUtil.newChannel({ 182 uri: NetUtil.newURI(uri, 'UTF-8'), 183 loadUsingSystemPrincipal: true} 184 ).open(); 185 let count = stream.available(); 186 let data = NetUtil.readInputStreamToString(stream, count, { 187 charset: 'UTF-8' 188 }); 189 190 stream.close(); and the open() call is what's throwing, NS_ERROR_FILE_NOT_FOUND. And we got there via a loadSubScript call like this: 03:01:39 INFO - evaluate@resource://gre/modules/commonjs/toolkit/loader.js:279:19 which is this code: 29 const { loadSubScript } = Cc['@mozilla.org/moz/jssubscript-loader;1']. 30 getService(Ci.mozIJSSubScriptLoader); ... 278 return source ? Cu.evalInSandbox(source, sandbox, version, uri, line) 279 : loadSubScript(uri, sandbox, encoding); OK, so mozJSSubScriptLoader::LoadSubScript takes a "JSContext* cx" as argument and does: 533 return DoLoadSubScriptWithOptions(url, options, cx, retval); mozJSSubScriptLoader::DoLoadSubScriptWithOptions does various stuff to actually get the script, then does: 684 return EvalScript(cx, targetObj, retval, uri, !!cache, script, function); And EvalScript looks like this: 200 bool ok = false; ... /* Several codepaths here that set ok to return values of JS_CallFunction or JS_ExecuteScript */ ... 214 if (ok) { 215 JSAutoCompartment rac(cx, target_obj); 216 if (!JS_WrapValue(cx, retval)) 217 return NS_ERROR_UNEXPECTED; 218 } and after that all the codepaths except the one where GetSystemPrincipal fails return NS_OK! So we leave a pending exception dangling on the JSContext. Oops.
Comment 13•8 years ago
|
||
OK, but then we should be going back out to CallMethodHelper::Call which should do: if (JS_IsExceptionPending(mCallContext)) { return false; } which should propagate back to spidermonkey. And if I try a simple testcase with loadSubScript throwing an exception, I see that exception rethrown to the loadSubScript caller...
Comment 14•8 years ago
|
||
What confuses me about the log linked from comment 10 is that it's really not clear who's calling the js::jit::InvokeFunction. Presumably jitcode, but what called into that? Put another way, did we somehow manage to reenter script somewhere between the false return value in EvalScript and mozJSSubScriptLoader::LoadSubScript returning?
Comment 16•8 years ago
|
||
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Updated•7 years ago
|
Priority: P3 → P5
Comment 17•5 years ago
|
||
The leave-open keyword is there and there is no activity for 6 months. :hsinyi, maybe it's time to close this bug?
Flags: needinfo?(htsai)
Comment 18•5 years ago
|
||
(In reply to Release mgmt bot [:sylvestre / :calixte] from comment #17)
The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?
I'll defer the decision making power to Boris :)
Flags: needinfo?(htsai) → needinfo?(bzbarsky)
Comment 19•5 years ago
|
||
The leave-open was so when I checked in the instrumentation people wouldn't resolve the bug.
If this isn't being hit anymore, we should resolve worksforme.
Status: NEW → RESOLVED
Closed: 5 years ago
Flags: needinfo?(bzbarsky)
Resolution: --- → WORKSFORME
Updated•5 years ago
|
Keywords: leave-open
Assignee | ||
Updated•5 years ago
|
Component: DOM → DOM: Core & HTML
You need to log in
before you can comment on or make changes to this bug.
Description
•