While playing with the btrfs in the latest linus-git tree (2.6.32-rc5), I got many dump in dmesg, which I highlight a few here: ------------[ cut here ]------------ WARNING: at fs/btrfs/extent_io.c:3523 map_private_extent_buffer+0xc0/0x119() Hardware name: System Product Name Modules linked in: scsi_wait_scan Pid: 20157, comm: loop0 Tainted: G W 2.6.32-rc5 #3 Call Trace: [<ffffffff81404a89>] ? map_private_extent_buffer+0xc0/0x119 [<ffffffff81089c27>] warn_slowpath_common+0x8d/0xd0 [<ffffffff81089c91>] warn_slowpath_null+0x27/0x3d [<ffffffff81404a89>] map_private_extent_buffer+0xc0/0x119 [<ffffffff81089b44>] ? add_taint+0xe/0x64 [<ffffffff81404b62>] map_extent_buffer+0x80/0xd1 [<ffffffff813f9d82>] btrfs_key_blockptr+0x84/0xe8 [<ffffffff813cfdcd>] read_block_for_search+0x63/0x2de [<ffffffff813cfa56>] ? unlock_up+0x16/0x105 [<ffffffff813d51da>] btrfs_search_slot+0x3d7/0x50f [<ffffffff81404333>] ? unmap_extent_buffer+0xd/0x41 [<ffffffff81404de2>] ? free_extent_buffer+0xd/0x56 [<ffffffff813e2b3d>] btrfs_csum_file_blocks+0x247/0x6bc [<ffffffff81416500>] ? copy_items+0x239/0x346 [<ffffffff810cae23>] ? trace_hardirqs_on+0x20/0x36 [<ffffffff814165dc>] ? copy_items+0x315/0x346 [<ffffffff814165c4>] copy_items+0x2fd/0x346 [<ffffffff81417bad>] btrfs_log_inode+0x355/0x42e [<ffffffff810caaa5>] ? mark_held_locks+0x60/0x96 [<ffffffff810cadc2>] ? trace_hardirqs_on_caller+0x132/0x173 [<ffffffff810cae23>] ? trace_hardirqs_on+0x20/0x36 [<ffffffff8141802a>] btrfs_log_inode_parent+0x20d/0x2e2 [<ffffffff813ea9b4>] ? start_transaction+0x137/0x159 [<ffffffff814181b8>] btrfs_log_dentry_safe+0x2c/0x42 [<ffffffff813f5b31>] btrfs_sync_file+0x103/0x18f [<ffffffff811a15ba>] vfs_fsync_range+0x90/0xd1 [<ffffffff811a169f>] vfs_fsync+0x30/0x46 [<ffffffff8160c74f>] loop_thread+0x2ee/0x53f [<ffffffff8160bf6c>] ? do_lo_send_direct_write+0x0/0x8e [<ffffffff810b5234>] ? autoremove_wake_function+0x0/0x63 [<ffffffff8160c461>] ? loop_thread+0x0/0x53f [<ffffffff810b4dec>] kthread+0x9d/0xa5 [<ffffffff8103faba>] child_rip+0xa/0x20 [<ffffffff8103f47c>] ? restore_args+0x0/0x30 [<ffffffff810b4d4f>] ? kthread+0x0/0xa5 [<ffffffff8103fab0>] ? child_rip+0x0/0x20 ---[ end trace 8e7402ff37ff58a5 ]--- btrfs bad mapping eb start 56213504 len 4096, wanted 8871 8 ------------[ cut here ]------------ WARNING: at fs/btrfs/extent_io.c:3523 map_private_extent_buffer+0xc0/0x119() Hardware name: System Product Name Modules linked in: scsi_wait_scan Pid: 20157, comm: loop0 Tainted: G W 2.6.32-rc5 #3 Call Trace: [<ffffffff81404a89>] ? map_private_extent_buffer+0xc0/0x119 [<ffffffff81089c27>] warn_slowpath_common+0x8d/0xd0 [<ffffffff81089c91>] warn_slowpath_null+0x27/0x3d [<ffffffff81404a89>] map_private_extent_buffer+0xc0/0x119 [<ffffffff81089b44>] ? add_taint+0xe/0x64 [<ffffffff81404b62>] map_extent_buffer+0x80/0xd1 [<ffffffff813f9c9a>] btrfs_key_generation+0x84/0xe8 [<ffffffff813cfddf>] read_block_for_search+0x75/0x2de [<ffffffff813cfa56>] ? unlock_up+0x16/0x105 [<ffffffff813d51da>] btrfs_search_slot+0x3d7/0x50f [<ffffffff81404333>] ? unmap_extent_buffer+0xd/0x41 [<ffffffff81404de2>] ? free_extent_buffer+0xd/0x56 [<ffffffff813e2b3d>] btrfs_csum_file_blocks+0x247/0x6bc [<ffffffff81416500>] ? copy_items+0x239/0x346 [<ffffffff810cae23>] ? trace_hardirqs_on+0x20/0x36 [<ffffffff814165dc>] ? copy_items+0x315/0x346 [<ffffffff814165c4>] copy_items+0x2fd/0x346 [<ffffffff81417bad>] btrfs_log_inode+0x355/0x42e [<ffffffff810caaa5>] ? mark_held_locks+0x60/0x96 [<ffffffff810cadc2>] ? trace_hardirqs_on_caller+0x132/0x173 [<ffffffff810cae23>] ? trace_hardirqs_on+0x20/0x36 [<ffffffff8141802a>] btrfs_log_inode_parent+0x20d/0x2e2 [<ffffffff813ea9b4>] ? start_transaction+0x137/0x159 [<ffffffff814181b8>] btrfs_log_dentry_safe+0x2c/0x42 [<ffffffff813f5b31>] btrfs_sync_file+0x103/0x18f [<ffffffff811a15ba>] vfs_fsync_range+0x90/0xd1 [<ffffffff811a169f>] vfs_fsync+0x30/0x46 [<ffffffff8160c74f>] loop_thread+0x2ee/0x53f [<ffffffff8160bf6c>] ? do_lo_send_direct_write+0x0/0x8e [<ffffffff810b5234>] ? autoremove_wake_function+0x0/0x63 [<ffffffff8160c461>] ? loop_thread+0x0/0x53f [<ffffffff810b4dec>] kthread+0x9d/0xa5 [<ffffffff8103faba>] child_rip+0xa/0x20 [<ffffffff8103f47c>] ? restore_args+0x0/0x30 [<ffffffff810b4d4f>] ? kthread+0x0/0xa5 [<ffffffff8103fab0>] ? child_rip+0x0/0x20 ---[ end trace 8e7402ff37ff58a6 ]--- ------------[ cut here ]------------ kernel BUG at fs/btrfs/extent-tree.c:1229! invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC last sysfs file: /sys/devices/pci0000:00/0000:00:12.0/0000:04:0b.0/local_cpus CPU 1 Modules linked in: scsi_wait_scan Pid: 6818, comm: btrfs-transacti Tainted: G W 2.6.32-rc5 #3 System Product Name RIP: 0010:[<ffffffff813dbcb3>] [<ffffffff813dbcb3>] lookup_inline_extent_backref+0x143/0x447 RSP: 0018:ffff8800bb495a00 EFLAGS: 00010202 RAX: 0000000000000001 RBX: 0000000000000001 RCX: ffff8800bb4959bc RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000 RBP: ffff8800bb495ab0 R08: ffff8800bb4958c8 R09: ffff8800bb4958c0 R10: 0000000000000011 R11: 00000000438270d2 R12: ffff880026210088 R13: 0000000000000000 R14: 00000000fffffff4 R15: 0000000000000000 FS: 00007f9df3303950(0000) GS:ffff880008e00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b CR2: 00007f3c5fd16154 CR3: 00000000b6117000 CR4: 00000000000006a0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff4ff0 DR7: 0000000000000400 Process btrfs-transacti (pid: 6818, threadinfo ffff8800bb494000, task ffff8800b946d480) Stack: 00000000bb495a40 0000000000000000 0000000000000001 0000000000000005 <0> 0000000000000000 0000000003519000 ffff8800bb495b70 ffff88002620f000 <0> ffff8800b6f02090 0000000000000246 0000009000008050 000000b0ffffffff Call Trace: [<ffffffff813dcf4f>] __btrfs_free_extent+0x113/0x717 [<ffffffff810cd8d2>] ? lock_release_non_nested+0x1d4/0x24b [<ffffffff8141daf7>] ? btrfs_delayed_ref_lock+0x4f/0xbf [<ffffffff813dfb2b>] ? run_clustered_refs+0x27d/0x2fa [<ffffffff813dda34>] run_one_delayed_ref+0x4e1/0x511 [<ffffffff813dfb41>] run_clustered_refs+0x293/0x2fa [<ffffffff813dfc89>] btrfs_run_delayed_refs+0xe1/0x1bd [<ffffffff813eaf62>] btrfs_commit_transaction+0x316/0x607 [<ffffffff810b5234>] ? autoremove_wake_function+0x0/0x63 [<ffffffff813e61a2>] transaction_kthread+0x195/0x22a [<ffffffff813e600d>] ? transaction_kthread+0x0/0x22a [<ffffffff810b4dec>] kthread+0x9d/0xa5 [<ffffffff8103faba>] child_rip+0xa/0x20 [<ffffffff8103f47c>] ? restore_args+0x0/0x30 [<ffffffff810b4d4f>] ? kthread+0x0/0xa5 [<ffffffff8103fab0>] ? child_rip+0x0/0x20 Code: 45 a8 48 8b 4d 88 4c 89 e7 48 8b 75 90 c6 45 b8 a8 48 89 55 b0 48 8d 55 b0 e8 5d 91 ff ff 83 f8 00 89 c3 0f 8c b4 02 00 00 74 04 <0f> 0b eb fe 48 8b 4d 88 48 63 71 40 4c 8b 31 4c 89 f7 48 6b f6 RIP [<ffffffff813dbcb3>] lookup_inline_extent_backref+0x143/0x447 RSP <ffff8800bb495a00> ---[ end trace 8e7402ff37ff58a7 ]--- What I did is two thing: a. fdisk and allocate the entire partition and mkfs.btrfs, and then mount it. subsequently just cp, gzip, gunzip and ln on the files after mounting and copying to the partition. b. "dd" and mounted it via loopback - using losetup as explained in the wiki, and similarly cp, gzip, gunzip and ln on the files after mounting and copying to the partition. Now the symptoms is "blocking" - "sync", ls, cd, cp etc all is not possible to be accomplished on the mounted filesystem - ie, it will block at the command line. OS as a whole is still running fine, as I can still enter my bugzilla report right now.
Created attachment 23754 [details] .config used for compilation
Created attachment 23755 [details] gzip image of partial output of dmesg this is taken partially from /var/log/messages (which is much larger than this), as dmesg has already overwritten itself, and is only a sublist of the following attachment.
Thanks for this bug report. Could you please provide the steps to setup your config in script form? I'd like to make sure I understand exactly what commands you ran.
Extracting from my bash history, this is the approximate list of command issued: dd if=/dev/zero of=btrfs_disk.dat bs=1024 count=1024000 mkfs.btrfs btrfs_disk.dat file btrfs_disk.dat blkid btrfs_disk.dat df mkdir /mnt/btrfs mount btrfs_disk.dat /mnt/btrfs/ mount -t btrfs btrfs_disk.dat /mnt/btrfs/ mount -t btrfs btrfs_disk.dat /mnt/btrfs/ -o loop losetup /dev/loop0 btrfs_disk.dat mount /dev/loop0 /mnt/btrfs/ mount -t btrfs /dev/loop0 /mnt/btrfs (the error could arise from the 2nd last line - mounting an already mounted partition? crash console messages seemed to be generated before the last line, although it does execute, but after executing the entire system hanged - this is specific for v2.6.32-rc6-346-gaa021ba (linus-git-tree): git describe v2.6.32-rc6-346-gaa021ba CONFIG_BTRFS_FS=y CONFIG_BTRFS_FS_POSIX_ACL=y But now, after rebooting without btrfs partition mounted, I immediately do a mount and got the following errors at the mount command (mount -t btrfs /dev/sda7 /sda7, and only one single command was issued): kernel BUG at fs/btrfs/extent-tree.c:3541! invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC last sysfs file: /sys/devices/pci0000:00/0000:00:12.0/0000:04:0b.0/local_cpus CPU 0 Modules linked in: scsi_wait_scan Pid: 8282, comm: mount Not tainted 2.6.32-rc6-00346-gaa021ba #4 System Product Name RIP: 0010:[<ffffffff81349f3a>] [<ffffffff81349f3a>] btrfs_pin_extent+0x37/0xce RSP: 0018:ffff8800949579c8 EFLAGS: 00010246 RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff8800b9a7aa78 RDX: 0000000000840083 RSI: 0000000000000507 RDI: ffff8800847540a8 RBP: ffff8800949579f8 R08: ffff8800847540a8 R09: 0000000000000000 R10: ffff880094957918 R11: 0000000000000001 R12: 0000000000001000 R13: 01ffffffffffffff R14: fa00000000000000 R15: 0000000000000000 FS: 00007f44aa1a87d0(0000) GS:ffff880008c00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 00000000017db208 CR3: 00000000b840c000 CR4: 00000000000006b0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff4ff0 DR7: 0000000000000400 Process mount (pid: 8282, threadinfo ffff880094956000, task ffff8800b9a7aa40) Stack: ffff880084754000 ffff880080449290 ffff880094957b08 01ffffffffffffff <0> ffff8800893b80d8 ffff88008a3961b0 ffff880094957a28 ffffffff81380c2e <0> ffff8800893b80d8 ffff880080449290 ffff880094957acc 01ffffffffffffff Call Trace: [<ffffffff81380c2e>] process_one_buffer+0x3a/0x73 [<ffffffff8137e34d>] walk_down_log_tree+0x14c/0x3c3 [<ffffffff8137e646>] walk_log_tree+0x82/0x18c [<ffffffff8137f35a>] btrfs_recover_log_trees+0x178/0x27d [<ffffffff81380bf4>] ? process_one_buffer+0x0/0x73 [<ffffffff81354428>] ? btree_read_extent_buffer_pages+0x6f/0xac [<ffffffff81357ce3>] open_ctree+0x104f/0x12b2 [<ffffffff8140deb5>] ? vsnprintf+0x3fc/0x43b [<ffffffff81131cb6>] ? set_anon_super+0x0/0xec [<ffffffff81340460>] btrfs_get_sb+0x298/0x489 [<ffffffff81132bdd>] vfs_kern_mount+0xa2/0x15d [<ffffffff81132cff>] do_kern_mount+0x4c/0xec [<ffffffff8114bdfa>] do_mount+0x704/0x76a [<ffffffff81108b72>] ? strndup_user+0x62/0x8a [<ffffffff8114bee4>] sys_mount+0x84/0xc0 [<ffffffff810c9636>] ? audit_syscall_entry+0x119/0x145 [<ffffffff8103612b>] system_call_fastpath+0x16/0x1b Code: 53 48 83 ec 08 e8 b7 bf ce ff 48 8b bf 60 01 00 00 49 89 f6 49 89 d4 41 89 cf 48 89 7d d0 e8 83 dd ff ff 48 85 c0 48 89 c3 75 04 <0f> 0b eb fe 48 8b b8 c8 00 00 00 4c 8d 6b 38 48 81 c7 28 01 00 RIP [<ffffffff81349f3a>] btrfs_pin_extent+0x37/0xce RSP <ffff8800949579c8> ---[ end trace e7f075c327663f12 ]--- Yes, I think the partition was corrupted from the previous testing, which was able to mount successfully though. So 2nd reboot gave the same error: btrfs: sda7 checksum verify failed on 56213504 wanted 4E62BB6A found 3B389F1F level 1 btrfs: sda7 checksum verify failed on 56213504 wanted 4E62BB6A found 3B389F1F level 1 btrfs: sda7 checksum verify failed on 56213504 wanted 4E62BB6A found 3B389F1F level 1 parent transid verify failed on 56217600 wanted 72057594037927937 found 45 ------------[ cut here ]------------ kernel BUG at fs/btrfs/extent-tree.c:3541! invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC last sysfs file: /sys/devices/pci0000:00/0000:00:12.0/0000:04:0b.0/local_cpus CPU 1 Modules linked in: scsi_wait_scan Pid: 8557, comm: mount Not tainted 2.6.32-rc6-00346-gaa021ba #4 System Product Name RIP: 0010:[<ffffffff81349f3a>] [<ffffffff81349f3a>] btrfs_pin_extent+0x37/0xce RSP: 0018:ffff880095db39c8 EFLAGS: 00010246 RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff8800b9be1558 RDX: 0000000000840083 RSI: 000000000000050c RDI: ffff880095f080a8 RBP: ffff880095db39f8 R08: ffff880095f080a8 R09: 0000000000000000 R10: ffff880095db3918 R11: 0000000000000001 R12: 0000000000001000 R13: 01ffffffffffffff R14: fa00000000000000 R15: 0000000000000000 FS: 00007fdce4c047d0(0000) GS:ffff880008e00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 00007fdcdef74170 CR3: 0000000095e4d000 CR4: 00000000000006a0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff4ff0 DR7: 0000000000000400 Process mount (pid: 8557, threadinfo ffff880095db2000, task ffff8800b9be1520) Stack: ffff880095f08000 ffff88008598b290 ffff880095db3b08 01ffffffffffffff <0> ffff8800858c00d8 ffff8800b35ab0d8 ffff880095db3a28 ffffffff81380c2e <0> ffff8800858c00d8 ffff88008598b290 ffff880095db3acc 01ffffffffffffff Call Trace: [<ffffffff81380c2e>] process_one_buffer+0x3a/0x73 [<ffffffff8137e34d>] walk_down_log_tree+0x14c/0x3c3 [<ffffffff8137e646>] walk_log_tree+0x82/0x18c [<ffffffff8137f35a>] btrfs_recover_log_trees+0x178/0x27d [<ffffffff81380bf4>] ? process_one_buffer+0x0/0x73 [<ffffffff81354428>] ? btree_read_extent_buffer_pages+0x6f/0xac [<ffffffff81357ce3>] open_ctree+0x104f/0x12b2 [<ffffffff8140deb5>] ? vsnprintf+0x3fc/0x43b [<ffffffff81131cb6>] ? set_anon_super+0x0/0xec [<ffffffff81340460>] btrfs_get_sb+0x298/0x489 [<ffffffff81132bdd>] vfs_kern_mount+0xa2/0x15d [<ffffffff81132cff>] do_kern_mount+0x4c/0xec [<ffffffff8114bdfa>] do_mount+0x704/0x76a [<ffffffff81108b72>] ? strndup_user+0x62/0x8a [<ffffffff8114bee4>] sys_mount+0x84/0xc0 [<ffffffff810c9636>] ? audit_syscall_entry+0x119/0x145 [<ffffffff8103612b>] system_call_fastpath+0x16/0x1b Code: 53 48 83 ec 08 0f 1f 44 00 00 48 8b bf 60 01 00 00 49 89 f6 49 89 d4 41 89 cf 48 89 7d d0 e8 83 dd ff ff 48 85 c0 48 89 c3 75 04 <0f> 0b eb fe 48 8b b8 c8 00 00 00 4c 8d 6b 38 48 81 c7 28 01 00 RIP [<ffffffff81349f3a>] btrfs_pin_extent+0x37/0xce RSP <ffff880095db39c8> ---[ end trace 1dfe64a8dc2d8116 ]--- Doing a blkid: /dev/sda7: UUID="136c469e-8931-4b20-8c43-0222eecae9d9" TYPE="btrfs" Do u need me to dd the /dev/sda7 for your post-mortem analysis? And how many bytes is good enough? Disk /dev/sda: 300.0 GB, 300069052416 bytes 255 heads, 63 sectors/track, 36481 cylinders Units = cylinders of 16065 * 512 = 8225280 bytes Disk identifier: 0xe271e271 Device Boot Start End Blocks Id System /dev/sda7 34443 36481 16378236 83 Linux So in summary, I think we are looking at a few bugs here, one arising from remount a loopback-mounted entry, and another from a single "mount" command - perhaps due to insufficient error checking on corrupted blocks. THanks.
Yes and yes. We do try and carry on in the face of metadata errors but we don't always survive. I'd say you've hit two known problems (double mounting and error recovery). Thanks for tracking the oops down to a specific setup. We don't need to save the corrupted disk.
It looks to me like I've hit the same thing in the openSUSE Factory 2.6.34 kernel: http://pastebin.mozilla.org/740969 - I've been running btrfs for quite some time now on a partition I use for daily compiling multiple Mozilla builds, and this happened during such a process, as "Progress gmake" is noted in that /var/log/messages excerpt. Should I paste this inline here (pastebin only keeps it for a month), is it redundant to the ones above, or is that a new bug to be reported?
Closing, if this is still affecting you on a newer kernel please reopen.