Magisk icon indicating copy to clipboard operation
Magisk copied to clipboard

Opening `/data/adb/magisk.db` causes vold to kill `magiskd` when it's umounting tmpfs data partition on FDE devices

Open icedream opened this issue 3 years ago • 10 comments
trafficstars

Device: Samsung Galaxy S8 (Exynos) (SM-G950F) Android version: 12L (Ivan Meler's LineageOS 19.1 ROM) Magisk version name: 25.2 Magisk version code: 25200

Additional info:

  • My ROM installation is a Samsung phone ROM with encryption enabled. I can not run on unencrypted data on this particular phone for non-technical reasons.
  • This issue can not be reproduced with debug build (presumably because APK signature verification is skipped for debug purposes?), so I will have to refer to the release build for this one. If there is a way to reproduce this with debug and it makes sense to do it, please let me know.

The Magisk app uninstalls itself on launch right after installation. Logcat output hints at an APK signature mismatch causing a trigger of deletePackageX, leading to the app getting killed and the APK getting completely uninstalled.

The only relevant lines from logcat here seem to be as follows, though I did attach some more logs at the end of this description:

07-29 22:16:13.073  5306  5308 E Magisk  : pkg: APK signature mismatch: /data/app/~~krn7_P6YhCO6wsaM6DuHNw==/com.topjohnwu.magisk-6V6BbOlZYiJu3yThSKBn7w==/base.apk
07-29 22:16:13.098 13037 13037 I Magisk  : pm_uninstall: com.topjohnwu.magisk
07-29 22:16:13.131  5388  5416 I ActivityManager: Force stopping com.topjohnwu.magisk appid=10251 user=-1: deletePackageX

And maybe the fact that this is encryption on a Samsung device specifically may play into Magisk having difficulty to deal with /data? Just guessing on my part though.

This appears on the release files distributed through GitHub Releases (https://github.com/topjohnwu/Magisk/releases/download/v25.2/Magisk-v25.2.apk) and it also happens when upgrading through Magisk 24.3's update installation option (24.3 runs pretty much fine except for Zygisk always detected as unloaded which is unrelated to this issue).

Reproduction steps:

  1. Start with a normal installation of the mentioned ROM. Keep a copy of boot.img from the ZIP. Encrypt the phone data.
  2. Install Magisk v25.2 APK straight from GitHub.
  3. Open the app. It will open just fine, patch the boot.img there with options left as-is.
  4. Flash boot.img (I specifically did it by using adb root, dd if=/storage/emulated/0/Download/magisk_patched-25200_U4Bsz.img of=/dev/block/platform/11120000.ufs/by-name/BOOT and sync).
  5. Reboot phone. Note that after this the "Magisk" app is no longer installed despite us not uninstalling it.
  6. Reinstall the exact APK used in step 2.
  7. Launch the app. It will close immediately and uninstall itself.

I attached more complete logs here:

/cache/magisk.log magisk.log
logcat excerpt where I started the app

07-29 22:16:12.836  5388 10954 I ActivityTaskManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.topjohnwu.magisk/.ui.MainActivity bnds=[584,1538][856,1970]} from uid 10092
07-29 22:16:12.885  5388  5417 I ActivityManager: Start proc 13004:com.topjohnwu.magisk/u0a251 for pre-top-activity {com.topjohnwu.magisk/com.topjohnwu.magisk.ui.MainActivity}
07-29 22:16:12.985 13004 13004 V GraphicsEnvironment: ANGLE Developer option for 'com.topjohnwu.magisk' set to: 'default'
07-29 22:16:12.986 13004 13004 V GraphicsEnvironment: ANGLE GameManagerService for com.topjohnwu.magisk: false
07-29 22:16:13.073  5306  5308 E Magisk  : pkg: APK signature mismatch: /data/app/~~krn7_P6YhCO6wsaM6DuHNw==/com.topjohnwu.magisk-6V6BbOlZYiJu3yThSKBn7w==/base.apk
07-29 22:16:13.098 13037 13037 I Magisk  : pm_uninstall: com.topjohnwu.magisk
07-29 22:16:13.131  5388  5416 I ActivityManager: Force stopping com.topjohnwu.magisk appid=10251 user=-1: deletePackageX
07-29 22:16:13.132  5388  5416 I ActivityManager: Killing 13004:com.topjohnwu.magisk/u0a251 (adj 0): stop com.topjohnwu.magisk due to deletePackageX
07-29 22:16:13.133  5388  5416 W ActivityTaskManager: Force removing ActivityRecord{7d81d96 u0 com.topjohnwu.magisk/.ui.MainActivity t540 f}}: app died, no saved state
07-29 22:16:13.139  4148  4370 E installd: Couldn't opendir /data/user/10/com.topjohnwu.magisk: No such file or directory
07-29 22:16:13.139  4148  4370 E installd: Failed to delete /data/user/10/com.topjohnwu.magisk: No such file or directory
07-29 22:16:13.140  4148  4370 E installd: Couldn't opendir /data/user_de/10/com.topjohnwu.magisk: No such file or directory
07-29 22:16:13.140  4148  4370 E installd: Failed to delete /data/user_de/10/com.topjohnwu.magisk: No such file or directory
07-29 22:16:13.156  5388  5435 W PackageManager: com.android.server.pm.Installer$InstallerException: android.os.ServiceSpecificException: Failed to delete /data/user_de/10/com.topjohnwu.magisk (code 2)
07-29 22:16:13.260     0     0 I [5: PackageManager: 5435] sdcardfs: removing com.topjohnwu.magisk
07-29 22:16:13.339  5388  5416 W WindowManager: Failed to deliver inset state change to w=Window{7f8d1da u0 com.topjohnwu.magisk/com.topjohnwu.magisk.ui.MainActivity}
07-29 22:16:13.339  5388  5416 W WindowManager: android.os.DeadObjectException
07-29 22:16:13.339  5388  5416 W WindowManager: 	at android.os.BinderProxy.transactNative(Native Method)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at android.os.BinderProxy.transact(BinderProxy.java:571)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at android.view.IWindow$Stub$Proxy.insetsControlChanged(IWindow.java:687)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.WindowState.notifyInsetsControlChanged(WindowState.java:4037)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.InsetsStateController.lambda$notifyPendingInsetsControlChanged$6$InsetsStateController(InsetsStateController.java:552)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.InsetsStateController$$ExternalSyntheticLambda1.run(Unknown Source:2)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.WindowAnimator.executeAfterPrepareSurfacesRunnables(WindowAnimator.java:345)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.RootWindowContainer.performSurfacePlacementNoTrace(RootWindowContainer.java:887)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.RootWindowContainer.performSurfacePlacement(RootWindowContainer.java:824)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.WindowSurfacePlacer.performSurfacePlacementLoop(WindowSurfacePlacer.java:177)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.WindowSurfacePlacer.performSurfacePlacement(WindowSurfacePlacer.java:126)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.WindowSurfacePlacer.performSurfacePlacement(WindowSurfacePlacer.java:115)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.WindowSurfacePlacer.continueLayout(WindowSurfacePlacer.java:97)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.ActivityTaskManagerService.continueWindowLayout(ActivityTaskManagerService.java:4355)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.wm.ActivityTaskManagerService$LocalService.handleAppDied(ActivityTaskManagerService.java:5941)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.am.ActivityManagerService.handleAppDiedLocked(ActivityManagerService.java:3053)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.am.ProcessList.removeProcessLocked(ProcessList.java:2958)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.am.ProcessList.killPackageProcessesLSP(ProcessList.java:2903)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.am.ActivityManagerService.forceStopPackageLocked(ActivityManagerService.java:4188)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.am.ActivityManagerService$MainHandler.handleMessage(ActivityManagerService.java:1706)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at android.os.Handler.dispatchMessage(Handler.java:106)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at android.os.Looper.loopOnce(Looper.java:201)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at android.os.Looper.loop(Looper.java:288)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at android.os.HandlerThread.run(HandlerThread.java:67)
07-29 22:16:13.339  5388  5416 W WindowManager: 	at com.android.server.ServiceThread.run(ServiceThread.java:44)
07-29 22:16:13.342  5388  7931 I WindowManager: WIN DEATH: Window{7f8d1da u0 com.topjohnwu.magisk/com.topjohnwu.magisk.ui.MainActivity}
07-29 22:16:13.343  5388  7931 W InputManager-JNI: Input channel object '7f8d1da com.topjohnwu.magisk/com.topjohnwu.magisk.ui.MainActivity (client)' was disposed without first being removed with the input manager!
07-29 22:16:13.399  5388  5664 V ActivityManager: Got obituary of 13004:com.topjohnwu.magisk
07-29 22:16:13.483  5388  5409 W InputManager-JNI: Input channel object '449dd70 Splash Screen com.topjohnwu.magisk (client)' was disposed without first being removed with the input manager!
07-29 22:16:13.500  5538  5609 E BufferQueueProducer: [ViewRootImpl[magisk]#12(BLAST Consumer)12](id:15a20000000c,api:0,p:-1,c:5538) disconnect: not connected (req=1)
07-29 22:16:13.766  5388  5435 I ActivityManager: Force stopping com.topjohnwu.magisk appid=10251 user=0: pkg removed
07-29 22:16:13.798  5306  5308 W Magisk  : pkg: cannot find com.topjohnwu.magisk for user=[0]
07-29 22:16:13.995  6941  6941 I Finsky  : [2] plc.n(8): Invalidating cached PackageState for com.topjohnwu.magisk

icedream avatar Jul 29 '22 20:07 icedream

Invalid bug report, automatically closed. Please report issues using the latest debug Magisk build (version code: 25201).

MagiskBot avatar Jul 29 '22 20:07 MagiskBot

@topjohnwu Not sure how special case issues like this are handled in your repository, but I did explain the situation for why this can not be reproduced on the debug build. Can you let me know whether this is still to be seen as invalid?

icedream avatar Jul 29 '22 20:07 icedream

07-29 20:14:02.760  5306  5306 I : Magisk 25.2(25200) daemon started
07-29 20:14:02.761  5306  5306 I : * Device API level: 32
07-29 20:14:02.770  5306  5308 I : ** post-fs-data mode running
07-29 20:14:02.774  5306  5308 I : * Mounting mirrors
07-29 20:14:02.774  5306  5308 I : link: /dev/lqIgKb/.magisk/mirror/cache
07-29 20:14:02.774  5306  5308 I : mount: /dev/lqIgKb/.magisk/mirror/data
07-29 20:14:02.774  5306  5308 I : link: /dev/lqIgKb/.magisk/mirror/system
07-29 20:14:02.775  5306  5308 I : mount: /dev/lqIgKb/.magisk/mirror/system_root
07-29 20:14:02.775  5306  5308 I : link: /dev/lqIgKb/.magisk/mirror/vendor
07-29 20:14:02.775  5306  5308 I : link: /dev/lqIgKb/.magisk/mirror/product
07-29 20:14:02.775  5306  5308 I : link: /dev/lqIgKb/.magisk/mirror/system_ext
07-29 20:14:02.841  5306  5308 I : * Initializing Magisk environment
07-29 20:14:03.330  5306  5308 I : * Running post-fs-data.d scripts
07-29 20:14:03.332  5306  5308 I : * Running module post-fs-data scripts
07-29 20:14:03.332  5306  5308 I : * Loading modules
07-29 20:14:03.721  5306  5308 I : ** post-fs-data mode running
07-29 20:14:03.724  5306  5308 I : * Mounting mirrors
07-29 20:14:03.724  5306  5308 E : symlink /cache->/dev/lqIgKb/.magisk/mirror/cache failed with 17: File exists
07-29 20:14:03.724  5306  5308 I : link: /dev/lqIgKb/.magisk/mirror/cache
07-29 20:14:03.725  5306  5308 E : mount /dev/lqIgKb/.magisk/block/data->/dev/lqIgKb/.magisk/mirror/data failed with 16: Device or resource busy
07-29 20:14:03.725  5306  5308 I : mount: /dev/lqIgKb/.magisk/mirror/data
07-29 20:14:03.729  5306  5308 I : * Initializing Magisk environment
07-29 20:14:03.729  5306  5308 E : open: /dev/lqIgKb/stub.apk failed with 2: No such file or directory

post-fs-data ran twice. I think your ROM is messed up. Try to do a data wipe or change to another ROM (like #877)

canyie avatar Jul 30 '22 04:07 canyie

We already have stage_lock and DAEMON_STATE which should prevent this.

vvb2060 avatar Jul 30 '22 04:07 vvb2060

Wiping /data does not help: Magisk killing itself occurs the moment that the phone uses encryption after any wipe. I've now tested this on two separate ROMs (PixelExperience for S8 and the one mentioned in the issue description), both times fully wiping everything beforehand, then doing the usual device setup up to enabling encryption, then installing Magisk, patching the boot image, etc.

I also noticed if I use 24.3 instead of 25.x (where the APK signature mismatch check does not exist), if I try to enable Zygisk and reboot, Zygisk never gets detected as enabled. I originally considered this to be an unrelated issue but this may be yet another consequence of this issue.

My thoughts on the post-fs-data dupe trigger: Maybe post-fs-data is triggered once due to loading the decryption prompt and then once again for the full boot?

icedream avatar Aug 02 '22 01:08 icedream

Does your device use full-disk encryption(FDE)? If you don't know what's it, execute getprop ro.crypto.type. A full bootlog (logcat when it boots) is also required

canyie avatar Aug 02 '22 03:08 canyie

do you think maybe it is unofficial? careful could brick it.

On Tue, Aug 2, 2022, 3:45 AM ncc1701-enterprise @.***> wrote:

I'm facing the same behaviour on SM-G920F (S6) with stock Android 7. Update 24.3 -> 25.x results in Magisk Manager not detecting root or phone not booting, depending on wether the update was flashed via recovery or done with Magisk Manager. Also, even though I enable Zygisk the Manager reports it as being disabled after reboot.

— Reply to this email directly, view it on GitHub https://github.com/topjohnwu/Magisk/issues/6148#issuecomment-1202134875, or unsubscribe https://github.com/notifications/unsubscribe-auth/AWIIQL5VM4ZWEYV2YCG7OG3VXDGZVANCNFSM55B4DMKA . You are receiving this because you are subscribed to this thread.Message ID: @.***>

BillingCode avatar Aug 02 '22 07:08 BillingCode

@canyie

Does your device use full-disk encryption(FDE)? If you don't know what's it, execute getprop ro.crypto.type.

Output is block.

A full bootlog (logcat when it boots) is also required

Getting back to you with a full bootlog later.

icedream avatar Aug 02 '22 10:08 icedream

08-02 10:48:38.446  3911  4021 I Cryptfs : Password matches
08-02 10:48:38.446  3911  4021 D Cryptfs : test_mount_encrypted_fs(): Master key saved
08-02 10:48:39.449  3911  5759 I Cryptfs : cryptfs_restart
08-02 10:48:39.450  3911  5759 D Cryptfs : Just asked init to shut down class main
08-02 10:48:39.456     0     0 I [5:           init:    1] init: processing action (vold.decrypt=trigger_shutdown_framework) from (/system/etc/init/hw/init.rc:1191)
08-02 10:48:41.454  3911  5759 W Cryptfs : found sub-directory mount /data - /data/user/0
08-02 10:48:41.469  3911  5759 W Cryptfs : umount sub-directory mount /data/user/0
08-02 10:48:41.671  3911  5759 W Cryptfs : sending SIGTERM to processes with open files
08-02 10:48:41.783  3911  5759 W vold    : Found symlink /proc/4032/fd/11 referencing /data/adb/magisk.db
08-02 10:48:42.014  3911  5759 W vold    : Sending Terminated to pid 4032 (magiskd, /dev/8MbuM/magisk64)
08-02 10:48:42.114  3911  5759 W Cryptfs : sending SIGKILL to processes with open files
08-02 10:48:42.183  3911  5759 W vold    : Found symlink /proc/4032/fd/11 referencing /data/adb/magisk.db
08-02 10:48:42.293  3911  5759 W vold    : Sending Killed to pid 4032 (magiskd, /dev/8MbuM/magisk64)

vvb2060 avatar Aug 02 '22 13:08 vvb2060

No it is not the actual reason. magiskd skipped the first post-fs-data correctly, and at that time it can be killed safely. The real reason is post-fs-data gets triggered twice after /data is decrypted.

canyie avatar Dec 25 '22 06:12 canyie