ossfs：两个Cache引发的Bug

2022-06-06 09:39:18

背景

ossfs是一个可以将OSS的Bucket挂载到本地文件系统的工具，用户可以像操作本地文件一样（ls/cat/stat）操作OSS的Object。

随机Fail

在跑ossfs的测试时，一个CASE偶尔会fail，确认原因时，发现这个CASE的逻辑非常简单：

function test_truncate_file {
    echo "Testing truncate file ..."
    # Write a small test file
    echo "${TEST_TEXT}" > ${TEST_TEXT_FILE}

    # Truncate file to 0 length.  This should trigger open(path, O_RDWR | O_TRUNC...)
    : > ${TEST_TEXT_FILE}

    # Verify file is zero length
    if [ -s ${TEST_TEXT_FILE} ]
    then
        echo "error: expected ${TEST_TEXT_FILE} to be zero length"
        exit 1
    fi
    rm_test_file
}

CASE分为3步：

写一点东西到文件test-file
通过bash中的重定向命令: > test-file将文件变成空
检查文件的size是0

失败发生在第3步，有时文件的size不是0！How can?

重现

于是决定用简单的方法重现：

挂载ossfs到/tmp/ossfs
用一个脚本反复地跑，直到fail

i=0
file=/tmp/ossfs/test-cache

while echo 'hello world' > $file \
    && : > $file \
    && [ ! -s $file ] \
; do echo $i && i=$((i+1)); done

果然很容易就重现了。

第一个Cache

开启ossfs的debug模式：

stdbuf -oL -eL ossfs gems /tmp/ossfs -ourl=http://oss-test.aliyun-inc.com \
    -f -d -d -s

注意上面的stdbuf -oL -eL可以让程序的输出是line buffered，避免有些log没有及时打出来的情况。（ 这个很关键 ）-f -d -d -s让ossfs输出debug日志。

再运行重现脚本，出现fail时，ossfs的输出是：

unique: 5325, opcode: OPEN (14), nodeid: 2, insize: 48, pid: 11713
open flags: 0x8201 /test-cache
[INF] s3fs.cpp:s3fs_open(2007): [path=/test-cache][flags=33281]

unique: 5326, opcode: REMOVEXATTR (24), nodeid: 2, insize: 53, pid: 11713
removexattr /test-cache security.ima
[INF] s3fs.cpp:s3fs_removexattr(3200): [path=/test-cache][name=security.ima]
   unique: 5326, error: -61 (No data available), outsize: 16

unique: 5327, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 11713
flush[5]
[INF] s3fs.cpp:s3fs_flush(2127): [path=/test-cache][fd=5]
[INF]       fdcache.cpp:RowFlush(1302): [tpath=][path=/test-cache][fd=5]
   unique: 5327, success, outsize: 16

unique: 5328, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 11713
flush[5]
[INF] s3fs.cpp:s3fs_flush(2127): [path=/test-cache][fd=5]
[INF]       fdcache.cpp:RowFlush(1302): [tpath=][path=/test-cache][fd=5]
   unique: 5328, success, outsize: 16

unique: 5329, opcode: RELEASE (18), nodeid: 2, insize: 64, pid: 0

unique: 5330, opcode: LOOKUP (1), nodeid: 1, insize: 51, pid: 11713
LOOKUP /test-cache
getattr /test-cache
[INF] s3fs.cpp:s3fs_getattr(797): [path=/test-cache]
release[5] flags: 0x8001
[INF] s3fs.cpp:s3fs_release(2180): [path=/test-cache][fd=5]
   NODEID: 2
[INF]       cache.cpp:DelStat(404): delete stat cache entry[path=/test-cache]
   unique: 5330, success, outsize: 144

unique: 5331, opcode: GETXATTR (22), nodeid: 2, insize: 68, pid: 11713
getxattr /test-cache security.capability 20

其中XATTR相关的日志可以忽略。上面的log中看到：

第5325次操作是open(O_TRUNC)，对应的是: > $file这句
之后的flush和release是关闭文件后的操作
第5330次的getattr操作对应的是判断文件size为0: [ ! -s $file ]

注意到getattr下面并没有发送HTTP HEAD请求向OSS获取文件的信息，从代码中可以看到，ossfs中有一个StatCache，用户缓存文件的Stat信息，这样能够避免频繁地发送HEAD请求以获取文件的size等meta信息。

src/s3fs.cpp
static int get_object_attribute(...)
{
  // ...
  // Check cache.
  strpath = path;
  if(overcheck && string::npos != (Pos = strpath.find("_$folder$", 0))){
    strpath = strpath.substr(0, Pos);
    strpath += "/";
  }
  if(pisforce){
    (*pisforce) = false;
  }
  if(StatCache::getStatCacheData()->GetStat(strpath, pstat, pheader, overcheck, pisforce)){
    return 0;
  }
  if(StatCache::getStatCacheData()->IsNoObjectCache(strpath)){
    // there is the path in the cache for no object, it is no object.
    return -ENOENT;
  }
  // ...
}

所以这次getattr是直接从ossfs的stat cache中取的。在代码中加入更多的debug信息后看到，这次getattr拿到的size是12，就是上次操作的size。为什么cache没有被更新呢？

从代码中看到在s3fs_release中进行了DelStat的操作：

static int s3fs_release(const char* path, struct fuse_file_info* fi)
{
  S3FS_PRN_INFO("[path=%s][fd=%llu]", path, (unsigned long long)(fi->fh));

  // [NOTICE]
  // At first, we remove stats cache.
  // Because fuse does not wait for response from "release" function. :-(
  // And fuse runs next command before this function returns.
  // Thus we call deleting stats function ASSAP.
  //
  if((fi->flags & O_RDWR) || (fi->flags & O_WRONLY)){
    StatCache::getStatCacheData()->DelStat(path);
  }

同时，还有一段颇长的注释。可以看到是由于fuse的一个known issue，导致s3fs_release函数是被异步调用的，也就是说发生了现在的时序：

        T1                        T2

echo 'hello world' > $file    put stat into cache

      : > $file

      getattr

                           release(delete stat from cache)

由于cache没有及时被删掉，导致第3步的操作获取到的stat还是第1步的操作放到cache中的结果。

尝试修复

既然在release中DelStat太晚了，那么将它提前到flush中总可以了吧？于是做了下面的fix：

--- a/src/fdcache.cpp
+++ b/src/fdcache.cpp
@@ -1297,6 +1297,8 @@ int FdEntity::NoCacheCompleteMultipartPost(void)

 int FdEntity::RowFlush(const char* tpath, bool force_sync)
 {
+  StatCache::getStatCacheData()->DelStat(path.c_str());
+
   int result;

   S3FS_PRN_INFO3("[tpath=%s][path=%s][fd=%d]", SAFESTRPTR(tpath), path.c_str(), fd);

修复后再跑，发现还是会随机fail。

第二个Cache

这次fail时的log更加奇怪：

unique: 671, opcode: OPEN (14), nodeid: 2, insize: 48, pid: 3641
open flags: 0x8201 /test-cache
[INF] s3fs.cpp:s3fs_open(2006): [path=/test-cache][flags=33281]

unique: 672, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 3641
flush[4]
[INF] s3fs.cpp:s3fs_flush(2126): [path=/test-cache][fd=4]
[INF]       fdcache.cpp:RowFlush(1302): [tpath=][path=/test-cache][fd=4]
   unique: 672, success, outsize: 16

unique: 673, opcode: RELEASE (18), nodeid: 2, insize: 64, pid: 0
release[4] flags: 0x8001
[INF] s3fs.cpp:s3fs_release(2179): [path=/test-cache][fd=4]
[INF]       cache.cpp:DelStat(404): delete stat cache entry[path=/test-cache]
[INF]       fdcache.cpp:GetFdEntity(1779): [path=/test-cache][fd=4]
   unique: 673, success, outsize: 16

注意到最后一步并不是getattr。为什么[ ! -s $file ]这句话没有对应的getattr呢？手动执行stat -c %s /tmp/ossfs/test-cache，发现第执行一次都会增加一条log：

unique: 674, opcode: LOOKUP (1), nodeid: 1, insize: 51, pid: 3645
LOOKUP /test-cache
getattr /test-cache
[INF] s3fs.cpp:s3fs_getattr(796): [path=/test-cache]
[INF]       curl.cpp:HeadRequest(2141): [tpath=/test-cache]
   NODEID: 2
   unique: 674, success, outsize: 144

unique: 675, opcode: LOOKUP (1), nodeid: 1, insize: 51, pid: 3648
LOOKUP /test-cache
getattr /test-cache
[INF] s3fs.cpp:s3fs_getattr(796): [path=/test-cache]
   NODEID: 2
   unique: 675, success, outsize: 144

连续两次执行的结果如上，可以看到第1次执行的时候由于Cache里没有，发生一次HEAD请求，第二次的时候直接从Cache里读出来。

循环执行100遍：for i in $(seq 100); do stat -c %s /tmp/ossfs; done，
发现并没有增加100条log！而只增加了1条！

为什么手动执行每次都能触发，但是循环就不行？猜测原因可能是：

fuse会对请求作group，短时间内的100次请求被group处理了
文件系统会对文件的stat进行cache

针对第1条猜测，去看libfuse的代码，并没有发现有group处理的逻辑。

针对第2条猜测，请教了内核和存储相关的同学，得到的答案是即使有cache（page cache)也不应该这么快就过期。

于是再去看fuse的代码，一个偶然的机会，看到fuse居然有一个attr_timeout，默认的时间是1s！上面的问题终于有了答案：fuse对attr有cache。

本以为到此为止，问题都解决了。但是fuse的这个解释说只要文件操作是经过内核的，attr_timeout不为0时正确性是保证的：对这个文件进行了相关的操作时，内核会invalidate这个cache（使cache失效）。

那么为什么truncate文件这个操作没有invalidate这个cache呢？突然想到有没有可能还是release的问题，要到release时才会invalidate这个cache，而release可能被异步执行。皓然认为不应该：为什么要到release才会去更新？

而我用C语言做了一个实验：用O_TRUNC的方式打开一个有内容的文件，然后就sleep，并不关闭它。另外一边用stat去看这个文件的大小，结果是open后文件的size就变成0了。

所以应该不是release的问题。

Kernel的问题

为了查清这个cache到底什么时候被失效，决定去看一看kernel的代码。我出问题的系统是CentOS6.5，内核是2.6.32版本的，于是去这里下载了2.6.32的代码，看到fs/fuse/file.c中：

// fs/fuse/file.c
void fuse_finish_open(struct inode *inode, struct file *file)
{
    struct fuse_file *ff = file->private_data;
    struct fuse_conn *fc = get_fuse_conn(inode);

    if (ff->open_flags & FOPEN_DIRECT_IO)
        file->f_op = &fuse_direct_io_file_operations;
    if (!(ff->open_flags & FOPEN_KEEP_CACHE))
        invalidate_inode_pages2(inode->i_mapping);
    if (ff->open_flags & FOPEN_NONSEEKABLE)
        nonseekable_open(inode, file);
    if (fc->atomic_o_trunc && (file->f_flags & O_TRUNC)) {
        struct fuse_inode *fi = get_fuse_inode(inode);

        spin_lock(&fc->lock);
        fi->attr_version = ++fc->attr_version;
        i_size_write(inode, 0);
        spin_unlock(&fc->lock);
        fuse_invalidate_attr(inode);
    }
}

从这里看到，如果以O_TRUNC的方式open的话，是立即就会失效cache的。那为什么问题还会出现呢？我只能怀疑上面的if (fc->atomic_o_trunc && (file->f_flags & O_TRUNC)) {中有某个条件不满足：

fc->atomic_o_trunc，翻libfuse的代码，看到这个值默认是true的，而
通过-oatomic_o_trunc参数挂载，问题也依然存在
file->f_flags中没有包含O_TRUNC，通过log可以看到open的flags是
0x8201，而O_TRUNC是0x0200

上面的两个条件都是满足的，为什么fuse_invalidate_attr没有生效呢？为了搞清楚这个问题，我决定在fuse的代码中打印一些调试信息，然后重新编译一个fuse模块。

编译内核模块

得益于当初搞cubieboard时编译无线网卡驱动，编译内核模块应该也不难。好在CentOS的wiki还是很详细，参考下来很容易就能编译好。

make oldconfig
make prepare
make modules_prepare
make M=fs/fuse

当我下载完CentOS-6.5的内核源码正准备对fuse模块稍加修改时，一个尴尬的事情发生了：fs/fuse/file.c中并没有fuse_invalidate_attr这一段：

void fuse_finish_open(struct inode *inode, struct file *file)
{
        struct fuse_file *ff = file->private_data;
        struct fuse_conn *fc = get_fuse_conn(inode);
        struct fuse_inode *fi = get_fuse_inode(inode);

        if (ff->open_flags & FOPEN_DIRECT_IO)
                file->f_op = &fuse_direct_io_file_operations;
        if (!(ff->open_flags & FOPEN_KEEP_CACHE))
                invalidate_inode_pages2(inode->i_mapping);
        if (ff->open_flags & FOPEN_NONSEEKABLE)
                nonseekable_open(inode, file);

        /* file might be required for fallocate */
        spin_lock(&fc->lock);
        if (S_ISREG(inode->i_mode) && (file->f_mode & FMODE_WRITE))
                list_add(&ff->write_entry, &fi->write_files);
        spin_unlock(&fc->lock);
}

原来如此！ 而我手动添加这几行代码后再编译&替换掉fuse模块，一切正常！

modprobe -r fuse
insmod fs/fuse/fuse.ko

进一步blame发现，这个patch是在2010年的时候进的，是在2.6.32之后进的，而CentOS-6.5的内核并没有包含这个patch。

stat & lstat

在测试中还发现一个现象，使用stat -c %s $file和[ ! -s $file ]这两个方式判断文件的size为0，重现的概率不一样。后者重现的概率要高一些。通过strace发现这两个方法几乎没有区别，一个调用stat，一个调用lstat。

后来想明白了，原因是前者比后者慢，使用后者时有更大的概率release还没有调用完。而release中包含了fuse_invalidate_attr的逻辑。

stat -c %s $file需要创建一个进程（来运行stat），而[ ! -s $file ]是在和bash同样的进程中进行的，所以会更快。

码农公寓

背景