[syzkaller] WARNING in `mptcp_incoming_options`

[matttbe]

My syzkaller instance hit this issue twice, the last time with bd5ce23, no reproducer:

netlink: 'syz.2.1415': attribute type 27 has an invalid length.
netlink: 44 bytes leftover after parsing attributes in process `syz.7.1420'.
netlink: 'syz.1.1421': attribute type 46 has an invalid length.
------------[ cut here ]------------
WARNING: CPU: 1 PID: 7704 at net/mptcp/protocol.h:1223 __mptcp_do_fallback net/mptcp/protocol.h:1223 [inline]
WARNING: CPU: 1 PID: 7704 at net/mptcp/protocol.h:1223 mptcp_do_fallback net/mptcp/protocol.h:1244 [inline]
WARNING: CPU: 1 PID: 7704 at net/mptcp/protocol.h:1223 check_fully_established net/mptcp/options.c:982 [inline]
WARNING: CPU: 1 PID: 7704 at net/mptcp/protocol.h:1223 mptcp_incoming_options+0x21a8/0x2510 net/mptcp/options.c:1153
Modules linked in:
CPU: 1 UID: 0 PID: 7704 Comm: syz.3.1419 Not tainted 6.16.0-rc3-gbd5ce2324dba #20 PREEMPT(voluntary) 
Hardware name: QEMU Ubuntu 24.04 PC (i440FX + PIIX, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
RIP: 0010:__mptcp_do_fallback net/mptcp/protocol.h:1223 [inline]
RIP: 0010:mptcp_do_fallback net/mptcp/protocol.h:1244 [inline]
RIP: 0010:check_fully_established net/mptcp/options.c:982 [inline]
RIP: 0010:mptcp_incoming_options+0x21a8/0x2510 net/mptcp/options.c:1153
Code: 24 18 e8 bb 2a 00 fd e9 1b df ff ff e8 b1 21 0f 00 e8 ec 5f c4 fc 44 0f b7 ac 24 b0 00 00 00 e9 54 f1 ff ff e8 d9 5f c4 fc 90 <0f> 0b 90 e9 b8 f4 ff ff e8 8b 2a 00 fd e9 8d e6 ff ff e8 81 2a 00
RSP: 0018:ffff8880a3f08448 EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffff8880180a8000 RCX: ffffffff84afcf45
RDX: ffff888090223700 RSI: ffffffff84afdaa7 RDI: 0000000000000001
RBP: ffff888017955780 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: ffff8880180a8910 R14: ffff8880a3e9d058 R15: 0000000000000000
FS:  00005555791b8500(0000) GS:ffff88811c495000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000110c2800b7 CR3: 0000000058e44000 CR4: 0000000000350ef0
Call Trace:
 <IRQ>
 tcp_reset+0x26f/0x2b0 net/ipv4/tcp_input.c:4432
 tcp_validate_incoming+0x1057/0x1b60 net/ipv4/tcp_input.c:5975
 tcp_rcv_established+0x5b5/0x21f0 net/ipv4/tcp_input.c:6166
 tcp_v4_do_rcv+0x5dc/0xa70 net/ipv4/tcp_ipv4.c:1925
 tcp_v4_rcv+0x3473/0x44a0 net/ipv4/tcp_ipv4.c:2363
 ip_protocol_deliver_rcu+0xba/0x480 net/ipv4/ip_input.c:205
 ip_local_deliver_finish+0x2f1/0x500 net/ipv4/ip_input.c:233
 NF_HOOK include/linux/netfilter.h:317 [inline]
 NF_HOOK include/linux/netfilter.h:311 [inline]
 ip_local_deliver+0x1be/0x560 net/ipv4/ip_input.c:254
 dst_input include/net/dst.h:469 [inline]
 ip_rcv_finish net/ipv4/ip_input.c:447 [inline]
 NF_HOOK include/linux/netfilter.h:317 [inline]
 NF_HOOK include/linux/netfilter.h:311 [inline]
 ip_rcv+0x514/0x810 net/ipv4/ip_input.c:567
 __netif_receive_skb_one_core+0x197/0x1e0 net/core/dev.c:5975
 __netif_receive_skb+0x1f/0x120 net/core/dev.c:6088
 process_backlog+0x301/0x1360 net/core/dev.c:6440
 __napi_poll.constprop.0+0xba/0x550 net/core/dev.c:7453
 napi_poll net/core/dev.c:7517 [inline]
 net_rx_action+0xb44/0x1010 net/core/dev.c:7644
 handle_softirqs+0x1d0/0x770 kernel/softirq.c:579
 do_softirq+0x3f/0x90 kernel/softirq.c:480
 </IRQ>
 <TASK>
 __local_bh_enable_ip+0xed/0x110 kernel/softirq.c:407
 local_bh_enable include/linux/bottom_half.h:33 [inline]
 inet_csk_listen_stop+0x2c5/0x1070 net/ipv4/inet_connection_sock.c:1524
 mptcp_check_listen_stop.part.0+0x1cc/0x220 net/mptcp/protocol.c:2985
 mptcp_check_listen_stop net/mptcp/mib.h:118 [inline]
 __mptcp_close+0x9b9/0xbd0 net/mptcp/protocol.c:3000
 mptcp_close+0x2f/0x140 net/mptcp/protocol.c:3066
 inet_release+0xed/0x200 net/ipv4/af_inet.c:435
 inet6_release+0x4f/0x70 net/ipv6/af_inet6.c:487
 __sock_release+0xb3/0x270 net/socket.c:649
 sock_close+0x1c/0x30 net/socket.c:1439
 __fput+0x402/0xb70 fs/file_table.c:465
 task_work_run+0x150/0x240 kernel/task_work.c:227
 resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
 exit_to_user_mode_loop+0xd4/0xe0 kernel/entry/common.c:114
 exit_to_user_mode_prepare include/linux/entry-common.h:330 [inline]
 syscall_exit_to_user_mode_work include/linux/entry-common.h:414 [inline]
 syscall_exit_to_user_mode include/linux/entry-common.h:449 [inline]
 do_syscall_64+0x245/0x360 arch/x86/entry/syscall_64.c:100
 entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fc92f8a36ad
Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 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 b0 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffcf52802d8 EFLAGS: 00000246 ORIG_RAX: 00000000000001b4
RAX: 0000000000000000 RBX: 00007ffcf52803a8 RCX: 00007fc92f8a36ad
RDX: 0000000000000000 RSI: 000000000000001e RDI: 0000000000000003
RBP: 00007fc92fae7ba0 R08: 0000000000000001 R09: 0000002800000000
R10: 00007fc92f700000 R11: 0000000000000246 R12: 00007fc92fae5fac
R13: 00007fc92fae5fa0 R14: 0000000000026d00 R15: 0000000000026c51
 </TASK>
irq event stamp: 4068
hardirqs last  enabled at (4076): [<ffffffff81544816>] __up_console_sem+0x76/0x80 kernel/printk/printk.c:344
hardirqs last disabled at (4085): [<ffffffff815447fb>] __up_console_sem+0x5b/0x80 kernel/printk/printk.c:342
softirqs last  enabled at (3096): [<ffffffff840e1be0>] local_bh_enable include/linux/bottom_half.h:33 [inline]
softirqs last  enabled at (3096): [<ffffffff840e1be0>] inet_csk_listen_stop+0x2c0/0x1070 net/ipv4/inet_connection_sock.c:1524
softirqs last disabled at (3097): [<ffffffff813b6b9f>] do_softirq+0x3f/0x90 kernel/softirq.c:480
---[ end trace 0000000000000000 ]---
netlink: 'syz.6.1422': attribute type 13 has an invalid length.

Logs: syzkaller-logs.txt

[matttbe]

Just in case, the older hit:

audit: type=1400 audit(1750941838.527:39): avc:  denied  { recv } for  pid=226 comm="kworker/0:3" saddr=172.20.20.187 src=54683 daddr=172.20.20.28 dest=20004 netif=lo scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:getty_exec_t:s0 tclass=peer permissive=1
------------[ cut here ]------------
WARNING: CPU: 0 PID: 12822 at net/mptcp/protocol.h:1223 __mptcp_do_fallback net/mptcp/protocol.h:1223 [inline]
WARNING: CPU: 0 PID: 12822 at net/mptcp/protocol.h:1223 mptcp_do_fallback net/mptcp/protocol.h:1244 [inline]
WARNING: CPU: 0 PID: 12822 at net/mptcp/protocol.h:1223 check_fully_established net/mptcp/options.c:982 [inline]
WARNING: CPU: 0 PID: 12822 at net/mptcp/protocol.h:1223 mptcp_incoming_options+0x21a8/0x2510 net/mptcp/options.c:1153
Modules linked in:
CPU: 0 UID: 0 PID: 12822 Comm: syz.4.2729 Not tainted 6.16.0-rc2-g6b0bd1bac6d7 #19 PREEMPT(voluntary) 
Hardware name: QEMU Ubuntu 24.04 PC (i440FX + PIIX, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
RIP: 0010:__mptcp_do_fallback net/mptcp/protocol.h:1223 [inline]
RIP: 0010:mptcp_do_fallback net/mptcp/protocol.h:1244 [inline]
RIP: 0010:check_fully_established net/mptcp/options.c:982 [inline]
RIP: 0010:mptcp_incoming_options+0x21a8/0x2510 net/mptcp/options.c:1153
Code: 24 18 e8 eb 39 01 fd e9 1b df ff ff e8 31 1e 0f 00 e8 2c 48 c5 fc 44 0f b7 ac 24 b0 00 00 00 e9 54 f1 ff ff e8 19 48 c5 fc 90 <0f> 0b 90 e9 b8 f4 ff ff e8 bb 39 01 fd e9 8d e6 ff ff e8 b1 39 01
RSP: 0018:ffff8880a3e08448 EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffff888036bd9700 RCX: ffffffff84aee285
RDX: ffff888041d65280 RSI: ffffffff84aeede7 RDI: 0000000000000001
RBP: ffff88801ab3e400 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: ffff888036bda010 R14: ffff888010a05058 R15: 0000000000000000
FS:  000055555b86e500(0000) GS:ffff88811c397000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fdaca0b91e0 CR3: 0000000014b1d000 CR4: 0000000000350ef0
Call Trace:
 <IRQ>
 tcp_reset+0x26f/0x2b0 net/ipv4/tcp_input.c:4432
 tcp_validate_incoming+0x1057/0x1b60 net/ipv4/tcp_input.c:5975
 tcp_rcv_established+0x5b5/0x21f0 net/ipv4/tcp_input.c:6166
 tcp_v4_do_rcv+0x5dc/0xa70 net/ipv4/tcp_ipv4.c:1925
 tcp_v4_rcv+0x3473/0x44a0 net/ipv4/tcp_ipv4.c:2363
 ip_protocol_deliver_rcu+0xba/0x480 net/ipv4/ip_input.c:205
 ip_local_deliver_finish+0x2f1/0x500 net/ipv4/ip_input.c:233
 NF_HOOK include/linux/netfilter.h:317 [inline]
 NF_HOOK include/linux/netfilter.h:311 [inline]
 ip_local_deliver+0x1be/0x560 net/ipv4/ip_input.c:254
 dst_input include/net/dst.h:469 [inline]
 ip_rcv_finish net/ipv4/ip_input.c:447 [inline]
 NF_HOOK include/linux/netfilter.h:317 [inline]
 NF_HOOK include/linux/netfilter.h:311 [inline]
 ip_rcv+0x514/0x810 net/ipv4/ip_input.c:567
 __netif_receive_skb_one_core+0x197/0x1e0 net/core/dev.c:5975
 __netif_receive_skb+0x1f/0x120 net/core/dev.c:6088
 process_backlog+0x301/0x1360 net/core/dev.c:6440
 __napi_poll.constprop.0+0xba/0x550 net/core/dev.c:7453
 napi_poll net/core/dev.c:7517 [inline]
 net_rx_action+0xb44/0x1010 net/core/dev.c:7644
 handle_softirqs+0x1d0/0x770 kernel/softirq.c:579
 do_softirq+0x3f/0x90 kernel/softirq.c:480
 </IRQ>
 <TASK>
 __local_bh_enable_ip+0xed/0x110 kernel/softirq.c:407
 local_bh_enable include/linux/bottom_half.h:33 [inline]
 inet_csk_listen_stop+0x2c5/0x1070 net/ipv4/inet_connection_sock.c:1524
 mptcp_check_listen_stop.part.0+0x1cc/0x220 net/mptcp/protocol.c:2985
 mptcp_check_listen_stop net/mptcp/mib.h:118 [inline]
 __mptcp_close+0x9b9/0xbd0 net/mptcp/protocol.c:3000
 mptcp_close+0x2f/0x140 net/mptcp/protocol.c:3066
 inet_release+0xed/0x200 net/ipv4/af_inet.c:435
 inet6_release+0x4f/0x70 net/ipv6/af_inet6.c:487
 __sock_release+0xb3/0x270 net/socket.c:649
 sock_close+0x1c/0x30 net/socket.c:1439
 __fput+0x402/0xb70 fs/file_table.c:465
 task_work_run+0x150/0x240 kernel/task_work.c:227
 resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
 exit_to_user_mode_loop+0xd4/0xe0 kernel/entry/common.c:114
 exit_to_user_mode_prepare include/linux/entry-common.h:330 [inline]
 syscall_exit_to_user_mode_work include/linux/entry-common.h:414 [inline]
 syscall_exit_to_user_mode include/linux/entry-common.h:449 [inline]
 do_syscall_64+0x245/0x360 arch/x86/entry/syscall_64.c:100
 entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f6982d836ad
Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 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 b0 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffc3f23b958 EFLAGS: 00000246 ORIG_RAX: 00000000000001b4
RAX: 0000000000000000 RBX: 00007ffc3f23ba28 RCX: 00007f6982d836ad
RDX: 0000000000000000 RSI: 000000000000001e RDI: 0000000000000003
RBP: 00007f6982fc7ba0 R08: 0000000000000001 R09: 0000000d00000000
R10: 00007f6982be0000 R11: 0000000000000246 R12: 00007f6982fc5fac
R13: 00007f6982fc5fa0 R14: 00000000000378a6 R15: 0000000000037817
 </TASK>
irq event stamp: 3218
hardirqs last  enabled at (3226): [<ffffffff81544816>] __up_console_sem+0x76/0x80 kernel/printk/printk.c:344
hardirqs last disabled at (3235): [<ffffffff815447fb>] __up_console_sem+0x5b/0x80 kernel/printk/printk.c:342
softirqs last  enabled at (2250): [<ffffffff840e2bf0>] local_bh_enable include/linux/bottom_half.h:33 [inline]
softirqs last  enabled at (2250): [<ffffffff840e2bf0>] inet_csk_listen_stop+0x2c0/0x1070 net/ipv4/inet_connection_sock.c:1524
softirqs last disabled at (2251): [<ffffffff813b6b9f>] do_softirq+0x3f/0x90 kernel/softirq.c:480
---[ end trace 0000000000000000 ]---

And the logs: syzkaller-logs2.txt

[pabeni]

In both logs, in the relevant syz script there is an mptcp-level disconnect, which in turns unconditionally clears msk->flags owning the mptcp-level lock. As the fallback happens under the first subflow socket lock, the above write is racy, but I can't see how a subflow could observe test_bit(MPTCP_FALLBACK_DONE, &msk->flags) shortly after.

@matttbe: do you know if the syzbot runner execute in different netns? I'm wondering if other program creating MPTCP endpoints could impact the 'current' one

[matttbe]

In both logs, in the relevant syz script there is an mptcp-level disconnect, which in turns unconditionally clears msk->flags owning the mptcp-level lock. As the fallback happens under the first subflow socket lock, the above write is racy, but I can't see how a subflow could observe test_bit(MPTCP_FALLBACK_DONE, &msk->flags) shortly after.

Thank you for having checked the logs! Yes, that's strange :-/

@matttbe: do you know if the syzbot runner execute in different netns? I'm wondering if other program creating MPTCP endpoints could impact the 'current' one

No, if I'm not mistaken, the log shows what happened in the dedicated VM where a few programs are executed, but in the same netns (except if some programs create some, but I didn't see that). So each program could clash with another one I suppose.

[pabeni]

No, if I'm not mistaken, the log shows what happened in the dedicated VM where a few programs are executed, but in the same netns (except if some programs create some, but I didn't see that). So each program could clash with another one I suppose.

Ah, that would explain why it's difficult for syzkaller to create a repro. It also fits the relevant scenario, as at least in one log additional endpoint where created by other runners. Having other subflows, possibly being re-set in other CPUs would allow for the race outlined here.

There are few concurrency problems open that can hit here: fallback, subflow join and allow_infinite fallback checks are not atomic. Additionally subflows are currently joined regarless of the fallback status. I think we need to address all the above to fix the issue at hand here for good.

[matttbe]

There are few concurrency problems open that can hit here: fallback, subflow join and allow_infinite fallback checks are not atomic. Additionally subflows are currently joined regarless of the fallback status. I think we need to address all the above to fix the issue at hand here for good.

Thank you for having checked. Indeed, it should be addressed, but it looks also not urgent.

[pabeni]

@matttbe: FYI, I'm trying to write a series bringing 'atomiticy' to fallback/allow_infinite_fallback tests and updates and hopefully to clean-up the fallback thing. It should solve for good this issue. The main blocker is the extremely limited time avail here.

[matttbe]

The main blocker is the extremely limited time avail here.

Thank you for having still managed to share this fix with us :)