01 起因
EFC（Elastic File Client）是 NAS 自研的分布式文件系统客户端，最近完成了对缓存架构的更新，现在支持多个客户端之间构成分布式缓存，底层支持 NAS、CPFS 和 OSS。由于开发时间较短，一直没有做 NAS 场景 CTO 测试的适配。
CTO：Close-to-Open，指当一个文件被关闭后，再次 open 时，文件系统必须保证之前所有通过 close 操作提交的数据已经持久化到文件系统，并且读取时能获取到最新的、一致的状态。
CTO 测试的具体实现是对本地和远端文件系统的文件执行相同的操作，在某些操作后读取两端文件系统的内容，比较是否相同。
本地为 EXT4 文件系统，符合 POSIX 语义，远端文件系统跟本地文件系统对比，信任本地文件系统的表现。
读缓存的测试是分布式的，单客户端读取由分布式缓存提供服务。
最近忙里偷闲适配了一下，静静等待测试的通过，结果没想到发生了 data mismatch 的错误，因为关闭缓存直读 NAS 的 CTO 测试在每次发版前都会跑一遍。得，缓存的锅铁定没跑了，那咱就来看看这个问题。
02 错误类型判断
读数据错误
EFC 读缓存在 NAS 场景下会使用 dv（data version）作为缓存的版本号，文件系统数据更新的时候会对 dv 自增。EFC 与文件系统通信的 RPC 会更新本地记录的 dv 信息，EFC 读缓存就会根据客户端手上的 dv 作为版本号从缓存读取数据。
由于这个机制的存在，所以 data mismatch 问题一眼认定为：使用了旧的 dv 读到了缓存里的旧数据。看来问题不大，喝口水压压惊。
CTO 测试会对本地文件和 NAS 上的文件执行相同的操作，并在执行某些操作后检查读到的文件是否一致。这样在读到缓存旧数据的情况下，本地文件（本地 /root 下）和远端文件系统的文件（NAS /mnt1 挂载下）内容是相同的。
由于 mnt1 还是通过 EFC 客户端进行挂载，读取数据还是走的缓存，依然存在读到旧数据的可能。因此，为了排除 EFC 缓存的影响，使用 NFS 协议挂载了 NAS 文件系统后（不通过 EFC 进行挂载），通过 diff 比较本地和 NAS 上的文件内容，结果两者竟然不一致。结果表明，文件系统数据被破坏掉了，也宣告着读到缓存中的旧数据的想法破产。
写数据错误！
调查过程陷入困局，决定看一下错误文件的内容有没有新的发现。由于原始文件存在大量的不可见字符，因此使用 hexdump 将文件转成 16 进制格式，每行显示 16 个字符。左侧为本地文件，右侧为 NAS 上文件，可以看到 NAS 上文件中的字符 f (0x66) 被替换成了空字符 NULL (0x00)。
但是 CTO 测试中并不会主动写入空字符，这些空字符是如何产生的呢？
计算错误字段的开始位置和结束位置：mismatch start = 0x94250 = 606800，mismatch end = 0x94ee0 + 2 = 610018，对一个 4K 页整除可以发现错误段正好位于一个 page 内。
这个 CTO 数据不一致问题几个小时的运行可以复现，每次结果的表现是一致的，均是正常字符被替换为空字符以及错误数据位于同一个 page 内（出现过数据错误开始位置正好 4K 对齐）。
这个时候开始把思路转向为：由于缓存的引入写坏了本地的 pagecache，当脏页需要刷到文件系统的时候把 pagecache 里的旧数据一并刷到了文件系统，造成了文件系统数据的不一致。
明确了问题后，现在的困扰来到了是什么操作写坏了 pagecache，以及空字符是如何产生的呢？
03 日志调查
在整个 CTO 测试期间，分析 EFC 缓存的日志，存在 6 条读缓存日志，并且命中缓存的仅有 3 条，错误也就发生在这 3 次读操作中。结合错误数据的 start offset (606208) 和 end offset (606208 + 3908 = 610116) 最终可以定位到第 3 次的读操作出错（606208 < 606800 < 610018 < 610116）。
进一步查看 CTO 测试日志，记录了每次读写操作的信息。可以看到，首先通过 op_write_append 操作追加写字符 f (0x66)，写的数据会首先存储在内核的 pagecache 中，然后通过 op_truncate_big 通知文件系统扩充文件长度到 610116，这样还没有被刷到文件系统的数据就是空字符 NULL (0x00)。接着通过op_fsync 将本地 pagecache 中的数据刷到文件系统。之后再通过 op_write_append 追加写字符 g (0x67)。
结合缓存的引入造成 pagecache 被写坏，分析第一个 op_write_append 的行为：
1.1：向内核 pagecache 中写入数据 f，pagecache 标记为 dirty；
1.2：向文件系统 setattr，扩充文件长度，扩充内容用 NULL 填充，文件系统数据的版本 dv1 → dv2；
1.3：另一个 EFC 客户端在缓冲不命中的情况下，从文件系统读取了 dv2 版本的 NULL 数据，并写到分布式缓存中；
1.4：在某个时刻（可能是主动 fsync 或者内核逻辑），pagecache 中的脏数据被刷到文件系统，NULL 被覆盖为 f，文件系统数据版本 dv2 → dv3；
接着分析第二个 op_write_append 的行为：
2.1：由于 direct 设置为 0，是一个 buffer 写操作，会先读取数据到 pagecache 中。由于缓存的存在，读取到了 dv2 版本的数据到 pagecache 中，填充为 NULL。
2.2：向内核 pagecache 中写入数据 g，pagecache 标记为 dirty。
2.3：向文件系统 setattr，扩充文件长度，扩充内容用 NULL 填充，文件系统数据的版本 dv3 → dv4。
2.4：pagecache 中的脏数据被刷到文件系统，NULL 被覆盖为 g，但是正确数据 f 被覆盖为 pagecache 中的 NULL，造成了文件系统数据不一致。
由于 buffer 写先读后写的行为，从缓存中读取到了旧版本的 dv2 数据，但是文件系统的数据已经更新到 dv3 版本，使用最新的 dv3 读取数据应该会缓存失效，直读文件系统才正确（直读文件系统读取 dv3 数据 f 到 pagecache 中也不会存在 NULL 刷到文件系统造成数据不一致的问题）。
而 EFC 客户端对每一个文件都会本地记录一个 dv 号用于读文件系统，推测 dv 发生了回退，查看 EFC 缓存日志也可以观察到 dv 回退的现象（5676 → 5675）。
分析后认为漂移在网络上的慢读请求会造成 dv 回退现象发生：假设存在一个 read 请求，从文件系统读到了 dv2，但是迟迟没有返回。而在中途其他的 write 更新了文件系统的 dv3，并通过 RPC 更新本地版本为 dv3。之后，慢 read 带回来 dv2 的数据到缓存中，且又使用 dv2 覆盖了客户端记录的 dv3，后续用 dv2 读取缓存就会读到旧数据。
04 问题复原
根据上述分析，错误的原因总结为：缓存读到了追加写操作中文件系统填充为 NULL 的数据，这部分数据在下一次 buffer 写操作中被读取到 pagecache 中，再被新数据写脏后刷到文件系统，缓存中的旧数据 NULL 破坏了文件系统数据，造成数据不一致。可以复原出写坏文件系统数据的整个流程：
client1 发起 append write，分为 write 和 setattr；
write 写数据 f 到 pagecache 中；
setattr 请求会发到文件系统扩充文件长度，扩充部分填充为字符 NULL；
client2 发起 read，读到数据空字符 NULL 写到缓存中；
client1 将 pagecache 中的数据 f 刷到文件系统；
client1 再次发起 buffer write，分为 read 和 write；
client1 拿到旧的 dv，读缓存读到旧数据 NULL（buffer write 会先读取数据到 pagecache），缓存中的数据读到 pagecache 中；
client1 write 了另一部分脏数据 g 到 pagecache 中（位于同一个 page）；
client1 将 pagecache 中的数据 NULL + g 刷到文件系统，原来的数据 f 被覆盖为 NULL，造成了文件系统数据的错误；
问题的根本原因在于：版本号发生回退，客户端使用了旧版本号从缓存中读到了旧数据。问题分析清楚后，还是比较好修复的，在本地维护了一个递增的缓存版本号，丢弃 RPC 收到的发生回退的版本号即可。
使用修复后的版本重新运行 CTO 测试，10 轮次近 30 个小时无数据不一致发生，可以认为问题得到了修复。
05 部分 POSIX 接口底层揭秘
到此为止，文件系统数据写坏的问题已经分析得差不多了，但是还是对内核发到 EFC 客户端的请求存在一知半解。纸上得来终觉浅，绝知此事要躬行。于是，写了一个简单的 python 程序模拟上述操作，模拟用户对文件进行操作，观察 EFC 客户端收到的内核请求信息：
1. open调用 open 打开文件；
2. fstat调用 getattr 获取文件大小；
3. pwrite在文件结尾（1M）追加写 1K 长度的字符 f。在 26s 执行时并未向 EFC 客户端发送请求，此时将数据 f 写到内核 pagecache 中；在 31s ftruncate执行时调用 setattr 扩充文件系统文件长度，并调用 write 将 pagecache 中数据写到文件系统；
4. ftruncate扩充文件长度为 2K，和 pwrite一起仅触发一次 setattr 调用；
5. fsync调用 fsync 将 pagecache 中数据显式刷到文件系统；
6. pwrite继续在文件末尾（1M + 1K）追加 1K 长度的字符 g。在 42s 执行时调用 read 读取数据到内核的 pagecache 中，并将数据 g 写到内核 pagecache 中；在 47s close执行时调用 write 将 pagecache 中数据写到文件系统，调用 setattr 更新文件属性；
7. close调用 flush 再次保证 pagecache 中数据刷到文件系统，调用 release 关闭文件；
由于内核会对用户的操作进行很多优化，很难将内核的行为一一罗列，这里仅对本次模拟过程中内核行为和用户操作不同的地方进行介绍：
setattr 触发机制
用户操作：
pwrite（写入 1K）与ftruncate（扩展 2K）均涉及文件长度扩展。内核行为：仅在
ftruncate时触发一次 setattr 请求，扩展文件长度至最终值（1M + 2K）。差异点：
pwrite本身不会直接触发 setattr，而是依赖后续 write 或ftruncate的操作。pwrite的 1K 写入被缓存在 pagecache 中，最终与ftruncate的 2K 扩展合并为一次 setattr 请求。
buffer write 的 pagecache 延迟提交
用户操作：
pwrite（26s）写入 1K 数据，但未立即触发内核请求。内核行为：数据先写入 pagecache，直到
ftruncate（31s）或fsync（36s）触发 write 请求时才提交至文件系统。差异点：用户需注意
pwrite仅为用户态写入，实际落盘需依赖 write 或fsync。
buffer write 先读数据到 pagecache
用户操作：第二次
pwrite（42s）在文件末尾追加 1K 数据。内核行为：内核先通过 getattr 和 read 请求读取目标页（4K）到 pagecache，再执行写入。
差异点：当写入位置超出当前 pagecache 范围时，内核会主动读取缺失页以保证写入完整性。
setattr 与 write 的顺序问题
用户操作：
ftruncate扩展文件长度后，pwrite数据需写入新扩展区域。内核行为：setattr 先扩展文件长度，填充 NULL 字符；write 请求将 pagecache 数据写入文件系统时，才真正填充空洞区域。
差异点：若在此期间读取文件，可能读取到未填充的空洞数据（本文 bug 读取到缓存的数据就发生在这次 setattr 和下一次 write 之间）
close 的双重作用
用户操作：
close仅视为关闭文件。内核行为：触发 flush（47s）确保数据持久化，并调用 release（47s）释放资源。
差异点：
close隐含了数据刷盘操作，即使未显式调用fsync。
06 心得体会
这个错误从发现到最后解决耗时了半个多月，从开始时发现文件系统错误时的迷茫，到发现空字符的错误数据以及位于一个 page 内，提供了 pagecache 写坏刷到文件系统的想法，之后不断根据日志分析可能存在的写坏文件系统操作，并验证猜想。
整个过程还是比较坎坷的，也学到了很多新知识：比如 buffer 写会先读后写，append 写会对文件系统扩充字符先填充为空字符，以及在网络上漂移的慢请求带来的异常影响等。后续在分析问题以及开发过程中，有了这些先验知识，就可以考虑得更为全面，在这里分享给大家。
附录
import osimport timelen = 1024print_time("open")fd = os.open("/mnt1/file1M", os.O_RDWR)time.sleep(5)print_time("fstat")file_size = os.fstat(fd).st_sizeprint(file_size)time.sleep(5)data = b'f' * lenprint_time("pwrite")os.pwrite(fd, data, file_size)time.sleep(5)print_time("ftruncate")os.ftruncate(fd, file_size + 2 * len)time.sleep(5)print_time("fsync")os.fsync(fd)time.sleep(5)data = b'g' * lenprint_time("pwrite")os.pwrite(fd, data, file_size + len)time.sleep(5)print_time("close")os.close(fd)
)
