#969376 openafs-client: Openafs cache erros on the logs

Package:
openafs-client
Source:
openafs
Description:
AFS distributed filesystem client support
Submitter:
Jose M Calhariz
Date:
2021-06-21 21:39:03 UTC
Severity:
normal
#969376#5
Date:
2020-09-01 14:43:37 UTC
From:
To:
I am using a private backport of openafs from testing.  On this server I
am getting multiples strange errors about openafs cache.  This server
is different in that it runs apache to serve personal web pages and every
web page runs under a different openafs user.  So is normal for this
server to be simultaneuous running code under 100 or 200 different openafs
users.

The an example of errors on the logs are:

afs: disk cache read error in CacheItems slot 350195 off 28015620/35000020 code -4/80
afs: Error while alloc'ing cache slot for file 204:536874423.964.4794; failing with an i/o error

I am not certain this types of errors are to be ignored and there have
been reports of problems accessing openafs files.  I am using this bug
report to collect more information about this cache errors and the
possibility of being an indication of important errors with the openafs
cache code.

Kind regards
Jose M Calhariz

#969376#10
Date:
2020-09-01 23:07:55 UTC
From:
To:
This error message is supposed to indicate that a read from the cache
filesystem got EIO, which in turn is supposed to indicate a physical
problem with the drive.  That said, I'm not going to jump to conclusions
and try to blame your drive, as there are several other things that could
be coming into play.

While the log message itself is pretty old, there's been a lot of work
recently to more accurately report EIO in error conditions (mostly instead
of ENOENT, since returning ENOENT can cause that to get cached at the VFS
layer and produce strange user-visible behavior).

Having a lot of users present makes me suspect that the credentials used by
the kernel to read/write the cache file are not being saved/restored
properly, and indeed we recently merged to 1.8.x (not in a release yet)
https://gerrit.openafs.org/14082 and https://gerrit.openafs.org/14099 which
improve such credentials management.

My recommendation would be to try pulling in those two patches to your
build before proceeding to try to trace the source of the EIO.

Thanks for the report!

#969376#15
Date:
2020-09-02 18:28:50 UTC
From:
To:
Hi,

I will then update my private backport and see if the things improve.
I will report here the results of your sugestion.  Thank you.

Kind regards
Jose M Calhariz

#969376#20
Date:
2020-09-04 17:12:30 UTC
From:
To:
Hi,

I have made an update to my private backport. It is better but I still
see the same errors on the logs.  This machine is a VM and no other VM
or host is reporting IO errors of any kind, that I know off.

It was my first time using gerrit, so can you please check if the
I have downloaded the correct patches?

ee578e9.diff
179a418.diff

There is a way to decode this errors and try to understand better what
is happening and find a fix?


[    9.760892] openafs: loading out-of-tree module taints kernel.
[    9.760898] openafs: module license 'http://www.openafs.org/dl/license10.html' taints kernel.
[    9.762091] openafs: module verification failed: signature and/or required key missing - tainting kernel
[    9.778441] Key type afs_pag registered
[ 8245.094223] afs: disk cache read error in CacheItems slot 211006 off 16880500/19660820 code -4/80
[ 8245.094254] afs: disk cache read error in CacheItems slot 211006 off 16880500/19660820 code -4/80
[ 8245.094277] afs: disk cache read error in CacheItems slot 211006 off 16880500/19660820 code -4/80
[ 8245.094299] afs: disk cache read error in CacheItems slot 211006 off 16880500/19660820 code -4/80
[10181.679636] afs: disk cache read error in CacheItems slot 156531 off 12522500/19660820 code -4/80
[10181.679638] afs: Error while alloc'ing cache slot for file 204:536874423.516.5309; failing with an i/o error
[11438.241843] afs_UFSGetVolSlot: error -4 reading volumeinfo
[11438.242213] afs_UFSGetVolSlot: error -4 reading volumeinfo


Kind regards
Jose M Calhariz

#969376#25
Date:
2020-09-30 15:18:27 UTC
From:
To:
Hi,

any progress on this?  There is anything I can do to help?


Kind regards
Jose M Calhariz

#969376#30
Date:
2020-11-10 15:14:44 UTC
From:
To:
Hi

Hi,  I collected internal debug messages about this using
ClientTracing.py

Is there anyone to send this debug messages and try to solve the
problem.


Kind regards
Jose M Calhariz

#969376#35
Date:
2021-06-17 22:06:00 UTC
From:
To:
Hi, I'm the person that mentioned this briefly during the AFS workshop
this week. These messages are not in themselves a problem; they are just
reporting that we got an error code from the Linux kernel when trying to
read from the disk cache.

The code logged is -4, which is EINTR (EIO would be -5). The most likely
trigger of this is a process that got a SIGKILL signal (or other fatal
signal) while we were reading from the disk cache. Traditionally we
wouldn't get errors in that case, but Linux started returning errors in
that situation after some version (possibly depending on the local fs in
use? but I don't recall exactly).

If you think these messages happen when some other bug or problem is
happening, that's possible, but the messages themselves are not a
problem. If you want to avoid the situation that causes these messages,
you can try to avoid SIGKILL'ing the relevant processes, if you know
what's causing that. The message you've shown doesn't log the pid, but
there is already a change in 1.8.8pre1 to log the pid and some other
information in that log message.

If you want the specific patch to add some more info to that log
message, it's here (gerrit 14437):

https://git.openafs.org/?p=openafs.git;a=patch;h=5d863b4f6e817b1cc2615265c7747e17a2037ae6

I know of at least one bug that can be triggered by the log message
you've mentioned, which is fixed by gerrit 14451 here:

https://git.openafs.org/?p=openafs.git;a=patch;h=c55607d732a65f8acb1dfc6bf93aee0f4409cecf

That's also in 1.8.8pre1, so if it's feasible for you to just try
1.8.8pre1, that's probably easiest. The messages will still appear with
1.8.8pre1, but they may be more informative, and some other related bugs
may be fixed. If you are seeing some other problematic behavior with
1.8.8pre1, I can take a look if you provide some details.

#969376#40
Date:
2021-06-18 11:29:27 UTC
From:
To:
No problem, here is the reply to the Debian bug and my coworkers.

Kind regards
Jose M Calhariz

#969376#45
Date:
2021-06-21 21:35:04 UTC
From:
To:
I have tried to package 1.8.8pre1 and compiled for bullseye.


On my first stress test "test_diff" it runs fine until I stopped the
stress test with a ^C.  This is a special machine only to run stress
tests of afs.  So no process are being killed and the errors messages
this time were for the killed stress test.

[Mon Jun 21 21:55:08 2021] afs: failed to write to CacheItems off 12588820 code -4/80
[Mon Jun 21 21:55:08 2021] afs: disk cache read error in CacheItems slot 71488 off 5719060/32500020 code -4/80 pid 3770 (tar)
[Mon Jun 21 21:55:08 2021] afs: Error while alloc'ing cache slot for file 203:536870928.1326742.311043289; failing with an i/o error
[Mon Jun 21 21:55:08 2021] afs: failed to store file (0/5)

So it was as explained.

Kind regards
Jose M Calhariz