We're seeing traces of the following form:
[10952.396347] svc: transport ffff88042ba4a 000 dequeued, inuse=2
[10952.396351] svc: tcp_accept ffff88042ba4 a000 sock ffff88042a6e4c80
[10952.396362] nfsd: connect from 10.2.6.1, port=187
[10952.396364] svc: svc_setup_socket ffff8800b99bcf00
[10952.396368] setting up TCP socket for reading
[10952.396370] svc: svc_setup_socket created ffff8803eb10a000 (inet ffff88042b75b800)
[10952.396373] svc: transport ffff8803eb10a000 put into queue
[10952.396375] svc: transport ffff88042ba4a000 put into queue
[10952.396377] svc: server ffff8800bb0ec000 waiting for data (to = 3600000)
[10952.396380] svc: transport ffff8803eb10a000 dequeued, inuse=2
[10952.396381] svc_recv: found XPT_CLOSE
[10952.396397] svc: svc_delete_xprt(ffff8803eb10a000)
[10952.396398] svc: svc_tcp_sock_detach(ffff8803eb10a000)
[10952.396399] svc: svc_sock_detach(ffff8803eb10a000)
[10952.396412] svc: svc_sock_free(ffff8803eb10a000)
i.e. an immediate close of the socket after initialisation.
The culprit appears to be the test at the end of svc_tcp_init, which
checks if the newly created socket is in the TCP_ESTABLISHED state,
and immediately closes it if not. The evidence appears to suggest that
the socket might still be in the SYN_RECV state at this time.
The fix is to check for both states, and then to add a check in
svc_tcp_state_change() to ensure we don't close the socket when
it transitions into TCP_ESTABLISHED.
Signed-off-by: Trond Myklebust <[email protected]>
---
net/sunrpc/svcsock.c | 13 ++++++++++---
1 file changed, 10 insertions(+), 3 deletions(-)
diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
index df61a4ec21a4..38b132ff6dce 100644
--- a/net/sunrpc/svcsock.c
+++ b/net/sunrpc/svcsock.c
@@ -767,8 +767,10 @@ static void svc_tcp_state_change(struct sock *sk)
printk("svc: socket %p: no user data\n", sk);
else {
svsk->sk_ostate(sk);
- set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
- svc_xprt_enqueue(&svsk->sk_xprt);
+ if (sk->sk_state != TCP_ESTABLISHED) {
+ set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
+ svc_xprt_enqueue(&svsk->sk_xprt);
+ }
}
}
@@ -1294,8 +1296,13 @@ static void svc_tcp_init(struct svc_sock *svsk, struct svc_serv *serv)
tcp_sk(sk)->nonagle |= TCP_NAGLE_OFF;
set_bit(XPT_DATA, &svsk->sk_xprt.xpt_flags);
- if (sk->sk_state != TCP_ESTABLISHED)
+ switch (sk->sk_state) {
+ case TCP_SYN_RECV:
+ case TCP_ESTABLISHED:
+ break;
+ default:
set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
+ }
}
}
--
2.7.4
This modification is useful for debugging issues that happen while
the socket is being initialised.
Signed-off-by: Trond Myklebust <[email protected]>
---
net/sunrpc/svcsock.c | 7 +++++--
1 file changed, 5 insertions(+), 2 deletions(-)
diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
index 38b132ff6dce..e84321a09880 100644
--- a/net/sunrpc/svcsock.c
+++ b/net/sunrpc/svcsock.c
@@ -1365,8 +1365,11 @@ static struct svc_sock *svc_setup_socket(struct svc_serv *serv,
else
svc_tcp_init(svsk, serv);
- dprintk("svc: svc_setup_socket created %p (inet %p)\n",
- svsk, svsk->sk_sk);
+ dprintk("svc: svc_setup_socket created %p (inet %p), "
+ "listen %d close %d\n",
+ svsk, svsk->sk_sk,
+ test_bit(XPT_LISTENER, &svsk->sk_xprt.xpt_flags),
+ test_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags));
return svsk;
}
--
2.7.4
On Tue, Jul 26, 2016 at 09:51:19AM -0400, Trond Myklebust wrote:
> We're seeing traces of the following form:
>
> [10952.396347] svc: transport ffff88042ba4a 000 dequeued, inuse=2
> [10952.396351] svc: tcp_accept ffff88042ba4 a000 sock ffff88042a6e4c80
> [10952.396362] nfsd: connect from 10.2.6.1, port=187
> [10952.396364] svc: svc_setup_socket ffff8800b99bcf00
> [10952.396368] setting up TCP socket for reading
> [10952.396370] svc: svc_setup_socket created ffff8803eb10a000 (inet ffff88042b75b800)
> [10952.396373] svc: transport ffff8803eb10a000 put into queue
> [10952.396375] svc: transport ffff88042ba4a000 put into queue
> [10952.396377] svc: server ffff8800bb0ec000 waiting for data (to = 3600000)
> [10952.396380] svc: transport ffff8803eb10a000 dequeued, inuse=2
> [10952.396381] svc_recv: found XPT_CLOSE
> [10952.396397] svc: svc_delete_xprt(ffff8803eb10a000)
> [10952.396398] svc: svc_tcp_sock_detach(ffff8803eb10a000)
> [10952.396399] svc: svc_sock_detach(ffff8803eb10a000)
> [10952.396412] svc: svc_sock_free(ffff8803eb10a000)
>
> i.e. an immediate close of the socket after initialisation.
Interesting, thanks!
So the one thing I don't understand is why this is correct behavior for
accept--I thought it wasn't supposed to return a socket until it was
fully established.
--b.
>
> The culprit appears to be the test at the end of svc_tcp_init, which
> checks if the newly created socket is in the TCP_ESTABLISHED state,
> and immediately closes it if not. The evidence appears to suggest that
> the socket might still be in the SYN_RECV state at this time.
>
> The fix is to check for both states, and then to add a check in
> svc_tcp_state_change() to ensure we don't close the socket when
> it transitions into TCP_ESTABLISHED.
>
> Signed-off-by: Trond Myklebust <[email protected]>
> ---
> net/sunrpc/svcsock.c | 13 ++++++++++---
> 1 file changed, 10 insertions(+), 3 deletions(-)
>
> diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
> index df61a4ec21a4..38b132ff6dce 100644
> --- a/net/sunrpc/svcsock.c
> +++ b/net/sunrpc/svcsock.c
> @@ -767,8 +767,10 @@ static void svc_tcp_state_change(struct sock *sk)
> printk("svc: socket %p: no user data\n", sk);
> else {
> svsk->sk_ostate(sk);
> - set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
> - svc_xprt_enqueue(&svsk->sk_xprt);
> + if (sk->sk_state != TCP_ESTABLISHED) {
> + set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
> + svc_xprt_enqueue(&svsk->sk_xprt);
> + }
> }
> }
>
> @@ -1294,8 +1296,13 @@ static void svc_tcp_init(struct svc_sock *svsk, struct svc_serv *serv)
> tcp_sk(sk)->nonagle |= TCP_NAGLE_OFF;
>
> set_bit(XPT_DATA, &svsk->sk_xprt.xpt_flags);
> - if (sk->sk_state != TCP_ESTABLISHED)
> + switch (sk->sk_state) {
> + case TCP_SYN_RECV:
> + case TCP_ESTABLISHED:
> + break;
> + default:
> set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
> + }
> }
> }
>
> --
> 2.7.4
> On Jul 26, 2016, at 11:43, J. Bruce Fields <[email protected]> wrote:
>
> On Tue, Jul 26, 2016 at 09:51:19AM -0400, Trond Myklebust wrote:
>> We're seeing traces of the following form:
>>
>> [10952.396347] svc: transport ffff88042ba4a 000 dequeued, inuse=2
>> [10952.396351] svc: tcp_accept ffff88042ba4 a000 sock ffff88042a6e4c80
>> [10952.396362] nfsd: connect from 10.2.6.1, port=187
>> [10952.396364] svc: svc_setup_socket ffff8800b99bcf00
>> [10952.396368] setting up TCP socket for reading
>> [10952.396370] svc: svc_setup_socket created ffff8803eb10a000 (inet ffff88042b75b800)
>> [10952.396373] svc: transport ffff8803eb10a000 put into queue
>> [10952.396375] svc: transport ffff88042ba4a000 put into queue
>> [10952.396377] svc: server ffff8800bb0ec000 waiting for data (to = 3600000)
>> [10952.396380] svc: transport ffff8803eb10a000 dequeued, inuse=2
>> [10952.396381] svc_recv: found XPT_CLOSE
>> [10952.396397] svc: svc_delete_xprt(ffff8803eb10a000)
>> [10952.396398] svc: svc_tcp_sock_detach(ffff8803eb10a000)
>> [10952.396399] svc: svc_sock_detach(ffff8803eb10a000)
>> [10952.396412] svc: svc_sock_free(ffff8803eb10a000)
>>
>> i.e. an immediate close of the socket after initialisation.
>
> Interesting, thanks!
>
> So the one thing I don't understand is why this is correct behavior for
> accept--I thought it wasn't supposed to return a socket until it was
> fully established.
inet_accept() appears to allow SYN_RECV:
int inet_accept(struct socket *sock, struct socket *newsock, int flags)
{
struct sock *sk1 = sock->sk;
int err = -EINVAL;
struct sock *sk2 = sk1->sk_prot->accept(sk1, flags, &err);
if (!sk2)
goto do_err;
lock_sock(sk2);
sock_rps_record_flow(sk2);
WARN_ON(!((1 << sk2->sk_state) &
(TCPF_ESTABLISHED | TCPF_SYN_RECV |
TCPF_CLOSE_WAIT | TCPF_CLOSE)));
sock_graft(sk2, newsock);
newsock->state = SS_CONNECTED;
err = 0;
release_sock(sk2);
do_err:
return err;
}
On Tue, Jul 26, 2016 at 04:08:29PM +0000, Trond Myklebust wrote:
>
> > On Jul 26, 2016, at 11:43, J. Bruce Fields <[email protected]> wrote:
> >
> > On Tue, Jul 26, 2016 at 09:51:19AM -0400, Trond Myklebust wrote:
> >> We're seeing traces of the following form:
> >>
> >> [10952.396347] svc: transport ffff88042ba4a 000 dequeued, inuse=2
> >> [10952.396351] svc: tcp_accept ffff88042ba4 a000 sock ffff88042a6e4c80
> >> [10952.396362] nfsd: connect from 10.2.6.1, port=187
> >> [10952.396364] svc: svc_setup_socket ffff8800b99bcf00
> >> [10952.396368] setting up TCP socket for reading
> >> [10952.396370] svc: svc_setup_socket created ffff8803eb10a000 (inet ffff88042b75b800)
> >> [10952.396373] svc: transport ffff8803eb10a000 put into queue
> >> [10952.396375] svc: transport ffff88042ba4a000 put into queue
> >> [10952.396377] svc: server ffff8800bb0ec000 waiting for data (to = 3600000)
> >> [10952.396380] svc: transport ffff8803eb10a000 dequeued, inuse=2
> >> [10952.396381] svc_recv: found XPT_CLOSE
> >> [10952.396397] svc: svc_delete_xprt(ffff8803eb10a000)
> >> [10952.396398] svc: svc_tcp_sock_detach(ffff8803eb10a000)
> >> [10952.396399] svc: svc_sock_detach(ffff8803eb10a000)
> >> [10952.396412] svc: svc_sock_free(ffff8803eb10a000)
> >>
> >> i.e. an immediate close of the socket after initialisation.
> >
> > Interesting, thanks!
> >
> > So the one thing I don't understand is why this is correct behavior for
> > accept--I thought it wasn't supposed to return a socket until it was
> > fully established.
>
> inet_accept() appears to allow SYN_RECV:
OK. Cc'ing netdev just to make sure we didn't overlook anything.
(Also: what were user-visible symptoms? Mounts failing, or unexpected
delays?)
--b.
>
> int inet_accept(struct socket *sock, struct socket *newsock, int flags)
> {
> struct sock *sk1 = sock->sk;
> int err = -EINVAL;
> struct sock *sk2 = sk1->sk_prot->accept(sk1, flags, &err);
>
> if (!sk2)
> goto do_err;
>
> lock_sock(sk2);
>
> sock_rps_record_flow(sk2);
> WARN_ON(!((1 << sk2->sk_state) &
> (TCPF_ESTABLISHED | TCPF_SYN_RECV |
> TCPF_CLOSE_WAIT | TCPF_CLOSE)));
>
> sock_graft(sk2, newsock);
>
> newsock->state = SS_CONNECTED;
> err = 0;
> release_sock(sk2);
> do_err:
> return err;
> }
On Wed, 2016-07-27 at 14:48 -0400, Fields Bruce James wrote:
> On Tue, Jul 26, 2016 at 04:08:29PM +0000, Trond Myklebust wrote:
> >
> > > On Jul 26, 2016, at 11:43, J. Bruce Fields <[email protected]> wrote:
> > >
> > > On Tue, Jul 26, 2016 at 09:51:19AM -0400, Trond Myklebust wrote:
> > >> We're seeing traces of the following form:
> > >>
> > >> [10952.396347] svc: transport ffff88042ba4a 000 dequeued, inuse=2
> > >> [10952.396351] svc: tcp_accept ffff88042ba4 a000 sock ffff88042a6e4c80
> > >> [10952.396362] nfsd: connect from 10.2.6.1, port=187
> > >> [10952.396364] svc: svc_setup_socket ffff8800b99bcf00
> > >> [10952.396368] setting up TCP socket for reading
> > >> [10952.396370] svc: svc_setup_socket created ffff8803eb10a000 (inet ffff88042b75b800)
> > >> [10952.396373] svc: transport ffff8803eb10a000 put into queue
> > >> [10952.396375] svc: transport ffff88042ba4a000 put into queue
> > >> [10952.396377] svc: server ffff8800bb0ec000 waiting for data (to = 3600000)
> > >> [10952.396380] svc: transport ffff8803eb10a000 dequeued, inuse=2
> > >> [10952.396381] svc_recv: found XPT_CLOSE
> > >> [10952.396397] svc: svc_delete_xprt(ffff8803eb10a000)
> > >> [10952.396398] svc: svc_tcp_sock_detach(ffff8803eb10a000)
> > >> [10952.396399] svc: svc_sock_detach(ffff8803eb10a000)
> > >> [10952.396412] svc: svc_sock_free(ffff8803eb10a000)
> > >>
> > >> i.e. an immediate close of the socket after initialisation.
> > >
> > > Interesting, thanks!
> > >
> > > So the one thing I don't understand is why this is correct behavior for
> > > accept--I thought it wasn't supposed to return a socket until it was
> > > fully established.
> >
> > inet_accept() appears to allow SYN_RECV:
>
> OK. Cc'ing netdev just to make sure we didn't overlook anything.
>
SYN_RECV after accept() is a TCP Fast Open property I think.
Maybe you are playing with some global TCP Fast Open settings ?
> (Also: what were user-visible symptoms? Mounts failing, or unexpected
> delays?)
>
> --b.
>
> >
> > int inet_accept(struct socket *sock, struct socket *newsock, int flags)
> > {
> > struct sock *sk1 = sock->sk;
> > int err = -EINVAL;
> > struct sock *sk2 = sk1->sk_prot->accept(sk1, flags, &err);
> >
> > if (!sk2)
> > goto do_err;
> >
> > lock_sock(sk2);
> >
> > sock_rps_record_flow(sk2);
> > WARN_ON(!((1 << sk2->sk_state) &
> > (TCPF_ESTABLISHED | TCPF_SYN_RECV |
> > TCPF_CLOSE_WAIT | TCPF_CLOSE)));
> >
> > sock_graft(sk2, newsock);
> >
> > newsock->state = SS_CONNECTED;
> > err = 0;
> > release_sock(sk2);
> > do_err:
> > return err;
> > }
SGkgRXJpYywNCg0KPiBPbiBKdWwgMjcsIDIwMTYsIGF0IDE0OjU5LCBFcmljIER1bWF6ZXQgPGVy
aWMuZHVtYXpldEBnbWFpbC5jb20+IHdyb3RlOg0KPiANCj4gT24gV2VkLCAyMDE2LTA3LTI3IGF0
IDE0OjQ4IC0wNDAwLCBGaWVsZHMgQnJ1Y2UgSmFtZXMgd3JvdGU6DQo+PiBPbiBUdWUsIEp1bCAy
NiwgMjAxNiBhdCAwNDowODoyOVBNICswMDAwLCBUcm9uZCBNeWtsZWJ1c3Qgd3JvdGU6DQo+Pj4g
DQo+Pj4+IE9uIEp1bCAyNiwgMjAxNiwgYXQgMTE6NDMsIEouIEJydWNlIEZpZWxkcyA8YmZpZWxk
c0BmaWVsZHNlcy5vcmc+IHdyb3RlOg0KPj4+PiANCj4+Pj4gT24gVHVlLCBKdWwgMjYsIDIwMTYg
YXQgMDk6NTE6MTlBTSAtMDQwMCwgVHJvbmQgTXlrbGVidXN0IHdyb3RlOg0KPj4+Pj4gV2UncmUg
c2VlaW5nIHRyYWNlcyBvZiB0aGUgZm9sbG93aW5nIGZvcm06DQo+Pj4+PiANCj4+Pj4+IFsxMDk1
Mi4zOTYzNDddIHN2YzogdHJhbnNwb3J0IGZmZmY4ODA0MmJhNGEgMDAwIGRlcXVldWVkLCBpbnVz
ZT0yDQo+Pj4+PiBbMTA5NTIuMzk2MzUxXSBzdmM6IHRjcF9hY2NlcHQgZmZmZjg4MDQyYmE0IGEw
MDAgc29jayBmZmZmODgwNDJhNmU0YzgwDQo+Pj4+PiBbMTA5NTIuMzk2MzYyXSBuZnNkOiBjb25u
ZWN0IGZyb20gMTAuMi42LjEsIHBvcnQ9MTg3DQo+Pj4+PiBbMTA5NTIuMzk2MzY0XSBzdmM6IHN2
Y19zZXR1cF9zb2NrZXQgZmZmZjg4MDBiOTliY2YwMA0KPj4+Pj4gWzEwOTUyLjM5NjM2OF0gc2V0
dGluZyB1cCBUQ1Agc29ja2V0IGZvciByZWFkaW5nDQo+Pj4+PiBbMTA5NTIuMzk2MzcwXSBzdmM6
IHN2Y19zZXR1cF9zb2NrZXQgY3JlYXRlZCBmZmZmODgwM2ViMTBhMDAwIChpbmV0IGZmZmY4ODA0
MmI3NWI4MDApDQo+Pj4+PiBbMTA5NTIuMzk2MzczXSBzdmM6IHRyYW5zcG9ydCBmZmZmODgwM2Vi
MTBhMDAwIHB1dCBpbnRvIHF1ZXVlDQo+Pj4+PiBbMTA5NTIuMzk2Mzc1XSBzdmM6IHRyYW5zcG9y
dCBmZmZmODgwNDJiYTRhMDAwIHB1dCBpbnRvIHF1ZXVlDQo+Pj4+PiBbMTA5NTIuMzk2Mzc3XSBz
dmM6IHNlcnZlciBmZmZmODgwMGJiMGVjMDAwIHdhaXRpbmcgZm9yIGRhdGEgKHRvID0gMzYwMDAw
MCkNCj4+Pj4+IFsxMDk1Mi4zOTYzODBdIHN2YzogdHJhbnNwb3J0IGZmZmY4ODAzZWIxMGEwMDAg
ZGVxdWV1ZWQsIGludXNlPTINCj4+Pj4+IFsxMDk1Mi4zOTYzODFdIHN2Y19yZWN2OiBmb3VuZCBY
UFRfQ0xPU0UNCj4+Pj4+IFsxMDk1Mi4zOTYzOTddIHN2Yzogc3ZjX2RlbGV0ZV94cHJ0KGZmZmY4
ODAzZWIxMGEwMDApDQo+Pj4+PiBbMTA5NTIuMzk2Mzk4XSBzdmM6IHN2Y190Y3Bfc29ja19kZXRh
Y2goZmZmZjg4MDNlYjEwYTAwMCkNCj4+Pj4+IFsxMDk1Mi4zOTYzOTldIHN2Yzogc3ZjX3NvY2tf
ZGV0YWNoKGZmZmY4ODAzZWIxMGEwMDApDQo+Pj4+PiBbMTA5NTIuMzk2NDEyXSBzdmM6IHN2Y19z
b2NrX2ZyZWUoZmZmZjg4MDNlYjEwYTAwMCkNCj4+Pj4+IA0KPj4+Pj4gaS5lLiBhbiBpbW1lZGlh
dGUgY2xvc2Ugb2YgdGhlIHNvY2tldCBhZnRlciBpbml0aWFsaXNhdGlvbi4NCj4+Pj4gDQo+Pj4+
IEludGVyZXN0aW5nLCB0aGFua3MhDQo+Pj4+IA0KPj4+PiBTbyB0aGUgb25lIHRoaW5nIEkgZG9u
J3QgdW5kZXJzdGFuZCBpcyB3aHkgdGhpcyBpcyBjb3JyZWN0IGJlaGF2aW9yIGZvcg0KPj4+PiBh
Y2NlcHQtLUkgdGhvdWdodCBpdCB3YXNuJ3Qgc3VwcG9zZWQgdG8gcmV0dXJuIGEgc29ja2V0IHVu
dGlsIGl0IHdhcw0KPj4+PiBmdWxseSBlc3RhYmxpc2hlZC4NCj4+PiANCj4+PiBpbmV0X2FjY2Vw
dCgpIGFwcGVhcnMgdG8gYWxsb3cgU1lOX1JFQ1Y6DQo+PiANCj4+IE9LLiAgQ2MnaW5nIG5ldGRl
diBqdXN0IHRvIG1ha2Ugc3VyZSB3ZSBkaWRuJ3Qgb3Zlcmxvb2sgYW55dGhpbmcuDQo+PiANCj4g
DQo+IFNZTl9SRUNWIGFmdGVyIGFjY2VwdCgpIGlzIGEgVENQIEZhc3QgT3BlbiBwcm9wZXJ0eSBJ
IHRoaW5rLg0KPiANCj4gTWF5YmUgeW91IGFyZSBwbGF5aW5nIHdpdGggc29tZSBnbG9iYWwgVENQ
IEZhc3QgT3BlbiBzZXR0aW5ncyA/DQo+IA0KDQpUaGUgTGludXgga2VybmVsIGNsaWVudCBzaG91
bGQgbm90IGJlIHVzaW5nIFRDUCBmYXN0IG9wZW4sIGJ1dCBpdCBpcyBwb3NzaWJsZSB0aGF0IHNv
bWUgb2YgdGhlIG90aGVyIE5GU3YzIGNsaWVudHMgd2XigJlyZSB1c2luZyBhcmUuDQpXb3VsZCBh
IHN0YW5kYXJkIGtuZnNkIGxpc3RlbmVyIHJlc3BvbmQgdG8gYSBUQ1AgZmFzdCBvcGVuIHJlcXVl
c3QsIG9yIHdvdWxkIHRoZSBkZWZhdWx0IGJlaGF2aW91ciBiZSB0byBpZ25vcmUgaXQ/DQoNCklm
IHRoZSBkZWZhdWx0IGJlaGF2aW91ciBmb3IgdGhlIHNlcnZlciBpcyB0byBhbGxvdyBmYXN0IG9w
ZW4sIHRoZW4gd2UgZG8gbmVlZCB0aGVzZSBwYXRjaGVzLCBJTU8uDQoNCj4gDQo+PiAoQWxzbzog
d2hhdCB3ZXJlIHVzZXItdmlzaWJsZSBzeW1wdG9tcz8gIE1vdW50cyBmYWlsaW5nLCBvciB1bmV4
cGVjdGVkDQo+PiBkZWxheXM/KQ0KPj4gDQoNCkNvbm5lY3Rpb24gcmV0cnkgc3Rvcm1zIG9uIHRo
ZSBzZXJ2ZXIuDQoNCj4+IC0tYi4NCj4+IA0KPj4+IA0KPj4+IGludCBpbmV0X2FjY2VwdChzdHJ1
Y3Qgc29ja2V0ICpzb2NrLCBzdHJ1Y3Qgc29ja2V0ICpuZXdzb2NrLCBpbnQgZmxhZ3MpDQo+Pj4g
ew0KPj4+ICAgICAgICBzdHJ1Y3Qgc29jayAqc2sxID0gc29jay0+c2s7DQo+Pj4gICAgICAgIGlu
dCBlcnIgPSAtRUlOVkFMOw0KPj4+ICAgICAgICBzdHJ1Y3Qgc29jayAqc2syID0gc2sxLT5za19w
cm90LT5hY2NlcHQoc2sxLCBmbGFncywgJmVycik7DQo+Pj4gDQo+Pj4gICAgICAgIGlmICghc2sy
KQ0KPj4+ICAgICAgICAgICAgICAgIGdvdG8gZG9fZXJyOw0KPj4+IA0KPj4+ICAgICAgICBsb2Nr
X3NvY2soc2syKTsNCj4+PiANCj4+PiAgICAgICAgc29ja19ycHNfcmVjb3JkX2Zsb3coc2syKTsN
Cj4+PiAgICAgICAgV0FSTl9PTighKCgxIDw8IHNrMi0+c2tfc3RhdGUpICYNCj4+PiAgICAgICAg
ICAgICAgICAgIChUQ1BGX0VTVEFCTElTSEVEIHwgVENQRl9TWU5fUkVDViB8DQo+Pj4gICAgICAg
ICAgICAgICAgICBUQ1BGX0NMT1NFX1dBSVQgfCBUQ1BGX0NMT1NFKSkpOw0KPj4+IA0KPj4+ICAg
ICAgICBzb2NrX2dyYWZ0KHNrMiwgbmV3c29jayk7DQo+Pj4gDQo+Pj4gICAgICAgIG5ld3NvY2st
PnN0YXRlID0gU1NfQ09OTkVDVEVEOw0KPj4+ICAgICAgICBlcnIgPSAwOw0KPj4+ICAgICAgICBy
ZWxlYXNlX3NvY2soc2syKTsNCj4+PiBkb19lcnI6DQo+Pj4gICAgICAgIHJldHVybiBlcnI7DQo+
Pj4gfQ0KPiANCj4gDQoNCg==
On Wed, Jul 27, 2016 at 07:11:23PM +0000, Trond Myklebust wrote:
> Hi Eric,
>
> > On Jul 27, 2016, at 14:59, Eric Dumazet <[email protected]> wrote:
> >
> > On Wed, 2016-07-27 at 14:48 -0400, Fields Bruce James wrote:
> >> On Tue, Jul 26, 2016 at 04:08:29PM +0000, Trond Myklebust wrote:
> >>>
> >>>> On Jul 26, 2016, at 11:43, J. Bruce Fields <[email protected]> wrote:
> >>>>
> >>>> On Tue, Jul 26, 2016 at 09:51:19AM -0400, Trond Myklebust wrote:
> >>>>> We're seeing traces of the following form:
> >>>>>
> >>>>> [10952.396347] svc: transport ffff88042ba4a 000 dequeued, inuse=2
> >>>>> [10952.396351] svc: tcp_accept ffff88042ba4 a000 sock ffff88042a6e4c80
> >>>>> [10952.396362] nfsd: connect from 10.2.6.1, port=187
> >>>>> [10952.396364] svc: svc_setup_socket ffff8800b99bcf00
> >>>>> [10952.396368] setting up TCP socket for reading
> >>>>> [10952.396370] svc: svc_setup_socket created ffff8803eb10a000 (inet ffff88042b75b800)
> >>>>> [10952.396373] svc: transport ffff8803eb10a000 put into queue
> >>>>> [10952.396375] svc: transport ffff88042ba4a000 put into queue
> >>>>> [10952.396377] svc: server ffff8800bb0ec000 waiting for data (to = 3600000)
> >>>>> [10952.396380] svc: transport ffff8803eb10a000 dequeued, inuse=2
> >>>>> [10952.396381] svc_recv: found XPT_CLOSE
> >>>>> [10952.396397] svc: svc_delete_xprt(ffff8803eb10a000)
> >>>>> [10952.396398] svc: svc_tcp_sock_detach(ffff8803eb10a000)
> >>>>> [10952.396399] svc: svc_sock_detach(ffff8803eb10a000)
> >>>>> [10952.396412] svc: svc_sock_free(ffff8803eb10a000)
> >>>>>
> >>>>> i.e. an immediate close of the socket after initialisation.
> >>>>
> >>>> Interesting, thanks!
> >>>>
> >>>> So the one thing I don't understand is why this is correct behavior for
> >>>> accept--I thought it wasn't supposed to return a socket until it was
> >>>> fully established.
> >>>
> >>> inet_accept() appears to allow SYN_RECV:
> >>
> >> OK. Cc'ing netdev just to make sure we didn't overlook anything.
> >>
> >
> > SYN_RECV after accept() is a TCP Fast Open property I think.
> >
> > Maybe you are playing with some global TCP Fast Open settings ?
> >
>
> The Linux kernel client should not be using TCP fast open, but it is possible that some of the other NFSv3 clients we’re using are.
> Would a standard knfsd listener respond to a TCP fast open request, or would the default behaviour be to ignore it?
>
> If the default behaviour for the server is to allow fast open, then we do need these patches, IMO.
Even if it's not a default, if there's a configuration that allows
accept to return a socket in SYN_RECV state, then knfsd should handle it
gracefully, especially as long as it's this easy.
It'd still be useful to understand why this is happening, though....
--b.