The Empty Error Log

Oct 18, 2011 / By Andrew Moore

Tags: ,

The MySQL errorlog is an important point of reference when administering a MySQL Server. We can grasp much about the state of our MySQL instance by the informational and error messages written out to it by our MySQL daemon. Our monitoring suite is set up to check the mysqld  error log file periodically for any new nasties logged and then it alerts  us if there’s anything to know about. Recently I was asked to investigate some replication outage alerts a colleague had received overnight. One  of the primary directions I took was the error log file. This is where I would expect find any evidence of replication being stopped or crashes etc – I was looking for anything that could fill me  in on the causes of replication alerts. When I ran the command to tail the log I was shocked to see the log was totally empty.Confused with what I didn’t see, I listed the file info and saw that the file was located in the root-user-owned-directory /var/log along with compressed (.gz) historic iterations of the error log. The mysql user owned the file itself so I didn’t expect it to be empty. There are some implications with this layout. Without inter-group participation  in place, having root as the owner of the directory and mysql the file owner, these permissions don’t work if I want the MySQL user to be able to create a new errorlog file upon rotation (FLUSH LOGS). This means there must be a privileged user creating the mysql errorlog file each time it’s rolled.

So to recap, I’ve got a file with the correct name (typos and case checked) that’s in the right location for all the errorlog-bound messages that mysqld wants to throw, but why is nothing in there? The server’s not generating any errors/informational messages? The file is writable by the mysql user, and I tested this. I switched user to ‘mysql’ and appended the file with a arbitrary string. No problems there then. Looking at the process revealed the various  options that mysqld had started with. I logged into mysql via the command line client and ran SHOW GLOBAL VARIABLES LIKE ‘log_error’ to  reveal the same path as described when checking the process. So why was  my file empty? I thought it was worth an attempt to recreate, so I  setup a local machine which meant I was free to run some scenarios which  I couldn’t do on a client’s production system.

Firstly  I caused some activity to make mysqld log to the error log. I achieved  this by enabling the innodb monitor. This is done by creating a table on  your server named innodb_monitor. This functionality causes the output  of `SHOW ENGINE INNODB STATUS` to be written out the error log. This  practice can be necessary if your `SHOW ENGINE INNODB STATUS` is too long and truncated before the end. Once this was enabled I could see  that there was output being written to my log file;

moore@ricky:/var/log/mysqld$ tail  /var/log/mysqld/mysqld.err

————–
ROW OPERATIONS
————–
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 6719, id 139758998271744, state: waiting for server activity
Number of rows inserted 8159766, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
—————————-
END OF INNODB MONITOR OUTPUT
============================

Next I renamed the active errorlog to see what would happen. The log_error option isn’t dynamic so I wouldn’t expect mysqld to try to write anywhere else. I ran the command;

`mv /var/log/mysqld/mysqld.err /var/log/mysqld.mysqld.err.

moved`and then waited for `SHOW ENGINE INNODB STATUS` output to be injected into the now missing file.Interestingly enough MySQL still logged new entries to the ‘old’ file. I say ‘old’  but it’s only cosmetically ‘old’ because I changed the name. I didn’t  inform MySQL that this is now an ‘old’ file and to forget about it. If  there was an errorlog errorlog… at this point I would expect an error to say mysqld couldn’t find the error file. That’s not what I see though;root@ricky:/var/log/mysqld# ls -la ./mysqld.err
-rw-r–r–  1 mysql mysql   7677 2011-09-21 21:23 mysqld.err
<p dir=”ltr”>***rename the file like a rotate would do***</p>root@ricky:/var/log/mysqld# mv ./mysqld.err /tmp/mysqld.err
<p dir=”ltr”>***send some errorlog activity***</p>

root@ricky:/var/log/mysqld# ls -la /tmp/mysqld.err*
-rw-r–r–  1 mysql mysql  11516 2011-09-21 21:23 mysqld.err

Looking  at the open files in the locations between moves I see that mysqld keeps hold of the file and this is why we’re still writing to the newly  named file even though it’s been moved to a new part of the system (or  at least pointing to a different part).

root@ricky:# lsof /tmp/*
COMMAND  PID    USER   FD   TYPE             DEVICE SIZE/OFF   NODE NAME
mysqld  6719   mysql    2w   REG                8,1   280245 531068 /tmp/mysql.err
mysqld  6719   mysql   37w   REG                8,1   280245 531068 /tmp/mysql.err

root@ricky:# stat /tmp/mysql.err
File: `/tmp/mysql.err’
Size: 295601          Blocks: 584        IO Block: 4096   regular file
Device: 801h/2049d      Inode: 531068      Links: 1
Access: (0644/-rw-r–r–)  Uid: ( 1001/   mysql)   Gid: ( 1001/   mysql)
Access: 2011-09-21 18:37:59.065468127 +0100
Modify: 2011-09-21 21:48:17.015466771 +0100
Change: 2011-09-21 21:48:17.015466771 +0100

root@ricky:# stat /home/moore/mysql.err
File: `/home/moore/mysql.err’
Size: 303279          Blocks: 600        IO Block: 4096   regular file
Device: 802h/2050d      Inode: 1835487     Links: 1
Access: (0644/-rw-r–r–)  Uid: ( 1001/   mysql)   Gid: ( 1001/   mysql)
Access: 2011-09-21 18:37:59.065468127 +0100
Modify: 2011-09-21 21:48:57.015466765 +0100
Change: 2011-09-21 21:48:57.705466765 +0100

So how to logically move onto the next file? FLUSH LOGS of course! When I  flushed the logs on my local server, I saw mysqld ‘let-go’ of the  current mysql errorlog and create a new one. Something that’s not too  hard to believe, hey? So next of all I needed to recreate the  permissions issue locally. I chown’d the directory;

root@ricky:/var/log/mysqld# chown root:root /var/log/mysqld/
root@ricky:/var/log/mysqld# ls -la
total 20
drwxr-xr-x  2 root  root   4096 2011-09-21 22:08 .
drwxr-xr-x 12 root  root   4096 2011-09-21 06:25 ..
-rw-rw—-  1 mysql mysql 11913 2011-09-21 22:08 mysqld.err

Now that I had my directories like the client’s and I ran some more simple tests. For the readers with the eagle eyes there is a highly important difference to why my client’s server isn’t writing to any of the error logs, old or new. To recreate the test in full truth, I compressed the current active mysql errorlog thus creating a file with a different format not just a different name. Common sense says that mysqld won’t be able to append to this binary file. Common sense prevails. I manually created a new file with the same name as my expected log file. I waited in anticipation for my new errorlog file to  grow with yet more `SHOW ENGINE INNODB STATUS` output. It didn’t.

You’ve probably already predicted the next move in this scenario… `FLUSH LOGS`, that’s right! The predicament here though is that the mysql user does not have write permissions on the directory so we can’t create the new file…ahh. So this is probably why I regularly see a mysqld directory under the /var/log directory; to enable granular permissions on creating and rotating log files.

In conclusion, what threw me most was this artificial placement of a file that posed as the ‘real’ error log. Now we know that the mysqld holds the errorlog file and as long as it’s accessible it will continue writing to it. Until it’s logically told to change by the flush logs command. When the old file is compressed during the rotate procedure we see what I’m calling a ‘dirty-detach’.  So there’s a few things to recommend after . The fallout of all this…a `trip around the houses` blog  post and a better vision of how mysqld rolls the mysql errorlog file.

Finally when you issue a `FLUSH LOGS` command, mysql closes and opens <strong>all</strong> log files, error, slow, general etc. In MySQL version 5.5+ we can be more specific with which logs we want to flush. Now I can issue a `FLUSH ERROR LOGS` or a `FLUSH BINARY LOGS` to avoid new iterations of log files applicable to my host.

Whilst researching the issue above I came across Ronald Bradfords note on the subject which describes the scenario but from the Slow Log’s perspective.

2 Responses to “The Empty Error Log”

  • Vincent Gu says:

    If you know inode, you know everything.

    MySQL grab the inode of error log, except something big changed this inode(like file was moved to another partition, or deleted), everything will works fine, move to another directory of the same partition is not a big deal. FLUSH LOGS let MySQL drop that inode and grab a new one.

  • Shantanu Oak says:

    Was the error log file name and location declared in the my.cnf ? I guess this will happen if you let mysql decide the way to handle the error log file.

Leave a Reply

  • (will not be published)

XHTML: You can use these tags: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>