记一个P0+的Bug

背景

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

初步应对

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

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

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

在关闭所有影响录制IO的进程后,重新读取错误的redo日志录制IO,得到数百个IO模型,frontend组编写脚本,将blktrace录制的IO转化为存储内部使用的chunk_idoffsetvolume_idpg_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暴露了好几个问题: