Confusing mysqld startup failure with apparmor (Hardy)

[Emilis Dambauskas]

DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=8.04
DISTRIB_CODENAME=hardy
DISTRIB_DESCRIPTION="Ubuntu hardy (development branch)"

Binary package hint: mysql-common
Installed: 5.0.51a-3ubuntu1
Binary package hint: apparmor
Installed: 2.1+1075-0ubuntu5

Steps to reproduce:

- $ sudo cp -pr /var/lib/mysql /home/mysql
- change datadir value in /etc/mysql/my.cnf to /home/mysql
- $ sudo /etc/init.d/mysql restart

Result:

- * Starting MySQL database server mysqld [fail]
- Errors in /var/log/daemon.log. See [1].

What's wrong:

- There is no information for the user on why startup REALLY failed (apparmor prevented mysqld from writing to /home/mysql) -- nowhere in /var/log/ you'll find a line about apparmor.

- There is some output in /var/log/kern.log , but that doesn't say much (see [2]). All available information points to file permissions, but file permissions in fact are OK. So that is very confusing.

- The only hint I found related to apparmor when googling was in Bug #197476 which barely seems related by its title.

- The same problem can be reproduced in other ways:
$ mysqld --datadir=/home/mysql
and so on.

Suggested fixes:

- Include a "# WARNING: you may have to adjust apparmor settings in /etc/apparmor.d/usr.sbin.mysqld if you change default directory and file paths." in /etc/mysql/my.cnf .

- Provide logs for apparmor in /var/log that can be grep'ed for "mysqld" and would clearly indicate that this is an apparmor issue ("audit" is not specific enough). Maybe I should file another bug for that? Because that may affect other packages.

Logs:

[1] /var/log/daemon.log:

Mar 13 15:07:42 emilis-laptop mysqld_safe[26177]: started
Mar 13 15:07:42 emilis-laptop mysqld[26180]: 080313 15:07:42 [Warning] Can't create test file /home/mysql/emilis-laptop.lower-test
Mar 13 15:07:42 emilis-laptop mysqld[26180]: 080313 15:07:42 [Warning] Can't create test file /home/mysql/emilis-laptop.lower-test
Mar 13 15:07:42 emilis-laptop mysqld[26180]: 080313 15:07:42 InnoDB: Operating system error number 13 in a file operation.
Mar 13 15:07:42 emilis-laptop mysqld[26180]: InnoDB: The error means mysqld does not have the access rights to
Mar 13 15:07:42 emilis-laptop mysqld[26180]: InnoDB: the directory.
Mar 13 15:07:42 emilis-laptop mysqld[26180]: InnoDB: File name ./ibdata1
Mar 13 15:07:42 emilis-laptop mysqld[26180]: InnoDB: File operation call: 'open'.
Mar 13 15:07:42 emilis-laptop mysqld[26180]: InnoDB: Cannot continue operation.
Mar 13 15:07:42 emilis-laptop mysqld_safe[26188]: ended
Mar 13 15:07:56 emilis-laptop /etc/init.d/mysql[26347]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Mar 13 15:07:56 emilis-laptop /etc/init.d/mysql[26347]: ^G/usr/bin/mysqladmin: connect to server at 'localhost' failed
Mar 13 15:07:56 emilis-laptop /etc/init.d/mysql[26347]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
Mar 13 15:07:56 emilis-laptop /etc/init.d/mysql[26347]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!
Mar 13 15:07:56 emilis-laptop /etc/init.d/mysql[26347]:

[2] /var/log/kern.log:

Mar 13 15:07:42 emilis-laptop kernel: [16748.861107] audit(1205413662.100:3): operation="inode_create" request_mask="w::" denied_mask="w::" name="/home/mysql/emilis-laptop.lower-test" pid=26179 profile="/usr/sbin/mysqld" namespace="default"
Mar 13 15:07:42 emilis-laptop kernel: [16748.861333] audit(1205413662.104:4): operation="inode_create" request_mask="w::" denied_mask="w::" name="/home/mysql/emilis-laptop.lower-test" pid=26179 profile="/usr/sbin/mysqld" namespace="default"
Mar 13 15:07:42 emilis-laptop kernel: [16748.884899] audit(1205413662.124:5): operation="inode_permission" request_mask="rw::" denied_mask="rw::" name="/home/mysql/ibdata1" pid=26179 profile="/usr/sbin/mysqld" namespace="default"

[Jamie Strandboge (jdstrand)]

Thank you for using Ubuntu and taking the time to report a bug. It is planned to add extra information to both the profiles, the README.Debian and the configuration files for apparmor enforcing profiles. This should happen sometime after Beta is released.

[Launchpad Janitor (janitor)]

This bug was fixed in the package mysql-dfsg-5.0 - 5.0.51a-3ubuntu3

---------------
mysql-dfsg-5.0 (5.0.51a-3ubuntu3) hardy; urgency=low

  [ Nicolas Valcárcel ]
  * Confirming password on install if given (LP: #162167)

  [ Jamie Strandboge ]
  * follow ApparmorProfileMigration and force apparmor complain mode on some
    upgrades (LP: #203531)
    - debian/control: Recommends apparmor >= 2.1+1075-0ubuntu6
    - debian/mysql-server-5.0.dirs: add etc/apparmor.d/force-complain
    - debian/mysql-server-5.0.preinst: create symlink for force-complain/
      on pre-feisty upgrades, upgrades where apparmor-profiles profile is
      unchanged (ie non-enforcing) and upgrades where the profile doesn't
      exist
    - debian/mysql-server-5.0.postrm: remove symlink in force-complain/ on
      purge
  * debian/additions/my.cnf: add warning about apparmor (LP: #201799)

 -- Mathias Gug <email address hidden> Tue, 25 Mar 2008 17:05:22 -0400

[Emilis Dambauskas (emilis-d)]

Yay! Got the fix today :-)

[Rick Bahague Jr (rickjr)]

I installed mysql just a few minutes ago. This same bug still exists. How do we fix this?

Apr 26 10:00:00 laptap kernel: [ 6026.254152] audit(1209175200.933:26): type=1503 operation="inode_permission" requested_mask="rw::" denied_mask="rw::" name="/home/mysql/ibdata1" pid=15730 profile="/usr/sbin/mysqld" namespace="default"

daemon logs:

Apr 26 10:00:00 laptap mysqld[15731]: InnoDB: the directory.
Apr 26 10:00:00 laptap mysqld[15731]: InnoDB: File name ./ibdata1
Apr 26 10:00:00 laptap mysqld[15731]: InnoDB: File operation call: 'open'.
Apr 26 10:00:00 laptap mysqld[15731]: InnoDB: Cannot continue operation.
Apr 26 10:00:00 laptap mysqld_safe[15739]: ended
Apr 26 10:00:15 laptap /etc/init.d/mysql[15890]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Apr 26 10:00:15 laptap /etc/init.d/mysql[15890]: ^G/usr/bin/mysqladmin: connect to server at 'localhost' failed
Apr 26 10:00:15 laptap /etc/init.d/mysql[15890]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
Apr 26 10:00:15 laptap /etc/init.d/mysql[15890]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!
Apr 26 10:00:15 laptap /etc/init.d/mysql[15890]:

Packages installed:

un mysql-client <wala> (walang paglalarawan)
ii mysql-client-5.0 5.0.51a-3ubuntu5 MySQL database client binaries
ii mysql-common 5.0.51a-3ubuntu5 MySQL database common files
ii mysql-server 5.0.51a-3ubuntu5 MySQL database server (meta package depending on the latest version)
ii mysql-server-5.0 5.0.51a-3ubuntu5 MySQL database server binaries

[Rick Bahague Jr (rickjr)]

I disabled app armor and now it is working.

/etc/init.d/apparmor stop
update-rc.d -f apparmor remove

We should really fix this since many are using this application in Ubuntu.

[Lost In Tokyo (hkkf1970)]

Alternative solution:

1. Edit /etc/apparmor.d/usr.sbin.mysqld and add the following two lines:

    /home/mysql/ r,
    /home/mysql/** rwk,

    somewhere in the middle of the file. After the /var/lib/mysql lines would be fine.
2. /etc/init.d/apparmor restart
3. /etc/init.d/mysql restart

You retain the benefis of apparmor. Maybe the comments in /etc/mysql/my.cnf regarding apparmor can be expanded to cover exactly what you should do if you reset mysql_data.

[Kees Cook (kees)]

On Sat, Apr 26, 2008 at 02:37:54AM -0000, Rick Bahague Jr wrote:
> I disabled app armor and now it is working.
>
> /etc/init.d/apparmor stop
> update-rc.d -f apparmor remove
>
> We should really fix this since many are using this application in
> Ubuntu.

No. Do not do this. Please disable the _profile_ for mysqld
if it is causing problems:

  sudo apt-get install apparmor
  sudo touch /etc/apparmor.d/disable/usr.sbin.mysqld
  sudo /etc/init.d/apparmor start
  sudo /etc/init.d/mysqld restart

or, just flip the profile into complain mode:

  sudo aa-complain mysqld

better yet, fix the profile:

  sudo vi /etc/apparmor.d/*mysqld
  sudo /etc/init.d/mysqld restart

Do not remove the entire subsystem. :P

--
Kees Cook
Ubuntu Security Team

[Rick Bahague Jr (rickjr)]

Hi everyone,

Thanks for the very immediate response. I followed Lost and Tokyo and Kess Cook fix. MySQL is now working. Maybe there should be some messages on MySQL installation saying to do the above if users change the default data directory.

Thanks guys.

Rick

[toddq (toddq)]

followed the recommended steps and it didn't work when I type

sudo /etc/init.d/mysqld restart
sudo: /etc/init.d/mysqld: command not found

synpatic says I do have mysql-server-5.0 installed

[Cristóbal M. Palmer (cristobalpalmer)]

toddq: you need to use 'sudo /etc/init.d/mysql restart' (no 'd' on the end of mysql there).

Cheers,
CMP

[Rocko (rockorequin)]

There must be a regression in Jaunty using:

mysql-server 5.1.30really5.0.75-0ubuntu10
apparmor 2.3+1289-0ubuntu14

because I just got this bug on a freshly installed Jaunty beta (with updates to 12th April).

How do I nominate a new task for this?

[Aisthesis (aisthesis)]

Just had the same issue and followed the steps provided by Lost In Tokyo. This did not work for me. I then followed the steps by Kees Cook. Working fine with it disabled.

I spent at least 3 hours trying to figure out what the cause of the issue was. My logs are identical, except I am moving the data to another drive mounted on the system. This is on Jaunty.

In addition to apparmor disallowing mysql user to write to other directories, it also is preventing the memlock option from working which forces mysql to use additional system memory instead of the disk for buffers, etc, greatly increasing performance.

mysql-server: 5.1.30really5.0.75-0ubuntu10.2
apparmor: 2.3+1289-0ubuntu14

[Jamie Strandboge (jdstrand)]

Aisthesis, this bug is closed. Please open a new bug by following http://wiki.ubuntu.com/DebuggingApparmor. Thanks!