Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 2620:137:e000::1:18 as permitted sender) client-ip=2620:137:e000::1:18;
From:   Enrico Scholz <enrico.scholz@sigma-chemnitz.de>
To:     Trond Myklebust <trondmy@hammerspace.com>
Cc:     "linux-nfs@vger.kernel.org" <linux-nfs@vger.kernel.org>
Subject: Re: Random NFS client lockups
References: <lyr172gl1t.fsf@ensc-virt.intern.sigma-chemnitz.de>
        <lysfrhr51i.fsf@ensc-virt.intern.sigma-chemnitz.de>
        <fd4d017808a5ff9492fc6dfce8506f64e600fb35.camel@hammerspace.com>
Date:   Wed, 16 Mar 2022 23:05:05 +0100
In-Reply-To: <fd4d017808a5ff9492fc6dfce8506f64e600fb35.camel@hammerspace.com>
        (Trond Myklebust's message of "Wed, 16 Mar 2022 21:39:37 +0000")
Message-ID: <lyilsd8sfi.fsf@ensc-virt.intern.sigma-chemnitz.de>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.2 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
Sender: Enrico Scholz <enrico.scholz@sigma-chemnitz.de>
Precedence: bulk

Trond Myklebust <trondmy@hammerspace.com> writes:

>> Mar 16 05:02:40.051969: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 state 8=
 conn 1 dead 0 zapped 1 sk_shutdown 1
>> Mar 16 05:02:40.052067: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 xs_clos=
e xprt 0000000022aecad1
>> Mar 16 05:02:40.052189: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 state 7=
 conn 0 dead 0 zapped 1 sk_shutdown 3
>> Mar 16 05:02:40.052243: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 xs_erro=
r_report client 0000000022aecad1, error=3D32...
>> Mar 16 05:02:40.052367: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 state 7=
 conn 0 dead 0 zapped 1 sk_shutdown 3
>> Mar 16 05:02:40.052503: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 state 7=
 conn 0 dead 0 zapped 1 sk_shutdown 3
>> Mar 16 05:02:40.053201: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 xs_conn=
ect scheduled xprt 0000000022aecad1
>> Mar 16 05:02:40.055886: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 xs_bind=
 0000:0000:0000:0000:0000:0000:0000:0000:875: ok (0)
>> __A__=C2=A0 05:02:40.055947: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 wo=
rker connecting xprt 0000000022aecad1 via tcp to XXXXX:2001:1022:: (port 20=
49)
>> Mar 16 05:02:40.055995: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 0000000=
022aecad1 connect status 115 connected 0 sock state 2
>
> Socket is in TCP state 2 =3D=3D SYN_SENT
> So the client requested to connect to the server

server closed the connection (state 8, CLOSE_WAIT), client cleaned up
correctly and reconnected.


>> Mar 16 05:07:28.326605: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 state 8=
 conn 1 dead 0 zapped 1 sk_shutdown 1
>
> Socket is now in TCP state 8 =3D=3D TCP_CLOSE_WAIT...
>
> That means the server sent a FIN to the client to request that the
> connection be closed.

yes; the same situation like above


>> Mar 16 05:07:28.326679: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 xs_conn=
ect scheduled xprt 0000000022aecad1
>> __B__=C2=A0 05:07:28.326978: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 wo=
rker connecting xprt 0000000022aecad1 via tcp to XXXXX:2001:1022:: (port 20=
49)
>> Mar 16 05:07:28.327050: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 0000000=
022aecad1 connect status 0 connected 0 sock state 8
>> __C__=C2=A0 05:07:28.327113: RPC:=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 xs=
_close xprt 0000000022aecad1
>
> Client closes the socket, which is still in TCP_CLOSE_WAIT

the 'xs_close' is very likely a reaction to the state change reported
above and should happen before 'xs_connect'.


> Basically, what the above means is that your server is initiating the
> close of the connection, not the client.

yes; but the client should reconnect (and does it in most cases).
Sometimes there seems to be a race which prevents the reconnect and
brings the client in a broken state.


Enrico