search

rovo89 / android_art

Android ART with modifications for the Xposed framework.
Other
371 stars 211 forks source link

arm64 / odex / 6.0.1: Some apps are not compiled at boot time #28

Closed m0vie closed 8 years ago

m0vie commented 8 years ago

I just set up a new nexus 6p like the following:

After rebooting 48 apps were optimized just fine.

But some others were not optimized on the boot but lateron, in which case it was not successful.

01-15 22:34:27.709  7105  7152 I ActivityManager: Start proc 8355:com.google.process.gapps/u0a12 for service com.google.android.gms/.clearcut.service.ClearcutLoggerService
01-15 22:34:27.710  8319  8319 E dex2oat : Failed to create oat file: /data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex: Permission denied
01-15 22:34:27.710  8319  8319 I dex2oat : dex2oat took 566.510us (threads: 2) 
01-15 22:34:27.712  8270  8270 W System  : ClassLoader referenced unknown path: /system/priv-app/TelephonyProvider/lib/arm64
01-15 22:34:27.713  8244  8244 W art     : Failed execv(/system/bin/dex2oat --runtime-arg -classpath --runtime-arg /system/framework/XposedBridge.jar --instruction-set=arm64 --instruction-set-features=smp,a53 --runtime-arg -Xnorelocate --boot-image=/system/framework/boot.art --runtime-arg -Xms64m --runtime-arg -Xmx512m -j2 --instruction-set-variant=cortex-a53 --instruction-set-features=default --dex-file=/system/app/NfcNci/oat/arm64/NfcNci.odex --oat-file=/data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex) because non-0 exit status
01-15 22:34:27.713  8244  8244 W art     : Entry not found

This leads to an infinitle FC loop.

Investigating the issue I did the following:

This still did not work:

01-15 22:52:09.205  5402  7721 I ActivityManager: Start proc 10156:com.android.nfc/1027 for restart com.android.nfc
01-15 22:52:09.218 10156 10156 W re-initialized>: type=1400 audit(0.0:51): avc: denied { write } for name="arm64" dev="dm-0" ino=1064963 scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=dir permissive=0
01-15 22:52:09.265 10171 10171 E dex2oat : Failed to create oat file: /data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex: Permission denied
01-15 22:52:09.258 10171 10171 W dex2oat : type=1400 audit(0.0:52): avc: denied { write } for name="arm64" dev="dm-0" ino=1064963 scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=dir permissive=0
01-15 22:52:09.265 10171 10171 I dex2oat : dex2oat took 761.510us (threads: 2) 
01-15 22:52:09.267 10156 10156 W art     : Failed execv(/system/bin/dex2oat --runtime-arg -classpath --runtime-arg /system/framework/XposedBridge.jar --instruction-set=arm64 --instruction-set-features=smp,a53 --runtime-arg -Xnorelocate --boot-image=/system/framework/boot.art --runtime-arg -Xms64m --runtime-arg -Xmx512m -j2 --instruction-set-variant=cortex-a53 --instruction-set-features=default --dex-file=/system/app/NfcNci/oat/arm64/NfcNci.odex --oat-file=/data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex) because non-0 exit status
01-15 22:52:09.267 10156 10156 W art     : Entry not found

So now the problem is the sepolicy: dex2oat is being run as UID nfc and not system.

So lets' try after setenforce permissive:

01-15 22:57:22.227  5402  9126 I ActivityManager: Start proc 11883:com.android.nfc/1027 for restart com.android.nfc
01-15 22:57:22.248 11883 11883 W re-initialized>: type=1400 audit(0.0:243): avc: denied { write } for name="arm64" dev="dm-0" ino=1064963 scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=dir permissive=0
01-15 22:57:22.278 11896 11896 I setenforce: type=1400 audit(0.0:244): avc: denied { setenforce } for scontext=u:r:init:s0 tcontext=u:object_r:kernel:s0 tclass=security permissive=1
01-15 22:57:22.278   349   349 W auditd  : type=1404 audit(0.0:245): enforcing=0 old_enforcing=1 auid=4294967295 ses=4294967295
01-15 22:57:22.313 11895 11895 I dex2oat : /system/bin/dex2oat -j2 --dex-file=/system/app/NfcNci/oat/arm64/NfcNci.odex --oat-file=/data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex
01-15 22:57:22.308 11895 11895 I dex2oat : type=1400 audit(0.0:246): avc: denied { write } for name="arm64" dev="dm-0" ino=1064963 scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=dir permissive=1
01-15 22:57:22.308 11895 11895 I dex2oat : type=1400 audit(0.0:247): avc: denied { add_name } for name="system@app@NfcNci@NfcNci.apk@classes.dex" scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=dir permissive=1
01-15 22:57:22.308 11895 11895 I dex2oat : type=1400 audit(0.0:248): avc: denied { create } for name="system@app@NfcNci@NfcNci.apk@classes.dex" scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=file permissive=1
01-15 22:57:22.308 11895 11895 I dex2oat : type=1400 audit(0.0:249): avc: denied { write } for path="/data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex" dev="dm-0" ino=1065162 scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=file permissive=1
01-15 22:57:22.308 11895 11895 I dex2oat : type=1400 audit(0.0:250): avc: denied { setattr } for name="system@app@NfcNci@NfcNci.apk@classes.dex" dev="dm-0" ino=1065162 scontext=u:r:nfc:s0 tcontext=u:object_r:dalvikcache_data_file:s0 tclass=file permissive=1
01-15 22:57:22.553 11895 11895 I dex2oat : dex2oat took 241.603ms (threads: 2) arena alloc=368KB java alloc=551KB native alloc=2MB free=1372KB
01-15 22:57:22.563   372   372 I SELinux : SELinux: Loaded service_contexts from /service_contexts.
01-15 22:57:22.563   372   372 I SELinux : avc:  received setenforce notice (enforcing=0)
01-15 22:57:22.575 11883 11883 I NfcService: Starting NFC service

The file could now be created, but has UID/GID of nfc/nfc:

# ls -Z /data/dalvik-cache/arm64/*Nfc*
-rw-r--r-- nfc      nfc               u:object_r:dalvikcache_data_file:s0 system@app@NfcNci@NfcNci.apk@classes.dex

And everything works perfectly.

The problem seems to be specific to odexed system apps for which dex2oat fails when being run on-demand.

I also tried the whole thing using various versions of SuperSU (2.66, 2.52, no SuperSU at all), to no avail so it seems to be unrelated to any other changes.

rovo89 commented 8 years ago

The problem seems to be specific to odexed system apps for which dex2oat fails when being run on-demand.

If dex2oat has to be run on demand, it's already too late. You can forget about the UID stuff, the question is why dex2oat isn't triggered earlier. You say that some apps were not optimized - do you have more information about that (e.g. logs where I can say that/why it fails or is skipped)? Does it try to repeat the optimization after a reboot?

m0vie commented 8 years ago

Reboots did not cause the Nfc app to be compiled. It kept failing.

I just noticed that I did actually create a logcat of the first boot after xposed installation in recovery, and uploaded it: http://sprunge.us/ffKW

I could not find any indication as to why some apps would get compiled and others wouldn't.

rovo89 commented 8 years ago

You could please try https://www.dropbox.com/s/8lddtv03riu8a1r/xposed-v80-sdk23-arm64-test2.zip?dl=0? It fixes some early errors on LG devices, it might help here as well.

m0vie commented 8 years ago

That build seems to work for me (flashed and cleared dalvik-cache). No dex2oat errors in the boot log anymore.

Note however, that I did not do a complete wipe, but used the device in its current state. So some system apps such as com.google.android.gsf were already updated and the version from /data/ was used instead. But the one that kept failing all the time before (com.android.nfc / NfcNci) is still the original system app and works perfectly now.

purpleman2k commented 8 years ago

Hey. Having similar issues on Nexus 6P, stock 6.0.1 latest image (mmb29p).

The steps I took:

  1. Flashed stock from Google servers in fastboot
  2. Flash twrp
  3. Flash BETA-SuperSU-v2.67-20160121175247.zip
  4. Reboot. (everything works fine)
  5. Reboot back to twrp
  6. flash xposed.
  7. Reboot

and then services (namely "Nfc Service") start to force-close in a loop.

I tried the above steps with "xposed-v79-sdk23-arm64.zip" and also with "xposed-v80-sdk23-arm64-test2.zip" Both versions result in the same issue :(

withlqs commented 8 years ago

I also met these same problems in the same situation.

I try to shutdown and reboot nexus 6p, NFC problem will be solved, but some other system apps still display "stop" sometimes.

AziraphaleES commented 8 years ago

same scenario as purpleman2k. clean install of everything. neither v79 nor v80t2 work, both produce nfc service crash.

UPD. after playing with a device for a few hours (too many apps installed and customisations done to list all and be able to pinpoint the fix, but amongst them was unrooting from SuperSU and rerooting again) I was able to install v80t2 without NFC crash. hm.

scarline commented 8 years ago

Hey, I have the same issue with a brand new Nexus 6p.

  1. Flashed MMB29Q
  2. Flashed TRWP Recovery 3.0.0 angler
  3. Installed SuperSU BETA-SuperSU-v2.67-20160121175247 (all fine until here)
  4. Flashed xposed-v80-sdk23-arm64.zip ---> Get NFC Loop

I also tried:

  1. Flashed MMB29Q
  2. Flashed TRWP Recovery 3.0.0 angler
  3. Installed SuperSU BETA-SuperSU-v2.67-20160121175247
  4. Installed XposedInstaller_3.0_alpha4.apk (all fine until here)
  5. Flashed xposed-v80-sdk23-arm64.zip

---> Get NFC Loop

Changed SuperSu to multiuser-support, thrust for systemlevel applications and activation during boot in the options had NO effect.

I did hear that flashing xposed > do factory reset, cleaning data > install xposed installer > flash SuperSU could be a possible way that works. Does anyone have experience on this? Does it make a difference when the reboot is done by the xposed-installer?

Many people have his issue, so it must be related to the more recent versions. Is there a confirmation that v78 is working better and without FC for NFC and gaps? Is there a workaround? I would like to install xprivacy....

robertoandrade commented 8 years ago

@rovo89 the link seems to be broken now. Is there a way to publish that fix again?

berlingozzo commented 8 years ago

Same NFC loop problem here. My configuration/ procedure: 1) nexus 5 lte 2) flashed factory 6.0.1 MMB29Q 3) flashed TWRP 3 4) flashed SUPERSU 2.66 BETA 5) flashed xposed-v80-sdk23-arm 6) nfc loop

I have tried v78-sdk23-6.0-arm as well, same problem I have tried disabling nfc first, setting SuperSU as multiuser support, start at boot, and trust system user, nothing.

Please help :)

thanks!

Inrego commented 8 years ago

Just wanted to let you know, I had the same problem on AOSP 6.0 on Xperia Z2 tablet.. I then did factory reset, delete cache and dalvik from the recovery, and then it worked fine.

watchmakerful commented 8 years ago

Confirmed on Nexus 5x on stock and Omni (both odexed), xposed v78..v80.

watchmakerful commented 8 years ago

PS, it works after a factory reset until a dalvik cache wipe.

watchmakerful commented 8 years ago

Many people have his issue, so it must be related to the more recent versions. Is there a confirmation that v78 is working better and without FC for NFC and gaps? Is there a workaround? I would like to install xprivacy....

Try a custom deodexed ROM (even simply a deodexed stock ROM). But it's strange to get this error on 32-bit.

pdc1 commented 8 years ago

Confirmed on Nexus 5 (32-bit). Stock MMB29V + SuperSU 2.68 (beta) + ElementalX kernel 6.14 + V80. Dirty flashing v78 resolved the problem.

PerfectSlayer commented 8 years ago

Confirmed on Nexus 6 (32-bit). Stock MMB29V + SuperSU 2.67 (beta) + v79 and v80.

It's not the first time it happened to me. I flash every monthly update and it happens about one times on three... I could not find a rule to get rid of it… (dalvik cache wip? reboot? flash system again?)

If you need any log or test, ask me! Thanks :+1:

michaelprager commented 8 years ago

Have the same problem on my Nexus 5 (hammerhead) after Stock update MMB29V.

I fixed the FC by executing the failed command via adb root shell:

/system/bin/dex2oat --runtime-arg -classpath --runtime-arg /system/framework/XposedBridge.jar --instruction-set=arm --instruction-set-features=smp,-div,-atomic_ldrd_strd --runtime-arg -Xnorelocate --boot-image=/system/framework/boot.art --runtime-arg -Xms64m --runtime-arg -Xmx512m --instruction-set-variant=krait --instruction-set-features=default --dex-file=/system/app/NfcNci/oat/arm/NfcNci.odex --oat-file=/data/dalvik-cache/arm/system@app@NfcNci@NfcNci.apk@classes.dex

Interestingly, after the next reboot, 13 further apps were optimized which were obviously skipped on the initial run.

When I clear the dalvik-cache now, everything is properly optimized in one run.

rovo89 commented 8 years ago

Please avoid "me too" comments. I'll let you know when I have time to analyze this further. I might need further logs then, especially of the initial boot where it misses to compile certain apps. I would like to see if they're mentioned at all and why they're skipped.

kwatkins commented 8 years ago

This worked for me, what @michaelprager did but for Nexus 6P/arm64: 

/system/bin/dex2oat --runtime-arg -classpath --runtime-arg /system/framework/XposedBridge.jar --instruction-set=arm64 --instruction-set-features=smp,a53 --runtime-arg -Xnorelocate --boot-image=/system/framework/boot.art --runtime-arg -Xms64m --runtime-arg -Xmx512m -j2 --instruction-set-variant=cortex-a53 --instruction-set-features=default --dex-file=/system/app/NfcNci/oat/arm64/NfcNci.odex --oat-file=/data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex
stangri commented 8 years ago

Had the same problem on Nexus 6. @michaelprager's trick didn't help, besides NFC there were problems with the other services. Even with the trick above I've had only a handful of apps (sometimes 13, sometimes 31, sometimes 31 and the count up would start from 10) which would optimize after cleaning cache.

TL;DR version -- before flashing Xposed I've flashed LED Enabler and I believe that was the reason Xposed flash "didn't take".

What did help me was:

  1. dirty-flash shamu-mmb29v
  2. adb reboot bootloader; fastboot boot twrp-3.0.0-1-shamu.img
  3. flash chainfire's SuperSU-v2.68.zip
  4. restart system
  5. ensure I have root, uninstall Xposed apk and all Xposed modules
  6. adb reboot bootloader; fastboot boot twrp-3.0.0-1-shamu.img
  7. make room in /system/ for Xposed (mount /system in twrp, adb shell and remove some IMEs)
  8. restart system
  9. make sure nothing is broken yet
  10. adb reboot bootloader; fastboot boot twrp-3.0.0-1-shamu.img
  11. flash xposed-v80-sdk23-arm.zip, use "clean dalvik/cache" option of twrp
  12. restart system
  13. reinstall (redownload) Xposed apk and modules
  14. adb reboot bootloader; fastboot boot twrp-3.0.0-1-shamu.img
  15. reinstall LED Enabler
yrom commented 8 years ago

Came across the same problem:

03-29 18:21:44.900 24452-24452/? E/dex2oat: Failed to create oat file: /data/dalvik-cache/arm/system@app@CloudPrint2@CloudPrint2.apk@classes.dex: Permission denied
03-29 18:21:44.902 24434-24434/? W/art: Failed execv(/system/bin/dex2oat --runtime-arg -classpath --runtime-arg /system/framework/XposedBridge.jar --instruction-set=arm --instruction-set-features=smp,-div,-atomic_ldrd_strd --runtime-arg -Xnorelocate --boot-image=/system/framework/boot.art --runtime-arg -Xms64m --runtime-arg -Xmx512m --instruction-set-variant=krait --instruction-set-features=default --dex-file=/system/app/CloudPrint2/CloudPrint2.apk --oat-file=/data/dalvik-cache/arm/system@app@CloudPrint2@CloudPrint2.apk@classes.dex) because non-0 exit status

Thanks @michaelprager, I re-exec the command of dex2oat manually via adb shell as root user.

➜~ adb shell shell@hammerhead:/ $ su root@hammerhead:/ # /system/bin/dex2oat --runtime-arg -classpath --runtime-arg /system/framework/XposedBridge.jar --instruction-set=arm --instruction-set-features=smp,-div,-atomic_ldrd_strd --runtime-arg -Xnorelocate --boot-image=/system/framework/boot.art --runtime-arg -Xms64m --runtime-arg -Xmx512m --instruction-set-variant=krait --instruction-set-features=default --dex-file=/system/app/CloudPrint2/CloudPrint2.apk --oat-file=/data/dalvik-cache/arm/system@app@CloudPrint2@CloudPrint2.apk@classes.dex

The CloudPrint2 does not FC again..

rovo89 commented 8 years ago

Could you try this please? https://www.dropbox.com/s/2wqrzrydabq4qbp/xposed-v83-sdk23-arm-test2.zip?dl=0 https://www.dropbox.com/s/473up554s3d07ax/xposed-v83-sdk23-arm64-test2.zip?dl=0 (you should propably clear the Dalvik cache if you have used some work-around before)

If this works, please just let me know and I'll release an official version with the fix soon. There's no need to create guides how to use these test versions, upload them to alternative places, ...

m0vie commented 8 years ago

Just flashed Nexus 6P mhc19q + xposed v83-sdk23-arm64-test2 and cleared the Dalvik cache. All apps were compiled on the first boot, and no crashes afterwards.

rovo89 commented 8 years ago

Great! Further tests would still be welcome, I'll do some more myself.

Just out of curiosity: Is there really a compiled file for NfcNci.apk in the Dalvik cache afterwards? There might not be one, and the trick is actually that apps should be able to run even if they haven't been recompiled.

m0vie commented 8 years ago 
/data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex   856744  2009-01-01 09:00:00

is there. Il'l have another detailed look later, but so far everything looks good.

rovo89 commented 8 years ago

OK. The issue is actually a bit more complex... Android sometimes decides to skip some apps when they haven't been used for a longer time. This behavior was even intensified on 6.0.1: https://github.com/android/platform_frameworks_base/commit/71d3260ffa99bf7e580d9ebd979a1e7863b50223

In your case, it seems that the system has decided to compile the app anyway. My fix is especially about those case where the app wasn't compiled.

m0vie commented 8 years ago

Does that mean that the app will be compiled on-the-fly? Is that going to degrade performance in some way?

rovo89 commented 8 years ago

As far as I could see so far, these apps aren't compiled at all, but interpreted. That will certainly have a little performance impact, but keep in mind that these are very few apps, and especially those which haven't been used for a longer time. Android might still decide to compile them at a later time if they're actually used. And the point is: AOSP already has the same behavior. It just wasn't used when Xposed is installed because Xposed forces the image to be recompiled, so checksums didn't match, and also it checks that the file is recompiled for Xposed. My changes allow the interpreted usage of the odex file when everything else has failed. And that's still better than a bootloop, right? 😊

giantpune commented 8 years ago

I experienced this issue on a nexus 5x with factory images (mhc19q). I was able to get the system to actually boot using this approach. https://github.com/rovo89/android_art/issues/28#issuecomment-202824817 I grep logcat looking for the Failed execv( and then manually running those commands as root.

However, even though the system boots up, even some 3rd party apps installed from the play store are crashing with this same type of issue.

rovo89 commented 8 years ago

@giantpune Did you try the test version I posted above?

giantpune commented 8 years ago

It seems like that test2 zip did fix the issue with the app I was having. I'll play with it some more and report back if I notice some other app misbehaving.

Modzon commented 8 years ago

Test version did worked. Apps are decompiled. But apps moved to external-sd won't load and some apps won't uninstall/install

EDIT: Apps moved to external-sd are loading, but it takes very long to load. The same for uninstalling apps

rovo89 commented 8 years ago

@Modzon Could you please be more specific? Does it affect all apps that you have moved? How have you moved them? Does moving them back to internal space help? Does the issue come back when you move them to external SD again? Which apps can't be installed/uninstalled? What's the error message? Can you provide logs for any of these issues?

Modzon commented 8 years ago

@rovo89 The problem of the apps that won't load is already fixed. The most app's I've moved to the external sdcard with the adoptable storage of Android MM. The uninstallation problem only affects the smaller apps moved to the external sdcard but it is also fixed.

rovo89 commented 8 years ago

Fixed in v83.