Closed Bug 1004671 Opened 6 years ago Closed 5 years ago

Intermittent *ASAN* TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output

Categories

(Core :: JavaScript Engine, defect)

x86_64
Linux
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla32
Tracking Status
firefox30 --- fixed
firefox31 --- fixed
firefox32 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: emorley, Assigned: jmaher)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Breaking out from bug 918759.

Ubuntu ASAN VM 12.04 x64 fx-team opt test mochitest-other on 2014-04-28 10:34:14 PDT for push a2d961fb4789

slave: tst-linux64-spot-203

https://tbpl.mozilla.org/php/getParsedLog.php?id=38646304&tree=Fx-Team

SUMMARY: AddressSanitizer: SEGV /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/ctypes/typedefs.h:78 js::ctypes::ConvertToJS(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, void*, bool, bool, JS::Value*)
TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
TEST-UNEXPECTED-FAIL | Shutdown | application terminated with exit code -9
Return code: 247

{
10:42:08     INFO -  1467 INFO TEST-START | chrome://mochitests/content/chrome/dom/ipc/tests/test_process_error.xul
10:42:09     INFO -  Xlib:  extension "RANDR" missing on display ":0".
10:42:09     INFO -  XPCOM_MEM_BLOAT_LOG: /tmp/tmpB8ThhB/runtests_leaks.log
10:42:09     INFO -  Writing to log: /tmp/tmpB8ThhB/runtests_leaks_tab_pid2588.log
10:42:09     INFO -  ASAN:SIGSEGV
10:42:09     INFO -  =================================================================
10:42:09     INFO -  ==2588==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000008 (pc 0x7f7d0a8fe0c6 sp 0x7ffff4f88f40 bp 0x7ffff4f89870 T0)
10:42:11     INFO -      #0 0x7f7d0a8fe0c5 in js::ctypes::ConvertToJS(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, void*, bool, bool, JS::Value*) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/ctypes/typedefs.h:78
10:42:11     INFO -      #1 0x7f7d0a8fda44 in js::ctypes::PointerType::ContentsGetter(JSContext*, JS::CallArgs) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/ctypes/CTypes.cpp:4143
10:42:11     INFO -      #2 0x7f7d0a94b112 in CallNonGenericMethod<&js::ctypes::PointerType::IsPointer, &js::ctypes::PointerType::ContentsGetter> /builds/slave/fx-team-l64-asan-0000000000000/build/obj-firefox/js/src/../../dist/include/js/CallNonGenericMethod.h:100
10:42:11     INFO -      #3 0x7f7d0a94b112 in js::ctypes::Property<&js::ctypes::PointerType::IsPointer, &js::ctypes::PointerType::ContentsGetter>::Fun(JSContext*, unsigned int, JS::Value*) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/ctypes/CTypes.cpp:171
10:42:11     INFO -      #4 0x7f7d0b4685e0 in CallJSNative /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jscntxtinlines.h:239
10:42:11     INFO -      #5 0x7f7d0b4685e0 in js::Invoke(JSContext*, JS::CallArgs, js::MaybeConstruct) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:468
10:42:11     INFO -      #6 0x7f7d0b469bde in js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value const*, JS::MutableHandle<JS::Value>) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:531
10:42:11     INFO -      #7 0x7f7d0b46af7d in js::InvokeGetterOrSetter(JSContext*, JSObject*, JS::Value, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:603
10:42:11     INFO -      #8 0x7f7d0b1ec7e6 in get /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Shape-inl.h:46
10:42:11     INFO -      #9 0x7f7d0b1ec7e6 in NativeGetInline<1> /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsobj.cpp:4302
10:42:11     INFO -      #10 0x7f7d0b1ec7e6 in GetPropertyHelperInline<1> /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsobj.cpp:4497
10:42:11     INFO -      #11 0x7f7d0b1ec7e6 in js::baseops::GetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsobj.cpp:4507
10:42:11     INFO -      #12 0x7f7d0b235345 in getGeneric /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsobj.h:985
10:42:11     INFO -      #13 0x7f7d0b235345 in js::DirectProxyHandler::get(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsproxy.cpp:576
10:42:11     INFO -      #14 0x7f7d0b34b7a2 in js::CrossCompartmentWrapper::get(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jswrapper.cpp:328
10:42:11     INFO -      #15 0x7f7d0b2533c8 in js::Proxy::get(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsproxy.cpp:2536
10:42:11     INFO -      #16 0x7f7d0b45bbab in getGeneric /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsobj.h:982
10:42:11     INFO -      #17 0x7f7d0b45bbab in GetPropertyOperation /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:265
10:42:11     INFO -      #18 0x7f7d0b45bbab in Interpret(JSContext*, js::RunState&) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:2415
10:42:11     INFO -      #19 0x7f7d0b43fe8c in js::RunScript(JSContext*, js::RunState&) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:422
10:42:11     INFO -      #20 0x7f7d0b46b50b in js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value const&, js::ExecuteType, js::AbstractFramePtr, JS::Value*) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:630
10:42:11     INFO -      #21 0x7f7d0b46baae in js::Execute(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value*) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/vm/Interpreter.cpp:666
10:42:11     INFO -      #22 0x7f7d0b0c128b in ExecuteScript(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSScript*>, JS::Value*) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsapi.cpp:4782
10:42:11     INFO -      #23 0x7f7d0b0c1667 in JS::CloneAndExecuteScript(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSScript*>) /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/jsapi.cpp:4808
10:42:11     INFO -      #24 0x7f7d077d5487 in nsFrameScriptExecutor::LoadFrameScriptInternal(nsAString_internal const&, bool) /builds/slave/fx-team-l64-asan-0000000000000/build/content/base/src/nsFrameMessageManager.cpp:1455
10:42:11     INFO -      #25 0x7f7d06898ab7 in mozilla::dom::TabChild::RecvLoadRemoteScript(nsString const&, bool const&) /builds/slave/fx-team-l64-asan-0000000000000/build/dom/ipc/TabChild.cpp:2264
10:42:11     INFO -      #26 0x7f7d047d22ec in mozilla::dom::PBrowserChild::OnMessageReceived(IPC::Message const&) /builds/slave/fx-team-l64-asan-0000000000000/build/obj-firefox/ipc/ipdl/./PBrowserChild.cpp:2622
10:42:11     INFO -      #27 0x7f7d04889a4e in mozilla::dom::PContentChild::OnMessageReceived(IPC::Message const&) /builds/slave/fx-team-l64-asan-0000000000000/build/obj-firefox/ipc/ipdl/./PContentChild.cpp:3417
10:42:11     INFO -      #28 0x7f7d0471a9f0 in mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const&) /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/glue/MessageChannel.cpp:1151
10:42:11     INFO -      #29 0x7f7d0470e935 in mozilla::ipc::MessageChannel::OnMaybeDequeueOne() /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/glue/MessageChannel.cpp:1048
10:42:11     INFO -      #30 0x7f7d046cb374 in RunTask /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:357
10:42:11     INFO -      #31 0x7f7d046cb374 in MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask const&) /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:365
10:42:11     INFO -      #32 0x7f7d046cc427 in MessageLoop::DoWork() /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:443
10:42:11     INFO -      #33 0x7f7d04720915 in mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/glue/MessagePump.cpp:278
10:42:11     INFO -      #34 0x7f7d046c9de0 in RunInternal /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:229
10:42:11     INFO -      #35 0x7f7d046c9de0 in RunHandler /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:222
10:42:11     INFO -      #36 0x7f7d046c9de0 in MessageLoop::Run() /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:196
10:42:11     INFO -      #37 0x7f7d06992c37 in nsBaseAppShell::Run() /builds/slave/fx-team-l64-asan-0000000000000/build/widget/xpwidgets/nsBaseAppShell.cpp:164
10:42:11     INFO -      #38 0x7f7d0968a392 in XRE_RunAppShell /builds/slave/fx-team-l64-asan-0000000000000/build/toolkit/xre/nsEmbedFunctions.cpp:679
10:42:11     INFO -      #39 0x7f7d046c9de0 in RunInternal /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:229
10:42:11     INFO -      #40 0x7f7d046c9de0 in RunHandler /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:222
10:42:11     INFO -      #41 0x7f7d046c9de0 in MessageLoop::Run() /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/base/message_loop.cc:196
10:42:11     INFO -      #42 0x7f7d09689a74 in XRE_InitChildProcess /builds/slave/fx-team-l64-asan-0000000000000/build/toolkit/xre/nsEmbedFunctions.cpp:516
10:42:11     INFO -      #43 0x488571 in main /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/app/MozillaRuntimeMain.cpp:149
10:42:11     INFO -      #44 0x7f7d0143d76c (/lib/x86_64-linux-gnu/libc.so.6+0x2176c)
10:42:11     INFO -      #45 0x4883fc in _start (/builds/slave/test/build/application/firefox/plugin-container+0x4883fc)
10:42:11     INFO -  AddressSanitizer can not provide additional info.
10:42:11     INFO -  SUMMARY: AddressSanitizer: SEGV /builds/slave/fx-team-l64-asan-0000000000000/build/js/src/ctypes/typedefs.h:78 js::ctypes::ConvertToJS(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, void*, bool, bool, JS::Value*)
10:42:11     INFO -  ==2588==ABORTING
10:42:11     INFO -  ###!!! [Parent][MessageChannel] Error: Channel error: cannot send/recv
10:42:11     INFO -  [Parent 2483] WARNING: pipe error (67): Connection reset by peer: file /builds/slave/fx-team-l64-asan-0000000000000/build/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 450
10:42:11     INFO -  1468 INFO TEST-INFO | MEMORY STAT vsize after test: 21991728738304
10:42:11     INFO -  1469 INFO TEST-INFO | MEMORY STAT residentFast after test: 732082176
10:42:11     INFO -  ************************************************************
10:42:11     INFO -  * Call to xpconnect wrapped JSObject produced this error:  *
10:42:11     INFO -  [Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIPropertyBag2.getPropertyAsAString]"  nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)"  location: "JS frame :: chrome://specialpowers/content/SpecialPowersObserverAPI.js :: addDumpIDToMessage :: line 74"  data: no]
10:42:11     INFO -  ************************************************************
10:42:11     INFO -  1470 INFO TEST-END | chrome://mochitests/content/chrome/dom/ipc/tests/test_process_error.xul | finished in 3154ms
}
Christian - may you direct this towards the correct person (and/or component)? :-)
Flags: needinfo?(choller)
Isn't that the generic ASAN error we get on every run due to the TBPL log parser?
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #2)
> Isn't that the generic ASAN error we get on every run due to the TBPL log
> parser?

I don't see it in these two green ASAN runs? (one opt, one debug)
https://tbpl.mozilla.org/php/getParsedLog.php?id=38890667&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=38889742&tree=Mozilla-Inbound
Those were build runs, not tests. See the various mochitest-bc logs:

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

It's an expected SEGV IIRC (so ASAN is doing the right thing) and our log parser is picking it up. I thought we had a bug for it.
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #4)
> Those were build runs, not tests. 

Ah true; too tired :-)

> It's an expected SEGV IIRC (so ASAN is doing the right thing) and our log
> parser is picking it up. I thought we had a bug for it.

Sigh yeah sounds familiar now. Ideally ASAN or an intermediate wrapper would filter this out.
Summary: Intermittent *ASAN* TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output (after: SEGV js/src/ctypes/typedefs.h:78 js::ctypes::ConvertToJS(...)) → Intermittent *ASAN* TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
Nope, we should not filter this out. Instead, the test shouldn't even run because it looks like this test requires the crash reporter to make sense and ASan builds are --disable-crashreporter builds.

The question is just if we should disable it based on the crashreporter setting or the ASan setting. Judging from what the test does, I'd say disable it based on the crash reporter.
Flags: needinfo?(choller)
Attached patch disable_test_process_error.patch (obsolete) — Splinter Review
Patch that disables test_process_error.xul when building without the crash reporter. Benjamin, is my judging correct here? :)
Assignee: nobody → choller
Status: NEW → ASSIGNED
Attachment #8416429 - Flags: review?(benjamin)
Thank you for the patch!

One additional thing - whilst I realise we shouldn't be running the test in the first place, given the crash reporter is disabled in ASAN builds, but shouldn't the job have been marked as a failure? We get these in "green" runs currently.
I haven't checked the test in detail but I assume it's a child that crashes and the test can deal with that in whatever way it wants to, so an orange is not guaranteed here if the test deals with this condition in some way.
Comment on attachment 8416429 [details] [diff] [review]
disable_test_process_error.patch

This test has two parts: checking to make sure that subprocess errors are handled correctly, and checking the crash reporting. The crash reporting bits obviously don't make sense when the crash reporter is disabled, but the base functionality should be checked.

The test already checks 'nsICrashReporter' in Components.interfaces. Is the ASAN build building the crash reporter but just disabling it at runtime? We might need another check for crashReporter.enabled.
Attachment #8416429 - Flags: review?(benjamin) → review-
(In reply to Benjamin Smedberg  [:bsmedberg] from comment #10)

> The test already checks 'nsICrashReporter' in Components.interfaces. Is the
> ASAN build building the crash reporter but just disabling it at runtime? We
> might need another check for crashReporter.enabled.

No, ASan builds disable the crash reporter at compile time with the respective build flag. Please let me know how we should proceed here, thanks :)
Flags: needinfo?(benjamin)
Then it appears the test harness has a bug, probably it's making incorrect assumptions about there always being a dump ID here: http://hg.mozilla.org/mozilla-central/annotate/e2e1b19fcffc/testing/specialpowers/content/SpecialPowersObserverAPI.js#l99
Flags: needinfo?(benjamin)
(In reply to Benjamin Smedberg  [:bsmedberg] from comment #12)
> Then it appears the test harness has a bug, probably it's making incorrect
> assumptions about there always being a dump ID here:
> http://hg.mozilla.org/mozilla-central/annotate/e2e1b19fcffc/testing/
> specialpowers/content/SpecialPowersObserverAPI.js#l99

Christian, I don't suppose you could drive this? :-)
Flags: needinfo?(choller)
Nope. To me it seems the test is defective, so it either needs to be fixed or disabled. I can do the disabling, but if I don't get review for that, then the author should fix the test.
Flags: needinfo?(choller)
The test is not defective. It is crashing intentionally, and this is the desired behavior of this test.
(In reply to Benjamin Smedberg  [:bsmedberg] from comment #17)
> The test is not defective. It is crashing intentionally, and this is the
> desired behavior of this test.

Do you believe the failure to be in the SpecialPowersObserverAPI or the mochitest harness?

I'm just struggling to work out who I can pester about this :-)
Flags: needinfo?(benjamin)
I already linked to the line in SpecialPowersObserverAPI which I believe is incorrect.
Flags: needinfo?(benjamin)
It wasn't clear if that was the issue, or if whatever consumed the dumpID made assumptions about it, which were untrue given the line quoted. Anyway, thank you for the clarification :-)
(In reply to Benjamin Smedberg  [:bsmedberg] from comment #10)
> This test has two parts: checking to make sure that subprocess errors are
> handled correctly, and checking the crash reporting. The crash reporting
> bits obviously don't make sense when the crash reporter is disabled, but the
> base functionality should be checked.
> 
> The test already checks 'nsICrashReporter' in Components.interfaces. Is the
> ASAN build building the crash reporter but just disabling it at runtime? We
> might need another check for crashReporter.enabled.

(In reply to Christian Holler (:decoder) from comment #11)
> No, ASan builds disable the crash reporter at compile time with the
> respective build flag. Please let me know how we should proceed here, thanks
> :)

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #12)
> Then it appears the test harness has a bug, probably it's making incorrect
> assumptions about there always being a dump ID here:
> http://hg.mozilla.org/mozilla-central/annotate/e2e1b19fcffc/testing/
> specialpowers/content/SpecialPowersObserverAPI.js#l99

Joel, hg annotate says this is your lucky day ;-)
Would you mind taking a look at this?
Flags: needinfo?(jmaher)
Assignee: choller → nobody
Status: ASSIGNED → NEW
seriously, that was 2.5 years ago :)

I just want feedback on this patch?  I can push to try if it looks right and do a bunch of reteriggers.

In fact, this error is seen in a couple of bugs:
bug 926210
bug 974759
Attachment #8420155 - Flags: feedback?(benjamin)
Flags: needinfo?(jmaher)
Attachment #8420155 - Flags: feedback?(benjamin) → feedback+
it looked like the 'oth' test was failing, I pushed to try and retriggered- it is looking green:
https://tbpl.mozilla.org/?tree=Try&rev=985d4128508c

Ed, can you comment on what was failing and if I have done enough retriggers to call this fixed?
Flags: needinfo?(emorley)
(In reply to Joel Maher (:jmaher) from comment #24)
> it looked like the 'oth' test was failing, I pushed to try and retriggered-
> it is looking green:
> https://tbpl.mozilla.org/?tree=Try&rev=985d4128508c
> 
> Ed, can you comment on what was failing and if I have done enough retriggers
> to call this fixed?

The retriggers on the try run lgtm, let's land this and we can reopen if it reoccurs :-)
Assignee: nobody → jmaher
Status: NEW → ASSIGNED
Flags: needinfo?(emorley)
Attachment #8416429 - Attachment is obsolete: true
Comment on attachment 8420155 [details] [diff] [review]
fix special powers to try/except and fail gracefully (0.9)

ted, can you check this out.  We are good on try server, this should clear up a frequent orange!
Attachment #8420155 - Flags: review?(ted)
Attachment #8420155 - Flags: review?(ted) → review+
https://hg.mozilla.org/mozilla-central/rev/40e2e7bc4f27
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla32
Looking at the log from comment 36, it looks like we hit a SEGV in a content process, and the test suite continued to run but timed out at the end. I'm not sure what would cause it to hang here, perhaps something in the IPC code is getting confused? (I'm also not sure what the right behavior is here for the test suite--should we be terminating the test run if a content process crashes unexpectedly?)
You need to log in before you can comment on or make changes to this bug.