Created attachment 448197 [details] Full debug output from virt-df Description of problem: I have a minix filesystem which provokes the stack trace attached (2.6.36-0.22.rc4.git2.fc15.x86_64 and also earlier kernel versions). There's nothing particularly special about the filesystem. I made it simply by installing Minix 3.1.7 in a qemu VM. Unfortunately though the disk image that contains it is pretty large (4GB) so it's going to be quite hard to provide a copy of it for anyone. [ 119.975051] BUG: unable to handle kernel paging request at ffff88001f3fd000 [ 119.975051] IP: [<ffffffffa01070b2>] count_free+0xb2/0x137 [minix] [ 119.975051] PGD 1a44063 PUD 1a48063 PMD 8067 PTE 0 [ 119.975051] Oops: 0000 [#1] SMP [ 119.975051] last sysfs file: /sys/devices/virtio-pci/virtio1/block/vda/dev [ 119.975051] CPU 0 [ 119.975051] Modules linked in: minix nls_utf8 hfsplus hfs vfat fat i2c_piix4 i2c_core virtio_blk virtio_net virtio_console virtio_rng virtio_balloon virtio_pci sym53c8xx virtio_ring virtio scsi_transport_spi libcrc32c ext2 crc7 crc_itu_t crc_ccitt [ 119.975051] [ 119.975051] Pid: 230, comm: guestfsd Not tainted 2.6.36-0.22.rc4.git2.fc15.x86_64 #1 /Bochs [ 119.975051] RIP: 0010:[<ffffffffa01070b2>] [<ffffffffa01070b2>] count_free+0xb2/0x137 [minix] [ 119.975051] RSP: 0018:ffff88001cdc3d70 EFLAGS: 00000203 [ 119.975051] RAX: 00000000fffffea2 RBX: ffff88001f07e000 RCX: 000000000037f000 [ 119.975051] RDX: 00000000000c751f RSI: ffff88001ca354d0 RDI: 000000000037f001 [ 119.975051] RBP: ffff88001cdc3d90 R08: 000000000178ca99 R09: 0000000000000019 [ 119.975051] R10: ffff88001ca35000 R11: 0000000000000019 R12: 0000000000001000 [ 119.975051] R13: 0000000000000000 R14: ffff88001cdc3e00 R15: 00007fff9a2d42c0 [ 119.975051] FS: 00007f1f4c7ff7c0(0000) GS:ffff880002c00000(0000) knlGS:0000000000000000 [ 119.975051] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 119.975051] CR2: ffff88001f3fd000 CR3: 000000001c47a000 CR4: 00000000000006f0 [ 119.975051] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 119.975051] DR3: 0000000000000000 DR6: 0000000000000000 DR7: 0000000000000000 [ 119.975051] Process guestfsd (pid: 230, threadinfo ffff88001cdc2000, task ffff88001c65a440) [ 119.975051] Stack: [ 119.975051] ffff88001ce5c000 ffff88001ce5c000 000000000fc00007 ffff88001cdc3ec8 [ 119.975051] <0> ffff88001cdc3da8 ffffffffa01072fa ffff88001cdc3e28 ffff88001cdc3dd8 [ 119.975051] <0> ffffffffa0109628 ffff88001cdc3dd8 ffff88001cdc3e28 ffff88001caa43d8 [ 119.975051] Call Trace: [ 119.975051] [<ffffffffa01072fa>] minix_count_free_blocks+0x23/0x2c [minix] [ 119.975051] [<ffffffffa0109628>] minix_statfs+0x5a/0xb0 [minix] [ 119.975051] [<ffffffff8114d60e>] statfs_by_dentry+0x56/0x6e [ 119.975051] [<ffffffff8114d641>] vfs_statfs+0x1b/0xb0 [ 119.975051] [<ffffffff8114d734>] do_statfs_native+0x22/0x3c [ 119.975051] [<ffffffff8114d79a>] sys_statfs+0x4c/0x8f [ 119.975051] [<ffffffff8113377a>] ? mntput+0x1d/0x1f [ 119.975051] [<ffffffff81009cea>] ? sysret_check+0x2e/0x69 [ 119.975051] [<ffffffff810801d5>] ? trace_hardirqs_on_caller+0x10b/0x12f [ 119.975051] [<ffffffff8149c10a>] ? trace_hardirqs_on_thunk+0x3a/0x3f [ 119.975051] [<ffffffff81009cb2>] system_call_fastpath+0x16/0x1b [ 119.975051] Code: 85 f6 0f 84 9f 00 00 00 48 8b 4e 20 89 d0 31 ff 48 c1 e1 03 49 0f af c9 48 29 c8 48 c1 e8 04 01 c0 eb 26 48 8b 5e 28 89 f9 ff c7 <8a> 0c 0b 88 cb 83 e1 0f c0 fb 04 83 e3 0f 44 03 04 9d b0 b0 10 [ 119.975051] RIP [<ffffffffa01070b2>] count_free+0xb2/0x137 [minix] [ 119.975051] RSP <ffff88001cdc3d70> [ 119.975051] CR2: ffff88001f3fd000 [ 119.975051] ---[ end trace 33e5808896065909 ]--- Version-Release number of selected component (if applicable): Linux version 2.6.36-0.22.rc4.git2.fc15.x86_64 (mockbuild.fedoraproject.org) (gcc version 4.5.1 20100907 (Red Hat 4.5.1-3) (GCC) ) #1 SMP Wed Sep 15 12:48:54 UTC 2010 (also happens with earlier kernel versions, I tested several versions from 2.6.33 onwards) How reproducible: Always. Steps to Reproduce: 1. Install Minix 3.1.7 in a qemu (not KVM) VM. 2. Attach the disk to a Rawhide VM, or just run LIBGUESTFS_DEBUG=1 virt-df -h /dev/vg/minix Actual results: Spectacular crash. Expected results: Shouldn't crash. Additional info:
Looking a bit more closely, what fails is *not* the mount, but the statfs system call on the mounted filesystem. To reproduce this you would have to first mount /dev/vda7 (readonly, not sure if that matters), and then perform a statfs(2) system call on the filesystem.
I filed a bug upstream here: https://bugzilla.kernel.org/show_bug.cgi?id=18792
Does this still happen on an F16 or F17 kernel?
It appears to be fixed with 3.0.0. I'm just doing a few more tests, and if it still works I will close the bug. Not sure what exactly fixed it. Al Viro has been doing some minor patches for minixfs upstream, but nothing that appears to touch this code. Also this commit could have fixed it: 0ab7620a0cefe6982b914a830a41f65ecccd74bd
Sorry, disregard the previous comment. With further testing, I *can* reproduce this issue using 3.0.0-1.fc16.x86_64. I am going to make a disk image available for testing.
The stack trace is longer with 3.0.0-1, but it appears to come from the same part of the code: [ 3.675747] BUG: unable to handle kernel paging request at ffff88001f3fd000 [ 3.676018] IP: [<ffffffffa00730a6>] count_free+0xa6/0x126 [minix] [ 3.676018] PGD 1a04063 PUD 1a08063 PMD 1f3fa067 PTE 0 [ 3.676018] Oops: 0000 [#1] SMP [ 3.676018] CPU 0 [ 3.676018] Modules linked in: minix i2c_piix4 i2c_core virtio_net virtio_blk virtio_rng virtio_balloon sparse_keymap rfkill sym53c8xx scsi_transport_spi crc7 crc_ccitt crc_itu_t libcrc32c [ 3.676018] [ 3.676018] Pid: 149, comm: guestfsd Not tainted 3.0.0-1.fc16.x86_64 #1 Bochs Bochs [ 3.676018] RIP: 0010:[<ffffffffa00730a6>] [<ffffffffa00730a6>] count_free+0xa6/0x126 [minix] [ 3.676018] RSP: 0018:ffff88001bd61e00 EFLAGS: 00010282 [ 3.676018] RAX: 00000000fffffe7a RBX: 0000000000001000 RCX: ffff88001bbc9000 [ 3.676018] RDX: 00000000000c73d9 RSI: ffff88001c162000 RDI: 0000000003834000 [ 3.676018] RBP: ffff88001bd61e10 R08: 0000000016a9dc8c R09: 000000000000000f [ 3.676018] R10: 0000000000000019 R11: 0000000000001000 R12: 0000000000000000 [ 3.676018] R13: 000000000fc00007 R14: 0000000000000003 R15: 0000000000000000 [ 3.676018] FS: 00007ffa909527c0(0000) GS:ffff88001f000000(0000) knlGS:0000000000000000 [ 3.676018] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 3.676018] CR2: ffff88001f3fd000 CR3: 000000001c702000 CR4: 00000000000006f0 [ 3.676018] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 3.676018] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 3.676018] Process guestfsd (pid: 149, threadinfo ffff88001bd60000, task ffff88001c490000) [ 3.676018] Stack: [ 3.676018] ffff88001c68b3e8 ffff88001c68b3e8 ffff88001bd61e28 ffffffffa00732e1 [ 3.676018] ffff88001bd61ef0 ffff88001bd61e58 ffffffffa0075464 ffffea0000617b28 [ 3.676018] ffff88001bd61ef0 ffff88001c227bd0 00000000053f3020 ffff88001bd61e78 [ 3.676018] Call Trace: [ 3.676018] [<ffffffffa00732e1>] minix_count_free_blocks+0x23/0x2c [minix] [ 3.676018] [<ffffffffa0075464>] minix_statfs+0x58/0xaf [minix] [ 3.676018] [<ffffffff8115f21e>] statfs_by_dentry+0x56/0x6e [ 3.676018] [<ffffffff8115f251>] vfs_statfs+0x1b/0x94 [ 3.676018] [<ffffffff8115f301>] user_statfs+0x37/0x4d [ 3.676018] [<ffffffff8108aafa>] ? lock_release+0x173/0x19c [ 3.676018] [<ffffffff8115f37d>] sys_statfs+0x20/0x3f [ 3.676018] [<ffffffff814e4fc2>] system_call_fastpath+0x16/0x1b [ 3.676018] Code: 0f 84 a0 00 00 00 48 8b 4e 20 89 d0 31 ff 48 c1 e1 03 49 0f af c9 48 29 c8 48 c1 e8 04 01 c0 eb 29 48 8b 4e 28 41 b9 0f 00 00 00 <8a> 0c 39 48 ff c7 49 21 c9 c0 f9 04 83 e1 0f 46 03 04 8d 40 70 [ 3.676018] RIP [<ffffffffa00730a6>] count_free+0xa6/0x126 [minix] [ 3.676018] RSP <ffff88001bd61e00> [ 3.676018] CR2: ffff88001f3fd000 [ 3.676018] ---[ end trace 5389ffbaa03bbeca ]--- [ 3.676018] BUG: sleeping function called from invalid context at kernel/rwsem.c:21 [ 3.676018] in_atomic(): 0, irqs_disabled(): 1, pid: 149, name: guestfsd [ 3.676018] INFO: lockdep is turned off. [ 3.676018] irq event stamp: 53046 [ 3.676018] hardirqs last enabled at (53045): [<ffffffff814de814>] restore_args+0x0/0x30 [ 3.676018] hardirqs last disabled at (53046): [<ffffffff814decd6>] error_sti+0x5/0x6 [ 3.676018] softirqs last enabled at (53044): [<ffffffff8105f25f>] __do_softirq+0x192/0x1ec [ 3.676018] softirqs last disabled at (53031): [<ffffffff814e625c>] call_softirq+0x1c/0x30 [ 3.676018] Pid: 149, comm: guestfsd Tainted: G D 3.0.0-1.fc16.x86_64 #1 [ 3.676018] Call Trace: [ 3.676018] [<ffffffff8108983a>] ? print_irqtrace_events+0x9e/0xa2 [ 3.676018] [<ffffffff8104c53a>] __might_sleep+0x103/0x108 [ 3.676018] [<ffffffff814dd183>] down_read+0x26/0x86 [ 3.676018] [<ffffffff81079758>] ? hrtimer_try_to_cancel+0x81/0x8f [ 3.676018] [<ffffffff8109ca47>] acct_collect+0x4d/0x188 [ 3.676018] [<ffffffff8105c8c4>] do_exit+0x23e/0x7fb [ 3.676018] [<ffffffff8105a76c>] ? kmsg_dump+0x122/0x132 [ 3.676018] [<ffffffff8105a6d3>] ? kmsg_dump+0x89/0x132 [ 3.676018] [<ffffffff814df721>] oops_end+0xbc/0xc5 [ 3.676018] [<ffffffff814d3866>] no_context+0x203/0x212 [ 3.676018] [<ffffffff814d3a0e>] __bad_area_nosemaphore+0x199/0x1bc [ 3.676018] [<ffffffff814d30f7>] ? pte_offset_kernel+0x19/0x3f [ 3.676018] [<ffffffff814d3a44>] bad_area_nosemaphore+0x13/0x15 [ 3.676018] [<ffffffff814e17dd>] do_page_fault+0x1df/0x3d5 [ 3.676018] [<ffffffff8108afe5>] ? trace_hardirqs_on_caller+0x10b/0x12f [ 3.676018] [<ffffffff810f3d18>] ? __free_pages_ok+0xb2/0xbb [ 3.676018] [<ffffffff810f3eaa>] ? __free_pages+0x2d/0x2f [ 3.676018] [<ffffffff810874cc>] ? trace_hardirqs_off_caller+0x33/0x90 [ 3.676018] [<ffffffff812452fd>] ? trace_hardirqs_off_thunk+0x3a/0x3c [ 3.676018] [<ffffffff814e12c4>] do_async_page_fault+0x31/0x4f [ 3.676018] [<ffffffff814deac5>] async_page_fault+0x25/0x30 [ 3.676018] [<ffffffffa00730a6>] ? count_free+0xa6/0x126 [minix] [ 3.676018] [<ffffffffa00732e1>] minix_count_free_blocks+0x23/0x2c [minix] [ 3.676018] [<ffffffffa0075464>] minix_statfs+0x58/0xaf [minix] [ 3.676018] [<ffffffff8115f21e>] statfs_by_dentry+0x56/0x6e [ 3.676018] [<ffffffff8115f251>] vfs_statfs+0x1b/0x94 [ 3.676018] [<ffffffff8115f301>] user_statfs+0x37/0x4d [ 3.676018] [<ffffffff8108aafa>] ? lock_release+0x173/0x19c [ 3.676018] [<ffffffff8115f37d>] sys_statfs+0x20/0x3f [ 3.676018] [<ffffffff814e4fc2>] system_call_fastpath+0x16/0x1b
Another observation: The bug does NOT occur when the total disk size is 1G. The bug only occurs when I increase the total disk size to 4G (and reinstall Minix of course). In both cases I chose the default partitioning options in the Minix installer.
Created attachment 518325 [details] minix.part7.zeroes.bz635266.img.xz I've made a compressed minix fs which reproduces the problem. Notes: (1) I wrote zeroes over everything except the first 100MB of the fs, just to make it small enough to distribute. This image still demonstrates the problem, but it's not a "real" minix filesystem. (2) There is no partition table, this is just a filesystem. To reproduce the bug: (a) Download this image. (b) Uncompress it: $ unxz minix.part7.zeroes.bz635266.img.xz (c) Verify uncompressed image: $ md5sum minix.part7.zeroes.bz635266.img abd1a3b3881a1cf32110dc86da896a75 minix.part7.zeroes.bz635266.img $ ls -l minix.part7.zeroes.bz635266.img.xz -rw-rw-r--. 1 rjones rjones 6874396 Aug 15 20:17 minix.part7.zeroes.bz635266.img.xz (d) Attach it to a Linux virtual machine, and boot the VM. (e) Try mounting it and running any command that uses 'statvfs', easiest is the 'df' command. # mount /dev/vdb /mnt # df /mnt Killed. (f) Observe kernel error in dmesg.
In step (c) above, UNcompressed size is: $ ls -l minix.part7.zeroes.bz635266.img -rw-rw-r--. 1 rjones rjones 3395982336 Aug 15 21:47 minix.part7.zeroes.bz635266.img
Yeah, I can oops my VM with this. Thanks for attaching the image.
This is the 1G image which does *not* trigger the bug. Unfortunately XZ doesn't compress this very well, so the compressed image is rather huge and will take ages for anyone to download. http://oirase.annexia.org/tmp/minix.1G.bz635266.img.xz Compressed: $ md5sum minix.1G.bz635266.img.xz b9712aad5fbdeaa046d2fad329a3f34c minix.1G.bz635266.img.xz $ ls -l minix.1G.bz635266.img.xz -rw-rw-r--. 1 rjones rjones 625640428 Aug 16 14:08 minix.1G.bz635266.img.xz Uncompressed: $ md5sum minix.1G.bz635266.img 9421b8ac0e40dba081571689592f9394 minix.1G.bz635266.img $ ls -l minix.1G.bz635266.img -rw-rw-r--. 1 rjones rjones 1073741824 Aug 16 14:08 minix.1G.bz635266.img
I installed minix 3.1.8 in a 1G virtual disk today instead of grabbing the image from comment #11. df "works" on the /home and / partitions, but /usr (which is ~768MB) generates the oops. What's happening is that a calculation in count_free is going negative, and that seems to be causing us to access beyond the end of the bh->b_data variable. I have no idea why this is at the moment.
I've got a patch for this and it's been sent upstream (on v3 now). Hopefully it will be fixed in the final 3.1.
This missed 3.1 due to kernel.org being compromised. It is fixed upstream (finally) and that should be included in tomorrow's rawihde
Yay. Thanks for fixing and chasing this.