Re: [btrfs] WARNING: CPU: 0 PID: 6379 at fs/direct-io.c:293 dio_complete+0x1d4/0x220

[Eric Biggers]

On Tue, Oct 31, 2017 at 02:54:17PM +0800, Eryu Guan wrote:
> On Tue, Oct 31, 2017 at 01:10:41AM +0100, Fengguang Wu wrote:
> > Hi Eryu,
> > 
> > On Mon, Oct 30, 2017 at 03:44:29PM +0800, Eryu Guan wrote:
> > > Hi Fengguang,
> > > 
> > > On Mon, Oct 30, 2017 at 08:20:21AM +0100, Fengguang Wu wrote:
> > > > CC fsdevel.
> > > > 
> > > > On Sun, Oct 29, 2017 at 11:51:55PM +0100, Fengguang Wu wrote:
> > > > > Hi Linus,
> > > > >
> > > > > Up to now we see the below boot error/warnings when testing v4.14-rc6.
> > > > >
> > > > > They hit the RC release mainly due to various imperfections in 0day's
> > > > > auto bisection. So I manually list them here and CC the likely easy to
> > > > > debug ones to the corresponding maintainers in the followup emails.
> > > > >
> > > > > boot_successes: 4700
> > > > > boot_failures: 247
> > > > 
> > > > [...]
> > > > 
> > > > > WARNING:at_fs/direct-io.c:#dio_complete: 7
> > > > > WARNING:at_fs/iomap.c:#iomap_dio_complete: 3
> > > > > WARNING:at_fs/iomap.c:#iomap_dio_rw: 1
> > > > 
> > > > The first warning happens on btrfs and is bisected to this commit.
> > > > The other 2 warnings happen on xfs.
> > > 
> > > I noticed that the warnings are triggered by generic/095 and
> > > generic/208, they're known to generate such warnings and I think these
> > > warnings are kind of 'known issue', please see comments above
> > > _filter_aiodio_dmesg() in fstests/common/filter.
> > > 
> > > Please make sure your local fstests contains the following 3 commits:
> > > 
> > > ca93e26865ab common: move _filter_xfs_dmesg() to common/filter
> > > 5aa662733ab0 common: turn _filter_xfs_dmesg() into _filter_aiodio_dmesg()
> > > 228aee780f13 generic/036,208: whitelist [iomap_]dio_complete() WARNs
> > 
> > OK.
> > 
> > > we filtered out such warnings in fstests on purpose so the affected
> > > tests won't fail because of such dmesg warnings.
> > 
> > We may also teach 0day robot to ignore the warning when running the
> > above 2 fstests.
> > 
> > The more generic way of filtering may be to inject a dmesg line like
> > 
> >        THIS TEST WILL TRIGGER KERNEL WARNING, PLEASE IGNORE.
> > 
> > just before the specific tests startup. Then 3rd party dmesg parsing
> > scripts can handle such purpose-made warnings in a uniform way.
> 
> fstests doesn't know, prior to the test, if the warnings the test is
> going to trigger are intentional or real bugs, fstests records the dmesg
> log and analyzes the log after test and reports PASS if all the warnings
> are intentional (based on the whitelist filter).
> 
> But I think it's possible to insert such a message to dmesg *after* test
> if fstests finds that all the warnings are intentional. Does that work
> for 0day robot?
> 

Please don't hack around this in tests.  WARN_ON() is only meant to be used to
indicate kernel bugs.  It should never be reachable by userspace.  I'm seeing
the same WARNING when fuzzing with syzkaller (see below).  If it's supposed to
be reachable by userspace, then it *must* be removed, or perhaps replaced with
pr_warn_ratelimited() with a message that is actually understandable, like
"process 'foo' mixes buffered I/O with direct I/O".

	WARNING: CPU: 2 PID: 27399 at fs/direct-io.c:293 dio_complete+0x532/0x7e0 fs/direct-io.c:293
	Kernel panic - not syncing: panic_on_warn set ...

	CPU: 2 PID: 27399 Comm: syz-executor0 Not tainted 4.14.0-rc7-00174-g2d6349944d96 #1
	Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.3-20171021_125229-anatol 04/01/2014
	Call Trace:
	 __dump_stack lib/dump_stack.c:17 [inline]
	 dump_stack+0x115/0x1da lib/dump_stack.c:53
	 panic+0x1b4/0x39c kernel/panic.c:181
	 __warn+0x1bf/0x1d4 kernel/panic.c:542
	 report_bug+0x23f/0x2c0 lib/bug.c:184
	 fixup_bug+0x3f/0x90 arch/x86/kernel/traps.c:178
	 do_trap_no_signal arch/x86/kernel/traps.c:212 [inline]
	 do_trap+0x260/0x390 arch/x86/kernel/traps.c:261
	 do_error_trap+0x11c/0x350 arch/x86/kernel/traps.c:298
	 do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:311
	 invalid_op+0x18/0x20 arch/x86/entry/entry_64.S:906
	RIP: 0010:dio_complete+0x532/0x7e0 fs/direct-io.c:293
	RSP: 0018:ffff880039dcf208 EFLAGS: 00010212
	RAX: 0000000000010000 RBX: ffff880061a1f040 RCX: 0000000000000ebd
	RDX: ffffffff816b97f2 RSI: ffffc90000696000 RDI: ffffed00073b9e36
	RBP: ffff880039dcf250 R08: ffff88007ffd709c R09: ffff880037874640
	R10: 00000000000002e7 R11: ffff88007ffd709d R12: 0000000000000200
	R13: 0000000000000200 R14: ffff8800593cf8f0 R15: ffffffff898005d0
	 do_blockdev_direct_IO fs/direct-io.c:1374 [inline]
	 __blockdev_direct_IO+0x46b9/0x8a70 fs/direct-io.c:1400
	 ext4_direct_IO_write fs/ext4/inode.c:3685 [inline]
	 ext4_direct_IO+0x98e/0x1950 fs/ext4/inode.c:3807
	 generic_file_direct_write+0x1e6/0x440 mm/filemap.c:2928
	 __generic_file_write_iter+0x21f/0x5b0 mm/filemap.c:3107
	 ext4_file_write_iter+0x5c2/0x10a0 fs/ext4/file.c:264
	 call_write_iter include/linux/fs.h:1771 [inline]
	 new_sync_write fs/read_write.c:469 [inline]
	 __vfs_write+0x681/0x970 fs/read_write.c:482
	 vfs_write+0x18b/0x480 fs/read_write.c:544
	 SYSC_write fs/read_write.c:589 [inline]
	 SyS_write+0xef/0x230 fs/read_write.c:581
	 entry_SYSCALL_64_fastpath+0x1f/0xbe
	RIP: 0033:0x4585c9
	RSP: 002b:00007ff87eff2bd8 EFLAGS: 00000216 ORIG_RAX: 0000000000000001
	RAX: ffffffffffffffda RBX: 0000000000738020 RCX: 00000000004585c9
	RDX: 0000000000000200 RSI: 0000000020010000 RDI: 0000000000000015
	RBP: 0000000000000046 R08: 0000000000000000 R09: 0000000000000000
	R10: 0000000000000000 R11: 0000000000000216 R12: 00000000006d1048
	R13: 00000000ffffffff R14: 00007ff87eff36bc R15: 0000000000000000
	Dumping ftrace buffer:
	   (ftrace buffer empty)
	Kernel Offset: 0x8000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
	Rebooting in 86400 seconds..