977204 - Intermittent B2G mochitest failures where the run finishes successfully and hits "NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIXPCComponents_Utils.cloneInto]" during shutdown

Status: RESOLVED WORKSFORME

(Firefox OS Graveyard :: General, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

These show up as "Summary is empty." on TBPL, so starring these is going to be a manual job (CCing :sheriffs). This could very well be a dupe of something else, and I don't know if the System JS error is actually the issue here or not, but it's the best theory I can see at the moment. Nothing obvious in the logcat that I can see either since I'm pretty sure that the "service 'media.resource_manager' died" at the end of the run is what we would expect to see at the end of shutting down.

https://tbpl.mozilla.org/php/getParsedLog.php?id=35290736&tree=B2g-Inbound

b2g_emulator_vm b2g-inbound opt test mochitest-5 on 2014-02-26 09:30:18 PST for push 39913ae5cf79
slave: tst-linux64-spot-331

10:00:09     INFO -  2077 INFO TEST-START | Shutdown
10:00:09     INFO -  2078 INFO Passed:  19842
10:01:21     INFO -  2079 INFO Mochitest INFO | runtestsb2g.py | Running tests: end.
10:01:25     INFO -  Failed:  0
10:01:25     INFO -  2080 INFO Todo:    7570
10:01:25     INFO -  2081 INFO Slowest: 93448ms - /tests/dom/contacts/tests/test_contacts_getall.html
10:01:25     INFO -  2082 INFO SimpleTest FINISHED
10:01:25     INFO -  2083 INFO TEST-INFO | Ran 1 Loops
10:01:25     INFO -  2084 INFO SimpleTest FINISHED
10:01:25     INFO -  System JS : ERROR chrome://b2g/content/shell.js:566 - NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIXPCComponents_Utils.cloneInto]
10:01:26     INFO - Return code: 0

10:01:28     INFO -  02-26 18:00:10.091   705   705 I GeckoDump: 2077 INFO TEST-START | Shutdown
10:01:28     INFO -  02-26 18:00:10.091   705   705 I GeckoDump: 2078 INFO Passed:  19842
10:01:28     INFO -  02-26 18:00:10.091   705   705 I GeckoDump: 2079 INFO Failed:  0
10:01:28     INFO -  02-26 18:00:10.111   705   705 I GeckoDump: 2080 INFO Todo:    7570
10:01:28     INFO -  02-26 18:00:10.121   705   705 I GeckoDump: 2081 INFO Slowest: 93448ms - /tests/dom/contacts/tests/test_contacts_getall.html
10:01:28     INFO -  02-26 18:00:10.131   705   705 I GeckoDump: 2082 INFO SimpleTest FINISHED
10:01:28     INFO -  02-26 18:00:10.151   705   705 I GeckoDump: 2083 INFO TEST-INFO | Ran 1 Loops
10:01:28     INFO -  02-26 18:00:10.161   705   705 I GeckoDump: 2084 INFO SimpleTest FINISHED
10:01:28     INFO -  02-26 18:00:12.031    40   111 V EmulatedCamera_CallbackNotifier: disableMessage: msg_type = 0xffff
10:01:28     INFO -  02-26 18:00:12.031    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_ERROR
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_SHUTTER
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_FOCUS
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_ZOOM
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_PREVIEW_FRAME
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_VIDEO_FRAME
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_POSTVIEW_FRAME
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_RAW_IMAGE
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_COMPRESSED_IMAGE
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_RAW_IMAGE_NOTIFY
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier:     CAMERA_MSG_PREVIEW_METADATA
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_CallbackNotifier: **** Currently enabled messages:
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_Camera: doStopPreview
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_Camera: cancelPicture
10:01:28     INFO -  02-26 18:00:12.041    40   111 V EmulatedCamera_Camera: releaseCamera
10:01:28     INFO -  02-26 18:00:12.051    40   111 V EmulatedCamera_Camera: doStopPreview
10:01:28     INFO -  02-26 18:00:12.051    40   111 V EmulatedCamera_FakeDevice: disconnectDevice
10:01:28     INFO -  02-26 18:00:12.051    40   111 I CameraService: Destroying camera 0
10:01:28     INFO -  02-26 18:00:12.051    40   111 V EmulatedCamera_Camera: closeCamera
10:01:28     INFO -  02-26 18:00:12.051    40   111 V EmulatedCamera_Camera: doStopPreview
10:01:28     INFO -  02-26 18:00:12.071    40   111 W AudioFlinger: session id 12 not found for pid 40
10:01:28     INFO -  02-26 18:00:12.071    40   111 W AudioFlinger: session id 13 not found for pid 40
10:01:28  WARNING -  02-26 18:00:12.181   658   658 E GeckoConsole: [JavaScript Error: "NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIXPCComponents_Utils.cloneInto]" {file: "chrome://b2g/content/shell.js" line: 566}]
10:01:28     INFO -  02-26 18:00:12.201   658   680 E Profiler: BPUnw: [1 total] thread_unregister_for_profiling(me=0x22fb8)  (NOT REGISTERED)
10:01:28     INFO -  02-26 18:00:13.811    33    33 I ServiceManager: service 'media.resource_manager' died
10:01:28     INFO -  02-26 18:00:13.811    33    33 I ServiceManager: service 'permission' died
10:01:28     INFO - Return code: 0

Comment 1

[Ryan VanderMeulen [:RyanVM]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=35289911&tree=Mozilla-Inbound

Comment 2

[Ryan VanderMeulen [:RyanVM]]

Same on debug mochitest-12.

https://tbpl.mozilla.org/php/getParsedLog.php?id=35297666&tree=Mozilla-Inbound

Comment 3

[(no longer active)]

So this is either sendChromeEvent or sendCustomEvent in http://mxr.mozilla.org/mozilla-central/source/b2g/chrome/content/shell.js.  My theory is that NS_ERROR_ILLEGAL_VALUE comes from <http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCQuickStubs.cpp#603> because the second argument is not a valid window somehow.

Bobby, does this theory make sense?

Comment 4

[Phil Ringnalda (:philor)]

comment 0: "INFO -  Failed:  0"
comment 1: "INFO -  2079 INFO FailMochitest INFO | runtestsb2g.py | Running tests: end."
comment 2: "724 INFO FaiMochitest INFO | runtestsb2g.py | Running tests: end."

I certainly wouldn't mind seeing some of b2g's shutdown spam get fixed, but the reason those jobs are failing is just ye olde bug 967647, any mochitest log which does not match "\d+ INFO Failed: 0" by definition failed.

Comment 5

[Bobby Holley (:bholley)]

(In reply to :Ehsan Akhgari (needinfo? me!) (slow responsiveness, emailapocalypse) from comment #3)
> So this is either sendChromeEvent or sendCustomEvent in
> http://mxr.mozilla.org/mozilla-central/source/b2g/chrome/content/shell.js. 
> My theory is that NS_ERROR_ILLEGAL_VALUE comes from
> <http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/src/
> XPCQuickStubs.cpp#603> because the second argument is not a valid window
> somehow.
> 
> Bobby, does this theory make sense?

I don't think so. The error seems to be coming from the cloneInto call (see the [nsIXPCComponents_Utils.cloneInto] bit in the log), either here or here:

http://hg.mozilla.org//mozilla-central/annotate/a98a1d78817f/b2g/chrome/content/shell.js#l557
http://hg.mozilla.org//mozilla-central/annotate/a98a1d78817f/b2g/chrome/content/shell.js#l573

Moreover, NS_ERROR_ILLEGAL_VALUE is a synonym for NS_ERROR_INVALID_ARG:

http://mxr.mozilla.org/mozilla-central/source/xpcom/base/ErrorList.h#29

which is thrown at the top of XPCComponents_Utils::CloneInto when a non-object scope parameter is passed:

http://dxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCComponents.cpp#3610

So I think it's pretty clear that getContentWindow() is returning null or undefined here.

Comment 6

[(no longer active)]

Ah right, I was confused on NS_ERROR_ILLEGAL_VALUE and NS_ERROR_INVALID_ARG.  Thanks for correcting me on that!  I think comment 5 is rigth on.

Comment 7

[Ed Morley [:emorley]]

Inactive; closing (see bug 1180138).