Closed Bug 1716205 Opened 3 years ago Closed 1 year ago

Intermittent Android toolkit/components/extensions/test/xpcshell/webidl-api/test_ext_webidl_api.js | application crashed [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)]

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(firefox-esr78 unaffected, firefox89 unaffected, firefox90 unaffected, firefox91 wontfix)

RESOLVED INCOMPLETE
Tracking Status
firefox-esr78 --- unaffected
firefox89 --- unaffected
firefox90 --- unaffected
firefox91 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: crash, intermittent-failure, regression)

Crash Data

Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=342622093&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Bz2RFY_RSl2QwHia8YRe4g/runs/1/artifacts/public/logs/live_backing.log


INFO -  TEST-START | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_manifest_incognito.js
[task 2021-06-13T11:32:00.066Z] 11:32:00     INFO -  remotexpcshelltests.py | Launched Test App PID=29448
[task 2021-06-13T11:32:00.085Z] 11:32:00     INFO -  adb launch_application: am startservice -W -n 'org.mozilla.geckoview.test/org.mozilla.geckoview.test.XpcshellTestRunnerService$i2' -a android.intent.action.MAIN --es arg8 'const _MOZINFO_JS_PATH = "/data/local/tmp/test_root/xpc/p/89506036-146a-4a41-a4ae-b4c2fdedb7d4/mozinfo.json";' --es arg9 -e --es arg0 -g --es arg1 /data/local/tmp/test_root/xpcb --es arg2 --greomni --es arg3 /data/local/tmp/test_root/xpcb/geckoview-androidTest.apk --es arg4 -m --es arg5 -e --es arg6 'const _HEAD_JS_PATH = "/data/local/tmp/test_root/xpc/head.js";' --es arg7 -e --es arg26 '_execute_test(); quit(0);' --es arg25 -e --es arg24 'const _TEST_NAME = "xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_manifest_incognito.js";' --es arg23 -e --es arg22 'const _TEST_FILE = ["test_ext_manifest_incognito.js"];' --es arg21 -e --es arg20 'const _TEST_CWD = "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell";' --ez use_multiprocess True --es arg12 'const _TESTING_MODULES_DIR = "/data/local/tmp/test_root/xpc/m";' --es arg13 -f --es arg10 'const _PREFS_FILE = "/data/local/tmp/test_root/xpc/tmp/f3409a07-e724-4aad-8683-0b8021875398/user.js";' --es arg11 -e --es arg16 'const _HEAD_FILES = ["/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_telemetry.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_sync.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_storage.js"];' --es arg17 -e --es arg14 /data/local/tmp/test_root/xpc/head.js --es arg15 -e --es arg18 'const _JSDEBUGGER_PORT = 0;' --es arg19 -e --es env9 MOZ_DISABLE_SOCKET_PROCESS=1 --es env8 MOZHTTP2_PORT=45241 --es out_file /data/local/tmp/test_root/xpc/logs/xpcshell-6eb88f97-6869-4c16-8432-abac8135810b.log --es env3 XPCSHELL_MINIDUMP_DIR=/data/local/tmp/test_root/xpc/minidumps/89506036-146a-4a41-a4ae-b4c2fdedb7d4 --es env2 XPCOM_DEBUG_BREAK=stack-and-abort --es env1 MOZ_WEBRENDER=0 --es env0 MOZ_CRASHREPORTER=1 --es env7 GRE_HOME=/data/local/tmp/test_root/xpcb --es env6 MOZ_ANDROID_DATA_DIR=/data/local/tmp/test_root/xpcb --es env5 XPCSHELL_TEST_TEMP_DIR=/data/local/tmp/test_root/xpc/tmp/f3409a07-e724-4aad-8683-0b8021875398 --es env4 MOZ_DISABLE_CONTENT_SANDBOX=1 --es env19 TMPDIR=/data/local/tmp/test_root/xpc/p/89506036-146a-4a41-a4ae-b4c2fdedb7d4 --es env18 MOZ_ANDROID_CPU_ABI=x86_64 --es env17 HOME=/data/local/tmp/test_root/xpc/p --es env16 MOZ_LINKER_CACHE=/data/local/tmp/test_root/xpcb --es env15 MOZ_DEVELOPER_REPO_DIR=/builds/worker/checkouts/gecko --es env14 MOZ_CRASHREPORTER_NO_REPORT=1 --es env13 MOZNODE_EXEC_PORT=37457 --es env12 XPCSHELL_TEST_PROFILE_DIR=/data/local/tmp/test_root/xpc/p/89506036-146a-4a41-a4ae-b4c2fdedb7d4 --es env11 LD_LIBRARY_PATH=/data/local/tmp/test_root/xpcb --es env10 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1
[task 2021-06-13T11:32:00.303Z] 11:32:00     INFO -  remotexpcshelltests.py | Launched Test App PID=29539
[task 2021-06-13T11:32:00.642Z] 11:32:00     INFO -  remotexpcshelltests.py | Application ran for: 0:00:01.294384
[task 2021-06-13T11:32:00.728Z] 11:32:00     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_json_parser.js | took 1381ms
[task 2021-06-13T11:32:00.835Z] 11:32:00     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_json_parser.js folder: /data/local/tmp/test_root/xpc/p/7a38c418-ce17-47c1-894e-34d62a6a9e94
[task 2021-06-13T11:32:01.069Z] 11:32:01     INFO -  remotexpcshelltests.py | Application ran for: 0:00:01.271607
[task 2021-06-13T11:32:01.165Z] 11:32:01     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_manifest_content_security_policy.js | took 1368ms
[task 2021-06-13T11:32:01.276Z] 11:32:01     INFO -  mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/7e295379-864e-77f4-2ec7-ff67aa66e557.dmp
[task 2021-06-13T11:32:01.276Z] 11:32:01     INFO -  mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/7e295379-864e-77f4-2ec7-ff67aa66e557.extra
[task 2021-06-13T11:32:01.283Z] 11:32:01  WARNING -  PROCESS-CRASH | toolkit/components/extensions/test/xpcshell/webidl-api/test_ext_webidl_api.js | application crashed [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)]
[task 2021-06-13T11:32:01.283Z] 11:32:01     INFO -  Mozilla crash reason: MOZ_CRASH()
[task 2021-06-13T11:32:01.283Z] 11:32:01     INFO -  Crash dump filename: /tmp/tmp1iV48F/7e295379-864e-77f4-2ec7-ff67aa66e557.dmp
[task 2021-06-13T11:32:01.283Z] 11:32:01     INFO -  Operating system: Android
[task 2021-06-13T11:32:01.283Z] 11:32:01     INFO -                    0.0.0 Linux 3.10.0+ #260 SMP PREEMPT Fri May 19 12:48:14 PDT 2017 x86_64
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -  CPU: amd64
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -       family 6 model 6 stepping 3
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -       4 CPUs
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -  GPU: UNKNOWN
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -  Crash reason:  SIGSEGV /SEGV_MAPERR
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -  Crash address: 0x0
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -  Process uptime: not available
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -  Thread 5 (crashed)
[task 2021-06-13T11:32:01.284Z] 11:32:01     INFO -   0  libmozglue.so!mozalloc_abort [mozalloc_abort.cpp:1d869c7669e62b7e5d7ccb359dfd7284051c078b : 33 + 0x16]
[task 2021-06-13T11:32:01.285Z] 11:32:01     INFO -      rax = 0x0000700c05863e2c   rdx = 0x0000000000000004
[task 2021-06-13T11:32:01.285Z] 11:32:01     INFO -      rcx = 0x0000700c05ac6c38   rbx = 0x0000700c1e810680
[task 2021-06-13T11:32:01.285Z] 11:32:01     INFO -      rsi = 0x0000700c1e80ff50   rdi = 0x000000000000001b
[task 2021-06-13T11:32:01.285Z] 11:32:01     INFO -      rbp = 0x0000700c1e810610   rsp = 0x0000700c1e810600
[task 2021-06-13T11:32:01.285Z] 11:32:01     INFO -       r8 = 0x0000000000000000    r9 = 0x0000700c23e83090
[task 2021-06-13T11:32:01.285Z] 11:32:01     INFO -      r10 = 0x0000000000000019   r11 = 0x0000000000000246
[task 2021-06-13T11:32:01.285Z] 11:32:01     INFO -      r12 = 0x0000700c023b0e9f   r13 = 0x0000700c01077cea
[task 2021-06-13T11:32:01.286Z] 11:32:01     INFO -      r14 = 0x0000700c1e810680   r15 = 0x0000000000000000
[task 2021-06-13T11:32:01.286Z] 11:32:01     INFO -      rip = 0x0000700c0578f1fc
INFO -      Found by: given as instruction pointer in context
[task 2021-06-13T11:32:01.286Z] 11:32:01     INFO -   1  libxul.so!Abort(char const*) [nsDebugImpl.cpp:1d869c7669e62b7e5d7ccb359dfd7284051c078b : 452 + 0x8]
[task 2021-06-13T11:32:01.286Z] 11:32:01     INFO -      rbp = 0x0000700c1e810630   rsp = 0x0000700c1e810620
[task 2021-06-13T11:32:01.286Z] 11:32:01     INFO -      rip = 0x0000700bfb127300
[task 2021-06-13T11:32:01.286Z] 11:32:01     INFO -      Found by: previous frame's frame pointer
[task 2021-06-13T11:32:01.287Z] 11:32:01     INFO -   2  libxul.so!NS_DebugBreak [nsDebugImpl.cpp:1d869c7669e62b7e5d7ccb359dfd7284051c078b : 401 + 0x25]
[task 2021-06-13T11:32:01.287Z] 11:32:01     INFO -      rbp = 0x0000700c1e810cc0   rsp = 0x0000700c1e810640
[task 2021-06-13T11:32:01.287Z] 11:32:01     INFO -      rip = 0x0000700bfb12711f
[task 2021-06-13T11:32:01.287Z] 11:32:01     INFO -      Found by: previous frame's frame pointer
[task 2021-06-13T11:32:01.287Z] 11:32:01     INFO -   3  libxul.so!NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int) [nsThreadUtils.cpp:1d869c7669e62b7e5d7ccb359dfd7284051c078b : 267 + 0x23]
[task 2021-06-13T11:32:01.287Z] 11:32:01     INFO -      rbp = 0x0000700c1e810d10   rsp = 0x0000700c1e810cd0
[task 2021-06-13T11:32:01.287Z] 11:32:01     INFO -      rip = 0x0000700bfb20b07c
[task 2021-06-13T11:32:01.288Z] 11:32:01     INFO -      Found by: previous frame's frame pointer
[task 2021-06-13T11:32:01.288Z] 11:32:01     INFO -   4  libxul.so!std::__ndk1::enable_if<(mozilla::java::EventDispatcher::NativeCallbackDelegate::Finalize_t::dispatchTarget)==((mozilla::jni::DispatchTarget)2), void>::type mozilla::jni::detail::Dispatcher<mozilla::widget::detail::NativeCallbackDelegateSupport, false, mozilla::jni::LocalRef<mozilla::java::EventDispatcher::NativeCallbackDelegate> const&>::Run<mozilla::java::EventDispatcher::NativeCallbackDelegate::Finalize_t, true, std::nullptr_t, void (*)(mozilla::jni::LocalRef<mozilla::java::EventDispatcher::NativeCallbackDelegate> const&), _JNIEnv*&, _jobject*&>(std::nullptr_t, void (*&&)(mozilla::jni::LocalRef<mozilla::java::EventDispatcher::NativeCallbackDelegate> const&), _JNIEnv*&, _jobject*&) [Natives.h:1d869c7669e62b7e5d7ccb359dfd7284051c078b : 1328 + 0xa]
[task 2021-06-13T11:32:01.288Z] 11:32:01     INFO -      rbp = 0x0000700c1e810d70   rsp = 0x0000700c1e810d20
[task 2021-06-13T11:32:01.289Z] 11:32:01     INFO -      rip = 0x0000700bfdc56aec
[task 2021-06-13T11:32:01.289Z] 11:32:01     INFO -      Found by: previous frame's frame pointer
[task 2021-06-13T11:32:01.289Z] 11:32:01     INFO -   5  libxul.so!void mozilla::jni::NativeStub<mozilla::java::EventDispatcher::NativeCallbackDelegate::Finalize_t, mozilla::widget::detail::NativeCallbackDelegateSupport, mozilla::jni::Args<> >::Wrap<&mozilla::widget::detail::NativeCallbackDelegateSupport(mozilla::jni::LocalRef<mozilla::java::EventDispatcher::NativeCallbackDelegate> const&)::Finalize>(_JNIEnv*, _jobject*) [Natives.h:1d869c7669e62b7e5d7ccb359dfd7284051c078b : 1480 + 0x7]
[task 2021-06-13T11:32:01.289Z] 11:32:01     INFO -      rbp = 0x0000700c1e810da0   rsp = 0x0000700c1e810d80
[task 2021-06-13T11:32:01.289Z] 11:32:01     INFO -      rip = 0x0000700bfdc5698a
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -      Found by: previous frame's frame pointer
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -   6  libxul.so + 0x3bdca64
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -      rbp = 0x0000700c1e810da0   rsp = 0x0000700c1e810d88
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -      rip = 0x0000700bfdc56a64
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -      Found by: stack scanning
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -   7  system@framework@boot-core-libart.art + 0xb6e0
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -      rsp = 0x0000700c1e810da8   rip = 0x00000000710976e0
[task 2021-06-13T11:32:01.290Z] 11:32:01     INFO -      Found by: stack scanning
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -   8  base.odex + 0xca5ad2
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -      rsp = 0x0000700c1e810db0   rip = 0x0000700c07073ad2
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -      Found by: stack scanning
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -   9  dalvik-main space 1 (deleted) + 0x33858
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -      rsp = 0x0000700c1e810dc0   rip = 0x0000000036c33858
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -      Found by: stack scanning
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -  10  dalvik-LinearAlloc (deleted) + 0x3060
[task 2021-06-13T11:32:01.291Z] 11:32:01     INFO -      rsp = 0x0000700c1e810dc8   rip = 0x0000700c17ac5060
[task 2021-06-13T11:32:01.292Z] 11:32:01     INFO -      Found by: stack scanning
<...>

Flags: needinfo?(lgreco)
Keywords: regression
Regressed by: 1682632
Summary: Intermittent toolkit/components/extensions/test/xpcshell/webidl-api/test_ext_webidl_api.js | application crashed [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)] → Intermittent Android toolkit/components/extensions/test/xpcshell/webidl-api/test_ext_webidl_api.js | application crashed [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)]
Has Regression Range: --- → yes

I did notice the same kind of failure in Bug 1684094 comment 10 and looking into it.

I'm currently unable to reproduce the same issue locally, and so I looked a bit more closely into the logs collected from the failures on try and I did notice that in all the ones I looked there is the following logs on the logcat side (in particular these logs are coming from this one, linked to this tree herder job):

06-13 11:30:28.739 28589 28598 I Gecko   : [Parent 28589, Unnamed thread 7bab4949ccd0] WARNING: Called GetMainThread but there isn't a main thread and we're not the main thread.: file /builds/worker/checkouts/gecko/xpcom/threads/nsThreadManager.cpp:615
06-13 11:30:28.739 28589 28598 I Gecko   : [Parent 28589, Unnamed thread 7bab4949ccd0] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:266
06-13 11:30:28.739 28589 28598 I Gecko   : [Parent 28589, Unnamed thread 7bab4949ccd0] ###!!! ASSERTION: Failed NS_DispatchToMainThread() in shutdown; leaking: 'false', file /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:268
06-13 11:30:28.741 28589 28598 E Gecko   : mozalloc_abort: [Parent 28589, Unnamed thread 7bab4949ccd0] ###!!! ASSERTION: Failed NS_DispatchToMainThread() in shutdown; leaking: 'false', file /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:268
06-13 11:30:28.741 28589 28598 F MOZ_CRASH: Hit MOZ_CRASH() at /builds/worker/checkouts/gecko/memory/mozalloc/mozalloc_abort.cpp:33

If I'm reading the logs correctly, it seems to be actually happening when the actual test tasks were all execute and the test file should be exiting.

And so I'm wondering if the java side of GeckoView service that starts the xpcshell test process may be trying to dispatch an event exactly while the xpcshell process is already in the process of shutting down (and got past the xpcom shutdown phase), as the stack trace from the crash seems to suggest if I'm not mistaken:

1  libxul.so!Abort(char const*) [nsDebugImpl.cpp]
2  libxul.so!NS_DebugBreak [nsDebugImpl.cpp]
3  libxul.so!NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int) [nsThreadUtils.cpp]
4  libxul.so!std::__ndk1::enable_if<(mozilla::java::EventDispatcher::NativeCallbackDelegate::Finalize_t::dispatchTarget)...[Natives.h]
5  libxul.so!void mozilla::jni::NativeStub<mozilla::java::EventDispatcher::NativeCallbackDelegate::Finalize_t... [Natives.h]
Flags: needinfo?(lgreco)

hey Agi,
what do you think about the rationale in comment 3? does it look like a possible scenario?

In addition, I was also wondering:

  • do you recall any similar intermittent or test failure happening in other xpcshell test running on Android?
  • is there a way to ask the java side to log the events that is going to dispatch before it does dispatch them to the Gecko?
    (i'm looking for some other way to get some more details useful for investigating this failures from a push to try, given that at the moment I'm not yet able to reproduce the same issue locally)
Flags: needinfo?(agi)

Hi Luca! I have seen this problem while developing but I thought I had fixed it before I landed the xpcshell patches.

From what I can see the error went away? Maybe it's an unrelated problem that got fixed/backed out?

Flags: needinfo?(agi)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #5)

Hi Luca! I have seen this problem while developing but I thought I had fixed it before I landed the xpcshell patches.

From what I can see the error went away? Maybe it's an unrelated problem that got fixed/backed out?

Apparently this one didn't reproduce again over the last few days, but another test file in the same group of tests seems to still be able to trigger the same conditions (at least based on the stack trace and messages logged in logcat, which looks the same I did mention in comment 3 for this one) from time to time: Bug 1716308

Crash Signature: [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)] → [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)] [@ nsDebugImpl::Abort(char const*, int)]

Linking some seemingly related failures, even though their reports were almost 1 year old - all Android in the webidl tests with similar stack traces.

Crash Signature: [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)] [@ nsDebugImpl::Abort(char const*, int)] → [@ NS_DispatchToMainThread(already_AddRefed<nsIRunnable>&&, unsigned int)] [@ nsDebugImpl::Abort(char const*, int)]
Priority: -- → P5
See Also: → 1735403, 1721770
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.