Re: [PATCH v2 0/2] fuse: add timeout option for requests

[Yafang Shao <laoar.shao@gmail.com>]

On Thu, Aug 1, 2024 at 2:46 AM Joanne Koong <joannelkoong@gmail.com> wrote:
>
> On Wed, Jul 31, 2024 at 10:52 AM Joanne Koong <joannelkoong@gmail.com> wrote:
> >
> > On Tue, Jul 30, 2024 at 7:14 PM Yafang Shao <laoar.shao@gmail.com> wrote:
> > >
> > > On Wed, Jul 31, 2024 at 2:16 AM Joanne Koong <joannelkoong@gmail.com> wrote:
> > > >
> > > > On Mon, Jul 29, 2024 at 11:00 PM Yafang Shao <laoar.shao@gmail.com> wrote:
> > > > >
> > > > > On Tue, Jul 30, 2024 at 8:28 AM Joanne Koong <joannelkoong@gmail.com> wrote:
> > > > > >
> > > > > > There are situations where fuse servers can become unresponsive or take
> > > > > > too long to reply to a request. Currently there is no upper bound on
> > > > > > how long a request may take, which may be frustrating to users who get
> > > > > > stuck waiting for a request to complete.
> > > > > >
> > > > > > This patchset adds a timeout option for requests and two dynamically
> > > > > > configurable fuse sysctls "default_request_timeout" and "max_request_timeout"
> > > > > > for controlling/enforcing timeout behavior system-wide.
> > > > > >
> > > > > > Existing fuse servers will not be affected unless they explicitly opt into the
> > > > > > timeout.
> > > > > >
> > > > > > v1: https://lore.kernel.org/linux-fsdevel/20240717213458.1613347-1-joannelkoong@gmail.com/
> > > > > > Changes from v1:
> > > > > > - Add timeout for background requests
> > > > > > - Handle resend race condition
> > > > > > - Add sysctls
> > > > > >
> > > > > > Joanne Koong (2):
> > > > > >   fuse: add optional kernel-enforced timeout for requests
> > > > > >   fuse: add default_request_timeout and max_request_timeout sysctls
> > > > > >
> > > > > >  Documentation/admin-guide/sysctl/fs.rst |  17 +++
> > > > > >  fs/fuse/Makefile                        |   2 +-
> > > > > >  fs/fuse/dev.c                           | 187 +++++++++++++++++++++++-
> > > > > >  fs/fuse/fuse_i.h                        |  30 ++++
> > > > > >  fs/fuse/inode.c                         |  24 +++
> > > > > >  fs/fuse/sysctl.c                        |  42 ++++++
> > > > > >  6 files changed, 293 insertions(+), 9 deletions(-)
> > > > > >  create mode 100644 fs/fuse/sysctl.c
> > > > > >
> > > > > > --
> > > > > > 2.43.0
> > > > > >
> > > > >
> > > > > Hello Joanne,
> > > > >
> > > > > Thanks for your update.
> > > > >
> > > > > I have tested your patches using my test case, which is similar to the
> > > > > hello-fuse [0] example, with an additional change as follows:
> > > > >
> > > > > @@ -125,6 +125,8 @@ static int hello_read(const char *path, char *buf,
> > > > > size_t size, off_t offset,
> > > > >         } else
> > > > >                 size = 0;
> > > > >
> > > > > +       // TO trigger timeout
> > > > > +       sleep(60);
> > > > >         return size;
> > > > >  }
> > > > >
> > > > > [0] https://github.com/libfuse/libfuse/blob/master/example/hello.c
> > > > >
> > > > > However, it triggered a crash with the following setup:
> > > > >
> > > > > 1. Set FUSE timeout:
> > > > >   sysctl -w fs.fuse.default_request_timeout=10
> > > > >   sysctl -w fs.fuse.max_request_timeout = 20
> > > > >
> > > > > 2. Start FUSE daemon:
> > > > >   ./hello /tmp/fuse
> > > > >
> > > > > 3. Read from FUSE:
> > > > >   cat /tmp/fuse/hello
> > > > >
> > > > > 4. Kill the process within 10 seconds (to avoid the timeout being triggered).
> > > > >    Then the crash will be triggered.
> > > >
> > > > Hi Yafang,
> > > >
> > > > Thanks for trying this out on your use case!
> > > >
> > > > How consistently are you able to repro this?
> > >
> > > It triggers the crash every time.
> > >
> > > > I tried reproing using
> > > > your instructions above but I'm not able to get the crash.
> > >
> > > Please note that it is the `cat /tmp/fuse/hello` process that was
> > > killed, not the fuse daemon.
> > > The crash seems to occur when the fuse daemon wakes up after
> > > sleep(60). Please ensure that the fuse daemon can be woken up.
> > >
> >
> > I'm still not able to trigger the crash by killing the `cat
> > /tmp/fuse/hello` process. This is how I'm repro-ing
> >
> > 1) Add sleep to test code in
> > https://github.com/libfuse/libfuse/blob/master/example/hello.c
> > @@ -125,6 +126,9 @@ static int hello_read(const char *path, char *buf,
> > size_t size, off_t offset,
> >         } else
> >                 size = 0;
> >
> > +       sleep(60);
> > +       printf("hello_read woke up from sleep\n");
> > +
> >         return size;
> >  }
> >
> > 2)  Set fuse timeout to 10 seconds
> > sysctl -w fs.fuse.default_request_timeout=10
> >
> > 3) Start fuse daemon
> > ./example/hello ./tmp/fuse
> >
> > 4) Read from fuse
> > cat /tmp/fuse/hello
> >
> > 5) Get pid of cat process
> > top -b | grep cat
> >
> > 6) Kill cat process (within 10 seconds)
> >  sudo kill -9 <cat-pid>
> >
> > 7) Wait 60 seconds for fuse's read request to complete
> >
> > From what it sounds like, this is exactly what you are doing as well?
> >
> > I added some kernel-side logs and I'm seeing that the read request is
> > timing out after ~10 seconds and handled by the timeout handler
> > successfully.
> >
> > On the fuse daemon side, these are the logs I'm seeing from the above repro:
> > ./example/hello /tmp/fuse -f -d
> >
> > FUSE library version: 3.17.0
> > nullpath_ok: 0
> > unique: 2, opcode: INIT (26), nodeid: 0, insize: 104, pid: 0
> > INIT: 7.40
> > flags=0x73fffffb
> > max_readahead=0x00020000
> >    INIT: 7.40
> >    flags=0x4040f039
> >    max_readahead=0x00020000
> >    max_write=0x00100000
> >    max_background=0
> >    congestion_threshold=0
> >    time_gran=1
> >    unique: 2, success, outsize: 80
> > unique: 4, opcode: LOOKUP (1), nodeid: 1, insize: 46, pid: 673
> > LOOKUP /hello
> > getattr[NULL] /hello
> >    NODEID: 2
> >    unique: 4, success, outsize: 144
> > unique: 6, opcode: OPEN (14), nodeid: 2, insize: 48, pid: 673
> > open flags: 0x8000 /hello
> >    open[0] flags: 0x8000 /hello
> >    unique: 6, success, outsize: 32
> > unique: 8, opcode: READ (15), nodeid: 2, insize: 80, pid: 673
> > read[0] 4096 bytes from 0 flags: 0x8000
> > unique: 10, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 673
> >    unique: 10, error: -38 (Function not implemented), outsize: 16
> > unique: 11, opcode: INTERRUPT (36), nodeid: 0, insize: 48, pid: 0
> > FUSE_INTERRUPT: reply to kernel to disable interrupt
> >    unique: 11, error: -38 (Function not implemented), outsize: 16
> >
> > unique: 12, opcode: RELEASE (18), nodeid: 2, insize: 64, pid: 0
> >    unique: 12, success, outsize: 16
> >
> > hello_read woke up from sleep
> >    read[0] 13 bytes from 0
> >    unique: 8, success, outsize: 29
> >
> >
> > Are these the debug logs you are seeing from the daemon side as well?
> >
> > Thanks,
> > Joanne
> > > >
> > > > From the crash logs you provided below, it looks like what's happening
> > > > is that if the process gets killed, the timer isn't getting deleted.
>
> When I looked at this log previously, I thought you were repro-ing by
> killing the fuse daemon process, not the cat process. When we kill the
> cat process, the timer shouldn't be getting deleted. (if the daemon
> itself is killed, the timers get deleted)
>
> > > > I'll look more into what happens in fuse when a process is killed and
> > > > get back to you on this.
>
> This is the flow of what is happening on the kernel side (verified by
> local printks) -
>
> `cat /tmp/fuse/hello`:
> Issues a FUSE_READ background request (via fuse_send_readpages(),
> fm->fc->async_read). This request will have a timeout of 10 seconds on
> it
>
> The cat process is killed:
> This does not clean up the request. The request is still on the fpq
> processing list.
>
> Timeout on request expires:
> The timeout handler runs and properly cleans up / frees the request.
>
> Fuse daemon wakes from sleep and replies to the request:
> In dev_do_write(), the kernel won't be able to find this request
> (since it timed out and was removed from the fpq processing list) and
> return with -ENOENT

Thank you for your explanation.
I will verify if there are any issues with my test environment.

--
Regards
Yafang