1256008 - Intermittent automation.py | application crashed [@ mozilla::dom::AutoJSAPI::InitInternal(JSObject*, JSContext*, bool)] (Assertion failure: !JS_IsExceptionPending(aCx), at dom/base/ScriptSettings.cpp:337)

Status: RESOLVED WORKSFORME

(Core :: DOM: Core & HTML, defect, P5)

Description

[Ryan VanderMeulen [:RyanVM]]

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

Comment 1

[Boris Zbarsky [:bzbarsky]]

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.

Comment 2

[Boris Zbarsky [:bzbarsky]]

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.  :(

Comment 3

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Can we log what the exception is somewhere?

Comment 4

[Boris Zbarsky [:bzbarsky]]

That should be doable.  I'll see if I can write up something.

Comment 5

[Boris Zbarsky [:bzbarsky]]

Attachment: Maybe like so?

Comment 6

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 8730878 [details] [diff] [review]
Maybe like so?

Review of attachment 8730878 [details] [diff] [review]:
-----------------------------------------------------------------

Yuck :)

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/f87cc2d2312c

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/f87cc2d2312c

Comment 9

[Andrew McCreight [:mccr8]]

It looks like this is still happening sometimes. It happened twice in the last week.

Comment 10

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

 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

Comment 11

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

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

[Boris Zbarsky [:bzbarsky]]

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

[Boris Zbarsky [:bzbarsky]]

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

[Boris Zbarsky [:bzbarsky]]

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

[BMO Automation]

Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.

Comment 17

[BugBot [:suhaib / :marco/ :calixte]]

The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?

Comment 18

[Hsin-Yi Tsai (she/her) | away [:hsinyi]]

(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 :)

Comment 19

[Boris Zbarsky [:bzbarsky]]

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.