mysql upstart job hangs if database directory not mounted

[Jo Liss]

[I think this might be a bug. Copied from http://serverfault.com/questions/291003/mysql-upstart-job-hangs-if-database-directory-not-mounted ]

I have mysqld pointed to an external volume:

    $ cat /etc/mysql/conf.d/data_joliss.cnf
    [mysqld]
    datadir=/mnt/data_joliss/mysql

This is working fine in general. But sometimes the volume is not mounted, for whatever reason. In those cases, mysqld fails like it should:

    # mysqld
    110716 14:17:42 [Warning] Can't create test file /mnt/data_joliss/mysql/opinionated-programmer.lower-test
    110716 14:17:42 [Warning] Can't create test file /mnt/data_joliss/mysql/opinionated-programmer.lower-test
    mysqld: Can't change dir to '/mnt/data_joliss/mysql/' (Errcode: 2)
    110716 14:17:42 [ERROR] Aborting

    110716 14:17:42 [Note] mysqld: Shutdown complete

However, the upstart job on Ubuntu 11.04 (`start mysql` or `service start mysql`) simply waits (hangs) indefinitely without outputting anything. The strace isn't telling me anything, but if anybody cares to take a look:
strace -fv start mysql => https://gist.github.com/1086397

I would like the `mysql` upstart job to just report an error and terminate rather than hanging. How do I do this?

(Background: I have an EC2 instance with an extra EBS volume to store permanent data. If the EBS volume is not available at boot time, the system hangs waiting for mysql, and I cannot even SSH into it to fix the problem -- so now my instance has become completely unusable. I would like it to just continue booting, even without a MySQL server.)

----------------

Ubuntu 11.04 on EC2, ami-06ad526f

mysql-server-core-5.1:
  Installed: 5.1.54-1ubuntu4
  Candidate: 5.1.54-1ubuntu4
  Version table:
 *** 5.1.54-1ubuntu4 0
        500 http://us-east-1.ec2.archive.ubuntu.com/ubuntu/ natty/main i386 Packages
        100 /var/lib/dpkg/status

ProblemType: Bug
DistroRelease: Ubuntu 11.04
Package: upstart 0.9.7-1
ProcVersionSignature: Ubuntu 2.6.38-8.42-virtual 2.6.38.2
Uname: Linux 2.6.38-8-virtual i686
Architecture: i386
Date: Mon Jul 18 17:13:55 2011
Ec2AMI: ami-06ad526f
Ec2AMIManifest: (unknown)
Ec2AvailabilityZone: us-east-1a
Ec2InstanceType: t1.micro
Ec2Kernel: aki-407d9529
Ec2Ramdisk: unavailable
ExecutablePath: /sbin/initctl
ProcEnviron:
 SHELL=/bin/bash
 PATH=(custom, user)
 LC_COLLATE=POSIX
 LANG=en_US.UTF-8
 LC_TIME=POSIX
SourcePackage: upstart
UpgradeStatus: No upgrade log present (probably fresh install)

[Clint Byrum (clint-fewbar)]

Can you include your fstab?

It doesn't make much sense that the entire system would block on this, since mysql doesn't really start on any blocking events.

[Jo Liss (joliss42)]

Sure.

$ cat /etc/fstab
LABEL=cloudimg-rootfs / ext4 defaults 0 0
LABEL=data_joliss /mnt/data_joliss auto noatime,errors=remount-ro 0 2
/var/swapfile none swap defaults 0 0

Still happens on Oneiric with mysql-server 5.1.58-1ubuntu1.

[Jo Liss (joliss42)]

Mounted as

/dev/xvdf on /mnt/data_joliss type ext3 (rw,noatime,errors=remount-ro)

[Clint Byrum (clint-fewbar)]

Hi Jo!

Its possible that the upstart job is respawning over and over rather than just failing, which it should. I think it might be helpful if you could provide us with /var/log/syslog during the time where you seee lines this hang. Usually the job will execute, and the run the post-start which will wait 30 seconds for mysql to be started, and then fail.

Can you please give us the lines from /var/log/syslog during the time where you were seeing the hang?

Thanks!

[Clint Byrum (clint-fewbar)]

In reading the upstart code, this is definitely a duplicate of bug #711635 .. respawn and post-start don't work together well. Marking as duplicate.

[Jo Liss (joliss42)]

On Sun, Feb 19, 2012 at 01:03, Clint Byrum <email address hidden> wrote:
> Its possible that the upstart job is respawning over and over rather
> than just failing, which it should. I think it might be helpful if you
> could provide us with /var/log/syslog during the time where you seee
> lines  this hang. Usually the job will execute, and the run the post-
> start which will wait 30 seconds for mysql to be started, and then fail.

Just wanted to quickly confirm that that's in fact the case (don't
know why I didn't notice earlier).

Feb 19 23:29:58 ip-10-204-242-176 kernel: [6052896.375740] type=1400
audit(1329694198.815:32): apparmor="STATUS"
operation="profile_replace" name="/usr/sbin/mysqld" pid=25129
comm="apparmor_parser"
Feb 19 23:29:58 ip-10-204-242-176 kernel: [6052896.514222] init: mysql
main process (25133) terminated with status 1
Feb 19 23:29:58 ip-10-204-242-176 kernel: [6052896.514275] init: mysql
main process ended, respawning
Feb 19 23:30:29 ip-10-204-242-176 kernel: [6052926.587238] init: mysql
post-start process (25134) terminated with status 1
Feb 19 23:30:29 ip-10-204-242-176 kernel: [6052926.599364] type=1400
audit(1329694229.040:33): apparmor="STATUS"
operation="profile_replace" name="/usr/sbin/mysqld" pid=25318
comm="apparmor_parser"
Feb 19 23:30:29 ip-10-204-242-176 kernel: [6052926.626133] init: mysql
main process (25322) terminated with status 1
Feb 19 23:30:29 ip-10-204-242-176 kernel: [6052926.626184] init: mysql
main process ended, respawning
Feb 19 23:30:59 ip-10-204-242-176 kernel: [6052956.768819] init: mysql
post-start process (25323) terminated with status 1
Feb 19 23:30:59 ip-10-204-242-176 kernel: [6052956.776625] type=1400
audit(1329694259.221:34): apparmor="STATUS"
operation="profile_replace" name="/usr/sbin/mysqld" pid=25410
comm="apparmor_parser"
Feb 19 23:30:59 ip-10-204-242-176 kernel: [6052956.802865] init: mysql
main process (25414) terminated with status 1
Feb 19 23:30:59 ip-10-204-242-176 kernel: [6052956.802914] init: mysql
main process ended, respawning
Feb 19 23:31:29 ip-10-204-242-176 kernel: [6052986.950767] init: mysql
post-start process (25415) terminated with status 1
Feb 19 23:31:29 ip-10-204-242-176 kernel: [6052986.962872] type=1400
audit(1329694289.406:35): apparmor="STATUS"
operation="profile_replace" name="/usr/sbin/mysqld" pid=25480
comm="apparmor_parser"
Feb 19 23:31:29 ip-10-204-242-176 kernel: [6052986.988213] init: mysql
main process (25484) terminated with status 1
Feb 19 23:31:29 ip-10-204-242-176 kernel: [6052986.988263] init: mysql
main process ended, respawning
Feb 19 23:31:59 ip-10-204-242-176 kernel: [6053017.133727] init: mysql
post-start process (25485) terminated with status 1
Feb 19 23:31:59 ip-10-204-242-176 kernel: [6053017.141439] type=1400
audit(1329694319.583:36): apparmor="STATUS"
operation="profile_replace" name="/usr/sbin/mysqld" pid=25559
comm="apparmor_parser"
Feb 19 23:31:59 ip-10-204-242-176 kernel: [6053017.167105] init: mysql
main process (25563) terminated with status 1
Feb 19 23:31:59 ip-10-204-242-176 kernel: [6053017.167152] init: mysql
main process ended, respawning
etc.

Thanks for following up!

Jo