Bug 205703 - [xfstests generic/461]: BUG: KASAN: use-after-free in iomap_finish_ioend+0x58c/0x5c0
Summary: [xfstests generic/461]: BUG: KASAN: use-after-free in iomap_finish_ioend+0x58...
Status: NEW
Alias: None
Product: File System
Classification: Unclassified
Component: XFS (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: FileSystem/XFS Default Virtual Assignee
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-11-29 11:47 UTC by Zorro Lang
Modified: 2019-12-04 15:37 UTC (History)
1 user (show)

See Also:
Kernel Version: linux 5.4+ with xfs-5.5-merge-15 and iomap-5.5-merge-11
Subsystem:
Regression: No
Bisected commit-id:


Attachments

Description Zorro Lang 2019-11-29 11:47:21 UTC
generic/461 hit a KASAN BUG on latest upstream mainline kernel with xfs-5.5-merge-15 and iomap-5.5-merge-11, as below:

FSTYP         -- xfs (non-debug)
PLATFORM      -- Linux/aarch64 hpe-apollo-cn99xx-19 5.4.0+ #1 SMP Wed Nov 27 00:00:45 EST 2019
MKFS_OPTIONS  -- -f -bsize=4096 /dev/sda5
MOUNT_OPTIONS -- -o context=system_u:object_r:nfs_t:s0 /dev/sda5 /mnt/xfstests/mnt2

generic/461 24s ... _check_dmesg: something found in dmesg (see /var/lib/xfstests/results//generic/461.dmesg)

Ran: generic/461
Failures: generic/461
Failed 1 of 1 tests

# cat generic/461.full
meta-data=/dev/sda5              isize=512    agcount=4, agsize=983040 blks
         =                       sectsz=4096  attr=2, projid32bit=1
         =                       crc=1        finobt=1, sparse=1, rmapbt=0
         =                       reflink=1
data     =                       bsize=4096   blocks=3932160, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0, ftype=1
log      =internal log           bsize=4096   blocks=2560, version=2
         =                       sectsz=4096  sunit=1 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

# cat generic/461.dmesg
[20546.220860] run fstests generic/461 at 2019-11-27 06:02:10
[20547.342821] XFS (sda5): Mounting V5 Filesystem
[20547.380750] XFS (sda5): Ending clean mount
[20547.389760] xfs filesystem being mounted at /mnt/xfstests/mnt2 supports timestamps until 2038 (0x7fffffff)
[20547.407045] XFS (sda5): User initiated shutdown received. Shutting down filesystem
[20547.424167] XFS (sda5): Unmounting Filesystem
[20548.307193] XFS (sda5): Mounting V5 Filesystem
[20548.355535] XFS (sda5): Ending clean mount
[20548.365016] xfs filesystem being mounted at /mnt/xfstests/mnt2 supports timestamps until 2038 (0x7fffffff)
[20563.616817] XFS (sda5): User initiated shutdown received. Shutting down filesystem
[20563.620286] ==================================================================
[20563.631624] BUG: KASAN: use-after-free in iomap_finish_ioend+0x58c/0x5c0
[20563.638319] Read of size 8 at addr fffffc0c54a36928 by task kworker/123:2/22184

[20563.647107] CPU: 123 PID: 22184 Comm: kworker/123:2 Not tainted 5.4.0+ #1
[20563.653887] Hardware name: HPE Apollo 70             /C01_APACHE_MB         , BIOS L50_5.13_1.11 06/18/2019
[20563.664499] Workqueue: xfs-conv/sda5 xfs_end_io [xfs]
[20563.669547] Call trace:
[20563.671993]  dump_backtrace+0x0/0x370
[20563.675648]  show_stack+0x1c/0x28
[20563.678958]  dump_stack+0x138/0x1b0
[20563.682455]  print_address_description.isra.9+0x60/0x378
[20563.687759]  __kasan_report+0x1a4/0x2a8
[20563.691587]  kasan_report+0xc/0x18
[20563.694985]  __asan_report_load8_noabort+0x18/0x20
[20563.699769]  iomap_finish_ioend+0x58c/0x5c0
[20563.703944]  iomap_finish_ioends+0x110/0x270
[20563.708396]  xfs_end_ioend+0x168/0x598 [xfs]
[20563.712823]  xfs_end_io+0x1e0/0x2d0 [xfs]
[20563.716834]  process_one_work+0x7f0/0x1ac8
[20563.720922]  worker_thread+0x334/0xae0
[20563.724664]  kthread+0x2c4/0x348
[20563.727889]  ret_from_fork+0x10/0x18

[20563.732941] Allocated by task 83403:
[20563.736512]  save_stack+0x24/0xb0
[20563.739820]  __kasan_kmalloc.isra.9+0xc4/0xe0
[20563.744169]  kasan_slab_alloc+0x14/0x20
[20563.747998]  slab_post_alloc_hook+0x50/0xa8
[20563.752173]  kmem_cache_alloc+0x154/0x330
[20563.756185]  mempool_alloc_slab+0x20/0x28
[20563.760186]  mempool_alloc+0xf4/0x2a8
[20563.763845]  bio_alloc_bioset+0x2d0/0x448
[20563.767849]  iomap_writepage_map+0x4b8/0x1740
[20563.772198]  iomap_do_writepage+0x200/0x8d0
[20563.776380]  write_cache_pages+0x8a4/0xed8
[20563.780469]  iomap_writepages+0x4c/0xb0
[20563.784463]  xfs_vm_writepages+0xf8/0x148 [xfs]
[20563.788989]  do_writepages+0xc8/0x218
[20563.792658]  __writeback_single_inode+0x168/0x18f8
[20563.797441]  writeback_sb_inodes+0x370/0xd30
[20563.801703]  wb_writeback+0x2d4/0x1270
[20563.805446]  wb_workfn+0x344/0x1178
[20563.808928]  process_one_work+0x7f0/0x1ac8
[20563.813016]  worker_thread+0x334/0xae0
[20563.816757]  kthread+0x2c4/0x348
[20563.819979]  ret_from_fork+0x10/0x18

[20563.825028] Freed by task 22184:
[20563.828251]  save_stack+0x24/0xb0
[20563.831559]  __kasan_slab_free+0x10c/0x180
[20563.835648]  kasan_slab_free+0x10/0x18
[20563.839389]  slab_free_freelist_hook+0xb4/0x1c0
[20563.843912]  kmem_cache_free+0x8c/0x3e8
[20563.847745]  mempool_free_slab+0x20/0x28
[20563.851660]  mempool_free+0xd4/0x2f8
[20563.855231]  bio_free+0x33c/0x518
[20563.858537]  bio_put+0xb8/0x100
[20563.861672]  iomap_finish_ioend+0x168/0x5c0
[20563.865847]  iomap_finish_ioends+0x110/0x270
[20563.870328]  xfs_end_ioend+0x168/0x598 [xfs]
[20563.874751]  xfs_end_io+0x1e0/0x2d0 [xfs]
[20563.878755]  process_one_work+0x7f0/0x1ac8
[20563.882844]  worker_thread+0x334/0xae0
[20563.886584]  kthread+0x2c4/0x348
[20563.889804]  ret_from_fork+0x10/0x18

[20563.894855] The buggy address belongs to the object at fffffc0c54a36900
                which belongs to the cache bio-1 of size 248
[20563.906844] The buggy address is located 40 bytes inside of
                248-byte region [fffffc0c54a36900, fffffc0c54a369f8)
[20563.918485] The buggy address belongs to the page:
[20563.923269] page:ffffffff82f528c0 refcount:1 mapcount:0 mapping:fffffc8e4ba31900 index:0xfffffc0c54a33300
[20563.932832] raw: 17ffff8000000200 ffffffffa3060100 0000000700000007 fffffc8e4ba31900
[20563.940567] raw: fffffc0c54a33300 0000000080aa0042 00000001ffffffff 0000000000000000
[20563.948300] page dumped because: kasan: bad access detected

[20563.955345] Memory state around the buggy address:
[20563.960129]  fffffc0c54a36800: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fc
[20563.967342]  fffffc0c54a36880: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[20563.974554] >fffffc0c54a36900: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
[20563.981766]                                   ^
[20563.986288]  fffffc0c54a36980: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fc
[20563.993501]  fffffc0c54a36a00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[20564.000713] ==================================================================
[20564.008173] sda5: writeback error on inode 16819694, offset 6569984, sector 117547992
[20564.008272] sda5: writeback error on inode 27891, offset 60567552, sector 101805992
[20569.967881] XFS (sda5): Unmounting Filesystem
[20570.481702] XFS (sda4): Unmounting Filesystem
Comment 1 Darrick J. Wong 2019-12-03 18:23:20 UTC
Could you please post the source line translations of the iomap functions?  I don't have your kernel build.
Comment 2 Zorro Lang 2019-12-04 14:40:40 UTC
(In reply to Darrick J. Wong from comment #1)
> Could you please post the source line translations of the iomap functions? 
> I don't have your kernel build.

I tryed to use the faddr2line tool, then it point to a printk_ratelimited() function. I'm sure I didn't change the kernel source code, the current kernel is installed from it. Is that something wrong?

# ./scripts/faddr2line vmlinux iomap_finish_ioend+0x58c
iomap_finish_ioend+0x58c/0x5c0:
iomap_finish_ioend at /mnt/tests/kernel/distribution/upstream-kernel/install/kernel/fs/iomap/buffered-io.c:1153

# ./scripts/faddr2line vmlinux iomap_finish_ioend+0x168
iomap_finish_ioend+0x168/0x5c0:
iomap_finish_ioend at /mnt/tests/kernel/distribution/upstream-kernel/install/kernel/fs/iomap/buffered-io.c:1133

   1124 static void
   1125 iomap_finish_ioend(struct iomap_ioend *ioend, int error)
   1126 {
   1127         struct inode *inode = ioend->io_inode;
   1128         struct bio *bio = &ioend->io_inline_bio;
   1129         struct bio *last = ioend->io_bio, *next;
   1130         u64 start = bio->bi_iter.bi_sector;
   1131         bool quiet = bio_flagged(bio, BIO_QUIET);
   1132 
   1133         for (bio = &ioend->io_inline_bio; bio; bio = next) {
   1134                 struct bio_vec *bv;
   1135                 struct bvec_iter_all iter_all;
   1136 
   1137                 /*
   1138                  * For the last bio, bi_private points to the ioend, so we
   1139                  * need to explicitly end the iteration here.
   1140                  */
   1141                 if (bio == last)
   1142                         next = NULL;
   1143                 else
   1144                         next = bio->bi_private;
   1145 
   1146                 /* walk each page on bio, ending page IO on them */
   1147                 bio_for_each_segment_all(bv, bio, iter_all)
   1148                         iomap_finish_page_writeback(inode, bv->bv_page, error);
   1149                 bio_put(bio);
   1150         }
   1151 
   1152         if (unlikely(error && !quiet)) {
   1153                 printk_ratelimited(KERN_ERR
   1154 "%s: writeback error on inode %lu, offset %lld, sector %llu",
   1155                         inode->i_sb->s_id, inode->i_ino, ioend->io_offset,
   1156                         start);
   1157         }
   1158 }
Comment 3 Zorro Lang 2019-12-04 15:37:24 UTC
(In reply to Zorro Lang from comment #2)
> (In reply to Darrick J. Wong from comment #1)
> > Could you please post the source line translations of the iomap functions? 
> > I don't have your kernel build.
> 
> I tryed to use the faddr2line tool, then it point to a printk_ratelimited()
> function. I'm sure I didn't change the kernel source code, the current
> kernel is installed from it. Is that something wrong?
> 
> # ./scripts/faddr2line vmlinux iomap_finish_ioend+0x58c
> iomap_finish_ioend+0x58c/0x5c0:
> iomap_finish_ioend at
> /mnt/tests/kernel/distribution/upstream-kernel/install/kernel/fs/iomap/
> buffered-io.c:1153
> 
> # ./scripts/faddr2line vmlinux iomap_finish_ioend+0x168
> iomap_finish_ioend+0x168/0x5c0:
> iomap_finish_ioend at
> /mnt/tests/kernel/distribution/upstream-kernel/install/kernel/fs/iomap/
> buffered-io.c:1133
> 
>    1124 static void
>    1125 iomap_finish_ioend(struct iomap_ioend *ioend, int error)
>    1126 {
>    1127         struct inode *inode = ioend->io_inode;
>    1128         struct bio *bio = &ioend->io_inline_bio;
>    1129         struct bio *last = ioend->io_bio, *next;
>    1130         u64 start = bio->bi_iter.bi_sector;
>    1131         bool quiet = bio_flagged(bio, BIO_QUIET);
>    1132 
>    1133         for (bio = &ioend->io_inline_bio; bio; bio = next) {
>    1134                 struct bio_vec *bv;
>    1135                 struct bvec_iter_all iter_all;
>    1136 
>    1137                 /*
>    1138                  * For the last bio, bi_private points to the ioend,
> so we
>    1139                  * need to explicitly end the iteration here.
>    1140                  */
>    1141                 if (bio == last)
>    1142                         next = NULL;
>    1143                 else
>    1144                         next = bio->bi_private;
>    1145 
>    1146                 /* walk each page on bio, ending page IO on them */
>    1147                 bio_for_each_segment_all(bv, bio, iter_all)
>    1148                         iomap_finish_page_writeback(inode,
> bv->bv_page, error);
>    1149                 bio_put(bio);
>    1150         }
>    1151 
>    1152         if (unlikely(error && !quiet)) {
>    1153                 printk_ratelimited(KERN_ERR
>    1154 "%s: writeback error on inode %lu, offset %lld, sector %llu",
>    1155                         inode->i_sb->s_id, inode->i_ino,
> ioend->io_offset,

The bio_put(bio) might already free the bio. The ioend->io_offset is invalid.
I'll test by saving the offset in a local var at first. If it's the issue, I'll try to send a patch.


>    1156                         start);
>    1157         }
>    1158 }

Note You need to log in before you can comment on or make changes to this bug.