CRASH and APP CRASH running Java apps on Android

[derekbruening]

After fixing config dir issues in DynamoRIO/drmemory#1857, we are able to try to run Java apps. I tried both Chrome and calculator and both failed early in similar ways.

In DR release we see a DR crash:

03-25 15:58:52.666  8280  8280 I wrap.sh : <Application /system/bin/app_process32 (8281).  DynamoRIO internal crash at PC 0xb6f31f6c.  Please report this at http://dynamorio.org/issues/.  Program aborted.
03-25 15:58:52.666  8280  8280 I wrap.sh : Received SIGSEGV at pc 0xb6f31f6c in thread 8281
03-25 15:58:52.666  8280  8280 I wrap.sh : Base: 0xb6e4f000
03-25 15:58:52.666  8280  8280 I wrap.sh : Registers:  r0 =0x00000000 r1 =0x7138e0bc r2 =0x00000000 r3 =0x00000000
03-25 15:58:52.666  8280  8280 I wrap.sh :  r4 =0x74952000 r5 =0x54fc0b64 r6 =0x7138e000 r7 =0x00000000
03-25 15:58:52.666  8280  8280 I wrap.sh :  r8 =0x54f05a20 r9 =0x7138e000

> cd /work/drmemory/releases/DrMemory-ARM-Android-EABI-1.10.0-2
> ../DrMemory-Linux-1.10.0-2/bin/symquery -e dynamorio/lib32/release/libdynamorio.so -f -v -a 0xe2f6c
<debug info: type=ELF symtab, has symbols, has line numbers>
module_fill_os_data.isra.2+0x25b
/work/drmemory_package/dynamorio/core/unix/module_elf.c:393+0x10

That's the TRY_EXCEPT, so why wasn't the fault handled? It is handled in debug build as shown below. Why not in release build?

Debug, this time via direct run instead of the wrapper through zygote:

data/local/tmp/build_android_dbg # bin32/drrun --  "/system/bin/app_process32" "/system/bin" "--application" "--nice-name=com.android.chrome" "com.android. signal 47                      "/system/bin/app_process32" "/system/bin" "--application" "--nice-name=com.android.chrome" "com.android.nit" "11" "23" "android.app.ActivityThread"
internal.os.WrapperInit" "11" "23" "android.app.ActivityThread"
<Starting application /system/bin/app_process32 (696)>
<Paste into GDB to debug DynamoRIO clients:
set confirm off
add-symbol-file '/data/local/tmp/build_android_dbg/lib32/debug/libdynamorio.so' 0x00021508
>
<Initial options = -no_dynamic_options -code_api -stack_size 56K -max_elide_jmp 0 -max_elide_call 0 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct >
<get_memory_info mismatch! (can happen if os combines entries in /proc/pid/maps)
        os says: 0xb6c6c000-0xb6c70000 prot=0x0000000b
        cache says: 0xb6c6a000-0xb6c70000 prot=0x0000000b
>
<(1+x) Handling our fault in a TRY at 0xb6f6263c>
<CURIOSITY : (0) && "crashed while walking dynamic header" in file /work/dr/git/src/core/unix/module_elf.c line 474
version 6.1.16887, custom build
-no_dynamic_options -code_api -stack_size 56K -max_elide_jmp 0 -max_elide_call 0 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct 
0xb6e0122d 0x78af04b0>
<CURIOSITY : (app_pc)((((ptr_uint_t)addr+len) + ((4096)-1)) & (~((ptr_uint_t)(4096)-1))) == ma->end in file /work/dr/git/src/core/unix/os.c line 6190
version 6.1.16887, custom build
-no_dynamic_options -code_api -stack_size 56K -max_elide_jmp 0 -max_elide_call 0 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct 
0xb6e0122d 0x78af04b0>
<CURIOSITY : (app_pc)((((ptr_uint_t)addr+len) + ((4096)-1)) & (~((ptr_uint_t)(4096)-1))) == ma->end in file /work/dr/git/src/core/unix/os.c line 6190
version 6.1.16887, custom build
-no_dynamic_options -code_api -stack_size 56K -max_elide_jmp 0 -max_elide_call 0 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct 
0xb6e0122d 0x78af04b0>
<Application tried to execute from dr memory 0x51e31840.
This may be a result of an unsuccessful attack or a potential application vulnerability.>

More details on the ELF fault:

os_add_new_app_module: /data/dalvik-cache/arm/system@framework@boot.oat
module_fill_os_data: 0x7138e000-0x749512bc 0x7138e000-0x74953000 dyn=0x74952000
<(1+x) Handling our fault in a TRY at 0xb6f03664>
<CURIOSITY : (0) && "crashed while walking dynamic header" in file /work/dr/git/src/core/unix/module_elf.c line 474
module_fill_os_data: 0x7138e000-0x74952038 0x7138e000-0x74953000 dyn=0x74952000

From #1860, we try each looking for dynamic, and crashing seems to be expected if we aren't there yet. Though it seems that maybe the at_map should just be removed from the check to avoid the crash, as the later fixup on Android has at_map=0.

The other curiosities are just the app passing a non-page-aligned size to munmap.

The "tried to execute from dr memory" seems to be due to an escaped dcontext:

THREAD 5931 (dcontext 0x4bfc5840)
<...>
Exit from F26704(0xb6c4ed8a).0x4c4a3c84 (shared)        
 (target 0x4bfc5840 not in cache)
dispatch: target = 0x4bfc5840
application tried to execute from dr 0x4bfc5840 is_allocated_mem=1 prot=0xb

[derekbruening]

It seems like the dcontext targeting happens in a signal handler for an app sigsegv which does not occur natively.

The SIGSEGV is r4 being null:

Got signal at pc 0x48e7b714 in this fragment:
Fragment 26690, tag 0xb48b0f2e, flags 0x9400230, shared, size 64:
  -------- prefix entry: --------
  0x48e7b710  f8da 0000  ldr    (%r10)[4byte] -> %r0
  -------- normal entry: --------
  0x48e7b714  f8d4 109c  ldr    +0x0000009c(%r4)[4byte] -> %r1

That shows up when running DrM:

03-28 13:20:39.420 20209 20209 I wrap.sh : ~~Dr.M~~ 
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ Error #1: UNADDRESSABLE ACCESS: reading 0x0000009c-0x000000a0 4 byte(s)
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 0 libart.so!art::DumpCheckpoint::Run
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 1 libart.so!art::ThreadList::RunCheckpoint
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 2 libart.so!art::ThreadList::Dump
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 3 libbacktrace.so!Backtrace::~Backtrace         +0x45     (0xb69c93e3 <libbacktrace.so+0x33e3>)
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 4 libbacktrace.so!?                             +0x0      (0xb69ca9d3 <libbacktrace.so+0x49d3>)
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 5 libc.so!strtoull
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 6 libart.so!art::Locks::Init
03-28 13:20:39.421 20209 20209 I wrap.sh : ~~Dr.M~~ # 7 libart.so!art::Runtime::Create
03-28 13:20:39.422 20209 20209 I wrap.sh : ~~Dr.M~~ # 8 libart.so!JNI_CreateJavaVM
03-28 13:20:39.422 20209 20209 I wrap.sh : ~~Dr.M~~ # 9 libandroid_runtime.so!android::AndroidRuntime::startVm+0x939    (0xb6b8306f <libandroid_runtime.so+0x5106f>)
03-28 13:20:39.422 20209 20209 I wrap.sh : ~~Dr.M~~ Note: @0:00:28.233 in thread 20211
03-28 13:20:39.422 20209 20209 I wrap.sh : ~~Dr.M~~ Note: instruction: ldr    +0x0000009c(%r4) -> %r1

[derekbruening]

The app crash is significant enough I split it out as #1918 for clarity.

The dcontext escape is due to sigaction handling skipping syscall execution and not realizing its own post-syscall handler thus won't be called.

After fixing both, we hit a mangling bug which I also split out: #1919

The bugs so far:

• ELF header crash
• App crash: separated into APP CRASH in Android apps due to DR incorrectly failing an mprotect #1918
• Dcontext escape due to sigaction bug
• Mangling bug: separated into Thumb add to PC is incorrectly mangled #1919

Now I can match the native behavior of directly launching app_process32, which is to die after a while:

/data/local/tmp/build_android_dbg # "/system/bin/app_process32" "/system/bin" "--application" "--nice-name=com.android.calculator2" "com.android.
internal.os.WrapperInit" "11" "23" "android.app.ActivityThread"; done
referenceTable GDEF length=814 1
referenceTable GSUB length=11364 1
referenceTable GPOS length=47302 1
Killed

/data/local/tmp/build_android_dbg # bin32/drrun -oom_timeout 2519600 -checklevel 1 -- "/system/bin/app_process32" "/system/bin" "--application" "
--nice-name=com.android.calculator2" "com.android.internal.os.WrapperInit" "11" "23" "android.app.ActivityThread"
<Starting application /system/bin/app_process32 (18648)>
<Paste into GDB to debug DynamoRIO clients:
set confirm off
add-symbol-file '/data/local/tmp/build_android_dbg/lib32/debug/libdynamorio.so' 0x00021508
>
<Initial options = -no_dynamic_options -checklevel 1 -code_api -stack_size 56K -max_elide_jmp 0 -max_elide_call 0 -oom_timeout 2519600 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct >
<unhandled signal system call 177>
referenceTable GDEF length=814 1
referenceTable GSUB length=11364 1
referenceTable GPOS length=47302 1
<-- parent 18648 forked child 18673 -->
<-- execve /system/bin/idmap -->
<Starting application /system/bin/idmap (18673)>
<Paste into GDB to debug DynamoRIO clients:
set confirm off
add-symbol-file '/data/local/tmp/build_android_dbg/lib32/debug/libdynamorio.so' 0x00021508
>
<Initial options = -checklevel 1 -code_api -stack_size 56K -max_elide_jmp 0 -max_elide_call 0 -oom_timeout 2519600 -early_inject -emulate_brk -no_inline_ignored_syscalls -native_exec_default_list '' -no_native_exec_managed_code -no_indcall2direct >
<Stopping application /system/bin/idmap (18673)>
Killed

The unhandled syscall is SYS_rt_sigtimedwait.

Moving on to launching the full app via wrap script and tapping on the screen, we hit an assert:

04-03 13:57:24.620 19924 19924 I wrap.sh : <Application /system/bin/app_process32 (19926).  Internal Error: DynamoRIO debug check failure: /work/dr/git/src/core/utils.c:573 !lock->owner
04-03 13:57:24.621 19924 19924 I wrap.sh : (Error occurred @45271 frags)

Using release DR, though, calculator comes up and seems to work -- at least, simple addition gets the right answer :)

[derekbruening]

The crashes are fixed. I'm moving the asserts out into a separate issue and closing this one.
Fixes are in:

554c523 i#1912 Java Android: avoid fault processing ELF headers
81e344e i#1912 Java Android: fix sigaction skip bug
9ccdb65 i#1918: do not proactively fail mprotect
4d1563d i#1919: fix mangling bug for Thumb add to pc

[colordancer]

I tried the latest dynamorio and drmemory releases. Both failed to start calculator App.
I directly used the shell command line, instead of wrap.

Command:
/data/local/tmp/dynamorio # ./bin32/drrun -t drmemory -- "/system/bin/app_process32" "/system/bin" "--application" "--nice-name=com.android.calculator2" "com.android.internal.os.WrapperInit" "11" "23" "android.app.ActivityThread"

Exception:

<Application /system/bin/app_process32_original (3232). Dr. Memory internal crash at PC 0x5548ac90. Please report this at http://drmemory.org/issues. Program aborted.
Received SIGSEGV at pc 0x5548ac90 in thread 3232
Base: 0xb6e63000
Registers: r0 =0x00000000 r1 =0x00000002 r2 =0x00000000 r3 =0x00000000
r4 =0x00000000 r5 =0x55423f20 r6 =0x5548a880 r7 =0xb6fa1000
r8 =0x55423f21 r9 =0xb6fa200
1.10.1-3-(Apr 10 2016 18:06:18)0
-disasm_mask 8 -logdir '/data/local/tmp/dynamorio/drmemory/drmemory/logs/dynamorio' -client_lib '/data/local/tmp/dynamorio/drmemory/bin/release/libdrmemorylib.so;0;-logdir /data/local/tmp/dynamorio/drmemory/drmemory/logs -symcache_dir /data/local/tmp/dynamorio/drmemory/drmemory/logs/symcache -resfile 3232 ' -code_api
0x5548a800 0x00000000>

[derekbruening]

"drrun -t drmemory" is Dr. Memory, identical to using the Dr. Memory release package. Can you confirm that plain DynamoRIO (i.e., "bin32/drrun" without any tool) fails to start calculator on your device? What version of Android is this?

[colordancer]

If I run plain DynamoRio with below command, I got a segmentation fault without further information.
The Android devices I used is Nexus 5 with aosp 5.1.1
/data/local/tmp/dynamorio # ./bin32/drrun -- "/system/bin/app_process32" "/system/bin" "--application" "--nice-name=com.android.calculator2" "com.android.internal.os.WrapperInit" "11" "23" "android.app.ActivityThread"

[derekbruening]

As shown above, that command line succeeds (matches native), on my Nexus 6 running 6.0. The wrap, which brings up the full app, also succeeds. Since I cannot reproduce what you're seeing, please try to debug it using debug build and log files (xref https://github.com/DynamoRIO/dynamorio/wiki/Debugging).

[colordancer]

Luckily, after I upgraded my Nexus 5 with Android 6.0.1, it seems I get closer to the success. But there was still a tiny problem.
Using DR release 6.1.1-3(https://github.com/DynamoRIO/dynamorio/releases/download/release_6_1_1/DynamoRIO-ARM-Android-EABI-6.1.1-3.tar.gz), I saw the same output you mentioned above.

referenceTable GDEF length=814 1
referenceTable GSUB length=11364 1
referenceTable GPOS length=47302 1
Killed

The command I used was not changed.

[colordancer]

@derekbruening
Sorry to refresh this topic, but I'm still stuck by the old problem.
I was trying to start Calculator over my Moto X with Android 6.0. I set the prop for Calculator in order to start it by drrun, with the command setporp wrap.com.android.calculator2 /data/local/tmp/dynamorio/bin32/drrun -- $*. But I always saw the same error:

06-15 10:23:10.745 W/Zygote ( 318): Error reading pid from wrapped process, child may have died
06-15 10:23:10.745 W/Zygote ( 318): java.io.EOFException
06-15 10:23:10.745 W/Zygote ( 318): at libcore.io.Streams.readFully(Streams.java:83)
06-15 10:23:10.745 W/Zygote ( 318): at java.io.DataInputStream.readInt(DataInputStream.java:103)
06-15 10:23:10.745 W/Zygote ( 318): at com.android.internal.os.ZygoteConnection.handleParentProc(ZygoteConnection.java:800)
06-15 10:23:10.745 W/Zygote ( 318): at com.android.internal.os.ZygoteConnection.runOnce(ZygoteConnection.java:257)
06-15 10:23:10.745 W/Zygote ( 318): at com.android.internal.os.ZygoteInit.runSelectLoop(ZygoteInit.java:690)
06-15 10:23:10.745 W/Zygote ( 318): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:612)

I believe the reason should be the child process failed to start. But interesting thing is if I use the pure command line to start calculator, I can see the process started successfully as expected.
./bin32/drrun -- "/system/bin/app_process32" "/system/bin" "--application" "--nice-name=com.android.calculator2" "com.android.internal.os.WrapperInit" "11" "23" "android.app.ActivityThread"

So, could you please share the way in which you succeeded to start Calculator with wrap? I hope to move on but have been paused for some time. Thank you.