Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Content-Type: text/plain;
        charset=us-ascii
Mime-Version: 1.0 (Mac OS X Mail 13.4 \(3608.120.23.2.4\))
Subject: Re: Random IO errors on nfs clients running linux > 4.20
From:   Chuck Lever <chuck.lever@oracle.com>
In-Reply-To: <20201026134216.GK74269@var.inittab.org>
Date:   Mon, 26 Oct 2020 09:58:17 -0400
Cc:     Bruce Fields <bfields@fieldses.org>,
        Linux NFS Mailing List <linux-nfs@vger.kernel.org>,
        Miguel Rodriguez <miguel.rodriguez@udima.es>,
        Isaac Marco Blancas <isaac.marco@udima.es>
Content-Transfer-Encoding: quoted-printable
Message-Id: <40FDCE82-5895-4184-BAB3-AC221326EB34@oracle.com>
References: <20200429171527.GG2531021@var.inittab.org>
 <20200430173200.GE29491@fieldses.org>
 <20200909092900.GO189595@var.inittab.org>
 <20200909134727.GA3894@fieldses.org> <20201026134216.GK74269@var.inittab.org>
To:     Alberto Gonzalez Iniesta <alberto.gonzalez@udima.es>
Precedence: bulk


> On Oct 26, 2020, at 9:42 AM, Alberto Gonzalez Iniesta =
<alberto.gonzalez@udima.es> wrote:
>=20
> On Wed, Sep 09, 2020 at 09:47:27AM -0400, J. Bruce Fields wrote:
>> On Wed, Sep 09, 2020 at 11:29:00AM +0200, Alberto Gonzalez Iniesta =
wrote:
>>> On Thu, Apr 30, 2020 at 01:32:00PM -0400, J. Bruce Fields wrote:
>>>> On Wed, Apr 29, 2020 at 07:15:27PM +0200, Alberto Gonzalez Iniesta =
wrote:
>>>>> We can run the previous "ls -lR" 20 times and get no error, or get
>>>>> this "ls: leyendo el directorio 'Becas y ayudas/': Error de =
entrada/salida"
>>>>> (ls: reading directorio 'Becas y ayudas/': Input/Output Error") =
every
>>>>> now and then.
>>>>>=20
>>>>> The error happens (obviously?) with ls, rsync and the users's GUI =
tools.
>>>>>=20
>>>>> There's nothing in dmesg (or elsewhere).
>>>>> These are the kernels with tried:
>>>>> 4.18.0-25   -> Can't reproduce
>>>>> 4.19.0      -> Can't reproduce
>>>>> 4.20.17     -> Happening (hard to reproduce)
>>>>> 5.0.0-15    -> Happening (hard to reproduce)
>>>>> 5.3.0-45    -> Happening (more frequently)
>>>>> 5.6.0-rc7   -> Reproduced a couple of times after boot, then =
nothing
>>>>>=20
>>>>> We did long (as in daylong) testing trying to reproduce this with =
all
>>>>> those kernel versions, so we are pretty sure 4.18 and 4.19 don't
>>>>> experience this and our Ubuntu 16.04 clients don't have any issue.
>>>>>=20
>>>>> I know we aren't providing much info but we are really looking =
forward
>>>>> to doing all the testing required (we already spent lots of time =
in it).
>>>>>=20
>>>>> Thanks for your work.
>>=20
>> So all I notice from this one is the readdir EIO came from =
call_decode.
>> I suspect that means it failed in the xdr decoding.  Looks like xdr
>> decoding of the actual directory data (which is the complicated part) =
is
>> done later, so this means it failed decoding the header or verifier,
>> which is a little odd:
>>=20
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016276] RPC:  3284 =
call_decode result -5
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016281] =
nfs41_sequence_process: Error 1 free the slot=20
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016286] RPC:       =
wake_up_first(00000000d3f50f4d "ForeChannel Slot table")
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016288] nfs4_free_slot: =
slotid 0 highest_used_slotid 4294967295
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016290] RPC:  3284 return =
0, status -5
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016291] RPC:  3284 =
release task
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016295] RPC:       =
freeing buffer of size 4144 at 00000000a3649daf
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016298] RPC:  3284 =
release request 0000000079df89b2
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016300] RPC:       =
wake_up_first(00000000c5ee49ee "xprt_backlog")
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016302] RPC:       =
rpc_release_client(00000000b930c343)
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016304] RPC:  3284 =
freeing task
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016309] =
_nfs4_proc_readdir: returns -5
>>> Sep  8 16:03:23 portatil264 kernel: [15033.016318] NFS: =
readdir(departamentos/innovacion) returns -5
>=20
> Hi, Bruce et al.
>=20
> Is there anything we can do to help debugging/fixing this? It's still
> biting our users with a +4.20.x kernel.

Alberto, can you share a snippet of a raw network capture that shows
the READDIR Reply that fails to decode?


--
Chuck Lever