3.0-rcX BUG at fs/btrfs/ioctl.c:432 - bisected

Hi,

I've run into the following BUG on 3.0-rcX kernels when running mkcephfs:

Jun  9 15:14:50 an1 [  299.446615] ------------[ cut here ]------------
Jun  9 15:14:50 an1 [  299.447357] kernel BUG at fs/btrfs/ioctl.c:432!

Jun  9 15:14:50 an1 [  299.447357] RSP: 0018:ffff88021b163c48  EFLAGS: 00010206
Jun  9 15:14:50 an1 [  299.447357] RAX: 0000000019b201a0 RBX: ffff88022402d800 RCX: ffff88019206c028

Please let me know what other information I can provide, or any testing I can do, that will help to resolve this issue.

Hi,

a candidate fix:

http://git.kernel.org/?p=linux/kernel/git/mason/btrfs-unstable.git;a=commit;h=aa0467d8d2a00e75b2bb6a56a4ee6d70c5d1928f

"
With Linus' tree, today's linux-next build (powercp ppc64_defconfig) produced this warning:

fs/btrfs/delayed-inode.c: In function 'btrfs_delayed_update_inode':
fs/btrfs/delayed-inode.c:1598:6: warning: 'ret' may be used uninitialized in this function
Introduced by commit 16cdcec736cd ("btrfs: implement delayed inode items operation").

This fixes a bug in btrfs_update_inode(): if the returned value from btrfs_delayed_update_inode is a nonzero garbage, inode stat data are not updated and several call paths may hit a BUG_ON or fail with strange code.
"

if you can reproduce it reliably, add this patch on top of the delayed inodes.

Quoted 7 lines

Hi,

I've run into the following BUG on 3.0-rcX kernels when running mkcephfs:

Jun  9 15:14:50 an1 [  299.446615] ------------[ cut here ]------------
Jun  9 15:14:50 an1 [  299.447357] kernel BUG at fs/btrfs/ioctl.c:432!

ioctl.c:
431 ret = btrfs_update_inode(trans, root, dir);
432 BUG_ON(ret);

Quoted 2 lines

Jun  9 15:14:50 an1 [  299.447357] RSP: 0018:ffff88021b163c48  EFLAGS: 00010206
Jun  9 15:14:50 an1 [  299.447357] RAX: 0000000019b201a0 RBX: ffff88022402d800 RCX: ffff88019206c028

                                          ^^^^^^^^^^^^^^^^

ret, which seems to contain value of delayed_node from previous return value (deduced from assembly):

delayed-node.c:
1600 delayed_node = btrfs_get_or_create_delayed_node(inode);
1601 if (IS_ERR(delayed_node))
1602 return PTR_ERR(delayed_node);

Quoted 2 lines

Please let me know what other information I can provide, or any testing I can do, that will help to resolve this issue.

thanks, I think the stacktrace contains everything important. I was trying to trigger the bugon myself when the report arrived, but did not succeed. the issue is quite recent and seeing this report was a "cache" hit :)

Note: there are two more possibilities to hit the bugon in the ioctl: ENOMEM and ENOENT being retunred from btrfs_update_inode, but the symptoms fit the case described above.

david

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

[  276.365127] PGD 1e4469067 PUD 1e1658067 PMD 0
[  276.365127] Oops: 0000 [#1] SMP
[  276.365127] CPU 2
[  276.365127] Modules linked in: btrfs zlib_deflate lzo_compress ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge stp i2c_dev i2c_core ext3 jbd scsi_transport_iscsi rds ib_ipoib rdma_ucm rdma_cm ib_ucm ib_uverbs ib_umad ib_cm iw_cm ib_addr ipv6 ib_sa dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod video sbs sbshc pci_slot battery acpi_pad ac kvm sg ses sd_mod enclosure megaraid_sas ide_cd_mod cdrom ib_mthca ib_mad qla2xxx button ib_core serio_raw scsi_transport_fc scsi_tgt dcdbas ata_piix libata tpm_tis tpm i5k_amb ioatdma tpm_bios hwmon iTCO_wdt scsi_mod i5000_edac iTCO_vendor_support ehci_hcd dca edac_core uhci_hcd pcspkr rtc nfs nfs_acl auth_rpcgss fscache lockd sunrpc tg

[  276.365127]
[  276.365127] Pid: 6076, comm: cosd Not tainted 3.0.0-rc2-00196-g06e8684 #26 Dell Inc. PowerEdge 1950/0DT097
[  276.365127] RIP: 0010:[<ffffffffa05434b1>]  [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]
[  276.365127] RSP: 0018:ffff8801e2897b28  EFLAGS: 00010286
[  276.365127] RAX: 000000000000000a RBX: ffff8801de8e1090 RCX: 0000000000000002
[  276.365127] RDX: 0000000019b2d000 RSI: 000000000000000e RDI: 000000000000000e
[  276.365127] RBP: ffff8801e2897b48 R08: 0000000000000003 R09: ffff8801e2897c38
[  276.365127] R10: ffff8801e2897ed8 R11: 0000000000000001 R12: ffff880223ff4400
[  276.365127] R13: ffff880218522d60 R14: 0000000000000ec6 R15: ffff88021f54d878
[  276.365127] FS:  00007f8ff0bbb710(0000) GS:ffff88022fc80000(0000) knlGS:0000000000000000
[  276.365127] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  276.365127] CR2: 000000000000000a CR3: 000000021744f000 CR4: 00000000000006e0
[  276.365127] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  276.365127] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  276.365127] Process cosd (pid: 6076, threadinfo ffff8801e2896000, task ffff880218522d60)
[  276.365127] Stack:
[  276.365127]  ffff8801e2897b68 ffffea000756e788 ffff88021f54d728 ffff8801e2897c78
[  276.365127]  ffff8801e2897b58 ffffffffa05670ce ffff8801e2897b68 ffffffffa055c72d
[  276.365127]  ffff8801e2897be8 ffffffffa055f044 ffff8801e2897c38 0000007400000000
[  276.365127] Call Trace:
[  276.365127]  [<ffffffffa05670ce>] ext3_journal_start_sb+0x4f/0x51 [ext3]
[  276.365127]  [<ffffffffa055c72d>] ext3_journal_start+0x12/0x14 [ext3]
[  276.365127]  [<ffffffffa055f044>] ext3_write_begin+0x93/0x1a1 [ext3]
[  276.365127]  [<ffffffff810c6f0e>] ? __kunmap_atomic+0xe/0x10
[  276.365127]  [<ffffffff810c75e5>] generic_perform_write+0xb1/0x172
[  276.365127]  [<ffffffff81036a33>] ? need_resched+0x23/0x2d
[  276.365127]  [<ffffffff810c76ea>] generic_file_buffered_write+0x44/0x6f
[  276.365127]  [<ffffffff810c91f5>] __generic_file_aio_write+0x253/0x2a8
[  276.365127]  [<ffffffff810c92ad>] generic_file_aio_write+0x63/0xb8
[  276.365127]  [<ffffffff81113b26>] do_sync_write+0xc7/0x10b
[  276.365127]  [<ffffffff81036a4b>] ? should_resched+0xe/0x2f
[  276.365127]  [<ffffffff813b0faf>] ? _cond_resched+0xe/0x22
[  276.365127]  [<ffffffff811986c3>] ? security_file_permission+0x2c/0x31
[  276.365127]  [<ffffffff81113d21>] ? rw_verify_area+0xac/0xdb
[  276.365127]  [<ffffffff81114253>] vfs_write+0xac/0xe4
[  276.365127]  [<ffffffff8111434f>] sys_write+0x4c/0x71
[  276.365127]  [<ffffffff813b8beb>] system_call_fastpath+0x16/0x1b
[  276.365127] Code: 89 fc 48 c7 c3 e2 ff ff ff 89 f7 65 4c 8b 2c 25 c0 b5 00 00 4d 85 e4 49 8b 85 48 06 00 00 74 5e 48 85 c0 74 14 48 89 c3 48 8b 00 <4c> 39 20 74 04 0f 0b eb fe ff 43 0c eb 45 e8 70 ff ff ff 48 85
[  276.365127] RIP  [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]
[  276.365127]  RSP <ffff8801e2897b28>
[  276.365127] CR2: 000000000000000a
[  276.725157] ---[ end trace 8a802dc03e3972ad ]---

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

[ rest of the oops below for context ]

-chris

Quoted 4 lines

[  276.365127] PGD 1e4469067 PUD 1e1658067 PMD 0
[  276.365127] Oops: 0000 [#1] SMP
[  276.365127] CPU 2
[  276.365127] Modules linked in: btrfs zlib_deflate lzo_compress ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge stp i2c_dev i2c_core ext3 jbd scsi_transport_iscsi rds ib_ipoib rdma_ucm rdma_cm ib_ucm ib_uverbs ib_umad ib_cm iw_cm ib_addr ipv6 ib_sa dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod video sbs sbshc pci_slot battery acpi_pad ac kvm sg ses sd_mod enclosure megaraid_sas ide_cd_mod cdrom ib_mthca ib_mad qla2xxx button ib_core serio_raw scsi_transport_fc scsi_tgt dcdbas ata_piix libata tpm_tis tpm i5k_amb ioatdma tpm_bios hwmon iTCO_wdt scsi_mod i5000_edac iTCO_vendor_support ehci_hcd dca edac_core uhci_hcd pcspkr rtc nfs nfs_acl auth_rpcgss fscache lockd sunrpc 

Quoted 34 lines

[  276.365127]
[  276.365127] Pid: 6076, comm: cosd Not tainted 3.0.0-rc2-00196-g06e8684 #26 Dell Inc. PowerEdge 1950/0DT097
[  276.365127] RIP: 0010:[<ffffffffa05434b1>]  [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]
[  276.365127] RSP: 0018:ffff8801e2897b28  EFLAGS: 00010286
[  276.365127] RAX: 000000000000000a RBX: ffff8801de8e1090 RCX: 0000000000000002
[  276.365127] RDX: 0000000019b2d000 RSI: 000000000000000e RDI: 000000000000000e
[  276.365127] RBP: ffff8801e2897b48 R08: 0000000000000003 R09: ffff8801e2897c38
[  276.365127] R10: ffff8801e2897ed8 R11: 0000000000000001 R12: ffff880223ff4400
[  276.365127] R13: ffff880218522d60 R14: 0000000000000ec6 R15: ffff88021f54d878
[  276.365127] FS:  00007f8ff0bbb710(0000) GS:ffff88022fc80000(0000) knlGS:0000000000000000
[  276.365127] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  276.365127] CR2: 000000000000000a CR3: 000000021744f000 CR4: 00000000000006e0
[  276.365127] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  276.365127] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  276.365127] Process cosd (pid: 6076, threadinfo ffff8801e2896000, task ffff880218522d60)
[  276.365127] Stack:
[  276.365127]  ffff8801e2897b68 ffffea000756e788 ffff88021f54d728 ffff8801e2897c78
[  276.365127]  ffff8801e2897b58 ffffffffa05670ce ffff8801e2897b68 ffffffffa055c72d
[  276.365127]  ffff8801e2897be8 ffffffffa055f044 ffff8801e2897c38 0000007400000000
[  276.365127] Call Trace:
[  276.365127]  [<ffffffffa05670ce>] ext3_journal_start_sb+0x4f/0x51 [ext3]
[  276.365127]  [<ffffffffa055c72d>] ext3_journal_start+0x12/0x14 [ext3]
[  276.365127]  [<ffffffffa055f044>] ext3_write_begin+0x93/0x1a1 [ext3]
[  276.365127]  [<ffffffff810c6f0e>] ? __kunmap_atomic+0xe/0x10
[  276.365127]  [<ffffffff810c75e5>] generic_perform_write+0xb1/0x172
[  276.365127]  [<ffffffff81036a33>] ? need_resched+0x23/0x2d
[  276.365127]  [<ffffffff810c76ea>] generic_file_buffered_write+0x44/0x6f
[  276.365127]  [<ffffffff810c91f5>] __generic_file_aio_write+0x253/0x2a8
[  276.365127]  [<ffffffff810c92ad>] generic_file_aio_write+0x63/0xb8
[  276.365127]  [<ffffffff81113b26>] do_sync_write+0xc7/0x10b
[  276.365127]  [<ffffffff81036a4b>] ? should_resched+0xe/0x2f
[  276.365127]  [<ffffffff813b0faf>] ? _cond_resched+0xe/0x22
[  276.365127]  [<ffffffff811986c3>] ? security_file_permission+0x2c/0x31
[  276.365127]  [<ffffffff81113d21>] ? rw_verify_area+0xac/0xdb

Quoted 9 lines

[  276.365127]  [<ffffffff81114253>] vfs_write+0xac/0xe4
[  276.365127]  [<ffffffff8111434f>] sys_write+0x4c/0x71
[  276.365127]  [<ffffffff813b8beb>] system_call_fastpath+0x16/0x1b
[  276.365127] Code: 89 fc 48 c7 c3 e2 ff ff ff 89 f7 65 4c 8b 2c 25 c0 b5 00 00 4d 85 e4 49 8b 85 48 06 00 00 74 5e 48 85 c0 74 14 48 89 c3 48 8b 00 <4c> 39 20 74 04 0f 0b eb fe ff 43 0c eb 45 e8 70 ff ff ff 48 85
[  276.365127] RIP  [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]
[  276.365127]  RSP <ffff8801e2897b28>
[  276.365127] CR2: 000000000000000a
[  276.725157] ---[ end trace 8a802dc03e3972ad ]---

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 21 lines · Chris Mason

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

Quoted 8 lines

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

Ah, yeah, that's the problem. We saw a similar problem a while back with the start/stop transaction ioctls. In this case, create_snapshot is doing

	trans = btrfs_start_transaction(root->fs_info->extent_root, 5);
	if (IS_ERR(trans)) {
		ret = PTR_ERR(trans);
		goto fail;
	}

which sets current->journal_info. Then

	ret = btrfs_snap_reserve_metadata(trans, pending_snapshot);
	BUG_ON(ret);

	list_add(&pending_snapshot->list,
		 &trans->transaction->pending_snapshots);
	if (async_transid) {
		*async_transid = trans->transid;
		ret = btrfs_commit_transaction_async(trans,
				     root->fs_info->extent_root, 1);
	} else {
		ret = btrfs_commit_transaction(trans,
				       root->fs_info->extent_root);
	}

but the async snap creation ioctl takes the async path, which runs btrfs_commit_transaction in a worker thread.

I'm not sure what the right thing to do is here is... can whatever is in journal_info be attached to trans instead in btrfs_commit_transaction_async()?

Quoted 59 lines · Sage Weil

Quoted 21 lines · Chris Mason

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

Quoted 8 lines

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

Ah, yeah, that's the problem. We saw a similar problem a while back with the start/stop transaction ioctls. In this case, create_snapshot is doing

	trans = btrfs_start_transaction(root->fs_info->extent_root, 5);
	if (IS_ERR(trans)) {
		ret = PTR_ERR(trans);
		goto fail;
	}

which sets current->journal_info. Then

	ret = btrfs_snap_reserve_metadata(trans, pending_snapshot);
	BUG_ON(ret);

	list_add(&pending_snapshot->list,
		 &trans->transaction->pending_snapshots);
	if (async_transid) {
		*async_transid = trans->transid;
		ret = btrfs_commit_transaction_async(trans,
				     root->fs_info->extent_root, 1);
	} else {
		ret = btrfs_commit_transaction(trans,
				       root->fs_info->extent_root);
	}

but the async snap creation ioctl takes the async path, which runs btrfs_commit_transaction in a worker thread.

Quoted 3 lines

I'm not sure what the right thing to do is here is... can whatever is in journal_info be attached to trans instead in btrfs_commit_transaction_async()?

It looks like it's not used for anything in btrfs, actually; it's just set and cleared. What's the point of that?

Quoted 64 lines · Sage Weil

Quoted 62 lines · Sage Weil

Quoted 21 lines · Chris Mason

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

Quoted 8 lines

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

Ah, yeah, that's the problem. We saw a similar problem a while back with the start/stop transaction ioctls. In this case, create_snapshot is doing

	trans = btrfs_start_transaction(root->fs_info->extent_root, 5);
	if (IS_ERR(trans)) {
		ret = PTR_ERR(trans);
		goto fail;
	}

which sets current->journal_info. Then

	ret = btrfs_snap_reserve_metadata(trans, pending_snapshot);
	BUG_ON(ret);

	list_add(&pending_snapshot->list,
		 &trans->transaction->pending_snapshots);
	if (async_transid) {
		*async_transid = trans->transid;
		ret = btrfs_commit_transaction_async(trans,
				     root->fs_info->extent_root, 1);
	} else {
		ret = btrfs_commit_transaction(trans,
				       root->fs_info->extent_root);
	}

but the async snap creation ioctl takes the async path, which runs btrfs_commit_transaction in a worker thread.

I'm not sure what the right thing to do is here is... can whatever is in journal_info be attached to trans instead in btrfs_commit_transaction_async()?

Quoted 3 lines

It looks like it's not used for anything in btrfs, actually; it's just set and cleared. What's the point of that?

It is used now, check the beginning of start_transaction(). Thanks,

Quoted 69 lines · Josef Bacik

Quoted 67 lines · Sage Weil

Quoted 56 lines · Sage Weil

Quoted 21 lines · Chris Mason

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

Quoted 8 lines

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

Ah, yeah, that's the problem. We saw a similar problem a while back with the start/stop transaction ioctls. In this case, create_snapshot is doing

	trans = btrfs_start_transaction(root->fs_info->extent_root, 5);
	if (IS_ERR(trans)) {
		ret = PTR_ERR(trans);
		goto fail;
	}

which sets current->journal_info. Then

	ret = btrfs_snap_reserve_metadata(trans, pending_snapshot);
	BUG_ON(ret);

	list_add(&pending_snapshot->list,
		 &trans->transaction->pending_snapshots);
	if (async_transid) {
		*async_transid = trans->transid;
		ret = btrfs_commit_transaction_async(trans,
				     root->fs_info->extent_root, 1);
	} else {
		ret = btrfs_commit_transaction(trans,
				       root->fs_info->extent_root);
	}

Quoted 6 lines

but the async snap creation ioctl takes the async path, which runs btrfs_commit_transaction in a worker thread.

I'm not sure what the right thing to do is here is... can whatever is in journal_info be attached to trans instead in btrfs_commit_transaction_async()?

It looks like it's not used for anything in btrfs, actually; it's just set and cleared. What's the point of that?

Quoted 1 line

It is used now, check the beginning of start_transaction(). Thanks,

Oh I see, okay.

So clearing it in btrfs_commit_transaction_async should be fine then, right? When btrfs_commit_transaction runs in the other thread it won't care that current->journal_info is NULL.

Quoted 72 lines · Sage Weil

Quoted 70 lines · Josef Bacik

Quoted 60 lines · Sage Weil

Quoted 59 lines · Sage Weil

Quoted 21 lines · Chris Mason

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

Quoted 8 lines

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

Ah, yeah, that's the problem. We saw a similar problem a while back with the start/stop transaction ioctls. In this case, create_snapshot is doing

	trans = btrfs_start_transaction(root->fs_info->extent_root, 5);
	if (IS_ERR(trans)) {
		ret = PTR_ERR(trans);
		goto fail;
	}

which sets current->journal_info. Then

	ret = btrfs_snap_reserve_metadata(trans, pending_snapshot);
	BUG_ON(ret);

	list_add(&pending_snapshot->list,
		 &trans->transaction->pending_snapshots);
	if (async_transid) {
		*async_transid = trans->transid;
		ret = btrfs_commit_transaction_async(trans,
				     root->fs_info->extent_root, 1);
	} else {
		ret = btrfs_commit_transaction(trans,
				       root->fs_info->extent_root);
	}

but the async snap creation ioctl takes the async path, which runs btrfs_commit_transaction in a worker thread.

Quoted 7 lines

Quoted 3 lines

I'm not sure what the right thing to do is here is... can whatever is in journal_info be attached to trans instead in btrfs_commit_transaction_async()?

It looks like it's not used for anything in btrfs, actually; it's just set and cleared. What's the point of that?

It is used now, check the beginning of start_transaction(). Thanks,

Quoted 6 lines

Oh I see, okay.

So clearing it in btrfs_commit_transaction_async should be fine then, right? When btrfs_commit_transaction runs in the other thread it won't care that current->journal_info is NULL.

Oh yeah your patch is good :),

From 9881c0752293769d5133c01dff3ab04c0c24c61b Mon Sep 17 00:00:00 2001

Quoted 62 lines · Josef Bacik

Quoted 61 lines · Sage Weil

Quoted 60 lines · Josef Bacik

Quoted 59 lines · Sage Weil

Quoted 53 lines · Sage Weil

Quoted 20 lines · Chris Mason

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

Quoted 8 lines

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

Ah, yeah, that's the problem. We saw a similar problem a while back with the start/stop transaction ioctls. In this case, create_snapshot is doing

	trans = btrfs_start_transaction(root->fs_info->extent_root, 5);
	if (IS_ERR(trans)) {
		ret = PTR_ERR(trans);
		goto fail;
	}

which sets current->journal_info. Then

	ret = btrfs_snap_reserve_metadata(trans, pending_snapshot);
	BUG_ON(ret);

	list_add(&pending_snapshot->list,
		 &trans->transaction->pending_snapshots);
	if (async_transid) {
		*async_transid = trans->transid;
		ret = btrfs_commit_transaction_async(trans,
				     root->fs_info->extent_root, 1);
	} else {
		ret = btrfs_commit_transaction(trans,
				       root->fs_info->extent_root);
	}

Quoted 3 lines

but the async snap creation ioctl takes the async path, which runs btrfs_commit_transaction in a worker thread.

I'm not sure what the right thing to do is here is... can whatever is in journal_info be attached to trans instead in btrfs_commit_transaction_async()?

It looks like it's not used for anything in btrfs, actually; it's just set and cleared. What's the point of that?

Quoted 6 lines

Quoted 5 lines

Quoted 1 line

It is used now, check the beginning of start_transaction(). Thanks,

Oh I see, okay.

So clearing it in btrfs_commit_transaction_async should be fine then, right? When btrfs_commit_transaction runs in the other thread it won't care that current->journal_info is NULL.

Oh yeah your patch is good :),

Okay cool. Here's the fix with a proper changelog and a little use-after-free paranoia.

Thanks!
sage

Quoted 1 line

From 9881c0752293769d5133c01dff3ab04c0c24c61b Mon Sep 17 00:00:00 2001

From: Sage Weil <[email protected]>
Date: Fri, 10 Jun 2011 11:41:25 -0700
Subject: [PATCH] Btrfs: clear current->journal_info on async transaction commit

Normally current->jouranl_info is cleared by commit_transaction. For an async snap or subvol creation, though, it runs in a work queue. Clear it in btrfs_commit_transaction_async() to avoid leaking a non-NULL journal_info when we return to userspace. When the actual commit runs in the other thread it won't care that it's current->journal_info is already NULL.

Signed-off-by Sage Weil <[email protected]>

---
 fs/btrfs/transaction.c |    5 ++++-
 1 files changed, 4 insertions(+), 1 deletions(-)

fs/btrfs/transaction.c +4 -1

index dd71966..9d516ed 100644
@@ -1118,8 +1118,11 @@ int btrfs_commit_transaction_async(struct btrfs_trans_handle *trans,
 		wait_current_trans_commit_start_and_unblock(root, cur_trans);
 	else
 		wait_current_trans_commit_start(root, cur_trans);
-	put_transaction(cur_trans);
 
+	if (current->journal_info == trans)
+		current->journal_info = NULL;
+
+	put_transaction(cur_trans);
 	return 0;
 }
 

Quoted 72 lines · Josef Bacik

Quoted 70 lines · Sage Weil

Quoted 60 lines · Sage Weil

Quoted 59 lines · Chris Mason

Quoted 21 lines

Excerpts from Jim Schutt's message of 2011-06-10 13:06:22 -0400:

[ two different btrfs crashes ]

I think your two crashes in btrfs were from the uninit variables and those should be fixed in rc2.

Quoted 8 lines

When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs:

[  276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a
[  276.365127] IP: [<ffffffffa05434b1>] journal_start+0x3e/0x9c [jbd]

Looking at the resulting code in the oops, we're here in journal_start:

        if (handle) {
                J_ASSERT(handle->h_transaction->t_journal == journal);

Quoted 8 lines

handle comes from current->journal_info, and we're doing a deref on handle->h_transaction, which is probably 0xa.

So, we're leaving crud in current->journal_info and ext3 is finding it.

Perhaps its from ceph starting a transaction but leaving it running? The bug came with Josef's transaction performance fixes, but it is probably a mixture of his code with the ioctls ceph is using.

Ah, yeah, that's the problem. We saw a similar problem a while back with the start/stop transaction ioctls. In this case, create_snapshot is doing

    trans = btrfs_start_transaction(root->fs_info->extent_root, 5);
    if (IS_ERR(trans)) {
        ret = PTR_ERR(trans);
        goto fail;
    }

which sets current->journal_info. Then

    ret = btrfs_snap_reserve_metadata(trans, pending_snapshot);
    BUG_ON(ret);

    list_add(&pending_snapshot->list,
         &trans->transaction->pending_snapshots);
    if (async_transid) {
        *async_transid = trans->transid;
        ret = btrfs_commit_transaction_async(trans,
                     root->fs_info->extent_root, 1);
    } else {
        ret = btrfs_commit_transaction(trans,
                       root->fs_info->extent_root);
    }

but the async snap creation ioctl takes the async path, which runs btrfs_commit_transaction in a worker thread.

Quoted 7 lines

Quoted 3 lines

I'm not sure what the right thing to do is here is... can whatever is in journal_info be attached to trans instead in btrfs_commit_transaction_async()?

It looks like it's not used for anything in btrfs, actually; it's just set and cleared. What's the point of that?

It is used now, check the beginning of start_transaction(). Thanks,

Quoted 6 lines

Oh I see, okay.

So clearing it in btrfs_commit_transaction_async should be fine then, right? When btrfs_commit_transaction runs in the other thread it won't care that current->journal_info is NULL.

Oh yeah your patch is good :),

Jun  9 15:14:50 an1 [  299.446615] ------------[ cut here ]------------
Jun  9 15:14:50 an1 [  299.447357] kernel BUG at fs/btrfs/ioctl.c:432!
Jun  9 15:14:50 an1 [  299.447357] invalid opcode: 0000 [#1] SMP
Jun  9 15:14:50 an1 [  299.447357] last sysfs file: /sys/devices/system/cpu/cpu3/cache/index2/shared_cpu_map
Jun  9 15:14:50 an1 [  299.447357] CPU 2
Jun  9 15:14:50 an1 [  299.447357] Modules linked in: btrfs zlib_deflate lzo_compress ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge stp i2c_dev i2c_core ext3 jbd scsi_transport_iscsi rds ib_ipoib rdma_ucm rdma_cm ib_ucm ib_uverbs ib_umad ib_cm iw_cm ib_addr ipv6 ib_sa dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod video sbs sbshc pci_slot battery acpi_pad ac kvm sg ses sd_mod enclosure ide_cd_mod cdrom megaraid_sas qla2xxx ib_mthca scsi_transport_fc scsi_tgt ib_mad ib_core button serio_raw ata_piix libata scsi_mod tpm_tis tpm dcdbas tpm_bios iTCO_wdt ioatdma iTCO_vendor_support ehci_hcd i5k_amb dca uhci_hcd hwmon i5000_edac edac_core pcspkr rtc nfs nfs_acl auth_rpcgss fsc

Jun  9 15:14:50 an1 [  299.447357]
Jun  9 15:14:50 an1 [  299.447357] Pid: 6047, comm: cosd Not tainted 2.6.39-00001-g16cdcec #24 Dell Inc. PowerEdge 1950/0DT097
Jun  9 15:14:50 an1 [  299.447357] RIP: 0010:[<ffffffffa0709b96>]  [<ffffffffa0709b96>] create_subvol+0x36a/0x440 [btrfs]
Jun  9 15:14:50 an1 [  299.447357] RSP: 0018:ffff88021b163c48  EFLAGS: 00010206
Jun  9 15:14:50 an1 [  299.447357] RAX: 0000000019b201a0 RBX: ffff88022402d800 RCX: ffff88019206c028
Jun  9 15:14:50 an1 [  299.447357] RDX: ffff88021884f618 RSI: 00000000fffffff4 RDI: ffff88019206c048
Jun  9 15:14:50 an1 [  299.447357] RBP: ffff88021b163de8 R08: ffff88021b163bb8 R09: ffff88019206c048
Jun  9 15:14:50 an1 [  299.447357] R10: ffffffffa06c7ed7 R11: ffff88021b163bb8 R12: ffff88021b163d88
Jun  9 15:14:50 an1 [  299.447357] R13: 0000000000000000 R14: ffff880222fac000 R15: ffff8801e8b6e280
Jun  9 15:14:50 an1 [  299.447357] FS:  00007fa5aa04d710(0000) GS:ffff88022fc80000(0000) knlGS:0000000000000000
Jun  9 15:14:50 an1 [  299.447357] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun  9 15:14:50 an1 [  299.447357] CR2: 0000000001d45000 CR3: 000000021bd42000 CR4: 00000000000006e0
Jun  9 15:14:50 an1 [  299.447357] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jun  9 15:14:50 an1 [  299.447357] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Jun  9 15:14:50 an1 [  299.447357] Process cosd (pid: 6047, threadinfo ffff88021b162000, task ffff8801dee243e0)
Jun  9 15:14:50 an1 [  299.447357] Stack:
Jun  9 15:14:50 an1 [  299.447357]  ffff880200000002 0000000000000003 0000000000000000 ffff8801e8b6d000
Jun  9 15:14:50 an1 [  299.447357]  0000000000000000 000000071b163c80 ffff8801d6af9008 ffff880192075000
Jun  9 15:14:50 an1 [  299.447357]  ffff8801e898eb40 ffff880219b201a0 0000000000000001 0000000000000000
Jun  9 15:14:50 an1 [  299.447357] Call Trace:
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffff810362ec>] ? need_resched+0x23/0x2d
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffffa0709d7a>] btrfs_mksubvol+0x10e/0x167 [btrfs]
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffffa070a29f>] btrfs_ioctl_snap_create_transid+0x9c/0x121 [btrfs]
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffffa070a45e>] btrfs_ioctl_snap_create+0x50/0x67 [btrfs]
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffffa070bc5a>] btrfs_ioctl+0x1d0/0x2c6 [btrfs]
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffff8111fe12>] vfs_ioctl+0x1d/0x34
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffff8112048d>] do_vfs_ioctl+0x171/0x17a
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffff811130a2>] ? fget_light+0x69/0x81
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffff811204f2>] sys_ioctl+0x5c/0x7c
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffff8111d48d>] ? putname+0x33/0x37
Jun  9 15:14:50 an1 [  299.447357]  [<ffffffff813b21eb>] system_call_fastpath+0x16/0x1b
Jun  9 f6 4c 89 ff 01 c0 48 98 48 03 82 c8 00 00 00 48 89 82 c8 00 00 00 48 89 42 c0 48 8b 95 a8 fe ff ff e8 5e d5 fd ff 85 c0 74 04 <0f> 0b eb fe 48 8b 85 a8 fe ff ff 49 8b 8e 17 01 00 00 4c 89 ff
Jun  9 15:14:50 an1 [  299.447357] RIP  [<ffffffffa0709b96>] create_subvol+0x36a/0x440 [btrfs]
Jun  9 15:14:50 an1 [  299.447357]  RSP <ffff88021b163c48>
Jun  9 15:14:50 an1 [  299.767860] ---[ end trace 10d1f43d69984a37 ]---
Jun  9 15:15:23 an1 [  333.037241] ------------[ cut here ]------------

It bisects to the following commit:

16cdcec736cd214350cdb591bf1091f8beedefa0 is the first bad commit commit 16cdcec736cd214350cdb591bf1091f8beedefa0

Author: Miao Xie <[email protected]>
Date:   Fri Apr 22 18:12:22 2011 +0800

btrfs: implement delayed inode items operation

Please let me know what other information I can provide, or any testing I can do, that will help to resolve this issue.

Thanks -- Jim