记一个P0+的Bug

背景

在产品TR5阶段的测试中，和存储团队对接的管理面团队发现Oracle的日志归档程序报错，具体为redo日志文件损坏。 在梳理问题后得到最初的一些背景：

初步应对

首先数据肯定是错了，具体哪里出了问题还没有结论，但可以初略分成两个部分：

  1. raft 三副本复制错误
  2. localstore 读取错误
  3. frontend 条带化错误

由于复现需要耗时很久，现场可以直接读这个错误的文件，然后将IO用blktrace录制下来，根据录制在localstore通过命令行工具校验三个副本的数据是否一致。

在关闭所有影响录制IO的进程后，重新读取错误的redo日志录制IO，得到数百个IO模型，frontend组编写脚本，将blktrace录制的IO转化为存储内部使用的chunk_id、offset、volume_id、pg_id等数据，再由localstore组编写脚本，使用这些数据对比三副本数据。

结果发现，这些数据块上根本没有写过数据！

反复确认，发现frontend组的脚本没有正确的配置条带化参数以及卷id。

由于复现困难，管理面还需要使用环境做其他测试，初步应对宣告失败。

另一种思路

根据背景中掌握的信息，可以推测是 512 字节小IO的某种模式触发了存储的bug，同时由于blktrace 抓下来的IO还需要通过脚本转换， 并且脚本可能出错（使用了不同于frontend运行时的配置），安排如下：

经过一天的努力，以上三个任务都已经完成，在春节期间，使用测试程序进行不间断的测试。

春节结束后，回顾测试，发现仅复现了一次，测试结果显示：读请求读到了旧的数据。

为了确保不再发生参数错误的问题，raft组代表被要求review这个测试程序，同时检查raft组的相关代码，是否存在读到旧数据的问题。frontend组被要求梳理条带化相关代码。同时，在存储内部的性能环境上搭建Oracle测试环境，用于复现问题。

这种方式也以失败告终。

为什么数据校验没有报错

对于数据本身就写错的情况，数据校验无法检查。 针对这种情况，在存储中的各个模块的读写请求增加额外的检查（chksec模块），分配一大块内存（数据错误位置大约是300M，所有这个方法可行，否则内存不够用）每一个写请求的512字节都算一个checkcusm，在读请求完成时重新计算checksum，和写时记录的对比。

任务安排如下：

测试发现，存储中的所有模块都在报错误，这不得不怀疑chksec模块的正确性，于是

接下来怎么办

经历了一系列的措施，仍然没有将问题范围缩小。 任务安排如下：

frontend的工作

好消息是存储中的模块有明显的界限，从frontend到crpc仅经历了网络传输，从crpc到localstore才经历了raft。另外，由于前期已经拿到了redo日志错误的读取模式（凭借公司DBA丰富的经验），能够稳定的复现出来。frontend组将crpc模块中错误IO模式对应得chunk镜像到文件中，同时frontend中也做相同的事。然后对比写入的数据和读取的数据是否一致。

结构发现，crpc中写入和读取完全一致，frontend中出现了不一致的情况，因此可以确定问题一定出在frontend中。

随后在frontend中针对出错的IO模式增加日志打印，发现：

在条带化的代码中增加额外的日志，对比以上两种IO模式发现，第一种IO会被拆成 32 + 32 + 32 + 7 个子IO，第二种IO会被拆成 31 + 32 + 32 + 7 个子IO，注意到数据出错是最后的 7 个IO。

通过对比发现，出现错误的IO模式的倒数第7个IO在发送时被拆成了两个iovec：

iov[0].iov_len 512
iov[1].iov_len 3072

而crpc回复时是一个WR （RDMA Work Request），最早在实现时约定，IO不足4k的单独使用一个WR发送，frontend会根据header后的64位拿到这个不足4k的数据的真实长度，一次性获取完。这部分代码如下：

static void parse_8bytes(struct conn_ctx *c, char *iov)
{
        ASSERT(c->p_status == P_8B);
        uint64_t _offset = 0;

        SPDK_INFOLOG(chunk_client_utils, "recv 8bytes id 0x%lx length %lu",
                c->rpl_hdr->request_id, c->_8b);

        if ((c->rpl_hdr->nr_chksum > 0) &&
                proc_chk_point_is_enable(PROC_CHK_POINT_FE_READ))
                cal_rcv_chksum(c, iov, c->_8b);

        while (_offset < c->_8b) {
                char *dst = c->rio->iov[c->r_idx].iov_base;
                uint64_t sz = spdk_min(c->_8b - _offset,
                        c->rio->iov[c->r_idx].iov_len);

                memcpy(dst, iov, sz);
                c->r_offset += sz;
                _offset += sz;

                ASSERT(c->rpl_hdr->bytes >= sz);
                c->rpl_hdr->bytes -= sz;

                if (c->rpl_hdr->bytes == 0) {
                        // _8b maybe less than 4k
                        if (c->rpl_hdr->nr_chksum > 0) {
                                c->p_status = P_CHKSUM;
                                return;
                        }

                        ASSERT(c->_8b <= MEMPOOL_ELEM_SZ);
                        parse_done(c);
                        return;
                }

                if (c->r_offset == c->rio->iov[c->r_idx].iov_len) {
                        c->r_offset = 0;
                        c->r_idx += 1;
                }
        }
        c->p_status = P_DATA;
}

可以看到，它是正确处理了本地拆分成的两个iovec的，但问题是，在循环过程种源iov的偏移没有增加

memcpy(dst, iov, sz);

这导致dst的前512字节会被覆盖掉，感觉像是数据被往前移动了512字节。

修改如下：

memcpy(dst, iov + _offset, sz);

这段代码同时也解释了为什么数据校验没有检查出错误：因为错误发生在数据校验之后。

总结

这个bug暴露了好几个问题：