1.问题描述

个人中心应用：车辆绑定之后，点击添加账号出现车辆未激活提示。

2.问题关键日志

从账号的崩溃日志中可以看到是Vechcle内部暴露出来的。

账号崩溃.png

继续跟踪vehicle堆栈

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
E/AndroidRuntime( 1115): Process: com.android.car, PID: 1115
// 崩溃最后调用方法时android.content.pm.PackageManager调用了getPackagesForUid()方法所致。
E/AndroidRuntime( 1115): java.lang.NullPointerException: Attempt to invoke virtual method 'java.lang.String[] android.content.pm.PackageManager.getPackagesForUid(int)' on a null object reference
E/AndroidRuntime( 1115): 	at android.os.Parcel.createException(Parcel.java:1956)
E/AndroidRuntime( 1115): 	at android.os.Parcel.readException(Parcel.java:1918)
E/AndroidRuntime( 1115): 	at android.os.Parcel.readException(Parcel.java:1868)
E/AndroidRuntime( 1115): 	at android.location.ILocationManager$Stub$Proxy.getLastLocation(ILocationManager.java:866)
E/AndroidRuntime( 1115): 	at android.location.LocationManager.getLastKnownLocation(LocationManager.java:1420)
E/AndroidRuntime( 1115): 	at com.android.car.CarLocationService.storeLocation(CarLocationService.java:193)
E/AndroidRuntime( 1115): 	at com.android.car.CarLocationService.access$200(CarLocationService.java:56)
E/AndroidRuntime( 1115): 	at com.android.car.CarLocationService$CarPropertyEventListener.lambda$onEvent$0(CarLocationService.java:389)
E/AndroidRuntime( 1115): 	at com.android.car.-$$Lambda$CarLocationService$CarPropertyEventListener$kbDcCpFJgPoaKrzM-WdKaZpDstE.run(Unknown Source:2)
E/AndroidRuntime( 1115): 	at com.android.car.CarLocationService.lambda$asyncOperation$6(CarLocationService.java:358)
E/AndroidRuntime( 1115): 	at com.android.car.-$$Lambda$CarLocationService$76mpQL5o-jUuJ4eRPNTgfDOA2bU.run(Unknown Source:4)
E/AndroidRuntime( 1115): 	at android.os.Handler.handleCallback(Handler.java:873)
E/AndroidRuntime( 1115): 	at android.os.Handler.dispatchMessage(Handler.java:99)
E/AndroidRuntime( 1115): 	at android.os.Looper.loop(Looper.java:193)
E/AndroidRuntime( 1115): 	at android.os.HandlerThread.run(HandlerThread.java:65)
E/AndroidRuntime( 1115): Caused by: android.os.RemoteException: Remote stack trace:
// 由于vehicle是通过AIDL远端调用到LocationManager
E/AndroidRuntime( 1115): 	at com.android.server.LocationManagerService.checkPackageName(LocationManagerService.java:2030)
E/AndroidRuntime( 1115): 	at com.android.server.LocationManagerService.getLastLocation(LocationManagerService.java:2218)
E/AndroidRuntime( 1115): 	at android.location.ILocationManager$Stub.onTransact(ILocationManager.java:159)
E/AndroidRuntime( 1115): 	at android.os.Binder.execTransact(Binder.java:731)

3.定位源码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
// /frameworks/base/services/core/java/com/android/server/LocationManagerService.java
// 调用栈：getLastLocation()  ->  checkPackageName()  
private void checkPackageName(String packageName) {
    if (packageName == null) {
        throw new SecurityException("invalid package name: " + packageName);
    }
    int uid = Binder.getCallingUid();
    // 此处由于mPackageManager是空的报的异常。查看mPackageManager在那里赋值的。
    String[] packages = mPackageManager.getPackagesForUid(uid);
    if (packages == null) {
        throw new SecurityException("invalid UID " + uid);
    }
    for (String pkg : packages) {
        if (packageName.equals(pkg)) return;
    }
    throw new SecurityException("invalid package name: " + packageName);
}

此处由于mPackageManager是空的报的异常。查看mPackageManager在那里赋值的。

1
2
3
4
5
6
7
8
public void systemRunning() {
    synchronized (mLock) {
    	if (D) Log.d(TAG, "systemRunning()");

   	 	// fetch package manager
   		mPackageManager = mContext.getPackageManager();
    	......
}

当SystemServer回调LocationManagerService.systemRunning()的时候，从Context中去获取PackageManager。

其实正常情况下PackageManagerService是在启动引导服务阶段就启动了，此处systemRunning()是在启动其他服务的方法中回调的。正常情况是不可能获取不到PackageManager的。但是偶发异常也必须应对。解决办法也很简单，在用之前判断一下空。

4.解决问题？

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
private void checkPackageName(String packageName) {
        if (packageName == null) {
            throw new SecurityException("invalid package name: " + packageName);
        }
        int uid = Binder.getCallingUid();
        // 在用之前如果是空的再次获取一下，由于mContext在构造方法中已经判空处理了，此处不用判空
        if (mPackageManager == null) {
            mPackageManager = mContext.getPackageManager();
        }
        String[] packages = mPackageManager.getPackagesForUid(uid);
        if (packages == null) {
            throw new SecurityException("invalid UID " + uid);
        }
        for (String pkg : packages) {
            if (packageName.equals(pkg)) return;
        }
        throw new SecurityException("invalid package name: " + packageName);
    }
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
private boolean doesUidHavePackage(int uid, String packageName) {
        if (packageName == null) {
            return false;
        }
    	// 同样也在doesUidHavePackage()中判断一下空，防范未然。
        if (mPackageManager == null) {
            mPackageManager = mContext.getPackageManager();
        }
        String[] packageNames = mPackageManager.getPackagesForUid(uid);
        if (packageNames == null) {
            return false;
        }
        for (String name : packageNames) {
            if (packageName.equals(name)) {
                return true;
            }
        }
        return false;
    }

5 问题反复

本以为这样修复了就解决问题了，结果重新编译系统烧写发现问题根本没有解决，由报如下错误：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
E/AndroidRuntime( 1120): Process: com.android.car, PID: 1120
// 优势LocationBlacklist为空了
E/AndroidRuntime( 1120): java.lang.NullPointerException: Attempt to invoke virtual method 'boolean com.android.server.location.LocationBlacklist.isBlacklisted(java.lang.String)' on a null object reference
E/AndroidRuntime( 1120): at android.os.Parcel.createException(Parcel.java:1956)
E/AndroidRuntime( 1120): at android.os.Parcel.readException(Parcel.java:1918)
E/AndroidRuntime( 1120): at android.os.Parcel.readException(Parcel.java:1868)
E/AndroidRuntime( 1120): at android.location.ILocationManager$Stub$Proxy.getLastLocation(ILocationManager.java:866)
E/AndroidRuntime( 1120): at android.location.LocationManager.getLastKnownLocation(LocationManager.java:1420)
E/AndroidRuntime( 1120): at com.android.car.CarLocationService.storeLocation(CarLocationService.java:193)
E/AndroidRuntime( 1120): at com.android.car.CarLocationService.access$200(CarLocationService.java:56)
E/AndroidRuntime( 1120): at com.android.car.CarLocationService$CarPropertyEventListener.lambda$onEvent$0(CarLocationService.java:389)
E/AndroidRuntime( 1120): at com.android.car.-$$Lambda$CarLocationService$CarPropertyEventListener$kbDcCpFJgPoaKrzM-WdKaZpDstE.run(Unknown Source:2)
E/AndroidRuntime( 1120): at com.android.car.CarLocationService.lambda$asyncOperation$6(CarLocationService.java:358)
E/AndroidRuntime( 1120): at com.android.car.-$$Lambda$CarLocationService$76mpQL5o-jUuJ4eRPNTgfDOA2bU.run(Unknown Source:4)
E/AndroidRuntime( 1120): at android.os.Handler.handleCallback(Handler.java:873)
E/AndroidRuntime( 1120): at android.os.Handler.dispatchMessage(Handler.java:99)
E/AndroidRuntime( 1120): at android.os.Looper.loop(Looper.java:193)
E/AndroidRuntime( 1120): at android.os.HandlerThread.run(HandlerThread.java:65)
E/AndroidRuntime( 1120): Caused by: android.os.RemoteException: Remote stack trace:
E/AndroidRuntime( 1120): at com.android.server.LocationManagerService.getLastLocation(LocationManagerService.java:2230)
E/AndroidRuntime( 1120): at android.location.ILocationManager$Stub.onTransact(ILocationManager.java:159)
E/AndroidRuntime( 1120): at android.os.Binder.execTransact(Binder.java:731)

分析原因：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
public Location getLastLocation(LocationRequest request, String packageName) {
        if (D) Log.d(TAG, "getLastLocation: " + request);
        if (request == null) request = DEFAULT_LOCATION_REQUEST;
        int allowedResolutionLevel = getCallerAllowedResolutionLevel();
        checkPackageName(packageName);  // 上面尝试改了这里
        checkResolutionLevelIsSufficientForProviderUse(allowedResolutionLevel,
                request.getProvider());
        // no need to sanitize this request, as only the provider name is used

        final int pid = Binder.getCallingPid();
        final int uid = Binder.getCallingUid();
        final long identity = Binder.clearCallingIdentity();
        try {
            // 现在mBlacklist又为null了
            if (mBlacklist.isBlacklisted(packageName)) {
                if (D) {
                    Log.d(TAG, "not returning last loc for blacklisted app: " +
                            packageName);
                }
                return null;
            }
       ......
}

从log看在checkPackageName里面修复了，下面又报空，然后看看初始化赋值。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
public void systemRunning() {
        synchronized (mLock) {
            if (D) Log.d(TAG, "systemRunning()");

            // fetch package manager
            mPackageManager = mContext.getPackageManager();  // 获取PackageManager

            // fetch power manager
            mPowerManager = (PowerManager) mContext.getSystemService(Context.POWER_SERVICE);

            // fetch activity manager
            mActivityManager
                    = (ActivityManager) mContext.getSystemService(Context.ACTIVITY_SERVICE);

            // prepare worker thread
            mLocationHandler = new LocationWorkerHandler(BackgroundThread.get().getLooper());

            // prepare mLocationHandler's dependents
            mLocationFudger = new LocationFudger(mContext, mLocationHandler);
            // 初始化mBlacklist
            mBlacklist = new LocationBlacklist(mContext, mLocationHandler);
            mBlacklist.init();
            ......
}

看到这里，发现问题一定不是那么简单了，上面获取PackageManager失败了，下面new LocationBlacklist也失败，肯定不可能！！！

所以怀疑是不是systemRunning()没有被调用。

6 思考

思考：SystemServer和原生Car是两个进程，是不是时序问题？

bootchar看启动时序.png

然后看SystemServer源码，Location创建在1253行，初始化在1893行。因此是否存在Car在此之间调用Location获取位置信息呢？ 看从日志中能不能找到线索？

Location创建.png

Locaton初始化.png

1
23.0189 44 ECU1 Syst LOGD 345 log info verbose 1 I/SystemServer( 794): MakeLocationServiceReady

从日志中看，Location在23.0189 s的时候初始化完成。

看看Car是什么时候调用getLastLocation()方法的

1
2
22.0504 21 ECU1 Andr LOGD 345 log error verbose 1 E/AndroidRuntime( 1120): at com.android.car.CarLocationService.lambda$asyncOperation$6(CarLocationService.java:358)
22.0504 22 ECU1 Andr LOGD 345 log error verbose 1 E/AndroidRuntime( 1120): at com.android.car.-$$Lambda$CarLocationService$76mpQL5o-jUuJ4eRPNTgfDOA2bU.run(Unknown Source:4)

Car在22.0504 s的时候去调用CarLocationService的getLastLocation()方法！！！！！

坐实了！！！坐实了！！！坐实了！！！

时序问题！！ 但是为什么突然会有时序问题呢？ 而且为什么Location初始化这么慢呢？正常情况15 s系统就可以启动结束了，为什么23s Location还没有初始化结束。看看各个服务启动的情况。

1
2
3
7356 2021/11/30 10:50:09.501198 11.0946 233 ECU1 Syst LOGD 345 log debug verbose 1 D/SystemServerTimingAsync( 794): AppDataPrepare took to complete: 479ms
10314 2021/11/30 10:50:18.847301 21.0279 119 ECU1 Syst LOGD 345 log debug verbose 1 D/SystemServerTiming( 794): StartAudioService took to complete: 10524ms
10318 2021/11/30 10:50:18.847362 21.0280 123 ECU1 Syst LOGD 345 log debug verbose 1 D/SystemServerTiming( 794): StartBroadcastRadioService took to complete: 1ms

从log看AudioService启动一定异常了！ 花费了10s+。

1
2
7.0301 1 ECU1 Audi LOGD 345 log info verbose 1 I/AudioFlinger( 474): Using default 3000 mSec as standby time.
21.0037 209 ECU1 Audi LOGD 345 log info verbose 1 I/AudioFlinger( 474): loadHwModule() Loaded primary audio interface, handle 10

AudioFlinger启动异常了，需要FO查看为什么启动异常了。

7 问题再现

AudioFlinger启动正常之后，发现Car开始会崩溃，继续看，还是时序问题。

1
14520 2021/12/13 18:02:06.749890 12.0864 229 ECU1 Andr LOGD 340 log error verbose 1 E/AndroidRuntime( 1125): java.lang.NullPointerException: Attempt to invoke virtual method 'java.lang.String[] android.content.pm.PackageManager.getPackagesForUid(int)' on a null object reference
1
15978 2021/12/13 18:02:07.479135 13.0594 151 ECU1 Syst LOGD 340 log info verbose 1 I/SystemServer( 866): MakeLocationServiceReady

car调用LocationManager的时间节点是12.86s，而LocationManager的systemReady()是在13.59s。说明调用时序还是有问题。

对照早期正常启动的日志，对比那个服务启动异常，发现网络模块启动异常，证据如下。

1
2
# 正常6ms
10947 2021/09/15 19:41:25.162599 12.0808 240 ECU1 Syst LOGD 339 log debug verbose 1 D/SystemServerTiming( 741): MakeNetworkStatsServiceReady took to complete: 6ms
1
2
# 异常1175ms
15704 2021/12/13 18:02:07.434853 13.0545 133 ECU1 Syst LOGD 340 log debug verbose 1 D/SystemServerTiming( 866): MakeNetworkStatsServiceReady took to complete: 1175ms

此处晚了一秒多，导致location启动时序异常。

查看tag:NetworkStats

1
2
15699 2021/12/13 18:02:07.434812 13.0543 128 ECU1 syst LOGD 340 log warn verbose 1 W/system_server( 866): Long monitor contention with owner main (866) at boolean android.os.BinderProxy.transactNative(int, android.os.Parcel, android.os.Parcel, int)(Binder.java:-2) waiters=0 in void com.android.server.net.NetworkStatsService.setUidForeground(int, boolean) for 983ms
15700 2021/12/13 18:02:07.434825 13.0543 129 ECU1 dvm_ LOGD 340 log info verbose 1 I/dvm_lock_sample( 866): [system_server,1,NetworkPolicy.uid,983,NetworkStatsService.java,835,void com.android.server.net.NetworkStatsService.setUidForeground(int, boolean),Binder.java,-2,boolean android.os.BinderProxy.transactNative(int, android.os.Parcel, android.os.Parcel, int),100]

8 终极解决办法

以上修改都没有最终解决问题，各种服务启动时序回退之后还是发现有问题。这次必须要Car服务来查问题了。

直击CarLocationService服务，查看保存定位信息逻辑。

一共有两处保存定位信息

1
2
3
4
5
6
@Override
public long onPrepareShutdown(boolean shuttingDown) {
    logd("onPrepareShutdown " + shuttingDown);
    asyncOperation(() -> storeLocation());  // 保存定位
    return 100;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
private class CarPropertyEventListener extends ICarPropertyEventListener.Stub {
	@Override
	public void onEvent(List<CarPropertyEvent> events) throws RemoteException {
		for (CarPropertyEvent event : events) {
			if (event.getEventType() == CarPropertyEvent.PROPERTY_EVENT_PROPERTY_CHANGE) {
				CarPropertyValue value = event.getCarPropertyValue();
				if (value.getPropertyId() == VehicleProperty.IGNITION_STATE) {
					int ignitionState = (Integer) value.getValue();
					logd("property ignition value: " + ignitionState);
					if (ignitionState == VehicleIgnitionState.OFF) {
						logd("ignition off");
						asyncOperation(() -> storeLocation());   //保存定位
					}
				}
			}
		}
	}
}

怀疑是否是电源管理服务是否错误所致。打开Car的日志开关，重编系统，看看日志。

1
2
14193 2021/12/23 11:43:23.675219 10.0713 158 ECU1 CarL LOGD 326 log debug verbose 1 D/CarLocationService( 1040): property ignition value: 2
14194 2021/12/23 11:43:23.675226 10.0713 159 ECU1 CarL LOGD 326 log debug verbose 1 D/CarLocationService( 1040): ignition off

第10.7秒的时候收到’伪’下电信号！！！！此时问题原因已经坐实了，因为底层取消了下点信号，上层读到的是默认值，导致默认是下电模式。