[syzbot] WARNING: ODEBUG bug in __cancel_work

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 6c8f479764eb Add linux-next specific files for 20220809
git tree: linux-next
console+strace: https://syzkaller.appspot.com/x/log.txt?x=1193703d080000
kernel config: https://syzkaller.appspot.com/x/.config?x=a5ae8cfa8d7075d1
dashboard link: https://syzkaller.appspot.com/bug?extid=83672956c7aa6af698b3
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=12b620f3080000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=127b1a0d080000

Bisection is inconclusive: the issue happens on the oldest tested release.

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=12371a0d080000
final oops: https://syzkaller.appspot.com/x/report.txt?x=11371a0d080000
console output: https://syzkaller.appspot.com/x/log.txt?x=16371a0d080000

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

------------[ cut here ]------------
ODEBUG: assert_init not available (active state 0) object type: timer_list hint: 0x0
WARNING: CPU: 0 PID: 3607 at lib/debugobjects.c:509 debug_print_object+0x16e/0x250 lib/debugobjects.c:509
Modules linked in:
CPU: 0 PID: 3607 Comm: syz-executor235 Not tainted 5.19.0-next-20220809-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/22/2022
RIP: 0010:debug_print_object+0x16e/0x250 lib/debugobjects.c:509
Code: ff df 48 89 fa 48 c1 ea 03 80 3c 02 00 0f 85 af 00 00 00 48 8b 14 dd 60 09 49 8a 4c 89 ee 48 c7 c7 00 fd 48 8a e8 73 ac 38 05 <0f> 0b 83 05 35 41 dd 09 01 48 83 c4 18 5b 5d 41 5c 41 5d 41 5e c3
RSP: 0018:ffffc900039ef8a0 EFLAGS: 00010082
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000000000
RDX: ffff88807f355880 RSI: ffffffff8161f1f8 RDI: fffff5200073df06
RBP: 0000000000000001 R08: 0000000000000005 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff89eeff60
R13: ffffffff8a4903c0 R14: ffffffff816b23c0 R15: 1ffff9200073df1f
FS: 0000000000000000(0000) GS:ffff8880b9a00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ff196b876a8 CR3: 00000000261c8000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
debug_object_assert_init lib/debugobjects.c:899 [inline]
debug_object_assert_init+0x1f4/0x2e0 lib/debugobjects.c:870
debug_timer_assert_init kernel/time/timer.c:792 [inline]
debug_assert_init kernel/time/timer.c:837 [inline]
del_timer+0x6d/0x110 kernel/time/timer.c:1257
try_to_grab_pending+0x6d/0xd0 kernel/workqueue.c:1275
__cancel_work+0x7c/0x340 kernel/workqueue.c:3250
l2cap_clear_timer include/net/bluetooth/l2cap.h:884 [inline]
l2cap_chan_del+0x565/0xa60 net/bluetooth/l2cap_core.c:688
l2cap_conn_del+0x3c0/0x7b0 net/bluetooth/l2cap_core.c:1922
l2cap_disconn_cfm net/bluetooth/l2cap_core.c:8213 [inline]
l2cap_disconn_cfm+0x8c/0xc0 net/bluetooth/l2cap_core.c:8206
hci_disconn_cfm include/net/bluetooth/hci_core.h:1779 [inline]
hci_conn_hash_flush+0x122/0x260 net/bluetooth/hci_conn.c:2366
hci_dev_close_sync+0x55d/0x1130 net/bluetooth/hci_sync.c:4476
hci_dev_do_close+0x2d/0x70 net/bluetooth/hci_core.c:554
hci_unregister_dev+0x17f/0x4e0 net/bluetooth/hci_core.c:2682
vhci_release+0x7c/0xf0 drivers/bluetooth/hci_vhci.c:568
__fput+0x277/0x9d0 fs/file_table.c:320
task_work_run+0xdd/0x1a0 kernel/task_work.c:177
exit_task_work include/linux/task_work.h:38 [inline]
do_exit+0xc39/0x2b60 kernel/exit.c:813
do_group_exit+0xd0/0x2a0 kernel/exit.c:943
__do_sys_exit_group kernel/exit.c:954 [inline]
__se_sys_exit_group kernel/exit.c:952 [inline]
__x64_sys_exit_group+0x3a/0x50 kernel/exit.c:952
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fbef442f629
Code: Unable to access opcode bytes at RIP 0x7fbef442f5ff.
RSP: 002b:00007ffc6284d478 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 00007fbef44ba390 RCX: 00007fbef442f629
RDX: 000000000000003c RSI: 00000000000000e7 RDI: 0000000000000001
RBP: 0000000000000001 R08: ffffffffffffffb8 R09: 000000fff44b4e00
R10: 0000000000000004 R11: 0000000000000246 R12: 00007fbef44ba390
R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000001
</TASK>


---
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.
For information about bisection process see: https://goo.gl/tpsmEJ#bisection
syzbot can test patches for this issue, for details see:
https://goo.gl/tpsmEJ#testing-patches

[Hillf Danton]

On Thu, 18 Aug 2022 19:44:25 -0700

> Hello,
>
> syzbot found the following issue on:
>
> HEAD commit: 6c8f479764eb Add linux-next specific files for 20220809
> git tree: linux-next
> console+strace: https://syzkaller.appspot.com/x/log.txt?x=1193703d080000
> kernel config: https://syzkaller.appspot.com/x/.config?x=a5ae8cfa8d7075d1
> dashboard link: https://syzkaller.appspot.com/bug?extid=83672956c7aa6af698b3
> compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=12b620f3080000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=127b1a0d080000

See if l2 channel is fully initialized.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git 6c8f479764eb

diff -pur a/include/net/bluetooth/l2cap.h b/include/net/bluetooth/l2cap.h
--- a/include/net/bluetooth/l2cap.h 2022-08-18 18:35:59.471364600 +0800
+++ b/include/net/bluetooth/l2cap.h 2022-08-18 18:41:09.480876900 +0800
@@ -628,6 +628,7 @@ struct l2cap_chan {
__u32 remote_acc_lat;
__u32 remote_flush_to;

+ int fully_init;
struct delayed_work chan_timer;
struct delayed_work retrans_timer;
struct delayed_work monitor_timer;
diff -pur a/net/bluetooth/l2cap_core.c b/net/bluetooth/l2cap_core.c
--- a/net/bluetooth/l2cap_core.c 2022-08-19 18:57:55.891994000 +0800
+++ b/net/bluetooth/l2cap_core.c 2022-08-19 19:01:35.547512700 +0800
@@ -685,6 +685,8 @@ void l2cap_chan_del(struct l2cap_chan *c
break;

case L2CAP_MODE_ERTM:
+ if (!chan->fully_init)
+ break;
__clear_retrans_timer(chan);
__clear_monitor_timer(chan);
__clear_ack_timer(chan);
@@ -3326,6 +3328,7 @@ int l2cap_ertm_init(struct l2cap_chan *c
INIT_DELAYED_WORK(&chan->ack_timer, l2cap_ack_timeout);

skb_queue_head_init(&chan->srej_q);
+ chan->fully_init = 1;

err = l2cap_seq_list_init(&chan->srej_list, chan->tx_win);
if (err < 0)
--

[syzbot]

Hello,

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

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

Tested on:

commit: 6c8f4797 Add linux-next specific files for 20220809
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git
console output: https://syzkaller.appspot.com/x/log.txt?x=104e8e5b080000

kernel config: https://syzkaller.appspot.com/x/.config?x=a5ae8cfa8d7075d1
dashboard link: https://syzkaller.appspot.com/bug?extid=83672956c7aa6af698b3
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=106ced2d080000

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

[Tetsuo Handa]

syzbot is reporting cancel_delayed_work() without INIT_DELAYED_WORK() at
l2cap_chan_del() [1], for CONF_NOT_COMPLETE flag (which meant to prevent
l2cap_chan_del() from calling cancel_delayed_work()) is cleared by timer
which fires before l2cap_chan_del() is called by closing file descriptor
created by socket(AF_BLUETOOTH, SOCK_STREAM, BTPROTO_L2CAP).

l2cap_bredr_sig_cmd(L2CAP_CONF_REQ) and l2cap_bredr_sig_cmd(L2CAP_CONF_RSP)
are calling l2cap_ertm_init(chan), and they call l2cap_chan_ready() (which
clears CONF_NOT_COMPLETE flag) only when l2cap_ertm_init(chan) succeeded.

l2cap_sock_init() does not call l2cap_ertm_init(chan), and it instead sets
CONF_NOT_COMPLETE flag by calling l2cap_chan_set_defaults(). However, when
connect() is requested, "command 0x0409 tx timeout" happens after 2 seconds
from connect() request, and CONF_NOT_COMPLETE flag is cleared after 4
seconds from connect() request, for l2cap_conn_start() from
l2cap_info_timeout() callback scheduled by

schedule_delayed_work(&conn->info_timer, L2CAP_INFO_TIMEOUT);

in l2cap_connect() is calling l2cap_chan_ready().

Fix this problem by initializing delayed works used by L2CAP_MODE_ERTM
mode as soon as l2cap_chan_create() allocates a channel, like I did in
commit be8597239379f0f5 ("Bluetooth: initialize skb_queue_head at
l2cap_chan_create()").

Link: https://syzkaller.appspot.com/bug?extid=83672956c7aa6af698b3 [1]
Reported-by: syzbot <syzbot+836729...@syzkaller.appspotmail.com>
Signed-off-by: Tetsuo Handa <penguin...@I-love.SAKURA.ne.jp>
---
net/bluetooth/l2cap_core.c | 10 ++++++----
1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/net/bluetooth/l2cap_core.c b/net/bluetooth/l2cap_core.c
index 2c9de67daadc..770891f68703 100644
--- a/net/bluetooth/l2cap_core.c
+++ b/net/bluetooth/l2cap_core.c
@@ -61,6 +61,9 @@ static void l2cap_send_disconn_req(struct l2cap_chan *chan, int err);

static void l2cap_tx(struct l2cap_chan *chan, struct l2cap_ctrl *control,
struct sk_buff_head *skbs, u8 event);
+static void l2cap_retrans_timeout(struct work_struct *work);
+static void l2cap_monitor_timeout(struct work_struct *work);
+static void l2cap_ack_timeout(struct work_struct *work);

static inline u8 bdaddr_type(u8 link_type, u8 bdaddr_type)
{
@@ -476,6 +479,9 @@ struct l2cap_chan *l2cap_chan_create(void)
write_unlock(&chan_list_lock);

INIT_DELAYED_WORK(&chan->chan_timer, l2cap_chan_timeout);
+ INIT_DELAYED_WORK(&chan->retrans_timer, l2cap_retrans_timeout);
+ INIT_DELAYED_WORK(&chan->monitor_timer, l2cap_monitor_timeout);
+ INIT_DELAYED_WORK(&chan->ack_timer, l2cap_ack_timeout);

chan->state = BT_OPEN;

@@ -3320,10 +3326,6 @@ int l2cap_ertm_init(struct l2cap_chan *chan)
chan->rx_state = L2CAP_RX_STATE_RECV;
chan->tx_state = L2CAP_TX_STATE_XMIT;

- INIT_DELAYED_WORK(&chan->retrans_timer, l2cap_retrans_timeout);
- INIT_DELAYED_WORK(&chan->monitor_timer, l2cap_monitor_timeout);
- INIT_DELAYED_WORK(&chan->ack_timer, l2cap_ack_timeout);
-
skb_queue_head_init(&chan->srej_q);

err = l2cap_seq_list_init(&chan->srej_list, chan->tx_win);

--
2.34.1

[patchwork-b...@kernel.org]

Hello:

This patch was applied to bluetooth/bluetooth-next.git (master)
by Luiz Augusto von Dentz <luiz.vo...@intel.com>:

On Sun, 4 Sep 2022 00:32:56 +0900 you wrote:
> syzbot is reporting cancel_delayed_work() without INIT_DELAYED_WORK() at
> l2cap_chan_del() [1], for CONF_NOT_COMPLETE flag (which meant to prevent
> l2cap_chan_del() from calling cancel_delayed_work()) is cleared by timer
> which fires before l2cap_chan_del() is called by closing file descriptor
> created by socket(AF_BLUETOOTH, SOCK_STREAM, BTPROTO_L2CAP).
>
> l2cap_bredr_sig_cmd(L2CAP_CONF_REQ) and l2cap_bredr_sig_cmd(L2CAP_CONF_RSP)
> are calling l2cap_ertm_init(chan), and they call l2cap_chan_ready() (which
> clears CONF_NOT_COMPLETE flag) only when l2cap_ertm_init(chan) succeeded.
>

> [...]

Here is the summary with links:
- Bluetooth: L2CAP: initialize delayed works at l2cap_chan_create()
https://git.kernel.org/bluetooth/bluetooth-next/c/2d2cb3066f2c

You are awesome, thank you!
--
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html