respawn does not occur if permission denied

[Greg Smolyn]

Occasionally, if a file is getting overwritten during a respawn, upstart may fail to run the file. However, it will not continue to attempt respawns, it only tries one attempt.

The message seen in /var/log/messages is

Sep 12 14:39:59 my-vm kernel: [246447.263602] init: mydaemon main process ended, respawning
Sep 12 14:39:59 my-vm kernel: [246447.268044] init: Failed to spawn mydaemon main process: unable to execute: Permission denied

The scenario can be easily be reproduced by

1. start mydaemon
2. chmod a-x /usr/bin/mydaemon
3. kill `pidof mydaemon`
4. sleep some amount of time (5-8 seconds), long enough to get it to notice it needs to respawn
5. chmod a+x /usr/bin/mydaemon

I tried without a respawn limit, as well as with a respawn limit set to an enormous number of allowable respawns.

Expected behaviour would be that upstart would continue to retry.

NOTE:
The chmod example is a bit contrived, however seems to show the same symptoms. The actual problem is usually caused when a new file is being copied in place of the new one (through a CMake build 'make install'). (on our system the daemon notices that this update has occurred and exits, expecting to be restarted by upstart).

[Greg Smolyn (smolyn)]

I turned debug logging on, here's what I saw:

Sep 13 11:01:17 my-vm kernel: [260144.570480] init: mydaemon main process (31494) exited normally
Sep 13 11:01:17 my-vm kernel: [260144.570528] init: mydaemon main process ended, respawning
Sep 13 11:01:17 my-vm kernel: [260144.570678] init: mydaemon state changed from running to stopping
Sep 13 11:01:17 my-vm kernel: [260144.570816] init: Handling stopping event
Sep 13 11:01:17 my-vm kernel: [260144.570958] init: mydaemon state changed from stopping to killed
Sep 13 11:01:17 my-vm kernel: [260144.571013] init: mydaemon state changed from killed to post-stop
Sep 13 11:01:17 my-vm kernel: [260144.571067] init: mydaemon state changed from post-stop to starting
Sep 13 11:01:17 my-vm kernel: [260144.571158] init: Handling starting event
Sep 13 11:01:17 my-vm kernel: [260144.571264] init: mydaemon state changed from starting to pre-start
Sep 13 11:01:17 my-vm kernel: [260144.571318] init: mydaemon state changed from pre-start to spawned
Sep 13 11:01:17 my-vm kernel: [260144.575151] init: Failed to spawn mydaemon main process: unable to execute: Permission denied
Sep 13 11:01:17 my-vm kernel: [260144.576028] init: mydaemon goal changed from start to stop
Sep 13 11:01:17 my-vm kernel: [260144.576094] init: mydaemon state changed from spawned to stopping
Sep 13 11:01:17 my-vm kernel: [260144.576302] init: Handling stopping event
Sep 13 11:01:17 my-vm kernel: [260144.577383] init: mydaemon state changed from stopping to killed
Sep 13 11:01:17 my-vm kernel: [260144.578249] init: mydaemon state changed from killed to post-stop
Sep 13 11:01:17 my-vm kernel: [260144.578478] init: mydaemon state changed from post-stop to waiting
Sep 13 11:01:17 my-vm kernel: [260144.579067] init: Handling stopped event