5.1.20 Gotcha – The MySQL Error Log

While using the latest MySQL 5.1.20 yesterday I came across another situation that was not expected as with previous editions of MySQL. The background is experimenting with DRBD. When I configured MySQL to startup with a /etc/my.cnf file with data on a DRBD partition I got a failed startup error message with mysqld_safe.

$ bin/mysqld_safe &
[1] 12615
070720 10:10:42 mysqld_safe Starting mysqld daemon with databases from /drbd/data
070720 10:10:42 mysqld_safe mysqld from pid file /drbd/data/newyork.localdomain.pid ended

Ok. Well this happens so I went to the data directory to look for `hostname`.err.

$ cd /drbd/data
$ ls -l

What the! There is no error log. Then the discussion started about this. Apparently mysqld_safe now uses syslog (e.g. /var/log/messages) for logging messages. Ok, but where is the line between mysqld_safe and mysqld. There was some confusion here about this, however investigation of /var/log/messages showed what was necessary to at least find the error.

$ tail -30 /var/log/messages
Jul 19 16:59:51 newyork mysqld_safe[6156]: Starting mysqld daemon with databases from /drbd/data
Jul 19 16:59:54 newyork mysqld[6160]: /usr/local/mysql/bin/mysqld: Can't find file: './mysql/plugin.frm' (errno: 13)
Jul 19 16:59:54 newyork mysqld[6160]: [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: The first specified data file ./ibdata1 did not exist:
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: a new database to be created!
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Setting file ./ibdata1 size to 10 MB
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Database physically writes the file full: wait...
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Log file ./ib_logfile0 did not exist: new to be created
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Setting log file ./ib_logfile0 size to 5 MB
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Database physically writes the file full: wait...
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Log file ./ib_logfile1 did not exist: new to be created
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Setting log file ./ib_logfile1 size to 5 MB
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Database physically writes the file full: wait...
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Doublewrite buffer not found: creating new
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Doublewrite buffer created
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Creating foreign key constraint system tables
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Foreign key constraint system tables created
Jul 19 16:59:54 newyork mysqld[6160]: InnoDB: Started; log sequence number 0 0
Jul 19 16:59:54 newyork mysqld[6160]: [ERROR] /usr/local/mysql/bin/mysqld: Can't find file: './mysql/host.frm' (errno: 13)
Jul 19 16:59:54 newyork mysqld[6160]: [ERROR] Fatal error: Can't open and lock privilege tables: Can't find file: './mysql/host.frm' (errno: 13)

To ensure backward compatibility now with previous versions of MySQL, it is necessary to specific in my.cnf the log-error parameter.

#my.cnf
[mysqld]
log-error = /drbd/data/mysql.err

Starting gives you expected error logging.

$ more /drbd/data/mysql.err
070720 10:16:30 mysqld_safe Starting mysqld daemon with databases from /drbd/data
/usr/local/mysql/bin/mysqld: Can't find file: './mysql/plugin.frm' (errno: 13)
070720 10:16:30 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
070720 10:16:30  InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.
InnoDB: File name ./ibdata1
InnoDB: File operation call: 'open'.
InnoDB: Cannot continue operation.
070720 10:16:30 mysqld_safe mysqld from pid file /drbd/data/newyork.localdomain.pid ended

So, you need to read the fine print in the Changes in release 5.1.20 (25 June 2007) 5.1 Manual you get.


Incompatible change: mysqld_safe now supports error logging to syslog on systems that support the logger command. The new –syslog and –skip-syslog options can be used in conjunction with the –log-error option to control logging behavior, as described in Section 5.3.1, “mysqld_safe — MySQL Server Startup Script”. The default is to use syslog, which differs from the previous default behavior of writing an error log file. To maintain the older behavior, use the –log-error option. (Bug#4858)

If you read mysqld_safe — MySQL Server Startup Script you also see the following note.


Note

As of MySQL 5.1.20, the default error logging behavior is to write errors to syslog on systems that support the logger program. This differs from the default behavior of writing an error log file for versions prior to 5.1.20. To maintain the older behavior, use the –log-error option.

RTFM those release notes!

Comments

  1. j says

    were you able to start mysqld_safe. I can’t seem to get to work. I always getting the following like you:

    $ bin/mysqld_safe &
    [1] 12615
    070720 10:10:42 mysqld_safe Starting mysqld daemon with databases from /home/mysql/data
    070720 10:10:42 mysqld_safe mysqld from pid file /home/mysql/data/mysqld.pid ended