背景

許久沒有分享 Java 相關的問題排查了，最近幫同事一起排查了一個問題：

在使用 Pulsar 消費時，發生了同一條訊息反覆消費的情況。

排查

當他告訴我這個現象的時候我就持懷疑態度，根據之前使用的經驗 Pulsar 在官方文件以及 API 中都解釋過：

只有當設定了消費的 ackTimeout 並超時消費時才會重複投遞訊息，預設情況下是關閉的，檢視程式碼也確實沒有開啟。

那會不會是呼叫了 negativeAcknowledge() 方法呢（呼叫該方法也會觸發重新投遞），因為我們使了一個第三方庫 https://github.com/majusko/pulsar-java-spring-boot-starter 只有當丟擲異常時才會呼叫該方法。

查閱程式碼之後也沒有地方丟擲異常，甚至整個過程中都沒看到異常產生；這就有點詭異了。

復現

為了捋清楚整個事情的來龍去脈，詳細瞭解了他的使用流程；

其實也就是業務出現了 bug，他在訊息消費時 debug 然後進行單步除錯，當走完一次除錯後，沒多久馬上又收到了同樣的訊息。

但奇怪的是也不是每次 debug 後都能重複消費，我們都說如果一個 bug 能 100% 完全復現，那基本上就解決一大半了。

所以我們排查的第一步就是完全復現這個問題。

為了排除掉是 IDEA 的問題（雖然極大概率不太可能）既然是 debug 的時候產生的問題，那其實轉換到程式碼也就是 sleep 嘛，所以我們打算在消費邏輯裡直接 sleep 一段時間看能否復現。

經過測試，sleep 幾秒到幾十秒都無法復現，最後索性 sleep 一分鐘，神奇的事情發生了，每次都成功復現！

既然能成功復現那就好說了，因為我自己的業務程式碼也有使用到 Pulsar 的地方，為了方便除錯就準備在自己的專案裡再復現一次。

結果詭異的事情再次發生，我這裡又不能復現了。

雖然這才是符合預期的，但這就沒法調了呀。

本著相信現代科學的前提，我們倆唯一的區別就是專案不一樣了，為此我對比了兩邊的程式碼。

    @PulsarConsumer(
            topic = xx,
            clazz = Xx.class,
            subscriptionType = SubscriptionType.Shared
    )
    public void consume(Data msg) {
        log.info("consume msg:{}", msg.getOrderId());
        Lock lock = redisLockRegistry.obtain(msg.getOrderId());
        if (lock.tryLock()) {
            try {
                orderService.do(msg.getOrderId());
            } catch (Exception e) {
                log.error("consumer msg:{} err:", msg.toString(), e);
            } finally {
                lock.unlock();
            }
        }

    }

結果不出所料，同事那邊的程式碼加了鎖；一個基於 Redis 的分散式鎖，這時我一拍大腿不會是解鎖的時候超時了導致拋了異常吧。

為了驗證這個問題，在能復現的基礎上我在框架的 Pulsar 消費處打了斷點：

果然破案了，異常提示已經非常清楚了：加鎖已經過了超時時間。