frequent failures with PROXY FSAL #580
Comments
|
Could you add FSAL=DEBUG (or FULL_DEBUG) to your config? I assume your backend is the standard nfs-kernel-server / knfsd, right? Which CentOS 7 release and kernel version (just for completeness, I assume this is a bug in what is now renamed PROXY_V4). Can you also paste your full rsync command (scrubbed if you prefer)? Does this only happen with your EFI bootloader directories or is that just an example? |
|
On Mon, 18 May 2020, Solomon Boulos wrote:
Could you add FSAL=DEBUG (or FULL_DEBUG) to your config?
I will do so and follow up soon with another debug log.
I assume your backend is the standard nfs-kernel-server / knfsd, right?
That's right, standard CentOS 7 kernel nfs server on backend server.
Which CentOS 7 release and kernel version (just for completeness, I
assume this is a bug in what is now renamed PROXY_V4).
- nfs-ganesha server : CentOS Linux release 7.8.2003 (Core)
- backend server: CentOS Linux release 7.6.1810 (Core)
Also for completeness, my ganesha config looks like this:
EXPORT {
Export_Id = 20030;
Path = /pool/host/backend;
Pseudo = /export/backend;
#Tag = backend
SecType = sys;
Access_Type = none;
Squash = All_Squash;
FSAL {
Name = PROXY_V4;
Srv_Addr=10.168.168.1;
Retry_SleepTime = 60;
Use_Privileged_Client_Port=TRUE;
}
CLIENT {
Clients = @Clients;
Access_Type = RW;
Squash = No_Root_Squash;
}
}
Can you also paste your full rsync command (scrubbed if you prefer)?
This is a representative example:
rsync -vax / /mnt/ganesha/export/backend/test
I will often add the -S option for efficient sparse file handling:
rsync -vaxS / /mnt/ganesha/export/backend/test
and I have a strong feeling that the problem occurs more frequently when
sparse files are involved.
Please note that rsync is just one case of where I've experienced this
instability, and what I have been using for reproducing the problem on
demand for my debug log collection. My first encounter with what I
believe is likely the same underlying problem is when I've tried to boot a
kvm guest with its root filesystem accessed via nfs-ganesha PROXY FSAL.
That's another test case I can use to reliably reproduce the problem on
demand.
Does this only happen with your EFI bootloader directories or is that
just an example?
That's just the example I used to produce the log. I can reproduce the
problem with pretty much any rsync source content writing to the path
mounted from the nfs-ganesha proxy server. As noted above, I think I can
reproduce it more quickly when I use rsync -S. I can also produce the
problem with rsync reading from the nfs-ganesha proxied path (perhaps even
more quickly - when I tested this yesterday I recall that it appeared to
hang almost immediately).
|
|
Here's a new log generated with
FSAL=FULL_DEBUG;
NFSPROTO=FULL_DEBUG;
NFS_V4=FULL_DEBUG;
NFS_V4_LOCK=FULL_DEBUG;
[ganesha.log.4.txt.gz](https://github.com/nfs-ganesha/nfs-ganesha/files/4641620/ganesha.log.4.txt.gz)
|
|
No explicit errors, but did you have an rsync failure there for the file mentioned here: fsal_remove :FSAL :F_DBG :.BOOTX64.EFI.y3rFjc The most visible thing from $ grep proxy is the renewal of the client sessions. $ grep -i proxy ganesha.log.4.txt | grep -v Recmark | grep -v XID shows the "build them up", run for a minute (not the 90s it says), and then issue client renewals. Do you have a timestamp for the first error you saw for this log? |
|
On Mon, 18 May 2020, Solomon Boulos wrote:
No explicit errors, but did you have an rsync failure there for the file
mentioned here:
fsal_remove :FSAL :F_DBG :.BOOTX64.EFI.y3rFjc
Yes, exactly, in this particular test run, that's the file for which rsync
reported an error before it terminated prematurely. I assure you that
there's nothing wrong with that file or the source filesystem that it's
coming from. If I run the exact same rsync command but with a different
destination path that doesn't write to the nfs-ganesha proxy path, there
are no problems.
The most visible thing from $ grep proxy is the renewal of the client
sessions.
$ grep -i proxy ganesha.log.4.txt | grep -v Recmark | grep -v XID
shows the "build them up", run for a minute (not the 90s it says), and then
issue client renewals.
Do you have a timestamp for the first error you saw for this log?
I'm not sure what you mean. It was a single rsync process run, the rsync
process terminated after the file error noted above, and I stopped the
nfs-ganesha server process to terminate the log as soon as possible after
the rsync process had terminated. So, the time of the rsync failure you
mentioned above would be the time of the only error I saw related to that
particular log file.
|
|
That suggests a problem with keeping the clientid/session renewed. Since PROXY_V4 uses 4.1, it seems odd that it would not be keeping the clientid/session renewed since basically all requests must start with a SEQUENCE op that will renew the clientid/session. Maybe something is stalling activity for long enough to put that renewal at risk, and PROXY_V4 isn't doing anything to renew clientid/session in the background? I'm not really at all familiar with the PROXY_V4 code. |
|
I should mention that I have had similar problems in the past with
nfs-ganesha 2.8.x and both NFS v3 and v4.
I had not yet tested PROXY_V3 in next branch but will do so now to confirm
whether or not this failure happens with v3 as well.
Here's the result of my first attempt with PROXY_V3.
I simply changed this:
FSAL {
Name = PROXY_V4;
to this:
FSAL {
Name = PROXY_V3;
and restarted the nfs-ganesha service, and then remounted the client. I
was suprised to see that the client still mounted as NFSv4. How is it
that nfs-ganesha is still providing NFSv4 access to this export when I've
explicitly changed the FSAL to PROXY_V3? Am I mistaken and PROXY_V3
versus PROXY_V4 only affects the NFS version used for the backend mount?
In any case, I the remounted the client with "-o vers=3" to force it to
use NFSv3.
Then I ran my rsync test again. This time it made it made it further and
was looking promising until the rsync process hung and this was logged on
the nfs-ganesha server:
18/05/2020 10:20:29 : epoch 5ec298cb : vh8 : ganesha.nfsd-74959[svc_24]
mdcache_lru_fds_available :INODE LRU :CRIT :FD Hard Limit (4055)
Exceeded (open_fd_count = 4055), waking LRU thread.
|
|
Nevermind my "mistaken" comment/question in my previous post. I just
answered this myself by looking at the documentation again. In
particular, ganesha-core-config(8), and "Protocols". If I want to disable
NFSv4 support in the nfs-ganesha frontend, I do that by setting Protocols
accordingly. What I have already set in the FSAL section only pertains to
the backend.
|
|
On Mon, 18 May 2020, Todd Pfaff wrote:
looking promising until the rsync process hung and this was logged on the
nfs-ganesha server:
18/05/2020 10:20:29 : epoch 5ec298cb : vh8 : ganesha.nfsd-74959[svc_24]
mdcache_lru_fds_available :INODE LRU :CRIT :FD Hard Limit (4055)
Exceeded (open_fd_count = 4055), waking LRU thread.
This is repeatable. I removed the destination copy from my previous test,
restarted the ganesha service, remounted the client NFSv3 again, and redid
the rsync command. It progressed to the exact same point as the last run
at which point the rsync hung and ganesha logged this error again:
18/05/2020 11:03:03 : epoch 5ec2a2c9 : vh8 : ganesha.nfsd-76146[svc_122]
mdcache_lru_fds_available :INODE LRU :CRIT :FD Hard Limit (4055)
Exceeded (open_fd_count = 4055), waking LRU thread.
A 'du -s' of the rsync destination is almost identical: 478372 bytes
copied this time versus 478376 for the previous test.
|
|
I believe I've overcome the fd limit by adding this to my
nfs-ganesha.service systemd unit:
LimitNOFILE=1048576
My first test following this change ran into the same error I've reported
with NFSv4.
My second test, running now, has made it significantly further and is
still making progress.
The inconsistency is disconcerting. I'll repeat the rsync test and try
some other tests to see if things are consistently more stable with
PROXY_V3.
|
|
While it made it much further than the previous test, my second rsync test
with FSAL PROXY_V3 and Protocols=3 eventually terminated prematurely with
the same sort of failure as reported previously with PROXY_V4:
rsync: close failed on "...": Remote I/O error (121)
Whatever the problems are, they are not isolated to PROXY_V4.
I don't know what else I can do to try to debug this, or to gather useful
data for developers, but I'm open to more ideas.
|
|
Hmm, the inode failure may suggest that my code (PROXY_V3) has another "failed to clean up" bug that leaks "fds" (these are synthetic, there are no real fds). I just wrote this code recently, so at the very least you're now in code that I can more easily debug. Unfortunately, my logging in PROXY_V3 was extremely noisy (if you happen to have a log for the proxy_v3 run, please attach it). I calmed it down a bunch in https://review.gerrithub.io/c/ffilz/nfs-ganesha/+/492048 (which is slated for V4-dev.18, which I thought Frank pushed... hopefully it comes back today?). Given a log from PROXY_V3, I'll likely make more progress (and I appreciate the bug report!). |
|
On Mon, 18 May 2020, Solomon Boulos wrote:
Given a log from PROXY_V3, I'll likely make more progress (and I appreciate
the bug report!).
And I appreciate your work on this! I'm on it and will report back soon.
|
|
I would probably either pull that patch in (and my memory leak patch, fwiw) or wait for V4-dev.18 to come back to life. |
|
On Mon, 18 May 2020, Solomon Boulos wrote:
I would probably either pull that patch in (and my memory leak patch, fwiw)
or wait for V4-dev.18 to come back to life.
Could I ask you to jumpstart me a bit here? My experience with git is
limited but I'm trying to learn so that I can contribute more. Assuming
I'm at the top of my git clone of 04-dev.17, what git commands should I
run to pull in the two patches you're recommending? After that I assume I
should remove my existing build tree and rebuild all again?
|
|
Solomon, I may have figured out what I need to do. Looking at the patch
description in the gerrithub.io url that you sent a couple of messages
back. Clicked on the download button and see option for "Pull". There's
some terminology I need to learn but I think I'm on track here. Advice
is still welcome though!
…On Mon, 18 May 2020, Todd Pfaff wrote:
On Mon, 18 May 2020, Solomon Boulos wrote:
> I would probably either pull that patch in (and my memory leak patch,
> fwiw)
> or wait for V4-dev.18 to come back to life.
Could I ask you to jumpstart me a bit here? My experience with git is
limited but I'm trying to learn so that I can contribute more. Assuming I'm
at the top of my git clone of 04-dev.17, what git commands should I run to
pull in the two patches you're recommending? After that I assume I should
remove my existing build tree and rebuild all again?
|
|
We're trying to reach @ffilz to have him push the tag so you can just clone v4-dev.18. It seems like he intended to on Friday afternoon (https://lists.nfs-ganesha.org/archives/list/devel@lists.nfs-ganesha.org/thread/Q5SIDAAQOGYYF6ZUQLRGJTWMFGEBT4GB/) but just didn't hit the button :). |
|
No worries. I already have your patches pulled and a new build running.
But I'll watch for 4-dev.18 too, thanks.
|
|
Just went up. So you should be able to pull the latest "next" branch and/or clone v4-dev.18 directly. |
|
Just checking in to see if you'd caught this again with the v4-dev.18 tag (and FSAL=DEBUG logging) |
|
Hi Solomon,
Sorry for the slow response.
I continued having the same sort of problems but haven't characterized it
well yet. Due to the lack of a quick solution I had to back off using
this nfs-ganesha proxy mechanism for some nfs clients that were
experiencing these problems.
I think I did do one log capture after moving to 4-dev.18 but, after
looking at it pretty thoroughly, I didn't think I saw anything in it that
I believed would be useful to you.
I had to put my testing on hold due to other priorities but will try to
get another log for you soon.
Thanks for checking.
Todd
|
|
Should we keep this issue open? |
|
Yes, please leave open as this issue still exists. I've tested again tonight using 4-dev.26. I can consistently reproduce the failure by trying to boot a kvm guest with the guest's root filesystem qcow2 file accessed via nfs-ganesha PROXY FSAL. The guest runs CentOS 7 and the boot always fails just after the switch root, with output similar to the following: I've captured an nfs-ganesha log with ALL=FULL_DEBUG during one of these kvm guest boot attempts - uploaded here: |
|
Can you help correlate the timestamps here? Assuming you stopped the log at when the badness happened roughly, I suspect this is related to the same bug elsewhere with trying to renew the session / connection: my question is whether the badness starts with regards to: or if it was already busted before then. |
|
Sorry but I'm not sure how I can make a better correlation other than to
say that I stopped the nfs-ganesa service as quickly as I could after I
saw the boot-time error in the kvm guest's console, with the goal of
trying to minimize the log content after I had witnessed the error state.
Do you have any suggestions as to how I might be able to narrow this down
further for you? As I said before, this is reproduceable on demand, and
the kvm guest always fails at the same point if its root filesystem is
accessed via my nfs-ganesha server. I can boot the same guest using the
same qcow2 image if that image is accessed via another nfs path that
doesn't involve nfs-ganesha.
|
|
That's helpful, thanks (I just kinda wanted to know if it basically died
near the end of the log or the log runs for a while after).
If you're willing to do a similar run with PROXY_V3, that would help me
triangulate (otherwise I can try both your rsync test and maybe a generic
"boot linux under kvm" test)
|
|
I've run the same test again after changing ganesha.conf from PROXY_V4 to PROXY_V3. |
|
A ha! $ egrep -i failed ganesha.log-20200722-23.33.txt I think those metadata/dirent ones are confusingly harmless. However the write failure does matter, and means that the RPC worked, but the backend server returned an error. Strangely that error (1) is NFS3ERR_PERM... Just to verify, the errors in your kernel boot though are all complaints about reads (or does the visible error to you vary?). Either way, looking at all the lines near there handled by the svc_73 thread, I see it's trying to do: ... and so 107 == 0x6b and you'd had tons of successful reads and writes to that file handle. Nothing looks suspicious in the actual writing code (though I have a printf bug on "Got a new socket", since I don't believe your host is 2.0.0.0) 22/07/2020 23:33:51 : epoch 5f190490 : vh8 : ganesha.nfsd-65631[svc_73] nfs3_write :NFS3 :F_DBG :Write offset=8246099968 size=8192 MaxOffSet=9223372036854775807 Moreover, there are tons of reads and writes that successfully happen afterwards too: $ egrep "proxyv3_(write2|read2)" ganesha.log-20200722-23.33.txt though I suppose they could have been in flight as svc_73 never shows up again. NFS experts: can knfsd return PERM/ACCESS errors under load or something? (Or any other suspicious outcomes for getting back error code 1?) |
|
On Fri, 24 Jul 2020, Solomon Boulos wrote:
Just to verify, the errors in your kernel boot though are all complaints
about reads (or does the visible error to you vary?).
The boot-time errors corresponding to the log you're inspecting are all
like this:
[ 34.511623] blk_update_request: I/O error, dev vda, sector 16785896
[ 34.512598] Buffer I/O error on dev vda1, logical block 2097981, lost
async page write
Nothing looks suspicious in the actual writing code (though I have a printf
bug on "Got a new socket", since I don't believe your host is 2.0.0.0)
Right, definitely not 2.0.0.0. The frontend host is 10.113.48.218 and the
backend is 10.168.168.1.
|
|
(Bringing this back here from the list) Running tshark while doing an rsync shows the same failure down to the "the backend replies with NFS3ERR_PERM": 454 71.197509325 192.168.1.2 → 192.168.1.5 NFS 190 V3 WRITE Reply (Call In 403) Error: NFS3ERR_PERM rsync is likely just so robust, that it's willing to retry these things enough to make progress. A more detailed and fancily decoded tshark run: shows what looks like a fairly reasonable write to me. These permission errors are strewn about in the write stream... |
|
I finally figured this out. By playing around with the maximum number of connections in rpc.c, I determined "it's a race of some sort, that's weird" (that is, it worked fine at 1 connection, 2, 4, 8 depending on debug settings, etc.). I burned a lot of time trying to get msan and tsan working with clang, but eventually decided to just hop over to my knfsd box and turn up all the logging while running the following from my client:
There was a lot of noise in the log, but this jumped out at me: Sep 12 23:10:45 ganesha-proxy-nfsd kernel: [16077266.727259] nfsd: request from insecure port 192.168.1.2, port=36953! because I call bindresvport_sa to get a reserved port... My comment for my local patch explains the problem: So the fix is easy enough, but I think like glibc, we should make bindresvport itself threadsafe: Thanks again, Todd for being so patient! |
|
Solomon,
This sounds promising. I'm eager to put your patch to the test.
Thanks for your effort on this.
cheers,
Todd
|
|
I realize this issue is closed but I just want to comment here that I've updated to V4-dev.34 and quickly hit this problem again when doing some rsync tests. My log shows: Todd |
|
Do you have less than 64 privileged ports available? (Since there are
~1000, I’m surprised that failed).
Alternatively, maybe I’m leaking / not properly cleaning them up? (I think
that close on the socket releases them back).
Either way, I need to change the code to go back to retrying if the binding
failed (I will block / wait / retry for a while, if all 64 are in use, but
I hadn’t ever triggered the bindresvport failure and it should be
considered transient, not permanent)
…On Sat, Sep 19, 2020 at 08:22 Todd Pfaff ***@***.***> wrote:
I realize this issue is closed but I just want to comment here that I've
updated to V4-dev.34 and quickly hit this problem again when doing some
rsync tests. My log shows:
19/09/2020 11:02:46 : epoch 5f659a35 : hostname : ganesha.nfsd-24063[svc_5010] proxyv3_openfd :FSAL :CRIT :Failed to reserve a privileged port. 98 Address already in use
19/09/2020 11:02:46 : epoch 5f659a35 : hostname : ganesha.nfsd-24063[svc_5010] proxyv3_read2 :FSAL :CRIT :proxyv3_nfs_call failed (0)
Todd
—
You are receiving this because you were assigned.
Reply to this email directly, view it on GitHub
<#580 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/AADPGPU7B4BAPPJQXLLGIFTSGTECFANCNFSM4NCUYFEQ>
.
|
|
If you want to retry, you can change the hardcoded 64 in
src/FSAL/FSAL_PROXY_V3/rpc.c to something lower like 16 (my next TODO was
to make this configurable anyway).
On Sat, Sep 19, 2020 at 9:37 AM Solomon Boulos <notifications@github.com>
wrote:
… Do you have less than 64 privileged ports available? (Since there are
~1000, I’m surprised that failed).
Alternatively, maybe I’m leaking / not properly cleaning them up? (I think
that close on the socket releases them back).
Either way, I need to change the code to go back to retrying if the binding
failed (I will block / wait / retry for a while, if all 64 are in use, but
I hadn’t ever triggered the bindresvport failure and it should be
considered transient, not permanent)
On Sat, Sep 19, 2020 at 08:22 Todd Pfaff ***@***.***> wrote:
>
>
> I realize this issue is closed but I just want to comment here that I've
> updated to V4-dev.34 and quickly hit this problem again when doing some
> rsync tests. My log shows:
>
>
> 19/09/2020 11:02:46 : epoch 5f659a35 : hostname :
ganesha.nfsd-24063[svc_5010] proxyv3_openfd :FSAL :CRIT :Failed to reserve
a privileged port. 98 Address already in use
>
> 19/09/2020 11:02:46 : epoch 5f659a35 : hostname :
ganesha.nfsd-24063[svc_5010] proxyv3_read2 :FSAL :CRIT :proxyv3_nfs_call
failed (0)
>
>
>
> Todd
>
>
>
>
> —
> You are receiving this because you were assigned.
> Reply to this email directly, view it on GitHub
> <
#580 (comment)
>,
> or unsubscribe
> <
https://github.com/notifications/unsubscribe-auth/AADPGPU7B4BAPPJQXLLGIFTSGTECFANCNFSM4NCUYFEQ
>
> .
>
>
>
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
<#580 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/AADPGPQYZBNXD5P3ZPW4KX3SGTM4TANCNFSM4NCUYFEQ>
.
|
|
even though i set i use docker image fedora:37 , simply run with below commands can repeat this error: use mount command directly will success. @boulos can you give some advice ? |
|
the log show connect timeout port is 43255. so grep 43255 port, i found no NLM running on backend NFS server. can i proxy v3 backend NFS without NLM ? if cannot, why below command ok.
|
I've been using nfs-ganesha with the PROXY FSAL for a while, first with 2.x versions and now with the "next" branch, currently at version 4-dev.17.
With older versions and with 4-dev.17 I'm frequently encountering a problem when copying data with rsync on an NFS client to a path that is mounted via PROXY FSAL. Often the rsync process will terminate with a error like this:
rsync: close failed on "/tmp/mnt/junk/boot/efi/EFI/BOOT/.fallback.efi.fkPpCQ": Invalid argument (22)
rsync error: error in file IO (code 11) at receiver.c(859) [receiver=3.1.2]
Sometimes I can simply restart the rsync process and it will make a bit more progress and then abort again in the same way on another file. Other times the NFS mount will have gone stale or will hang when accessed. Sometimes I can simply restart the nfs-ganesha service to get the client working again, until the next repeat of this problem. Other times I have been able to unmount and remount the NFS client to get things sorted. Other times I have needed to reboot the client. I have also encountered cases where the NFS client was wedged and needed a power cycle.
In all cases, the nfs-ganesha server does not crash, and is usually still operating fine for other NFS clients than the one on which the problem was initiated, so there is no crash dump or backtrace to provide.
I can usually trigger the problem quickly on demand with rsync, for example by simply copying a typical linux root filesystem from the NFS client to server via the ganesha PROXY.
I've captured a couple of ganesha logs corresponding to rsync commands as described above with the following debug options in ganesha.conf:
I've uploaded those logs here:
ganesha.log.1.txt.gz
ganesha.log.2.txt.gz
My operating environment is CentOS 7 on all systems: the NFS client host, the nfs-ganesha PROXY FSAL server, and the NFS server host behind the ganesha NFS PROXY.
Please let me know if there's anything else I can provide to help debug this problem.
The text was updated successfully, but these errors were encountered: