Re: INFO: task hung in generic_file_write_iter

From: Tetsuo Handa
Date: Mon Aug 06 2018 - 07:57:46 EST

Next message: Dmitry Vyukov: "Re: WARNING in try_charge"
Previous message: Thomas Richter: "[PATCH] perf report: Create auxiliary trace data files for s390"
In reply to: Jan Kara: "Re: INFO: task hung in generic_file_write_iter"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On 2018/08/06 19:09, Jan Kara wrote:
>> syzbot reproduced this problem ( https://syzkaller.appspot.com/text?tag=CrashLog&x=11f2fc44400000 ) .
>> It says that grow_dev_page() is returning 1 but __find_get_block() is failing forever. Any idea?

So far syzbot reproduced 7 times, and all reports are saying that
grow_dev_page() is returning 1 but __find_get_block() is failing forever.

INFO: task hung in __get_super
https://syzkaller.appspot.com/text?tag=CrashLog&x=17347272400000

INFO: task hung in __blkdev_get (2)
https://syzkaller.appspot.com/text?tag=CrashLog&x=144347fc400000
https://syzkaller.appspot.com/text?tag=CrashLog&x=12382bfc400000

INFO: task hung in __writeback_inodes_sb_nr
https://syzkaller.appspot.com/text?tag=CrashLog&x=11f2fc44400000
https://syzkaller.appspot.com/text?tag=CrashLog&x=13c2449c400000

INFO: task hung in filename_create
https://syzkaller.appspot.com/text?tag=CrashLog&x=174a672c400000

INFO: task hung in lookup_slow
https://syzkaller.appspot.com/text?tag=CrashLog&x=16113bdc400000

>
> Looks like some kind of a race where device block size gets changed while
> getblk() runs (and creates buffers for underlying page). I don't have time
> to nail it down at this moment can have a look into it later unless someone
> beats me to it.
>

It seems that loop device is relevant to this problem.

144347fc400000:

[ 557.484258] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 560.491589] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 563.500432] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 566.508502] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 569.516546] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 572.524800] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 575.532499] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 575.803688] INFO: task syz-executor7:7893 blocked for more than 140 seconds.
[ 575.810957] Not tainted 4.18.0-rc7-next-20180801+ #29
[ 575.816685] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 575.824663] syz-executor7 D24464 7893 4272 0x00000004
[ 575.830298] Call Trace:
[ 575.832911] __schedule+0x87c/0x1ec0
[ 575.879299] schedule+0xfb/0x450
[ 575.912448] rwsem_down_read_failed+0x362/0x610
[ 575.951922] call_rwsem_down_read_failed+0x18/0x30
[ 575.956843] down_read+0xc3/0x1d0
[ 575.990222] __get_super.part.12+0x20f/0x2e0
[ 575.994654] get_super+0x2d/0x50
[ 575.998016] fsync_bdev+0x17/0xc0
[ 576.001469] invalidate_partition+0x35/0x60
[ 576.005800] drop_partitions.isra.13+0xe8/0x200
[ 576.023366] rescan_partitions+0x75/0x910
[ 576.037534] __blkdev_reread_part+0x1ad/0x230
[ 576.042023] blkdev_reread_part+0x26/0x40
[ 576.046173] loop_reread_partitions+0x163/0x190
[ 576.055795] loop_set_status+0xb95/0x1010
[ 576.059938] loop_set_status64+0xaa/0x100
[ 576.078629] lo_ioctl+0x90e/0x1d70
[ 576.095290] blkdev_ioctl+0x9cd/0x2030
[ 576.146746] block_ioctl+0xee/0x130
[ 576.154704] do_vfs_ioctl+0x1de/0x1720
[ 576.183069] ksys_ioctl+0xa9/0xd0
[ 576.186519] __x64_sys_ioctl+0x73/0xb0
[ 576.190423] do_syscall_64+0x1b9/0x820

It seems that there was loop_reread_partitions() failure before this message starts.

12382bfc400000:

[ 205.467816] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 205.467816] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=1)

[ 205.905418] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 205.905418] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=-16)

[ 206.113592] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 206.113592] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=-16)

[ 206.767225] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 206.767225] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=-16)

[ 206.990060] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 206.990060] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=1)

[ 208.630329] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 208.630329] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=-16)

[ 228.101929] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 228.101929] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=-16)

[ 228.605840] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 228.605840] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=1)

[ 229.400629] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 229.400629] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=1)

[ 229.622379] loop_reread_partitions: partition scan of loop0 (<E1><D3><F8>w<E5><EA><E4>S<E5>]}d<D0>^MI^A<BA><ED>!<F7><DE><92><A8>f<9B>8<CC><D6>W<DB><F5><AE>F5Eice^W<B5>^O<80>Z<E2>^H%<8D><BA>}
[ 229.622379] <BE><8D> <8F>^OESC<CC><88>\<8B><A9>) failed (rc=1)

[ 233.406342] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0
[ 236.414328] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0
[ 239.422327] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0
[ 242.430332] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0
(...snipped...)
[ 416.894327] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0
[ 419.902327] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0
[ 422.910325] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0
[ 425.918329] syz-executor0(18214): getblk(): executed=9 bh_count=0 bh_state=0

[ 431.005871] NMI backtrace for cpu 0
[ 431.005876] CPU: 0 PID: 18214 Comm: syz-executor0 Not tainted 4.18.0-rc6-next-20180725+ #18
[ 431.005881] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[ 431.005884] RIP: 0010:write_comp_data+0x14/0x70
[ 431.005893] Code: 4c 89 ef e8 1e 93 3e 00 e9 76 fc ff ff e8 b4 9c ca ff 90 90 90 90 55 65 4c 8b 04 25 40 ee 01 00 65 8b 05 2f 46 85 7e 48 89 e5 <a9> 00 01 1f 00 75 51 41 8b 80 98 12 00 00 83 f8 03 75 45 49 8b 80
[ 431.005896] RSP: 0018:ffff880192487130 EFLAGS: 00000046
[ 431.005903] RAX: 0000000080000000 RBX: ffff880168426b28 RCX: ffffffff81d704dd
[ 431.005906] RDX: 000000000003085f RSI: 000000000000000d RDI: 0000000000000006
[ 431.005910] RBP: ffff880192487130 R08: ffff8801d9696200 R09: fffff94000af6a66
[ 431.005914] R10: fffff94000af6a66 R11: ffffea00057b5337 R12: 0000000000000006
[ 431.005918] R13: dffffc0000000000 R14: 0000000000000006 R15: 000000000003085f
[ 431.005923] FS: 00007f6c291f1700(0000) GS:ffff8801db000000(0000) knlGS:0000000000000000
[ 431.005926] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 431.005930] CR2: ffffffffff600400 CR3: 00000001c5ff4000 CR4: 00000000001406f0
[ 431.005935] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 431.005938] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 431.005941] Call Trace:
[ 431.005944] __sanitizer_cov_trace_cmp8+0x18/0x20
[ 431.005946] __find_get_block+0x1bd/0xe60
[ 431.005969] __getblk_gfp+0x3dc/0xe00
[ 431.005996] __bread_gfp+0x2d/0x310
[ 431.005999] fat__get_entry+0x59c/0xa30
[ 431.006017] fat_get_short_entry+0x13c/0x2c0
[ 431.006020] fat_subdirs+0x13c/0x290
[ 431.006043] fat_fill_super+0x29f6/0x4430
[ 431.006068] vfat_fill_super+0x31/0x40
[ 431.006070] mount_bdev+0x314/0x3e0
[ 431.006075] vfat_mount+0x3c/0x50
[ 431.006080] legacy_get_tree+0x131/0x460
[ 431.006083] vfs_get_tree+0x1cb/0x5c0
[ 431.006088] do_mount+0x6f2/0x1e20
[ 431.006113] ksys_mount+0x12d/0x140
[ 431.006116] __x64_sys_mount+0xbe/0x150
[ 431.006118] do_syscall_64+0x1b9/0x820
[ 431.006143] entry_SYSCALL_64_after_hwframe+0x49/0xbe

There were a lot of directory bread failure messages before this message starts.

17347272400000:

[ 431.497237] FAT-fs (loop3): Directory bread(block 2574) failed
[ 431.505561] FAT-fs (loop3): Directory bread(block 2575) failed
[ 431.516048] FAT-fs (loop3): Directory bread(block 2576) failed
[ 431.525740] FAT-fs (loop3): Directory bread(block 2577) failed
[ 431.535899] FAT-fs (loop3): Directory bread(block 2578) failed
[ 431.636001] FAT-fs (loop5): bogus number of reserved sectors
[ 431.641910] FAT-fs (loop5): Can't find a valid FAT filesystem
[ 434.145080] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 437.152496] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 440.161598] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 443.169498] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
(...snipped...)
[ 563.500432] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 566.508502] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 569.516546] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 572.524800] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 575.532499] syz-executor0(7883): getblk(): executed=9 bh_count=0 bh_state=0
[ 575.803688] INFO: task syz-executor7:7893 blocked for more than 140 seconds.
[ 575.810957] Not tainted 4.18.0-rc7-next-20180801+ #29
[ 575.816685] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 575.824663] syz-executor7 D24464 7893 4272 0x00000004
[ 575.830298] Call Trace:
[ 575.832911] __schedule+0x87c/0x1ec0
[ 575.879299] schedule+0xfb/0x450
[ 575.912448] rwsem_down_read_failed+0x362/0x610
[ 575.951922] call_rwsem_down_read_failed+0x18/0x30
[ 575.956843] down_read+0xc3/0x1d0
[ 575.990222] __get_super.part.12+0x20f/0x2e0
[ 575.994654] get_super+0x2d/0x50
[ 575.998016] fsync_bdev+0x17/0xc0
[ 576.001469] invalidate_partition+0x35/0x60
[ 576.005800] drop_partitions.isra.13+0xe8/0x200
[ 576.023366] rescan_partitions+0x75/0x910
[ 576.037534] __blkdev_reread_part+0x1ad/0x230
[ 576.042023] blkdev_reread_part+0x26/0x40
[ 576.046173] loop_reread_partitions+0x163/0x190
[ 576.055795] loop_set_status+0xb95/0x1010
[ 576.059938] loop_set_status64+0xaa/0x100
[ 576.078629] lo_ioctl+0x90e/0x1d70
[ 576.095290] blkdev_ioctl+0x9cd/0x2030
[ 576.146746] block_ioctl+0xee/0x130
[ 576.154704] do_vfs_ioctl+0x1de/0x1720
[ 576.183069] ksys_ioctl+0xa9/0xd0
[ 576.186519] __x64_sys_ioctl+0x73/0xb0
[ 576.190423] do_syscall_64+0x1b9/0x820
[ 576.246994] entry_SYSCALL_64_after_hwframe+0x49/0xbe

Next message: Dmitry Vyukov: "Re: WARNING in try_charge"
Previous message: Thomas Richter: "[PATCH] perf report: Create auxiliary trace data files for s390"
In reply to: Jan Kara: "Re: INFO: task hung in generic_file_write_iter"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]