案例分析 - 2017/03/19数据库回档失败

事故表现

​ 游戏服务器机器异常重启之后, 数据库回档(游戏服务器数据存放在redis并同时写入leveldb,回档操作是通过leveldb中的数据恢复到redis)完成之后发现玩家数据丢失严重,连续使用10天内备份的数据进行回档操作依然失败。

问题分析

  • 首先,可能的问题是: 磁盘故障导致数据写入leveldb失败,进而导致数据回档失败。但是通过对服务器日志分析发现并没有写入失败记录,基本上排除是磁盘故障这种可能

  • 其次,发现leveldb备份文件(20M)明显小于同期其他游戏区服leveldb备份文件(60M),该服务器异常之前,玩家访问正常,随之想到的可能性就是: 仅有leveldb数据在十天以前被异常操作删除,导致后续备份数据不完整。能够导致leveldb数据被操作删除的最大可能性就是,通过GM后台访问删除。由于GM后台操作没有日志可以查询,这种可能性不好验证,暂且放下,不深入考证。

  • 最后,在查看数据库日志的时候发现这台机器只有2017/01/07开始的日志,但是游戏服务器是2016/12/开服的,明显缺失日志。通过跟运维沟通,2017/01/07由于服务器机器异常数据进行了一次迁移。进一步分析ssdb(ssdb数据本质上是存放在leveldb中)日志,发现ssdb在7号14:47:50第一次启动成功后,15:01:05进行了一次数据库备份,时长在20毫秒左右,基本上可以判断此时的leveldb中保存数据很少,更可能的此时的启动的ssdb是空的。

    到此,我们基本上可以断定数据库备份回档失败的原因是:作为redis备份的leveldb,它丢失了数据迁移之前的leveldb数据,后续备份文件中保存的仅是增量数据,所有通过备份文件回档会丢失大量玩家数据。

    在我们明确事故产生的原因之后,但是还有一个疑惑: 既然redis数据是通过leveldb恢复的,为什么redis数据在01/07没有缺少,再次查看ssdb,redis日志发现在第一次ssdb启动成功后,ssdb进程没有关闭的情况下,14:58:03再次进行启动操作,由于监听tcp port已经存在,导致第二次启动失败。同时也伴随两次redis的启动,但是不同的地方,redis在第二次启动之前关闭了之前运行的redis。现在我们可以做出一个假设(后面查看1/7迁移的另一组服务器部分操作日志验证了这种假设),操作如下:

    1. 运维启动了一个空的ssdb和redis;
    2. 运维关闭了redis,进行正常的数据恢复;
      • 清空leveldb数据存储目录下文件;
      • 移动数据库备份文件到leveldb数据存储目录;
      • 通过leveldb文件恢复到redis中。
    3. 恢复完成之后,再次启动ssdb,由于端口冲突,启动失败,但不影响redis的正常使用。

    这样,产生问题的操作我们基本上就还原出来了。这里有一个比较有趣的技术点是,leveldb使用文件锁来保证同一个数据存储目录下只能启动一个leveldb,那么为什么在第一个leveldb没有关闭的情况下,还能再次启动leveldb恢复redis数据?仔细查看运维操作过程可以发现问题,运维在恢复redis数据之前第一步就是清空了数据存储目录中的文件(包括leveldb的文件锁使用的LOCK文件),所以可以再次启动leveldb恢复redis数据。

    在查找问题的过程中,使用ltrace跟踪进程时发现mmap使用的参数对不上源码,最后发现是leveldb版本的不一致,ssdb使用的是leveldb1.14.0,我看的是leveldb1.18.0源码。也同时加深了对leveldb中文件组织方式和保存的认识,即通过VersionEdit记录leveldb中文件的增加和删除,每次改动信息增量写入MANIFEST文件中,并且在服务器每次启动的时候合并增量,生成一个新的文件组织快照并写入MANIFEST文件。

防范措施

  • 回档操作之前要确保ssdb是关闭状态;
  • 定期检查回档文件,确定其完整性。