ossfs:两个Cache引发的Bug

背景

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步:

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

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

重现

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

  1. 挂载ossfs到/tmp/ossfs
  2. 用一个脚本反复地跑,直到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中看到:

  1. 第5325次操作是open(O_TRUNC),对应的是: > $file这句
  2. 之后的flush和release是关闭文件后的操作
  3. 第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中的结果。

尝试修复

既然在releaseDelStat太晚了,那么将它提前到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条!

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

  1. fuse会对请求作group,短时间内的100次请求被group处理了
  2. 文件系统会对文件的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)) {中有某个条件不满足:

  1. fc->atomic_o_trunc,翻libfuse的代码,看到这个值默认是true的,而
    通过-oatomic_o_trunc参数挂载,问题也依然存在
  2. 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同样的进程中进行的,所以会更快。

上一篇:阿里云函数计算支持 Python 运行环境


下一篇:[转]jQuery的.live()和.die()