一个ceph-osd异常DOWN掉的原因分析

今天早上，运维的兄弟报告说，ceph分布式存储集群同时有3个OSD异常DOWN掉。因为CEPH集群是三份数据存储的，所以对业务没有什么太大的影响，所以等有空再查根本原因。

同时报告了有一台物理机当机了，做了重启恢复的操作。

有空的时候对问题进行了分析，同事进行了预查，发现如下：

1、在osd down掉的一段时间，所有的CEPH节点的网络流量都高上去了。

2、3个OSD down掉的时候可以看到日志是大概是说，本OSD断言心跳断掉了，所以由断言触发了关闭。

3、上面物理机当机的时时间与osd当机的时间基本上是同时。

由于物理机(KVM HOST)的问题比较严重，所以先查它的问题，查看系统日志发现是之前已经知道的一个原因导致的。这个原因是：由于这一批物理机部署的比较久，当时是安装的centos7.0，kernel是3.10-123，由于我们使用了openvswitch，而这个版本的Kernel有一个openvswitch的Bug，在某些极端的状况下，会出现Soft lockup的问题。由于升级kernel会影响客户的VM，所以一直没有升级。

再分析ceph osd down掉的问题

一开始怀疑是由于网络流量高导致的心跳不正常，最后发现在那个时间段，使用该存储集群的物理机的流量在那个时间段内都没有流量异常，初步排除由于Guest OS导致的问题。

查看监控流量图，发现流量高的时间是在OSD down掉之后才发生的，所以更确定是因为ceph进行数据恢复导致的流量攀升，所以确定流量异常和OSD异常的关系是：OSD异常是因，流量异常是果。

再分析OSD异常的原因，首先发现monitor有以下日志：

2015-09-11 05:50:50.941975 7fc7f0985700  1 mon.mdsmon1@0(leader).osd e59081 prepare_failure osd.13 192.168.20.22:6806/23132 from osd.56 192.168.20.25:6828/4297 is reporting failure:1
2015-09-11 05:50:50.941995 7fc7f0985700  0 log_channel(cluster) log [DBG] : osd.13 192.168.20.22:6806/23132 reported failed by osd.56 192.168.20.25:6828/4297
2015-09-11 05:50:51.494959 7fc7f33be700  0 log_channel(cluster) log [INF] : pgmap v35579953: 2688 pgs: 2688 active+clean; 13309 GB data, 40498 GB used, 34722 GB / 75220 GB avail; 101082 B/s rd, 3726 kB/s wr, 883 op/s
2015-09-11 05:50:51.839815 7fc7f0985700  1 mon.mdsmon1@0(leader).osd e59081 prepare_failure osd.13 192.168.20.22:6806/23132 from osd.12 192.168.20.22:6800/45218 is reporting failure:1
2015-09-11 05:50:51.839834 7fc7f0985700  0 log_channel(cluster) log [DBG] : osd.13 192.168.20.22:6806/23132 reported failed by osd.12 192.168.20.22:6800/45218
2015-09-11 05:50:52.551379 7fc7f33be700  0 log_channel(cluster) log [INF] : pgmap v35579954: 2688 pgs: 2688 active+clean; 13309 GB data, 40498 GB used, 34722 GB / 75220 GB avail; 159 kB/s rd, 4259 kB/s wr, 804 op/s
2015-09-11 05:50:52.822059 7fc7f0985700  1 mon.mdsmon1@0(leader).osd e59081 prepare_failure osd.13 192.168.20.22:6806/23132 from osd.14 192.168.20.22:6820/4240 is reporting failure:1
2015-09-11 05:50:52.822077 7fc7f0985700  0 log_channel(cluster) log [DBG] : osd.13 192.168.20.22:6806/23132 reported failed by osd.14 192.168.20.22:6820/4240
2015-09-11 05:50:53.304056 7fc7f0985700  1 mon.mdsmon1@0(leader).osd e59081 prepare_failure osd.13 192.168.20.22:6806/23132 from osd.97 192.168.20.29:6833/42329 is reporting failure:1
2015-09-11 05:50:53.304074 7fc7f0985700  0 log_channel(cluster) log [DBG] : osd.13 192.168.20.22:6806/23132 reported failed by osd.97 192.168.20.29:6833/42329
2015-09-11 05:50:53.304280 7fc7f0985700  1 mon.mdsmon1@0(leader).osd e59081  we have enough reports/reporters to mark osd.13 down

大体意思就是说，有好几个OSD都报告说osd.13DOWN掉了，既然大家都这么说，那就认为它死了吧。

再看这个osd的日志：

 -3722> 2015-09-11 05:50:34.371402 7f91c3e0f700  1 -- 192.168.20.22:6809/23132 <== osd.45 192.168.20.24:0/45829 1146487 ==== osd_ping(ping e59081 stamp 2015-09-11 05:50:34.557436) v2 ==== 47+0+0 (3343728556 0 0) 0x148d0200 con 0xab37220
 -3721> 2015-09-11 05:50:34.371436 7f91c260c700  1 -- 192.168.20.22:6808/23132 <== osd.45 192.168.20.24:0/45829 1146487 ==== osd_ping(ping e59081 stamp 2015-09-11 05:50:34.557436) v2 ==== 47+0+0 (3343728556 0 0) 0x6e2e800 con 0xab32c00
 -3720> 2015-09-11 05:50:34.371459 7f91c3e0f700  1 -- 192.168.20.22:6809/23132 --> 192.168.20.24:0/45829 -- osd_ping(ping_reply e59081 stamp 2015-09-11 05:50:34.557436) v2 -- ?+0 0x127f1400 con 0xab37220
 -3719> 2015-09-11 05:50:34.371547 7f91c260c700  1 -- 192.168.20.22:6808/23132 --> 192.168.20.24:0/45829 -- osd_ping(ping_reply e59081 stamp 2015-09-11 05:50:34.557436) v2 -- ?+0 0x1055e000 con 0xab32c00
 -3718> 2015-09-11 05:50:34.518138 7f91c260c700  1 -- 192.168.20.22:6808/23132 <== osd.90 192.168.20.28:0/13937 1146080 ==== osd_ping(ping e59081 stamp 2015-09-11 05:50:34.918851) v2 ==== 47+0+0 (2786616502 0 0) 0x15bfb800 con 0xadb44c0
 -3717> 2015-09-11 05:50:34.518181 7f91c260c700  1 -- 192.168.20.22:6808/23132 --> 192.168.20.28:0/13937 -- osd_ping(ping_reply e59081 stamp 2015-09-11 05:50:34.918851) v2 -- ?+0 0x6e2e800 con 0xadb44c0
 -3716> 2015-09-11 05:50:34.518227 7f91c3e0f700  1 -- 192.168.20.22:6809/23132 <== osd.90 192.168.20.28:0/13937 1146080 ==== osd_ping(ping e59081 stamp 2015-09-11 05:50:34.918851) v2 ==== 47+0+0 (2786616502 0 0) 0xff8fe00 con 0x11ce1600
 -3715> 2015-09-11 05:50:34.518307 7f91c3e0f700  1 -- 192.168.20.22:6809/23132 --> 192.168.20.28:0/13937 -- osd_ping(ping_reply e59081 stamp 2015-09-11 05:50:34.918851) v2 -- ?+0 0x148d0200 con 0x11ce1600
 -3714> 2015-09-11 05:50:34.686020 7f91af0da700  1 -- 192.168.20.22:6807/23132 <== osd.73 192.168.20.27:6825/23657 1691650 ==== osd_repop(client.2449020.0:3342441 3.13e e056913e/rbd_data.255e726b8b4567.0000000000000e46/head//3 v 59081'19449146) v1 ==== 929+0+8971 (805582020 0 3664754197) 0xdfa3c00 con 0xb401760
 -3713> 2015-09-11 05:50:34.686433 7f91af0da700  5 -- op tracker -- seq: 39473910, time: 2015-09-11 05:50:34.685145, event: header_read, op: osd_repop(client.2449020.0:3342441 3.13e e056913e/rbd_data.255e726b8b4567.0000000000000e46/head//3 v 59081'19449146)
 -3712> 2015-09-11 05:50:34.686618 7f91af0da700  5 -- op tracker -- seq: 39473910, time: 2015-09-11 05:50:34.685147, event: throttled, op: osd_repop(client.2449020.0:3342441 3.13e e056913e/rbd_data.255e726b8b4567.0000000000000e46/head//3 v 59081'19449146)
 -3711> 2015-09-11 05:50:34.686658 7f91af0da700  5 -- op tracker -- seq: 39473910, time: 2015-09-11 05:50:34.685897, event: all_read, op: osd_repop(client.2449020.0:3342441 3.13e e056913e/rbd_data.255e726b8b4567.0000000000000e46/head//3 v 59081'19449146)
 -3710> 2015-09-11 05:50:34.686712 7f91af0da700  5 -- op tracker -- seq: 39473910, time: 0.000000, event: dispatched, op: osd_repop(client.2449020.0:3342441 3.13e e056913e/rbd_data.255e726b8b4567.0000000000000e46/head//3 v 59081'19449146)

结合最后死掉的日志，分析就是这个OSD和其它的OSD都不太能发送和接受心跳包了，问题是，为什么？？？

经过一系列的分析，结果是无果，但是也看到了另外一个线索即：计算节点物理机的crash时间正好在这三个OSD出现故障之前。

最终，因为正好大胆地做了一个假设：rbd的客户端(kvm)因为kernel出现了异常，所以无法完成分布式存储的某些操作，进而导致相关对象所在的块的OSD有了锁之类的东西，进而导致这个OSD无法正常反馈心跳，进而导致了OSD被自己断言死亡。

这是一个猜测，但是是一个非常合理的猜测。

有知道的同学，也请告知，回头把这个问题报告到社区中问一下。