statd job starts before service is listening

I did the following to get more verbose logging:

--- etc/default/grub.20100728 2010-07-28 18:15:41.536842847 +1000
+++ etc/default/grub 2010-07-28 21:57:45.144891535 +1000
@@ -6,7 +6,7 @@
 GRUB_HIDDEN_TIMEOUT_QUIET=true
 GRUB_TIMEOUT=10
 GRUB_DISTRIBUTOR=`lsb_release -i -s 2> /dev/null || echo Debian`
-GRUB_CMDLINE_LINUX_DEFAULT="quiet splash"
+GRUB_CMDLINE_LINUX_DEFAULT="--verbose"
 GRUB_CMDLINE_LINUX=""

 # Uncomment to disable graphical terminal (grub-pc only)

... and ...

--- etc/init/mountall.conf.20100728 2010-04-26 15:46:36.000000000 +1000
+++ etc/init/mountall.conf 2010-07-28 21:58:14.917391034 +1000
@@ -28,7 +28,7 @@
     [ -f /forcefsck ] && force_fsck="--force-fsck"
     [ "$FSCKFIX" = "yes" ] && fsck_fix="--fsck-fix"

- exec mountall --daemon $force_fsck $fsck_fix
+ exec mountall --daemon --verbose $force_fsck $fsck_fix
 end script

 post-stop script

Theory A:
A "mounting TYPE=nfs" event while statd is stopped will cause statd to be started and mountall will block untill statd is running. However a "mounting TYPE=nfs" event while statd is in (say) pre-start or spawned state is ignored and does not block mountall. Therefore it is not guaranteed that statd is in running state when mountall calls mount.nfs.

Theory B:
statd is not really ready for business when upstart marks it as "runnning". It needs a post-start script that waits while it does initialization tasks such as registering with portmap.

I have not so far dug into the source sufficiently to prove or rule out either of these.

The log that I posted seems to support theory B but I have other examples that seem more consistent with theory A.

I scanned quickly through the source of relevant packages. The following lines caught my eye (upstart-0.6.5/init/job_process.c around line 1394):

        nih_info (_("%s %s process (%d) became new process (%d)"),
                  job_name (job), process_name (process),
                  job->pid[process], (pid_t)data);

        /* We no longer care about this process, it's the child that we're
         * interested in from now on, so detach it and allow it to go about
         * its business unhindered.
         */

The comment here is revealing. statd takes care not to let its parent process exit until the child is ready to service client requests. I think the sysvinit startup scripts depended on this. If upstart completely ignores the parent as soon as it has forked, this would introduce a race as per theory B above.

In the above output there are 5 examples where upstart has marked statd as running but the parent process still exists, which implies that statd is not ready to service client requests.

The above patch adds a post-start script that loops until the statd parent process has exited. This is the best workaround that I can think of. It doesn't seem possible to just wait() for the process with the current implementation of upstart's "expect fork" feature.

Suggestion for a better approach: The start script should be allowed to tell upstart the PID of the process that upstart should supervise. The information could be sent (for example) via a pipe, or the traditional /var/run/<job>.pid file. Then the knowledge of how to correctly start a particular daemon could be entirely in the start script where it belongs, rather than part of it being coded into upstart. This would allow the "expect fork" and "expect daemon" features to go away.

apport information

Tested on Maverick alpha 3 and confirmed that this bug is still present. Debdiff for Maverick attached.

I just noticed that the underlying upstart issue mentioned in #8 is already described by https://bugs.launchpad.net/upstart/+bug/530779. I won't mark this as a duplicate though - the workaround described here may be useful until the upstart bug is fixed.

Hi Andrew,

I notice there have been a number of changes since 1.2.0 which appear to improve behavior with upstart; would you mind confirming that the issue still exists with nfs-utils 1.2.4 (e.g. snag an oneiric livecd and reproduce there).

If the issue is still present, we should properly address it by fixing the statd startup code, not by adding a post-start script.