一次生产环境P0级事故分析( 四 ) _P0级事故

快到天亮的时候，翻看了很多代码和日志，也是毫无头绪。真的是毫无头绪，连疑似的原因都找不到，本来说让性能测试组过来，看能不能复现，但是源头都没有，性能测试总不可能一个个场景压过去去找问题吧。
白天休息了一个多小时吧，起来继续工作了。
因为我属于被拉过去的，正儿八经排查代码是有其他开发负责人在的，前面我大部分时间就是跟他们头脑风暴，然后翻翻日志文件什么的。那时候潜意识也是认为应该跟代码没什么关系，还是跟环境有关系。所以第二天一早，我开始查看服务器上的部署文件，算是漫无目的吧，因为根本没头绪。
细节决定成败，我在翻看配置文件的时候，发现同级目录下的log4j.properties文件的修改时间不正常，是25号下午17:03分，这个时间差不多就是我们最后一次重启的时间，那时候本能的反应就是这个和这次事故有关系。打开文件看了下内容，看起来很正常，日志级别也是ERROR的(我们要求生产环境不允许开启debug日志的)，但是这个修改时间表明当时这个文件被覆盖过或者修改过。那时候真的，一下子来了精神，看到曙光了。
我叫上相关的所有人，开始反推当时从12:00更新开始的全过程，也把当时更新服务器的开发人员叫上，努力回想当时干了什么事情。经过将近两个多小时左右的回溯和头脑风暴，终于把事情理清楚了。

星期五中午的时候，开发人员更新了几个文件，其中就有log4j.properties，他自己也没注意到，然后覆盖上去的文件，是开启日志模式为Debug的。当时下午大家一团闹哄哄，他潜意识也压根联想不到这块，后来也是明确定位到这个文件，他才想起来。
我们重新把配置文件修改成Debug模式，然后启动服务，果然出现了当时的情况，两台服务器CPU飚高了，但是大概10几分钟以后恢复下来了，所以中午重启完以后，我们都去吃饭了，也没管服务器，那时候应该也是CPU异常，只是后续自动恢复了。(这个也很郁闷，到时如果我们能多等一会，可能就不会造成这么大的事故了) 。
分析了下，为什么开启Debug以后会造成CPU异常，原因就是系统启动的时候tomcat控制台疯狂刷日志，导致控制台假死，进而导致服务器CPU异常系统假死(为什么会这样，后面会详细描述) 。
而导致控制台疯狂刷日志的原因是因为会话同步的功能，因为架构比较老，并且是负载均衡，需要保持会话一直，所以采用的是Shiro+Ehcache缓存来管理会话，然后通过Ehcache来实现两台服务器的会话同步。因为会话是做了持久化+超期时间的方式，所以后续每次启动的时候都会执行会话同步的功能。
本来这个事情也没什么关系，但是因为业务场景需要，会话里是存了用户大部分的信息，其中就包括指纹特征码(系统支持指纹登录)，然后指纹特征码是一串Base64编码的字符串，非常长，所以同步的过程中日志都输出了，在控制台疯狂滚屏，就造成了第4步描述的局面。后面关掉会话同步的功能，程序就启动正常了，不会假死，也印证了我们的猜想（单台服务启动，不一会儿也会假死，也是这个会话同步造成的）。
然后就是下午14:00的时候，上班高峰期为什么也会造成系统崩溃，那时候会话同步已经结束了，因为知道tomcat控制台疯狂刷日志，所以反向分析，当时应该是大量登录的场景，所以我们找了客户端打开系统，登录了下，果然发现问题了，只要一打开系统，控制台就开始疯狂刷新日志，CPU也逐渐上去了，那时候几百个客户端差不多时间登录，那就造成系统崩溃了
查看日志以后发现也是在刷用户信息(同会话同步)，进一步排查代码以后是指纹登录功能引起的。指纹登录的设备是甲方自己采购的，当时设备没有提供JAVA的SDK，只有JS的SDK，也就是不支持后台比对指纹，所以当时的做法是把所有用户(大几百个)的指纹信息输出到前端，然后前端根据指纹特征码循环去比较，匹配以后，找到指纹对应的用户，在进行系统登录。(客户要求直接按指纹就登录，而不是先用用户名登录，然后再指纹二次登录，所以用了比较傻瓜的方式，指纹特征码也不能直接Base64字符串比较，要根据匹配程度，然后有一套算法去匹配的。也得亏系统在内网，带宽高，不然这种玩法，老早挂了)

到此为止，基本上已经分析清楚了造成问题的原因，也一步步复现了当时系统所有的异常现象。