Bug 1470467 - Permission errors after server reboot
Permission errors after server reboot
Status: CLOSED EOL
Product: Fedora
Classification: Fedora
Component: kernel (Show other bugs)
25
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: nfs-maint
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-07-12 21:50 EDT by Jason Tibbitts
Modified: 2017-12-12 05:23 EST (History)
26 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2017-12-12 05:23:19 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
rpc.gssd and gssproxy logs (607.96 KB, text/plain)
2017-07-12 21:50 EDT, Jason Tibbitts
no flags Details
tshark dump (1.02 MB, text/plain)
2017-07-14 00:25 EDT, Jason Tibbitts
no flags Details

  None (edit)
Description Jason Tibbitts 2017-07-12 21:50:09 EDT
Created attachment 1297353 [details]
rpc.gssd and gssproxy logs

This grew out of my investigation of https://bugzilla.redhat.com/show_bug.cgi?id=1466944.  I'm not ever sure where to file nfs-related things so I'm just starting at nfs-utils.  Sorry if that's not the right place.

Basically I'm trying to work out some issues with client recovery when a server restarts.  One of the things I did was cd to a directory mounted from a test server and run a quick loop that appends text to a file, while rebooting the server in the middle.  The mount is via NFS4.2, sec=krb5.  (I normally run at least krb5i but I went back to krb5 for hopefully easier debugging.)

[tester@ld01]/nas/tester-00% while true; do date; date >> d; sleep 1; done
Wed Jul 12 16:51:45 CDT 2017
Wed Jul 12 16:51:46 CDT 2017
Wed Jul 12 16:51:47 CDT 2017
Wed Jul 12 16:51:48 CDT 2017
Wed Jul 12 16:51:49 CDT 2017
Wed Jul 12 16:51:50 CDT 2017
Wed Jul 12 16:51:51 CDT 2017
Wed Jul 12 16:51:52 CDT 2017
Wed Jul 12 16:51:53 CDT 2017
[server goes down for a few minutes and then comes back]
zsh: Input/output error: d
Wed Jul 12 16:56:51 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:52 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:53 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:54 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:55 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:56 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:57 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:58 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:56:59 CDT 2017
zsh: permission denied: d
Wed Jul 12 16:57:00 CDT 2017
Wed Jul 12 16:58:14 CDT 2017
Wed Jul 12 16:58:15 CDT 2017
Wed Jul 12 16:58:16 CDT 2017
Wed Jul 12 16:58:17 CDT 2017
Wed Jul 12 16:58:18 CDT 2017
Wed Jul 12 16:58:19 CDT 2017
Wed Jul 12 16:58:20 CDT 2017
Wed Jul 12 16:58:21 CDT 2017
Wed Jul 12 16:58:22 CDT 2017
Wed Jul 12 16:58:23 CDT 2017
Wed Jul 12 16:58:24 CDT 2017
^C%
[tester@ld01]/nas/tester-00% wc -l d
12 d
[tester@ld01]/nas/tester-00% cat d
Wed Jul 12 16:58:13 CDT 2017
Wed Jul 12 16:58:14 CDT 2017
Wed Jul 12 16:58:15 CDT 2017
Wed Jul 12 16:58:16 CDT 2017
Wed Jul 12 16:58:17 CDT 2017
Wed Jul 12 16:58:18 CDT 2017
Wed Jul 12 16:58:19 CDT 2017
Wed Jul 12 16:58:20 CDT 2017
Wed Jul 12 16:58:21 CDT 2017
Wed Jul 12 16:58:22 CDT 2017
Wed Jul 12 16:58:23 CDT 2017
Wed Jul 12 16:58:24 CDT 2017

The permission errors are weird, but they do clear up.  Unfortunately this somehow results in the file being truncated.  I guess this could be bad behavior by the shell (which is zsh in this case) but I can't really tell.

Since I was trying to debug a gssproxy problem, I have gssproxy running at debug_level=3, and also rpc.gssd running with '-r -r -r' and I'll attach those logs.  I also have a complete packet capture but I'm not sure what to do with it.

The server is running current Centos7 (kernel-3.10.0-514.26.2.el7.x86_64, nfs-utils-1.3.0-0.33.el7_3.x86_64).  The client is running current Fedora 25 (kernel-4.11.8-200.fc25.x86_64, nfs-utils-2.1.1-5.rc4.fc25.x86_64, gssproxy-0.7.0-9.fc25.x86_64).
Comment 1 J. Bruce Fields 2017-07-13 14:12:57 EDT
(In reply to Jason Tibbitts from comment #0)
> The permission errors are weird, but they do clear up.

Sure sounds like a bug, though.  Might be interesting to see what's going on on the wire while you're getting permissions errors.

> Unfortunately this somehow results in the file being truncated.

I'm not sure if I'm counting right, but it looks like the number of lines you end up with is the number of successful writes after the reboot?  So this would be consistent with the file getting truncated to zero on reboot (or some sort of caching bug making the client thing it had been).  (Or even just being removed server-side on reboot--unliely, but you might print out the inode number and/or check the trace to see that the filehandle is the same on boot.)  Might again be interesting to see what's happening on the wire.  (What do getattrs of the file length report, for example?)

Might also be interesting to contrast with the case where you hold a single open rather than reopening the file each time through the loop.
Comment 2 Jason Tibbitts 2017-07-14 00:20:52 EDT
Yes, exactly; the file is truncated at some point.  Kind of difficult to tell when exactly that happens because the client has no permission to access that directory for a few seconds after the server comes back up.

I do have a complete package capture taken from the client from the initial mount until the conclusion of the experiment; I'm just not sure what to do with it.  But in case it's useful, I'll attach the output of

tshark -r pcap-overwrittenfile -O nfs 'ip.addr == 172.21.87.243'

Where that is the IP of the server.  It's about 700 packets total.
Comment 3 Jason Tibbitts 2017-07-14 00:25 EDT
Created attachment 1298093 [details]
tshark dump
Comment 4 Jason Tibbitts 2017-07-14 11:33:41 EDT
In case it's not obvious (or maybe to save you some time), the server goes down at frame 2183 in that capture.  I might have missed some flag to tcpdump to make it timestamp the packets it captures.  It would certainly be nice to be able to correlate the packets with the output of the loop.
Comment 5 Steve Dickson 2017-10-05 14:02:21 EDT
I'm thinking this is not an nfs-utils issued... 

Changing the component
Comment 6 Fedora End Of Life 2017-11-16 13:55:56 EST
This message is a reminder that Fedora 25 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 25. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '25'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 25 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.
Comment 7 Fedora End Of Life 2017-12-12 05:23:19 EST
Fedora 25 changed to end-of-life (EOL) status on 2017-12-12. Fedora 25 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Note You need to log in before you can comment on or make changes to this bug.