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

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

Hello Mateusz,

On 3/24/2025 6:47 PM, Mateusz Guzik wrote:
> On Mon, Mar 24, 2025 at 11:48 AM K Prateek Nayak <kprateek.nayak@amd.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@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?
>>
> 
> 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.

I got the reproducer running locally. Tracing stuff currently to see
what is tripping. Will report back once I find something interesting.
Might take a while since the 9p bits are so far spread out.

-- 
Thanks and Regards,
Prateek