事件背景公司的核心业务是做政府信息化软件，也就是为政府部门开发信息系统。其中有一个客户每天都需要用到的信息化软件，他们的客户是普通人。某年某月，某地区信息系统在周末升级系统后，连续一周出现系统不稳定、宕机、服务假死、数据库表锁等事件。即使在周五下午，系统也超过三个小时无法恢复，造成不良影响。整体系统运行架构整体系统架构相对传统的负载均衡运行架构。系统搭建时间较早（2016年），没有分布式框架，是传统的SpringMVC+Mybatis架构，服务器都是基于WindowsServer2008，这个架构是出问题前的架构，问题比较大，在后面的负载均衡章节会详细讲解。事件经过事件持续了大约一个星期，出现了几个严重的问题。事件对事故时间线的影响公司声誉受到较大影响。此次事件中，公司常务副总、研发中心经理、主管均出动安抚客户、解决问题（系统位于沿海省会城市，面向老百姓，影响较大）。就在严重问题发生的当天，正好有督导组来访。遇到这件事，组织的年度考核被扣了很多分。后续机构接到大量投诉，影响了很多人的评价。事件一：服务假死无法访问9月21日上午，系统出现大面积服务假死，访问长时间无响应。服务器网络延迟也很严重。分析过程中查看了服务器，发现CPU异常高；通过jstack，发现有大量的服务在等待（当时时间紧，不允许操作太多，所以要马上恢复）。直接重新启动其中一台服务器上的所有服务。发现没有变化，新请求还是直接挂起，估计不是服务问题；查看网络情况，发现服务器网络延迟很严重，开始怀疑是不是网络有问题，联系网络管理员查了一下，只有我们系统所在的服务器有问题延迟，其他服务器正常，服务器本身CPU??也异常，基本排除网络原因（为什么网络大面积延迟，后面会提到）；立即查看数据库监控，发现数据库CPU和IO异常（数据库由第三方公司管理运行，我们前期无法直接查看，联系他们后会给出监控报告）通过DBA查询数据库中挂起的脚本，发现有一个更新请求占用了所有的数据库资源，导致其他数据库请求无法进来或者响应很慢，导致服务挂起。追根溯源查询发现，这个操作是一个叫做更新“数据实例”的功能，每次升级版本都需要手动操作（情况比较复杂，不能自动处理）。所有的历史实例数据都会存在这个表中。当发生意外时，这张表会包含大约1.3亿条数据（Oracle比较抗拒，数据量也不会太大）。更新实例的功能还包括提供“调整表结构、重建索引、更新数据”等功能（业务场景需要，原则上每次升级只需要一次升级操作），所以整张表都会被在操作过程中锁定。本来这个操作是在系统升级完成之后进行的。不过升级的时候，现场人员都是新人，不熟悉情况。客户在操作过程中发现数据有问题。沟通后发现缺少更新实例的操作。客户催促对比比较着急，在线期间我直接操作了这个功能。因为这张表是核心表，所有的业务都会用到这张表，导致所有的服务都卡住了。后来直接重启数据库服务器（当时DBA杀不了进程，重启服务也失败，时间紧，沟通后直接重启服务器），然后系统恢复.整个过程持续了大约30分钟。解决方案系统优化。原实例表是单表，以后数据量会增加，所以修改程序，对这张表做分表功能（按时间点建表，程序自动对数据进行处理，自动创建分表，相应的查询统计等进行了调整）；增加权限控制，更新实例功能只允许管理员角色操作；加强人员培训现场实施，线上期间不得进行操作；因为系统所在区域的业务量比较大，数据积累很快，所以其实很早就有一些架构设计存在问题，以后对类似的数据表也做了同样的处理。本来想改变整体的业务架构，但发现成本太高，不仅涉及到系统本身的修改，还涉及到供应链的一系列系统修改，所以放弃了这个计划。事件二：tomcat内存溢出崩溃9月21日下午，发现两个核心服务不时出现内存溢出，随后tomcat直接崩溃。软件里的人都知道，虽然异常的表象是一样的，但实际的原因可能是完全不同的。因为分析过程涉及到tomcat的crash，在tomcat目录下产生了hs_err_pid.log日志，所以比较容易找到原因。结合业务日志的逆向搜索和分析后，定位到问题所在。原因要追溯到死循环。9.21下午出现的两个核心服务时不时出现内存溢出。查询日志后发现，问题期间会出现大量的服务访问日志。追查代码发现是前端的判断逻辑有问题，会导致服务死循环访问，即A-->B，A-->B，.....由于历史原因，部分业务逻辑代码在前端处理。服务A访问成功后，会继续访问B服务，然后B服务访问成功后，结束。但是这里代码的逻辑判断在某些条件下并不严谨，会触发刷新服务，会一直重复访问A和B服务。模糊查询9月22日下午发生的另一个服务内存溢出。同样分析后，发现是一个模糊查询请求异常。正常情况下代码是没有问题的，但是分析日志发现都是比较简单模糊条件的请求，初步怀疑是数据没有经过过滤，当时数据全部加载到内存中。因为分析是在上线期间，为了防止系统出现问题，没有直接抓取原始请求来重现问题。后者是让DBA根据查询SQL语句，去数据库日志中查询当时的执行记录，发现这些请求返回的平均记录数超过“200万”。至此，我们基本知道了内存溢出的原因。该程序不仅在加载数据，而且还为数据处理执行计算。解决方案第一个问题比较容易处理，只需修复程序，然后重新审核这段代码的逻辑，最大程度地消除逻辑缺陷。这些情况也整理出了对应的测试用例，会纳入到常规的测试计划中。第二个问题处理起来比较简单。模糊查询对返回的数据量有限制。根据当时的业务场景，限制为1000条，如果查不到记录，输入更精确的查询条件，简化代码中的逻辑操作，大部分场景都移到数据库计算（不影响整体性能）。“不过，这个方案本身存在的问题是比较低级的，当时审核过程中也存在问题，不应该出现这样的问题。”后来问了相关人员为什么要这样查询，才知道是自己的问题（设计不合理）。这个版本增加了回车查询的功能，然后客户输入一个词后会习惯性的按回车，然后触发查询，就造成了之前的意外。比如你想查询XXXX省某个位置的门牌号，然后输入XXXX省回车，就会查询到XXXX省的所有数据。随后，公司内部团队也进行了案例分析。其实很多开发者并没有把这个问题当回事，认为这不是什么大问题，只是改了几行代码而已。但实际后果堪比网上的P0级事故。这带来的不是人力成本的损失，而是口碑、信任等诸多无形的损失。负载均衡问题21号和24号之间出现了几个问题。其实很多时候是某台服务器的服务有问题，但是发现负载均衡没有起到任何作用，服务挂了，请求不断的来。正好周五下午发生了比较严重的事故，所以后来调整了整体策略。负载均衡设备的问题也算是为我们周五的大事故转移了一些注意力，压力也相对缓解了一些。原运行架构图整体系统架构的接口有问题。测试一下，只要端口能访问，服务假死的时候端口还是可以访问的，所以他认为服务还是正常的，请求还是来了。负载均衡访问策略不是很合理。出事前是按照IPhash方式设置的（经查询，原来是为了session维护，设备的访问策略很少，只有两三种方式）。中间一个下线的时候，请求转到另一个，后面再重启另一个，请求就不会过来了。所以很多时候，监控会发现两台服务器的压力差非常大。整体负载均衡方案也存在问题。仅完成服务器负载。整体系统架构为A-->B-->C的形式。如上图所示，该策略只加载了两台服务器的service1所在的端口，也就是说service1端口没有问题的话，service会一直过来。如上链接所示，服务2和服务3，不管出现什么问题，请求还是会来。厂家其实就是小代理，装备比较低，前期也比较尴尬。以上问题据说前期沟通过，但人家不配合。做过政务信息软件的都知道，内部会涉及到多方博弈，有时候很多问题不是靠技术就能解决的。这次意外也是好事。至少甲方意识到设备有问题，打电话给设备供应商调整负载均衡的内容；在某种程度上，我们的压力也减轻了。解决方法是增加服务监听（“保留原有端口监听，同时增加其他服务的端口监听”）。为了不影响系统运行，我们为每个服务都额外写了一个监控服务接口，专门用于设备配置服务监控。（“因为老系统是基于jsp的，不能是html页面，需要jsp页面，返回200表示正常，其他都是异常。”）访问策略改为轮询策略，以平衡分配请求流量并调整程序配置以支持服务。跨负载（类似分布式架构）服务和端口监控场景整体系统架构服务监控服务访问场景整体系统架构服务访问所有内部服务访问通过负载转发，保证每个服务高可用。承担的风险：1.高度依赖负载均衡设备的稳定性。以前请求比较少，现在所有的请求都会通过。（后来出现负载无法承受压力，系统彻底崩溃的情况）。2、会话持久化取决于软件架构的设计。如果无法实现会话持久化，则无法使用该架构。按照上面的方法调整了负载均衡策略，效果还是不好。设置完成后，厂家告诉我们老设备的监控有问题，需要10分钟才能切换（好像是老设备的问题），需要更换用一个新的。10分钟对于业务来说太长了，效果根本没有用。回到当时内部多方博弈，业务部要求改，信息部让我们的“软件供应商”写保函，更换设备后，系统100%有问题——自由的。这种说法是耍流氓。我敢说，没有哪个软件公司敢说自己的产品100%没有bug。再说了，涉及到硬件负载的切换和更换，软件公司凭什么要保证。事后，此事不复存在。网上常说一句话，“最简单的方法往往是最有效的方法。”后来，甲方也知道自己的硬件设备不够好，于是采用了“重启法”，并且他们会定期（差不多一个月）看看，重启所有设备，之后就没有什么大问题了。后来我们在公司内部充分模拟了现场情况，采用了国内知名硬件厂商的负载均衡设备（品牌不再是品牌，有打广告的嫌疑），发现效果很理想，可以达到预期的切换效果。说明说说做的策略没有错。系统是晚上9点25分开始宕机无法恢复，那可就惨了，当天所有领导都聚集到现场安抚客户，这一天系统近三个小时都无法恢复，还有企业s直接关机了。黑色星期五，这一天我也去了现场，前方是远程指挥（开发负责人在现场）。系统无法恢复时间线。整个事件来来去去莫名其妙，从周五晚上开始（通宵两晚），一直到周六半夜，经过多人集思广益，基本确定了问题所在。真的找到问题了，发现过程很可笑，但代价也太惨痛了。我们一直怀疑是中午12:00左右更新代码导致的问题，因为从各种现象来看，是更新后出现的问题。但经过一个多小时的反复验证和讨论，直接排除了这方面的原因。当时就直接开玩笑说，“敢用脑袋保证新加的代码没问题”。后来开始翻各种本地日志。当时的日志文件非常大，几百兆（其实是文件大小有问题，只是没人意识到，为了方便排错，每天都会备份日志，清理。正常业务应该不会产生这么大的日志，今天下午也基本没有业务处理，只是当时刚到，不了解情况，也没多想），日志很大，加载很慢。看了“一大堆无用”的“运行日志”，也没有发现什么有价值的信息。天快亮的时候，翻了很多代码和日志，也是“毫无头绪”。实在是毫无头绪，连疑似的原因都找不到。本来问过性能测试组看能不能复现，但是没有出处。白天休息了一个多小时，就起床继续工作。因为被拉过来了，查了一下代码，还有其他的开发组长。我大部分时间都在和他们一起集思广益，然后查看日志文件等等。当时潜意识里也认为应该和代码无关，或者和环境有关。所以第二天一早，我就开始漫无目的地查看服务器上的部署文件，因为我没有头绪。“细节决定成败”。查看配置文件时，发现同目录下的log4j.properties文件修改时间异常。“是25号下午17点03分。”这一次几乎是我们最后一次重启。当时本能的反应是，这跟事故有关。打开文件看内容，貌似正常，日志级别也是ERROR（我们要求生产环境不允许开启Debug日志），但是修改时间提示文件被覆盖或者修改在那时。那时，我真的回过神来，看到了曙光。我打电话给所有相关人员，从12:00更新开始逆向整个过程。我也给当时更新服务器的开发者打了电话，努力回忆当时我做了什么。经过近两个小时的回溯和头脑风暴，我终于想通了。周五中午，开发人员更新了几个文件，包括log4j.properties。他自己都没注意到，被覆盖的文件开启了日志模式为Debug。当时下午大家都很吵，他下意识的根本就想不起来，直到明确定位到这份文件后才想起来。我们重新修改配置文件为调试模式，然后启动服务。果然出现了当时的情况，“两台服务器CPU高，不过10分钟左右就恢复了”。于是中午重启后，我们都去吃过饭，也没管服务器。当时CPU应该是异常了，后来自动恢复了。（这也很郁闷，如果能多等一会，说不定就不会酿成这么大的事故了）。经过分析，为什么开启Debug后会出现CPU异常？原因是系统启动时，tomcat控制台疯狂刷日志，“导致控制台假死，进而导致服务器CPU异常系统假死”（为什么会这样，后面会详细介绍）.控制台之所以疯狂刷日志，是因为session同步功能。因为架构比较老，做负载均衡，所以需要保持session。所以采用Shiro+Ehcache来管理session，然后通过Ehcache实现两台服务器。服务器会话同步。因为session是采用持久化+过期时间的方式，每次启动都会执行session同步函数。本来这件事无关紧要，但是因为业务场景的需要，用户的大部分信息都保存在session中，包括“指纹特征码”（系统支持指纹登录），指纹特征码是一个stringofBase64-encodedcharacters字符串很长，所以同步过程中输出日志，控制台疯狂滚动，导致第4步描述的情况。关闭session同步功能后，程序会启动正常没有假死，这也印证了我们的猜想（单服务启动，过一会也会卡死，也是这次session同步造成的）。那么下午14:00，上班高峰期系统为什么会崩溃呢？那时，会话同步已经结束。因为知道tomcat控制台在疯狂刷日志，所以逆向分析应该是当时大量登录的场景，于是找了个客户端开机，登录，发现问题.系统一开机，控制台就开始疯狂刷新日志，CPU逐渐升高。当时大约有数百个客户端同时登录，导致系统崩溃。查看日志后发现用户信息也在刷新（与session同步）。进一步查看代码，是指纹登录功能引起的。指纹登录设备是甲方购买的，当时设备没有提供JAVASDK，只有JSSDK，即不支持后台指纹比对。信息输出到前端”，然后前端根据指纹特征码循环比对，匹配后找到指纹对应的用户，进行系统登录。（客户要求登录直接用指纹，而不是先用用户名登录，再用指纹再登录，这样比较傻，而且指纹特征码不能直接和Base64字符串进行比较，要看程度匹配，然后就是一套算法来匹配。也是系统内网带宽高，不然这游戏早就挂了）至此，问题的原因已经基本分析完毕，并且当时的系统已经一步步重现了所有的异常。为什么consolelogging会导致CPU异常呢？但是最关键的问题是consolelogging为什么会导致CPU异常。这也是阻碍我们进行的最大原因故障排除。我们在自己的笔记本电脑上也做了很多模拟，包括通过JMeter压测，控制台logging的时候没有发现CPU异常。其实求解过程很简单。关闭调试日志，系统基本正常。但是抱着询问的态度，卡在这里是很不爽的，这种问题估计也只有这种了。因为那天甲方在，硬件公司也来了，在聊天中终于发现了问题。服务器分布图你没看错，运行系统这么久的服务器其实就是“两台VM虚拟机”。用过虚拟机的人都知道，虚拟机就是公共主机的内存和CPU，是动态计算分配的。与专业人士交流后，“虚拟机内部的很多操作都是通过软件模拟出来的，比如网络。”.这也解释了9.21服务器CPU异常导致的大规模网络延迟。大体流程基本是CMD封装刷日志-->CPU异常-->然后暂停所有其他操作（包括网络等），等待CMD日志刷新，释放CPU后返回到正常。因为对操作系统的原理了解不多，一直没能分析出是怎么回事。届时cmd日志会占用所有CPU，我们将无权查看VM服务器相关的日志。这属于硬件公司。辖区硬件公司不承认VM虚拟化做服务器有问题，但在我看来，CPU飙升，网络会出现大面积延迟是个问题。也许硬件公司知道其中的窍门，所以他们没有向我们展示服务器日志。他们总是强调服务器很好。前面说过，回到公司后，我们搭建了一套一模一样的环境（物理机），但是无法重现控制台狂刷log，导致CPU异常，系统假死的情况。总结人的习惯就是这样。第一印象会把问题留给“异常输出平台”，所以这次事件基本上都归咎于我们的软件平台。事后我们还写了一大篇《》事故总结。报告”、各种“保证书”等等。
