* [4.7-rc4] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 @ 2016-07-04 23:46 Dave Chinner 2016-07-05 4:45 ` Theodore Ts'o 0 siblings, 1 reply; 4+ messages in thread From: Dave Chinner @ 2016-07-04 23:46 UTC (permalink / raw) To: linux-ext4 Hi folks, I just got this warning on boot from a test VM running an ext3 root filesystem: [ 14.874951] ------------[ cut here ]------------ [ 14.876447] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 [ 14.878520] Modules linked in: [ 14.880065] CPU: 10 PID: 3359 Comm: mv Not tainted 4.7.0-rc4-dgc+ #821 [ 14.883062] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 [ 14.886648] 0000000000000000 ffff8800bad63c90 ffffffff817f1321 0000000000000000 [ 14.888942] 0000000000000000 ffff8800bad63cd0 ffffffff810b3531 000001183750906c [ 14.891613] ffff8800bb3095b0 ffff8800bad63d48 ffff88033750906c 0000000000000000 [ 14.893635] Call Trace: [ 14.894096] [<ffffffff817f1321>] dump_stack+0x63/0x82 [ 14.895387] [<ffffffff810b3531>] __warn+0xd1/0xf0 [ 14.896709] [<ffffffff810b361d>] warn_slowpath_null+0x1d/0x20 [ 14.898421] [<ffffffff8121339e>] drop_nlink+0x3e/0x50 [ 14.899737] [<ffffffff812d7d7b>] ext4_dec_count.isra.26+0x1b/0x30 [ 14.901360] [<ffffffff812dd8a2>] ext4_rename+0x4d2/0x880 [ 14.903025] [<ffffffff8177bde8>] ? security_capable+0x48/0x60 [ 14.904524] [<ffffffff812ddc6d>] ext4_rename2+0x1d/0x30 [ 14.905833] [<ffffffff8120676d>] vfs_rename+0x5fd/0x900 [ 14.907163] [<ffffffff81209738>] SyS_rename+0x398/0x3b0 [ 14.908496] [<ffffffff81e3c2f2>] entry_SYSCALL_64_fastpath+0x1a/0xa4 [ 14.910251] ---[ end trace b59a7c09fe84eaba ]--- It's from the root device: 16 0 8:1 / / rw,relatime shared:1 - ext3 /dev/root rw,errors=remount-ro,data=ordered It happened during boot after I had to forcible terminate the VM from the host due to it becoming unresponsive while testing XFS code changes on a test filesystem. The mount messages were: [ 3.187990] EXT4-fs (sda1): mounting ext3 file system using the ext4 subsystem [ 3.191331] EXT4-fs (sda1): INFO: recovery required on readonly filesystem [ 3.193546] EXT4-fs (sda1): write access will be enabled during recovery [ 3.448499] EXT4-fs (sda1): orphan cleanup on readonly fs [ 3.450334] EXT4-fs (sda1): 1 orphan inode deleted [ 3.451762] EXT4-fs (sda1): recovery complete [ 3.462121] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null) It's a 10GB fs, 85% full. I can't reproduce it and I've got no more information in the logs about the problem.... Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [4.7-rc4] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 2016-07-04 23:46 [4.7-rc4] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 Dave Chinner @ 2016-07-05 4:45 ` Theodore Ts'o 2016-07-10 0:14 ` Dave Chinner 0 siblings, 1 reply; 4+ messages in thread From: Theodore Ts'o @ 2016-07-05 4:45 UTC (permalink / raw) To: Dave Chinner; +Cc: linux-ext4 On Tue, Jul 05, 2016 at 09:46:33AM +1000, Dave Chinner wrote: > Hi folks, > > I just got this warning on boot from a test VM running an ext3 > root filesystem: > > [ 14.874951] ------------[ cut here ]------------ > [ 14.876447] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 > [ 14.878520] Modules linked in: > [ 14.880065] CPU: 10 PID: 3359 Comm: mv Not tainted 4.7.0-rc4-dgc+ #821 > [ 14.883062] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 > [ 14.886648] 0000000000000000 ffff8800bad63c90 ffffffff817f1321 0000000000000000 > [ 14.888942] 0000000000000000 ffff8800bad63cd0 ffffffff810b3531 000001183750906c > [ 14.891613] ffff8800bb3095b0 ffff8800bad63d48 ffff88033750906c 0000000000000000 > [ 14.893635] Call Trace: > [ 14.894096] [<ffffffff817f1321>] dump_stack+0x63/0x82 > [ 14.895387] [<ffffffff810b3531>] __warn+0xd1/0xf0 > [ 14.896709] [<ffffffff810b361d>] warn_slowpath_null+0x1d/0x20 > [ 14.898421] [<ffffffff8121339e>] drop_nlink+0x3e/0x50 > [ 14.899737] [<ffffffff812d7d7b>] ext4_dec_count.isra.26+0x1b/0x30 > [ 14.901360] [<ffffffff812dd8a2>] ext4_rename+0x4d2/0x880 > [ 14.903025] [<ffffffff8177bde8>] ? security_capable+0x48/0x60 > [ 14.904524] [<ffffffff812ddc6d>] ext4_rename2+0x1d/0x30 > [ 14.905833] [<ffffffff8120676d>] vfs_rename+0x5fd/0x900 > [ 14.907163] [<ffffffff81209738>] SyS_rename+0x398/0x3b0 > [ 14.908496] [<ffffffff81e3c2f2>] entry_SYSCALL_64_fastpath+0x1a/0xa4 > [ 14.910251] ---[ end trace b59a7c09fe84eaba ]--- Thanks for the report. I'm pretty sure what happened is that the file system was corrupted, but ext4_rename() does't have a check to make sure i_links_count of the destination inode is non-zero (and to call ext4_error() to flag the fs corruption if it is zero). Specifically, I suspect what happened is that there was a file with two hard links, but a i_link_count of 1. Both links were in the dentry cache, and then the first link got deleted, leaving the second link still in the dentry cache, but with a link count of 0. How the file system got corrupted is of course a different question, but I assume it happened when the VM was forcibly terminated beforehand. How is the root device configured in terms of qemu device cacheing? I don't think we have any corruption after crash problems at this point (at least I haven't noticed any of the dm-flaky tests failing recently), so my first suspicion is would be how qemu is configured. Cheers, - Ted ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [4.7-rc4] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 2016-07-05 4:45 ` Theodore Ts'o @ 2016-07-10 0:14 ` Dave Chinner 2016-07-10 15:25 ` Theodore Ts'o 0 siblings, 1 reply; 4+ messages in thread From: Dave Chinner @ 2016-07-10 0:14 UTC (permalink / raw) To: Theodore Ts'o; +Cc: linux-ext4 On Tue, Jul 05, 2016 at 12:45:24AM -0400, Theodore Ts'o wrote: > On Tue, Jul 05, 2016 at 09:46:33AM +1000, Dave Chinner wrote: > > Hi folks, > > > > I just got this warning on boot from a test VM running an ext3 > > root filesystem: > > > > [ 14.874951] ------------[ cut here ]------------ > > [ 14.876447] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 > > [ 14.878520] Modules linked in: > > [ 14.880065] CPU: 10 PID: 3359 Comm: mv Not tainted 4.7.0-rc4-dgc+ #821 > > [ 14.883062] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014 > > [ 14.886648] 0000000000000000 ffff8800bad63c90 ffffffff817f1321 0000000000000000 > > [ 14.888942] 0000000000000000 ffff8800bad63cd0 ffffffff810b3531 000001183750906c > > [ 14.891613] ffff8800bb3095b0 ffff8800bad63d48 ffff88033750906c 0000000000000000 > > [ 14.893635] Call Trace: > > [ 14.894096] [<ffffffff817f1321>] dump_stack+0x63/0x82 > > [ 14.895387] [<ffffffff810b3531>] __warn+0xd1/0xf0 > > [ 14.896709] [<ffffffff810b361d>] warn_slowpath_null+0x1d/0x20 > > [ 14.898421] [<ffffffff8121339e>] drop_nlink+0x3e/0x50 > > [ 14.899737] [<ffffffff812d7d7b>] ext4_dec_count.isra.26+0x1b/0x30 > > [ 14.901360] [<ffffffff812dd8a2>] ext4_rename+0x4d2/0x880 > > [ 14.903025] [<ffffffff8177bde8>] ? security_capable+0x48/0x60 > > [ 14.904524] [<ffffffff812ddc6d>] ext4_rename2+0x1d/0x30 > > [ 14.905833] [<ffffffff8120676d>] vfs_rename+0x5fd/0x900 > > [ 14.907163] [<ffffffff81209738>] SyS_rename+0x398/0x3b0 > > [ 14.908496] [<ffffffff81e3c2f2>] entry_SYSCALL_64_fastpath+0x1a/0xa4 > > [ 14.910251] ---[ end trace b59a7c09fe84eaba ]--- > > Thanks for the report. I'm pretty sure what happened is that the file > system was corrupted, Filesystem checked clean, both before and after, so you're initial assumption is wrong. > but ext4_rename() does't have a check to make > sure i_links_count of the destination inode is non-zero (and to call > ext4_error() to flag the fs corruption if it is zero). Specifically, > I suspect what happened is that there was a file with two hard links, > but a i_link_count of 1. Both links were in the dentry cache, and > then the first link got deleted, leaving the second link still in the > dentry cache, but with a link count of 0. Or, more likely, a dentry cache lookup bug. There was one introduced in 4.7-rc1 with the parallel lookup code and fixed in 4.7-rc6 that could result in this happening. Funnily enough, XFS hit this same lookup bug, too, but with different symptoms (triggered corruption warnings in unlink processing) so it wasn't immiedately obvious that they had the same root cause. > How the file system got corrupted is of course a different question, > but I assume it happened when the VM was forcibly terminated > beforehand. How is the root device configured in terms of qemu device > cacheing? I don't think we have any corruption after crash problems > at this point (at least I haven't noticed any of the dm-flaky tests > failing recently), so my first suspicion is would be how qemu is > configured So, to top off the incorrect assumption, your first suspicion is a newbie mistake? Really, Ted? The VM uses "cache="none", which means the responsibility for correct flushing of the device belongs with the guest OS filesystem, not qemu. Hence data loss or filesystem corruption on guest crash or host qemu process kill is a guest OS bug, not a qemu issue.... Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [4.7-rc4] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 2016-07-10 0:14 ` Dave Chinner @ 2016-07-10 15:25 ` Theodore Ts'o 0 siblings, 0 replies; 4+ messages in thread From: Theodore Ts'o @ 2016-07-10 15:25 UTC (permalink / raw) To: Dave Chinner; +Cc: linux-ext4 Sorry if I offended your sense of non-newbieness :-), but I didn't know how your root file system and qemu was configured, and I did find a potential place where a corrupted file system could lead to exact symptoms that you reported. Hence the reason that I made the assumption that I did. Cheers, - Ted ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2016-07-10 15:25 UTC | newest] Thread overview: 4+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2016-07-04 23:46 [4.7-rc4] WARNING: CPU: 10 PID: 3359 at fs/inode.c:280 drop_nlink+0x3e/0x50 Dave Chinner 2016-07-05 4:45 ` Theodore Ts'o 2016-07-10 0:14 ` Dave Chinner 2016-07-10 15:25 ` Theodore Ts'o
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).