Wasmer: Aarch64 android calling Java function in host function aborts

Created on 14 Apr 2020  ·  11Comments  ·  Source: wasmerio/wasmer

Describe the bug

I am trying to run wasmer embedded in an android app and call android app functions from WASM.
This succeeds on x86_64 emulator, but not on an ARM phone.
When an android class instance's method is being called from a host function exposed to WASM the program aborts.

rustc 1.41.1 (f3e1a954d 2020-02-24)
rustc 1.44.0-nightly (f509b26a7 2020-03-18)
x86_64

I have attached a reproduction case where there is a WASM module, an android wasmer runtime and an android project that uses the wasm module and wasmer runtime.
The application loads the wasmer runtime as a shared library. It then loads the wasm module from assets folder as byte array and calls a function of the wasmer runtime through JNI. In this call the runtime gets the module bytes, the instance of the java class and java environment.
The function will load the wasm module so it is ready to execute, shows how a test JNI call works outside of wasmer runtime, places java class and vm references to global variables and runs the wasm module.
The wasm module simply executes the Test host function (named java_test in rust) in it's main function.
The host function gets the java environment and class instance from the global variables and uses them to do a function call into Java again. This call should be the exact same as the JNI function call performed earlier.

The running of the wasm module works on x86_64, but not on a real phone using aarch64 build.
The JNI function call succeeds outside of wasmer code, but not inside the wasmer host function.

aarch64_diagram

Steps to reproduce

  1. Clone https://github.com/Rochet2/wasmer_android_jnicall_repro
    (also attached as zip: wasmer_android_jnicall_repro-master.zip)
  2. Compile and run it with the instructions in readme files
  3. See success on x86_64 and abort on aarch64 build

Expected behavior


The program runs without aborting on both x86_64 and aarch64.

Log of x86_64 succeeding (program finishes cleanly and all prints appear):

04/14 17:15:52: Launching 'app' on Pixel 2 API 29.
$ adb shell am start -n "com.wasmer.android/com.wasmer.android.MainActivity" -a android.intent.action.MAIN -c android.intent.category.LAUNCHER
Connected to process 14168 on device 'Pixel_2_API_29 [emulator-5554]'.
Capturing and displaying logcat messages from application. This behavior can be disabled in the "Logcat output" section of the "Debugger" settings page.
D/libEGL: Emulator has host GPU support, qemu.gles is set to 1.
W/libc: Unable to set property "qemu.gles" to "1": connection failed; errno=13 (Permission denied)
D/libEGL: loaded /vendor/lib64/egl/libEGL_emulation.so
D/libEGL: loaded /vendor/lib64/egl/libGLESv1_CM_emulation.so
D/libEGL: loaded /vendor/lib64/egl/libGLESv2_emulation.so
W/RenderThread: type=1400 audit(0.0:227): avc: denied { write } for name="property_service" dev="tmpfs" ino=1667 scontext=u:r:untrusted_app:s0:c136,c256,c512,c768 tcontext=u:object_r:property_socket:s0 tclass=sock_file permissive=0
W/.wasmer.androi: Accessing hidden method Landroid/view/View;->computeFitSystemWindows(Landroid/graphics/Rect;Landroid/graphics/Rect;)Z (greylist, reflection, allowed)
W/.wasmer.androi: Accessing hidden method Landroid/view/ViewGroup;->makeOptionalFitsSystemWindows()V (greylist, reflection, allowed)
I/System.out: Calling JNIExecuteWasm!
I/System.out: Test was called from WASM!
I/chatty: uid=10136(com.wasmer.android) identical 1 line
I/System.out: Test was called from WASM!
    Finished calling JNIExecuteWasm!
    Finished program!
D/HostConnection: HostConnection::get() New Host Connection established 0x719255ae7fe0, tid 14199
D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_YUV420_888_to_NV21 ANDROID_EMU_YUV_Cache ANDROID_EMU_async_unmap_buffer GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_gles_max_version_2 
W/OpenGLRenderer: Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without...
D/eglCodecCommon: setVertexArrayObject: set vao to 0 (0) 0 0
D/EGL_emulation: eglCreateContext: 0x719255ae81c0: maj 2 min 0 rcv 2
D/EGL_emulation: eglMakeCurrent: 0x719255ae81c0: ver 2 0 (tinfo 0x7192e6fc2b20)
W/Gralloc3: mapper 3.x is not supported
D/HostConnection: createUnique: call
    HostConnection::get() New Host Connection established 0x719255ae8300, tid 14199
D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_YUV420_888_to_NV21 ANDROID_EMU_YUV_Cache ANDROID_EMU_async_unmap_buffer GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_gles_max_version_2 
D/eglCodecCommon: allocate: Ask for block of size 0x1000
    allocate: ioctl allocate returned offset 0x3ff803000 size 0x2000
D/EGL_emulation: eglMakeCurrent: 0x719255ae81c0: ver 2 0 (tinfo 0x7192e6fc2b20)
D/eglCodecCommon: setVertexArrayObject: set vao to 0 (0) 1 0

Actual behavior


The program works on x86_64, but aborts during a JNI call in a host function on aarch64.

Log of aarch64 failing (last 3 lines show how the call aborted):

04/14 17:16:44: Launching 'app' on HUAWEI ELE-L29.
$ adb shell am start -n "com.wasmer.android/com.wasmer.android.MainActivity" -a android.intent.action.MAIN -c android.intent.category.LAUNCHER
Connected to process 20190 on device 'huawei-ele_l29-XPH0219A31006737'.
Capturing and displaying logcat messages from application. This behavior can be disabled in the "Logcat output" section of the "Debugger" settings page.
I/.wasmer.androi: Late-enabling -Xcheck:jni
E/.wasmer.androi: Unknown bits set in runtime_flags: 0x8000
I/.wasmer.androi: Reinit property: dalvik.vm.checkjni= false
D/ActivityThread: Attach thread to application
I/.wasmer.androi: QarthPatchMonintor::Init
    QarthPatchMonintor::StartWatch
I/.wasmer.androi: QarthPatchMonintor::WatchPackage: /data/hotpatch/fwkhotpatch/
    QarthPatchMonintor::CheckAndWatchPatch: /data/hotpatch/fwkhotpatch/com.wasmer.android
    QarthPatchMonintor::CheckAndWatchPatch: /data/hotpatch/fwkhotpatch/all
    QarthPatchMonintor::Run
I/.wasmer.androi: QarthPatchMonintor::Reading
    QarthPatchMonintor::CheckNotifyEvent
    QarthPatchMonintor::CheckNotifyEvent before read
I/HwApiCacheMangerEx: apicache path=/storage/emulated/0 state=mounted key=com.wasmer.android#10233#256
I/HwApiCacheMangerEx: apicache path=/storage/emulated/0 state=mounted key=com.wasmer.android#10233#0
I/AwareBitmapCacher: init processName:com.wasmer.android pid=20190 uid=10233
E/AwareLog: AtomicFileUtils: readFileLines file not exist: android.util.AtomicFile@baf548f
E/AwareLog: AtomicFileUtils: readFileLines file not exist: android.util.AtomicFile@b04c31c
V/ActivityThread: callActivityOnCreate
V/HwWidgetFactory: : successes to get AllImpl object and return....
I/OverScrollerOptimization: start init SmartSlideOverScroller and get the overscroller config
    get the overscroller config
I/AwareAppScheduleManager: post cache drawable res id to aware, resId = 17302090, packagename = com.wasmer.android, cost time = 9693229
W/.wasmer.androi: Accessing hidden method Landroid/view/View;->computeFitSystemWindows(Landroid/graphics/Rect;Landroid/graphics/Rect;)Z (greylist, reflection, allowed)
W/.wasmer.androi: Accessing hidden method Landroid/view/ViewGroup;->makeOptionalFitsSystemWindows()V (greylist, reflection, allowed)
D/: [ZeroHung]zrhung_send_event: wp = 257, ret = 0
I/System.out: Calling JNIExecuteWasm!
I/System.out: Test was called from WASM!
A/libc: Fatal signal 6 (SIGABRT), code -1 (SI_QUEUE) in tid 20190 (.wasmer.android), pid 20190 (.wasmer.android)

Additional context


Pretty new to android, JNI and wasm so it is entirely possible I have a simple logical error in my code. However the code working on x86_64 suggests that might not be the case.
Unsure if this is an issue in my code, JNI code or wasmer code, but it only appears in wasmer host function.

🐞 bug 🕵️ needs investigation
Source
picture Rochet2

Most helpful comment

Have you enabled logging with android_logger and hook on panic? That will show the error in details.

Here are the related codes in my app:

picture igrep on 15 Apr 2020
❤2

All 11 comments

Have you enabled logging with android_logger and hook on panic? That will show the error in details.

Here are the related codes in my app:

igrep picture igrep on 15 Apr 2020
❤2

Couldnt get your panic to work quite the same due to various compilation errors.
Edit: got it working, but it had no difference in the log.

However with the following changes that I made to logging branch of the repro repo: https://github.com/Rochet2/wasmer_android_jnicall_repro/commit/6a8de4eda2f5fdc41a6ed832de805655e696780e

I get the following log:


04/15 13:27:09: Launching 'app' on HUAWEI ELE-L29.
$ adb shell am start -n "com.wasmer.android/com.wasmer.android.MainActivity" -a android.intent.action.MAIN -c android.intent.category.LAUNCHER
Connected to process 32267 on device 'huawei-ele_l29-XPH0219A31006737'.
Capturing and displaying logcat messages from application. This behavior can be disabled in the "Logcat output" section of the "Debugger" settings page.
I/.wasmer.androi: Late-enabling -Xcheck:jni
E/.wasmer.androi: Unknown bits set in runtime_flags: 0x8000
I/.wasmer.androi: Reinit property: dalvik.vm.checkjni= false
D/ActivityThread: Attach thread to application
I/.wasmer.androi: QarthPatchMonintor::Init
    QarthPatchMonintor::StartWatch
I/.wasmer.androi: QarthPatchMonintor::WatchPackage: /data/hotpatch/fwkhotpatch/
    QarthPatchMonintor::CheckAndWatchPatch: /data/hotpatch/fwkhotpatch/com.wasmer.android
    QarthPatchMonintor::CheckAndWatchPatch: /data/hotpatch/fwkhotpatch/all
    QarthPatchMonintor::Run
I/.wasmer.androi: QarthPatchMonintor::Reading
    QarthPatchMonintor::CheckNotifyEvent
    QarthPatchMonintor::CheckNotifyEvent before read
I/HwApiCacheMangerEx: apicache path=/storage/emulated/0 state=mounted key=com.wasmer.android#10233#256
I/HwApiCacheMangerEx: apicache path=/storage/emulated/0 state=mounted key=com.wasmer.android#10233#0
I/AwareBitmapCacher: init processName:com.wasmer.android pid=32267 uid=10233
E/AwareLog: AtomicFileUtils: readFileLines file not exist: android.util.AtomicFile@5e6f4fa
V/ActivityThread: callActivityOnCreate
V/HwWidgetFactory: : successes to get AllImpl object and return....
I/OverScrollerOptimization: start init SmartSlideOverScroller and get the overscroller config
    get the overscroller config
W/.wasmer.androi: Accessing hidden method Landroid/view/View;->computeFitSystemWindows(Landroid/graphics/Rect;Landroid/graphics/Rect;)Z (greylist, reflection, allowed)
W/.wasmer.androi: Accessing hidden method Landroid/view/ViewGroup;->makeOptionalFitsSystemWindows()V (greylist, reflection, allowed)
D/: [ZeroHung]zrhung_send_event: wp = 257, ret = 0
I/System.out: Calling JNIExecuteWasm!
V/jni::wrapper::jnienv: calling checked jni method: GetArrayLength
    looking up jni method GetArrayLength
    found jni method
    checking for exception
    calling unchecked jni method: ExceptionCheck
    looking up jni method ExceptionCheck
V/jni::wrapper::jnienv: found jni method
    no exception found
    calling unchecked jni method: GetByteArrayRegion
    looking up jni method GetByteArrayRegion
    found jni method
V/jni::wrapper::jnienv: calling unchecked jni method: NewGlobalRef
    looking up jni method NewGlobalRef
    found jni method
    calling unchecked jni method: GetJavaVM
    looking up jni method GetJavaVM
    found jni method
    calling unchecked jni method: GetJavaVM
    looking up jni method GetJavaVM
    found jni method
V/jni::wrapper::java_vm..: calling unchecked JavaVM method: GetEnv
    looking up JavaVM method GetEnv
    found JavaVM method
V/jni::wrapper::jnienv: calling unchecked jni method: GetObjectClass
    looking up jni method GetObjectClass
    found jni method
V/jni::wrapper::jnienv: calling checked jni method: GetMethodID
    looking up jni method GetMethodID
    found jni method
    checking for exception
    calling unchecked jni method: ExceptionCheck
    looking up jni method ExceptionCheck
    found jni method
    no exception found
    calling checked jni method: CallVoidMethodA
    looking up jni method CallVoidMethodA
    found jni method
I/System.out: Test was called from WASM!
V/jni::wrapper::jnienv: checking for exception
    calling unchecked jni method: ExceptionCheck
    looking up jni method ExceptionCheck
    found jni method
    no exception found
    calling unchecked jni method: DeleteLocalRef
    looking up jni method DeleteLocalRef
    found jni method
V/jni::wrapper::java_vm..: calling unchecked JavaVM method: GetEnv
    looking up JavaVM method GetEnv
    found JavaVM method
V/jni::wrapper::jnienv: calling unchecked jni method: GetObjectClass
    looking up jni method GetObjectClass
    found jni method
    calling checked jni method: GetMethodID
    looking up jni method GetMethodID
    found jni method
    checking for exception
    calling unchecked jni method: ExceptionCheck
    looking up jni method ExceptionCheck
    found jni method
    no exception found
    calling checked jni method: CallVoidMethodA
    looking up jni method CallVoidMethodA
    found jni method
I/System.out: Test was called from WASM!
V/jni::wrapper::jnienv: checking for exception
    calling unchecked jni method: ExceptionCheck
    looking up jni method ExceptionCheck
    found jni method
    no exception found
    calling unchecked jni method: DeleteLocalRef
    looking up jni method DeleteLocalRef
    found jni method
V/jni::wrapper::java_vm..: calling unchecked JavaVM method: GetEnv
    looking up JavaVM method GetEnv
    found JavaVM method
V/jni::wrapper::jnienv: calling unchecked jni method: GetObjectClass
    looking up jni method GetObjectClass
    found jni method
    calling checked jni method: GetMethodID
    looking up jni method GetMethodID
    found jni method
    checking for exception
    calling unchecked jni method: ExceptionCheck
    looking up jni method ExceptionCheck
    found jni method
    no exception found
    calling checked jni method: CallVoidMethodA
    looking up jni method CallVoidMethodA
    found jni method
    checking for exception
    calling unchecked jni method: ExceptionCheck
    looking up jni method ExceptionCheck
    found jni method
    exception found, returning error
V/jni::wrapper::jnienv: calling unchecked jni method: DeleteLocalRef
    looking up jni method DeleteLocalRef
    found jni method
E/wasmer_android: ERR: panicked at 'called `Result::unwrap()` on an `Err` value: Error(JavaException, State { next_error: None, backtrace: InternalBacktrace })', src/lib.rs:85:5
E/wasmer_android: ERR: panicked at 'called `Result::unwrap()` on an `Err` value: RuntimeError: "called `Result::unwrap()` on an `Err` value: Error(JavaException, State { next_error: None, backtrace: InternalBacktrace })"', src/lib.rs:51:5
A/libc: Fatal signal 6 (SIGABRT), code -1 (SI_QUEUE) in tid 32267 (.wasmer.android), pid 32267 (.wasmer.android)

In the log we can see that the two function calls before entering WASM work and print Test was called from WASM!
However the third print done from the host function fails. The function is the same and uses same variables.
The error messages about unwrap occur due to java exception that occurs during the function call - even if the call should be identical to the ones that succeeded.

src/lib.rs:85 is
https://github.com/Rochet2/wasmer_android_jnicall_repro/blob/6a8de4eda2f5fdc41a6ed832de805655e696780e/android_runtime/src/lib.rs#L85-L86

and src/lib.rs:51 is
https://github.com/Rochet2/wasmer_android_jnicall_repro/blob/6a8de4eda2f5fdc41a6ed832de805655e696780e/android_runtime/src/lib.rs#L51

Rochet2 picture Rochet2 on 15 Apr 2020

From the above log we can see that the succeeding and failing calls have identical apart from failing call getting some exception in the middle of the call and never printing.

Here is a diff of a successful call (success.log) and the failing call (fail.log) showing how they look the same in the log apart from an exception that seems to occur during the call from host function:

--- success.log 2020-04-15 13:52:39.813318990 +0300
+++ fail.log    2020-04-15 13:52:49.757414699 +0300
@@ -15,12 +15,12 @@
     calling checked jni method: CallVoidMethodA
     looking up jni method CallVoidMethodA
     found jni method
-I/System.out: Test was called from WASM!
     checking for exception
     calling unchecked jni method: ExceptionCheck
     looking up jni method ExceptionCheck
     found jni method
-    no exception found
+    exception found, returning error
     calling unchecked jni method: DeleteLocalRef
     looking up jni method DeleteLocalRef
     found jni method
+E/wasmer_android: ERR: panicked at 'called `Result::unwrap()` on an `Err` value: Error(JavaException, State { next_error: None, backtrace: InternalBacktrace })', src/lib.rs:85:5
Rochet2 picture Rochet2 on 15 Apr 2020

You can throw the exception from Rust code by JNIEnv::throw.
And I made this patch to use it to see the exception because I'm also very interested in this issue!

Now, the log message reports an error exactly same with https://github.com/iij-ii/wasmonandroid/issues/1: StackOverflowError occurred.
Extracted from the log:

...
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: found jni method
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: exception found, returning error
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: calling unchecked jni method: DeleteLocalRef
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: looking up jni method DeleteLocalRef
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: found jni method
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: calling unchecked jni method: ExceptionOccurred
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: looking up jni method ExceptionOccurred
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: found jni method
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: calling unchecked jni method: Throw
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: looking up jni method Throw
2020-04-16 16:17:28.950 23545-23545/com.wasmer.android V/jni::wrapper::jnienv: found jni method
2020-04-16 16:17:29.114 23545-23545/com.wasmer.android A/.wasmer.androi: java_vm_ext.cc:561] JNI DETECTED ERROR IN APPLICATION: JNI Throw called with pending exception java.lang.StackOverflowError: stack size 8MB
2020-04-16 16:17:29.114 23545-23545/com.wasmer.android A/.wasmer.androi: java_vm_ext.cc:561]   at void com.wasmer.android.MainActivity.JNIExecuteWasm(com.wasmer.android.MainActivity, byte[]) (MainActivity.java:-2)
...
igrep picture igrep on 16 Apr 2020
👍1

As written in https://github.com/iij-ii/wasmonandroid/issues/1, I thought this was because my code consumes stack too much until getting this issue.
Now I suspect this is a problem of wasmer.

@MarkMcCaskey
Any ideas of why wasmer consumes the stack too much?

igrep picture igrep on 16 Apr 2020

Sorry, this can be a known issue of Android, according to https://stackoverflow.com/questions/27223005/unable-to-make-jni-call-from-c-to-java-in-android-lollipop-using-jni and https://issuetracker.google.com/issues/37035211.

igrep picture igrep on 16 Apr 2020
👀1

Progress report of debugging: To show log while running wasmer, I switched the logger to write on the application data: https://github.com/igrep/wasmer_android_jnicall_repro/commit/6387f88f57a3e1b61516a302931ace71d8fef5ad

Now, we can see the log written by libwasmer_android.so with this command after running the app:

adb shell run-as com.wasmer.android cat files/wasmer_android.log

I'm going to add debug codes to wasmer from now on.

igrep picture igrep on 17 Apr 2020
❤1

Progress report:

I tried two ways to fix after adding loggings:

igrep picture igrep on 20 Apr 2020

A bit out of my expertise, but based on the comments in the threads you linked earlier and based on

I would say that the native function call should be moved to some other context which is outside of this signal handling if possible - if that indeed is the reason for the issue.
Creating new threads is not a proper solution and some of the posts hint that it would still be wrong to do so even if it worked as it is fundamentally wrong place to call a function anyways. Though maybe doing so can help debugging.

There must be something that wasmer does to create this situation where it is not possible to call java as the java calls normally work outside of wasmer. Relocating the native call to outside of that or removing the error creating code or correcting it if done wrong would be the solution in my mind.

ps. really nice stuff here. definitely taking some of this logging and error handling to use.

Rochet2 picture Rochet2 on 20 Apr 2020

Thanks for figuring this out! It looks like our signal handling code is not built to be used outside of a wasm context.

I'm not familiar with the details here at all, but it seems highly plausible that the signal handling of Wasmer and the Android runtime could be interacting poorly.

This seems like a problem that would show up in quite a few places actually, I'm not sure what the standard solutions are for conflicting signal handling code... I'll look into this later if I have the bandwidth and post any ideas I have!

MarkMcCaskey picture MarkMcCaskey on 20 Apr 2020
👍1

After browsing the source code of Android and wasmer, I suspect this is just because wasmer alters sp to point at mmaped area in AArch64, while doesn't do that in x86_64, if I read the assembly correctly.
Some very plausibly named method validates the stack frame to throw a StackOverflowError if invalid. And there are several other lines like that.
I guess the error is caused by the guard.

Now, I'm interested in why the singlepass backend for AArch64 is implemented in such a way, and how to fix it?

igrep picture igrep on 27 Apr 2020
👀2
Was this page helpful?
0 / 5 - 0 ratings

Related issues

repi picture repi  ·  3Comments
MaxGraey picture MaxGraey  ·  3Comments
RReverser picture RReverser  ·  4Comments
robinvanemden picture robinvanemden  ·  4Comments
hrydgard picture hrydgard  ·  4Comments