/usr/libexec/mysqld: Normal shutdown, but my team doesn't do that?

Question

One of my databases has been shutting down abnormally, but the log said "normal":

130422 13:23:01 [Note] /usr/libexec/mysqld: Normal shutdown

130422 13:23:01 [Note] Event Scheduler: Killing the scheduler thread, thread id 379021
130422 13:23:01 [Note] Event Scheduler: Waiting for the scheduler thread to reply
130422 13:23:01 [Note] Event Scheduler: Stopped
130422 13:23:01 [Note] Event Scheduler: Purging the queue. 41 events
130422 13:23:01 [Note] Error reading relay log event: slave SQL thread was killed
130422 13:23:01 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
130422 13:23:01 [Note] Slave I/O thread killed while reading event
130422 13:23:01 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.002426', position 107
...
130422 13:23:04  InnoDB: Starting shutdown...
130422 13:23:04  InnoDB: Waiting for 201 pages to be flushed
130422 13:23:08  InnoDB: Shutdown completed; log sequence number 6942784551767
130422 13:23:08 [Note] /usr/libexec/mysqld: Shutdown complete

There is no related error or stack trace in the mysqld.log, just some errors:

No data - zero rows fetched, selected, or processed

from Event Scheduler.

I'm pretty sure my team doesn't stop it (via init script or mysqladmin shutdown, ...). grep through the last binlog file, I didn't see any SHUTDOWN statement.

Is there any other causes? Let me know if you need more information.

PS: mysql Ver 14.14 Distrib 5.5.28, for Linux (x86_64) using readline 5.1

---

UPDATE at Mon Apr 22 18:23:33 ICT 2013

Searching through the source code, I found this:

$ grep -lir 'normal shutdown' mysql-5.5.28
mysql-5.5.28/scripts/mysqld_safe.sh
mysql-5.5.28/Docs/mysql.info
mysql-5.5.28/sql/share/errmsg-utf8.txt

$ grep -lr 'ER_NORMAL_SHUTDOWN' mysql-5.5.28
mysql-5.5.28/Docs/mysql.info
mysql-5.5.28/sql/mysqld.cc
mysql-5.5.28/sql/share/errmsg-utf8.txt

mysql-5.5.28/sql/mysqld.cc

  if (sig != 0) // 0 is not a valid signal number
    my_sigset(sig, SIG_IGN);                    /* purify inspected */
  if (sig == MYSQL_KILL_SIGNAL || sig == 0)
    sql_print_information(ER_DEFAULT(ER_NORMAL_SHUTDOWN),my_progname);
  else
    sql_print_error(ER_DEFAULT(ER_GOT_SIGNAL),my_progname,sig); /* purecov: inspected */

Looks like that there is no other reason for this message can be logged into the log file. One possibility I'm thinking is someone (who has SUPER privilege) turned off the binary log then run SHUTDOWN and close the db connection.

PS: In this bug report, there is one person also got this problem on 5.5.24.

Answer 1

Linux's Viewpoint

You should run this Linux command

history | grep mysqladmin

This will let you see if anyone ran a shutdown from within the server. Note that this will not let you see remote mysqladmin shutdowns. Perhaps running tcpdump and locating the word mysqladmin or shutdown might help.

MySQL's Viewpoint

Shutdown commands do not exist from command line utilities. Therefore, binary logs will not have shutdowns recorded. You are on the right track when you said;

One possibility I'm thinking is someone (who has SUPER privilege) turned off the binary log then run SHUTDOWN and turned it on again.

Look over the users with that privilege. Run this query:

SELECT user,host FROM mysql.user WHERE shutdown_priv='Y';

You may see something like this:

mysql> select user,host from mysql.user where shutdown_priv='Y';
+-------+--------------+
| user  | host         |
+-------+--------------+
| root  | localhost    |
| root  | 127.0.0.1    |
| root  | ::1          |
| root  | 10.240.163.% |
| root  | 10.48.19.%   |
| user1 | %            |
+-------+--------------+
6 rows in set (0.00 sec)

mysql>

You will see all the users that have shutdown privilege. SUPER privilege does not have the shutdown privilege. There is a separate privilege called SHUTDOWN.

You can quickly revoke that privilege. For example, note the user user1@'%'. It has remote shutdown privileges. You can yank it with

REVOKE SHUTDOWN ON *.* FROM user1.'%';

or

UPDATE mysql.user SET shutdown_priv='N'
WHERE user='user1' AND host='%';
FLUSH PRIVILEGES;

That takes care of the remote shutdown privileges.

You should also address securing user connections by removing SHUTDOWN privilege from every user that does not need to have it. Perhaps you can do this:

UPDATE mysql.user SET shutdown_priv='N'
WHERE CONCAT(user,'@',host) NOT IN
('root@localhost','[email protected]');
FLUSH PRIVILEGES;

That way, only root@localhost and [email protected] can do mysqladmin shutdown within the localhost. I would definitely have the [email protected] on hand because there are times when mysqld loses connection to the mysql.sock file and prevents root@localhost from connecting to issue a shutdown. With the [email protected], you can issue this:

mysqladmin -uroot -p -h127.0.0.1 --protocol=tcp

to issue a mysqladmin shutdown without needed the socket file.

Give it a Try !!!

Answer 2

I ran into this problem on a managed system. Took me a while to spot the very obvious cause, which is that the system as a whole had gone down for scheduled maintenance -- I guess because an updated kernel package was available.

So obvious!

The fix was of course to change the system configuration so that MySQL was automatically started when the system comes up. This was on CentOS, so the fix was:

$ sudo /sbin/chkconfig --level 3 mysqld on

Answer 3

Just to add one more possible reason: in my case it was the unattended-upgrades (on Ubuntu) who did the restart of mysql.

Answer 4

This can happen if you are running out of memory (like we just experienced). Linux's Out Of Memory Manager will attempt to kill processes with the lowest Out of Memory (OOM) score.

Check your logs for something like message around that timestamp in your mysql log:

Out of memory: Kill process 16503 (mysqld) score 156 or sacrifice child

With:

grep --ignore-case mysql /var/log/syslog (Debian/Ubuntu)

grep --ignore-case mysql /var/log/messages (CentOS/Fedora/RHEL)

Answer 5

I had same problem and I know that reason. (Ubunut 18.04) See syslog.

May 20 06:27:28 saw-ac-1 systemd[1]: Starting Daily apt upgrade and clean activities...
May 20 06:27:39 saw-ac-1 systemd[1]: Stopping MariaDB 10.1.47 database server...  <===========================
May 20 06:27:42 saw-ac-1 kernel: [20186037.318096] traps: GUI_OAMP[23214] general protection ip:7f8a850989fd sp:7ffe4d677630 error:0 in libc-2.27.so[7f8a85001000+1e7000]
May 20 06:27:42 saw-ac-1 systemd[1]: Stopped MariaDB 10.1.47 database server.
May 20 06:27:45 saw-ac-1 systemd[1]: Reloading.
May 20 06:27:50 saw-ac-1 systemd[1]: Reloading.
May 20 06:27:54 saw-ac-1 systemd[1]: Started Daily apt upgrade and clean activities.