Loop (and error) when running with real device

[mrpinghe]

Hi,

First, thank you for developing this promising tool and I have been following it for a while, and it is wonderful to see you guys are supporting real device now!

However, I ran into a problem while trying to run it. It first says I don't have APK instrumenter installed, but I do (see last phone screenshot). Then it kept going even after that error, until it stuck in the loop in the end (see Terminal screenshot). I can provide more information as needed, and thank you in advance for any help!

[Tibap]

Hi mrpinghe, First of all, thanks for your interest in Hooker :) Concerning your bug, can you open a shell and check return of the command that fails? Regarding your screenshots, it's seems to be: adb shell pm list packages com.amossys.hooker Concerning the infinite loop, we have already identified that bug. We'll have to push the patch in a future release.

[mrpinghe]

Thank you for the pointer! I didn't understand the error message enough, I guess.

Anyway, I ran that command, it works fine. I added "-s $myDeviceId" like it says in the error message, it says device not found. That's when I realize this is the device ID from "adb devices" (and of course you put that in the comment as well...) not the android_id...

Anyway, changing that solved the problem! However, now another... I think this could be a better brain teaser... While running the experiment, one of the command seems to be adb reboot. The phone rebooted, but then the experiment errors out while my phone is still not back up yet (screenshot).

I waited about 40 "[MainProcess/MainThread/DEBUG] 45227: All APKs have been pushed to the analyzing queue, sleeping 5 secs..." (so, 200 sec?) before interrupted the process.

I don't think any command listed there is problematic, simply because the phone was still rebooting... Is reboot mandatory? Can I comment out anything to skip the reboot? Or there is some other way to resolve this? Thanks!!

[Tibap]

Concerning the reboot error, you have highlighted a bug. We'll try to patch it in the next release.

If you want to bypass the reboot, you have to edit your configuration file. Check the parameter "scenario" to modify what the device has to execute. However, if you want to analyze just one application, I think it is better for you to run a manual analysis instead of an automatic one. Check the file named sampleManualAnalysisOnRealDevice.conf in the hooker_xp directory. When you run a manual analysis, hooker_xp is launching the experience, and it is your job to stimulate the application. When your done stimulating, just press Ctrl-C in your hooker_xp console and read the logs to make sure everything's right.

Hope that helps!

[mrpinghe]

Manual?! I don't do no manual! :P just kidding This is immensely helpful and I got further again with manual! However... (trust me, I'm getting tired of redacting screenshots too) the events.logs doesn't seem to be generated at all.

As you can see from the last couple of lines in the screenshot below, events.logs doesn't exist on my phone, and of course the one supposedly copied over to /tmp/android also doesn't exist. I checked my phone as well. The "hooker" directory is there, and there is an experiment.conf, which is an empty file, as well as the "backup" folder with all the twrp backup files.

What did I do wrong? T_T I have the full log saved, so I can share the rest of the log as well.

[Tibap]

Can you check in your configuration file that you have your parameter file_mode to true? If this is indeed the case, I think you've found a new bug... If I were you, I would check android logs using logcat. You'll have logs from APK-instrumenter, which should be the one writing in the events.log file... If you cannot see anything useful, can you precise what device you're using? Android version should be useful too.

[mrpinghe]

Yes, file_mode is true. However, when opening the Hooker app (APK-instrumenter), and click on "Actualize Configuration" it says "File Mode: Off". See screenshot below.

I started dumping logcat before running the experiment, and here are some highlights when grepping "hooker" from the dump file, i.e. $cat ~/Desktop/ah-manual.log | grep -i hooker | less

I/ActivityManager( 383): Process com.amossys.hooker:remote (pid 867) has died. W/ActivityManager( 383): Scheduling restart of crashed service com.amossys.hooker/.service.InstrumentationService in 5000ms I/ActivityManager( 383): Start proc com.amossys.hooker:remote for service com.amossys.hooker/.service.InstrumentationService: pid=3492 uid=10078 gids={50078, 1015, 3 003, 1028} W/ContextImpl( 3333): Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1352 android.content.ContextWrapper.startS ervice:450 com.saurik.substrate._MS$MethodPointer.invoke:-2 com.saurik.substrate.MS$MethodPointer.invoke:58 com.amossys.hooker.hookers.Hooker$1$1.invoked:209 W/ContextImpl( 3874): Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1352 android.content.ContextWrapper.startS ervice:450 com.saurik.substrate._MS$MethodPointer.invoke:-2 com.saurik.substrate.MS$MethodPointer.invoke:58 com.amossys.hooker.hookers.Hooker$1$1.invoked:209

...... (a lot of repetitive entry of the last line) ...

I/ActivityManager( 383): START u0 {act=android.intent.action.VIEW dat=file:///storage/emulated/0/hooker/experiment.conf typ=text/plain flg=0x10000000 cmp=com.estrongs.android.pop/.app.editor.PopNoteEditor (has extras)} from pid 2370 I/ActivityManager( 383): START u0 {act=android.intent.action.VIEW dat=file:///storage/emulated/0/hooker/experiment.conf typ=text/plain flg=0x10000000 cmp=com.estrongs.android.pop/.app.editor.PopNoteEditor (has extras)} from pid 2370 E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent.readParametersList(InterceptEvent.java:134) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent.(InterceptEvent.java:99) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent.(InterceptEvent.java:52) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent$1.createFromParcel(InterceptEvent.java:210) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent$1.createFromParcel(InterceptEvent.java:208) E/AndroidRuntime( 3492): at com.amossys.hooker.service.InstrumentationService$IncomingHandler.handleMessage(InstrumentationService.java:104) I/ActivityManager( 383): Process com.amossys.hooker:remote (pid 3492) has died. W/ActivityManager( 383): Service crashed 2 times, stopping: ServiceRecord{4203c510 u0 com.amossys.hooker/.service.InstrumentationService} I/ActivityManager( 383): Start proc com.amossys.hooker:remote for service com.amossys.hooker/.service.InstrumentationService: pid=12969 uid=10078 gids={50078, 1015, 3003, 1028} W/ContextImpl(12333): Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1352 android.content.ContextWrapper.startService:450 com.saurik.substrate._MS$MethodPointer.invoke:-2 com.saurik.substrate.MS$MethodPointer.invoke:58 com.amossys.hooker.hookers.Hooker$1$1.invoked:209 W/ContextImpl(13573): Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1352 android.content.ContextWrapper.startService:450 com.saurik.substrate._MS$MethodPointer.invoke:-2 com.saurik.substrate.MS$MethodPointer.invoke:58 com.amossys.hooker.hookers.Hooker$1$1.invoked:209 I/Hooker (13665): Hooking method android.hardware.usb.UsbDeviceConnection:releaseInterface I/Hooker (13665): hooking android.hardware.usb.UsbDeviceConnection methods sucessful I/Hooker (13665): Hooking method android.hardware.Camera:takePicture I/Hooker (13665): Hooking method android.hardware.Camera:takePicture I/Hooker (13665): Hooking method android.hardware.Camera:setFaceDetectionListener I/Hooker (13665): Hooking method android.hardware.Camera:startPreview

.... then a lot of "Hooking method..." lines....

I/Hooker (13665): Hooking method java.lang.Runtime:getRuntime I/Hooker (13665): Hooking method java.lang.Runtime:traceMethodCalls I/Hooker ( 2370): Sending previous stored event before current one. I/Hooker ( 2370): InterceptEvent [idEvent=70383612-ffd3-470f-ac42-527fc3996936, IDXP=null, timestamp=1428590234600, hookerName=IPC, intrusiveLevel=0, instanceID=1107037568, packageName=com.estrongs.android.pop, className=android.content.Intent, methodName=setAction] I/Hooker (12969): Collecting Service received an event to report. I/Hooker (12969): No reporter available, will try to parse the configuration file... I/Hooker (12969): Try to create reporters based on configuration file I/Hooker (12969): Parsing the configuration file '/storage/emulated/0/hooker/experiment.conf' I/Hooker (12969): Collecting Service received an event to report. I/Hooker (12969): No reporter available, will try to parse the configuration file... I/Hooker (12969): Try to create reporters based on configuration file I/Hooker ( 2370): Sending previous stored event before current one. I/Hooker (12969): Parsing the configuration file '/storage/emulated/0/hooker/experiment.conf'

.... then it's basically a lot of these "Parsing... Collecting... No report... Try to... " messages in the midst of "InterceptEvnet..." messages ....

Once in a while, it would have messages like I/Hooker (13676): Hooking method javax.crypto.Mac:update I/Hooker (13676): Hooking method javax.crypto.Mac:init I/Hooker (13676): Hooking method javax.crypto.Mac:init I/Hooker (13676): Hooking method javax.crypto.Mac:getInstance ... and ... I/Hooker ( 2370): Self hooking detected on method 'exists'. I/Hooker ( 2370): Self hooking detected on method 'java.io.File'. I/Hooker ( 2370): Self hooking detected on method 'getPath'.

So something is definitely wrong.

My device: Verizon Galaxy Nexus (toro) running on 4.2.2 (build JDQ39), the factory image I pulled from developers.google.com. The phone is a test phone not associated with any Google account, not sure if that matters.

[mrpinghe]

I realize some of the log entry seems to be stack trace, so I grepped AndroidRuntime and here is what I have:

E/AndroidRuntime( 3492): FATAL EXCEPTION: main E/AndroidRuntime( 3492): java.lang.OutOfMemoryError E/AndroidRuntime( 3492): at android.os.Parcel.nativeReadString(Native Method) E/AndroidRuntime( 3492): at android.os.Parcel.readString(Parcel.java:1473) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent.readParametersList(InterceptEvent.java:134) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent.(InterceptEvent.java:99) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent.(InterceptEvent.java:52) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent$1.createFromParcel(InterceptEvent.java:210) E/AndroidRuntime( 3492): at com.amossys.hooker.common.InterceptEvent$1.createFromParcel(InterceptEvent.java:208) E/AndroidRuntime( 3492): at android.os.Parcel.readParcelable(Parcel.java:2103) E/AndroidRuntime( 3492): at android.os.Parcel.readValue(Parcel.java:1965) E/AndroidRuntime( 3492): at android.os.Parcel.readMapInternal(Parcel.java:2226) E/AndroidRuntime( 3492): at android.os.Bundle.unparcel(Bundle.java:223) E/AndroidRuntime( 3492): at android.os.Bundle.getParcelable(Bundle.java:1173) E/AndroidRuntime( 3492): at com.amossys.hooker.service.InstrumentationService$IncomingHandler.handleMessage(InstrumentationService.java:104) E/AndroidRuntime( 3492): at android.os.Handler.dispatchMessage(Handler.java:99) E/AndroidRuntime( 3492): at android.os.Looper.loop(Looper.java:137) E/AndroidRuntime( 3492): at android.app.ActivityThread.main(ActivityThread.java:5041) E/AndroidRuntime( 3492): at java.lang.reflect.Method.invokeNative(Native Method) E/AndroidRuntime( 3492): at java.lang.reflect.Method.invoke(Method.java:511) E/AndroidRuntime( 3492): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:793) E/AndroidRuntime( 3492): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:560) E/AndroidRuntime( 3492): at com.android.internal.os.ZygoteInit.main(Native Method) E/AndroidRuntime( 3492): at dalvik.system.NativeStart.main(Native Method) D/AndroidRuntime(13665): Calling main entry com.android.commands.am.Am D/AndroidRuntime(13665): Shutting down VM D/AndroidRuntime(13746): D/AndroidRuntime(13746): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<< D/AndroidRuntime(13746): CheckJNI is OFF D/AndroidRuntime(13746): Calling main entry com.android.commands.pm.Pm D/AndroidRuntime(13746): Shutting down VM

[mrpinghe]

So, according to Android Apps setting, I have about 300 MB free memory while not doing anything, and the memory doesn't change much when I run the experiment, floating between 280 and 320. Hooker is one of the cached processes.

Also, a possibly unrelated note, why is configuration about elasticsearch is commented out in auto config, but not in manual config? Do I have to have elasticsearch running while doing the experiment? I do have elasticsearch database server running on localhost though, in case you are wondering.

[gbossert]

Hello mrpinghe,

1) The elasticsearch mode is optional. Check that "elasticsearch_mode" is set to false in configuration file if you want to deactivate it. 2) You need no google account to use Hooker. 3) Regarding the main issue, I believe there can be a link between the large memory usage and the fact that no reporters are available (cf. error " I/Hooker (12969): No reporter available, will try to parse the configuration file..."). If no reporters are available, InterceptedEvents are kept in memory and never dropped (we should fix that: https://github.com/AndroidHooker/hooker/issues/6), thus leading to an OutofMemoryError. So IMHO, the big question is "why the hell no reporters are detected by the APKInstrumenter". The function "createReportersFromConfigFile" (in InstrumentationService.java) is the key here. If we compare the log entries you provided against the source code of this function it underlines a potential issue in the configuration file that is pushed on the android device. Can you publish here the content of this file you can find at '/storage/emulated/0/hooker/experiment.conf'.

Many thanks for your help

[mrpinghe]

Hi gbossert,

Thank you for following up! The environment.conf is an empty file. Should I have manually put something in there?

Thanks

[gbossert]

Ok, so here we have a bug. This file (experiment.conf and not environment.conf) must contain the configuration of the experiment so the Android Application knows where and how to export the collected events. Here is an example of its content for a simple file reporting mode :

# Hooker Analysis Configuration File
# Network configuration
[elasticsearch]
elasticsearch_mode=false
elasticsearch_nb_thread=1
elasticsearch_ip=10.0.2.2
elasticsearch_port=9200
elasticsearch_index=hooker_test
elasticsearch_doctype=event

# File configuration
[file]
file_mode=true
file_name=events.log

[analysis]
idXP=1

Can you start the emulator with the Hooker started (you should see logs showlng some events are captured) and then update the experiment.conf content with the example. It should work (hopefully).

[mrpinghe]

Sorry for the typo... Yeah, it's experiment.conf. Anyway, so in the context of running on real device, I should run the manual experiment with the python command first, and push the new experiment.conf into the hooker directory in /sdcard, once I see from the logcat that it intercepted some events? And hopefully the Hooker process will pick up the config halfway and starts working properly?

[gbossert]

Exactly :)

[mrpinghe]

Great! It works! Thanks! Will try turning on elasticsearch and see what happens next (probably in a couple of days).

One small thing, in the sample .conf file, you have "events.log" whereas the script looks for "events.logs". The trailing "s" in the file extension caused some small problem when the script trying to copy the file from the device to my laptop. Other than that, it works fine! Thank you again for all the help and can't wait to do a pull request with fixes :)

[gbossert]

Thank you for your time and your help.