FROZEN MySQL-Server runs, does everything fine, except security updates don't start the service after install.

Bug #1799763 reported by Steve Ramage on 2018-10-24
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
mysql-5.7 (Ubuntu)
High
Karl Stenerud

Bug Description

[Impact]

MySql and MariaDB share the same data directory, and thus cannot both be installed at the same time. Uninstalling MariaDB and installing MySQL causes the system to enter an inconsistent state, where the install script determines that it shouldn't run, but systemd allows it to run.

As well, once a security update occurs, the installer will shut it down, detect that mysql shouldn't be running, and then fail to start it again. If the user has managed to get a legitimate mysql running in the meantime, it will stop and not restart.

[Test Case]

# lxc launch ubuntu:cosmic tester
# lxc exec tester bash
# apt update
# apt dist-upgrade -y
# apt install -y mysql-server
# apt remove -y mysql-server
# apt install -y mariadb-server
# apt remove -y mariadb-server
# apt install -y mysql-server

Pop up window:
 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.

Console:

 Packaging maintenance of MySQL will stop and the daemon disabled to prevent damage to your system.
 For help, see /etc/mysql/FROZEN

# journalctl -xe
(nothing in the journal)
#service mysql start
(starts successfully when it should error out)

[Regression Potential]

This is a stopgap measure to prevent further damage before the data directories of mysql and mariadb are split in a future release. There are probably still edge cases that aren't handled properly due to the complexity of determining what happened in between an uninstall of mariadb and an install of mysql, and afterwards. Systems that currently work "fine" will fail to start if a previous downgrade had failed, even if the user got it running again. If /etc/mysql/FROZEN still exists, attempting to start the mysql service will error out with a log message to syslog explaining why, and how to fix it.

[Original Description]

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.

Also maybe:

2) Changed the text of /etc/mysql/FROZEN a bit, to mention the "latching" behaviour, the file staying there. The line that says:

"In this particular case, an incompatible downgrade attempt has been
detected. This can be resolved in one of two ways:"

It was previously detected months ago, but that makes it seem like it was present tense. In truth just to get MySQL to work I had to resolve this issue months ago but never saw this file, which made it confusing (and even confusing to the maintainer on IRC), that this file was there when the heuristic it was checking /var/lib/mysql/*.flag file didn't exist.

And maybe some subset of the following should be done:

3) 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.

4) You probably shouldn't even let the package be updated.

5) 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)).

6) Maybe redetect the /etc/mysql/FROZEN status, I'm not sure on this.

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.

BG Info:
$ lsb_release -rd
Description: Ubuntu 18.04.1 LTS
Release: 18.04

$apt-cache policy mysql-server-5.7
mysql-server-5.7:
  Installed: 5.7.24-0ubuntu0.18.04.1
  Candidate: 5.7.24-0ubuntu0.18.04.1
  Version table:
 *** 5.7.24-0ubuntu0.18.04.1 500
        500 http://archive.ubuntu.com/ubuntu bionic-updates/main amd64 Packages
        500 http://security.ubuntu.com/ubuntu bionic-security/main amd64 Packages
        100 /var/lib/dpkg/status
     5.7.21-1ubuntu1 500
        500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages

Expected Behaviour: MySQL to not mysteriously shutdown.
Actual Behaviour: MySQL shutdown.

Related branches

Robie Basak (racb) on 2018-10-24
Changed in mysql-5.7 (Ubuntu):
status: New → Triaged
importance: Undecided → High
tags: added: server-next
summary: - Frozen MySQL-Server does everything fine except security updates don't
- restart
+ FROZEN MySQL-Server runs, does everything fine, except security updates
+ don't start the service after install.
Changed in mysql-5.7 (Ubuntu):
assignee: nobody → Karl Stenerud (kstenerud)
description: updated
Changed in mysql-5.7 (Ubuntu):
status: Triaged → In Progress
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package mysql-5.7 - 5.7.24-2

---------------
mysql-5.7 (5.7.24-2) unstable; urgency=medium

  [ Karl Stenerud ]
  * d/mysql-server-5.7.{pre,post}inst, d/additions/mysql-systemd-start: improve
    frozen state handling (LP: #1799763):
     - Do not proceed in preinst if already in frozen state to prevent daemon
       stop if it had been started manually.
     - Log to syslog via logger to increase visibility of the problem.
     - Prevent systemd service start when in frozen state.

  [ Robie Basak ]
  * Update Dutch, Portuguese, French and German translations. Thanks to Frans
    Spiesschaert, "Traduz", Alban Vidal and Helge Kreutzmann. Closes: #895458,
    #898190, #898827, #906169.

 -- Robie Basak <email address hidden> Thu, 15 Nov 2018 13:55:54 +0000

Changed in mysql-5.7 (Ubuntu):
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers