linux-kernel - [Syzkaller & bisect] There is task hung in "synchronize

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-ID: <Y3sOgrOmMQqPMItu@xpf.sh.intel.com>
Date:   Mon, 21 Nov 2022 13:37:06 +0800
From:   Pengfei Xu <pengfei.xu@...el.com>
To:     <frederic@...nel.org>
CC:     <linux-kernel@...r.kernel.org>, <heng.su@...el.com>,
        <pengfei.xu@...el.com>
Subject: [Syzkaller & bisect] There is task hung in "synchronize_rcu" in
 v6.1-rc5 kernel

Hi Frederic Weisbecker and kernel developers,

Greeting!
There is task hung in "synchronize_rcu" in v6.1-rc5 kernel.

Bisected the issue on Raptor and server(No atom small core, big core only),
both platforms bisected results show that:
first bad commit is c597bfddc9e9e8a63817252b67c3ca0e544ace26:
"sched: Provide Kconfig support for default dynamic preempt mode"

[  300.097166] INFO: task rcu_tasks_kthre:11 blocked for more than 147 seconds.
[  300.097455]       Not tainted 6.1.0-rc5-094226ad94f4 #1
[  300.097641] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  300.097922] task:rcu_tasks_kthre state:D stack:0     pid:11    ppid:2      flags:0x00004000
[  300.098230] Call Trace:
[  300.098325]  <TASK>
[  300.098410]  __schedule+0x2de/0x8f0
[  300.098562]  schedule+0x5b/0xe0
[  300.098693]  schedule_timeout+0x3f1/0x4b0
[  300.098849]  ? __sanitizer_cov_trace_pc+0x25/0x60
[  300.099032]  ? queue_delayed_work_on+0x82/0xc0
[  300.099206]  wait_for_completion+0x81/0x140
[  300.099373]  __synchronize_srcu.part.23+0x83/0xb0
[  300.099558]  ? __bpf_trace_rcu_stall_warning+0x20/0x20
[  300.099757]  synchronize_srcu+0xd6/0x100
[  300.099913]  rcu_tasks_postscan+0x19/0x20
[  300.100070]  rcu_tasks_wait_gp+0x108/0x290
[  300.100230]  ? _raw_spin_unlock+0x1d/0x40
[  300.100389]  rcu_tasks_one_gp+0x27f/0x370
[  300.100546]  ? rcu_tasks_postscan+0x20/0x20
[  300.100709]  rcu_tasks_kthread+0x37/0x50
[  300.100863]  kthread+0x14d/0x190
[  300.100998]  ? kthread_complete_and_exit+0x40/0x40
[  300.101199]  ret_from_fork+0x1f/0x30
[  300.101347]  </TASK>
[  300.101457] INFO: task repro:568 blocked for more than 147 seconds.
[  300.101688]       Not tainted 6.1.0-rc5-094226ad94f4 #1
[  300.101881] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  300.102162] task:repro           state:D stack:0     pid:568   ppid:567    flags:0x00004004
[  300.102471] Call Trace:
[  300.102565]  <TASK>
[  300.102648]  __schedule+0x2de/0x8f0
[  300.102793]  schedule+0x5b/0xe0
[  300.102922]  schedule_timeout+0x3f1/0x4b0
[  300.103076]  ? __schedule+0x2e6/0x8f0
[  300.103224]  ? __cond_resched+0x25/0x30
[  300.103377]  wait_for_completion+0x81/0x140
[  300.103543]  __wait_rcu_gp+0x121/0x150
[  300.103691]  synchronize_rcu_tasks_generic+0x52/0xa0
[  300.103880]  ? call_rcu_tasks_generic+0x230/0x230
[  300.104059]  ? __bpf_trace_rcu_stall_warning+0x20/0x20
[  300.104253]  synchronize_rcu_tasks+0x19/0x20
[  300.104418]  ftrace_shutdown+0x1cf/0x370
[  300.104570]  unregister_ftrace_function+0x33/0x210
[  300.104750]  ? __sanitizer_cov_trace_switch+0x57/0xa0
[  300.104941]  perf_ftrace_event_register+0x95/0xf0
[  300.105140]  ? perf_tp_event_init+0xa0/0xa0
[  300.105324]  perf_trace_destroy+0x38/0xa0
[  300.105502]  ? perf_tp_event_init+0xa0/0xa0
[  300.105686]  tp_perf_event_destroy+0x1e/0x30
[  300.105875]  _free_event+0xff/0x690
[  300.106018]  put_event+0x3c/0x50
[  300.106152]  perf_event_release_kernel+0x2f2/0x370
[  300.106338]  ? perf_event_release_kernel+0x9/0x370
[  300.106536]  ? perf_event_release_kernel+0x370/0x370
[  300.106742]  perf_release+0x22/0x30
[  300.106883]  __fput+0x10e/0x440
[  300.107017]  ____fput+0x1e/0x30
[  300.107145]  task_work_run+0xa6/0x100
[  300.107291]  exit_to_user_mode_prepare+0x173/0x180
[  300.107480]  syscall_exit_to_user_mode+0x1f/0x30
[  300.107659]  do_syscall_64+0x4a/0x90
[  300.107803]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
[  300.108001] RIP: 0033:0x7f66e159f59d
[  300.108139] RSP: 002b:00007fff47f04688 EFLAGS: 00000246 ORIG_RAX: 000000000000012a
[  300.108419] RAX: ffffffffffffffea RBX: 0000000000000000 RCX: 00007f66e159f59d
[  300.108679] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00000000200001c0
[  300.108940] RBP: 00007fff47f04690 R08: 0000000000000000 R09: 00007fff47f046c0
[  300.109226] R10: 00000000ffffffff R11: 0000000000000246 R12: 0000000000401180
[  300.109516] R13: 00007fff47f047b0 R14: 0000000000000000 R15: 0000000000000000
[  300.109809]  </TASK>

Kconfig, reproduced code from syzkaller, bisect info from Raptor lake is
in attached.

More detailed info from RPL is in link:
https://github.com/xupengfe/syzkaller_logs/tree/main/221115_105658_synchronize_rcu

If it's helpful and fixed, please added Reported tag from me.

Thanks!
BR.

View attachment "kconfig" of type "text/plain" (278991 bytes)

View attachment "bisect_info.log" of type "text/plain" (3927 bytes)

View attachment "repro.c" of type "text/plain" (7738 bytes)