场景
国庆期间,线上微信端系统,出现无法正常使用情况,根据日志排查,出现42001错误码,是redis中存储的accessToken失效,导致系统异常,将redis中缓存的过期accessToken删除后,即恢复正常使用。
思考排错
首先根据代码层面的观察,获取到token之后,存储的是6000秒,而微信官方文档描述的是,返回的accessToken有效期在7200秒,所以系统缓存中的token一般来说肯定会在微信系统失效前进行失效，但是为什么会发生token在本系统中失效的情况呢。
1. 白名单问题
首先进行log日志的异常查找,(PS: 我们这里使用的是grafana日志系统,挺方便使用的,可以了解一下,官网: grafana.com),
这里获取token的时候，出现了白名单问题，开始我们以为是这台发送请求的服务器，没有在微信白名单内，但是根据我们到微信公众平台上查看，这台服务器的ip是设置到了微信公众平台上的，这里就又出现了疑问，这是为啥？关键是这台服务器有的请求token是成功获取了的，但是有的就失败~
继续观察，出现上图的log，发现获取token的频率并不在 6000 秒左右，有的十几分钟就发生了重新获取的情况，看到这里莫非我们的redis出现了问题？或者在别的地方有人手动删除了redis或者代码里有别的地方将token删除？
首先搜索代码中，并没有发现删除redis中token的地方，人为操作，因为是线上服务器基本也不可能，
最后从业务的角度思考，我们的系统服务了多个微信公众平台~，上面的几个问题迎刃而解，出现白名单问题是因为，有一个新加入的平台，没有在它的白名单中设置我们的服务器ip，获取token频率不对，也是因为多个公众平台可能在相隔时间段内比较小的情况去进行token获取。
当然这个只能解释白名单和频率的问题，token为什么会无缘无故失效还得继续排查。
2. 分布式锁问题
根据当时删除token解决问题的同事描述,系统是在7号中午1点多左右出现了异常,他在一点半左右删除了过期的token，随后系统恢复正常，于是观察了一下7号获取token的日志记录情况，如下。
194的appid在7号的第一次获取token是在下午1.32，在这之前，7号根本没有获取token的记录，按道理来说6000秒的失效时间，删除token的同事根本不该看到redis中存有token，当时为了急于恢复正常，没有细看token的情况，剩余时间等等，直接删除了，那么这个token是怎么存在redis中那么久的呢？
我们再来看下7号之前，6号发生了什么，如下图
6号晚上8点钟，194这个appid在同一秒内发生了12次获取token的请求，并且线程号都不相同，这说明是同一秒内有多个用户进行了操作，并且这时候redis中的token已经失效，但是因为系统代码中获取token的代码块，做了redis分布式锁的处理，按道理来说不应该出现同一秒内多个资源请求呀，
除非是redis出现了问题，线上redis用的是阿里云的主从模式，一主一从，查看一下redis在8点时的波动和告警，告警没有发生，波动也仅仅是跳了一下，占了百分之5.x。
本来，我们认为的是redis发生了主从切换或者redis主从发生了同步延迟，但是主从切换没有告警发生，那就只有同步延迟了，但是锁的命令是一条也就是,set ... nx，这个样子，是一个写命令，些命令应该全部打到主服务器上的，不存在同步延迟的问题，难道是获取到锁后，从缓存中读取的时候发生了同步延迟，读从库的时候没有读到？
首先我们观察一下日志，8点时的并发，15秒.753是最早拿到锁并进行请求的，直到15秒.872才进行获取token结束，但是在这之间，就直接发生了后续的11条请求直接进入获取token的代码中，这说明非同步延迟问题，而是我们的锁并没有进行锁住，导致后续请求直接进入。
但是即便如此，没有锁住，无非也就是存入redis中的token可能不是有效token，并且在6000秒后会自动消失，为什么8点以后没有获取token的请求了，直到第二天问题爆发，同事去redis中删除token，才解决问题，为什么8点钟最后存储的token会存在了redis中如此之久？
首先我们框架中因为历史问题，set token的时候，使用的是ace-cache这个开源框架，看下他的代码：
设置值和时间并非原子性操作，而是分两步操作的，我们怀疑是不是这段时间redis抖动，导致了第二部操作失败？使的值放进去了，但是没有设置失效时间？
在日志系统中，搜寻这段时间的错误日志，没有发现有redis相关的错误日志发生。
最终仔细一看它的实现代码。。 int time = jedis.ttl(key).intValue() + expire; , 这个框架set一个值的时候，先获取它之前的有效时间，并和现在的进行相加。。。
也就是说，并发了12次，12 * 6000 = 72000秒，20个小时后失效~！
这个token将在我们的redis中存储20个小时，实际上2个小时它就失效了，这就解释了为什么，问题在第二天中午爆发，因为第二天中午，用户来微信端进行操作使用了，但是token是无效的，所以没有系统没办法正常运行下去，但是同事依然在redis中看到了token，并进行删除，其实这个时候的token存储的是昨天晚上的了。
这里的问题已经接近真相全部露出了，是因为分布式锁没有控制住，导致并发请求token，并且过期时间进行不停的迭代累加，出现的连锁反应。
分布式锁为什么没有锁住？
token为什么会存储那么久的问题解释清楚了，但是为什么会出现分布式锁失效？
上面说了，因为是主从架构，一主一从，所以不存在数据不同步等等的问题，难道是 setNx 这块的代码并非原子性？
我们使用redis的MONITOR命令监控一下redis接收到的命令：
发现这块代码并没有，确实是原子性的操作。
既然是原子性操作，难道是redis自身发生了问题，导致没有锁住。。竟然已经到了怀疑中间件代码的地步上了。。
最后是看到了某段资料上的问题提醒了我，大致意思就是多个人同时请求锁啥啥的，这时候我一看锁代码：
问题就出在这里了，细心的同学看到这里可能一下就明白了，
是的没错，这个finally块直接做了删除锁的操作，竟然没有关心当前线程有没有获取到锁，就直接进行解锁操作。
也就是说A同学进来获取到锁了，这时候在执行自己的事情，
B同学来了发现没有拿到锁，直接把锁删除掉了。。。
C同学进来的时候，发现锁没人用 自己就直接进去使用了。。。
其实A同学正在使用，
但是锁被B删了，
后面如此循环这种操作，
有人获取到锁后立马被其他人删除了，
所以这个点很多人都拿到了锁，出现了并发没有控制住，
并且set的时候进行了时间累加，这就是最终问题原因了。
正确的处理应该是，用一个标识，记录当前用户有没有获取到锁，只有当前用户获取到锁才能释放这个锁，其他没有获取到锁的人，没有资格释放锁，否则会出现乱子，这就是解铃需要系铃人.. 按照之前的写法，基本等于没有上锁。。
引用Java并发编程里的话，就是 健壮的应用程序在多人使用和单人使用的情况下，每个响应结果都应该是相同的。
总结
这次问题的发生主要是自身业务代码实现的分布式锁问题，疏忽了释放锁时候的权限判断，闹了一出乌龙，
并且使用第三方框架的时候，一定要多观察它的源码实现，例如上面的ace-cache，对时间进行了累加，一般使用set的时候，其实希望的是时间就是自己设置的时间，而不是进行累加，并且 jedis.ttl(key) 还有一个问题，就是当这个key不存在的时候 返回的是 -2 , 如果这个key已经失效了， -2 和 自己设置的时间累加 -2 + 6000 = 5998，这里又是一个不严谨的地方。
这次的事故让自己的排查错误各方面能力有所增长，并发方面的意识更加强烈，同时自身以后也要多深入一下源码和别人的设计思想和原理理解，做到快速定位和排查相关的问题。
这里是我自身实现的一个分布式锁: github.com/qiaomengnan… , 适合单机版的redis或者一主一从，一主多从版本的redis进行使用。
同时推荐一下基于redisson实现的klock分布式锁，对集群哨兵等redis模式友好支持：github.com/kekingcn/sp…
boss版推荐，redisson：github.com/redisson/re… ， 一个完善的分布式锁框架。
