面对 bug，一切从源码看起

Mar 13 2020

我相信程序员在解 bug 的过程中，或多或少都遇到过 log 的内容看起来非常“诡异”的问题，甚至跟代码的逻辑相排斥的情况。比如下面这两段代码，是我们测试平台一段实现蓝牙配对过程中，查找蓝牙设备的逻辑

1
2
3
4
5
6
7
8
9
10
11
12
13
// 代码 1
Log.i(TAG, "discovery launch, Searching Test Device: " + testDeviceName + "...");

// 代码2
@Override
public void btOnDeviceFound(BtDevice btDevice) {
    Log.i(TAG, "btOnDeviceFound: " + btDevice.getName());
    
    if (testDeviceName.equals(btDevice.getName()) {
        Log.i(TAG, "target bt device found");
        testDeviceAddr = btDevice.getAddress();
    }
}

当查看 log 的时候有如下内容

1
2
3
21879 7788 I UiTest: discovery launch, Searching Test Device: Remote-1
21879 21895 I UiTest: btOnDeviceFound: BT-1
21879 21895 I UiTest: target bt device found

发现在第一段 log 中，
变量 testDeviceName=”Remote-1”，
而第二段和第三段结合代码逻辑来看，testDeviceName=”BT-1”

诡异的事情发生，testDeviceName 前后不一致了

这里细心的读者会提问，也许是中间某个地方修改了 testDeviceName

这里我解答一下，testDeviceName 通过构造方法传递进来并初始化，中间没有任何一处代码有重新设置它的值，因此该变量没可能被修改

还有读者会小心翼翼提问，难道是 Java 代码出错了？

我认为，这种情况完全可以忽略，200 % 不可能在这里发生

那么只剩下一种可能，代码一定在哪里存在逻辑漏洞，并且在特定场景下会发生

熟悉不熟悉，程序员最了解的配方。无论自己怎样自测，总是能被测试人员发现问题

一切，还是得从源码看起

由于搜索蓝牙的过程是异步的，因此上面的代码 2 实际是在 SDK 的回调中执行到。经验上，感觉应该从回调（callback）这里作为突破进行排查

因此开始查找 callback 是如何注册到 SDK 中，打开注册时的源码，找到这里

1
2
3
4
5
6
7
8
9
int btRegisterCallback(BtCallback callback) {
    if (callback != null) {
        synchronized(this.mCallbackList) {
            return this.mCallbackList.add(callback) ? 1 : -1;
        }
    } else {
        return -1;
    }
}

注册时将我们的 callback 放到了一个 mCallbackList 变量中，顺手查看一下 mCallbackList 是什么类型

1
List<BtCallback> mCallbackList = new ArrayList();

原来是一个 List。记住这个细节，继续往下看，由于代码是在执行回调方法时出的异常，那就看看 mCallbackList 是如何执行回调操作的

1
2
3
4
5
6
7
8
public void btOnDeviceFound(BtDevice device) {
    Iterator var2 = BtManager.this.mCallbackList.iterator();

    while(var2.hasNext()) {
        BtCallback callback = (BtCallback)var2.next();
        callback.btOnDeviceFound(device);
    }
}

可见，当搜索蓝牙设备过程中，一旦有设备找到，则会遍历 mCallbackList 中的元素，并逐一执行回调方法

结合 mCallbackList 是一个 List 的特性，到这里，心里大概有了结论：

前序步骤中初始化过一个 Bt 对象，它的成员 testDeviceName=”BT-1”，同时它注册了它的 callback 到 mCallbackList 中，当执行到当前代码时，再次初始化了另一个 Bt 对象，它的成员 testDeviceName=”Remote-1”，它也注册了自己的 callback。由于实际搜索蓝牙设备时，只找到了 “BT-1”，所以触发了第一个 Bt 对象的 btOnDeviceFound，导致输出了本文开头提到的 log

“作案手法”知道了，得找到证据证明呀。于是，在代码中添加了反注册的代码，重新运行相同的 case，这一次，果然没有再出现

1
2
3
I UiTest: discovery launch, Searching Test Device: Remote-1
I UiTest: btOnDeviceFound: BT-1
I UiTest: target bt device found

通过这次一个小的 log 案例分析，我们知道，代码永远是客观的，而人是主观的，如果凭借主观随意推测，则会对分析问题造成非常大的影响，从而在错误的道路上一去难回头

所以务必记住，程序员排查问题的口号是：面对 bug，一切从源码看起