[syzbot] [media?] INFO: task hung in cec_claim_log_addrs

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 83d49ede4b18 Merge branch 'for-next/core' into for-kernelci
git tree: git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci
console output: https://syzkaller.appspot.com/x/log.txt?x=1719dcf8180000
kernel config: https://syzkaller.appspot.com/x/.config?x=af5c6c699e57bbb3
dashboard link: https://syzkaller.appspot.com/bug?extid=116b65a23bc791ae49a6
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
userspace arch: arm64
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16b9ffc8180000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=11ddc734180000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/773990dc198f/disk-83d49ede.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/cf9c558cd3e8/vmlinux-83d49ede.xz
kernel image: https://storage.googleapis.com/syzbot-assets/25f87616316c/Image-83d49ede.gz.xz

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

INFO: task syz-executor398:6279 blocked for more than 143 seconds.
Tainted: G B 6.8.0-rc5-syzkaller-g83d49ede4b18 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor398 state:D stack:0 pid:6279 tgid:6279 ppid:6193 flags:0x0000000d
Call trace:
__switch_to+0x314/0x560 arch/arm64/kernel/process.c:556
context_switch kernel/sched/core.c:5400 [inline]
__schedule+0x1498/0x24b4 kernel/sched/core.c:6727
__schedule_loop kernel/sched/core.c:6802 [inline]
schedule+0xb8/0x19c kernel/sched/core.c:6817
schedule_timeout+0xb8/0x348 kernel/time/timer.c:2159
do_wait_for_common+0x30c/0x468 kernel/sched/completion.c:95
__wait_for_common kernel/sched/completion.c:116 [inline]
wait_for_common kernel/sched/completion.c:127 [inline]
wait_for_completion+0x48/0x60 kernel/sched/completion.c:148
cec_claim_log_addrs+0x164/0x210 drivers/media/cec/core/cec-adap.c:1606
__cec_s_log_addrs+0x1238/0x18d8 drivers/media/cec/core/cec-adap.c:1920
cec_adap_s_log_addrs drivers/media/cec/core/cec-api.c:184 [inline]
cec_ioctl+0x2684/0x37b0 drivers/media/cec/core/cec-api.c:528
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:871 [inline]
__se_sys_ioctl fs/ioctl.c:857 [inline]
__arm64_sys_ioctl+0x14c/0x1c8 fs/ioctl.c:857
__invoke_syscall arch/arm64/kernel/syscall.c:37 [inline]
invoke_syscall+0x98/0x2b8 arch/arm64/kernel/syscall.c:51
el0_svc_common+0x130/0x23c arch/arm64/kernel/syscall.c:136
do_el0_svc+0x48/0x58 arch/arm64/kernel/syscall.c:155
el0_svc+0x54/0x158 arch/arm64/kernel/entry-common.c:678
el0t_64_sync_handler+0x84/0xfc arch/arm64/kernel/entry-common.c:696
el0t_64_sync+0x190/0x194 arch/arm64/kernel/entry.S:598
INFO: task syz-executor398:6329 blocked for more than 143 seconds.
Tainted: G B 6.8.0-rc5-syzkaller-g83d49ede4b18 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor398 state:D stack:0 pid:6329 tgid:6329 ppid:6197 flags:0x0000000d
Call trace:
__switch_to+0x314/0x560 arch/arm64/kernel/process.c:556
context_switch kernel/sched/core.c:5400 [inline]
__schedule+0x1498/0x24b4 kernel/sched/core.c:6727
__schedule_loop kernel/sched/core.c:6802 [inline]
schedule+0xb8/0x19c kernel/sched/core.c:6817
schedule_timeout+0xb8/0x348 kernel/time/timer.c:2159
do_wait_for_common+0x30c/0x468 kernel/sched/completion.c:95
__wait_for_common kernel/sched/completion.c:116 [inline]
wait_for_common kernel/sched/completion.c:127 [inline]
wait_for_completion+0x48/0x60 kernel/sched/completion.c:148
cec_claim_log_addrs+0x164/0x210 drivers/media/cec/core/cec-adap.c:1606
__cec_s_log_addrs+0x1238/0x18d8 drivers/media/cec/core/cec-adap.c:1920
cec_adap_s_log_addrs drivers/media/cec/core/cec-api.c:184 [inline]
cec_ioctl+0x2684/0x37b0 drivers/media/cec/core/cec-api.c:528
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:871 [inline]
__se_sys_ioctl fs/ioctl.c:857 [inline]
__arm64_sys_ioctl+0x14c/0x1c8 fs/ioctl.c:857
__invoke_syscall arch/arm64/kernel/syscall.c:37 [inline]
invoke_syscall+0x98/0x2b8 arch/arm64/kernel/syscall.c:51
el0_svc_common+0x130/0x23c arch/arm64/kernel/syscall.c:136
do_el0_svc+0x48/0x58 arch/arm64/kernel/syscall.c:155
el0_svc+0x54/0x158 arch/arm64/kernel/entry-common.c:678
el0t_64_sync_handler+0x84/0xfc arch/arm64/kernel/entry-common.c:696
el0t_64_sync+0x190/0x194 arch/arm64/kernel/entry.S:598
INFO: task syz-executor398:6367 blocked for more than 143 seconds.
Tainted: G B 6.8.0-rc5-syzkaller-g83d49ede4b18 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor398 state:D stack:0 pid:6367 tgid:6367 ppid:6196 flags:0x0000000d
Call trace:
__switch_to+0x314/0x560 arch/arm64/kernel/process.c:556
context_switch kernel/sched/core.c:5400 [inline]
__schedule+0x1498/0x24b4 kernel/sched/core.c:6727
__schedule_loop kernel/sched/core.c:6802 [inline]
schedule+0xb8/0x19c kernel/sched/core.c:6817
schedule_timeout+0xb8/0x348 kernel/time/timer.c:2159
do_wait_for_common+0x30c/0x468 kernel/sched/completion.c:95
__wait_for_common kernel/sched/completion.c:116 [inline]
wait_for_common kernel/sched/completion.c:127 [inline]
wait_for_completion+0x48/0x60 kernel/sched/completion.c:148
cec_claim_log_addrs+0x164/0x210 drivers/media/cec/core/cec-adap.c:1606
__cec_s_log_addrs+0x1238/0x18d8 drivers/media/cec/core/cec-adap.c:1920
cec_adap_s_log_addrs drivers/media/cec/core/cec-api.c:184 [inline]
cec_ioctl+0x2684/0x37b0 drivers/media/cec/core/cec-api.c:528
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:871 [inline]
__se_sys_ioctl fs/ioctl.c:857 [inline]
__arm64_sys_ioctl+0x14c/0x1c8 fs/ioctl.c:857
__invoke_syscall arch/arm64/kernel/syscall.c:37 [inline]
invoke_syscall+0x98/0x2b8 arch/arm64/kernel/syscall.c:51
el0_svc_common+0x130/0x23c arch/arm64/kernel/syscall.c:136
do_el0_svc+0x48/0x58 arch/arm64/kernel/syscall.c:155
el0_svc+0x54/0x158 arch/arm64/kernel/entry-common.c:678
el0t_64_sync_handler+0x84/0xfc arch/arm64/kernel/entry-common.c:696
el0t_64_sync+0x190/0x194 arch/arm64/kernel/entry.S:598
INFO: lockdep is turned off.


---
This report 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 issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

If the report is already addressed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.

If you want to overwrite report's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the report is a duplicate of another one, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup

[Hillf Danton]

On Tue, 20 Feb 2024 22:13:24 -0800

> HEAD commit: 83d49ede4b18 Merge branch 'for-next/core' into for-kernelci
> git tree: git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci

> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=11ddc734180000

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci

--- x/drivers/media/cec/core/cec-adap.c
+++ y/drivers/media/cec/core/cec-adap.c
@@ -1575,7 +1575,6 @@ unconfigure:
cec_adap_unconfigure(adap);
adap->is_configuring = false;
adap->must_reconfigure = false;
- adap->kthread_config = NULL;
complete(&adap->config_completion);
mutex_unlock(&adap->lock);
return 0;
@@ -1592,6 +1591,8 @@ static void cec_claim_log_addrs(struct c
if (WARN_ON(adap->is_configuring || adap->is_configured))
return;

+ if (adap->kthread_config)
+ return;
init_completion(&adap->config_completion);

/* Ready to kick off the thread */
@@ -1605,6 +1606,7 @@ static void cec_claim_log_addrs(struct c
mutex_unlock(&adap->lock);
wait_for_completion(&adap->config_completion);
mutex_lock(&adap->lock);
+ adap->kthread_config = NULL;
}
}

--

[Edward Adam Davis]

please test hung in cec_claim_log_addrs

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

diff --git a/drivers/media/cec/core/cec-adap.c b/drivers/media/cec/core/cec-adap.c
index 5741adf09a2e..21b3ff504524 100644
--- a/drivers/media/cec/core/cec-adap.c
+++ b/drivers/media/cec/core/cec-adap.c
@@ -1436,7 +1436,6 @@ static int cec_config_thread_func(void *arg)
int err;
int i, j;

- mutex_lock(&adap->lock);
dprintk(1, "physical address: %x.%x.%x.%x, claim %d logical addresses\n",
cec_phys_addr_exp(adap->phys_addr), las->num_log_addrs);
las->log_addr_mask = 0;
@@ -1565,7 +1564,6 @@ static int cec_config_thread_func(void *arg)

}
adap->kthread_config = NULL;
complete(&adap->config_completion);

- mutex_unlock(&adap->lock);
call_void_op(adap, configured);
return 0;

@@ -1577,7 +1575,6 @@ static int cec_config_thread_func(void *arg)
adap->must_reconfigure = false;

adap->kthread_config = NULL;
complete(&adap->config_completion);

- mutex_unlock(&adap->lock);
return 0;
}

@@ -1602,9 +1599,7 @@ static void cec_claim_log_addrs(struct cec_adapter *adap, bool block)
adap->kthread_config = NULL;
adap->is_configuring = false;
} else if (block) {
- mutex_unlock(&adap->lock);
wait_for_completion(&adap->config_completion);
- mutex_lock(&adap->lock);
}
}

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in cec_claim_log_addrs

INFO: task syz-executor.1:9052 blocked for more than 143 seconds.
Tainted: G B 6.8.0-rc5-syzkaller-00063-ge6ac7c55d3ec-dirty #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor.1 state:D stack:0 pid:9052 tgid:9051 ppid:6538 flags:0x0000000d

Call trace:
__switch_to+0x314/0x560 arch/arm64/kernel/process.c:556
context_switch kernel/sched/core.c:5400 [inline]
__schedule+0x1498/0x24b4 kernel/sched/core.c:6727
__schedule_loop kernel/sched/core.c:6802 [inline]
schedule+0xb8/0x19c kernel/sched/core.c:6817
schedule_timeout+0xb8/0x348 kernel/time/timer.c:2159
do_wait_for_common+0x30c/0x468 kernel/sched/completion.c:95
__wait_for_common kernel/sched/completion.c:116 [inline]
wait_for_common kernel/sched/completion.c:127 [inline]
wait_for_completion+0x48/0x60 kernel/sched/completion.c:148

cec_claim_log_addrs+0x180/0x244 drivers/media/cec/core/cec-adap.c:1607
__cec_s_log_addrs+0x1238/0x18d8 drivers/media/cec/core/cec-adap.c:1922

cec_adap_s_log_addrs drivers/media/cec/core/cec-api.c:184 [inline]
cec_ioctl+0x2684/0x37b0 drivers/media/cec/core/cec-api.c:528
vfs_ioctl fs/ioctl.c:51 [inline]
__do_sys_ioctl fs/ioctl.c:871 [inline]
__se_sys_ioctl fs/ioctl.c:857 [inline]
__arm64_sys_ioctl+0x14c/0x1c8 fs/ioctl.c:857
__invoke_syscall arch/arm64/kernel/syscall.c:37 [inline]
invoke_syscall+0x98/0x2b8 arch/arm64/kernel/syscall.c:51
el0_svc_common+0x130/0x23c arch/arm64/kernel/syscall.c:136
do_el0_svc+0x48/0x58 arch/arm64/kernel/syscall.c:155

el0_svc+0x54/0x168 arch/arm64/kernel/entry-common.c:712
el0t_64_sync_handler+0x84/0xfc arch/arm64/kernel/entry-common.c:730

el0t_64_sync+0x190/0x194 arch/arm64/kernel/entry.S:598
INFO: lockdep is turned off.

Tested on:

commit: e6ac7c55 Merge branch 'for-next/core' into for-kernelci
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci
console output: https://syzkaller.appspot.com/x/log.txt?x=1772604a180000

kernel config: https://syzkaller.appspot.com/x/.config?x=af5c6c699e57bbb3
dashboard link: https://syzkaller.appspot.com/bug?extid=116b65a23bc791ae49a6
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
userspace arch: arm64

patch: https://syzkaller.appspot.com/x/patch.diff?x=13488eb4180000

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+116b65...@syzkaller.appspotmail.com

Tested on:

commit: 9fc1cccc Merge tag 'for-linus' of git://git.kernel.org..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
console output: https://syzkaller.appspot.com/x/log.txt?x=162ca072180000
kernel config: https://syzkaller.appspot.com/x/.config?x=95be8c66da553d84

dashboard link: https://syzkaller.appspot.com/bug?extid=116b65a23bc791ae49a6
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
userspace arch: arm64

patch: https://syzkaller.appspot.com/x/patch.diff?x=148ff694180000

Note: testing is done by a robot and is best-effort only.

[Edward Adam Davis]

After unlocking adap->lock in cec_claim_log_addrs(), cec_claim_log_addrs() may
re-enter, causing this issue to occur.

In the thread function cec_config_thread_func() adap->lock is also used, so there
is no need to unlock adap->lock in cec_claim_log_addrs(), and then use adap->lock
in cec_config_thread_func() to protect.

Reported-and-tested-by: syzbot+116b65...@syzkaller.appspotmail.com
Signed-off-by: Edward Adam Davis <ead...@qq.com>
---
drivers/media/cec/core/cec-adap.c | 5 -----
1 file changed, 5 deletions(-)

--
2.43.0

[Hans Verkuil]

On 21/02/2024 15:20, Edward Adam Davis wrote:
> After unlocking adap->lock in cec_claim_log_addrs(), cec_claim_log_addrs() may
> re-enter, causing this issue to occur.

But if it is called again, then it should hit this at the start of the function:

if (WARN_ON(adap->is_configuring || adap->is_configured))
return;

I'm still not sure what causes the KASAN hung task since I cannot seem to reproduce
it, and because it is hard for me to find enough time to dig into this.

Regards,

Hans

[Hillf Danton]

On Tue, 20 Feb 2024 22:13:24 -0800

> HEAD commit: 83d49ede4b18 Merge branch 'for-next/core' into for-kernelci
> git tree: git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci

> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=11ddc734180000

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci

--- x/drivers/media/cec/core/cec-adap.c
+++ y/drivers/media/cec/core/cec-adap.c

@@ -1592,8 +1592,6 @@ static void cec_claim_log_addrs(struct c

if (WARN_ON(adap->is_configuring || adap->is_configured))
return;

- init_completion(&adap->config_completion);
-

/* Ready to kick off the thread */

adap->is_configuring = true;
adap->kthread_config = kthread_run(cec_config_thread_func, adap,
--- x/drivers/media/cec/core/cec-core.c
+++ y/drivers/media/cec/core/cec-core.c
@@ -284,6 +284,7 @@ struct cec_adapter *cec_allocate_adapter
mutex_init(&adap->lock);
INIT_LIST_HEAD(&adap->transmit_queue);
INIT_LIST_HEAD(&adap->wait_queue);
+ init_completion(&adap->config_completion);
init_waitqueue_head(&adap->kthread_waitq);

/* adap->devnode initialization */
--

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+116b65...@syzkaller.appspotmail.com

Tested on:

commit: 59a96b71 Merge branch 'for-next/core' into for-kernelci

git tree: https://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci

console output: https://syzkaller.appspot.com/x/log.txt?x=1474b4f8180000
kernel config: https://syzkaller.appspot.com/x/.config?x=af5c6c699e57bbb3

dashboard link: https://syzkaller.appspot.com/bug?extid=116b65a23bc791ae49a6
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
userspace arch: arm64

patch: https://syzkaller.appspot.com/x/patch.diff?x=1369628c180000

[Hillf Danton]

On Wed, 21 Feb 2024 15:38:47 +0100 Hans Verkuil <hverkui...@xs4all.nl>

> On 21/02/2024 15:20, Edward Adam Davis wrote:
> > After unlocking adap->lock in cec_claim_log_addrs(), cec_claim_log_addrs() may
> > re-enter, causing this issue to occur.
>
> But if it is called again, then it should hit this at the start of the function:
>
> if (WARN_ON(adap->is_configuring || adap->is_configured))
> return;
>
> I'm still not sure what causes the KASAN hung task since I cannot seem to reproduce
> it, and because it is hard for me to find enough time to dig into this.

Likely because of the window for initializing completion more than once [1].

[1] https://lore.kernel.org/lkml/00000000000054...@google.com/

[Edward Adam Davis]

On Wed, 21 Feb 2024 15:38:47 +0100, Hans Verkuil wrote:
> > After unlocking adap->lock in cec_claim_log_addrs(), cec_claim_log_addrs() may
> > re-enter, causing this issue to occur.
>
> But if it is called again, then it should hit this at the start of the function:
>
> if (WARN_ON(adap->is_configuring || adap->is_configured))
> return;
>
> I'm still not sure what causes the KASAN hung task since I cannot seem to reproduce
> it, and because it is hard for me to find enough time to dig into this.

Please pay attention to the following section of code in cec_config_thread_func():
3 unconfigure:
2 for (i = 0; i < las->num_log_addrs; i++)
1 las->log_addr[i] = CEC_LOG_ADDR_INVALID;
1573 cec_adap_unconfigure(adap); // [1], is_configured = false;
1 adap->is_configuring = false; // [2], is_configuring = false;
2 adap->must_reconfigure = false;
3 adap->kthread_config = NULL;
4 complete(&adap->config_completion);
5 mutex_unlock(&adap->lock); // [3], Afterwards

And the following code is included in cec_claim_log-addrs():
3 } else if (block) {
2 mutex_unlock(&adap->lock);
1 wait_for_completion(&adap->config_completion);
1607 mutex_lock(&adap->lock); // [4], During the period before re obtaining the adap->lock, how did cec_claim_log-addrs() re-enter?

BR,
edward

[Hans Verkuil]

I have been able to reproduce this by adding msleeps in several places.

When I have some more time I will start digging into this.

Regards,

Hans