問(wèn)題出現(xiàn)
先說(shuō)下現(xiàn)象虚青，在k8s上部署了微服務(wù)應(yīng)用窗慎，注冊(cè)和配置中心使用了nacos 2.0.3（3節(jié)點(diǎn)集群）个束。某一天開(kāi)始劲够，應(yīng)用日志里輸出了很多token expired的異常
[2022-02-11 05:15:03.528] [] [com.alibaba.nacos.client.config.impl.ClientWorker] [DubboSaveMetadataReport-thread-1] [1121] [WARN ] [config_rpc_client] [publish-single] fail, dataId=com.anta.plm.c8.api.facade.NodeFacade:1.0.0::consumer:outdoor-app-clo-dubbo, group=dubbo, tenant=outdoor, code=403, msg=token expired!
[2022-02-11 05:15:03.547] [] [com.alibaba.nacos.client.config.impl.ClientWorker] [DubboSaveMetadataReport-thread-1] [1121] [WARN ] [config_rpc_client] [publish-single] fail, dataId=com.anta.plm.c8.api.facade.NodeFacade:1.0.0::consumer:outdoor-app-clo-dubbo, group=dubbo, tenant=outdoor, code=403, msg=token expired!
[2022-02-11 05:15:03.550] [] [com.alibaba.nacos.client.config.impl.ClientWorker] [DubboSaveMetadataReport-thread-1] [1121] [WARN ] [config_rpc_client] [publish-single] fail, dataId=com.anta.plm.c8.api.facade.IpWhiteListFacade:1.0.0::consumer:outdoor-app-clo-dubbo, group=dubbo, tenant=outdoor, code=403, msg=token expired!
打開(kāi)nacos的日志靠粪，也是一堆的token過(guò)期信息
問(wèn)題排查
-
首先排查下nacos里有沒(méi)有地方打印token信息
找了一遍源碼蜡吧，只在這里有打印
image.png
但是，token失效的話(huà)占键，在authManager.loginRemote()的時(shí)候已經(jīng)拋了異常了昔善，所以沒(méi)有地方可以打印
image.png
查看core-auth日志，有的token是正常打印的畔乙，說(shuō)明沒(méi)有過(guò)期君仆，有的又報(bào)了過(guò)期，很奇怪
image.png -
既然服務(wù)端沒(méi)地方打印牲距，那我們找找客戶(hù)端返咱，看看是在哪里獲取和設(shè)置token的。找了下源碼牍鞠，發(fā)現(xiàn)服務(wù)端是從請(qǐng)求頭的accessToken獲取token的
那么再找下客戶(hù)端傳值的地方：
image.png -
進(jìn)到SecurityProxy里咖摹，發(fā)下accessToken是在login方法里進(jìn)行設(shè)置的
image.png 跟蹤下代碼，發(fā)現(xiàn)nacos-client里有兩個(gè)地方有調(diào)用登錄难述∮┣纾看源碼吐句，都是每隔5秒會(huì)調(diào)用一次登錄操作
-
ConfigTransportClient.start()方法
image.png -
NamingClientProxyDelegate.initSecurityProxy()方法
image.png
- 看著代碼沒(méi)什么問(wèn)題，那就再看看請(qǐng)求的token店读。系統(tǒng)里沒(méi)有任何地方有打印嗦枢，這時(shí)候想到了arthas，可以進(jìn)行程序執(zhí)行監(jiān)控
# 安裝 & 啟動(dòng)
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
# 查看token的值
watch com.alibaba.nacos.client.security.SecurityProxy getAccessToken '{returnObj}'
# 發(fā)現(xiàn)有好幾個(gè)token值屯断，有的是正常的文虏，有的是已經(jīng)過(guò)期的token
這里有個(gè)疑問(wèn)，為什么會(huì)有這么多個(gè)token值殖演，是不是SecurityProxy對(duì)象本身有多個(gè)择葡？
通過(guò)jmap -histo 1 |grep SecurityProxy，查看到有6個(gè)對(duì)象
跟蹤源碼剃氧，發(fā)現(xiàn)SecurityProxy是ConfigService和NamingService創(chuàng)建的
用于nacos集群是3節(jié)點(diǎn)敏储，那這里每個(gè)類(lèi)型的對(duì)象是3個(gè)也就可以理解了
- 那為什么有的token是過(guò)期的？正常如果有執(zhí)行登錄操作的話(huà)朋鞍，token就應(yīng)該會(huì)被更新已添。帶著這個(gè)問(wèn)題，就接著監(jiān)控了下登錄操作
# 監(jiān)控登錄操作滥酥，發(fā)現(xiàn)返回的token都是正常的
watch com.alibaba.nacos.client.security.SecurityProxy login '{params, returnObj, target}' -x 2
# 那過(guò)期的token存在于哪里更舞？這里通過(guò)stack命令查看方法的調(diào)用
stack com.alibaba.nacos.client.security.SecurityProxy login
發(fā)現(xiàn)只有NamingClientProxyDelegate里面在調(diào)用。ConfigTransportClient里并沒(méi)在調(diào)用
-
這時(shí)候已經(jīng)接近問(wèn)題的真相了坎吻。找源碼缆蝉！
從源碼里可以看出，executor執(zhí)行了兩個(gè)定時(shí)任務(wù)
定時(shí)任務(wù)1：登錄
image.png
定時(shí)任務(wù)2：配置監(jiān)聽(tīng)
image.png
會(huì)不會(huì)是線(xiàn)程池的問(wèn)題瘦真，導(dǎo)致只有一個(gè)線(xiàn)程一直在運(yùn)行刊头，導(dǎo)致另一個(gè)任務(wù)一直得不到執(zhí)行？
這里是線(xiàn)程池聲明的地方：
image.png
通過(guò)arthas調(diào)用(找出classLoader诸尽，然后執(zhí)行獲取線(xiàn)程數(shù)方法)原杂，發(fā)現(xiàn)線(xiàn)程池只會(huì)有一個(gè)線(xiàn)程
classLoader.png
-
驗(yàn)證下單線(xiàn)程池執(zhí)行響應(yīng)邏輯
可以看出，任務(wù)1只執(zhí)行了一次您机，后面一直執(zhí)行任務(wù)2
image.png -
這里的問(wèn)題已經(jīng)明確了穿肄，就是線(xiàn)程數(shù)太小，只有1际看，導(dǎo)致執(zhí)行不了配置的登錄操作咸产。
而線(xiàn)程數(shù)是根據(jù)Runtime.getRuntime().availableProcessors()來(lái)計(jì)算的，也就是說(shuō)處理器的數(shù)量太小了仲闽。
這時(shí)候通過(guò)增加Pod的cpu資源脑溢，可以解決該問(wèn)題。
也就是調(diào)大cpu的資源數(shù)蔼囊！
image.png
驗(yàn)證了下焚志，調(diào)整cpu資源后衣迷，再次獲取線(xiàn)程數(shù)，已經(jīng)恢復(fù)正常了
調(diào)整后線(xiàn)程數(shù).png
