Bug 1253839

(In reply to Brian J. Murrell from comment #0)

> Additional info:
> # systemctl status nfs-server
> ● nfs-server.service - NFS server and services
>    Loaded: loaded (/usr/lib/systemd/system/nfs-server.service; enabled;
> vendor preset: disabled)
I wonder what "vendor preset: disabled" means?

Just a guess, but my guess is that it's the state of the service as shipped by the vendor, Red Hat.

This is ****still**** happening on F23.

Is there any chance at all at making any progress on this issue?

I am happy to do whatever testing, debugging, information gathering, etc. that you would like/need.

(In reply to Brian J. Murrell from comment #3)
> This is ****still**** happening on F23.
> 
> Is there any chance at all at making any progress on this issue?
> 
> I am happy to do whatever testing, debugging, information gathering, etc.
> that you would like/need.

I have no idea why this is not working... The service is 
enabled so it should be started... 

The nfs-server.service script is the same one upstream is using 
and this problem is not being reported so I guess 
other distros aren't see this.. 

Not to passes the buck but I'm going to reassign this 
to systemd people b/c I can't see what's wrong so 
I really don't know how to debug it...  Maybe they can.

I'm confused: did the reporter enable nfs-server?

I believe the described behavior is as expected.  You need to run "systemctl enable nfs-server" to request that it be run on next boot.

(In reply to J. Bruce Fields from comment #5)
> I'm confused: did the reporter enable nfs-server?

Most certainly.  From the first comment/description:

Additional info:
# systemctl status nfs-server
● nfs-server.service - NFS server and services
   Loaded: loaded (/usr/lib/systemd/system/nfs-server.service; enabled; vendor preset: disabled)
   Active: inactive (dead)


And from the system currently:

# systemctl status nfs-server
● nfs-server.service - NFS server and services
   Loaded: loaded (/usr/lib/systemd/system/nfs-server.service; enabled; vendor preset: disabled)
   Active: active (exited) since Thu 2015-11-19 12:31:49 EST; 27min ago
  Process: 14462 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS (code=exited, status=0/SUCCESS)
  Process: 14455 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS)
 Main PID: 14462 (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/nfs-server.service

Nov 19 12:31:49 pc.interlinx.bc.ca systemd[1]: Starting NFS server and services...
Nov 19 12:31:49 pc.interlinx.bc.ca systemd[1]: Started NFS server and services.
 
> I believe the described behavior is as expected.  You need to run "systemctl
> enable nfs-server" to request that it be run on next boot.

Indeed.  I knew that.  I did that.  I think the output above confirms it: "/usr/lib/systemd/system/nfs-server.service; enabled;" yes?

(In reply to Brian J. Murrell from comment #6)
> Indeed.  I knew that.  I did that.  I think the output above confirms it:
> "/usr/lib/systemd/system/nfs-server.service; enabled;" yes?

Got it, thanks!

Have you checked the logs for anything possibly relevant?  I would have thought anything relevant would already be included in the "systemctl status" output, but maybe not.

I tried on a fresh F23 install:

   # mkdir /exports
   # echo "/exports localhost(rw)" >/etc/exports
   # systemctl enable nfs-server
   # reboot

and the server came up after boot.

(In reply to J. Bruce Fields from comment #7)
> 
> Have you checked the logs for anything possibly relevant?

Yeah, nothing.

> I tried on a fresh F23 install:
> 
>    # mkdir /exports
>    # echo "/exports localhost(rw)" >/etc/exports
>    # systemctl enable nfs-server
>    # reboot
> 
> and the server came up after boot.

Yeah, I'm not at all surprised or this ticket would not have been idle for so long.

But this problem is absolutely 100% reproducible here so something is not right/working in my circumstances so undoubtedly some kind of corner-case bug.  The question is just what and how to gather more information to figure out what.

It's something that only happens at boot so somehow we need to gather more information about what is [not] happening at boot that the nfs-server doesn't get started (or gets started and dies right away) here.

I'm pretty experienced with how Linux systems boot and poking around while they do boot.  Or rather I was before systemd.  That's not at all meant to be a systemd bash by any means -- I am not one of the hoard of systemd bashers out there, but am just calling it how it is at this point in time.

(In reply to Brian J. Murrell from comment #8)
> (In reply to J. Bruce Fields from comment #7)
> 
> But this problem is absolutely 100% reproducible here so something is not
> right/working in my circumstances so undoubtedly some kind of corner-case
> bug.  The question is just what and how to gather more information to figure
> out what.
True this is definitely a corner case... But I have seen it
take longer than expected for the NFS server to come up after 
a reboot. 
 
> 
> It's something that only happens at boot so somehow we need to gather more
> information about what is [not] happening at boot that the nfs-server
> doesn't get started (or gets started and dies right away) here.
This is why I've asked the systemd people to take a look, to
hopefully help debug this... 

> 
> I'm pretty experienced with how Linux systems boot and poking around while
> they do boot.  Or rather I was before systemd.  That's not at all meant to
> be a systemd bash by any means -- I am not one of the hoard of systemd
> bashers out there, but am just calling it how it is at this point in time.
Aren't we all.. but it is what it is... we are in a new world... 
The systemd world.. So we are going have to learn a whole new
way of debugging...

Can you please boot up in debug mode, add following on kernel command line
systemd.log_level=debug systemd.log_target=kmsg log_buf_len=4M and attach output of journalctl -b?

I know this is getting old. Anyhow, did you try booting with SELinux in permissive mode?

(In reply to Michal Sekletar from comment #10)
> Can you please boot up in debug mode, add following on kernel command line
> systemd.log_level=debug systemd.log_target=kmsg log_buf_len=4M and attach
> output of journalctl -b?
> 
Wow... that does spew ton of debugging... Thanks for the tip... 
To make the output a bit more readable I used
  journalctl -o cat -b

Created attachment 1097212 [details]
journalctl -o cat -b output

(In reply to Brian J. Murrell from comment #12)
> Created attachment 1097212 [details]
> journalctl -o cat -b output

Doing a diff of my working system and your non-working system
I see the following:

Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 object=/org/freedesktop/systemd1/unit/nfs_2dserver_2eservice interface=org.freedesktop.DBus.Properties member=GetAll cookie=1 reply_cookie=0 error=n/a

SELinux access check scon=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 tcon=system_u:object_r:nfsd_unit_file_t:s0 tclass=service perm=status path=/usr/lib/systemd/system/nfs-server.service cmdline=systemctl status nfs-server: 0
Preset file says disable nfs-server.service.

If I'm reading this correct it appear SELinux is telling systemd
to "disable nfs-server.service". Is that possible?

Note on my working systemd selinux is enabled so maybe
its some type of labelling issue?

(In reply to Steve Dickson from comment #13)
> 
> Got message type=method_call sender=n/a destination=org.freedesktop.systemd1
> object=/org/freedesktop/systemd1/unit/nfs_2dserver_2eservice
> interface=org.freedesktop.DBus.Properties member=GetAll cookie=1
> reply_cookie=0 error=n/a
> 
> SELinux access check
> scon=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
> tcon=system_u:object_r:nfsd_unit_file_t:s0 tclass=service perm=status
> path=/usr/lib/systemd/system/nfs-server.service cmdline=systemctl status
> nfs-server: 0
> Preset file says disable nfs-server.service.

Yeah, I took particular notice of that too, but I wasn't quite sure what it was trying to tell me.

> Note on my working systemd selinux is enabled so maybe
> its some type of labelling issue?

Yeah, I have it enabled and enforcing also.  I thought it might be a labelling issue also but the nfs-server unit file and links look the same as the rest.  Nothing odd stood out for me.

@Michal: Was there anything useful in that debug I attached last week?

@Michal?  Any chance you will have a chance to look at the data I provided for your ask?

(In reply to Brian J. Murrell from comment #15)
> @Michal: Was there anything useful in that debug I attached last week?

Ahh, sorry for the delay.

I grepped trough the log file provided and also checked unit file for NFS server and couple related services. To be honest I can't make sense out of all this information yet.

Anyway, let's start debugging.

First, I'd like to know whether nfs-server.service is actually enabled at the time systemd is putting together initial boot transaction. I'd suggest pausing boot just before switch root from initramfs (add rd.break on kernel command line and in spawned bash type chroot /sysroot) and check whether symlink /etc/systemd/system/multi-user.target.wants/nfs-server.service -> /usr/lib/systemd/system/nfs-server.service actually exists.

PS: as for SELinux related log message posted in comment #13, it is harmless. It basically says that status of nfs-server.service was requested by user on command line (guessing based on scon) and systemd didn't have any information about related unit file thus it parsed it from disk and discovered that preset status is disabled.

Here (#1209213) is a very similarly sounding report. Brian, are we sure that we are not dealing with the same problem? Can you verify that fix described there doesn't fix this issue. I mean, trying following

(In reply to David Jones from comment #0)
> The problem is that, when nfs-server was enabled originally, the link was
> placed in /etc/systemd/system/nfs.target.wants. The update removed
> nfs.target, so the service is never started.
> 
> Disabling and re-enabling re-links nfs-server to
> /etc/systemd/system/multi-user.target.wants.

The problem with bug 1209213 is that it was closed, duplicated to s "secret" ticket so nobody can follow along on the solution.  Before I go ahead and start fiddling with the service this is what I have:

$ ls -l /etc/systemd/system/nfs.target.wants
total 3
lrwxrwxrwx. 1 root root 49 Jun 18  2014 nfs-secure-server.service -> /usr/lib/systemd/system/nfs-secure-server.service
lrwxrwxrwx. 1 root root 42 Nov 29  2013 nfs-secure.service -> /usr/lib/systemd/system/nfs-secure.service
lrwxrwxrwx. 1 root root 42 Jun  2  2014 nfs-server.service -> /usr/lib/systemd/system/nfs-server.service

The first link above is broken:

$ ls -l /usr/lib/systemd/system/nfs-secure-server.service
ls: cannot access /usr/lib/systemd/system/nfs-secure-server.service: No such file or directory

The subsequent two are fine:
$ ls -l /usr/lib/systemd/system/nfs-secure.service /usr/lib/systemd/system/nfs-server.service
lrwxrwxrwx. 1 root root  16 Nov  5 07:17 /usr/lib/systemd/system/nfs-secure.service -> rpc-gssd.service
-rw-r--r--. 1 root root 998 Nov  5 07:17 /usr/lib/systemd/system/nfs-server.service

and:

$ ls -l /etc/systemd/system/multi-user.target.wants/
total 37
lrwxrwxrwx. 1 root root 41 Jul 12  2013 abrt-ccpp.service -> /usr/lib/systemd/system/abrt-ccpp.service
lrwxrwxrwx. 1 root root 37 Jul 12  2013 abrtd.service -> /usr/lib/systemd/system/abrtd.service
lrwxrwxrwx. 1 root root 41 Jul 12  2013 abrt-oops.service -> /usr/lib/systemd/system/abrt-oops.service
lrwxrwxrwx. 1 root root 43 Jul 12  2013 abrt-vmcore.service -> /usr/lib/systemd/system/abrt-vmcore.service
lrwxrwxrwx. 1 root root 41 Jul 12  2013 abrt-xorg.service -> /usr/lib/systemd/system/abrt-xorg.service
lrwxrwxrwx. 1 root root 37 Nov  7  2013 acpid.service -> /usr/lib/systemd/system/acpid.service
lrwxrwxrwx. 1 root root 35 Jul 12  2013 atd.service -> /usr/lib/systemd/system/atd.service
lrwxrwxrwx. 1 root root 38 Jul 12  2013 auditd.service -> /usr/lib/systemd/system/auditd.service
lrwxrwxrwx. 1 root root 38 Jan  5  2014 autofs.service -> /usr/lib/systemd/system/autofs.service
lrwxrwxrwx. 1 root root 44 Jul 12  2013 avahi-daemon.service -> /usr/lib/systemd/system/avahi-daemon.service
lrwxrwxrwx. 1 root root 37 Jul 12  2013 crond.service -> /usr/lib/systemd/system/crond.service
lrwxrwxrwx. 1 root root 44 Nov 19 11:02 cups-browsed.service -> /usr/lib/systemd/system/cups-browsed.service
lrwxrwxrwx. 1 root root 33 Jul 12  2013 cups.path -> /usr/lib/systemd/system/cups.path
lrwxrwxrwx. 1 root root 42 Jul 12  2013 irqbalance.service -> /usr/lib/systemd/system/irqbalance.service
lrwxrwxrwx. 1 root root 40 Jul 12  2013 libvirtd.service -> /usr/lib/systemd/system/libvirtd.service
lrwxrwxrwx. 1 root root 42 Nov  4  2013 lm_sensors.service -> /usr/lib/systemd/system/lm_sensors.service
lrwxrwxrwx. 1 root root 38 Jul 12  2013 mcelog.service -> /usr/lib/systemd/system/mcelog.service
lrwxrwxrwx. 1 root root 41 Jul 12  2013 mdmonitor.service -> /usr/lib/systemd/system/mdmonitor.service
lrwxrwxrwx. 1 root root 44 Dec 24  2014 ModemManager.service -> /usr/lib/systemd/system/ModemManager.service
lrwxrwxrwx. 1 root root 49 Dec 24  2014 netcf-transaction.service -> /usr/lib/systemd/system/netcf-transaction.service
lrwxrwxrwx. 1 root root 57 Jul 29  2013 NetworkManager-dispatcher.service -> /usr/lib/systemd/system/NetworkManager-dispatcher.service
lrwxrwxrwx. 1 root root 46 Jul 12  2013 NetworkManager.service -> /usr/lib/systemd/system/NetworkManager.service
lrwxrwxrwx. 1 root root 41 Feb  1  2015 nfs-client.target -> /usr/lib/systemd/system/nfs-client.target
lrwxrwxrwx. 1 root root 34 Nov 28  2014 nfs.target -> /usr/lib/systemd/system/nfs.target
lrwxrwxrwx. 1 root root 36 Aug  9 11:34 ntpd.service -> /usr/lib/systemd/system/ntpd.service
lrwxrwxrwx. 1 root root 37 Jun 17  2014 ospfd.service -> /usr/lib/systemd/system/ospfd.service
lrwxrwxrwx. 1 root root 39 Jun 18  2014 postfix.service -> /usr/lib/systemd/system/postfix.service
lrwxrwxrwx. 1 root root 40 Jul 12  2013 remote-fs.target -> /usr/lib/systemd/system/remote-fs.target
lrwxrwxrwx. 1 root root 36 Jul 12  2013 rngd.service -> /usr/lib/systemd/system/rngd.service
lrwxrwxrwx. 1 root root 39 Jul 12  2013 rpcbind.service -> /usr/lib/systemd/system/rpcbind.service
lrwxrwxrwx. 1 root root 39 Jul 12  2013 rsyslog.service -> /usr/lib/systemd/system/rsyslog.service
lrwxrwxrwx. 1 root root 40 Apr  3  2014 SABnzbd -> /usr/lib/systemd/system/SABnzbd@.service
lrwxrwxrwx. 1 root root 40 Mar 17  2014 SABnzbd@.service -> /usr/lib/systemd/system/SABnzbd@.service
lrwxrwxrwx. 1 root root 38 Jul 12  2013 smartd.service -> /usr/lib/systemd/system/smartd.service
lrwxrwxrwx. 1 root root 36 Jul 12  2013 sshd.service -> /usr/lib/systemd/system/sshd.service
lrwxrwxrwx. 1 root root 36 Aug  9 11:34 sssd.service -> /usr/lib/systemd/system/sssd.service
lrwxrwxrwx. 1 root root 37 Oct 16  2014 zebra.service -> /usr/lib/systemd/system/zebra.service

The nfs.target link is broken:

$ ls -l /usr/lib/systemd/system/nfs.target
ls: cannot access /usr/lib/systemd/system/nfs.target: No such file or directory

Is that enough information to confirm that this is a duplicate of bug 1209213, or rather bug 1203765 which the mere mortals cannot see?

If so, a package update fixing all of this breakage ought to be produced, yes?

@Michal Any thoughts on my question in comment #21?

(In reply to Brian J. Murrell from comment #21)
> The problem with bug 1209213 is that it was closed, duplicated to s "secret"
> ticket so nobody can follow along on the solution.  Before I go ahead and
> start fiddling with the service this is what I have:
> 
> $ ls -l /etc/systemd/system/nfs.target.wants
> total 3
> lrwxrwxrwx. 1 root root 49 Jun 18  2014 nfs-secure-server.service ->
> /usr/lib/systemd/system/nfs-secure-server.service
> lrwxrwxrwx. 1 root root 42 Nov 29  2013 nfs-secure.service ->
> /usr/lib/systemd/system/nfs-secure.service
> lrwxrwxrwx. 1 root root 42 Jun  2  2014 nfs-server.service ->
> /usr/lib/systemd/system/nfs-server.service
This is interesting.... 
f23# ls -l /etc/systemd/system/nfs.target.wants
/bin/ls: cannot access /etc/systemd/system/nfs.target.wants: No such file or directory

But on f22
f22$ ll /etc/systemd/system/nfs.target.wants
total 4.0K
50375814 drwxr-xr-x.  2 root root   29 Mar 31  2015 .
17341034 drwxr-xr-x. 16 root root 4.0K Oct 19 05:21 ..
50556747 lrwxrwxrwx.  1 root root   40 Jan  6  2015 nfs-lock.service -> /usr/lib/systemd/system/nfs-lock.service


> 
> The first link above is broken:
> 
> $ ls -l /usr/lib/systemd/system/nfs-secure-server.service
> ls: cannot access /usr/lib/systemd/system/nfs-secure-server.service: No such
> file or directory
This is the same on both my f23 and f22 which is not a problem
because the server now uses gssproxy.

> 
> The subsequent two are fine:
> $ ls -l /usr/lib/systemd/system/nfs-secure.service
> /usr/lib/systemd/system/nfs-server.service
> lrwxrwxrwx. 1 root root  16 Nov  5 07:17
> /usr/lib/systemd/system/nfs-secure.service -> rpc-gssd.service
> -rw-r--r--. 1 root root 998 Nov  5 07:17
> /usr/lib/systemd/system/nfs-server.service
On both systems that file is:

f22$ ls -l /usr/lib/systemd/system/nfs-secure.service
lrwxrwxrwx. 1 root root 16 Nov  5 07:18 /usr/lib/systemd/system/nfs-secure.service -> rpc-gssd.service

> and:
> 
> $ ls -l /etc/systemd/system/multi-user.target.wants/
> total 37
> lrwxrwxrwx. 1 root root 38 Jan  5  2014 autofs.service ->
> /usr/lib/systemd/system/autofs.service
> lrwxrwxrwx. 1 root root 41 Feb  1  2015 nfs-client.target ->
> /usr/lib/systemd/system/nfs-client.target
> lrwxrwxrwx. 1 root root 34 Nov 28  2014 nfs.target ->
> /usr/lib/systemd/system/nfs.target
This is wrong... I have 
lrwxrwxrwx.  1 root root   41 Jan 20  2015 nfs-client.target -> /usr/lib/systemd/system/nfs-client.target
lrwxrwxrwx.  1 root root   42 Feb  3  2015 nfs-server.service -> /usr/lib/systemd/system/nfs-server.service

> 
> The nfs.target link is broken:
> 
> $ ls -l /usr/lib/systemd/system/nfs.target
> ls: cannot access /usr/lib/systemd/system/nfs.target: No such file or
> directory
Try 
  systemctl disable nfs.target # to remove the link
Then do 
  systemctl enable nfs-server

> 
> Is that enough information to confirm that this is a duplicate of bug
> 1209213, or rather bug 1203765 which the mere mortals cannot see?
I opened them up for you.... Basically rpcbind was not start which 
was cause the server not to start but there were error messages
in /var/log/message... I believe... 

> 
> If so, a package update fixing all of this breakage ought to be produced,
> yes?
Try removing nfs-utils and then reinstalling.

In comment #20 I actually referenced incorrect bug. Sorry about that. Actually, I wanted to ask whether this is not the same bug as https://bugzilla.redhat.com/show_bug.cgi?id=1178720.

According to comment #21 I think this is the same bug. Basically, nfs is not started because it is not pulled in to the boot transaction due to messed up symlinks.

At any rate, I don't think this is caused by bug in systemd. Seems more like packaging bug in nfs-utils.

@Steve, feel free to reassign back if you disagree with my assessment.

(In reply to Steve Dickson from comment #24)
> 
> Try 
>   systemctl disable nfs.target # to remove the link
> Then do 
>   systemctl enable nfs-server

It might have been from doing this, but I seem to have NFS starting when Fedora does now.

Thanks much for all of the insight!!