WARN_ON_ONCE(1) in iomap_dio_actor()

WARN_ON_ONCE(1) in iomap_dio_actor()

[Qian Cai]

Running a syscall fuzzer by a normal user could trigger this,

[55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
[55649.339490][T515839] Modules linked in: vfio_pci vfio_virqfd vfio_iommu_type1 vfio processor efivarfs ip_tables x_tables sd_mod mlx5_core ahci firmware_class libahci libata dm_mirror dm_region_hash dm_log dm_mod
[55649.358315][T515839] CPU: 6 PID: 515839 Comm: trinity-c21 Not tainted 5.8.0-rc1-next-20200618 #1
[55649.367100][T515839] Hardware name: HPE Apollo 70             /C01_APACHE_MB         , BIOS L50_5.13_1.11 06/18/2019
[55649.377624][T515839] pstate: 80400009 (Nzcv daif +PAN -UAO BTYPE=--)
[55649.383987][T515839] pc : iomap_dio_actor+0x29c/0x420
[55649.389040][T515839] lr : iomap_apply+0x31c/0x14e8
[55649.393830][T515839] sp : ffff00953540f670
[55649.397925][T515839] x29: ffff00953540f670 x28: 0000000000000000
[55649.404022][T515839] x27: ffff00953540f7b0 x26: ffffa00012113000
[55649.410119][T515839] x25: 000000000000d904 x24: ffffa00011553400
[55649.416216][T515839] x23: ffff0095c49d1288 x22: ffff0095c49d1288
[55649.422313][T515839] x21: 0000000000000080 x20: 000000000000d904
[55649.428416][T515839] x19: ffff0088f9ad9b80 x18: 0000000000000000
[55649.434516][T515839] x17: 0000000000000000 x16: 0000000000000000
[55649.440613][T515839] x15: 0000000000000000 x14: 0000000000000022
[55649.446709][T515839] x13: ffff80113ef86764 x12: 1fffe0113ef86763
[55649.452808][T515839] x11: 1fffe0113ef86763 x10: ffff80113ef86763
[55649.458913][T515839] x9 : dfffa00000000000 x8 : ffff0089f7c33b1b
[55649.465034][T515839] x7 : 0000000000000001 x6 : dfffa00000000000
[55649.471144][T515839] x5 : ffff00953540f7c8 x4 : ffff00953540f7b0
[55649.477248][T515839] x3 : ffff0088f9ad9b80 x2 : 0000000000000001
[55649.483346][T515839] x1 : 0000000000000001 x0 : ffff0095c49d1288
[55649.489452][T515839] Call trace:
[55649.492700][T515839]  iomap_dio_actor+0x29c/0x420
[55649.497411][T515839]  iomap_apply+0x31c/0x14e8
iomap_apply at fs/iomap/apply.c:80 (discriminator 4)
[55649.501860][T515839]  iomap_dio_rw+0x600/0xb60
iomap_dio_rw at fs/iomap/direct-io.c:503
[55649.506312][T515839]  xfs_file_dio_aio_read+0x204/0x7a0
xfs_file_dio_aio_read at fs/xfs/xfs_file.c:186
[55649.511543][T515839]  xfs_file_read_iter+0x3f0/0x628
xfs_file_read_iter at fs/xfs/xfs_file.c:260
[55649.516514][T515839]  new_sync_read+0x300/0x4f0
call_read_iter at include/linux/fs.h:1920 (discriminator 1)
(inlined by) new_sync_read at fs/read_write.c:415 (discriminator 1)
[55649.521051][T515839]  __vfs_read+0x88/0xe8
__vfs_read at fs/read_write.c:431
[55649.525152][T515839]  vfs_read+0xd8/0x228
[55649.529167][T515839]  ksys_pread64+0x110/0x158
[55649.533614][T515839]  __arm64_sys_pread64+0x84/0xc0
[55649.538498][T515839]  do_el0_svc+0x124/0x220
[55649.542771][T515839]  el0_sync_handler+0x260/0x408
[55649.547565][T515839]  el0_sync+0x140/0x180
[55649.551662][T515839] irq event stamp: 257496
[55649.555941][T515839] hardirqs last  enabled at (257495): [<ffffa000107185ec>] free_unref_page_list+0x5ec/0x940
[55649.565951][T515839] hardirqs last disabled at (257496): [<ffffa0001020c154>] do_debug_exception+0x304/0x524
[55649.575783][T515839] softirqs last  enabled at (256808): [<ffffa000101e1b38>] efi_header_end+0xb38/0x1204
[55649.585355][T515839] softirqs last disabled at (256801): [<ffffa000102c046c>] irq_exit+0x2dc/0x3d0

371 static loff_t
372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
373                 void *data, struct iomap *iomap, struct iomap *srcmap)
374 {
375         struct iomap_dio *dio = data;
376
377         switch (iomap->type) {
378         case IOMAP_HOLE:
379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
380                         return -EIO;
381                 return iomap_dio_hole_actor(length, dio);
382         case IOMAP_UNWRITTEN:
383                 if (!(dio->flags & IOMAP_DIO_WRITE))
384                         return iomap_dio_hole_actor(length, dio);
385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
386         case IOMAP_MAPPED:
387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
388         case IOMAP_INLINE:
389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
390         default:
391                 WARN_ON_ONCE(1);
392                 return -EIO;
393         }
394 }

Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
it contains a few pread64() calls until this happens,

[child21:124180] [17] pread64(fd=353, buf=0x0, count=0x59b5, pos=0xe0e0e0e) = -1 (Illegal seek)
[child21:124180] [339] pread64(fd=339, buf=0xffffbcc40000, count=0xbd71, pos=0xff26) = -1 (Illegal seek)
[child21:124627] [136] pread64(fd=69, buf=0xffffbd290000, count=0xee42, pos=2) = -1 (Illegal seek)
[child21:124627] [196] pread64(fd=83, buf=0x1, count=0x62f8, pos=0x15390000) = -1 (Illegal seek)
[child21:125127] [154] pread64(fd=345, buf=0xffffbcc40000, count=9332, pos=0xffbd) = 9332
[child21:125169] [188] pread64(fd=69, buf=0xffffbce90000, count=0x4d47, pos=0) = -1 (Illegal seek)
[child21:125169] [227] pread64(fd=345, buf=0x1, count=0xe469, pos=1046) = -1 (Bad address)
[child21:125569] [354] pread64(fd=87, buf=0xffffbcc50000, count=0x4294, pos=0x16161616) = -1 (Illegal seek)
[child21:125569] [655] pread64(fd=341, buf=0xffffbcc70000, count=2210, pos=0xffff) = -1 (Illegal seek)
[child21:125569] [826] pread64(fd=343, buf=0x8, count=0xeb22, pos=0xc090c202e598b) = 0
[child21:126233] [261] pread64(fd=338, buf=0xffffbcc40000, count=0xe8fe, pos=105) = -1 (Illegal seek)
[child21:126233] [275] pread64(fd=190, buf=0x8, count=0x9c24, pos=116) = -1 (Is a directory)
[child21:126882] [32] pread64(fd=86, buf=0xffffbcc40000, count=0x7fc2, pos=2) = -1 (Illegal seek)
[child21:127448] [14] pread64(fd=214, buf=0x4, count=11371, pos=0x9b26) = 0
[child21:127489] [70] pread64(fd=339, buf=0xffffbcc70000, count=0xb07a, pos=8192) = -1 (Illegal seek)
[child21:127489] [80] pread64(fd=339, buf=0x0, count=6527, pos=205) = -1 (Illegal seek)
[child21:127489] [245] pread64(fd=69, buf=0x8, count=0xbba2, pos=47) = -1 (Illegal seek)
[child21:128098] [334] pread64(fd=353, buf=0xffffbcc90000, count=0x4540, pos=168) = -1 (Illegal seek)
[child21:129079] [157] pread64(fd=422, buf=0x0, count=0x80df, pos=0xdfef6378b650aa) = 0
[child21:134700] [275] pread64(fd=397, buf=0xffffbcc50000, count=0xdee6, pos=0x887b1e74a2) = -1 (Illegal seek)
[child21:135042] [7] pread64(fd=80, buf=0x8, count=0xc494, pos=216) = -1 (Illegal seek)
[child21:135056] [188] pread64(fd=430, buf=0xffffbd090000, count=0xbe66, pos=0x3a3a3a3a) = -1 (Illegal seek)
[child21:135442] [143] pread64(fd=226, buf=0xffffbd390000, count=11558, pos=0x1000002d) = 0
[child21:135513] [275] pread64(fd=69, buf=0x4, count=4659, pos=0x486005206c2986) = -1 (Illegal seek)
[child21:135513] [335] pread64(fd=339, buf=0xffffbd090000, count=0x90fd, pos=253) = -1 (Illegal seek)
[child21:135513] [392] pread64(fd=76, buf=0xffffbcc40000, count=0xf324, pos=0x5d5d5d5d) = -1 (Illegal seek)
[child21:135665] [5] pread64(fd=431, buf=0xffffbcc70000, count=10545, pos=16384) = -1 (Illegal seek)
[child21:135665] [293] pread64(fd=349, buf=0x4, count=0xd2ad, pos=0x2000000) = -1 (Illegal seek)
[child21:135790] [99] pread64(fd=76, buf=0x8, count=0x70d7, pos=0x21000440) = -1 (Illegal seek)
[child21:135790] [149] pread64(fd=70, buf=0xffffbd5b0000, count=0x53f3, pos=255) = -1 (Illegal seek)
[child21:135790] [301] pread64(fd=348, buf=0x4, count=5713, pos=0x6c00401a) = -1 (Illegal seek)
[child21:136162] [570] pread64(fd=435, buf=0x1, count=11182, pos=248) = -1 (Illegal seek)
[child21:136162] [584] pread64(fd=78, buf=0xffffbcc40000, count=0xa401, pos=8192) = -1 (Illegal seek)
[child21:138090] [167] pread64(fd=339, buf=0x4, count=0x6aba, pos=256) = -1 (Illegal seek)
[child21:138090] [203] pread64(fd=348, buf=0xffffbcc90000, count=0x8625, pos=128) = -1 (Illegal seek)
[child21:138551] [174] pread64(fd=426, buf=0x0, count=0xd582, pos=0xd7e8674d0a86) = 0
[child21:138551] [179] pread64(fd=426, buf=0xffffbce90000, count=0x415a, pos=0x536e873600750b2d) = 0
[child21:138988] [306] pread64(fd=436, buf=0x8, count=0x62e6, pos=0x445c403204924c1) = -1 (Illegal seek)
[child21:138988] [353] pread64(fd=427, buf=0x4, count=0x993b, pos=176) = 0

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Matthew Wilcox]

On Fri, Jun 19, 2020 at 05:17:50PM -0400, Qian Cai wrote:
> Running a syscall fuzzer by a normal user could trigger this,
> 
> [55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
...
> 371 static loff_t
> 372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
> 373                 void *data, struct iomap *iomap, struct iomap *srcmap)
> 374 {
> 375         struct iomap_dio *dio = data;
> 376
> 377         switch (iomap->type) {
> 378         case IOMAP_HOLE:
> 379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
> 380                         return -EIO;
> 381                 return iomap_dio_hole_actor(length, dio);
> 382         case IOMAP_UNWRITTEN:
> 383                 if (!(dio->flags & IOMAP_DIO_WRITE))
> 384                         return iomap_dio_hole_actor(length, dio);
> 385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> 386         case IOMAP_MAPPED:
> 387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> 388         case IOMAP_INLINE:
> 389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
> 390         default:
> 391                 WARN_ON_ONCE(1);
> 392                 return -EIO;
> 393         }
> 394 }
> 
> Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
> it contains a few pread64() calls until this happens,

It _shouldn't_ be able to happen.  XFS writes back ranges which exist
in the page cache upon seeing an O_DIRECT I/O.  So it's not supposed to
be possible for there to be an extent which is waiting for the contents
of the page cache to be written back.

> [child21:124180] [17] pread64(fd=353, buf=0x0, count=0x59b5, pos=0xe0e0e0e) = -1 (Illegal seek)
> [child21:124180] [339] pread64(fd=339, buf=0xffffbcc40000, count=0xbd71, pos=0xff26) = -1 (Illegal seek)
> [child21:124627] [136] pread64(fd=69, buf=0xffffbd290000, count=0xee42, pos=2) = -1 (Illegal seek)
> [child21:124627] [196] pread64(fd=83, buf=0x1, count=0x62f8, pos=0x15390000) = -1 (Illegal seek)
> [child21:125127] [154] pread64(fd=345, buf=0xffffbcc40000, count=9332, pos=0xffbd) = 9332
> [child21:125169] [188] pread64(fd=69, buf=0xffffbce90000, count=0x4d47, pos=0) = -1 (Illegal seek)
> [child21:125169] [227] pread64(fd=345, buf=0x1, count=0xe469, pos=1046) = -1 (Bad address)
> [child21:125569] [354] pread64(fd=87, buf=0xffffbcc50000, count=0x4294, pos=0x16161616) = -1 (Illegal seek)
> [child21:125569] [655] pread64(fd=341, buf=0xffffbcc70000, count=2210, pos=0xffff) = -1 (Illegal seek)
> [child21:125569] [826] pread64(fd=343, buf=0x8, count=0xeb22, pos=0xc090c202e598b) = 0
> [child21:126233] [261] pread64(fd=338, buf=0xffffbcc40000, count=0xe8fe, pos=105) = -1 (Illegal seek)
> [child21:126233] [275] pread64(fd=190, buf=0x8, count=0x9c24, pos=116) = -1 (Is a directory)
> [child21:126882] [32] pread64(fd=86, buf=0xffffbcc40000, count=0x7fc2, pos=2) = -1 (Illegal seek)
> [child21:127448] [14] pread64(fd=214, buf=0x4, count=11371, pos=0x9b26) = 0
> [child21:127489] [70] pread64(fd=339, buf=0xffffbcc70000, count=0xb07a, pos=8192) = -1 (Illegal seek)
> [child21:127489] [80] pread64(fd=339, buf=0x0, count=6527, pos=205) = -1 (Illegal seek)
> [child21:127489] [245] pread64(fd=69, buf=0x8, count=0xbba2, pos=47) = -1 (Illegal seek)
> [child21:128098] [334] pread64(fd=353, buf=0xffffbcc90000, count=0x4540, pos=168) = -1 (Illegal seek)
> [child21:129079] [157] pread64(fd=422, buf=0x0, count=0x80df, pos=0xdfef6378b650aa) = 0
> [child21:134700] [275] pread64(fd=397, buf=0xffffbcc50000, count=0xdee6, pos=0x887b1e74a2) = -1 (Illegal seek)
> [child21:135042] [7] pread64(fd=80, buf=0x8, count=0xc494, pos=216) = -1 (Illegal seek)
> [child21:135056] [188] pread64(fd=430, buf=0xffffbd090000, count=0xbe66, pos=0x3a3a3a3a) = -1 (Illegal seek)
> [child21:135442] [143] pread64(fd=226, buf=0xffffbd390000, count=11558, pos=0x1000002d) = 0
> [child21:135513] [275] pread64(fd=69, buf=0x4, count=4659, pos=0x486005206c2986) = -1 (Illegal seek)
> [child21:135513] [335] pread64(fd=339, buf=0xffffbd090000, count=0x90fd, pos=253) = -1 (Illegal seek)
> [child21:135513] [392] pread64(fd=76, buf=0xffffbcc40000, count=0xf324, pos=0x5d5d5d5d) = -1 (Illegal seek)
> [child21:135665] [5] pread64(fd=431, buf=0xffffbcc70000, count=10545, pos=16384) = -1 (Illegal seek)
> [child21:135665] [293] pread64(fd=349, buf=0x4, count=0xd2ad, pos=0x2000000) = -1 (Illegal seek)
> [child21:135790] [99] pread64(fd=76, buf=0x8, count=0x70d7, pos=0x21000440) = -1 (Illegal seek)
> [child21:135790] [149] pread64(fd=70, buf=0xffffbd5b0000, count=0x53f3, pos=255) = -1 (Illegal seek)
> [child21:135790] [301] pread64(fd=348, buf=0x4, count=5713, pos=0x6c00401a) = -1 (Illegal seek)
> [child21:136162] [570] pread64(fd=435, buf=0x1, count=11182, pos=248) = -1 (Illegal seek)
> [child21:136162] [584] pread64(fd=78, buf=0xffffbcc40000, count=0xa401, pos=8192) = -1 (Illegal seek)
> [child21:138090] [167] pread64(fd=339, buf=0x4, count=0x6aba, pos=256) = -1 (Illegal seek)
> [child21:138090] [203] pread64(fd=348, buf=0xffffbcc90000, count=0x8625, pos=128) = -1 (Illegal seek)
> [child21:138551] [174] pread64(fd=426, buf=0x0, count=0xd582, pos=0xd7e8674d0a86) = 0
> [child21:138551] [179] pread64(fd=426, buf=0xffffbce90000, count=0x415a, pos=0x536e873600750b2d) = 0
> [child21:138988] [306] pread64(fd=436, buf=0x8, count=0x62e6, pos=0x445c403204924c1) = -1 (Illegal seek)
> [child21:138988] [353] pread64(fd=427, buf=0x4, count=0x993b, pos=176) = 0

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Qian Cai]

On Fri, Jun 19, 2020 at 05:17:47PM -0700, Matthew Wilcox wrote:
> On Fri, Jun 19, 2020 at 05:17:50PM -0400, Qian Cai wrote:
> > Running a syscall fuzzer by a normal user could trigger this,
> > 
> > [55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
> ...
> > 371 static loff_t
> > 372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
> > 373                 void *data, struct iomap *iomap, struct iomap *srcmap)
> > 374 {
> > 375         struct iomap_dio *dio = data;
> > 376
> > 377         switch (iomap->type) {
> > 378         case IOMAP_HOLE:
> > 379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
> > 380                         return -EIO;
> > 381                 return iomap_dio_hole_actor(length, dio);
> > 382         case IOMAP_UNWRITTEN:
> > 383                 if (!(dio->flags & IOMAP_DIO_WRITE))
> > 384                         return iomap_dio_hole_actor(length, dio);
> > 385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > 386         case IOMAP_MAPPED:
> > 387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > 388         case IOMAP_INLINE:
> > 389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
> > 390         default:
> > 391                 WARN_ON_ONCE(1);
> > 392                 return -EIO;
> > 393         }
> > 394 }
> > 
> > Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
> > it contains a few pread64() calls until this happens,
> 
> It _shouldn't_ be able to happen.  XFS writes back ranges which exist
> in the page cache upon seeing an O_DIRECT I/O.  So it's not supposed to
> be possible for there to be an extent which is waiting for the contents
> of the page cache to be written back.

BTW, this is rather easy to reproduce where it happens on x86 as well.

[ 1248.397398] Page cache invalidation failure on direct I/O.  Possible data corruption due to collision with buffered I/O!
[ 1248.418261] flags: 0xbfffc000010200(slab|head)
[ 1248.473270] File: /tmp/trinity-testfile2 (deleted) PID: 18127 Comm: trinity-c33
[ 1248.475128] ------------[ cut here ]------------
[ 1248.475130] WARNING: CPU: 54 PID: 18127 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x319/0x480
[ 1248.475131] Modules linked in: nls_ascii nls_cp437 vfat fat kvm_intel kvm irqbypass efivars efivarfs ip_tables x_tables sd_mod hpsa scsi_transport_sas be2net firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 1248.475150] CPU: 54 PID: 18127 Comm: trinity-c33 Not tainted 5.8.0-rc1-next-20200618 #1
[ 1248.475151] Hardware name: HP ProLiant BL460c Gen9, BIOS I36 01/22/2018
[ 1248.475152] RIP: 0010:iomap_dio_actor+0x319/0x480
[ 1248.475154] Code: 24 f6 43 27 40 0f 84 62 ff ff ff 48 83 c4 20 48 89 d9 48 89 ea 4c 89 e6 5b 4c 89 ff 5d 41 5c 41 5d 41 5e 41 5f e9 f7 ee ff ff <0f> 0b 48 83 c4 20 48 c7 c0 fb ff ff ff 5b 5d 41 5c 41 5d 41 5e 41
[ 1248.475156] RSP: 0018:ffffc9003041f6f8 EFLAGS: 00010202
[ 1248.475158] RAX: 0000000000000001 RBX: ffff888c5e4bdd00 RCX: ffff888c5e4bdd00
[ 1248.475159] RDX: 1ffff92006083ef9 RSI: 00000000001ff000 RDI: ffffc9003041f7c8
[ 1248.475160] RBP: 0000000000001000 R08: ffffc9003041f7b0 R09: ffffc9003041f7b0
[ 1248.475162] R10: ffff888c678b2e1b R11: ffffed118cf165c3 R12: 00000000001ff000
[ 1248.475163] R13: 00000000001ff000 R14: ffff888c4ded4f08 R15: ffff888c4ded4f08
[ 1248.475164] FS:  00007f34c3897740(0000) GS:ffff888c67880000(0000) knlGS:0000000000000000
[ 1248.475165] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1248.475166] CR2: 00007f34c13ff000 CR3: 0000000abd5c0004 CR4: 00000000001606e0
[ 1248.475167] Call Trace:
[ 1248.475168]  iomap_apply+0x258/0xb02
[ 1248.475169]  ? iomap_dio_bio_actor+0xdf0/0xdf0
[ 1248.475170]  ? trace_event_raw_event_iomap_apply+0x420/0x420
[ 1248.475171]  ? generic_write_checks+0x320/0x320
[ 1248.475172]  ? ___ratelimit+0x1c6/0x400
[ 1248.475173]  iomap_dio_rw+0x7ac/0xfe0
[ 1248.475174]  ? iomap_dio_bio_actor+0xdf0/0xdf0
[ 1248.475176]  ? iomap_dio_complete+0x710/0x710
[ 1248.475177]  ? down_read_nested+0x114/0x430
[ 1248.475179]  ? downgrade_write+0x3a0/0x3a0
[ 1248.475181]  ? rcu_read_lock_sched_held+0xaa/0xd0
[ 1248.475183]  ? xfs_file_dio_aio_read+0x1d5/0x4c0
[ 1248.475185]  xfs_file_dio_aio_read+0x1d5/0x4c0
[ 1248.475186]  ? lock_downgrade+0x720/0x720
[ 1248.475188]  xfs_file_read_iter+0x3e3/0x6b0
[ 1248.475190]  do_iter_readv_writev+0x472/0x6e0
[ 1248.475192]  ? default_llseek+0x240/0x240
[ 1248.475194]  ? _copy_from_user+0xbe/0x100
[ 1248.475196]  ? lock_acquire+0x1ac/0xaf0
[ 1248.475197]  ? __fdget_pos+0x9c/0xb0
[ 1248.475199]  do_iter_read+0x1eb/0x5a0
[ 1248.475201]  vfs_readv+0xc7/0x130
[ 1248.475203]  ? __mutex_lock+0x4aa/0x1390
[ 1248.475205]  ? rw_copy_check_uvector+0x380/0x380
[ 1248.475206]  ? __fdget_pos+0x9c/0xb0
[ 1248.475208]  ? find_held_lock+0x33/0x1c0
[ 1248.475210]  ? __task_pid_nr_ns+0x1d1/0x3f0
[ 1248.475212]  do_readv+0xfb/0x1e0
[ 1248.475213]  ? vfs_readv+0x130/0x130
[ 1248.475216]  ? lockdep_hardirqs_on_prepare+0x38c/0x550
[ 1248.475217]  ? do_syscall_64+0x24/0x310
[ 1248.475219]  do_syscall_64+0x5f/0x310
[ 1248.475221]  ? asm_exc_page_fault+0x8/0x30
[ 1248.475223]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1248.475225] RIP: 0033:0x7f34c31aa6ed
[ 1248.475226] Code: Bad RIP value.
[ 1248.475228] RSP: 002b:00007ffc2c0bc698 EFLAGS: 00000246 ORIG_RAX: 0000000000000013
[ 1248.475230] RAX: ffffffffffffffda RBX: 0000000000000013 RCX: 00007f34c31aa6ed
[ 1248.475232] RDX: 000000000000008c RSI: 00000000038113c0 RDI: 00000000000001b3
[ 1248.475233] RBP: 0000000000000013 R08: 0000000000010000 R09: fffffffffffffff6
[ 1248.475234] R10: 0000020010120040 R11: 0000000000000246 R12: 0000000000000002
[ 1248.475236] R13: 00007f34c37b0058 R14: 00007f34c38976c0 R15: 00007f34c37b0000
[ 1248.475237] irq event stamp: 191529
[ 1248.475238] hardirqs last  enabled at (191529): [<ffffffff98800ace>] asm_exc_page_fault+0x1e/0x30
[ 1248.475239] hardirqs last disabled at (191528): [<ffffffff98779f6d>] exc_page_fault+0x5dd/0xe90
[ 1248.475241] softirqs last  enabled at (189658): [<ffffffff98a007c2>] __do_softirq+0x7c2/0xb70
[ 1248.475242] softirqs last disabled at (189651): [<ffffffff98800f02>] asm_call_on_stack+0x12/0x20

> 
> > [child21:124180] [17] pread64(fd=353, buf=0x0, count=0x59b5, pos=0xe0e0e0e) = -1 (Illegal seek)
> > [child21:124180] [339] pread64(fd=339, buf=0xffffbcc40000, count=0xbd71, pos=0xff26) = -1 (Illegal seek)
> > [child21:124627] [136] pread64(fd=69, buf=0xffffbd290000, count=0xee42, pos=2) = -1 (Illegal seek)
> > [child21:124627] [196] pread64(fd=83, buf=0x1, count=0x62f8, pos=0x15390000) = -1 (Illegal seek)
> > [child21:125127] [154] pread64(fd=345, buf=0xffffbcc40000, count=9332, pos=0xffbd) = 9332
> > [child21:125169] [188] pread64(fd=69, buf=0xffffbce90000, count=0x4d47, pos=0) = -1 (Illegal seek)
> > [child21:125169] [227] pread64(fd=345, buf=0x1, count=0xe469, pos=1046) = -1 (Bad address)
> > [child21:125569] [354] pread64(fd=87, buf=0xffffbcc50000, count=0x4294, pos=0x16161616) = -1 (Illegal seek)
> > [child21:125569] [655] pread64(fd=341, buf=0xffffbcc70000, count=2210, pos=0xffff) = -1 (Illegal seek)
> > [child21:125569] [826] pread64(fd=343, buf=0x8, count=0xeb22, pos=0xc090c202e598b) = 0
> > [child21:126233] [261] pread64(fd=338, buf=0xffffbcc40000, count=0xe8fe, pos=105) = -1 (Illegal seek)
> > [child21:126233] [275] pread64(fd=190, buf=0x8, count=0x9c24, pos=116) = -1 (Is a directory)
> > [child21:126882] [32] pread64(fd=86, buf=0xffffbcc40000, count=0x7fc2, pos=2) = -1 (Illegal seek)
> > [child21:127448] [14] pread64(fd=214, buf=0x4, count=11371, pos=0x9b26) = 0
> > [child21:127489] [70] pread64(fd=339, buf=0xffffbcc70000, count=0xb07a, pos=8192) = -1 (Illegal seek)
> > [child21:127489] [80] pread64(fd=339, buf=0x0, count=6527, pos=205) = -1 (Illegal seek)
> > [child21:127489] [245] pread64(fd=69, buf=0x8, count=0xbba2, pos=47) = -1 (Illegal seek)
> > [child21:128098] [334] pread64(fd=353, buf=0xffffbcc90000, count=0x4540, pos=168) = -1 (Illegal seek)
> > [child21:129079] [157] pread64(fd=422, buf=0x0, count=0x80df, pos=0xdfef6378b650aa) = 0
> > [child21:134700] [275] pread64(fd=397, buf=0xffffbcc50000, count=0xdee6, pos=0x887b1e74a2) = -1 (Illegal seek)
> > [child21:135042] [7] pread64(fd=80, buf=0x8, count=0xc494, pos=216) = -1 (Illegal seek)
> > [child21:135056] [188] pread64(fd=430, buf=0xffffbd090000, count=0xbe66, pos=0x3a3a3a3a) = -1 (Illegal seek)
> > [child21:135442] [143] pread64(fd=226, buf=0xffffbd390000, count=11558, pos=0x1000002d) = 0
> > [child21:135513] [275] pread64(fd=69, buf=0x4, count=4659, pos=0x486005206c2986) = -1 (Illegal seek)
> > [child21:135513] [335] pread64(fd=339, buf=0xffffbd090000, count=0x90fd, pos=253) = -1 (Illegal seek)
> > [child21:135513] [392] pread64(fd=76, buf=0xffffbcc40000, count=0xf324, pos=0x5d5d5d5d) = -1 (Illegal seek)
> > [child21:135665] [5] pread64(fd=431, buf=0xffffbcc70000, count=10545, pos=16384) = -1 (Illegal seek)
> > [child21:135665] [293] pread64(fd=349, buf=0x4, count=0xd2ad, pos=0x2000000) = -1 (Illegal seek)
> > [child21:135790] [99] pread64(fd=76, buf=0x8, count=0x70d7, pos=0x21000440) = -1 (Illegal seek)
> > [child21:135790] [149] pread64(fd=70, buf=0xffffbd5b0000, count=0x53f3, pos=255) = -1 (Illegal seek)
> > [child21:135790] [301] pread64(fd=348, buf=0x4, count=5713, pos=0x6c00401a) = -1 (Illegal seek)
> > [child21:136162] [570] pread64(fd=435, buf=0x1, count=11182, pos=248) = -1 (Illegal seek)
> > [child21:136162] [584] pread64(fd=78, buf=0xffffbcc40000, count=0xa401, pos=8192) = -1 (Illegal seek)
> > [child21:138090] [167] pread64(fd=339, buf=0x4, count=0x6aba, pos=256) = -1 (Illegal seek)
> > [child21:138090] [203] pread64(fd=348, buf=0xffffbcc90000, count=0x8625, pos=128) = -1 (Illegal seek)
> > [child21:138551] [174] pread64(fd=426, buf=0x0, count=0xd582, pos=0xd7e8674d0a86) = 0
> > [child21:138551] [179] pread64(fd=426, buf=0xffffbce90000, count=0x415a, pos=0x536e873600750b2d) = 0
> > [child21:138988] [306] pread64(fd=436, buf=0x8, count=0x62e6, pos=0x445c403204924c1) = -1 (Illegal seek)
> > [child21:138988] [353] pread64(fd=427, buf=0x4, count=0x993b, pos=176) = 0

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Qian Cai]

On Fri, Jun 19, 2020 at 05:17:47PM -0700, Matthew Wilcox wrote:
> On Fri, Jun 19, 2020 at 05:17:50PM -0400, Qian Cai wrote:
> > Running a syscall fuzzer by a normal user could trigger this,
> > 
> > [55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
> ...
> > 371 static loff_t
> > 372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
> > 373                 void *data, struct iomap *iomap, struct iomap *srcmap)
> > 374 {
> > 375         struct iomap_dio *dio = data;
> > 376
> > 377         switch (iomap->type) {
> > 378         case IOMAP_HOLE:
> > 379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
> > 380                         return -EIO;
> > 381                 return iomap_dio_hole_actor(length, dio);
> > 382         case IOMAP_UNWRITTEN:
> > 383                 if (!(dio->flags & IOMAP_DIO_WRITE))
> > 384                         return iomap_dio_hole_actor(length, dio);
> > 385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > 386         case IOMAP_MAPPED:
> > 387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > 388         case IOMAP_INLINE:
> > 389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
> > 390         default:
> > 391                 WARN_ON_ONCE(1);
> > 392                 return -EIO;
> > 393         }
> > 394 }
> > 
> > Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
> > it contains a few pread64() calls until this happens,
> 
> It _shouldn't_ be able to happen.  XFS writes back ranges which exist
> in the page cache upon seeing an O_DIRECT I/O.  So it's not supposed to
> be possible for there to be an extent which is waiting for the contents
> of the page cache to be written back.

Okay, it is IOMAP_DELALLOC. We have,

[11746.454628][T431855] Page cache invalidation failure on direct I/O.  Possible data corruption due to collision with buffered I/O!
[11746.466345][T431855] File: /tmp/trinity-testfile2 (deleted) PID: 431855 Comm: trinity-c54
[11746.474608][T431855] iomap->type = 1, iomap->flags = 2, iomap->length = 2031616

I noticed the commit 5a9d929d6e13 ("iomap: report collisions between directio
and buffered writes to userspace") started to convert those WARN_ON_ONCE() to
dio_warn_stale_pagecache() indicating that those to be triggered by userspace
programs, so this looks like just another missing place to convert? Apparently,
we don't want non-root users to be able to trigger this warning and kernel
tainted. This?

diff --git a/fs/iomap/direct-io.c b/fs/iomap/direct-io.c
index ec7b78e6feca..7f49292df420 100644
--- a/fs/iomap/direct-io.c
+++ b/fs/iomap/direct-io.c
@@ -388,7 +388,7 @@ iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
        case IOMAP_INLINE:
                return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
        default:
-               WARN_ON_ONCE(1);
+               dio_warn_stale_pagecache(dio->iocb->ki_filp);
                return -EIO;
        }
 }

> 
> > [child21:124180] [17] pread64(fd=353, buf=0x0, count=0x59b5, pos=0xe0e0e0e) = -1 (Illegal seek)
> > [child21:124180] [339] pread64(fd=339, buf=0xffffbcc40000, count=0xbd71, pos=0xff26) = -1 (Illegal seek)
> > [child21:124627] [136] pread64(fd=69, buf=0xffffbd290000, count=0xee42, pos=2) = -1 (Illegal seek)
> > [child21:124627] [196] pread64(fd=83, buf=0x1, count=0x62f8, pos=0x15390000) = -1 (Illegal seek)
> > [child21:125127] [154] pread64(fd=345, buf=0xffffbcc40000, count=9332, pos=0xffbd) = 9332
> > [child21:125169] [188] pread64(fd=69, buf=0xffffbce90000, count=0x4d47, pos=0) = -1 (Illegal seek)
> > [child21:125169] [227] pread64(fd=345, buf=0x1, count=0xe469, pos=1046) = -1 (Bad address)
> > [child21:125569] [354] pread64(fd=87, buf=0xffffbcc50000, count=0x4294, pos=0x16161616) = -1 (Illegal seek)
> > [child21:125569] [655] pread64(fd=341, buf=0xffffbcc70000, count=2210, pos=0xffff) = -1 (Illegal seek)
> > [child21:125569] [826] pread64(fd=343, buf=0x8, count=0xeb22, pos=0xc090c202e598b) = 0
> > [child21:126233] [261] pread64(fd=338, buf=0xffffbcc40000, count=0xe8fe, pos=105) = -1 (Illegal seek)
> > [child21:126233] [275] pread64(fd=190, buf=0x8, count=0x9c24, pos=116) = -1 (Is a directory)
> > [child21:126882] [32] pread64(fd=86, buf=0xffffbcc40000, count=0x7fc2, pos=2) = -1 (Illegal seek)
> > [child21:127448] [14] pread64(fd=214, buf=0x4, count=11371, pos=0x9b26) = 0
> > [child21:127489] [70] pread64(fd=339, buf=0xffffbcc70000, count=0xb07a, pos=8192) = -1 (Illegal seek)
> > [child21:127489] [80] pread64(fd=339, buf=0x0, count=6527, pos=205) = -1 (Illegal seek)
> > [child21:127489] [245] pread64(fd=69, buf=0x8, count=0xbba2, pos=47) = -1 (Illegal seek)
> > [child21:128098] [334] pread64(fd=353, buf=0xffffbcc90000, count=0x4540, pos=168) = -1 (Illegal seek)
> > [child21:129079] [157] pread64(fd=422, buf=0x0, count=0x80df, pos=0xdfef6378b650aa) = 0
> > [child21:134700] [275] pread64(fd=397, buf=0xffffbcc50000, count=0xdee6, pos=0x887b1e74a2) = -1 (Illegal seek)
> > [child21:135042] [7] pread64(fd=80, buf=0x8, count=0xc494, pos=216) = -1 (Illegal seek)
> > [child21:135056] [188] pread64(fd=430, buf=0xffffbd090000, count=0xbe66, pos=0x3a3a3a3a) = -1 (Illegal seek)
> > [child21:135442] [143] pread64(fd=226, buf=0xffffbd390000, count=11558, pos=0x1000002d) = 0
> > [child21:135513] [275] pread64(fd=69, buf=0x4, count=4659, pos=0x486005206c2986) = -1 (Illegal seek)
> > [child21:135513] [335] pread64(fd=339, buf=0xffffbd090000, count=0x90fd, pos=253) = -1 (Illegal seek)
> > [child21:135513] [392] pread64(fd=76, buf=0xffffbcc40000, count=0xf324, pos=0x5d5d5d5d) = -1 (Illegal seek)
> > [child21:135665] [5] pread64(fd=431, buf=0xffffbcc70000, count=10545, pos=16384) = -1 (Illegal seek)
> > [child21:135665] [293] pread64(fd=349, buf=0x4, count=0xd2ad, pos=0x2000000) = -1 (Illegal seek)
> > [child21:135790] [99] pread64(fd=76, buf=0x8, count=0x70d7, pos=0x21000440) = -1 (Illegal seek)
> > [child21:135790] [149] pread64(fd=70, buf=0xffffbd5b0000, count=0x53f3, pos=255) = -1 (Illegal seek)
> > [child21:135790] [301] pread64(fd=348, buf=0x4, count=5713, pos=0x6c00401a) = -1 (Illegal seek)
> > [child21:136162] [570] pread64(fd=435, buf=0x1, count=11182, pos=248) = -1 (Illegal seek)
> > [child21:136162] [584] pread64(fd=78, buf=0xffffbcc40000, count=0xa401, pos=8192) = -1 (Illegal seek)
> > [child21:138090] [167] pread64(fd=339, buf=0x4, count=0x6aba, pos=256) = -1 (Illegal seek)
> > [child21:138090] [203] pread64(fd=348, buf=0xffffbcc90000, count=0x8625, pos=128) = -1 (Illegal seek)
> > [child21:138551] [174] pread64(fd=426, buf=0x0, count=0xd582, pos=0xd7e8674d0a86) = 0
> > [child21:138551] [179] pread64(fd=426, buf=0xffffbce90000, count=0x415a, pos=0x536e873600750b2d) = 0
> > [child21:138988] [306] pread64(fd=436, buf=0x8, count=0x62e6, pos=0x445c403204924c1) = -1 (Illegal seek)
> > [child21:138988] [353] pread64(fd=427, buf=0x4, count=0x993b, pos=176) = 0

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Christoph Hellwig]

On Fri, Jul 24, 2020 at 02:24:32PM -0400, Qian Cai wrote:
> On Fri, Jun 19, 2020 at 05:17:47PM -0700, Matthew Wilcox wrote:
> > On Fri, Jun 19, 2020 at 05:17:50PM -0400, Qian Cai wrote:
> > > Running a syscall fuzzer by a normal user could trigger this,
> > > 
> > > [55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
> > ...
> > > 371 static loff_t
> > > 372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
> > > 373                 void *data, struct iomap *iomap, struct iomap *srcmap)
> > > 374 {
> > > 375         struct iomap_dio *dio = data;
> > > 376
> > > 377         switch (iomap->type) {
> > > 378         case IOMAP_HOLE:
> > > 379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
> > > 380                         return -EIO;
> > > 381                 return iomap_dio_hole_actor(length, dio);
> > > 382         case IOMAP_UNWRITTEN:
> > > 383                 if (!(dio->flags & IOMAP_DIO_WRITE))
> > > 384                         return iomap_dio_hole_actor(length, dio);
> > > 385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > 386         case IOMAP_MAPPED:
> > > 387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > 388         case IOMAP_INLINE:
> > > 389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
> > > 390         default:
> > > 391                 WARN_ON_ONCE(1);
> > > 392                 return -EIO;
> > > 393         }
> > > 394 }
> > > 
> > > Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
> > > it contains a few pread64() calls until this happens,
> > 
> > It _shouldn't_ be able to happen.  XFS writes back ranges which exist
> > in the page cache upon seeing an O_DIRECT I/O.  So it's not supposed to
> > be possible for there to be an extent which is waiting for the contents
> > of the page cache to be written back.
> 
> Okay, it is IOMAP_DELALLOC. We have,

Can you share the fuzzer?  If we end up with delalloc space here we
probably need to fix a bug in the cache invalidation code.

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Qian Cai]

On Sun, Jul 26, 2020 at 04:24:12PM +0100, Christoph Hellwig wrote:
> On Fri, Jul 24, 2020 at 02:24:32PM -0400, Qian Cai wrote:
> > On Fri, Jun 19, 2020 at 05:17:47PM -0700, Matthew Wilcox wrote:
> > > On Fri, Jun 19, 2020 at 05:17:50PM -0400, Qian Cai wrote:
> > > > Running a syscall fuzzer by a normal user could trigger this,
> > > > 
> > > > [55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
> > > ...
> > > > 371 static loff_t
> > > > 372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
> > > > 373                 void *data, struct iomap *iomap, struct iomap *srcmap)
> > > > 374 {
> > > > 375         struct iomap_dio *dio = data;
> > > > 376
> > > > 377         switch (iomap->type) {
> > > > 378         case IOMAP_HOLE:
> > > > 379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
> > > > 380                         return -EIO;
> > > > 381                 return iomap_dio_hole_actor(length, dio);
> > > > 382         case IOMAP_UNWRITTEN:
> > > > 383                 if (!(dio->flags & IOMAP_DIO_WRITE))
> > > > 384                         return iomap_dio_hole_actor(length, dio);
> > > > 385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > > 386         case IOMAP_MAPPED:
> > > > 387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > > 388         case IOMAP_INLINE:
> > > > 389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
> > > > 390         default:
> > > > 391                 WARN_ON_ONCE(1);
> > > > 392                 return -EIO;
> > > > 393         }
> > > > 394 }
> > > > 
> > > > Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
> > > > it contains a few pread64() calls until this happens,
> > > 
> > > It _shouldn't_ be able to happen.  XFS writes back ranges which exist
> > > in the page cache upon seeing an O_DIRECT I/O.  So it's not supposed to
> > > be possible for there to be an extent which is waiting for the contents
> > > of the page cache to be written back.
> > 
> > Okay, it is IOMAP_DELALLOC. We have,
> 
> Can you share the fuzzer?  If we end up with delalloc space here we
> probably need to fix a bug in the cache invalidation code.

This is just a wrapper of the trinity fuzzer.

# git clone https://gitlab.com/cailca/linux-mm
# cd linux-mm; make
# ./random -x 0-100 -f

https://gitlab.com/cailca/linux-mm/-/blob/master/random.c#L1383

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Qian Cai]

On Sun, Jul 26, 2020 at 04:24:12PM +0100, Christoph Hellwig wrote:
> On Fri, Jul 24, 2020 at 02:24:32PM -0400, Qian Cai wrote:
> > On Fri, Jun 19, 2020 at 05:17:47PM -0700, Matthew Wilcox wrote:
> > > On Fri, Jun 19, 2020 at 05:17:50PM -0400, Qian Cai wrote:
> > > > Running a syscall fuzzer by a normal user could trigger this,
> > > > 
> > > > [55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
> > > ...
> > > > 371 static loff_t
> > > > 372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
> > > > 373                 void *data, struct iomap *iomap, struct iomap *srcmap)
> > > > 374 {
> > > > 375         struct iomap_dio *dio = data;
> > > > 376
> > > > 377         switch (iomap->type) {
> > > > 378         case IOMAP_HOLE:
> > > > 379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
> > > > 380                         return -EIO;
> > > > 381                 return iomap_dio_hole_actor(length, dio);
> > > > 382         case IOMAP_UNWRITTEN:
> > > > 383                 if (!(dio->flags & IOMAP_DIO_WRITE))
> > > > 384                         return iomap_dio_hole_actor(length, dio);
> > > > 385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > > 386         case IOMAP_MAPPED:
> > > > 387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > > 388         case IOMAP_INLINE:
> > > > 389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
> > > > 390         default:
> > > > 391                 WARN_ON_ONCE(1);
> > > > 392                 return -EIO;
> > > > 393         }
> > > > 394 }
> > > > 
> > > > Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
> > > > it contains a few pread64() calls until this happens,
> > > 
> > > It _shouldn't_ be able to happen.  XFS writes back ranges which exist
> > > in the page cache upon seeing an O_DIRECT I/O.  So it's not supposed to
> > > be possible for there to be an extent which is waiting for the contents
> > > of the page cache to be written back.
> > 
> > Okay, it is IOMAP_DELALLOC. We have,
> 
> Can you share the fuzzer?  If we end up with delalloc space here we
> probably need to fix a bug in the cache invalidation code.

Here is a simple reproducer (I believe it can also be reproduced using xfstests
generic/503 on a plain xfs without DAX when SCRATCH_MNT == TEST_DIR),

# git clone https://gitlab.com/cailca/linux-mm
# cd linux-mm; make
# ./random 14
- start: mmap_collision
wrote 20480/20480 bytes at offset 0
20 KiB, 5 ops; 0.0000 sec (673.491 MiB/sec and 172413.7931 ops/sec)
wrote 20480/20480 bytes at offset 0
20 KiB, 5 ops; 0.0000 sec (697.545 MiB/sec and 178571.4286 ops/sec)
wrote 20480/20480 bytes at offset 0
20 KiB, 5 ops; 0.0000 sec (723.380 MiB/sec and 185185.1852 ops/sec)
pread: Input/output error

[ 8944.905010][ T6995] ------------[ cut here ]------------
[ 8944.911193][ T6995] WARNING: CPU: 4 PID: 6995 at fs/iomap/direct-io.c:392 iomap_dio_actor+0x319/0x480
[ 8944.920498][ T6995] Modules linked in: nls_ascii nls_cp437 vfat fat kvm_amd ses enclosure kvm irqbypass efivars acpi_cpufreq efivarfs ip_tables x_tables sd_mod smartpqi scsi_transport_sas tg3 mlx5_core libphy firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 8944.943950][ T6995] CPU: 4 PID: 6995 Comm: random Not tainted 5.8.0-next-20200810+ #2
[ 8944.951855][ T6995] Hardware name: HPE ProLiant DL385 Gen10/ProLiant DL385 Gen10, BIOS A40 07/10/2019
[ 8944.961162][ T6995] RIP: 0010:iomap_dio_actor+0x319/0x480
[ 8944.966622][ T6995] Code: 24 f6 43 27 40 0f 84 62 ff ff ff 48 83 c4 20 48 89 d9 48 89 ea 4c 89 e6 5b 4c 89 ff 5d 41 5c 41 5d 41 5e 41 5f e9 07 ef ff ff <0f> 0b 48 83 c4 20 48 c7 c0 fb ff ff ff 5b 5d 41 5c 41 5d 41 5e 41
[ 8944.986232][ T6995] RSP: 0018:ffffc90007d1f8d0 EFLAGS: 00010202
[ 8944.992203][ T6995] RAX: 0000000000000001 RBX: ffff88861b681c00 RCX: ffff88861b681c00
[ 8945.000105][ T6995] RDX: 1ffff92000fa3f33 RSI: 0000000000000000 RDI: ffffc90007d1f998
[ 8945.008014][ T6995] RBP: 0000000000001000 R08: ffffc90007d1f980 R09: ffffc90007d1f980
[ 8945.015920][ T6995] R10: ffffffffa72e72a7 R11: fffffbfff4e5ce54 R12: 0000000000000000
[ 8945.023805][ T6995] R13: ffff8888060e1388 R14: ffffffffa1f2e080 R15: ffff8888060e1388
[ 8945.031705][ T6995] FS:  00007fa50e389700(0000) GS:ffff88905ec00000(0000) knlGS:0000000000000000
[ 8945.040562][ T6995] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 8945.047063][ T6995] CR2: 00007fa50eb93000 CR3: 00000005ad9f2000 CR4: 00000000003506e0
[ 8945.054952][ T6995] Call Trace:
[ 8945.058147][ T6995]  iomap_apply+0x25a/0xb73
[ 8945.062453][ T6995]  ? iomap_dio_bio_actor+0xde0/0xde0
[ 8945.067650][ T6995]  ? generic_perform_write+0x410/0x410
[ 8945.073003][ T6995]  ? trace_event_raw_event_iomap_apply+0x420/0x420
[ 8945.079424][ T6995]  ? filemap_check_errors+0x51/0xe0
[ 8945.084514][ T6995]  iomap_dio_rw+0x644/0x1298
[ 8945.089011][ T6995]  ? iomap_dio_bio_actor+0xde0/0xde0
[ 8945.094192][ T6995]  ? iomap_dio_bio_end_io+0x4a0/0x4a0
[ 8945.099474][ T6995]  ? down_read_nested+0x10e/0x430
[ 8945.104391][ T6995]  ? downgrade_write+0x3a0/0x3a0
[ 8945.109237][ T6995]  ? rcu_read_lock_sched_held+0xaa/0xd0
[ 8945.114680][ T6995]  ? xfs_file_dio_aio_read+0x1d5/0x4c0
[ 8945.120051][ T6995]  xfs_file_dio_aio_read+0x1d5/0x4c0
[ 8945.125253][ T6995]  xfs_file_read_iter+0x3e3/0x6b0
[ 8945.130173][ T6995]  new_sync_read+0x39b/0x600
[ 8945.134648][ T6995]  ? vfs_dedupe_file_range+0x5f0/0x5f0
[ 8945.140022][ T6995]  ? __fget_files+0x1cb/0x300
[ 8945.144588][ T6995]  ? lock_downgrade+0x730/0x730
[ 8945.149346][ T6995]  ? rcu_read_lock_held+0xaa/0xc0
[ 8945.154265][ T6995]  vfs_read+0x226/0x450
[ 8945.158323][ T6995]  ksys_pread64+0x116/0x140
[ 8945.162714][ T6995]  ? __x64_sys_write+0xa0/0xa0
[ 8945.167386][ T6995]  ? syscall_enter_from_user_mode+0x20/0x210
[ 8945.173269][ T6995]  ? trace_hardirqs_on+0x20/0x1b5
[ 8945.178202][ T6995]  do_syscall_64+0x33/0x40
[ 8945.182512][ T6995]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 8945.188323][ T6995] RIP: 0033:0x7fa50e75e4b7
[ 8945.192628][ T6995] Code: 41 54 49 89 d4 55 48 89 f5 53 89 fb 48 83 ec 18 e8 3e f3 ff ff 4d 89 ea 4c 89 e2 48 89 ee 41 89 c0 89 df b8 11 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 35 44 89 c7 48 89 44 24 08 e8 74 f3 ff ff 48
[ 8945.212238][ T6995] RSP: 002b:00007fa50e388e70 EFLAGS: 00000293 ORIG_RAX: 0000000000000011
[ 8945.220584][ T6995] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fa50e75e4b7
[ 8945.228489][ T6995] RDX: 0000000000004000 RSI: 00007fa50eb90000 RDI: 0000000000000004
[ 8945.236392][ T6995] RBP: 00007fa50eb90000 R08: 0000000000000000 R09: 00007fa50e746260
[ 8945.244278][ T6995] R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000004000
[ 8945.252177][ T6995] R13: 0000000000000000 R14: 0000000000000000 R15: 00007fa50e388fc0
[ 8945.260084][ T6995] irq event stamp: 8871
[ 8945.264129][ T6995] hardirqs last  enabled at (8879): [<ffffffffa0866c8f>] console_unlock+0x75f/0xaf0
[ 8945.273427][ T6995] hardirqs last disabled at (8888): [<ffffffffa086677d>] console_unlock+0x24d/0xaf0
[ 8945.282728][ T6995] softirqs last  enabled at (8236): [<ffffffffa1c0070f>] __do_softirq+0x70f/0xa9f
[ 8945.291857][ T6995] softirqs last disabled at (7067): [<ffffffffa1a00ec2>] asm_call_on_stack+0x12/0x20
[ 8945.301246][ T6995] ---[ end trace 2deaef5e80c278a7 ]---

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Dave Chinner]

On Mon, Aug 10, 2020 at 10:03:03PM -0400, Qian Cai wrote:
> On Sun, Jul 26, 2020 at 04:24:12PM +0100, Christoph Hellwig wrote:
> > On Fri, Jul 24, 2020 at 02:24:32PM -0400, Qian Cai wrote:
> > > On Fri, Jun 19, 2020 at 05:17:47PM -0700, Matthew Wilcox wrote:
> > > > On Fri, Jun 19, 2020 at 05:17:50PM -0400, Qian Cai wrote:
> > > > > Running a syscall fuzzer by a normal user could trigger this,
> > > > > 
> > > > > [55649.329999][T515839] WARNING: CPU: 6 PID: 515839 at fs/iomap/direct-io.c:391 iomap_dio_actor+0x29c/0x420
> > > > ...
> > > > > 371 static loff_t
> > > > > 372 iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
> > > > > 373                 void *data, struct iomap *iomap, struct iomap *srcmap)
> > > > > 374 {
> > > > > 375         struct iomap_dio *dio = data;
> > > > > 376
> > > > > 377         switch (iomap->type) {
> > > > > 378         case IOMAP_HOLE:
> > > > > 379                 if (WARN_ON_ONCE(dio->flags & IOMAP_DIO_WRITE))
> > > > > 380                         return -EIO;
> > > > > 381                 return iomap_dio_hole_actor(length, dio);
> > > > > 382         case IOMAP_UNWRITTEN:
> > > > > 383                 if (!(dio->flags & IOMAP_DIO_WRITE))
> > > > > 384                         return iomap_dio_hole_actor(length, dio);
> > > > > 385                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > > > 386         case IOMAP_MAPPED:
> > > > > 387                 return iomap_dio_bio_actor(inode, pos, length, dio, iomap);
> > > > > 388         case IOMAP_INLINE:
> > > > > 389                 return iomap_dio_inline_actor(inode, pos, length, dio, iomap);
> > > > > 390         default:
> > > > > 391                 WARN_ON_ONCE(1);
> > > > > 392                 return -EIO;
> > > > > 393         }
> > > > > 394 }
> > > > > 
> > > > > Could that be iomap->type == IOMAP_DELALLOC ? Looking throught the logs,
> > > > > it contains a few pread64() calls until this happens,
> > > > 
> > > > It _shouldn't_ be able to happen.  XFS writes back ranges which exist
> > > > in the page cache upon seeing an O_DIRECT I/O.  So it's not supposed to
> > > > be possible for there to be an extent which is waiting for the contents
> > > > of the page cache to be written back.
> > > 
> > > Okay, it is IOMAP_DELALLOC. We have,
> > 
> > Can you share the fuzzer?  If we end up with delalloc space here we
> > probably need to fix a bug in the cache invalidation code.
> 
> Here is a simple reproducer (I believe it can also be reproduced using xfstests
> generic/503 on a plain xfs without DAX when SCRATCH_MNT == TEST_DIR),
> 
> # git clone https://gitlab.com/cailca/linux-mm
> # cd linux-mm; make
> # ./random 14

Ok:

file.fd_write = safe_open("./testfile", O_RDWR|O_CREAT);
....
file.fd_read = safe_open("./testfile", O_RDWR|O_CREAT|O_DIRECT);
....
file.ptr = safe_mmap(NULL, fsize, PROT_READ|PROT_WRITE, MAP_SHARED,
			file.fd_write, 0);

So this is all IO to the same inode....

and you loop

while !done {

	do {
		rc = pread(file.fd_read, file.ptr + read, fsize - read,
			read);
		if (rc > 0)
			read += rc;
	} while (rc > 0);

	rc = safe_fallocate(file.fd_write,
			FALLOC_FL_PUNCH_HOLE | FALLOC_FL_KEEP_SIZE,
			0, fsize);
}

On two threads at once?

So, essentially, you do a DIO read into a mmap()d range from the
same file, with DIO read ascending and the mmap() range descending,
then once that is done you hole punch the file and do it again?

IOWs, this is a racing page_mkwrite()/DIO read workload, and the
moment the two threads hit the same block of the file with a
DIO read and a page_mkwrite at the same time, it throws a warning.

Well, that's completely expected behaviour. DIO is not serialised
against mmap() access at all, and so if the page_mkwrite occurs
between the writeback and the iomap_apply() call in the dio path,
then it will see the delalloc block taht the page-mkwrite allocated.

No sane application would ever do this, it's behaviour as expected,
so I don't think there's anything to care about here.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Qian Cai]

> On Aug 13, 2020, at 1:44 AM, Dave Chinner <david@fromorbit.com> wrote:
> 
> Ok:
> 
> file.fd_write = safe_open("./testfile", O_RDWR|O_CREAT);
> ....
> file.fd_read = safe_open("./testfile", O_RDWR|O_CREAT|O_DIRECT);
> ....
> file.ptr = safe_mmap(NULL, fsize, PROT_READ|PROT_WRITE, MAP_SHARED,
>            file.fd_write, 0);
> 
> So this is all IO to the same inode....
> 
> and you loop
> 
> while !done {
> 
>    do {
>        rc = pread(file.fd_read, file.ptr + read, fsize - read,
>            read);
>        if (rc > 0)
>            read += rc;
>    } while (rc > 0);
> 
>    rc = safe_fallocate(file.fd_write,
>            FALLOC_FL_PUNCH_HOLE | FALLOC_FL_KEEP_SIZE,
>            0, fsize);
> }
> 
> On two threads at once?
> 
> So, essentially, you do a DIO read into a mmap()d range from the
> same file, with DIO read ascending and the mmap() range descending,
> then once that is done you hole punch the file and do it again?
> 
> IOWs, this is a racing page_mkwrite()/DIO read workload, and the
> moment the two threads hit the same block of the file with a
> DIO read and a page_mkwrite at the same time, it throws a warning.
> 
> Well, that's completely expected behaviour. DIO is not serialised
> against mmap() access at all, and so if the page_mkwrite occurs
> between the writeback and the iomap_apply() call in the dio path,
> then it will see the delalloc block taht the page-mkwrite allocated.
> 
> No sane application would ever do this, it's behaviour as expected,
> so I don't think there's anything to care about here.

It looks me the kernel warning is trivial to trigger by an non-root user. Shouldn’t we worry a bit because this could be a DoS for systems which set panic_on_warn?

Re: WARN_ON_ONCE(1) in iomap_dio_actor()

[Christoph Hellwig]

On Thu, Aug 13, 2020 at 03:52:13AM -0400, Qian Cai wrote:
> > No sane application would ever do this, it's behaviour as expected,
> > so I don't think there's anything to care about here.
> 
> It looks me the kernel warning is trivial to trigger by an non-root user. Shouldn???t we worry a bit because this could be a DoS for systems which set panic_on_warn?

Yes, we should trigger a WARN_ON on user behavior.  a
pr_info_ratelimited + tracepoint and a good comment is probably the
better solution.