Linux-NFS Archive on lore.kernel.org
 help / color / Atom feed
* [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
@ 2019-10-10  7:40 Murphy Zhou
  2019-10-10 14:46 ` Trond Myklebust
  2019-10-10 17:32 ` Olga Kornievskaia
  0 siblings, 2 replies; 9+ messages in thread
From: Murphy Zhou @ 2019-10-10  7:40 UTC (permalink / raw)
  To: linux-nfs, Trond Myklebust

Since commit:
  [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE

xfstests generic/168 on v4.2 starts to fail because reflink call gets:
  +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable

In tshark output, NFS4ERR_OLD_STATEID stands out when comparing with
good ones:

 5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
 5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
 5212   NFS 250 V4 Reply (Call In 5211) GETATTR
 5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
 5214   NFS 250 V4 Reply (Call In 5213) GETATTR
 5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len: 65536
 5218   NFS 266 V4 Reply (Call In 5216) WRITE
 5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
 5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
 5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
 5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status: NFS4ERR_OLD_STATEID
 5225   NFS 338 V4 Call CLOSE StateID: 0xa342
 5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
 5227   NFS 266 V4 Reply (Call In 5225) CLOSE
 5228   NFS 250 V4 Reply (Call In 5226) GETATTR

It's easy to reproduce. By printing some logs, found that we are making
CLOSE seqid larger then OPEN seqid when racing.

Fix this by not bumping seqid when it's equal to OPEN seqid. Also
put the whole changing process into seqlock read protection in case
really bad luck, and this is the same locking behavior with the
old deleted function.

Fixes: 0e0cb35b417f ("NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE")
Signed-off-by: Murphy Zhou <jencce.kernel@gmail.com>
---
 fs/nfs/nfs4proc.c | 13 ++++++++-----
 1 file changed, 8 insertions(+), 5 deletions(-)

diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
index 11eafcf..6db5a09 100644
--- a/fs/nfs/nfs4proc.c
+++ b/fs/nfs/nfs4proc.c
@@ -3334,12 +3334,13 @@ static void nfs4_sync_open_stateid(nfs4_stateid *dst,
 			break;
 		}
 		seqid_open = state->open_stateid.seqid;
-		if (read_seqretry(&state->seqlock, seq))
-			continue;
 
 		dst_seqid = be32_to_cpu(dst->seqid);
 		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) < 0)
 			dst->seqid = seqid_open;
+
+		if (read_seqretry(&state->seqlock, seq))
+			continue;
 		break;
 	}
 }
@@ -3367,14 +3368,16 @@ static bool nfs4_refresh_open_old_stateid(nfs4_stateid *dst,
 			break;
 		}
 		seqid_open = state->open_stateid.seqid;
-		if (read_seqretry(&state->seqlock, seq))
-			continue;
 
 		dst_seqid = be32_to_cpu(dst->seqid);
-		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) >= 0)
+		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) > 0)
 			dst->seqid = cpu_to_be32(dst_seqid + 1);
 		else
 			dst->seqid = seqid_open;
+
+		if (read_seqretry(&state->seqlock, seq))
+			continue;
+
 		ret = true;
 		break;
 	}
-- 
1.8.3.1


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-10  7:40 [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN Murphy Zhou
@ 2019-10-10 14:46 ` Trond Myklebust
  2019-10-11  8:49   ` Murphy Zhou
  2019-10-10 17:32 ` Olga Kornievskaia
  1 sibling, 1 reply; 9+ messages in thread
From: Trond Myklebust @ 2019-10-10 14:46 UTC (permalink / raw)
  To: linux-nfs, jencce.kernel

On Thu, 2019-10-10 at 15:40 +0800, Murphy Zhou wrote:
> Since commit:
>   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE
> 
> xfstests generic/168 on v4.2 starts to fail because reflink call
> gets:
>   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable
> 
> In tshark output, NFS4ERR_OLD_STATEID stands out when comparing with
> good ones:
> 
>  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
>  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
>  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
>  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
>  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
>  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len:
> 65536
>  5218   NFS 266 V4 Reply (Call In 5216) WRITE
>  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
>  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
>  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
>  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status:
> NFS4ERR_OLD_STATEID
>  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
>  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
>  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
>  5228   NFS 250 V4 Reply (Call In 5226) GETATTR
> 
> It's easy to reproduce. By printing some logs, found that we are
> making
> CLOSE seqid larger then OPEN seqid when racing.
> 
> Fix this by not bumping seqid when it's equal to OPEN seqid. Also
> put the whole changing process into seqlock read protection in case
> really bad luck, and this is the same locking behavior with the
> old deleted function.
> 
> Fixes: 0e0cb35b417f ("NFSv4: Handle NFS4ERR_OLD_STATEID in
> CLOSE/OPEN_DOWNGRADE")
> Signed-off-by: Murphy Zhou <jencce.kernel@gmail.com>
> ---
>  fs/nfs/nfs4proc.c | 13 ++++++++-----
>  1 file changed, 8 insertions(+), 5 deletions(-)
> 
> diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
> index 11eafcf..6db5a09 100644
> --- a/fs/nfs/nfs4proc.c
> +++ b/fs/nfs/nfs4proc.c
> @@ -3334,12 +3334,13 @@ static void
> nfs4_sync_open_stateid(nfs4_stateid *dst,
>  			break;
>  		}
>  		seqid_open = state->open_stateid.seqid;
> -		if (read_seqretry(&state->seqlock, seq))
> -			continue;
>  
>  		dst_seqid = be32_to_cpu(dst->seqid);
>  		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) < 0)
>  			dst->seqid = seqid_open;
> +
> +		if (read_seqretry(&state->seqlock, seq))
> +			continue;

What's the intention of this change? Neither dst_seqid nor dst->seqid
are protected by the state->seqlock so why move this code under the
lock.

>  		break;
>  	}
>  }
> @@ -3367,14 +3368,16 @@ static bool
> nfs4_refresh_open_old_stateid(nfs4_stateid *dst,
>  			break;
>  		}
>  		seqid_open = state->open_stateid.seqid;
> -		if (read_seqretry(&state->seqlock, seq))
> -			continue;
>  
>  		dst_seqid = be32_to_cpu(dst->seqid);
> -		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) >= 0)
> +		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) > 0)
>  			dst->seqid = cpu_to_be32(dst_seqid + 1);

This negates the whole intention of the patch you reference in the
'Fixes:', which was to allow us to CLOSE files even if seqid bumps have
been lost due to interrupted RPC calls e.g. when using 'soft' or
'softerr' mounts.
With the above change, the check could just be tossed out altogether,
because dst_seqid will never become larger than seqid_open.

>  		else
>  			dst->seqid = seqid_open;
> +
> +		if (read_seqretry(&state->seqlock, seq))
> +			continue;
> +

Again, why this change to code that doesn't appear to need protection?
If the bump does succeed above, then looping back will actually cause
unpredictable behaviour.

>  		ret = true;
>  		break;
>  	}
-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com



^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-10  7:40 [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN Murphy Zhou
  2019-10-10 14:46 ` Trond Myklebust
@ 2019-10-10 17:32 ` Olga Kornievskaia
  2019-10-11  9:42   ` Murphy Zhou
  2019-10-11 14:18   ` Trond Myklebust
  1 sibling, 2 replies; 9+ messages in thread
From: Olga Kornievskaia @ 2019-10-10 17:32 UTC (permalink / raw)
  To: Murphy Zhou; +Cc: linux-nfs, Trond Myklebust

On Thu, Oct 10, 2019 at 3:42 AM Murphy Zhou <jencce.kernel@gmail.com> wrote:
>
> Since commit:
>   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE
>
> xfstests generic/168 on v4.2 starts to fail because reflink call gets:
>   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable

I don't believe this failure has to do with getting ERR_OLD_STATEID on
the CLOSE. What you see on the network trace is expected as the client
in parallel sends OPEN/CLOSE thus server will fail the CLOSE with the
ERR_OLD_STATEID since it already updated its stateid for the OPEN.

> In tshark output, NFS4ERR_OLD_STATEID stands out when comparing with
> good ones:
>
>  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
>  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
>  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
>  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
>  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
>  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len: 65536
>  5218   NFS 266 V4 Reply (Call In 5216) WRITE
>  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
>  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
>  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
>  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status: NFS4ERR_OLD_STATEID
>  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
>  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
>  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
>  5228   NFS 250 V4 Reply (Call In 5226) GETATTR

"resource temporarily unavailable" is more likely to do with ulimit limits.

I also saw the same error. After I increased the ulimit for the stack
size, the problem went away. There might still be a problem somewhere
in the kernel.

Trond, is it possible that we have too many CLOSE recovery on the
stack that's eating up stack space?

> It's easy to reproduce. By printing some logs, found that we are making
> CLOSE seqid larger then OPEN seqid when racing.
>
> Fix this by not bumping seqid when it's equal to OPEN seqid. Also
> put the whole changing process into seqlock read protection in case
> really bad luck, and this is the same locking behavior with the
> old deleted function.
>
> Fixes: 0e0cb35b417f ("NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE")
> Signed-off-by: Murphy Zhou <jencce.kernel@gmail.com>
> ---
>  fs/nfs/nfs4proc.c | 13 ++++++++-----
>  1 file changed, 8 insertions(+), 5 deletions(-)
>
> diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
> index 11eafcf..6db5a09 100644
> --- a/fs/nfs/nfs4proc.c
> +++ b/fs/nfs/nfs4proc.c
> @@ -3334,12 +3334,13 @@ static void nfs4_sync_open_stateid(nfs4_stateid *dst,
>                         break;
>                 }
>                 seqid_open = state->open_stateid.seqid;
> -               if (read_seqretry(&state->seqlock, seq))
> -                       continue;
>
>                 dst_seqid = be32_to_cpu(dst->seqid);
>                 if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) < 0)
>                         dst->seqid = seqid_open;
> +
> +               if (read_seqretry(&state->seqlock, seq))
> +                       continue;
>                 break;
>         }
>  }
> @@ -3367,14 +3368,16 @@ static bool nfs4_refresh_open_old_stateid(nfs4_stateid *dst,
>                         break;
>                 }
>                 seqid_open = state->open_stateid.seqid;
> -               if (read_seqretry(&state->seqlock, seq))
> -                       continue;
>
>                 dst_seqid = be32_to_cpu(dst->seqid);
> -               if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) >= 0)
> +               if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) > 0)
>                         dst->seqid = cpu_to_be32(dst_seqid + 1);
>                 else
>                         dst->seqid = seqid_open;
> +
> +               if (read_seqretry(&state->seqlock, seq))
> +                       continue;
> +
>                 ret = true;
>                 break;
>         }
> --
> 1.8.3.1
>

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-10 14:46 ` Trond Myklebust
@ 2019-10-11  8:49   ` Murphy Zhou
  2019-10-11 14:14     ` Trond Myklebust
  0 siblings, 1 reply; 9+ messages in thread
From: Murphy Zhou @ 2019-10-11  8:49 UTC (permalink / raw)
  To: Trond Myklebust; +Cc: linux-nfs, jencce.kernel

On Thu, Oct 10, 2019 at 02:46:40PM +0000, Trond Myklebust wrote:
> On Thu, 2019-10-10 at 15:40 +0800, Murphy Zhou wrote:
> > Since commit:
> >   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE
> > 
> > xfstests generic/168 on v4.2 starts to fail because reflink call
> > gets:
> >   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable
> > 
> > In tshark output, NFS4ERR_OLD_STATEID stands out when comparing with
> > good ones:
> > 
> >  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
> >  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
> >  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
> >  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len:
> > 65536
> >  5218   NFS 266 V4 Reply (Call In 5216) WRITE
> >  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
> >  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
> >  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
> >  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status:
> > NFS4ERR_OLD_STATEID
> >  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
> >  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
> >  5228   NFS 250 V4 Reply (Call In 5226) GETATTR
> > 
> > It's easy to reproduce. By printing some logs, found that we are
> > making
> > CLOSE seqid larger then OPEN seqid when racing.
> > 
> > Fix this by not bumping seqid when it's equal to OPEN seqid. Also
> > put the whole changing process into seqlock read protection in case
> > really bad luck, and this is the same locking behavior with the
> > old deleted function.
> > 
> > Fixes: 0e0cb35b417f ("NFSv4: Handle NFS4ERR_OLD_STATEID in
> > CLOSE/OPEN_DOWNGRADE")
> > Signed-off-by: Murphy Zhou <jencce.kernel@gmail.com>
> > ---
> >  fs/nfs/nfs4proc.c | 13 ++++++++-----
> >  1 file changed, 8 insertions(+), 5 deletions(-)
> > 
> > diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
> > index 11eafcf..6db5a09 100644
> > --- a/fs/nfs/nfs4proc.c
> > +++ b/fs/nfs/nfs4proc.c
> > @@ -3334,12 +3334,13 @@ static void
> > nfs4_sync_open_stateid(nfs4_stateid *dst,
> >  			break;
> >  		}
> >  		seqid_open = state->open_stateid.seqid;
> > -		if (read_seqretry(&state->seqlock, seq))
> > -			continue;
> >  
> >  		dst_seqid = be32_to_cpu(dst->seqid);
> >  		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) < 0)
> >  			dst->seqid = seqid_open;
> > +
> > +		if (read_seqretry(&state->seqlock, seq))
> > +			continue;
> 
> What's the intention of this change? Neither dst_seqid nor dst->seqid
> are protected by the state->seqlock so why move this code under the
> lock.

Because seqid_open could have changed when writing to dst->seqid ?

The old nfs4_refresh_open_stateid function put the writing under the lock.

> 
> >  		break;
> >  	}
> >  }
> > @@ -3367,14 +3368,16 @@ static bool
> > nfs4_refresh_open_old_stateid(nfs4_stateid *dst,
> >  			break;
> >  		}
> >  		seqid_open = state->open_stateid.seqid;
> > -		if (read_seqretry(&state->seqlock, seq))
> > -			continue;
> >  
> >  		dst_seqid = be32_to_cpu(dst->seqid);
> > -		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) >= 0)
> > +		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) > 0)
> >  			dst->seqid = cpu_to_be32(dst_seqid + 1);
> 
> This negates the whole intention of the patch you reference in the
> 'Fixes:', which was to allow us to CLOSE files even if seqid bumps have
> been lost due to interrupted RPC calls e.g. when using 'soft' or
> 'softerr' mounts.
> With the above change, the check could just be tossed out altogether,
> because dst_seqid will never become larger than seqid_open.

Hmm.. I got it wrong. Thanks for the explanation.

> 
> >  		else
> >  			dst->seqid = seqid_open;
> > +
> > +		if (read_seqretry(&state->seqlock, seq))
> > +			continue;
> > +
> 
> Again, why this change to code that doesn't appear to need protection?
> If the bump does succeed above, then looping back will actually cause
> unpredictable behaviour.

Same as above. This change have nothing to do with the stateid race. I
just found it when reading the patch.

Thanks,
M
> 
> >  		ret = true;
> >  		break;
> >  	}
> -- 
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> trond.myklebust@hammerspace.com
> 
> 

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-10 17:32 ` Olga Kornievskaia
@ 2019-10-11  9:42   ` Murphy Zhou
  2019-10-11 14:18   ` Trond Myklebust
  1 sibling, 0 replies; 9+ messages in thread
From: Murphy Zhou @ 2019-10-11  9:42 UTC (permalink / raw)
  To: Olga Kornievskaia; +Cc: Murphy Zhou, linux-nfs, Trond Myklebust

On Thu, Oct 10, 2019 at 01:32:50PM -0400, Olga Kornievskaia wrote:
> On Thu, Oct 10, 2019 at 3:42 AM Murphy Zhou <jencce.kernel@gmail.com> wrote:
> >
> > Since commit:
> >   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE
> >
> > xfstests generic/168 on v4.2 starts to fail because reflink call gets:
> >   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable
> 
> I don't believe this failure has to do with getting ERR_OLD_STATEID on
> the CLOSE. What you see on the network trace is expected as the client
> in parallel sends OPEN/CLOSE thus server will fail the CLOSE with the
> ERR_OLD_STATEID since it already updated its stateid for the OPEN.
> 
> > In tshark output, NFS4ERR_OLD_STATEID stands out when comparing with
> > good ones:
> >
> >  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
> >  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
> >  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
> >  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len: 65536
> >  5218   NFS 266 V4 Reply (Call In 5216) WRITE
> >  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
> >  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
> >  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
> >  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status: NFS4ERR_OLD_STATEID
> >  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
> >  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
> >  5228   NFS 250 V4 Reply (Call In 5226) GETATTR
> 
> "resource temporarily unavailable" is more likely to do with ulimit limits.
> 
> I also saw the same error. After I increased the ulimit for the stack
> size, the problem went away. There might still be a problem somewhere
> in the kernel.

Do you mean ulimit -s ? I set it to 'unlimited' and still can reproduce
this.

Thanks,
M
> 
> Trond, is it possible that we have too many CLOSE recovery on the
> stack that's eating up stack space?
> 
> > It's easy to reproduce. By printing some logs, found that we are making
> > CLOSE seqid larger then OPEN seqid when racing.
> >
> > Fix this by not bumping seqid when it's equal to OPEN seqid. Also
> > put the whole changing process into seqlock read protection in case
> > really bad luck, and this is the same locking behavior with the
> > old deleted function.
> >
> > Fixes: 0e0cb35b417f ("NFSv4: Handle NFS4ERR_OLD_STATEID in CLOSE/OPEN_DOWNGRADE")
> > Signed-off-by: Murphy Zhou <jencce.kernel@gmail.com>
> > ---
> >  fs/nfs/nfs4proc.c | 13 ++++++++-----
> >  1 file changed, 8 insertions(+), 5 deletions(-)
> >
> > diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
> > index 11eafcf..6db5a09 100644
> > --- a/fs/nfs/nfs4proc.c
> > +++ b/fs/nfs/nfs4proc.c
> > @@ -3334,12 +3334,13 @@ static void nfs4_sync_open_stateid(nfs4_stateid *dst,
> >                         break;
> >                 }
> >                 seqid_open = state->open_stateid.seqid;
> > -               if (read_seqretry(&state->seqlock, seq))
> > -                       continue;
> >
> >                 dst_seqid = be32_to_cpu(dst->seqid);
> >                 if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) < 0)
> >                         dst->seqid = seqid_open;
> > +
> > +               if (read_seqretry(&state->seqlock, seq))
> > +                       continue;
> >                 break;
> >         }
> >  }
> > @@ -3367,14 +3368,16 @@ static bool nfs4_refresh_open_old_stateid(nfs4_stateid *dst,
> >                         break;
> >                 }
> >                 seqid_open = state->open_stateid.seqid;
> > -               if (read_seqretry(&state->seqlock, seq))
> > -                       continue;
> >
> >                 dst_seqid = be32_to_cpu(dst->seqid);
> > -               if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) >= 0)
> > +               if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) > 0)
> >                         dst->seqid = cpu_to_be32(dst_seqid + 1);
> >                 else
> >                         dst->seqid = seqid_open;
> > +
> > +               if (read_seqretry(&state->seqlock, seq))
> > +                       continue;
> > +
> >                 ret = true;
> >                 break;
> >         }
> > --
> > 1.8.3.1
> >

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-11  8:49   ` Murphy Zhou
@ 2019-10-11 14:14     ` Trond Myklebust
  0 siblings, 0 replies; 9+ messages in thread
From: Trond Myklebust @ 2019-10-11 14:14 UTC (permalink / raw)
  To: jencce.kernel; +Cc: linux-nfs

On Fri, 2019-10-11 at 16:49 +0800, Murphy Zhou wrote:
> On Thu, Oct 10, 2019 at 02:46:40PM +0000, Trond Myklebust wrote:
> > On Thu, 2019-10-10 at 15:40 +0800, Murphy Zhou wrote:
> > > Since commit:
> > >   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in
> > > CLOSE/OPEN_DOWNGRADE
> > > 
> > > xfstests generic/168 on v4.2 starts to fail because reflink call
> > > gets:
> > >   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable
> > > 
> > > In tshark output, NFS4ERR_OLD_STATEID stands out when comparing
> > > with
> > > good ones:
> > > 
> > >  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
> > >  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > >  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
> > >  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > >  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
> > >  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len:
> > > 65536
> > >  5218   NFS 266 V4 Reply (Call In 5216) WRITE
> > >  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
> > >  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
> > >  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
> > >  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status:
> > > NFS4ERR_OLD_STATEID
> > >  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
> > >  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > >  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
> > >  5228   NFS 250 V4 Reply (Call In 5226) GETATTR
> > > 
> > > It's easy to reproduce. By printing some logs, found that we are
> > > making
> > > CLOSE seqid larger then OPEN seqid when racing.
> > > 
> > > Fix this by not bumping seqid when it's equal to OPEN seqid. Also
> > > put the whole changing process into seqlock read protection in
> > > case
> > > really bad luck, and this is the same locking behavior with the
> > > old deleted function.
> > > 
> > > Fixes: 0e0cb35b417f ("NFSv4: Handle NFS4ERR_OLD_STATEID in
> > > CLOSE/OPEN_DOWNGRADE")
> > > Signed-off-by: Murphy Zhou <jencce.kernel@gmail.com>
> > > ---
> > >  fs/nfs/nfs4proc.c | 13 ++++++++-----
> > >  1 file changed, 8 insertions(+), 5 deletions(-)
> > > 
> > > diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
> > > index 11eafcf..6db5a09 100644
> > > --- a/fs/nfs/nfs4proc.c
> > > +++ b/fs/nfs/nfs4proc.c
> > > @@ -3334,12 +3334,13 @@ static void
> > > nfs4_sync_open_stateid(nfs4_stateid *dst,
> > >  			break;
> > >  		}
> > >  		seqid_open = state->open_stateid.seqid;
> > > -		if (read_seqretry(&state->seqlock, seq))
> > > -			continue;
> > >  
> > >  		dst_seqid = be32_to_cpu(dst->seqid);
> > >  		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) < 0)
> > >  			dst->seqid = seqid_open;
> > > +
> > > +		if (read_seqretry(&state->seqlock, seq))
> > > +			continue;
> > 
> > What's the intention of this change? Neither dst_seqid nor dst-
> > >seqid
> > are protected by the state->seqlock so why move this code under the
> > lock.
> 
> Because seqid_open could have changed when writing to dst->seqid ?
> 
> The old nfs4_refresh_open_stateid function put the writing under the
> lock.

The value of state->open_stateid could change both before and after we
write to dst->seqid. If we hold a lock, then it could change the moment
we release that lock. That's not something we're able to control.

The only thing we should care about here is whether or not the call to
nfs4_state_match_open_stateid_other(state, dst) and the storage of
state->open_stateid.seqid in seqid_open are being performed with the
same instance of the full state->open_stateid.

> 
> > >  		break;
> > >  	}
> > >  }
> > > @@ -3367,14 +3368,16 @@ static bool
> > > nfs4_refresh_open_old_stateid(nfs4_stateid *dst,
> > >  			break;
> > >  		}
> > >  		seqid_open = state->open_stateid.seqid;
> > > -		if (read_seqretry(&state->seqlock, seq))
> > > -			continue;
> > >  
> > >  		dst_seqid = be32_to_cpu(dst->seqid);
> > > -		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) >= 0)
> > > +		if ((s32)(dst_seqid - be32_to_cpu(seqid_open)) > 0)
> > >  			dst->seqid = cpu_to_be32(dst_seqid + 1);
> > 
> > This negates the whole intention of the patch you reference in the
> > 'Fixes:', which was to allow us to CLOSE files even if seqid bumps
> > have
> > been lost due to interrupted RPC calls e.g. when using 'soft' or
> > 'softerr' mounts.
> > With the above change, the check could just be tossed out
> > altogether,
> > because dst_seqid will never become larger than seqid_open.
> 
> Hmm.. I got it wrong. Thanks for the explanation.

So to be clear: I'm not saying that what you describe is not a problem.
I'm just saying that the fix you propose is really no better than
reverting the entire patch. I'd prefer not to do that, and would rather
see us look for ways to fix both problems, but if we can't find such as
fix then that would be the better solution.

> 
> > >  		else
> > >  			dst->seqid = seqid_open;
> > > +
> > > +		if (read_seqretry(&state->seqlock, seq))
> > > +			continue;
> > > +
> > 
> > Again, why this change to code that doesn't appear to need
> > protection?
> > If the bump does succeed above, then looping back will actually
> > cause
> > unpredictable behaviour.
> 
> Same as above. This change have nothing to do with the stateid race.
> I
> just found it when reading the patch.
> 
> Thanks,
> M
> > >  		ret = true;
> > >  		break;
> > >  	}
-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com



^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-10 17:32 ` Olga Kornievskaia
  2019-10-11  9:42   ` Murphy Zhou
@ 2019-10-11 14:18   ` Trond Myklebust
  2019-10-11 18:50     ` Olga Kornievskaia
  1 sibling, 1 reply; 9+ messages in thread
From: Trond Myklebust @ 2019-10-11 14:18 UTC (permalink / raw)
  To: aglo, jencce.kernel; +Cc: linux-nfs

On Thu, 2019-10-10 at 13:32 -0400, Olga Kornievskaia wrote:
> On Thu, Oct 10, 2019 at 3:42 AM Murphy Zhou <jencce.kernel@gmail.com>
> wrote:
> > Since commit:
> >   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in
> > CLOSE/OPEN_DOWNGRADE
> > 
> > xfstests generic/168 on v4.2 starts to fail because reflink call
> > gets:
> >   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable
> 
> I don't believe this failure has to do with getting ERR_OLD_STATEID
> on
> the CLOSE. What you see on the network trace is expected as the
> client
> in parallel sends OPEN/CLOSE thus server will fail the CLOSE with the
> ERR_OLD_STATEID since it already updated its stateid for the OPEN.
> 
> > In tshark output, NFS4ERR_OLD_STATEID stands out when comparing
> > with
> > good ones:
> > 
> >  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
> >  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
> >  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
> >  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len:
> > 65536
> >  5218   NFS 266 V4 Reply (Call In 5216) WRITE
> >  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
> >  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
> >  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
> >  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status:
> > NFS4ERR_OLD_STATEID
> >  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
> >  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> >  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
> >  5228   NFS 250 V4 Reply (Call In 5226) GETATTR
> 
> "resource temporarily unavailable" is more likely to do with ulimit
> limits.
> 
> I also saw the same error. After I increased the ulimit for the stack
> size, the problem went away. There might still be a problem somewhere
> in the kernel.
> 
> Trond, is it possible that we have too many CLOSE recovery on the
> stack that's eating up stack space?

That shouldn't normally happen. CLOSE runs as an asynchronous RPC call,
so its stack usage should be pretty minimal (limited to whatever each
callback function uses).


-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com



^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-11 14:18   ` Trond Myklebust
@ 2019-10-11 18:50     ` Olga Kornievskaia
  2019-10-19  0:34       ` Olga Kornievskaia
  0 siblings, 1 reply; 9+ messages in thread
From: Olga Kornievskaia @ 2019-10-11 18:50 UTC (permalink / raw)
  To: Trond Myklebust; +Cc: jencce.kernel, linux-nfs

On Fri, Oct 11, 2019 at 10:18 AM Trond Myklebust
<trondmy@hammerspace.com> wrote:
>
> On Thu, 2019-10-10 at 13:32 -0400, Olga Kornievskaia wrote:
> > On Thu, Oct 10, 2019 at 3:42 AM Murphy Zhou <jencce.kernel@gmail.com>
> > wrote:
> > > Since commit:
> > >   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in
> > > CLOSE/OPEN_DOWNGRADE
> > >
> > > xfstests generic/168 on v4.2 starts to fail because reflink call
> > > gets:
> > >   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable
> >
> > I don't believe this failure has to do with getting ERR_OLD_STATEID
> > on
> > the CLOSE. What you see on the network trace is expected as the
> > client
> > in parallel sends OPEN/CLOSE thus server will fail the CLOSE with the
> > ERR_OLD_STATEID since it already updated its stateid for the OPEN.
> >
> > > In tshark output, NFS4ERR_OLD_STATEID stands out when comparing
> > > with
> > > good ones:
> > >
> > >  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
> > >  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > >  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
> > >  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > >  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
> > >  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len:
> > > 65536
> > >  5218   NFS 266 V4 Reply (Call In 5216) WRITE
> > >  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
> > >  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
> > >  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
> > >  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status:
> > > NFS4ERR_OLD_STATEID
> > >  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
> > >  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > >  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
> > >  5228   NFS 250 V4 Reply (Call In 5226) GETATTR
> >
> > "resource temporarily unavailable" is more likely to do with ulimit
> > limits.
> >
> > I also saw the same error. After I increased the ulimit for the stack
> > size, the problem went away. There might still be a problem somewhere
> > in the kernel.
> >
> > Trond, is it possible that we have too many CLOSE recovery on the
> > stack that's eating up stack space?
>
> That shouldn't normally happen. CLOSE runs as an asynchronous RPC call,
> so its stack usage should be pretty minimal (limited to whatever each
> callback function uses).

Yeah, that wasn't it. I've straced generic/168 to catch
ioctl(clone_file_range) returning EAGAIN.

I've instrumented the kernel to see where we are returning an EAGAIN
in nfs42_proc_clone(). nfs42_proc_clone is failing on
nfs42_select_rw_context() because nfs4_copy_open_stateid() is failing
to get the open state. Basically it looks like we are trying to do a
clone on a file that's not opened. Still trying to understand
things...

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN
  2019-10-11 18:50     ` Olga Kornievskaia
@ 2019-10-19  0:34       ` Olga Kornievskaia
  0 siblings, 0 replies; 9+ messages in thread
From: Olga Kornievskaia @ 2019-10-19  0:34 UTC (permalink / raw)
  To: Trond Myklebust; +Cc: jencce.kernel, linux-nfs

On Fri, Oct 11, 2019 at 2:50 PM Olga Kornievskaia <aglo@umich.edu> wrote:
>
> On Fri, Oct 11, 2019 at 10:18 AM Trond Myklebust
> <trondmy@hammerspace.com> wrote:
> >
> > On Thu, 2019-10-10 at 13:32 -0400, Olga Kornievskaia wrote:
> > > On Thu, Oct 10, 2019 at 3:42 AM Murphy Zhou <jencce.kernel@gmail.com>
> > > wrote:
> > > > Since commit:
> > > >   [0e0cb35] NFSv4: Handle NFS4ERR_OLD_STATEID in
> > > > CLOSE/OPEN_DOWNGRADE
> > > >
> > > > xfstests generic/168 on v4.2 starts to fail because reflink call
> > > > gets:
> > > >   +XFS_IOC_CLONE_RANGE: Resource temporarily unavailable
> > >
> > > I don't believe this failure has to do with getting ERR_OLD_STATEID
> > > on
> > > the CLOSE. What you see on the network trace is expected as the
> > > client
> > > in parallel sends OPEN/CLOSE thus server will fail the CLOSE with the
> > > ERR_OLD_STATEID since it already updated its stateid for the OPEN.
> > >
> > > > In tshark output, NFS4ERR_OLD_STATEID stands out when comparing
> > > > with
> > > > good ones:
> > > >
> > > >  5210   NFS 406 V4 Reply (Call In 5209) OPEN StateID: 0xadb5
> > > >  5211   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > > >  5212   NFS 250 V4 Reply (Call In 5211) GETATTR
> > > >  5213   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > > >  5214   NFS 250 V4 Reply (Call In 5213) GETATTR
> > > >  5216   NFS 422 V4 Call WRITE StateID: 0xa818 Offset: 851968 Len:
> > > > 65536
> > > >  5218   NFS 266 V4 Reply (Call In 5216) WRITE
> > > >  5219   NFS 382 V4 Call OPEN DH: 0x8d44a6b1/
> > > >  5220   NFS 338 V4 Call CLOSE StateID: 0xadb5
> > > >  5222   NFS 406 V4 Reply (Call In 5219) OPEN StateID: 0xa342
> > > >  5223   NFS 250 V4 Reply (Call In 5220) CLOSE Status:
> > > > NFS4ERR_OLD_STATEID
> > > >  5225   NFS 338 V4 Call CLOSE StateID: 0xa342
> > > >  5226   NFS 314 V4 Call GETATTR FH: 0x8d44a6b1
> > > >  5227   NFS 266 V4 Reply (Call In 5225) CLOSE
> > > >  5228   NFS 250 V4 Reply (Call In 5226) GETATTR
> > >
> > > "resource temporarily unavailable" is more likely to do with ulimit
> > > limits.
> > >
> > > I also saw the same error. After I increased the ulimit for the stack
> > > size, the problem went away. There might still be a problem somewhere
> > > in the kernel.
> > >
> > > Trond, is it possible that we have too many CLOSE recovery on the
> > > stack that's eating up stack space?
> >
> > That shouldn't normally happen. CLOSE runs as an asynchronous RPC call,
> > so its stack usage should be pretty minimal (limited to whatever each
> > callback function uses).
>
> Yeah, that wasn't it. I've straced generic/168 to catch
> ioctl(clone_file_range) returning EAGAIN.
>
> I've instrumented the kernel to see where we are returning an EAGAIN
> in nfs42_proc_clone(). nfs42_proc_clone is failing on
> nfs42_select_rw_context() because nfs4_copy_open_stateid() is failing
> to get the open state. Basically it looks like we are trying to do a
> clone on a file that's not opened. Still trying to understand
> things...

Trond,

Generic/168 fails in 2 ways (though only 1 leads to the failure in
xfs_io). Another way is having a file closed then client using the
stateid for the write and getting a bad_stateid which the client
recovers from (but the fact that client shouldn't have done that is a
problem). Another is the clone where again happens that file is
"closed" and clone is trying to use a stateid.

The problem comes from the following fact. We have a racing CLOSE and
OPEN. Where client did the CLOSE followed by the OPEN but the server
processed OPEN and then the CLOSE. Server returns OLD_STATEID to the
CLOSE. What the code does it bumps the sequence id and resends the
CLOSE which inadvertently is closing a file that was opened before.
While IO errors from this are recoverable, the clone error is visible
to the application (I think another case would be a copy).

I don't have a code solution yet. But it'll have to be something where
we need to ignore a CLOSE with OLD_STATEID when another OPEN happened.

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, back to index

Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-10-10  7:40 [PATCH] NFSv4: fix stateid refreshing when CLOSE racing with OPEN Murphy Zhou
2019-10-10 14:46 ` Trond Myklebust
2019-10-11  8:49   ` Murphy Zhou
2019-10-11 14:14     ` Trond Myklebust
2019-10-10 17:32 ` Olga Kornievskaia
2019-10-11  9:42   ` Murphy Zhou
2019-10-11 14:18   ` Trond Myklebust
2019-10-11 18:50     ` Olga Kornievskaia
2019-10-19  0:34       ` Olga Kornievskaia

Linux-NFS Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-nfs/0 linux-nfs/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-nfs linux-nfs/ https://lore.kernel.org/linux-nfs \
		linux-nfs@vger.kernel.org linux-nfs@archiver.kernel.org
	public-inbox-index linux-nfs

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-nfs


AGPL code for this site: git clone https://public-inbox.org/ public-inbox