Square Enix' red herring

To get games to unlock on the defunct OUYA gaming console, I wrote an Xposed module that disables encryption for purchase receipt requests and responses that the games send and receive.

While it worked for many games, users reported that Final Fantasy III crashes when my plain-purchases module is enabled. adb logcat shows the following stacktrace:

E/AndroidRuntime: *** FATAL EXCEPTION IN SYSTEM PROCESS: main
   java.lang.SecurityException: 1466 does not have permission:android.permission.CLEAR_APP_USER_DATA to clear datafor process:de.cweiske.ouya.plainpurchases
       at android.os.Parcel.readException(Parcel.java:1425)
       at android.os.Parcel.readException(Parcel.java:1379)
       at android.app.ActivityManagerProxy.clearApplicationUserData(ActivityManagerNative.java:2889)
       at com.android.commands.pm.Pm.runClear(Pm.java:1126)
       at com.android.commands.pm.Pm.run(Pm.java:116)
       at com.android.commands.pm.Pm.main(Pm.java:75)
       at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method)
       at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:235)
       at de.robv.android.xposed.XposedBridge.main(XposedBridge.java:135)
       at dalvik.system.NativeStart.main(Native Method)

Final Fantasy 3 is not the only game that shows this behavior; many Square Enix games exhibit this behavior.

Investigation​

FF3 for Android/OUYA contains a native library lib__57d5__.so which seems to be the source of the problem. Fortunately for me, the Xposed author had a look at that library before:

Ok, whatever Final Fantasy does there: It looks like some very dirty coding.

• com/square_enix/android_googleplay/FFIV_GP/MainActivitya loads lib__57d5__.so and then calls native function MainActivityb.a(I)I with some random (?) integer constants
• Actually already the library loading fails because somewhere during the initialization, it calls sh -c pm clear <package> for the Xposed modules, which fails with a permission error and crashes the process
• [...]

To summarize: A strange native library in FF seems to get all /data/app/*-?.apk entries from the memory mapping file and tries to clear the data for them.

So the lib tries to clear the application user data for all apks that somehow linger in the memory of the FF3 game. It does not do this directly, but by opening a shell and using the android package manager command line tool pm:

$ sh -c pm clear packagename

After reading the sources of pm I came to the following call stack:

final fantasy 3
+ lib__57d5__.so
  + sh -c pm clear $package
    + android.app.ActivityManagerProxy::clearApplicationUserData
      + ?? IPackageDataObserver - transact(CLEAR_APP_DATA_TRANSACTION)
           something with binder
        + ??? PackageManager::clearApplicationUserData()
          + com.android.server.pm.PackageManagerService::clearApplicationUserData
            (final String packageName, final IPackageDataObserver observer, final int userId)

The pm cli tool does not directly call the package manager, but - to my limited understanding - uses some Android IPC mechanism to call the one authorative instance of the actual package manager.

Attempt #1: Hack package manager service​

At first I wrote an xposed module that hooked into PackageManagerService::clearApplicationUserData and simply said "success" when the data of my own module were to be cleaned:

import java.lang.reflect.Method;
import de.robv.android.xposed.IXposedHookLoadPackage;
import de.robv.android.xposed.XC_MethodHook;
import de.robv.android.xposed.XposedBridge;
import de.robv.android.xposed.XposedHelpers;
import de.robv.android.xposed.callbacks.XC_LoadPackage;
 
public class PlainPurchases implements IXposedHookLoadPackage
{
    @Override
    public void handleLoadPackage(XC_LoadPackage.LoadPackageParam lpparam)
    {
        XposedHelpers.findAndHookMethod(
            "com.android.server.pm.PackageManagerService",
            lpparam.classLoader,
            "clearApplicationUserData",
            String.class,
            "android.content.pm.IPackageDataObserver",
            int.class,
            new XC_MethodHook() {
                @Override
                protected void beforeHookedMethod(MethodHookParam param) throws Throwable {
                    String packageName = (String) param.args[0];
                    XposedBridge.log("clearApplicationUserData: " + packageName);
                    if (packageName.equals("de.cweiske.ouya.plainpurchases")) {
                        param.setResult(null);
 
                        //we do not have direct access to IPackageDataObserver, so we have to dance
                        Object observer = param.args[1];
                        if(observer != null) {
                            Class<?> iPackageDataObserverClass = Class.forName("android.content.pm.IPackageDataObserver");
                            Class<?>[] paramTypes = {String.class, boolean.class};
                            Method onRemoveCompletedMethod = iPackageDataObserverClass.getMethod("onRemoveCompleted", paramTypes);
                            Object[] params = {packageName, true};
                            try {
                                onRemoveCompletedMethod.invoke(observer, params);
                                //observer.onRemoveCompleted(packageName, true);
                            } catch (Exception e) {
                                XposedBridge.log("Observer no longer exists.");
                            }
                        }
                        //end dance
                    }
                }
            }
        );
    }
}

The unaccessible IPackageDataObserver made it a bit hard to call the right methods, but it was still relatively easy. Unfortunately, it did not work at all because it was too late: ActivityManagerProxy.clearApplicationUserData() already does the permission checks!

Attempt #2: Hack activity manager proxy​

My goal was to hook into ActivityManagerProxy that does the IPC call to the package manager.

This proved to be extremely hard for me because hooking into command line tools with IXposedHookCmdInit is not supported anymore by Xposed: See XDA: Hook cmds (PM) and the XPosed API changelog for 2.6:

IXposedHookCmdInit is deprecated now, initCmdApps() won't be called anymore unless an undocumented file has been created. Only two modules used it, both got rid of it without any loss of functionality.

Rolling back my OUYA's XPosed from version 2.6.1 (API v31) to 2.5.1 (API v50) worked, but then I faced the most difficult problem: I could not compile the code, because the compileOnly de.robv.android.xposed:api dependency is only available for API version 53 and higher - and 52 was the last one with support for command line tool hooks :/

It took quite some time to find an older XposedBridgeApi jar file, but eventually one turned up: XposedBridgeApi-52.jar. Moving that to the module's lib/ directory let me compile the module with the cli hook! Now I faced a very strange error:

I/Xposed: Running ROM 'JZO54L-OUYA' with fingerprint 'OUYA/ouya_1_1/ouya_1_1:4.1.2/JZO54L-OUYA/1427:user/test-keys'
I/Xposed: Loading modules from /data/app/de.cweiske.ouya.plainpurchases-2.apk
I/Xposed:   Loading class de.cweiske.ouya.plainpurchases.PlainPurchases
I/Xposed: java.lang.IllegalAccessError: Class ref in pre-verified class resolved to unexpected implementation
        at dalvik.system.DexFile.defineClass(Native Method)
        at dalvik.system.DexFile.loadClassBinaryName(DexFile.java:211)
        at dalvik.system.DexPathList.findClass(DexPathList.java:315)
        at dalvik.system.BaseDexClassLoader.findClass(BaseDexClassLoader.java:58)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:501)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:461)
        at de.robv.android.xposed.XposedBridge.loadModule(XposedBridge.java:441)
        at de.robv.android.xposed.XposedBridge.loadModules(XposedBridge.java:407)
        at de.robv.android.xposed.XposedBridge.main(XposedBridge.java:121)
        at dalvik.system.NativeStart.main(Native Method)

The source of the problem was that I moved XposedBridgeApi-52.jar into the lib/ folder, which meant it got compiled into the xposed module jar file. Now on the OUYA, there were suddenly two implementations of the bridge API, and the JVM could not decide which was the right one.

I moved it into a different directory, told gradle/Android Studio to use it for compilation only and could load the mod without problems!

import java.lang.reflect.Method;
 
import de.robv.android.xposed.IXposedHookCmdInit;
import de.robv.android.xposed.XC_MethodHook;
import de.robv.android.xposed.XposedBridge;
import de.robv.android.xposed.XposedHelpers;
 
public class PlainPurchases implements IXposedHookCmdInit
{
    @Override
    public void initCmdApp(StartupParam startupParam) throws Throwable {
        if (!startupParam.startClassName.equals("com.android.commands.pm.Pm")) {
            return;
        }
 
        XposedHelpers.findAndHookMethod(
            "android.app.ActivityManagerProxy",
            null,
            "clearApplicationUserData",
            String.class,
            "android.content.pm.IPackageDataObserver",
            int.class,
            new XC_MethodHook() {
                @Override
                protected void beforeHookedMethod(MethodHookParam param) throws Throwable {
                    String packageName = (String) param.args[0];
                    XposedBridge.log("clearApplicationUserData: " + packageName);
                    if (!packageName.equals("de.cweiske.ouya.plainpurchases")) {
                        return;
                    }
 
                    param.setResult(true);
 
                    //we do not have direct access to IPackageDataObserver, so we have to dance
                    Object observer = param.args[1];
                    if(observer != null) {
                        Class<?> iPackageDataObserverClass = Class.forName("android.content.pm.IPackageDataObserver");
                        Class<?>[] paramTypes = {String.class, boolean.class};
                        Method onRemoveCompletedMethod = iPackageDataObserverClass.getMethod("onRemoveCompleted", paramTypes);
                        Object[] params = {packageName, true};
                        try {
                            onRemoveCompletedMethod.invoke(observer, params);
                            //observer.onRemoveCompleted(packageName, true);
                        } catch (Exception e) {
                            XposedBridge.log("Observer no longer exists.");
                        }
                    }
                    //end dance
                }
            }
        );
    }
}

Success?​

Running pm clear ... from shell as limited user worked flawlessly and gave exit code 0 and no exceptions! Now I had beaten Square Enix! I started Final Fantasy 3 via shell:

$ adb shell am start -n com.square_enix.android_OUYA.FFIII/com.square_enix.FFIII_J.MainActivity

... and FF3 stopped as it had before:

I/Xposed: clearApplicationUserData: de.cweiske.ouya.plainpurchases
D/AndroidRuntime: Shutting down VM
I/AndroidRuntime: NOTE: attach of thread 'Binder_3' failed
D/dalvikvm: JIT code cache reset in 0 ms (86452 bytes 1/0)
D/dalvikvm: Debugger has detached; object registry had 1 entries
D/Zygote: Process 1572 exited cleanly (1)
I/ActivityManager: Process com.square_enix.android_OUYA.FFIII (pid 1572) has died.
W/ActivityManager: Force removing ActivityRecord{420f33f0 com.square_enix.android_OUYA.FFIII/com.square_enix.FFIII_J.MainActivity}: app died, no saved state

lib__57d5__.so did not care about pm's exit code, it always stops when it detects that XPosed is running.

I'm very sure that the SecurityException was just a red herring to make people spend time with a pretty difficult problem that has nothing to do with the actual problem.

/me tips his hat to the lib__57d5__.so developers.

Update 2023-01-10: We have a solution.

Links​

• Experiences in Debugging Non-Symbol Android Shared Library