[Android N]KeyStore mBinder成员空指针引起system process不断重启_aloge %s 空指针

本地编译Android N项目得Rom刷机后，发现重启回到值SYSTEM_PROCESS无法启动，一直重启停留再开机动画阶段。

---

经查，发现android.security.keystore对应的service binder对象为NULL，报了空指针异常（LOG如下所示）。

--------- beginning of crash
01-01 00:54:27.593  1102  1102 E AndroidRuntime: *** FATAL EXCEPTION IN SYSTEM PROCESS: main
01-01 00:54:27.593  1102  1102 E AndroidRuntime: java.lang.RuntimeException: Error receiving broadcast Intent { act=android.intent.action.USER_STARTED flg=0x50000010 (has extras) } in com.android.server.ConnectivityService$3@26aa3ad
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:1174)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at android.os.Handler.handleCallback(Handler.java:836)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at android.os.Handler.dispatchMessage(Handler.java:103)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at android.os.Looper.loop(Looper.java:203)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.server.SystemServer.run(SystemServer.java:432)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.server.SystemServer.main(SystemServer.java:286)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at java.lang.reflect.Method.invoke(Native Method)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1084)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:945)
01-01 00:54:27.593  1102  1102 E AndroidRuntime: Caused by: java.lang.NullPointerException: Attempt to invoke interface method 'int android.security.IKeystoreService.exist(java.lang.String, int)' on a null object reference
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at android.security.KeyStore.contains(KeyStore.java:210)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at android.security.KeyStore.contains(KeyStore.java:218)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.server.net.LockdownVpnTracker.isEnabled(LockdownVpnTracker.java:98)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.server.ConnectivityService.onUserStart(ConnectivityService.java:4060)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.server.ConnectivityService.-wrap27(ConnectivityService.java)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at com.android.server.ConnectivityService$3.onReceive(ConnectivityService.java:4114)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:1164)
01-01 00:54:27.593  1102  1102 E AndroidRuntime:    ... 8 more
01-01 00:54:27.643  1102  1102 D AMEventHook: onEvent: AM_EndOfErrorDumpThread
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22

经此LOG跟踪，发现是ConncetivityService在收到android.intent.action.USER_STARTED广播后，进行响应处理时调用了KeyStore的mBinder成员为空，导致系统进程无法正常地运行。

/frameworks/base/keystore/java/android/security/KeyStore.java

    public boolean contains(String key, int uid) {
        try {
            return mBinder.exist(key, uid) == NO_ERROR;//mBinder == NULL
        } catch (RemoteException e) {
            Log.w(TAG, "Cannot connect to keystore", e);
            return false;
        }
    }

    public boolean contains(String key) {
        return contains(key, UID_SELF);
    }
1
2
3
4
5
6
7
8
9
10
11
12

ConnectivityService响应广播时，通过LockdownVpnTracker.isEnabled()，间接地使用KeyStore的getInstance()方法和contains()方法。
/frameworks/base/services/core/java/com/android/server/ConnectivityService.java

    public static boolean isEnabled() {
        return KeyStore.getInstance().contains(Credentials.LOCKDOWN_VPN);
    }
1
2
3

---

经此，调用关系很清晰简单，问题也很明显，现在需要确定的是时序问题，看看是android.security.keystore这个服务启动绑定失败还是时序上的小偏差，前者的可能性更大，下面进行验证。

首先，看看KeyStore的mBinder怎么来的。
/frameworks/base/keystore/java/android/security/KeyStore.java

    private KeyStore(IKeystoreService binder) {
        mBinder = binder;
        mContext = getApplicationContext();
    }

    public static KeyStore getInstance() {
        IKeystoreService keystore = IKeystoreService.Stub.asInterface(ServiceManager
                .getService("android.security.keystore"));//
        Log.i(TAG, "---->KeyStore getInstance on keystore file-- xdy ----->");
        return new KeyStore(keystore);
    }
1
2
3
4
5
6
7
8
9
10
11

是从ServiceManager中根据android.security.keystore去获取对应的服务，这就需要看是谁往ServiceManager中注册了此服务。

经过一番搜寻，发现是keystore_main.cpp中有个main方法，往SM中addService。
/system/security/keystore/keystore_main.cpp

int main(int argc, char* argv[]) {
    ALOGE("------------> system --> security --> xdy1--->");
    if (argc < 2) {
        ALOGE("A directory must be specified!");
        return 1;
    }
    ALOGE("------------> system --> security --> xdy2--->");
    if (chdir(argv[1]) == -1) {
        ALOGE("chdir: %s: %s", argv[1], strerror(errno));
        return 1;
    }

    ALOGE("------------> system --> security --> xdy3--->");

    Entropy entropy;
    if (!entropy.open()) {
        return 1;
    }
    ALOGE("------------> system --> security --> xdy4--->");

    keymaster2_device_t* dev;
    if (keymaster_device_initialize(&dev)) {
        ALOGE("keystore keymaster could not be initialized; exiting");
        return 1;
    }

    ALOGE("------------> system --> security --> xdy5--->");

    keymaster2_device_t* fallback;
    if (fallback_keymaster_device_initialize(&fallback)) {
        ALOGE("software keymaster could not be initialized; exiting");
        return 1;
    }

    ALOGE("------------> system --> security --> xdy6--->");

    if (configure_keymaster_devices(dev, fallback)) {
        ALOGE("Keymaster devices could not be configured; exiting");
        return 1;
    }

    ALOGE("------------> system --> security --> xdy7--->");

    if (configure_selinux() == -1) {
        return -1;
    }

    ALOGE("------------> system --> security --> xdy8--->");

    KeyStore keyStore(&entropy, dev, fallback);
    keyStore.initialize();
    android::sp<android::IServiceManager> sm = android::defaultServiceManager();
    android::sp<android::KeyStoreService> service = new android::KeyStoreService(&keyStore);
    android::status_t ret = sm->addService(android::String16("android.security.keystore"), service); ///核心代码
    if (ret != android::OK) {
        ALOGE("Couldn't register binder service!");
        ALOGE("------------> system --> security --> xdy9--->");
        return -1;
    }

    ALOGE("------------> system --> security --> xdy10--->");

    /*
     * We're the only thread in existence, so we're just going to process
     * Binder transaction as a single-threaded program.
     */
    android::IPCThreadState::self()->joinThreadPool();

    keymaster_device_release(dev);
    return 1;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71

上方自添加了一些ALOGE LOG。

---

经过重新编译，重新刷机，发现reboot不再复现该问题，但二者时序可以从下方log看出。
1.keystore

2.USER_STARTED

3.ConnectivityService启动

 1579: 01-01 03:30:54.638540  1100  1100 I SystemServer: StartConnectivityService
 1580: 01-01 03:30:54.683255  1100  1100 D ConnectivityService: ConnectivityService starting up
1
2

---

综合上述LOG，最先addService，然后ConnectivityService被实例化启动，AMS发送USER_STARTED广播，ConnectivityService响应。

所以结论是，在keystore_main.cpp的main方法执行时,addService注册binder service不成功，应该会有如下log输出才对。

    android::status_t ret = sm->addService(android::String16("android.security.keystore"), service);
    if (ret != android::OK) {
        ALOGE("Couldn't register binder service!");//LOG输出
        return -1;
    }
1
2
3
4
5
6

其实从addService出现的地方就应该能够基本确定了，keystore是要在ConnectivityService之前的。

---

遗憾的是复现的版本，只是从终端logcat一部分log，未抓取到keystore部分的log，且暂记录之。