[MDEV-9193] Upgrade from 10.0.22 to 10.1.9 fails Created: 2015-11-25  Updated: 2016-01-22  Resolved: 2016-01-22

Status: Closed
Project: MariaDB Server
Component/s: Plugins, XA
Affects Version/s: 10.1.9
Fix Version/s: 10.1.10

Type: Bug Priority: Major
Reporter: Sander Vancanneyt Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: None
Environment:

CentOS 6.6

Attachments: JPEG File SafariSchermSnapz001.jpg     PNG File Schermafbeelding 2015-11-27 om 23.34.16.png    
Issue Links:
Blocks
is blocked by MDEV-9214 Server miscalculates the number of XA... Closed
Sprint: 10.1.11

 Description   

Trying to upgrade MariaDB from 10.0.22 to 10.1.9 fails. Downgrading back to 10.0.22 makes mariaDB work again.
Here are the logs during upgrade:

Found /usr/local/directadmin/custombuild/mysql/MariaDB-10.1.9-centos6-x86_64-client.rpm
 
Found /usr/local/directadmin/custombuild/mysql/MariaDB-10.1.9-centos6-x86_64-devel.rpm
 
Found /usr/local/directadmin/custombuild/mysql/MariaDB-10.1.9-centos6-x86_64-server.rpm
 
Found /usr/local/directadmin/custombuild/mysql/MariaDB-10.1.9-centos6-x86_64-shared.rpm
 
Found /usr/local/directadmin/custombuild/mysql/MariaDB-10.1.9-centos6-x86_64-common.rpm
 
Found /usr/local/directadmin/custombuild/mysql/MariaDB-10.1.9-centos6-x86_64-compat.rpm
 
Installing libjemalloc...
 
Found /usr/local/directadmin/custombuild/mysql/jemalloc-3.6.0-1.el6.x86_64.rpm
 
Found /usr/local/directadmin/custombuild/mysql/jemalloc-devel-3.6.0-1.el6.x86_64.rpm
 
warning: /usr/local/directadmin/custombuild/mysql/jemalloc-3.6.0-1.el6.x86_64.rpm: Header V4 DSA/SHA1 Signature, key ID 1bb943db: NOKEY
 
Preparing...                ########################################### [100%]
 
   1:jemalloc               ########################################### [ 50%]
 
   2:jemalloc-devel         ########################################### [100%]
 
Stopping mysqld ...
 
Shutting down MySQL..................................... SUCCESS! 
Upgrading MariaDB 10.0.22 to 10.1.9
 
warning: /etc/my.cnf.d/server.cnf saved as /etc/my.cnf.d/server.cnf.rpmsave
 
warning: MariaDB-10.1.9-centos6-x86_64-client.rpm: Header V4 DSA/SHA1 Signature, key ID 1bb943db: NOKEY
 
Preparing...                ########################################### [100%]
 
   1:MariaDB-compat         ########################################### [ 17%]
 
   2:MariaDB-common         ########################################### [ 33%]
 
   3:MariaDB-client         ########################################### [ 50%]
 
   4:MariaDB-server         ########################################### [ 67%]
 
   5:MariaDB-devel          ########################################### [ 83%]
 
   6:MariaDB-shared         ########################################### [100%]
 
Starting MySQL.... ERROR! 
Giving mysqld a few seconds to start up...
 
Version check failed. Got the following error when calling the 'mysql' command line client
 
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/lib/mysql/mysql.sock' (2 "No such file or directory")
 
FATAL ERROR: Upgrade failed
 
/usr/bin/mysqlcheck: Got error: 2002: Can't connect to local MySQL server through socket '/var/lib/mysql/mysql.sock' (2 "No such file or directory") when trying to connect
 
cp: `/usr/lib/libmysqlclient.so' and `/usr/lib/mysql/libmysqlclient.so' are the same file
 
Restarting MySQL.
 
 ERROR! MySQL server PID file could not be found!
 
Starting MySQL... ERROR! 
 ERROR! Failed to restart server.

and mysql error log:

151125 17:54:18 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
 
/usr/sbin/mysqld: /usr/local/lib/libz.so.1: no version information available (required by /usr/sbin/mysqld)
 
2015-11-25 17:54:18 140379608573984 [Note] /usr/sbin/mysqld (mysqld 10.1.9-MariaDB) starting as process 11140 ...
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: The InnoDB memory heap is disabled
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Memory barrier is not used
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Using Linux native AIO
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Using CPU crc32 instructions
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Initializing buffer pool, size = 128.0M
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Completed initialization of buffer pool
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Highest supported file format is Barracuda.
 
2015-11-25 17:54:19 140379608573984 [Warning] InnoDB: Resizing redo log from 2*16384 to 2*3072 pages, LSN=307161985788
 
2015-11-25 17:54:19 140379608573984 [Warning] InnoDB: Starting to delete and rewrite log files.
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
 
2015-11-25 17:54:19 140379608573984 [Warning] InnoDB: New log files created, LSN=307161986060
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: 128 rollback segment(s) are active.
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB: Waiting for purge to start
 
2015-11-25 17:54:19 140379608573984 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 307161985788
 
2015-11-25 17:54:20 140378833417984 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2015-11-25 17:54:20 140379608573984 [Note] Plugin 'FEEDBACK' is disabled.
 
2015-11-25 17:54:20 140379608573984 [Note] Recovering after a crash using tc.log
 
2015-11-25 17:54:20 140379608573984 [ERROR] Recovery failed! You must enable exactly 3 storage engines that support two-phase commit protocol
 
2015-11-25 17:54:20 140379608573984 [ERROR] Crash recovery failed. Either correct the problem (if it's, for example, out of memory error) and restart, or delete tc log and start mysqld with --tc-heuristic-recover={commit|rollback}
 
2015-11-25 17:54:20 140379608573984 [ERROR] Can't init tc log
 
2015-11-25 17:54:20 140379608573984 [ERROR] Aborting



 Comments   
Comment by Elena Stepanova [ 2015-11-27 ]

vancanneyt,

Did you try to remove tc.log as the server log suggests?
If you didn't, please try to shut down 10.0.22 server gracefully, and if the tc.log is still in the datadir after that, remove it before you run upgrade.

The general problem is described here: MDEV-8794.
It caused a problem with upgrade to 10.1.8, so some changes were made here: MDEV-9039.
Apparently, there is still a combination of engines/parameters that is affected, it is not particularly surprising.
If you can, please run SHOW ENGINES before upgrade, on 10.0.22, and then after upgrade, on 10.1.9, so that we could understand how your instance got affected.

Thanks.

Comment by Sander Vancanneyt [ 2015-11-28 ]

Thanks for your feedback!
Removed tc.log as it wasn't deleted after stopping mysqld
Tried upgrading, now without errors. Checked the error log again, this was the result:

2015-11-27 23:32:30 140145192560672 [Note] /usr/sbin/mysqld (mysqld 10.1.9-MariaDB) starting as process 13300 ...
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: The InnoDB memory heap is disabled
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Memory barrier is not used
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Using Linux native AIO
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Using CPU crc32 instructions
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Initializing buffer pool, size = 128.0M
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Completed initialization of buffer pool
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Highest supported file format is Barracuda.
 
2015-11-27 23:32:30 140145192560672 [Warning] InnoDB: Resizing redo log from 2*16384 to 2*3072 pages, LSN=311502829507
 
2015-11-27 23:32:30 140145192560672 [Warning] InnoDB: Starting to delete and rewrite log files.
 
2015-11-27 23:32:30 140145192560672 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
 
2015-11-27 23:32:31 140145192560672 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
 
2015-11-27 23:32:31 140145192560672 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
 
2015-11-27 23:32:31 140145192560672 [Warning] InnoDB: New log files created, LSN=311502829580
 
2015-11-27 23:32:31 140145192560672 [Note] InnoDB: 128 rollback segment(s) are active.
 
2015-11-27 23:32:31 140145192560672 [Note] InnoDB: Waiting for purge to start
 
2015-11-27 23:32:31 140145192560672 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 311502829507
 
2015-11-27 23:32:31 140144422156032 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2015-11-27 23:32:31 140145192560672 [Note] Plugin 'FEEDBACK' is disabled.
 
2015-11-27 23:32:31 140145192560672 [Note] Server socket created on IP: '::'.
 
2015-11-27 23:32:31 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:31 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "mysql"."gtid_slave_pos" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:31 140145192560672 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.1.9-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "spacepage_joomla"."j17_session" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "spacepage_joomla"."j17_extensions" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "spacepage_joomla"."j17_usergroups" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "spacepage_joomla"."j17_viewlevels" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "spacepage_joomla"."j17_languages" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "spacepage_joomla"."j17_menu" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:33 7f761866a700 InnoDB: Error: Fetch of persistent statistics requested for table "spacepage_joomla"."j17_sh404sef_aliases" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2015-11-27 23:32:37 7f761866a700 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2015-11-27 23:32:37 140145192249088 [Note] /usr/sbin/mysqld: Normal shutdown
 
 
 
2015-11-27 23:32:37 140145192249088 [Note] Event Scheduler: Purging the queue. 0 events
 
2015-11-27 23:32:37 140144401176320 [Note] InnoDB: FTS optimize thread exiting.
 
2015-11-27 23:32:37 140145192249088 [Note] InnoDB: Starting shutdown...
 
2015-11-27 23:32:39 140145192249088 [Note] InnoDB: Shutdown completed; log sequence number 311505291238
 
2015-11-27 23:32:39 140145192249088 [Note] /usr/sbin/mysqld: Shutdown complete
 
 
 
151127 23:32:39 mysqld_safe mysqld from pid file /var/lib/mysql/server.aegvzw.be.pid ended
 
151127 23:32:39 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
 
/usr/sbin/mysqld: /usr/local/lib/libz.so.1: no version information available (required by /usr/sbin/mysqld)
 
2015-11-27 23:32:39 140391067760672 [Note] /usr/sbin/mysqld (mysqld 10.1.9-MariaDB) starting as process 13493 ...
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: The InnoDB memory heap is disabled
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: Memory barrier is not used
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: Using Linux native AIO
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: Using CPU crc32 instructions
 
2015-11-27 23:32:39 140391067760672 [Note] InnoDB: Initializing buffer pool, size = 128.0M
 
2015-11-27 23:32:40 140391067760672 [Note] InnoDB: Completed initialization of buffer pool
 
2015-11-27 23:32:40 140391067760672 [Note] InnoDB: Highest supported file format is Barracuda.
 
2015-11-27 23:32:40 140391067760672 [Note] InnoDB: 128 rollback segment(s) are active.
 
2015-11-27 23:32:40 140391067760672 [Note] InnoDB: Waiting for purge to start
 
2015-11-27 23:32:40 140391067760672 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 311505291238
 
2015-11-27 23:32:40 140391067760672 [Note] Plugin 'FEEDBACK' is disabled.
 
2015-11-27 23:32:40 140390296450816 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2015-11-27 23:32:40 140391067760672 [Note] Server socket created on IP: '::'.
 
2015-11-27 23:32:40 140391067760672 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.1.9-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

Also include two screenshots pre upgrade een post upgrade of SHOW ENGINES

Thanks a bunch!

Comment by Elena Stepanova [ 2015-12-01 ]

Thanks.

With this set of engines on 10.0, you should not have had a tc.log at all. My best guess that it was an old one, created at some point (maybe long time ago) when some other engines were enabled. After the engines got disabled, and only one XA-capable engine left, 10.0 didn't care about the stale tc.log, but when you upgraded to 10.1, you encountered the problem MDEV-9214, which basically means 10.1 always cares about tc.log, even when it shouldn't.

In general, whenever you hit the problem, if you are only using one XA-capable engine, it should be safe to remove tc.log as the error message suggests.

I will set this bug report as blocked by MDEV-9214 for now.

Generated at Thu Feb 08 07:32:50 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.