INFO: task hung in jbd2_journal_commit_transaction

57 views
Skip to first unread message

syzbot

unread,
Apr 10, 2019, 8:00:23 PM4/10/19
to syzkaller-a...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 666c420f FROMLIST: ANDROID: binder: Add BINDER_GET_NODE_IN..
git tree: android-4.14
console output: https://syzkaller.appspot.com/x/log.txt?x=16cb98e6400000
kernel config: https://syzkaller.appspot.com/x/.config?x=89d929f317ea847c
dashboard link: https://syzkaller.appspot.com/bug?extid=230460ede9f5a799eadf
compiler: gcc (GCC) 8.0.1 20180413 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=13d763fa400000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=10deabfa400000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+230460...@syzkaller.appspotmail.com

random: sshd: uninitialized urandom read (32 bytes read)
audit: type=1400 audit(1537944812.565:7): avc: denied { map } for
pid=1886 comm="syz-executor339" path="/root/syz-executor339857099"
dev="sda1" ino=16481 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023
tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file permissive=1
INFO: task jbd2/sda1-8:75 blocked for more than 140 seconds.
Not tainted 4.14.71+ #8
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
jbd2/sda1-8 D27584 75 2 0x80000000
Call Trace:
schedule+0x7f/0x1b0 kernel/sched/core.c:3490
jbd2_journal_commit_transaction+0x724/0x648c fs/jbd2/commit.c:437
kjournald2+0x244/0x820 fs/jbd2/journal.c:233
kthread+0x348/0x420 kernel/kthread.c:232
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:402
INFO: task kworker/u4:2:365 blocked for more than 140 seconds.
Not tainted 4.14.71+ #8
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u4:2 D25600 365 2 0x80000000
Workqueue: writeback wb_workfn (flush-8:0)
Call Trace:
schedule+0x7f/0x1b0 kernel/sched/core.c:3490
wait_transaction_locked+0x1a1/0x220 fs/jbd2/transaction.c:164
add_transaction_credits+0x403/0x970 fs/jbd2/transaction.c:192
start_this_handle+0x368/0xfc0 fs/jbd2/transaction.c:362
jbd2__journal_start+0x30a/0x8b0 fs/jbd2/transaction.c:444
__ext4_journal_start_sb+0x109/0x460 fs/ext4/ext4_jbd2.c:81
__ext4_journal_start fs/ext4/ext4_jbd2.h:314 [inline]
ext4_writepages+0x105e/0x3040 fs/ext4/inode.c:2867
do_writepages+0xe0/0x270 mm/page-writeback.c:2341
__writeback_single_inode+0xd8/0x1020 fs/fs-writeback.c:1320
writeback_sb_inodes+0x468/0xcd0 fs/fs-writeback.c:1584
__writeback_inodes_wb+0xf8/0x1e0 fs/fs-writeback.c:1653
wb_writeback+0x4ee/0xb90 fs/fs-writeback.c:1762
wb_check_old_data_flush fs/fs-writeback.c:1875 [inline]
wb_do_writeback fs/fs-writeback.c:1899 [inline]
wb_workfn+0x85d/0xe00 fs/fs-writeback.c:1928
process_one_work+0x86e/0x15c0 kernel/workqueue.c:2114
worker_thread+0xdc/0x1000 kernel/workqueue.c:2248
kthread+0x348/0x420 kernel/kthread.c:232
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:402

Showing all locks held in the system:
1 lock held by khungtaskd/23:
#0: (tasklist_lock){.+.+}, at: [<ffffffffa3e01e67>]
debug_show_all_locks+0x74/0x20f kernel/locking/lockdep.c:4541
4 locks held by kworker/u4:2/365:
#0: ("writeback"){+.+.}, at: [<ffffffffa3d275d7>]
process_one_work+0x787/0x15c0 kernel/workqueue.c:2085
#1: ((&(&wb->dwork)->work)){+.+.}, at: [<ffffffffa3d2760f>]
process_one_work+0x7bf/0x15c0 kernel/workqueue.c:2089
#2: (&type->s_umount_key#34){++++}, at: [<ffffffffa41628fa>]
trylock_super+0x1a/0xe0 fs/super.c:402
#3: (&sbi->s_journal_flag_rwsem){.+.+}, at: [<ffffffffa4053770>]
do_writepages+0xe0/0x270 mm/page-writeback.c:2341
3 locks held by rs:main Q:Reg/1627:
#0: (&f->f_pos_lock){+.+.}, at: [<ffffffffa41bd162>]
__fdget_pos+0xa2/0xc0 fs/file.c:768
#1: (sb_writers#4){.+.+}, at: [<ffffffffa415ba57>] file_start_write
include/linux/fs.h:2722 [inline]
#1: (sb_writers#4){.+.+}, at: [<ffffffffa415ba57>] vfs_write+0x3d7/0x4d0
fs/read_write.c:545
#2: (&sb->s_type->i_mutex_key#10){+.+.}, at: [<ffffffffa4314f59>]
inode_trylock include/linux/fs.h:733 [inline]
#2: (&sb->s_type->i_mutex_key#10){+.+.}, at: [<ffffffffa4314f59>]
ext4_file_write_iter+0x1b9/0xe20 fs/ext4/file.c:230
2 locks held by getty/1757:
#0: (&tty->ldisc_sem){++++}, at: [<ffffffffa49245e0>]
tty_ldisc_ref_wait+0x20/0x80 drivers/tty/tty_ldisc.c:275
#1: (&ldata->atomic_read_lock){+.+.}, at: [<ffffffffa491fb5f>]
n_tty_read+0x1ff/0x15e0 drivers/tty/n_tty.c:2142
2 locks held by init/1890:
#0: (sb_writers#4){.+.+}, at: [<ffffffffa415ba57>] file_start_write
include/linux/fs.h:2722 [inline]
#0: (sb_writers#4){.+.+}, at: [<ffffffffa415ba57>] vfs_write+0x3d7/0x4d0
fs/read_write.c:545
#1: (&sb->s_type->i_mutex_key#10){+.+.}, at: [<ffffffffa4314f59>]
inode_trylock include/linux/fs.h:733 [inline]
#1: (&sb->s_type->i_mutex_key#10){+.+.}, at: [<ffffffffa4314f59>]
ext4_file_write_iter+0x1b9/0xe20 fs/ext4/file.c:230

=============================================

NMI backtrace for cpu 1
CPU: 1 PID: 23 Comm: khungtaskd Not tainted 4.14.71+ #8
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0xb9/0x11b lib/dump_stack.c:53
nmi_cpu_backtrace.cold.0+0x47/0x85 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x121/0x146 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:138 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:196 [inline]
watchdog+0x574/0xa70 kernel/hung_task.c:252
kthread+0x348/0x420 kernel/kthread.c:232
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:402
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 1886 Comm: syz-executor339 Not tainted 4.14.71+ #8
task: ffff8801c8532f00 task.stack: ffff8801c69f0000
RIP: 0010:mext_check_coverage.constprop.2+0x1b0/0x3c0
fs/ext4/move_extent.c:109
RSP: 0018:ffff8801c69f76e8 EFLAGS: 00000246
RAX: ffff8801ca4bb780 RBX: ffff8801ca4bb780 RCX: 1ffff100394976f2
RDX: dffffc0000000000 RSI: 00000000bbdd3916 RDI: ffff8801ca4bb790
RBP: 00000000bbdd3916 R08: 00000000e36c30ef R09: 0000000000000000
R10: ffff8801c8533820 R11: 0000000000000001 R12: ffff8801c69f78f8
R13: ffff8801bf416b28 R14: ffff8801bf416938 R15: 0000000000008002
FS: 00000000011cf880(0000) GS:ffff8801d7600000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fd37ff39330 CR3: 00000001c7112004 CR4: 00000000001606b0
Call Trace:
move_extent_per_page fs/ext4/move_extent.c:333 [inline]
ext4_move_extents+0x17dc/0x2a10 fs/ext4/move_extent.c:681
ext4_ioctl+0x275c/0x35e0 fs/ext4/ioctl.c:765
vfs_ioctl fs/ioctl.c:46 [inline]
file_ioctl fs/ioctl.c:500 [inline]
do_vfs_ioctl+0x1a0/0x1030 fs/ioctl.c:684
SYSC_ioctl fs/ioctl.c:701 [inline]
SyS_ioctl+0x7e/0xb0 fs/ioctl.c:692
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x440169
RSP: 002b:00007ffd9739b378 EFLAGS: 00000217 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00000000004002c8 RCX: 0000000000440169
RDX: 0000000020000040 RSI: 00000000c028660f RDI: 0000000000000003
RBP: 00000000006ca018 R08: 00000000004002c8 R09: 00000000004002c8
R10: 00000000004002c8 R11: 0000000000000217 R12: 00000000004019f0
R13: 0000000000401a80 R14: 0000000000000000 R15: 0000000000000000
Code: 0f b7 85 16 fe ff ff 48 ba 00 00 00 00 00 fc ff df 48 8d 04 40 48 c1
e0 04 48 01 d8 48 8d 78 10 48 89 f9 48 c1 e9 03 80 3c 11 00 <0f> 85 a9 01
00 00 4c 8b 78 10 48 b8 00 00 00 00 00 fc ff df 49


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
syzbot can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches

syzbot

unread,
Apr 12, 2019, 8:00:52 PM4/12/19
to syzkaller-a...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: cf21a9ac ANDROID: Add kconfig to make dm-verity check_at_m..
git tree: android-4.4
console output: https://syzkaller.appspot.com/x/log.txt?x=111276cc400000
kernel config: https://syzkaller.appspot.com/x/.config?x=b6b946fc0167c90b
dashboard link: https://syzkaller.appspot.com/bug?extid=2d9fd056695d29a86f66
compiler: gcc (GCC) 8.0.1 20180413 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1241a3a8400000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1611a300400000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+2d9fd0...@syzkaller.appspotmail.com

binder: 31824:31824 transaction failed 29201/-22, size 0-0 line 3019
binder: 31825:31825 got transaction to invalid handle
binder: 31825:31825 transaction failed 29201/-22, size 0-0 line 3019
binder: 31826:31826 got transaction to invalid handle
binder: 31826:31826 transaction failed 29201/-22, size 0-0 line 3019
INFO: task jbd2/sda1-8:1907 blocked for more than 120 seconds.
Not tainted 4.4.138-gcf21a9a #64
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
jbd2/sda1-8 D ffff8800b64af590 27104 1907 2 0x00000000
ffff8800b64af590 0000000000000000 0000000000000000 0000000000000002
0000000000000000 ffff8801db21fdb8 ffff8801db21fde0 ffff8801db21f4d8
ffff8801db21f4c0 ffff8801bc586000 ffff8800b64e9800 0000000000000000
Call Trace:
[<ffffffff838b46ea>] schedule+0x7a/0x1b0 kernel/sched/core.c:3359
[<ffffffff838bfb01>] schedule_timeout+0x481/0x8b0 kernel/time/timer.c:1515
[<ffffffff838b25aa>] io_schedule_timeout+0x1ba/0x390
kernel/sched/core.c:4941
[<ffffffff838b593b>] io_schedule include/linux/sched.h:447 [inline]
[<ffffffff838b593b>] bit_wait_io+0x1b/0xd0 kernel/sched/wait.c:595
[<ffffffff838b50cd>] __wait_on_bit+0xbd/0x140 kernel/sched/wait.c:395
[<ffffffff838b5238>] out_of_line_wait_on_bit+0xe8/0x120
kernel/sched/wait.c:408
[<ffffffff815c572c>] wait_on_bit_io include/linux/wait.h:1015 [inline]
[<ffffffff815c572c>] __wait_on_buffer+0x5c/0x70 fs/buffer.c:123
[<ffffffff81824555>] wait_on_buffer include/linux/buffer_head.h:342
[inline]
[<ffffffff81824555>] journal_wait_on_commit_record fs/jbd2/commit.c:178
[inline]
[<ffffffff81824555>] jbd2_journal_commit_transaction+0x4725/0x65a0
fs/jbd2/commit.c:895
[<ffffffff8183339a>] kjournald2+0x22a/0x830 fs/jbd2/journal.c:223
[<ffffffff81190958>] kthread+0x268/0x300 kernel/kthread.c:211
[<ffffffff838c2b55>] ret_from_fork+0x55/0x80 arch/x86/entry/entry_64.S:510
no locks held by jbd2/sda1-8/1907.
Sending NMI to all CPUs:
NMI backtrace for cpu 0
CPU: 0 PID: 491 Comm: khungtaskd Not tainted 4.4.138-gcf21a9a #64
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
task: ffff8801d8da8000 task.stack: ffff8801d8d60000
RIP: 0010:[<ffffffff810bfb26>] [<ffffffff810bfb26>] native_apic_mem_write
arch/x86/include/asm/apic.h:94 [inline]
RIP: 0010:[<ffffffff810bfb26>] [<ffffffff810bfb26>]
__default_send_IPI_dest_field arch/x86/include/asm/ipi.h:119 [inline]
RIP: 0010:[<ffffffff810bfb26>] [<ffffffff810bfb26>] _flat_send_IPI_mask
arch/x86/kernel/apic/apic_flat_64.c:61 [inline]
RIP: 0010:[<ffffffff810bfb26>] [<ffffffff810bfb26>]
flat_send_IPI_mask+0xf6/0x1a0 arch/x86/kernel/apic/apic_flat_64.c:69
RSP: 0018:ffff8801d8d67cc8 EFLAGS: 00000046
RAX: 0000000003000000 RBX: 0000000000000c00 RCX: 0000000000000000
RDX: 0000000000000c00 RSI: 0000000000000000 RDI: ffffffffff5fb300
RBP: ffff8801d8d67cf0 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000246
R13: 0000000000000003 R14: 0000000000000002 R15: ffffffff8446f6a0
FS: 0000000000000000(0000) GS:ffff8801db200000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000006cf090 CR3: 0000000148891000 CR4: 00000000001606f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Stack:
ffffffff8446f6a0 ffffffff84a18ee0 0000000000000007 fffffbfff0942c8c
0000000000000040 ffff8801d8d67d10 ffffffff810b5ae1 ffffffff83c0b460
0000000000000003 ffff8801d8d67d68 ffffffff81e19d83 ffff8800b64e9800
Call Trace:
[<ffffffff810b5ae1>] nmi_raise_cpu_backtrace+0x61/0x80
arch/x86/kernel/apic/hw_nmi.c:33
[<ffffffff81e19d83>] nmi_trigger_all_cpu_backtrace.cold.4+0x70/0xad
lib/nmi_backtrace.c:85
[<ffffffff810b5b84>] arch_trigger_all_cpu_backtrace+0x14/0x20
arch/x86/kernel/apic/hw_nmi.c:38
[<ffffffff8141a459>] trigger_all_cpu_backtrace include/linux/nmi.h:44
[inline]
[<ffffffff8141a459>] check_hung_task kernel/hung_task.c:125 [inline]
[<ffffffff8141a459>] check_hung_uninterruptible_tasks
kernel/hung_task.c:182 [inline]
[<ffffffff8141a459>] watchdog.cold.1+0xd3/0xee kernel/hung_task.c:238
[<ffffffff81190958>] kthread+0x268/0x300 kernel/kthread.c:211
[<ffffffff838c2b55>] ret_from_fork+0x55/0x80 arch/x86/entry/entry_64.S:510
Code: b3 5f ff f6 c4 10 75 e2 44 89 e8 c1 e0 18 89 04 25 10 b3 5f ff 44 89
f2 09 da 80 cf 04 41 83 fe 02 0f 44 d3 89 14 25 00 b3 5f ff <41> f7 c4 00
02 00 00 75 1a 4c 89 e7 57 9d 0f 1f 44 00 00 e8 02
NMI backtrace for cpu 1
CPU: 1 PID: 19 Comm: kworker/u4:1 Not tainted 4.4.138-gcf21a9a #64
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: binder binder_deferred_func
task: ffff8801d9b88000 task.stack: ffff8801d9b90000
RIP: 0010:[<ffffffff82083f3b>] [<ffffffff82083f3b>] inb
arch/x86/include/asm/io.h:316 [inline]
RIP: 0010:[<ffffffff82083f3b>] [<ffffffff82083f3b>] io_serial_in+0x6b/0x90
drivers/tty/serial/8250/8250_port.c:398
RSP: 0018:ffff8801d9b976b8 EFLAGS: 00000002
RAX: dffffc0000000000 RBX: 00000000000003fd RCX: 0000000000000000
RDX: 00000000000003fd RSI: ffffffff82083ee1 RDI: ffffffff862aa4b8
RBP: ffff8801d9b976c8 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000001 R11: ffffffff858ed132 R12: ffffffff862aa480
R13: 0000000000000020 R14: fffffbfff0c554d7 R15: fffffbfff0c55499
FS: 0000000000000000(0000) GS:ffff8801db300000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000006cf090 CR3: 000000000440c000 CR4: 00000000001606f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Stack:
ffffffff862aa480 0000000000002709 ffff8801d9b97718 ffffffff82085a9f
ffffffff81e37855 ffffffff862aa4c8 ffffffff862aa6ba ffffffff862aa480
0000000000000032 ffffffff82085bf0 dffffc0000000000 0000000000000032
Call Trace:
[<ffffffff82085a9f>] serial_in drivers/tty/serial/8250/8250.h:97 [inline]
[<ffffffff82085a9f>] wait_for_xmitr+0x8f/0x1e0
drivers/tty/serial/8250/8250_port.c:1717
[<ffffffff82085c0f>] serial8250_console_putchar+0x1f/0x60
drivers/tty/serial/8250/8250_port.c:2806
[<ffffffff820700a9>] uart_console_write+0x59/0xf0
drivers/tty/serial/serial_core.c:1789
[<ffffffff82090269>] serial8250_console_write+0x539/0x830
drivers/tty/serial/8250/8250_port.c:2872
[<ffffffff8207ec4f>] univ8250_console_write+0x5f/0x70
drivers/tty/serial/8250/8250_core.c:594
[<ffffffff81259f1f>] call_console_drivers.constprop.28+0x1ef/0x3f0
kernel/printk/printk.c:1463
[<ffffffff8125cbf5>] console_unlock+0x605/0xa10 kernel/printk/printk.c:2330
[<ffffffff8125d51e>] vprintk_emit+0x51e/0x840 kernel/printk/printk.c:1832
[<ffffffff8125d868>] vprintk+0x28/0x30 kernel/printk/printk.c:1843
[<ffffffff8125d88d>] vprintk_default+0x1d/0x30 kernel/printk/printk.c:1844
[<ffffffff81415328>] printk+0xaf/0xd7 kernel/printk/printk.c:1922
[<ffffffff82dcd626>] binder_release_work.cold.73+0x79/0x9b
drivers/android/binder.c:4387
[<ffffffff82d67ac2>] binder_thread_release+0x422/0x520
drivers/android/binder.c:4578
[<ffffffff82d67fe7>] binder_deferred_release drivers/android/binder.c:5119
[inline]
[<ffffffff82d67fe7>] binder_deferred_func+0x427/0xc00
drivers/android/binder.c:5191
[<ffffffff81181f4f>] process_one_work+0x7df/0x1600 kernel/workqueue.c:2064
[<ffffffff81182e49>] worker_thread+0xd9/0xfc0 kernel/workqueue.c:2196
[<ffffffff81190958>] kthread+0x268/0x300 kernel/kthread.c:211
[<ffffffff838c2b55>] ret_from_fork+0x55/0x80 arch/x86/entry/entry_64.S:510
Code: 24 c1 00 00 00 49 8d 7c 24 38 48 b8 00 00 00 00 00 fc ff df 48 89 fa
48 c1 ea 03 d3 e3 80 3c 02 00 75 17 41 03 5c 24 38 89 da ec <5b> 0f b6 c0
41 5c 5d c3 e8 68 58 47 ff eb c2 e8 c1 58 47 ff eb
Reply all
Reply to author
Forward
0 new messages