Upgrade from MySQL server requires extra server restart to upgrade tables properly

Bug #484120 reported by Kristian Nielsen on 2009-11-17
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MariaDB
Fix Released
High
Kristian Nielsen
OurDelta
High
Kristian Nielsen

Bug Description

I tried today installing mariadb-server-5.1 (5.1.39-ourdelta67) on an Ubuntu 8.04 machine that previously ran the standard Ubuntu MySQL 5.0, so an upgrade scenario.

After the install, I see this in the /var/log/daemon.log from the bootstrap done during postinst:

Nov 17 10:40:52 odin mysqld_safe[10176]: 091117 10:40:52 [Warning] options --log-slow-admin-statements, --log-queries-not-using-indexes and --log-slow-slave-statements have no effect if --log_slow_queries is not set
Nov 17 10:40:52 odin mysqld_safe[10176]: ERROR: 1136 Column count doesn't match value count at row 1
Nov 17 10:40:52 odin mysqld_safe[10176]: 091117 10:40:52 [ERROR] Aborting

It seems this comes from this line in mariadb-server-5.1.postinst:

    echo "$replace_query" | $MYSQL_BOOTSTRAP 2>&1 | $ERR_LOGGER

The problem is that my mysql.user table is missing the columns Event_priv and Trigger_priv. The postinst script tries to add them with this statement:

    fix_privs=`/bin/echo -e \
        "USE mysql;\n" \
        "ALTER TABLE user ADD column Create_view_priv enum('N','Y') CHARACTER SET utf8 NOT NULL DEFAULT 'N'; " \
        "ALTER TABLE user ADD column Show_view_priv enum('N','Y') CHARACTER SET utf8 NOT NULL DEFAULT 'N'; " \
        "ALTER TABLE user ADD column Create_routine_priv enum('N','Y') CHARACTER SET utf8 NOT NULL DEFAULT 'N'; " \
        "ALTER TABLE user ADD column Alter_routine_priv enum('N','Y') CHARACTER SET utf8 NOT NULL DEFAULT 'N'; " \
        "ALTER TABLE user ADD column Create_user_priv enum('N','Y') CHARACTER SET utf8 NOT NULL DEFAULT 'N'; " \
        "ALTER TABLE user ADD column Event_priv enum('N','Y') CHARACTER SET utf8 NOT NULL DEFAULT 'N'; " \
        "ALTER TABLE user ADD column Trigger_priv enum('N','Y') CHARACTER SET utf8 NOT NULL DEFAULT 'N'; " `

But this failed to create the Event_priv and Trigger_priv columns. This is not surprising, as in MySQL 5.0 the other columns are already present. So the first ALTER TABLE fails and bootstrap aborts. (I did not find any error message in the logs for failing ALTER TABLE, not sure why...)

Manually adding the Event_priv and Trigger_priv columns and re-installing seems to get rid of the "Column count doesn't match value count" error.

A possible solution might be to seperate this into two bootstrap statements, so that Event_priv and Trigger_priv will be created even if adding the other columns fails.

Related branches

tags: added: 5.1
Michael Widenius (monty) wrote :

How things 'should' work is that one should start mysqld, run the
mysql_fix_privilege_tables and then stop mysqld.

I don't think it's correct to duplicate the work to fix the privilege tables as we then have to constantly have to keep
the scripts in sync.

Also the way 'fix_privs' now works, it will not be able to handle all cases that mysql_fix_privilege_tables does.

Changed in maria:
status: New → Confirmed
importance: Undecided → High
Kristian Nielsen (knielsen) wrote :

We have seen several cases of silent failures in the postinst script due to this construct:

    <cmd> | $ERR_LOGGER

This ignores the exit code of <cmd> by default, causing the `set -e` in
the script to not catch any errors here.

I suggest to not ignore the exit codes of commands in the pipe:

    set -o pipefail

This will make an error in a logged command immediately apparent by aborting
the install, rather than failing silently and leaving a broken install.

Cafuego (cafuego) wrote :

I've committed Kristians suggested fix; the "proper" way of doing things will take a bit longer.

The postinst should now fail verbosely and fall in a heap, rather than stay silent.

Changed in ourdelta:
assignee: nobody → Cafuego (cafuego)
Changed in maria:
assignee: nobody → Cafuego (cafuego)
status: Confirmed → In Progress
status: In Progress → Fix Committed
Changed in ourdelta:
status: Confirmed → Fix Committed
tags: added: packaging
Kristian Nielsen (knielsen) wrote :

Cafuego, I tested this, and it seems to not work.

I get this when installing:

dpkg: error processing mariadb-server-5.1 (--configure):
 subprocess post-installation script returned error exit status 1

And in /var/lib/daemon.err I get this:

Dec 8 21:06:15 vm-debian5-i386 mysqld_safe[2988]: ERROR: 1064 You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'ALTER TABLE user ADD column Show_view_priv enum('N','Y') CHARACTER SET utf8 NOT ' at line 1

(I merged it into a recent ourdelta version to test in buildbot, the tree is here: lp:~knielsen/ourdelta/bug484120)

So not sure why I get this ...

And there is another problem. In the upgrade case, the ADD COLUMN statements will definitely fail, and with the set pipefail that will also cause the installation to fail. Thus these particular statements need protection with || /bin/true or similar. The set pipefail is still good for statements that should not fail.

Changed in ourdelta:
status: Fix Committed → In Progress
Kristian Nielsen (knielsen) wrote :

Ok, I see what the problem is. In fact these statements have never worked, as a newline is needed between statements for --bootstrap!

I will take over this and fix, hope that is ok.

Changed in maria:
assignee: Cafuego (cafuego) → Kristian Nielsen (knielsen)
Changed in ourdelta:
assignee: Cafuego (cafuego) → Kristian Nielsen (knielsen)
Changed in maria:
status: Fix Committed → In Progress
Kristian Nielsen (knielsen) wrote :

I tested a new fix but there a lots of other problems. Like these:

Dec 9 16:39:30 vm-hardy-x86 /etc/mysql/debian-start[4990]: error : Table upgrade required. Please do "REPAIR TABLE `help_category`" or dump/reload to fix it!

Dec 9 16:39:29 vm-hardy-x86 mysqld: 091209 16:39:29 [ERROR] Column count of mysql.db is wrong. Expected 22, found 20. Created with MySQL 50051, now running 50141. Please use mysql_upgrade to fix
this error.
Dec 9 16:39:29 vm-hardy-x86 mysqld: 091209 16:39:29 [ERROR] mysql.user has no `Event_priv` column at position 29

ATTENTION: An error has occured. More info is in the syslog!

I think Monty is right that we have to solve this by properly running mysql_fix_privilege_tables...

Kristian Nielsen (knielsen) wrote :

Ok, the problem here is a bit deeper, and different from what I first thought.

The above error message about multiple columns is also there when upgrading the stock MySQL 5.0 to stock MySQL 5.1 in Ubuntu Jaunty. As is the syntax error.

Seems that these ADD COLUMN statements are just some old cruft that never worked, nor were needed?!?

The actual upgrade of the system tables to 5.1 format is done when the /etc/init.d/mysql start script calls mysql_upgrade during startup (mysql_upgrade is the 5.1 replacement for mysql_fix_privilege_tables). This happens on every start of the mysql server.

I just tested an upgrade from mysql 5.0 to mariadb 5.1.39 on Ubuntu Hardy. There was some issue with a stuck mysqld_safe which I want to investigate further, but after second restart of mysql I checked and mysql.user / mysql.db were ok and correctly upgraded by mysql_upgrade by the startup script.

I suspect that the reason I saw a problem was due to other issues with my install and/or waiting for mysqlcheck to finish before the upgrade is actually done. At least also my original install seems ok now.

Will double check and then if no further problems I will just remove the useless, non-functional SQL from the postinst.

Kristian Nielsen (knielsen) wrote :

So the real problems here are:

1. When upgrading from mysql-5.0 to mariadb on Ubuntu Hardy 64-bit (haven't tested other platforms), the upgrade is not done correctly on the first start of mysqld. Only after a second restart is the upgrade done, and then it is correct.

2. After installation, if the server is stopped the mysqld_safe process does not end, but loops endlessly, with strace showing infinite calls like this:

    wait4(4294967295, 0x7fffedde19fc, 0, NULL) = -1 ECHILD (No child processes)

3. mariadb-server-5.1.postinst contains some old junk SQL that is passed to $BOOTSTRAP during installation, but which is neither needed nor functional.

summary: - "ERROR: 1136 Column count doesn't match value count at row 1" when
- installing mariadb-server-5.1
+ Upgrade from MySQL server requires extra server restart to upgrade
+ tables properly
Kristian Nielsen (knielsen) wrote :
Download full text (9.8 KiB)

Having a hard time tracking this down.

I tested on Jaunty (amd64), it does not have the problem. But on Hardy, after
upgrading from mysql 5.0 to mariadb 5.1, the mysql_upgrade does not complete,
and mysqld_safe hangs when stopping the server. Upon next restart,
mysql_upgrade completes successfully, and everything seems ok.

I have appended logs below, note how the mysqlcheck and mysql_upgrade seems to
abort early, without any visible error messages.

Here is the log from /etc/mysql/debian-start from the first, unsuccessful
start:

Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5418]: Upgrading MySQL tables if necessary.
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: /usr/bin/mysql_upgrade: the '--basedir' option is always ignored
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: Looking for 'mysql' as: /usr/bin/mysql
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: Running 'mysqlcheck' with connection arguments: '--port=3306' '--socket=/var/run/mysqld/mysqld.sock' '--host=localhost' '--socket=/var/run/mysqld/mysqld.sock' '--socket=/var/run/mysqld/mysqld.sock'
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: Running 'mysqlcheck' with connection arguments: '--port=3306' '--socket=/var/run/mysqld/mysqld.sock' '--host=localhost' '--socket=/var/run/mysqld/mysqld.sock' '--socket=/var/run/mysqld/mysqld.sock'
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.columns_priv OK
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.db OK
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.event OK
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.func OK
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.general_log
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: Error : You can't use locks with log tables.
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: status : OK
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.help_category
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: error : Table upgrade required. Please do "REPAIR TABLE `help_category`" or dump/reload to fix it!
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.help_keyword
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: error : Table upgrade required. Please do "REPAIR TABLE `help_keyword`" or dump/reload to fix it!
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.help_relation OK
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.help_topic
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: error : Table upgrade required. Please do "REPAIR TABLE `help_topic`" or dump/reload to fix it!
Dec 15 10:54:17 vm-hardy-amd64 /etc/mysql/debian-start[5425]: mysql.host OK
Dec 15 10:...

Kristian Nielsen (knielsen) wrote :

Think I finally found it. Seems the mysql_upgrade running from /etc/mysql/debian-start got a SIGHUP in the middle.

I have pushed a branch with a proposed fix for this, we will see what tests say.

Changed in maria:
status: In Progress → Fix Committed
Changed in ourdelta:
status: In Progress → Fix Committed
Changed in maria:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers