你知道嗎？Pulsar 也會(huì)重復(fù)消費(fèi)？
背景
許久沒(méi)有分享 Java 相關(guān)的問(wèn)題排查了，最近幫同事一起排查了一個(gè)問(wèn)題：
在使用 Pulsar 消費(fèi)時(shí)，發(fā)生了同一條消息反復(fù)消費(fèi)的情況。
排查
當(dāng)他告訴我這個(gè)現(xiàn)象的時(shí)候我就持懷疑態(tài)度，根據(jù)之前使用的經(jīng)驗(yàn) Pulsar 在官方文檔以及 API 中都解釋過(guò)：
只有當(dāng)設(shè)置了消費(fèi)的 ackTimeout 并超時(shí)消費(fèi)時(shí)才會(huì)重復(fù)投遞消息，默認(rèn)情況下是關(guān)閉的，查看代碼也確實(shí)沒(méi)有開啟。
那會(huì)不會(huì)是調(diào)用了 negativeAcknowledge() 方法呢(調(diào)用該方法也會(huì)觸發(fā)重新投遞)，因?yàn)槲覀兪褂昧艘粋€(gè)第三方庫(kù) https://github.com/majusko/pulsar-java-spring-boot-starter 只有當(dāng)拋出異常時(shí)才會(huì)調(diào)用該方法。
查閱代碼之后也沒(méi)有地方拋出異常，甚至整個(gè)過(guò)程中都沒(méi)看到異常產(chǎn)生;這就有點(diǎn)詭異了。
復(fù)現(xiàn)
為了捋清楚整個(gè)事情的來(lái)龍去脈，詳細(xì)了解了他的使用流程;
其實(shí)也就是業(yè)務(wù)出現(xiàn)了 bug，他在消息消費(fèi)時(shí) debug 然后進(jìn)行單步調(diào)試，當(dāng)走完一次調(diào)試后，沒(méi)多久馬上又收到了同樣的消息。
但奇怪的是也不是每次 debug 后都能重復(fù)消費(fèi)，我們都說(shuō)如果一個(gè) bug 能 100% 完全復(fù)現(xiàn)，那基本上就解決一大半了。
所以我們排查的第一步就是完全復(fù)現(xiàn)這個(gè)問(wèn)題。
為了排除掉是 IDEA 的問(wèn)題(雖然極大概率不太可能)既然是 debug 的時(shí)候產(chǎn)生的問(wèn)題，那其實(shí)轉(zhuǎn)換到代碼也就是 sleep 嘛，所以我們打算在消費(fèi)邏輯里直接 sleep 一段時(shí)間看能否復(fù)現(xiàn)。
經(jīng)過(guò)測(cè)試，sleep 幾秒到幾十秒都無(wú)法復(fù)現(xiàn)，最后索性 sleep 一分鐘，神奇的事情發(fā)生了，每次都成功復(fù)現(xiàn)!
既然能成功復(fù)現(xiàn)那就好說(shuō)了，因?yàn)槲易约旱臉I(yè)務(wù)代碼也有使用到 Pulsar 的地方，為了方便調(diào)試就準(zhǔn)備在自己的項(xiàng)目里再?gòu)?fù)現(xiàn)一次。
結(jié)果詭異的事情再次發(fā)生，我這里又不能復(fù)現(xiàn)了。
雖然這才是符合預(yù)期的，但這就沒(méi)法調(diào)了呀。
本著相信現(xiàn)代科學(xué)的前提，我們倆唯一的區(qū)別就是項(xiàng)目不一樣了，為此我對(duì)比了兩邊的代碼。
@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();
}
}
}
結(jié)果不出所料，同事那邊的代碼加了鎖;一個(gè)基于 Redis 的分布式鎖，這時(shí)我一拍大腿不會(huì)是解鎖的時(shí)候超時(shí)了導(dǎo)致拋了異常吧。
為了驗(yàn)證這個(gè)問(wèn)題，在能復(fù)現(xiàn)的基礎(chǔ)上我在框架的 Pulsar 消費(fèi)處打了斷點(diǎn)：
果然破案了，異常提示已經(jīng)非常清楚了：加鎖已經(jīng)過(guò)了超時(shí)時(shí)間。
進(jìn)入異常后直接 negative 消息，同時(shí)異常也被吃掉了，所以之前沒(méi)有發(fā)現(xiàn)。
查閱了 RedisLockRegistry 的源碼，默認(rèn)超時(shí)時(shí)間正好是一分鐘，所以之前我們 sleep 幾十秒也無(wú)法復(fù)現(xiàn)這個(gè)問(wèn)題。
總結(jié)
事后我向同事了解了下為啥這里要加鎖，因?yàn)槲铱聪聛?lái)完全沒(méi)有加鎖的必要;結(jié)果他是因?yàn)閺膭e人那里復(fù)制的代碼才加上的，壓根沒(méi)想那么多。
所以這事也能得出一些教訓(xùn)：
- ctrl C/V 雖然方便，但也得充分考慮自己的業(yè)務(wù)場(chǎng)景。
- 使用一些第三方 API 時(shí)，需要充分了解其作用、參數(shù)。
