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;
[email protected]:/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.
-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>[email protected]:/var/log/mysqld# mv ./mysqld.err /tmp/mysqld.err
<p dir=”ltr”>***send some errorlog activity***</p>[email protected]:/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).
[email protected]:# 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
[email protected]:# 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
[email protected]:# 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;
[email protected]:/var/log/mysqld# chown root:root /var/log/mysqld/
[email protected]:/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 Bradford’s note on the subject which describes the scenario but from the Slow Log’s perspective.
2 Comments. Leave new
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.
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.