[syzbot] WARNING: ODEBUG bug in __cancel_work

[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+83672956c7aa6af698b3@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 syzkaller@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

[PATCH] Bluetooth: L2CAP: initialize delayed works at l2cap_chan_create()

[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+83672956c7aa6af698b3@syzkaller.appspotmail.com>
Signed-off-by: Tetsuo Handa <penguin-kernel@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

RE: Bluetooth: L2CAP: initialize delayed works at l2cap_chan_create()

[bluez.test.bot]

[-- Attachment #1: Type: text/plain, Size: 2071 bytes --]

This is automated email and please do not reply to this email!

Dear submitter,

Thank you for submitting the patches to the linux bluetooth mailing list.
This is a CI test results with your patch series:
PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=673830

---Test result---

Test Summary:
CheckPatch                    FAIL      1.92 seconds
GitLint                       PASS      0.77 seconds
SubjectPrefix                 PASS      0.62 seconds
BuildKernel                   PASS      46.71 seconds
BuildKernel32                 PASS      41.98 seconds
Incremental Build with patchesPASS      60.74 seconds
TestRunner: Setup             PASS      695.46 seconds
TestRunner: l2cap-tester      PASS      21.77 seconds
TestRunner: iso-tester        PASS      22.27 seconds
TestRunner: bnep-tester       PASS      8.61 seconds
TestRunner: mgmt-tester       PASS      136.49 seconds
TestRunner: rfcomm-tester     PASS      12.60 seconds
TestRunner: sco-tester        PASS      12.50 seconds
TestRunner: smp-tester        PASS      12.46 seconds
TestRunner: userchan-tester   PASS      9.00 seconds

Details
##############################
Test: CheckPatch - FAIL - 1.92 seconds
Run checkpatch.pl script with rule in .checkpatch.conf
Bluetooth: L2CAP: initialize delayed works at l2cap_chan_create()\ERROR:GIT_COMMIT_ID: Please use git commit description style 'commit <12+ chars of sha1> ("<title line>")' - ie: 'commit fatal: unsaf ("ace/src' is owned by someone else)")'
#84: 
commit be8597239379f0f5 ("Bluetooth: initialize skb_queue_head at
l2cap_chan_create()").

total: 1 errors, 0 warnings, 0 checks, 28 lines checked

NOTE: For some of the reported defects, checkpatch may be able to
      mechanically convert to the typical style using --fix or --fix-inplace.

/github/workspace/src/12964990.patch has style problems, please review.

NOTE: Ignored message types: UNKNOWN_COMMIT_ID

NOTE: If any of the errors are false positives, please report
      them to the maintainer, see CHECKPATCH in MAINTAINERS.




---
Regards,
Linux Bluetooth

Re: [PATCH] Bluetooth: L2CAP: initialize delayed works at l2cap_chan_create()

[patchwork-bot+bluetooth]

Hello:

This patch was applied to bluetooth/bluetooth-next.git (master)
by Luiz Augusto von Dentz <luiz.von.dentz@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