[PATCH] netfs: Fix setting NETFS_RREQ_ALL_QUEUED to be after all subreqs queued

[David Howells <dhowells@redhat.com>]

Hi Ihor,

Okay, the bug you're hitting appears to be a different one to the one I
thought first.  Can you try the attached patch?  I managed to reproduce it
with AFS by injecting a delay.

Grepping your logs for the stuck request, you can see the issue:

          ip: netfs_rreq_ref: R=00002152 NEW         r=1
          ip: netfs_read: R=00002152 READAHEAD c=00000000 ni=1034fe3 s=4000 l=3000 sz=6898
          ip: netfs_rreq_ref: R=00002152 GET SUBREQ  r=2

Subrequest 1 completes synchronously and queues the collector work item:

          ip: netfs_sreq: R=00002152[1] DOWN TERM  f=192 s=4000 2898/2898 s=2 e=0
          ip: netfs_rreq_ref: R=00002152 GET WORK    r=3
kworker/u8:3: netfs_rreq_ref: R=00002152 SEE WORK    r=3
          ip: netfs_sreq_ref: R=00002152[1] PUT TERM    r=1
          ip: netfs_rreq_ref: R=00002152 GET SUBREQ  r=4

Then proposed a new subreq to clear the end of the page, but it's not queued
at this point:

          ip: netfs_sreq: R=00002152[2] ZERO SUBMT f=00 s=6898 0/768 s=0 e=0

(I should probably move the tracepoint to the queue point to make it more
obvious).  The collector processes the subrequests it can see, and
NETFS_RREQ_ALL_QUEUED (0x2000) is set in the flags (f=2021):

kworker/u8:3: netfs_rreq: R=00002152 RA COLLECT f=2021
kworker/u8:3: netfs_collect: R=00002152 s=4000-7000
kworker/u8:3: netfs_collect_sreq: R=00002152[0:01] s=4000 t=2898/2898
kworker/u8:3: netfs_sreq: R=00002152[1] DOWN DSCRD f=92 s=4000 2898/2898 s=2 e=0
kworker/u8:3: netfs_sreq_ref: R=00002152[1] PUT DONE    r=0
kworker/u8:3: netfs_sreq: R=00002152[1] DOWN FREE  f=92 s=4000 2898/2898 s=2 e=0
kworker/u8:3: netfs_rreq_ref: R=00002152 PUT SUBREQ  r=3

The notes (n=x) indicate that the collector didn't see subreq 2 (bit 0,
HIT_PENDING, wasn't set)...:

kworker/u8:3: netfs_collect_state: R=00002152 col=6898 cln=7000 n=c
kworker/u8:3: netfs_collect_state: R=00002152 col=6898 cln=7000 n=8

... and so it completed the request:

kworker/u8:3: netfs_rreq: R=00002152 RA COMPLET f=2021
kworker/u8:3: netfs_rreq: R=00002152 RA WAKE-IP f=2021

And now, NETFS_RREQ_IN_PROGRESS has been cleared, which means we can't get
back into the read collector.

kworker/u8:3: netfs_rreq: R=00002152 RA DONE    f=2001
kworker/u8:3: netfs_rreq_ref: R=00002152 PUT WORK    r=2

Then subreq 2 finishes and you can see the worker happen, but do nothing:

          ip: netfs_sreq: R=00002152[2] ZERO TERM  f=102 s=6898 768/768 s=2 e=0
          ip: netfs_rreq_ref: R=00002152 GET WORK    r=3
kworker/u8:3: netfs_rreq_ref: R=00002152 SEE WORK    r=3
kworker/u8:3: netfs_rreq_ref: R=00002152 PUT WORK    r=2

David
---
netfs: Fix setting NETFS_RREQ_ALL_QUEUED to be after all subreqs queued

Due to the code that queues a subreq on the active subrequest list getting
moved to netfs_issue_read(), the NETFS_RREQ_ALL_QUEUED flag may now get set
before the list-add actually happens.  This is not a problem if the
collection worker happens after the list-add, but it's a race - and, for
9P, where the read from the server is synchronous and done in the
submitting thread, this is a lot more likely.

The result is that, if the timing is wrong, a ref gets leaked because the
collector thinks that all the subreqs have completed (because it can't see
the last one yet) and clears NETFS_RREQ_IN_PROGRESS - at which point, the
collection worker no longer goes into the collector.

This can be provoked with AFS by injecting an msleep() right before the
final subreq is queued.

Fix this by splitting the queuing part out of netfs_issue_read() into a new
function, netfs_queue_read(), and calling it separately.  The setting of
NETFS_RREQ_ALL_QUEUED is then done by netfs_queue_read() whilst it is
holding the spinlock (that's probably unnecessary, but shouldn't hurt).

It might be better to set a flag on the final subreq, but this could be a
problem if an error occurs and we can't queue it.

Fixes: e2d46f2ec332 ("netfs: Change the read result collector to only use one work item")
Reported-by: Ihor Solodrai <ihor.solodrai@pm.me>
Closes: https://lore.kernel.org/r/a7x33d4dnMdGTtRivptq6S1i8btK70SNBP2XyX_xwDAhLvgQoPox6FVBOkifq4eBinfFfbZlIkMZBe3QarlWTxoEtHZwJCZbNKtaqrR7PvI=@pm.me/
Signed-off-by: David Howells <dhowells@redhat.com>
cc: Eric Van Hensbergen <ericvh@kernel.org>
cc: Latchesar Ionkov <lucho@ionkov.net>
cc: Dominique Martinet <asmadeus@codewreck.org>
cc: Christian Schoenebeck <linux_oss@crudebyte.com>
cc: Marc Dionne <marc.dionne@auristor.com>
cc: Steve French <stfrench@microsoft.com>
cc: Paulo Alcantara <pc@manguebit.com>
cc: Jeff Layton <jlayton@kernel.org>
cc: v9fs@lists.linux.dev
cc: linux-cifs@vger.kernel.org
cc: netfs@lists.linux.dev
cc: linux-fsdevel@vger.kernel.org
---
 fs/netfs/buffered_read.c |   19 +++++++++++++------
 1 file changed, 13 insertions(+), 6 deletions(-)

diff --git a/fs/netfs/buffered_read.c b/fs/netfs/buffered_read.c
index f761d44b3436..0d1b6d35ff3b 100644
--- a/fs/netfs/buffered_read.c
+++ b/fs/netfs/buffered_read.c
@@ -155,8 +155,9 @@ static void netfs_read_cache_to_pagecache(struct netfs_io_request *rreq,
 			netfs_cache_read_terminated, subreq);
 }
 
-static void netfs_issue_read(struct netfs_io_request *rreq,
-			     struct netfs_io_subrequest *subreq)
+static void netfs_queue_read(struct netfs_io_request *rreq,
+			     struct netfs_io_subrequest *subreq,
+			     bool last_subreq)
 {
 	struct netfs_io_stream *stream = &rreq->io_streams[0];
 
@@ -177,8 +178,17 @@ static void netfs_issue_read(struct netfs_io_request *rreq,
 		}
 	}
 
+	if (last_subreq) {
+		smp_wmb(); /* Write lists before ALL_QUEUED. */
+		set_bit(NETFS_RREQ_ALL_QUEUED, &rreq->flags);
+	}
+
 	spin_unlock(&rreq->lock);
+}
 
+static void netfs_issue_read(struct netfs_io_request *rreq,
+			     struct netfs_io_subrequest *subreq)
+{
 	switch (subreq->source) {
 	case NETFS_DOWNLOAD_FROM_SERVER:
 		rreq->netfs_ops->issue_read(subreq);
@@ -293,11 +303,8 @@ static void netfs_read_to_pagecache(struct netfs_io_request *rreq)
 		}
 		size -= slice;
 		start += slice;
-		if (size <= 0) {
-			smp_wmb(); /* Write lists before ALL_QUEUED. */
-			set_bit(NETFS_RREQ_ALL_QUEUED, &rreq->flags);
-		}
 
+		netfs_queue_read(rreq, subreq, size <= 0);
 		netfs_issue_read(rreq, subreq);
 		cond_resched();
 	} while (size > 0);