Message-ID: <CAGudoHH9w8VO8069iKf_TsAjnfuRSrgiJ2e2D9-NGEDgXW+Lcw@mail.gmail.com>
Date: Mon, 24 Mar 2025 14:17:11 +0100
From: Mateusz Guzik <mjguzik@...il.com>
To: K Prateek Nayak <kprateek.nayak@....com>
Cc: Oleg Nesterov <oleg@...hat.com>, 
	syzbot <syzbot+62262fdc0e01d99573fc@...kaller.appspotmail.com>, brauner@...nel.org, 
	dhowells@...hat.com, jack@...e.cz, jlayton@...nel.org, 
	linux-fsdevel@...r.kernel.org, linux-kernel@...r.kernel.org, 
	netfs@...ts.linux.dev, swapnil.sapkal@....com, 
	syzkaller-bugs@...glegroups.com, viro@...iv.linux.org.uk
Subject: Re: [syzbot] [netfs?] INFO: task hung in netfs_unbuffered_write_iter

On Mon, Mar 24, 2025 at 11:48 AM K Prateek Nayak <kprateek.nayak@....com> wrote:
>
> 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@...hat.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?
>

Per syzbot this attempt did not work out either.

I think the blind stabs taken by everyone here are enough.

The report does not provide the crucial bit: what are the other
threads doing. Presumably someone else is stuck somewhere, possibly
not even in pipe code and that stuck thread was supposed to wake up
the one which trips over hung task detector. Figuring out what that
thread is imo the next step.

I failed to find a relevant command in
https://github.com/google/syzkaller/blob/master/docs/syzbot.md

So if you guys know someone on syzkaller side, maybe you can ask them
to tweak the report *or* maybe syzbot can test a "fix" which makes
hung task detector also report all backtraces? I don't know if that
can work, the output may be long enough that it will get trimmed by
something.

I don't have to time work on this for now, just throwing ideas.
-- 
Mateusz Guzik <mjguzik gmail.com>

Powered by blists - more mailing lists