Re: KASAN: soft lockup in paste_selection

Re: KASAN: soft lockup in paste_selection

[andriy.shevchenko]

+Cc: Ilpo (not sure if you can do anything about that, so JFYI)

On Fri, May 12, 2023 at 08:28:26AM +0000, zhangqiumiao wrote:
> Hello,
> 
> We found the following issue using syzkaller on Linux v5.10.0.
> A similar issue was found in function `paste_selection` before and
> I believe they are the same.
> (https://lore.kernel.org/all/000000000000fe769905d315a1b7@google.com/)
> 
> Unfortunately, no one seems to be paying attention to this issue.
> 
> The brief report is below:
> ========================================================
> kasan
> 
> RBP: 00007fcdf2facd75 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
> R13: 00007fff5a65520f R14: 00007fff5a6553b0 R15: 00007fcdf14acd80
> watchdog: BUG: soft lockup - CPU#1 stuck for 123s! [syz-executor.3:23295]
> Modules linked in:
> 
> Sample time: 21774237378 ns(HZ: 1000)
> Sample stat:
> curr: user: 39128997021, nice: 0, sys: 466294657699, idle: 246835945000, iowait: 5392968000, irq: 19049308342, softirq: 7849858971, st: 1336816062
> deta: user: 0, nice: 0, sys: 21408617598, idle: 0, iowait: 0, irq: 588225776, softirq: 0, st: 255856
> Sample softirq:
> Sample irqstat:
>     irq   15: delta         22, curr:       1301, ata_piix
> CPU: 1 PID: 23295 Comm: syz-executor.3 Not tainted 5.10.0 #1
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1ubuntu1.1 04/01/2014
> RIP: 0010:check_kcov_mode kernel/kcov.c:163 [inline]
> RIP: 0010:__sanitizer_cov_trace_pc+0x14/0x60 kernel/kcov.c:197
> Code: 80 ee 02 00 48 8b 80 68 14 00 00 c3 cc cc cc cc 66 0f 1f 44 00 00 48 8b 34 24 65 48 8b 04 25 80 ee 02 00 65 8b 15 8c 69 8c 7e <f7> c2 00 01 ff 00 74 0f 80 e6 01 74 35 8b 90 74 14 00 00 85 d2 74
> RSP: 0018:ffff88812919fa90 EFLAGS: 00000286
> 
> RAX: ffff888084ced100 RBX: ffff888084ced100 RCX: ffffc90008523000
> RDX: 0000000000000000 RSI: ffffffff83696570 RDI: ffff888112c729e8
> RBP: 0000000000000000 R08: 0000000000000001 R09: ffffed102258e538
> R10: ffff888112c729bf R11: ffffed102258e537 R12: ffff888112c72800
> R13: ffffed101099da20 R14: dffffc0000000000 R15: ffff888103922ec0
> FS:  00007fcdf14ad700(0000) GS:ffff888134c00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000000020000000 CR3: 0000000100af4000 CR4: 0000000000150ee0
> Call Trace:
> paste_selection+0x170/0x3e0 drivers/tty/vt/selection.c:401
> tioclinux+0x3c3/0x480 drivers/tty/vt/vt.c:3208
> vt_ioctl+0x114d/0x1b90 drivers/tty/vt/vt_ioctl.c:762
> tty_ioctl+0x6d2/0x14a0 drivers/tty/tty_io.c:2757
> vfs_ioctl fs/ioctl.c:48 [inline]
> __do_sys_ioctl fs/ioctl.c:753 [inline]
> __se_sys_ioctl+0x112/0x150 fs/ioctl.c:739
> do_syscall_64+0x33/0x40 arch/x86/entry/common.c:46
> entry_SYSCALL_64_after_hwframe+0x61/0xc6
> RIP: 0033:0x7fcdf2f3f6cd
> Code: c3 e8 17 32 00 00 0f 1f 80 00 00 00 00 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
> RSP: 002b:00007fcdf14acbf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> RAX: ffffffffffffffda RBX: 00007fcdf307af80 RCX: 00007fcdf2f3f6cd
> RDX: 0000000020000100 RSI: 000000000000541c RDI: 0000000000000004
> RBP: 00007fcdf2facd75 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
> R13: 00007fff5a65520f R14: 00007fff5a6553b0 R15: 00007fcdf14acd80
> Sending NMI from CPU 1 to CPUs 0,2-3:
> NMI backtrace for cpu 0 skipped: idling at native_safe_halt arch/x86/include/asm/irqflags.h:60 [inline]
> NMI backtrace for cpu 0 skipped: idling at arch_safe_halt arch/x86/include/asm/irqflags.h:103 [inline]
> NMI backtrace for cpu 0 skipped: idling at default_idle+0x13/0x20 arch/x86/kernel/process.c:713
> NMI backtrace for cpu 2 skipped: idling at native_safe_halt arch/x86/include/asm/irqflags.h:60 [inline]
> NMI backtrace for cpu 2 skipped: idling at arch_safe_halt arch/x86/include/asm/irqflags.h:103 [inline]
> NMI backtrace for cpu 2 skipped: idling at default_idle+0x13/0x20 arch/x86/kernel/process.c:713
> NMI backtrace for cpu 3 skipped: idling at native_safe_halt arch/x86/include/asm/irqflags.h:60 [inline]
> NMI backtrace for cpu 3 skipped: idling at arch_safe_halt arch/x86/include/asm/irqflags.h:103 [inline]
> NMI backtrace for cpu 3 skipped: idling at default_idle+0x13/0x20 arch/x86/kernel/process.c:713
> 
> ========================================================

-- 
With Best Regards,
Andy Shevchenko

Re: KASAN: soft lockup in paste_selection

[gregkh]

On Fri, May 12, 2023 at 08:28:26AM +0000, zhangqiumiao wrote:
> Hello,
> 
> We found the following issue using syzkaller on Linux v5.10.0.

5.10.0 is very old and obsolete and over 20 thousand patches old.
Please, if you are testing LTS kernels, use the latest one.

> A similar issue was found in function `paste_selection` before and
> I believe they are the same.
> (https://lore.kernel.org/all/000000000000fe769905d315a1b7@google.com/)
> 
> Unfortunately, no one seems to be paying attention to this issue.

Do you have a proposed patch for this fix now that you have a way to
reproduce this?  Do you see this in real situations or only in
fault-injection systems running syzbot?

And can you reproduce this on 6.4-rc1?  Do you have a reproducer?

thanks,

greg k-h

Re: Re: KASAN: soft lockup in paste_selection

[Qiumiao Zhang]

On Fri, May 12, 2023 at 11:33:26AM +0000, gregkh wrote:
>> Hello,
>> 
>> We found the following issue using syzkaller on Linux v5.10.0.
> 
> 5.10.0 is very old and obsolete and over 20 thousand patches old.
> Please, if you are testing LTS kernels, use the latest one.
> 
>> A similar issue was found in function `paste_selection` before and I 
>> believe they are the same.
>> (https://lore.kernel.org/all/000000000000fe769905d315a1b7@google.com/)
>> 
>> Unfortunately, no one seems to be paying attention to this issue.
> 
> Do you have a proposed patch for this fix now that you have a way to reproduce this?  Do you see this in real situations or only in > fault-injection systems running syzbot?
> 
> And can you reproduce this on 6.4-rc1?  Do you have a reproducer?
> 
> thanks,
> 
> greg k-h

I see this issue only in fault-injection systems running syzbot. And I can reproduce this on 6.4-rc1.
HEAD commit:    ac9a78681b92 Linux 6.4-rc1
git tree:       upstream
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=16c3bc25b00000

I am trying to analyze this issue, but I don't have any suggestions at the moment.

The brief report is below:
========================================================
INFO: task kworker/u16:5:67 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u16:5   state:D stack:0     pid:67    ppid:2      flags:0x00004000
Workqueue: events_unbound flush_to_ldisc
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 ? update_load_avg+0x7e/0x740
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? _raw_spin_unlock+0xe/0x30
 flush_to_ldisc+0x2a/0x190
 process_one_work+0x1e5/0x3f0
 worker_thread+0x4d/0x2f0
 ? __pfx_worker_thread+0x10/0x10
 kthread+0xe5/0x120
 ? __pfx_kthread+0x10/0x10
 ret_from_fork+0x2c/0x50
 </TASK>
INFO: task a.out:8707 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8707  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8713 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8713  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8842 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8842  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8843 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8843  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8851 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8851  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8858 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8858  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8861 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8861  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8868 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8868  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
INFO: task a.out:8997 blocked for more than 122 seconds.
      Not tainted 6.4.0-rc1 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:a.out           state:D stack:0     pid:8997  ppid:1      flags:0x00000000
Call Trace:
 <TASK>
 __schedule+0x281/0x840
 schedule+0x5e/0xd0
 schedule_preempt_disabled+0x15/0x30
 __mutex_lock.constprop.0+0x357/0x6a0
 ? prb_read_valid+0x1b/0x30
 paste_selection+0x97/0x1d0
 ? __pfx_default_wake_function+0x10/0x10
 tty_ioctl+0x2cd/0x750
 __x64_sys_ioctl+0x8f/0xc0
 do_syscall_64+0x3f/0x90
 entry_SYSCALL_64_after_hwframe+0x72/0xdc
RIP: 0033:0x7f670550677d
RSP: 002b:00007f67057dedf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f67057df640 RCX: 00007f670550677d
RDX: 00000000200000c0 RSI: 000000000000541c RDI: 0000000000000003
RBP: 00007f67057dee20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f67057df640
R13: 0000000000000000 R14: 00007f670548b170 R15: 00007ffc74714c40
 </TASK>
Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings

With Best Regards,

Qiumiao Zhang

Re: Re: KASAN: soft lockup in paste_selection

[Greg KH]

On Mon, May 15, 2023 at 03:26:29PM +0800, Qiumiao Zhang wrote:
> On Fri, May 12, 2023 at 11:33:26AM +0000, gregkh wrote:
> >> Hello,
> >> 
> >> We found the following issue using syzkaller on Linux v5.10.0.
> > 
> > 5.10.0 is very old and obsolete and over 20 thousand patches old.
> > Please, if you are testing LTS kernels, use the latest one.
> > 
> >> A similar issue was found in function `paste_selection` before and I 
> >> believe they are the same.
> >> (https://lore.kernel.org/all/000000000000fe769905d315a1b7@google.com/)
> >> 
> >> Unfortunately, no one seems to be paying attention to this issue.
> > 
> > Do you have a proposed patch for this fix now that you have a way to reproduce this?  Do you see this in real situations or only in > fault-injection systems running syzbot?
> > 
> > And can you reproduce this on 6.4-rc1?  Do you have a reproducer?
> > 
> > thanks,
> > 
> > greg k-h
> 
> I see this issue only in fault-injection systems running syzbot. And I can reproduce this on 6.4-rc1.

fault-injection systems are "fake" and for many issues in the
tty/console layer, we really do not care about them as they the failures
can never be triggered in real life.

Are you sure this is not such a issue?

Try to fix this up by adding the needed "error handling" to the place
where the fault injection was causing the failure, and see if that
really is realistic or not.

good luck!

greg k-h