Bug 1535424

Summary: nfs-utils need to cause gssproxy reload
Product: [Fedora] Fedora Reporter: Bruno Goncalves <bgoncalv>
Component: nfs-utilsAssignee: Steve Dickson <steved>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: rawhideCC: bfields, jlayton, steved, yoyang
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: nfs-utils-2.2.1-4.rc2.fc27 nfs-utils-2.2.1-4.rc2.fc26 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-01-23 21:48:02 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Bruno Goncalves 2018-01-17 11:05:07 UTC
Description of problem:
Gssproxy needs to poke the kernel rpcgss module after it is loaded *before* the nfsd kernel server starts listening for potentially GSS protected mounts.

However the gssproxy daemon may be already running on a system, so it needs to be forced o reload in order to poke the modules at the right time.

This can be done with an (optional) ExecStartPre line in the nfs-server unit, which already guarantees the rpcgss kernel modules are loaded in advance.

Version-Release number of selected component (if applicable):
nfs-utils-2.3.1-1.fc28.x86_64
gssproxy-0.7.0-29.fc28.x86_64

How reproducible:
100%

Steps to Reproduce:
1.# systemctl start proc-fs-nfsd.mount
2.# echo '[gssproxy]' > /etc/gssproxy/gssproxy.conf
3.# echo 'debug = true' >> /etc/gssproxy/gssproxy.conf
4.# systemctl restart gssproxy
5.# systemctl status gssproxy
● gssproxy.service - GSSAPI Proxy Daemon
   Loaded: loaded (/usr/lib/systemd/system/gssproxy.service; disabled; vendor preset: disabled)
   Active: active (running) since Wed 2018-01-17 11:02:18 UTC; 5s ago
  Process: 803 ExecStart=/usr/sbin/gssproxy -D (code=exited, status=0/SUCCESS)
 Main PID: 804 (gssproxy)
    Tasks: 6 (limit: 4915)
   CGroup: /system.slice/gssproxy.service
           └─804 /usr/sbin/gssproxy -D

Jan 17 11:02:18 localhost.localdomain systemd[1]: Starting GSSAPI Proxy Daemon...
Jan 17 11:02:18 localhost.localdomain gssproxy[803]: [2018/01/17 11:02:18]: Debug Enabled (level: 1)
Jan 17 11:02:18 localhost.localdomain gssproxy[803]: [2018/01/17 11:02:18]: Problem with kernel communication!  NFS server will not work
Jan 17 11:02:18 localhost.localdomain gssproxy[803]: [2018/01/17 11:02:18]: Client connected (fd = 10)[2018/01/17 11:02:18]:  (pid = 804) (uid = 0) (gid = 0)[2018/01/17 11:02:18]:  (context = system_u:system_r:k
Jan 17 11:02:18 localhost.localdomain systemd[1]: Started GSSAPI Proxy Daemon.


6.# systemctl restart nfs
7.# systemctl status nfs
● nfs-server.service - NFS server and services
   Loaded: loaded (/usr/lib/systemd/system/nfs-server.service; disabled; vendor preset: disabled)
   Active: active (exited) since Wed 2018-01-17 11:03:36 UTC; 6s ago
  Process: 816 ExecStopPost=/usr/sbin/exportfs -f (code=exited, status=0/SUCCESS)
  Process: 815 ExecStopPost=/usr/sbin/exportfs -au (code=exited, status=0/SUCCESS)
  Process: 814 ExecStop=/usr/sbin/rpc.nfsd 0 (code=exited, status=0/SUCCESS)
  Process: 826 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS (code=exited, status=0/SUCCESS)
  Process: 825 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS)
 Main PID: 826 (code=exited, status=0/SUCCESS)

Jan 17 11:03:36 localhost.localdomain systemd[1]: Starting NFS server and services...
Jan 17 11:03:36 localhost.localdomain systemd[1]: Started NFS server and services.



Actual results:
gssproxy is not reloaded

Expected results:
gssproxy should reload

Additional info:
# journalctl -r
-- Logs begin at Wed 2018-01-17 10:35:15 UTC, end at Wed 2018-01-17 11:03:36 UTC. --
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-server comm="systemd" exe="/usr/lib/systemd/systemd" hostna
Jan 17 11:03:36 localhost.localdomain systemd[1]: Started NFS server and services.
Jan 17 11:03:36 localhost.localdomain kernel: NFSD: starting 90-second grace period (net f0000099)
Jan 17 11:03:36 localhost.localdomain rpc.mountd[824]: Version 3.1.1 starting
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-mountd comm="systemd" exe="/usr/lib/systemd/systemd" hostna
Jan 17 11:03:36 localhost.localdomain systemd[1]: Starting NFS server and services...
Jan 17 11:03:36 localhost.localdomain systemd[1]: Started NFS Mount Daemon.
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=rpc-statd comm="systemd" exe="/usr/lib/systemd/systemd" hostnam
Jan 17 11:03:36 localhost.localdomain systemd[1]: Failed to start NFS status monitor for NFSv2/3 locking..
Jan 17 11:03:36 localhost.localdomain systemd[1]: rpc-statd.service: Failed with result 'exit-code'.
Jan 17 11:03:36 localhost.localdomain systemd[1]: rpc-statd.service: Control process exited, code=exited status=1
Jan 17 11:03:36 localhost.localdomain rpc.statd[823]: Failed to create /var/lib/nfs/statd/state.new: Permission denied
Jan 17 11:03:36 localhost.localdomain audit[823]: AVC avc:  denied  { dac_override } for  pid=823 comm="rpc.statd" capability=1  scontext=system_u:system_r:rpcd_t:s0 tcontext=system_u:system_r:rpcd_t:s0 tclass=c
Jan 17 11:03:36 localhost.localdomain rpc.statd[823]: Initializing NSM state
Jan 17 11:03:36 localhost.localdomain rpc.statd[823]: Flags: TI-RPC
Jan 17 11:03:36 localhost.localdomain rpc.statd[823]: Version 3.1.1 starting
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-idmapd comm="systemd" exe="/usr/lib/systemd/systemd" hostna
Jan 17 11:03:36 localhost.localdomain systemd[1]: Started NFSv4 ID-name mapping service.
Jan 17 11:03:36 localhost.localdomain rpc.idmapd[822]: Setting log level to 0
Jan 17 11:03:36 localhost.localdomain systemd[1]: Starting NFS Mount Daemon...
Jan 17 11:03:36 localhost.localdomain systemd[1]: Starting NFSv4 ID-name mapping service...
Jan 17 11:03:36 localhost.localdomain systemd[1]: Starting NFS status monitor for NFSv2/3 locking....
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-config comm="systemd" exe="/usr/lib/systemd/systemd" hostnam
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-config comm="systemd" exe="/usr/lib/systemd/systemd" hostna
Jan 17 11:03:36 localhost.localdomain systemd[1]: Started Preprocess NFS configuration.
Jan 17 11:03:36 localhost.localdomain systemd[1]: Starting Preprocess NFS configuration...
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-mountd comm="systemd" exe="/usr/lib/systemd/systemd" hostnam
Jan 17 11:03:36 localhost.localdomain systemd[1]: Stopped NFS Mount Daemon.
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-idmapd comm="systemd" exe="/usr/lib/systemd/systemd" hostnam
Jan 17 11:03:36 localhost.localdomain systemd[1]: Stopped NFSv4 ID-name mapping service.
Jan 17 11:03:36 localhost.localdomain systemd[1]: Stopping NFS Mount Daemon...
Jan 17 11:03:36 localhost.localdomain rpc.mountd[763]: Caught signal 15, un-registering and exiting.
Jan 17 11:03:36 localhost.localdomain systemd[1]: Stopping NFSv4 ID-name mapping service...
Jan 17 11:03:36 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=nfs-server comm="systemd" exe="/usr/lib/systemd/systemd" hostnam
Jan 17 11:03:36 localhost.localdomain systemd[1]: Stopped NFS server and services.
Jan 17 11:03:36 localhost.localdomain kernel: nfsd: last server has exited, flushing export cache
Jan 17 11:03:36 localhost.localdomain systemd[1]: Stopping NFS server and services...

Comment 1 Bruno Goncalves 2018-01-17 11:05:46 UTC
Also I do not know about this message:

Jan 17 11:02:18 localhost.localdomain gssproxy[803]: [2018/01/17 11:02:18]: Problem with kernel communication!  NFS server will not work

Comment 3 Fedora Update System 2018-01-19 18:15:13 UTC
nfs-utils-2.2.1-4.rc2.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2018-8633570be3

Comment 4 Fedora Update System 2018-01-19 18:15:22 UTC
nfs-utils-2.2.1-4.rc2.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-4d8b609336

Comment 5 Fedora Update System 2018-01-21 09:43:15 UTC
nfs-utils-2.2.1-4.rc2.fc26 has been pushed to the Fedora 26 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-8633570be3

Comment 6 Fedora Update System 2018-01-21 10:40:48 UTC
nfs-utils-2.2.1-4.rc2.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-4d8b609336

Comment 7 Fedora Update System 2018-01-23 21:48:02 UTC
nfs-utils-2.2.1-4.rc2.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.

Comment 8 Fedora Update System 2018-02-06 10:47:49 UTC
nfs-utils-2.2.1-4.rc2.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.