Bug #1975: btrfs: EINVAL on snap create - Ceph - Ceph

Bug #1975

btrfs: EINVAL on snap create

Added by Sage Weil over 11 years ago. Updated about 11 years ago.

Status:

Won't Fix

Priority:

Normal

Assignee:

Joao Eduardo Luis

Category:

OSD

Target version:

% Done:

Source:

Tags:

Backport:

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Pull request ID:

Crash signature (v1):

Crash signature (v2):

Description

/var/lib/teuthworker/archive/nightly_coverage_2012-01-24-a/8879

os/FileStore.cc: In function 'void FileStore::sync_entry()', in thread '7fe8e22fb700'
os/FileStore.cc: 3059: FAILED assert(r == 0)
 ceph version 0.40-217-g1e42109 (commit:1e4210937fa3951881d39425a0469dcadaae61bf)
 1: (FileStore::sync_entry()+0x2d9f) [0x7fb12f]
 2: (FileStore::SyncThread::entry()+0x15) [0x829e25]
 3: (Thread::_entry_func(void*)+0x12) [0x637042]
 4: (()+0x7971) [0x7fe8e977b971]
 5: (clone()+0x6d) [0x7fe8e7e0692d]
 ceph version 0.40-217-g1e42109 (commit:1e4210937fa3951881d39425a0469dcadaae61bf)
 1: (FileStore::sync_entry()+0x2d9f) [0x7fb12f]
 2: (FileStore::SyncThread::entry()+0x15) [0x829e25]
 3: (Thread::_entry_func(void*)+0x12) [0x637042]
 4: (()+0x7971) [0x7fe8e977b971]
 5: (clone()+0x6d) [0x7fe8e7e0692d]

improving the error reporting to catch this one.

History

#1 Updated by Sage Weil over 11 years ago

Status changed from New to 4

wip-filestore-errors check should be reviewed+merged so we can see the actual error code. sadly,

(gdb) p errno
Cannot find thread-local variables on this target

#2 Updated by Sage Weil over 11 years ago

Priority changed from High to Urgent

#3 Updated by Samuel Just over 11 years ago

wip-filestore-errors looks good to me except for one comment on github.

#4 Updated by Sage Weil over 11 years ago

2012-01-25 01:27:09.946266 7f8784da6700 filestore(/tmp/cephtest/data/osd.0.data) async snap create 'snap_320835' transid 4049074024983129715 got (22) Invalid argument
os/FileStore.cc: In function 'void FileStore::sync_entry()', in thread '7f8784da6700'
os/FileStore.cc: 3068: FAILED assert(0 == "async snap ioctl error")
 ceph version 0.40-227-g44b1144 (commit:44b11441ad3ef231ff207476bbb0d2e8ab130f26)
 1: (FileStore::sync_entry()+0x3a10) [0x81c6b0]
 2: (FileStore::SyncThread::entry()+0x15) [0x82b265]
 3: (Thread::_entry_func(void*)+0x12) [0x637442]
 4: (()+0x7971) [0x7f878c226971]
 5: (clone()+0x6d) [0x7f878a8b192d]
 ceph version 0.40-227-g44b1144 (commit:44b11441ad3ef231ff207476bbb0d2e8ab130f26)
 1: (FileStore::sync_entry()+0x3a10) [0x81c6b0]
 2: (FileStore::SyncThread::entry()+0x15) [0x82b265]
 3: (Thread::_entry_func(void*)+0x12) [0x637442]
 4: (()+0x7971) [0x7f878c226971]
 5: (clone()+0x6d) [0x7f878a8b192d]

and gdb tells us

(gdb) p async_args
$1 = {
  fd = 14, 
  transid = 4049074024983129715, 
  flags = 1, 
  unused = {0, 0, 0, 0}, 
  name = "snap_320835", '\000' <repeats 4028 times>
}

#5 Updated by Sage Weil over 11 years ago

Status changed from 4 to Need More Info

added btrfs printks to figure out where that EINVAL is coming from. also changed it to return EBADF if the fd is invalid (that's where my money is)

#6 Updated by Sage Weil over 11 years ago


[ 6094.814926] ------------[ cut here ]------------
[ 6094.814952] WARNING: at /srv/autobuild-ceph/gitbuilder.git/build/fs/btrfs/inode.c:2222 btrfs_orphan_cleanup+0x48b/0x510 [btrfs]()
[ 6094.814955] Hardware name: PDSMi
[ 6094.814956] Modules linked in: ufs qnx4 hfsplus hfs minix ntfs vfat msdos fat jfs xfs exportfs reiserfs radeon ttm drm_kms_helper drm ppdev parport_pc lp parport i3000_edac edac_core i2c_algo_bit shpchp serio_raw ahci libahci e1000e btrfs floppy zlib_deflate crc32c libcrc32c
[ 6094.814989] Pid: 20427, comm: ceph-osd Not tainted 3.2.0-ceph-00038-gf2450c8 #1
[ 6094.814991] Call Trace:
[ 6094.814998]  [<ffffffff810634af>] warn_slowpath_common+0x7f/0xc0
[ 6094.815001]  [<ffffffff8106350a>] warn_slowpath_null+0x1a/0x20
[ 6094.815014]  [<ffffffffa004256b>] btrfs_orphan_cleanup+0x48b/0x510 [btrfs]
[ 6094.815019]  [<ffffffff8131bffe>] ? do_raw_spin_unlock+0x5e/0xb0
[ 6094.815033]  [<ffffffffa0068c22>] btrfs_mksubvol+0x302/0x3d0 [btrfs]
[ 6094.815046]  [<ffffffffa0068dd8>] btrfs_ioctl_snap_create_transid+0xe8/0x180 [btrfs]
[ 6094.815059]  [<ffffffffa0068ef9>] btrfs_ioctl_snap_create_v2+0x89/0x100 [btrfs]
[ 6094.815063]  [<ffffffff8109f730>] ? __lock_acquire+0x210/0x15d0
[ 6094.815076]  [<ffffffffa006995a>] btrfs_ioctl+0x59a/0x1060 [btrfs]
[ 6094.815081]  [<ffffffff81178040>] ? fget_light+0x40/0x130
[ 6094.815085]  [<ffffffff81188714>] do_vfs_ioctl+0xa4/0x580
[ 6094.815089]  [<ffffffff811780d2>] ? fget_light+0xd2/0x130
[ 6094.815092]  [<ffffffff81178040>] ? fget_light+0x40/0x130
[ 6094.815095]  [<ffffffff81188c91>] sys_ioctl+0xa1/0xb0
[ 6094.815100]  [<ffffffff8160e1c2>] system_call_fastpath+0x16/0x1b
[ 6094.815103] ---[ end trace 13d3f124c13ac772 ]---
[ 6094.815106] weird orphan 1159 uid/gid 1000.1000 mode 040755 size 1074
[ 6094.815120] btrfs: Error removing orphan entry, stopping orphan cleanup
[ 6094.821860] btrfs: could not do orphan cleanup -22

on ubuntu@teuthology:/a/nightly_coverage_2012-01-28-a/9534

#7 Updated by Sage Weil over 11 years ago

hit this 2 days ago with ubuntu@teuthology:/var/lib/teuthworker/archive/nightly_coverage_2012-01-27-a/9261. thrashing. added more btrfs debug to console

#8 Updated by Sage Weil over 11 years ago

Assignee set to Sage Weil

#9 Updated by Sage Weil over 11 years ago


2012-02-04T20:25:48.382899-08:00 sepia78 kernel: [ 9527.548092] rmdir on ffff8800a4bff4e0 1315 got 0
2012-02-04T20:25:48.382939-08:00 sepia78 kernel: [ 9527.549597] ------------[ cut here ]------------
2012-02-04T20:25:48.383172-08:00 sepia78 kernel: [ 9527.549634] WARNING: at /srv/autobuild-ceph/gitbuilder.git/build/fs/btrfs/inode.c:2237 btrfs_orphan_cleanup+0x44b/0x4d0 [btrfs]()
2012-02-04T20:25:48.383313-08:00 sepia78 kernel: [ 9527.549638] Hardware name: H8SSL
2012-02-04T20:25:48.383399-08:00 sepia78 kernel: [ 9527.549640] Modules linked in: psmouse amd64_edac_mod edac_core serio_raw lp edac_mce_amd shpchp i2c_piix4 k8temp parport btrfs floppy tg3 sata_svw pata_serverworks zlib_deflate crc32c libcrc32c
2012-02-04T20:25:48.383536-08:00 sepia78 kernel: [ 9527.549666] Pid: 4053, comm: ceph-osd Not tainted 3.2.0-ceph-00142-g9e98323 #1
2012-02-04T20:25:48.383701-08:00 sepia78 kernel: [ 9527.549669] Call Trace:
2012-02-04T20:25:48.383779-08:00 sepia78 kernel: [ 9527.549676]  [<ffffffff810634af>] warn_slowpath_common+0x7f/0xc0
2012-02-04T20:25:48.383911-08:00 sepia78 kernel: [ 9527.549681]  [<ffffffff8106350a>] warn_slowpath_null+0x1a/0x20
2012-02-04T20:25:48.383986-08:00 sepia78 kernel: [ 9527.549699]  [<ffffffffa009649b>] btrfs_orphan_cleanup+0x44b/0x4d0 [btrfs]
2012-02-04T20:25:48.384123-08:00 sepia78 kernel: [ 9527.549705]  [<ffffffff8131bffe>] ? do_raw_spin_unlock+0x5e/0xb0
2012-02-04T20:25:48.384209-08:00 sepia78 kernel: [ 9527.549723]  [<ffffffffa00b8d42>] btrfs_mksubvol+0x302/0x3d0 [btrfs]
2012-02-04T20:25:48.384342-08:00 sepia78 kernel: [ 9527.549740]  [<ffffffffa00b8ef8>] btrfs_ioctl_snap_create_transid+0xe8/0x180 [btrfs]
2012-02-04T20:25:48.384415-08:00 sepia78 kernel: [ 9527.549758]  [<ffffffffa00b9019>] btrfs_ioctl_snap_create_v2+0x89/0x100 [btrfs]
2012-02-04T20:25:48.384546-08:00 sepia78 kernel: [ 9527.549763]  [<ffffffff8109f730>] ? __lock_acquire+0x210/0x15d0
2012-02-04T20:25:48.384619-08:00 sepia78 kernel: [ 9527.549781]  [<ffffffffa00b98fc>] btrfs_ioctl+0x41c/0x1290 [btrfs]
2012-02-04T20:25:48.384747-08:00 sepia78 kernel: [ 9527.549788]  [<ffffffff81178040>] ? fget_light+0x40/0x130
2012-02-04T20:25:48.384876-08:00 sepia78 kernel: [ 9527.549793]  [<ffffffff81188714>] do_vfs_ioctl+0xa4/0x580
2012-02-04T20:25:48.384949-08:00 sepia78 kernel: [ 9527.549798]  [<ffffffff811780d2>] ? fget_light+0xd2/0x130
2012-02-04T20:25:48.385022-08:00 sepia78 kernel: [ 9527.549803]  [<ffffffff81178040>] ? fget_light+0x40/0x130
2012-02-04T20:25:48.385169-08:00 sepia78 kernel: [ 9527.549807]  [<ffffffff81188c91>] sys_ioctl+0xa1/0xb0
2012-02-04T20:25:48.385304-08:00 sepia78 kernel: [ 9527.549813]  [<ffffffff8160e1c2>] system_call_fastpath+0x16/0x1b
2012-02-04T20:25:48.385405-08:00 sepia78 kernel: [ 9527.549817] ---[ end trace 5da2aa3d7edb35b0 ]---
2012-02-04T20:25:48.385477-08:00 sepia78 kernel: [ 9527.549820] weird orphan ffff8800ef7365d0 1315 uid/gid 1000.1000 mode 040755 size 4930
2012-02-04T20:25:48.385549-08:00 sepia78 kernel: [ 9527.549835] btrfs: Error removing orphan entry, stopping orphan cleanup
2012-02-04T20:25:48.385716-08:00 sepia78 kernel: [ 9527.556608] btrfs: could not do orphan cleanup -22
2012-02-04T20:30:42.855792-08:00 sepia78 kernel: [ 9822.024463] BTRFS: inode 1315 still on the orphan list

ubuntu@teuthology:/a/wip-journal-aio-rebased-2012-02-04_18:22:43/10802

#10 Updated by Sage Weil over 11 years ago

Priority changed from Urgent to High

#11 Updated by Anonymous over 11 years ago

RATIONALE:
We seem to be able to make this happen, and believe it to be a btrfs bug.
We are not calling it urgent because it is only a warning, but suspect
that it is resulting in lost I-nodes ... so it really ought to be found
and fixed.

#12 Updated by Sage Weil over 11 years ago

I'm pretty sure this was triggered by #2046. There is still a btrfs bug, but we were doing the wrong thing if rmdir was racing with a snapshot, so now that #2046 is fixed I don't think we'll see this anymore.

If it doesn't pop up in the next day or two of qa, I'll drop the priority here.

My feeble attempts at making a reproducer haven't been successful. :(

#13 Updated by Sage Weil over 11 years ago

Subject changed from filestore: error code on snap create to btrfs: EINVAL on snap create
Assignee deleted (~~Sage Weil~~)
Priority changed from High to Normal

We aren't triggering this any more, now that the filestore transaction bug is fixed.

#14 Updated by Sage Weil over 11 years ago

quick brain dump:

- last time this reproduced i narrowed it down to a case where there were racing rmdirs with the async snap ioctl. the osd was removing a collection and removing the dir.
- i did some basic testing with rmdirs in a loop and taking async snap ioctls (using the tool in ceph.git/qa/btrfs/) but didn't trigger it. i may have been doing something wrong, or it may take something in addition to rmdir to trigger the race/bug in btrfs.
- ceph.git/src/test/store_test.cc should be pretty easily modified to generate similar transactions to generate this, if the fixes for #2046 are reverted. those commits are 1009d1a016f049e19ad729a0c00a354a3956caf7 and 93d7ef96316f30d3d7caefe07a5a747ce883ca2d.

#15 Updated by Sage Weil over 11 years ago

somehow we end up here in btrfs:

        /* if we have links, this was a truncate, lets do that */
        if (inode->i_nlink) {
            if (!S_ISREG(inode->i_mode)) {
                WARN_ON(1);
                printk("weird orphan %p %lld uid/gid %d.%d mode 0%o size %lld",
                       inode, (unsigned long long)inode->i_ino,
                       inode->i_uid, inode->i_gid, inode->i_mode, inode->i_size);
                iput(inode);
                continue;
            }
            nr_truncate++;
            ret = btrfs_truncate(inode);

where the directory inode should have i_nlink == 0, but for some reason it is still 1.

there are various patches in the ceph-client.git testing branch that add printks trying to track this down. they may be helpful.

#16 Updated by Sage Weil over 11 years ago

the EINVAL seems to have come from

    ret = btrfs_orphan_cleanup(pending_snapshot->snap);
    if (ret)
        goto fail;

in create_snapshot() in ioctl.c.

#17 Updated by Sage Weil over 11 years ago

Assignee set to Joao Eduardo Luis

#18 Updated by Sage Weil over 11 years ago

see also this thread: http://marc.info/?t=132768583600004&r=1&w=2

#19 Updated by Sage Weil about 11 years ago

Status changed from Need More Info to Won't Fix

Also available in: Atom PDF

Project

General

Profile

Ceph

Issues

Tags

Custom queries