背景: 測試環(huán)境中某次升級后王滤,Jedis調(diào)用時(shí)出現(xiàn)詭異的ClassCastException拣展,代碼堆棧如下: java.lang.ClassCastException: [B cannot be cast to java.lang.Long at redis.clients.jedis.Connection.getIntegerReply(Connection.java:222) at redis.clients.jedis.Jedis.hset(Jedis.java:606) ... 有時(shí)候票编,也會報(bào)Unknown reply:的異常陷遮。 每次啟動1小時(shí)內(nèi)必現(xiàn)挠乳。
排查過程:
1. 首先看一下jedis的源碼,看看什么情況下可能出現(xiàn)這個(gè)問題讼呢,相應(yīng)的源代碼如下:
Connection.java:
219? public Long getIntegerReply() {
220? ? flush();
221? ? pipelinedCommands--;
222? ? return (Long) readProtocolWithCheckingBroken();
223? }
...
295 protected Object readProtocolWithCheckingBroken() {
296? ? try {
297? ? ? return Protocol.read(inputStream);
298? ? } catch (JedisConnectionException exc) {
299? ? ? broken = true;
300? ? ? throw exc;
301? ? }
302? }
...
Protocol.java:
204 public static Object read(final RedisInputStream is) {
205? ? return process(is);
206 }
...
139 private static Object process(final RedisInputStream is) {
140
141 final byte b = is.readByte();
142? ? if (b == PLUS_BYTE) {
143? ? ? return processStatusCodeReply(is);
144? ? } else if (b == DOLLAR_BYTE) {
145? ? ? return processBulkReply(is);
146? ? } else if (b == ASTERISK_BYTE) {
147? ? ? return processMultiBulkReply(is);
148? ? } else if (b == COLON_BYTE) {
149? ? ? return processInteger(is);
150? ? } else if (b == MINUS_BYTE) {
151? ? ? processError(is);
152? ? ? return null;
153? ? } else {
154? ? ? throw new JedisConnectionException("Unknown reply: " + (char) b);
155? ? }
156? }
顯然是撩鹿,hset調(diào)用Connection.getIntegerReply()是期待Protocol.process()返回Long,然而返回了byte[]對象悦屏,應(yīng)該是走到了錯(cuò)誤的if else分支(當(dāng)b == DOLLAR_BYTE或b == ASTERISK_BYTE時(shí)才會返回byte[]對象节沦,最后一個(gè)else分支會報(bào)Unknown reply異常),問題定位就在這里础爬,應(yīng)該是從RedisInputStream(redis服務(wù)器端)讀取到了錯(cuò)誤的內(nèi)容甫贯。
首先,基本可以排除高并發(fā)下redis服務(wù)器返回錯(cuò)誤內(nèi)容看蚜,因?yàn)槌鰡栴}的應(yīng)用并發(fā)并不高叫搁,我們生產(chǎn)環(huán)境使用jedis處理過比這高得多的并發(fā),從來沒碰到過這個(gè)錯(cuò)誤供炎,再加上是某次升級后碰到的渴逻,初步懷疑是升級的代碼有什么特殊的場景。
2. 網(wǎng)上搜索一圈后也有其他人遇到這個(gè)問題
? ? https://github.com/xetorthio/jedis/issues/186
? ? http://www.reibang.com/p/d78d0009a116
? ? https://my.oschina.net/jrrx/blog/1634837
? ? 看了一下分析的過程音诫,基本上都屬于使用不當(dāng)惨奕,分為兩種情形,一種是多線程下共享Jedis實(shí)例竭钝,一種是使用JedisPool梨撞,但并沒有遵守Pool的使用規(guī)范雹洗,沒有在使用完后的finally方法塊中調(diào)用jedis.close()方法。 注:Jedis設(shè)計(jì)為非線程安全聋袋,不支持多線程共享一個(gè)Jedis使用,如果使用JedisPool穴吹,則規(guī)范的調(diào)用方式為:
? ? Jedis jedis = null;
? ? try {
? ? ? ? jedis = jedisPool.getResource();
? ? ? ? jedis.xxx();
? ? ? ? ....
? ? } catch(Throwable t) {
? ? ? ? ...
? ? } finally {
? ? ? ? if(jedis != null) {
? ? ? ? ? ? try {
? ? ? ? ? ? ? ? jedis.close();
? ? ? ? ? ? } catch(Throwable t) {
? ? ? ? ? ? ? ? ....
? ? ? ? ? ? }
? ? ? ? }
? ? }
? ? 唯一特殊的一個(gè)案例是幽勒,https://my.oschina.net/jrrx/blog/1634837 中提到TimeoutException之后引發(fā)ClassCastException,究其原因港令,還是沒有在正確的地方調(diào)用jedis.close方法啥容,確保有問題的jedis被銷毀。
? ? 實(shí)際上顷霹,深入看下jedis的代碼咪惠,讀寫流或處理的過程中會捕捉IOException以及通用的Exception(注意:jedis的源代碼里catch的是Exception,而非Throwable)淋淀,并將當(dāng)前jedis實(shí)例的isBroken標(biāo)識置為true遥昧,在jedis.close()被正確調(diào)用的情況下,會將該實(shí)例銷毀朵纷,如果是連接池模式炭臭,則會同時(shí)從pool中移除“已損壞”的jedis實(shí)例,確保應(yīng)用層下次調(diào)用getResource()方法袍辞,返回的是正承裕或新創(chuàng)建的實(shí)例。
3. 雖然對網(wǎng)上的幾個(gè)類似問題提出的可能是由于多線程導(dǎo)致的分析結(jié)果存疑搅吁,但從現(xiàn)象上看確實(shí)很像威创,那就先確認(rèn)一下有沒有可能Jedis或JedisPool(底層使用的是commons-pool2)在多線程并發(fā)時(shí)可能出現(xiàn)狀態(tài)錯(cuò)誤,或者pool返回正在被其它線程使用的實(shí)例谎懦,這個(gè)雖然不容易驗(yàn)證肚豺,但是終歸還是有辦法做到的,直接重載或修改Jedis界拦、JedisPool详炬、commons-pool2的關(guān)鍵的幾個(gè)地方的源碼,加上調(diào)試日志寞奸,驗(yàn)證一下JedisPool有沒有在returnResource一個(gè)Jedis實(shí)例之前呛谜,同時(shí)又將相同的實(shí)例分配給了下一個(gè)并發(fā)的線程,具體代碼就不貼了枪萄,總之很曲折隐岛,加調(diào)試代碼比較簡單,曲折的是調(diào)試的過程中發(fā)現(xiàn)了更詭異的問題:在JedisPool makeObject(用于給pool創(chuàng)建新Jedis對象)瓷翻、getResource(應(yīng)用層從pool中獲取Jedis對象)聚凹、activiateObject(getResource返回對象前會先調(diào)用激活方法)以及returnResource(若為Pool模式割坠,jedis.close時(shí)自動調(diào)用returnResource,而不是自我銷毀)方法上分別給操作的jedis實(shí)例加上唯一ID妒牙,并在上述方法被調(diào)用時(shí)操作到的jedis唯一ID在日志打印出來彼哼,調(diào)試的過程中,出現(xiàn)了另一個(gè)詭異的現(xiàn)象湘今,偶爾看到某個(gè)jedis實(shí)例敢朱,有activiated的日志,但是竟然找不到makeObject的日志摩瞎。 于是懷疑logback是不是有丟日志的問題拴签,又開始測試logback,并沒有發(fā)現(xiàn)丟日志(非常高的并發(fā)下也并沒有)旗们;考慮到應(yīng)用及依賴的組件使用了slf4j蚓哩、commons-logging、jcl-over-slf4j上渴、log4j-over-slf4j岸梨、slf4j-log4j12,且后2個(gè)jar包實(shí)際上是沖突的稠氮,并不建議同時(shí)使用盛嘿,這下蛋疼了,原本的問題還沒解決括袒,又引出了新的棘手的問題次兆,而且日志的問題還不能說先放一邊再說,因?yàn)榕挪榈倪^程會需要打印大量日志锹锰,必須依賴日志系統(tǒng)芥炭,總不能IDE里debug直接吧。恃慧。园蝠。新的問題又排查了半天,無果痢士,無奈只能先擱置了彪薛。
4. 不管怎么樣,既然是升級后出現(xiàn)的問題怠蹂,還是用屢試不爽的排除法善延,開發(fā)同學(xué)review升級的代碼,確認(rèn)增加了一個(gè)小模塊城侧,主要跟redis的交互代碼如下:
private Cache<String, Integer> cache =
? ? ? ? ? ? CacheBuilder.newBuilder()
? ? ? ? ? ? ? ? ? ? .expireAfterWrite(LOCAL_CACHE_TIME_MS, TimeUnit.MILLISECONDS)
? ? ? ? ? ? ? ? ? ? .initialCapacity(1024)
? ? ? ? ? ? ? ? ? ? .removalListener((RemovalListener<String, Integer>) notification -> onRemoval(notification.getKey()))
? ? ? ? ? ? ? ? ? ? .build();
}
private void onRemoval(String field) {
? ? try {
? ? ? ? String value = redisClient.hget(redisKey, field);
? ? ? ? if(value ...) {
? ? ? ? ? ? redisClient.hdel(redisKey, field);
? ? ? ? } else {
? ? ? ? ? ? cache.put(field, Integer.parseInt(value));
? ? ? ? }
? ? } catch (Exception e) {
? ? ? ? logger.error(e.getMessage(), e);
? ? }
}
...
public void doUpdateSomething() {
? ? try {
? ? ? ? ...
? ? ? ? if(...) {
? ? ? ? ? ? ...
? ? ? ? } else {
? ? ? ? ? ? ...
? ? ? ? ? ? loadingCache.put(field, value);
? ? ? ? ? ? redisClient.hset(redisKey, field, String.valueOf(current));
? ? ? ? ? ? // 設(shè)置 key 的過期時(shí)間為一個(gè)小時(shí)易遣,主要是作為清除緩存的作用
? ? ? ? ? ? redisClient.expire(redisKey, REDIS_KEY_EXPIRE_SECONDS);
? ? ? ? }
? ? } catch(Exception ex) {
? ? ? ? logger.error(...);
? ? }
}
把整塊代碼邏輯干掉,上面的問題沒有了嫌佑,確定是升級的邏輯引發(fā)的bug豆茫;然后逐個(gè)函數(shù)排除侨歉,很快定位到是onRemoval函數(shù)的問題,將onRemoval函數(shù)去掉之后揩魂,問題也消失了幽邓,review onRemoval代碼,發(fā)現(xiàn)這個(gè)函數(shù)使用上確實(shí)有問題火脉,應(yīng)用層的邏輯很簡單牵舵,想在onRemoval回調(diào)函數(shù)中對expireAfterWrite過期的key做處理,如果redis中存在忘分,說明這個(gè)key沒有真正過期棋枕,再put加載回本地緩存白修。實(shí)際上妒峦,guava對onRemoval處理是很多情況下都會觸發(fā)onRemoval回調(diào),而不僅僅是當(dāng)key過期或超過大小被移除時(shí)調(diào)用兵睛,正常put也可能觸發(fā)REPLACE類型的removal肯骇,查看其源碼即很容易發(fā)現(xiàn)該回調(diào)接口的完整傳參是RemovalNotification對象:
public final class RemovalNotification<K, V> implements Entry<K, V> {
? @Nullable private final K key;
? @Nullable private final V value;
? private final RemovalCause cause;
? RemovalNotification(@Nullable K key, @Nullable V value, RemovalCause cause) {
? ? this.key = key;
? ? this.value = value;
? ? this.cause = checkNotNull(cause);
? }
}
其中,RemovalCause是一個(gè)枚舉類型祖很,完整的枚舉值包括:
/**
* The entry was manually removed by the user. This can result from the user invoking
* {@link Cache#invalidate}, {@link Cache#invalidateAll(Iterable)}, {@link Cache#invalidateAll()},
* {@link Map#remove}, {@link ConcurrentMap#remove}, or {@link Iterator#remove}.
*/
EXPLICIT
/**
* The entry itself was not actually removed, but its value was replaced by the user. This can
* result from the user invoking {@link Cache#put}, {@link LoadingCache#refresh}, {@link Map#put},
* {@link Map#putAll}, {@link ConcurrentMap#replace(Object, Object)}, or
* {@link ConcurrentMap#replace(Object, Object, Object)}.
*/
REPLACED
/**
* The entry was removed automatically because its key or value was garbage-collected. This
* can occur when using {@link CacheBuilder#weakKeys}, {@link CacheBuilder#weakValues}, or
* {@link CacheBuilder#softValues}.
*/
COLLECTED
/**
* The entry's expiration timestamp has passed. This can occur when using
* {@link CacheBuilder#expireAfterWrite} or {@link CacheBuilder#expireAfterAccess}.
*/
EXPIRED
/**
* The entry was evicted due to size constraints. This can occur when using
* {@link CacheBuilder#maximumSize} or {@link CacheBuilder#maximumWeight}.
*/
SIZE
而且笛丙,查看guava的源碼會發(fā)現(xiàn),cache的清理并不一定是后臺定時(shí)器觸發(fā)假颇,而是put完成后會立即出發(fā)清理的過程
如果onRemoval方法中再調(diào)用cache.put方法胚鸯,而且put的key還是onRemoval的key(例如上面這段業(yè)務(wù)邏輯),就會觸發(fā)無限循環(huán)遞歸笨鸡,最終的結(jié)果就是StackOverflowError姜钳。
將上述代碼修復(fù)一下:
private void onRemoval(RemovalNotification notification) {
? ? if(!notification.wasEvicted() || notification.getCause() != RemovalCause.EXPIRED) {
? ? ? ? return;
? ? }
? ? try {
? ? ? ? String value = redisClient.hget(redisKey, field);
? ? ? ? if(value ...) {
? ? ? ? ? ? redisClient.hdel(redisKey, field);
? ? ? ? } else {
? ? ? ? ? ? cache.put(field, Integer.parseInt(value));
? ? ? ? }
? ? } catch (Exception e) {
? ? ? ? logger.error(e.getMessage(), e);
? ? }
}
測試,問題就解決了形耗。
3. BUG雖然修復(fù)了哥桥,但是梁肿。兴枯。。尘喝,看了半天倦踢,跟redis有毛關(guān)系啊送滞,為毛會引發(fā)ClassCastException,而不是StackOverflowError辱挥,剛剛沒有提到的是累澡,后臺日志從頭到尾沒有看到任何StackOverflowError的日志,除了日志里看到ClassCastException般贼,JVM也沒有停止運(yùn)行愧哟。所以奥吩,想要探查個(gè)究竟,還得再排查一輪蕊梧。上面的遞歸調(diào)用本身是很好確認(rèn)的霞赫,在onRemoval里加調(diào)試日志就能看到日志被遞歸輸出了,但是看guava處理onRemoval的源碼:
void processPendingNotifications() {
? ? RemovalNotification<K, V> notification;
? ? while ((notification = removalNotificationQueue.poll()) != null) {
? ? ? ? try {
? ? ? ? ? ? removalListener.onRemoval(notification);
? ? ? ? } catch (Throwable e) {
? ? ? ? ? ? logger.log(Level.WARNING, "Exception thrown by removal listener", e);
? ? ? ? }
? ? }
}
按理說肥矢,StackOverflowError繼承了Throwable端衰,所以guava cache處理onRemoval回調(diào)如果發(fā)生StackOverflow的話,應(yīng)該會捕捉該錯(cuò)誤甘改,并輸出到日志里旅东,但是應(yīng)用的日志里一條StackOverflowError都沒有,不管復(fù)現(xiàn)多少次這個(gè)BUG十艾,也沒有一條StackOverflowError日志抵代。各種方法嘗試了很久,依然沒有頭緒忘嫉,直到在應(yīng)用層onRemoval回掉函數(shù)里try catch(Exception)改成try catch(Throwable)之后偶然發(fā)現(xiàn)了一條不太一樣的日志:
error onRemoval: Could not initialize class java.util.logging.LogRecord
? ? java.lang.NoClassDefFoundError: Could not initialize class java.util.logging.LogRecord
? ? at java.util.logging.Logger.log(Logger.java:873) ~[na:1.8.0_25]
? ? at com.google.common.cache.LocalCache.processPendingNotifications(LocalCache.java:1958) [guava-18.0.jar:na]
? ? ...
這個(gè)錯(cuò)誤報(bào)的依然莫名其妙荤牍,依然不是StackOverflowError,卻冒出個(gè)無厘頭的異常庆冕,乍一看還以為是前面提到的應(yīng)用中幾個(gè)依賴的日志組件包太多了康吵,沖突導(dǎo)致的,仔細(xì)一想访递,不大對勁晦嵌,這個(gè)是JDK自帶的日志框架,怎么會NoClassDefFound呢拷姿,仔細(xì)一想才恍然大悟惭载,StackOverflowError啊,我們在排查的錯(cuò)誤是StackOverflowError跌前,堆棧滿了棕兼,任何函數(shù)調(diào)用(當(dāng)然也包括logger.error(),System.out.println()等等)都需要先壓棧,所以StackOverflowError之后抵乓,任何函數(shù)調(diào)用都可能是繼續(xù)拋出異常StackOverflowError伴挚,所以,StackOverflowError 永灾炭!遠(yuǎn)茎芋!不!會蜈出!輸田弥!出!到铡原!日偷厦!志商叹!里!(當(dāng)然只泼,如果使用nohup啟動的話剖笙,JVM底層是有機(jī)會輸出到控制臺的,但是请唱,java應(yīng)用層不行C诌洹)。
想通了這一點(diǎn)十绑,前面所有問題全都迎刃而解了聚至,StackOverflowError既然可以影響日志輸出,當(dāng)然也可以影響Jedis的任何函數(shù)調(diào)用本橙!出問題的流程大致是這樣的:
? ? (1) 遞歸調(diào)用onRemoval過程中扳躬,在onRemoval內(nèi)redisClient.hget內(nèi)部stack overflow(具體在哪個(gè)函數(shù)達(dá)到overflow的臨界點(diǎn)不定,有一定的概率會剛好在讀寫socket流時(shí)恰好達(dá)到臨界點(diǎn)勋功,則會觸發(fā)ClassCastException)
? ? (2) 上一步觸發(fā)的StackOverflowError坦报,被guava的processPendingNotifications函數(shù)捕捉库说,并試圖打印日志狂鞋,但是logger.log會繼續(xù)觸發(fā)StackOverflowError,異常拋出過程中中斷遞歸潜的,跳出guava cache的put方法骚揍,繼續(xù)執(zhí)行(應(yīng)用層貌似正常,并沒有一直陷入遞歸死循環(huán)的魔咒)啰挪,但是由于該Jedis實(shí)例的socket流由于前面的stack overflow其實(shí)只被讀取了一半信不,Jedis實(shí)例實(shí)際上是處在broken的狀態(tài)(Jedis只會捕捉讀寫過程中的IOException,StackOverflowError時(shí)并不會將jedis實(shí)例標(biāo)識為broken)
? ? (3) 當(dāng)Jedis實(shí)例再次被當(dāng)成健康的實(shí)例返回給應(yīng)用層時(shí)亡呵,由于底層的Socket流并非初始化狀態(tài)抽活,任何操作都可能讀到臟數(shù)據(jù),從而觸發(fā)ClassCastException
4. 驗(yàn)證:基于上面的假設(shè)锰什,以及查看Jedis的源代碼下硕,只有當(dāng)讀取Socket InputStream過程中發(fā)生stack overflow,才可能引發(fā)后續(xù)的ClassCastException汁胆,是時(shí)候精心設(shè)計(jì)測試用例驗(yàn)證這個(gè)假設(shè)了梭姓。設(shè)計(jì)測試用例前,首先要始終小心一點(diǎn)嫩码,Stack overflow的時(shí)候誉尖,日志或任何函數(shù)都會失效,但是簡單的賦值操作還是不受Stack overflow影響的铸题,因此铡恕,測試用例設(shè)計(jì)如下:
? ? (1) 模擬遞歸調(diào)用邏輯琢感,并在遞歸調(diào)用的函數(shù)里調(diào)用jedis
? ? (2) 遞歸調(diào)用時(shí)try...catch(StackOverflowError over),并在catch塊中記錄發(fā)生stack overflow的次數(shù)并將異常及堆棧存入一個(gè)數(shù)組里(不調(diào)任何函數(shù)):
? ? ? ? ? ? ++stackOverflowErrorCount;
? ? ? ? ? ? if(stackOverflowErrorCount <= MAX_STACK_OVERFLOW_ERROR_COUNT) {
? ? ? ? ? ? ? ? lastStackOverflowErrors[stackOverflowErrorCount - 1] = over;
? ? ? ? ? ? }
? ? (3) 當(dāng)檢測到ClassCastException(復(fù)現(xiàn)問題)時(shí)探熔,跳出遞歸猩谊,測試用例退出前,并將暫存的異常堆棧打印出來
? ? 果然抓到了SocketInputStream.read時(shí)發(fā)生StackOverflowError的現(xiàn)場:
? ? java.lang.StackOverflowError
? ? ? ? at java.net.SocketInputStream.read(SocketInputStream.java:157)
? ? ? ? at java.net.SocketInputStream.read(SocketInputStream.java:121)
? ? ? ? at java.net.SocketInputStream.read(SocketInputStream.java:107)
? ? ? ? at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:195)
? ? ? ? at redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)
? ? ? ? at redis.clients.jedis.Protocol.process(Protocol.java:141)
? ? ? ? at redis.clients.jedis.Protocol.read(Protocol.java:205)
? ? ? ? at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:297)
? ? ? ? at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:216)
? ? ? ? at redis.clients.jedis.Connection.getBulkReply(Connection.java:205)
? ? ? ? at redis.clients.jedis.Jedis.hget(Jedis.java:622)
5. 總結(jié):一切都是StackOverflow惹的禍祭刚!小結(jié)一下:
? ? (1) 當(dāng)出現(xiàn)StackOverflowError時(shí)牌捷,日志里很可能看不到相應(yīng)的異常日志(即便應(yīng)用層try...catch)
? ? (2) 當(dāng)StackOverflowError發(fā)生時(shí),應(yīng)用層出現(xiàn)任何詭異的現(xiàn)象都是可能的
? ? (3) 通常涡驮,StackOverflowError是由于誤引入了循環(huán)遞歸邏輯暗甥,但很多框架或應(yīng)用層出于健壯性考慮,會try...catch(Throwable)捉捅,此時(shí)撤防,可能會“恰巧”意外中斷遞歸邏輯,即便是通過jstack去查看問題現(xiàn)場的堆棧棒口,也不一定能看到堆棧里有遞歸寄月,因?yàn)椋?dāng)你運(yùn)行jstack的時(shí)候无牵,遞歸很可能已經(jīng)因?yàn)楫惓L鋈チ搜梗菜埔呀?jīng)恢復(fù)了,其實(shí)內(nèi)部不一定哪里狀態(tài)是異常的