2017 08 12 所有网站无法访问

2017/08/12 所有网站无法访问事故

-	-
发现时间	2017/08/12 20:21
发现人	微信群 ^张亚^
处理时间	2017/08/12 20:45 - 2017/08/12 21:51
处理人	徐晓诗 卢朋 殷管中 季星宇 刘卓 董利军
撰写人	董利军

问题描述

所有网站无法打开，有的提示502错误，有的提示数据库无法连接

处理过程 - 复盘版

• [20:21] 微信群里有人反映与非网打不开
• [20:39] 反映与非其他网站也都打不开
• [20:44] 卢朋在返回路上，已经通知晓诗开始处理
• [20:45] 运维在群里通知正在处理故障
• [21:10] 晓诗反馈数据库服务器硬盘满，正在清理部分数据并重启
  • 初步判断数据库和日志文件出问题的可能性最大
  • 解决思路是优先让网站恢复运行，然后排查具体原因
• [21:23] 除电路城网站，其他都已恢复
• [21:45] 运维反馈其他服务已经恢复，只有cirmall起不来，已经联系管中在处理
• [21:51] 运维通知cirmall网站恢复，至此全部网站恢复运行，进入问题分析排查阶段
  • 确认cirmall的问题是由于上线流程不规范，没有走完整的测试发布流程，直接在线修改代码造成的
  • 隐含的问题是开发流程不规范，直接在Git仓库主干开发，导致多人协作开发的情况下，部署代码困难
• [22:00] 排查到MySQL的binlog数据突然增多

数据库端口	binlog大小
3310	303G
3313	201G
3314	120G

• [22:07] 卢朋报告爱板网导航栏错乱，开始并行处理
• [22:21] 星宇判断爱板导航数据有问题，参与排查
• [22:35] 排查到3310的binlog是从9号开始迅速增长，频繁时候几分钟就能生成一个1G容量的日志文件，3313和3314的数据增长量平稳
  • 确定思路放在重点排查3310的binlog，找出是哪个或哪些SQL在大量触发
• [22:40] 星宇反映爱板网导航的url和层次关系都没了，可能的方式是操作后台或者修改数据库
• [22:52] 晓诗反馈3310的binlog中有大量疑似读写avatar（用户头像）的数据，这个数据库端口是爱板网在用
• [23:11] 确认binlog格式是MIXED，尝试让运维输出可读性更好的binlog日志，用于定位问题SQL
• [23:28] 晓诗找出完整的嫌疑SQLuse eeboards; REPLACE INTO bbs_common_syscache SET cname=..., data=...
• [23:33] 思路调整到快速统计这条嫌疑SQL语句在每个binlog文件中出现的数量，以判断是否为问题根源
• [23:46] 星宇反馈一时半会找不出爱板导航问题的原因，建议恢复到当天备份的数据库
  • 确定解决思路是恢复备份会丢数据，尽可能找无损的解决方案，实在解决不了，再考虑回档
  • 晓诗建议找编辑重新设置导航数据
  • 确定爱板导航问题和本次数据库磁盘满问题无关
• [00:08] 为验证猜测，确定先统计单条嫌疑SQL语句的大小，再根据出现数量计算一个binlog文件中占用的大小
  • 联想到爱板网最近做过一次修复用户头像同步问题的改动，时间点有契合
• [00:12] 根据嫌疑SQL，定位到爱板论坛代码中调用的部分，初步判断程序逻辑存在问题，导致不合理地把大量数据缓存到数据库中
  • 确定快速解决方案，注释掉缓存用户头像url到数据库的操作，先解决binlog持续快速增长的问题
  • 并留言刘卓尽快检查这部分代码的逻辑
• [00:28] 晓诗反馈单条嫌疑SQL大小为2M左右
• [00:32] 刘卓加入排查
• [00:38] 刘卓恢复论坛头像部分的更改代码，解决日志增长问题
  • 用户头像不同步的bug也会复现，优先级较低，放在事后解决
• [00:59] 刘卓尝试连测试环境，排查爱板导航问题
  • 确定测试环境用的上周四更新的数据库，能保证导航数据完整性
• [01:23] 确认恢复爱板论坛代码后，数据库磁盘增常速度恢复正常
• [01:25] 讨论本次事故没有提前收到预警的问题
  • 晓诗反映Nagios有发磁盘空间满的警报邮件，但是大家都没注意到
  • 阿里云监控有发网站无法访问的短信警报，但是大家都没注意手机
  • 确定增加董利军到报警联系人列表
  • 强调工作方式，从沟通角度讲，遇到类似问题，不管在干什么或者能不能立刻解决，先在群里给其他人一个回复，免得都不知道有没有人在处理
• [02:12] 晓诗配合刘卓重新配置线上爱板网导航栏
• [03:20] 卢朋统计出抽样数据，单个binlog文件包含400~600的问题SQL语句，总容量近1G
  • 数据量符合预测，可以作为本次事故原因分析的数据依据，把事故总结在微信群做通报
  • 安排卢朋统计本次事故期间产生的全部异常增量数据大小，下周一给出

时间	异常log大小
20170801	785M
20170802	707M
20170804	764M
20170807	653M
20170809	35.9G
20170810	102.8G
20170811	96.7G
20170812	68.1G
20170813	1.1G

• [04:13] 爱板网导航栏修复完毕
  • 导航数据错乱原因需另行调查

处理过程 - 简约版

紧急恢复网站服务

• 根据网站报错信息，初步判断数据库出问题可能性较大
• 登录数据库服务器，检查各项状态，发现磁盘空间占满
• 清除部分过期或无用数据，腾出安全大小的磁盘空间，并重启数据库服务
• 尝试重启各网站服务，检查是否可以正常通过浏览器访问
• 各网站恢复正常访问，只有cirmall重启失败，最后联系开发协助解决，cirmall恢复

排查问题根源

• 根据事故症状，优先检查各数据库文件和日志文件大小是否正常
• 筛选出3310,3313,3314三个端口的binlog日志占用空间巨大（数百G），其中只有3310符合近期空间暴涨的特征，对应的网站服务是爱板网
• 重点排查3310的日志，用mysqlbinlog转化近期的binlog日志输出可读性好的日志格式，尝试找出是哪个或者哪些SQL在频繁出现
• 定位到可疑的SQLuse eeboards; REPLACE INTO bbs_common_syscache SET cname=..., data=...，单条大小2M左右，充斥日志
• 尝试抽样统计几个近期binlog日志，发现每个日志文件中包含400~600条可疑SQL语句，计算可知接近整个binlog文件大小，由此判断这条SQL就是直接问题根源
• 根据SQL语句特征，尝试搜索爱板论坛代码，定位可能的代码调用点
• 相关代码9日更新上线，用于从主站获取用户头像，并缓存到数据库，由于设计不当，导致大量数据被频繁写入数据库，由此产生的binlog日志逐渐占满了磁盘空间（从9日到12日产生了300G+ 日志数据）

解决方案（临时）

• 注释相关写数据库代码或者回滚论坛代码到修改前版本，暂时解决日志增长问题

暴露的问题

• 预警机制不完善
  • 磁盘空间不足的预警信息淹没在大量其他警报邮件中，不能引起人的关注，就失去了通知的意义
  • 警报通知人太少，巧合情况下会出现大家都没有注意到警告短信
• 开发流程不规范，直接在代码主干开发
• 写代码前的设计工作不足，没有选择有效的实现方案

改进措施

• 运维方面
  • 预警机制
    • 优化Nagios报警策略，减少不必要的邮件通知，只发送特别严重的预警
    • 增加董利军到报警通知联系人列表，以期缩短应急反应的时间
  • 提升排查、定位问题的能力，在遇到类似突发事故时候，能更快找到解决方案
• 开发方面
  • 规范开发流程，协作开发要自建分支，避免在主干上开发
  • 尽可能避免人工修改线上代码的操作方式，线上更新走正规的测试发布流程
  • 重视设计，在功能开发或者改进前，选择合理有效的解决方案
  • 重构爱板网获取用户头像部分的代码，解决头像不同步问题