Bug #1975
closedbtrfs: EINVAL on snap create
Added by Sage Weil over 12 years ago. Updated over 11 years ago.
0%
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.
Updated by Sage Weil over 12 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
Updated by Samuel Just over 12 years ago
wip-filestore-errors looks good to me except for one comment on github.
Updated by Sage Weil over 12 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>
}
Updated by Sage Weil over 12 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)
Updated by Sage Weil over 12 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
Updated by Sage Weil over 12 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
Updated by Sage Weil about 12 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
Updated by Anonymous about 12 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.
Updated by Sage Weil about 12 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. :(
Updated by Sage Weil about 12 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.
Updated by Sage Weil about 12 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.
Updated by Sage Weil about 12 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.
Updated by Sage Weil about 12 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.
Updated by Sage Weil about 12 years ago
see also this thread: http://marc.info/?t=132768583600004&r=1&w=2
Updated by Sage Weil over 11 years ago
- Status changed from Need More Info to Won't Fix