Re: [syzbot] [netfs?] INFO: task hung in netfs_unbuffered_write_iter

[K Prateek Nayak <kprateek.nayak@amd.com>]

Hello Oleg, Mateusz,

On 3/24/2025 2:32 AM, Oleg Nesterov wrote:
> Prateek, Mateusz, thanks for your participation!
> 
> On 03/23, Mateusz Guzik wrote:
>>
>> On Sun, Mar 23, 2025 at 8:47 PM Oleg Nesterov <oleg@redhat.com> wrote:
>>>
>>> OK, as expected.
>>>
>>> Dear syzbot, thank you.
>>>
>>> So far I think this is another problem revealed by aaec5a95d59615523db03dd5
>>> ("pipe_read: don't wake up the writer if the pipe is still full").
>>>
>>> I am going to forget about this report for now and return to it later, when
>>> all the pending pipe-related changes in vfs.git are merged.
>>>
>>
>> How do you ask syzbot for all stacks?
> 
> Heh, I don't know.
> 
>> The reproducer *does* use pipes, but it is unclear to me if they play
>> any role here
> 
> please see the reproducer,
> 
> 	https://syzkaller.appspot.com/x/repro.c?x=10d6a44c580000
> 
>    res = syscall(__NR_pipe2, /*pipefd=*/0x400000001900ul, /*flags=*/0ul);
>    if (res != -1) {
>      r[2] = *(uint32_t*)0x400000001900;
>      r[3] = *(uint32_t*)0x400000001904;
>    }
> 
> then
> 
>    res = syscall(__NR_dup, /*oldfd=*/r[3]);
>    if (res != -1)
>      r[4] = res;
> 
> so r[2] and r[4] are the read/write fd's.
> 
> then later
> 
>     memcpy((void*)0x400000000280, "trans=fd,", 9);
>     ...
>     memcpy((void*)0x400000000289, "rfdno", 5);
>     ...
>     sprintf((char*)0x40000000028f, "0x%016llx", (long long)r[2]);
>     ...
>     memcpy((void*)0x4000000002a2, "wfdno", 5);
>     ...
>     sprintf((char*)0x4000000002a8, "0x%016llx", (long long)r[4]);
>     ...
>     syscall(__NR_mount, /*src=*/0ul, /*dst=*/0x400000000000ul,
>             /*type=*/0x400000000040ul, /*flags=*/0ul, /*opts=*/0x400000000280ul);
> 
> so this pipe is actually used as "trans=fd".
> 
>> -- and notably we don't know if there is someone stuck
>> in pipe code, resulting in not waking up the reported thread.
> 
> Yes, I am not familiar with 9p or netfs, so I don't know either.

Didn't have any luck reproducing this yet but I'm looking at
https://syzkaller.appspot.com/x/log.txt?x=1397319b980000
which is the trimmed log from original report and I see ...

[pid  5842] creat("./file0", 000)       = 7
[  137.753309][   T30] audit: type=1400 audit(1742312362.045:90): avc:  denied  { mount } for  pid=5842 comm="syz-executor309" name="/" dev="9p" ino=2 scontext=root:sysadm_r:sysadm_t tcontext=system_u:object_r:unlabeled_t tclass=filesystem permissive=1
[  137.775741][   T30] audit: type=1400 audit(1742312362.065:91): avc:  denied  { setattr } for  pid=5842 comm="syz-executor309" name="/" dev="9p" ino=2 scontext=root:sysadm_r:sysadm_t tcontext=system_u:object_r:unlabeled_t tclass=file permissive=1
[  137.798215][   T30] audit: type=1400 audit(1742312362.075:92): avc:  denied  { write } for  pid=5842 comm="syz-executor309" dev="9p" ino=2 scontext=root:sysadm_r:sysadm_t tcontext=system_u:object_r:unlabeled_t tclass=file permissive=1
[  137.819189][   T30] audit: type=1400 audit(1742312362.075:93): avc:  denied  { open } for  pid=5842 comm="syz-executor309" path="/file0" dev="9p" ino=2 scontext=root:sysadm_r:sysadm_t tcontext=system_u:object_r:unlabeled_t tclass=file permissive=1
[pid  5842] write(7, "\x08\x00\x00\x00\x1a\x17\x92\x4a\xb2\x18\xea\xcb\x15\xa3\xfc\xcf\x92\x9e\x2d\xd2\x49\x79\x03\xc1\xf8\x53\xd9\x5b\x99\x5c\x65\xe9\x94\x49\xff\x95\x3f\xa1\x1c\x77\x23\xb2\x14\x9e\xcd\xaa\x7f\x83\x3f\x60\xe1\x3b\x19\xa6\x6e\x96\x3f\x7e\x8d\xa4\x29\x7e\xbb\xfd\xda\x5b\x36\xfb\x4d\x01\xbd\x02\xe6\xc6\x52\xdc\x4d\x99\xe2\xcb\x82\xc2\xa1\xd4\xa4\x5e\x4c\x89\xba\x99\x94\xe8\x2f\x85\x4b\xbc\x34\xa4\x0b\x3a"..., 32748 <unfinished ...>

So we have a "write" denied for pid 5842 and then it tries a write that
seems to hangs. In all the traces for hang, I see a denied for a task
followed by a hang for the task in the same tgid.

But since this is a "permissive" policy, it should not cause a hang,
only report that the program is in violation. Also I have no clue how a
spurious wakeup of a writer could then lead to progress.

Since in all cases the thread info flags "flags:0x00004006" has the
TIF_NOTIFY_SIGNAL bit set, I'm wondering if it has something to do with
the fact that pipe_read() directly return -ERESTARTSYS in case of a
pending signal without any wakeups?

Well here goes nothing I guess; Totally a shot in the dark:

P.S. I think it should be wake_next_reader but if this does not hang,
perhaps it could point to some interaction with signal pending and
wakeup. There are some EPOLL semantics in pipe_write() which will
cause readers to wakeup if the writer has signal_pending() and
pipe->poll_usage is set.

#syz test: upstream aaec5a95d59615523db03dd53c2052f0a87beea7

diff --git a/fs/pipe.c b/fs/pipe.c
index 82fede0f2111..9efeb86eaac5 100644
--- a/fs/pipe.c
+++ b/fs/pipe.c
@@ -359,6 +359,8 @@ pipe_read(struct kiocb *iocb, struct iov_iter *to)
  			ret = -EAGAIN;
  			break;
  		}
+		if (signal_pending(current) && pipe_full(pipe->head, pipe->tail, pipe->max_usage))
+			wake_writer = true;
  		mutex_unlock(&pipe->mutex);
  
  		/*