Created attachment 534221 [details] F16 NFS configuration. Description of problem: Due to firewall requirements I've been using static ports for all NFS related services using variables defined in /etc/sysconfig/nfs (F15 and F16 versions attached). With the move to systemd, I've converted my /etc/sysconfig/nfs to systemd compatible version. However, no matter what I do systemctl start nfs-server.service silently fails without throwing any meaningful error code, even if I disable SELinux enforce. Manually starting each of the services listed in the systemd file works just fine. (See transcript below). I've managed to reproduce this issue on 3 different servers - all freshly installed. Version-Release number of selected component (if applicable): nfs-utils-1.2.5-1.fc16.x86_64 How reproducible: Always. Service start transcript: $ systemctl start nfs-lock.service Job failed. See system logs and 'systemctl status' for details. $ systemctl status nfs-lock.service nfs-lock.service - NFS file locking service. Loaded: loaded (/lib/systemd/system/nfs-lock.service; enabled) Active: failed since Wed, 16 Nov 2011 09:35:59 +0200; 6s ago Process: 28755 ExecStart=/sbin/rpc.statd $STATDARG (code=exited, status=1/FAILURE) Process: 28750 ExecStartPre=/usr/lib/nfs-utils/scripts/nfs-lock.preconfig (code=exited, status=0/SUCCESS) Main PID: 1940 (code=exited, status=1/FAILURE) CGroup: name=systemd:/system/nfs-lock.service $ cd /lib/systemd/system/ $ /usr/lib/nfs-utils/scripts/nfs-lock.preconfig ; echo $? 0 $ . /etc/sysconfig/nfs $ /usr/lib/nfs-utils/scripts/nfs-server.preconfig ; echo $? 0 $ echo /usr/sbin/rpc.rquotad $RPCRQUOTADOPTS /usr/sbin/rpc.rquotad --port 2051 $ /usr/sbin/rpc.rquotad $RPCRQUOTADOPTS ; echo $? 0 $ /usr/sbin/exportfs -r && echo $? 0 $ echo /usr/sbin/rpc.nfsd $RPCNFSDARGS ${RPCNFSDCOUNT} /usr/sbin/rpc.nfsd 8 $ /usr/sbin/rpc.nfsd $RPCNFSDARGS ${RPCNFSDCOUNT} ; echo $? 0 $ echo /usr/sbin/rpc.mountd $RPCMOUNTDOPTS /usr/sbin/rpc.mountd --port 2050 $ /usr/sbin/rpc.mountd $RPCMOUNTDOPTS ; echo $? 0 $ /usr/lib/nfs-utils/scripts/nfs-server.postconfig && echo $? 0 $ netstat -nlp | egrep -e 'stat|rpc|nfs' tcp 0 0 0.0.0.0:2050 0.0.0.0:* LISTEN 28877/rpc.mountd tcp 0 0 0.0.0.0:2051 0.0.0.0:* LISTEN 28857/rpc.rquotad tcp 0 0 0.0.0.0:2053 0.0.0.0:* LISTEN 28840/rpc.statd tcp 0 0 0.0.0.0:111 0.0.0.0:* LISTEN 28702/rpcbind tcp 0 0 :::2050 :::* LISTEN 28877/rpc.mountd tcp 0 0 :::2053 :::* LISTEN 28840/rpc.statd tcp 0 0 :::111 :::* LISTEN 28702/rpcbind udp 0 0 0.0.0.0:111 0.0.0.0:* 28702/rpcbind udp 0 0 127.0.0.1:608 0.0.0.0:* 28840/rpc.statd udp 0 0 0.0.0.0:893 0.0.0.0:* 28702/rpcbind udp 0 0 0.0.0.0:2050 0.0.0.0:* 28877/rpc.mountd udp 0 0 0.0.0.0:2051 0.0.0.0:* 28857/rpc.rquotad udp 0 0 0.0.0.0:2053 0.0.0.0:* 28840/rpc.statd udp 0 0 :::111 :::* 28702/rpcbind udp 0 0 :::893 :::* 28702/rpcbind udp 0 0 :::2050 :::* 28877/rpc.mountd udp 0 0 :::2053 :::* 28840/rpc.statd unix 2 [ ACC ] STREAM LISTENING 20287 28702/rpcbind /var/run/rpcbind.sock unix 2 [ ACC ] STREAM LISTENING 261075 1/systemd /var/run/rpcbind.sock
Created attachment 534222 [details] F15 NFS configuration.
I'm not see any problems...I took your f16 config and restarted everything I get: # sysctl fs.nfs.nlm_udpport fs.nfs.nlm_udpport = 2052 # sysctl fs.nfs.nlm_tcpport fs.nfs.nlm_tcpport = 2052 # rpcinfo -p | egrep "status|mountd|rquotad" 100011 1 udp 2051 rquotad 100011 2 udp 2051 rquotad 100011 1 tcp 2051 rquotad 100011 2 tcp 2051 rquotad 100024 1 udp 2053 status 100024 1 tcp 2053 status 100005 1 udp 2050 mountd 100005 1 tcp 2050 mountd 100005 2 udp 2050 mountd 100005 2 tcp 2050 mountd 100005 3 udp 2050 mountd 100005 3 tcp 2050 mountd What am I missing? Note, I did this test with a nfs-utils-1.2.5-3.fc16 rpm
I'm lost. Upgraded to 1.2.5-3 from updates-testing, killed all the RPC servers beyond rpcbind. $ systemctl stop nfs-server.service $ netstat -nlp | egrep -e 'stat|rpc|nfs' tcp 0 0 0.0.0.0:111 0.0.0.0:* LISTEN 28702/rpcbind tcp 0 0 :::111 :::* LISTEN 28702/rpcbind udp 0 0 0.0.0.0:111 0.0.0.0:* 28702/rpcbind udp 0 0 0.0.0.0:893 0.0.0.0:* 28702/rpcbind udp 0 0 :::111 :::* 28702/rpcbind udp 0 0 :::893 :::* 28702/rpcbind unix 2 [ ACC ] STREAM LISTENING 20287 28702/rpcbind /var/run/rpcbind.sock unix 2 [ ACC ] STREAM LISTENING 261075 1/systemd /var/run/rpcbind.sock $ systemctl start nfs-lock.service Job failed. See system logs and 'systemctl status' for details. $ systemctl status nfs-lock.service nfs-lock.service - NFS file locking service. Loaded: loaded (/lib/systemd/system/nfs-lock.service; enabled) Active: failed since Fri, 18 Nov 2011 22:49:09 +0200; 5s ago Process: 5574 ExecStart=/sbin/rpc.statd $STATDARG (code=exited, status=1/FAILURE) Process: 5569 ExecStartPre=/usr/lib/nfs-utils/scripts/nfs-lock.preconfig (code=exited, status=0/SUCCESS) Main PID: 1940 (code=exited, status=1/FAILURE) CGroup: name=systemd:/system/nfs-lock.service $ echo ... Trying nfs-server, just in-case... ... Trying nfs-server, just in-case... $ systemctl start nfs-server.service $ sleep 10s; systemctl status nfs-server.service nfs-server.service - NFS Server Loaded: loaded (/lib/systemd/system/nfs-server.service; enabled) Active: active (running) since Fri, 18 Nov 2011 22:46:45 +0200; 20s ago Process: 5211 ExecStopPost=/usr/sbin/exportfs -f (code=exited, status=0/SUCCESS) Process: 5209 ExecStop=/usr/sbin/rpc.nfsd 0 (code=exited, status=0/SUCCESS) Process: 5307 ExecStartPost=/usr/sbin/rpc.mountd $RPCMOUNTDOPTS (code=exited, status=1/FAILURE) Process: 5295 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS ${RPCNFSDCOUNT} (code=exited, status=0/SUCCESS) Process: 5294 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS) Process: 5292 ExecStartPre=/usr/sbin/rpc.rquotad $RPCRQUOTADOPTS (code=exited, status=0/SUCCESS) Process: 5290 ExecStartPre=/usr/lib/nfs-utils/scripts/nfs-server.preconfig (code=exited, status=0/SUCCESS) Main PID: 5293 (rpc.rquotad) CGroup: name=systemd:/system/nfs-server.service └ 5293 /usr/sbin/rpc.rquotad --port 2051 $ netstat -nlp | egrep -e 'stat|rpc|nfs' tcp 0 0 0.0.0.0:809 0.0.0.0:* LISTEN 5293/rpc.rquotad tcp 0 0 0.0.0.0:111 0.0.0.0:* LISTEN 28702/rpcbind tcp 0 0 :::111 :::* LISTEN 28702/rpcbind udp 0 0 0.0.0.0:111 0.0.0.0:* 28702/rpcbind udp 0 0 0.0.0.0:806 0.0.0.0:* 5293/rpc.rquotad udp 0 0 0.0.0.0:893 0.0.0.0:* 28702/rpcbind udp 0 0 :::111 :::* 28702/rpcbind udp 0 0 :::893 :::* 28702/rpcbind unix 2 [ ACC ] STREAM LISTENING 20287 28702/rpcbind /var/run/rpcbind.sock unix 2 [ ACC ] STREAM LISTENING 261075 1/systemd /var/run/rpcbind.sock
(In reply to comment #3) > I'm lost. > Upgraded to 1.2.5-3 from updates-testing, killed all the RPC servers beyond > rpcbind. > > $ systemctl stop nfs-server.service > $ systemctl start nfs-lock.service > Job failed. See system logs and 'systemctl status' for details. There should be some type of error message in /var/log/messages.
Gaah, I wonder why I didn't notice it to begin with. SELinux issue. setenforce 1: rpc.rquotad[4279]: rpc.rquotad: Cannot bind to given address: Permission denied rpc.rquotad[4279]: rpc.rquotad: Cannot bind to given address: Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: Could not bind socket: (13) Permission denied rpc.mountd[4283]: mountd: could not create listeners nfs-server.service: control process exited, code=exited status=1 nfsd: last server has exited, flushing export cache Unit nfs-server.service entered failed state. setenforce 0: avc: received setenforce notice (enforcing=0) NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory NFSD: starting 90-second grace period ... The weird thing is when I try to start the services by hand, selinux doesn't kick in - only when systemd tried to start nfs. - Gilboa
CC one of our selinux guys... Dan, what's need to figure out what the problem is ?
What AVC's are you seeing? Get the problem to happen # ausearch -m avc -ts recent
$ systemctl stop nfs-server.service $ sleep 5s $ systemctl start nfs-server.service $ sleep 10s $ systemctl status nfs-server.service nfs-server.service - NFS Server Loaded: loaded (/lib/systemd/system/nfs-server.service; enabled) Active: active (running) since Thu, 24 Nov 2011 07:40:23 +0200; 2min 52s ago Process: 8123 ExecStartPost=/usr/sbin/rpc.mountd $RPCMOUNTDOPTS (code=exited, status=1/FAILURE) Process: 8122 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS ${RPCNFSDCOUNT} (code=exited, status=0/SUCCESS) Process: 8121 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS) Process: 8119 ExecStartPre=/usr/sbin/rpc.rquotad $RPCRQUOTADOPTS (code=exited, status=0/SUCCESS) Process: 8117 ExecStartPre=/usr/lib/nfs-utils/scripts/nfs-server.preconfig (code=exited, status=0/SUCCESS) Main PID: 8120 (rpc.rquotad) CGroup: name=systemd:/system/nfs-server.service └ 8120 /usr/sbin/rpc.rquotad --port 2051 $ ausearch -m avc -ts recent <no matches> $ tail -n 40 /var/log/messages | grep rpc Nov 24 07:40:23 gilboa-home-dev rpc.rquotad[8119]: rpc.rquotad: Cannot bind to given address: Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.rquotad[8119]: rpc.rquotad: Cannot bind to given address: Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: Could not bind socket: (13) Permission denied Nov 24 07:40:23 gilboa-home-dev rpc.mountd[8123]: mountd: could not create listeners $ systemctl stop nfs-server.service $ sleep 5s $ setenforce 0 $ systemctl start nfs-server.service $ sleep 10s $ systemctl status nfs-server.service nfs-server.service - NFS Server Loaded: loaded (/lib/systemd/system/nfs-server.service; enabled) Active: active (running) since Thu, 24 Nov 2011 07:44:07 +0200; 41s ago Process: 8465 ExecStopPost=/usr/sbin/exportfs -f (code=exited, status=0/SUCCESS) Process: 8463 ExecStop=/usr/sbin/rpc.nfsd 0 (code=exited, status=0/SUCCESS) Process: 8500 ExecStartPost=/usr/lib/nfs-utils/scripts/nfs-server.postconfig (code=exited, status=0/SUCCESS) Process: 8498 ExecStartPost=/usr/sbin/rpc.mountd $RPCMOUNTDOPTS (code=exited, status=0/SUCCESS) Process: 8486 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS ${RPCNFSDCOUNT} (code=exited, status=0/SUCCESS) Process: 8485 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS) Process: 8483 ExecStartPre=/usr/sbin/rpc.rquotad $RPCRQUOTADOPTS (code=exited, status=0/SUCCESS) Process: 8481 ExecStartPre=/usr/lib/nfs-utils/scripts/nfs-server.preconfig (code=exited, status=0/SUCCESS) Main PID: 8484 (rpc.rquotad) CGroup: name=systemd:/system/nfs-server.service ├ 8484 /usr/sbin/rpc.rquotad --port 2051 └ 8499 /usr/sbin/rpc.mountd --port 2050 Gaaah?
systemctl enable auditd.service systemctl start auditd.service THen you should get AVC messages. Currently if you execute dmesg | grep avc You should see them.
auditd was already enabled and running. P.S. May or may not be relevant - IPv6 is completely disabled (via sysctl) on these machines. $ systemctl status auditd.service auditd.service - Security Auditing Service Loaded: loaded (/lib/systemd/system/auditd.service; enabled) Active: active (running) since Thu, 24 Nov 2011 07:49:05 +0200; 4 days ago Main PID: 2617 (auditd) CGroup: name=systemd:/system/auditd.service ├ 2617 /sbin/auditd -n ├ 2621 /sbin/audispd └ 2622 /usr/sbin/sedispatch $ systemctl stop nfs-server.service $ tail /var/log/messages -n 100 | grep rpc rpc.rquotad[4217]: rpc.rquotad: Cannot bind to given address: Permission denied rpc.rquotad[4217]: rpc.rquotad: Cannot bind to given address: Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: Could not bind socket: (13) Permission denied rpc.mountd[4221]: mountd: could not create listeners
(Forgot to add) $ dmesg | grep avc $
# semodule -DB To disable dontaudit rules. then try to start the service. See if there are avc's related to the ports. # semodule -B Turns back on the dontaudit rules.
$ semodule -DB $ killall rpc.statd rpc.rquotad rpc.mountd $ systemctl stop nfs-server.service $ systemctl start nfs-server.service $ sleep 5s $ dmesg -c | grep avc $ tail /var/log/messages -n 100 | grep rpc rpc.mountd[4612]: Caught signal 15, un-registering and exiting. rpc.mountd[4610]: Caught signal 15, un-registering and exiting. rpc.rquotad[7570]: rpc.rquotad: Cannot bind to given address: Permission denied rpc.rquotad[7570]: rpc.rquotad: Cannot bind to given address: Permission denied rpc.mountd[7574]: Could not bind socket: (13) Permission denied rpc.mountd[7574]: Could not bind socket: (13) Permission denied ... rpc.mountd[7574]: mountd: could not create listeners Gaaah :(
grep avc /var/log/audit/audit.log
grep avc /var/log/audit/audit.log | tail -n10 type=AVC msg=audit(1322716499.838:28680): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=udp_socket type=AVC msg=audit(1322716499.838:28681): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=tcp_socket type=AVC msg=audit(1322716499.839:28682): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=udp_socket type=AVC msg=audit(1322716499.839:28683): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=tcp_socket type=AVC msg=audit(1322716499.839:28684): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=udp_socket type=AVC msg=audit(1322716499.839:28685): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=tcp_socket type=AVC msg=audit(1322716499.839:28686): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=udp_socket type=AVC msg=audit(1322716499.839:28687): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=tcp_socket type=AVC msg=audit(1322716499.839:28688): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=udp_socket type=AVC msg=audit(1322716499.839:28689): avc: denied { name_bind } for pid=18403 comm="rpc.mountd" src=2050 scontext=system_u:system_r:nfsd_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=tcp_socket
Keep in mind that when I start mountd and statd from a script, it works just fine.
Because they are then running as your user context, not as a confined domain, meaning you are running them as unconfined_t. This problem should be fixed in selinux-policy-3.10.0-57 Please yum -y update.
Fixed. Thanks!