[syzbot] [fs?] INFO: task hung in pipe_release (4)

[syzbot] [fs?] INFO: task hung in pipe_release (4)

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit:    3f01e9fed845 Merge tag 'linux-watchdog-6.5-rc2' of git://w..
git tree:       upstream
console+strace: https://syzkaller.appspot.com/x/log.txt?x=16c5cd8ca80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=150188feee7071a7
dashboard link: https://syzkaller.appspot.com/bug?extid=f527b971b4bdc8e79f9e
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=12a86682a80000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=1520ab6ca80000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/991cea284d12/disk-3f01e9fe.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/13051b4d971a/vmlinux-3f01e9fe.xz
kernel image: https://storage.googleapis.com/syzbot-assets/31cc7c3c2596/bzImage-3f01e9fe.xz

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

INFO: task syz-executor421:5031 blocked for more than 143 seconds.
      Not tainted 6.5.0-rc1-syzkaller-00006-g3f01e9fed845 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor421 state:D stack:27728 pid:5031  ppid:5021   flags:0x00004006
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0xc9a/0x5880 kernel/sched/core.c:6710
 schedule+0xde/0x1a0 kernel/sched/core.c:6786
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6845
 __mutex_lock_common kernel/locking/mutex.c:679 [inline]
 __mutex_lock+0xa3b/0x1350 kernel/locking/mutex.c:747
 __pipe_lock fs/pipe.c:103 [inline]
 pipe_release+0x4d/0x310 fs/pipe.c:721
 __fput+0x40c/0xad0 fs/file_table.c:384
 task_work_run+0x16f/0x270 kernel/task_work.c:179
 ptrace_notify+0x118/0x140 kernel/signal.c:2372
 ptrace_report_syscall include/linux/ptrace.h:411 [inline]
 ptrace_report_syscall_exit include/linux/ptrace.h:473 [inline]
 syscall_exit_work kernel/entry/common.c:252 [inline]
 syscall_exit_to_user_mode_prepare+0x129/0x220 kernel/entry/common.c:279
 __syscall_exit_to_user_mode_work kernel/entry/common.c:284 [inline]
 syscall_exit_to_user_mode+0xd/0x50 kernel/entry/common.c:297
 do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fbe8982b7da
RSP: 002b:00007ffd74cb3820 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 00007fbe8982b7da
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
RBP: 000000000000000a R08: 0000000000000000 R09: 00007ffd74d90080
R10: 0000000000000000 R11: 0000000000000293 R12: 000000000000a9f7
R13: 000000000000aa29 R14: 00007fbe898b642c R15: 00007fbe898b6420
 </TASK>

Showing all locks held in the system:
1 lock held by rcu_tasks_kthre/13:
 #0: ffffffff8c9a3af0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:522
1 lock held by rcu_tasks_trace/14:
 #0: ffffffff8c9a37f0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:522
1 lock held by khungtaskd/28:
 #0: ffffffff8c9a4700 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x55/0x340 kernel/locking/lockdep.c:6615
2 locks held by getty/4773:
 #0: ffff88802d33a098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:243
 #1: ffffc900015c02f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xf08/0x13f0 drivers/tty/n_tty.c:2187
1 lock held by syz-executor421/5031:
 #0: ffff888022606868 (&pipe->mutex/1){+.+.}-{3:3}, at: __pipe_lock fs/pipe.c:103 [inline]
 #0: ffff888022606868 (&pipe->mutex/1){+.+.}-{3:3}, at: pipe_release+0x4d/0x310 fs/pipe.c:721
2 locks held by syz-executor421/5032:

=============================================

NMI backtrace for cpu 1
CPU: 1 PID: 28 Comm: khungtaskd Not tainted 6.5.0-rc1-syzkaller-00006-g3f01e9fed845 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/03/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0xd9/0x150 lib/dump_stack.c:106
 nmi_cpu_backtrace+0x29c/0x350 lib/nmi_backtrace.c:113
 nmi_trigger_cpumask_backtrace+0x2a4/0x300 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:160 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
 watchdog+0xe16/0x1090 kernel/hung_task.c:379
 kthread+0x344/0x440 kernel/kthread.c:389
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
 </TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 5032 Comm: syz-executor421 Not tainted 6.5.0-rc1-syzkaller-00006-g3f01e9fed845 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/03/2023
RIP: 0010:__ip_append_data+0x957/0x3c90 net/ipv4/ip_output.c:1198
Code: 31 ff 29 eb 89 de e8 d8 6d e9 f8 85 db 0f 8e b5 1a 00 00 e8 ab 71 e9 f8 48 8b 44 24 38 41 39 de 41 0f 4e de 41 89 dc 80 38 00 <0f> 85 15 29 00 00 48 8b 44 24 18 48 8b 18 48 8d bb f0 00 00 00 48
RSP: 0018:ffffc90003b9f520 EFLAGS: 00000246
RAX: ffffed100fab0f00 RBX: 0000000000000006 RCX: 0000000000000000
RDX: ffff888019e95940 RSI: ffffffff889b7015 RDI: 0000000000000005
RBP: 000000000000001c R08: 0000000000000005 R09: 0000000000000000
R10: 000000000000057e R11: 0000000000000001 R12: 0000000000000006
R13: dffffc0000000000 R14: 0000000000000006 R15: ffff8880132dd3c0
FS:  00007fbe897e96c0(0000) GS:ffff8880b9800000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00005598ca226780 CR3: 00000000193f8000 CR4: 0000000000350ef0
Call Trace:
 <NMI>
 </NMI>
 <TASK>
 ip_append_data net/ipv4/ip_output.c:1352 [inline]
 ip_append_data+0x115/0x1a0 net/ipv4/ip_output.c:1331
 udp_sendmsg+0x881/0x2840 net/ipv4/udp.c:1287
 inet_sendmsg+0x9d/0xe0 net/ipv4/af_inet.c:830
 sock_sendmsg_nosec net/socket.c:725 [inline]
 sock_sendmsg+0xde/0x190 net/socket.c:748
 splice_to_socket+0x964/0xee0 fs/splice.c:882
 do_splice_from fs/splice.c:934 [inline]
 do_splice+0xb8a/0x1ec0 fs/splice.c:1295
 __do_splice+0x14e/0x270 fs/splice.c:1373
 __do_sys_splice fs/splice.c:1584 [inline]
 __se_sys_splice fs/splice.c:1566 [inline]
 __x64_sys_splice+0x19c/0x250 fs/splice.c:1566
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x39/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7fbe8982c519
Code: 28 00 00 00 75 05 48 83 c4 28 c3 e8 61 1a 00 00 90 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:00007fbe897e9218 EFLAGS: 00000246 ORIG_RAX: 0000000000000113
RAX: ffffffffffffffda RBX: 00007fbe898b6428 RCX: 00007fbe8982c519
RDX: 0000000000000005 RSI: 0000000000000000 RDI: 0000000000000003
RBP: 00007fbe898b6420 R08: 000000000004ffe0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fbe898b642c
R13: 00007fbe898834f4 R14: 04000000000003bd R15: 00007ffd74cb3758
 </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.

If the bug is already fixed, 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 change bug's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

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

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

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[syzbot]

syzbot has bisected this issue to:

commit 7ac7c987850c3ec617c778f7bd871804dc1c648d
Author: David Howells <dhowells@redhat.com>
Date:   Mon May 22 12:11:22 2023 +0000

    udp: Convert udp_sendpage() to use MSG_SPLICE_PAGES

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=15853bcaa80000
start commit:   3f01e9fed845 Merge tag 'linux-watchdog-6.5-rc2' of git://w..
git tree:       upstream
final oops:     https://syzkaller.appspot.com/x/report.txt?x=17853bcaa80000
console output: https://syzkaller.appspot.com/x/log.txt?x=13853bcaa80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=150188feee7071a7
dashboard link: https://syzkaller.appspot.com/bug?extid=f527b971b4bdc8e79f9e
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=12a86682a80000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=1520ab6ca80000

Reported-by: syzbot+f527b971b4bdc8e79f9e@syzkaller.appspotmail.com
Fixes: 7ac7c987850c ("udp: Convert udp_sendpage() to use MSG_SPLICE_PAGES")

For information about bisection process see: https://goo.gl/tpsmEJ#bisection

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[Jakub Kicinski]

On Wed, 12 Jul 2023 11:54:33 -0700 syzbot wrote:
> syzbot has bisected this issue to:
> 
> commit 7ac7c987850c3ec617c778f7bd871804dc1c648d
> Author: David Howells <dhowells@redhat.com>
> Date:   Mon May 22 12:11:22 2023 +0000
> 
>     udp: Convert udp_sendpage() to use MSG_SPLICE_PAGES
> 
> bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=15853bcaa80000
> start commit:   3f01e9fed845 Merge tag 'linux-watchdog-6.5-rc2' of git://w..
> git tree:       upstream
> final oops:     https://syzkaller.appspot.com/x/report.txt?x=17853bcaa80000
> console output: https://syzkaller.appspot.com/x/log.txt?x=13853bcaa80000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=150188feee7071a7
> dashboard link: https://syzkaller.appspot.com/bug?extid=f527b971b4bdc8e79f9e
> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=12a86682a80000
> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=1520ab6ca80000
> 
> Reported-by: syzbot+f527b971b4bdc8e79f9e@syzkaller.appspotmail.com
> Fixes: 7ac7c987850c ("udp: Convert udp_sendpage() to use MSG_SPLICE_PAGES")
> 
> For information about bisection process see: https://goo.gl/tpsmEJ#bisection

Hi David, any ideas about this one? Looks like it triggers on fairly
recent upstream?

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[David Howells]

Note that the test program is dodgy:

    pipe(&(0x7f0000000100)={<r0=>0xffffffffffffffff, <r1=>0xffffffffffffffff})
    r2 = socket$inet_udp(0x2, 0x2, 0x0)

r2 is closed here:

    close(r2)
    r3 = socket$inet_udp(0x2, 0x2, 0x0)
    setsockopt$sock_int(r3, 0x1, 0x6, &(0x7f0000000140)=0x32, 0x4)
    bind$inet(r3, &(0x7f0000000000)={0x2, 0x0, @dev={0xac, 0x14, 0x14, 0x15}}, 0x10)
    connect$inet(r3, &(0x7f0000000200)={0x2, 0x0, @broadcast}, 0x10)
    sendmmsg(r3, &(0x7f0000000180)=[{{0x0, 0x0, 0x0}}, {{0x0, 0xfffffffffffffed3, &(0x7f0000000940)=[{&(0x7f00000006c0)='O', 0x57e}], 0x1}}], 0x4000000000003bd, 0x8800)
    write$binfmt_misc(r1, &(0x7f0000000440)=ANY=[], 0x8)

but then used here:

    splice(r0, 0x0, r2, 0x0, 0x4ffe0, 0x0)

As it happens, r3 will probably end up referring to the same fd as r2 did, but
that's not guaranteed.

David

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[David Howells]

Jakub Kicinski <kuba@kernel.org> wrote:

> Hi David, any ideas about this one? Looks like it triggers on fairly
> recent upstream?

I've managed to reproduce it finally.  Instrumenting the pipe_lock/unlock
functions, splice_to_socket() and pipe_release() seems to show that
pipe_release() is being called whilst splice_to_socket() is still running.

I *think* syzbot is arranging things such that splice_to_socket() takes a
significant amount of time so that another thread can close the socket as it
exits.

In this sample logging, the pipe is created by pid 7101:

[   66.205719] --pipe 7101
[   66.209942] lock
[   66.212526] locked
[   66.215344] unlock
[   66.218103] unlocked

splice begins in 7101 also and locks the pipe:

[   66.221057] ==>splice_to_socket() 7101
[   66.225596] lock
[   66.228177] locked

but for some reason, pid 7100 then tries to release it:

[   66.377781] release 7100

and hangs on the __pipe_lock() call in pipe_release():

[   66.381059] lock

The syz reproducer does weird things with threading - and I'm wondering if
there's a file struct refcount bug here.  Note that splice_to_socket() can't
access the pipe file structs to alter the refcount, and the involved pipe
isn't communicated to udp_sendmsg() in any way - so if there is a refcount
bug, it must be somewhere in the VFS, the pipe driver or the splice
infrastructure:-/.

I'm also not sure what's going on inside udp_sendmsg() as yet.  It doesn't
show a stack in /proc/7101/stacks, which means it doesn't hit a schedule().

David

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[David Howells]

David Howells <dhowells@redhat.com> wrote:

> I've managed to reproduce it finally.  Instrumenting the pipe_lock/unlock
> functions, splice_to_socket() and pipe_release() seems to show that
> pipe_release() is being called whilst splice_to_socket() is still running.

That's actually a bit of a red herring.  pipe_release() is so-called because
it's called as the release file op for an end of the pipe.  It doesn't
automatically free the pipe_inode_info struct - there's refcounting on that.

So the problem is that udp_sendmsg() didn't return; pipe_release() hanging on
the pipe_lock() is merely a noisy symptom thereof.

David

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[syzbot]

Hello,

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

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

Tested on:

commit:         3f01e9fe Merge tag 'linux-watchdog-6.5-rc2' of git://w..
git tree:       https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
console output: https://syzkaller.appspot.com/x/log.txt?x=1208a829a80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=87ef4ae61b35aae1
dashboard link: https://syzkaller.appspot.com/bug?extid=f527b971b4bdc8e79f9e
compiler:       gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch:          https://syzkaller.appspot.com/x/patch.diff?x=14dbfef6a80000

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

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[David Howells]

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

udp: Fix __ip_append_data()'s handling of MSG_SPLICE_PAGES
    
__ip_append_data() can get into an infinite loop when asked to splice into
a partially-built UDP message that has more than the frag-limit data and up
to the MTU limit.  Something like:

        pipe(pfd);
        sfd = socket(AF_INET, SOCK_DGRAM, 0);
        connect(sfd, ...);
        send(sfd, buffer, 8161, MSG_CONFIRM|MSG_MORE);
        write(pfd[1], buffer, 8);
        splice(pfd[0], 0, sfd, 0, 0x4ffe0ul, 0);

where the amount of data given to send() is dependent on the MTU size (in
this instance an interface with an MTU of 8192).

The problem is that the calculation of the amount to copy in
__ip_append_data() goes negative in two places, and, in the second place,
this gets subtracted from the length remaining, thereby increasing it.

This happens when pagedlen > 0 (which happens for MSG_ZEROCOPY and
MSG_SPLICE_PAGES), because the terms in:

        copy = datalen - transhdrlen - fraggap - pagedlen;

then mostly cancel when pagedlen is substituted for, leaving just -fraggap.
This causes:

        length -= copy + transhdrlen;

to increase the length to more than the amount of data in msg->msg_iter,
which causes skb_splice_from_iter() to be unable to fill the request and it
returns less than 'copied' - which means that length never gets to 0 and we
never exit the loop.

Fix this by:

 (1) Insert a note about the dodgy calculation of 'copy'.

 (2) If MSG_SPLICE_PAGES, clear copy if it is negative from the above
     equation, so that 'offset' isn't regressed and 'length' isn't
     increased, which will mean that length and thus copy should match the
     amount left in the iterator.

 (3) When handling MSG_SPLICE_PAGES, give a warning and return -EIO if
     we're asked to splice more than is in the iterator.  It might be
     better to not give the warning or even just give a 'short' write.

[!] Note that this ought to also affect MSG_ZEROCOPY, but MSG_ZEROCOPY
avoids the problem by simply assuming that everything asked for got copied,
not just the amount that was in the iterator.  This is a potential bug for
the future.

Fixes: 7ac7c987850c ("udp: Convert udp_sendpage() to use MSG_SPLICE_PAGES")
Reported-by: syzbot+f527b971b4bdc8e79f9e@syzkaller.appspotmail.com
Link: https://lore.kernel.org/r/000000000000881d0606004541d1@google.com/
Signed-off-by: David Howells <dhowells@redhat.com>
cc: Willem de Bruijn <willemdebruijn.kernel@gmail.com>
cc: "David S. Miller" <davem@davemloft.net>
cc: Eric Dumazet <edumazet@google.com>
cc: Jakub Kicinski <kuba@kernel.org>
cc: Paolo Abeni <pabeni@redhat.com>
cc: David Ahern <dsahern@kernel.org>
cc: Jens Axboe <axboe@kernel.dk>
cc: netdev@vger.kernel.org
---
 net/ipv4/ip_output.c |    9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/net/ipv4/ip_output.c b/net/ipv4/ip_output.c
index 6e70839257f7..91715603cf6e 100644
--- a/net/ipv4/ip_output.c
+++ b/net/ipv4/ip_output.c
@@ -1158,10 +1158,15 @@ static int __ip_append_data(struct sock *sk,
 			}
 
 			copy = datalen - transhdrlen - fraggap - pagedlen;
+			/* [!] NOTE: copy will be negative if pagedlen>0
+			 * because then the equation reduces to -fraggap.
+			 */
 			if (copy > 0 && getfrag(from, data + transhdrlen, offset, copy, fraggap, skb) < 0) {
 				err = -EFAULT;
 				kfree_skb(skb);
 				goto error;
+			} else if (flags & MSG_SPLICE_PAGES) {
+				copy = 0;
 			}
 
 			offset += copy;
@@ -1209,6 +1214,10 @@ static int __ip_append_data(struct sock *sk,
 		} else if (flags & MSG_SPLICE_PAGES) {
 			struct msghdr *msg = from;
 
+			err = -EIO;
+			if (WARN_ON_ONCE(copy > msg->msg_iter.count))
+				goto error;
+
 			err = skb_splice_from_iter(skb, &msg->msg_iter, copy,
 						   sk->sk_allocation);
 			if (err < 0)

Re: [syzbot] [fs?] INFO: task hung in pipe_release (4)

[syzbot]

Hello,

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

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

Tested on:

commit:         5d0c230f Linux 6.5-rc4
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=15a8b5d5a80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=df103238a07f256e
dashboard link: https://syzkaller.appspot.com/bug?extid=f527b971b4bdc8e79f9e
compiler:       gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch:          https://syzkaller.appspot.com/x/patch.diff?x=17e285dea80000

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