问题出现
先说下现象，在k8s上部署了微服务应用，注册和配置中心使用了nacos 2.0.3（3节点集群）。某一天开始，应用日志里输出了很多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!
打开nacos的日志，也是一堆的token过期信息
问题排查
-
首先排查下nacos里有没有地方打印token信息
找了一遍源码，只在这里有打印
image.png
但是，token失效的话，在authManager.loginRemote()的时候已经抛了异常了，所以没有地方可以打印
image.png
查看core-auth日志，有的token是正常打印的，说明没有过期，有的又报了过期，很奇怪
image.png -
既然服务端没地方打印，那我们找找客户端，看看是在哪里获取和设置token的。找了下源码，发现服务端是从请求头的accessToken获取token的
那么再找下客户端传值的地方：
image.png -
进到SecurityProxy里，发下accessToken是在login方法里进行设置的
image.png 跟踪下代码，发现nacos-client里有两个地方有调用登录。看源码，都是每隔5秒会调用一次登录操作
-
ConfigTransportClient.start()方法
image.png -
NamingClientProxyDelegate.initSecurityProxy()方法
image.png
- 看着代码没什么问题，那就再看看请求的token。系统里没有任何地方有打印，这时候想到了arthas，可以进行程序执行监控
# 安装 & 启动
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
# 查看token的值
watch com.alibaba.nacos.client.security.SecurityProxy getAccessToken '{returnObj}'
# 发现有好几个token值，有的是正常的，有的是已经过期的token
这里有个疑问，为什么会有这么多个token值，是不是SecurityProxy对象本身有多个？
通过jmap -histo 1 |grep SecurityProxy，查看到有6个对象
跟踪源码，发现SecurityProxy是ConfigService和NamingService创建的
用于nacos集群是3节点，那这里每个类型的对象是3个也就可以理解了
- 那为什么有的token是过期的？正常如果有执行登录操作的话，token就应该会被更新。带着这个问题，就接着监控了下登录操作
# 监控登录操作，发现返回的token都是正常的
watch com.alibaba.nacos.client.security.SecurityProxy login '{params, returnObj, target}' -x 2
# 那过期的token存在于哪里？这里通过stack命令查看方法的调用
stack com.alibaba.nacos.client.security.SecurityProxy login
发现只有NamingClientProxyDelegate里面在调用。ConfigTransportClient里并没在调用
-
这时候已经接近问题的真相了。找源码！
从源码里可以看出，executor执行了两个定时任务
定时任务1：登录
image.png
定时任务2：配置监听
image.png
会不会是线程池的问题，导致只有一个线程一直在运行，导致另一个任务一直得不到执行？
这里是线程池声明的地方：
image.png
通过arthas调用(找出classLoader，然后执行获取线程数方法)，发现线程池只会有一个线程
classLoader.png
-
验证下单线程池执行响应逻辑
可以看出，任务1只执行了一次，后面一直执行任务2
image.png -
这里的问题已经明确了，就是线程数太小，只有1，导致执行不了配置的登录操作。
而线程数是根据Runtime.getRuntime().availableProcessors()来计算的，也就是说处理器的数量太小了。
这时候通过增加Pod的cpu资源，可以解决该问题。
也就是调大cpu的资源数！
image.png
验证了下，调整cpu资源后，再次获取线程数，已经恢复正常了
调整后线程数.png
