package info not found issue

之前遇到一个问题，如下：

https://cmi-web-tools.amazon.com/crashboard/?start=2017-04-21&end=2017-04-28&dtype=ALL&cdesc=7814d32f7103b7cadd6a3a7e09a678d98c499e78

[Events]java.lang.RuntimeException: Unable to instantiate application com.amazon.venezia.VeneziaApplication: java.lang.IllegalStateException: Unable to get package info for com.amazon.venezia; is package not installed?at android.app.LoadedApk.makeApplication(LoadedApk.java:596)at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4730)at android.app.ActivityThread.access$1500(ActivityThread.java:160)at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1381)at android.os.Handler.dispatchMessage(Handler.java:102)at android.os.Looper.loop(Looper.java:135)at android.app.ActivityThread.main(ActivityThread.java:5466)at java.lang.reflect.Method.invoke(Native Method)at java.lang.reflect.Method.invoke(Method.java:372)at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:984)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:779)Caused by: java.lang.IllegalStateException: Unable to get package info for com.amazon.venezia; is package not installed?at android.app.LoadedApk.initializeJavaContextClassLoader(LoadedApk.java:435)at android.app.LoadedApk.makeApplication(LoadedApk.java:587)... 10 more

从crash堆栈信息看，是android framework 在启动应用程序 com.amazon.venezia 的过程中出现问题。 出现问题的原因是 LoadedApk.makeApplication 中没有找到当前要启动的package的信息。在initializeJavaContextClassLoader函数中，用PMS.getPackageInfo查询package信息，但是结果是null，所以抛出异常。

420    private void initializeJavaContextClassLoader() {425426        IPackageManager pm = ActivityThread.getPackageManager();427        android.content.pm.PackageInfo pi;428        try {429            pi = pm.getPackageInfo(mPackageName, 0, UserHandle.myUserId());430        } catch (RemoteException e) {431            throw new IllegalStateException("Unable to get package info for "432                    + mPackageName + "; is system dying?", e);433        }434        if (pi == null) {435            throw new IllegalStateException("Unable to get package info for "436                    + mPackageName + "; is package not installed?");437        }

从PMS.getPackageInfo的实现看，返回null的原因有几个。

1. 指定的用户不存在

2. 制定的package不存在

3. 制定的package被hidden

2075    public PackageInfo getPackageInfo(String packageName, int flags, int userId) {2076        if (!sUserManager.exists(userId)) return null;2077        enforceCrossUserPermission(Binder.getCallingUid(), userId, false, false, "get package info");2078        // reader2079        synchronized (mPackages) {2080            PackageParser.Package p = mPackages.get(packageName);2081            if (DEBUG_PACKAGE_INFO)2082                Log.v(TAG, "getPackageInfo " + packageName + ": " + p);2083            if (p != null) {2084                return generatePackageInfo(p, flags, userId);2085            }2086            if((flags & PackageManager.GET_UNINSTALLED_PACKAGES) != 0) {2087                return generatePackageInfoFromSettingsLPw(packageName, flags, userId);2088            }2089        }2090        return null;2091    }

从一些辅助的logs分析，可以得到一下信息。

1. crash的进程属于user 0

2. com.amazon.venezia 应用是因为其他的应用访问了它里面的ContentProvider 而被启动的。

05-03 16:16:08.716   907  1368 I am_proc_start: [0,8329,32095,com.amazon.venezia,content provider,com.amazon.venezia/com.amazon.mas.client.appsharing.data.AppSharingProvider]
05-03 16:16:08.717   907  1368 I ActivityManager: Start proc 8329:com.amazon.venezia/u0a22095 for content provider com.amazon.venezia/com.amazon.mas.client.appsharing.data.AppSharingProvider

05-03 16:16:08.757   907  1710 I am_proc_bound: [0,8329,com.amazon.venezia]
05-03 16:16:08.948  8329  8329 I AndroidRuntime: To Report FATAL to activityManagerService

05-03 16:16:08.971   907   956 I am_crash: [8329,0,com.amazon.venezia,1083817541,java.lang.IllegalStateException,Unable to get package info for com.amazon.venezia; is package not installed?,LoadedApk.java,435]
05-03 16:16:09.182   907   926 I CrashDescriptorUtil: addErrorToCommonLog Hash already present in file
05-03 16:16:09.191   907   927 W ActivityManager: Skipping crash dialog of ProcessRecord{3ede267e 8329:com.amazon.venezia/u0a22095}: background
05-03 16:16:09.191  8329  8329 I AndroidRuntime: Finished reporting FATAL to activityManagerService
05-03 16:16:09.249   907   923 I ActivityManager: Process com.amazon.venezia (pid 8329) has died
05-03 16:16:09.278   907   923 I ActivityManager: Start proc 8361:com.amazon.venezia/u0a22095 for restart com.amazon.venezia
05-03 16:16:09.434  8361  8361 I AndroidRuntime: To Report FATAL to activityManagerService
05-03 16:16:09.468   907  1710 W ActivityManager: Process com.amazon.venezia has crashed too many times: killing!
05-03 16:16:09.470   907  1710 I ActivityManager: Killing 8361:com.amazon.venezia/u0a22095 (adj 13): crash

05-03 16:16:09.576   907  1368 W ActivityManager: Unable to launch app com.amazon.venezia/32095 for provider com.amazon.mas.client.appsharing: launching app became null
05-03 16:16:09.576  7794  8326 E ActivityThread: Failed to find provider info for com.amazon.mas.client.appsharing
05-03 16:16:09.577   907  1270 W ActivityManager: Spurious death for ProcessRecord{3ede267e 8361:com.amazon.venezia/u0a22095}, curProc for 8361: null

Root Casue 分析。

从上面的log分析看，导致PMS.getPackageInfo返回null的原因，不是user不存在。很可能是package已经被移除。 而com.amazon.venezia应用是system app，不太可能被用户移除，比较大的可能是该app正在升级，到之旧的app被移除，新的app还没有安装。

也就是说AMS在启动应用，和PMS升级应用的操作中，存在race condition。

场景模拟。

思路： 在应用程序进程启动application前，AMS依据ContentProvider启动applicaiton前，和PMS升级应用过程中，加入合理的延时时间，用以模拟这种race condition。

写一个应用程序，尝试去访问对应的ContentProvider。

String columns[] = new String[] { "_id" };Uri myUri = Uri.parse("content://com.amazon.mas.client.download-com.amazon.venezia");;Cursor cur = managedQuery(myUri, columns, null, null, null );if (cur != null) {    cur.close();}

实际重现

1. 确保当前系统中com.amazon.venezia没有运行。

用 adb shell ps | grep “com.amazon.venezia” 查询有没有，如果有的话，就用 adb shell kill 命令把进程杀掉。

2. 设置延时参数。

adb shell ps | grep venezia
adb shell setprop "debug.application.name" "com.amazon.venezia"
adb shell setprop "debug.getCP.delay" 3000
adb shell setprop "debug.killApp.delay" 5000
adb shell setprop "debug.application.delay" 3500
adb shell setprop "debug.removeApp.delay" 1000
adb logcat -c

3. 升级“com.amazon.venezia”，同时访问对应的ContentProvider。

adb install -r com.amazon.venezia.apk

用adb logcat -v time > log.txt 抓取logs。 如下：

05-09 14:10:54.228 E/FragmentTestActivity( 8375): OnClickListener---1
05-09 14:10:54.228 E/FragmentTestActivity( 8375): OnClickListener---2    应用程序请求ContentProvider

05-09 14:10:54.617 D/AndroidRuntime( 9626): >>>>>> START com.android.internal.os.RuntimeInit uid 0 <<<<<<
05-09 14:10:54.618 D/AndroidRuntime( 9626): CheckJNI is OFF
05-09 14:10:54.680 D/AndroidRuntime( 9626): Calling main entry com.android.commands.pm.Pm

05-09 14:10:54.803 D/DefContainer( 9638): Copying /data/local/tmp/com.amazon.venezia.apk to base.apk    升级过程初始化，即复制apk文件

05-09 14:10:55.620 W/PackageManager(  658): Centralized permission: Package com.amazon.veneziais declaring a permission com.amazon.mas.client.pdiservice.db.provider.CONTENT_PROVIDER_WRITE_com.amazon.venezia which is notdeclared in the centralized apk
05-09 14:10:55.622 W/PackageManager(  658): Centralized permission: Package com.amazon.veneziais declaring a permission com.amazon.venezia.command.shared.ACCOUNT_INFO_PROVIDER_WRITE_com.amazon.venezia which is notdeclared in the centralized apk
05-09 14:10:55.625 W/PackageManager(  658): Centralized permission: Package com.amazon.veneziais declaring a permission com.amazon.apps_unlocked.READ_STATUS which is notdeclared in the centralized apk
05-09 14:10:55.630 W/PackageManager(  658): Centralized permission: Package com.amazon.veneziais declaring a permission com.amazon.venezia.permission.alexa.app_launch which is notdeclared in the centralized apk
05-09 14:10:55.630 D/PackageManager(  658): Renaming /data/app/vmdl1020667117.tmp to /data/app/com.amazon.venezia-2
05-09 14:10:55.632 I/ActivityManager(  658): Force stopping com.amazon.venezia appid=32110 user=-1: replace sys pkg  安装前，杀掉已经启动的进程，由于加了延时，我们的目标进程venezia没有启动，所以不会被杀掉
05-09 14:10:55.632 I/ActivityManager(  658): Killing 8720:com.amazon.venezia/u0a22110 (adj 9): stop com.amazon.venezia   kill application之后，就吧package从PMS中的列表中删除

05-09 14:10:57.267 I/ActivityManager(  658): Start proc 9697:com.amazon.venezia/u0a22110 for content provider com.amazon.venezia/com.amazon.mas.client.download.query.DownloadQueueProvider             AMS 启动应用程序

05-09 14:11:00.633 W/CompatManager(  658): failed deleting the hint file for package com.amazon.venezia
05-09 14:11:00.896 D/AndroidRuntime( 9697): Shutting down VM
--------- beginning of crash
05-09 14:11:00.898 E/AndroidRuntime( 9697): FATAL EXCEPTION: main  目标进程crash
05-09 14:11:00.898 E/AndroidRuntime( 9697): Process: com.amazon.venezia, PID: 9697
05-09 14:11:00.898 E/AndroidRuntime( 9697): java.lang.RuntimeException: Unable to instantiate application com.amazon.venezia.VeneziaApplication: java.lang.IllegalStateException: Unable to get package info for com.amazon.venezia; is package not installed?
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.app.LoadedApk.makeApplication(LoadedApk.java:596)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4762)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.app.ActivityThread.access$1500(ActivityThread.java:160)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1382)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.os.Handler.dispatchMessage(Handler.java:102)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.os.Looper.loop(Looper.java:135)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.app.ActivityThread.main(ActivityThread.java:5498)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at java.lang.reflect.Method.invoke(Native Method)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at java.lang.reflect.Method.invoke(Method.java:372)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:984)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:779)
05-09 14:11:00.898 E/AndroidRuntime( 9697): Caused by: java.lang.IllegalStateException: Unable to get package info for com.amazon.venezia; is package not installed?
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.app.LoadedApk.initializeJavaContextClassLoader(LoadedApk.java:435)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     at android.app.LoadedApk.makeApplication(LoadedApk.java:587)
05-09 14:11:00.898 E/AndroidRuntime( 9697):     ... 10 more
05-09 14:11:00.899 I/AndroidRuntime( 9697): To Report FATAL to activityManagerService
05-09 14:11:00.903 I/ActivityManager(  658): handleApplicationCrash
05-09 14:11:00.976 I/ActivityManager(  658): addErrorToDropBox inserted hashcode=7a90a9884be2f9effaa48d5fbc12926e65f586fa for eventType crash.
05-09 14:11:00.984 E/ActivityManager(  658): Exception for hashCode java.lang.NullPointerException: Attempt to read from field 'android.content.pm.Signature[] android.content.pm.PackageInfo.signatures' on a null object reference
05-09 14:11:00.983 W/ResourceType(  658): Attempt to retrieve bag 0x0103003e which is invalid or in a cycle.

05-09 14:11:01.658 W/PackageManager(  658): Trying to update system app code path from /data/app/com.amazon.venezia-1 to /data/app/com.amazon.venezia-2  升级应用正式开始
05-09 14:11:01.658 W/PackageManager(  658): Package com.amazon.venezia desires unavailable shared library kcpsdk-auth; ignoring!
05-09 14:11:01.658 W/PackageManager(  658): Package com.amazon.venezia desires unavailable shared library org.json.simple; ignoring!
05-09 14:11:01.660 I/PackageManager(  658): Derived cpuAbiOverride=null
05-09 14:11:01.696 D/PackageManager(  658): Resolved nativeLibraryRoot for com.amazon.venezia to root=/data/app/com.amazon.venezia-2/lib, isa=true
05-09 14:11:01.696 D/PackageManager(  658): Abis for package[com.amazon.venezia] are primary=null secondary=null
05-09 14:11:01.697 I/PackageManager(  658): Running dexopt on: /data/app/com.amazon.venezia-2/base.apk pkg=com.amazon.venezia isa=arm vmSafeMode=false
05-09 14:11:01.739 I/dex2oat ( 9826): /system/bin/dex2oat --zip-fd=6 --zip-location=/data/app/com.amazon.venezia-2/base.apk --oat-fd=7 --oat-location=/data/dalvik-cache/arm/data@[e-mail][e-mail]@classes.dex --instruction-set=arm --compile-pic --instruction-set-features=div --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-09 14:11:01.826 I/AmazonLocationController(  837): onWifiSignalChanged : connected : true

05-09 14:11:09.108 W/ActivityManager(  658): Unable to launch app com.amazon.venezia/32110 for provider com.amazon.mas.client.download-com.amazon.venezia: launching app became null

05-09 14:11:09.112 W/ActivityManager(  658): Spurious death for ProcessRecord{7e2a94b 9697:com.amazon.venezia/u0a22110}, curProc for 9697: null
05-09 14:11:09.112 E/ActivityThread( 8375): Failed to find provider info for com.amazon.mas.client.download-com.amazon.venezia用户进程得到反馈，启动ContentProvider失败
05-09 14:11:09.113 E/FragmentTestActivity( 8375): OnClickListener---3
05-09 14:11:09.113 E/FragmentTestActivity( 8375): OnClickListener---4