一行Log引发多线程并发问题的案例

2019年4月9日 250次阅读来源: Gityuan

这是作者在2017年处理的一个多线程并发的案例，带着大家一起来领略异常分析思路

一. 问题描述

问题表现是文件管理器（fileexplorer）应用出现java.lang.NullPointerException导致应用崩溃的问题，这是一个极低概率问题，本地无法复现，在大数据统计信息中陆陆续续的有上报，而且只出现在部分机型。

二. 问题分析

问题出在文件管理器，但最终导致异常的代码比较扑所迷离，下面就带来大家来看看这个过程。

2.1 log信息

这是Bugreport中最有价值的信息，其中pid=2153代表的是进程是com.android.fileexplorer:remote

05-10 09:52:37.082 2153 2153 E AndroidRuntime: Process: com.android.fileexplorer:remote, PID: 2153
05-10 09:52:37.082 2153 2153 E AndroidRuntime: java.lang.NullPointerException
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.content.Intent.toShortString(Intent.java:7059)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.content.Intent.toString(Intent.java:6966)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.StringBuilder.append(StringBuilder.java:202)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.app.ActivityThread$ServiceArgsData.toString(ActivityThread.java:433)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.StringBuilder.append(StringBuilder.java:202)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1559)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:110)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.os.Looper.loop(Looper.java:193)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:5316)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.reflect.Method.invokeNative(Native Method)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.reflect.Method.invoke(Method.java:515)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:832)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:648)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at dalvik.system.NativeStart.main(Native Method)

2.2 初步推测

从上面栈信息，可定位到NullPointerException发生在Intent.java中的toShortString()方法的第7059行，再找到该问题所上报机型所对应的源码如下：

public void toShortString() {
  if (comp && mComponent != null) { //step1: mComponent非空才能进入
      if (!first) {
          b.append(' ');
      }
      b.append("cmp=").append(mComponent.flattenToShortString()); //step 2: 这就是7059行出现空指针
  }
  ...
}

mComponent非空才能进入该分支，进来之后却又报出空指针异常。那么很可能是由于多线程并发导致的：在判定完step1之后，另一个线程并发修改了mComponent，导致空指针出现。到这里心中有了第一个推测：

进展1：初步推测多线程并发导致mComponent报出空指针异常。

2.3 验证推论

有了这个推论，那么接下来需要验证这个问题。既然可能是多线程并发修改导致，首要的问题就是从framework层出发，来查看所有可能导致修改mComponent的方法，并加上log本地尝试复现。

这里会遇到两个问题：

修改mComponent的方法会不会有很多？
系统中大量的Intent传递，直接在热点代码出加log，估计满屏幕都是这些信息，有效日志会被冲掉，log太多如何解决？

2.3.1 mComponent可能修改处

在这里不用担心修改mComponent的方法地方会很多，因为mComponent作为Intent.java的 private属性成员变量，一般情况下只能该类可以修改，所以只需要在Intent.java文件涉及mComponent赋值操作的地方加log。

通过搜索发现总有Intent构造函数, setClass，setClassName，setComponent，readFromParcel，fillIn这些方法会修改mComponent值。

经过对上面这些方法逐一分析和排除，锁定只有setComponent()和readFromParcel()这两个方法处最为可疑。可能你会好奇是如何排除其他方法的，这就不逐一排除，就说一说被排除在外的setClassName方法：

```
public Intent setClassName(Context packageContext, String className) {
    mComponent = new ComponentName(packageContext, className);
    return this;
}
```

很明显，这个方法不会导致mComponent为空，最多只会修改mComponent方法，其他方法也是类似。

另外，mComponent虽然为private属性，也有可能在其他文件通过反射修改或者第三方root后采用xposed等框架都能修改，以及上面的最为可疑方法失败后可尝试定位其他方法，都会成为备选可能方案。如果前面推测验证失败，就需要fallback来分析，目前先验证可能性最大的Case。

进展2：多线程可能通过setComponent()或readFromParcel()方法并发修改而导致异常。

2.3.2 如何添加调试log

不能简单粗暴地在热点代码出加log，为了防止输出log过多，可采用条件输出log。只输出同时满足以下两个条件的log：

通过条件判断只有fileexplorer app的Intent才输出log;
mComponent的包名为”com.android.fileexplorer”，方法调用之后却变成null的地方才添加log.

有了添加log的条件，那么接下来需要考虑该添加哪些log？这里最重要的信息就是打印出调用栈信息以及component的mPackage和mClass，当然也可以再打印出调用者进程的pid/uid/processName.

下面便是在Intent.java中新添加的log信息。

//Gityuan ADD: START
private static final String FILE_EXPLORER_PKG_NAME="com.android.fileexplorer";
private static final String FILE_EXPLORER_TAG="fileexplorer";
//END
 
 
public Intent setComponent(ComponentName component) {
    //Gityuan ADD: START
    if((mComponent != null) && (component==null) && FILE_EXPLORER_PKG_NAME.equals(mComponent.getPackageName())){
        Log.e(FILE_EXPLORER_TAG, "setComponent() maybe occur NullException: " + mComponent.toShortString());
        new RuntimeException("fileexplorer stack info").printStackTrace();
    }
    //END
    mComponent = component;
    return this;
}
 
public void readFromParcel(Parcel in) {
    ...
    //Gityuan ADD: START
    boolean isFileExplorer = false;
    if(mComponent != null && FILE_EXPLORER_PKG_NAME.equals(mComponent.getPackageName())){
        isFileExplorer = true;
    }
    //END  
    
    mComponent = ComponentName.readFromParcel(in);
    
    //Gityuan ADD: START
    if(isFileExplorer && (mComponent==null)){
        Log.e(FILE_EXPLORER_TAG, "readFromParcel() maybe occur NullException: " + mComponent.toShortString());
        new RuntimeException("fileexplorer stack info").printStackTrace();
    }
    //END
}

2.4 压测无果

这个BUG已经有同事尝试过跑ｍonkey等压力手段测试，一直无法复现NullPointerException的问题。只有在用户基数很大的时候，极低概率事件也能复现。后面我再一寻思，加上log后，本地可以先试试，就算bug无法复现，至少能看看有哪些家伙可能会去并发的修改mComponent值，多做尝试或许成功就不远了，接下来展开了本地复现计划。

2.5 本地验证

2.5.1 Log分析

通过增加关键log，本地测试多次，总结下能修改mComponent = null，主要分两类：

第一类是BroadcastRecevier生命周期的结束，如下：

E/fileexplorer(32365): setComponent() maybe occur NullException:
{com.android.fileexplorer/cn.kuaipan.android.service.MediaMountedReceiver}
W/System.err(32365): java.lang.RuntimeException: fileexplorer stack info
W/System.err(32365): at android.content.Intent.setComponent(Intent.java:6325)
W/System.err(32365): at com.android.server.am.BroadcastQueue.finishReceiverLocked(BroadcastQueue.java:355)
W/System.err(32365): at com.android.server.am.ActivityManagerService.finishReceiver(ActivityManagerService.java:13944)
W/System.err(32365): at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:384)
W/System.err(32365): at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2079)
W/System.err(32365): at android.os.Binder.execTransact(Binder.java:404)
W/System.err(32365): at dalvik.system.NativeStart.run(Native Method)

当然还有 {com.android.fileexplorer/com.xiaomi.push.service.receivers.NetworkStatusReceiver} {com.android.fileexplorer/cn.kuaipan.android.service.NetChangeReceiver}等等。这里的pid=32365是system_server进程，广播执行onReceive后由system_server清理应该属于正常情况，可以忽略。

第二类是重点，即快盘的服务service：cn.kuaipan.android.service.KscService，如下：

E/fileexplorer( 3024): setComponent() maybe occur NullException:
{com.android.fileexplorer/cn.kuaipan.android.service.KscService}
W/System.err( 3024): java.lang.RuntimeException: fileexplorer stack info
W/System.err( 3024): at android.content.Intent.setComponent(Intent.java:6325)
W/System.err( 3024): at cn.kuaipan.android.service.KscService.onReceiveAction(KscService.java:458)
W/System.err( 3024): at cn.kuaipan.android.service.KscService.dispatchAction(KscService.java:702)
W/System.err( 3024): at cn.kuaipan.android.service.KscService.access$2(KscService.java:688)
W/System.err( 3024): at cn.kuaipan.android.service.KscService$MainHandler.handleMessage(KscService.java:862)
W/System.err( 3024): at android.os.Handler.dispatchMessage(Handler.java:102)
W/System.err( 3024): at android.os.Looper.loop(Looper.java:136)
W/System.err( 3024): at android.os.HandlerThread.run(HandlerThread.java:61)

这里pid=3024，正是com.android.fileexplorer:remote进程，这与bugreport中的 java.lang.NullPointerException所属于进程也是同一个完全吻合。

进展３：初步认定问题出在这个服务cn.kuaipan.android.service.KscService。

2.5.2 Fileexplorer

再接下来，需要查看KscService这个服务是如何调用的，进入Fileexplorer应用程序的源码，通过grep搜索了一番，发现在该app的AndroidManifest.xml中：

androidManifest.xml
<service
android:name="cn.kuaipan.android.service.KscService"
android:process=":remote" />

进一步分析发现，KscService是快盘的，并通过jar包形式引入，源码位于libs/kssmiddleware.jar。问题已经定位到第三方jar包，迅雷同事很快给出的回应，KscService的onReceiveAction中确实有setComponent(null)，而且是在子线程中调用。

public void onReceiveAction(Intent intent) {
    String action = intent.getAction();
    if (TextUtils.equals(action, ConnectivityManager.CONNECTIVITY_ACTION)) {
    intent.setAction(EVENT_NET_CHANGED);
    intent.putExtra(EXTRA_ORG_ACTION, action);
    intent.setComponent(null); 　//引发BUG的关键语句
    sendEvent(this, intent);
}

分析到这里，回过来看可能觉得问题比较简单，试想这个在fileexplorer应用的FC，谁能想到居然是由于第三方的JAR引起的。

2.６结论

进展４：　mComponent报空指针异常，的确是由于多线程并发修改导致的。简单说说并发流程如下：

//以下是com.android.fileexplorer:remote进程
if (comp && mComponent != null) {　//流程１
    if (!first) {
    b.append(' ');
}
first = false;
b.append("cmp=").append(mComponent.flattenToShortString());　//流程３
}

//以下是KscService所在的子线程
public void onReceiveAction(Intent intent) {
    String action = intent.getAction();
    if (TextUtils.equals(action, ConnectivityManager.CONNECTIVITY_ACTION)) {
        intent.setAction(EVENT_NET_CHANGED);
        intent.putExtra(EXTRA_ORG_ACTION, action);
        intent.setComponent(null); 　//流程２
        sendEvent(this, intent);
　 }
}

结论(并发执行流程)：

首先，com.android.fileexplorer:remote进程执行流程１；
然后，KscService所在子线程执行到流程２；
最后，com.android.fileexplorer:remote进程执行到流程３，便抛出NullPointerException异常。

整个过程并没有加锁，多线程并发就会有概率出现异常。到此这里这个BUG解决了，迅雷同事也提交了patch做了相应修改。问题看似圆满的结束了，大家难道心中没有疑虑吗？这么容易导致并发问题，引入JAR岂不是非常危险，有没有更彻底解决方案？

三.新的征程

问题虽然解决了，我并不满足，因为心中还有疑虑：

相同app为何有些机型出现概率高，有些机型却从未出现过，是偶然？
对于这类低概率事件，能否在本地直接复现呢，从而进一步佐证结论？
并发问题触发的根到底在哪呢？

在徘徊是去分析新问题，还是去分析上面的疑虑，在去公司的路上这些疑问依然在我脑海里浮现。在大数据下，没有理由，为何有些机型从不出现，既然概率再低，哪怕是百万分之一，也应该会有出现，直觉和经验告诉我这绝不是偶然的，于是决定来进一步剖析心中的疑虑。

3.1 复现低概率事件

已知是由于多线程并发修改导致的异常，那么想办法提高并发的概率，就能提高bug复现的概率。回到最开始的分析，下面代码由其他线程并发修改导致的异常

public void toShortString() {
  if (comp && mComponent != null) { //step1: mComponent非空才能进入
      if (!first) {
          b.append(' ');
      }
      b.append("cmp=").append(mComponent.flattenToShortString()); //step 2: 这就是7059行出现空指针
  }
  ...
}

为了提高并发，也就是进入该分支后，让该线程休眠一段时间，也就增大了其他线程并发修改的概率，修改如下：

if (comp && mComponent != null) {
    //Gityuan ADD: START
    if(FILE_EXPLORER_PKG_NAME.equals(mComponent.getPackageName())){
        Log.e(FILE_EXPLORER_TAG, "toShortString() sleep 1s, mComponent: " + mComponent.toShortString());
        try {
            Thread.sleep(1000);　　//休眠１秒种，提高并发碰撞概率
        } catch (InterruptedException e1) {
            e1.printStackTrace();
        }
    }
    //END
    if (!first) {
        b.append(' ');
    }
    first = false;
    //Gityuan ADD: START
    try{
        b.append("cmp=").append(mComponent.flattenToShortString());
    }catch(NullPointerException e){
        Log.e(FILE_EXPLORER_TAG, "toShortString() mComponent==null occur Exception");
        throw e;
    }
//END
}

3.1.1 见证奇怪

见证奇迹的时候，果然复现了问题，心中顿时豁然开朗，见下图：

《一行Log引发多线程并发问题的案例》

以下是BUG复现时的新增LOG信息：

E/fileexplorer( 8316): toShortString() sleep 1s, mComponent: {com.android.fileexplorer/cn.kuaipan.android.service.KscService}
E/fileexplorer( 8316): setComponent() maybe occur NullException: {com.android.fileexplorer/cn.kuaipan.android.service.KscService}
W/System.err( 8316): at cn.kuaipan.android.service.KscService.onReceiveAction(KscService.java:458)
W/System.err( 8316): at cn.kuaipan.android.service.KscService.dispatchAction(KscService.java:702)
W/System.err( 8316): at cn.kuaipan.android.service.KscService.access$2(KscService.java:688)
W/System.err( 8316): at cn.kuaipan.android.service.KscService$MainHandler.handleMessage(KscService.java:862)
E/fileexplorer( 8316): toShortString() mComponent==null occur Exception

进展5：提高并发性，复现bug，从而进一步佐证并发导致异常的结论。

3.2 bug的适用版本

居然找到了复现该问题的路径了，为何部分机型才会复现的问题，也就有必须深挖到底了。刚开始尝试了几款低内存、低性能的手机复现了，性能高的都没有复现，这个不由得怀疑性能高的手机就不容易遇到这个并发导致问题的可能性，碰撞到一起就不容易了，但后面发现一块低性能的手机也不会复现。猜测极有可能是由于android系统版本差异导致，通过对比发现跟Android大版本没有直接规律。

这时，再回过头来，再来理一边最初的NullPointerException的栈信息：

05-10 09:52:37.082 2153 2153 E AndroidRuntime: Process: com.android.fileexplorer:remote, PID: 2153
05-10 09:52:37.082 2153 2153 E AndroidRuntime: java.lang.NullPointerException
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.content.Intent.toShortString(Intent.java:7059)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.content.Intent.toString(Intent.java:6966)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.StringBuilder.append(StringBuilder.java:202)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.app.ActivityThread$ServiceArgsData.toString(ActivityThread.java:433)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.StringBuilder.append(StringBuilder.java:202)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1559)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:110)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.os.Looper.loop(Looper.java:193)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:5316)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.reflect.Method.invokeNative(Native Method)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at java.lang.reflect.Method.invoke(Method.java:515)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:832)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:648)
05-10 09:52:37.082 2153 2153 E AndroidRuntime: at dalvik.system.NativeStart.main(Native Method)

之前忽略了这一行：　android.app.ActivityThread$H.handleMessage(ActivityThread.java:1559)

//为了后面称呼方便，下面语句称为：key_code
if(!mIsUserBuild && isDebuggableMessage(msg.what)){
    Slog.d(TAG, codeToString(msg.what) + " handled "
    + ": " + msg.arg1 + " / " + msg.obj);
}

之前被忽略是由于没有搞明白为何这里会调用到ServiceArgsData.toString，觉得有可能是代码行数对应关系错了。通过再进一步分析，原来触发这个异常时ActivityThread收到msg.what＝SERVICE_ARGS，那么msg.obj也就是ServiceArgsData，一切就顺理成章。　这也跟最初bug特征，即启动service出现异常，这条信息是前后印证，这下彻底坐实了空指针异常的前因后果。

最终结论：　包含上面key_code的机型都有概率复现该问题，而这个代码恰好是ODM加的代码，带有该ODM代码的机型都可能复现，其他机型不会出现该问题。

3.5 并发问题的思考

看到这觉得有些大跌眼镜，原来是由一行log代码，遇到第三方jar一行修改mComponent代码，两个线程碰撞到一起，就产生了bug的火花。这个问题之所以比较难分析，是由于出在系统的一行log代码＋正好遭遇上这第三方jar。对于fileexplorer app的开发同事再怎么优化代码也没用，甚至都无法定位。

建议引入第三方库或者jar要谨慎，否则出现问题，很难定位与分析；
热点代码增加log，可以考虑以app或者pid等这些约束条件来输出目标log，提高定位准度；
分析低概率bug，尝试根据问题特征去尝试复现，提高复现并发性问题可通过两个或多个需要碰撞的线程，在方法内增加休眠时长，将低概率事件转换为高概率事件，当然具体问题还需具体分析。
并发解决方法，可以通过增加同步锁，或者在使用前先拷贝一份副本再使用都能有效解决并发问题。

本文从我分析一个BUG流程为主线，讲述一行Log引发的血案，只是跟大家分享一种破案手法，希望能对大家有所启发与帮忙。

    原文作者：Gityuan
    原文地址: http://gityuan.com/2018/02/03/log-fc/
    本文转自网络文章，转载此文章仅为分享知识，如有侵权，请联系博主进行删除。