Comment 0 for bug 1799763

This morning I noticed that MySQL had stopped, when I looked in journalctl this is what I saw:

Oct 24 06:55:14 cantor systemd[1]: Starting Daily apt upgrade and clean activities...
Oct 24 06:55:29 cantor systemd[1]: Reloading.
Oct 24 06:55:29 cantor systemd[1]: Starting Daily apt download activities...
Oct 24 06:55:29 cantor systemd[1]: Stopping MySQL Community Server...
Oct 24 06:55:29 cantor mysqld[1001]: 2018-10-24T06:55:29.818224Z 0 [Note] Giving 10 client threads a chance to die gracefully
Oct 24 06:55:29 cantor mysqld[1001]: 2018-10-24T06:55:29.818330Z 0 [Note] Shutting down slave threads
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.818809Z 0 [Note] Forcefully disconnecting 10 remaining clients
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819027Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 1429 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819058Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 14 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819075Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 12 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819091Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 13 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819105Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 10 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819121Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 11 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819141Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 8 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819161Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 9 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819180Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 7 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.819200Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 5 user: 'kopano'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.820350Z 0 [Note] Event Scheduler: Purging the queue. 0 events
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.831822Z 0 [Note] Binlog end
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.913078Z 0 [Note] Shutting down plugin 'ngram'

(... other plugins ...)

Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.914610Z 0 [Note] Shutting down plugin 'InnoDB'
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.916864Z 0 [Note] InnoDB: FTS optimize thread exiting.
Oct 24 06:55:31 cantor mysqld[1001]: 2018-10-24T06:55:31.917188Z 0 [Note] InnoDB: Starting shutdown...
Oct 24 06:55:32 cantor mysqld[1001]: 2018-10-24T06:55:32.018123Z 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
Oct 24 06:55:32 cantor mysqld[1001]: 2018-10-24T06:55:32.019085Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 181024 6:55:32
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.655024Z 0 [Note] InnoDB: Shutdown completed; log sequence number 48965157320
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.655315Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.655324Z 0 [Note] Shutting down plugin 'MEMORY'
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.655329Z 0 [Note] Shutting down plugin 'CSV'
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.655335Z 0 [Note] Shutting down plugin 'sha256_password'
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.655337Z 0 [Note] Shutting down plugin 'mysql_native_password'
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.655462Z 0 [Note] Shutting down plugin 'binlog'
Oct 24 06:55:33 cantor mysqld[1001]: 2018-10-24T06:55:33.657476Z 0 [Note] /usr/sbin/mysqld: Shutdown complete
Oct 24 06:55:33 cantor systemd[1]: Stopped MySQL Community Server.
Oct 24 06:55:33 cantor systemd[1]: Reloading.
Oct 24 06:55:34 cantor systemd[1]: Reloading.
Oct 24 06:55:36 cantor systemd[1]: Reloading.
Oct 24 06:55:37 cantor systemd[1]: Reloading.
Oct 24 06:55:39 cantor systemd[1]: Started Daily apt upgrade and clean activities.
Oct 24 06:55:40 cantor systemd[1]: Started Daily apt download activities.

So it appears that MySQL just got shutdown for no reason. I could find no errors in journalctl that I could find (I checked journalctl -u mysql and journalctl -u apt-daily).

I started the service again and everything was fine.

I also checked /var/log/apt/history.log and saw the changes:

Start-Date: 2018-10-24 06:55:29
Commandline: /usr/bin/unattended-upgrade
Upgrade: mysql-server-5.7:amd64 (5.7.23-0ubuntu0.18.04.1, 5.7.24-0ubuntu0.18.04.1), mysql-server-core-5.7:amd64 (5.7.23-0ubuntu0.18.04.1, 5.7.24-0ubuntu0.18.04.1)
End-Date: 2018-10-24 06:55:37

When I logged into MySQL it was indeed 5.7.24, so the package upgrade completed fine.

I wasn't able to find anything online but with the help of rbasak on freenode / #ubuntu-server, I eventually just tried to `apt-get install --reinstall mysql-server-5.7`, this completed but then warns that:
"Automatic maintenance of MySQL server daemon disabled. Packaging maintainer scripts detected a case that it does not know how to handle and cannot continue configuring MySQL. Automatic management of your MySQL installation has been disabled to allow other packaging tasks to complete, For more details, see /etc/mysql/FROZEN".

It was not clear at all what the issue was because MySQL has been running fine for months. Now I initially tried setting up MariaDB many months ago, and then gave up because I encountered a minor issue I didn't want to deal with. At the time I was using ansible where common practice is to manually stop, install, then manually start the package. My guess is that when it was frozen in ansible mode, it completely successfully. The service then started and then I never noticed. Also when I switched between MariaDB -> MySQL I remember it being an annoying hell for an hour trying to clean it up.

I'm fairly confident that I rebuilt the /var/lib/mysql folder, but I did not clean up /etc/mysql/ and it appears that the FROZEN file is just "latched" it stays there until it is fixed. However the only thing this FROZEN file does is seemingly prevent apt from starting the service after updates.

Right now the behaviour is the following:

1) Shutdown the service
2) Install the upgrade
3) Don't start it.

I understand that there are probably many constraints with this, and many trade offs however I think this is suboptimal.

I think at the very least:

1) If there is a problem, journalctl should have had something stating this.

And that some subset of the following should be done:

2) You probably shouldn't let the service be started manually (or even on reboot) if it is FROZEN. If a security update did this in an unattended way and it is such a risk _why_ let me start the service and not disable it.
3) You probably shouldn't even let the package be updated.
4) If you stop the service, and can't process it, you should restart with the old version (or just fail and not touch it, (i.e., have failure atomicity)).

I'm not sure, but I did find a post on stack overflow and the best answer (I am going to submit an update), is to simply turn of automatic updates (https://askubuntu.com/questions/1037285/starting-daily-apt-upgrade-and-clean-activities-stopping-mysql-service). Also it doesn't matter to me in particular, but I'm surprised that an unattended upgrade just kills mysql on the server version.