init: post-start can cause respawn to hang

I can confirm this behavior. To reproduce, I did:
 * launch ec2 instance (ami-fa01f193 us-east-1 ubuntu-lucid-10.04-amd64-server-20110201.1)
 * disable lucid-updates
 * sudo apt-get update && sudo apt-get install mysql-server-5.1
 * modify /etc/apparmor.d/usr.sbin.mysqld, adding hashes to the two lines below:
  # /var/lib/mysql/ r,
  # /var/lib/mysql/** rwk,
 * enable -updates
 * sudo apt-get update && sudo apt-get dist-upgrade
 * system hangs on:
   Setting up mysql-server-core-5.1 (5.1.41-3ubuntu12.9) ...
   Setting up mysql-server-5.1 (5.1.41-3ubuntu12.9) ...
   Installing new version of config file /etc/init/mysql.conf ...

These 4 processes are running:
 7476 pts/2 Ss+ 0:00 /usr/bin/dpkg --status-fd 14 --configure libmysqlclient16 mysql-client-core-5.1 mysql-client-5.1 mysql-server-core-5.1 mysql-server-5.1
 7486 pts/2 S+ 0:00 /usr/bin/perl -w /usr/share/debconf/frontend /var/lib/dpkg/info/mysql-server-5.1.postinst configure 5.1.41-3ubuntu12.7
 7496 pts/2 S+ 0:00 /bin/bash -e /var/lib/dpkg/info/mysql-server-5.1.postinst configure 5.1.41-3ubuntu12.7
 7703 pts/2 S+ 0:00 start mysql

because you commented out the lines in the config file, mysql cannot access /var/lib/mysql. I suspect you have app armour messages in your dmesg indicating this.

I'm not sure if I should call this bug invalid or confirmed.

I think there is a bug in upstart here, as start shouldn't hang forever. It should error out pretty early actually. This seems to be a problem with post-start and respawn handling.

I created this job to simulate what mysqld does in this case, which is, start, and fail, while the post-start script loops for 30 seconds pinging mysql before exitting with a return code of 1.

# test-pstart

respawn
script
  sleep 2
  exit 1
end script

post-start script
  sleep 30
  exit 1
end script

# EOF

start test-pstart will hang forever.

Adding

respawn limit 3 120

saying only respawn it 3 times in 120 seconds before giving up, produces an immediate failure...

start: Job failed to start

Removing the 'exit 1' of the post-start doesn't change this.. just having the post-start wait 30 seconds seems to produce the error, but only when a respawn limit of any kind is specified. I've even tried respawn limit 10000 10000 .. this still produces the error where bare 'respawn' does not.

If nothing else, this behavior is *confusing*, and a warning in the man page for upstart that respawn may cause your start commands to hang indefinitely without a limit is in order, which is why I've added upstart to this bug report.

For the mysql-5.1 package, we should add a respawn limit to work around the problem. Since this is changing a default behavior, we should be very conservative. Three times in 120 seconds seems that.. as that means in 2 minutes mysql exited with a non-zero exit code. If mysql fails more than that.. it may be necessary for an administrator to step in and fix data/problems.

Marking Triaged in mysql. Agree with the importance of Low, as this only affects people whose mysqld's are severely broken already.

In reading the upstart code, specifically in init/job_process.c in the job_process_terminated() function, I believe the problem is the
assumption that there is nothing we need to do when the post-start exits with a non-zero status. In fact, I think this should mark the
job as failed, *even* if there is a respawn stanza, as a post-start delays the 'started' event, and so the job is not yet in the status where the job writer has verified that it has reached a state of working.

Perhaps when post-start exits with non-zero, the job goal should be changed to stop?

In the mean time, as a workaround, if a post-start detects problems with the main process, it should most likely *stop* the job itself. In the case of mysql, this would simply mean running 'stop' if mysql fails to start within 30 seconds.

I spent some time on this today, and I think that upstart's handling of respawn + post-start is probably making jobs harder than they need to be.

In the mysql case, we need to exit the mysqladmin ping loop if the process goes into 'respawn', so that the process can in fact be respawned... otherwise it waits. This also causes the usual respawn limit to not be hit because we're respawning 1 time every 30 seconds. In fact, just the lag of forking and running mysqladmin ping is enough to prevent us from restarting 10 times in 5 seconds, which is the default limit.

So IMO, upstart should have a way to respawn independent of post-start. But that is a much bigger change and needs more thought. For jobs with a post-start, they need to make sure the post-start is reactive to the respawn status by exitting when it is detected, and considering this in any respawn limits.

So, I'll be uploading a fix to precise's mysql-5.5 package which will fail with 2 respawns in 5 seconds, and exits the mysqladmin loop if status is respawn. This causes the job to report a failure to start if things are truly broken, which is what we want. It will also cause respawn to give up faster if mysqld exits, but I think that is fine given that it is a large database daemon and probably isn't going to respond well to the rapid respawning.

One final thought, I'm raising the importance to High. Failing to detect and report a serious problem in this sort of daemon seems like an important problem!

This bug was fixed in the package mysql-5.5 - 5.5.22-0ubuntu1

---------------
mysql-5.5 (5.5.22-0ubuntu1) precise; urgency=low

  * New upstream release (LP: #965523)
  * d/mysql-server-5.5.mysql.upstart: Add respawn limit and code
    to exit ping loop if mysqld needs to be respawned. (LP: #711635)
  * New upstream bugfix release.
  * Refreshed patches
  * d/control: Build-Dep on dh-apparmor (LP: #948481)
  * d/p/fix-mysqldump-test.patch: Fixes unreliable test introduced in
    new upstream version. http://bugs.mysql.com/bug.php?id=64401
  * d/control: Re-add empty meta-package for mysql-testsuite so users
    will get the 5.5 version on upgrade and when installing
    mysql-testsuite. (LP: #959683)
 -- Clint Byrum <email address hidden> Thu, 29 Mar 2012 17:31:30 -0700

Status changed to 'Confirmed' because the bug affects multiple users.

I've rejected the lucid upload here; 5.1.62 has been uploaded by the security team to -proposed, so this will need to be rebased on that.

eol reached https://wiki.ubuntu.com/Releases

lucid has seen the end of its life and is no longer receiving any updates. Marking the lucid task for this ticket as "Won't Fix".

The Precise Pangolin has reached end of life, so this bug will not be fixed for that release