bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

The rpc.mountd service, one of the required services for
nfs-service-type, respawns the process quickly until disabled.

Opening the service file,
/ssh:hurd:/gnu/store/qq1dd9rqa2svxhbkpiq6bkpg6dyxwzqb-shepherd-rpc.mountd.scm:

--8<---------------cut here---------------start------------->8---
(eval-when
    (expand load eval)
  (let
      ((extensions
	(quote
	 ()))
       (prepend
	(lambda
	    (items lst)
	  (let loop
	      ((items items)
	       (lst lst))
	    (if
	     (null? items)
	     lst
	     (loop
	      (cdr items)
	      (cons
	       (car items)
	       (delete
		(car items)
		lst))))))))
    (set! %load-path
      (prepend
       (cons "/gnu/store/wy6fvwp3dfrp9frckdascrrb9rvn3h3g-module-import"
	     (map
	      (lambda
		  (extension)
		(string-append extension "/share/guile/site/"
			       (effective-version)))
	      extensions))
       %load-path))
    (set! %load-compiled-path
      (prepend
       (cons "/gnu/store/xd4lwx10ljn902712sphac3k0k97g1vy-module-import-compiled"
	     (map
	      (lambda
		  (extension)
		(string-append extension "/lib/guile/"
			       (effective-version)
			       "/site-ccache"))
	      extensions))
       %load-compiled-path))))
(begin
  (use-modules
   (shepherd service)
   (oop goops)
   (guix build utils)
   (guix build syscalls))
  (make <service> #:docstring
	(quote "Run the NFS mountd daemon.")
	#:provides
	(quote
	 (rpc.mountd))
	#:requires
	(quote
	 (rpc.statd))
	#:one-shot?
	(quote #f)
	#:respawn?
	(quote #t)
	#:start
	(make-forkexec-constructor
	 (list "/gnu/store/c7kpr1jh5z3mrkz0yw9am86851y57cq7-nfs-utils-2.4.2/sbin/rpc.mountd" "--debug" "all"))
	#:stop
	(make-kill-destructor)
	#:actions
	(make-actions)))
--8<---------------cut here---------------end--------------->8---

The process is launched with the equivalent of:

$ /gnu/store/c7kpr1jh5z3mrkz0yw9am86851y57cq7-nfs-utils-2.4.2/sbin/rpc.mountd \
    --debug all

Which doesn't print any output, but returns cleanly.  The process is
daemonized and runs in the background.

Attempting the equivalent using Shepherd yields the same:

scheme@(guix-user)> ,m (shepherd service)
;;; WARNING: loading compiled file /run/current-system/profile/lib/guile/2.2/site-ccache/shepherd/service.go failed:
;;; In procedure load-thunk-from-memory: incompatible bytecode kind

[...]

scheme@(shepherd service)> (make-forkexec-constructor (list "/gnu/store/c7kpr1jh5z3mrkz0yw9am86851y57cq7-nfs-utils-2.4.2/sbin/rpc.mountd" "--debug" "all"))
$1 = #<procedure 7f472f0dbca0 at ice-9/eval.scm:383:13 rest>
scheme@(shepherd service)> ($1)
$2 = 19655

We get back the PID of the rpc.mountd process, and it lives on.

So, I wonder what is causing Shepherd to respawn the process?

Maxim

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Ludovic Courtès]

Hi,

Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:

> The rpc.mountd service, one of the required services for
> nfs-service-type, respawns the process quickly until disabled.

Does /var/log/messages contain hints?  Is rpc.statd running?
Could it be that all these services need to depend on ‘loopback’?

No answers, but a lot of questions.  :-)

Ludo’.

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

Hello Ludovic!

Ludovic Courtès <ludo@gnu.org> writes:

> Hi,
>
> Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:
>
>> The rpc.mountd service, one of the required services for
>> nfs-service-type, respawns the process quickly until disabled.
>
> Does /var/log/messages contain hints?

 herd restart nfs
Service nfs has been stopped.
Service rpc.mountd is currently disabled.
Service nfs depends on rpc.mountd.
Service nfs could not be started.
root@hurd ~# herd stop rpc.mountd
root@hurd ~# herd enable rpc.mountd
Enabled service rpc.mountd.
root@hurd ~# herd status rpc.mountd
Status of rpc.mountd:
  It is stopped.
  It is enabled.
  Provides (rpc.mountd).
  Requires (rpc.statd).
  Conflicts with ().
  Will be respawned.
  Last respawned on Sat Mar 07 21:56:43-0500 2020.
root@hurd ~# herd restart nfs
Service nfs is not running.
Service rpc.mountd has been started.
Service nfs has been started.

And then, in /var/log/messages:

Mar  7 21:56:4--8<---------------cut here---------------start------------->8---
Mar  7 22:06:45 localhost shepherd[1]: Service nfs has been stopped. 
Mar  7 22:06:45 localhost shepherd[1]: Service rpc.mountd is currently disabled. 
Mar  7 22:06:45 localhost shepherd[1]: Service nfs depends on rpc.mountd. 
Mar  7 22:06:45 localhost shepherd[1]: Service nfs could not be started. 
Mar  7 22:07:05 localhost shepherd[1]: Enabled service rpc.mountd. 
Mar  7 22:07:15 localhost shepherd[1]: Service nfs is not running. 
Mar  7 22:07:15 localhost shepherd[1]: Service rpc.mountd has been started. 
Mar  7 22:07:15 localhost shepherd[1]: Service nfs has been started. 
Mar  7 22:07:15 localhost rpc.mountd[25270]: Version 2.4.2 starting
Mar  7 22:07:15 localhost shepherd[1]: Respawning rpc.mountd. 
Mar  7 22:07:15 localhost shepherd[1]: Service rpc.mountd has been started. 
Mar  7 22:07:15 localhost rpc.mountd[25272]: Version 2.4.2 starting
Mar  7 22:07:15 localhost shepherd[1]: Respawning rpc.mountd. 
Mar  7 22:07:15 localhost shepherd[1]: Service rpc.mountd has been started. 
Mar  7 22:07:15 localhost rpc.mountd[25274]: Version 2.4.2 starting
Mar  7 22:07:15 localhost shepherd[1]: Respawning rpc.mountd. 
Mar  7 22:07:15 localhost shepherd[1]: Service rpc.mountd has been started. 
Mar  7 22:07:15 localhost rpc.mountd[25276]: Version 2.4.2 starting
Mar  7 22:07:15 localhost shepherd[1]: Respawning rpc.mountd. 
Mar  7 22:07:15 localhost shepherd[1]: Service rpc.mountd has been started. 
Mar  7 22:07:15 localhost rpc.mountd[25278]: Version 2.4.2 starting
Mar  7 22:07:15 localhost shepherd[1]: Respawning rpc.mountd. 
Mar  7 22:07:15 localhost shepherd[1]: Service rpc.mountd has been started. 
Mar  7 22:07:15 localhost rpc.mountd[25280]: Version 2.4.2 starting
Mar  7 22:07:15 localhost shepherd[1]: Service rpc.mountd has been disabled. 
Mar  7 22:07:15 localhost shepherd[1]:   (Respawning too fast.)
--8<---------------cut here---------------end--------------->8---

>  Is rpc.statd running?

herd status rpc.statd
Status of rpc.statd:
  It is started.
  Running value is 348.
  It is enabled.
  Provides (rpc.statd).
  Requires (rpcbind-daemon).
  Conflicts with ().
  Will be respawned.

root@hurd ~# pidof rpc.statd
348

So, yes :-)

> Could it be that all these services need to depend on ‘loopback’?

I don't think so, because attempting to restart those services in a
state where the network is live and a loopback interface exists
(127.0.0.1 pings) doesn't change the outcome.  Or am I misunderstanding
something?

An interesting fact is that every time 'herd restart rpc.mountd' is run,
the number of running processes of rpc.mountd goes up:

--8<---------------cut here---------------start------------->8---
herd enable rpc.mountd && herd start rpc.mountd && pidof rpc.mountd | wc -w
Enabled service rpc.mountd.
Service rpc.mountd has been started.
6
root@hurd ~# herd enable rpc.mountd && herd start rpc.mountd && pidof rpc.mountd | wc -w
Enabled service rpc.mountd.
Service rpc.mountd has been started.
12
root@hurd ~# herd enable rpc.mountd && herd start rpc.mountd && pidof rpc.mountd | wc -w
Enabled service rpc.mountd.
Service rpc.mountd has been started.
13
root@hurd ~# herd enable rpc.mountd && herd start rpc.mountd && pidof rpc.mountd | wc -w
Enabled service rpc.mountd.
Service rpc.mountd has been started.
19
root@hurd ~# herd enable rpc.mountd && herd start rpc.mountd && pidof rpc.mountd | wc -w
Enabled service rpc.mountd.
Service rpc.mountd has been started.
20
root@hurd ~# herd enable rpc.mountd && herd start rpc.mountd && pidof rpc.mountd | wc -w
Enabled service rpc.mountd.
Service rpc.mountd has been started.
26
--8<---------------cut here---------------end--------------->8---

So, to me it seems to be a problem with Shepherd: it erroneously thinks
the process has died and restart it, while in reality it is still
running fine.

Running the rpc.mountd command manually doesn't exhibit any issue, as I
mentioned in my original report.

Thanks for the help!

Maxim

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

Hi again,

Another note: Even with 'herd status rpc.mountd' reporting that it is
stopped and disabled, and 'pidof rpc.mountd' showing 6 processes, the
NFS service manages to work, at least for the very limited testing I've
done.

So, at least, it should be usable even though the Shepherd handling of
rpc.mountd needs to be fixed.

Maxim

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

I think I've gathered a clue!

scheme@(guix-user)> ,m (shepherd service)
scheme@(shepherd service)> (system "pidof rpc.mountd")
413 408 406 404 399 389 387
$1 = 0
scheme@(shepherd service)> (system "killall rpc.mountd")
$2 = 0
scheme@(shepherd service)> (system "pidof rpc.mountd")
$3 = 256
[...]
scheme@(shepherd service)> (make-forkexec-constructor
  (list "/gnu/store/qyz1bncxlkxv44c03sva2akfsyqzkzh5-nfs-utils-2.4.2/sbin/rpc.mountd" "--debug" "all"))
$5 = #<procedure 7f67f82862a0 at shepherd/service.scm:930:8 args>
scheme@(shepherd service)> ($5)
$6 = 816
scheme@(shepherd service)> (system "pidof rpc.mountd")
warning: 'waitpid' -1 failed unexpectedly: No child processes
817
warning: 'waitpid' -1 failed unexpectedly: No child processes
$7 = 0

[...]

scheme@(shepherd service)> (system "pgrep rpc.mountd")
817
warning: 'waitpid' -1 failed unexpectedly: No child processes
$10 = 0
scheme@(shepherd service)>

That warning thrown by Guile/Shepherd is our clue.  To be continued :-).

Maxim

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

Sorry for the spam, but I also managed to get something slightly
different (doesn't seem to be reproducible easily though):

--8<---------------cut here---------------start------------->8---
scheme@(guix-user)> ,m (shepherd service)
scheme@(shepherd service)> (make-forkexec-constructor
  (list "/gnu/store/qyz1bncxlkxv44c03sva2akfsyqzkzh5-nfs-utils-2.4.2/sbin/rpc.mountd" "--debug" "all"))
$1 = #<procedure 7f5f7e17e600 at shepherd/service.scm:930:8 args>
scheme@(shepherd service)> ($1)
$2 = 920
scheme@(shepherd service)> error in finalization thread: Bad file descriptor

warning: 'waitpid' -1 failed unexpectedly: No child processes
--8<---------------cut here---------------end--------------->8---

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Ludovic Courtès]

Hi!

Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:

> I think I've gathered a clue!

[...]

> scheme@(shepherd service)> (make-forkexec-constructor
>   (list "/gnu/store/qyz1bncxlkxv44c03sva2akfsyqzkzh5-nfs-utils-2.4.2/sbin/rpc.mountd" "--debug" "all"))
> $5 = #<procedure 7f67f82862a0 at shepherd/service.scm:930:8 args>
> scheme@(shepherd service)> ($5)
> $6 = 816
> scheme@(shepherd service)> (system "pidof rpc.mountd")
> warning: 'waitpid' -1 failed unexpectedly: No child processes
> 817

So that means that rpc.mountd “daemonizes”.  Thus, shepherd shouldn’t
look at the PID of the process it spawns, but rather at what
rpc.mountd’s PID file contains (I assume it creates a PID file,
right?).  IOW, we need to pass #:pid-file to ‘make-forkexec-constructor’.

Does that work for you?

Thanks for debugging!

Ludo’.

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

Hello Ludovic!

Ludovic Courtès <ludo@gnu.org> writes:

> Hi!
>
> Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:
>
>> I think I've gathered a clue!
>
> [...]
>
>> scheme@(shepherd service)> (make-forkexec-constructor
>>   (list "/gnu/store/qyz1bncxlkxv44c03sva2akfsyqzkzh5-nfs-utils-2.4.2/sbin/rpc.mountd" "--debug" "all"))
>> $5 = #<procedure 7f67f82862a0 at shepherd/service.scm:930:8 args>
>> scheme@(shepherd service)> ($5)
>> $6 = 816
>> scheme@(shepherd service)> (system "pidof rpc.mountd")
>> warning: 'waitpid' -1 failed unexpectedly: No child processes
>> 817
>
> So that means that rpc.mountd “daemonizes”.  Thus, shepherd shouldn’t
> look at the PID of the process it spawns, but rather at what
> rpc.mountd’s PID file contains (I assume it creates a PID file,
> right?).  IOW, we need to pass #:pid-file to ‘make-forkexec-constructor’.

That process doesn't create a PID file, so that doesn't work.

> Does that work for you?
>
> Thanks for debugging!

Thanks for assisting, and for adding a note to the Shepherd manual! :-)

I'm closing this issue.

Maxim

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Ludovic Courtès]

Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:

>> So that means that rpc.mountd “daemonizes”.  Thus, shepherd shouldn’t
>> look at the PID of the process it spawns, but rather at what
>> rpc.mountd’s PID file contains (I assume it creates a PID file,
>> right?).  IOW, we need to pass #:pid-file to ‘make-forkexec-constructor’.
>
> That process doesn't create a PID file, so that doesn't work.

OK, so ‘--foreground’ was the right thing.  Thanks for explaining!

Ludo’.

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Ricardo Wurmus]

Ludovic Courtès <ludo@gnu.org> writes:

> Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:
>
>>> So that means that rpc.mountd “daemonizes”.  Thus, shepherd shouldn’t
>>> look at the PID of the process it spawns, but rather at what
>>> rpc.mountd’s PID file contains (I assume it creates a PID file,
>>> right?).  IOW, we need to pass #:pid-file to ‘make-forkexec-constructor’.
>>
>> That process doesn't create a PID file, so that doesn't work.
>
> OK, so ‘--foreground’ was the right thing.  Thanks for explaining!

Does this affect the system test at all?  When I added nfs-service-type
I also added a system test, which passed.  Did I miss something?

-- 
Ricardo

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

Hello Ricardo!

Ricardo Wurmus <rekado@elephly.net> writes:

> Ludovic Courtès <ludo@gnu.org> writes:
>
>> Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:
>>
>>>> So that means that rpc.mountd “daemonizes”.  Thus, shepherd shouldn’t
>>>> look at the PID of the process it spawns, but rather at what
>>>> rpc.mountd’s PID file contains (I assume it creates a PID file,
>>>> right?).  IOW, we need to pass #:pid-file to ‘make-forkexec-constructor’.
>>>
>>> That process doesn't create a PID file, so that doesn't work.
>>
>> OK, so ‘--foreground’ was the right thing.  Thanks for explaining!
>
> Does this affect the system test at all?  When I added nfs-service-type
> I also added a system test, which passed.  Did I miss something?

As I mentioned in an earlier message in this thread;

> Even with 'herd status rpc.mountd' reporting that it is stopped and
> disabled, and 'pidof rpc.mountd' showing 6 processes, the NFS service
> manages to work, at least for the very limited testing I've done.

So, the test validating that files written to the mounted NFS share
appear in the exported file system would pass, but if you view the
output of 'herd status nfs' on a system configured before the fix you'd
see rpc.mountd reported as stopped and disabled (with something like 6
processes running :-)).

Maxim

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Maxim Cournoyer]

[-- Attachment #1.1: Type: text/plain, Size: 991 bytes --]

Ludovic Courtès <ludo@gnu.org> writes:

> Hi,
>
> Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:
>
>> The rpc.mountd service, one of the required services for
>> nfs-service-type, respawns the process quickly until disabled.
>
> Does /var/log/messages contain hints?  Is rpc.statd running?
> Could it be that all these services need to depend on ‘loopback’?
>
> No answers, but a lot of questions.  :-)
>
> Ludo’.

OK, I've managed to find the problem.  rpc.mountd daemonizes itself upon
starting by default, which is not supported by Shepherd (at least not
its `make-forkexec-constructor' procedure).  I had to pass the
'--foreground' option to workaround this limitation (c.f.: commit
5fdc5b2d57d2e7ab04dbaf9c85e7f34eebe81495).

It'd be interesting to see what systemd does when a service is hinted as
forking in its configuration file.  We should also document that
limitation in the Shepherd info manual (see attached patch for
Shepherd).

Maxim

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1.2: 0001-doc-Note-that-make-forkexec-constructor-requires-a-n.patch --]
[-- Type: text/x-patch, Size: 1970 bytes --]

From 8f84ce9abe12b49340befbeee663896d226bb869 Mon Sep 17 00:00:00 2001
From: Maxim Cournoyer <maxim.cournoyer@gmail.com>
Date: Sun, 8 Mar 2020 00:34:36 -0500
Subject: [PATCH] doc: Note that make-forkexec-constructor requires a
 non-forking process.

This merits to be documented as it can be confusing, as demonstrated by
<https://bugs.gnu.org/39708>.
---
 doc/shepherd.texi | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/doc/shepherd.texi b/doc/shepherd.texi
index fbd1a3f..a0ac11b 100644
--- a/doc/shepherd.texi
+++ b/doc/shepherd.texi
@@ -898,12 +898,14 @@ execution of the @var{command} was successful, @code{#t} if not.
   [#:directory (default-service-directory)] @
   [#:environment-variables (default-environment-variables)]
 Return a procedure that forks a child process, closes all file
-descriptors except the standard output and standard error descriptors, sets
-the current directory to @var{directory}, changes the environment to
-@var{environment-variables} (using the @code{environ} procedure), sets the
-current user to @var{user} and the current group to @var{group} unless they
-are @code{#f}, and executes @var{command} (a list of strings.)  The result of
-the procedure will be the PID of the child process.
+descriptors except the standard output and standard error descriptors,
+sets the current directory to @var{directory}, changes the environment
+to @var{environment-variables} (using the @code{environ} procedure),
+sets the current user to @var{user} and the current group to @var{group}
+unless they are @code{#f}, and executes @var{command} (a list of
+strings.)  The result of the procedure will be the PID of the child
+process.  The child process must not fork (daemonize) itself for this to
+work correctly.
 
 When @var{pid-file} is true, it must be the name of a PID file
 associated with the process being launched; the return value is the PID
-- 
2.25.0


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

bug#39708: nfs-service-type broken: rpc.mountd respawns too quickly

[Ludovic Courtès]

Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:

> OK, I've managed to find the problem.  rpc.mountd daemonizes itself upon
> starting by default, which is not supported by Shepherd (at least not
> its `make-forkexec-constructor' procedure).  I had to pass the
> '--foreground' option to workaround this limitation (c.f.: commit
> 5fdc5b2d57d2e7ab04dbaf9c85e7f34eebe81495).

Great!  (I had replied earlier before seeing this message.)

> It'd be interesting to see what systemd does when a service is hinted as
> forking in its configuration file.  We should also document that
> limitation in the Shepherd info manual (see attached patch for
> Shepherd).

Good idea.  I pushed a slightly different version as Shepherd commit
3bc4a9c96c76abf78c76d71d42536e62ea173b21.

Thanks,
Ludo’.